niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #325
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestRegisterUploadedObjectReusesConnections5=== PAUSE TestRegisterUploadedObjectReusesConnections6=== RUN TestCaseHackSuffix7=== PAUSE TestCaseHackSuffix8=== RUN TestFilterOversizedClosures9=== PAUSE TestFilterOversizedClosures10=== RUN TestUploadMultipart_PartsInParallel11=== PAUSE TestUploadMultipart_PartsInParallel12=== RUN TestPartSizeForNAR13=== PAUSE TestPartSizeForNAR14=== RUN TestUploadMultipart_SupersededByPeer15=== PAUSE TestUploadMultipart_SupersededByPeer16=== RUN TestDumpPathCaseHackMatchesNix17--- PASS: TestDumpPathCaseHackMatchesNix (0.09s)18=== RUN TestDumpPathCaseHackCollision19--- PASS: TestDumpPathCaseHackCollision (0.00s)20=== RUN TestDumpPathMatchesNix21=== PAUSE TestDumpPathMatchesNix22=== RUN TestDumpPathSingleFile23=== PAUSE TestDumpPathSingleFile24=== RUN TestDumpPathWriterError25=== PAUSE TestDumpPathWriterError26=== RUN TestEncodeNixBase3227=== PAUSE TestEncodeNixBase3228=== RUN TestEncodeNixBase32WithRealHash29=== PAUSE TestEncodeNixBase32WithRealHash30=== RUN TestConvertHashToNix3231=== PAUSE TestConvertHashToNix3232=== RUN TestGetStorePathHash33=== PAUSE TestGetStorePathHash34=== RUN TestPathInfoHashCompatibility35=== PAUSE TestPathInfoHashCompatibility36=== RUN TestParsePathInfoJSON37=== PAUSE TestParsePathInfoJSON38=== RUN TestParsePathInfoJSONMultiplePaths39=== PAUSE TestParsePathInfoJSONMultiplePaths40=== RUN TestPathInfoCACompatibility41=== PAUSE TestPathInfoCACompatibility42=== RUN TestRateLimiterFeedback43=== PAUSE TestRateLimiterFeedback44=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess45=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== RUN TestResolveStorePath47=== PAUSE TestResolveStorePath48=== RUN TestDoWithRetry_BodyReplayedViaGetBody49=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody50=== RUN TestShellSplit51=== PAUSE TestShellSplit52=== RUN TestShellSplitErrors53=== PAUSE TestShellSplitErrors54=== RUN TestStreamPushReportsEveryPath55=== PAUSE TestStreamPushReportsEveryPath56=== RUN TestStreamPushBatchesUnderLoad57=== PAUSE TestStreamPushBatchesUnderLoad58=== RUN TestStreamPushIsolatesFailures59=== PAUSE TestStreamPushIsolatesFailures60=== RUN TestStreamPushGivesUpOnDeadServer61=== PAUSE TestStreamPushGivesUpOnDeadServer62=== RUN TestStreamPushRequestLine63=== PAUSE TestStreamPushRequestLine64=== RUN TestStreamPushReportsSignatures65=== PAUSE TestStreamPushReportsSignatures66=== RUN TestClientSignaturesByStorePath67=== PAUSE TestClientSignaturesByStorePath68=== RUN TestSetClientTLS69=== PAUSE TestSetClientTLS70=== RUN TestSetClientTLSDoesNotMutateDefaultTransport71=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport72=== RUN TestSetClientTLSErrors73=== PAUSE TestSetClientTLSErrors74=== RUN TestStaticToken75=== PAUSE TestStaticToken76=== RUN TestFileTokenReadsAndCaches77=== PAUSE TestFileTokenReadsAndCaches78=== RUN TestFileTokenMissing79=== PAUSE TestFileTokenMissing80=== RUN TestFileTokenEmpty81=== PAUSE TestFileTokenEmpty82=== RUN TestScriptTokenNoExpiryRerunsEveryCall83=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall84=== RUN TestScriptTokenCachesUntilRefresh85=== PAUSE TestScriptTokenCachesUntilRefresh86=== RUN TestScriptTokenEmptyToken87=== PAUSE TestScriptTokenEmptyToken88=== RUN TestScriptTokenBadJSON89=== PAUSE TestScriptTokenBadJSON90=== RUN TestScriptTokenScriptFails91=== PAUSE TestScriptTokenScriptFails92=== RUN TestScriptTokenEmptyCommand93=== PAUSE TestScriptTokenEmptyCommand94=== CONT TestDoServerRequestAttachesToken95=== CONT TestShellSplit96--- PASS: TestShellSplit (0.00s)97=== CONT TestEncodeNixBase32WithRealHash98--- PASS: TestEncodeNixBase32WithRealHash (0.00s)99=== CONT TestGetStorePathHash100=== RUN TestGetStorePathHash/valid_store_path101=== PAUSE TestGetStorePathHash/valid_store_path102=== RUN TestGetStorePathHash/basename_without_hyphen_should_error103=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error104=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error105=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error106=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error107=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error108=== CONT TestConvertHashToNix32109=== RUN TestConvertHashToNix32/SRI_format_to_Nix32110=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32111=== RUN TestConvertHashToNix32/already_Nix32_format112=== PAUSE TestConvertHashToNix32/already_Nix32_format113=== RUN TestConvertHashToNix32/invalid_format114=== PAUSE TestConvertHashToNix32/invalid_format115=== CONT TestDoWithRetry_BodyReplayedViaGetBody116=== CONT TestUploadMultipart_SupersededByPeer117=== RUN TestUploadMultipart_SupersededByPeer/exists118=== CONT TestPathInfoHashCompatibility119=== PAUSE TestUploadMultipart_SupersededByPeer/exists120=== CONT TestResolveStorePath121=== CONT TestRateLimiterFeedback122=== CONT TestPathInfoCACompatibility123=== RUN TestPathInfoCACompatibility/null_ca_field124=== PAUSE TestPathInfoCACompatibility/null_ca_field125=== RUN TestPathInfoCACompatibility/old_string_format_-_text126=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text127=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive128=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive129=== RUN TestPathInfoCACompatibility/new_structured_format_-_text130=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text131=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method132=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method133=== CONT TestParsePathInfoJSONMultiplePaths134=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths135=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths136=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)137=== CONT TestParsePathInfoJSON138=== RUN TestParsePathInfoJSON/Nix_format139=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)140=== PAUSE TestParsePathInfoJSON/Nix_format141=== CONT TestEncodeNixBase32142=== RUN TestEncodeNixBase32/test_string_hash143=== PAUSE TestEncodeNixBase32/test_string_hash144=== RUN TestEncodeNixBase32/empty_input145=== PAUSE TestEncodeNixBase32/empty_input146=== CONT TestDumpPathWriterError147=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths148=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths149=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon150=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon151=== RUN TestParsePathInfoJSON/Lix_format152=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI153=== PAUSE TestParsePathInfoJSON/Lix_format154=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI155=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512156=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512157=== RUN TestParsePathInfoJSON/empty_input158=== RUN TestUploadMultipart_SupersededByPeer/missing159=== PAUSE TestParsePathInfoJSON/empty_input160=== RUN TestRateLimiterFeedback/429_enables_limiter161=== PAUSE TestRateLimiterFeedback/429_enables_limiter162=== RUN TestRateLimiterFeedback/503_enables_limiter163=== RUN TestParsePathInfoJSON/whitespace_only164=== PAUSE TestUploadMultipart_SupersededByPeer/missing165=== CONT TestDumpPathSingleFile166=== PAUSE TestParsePathInfoJSON/whitespace_only167=== RUN TestParsePathInfoJSON/invalid_JSON168=== PAUSE TestParsePathInfoJSON/invalid_JSON169=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess170=== CONT TestScriptTokenEmptyCommand171=== PAUSE TestRateLimiterFeedback/503_enables_limiter172--- PASS: TestScriptTokenEmptyCommand (0.00s)173=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter174=== CONT TestSetClientTLSErrors175=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter176=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter177=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter178=== CONT TestScriptTokenScriptFails1792026/10/01 09:52:11 WARN Rate limiter enabled after throttle name=server-test rate=5180=== CONT TestScriptTokenBadJSON1812026/10/01 09:52:11 WARN Rate limiter enabled after throttle na=== CONT TestDumpPathMatchesNix182me=server-test rate=5183=== CONT TestScriptTokenEmptyToken1842026/10/01 09:52:11 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:54896185--- PASS: TestDoServerRequestAttachesToken (0.00s)1862026/10/01 09:52:11 WARN Rate limiter backed off name=server-test rate=51872026/10/01 09:52:11 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:54896188--- PASS: TestResolveStorePath (0.00s)189=== CONT TestScriptTokenCachesUntilRefresh190--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)191=== CONT TestScriptTokenNoExpiryRerunsEveryCall192=== RUN TestSetClientTLSErrors/missing_cert_file193=== PAUSE TestSetClientTLSErrors/missing_cert_file194=== RUN TestSetClientTLSErrors/missing_key_file195=== PAUSE TestSetClientTLSErrors/missing_key_file196=== RUN TestSetClientTLSErrors/missing_ca_file197=== PAUSE TestSetClientTLSErrors/missing_ca_file198=== RUN TestSetClientTLSErrors/invalid_ca_file199=== PAUSE TestSetClientTLSErrors/invalid_ca_file200=== CONT TestFileTokenEmpty201--- PASS: TestScriptTokenScriptFails (0.01s)202=== CONT TestFileTokenMissing203--- PASS: TestFileTokenMissing (0.00s)204--- PASS: TestFileTokenEmpty (0.00s)205=== CONT TestStaticToken206--- PASS: TestStaticToken (0.00s)207=== CONT TestPartSizeForNAR208=== RUN TestPartSizeForNAR/zero_stays_at_minimum209=== CONT TestFileTokenReadsAndCaches210=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum211=== RUN TestPartSizeForNAR/small_stays_at_minimum212=== PAUSE TestPartSizeForNAR/small_stays_at_minimum213=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum214=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum215=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts216=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts217=== RUN TestPartSizeForNAR/1_TiB218=== PAUSE TestPartSizeForNAR/1_TiB219=== RUN TestPartSizeForNAR/5_TiB_S3_max_object220=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object221=== RUN TestPartSizeForNAR/capped_at_5_GiB222=== PAUSE TestPartSizeForNAR/capped_at_5_GiB223=== CONT TestCaseHackSuffix224--- PASS: TestFileTokenReadsAndCaches (0.00s)225=== CONT TestRegisterUploadedObjectReusesConnections226--- PASS: TestScriptTokenEmptyToken (0.01s)227=== CONT TestUploadMultipart_PartsInParallel228--- PASS: TestScriptTokenBadJSON (0.03s)229=== CONT TestFilterOversizedClosures230=== RUN TestFilterOversizedClosures/no_limit_keeps_everything231=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything232=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped233=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped234=== RUN TestFilterOversizedClosures/all_closures_skipped235=== PAUSE TestFilterOversizedClosures/all_closures_skipped236=== CONT TestSetClientTLS237=== RUN TestSetClientTLS/rejects_connection_without_client_cert238=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert239=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA240=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA241=== RUN TestSetClientTLS/preserves_debug_logging_transport242=== PAUSE TestSetClientTLS/preserves_debug_logging_transport243=== CONT TestStreamPushRequestLine2442026/10/01 09:52:11 ERROR Upload failed error=boom count=1245--- PASS: TestStreamPushRequestLine (0.02s)246=== CONT TestSetClientTLSDoesNotMutateDefaultTransport247--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)248=== CONT TestClientSignaturesByStorePath249--- PASS: TestClientSignaturesByStorePath (0.00s)250=== CONT TestStreamPushReportsSignatures2512026/10/01 09:52:11 ERROR Upload failed error=boom count=1252--- PASS: TestStreamPushReportsSignatures (0.00s)253=== CONT TestStreamPushBatchesUnderLoad254--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)255=== CONT TestStreamPushGivesUpOnDeadServer2562026/10/01 09:52:11 ERROR Upload failed error="connection refused" count=202572026/10/01 09:52:11 ERROR Server seems unavailable, giving up on batch untried=17258--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)259=== CONT TestStreamPushIsolatesFailures2602026/10/01 09:52:11 ERROR Upload failed error="bad path" count=3261--- PASS: TestStreamPushIsolatesFailures (0.00s)262=== CONT TestStreamPushReportsEveryPath263--- PASS: TestStreamPushReportsEveryPath (0.00s)264=== CONT TestShellSplitErrors265--- PASS: TestShellSplitErrors (0.00s)266=== CONT TestGetStorePathHash/valid_store_path267=== CONT TestConvertHashToNix32/SRI_format_to_Nix32268=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error269=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error270=== CONT TestGetStorePathHash/basename_without_hyphen_should_error271--- PASS: TestGetStorePathHash (0.00s)272 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)273 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)274 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)275 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)276=== CONT TestConvertHashToNix32/invalid_format277=== CONT TestConvertHashToNix32/already_Nix32_format278--- PASS: TestConvertHashToNix32 (0.00s)279 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)280 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)281 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)282=== CONT TestPathInfoCACompatibility/null_ca_field283=== CONT TestPathInfoCACompatibility/new_structured_format_-_text284=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive285=== CONT TestPathInfoCACompatibility/old_string_format_-_text286=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method287--- PASS: TestPathInfoCACompatibility (0.00s)288 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)289 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)290 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)291 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)292 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)293=== CONT TestEncodeNixBase32/test_string_hash294=== CONT TestEncodeNixBase32/empty_input295--- PASS: TestEncodeNixBase32 (0.00s)296 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)297 --- PASS: TestEncodeNixBase32/empty_input (0.00s)298=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths299=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths300--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)301 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)302 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)303=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)304=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512305=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI306=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon307--- PASS: TestPathInfoHashCompatibility (0.00s)308 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)309 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)310 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)311 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)312=== CONT TestUploadMultipart_SupersededByPeer/exists313=== CONT TestParsePathInfoJSON/Nix_format314=== CONT TestParsePathInfoJSON/invalid_JSON315=== CONT TestParsePathInfoJSON/whitespace_only316=== CONT TestParsePathInfoJSON/empty_input317=== CONT TestParsePathInfoJSON/Lix_format318--- PASS: TestParsePathInfoJSON (0.00s)319 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)320 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)321 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)322 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)323 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)324=== CONT TestRateLimiterFeedback/429_enables_limiter3252026/10/01 09:52:11 WARN Rate limiter enabled after throttle name=server-test rate=53262026/10/01 09:52:11 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:549743272026/10/01 09:52:11 WARN Rate limiter backed off name=server-test rate=5328=== CONT TestUploadMultipart_SupersededByPeer/missing329--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)330 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)331 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)332=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter333--- PASS: TestRegisterUploadedObjectReusesConnections (0.05s)334=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter335=== CONT TestRateLimiterFeedback/503_enables_limiter336=== CONT TestSetClientTLSErrors/missing_cert_file3372026/10/01 09:52:11 WARN Rate limiter enabled after throttle name=server-test rate=53382026/10/01 09:52:11 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:54982339=== CONT TestSetClientTLSErrors/missing_ca_file3402026/10/01 09:52:11 WARN Rate limiter backed off name=server-test rate=5341--- PASS: TestRateLimiterFeedback (0.00s)342 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)343 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)344 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)345 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)346=== CONT TestSetClientTLSErrors/invalid_ca_file347=== CONT TestSetClientTLSErrors/missing_key_file348=== CONT TestPartSizeForNAR/zero_stays_at_minimum349=== CONT TestPartSizeForNAR/5_TiB_S3_max_object350=== CONT TestPartSizeForNAR/1_TiB351=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts352=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum353=== CONT TestPartSizeForNAR/small_stays_at_minimum354=== CONT TestFilterOversizedClosures/no_limit_keeps_everything355=== CONT TestFilterOversizedClosures/all_closures_skipped3562026/10/01 09:52:11 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=50357=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3582026/10/01 09:52:11 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=2000359=== CONT TestPartSizeForNAR/capped_at_5_GiB360=== CONT TestSetClientTLS/rejects_connection_without_client_cert361=== CONT TestSetClientTLS/preserves_debug_logging_transport362--- PASS: TestFilterOversizedClosures (0.00s)363 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)364 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)365 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)366--- PASS: TestPartSizeForNAR (0.00s)367 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)368 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)369 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)370 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)371 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)372 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)373 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)374--- PASS: TestSetClientTLSErrors (0.01s)375 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)376 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)377 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)378 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)379=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA380--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.06s)3812026/10/01 09:52:11 http: TLS handshake error from 127.0.0.1:54984: remote error: tls: bad certificate382--- PASS: TestSetClientTLS (0.01s)383 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)384 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)385 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)386--- PASS: TestDumpPathWriterError (0.07s)387--- PASS: TestDumpPathSingleFile (0.09s)388--- PASS: TestCaseHackSuffix (0.10s)389--- PASS: TestDumpPathMatchesNix (0.13s)390--- PASS: TestStreamPushBatchesUnderLoad (0.10s)391--- PASS: TestUploadMultipart_PartsInParallel (0.62s)392--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)393PASS394Running server tests...395The files belonging to this database system will be owned by user "_nixbld1".396This user must also own the server process.397398The database cluster will be initialized with locale "C".399The default database encoding has accordingly been set to "SQL_ASCII".400The default text search configuration will be set to "english".401402Data page checksums are enabled.403404creating directory /nix/var/nix/builds/nix-90547-3700828917/postgres4290668340/data ... ok405creating subdirectories ... ok406selecting dynamic shared memory implementation ... posix407selecting default "max_connections" ... 100408selecting default "shared_buffers" ... 128MB409selecting default time zone ... UTC410creating configuration files ... ok411running bootstrap script ... ok412performing post-bootstrap initialization ... ok413syncing data to disk ... ok414415initdb: warning: enabling "trust" authentication for local connections416initdb: 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.417418Success. You can now start the database server using:419420 pg_ctl -D /nix/var/nix/builds/nix-90547-3700828917/postgres4290668340/data -l logfile start421422/nix/var/nix/builds/nix-90547-3700828917/postgres4290668340:5432 - no response4232026-10-01 09:52:13.273 UTC [90737] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4242026-10-01 09:52:13.273 UTC [90737] LOG: listening on Unix socket "/nix/var/nix/builds/nix-90547-3700828917/postgres4290668340/.s.PGSQL.5432"4252026-10-01 09:52:13.278 UTC [90744] LOG: database system was shut down at 2026-10-01 09:52:13 UTC4262026-10-01 09:52:13.281 UTC [90737] LOG: database system is ready to accept connections427/nix/var/nix/builds/nix-90547-3700828917/postgres4290668340:5432 - accepting connections428{"timestamp":"2026-10-01T09:52:13.49739Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"6665cf44-258a-40b6-a28c-facb231c4bcf","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}429{"timestamp":"2026-10-01T09:52:13.602103Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"4666d48c-7d06-4e96-a81b-3b338f397cb9","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}430=== RUN TestService_AuthMiddleware431=== PAUSE TestService_AuthMiddleware432=== RUN TestService_AuthMiddleware_MTLSProxyHeader433=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader434=== RUN TestService_AuthMiddleware_MTLSBoundSubjects435=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects436=== RUN TestService_ReadAuthMiddleware437=== PAUSE TestService_ReadAuthMiddleware438=== RUN TestService_AuthMiddleware_OIDC439=== PAUSE TestService_AuthMiddleware_OIDC440=== RUN TestService_RequireScope_OIDC441=== PAUSE TestService_RequireScope_OIDC442=== RUN TestService_ReadScope_PublicByDefault443=== PAUSE TestService_ReadScope_PublicByDefault444=== RUN TestCacheConfigHandler445=== PAUSE TestCacheConfigHandler446=== RUN TestCacheStatsHandler447=== PAUSE TestCacheStatsHandler448=== RUN TestClientCADerivations449=== PAUSE TestClientCADerivations450=== RUN TestClientErrorHandling451=== PAUSE TestClientErrorHandling452=== RUN TestClientIntegration453=== PAUSE TestClientIntegration454=== RUN TestClientMultipleUploads455=== PAUSE TestClientMultipleUploads456=== RUN TestClientWithDependencies457=== PAUSE TestClientWithDependencies458=== RUN TestClientSharedPathCommittedMidPush459=== PAUSE TestClientSharedPathCommittedMidPush460=== RUN TestPinProtectsFromGC461=== PAUSE TestPinProtectsFromGC462=== RUN TestClientPushesUseOnePush463=== PAUSE TestClientPushesUseOnePush464=== RUN TestClientFallsBackToClosures465=== PAUSE TestClientFallsBackToClosures466=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock467=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock468=== RUN TestResolveDBConnectionString469=== PAUSE TestResolveDBConnectionString470=== RUN TestLeadElectsOneAndHandsOver471=== PAUSE TestLeadElectsOneAndHandsOver472=== RUN TestLeadIncumbentWinsAfterRestart4732026-10-01 09:52:13.902 UTC [90779] ERROR: relation "goose_db_version" does not exist at character 364742026-10-01 09:52:13.902 UTC [90779] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4752026/10/01 09:52:13 OK 20241026095416_initial_model.sql (7.9ms)4762026/10/01 09:52:13 OK 20251210153512_drop_unused_gin_index.sql (1.06ms)4772026/10/01 09:52:13 OK 20251218171726_add_pins.sql (2.33ms)4782026/10/01 09:52:13 OK 20260628120000_add_object_size_and_stats.sql (2.48ms)4792026/10/01 09:52:13 OK 20260905000000_add_claims.sql (3.02ms)4802026/10/01 09:52:13 OK 20260920000000_drop_claims.sql (1.74ms)4812026/10/01 09:52:13 OK 20260923120000_add_pushes.sql (1.28ms)4822026/10/01 09:52:13 goose: successfully migrated database to version: 202609231200004832026/10/01 09:52:13 OK 1_commit_pending_closure.sql (2.12ms)4842026/10/01 09:52:13 OK 2_object_stats_trigger.sql (520.38µs)4852026/10/01 09:52:13 OK 3_commit_push.sql (422.25µs)4862026/10/01 09:52:13 goose: up to current file version: 34872026/10/01 09:52:14 INFO lead: acquired remote=192.0.2.1:12344882026/10/01 09:52:14 INFO lead: released remote=192.0.2.1:12344892026/10/01 09:52:14 INFO lead: acquired remote=192.0.2.1:12344902026/10/01 09:52:14 INFO lead: released remote=192.0.2.1:1234491--- PASS: TestLeadIncumbentWinsAfterRestart (0.97s)492=== RUN TestLeadEndsOnShutdown493=== PAUSE TestLeadEndsOnShutdown494=== RUN TestGCAdvisoryLockBlocksConcurrentRun4952026-10-01 09:52:14.751 UTC [90833] ERROR: relation "goose_db_version" does not exist at character 364962026-10-01 09:52:14.751 UTC [90833] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4972026/10/01 09:52:14 OK 20241026095416_initial_model.sql (8.05ms)4982026/10/01 09:52:14 OK 20251210153512_drop_unused_gin_index.sql (958.96µs)4992026/10/01 09:52:14 OK 20251218171726_add_pins.sql (2.2ms)5002026/10/01 09:52:14 OK 20260628120000_add_object_size_and_stats.sql (2.26ms)5012026/10/01 09:52:14 OK 20260905000000_add_claims.sql (2.58ms)5022026/10/01 09:52:14 OK 20260920000000_drop_claims.sql (1.32ms)5032026/10/01 09:52:14 OK 20260923120000_add_pushes.sql (1.26ms)5042026/10/01 09:52:14 goose: successfully migrated database to version: 202609231200005052026/10/01 09:52:14 OK 1_commit_pending_closure.sql (1.86ms)5062026/10/01 09:52:14 OK 2_object_stats_trigger.sql (559.79µs)5072026/10/01 09:52:14 OK 3_commit_push.sql (407.46µs)5082026/10/01 09:52:14 goose: up to current file version: 3509--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.19s)510=== RUN TestGCBugBareHashReferences511=== PAUSE TestGCBugBareHashReferences512=== RUN TestGCMetrics513=== PAUSE TestGCMetrics514=== RUN TestPushDedupSurvivesConcurrentGC515=== PAUSE TestPushDedupSurvivesConcurrentGC516=== RUN TestDeduplicatedObjectsRecordedAsPending517=== PAUSE TestDeduplicatedObjectsRecordedAsPending518=== RUN TestGCSweepSkipsPendingObjects519=== PAUSE TestGCSweepSkipsPendingObjects520=== RUN TestTombstonedObjectOfferedWithoutWaiting521=== PAUSE TestTombstonedObjectOfferedWithoutWaiting522=== RUN TestGCSweepDeliversEachKeyOnce523=== PAUSE TestGCSweepDeliversEachKeyOnce524=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection525=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection526=== RUN TestForceGCDuringPushOffersSweptObject527=== PAUSE TestForceGCDuringPushOffersSweptObject528=== RUN TestFailedS3DeleteKeepsTombstone529=== PAUSE TestFailedS3DeleteKeepsTombstone530=== RUN TestSweepSkipsRowsLockedByPush531=== PAUSE TestSweepSkipsRowsLockedByPush532=== RUN TestRegisterCompletedObjectNeedsPendingRow533=== PAUSE TestRegisterCompletedObjectNeedsPendingRow534=== RUN TestGetExistingObjectsLocksRows535=== PAUSE TestGetExistingObjectsLocksRows536=== RUN TestSweepRechecksPendingAfterLocking537=== PAUSE TestSweepRechecksPendingAfterLocking538=== RUN TestPushWaitsForSweepHoldingRow539=== PAUSE TestPushWaitsForSweepHoldingRow540=== RUN TestCommitRacingPendingCleanupKeepsObjects541=== PAUSE TestCommitRacingPendingCleanupKeepsObjects542=== RUN TestGCEndsOnShutdown543=== PAUSE TestGCEndsOnShutdown544=== RUN TestGCTaskStore_StartNew545=== PAUSE TestGCTaskStore_StartNew546=== RUN TestGCTaskStore_DeduplicateSameParams547=== PAUSE TestGCTaskStore_DeduplicateSameParams548=== RUN TestGCTaskStore_ConflictDifferentParams549=== PAUSE TestGCTaskStore_ConflictDifferentParams550=== RUN TestGCTaskStore_GetEmpty551=== PAUSE TestGCTaskStore_GetEmpty552=== RUN TestGCTaskStore_GetReturnsLatest553=== PAUSE TestGCTaskStore_GetReturnsLatest554=== RUN TestGCTaskStore_CompletedAllowsNewTask555=== PAUSE TestGCTaskStore_CompletedAllowsNewTask556=== RUN TestGCTaskStore_PhaseUpdates557=== PAUSE TestGCTaskStore_PhaseUpdates558=== RUN TestGCTaskStore_Fail559=== PAUSE TestGCTaskStore_Fail560=== RUN TestGracefulShutdownDrainsInflight561=== PAUSE TestGracefulShutdownDrainsInflight562=== RUN TestService_healthCheckHandler563=== PAUSE TestService_healthCheckHandler564=== RUN TestService_readinessHandler565=== PAUSE TestService_readinessHandler566=== RUN TestGenerateLandingPage567=== PAUSE TestGenerateLandingPage568=== RUN TestCacheConfigHandlerMaxNarSize569=== PAUSE TestCacheConfigHandlerMaxNarSize570=== RUN TestCreatePendingClosureRejectsOversizedNAR571=== PAUSE TestCreatePendingClosureRejectsOversizedNAR572=== RUN TestNARDeduplicationMetadataUploadBug573=== PAUSE TestNARDeduplicationMetadataUploadBug574=== RUN TestMetricsInventory575=== PAUSE TestMetricsInventory576=== RUN TestService_NativeMTLS577=== PAUSE TestService_NativeMTLS578=== RUN TestServerTLSConfig579=== PAUSE TestServerTLSConfig580=== RUN TestMultipartCleanup581=== PAUSE TestMultipartCleanup582=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded583=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded584=== RUN TestPendingCleanupUsesOneCutoff585=== PAUSE TestPendingCleanupUsesOneCutoff586=== RUN TestObjectStatsTrigger587=== PAUSE TestObjectStatsTrigger588=== RUN TestOrphanedObjectsGC589=== PAUSE TestOrphanedObjectsGC590=== RUN TestOrphanedObjectsGCStressTest591=== PAUSE TestOrphanedObjectsGCStressTest592=== RUN TestCreatePin_ReservedPins593=== PAUSE TestCreatePin_ReservedPins594=== RUN TestPresentReportsOnlyClosureRoots595=== PAUSE TestPresentReportsOnlyClosureRoots596=== RUN TestPresentNotReportedWhileGCDeletesClosure597=== PAUSE TestPresentNotReportedWhileGCDeletesClosure598=== RUN TestParseSingleRange599=== PAUSE TestParseSingleRange600=== RUN TestProxyHeadersOnlyTrustedOnSocket601=== PAUSE TestProxyHeadersOnlyTrustedOnSocket602=== RUN TestIsValidCachePath603=== PAUSE TestIsValidCachePath604=== RUN TestReadProxyNarinfo605=== PAUSE TestReadProxyNarinfo606=== RUN TestReadProxyNarinfoAlreadyDecompressed607=== PAUSE TestReadProxyNarinfoAlreadyDecompressed608=== RUN TestReadProxyNarStreaming609=== PAUSE TestReadProxyNarStreaming610=== RUN TestReadProxy404611=== PAUSE TestReadProxy404612=== RUN TestReadProxyInvalidPath613=== PAUSE TestReadProxyInvalidPath614=== RUN TestReadProxyHead615=== PAUSE TestReadProxyHead616=== RUN TestReadProxyConditionalGet617=== PAUSE TestReadProxyConditionalGet618=== RUN TestReadProxyRootRedirectsToIndexHTML619=== PAUSE TestReadProxyRootRedirectsToIndexHTML620=== RUN TestReadProxyDisabled621=== PAUSE TestReadProxyDisabled622=== RUN TestReadRedirectNar623=== PAUSE TestReadRedirectNar624=== RUN TestReadRedirectKeepsNarinfoProxied625=== PAUSE TestReadRedirectKeepsNarinfoProxied626=== RUN TestReadProxyRangeRequest627=== PAUSE TestReadProxyRangeRequest628=== RUN TestReadRedirectUsesPublicS3URL629=== PAUSE TestReadRedirectUsesPublicS3URL630=== RUN TestPush_OverlappingRootsStoreOneRowPerKey631=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey632=== RUN TestPush_CompleteCommitsEveryRoot633=== PAUSE TestPush_CompleteCommitsEveryRoot634=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit635=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit636=== RUN TestPush_RejectsBadRequests637=== PAUSE TestPush_RejectsBadRequests638=== RUN TestPush_SignsNarinfosOfItsPendingObjects639=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects640=== RUN TestRedundantMultipartUpload641=== PAUSE TestRedundantMultipartUpload642=== RUN TestCompleteMultipartUpload_ErrorButObjectExists643=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists644=== RUN TestCompletedNarNotReofferedAcrossClosures645=== PAUSE TestCompletedNarNotReofferedAcrossClosures646=== RUN TestPresignedUploadRegisteredBeforeCommit647=== PAUSE TestPresignedUploadRegisteredBeforeCommit648=== RUN TestService_Rustfstest649=== PAUSE TestService_Rustfstest650=== RUN TestParseSize651=== PAUSE TestParseSize652=== RUN TestSkippedUploadsHandler653=== PAUSE TestSkippedUploadsHandler654=== RUN TestSystemdListenerNotActivated655--- PASS: TestSystemdListenerNotActivated (0.00s)656=== RUN TestWatchdogBeatsWhenHealthy657--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)658=== RUN TestWatchdogSkipsWhenUnhealthy6592026/10/01 09:52:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6602026/10/01 09:52:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6612026/10/01 09:52:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6622026/10/01 09:52:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6632026/10/01 09:52:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6642026/10/01 09:52:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6652026/10/01 09:52:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6662026/10/01 09:52:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6672026/10/01 09:52:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6682026/10/01 09:52:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"669--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)670=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle671=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle672=== RUN TestProxyWriteTimeout673=== PAUSE TestProxyWriteTimeout674=== RUN TestIsValidUploadKey675=== PAUSE TestIsValidUploadKey676=== RUN TestUploadHandlersRejectInvalidKeys677=== PAUSE TestUploadHandlersRejectInvalidKeys678=== RUN TestUploadHandlersRejectOversizedBody679=== PAUSE TestUploadHandlersRejectOversizedBody680=== RUN TestService_cleanupPendingClosuresHandler681=== PAUSE TestService_cleanupPendingClosuresHandler682=== RUN TestService_createPendingClosureHandler683=== PAUSE TestService_createPendingClosureHandler684=== RUN TestService_verifyS3Integrity685=== PAUSE TestService_verifyS3Integrity686=== RUN TestCompleteMultipartUnregistered687=== PAUSE TestCompleteMultipartUnregistered688=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT689=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT690=== CONT TestParseSize691=== CONT TestService_Rustfstest692=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT693=== CONT TestProxyWriteTimeout694=== RUN TestProxyWriteTimeout/narinfo695=== PAUSE TestProxyWriteTimeout/narinfo696--- PASS: TestParseSize (0.00s)697=== CONT TestUploadHandlersRejectOversizedBody698=== CONT TestService_AuthMiddleware699=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle700=== CONT TestSkippedUploadsHandler701=== CONT TestService_verifyS3Integrity702=== CONT TestCompleteMultipartUnregistered703=== CONT TestService_createPendingClosureHandler7042026/10/01 09:52:15 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000705=== RUN TestProxyWriteTimeout/1_GiB_nar706=== PAUSE TestProxyWriteTimeout/1_GiB_nar707=== RUN TestProxyWriteTimeout/10_GiB_nar708=== PAUSE TestProxyWriteTimeout/10_GiB_nar709=== RUN TestProxyWriteTimeout/unknown_size710=== PAUSE TestProxyWriteTimeout/unknown_size711=== CONT TestGCTaskStore_Fail712--- PASS: TestGCTaskStore_Fail (0.00s)713=== CONT TestPresignedUploadRegisteredBeforeCommit714--- PASS: TestSkippedUploadsHandler (0.00s)715=== CONT TestCompletedNarNotReofferedAcrossClosures716=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure717=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure718=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart719=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart720=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts721=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts722=== CONT TestCompleteMultipartUpload_ErrorButObjectExists7232026-10-01 09:52:15.409 UTC [90876] ERROR: relation "goose_db_version" does not exist at character 367242026-10-01 09:52:15.409 UTC [90876] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7252026-10-01 09:52:15.435 UTC [90887] ERROR: relation "goose_db_version" does not exist at character 367262026-10-01 09:52:15.435 UTC [90887] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7272026-10-01 09:52:15.435 UTC [90886] ERROR: relation "goose_db_version" does not exist at character 367282026-10-01 09:52:15.435 UTC [90886] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7292026-10-01 09:52:15.440 UTC [90888] ERROR: relation "goose_db_version" does not exist at character 367302026-10-01 09:52:15.440 UTC [90888] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7312026-10-01 09:52:15.440 UTC [90889] ERROR: relation "goose_db_version" does not exist at character 367322026-10-01 09:52:15.440 UTC [90889] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7332026/10/01 09:52:15 OK 20241026095416_initial_model.sql (23.59ms)7342026-10-01 09:52:15.441 UTC [90890] ERROR: relation "goose_db_version" does not exist at character 367352026-10-01 09:52:15.441 UTC [90890] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7362026/10/01 09:52:15 OK 20251210153512_drop_unused_gin_index.sql (1.35ms)7372026-10-01 09:52:15.444 UTC [90892] ERROR: relation "goose_db_version" does not exist at character 367382026-10-01 09:52:15.444 UTC [90892] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7392026-10-01 09:52:15.445 UTC [90891] ERROR: relation "goose_db_version" does not exist at character 367402026-10-01 09:52:15.445 UTC [90891] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7412026/10/01 09:52:15 OK 20251218171726_add_pins.sql (3.04ms)7422026-10-01 09:52:15.447 UTC [90893] ERROR: relation "goose_db_version" does not exist at character 367432026-10-01 09:52:15.447 UTC [90893] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7442026/10/01 09:52:15 OK 20260628120000_add_object_size_and_stats.sql (2.89ms)7452026/10/01 09:52:15 OK 20260905000000_add_claims.sql (3.57ms)7462026/10/01 09:52:15 OK 20241026095416_initial_model.sql (12.52ms)7472026/10/01 09:52:15 OK 20241026095416_initial_model.sql (12.57ms)7482026-10-01 09:52:15.454 UTC [90894] ERROR: relation "goose_db_version" does not exist at character 367492026-10-01 09:52:15.454 UTC [90894] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7502026/10/01 09:52:15 OK 20260920000000_drop_claims.sql (2.5ms)7512026/10/01 09:52:15 OK 20251210153512_drop_unused_gin_index.sql (1.09ms)7522026/10/01 09:52:15 OK 20251210153512_drop_unused_gin_index.sql (1.17ms)7532026/10/01 09:52:15 OK 20260923120000_add_pushes.sql (1.56ms)7542026/10/01 09:52:15 goose: successfully migrated database to version: 202609231200007552026/10/01 09:52:15 OK 20241026095416_initial_model.sql (11.79ms)7562026/10/01 09:52:15 OK 20251218171726_add_pins.sql (2.71ms)7572026/10/01 09:52:15 OK 20241026095416_initial_model.sql (11.22ms)7582026/10/01 09:52:15 OK 1_commit_pending_closure.sql (2.24ms)7592026/10/01 09:52:15 OK 20251218171726_add_pins.sql (3.2ms)7602026/10/01 09:52:15 OK 2_object_stats_trigger.sql (613.38µs)7612026/10/01 09:52:15 OK 20251210153512_drop_unused_gin_index.sql (1.27ms)7622026/10/01 09:52:15 OK 20251210153512_drop_unused_gin_index.sql (1.11ms)7632026/10/01 09:52:15 OK 3_commit_push.sql (538.79µs)7642026/10/01 09:52:15 goose: up to current file version: 37652026/10/01 09:52:15 OK 20241026095416_initial_model.sql (12.84ms)7662026/10/01 09:52:15 OK 20260628120000_add_object_size_and_stats.sql (2.71ms)7672026/10/01 09:52:15 OK 20241026095416_initial_model.sql (11.17ms)7682026/10/01 09:52:15 OK 20251210153512_drop_unused_gin_index.sql (1.67ms)7692026/10/01 09:52:15 OK 20241026095416_initial_model.sql (10.88ms)7702026/10/01 09:52:15 OK 20260628120000_add_object_size_and_stats.sql (2.84ms)7712026/10/01 09:52:15 OK 20251218171726_add_pins.sql (2.4ms)7722026/10/01 09:52:15 OK 20251218171726_add_pins.sql (2.6ms)7732026/10/01 09:52:15 OK 20251210153512_drop_unused_gin_index.sql (999.54µs)7742026/10/01 09:52:15 OK 20241026095416_initial_model.sql (10.07ms)7752026/10/01 09:52:15 OK 20251210153512_drop_unused_gin_index.sql (1.14ms)7762026/10/01 09:52:15 OK 20251210153512_drop_unused_gin_index.sql (1.59ms)7772026/10/01 09:52:15 OK 20251218171726_add_pins.sql (2.45ms)7782026/10/01 09:52:15 OK 20260905000000_add_claims.sql (3.09ms)7792026/10/01 09:52:15 OK 20260905000000_add_claims.sql (9.63ms)7802026/10/01 09:52:15 OK 20251218171726_add_pins.sql (9.16ms)7812026/10/01 09:52:15 OK 20260628120000_add_object_size_and_stats.sql (9.78ms)7822026/10/01 09:52:15 OK 20260628120000_add_object_size_and_stats.sql (10.09ms)7832026/10/01 09:52:15 OK 20251218171726_add_pins.sql (9.83ms)7842026/10/01 09:52:15 OK 20251218171726_add_pins.sql (14.69ms)7852026/10/01 09:52:15 OK 20260920000000_drop_claims.sql (15.78ms)7862026/10/01 09:52:15 OK 20260920000000_drop_claims.sql (8.72ms)7872026/10/01 09:52:15 OK 20260628120000_add_object_size_and_stats.sql (16.27ms)7882026/10/01 09:52:15 OK 20260923120000_add_pushes.sql (7.57ms)7892026/10/01 09:52:15 goose: successfully migrated database to version: 202609231200007902026/10/01 09:52:15 OK 20260923120000_add_pushes.sql (7.77ms)7912026/10/01 09:52:15 goose: successfully migrated database to version: 202609231200007922026/10/01 09:52:15 OK 1_commit_pending_closure.sql (2.19ms)7932026/10/01 09:52:15 OK 1_commit_pending_closure.sql (2.19ms)7942026/10/01 09:52:15 OK 2_object_stats_trigger.sql (483.29µs)7952026/10/01 09:52:15 OK 2_object_stats_trigger.sql (559.92µs)7962026/10/01 09:52:15 OK 3_commit_push.sql (394.25µs)7972026/10/01 09:52:15 goose: up to current file version: 37982026/10/01 09:52:15 OK 3_commit_push.sql (416.96µs)7992026/10/01 09:52:15 goose: up to current file version: 38002026/10/01 09:52:15 OK 20260628120000_add_object_size_and_stats.sql (24.34ms)8012026/10/01 09:52:15 OK 20260628120000_add_object_size_and_stats.sql (23.23ms)8022026/10/01 09:52:15 OK 20260628120000_add_object_size_and_stats.sql (17.18ms)8032026/10/01 09:52:15 OK 20260905000000_add_claims.sql (24.51ms)8042026/10/01 09:52:15 OK 20260905000000_add_claims.sql (34.06ms)8052026/10/01 09:52:15 OK 20260920000000_drop_claims.sql (10.66ms)8062026/10/01 09:52:15 OK 20260905000000_add_claims.sql (26.91ms)8072026/10/01 09:52:15 OK 20241026095416_initial_model.sql (49.41ms)8082026/10/01 09:52:15 OK 20260905000000_add_claims.sql (13.04ms)8092026/10/01 09:52:15 OK 20260905000000_add_claims.sql (13.32ms)8102026/10/01 09:52:15 OK 20260923120000_add_pushes.sql (2.24ms)8112026/10/01 09:52:15 goose: successfully migrated database to version: 202609231200008122026/10/01 09:52:15 OK 20260905000000_add_claims.sql (13.4ms)8132026/10/01 09:52:15 OK 20260920000000_drop_claims.sql (3.21ms)8142026/10/01 09:52:15 OK 20260920000000_drop_claims.sql (2.98ms)8152026/10/01 09:52:15 OK 20251210153512_drop_unused_gin_index.sql (1.76ms)8162026/10/01 09:52:15 OK 20260920000000_drop_claims.sql (1.78ms)8172026/10/01 09:52:15 OK 1_commit_pending_closure.sql (1.85ms)8182026/10/01 09:52:15 OK 20260920000000_drop_claims.sql (1.99ms)8192026/10/01 09:52:15 OK 20260923120000_add_pushes.sql (900.08µs)8202026/10/01 09:52:15 goose: successfully migrated database to version: 202609231200008212026/10/01 09:52:15 OK 20260923120000_add_pushes.sql (1.62ms)8222026/10/01 09:52:15 goose: successfully migrated database to version: 202609231200008232026/10/01 09:52:15 OK 2_object_stats_trigger.sql (565.04µs)8242026/10/01 09:52:15 OK 20260920000000_drop_claims.sql (2.8ms)8252026/10/01 09:52:15 OK 3_commit_push.sql (857.33µs)8262026/10/01 09:52:15 goose: up to current file version: 38272026/10/01 09:52:15 OK 20260923120000_add_pushes.sql (1.96ms)8282026/10/01 09:52:15 goose: successfully migrated database to version: 202609231200008292026/10/01 09:52:15 OK 20260923120000_add_pushes.sql (1.59ms)8302026/10/01 09:52:15 goose: successfully migrated database to version: 202609231200008312026/10/01 09:52:15 OK 1_commit_pending_closure.sql (1.64ms)8322026/10/01 09:52:15 OK 1_commit_pending_closure.sql (1.77ms)8332026/10/01 09:52:15 OK 2_object_stats_trigger.sql (462.63µs)8342026/10/01 09:52:15 OK 1_commit_pending_closure.sql (2.37ms)8352026/10/01 09:52:15 OK 2_object_stats_trigger.sql (2.05ms)8362026/10/01 09:52:15 OK 3_commit_push.sql (1.85ms)8372026/10/01 09:52:15 goose: up to current file version: 38382026/10/01 09:52:15 OK 3_commit_push.sql (373.79µs)8392026/10/01 09:52:15 goose: up to current file version: 38402026/10/01 09:52:15 OK 2_object_stats_trigger.sql (465.29µs)8412026/10/01 09:52:15 OK 1_commit_pending_closure.sql (3.16ms)8422026/10/01 09:52:15 OK 3_commit_push.sql (396.67µs)8432026/10/01 09:52:15 goose: up to current file version: 38442026/10/01 09:52:15 OK 2_object_stats_trigger.sql (495.42µs)8452026/10/01 09:52:15 OK 3_commit_push.sql (393.88µs)8462026/10/01 09:52:15 goose: up to current file version: 38472026/10/01 09:52:15 OK 20260923120000_add_pushes.sql (8.86ms)8482026/10/01 09:52:15 goose: successfully migrated database to version: 202609231200008492026/10/01 09:52:15 OK 1_commit_pending_closure.sql (1.95ms)8502026/10/01 09:52:15 OK 2_object_stats_trigger.sql (507.63µs)8512026/10/01 09:52:15 OK 3_commit_push.sql (380.58µs)8522026/10/01 09:52:15 goose: up to current file version: 38532026/10/01 09:52:15 OK 20251218171726_add_pins.sql (18.85ms)8542026/10/01 09:52:15 OK 20260628120000_add_object_size_and_stats.sql (9.14ms)8552026/10/01 09:52:15 OK 20260905000000_add_claims.sql (25.95ms)8562026/10/01 09:52:15 OK 20260920000000_drop_claims.sql (17.84ms)8572026/10/01 09:52:15 OK 20260923120000_add_pushes.sql (12.17ms)8582026/10/01 09:52:15 goose: successfully migrated database to version: 202609231200008592026/10/01 09:52:15 OK 1_commit_pending_closure.sql (1.34ms)8602026/10/01 09:52:15 OK 2_object_stats_trigger.sql (286.67µs)8612026/10/01 09:52:15 OK 3_commit_push.sql (211.42µs)8622026/10/01 09:52:15 goose: up to current file version: 3863--- PASS: TestService_Rustfstest (0.50s)864=== CONT TestRedundantMultipartUpload8652026/10/01 09:52:15 INFO Received uploads request method=POST path=/api/pending_closures8662026/10/01 09:52:15 INFO Received uploads request method=POST path=/api/pending_closures8672026/10/01 09:52:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete868--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.06s)869=== CONT TestPush_SignsNarinfosOfItsPendingObjects8702026-10-01 09:52:16.198 UTC [90923] ERROR: relation "goose_db_version" does not exist at character 368712026-10-01 09:52:16.198 UTC [90923] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8722026/10/01 09:52:16 INFO Received uploads request method=POST path=/api/pending_closures8732026/10/01 09:52:16 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst8742026/10/01 09:52:16 INFO Received uploads request method=POST path=/api/pending_closures875--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.18s)876=== CONT TestPush_RejectsBadRequests8772026/10/01 09:52:16 OK 20241026095416_initial_model.sql (63.71ms)8782026/10/01 09:52:16 OK 20251210153512_drop_unused_gin_index.sql (11.71ms)8792026/10/01 09:52:16 OK 20251218171726_add_pins.sql (16.41ms)8802026/10/01 09:52:16 OK 20260628120000_add_object_size_and_stats.sql (13.15ms)8812026/10/01 09:52:16 OK 20260905000000_add_claims.sql (7.78ms)8822026/10/01 09:52:16 OK 20260920000000_drop_claims.sql (21.22ms)8832026/10/01 09:52:16 OK 20260923120000_add_pushes.sql (22.83ms)8842026/10/01 09:52:16 goose: successfully migrated database to version: 202609231200008852026/10/01 09:52:16 OK 1_commit_pending_closure.sql (10.52ms)8862026/10/01 09:52:16 OK 2_object_stats_trigger.sql (6.49ms)8872026/10/01 09:52:16 OK 3_commit_push.sql (910.63µs)8882026/10/01 09:52:16 goose: up to current file version: 38892026-10-01 09:52:16.442 UTC [90929] ERROR: relation "goose_db_version" does not exist at character 368902026-10-01 09:52:16.442 UTC [90929] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8912026/10/01 09:52:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8922026/10/01 09:52:16 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst893--- PASS: TestCompleteMultipartUnregistered (1.36s)894=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit8952026/10/01 09:52:16 OK 20241026095416_initial_model.sql (56.29ms)8962026/10/01 09:52:16 OK 20251210153512_drop_unused_gin_index.sql (6.79ms)8972026/10/01 09:52:16 OK 20251218171726_add_pins.sql (2.35ms)8982026/10/01 09:52:16 OK 20260628120000_add_object_size_and_stats.sql (17.85ms)8992026/10/01 09:52:16 OK 20260905000000_add_claims.sql (22.49ms)9002026-10-01 09:52:16.579 UTC [90932] ERROR: relation "goose_db_version" does not exist at character 369012026-10-01 09:52:16.579 UTC [90932] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9022026/10/01 09:52:16 OK 20260920000000_drop_claims.sql (12.33ms)9032026/10/01 09:52:16 OK 20260923120000_add_pushes.sql (6.51ms)9042026/10/01 09:52:16 goose: successfully migrated database to version: 202609231200009052026/10/01 09:52:16 OK 1_commit_pending_closure.sql (1.33ms)9062026/10/01 09:52:16 OK 2_object_stats_trigger.sql (335.46µs)9072026/10/01 09:52:16 OK 3_commit_push.sql (261.67µs)9082026/10/01 09:52:16 goose: up to current file version: 39092026/10/01 09:52:16 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"910--- PASS: TestService_AuthMiddleware (1.53s)911=== CONT TestPush_CompleteCommitsEveryRoot9122026/10/01 09:52:16 OK 20241026095416_initial_model.sql (80.67ms)9132026/10/01 09:52:16 OK 20251210153512_drop_unused_gin_index.sql (6.73ms)9142026/10/01 09:52:16 OK 20251218171726_add_pins.sql (6.27ms)9152026/10/01 09:52:16 OK 20260628120000_add_object_size_and_stats.sql (14.21ms)9162026/10/01 09:52:16 OK 20260905000000_add_claims.sql (19.87ms)9172026/10/01 09:52:16 OK 20260920000000_drop_claims.sql (14.41ms)9182026/10/01 09:52:16 OK 20260923120000_add_pushes.sql (35.07ms)9192026/10/01 09:52:16 goose: successfully migrated database to version: 202609231200009202026/10/01 09:52:16 OK 1_commit_pending_closure.sql (1.52ms)9212026/10/01 09:52:16 OK 2_object_stats_trigger.sql (367.21µs)9222026/10/01 09:52:16 OK 3_commit_push.sql (241.25µs)9232026/10/01 09:52:16 goose: up to current file version: 39242026/10/01 09:52:16 INFO Received uploads request method=POST path=/api/pending_closures9252026-10-01 09:52:16.915 UTC [90938] ERROR: relation "goose_db_version" does not exist at character 369262026-10-01 09:52:16.915 UTC [90938] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9272026/10/01 09:52:17 INFO Received uploads request method=POST path=/api/pending_closures9282026/10/01 09:52:17 INFO Received uploads request method=POST path=/api/pending_closures9292026/10/01 09:52:17 INFO Received uploads request method=POST path=/api/pending_closures9302026/10/01 09:52:17 OK 20241026095416_initial_model.sql (94.03ms)9312026/10/01 09:52:17 OK 20251210153512_drop_unused_gin_index.sql (8.86ms)9322026/10/01 09:52:17 OK 20251218171726_add_pins.sql (24.24ms)9332026/10/01 09:52:17 OK 20260628120000_add_object_size_and_stats.sql (19.72ms)9342026/10/01 09:52:17 OK 20260905000000_add_claims.sql (36.09ms)9352026/10/01 09:52:17 OK 20260920000000_drop_claims.sql (31.67ms)9362026/10/01 09:52:17 OK 20260923120000_add_pushes.sql (20.6ms)9372026/10/01 09:52:17 goose: successfully migrated database to version: 202609231200009382026/10/01 09:52:17 OK 1_commit_pending_closure.sql (1.08ms)9392026/10/01 09:52:17 OK 2_object_stats_trigger.sql (323.29µs)9402026/10/01 09:52:17 OK 3_commit_push.sql (245.21µs)9412026/10/01 09:52:17 goose: up to current file version: 39422026/10/01 09:52:17 INFO Received uploads request method=POST path=/api/pending_closures9432026/10/01 09:52:17 INFO Received uploads request method=POST path=/api/pending_closures9442026/10/01 09:52:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9452026/10/01 09:52:17 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZmM0OGM4ZDUtNjZmYS00MjY2LWEyNGYtZmU0MDM3OTRmOWE2LjdhM2FhMDZiLTQzZmMtNGRkYy05ZGFmLTBmZWYzNDViNTk5OHgxNzkwODQ4MzM3NjI2NzkwMDAw9462026/10/01 09:52:17 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZmM0OGM4ZDUtNjZmYS00MjY2LWEyNGYtZmU0MDM3OTRmOWE2LjdhM2FhMDZiLTQzZmMtNGRkYy05ZGFmLTBmZWYzNDViNTk5OHgxNzkwODQ4MzM3NjI2NzkwMDAw parts=1947--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.72s)948=== CONT TestPush_OverlappingRootsStoreOneRowPerKey9492026/10/01 09:52:17 INFO Received uploads request method=POST path=/api/pending_closures9502026/10/01 09:52:18 INFO Received uploads request method=POST path=/api/pending_closures9512026/10/01 09:52:18 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9522026/10/01 09:52:18 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZmM0OGM4ZDUtNjZmYS00MjY2LWEyNGYtZmU0MDM3OTRmOWE2LmNjMmZjZmRhLTU2YmYtNDEyMS05YmQ2LTBmMGY4ODgwYTg4ZHgxNzkwODQ4MzM2ODM0NTEyMDAw parts=109532026/10/01 09:52:18 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9542026/10/01 09:52:18 INFO Received push request method=POST path=/api/pushes9552026/10/01 09:52:18 INFO Completed upload id=19562026/10/01 09:52:18 INFO Received uploads request method=POST path=/api/pending_closures9572026/10/01 09:52:18 INFO Received uploads request method=POST path=/api/pending_closures9582026/10/01 09:52:18 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9592026/10/01 09:52:18 WARN Found objects in DB but missing from S3, will re-upload count=1960--- PASS: TestService_verifyS3Integrity (3.28s)961=== CONT TestReadRedirectUsesPublicS3URL9622026/10/01 09:52:18 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9632026/10/01 09:52:18 INFO Signed narinfos id=1 count=1964--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (2.33s)965=== CONT TestReadProxyRangeRequest9662026/10/01 09:52:18 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9672026-10-01 09:52:18.623 UTC [90991] ERROR: relation "goose_db_version" does not exist at character 369682026-10-01 09:52:18.623 UTC [90991] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9692026/10/01 09:52:18 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZmM0OGM4ZDUtNjZmYS00MjY2LWEyNGYtZmU0MDM3OTRmOWE2LmM3MzdkNmFiLTM5ZDAtNDg1Yi05Njk2LTdjZjRlZDdmMGFiYXgxNzkwODQ4MzM3MDQxMzYxMDAw parts=109702026/10/01 09:52:18 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9712026/10/01 09:52:18 INFO Completed upload id=19722026/10/01 09:52:18 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009732026/10/01 09:52:18 INFO Received uploads request method=POST path=/api/pending_closures9742026/10/01 09:52:18 INFO Starting cleanup of old closures method=DELETE path=/api/closures9752026/10/01 09:52:18 INFO Aborted multipart uploads count=0 kept=09762026/10/01 09:52:18 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=09772026/10/01 09:52:18 INFO Vacuumed table table=pending_closures978=== RUN TestPush_RejectsBadRequests/no_roots979=== PAUSE TestPush_RejectsBadRequests/no_roots980=== RUN TestPush_RejectsBadRequests/no_objects981=== PAUSE TestPush_RejectsBadRequests/no_objects982=== RUN TestPush_RejectsBadRequests/bad_root983=== PAUSE TestPush_RejectsBadRequests/bad_root984=== RUN TestPush_RejectsBadRequests/root_not_in_objects985=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects986=== CONT TestReadRedirectKeepsNarinfoProxied9872026/10/01 09:52:18 INFO Vacuumed table table=pending_objects9882026/10/01 09:52:18 INFO Vacuumed table table=multipart_uploads9892026/10/01 09:52:18 INFO Vacuumed table table=closures9902026/10/01 09:52:18 INFO Vacuumed table table=objects9912026/10/01 09:52:18 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000992--- PASS: TestService_createPendingClosureHandler (3.76s)993=== CONT TestReadRedirectNar9942026/10/01 09:52:18 OK 20241026095416_initial_model.sql (243.04ms)9952026/10/01 09:52:18 OK 20251210153512_drop_unused_gin_index.sql (11.15ms)9962026/10/01 09:52:19 OK 20251218171726_add_pins.sql (51.68ms)9972026/10/01 09:52:19 OK 20260628120000_add_object_size_and_stats.sql (47.35ms)9982026/10/01 09:52:19 INFO Received push request method=POST path=/api/pushes9992026/10/01 09:52:19 OK 20260905000000_add_claims.sql (28.75ms)10002026/10/01 09:52:19 OK 20260920000000_drop_claims.sql (64.2ms)10012026/10/01 09:52:19 OK 20260923120000_add_pushes.sql (25.35ms)10022026/10/01 09:52:19 goose: successfully migrated database to version: 2026092312000010032026/10/01 09:52:19 OK 1_commit_pending_closure.sql (1.34ms)10042026/10/01 09:52:19 OK 2_object_stats_trigger.sql (304µs)10052026/10/01 09:52:19 OK 3_commit_push.sql (240.88µs)10062026/10/01 09:52:19 goose: up to current file version: 310072026/10/01 09:52:19 INFO Received complete push request method=POST path=/api/pushes/1/complete10082026/10/01 09:52:19 INFO Received push request method=POST path=/api/pushes10092026/10/01 09:52:19 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10102026/10/01 09:52:19 INFO Aborted multipart uploads count=0 kept=010112026/10/01 09:52:19 WARN Force mode enabled - objects will be deleted immediately without grace period10122026/10/01 09:52:19 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=2 objects-failed-to-delete=010132026/10/01 09:52:19 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZmM0OGM4ZDUtNjZmYS00MjY2LWEyNGYtZmU0MDM3OTRmOWE2LjNkYjQwNmZmLTk1NjktNGFmNy05ODY5LTgyN2VlODM5MjRiZngxNzkwODQ4MzM3MzIxMjY0MDAw parts=1210142026/10/01 09:52:19 INFO Received uploads request method=POST path=/api/pending_closures1015--- PASS: TestCompletedNarNotReofferedAcrossClosures (4.24s)1016=== CONT TestReadProxyDisabled10172026/10/01 09:52:19 INFO Vacuumed table table=pending_closures10182026/10/01 09:52:19 INFO Vacuumed table table=pending_objects10192026/10/01 09:52:19 INFO Vacuumed table table=multipart_uploads10202026/10/01 09:52:19 INFO Vacuumed table table=closures10212026/10/01 09:52:19 INFO Vacuumed table table=objects10222026/10/01 09:52:19 INFO Received complete push request method=POST path=/api/pushes/2/complete1023--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (3.00s)1024=== CONT TestReadProxyRootRedirectsToIndexHTML10252026/10/01 09:52:19 INFO Received push request method=POST path=/api/pushes10262026/10/01 09:52:19 INFO Received complete push request method=POST path=/api/pushes/1/complete1027--- PASS: TestPush_CompleteCommitsEveryRoot (3.02s)1028=== CONT TestReadProxyConditionalGet10292026-10-01 09:52:19.810 UTC [91015] ERROR: relation "goose_db_version" does not exist at character 3610302026-10-01 09:52:19.810 UTC [91015] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10312026/10/01 09:52:19 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10322026/10/01 09:52:19 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZmM0OGM4ZDUtNjZmYS00MjY2LWEyNGYtZmU0MDM3OTRmOWE2LmE2Nzg1MWNlLWUxMDUtNDdlYy1hNmRhLTEyMzU4YzA0NWVlZngxNzkwODQ4MzM3OTg0NDM2MDAw parts=1210332026/10/01 09:52:19 INFO Received uploads request method=POST path=/api/pending_closures10342026/10/01 09:52:20 INFO Received uploads request method=POST path=/api/pending_closures10352026/10/01 09:52:20 OK 20241026095416_initial_model.sql (154.54ms)10362026/10/01 09:52:20 OK 20251210153512_drop_unused_gin_index.sql (12.02ms)10372026/10/01 09:52:20 OK 20251218171726_add_pins.sql (23.62ms)10382026/10/01 09:52:20 OK 20260628120000_add_object_size_and_stats.sql (34.33ms)10392026/10/01 09:52:20 WARN Rate limiter enabled after throttle name=s3-test rate=510402026/10/01 09:52:20 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1041=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1042 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101043 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001044--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.07s)1045=== CONT TestReadProxyHead10462026/10/01 09:52:20 OK 20260905000000_add_claims.sql (83.52ms)10472026/10/01 09:52:20 OK 20260920000000_drop_claims.sql (26.21ms)10482026/10/01 09:52:20 OK 20260923120000_add_pushes.sql (19.66ms)10492026/10/01 09:52:20 goose: successfully migrated database to version: 2026092312000010502026/10/01 09:52:20 OK 1_commit_pending_closure.sql (1.42ms)10512026/10/01 09:52:20 OK 2_object_stats_trigger.sql (233.58µs)10522026/10/01 09:52:20 OK 3_commit_push.sql (172.33µs)10532026/10/01 09:52:20 goose: up to current file version: 310542026/10/01 09:52:20 INFO Received push request method=POST path=/api/pushes1055--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (2.90s)1056=== CONT TestReadProxyInvalidPath10572026-10-01 09:52:20.791 UTC [91088] ERROR: relation "goose_db_version" does not exist at character 3610582026-10-01 09:52:20.791 UTC [91088] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10592026-10-01 09:52:20.802 UTC [91091] ERROR: relation "goose_db_version" does not exist at character 3610602026-10-01 09:52:20.802 UTC [91091] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10612026-10-01 09:52:20.809 UTC [91092] ERROR: relation "goose_db_version" does not exist at character 3610622026-10-01 09:52:20.809 UTC [91092] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10632026-10-01 09:52:20.810 UTC [91094] ERROR: relation "goose_db_version" does not exist at character 3610642026-10-01 09:52:20.810 UTC [91094] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10652026/10/01 09:52:20 OK 20241026095416_initial_model.sql (33.98ms)10662026/10/01 09:52:20 OK 20241026095416_initial_model.sql (33.13ms)10672026/10/01 09:52:20 OK 20241026095416_initial_model.sql (31.29ms)10682026/10/01 09:52:20 OK 20251210153512_drop_unused_gin_index.sql (2.47ms)10692026/10/01 09:52:20 OK 20251210153512_drop_unused_gin_index.sql (2.65ms)10702026/10/01 09:52:20 OK 20251210153512_drop_unused_gin_index.sql (2.6ms)10712026/10/01 09:52:20 OK 20241026095416_initial_model.sql (21.97ms)10722026/10/01 09:52:20 OK 20251218171726_add_pins.sql (1.84ms)10732026/10/01 09:52:20 OK 20251218171726_add_pins.sql (2.27ms)10742026/10/01 09:52:20 OK 20251210153512_drop_unused_gin_index.sql (16.92ms)10752026/10/01 09:52:20 OK 20251218171726_add_pins.sql (26.27ms)10762026/10/01 09:52:20 OK 20260628120000_add_object_size_and_stats.sql (36.09ms)10772026/10/01 09:52:20 OK 20260628120000_add_object_size_and_stats.sql (35.72ms)10782026/10/01 09:52:20 OK 20260628120000_add_object_size_and_stats.sql (12.62ms)10792026/10/01 09:52:20 OK 20251218171726_add_pins.sql (27.92ms)10802026/10/01 09:52:20 OK 20260905000000_add_claims.sql (18.6ms)10812026/10/01 09:52:20 OK 20260905000000_add_claims.sql (28.02ms)10822026/10/01 09:52:20 OK 20260628120000_add_object_size_and_stats.sql (21.34ms)10832026/10/01 09:52:20 OK 20260920000000_drop_claims.sql (12.23ms)10842026/10/01 09:52:20 OK 20260905000000_add_claims.sql (29.95ms)10852026/10/01 09:52:20 OK 20260920000000_drop_claims.sql (4.64ms)10862026/10/01 09:52:20 OK 20260905000000_add_claims.sql (6.27ms)10872026/10/01 09:52:20 OK 20260920000000_drop_claims.sql (5.08ms)10882026/10/01 09:52:20 OK 20260923120000_add_pushes.sql (5.5ms)10892026/10/01 09:52:20 goose: successfully migrated database to version: 2026092312000010902026/10/01 09:52:20 OK 20260923120000_add_pushes.sql (4.13ms)10912026/10/01 09:52:20 goose: successfully migrated database to version: 2026092312000010922026/10/01 09:52:20 OK 20260920000000_drop_claims.sql (3.31ms)10932026/10/01 09:52:20 OK 1_commit_pending_closure.sql (3.96ms)10942026/10/01 09:52:20 OK 1_commit_pending_closure.sql (3.83ms)10952026/10/01 09:52:20 OK 20260923120000_add_pushes.sql (5.11ms)10962026/10/01 09:52:20 goose: successfully migrated database to version: 2026092312000010972026/10/01 09:52:20 OK 2_object_stats_trigger.sql (1.49ms)10982026/10/01 09:52:20 OK 2_object_stats_trigger.sql (1.22ms)10992026/10/01 09:52:20 OK 20260923120000_add_pushes.sql (2.78ms)11002026/10/01 09:52:20 goose: successfully migrated database to version: 2026092312000011012026/10/01 09:52:20 OK 3_commit_push.sql (1.03ms)11022026/10/01 09:52:20 goose: up to current file version: 311032026/10/01 09:52:20 OK 3_commit_push.sql (1.32ms)11042026/10/01 09:52:20 goose: up to current file version: 311052026/10/01 09:52:20 OK 1_commit_pending_closure.sql (2.85ms)11062026/10/01 09:52:20 OK 1_commit_pending_closure.sql (3.08ms)11072026/10/01 09:52:20 OK 2_object_stats_trigger.sql (1.83ms)11082026/10/01 09:52:20 OK 2_object_stats_trigger.sql (1.2ms)11092026/10/01 09:52:20 OK 3_commit_push.sql (1.3ms)11102026/10/01 09:52:20 goose: up to current file version: 311112026/10/01 09:52:20 OK 3_commit_push.sql (1.68ms)11122026/10/01 09:52:20 goose: up to current file version: 311132026-10-01 09:52:21.080 UTC [91099] ERROR: relation "goose_db_version" does not exist at character 3611142026-10-01 09:52:21.080 UTC [91099] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1115--- PASS: TestReadProxyRangeRequest (2.81s)1116=== CONT TestReadProxy40411172026/10/01 09:52:21 OK 20241026095416_initial_model.sql (187.38ms)11182026/10/01 09:52:21 OK 20251210153512_drop_unused_gin_index.sql (18.34ms)11192026/10/01 09:52:21 OK 20251218171726_add_pins.sql (39.03ms)11202026/10/01 09:52:21 OK 20260628120000_add_object_size_and_stats.sql (66.88ms)11212026/10/01 09:52:21 OK 20260905000000_add_claims.sql (103.64ms)11222026/10/01 09:52:21 OK 20260920000000_drop_claims.sql (71ms)11232026/10/01 09:52:21 OK 20260923120000_add_pushes.sql (24.29ms)11242026/10/01 09:52:21 goose: successfully migrated database to version: 2026092312000011252026/10/01 09:52:21 OK 1_commit_pending_closure.sql (1.17ms)11262026/10/01 09:52:21 OK 2_object_stats_trigger.sql (264.71µs)11272026/10/01 09:52:21 OK 3_commit_push.sql (230.71µs)11282026/10/01 09:52:21 goose: up to current file version: 311292026/10/01 09:52:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1130--- PASS: TestReadRedirectUsesPublicS3URL (3.32s)1131=== CONT TestReadProxyNarStreaming11322026/10/01 09:52:21 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZmM0OGM4ZDUtNjZmYS00MjY2LWEyNGYtZmU0MDM3OTRmOWE2LmJjOTA0MmQ4LWZmNjUtNDQ2MS1hYjhmLTdkMDlhYzQ1NDAzNHgxNzkwODQ4MzQwMDI2MDE4MDAw error="Get \"http://127.0.0.1:1/bucket13/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"11332026/10/01 09:52:21 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZmM0OGM4ZDUtNjZmYS00MjY2LWEyNGYtZmU0MDM3OTRmOWE2LjNlOTExN2M4LTQxZDMtNGE1ZC04YjcxLWNhOWQ0YzBiOTEzN3gxNzkwODQ4MzM5OTg1MDA0MDAw parts=1211342026/10/01 09:52:21 INFO Received cleanup request method=DELETE path=/api/pending_closures11352026/10/01 09:52:21 INFO Aborted multipart uploads count=1 kept=01136--- PASS: TestRedundantMultipartUpload (6.32s)1137=== CONT TestReadProxyNarinfoAlreadyDecompressed11382026-10-01 09:52:22.014 UTC [91108] ERROR: relation "goose_db_version" does not exist at character 3611392026-10-01 09:52:22.014 UTC [91108] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1140--- PASS: TestReadRedirectKeepsNarinfoProxied (3.39s)1141=== CONT TestReadProxyNarinfo11422026/10/01 09:52:22 OK 20241026095416_initial_model.sql (240.42ms)11432026/10/01 09:52:22 OK 20251210153512_drop_unused_gin_index.sql (14.28ms)11442026/10/01 09:52:22 OK 20251218171726_add_pins.sql (23.51ms)11452026/10/01 09:52:22 OK 20260628120000_add_object_size_and_stats.sql (66.4ms)11462026-10-01 09:52:22.491 UTC [91113] ERROR: relation "goose_db_version" does not exist at character 3611472026-10-01 09:52:22.491 UTC [91113] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1148--- PASS: TestReadRedirectNar (3.66s)1149=== CONT TestIsValidCachePath1150=== RUN TestIsValidCachePath/narinfo1151=== PAUSE TestIsValidCachePath/narinfo1152=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1153=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1154=== RUN TestIsValidCachePath/nar_zst1155=== PAUSE TestIsValidCachePath/nar_zst1156=== RUN TestIsValidCachePath/nar_xz1157=== PAUSE TestIsValidCachePath/nar_xz1158=== RUN TestIsValidCachePath/nar_bz21159=== PAUSE TestIsValidCachePath/nar_bz21160=== RUN TestIsValidCachePath/nar_uncompressed1161=== PAUSE TestIsValidCachePath/nar_uncompressed1162=== RUN TestIsValidCachePath/ls1163=== PAUSE TestIsValidCachePath/ls1164=== RUN TestIsValidCachePath/log1165=== PAUSE TestIsValidCachePath/log1166=== RUN TestIsValidCachePath/realisation1167=== PAUSE TestIsValidCachePath/realisation1168=== RUN TestIsValidCachePath/nix-cache-info1169=== PAUSE TestIsValidCachePath/nix-cache-info1170=== RUN TestIsValidCachePath/index.html1171=== PAUSE TestIsValidCachePath/index.html1172=== RUN TestIsValidCachePath/traversal_parent1173=== PAUSE TestIsValidCachePath/traversal_parent1174=== RUN TestIsValidCachePath/traversal_in_middle1175=== PAUSE TestIsValidCachePath/traversal_in_middle1176=== RUN TestIsValidCachePath/invalid_char_e1177=== PAUSE TestIsValidCachePath/invalid_char_e1178=== RUN TestIsValidCachePath/invalid_char_u1179=== PAUSE TestIsValidCachePath/invalid_char_u1180=== RUN TestIsValidCachePath/random_path1181=== PAUSE TestIsValidCachePath/random_path1182=== RUN TestIsValidCachePath/empty1183=== PAUSE TestIsValidCachePath/empty1184=== RUN TestIsValidCachePath/leading_slash1185=== PAUSE TestIsValidCachePath/leading_slash1186=== RUN TestIsValidCachePath/wrong_extension1187=== PAUSE TestIsValidCachePath/wrong_extension1188=== RUN TestIsValidCachePath/short_hash1189=== PAUSE TestIsValidCachePath/short_hash1190=== CONT TestProxyHeadersOnlyTrustedOnSocket11912026/10/01 09:52:22 OK 20260905000000_add_claims.sql (135.17ms)11922026/10/01 09:52:22 OK 20260920000000_drop_claims.sql (75.86ms)11932026/10/01 09:52:22 OK 20260923120000_add_pushes.sql (37.61ms)11942026/10/01 09:52:22 goose: successfully migrated database to version: 2026092312000011952026/10/01 09:52:22 OK 1_commit_pending_closure.sql (1.29ms)11962026/10/01 09:52:22 OK 2_object_stats_trigger.sql (319.58µs)11972026/10/01 09:52:22 OK 3_commit_push.sql (238.38µs)11982026/10/01 09:52:22 goose: up to current file version: 311992026/10/01 09:52:22 OK 20241026095416_initial_model.sql (263.65ms)1200--- PASS: TestReadProxyDisabled (3.52s)1201=== CONT TestParseSingleRange1202=== RUN TestParseSingleRange/none1203=== PAUSE TestParseSingleRange/none1204=== RUN TestParseSingleRange/unknown_unit1205=== PAUSE TestParseSingleRange/unknown_unit1206=== RUN TestParseSingleRange/multi-range_ignored1207=== PAUSE TestParseSingleRange/multi-range_ignored1208=== RUN TestParseSingleRange/malformed_no_dash1209=== PAUSE TestParseSingleRange/malformed_no_dash1210=== RUN TestParseSingleRange/malformed_both_empty1211=== PAUSE TestParseSingleRange/malformed_both_empty1212=== RUN TestParseSingleRange/malformed_end_before_start1213=== PAUSE TestParseSingleRange/malformed_end_before_start1214=== RUN TestParseSingleRange/closed1215=== PAUSE TestParseSingleRange/closed1216=== RUN TestParseSingleRange/open-ended1217=== PAUSE TestParseSingleRange/open-ended1218=== RUN TestParseSingleRange/end_clamped_to_size1219=== PAUSE TestParseSingleRange/end_clamped_to_size1220=== RUN TestParseSingleRange/suffix1221=== PAUSE TestParseSingleRange/suffix1222=== RUN TestParseSingleRange/suffix_exceeds_size1223=== PAUSE TestParseSingleRange/suffix_exceeds_size1224=== RUN TestParseSingleRange/single_byte1225=== PAUSE TestParseSingleRange/single_byte1226=== RUN TestParseSingleRange/start_past_EOF1227=== PAUSE TestParseSingleRange/start_past_EOF1228=== RUN TestParseSingleRange/start_far_past_EOF1229=== PAUSE TestParseSingleRange/start_far_past_EOF1230=== CONT TestPresentNotReportedWhileGCDeletesClosure12312026/10/01 09:52:22 OK 20251210153512_drop_unused_gin_index.sql (7.28ms)12322026-10-01 09:52:22.932 UTC [91117] ERROR: relation "goose_db_version" does not exist at character 3612332026-10-01 09:52:22.932 UTC [91117] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12342026/10/01 09:52:22 OK 20251218171726_add_pins.sql (64.5ms)12352026/10/01 09:52:23 OK 20260628120000_add_object_size_and_stats.sql (72.56ms)12362026/10/01 09:52:23 OK 20260905000000_add_claims.sql (30.62ms)12372026/10/01 09:52:23 OK 20260920000000_drop_claims.sql (56.9ms)12382026/10/01 09:52:23 OK 20260923120000_add_pushes.sql (30.33ms)12392026/10/01 09:52:23 goose: successfully migrated database to version: 2026092312000012402026/10/01 09:52:23 OK 1_commit_pending_closure.sql (1.04ms)12412026/10/01 09:52:23 OK 2_object_stats_trigger.sql (262.08µs)12422026/10/01 09:52:23 OK 3_commit_push.sql (186.17µs)12432026/10/01 09:52:23 goose: up to current file version: 312442026/10/01 09:52:23 OK 20241026095416_initial_model.sql (292.8ms)1245--- PASS: TestReadProxyRootRedirectsToIndexHTML (3.85s)1246=== CONT TestPresentReportsOnlyClosureRoots12472026/10/01 09:52:23 OK 20251210153512_drop_unused_gin_index.sql (11.22ms)12482026/10/01 09:52:23 OK 20251218171726_add_pins.sql (57.07ms)12492026/10/01 09:52:23 OK 20260628120000_add_object_size_and_stats.sql (129.15ms)12502026/10/01 09:52:23 OK 20260905000000_add_claims.sql (89.6ms)12512026-10-01 09:52:23.622 UTC [91163] ERROR: relation "goose_db_version" does not exist at character 3612522026-10-01 09:52:23.622 UTC [91163] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12532026/10/01 09:52:23 OK 20260920000000_drop_claims.sql (94.88ms)12542026/10/01 09:52:23 OK 20260923120000_add_pushes.sql (31.27ms)12552026/10/01 09:52:23 goose: successfully migrated database to version: 2026092312000012562026/10/01 09:52:23 OK 1_commit_pending_closure.sql (851.75µs)12572026/10/01 09:52:23 OK 2_object_stats_trigger.sql (214.46µs)12582026/10/01 09:52:23 OK 3_commit_push.sql (182.33µs)12592026/10/01 09:52:23 goose: up to current file version: 31260--- PASS: TestReadProxyConditionalGet (4.13s)1261=== CONT TestCreatePin_ReservedPins12622026/10/01 09:52:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55213/oidc12632026/10/01 09:52:24 OK 20241026095416_initial_model.sql (424.6ms)12642026/10/01 09:52:24 OK 20251210153512_drop_unused_gin_index.sql (28.85ms)12652026/10/01 09:52:24 OK 20251218171726_add_pins.sql (60.34ms)1266--- PASS: TestReadProxyHead (4.12s)1267=== CONT TestOrphanedObjectsGCStressTest12682026/10/01 09:52:24 OK 20260628120000_add_object_size_and_stats.sql (62.3ms)12692026/10/01 09:52:24 OK 20260905000000_add_claims.sql (111.79ms)12702026/10/01 09:52:24 OK 20260920000000_drop_claims.sql (107.05ms)12712026/10/01 09:52:24 OK 20260923120000_add_pushes.sql (40.28ms)12722026/10/01 09:52:24 goose: successfully migrated database to version: 2026092312000012732026/10/01 09:52:24 OK 1_commit_pending_closure.sql (4.16ms)12742026/10/01 09:52:24 OK 2_object_stats_trigger.sql (658.96µs)12752026/10/01 09:52:24 OK 3_commit_push.sql (422.83µs)12762026/10/01 09:52:24 goose: up to current file version: 31277--- PASS: TestReadProxyInvalidPath (4.36s)1278=== CONT TestOrphanedObjectsGC12792026-10-01 09:52:25.226 UTC [91211] ERROR: relation "goose_db_version" does not exist at character 3612802026-10-01 09:52:25.226 UTC [91211] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12812026-10-01 09:52:25.363 UTC [91212] ERROR: relation "goose_db_version" does not exist at character 3612822026-10-01 09:52:25.363 UTC [91212] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12832026-10-01 09:52:25.423 UTC [91215] ERROR: relation "goose_db_version" does not exist at character 3612842026-10-01 09:52:25.423 UTC [91215] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12852026/10/01 09:52:25 OK 20241026095416_initial_model.sql (173.47ms)12862026/10/01 09:52:25 OK 20251210153512_drop_unused_gin_index.sql (10.21ms)12872026/10/01 09:52:25 OK 20251218171726_add_pins.sql (31.33ms)12882026/10/01 09:52:25 OK 20260628120000_add_object_size_and_stats.sql (31.8ms)12892026/10/01 09:52:25 OK 20241026095416_initial_model.sql (156.57ms)12902026/10/01 09:52:25 OK 20251210153512_drop_unused_gin_index.sql (2.46ms)12912026/10/01 09:52:25 OK 20260905000000_add_claims.sql (71.86ms)12922026-10-01 09:52:25.634 UTC [91216] ERROR: relation "goose_db_version" does not exist at character 3612932026-10-01 09:52:25.634 UTC [91216] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12942026/10/01 09:52:25 OK 20251218171726_add_pins.sql (52.1ms)12952026/10/01 09:52:25 OK 20260920000000_drop_claims.sql (49.91ms)12962026/10/01 09:52:25 OK 20260628120000_add_object_size_and_stats.sql (54.16ms)12972026/10/01 09:52:25 OK 20260923120000_add_pushes.sql (25.59ms)12982026/10/01 09:52:25 goose: successfully migrated database to version: 2026092312000012992026/10/01 09:52:25 OK 20241026095416_initial_model.sql (210.09ms)13002026/10/01 09:52:25 OK 1_commit_pending_closure.sql (1.71ms)13012026/10/01 09:52:25 OK 2_object_stats_trigger.sql (354.54µs)13022026/10/01 09:52:25 OK 3_commit_push.sql (275.21µs)13032026/10/01 09:52:25 goose: up to current file version: 313042026/10/01 09:52:25 OK 20251210153512_drop_unused_gin_index.sql (18.75ms)13052026/10/01 09:52:25 OK 20251218171726_add_pins.sql (34.95ms)13062026/10/01 09:52:25 OK 20260905000000_add_claims.sql (90.4ms)13072026/10/01 09:52:25 OK 20260628120000_add_object_size_and_stats.sql (52.82ms)13082026/10/01 09:52:25 OK 20260920000000_drop_claims.sql (83.58ms)13092026/10/01 09:52:25 OK 20260905000000_add_claims.sql (71.95ms)13102026/10/01 09:52:25 OK 20260923120000_add_pushes.sql (23.3ms)13112026/10/01 09:52:25 goose: successfully migrated database to version: 2026092312000013122026/10/01 09:52:25 OK 1_commit_pending_closure.sql (2.54ms)13132026/10/01 09:52:25 OK 2_object_stats_trigger.sql (519.38µs)13142026/10/01 09:52:25 OK 3_commit_push.sql (308.42µs)13152026/10/01 09:52:25 goose: up to current file version: 313162026/10/01 09:52:25 OK 20260920000000_drop_claims.sql (50.03ms)13172026/10/01 09:52:25 OK 20260923120000_add_pushes.sql (33.18ms)13182026/10/01 09:52:25 goose: successfully migrated database to version: 2026092312000013192026/10/01 09:52:25 OK 1_commit_pending_closure.sql (3.09ms)13202026/10/01 09:52:25 OK 2_object_stats_trigger.sql (587.83µs)13212026/10/01 09:52:25 OK 3_commit_push.sql (345.38µs)13222026/10/01 09:52:25 goose: up to current file version: 313232026/10/01 09:52:25 OK 20241026095416_initial_model.sql (235.1ms)13242026/10/01 09:52:25 OK 20251210153512_drop_unused_gin_index.sql (5.82ms)13252026/10/01 09:52:26 OK 20251218171726_add_pins.sql (26.92ms)13262026-10-01 09:52:26.010 UTC [91219] ERROR: relation "goose_db_version" does not exist at character 3613272026-10-01 09:52:26.010 UTC [91219] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13282026/10/01 09:52:26 OK 20260628120000_add_object_size_and_stats.sql (62.57ms)1329--- PASS: TestReadProxy404 (4.78s)1330=== CONT TestObjectStatsTrigger13312026/10/01 09:52:26 OK 20260905000000_add_claims.sql (106.02ms)13322026/10/01 09:52:26 OK 20260920000000_drop_claims.sql (75.8ms)13332026/10/01 09:52:26 OK 20260923120000_add_pushes.sql (31.99ms)13342026/10/01 09:52:26 goose: successfully migrated database to version: 2026092312000013352026/10/01 09:52:26 OK 1_commit_pending_closure.sql (2.88ms)13362026/10/01 09:52:26 OK 2_object_stats_trigger.sql (408.71µs)13372026/10/01 09:52:26 OK 3_commit_push.sql (337.63µs)13382026/10/01 09:52:26 goose: up to current file version: 313392026/10/01 09:52:26 OK 20241026095416_initial_model.sql (327.76ms)13402026/10/01 09:52:26 OK 20251210153512_drop_unused_gin_index.sql (27.9ms)13412026/10/01 09:52:26 OK 20251218171726_add_pins.sql (50.04ms)13422026/10/01 09:52:26 OK 20260628120000_add_object_size_and_stats.sql (93.78ms)1343--- PASS: TestReadProxyNarinfoAlreadyDecompressed (4.70s)1344=== CONT TestPendingCleanupUsesOneCutoff13452026/10/01 09:52:26 OK 20260905000000_add_claims.sql (155.42ms)13462026/10/01 09:52:26 OK 20260920000000_drop_claims.sql (100.98ms)13472026/10/01 09:52:26 OK 20260923120000_add_pushes.sql (27.31ms)13482026/10/01 09:52:26 goose: successfully migrated database to version: 2026092312000013492026/10/01 09:52:26 OK 1_commit_pending_closure.sql (2.83ms)13502026/10/01 09:52:26 OK 2_object_stats_trigger.sql (658.29µs)13512026/10/01 09:52:26 OK 3_commit_push.sql (576.21µs)13522026/10/01 09:52:26 goose: up to current file version: 313532026-10-01 09:52:26.932 UTC [91227] ERROR: relation "goose_db_version" does not exist at character 3613542026-10-01 09:52:26.932 UTC [91227] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1355--- PASS: TestReadProxyNarStreaming (5.51s)1356=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded13572026/10/01 09:52:27 OK 20241026095416_initial_model.sql (415.94ms)13582026/10/01 09:52:27 OK 20251210153512_drop_unused_gin_index.sql (18.52ms)1359--- PASS: TestReadProxyNarinfo (5.59s)1360=== CONT TestMultipartCleanup13612026/10/01 09:52:27 OK 20251218171726_add_pins.sql (78.9ms)13622026-10-01 09:52:27.869 UTC [91236] ERROR: relation "goose_db_version" does not exist at character 3613632026-10-01 09:52:27.869 UTC [91236] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13642026/10/01 09:52:27 OK 20260628120000_add_object_size_and_stats.sql (72.76ms)13652026/10/01 09:52:28 OK 20260905000000_add_claims.sql (122.53ms)13662026/10/01 09:52:28 OK 20260920000000_drop_claims.sql (78.02ms)13672026/10/01 09:52:28 OK 20260923120000_add_pushes.sql (28.35ms)13682026/10/01 09:52:28 goose: successfully migrated database to version: 2026092312000013692026/10/01 09:52:28 OK 1_commit_pending_closure.sql (2.89ms)13702026/10/01 09:52:28 OK 2_object_stats_trigger.sql (474µs)13712026/10/01 09:52:28 OK 3_commit_push.sql (382.79µs)13722026/10/01 09:52:28 goose: up to current file version: 313732026/10/01 09:52:28 INFO Starting HTTP server address=/nix/var/nix/builds/nix-90547-3700828917/TestProxyHeadersOnlyTrustedOnSocket3199645437/001/proxy.sock13742026/10/01 09:52:28 INFO Starting HTTP server address=127.0.0.1:5527513752026/10/01 09:52:28 WARN mTLS auth: subject not in bound subjects subject="CN=someone"13762026/10/01 09:52:28 INFO Shutdown signal received, draining in-flight requests timeout=10s1377--- PASS: TestProxyHeadersOnlyTrustedOnSocket (5.75s)1378=== CONT TestServerTLSConfig1379=== RUN TestServerTLSConfig/no_client_CA1380=== PAUSE TestServerTLSConfig/no_client_CA1381=== RUN TestServerTLSConfig/missing_CA_file1382=== PAUSE TestServerTLSConfig/missing_CA_file1383=== RUN TestServerTLSConfig/not_a_PEM_file1384=== PAUSE TestServerTLSConfig/not_a_PEM_file1385=== CONT TestService_NativeMTLS13862026/10/01 09:52:28 OK 20241026095416_initial_model.sql (411.7ms)13872026/10/01 09:52:28 OK 20251210153512_drop_unused_gin_index.sql (17.84ms)13882026/10/01 09:52:28 OK 20251218171726_add_pins.sql (61.26ms)13892026-10-01 09:52:28.531 UTC [91240] ERROR: relation "goose_db_version" does not exist at character 3613902026-10-01 09:52:28.531 UTC [91240] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13912026/10/01 09:52:28 OK 20260628120000_add_object_size_and_stats.sql (67.74ms)13922026/10/01 09:52:28 OK 20260905000000_add_claims.sql (106.22ms)13932026/10/01 09:52:28 OK 20260920000000_drop_claims.sql (75.88ms)13942026/10/01 09:52:28 OK 20260923120000_add_pushes.sql (36.13ms)13952026/10/01 09:52:28 goose: successfully migrated database to version: 2026092312000013962026/10/01 09:52:28 OK 1_commit_pending_closure.sql (990.21µs)13972026/10/01 09:52:28 OK 2_object_stats_trigger.sql (224.29µs)13982026/10/01 09:52:28 OK 3_commit_push.sql (181.13µs)13992026/10/01 09:52:28 goose: up to current file version: 314002026-10-01 09:52:28.844 UTC [91247] ERROR: relation "goose_db_version" does not exist at character 3614012026-10-01 09:52:28.844 UTC [91247] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14022026/10/01 09:52:28 OK 20241026095416_initial_model.sql (293.29ms)14032026/10/01 09:52:28 OK 20251210153512_drop_unused_gin_index.sql (9ms)14042026/10/01 09:52:28 OK 20251218171726_add_pins.sql (51.97ms)14052026/10/01 09:52:29 OK 20260628120000_add_object_size_and_stats.sql (19.14ms)14062026/10/01 09:52:29 OK 20260905000000_add_claims.sql (87.37ms)14072026-10-01 09:52:29.130 UTC [91257] ERROR: relation "goose_db_version" does not exist at character 3614082026-10-01 09:52:29.130 UTC [91257] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14092026/10/01 09:52:29 OK 20260920000000_drop_claims.sql (66.54ms)14102026/10/01 09:52:29 OK 20241026095416_initial_model.sql (247.69ms)1411--- PASS: TestPresentReportsOnlyClosureRoots (5.84s)1412=== CONT TestMetricsInventory14132026/10/01 09:52:29 OK 20251210153512_drop_unused_gin_index.sql (23ms)14142026/10/01 09:52:29 OK 20260923120000_add_pushes.sql (27.51ms)14152026/10/01 09:52:29 goose: successfully migrated database to version: 2026092312000014162026/10/01 09:52:29 OK 1_commit_pending_closure.sql (7.35ms)14172026/10/01 09:52:29 OK 2_object_stats_trigger.sql (581.38µs)14182026/10/01 09:52:29 OK 3_commit_push.sql (240.42µs)14192026/10/01 09:52:29 goose: up to current file version: 314202026/10/01 09:52:29 OK 20251218171726_add_pins.sql (44.87ms)1421--- PASS: TestPresentNotReportedWhileGCDeletesClosure (6.36s)1422=== CONT TestNARDeduplicationMetadataUploadBug14232026/10/01 09:52:29 OK 20260628120000_add_object_size_and_stats.sql (55.05ms)14242026/10/01 09:52:29 OK 20260905000000_add_claims.sql (132.35ms)14252026/10/01 09:52:29 OK 20260920000000_drop_claims.sql (83.14ms)14262026/10/01 09:52:29 OK 20241026095416_initial_model.sql (259.87ms)14272026/10/01 09:52:29 OK 20251210153512_drop_unused_gin_index.sql (9.05ms)14282026/10/01 09:52:29 OK 20260923120000_add_pushes.sql (19.06ms)14292026/10/01 09:52:29 goose: successfully migrated database to version: 2026092312000014302026/10/01 09:52:29 OK 1_commit_pending_closure.sql (2.94ms)14312026/10/01 09:52:29 OK 2_object_stats_trigger.sql (239.21µs)14322026/10/01 09:52:29 OK 3_commit_push.sql (189.75µs)14332026/10/01 09:52:29 goose: up to current file version: 314342026/10/01 09:52:29 OK 20251218171726_add_pins.sql (55.33ms)14352026/10/01 09:52:29 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14362026/10/01 09:52:29 WARN Refused reserved pin name=worker-x86_64-linux14372026/10/01 09:52:29 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14382026/10/01 09:52:29 INFO Received create pin request method=POST path=/api/pins/my-app14392026/10/01 09:52:29 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1440--- PASS: TestCreatePin_ReservedPins (5.80s)1441=== CONT TestCreatePendingClosureRejectsOversizedNAR14422026/10/01 09:52:29 INFO Received uploads request method=POST path=/api/pending_closures1443--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1444=== CONT TestCacheConfigHandlerMaxNarSize1445--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1446=== CONT TestGenerateLandingPage1447--- PASS: TestGenerateLandingPage (0.00s)1448=== CONT TestService_readinessHandler14492026/10/01 09:52:29 OK 20260628120000_add_object_size_and_stats.sql (75.56ms)14502026/10/01 09:52:29 OK 20260905000000_add_claims.sql (89.02ms)14512026-10-01 09:52:29.747 UTC [91278] ERROR: relation "goose_db_version" does not exist at character 3614522026-10-01 09:52:29.747 UTC [91278] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14532026/10/01 09:52:29 OK 20260920000000_drop_claims.sql (20.54ms)14542026/10/01 09:52:29 OK 20260923120000_add_pushes.sql (17.88ms)14552026/10/01 09:52:29 goose: successfully migrated database to version: 2026092312000014562026/10/01 09:52:29 OK 1_commit_pending_closure.sql (1.28ms)14572026/10/01 09:52:29 OK 2_object_stats_trigger.sql (260.33µs)14582026/10/01 09:52:29 OK 3_commit_push.sql (209.83µs)14592026/10/01 09:52:29 goose: up to current file version: 314602026/10/01 09:52:30 OK 20241026095416_initial_model.sql (369.27ms)14612026/10/01 09:52:30 OK 20251210153512_drop_unused_gin_index.sql (26.31ms)14622026/10/01 09:52:30 OK 20251218171726_add_pins.sql (100.78ms)14632026/10/01 09:52:30 OK 20260628120000_add_object_size_and_stats.sql (11.85ms)14642026/10/01 09:52:30 OK 20260905000000_add_claims.sql (122.87ms)14652026/10/01 09:52:30 OK 20260920000000_drop_claims.sql (57.38ms)14662026/10/01 09:52:30 OK 20260923120000_add_pushes.sql (13.74ms)14672026/10/01 09:52:30 goose: successfully migrated database to version: 2026092312000014682026/10/01 09:52:30 OK 1_commit_pending_closure.sql (2.87ms)14692026/10/01 09:52:30 OK 2_object_stats_trigger.sql (705.08µs)14702026/10/01 09:52:30 OK 3_commit_push.sql (751.38µs)14712026/10/01 09:52:30 goose: up to current file version: 314722026-10-01 09:52:30.582 UTC [91285] ERROR: relation "goose_db_version" does not exist at character 3614732026-10-01 09:52:30.582 UTC [91285] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14742026-10-01 09:52:30.640 UTC [91290] ERROR: relation "goose_db_version" does not exist at character 3614752026-10-01 09:52:30.640 UTC [91290] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14762026-10-01 09:52:30.683 UTC [91292] ERROR: relation "goose_db_version" does not exist at character 3614772026-10-01 09:52:30.683 UTC [91292] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14782026/10/01 09:52:31 OK 20241026095416_initial_model.sql (302.93ms)14792026/10/01 09:52:31 OK 20251210153512_drop_unused_gin_index.sql (26.88ms)14802026/10/01 09:52:31 OK 20241026095416_initial_model.sql (303.95ms)14812026/10/01 09:52:31 OK 20251218171726_add_pins.sql (108.87ms)14822026/10/01 09:52:31 OK 20241026095416_initial_model.sql (338.13ms)14832026/10/01 09:52:31 OK 20251210153512_drop_unused_gin_index.sql (100.54ms)14842026/10/01 09:52:31 OK 20251210153512_drop_unused_gin_index.sql (27.43ms)14852026/10/01 09:52:31 OK 20251218171726_add_pins.sql (49.64ms)14862026/10/01 09:52:31 OK 20251218171726_add_pins.sql (34.55ms)14872026/10/01 09:52:31 OK 20260628120000_add_object_size_and_stats.sql (64.45ms)1488--- PASS: TestObjectStatsTrigger (5.13s)1489=== CONT TestService_healthCheckHandler14902026/10/01 09:52:31 OK 20260628120000_add_object_size_and_stats.sql (70.66ms)14912026/10/01 09:52:31 OK 20260628120000_add_object_size_and_stats.sql (63.11ms)14922026/10/01 09:52:31 OK 20260905000000_add_claims.sql (64.9ms)14932026/10/01 09:52:31 OK 20260905000000_add_claims.sql (95.11ms)14942026/10/01 09:52:31 OK 20260920000000_drop_claims.sql (88.99ms)14952026/10/01 09:52:31 OK 20260905000000_add_claims.sql (107.04ms)14962026/10/01 09:52:31 OK 20260923120000_add_pushes.sql (35.05ms)14972026/10/01 09:52:31 goose: successfully migrated database to version: 2026092312000014982026/10/01 09:52:31 OK 1_commit_pending_closure.sql (1.76ms)14992026/10/01 09:52:31 OK 2_object_stats_trigger.sql (409.46µs)15002026/10/01 09:52:31 OK 3_commit_push.sql (336.29µs)15012026/10/01 09:52:31 goose: up to current file version: 315022026/10/01 09:52:31 OK 20260920000000_drop_claims.sql (104.22ms)15032026/10/01 09:52:31 OK 20260920000000_drop_claims.sql (115.38ms)15042026/10/01 09:52:31 OK 20260923120000_add_pushes.sql (39.38ms)15052026/10/01 09:52:31 goose: successfully migrated database to version: 2026092312000015062026/10/01 09:52:31 OK 1_commit_pending_closure.sql (2.38ms)15072026/10/01 09:52:31 OK 2_object_stats_trigger.sql (500.54µs)15082026/10/01 09:52:31 OK 3_commit_push.sql (392.29µs)15092026/10/01 09:52:31 goose: up to current file version: 315102026/10/01 09:52:31 OK 20260923120000_add_pushes.sql (37.15ms)15112026/10/01 09:52:31 goose: successfully migrated database to version: 2026092312000015122026/10/01 09:52:31 OK 1_commit_pending_closure.sql (2.25ms)15132026/10/01 09:52:31 OK 2_object_stats_trigger.sql (522.21µs)15142026/10/01 09:52:31 OK 3_commit_push.sql (330.63µs)15152026/10/01 09:52:31 goose: up to current file version: 31516=== NAME TestOrphanedObjectsGC1517 orphaned_objects_gc_test.go:290: GC Test Summary:1518 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1519 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1520 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1521 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1522 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1523--- PASS: TestOrphanedObjectsGC (6.82s)1524=== CONT TestGracefulShutdownDrainsInflight15252026/10/01 09:52:31 INFO Starting HTTP server address=127.0.0.1:5531315262026/10/01 09:52:31 INFO Shutdown signal received, draining in-flight requests timeout=10s15272026/10/01 09:52:31 INFO Received uploads request method=POST path=/api/pending_closures1528--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1529=== CONT TestGCMetrics15302026/10/01 09:52:32 INFO Received uploads request method=POST path=/api/pending_closures15312026/10/01 09:52:32 INFO Received cleanup request method=DELETE path=/api/pending_closures15322026-10-01 09:52:32.341 UTC [91298] ERROR: relation "goose_db_version" does not exist at character 3615332026-10-01 09:52:32.341 UTC [91298] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15342026/10/01 09:52:32 INFO Received uploads request method=POST path=/api/pending_closures1535--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (5.64s)1536=== CONT TestGCTaskStore_PhaseUpdates1537--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1538=== CONT TestGCTaskStore_CompletedAllowsNewTask1539--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1540=== CONT TestGCTaskStore_GetReturnsLatest1541--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1542=== CONT TestGCTaskStore_GetEmpty1543--- PASS: TestGCTaskStore_GetEmpty (0.00s)1544=== CONT TestGCTaskStore_ConflictDifferentParams1545--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1546=== CONT TestGCTaskStore_DeduplicateSameParams1547--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1548=== CONT TestGCTaskStore_StartNew1549--- PASS: TestGCTaskStore_StartNew (0.00s)1550=== CONT TestGCEndsOnShutdown15512026/10/01 09:52:32 OK 20241026095416_initial_model.sql (456.71ms)15522026/10/01 09:52:32 OK 20251210153512_drop_unused_gin_index.sql (22.89ms)15532026/10/01 09:52:33 OK 20251218171726_add_pins.sql (77.04ms)15542026/10/01 09:52:33 OK 20260628120000_add_object_size_and_stats.sql (102.97ms)15552026/10/01 09:52:33 OK 20260905000000_add_claims.sql (231.79ms)15562026/10/01 09:52:33 OK 20260920000000_drop_claims.sql (37.31ms)15572026/10/01 09:52:33 INFO Received uploads request method=POST path=/api/pending_closures15582026/10/01 09:52:33 OK 20260923120000_add_pushes.sql (58.74ms)15592026/10/01 09:52:33 goose: successfully migrated database to version: 2026092312000015602026/10/01 09:52:33 OK 1_commit_pending_closure.sql (3.38ms)15612026/10/01 09:52:33 OK 2_object_stats_trigger.sql (737.58µs)15622026/10/01 09:52:33 OK 3_commit_push.sql (460.04µs)15632026/10/01 09:52:33 goose: up to current file version: 315642026/10/01 09:52:33 INFO Received cleanup request method=DELETE path=/api/pending_closures15652026/10/01 09:52:33 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket41/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""15662026/10/01 09:52:33 INFO Aborted multipart uploads count=0 kept=115672026/10/01 09:52:33 INFO Received cleanup request method=DELETE path=/api/pending_closures15682026/10/01 09:52:33 INFO Aborted multipart uploads count=1 kept=01569--- PASS: TestMultipartCleanup (6.05s)1570=== CONT TestCommitRacingPendingCleanupKeepsObjects15712026/10/01 09:52:34 WARN mTLS auth: subject not in bound subjects subject="CN=reader"15722026/10/01 09:52:34 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1573--- PASS: TestService_NativeMTLS (5.82s)1574=== CONT TestPushWaitsForSweepHoldingRow15752026-10-01 09:52:34.167 UTC [91315] ERROR: relation "goose_db_version" does not exist at character 3615762026-10-01 09:52:34.167 UTC [91315] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15772026-10-01 09:52:34.318 UTC [91320] ERROR: relation "goose_db_version" does not exist at character 3615782026-10-01 09:52:34.318 UTC [91320] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15792026-10-01 09:52:34.442 UTC [91322] ERROR: relation "goose_db_version" does not exist at character 3615802026-10-01 09:52:34.442 UTC [91322] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15812026/10/01 09:52:34 OK 20241026095416_initial_model.sql (261.97ms)15822026/10/01 09:52:34 OK 20251210153512_drop_unused_gin_index.sql (31.92ms)15832026/10/01 09:52:34 OK 20251218171726_add_pins.sql (46.63ms)15842026/10/01 09:52:34 OK 20260628120000_add_object_size_and_stats.sql (70.93ms)15852026/10/01 09:52:34 OK 20241026095416_initial_model.sql (296ms)15862026/10/01 09:52:34 OK 20251210153512_drop_unused_gin_index.sql (13.98ms)15872026/10/01 09:52:34 OK 20251218171726_add_pins.sql (82.22ms)15882026/10/01 09:52:34 OK 20260905000000_add_claims.sql (164.27ms)15892026/10/01 09:52:34 OK 20241026095416_initial_model.sql (313.33ms)15902026/10/01 09:52:34 OK 20251210153512_drop_unused_gin_index.sql (31.71ms)15912026/10/01 09:52:34 OK 20260628120000_add_object_size_and_stats.sql (92.22ms)15922026/10/01 09:52:34 OK 20260920000000_drop_claims.sql (106.47ms)15932026/10/01 09:52:34 OK 20251218171726_add_pins.sql (77.04ms)15942026/10/01 09:52:34 OK 20260923120000_add_pushes.sql (19.79ms)15952026/10/01 09:52:34 goose: successfully migrated database to version: 2026092312000015962026/10/01 09:52:34 OK 1_commit_pending_closure.sql (4.24ms)15972026/10/01 09:52:34 OK 2_object_stats_trigger.sql (666.13µs)15982026/10/01 09:52:34 OK 3_commit_push.sql (537.58µs)15992026/10/01 09:52:34 goose: up to current file version: 316002026/10/01 09:52:35 OK 20260628120000_add_object_size_and_stats.sql (71.41ms)16012026/10/01 09:52:35 OK 20260905000000_add_claims.sql (127.4ms)16022026/10/01 09:52:35 OK 20260920000000_drop_claims.sql (122.66ms)16032026/10/01 09:52:35 OK 20260905000000_add_claims.sql (154.56ms)16042026/10/01 09:52:35 OK 20260923120000_add_pushes.sql (35.38ms)16052026/10/01 09:52:35 goose: successfully migrated database to version: 2026092312000016062026/10/01 09:52:35 OK 1_commit_pending_closure.sql (4.91ms)16072026/10/01 09:52:35 OK 2_object_stats_trigger.sql (797µs)16082026/10/01 09:52:35 OK 3_commit_push.sql (474.17µs)16092026/10/01 09:52:35 goose: up to current file version: 316102026/10/01 09:52:35 OK 20260920000000_drop_claims.sql (77.64ms)16112026/10/01 09:52:35 OK 20260923120000_add_pushes.sql (28.86ms)16122026/10/01 09:52:35 goose: successfully migrated database to version: 2026092312000016132026/10/01 09:52:35 OK 1_commit_pending_closure.sql (3.84ms)16142026/10/01 09:52:35 OK 2_object_stats_trigger.sql (782.04µs)16152026/10/01 09:52:35 OK 3_commit_push.sql (341.08µs)16162026/10/01 09:52:35 goose: up to current file version: 31617--- PASS: TestMetricsInventory (7.05s)1618=== CONT TestSweepRechecksPendingAfterLocking1619=== NAME TestNARDeduplicationMetadataUploadBug1620 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-90547-3700828917/TestNARDeduplicationMetadataUploadBug3905560596/001/store/h23rwf201ip73xq6yrhr2c13lzrrja1j-file1.txt16212026/10/01 09:52:36 INFO Received push request method=POST path=/api/pushes16222026/10/01 09:52:36 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16232026/10/01 09:52:36 INFO Uploading h23rwf201ip73xq6yrhr2c13lzrrja1j-file1.txt (160B)16242026/10/01 09:52:36 WARN Failed to register uploaded object key=h23rwf201ip73xq6yrhr2c13lzrrja1j.ls error="server returned 404: 404 page not found\n"16252026/10/01 09:52:36 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"16262026/10/01 09:52:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16272026/10/01 09:52:36 INFO Signed narinfos id=1 count=116282026/10/01 09:52:36 INFO Uploading 1 narinfos16292026/10/01 09:52:36 INFO Received complete push request method=POST path=/api/pushes/1/complete16302026/10/01 09:52:36 WARN Failed to register uploaded object key=h23rwf201ip73xq6yrhr2c13lzrrja1j.narinfo error="server returned 404: 404 page not found\n"16312026/10/01 09:52:36 INFO Upload complete. (370ms)1632 metadata_upload_test.go:54: Retrieved narinfo from S3:1633 StorePath: /nix/var/nix/builds/nix-90547-3700828917/TestNARDeduplicationMetadataUploadBug3905560596/001/store/h23rwf201ip73xq6yrhr2c13lzrrja1j-file1.txt1634 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1635 Compression: zstd1636 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1637 NarSize: 1601638 References: 1639 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1640 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1641 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1642 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}16432026/10/01 09:52:36 WARN readiness check failed error="closed pool"1644--- PASS: TestService_readinessHandler (7.08s)1645=== CONT TestGetExistingObjectsLocksRows16462026-10-01 09:52:36.820 UTC [91338] ERROR: relation "goose_db_version" does not exist at character 3616472026-10-01 09:52:36.820 UTC [91338] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1648=== NAME TestNARDeduplicationMetadataUploadBug1649 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-90547-3700828917/TestNARDeduplicationMetadataUploadBug3905560596/001/store/a5q2h3grn5my8cw887q9zqjkdm16hm3a-file2.txt16502026/10/01 09:52:37 INFO Received push request method=POST path=/api/pushes16512026/10/01 09:52:37 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)16522026/10/01 09:52:37 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16532026/10/01 09:52:37 INFO Signed narinfos id=2 count=116542026/10/01 09:52:37 INFO Uploading 1 narinfos16552026/10/01 09:52:37 WARN Failed to register uploaded object key=a5q2h3grn5my8cw887q9zqjkdm16hm3a.ls error="server returned 404: 404 page not found\n"16562026/10/01 09:52:37 INFO Received complete push request method=POST path=/api/pushes/2/complete16572026/10/01 09:52:37 WARN Failed to register uploaded object key=a5q2h3grn5my8cw887q9zqjkdm16hm3a.narinfo error="server returned 404: 404 page not found\n"16582026/10/01 09:52:37 INFO Upload complete. (226ms)1659 metadata_upload_test.go:76: Retrieved narinfo from S3:1660 StorePath: /nix/var/nix/builds/nix-90547-3700828917/TestNARDeduplicationMetadataUploadBug3905560596/001/store/a5q2h3grn5my8cw887q9zqjkdm16hm3a-file2.txt1661 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1662 Compression: zstd1663 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1664 NarSize: 1601665 References: 1666 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1667 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1668 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1669 {"version":1,"root":{"type":"regular","size":44}}1670--- PASS: TestNARDeduplicationMetadataUploadBug (8.23s)1671=== CONT TestRegisterCompletedObjectNeedsPendingRow16722026/10/01 09:52:37 OK 20241026095416_initial_model.sql (524.74ms)16732026/10/01 09:52:37 OK 20251210153512_drop_unused_gin_index.sql (10ms)16742026/10/01 09:52:37 OK 20251218171726_add_pins.sql (61.14ms)16752026/10/01 09:52:37 OK 20260628120000_add_object_size_and_stats.sql (72.44ms)16762026-10-01 09:52:37.640 UTC [91347] ERROR: relation "goose_db_version" does not exist at character 3616772026-10-01 09:52:37.640 UTC [91347] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16782026/10/01 09:52:37 OK 20260905000000_add_claims.sql (163.75ms)16792026/10/01 09:52:37 OK 20260920000000_drop_claims.sql (81.97ms)16802026/10/01 09:52:37 OK 20260923120000_add_pushes.sql (26.63ms)16812026/10/01 09:52:37 goose: successfully migrated database to version: 2026092312000016822026/10/01 09:52:37 OK 1_commit_pending_closure.sql (1.71ms)16832026/10/01 09:52:37 OK 2_object_stats_trigger.sql (399.04µs)16842026/10/01 09:52:37 OK 3_commit_push.sql (292.92µs)16852026/10/01 09:52:37 goose: up to current file version: 316862026/10/01 09:52:38 OK 20241026095416_initial_model.sql (370.54ms)16872026/10/01 09:52:38 OK 20251210153512_drop_unused_gin_index.sql (15.09ms)16882026/10/01 09:52:38 OK 20251218171726_add_pins.sql (61.58ms)16892026/10/01 09:52:38 INFO Aborted multipart uploads count=1 kept=016902026/10/01 09:52:38 INFO Received cleanup request method=DELETE path=/api/pending_closures16912026/10/01 09:52:38 OK 20260628120000_add_object_size_and_stats.sql (68.21ms)16922026/10/01 09:52:38 INFO Aborted multipart uploads count=1 kept=01693--- PASS: TestPendingCleanupUsesOneCutoff (11.70s)1694=== CONT TestSweepSkipsRowsLockedByPush1695--- PASS: TestService_healthCheckHandler (7.12s)1696=== CONT TestFailedS3DeleteKeepsTombstone16972026/10/01 09:52:38 OK 20260905000000_add_claims.sql (110.55ms)16982026/10/01 09:52:38 OK 20260920000000_drop_claims.sql (36.59ms)16992026-10-01 09:52:38.457 UTC [91362] ERROR: relation "goose_db_version" does not exist at character 3617002026-10-01 09:52:38.457 UTC [91362] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17012026/10/01 09:52:38 OK 20260923120000_add_pushes.sql (91.96ms)17022026/10/01 09:52:38 goose: successfully migrated database to version: 2026092312000017032026/10/01 09:52:38 OK 1_commit_pending_closure.sql (1.09ms)17042026/10/01 09:52:38 OK 2_object_stats_trigger.sql (269.63µs)17052026/10/01 09:52:38 OK 3_commit_push.sql (179.25µs)17062026/10/01 09:52:38 goose: up to current file version: 317072026-10-01 09:52:38.768 UTC [91369] ERROR: relation "goose_db_version" does not exist at character 3617082026-10-01 09:52:38.768 UTC [91369] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17092026/10/01 09:52:38 OK 20241026095416_initial_model.sql (324.85ms)17102026-10-01 09:52:38.913 UTC [91370] ERROR: relation "goose_db_version" does not exist at character 3617112026-10-01 09:52:38.913 UTC [91370] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17122026/10/01 09:52:38 OK 20251210153512_drop_unused_gin_index.sql (33.84ms)17132026/10/01 09:52:38 OK 20251218171726_add_pins.sql (62.41ms)17142026/10/01 09:52:39 INFO Aborted multipart uploads count=0 kept=017152026/10/01 09:52:39 WARN Force mode enabled - objects will be deleted immediately without grace period17162026/10/01 09:52:39 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=017172026/10/01 09:52:39 INFO Vacuumed table table=pending_closures17182026/10/01 09:52:39 INFO Vacuumed table table=pending_objects17192026/10/01 09:52:39 INFO Vacuumed table table=multipart_uploads17202026/10/01 09:52:39 INFO Vacuumed table table=closures17212026/10/01 09:52:39 INFO Vacuumed table table=objects1722--- PASS: TestGCMetrics (6.98s)1723=== CONT TestForceGCDuringPushOffersSweptObject1724=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1725=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1726=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1727=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1728=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection17292026/10/01 09:52:39 OK 20260628120000_add_object_size_and_stats.sql (57.99ms)17302026/10/01 09:52:39 OK 20241026095416_initial_model.sql (203.37ms)17312026/10/01 09:52:39 OK 20251210153512_drop_unused_gin_index.sql (15.17ms)17322026/10/01 09:52:39 OK 20251218171726_add_pins.sql (49.8ms)17332026/10/01 09:52:39 OK 20260905000000_add_claims.sql (137.34ms)17342026/10/01 09:52:39 OK 20260628120000_add_object_size_and_stats.sql (81.11ms)17352026/10/01 09:52:39 OK 20260920000000_drop_claims.sql (59.1ms)17362026/10/01 09:52:39 OK 20260923120000_add_pushes.sql (17.94ms)17372026/10/01 09:52:39 goose: successfully migrated database to version: 2026092312000017382026/10/01 09:52:39 OK 1_commit_pending_closure.sql (2.04ms)17392026/10/01 09:52:39 OK 2_object_stats_trigger.sql (295.75µs)17402026/10/01 09:52:39 OK 3_commit_push.sql (223.13µs)17412026/10/01 09:52:39 goose: up to current file version: 317422026/10/01 09:52:39 OK 20260905000000_add_claims.sql (142.03ms)17432026/10/01 09:52:39 OK 20241026095416_initial_model.sql (371.67ms)17442026/10/01 09:52:39 OK 20251210153512_drop_unused_gin_index.sql (27.81ms)17452026/10/01 09:52:39 OK 20251218171726_add_pins.sql (73.94ms)17462026/10/01 09:52:39 OK 20260920000000_drop_claims.sql (160.69ms)17472026/10/01 09:52:39 OK 20260923120000_add_pushes.sql (43.73ms)17482026/10/01 09:52:39 goose: successfully migrated database to version: 2026092312000017492026/10/01 09:52:39 OK 1_commit_pending_closure.sql (3.15ms)17502026/10/01 09:52:39 OK 2_object_stats_trigger.sql (714.17µs)17512026/10/01 09:52:39 OK 3_commit_push.sql (431.38µs)17522026/10/01 09:52:39 goose: up to current file version: 317532026/10/01 09:52:39 OK 20260628120000_add_object_size_and_stats.sql (87.77ms)17542026/10/01 09:52:39 OK 20260905000000_add_claims.sql (185.91ms)17552026/10/01 09:52:39 OK 20260920000000_drop_claims.sql (149.77ms)1756--- PASS: TestGCEndsOnShutdown (7.10s)1757=== CONT TestGCSweepDeliversEachKeyOnce17582026/10/01 09:52:39 OK 20260923120000_add_pushes.sql (29.03ms)17592026/10/01 09:52:39 goose: successfully migrated database to version: 2026092312000017602026/10/01 09:52:39 OK 1_commit_pending_closure.sql (1.02ms)17612026/10/01 09:52:39 OK 2_object_stats_trigger.sql (252.5µs)17622026/10/01 09:52:39 OK 3_commit_push.sql (196.25µs)17632026/10/01 09:52:39 goose: up to current file version: 317642026/10/01 09:52:40 INFO Aborted multipart uploads count=0 kept=017652026/10/01 09:52:40 WARN Force mode enabled - objects will be deleted immediately without grace period17662026/10/01 09:52:40 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=017672026/10/01 09:52:40 INFO Vacuumed table table=pending_closures17682026/10/01 09:52:40 INFO Vacuumed table table=pending_objects17692026/10/01 09:52:40 INFO Vacuumed table table=multipart_uploads17702026/10/01 09:52:41 INFO Vacuumed table table=closures17712026/10/01 09:52:41 INFO Vacuumed table table=objects1772--- PASS: TestCommitRacingPendingCleanupKeepsObjects (7.25s)1773=== CONT TestTombstonedObjectOfferedWithoutWaiting17742026/10/01 09:52:41 INFO Received uploads request method=POST path=/api/pending_closures17752026-10-01 09:52:41.655 UTC [91398] ERROR: relation "goose_db_version" does not exist at character 3617762026-10-01 09:52:41.655 UTC [91398] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1777--- PASS: TestPushWaitsForSweepHoldingRow (7.57s)1778=== CONT TestGCSweepSkipsPendingObjects17792026-10-01 09:52:41.692 UTC [91399] ERROR: relation "goose_db_version" does not exist at character 3617802026-10-01 09:52:41.692 UTC [91399] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1781=== NAME TestOrphanedObjectsGCStressTest1782 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains17832026/10/01 09:52:42 OK 20241026095416_initial_model.sql (250.91ms)17842026/10/01 09:52:42 OK 20251210153512_drop_unused_gin_index.sql (16.39ms)17852026/10/01 09:52:42 OK 20241026095416_initial_model.sql (258.51ms)17862026/10/01 09:52:42 OK 20251218171726_add_pins.sql (17.82ms)1787 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion17882026/10/01 09:52:42 OK 20251210153512_drop_unused_gin_index.sql (16.75ms)17892026-10-01 09:52:42.078 UTC [91406] ERROR: relation "goose_db_version" does not exist at character 3617902026-10-01 09:52:42.078 UTC [91406] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17912026/10/01 09:52:42 OK 20260628120000_add_object_size_and_stats.sql (55.26ms)17922026/10/01 09:52:42 OK 20251218171726_add_pins.sql (41.9ms)17932026/10/01 09:52:42 OK 20260628120000_add_object_size_and_stats.sql (54.5ms)17942026/10/01 09:52:42 OK 20260905000000_add_claims.sql (71.06ms)17952026/10/01 09:52:42 OK 20260920000000_drop_claims.sql (49.29ms)17962026/10/01 09:52:42 OK 20260923120000_add_pushes.sql (16.4ms)17972026/10/01 09:52:42 goose: successfully migrated database to version: 2026092312000017982026/10/01 09:52:42 OK 1_commit_pending_closure.sql (1.05ms)17992026/10/01 09:52:42 OK 2_object_stats_trigger.sql (233.88µs)18002026/10/01 09:52:42 OK 3_commit_push.sql (176.96µs)18012026/10/01 09:52:42 goose: up to current file version: 318022026/10/01 09:52:42 OK 20260905000000_add_claims.sql (83.95ms)18032026/10/01 09:52:42 OK 20260920000000_drop_claims.sql (74.92ms)18042026/10/01 09:52:42 OK 20260923120000_add_pushes.sql (18.86ms)18052026/10/01 09:52:42 goose: successfully migrated database to version: 2026092312000018062026/10/01 09:52:42 OK 1_commit_pending_closure.sql (4.77ms)18072026/10/01 09:52:42 OK 2_object_stats_trigger.sql (617.38µs)18082026/10/01 09:52:42 OK 3_commit_push.sql (178.67µs)18092026/10/01 09:52:42 goose: up to current file version: 318102026/10/01 09:52:42 OK 20241026095416_initial_model.sql (201.17ms)18112026/10/01 09:52:42 OK 20251210153512_drop_unused_gin_index.sql (16.39ms)18122026/10/01 09:52:42 OK 20251218171726_add_pins.sql (45.97ms)18132026/10/01 09:52:42 OK 20260628120000_add_object_size_and_stats.sql (69.43ms)18142026-10-01 09:52:42.549 UTC [91412] ERROR: relation "goose_db_version" does not exist at character 3618152026-10-01 09:52:42.549 UTC [91412] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18162026/10/01 09:52:42 OK 20260905000000_add_claims.sql (130.32ms)18172026/10/01 09:52:42 OK 20260920000000_drop_claims.sql (79.58ms)18182026/10/01 09:52:42 OK 20260923120000_add_pushes.sql (27.52ms)18192026/10/01 09:52:42 goose: successfully migrated database to version: 2026092312000018202026/10/01 09:52:42 OK 1_commit_pending_closure.sql (2.43ms)18212026/10/01 09:52:42 OK 2_object_stats_trigger.sql (639.92µs)18222026/10/01 09:52:42 OK 3_commit_push.sql (394.46µs)18232026/10/01 09:52:42 goose: up to current file version: 318242026/10/01 09:52:42 INFO Aborted multipart uploads count=0 kept=018252026/10/01 09:52:42 WARN Force mode enabled - objects will be deleted immediately without grace period18262026/10/01 09:52:42 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=018272026-10-01 09:52:42.803 UTC [91413] ERROR: relation "goose_db_version" does not exist at character 3618282026-10-01 09:52:42.803 UTC [91413] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18292026/10/01 09:52:42 INFO Vacuumed table table=pending_closures18302026/10/01 09:52:42 INFO Vacuumed table table=pending_objects18312026/10/01 09:52:42 INFO Vacuumed table table=multipart_uploads18322026/10/01 09:52:42 INFO Vacuumed table table=closures18332026/10/01 09:52:42 INFO Vacuumed table table=objects1834--- PASS: TestSweepRechecksPendingAfterLocking (6.71s)1835=== CONT TestDeduplicatedObjectsRecordedAsPending18362026/10/01 09:52:43 OK 20241026095416_initial_model.sql (408.16ms)18372026/10/01 09:52:43 OK 20251210153512_drop_unused_gin_index.sql (15.35ms)18382026/10/01 09:52:43 OK 20251218171726_add_pins.sql (69.92ms)1839--- PASS: TestGetExistingObjectsLocksRows (6.56s)1840=== CONT TestPushDedupSurvivesConcurrentGC18412026/10/01 09:52:43 OK 20260628120000_add_object_size_and_stats.sql (113.05ms)18422026/10/01 09:52:43 OK 20241026095416_initial_model.sql (588.38ms)18432026/10/01 09:52:43 OK 20260905000000_add_claims.sql (263.75ms)18442026/10/01 09:52:43 OK 20251210153512_drop_unused_gin_index.sql (31.42ms)18452026/10/01 09:52:43 OK 20251218171726_add_pins.sql (74.33ms)18462026/10/01 09:52:43 OK 20260920000000_drop_claims.sql (137.86ms)18472026/10/01 09:52:43 OK 20260923120000_add_pushes.sql (57.97ms)18482026/10/01 09:52:43 goose: successfully migrated database to version: 2026092312000018492026/10/01 09:52:43 OK 1_commit_pending_closure.sql (3.24ms)18502026/10/01 09:52:43 OK 2_object_stats_trigger.sql (703.92µs)18512026/10/01 09:52:43 OK 3_commit_push.sql (564.88µs)18522026/10/01 09:52:43 goose: up to current file version: 318532026/10/01 09:52:43 OK 20260628120000_add_object_size_and_stats.sql (116.63ms)1854--- PASS: TestRegisterCompletedObjectNeedsPendingRow (6.46s)1855=== CONT TestService_cleanupPendingClosuresHandler18562026/10/01 09:52:43 OK 20260905000000_add_claims.sql (204.99ms)18572026/10/01 09:52:44 OK 20260920000000_drop_claims.sql (126.45ms)18582026/10/01 09:52:44 OK 20260923120000_add_pushes.sql (60.34ms)18592026/10/01 09:52:44 goose: successfully migrated database to version: 2026092312000018602026/10/01 09:52:44 OK 1_commit_pending_closure.sql (5.11ms)18612026/10/01 09:52:44 OK 2_object_stats_trigger.sql (1.4ms)18622026/10/01 09:52:44 OK 3_commit_push.sql (664.75µs)18632026/10/01 09:52:44 goose: up to current file version: 318642026-10-01 09:52:44.169 UTC [91423] ERROR: relation "goose_db_version" does not exist at character 3618652026-10-01 09:52:44.169 UTC [91423] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18662026/10/01 09:52:44 INFO Aborted multipart uploads count=0 kept=018672026/10/01 09:52:44 WARN Force mode enabled - objects will be deleted immediately without grace period18682026/10/01 09:52:44 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=018692026/10/01 09:52:44 INFO Vacuumed table table=pending_closures18702026/10/01 09:52:44 INFO Vacuumed table table=pending_objects18712026/10/01 09:52:44 INFO Vacuumed table table=multipart_uploads18722026/10/01 09:52:44 INFO Vacuumed table table=closures18732026/10/01 09:52:44 INFO Vacuumed table table=objects18742026/10/01 09:52:44 INFO Aborted multipart uploads count=0 kept=018752026/10/01 09:52:44 WARN Force mode enabled - objects will be deleted immediately without grace period18762026/10/01 09:52:44 OK 20241026095416_initial_model.sql (619.46ms)18772026/10/01 09:52:44 OK 20251210153512_drop_unused_gin_index.sql (23ms)18782026/10/01 09:52:44 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=1 objects-failed-to-delete=018792026/10/01 09:52:45 INFO Vacuumed table table=pending_closures18802026/10/01 09:52:45 INFO Vacuumed table table=pending_objects18812026/10/01 09:52:45 INFO Vacuumed table table=multipart_uploads18822026/10/01 09:52:45 INFO Vacuumed table table=closures18832026/10/01 09:52:45 INFO Vacuumed table table=objects1884--- PASS: TestSweepSkipsRowsLockedByPush (6.71s)1885=== CONT TestIsValidUploadKey1886=== RUN TestIsValidUploadKey/narinfo1887=== PAUSE TestIsValidUploadKey/narinfo1888=== RUN TestIsValidUploadKey/nar_zst1889=== PAUSE TestIsValidUploadKey/nar_zst1890=== RUN TestIsValidUploadKey/nar_xz1891=== PAUSE TestIsValidUploadKey/nar_xz1892=== RUN TestIsValidUploadKey/nar_plain1893=== PAUSE TestIsValidUploadKey/nar_plain1894=== RUN TestIsValidUploadKey/listing1895=== PAUSE TestIsValidUploadKey/listing1896=== RUN TestIsValidUploadKey/build_log1897=== PAUSE TestIsValidUploadKey/build_log1898=== RUN TestIsValidUploadKey/build_log_home-manager_file1899=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1900=== RUN TestIsValidUploadKey/build_log_plus_in_name1901=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1902=== RUN TestIsValidUploadKey/build_log_question_mark1903=== PAUSE TestIsValidUploadKey/build_log_question_mark1904=== RUN TestIsValidUploadKey/build_log_equals1905=== PAUSE TestIsValidUploadKey/build_log_equals1906=== RUN TestIsValidUploadKey/realisation1907=== PAUSE TestIsValidUploadKey/realisation1908=== RUN TestIsValidUploadKey/realisation_plus_in_output1909=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1910=== RUN TestIsValidUploadKey/nix-cache-info1911=== PAUSE TestIsValidUploadKey/nix-cache-info1912=== RUN TestIsValidUploadKey/index.html1913=== PAUSE TestIsValidUploadKey/index.html1914=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1915=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1916=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1917=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1918=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1919=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1920=== RUN TestIsValidUploadKey/traversal1921=== PAUSE TestIsValidUploadKey/traversal1922=== RUN TestIsValidUploadKey/traversal_nar1923=== PAUSE TestIsValidUploadKey/traversal_nar1924=== RUN TestIsValidUploadKey/absolute1925=== PAUSE TestIsValidUploadKey/absolute1926=== RUN TestIsValidUploadKey/empty_key1927=== PAUSE TestIsValidUploadKey/empty_key1928=== RUN TestIsValidUploadKey/unknown_type1929=== PAUSE TestIsValidUploadKey/unknown_type1930=== CONT TestUploadHandlersRejectInvalidKeys1931=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1932=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1933=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1934=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1935=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1936=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1937=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1938=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1939=== CONT TestClientMultipleUploads19402026/10/01 09:52:45 OK 20251218171726_add_pins.sql (113.05ms)19412026/10/01 09:52:45 OK 20260628120000_add_object_size_and_stats.sql (85.74ms)19422026/10/01 09:52:45 OK 20260905000000_add_claims.sql (192.05ms)19432026/10/01 09:52:45 INFO Received uploads request method=POST path=/api/pending_closures19442026/10/01 09:52:45 OK 20260920000000_drop_claims.sql (41.59ms)19452026/10/01 09:52:45 OK 20260923120000_add_pushes.sql (43.55ms)19462026/10/01 09:52:45 goose: successfully migrated database to version: 2026092312000019472026/10/01 09:52:45 OK 1_commit_pending_closure.sql (3.67ms)19482026/10/01 09:52:45 OK 2_object_stats_trigger.sql (697.13µs)19492026/10/01 09:52:45 OK 3_commit_push.sql (413.04µs)19502026/10/01 09:52:45 goose: up to current file version: 319512026-10-01 09:52:45.528 UTC [91442] ERROR: relation "goose_db_version" does not exist at character 3619522026-10-01 09:52:45.528 UTC [91442] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19532026/10/01 09:52:45 INFO Aborted multipart uploads count=0 kept=019542026/10/01 09:52:45 WARN Force mode enabled - objects will be deleted immediately without grace period19552026/10/01 09:52:45 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."19562026/10/01 09:52:45 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1957--- PASS: TestFailedS3DeleteKeepsTombstone (7.45s)1958=== CONT TestGCBugBareHashReferences19592026/10/01 09:52:46 INFO Received uploads request method=POST path=/api/pending_closures19602026/10/01 09:52:46 OK 20241026095416_initial_model.sql (562.25ms)19612026/10/01 09:52:46 OK 20251210153512_drop_unused_gin_index.sql (34.3ms)19622026/10/01 09:52:46 OK 20251218171726_add_pins.sql (75.75ms)19632026/10/01 09:52:46 OK 20260628120000_add_object_size_and_stats.sql (68.27ms)19642026-10-01 09:52:46.461 UTC [91449] ERROR: relation "goose_db_version" does not exist at character 3619652026-10-01 09:52:46.461 UTC [91449] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1966--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (7.49s)1967=== CONT TestLeadEndsOnShutdown19682026/10/01 09:52:46 OK 20260905000000_add_claims.sql (146.4ms)19692026/10/01 09:52:46 OK 20260920000000_drop_claims.sql (109.28ms)19702026/10/01 09:52:46 OK 20260923120000_add_pushes.sql (162.77ms)19712026/10/01 09:52:46 goose: successfully migrated database to version: 2026092312000019722026/10/01 09:52:46 OK 1_commit_pending_closure.sql (2.07ms)19732026/10/01 09:52:46 OK 2_object_stats_trigger.sql (635.88µs)19742026/10/01 09:52:46 OK 3_commit_push.sql (373.79µs)19752026/10/01 09:52:46 goose: up to current file version: 319762026/10/01 09:52:47 OK 20241026095416_initial_model.sql (403.04ms)19772026/10/01 09:52:47 OK 20251210153512_drop_unused_gin_index.sql (21.93ms)19782026-10-01 09:52:47.089 UTC [91457] ERROR: relation "goose_db_version" does not exist at character 3619792026-10-01 09:52:47.089 UTC [91457] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19802026/10/01 09:52:47 OK 20251218171726_add_pins.sql (99.07ms)19812026/10/01 09:52:47 OK 20260628120000_add_object_size_and_stats.sql (71.26ms)19822026/10/01 09:52:47 OK 20260905000000_add_claims.sql (173.7ms)19832026/10/01 09:52:47 OK 20260920000000_drop_claims.sql (99.09ms)19842026/10/01 09:52:47 OK 20260923120000_add_pushes.sql (23.61ms)19852026/10/01 09:52:47 goose: successfully migrated database to version: 2026092312000019862026/10/01 09:52:47 OK 1_commit_pending_closure.sql (1.44ms)19872026/10/01 09:52:47 OK 2_object_stats_trigger.sql (335.54µs)19882026/10/01 09:52:47 OK 3_commit_push.sql (265.88µs)19892026/10/01 09:52:47 goose: up to current file version: 319902026/10/01 09:52:47 OK 20241026095416_initial_model.sql (473.21ms)19912026/10/01 09:52:47 OK 20251210153512_drop_unused_gin_index.sql (33.02ms)19922026/10/01 09:52:47 INFO Aborted multipart uploads count=0 kept=019932026/10/01 09:52:47 WARN Force mode enabled - objects will be deleted immediately without grace period19942026/10/01 09:52:47 OK 20251218171726_add_pins.sql (52.71ms)19952026/10/01 09:52:47 OK 20260628120000_add_object_size_and_stats.sql (83.93ms)19962026/10/01 09:52:47 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=019972026/10/01 09:52:47 INFO Vacuumed table table=pending_closures19982026/10/01 09:52:47 INFO Vacuumed table table=pending_objects19992026/10/01 09:52:47 INFO Vacuumed table table=multipart_uploads20002026/10/01 09:52:47 INFO Vacuumed table table=closures20012026/10/01 09:52:48 OK 20260905000000_add_claims.sql (200.78ms)20022026/10/01 09:52:48 INFO Vacuumed table table=objects2003--- PASS: TestGCSweepDeliversEachKeyOnce (8.12s)2004=== CONT TestLeadElectsOneAndHandsOver20052026/10/01 09:52:48 INFO Received uploads request method=POST path=/api/pending_closures20062026/10/01 09:52:48 OK 20260920000000_drop_claims.sql (131.96ms)20072026/10/01 09:52:48 OK 20260923120000_add_pushes.sql (29.34ms)20082026/10/01 09:52:48 goose: successfully migrated database to version: 2026092312000020092026/10/01 09:52:48 OK 1_commit_pending_closure.sql (3.17ms)20102026/10/01 09:52:48 OK 2_object_stats_trigger.sql (586.38µs)20112026/10/01 09:52:48 OK 3_commit_push.sql (447.71µs)20122026/10/01 09:52:48 goose: up to current file version: 32013--- PASS: TestTombstonedObjectOfferedWithoutWaiting (7.18s)2014=== CONT TestResolveDBConnectionString2015=== RUN TestResolveDBConnectionString/flag_wins2016=== PAUSE TestResolveDBConnectionString/flag_wins2017=== RUN TestResolveDBConnectionString/file_when_flag_empty2018=== PAUSE TestResolveDBConnectionString/file_when_flag_empty2019=== RUN TestResolveDBConnectionString/missing_file_is_an_error2020=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error2021=== RUN TestResolveDBConnectionString/PGHOST_allows_empty2022=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty2023=== RUN TestResolveDBConnectionString/nothing_configured2024=== PAUSE TestResolveDBConnectionString/nothing_configured2025=== CONT TestService_ReadScope_PublicByDefault20262026/10/01 09:52:48 INFO Received uploads request method=POST path=/api/pending_closures20272026/10/01 09:52:48 INFO Aborted multipart uploads count=0 kept=020282026/10/01 09:52:48 WARN Force mode enabled - objects will be deleted immediately without grace period20292026/10/01 09:52:48 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=020302026/10/01 09:52:49 INFO Vacuumed table table=pending_closures20312026/10/01 09:52:49 INFO Vacuumed table table=pending_objects20322026/10/01 09:52:49 INFO Vacuumed table table=multipart_uploads20332026/10/01 09:52:49 INFO Vacuumed table table=closures20342026/10/01 09:52:49 INFO Vacuumed table table=objects2035--- PASS: TestGCSweepSkipsPendingObjects (7.58s)2036=== CONT TestClientIntegration20372026-10-01 09:52:49.401 UTC [91507] ERROR: relation "goose_db_version" does not exist at character 3620382026-10-01 09:52:49.401 UTC [91507] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20392026-10-01 09:52:49.868 UTC [91516] ERROR: relation "goose_db_version" does not exist at character 3620402026-10-01 09:52:49.868 UTC [91516] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20412026/10/01 09:52:50 OK 20241026095416_initial_model.sql (371.8ms)20422026/10/01 09:52:50 OK 20251210153512_drop_unused_gin_index.sql (21.77ms)20432026/10/01 09:52:50 OK 20251218171726_add_pins.sql (61.16ms)20442026/10/01 09:52:50 OK 20260628120000_add_object_size_and_stats.sql (68.72ms)20452026/10/01 09:52:50 OK 20260905000000_add_claims.sql (111.97ms)20462026/10/01 09:52:50 OK 20241026095416_initial_model.sql (415.07ms)20472026/10/01 09:52:50 OK 20260920000000_drop_claims.sql (141.65ms)20482026/10/01 09:52:50 OK 20251210153512_drop_unused_gin_index.sql (54.41ms)20492026-10-01 09:52:50.453 UTC [91518] ERROR: relation "goose_db_version" does not exist at character 3620502026-10-01 09:52:50.453 UTC [91518] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20512026/10/01 09:52:50 OK 20260923120000_add_pushes.sql (37.84ms)20522026/10/01 09:52:50 goose: successfully migrated database to version: 2026092312000020532026/10/01 09:52:50 OK 1_commit_pending_closure.sql (3.28ms)20542026/10/01 09:52:50 OK 2_object_stats_trigger.sql (692.5µs)20552026/10/01 09:52:50 OK 3_commit_push.sql (467.83µs)20562026/10/01 09:52:50 goose: up to current file version: 320572026/10/01 09:52:50 OK 20251218171726_add_pins.sql (85.93ms)20582026/10/01 09:52:50 OK 20260628120000_add_object_size_and_stats.sql (84.07ms)20592026/10/01 09:52:50 OK 20260905000000_add_claims.sql (186.96ms)20602026/10/01 09:52:50 OK 20260920000000_drop_claims.sql (19.07ms)20612026/10/01 09:52:50 OK 20260923120000_add_pushes.sql (50.85ms)20622026/10/01 09:52:50 goose: successfully migrated database to version: 2026092312000020632026/10/01 09:52:50 OK 1_commit_pending_closure.sql (3.11ms)20642026/10/01 09:52:50 OK 2_object_stats_trigger.sql (674.38µs)20652026/10/01 09:52:50 OK 3_commit_push.sql (421.46µs)20662026/10/01 09:52:50 goose: up to current file version: 320672026-10-01 09:52:50.893 UTC [91523] ERROR: relation "goose_db_version" does not exist at character 3620682026-10-01 09:52:50.893 UTC [91523] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2069=== NAME TestOrphanedObjectsGCStressTest2070 orphaned_objects_gc_test.go:509: Stress test completed successfully:2071 orphaned_objects_gc_test.go:510: - Active objects preserved: 202072 orphaned_objects_gc_test.go:511: - Objects deleted: 2102073 orphaned_objects_gc_test.go:512: - Total GC'd: 2102074--- PASS: TestOrphanedObjectsGCStressTest (26.66s)2075=== CONT TestClientErrorHandling2076=== RUN TestClientErrorHandling/InvalidStorePath2077=== PAUSE TestClientErrorHandling/InvalidStorePath2078=== RUN TestClientErrorHandling/InvalidAuthToken2079=== PAUSE TestClientErrorHandling/InvalidAuthToken2080=== RUN TestClientErrorHandling/ServerNotAvailable2081=== PAUSE TestClientErrorHandling/ServerNotAvailable2082=== CONT TestClientCADerivations20832026/10/01 09:52:51 OK 20241026095416_initial_model.sql (442.98ms)20842026/10/01 09:52:51 OK 20251210153512_drop_unused_gin_index.sql (34.86ms)20852026/10/01 09:52:51 OK 20251218171726_add_pins.sql (37.59ms)20862026/10/01 09:52:51 INFO Received uploads request method=POST path=/api/pending_closures2087--- PASS: TestDeduplicatedObjectsRecordedAsPending (8.28s)2088=== CONT TestCacheStatsHandler20892026/10/01 09:52:51 OK 20260628120000_add_object_size_and_stats.sql (116.86ms)20902026/10/01 09:52:51 OK 20260905000000_add_claims.sql (109.4ms)20912026/10/01 09:52:51 OK 20241026095416_initial_model.sql (289.95ms)20922026/10/01 09:52:51 OK 20251210153512_drop_unused_gin_index.sql (19.45ms)20932026/10/01 09:52:51 OK 20260920000000_drop_claims.sql (123.02ms)20942026/10/01 09:52:51 OK 20251218171726_add_pins.sql (87.34ms)20952026/10/01 09:52:51 OK 20260923120000_add_pushes.sql (36.67ms)20962026/10/01 09:52:51 goose: successfully migrated database to version: 2026092312000020972026/10/01 09:52:51 OK 1_commit_pending_closure.sql (2.65ms)20982026/10/01 09:52:51 OK 2_object_stats_trigger.sql (545.25µs)20992026/10/01 09:52:51 OK 3_commit_push.sql (339.88µs)21002026/10/01 09:52:51 goose: up to current file version: 321012026/10/01 09:52:51 OK 20260628120000_add_object_size_and_stats.sql (59.27ms)21022026-10-01 09:52:51.594 UTC [91528] ERROR: relation "goose_db_version" does not exist at character 3621032026-10-01 09:52:51.594 UTC [91528] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21042026/10/01 09:52:51 OK 20260905000000_add_claims.sql (126.81ms)21052026/10/01 09:52:51 OK 20260920000000_drop_claims.sql (120.49ms)21062026/10/01 09:52:51 OK 20260923120000_add_pushes.sql (43.99ms)21072026/10/01 09:52:51 goose: successfully migrated database to version: 2026092312000021082026/10/01 09:52:51 OK 1_commit_pending_closure.sql (3.11ms)21092026/10/01 09:52:51 OK 2_object_stats_trigger.sql (2.75ms)21102026/10/01 09:52:51 OK 3_commit_push.sql (1.65ms)21112026/10/01 09:52:51 goose: up to current file version: 321122026/10/01 09:52:51 INFO Received uploads request method=POST path=/api/pending_closures21132026/10/01 09:52:52 INFO Aborted multipart uploads count=0 kept=021142026/10/01 09:52:52 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=021152026/10/01 09:52:52 INFO Vacuumed table table=pending_closures21162026-10-01 09:52:52.183 UTC [91531] ERROR: relation "goose_db_version" does not exist at character 3621172026-10-01 09:52:52.183 UTC [91531] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21182026/10/01 09:52:52 INFO Vacuumed table table=pending_objects21192026/10/01 09:52:52 INFO Vacuumed table table=multipart_uploads21202026/10/01 09:52:52 OK 20241026095416_initial_model.sql (492.05ms)21212026/10/01 09:52:52 OK 20251210153512_drop_unused_gin_index.sql (29.61ms)21222026/10/01 09:52:52 INFO Received cleanup request method=DELETE path=/api/pending_closures21232026/10/01 09:52:52 INFO Vacuumed table table=closures21242026/10/01 09:52:52 INFO Aborted multipart uploads count=0 kept=021252026/10/01 09:52:52 INFO Received uploads request method=POST path=/api/pending_closures21262026/10/01 09:52:52 INFO Vacuumed table table=objects21272026/10/01 09:52:52 OK 20251218171726_add_pins.sql (71.74ms)21282026/10/01 09:52:52 INFO Aborted multipart uploads count=0 kept=021292026/10/01 09:52:52 WARN Force mode enabled - objects will be deleted immediately without grace period21302026/10/01 09:52:52 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=021312026/10/01 09:52:52 INFO Vacuumed table table=pending_closures21322026/10/01 09:52:52 INFO Vacuumed table table=pending_objects21332026/10/01 09:52:52 INFO Vacuumed table table=multipart_uploads21342026/10/01 09:52:52 OK 20260628120000_add_object_size_and_stats.sql (78.21ms)21352026/10/01 09:52:52 INFO Vacuumed table table=closures21362026/10/01 09:52:52 INFO Vacuumed table table=objects21372026/10/01 09:52:52 INFO Received cleanup request method=DELETE path=/api/pending_closures21382026/10/01 09:52:52 INFO Aborted multipart uploads count=1 kept=02139--- PASS: TestPushDedupSurvivesConcurrentGC (9.24s)2140=== CONT TestCacheConfigHandler2141=== RUN TestCacheConfigHandler/full_config,_no_issuer2142=== PAUSE TestCacheConfigHandler/full_config,_no_issuer2143=== RUN TestCacheConfigHandler/no_cache_url_configured2144=== PAUSE TestCacheConfigHandler/no_cache_url_configured2145=== RUN TestCacheConfigHandler/no_signing_keys2146=== PAUSE TestCacheConfigHandler/no_signing_keys2147=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2148=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2149=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock21502026/10/01 09:52:52 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21512026-10-01 09:52:52.503 UTC [91518] ERROR: Closure does not exist: id=121522026-10-01 09:52:52.503 UTC [91518] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE21532026-10-01 09:52:52.503 UTC [91518] STATEMENT: -- name: CommitPendingClosure :exec2154 SELECT commit_pending_closure($1::bigint)2155 2156--- PASS: TestService_cleanupPendingClosuresHandler (8.58s)2157=== CONT TestClientFallsBackToClosures21582026/10/01 09:52:52 OK 20260905000000_add_claims.sql (163.55ms)21592026/10/01 09:52:52 OK 20260920000000_drop_claims.sql (122.27ms)21602026/10/01 09:52:52 OK 20260923120000_add_pushes.sql (189.61ms)21612026/10/01 09:52:52 goose: successfully migrated database to version: 2026092312000021622026/10/01 09:52:52 OK 20241026095416_initial_model.sql (572.79ms)21632026/10/01 09:52:52 OK 1_commit_pending_closure.sql (6.48ms)21642026/10/01 09:52:52 OK 2_object_stats_trigger.sql (1.01ms)21652026/10/01 09:52:52 OK 3_commit_push.sql (517.17µs)21662026/10/01 09:52:52 goose: up to current file version: 321672026/10/01 09:52:52 OK 20251210153512_drop_unused_gin_index.sql (18.05ms)21682026/10/01 09:52:52 OK 20251218171726_add_pins.sql (59.19ms)21692026/10/01 09:52:53 OK 20260628120000_add_object_size_and_stats.sql (93.22ms)21702026/10/01 09:52:53 OK 20260905000000_add_claims.sql (136.93ms)21712026/10/01 09:52:53 OK 20260920000000_drop_claims.sql (46.98ms)21722026/10/01 09:52:53 OK 20260923120000_add_pushes.sql (14.1ms)21732026/10/01 09:52:53 goose: successfully migrated database to version: 2026092312000021742026/10/01 09:52:53 OK 1_commit_pending_closure.sql (1.7ms)21752026/10/01 09:52:53 OK 2_object_stats_trigger.sql (386.75µs)21762026/10/01 09:52:53 OK 3_commit_push.sql (301.25µs)21772026/10/01 09:52:53 goose: up to current file version: 32178=== NAME TestClientMultipleUploads2179 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-90547-3700828917/TestClientMultipleUploads2948651161/001/store/pb7g57mxgr0b4lix386fyynv6cz3pf4k-test-file-0.txt21802026-10-01 09:52:53.751 UTC [91543] ERROR: relation "goose_db_version" does not exist at character 3621812026-10-01 09:52:53.751 UTC [91543] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2182--- PASS: TestGCBugBareHashReferences (7.98s)2183=== CONT TestClientPushesUseOnePush2184=== NAME TestClientMultipleUploads2185 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-90547-3700828917/TestClientMultipleUploads2948651161/001/store/wgxgysaqwi8gsswyry060sarj6cvamy3-test-file-1.txt21862026/10/01 09:52:53 INFO lead: acquired remote=192.0.2.1:123421872026/10/01 09:52:53 INFO lead: released remote=192.0.2.1:12342188--- PASS: TestLeadEndsOnShutdown (7.44s)2189=== CONT TestPinProtectsFromGC21902026-10-01 09:52:54.012 UTC [91549] ERROR: relation "goose_db_version" does not exist at character 3621912026-10-01 09:52:54.012 UTC [91549] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2192=== NAME TestClientMultipleUploads2193 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-90547-3700828917/TestClientMultipleUploads2948651161/001/store/fp97jlnz5h6k9k6i4ylmy18hb0r12g2k-test-file-2.txt21942026/10/01 09:52:54 INFO Received push request method=POST path=/api/pushes21952026/10/01 09:52:54 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)21962026/10/01 09:52:54 INFO Uploading wgxgysaqwi8gsswyry060sarj6cvamy3-test-file-1.txt (160B)21972026/10/01 09:52:54 INFO Uploading pb7g57mxgr0b4lix386fyynv6cz3pf4k-test-file-0.txt (160B)21982026/10/01 09:52:54 INFO Uploading fp97jlnz5h6k9k6i4ylmy18hb0r12g2k-test-file-2.txt (160B)21992026/10/01 09:52:54 OK 20241026095416_initial_model.sql (347.44ms)22002026/10/01 09:52:54 WARN Failed to register uploaded object key=fp97jlnz5h6k9k6i4ylmy18hb0r12g2k.ls error="server returned 404: 404 page not found\n"22012026/10/01 09:52:54 WARN Failed to register uploaded object key=wgxgysaqwi8gsswyry060sarj6cvamy3.ls error="server returned 404: 404 page not found\n"22022026/10/01 09:52:54 WARN Failed to register uploaded object key=pb7g57mxgr0b4lix386fyynv6cz3pf4k.ls error="server returned 404: 404 page not found\n"22032026/10/01 09:52:54 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"22042026/10/01 09:52:54 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"22052026/10/01 09:52:54 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22062026/10/01 09:52:54 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"22072026/10/01 09:52:54 INFO Signed narinfos id=1 count=322082026/10/01 09:52:54 INFO Uploading 3 narinfos22092026/10/01 09:52:54 OK 20251210153512_drop_unused_gin_index.sql (12.69ms)22102026/10/01 09:52:54 WARN Failed to register uploaded object key=fp97jlnz5h6k9k6i4ylmy18hb0r12g2k.narinfo error="server returned 404: 404 page not found\n"22112026/10/01 09:52:54 WARN Failed to register uploaded object key=wgxgysaqwi8gsswyry060sarj6cvamy3.narinfo error="server returned 404: 404 page not found\n"22122026-10-01 09:52:54.278 UTC [91561] ERROR: relation "goose_db_version" does not exist at character 3622132026-10-01 09:52:54.278 UTC [91561] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22142026/10/01 09:52:54 INFO Received complete push request method=POST path=/api/pushes/1/complete22152026/10/01 09:52:54 WARN Failed to register uploaded object key=pb7g57mxgr0b4lix386fyynv6cz3pf4k.narinfo error="server returned 404: 404 page not found\n"22162026/10/01 09:52:54 OK 20251218171726_add_pins.sql (76.65ms)22172026/10/01 09:52:54 INFO Upload complete. (250ms)2218 client_integration_test.go:369: Uploaded 3 paths in 304.111ms22192026/10/01 09:52:54 OK 20241026095416_initial_model.sql (273.6ms)22202026/10/01 09:52:54 OK 20251210153512_drop_unused_gin_index.sql (19.71ms)22212026/10/01 09:52:54 OK 20260628120000_add_object_size_and_stats.sql (80.93ms)22222026/10/01 09:52:54 OK 20251218171726_add_pins.sql (63.53ms)22232026/10/01 09:52:54 OK 20260905000000_add_claims.sql (77.9ms)22242026/10/01 09:52:54 OK 20260628120000_add_object_size_and_stats.sql (54.98ms)2225--- PASS: TestClientMultipleUploads (9.48s)2226=== CONT TestClientSharedPathCommittedMidPush22272026/10/01 09:52:54 OK 20260920000000_drop_claims.sql (62.47ms)22282026/10/01 09:52:54 OK 20260923120000_add_pushes.sql (24.56ms)22292026/10/01 09:52:54 goose: successfully migrated database to version: 2026092312000022302026/10/01 09:52:54 OK 1_commit_pending_closure.sql (1.43ms)22312026/10/01 09:52:54 OK 2_object_stats_trigger.sql (377.58µs)22322026/10/01 09:52:54 OK 3_commit_push.sql (327.04µs)22332026/10/01 09:52:54 goose: up to current file version: 322342026/10/01 09:52:54 OK 20260905000000_add_claims.sql (90.19ms)22352026/10/01 09:52:54 OK 20241026095416_initial_model.sql (280.63ms)22362026/10/01 09:52:54 OK 20251210153512_drop_unused_gin_index.sql (26.36ms)22372026/10/01 09:52:54 OK 20260920000000_drop_claims.sql (108.74ms)22382026/10/01 09:52:54 OK 20260923120000_add_pushes.sql (59.22ms)22392026/10/01 09:52:54 goose: successfully migrated database to version: 2026092312000022402026/10/01 09:52:54 OK 1_commit_pending_closure.sql (4.62ms)22412026/10/01 09:52:54 OK 2_object_stats_trigger.sql (4.76ms)22422026/10/01 09:52:54 OK 3_commit_push.sql (884.13µs)22432026/10/01 09:52:54 goose: up to current file version: 322442026/10/01 09:52:54 OK 20251218171726_add_pins.sql (92.36ms)22452026/10/01 09:52:54 OK 20260628120000_add_object_size_and_stats.sql (115.84ms)22462026/10/01 09:52:55 OK 20260905000000_add_claims.sql (250.65ms)2247--- PASS: TestService_ReadScope_PublicByDefault (7.00s)2248=== CONT TestClientWithDependencies22492026/10/01 09:52:55 OK 20260920000000_drop_claims.sql (111.46ms)22502026/10/01 09:52:55 OK 20260923120000_add_pushes.sql (46.83ms)22512026/10/01 09:52:55 goose: successfully migrated database to version: 2026092312000022522026/10/01 09:52:55 OK 1_commit_pending_closure.sql (2.83ms)22532026/10/01 09:52:55 OK 2_object_stats_trigger.sql (556.54µs)22542026/10/01 09:52:55 OK 3_commit_push.sql (434µs)22552026/10/01 09:52:55 goose: up to current file version: 322562026/10/01 09:52:55 INFO lead: acquired remote=192.0.2.1:123422572026/10/01 09:52:56 INFO lead: released remote=192.0.2.1:123422582026/10/01 09:52:56 INFO lead: acquired remote=192.0.2.1:123422592026/10/01 09:52:56 INFO lead: released remote=192.0.2.1:12342260--- PASS: TestLeadElectsOneAndHandsOver (8.05s)2261=== CONT TestService_ReadAuthMiddleware22622026-10-01 09:52:56.806 UTC [91593] ERROR: relation "goose_db_version" does not exist at character 3622632026-10-01 09:52:56.806 UTC [91593] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22642026-10-01 09:52:56.896 UTC [91595] ERROR: relation "goose_db_version" does not exist at character 3622652026-10-01 09:52:56.896 UTC [91595] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2266=== NAME TestClientIntegration2267 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-90547-3700828917/TestClientIntegration2949002262/002/store/xpjy4pwnp9cv19glpc8qj78497qb8cbh-test-file.txt22682026/10/01 09:52:56 OK 20241026095416_initial_model.sql (61.81ms)22692026/10/01 09:52:56 OK 20251210153512_drop_unused_gin_index.sql (13.96ms)22702026-10-01 09:52:56.984 UTC [91601] ERROR: relation "goose_db_version" does not exist at character 3622712026-10-01 09:52:56.984 UTC [91601] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22722026/10/01 09:52:56 OK 20251218171726_add_pins.sql (32.79ms)22732026-10-01 09:52:56.984 UTC [91600] ERROR: relation "goose_db_version" does not exist at character 3622742026-10-01 09:52:56.984 UTC [91600] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22752026/10/01 09:52:57 OK 20260628120000_add_object_size_and_stats.sql (42.49ms)22762026/10/01 09:52:57 OK 20241026095416_initial_model.sql (112.26ms)22772026/10/01 09:52:57 INFO Received push request method=POST path=/api/pushes22782026/10/01 09:52:57 OK 20251210153512_drop_unused_gin_index.sql (1.82ms)22792026/10/01 09:52:57 OK 20260905000000_add_claims.sql (25.72ms)22802026/10/01 09:52:57 OK 20251218171726_add_pins.sql (12.95ms)22812026/10/01 09:52:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)22822026/10/01 09:52:57 INFO Uploading xpjy4pwnp9cv19glpc8qj78497qb8cbh-test-file.txt (152B)22832026/10/01 09:52:57 OK 20260920000000_drop_claims.sql (25ms)22842026/10/01 09:52:57 OK 20260628120000_add_object_size_and_stats.sql (26.08ms)22852026/10/01 09:52:57 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"22862026/10/01 09:52:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22872026/10/01 09:52:57 WARN Failed to register uploaded object key=xpjy4pwnp9cv19glpc8qj78497qb8cbh.ls error="server returned 404: 404 page not found\n"22882026/10/01 09:52:57 INFO Signed narinfos id=1 count=122892026/10/01 09:52:57 INFO Uploading 1 narinfos22902026/10/01 09:52:57 OK 20260923120000_add_pushes.sql (5.28ms)22912026/10/01 09:52:57 goose: successfully migrated database to version: 2026092312000022922026/10/01 09:52:57 OK 1_commit_pending_closure.sql (990.5µs)22932026/10/01 09:52:57 OK 2_object_stats_trigger.sql (238.13µs)22942026/10/01 09:52:57 OK 3_commit_push.sql (1ms)22952026/10/01 09:52:57 goose: up to current file version: 322962026/10/01 09:52:57 INFO Received complete push request method=POST path=/api/pushes/1/complete22972026/10/01 09:52:57 WARN Failed to register uploaded object key=xpjy4pwnp9cv19glpc8qj78497qb8cbh.narinfo error="server returned 404: 404 page not found\n"22982026/10/01 09:52:57 OK 20260905000000_add_claims.sql (124.06ms)22992026/10/01 09:52:57 INFO Upload complete. (235ms)23002026/10/01 09:52:57 INFO All 1 paths already cached2301 client_integration_test.go:312: Retrieved narinfo from S3:2302 StorePath: /nix/var/nix/builds/nix-90547-3700828917/TestClientIntegration2949002262/002/store/xpjy4pwnp9cv19glpc8qj78497qb8cbh-test-file.txt2303 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2304 Compression: zstd2305 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12306 NarSize: 1522307 References: 2308 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12309 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2310 client_integration_test.go:313: Decompressed .ls content (64 bytes):2311 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2312 client_integration_test.go:316: Testing garbage collection...23132026/10/01 09:52:57 OK 20241026095416_initial_model.sql (219.84ms)23142026/10/01 09:52:57 OK 20251210153512_drop_unused_gin_index.sql (17.36ms)23152026/10/01 09:52:57 OK 20260920000000_drop_claims.sql (73.64ms)23162026/10/01 09:52:57 INFO Starting cleanup of old closures method=DELETE path=/api/closures23172026/10/01 09:52:57 INFO Garbage collection started23182026/10/01 09:52:57 INFO Aborted multipart uploads count=0 kept=023192026/10/01 09:52:57 WARN Force mode enabled - objects will be deleted immediately without grace period23202026/10/01 09:52:57 OK 20241026095416_initial_model.sql (259.45ms)23212026/10/01 09:52:57 OK 20260923120000_add_pushes.sql (23.98ms)23222026/10/01 09:52:57 goose: successfully migrated database to version: 2026092312000023232026/10/01 09:52:57 OK 1_commit_pending_closure.sql (822.58µs)23242026/10/01 09:52:57 OK 2_object_stats_trigger.sql (635.63µs)23252026/10/01 09:52:57 OK 3_commit_push.sql (159.54µs)23262026/10/01 09:52:57 goose: up to current file version: 323272026/10/01 09:52:57 OK 20251218171726_add_pins.sql (31.86ms)23282026/10/01 09:52:57 OK 20251210153512_drop_unused_gin_index.sql (16.32ms)23292026/10/01 09:52:57 OK 20251218171726_add_pins.sql (21.26ms)23302026/10/01 09:52:57 OK 20260628120000_add_object_size_and_stats.sql (40.39ms)23312026/10/01 09:52:57 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=023322026/10/01 09:52:57 OK 20260628120000_add_object_size_and_stats.sql (52.26ms)23332026/10/01 09:52:57 INFO Vacuumed table table=pending_closures23342026/10/01 09:52:57 OK 20260905000000_add_claims.sql (79.93ms)23352026/10/01 09:52:57 OK 20260905000000_add_claims.sql (70.7ms)23362026/10/01 09:52:57 OK 20260920000000_drop_claims.sql (40.94ms)23372026/10/01 09:52:57 INFO Vacuumed table table=pending_objects23382026/10/01 09:52:57 INFO Vacuumed table table=multipart_uploads23392026/10/01 09:52:57 OK 20260923120000_add_pushes.sql (22.68ms)23402026/10/01 09:52:57 goose: successfully migrated database to version: 2026092312000023412026/10/01 09:52:57 OK 1_commit_pending_closure.sql (1.81ms)23422026/10/01 09:52:57 OK 2_object_stats_trigger.sql (283.17µs)23432026/10/01 09:52:57 OK 3_commit_push.sql (222.54µs)23442026/10/01 09:52:57 goose: up to current file version: 323452026/10/01 09:52:57 OK 20260920000000_drop_claims.sql (52.19ms)23462026/10/01 09:52:57 INFO Vacuumed table table=closures23472026/10/01 09:52:57 OK 20260923120000_add_pushes.sql (25.09ms)23482026/10/01 09:52:57 goose: successfully migrated database to version: 2026092312000023492026/10/01 09:52:57 OK 1_commit_pending_closure.sql (1.29ms)23502026/10/01 09:52:57 OK 2_object_stats_trigger.sql (324.46µs)23512026/10/01 09:52:57 OK 3_commit_push.sql (247.67µs)23522026/10/01 09:52:57 goose: up to current file version: 323532026/10/01 09:52:57 INFO Vacuumed table table=objects2354--- PASS: TestCacheStatsHandler (6.79s)2355=== CONT TestService_RequireScope_OIDC23562026-10-01 09:52:58.073 UTC [91620] ERROR: relation "goose_db_version" does not exist at character 3623572026-10-01 09:52:58.073 UTC [91620] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23582026/10/01 09:52:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55557/oidc23592026-10-01 09:52:58.141 UTC [91624] ERROR: relation "goose_db_version" does not exist at character 3623602026-10-01 09:52:58.141 UTC [91624] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2361=== NAME TestClientCADerivations2362 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-90547-3700828917/TestClientCADerivations2952202293/001/store/3k66cjr6zli7i22cabl6jrhx9v4539mz-ca-test23632026/10/01 09:52:58 OK 20241026095416_initial_model.sql (305.85ms)2364 client_ca_test.go:139: Found 1 dependencies (including self)23652026/10/01 09:52:58 OK 20251210153512_drop_unused_gin_index.sql (30.08ms)23662026/10/01 09:52:58 OK 20251218171726_add_pins.sql (45.56ms)23672026/10/01 09:52:58 OK 20241026095416_initial_model.sql (320.29ms)23682026/10/01 09:52:58 OK 20251210153512_drop_unused_gin_index.sql (13.43ms)23692026/10/01 09:52:58 OK 20260628120000_add_object_size_and_stats.sql (38.65ms)23702026/10/01 09:52:58 OK 20251218171726_add_pins.sql (42.93ms)23712026-10-01 09:52:58.607 UTC [91636] ERROR: relation "goose_db_version" does not exist at character 3623722026-10-01 09:52:58.607 UTC [91636] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23732026/10/01 09:52:58 OK 20260628120000_add_object_size_and_stats.sql (64.84ms)23742026/10/01 09:52:58 OK 20260905000000_add_claims.sql (110.33ms)23752026/10/01 09:52:58 INFO Received push request method=POST path=/api/pushes23762026/10/01 09:52:58 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)23772026/10/01 09:52:58 INFO Uploading 3k66cjr6zli7i22cabl6jrhx9v4539mz-ca-test (144B)23782026/10/01 09:52:58 OK 20260920000000_drop_claims.sql (59.33ms)23792026/10/01 09:52:58 OK 20260923120000_add_pushes.sql (21.44ms)23802026/10/01 09:52:58 goose: successfully migrated database to version: 2026092312000023812026/10/01 09:52:58 WARN Failed to register uploaded object key=3k66cjr6zli7i22cabl6jrhx9v4539mz.ls error="server returned 404: 404 page not found\n"23822026/10/01 09:52:58 OK 1_commit_pending_closure.sql (1.24ms)23832026/10/01 09:52:58 OK 2_object_stats_trigger.sql (453.54µs)23842026/10/01 09:52:58 OK 3_commit_push.sql (1.25ms)23852026/10/01 09:52:58 goose: up to current file version: 323862026/10/01 09:52:58 WARN Failed to register uploaded object key=log/4i4c2lbv7iadi3kahxbv001n2yc8khxn-ca-test.drv error="server returned 404: 404 page not found\n"23872026/10/01 09:52:58 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"23882026/10/01 09:52:58 OK 20260905000000_add_claims.sql (109.17ms)23892026/10/01 09:52:58 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23902026/10/01 09:52:58 INFO Signed narinfos id=1 count=123912026/10/01 09:52:58 INFO Uploading 1 narinfos23922026/10/01 09:52:58 INFO Received complete push request method=POST path=/api/pushes/1/complete23932026/10/01 09:52:58 WARN Failed to register uploaded object key=3k66cjr6zli7i22cabl6jrhx9v4539mz.narinfo error="server returned 404: 404 page not found\n"23942026/10/01 09:52:58 INFO Upload complete. (356ms)2395 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-90547-3700828917/TestClientCADerivations2952202293/001/store/3k66cjr6zli7i22cabl6jrhx9v4539mz-ca-test2396 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2397 Compression: zstd2398 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2399 NarSize: 1442400 References: 2401 Deriver: /nix/var/nix/builds/nix-90547-3700828917/TestClientCADerivations2952202293/001/store/4i4c2lbv7iadi3kahxbv001n2yc8khxn-ca-test.drv2402 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2403 client_ca_test.go:185: Checking for realisation files in S3...24042026/10/01 09:52:58 OK 20260920000000_drop_claims.sql (102.2ms)2405 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2406 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache24072026/10/01 09:52:58 OK 20260923120000_add_pushes.sql (40.1ms)24082026/10/01 09:52:58 goose: successfully migrated database to version: 2026092312000024092026/10/01 09:52:58 OK 1_commit_pending_closure.sql (884.58µs)24102026/10/01 09:52:58 OK 2_object_stats_trigger.sql (252.63µs)24112026/10/01 09:52:58 OK 3_commit_push.sql (191.5µs)24122026/10/01 09:52:58 goose: up to current file version: 32413 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket69?endpoint=http://localhost:55085®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-90547-3700828917/TestClientCADerivations2952202293/001/store'2414 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 124152026/10/01 09:52:59 OK 20241026095416_initial_model.sql (332.85ms)24162026/10/01 09:52:59 OK 20251210153512_drop_unused_gin_index.sql (10.03ms)24172026/10/01 09:52:59 OK 20251218171726_add_pins.sql (48.5ms)24182026/10/01 09:52:59 OK 20260628120000_add_object_size_and_stats.sql (50.26ms)24192026-10-01 09:52:59.175 UTC [91648] ERROR: relation "goose_db_version" does not exist at character 3624202026-10-01 09:52:59.175 UTC [91648] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2421--- PASS: TestClientCADerivations (8.22s)2422=== CONT TestService_AuthMiddleware_OIDC24232026/10/01 09:52:59 INFO Received uploads request method=POST path=/api/pending_closures24242026/10/01 09:52:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55583/oidc24252026/10/01 09:52:59 OK 20260905000000_add_claims.sql (102.97ms)24262026/10/01 09:52:59 INFO Received uploads request method=POST path=/api/pending_closures24272026/10/01 09:52:59 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)24282026/10/01 09:52:59 INFO Uploading iw936i34g107ksaq5dqjbmrdsal4k4nn-shared-dep (136B)24292026/10/01 09:52:59 INFO Uploading i970lzfqq98hfsllaiv0k0160yfdjgp6-b (248B)24302026/10/01 09:52:59 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"24312026/10/01 09:52:59 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02432=== NAME TestClientIntegration2433 client_integration_test.go:323: Objects in database after GC:2434 client_integration_test.go:323: Successfully deleted all objects with GC --force24352026/10/01 09:52:59 WARN Failed to register uploaded object key=i970lzfqq98hfsllaiv0k0160yfdjgp6.ls error="server returned 404: 404 page not found\n"24362026/10/01 09:52:59 WARN Failed to register uploaded object key=pvvn8byfv5vys7rb9bzb1950g5pdf52b.ls error="server returned 404: 404 page not found\n"24372026/10/01 09:52:59 WARN Failed to register uploaded object key=iw936i34g107ksaq5dqjbmrdsal4k4nn.ls error="server returned 404: 404 page not found\n"24382026/10/01 09:52:59 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign24392026/10/01 09:52:59 WARN Failed to register uploaded object key=nar/0rqiwpmna7lvn2ai12gq32rdw0w60sfbf8c7n6j9ljm0qwh2xk43.nar.zst error="server returned 404: 404 page not found\n"24402026/10/01 09:52:59 INFO Signed narinfos id=1 count=224412026/10/01 09:52:59 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign24422026/10/01 09:52:59 INFO Signed narinfos id=2 count=224432026/10/01 09:52:59 INFO Uploading 4 narinfos24442026/10/01 09:52:59 OK 20260920000000_drop_claims.sql (67.85ms)24452026/10/01 09:52:59 WARN Failed to register uploaded object key=iw936i34g107ksaq5dqjbmrdsal4k4nn.narinfo error="server returned 404: 404 page not found\n"24462026/10/01 09:52:59 WARN Failed to register uploaded object key=i970lzfqq98hfsllaiv0k0160yfdjgp6.narinfo error="server returned 404: 404 page not found\n"24472026/10/01 09:52:59 WARN Failed to register uploaded object key=pvvn8byfv5vys7rb9bzb1950g5pdf52b.narinfo error="server returned 404: 404 page not found\n"24482026/10/01 09:52:59 OK 20260923120000_add_pushes.sql (13.95ms)24492026/10/01 09:52:59 goose: successfully migrated database to version: 2026092312000024502026/10/01 09:52:59 OK 1_commit_pending_closure.sql (989.38µs)24512026/10/01 09:52:59 OK 2_object_stats_trigger.sql (246.04µs)24522026/10/01 09:52:59 OK 3_commit_push.sql (188.33µs)24532026/10/01 09:52:59 goose: up to current file version: 324542026/10/01 09:52:59 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete24552026/10/01 09:52:59 WARN Failed to register uploaded object key=iw936i34g107ksaq5dqjbmrdsal4k4nn.narinfo error="server returned 404: 404 page not found\n"2456--- PASS: TestClientIntegration (10.13s)2457=== CONT TestService_AuthMiddleware_MTLSBoundSubjects24582026/10/01 09:52:59 INFO Completed upload id=124592026/10/01 09:52:59 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete24602026/10/01 09:52:59 INFO Completed upload id=224612026/10/01 09:52:59 INFO Upload complete. (260ms)2462=== NAME TestClientFallsBackToClosures2463 client_pushes_test.go:112: Retrieved narinfo from S3:2464 StorePath: /nix/var/nix/builds/nix-90547-3700828917/TestClientFallsBackToClosures4288605862/001/store/iw936i34g107ksaq5dqjbmrdsal4k4nn-shared-dep2465 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2466 Compression: zstd2467 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822468 NarSize: 1362469 References: 2470 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2471 client_pushes_test.go:112: Retrieved narinfo from S3:2472 StorePath: /nix/var/nix/builds/nix-90547-3700828917/TestClientFallsBackToClosures4288605862/001/store/pvvn8byfv5vys7rb9bzb1950g5pdf52b-a2473 URL: nar/0rqiwpmna7lvn2ai12gq32rdw0w60sfbf8c7n6j9ljm0qwh2xk43.nar.zst2474 Compression: zstd2475 NarHash: sha256:0rqiwpmna7lvn2ai12gq32rdw0w60sfbf8c7n6j9ljm0qwh2xk432476 NarSize: 2482477 References: /nix/var/nix/builds/nix-90547-3700828917/TestClientFallsBackToClosures4288605862/001/store/iw936i34g107ksaq5dqjbmrdsal4k4nn-shared-dep2478 CA: text:sha256:1vykdzmdp7dmiq751ijkn8q520nfm36zbla9hvqk80fzn484rbwr2479 client_pushes_test.go:112: Retrieved narinfo from S3:2480 StorePath: /nix/var/nix/builds/nix-90547-3700828917/TestClientFallsBackToClosures4288605862/001/store/i970lzfqq98hfsllaiv0k0160yfdjgp6-b2481 URL: nar/0rqiwpmna7lvn2ai12gq32rdw0w60sfbf8c7n6j9ljm0qwh2xk43.nar.zst2482 Compression: zstd2483 NarHash: sha256:0rqiwpmna7lvn2ai12gq32rdw0w60sfbf8c7n6j9ljm0qwh2xk432484 NarSize: 2482485 References: /nix/var/nix/builds/nix-90547-3700828917/TestClientFallsBackToClosures4288605862/001/store/iw936i34g107ksaq5dqjbmrdsal4k4nn-shared-dep2486 CA: text:sha256:1vykdzmdp7dmiq751ijkn8q520nfm36zbla9hvqk80fzn484rbwr24872026/10/01 09:52:59 OK 20241026095416_initial_model.sql (230.37ms)2488--- PASS: TestClientFallsBackToClosures (7.02s)24892026/10/01 09:52:59 OK 20251210153512_drop_unused_gin_index.sql (9.43ms)2490=== CONT TestService_AuthMiddleware_MTLSProxyHeader24912026-10-01 09:52:59.531 UTC [91660] ERROR: relation "goose_db_version" does not exist at character 3624922026-10-01 09:52:59.531 UTC [91660] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24932026/10/01 09:52:59 OK 20251218171726_add_pins.sql (14.54ms)24942026/10/01 09:52:59 OK 20260628120000_add_object_size_and_stats.sql (52.84ms)24952026/10/01 09:52:59 OK 20260905000000_add_claims.sql (41.35ms)24962026/10/01 09:52:59 OK 20260920000000_drop_claims.sql (39.16ms)24972026/10/01 09:52:59 OK 20260923120000_add_pushes.sql (47.32ms)24982026/10/01 09:52:59 goose: successfully migrated database to version: 2026092312000024992026/10/01 09:52:59 OK 20241026095416_initial_model.sql (144.74ms)25002026/10/01 09:52:59 OK 1_commit_pending_closure.sql (1.08ms)25012026/10/01 09:52:59 OK 2_object_stats_trigger.sql (245.5µs)25022026/10/01 09:52:59 OK 3_commit_push.sql (202.29µs)25032026/10/01 09:52:59 goose: up to current file version: 325042026/10/01 09:52:59 OK 20251210153512_drop_unused_gin_index.sql (12.44ms)25052026/10/01 09:52:59 OK 20251218171726_add_pins.sql (25.24ms)25062026/10/01 09:52:59 OK 20260628120000_add_object_size_and_stats.sql (42.46ms)25072026/10/01 09:52:59 INFO Received push request method=POST path=/api/pushes25082026/10/01 09:52:59 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)25092026/10/01 09:52:59 INFO Uploading m8vxiwdq7bs59js4b6rb2kxvcbjsv0hh-shared-dep (136B)25102026/10/01 09:52:59 INFO Uploading vxp2ki1gs0f3v0jqdkl9y877lb4px21i-b (248B)25112026/10/01 09:52:59 WARN Failed to register uploaded object key=0hicrg7yasgx39p3imvwv4g2dh6wgrnj.ls error="server returned 404: 404 page not found\n"25122026/10/01 09:52:59 WARN Failed to register uploaded object key=nar/0sicmqmnagxy9rnwrqlysqsajbr44gb8vr0pmkc5l3vaz8hn73hh.nar.zst error="server returned 404: 404 page not found\n"2513=== NAME TestPinProtectsFromGC2514 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-90547-3700828917/TestPinProtectsFromGC1185016483/001/store/nynyn91ss2mhv87xy61bd8m7zqvmvhx4-pinned-file.txt2515 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-90547-3700828917/TestPinProtectsFromGC1185016483/001/store/zw4xl1fwkwwmjhd3z65534s928b58dbf-unpinned-file.txt25162026/10/01 09:52:59 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"25172026/10/01 09:52:59 OK 20260905000000_add_claims.sql (70.09ms)25182026/10/01 09:52:59 WARN Failed to register uploaded object key=vxp2ki1gs0f3v0jqdkl9y877lb4px21i.ls error="server returned 404: 404 page not found\n"25192026/10/01 09:52:59 WARN Failed to register uploaded object key=m8vxiwdq7bs59js4b6rb2kxvcbjsv0hh.ls error="server returned 404: 404 page not found\n"25202026/10/01 09:52:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25212026/10/01 09:52:59 INFO Signed narinfos id=1 count=325222026/10/01 09:52:59 INFO Uploading 3 narinfos25232026/10/01 09:52:59 WARN Failed to register uploaded object key=vxp2ki1gs0f3v0jqdkl9y877lb4px21i.narinfo error="server returned 404: 404 page not found\n"25242026/10/01 09:52:59 INFO Received complete push request method=POST path=/api/pushes/1/complete25252026/10/01 09:52:59 WARN Failed to register uploaded object key=0hicrg7yasgx39p3imvwv4g2dh6wgrnj.narinfo error="server returned 404: 404 page not found\n"25262026/10/01 09:52:59 WARN Failed to register uploaded object key=m8vxiwdq7bs59js4b6rb2kxvcbjsv0hh.narinfo error="server returned 404: 404 page not found\n"25272026/10/01 09:52:59 OK 20260920000000_drop_claims.sql (85.69ms)25282026/10/01 09:52:59 INFO Upload complete. (223ms)2529=== NAME TestClientPushesUseOnePush2530 client_pushes_test.go:97: Retrieved narinfo from S3:2531 StorePath: /nix/var/nix/builds/nix-90547-3700828917/TestClientPushesUseOnePush3735754990/001/store/m8vxiwdq7bs59js4b6rb2kxvcbjsv0hh-shared-dep2532 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2533 Compression: zstd2534 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822535 NarSize: 1362536 References: 2537 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2538 client_pushes_test.go:97: Retrieved narinfo from S3:2539 StorePath: /nix/var/nix/builds/nix-90547-3700828917/TestClientPushesUseOnePush3735754990/001/store/0hicrg7yasgx39p3imvwv4g2dh6wgrnj-a2540 URL: nar/0sicmqmnagxy9rnwrqlysqsajbr44gb8vr0pmkc5l3vaz8hn73hh.nar.zst2541 Compression: zstd2542 NarHash: sha256:0sicmqmnagxy9rnwrqlysqsajbr44gb8vr0pmkc5l3vaz8hn73hh2543 NarSize: 2482544 References: /nix/var/nix/builds/nix-90547-3700828917/TestClientPushesUseOnePush3735754990/001/store/m8vxiwdq7bs59js4b6rb2kxvcbjsv0hh-shared-dep2545 CA: text:sha256:0sm799qwfpbddismbgdidagh0l30crjz6h8phggisnyllahchrq62546 client_pushes_test.go:97: Retrieved narinfo from S3:2547 StorePath: /nix/var/nix/builds/nix-90547-3700828917/TestClientPushesUseOnePush3735754990/001/store/vxp2ki1gs0f3v0jqdkl9y877lb4px21i-b2548 URL: nar/0sicmqmnagxy9rnwrqlysqsajbr44gb8vr0pmkc5l3vaz8hn73hh.nar.zst2549 Compression: zstd2550 NarHash: sha256:0sicmqmnagxy9rnwrqlysqsajbr44gb8vr0pmkc5l3vaz8hn73hh2551 NarSize: 2482552 References: /nix/var/nix/builds/nix-90547-3700828917/TestClientPushesUseOnePush3735754990/001/store/m8vxiwdq7bs59js4b6rb2kxvcbjsv0hh-shared-dep2553 CA: text:sha256:0sm799qwfpbddismbgdidagh0l30crjz6h8phggisnyllahchrq625542026/10/01 09:52:59 INFO Received push request method=POST path=/api/pushes25552026/10/01 09:52:59 OK 20260923120000_add_pushes.sql (26.17ms)25562026/10/01 09:52:59 goose: successfully migrated database to version: 2026092312000025572026/10/01 09:52:59 OK 1_commit_pending_closure.sql (980.29µs)25582026/10/01 09:52:59 OK 2_object_stats_trigger.sql (251.5µs)25592026/10/01 09:52:59 OK 3_commit_push.sql (186.75µs)25602026/10/01 09:52:59 goose: up to current file version: 325612026/10/01 09:53:00 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)25622026/10/01 09:53:00 INFO Uploading nynyn91ss2mhv87xy61bd8m7zqvmvhx4-pinned-file.txt (128B)2563--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (7.59s)2564=== CONT TestProxyWriteTimeout/narinfo2565=== CONT TestProxyWriteTimeout/unknown_size2566=== CONT TestProxyWriteTimeout/10_GiB_nar2567=== CONT TestProxyWriteTimeout/1_GiB_nar2568--- PASS: TestProxyWriteTimeout (0.00s)2569 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2570 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2571 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2572 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2573=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure25742026/10/01 09:53:00 INFO Received uploads request method=POST path=/25752026/10/01 09:53:00 WARN Failed to register uploaded object key=nynyn91ss2mhv87xy61bd8m7zqvmvhx4.ls error="server returned 404: 404 page not found\n"25762026/10/01 09:53:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25772026/10/01 09:53:00 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"25782026/10/01 09:53:00 INFO Signed narinfos id=1 count=125792026/10/01 09:53:00 INFO Uploading 1 narinfos2580--- PASS: TestClientPushesUseOnePush (6.33s)2581=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts25822026/10/01 09:53:00 INFO Received request for more parts method=POST path=/2583=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart25842026/10/01 09:53:00 INFO Received complete multipart upload request method=POST path=/25852026/10/01 09:53:00 INFO Received complete push request method=POST path=/api/pushes/1/complete25862026/10/01 09:53:00 WARN Failed to register uploaded object key=nynyn91ss2mhv87xy61bd8m7zqvmvhx4.narinfo error="server returned 404: 404 page not found\n"2587=== CONT TestPush_RejectsBadRequests/no_roots25882026/10/01 09:53:00 INFO Received push request method=POST path=/api/pushes2589=== CONT TestPush_RejectsBadRequests/bad_root25902026/10/01 09:53:00 INFO Received push request method=POST path=/api/pushes2591=== CONT TestPush_RejectsBadRequests/root_not_in_objects25922026/10/01 09:53:00 INFO Received push request method=POST path=/api/pushes2593=== CONT TestPush_RejectsBadRequests/no_objects25942026/10/01 09:53:00 INFO Received push request method=POST path=/api/pushes2595=== CONT TestIsValidCachePath/narinfo2596=== CONT TestIsValidCachePath/index.html2597=== CONT TestIsValidCachePath/nix-cache-info2598=== CONT TestIsValidCachePath/realisation2599--- PASS: TestPush_RejectsBadRequests (2.49s)2600 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2601 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2602 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2603 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2604=== CONT TestIsValidCachePath/traversal_parent2605=== CONT TestIsValidCachePath/log2606=== CONT TestIsValidCachePath/ls2607=== CONT TestIsValidCachePath/nar_uncompressed2608=== CONT TestIsValidCachePath/nar_bz22609=== CONT TestIsValidCachePath/nar_xz2610=== CONT TestIsValidCachePath/nar_zst2611=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2612=== CONT TestIsValidCachePath/empty2613=== CONT TestIsValidCachePath/short_hash2614=== CONT TestIsValidCachePath/wrong_extension2615=== CONT TestIsValidCachePath/leading_slash2616=== CONT TestIsValidCachePath/invalid_char_u2617=== CONT TestIsValidCachePath/random_path2618=== CONT TestIsValidCachePath/invalid_char_e2619=== CONT TestIsValidCachePath/traversal_in_middle2620--- PASS: TestIsValidCachePath (0.00s)2621 --- PASS: TestIsValidCachePath/narinfo (0.00s)2622 --- PASS: TestIsValidCachePath/index.html (0.00s)2623 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2624 --- PASS: TestIsValidCachePath/realisation (0.00s)2625 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2626 --- PASS: TestIsValidCachePath/log (0.00s)2627 --- PASS: TestIsValidCachePath/ls (0.00s)2628 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2629 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2630 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2631 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2632 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2633 --- PASS: TestIsValidCachePath/empty (0.00s)2634 --- PASS: TestIsValidCachePath/short_hash (0.00s)2635 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2636 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2637 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2638 --- PASS: TestIsValidCachePath/random_path (0.00s)2639 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2640 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2641=== CONT TestParseSingleRange/none2642=== CONT TestParseSingleRange/open-ended2643=== CONT TestParseSingleRange/start_far_past_EOF2644=== CONT TestParseSingleRange/start_past_EOF2645=== CONT TestParseSingleRange/suffix_exceeds_size2646=== CONT TestParseSingleRange/suffix2647=== CONT TestParseSingleRange/single_byte2648=== CONT TestParseSingleRange/end_clamped_to_size2649=== CONT TestParseSingleRange/malformed_both_empty2650=== CONT TestParseSingleRange/closed2651=== CONT TestParseSingleRange/malformed_end_before_start2652=== CONT TestParseSingleRange/multi-range_ignored2653=== CONT TestParseSingleRange/unknown_unit2654=== CONT TestParseSingleRange/malformed_no_dash2655--- PASS: TestParseSingleRange (0.00s)2656 --- PASS: TestParseSingleRange/none (0.00s)2657 --- PASS: TestParseSingleRange/open-ended (0.00s)2658 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2659 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2660 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2661 --- PASS: TestParseSingleRange/suffix (0.00s)2662 --- PASS: TestParseSingleRange/single_byte (0.00s)2663 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2664 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2665 --- PASS: TestParseSingleRange/closed (0.00s)2666 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2667 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2668 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2669 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2670=== CONT TestServerTLSConfig/no_client_CA2671=== CONT TestServerTLSConfig/not_a_PEM_file26722026/10/01 09:53:00 INFO Upload complete. (263ms)2673=== CONT TestServerTLSConfig/missing_CA_file2674--- PASS: TestServerTLSConfig (0.00s)2675 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2676 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.04s)2677 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2678=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows26792026/10/01 09:53:00 INFO Received push request method=POST path=/api/pushes26802026/10/01 09:53:00 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)26812026/10/01 09:53:00 INFO Uploading zw4xl1fwkwwmjhd3z65534s928b58dbf-unpinned-file.txt (128B)26822026/10/01 09:53:00 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"26832026/10/01 09:53:00 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign26842026/10/01 09:53:00 WARN Failed to register uploaded object key=zw4xl1fwkwwmjhd3z65534s928b58dbf.ls error="server returned 404: 404 page not found\n"26852026/10/01 09:53:00 INFO Signed narinfos id=2 count=126862026/10/01 09:53:00 INFO Uploading 1 narinfos26872026/10/01 09:53:00 INFO Received complete push request method=POST path=/api/pushes/2/complete26882026/10/01 09:53:00 WARN Failed to register uploaded object key=zw4xl1fwkwwmjhd3z65534s928b58dbf.narinfo error="server returned 404: 404 page not found\n"26892026/10/01 09:53:00 INFO Upload complete. (141ms)2690=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check2691--- PASS: TestUploadHandlersRejectOversizedBody (0.05s)2692 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)2693 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2694 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.29s)26952026/10/01 09:53:00 INFO Starting cleanup of old closures method=DELETE path=/api/closures26962026/10/01 09:53:00 INFO Garbage collection started26972026/10/01 09:53:00 INFO Aborted multipart uploads count=0 kept=026982026/10/01 09:53:00 WARN Force mode enabled - objects will be deleted immediately without grace period26992026/10/01 09:53:00 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=027002026/10/01 09:53:00 INFO Vacuumed table table=pending_closures27012026/10/01 09:53:00 INFO Vacuumed table table=pending_objects27022026/10/01 09:53:00 INFO Vacuumed table table=multipart_uploads27032026/10/01 09:53:00 INFO Vacuumed table table=closures27042026/10/01 09:53:00 INFO Received push request method=POST path=/api/pushes27052026/10/01 09:53:00 INFO Vacuumed table table=objects27062026/10/01 09:53:00 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)27072026/10/01 09:53:00 INFO Uploading gwind9466dsyjb5danfnwgmag5rwdmqy-shared-dep (136B)27082026/10/01 09:53:00 INFO Uploading p2vl9mgxikp26m4sdbvy25150clknppi-top (256B)2709--- PASS: TestService_ReadAuthMiddleware (4.67s)2710=== CONT TestIsValidUploadKey/narinfo2711=== CONT TestIsValidUploadKey/realisation_plus_in_output2712=== CONT TestIsValidUploadKey/unknown_type2713=== CONT TestIsValidUploadKey/empty_key2714=== CONT TestIsValidUploadKey/absolute2715=== CONT TestIsValidUploadKey/traversal_nar2716=== CONT TestIsValidUploadKey/traversal2717=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2718=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2719=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2720=== CONT TestIsValidUploadKey/index.html2721=== CONT TestIsValidUploadKey/nix-cache-info2722=== CONT TestIsValidUploadKey/build_log_home-manager_file2723=== CONT TestIsValidUploadKey/realisation2724=== CONT TestIsValidUploadKey/build_log_equals2725=== CONT TestIsValidUploadKey/build_log_question_mark2726=== CONT TestIsValidUploadKey/build_log_plus_in_name2727=== CONT TestIsValidUploadKey/nar_plain2728=== CONT TestIsValidUploadKey/build_log2729=== CONT TestIsValidUploadKey/listing2730=== CONT TestIsValidUploadKey/nar_xz2731=== CONT TestIsValidUploadKey/nar_zst2732--- PASS: TestIsValidUploadKey (0.00s)2733 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2734 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2735 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2736 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2737 --- PASS: TestIsValidUploadKey/absolute (0.00s)2738 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2739 --- PASS: TestIsValidUploadKey/traversal (0.00s)2740 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2741 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2742 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2743 --- PASS: TestIsValidUploadKey/index.html (0.00s)2744 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2745 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2746 --- PASS: TestIsValidUploadKey/realisation (0.00s)2747 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2748 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2749 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2750 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2751 --- PASS: TestIsValidUploadKey/build_log (0.00s)2752 --- PASS: TestIsValidUploadKey/listing (0.00s)2753 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2754 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2755=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info27562026/10/01 09:53:00 INFO Received uploads request method=POST path=/2757=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key27582026/10/01 09:53:00 INFO Received complete multipart upload request method=POST path=/2759=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key27602026/10/01 09:53:00 INFO Received request for more parts method=POST path=/2761=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal27622026/10/01 09:53:00 INFO Received uploads request method=POST path=/2763--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2764 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2765 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2766 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2767 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2768=== CONT TestResolveDBConnectionString/flag_wins2769=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2770=== CONT TestResolveDBConnectionString/nothing_configured2771=== CONT TestResolveDBConnectionString/missing_file_is_an_error2772=== CONT TestResolveDBConnectionString/file_when_flag_empty2773=== CONT TestClientErrorHandling/InvalidStorePath2774--- PASS: TestResolveDBConnectionString (0.04s)2775 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2776 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2777 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2778 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2779 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)27802026/10/01 09:53:00 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"27812026/10/01 09:53:00 WARN Failed to register uploaded object key=p2vl9mgxikp26m4sdbvy25150clknppi.ls error="server returned 404: 404 page not found\n"27822026/10/01 09:53:00 WARN Failed to register uploaded object key=gwind9466dsyjb5danfnwgmag5rwdmqy.ls error="server returned 404: 404 page not found\n"27832026/10/01 09:53:00 WARN Failed to register uploaded object key=nar/01n8yi6qmkyzm9mprqcrwy63s0cpgm8wwpyg8wb0wx18r3ilsbi2.nar.zst error="server returned 404: 404 page not found\n"27842026/10/01 09:53:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign27852026/10/01 09:53:00 INFO Signed narinfos id=1 count=227862026/10/01 09:53:00 INFO Uploading 2 narinfos27872026/10/01 09:53:00 WARN Failed to register uploaded object key=gwind9466dsyjb5danfnwgmag5rwdmqy.narinfo error="server returned 404: 404 page not found\n"27882026/10/01 09:53:00 INFO Received complete push request method=POST path=/api/pushes/1/complete27892026/10/01 09:53:00 WARN Failed to register uploaded object key=p2vl9mgxikp26m4sdbvy25150clknppi.narinfo error="server returned 404: 404 page not found\n"27902026/10/01 09:53:00 INFO Upload complete. (272ms)2791=== NAME TestClientSharedPathCommittedMidPush2792 client_integration_test.go:680: Retrieved narinfo from S3:2793 StorePath: /nix/var/nix/builds/nix-90547-3700828917/TestClientSharedPathCommittedMidPush2914405561/001/store/gwind9466dsyjb5danfnwgmag5rwdmqy-shared-dep2794 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2795 Compression: zstd2796 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822797 NarSize: 1362798 References: 2799 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2800 client_integration_test.go:680: Retrieved narinfo from S3:2801 StorePath: /nix/var/nix/builds/nix-90547-3700828917/TestClientSharedPathCommittedMidPush2914405561/001/store/p2vl9mgxikp26m4sdbvy25150clknppi-top2802 URL: nar/01n8yi6qmkyzm9mprqcrwy63s0cpgm8wwpyg8wb0wx18r3ilsbi2.nar.zst2803 Compression: zstd2804 NarHash: sha256:01n8yi6qmkyzm9mprqcrwy63s0cpgm8wwpyg8wb0wx18r3ilsbi22805 NarSize: 2562806 References: /nix/var/nix/builds/nix-90547-3700828917/TestClientSharedPathCommittedMidPush2914405561/001/store/gwind9466dsyjb5danfnwgmag5rwdmqy-shared-dep2807 CA: text:sha256:16580x8rj5fikzkc6czpm9qfi5qnq2f923r2bm0af56myvh182g02808--- PASS: TestClientSharedPathCommittedMidPush (6.49s)2809=== CONT TestClientErrorHandling/ServerNotAvailable2810=== NAME TestClientWithDependencies2811 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-90547-3700828917/TestClientWithDependencies2948283604/001/store/6xr0m4wrvxv6wgnv7zkmdw5pqxisrfaf-test-script2812 client_integration_test.go:615: Found 1 dependencies (including self)28132026/10/01 09:53:01 INFO Received push request method=POST path=/api/pushes28142026-10-01 09:53:01.373 UTC [91746] ERROR: relation "goose_db_version" does not exist at character 3628152026-10-01 09:53:01.373 UTC [91746] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28162026/10/01 09:53:01 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)28172026/10/01 09:53:01 INFO Uploading 6xr0m4wrvxv6wgnv7zkmdw5pqxisrfaf-test-script (136B)28182026/10/01 09:53:01 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28192026/10/01 09:53:01 WARN Failed to register uploaded object key=6xr0m4wrvxv6wgnv7zkmdw5pqxisrfaf.ls error="server returned 404: 404 page not found\n"28202026/10/01 09:53:01 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"28212026/10/01 09:53:01 WARN Failed to register uploaded object key=log/zjaqd0ay1i6s1v1csnw1cakyrvjm7ng9-test-script.drv error="server returned 404: 404 page not found\n"28222026/10/01 09:53:01 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign28232026/10/01 09:53:01 INFO Signed narinfos id=1 count=128242026/10/01 09:53:01 INFO Uploading 1 narinfos28252026/10/01 09:53:01 INFO Received complete push request method=POST path=/api/pushes/1/complete28262026/10/01 09:53:01 WARN Failed to register uploaded object key=6xr0m4wrvxv6wgnv7zkmdw5pqxisrfaf.narinfo error="server returned 404: 404 page not found\n"28272026/10/01 09:53:01 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=192.852035ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28282026/10/01 09:53:01 INFO Upload complete. (320ms)2829 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-90547-3700828917/TestClientWithDependencies2948283604/001/store) requires matching store prefix2830--- PASS: TestClientWithDependencies (6.48s)2831=== CONT TestClientErrorHandling/InvalidAuthToken28322026/10/01 09:53:01 OK 20241026095416_initial_model.sql (290.71ms)28332026/10/01 09:53:01 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=428.196517ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28342026/10/01 09:53:01 OK 20251210153512_drop_unused_gin_index.sql (11.3ms)28352026/10/01 09:53:01 OK 20251218171726_add_pins.sql (36.58ms)28362026/10/01 09:53:01 OK 20260628120000_add_object_size_and_stats.sql (50.35ms)28372026/10/01 09:53:01 OK 20260905000000_add_claims.sql (61.75ms)28382026/10/01 09:53:01 OK 20260920000000_drop_claims.sql (47.27ms)28392026/10/01 09:53:01 OK 20260923120000_add_pushes.sql (4.12ms)28402026/10/01 09:53:01 goose: successfully migrated database to version: 2026092312000028412026/10/01 09:53:01 OK 1_commit_pending_closure.sql (1.27ms)28422026/10/01 09:53:01 OK 2_object_stats_trigger.sql (364.54µs)28432026/10/01 09:53:01 OK 3_commit_push.sql (763.04µs)28442026/10/01 09:53:01 goose: up to current file version: 328452026/10/01 09:53:02 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=774.122621ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2846=== RUN TestService_RequireScope_OIDC/builder_may_write2847=== PAUSE TestService_RequireScope_OIDC/builder_may_write2848=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2849=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2850=== RUN TestService_RequireScope_OIDC/ops_may_admin2851=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2852=== RUN TestService_RequireScope_OIDC/ops_may_not_write2853=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2854=== RUN TestService_RequireScope_OIDC/reader_may_not_write2855=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2856=== RUN TestService_RequireScope_OIDC/static_token_may_admin2857=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2858=== RUN TestService_RequireScope_OIDC/static_token_may_write2859=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2860=== RUN TestService_RequireScope_OIDC/reader_may_read2861=== PAUSE TestService_RequireScope_OIDC/reader_may_read2862=== RUN TestService_RequireScope_OIDC/writer_implies_read2863=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2864=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2865=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2866=== CONT TestCacheConfigHandler/full_config,_no_issuer2867=== CONT TestCacheConfigHandler/no_signing_keys2868=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2869=== CONT TestCacheConfigHandler/no_cache_url_configured2870--- PASS: TestCacheConfigHandler (0.00s)2871 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2872 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2873 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2874 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2875=== CONT TestService_RequireScope_OIDC/builder_may_write2876=== CONT TestService_RequireScope_OIDC/static_token_may_admin2877=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2878=== CONT TestService_RequireScope_OIDC/writer_implies_read2879=== CONT TestService_RequireScope_OIDC/reader_may_read2880=== CONT TestService_RequireScope_OIDC/static_token_may_write2881=== CONT TestService_RequireScope_OIDC/ops_may_not_write2882=== CONT TestService_RequireScope_OIDC/reader_may_not_write2883=== CONT TestService_RequireScope_OIDC/ops_may_admin2884=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2885--- PASS: TestService_RequireScope_OIDC (4.38s)2886 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2887 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2888 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2889 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2890 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2891 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2892 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2893 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2894 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2895 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)28962026/10/01 09:53:02 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=028972026/10/01 09:53:02 INFO Received create pin request method=POST path=/api/pins/myapp28982026-10-01 09:53:02.451 UTC [91775] ERROR: relation "goose_db_version" does not exist at character 3628992026-10-01 09:53:02.451 UTC [91775] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29002026/10/01 09:53:02 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-90547-3700828917/TestPinProtectsFromGC1185016483/001/store/nynyn91ss2mhv87xy61bd8m7zqvmvhx4-pinned-file.txt narinfo_key=nynyn91ss2mhv87xy61bd8m7zqvmvhx4.narinfo29012026/10/01 09:53:02 INFO Starting cleanup of old closures method=DELETE path=/api/closures29022026/10/01 09:53:02 INFO Garbage collection started29032026/10/01 09:53:02 INFO Aborted multipart uploads count=0 kept=029042026/10/01 09:53:02 WARN Force mode enabled - objects will be deleted immediately without grace period29052026/10/01 09:53: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=029062026/10/01 09:53:02 INFO Vacuumed table table=pending_closures29072026/10/01 09:53:02 INFO Vacuumed table table=pending_objects29082026/10/01 09:53:02 INFO Vacuumed table table=multipart_uploads29092026/10/01 09:53:02 INFO Vacuumed table table=closures29102026/10/01 09:53:02 INFO Vacuumed table table=objects29112026-10-01 09:53:02.675 UTC [91781] ERROR: relation "goose_db_version" does not exist at character 3629122026-10-01 09:53:02.675 UTC [91781] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29132026/10/01 09:53:02 OK 20241026095416_initial_model.sql (226.65ms)29142026/10/01 09:53:02 OK 20251210153512_drop_unused_gin_index.sql (10.49ms)29152026-10-01 09:53:02.817 UTC [91796] ERROR: relation "goose_db_version" does not exist at character 3629162026-10-01 09:53:02.817 UTC [91796] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29172026/10/01 09:53:02 OK 20251218171726_add_pins.sql (44.26ms)29182026/10/01 09:53:02 OK 20260628120000_add_object_size_and_stats.sql (44.82ms)29192026/10/01 09:53:02 OK 20260905000000_add_claims.sql (64.61ms)29202026/10/01 09:53:02 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.58369408s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29212026/10/01 09:53:02 OK 20241026095416_initial_model.sql (214.45ms)29222026/10/01 09:53:02 OK 20251210153512_drop_unused_gin_index.sql (15.73ms)29232026/10/01 09:53:03 OK 20260920000000_drop_claims.sql (102.04ms)29242026/10/01 09:53:03 OK 20251218171726_add_pins.sql (46.54ms)29252026/10/01 09:53:03 OK 20260923120000_add_pushes.sql (12.22ms)29262026/10/01 09:53:03 goose: successfully migrated database to version: 2026092312000029272026/10/01 09:53:03 OK 1_commit_pending_closure.sql (957.42µs)29282026/10/01 09:53:03 OK 2_object_stats_trigger.sql (221.33µs)29292026/10/01 09:53:03 OK 3_commit_push.sql (188.67µs)29302026/10/01 09:53:03 goose: up to current file version: 329312026/10/01 09:53:03 OK 20260628120000_add_object_size_and_stats.sql (45.6ms)29322026/10/01 09:53:03 OK 20241026095416_initial_model.sql (269.62ms)29332026/10/01 09:53:03 OK 20260905000000_add_claims.sql (85.58ms)29342026/10/01 09:53:03 OK 20251210153512_drop_unused_gin_index.sql (23.02ms)29352026/10/01 09:53:03 OK 20260920000000_drop_claims.sql (55.97ms)29362026/10/01 09:53:03 OK 20251218171726_add_pins.sql (41.75ms)29372026/10/01 09:53:03 OK 20260923120000_add_pushes.sql (14.61ms)29382026/10/01 09:53:03 goose: successfully migrated database to version: 2026092312000029392026/10/01 09:53:03 OK 1_commit_pending_closure.sql (1.13ms)29402026/10/01 09:53:03 OK 2_object_stats_trigger.sql (268.92µs)29412026/10/01 09:53:03 OK 3_commit_push.sql (205.88µs)29422026/10/01 09:53:03 goose: up to current file version: 329432026/10/01 09:53:03 OK 20260628120000_add_object_size_and_stats.sql (52.66ms)29442026/10/01 09:53:03 OK 20260905000000_add_claims.sql (126.09ms)2945=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2946=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2947=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2948=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2949=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2950=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2951=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2952=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2953=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2954=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected29552026/10/01 09:53: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]2956=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2957=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured29582026/10/01 09:53:03 WARN Authentication failed token_preview=eyJhbGciOi...G5RcSYYPtw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]29592026/10/01 09:53:03 OK 20260920000000_drop_claims.sql (107.55ms)2960--- PASS: TestService_AuthMiddleware_OIDC (4.33s)2961 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2962 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2963 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2964 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)29652026/10/01 09:53:03 OK 20260923120000_add_pushes.sql (36.36ms)29662026/10/01 09:53:03 goose: successfully migrated database to version: 2026092312000029672026/10/01 09:53:03 OK 1_commit_pending_closure.sql (1.08ms)29682026/10/01 09:53:03 OK 2_object_stats_trigger.sql (267.29µs)29692026/10/01 09:53:03 OK 3_commit_push.sql (219.67µs)29702026/10/01 09:53:03 goose: up to current file version: 329712026/10/01 09:53:03 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"29722026/10/01 09:53:03 WARN mTLS auth: bound subjects configured but subject DN unavailable29732026/10/01 09:53:03 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2974--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (4.48s)29752026-10-01 09:53:04.004 UTC [91807] ERROR: relation "goose_db_version" does not exist at character 3629762026-10-01 09:53:04.004 UTC [91807] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29772026-10-01 09:53:04.191 UTC [91808] ERROR: relation "goose_db_version" does not exist at character 3629782026-10-01 09:53:04.191 UTC [91808] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2979--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (4.84s)29802026/10/01 09:53:04 OK 20241026095416_initial_model.sql (274.81ms)29812026-10-01 09:53:04.431 UTC [91814] ERROR: relation "goose_db_version" does not exist at character 3629822026-10-01 09:53:04.431 UTC [91814] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29832026/10/01 09:53:04 OK 20251210153512_drop_unused_gin_index.sql (2.03ms)29842026/10/01 09:53:04 OK 20241026095416_initial_model.sql (159.81ms)29852026/10/01 09:53:04 OK 20251210153512_drop_unused_gin_index.sql (12.97ms)2986=== NAME TestPinProtectsFromGC2987 client_integration_test.go:840: Pin successfully protected closure from garbage collection29882026/10/01 09:53:04 OK 20251218171726_add_pins.sql (26.23ms)29892026/10/01 09:53:04 OK 20251218171726_add_pins.sql (25.08ms)29902026/10/01 09:53:04 OK 20260628120000_add_object_size_and_stats.sql (26.93ms)29912026/10/01 09:53:04 OK 20260628120000_add_object_size_and_stats.sql (14.47ms)2992--- PASS: TestPinProtectsFromGC (10.57s)29932026/10/01 09:53:04 OK 20260905000000_add_claims.sql (41.22ms)29942026/10/01 09:53:04 OK 20260905000000_add_claims.sql (42.04ms)29952026/10/01 09:53:04 OK 20260920000000_drop_claims.sql (15.1ms)29962026/10/01 09:53:04 OK 20260920000000_drop_claims.sql (15.55ms)29972026/10/01 09:53:04 OK 20260923120000_add_pushes.sql (3.77ms)29982026/10/01 09:53:04 goose: successfully migrated database to version: 2026092312000029992026/10/01 09:53:04 OK 20260923120000_add_pushes.sql (4.25ms)30002026/10/01 09:53:04 goose: successfully migrated database to version: 2026092312000030012026/10/01 09:53:04 OK 1_commit_pending_closure.sql (2.82ms)30022026/10/01 09:53:04 OK 20241026095416_initial_model.sql (67.43ms)30032026/10/01 09:53:04 OK 1_commit_pending_closure.sql (6.35ms)30042026/10/01 09:53:04 OK 2_object_stats_trigger.sql (2.18ms)30052026/10/01 09:53:04 OK 2_object_stats_trigger.sql (1.23ms)30062026/10/01 09:53:04 OK 20251210153512_drop_unused_gin_index.sql (2.63ms)30072026/10/01 09:53:04 OK 3_commit_push.sql (1.57ms)30082026/10/01 09:53:04 goose: up to current file version: 330092026-10-01 09:53:04.556 UTC [91821] ERROR: relation "goose_db_version" does not exist at character 3630102026-10-01 09:53:04.556 UTC [91821] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC30112026/10/01 09:53:04 OK 3_commit_push.sql (1.44ms)30122026/10/01 09:53:04 goose: up to current file version: 330132026/10/01 09:53:04 OK 20251218171726_add_pins.sql (66.11ms)30142026/10/01 09:53:04 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-config30152026/10/01 09:53:04 OK 20260628120000_add_object_size_and_stats.sql (43.24ms)30162026/10/01 09:53:04 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=209.190123ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30172026/10/01 09:53:04 OK 20260905000000_add_claims.sql (105.26ms)30182026/10/01 09:53:04 OK 20260920000000_drop_claims.sql (58.27ms)30192026/10/01 09:53:04 OK 20260923120000_add_pushes.sql (22.91ms)30202026/10/01 09:53:04 goose: successfully migrated database to version: 2026092312000030212026/10/01 09:53:04 OK 1_commit_pending_closure.sql (3.04ms)30222026/10/01 09:53:04 OK 2_object_stats_trigger.sql (605.88µs)30232026/10/01 09:53:04 OK 3_commit_push.sql (382.46µs)30242026/10/01 09:53:04 goose: up to current file version: 330252026/10/01 09:53:04 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=421.877522ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30262026/10/01 09:53:05 OK 20241026095416_initial_model.sql (350.35ms)30272026/10/01 09:53:05 OK 20251210153512_drop_unused_gin_index.sql (10.39ms)30282026/10/01 09:53:05 OK 20251218171726_add_pins.sql (60.36ms)30292026/10/01 09:53:05 INFO Received uploads request method=POST path=/api/pending_closures30302026/10/01 09:53:05 OK 20260628120000_add_object_size_and_stats.sql (55.56ms)30312026/10/01 09:53:05 INFO Aborted multipart uploads count=0 kept=030322026/10/01 09:53:05 WARN Force mode enabled - objects will be deleted immediately without grace period30332026/10/01 09:53:05 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=030342026/10/01 09:53:05 INFO Vacuumed table table=pending_closures30352026/10/01 09:53:05 OK 20260905000000_add_claims.sql (123.58ms)30362026/10/01 09:53:05 INFO Vacuumed table table=pending_objects30372026/10/01 09:53:05 INFO Vacuumed table table=multipart_uploads30382026/10/01 09:53:05 INFO Vacuumed table table=closures30392026/10/01 09:53:05 INFO Vacuumed table table=objects30402026/10/01 09:53:05 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=725.3487ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30412026/10/01 09:53:05 OK 20260920000000_drop_claims.sql (147.17ms)30422026/10/01 09:53:05 OK 20260923120000_add_pushes.sql (20.4ms)30432026/10/01 09:53:05 goose: successfully migrated database to version: 2026092312000030442026/10/01 09:53:05 OK 1_commit_pending_closure.sql (1.72ms)30452026/10/01 09:53:05 OK 2_object_stats_trigger.sql (463.42µs)30462026/10/01 09:53:05 OK 3_commit_push.sql (344.33µs)30472026/10/01 09:53:05 goose: up to current file version: 330482026/10/01 09:53:05 INFO Received uploads request method=POST path=/api/pending_closures30492026/10/01 09:53:05 INFO Aborted multipart uploads count=0 kept=030502026/10/01 09:53:05 WARN Force mode enabled - objects will be deleted immediately without grace period30512026/10/01 09:53:05 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=030522026/10/01 09:53:05 INFO Vacuumed table table=pending_closures30532026/10/01 09:53:05 INFO Vacuumed table table=pending_objects30542026/10/01 09:53:05 INFO Vacuumed table table=multipart_uploads30552026/10/01 09:53:05 INFO Vacuumed table table=closures30562026/10/01 09:53:05 INFO Vacuumed table table=objects3057--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)3058 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (5.09s)3059 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (5.77s)30602026/10/01 09:53:06 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.605686827s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30612026/10/01 09:53:07 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30622026/10/01 09:53:07 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30632026/10/01 09:53:07 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"30642026/10/01 09:53:07 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-config30652026/10/01 09:53:07 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=185.372421ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30662026/10/01 09:53:07 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=368.777274ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30672026/10/01 09:53:08 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=848.354203ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30682026/10/01 09:53:09 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.539028733s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30692026/10/01 09:53:10 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_closures30702026/10/01 09:53:10 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=206.996675ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30712026/10/01 09:53:11 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=394.090864ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30722026/10/01 09:53:11 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=780.145768ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30732026/10/01 09:53:12 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.738311931s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures3074--- PASS: TestClientErrorHandling (0.00s)3075 --- PASS: TestClientErrorHandling/InvalidStorePath (5.40s)3076 --- PASS: TestClientErrorHandling/InvalidAuthToken (5.52s)3077 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.02s)3078PASS3079{"timestamp":"2026-10-01T09:53:14.036892Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:55154","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}30802026-10-01 09:53:14.199 UTC [90737] LOG: received smart shutdown request30812026-10-01 09:53:14.200 UTC [90737] LOG: background worker "logical replication launcher" (PID 90747) exited with exit code 130822026-10-01 09:53:14.203 UTC [90742] LOG: shutting down30832026-10-01 09:53:14.203 UTC [90742] LOG: checkpoint starting: shutdown immediate30842026-10-01 09:53:15.380 UTC [90742] LOG: checkpoint complete: wrote 12975 buffers (79.2%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 25 recycled; write=0.644 s, sync=0.496 s, total=1.178 s; sync files=28653, longest=0.001 s, average=0.001 s; distance=403358 kB, estimate=403358 kB; lsn=0/1A174920, redo lsn=0/1A17492030852026-10-01 09:53:15.386 UTC [90737] LOG: database system is shut down3086Running OIDC tests...3087=== RUN TestAudienceForIssuer3088=== PAUSE TestAudienceForIssuer3089=== RUN TestGlobMatch3090=== PAUSE TestGlobMatch3091=== RUN TestValidateToken_ValidToken3092=== PAUSE TestValidateToken_ValidToken3093=== RUN TestValidateToken_WrongAudience3094=== PAUSE TestValidateToken_WrongAudience3095=== RUN TestValidateToken_Expired3096=== PAUSE TestValidateToken_Expired3097=== RUN TestValidateToken_BoundClaimsMismatch3098=== PAUSE TestValidateToken_BoundClaimsMismatch3099=== RUN TestValidateToken_BoundSubjectMismatch3100=== PAUSE TestValidateToken_BoundSubjectMismatch3101=== RUN TestValidateToken_MultipleProviders3102=== PAUSE TestValidateToken_MultipleProviders3103=== RUN TestValidateToken_NoMatchingProvider3104=== PAUSE TestValidateToken_NoMatchingProvider3105=== RUN TestValidateToken_KubernetesServiceAccount3106=== PAUSE TestValidateToken_KubernetesServiceAccount3107=== RUN TestNewValidator_KubernetesRequiresCA3108=== PAUSE TestNewValidator_KubernetesRequiresCA3109=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3110=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3111=== RUN TestPins_ReservedForMatchingRule3112=== PAUSE TestPins_ReservedForMatchingRule3113=== RUN TestPins_TopLevelShorthand3114=== PAUSE TestPins_TopLevelShorthand3115=== RUN TestPins_ConfigValidation3116=== PAUSE TestPins_ConfigValidation3117=== RUN TestScopes_LegacyProviderDefaultsToWrite3118=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3119=== RUN TestScopes_Rules3120=== PAUSE TestScopes_Rules3121=== RUN TestScopes_ConfigValidation3122=== PAUSE TestScopes_ConfigValidation3123=== CONT TestAudienceForIssuer3124--- PASS: TestAudienceForIssuer (0.00s)3125=== CONT TestValidateToken_NoMatchingProvider3126=== CONT TestPins_ConfigValidation3127=== CONT TestValidateToken_KubernetesServiceAccount3128=== CONT TestPins_ReservedForMatchingRule3129=== CONT TestScopes_LegacyProviderDefaultsToWrite3130=== CONT TestScopes_Rules3131=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3132=== CONT TestValidateToken_Expired3133=== CONT TestNewValidator_KubernetesRequiresCA3134=== CONT TestValidateToken_ValidToken3135--- PASS: TestPins_ConfigValidation (0.01s)3136=== CONT TestScopes_ConfigValidation3137--- PASS: TestScopes_ConfigValidation (0.01s)3138=== CONT TestPins_TopLevelShorthand31392026/10/01 09:53:19 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56138/oidc3140--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.06s)3141=== CONT TestGlobMatch3142=== RUN TestGlobMatch/foo_foo3143=== PAUSE TestGlobMatch/foo_foo3144=== RUN TestGlobMatch/foo_bar3145=== PAUSE TestGlobMatch/foo_bar3146=== RUN TestGlobMatch/*_3147=== PAUSE TestGlobMatch/*_3148=== RUN TestGlobMatch/*_anything3149=== PAUSE TestGlobMatch/*_anything3150=== RUN TestGlobMatch/foo*_foo3151=== PAUSE TestGlobMatch/foo*_foo3152=== RUN TestGlobMatch/foo*_foobar3153=== PAUSE TestGlobMatch/foo*_foobar3154=== RUN TestGlobMatch/foo*_bar3155=== PAUSE TestGlobMatch/foo*_bar3156=== RUN TestGlobMatch/*bar_bar3157=== PAUSE TestGlobMatch/*bar_bar3158=== RUN TestGlobMatch/*bar_foobar3159=== PAUSE TestGlobMatch/*bar_foobar3160=== RUN TestGlobMatch/*bar_foo3161=== PAUSE TestGlobMatch/*bar_foo3162=== RUN TestGlobMatch/foo*bar_foobar3163=== PAUSE TestGlobMatch/foo*bar_foobar3164=== RUN TestGlobMatch/foo*bar_foo123bar3165=== PAUSE TestGlobMatch/foo*bar_foo123bar3166=== RUN TestGlobMatch/foo*bar_foobarbaz3167=== PAUSE TestGlobMatch/foo*bar_foobarbaz3168=== RUN TestGlobMatch/*/*_foo/bar3169=== PAUSE TestGlobMatch/*/*_foo/bar3170=== RUN TestGlobMatch/*/*_foo3171=== PAUSE TestGlobMatch/*/*_foo3172=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3173=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3174=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03175=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03176=== RUN TestGlobMatch/refs/*/main_refs/heads/main3177=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3178=== RUN TestGlobMatch/fo?_foo3179=== PAUSE TestGlobMatch/fo?_foo3180=== RUN TestGlobMatch/fo?_fo3181=== PAUSE TestGlobMatch/fo?_fo3182=== RUN TestGlobMatch/fo?_fooo3183=== PAUSE TestGlobMatch/fo?_fooo3184=== RUN TestGlobMatch/?oo_foo3185=== PAUSE TestGlobMatch/?oo_foo3186=== RUN TestGlobMatch/?oo_boo3187=== PAUSE TestGlobMatch/?oo_boo3188=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3189=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3190=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3191=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/my2026/10/01 09:53:19 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56140/oidc3192repo:ref:refs/heads/main3193=== CONT TestValidateToken_BoundSubjectMismatch3194--- PASS: TestPins_ReservedForMatchingRule (0.07s)3195=== CONT TestValidateToken_MultipleProviders31962026/10/01 09:53:19 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:56137/oidc3197--- PASS: TestValidateToken_NoMatchingProvider (0.08s)3198=== CONT TestValidateToken_BoundClaimsMismatch31992026/10/01 09:53:19 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56145/oidc3200--- PASS: TestPins_TopLevelShorthand (0.09s)3201=== CONT TestValidateToken_WrongAudience32022026/10/01 09:53:19 http: TLS handshake error from 127.0.0.1:56147: remote error: tls: bad certificate3203--- PASS: TestNewValidator_KubernetesRequiresCA (0.11s)3204=== CONT TestGlobMatch/foo_foo3205=== CONT TestGlobMatch/*/*_foo/bar3206=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3207=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3208=== CONT TestGlobMatch/?oo_boo3209=== CONT TestGlobMatch/?oo_foo3210=== CONT TestGlobMatch/fo?_fooo3211=== CONT TestGlobMatch/fo?_fo3212=== CONT TestGlobMatch/fo?_foo3213=== CONT TestGlobMatch/refs/*/main_refs/heads/main3214=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03215=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3216=== CONT TestGlobMatch/*/*_foo3217=== CONT TestGlobMatch/*bar_bar3218=== CONT TestGlobMatch/foo*bar_foobarbaz32192026/10/01 09:53:19 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1233220=== CONT TestGlobMatch/foo*bar_foo123bar3221=== CONT TestGlobMatch/foo*bar_foobar3222=== CONT TestGlobMatch/*bar_foo3223=== CONT TestGlobMatch/*bar_foobar3224=== CONT TestGlobMatch/foo*_foo3225=== CONT TestGlobMatch/foo*_bar3226=== CONT TestGlobMatch/foo*_foobar3227=== CONT TestGlobMatch/*_3228=== CONT TestGlobMatch/*_anything3229=== CONT TestGlobMatch/foo_bar3230--- PASS: TestGlobMatch (0.00s)3231 --- PASS: TestGlobMatch/foo_foo (0.00s)3232 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3233 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3234 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3235 --- PASS: TestGlobMatch/?oo_boo (0.00s)3236 --- PASS: TestGlobMatch/?oo_foo (0.00s)3237 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3238 --- PASS: TestGlobMatch/fo?_fo (0.00s)3239 --- PASS: TestGlobMatch/fo?_foo (0.00s)3240 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3241 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3242 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3243 --- PASS: TestGlobMatch/*/*_foo (0.00s)3244 --- PASS: TestGlobMatch/*bar_bar (0.00s)3245 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3246 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3247 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3248 --- PASS: TestGlobMatch/*bar_foo (0.00s)3249 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3250 --- PASS: TestGlobMatch/foo*_foo (0.00s)3251 --- PASS: TestGlobMatch/foo*_bar (0.00s)3252 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3253 --- PASS: TestGlobMatch/*_ (0.00s)3254 --- PASS: TestGlobMatch/*_anything (0.00s)3255 --- PASS: TestGlobMatch/foo_bar (0.00s)3256--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.11s)32572026/10/01 09:53:19 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56151/oidc32582026/10/01 09:53:19 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56150/oidc3259--- PASS: TestValidateToken_Expired (0.13s)3260--- PASS: TestValidateToken_ValidToken (0.13s)32612026/10/01 09:53:19 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56154/oidc3262--- PASS: TestScopes_Rules (0.16s)32632026/10/01 09:53:19 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56156/oidc32642026/10/01 09:53:19 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56157/oidc3265--- PASS: TestValidateToken_WrongAudience (0.06s)3266--- PASS: TestValidateToken_BoundClaimsMismatch (0.08s)32672026/10/01 09:53:19 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:561603268--- PASS: TestValidateToken_KubernetesServiceAccount (0.17s)32692026/10/01 09:53:19 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56163/oidc3270--- PASS: TestValidateToken_BoundSubjectMismatch (0.16s)32712026/10/01 09:53:19 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:56162/oidc32722026/10/01 09:53:19 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:56165/oidc3273--- PASS: TestValidateToken_MultipleProviders (0.15s)3274PASS3275Running hook tests...3276=== RUN TestSendPathsEmpty3277=== PAUSE TestSendPathsEmpty3278=== RUN TestQueueEnqueueAndFetch3279=== PAUSE TestQueueEnqueueAndFetch3280=== RUN TestQueueDeduplication3281=== PAUSE TestQueueDeduplication3282=== RUN TestQueueRemove3283=== PAUSE TestQueueRemove3284=== RUN TestQueueFetchBatchLimit3285=== PAUSE TestQueueFetchBatchLimit3286=== RUN TestQueueRetryMovesToBack3287=== PAUSE TestQueueRetryMovesToBack3288=== RUN TestQueueFetchRemoveLifecycle3289=== PAUSE TestQueueFetchRemoveLifecycle3290=== RUN TestQueueConcurrentWriters3291=== PAUSE TestQueueConcurrentWriters3292=== RUN TestQueueRemoveLargeClosure3293=== PAUSE TestQueueRemoveLargeClosure3294=== RUN TestServerClientIntegration3295=== PAUSE TestServerClientIntegration3296=== RUN TestServerQueueError3297=== PAUSE TestServerQueueError3298=== RUN TestGetListenerSocketActivation3299 server_test.go:210: === RUN TestGetListenerSocketActivation3300 --- PASS: TestGetListenerSocketActivation (0.00s)3301 PASS3302 3303--- PASS: TestGetListenerSocketActivation (0.01s)3304=== RUN TestDrainIsolatesPoisonPath3305=== PAUSE TestDrainIsolatesPoisonPath3306=== RUN TestRunNotBlockedByPoisonHead3307=== PAUSE TestRunNotBlockedByPoisonHead3308=== RUN TestDrainGivesUpWhenServerDown3309=== PAUSE TestDrainGivesUpWhenServerDown3310=== RUN TestFailedPathPrunedByLaterClosure3311=== PAUSE TestFailedPathPrunedByLaterClosure3312=== RUN TestWorkerUploadsAndRemoves3313=== PAUSE TestWorkerUploadsAndRemoves3314=== RUN TestWorkerSkipsGCdPaths3315=== PAUSE TestWorkerSkipsGCdPaths3316=== RUN TestWorkerPrunesClosureDeps3317=== PAUSE TestWorkerPrunesClosureDeps3318=== RUN TestDrainTimeout3319=== PAUSE TestDrainTimeout3320=== CONT TestSendPathsEmpty3321--- PASS: TestSendPathsEmpty (0.00s)3322=== CONT TestDrainTimeout3323=== CONT TestServerClientIntegration3324=== CONT TestFailedPathPrunedByLaterClosure3325=== CONT TestQueueRetryMovesToBack3326=== CONT TestQueueConcurrentWriters3327=== CONT TestQueueRemoveLargeClosure3328=== CONT TestQueueFetchRemoveLifecycle3329=== CONT TestQueueRemove3330=== CONT TestWorkerUploadsAndRemoves3331=== CONT TestQueueFetchBatchLimit3332--- PASS: TestServerClientIntegration (0.00s)3333=== CONT TestQueueDeduplication33342026/10/01 09:53:20 INFO Upload queue status pending=233352026/10/01 09:53:20 INFO Uploading batch count=23336--- PASS: TestQueueRemove (0.04s)3337=== CONT TestDrainGivesUpWhenServerDown3338--- PASS: TestQueueFetchBatchLimit (0.03s)3339=== CONT TestRunNotBlockedByPoisonHead33402026/10/01 09:53:20 INFO Uploading batch count=133412026/10/01 09:53:20 ERROR Upload failed error="upload failed" count=133422026/10/01 09:53:20 INFO Uploading batch count=23343--- PASS: TestQueueFetchRemoveLifecycle (0.04s)3344=== CONT TestDrainIsolatesPoisonPath33452026/10/01 09:53:20 INFO Uploading batch count=133462026/10/01 09:53:20 INFO Uploading batch count=13347--- PASS: TestQueueDeduplication (0.05s)3348=== CONT TestServerQueueError3349--- PASS: TestQueueRetryMovesToBack (0.05s)3350=== CONT TestWorkerPrunesClosureDeps33512026/10/01 09:53:20 ERROR Failed to queue paths error="permission denied" count=13352--- PASS: TestServerQueueError (0.00s)3353=== CONT TestQueueEnqueueAndFetch3354--- PASS: TestWorkerUploadsAndRemoves (0.05s)3355=== CONT TestWorkerSkipsGCdPaths3356--- PASS: TestFailedPathPrunedByLaterClosure (0.06s)33572026/10/01 09:53:20 INFO Upload queue status pending=333582026/10/01 09:53:20 INFO Uploading batch count=133592026/10/01 09:53:20 ERROR Upload failed error="upload failed" count=133602026/10/01 09:53:20 INFO Uploading batch count=433612026/10/01 09:53:20 ERROR Upload failed error="upload failed" count=433622026/10/01 09:53:20 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-90547-3700828917/TestDrainIsolatesPoisonPath2729818665/002/bbb33632026/10/01 09:53:20 INFO Upload queue status pending=23364--- PASS: TestQueueEnqueueAndFetch (0.00s)33652026/10/01 09:53:20 INFO Uploading batch count=133662026/10/01 09:53:20 ERROR Upload failed error="upload failed" count=133672026/10/01 09:53:20 INFO Uploading batch count=133682026/10/01 09:53:20 INFO Uploading batch count=233692026/10/01 09:53:20 ERROR Upload failed error="upload failed" count=233702026/10/01 09:53:20 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-90547-3700828917/TestDrainGivesUpWhenServerDown2515197148/002/a33712026/10/01 09:53:20 INFO Uploading batch count=133722026/10/01 09:53:20 ERROR Upload failed error="upload failed" count=133732026/10/01 09:53:20 INFO Upload queue status pending=233742026/10/01 09:53:20 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-90547-3700828917/TestWorkerSkipsGCdPaths3996979301/002/nonexistent33752026/10/01 09:53:20 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-90547-3700828917/TestDrainGivesUpWhenServerDown2515197148/002/b33762026/10/01 09:53:20 INFO Uploading batch count=133772026/10/01 09:53:20 ERROR Upload failed error="upload failed" count=133782026/10/01 09:53:20 INFO Uploading batch count=133792026/10/01 09:53:20 INFO Uploading batch count=233802026/10/01 09:53:20 ERROR Drain finished with paths left in queue remaining=133812026/10/01 09:53:20 ERROR Upload failed error="upload failed" count=233822026/10/01 09:53:20 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-90547-3700828917/TestDrainGivesUpWhenServerDown2515197148/002/c33832026/10/01 09:53:20 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-90547-3700828917/TestDrainGivesUpWhenServerDown2515197148/002/d33842026/10/01 09:53:20 INFO Uploading batch count=233852026/10/01 09:53:20 ERROR Upload failed error="upload failed" count=233862026/10/01 09:53:20 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-90547-3700828917/TestDrainGivesUpWhenServerDown2515197148/002/e33872026/10/01 09:53:20 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-90547-3700828917/TestDrainGivesUpWhenServerDown2515197148/002/f33882026/10/01 09:53:20 ERROR Drain finished with paths left in queue remaining=103389--- PASS: TestDrainIsolatesPoisonPath (0.03s)3390--- PASS: TestDrainGivesUpWhenServerDown (0.04s)3391--- PASS: TestWorkerSkipsGCdPaths (0.03s)3392--- PASS: TestWorkerPrunesClosureDeps (0.03s)3393--- PASS: TestQueueRemoveLargeClosure (0.10s)33942026/10/01 09:53:20 ERROR Upload failed error="context deadline exceeded" count=233952026/10/01 09:53:20 ERROR Drain finished with paths left in queue remaining=43396--- PASS: TestDrainTimeout (0.25s)3397--- PASS: TestQueueConcurrentWriters (0.71s)33982026/10/01 09:53:21 INFO Uploading batch count=133992026/10/01 09:53:21 INFO Uploading batch count=134002026/10/01 09:53:21 INFO Uploading batch count=134012026/10/01 09:53:21 ERROR Upload failed error="upload failed" count=134022026/10/01 09:53:21 INFO Uploading batch count=134032026/10/01 09:53:21 ERROR Upload failed error="upload failed" count=134042026/10/01 09:53:21 INFO Uploading batch count=134052026/10/01 09:53:21 ERROR Upload failed error="upload failed" count=134062026/10/01 09:53:21 INFO Uploading batch count=134072026/10/01 09:53:21 ERROR Upload failed error="upload failed" count=134082026/10/01 09:53:21 ERROR Drain finished with paths left in queue remaining=13409--- PASS: TestRunNotBlockedByPoisonHead (1.03s)3410PASS