action #53435

[logwarn] o3: DBI Exception: number of parameters must be between 0 and 65535 in lib/OpenQA/WebAPI/Controller/API/V1/Job.pm line 133

Added by okurz 8 months ago. Updated 6 months ago.

Status:ResolvedStart date:21/06/2019
Priority:NormalDue date:
Assignee:mkittler% Done:

0%

Category:Concrete Bugs
Target version:Done
Difficulty:
Duration:

Description

Observation

This nearly killed my email client, from o3 monitoring in /var/log/openqa:

[2019-06-21T09:25:50.0548 UTC] [error] DBIx::Class::Storage::DBI::_dbh_execute(): DBI Exception: DBD::Pg::st execute failed: number of parameters must be between 0 and 65535 [for Statement "SELECT me.job_id, me.asset_id, me.created_by, me.t_created, me.t_updated, asset.id, asset.type, asset.name, asset.size, asset.checksum, asset.last_use_job_id, asset.fixed, asset.t_created, asset.t_updated FROM jobs_assets me  JOIN assets asset ON asset.id = me.asset_id WHERE ( job_id IN ( ?, … ) )" with ParamValues: 1='934057', 2='775775', 3='774972', 4='852279', 5='937661', 6='957555', 7='924633', 8='869768', 9='889133', 10='865729',… 80516='740865'] at /usr/share/openqa/script/../lib/OpenQA/WebAPI/Controller/API/V1/Job.pm line 133

Problem

Looks like one of the reasons why people preferred to ditch sqlite which couldn't handle more than 5k jobs, postgres's limit seems to be at 216 ;)

https://github.com/os-autoinst/openQA/blob/master/lib/OpenQA/WebAPI/Controller/API/V1/Job.pm#L133 is within the method "list" trying to iterative over the assets of jobs:

132:    my $jas = $schema->resultset('JobsAssets')->search({job_id => {in => [keys %jobs]}}, {prefetch => ['asset']});
133:    while (my $ja = $jas->next) {

History

#2 Updated by okurz 8 months ago

  • Priority changed from Normal to High

these messages unfortunately pass the logwarn filter and clog up the o3-admins mailing list input channel because they are so big. Trying to display these emails with my email client kmail is even a challenge. I would appreciate if we can look into this soon.

#3 Updated by okurz 8 months ago

[2019-07-10T10:58:26.0989 UTC] is the last timestamp I found.

But actually it does not happen that often:

# grep 'must be between' /var/log/openqa | grep 2019-0[67]- | cut -c -100
[2019-06-21T09:25:50.0548 UTC] [error] DBIx::Class::Storage::DBI::_dbh_execute(): DBI Exception: DBD
[2019-06-25T16:35:55.0844 UTC] [error] DBIx::Class::Storage::DBI::_dbh_execute(): DBI Exception: DBD
[2019-06-25T16:36:18.0171 UTC] [error] DBIx::Class::Storage::DBI::_dbh_execute(): DBI Exception: DBD
[2019-06-25T16:36:34.0783 UTC] [error] DBIx::Class::Storage::DBI::_dbh_execute(): DBI Exception: DBD
[2019-07-10T10:57:13.0747 UTC] [error] DBIx::Class::Storage::DBI::_dbh_execute(): DBI Exception: DBD
[2019-07-10T10:58:26.0989 UTC] [error] DBIx::Class::Storage::DBI::_dbh_execute(): DBI Exception: DBD

I wonder if that is an external request triggering it or something from openQA or internal to o3 itself. With this low number of occurences I don't think we can find something easily in apache access logs.

#4 Updated by okurz 8 months ago

  • Priority changed from High to Normal

https://github.com/os-autoinst/openqa-logwarn/pull/12 created to at least cut the overly long lines in reporting.

#5 Updated by mkittler 8 months ago

  • Assignee set to mkittler

One can reproduce this locally with an o3 dump using script/client --host localhost:9526 jobs. We could split the query but returning that much data (the JSON object contains the settings for each job!) makes no sense. So I would simply limit it.

#6 Updated by mkittler 8 months ago

  • Status changed from New to In Progress
  • Target version set to Current Sprint

#7 Updated by mkittler 8 months ago

  • Status changed from In Progress to Resolved

PR has been merged

#8 Updated by mkittler 6 months ago

  • Target version changed from Current Sprint to Done

Also available in: Atom PDF