## Problem System clocks are synced, however a customer is seeing Git repositories fail to sync, with `last_sync_failure`: `Error syncing repository: 13:fatal: could not read Username for 'https://gitlab.example.com': terminal prompts disabled` Essentially `could not read Username` occurs because Geo's JWT authentication failed, and the primary site returned a 401, which would normally cause a Git client to ask for credentials, but the Git client in this case is running in the secondary site's Gitaly node, non-interactively. ### More details The JWT expiration is 60s, plus 60s of leeway =\> 120s. If the JWT is decoded after 120s, then you will see errors like: `fatal: could not read Username for 'https://gitlab.example.com': terminal prompts disabled`. Copied and redacted from confidential issue https://gitlab.com/gitlab-com/geo-customers/-/issues/207#note_1921672521: <details> <summary>Click here to expand details</summary> > > indicates this is an authentication issue. In Gitaly, [heres a test](https://gitlab.com/gitlab-org/gitaly/-/blob/master/internal/gitaly/service/repository/fetch_remote_test.go#L831) that produces that same error. @brodock how does the http auth token get propagated to Gitaly? > > Oh... [RepoSyncRequest uses an authorization expiration of 10 minutes](https://gitlab.com/gitlab-org/gitlab/-/blob/v16.7.6-ee/ee/lib/gitlab/geo/repo_sync_request.rb). Maybe these 3 repos in particular are affected because this expiration is reached? > > The default 1 minute expiration was overridden with 10 minutes many years ago to fix the same error: https://gitlab.com/gitlab-org/gitlab/-/issues/4881 > > > We do an info-refs call and then a receive-pack / upload-pack (I always forget which is which). both use the same token, which will expire if info-refs takes too long. > Though, that `expiration_time` method doesn't appear to be called. We will look into this. > I found in `primary_site_sos_20240424141441/var/log/gitlab/gitlab-rails/geo.log` many of these messages: > > `{"severity":"ERROR","time":"2024-04-24T07:03:58.904Z","correlation_id":"01HW7EP5N58X5ER4HHZMTFF58Y","class":"Gitlab::Geo::SignedData","gitlab_host":"REDACTED","message":"Signature not within leeway of 60 seconds. Check your system clocks!"}` > > Which is logged [here](https://gitlab.com/gitlab-org/gitlab/-/blob/v16.7.6-ee/ee/lib/gitlab/geo/signed_data.rb#L48) on both `JWT::ImmatureSignature` and `JWT::ExpiredSignature` errors. So those leeway messages could be due to expiration. > > But I didn't find in the primary site logs: [`Geo JWT authentication failed`](https://gitlab.com/gitlab-org/gitlab/-/blob/v16.7.6-ee/ee/app/controllers/ee/repositories/git_http_controller.rb#L133), which I expected to see along with [`Invalid signature time`](https://gitlab.com/gitlab-org/gitlab/-/blob/v16.7.6-ee/ee/app/controllers/ee/repositories/git_http_controller.rb#L113). > It appears `expiration_time` stopped being used accidentally during a [refactor](https://gitlab.com/gitlab-org/gitlab/-/commit/80e198829e65f1b29f7435e62f52d6c5d885b1bf#73be2a01ac1f9d364f3c117841b3589d21363e78_36_34 "Refactor Geo signing data logic") in 14.10. > > I confirmed that the JWT token must be decoded within 120s (60s default validity period + 60s leeway) or else an expiration error will be raised: > > ``` > [88] pry(main)> signed_data = Gitlab::Geo::SignedData.new(geo_node: GeoNode.secondary_nodes.first, validity_period: 10.seconds).sign_and_encode_data({ 'foo' => 'bar' }); sleep 71; data = Gitlab::Geo::SignedData.new(include_disabled_nodes: @include_disabled).decode_data(signed_data); puts '2'; signed_data = Gitlab::Geo::SignedData.new(geo_node: GeoNode.secondary_nodes.first, validity_period: 10.seconds).sign_and_encode_data({ 'foo' => 'bar' }); sleep 68; data = Gitlab::Geo::SignedData.new(include_disabled_nodes: @include_disabled).decode_data(signed_data) > GeoNode Load (0.4ms) SELECT "geo_nodes".* FROM "geo_nodes" WHERE "geo_nodes"."primary" = FALSE ORDER BY "geo_nodes"."id" ASC LIMIT 1 /*application:console,db_config_name:main,console_hostname:MikesGitLabMBP.localdomain,console_username:mkozonogitlab,line:(pry):62:in `__pry__'*/ > GeoNode Load (1.1ms) SELECT "geo_nodes".* FROM "geo_nodes" WHERE "geo_nodes"."enabled" = TRUE AND "geo_nodes"."access_key" = 'JQmgyI_TKG9An1wBHIDg' LIMIT 1 /*application:console,db_config_name:main,console_hostname:MikesGitLabMBP.localdomain,console_username:mkozonogitlab,line:/ee/lib/gitlab/geo/signed_data.rb:83:in `hmac_secret'*/ > Gitlab::Geo::InvalidSignatureTimeError: Signature not within leeway of 60 seconds. Check your system clocks! > from /Users/mkozonogitlab/Developer/gdk2/gitlab/ee/lib/gitlab/geo/signed_data.rb:50:in `rescue in decode_data' > Caused by JWT::ExpiredSignature: Signature has expired > from /Users/mkozonogitlab/.asdf/installs/ruby/3.2.3/lib/ruby/gems/3.2.0/gems/jwt-2.5.0/lib/jwt/verify.rb:42:in `verify_expiration' > [89] pry(main)> signed_data = Gitlab::Geo::SignedData.new(geo_node: GeoNode.secondary_nodes.first, validity_period: 10.seconds).sign_and_encode_data({ 'foo' => 'bar' }); sleep 68; data = Gitlab::Geo::SignedData.new(include_disabled_nodes: @include_disabled).decode_data(signed_data) > GeoNode Load (0.4ms) SELECT "geo_nodes".* FROM "geo_nodes" WHERE "geo_nodes"."primary" = FALSE ORDER BY "geo_nodes"."id" ASC LIMIT 1 /*application:console,db_config_name:main,console_hostname:MikesGitLabMBP.localdomain,console_username:mkozonogitlab,line:(pry):63:in `__pry__'*/ > GeoNode Load (0.8ms) SELECT "geo_nodes".* FROM "geo_nodes" WHERE "geo_nodes"."enabled" = TRUE AND "geo_nodes"."access_key" = 'JQmgyI_TKG9An1wBHIDg' LIMIT 1 /*application:console,db_config_name:main,console_hostname:MikesGitLabMBP.localdomain,console_username:mkozonogitlab,line:/ee/lib/gitlab/geo/signed_data.rb:83:in `hmac_secret'*/ > => {:foo=>"bar"} > ``` > > We know that Git fetch can take far over 1 or even 10 minutes. And https://gitlab.com/gitlab-org/gitlab/-/issues/4881 implies that the `upload-pack` request only needs to reach the primary Geo site before expiration. `upload-pack` comes after `info-refs`. So I tried to reproduce the error by making the primary site sleep for 61s during the `info/refs` request. > > I ended up seeing a another error which also has been an occasional mystery: `Error syncing repository: 13:Received RST_STREAM with error code 2.`. > > So I reduced the info refs sleep a little bit, in case a different timeout was being tripped. And saw yet another error that we've seen with `RST_STREAM` before: `Error syncing repository: 4:Deadline Exceeded.`. > > At 30s, as well as at 31s, I got: `Error syncing repository: 13:fetch remote: \"fatal: unable to access 'https://gdk.test:3443/testmkozono/fork-test-2018-08-11/gitaly.git/': Failure when receiving data from the peer\\n\": exit status 128.` > > At 20s and 28s, the sync succeeded. > > Did Gitaly timeouts get increased at some point? Perhaps JWT expiration can only be reached in that way. > Ah ha, I was able to reproduce it by monkeypatching the validity period to a value far below Gitaly timeouts: > > ``` > module Gitlab; module Geo; class BaseRequest > private > def geo_auth_token(message) > signed_data = Gitlab::Geo::SignedData.new(geo_node: requesting_node, validity_period: -61.seconds).sign_and_encode_data(message) > > "#{GITLAB_GEO_AUTH_TOKEN_TYPE} #{signed_data}" > end > end;end;end > ``` > > With a long info/refs sleep, this yielded `Error syncing repository: 13:fetch remote: \"fatal: could not read Username for 'https://gdk.test:3443': terminal prompts disabled\\n\": exit status 128.`. > > With info/refs sleep of 5s, and validity period of -56s or -54s: `Error syncing repository: 13:fetch remote: \"fatal: could not read Username for 'https://gdk.test:3443': terminal prompts disabled\\nfatal: expected flush after ref listing\\n\": exit status 128.` > > With info/refs sleep of 5s, and validity period of -52s, sync succeeded. > > Unfortunately I haven't been able to reproduce the exact error `fatal: unable to write request to remote: Broken pipe`, but we can be pretty confident that this would be resolved by increasing the JWT expiration time. > > Please have the customer validate this assertion by running this in Rails console on the secondary site: > > ```ruby > module Gitlab; module Geo; class BaseRequest > private > def geo_auth_token(message) > signed_data = Gitlab::Geo::SignedData.new(geo_node: requesting_node, validity_period: 10.minutes).sign_and_encode_data(message) > > "#{GITLAB_GEO_AUTH_TOKEN_TYPE} #{signed_data}" > end > end;end;end > ``` > > and then in console, resync an affected project: > > ```ruby > Project.find_by_full_path('mygroup/mysubgroup/myproject').replicator.resync > ``` > > and run this to look at the sync state: > > ```ruby > Project.find_by_full_path('mygroup/mysubgroup/myproject').replicator.registry > ``` > > Note that if they are seeing other errors with the repo then this may not immediately work. This is only expected to resolve JWT authorization expiration: `"error": "fetch remote: \"fatal: could not read Username for 'https://gitlab.example.com': terminal prompts disabled\\nfatal: unable to write request to remote: Broken pipe\\n\": exit status 128",` </details> Note that you can also see this same error if your primary site's Puma node's system clock is lagging behind the secondary site's Sidekiq node's clock. ## Validate this is your issue Monkey patch the code in Rails console to increase the validity period of the token from 1 minute to 10 minutes. Run this in Rails console on the secondary site: ```ruby module Gitlab; module Geo; class BaseRequest private def geo_auth_token(message) signed_data = Gitlab::Geo::SignedData.new(geo_node: requesting_node, validity_period: 10.minutes).sign_and_encode_data(message) "#{GITLAB_GEO_AUTH_TOKEN_TYPE} #{signed_data}" end end;end;end ``` In the same Rails console, resync an affected project: ```ruby Project.find_by_full_path('mygroup/mysubgroup/myproject').replicator.resync ``` Look at the sync state: ```ruby Project.find_by_full_path('mygroup/mysubgroup/myproject').replicator.registry ``` If this issue is your issue, then `last_sync_failure` should no longer include `fatal: could not read Username`. The `state` should now be `2`, meaning synced. ## Possible workarounds ### Workaround 1 1. Hot patch Sidekiq nodes in the secondary site. Meaning, edit `/opt/gitlab/embedded/service/gitlab-rails/ee/lib/gitlab/geo/signed_data.rb` to add `, validity_period: 10.minutes` like in the monkey patch above. Then restart Sidekiq. You would have to do this after every upgrade. ### Workaround 2 If there are only a few affected projects, and if the sync is long due to "too many refs", then subsequent syncs are expected to go much faster after the first successful one. In that case: 1. SSH into a Puma/Sidekiq/Geo Log Cursor node in the secondary site 1. Open Rails console: `sudo gitlab-rails console` 1. Paste this into Rails console: ```ruby module Gitlab; module Geo; class BaseRequest private def geo_auth_token(message) signed_data = Gitlab::Geo::SignedData.new(geo_node: requesting_node, validity_period: 180.minutes).sign_and_encode_data(message) "#{GITLAB_GEO_AUTH_TOKEN_TYPE} #{signed_data}" end end;end;end ``` 1. In the same Rails console, resync an affected project: ```ruby Project.find_by_full_path('mygroup/mysubgroup/myproject').replicator.resync ``` 1. Run this to look at the sync state: ```ruby Project.find_by_full_path('mygroup/mysubgroup/myproject').replicator.registry ``` 1. If successful, then its `state` should now be `2`, meaning synced. 1. Repeat for other affected projects. 1. If the sync is long due to "too many refs" (which causes Git in the secondary site's Gitaly to take a long time to figure out which refs to ask for), then the affected projects should now sync much more quickly. ## Proposal * Weight 1: Increase the expiration length from 1 minute to 10 minutes. This was the case from GitLab [10.5](https://gitlab.com/gitlab-org/gitlab/-/merge_requests/4489 "Bump Geo JWT timeout from 1 minute to 10 minutes") until it was [accidentally reverted in 14.10](https://gitlab.com/gitlab-org/gitlab/-/commit/80e198829e65f1b29f7435e62f52d6c5d885b1bf#73be2a01ac1f9d364f3c117841b3589d21363e78_36_34 "Refactor Geo signing data logic"). Also, we should document the workarounds. In that documentation, we should link to the medium term proposal - re-introduce `redownload`. So customers can upvote or comment on it.