niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #211
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestCaseHackSuffix6=== PAUSE TestCaseHackSuffix7=== RUN TestFilterOversizedClosures8=== PAUSE TestFilterOversizedClosures9=== RUN TestPartSizeForNAR10=== PAUSE TestPartSizeForNAR11=== RUN TestUploadMultipart_SupersededByPeer12=== PAUSE TestUploadMultipart_SupersededByPeer13=== RUN TestDumpPathCaseHackMatchesNix14--- PASS: TestDumpPathCaseHackMatchesNix (0.03s)15=== RUN TestDumpPathCaseHackCollision16--- PASS: TestDumpPathCaseHackCollision (0.00s)17=== RUN TestDumpPathMatchesNix18=== PAUSE TestDumpPathMatchesNix19=== RUN TestDumpPathSingleFile20=== PAUSE TestDumpPathSingleFile21=== RUN TestDumpPathWriterError22=== PAUSE TestDumpPathWriterError23=== RUN TestEncodeNixBase3224=== PAUSE TestEncodeNixBase3225=== RUN TestEncodeNixBase32WithRealHash26=== PAUSE TestEncodeNixBase32WithRealHash27=== RUN TestConvertHashToNix3228=== PAUSE TestConvertHashToNix3229=== RUN TestGetStorePathHash30=== PAUSE TestGetStorePathHash31=== RUN TestPathInfoHashCompatibility32=== PAUSE TestPathInfoHashCompatibility33=== RUN TestParsePathInfoJSON34=== PAUSE TestParsePathInfoJSON35=== RUN TestParsePathInfoJSONMultiplePaths36=== PAUSE TestParsePathInfoJSONMultiplePaths37=== RUN TestPathInfoCACompatibility38=== PAUSE TestPathInfoCACompatibility39=== RUN TestRateLimiterFeedback40=== PAUSE TestRateLimiterFeedback41=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess42=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess43=== RUN TestResolveStorePath44=== PAUSE TestResolveStorePath45=== RUN TestDoWithRetry_BodyReplayedViaGetBody46=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody47=== RUN TestShellSplit48=== PAUSE TestShellSplit49=== RUN TestShellSplitErrors50=== PAUSE TestShellSplitErrors51=== RUN TestStreamPushReportsEveryPath52=== PAUSE TestStreamPushReportsEveryPath53=== RUN TestStreamPushBatchesUnderLoad54=== PAUSE TestStreamPushBatchesUnderLoad55=== RUN TestStreamPushIsolatesFailures56=== PAUSE TestStreamPushIsolatesFailures57=== RUN TestStreamPushGivesUpOnDeadServer58=== PAUSE TestStreamPushGivesUpOnDeadServer59=== RUN TestStreamPushRequestLine60=== PAUSE TestStreamPushRequestLine61=== RUN TestSetClientTLS62=== PAUSE TestSetClientTLS63=== RUN TestSetClientTLSDoesNotMutateDefaultTransport64=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport65=== RUN TestSetClientTLSErrors66=== PAUSE TestSetClientTLSErrors67=== RUN TestStaticToken68=== PAUSE TestStaticToken69=== RUN TestFileTokenReadsAndCaches70=== PAUSE TestFileTokenReadsAndCaches71=== RUN TestFileTokenMissing72=== PAUSE TestFileTokenMissing73=== RUN TestFileTokenEmpty74=== PAUSE TestFileTokenEmpty75=== RUN TestScriptTokenNoExpiryRerunsEveryCall76=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall77=== RUN TestScriptTokenCachesUntilRefresh78=== PAUSE TestScriptTokenCachesUntilRefresh79=== RUN TestScriptTokenEmptyToken80=== PAUSE TestScriptTokenEmptyToken81=== RUN TestScriptTokenBadJSON82=== PAUSE TestScriptTokenBadJSON83=== RUN TestScriptTokenScriptFails84=== PAUSE TestScriptTokenScriptFails85=== RUN TestScriptTokenEmptyCommand86=== PAUSE TestScriptTokenEmptyCommand87=== CONT TestDoServerRequestAttachesToken88=== CONT TestShellSplit89--- PASS: TestShellSplit (0.00s)90=== CONT TestDumpPathWriterError91=== CONT TestStaticToken92--- PASS: TestStaticToken (0.00s)93=== CONT TestScriptTokenEmptyCommand94--- PASS: TestScriptTokenEmptyCommand (0.00s)95=== CONT TestDumpPathSingleFile96=== CONT TestScriptTokenScriptFails97=== CONT TestScriptTokenBadJSON98=== CONT TestScriptTokenEmptyToken99=== CONT TestScriptTokenCachesUntilRefresh100=== CONT TestScriptTokenNoExpiryRerunsEveryCall101=== CONT TestFileTokenEmpty102=== CONT TestFileTokenMissing103=== CONT TestFileTokenReadsAndCaches104=== CONT TestStreamPushBatchesUnderLoad105=== CONT TestStreamPushGivesUpOnDeadServer106=== CONT TestSetClientTLS107=== CONT TestStreamPushIsolatesFailures108=== CONT TestStreamPushRequestLine109=== CONT TestSetClientTLSErrors110=== CONT TestConvertHashToNix32111=== CONT TestDumpPathMatchesNix112=== CONT TestDoWithRetry_BodyReplayedViaGetBody113=== CONT TestEncodeNixBase32WithRealHash114--- PASS: TestEncodeNixBase32WithRealHash (0.00s)115=== CONT TestRateLimiterFeedback116--- PASS: TestScriptTokenScriptFails (0.00s)117=== CONT TestPathInfoCACompatibility118=== RUN TestPathInfoCACompatibility/null_ca_field119=== PAUSE TestPathInfoCACompatibility/null_ca_field120=== RUN TestRateLimiterFeedback/429_enables_limiter121=== PAUSE TestRateLimiterFeedback/429_enables_limiter122=== CONT TestResolveStorePath123=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess124=== CONT TestEncodeNixBase32125=== RUN TestPathInfoCACompatibility/old_string_format_-_text126=== RUN TestRateLimiterFeedback/503_enables_limiter127=== PAUSE TestRateLimiterFeedback/503_enables_limiter128=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter129=== RUN TestEncodeNixBase32/test_string_hash130--- PASS: TestScriptTokenBadJSON (0.00s)1312026/09/16 20:17:59 WARN Rate limiter enabled after throttle name=server-test rate=5132--- PASS: TestFileTokenEmpty (0.00s)133--- PASS: TestFileTokenMissing (0.00s)134=== CONT TestParsePathInfoJSONMultiplePaths135=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths136--- PASS: TestFileTokenReadsAndCaches (0.00s)137=== RUN TestConvertHashToNix32/SRI_format_to_Nix32138=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32139=== RUN TestConvertHashToNix32/already_Nix32_format140=== PAUSE TestConvertHashToNix32/already_Nix32_format141=== RUN TestConvertHashToNix32/invalid_format142--- PASS: TestResolveStorePath (0.00s)143=== CONT TestPartSizeForNAR144=== RUN TestPartSizeForNAR/zero_stays_at_minimum1452026/09/16 20:17:59 ERROR Upload failed error="connection refused" count=20146=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum1472026/09/16 20:17:59 ERROR Server seems unavailable, giving up on batch untried=17148=== PAUSE TestEncodeNixBase32/test_string_hash149=== RUN TestEncodeNixBase32/empty_input1502026/09/16 20:17:59 ERROR Upload failed error="bad path" count=3151=== PAUSE TestEncodeNixBase32/empty_input1522026/09/16 20:17:59 ERROR Upload failed error="stale build claim" count=1153=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter1542026/09/16 20:17:59 WARN Rate limiter enabled after throttle name=server-test rate=5155=== CONT TestCaseHackSuffix1562026/09/16 20:17:59 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:34803157=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text158=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths159=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths160=== CONT TestGetStorePathHash161=== PAUSE TestConvertHashToNix32/invalid_format162=== RUN TestPartSizeForNAR/small_stays_at_minimum163=== CONT TestShellSplitErrors164=== CONT TestSetClientTLSDoesNotMutateDefaultTransport165=== PAUSE TestPartSizeForNAR/small_stays_at_minimum166=== CONT TestParsePathInfoJSON167--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)168=== CONT TestFilterOversizedClosures169=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter170=== RUN TestFilterOversizedClosures/no_limit_keeps_everything1712026/09/16 20:17:59 WARN Rate limiter backed off name=server-test rate=5172=== CONT TestPathInfoHashCompatibility1732026/09/16 20:17:59 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:34803174=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)175=== RUN TestGetStorePathHash/valid_store_path176=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths177=== CONT TestStreamPushReportsEveryPath178=== CONT TestUploadMultipart_SupersededByPeer179=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum180=== RUN TestParsePathInfoJSON/Nix_format181--- PASS: TestStreamPushIsolatesFailures (0.00s)182=== CONT TestEncodeNixBase32/test_string_hash183=== RUN TestSetClientTLSErrors/missing_cert_file184--- PASS: TestScriptTokenEmptyToken (0.01s)185--- PASS: TestShellSplitErrors (0.00s)186--- PASS: TestDoServerRequestAttachesToken (0.01s)187=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter188=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive189=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum190=== PAUSE TestParsePathInfoJSON/Nix_format191=== CONT TestConvertHashToNix32/invalid_format192=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts193=== CONT TestEncodeNixBase32/empty_input194=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts195=== CONT TestRateLimiterFeedback/429_enables_limiter196=== RUN TestUploadMultipart_SupersededByPeer/exists197=== PAUSE TestUploadMultipart_SupersededByPeer/exists198=== CONT TestConvertHashToNix32/SRI_format_to_Nix32199=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything200=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive201=== PAUSE TestGetStorePathHash/valid_store_path202=== CONT TestConvertHashToNix32/already_Nix32_format203=== PAUSE TestSetClientTLSErrors/missing_cert_file204--- PASS: TestScriptTokenCachesUntilRefresh (0.01s)205=== RUN TestSetClientTLSErrors/missing_key_file206=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths207=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths208=== RUN TestParsePathInfoJSON/Lix_format209=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)210=== RUN TestPartSizeForNAR/1_TiB211=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter212=== RUN TestUploadMultipart_SupersededByPeer/missing2132026/09/16 20:17:59 WARN Rate limiter enabled after throttle name=server-test rate=52142026/09/16 20:17:59 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:34445215=== CONT TestRateLimiterFeedback/503_enables_limiter2162026/09/16 20:17:59 WARN Rate limiter backed off name=server-test rate=5217=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter218=== RUN TestSetClientTLS/rejects_connection_without_client_cert219=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped220=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped221=== RUN TestFilterOversizedClosures/all_closures_skipped222=== RUN TestGetStorePathHash/basename_without_hyphen_should_error223=== RUN TestPathInfoCACompatibility/new_structured_format_-_text224--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)225=== PAUSE TestSetClientTLSErrors/missing_key_file226=== PAUSE TestParsePathInfoJSON/Lix_format227=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon228=== PAUSE TestPartSizeForNAR/1_TiB229=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon230=== PAUSE TestUploadMultipart_SupersededByPeer/missing231=== RUN TestSetClientTLSErrors/missing_ca_file232=== PAUSE TestSetClientTLSErrors/missing_ca_file2332026/09/16 20:17:59 WARN Rate limiter enabled after throttle name=server-test rate=5234=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert2352026/09/16 20:17:59 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:36201236=== PAUSE TestFilterOversizedClosures/all_closures_skipped237=== RUN TestSetClientTLSErrors/invalid_ca_file238=== CONT TestFilterOversizedClosures/all_closures_skipped2392026/09/16 20:17:59 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50240=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text241--- PASS: TestEncodeNixBase32 (0.00s)242 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)243 --- PASS: TestEncodeNixBase32/empty_input (0.00s)244--- PASS: TestStreamPushReportsEveryPath (0.00s)245=== CONT TestUploadMultipart_SupersededByPeer/missing2462026/09/16 20:17:59 WARN Rate limiter backed off name=server-test rate=5247=== RUN TestParsePathInfoJSON/empty_input248=== PAUSE TestParsePathInfoJSON/empty_input249=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI250=== CONT TestUploadMultipart_SupersededByPeer/exists251=== RUN TestPartSizeForNAR/5_TiB_S3_max_object252=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object253=== RUN TestParsePathInfoJSON/whitespace_only254=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI255=== RUN TestPartSizeForNAR/capped_at_5_GiB256=== PAUSE TestPartSizeForNAR/capped_at_5_GiB257=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512258=== CONT TestPartSizeForNAR/zero_stays_at_minimum259=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA260=== CONT TestFilterOversizedClosures/no_limit_keeps_everything261=== PAUSE TestSetClientTLSErrors/invalid_ca_file262=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method263--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)264=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped265=== CONT TestSetClientTLSErrors/invalid_ca_file2662026/09/16 20:17:59 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-vm-image nar_size=5000 max_nar_size=2000267=== CONT TestSetClientTLSErrors/missing_key_file268=== PAUSE TestParsePathInfoJSON/whitespace_only269=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error270=== CONT TestPartSizeForNAR/1_TiB271=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum272=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error273=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error274=== CONT TestPartSizeForNAR/5_TiB_S3_max_object275=== CONT TestPartSizeForNAR/small_stays_at_minimum276=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts277=== CONT TestPartSizeForNAR/capped_at_5_GiB278=== CONT TestSetClientTLSErrors/missing_ca_file279=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA280=== CONT TestSetClientTLSErrors/missing_cert_file281=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512282=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)283=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI284=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512285--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.01s)286--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)287 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)288 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)289--- PASS: TestConvertHashToNix32 (0.00s)290 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)291 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)292 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)293--- PASS: TestFilterOversizedClosures (0.01s)294 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)295 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)296 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)297=== RUN TestParsePathInfoJSON/invalid_JSON298=== PAUSE TestParsePathInfoJSON/invalid_JSON299=== CONT TestParsePathInfoJSON/Nix_format300=== CONT TestParsePathInfoJSON/whitespace_only301=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error302=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error303=== CONT TestGetStorePathHash/valid_store_path304=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error305=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error306=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method307=== CONT TestPathInfoCACompatibility/null_ca_field308=== CONT TestPathInfoCACompatibility/new_structured_format_-_text309=== CONT TestPathInfoCACompatibility/old_string_format_-_text310=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon311--- PASS: TestPartSizeForNAR (0.01s)312 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)313 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)314 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)315 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)316 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)317 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)318 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)319=== CONT TestParsePathInfoJSON/empty_input320=== CONT TestParsePathInfoJSON/invalid_JSON321=== CONT TestParsePathInfoJSON/Lix_format322=== RUN TestSetClientTLS/preserves_debug_logging_transport323=== CONT TestGetStorePathHash/basename_without_hyphen_should_error324=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive325=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method326--- PASS: TestRateLimiterFeedback (0.01s)327 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)328 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)329 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)330 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)331=== PAUSE TestSetClientTLS/preserves_debug_logging_transport332=== CONT TestSetClientTLS/rejects_connection_without_client_cert333=== CONT TestSetClientTLS/preserves_debug_logging_transport334--- PASS: TestParsePathInfoJSON (0.01s)335 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)336 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)337 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)338 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)339 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)340=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA341--- PASS: TestSetClientTLSErrors (0.01s)342 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)343 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)344 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)345 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)346--- PASS: TestGetStorePathHash (0.01s)347 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)348 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)349 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)350 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)351--- PASS: TestPathInfoCACompatibility (0.02s)352 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)353 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)354 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)355 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)356 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)357--- PASS: TestPathInfoHashCompatibility (0.01s)358 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)359 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)360 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)361 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)362--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)363 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)364 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)365--- PASS: TestStreamPushRequestLine (0.02s)3662026/09/16 20:17:59 http: TLS handshake error from 127.0.0.1:56590: remote error: tls: bad certificate367--- PASS: TestSetClientTLS (0.02s)368 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)369 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)370 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)371--- PASS: TestDumpPathSingleFile (0.03s)372--- PASS: TestCaseHackSuffix (0.03s)373--- PASS: TestDumpPathWriterError (0.05s)374--- PASS: TestDumpPathMatchesNix (0.09s)375--- PASS: TestStreamPushBatchesUnderLoad (0.10s)376--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)377PASS378Running server tests...379The files belonging to this database system will be owned by user "nixbld".380This user must also own the server process.381382The database cluster will be initialized with locale "C".383The default database encoding has accordingly been set to "SQL_ASCII".384The default text search configuration will be set to "english".385386Data page checksums are enabled.387388creating directory /build/postgres1017436748/data ... ok389creating subdirectories ... ok390selecting dynamic shared memory implementation ... posix391selecting default "max_connections" ... 100392selecting default "shared_buffers" ... 128MB393selecting default time zone ... UTC394creating configuration files ... ok395running bootstrap script ... ok396performing post-bootstrap initialization ... ok397syncing data to disk ... ok398399initdb: warning: enabling "trust" authentication for local connections400initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.401402Success. You can now start the database server using:403404 pg_ctl -D /build/postgres1017436748/data -l logfile start405406/build/postgres1017436748:5432 - no response4072026-09-16 20:18:00.860 UTC [129] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit4082026-09-16 20:18:00.861 UTC [129] LOG: listening on Unix socket "/build/postgres1017436748/.s.PGSQL.5432"4092026-09-16 20:18:00.865 UTC [136] LOG: database system was shut down at 2026-09-16 20:18:00 UTC4102026-09-16 20:18:00.869 UTC [129] LOG: database system is ready to accept connections411/build/postgres1017436748:5432 - accepting connections412=== RUN TestService_AuthMiddleware413=== PAUSE TestService_AuthMiddleware414=== RUN TestService_AuthMiddleware_MTLSProxyHeader415=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader416=== RUN TestService_AuthMiddleware_MTLSBoundSubjects417=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects418=== RUN TestService_ReadAuthMiddleware419=== PAUSE TestService_ReadAuthMiddleware420=== RUN TestService_AuthMiddleware_OIDC421=== PAUSE TestService_AuthMiddleware_OIDC422=== RUN TestService_RequireScope_OIDC423=== PAUSE TestService_RequireScope_OIDC424=== RUN TestService_ReadScope_PublicByDefault425=== PAUSE TestService_ReadScope_PublicByDefault426=== RUN TestCacheConfigHandler427=== PAUSE TestCacheConfigHandler428=== RUN TestCacheStatsHandler429=== PAUSE TestCacheStatsHandler430=== RUN TestClaim_BuildWaitComplete431=== PAUSE TestClaim_BuildWaitComplete432=== RUN TestClaim_GCMarkedOutputCountsAsAbsent433=== PAUSE TestClaim_GCMarkedOutputCountsAsAbsent434=== RUN TestClaim_TooManyStreams435=== PAUSE TestClaim_TooManyStreams436=== RUN TestClaim_HolderDisconnectKeepsClaim437=== PAUSE TestClaim_HolderDisconnectKeepsClaim438=== RUN TestClaim_FailWakesWaitersButIsNotRemembered439=== PAUSE TestClaim_FailWakesWaitersButIsNotRemembered440=== RUN TestClaim_FailWithoutKindReleases441=== PAUSE TestClaim_FailWithoutKindReleases442=== RUN TestClaim_StaleHeartbeatStolen443=== PAUSE TestClaim_StaleHeartbeatStolen444=== RUN TestClaim_TwoInstances445=== PAUSE TestClaim_TwoInstances446=== RUN TestClaim_InputsTouched447=== PAUSE TestClaim_InputsTouched448=== RUN TestClaim_StreamsThroughServer449=== PAUSE TestClaim_StreamsThroughServer450=== RUN TestClientCADerivations451=== PAUSE TestClientCADerivations452=== RUN TestClientErrorHandling453=== PAUSE TestClientErrorHandling454=== RUN TestClientIntegration455=== PAUSE TestClientIntegration456=== RUN TestClientMultipleUploads457=== PAUSE TestClientMultipleUploads458=== RUN TestClientWithDependencies459=== PAUSE TestClientWithDependencies460=== RUN TestPinProtectsFromGC461=== PAUSE TestPinProtectsFromGC462=== RUN TestResolveDBConnectionString463=== PAUSE TestResolveDBConnectionString464=== RUN TestGCAdvisoryLockBlocksConcurrentRun4652026-09-16 20:18:01.250 UTC [564] ERROR: relation "goose_db_version" does not exist at character 364662026-09-16 20:18:01.250 UTC [564] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4672026/09/16 20:18:01 OK 20241026095416_initial_model.sql (6.35ms)4682026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (1.61ms)4692026/09/16 20:18:01 OK 20251218171726_add_pins.sql (1.96ms)4702026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (1.9ms)4712026/09/16 20:18:01 OK 20260905000000_add_claims.sql (2.05ms)4722026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000004732026/09/16 20:18:01 OK 1_commit_pending_closure.sql (1.37ms)4742026/09/16 20:18:01 OK 2_object_stats_trigger.sql (606.73µs)4752026/09/16 20:18:01 goose: up to current file version: 2476--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.14s)477=== RUN TestGCBugBareHashReferences478=== PAUSE TestGCBugBareHashReferences479=== RUN TestGCMetrics480=== PAUSE TestGCMetrics481=== RUN TestGCTaskStore_StartNew482=== PAUSE TestGCTaskStore_StartNew483=== RUN TestGCTaskStore_DeduplicateSameParams484=== PAUSE TestGCTaskStore_DeduplicateSameParams485=== RUN TestGCTaskStore_ConflictDifferentParams486=== PAUSE TestGCTaskStore_ConflictDifferentParams487=== RUN TestGCTaskStore_GetEmpty488=== PAUSE TestGCTaskStore_GetEmpty489=== RUN TestGCTaskStore_GetReturnsLatest490=== PAUSE TestGCTaskStore_GetReturnsLatest491=== RUN TestGCTaskStore_CompletedAllowsNewTask492=== PAUSE TestGCTaskStore_CompletedAllowsNewTask493=== RUN TestGCTaskStore_PhaseUpdates494=== PAUSE TestGCTaskStore_PhaseUpdates495=== RUN TestGCTaskStore_Fail496=== PAUSE TestGCTaskStore_Fail497=== RUN TestGracefulShutdownDrainsInflight498=== PAUSE TestGracefulShutdownDrainsInflight499=== RUN TestService_healthCheckHandler500=== PAUSE TestService_healthCheckHandler501=== RUN TestService_readinessHandler502=== PAUSE TestService_readinessHandler503=== RUN TestGenerateLandingPage504=== PAUSE TestGenerateLandingPage505=== RUN TestCacheConfigHandlerMaxNarSize506=== PAUSE TestCacheConfigHandlerMaxNarSize507=== RUN TestCreatePendingClosureRejectsOversizedNAR508=== PAUSE TestCreatePendingClosureRejectsOversizedNAR509=== RUN TestNARDeduplicationMetadataUploadBug510=== PAUSE TestNARDeduplicationMetadataUploadBug511=== RUN TestMetricsInventory512=== PAUSE TestMetricsInventory513=== RUN TestService_NativeMTLS514=== PAUSE TestService_NativeMTLS515=== RUN TestServerTLSConfig516=== PAUSE TestServerTLSConfig517=== RUN TestMultipartCleanup518=== PAUSE TestMultipartCleanup519=== RUN TestObjectStatsTrigger520=== PAUSE TestObjectStatsTrigger521=== RUN TestOrphanedObjectsGC522=== PAUSE TestOrphanedObjectsGC523=== RUN TestOrphanedObjectsGCStressTest524=== PAUSE TestOrphanedObjectsGCStressTest525=== RUN TestResurrectedObjectNotDeleted526=== PAUSE TestResurrectedObjectNotDeleted527=== RUN TestParseSingleRange528=== PAUSE TestParseSingleRange529=== RUN TestIsValidCachePath530=== PAUSE TestIsValidCachePath531=== RUN TestReadProxyNarinfo532=== PAUSE TestReadProxyNarinfo533=== RUN TestReadProxyNarinfoAlreadyDecompressed534=== PAUSE TestReadProxyNarinfoAlreadyDecompressed535=== RUN TestReadProxyNarStreaming536=== PAUSE TestReadProxyNarStreaming537=== RUN TestReadProxy404538=== PAUSE TestReadProxy404539=== RUN TestReadProxyInvalidPath540=== PAUSE TestReadProxyInvalidPath541=== RUN TestReadProxyHead542=== PAUSE TestReadProxyHead543=== RUN TestReadProxyConditionalGet544=== PAUSE TestReadProxyConditionalGet545=== RUN TestReadProxyRootRedirectsToIndexHTML546=== PAUSE TestReadProxyRootRedirectsToIndexHTML547=== RUN TestReadProxyDisabled548=== PAUSE TestReadProxyDisabled549=== RUN TestReadRedirectNar550=== PAUSE TestReadRedirectNar551=== RUN TestReadRedirectKeepsNarinfoProxied552=== PAUSE TestReadRedirectKeepsNarinfoProxied553=== RUN TestReadProxyRangeRequest554=== PAUSE TestReadProxyRangeRequest555=== RUN TestReadRedirectUsesPublicS3URL556=== PAUSE TestReadRedirectUsesPublicS3URL557=== RUN TestRedundantMultipartUpload558=== PAUSE TestRedundantMultipartUpload559=== RUN TestCompleteMultipartUpload_ErrorButObjectExists560=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists561=== RUN TestCompletedNarNotReofferedAcrossClosures562=== PAUSE TestCompletedNarNotReofferedAcrossClosures563=== RUN TestPresignedUploadRegisteredBeforeCommit564=== PAUSE TestPresignedUploadRegisteredBeforeCommit565=== RUN TestService_Rustfstest566=== PAUSE TestService_Rustfstest567=== RUN TestParseSize568=== PAUSE TestParseSize569=== RUN TestSkippedUploadsHandler570=== PAUSE TestSkippedUploadsHandler571=== RUN TestSystemdListenerNotActivated572--- PASS: TestSystemdListenerNotActivated (0.00s)573=== RUN TestWatchdogBeatsWhenHealthy574--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)575=== RUN TestWatchdogSkipsWhenUnhealthy5762026/09/16 20:18:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5772026/09/16 20:18:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5782026/09/16 20:18:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5792026/09/16 20:18:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5802026/09/16 20:18:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5812026/09/16 20:18:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5822026/09/16 20:18:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5832026/09/16 20:18:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5842026/09/16 20:18:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"585--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)586=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle587=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle588=== RUN TestProxyWriteTimeout589=== PAUSE TestProxyWriteTimeout590=== RUN TestIsValidUploadKey591=== PAUSE TestIsValidUploadKey592=== RUN TestUploadHandlersRejectInvalidKeys593=== PAUSE TestUploadHandlersRejectInvalidKeys594=== RUN TestUploadHandlersRejectOversizedBody595=== PAUSE TestUploadHandlersRejectOversizedBody596=== RUN TestService_cleanupPendingClosuresHandler597=== PAUSE TestService_cleanupPendingClosuresHandler598=== RUN TestService_createPendingClosureHandler599=== PAUSE TestService_createPendingClosureHandler600=== RUN TestService_verifyS3Integrity601=== PAUSE TestService_verifyS3Integrity602=== RUN TestCompleteMultipartUnregistered603=== PAUSE TestCompleteMultipartUnregistered604=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT605=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT606=== CONT TestService_AuthMiddleware607=== CONT TestNARDeduplicationMetadataUploadBug608=== CONT TestClientIntegration609=== CONT TestCreatePendingClosureRejectsOversizedNAR610=== CONT TestCacheConfigHandlerMaxNarSize6112026/09/16 20:18:01 INFO Received uploads request method=POST path=/api/pending_closures612=== CONT TestGenerateLandingPage613--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)614=== CONT TestService_readinessHandler615=== CONT TestService_healthCheckHandler616=== CONT TestGracefulShutdownDrainsInflight617=== CONT TestGCTaskStore_Fail618=== CONT TestGCTaskStore_PhaseUpdates619=== CONT TestGCTaskStore_CompletedAllowsNewTask620=== CONT TestGCTaskStore_GetReturnsLatest621=== CONT TestGCTaskStore_GetEmpty622=== CONT TestGCTaskStore_ConflictDifferentParams623=== CONT TestGCTaskStore_DeduplicateSameParams624=== CONT TestGCTaskStore_StartNew625=== CONT TestGCMetrics626=== CONT TestGCBugBareHashReferences627=== CONT TestResolveDBConnectionString628=== CONT TestPinProtectsFromGC629=== CONT TestClientWithDependencies630=== CONT TestClientMultipleUploads631=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT632=== CONT TestCompleteMultipartUnregistered633=== CONT TestClientErrorHandling634=== CONT TestService_createPendingClosureHandler6352026/09/16 20:18:01 INFO Starting HTTP server address=127.0.0.1:43471636=== RUN TestClientErrorHandling/InvalidStorePath637=== CONT TestService_verifyS3Integrity638=== PAUSE TestClientErrorHandling/InvalidStorePath639=== CONT TestReadRedirectKeepsNarinfoProxied640--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)641=== CONT TestClientCADerivations642=== CONT TestClaim_StreamsThroughServer6432026/09/16 20:18:01 INFO Shutdown signal received, draining in-flight requests timeout=10s644--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)645=== CONT TestService_cleanupPendingClosuresHandler646=== RUN TestClientErrorHandling/InvalidAuthToken647=== PAUSE TestClientErrorHandling/InvalidAuthToken648=== CONT TestClaim_InputsTouched649=== CONT TestClaim_TooManyStreams650--- PASS: TestGCTaskStore_GetEmpty (0.00s)651--- PASS: TestGCTaskStore_Fail (0.00s)652--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)653--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)654--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)655--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)656--- PASS: TestGCTaskStore_StartNew (0.00s)657=== RUN TestResolveDBConnectionString/flag_wins658=== PAUSE TestResolveDBConnectionString/flag_wins659=== RUN TestClientErrorHandling/ServerNotAvailable660=== RUN TestResolveDBConnectionString/file_when_flag_empty661=== PAUSE TestResolveDBConnectionString/file_when_flag_empty662=== RUN TestResolveDBConnectionString/missing_file_is_an_error663=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error664=== RUN TestResolveDBConnectionString/PGHOST_allows_empty665=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty666=== PAUSE TestClientErrorHandling/ServerNotAvailable667=== RUN TestResolveDBConnectionString/nothing_configured668=== CONT TestClaim_TwoInstances669=== PAUSE TestResolveDBConnectionString/nothing_configured670=== CONT TestUploadHandlersRejectOversizedBody671--- PASS: TestGenerateLandingPage (0.01s)672=== CONT TestClaim_StaleHeartbeatStolen673--- PASS: TestGracefulShutdownDrainsInflight (0.07s)674=== CONT TestClaim_FailWithoutKindReleases6752026-09-16 20:18:01.688 UTC [641] ERROR: relation "goose_db_version" does not exist at character 366762026-09-16 20:18:01.688 UTC [641] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6772026-09-16 20:18:01.706 UTC [642] ERROR: relation "goose_db_version" does not exist at character 366782026-09-16 20:18:01.706 UTC [642] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6792026-09-16 20:18:01.709 UTC [643] ERROR: relation "goose_db_version" does not exist at character 366802026-09-16 20:18:01.709 UTC [643] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6812026-09-16 20:18:01.717 UTC [644] ERROR: relation "goose_db_version" does not exist at character 366822026-09-16 20:18:01.717 UTC [644] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6832026-09-16 20:18:01.717 UTC [645] ERROR: relation "goose_db_version" does not exist at character 366842026-09-16 20:18:01.717 UTC [645] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC685=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure686=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure687=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart688=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart689=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts690=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts691=== CONT TestUploadHandlersRejectInvalidKeys692=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info693=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info694=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal695=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal696=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key697=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key698=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key699=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key700=== CONT TestIsValidUploadKey701=== RUN TestIsValidUploadKey/narinfo702=== PAUSE TestIsValidUploadKey/narinfo703=== RUN TestIsValidUploadKey/nar_zst704=== PAUSE TestIsValidUploadKey/nar_zst705=== RUN TestIsValidUploadKey/nar_xz706=== PAUSE TestIsValidUploadKey/nar_xz707=== RUN TestIsValidUploadKey/nar_plain708=== PAUSE TestIsValidUploadKey/nar_plain709=== RUN TestIsValidUploadKey/listing710=== PAUSE TestIsValidUploadKey/listing711=== RUN TestIsValidUploadKey/build_log712=== PAUSE TestIsValidUploadKey/build_log713=== RUN TestIsValidUploadKey/build_log_home-manager_file714=== PAUSE TestIsValidUploadKey/build_log_home-manager_file715=== RUN TestIsValidUploadKey/build_log_plus_in_name716=== PAUSE TestIsValidUploadKey/build_log_plus_in_name717=== RUN TestIsValidUploadKey/build_log_question_mark718=== PAUSE TestIsValidUploadKey/build_log_question_mark719=== RUN TestIsValidUploadKey/build_log_equals720=== PAUSE TestIsValidUploadKey/build_log_equals721=== RUN TestIsValidUploadKey/realisation722=== PAUSE TestIsValidUploadKey/realisation723=== RUN TestIsValidUploadKey/realisation_plus_in_output724=== PAUSE TestIsValidUploadKey/realisation_plus_in_output725=== RUN TestIsValidUploadKey/nix-cache-info726=== PAUSE TestIsValidUploadKey/nix-cache-info727=== RUN TestIsValidUploadKey/index.html728=== PAUSE TestIsValidUploadKey/index.html729=== RUN TestIsValidUploadKey/narinfo_key,_nar_type730=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type731=== RUN TestIsValidUploadKey/nar_key,_narinfo_type732=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type733=== RUN TestIsValidUploadKey/listing_key,_narinfo_type734=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type735=== RUN TestIsValidUploadKey/traversal736=== PAUSE TestIsValidUploadKey/traversal737=== RUN TestIsValidUploadKey/traversal_nar738=== PAUSE TestIsValidUploadKey/traversal_nar739=== RUN TestIsValidUploadKey/absolute740=== PAUSE TestIsValidUploadKey/absolute741=== RUN TestIsValidUploadKey/empty_key742=== PAUSE TestIsValidUploadKey/empty_key743=== RUN TestIsValidUploadKey/unknown_type744=== PAUSE TestIsValidUploadKey/unknown_type745=== CONT TestClaim_FailWakesWaitersButIsNotRemembered7462026-09-16 20:18:01.810 UTC [646] ERROR: relation "goose_db_version" does not exist at character 367472026-09-16 20:18:01.810 UTC [646] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7482026/09/16 20:18:01 OK 20241026095416_initial_model.sql (107.28ms)7492026-09-16 20:18:01.825 UTC [649] ERROR: relation "goose_db_version" does not exist at character 367502026-09-16 20:18:01.825 UTC [649] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7512026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (14.62ms)7522026/09/16 20:18:01 OK 20251218171726_add_pins.sql (8.35ms)7532026/09/16 20:18:01 OK 20241026095416_initial_model.sql (45.07ms)7542026/09/16 20:18:01 OK 20241026095416_initial_model.sql (28.97ms)7552026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (5.17ms)7562026/09/16 20:18:01 OK 20241026095416_initial_model.sql (24.67ms)7572026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (6.78ms)7582026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (14.72ms)7592026/09/16 20:18:01 OK 20241026095416_initial_model.sql (40.07ms)7602026-09-16 20:18:01.860 UTC [650] ERROR: relation "goose_db_version" does not exist at character 367612026-09-16 20:18:01.860 UTC [650] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7622026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (5.67ms)7632026/09/16 20:18:01 OK 20241026095416_initial_model.sql (56.2ms)7642026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (16.93ms)7652026/09/16 20:18:01 OK 20260905000000_add_claims.sql (19.91ms)7662026/09/16 20:18:01 OK 20251218171726_add_pins.sql (22.26ms)7672026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000007682026/09/16 20:18:01 OK 20251218171726_add_pins.sql (25.83ms)7692026/09/16 20:18:01 OK 20241026095416_initial_model.sql (39.28ms)7702026/09/16 20:18:01 OK 20251218171726_add_pins.sql (18.06ms)7712026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (3.98ms)7722026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (7.93ms)7732026/09/16 20:18:01 OK 1_commit_pending_closure.sql (6.67ms)7742026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (7.62ms)7752026/09/16 20:18:01 OK 20251218171726_add_pins.sql (12.09ms)7762026/09/16 20:18:01 OK 20251218171726_add_pins.sql (6.16ms)7772026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (10.96ms)7782026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (10.57ms)7792026/09/16 20:18:01 OK 2_object_stats_trigger.sql (3.94ms)7802026/09/16 20:18:01 goose: up to current file version: 27812026/09/16 20:18:01 OK 20251218171726_add_pins.sql (7.86ms)7822026/09/16 20:18:01 OK 20260905000000_add_claims.sql (5.07ms)7832026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000007842026/09/16 20:18:01 OK 20260905000000_add_claims.sql (7.07ms)7852026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000007862026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (9.28ms)7872026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (10.91ms)7882026/09/16 20:18:01 OK 20260905000000_add_claims.sql (9.17ms)7892026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000007902026/09/16 20:18:01 OK 1_commit_pending_closure.sql (5.64ms)7912026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (10.38ms)7922026/09/16 20:18:01 OK 2_object_stats_trigger.sql (4.03ms)7932026/09/16 20:18:01 goose: up to current file version: 27942026/09/16 20:18:01 OK 1_commit_pending_closure.sql (6.31ms)7952026-09-16 20:18:01.904 UTC [651] ERROR: relation "goose_db_version" does not exist at character 367962026-09-16 20:18:01.904 UTC [651] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7972026-09-16 20:18:01.904 UTC [652] ERROR: relation "goose_db_version" does not exist at character 367982026-09-16 20:18:01.904 UTC [652] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7992026/09/16 20:18:01 OK 20260905000000_add_claims.sql (5.99ms)8002026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000008012026/09/16 20:18:01 OK 1_commit_pending_closure.sql (6.01ms)8022026/09/16 20:18:01 OK 20241026095416_initial_model.sql (16.23ms)8032026/09/16 20:18:01 OK 20260905000000_add_claims.sql (7.19ms)8042026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000008052026/09/16 20:18:01 OK 2_object_stats_trigger.sql (3.76ms)8062026/09/16 20:18:01 goose: up to current file version: 28072026/09/16 20:18:01 OK 2_object_stats_trigger.sql (3.49ms)8082026/09/16 20:18:01 goose: up to current file version: 28092026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (3.1ms)8102026/09/16 20:18:01 OK 1_commit_pending_closure.sql (3.88ms)8112026/09/16 20:18:01 OK 20260905000000_add_claims.sql (7.34ms)8122026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000008132026-09-16 20:18:01.912 UTC [654] ERROR: relation "goose_db_version" does not exist at character 368142026-09-16 20:18:01.912 UTC [654] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8152026/09/16 20:18:01 OK 1_commit_pending_closure.sql (5.8ms)8162026-09-16 20:18:01.913 UTC [653] ERROR: relation "goose_db_version" does not exist at character 368172026-09-16 20:18:01.913 UTC [653] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8182026/09/16 20:18:01 OK 2_object_stats_trigger.sql (4.06ms)8192026/09/16 20:18:01 goose: up to current file version: 28202026/09/16 20:18:01 OK 2_object_stats_trigger.sql (2.55ms)8212026/09/16 20:18:01 goose: up to current file version: 28222026/09/16 20:18:01 OK 20251218171726_add_pins.sql (5.57ms)8232026/09/16 20:18:01 OK 1_commit_pending_closure.sql (5.36ms)8242026-09-16 20:18:01.917 UTC [655] ERROR: relation "goose_db_version" does not exist at character 368252026-09-16 20:18:01.917 UTC [655] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8262026-09-16 20:18:01.918 UTC [657] ERROR: relation "goose_db_version" does not exist at character 368272026-09-16 20:18:01.918 UTC [657] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8282026-09-16 20:18:01.919 UTC [658] ERROR: relation "goose_db_version" does not exist at character 368292026-09-16 20:18:01.919 UTC [658] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8302026-09-16 20:18:01.919 UTC [656] ERROR: relation "goose_db_version" does not exist at character 368312026-09-16 20:18:01.919 UTC [656] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8322026-09-16 20:18:01.928 UTC [659] ERROR: relation "goose_db_version" does not exist at character 368332026-09-16 20:18:01.928 UTC [659] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8342026/09/16 20:18:01 OK 2_object_stats_trigger.sql (15.71ms)8352026/09/16 20:18:01 goose: up to current file version: 28362026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (18.64ms)8372026/09/16 20:18:01 OK 20241026095416_initial_model.sql (16.15ms)8382026/09/16 20:18:01 OK 20241026095416_initial_model.sql (18.11ms)8392026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (1.7ms)8402026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (2.17ms)8412026/09/16 20:18:01 OK 20260905000000_add_claims.sql (3.71ms)8422026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000008432026/09/16 20:18:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8442026/09/16 20:18:01 OK 20251218171726_add_pins.sql (3.89ms)8452026/09/16 20:18:01 OK 1_commit_pending_closure.sql (3.65ms)8462026/09/16 20:18:01 OK 20251218171726_add_pins.sql (4.72ms)8472026/09/16 20:18:01 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst848--- PASS: TestCompleteMultipartUnregistered (0.41s)849=== CONT TestProxyWriteTimeout850=== RUN TestProxyWriteTimeout/narinfo851=== PAUSE TestProxyWriteTimeout/narinfo852=== RUN TestProxyWriteTimeout/1_GiB_nar853=== PAUSE TestProxyWriteTimeout/1_GiB_nar854=== RUN TestProxyWriteTimeout/10_GiB_nar855=== PAUSE TestProxyWriteTimeout/10_GiB_nar856=== RUN TestProxyWriteTimeout/unknown_size857=== PAUSE TestProxyWriteTimeout/unknown_size858=== CONT TestClaim_HolderDisconnectKeepsClaim8592026/09/16 20:18:01 OK 2_object_stats_trigger.sql (2.2ms)8602026/09/16 20:18:01 goose: up to current file version: 28612026-09-16 20:18:01.945 UTC [663] ERROR: relation "goose_db_version" does not exist at character 368622026-09-16 20:18:01.945 UTC [663] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8632026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (4.61ms)8642026/09/16 20:18:01 OK 20241026095416_initial_model.sql (10.9ms)8652026-09-16 20:18:01.946 UTC [664] ERROR: relation "goose_db_version" does not exist at character 368662026-09-16 20:18:01.946 UTC [664] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8672026-09-16 20:18:01.946 UTC [665] ERROR: relation "goose_db_version" does not exist at character 368682026-09-16 20:18:01.946 UTC [665] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8692026/09/16 20:18:01 OK 20241026095416_initial_model.sql (11.7ms)8702026/09/16 20:18:01 OK 20241026095416_initial_model.sql (12.05ms)8712026-09-16 20:18:01.947 UTC [667] ERROR: relation "goose_db_version" does not exist at character 368722026-09-16 20:18:01.947 UTC [667] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8732026-09-16 20:18:01.947 UTC [666] ERROR: relation "goose_db_version" does not exist at character 368742026-09-16 20:18:01.947 UTC [666] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8752026-09-16 20:18:01.947 UTC [668] ERROR: relation "goose_db_version" does not exist at character 368762026-09-16 20:18:01.947 UTC [668] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8772026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (5.69ms)8782026/09/16 20:18:01 OK 20241026095416_initial_model.sql (12.96ms)8792026/09/16 20:18:01 OK 20241026095416_initial_model.sql (13.39ms)8802026/09/16 20:18:01 OK 20241026095416_initial_model.sql (12.92ms)8812026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (3.12ms)8822026/09/16 20:18:01 OK 20241026095416_initial_model.sql (13.27ms)8832026/09/16 20:18:01 OK 20260905000000_add_claims.sql (3.42ms)8842026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000008852026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (2.14ms)8862026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (2.22ms)8872026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (2.03ms)8882026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (1.66ms)8892026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (2.19ms)8902026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (2.74ms)8912026/09/16 20:18:01 OK 1_commit_pending_closure.sql (2.9ms)8922026/09/16 20:18:01 OK 20260905000000_add_claims.sql (3.76ms)8932026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000008942026/09/16 20:18:01 OK 20251218171726_add_pins.sql (3.99ms)8952026/09/16 20:18:01 OK 20251218171726_add_pins.sql (4.23ms)8962026/09/16 20:18:01 OK 20251218171726_add_pins.sql (3.49ms)8972026/09/16 20:18:01 OK 20251218171726_add_pins.sql (4.98ms)8982026/09/16 20:18:01 OK 2_object_stats_trigger.sql (2.17ms)8992026/09/16 20:18:01 goose: up to current file version: 29002026/09/16 20:18:01 OK 1_commit_pending_closure.sql (2.86ms)9012026/09/16 20:18:01 OK 20251218171726_add_pins.sql (3.72ms)9022026/09/16 20:18:01 OK 20251218171726_add_pins.sql (3.89ms)9032026/09/16 20:18:01 OK 20251218171726_add_pins.sql (4.61ms)9042026/09/16 20:18:01 OK 2_object_stats_trigger.sql (2.19ms)9052026/09/16 20:18:01 goose: up to current file version: 29062026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (4.31ms)9072026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (4.06ms)9082026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (5.03ms)9092026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (4.72ms)910=== NAME TestClientIntegration911 client_integration_test.go:277: Created store path: /build/TestClientIntegration2728371807/002/store/8xc9a067v22ww9sgwhx37y5a676mn869-test-file.txt9122026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (4.88ms)9132026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (5.94ms)9142026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (6.13ms)9152026/09/16 20:18:01 OK 20260905000000_add_claims.sql (3.92ms)9162026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000009172026/09/16 20:18:01 OK 20260905000000_add_claims.sql (4.97ms)9182026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000009192026/09/16 20:18:01 OK 20260905000000_add_claims.sql (4.24ms)9202026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000009212026/09/16 20:18:01 OK 20260905000000_add_claims.sql (4.18ms)9222026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000009232026/09/16 20:18:01 OK 20260905000000_add_claims.sql (4.32ms)9242026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000009252026/09/16 20:18:01 OK 20260905000000_add_claims.sql (4.3ms)9262026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000009272026/09/16 20:18:01 OK 1_commit_pending_closure.sql (2.97ms)9282026/09/16 20:18:01 OK 1_commit_pending_closure.sql (2.83ms)9292026/09/16 20:18:01 OK 1_commit_pending_closure.sql (3.28ms)9302026/09/16 20:18:01 OK 20260905000000_add_claims.sql (4.16ms)9312026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000009322026/09/16 20:18:01 OK 20241026095416_initial_model.sql (12.14ms)9332026/09/16 20:18:01 OK 1_commit_pending_closure.sql (3.02ms)9342026/09/16 20:18:01 OK 20241026095416_initial_model.sql (11.23ms)9352026/09/16 20:18:01 OK 20241026095416_initial_model.sql (13.01ms)9362026/09/16 20:18:01 OK 2_object_stats_trigger.sql (1.74ms)9372026/09/16 20:18:01 OK 1_commit_pending_closure.sql (2.92ms)9382026/09/16 20:18:01 OK 2_object_stats_trigger.sql (1.64ms)9392026/09/16 20:18:01 goose: up to current file version: 29402026/09/16 20:18:01 OK 2_object_stats_trigger.sql (1.71ms)9412026/09/16 20:18:01 goose: up to current file version: 29422026/09/16 20:18:01 goose: up to current file version: 29432026/09/16 20:18:01 OK 20241026095416_initial_model.sql (12.07ms)9442026/09/16 20:18:01 OK 2_object_stats_trigger.sql (1.69ms)9452026/09/16 20:18:01 goose: up to current file version: 29462026/09/16 20:18:01 OK 20241026095416_initial_model.sql (11.42ms)9472026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (1.74ms)9482026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (2.45ms)9492026/09/16 20:18:01 OK 1_commit_pending_closure.sql (2.77ms)9502026/09/16 20:18:01 OK 20241026095416_initial_model.sql (12.9ms)9512026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (1.65ms)9522026/09/16 20:18:01 OK 2_object_stats_trigger.sql (987.38µs)9532026/09/16 20:18:01 goose: up to current file version: 29542026/09/16 20:18:01 OK 1_commit_pending_closure.sql (2.66ms)9552026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (1.11ms)9562026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (1.05ms)9572026/09/16 20:18:01 OK 2_object_stats_trigger.sql (1.58ms)9582026/09/16 20:18:01 goose: up to current file version: 29592026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (1.67ms)9602026/09/16 20:18:01 OK 2_object_stats_trigger.sql (2.38ms)9612026/09/16 20:18:01 goose: up to current file version: 29622026-09-16 20:18:01.971 UTC [688] ERROR: relation "goose_db_version" does not exist at character 369632026-09-16 20:18:01.971 UTC [688] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9642026/09/16 20:18:01 OK 20251218171726_add_pins.sql (3.77ms)9652026/09/16 20:18:01 OK 20251218171726_add_pins.sql (3.64ms)9662026/09/16 20:18:01 OK 20251218171726_add_pins.sql (3.8ms)9672026/09/16 20:18:01 OK 20251218171726_add_pins.sql (3.32ms)9682026/09/16 20:18:01 OK 20251218171726_add_pins.sql (3.74ms)9692026/09/16 20:18:01 OK 20251218171726_add_pins.sql (3.84ms)9702026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (3.69ms)9712026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (4.37ms)9722026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (4.33ms)9732026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (3.45ms)9742026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (4.42ms)9752026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (3.66ms)9762026/09/16 20:18:01 OK 20260905000000_add_claims.sql (2.91ms)9772026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000009782026/09/16 20:18:01 OK 20260905000000_add_claims.sql (3.17ms)9792026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000009802026/09/16 20:18:01 OK 20260905000000_add_claims.sql (3.16ms)9812026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000009822026/09/16 20:18:01 OK 20260905000000_add_claims.sql (2.64ms)9832026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000009842026/09/16 20:18:01 OK 20260905000000_add_claims.sql (3.79ms)9852026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000009862026/09/16 20:18:01 OK 20260905000000_add_claims.sql (3.68ms)9872026/09/16 20:18:01 goose: successfully migrated database to version: 202609050000009882026/09/16 20:18:01 OK 1_commit_pending_closure.sql (2.4ms)9892026/09/16 20:18:01 OK 1_commit_pending_closure.sql (2.06ms)9902026/09/16 20:18:01 OK 1_commit_pending_closure.sql (1.99ms)9912026/09/16 20:18:01 OK 2_object_stats_trigger.sql (1.3ms)9922026/09/16 20:18:01 goose: up to current file version: 29932026/09/16 20:18:01 OK 1_commit_pending_closure.sql (2.15ms)9942026/09/16 20:18:01 OK 1_commit_pending_closure.sql (2.2ms)9952026/09/16 20:18:01 OK 2_object_stats_trigger.sql (1.5ms)9962026/09/16 20:18:01 goose: up to current file version: 29972026/09/16 20:18:01 OK 1_commit_pending_closure.sql (3ms)9982026/09/16 20:18:01 OK 2_object_stats_trigger.sql (1.61ms)9992026/09/16 20:18:01 goose: up to current file version: 210002026/09/16 20:18:01 OK 2_object_stats_trigger.sql (1.66ms)10012026/09/16 20:18:01 goose: up to current file version: 210022026/09/16 20:18:01 OK 2_object_stats_trigger.sql (1.41ms)10032026/09/16 20:18:01 OK 20241026095416_initial_model.sql (8.29ms)10042026/09/16 20:18:01 OK 2_object_stats_trigger.sql (2.33ms)10052026/09/16 20:18:01 goose: up to current file version: 210062026/09/16 20:18:01 goose: up to current file version: 210072026/09/16 20:18:01 OK 20251210153512_drop_unused_gin_index.sql (1.56ms)10082026/09/16 20:18:01 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1009--- PASS: TestService_AuthMiddleware (0.46s)1010=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle10112026/09/16 20:18:01 OK 20251218171726_add_pins.sql (2.53ms)10122026/09/16 20:18:01 OK 20260628120000_add_object_size_and_stats.sql (2.61ms)10132026/09/16 20:18:01 OK 20260905000000_add_claims.sql (2.32ms)10142026/09/16 20:18:01 goose: successfully migrated database to version: 2026090500000010152026/09/16 20:18:01 OK 1_commit_pending_closure.sql (1.92ms)10162026/09/16 20:18:01 OK 2_object_stats_trigger.sql (1.37ms)10172026/09/16 20:18:01 goose: up to current file version: 21018=== NAME TestNARDeduplicationMetadataUploadBug1019 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug4053993884/001/store/9jpzzsznxp3b8assdi4ykv6cnfvsw231-file1.txt10202026/09/16 20:18:02 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10212026/09/16 20:18:02 WARN readiness check failed error="closed pool"1022--- PASS: TestService_readinessHandler (0.50s)1023=== CONT TestClaim_BuildWaitComplete10242026-09-16 20:18:02.033 UTC [745] ERROR: relation "goose_db_version" does not exist at character 3610252026-09-16 20:18:02.033 UTC [745] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10262026/09/16 20:18:02 OK 20241026095416_initial_model.sql (8.29ms)10272026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (1.74ms)10282026/09/16 20:18:02 OK 20251218171726_add_pins.sql (2.45ms)1029--- PASS: TestService_healthCheckHandler (0.52s)1030=== CONT TestClaim_GCMarkedOutputCountsAsAbsent10312026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (3.71ms)10322026/09/16 20:18:02 OK 20260905000000_add_claims.sql (3.01ms)10332026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000010342026/09/16 20:18:02 OK 1_commit_pending_closure.sql (2.24ms)10352026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures10362026/09/16 20:18:02 OK 2_object_stats_trigger.sql (8.79ms)10372026/09/16 20:18:02 goose: up to current file version: 210382026/09/16 20:18:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10392026/09/16 20:18:02 INFO Uploading 8xc9a067v22ww9sgwhx37y5a676mn869-test-file.txt (152B)10402026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures10412026/09/16 20:18:02 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"10422026/09/16 20:18:02 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10432026-09-16 20:18:02.079 UTC [820] ERROR: relation "goose_db_version" does not exist at character 3610442026-09-16 20:18:02.079 UTC [820] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10452026/09/16 20:18:02 WARN Failed to register uploaded object key=8xc9a067v22ww9sgwhx37y5a676mn869.ls error="server returned 404: 404 page not found\n"10462026/09/16 20:18:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10472026/09/16 20:18:02 INFO Signed narinfos id=1 count=110482026/09/16 20:18:02 INFO Uploading 1 narinfos10492026/09/16 20:18:02 WARN Failed to register uploaded object key=8xc9a067v22ww9sgwhx37y5a676mn869.narinfo error="server returned 404: 404 page not found\n"10502026/09/16 20:18:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1051=== NAME TestPinProtectsFromGC1052 client_integration_test.go:648: Pinned store path: /build/TestPinProtectsFromGC3411165378/001/store/yf136shfj0h8xj3c227isjfjcis5jyav-pinned-file.txt1053 client_integration_test.go:649: Unpinned store path: /build/TestPinProtectsFromGC3411165378/001/store/hsm386azx553p24qfq36jpafb5akw46b-unpinned-file.txt10542026/09/16 20:18:02 INFO Completed upload id=110552026/09/16 20:18:02 INFO Upload complete. (96ms)1056--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.56s)1057=== CONT TestCacheStatsHandler10582026/09/16 20:18:02 OK 20241026095416_initial_model.sql (8.08ms)1059=== NAME TestClientIntegration1060 client_integration_test.go:293: Retrieved narinfo from S3:1061 StorePath: /build/TestClientIntegration2728371807/002/store/8xc9a067v22ww9sgwhx37y5a676mn869-test-file.txt1062 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1063 Compression: zstd1064 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11065 NarSize: 1521066 References: 1067 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk110682026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (1.6ms)1069 client_integration_test.go:294: Retrieved .ls file from S3 (compressed size: 77 bytes)1070 client_integration_test.go:294: Decompressed .ls content (64 bytes):1071 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1072 client_integration_test.go:297: Testing garbage collection...10732026/09/16 20:18:02 OK 20251218171726_add_pins.sql (2.74ms)10742026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (3.45ms)10752026/09/16 20:18:02 OK 20260905000000_add_claims.sql (3.49ms)10762026/09/16 20:18:02 goose: successfully migrated database to version: 202609050000001077--- PASS: TestReadRedirectKeepsNarinfoProxied (0.57s)1078=== CONT TestSkippedUploadsHandler10792026/09/16 20:18:02 OK 1_commit_pending_closure.sql (2.57ms)10802026/09/16 20:18:02 INFO Client skipped oversized paths paths=3 nar_bytes=500000000010812026/09/16 20:18:02 OK 2_object_stats_trigger.sql (1.32ms)10822026/09/16 20:18:02 goose: up to current file version: 210832026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures1084--- PASS: TestSkippedUploadsHandler (0.01s)1085=== CONT TestCacheConfigHandler1086=== RUN TestCacheConfigHandler/full_config,_no_issuer1087=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1088=== RUN TestCacheConfigHandler/no_cache_url_configured1089=== PAUSE TestCacheConfigHandler/no_cache_url_configured1090=== RUN TestCacheConfigHandler/no_signing_keys1091=== PAUSE TestCacheConfigHandler/no_signing_keys1092=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1093=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1094=== CONT TestParseSize1095--- PASS: TestParseSize (0.00s)1096=== CONT TestService_ReadScope_PublicByDefault10972026/09/16 20:18:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10982026/09/16 20:18:02 INFO Uploading 9jpzzsznxp3b8assdi4ykv6cnfvsw231-file1.txt (160B)10992026-09-16 20:18:02.126 UTC [878] ERROR: relation "goose_db_version" does not exist at character 3611002026-09-16 20:18:02.126 UTC [878] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11012026/09/16 20:18:02 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11022026/09/16 20:18:02 INFO Starting cleanup of old closures method=DELETE path=/api/closures11032026/09/16 20:18:02 INFO Garbage collection started11042026/09/16 20:18:02 WARN Failed to register uploaded object key=9jpzzsznxp3b8assdi4ykv6cnfvsw231.ls error="server returned 404: 404 page not found\n"11052026/09/16 20:18:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11062026/09/16 20:18:02 INFO Signed narinfos id=1 count=111072026/09/16 20:18:02 INFO Uploading 1 narinfos11082026/09/16 20:18:02 INFO Aborted multipart uploads count=011092026/09/16 20:18:02 WARN Failed to register uploaded object key=9jpzzsznxp3b8assdi4ykv6cnfvsw231.narinfo error="server returned 404: 404 page not found\n"11102026/09/16 20:18:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11112026/09/16 20:18:02 WARN Force mode enabled - objects will be deleted immediately without grace period11122026/09/16 20:18:02 INFO Aborted multipart uploads count=011132026/09/16 20:18:02 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011142026/09/16 20:18:02 INFO Vacuumed table table=pending_closures11152026/09/16 20:18:02 INFO Vacuumed table table=pending_objects11162026/09/16 20:18:02 INFO Vacuumed table table=multipart_uploads11172026/09/16 20:18:02 INFO Vacuumed table table=closures11182026/09/16 20:18:02 INFO Vacuumed table table=objects11192026/09/16 20:18:02 WARN Force mode enabled - objects will be deleted immediately without grace period11202026/09/16 20:18:02 INFO Completed upload id=111212026/09/16 20:18:02 OK 20241026095416_initial_model.sql (10.6ms)11222026/09/16 20:18:02 INFO Upload complete. (104ms)1123=== NAME TestNARDeduplicationMetadataUploadBug1124 metadata_upload_test.go:54: Retrieved narinfo from S3:1125 StorePath: /build/TestNARDeduplicationMetadataUploadBug4053993884/001/store/9jpzzsznxp3b8assdi4ykv6cnfvsw231-file1.txt1126 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1127 Compression: zstd1128 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1129 NarSize: 1601130 References: 1131 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf11322026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (1.6ms)11332026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures1134 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1135 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1136 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}11372026/09/16 20:18:02 OK 20251218171726_add_pins.sql (3.05ms)11382026/09/16 20:18:02 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1139--- PASS: TestGCMetrics (0.62s)1140=== CONT TestReadProxyNarinfo11412026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (3.51ms)11422026-09-16 20:18:02.154 UTC [916] ERROR: relation "goose_db_version" does not exist at character 3611432026-09-16 20:18:02.154 UTC [916] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11442026/09/16 20:18:02 OK 20260905000000_add_claims.sql (2.9ms)11452026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000011462026/09/16 20:18:02 OK 1_commit_pending_closure.sql (2.3ms)11472026/09/16 20:18:02 OK 2_object_stats_trigger.sql (1.48ms)11482026/09/16 20:18:02 goose: up to current file version: 211492026/09/16 20:18:02 OK 20241026095416_initial_model.sql (8.66ms)11502026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (1.28ms)11512026/09/16 20:18:02 OK 20251218171726_add_pins.sql (3.36ms)11522026/09/16 20:18:02 WARN claim: cannot clear write deadline error="feature not supported"1153=== NAME TestNARDeduplicationMetadataUploadBug1154 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug4053993884/001/store/583w4znw71a5vf4ja5wg16rqlx4n9iv5-file2.txt11552026-09-16 20:18:02.185 UTC [956] ERROR: relation "goose_db_version" does not exist at character 3611562026-09-16 20:18:02.185 UTC [956] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11572026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures11582026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (13.48ms)11592026/09/16 20:18:02 WARN claim: cannot clear write deadline error="feature not supported"11602026/09/16 20:18:02 OK 20260905000000_add_claims.sql (5.36ms)11612026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000011622026/09/16 20:18:02 OK 1_commit_pending_closure.sql (1.44ms)11632026/09/16 20:18:02 OK 2_object_stats_trigger.sql (673.38µs)11642026/09/16 20:18:02 goose: up to current file version: 211652026/09/16 20:18:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11662026/09/16 20:18:02 INFO Uploading yf136shfj0h8xj3c227isjfjcis5jyav-pinned-file.txt (128B)11672026/09/16 20:18:02 WARN claim: cannot clear write deadline error="feature not supported"11682026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures11692026/09/16 20:18:02 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"11702026/09/16 20:18:02 OK 20241026095416_initial_model.sql (10.24ms)11712026/09/16 20:18:02 INFO Received cleanup request method=DELETE path=/api/pending_closures11722026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (1.79ms)11732026/09/16 20:18:02 WARN Failed to register uploaded object key=yf136shfj0h8xj3c227isjfjcis5jyav.ls error="server returned 404: 404 page not found\n"11742026/09/16 20:18:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11752026/09/16 20:18:02 OK 20251218171726_add_pins.sql (2.59ms)11762026/09/16 20:18:02 INFO Signed narinfos id=1 count=111772026/09/16 20:18:02 INFO Aborted multipart uploads count=011782026/09/16 20:18:02 INFO Uploading 1 narinfos11792026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures11802026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (3.34ms)11812026/09/16 20:18:02 WARN Failed to register uploaded object key=yf136shfj0h8xj3c227isjfjcis5jyav.narinfo error="server returned 404: 404 page not found\n"11822026/09/16 20:18:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11832026/09/16 20:18:02 OK 20260905000000_add_claims.sql (3.21ms)11842026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000011852026-09-16 20:18:02.214 UTC [981] ERROR: relation "goose_db_version" does not exist at character 3611862026-09-16 20:18:02.214 UTC [981] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11872026/09/16 20:18:02 OK 1_commit_pending_closure.sql (1.88ms)11882026/09/16 20:18:02 OK 2_object_stats_trigger.sql (955.27µs)11892026/09/16 20:18:02 goose: up to current file version: 211902026/09/16 20:18:02 INFO Received cleanup request method=DELETE path=/api/pending_closures11912026/09/16 20:18:02 INFO Completed upload id=111922026/09/16 20:18:02 INFO Upload complete. (99ms)11932026/09/16 20:18:02 INFO Aborted multipart uploads count=111942026/09/16 20:18:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11952026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures11962026-09-16 20:18:02.227 UTC [658] ERROR: Closure does not exist: id=111972026-09-16 20:18:02.227 UTC [658] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE11982026-09-16 20:18:02.227 UTC [658] STATEMENT: -- name: CommitPendingClosure :exec1199 SELECT commit_pending_closure($1::bigint)1200 1201--- PASS: TestService_cleanupPendingClosuresHandler (0.69s)1202=== CONT TestService_Rustfstest12032026/09/16 20:18:02 OK 20241026095416_initial_model.sql (7.72ms)12042026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (1.6ms)12052026/09/16 20:18:02 OK 20251218171726_add_pins.sql (2.44ms)12062026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (2.72ms)12072026/09/16 20:18:02 OK 20260905000000_add_claims.sql (2.37ms)12082026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000012092026/09/16 20:18:02 OK 1_commit_pending_closure.sql (2.48ms)12102026/09/16 20:18:02 OK 2_object_stats_trigger.sql (744.07µs)12112026/09/16 20:18:02 goose: up to current file version: 212122026-09-16 20:18:02.242 UTC [988] ERROR: relation "goose_db_version" does not exist at character 3612132026-09-16 20:18:02.242 UTC [988] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12142026/09/16 20:18:02 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12152026/09/16 20:18:02 OK 20241026095416_initial_model.sql (8.07ms)12162026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (1.31ms)12172026/09/16 20:18:02 OK 20251218171726_add_pins.sql (2.24ms)12182026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (2.69ms)12192026/09/16 20:18:02 OK 20260905000000_add_claims.sql (3.02ms)12202026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000012212026/09/16 20:18:02 OK 1_commit_pending_closure.sql (1.73ms)12222026/09/16 20:18:02 OK 2_object_stats_trigger.sql (1.07ms)12232026/09/16 20:18:02 goose: up to current file version: 212242026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures12252026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures12262026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures12272026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures12282026/09/16 20:18:02 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12292026/09/16 20:18:02 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12302026/09/16 20:18:02 WARN Failed to register uploaded object key=583w4znw71a5vf4ja5wg16rqlx4n9iv5.ls error="server returned 404: 404 page not found\n"12312026/09/16 20:18:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12322026/09/16 20:18:02 INFO Signed narinfos id=2 count=112332026/09/16 20:18:02 INFO Uploading 1 narinfos12342026/09/16 20:18:02 WARN Failed to register uploaded object key=583w4znw71a5vf4ja5wg16rqlx4n9iv5.narinfo error="server returned 404: 404 page not found\n"12352026/09/16 20:18:02 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12362026/09/16 20:18:02 INFO Completed upload id=212372026/09/16 20:18:02 INFO Upload complete. (85ms)1238=== NAME TestNARDeduplicationMetadataUploadBug1239 metadata_upload_test.go:76: Retrieved narinfo from S3:1240 StorePath: /build/TestNARDeduplicationMetadataUploadBug4053993884/001/store/583w4znw71a5vf4ja5wg16rqlx4n9iv5-file2.txt1241 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1242 Compression: zstd1243 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1244 NarSize: 1601245 References: 1246 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1247 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1248 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1249 {"version":1,"root":{"type":"regular","size":44}}12502026-09-16 20:18:02.307 UTC [1061] ERROR: relation "goose_db_version" does not exist at character 3612512026-09-16 20:18:02.307 UTC [1061] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1252--- PASS: TestNARDeduplicationMetadataUploadBug (0.78s)1253=== CONT TestPresignedUploadRegisteredBeforeCommit12542026/09/16 20:18:02 OK 20241026095416_initial_model.sql (6.74ms)12552026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (979.21µs)12562026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures12572026/09/16 20:18:02 OK 20251218171726_add_pins.sql (2.17ms)12582026/09/16 20:18:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12592026/09/16 20:18:02 INFO Uploading hsm386azx553p24qfq36jpafb5akw46b-unpinned-file.txt (128B)12602026/09/16 20:18:02 WARN claim: cannot clear write deadline error="feature not supported"12612026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (3ms)12622026/09/16 20:18:02 OK 20260905000000_add_claims.sql (2.5ms)12632026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000012642026/09/16 20:18:02 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"12652026/09/16 20:18:02 OK 1_commit_pending_closure.sql (2.04ms)12662026/09/16 20:18:02 OK 2_object_stats_trigger.sql (656.81µs)12672026/09/16 20:18:02 goose: up to current file version: 212682026/09/16 20:18:02 WARN Failed to register uploaded object key=hsm386azx553p24qfq36jpafb5akw46b.ls error="server returned 404: 404 page not found\n"12692026/09/16 20:18:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12702026/09/16 20:18:02 INFO Signed narinfos id=2 count=112712026/09/16 20:18:02 INFO Uploading 1 narinfos12722026/09/16 20:18:02 WARN claim: cannot clear write deadline error="feature not supported"1273--- PASS: TestClaim_StaleHeartbeatStolen (0.79s)1274=== CONT TestReadRedirectNar12752026/09/16 20:18:02 WARN Failed to register uploaded object key=hsm386azx553p24qfq36jpafb5akw46b.narinfo error="server returned 404: 404 page not found\n"12762026/09/16 20:18:02 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12772026/09/16 20:18:02 INFO Completed upload id=212782026/09/16 20:18:02 INFO Upload complete. (87ms)1279=== NAME TestClientMultipleUploads1280 client_integration_test.go:339: Created store path 0: /build/TestClientMultipleUploads4256613242/001/store/ff4m6h9qxy01yh9pzcvcyjm0l6gwrn86-test-file-0.txt12812026/09/16 20:18:02 INFO Received create pin request method=POST path=/api/pins/myapp1282 client_integration_test.go:339: Created store path 1: /build/TestClientMultipleUploads4256613242/001/store/jx4rb7s1mrbk96svqjjiyp5labqyc3r2-test-file-1.txt12832026/09/16 20:18:02 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC3411165378/001/store/yf136shfj0h8xj3c227isjfjcis5jyav-pinned-file.txt narinfo_key=yf136shfj0h8xj3c227isjfjcis5jyav.narinfo12842026/09/16 20:18:02 INFO Starting cleanup of old closures method=DELETE path=/api/closures12852026/09/16 20:18:02 INFO Garbage collection started12862026/09/16 20:18:02 INFO Aborted multipart uploads count=012872026/09/16 20:18:02 WARN Force mode enabled - objects will be deleted immediately without grace period12882026/09/16 20:18:02 WARN claim: cannot clear write deadline error="feature not supported"12892026-09-16 20:18:02.405 UTC [1157] ERROR: relation "goose_db_version" does not exist at character 3612902026-09-16 20:18:02.405 UTC [1157] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1291 client_integration_test.go:339: Created store path 2: /build/TestClientMultipleUploads4256613242/001/store/8hhylnc6nccx3rycapc871gqg66hj4g3-test-file-2.txt1292--- PASS: TestClaim_TooManyStreams (0.88s)1293=== CONT TestCompletedNarNotReofferedAcrossClosures12942026/09/16 20:18:02 OK 20241026095416_initial_model.sql (7.12ms)12952026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (924.86µs)12962026-09-16 20:18:02.418 UTC [1191] ERROR: relation "goose_db_version" does not exist at character 3612972026-09-16 20:18:02.418 UTC [1191] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12982026/09/16 20:18:02 OK 20251218171726_add_pins.sql (3.85ms)12992026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (2.98ms)13002026/09/16 20:18:02 OK 20260905000000_add_claims.sql (3.94ms)13012026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000013022026/09/16 20:18:02 OK 1_commit_pending_closure.sql (2.02ms)13032026/09/16 20:18:02 OK 2_object_stats_trigger.sql (2.91ms)13042026/09/16 20:18:02 goose: up to current file version: 213052026/09/16 20:18:02 OK 20241026095416_initial_model.sql (12.19ms)13062026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (923.34µs)13072026/09/16 20:18:02 OK 20251218171726_add_pins.sql (3.99ms)1308=== NAME TestClientWithDependencies1309 client_integration_test.go:594: Built derivation: /build/TestClientWithDependencies1637429872/001/store/a40pzx1s7ig8h79ip0v8wvz7yaycr9kx-test-script13102026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (4.14ms)13112026/09/16 20:18:02 OK 20260905000000_add_claims.sql (3.43ms)13122026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000013132026/09/16 20:18:02 OK 1_commit_pending_closure.sql (2.22ms)13142026/09/16 20:18:02 OK 2_object_stats_trigger.sql (1.12ms)13152026/09/16 20:18:02 goose: up to current file version: 213162026/09/16 20:18:02 WARN claim: cannot clear write deadline error="feature not supported"13172026/09/16 20:18:02 WARN claim: cannot clear write deadline error="feature not supported"1318=== NAME TestClientCADerivations1319 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations26700939/001/store/wknhrg0ipfy43d3gka61bs6ff9iw7w0q-ca-test1320--- PASS: TestClaim_FailWithoutKindReleases (0.87s)1321=== CONT TestReadProxyHead1322=== NAME TestClientWithDependencies1323 client_integration_test.go:596: Found 1 dependencies (including self)13242026/09/16 20:18:02 WARN claim: cannot clear write deadline error="feature not supported"13252026/09/16 20:18:02 WARN claim: cannot clear write deadline error="feature not supported"13262026/09/16 20:18:02 WARN claim: cannot clear write deadline error="feature not supported"1327--- PASS: TestClaim_FailWakesWaitersButIsNotRemembered (0.69s)1328=== CONT TestReadProxyInvalidPath13292026-09-16 20:18:02.495 UTC [1272] ERROR: relation "goose_db_version" does not exist at character 3613302026-09-16 20:18:02.495 UTC [1272] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13312026/09/16 20:18:02 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1332=== NAME TestClientCADerivations1333 client_ca_test.go:139: Found 1 dependencies (including self)13342026/09/16 20:18:02 OK 20241026095416_initial_model.sql (7.86ms)13352026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (1.54ms)13362026/09/16 20:18:02 WARN claim: cannot clear write deadline error="feature not supported"13372026/09/16 20:18:02 OK 20251218171726_add_pins.sql (2.96ms)13382026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (3.45ms)13392026/09/16 20:18:02 OK 20260905000000_add_claims.sql (2.9ms)13402026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000013412026/09/16 20:18:02 WARN claim: cannot clear write deadline error="feature not supported"13422026/09/16 20:18:02 OK 1_commit_pending_closure.sql (2.02ms)13432026/09/16 20:18:02 OK 2_object_stats_trigger.sql (1.41ms)13442026/09/16 20:18:02 goose: up to current file version: 213452026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures13462026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures13472026/09/16 20:18:02 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13482026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures13492026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures13502026/09/16 20:18:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13512026/09/16 20:18:02 INFO Uploading a40pzx1s7ig8h79ip0v8wvz7yaycr9kx-test-script (136B)13522026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures13532026/09/16 20:18:02 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)13542026/09/16 20:18:02 INFO Uploading 8hhylnc6nccx3rycapc871gqg66hj4g3-test-file-2.txt (160B)13552026/09/16 20:18:02 INFO Uploading ff4m6h9qxy01yh9pzcvcyjm0l6gwrn86-test-file-0.txt (160B)13562026/09/16 20:18:02 INFO Uploading jx4rb7s1mrbk96svqjjiyp5labqyc3r2-test-file-1.txt (160B)13572026/09/16 20:18:02 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"13582026/09/16 20:18:02 WARN Failed to register uploaded object key=log/pjns3bdszznf68a7kpa89vscijg58cyj-test-script.drv error="server returned 404: 404 page not found\n"13592026/09/16 20:18:02 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"13602026/09/16 20:18:02 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"13612026/09/16 20:18:02 WARN Failed to register uploaded object key=a40pzx1s7ig8h79ip0v8wvz7yaycr9kx.ls error="server returned 404: 404 page not found\n"13622026/09/16 20:18:02 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"13632026/09/16 20:18:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13642026/09/16 20:18:02 INFO Signed narinfos id=1 count=113652026/09/16 20:18:02 WARN claim: cannot clear write deadline error="feature not supported"13662026-09-16 20:18:02.566 UTC [1384] ERROR: relation "goose_db_version" does not exist at character 3613672026-09-16 20:18:02.566 UTC [1384] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13682026/09/16 20:18:02 INFO Uploading 1 narinfos13692026/09/16 20:18:02 WARN Failed to register uploaded object key=8hhylnc6nccx3rycapc871gqg66hj4g3.ls error="server returned 404: 404 page not found\n"13702026/09/16 20:18:02 WARN Failed to register uploaded object key=jx4rb7s1mrbk96svqjjiyp5labqyc3r2.ls error="server returned 404: 404 page not found\n"13712026/09/16 20:18:02 WARN Failed to register uploaded object key=ff4m6h9qxy01yh9pzcvcyjm0l6gwrn86.ls error="server returned 404: 404 page not found\n"13722026/09/16 20:18:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13732026/09/16 20:18:02 INFO Signed narinfos id=1 count=113742026/09/16 20:18:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13752026/09/16 20:18:02 INFO Signed narinfos id=2 count=113762026/09/16 20:18:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign13772026/09/16 20:18:02 INFO Signed narinfos id=3 count=113782026/09/16 20:18:02 WARN Failed to register uploaded object key=a40pzx1s7ig8h79ip0v8wvz7yaycr9kx.narinfo error="server returned 404: 404 page not found\n"13792026/09/16 20:18:02 INFO Uploading 3 narinfos13802026/09/16 20:18:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13812026/09/16 20:18:02 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13822026/09/16 20:18:02 WARN Failed to register uploaded object key=8hhylnc6nccx3rycapc871gqg66hj4g3.narinfo error="server returned 404: 404 page not found\n"13832026/09/16 20:18:02 WARN Failed to register uploaded object key=jx4rb7s1mrbk96svqjjiyp5labqyc3r2.narinfo error="server returned 404: 404 page not found\n"13842026/09/16 20:18:02 WARN Failed to register uploaded object key=ff4m6h9qxy01yh9pzcvcyjm0l6gwrn86.narinfo error="server returned 404: 404 page not found\n"13852026/09/16 20:18:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13862026/09/16 20:18:02 WARN claim: cannot clear write deadline error="feature not supported"13872026/09/16 20:18:02 WARN claim: cannot clear write deadline error="feature not supported"13882026/09/16 20:18:02 INFO Completed upload id=113892026/09/16 20:18:02 INFO Upload complete. (70ms)13902026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures13912026/09/16 20:18:02 OK 20241026095416_initial_model.sql (7.22ms)13922026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (1.07ms)1393=== NAME TestClientWithDependencies1394 client_integration_test.go:598: Skipping nix copy test - isolated store (/build/TestClientWithDependencies1637429872/001/store) requires matching store prefix13952026-09-16 20:18:02.582 UTC [1404] ERROR: relation "goose_db_version" does not exist at character 3613962026-09-16 20:18:02.582 UTC [1404] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13972026/09/16 20:18:02 OK 20251218171726_add_pins.sql (2.62ms)13982026/09/16 20:18:02 INFO Completed upload id=113992026/09/16 20:18:02 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14002026/09/16 20:18:02 INFO Completed upload id=214012026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (3.08ms)14022026/09/16 20:18:02 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete14032026/09/16 20:18:02 INFO Completed upload id=314042026/09/16 20:18:02 INFO Upload complete. (122ms)1405=== NAME TestClientMultipleUploads1406 client_integration_test.go:350: Uploaded 3 paths in 172.724131ms1407--- PASS: TestClientWithDependencies (1.05s)1408=== CONT TestCompleteMultipartUpload_ErrorButObjectExists14092026/09/16 20:18:02 OK 20260905000000_add_claims.sql (3.48ms)14102026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000014112026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures1412--- PASS: TestClientMultipleUploads (1.06s)1413=== CONT TestReadProxy40414142026/09/16 20:18:02 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14152026/09/16 20:18:02 OK 1_commit_pending_closure.sql (9.24ms)14162026/09/16 20:18:02 OK 20241026095416_initial_model.sql (13.76ms)14172026/09/16 20:18:02 OK 2_object_stats_trigger.sql (831.18µs)14182026/09/16 20:18:02 goose: up to current file version: 214192026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (2ms)14202026/09/16 20:18:02 OK 20251218171726_add_pins.sql (3.07ms)14212026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures14222026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (4.07ms)14232026/09/16 20:18:02 OK 20260905000000_add_claims.sql (3.71ms)14242026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000014252026/09/16 20:18:02 OK 1_commit_pending_closure.sql (3.85ms)14262026/09/16 20:18:02 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=OWUwY2EzYmUtNTI3OS00YzhhLWFhY2EtZWNkODRhYzY2OTYzLjUxNDcyNzYxLTdmMDUtNGJkNS05ZmUwLWNjODlhMmIxZTNhMXgxNzg5NTg5ODgyMTU2NTAzOTk0 parts=1014272026/09/16 20:18:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14282026/09/16 20:18:02 OK 2_object_stats_trigger.sql (2.18ms)14292026/09/16 20:18:02 goose: up to current file version: 214302026/09/16 20:18:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14312026/09/16 20:18:02 INFO Uploading wknhrg0ipfy43d3gka61bs6ff9iw7w0q-ca-test (144B)14322026/09/16 20:18:02 INFO Completed upload id=114332026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures14342026/09/16 20:18:02 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"14352026/09/16 20:18:02 WARN Failed to register uploaded object key=log/pn46q76wfwymbjn3ylnzg31vwdll8a1p-ca-test.drv error="server returned 404: 404 page not found\n"14362026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures14372026/09/16 20:18:02 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo14382026/09/16 20:18:02 WARN Found objects in DB but missing from S3, will re-upload count=11439--- PASS: TestService_verifyS3Integrity (1.10s)1440=== CONT TestReadProxyDisabled14412026/09/16 20:18:02 WARN Failed to register uploaded object key=wknhrg0ipfy43d3gka61bs6ff9iw7w0q.ls error="server returned 404: 404 page not found\n"14422026/09/16 20:18:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14432026/09/16 20:18:02 INFO Signed narinfos id=1 count=114442026/09/16 20:18:02 INFO Uploading 1 narinfos14452026/09/16 20:18:02 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14462026/09/16 20:18:02 WARN Failed to register uploaded object key=wknhrg0ipfy43d3gka61bs6ff9iw7w0q.narinfo error="server returned 404: 404 page not found\n"14472026/09/16 20:18:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1448--- PASS: TestCacheStatsHandler (0.55s)1449=== CONT TestReadProxyNarStreaming14502026/09/16 20:18:02 INFO Completed upload id=114512026/09/16 20:18:02 INFO Upload complete. (115ms)14522026/09/16 20:18:02 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1453=== NAME TestClientCADerivations1454 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations26700939/001/store/wknhrg0ipfy43d3gka61bs6ff9iw7w0q-ca-test1455 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1456 Compression: zstd1457 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1458 NarSize: 1441459 References: 1460 Deriver: /build/TestClientCADerivations26700939/001/store/pn46q76wfwymbjn3ylnzg31vwdll8a1p-ca-test.drv1461 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1462 client_ca_test.go:185: Checking for realisation files in S3...1463 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1464 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache14652026/09/16 20:18:02 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001600000000000000000000.nar.zst upload_id=OWUwY2EzYmUtNTI3OS00YzhhLWFhY2EtZWNkODRhYzY2OTYzLjkzMDE2ZGU5LWMzOTAtNDYzMy05MjdhLWYxNjBmOWNmN2U2MngxNzg5NTg5ODgyMjA0ODgzNTE0 parts=1014662026/09/16 20:18:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14672026/09/16 20:18:02 INFO Signed narinfos id=1 count=114682026/09/16 20:18:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14692026/09/16 20:18:02 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1470--- PASS: TestService_ReadScope_PublicByDefault (0.57s)1471=== CONT TestRedundantMultipartUpload1472--- PASS: TestGCBugBareHashReferences (1.15s)1473=== CONT TestReadProxyNarinfoAlreadyDecompressed14742026/09/16 20:18:02 INFO Completed upload id=11475--- PASS: TestClaim_TwoInstances (1.16s)1476=== CONT TestReadProxyRootRedirectsToIndexHTML14772026-09-16 20:18:02.703 UTC [1482] ERROR: relation "goose_db_version" does not exist at character 3614782026-09-16 20:18:02.703 UTC [1482] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14792026/09/16 20:18:02 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001700000000000000000000.nar.zst upload_id=OWUwY2EzYmUtNTI3OS00YzhhLWFhY2EtZWNkODRhYzY2OTYzLmFhYzljNDQwLWY5OTEtNGM0OC1iMzQ4LWJkMzQwZmQ0NTFhYngxNzg5NTg5ODgyMjQxMTE5Mjcw parts=1014802026/09/16 20:18:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14812026/09/16 20:18:02 INFO Completed upload id=114822026/09/16 20:18:02 WARN claim: cannot clear write deadline error="feature not supported"14832026-09-16 20:18:02.712 UTC [1484] ERROR: relation "goose_db_version" does not exist at character 3614842026-09-16 20:18:02.712 UTC [1484] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14852026/09/16 20:18:02 OK 20241026095416_initial_model.sql (10.89ms)14862026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (2.11ms)1487--- PASS: TestReadProxyNarinfo (0.57s)1488=== CONT TestReadRedirectUsesPublicS3URL14892026/09/16 20:18:02 INFO Aborted multipart uploads count=014902026/09/16 20:18:02 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14912026/09/16 20:18:02 OK 20251218171726_add_pins.sql (3.21ms)14922026/09/16 20:18:02 WARN Force mode enabled - objects will be deleted immediately without grace period14932026/09/16 20:18:02 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014942026/09/16 20:18:02 OK 20241026095416_initial_model.sql (19.52ms)1495--- PASS: TestService_Rustfstest (0.51s)1496=== CONT TestReadProxyConditionalGet14972026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (16.33ms)14982026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (5.72ms)14992026/09/16 20:18:02 INFO Vacuumed table table=pending_closures15002026/09/16 20:18:02 OK 20260905000000_add_claims.sql (5ms)15012026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000015022026/09/16 20:18:02 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=OWUwY2EzYmUtNTI3OS00YzhhLWFhY2EtZWNkODRhYzY2OTYzLjMxM2RkMjU0LTY1YTctNDVkYi05NDM2LTNmMzI1Zjg5Y2NkM3gxNzg5NTg5ODgyMjg1NzUxODUy parts=1015032026/09/16 20:18:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15042026/09/16 20:18:02 OK 20251218171726_add_pins.sql (3.79ms)15052026/09/16 20:18:02 OK 1_commit_pending_closure.sql (2.83ms)15062026/09/16 20:18:02 INFO Vacuumed table table=pending_objects15072026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (4.01ms)15082026/09/16 20:18:02 INFO Completed upload id=115092026/09/16 20:18:02 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000015102026/09/16 20:18:02 OK 2_object_stats_trigger.sql (3.98ms)15112026/09/16 20:18:02 goose: up to current file version: 215122026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures15132026/09/16 20:18:02 INFO Vacuumed table table=multipart_uploads15142026/09/16 20:18:02 OK 20260905000000_add_claims.sql (5.02ms)15152026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000015162026/09/16 20:18:02 INFO Starting cleanup of old closures method=DELETE path=/api/closures15172026/09/16 20:18:02 INFO Vacuumed table table=closures15182026/09/16 20:18:02 OK 1_commit_pending_closure.sql (2.96ms)15192026/09/16 20:18:02 INFO Vacuumed table table=objects15202026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures15212026/09/16 20:18:02 OK 2_object_stats_trigger.sql (2.56ms)15222026/09/16 20:18:02 goose: up to current file version: 21523--- PASS: TestClaim_InputsTouched (1.22s)1524=== CONT TestReadProxyRangeRequest15252026-09-16 20:18:02.766 UTC [1615] ERROR: relation "goose_db_version" does not exist at character 3615262026-09-16 20:18:02.766 UTC [1615] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15272026/09/16 20:18:02 INFO Aborted multipart uploads count=015282026/09/16 20:18:02 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=0 objects-failed-to-delete=015292026/09/16 20:18:02 INFO Vacuumed table table=pending_closures15302026-09-16 20:18:02.785 UTC [1619] ERROR: relation "goose_db_version" does not exist at character 3615312026-09-16 20:18:02.785 UTC [1619] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1532--- PASS: TestReadRedirectNar (0.46s)1533=== CONT TestOrphanedObjectsGC15342026/09/16 20:18:02 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst15352026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures15362026/09/16 20:18:02 INFO Vacuumed table table=pending_objects15372026/09/16 20:18:02 OK 20241026095416_initial_model.sql (22.79ms)1538--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.49s)1539=== CONT TestService_NativeMTLS15402026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (3.27ms)15412026/09/16 20:18:02 INFO Vacuumed table table=multipart_uploads15422026/09/16 20:18:02 OK 20251218171726_add_pins.sql (5.74ms)15432026/09/16 20:18:02 OK 20241026095416_initial_model.sql (10.21ms)15442026/09/16 20:18:02 INFO Vacuumed table table=closures15452026-09-16 20:18:02.808 UTC [1692] ERROR: relation "goose_db_version" does not exist at character 3615462026-09-16 20:18:02.808 UTC [1692] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15472026/09/16 20:18:02 INFO Vacuumed table table=objects15482026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (2.28ms)15492026-09-16 20:18:02.810 UTC [1694] ERROR: relation "goose_db_version" does not exist at character 3615502026-09-16 20:18:02.810 UTC [1694] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15512026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures15522026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (6.1ms)15532026/09/16 20:18:02 OK 20251218171726_add_pins.sql (4.12ms)15542026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (3.67ms)15552026-09-16 20:18:02.818 UTC [1695] ERROR: relation "goose_db_version" does not exist at character 3615562026-09-16 20:18:02.818 UTC [1695] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15572026/09/16 20:18:02 OK 20260905000000_add_claims.sql (6.48ms)15582026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000015592026/09/16 20:18:02 OK 20260905000000_add_claims.sql (3.72ms)15602026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000015612026/09/16 20:18:02 OK 1_commit_pending_closure.sql (3.45ms)1562=== NAME TestClientCADerivations1563 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1564 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1565 error: binary cache 's3://bucket21?endpoint=http://localhost:40497®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations26700939/001/store'1566 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 115672026/09/16 20:18:02 OK 1_commit_pending_closure.sql (3.54ms)15682026/09/16 20:18:02 OK 2_object_stats_trigger.sql (2.53ms)15692026/09/16 20:18:02 goose: up to current file version: 215702026/09/16 20:18:02 OK 20241026095416_initial_model.sql (12.23ms)15712026/09/16 20:18:02 OK 2_object_stats_trigger.sql (2.87ms)15722026/09/16 20:18:02 goose: up to current file version: 215732026/09/16 20:18:02 OK 20241026095416_initial_model.sql (12.83ms)1574--- PASS: TestClientCADerivations (1.29s)1575=== CONT TestIsValidCachePath1576=== RUN TestIsValidCachePath/narinfo1577=== PAUSE TestIsValidCachePath/narinfo1578=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1579=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1580=== RUN TestIsValidCachePath/nar_zst1581=== PAUSE TestIsValidCachePath/nar_zst1582=== RUN TestIsValidCachePath/nar_xz1583=== PAUSE TestIsValidCachePath/nar_xz1584=== RUN TestIsValidCachePath/nar_bz21585=== PAUSE TestIsValidCachePath/nar_bz21586=== RUN TestIsValidCachePath/nar_uncompressed1587=== PAUSE TestIsValidCachePath/nar_uncompressed1588=== RUN TestIsValidCachePath/ls1589=== PAUSE TestIsValidCachePath/ls1590=== RUN TestIsValidCachePath/log1591=== PAUSE TestIsValidCachePath/log1592=== RUN TestIsValidCachePath/realisation1593=== PAUSE TestIsValidCachePath/realisation1594=== RUN TestIsValidCachePath/nix-cache-info1595=== PAUSE TestIsValidCachePath/nix-cache-info1596=== RUN TestIsValidCachePath/index.html15972026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (2.62ms)1598=== PAUSE TestIsValidCachePath/index.html1599=== RUN TestIsValidCachePath/traversal_parent1600=== PAUSE TestIsValidCachePath/traversal_parent1601=== RUN TestIsValidCachePath/traversal_in_middle1602=== PAUSE TestIsValidCachePath/traversal_in_middle1603=== RUN TestIsValidCachePath/invalid_char_e1604=== PAUSE TestIsValidCachePath/invalid_char_e1605=== RUN TestIsValidCachePath/invalid_char_u1606=== PAUSE TestIsValidCachePath/invalid_char_u1607=== RUN TestIsValidCachePath/random_path1608=== PAUSE TestIsValidCachePath/random_path1609=== RUN TestIsValidCachePath/empty1610=== PAUSE TestIsValidCachePath/empty1611=== RUN TestIsValidCachePath/leading_slash1612=== PAUSE TestIsValidCachePath/leading_slash1613=== RUN TestIsValidCachePath/wrong_extension1614=== PAUSE TestIsValidCachePath/wrong_extension1615=== RUN TestIsValidCachePath/short_hash1616=== PAUSE TestIsValidCachePath/short_hash1617=== CONT TestServerTLSConfig1618=== RUN TestServerTLSConfig/no_client_CA1619=== PAUSE TestServerTLSConfig/no_client_CA1620=== RUN TestServerTLSConfig/missing_CA_file1621=== PAUSE TestServerTLSConfig/missing_CA_file16222026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (1.77ms)1623=== RUN TestServerTLSConfig/not_a_PEM_file1624=== PAUSE TestServerTLSConfig/not_a_PEM_file1625=== CONT TestParseSingleRange1626=== RUN TestParseSingleRange/none1627=== PAUSE TestParseSingleRange/none1628=== RUN TestParseSingleRange/unknown_unit1629=== PAUSE TestParseSingleRange/unknown_unit1630=== RUN TestParseSingleRange/multi-range_ignored1631=== PAUSE TestParseSingleRange/multi-range_ignored1632=== RUN TestParseSingleRange/malformed_no_dash1633=== PAUSE TestParseSingleRange/malformed_no_dash1634=== RUN TestParseSingleRange/malformed_both_empty1635=== PAUSE TestParseSingleRange/malformed_both_empty1636=== RUN TestParseSingleRange/malformed_end_before_start1637=== PAUSE TestParseSingleRange/malformed_end_before_start1638=== RUN TestParseSingleRange/closed1639=== PAUSE TestParseSingleRange/closed1640=== RUN TestParseSingleRange/open-ended1641=== PAUSE TestParseSingleRange/open-ended1642=== RUN TestParseSingleRange/end_clamped_to_size1643=== PAUSE TestParseSingleRange/end_clamped_to_size1644=== RUN TestParseSingleRange/suffix1645=== PAUSE TestParseSingleRange/suffix1646=== RUN TestParseSingleRange/suffix_exceeds_size1647=== PAUSE TestParseSingleRange/suffix_exceeds_size1648=== RUN TestParseSingleRange/single_byte1649=== PAUSE TestParseSingleRange/single_byte1650=== RUN TestParseSingleRange/start_past_EOF1651=== PAUSE TestParseSingleRange/start_past_EOF1652=== RUN TestParseSingleRange/start_far_past_EOF1653=== PAUSE TestParseSingleRange/start_far_past_EOF1654=== CONT TestObjectStatsTrigger16552026/09/16 20:18:02 OK 20251218171726_add_pins.sql (3.24ms)16562026/09/16 20:18:02 OK 20251218171726_add_pins.sql (3.35ms)16572026/09/16 20:18:02 OK 20241026095416_initial_model.sql (9.97ms)16582026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (3.61ms)16592026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (3.21ms)16602026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (1.57ms)16612026/09/16 20:18:02 OK 20260905000000_add_claims.sql (2.87ms)16622026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000016632026/09/16 20:18:02 OK 20260905000000_add_claims.sql (3.36ms)16642026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000016652026-09-16 20:18:02.841 UTC [1697] ERROR: relation "goose_db_version" does not exist at character 3616662026-09-16 20:18:02.841 UTC [1697] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16672026/09/16 20:18:02 OK 20251218171726_add_pins.sql (3.41ms)16682026/09/16 20:18:02 OK 1_commit_pending_closure.sql (2.44ms)16692026/09/16 20:18:02 OK 1_commit_pending_closure.sql (2.41ms)16702026/09/16 20:18:02 OK 2_object_stats_trigger.sql (1.71ms)16712026/09/16 20:18:02 goose: up to current file version: 21672--- PASS: TestReadProxyHead (0.37s)1673=== CONT TestResurrectedObjectNotDeleted16742026/09/16 20:18:02 OK 2_object_stats_trigger.sql (1.99ms)16752026/09/16 20:18:02 goose: up to current file version: 216762026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (4.47ms)16772026-09-16 20:18:02.848 UTC [1699] ERROR: relation "goose_db_version" does not exist at character 3616782026-09-16 20:18:02.848 UTC [1699] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16792026/09/16 20:18:02 OK 20260905000000_add_claims.sql (3.56ms)16802026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000016812026/09/16 20:18:02 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000016822026/09/16 20:18:02 OK 1_commit_pending_closure.sql (11.79ms)1683--- PASS: TestService_createPendingClosureHandler (1.32s)1684=== CONT TestOrphanedObjectsGCStressTest16852026/09/16 20:18:02 OK 20241026095416_initial_model.sql (16.83ms)16862026/09/16 20:18:02 OK 2_object_stats_trigger.sql (3.78ms)16872026/09/16 20:18:02 goose: up to current file version: 216882026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (2.07ms)1689--- PASS: TestReadProxyInvalidPath (0.37s)1690=== CONT TestMultipartCleanup16912026/09/16 20:18:02 OK 20251218171726_add_pins.sql (4.28ms)16922026-09-16 20:18:02.874 UTC [1704] ERROR: relation "goose_db_version" does not exist at character 3616932026-09-16 20:18:02.874 UTC [1704] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16942026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (3.77ms)16952026/09/16 20:18:02 OK 20241026095416_initial_model.sql (11.86ms)16962026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (2.91ms)16972026/09/16 20:18:02 OK 20260905000000_add_claims.sql (5.93ms)16982026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000016992026/09/16 20:18:02 OK 20251218171726_add_pins.sql (3.49ms)17002026/09/16 20:18:02 OK 1_commit_pending_closure.sql (3.2ms)17012026/09/16 20:18:02 OK 2_object_stats_trigger.sql (2.02ms)17022026/09/16 20:18:02 goose: up to current file version: 217032026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (4.25ms)17042026/09/16 20:18:02 OK 20260905000000_add_claims.sql (3.79ms)17052026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000017062026/09/16 20:18:02 INFO Received uploads request method=POST path=/api/pending_closures17072026/09/16 20:18:02 OK 20241026095416_initial_model.sql (12.72ms)17082026/09/16 20:18:02 OK 1_commit_pending_closure.sql (3.66ms)17092026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (2.6ms)17102026/09/16 20:18:02 OK 2_object_stats_trigger.sql (2.64ms)17112026/09/16 20:18:02 goose: up to current file version: 217122026/09/16 20:18:02 OK 20251218171726_add_pins.sql (3.11ms)17132026-09-16 20:18:02.901 UTC [1708] ERROR: relation "goose_db_version" does not exist at character 3617142026-09-16 20:18:02.901 UTC [1708] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17152026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (4.27ms)17162026/09/16 20:18:02 OK 20260905000000_add_claims.sql (4.13ms)17172026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000017182026/09/16 20:18:02 OK 1_commit_pending_closure.sql (2.13ms)17192026/09/16 20:18:02 OK 2_object_stats_trigger.sql (1.94ms)17202026/09/16 20:18:02 goose: up to current file version: 217212026/09/16 20:18:02 OK 20241026095416_initial_model.sql (9.62ms)17222026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (2.2ms)17232026-09-16 20:18:02.922 UTC [1709] ERROR: relation "goose_db_version" does not exist at character 3617242026-09-16 20:18:02.922 UTC [1709] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1725--- PASS: TestReadProxy404 (0.33s)1726=== CONT TestService_AuthMiddleware_MTLSBoundSubjects17272026/09/16 20:18:02 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17282026/09/16 20:18:02 OK 20251218171726_add_pins.sql (11.99ms)17292026/09/16 20:18:02 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OWUwY2EzYmUtNTI3OS00YzhhLWFhY2EtZWNkODRhYzY2OTYzLjQ5MWU4Mzg5LTNjNGEtNGNkZC05Njk1LTY4ZTNmMGY5NDZiMXgxNzg5NTg5ODgyOTAyNjM2NjA417302026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (4.63ms)17312026/09/16 20:18:02 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OWUwY2EzYmUtNTI3OS00YzhhLWFhY2EtZWNkODRhYzY2OTYzLjQ5MWU4Mzg5LTNjNGEtNGNkZC05Njk1LTY4ZTNmMGY5NDZiMXgxNzg5NTg5ODgyOTAyNjM2NjA4 parts=11732--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.35s)1733=== CONT TestService_RequireScope_OIDC17342026/09/16 20:18:02 OK 20260905000000_add_claims.sql (4.01ms)17352026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000017362026/09/16 20:18:02 OK 1_commit_pending_closure.sql (2.73ms)17372026-09-16 20:18:02.944 UTC [1712] ERROR: relation "goose_db_version" does not exist at character 3617382026-09-16 20:18:02.944 UTC [1712] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17392026/09/16 20:18:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42799/oidc17402026/09/16 20:18:02 OK 20241026095416_initial_model.sql (10.01ms)17412026/09/16 20:18:02 OK 2_object_stats_trigger.sql (2.6ms)17422026/09/16 20:18:02 goose: up to current file version: 217432026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (2.42ms)17442026/09/16 20:18:02 OK 20251218171726_add_pins.sql (4.08ms)1745--- PASS: TestReadProxyDisabled (0.32s)1746=== CONT TestService_AuthMiddleware_OIDC17472026/09/16 20:18:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36435/oidc17482026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (3.77ms)17492026/09/16 20:18:02 OK 20241026095416_initial_model.sql (9.07ms)17502026/09/16 20:18:02 OK 20260905000000_add_claims.sql (3.4ms)17512026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000017522026-09-16 20:18:02.962 UTC [1715] ERROR: relation "goose_db_version" does not exist at character 3617532026-09-16 20:18:02.962 UTC [1715] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17542026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (2.38ms)17552026/09/16 20:18:02 OK 1_commit_pending_closure.sql (2.44ms)17562026/09/16 20:18:02 OK 2_object_stats_trigger.sql (1.27ms)17572026/09/16 20:18:02 goose: up to current file version: 217582026/09/16 20:18:02 OK 20251218171726_add_pins.sql (2.71ms)17592026-09-16 20:18:02.968 UTC [1718] ERROR: relation "goose_db_version" does not exist at character 3617602026-09-16 20:18:02.968 UTC [1718] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17612026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (4.01ms)17622026/09/16 20:18:02 OK 20260905000000_add_claims.sql (3.14ms)17632026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000017642026/09/16 20:18:02 OK 1_commit_pending_closure.sql (2.09ms)17652026-09-16 20:18:02.975 UTC [1719] ERROR: relation "goose_db_version" does not exist at character 3617662026-09-16 20:18:02.975 UTC [1719] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17672026/09/16 20:18:02 OK 2_object_stats_trigger.sql (1.67ms)17682026/09/16 20:18:02 goose: up to current file version: 217692026/09/16 20:18:02 OK 20241026095416_initial_model.sql (9.1ms)17702026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (2.07ms)17712026/09/16 20:18:02 OK 20241026095416_initial_model.sql (9.15ms)17722026/09/16 20:18:02 OK 20251218171726_add_pins.sql (2.73ms)17732026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (1.68ms)17742026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (3.81ms)17752026/09/16 20:18:02 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17762026/09/16 20:18:02 OK 20251218171726_add_pins.sql (3.61ms)17772026/09/16 20:18:02 OK 20260905000000_add_claims.sql (3.7ms)17782026/09/16 20:18:02 goose: successfully migrated database to version: 202609050000001779--- PASS: TestReadProxyNarStreaming (0.34s)1780=== CONT TestService_ReadAuthMiddleware17812026/09/16 20:18:02 OK 20241026095416_initial_model.sql (10.41ms)17822026/09/16 20:18:02 OK 20260628120000_add_object_size_and_stats.sql (4.81ms)17832026/09/16 20:18:02 OK 1_commit_pending_closure.sql (3.22ms)17842026/09/16 20:18:02 OK 20251210153512_drop_unused_gin_index.sql (2.03ms)17852026/09/16 20:18:02 OK 2_object_stats_trigger.sql (1.5ms)17862026/09/16 20:18:02 goose: up to current file version: 217872026/09/16 20:18:02 OK 20260905000000_add_claims.sql (3.31ms)17882026/09/16 20:18:02 goose: successfully migrated database to version: 2026090500000017892026/09/16 20:18:02 OK 20251218171726_add_pins.sql (2.92ms)17902026/09/16 20:18:02 OK 1_commit_pending_closure.sql (2.06ms)17912026/09/16 20:18:03 OK 2_object_stats_trigger.sql (1.18ms)17922026/09/16 20:18:03 goose: up to current file version: 217932026/09/16 20:18:03 OK 20260628120000_add_object_size_and_stats.sql (3.34ms)17942026/09/16 20:18:03 OK 20260905000000_add_claims.sql (2.96ms)17952026/09/16 20:18:03 goose: successfully migrated database to version: 2026090500000017962026/09/16 20:18:03 OK 1_commit_pending_closure.sql (2.78ms)17972026/09/16 20:18:03 OK 2_object_stats_trigger.sql (10.2ms)17982026/09/16 20:18:03 goose: up to current file version: 21799--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.33s)1800=== CONT TestService_AuthMiddleware_MTLSProxyHeader18012026/09/16 20:18:03 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001000000000000000000000.nar.zst upload_id=OWUwY2EzYmUtNTI3OS00YzhhLWFhY2EtZWNkODRhYzY2OTYzLmQyZTlkYTNhLTM5OGYtNGZjNC1iZWRkLWIzZGIwMDU2OWU3ZngxNzg5NTg5ODgyNTgzNzQyMTE0 parts=1018022026/09/16 20:18:03 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18032026/09/16 20:18:03 WARN claim: cannot clear write deadline error="feature not supported"18042026/09/16 20:18:03 INFO Signed narinfos id=1 count=118052026/09/16 20:18:03 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18062026/09/16 20:18:03 INFO Received uploads request method=POST path=/api/pending_closures18072026/09/16 20:18:03 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18082026/09/16 20:18:03 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign18092026/09/16 20:18:03 INFO Signed narinfos id=2 count=118102026/09/16 20:18:03 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete18112026/09/16 20:18:03 INFO Completed upload id=218122026-09-16 20:18:03.033 UTC [1725] ERROR: relation "goose_db_version" does not exist at character 3618132026-09-16 20:18:03.033 UTC [1725] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18142026/09/16 20:18:03 WARN claim: cannot clear write deadline error="feature not supported"1815--- PASS: TestClaim_BuildWaitComplete (1.00s)1816=== CONT TestMetricsInventory18172026/09/16 20:18:03 INFO Received uploads request method=POST path=/api/pending_closures18182026-09-16 20:18:03.047 UTC [1728] ERROR: relation "goose_db_version" does not exist at character 3618192026-09-16 20:18:03.047 UTC [1728] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18202026/09/16 20:18:03 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001100000000000000000000.nar.zst upload_id=OWUwY2EzYmUtNTI3OS00YzhhLWFhY2EtZWNkODRhYzY2OTYzLmY4NmY4MGJlLTY3MGItNDM2Yy04Y2RjLTI3ZjBkMzU0M2JlY3gxNzg5NTg5ODgyNjA2MDczNzM1 parts=1018212026/09/16 20:18:03 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18222026/09/16 20:18:03 OK 20241026095416_initial_model.sql (9.32ms)18232026/09/16 20:18:03 OK 20251210153512_drop_unused_gin_index.sql (2.78ms)18242026/09/16 20:18:03 INFO Completed upload id=118252026/09/16 20:18:03 WARN claim: cannot clear write deadline error="feature not supported"18262026/09/16 20:18:03 OK 20251218171726_add_pins.sql (3.16ms)18272026/09/16 20:18:03 INFO Received uploads request method=POST path=/api/pending_closures18282026/09/16 20:18:03 WARN claim: cannot clear write deadline error="feature not supported"18292026-09-16 20:18:03.060 UTC [1729] ERROR: relation "goose_db_version" does not exist at character 3618302026-09-16 20:18:03.060 UTC [1729] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18312026/09/16 20:18:03 OK 20260628120000_add_object_size_and_stats.sql (4.63ms)18322026/09/16 20:18:03 OK 20241026095416_initial_model.sql (9.53ms)18332026/09/16 20:18:03 OK 20260905000000_add_claims.sql (3.92ms)1834--- PASS: TestClaim_GCMarkedOutputCountsAsAbsent (1.01s)18352026/09/16 20:18:03 goose: successfully migrated database to version: 202609050000001836=== CONT TestClientErrorHandling/InvalidStorePath18372026/09/16 20:18:03 OK 20251210153512_drop_unused_gin_index.sql (2.17ms)18382026/09/16 20:18:03 OK 1_commit_pending_closure.sql (2.41ms)1839--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.37s)1840=== CONT TestClientErrorHandling/InvalidAuthToken18412026/09/16 20:18:03 OK 2_object_stats_trigger.sql (1.45ms)18422026/09/16 20:18:03 goose: up to current file version: 218432026/09/16 20:18:03 OK 20251218171726_add_pins.sql (3.88ms)18442026/09/16 20:18:03 OK 20260628120000_add_object_size_and_stats.sql (3.59ms)18452026/09/16 20:18:03 OK 20260905000000_add_claims.sql (3.3ms)18462026/09/16 20:18:03 goose: successfully migrated database to version: 2026090500000018472026/09/16 20:18:03 OK 20241026095416_initial_model.sql (11.51ms)18482026/09/16 20:18:03 OK 1_commit_pending_closure.sql (2.87ms)18492026/09/16 20:18:03 OK 20251210153512_drop_unused_gin_index.sql (2.03ms)18502026/09/16 20:18:03 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2139 objects-failed-to-delete=018512026/09/16 20:18:03 OK 2_object_stats_trigger.sql (2.78ms)18522026/09/16 20:18:03 goose: up to current file version: 218532026/09/16 20:18:03 OK 20251218171726_add_pins.sql (5.62ms)18542026/09/16 20:18:03 INFO Vacuumed table table=pending_closures18552026/09/16 20:18:03 OK 20260628120000_add_object_size_and_stats.sql (4.05ms)18562026-09-16 20:18:03.091 UTC [1734] ERROR: relation "goose_db_version" does not exist at character 3618572026-09-16 20:18:03.091 UTC [1734] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18582026/09/16 20:18:03 OK 20260905000000_add_claims.sql (11.36ms)18592026/09/16 20:18:03 goose: successfully migrated database to version: 202609050000001860--- PASS: TestReadRedirectUsesPublicS3URL (0.38s)1861=== CONT TestClientErrorHandling/ServerNotAvailable18622026/09/16 20:18:03 INFO Vacuumed table table=pending_objects18632026/09/16 20:18:03 OK 1_commit_pending_closure.sql (5.05ms)18642026/09/16 20:18:03 INFO Vacuumed table table=multipart_uploads18652026/09/16 20:18:03 OK 2_object_stats_trigger.sql (2.38ms)18662026/09/16 20:18:03 goose: up to current file version: 218672026/09/16 20:18:03 INFO Vacuumed table table=closures18682026/09/16 20:18:03 OK 20241026095416_initial_model.sql (8.12ms)18692026/09/16 20:18:03 OK 20251210153512_drop_unused_gin_index.sql (2.17ms)18702026/09/16 20:18:03 INFO Vacuumed table table=objects18712026-09-16 20:18:03.118 UTC [1736] ERROR: relation "goose_db_version" does not exist at character 3618722026-09-16 20:18:03.118 UTC [1736] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18732026/09/16 20:18:03 OK 20251218171726_add_pins.sql (2.96ms)18742026/09/16 20:18:03 OK 20260628120000_add_object_size_and_stats.sql (3.66ms)1875--- PASS: TestReadProxyConditionalGet (0.39s)1876=== CONT TestResolveDBConnectionString/flag_wins1877=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1878=== CONT TestResolveDBConnectionString/nothing_configured1879=== CONT TestResolveDBConnectionString/missing_file_is_an_error1880=== CONT TestResolveDBConnectionString/file_when_flag_empty1881=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18822026/09/16 20:18:03 INFO Received uploads request method=POST path=/1883--- PASS: TestResolveDBConnectionString (0.00s)1884 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1885 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1886 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1887 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1888 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)18892026/09/16 20:18:03 OK 20260905000000_add_claims.sql (3.05ms)18902026/09/16 20:18:03 goose: successfully migrated database to version: 2026090500000018912026/09/16 20:18:03 OK 1_commit_pending_closure.sql (2.43ms)18922026/09/16 20:18:03 OK 2_object_stats_trigger.sql (1.41ms)18932026/09/16 20:18:03 goose: up to current file version: 218942026/09/16 20:18:03 OK 20241026095416_initial_model.sql (8.45ms)18952026/09/16 20:18:03 OK 20251210153512_drop_unused_gin_index.sql (1.73ms)18962026/09/16 20:18:03 OK 20251218171726_add_pins.sql (3.4ms)18972026-09-16 20:18:03.140 UTC [1753] ERROR: relation "goose_db_version" does not exist at character 3618982026-09-16 20:18:03.140 UTC [1753] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18992026/09/16 20:18:03 OK 20260628120000_add_object_size_and_stats.sql (3.54ms)19002026/09/16 20:18:03 OK 20260905000000_add_claims.sql (3.07ms)19012026/09/16 20:18:03 goose: successfully migrated database to version: 2026090500000019022026/09/16 20:18:03 OK 1_commit_pending_closure.sql (2.1ms)19032026/09/16 20:18:03 OK 2_object_stats_trigger.sql (1.17ms)19042026/09/16 20:18:03 goose: up to current file version: 21905--- PASS: TestReadProxyRangeRequest (0.39s)1906=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19072026/09/16 20:18:03 INFO Received request for more parts method=POST path=/19082026-09-16 20:18:03.158 UTC [1755] ERROR: relation "goose_db_version" does not exist at character 3619092026-09-16 20:18:03.158 UTC [1755] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19102026/09/16 20:18:03 OK 20241026095416_initial_model.sql (15.32ms)19112026/09/16 20:18:03 OK 20251210153512_drop_unused_gin_index.sql (1.42ms)19122026-09-16 20:18:03.164 UTC [1756] ERROR: relation "goose_db_version" does not exist at character 3619132026-09-16 20:18:03.164 UTC [1756] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19142026/09/16 20:18:03 OK 20251218171726_add_pins.sql (4.07ms)19152026/09/16 20:18:03 OK 20241026095416_initial_model.sql (7.17ms)19162026/09/16 20:18:03 OK 20260628120000_add_object_size_and_stats.sql (4.37ms)19172026/09/16 20:18:03 OK 20251210153512_drop_unused_gin_index.sql (1.19ms)19182026/09/16 20:18:03 OK 20251218171726_add_pins.sql (2.26ms)19192026/09/16 20:18:03 OK 20260905000000_add_claims.sql (4.37ms)19202026/09/16 20:18:03 goose: successfully migrated database to version: 2026090500000019212026/09/16 20:18:03 OK 20260628120000_add_object_size_and_stats.sql (2.49ms)19222026/09/16 20:18:03 OK 20241026095416_initial_model.sql (6.94ms)19232026/09/16 20:18:03 OK 1_commit_pending_closure.sql (2.06ms)19242026/09/16 20:18:03 OK 20251210153512_drop_unused_gin_index.sql (948.25µs)19252026/09/16 20:18:03 OK 2_object_stats_trigger.sql (858.8µs)19262026/09/16 20:18:03 goose: up to current file version: 219272026/09/16 20:18:03 OK 20260905000000_add_claims.sql (1.95ms)19282026/09/16 20:18:03 goose: successfully migrated database to version: 2026090500000019292026/09/16 20:18:03 OK 1_commit_pending_closure.sql (1.28ms)19302026/09/16 20:18:03 OK 20251218171726_add_pins.sql (2ms)19312026/09/16 20:18:03 OK 2_object_stats_trigger.sql (940.38µs)19322026/09/16 20:18:03 goose: up to current file version: 219332026/09/16 20:18:03 OK 20260628120000_add_object_size_and_stats.sql (2.38ms)19342026/09/16 20:18:03 OK 20260905000000_add_claims.sql (2.33ms)19352026/09/16 20:18:03 goose: successfully migrated database to version: 2026090500000019362026/09/16 20:18:03 OK 1_commit_pending_closure.sql (1.86ms)19372026/09/16 20:18:03 WARN mTLS auth: subject not in bound subjects subject="CN=reader"19382026/09/16 20:18:03 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1939--- PASS: TestService_NativeMTLS (0.39s)1940=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart19412026/09/16 20:18:03 INFO Received complete multipart upload request method=POST path=/19422026/09/16 20:18:03 OK 2_object_stats_trigger.sql (812.67µs)19432026/09/16 20:18:03 goose: up to current file version: 21944=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info19452026/09/16 20:18:03 INFO Received uploads request method=POST path=/1946=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key19472026/09/16 20:18:03 INFO Received complete multipart upload request method=POST path=/1948=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key19492026/09/16 20:18:03 INFO Received request for more parts method=POST path=/1950=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal19512026/09/16 20:18:03 INFO Received uploads request method=POST path=/1952--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1953 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1954 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1955 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1956 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1957=== CONT TestIsValidUploadKey/narinfo1958=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1959=== CONT TestIsValidUploadKey/index.html1960=== CONT TestIsValidUploadKey/nix-cache-info1961=== CONT TestIsValidUploadKey/realisation_plus_in_output1962=== CONT TestIsValidUploadKey/realisation1963=== CONT TestIsValidUploadKey/build_log_equals1964=== CONT TestIsValidUploadKey/build_log_question_mark1965=== CONT TestIsValidUploadKey/build_log_plus_in_name1966=== CONT TestIsValidUploadKey/build_log_home-manager_file1967=== CONT TestIsValidUploadKey/build_log1968=== CONT TestIsValidUploadKey/listing1969=== CONT TestIsValidUploadKey/nar_plain1970=== CONT TestIsValidUploadKey/nar_xz1971=== CONT TestIsValidUploadKey/nar_zst1972=== CONT TestIsValidUploadKey/absolute1973=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1974=== CONT TestIsValidUploadKey/traversal_nar1975=== CONT TestIsValidUploadKey/traversal1976=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1977=== CONT TestIsValidUploadKey/empty_key1978=== CONT TestIsValidUploadKey/unknown_type1979--- PASS: TestIsValidUploadKey (0.00s)1980 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1981 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1982 --- PASS: TestIsValidUploadKey/index.html (0.00s)1983 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1984 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1985 --- PASS: TestIsValidUploadKey/realisation (0.00s)1986 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1987 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1988 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1989 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1990 --- PASS: TestIsValidUploadKey/build_log (0.00s)1991 --- PASS: TestIsValidUploadKey/listing (0.00s)1992 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1993 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1994 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1995 --- PASS: TestIsValidUploadKey/absolute (0.00s)1996 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1997 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1998 --- PASS: TestIsValidUploadKey/traversal (0.00s)1999 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2000 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2001 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2002=== CONT TestProxyWriteTimeout/narinfo2003=== CONT TestProxyWriteTimeout/10_GiB_nar2004=== CONT TestProxyWriteTimeout/1_GiB_nar2005=== CONT TestProxyWriteTimeout/unknown_size2006--- PASS: TestProxyWriteTimeout (0.00s)2007 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2008 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2009 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2010 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2011=== CONT TestCacheConfigHandler/full_config,_no_issuer2012=== CONT TestCacheConfigHandler/no_signing_keys2013=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2014=== CONT TestCacheConfigHandler/no_cache_url_configured2015--- PASS: TestCacheConfigHandler (0.00s)2016 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2017 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2018 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2019 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2020=== CONT TestIsValidCachePath/narinfo2021=== CONT TestIsValidCachePath/index.html2022=== CONT TestIsValidCachePath/short_hash2023=== CONT TestIsValidCachePath/wrong_extension2024=== CONT TestIsValidCachePath/leading_slash2025=== CONT TestIsValidCachePath/empty2026=== CONT TestIsValidCachePath/random_path2027=== CONT TestIsValidCachePath/invalid_char_u2028=== CONT TestIsValidCachePath/invalid_char_e2029=== CONT TestIsValidCachePath/traversal_in_middle2030=== CONT TestIsValidCachePath/traversal_parent2031=== CONT TestIsValidCachePath/nar_uncompressed2032=== CONT TestIsValidCachePath/nix-cache-info2033=== CONT TestIsValidCachePath/realisation2034=== CONT TestIsValidCachePath/log2035=== CONT TestIsValidCachePath/ls2036=== CONT TestIsValidCachePath/nar_xz2037=== CONT TestIsValidCachePath/nar_bz22038=== CONT TestIsValidCachePath/nar_zst2039=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2040=== CONT TestServerTLSConfig/no_client_CA2041--- PASS: TestIsValidCachePath (0.00s)2042 --- PASS: TestIsValidCachePath/narinfo (0.00s)2043 --- PASS: TestIsValidCachePath/index.html (0.00s)2044 --- PASS: TestIsValidCachePath/short_hash (0.00s)2045 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2046 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2047 --- PASS: TestIsValidCachePath/empty (0.00s)2048 --- PASS: TestIsValidCachePath/random_path (0.00s)2049 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2050 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2051 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2052 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2053 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2054 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2055 --- PASS: TestIsValidCachePath/realisation (0.00s)2056 --- PASS: TestIsValidCachePath/log (0.00s)2057 --- PASS: TestIsValidCachePath/ls (0.00s)2058 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2059 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2060 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2061 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2062=== CONT TestServerTLSConfig/not_a_PEM_file2063=== CONT TestServerTLSConfig/missing_CA_file2064--- PASS: TestServerTLSConfig (0.00s)2065 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2066 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2067 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2068=== CONT TestParseSingleRange/none2069=== CONT TestParseSingleRange/open-ended2070=== CONT TestParseSingleRange/start_far_past_EOF2071=== CONT TestParseSingleRange/start_past_EOF2072=== CONT TestParseSingleRange/single_byte2073=== CONT TestParseSingleRange/suffix_exceeds_size2074=== CONT TestParseSingleRange/suffix2075=== CONT TestParseSingleRange/end_clamped_to_size2076=== CONT TestParseSingleRange/malformed_both_empty2077=== CONT TestParseSingleRange/closed2078=== CONT TestParseSingleRange/malformed_end_before_start2079=== CONT TestParseSingleRange/multi-range_ignored2080=== CONT TestParseSingleRange/unknown_unit2081=== CONT TestParseSingleRange/malformed_no_dash2082--- PASS: TestParseSingleRange (0.00s)2083 --- PASS: TestParseSingleRange/none (0.00s)2084 --- PASS: TestParseSingleRange/open-ended (0.00s)2085 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2086 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2087 --- PASS: TestParseSingleRange/single_byte (0.00s)2088 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2089 --- PASS: TestParseSingleRange/suffix (0.00s)2090 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2091 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2092 --- PASS: TestParseSingleRange/closed (0.00s)2093 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2094 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2095 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2096 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)20972026/09/16 20:18:03 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2098--- PASS: TestObjectStatsTrigger (0.38s)2099--- PASS: TestResurrectedObjectNotDeleted (0.42s)21002026/09/16 20:18:03 INFO Received uploads request method=POST path=/api/pending_closures21012026/09/16 20:18:03 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21022026/09/16 20:18:03 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"21032026/09/16 20:18:03 WARN mTLS auth: bound subjects configured but subject DN unavailable21042026/09/16 20:18:03 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2105--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.36s)21062026/09/16 20:18:03 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=OWUwY2EzYmUtNTI3OS00YzhhLWFhY2EtZWNkODRhYzY2OTYzLjU5YTM0MGE2LWJlYjItNDYxNS04NmJiLTBlMDA2MzVhMzk4MXgxNzg5NTg5ODgyODIwMjA4OTIw parts=1221072026/09/16 20:18:03 INFO Received uploads request method=POST path=/api/pending_closures2108--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.88s)21092026/09/16 20:18:03 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=021102026/09/16 20:18:03 INFO Vacuumed table table=pending_closures21112026/09/16 20:18:03 INFO Vacuumed table table=pending_objects21122026/09/16 20:18:03 INFO Vacuumed table table=multipart_uploads21132026/09/16 20:18:03 INFO Vacuumed table table=closures21142026/09/16 20:18:03 INFO Vacuumed table table=objects21152026/09/16 20:18:03 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=218.087064ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2116=== RUN TestService_RequireScope_OIDC/builder_may_write2117=== PAUSE TestService_RequireScope_OIDC/builder_may_write2118=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2119=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2120=== RUN TestService_RequireScope_OIDC/ops_may_admin2121=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2122=== RUN TestService_RequireScope_OIDC/ops_may_not_write2123=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2124=== RUN TestService_RequireScope_OIDC/reader_may_not_write2125=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2126=== RUN TestService_RequireScope_OIDC/static_token_may_admin2127=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2128=== RUN TestService_RequireScope_OIDC/static_token_may_write2129=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2130=== RUN TestService_RequireScope_OIDC/reader_may_read2131=== PAUSE TestService_RequireScope_OIDC/reader_may_read2132=== RUN TestService_RequireScope_OIDC/writer_implies_read2133=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2134=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2135=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2136=== CONT TestService_RequireScope_OIDC/builder_may_write2137=== CONT TestService_RequireScope_OIDC/static_token_may_write2138=== CONT TestService_RequireScope_OIDC/static_token_may_admin2139=== CONT TestService_RequireScope_OIDC/ops_may_admin2140=== CONT TestService_RequireScope_OIDC/ops_may_not_write2141=== CONT TestService_RequireScope_OIDC/writer_implies_read2142=== CONT TestService_RequireScope_OIDC/reader_may_read2143=== CONT TestService_RequireScope_OIDC/reader_may_not_write2144=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2145=== CONT TestService_RequireScope_OIDC/builder_may_not_admin21462026/09/16 20:18:03 INFO OIDC auth successful provider=test scopes=[admin]21472026/09/16 20:18:03 INFO OIDC auth successful provider=test scopes=[read]21482026/09/16 20:18:03 INFO OIDC auth successful provider=test scopes=[admin]21492026/09/16 20:18:03 INFO OIDC auth successful provider=test scopes=[write]21502026/09/16 20:18:03 INFO OIDC auth successful provider=test scopes=[read]21512026/09/16 20:18:03 INFO OIDC auth successful provider=test scopes=[write]21522026/09/16 20:18:03 INFO OIDC auth successful provider=test scopes=[write]2153--- PASS: TestService_RequireScope_OIDC (0.38s)2154 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2155 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2156 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2157 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2158 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2159 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2160 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2161 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2162 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2163 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2164=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2165=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2166=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2167=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2168=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2169=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2170=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2171=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2172=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2173=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2174=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2175=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected21762026/09/16 20:18:03 WARN Authentication failed token_preview=not-a-valid-jwt token_length=15 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]21772026/09/16 20:18:03 INFO OIDC auth successful provider=test scopes=[write]21782026/09/16 20:18:03 WARN Authentication failed token_preview=eyJhbGciOi...ihnIhIralg token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2179--- PASS: TestService_AuthMiddleware_OIDC (0.37s)2180 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2181 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2182 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2183 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2184--- PASS: TestService_ReadAuthMiddleware (0.35s)2185--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.35s)21862026/09/16 20:18:03 INFO Received cleanup request method=DELETE path=/api/pending_closures21872026/09/16 20:18:03 INFO Aborted multipart uploads count=12188--- PASS: TestMultipartCleanup (0.51s)2189--- PASS: TestMetricsInventory (0.36s)2190=== NAME TestOrphanedObjectsGC2191 orphaned_objects_gc_test.go:290: GC Test Summary:2192 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A2193 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B2194 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)2195 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)2196 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects2197--- PASS: TestOrphanedObjectsGC (0.67s)21982026/09/16 20:18:03 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21992026/09/16 20:18:03 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=OWUwY2EzYmUtNTI3OS00YzhhLWFhY2EtZWNkODRhYzY2OTYzLmQ5ODA2NzljLTVmNDgtNGJkYi04NThlLTM4NzgxZmQ5OWM5ZngxNzg5NTg5ODgzMDUyMDQzNDk4 parts=122200--- PASS: TestRedundantMultipartUpload (0.81s)22012026/09/16 20:18:03 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"22022026/09/16 20:18:03 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=423.199094ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22032026/09/16 20:18:03 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2204--- PASS: TestUploadHandlersRejectOversizedBody (0.26s)2205 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)2206 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.05s)2207 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.61s)2208--- PASS: TestClaim_StreamsThroughServer (2.21s)22092026/09/16 20:18:03 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=768.027471ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22102026/09/16 20:18:04 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2139 objects_failed=02211=== NAME TestClientIntegration2212 client_integration_test.go:304: Objects in database after GC:2213 client_integration_test.go:304: Successfully deleted all objects with GC --force2214--- PASS: TestClientIntegration (2.60s)22152026/09/16 20:18:04 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02216=== NAME TestPinProtectsFromGC2217 client_integration_test.go:711: Pin successfully protected closure from garbage collection2218--- PASS: TestPinProtectsFromGC (2.86s)2219=== NAME TestOrphanedObjectsGCStressTest2220 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2221 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion22222026/09/16 20:18:04 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.465415982s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2223 orphaned_objects_gc_test.go:509: Stress test completed successfully:2224 orphaned_objects_gc_test.go:510: - Active objects preserved: 202225 orphaned_objects_gc_test.go:511: - Objects deleted: 2102226 orphaned_objects_gc_test.go:512: - Total GC'd: 2102227--- PASS: TestOrphanedObjectsGCStressTest (1.96s)2228--- PASS: TestClaim_HolderDisconnectKeepsClaim (3.08s)22292026/09/16 20:18:05 WARN Rate limiter enabled after throttle name=s3-test rate=522302026/09/16 20:18:05 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2231=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2232 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102233 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002234--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (3.58s)22352026/09/16 20:18:06 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"22362026/09/16 20:18:06 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22372026/09/16 20:18:06 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=213.686375ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22382026/09/16 20:18:06 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=364.534678ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22392026/09/16 20:18:06 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=804.918047ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22402026/09/16 20:18:07 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.52043032s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2241--- PASS: TestClientErrorHandling (0.00s)2242 --- PASS: TestClientErrorHandling/InvalidStorePath (0.37s)2243 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.50s)2244 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.15s)2245PASS2246{"timestamp":"2026-09-16T20:18:09.255067427Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:59940","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1880,"threadName":"rustfs-worker","threadId":"ThreadId(392)"}22472026-09-16 20:18:09.495 UTC [129] LOG: received smart shutdown request22482026-09-16 20:18:09.498 UTC [129] LOG: background worker "logical replication launcher" (PID 139) exited with exit code 122492026-09-16 20:18:09.504 UTC [134] LOG: shutting down22502026-09-16 20:18:09.505 UTC [134] LOG: checkpoint starting: shutdown immediate22512026-09-16 20:18:11.234 UTC [134] LOG: checkpoint complete: wrote 11428 buffers (69.8%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 17 recycled; write=0.257 s, sync=1.456 s, total=1.731 s; sync files=21000, longest=0.003 s, average=0.001 s; distance=282890 kB, estimate=282890 kB; lsn=0/12BA85B0, redo lsn=0/12BA85B022522026-09-16 20:18:11.319 UTC [129] LOG: database system is shut down2253Running OIDC tests...2254=== RUN TestGlobMatch2255=== PAUSE TestGlobMatch2256=== RUN TestAudienceForIssuer2257=== PAUSE TestAudienceForIssuer2258=== RUN TestValidateToken_ValidToken2259=== PAUSE TestValidateToken_ValidToken2260=== RUN TestValidateToken_WrongAudience2261=== PAUSE TestValidateToken_WrongAudience2262=== RUN TestValidateToken_Expired2263=== PAUSE TestValidateToken_Expired2264=== RUN TestValidateToken_BoundClaimsMismatch2265=== PAUSE TestValidateToken_BoundClaimsMismatch2266=== RUN TestValidateToken_BoundSubjectMismatch2267=== PAUSE TestValidateToken_BoundSubjectMismatch2268=== RUN TestValidateToken_MultipleProviders2269=== PAUSE TestValidateToken_MultipleProviders2270=== RUN TestValidateToken_NoMatchingProvider2271=== PAUSE TestValidateToken_NoMatchingProvider2272=== RUN TestValidateToken_KubernetesServiceAccount2273=== PAUSE TestValidateToken_KubernetesServiceAccount2274=== RUN TestNewValidator_KubernetesRequiresCA2275=== PAUSE TestNewValidator_KubernetesRequiresCA2276=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2277=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2278=== RUN TestScopes_LegacyProviderDefaultsToWrite2279=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2280=== RUN TestScopes_Rules2281=== PAUSE TestScopes_Rules2282=== RUN TestScopes_ConfigValidation2283=== PAUSE TestScopes_ConfigValidation2284=== CONT TestGlobMatch2285=== RUN TestGlobMatch/foo_foo2286=== CONT TestValidateToken_MultipleProviders2287=== CONT TestValidateToken_ValidToken2288=== PAUSE TestGlobMatch/foo_foo2289=== CONT TestAudienceForIssuer2290=== CONT TestValidateToken_Expired2291=== CONT TestValidateToken_WrongAudience2292=== CONT TestScopes_LegacyProviderDefaultsToWrite2293=== CONT TestScopes_ConfigValidation2294=== CONT TestScopes_Rules2295=== CONT TestValidateToken_BoundSubjectMismatch2296=== CONT TestValidateToken_BoundClaimsMismatch2297=== CONT TestNewValidator_KubernetesRequiresCA2298=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2299=== CONT TestValidateToken_KubernetesServiceAccount2300=== CONT TestValidateToken_NoMatchingProvider2301=== RUN TestGlobMatch/foo_bar2302--- PASS: TestAudienceForIssuer (0.00s)2303--- PASS: TestScopes_ConfigValidation (0.00s)2304=== PAUSE TestGlobMatch/foo_bar2305=== RUN TestGlobMatch/*_2306=== PAUSE TestGlobMatch/*_2307=== RUN TestGlobMatch/*_anything2308=== PAUSE TestGlobMatch/*_anything2309=== RUN TestGlobMatch/foo*_foo2310=== PAUSE TestGlobMatch/foo*_foo2311=== RUN TestGlobMatch/foo*_foobar2312=== PAUSE TestGlobMatch/foo*_foobar2313=== RUN TestGlobMatch/foo*_bar2314=== PAUSE TestGlobMatch/foo*_bar2315=== RUN TestGlobMatch/*bar_bar2316=== PAUSE TestGlobMatch/*bar_bar2317=== RUN TestGlobMatch/*bar_foobar2318=== PAUSE TestGlobMatch/*bar_foobar23192026/09/16 20:18:12 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:37759/oidc23202026/09/16 20:18:12 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40327/oidc2321=== RUN TestGlobMatch/*bar_foo23222026/09/16 20:18:12 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42771/oidc2323=== PAUSE TestGlobMatch/*bar_foo23242026/09/16 20:18:12 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37563/oidc2325=== RUN TestGlobMatch/foo*bar_foobar23262026/09/16 20:18:12 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44461/oidc23272026/09/16 20:18:12 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35185/oidc23282026/09/16 20:18:12 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41639/oidc2329=== PAUSE TestGlobMatch/foo*bar_foobar23302026/09/16 20:18:12 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232331=== RUN TestGlobMatch/foo*bar_foo123bar23322026/09/16 20:18:12 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:42253/oidc2333=== PAUSE TestGlobMatch/foo*bar_foo123bar2334=== RUN TestGlobMatch/foo*bar_foobarbaz2335=== PAUSE TestGlobMatch/foo*bar_foobarbaz2336=== RUN TestGlobMatch/*/*_foo/bar23372026/09/16 20:18:12 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44107/oidc2338=== PAUSE TestGlobMatch/*/*_foo/bar2339=== RUN TestGlobMatch/*/*_foo2340=== PAUSE TestGlobMatch/*/*_foo2341=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2342=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2343=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02344=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02345=== RUN TestGlobMatch/refs/*/main_refs/heads/main2346=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2347=== RUN TestGlobMatch/fo?_foo2348=== PAUSE TestGlobMatch/fo?_foo2349=== RUN TestGlobMatch/fo?_fo2350=== PAUSE TestGlobMatch/fo?_fo2351=== RUN TestGlobMatch/fo?_fooo2352=== PAUSE TestGlobMatch/fo?_fooo2353=== RUN TestGlobMatch/?oo_foo2354=== PAUSE TestGlobMatch/?oo_foo2355=== RUN TestGlobMatch/?oo_boo2356=== PAUSE TestGlobMatch/?oo_boo23572026/09/16 20:18:12 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:42507/oidc2358=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2359=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2360=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2361=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2362=== CONT TestGlobMatch/foo_foo2363=== CONT TestGlobMatch/*/*_foo/bar2364=== CONT TestGlobMatch/*bar_bar2365=== CONT TestGlobMatch/foo*_foobar2366=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2367=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2368=== CONT TestGlobMatch/*_anything2369=== CONT TestGlobMatch/?oo_boo2370=== CONT TestGlobMatch/?oo_foo2371=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02372=== CONT TestGlobMatch/foo_bar2373=== CONT TestGlobMatch/fo?_fooo2374=== CONT TestGlobMatch/fo?_fo2375=== CONT TestGlobMatch/fo?_foo2376=== CONT TestGlobMatch/refs/*/main_refs/heads/main2377=== CONT TestGlobMatch/foo*bar_foobarbaz2378=== CONT TestGlobMatch/foo*_bar2379=== CONT TestGlobMatch/*_2380=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2381=== CONT TestGlobMatch/foo*bar_foobar2382=== CONT TestGlobMatch/foo*_foo2383=== CONT TestGlobMatch/*bar_foobar2384=== CONT TestGlobMatch/foo*bar_foo123bar2385=== CONT TestGlobMatch/*bar_foo2386=== CONT TestGlobMatch/*/*_foo2387--- PASS: TestGlobMatch (0.01s)2388 --- PASS: TestGlobMatch/foo_foo (0.00s)2389 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2390 --- PASS: TestGlobMatch/*bar_bar (0.00s)2391 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2392 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2393 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2394 --- PASS: TestGlobMatch/*_anything (0.00s)2395 --- PASS: TestGlobMatch/?oo_boo (0.00s)2396 --- PASS: TestGlobMatch/?oo_foo (0.00s)2397 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2398 --- PASS: TestGlobMatch/foo_bar (0.00s)2399 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2400 --- PASS: TestGlobMatch/fo?_fo (0.00s)2401 --- PASS: TestGlobMatch/fo?_foo (0.00s)2402 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2403 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2404 --- PASS: TestGlobMatch/foo*_bar (0.00s)2405 --- PASS: TestGlobMatch/*_ (0.00s)2406 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2407 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2408 --- PASS: TestGlobMatch/foo*_foo (0.00s)2409 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2410 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2411 --- PASS: TestGlobMatch/*/*_foo (0.00s)2412 --- PASS: TestGlobMatch/*bar_foo (0.00s)2413--- PASS: TestValidateToken_NoMatchingProvider (0.01s)2414--- PASS: TestValidateToken_Expired (0.02s)2415--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)24162026/09/16 20:18:12 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:358612417--- PASS: TestValidateToken_ValidToken (0.02s)2418--- PASS: TestValidateToken_WrongAudience (0.02s)2419--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)2420--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.02s)2421--- PASS: TestValidateToken_MultipleProviders (0.02s)2422--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.02s)2423--- PASS: TestScopes_Rules (0.02s)2424--- PASS: TestValidateToken_KubernetesServiceAccount (0.02s)24252026/09/16 20:18:12 http: TLS handshake error from 127.0.0.1:60720: remote error: tls: bad certificate2426--- PASS: TestNewValidator_KubernetesRequiresCA (0.02s)2427PASS2428Running hook tests...2429=== RUN TestSendPathsEmpty2430=== PAUSE TestSendPathsEmpty2431=== RUN TestQueueEnqueueAndFetch2432=== PAUSE TestQueueEnqueueAndFetch2433=== RUN TestQueueDeduplication2434=== PAUSE TestQueueDeduplication2435=== RUN TestQueueRemove2436=== PAUSE TestQueueRemove2437=== RUN TestQueueFetchBatchLimit2438=== PAUSE TestQueueFetchBatchLimit2439=== RUN TestQueueRetryMovesToBack2440=== PAUSE TestQueueRetryMovesToBack2441=== RUN TestQueueFetchRemoveLifecycle2442=== PAUSE TestQueueFetchRemoveLifecycle2443=== RUN TestQueueConcurrentWriters2444=== PAUSE TestQueueConcurrentWriters2445=== RUN TestQueueRemoveLargeClosure2446=== PAUSE TestQueueRemoveLargeClosure2447=== RUN TestServerClientIntegration2448=== PAUSE TestServerClientIntegration2449=== RUN TestServerQueueError2450=== PAUSE TestServerQueueError2451=== RUN TestGetListenerSocketActivation2452 server_test.go:210: === RUN TestGetListenerSocketActivation2453 --- PASS: TestGetListenerSocketActivation (0.00s)2454 PASS2455 2456--- PASS: TestGetListenerSocketActivation (0.01s)2457=== RUN TestDrainIsolatesPoisonPath2458=== PAUSE TestDrainIsolatesPoisonPath2459=== RUN TestRunNotBlockedByPoisonHead2460=== PAUSE TestRunNotBlockedByPoisonHead2461=== RUN TestDrainGivesUpWhenServerDown2462=== PAUSE TestDrainGivesUpWhenServerDown2463=== RUN TestFailedPathPrunedByLaterClosure2464=== PAUSE TestFailedPathPrunedByLaterClosure2465=== RUN TestWorkerUploadsAndRemoves2466=== PAUSE TestWorkerUploadsAndRemoves2467=== RUN TestWorkerSkipsGCdPaths2468=== PAUSE TestWorkerSkipsGCdPaths2469=== RUN TestWorkerPrunesClosureDeps2470=== PAUSE TestWorkerPrunesClosureDeps2471=== RUN TestDrainTimeout2472=== PAUSE TestDrainTimeout2473=== CONT TestSendPathsEmpty2474=== CONT TestRunNotBlockedByPoisonHead2475=== CONT TestDrainIsolatesPoisonPath2476=== CONT TestQueueRetryMovesToBack2477=== CONT TestServerQueueError2478=== CONT TestDrainTimeout2479=== CONT TestWorkerPrunesClosureDeps2480=== CONT TestWorkerSkipsGCdPaths2481=== CONT TestWorkerUploadsAndRemoves2482=== CONT TestFailedPathPrunedByLaterClosure2483=== CONT TestDrainGivesUpWhenServerDown2484--- PASS: TestSendPathsEmpty (0.00s)2485=== CONT TestServerClientIntegration2486=== CONT TestQueueFetchBatchLimit2487=== CONT TestQueueRemove2488=== CONT TestQueueDeduplication2489=== CONT TestQueueEnqueueAndFetch2490=== CONT TestQueueConcurrentWriters2491=== CONT TestQueueRemoveLargeClosure24922026/09/16 20:18:12 ERROR Failed to queue paths error="permission denied" count=12493=== CONT TestQueueFetchRemoveLifecycle2494--- PASS: TestServerClientIntegration (0.00s)2495--- PASS: TestServerQueueError (0.00s)24962026/09/16 20:18:12 INFO Upload queue status pending=224972026/09/16 20:18:12 INFO Uploading batch count=124982026/09/16 20:18:12 INFO Upload queue status pending=224992026/09/16 20:18:12 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths1228088595/002/nonexistent25002026/09/16 20:18:12 INFO Upload queue status pending=325012026/09/16 20:18:12 INFO Uploading batch count=125022026/09/16 20:18:12 ERROR Upload failed error="upload failed" count=125032026/09/16 20:18:12 INFO Uploading batch count=125042026/09/16 20:18:12 INFO Uploading batch count=125052026/09/16 20:18:12 ERROR Upload failed error="upload failed" count=125062026/09/16 20:18:12 INFO Uploading batch count=425072026/09/16 20:18:12 ERROR Upload failed error="upload failed" count=425082026/09/16 20:18:12 INFO Uploading batch count=225092026/09/16 20:18:12 INFO Uploading batch count=225102026/09/16 20:18:12 ERROR Upload failed error="upload failed" count=22511--- PASS: TestQueueFetchBatchLimit (0.01s)25122026/09/16 20:18:12 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1186559922/002/a25132026/09/16 20:18:12 INFO Upload queue status pending=22514--- PASS: TestQueueEnqueueAndFetch (0.02s)25152026/09/16 20:18:12 INFO Uploading batch count=12516--- PASS: TestQueueFetchRemoveLifecycle (0.01s)25172026/09/16 20:18:12 INFO Uploading batch count=225182026/09/16 20:18:12 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath1574975709/002/bbb25192026/09/16 20:18:12 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1186559922/002/b25202026/09/16 20:18:12 INFO Uploading batch count=12521--- PASS: TestQueueRemove (0.02s)2522--- PASS: TestQueueDeduplication (0.02s)25232026/09/16 20:18:12 INFO Uploading batch count=225242026/09/16 20:18:12 ERROR Upload failed error="upload failed" count=22525--- PASS: TestQueueRetryMovesToBack (0.02s)25262026/09/16 20:18:12 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1186559922/002/c25272026/09/16 20:18:12 INFO Uploading batch count=125282026/09/16 20:18:12 ERROR Upload failed error="upload failed" count=125292026/09/16 20:18:12 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1186559922/002/d25302026/09/16 20:18:12 INFO Uploading batch count=125312026/09/16 20:18:12 ERROR Upload failed error="upload failed" count=12532--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)25332026/09/16 20:18:12 INFO Uploading batch count=225342026/09/16 20:18:12 ERROR Upload failed error="upload failed" count=225352026/09/16 20:18:12 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1186559922/002/e25362026/09/16 20:18:12 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1186559922/002/f25372026/09/16 20:18:12 INFO Uploading batch count=125382026/09/16 20:18:12 ERROR Upload failed error="upload failed" count=125392026/09/16 20:18:12 ERROR Drain finished with paths left in queue remaining=1025402026/09/16 20:18:12 ERROR Drain finished with paths left in queue remaining=12541--- PASS: TestDrainIsolatesPoisonPath (0.02s)2542--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2543--- PASS: TestWorkerSkipsGCdPaths (0.03s)2544--- PASS: TestWorkerUploadsAndRemoves (0.04s)2545--- PASS: TestWorkerPrunesClosureDeps (0.04s)2546--- PASS: TestQueueRemoveLargeClosure (0.07s)25472026/09/16 20:18:13 ERROR Upload failed error="context deadline exceeded" count=225482026/09/16 20:18:13 ERROR Drain finished with paths left in queue remaining=42549--- PASS: TestDrainTimeout (0.22s)2550--- PASS: TestQueueConcurrentWriters (0.27s)25512026/09/16 20:18:13 INFO Uploading batch count=125522026/09/16 20:18:13 INFO Uploading batch count=125532026/09/16 20:18:13 INFO Uploading batch count=125542026/09/16 20:18:13 ERROR Upload failed error="upload failed" count=125552026/09/16 20:18:13 INFO Uploading batch count=125562026/09/16 20:18:13 ERROR Upload failed error="upload failed" count=125572026/09/16 20:18:13 INFO Uploading batch count=125582026/09/16 20:18:13 ERROR Upload failed error="upload failed" count=125592026/09/16 20:18:13 INFO Uploading batch count=125602026/09/16 20:18:13 ERROR Upload failed error="upload failed" count=125612026/09/16 20:18:13 ERROR Drain finished with paths left in queue remaining=12562--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2563PASS