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.