Geo log helpers broken in dev and test
Problem
Exception in Geo-related Sidekiq jobs: The following log keys used are reserved: host\n\nUse key names that are descriptive e.g. by using a prefix.
The exception is due to this line https://gitlab.com/gitlab-org/gitlab/-/blob/0a0031bb5c88b76b5583bb13a8945fd4b2ec4d97/ee/lib/gitlab/geo/log_helpers.rb#L32.
Called by e.g. log_info
at https://gitlab.com/gitlab-org/gitlab/-/blob/0a0031bb5c88b76b5583bb13a8945fd4b2ec4d97/ee/app/services/geo/repository_base_sync_service.rb#L28.
E.g. a ProjectSyncWorker
job locally:
{"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}
Proposal
The host
key in logs is rejected by gitlab-org/ruby/gems/labkit-ruby!105 (merged) in dev and test, since !111590 (merged).
So, rename the host
key to gitlab_host
similar to another change in !111590 (merged).