OCIS slower than OC10 - how to accelerate?

Async Processing only affects uploads. Unrelated, for now. Let us focus on downloads first:

We tried to come as close to your tests as possible:

  • use oCIS v2.0 release
  • replicate your test data with this beautiful snippet:
i=0; for s in 97 97 97 510 630 630 630 631 631 631 631 631 631 631 631 631 631 631 631 631 631 631 631 631 631 631 631 632 632 632 632 633 633 635 635 635 635 635 635 635 635 855 1167 1475 1592 1594 1602 1606 1608 1608 1610 1677 1724 1927 2005 2105 2230 2311 2615 2695 2830 2830 2892 2892 3007 3087 3216 3245 3317 3317 3577 3717 3770 3981 4019 4136 4251 4349 4676 4677 4677 4677 4702 4809 4872 4915 5007 5061 5099 5161 5315 5410 5495 5550 5582 5590 5666 5695 5902 6087 6311 6506 6506 6753 6786 6909 6959 7145 7148 7675 7678 7782 7842 8093 8189 8272 8345 8624 8715 8844 8861 9472 9529 9986 10341 10612 10659 10685 10831 10878 11461 11613 11680 11752 12520 12597 12657 12820 13970 14447 14793 15225 15225 15237 15446 15625 15788 15986 16194 16785 16967 17122 17294 18030 18030 18574 19146 19232 19232 19245 19817 19975 20162 20346 21209 21343 21498 21789 21921 22735 23218 23366 23389 25101 25101 25769 25789 25789 25832 26195 26250 26535 27221 27598 28024 28407 28649 28649 29533 29794 29949 30074 30088 30267 30843 30871 30889 31149 31149 31234 31391 31391 31522 31812 31952 32043 33333 33732 33798 34364 35139 35508 35515 35663 36042 36042 36329 36747 37213 37691 37721 37795 38835 39139 39727 39865 40020 40083 40446 41165 42846 42849 43481 43561 44009 44854 44894 44975 44975 45425 45430 45535 46045 46140 46489 46960 47545 47933 48030 48615 48618 48634 48767 48900 48900 49470 49682 49957 50445 50801 51798 52111 52111 52382 52841 54431 54431 54739 55410 55989 57035 58291 59217 59691 59798 60207 61907 62709 63369 64127 65000 66392 67211 67265 67878 68036 68036 68395 69599 69707 71594 71974 74302 74375 74375 74375 74375 74375 74375 74375 74663 76258 77191 78422 78560 79251 80241 82245 82257 82860 83187 83271 84562 84917 86248 86895 87636 88076 88626 89097 89103 90123 90336 90793 91425 91997 92259 93985 94060 94431 94952 96199 98136 98151 98500 100762 103866 104207 105039 106798 108224 108292 109406 111761 112837 114152 114515 116407 117843 117939 120122 121337 121832 122524 123022 124712 125158 125269 127741 130122 131743 134256 136572 137090 137092 142224 142224 142561 143027 143624 143862 144695 146022 147257 149009 152314 154358 155854 157116 157116 161842 162398 165409 165962 166266 167426 169101 172864 172934 173316 176855 179240 179308 179824 180128 182085 184543 184782 185084 185429 186777 186920 190275 194821 195920 196662 196662 196662 196662 197584 199936 199943 200169 200998 202329 203392 206177 206308 210923 211497 211595 213138 213376 214144 214628 214947 216022 216420 219590 219702 221257 221512 224159 226584 227480 229983 231019 231019 232280 233153 235810 237190 247002 247739 248078 254061 261963 262467 270162 280658 284117 285766 289779 290346 294511 294528 298910 308526 309875 313581 314061 316643 317630 317816 318035 318232 322264 326793 330712 335610 339530 340106 340182 341648 341648 345017 345980 346213 347350 347888 354919 357438 364646 365600 365961 368645 373271 376217 376523 379065 380116 380116 382607 386276 387928 388427 388451 392465 399357 401438 401746 403733 410202 413712 414058 417550 422351 429275 430573 434724 437153 437153 438194 439656 440138 441052 442339 450940 451457 453990 455794 457712 458315 459237 463208 464109 464125 465836 467765 475986 478426 491130 496842 496890 497343 503614 510009 511004 516622 517097 519804 520518 536312 538206 541640 544911 552983 562594 566982 567005 567483 569184 570415 576653 576908 595001 595287 596969 608853 610229 618455 624449 631691 636737 662183 663975 664638 669999 671863 681999 688150 689108 699177 699296 700459 700768 705440 715126 719806 720605 722760 732936 735480 738416 748504 749320 749407 751471 765915 766425 768703 769433 771172 773492 778433 783226 786486 786486 786486 786486 786486 786486 786929 788228 792128 795160 800332 804196 822018 823961 825518 843836 849707 852669 852669 870202 873578 878616 882485 886475 893712 932120 942301 942301 961406 962275 963049 963049 965061 969786 998455 1008428 1021049 1034435 1043485 1043485 1044555 1044555 1086190 1127365 1127366 1159873 1162462 1163144 1234111 1234672 1284107 1285044 1288815 1303582 1375915 1391808 1394752 1395600 1465860 1497915 1501002 1508898 1513708 1520411 1525055 1532613 1539150 1564254 1572918 1572918 1572918 1609532 1634756 1668533 1692470 1695188 1705814 1715629 1767228 1791456 1838331 1840180 1852369 1916313 2042467 2085756 2105200 2200662 2233522 2244547 2267215 2631481 2727624 2786144 2787040 2787392 2790064 2790896 2791936 2806624 2825200 2914884 2926934 2936216 3004791 3076806 3140593 3145782 3145782 3145782 3145782 3145782 3145782 3176483 3184697 3224118 3246867 3385306 3458243 3668350 3844421 4029165 4499420 4525497 4551995 4643226 4730541 4795033 4925406 5044316 5205931 5263709 5323896 5517019 5517528 5626693 5702050 5918657 6129762 6237707 6507848 6521822 6571699 6636694 6657595 6728410 6833994 6842382 6878252 6941044 7018925 7050826 7406837 7427777 7441626 7476645 7545102 7729847 7831469 7914008 7915091 8093071 8208383 8294290 8349201 8403053 8522813 8549582 8741233 8765117 8770739 8853296 8962138 8981319 9006599 9143936 9160937 9168242 9190632 9274462 9372532 9918768 10752617 10842373 10981440 11206609 11626212 12124816 12401998 12582966 12619661 12630624 12716415 12716415 12781625 12914467 13184135 13431695 13747767 13966588 14247705 14342531 14466284 14599445 14668765 14747664 14758216 14855935 15015880 15027702 15133591 15286732 15327826 15399389 15409449 15596322 15700270 15728793 15889216 15892394 16379480 16392216 16459975 16478128 16596964 16799762 16869084 17289936 17611096 17981612 18014599 18104458 18221892 18239700 18307768 18312792 18330662 18493647 18531998 18541229 18614342 18779464 18839129 19103916 19188161 19266225 19374038 19572840 19630233 19662925 19796781 19823017 20662723 20805211 20872812 20976148 20983458 21374434 21433928 21729617 21833066 21972356 21973835 22237553 22295469 22642379 22728018 23109225 23144175 23491371 23550387 23584169 23615853 23671038 23963446 24198833 24221462 24243051 24424287 24488369 24497107 24724129 24961823 25007812 25050940 25103206 25469332 25743953 25744234 25968567 26163243 26195454 26250067 26591434 26666950 27138879 27324684 27407221 27709286 28473405 29041712 29161834 29623575 29673823 30385049 30569987 30577112 30869316 30991058 31033335 31698843 31730092 33554777 34015030 34160785 34296161 34423885 34539418 35798610 35909613 36208200 36706569 37445313 37642033 39174144 39272594 39283597 40224416 40564108 42020087 45101096 46705128 49378817 54121952 57474957 61329827 63485014 76423283 87070536 89758931 90005778 99117342 101389909 112547930 209715200 250316620 611472498 ; do dd if=/dev/urandom of=file$i.bin bs=$s count=1; i=$((i+1)); done

oCIS is still faster

  • oc10 download: Sync run took 369750 ms
  • oCIS download: Sync run took 241174 ms

Next thing for you to try to dig into the problem is by enabling tracing as per: Tracing | ownCloud

The only difference I see in our setup that we are using docker compose to run oc10 … but that should not make a difference when downloading 1k files.

Okay - we’ll get tracing enabled and see what that can shed light on. What should we be specifically looking for or at?

You could get the X-Request-Id from one of the slow requests in the desktop log, then search for the corresponding traces in the Jaeger.

@butonic @michaelstingl The slowness is entirely due to OpenID Connect with Keycloak. We ran a test commenting out OCIS_OIDC_ISSUER and downloads of our test with 944 files went from 4:31 to 1:46.

Our Keycloak server is on a different network that’s definitely not the fastest to access from the subnet on which OC10 and OCIS are running. Normally that’s not an issue for us as services authenticate once and if that takes an extra 500ms no one cares. If ownCloud Desktop syncs are running auth to the Keycloak server for every file, it’s absolutely going to crawl.

We ran a test with a temporary Keycloak server on the same subnet as OCIS and syncs of those 944 files ran around 2:45. Definitely better than 4:31, but nowhere near as fast as the 1:46 we get when using OCIS’ built-in IdP.

It seems one way or another we need to greatly reduce OCIS’ reliance on Keycloak for authentication. Is there a way to have OCIS auth against Keycloak only at login and not on every file request? Or can we have OCIS use Keycloak purely as an external IdP to provision accounts on the internal IdP?

Hm, sounds strange.

OICD with the desktop client relies on access_token and refresh_token. Client connects with the access_token to oCIS, and oCIS has the access_token cached for a while (5 Minutes in our deployment examples). After access_token expiration, client sends the refresh_token in a POST request to the Keycloak token endpoint, to get a new access_token.

Hmmm… definitely strange if that’s how things are set up.

FWIW, our Keycloak is configured with an access_token lifespan of 30 days. Refresh tokens should also have a lifespan of 30 days since our SSO and client session idles and session maxes are all 30 days.

@walt in oCIS v2.0 PROXY_OIDC_USERINFO_CACHE_TTL defaults to 10 … which is documented as Max TTL in seconds for the OIDC user info cache. This default is used as a fallback when the token does not have an exp claim or when PROXY_OIDC_ACCESS_TOKEN_VERIFY_METHOD is set to none.

Unfortunately, there seems to be a bug in how the TTL of 10 is interpreted, as I cannot find a place that turns it into seconds. AFAICT it is interpretet in nanoeconds. Could you try PROXY_OIDC_USERINFO_CACHE_TTL=10000000000 to get the 10s or maybe even PROXY_OIDC_USERINFO_CACHE_TTL=1800000000000 to get 30min?

Why don’t you use PROXY_OIDC_ACCESS_TOKEN_VERIFY_METHOD=jwt?

In any case I am literally working on the proxy cache right now and the env var will change to be parsed as a duration, which will allow you to use an h, m or h suffix, so the numbers will become better understandable. … at the cost of some variable renaming … :man_shrugging:

Let us know if that helps!

1 Like

produces similar results as without it set: average 2:45 to sync those 944 files via the Desktop app.

It wasn’t used in the example setup we followed from Helge Klein and everything seemed to work fine without it. If you believe this would be of benefit in v2.0.0 we’re happy to give it a try.

1 Like

keycloak uses a JWT access token, so you can use the default PROXY_OIDC_ACCESS_TOKEN_VERIFY_METHOD=jwt. The proxy will then cache the token until the contained expiry date time is reached. It should no longer make any subsequent requests to keycloak for that access token.

That being said, PROXY_OIDC_USERINFO_CACHE_TTL=1800000000000 should have had the same effect for you. Now … leaving OCIS_OIDC_ISSUER unconfigured will tell the clients to talk to the oCIS built in IDP (you may want to disable it with OCIS_EXCLUDE_RUN_SERVICES=idp since you are using keycloak anyway). The proxy also only needs to talk to another service on the same host, so that reduces latency in comparison to keycloak on another machine (which not only adds the network latency but also the actual access token verification).

Still, that userinfo lookup request from the proxy should only be made in the first request. For subsequent requests the cache should be hit. No more latency …

:thinking:

Could you set PROXY_LOG_LEVEL=debug? It should log the cache hits, misses and inserts.

2 Likes

That did the trick! With both PROXY_OIDC_ACCESS_TOKEN_VERIFY_METHOD=jwt and OCIS_EXCLUDE_RUN_SERVICES=idp we’re now matching the speed of transfers with the internal IdP - 1:46 for 944 files down, 1:34 for 944 files up - via the Desktop app.

6 Likes

Nice! Tweet or toot that somewhere to spread the word, will ya?

1 Like

Absolutely will. This was a tough one to solve, even if the ultimate answer is pretty simple. Couldn’t have done it without you and @michaelstingl both poking at this from every possible angle.

1 Like

Awesome, thanks for your patience and great that it could be nailed down.

2 Likes

This was an interesting read. Nicely investigated.

I have a related question; I am wondering if you have any insights on how to successfully use JWTs to verify tokens when using Authelia as IAM?

I am running OCIS 3.0.0 with Authelia, and when PROXY_OIDC_ACCESS_TOKEN_VERIFY_METHOD=jwt is set, then authentication fails with the following message:

2023-07-22T13:49:58Z ERR failed to authenticate the request error=\"failed to verify access token: token contains an invalid number of segments\" authenticator=oidc path=/ocs/v1.php/cloud/user service=proxy

Authentication works fine when PROXY_OIDC_ACCESS_TOKEN_VERIFY_METHOD=none

Thanks for your input.

AFAIK for validating the access tokens issued by authelia, we’d need to query the introspection endpoind. Unfortunately ocis does not support that currently. So PROXY_OIDC_ACCESS_TOKEN_VERIFY_METHOD=none is the correct setting for authelia currently.

We can be sure that we have a valid access_token as we use it to query the IDPs userinfo endpoint. Doing that with an invalid token would fail.

1 Like

Is this still true or is there a workaround for authelia and ocis to use jwt?

That is still true. Authelia cannot issue jwt encoded access tokens.

Authelia actually does technically support the JWT Profile for Access Tokens in the latest beta.

However I feel like there is not a use case for validating the Access Token in this way as it’s a stateless validation (i.e. if it were revoked the token would still be considered valid using this method). The introspection endpoint provides accurate stateful information about the token being valid, whereas the JWT method does not. The JWT validation in addition if applied to the ID Token would yield similar results. I am curious about what is intended to be validated in regards to the access token?

It should also be noted that the introspection flow is very simple and light.

2 Likes

Nice

It depends a bit on the configuration. When using Keycloak IIRC we just extracting the exp claim and use that as a ttl for our internal userinfo cache. As we support backchannel logout with keycloak, we’ll get informed via the backchannel as soon a session is revoked. In other configurations we can also extract stuff like role-assignments from the access token.

True. We just don’t have an implementation for that yet. Also it obviously needs another roundtrip to the IDP.