QA » openQA Project

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.

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

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

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.

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.

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)?

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?

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

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

Reproducer by @tinita: https://gist.github.com/perlpunk/7e96f3070a31c5f28a32a2d94ac4d634

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