QA (public) » openQA Project (public)

Reoccurred today:

[2024-10-20T16:25:05.567628Z] [error] [NtIj5y1ehJJS] Can't call method "BUILD" on an undefined value at /usr/share/openqa/script/../lib/OpenQA/WebAPI/Plugin/AMQP.pm line 93.

[2024-10-21T15:22:59.751468Z] [error] [CzG_2DyxpwId] Can't call method "BUILD" on an undefined value at /usr/share/openqa/script/../lib/OpenQA/WebAPI/Plugin/AMQP.pm line 93. 

[2024-10-22T10:51:21.780582Z] [error] [GjyMrlB_8Q6x] Can't call method "BUILD" on an undefined value at /usr/share/openqa/script/../lib/OpenQA/WebAPI/Plugin/AMQP.pm line 93. 

[2024-10-26T21:20:55.269574Z] [error] [tBsyR_oI8awR] Can't call method "BUILD" on an undefined value at /usr/share/openqa/script/../lib/OpenQA/WebAPI/Plugin/AMQP.pm line 93. 

I had a quick look into /var/log/openqa.* and it really helps to see the context. The message is now always accompanied by this:

[2024-10-26T21:20:55.261543Z] [debug] [pid:7820] GruTask 20710984 already gone, skip assigning jobs (message: DBIx::Class::Storage::DBI::_dbh_execute(): DBI Exception: DBD::Pg::st execute failed: ERROR:  insert
 or update on table "gru_dependencies" violates foreign key constraint "gru_dependencies_fk_gru_task_id"
DETAIL:  Key (gru_task_id)=(20710984) is not present in table "gru_tasks". [for Statement "INSERT INTO gru_dependencies ( gru_task_id, job_id) VALUES ( ?, ? )" with ParamValues: 1='20710984', 2='4597848'] at /u
sr/share/openqa/script/../lib/OpenQA/Shared/Plugin/Gru.pm line 149
)
[2024-10-26T21:20:55.269574Z] [error] [tBsyR_oI8awR] Can't call method "BUILD" on an undefined value at /usr/share/openqa/script/../lib/OpenQA/WebAPI/Plugin/AMQP.pm line 93.

The first message is an expected debug message when we try to insert a gru job for each job in the list but the main grutask is already gone.

Now this should be easier to reproduce, with a bit of fiddling.

Always check the openqa log file for context.
Not sure what the original context from 1.5 years ago was.

Interesting facts:
The job from two days ago is https://openqa.opensuse.org/tests/4597848 which does not exist anymore.
I can see from the audit event that it was an investigate job:
https://openqa.opensuse.org/admin/auditlog?eventid=51487851
"OPENQA_INVESTIGATE_ORIGIN": "http://openqa.opensuse.org/t4597369"
Now if I look at its comments, it does not show the comment with the list of investigate jobs, but still shows the intermediate Starting investigation for job 4597369 comment which is supposed to be deleted/overwritten by openqa-investigate:
https://openqa.opensuse.org/tests/4597369#comments

and in the gru journal at that time I see:

Oct 26 21:20:55 ariel openqa-gru[22019]: openqa-clone-job (81 /opt/os-autoinst-scripts/openqa-investigate): (openqa-clone-job --json-output --skip-chained-deps --max-depth 0 --parental-inheritance --within-instance http://openqa.opensuse.org/tests/4591363 TEST+=:investigate:last_good_build:20241023 _TRIGGER_JOB_DONE_HOOK=1 _GROUP_ID=0 BUILD= OPENQA_INVESTIGATE_ORIGIN=http://openqa.opensuse.org/t4597369) stderr: >>>Failed to create job, server replied: { error_status => 500 }<<<
Oct 26 21:20:55 ariel openqa-gru[22019]: openqa-clone-job (81 /opt/os-autoinst-scripts/openqa-investigate): (openqa-clone-job --json-output --skip-chained-deps --max-depth 0 --parental-inheritance --within-instance http://openqa.opensuse.org/tests/4591363 TEST+=:investigate:last_good_build:20241023 _TRIGGER_JOB_DONE_HOOK=1 _GROUP_ID=0 BUILD= OPENQA_INVESTIGATE_ORIGIN=http://openqa.opensuse.org/t4597369) rc: 255 >>><<<

Could it be that the transaction is actually rolled back because of the database failure? wrapping it in an eval might not be enough.
So that could be the reason why the job is never added to the database and the AMQP event tries to retrieve it from the database and doesn't find it.

https://github.com/os-autoinst/openQA/pull/6028 Handle foreign key violation with savepoint
https://www.postgresql.org/docs/current/sql-savepoint.html
https://metacpan.org/pod/DBIx::Class::Storage#svp_begin