Project

General

Profile

Actions

action #108272

closed

openQA 25-cache-client.t fails in OBS

Added by tinita over 2 years ago. Updated over 2 years ago.

Status:
Resolved
Priority:
High
Assignee:
Category:
Regressions/Crashes
Target version:
Start date:
2022-03-14
Due date:
2022-03-29
% Done:

0%

Estimated time:

Description

https://build.opensuse.org/public/build/devel:openQA/openSUSE_Factory/x86_64/openQA

[  565s] [2022-03-14 03:52:18.73990] [5685] [error] [iOHlpNdWlJyJ] DBD::SQLite::db do failed: SQL logic error at /usr/lib/perl5/vendor_perl/5.34.0/Mojo/SQLite.pm line 118.
[  565s] 
[  565s] 
[  565s]     #   Failed test 'no error'
[  565s]     #   at ./t/25-cache-client.t line 60.
[  565s] 
[  565s]     #   Failed test 'has Minion id'
[  565s]     #   at ./t/25-cache-client.t line 61.
[  565s]     # Looks like you failed 2 tests of 2.
[  565s] 
[  565s] #   Failed test 'Enqueue'
[  565s] #   at ./t/25-cache-client.t line 72.
[  565s] DBD::SQLite::db prepare_cached failed: no such table: minion_jobs at /usr/lib/perl5/vendor_perl/5.34.0/Minion/Backend/SQLite.pm line 138.
[  565s]  at /usr/lib/perl5/vendor_perl/5.34.0/Minion/Backend/SQLite.pm line 138.
[  565s] # Tests were run but no plan was declared and done_testing() was not seen.
[  565s] # Looks like your test exited with 29 just after 2.
[  565s] ./t/25-cache-client.t ....................................... 
[  565s] # Subtest: Enqueue
[  565s]     not ok 1 - no error
[  565s]     not ok 2 - has Minion id
[  565s]     1..2
[  565s] not ok 1 - Enqueue
[  565s] ok 2 - no (unexpected) warnings (via END block)
[  565s] Dubious, test returned 29 (wstat 7424, 0x1d00)
[  565s] Failed 1/2 subtests 

This happens since March 12, and only for Tumbleweed and Factory.

One related module that has been updated is DBD::SQLite: https://build.opensuse.org/request/show/960440 (for https://bugzilla.opensuse.org/show_bug.cgi?id=1195771)

Workarounds to roll-back

Actions #1

Updated by tinita over 2 years ago

  • Project changed from openQA Infrastructure to openQA Project
  • Category set to Regressions/Crashes
Actions #2

Updated by mkittler over 2 years ago

  • Description updated (diff)
Actions #3

Updated by mkittler over 2 years ago

  • Assignee set to mkittler
Actions #4

Updated by mkittler over 2 years ago

  • Description updated (diff)

To reduce the urgency I've created a link in our devel repos via osc linkpac --revision=47 openSUSE:Factory perl-DBD-SQLite devel:openQA: https://build.opensuse.org/package/show/devel:openQA/perl-DBD-SQLite

Actions #5

Updated by tinita over 2 years ago

It's likely that the problem comes from this request: https://build.opensuse.org/request/show/960440

It is patching DBD::SQlite to use the system version of sqlite instead of the one that the module ships with.

Actions #6

Updated by tinita over 2 years ago

I commented here that we are currently having problems: https://bugzilla.opensuse.org/show_bug.cgi?id=1195771

Actions #7

Updated by mkittler over 2 years ago

I also pinned the package in our sub projects to the previous rev via osc linkpac --force --revision=47 openSUSE:Factory perl-DBD-SQLite devel:openQA:Leap:15.3 perl-DBD-SQLite and osc linkpac --force --revision=47 openSUSE:Factory perl-DBD-SQLite devel:openQA:SLE-15 perl-DBD-SQLite

Actions #8

Updated by mkittler over 2 years ago

  • Description updated (diff)
Actions #9

Updated by mkittler over 2 years ago

  • Description updated (diff)
Actions #10

Updated by kraih over 2 years ago

tinita wrote:

It's likely that the problem comes from this request: https://build.opensuse.org/request/show/960440

Agreed. If that change stays we'll probably have many similar issues in the future.

Actions #11

Updated by kraih over 2 years ago

That line is the auto-migration btw., so it happens during the migration step.

[  565s] [2022-03-14 03:52:18.73990] [5685] [error] [iOHlpNdWlJyJ] DBD::SQLite::db do failed: SQL logic error at /usr/lib/perl5/vendor_perl/5.34.0/Mojo/SQLite.pm line 118.
Actions #12

Updated by mkittler over 2 years ago

Fixing this in TW or even upstream likely takes a while so I'm currently focusing on making the CI work again regardless. The linking didn't help with the OBS checks so I've created: https://github.com/os-autoinst/openQA/pull/4557

Agreed. If that change stays we'll probably have many similar issues in the future.

I suppose that'll be the case, indeed. Maybe we can at least add further tests within perl-DBD-SQLite itself to uncover problems early (and not only in tests of the openQA package)?

Actions #13

Updated by mkittler over 2 years ago

  • Status changed from New to In Progress
Actions #14

Updated by mkittler over 2 years ago

That's how it looks like with DBI_TRACE=1:

# Subtest: Enqueue
    <- ping= ( 1 ) [1 items] at SQLite.pm line 81
    <- EXISTS('RaiseError')= ( 1 ) [1 items] at Migrations.pm line 112
    <- FETCH('RaiseError')= ( 1 ) [1 items] at Migrations.pm line 112
    <- STORE('RaiseError', 0)= ( 1 ) [1 items] at Migrations.pm line 112
    <> FETCH('HandleError')= ( CODE(0x55b6ef429278) ) [1 items] ('HandleError' from cache) at Database.pm line 58
    <- EXISTS('HandleError')= ( 1 ) [1 items] at Database.pm line 60
    <> FETCH('HandleError')= ( CODE(0x55b6ef429278) ) [1 items] ('HandleError' from cache) at Database.pm line 60
    <- STORE('HandleError', CODE(0x55b6ef651e00))= ( 1 ) [1 items] at Database.pm line 60
    <- prepare_cached('select version from mojo_migrations where name = ?', undef, ...)= ( DBI::st=HASH(0x55b6ef451448) ) [1 items] at Database.pm line 67
    <- bind_param(1, 'minion')= ( 1 ) [1 items] at Database.pm line 123
    <- execute= ( '0E0' ) [1 items] at Database.pm line 69
    <> FETCH('private_mojo_refcount')= ( 0 ) [1 items] ('private_mojo_refcount' from cache) at Results.pm line 14
    <- STORE('private_mojo_refcount', 1)= ( 1 ) [1 items] at Results.pm line 14
    <> FETCH('private_mojo_last_insert_id')= ( 1 ) [1 items] ('private_mojo_last_insert_id' from cache) at Database.pm line 82
    <- STORE('HandleError', CODE(0x55b6ef429278))= ( 1 ) [1 items] at Database.pm line 85
    <- STORE('RaiseError', 1)= ( 1 ) [1 items] at Migrations.pm line 114
    <- fetchrow_arrayref= ( undef ) [1 items] at Results.pm line 24
    <- err= ( undef ) [1 items] at Migrations.pm line 120
    <> FETCH('HandleError')= ( CODE(0x55b6ef429278) ) [1 items] ('HandleError' from cache) at Database.pm line 58
    <- EXISTS('HandleError')= ( 1 ) [1 items] at Database.pm line 60
    <> FETCH('HandleError')= ( CODE(0x55b6ef429278) ) [1 items] ('HandleError' from cache) at Database.pm line 60
    <- STORE('HandleError', CODE(0x55b6ef651e90))= ( 1 ) [1 items] at Database.pm line 60
    <- prepare_cached('insert into mojo_migrations values (?, ?)', undef, ...)= ( DBI::st=HASH(0x55b6ef450cb0) ) [1 items] at Database.pm line 67
    <- bind_param(1, 'minion')= ( 1 ) [1 items] at Database.pm line 123
    <- bind_param(2, 0)= ( 1 ) [1 items] at Database.pm line 123
    <- STORE('private_mojo_last_insert_id', 2)= ( 1 ) [1 items] at SQLite.pm line 95
    <- execute= ( 1 ) [1 items] at Database.pm line 69
    <> FETCH('private_mojo_refcount')= ( 0 ) [1 items] ('private_mojo_refcount' from cache) at Results.pm line 14
    <- STORE('private_mojo_refcount', 1)= ( 1 ) [1 items] at Results.pm line 14
    <> FETCH('private_mojo_last_insert_id')= ( 2 ) [1 items] ('private_mojo_last_insert_id' from cache) at Database.pm line 82
    <> FETCH('private_mojo_refcount')= ( 1 ) [1 items] ('private_mojo_refcount' from cache) at Results.pm line 21
    <- STORE('private_mojo_refcount', 0)= ( 1 ) [1 items] at Results.pm line 21
    <> FETCH('private_mojo_refcount')= ( 0 ) [1 items] ('private_mojo_refcount' from cache) at Results.pm line 21
    <- finish= ( 1 ) [1 items] at Results.pm line 21
    <- STORE('HandleError', CODE(0x55b6ef429278))= ( 1 ) [1 items] at Database.pm line 85
    <> FETCH('private_mojo_refcount')= ( 1 ) [1 items] ('private_mojo_refcount' from cache) at Results.pm line 21
    <- STORE('private_mojo_refcount', 0)= ( 1 ) [1 items] at Results.pm line 21
    <> FETCH('private_mojo_refcount')= ( 0 ) [1 items] ('private_mojo_refcount' from cache) at Results.pm line 21
    <- finish= ( 1 ) [1 items] at Results.pm line 21
    <- begin_work= ( 1 ) [1 items] at Transaction.pm line 19
    <- EXISTS('RaiseError')= ( 1 ) [1 items] at Migrations.pm line 112
    <- FETCH('RaiseError')= ( 1 ) [1 items] at Migrations.pm line 112
    <- STORE('RaiseError', 0)= ( 1 ) [1 items] at Migrations.pm line 112
    <> FETCH('HandleError')= ( CODE(0x55b6ef429278) ) [1 items] ('HandleError' from cache) at Database.pm line 58
    <- EXISTS('HandleError')= ( 1 ) [1 items] at Database.pm line 60
    <> FETCH('HandleError')= ( CODE(0x55b6ef429278) ) [1 items] ('HandleError' from cache) at Database.pm line 60
    <- STORE('HandleError', CODE(0x55b6ef651fe0))= ( 1 ) [1 items] at Database.pm line 60
    <- prepare_cached('select version from mojo_migrations where name = ?', undef, ...)= ( DBI::st=HASH(0x55b6ef451448) ) [1 items] at Database.pm line 67
    <- bind_param(1, 'minion')= ( 1 ) [1 items] at Database.pm line 123
    <- execute= ( '0E0' ) [1 items] at Database.pm line 69
    <> FETCH('private_mojo_refcount')= ( 0 ) [1 items] ('private_mojo_refcount' from cache) at Results.pm line 14
    <- STORE('private_mojo_refcount', 1)= ( 1 ) [1 items] at Results.pm line 14
    <> FETCH('private_mojo_last_insert_id')= ( 2 ) [1 items] ('private_mojo_last_insert_id' from cache) at Database.pm line 82
    <- STORE('HandleError', CODE(0x55b6ef429278))= ( 1 ) [1 items] at Database.pm line 85
    <- STORE('RaiseError', 1)= ( 1 ) [1 items] at Migrations.pm line 114
    <- fetchrow_arrayref= ( [ 0 ] ) [1 items] row1 at Results.pm line 24
    <> FETCH('private_mojo_refcount')= ( 1 ) [1 items] ('private_mojo_refcount' from cache) at Results.pm line 21
    <- STORE('private_mojo_refcount', 0)= ( 1 ) [1 items] at Results.pm line 21
    <> FETCH('private_mojo_refcount')= ( 0 ) [1 items] ('private_mojo_refcount' from cache) at Results.pm line 21
    <- finish= ( 1 ) [1 items] at Results.pm line 21
    <- EXISTS('sqlite_allow_multiple_statements')= ( 1 ) [1 items] at Migrations.pm line 66
    <- FETCH('sqlite_allow_multiple_statements')= ( 0 ) [1 items] at Migrations.pm line 66
    <- STORE('sqlite_allow_multiple_statements', 1)= ( 1 ) [1 items] at Migrations.pm line 66
    <- sqlite_update_hook(undef)= ( CODE(0x55b6ef404e80) ) [1 items] at Migrations.pm line 69
    !! ERROR: 1 'SQL logic error' (err#2)
    <- do("-- 1 up
create table if not exists minion_jobs (
  id       integer not null primary key autoincrement,
  args     blob not null,
  created  text not null default current_timestamp,
  delayed  text not null,
  finished text,
  priority integer not null,
  result   blob,
  retried  text,
  retries  integer not null default 0,
  started  text,
  state    text not null default 'inactive',
  task     text not null,
  worker   integer,
  queue    text not null default 'default'
);
create index if not exists minion_jobs_priority_created on minion_jobs (priority desc, created);
create index if not exists minion_jobs_state on minion_jobs (state);
create table if not exists minion_workers (
  id       integer not null primary key autoincrement,
  host     text not null,
  pid      integer not null,
  started  text not null default current_timestamp,
  notified text not null default current_timestamp
);

-- 2 up
alter table minion_jobs add column attempts integer not null default 1;

-- 3 u...")= ( undef ) [1 items] at Migrations.pm line 75
    -> HandleError on DBI::db=HASH(0x55b6ef428ca8) via CODE(0x55b6ef429278) (undef)
    <- HandleError= 0 (undef)
    !! The ERROR '1' was CLEARED by call to sqlite_update_hook method
    <- sqlite_update_hook(CODE(0x55b6ef404e80))= ( undef ) [1 items] at Migrations.pm line 80
    <- STORE('sqlite_allow_multiple_statements', 0)= ( 1 ) [1 items] at Carp.pm line 291
    <- rollback= ( 1 ) [1 items] at Transaction.pm line 26
    <- FETCH('Active')= ( 1 ) [1 items] at SQLite.pm line 109
[2022-03-14 13:28:57.18178] [7766] [error] [LFlC6V9bJbEy] DBD::SQLite::db do failed: SQL logic error at /usr/lib/perl5/vendor_perl/5.34.0/Mojo/SQLite.pm line 118.

    not ok 1 - no error

It looks like the handling of -- N marks is messed up. Maybe a problem of Mojo::SQLite after all?

Actions #15

Updated by mkittler over 2 years ago

  • Priority changed from Urgent to High

Lowering the prio because https://github.com/os-autoinst/openQA/pull/4557 has been merged.

Btw, I configured my fork following https://openbuildservice.org/2021/05/31/scm-integration, pushed https://github.com/os-autoinst/openQA/pull/4557 on master of my fork and created the arbitrary PR https://github.com/Martchus/openQA/pull/2 there. This worked just fine so I'm confident https://github.com/os-autoinst/openQA/pull/4557 helps. However, I still have to test out whether it helps for existing PRs. (The OBS integration needed to change the project config for this according to new changes on master.) Rebasing existing PR should help, the OBS integration updates the project config accordingly (e.g. https://build.opensuse.org/repositories/devel:openQA:GitHub:os-autoinst:openQA:PR-4555).

Actions #16

Updated by kraih over 2 years ago

Worth mentioning that the cache service migration works fine, it is the Minion::Backend::SQLite one that fails afterwards.

Actions #17

Updated by kraih over 2 years ago

Upstream ticket tracking the same problem. https://github.com/Grinnz/Minion-Backend-SQLite/issues/20

Actions #19

Updated by openqa_review over 2 years ago

  • Due date set to 2022-03-29

Setting due date based on mean cycle time of SUSE QE Tools

Actions #20

Updated by mkittler over 2 years ago

  • Status changed from In Progress to Feedback

The fix is on its way (https://build.opensuse.org/request/show/961697) so we'll just have to wait.

Actions #21

Updated by mkittler over 2 years ago

The fixed sqlite3 package is in TW and it works (tested locally). So I've reverted the workarounds.

Actions #22

Updated by mkittler over 2 years ago

  • Status changed from Feedback to Resolved
Actions

Also available in: Atom PDF