diff --git a/src/worker.c b/src/worker.c index 107f828..0522308 100644 --- a/src/worker.c +++ b/src/worker.c @@ -16,6 +16,7 @@ #include #include "commands/dbcommands.h" +#include "mb/pg_wchar.h" #include "pgstat.h" #include "postmaster/bgworker.h" #include "postmaster/interrupt.h" @@ -263,7 +264,35 @@ queue_item_note_error(void) edata = CopyErrorData(); if (edata->message != NULL) - strlcpy(failed_item_error, edata->message, sizeof(failed_item_error)); + { + /* + * Clipped where a character ends rather than where the buffer does. + * Clipping by bytes alone left a partial character behind whenever the + * cut fell inside a multi-byte one, and that partial character went on + * to be stored: nothing between here and the UPDATE in + * queue_item_record_failure() validates the encoding, because SPI does + * not cross the protocol boundary at which input from a client is + * checked. The column was left holding text that is invalid in the + * server encoding, so reading it back with anything that walks + * characters rather than bytes -- length(), or a client decoding it + * strictly -- fails on that row. pg_mbcliplen() works in the server + * encoding and allocates nothing, both of which matter here. + * + * The length handed to it is measured with strnlen() bounded by the + * buffer rather than with strlen(), as trim_whitespace() does and for + * the same reason: nothing longer than the buffer can be kept anyway, + * and the bound means we cannot over-read even if handed a message that + * is somehow not NUL-terminated (CWE-126). strlcpy() then gets the + * clipped length plus its terminator, so it copies exactly as far as + * pg_mbcliplen() allows. + */ + int len = pg_mbcliplen(edata->message, + strnlen(edata->message, + sizeof(failed_item_error)), + sizeof(failed_item_error) - 1); + + strlcpy(failed_item_error, edata->message, len + 1); + } FreeErrorData(edata); diff --git a/test/t/007_error_message_truncation.pl b/test/t/007_error_message_truncation.pl new file mode 100644 index 0000000..cdd5edc --- /dev/null +++ b/test/t/007_error_message_truncation.pl @@ -0,0 +1,187 @@ +# Copyright (c) 2025 - 2026, pgEdge, Inc. +# +# Verify that an over-long error message is clipped on a character boundary, so +# that the failure can still be recorded against the item. +# +# The worker keeps a failed item's message in a fixed 1024 byte buffer and +# quotes it into the UPDATE that charges the attempt. Clipping that buffer by +# bytes left a partial character behind whenever the cut fell inside a multi-byte +# one, and that partial character was then stored: SPI does not cross the +# protocol boundary at which input from a client is checked, so nothing on the +# way in validates the encoding. queue.error_message was left holding text that +# is invalid in the server encoding, and reading such a row back with anything +# that walks characters rather than bytes -- length(), or a client decoding +# strictly -- fails. +# +# The failure itself is still recorded, so this is not the runaway that 004 rules +# out; the damage is confined to the stored message. +# +# The fault injected here is a trigger on the chunk table that raises a message +# of 1022 single-byte characters followed by one three-byte character, so the +# 1023rd byte of the buffer is the first byte of a character whose other two do +# not fit. +# +# The item is marked sparse_only, so no embedding is ever requested, but the +# worker resolves and initialises the provider for every batch before it reaches +# that decision. The provider is therefore set to ollama, whose init needs +# neither an API key nor a network round trip; nothing here ever calls it to +# generate anything. + +use strict; +use warnings; + +# See the comment in 001_worker_coverage.pl about loading these at compile time. +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +my $dbname = 'message_truncation'; + +# Deliberately no pgedge_vectorizer.databases yet; see the comment in 004 about +# why the database is named only once its extension exists. +my $node = PostgreSQL::Test::Cluster->new('vectorizer_message_truncation'); + +# The encoding is pinned rather than inherited from whatever locale the developer +# happens to be running under, because this test counts bytes: it relies on +# U+4E16 occupying three of them, which is true of UTF-8 and not of everything +# else. The fix under test is encoding-agnostic, since pg_mbcliplen() reads the +# server encoding, but the arithmetic in the fixture below is not. +$node->init(extra => [ '--locale=C', '--encoding=UTF8' ]); +$node->append_conf( + 'postgresql.conf', qq( +shared_preload_libraries = 'pgedge_vectorizer' +pgedge_vectorizer.worker_poll_interval = 200 +pgedge_vectorizer.provider = 'ollama' +pgedge_vectorizer.enable_hybrid = on +max_worker_processes = 16 +)); + +$node->start; + +$node->safe_psql('postgres', "CREATE DATABASE $dbname"); +$node->safe_psql($dbname, 'CREATE EXTENSION vector'); +$node->safe_psql($dbname, 'CREATE EXTENSION pgedge_vectorizer'); + +$node->append_conf('postgresql.conf', + "pgedge_vectorizer.databases = '$dbname'\n"); +$node->reload; + +# The chunk table carries the columns the worker touches on this path: embedding, +# which the probe deciding whether a dense vector is still needed reads for every +# claimed item, and token_count and sparse_embedding, which the sparse path reads +# and writes. embedding is left NULL, so it is the queue row's own sparse_only +# flag that keeps the embedding provider out of this test. The _idf_stats sidecar +# is deliberately absent, which bm25_load_idf_stats() handles on its own. +# +# 1022 'x' followed by U+4E16, whose UTF-8 encoding is three bytes. The message +# is therefore 1025 bytes, and a byte-wise clip to fit a 1024 byte buffer keeps +# 1023 of them: the last is the first byte of a character on its own. +$node->safe_psql( + $dbname, q( +CREATE TABLE long_message_chunks ( + id bigint PRIMARY KEY, + token_count int, + embedding vector(3), + sparse_embedding sparsevec +); + +INSERT INTO long_message_chunks (id, token_count) VALUES (1, 3); + +CREATE FUNCTION raise_long_message() RETURNS trigger AS $$ +BEGIN + RAISE EXCEPTION '%', repeat('x', 1022) || U&'\4E16'; +END +$$ LANGUAGE plpgsql; + +CREATE TRIGGER raise_long_message + BEFORE UPDATE ON long_message_chunks + FOR EACH ROW EXECUTE FUNCTION raise_long_message(); +)); + +my $log_offset = (-s $node->logfile) // 0; + +$node->safe_psql( + $dbname, qq( +INSERT INTO pgedge_vectorizer.queue + (chunk_id, chunk_table, content, status, metadata, max_attempts) +VALUES (1, 'long_message_chunks', 'alpha beta gamma', 'pending', + '{"sparse_only": true}'::jsonb, 2) +)); + +# Wait for the attempt rather than assuming one has happened by now. An unfixed +# build never records one, so this waits out the timeout and the assertion below +# fails on the value it did see. +my $attempts = 0; +my $deadline = time() + 30; + +while (time() < $deadline) +{ + $attempts = $node->safe_psql($dbname, + "SELECT attempts FROM pgedge_vectorizer.queue WHERE chunk_table = 'long_message_chunks'"); + + last if $attempts > 0; + + sleep 1; +} + +# A guard rather than the point of the test: recording the failure works either +# way, since the invalid sequence is stored rather than rejected, and both of +# these hold on an unfixed build too. +cmp_ok($attempts, '>', 0, + 'an over-long message does not stop the attempt being charged'); + +my $log = slurp_file($node->logfile, $log_offset); + +unlike($log, qr/could not record failure for queue item/, + 'the failure is recorded rather than being reported as unrecordable'); + +# This is the point of the test. length() walks characters, so it raises on a +# stored message ending in half of one; an unfixed build fails here rather than +# returning a number. +my ($rc, $stdout, $stderr) = $node->psql($dbname, q( +SELECT length(error_message) FROM pgedge_vectorizer.queue + WHERE chunk_table = 'long_message_chunks' +)); + +is($rc, 0, + 'the recorded message is valid in the server encoding'); + +is($stdout, '1022', + 'every character of the recorded message is whole'); + +# The message is kept as far as it fits and no further: 1022 bytes, because the +# three-byte character that follows cannot fit in the 1023 available and is +# therefore dropped whole rather than in part. +my $stored = $node->safe_psql($dbname, q( +SELECT octet_length(error_message) FROM pgedge_vectorizer.queue + WHERE chunk_table = 'long_message_chunks' +)); + +is($stored, '1022', + 'the message is clipped to the last character that fits entirely'); + +my $intact = $node->safe_psql($dbname, q( +SELECT error_message = repeat('x', 1022) FROM pgedge_vectorizer.queue + WHERE chunk_table = 'long_message_chunks' +)); + +is($intact, 't', + 'what is kept is the head of the message, unaltered'); + +# Prove the fixture is what the test claims, so that the assertions above cannot +# pass because the error was something shorter than the buffer all along. The +# length is measured by the server, which is the only thing that agrees with the +# worker on how many bytes the message runs to. +my $fixture_bytes = $node->safe_psql($dbname, + q(SELECT octet_length(repeat('x', 1022) || U&'\4E16'))); + +is($fixture_bytes, '1025', + 'the injected message is longer than the buffer that has to hold it'); + +# And that this is the error the worker actually hit: it reports the original in +# full before recording it. +like($log, qr/x{1022}/, + 'the over-long message is the failure being recorded'); + +$node->stop; +done_testing();