New subject: [Bug 34070] background_jobs_worker.pl floods logs when not connecting

20 Jun 2023

      https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=34070

            Bug ID: 34070
           Summary: background_jobs_worker.pl fills logs when not
                    connecting
 Change sponsored?: ---
           Product: Koha
           Version: 22.11
          Hardware: All
                OS: All
            Status: NEW
          Severity: major
          Priority: P5 - low
         Component: Architecture, internals, and plumbing
          Assignee: koha-bugs@lists.koha-community.org
          Reporter: magnus@libriotech.no
        QA Contact: testopia@bugs.koha-community.org

I noticed my disk was filling up, because worker-output.log was getting several
hundred of these per second: 

[2023/06/20 18:21:24] [WARN] Frame not processed - malformed JSON string,
neither tag, array, object, number, string or atom, at character offset 0
(before "You must log in usin...") at
/usr/share/koha/bin/background_jobs_worker.pl line 116.
 main::catch {...}  /usr/share/koha/bin/background_jobs_worker.pl (119)

I think the problem is related to this code: 

106 while (1) {
107     if ( $conn ) {
108         my $frame = $conn->receive_frame;
109         if ( !defined $frame ) {
110             # maybe log connection problems
111             next;    # will reconnect automatically
112         }
113 
114         my $args = try {
115             my $body = $frame->body;
116             decode_json($body); # TODO Should this be from_json? Check utf8
flag.
117         } catch {
118             Koha::Logger->get({ interface => 'worker' })->warn(sprintf
"Frame not processed - %s", $_);
119             return;
120         } finally {
121             $conn->ack( { frame => $frame } );
122         };
123 
124         next unless $args;
125 
126         # FIXME This means we need to have create the DB entry before
127         # It could work in a first step, but then we will want to handle
job that will be created from the message received
128         my $job = Koha::BackgroundJobs->find($args->{job_id});

There is a problem with the connection, but $conn is still defined, so this
code is run. When I Dump $conn after line 107 it looks like this:

$VAR1 = bless( {
                 'bufsize' => 8192,
                 'logger' => bless( {
                                      'warn' => 1,
                                      'error' => 1,
                                      'fatal' => 1
                                    }, 'Net::Stomp::StupidLogger' ),
                 '_framebuf_changed' => 1,
                 'port' => '61613',
                 'connect_delay' => 5,
                 '_pid' => ***,
                 'hostname' => 'localhost',
                 'reconnect_attempts' => 0,
                 'reconnect_on_fork' => 1,
                 'select' => bless( [
                                      '�',
                                      1,
                                      undef,
                                      undef,
                                      undef,
                                      undef,
                                      undef,
                                      undef,
                                      undef,
                                      bless( \*Symbol::GEN0, 'IO::Socket::IP' )
                                    ], 'IO::Select' ),
                 'socket' => $VAR1->{'select'}[9],
                 'initial_reconnect_attempts' => 1,
                 '_framebuf' => '',
                 'socket_options' => {},
                 'subscriptions' => {
                                      'dest-/queue/koha_***-default' => {

'ack' => 'client',

'destination' => '/queue/koha_***-default',

'prefetch-count' => 1
                                                                             }
                                    }
               }, 'Net::Stomp' );

If I dump the contents of $body after line 115, I get 'You must log in using
CONNECT first'. Not sure why that happens yet, but how we handle it seems to be
problematic. We fail to decode it, because it is not JSON. So the "catch" block
is run and logs the problem. But then I think the "return" kicks us back to the
start of the "while" and we end up logging the same error as fast as we can,
which seems to be pretty fast. And we never get to the "ack" on line 121.

The comment "will reconnect automatically" seems to be a little optimistic? 

Moving the "return" from the end of the "catch" block, to the end of the
"finally" block slows things down, now the logging only happens about every
other second.

But there is also a problem because we are assigning the "output" from the
try/catch to $args. If we can decode_json the $body, that works as expected.
But if we execute the "catch" block, it looks like $args gets assigned the
result of Koha::Logger->get, which seems to be 1. So $args is defined on line
124 and we get to Koha::BackgroundJobs->find, but using "1" as a hashref there
does not work. 

I think maybe something like this would work better: 

         my $args;
         try {
             my $body = $frame->body;
             $args = decode_json($body); # TODO Should this be from_json? Check
utf8 flag.
         } catch {
             Koha::Logger->get({ interface => 'worker' })->warn(sprintf "Frame
not processed - %s", $_);
         } finally {
             $conn->ack( { frame => $frame } );
             return;
         };

Is the return needed? This is a little above my head, so other solutions are
most welcome. And if anyone can tell me why I get 'You must log in using
CONNECT first' I would be most grateful. :-)

-- 
You are receiving this mail because:
You are watching all bug changes.
You are the assignee for the bug.

[Bug 34070] New: background_jobs_worker.pl fills logs when not connecting

tags

participants (1)