Stop reporting a failed semantic search as a slow model

The search page has two ways to print "The model took too long, so this
search used words only", and only one of them is about the model.

SemanticQuery answers TimedOut when Ollama does not return a query vector
inside EMBED_TIMEOUT. That one is honest. MessageThreadRepository::cheapRows()
answered the same TimedOut when the vector arm blew its 5s statement budget —
by which point the model had already answered, in milliseconds, and is sitting
in ai_call_metric marked a success. An operator reading that sentence goes to
the model host, where there is nothing to find.

SemanticQuery's own docblock guards the mirror image of this: the embedding is
done in the controller so that a slow model is never reported as a database
fault. This was the same confusion pointing the other way, and it is the worse
direction, because it names a machine that is working.

Worse, the catch was on DriverException, which is every driver fault Postgres
can raise. DBAL's PostgreSQL ExceptionConverter maps deadlocks, constraint
violations and syntax errors onto dedicated classes and lets 57014 fall through
to a plain DriverException, so "the budget fired" and "the query is broken"
arrived as the same type. A missing plmail_embed_distance(), a stored width
that disagrees with its vector, a connection dropped mid-statement: all
deterministic, all degrading every search instantly and for as long as the
cause stands, all reported as an occasional overrun — and none of them logged
anywhere at all, because the exception was discarded unnamed.

So: SearchTooSlow for a real cancellation, SearchFailed for everything else,
each with its own sentence in all three catalogues, and both logged with their
SQLSTATE. The repository gets its first logger for it. A rare give-up path that
leaves no trace is indistinguishable from a common one, which is how this
stayed invisible.

The new test drops plmail_embed_distance inside the test transaction rather
than making the query slow, so it cannot pass by accident on a busy machine:
42883 is not 57014 under any load.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

docs/de/features/mail.md

@@ -1,4 +1,4 @@
-<!-- translated-from: features/mail.md sha1:2b3becdea14254b65aaa211e8e71ee2b8963bad2 -->
+<!-- translated-from: features/mail.md sha1:75906ba33b88ccd8efd121f0ba99cfa471a42b57 -->
 
 # Mail
 
@@ -347,7 +347,10 @@ sich, bevor du die Ergebnisse beurteilst:
 |---|---|
 | *Bedeutung wird über 4.120 von 48.900 Nachrichten durchsucht — zu 8% fertig* | Der Index wird noch aufgebaut. Was er noch nicht erreicht hat, ist über die Bedeutung noch nicht auffindbar — die Antwort wird also von allein besser. |
 | *Das Such-Modell hat sich geändert …* | Jeder Vektor, der vor der Änderung gespeichert wurde, gehört zu einem anderen Modell und ist mit dem neuen nicht vergleichbar. Bis das Postfach neu indexiert ist, wird nichts nach Bedeutung durchsucht. |
-| *… deshalb wurde nur nach Wörtern gesucht* | Der Durchgang lief nicht: der Modell-Host hat nicht geantwortet, das Modell liegt nicht darauf, es hat zu lange gedauert, oder die Funktion ist ohne Host eingeschaltet. Deine Ergebnisse sind die der normalen Suche, vollständig und richtig. |
+| *Das Modell hat zu lange gebraucht …* / *der Modell-Host hat nicht geantwortet …* / *hat das Such-Modell nicht …* / *kein Modell-Host eingerichtet …* | Der Durchgang hat nie einen Vektor bekommen, und der Satz sagt, woran es lag. Alle vier drehen sich um den **Modell-Host**; die Suche selbst wurde nie danach gefragt. |
+| *Die Suche nach Bedeutung hat hier zu lange gebraucht …* | Der Vektor war da, und die **Datenbank** hat es innerhalb ihrer fünf Sekunden nicht geschafft, ihn zu verrechnen. Am Modell-Host liegt es nicht — hier ist das Postfach größer oder die Maschine beschäftigter, als das Zeitbudget erlaubt. |
+| *Die Suche nach Bedeutung konnte nicht abgeschlossen werden …* | Die Abfrage ist nicht in der Zeit gescheitert, sondern überhaupt — sie wird bei jeder Suche scheitern, bis jemand nachsieht. Der Grund steht im Server-Log, als Fehler, mit seinem SQLSTATE. |
+| *… deshalb wurde nur nach Wörtern gesucht* (bei allen oben) | Woran es auch lag: deine Ergebnisse sind die der normalen Suche, vollständig und richtig. Es fehlt nur der zusätzliche Durchgang. |
 | *hat nichts gefunden, was die Wörter nicht schon hatten* | Er lief, über einen fertigen Index, und hatte nichts hinzuzufügen. |
 
 Der Unterschied zwischen der ersten und der letzten Zeile ist der, auf den es ankommt: „noch nicht“

docs/features/mail.md

@@ -314,7 +314,10 @@ judging the results:
 |---|---|
 | *Searching meaning across 4,120 of 48,900 messages — 8% complete* | The index is still being built. Anything it has not reached cannot be found by meaning yet, so the answer will get better on its own. |
 | *The search model changed…* | Every vector stored before the change belongs to a different model and cannot be compared with the new one. Nothing is searched by meaning until the mailbox has been indexed again. |
-| *…so this search used words only* | The pass did not run: the model host did not answer, the model is not on it, it took too long, or the feature is switched on without a host. Your results are the ordinary search, complete and correct. |
+| *The model took too long…* / *the model host did not answer…* / *does not have the search model…* / *no model host is set up…* | The pass never got a vector, and the sentence names which of those it was. All four are about the **model host**; the search itself was never asked to run. |
+| *Searching by meaning took too long here…* | The vector arrived, and the **database** gave up scoring it inside its five-second budget. Nothing is wrong with the model host — this one is about the mailbox being larger or the machine busier than the budget allows. |
+| *Searching by meaning could not be completed…* | The scoring query failed outright rather than running out of time, so it will fail on every search until somebody looks. The reason is in the server log, at error level, with its SQLSTATE. |
+| *…so this search used words only* (any of the above) | Whatever the reason, your results are the ordinary search, complete and correct. Only the extra pass is missing. |
 | *found nothing the words had not already* | It ran, over a finished index, and had nothing to add. |
 
 The difference between the first and the last is the one that matters: "not yet" and "there was

src/Domain/Enum/Ai/SemanticSkipReason.php

@@ -54,6 +54,40 @@ enum SemanticSkipReason: string
     /** The host is there and the model did not answer in time. */
     case TimedOut = 'timed_out';
 
+    /**
+     * The model answered, and the DATABASE gave up on the search that used it.
+     *
+     * NOT THE SAME FAULT AS TimedOut, AND IT USED TO BE REPORTED AS ONE.
+     * MessageThreadRepository::cheapRows() runs the vector arm under a
+     * statement timeout and re-runs without it on expiry; that give-up path
+     * answered TimedOut, so a mailbox whose vector arm was too slow told
+     * everybody searching that "the model took too long". The model had already
+     * answered — in milliseconds, recorded as a success in ai_call_metric — and
+     * the operator sent to look at the model host finds nothing wrong with it,
+     * because there is nothing wrong with it.
+     *
+     * The two failures live in different machines and are fixed by different
+     * people. They get different sentences.
+     */
+    case SearchTooSlow = 'search_too_slow';
+
+    /**
+     * The vector arm did not time out; it errored.
+     *
+     * The catch that produced SearchTooSlow above is on DriverException, which
+     * is every driver fault Postgres can raise and not merely a cancelled
+     * statement: a missing plmail_embed_distance(), `different vector
+     * dimensions` from a row whose stored width disagrees with its column, a
+     * connection dropped mid-statement. All of those arrived as "the model took
+     * too long" — instantly, on every search, with nothing logged anywhere —
+     * which is the most misleading sentence available for a deterministic
+     * failure that has nothing to do with the model.
+     *
+     * The specifics belong in the log and are put there. This is the sentence
+     * that tells somebody the log is worth reading.
+     */
+    case SearchFailed = 'search_failed';
+
     /** Something came back and it was not a vector this can use. */
     case ModelAnsweredBadly = 'bad_answer';
 

src/Repository/Mail/MessageThreadRepository.php

@@ -22,6 +22,8 @@ use Doctrine\DBAL\Exception\DriverException;
 use Doctrine\DBAL\ParameterType;
 use Doctrine\ORM\QueryBuilder;
 use Doctrine\Persistence\ManagerRegistry;
+use Psr\Log\LoggerInterface;
+use Psr\Log\NullLogger;
 use Symfony\Component\Security\Core\User\UserInterface;
 
 class MessageThreadRepository extends ServiceEntityRepository
@@ -43,6 +45,16 @@ class MessageThreadRepository extends ServiceEntityRepository
          * the other as well.
          */
         private readonly int $semanticTimeoutMs = self::SEARCH_SEMANTIC_TIMEOUT_MS,
+        /**
+         * The first logger this repository has ever had, and it is here for
+         * one call site: the vector arm's give-up path, which discarded the
+         * exception it caught and told the person searching that the model had
+         * been slow. See cheapRows().
+         *
+         * Defaulted so that the several tests which build this by hand keep
+         * working unchanged; autowiring hands the real one to the application.
+         */
+        private readonly LoggerInterface $logger = new NullLogger(),
     ) {
         parent::__construct($registry, MessageThread::class);
     }
@@ -1490,6 +1502,19 @@ class MessageThreadRepository extends ServiceEntityRepository
      */
     private const int SEARCH_SEMANTIC_TIMEOUT_MS = 5000;
 
+    /**
+     * `query_canceled` — what `statement_timeout` raises when it fires.
+     *
+     * Spelled here because DBAL does not name it. Its PostgreSQL
+     * ExceptionConverter maps deadlocks, constraint violations, syntax errors
+     * and half a dozen others onto dedicated classes and lets 57014 fall
+     * through to a plain DriverException, so "the budget fired" and "the query
+     * is broken" arrive at cheapRows() as the same type. The SQLSTATE is the
+     * only thing that tells them apart, and the difference is which machine
+     * somebody is sent to look at.
+     */
+    private const string SQLSTATE_QUERY_CANCELED = '57014';
+
     /**
      * Run the body-substring pass under a time budget, keeping whatever the
      * cheap passes already found if it does not come back in time.
@@ -1619,7 +1644,7 @@ class MessageThreadRepository extends ServiceEntityRepository
             );
 
             return [$rows, $semantic];
-        } catch (DriverException) {
+        } catch (DriverException $exception) {
             // Run again without it, and OUTSIDE the transaction the timeout
             // was set on: the keyword statement is the one this search has
             // always been able to afford, and putting the budget that the
@@ -1633,7 +1658,51 @@ class MessageThreadRepository extends ServiceEntityRepository
             // degradation is the exact thing the skip reasons were built to
             // stop, and it would have been reintroduced by the timeout that
             // was added to protect the page.
-            return [$pass(null), SemanticSearch::skipped(SemanticSkipReason::TimedOut)];
+            //
+            // AND SAYING WHICH, WHICH IS THE PART THIS USED TO GET WRONG.
+            // It answered TimedOut for everything it caught, and TimedOut
+            // prints "the model took too long" — a sentence about the OTHER
+            // machine. The model had already answered before this method was
+            // entered; SemanticQuery does the embedding in the controller,
+            // precisely so that a slow model is never reported as a database
+            // fault. This was the same confusion pointing the other way, and
+            // it is the worse direction: an operator reading "the model took
+            // too long" goes to the model host, where the panel shows every
+            // search_query call succeeding in single-digit milliseconds, and
+            // there is nothing else for them to find.
+            //
+            // Worse still, DriverException is not "the statement was
+            // cancelled". It is every fault the driver can raise — a
+            // plmail_embed_distance() that is not installed, a stored width
+            // that disagrees with its vector, a connection dropped mid-query —
+            // and each of those is DETERMINISTIC. They do not degrade a search
+            // occasionally under load; they degrade EVERY search, instantly,
+            // for as long as the cause stands, while reporting a timeout that
+            // never happened and logging nothing at all.
+            $cancelled = self::SQLSTATE_QUERY_CANCELED === $exception->getSQLState();
+
+            // Both branches log, and both log the SQLSTATE. The give-up path is
+            // meant to be rare, and a rare thing that leaves no trace is
+            // indistinguishable from a common one — which is exactly how this
+            // stayed invisible.
+            $this->logger->log(
+                $cancelled ? 'warning' : 'error',
+                $cancelled
+                    ? 'Search: the semantic pass was cancelled at its budget; results are lexical only'
+                    : 'Search: the semantic pass failed; results are lexical only',
+                [
+                    'sqlstate'  => $exception->getSQLState(),
+                    'budget_ms' => $budget,
+                    'exception' => $exception,
+                ],
+            );
+
+            return [
+                $pass(null),
+                SemanticSearch::skipped(
+                    $cancelled ? SemanticSkipReason::SearchTooSlow : SemanticSkipReason::SearchFailed,
+                ),
+            ];
         }
     }
 

tests/Repository/Mail/MessageSearchTest.php

@@ -681,14 +681,62 @@ final class MessageSearchTest extends KernelTestCase
         // exist to prevent. The timeout added to protect the page must not
         // reintroduce it.
         self::assertNotNull($page->semantic, 'the page has to carry the search that actually ran');
+
+        // SearchTooSlow, NOT TimedOut, and the difference is the whole point of
+        // there being two. TimedOut prints "the model took too long" — and the
+        // model was never asked anything here: SemanticQuery embedded in the
+        // controller long before this method was entered, and on a real
+        // installation that call is sitting in ai_call_metric marked a success.
+        // Reporting this as a model fault sends an operator to a host where
+        // there is nothing to find.
         self::assertSame(
-            SemanticSkipReason::TimedOut,
+            SemanticSkipReason::SearchTooSlow,
             $page->semantic->skipped,
-            'an expired vector is reported as expired, not as absent',
+            'a statement killed at its budget is the database giving up, not the model',
         );
         self::assertNull($page->semantic->literal, 'and it is not still offering the vector it gave up');
     }
 
+    /**
+     * A vector pass that FAILS is not a vector pass that ran out of time.
+     *
+     * The give-up path catches DriverException, which is every driver fault
+     * Postgres can raise — and it answered "the model took too long" for all of
+     * them, logging nothing. That is the wrong sentence twice over: it names
+     * the wrong machine, and it describes as an occasional overrun a class of
+     * fault that is DETERMINISTIC. A plmail_embed_distance() that is not
+     * installed degrades every search, instantly, for as long as it is missing,
+     * while the page insists something was slow.
+     *
+     * Dropped rather than made slow, so this cannot pass by accident on a busy
+     * machine: 42883 is not 57014 under any load. The DROP is inside the test's
+     * transaction and leaves with it.
+     */
+    public function testAFailedSemanticPassIsNotReportedAsATimeout(): void
+    {
+        $this->seedMessage('Quarterly figures', body: 'The pelican audit is attached.');
+        $this->store()->store($this->messageId('Quarterly figures'), [1.0, 0.0, 0.0], 'test-model');
+
+        $this->connection->executeStatement('DROP FUNCTION plmail_embed_distance(real[], real[])');
+
+        $page = $this->repository->searchPage(
+            $this->user,
+            $this->parser->parse('pelican'),
+            semantic: $this->semantic([1.0, 0.0, 0.0]),
+        );
+
+        // Still a search. The scoring being broken costs the scoring.
+        self::assertCount(1, $page->threads, 'the keyword pass answers when the vector arm is broken');
+        self::assertSame('Quarterly figures', $page->threads[0]->subject);
+
+        self::assertNotNull($page->semantic);
+        self::assertSame(
+            SemanticSkipReason::SearchFailed,
+            $page->semantic->skipped,
+            'a broken scoring query must not be dressed up as a slow model',
+        );
+    }
+
     /**
      * And what only the vector could have found is what is given up.
      *

translations/messages.de.yaml

@@ -2159,6 +2159,8 @@ search:
             model_missing: 'Der Modell-Host hat das Such-Modell nicht — deshalb wurde nur nach Wörtern gesucht.'
             not_configured: 'Die Suche nach Bedeutung ist an, aber es ist kein Modell-Host eingerichtet — deshalb wurde nur nach Wörtern gesucht.'
             query_too_short: 'Schreib etwas mehr, dann wird auch nach Bedeutung gesucht.'
+            search_failed: 'Die Suche nach Bedeutung konnte nicht abgeschlossen werden — deshalb wurde nur nach Wörtern gesucht. Warum, steht im Server-Log.'
+            search_too_slow: 'Die Suche nach Bedeutung hat hier zu lange gebraucht — deshalb wurde nur nach Wörtern gesucht.'
             timed_out: 'Das Modell hat zu lange gebraucht — deshalb wurde nur nach Wörtern gesucht.'
     sort:
         label: Sortieren nach

translations/messages.en.yaml

@@ -2173,6 +2173,8 @@ search:
             model_missing: 'The model host does not have the search model, so this search used words only.'
             not_configured: 'Search by meaning is switched on, but no model host is set up, so this search used words only.'
             query_too_short: 'Type a little more to search by meaning as well.'
+            search_failed: 'Searching by meaning could not be completed, so this search used words only. An administrator can find out why in the server log.'
+            search_too_slow: 'Searching by meaning took too long here, so this search used words only.'
             timed_out: 'The model took too long, so this search used words only.'
     sort:
         label: Sort by

translations/messages.en_PI.yaml

@@ -1843,6 +1843,8 @@ search:
             model_missing: "That berth holds no divinin' model — so this search used words alone."
             not_configured: "Search by meanin' be on, but no berth be set — so this search used words alone."
             query_too_short: "Write a little more an' the meanin' be searched too."
+            search_failed: "The search by meanin' ran aground — so this search used words alone. The ship's log says why."
+            search_too_slow: "Searchin' by meanin' took too long in these waters — so this search used words alone."
             timed_out: 'The oracle took too long — so this search used words alone.'
     sort:
         label: Sort by