Skip to content

Fix Gitlab::Geo::LogHelpers base log data

Michael Kozono requested to merge mk/fix-geo-loghelpers-exceptions into master

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.:

  1. Set up Geo
  2. Create a project with a repo
  3. Look at logs for exceptions
  4. Then switch to this branch and gdk restart rails-background-jobs
  5. Push to a repo
  6. 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.

Edited by Michael Kozono

Merge request reports