https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41794 --- Comment #1 from Manos PETRIDIS <egpetridis@yahoo.com> --- Created attachment 192678 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=192678&action=edit intranet-error.log -- You are receiving this mail because: You are watching all bug changes. You are the assignee for the bug.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41794 Manos PETRIDIS <egpetridis@yahoo.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Severity|enhancement |normal -- You are receiving this mail because: You are the assignee for the bug. You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41794 --- Comment #3 from Katrin Fischer <katrin.fischer@bsz-bw.de> --- Please check your configuration for the AdditionalFieldsInZ3950Result system preference. It says there is some invalid code in there. -- You are receiving this mail because: You are watching all bug changes. You are the assignee for the bug.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41794 Katrin Fischer <katrin.fischer@bsz-bw.de> changed: What |Removed |Added ---------------------------------------------------------------------------- Resolution|--- |INVALID Status|NEW |RESOLVED -- You are receiving this mail because: You are the assignee for the bug. You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41794 --- Comment #6 from Manos PETRIDIS <egpetridis@yahoo.com> --- Created attachment 192811 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=192811&action=edit results example 2 -- You are receiving this mail because: You are the assignee for the bug. You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41794 Manos PETRIDIS <egpetridis@yahoo.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Resolution|INVALID |--- Status|RESOLVED |REOPENED --- Comment #8 from Manos PETRIDIS <egpetridis@yahoo.com> --- Thank you for the time and attention! I failed to notice the pointer to the error in the logs. I beg to differ however, the issue is neither invalid nor resolved. AdditionalFieldsInZ3950Result value is "022$a, 040$a, 082$a2, 092$a2, 245$abc, 247$a, 260$abc, 440$a, 500a, 600$a, 650$avxyz2, 651$avxyz2". Which part is erroneous, and why? Are any of these fields noted in a do-not-use list somewhere in koha documentation? If indeed the value above was an "invalid expression", then we wouldn't get any results. Please note attached examples of result pages. It seems that some servers/targets include garbage/erroneous data in their replies, and koha is unable to report the fact, recover and proceed to the next server in the list. In order to make things clearer, one may * make koha report on the targets sucessfully queried, * make koha not stumble when encountering erroneous replies from z39.50 targets * make koha note in the logs the target raising the error. You may recreate the error by querying LOC for title "koha" or keyword "koha", using the AdditionalFieldsInZ3950Result value above. -- You are receiving this mail because: You are the assignee for the bug. You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41794 --- Comment #10 from Manos PETRIDIS <egpetridis@yahoo.com> --- Created attachment 192947 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=192947&action=edit z39.50 search result page, showing 500$a info AdditionalFieldsInZ3950ResultSearch value now is "022$a, 040$a, 082$a2, 092$a2, 245$abc, 247$a, 260$abc, 440$a, 500$a, 600$a, 650$avxyz2, 651$avxyz2". This is reflected in image #4, where we can see that field 500$a is shown in the results, when searching against known "safe" targets. -- You are receiving this mail because: You are the assignee for the bug. You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41794 Manos PETRIDIS <egpetridis@yahoo.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #192677|0 |1 is obsolete| | --- Comment #12 from Manos PETRIDIS <egpetridis@yahoo.com> --- Created attachment 192948 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=192948&action=edit Intranet access log -- You are receiving this mail because: You are watching all bug changes. You are the assignee for the bug.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41794 Manos PETRIDIS <egpetridis@yahoo.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #192678|0 |1 is obsolete| | --- Comment #14 from Manos PETRIDIS <egpetridis@yahoo.com> --- Created attachment 192949 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=192949&action=edit intranet error log -- You are receiving this mail because: You are the assignee for the bug. You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41794 --- Comment #16 from Manos PETRIDIS <egpetridis@yahoo.com> --- Created attachment 192951 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=192951&action=edit OPAC access log -- You are receiving this mail because: You are watching all bug changes. You are the assignee for the bug.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41794 --- Comment #18 from Manos PETRIDIS <egpetridis@yahoo.com> --- Same error appears having selected English (en) interface. Tried to modify /usr/share/local/lib/C4/Breeding.pm so that it would write to a log in /tmp just before querying each z39.50 target, but I have still to get an output. -- You are receiving this mail because: You are watching all bug changes. You are the assignee for the bug.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41794 --- Comment #20 from Manos PETRIDIS <egpetridis@yahoo.com> --- Correct, 192.168.0.0 are private networks, the newer logs however were created accessing the server's external address. -- You are receiving this mail because: You are the assignee for the bug. You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41794 --- Comment #22 from Marcel de Rooy <m.de.rooy@rijksmuseum.nl> --- Hi Manos, The attachment should be formatted as a git patch file. (AI should be able to handle that as well :) It contains about 300 lines of new code. Since you 'authored' the patch, we would expect you to test it and understand what AI actually changed here. Note that is not clear yet how our workflow should adapt to AI. -- You are receiving this mail because: You are the assignee for the bug. You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41794 --- Comment #23 from Manos PETRIDIS <egpetridis@yahoo.com> --- Documentation of changes and reasoning behind them, from same "author": The starting point was Koha 26.05.x's stock Z3950Search(). In the upstream code, Koha builds an asynchronous ZOOM connection for every selected target, then waits for completion events via ZOOM::event(). It checks the target diagnostic, obtains the result-set size, and then retrieves individual records. Record handling passes through _handle_one_result(), which performs raw-record extraction, MARC/MARCXML decoding, character-set conversion, optional XSLT processing, reservoir import, and transformation to Koha fields. Purpose of the modification The modification was intended to solve two related operational problems: - Identify exactly which Z39.50 target is responsible for an error or abnormal response. - Prevent one faulty, slow, malformed, or obsolete target from causing the entire multi-target Z39.50 search to terminate with HTTP 500. This is particularly relevant when Koha searches hundreds of Z39.50 targets concurrently. The diagnostic log subsequently demonstrated that many targets are dead or slow—some return Connect failed, others time out, while valid targets continue returning successful results. z3950_queried_targets Summary of changes: Diagnostic logging Stock Koha behaviour: Minimal/no per-target trace Modified behaviour: Detailed target and result logging Initial connection/search Stock Koha behaviour: Exception may propagate Modified behaviour: Isolated with eval Failed launch Stock Koha behaviour: Could disrupt array processing Modified behaviour: Logged and excluded cleanly ZOOM event processing Stock Koha behaviour: Unprotected Modified behaviour: Protected with eval Z39.50 diagnostics Stock Koha behaviour: Mostly error code only Modified behaviour: Full code/message/additional info/diagnostic set Result-set size Stock Koha behaviour: Unprotected Modified behaviour: Protected Empty result set Stock Koha behaviour: Normal Modified behaviour: Explicitly logged as successful Record retrieval Stock Koha behaviour: Unprotected Modified behaviour: eval + 20-second hard timeout MARC/charset/XSLT/import Stock Koha behaviour: Unprotected as a whole Modified behaviour: eval + 20-second hard timeout Malformed record Stock Koha behaviour: Could potentially cause HTTP 500 Modified behaviour: Logged; offending target result set abandoned Target timeout Stock Koha behaviour: Only if configured Modified behaviour: Default 15 seconds if unspecified Asynchronous processing Stock Koha behaviour: Existing Koha design Modified behaviour: Preserved 1. Dedicated Z39.50 diagnostic logger A new private function was added: sub _z3950_debug_log { ... } It obtains Koha's configured log directory using: C4::Context->config('logdir') and writes to: z3950_queried_targets.log This usually resolves to: /var/log/koha/{instancename}/z3950_queried_targets.log Each record contains: - timestamp; - event/status; - Koha Z39.50 target ID; - configured target name; - server type (zed or SRU); - hostname; - TCP port; - database name; - event-specific diagnostic information. For example: TARGET_ERROR id="..." target="..." host="..." port="..." errcode="10007" errmsg="Timeout" The logger uses: sysopen(... O_WRONLY | O_CREAT | O_APPEND ...) and: flock($fh, LOCK_EX) The reason for flock() is that multiple Koha CGI processes could potentially write to the same log simultaneously. Exclusive locking prevents their output from becoming interleaved. Newlines are removed from exception/error strings before logging so that one diagnostic event remains one physical log line. This makes the file suitable for grep, awk, later automated analysis, etc. Failure of the diagnostic logger itself does not terminate the Z39.50 request. It only emits a Perl warn. 2. Logging before any communication with a target The stock loop begins approximately as follows: foreach my $server (@servers) { ... $oConnection[$s] = _create_connection($server); ... } In the modified version, immediately before _create_connection() we added: _z3950_debug_log( $server, 'QUERY_START', '' ); This placement is deliberate. QUERY_START means: Koha is now about to attempt communication with this particular target. It is logged before ZOOM is given an opportunity to connect. Therefore, even if _create_connection() or search_pqf() throws an exception, the target responsible for that operation is already recorded. After ZOOM has successfully accepted the asynchronous search operation, another event is written: QUERY_QUEUED So: QUERY_START QUERY_QUEUED means that the asynchronous request was successfully constructed and submitted to ZOOM. This distinction was necessary because merely logging targets selected by the operator does not establish whether Koha actually reached the point of issuing the request. 3. Connection/search launch isolated with eval Originally Koha directly performs: _create_connection($server); ... search_pqf(...) The modified version executes those operations inside: my $launch_ok = eval { ... 1; }; If Perl/ZOOM throws an exception, it is caught rather than propagating to Apache and becoming HTTP 500. The failure is logged as: QUERY_ERROR stage=launch exception="..." and is also placed into Koha's existing @errconn structure. The incomplete ZOOM objects are destroyed where possible: eval { $result->destroy() if $result }; eval { $connection->destroy() if $connection }; and processing proceeds to the next target. Why this was necessary With a large target list it is entirely reasonable that some target definitions will refer to: - retired systems; - hosts no longer resolving; - closed Z39.50 ports; - invalid databases; - authentication-required services; Servers returning protocol errors. Such a target should be treated as one failed search source, not as a fatal failure of the entire Koha request. 4. Introduction of @active_servers This is a subtle but important change. Stock Koha relies on three arrays having identical indexes: @servers @oConnection @oResult If we simply used: next; when launching one target failed, those arrays would become misaligned. For example: servers[5] = Server F connection[5] = Server G The diagnostic log could then attribute Server G's error to Server F. To avoid that, the modified version introduces: my @active_servers; Only successfully launched targets are added to: @oConnection @oResult @active_servers simultaneously. Thus: $active_servers[$k] $oConnection[$k] $oResult[$k] always refer to the same target. This is essential because ZOOM searches are asynchronous: responses do not necessarily arrive in the same order in which the queries were launched. 5. Protection around ZOOM::event() Koha waits for asynchronous completion using: ZOOM::event( \@oConnection ) The modified version wraps the event operation in eval. If ZOOM itself raises an exception while servicing the connection set, the exception no longer immediately becomes an HTTP 500. An important limitation was deliberately preserved: If ZOOM::event() itself fails before identifying a connection index, the exception cannot reliably be attributed to a particular target. Therefore such an error is written through warn, and processing continues where possible rather than falsely blaming a server. This was chosen over manufacturing a target association that might be incorrect. 6. Full Z39.50 diagnostic capture The stock Koha code effectively uses: my ($error) = $oConnection[$k]->error_x(); and therefore normally concentrates on the numeric error code. The modification retrieves all four diagnostic elements: my @diags = $oConnection[$k]->error_x(); These correspond to: errcode errmsg addinfo diagset The log can therefore distinguish, for example: errcode="10000" errmsg="Connect failed" diagset="ZOOM" from a genuine Bib-1 application diagnostic such as: errcode="101" errmsg="Access-control failure" addinfo="...Failed to authenticate user..." diagset="Bib-1" The actual test log confirms both kinds occur. It contains ordinary network failures as well as server-generated protocol diagnostics. z3950_queried_targets This distinction is valuable operationally: - ZOOM 10000 Connect failed → network/host/service problem; - ZOOM 10007 Timeout → target did not answer within the configured time; - Bib-1 101 Access-control failure → server answered, but rejected the request; - other Bib-1 diagnostics → application/protocol problem. 7. Explicit distinction between a successful empty search and an error After an error-free target completion, Koha executes: $numresults = $oResult[$k]->size(); We wrapped that call in eval, because result-set access itself is an external-library operation and can theoretically raise an exception. If successful, the diagnostic log records: TARGET_SUCCESS ... hits=N Crucially: TARGET_SUCCESS ... hits=0 is explicitly considered successful. That was intentional. A Z39.50 server which correctly says: I searched successfully and found no records. must not be confused with a target which: - could not be reached; - timed out; - returned an invalid result set; - sent a protocol diagnostic. 8. Protection of individual Z39.50 Present / record retrieval operations A Z39.50 search and a Z39.50 record retrieval are not necessarily the same network transaction. Calling: $oResult[$k]->record($i) can cause a Z39.50 Present operation to be sent to the target. Therefore a target might: successfully execute Search; report N hits; fail only when Koha requests record number 1, 2, etc. The modified version wraps record retrieval in: eval { local $SIG{ALRM} = sub { die "record retrieval timeout after 20 seconds\n"; }; alarm 20; $zoomrec = $oResult[$k]->record($i); alarm 0; }; There are thus two independent protections: the ZOOM connection timeout; a Perl-side 20-second hard guard around record retrieval. A failure is recorded as: RESULT_ERROR stage=retrieve record=N exception="..." and then: TARGET_ABORTED reason=record_retrieval_error The remainder of that target's record set is skipped, while processing of other targets continues. Why abort the target rather than merely skip one record? A retrieval failure often indicates that the server's result-set/Present state has become unreliable. Repeatedly requesting subsequent records from the same damaged result set could cause repeated stalls or exceptions. Therefore the safer policy is: preserve already accepted results from that server, abandon the remainder of its result set, continue with all other servers. 9. Isolation of _handle_one_result() This is arguably the most important defensive modification. In stock Koha, a returned record is passed directly to: _handle_one_result(...) without an exception boundary around the complete operation. That function performs several processing stages: ZOOM raw record ↓ MARC / MARCXML decoding ↓ character-set conversion ↓ SetUTF8Flag ↓ optional XSLT ↓ GetZ3950BatchId ↓ AddBiblioToBatch ↓ TransformMarcToKoha The upstream implementation shows these stages explicitly. Therefore malformed non-empty data could potentially fail at several places: $zoomrec->raw(); MARC::Record->new_from_xml(); MarcToUTF8Record(); malformed MARC structure; unexpected character encoding; XSLT transformation; MARC serialization; reservoir/database import; subsequent transformation to Koha fields. The modified version encloses the complete call in: eval { ... } with an additional: alarm 20; guard. If an exception or pathological processing delay occurs, it is recorded as: RESULT_ERROR stage=parse_import record=N exception="..." followed by: TARGET_ABORTED reason=malformed_record The target's remaining records are abandoned and Koha continues processing other result sets. This directly addresses the original requirement: bad data from one external target must not make the complete multi-target search fail. 10. XSLT errors are distinguished from exceptions Koha's _do_xslt_proc() already has a controlled error-return mechanism. It can return the original MARC record together with an XSLT error rather than necessarily throwing an exception. Therefore, after _handle_one_result() succeeds as a Perl call, the modified code also checks its returned $error. If present, it logs: RESULT_ERROR stage=xslt If not, the result is recorded as: RESULT_SUCCESS record=N This distinction matters because: exception during parsing/import and: controlled XSLT processing error are fundamentally different failure classes. 11. Preservation of Koha 26.05.02 empty-record behaviour Koha 26.05.x already contains logic corresponding to the fix for empty Z39.50 results: next unless $diags[0]; In other words, if: $oResult[$k]->record($i) returns no record and no ZOOM diagnostic exists, Koha treats that as an empty response rather than as a fatal condition. We retained that behaviour. The only change was to make it visible diagnostically: RESULT_EMPTY record=N If there is an accompanying diagnostic, it instead becomes: RESULT_ERROR record=N errcode=... errmsg=... Thus an empty response is not falsely classified as an error. 12. Default ZOOM timeout changed to 15 seconds Stock Koha 26.05.x uses: $option1->option( 'timeout', $server->{timeout} ) if $server->{timeout}; That means a target with no configured timeout receives no explicit ZOOM timeout from Koha. We changed this to: $option1->option( 'timeout', $server->{timeout} || 15 ); The logic is therefore: Configured target timeout exists ↓ use configured value No target timeout configured ↓ use 15 seconds Reasoning With hundreds of targets, a few servers which do not terminate properly can dramatically extend the total CGI execution time. The 15-second value is deliberately a compromise: - long enough for a reasonably slow public Z39.50 server; - short enough that dead targets do not occupy the search indefinitely. 13. Existing asynchronous Z39.50 design was preserved We did not convert Koha into sequential Z39.50 searching and ultimately did not introduce a two-second artificial pause between targets. That is important. Koha intentionally uses: $option1->option( 'async' => 1 ); and: ZOOM::event(...) so many Z39.50 requests can be outstanding simultaneously. Serializing hundreds of targets would make a large search prohibitively slow. Instead, the modification preserves the asynchronous architecture while adding: - target attribution; - exception isolation; - timeouts; - detailed logging. 14. What was not changed The following core Koha behaviour remains unchanged: - query construction (_bib_build_query); - PQF searching for Z39.50 targets; - CQL handling for SRU; - asynchronous ZOOM operation; - configured preferred record syntax; - configured authentication; - configured target database; - target-specific XSLT; - reservoir/breeding import; - 20-result pagination per target; - @breeding_loop result presentation; - Koha's existing @errconn mechanism; - cataloguing/acquisitions use of Z3950Search(). The intention was defensive hardening and diagnostics, not a redesign of Koha's cataloguing reservoir. Meaning of the new log events For documentation purposes, I would define the event vocabulary as follows: Log event Meaning QUERY_START Koha is about to create/contact this target QUERY_QUEUED ZOOM accepted the asynchronous search QUERY_ERROR Connection/search could not even be launched TARGET_SUCCESS hits=N Search completed without a Z39.50 diagnostic; N may be zero TARGET_ERROR Target/network/protocol/result-set level failure RESULT_SUCCESS Individual returned record completed Koha processing RESULT_EMPTY Target supplied no record and no ZOOM diagnostic RESULT_ERROR stage=retrieve Failure during Z39.50 Present/record acquisition RESULT_ERROR stage=parse_import Exception during MARC decode/charset/XSLT/import processing RESULT_ERROR stage=xslt Controlled XSLT error returned by Koha TARGET_ABORTED Remaining records from that target deliberately skipped This allows a log to identify the failure stage much more precisely than a generic HTTP 500. -- You are receiving this mail because: You are the assignee for the bug. You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=41794 David Cook <dcook@prosentient.com.au> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|REOPENED |In Discussion -- You are receiving this mail because: You are the assignee for the bug. You are watching all bug changes.