GitHub importer "PG::InvalidTextRepresentation: ERROR: malformed array literal" when storing user mention
About
When importing ansible/ansible we noticed around 1k PG::InvalidTextRepresentation: ERROR: malformed array literal errors https://gitlab.com/gitlab-org/manage/import-and-integrate/discussions/-/issues/61#note_1663050116.
We can see error logs here https://cloudlogging.app.goo.gl/zigEVzzvAAKdzTfTA (at time of writing).
These errors happen in the Importer::IssueEventImporter.
They do not cause the note import to fail, as we create the note successfully but then error when we try to store the user mention. I think this only means that the list of people who are considered as "participants" on the issue/MR may be missing people when this error strikes. They should be causing the note to fail, as the error happens within after_save, so within the same transaction as the save.
Proposal
The callback that's running should actually be switched off to protect GitLab's DB https://gitlab.com/gitlab-org/gitlab/-/issues/336788 but we don't set importing: true when we create the note.
The "fix" for this should be to set that property, as it seems like we don't want that particular callback to fire (and possibly others). Ideally, we should define/use a SSOT to create notes, and make sure that SSOT sets importing: true across our importers.
External identifiers
We log the external_identifiers (GitHub object IDs) to help debug errors in the error logs.
In case the error logs disappear, here are some of those external identifiers. We should be able to use these to find the real API response for ansible/ansible for these objects to help debug the problem (for example, create a fixture to trigger the error in a test).
extra.external_identifiers: {
event: "assigned"
id: 4296916455
issuable_iid: 73505
object_type: "issue_event"
}event: "assigned"
id: 4292183255
issuable_iid: 73483
object_type: "issue_event"
}extra.external_identifiers: {
event: "assigned"
id: 10716129746
issuable_iid: 73100
object_type: "issue_event"
}Exception details
We can see error logs here https://cloudlogging.app.goo.gl/zigEVzzvAAKdzTfTA (at time of writing).
Exception Class: "ActiveRecord::StatementInvalid"
Exception Cause Class: "PG::InvalidTextRepresentation"
Exception message:
"PG::InvalidTextRepresentation: ERROR: malformed array literal: "---
- '34'
"
LINE 1: ...,"mentioned_projects_ids","issue_id","note_id") VALUES ('---
^
DETAIL: Array value must start with "{" or dimension information.
"Exception SQL:
"/*application:sidekiq,correlation_id:2964f3e67362d6f98e322bdf313aef09,jid:a9954f3dfed32f9032506a25,endpoint_id:Gitlab::GithubImport::ImportIssueEventWorker,db_config_name:main*/ INSERT INTO "issue_user_mentions" ("mentioned_users_ids","mentioned_groups_ids","mentioned_projects_ids","issue_id","note_id") VALUES ($1, $2, $3, $4, $5) ON CONFLICT ("issue_id","note_id") DO UPDATE SET "mentioned_users_ids"=excluded."mentioned_users_ids","mentioned_groups_ids"=excluded."mentioned_groups_ids","mentioned_projects_ids"=excluded."mentioned_projects_ids" RETURNING "id""Exception backtrace:
0: "lib/gitlab/database/load_balancing/connection_proxy.rb:127:in `public_send'"
1: "lib/gitlab/database/load_balancing/connection_proxy.rb:127:in `block in write_using_load_balancer'"
2: "lib/gitlab/database/load_balancing/load_balancer.rb:141:in `block in read_write'"
3: "lib/gitlab/database/load_balancing/load_balancer.rb:235:in `retry_with_backoff'"
4: "lib/gitlab/database/load_balancing/load_balancer.rb:130:in `read_write'"
5: "lib/gitlab/database/load_balancing/connection_proxy.rb:126:in `write_using_load_balancer'"
6: "lib/gitlab/database/load_balancing/connection_proxy.rb:61:in `block (2 levels) in <class:ConnectionProxy>'"
7: "app/models/concerns/cache_markdown_field.rb:180:in `store_mentions!'"
8: "lib/gitlab/database/load_balancing/connection_proxy.rb:127:in `public_send'"
9: "lib/gitlab/database/load_balancing/connection_proxy.rb:127:in `block in write_using_load_balancer'"
10: "lib/gitlab/database/load_balancing/load_balancer.rb:141:in `block in read_write'"
11: "lib/gitlab/database/load_balancing/load_balancer.rb:235:in `retry_with_backoff'"
12: "lib/gitlab/database/load_balancing/load_balancer.rb:130:in `read_write'"
13: "lib/gitlab/database/load_balancing/connection_proxy.rb:126:in `write_using_load_balancer'"
14: "lib/gitlab/database/load_balancing/connection_proxy.rb:78:in `transaction'"
15: "lib/gitlab/github_import/importer/events/changed_assignee.rb:20:in `create_note'"
16: "lib/gitlab/github_import/importer/events/changed_assignee.rb:14:in `execute'"
17: "lib/gitlab/github_import/importer/issue_event_importer.rb:21:in `execute'"
18: "app/workers/concerns/gitlab/github_import/object_importer.rb:53:in `import'"
19: "app/workers/concerns/gitlab/github_import/rescheduling_methods.rb:35:in `try_import'"
20: "app/workers/concerns/gitlab/github_import/rescheduling_methods.rb:27:in `perform'"
21: "lib/gitlab/sidekiq_middleware/skip_jobs.rb:49:in `call'"
22: "lib/gitlab/database/load_balancing/sidekiq_server_middleware.rb:29:in `call'"
23: "lib/gitlab/sidekiq_middleware/duplicate_jobs/strategies/until_executing.rb:16:in `perform'"
24: "lib/gitlab/sidekiq_middleware/duplicate_jobs/duplicate_job.rb:45:in `perform'"
25: "lib/gitlab/sidekiq_middleware/duplicate_jobs/server.rb:8:in `call'"
26: "lib/gitlab/sidekiq_middleware/pause_control/strategies/base.rb:31:in `perform'"
27: "lib/gitlab/sidekiq_middleware/pause_control/strategy_handler.rb:22:in `perform'"
28: "lib/gitlab/sidekiq_middleware/pause_control/server.rb:8:in `call'"
29: "lib/gitlab/sidekiq_middleware/worker_context.rb:9:in `wrap_in_optional_context'"
30: "lib/gitlab/sidekiq_middleware/worker_context/server.rb:19:in `block in call'"
31: "lib/gitlab/application_context.rb:130:in `block in use'"
32: "lib/gitlab/application_context.rb:130:in `use'"
33: "lib/gitlab/application_context.rb:64:in `with_context'"
34: "lib/gitlab/sidekiq_middleware/worker_context/server.rb:17:in `call'"
35: "lib/gitlab/sidekiq_status/server_middleware.rb:7:in `call'"
36: "lib/gitlab/sidekiq_versioning/middleware.rb:9:in `call'"
37: "lib/gitlab/sidekiq_middleware/query_analyzer.rb:7:in `block in call'"
38: "lib/gitlab/database/query_analyzer.rb:37:in `within'"
39: "lib/gitlab/sidekiq_middleware/query_analyzer.rb:7:in `call'"
40: "lib/gitlab/sidekiq_middleware/admin_mode/server.rb:14:in `call'"
41: "lib/gitlab/sidekiq_middleware/instrumentation_logger.rb:9:in `call'"
42: "lib/gitlab/sidekiq_middleware/batch_loader.rb:7:in `call'"
43: "lib/gitlab/sidekiq_middleware/extra_done_log_metadata.rb:7:in `call'"
44: "lib/gitlab/sidekiq_middleware/request_store_middleware.rb:8:in `block in call'"
45: "lib/gitlab/sidekiq_middleware/request_store_middleware.rb:7:in `call'"
46: "lib/gitlab/sidekiq_middleware/server_metrics.rb:105:in `block in call'"
47: "lib/gitlab/sidekiq_middleware/server_metrics.rb:133:in `block in instrument'"
48: "lib/gitlab/metrics/background_transaction.rb:33:in `run'"
49: "lib/gitlab/sidekiq_middleware/server_metrics.rb:133:in `instrument'"
50: "lib/gitlab/sidekiq_middleware/server_metrics.rb:104:in `call'"
51: "lib/gitlab/sidekiq_middleware/monitor.rb:10:in `block in call'"
52: "lib/gitlab/sidekiq_daemon/monitor.rb:46:in `within_job'"
53: "lib/gitlab/sidekiq_middleware/monitor.rb:9:in `call'"
54: "lib/gitlab/sidekiq_middleware/size_limiter/server.rb:13:in `call'"
55: "lib/gitlab/sidekiq_logging/structured_logger.rb:21:in `call'"