Fix Gitlab::Geo::LogHelpers base log data
What does this MR do and why?
- Removes usage of
host
key in logs. - Fixes exceptions in dev and test environments during any call of the Geo log helpers.
The host
key in logs is rejected by gitlab-org/ruby/gems/labkit-ruby!105 (merged) in dev and test, since 15.9 with !111590 (merged).
This shouldn't need to be backported since it doesn't affect production environments.
But if this problem is blocking something for example in a security release, then I suggest it it quite safe to cherry pick.
Fixes #393299 (closed)
Screenshots or screen recordings
For example, in Sidekiq logs when syncing a project Git repo:
Before:
Notice there is an exception message: The following log keys used are reserved: host\n\nUse key names that are descriptive e.g. by using a prefix.
{"severity":"WARN","time":"2023-02-27T19:17:02.840Z","retry":1,"queue":"default","backtrace":true,"version":0,"queue_namespace":"geo","dead":false,"args":["256","{:sync_repository=\u003etrue, :sync_wiki=\u003efalse}"],"class":"Geo::ProjectSyncWorker","jid":"153b1a4261f74855b2fb129f","created_at":"2023-02-27T19:16:15.871Z","meta.feature_category":"geo_replication","correlation_id":"3d758529caa420c180a96fe701806ed2","worker_data_consistency":"always","idempotency_key":"resque:gitlab:duplicate:default:f46a428b411d9a69741b56ee06cb207b14b37f74f2a03c2aabdb007b3ef49d14","size_limiter":"validated","enqueued_at":"2023-02-27T19:16:15.878Z","job_size_bytes":48,"pid":97019,"message":"Geo::ProjectSyncWorker JID-153b1a4261f74855b2fb129f: fail: 0.195451 sec","job_status":"fail","scheduling_latency_s":46.765309,"redis_calls":8,"redis_duration_s":0.001633,"redis_read_bytes":812,"redis_write_bytes":721,"redis_cache_calls":5,"redis_cache_duration_s":0.000968,"redis_cache_read_bytes":809,"redis_cache_write_bytes":298,"redis_queues_calls":1,"redis_queues_duration_s":0.00014,"redis_queues_read_bytes":1,"redis_queues_write_bytes":123,"redis_shared_state_calls":2,"redis_shared_state_duration_s":0.000525,"redis_shared_state_read_bytes":2,"redis_shared_state_write_bytes":300,"db_count":0,"db_write_count":0,"db_cached_count":0,"db_replica_count":0,"db_primary_count":0,"db_main_count":0,"db_ci_count":0,"db_geo_count":0,"db_main_replica_count":0,"db_ci_replica_count":0,"db_replica_cached_count":0,"db_primary_cached_count":0,"db_main_cached_count":0,"db_ci_cached_count":0,"db_geo_cached_count":0,"db_main_replica_cached_count":0,"db_ci_replica_cached_count":0,"db_replica_wal_count":0,"db_primary_wal_count":0,"db_main_wal_count":0,"db_ci_wal_count":0,"db_geo_wal_count":0,"db_main_replica_wal_count":0,"db_ci_replica_wal_count":0,"db_replica_wal_cached_count":0,"db_primary_wal_cached_count":0,"db_main_wal_cached_count":0,"db_ci_wal_cached_count":0,"db_geo_wal_cached_count":0,"db_main_replica_wal_cached_count":0,"db_ci_replica_wal_cached_count":0,"db_replica_duration_s":0.0,"db_primary_duration_s":0.0,"db_main_duration_s":0.0,"db_ci_duration_s":0.0,"db_geo_duration_s":0.0,"db_main_replica_duration_s":0.0,"db_ci_replica_duration_s":0.0,"cpu_s":0.122315,"worker_id":"sidekiq_0","rate_limiting_gates":[],"duration_s":0.195451,"completed_at":"2023-02-27T19:17:02.838Z","load_balancing_strategy":"primary","exception.class":"RuntimeError","exception.message":"The following log keys used are reserved: host\n\nUse key names that are descriptive e.g. by using a prefix.","exception.backtrace":["lib/gitlab/json_logger.rb:28:in `info'","ee/lib/gitlab/geo/log_helpers.rb:11:in `log_info'","ee/app/services/geo/repository_base_sync_service.rb:28:in `block in execute'","app/services/concerns/exclusive_lease_guard.rb:29:in `try_obtain_lease'","ee/app/services/geo/repository_base_sync_service.rb:27:in `execute'","ee/app/workers/geo/project_sync_worker.rb:54:in `sync_repository'","ee/app/workers/geo/project_sync_worker.rb:46:in `perform'","lib/gitlab/sidekiq_middleware/duplicate_jobs/strategies/until_executed.rb:17:in `perform'","lib/gitlab/sidekiq_middleware/duplicate_jobs/duplicate_job.rb:44:in `perform'","lib/gitlab/sidekiq_middleware/duplicate_jobs/server.rb:8:in `call'","lib/gitlab/sidekiq_middleware/worker_context.rb:9:in `wrap_in_optional_context'","lib/gitlab/sidekiq_middleware/worker_context/server.rb:19:in `block in call'","lib/gitlab/application_context.rb:115:in `block in use'","lib/gitlab/application_context.rb:115:in `use'","lib/gitlab/application_context.rb:55:in `with_context'","lib/gitlab/sidekiq_middleware/worker_context/server.rb:17:in `call'","lib/gitlab/sidekiq_status/server_middleware.rb:7:in `call'","lib/gitlab/sidekiq_versioning/middleware.rb:9:in `call'","lib/gitlab/sidekiq_middleware/query_analyzer.rb:7:in `block in call'","lib/gitlab/database/query_analyzer.rb:37:in `within'","lib/gitlab/sidekiq_middleware/query_analyzer.rb:7:in `call'","lib/gitlab/sidekiq_middleware/admin_mode/server.rb:14:in `call'","lib/gitlab/sidekiq_middleware/instrumentation_logger.rb:9:in `call'","lib/gitlab/sidekiq_middleware/batch_loader.rb:7:in `call'","lib/gitlab/sidekiq_middleware/extra_done_log_metadata.rb:7:in `call'","lib/gitlab/sidekiq_middleware/request_store_middleware.rb:10:in `block in call'","lib/gitlab/with_request_store.rb:17:in `enabling_request_store'","lib/gitlab/with_request_store.rb:10:in `with_request_store'","lib/gitlab/sidekiq_middleware/request_store_middleware.rb:9:in `call'","lib/gitlab/sidekiq_middleware/server_metrics.rb:76:in `block in call'","lib/gitlab/sidekiq_middleware/server_metrics.rb:103:in `block in instrument'","lib/gitlab/metrics/background_transaction.rb:33:in `run'","lib/gitlab/sidekiq_middleware/server_metrics.rb:103:in `instrument'","lib/gitlab/sidekiq_middleware/server_metrics.rb:75:in `call'","lib/gitlab/sidekiq_middleware/monitor.rb:10:in `block in call'","lib/gitlab/sidekiq_daemon/monitor.rb:46:in `within_job'","lib/gitlab/sidekiq_middleware/monitor.rb:9:in `call'","lib/gitlab/sidekiq_middleware/size_limiter/server.rb:13:in `call'","lib/gitlab/sidekiq_logging/structured_logger.rb:21:in `call'"],"db_duration_s":0.027041}
After:
Notice the job finishes without exception.
{"severity":"INFO","time":"2023-02-27T19:33:46.580Z","retry":1,"queue":"default","backtrace":true,"version":0,"queue_namespace":"geo","dead":false,"args":["256","{:sync_repository=\u003etrue, :sync_wiki=\u003efalse}"],"class":"Geo::ProjectSyncWorker","jid":"eecf580effef0117f8bbc595","created_at":"2023-02-27T19:33:46.535Z","meta.feature_category":"geo_replication","correlation_id":"f3ee2e1672a05a3536b359241718b8cb","worker_data_consistency":"always","idempotency_key":"resque:gitlab:duplicate:default:f46a428b411d9a69741b56ee06cb207b14b37f74f2a03c2aabdb007b3ef49d14","size_limiter":"validated","enqueued_at":"2023-02-27T19:33:46.551Z","job_size_bytes":48,"pid":99385,"message":"Geo::ProjectSyncWorker JID-eecf580effef0117f8bbc595: done: 0.027768 sec","job_status":"done","scheduling_latency_s":0.000685,"redis_calls":10,"redis_duration_s":0.001123,"redis_read_bytes":706,"redis_write_bytes":1468,"redis_cache_calls":4,"redis_cache_duration_s":0.000369,"redis_cache_read_bytes":607,"redis_cache_write_bytes":243,"redis_queues_calls":6,"redis_queues_duration_s":0.000754,"redis_queues_read_bytes":99,"redis_queues_write_bytes":1225,"db_count":3,"db_write_count":0,"db_cached_count":0,"db_replica_count":0,"db_primary_count":3,"db_main_count":2,"db_ci_count":0,"db_geo_count":1,"db_main_replica_count":0,"db_ci_replica_count":0,"db_replica_cached_count":0,"db_primary_cached_count":0,"db_main_cached_count":0,"db_ci_cached_count":0,"db_geo_cached_count":0,"db_main_replica_cached_count":0,"db_ci_replica_cached_count":0,"db_replica_wal_count":0,"db_primary_wal_count":0,"db_main_wal_count":0,"db_ci_wal_count":0,"db_geo_wal_count":0,"db_main_replica_wal_count":0,"db_ci_replica_wal_count":0,"db_replica_wal_cached_count":0,"db_primary_wal_cached_count":0,"db_main_wal_cached_count":0,"db_ci_wal_cached_count":0,"db_geo_wal_cached_count":0,"db_main_replica_wal_cached_count":0,"db_ci_replica_wal_cached_count":0,"db_replica_duration_s":0.0,"db_primary_duration_s":0.011,"db_main_duration_s":0.01,"db_ci_duration_s":0.0,"db_geo_duration_s":0.001,"db_main_replica_duration_s":0.0,"db_ci_replica_duration_s":0.0,"cpu_s":0.019766,"worker_id":"sidekiq_0","rate_limiting_gates":[],"duration_s":0.027768,"completed_at":"2023-02-27T19:33:46.580Z","load_balancing_strategy":"primary","db_duration_s":0.004476}
How to set up and validate locally
It appears that before this change, any Project Git repo sync will fail on log_info
. So, e.g.:
- Set up Geo
- Create a project with a repo
- Look at logs for exceptions
- Then switch to this branch and
gdk restart rails-background-jobs
- Push to a repo
- Look at logs. Those exceptions should not be there.
MR acceptance checklist
This checklist encourages us to confirm any changes have been analyzed to reduce risks in quality, performance, reliability, security, and maintainability.
-
I have evaluated the MR acceptance checklist for this MR.