Actions
action #57287
closedLimit assets task fails violating database key constraint
Description
Log from Minion dashboard:
{
"args" => [],
"attempts" => 1,
"children" => [],
"created" => "2019-09-24T06:37:17.66909Z",
"delayed" => "2019-09-24T06:37:17.66909Z",
"finished" => "2019-09-24T06:38:08.36978Z",
"id" => 261890,
"notes" => {
"gru_id" => 27376226,
"ttl" => 172800
},
"parents" => [],
"priority" => 10,
"queue" => "default",
"result" => {
"error" => "\$VAR1 = bless( {\n 'msg' => 'OpenQA::Task::Asset::Limit::_limit(): DBI Exception: DBD::Pg::st execute failed: ERROR: insert or update on table \"assets\" violates foreign key constraint \"assets_fk_last_use_job_id\"\nDETAIL: Key (last_use_job_id)=(3397396) is not present in table \"jobs\". [for Statement \"UPDATE assets SET last_use_job_id = ? WHERE id = ?\" with ParamValues: 1=\\'3397396\\', 2=\\'791810\\'] at /usr/share/openqa/script/../lib/OpenQA/Task/Asset/Limit.pm line 25\n'\n }, 'DBIx::Class::Exception' );\n"
},
"retried" => undef,
"retries" => 0,
"started" => "2019-09-24T06:37:17.69231Z",
"state" => "failed",
"task" => "limit_assets",
"time" => "2019-09-24T10:54:56.24295Z",
"worker" => 196
}
Updated by coolo over 4 years ago
the job was deleted through the API while the task was running - so restart when this happens?
Updated by okurz over 4 years ago
could this become racy when we restart tasks while multiple jobs are deleted? Would it be ok to simply wait for the next task or are subsequent tasks very cheap?
Updated by coolo over 4 years ago
Of course this is racy and we want to avoid locking the tables - so we will have to catch the exceptions. So far the limit_assets tasks are run more frequent than necessary so just exiting the task if there is a problem is good enough.
But there is another ticket to run it on a timer base - then we'd have to restart the task, so I guess even now restarting the task is the better approach.
Updated by mkittler over 4 years ago
- Status changed from New to In Progress
- Assignee set to mkittler
- Target version changed from Ready to Current Sprint
Updated by mkittler over 4 years ago
Another instance of the problem:
{
"args" => [],
"attempts" => 1,
"children" => [],
"created" => "2019-09-27T07:56:32.25331Z",
"delayed" => "2019-09-27T07:56:32.25331Z",
"finished" => "2019-09-27T07:56:35.34779Z",
"id" => 263466,
"notes" => {
"gru_id" => 27377799,
"ttl" => 172800
},
"parents" => [],
"priority" => 10,
"queue" => "default",
"result" => {
"error" => "\$VAR1 = bless( {\n 'msg' => 'DBIx::Class::Storage::DBI::_dbh_execute(): DBI Exception: DBD::Pg::st execute failed: ERROR: duplicate key value violates unique constraint \"assets_type_name\"\nDETAIL: Key (type, name)=(iso, SLE-12-SP5-SDK-DVD-x86_64-Build0268-Media1.iso) already exists. [for Statement \"INSERT INTO assets ( name, t_created, t_updated, type) VALUES ( ?, ?, ?, ? ) RETURNING id\" with ParamValues: 1=\\'SLE-12-SP5-SDK-DVD-x86_64-Build0268-Media1.iso\\', 2=\\'2019-09-27 07:56:32\\', 3=\\'2019-09-27 07:56:32\\', 4=\\'iso\\'] at /usr/share/openqa/script/../lib/OpenQA/Schema/ResultSet/Assets.pm line 61\n'\n }, 'DBIx::Class::Exception' );\n",
"output" => "[debug] [pid:6873] [DBIC] Took 0.01458800 seconds: SELECT me.id, me.type, me.name, me.size, me.checksum, me.last_use_job_id, me.fixed, me.t_created, me.t_updated FROM assets me WHERE ( type = ? ): 'iso'\n[info] [pid:6873] Registering asset iso/SLE-12-SP5-SDK-DVD-ppc64le-Build0268-Media1.iso\n[debug] [pid:6873] [DBIC] Took 0.00081800 seconds: SELECT me.id, me.type, me.name, me.size, me.checksum, me.last_use_job_id, me.fixed, me.t_created, me.t_updated FROM assets me WHERE ( ( me.name = ? AND me.type = ? ) ): 'SLE-12-SP5-SDK-DVD-ppc64le-Build0268-Media1.iso', 'iso'\n[debug] [pid:6873] [DBIC] Took 0.00137100 seconds: INSERT INTO assets ( name, t_created, t_updated, type) VALUES ( ?, ?, ?, ? ) RETURNING id: 'SLE-12-SP5-SDK-DVD-ppc64le-Build0268-Media1.iso', '2019-09-27 07:56:32', '2019-09-27 07:56:32', 'iso'\n[info] [pid:6873] Registering asset iso/SLE-12-SP5-HA-DVD-x86_64-Build0149-Media1.iso\n[debug] [pid:6873] [DBIC] Took 0.01329400 seconds: SELECT me.id, me.type, me.name, me.size, me.checksum, me.last_use_job_id, me.fixed, me.t_created, me.t_updated FROM assets me WHERE ( ( me.name = ? AND me.type = ? ) ): 'SLE-12-SP5-HA-DVD-x86_64-Build0149-Media1.iso', 'iso'\n[debug] [pid:6873] [DBIC] Took 0.00062100 seconds: INSERT INTO assets ( name, t_created, t_updated, type) VALUES ( ?, ?, ?, ? ) RETURNING id: 'SLE-12-SP5-HA-DVD-x86_64-Build0149-Media1.iso', '2019-09-27 07:56:32', '2019-09-27 07:56:32', 'iso'\n[info] [pid:6873] Registering asset iso/SLE-12-SP5-Server-DVD-ppc64le-Build0339-Media1.iso\n[debug] [pid:6873] [DBIC] Took 0.00041800 seconds: SELECT me.id, me.type, me.name, me.size, me.checksum, me.last_use_job_id, me.fixed, me.t_created, me.t_updated FROM assets me WHERE ( ( me.name = ? AND me.type = ? ) ): 'SLE-12-SP5-Server-DVD-ppc64le-Build0339-Media1.iso', 'iso'\n[debug] [pid:6873] [DBIC] Took 0.00046400 seconds: INSERT INTO assets ( name, t_created, t_updated, type) VALUES ( ?, ?, ?, ? ) RETURNING id: 'SLE-12-SP5-Server-DVD-ppc64le-Build0339-Media1.iso', '2019-09-27 07:56:32', '2019-09-27 07:56:32', 'iso'\n[info] [pid:6873] Registering asset iso/SLE-12-SP5-HA-GEO-DVD-s390x-x86_64-Build0119-Media.iso\n[debug] [pid:6873] [DBIC] Took 0.00055100 seconds: SELECT me.id, me.type, me.name, me.size, me.checksum, me.last_use_job_id, me.fixed, me.t_created, me.t_updated FROM assets me WHERE ( ( me.name = ? AND me.type = ? ) ): 'SLE-12-SP5-HA-GEO-DVD-s390x-x86_64-Build0119-Media.iso', 'iso'\n[debug] [pid:6873] [DBIC] Took 0.00038800 seconds: INSERT INTO assets ( name, t_created, t_updated, type) VALUES ( ?, ?, ?, ? ) RETURNING id: 'SLE-12-SP5-HA-GEO-DVD-s390x-x86_64-Build0119-Media.iso', '2019-09-27 07:56:32', '2019-09-27 07:56:32', 'iso'\n[info] [pid:6873] Registering asset iso/SLE-12-SP5-WE-DVD-x86_64-Build0162-Media1.iso\n[debug] [pid:6873] [DBIC] Took 0.00034900 seconds: SELECT me.id, me.type, me.name, me.size, me.checksum, me.last_use_job_id, me.fixed, me.t_created, me.t_updated FROM assets me WHERE ( ( me.name = ? AND me.type = ? ) ): 'SLE-12-SP5-WE-DVD-x86_64-Build0162-Media1.iso', 'iso'\n[debug] [pid:6873] [DBIC] Took 0.00028300 seconds: INSERT INTO assets ( name, t_created, t_updated, type) VALUES ( ?, ?, ?, ? ) RETURNING id: 'SLE-12-SP5-WE-DVD-x86_64-Build0162-Media1.iso', '2019-09-27 07:56:32', '2019-09-27 07:56:32', 'iso'\n[info] [pid:6873] Registering asset iso/SLE-12-SP5-Server-DVD-aarch64-Build0339-Media1.iso\n[debug] [pid:6873] [DBIC] Took 0.00034000 seconds: SELECT me.id, me.type, me.name, me.size, me.checksum, me.last_use_job_id, me.fixed, me.t_created, me.t_updated FROM assets me WHERE ( ( me.name = ? AND me.type = ? ) ): 'SLE-12-SP5-Server-DVD-aarch64-Build0339-Media1.iso', 'iso'\n[debug] [pid:6873] [DBIC] Took 0.00031300 seconds: INSERT INTO assets ( name, t_created, t_updated, type) VALUES ( ?, ?, ?, ? ) RETURNING id: 'SLE-12-SP5-Server-DVD-aarch64-Build0339-Media1.iso', '2019-09-27 07:56:32', '2019-09-27 07:56:32', 'iso'\n[info] [pid:6873] Registering asset iso/SLE-12-SP5-SDK-DVD-aarch64-Build0268-Media1.iso\n[debug] [pid:6873] [DBIC] Took 0.00037900 seconds: SELECT me.id, me.type, me.name, me.size, me.checksum, me.last_use_job_id, me.fixed, me.t_created, me.t_updated FROM assets me WHERE ( ( me.name = ? AND me.type = ? ) ): 'SLE-12-SP5-SDK-DVD-aarch64-Build0268-Media1.iso', 'iso'\n[debug] [pid:6873] [DBIC] Took 0.00028700 seconds: INSERT INTO assets ( name, t_created, t_updated, type) VALUES ( ?, ?, ?, ? ) RETURNING id: 'SLE-12-SP5-SDK-DVD-aarch64-Build0268-Media1.iso', '2019-09-27 07:56:32', '2019-09-27 07:56:32', 'iso'\n[info] [pid:6873] Registering asset iso/SLE-12-SP5-SAP-DVD-x86_64-Build0312-Media1.iso\n[debug] [pid:6873] [DBIC] Took 0.00022400 seconds: SELECT me.id, me.type, me.name, me.size, me.checksum, me.last_use_job_id, me.fixed, me.t_created, me.t_updated FROM assets me WHERE ( ( me.name = ? AND me.type = ? ) ): 'SLE-12-SP5-SAP-DVD-x86_64-Build0312-Media1.iso', 'iso'\n[debug] [pid:6873] [DBIC] Took 0.00022500 seconds: INSERT INTO assets ( name, t_created, t_updated, type) VALUES ( ?, ?, ?, ? ) RETURNING id: 'SLE-12-SP5-SAP-DVD-x86_64-Build0312-Media1.iso', '2019-09-27 07:56:32', '2019-09-27 07:56:32', 'iso'\n[info] [pid:6873] Registering asset iso/SLE-12-SP5-SAP-DVD-ppc64le-Build0312-Media1.iso\n[debug] [pid:6873] [DBIC] Took 0.00036600 seconds: SELECT me.id, me.type, me.name, me.size, me.checksum, me.last_use_job_id, me.fixed, me.t_created, me.t_updated FROM assets me WHERE ( ( me.name = ? AND me.type = ? ) ): 'SLE-12-SP5-SAP-DVD-ppc64le-Build0312-Media1.iso', 'iso'\n[debug] [pid:6873] [DBIC] Took 0.00030600 seconds: INSERT INTO assets ( name, t_created, t_updated, type) VALUES ( ?, ?, ?, ? ) RETURNING id: 'SLE-12-SP5-SAP-DVD-ppc64le-Build0312-Media1.iso', '2019-09-27 07:56:32', '2019-09-27 07:56:32', 'iso'\n[info] [pid:6873] Registering asset iso/SLE-12-SP5-HA-DVD-ppc64le-Build0149-Media1.iso\n[debug] [pid:6873] [DBIC] Took 0.00032300 seconds: SELECT me.id, me.type, me.name, me.size, me.checksum, me.last_use_job_id, me.fixed, me.t_created, me.t_updated FROM assets me WHERE ( ( me.name = ? AND me.type = ? ) ): 'SLE-12-SP5-HA-DVD-ppc64le-Build0149-Media1.iso', 'iso'\n[debug] [pid:6873] [DBIC] Took 0.00030200 seconds: INSERT INTO assets ( name, t_created, t_updated, type) VALUES ( ?, ?, ?, ? ) RETURNING id: 'SLE-12-SP5-HA-DVD-ppc64le-Build0149-Media1.iso', '2019-09-27 07:56:32', '2019-09-27 07:56:32', 'iso'\n[info] [pid:6873] Registering asset iso/SLE-12-SP5-Server-MINI-ISO-x86_64-Build0339-Media.iso\n[debug] [pid:6873] [DBIC] Took 0.00027700 seconds: SELECT me.id, me.type, me.name, me.size, me.checksum, me.last_use_job_id, me.fixed, me.t_created, me.t_updated FROM assets me WHERE ( ( me.name = ? AND me.type = ? ) ): 'SLE-12-SP5-Server-MINI-ISO-x86_64-Build0339-Media.iso', 'iso'\n[debug] [pid:6873] [DBIC] Took 0.00035600 seconds: INSERT INTO assets ( name, t_created, t_updated, type) VALUES ( ?, ?, ?, ? ) RETURNING id: 'SLE-12-SP5-Server-MINI-ISO-x86_64-Build0339-Media.iso', '2019-09-27 07:56:32', '2019-09-27 07:56:32', 'iso'\n[info] [pid:6873] Registering asset iso/SLE-12-SP5-Server-DVD-x86_64-Build0339-Media1.iso\n[debug] [pid:6873] [DBIC] Took 0.00026300 seconds: SELECT me.id, me.type, me.name, me.size, me.checksum, me.last_use_job_id, me.fixed, me.t_created, me.t_updated FROM assets me WHERE ( ( me.name = ? AND me.type = ? ) ): 'SLE-12-SP5-Server-DVD-x86_64-Build0339-Media1.iso', 'iso'\n[debug] [pid:6873] [DBIC] Took 0.00024200 seconds: INSERT INTO assets ( name, t_created, t_updated, type) VALUES ( ?, ?, ?, ? ) RETURNING id: 'SLE-12-SP5-Server-DVD-x86_64-Build0339-Media1.iso', '2019-09-27 07:56:32', '2019-09-27 07:56:32', 'iso'\n[info] [pid:6873] Registering asset iso/SLE-12-SP5-HA-DVD-s390x-Build0149-Media1.iso\n[debug] [pid:6873] [DBIC] Took 0.00023400 seconds: SELECT me.id, me.type, me.name, me.size, me.checksum, me.last_use_job_id, me.fixed, me.t_created, me.t_updated FROM assets me WHERE ( ( me.name = ? AND me.type = ? ) ): 'SLE-12-SP5-HA-DVD-s390x-Build0149-Media1.iso', 'iso'\n[debug] [pid:6873] [DBIC] Took 0.00021400 seconds: INSERT INTO assets ( name, t_created, t_updated, type) VALUES ( ?, ?, ?, ? ) RETURNING id: 'SLE-12-SP5-HA-DVD-s390x-Build0149-Media1.iso', '2019-09-27 07:56:32', '2019-09-27 07:56:32', 'iso'\n[info] [pid:6873] Registering asset iso/SLE-12-SP5-SDK-DVD-x86_64-Build0268-Media1.iso\n[debug] [pid:6873] [DBIC] Took 0.00024200 seconds: SELECT me.id, me.type, me.name, me.size, me.checksum, me.last_use_job_id, me.fixed, me.t_created, me.t_updated FROM assets me WHERE ( ( me.name = ? AND me.type = ? ) ): 'SLE-12-SP5-SDK-DVD-x86_64-Build0268-Media1.iso', 'iso'\n"
},
"retried" => undef,
"retries" => 0,
"started" => "2019-09-27T07:56:32.2584Z",
"state" => "failed",
"task" => "limit_assets",
"time" => "2019-09-30T09:38:33.61567Z",
"worker" => 198
}
This time it is a unique key constraint. I guess for the sake of the ticket is doesn't matter whether it is a unique for foreign key constraint. So I'm implementing a retry in any case.
Updated by mkittler over 4 years ago
Updated by okurz over 4 years ago
- Status changed from In Progress to Feedback
PR merged. I guess we should wait until we see some verification of issues not appearing anymore in production
Updated by mkittler over 4 years ago
- Status changed from Feedback to In Progress
2nd PR: https://github.com/os-autoinst/openQA/pull/2373
Because we still see
{
"args" => [],
"attempts" => 1,
"children" => [],
"created" => "2019-10-02T12:16:36.78359Z",
"delayed" => "2019-10-02T12:16:36.78359Z",
"finished" => "2019-10-02T12:16:36.97373Z",
"id" => 265100,
"notes" => {
"gru_id" => 27379428,
"ttl" => 172800
},
"parents" => [],
"priority" => 10,
"queue" => "default",
"result" => {
"error" => "\$VAR1 = bless( {\n 'msg' => 'DBIx::Class::Storage::DBI::_dbh_execute(): DBI Exception: DBD::Pg::st execute failed: ERROR: duplicate key value violates unique constraint \"assets_type_name\"\nDETAIL: Key (type, name)=(iso, SUSE-Enterprise-Storage-6-DVD-x86_64-Build5.88-Media1.iso) already exists. [for Statement \"INSERT INTO assets ( name, t_created, t_updated, type) VALUES ( ?, ?, ?, ? ) RETURNING id\" with ParamValues: 1=\\'SUSE-Enterprise-Storage-6-DVD-x86_64-Build5.88-Media1.iso\\', 2=\\'2019-10-02 12:16:36\\', 3=\\'2019-10-02 12:16:36\\', 4=\\'iso\\'] at /usr/share/openqa/script/../lib/OpenQA/Schema/ResultSet/Assets.pm line 61\n'\n }, 'DBIx::Class::Exception' );\n"
},
"retried" => undef,
"retries" => 0,
"started" => "2019-10-02T12:16:36.78959Z",
"state" => "failed",
"task" => "limit_assets",
"time" => "2019-10-02T13:09:21.546Z",
"worker" => 267
}
on OSD.
Updated by mkittler over 4 years ago
- Status changed from In Progress to Resolved
- Target version changed from Current Sprint to Done
Let's re-open if failed job occur on the minion dashboard again. Until then I'll consider it resolved.
Actions