niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #322
· 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.08s)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=== CONT TestScriptTokenCachesUntilRefresh97=== CONT TestSetClientTLSErrors98=== CONT TestEncodeNixBase32WithRealHash99=== CONT TestParsePathInfoJSON100=== CONT TestDoWithRetry_BodyReplayedViaGetBody101=== CONT TestResolveStorePath102=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1032026/10/01 09:52:12 WARN Rate limiter enabled after throttle name=server-test rate=5104=== CONT TestRateLimiterFeedback105=== RUN TestRateLimiterFeedback/429_enables_limiter106=== PAUSE TestRateLimiterFeedback/429_enables_limiter107=== CONT TestPathInfoCACompatibility108--- PASS: TestShellSplit (0.00s)109--- PASS: TestEncodeNixBase32WithRealHash (0.00s)110=== CONT TestParsePathInfoJSONMultiplePaths111=== RUN TestParsePathInfoJSON/Nix_format112=== RUN TestRateLimiterFeedback/503_enables_limiter113=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths114=== RUN TestPathInfoCACompatibility/null_ca_field115=== PAUSE TestRateLimiterFeedback/503_enables_limiter116=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter117=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter118=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter119=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths120=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths121=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths122=== PAUSE TestParsePathInfoJSON/Nix_format123=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter124=== CONT TestPathInfoHashCompatibility125=== RUN TestParsePathInfoJSON/Lix_format126=== PAUSE TestParsePathInfoJSON/Lix_format127=== RUN TestParsePathInfoJSON/empty_input128=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)129=== PAUSE TestPathInfoCACompatibility/null_ca_field130=== PAUSE TestParsePathInfoJSON/empty_input131=== RUN TestParsePathInfoJSON/whitespace_only132=== PAUSE TestParsePathInfoJSON/whitespace_only133=== RUN TestParsePathInfoJSON/invalid_JSON134=== RUN TestPathInfoCACompatibility/old_string_format_-_text135--- PASS: TestResolveStorePath (0.00s)136=== CONT TestGetStorePathHash137=== RUN TestGetStorePathHash/valid_store_path138=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)139=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon140=== PAUSE TestGetStorePathHash/valid_store_path141=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon142=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI143=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI144=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512145=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512146=== RUN TestGetStorePathHash/basename_without_hyphen_should_error147=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error148=== CONT TestFileTokenMissing149=== PAUSE TestParsePathInfoJSON/invalid_JSON150=== CONT TestScriptTokenNoExpiryRerunsEveryCall151=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error152=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error153=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error154=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text155=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive156=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive157=== RUN TestPathInfoCACompatibility/new_structured_format_-_text158=== CONT TestConvertHashToNix32159=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error160=== RUN TestConvertHashToNix32/SRI_format_to_Nix32161=== CONT TestFileTokenEmpty162=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text163=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method164=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32165=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method166=== RUN TestConvertHashToNix32/already_Nix32_format167=== CONT TestStreamPushRequestLine168=== PAUSE TestConvertHashToNix32/already_Nix32_format169=== RUN TestConvertHashToNix32/invalid_format170=== PAUSE TestConvertHashToNix32/invalid_format171=== CONT TestSetClientTLSDoesNotMutateDefaultTransport1722026/10/01 09:52:12 WARN Rate limiter enabled after throttle name=server-test rate=51732026/10/01 09:52:12 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:54992174--- PASS: TestFileTokenMissing (0.00s)1752026/10/01 09:52:12 WARN Rate limiter backed off name=server-test rate=5176=== CONT TestSetClientTLS1772026/10/01 09:52:12 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:54992178--- PASS: TestFileTokenEmpty (0.00s)179--- PASS: TestDoServerRequestAttachesToken (0.00s)180--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)181=== CONT TestStreamPushReportsSignatures182=== RUN TestSetClientTLSErrors/missing_cert_file183=== CONT TestClientSignaturesByStorePath184=== PAUSE TestSetClientTLSErrors/missing_cert_file185--- PASS: TestClientSignaturesByStorePath (0.00s)186=== RUN TestSetClientTLSErrors/missing_key_file187=== PAUSE TestSetClientTLSErrors/missing_key_file188=== RUN TestSetClientTLSErrors/missing_ca_file189=== PAUSE TestSetClientTLSErrors/missing_ca_file190=== RUN TestSetClientTLSErrors/invalid_ca_file191=== CONT TestScriptTokenScriptFails192=== CONT TestFileTokenReadsAndCaches193=== PAUSE TestSetClientTLSErrors/invalid_ca_file1942026/10/01 09:52:12 ERROR Upload failed error=boom count=1195=== CONT TestScriptTokenEmptyCommand196--- PASS: TestScriptTokenEmptyCommand (0.00s)197=== CONT TestStaticToken1982026/10/01 09:52:12 ERROR Upload failed error=boom count=1199=== CONT TestEncodeNixBase32200--- PASS: TestStreamPushReportsSignatures (0.00s)201--- PASS: TestStaticToken (0.00s)202=== RUN TestEncodeNixBase32/test_string_hash203=== PAUSE TestEncodeNixBase32/test_string_hash204=== CONT TestUploadMultipart_SupersededByPeer205=== RUN TestEncodeNixBase32/empty_input206=== PAUSE TestEncodeNixBase32/empty_input207=== RUN TestUploadMultipart_SupersededByPeer/exists208=== PAUSE TestUploadMultipart_SupersededByPeer/exists209=== CONT TestDumpPathWriterError210=== RUN TestUploadMultipart_SupersededByPeer/missing211=== PAUSE TestUploadMultipart_SupersededByPeer/missing212=== CONT TestDumpPathSingleFile213--- PASS: TestFileTokenReadsAndCaches (0.00s)214--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)215=== CONT TestFilterOversizedClosures216=== CONT TestDumpPathMatchesNix217=== RUN TestFilterOversizedClosures/no_limit_keeps_everything218=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything219=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped220=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped221=== RUN TestFilterOversizedClosures/all_closures_skipped222=== PAUSE TestFilterOversizedClosures/all_closures_skipped223=== CONT TestPartSizeForNAR224=== RUN TestPartSizeForNAR/zero_stays_at_minimum225=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum226=== RUN TestPartSizeForNAR/small_stays_at_minimum227=== RUN TestSetClientTLS/rejects_connection_without_client_cert228=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert229=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA230=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA231=== RUN TestSetClientTLS/preserves_debug_logging_transport232=== PAUSE TestSetClientTLS/preserves_debug_logging_transport233=== CONT TestUploadMultipart_PartsInParallel234--- PASS: TestScriptTokenScriptFails (0.01s)235=== PAUSE TestPartSizeForNAR/small_stays_at_minimum236=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum237=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum238=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts239=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts240=== RUN TestPartSizeForNAR/1_TiB241=== PAUSE TestPartSizeForNAR/1_TiB242=== RUN TestPartSizeForNAR/5_TiB_S3_max_object243=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object244=== RUN TestPartSizeForNAR/capped_at_5_GiB245=== PAUSE TestPartSizeForNAR/capped_at_5_GiB246=== CONT TestScriptTokenBadJSON247=== CONT TestStreamPushGivesUpOnDeadServer2482026/10/01 09:52:12 ERROR Upload failed error="connection refused" count=202492026/10/01 09:52:12 ERROR Server seems unavailable, giving up on batch untried=17250--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)251=== CONT TestStreamPushIsolatesFailures2522026/10/01 09:52:12 ERROR Upload failed error="bad path" count=3253--- PASS: TestStreamPushIsolatesFailures (0.00s)254=== CONT TestCaseHackSuffix255--- PASS: TestStreamPushRequestLine (0.02s)256=== CONT TestScriptTokenEmptyToken257--- PASS: TestScriptTokenBadJSON (0.01s)258=== CONT TestStreamPushReportsEveryPath259--- PASS: TestStreamPushReportsEveryPath (0.00s)260=== CONT TestShellSplitErrors261--- PASS: TestShellSplitErrors (0.00s)262=== CONT TestRegisterUploadedObjectReusesConnections263--- PASS: TestScriptTokenEmptyToken (0.02s)264=== CONT TestStreamPushBatchesUnderLoad265--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)266=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths267=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths268--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)269 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)270 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)271=== CONT TestRateLimiterFeedback/429_enables_limiter272--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)273=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter2742026/10/01 09:52:12 WARN Rate limiter enabled after throttle name=server-test rate=52752026/10/01 09:52:12 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:550682762026/10/01 09:52:12 WARN Rate limiter backed off name=server-test rate=5277=== CONT TestRateLimiterFeedback/503_enables_limiter278=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2792026/10/01 09:52:12 WARN Rate limiter enabled after throttle name=server-test rate=52802026/10/01 09:52:12 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:55072281=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)282=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512283=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI284=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon285--- PASS: TestPathInfoHashCompatibility (0.00s)286 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)287 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)288 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)289 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)290=== CONT TestParsePathInfoJSON/Nix_format291=== CONT TestParsePathInfoJSON/whitespace_only292=== CONT TestParsePathInfoJSON/invalid_JSON293=== CONT TestParsePathInfoJSON/empty_input294=== CONT TestParsePathInfoJSON/Lix_format295--- PASS: TestParsePathInfoJSON (0.00s)296 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)297 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)298 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)299 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)300 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)301=== CONT TestGetStorePathHash/valid_store_path302=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error303=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error304=== CONT TestGetStorePathHash/basename_without_hyphen_should_error305--- PASS: TestGetStorePathHash (0.00s)306 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)307 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)308 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)309 2026/10/01 09:52:12 WARN Rate limiter backed off name=server-test rate=5310 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)311--- PASS: TestRateLimiterFeedback (0.00s)312 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)313 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)314 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)315 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)316=== CONT TestPathInfoCACompatibility/null_ca_field317=== CONT TestPathInfoCACompatibility/new_structured_format_-_text318=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive319=== CONT TestPathInfoCACompatibility/old_string_format_-_text320=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method321--- PASS: TestPathInfoCACompatibility (0.00s)322 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)323 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)324 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)325 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)326 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)327=== CONT TestConvertHashToNix32/SRI_format_to_Nix32328=== CONT TestConvertHashToNix32/invalid_format329=== CONT TestSetClientTLSErrors/missing_cert_file330=== CONT TestConvertHashToNix32/already_Nix32_format331--- PASS: TestConvertHashToNix32 (0.00s)332 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)333 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)334 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)335=== CONT TestSetClientTLSErrors/invalid_ca_file336=== CONT TestSetClientTLSErrors/missing_ca_file337=== CONT TestSetClientTLSErrors/missing_key_file338=== CONT TestEncodeNixBase32/test_string_hash339=== CONT TestEncodeNixBase32/empty_input340--- PASS: TestEncodeNixBase32 (0.00s)341 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)342 --- PASS: TestEncodeNixBase32/empty_input (0.00s)343=== CONT TestUploadMultipart_SupersededByPeer/missing344=== CONT TestUploadMultipart_SupersededByPeer/exists345--- PASS: TestSetClientTLSErrors (0.01s)346 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)347 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)348 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)349 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)350=== CONT TestFilterOversizedClosures/no_limit_keeps_everything351=== CONT TestFilterOversizedClosures/all_closures_skipped3522026/10/01 09:52:12 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50353=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3542026/10/01 09:52:12 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=2000355--- PASS: TestFilterOversizedClosures (0.00s)356 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)357 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)358 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)359=== CONT TestSetClientTLS/rejects_connection_without_client_cert360--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)361 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)362 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)363=== CONT TestSetClientTLS/preserves_debug_logging_transport364--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)365=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA366=== CONT TestPartSizeForNAR/zero_stays_at_minimum367=== CONT TestPartSizeForNAR/1_TiB368=== CONT TestPartSizeForNAR/capped_at_5_GiB369=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum370=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts371=== CONT TestPartSizeForNAR/small_stays_at_minimum372=== CONT TestPartSizeForNAR/5_TiB_S3_max_object373--- PASS: TestPartSizeForNAR (0.00s)374 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)375 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)376 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)377 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)378 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)379 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)380 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)381--- PASS: TestDumpPathWriterError (0.05s)3822026/10/01 09:52:12 http: TLS handshake error from 127.0.0.1:55080: remote error: tls: bad certificate383--- PASS: TestSetClientTLS (0.01s)384 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)385 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)386 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)387--- PASS: TestDumpPathSingleFile (0.11s)388--- PASS: TestCaseHackSuffix (0.10s)389--- PASS: TestStreamPushBatchesUnderLoad (0.10s)390--- PASS: TestDumpPathMatchesNix (0.14s)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 "_nixbld10".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-90619-4025703153/postgres1079303356/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-90619-4025703153/postgres1079303356/data -l logfile start421422/nix/var/nix/builds/nix-90619-4025703153/postgres1079303356:5432 - no response4232026-10-01 09:52:15.389 UTC [90874] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4242026-10-01 09:52:15.390 UTC [90874] LOG: listening on Unix socket "/nix/var/nix/builds/nix-90619-4025703153/postgres1079303356/.s.PGSQL.5432"4252026-10-01 09:52:15.398 UTC [90882] LOG: database system was shut down at 2026-10-01 09:52:15 UTC4262026-10-01 09:52:15.402 UTC [90874] LOG: database system is ready to accept connections427/nix/var/nix/builds/nix-90619-4025703153/postgres1079303356:5432 - accepting connections428{"timestamp":"2026-10-01T09:52:15.615772Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"5f2e2029-4055-4987-b78b-d6ab3e2e8f44","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(6)"}429{"timestamp":"2026-10-01T09:52:15.718924Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"e673e37f-b4e1-475e-a81e-bd30ad7f8753","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:16.792 UTC [90935] ERROR: relation "goose_db_version" does not exist at character 364742026-10-01 09:52:16.792 UTC [90935] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4752026/10/01 09:52:16 OK 20241026095416_initial_model.sql (62.52ms)4762026/10/01 09:52:16 OK 20251210153512_drop_unused_gin_index.sql (11.18ms)4772026/10/01 09:52:16 OK 20251218171726_add_pins.sql (2.32ms)4782026/10/01 09:52:16 OK 20260628120000_add_object_size_and_stats.sql (10.17ms)4792026/10/01 09:52:16 OK 20260905000000_add_claims.sql (45.58ms)4802026/10/01 09:52:16 OK 20260920000000_drop_claims.sql (20.05ms)4812026/10/01 09:52:16 OK 20260923120000_add_pushes.sql (7.86ms)4822026/10/01 09:52:16 goose: successfully migrated database to version: 202609231200004832026/10/01 09:52:16 OK 1_commit_pending_closure.sql (2.41ms)4842026/10/01 09:52:16 OK 2_object_stats_trigger.sql (771.04µs)4852026/10/01 09:52:16 OK 3_commit_push.sql (517.13µs)4862026/10/01 09:52:16 goose: up to current file version: 34872026/10/01 09:52:17 INFO lead: acquired remote=192.0.2.1:12344882026/10/01 09:52:17 INFO lead: released remote=192.0.2.1:12344892026/10/01 09:52:17 INFO lead: acquired remote=192.0.2.1:12344902026/10/01 09:52:17 INFO lead: released remote=192.0.2.1:1234491--- PASS: TestLeadIncumbentWinsAfterRestart (2.04s)492=== RUN TestLeadEndsOnShutdown493=== PAUSE TestLeadEndsOnShutdown494=== RUN TestGCAdvisoryLockBlocksConcurrentRun4952026-10-01 09:52:19.744 UTC [91008] ERROR: relation "goose_db_version" does not exist at character 364962026-10-01 09:52:19.744 UTC [91008] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4972026/10/01 09:52:19 OK 20241026095416_initial_model.sql (24.48ms)4982026/10/01 09:52:19 OK 20251210153512_drop_unused_gin_index.sql (1.24ms)4992026/10/01 09:52:19 OK 20251218171726_add_pins.sql (2.31ms)5002026/10/01 09:52:19 OK 20260628120000_add_object_size_and_stats.sql (11.88ms)5012026/10/01 09:52:19 OK 20260905000000_add_claims.sql (51.26ms)5022026/10/01 09:52:19 OK 20260920000000_drop_claims.sql (28.74ms)5032026/10/01 09:52:19 OK 20260923120000_add_pushes.sql (5.03ms)5042026/10/01 09:52:19 goose: successfully migrated database to version: 202609231200005052026/10/01 09:52:19 OK 1_commit_pending_closure.sql (1.31ms)5062026/10/01 09:52:19 OK 2_object_stats_trigger.sql (775.54µs)5072026/10/01 09:52:19 OK 3_commit_push.sql (428.54µs)5082026/10/01 09:52:19 goose: up to current file version: 3509--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (2.24s)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 TestObjectStatsTrigger585=== PAUSE TestObjectStatsTrigger586=== RUN TestOrphanedObjectsGC587=== PAUSE TestOrphanedObjectsGC588=== RUN TestOrphanedObjectsGCStressTest589=== PAUSE TestOrphanedObjectsGCStressTest590=== RUN TestCreatePin_ReservedPins591=== PAUSE TestCreatePin_ReservedPins592=== RUN TestPresentReportsOnlyClosureRoots593=== PAUSE TestPresentReportsOnlyClosureRoots594=== RUN TestPresentNotReportedWhileGCDeletesClosure595=== PAUSE TestPresentNotReportedWhileGCDeletesClosure596=== RUN TestParseSingleRange597=== PAUSE TestParseSingleRange598=== RUN TestProxyHeadersOnlyTrustedOnSocket599=== PAUSE TestProxyHeadersOnlyTrustedOnSocket600=== RUN TestIsValidCachePath601=== PAUSE TestIsValidCachePath602=== RUN TestReadProxyNarinfo603=== PAUSE TestReadProxyNarinfo604=== RUN TestReadProxyNarinfoAlreadyDecompressed605=== PAUSE TestReadProxyNarinfoAlreadyDecompressed606=== RUN TestReadProxyNarStreaming607=== PAUSE TestReadProxyNarStreaming608=== RUN TestReadProxy404609=== PAUSE TestReadProxy404610=== RUN TestReadProxyInvalidPath611=== PAUSE TestReadProxyInvalidPath612=== RUN TestReadProxyHead613=== PAUSE TestReadProxyHead614=== RUN TestReadProxyConditionalGet615=== PAUSE TestReadProxyConditionalGet616=== RUN TestReadProxyRootRedirectsToIndexHTML617=== PAUSE TestReadProxyRootRedirectsToIndexHTML618=== RUN TestReadProxyDisabled619=== PAUSE TestReadProxyDisabled620=== RUN TestReadRedirectNar621=== PAUSE TestReadRedirectNar622=== RUN TestReadRedirectKeepsNarinfoProxied623=== PAUSE TestReadRedirectKeepsNarinfoProxied624=== RUN TestReadProxyRangeRequest625=== PAUSE TestReadProxyRangeRequest626=== RUN TestReadRedirectUsesPublicS3URL627=== PAUSE TestReadRedirectUsesPublicS3URL628=== RUN TestPush_OverlappingRootsStoreOneRowPerKey629=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey630=== RUN TestPush_CompleteCommitsEveryRoot631=== PAUSE TestPush_CompleteCommitsEveryRoot632=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit633=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit634=== RUN TestPush_RejectsBadRequests635=== PAUSE TestPush_RejectsBadRequests636=== RUN TestPush_SignsNarinfosOfItsPendingObjects637=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects638=== RUN TestRedundantMultipartUpload639=== PAUSE TestRedundantMultipartUpload640=== RUN TestCompleteMultipartUpload_ErrorButObjectExists641=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists642=== RUN TestCompletedNarNotReofferedAcrossClosures643=== PAUSE TestCompletedNarNotReofferedAcrossClosures644=== RUN TestPresignedUploadRegisteredBeforeCommit645=== PAUSE TestPresignedUploadRegisteredBeforeCommit646=== RUN TestService_Rustfstest647=== PAUSE TestService_Rustfstest648=== RUN TestParseSize649=== PAUSE TestParseSize650=== RUN TestSkippedUploadsHandler651=== PAUSE TestSkippedUploadsHandler652=== RUN TestSystemdListenerNotActivated653--- PASS: TestSystemdListenerNotActivated (0.00s)654=== RUN TestWatchdogBeatsWhenHealthy655--- PASS: TestWatchdogBeatsWhenHealthy (0.05s)656=== RUN TestWatchdogSkipsWhenUnhealthy6572026/10/01 09:52:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6582026/10/01 09:52:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6592026/10/01 09:52:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6602026/10/01 09:52:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6612026/10/01 09:52:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6622026/10/01 09:52:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6632026/10/01 09:52:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6642026/10/01 09:52:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6652026/10/01 09:52:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6662026/10/01 09:52:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"667--- PASS: TestWatchdogSkipsWhenUnhealthy (0.22s)668=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle669=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle670=== RUN TestProxyWriteTimeout671=== PAUSE TestProxyWriteTimeout672=== RUN TestIsValidUploadKey673=== PAUSE TestIsValidUploadKey674=== RUN TestUploadHandlersRejectInvalidKeys675=== PAUSE TestUploadHandlersRejectInvalidKeys676=== RUN TestUploadHandlersRejectOversizedBody677=== PAUSE TestUploadHandlersRejectOversizedBody678=== RUN TestService_cleanupPendingClosuresHandler679=== PAUSE TestService_cleanupPendingClosuresHandler680=== RUN TestService_createPendingClosureHandler681=== PAUSE TestService_createPendingClosureHandler682=== RUN TestService_verifyS3Integrity683=== PAUSE TestService_verifyS3Integrity684=== RUN TestCompleteMultipartUnregistered685=== PAUSE TestCompleteMultipartUnregistered686=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT687=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT688=== CONT TestService_AuthMiddleware689=== CONT TestCreatePendingClosureRejectsOversizedNAR690=== CONT TestGCSweepSkipsPendingObjects691=== CONT TestReadRedirectKeepsNarinfoProxied6922026/10/01 09:52:20 INFO Received uploads request method=POST path=/api/pending_closures693=== CONT TestClientWithDependencies694--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)695=== CONT TestReadRedirectNar696=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT697=== CONT TestCompleteMultipartUnregistered698=== CONT TestService_verifyS3Integrity699=== CONT TestReadProxyDisabled700=== CONT TestDeduplicatedObjectsRecordedAsPending7012026-10-01 09:52:23.039 UTC [91125] ERROR: relation "goose_db_version" does not exist at character 367022026-10-01 09:52:23.039 UTC [91125] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7032026-10-01 09:52:23.062 UTC [91124] ERROR: relation "goose_db_version" does not exist at character 367042026-10-01 09:52:23.062 UTC [91124] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7052026-10-01 09:52:23.072 UTC [91123] ERROR: relation "goose_db_version" does not exist at character 367062026-10-01 09:52:23.072 UTC [91123] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7072026-10-01 09:52:23.102 UTC [91127] ERROR: relation "goose_db_version" does not exist at character 367082026-10-01 09:52:23.102 UTC [91127] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7092026-10-01 09:52:23.152 UTC [91126] ERROR: relation "goose_db_version" does not exist at character 367102026-10-01 09:52:23.152 UTC [91126] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7112026-10-01 09:52:23.199 UTC [91129] ERROR: relation "goose_db_version" does not exist at character 367122026-10-01 09:52:23.199 UTC [91129] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7132026-10-01 09:52:23.271 UTC [91128] ERROR: relation "goose_db_version" does not exist at character 367142026-10-01 09:52:23.271 UTC [91128] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7152026-10-01 09:52:23.391 UTC [91139] ERROR: relation "goose_db_version" does not exist at character 367162026-10-01 09:52:23.391 UTC [91139] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7172026-10-01 09:52:23.392 UTC [91146] ERROR: relation "goose_db_version" does not exist at character 367182026-10-01 09:52:23.392 UTC [91146] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7192026-10-01 09:52:23.402 UTC [91138] ERROR: relation "goose_db_version" does not exist at character 367202026-10-01 09:52:23.402 UTC [91138] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7212026/10/01 09:52:23 OK 20241026095416_initial_model.sql (293.87ms)7222026/10/01 09:52:23 OK 20251210153512_drop_unused_gin_index.sql (29.01ms)7232026/10/01 09:52:23 OK 20241026095416_initial_model.sql (334.07ms)7242026/10/01 09:52:23 OK 20241026095416_initial_model.sql (334.01ms)7252026/10/01 09:52:23 OK 20251210153512_drop_unused_gin_index.sql (10.87ms)7262026/10/01 09:52:23 OK 20251210153512_drop_unused_gin_index.sql (19.41ms)7272026/10/01 09:52:23 OK 20251218171726_add_pins.sql (31.67ms)7282026/10/01 09:52:23 OK 20241026095416_initial_model.sql (340ms)7292026/10/01 09:52:23 OK 20251218171726_add_pins.sql (43.53ms)7302026/10/01 09:52:23 OK 20241026095416_initial_model.sql (312.96ms)7312026/10/01 09:52:23 OK 20251218171726_add_pins.sql (43.8ms)7322026/10/01 09:52:23 OK 20251210153512_drop_unused_gin_index.sql (8.96ms)7332026/10/01 09:52:23 OK 20260628120000_add_object_size_and_stats.sql (53.63ms)7342026/10/01 09:52:23 OK 20251210153512_drop_unused_gin_index.sql (11.75ms)7352026/10/01 09:52:23 OK 20241026095416_initial_model.sql (271.28ms)7362026/10/01 09:52:23 OK 20260628120000_add_object_size_and_stats.sql (52.54ms)7372026/10/01 09:52:23 OK 20260628120000_add_object_size_and_stats.sql (52.36ms)7382026/10/01 09:52:23 OK 20251218171726_add_pins.sql (52.52ms)7392026/10/01 09:52:23 OK 20251210153512_drop_unused_gin_index.sql (18.67ms)7402026/10/01 09:52:23 OK 20251218171726_add_pins.sql (57.7ms)7412026/10/01 09:52:23 OK 20260905000000_add_claims.sql (67.49ms)7422026/10/01 09:52:23 OK 20241026095416_initial_model.sql (251.58ms)7432026/10/01 09:52:23 OK 20251210153512_drop_unused_gin_index.sql (27.77ms)7442026/10/01 09:52:23 OK 20260905000000_add_claims.sql (89.47ms)7452026/10/01 09:52:23 OK 20260628120000_add_object_size_and_stats.sql (75.3ms)7462026/10/01 09:52:23 OK 20260628120000_add_object_size_and_stats.sql (78.37ms)7472026/10/01 09:52:23 OK 20251218171726_add_pins.sql (89.71ms)7482026/10/01 09:52:23 OK 20260920000000_drop_claims.sql (83.82ms)7492026/10/01 09:52:23 OK 20260905000000_add_claims.sql (110.51ms)7502026/10/01 09:52:23 OK 20251218171726_add_pins.sql (59.06ms)7512026/10/01 09:52:23 OK 20260628120000_add_object_size_and_stats.sql (36.43ms)7522026/10/01 09:52:23 OK 20260923120000_add_pushes.sql (31.13ms)7532026/10/01 09:52:23 goose: successfully migrated database to version: 202609231200007542026/10/01 09:52:23 OK 1_commit_pending_closure.sql (900.67µs)7552026/10/01 09:52:23 OK 2_object_stats_trigger.sql (211.63µs)7562026/10/01 09:52:23 OK 3_commit_push.sql (187.21µs)7572026/10/01 09:52:23 goose: up to current file version: 37582026/10/01 09:52:23 OK 20260920000000_drop_claims.sql (39.67ms)7592026/10/01 09:52:23 OK 20241026095416_initial_model.sql (259.94ms)7602026/10/01 09:52:23 OK 20260920000000_drop_claims.sql (87.04ms)7612026/10/01 09:52:23 OK 20251210153512_drop_unused_gin_index.sql (27.38ms)7622026/10/01 09:52:23 OK 20260923120000_add_pushes.sql (28.71ms)7632026/10/01 09:52:23 goose: successfully migrated database to version: 202609231200007642026/10/01 09:52:23 OK 20260628120000_add_object_size_and_stats.sql (57.42ms)7652026/10/01 09:52:23 OK 1_commit_pending_closure.sql (1.08ms)7662026/10/01 09:52:23 OK 2_object_stats_trigger.sql (265.25µs)7672026/10/01 09:52:23 OK 3_commit_push.sql (183.63µs)7682026/10/01 09:52:23 goose: up to current file version: 37692026/10/01 09:52:23 OK 20260905000000_add_claims.sql (103.53ms)7702026/10/01 09:52:23 OK 20260905000000_add_claims.sql (123.22ms)7712026/10/01 09:52:23 OK 20260923120000_add_pushes.sql (47.17ms)7722026/10/01 09:52:23 goose: successfully migrated database to version: 202609231200007732026/10/01 09:52:23 OK 1_commit_pending_closure.sql (947µs)7742026/10/01 09:52:23 OK 2_object_stats_trigger.sql (200.5µs)7752026/10/01 09:52:23 OK 3_commit_push.sql (175.13µs)7762026/10/01 09:52:23 goose: up to current file version: 37772026/10/01 09:52:23 OK 20241026095416_initial_model.sql (351.56ms)7782026/10/01 09:52:23 OK 20251218171726_add_pins.sql (83.35ms)7792026/10/01 09:52:23 OK 20251210153512_drop_unused_gin_index.sql (24.89ms)7802026/10/01 09:52:23 OK 20241026095416_initial_model.sql (345.13ms)7812026/10/01 09:52:23 OK 20251210153512_drop_unused_gin_index.sql (31.66ms)7822026/10/01 09:52:23 OK 20260920000000_drop_claims.sql (89.73ms)7832026/10/01 09:52:23 OK 20260905000000_add_claims.sql (165.1ms)7842026/10/01 09:52:23 OK 20260920000000_drop_claims.sql (116.9ms)7852026/10/01 09:52:23 OK 20260905000000_add_claims.sql (141.18ms)7862026/10/01 09:52:23 OK 20260923120000_add_pushes.sql (17.89ms)7872026/10/01 09:52:23 goose: successfully migrated database to version: 202609231200007882026/10/01 09:52:23 OK 20260628120000_add_object_size_and_stats.sql (59.04ms)7892026/10/01 09:52:23 OK 1_commit_pending_closure.sql (908.42µs)7902026/10/01 09:52:23 OK 2_object_stats_trigger.sql (239.79µs)7912026/10/01 09:52:23 OK 3_commit_push.sql (184.46µs)7922026/10/01 09:52:23 goose: up to current file version: 37932026/10/01 09:52:23 OK 20251218171726_add_pins.sql (70.57ms)7942026/10/01 09:52:23 OK 20260923120000_add_pushes.sql (36.06ms)7952026/10/01 09:52:23 goose: successfully migrated database to version: 202609231200007962026/10/01 09:52:23 OK 1_commit_pending_closure.sql (767.83µs)7972026/10/01 09:52:23 OK 2_object_stats_trigger.sql (225.83µs)7982026/10/01 09:52:23 OK 3_commit_push.sql (170.67µs)7992026/10/01 09:52:23 goose: up to current file version: 38002026/10/01 09:52:23 OK 20251218171726_add_pins.sql (76.63ms)8012026/10/01 09:52:24 OK 20260628120000_add_object_size_and_stats.sql (72.24ms)8022026/10/01 09:52:24 OK 20260920000000_drop_claims.sql (107.52ms)8032026/10/01 09:52:24 OK 20260920000000_drop_claims.sql (104.41ms)8042026/10/01 09:52:24 OK 20260628120000_add_object_size_and_stats.sql (51.96ms)8052026/10/01 09:52:24 OK 20260923120000_add_pushes.sql (29.79ms)8062026/10/01 09:52:24 goose: successfully migrated database to version: 202609231200008072026/10/01 09:52:24 OK 1_commit_pending_closure.sql (915.5µs)8082026/10/01 09:52:24 OK 2_object_stats_trigger.sql (215.33µs)8092026/10/01 09:52:24 OK 3_commit_push.sql (172.13µs)8102026/10/01 09:52:24 goose: up to current file version: 38112026/10/01 09:52:24 OK 20260905000000_add_claims.sql (128.01ms)8122026/10/01 09:52:24 OK 20260923120000_add_pushes.sql (31.9ms)8132026/10/01 09:52:24 goose: successfully migrated database to version: 202609231200008142026/10/01 09:52:24 OK 1_commit_pending_closure.sql (929.25µs)8152026/10/01 09:52:24 OK 2_object_stats_trigger.sql (226.58µs)8162026/10/01 09:52:24 OK 3_commit_push.sql (188.63µs)8172026/10/01 09:52:24 goose: up to current file version: 38182026/10/01 09:52:24 INFO Received uploads request method=POST path=/api/pending_closures8192026/10/01 09:52:24 OK 20260905000000_add_claims.sql (118.45ms)8202026/10/01 09:52:24 OK 20260920000000_drop_claims.sql (90.75ms)8212026/10/01 09:52:24 OK 20260905000000_add_claims.sql (109.08ms)8222026/10/01 09:52:24 OK 20260923120000_add_pushes.sql (35.89ms)8232026/10/01 09:52:24 goose: successfully migrated database to version: 202609231200008242026/10/01 09:52:24 OK 1_commit_pending_closure.sql (1.46ms)8252026/10/01 09:52:24 OK 2_object_stats_trigger.sql (333.67µs)8262026/10/01 09:52:24 OK 3_commit_push.sql (244.67µs)8272026/10/01 09:52:24 goose: up to current file version: 38282026/10/01 09:52:24 OK 20260920000000_drop_claims.sql (101.65ms)829--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (3.87s)830=== CONT TestGCEndsOnShutdown8312026/10/01 09:52:24 OK 20260923120000_add_pushes.sql (22.8ms)8322026/10/01 09:52:24 goose: successfully migrated database to version: 202609231200008332026/10/01 09:52:24 OK 20260920000000_drop_claims.sql (114.62ms)8342026/10/01 09:52:24 OK 1_commit_pending_closure.sql (2.73ms)8352026/10/01 09:52:24 OK 2_object_stats_trigger.sql (448.92µs)8362026/10/01 09:52:24 OK 3_commit_push.sql (302.63µs)8372026/10/01 09:52:24 goose: up to current file version: 38382026/10/01 09:52:24 OK 20260923120000_add_pushes.sql (27.04ms)8392026/10/01 09:52:24 goose: successfully migrated database to version: 202609231200008402026/10/01 09:52:24 OK 1_commit_pending_closure.sql (1.32ms)8412026/10/01 09:52:24 OK 2_object_stats_trigger.sql (291.88µs)8422026/10/01 09:52:24 OK 3_commit_push.sql (263.25µs)8432026/10/01 09:52:24 goose: up to current file version: 38442026/10/01 09:52:24 INFO Received uploads request method=POST path=/api/pending_closures8452026/10/01 09:52:24 INFO Aborted multipart uploads count=08462026/10/01 09:52:24 WARN Force mode enabled - objects will be deleted immediately without grace period8472026/10/01 09:52:24 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=08482026/10/01 09:52:24 INFO Vacuumed table table=pending_closures8492026/10/01 09:52:24 INFO Vacuumed table table=pending_objects8502026/10/01 09:52:24 INFO Vacuumed table table=multipart_uploads8512026/10/01 09:52:24 INFO Vacuumed table table=closures8522026/10/01 09:52:24 INFO Vacuumed table table=objects853--- PASS: TestGCSweepSkipsPendingObjects (4.43s)854=== CONT TestCommitRacingPendingCleanupKeepsObjects855--- PASS: TestReadRedirectKeepsNarinfoProxied (4.59s)856=== CONT TestPushWaitsForSweepHoldingRow8572026/10/01 09:52:25 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"858--- PASS: TestService_AuthMiddleware (4.99s)859=== CONT TestSweepRechecksPendingAfterLocking8602026/10/01 09:52:25 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8612026/10/01 09:52:25 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst862--- PASS: TestCompleteMultipartUnregistered (5.25s)863=== CONT TestGetExistingObjectsLocksRows8642026/10/01 09:52:26 INFO Received uploads request method=POST path=/api/pending_closures8652026/10/01 09:52:26 INFO Received uploads request method=POST path=/api/pending_closures866--- PASS: TestDeduplicatedObjectsRecordedAsPending (6.22s)867=== CONT TestRegisterCompletedObjectNeedsPendingRow8682026-10-01 09:52:26.872 UTC [91223] ERROR: relation "goose_db_version" does not exist at character 368692026-10-01 09:52:26.872 UTC [91223] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC870--- PASS: TestReadRedirectNar (6.72s)871=== CONT TestSweepSkipsRowsLockedByPush8722026/10/01 09:52:27 OK 20241026095416_initial_model.sql (455.19ms)8732026/10/01 09:52:27 OK 20251210153512_drop_unused_gin_index.sql (18.68ms)8742026/10/01 09:52:27 OK 20251218171726_add_pins.sql (65.11ms)8752026-10-01 09:52:27.525 UTC [91232] ERROR: relation "goose_db_version" does not exist at character 368762026-10-01 09:52:27.525 UTC [91232] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC877--- PASS: TestReadProxyDisabled (7.19s)878=== CONT TestFailedS3DeleteKeepsTombstone8792026/10/01 09:52:27 OK 20260628120000_add_object_size_and_stats.sql (75.5ms)8802026/10/01 09:52:27 OK 20260905000000_add_claims.sql (120.02ms)8812026/10/01 09:52:27 OK 20260920000000_drop_claims.sql (85.93ms)8822026/10/01 09:52:27 OK 20260923120000_add_pushes.sql (40.14ms)8832026/10/01 09:52:27 goose: successfully migrated database to version: 202609231200008842026/10/01 09:52:27 OK 1_commit_pending_closure.sql (1.87ms)8852026/10/01 09:52:27 OK 2_object_stats_trigger.sql (424.63µs)8862026/10/01 09:52:27 OK 3_commit_push.sql (343.58µs)8872026/10/01 09:52:27 goose: up to current file version: 38882026-10-01 09:52:27.910 UTC [91235] ERROR: relation "goose_db_version" does not exist at character 368892026-10-01 09:52:27.910 UTC [91235] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8902026/10/01 09:52:28 OK 20241026095416_initial_model.sql (412.65ms)8912026/10/01 09:52:28 OK 20251210153512_drop_unused_gin_index.sql (17.11ms)8922026/10/01 09:52:28 OK 20251218171726_add_pins.sql (52.04ms)8932026/10/01 09:52:28 OK 20260628120000_add_object_size_and_stats.sql (73.08ms)8942026/10/01 09:52:28 OK 20260905000000_add_claims.sql (160.93ms)8952026/10/01 09:52:28 OK 20260920000000_drop_claims.sql (88.62ms)8962026/10/01 09:52:28 OK 20260923120000_add_pushes.sql (26.29ms)8972026/10/01 09:52:28 goose: successfully migrated database to version: 202609231200008982026/10/01 09:52:28 OK 1_commit_pending_closure.sql (2.48ms)8992026/10/01 09:52:28 OK 2_object_stats_trigger.sql (1.88ms)9002026/10/01 09:52:28 OK 3_commit_push.sql (422.58µs)9012026/10/01 09:52:28 goose: up to current file version: 39022026/10/01 09:52:28 OK 20241026095416_initial_model.sql (426.82ms)9032026/10/01 09:52:28 OK 20251210153512_drop_unused_gin_index.sql (26.58ms)9042026/10/01 09:52:28 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9052026/10/01 09:52:28 OK 20251218171726_add_pins.sql (54.63ms)9062026/10/01 09:52:28 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZTk3NDBhMTQtZmM4MC00OGM1LTgyZTUtOTc2OTc4NzFmYmI0LjcxODI4YjJhLWUzZjEtNDhhYS1iZmRmLTRjYzAxMjAxYjNjOXgxNzkwODQ4MzQ2MDkzMDY1MDAw parts=109072026/10/01 09:52:28 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9082026/10/01 09:52:28 INFO Completed upload id=19092026/10/01 09:52:28 INFO Received uploads request method=POST path=/api/pending_closures9102026/10/01 09:52:28 INFO Received uploads request method=POST path=/api/pending_closures9112026/10/01 09:52:28 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9122026/10/01 09:52:28 WARN Found objects in DB but missing from S3, will re-upload count=1913--- PASS: TestService_verifyS3Integrity (8.24s)914=== CONT TestForceGCDuringPushOffersSweptObject915=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows916=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows917=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check918=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check919=== CONT TestService_createPendingClosureHandler9202026/10/01 09:52:28 OK 20260628120000_add_object_size_and_stats.sql (83.9ms)921--- PASS: TestGCEndsOnShutdown (4.41s)922=== CONT TestService_cleanupPendingClosuresHandler9232026/10/01 09:52:28 OK 20260905000000_add_claims.sql (141.89ms)9242026/10/01 09:52:28 OK 20260920000000_drop_claims.sql (67.13ms)9252026/10/01 09:52:28 OK 20260923120000_add_pushes.sql (23.08ms)9262026/10/01 09:52:28 goose: successfully migrated database to version: 202609231200009272026/10/01 09:52:28 OK 1_commit_pending_closure.sql (2.26ms)9282026/10/01 09:52:28 OK 2_object_stats_trigger.sql (294.25µs)9292026/10/01 09:52:28 OK 3_commit_push.sql (200.5µs)9302026/10/01 09:52:28 goose: up to current file version: 39312026-10-01 09:52:28.971 UTC [91255] ERROR: relation "goose_db_version" does not exist at character 369322026-10-01 09:52:28.971 UTC [91255] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC933=== NAME TestClientWithDependencies934 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-90619-4025703153/TestClientWithDependencies3492237648/001/store/33y3088kylzqzcn9xlj6zxs72rcx2mkm-test-script935 client_integration_test.go:615: Found 1 dependencies (including self)9362026/10/01 09:52:29 INFO Aborted multipart uploads count=09372026/10/01 09:52:29 WARN Force mode enabled - objects will be deleted immediately without grace period9382026/10/01 09:52:29 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=09392026/10/01 09:52:29 INFO Vacuumed table table=pending_closures9402026/10/01 09:52:29 INFO Received push request method=POST path=/api/pushes9412026/10/01 09:52:29 INFO Vacuumed table table=pending_objects9422026/10/01 09:52:29 INFO Vacuumed table table=multipart_uploads9432026/10/01 09:52:29 OK 20241026095416_initial_model.sql (158.64ms)9442026-10-01 09:52:29.278 UTC [91267] ERROR: relation "goose_db_version" does not exist at character 369452026-10-01 09:52:29.278 UTC [91267] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9462026/10/01 09:52:29 INFO Vacuumed table table=closures9472026/10/01 09:52:29 INFO Vacuumed table table=objects9482026/10/01 09:52:29 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9492026/10/01 09:52:29 INFO Uploading 33y3088kylzqzcn9xlj6zxs72rcx2mkm-test-script (136B)9502026/10/01 09:52:29 OK 20251210153512_drop_unused_gin_index.sql (74.97ms)951--- PASS: TestCommitRacingPendingCleanupKeepsObjects (4.51s)952=== CONT TestUploadHandlersRejectInvalidKeys953=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info954=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info955=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal956=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal957=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key958=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key959=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key960=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key961=== CONT TestIsValidUploadKey962=== RUN TestIsValidUploadKey/narinfo963=== PAUSE TestIsValidUploadKey/narinfo964=== RUN TestIsValidUploadKey/nar_zst965=== PAUSE TestIsValidUploadKey/nar_zst966=== RUN TestIsValidUploadKey/nar_xz967=== PAUSE TestIsValidUploadKey/nar_xz968=== RUN TestIsValidUploadKey/nar_plain969=== PAUSE TestIsValidUploadKey/nar_plain970=== RUN TestIsValidUploadKey/listing971=== PAUSE TestIsValidUploadKey/listing972=== RUN TestIsValidUploadKey/build_log973=== PAUSE TestIsValidUploadKey/build_log974=== RUN TestIsValidUploadKey/build_log_home-manager_file975=== PAUSE TestIsValidUploadKey/build_log_home-manager_file976=== RUN TestIsValidUploadKey/build_log_plus_in_name977=== PAUSE TestIsValidUploadKey/build_log_plus_in_name978=== RUN TestIsValidUploadKey/build_log_question_mark979=== PAUSE TestIsValidUploadKey/build_log_question_mark980=== RUN TestIsValidUploadKey/build_log_equals981=== PAUSE TestIsValidUploadKey/build_log_equals982=== RUN TestIsValidUploadKey/realisation983=== PAUSE TestIsValidUploadKey/realisation984=== RUN TestIsValidUploadKey/realisation_plus_in_output985=== PAUSE TestIsValidUploadKey/realisation_plus_in_output986=== RUN TestIsValidUploadKey/nix-cache-info987=== PAUSE TestIsValidUploadKey/nix-cache-info988=== RUN TestIsValidUploadKey/index.html989=== PAUSE TestIsValidUploadKey/index.html990=== RUN TestIsValidUploadKey/narinfo_key,_nar_type991=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type992=== RUN TestIsValidUploadKey/nar_key,_narinfo_type993=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type994=== RUN TestIsValidUploadKey/listing_key,_narinfo_type995=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type996=== RUN TestIsValidUploadKey/traversal997=== PAUSE TestIsValidUploadKey/traversal998=== RUN TestIsValidUploadKey/traversal_nar999=== PAUSE TestIsValidUploadKey/traversal_nar1000=== RUN TestIsValidUploadKey/absolute1001=== PAUSE TestIsValidUploadKey/absolute1002=== RUN TestIsValidUploadKey/empty_key1003=== PAUSE TestIsValidUploadKey/empty_key1004=== RUN TestIsValidUploadKey/unknown_type1005=== PAUSE TestIsValidUploadKey/unknown_type1006=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection10072026/10/01 09:52:29 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"10082026/10/01 09:52:29 WARN Failed to register uploaded object key=33y3088kylzqzcn9xlj6zxs72rcx2mkm.ls error="server returned 404: 404 page not found\n"10092026/10/01 09:52:29 OK 20251218171726_add_pins.sql (46.75ms)10102026/10/01 09:52:29 WARN Failed to register uploaded object key=log/5pw9a200vd6187m5fn674vnl1cv3n80j-test-script.drv error="server returned 404: 404 page not found\n"10112026/10/01 09:52:29 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10122026/10/01 09:52:29 INFO Signed narinfos id=1 count=110132026/10/01 09:52:29 INFO Uploading 1 narinfos10142026/10/01 09:52:29 INFO Received complete push request method=POST path=/api/pushes/1/complete10152026/10/01 09:52:29 WARN Failed to register uploaded object key=33y3088kylzqzcn9xlj6zxs72rcx2mkm.narinfo error="server returned 404: 404 page not found\n"10162026/10/01 09:52:29 OK 20260628120000_add_object_size_and_stats.sql (61.58ms)10172026/10/01 09:52:29 INFO Received uploads request method=POST path=/api/pending_closures10182026/10/01 09:52:29 INFO Upload complete. (326ms)1019=== NAME TestClientWithDependencies1020 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-90619-4025703153/TestClientWithDependencies3492237648/001/store) requires matching store prefix10212026/10/01 09:52:29 OK 20260905000000_add_claims.sql (86.68ms)10222026/10/01 09:52:29 OK 20260920000000_drop_claims.sql (19.8ms)1023--- PASS: TestClientWithDependencies (9.15s)1024=== CONT TestReadProxyRootRedirectsToIndexHTML10252026/10/01 09:52:29 OK 20260923120000_add_pushes.sql (18.45ms)10262026/10/01 09:52:29 goose: successfully migrated database to version: 2026092312000010272026/10/01 09:52:29 OK 1_commit_pending_closure.sql (4.13ms)10282026/10/01 09:52:29 OK 2_object_stats_trigger.sql (312.42µs)10292026/10/01 09:52:29 OK 3_commit_push.sql (219.21µs)10302026/10/01 09:52:29 goose: up to current file version: 310312026/10/01 09:52:29 OK 20241026095416_initial_model.sql (201.5ms)10322026/10/01 09:52:29 OK 20251210153512_drop_unused_gin_index.sql (17.73ms)10332026/10/01 09:52:29 OK 20251218171726_add_pins.sql (41.59ms)10342026/10/01 09:52:29 OK 20260628120000_add_object_size_and_stats.sql (49.33ms)10352026/10/01 09:52:29 OK 20260905000000_add_claims.sql (98.21ms)10362026/10/01 09:52:29 OK 20260920000000_drop_claims.sql (43.14ms)10372026/10/01 09:52:29 OK 20260923120000_add_pushes.sql (21.88ms)10382026/10/01 09:52:29 goose: successfully migrated database to version: 2026092312000010392026/10/01 09:52:29 OK 1_commit_pending_closure.sql (971.04µs)10402026/10/01 09:52:29 OK 2_object_stats_trigger.sql (253.33µs)10412026/10/01 09:52:29 OK 3_commit_push.sql (198.58µs)10422026/10/01 09:52:29 goose: up to current file version: 31043--- PASS: TestPushWaitsForSweepHoldingRow (4.96s)1044=== CONT TestProxyWriteTimeout1045=== RUN TestProxyWriteTimeout/narinfo1046=== PAUSE TestProxyWriteTimeout/narinfo1047=== RUN TestProxyWriteTimeout/1_GiB_nar1048=== PAUSE TestProxyWriteTimeout/1_GiB_nar1049=== RUN TestProxyWriteTimeout/10_GiB_nar1050=== PAUSE TestProxyWriteTimeout/10_GiB_nar1051=== RUN TestProxyWriteTimeout/unknown_size1052=== PAUSE TestProxyWriteTimeout/unknown_size1053=== CONT TestUploadHandlersRejectOversizedBody1054=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1055=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1056=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1057=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1058=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1059=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1060=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle10612026/10/01 09:52:29 INFO Aborted multipart uploads count=010622026/10/01 09:52:29 WARN Force mode enabled - objects will be deleted immediately without grace period10632026/10/01 09:52:30 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=010642026/10/01 09:52:30 INFO Vacuumed table table=pending_closures10652026/10/01 09:52:30 INFO Vacuumed table table=pending_objects10662026/10/01 09:52:30 INFO Vacuumed table table=multipart_uploads10672026/10/01 09:52:30 INFO Vacuumed table table=closures10682026/10/01 09:52:30 INFO Vacuumed table table=objects1069--- PASS: TestSweepRechecksPendingAfterLocking (4.84s)1070=== CONT TestReadProxyConditionalGet1071--- PASS: TestGetExistingObjectsLocksRows (4.86s)1072=== CONT TestGCSweepDeliversEachKeyOnce10732026-10-01 09:52:30.582 UTC [91291] ERROR: relation "goose_db_version" does not exist at character 3610742026-10-01 09:52:30.582 UTC [91291] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10752026-10-01 09:52:30.586 UTC [91288] ERROR: relation "goose_db_version" does not exist at character 3610762026-10-01 09:52:30.586 UTC [91288] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10772026-10-01 09:52:30.836 UTC [91293] ERROR: relation "goose_db_version" does not exist at character 3610782026-10-01 09:52:30.836 UTC [91293] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10792026/10/01 09:52:31 OK 20241026095416_initial_model.sql (261.3ms)10802026/10/01 09:52:31 OK 20251210153512_drop_unused_gin_index.sql (26.04ms)10812026/10/01 09:52:31 OK 20241026095416_initial_model.sql (315.42ms)10822026-10-01 09:52:31.093 UTC [91294] ERROR: relation "goose_db_version" does not exist at character 3610832026-10-01 09:52:31.093 UTC [91294] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10842026/10/01 09:52:31 OK 20251210153512_drop_unused_gin_index.sql (18.6ms)10852026/10/01 09:52:31 OK 20251218171726_add_pins.sql (49.38ms)10862026/10/01 09:52:31 OK 20251218171726_add_pins.sql (52.64ms)10872026/10/01 09:52:31 OK 20260628120000_add_object_size_and_stats.sql (59.62ms)10882026/10/01 09:52:31 OK 20260628120000_add_object_size_and_stats.sql (74.42ms)10892026/10/01 09:52:31 OK 20241026095416_initial_model.sql (333.43ms)10902026/10/01 09:52:31 OK 20251210153512_drop_unused_gin_index.sql (25.47ms)10912026/10/01 09:52:31 OK 20260905000000_add_claims.sql (98.24ms)10922026/10/01 09:52:31 OK 20251218171726_add_pins.sql (8.65ms)10932026/10/01 09:52:31 OK 20260905000000_add_claims.sql (64.29ms)10942026/10/01 09:52:31 OK 20260628120000_add_object_size_and_stats.sql (79.1ms)10952026/10/01 09:52:31 OK 20260920000000_drop_claims.sql (88.35ms)10962026/10/01 09:52:31 OK 20260920000000_drop_claims.sql (69.33ms)10972026/10/01 09:52:31 OK 20260923120000_add_pushes.sql (23.04ms)10982026/10/01 09:52:31 goose: successfully migrated database to version: 2026092312000010992026/10/01 09:52:31 OK 20260923120000_add_pushes.sql (26.5ms)11002026/10/01 09:52:31 goose: successfully migrated database to version: 2026092312000011012026/10/01 09:52:31 OK 1_commit_pending_closure.sql (2.88ms)11022026/10/01 09:52:31 OK 1_commit_pending_closure.sql (2.97ms)11032026/10/01 09:52:31 OK 2_object_stats_trigger.sql (462.42µs)11042026/10/01 09:52:31 OK 2_object_stats_trigger.sql (461.58µs)11052026/10/01 09:52:31 OK 3_commit_push.sql (319.25µs)11062026/10/01 09:52:31 goose: up to current file version: 311072026/10/01 09:52:31 OK 3_commit_push.sql (340.17µs)11082026/10/01 09:52:31 goose: up to current file version: 311092026/10/01 09:52:31 OK 20260905000000_add_claims.sql (122.12ms)11102026/10/01 09:52:31 OK 20241026095416_initial_model.sql (301.59ms)11112026/10/01 09:52:31 OK 20251210153512_drop_unused_gin_index.sql (17.48ms)11122026/10/01 09:52:31 OK 20251218171726_add_pins.sql (70.74ms)11132026/10/01 09:52:31 OK 20260920000000_drop_claims.sql (117.36ms)11142026/10/01 09:52:31 OK 20260923120000_add_pushes.sql (43.21ms)11152026/10/01 09:52:31 goose: successfully migrated database to version: 2026092312000011162026/10/01 09:52:31 OK 1_commit_pending_closure.sql (3.84ms)11172026/10/01 09:52:31 OK 2_object_stats_trigger.sql (2.62ms)11182026/10/01 09:52:31 OK 3_commit_push.sql (922.67µs)11192026/10/01 09:52:31 goose: up to current file version: 311202026/10/01 09:52:31 OK 20260628120000_add_object_size_and_stats.sql (95.76ms)11212026/10/01 09:52:31 OK 20260905000000_add_claims.sql (184.53ms)11222026/10/01 09:52:32 OK 20260920000000_drop_claims.sql (136.08ms)11232026/10/01 09:52:32 OK 20260923120000_add_pushes.sql (46.36ms)11242026/10/01 09:52:32 goose: successfully migrated database to version: 2026092312000011252026/10/01 09:52:32 OK 1_commit_pending_closure.sql (1.85ms)11262026/10/01 09:52:32 OK 2_object_stats_trigger.sql (418.88µs)11272026/10/01 09:52:32 OK 3_commit_push.sql (310.88µs)11282026/10/01 09:52:32 goose: up to current file version: 311292026/10/01 09:52:32 INFO Aborted multipart uploads count=011302026/10/01 09:52:32 WARN Force mode enabled - objects will be deleted immediately without grace period11312026/10/01 09:52:32 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=011322026/10/01 09:52:32 INFO Vacuumed table table=pending_closures11332026/10/01 09:52:32 INFO Vacuumed table table=pending_objects11342026/10/01 09:52:32 INFO Vacuumed table table=multipart_uploads11352026/10/01 09:52:32 INFO Vacuumed table table=closures11362026/10/01 09:52:32 INFO Vacuumed table table=objects11372026/10/01 09:52:32 INFO Aborted multipart uploads count=011382026/10/01 09:52:32 WARN Force mode enabled - objects will be deleted immediately without grace period11392026/10/01 09:52:32 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=011402026/10/01 09:52:32 INFO Vacuumed table table=pending_closures11412026/10/01 09:52:32 INFO Vacuumed table table=pending_objects11422026/10/01 09:52:32 INFO Vacuumed table table=multipart_uploads11432026/10/01 09:52:32 INFO Vacuumed table table=closures11442026/10/01 09:52:32 INFO Vacuumed table table=objects1145--- PASS: TestSweepSkipsRowsLockedByPush (5.21s)1146=== CONT TestSkippedUploadsHandler11472026/10/01 09:52:32 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001148--- PASS: TestSkippedUploadsHandler (0.00s)1149=== CONT TestReadProxyHead1150--- PASS: TestRegisterCompletedObjectNeedsPendingRow (6.05s)1151=== CONT TestTombstonedObjectOfferedWithoutWaiting11522026-10-01 09:52:32.999 UTC [91305] ERROR: relation "goose_db_version" does not exist at character 3611532026-10-01 09:52:32.999 UTC [91305] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11542026/10/01 09:52:33 INFO Received uploads request method=POST path=/api/pending_closures11552026/10/01 09:52:33 INFO Aborted multipart uploads count=011562026/10/01 09:52:33 WARN Force mode enabled - objects will be deleted immediately without grace period11572026/10/01 09:52:33 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."11582026/10/01 09:52:33 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1159--- PASS: TestFailedS3DeleteKeepsTombstone (6.07s)1160=== CONT TestParseSize1161--- PASS: TestParseSize (0.00s)1162=== CONT TestReadProxyInvalidPath11632026/10/01 09:52:33 OK 20241026095416_initial_model.sql (586.69ms)11642026/10/01 09:52:33 OK 20251210153512_drop_unused_gin_index.sql (26.8ms)11652026/10/01 09:52:33 OK 20251218171726_add_pins.sql (61.32ms)11662026/10/01 09:52:33 INFO Received cleanup request method=DELETE path=/api/pending_closures11672026/10/01 09:52:33 INFO Aborted multipart uploads count=011682026/10/01 09:52:33 INFO Received uploads request method=POST path=/api/pending_closures11692026/10/01 09:52:33 OK 20260628120000_add_object_size_and_stats.sql (93.55ms)11702026/10/01 09:52:34 INFO Received cleanup request method=DELETE path=/api/pending_closures11712026/10/01 09:52:34 INFO Aborted multipart uploads count=111722026/10/01 09:52:34 OK 20260905000000_add_claims.sql (126.59ms)11732026-10-01 09:52:34.074 UTC [91312] ERROR: relation "goose_db_version" does not exist at character 3611742026-10-01 09:52:34.074 UTC [91312] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11752026/10/01 09:52:34 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11762026-10-01 09:52:34.101 UTC [91294] ERROR: Closure does not exist: id=111772026-10-01 09:52:34.101 UTC [91294] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE11782026-10-01 09:52:34.101 UTC [91294] STATEMENT: -- name: CommitPendingClosure :exec1179 SELECT commit_pending_closure($1::bigint)1180 1181--- PASS: TestService_cleanupPendingClosuresHandler (5.45s)1182=== CONT TestService_Rustfstest11832026/10/01 09:52:34 OK 20260920000000_drop_claims.sql (99.19ms)11842026/10/01 09:52:34 OK 20260923120000_add_pushes.sql (27.68ms)11852026/10/01 09:52:34 goose: successfully migrated database to version: 2026092312000011862026/10/01 09:52:34 OK 1_commit_pending_closure.sql (4.87ms)11872026/10/01 09:52:34 OK 2_object_stats_trigger.sql (473.17µs)11882026/10/01 09:52:34 OK 3_commit_push.sql (315.46µs)11892026/10/01 09:52:34 goose: up to current file version: 311902026-10-01 09:52:34.308 UTC [91321] ERROR: relation "goose_db_version" does not exist at character 3611912026-10-01 09:52:34.308 UTC [91321] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11922026/10/01 09:52:34 OK 20241026095416_initial_model.sql (249.79ms)11932026/10/01 09:52:34 OK 20251210153512_drop_unused_gin_index.sql (10.71ms)11942026/10/01 09:52:34 OK 20251218171726_add_pins.sql (28.65ms)11952026/10/01 09:52:34 OK 20260628120000_add_object_size_and_stats.sql (36.42ms)11962026/10/01 09:52:34 INFO Received uploads request method=POST path=/api/pending_closures11972026/10/01 09:52:34 INFO Received uploads request method=POST path=/api/pending_closures11982026/10/01 09:52:34 INFO Received uploads request method=POST path=/api/pending_closures11992026/10/01 09:52:34 OK 20260905000000_add_claims.sql (132.17ms)12002026/10/01 09:52:34 OK 20241026095416_initial_model.sql (242.73ms)12012026/10/01 09:52:34 OK 20251210153512_drop_unused_gin_index.sql (11.11ms)12022026/10/01 09:52:34 OK 20251218171726_add_pins.sql (33.21ms)12032026/10/01 09:52:34 OK 20260920000000_drop_claims.sql (53.77ms)12042026/10/01 09:52:34 OK 20260923120000_add_pushes.sql (34.08ms)12052026/10/01 09:52:34 goose: successfully migrated database to version: 2026092312000012062026/10/01 09:52:34 OK 1_commit_pending_closure.sql (2.74ms)12072026/10/01 09:52:34 OK 2_object_stats_trigger.sql (589.21µs)12082026/10/01 09:52:34 OK 3_commit_push.sql (372.42µs)12092026/10/01 09:52:34 goose: up to current file version: 312102026/10/01 09:52:34 OK 20260628120000_add_object_size_and_stats.sql (48.38ms)12112026-10-01 09:52:34.791 UTC [91323] ERROR: relation "goose_db_version" does not exist at character 3612122026-10-01 09:52:34.791 UTC [91323] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12132026/10/01 09:52:34 OK 20260905000000_add_claims.sql (85.01ms)12142026/10/01 09:52:34 OK 20260920000000_drop_claims.sql (106.16ms)12152026/10/01 09:52:34 OK 20260923120000_add_pushes.sql (25.47ms)12162026/10/01 09:52:34 goose: successfully migrated database to version: 2026092312000012172026/10/01 09:52:34 OK 1_commit_pending_closure.sql (2.95ms)12182026/10/01 09:52:34 OK 2_object_stats_trigger.sql (531.5µs)12192026/10/01 09:52:34 OK 3_commit_push.sql (332.54µs)12202026/10/01 09:52:34 goose: up to current file version: 312212026-10-01 09:52:34.997 UTC [91324] ERROR: relation "goose_db_version" does not exist at character 3612222026-10-01 09:52:34.997 UTC [91324] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12232026/10/01 09:52:35 INFO Received uploads request method=POST path=/api/pending_closures12242026-10-01 09:52:35.268 UTC [91325] ERROR: relation "goose_db_version" does not exist at character 3612252026-10-01 09:52:35.268 UTC [91325] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12262026/10/01 09:52:35 OK 20241026095416_initial_model.sql (390.23ms)12272026/10/01 09:52:35 OK 20251210153512_drop_unused_gin_index.sql (17.53ms)12282026/10/01 09:52:35 OK 20251218171726_add_pins.sql (55.31ms)12292026/10/01 09:52:35 OK 20260628120000_add_object_size_and_stats.sql (94.31ms)1230--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (6.17s)1231=== CONT TestCreatePin_ReservedPins12322026/10/01 09:52:35 OK 20241026095416_initial_model.sql (393.96ms)12332026/10/01 09:52:35 OK 20251210153512_drop_unused_gin_index.sql (17.58ms)12342026/10/01 09:52:35 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55351/oidc12352026/10/01 09:52:35 OK 20251218171726_add_pins.sql (55.24ms)12362026/10/01 09:52:35 OK 20260905000000_add_claims.sql (151.61ms)12372026/10/01 09:52:35 OK 20260628120000_add_object_size_and_stats.sql (76.04ms)12382026/10/01 09:52:35 OK 20260920000000_drop_claims.sql (122.61ms)1239--- PASS: TestReadProxyRootRedirectsToIndexHTML (6.24s)1240=== CONT TestOrphanedObjectsGCStressTest12412026/10/01 09:52:35 OK 20260923120000_add_pushes.sql (171.51ms)12422026/10/01 09:52:35 goose: successfully migrated database to version: 2026092312000012432026/10/01 09:52:35 OK 1_commit_pending_closure.sql (1.6ms)12442026/10/01 09:52:35 OK 2_object_stats_trigger.sql (382.92µs)12452026/10/01 09:52:35 OK 3_commit_push.sql (280.21µs)12462026/10/01 09:52:35 goose: up to current file version: 312472026/10/01 09:52:35 OK 20260905000000_add_claims.sql (252.91ms)12482026/10/01 09:52:35 OK 20241026095416_initial_model.sql (556.86ms)12492026/10/01 09:52:35 OK 20251210153512_drop_unused_gin_index.sql (29.73ms)12502026/10/01 09:52:36 OK 20251218171726_add_pins.sql (55.29ms)12512026/10/01 09:52:36 OK 20260920000000_drop_claims.sql (131.92ms)12522026/10/01 09:52:36 OK 20260923120000_add_pushes.sql (43.11ms)12532026/10/01 09:52:36 goose: successfully migrated database to version: 2026092312000012542026/10/01 09:52:36 OK 1_commit_pending_closure.sql (2.01ms)12552026/10/01 09:52:36 OK 2_object_stats_trigger.sql (463.63µs)12562026/10/01 09:52:36 OK 3_commit_push.sql (345µs)12572026/10/01 09:52:36 goose: up to current file version: 312582026/10/01 09:52:36 OK 20260628120000_add_object_size_and_stats.sql (99.25ms)12592026/10/01 09:52:36 OK 20260905000000_add_claims.sql (165.82ms)12602026/10/01 09:52:36 OK 20260920000000_drop_claims.sql (116.44ms)12612026/10/01 09:52:36 OK 20260923120000_add_pushes.sql (38.57ms)12622026/10/01 09:52:36 goose: successfully migrated database to version: 2026092312000012632026/10/01 09:52:36 OK 1_commit_pending_closure.sql (1.12ms)12642026/10/01 09:52:36 OK 2_object_stats_trigger.sql (297.75µs)12652026/10/01 09:52:36 OK 3_commit_push.sql (184.88µs)12662026/10/01 09:52:36 goose: up to current file version: 312672026/10/01 09:52:36 INFO Received uploads request method=POST path=/api/pending_closures12682026/10/01 09:52:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12692026/10/01 09:52:37 INFO Aborted multipart uploads count=012702026/10/01 09:52:37 WARN Force mode enabled - objects will be deleted immediately without grace period12712026/10/01 09:52:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12722026/10/01 09:52:37 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZTk3NDBhMTQtZmM4MC00OGM1LTgyZTUtOTc2OTc4NzFmYmI0LmU0NDVlYmZhLTFjMDQtNGI4MS05ZTY1LWE3ZTVjOGE2ZDM4MHgxNzkwODQ4MzU0Njg4NDA4MDAw parts=1012732026/10/01 09:52:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12742026/10/01 09:52:37 INFO Completed upload id=112752026/10/01 09:52:37 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000012762026/10/01 09:52:37 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=012772026/10/01 09:52:37 INFO Received uploads request method=POST path=/api/pending_closures12782026/10/01 09:52:37 INFO Vacuumed table table=pending_closures12792026/10/01 09:52:37 INFO Starting cleanup of old closures method=DELETE path=/api/closures12802026/10/01 09:52:37 INFO Vacuumed table table=pending_objects12812026/10/01 09:52:37 INFO Vacuumed table table=multipart_uploads12822026/10/01 09:52:37 INFO Vacuumed table table=closures12832026/10/01 09:52:37 INFO Aborted multipart uploads count=012842026/10/01 09:52:37 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=012852026/10/01 09:52:37 INFO Vacuumed table table=pending_closures12862026/10/01 09:52:37 INFO Vacuumed table table=objects1287--- PASS: TestGCSweepDeliversEachKeyOnce (7.09s)1288=== CONT TestReadProxy40412892026/10/01 09:52:37 INFO Vacuumed table table=pending_objects12902026/10/01 09:52:37 INFO Vacuumed table table=multipart_uploads1291--- PASS: TestReadProxyConditionalGet (7.53s)1292=== CONT TestPresignedUploadRegisteredBeforeCommit12932026/10/01 09:52:37 INFO Vacuumed table table=closures12942026/10/01 09:52:37 INFO Vacuumed table table=objects12952026/10/01 09:52:37 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001296--- PASS: TestService_createPendingClosureHandler (9.24s)1297=== CONT TestReadProxyNarStreaming12982026-10-01 09:52:38.075 UTC [91358] ERROR: relation "goose_db_version" does not exist at character 3612992026-10-01 09:52:38.075 UTC [91358] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13002026-10-01 09:52:38.326 UTC [91361] ERROR: relation "goose_db_version" does not exist at character 3613012026-10-01 09:52:38.326 UTC [91361] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13022026-10-01 09:52:38.457 UTC [91363] ERROR: relation "goose_db_version" does not exist at character 3613032026-10-01 09:52:38.457 UTC [91363] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13042026-10-01 09:52:38.458 UTC [91368] ERROR: relation "goose_db_version" does not exist at character 3613052026-10-01 09:52:38.458 UTC [91368] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13062026/10/01 09:52:38 OK 20241026095416_initial_model.sql (242.64ms)13072026/10/01 09:52:38 OK 20251210153512_drop_unused_gin_index.sql (17.35ms)13082026/10/01 09:52:38 OK 20251218171726_add_pins.sql (58.35ms)13092026/10/01 09:52:38 OK 20260628120000_add_object_size_and_stats.sql (71.82ms)13102026/10/01 09:52:38 OK 20260905000000_add_claims.sql (23.86ms)13112026/10/01 09:52:38 OK 20241026095416_initial_model.sql (285.21ms)13122026/10/01 09:52:38 OK 20251210153512_drop_unused_gin_index.sql (17.99ms)13132026/10/01 09:52:38 OK 20260920000000_drop_claims.sql (92.1ms)13142026/10/01 09:52:38 OK 20251218171726_add_pins.sql (134.25ms)13152026/10/01 09:52:38 OK 20260923120000_add_pushes.sql (118.68ms)13162026/10/01 09:52:38 goose: successfully migrated database to version: 2026092312000013172026/10/01 09:52:38 OK 1_commit_pending_closure.sql (1.01ms)13182026/10/01 09:52:38 OK 2_object_stats_trigger.sql (235.79µs)13192026/10/01 09:52:38 OK 3_commit_push.sql (173.5µs)13202026/10/01 09:52:38 goose: up to current file version: 313212026/10/01 09:52:38 OK 20241026095416_initial_model.sql (293.02ms)13222026/10/01 09:52:38 OK 20251210153512_drop_unused_gin_index.sql (46.03ms)13232026/10/01 09:52:38 OK 20260628120000_add_object_size_and_stats.sql (87.5ms)13242026/10/01 09:52:38 OK 20241026095416_initial_model.sql (374.28ms)13252026/10/01 09:52:38 OK 20251218171726_add_pins.sql (53.04ms)13262026/10/01 09:52:38 OK 20251210153512_drop_unused_gin_index.sql (29.29ms)13272026/10/01 09:52:39 OK 20260628120000_add_object_size_and_stats.sql (70.05ms)13282026/10/01 09:52:39 OK 20251218171726_add_pins.sql (70.97ms)13292026/10/01 09:52:39 OK 20260905000000_add_claims.sql (140.03ms)13302026/10/01 09:52:39 OK 20260920000000_drop_claims.sql (64.22ms)13312026/10/01 09:52:39 OK 20260628120000_add_object_size_and_stats.sql (74.73ms)13322026/10/01 09:52:39 OK 20260923120000_add_pushes.sql (26.81ms)13332026/10/01 09:52:39 goose: successfully migrated database to version: 2026092312000013342026/10/01 09:52:39 OK 1_commit_pending_closure.sql (998.21µs)13352026/10/01 09:52:39 OK 2_object_stats_trigger.sql (237.29µs)13362026/10/01 09:52:39 OK 3_commit_push.sql (174.67µs)13372026/10/01 09:52:39 goose: up to current file version: 313382026/10/01 09:52:39 OK 20260905000000_add_claims.sql (147.11ms)13392026/10/01 09:52:39 OK 20260905000000_add_claims.sql (109.42ms)13402026/10/01 09:52:39 OK 20260920000000_drop_claims.sql (75.41ms)13412026/10/01 09:52:39 OK 20260920000000_drop_claims.sql (33.93ms)13422026/10/01 09:52:39 OK 20260923120000_add_pushes.sql (24.97ms)13432026/10/01 09:52:39 goose: successfully migrated database to version: 2026092312000013442026/10/01 09:52:39 OK 1_commit_pending_closure.sql (1.25ms)13452026/10/01 09:52:39 OK 2_object_stats_trigger.sql (297.29µs)13462026/10/01 09:52:39 OK 3_commit_push.sql (284.92µs)13472026/10/01 09:52:39 goose: up to current file version: 313482026/10/01 09:52:39 OK 20260923120000_add_pushes.sql (55.84ms)13492026/10/01 09:52:39 goose: successfully migrated database to version: 2026092312000013502026/10/01 09:52:39 OK 1_commit_pending_closure.sql (1.6ms)13512026/10/01 09:52:39 OK 2_object_stats_trigger.sql (355.08µs)13522026/10/01 09:52:39 OK 3_commit_push.sql (268.63µs)13532026/10/01 09:52:39 goose: up to current file version: 313542026/10/01 09:52:39 INFO Received uploads request method=POST path=/api/pending_closures1355--- PASS: TestTombstonedObjectOfferedWithoutWaiting (6.79s)1356=== CONT TestOrphanedObjectsGC13572026/10/01 09:52:39 WARN Rate limiter enabled after throttle name=s3-test rate=513582026/10/01 09:52:39 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1359=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1360 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101361 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001362--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (9.93s)1363=== CONT TestCompletedNarNotReofferedAcrossClosures1364--- PASS: TestReadProxyHead (7.68s)1365=== CONT TestReadProxyNarinfoAlreadyDecompressed1366--- PASS: TestService_Rustfstest (6.44s)1367=== CONT TestCompleteMultipartUpload_ErrorButObjectExists13682026-10-01 09:52:41.080 UTC [91386] ERROR: relation "goose_db_version" does not exist at character 3613692026-10-01 09:52:41.080 UTC [91386] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1370--- PASS: TestReadProxyInvalidPath (7.52s)1371=== CONT TestReadProxyNarinfo13722026-10-01 09:52:41.422 UTC [91397] ERROR: relation "goose_db_version" does not exist at character 3613732026-10-01 09:52:41.422 UTC [91397] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13742026/10/01 09:52:41 OK 20241026095416_initial_model.sql (317.12ms)13752026/10/01 09:52:41 OK 20251210153512_drop_unused_gin_index.sql (19.14ms)13762026/10/01 09:52:41 OK 20251218171726_add_pins.sql (46.74ms)13772026/10/01 09:52:41 OK 20260628120000_add_object_size_and_stats.sql (62.81ms)13782026/10/01 09:52:41 OK 20260905000000_add_claims.sql (103.65ms)13792026/10/01 09:52:41 OK 20241026095416_initial_model.sql (253.54ms)13802026/10/01 09:52:41 OK 20260920000000_drop_claims.sql (22.43ms)13812026/10/01 09:52:41 OK 20251210153512_drop_unused_gin_index.sql (6.89ms)13822026/10/01 09:52:41 OK 20260923120000_add_pushes.sql (21.64ms)13832026/10/01 09:52:41 goose: successfully migrated database to version: 2026092312000013842026/10/01 09:52:41 OK 1_commit_pending_closure.sql (1.22ms)13852026/10/01 09:52:41 OK 2_object_stats_trigger.sql (289.38µs)13862026/10/01 09:52:41 OK 3_commit_push.sql (230.21µs)13872026/10/01 09:52:41 goose: up to current file version: 313882026/10/01 09:52:41 OK 20251218171726_add_pins.sql (43.4ms)13892026/10/01 09:52:41 OK 20260628120000_add_object_size_and_stats.sql (50.48ms)13902026/10/01 09:52:41 OK 20260905000000_add_claims.sql (94.54ms)13912026-10-01 09:52:42.031 UTC [91407] ERROR: relation "goose_db_version" does not exist at character 3613922026-10-01 09:52:42.031 UTC [91407] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13932026/10/01 09:52:42 OK 20260920000000_drop_claims.sql (68.26ms)13942026/10/01 09:52:42 OK 20260923120000_add_pushes.sql (20.73ms)13952026/10/01 09:52:42 goose: successfully migrated database to version: 2026092312000013962026/10/01 09:52:42 OK 1_commit_pending_closure.sql (981.67µs)13972026/10/01 09:52:42 OK 2_object_stats_trigger.sql (245.5µs)13982026/10/01 09:52:42 OK 3_commit_push.sql (197.92µs)13992026/10/01 09:52:42 goose: up to current file version: 314002026-10-01 09:52:42.227 UTC [91408] ERROR: relation "goose_db_version" does not exist at character 3614012026-10-01 09:52:42.227 UTC [91408] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14022026/10/01 09:52:42 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14032026/10/01 09:52:42 WARN Refused reserved pin name=worker-x86_64-linux14042026/10/01 09:52:42 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14052026/10/01 09:52:42 INFO Received create pin request method=POST path=/api/pins/my-app14062026/10/01 09:52:42 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1407--- PASS: TestCreatePin_ReservedPins (6.76s)1408=== CONT TestRedundantMultipartUpload14092026-10-01 09:52:42.330 UTC [91409] ERROR: relation "goose_db_version" does not exist at character 3614102026-10-01 09:52:42.330 UTC [91409] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14112026/10/01 09:52:42 OK 20241026095416_initial_model.sql (209.68ms)14122026/10/01 09:52:42 OK 20251210153512_drop_unused_gin_index.sql (11.3ms)14132026/10/01 09:52:42 OK 20251218171726_add_pins.sql (44.29ms)14142026/10/01 09:52:42 OK 20260628120000_add_object_size_and_stats.sql (48.52ms)14152026/10/01 09:52:42 OK 20260905000000_add_claims.sql (127.28ms)14162026/10/01 09:52:42 OK 20241026095416_initial_model.sql (282ms)14172026/10/01 09:52:42 OK 20251210153512_drop_unused_gin_index.sql (17.99ms)14182026/10/01 09:52:42 OK 20260920000000_drop_claims.sql (106.53ms)14192026/10/01 09:52:42 OK 20251218171726_add_pins.sql (61.61ms)14202026/10/01 09:52:42 OK 20260923120000_add_pushes.sql (38.74ms)14212026/10/01 09:52:42 goose: successfully migrated database to version: 2026092312000014222026/10/01 09:52:42 OK 1_commit_pending_closure.sql (4.91ms)14232026/10/01 09:52:42 OK 2_object_stats_trigger.sql (677µs)14242026/10/01 09:52:42 OK 3_commit_push.sql (409.04µs)14252026/10/01 09:52:42 goose: up to current file version: 314262026/10/01 09:52:42 OK 20260628120000_add_object_size_and_stats.sql (66.4ms)14272026/10/01 09:52:42 OK 20241026095416_initial_model.sql (379.72ms)14282026/10/01 09:52:42 OK 20251210153512_drop_unused_gin_index.sql (19.17ms)14292026/10/01 09:52:42 OK 20251218171726_add_pins.sql (52.65ms)14302026/10/01 09:52:42 OK 20260905000000_add_claims.sql (164.89ms)14312026/10/01 09:52:42 OK 20260628120000_add_object_size_and_stats.sql (90.35ms)14322026/10/01 09:52:43 OK 20260920000000_drop_claims.sql (121.37ms)14332026/10/01 09:52:43 OK 20260923120000_add_pushes.sql (127.14ms)14342026/10/01 09:52:43 goose: successfully migrated database to version: 2026092312000014352026/10/01 09:52:43 OK 20260905000000_add_claims.sql (185.23ms)14362026/10/01 09:52:43 OK 1_commit_pending_closure.sql (6.73ms)14372026/10/01 09:52:43 OK 2_object_stats_trigger.sql (967.67µs)14382026/10/01 09:52:43 OK 3_commit_push.sql (605.63µs)14392026/10/01 09:52:43 goose: up to current file version: 314402026/10/01 09:52:43 OK 20260920000000_drop_claims.sql (142.58ms)14412026/10/01 09:52:43 OK 20260923120000_add_pushes.sql (34.7ms)14422026/10/01 09:52:43 goose: successfully migrated database to version: 2026092312000014432026/10/01 09:52:43 OK 1_commit_pending_closure.sql (3.05ms)14442026/10/01 09:52:43 OK 2_object_stats_trigger.sql (663.75µs)14452026/10/01 09:52:43 OK 3_commit_push.sql (369.17µs)14462026/10/01 09:52:43 goose: up to current file version: 31447--- PASS: TestReadProxy404 (5.78s)1448=== CONT TestIsValidCachePath1449=== RUN TestIsValidCachePath/narinfo1450=== PAUSE TestIsValidCachePath/narinfo1451=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1452=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1453=== RUN TestIsValidCachePath/nar_zst1454=== PAUSE TestIsValidCachePath/nar_zst1455=== RUN TestIsValidCachePath/nar_xz1456=== PAUSE TestIsValidCachePath/nar_xz1457=== RUN TestIsValidCachePath/nar_bz21458=== PAUSE TestIsValidCachePath/nar_bz21459=== RUN TestIsValidCachePath/nar_uncompressed1460=== PAUSE TestIsValidCachePath/nar_uncompressed1461=== RUN TestIsValidCachePath/ls1462=== PAUSE TestIsValidCachePath/ls1463=== RUN TestIsValidCachePath/log1464=== PAUSE TestIsValidCachePath/log1465=== RUN TestIsValidCachePath/realisation1466=== PAUSE TestIsValidCachePath/realisation1467=== RUN TestIsValidCachePath/nix-cache-info1468=== PAUSE TestIsValidCachePath/nix-cache-info1469=== RUN TestIsValidCachePath/index.html1470=== PAUSE TestIsValidCachePath/index.html1471=== RUN TestIsValidCachePath/traversal_parent1472=== PAUSE TestIsValidCachePath/traversal_parent1473=== RUN TestIsValidCachePath/traversal_in_middle1474=== PAUSE TestIsValidCachePath/traversal_in_middle1475=== RUN TestIsValidCachePath/invalid_char_e1476=== PAUSE TestIsValidCachePath/invalid_char_e1477=== RUN TestIsValidCachePath/invalid_char_u1478=== PAUSE TestIsValidCachePath/invalid_char_u1479=== RUN TestIsValidCachePath/random_path1480=== PAUSE TestIsValidCachePath/random_path1481=== RUN TestIsValidCachePath/empty1482=== PAUSE TestIsValidCachePath/empty1483=== RUN TestIsValidCachePath/leading_slash1484=== PAUSE TestIsValidCachePath/leading_slash1485=== RUN TestIsValidCachePath/wrong_extension1486=== PAUSE TestIsValidCachePath/wrong_extension1487=== RUN TestIsValidCachePath/short_hash1488=== PAUSE TestIsValidCachePath/short_hash1489=== CONT TestPush_SignsNarinfosOfItsPendingObjects14902026/10/01 09:52:44 INFO Received uploads request method=POST path=/api/pending_closures14912026/10/01 09:52:44 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst14922026/10/01 09:52:44 INFO Received uploads request method=POST path=/api/pending_closures1493--- PASS: TestPresignedUploadRegisteredBeforeCommit (6.68s)1494=== CONT TestPush_RejectsBadRequests1495--- PASS: TestReadProxyNarStreaming (7.20s)1496=== CONT TestProxyHeadersOnlyTrustedOnSocket14972026-10-01 09:52:45.311 UTC [91435] ERROR: relation "goose_db_version" does not exist at character 3614982026-10-01 09:52:45.311 UTC [91435] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14992026-10-01 09:52:45.346 UTC [91436] ERROR: relation "goose_db_version" does not exist at character 3615002026-10-01 09:52:45.346 UTC [91436] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15012026-10-01 09:52:45.857 UTC [91443] ERROR: relation "goose_db_version" does not exist at character 3615022026-10-01 09:52:45.857 UTC [91443] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15032026/10/01 09:52:46 OK 20241026095416_initial_model.sql (597.85ms)15042026/10/01 09:52:46 OK 20241026095416_initial_model.sql (595.84ms)15052026/10/01 09:52:46 OK 20251210153512_drop_unused_gin_index.sql (42.15ms)15062026/10/01 09:52:46 OK 20251210153512_drop_unused_gin_index.sql (28.9ms)15072026/10/01 09:52:46 OK 20251218171726_add_pins.sql (78.7ms)15082026/10/01 09:52:46 OK 20251218171726_add_pins.sql (87.66ms)15092026/10/01 09:52:46 OK 20260628120000_add_object_size_and_stats.sql (79.93ms)15102026/10/01 09:52:46 OK 20260628120000_add_object_size_and_stats.sql (105.19ms)15112026-10-01 09:52:46.326 UTC [91447] ERROR: relation "goose_db_version" does not exist at character 3615122026-10-01 09:52:46.326 UTC [91447] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15132026/10/01 09:52:46 OK 20260905000000_add_claims.sql (103.01ms)15142026/10/01 09:52:46 OK 20260905000000_add_claims.sql (86.92ms)15152026/10/01 09:52:46 OK 20260920000000_drop_claims.sql (55.43ms)15162026/10/01 09:52:46 OK 20260920000000_drop_claims.sql (56.28ms)15172026/10/01 09:52:46 OK 20260923120000_add_pushes.sql (26.13ms)15182026/10/01 09:52:46 goose: successfully migrated database to version: 2026092312000015192026/10/01 09:52:46 OK 20260923120000_add_pushes.sql (27.01ms)15202026/10/01 09:52:46 goose: successfully migrated database to version: 2026092312000015212026/10/01 09:52:46 OK 1_commit_pending_closure.sql (2.78ms)15222026/10/01 09:52:46 OK 1_commit_pending_closure.sql (2.72ms)15232026/10/01 09:52:46 OK 2_object_stats_trigger.sql (607.38µs)15242026/10/01 09:52:46 OK 2_object_stats_trigger.sql (714.38µs)15252026/10/01 09:52:46 OK 3_commit_push.sql (401µs)15262026/10/01 09:52:46 goose: up to current file version: 315272026/10/01 09:52:46 OK 3_commit_push.sql (417.29µs)15282026/10/01 09:52:46 goose: up to current file version: 315292026/10/01 09:52:46 OK 20241026095416_initial_model.sql (483.96ms)15302026/10/01 09:52:46 OK 20251210153512_drop_unused_gin_index.sql (25.97ms)15312026-10-01 09:52:46.579 UTC [91450] ERROR: relation "goose_db_version" does not exist at character 3615322026-10-01 09:52:46.579 UTC [91450] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15332026/10/01 09:52:46 OK 20251218171726_add_pins.sql (73.45ms)15342026/10/01 09:52:46 OK 20260628120000_add_object_size_and_stats.sql (86.21ms)15352026/10/01 09:52:46 OK 20260905000000_add_claims.sql (160.54ms)15362026/10/01 09:52:46 OK 20241026095416_initial_model.sql (443.55ms)15372026/10/01 09:52:46 OK 20251210153512_drop_unused_gin_index.sql (26.68ms)15382026/10/01 09:52:46 OK 20260920000000_drop_claims.sql (129.52ms)15392026/10/01 09:52:46 OK 20251218171726_add_pins.sql (71.88ms)15402026/10/01 09:52:47 INFO Received uploads request method=POST path=/api/pending_closures15412026/10/01 09:52:47 OK 20260923120000_add_pushes.sql (24.12ms)15422026/10/01 09:52:47 goose: successfully migrated database to version: 2026092312000015432026/10/01 09:52:47 OK 1_commit_pending_closure.sql (1.82ms)15442026/10/01 09:52:47 OK 2_object_stats_trigger.sql (287.5µs)15452026/10/01 09:52:47 OK 3_commit_push.sql (173.08µs)15462026/10/01 09:52:47 goose: up to current file version: 315472026/10/01 09:52:47 OK 20260628120000_add_object_size_and_stats.sql (63.19ms)15482026/10/01 09:52:47 OK 20241026095416_initial_model.sql (463.95ms)15492026/10/01 09:52:47 OK 20251210153512_drop_unused_gin_index.sql (17.65ms)15502026/10/01 09:52:47 OK 20260905000000_add_claims.sql (190.58ms)15512026/10/01 09:52:47 OK 20251218171726_add_pins.sql (63.04ms)15522026/10/01 09:52:47 OK 20260628120000_add_object_size_and_stats.sql (72.14ms)15532026/10/01 09:52:47 OK 20260920000000_drop_claims.sql (148.43ms)15542026/10/01 09:52:47 OK 20260923120000_add_pushes.sql (30.8ms)15552026/10/01 09:52:47 goose: successfully migrated database to version: 2026092312000015562026/10/01 09:52:47 OK 1_commit_pending_closure.sql (1.35ms)15572026/10/01 09:52:47 OK 2_object_stats_trigger.sql (277.67µs)15582026/10/01 09:52:47 OK 3_commit_push.sql (241.25µs)15592026/10/01 09:52:47 goose: up to current file version: 315602026/10/01 09:52:47 OK 20260905000000_add_claims.sql (146.96ms)15612026/10/01 09:52:47 OK 20260920000000_drop_claims.sql (302.93ms)15622026/10/01 09:52:47 OK 20260923120000_add_pushes.sql (42.82ms)15632026/10/01 09:52:47 goose: successfully migrated database to version: 2026092312000015642026/10/01 09:52:47 OK 1_commit_pending_closure.sql (2.11ms)15652026/10/01 09:52:47 OK 2_object_stats_trigger.sql (454µs)15662026/10/01 09:52:47 OK 3_commit_push.sql (321.25µs)15672026/10/01 09:52:47 goose: up to current file version: 315682026-10-01 09:52:48.209 UTC [91500] ERROR: relation "goose_db_version" does not exist at character 3615692026-10-01 09:52:48.209 UTC [91500] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1570--- PASS: TestReadProxyNarinfoAlreadyDecompressed (8.27s)1571=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit15722026/10/01 09:52:48 OK 20241026095416_initial_model.sql (455.85ms)15732026/10/01 09:52:48 OK 20251210153512_drop_unused_gin_index.sql (20.79ms)15742026/10/01 09:52:48 INFO Received uploads request method=POST path=/api/pending_closures15752026/10/01 09:52:48 OK 20251218171726_add_pins.sql (75.19ms)15762026/10/01 09:52:48 OK 20260628120000_add_object_size_and_stats.sql (90.96ms)15772026/10/01 09:52:49 OK 20260905000000_add_claims.sql (204.26ms)1578=== NAME TestOrphanedObjectsGC1579 orphaned_objects_gc_test.go:290: GC Test Summary:1580 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1581 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1582 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1583 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1584 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1585--- PASS: TestOrphanedObjectsGC (9.85s)1586=== CONT TestParseSingleRange1587=== RUN TestParseSingleRange/none1588=== PAUSE TestParseSingleRange/none1589=== RUN TestParseSingleRange/unknown_unit1590=== PAUSE TestParseSingleRange/unknown_unit1591=== RUN TestParseSingleRange/multi-range_ignored1592=== PAUSE TestParseSingleRange/multi-range_ignored1593=== RUN TestParseSingleRange/malformed_no_dash1594=== PAUSE TestParseSingleRange/malformed_no_dash1595=== RUN TestParseSingleRange/malformed_both_empty1596=== PAUSE TestParseSingleRange/malformed_both_empty1597=== RUN TestParseSingleRange/malformed_end_before_start1598=== PAUSE TestParseSingleRange/malformed_end_before_start1599=== RUN TestParseSingleRange/closed1600=== PAUSE TestParseSingleRange/closed1601=== RUN TestParseSingleRange/open-ended1602=== PAUSE TestParseSingleRange/open-ended1603=== RUN TestParseSingleRange/end_clamped_to_size1604=== PAUSE TestParseSingleRange/end_clamped_to_size1605=== RUN TestParseSingleRange/suffix1606=== PAUSE TestParseSingleRange/suffix1607=== RUN TestParseSingleRange/suffix_exceeds_size1608=== PAUSE TestParseSingleRange/suffix_exceeds_size1609=== RUN TestParseSingleRange/single_byte1610=== PAUSE TestParseSingleRange/single_byte1611=== RUN TestParseSingleRange/start_past_EOF1612=== PAUSE TestParseSingleRange/start_past_EOF1613=== RUN TestParseSingleRange/start_far_past_EOF1614=== PAUSE TestParseSingleRange/start_far_past_EOF1615=== CONT TestPush_CompleteCommitsEveryRoot16162026/10/01 09:52:49 OK 20260920000000_drop_claims.sql (147.28ms)16172026/10/01 09:52:49 OK 20260923120000_add_pushes.sql (28.75ms)16182026/10/01 09:52:49 goose: successfully migrated database to version: 2026092312000016192026/10/01 09:52:49 OK 1_commit_pending_closure.sql (1.53ms)16202026/10/01 09:52:49 OK 2_object_stats_trigger.sql (361.54µs)16212026/10/01 09:52:49 OK 3_commit_push.sql (311.08µs)16222026/10/01 09:52:49 goose: up to current file version: 316232026/10/01 09:52:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16242026/10/01 09:52:49 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZTk3NDBhMTQtZmM4MC00OGM1LTgyZTUtOTc2OTc4NzFmYmI0Ljg5NGQwY2EzLWFkZmEtNGU4Yy1iMGYxLWNmNjNiOGQzMzIzMHgxNzkwODQ4MzY4ODU5NzY5MDAw16252026/10/01 09:52:49 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZTk3NDBhMTQtZmM4MC00OGM1LTgyZTUtOTc2OTc4NzFmYmI0Ljg5NGQwY2EzLWFkZmEtNGU4Yy1iMGYxLWNmNjNiOGQzMzIzMHgxNzkwODQ4MzY4ODU5NzY5MDAw parts=11626--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (8.88s)1627=== CONT TestPresentNotReportedWhileGCDeletesClosure1628--- PASS: TestReadProxyNarinfo (8.35s)1629=== CONT TestPush_OverlappingRootsStoreOneRowPerKey16302026-10-01 09:52:49.902 UTC [91517] ERROR: relation "goose_db_version" does not exist at character 3616312026-10-01 09:52:49.902 UTC [91517] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16322026/10/01 09:52:50 INFO Received uploads request method=POST path=/api/pending_closures16332026/10/01 09:52:50 INFO Received uploads request method=POST path=/api/pending_closures16342026/10/01 09:52:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16352026/10/01 09:52:50 OK 20241026095416_initial_model.sql (434.42ms)16362026/10/01 09:52:50 OK 20251210153512_drop_unused_gin_index.sql (26.18ms)16372026/10/01 09:52:50 OK 20251218171726_add_pins.sql (61.04ms)16382026/10/01 09:52:50 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZTk3NDBhMTQtZmM4MC00OGM1LTgyZTUtOTc2OTc4NzFmYmI0LmNmMGY5MTY0LTU0YTItNDg5NC04MWQ5LTAxNzQwMzFkZDE2N3gxNzkwODQ4MzY3MDQ1NDM5MDAw parts=1216392026/10/01 09:52:50 INFO Received uploads request method=POST path=/api/pending_closures1640--- PASS: TestCompletedNarNotReofferedAcrossClosures (10.71s)1641=== CONT TestReadRedirectUsesPublicS3URL16422026/10/01 09:52:50 OK 20260628120000_add_object_size_and_stats.sql (80.46ms)16432026-10-01 09:52:50.690 UTC [91519] ERROR: relation "goose_db_version" does not exist at character 3616442026-10-01 09:52:50.690 UTC [91519] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16452026/10/01 09:52:50 OK 20260905000000_add_claims.sql (193.65ms)16462026/10/01 09:52:50 OK 20260920000000_drop_claims.sql (57.87ms)16472026-10-01 09:52:50.893 UTC [91522] ERROR: relation "goose_db_version" does not exist at character 3616482026-10-01 09:52:50.893 UTC [91522] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16492026/10/01 09:52:50 OK 20260923120000_add_pushes.sql (41.1ms)16502026/10/01 09:52:50 goose: successfully migrated database to version: 2026092312000016512026/10/01 09:52:50 OK 1_commit_pending_closure.sql (3ms)16522026/10/01 09:52:50 OK 2_object_stats_trigger.sql (627.33µs)16532026/10/01 09:52:50 OK 3_commit_push.sql (439.08µs)16542026/10/01 09:52:50 goose: up to current file version: 316552026/10/01 09:52:51 OK 20241026095416_initial_model.sql (293.08ms)16562026/10/01 09:52:51 OK 20251210153512_drop_unused_gin_index.sql (14.77ms)16572026/10/01 09:52:51 OK 20251218171726_add_pins.sql (77.41ms)16582026/10/01 09:52:51 OK 20260628120000_add_object_size_and_stats.sql (72.13ms)16592026/10/01 09:52:51 OK 20260905000000_add_claims.sql (70.96ms)16602026/10/01 09:52:51 OK 20241026095416_initial_model.sql (289.93ms)16612026/10/01 09:52:51 OK 20251210153512_drop_unused_gin_index.sql (20.07ms)16622026/10/01 09:52:51 OK 20260920000000_drop_claims.sql (107.96ms)16632026/10/01 09:52:51 INFO Received push request method=POST path=/api/pushes16642026/10/01 09:52:51 OK 20260923120000_add_pushes.sql (120.06ms)16652026/10/01 09:52:51 goose: successfully migrated database to version: 2026092312000016662026/10/01 09:52:51 OK 20251218171726_add_pins.sql (210.92ms)16672026/10/01 09:52:51 OK 1_commit_pending_closure.sql (12.31ms)16682026/10/01 09:52:51 OK 2_object_stats_trigger.sql (2.37ms)16692026/10/01 09:52:51 OK 3_commit_push.sql (620.46µs)16702026/10/01 09:52:51 goose: up to current file version: 316712026/10/01 09:52:51 OK 20260628120000_add_object_size_and_stats.sql (29.64ms)16722026/10/01 09:52:51 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16732026/10/01 09:52:51 INFO Signed narinfos id=1 count=11674--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (8.30s)1675=== CONT TestReadProxyRangeRequest16762026/10/01 09:52:51 OK 20260905000000_add_claims.sql (177.21ms)16772026/10/01 09:52:51 OK 20260920000000_drop_claims.sql (91.47ms)16782026/10/01 09:52:51 OK 20260923120000_add_pushes.sql (51.45ms)16792026/10/01 09:52:51 goose: successfully migrated database to version: 2026092312000016802026/10/01 09:52:51 OK 1_commit_pending_closure.sql (3.49ms)16812026/10/01 09:52:51 OK 2_object_stats_trigger.sql (793.5µs)16822026/10/01 09:52:51 OK 3_commit_push.sql (472.71µs)16832026/10/01 09:52:51 goose: up to current file version: 31684=== RUN TestPush_RejectsBadRequests/no_roots1685=== PAUSE TestPush_RejectsBadRequests/no_roots1686=== RUN TestPush_RejectsBadRequests/no_objects1687=== PAUSE TestPush_RejectsBadRequests/no_objects1688=== RUN TestPush_RejectsBadRequests/bad_root1689=== PAUSE TestPush_RejectsBadRequests/bad_root1690=== RUN TestPush_RejectsBadRequests/root_not_in_objects1691=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1692=== CONT TestGCTaskStore_Fail1693--- PASS: TestGCTaskStore_Fail (0.00s)1694=== CONT TestCacheConfigHandlerMaxNarSize1695--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1696=== CONT TestGenerateLandingPage1697--- PASS: TestGenerateLandingPage (0.00s)1698=== CONT TestService_readinessHandler16992026/10/01 09:52:52 INFO Starting HTTP server address=/nix/var/nix/builds/nix-90619-4025703153/TestProxyHeadersOnlyTrustedOnSocket938882868/001/proxy.sock17002026/10/01 09:52:52 INFO Starting HTTP server address=127.0.0.1:5548317012026/10/01 09:52:52 WARN mTLS auth: subject not in bound subjects subject="CN=someone"17022026/10/01 09:52:52 INFO Shutdown signal received, draining in-flight requests timeout=10s1703=== CONT TestService_healthCheckHandler1704--- PASS: TestProxyHeadersOnlyTrustedOnSocket (7.87s)17052026/10/01 09:52:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17062026/10/01 09:52:53 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZTk3NDBhMTQtZmM4MC00OGM1LTgyZTUtOTc2OTc4NzFmYmI0LjY4OWIzMGRiLTAzNDAtNGNlZC04MTQxLWNmZjllNzVkYTc4NXgxNzkwODQ4MzcwMTAxMzQzMDAw parts=121707--- PASS: TestRedundantMultipartUpload (11.36s)1708=== CONT TestGracefulShutdownDrainsInflight17092026/10/01 09:52:53 INFO Starting HTTP server address=127.0.0.1:5549017102026/10/01 09:52:53 INFO Shutdown signal received, draining in-flight requests timeout=10s1711--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1712=== CONT TestResolveDBConnectionString1713=== RUN TestResolveDBConnectionString/flag_wins1714=== PAUSE TestResolveDBConnectionString/flag_wins1715=== RUN TestResolveDBConnectionString/file_when_flag_empty1716=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1717=== RUN TestResolveDBConnectionString/missing_file_is_an_error1718=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1719=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1720=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1721=== RUN TestResolveDBConnectionString/nothing_configured1722=== PAUSE TestResolveDBConnectionString/nothing_configured1723=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock17242026-10-01 09:52:53.806 UTC [91544] ERROR: relation "goose_db_version" does not exist at character 3617252026-10-01 09:52:53.806 UTC [91544] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17262026-10-01 09:52:54.235 UTC [91560] ERROR: relation "goose_db_version" does not exist at character 3617272026-10-01 09:52:54.235 UTC [91560] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17282026/10/01 09:52:54 OK 20241026095416_initial_model.sql (289.69ms)17292026/10/01 09:52:54 OK 20251210153512_drop_unused_gin_index.sql (24.35ms)17302026/10/01 09:52:54 OK 20251218171726_add_pins.sql (65.65ms)17312026/10/01 09:52:54 OK 20260628120000_add_object_size_and_stats.sql (73.51ms)17322026-10-01 09:52:54.504 UTC [91562] ERROR: relation "goose_db_version" does not exist at character 3617332026-10-01 09:52:54.504 UTC [91562] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17342026/10/01 09:52:54 OK 20260905000000_add_claims.sql (101.89ms)17352026-10-01 09:52:54.537 UTC [91563] ERROR: relation "goose_db_version" does not exist at character 3617362026-10-01 09:52:54.537 UTC [91563] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17372026/10/01 09:52:54 OK 20260920000000_drop_claims.sql (20.93ms)17382026/10/01 09:52:54 OK 20260923120000_add_pushes.sql (23.34ms)17392026/10/01 09:52:54 goose: successfully migrated database to version: 2026092312000017402026/10/01 09:52:54 OK 1_commit_pending_closure.sql (1.87ms)17412026/10/01 09:52:54 OK 2_object_stats_trigger.sql (377.38µs)17422026/10/01 09:52:54 OK 3_commit_push.sql (293.79µs)17432026/10/01 09:52:54 goose: up to current file version: 317442026/10/01 09:52:54 OK 20241026095416_initial_model.sql (312.5ms)17452026/10/01 09:52:54 OK 20251210153512_drop_unused_gin_index.sql (16.89ms)17462026/10/01 09:52:54 OK 20251218171726_add_pins.sql (72.83ms)17472026/10/01 09:52:54 OK 20260628120000_add_object_size_and_stats.sql (104.72ms)17482026/10/01 09:52:55 OK 20260905000000_add_claims.sql (140.78ms)17492026/10/01 09:52:55 OK 20241026095416_initial_model.sql (452.81ms)17502026/10/01 09:52:55 OK 20251210153512_drop_unused_gin_index.sql (37.98ms)17512026/10/01 09:52:55 OK 20260920000000_drop_claims.sql (115.1ms)17522026/10/01 09:52:55 OK 20260923120000_add_pushes.sql (45.82ms)17532026/10/01 09:52:55 goose: successfully migrated database to version: 2026092312000017542026/10/01 09:52:55 OK 1_commit_pending_closure.sql (4.37ms)17552026/10/01 09:52:55 OK 2_object_stats_trigger.sql (5.76ms)17562026/10/01 09:52:55 INFO Received push request method=POST path=/api/pushes17572026/10/01 09:52:55 OK 3_commit_push.sql (941.46µs)17582026/10/01 09:52:55 goose: up to current file version: 317592026/10/01 09:52:55 OK 20251218171726_add_pins.sql (92.44ms)17602026/10/01 09:52:55 OK 20241026095416_initial_model.sql (529.85ms)17612026/10/01 09:52:55 OK 20251210153512_drop_unused_gin_index.sql (28.63ms)17622026/10/01 09:52:55 OK 20260628120000_add_object_size_and_stats.sql (104.27ms)17632026/10/01 09:52:55 OK 20251218171726_add_pins.sql (101.6ms)17642026/10/01 09:52:55 INFO Received complete push request method=POST path=/api/pushes/1/complete17652026/10/01 09:52:55 INFO Received push request method=POST path=/api/pushes17662026/10/01 09:52:55 OK 20260628120000_add_object_size_and_stats.sql (80.96ms)17672026/10/01 09:52:55 OK 20260905000000_add_claims.sql (186.94ms)17682026/10/01 09:52:55 INFO Aborted multipart uploads count=017692026/10/01 09:52:55 WARN Force mode enabled - objects will be deleted immediately without grace period17702026/10/01 09:52:55 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=017712026/10/01 09:52:55 OK 20260905000000_add_claims.sql (174.19ms)17722026/10/01 09:52:55 INFO Vacuumed table table=pending_closures17732026/10/01 09:52:55 OK 20260920000000_drop_claims.sql (137.28ms)17742026/10/01 09:52:55 INFO Vacuumed table table=pending_objects17752026/10/01 09:52:55 OK 20260923120000_add_pushes.sql (64.11ms)17762026/10/01 09:52:55 goose: successfully migrated database to version: 2026092312000017772026/10/01 09:52:55 OK 1_commit_pending_closure.sql (8.33ms)17782026/10/01 09:52:55 OK 2_object_stats_trigger.sql (1.21ms)17792026/10/01 09:52:55 OK 3_commit_push.sql (737.08µs)17802026/10/01 09:52:55 goose: up to current file version: 317812026/10/01 09:52:55 INFO Vacuumed table table=multipart_uploads17822026/10/01 09:52:55 OK 20260920000000_drop_claims.sql (150.31ms)17832026/10/01 09:52:55 OK 20260923120000_add_pushes.sql (53.11ms)17842026/10/01 09:52:55 goose: successfully migrated database to version: 2026092312000017852026/10/01 09:52:55 OK 1_commit_pending_closure.sql (4.6ms)17862026/10/01 09:52:55 OK 2_object_stats_trigger.sql (1.24ms)17872026/10/01 09:52:55 OK 3_commit_push.sql (813.42µs)17882026/10/01 09:52:55 goose: up to current file version: 317892026/10/01 09:52:55 INFO Vacuumed table table=closures17902026/10/01 09:52:55 INFO Received push request method=POST path=/api/pushes17912026/10/01 09:52:55 INFO Vacuumed table table=objects17922026/10/01 09:52:55 INFO Received complete push request method=POST path=/api/pushes/2/complete1793--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (7.64s)1794=== CONT TestPushDedupSurvivesConcurrentGC17952026/10/01 09:52:56 INFO Received complete push request method=POST path=/api/pushes/1/complete1796--- PASS: TestPush_CompleteCommitsEveryRoot (6.82s)1797=== CONT TestClientFallsBackToClosures17982026-10-01 09:52:56.195 UTC [91576] ERROR: relation "goose_db_version" does not exist at character 3617992026-10-01 09:52:56.195 UTC [91576] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18002026/10/01 09:52:56 INFO Received push request method=POST path=/api/pushes1801--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (7.09s)1802=== CONT TestGCMetrics18032026/10/01 09:52:56 OK 20241026095416_initial_model.sql (443.02ms)18042026/10/01 09:52:56 OK 20251210153512_drop_unused_gin_index.sql (5.75ms)1805=== NAME TestOrphanedObjectsGCStressTest1806 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains18072026/10/01 09:52:56 OK 20251218171726_add_pins.sql (36.84ms)18082026/10/01 09:52:56 OK 20260628120000_add_object_size_and_stats.sql (49.7ms)1809 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion18102026/10/01 09:52:56 OK 20260905000000_add_claims.sql (47.82ms)18112026/10/01 09:52:56 OK 20260920000000_drop_claims.sql (15.38ms)18122026/10/01 09:52:56 OK 20260923120000_add_pushes.sql (5.57ms)18132026/10/01 09:52:56 goose: successfully migrated database to version: 2026092312000018142026/10/01 09:52:56 OK 1_commit_pending_closure.sql (3.49ms)18152026/10/01 09:52:56 OK 2_object_stats_trigger.sql (1.16ms)18162026/10/01 09:52:56 OK 3_commit_push.sql (893.13µs)18172026/10/01 09:52:56 goose: up to current file version: 318182026-10-01 09:52:56.931 UTC [91598] ERROR: relation "goose_db_version" does not exist at character 3618192026-10-01 09:52:56.931 UTC [91598] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18202026-10-01 09:52:56.937 UTC [91599] ERROR: relation "goose_db_version" does not exist at character 3618212026-10-01 09:52:56.937 UTC [91599] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18222026-10-01 09:52:56.984 UTC [91602] ERROR: relation "goose_db_version" does not exist at character 3618232026-10-01 09:52:56.984 UTC [91602] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18242026/10/01 09:52:57 OK 20241026095416_initial_model.sql (158.27ms)18252026/10/01 09:52:57 OK 20241026095416_initial_model.sql (158.49ms)18262026/10/01 09:52:57 OK 20251210153512_drop_unused_gin_index.sql (29.21ms)18272026/10/01 09:52:57 OK 20251210153512_drop_unused_gin_index.sql (29.47ms)18282026/10/01 09:52:57 OK 20251218171726_add_pins.sql (55.55ms)18292026/10/01 09:52:57 OK 20241026095416_initial_model.sql (220.75ms)18302026/10/01 09:52:57 OK 20251218171726_add_pins.sql (69.9ms)1831--- PASS: TestReadRedirectUsesPublicS3URL (6.69s)1832=== CONT TestGCBugBareHashReferences18332026/10/01 09:52:57 OK 20251210153512_drop_unused_gin_index.sql (17.5ms)18342026/10/01 09:52:57 OK 20260628120000_add_object_size_and_stats.sql (48.08ms)18352026/10/01 09:52:57 OK 20260628120000_add_object_size_and_stats.sql (49.29ms)18362026/10/01 09:52:57 OK 20251218171726_add_pins.sql (56.41ms)18372026/10/01 09:52:57 OK 20260628120000_add_object_size_and_stats.sql (47.57ms)18382026/10/01 09:52:57 OK 20260905000000_add_claims.sql (88.18ms)1839--- PASS: TestPresentNotReportedWhileGCDeletesClosure (7.98s)1840=== CONT TestLeadEndsOnShutdown18412026/10/01 09:52:57 OK 20260905000000_add_claims.sql (80.64ms)18422026/10/01 09:52:57 OK 20260920000000_drop_claims.sql (61.76ms)18432026/10/01 09:52:57 OK 20260920000000_drop_claims.sql (69.78ms)18442026/10/01 09:52:57 OK 20260923120000_add_pushes.sql (11.85ms)18452026/10/01 09:52:57 goose: successfully migrated database to version: 2026092312000018462026/10/01 09:52:57 OK 20260923120000_add_pushes.sql (11.99ms)18472026/10/01 09:52:57 goose: successfully migrated database to version: 2026092312000018482026/10/01 09:52:57 OK 20260905000000_add_claims.sql (89.78ms)18492026/10/01 09:52:57 OK 1_commit_pending_closure.sql (2.35ms)18502026/10/01 09:52:57 OK 1_commit_pending_closure.sql (2.48ms)18512026/10/01 09:52:57 OK 2_object_stats_trigger.sql (406.04µs)18522026/10/01 09:52:57 OK 2_object_stats_trigger.sql (459.5µs)18532026/10/01 09:52:57 OK 3_commit_push.sql (228.25µs)18542026/10/01 09:52:57 goose: up to current file version: 318552026/10/01 09:52:57 OK 3_commit_push.sql (235.25µs)18562026/10/01 09:52:57 goose: up to current file version: 318572026/10/01 09:52:57 OK 20260920000000_drop_claims.sql (83.15ms)18582026/10/01 09:52:57 OK 20260923120000_add_pushes.sql (22.33ms)18592026/10/01 09:52:57 goose: successfully migrated database to version: 2026092312000018602026/10/01 09:52:57 OK 1_commit_pending_closure.sql (1.68ms)18612026/10/01 09:52:57 OK 2_object_stats_trigger.sql (433.67µs)18622026/10/01 09:52:57 OK 3_commit_push.sql (248.13µs)18632026/10/01 09:52:57 goose: up to current file version: 318642026-10-01 09:52:57.770 UTC [91616] ERROR: relation "goose_db_version" does not exist at character 3618652026-10-01 09:52:57.770 UTC [91616] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18662026/10/01 09:52:57 WARN readiness check failed error="closed pool"1867--- PASS: TestService_readinessHandler (5.68s)1868=== CONT TestLeadElectsOneAndHandsOver18692026/10/01 09:52:58 OK 20241026095416_initial_model.sql (263.8ms)18702026/10/01 09:52:58 OK 20251210153512_drop_unused_gin_index.sql (8.4ms)18712026/10/01 09:52:58 OK 20251218171726_add_pins.sql (32.17ms)18722026/10/01 09:52:58 OK 20260628120000_add_object_size_and_stats.sql (42.59ms)18732026/10/01 09:52:58 OK 20260905000000_add_claims.sql (103.53ms)1874--- PASS: TestReadProxyRangeRequest (6.71s)1875=== CONT TestGCTaskStore_GetReturnsLatest1876--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1877=== CONT TestObjectStatsTrigger18782026/10/01 09:52:58 OK 20260920000000_drop_claims.sql (115.37ms)18792026/10/01 09:52:58 OK 20260923120000_add_pushes.sql (32.23ms)18802026/10/01 09:52:58 goose: successfully migrated database to version: 2026092312000018812026/10/01 09:52:58 OK 1_commit_pending_closure.sql (856µs)18822026/10/01 09:52:58 OK 2_object_stats_trigger.sql (256.13µs)18832026/10/01 09:52:58 OK 3_commit_push.sql (192.58µs)18842026/10/01 09:52:58 goose: up to current file version: 31885--- PASS: TestService_healthCheckHandler (5.83s)1886=== CONT TestGCTaskStore_PhaseUpdates1887--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1888=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded18892026-10-01 09:52:59.365 UTC [91656] ERROR: relation "goose_db_version" does not exist at character 3618902026-10-01 09:52:59.365 UTC [91656] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18912026-10-01 09:52:59.537 UTC [91661] ERROR: relation "goose_db_version" does not exist at character 3618922026-10-01 09:52:59.537 UTC [91661] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18932026-10-01 09:52:59.608 UTC [91665] ERROR: relation "goose_db_version" does not exist at character 3618942026-10-01 09:52:59.608 UTC [91665] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18952026/10/01 09:52:59 OK 20241026095416_initial_model.sql (183.65ms)18962026/10/01 09:52:59 OK 20251210153512_drop_unused_gin_index.sql (8.98ms)18972026/10/01 09:52:59 OK 20251218171726_add_pins.sql (39.55ms)18982026/10/01 09:52:59 OK 20260628120000_add_object_size_and_stats.sql (48.15ms)18992026/10/01 09:52:59 OK 20260905000000_add_claims.sql (39.11ms)19002026/10/01 09:52:59 OK 20241026095416_initial_model.sql (146.06ms)19012026/10/01 09:52:59 OK 20260920000000_drop_claims.sql (8.72ms)19022026/10/01 09:52:59 OK 20251210153512_drop_unused_gin_index.sql (9.84ms)19032026/10/01 09:52:59 OK 20260923120000_add_pushes.sql (9.74ms)19042026/10/01 09:52:59 goose: successfully migrated database to version: 2026092312000019052026/10/01 09:52:59 OK 1_commit_pending_closure.sql (965.46µs)19062026/10/01 09:52:59 OK 2_object_stats_trigger.sql (219.63µs)19072026/10/01 09:52:59 OK 3_commit_push.sql (1.31ms)19082026/10/01 09:52:59 goose: up to current file version: 319092026/10/01 09:52:59 OK 20241026095416_initial_model.sql (107.28ms)19102026/10/01 09:52:59 OK 20251210153512_drop_unused_gin_index.sql (18.83ms)19112026/10/01 09:52:59 OK 20251218171726_add_pins.sql (43.75ms)19122026/10/01 09:52:59 OK 20251218171726_add_pins.sql (35.28ms)19132026/10/01 09:52:59 OK 20260628120000_add_object_size_and_stats.sql (45.52ms)19142026/10/01 09:52:59 OK 20260628120000_add_object_size_and_stats.sql (33.04ms)19152026/10/01 09:53:00 OK 20260905000000_add_claims.sql (190.55ms)19162026/10/01 09:53:00 OK 20260905000000_add_claims.sql (199.77ms)19172026/10/01 09:53:00 OK 20260920000000_drop_claims.sql (79.74ms)19182026/10/01 09:53:00 OK 20260920000000_drop_claims.sql (80.62ms)19192026/10/01 09:53:00 OK 20260923120000_add_pushes.sql (28.74ms)19202026/10/01 09:53:00 goose: successfully migrated database to version: 2026092312000019212026/10/01 09:53:00 OK 1_commit_pending_closure.sql (954.21µs)19222026/10/01 09:53:00 OK 2_object_stats_trigger.sql (235.83µs)19232026/10/01 09:53:00 OK 3_commit_push.sql (207.92µs)19242026/10/01 09:53:00 goose: up to current file version: 319252026/10/01 09:53:00 OK 20260923120000_add_pushes.sql (36.05ms)19262026/10/01 09:53:00 goose: successfully migrated database to version: 2026092312000019272026/10/01 09:53:00 OK 1_commit_pending_closure.sql (1.71ms)19282026/10/01 09:53:00 OK 2_object_stats_trigger.sql (608.33µs)19292026/10/01 09:53:00 OK 3_commit_push.sql (191.58µs)19302026/10/01 09:53:00 goose: up to current file version: 319312026-10-01 09:53:00.305 UTC [91694] ERROR: relation "goose_db_version" does not exist at character 3619322026-10-01 09:53:00.305 UTC [91694] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19332026/10/01 09:53:00 INFO Received uploads request method=POST path=/api/pending_closures19342026/10/01 09:53:00 INFO Aborted multipart uploads count=019352026/10/01 09:53:00 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=019362026/10/01 09:53:00 INFO Vacuumed table table=pending_closures19372026/10/01 09:53:00 INFO Vacuumed table table=pending_objects19382026/10/01 09:53:00 INFO Vacuumed table table=multipart_uploads19392026/10/01 09:53:00 INFO Vacuumed table table=closures19402026/10/01 09:53:00 INFO Vacuumed table table=objects19412026/10/01 09:53:00 INFO Aborted multipart uploads count=019422026/10/01 09:53:00 WARN Force mode enabled - objects will be deleted immediately without grace period19432026/10/01 09:53:00 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=019442026/10/01 09:53:00 INFO Vacuumed table table=pending_closures19452026/10/01 09:53:00 INFO Vacuumed table table=pending_objects19462026/10/01 09:53:00 INFO Vacuumed table table=multipart_uploads19472026/10/01 09:53:00 INFO Vacuumed table table=closures19482026/10/01 09:53:00 INFO Vacuumed table table=objects19492026/10/01 09:53:00 INFO Aborted multipart uploads count=019502026/10/01 09:53:00 WARN Force mode enabled - objects will be deleted immediately without grace period19512026/10/01 09:53:00 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=019522026/10/01 09:53:00 INFO Vacuumed table table=pending_closures1953--- PASS: TestPushDedupSurvivesConcurrentGC (4.81s)1954=== CONT TestGCTaskStore_CompletedAllowsNewTask1955--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1956=== CONT TestMultipartCleanup19572026/10/01 09:53:00 INFO Vacuumed table table=pending_objects19582026/10/01 09:53:00 INFO Vacuumed table table=multipart_uploads19592026/10/01 09:53:00 INFO Vacuumed table table=closures19602026/10/01 09:53:00 INFO Vacuumed table table=objects1961--- PASS: TestGCMetrics (4.13s)1962=== CONT TestMetricsInventory19632026/10/01 09:53:00 OK 20241026095416_initial_model.sql (399.78ms)19642026-10-01 09:53:00.805 UTC [91713] ERROR: relation "goose_db_version" does not exist at character 3619652026-10-01 09:53:00.805 UTC [91713] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19662026/10/01 09:53:00 OK 20251210153512_drop_unused_gin_index.sql (11.46ms)19672026/10/01 09:53:00 OK 20251218171726_add_pins.sql (60.95ms)1968--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (7.20s)1969=== CONT TestNARDeduplicationMetadataUploadBug19702026/10/01 09:53:00 OK 20260628120000_add_object_size_and_stats.sql (20.13ms)19712026/10/01 09:53:01 OK 20260905000000_add_claims.sql (104.47ms)19722026/10/01 09:53:01 OK 20260920000000_drop_claims.sql (71.01ms)19732026/10/01 09:53:01 OK 20260923120000_add_pushes.sql (27.52ms)19742026/10/01 09:53:01 goose: successfully migrated database to version: 2026092312000019752026/10/01 09:53:01 OK 1_commit_pending_closure.sql (1ms)19762026/10/01 09:53:01 OK 2_object_stats_trigger.sql (245.5µs)19772026/10/01 09:53:01 OK 3_commit_push.sql (181.33µs)19782026/10/01 09:53:01 goose: up to current file version: 319792026/10/01 09:53:01 OK 20241026095416_initial_model.sql (309ms)19802026/10/01 09:53:01 OK 20251210153512_drop_unused_gin_index.sql (16.13ms)19812026/10/01 09:53:01 OK 20251218171726_add_pins.sql (39.76ms)19822026/10/01 09:53:01 OK 20260628120000_add_object_size_and_stats.sql (60.01ms)19832026/10/01 09:53:01 OK 20260905000000_add_claims.sql (85.75ms)19842026/10/01 09:53:01 OK 20260920000000_drop_claims.sql (72.05ms)19852026-10-01 09:53:01.487 UTC [91747] ERROR: relation "goose_db_version" does not exist at character 3619862026-10-01 09:53:01.487 UTC [91747] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19872026/10/01 09:53:01 OK 20260923120000_add_pushes.sql (20.25ms)19882026/10/01 09:53:01 goose: successfully migrated database to version: 2026092312000019892026/10/01 09:53:01 OK 1_commit_pending_closure.sql (1.2ms)19902026/10/01 09:53:01 OK 2_object_stats_trigger.sql (334.33µs)19912026/10/01 09:53:01 OK 3_commit_push.sql (720.88µs)19922026/10/01 09:53:01 goose: up to current file version: 319932026-10-01 09:53:01.803 UTC [91754] ERROR: relation "goose_db_version" does not exist at character 3619942026-10-01 09:53:01.803 UTC [91754] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1995--- PASS: TestGCBugBareHashReferences (4.57s)1996=== CONT TestClientPushesUseOnePush19972026/10/01 09:53:01 OK 20241026095416_initial_model.sql (277.75ms)19982026/10/01 09:53:01 OK 20251210153512_drop_unused_gin_index.sql (16.28ms)1999=== NAME TestOrphanedObjectsGCStressTest2000 orphaned_objects_gc_test.go:509: Stress test completed successfully:2001 orphaned_objects_gc_test.go:510: - Active objects preserved: 202002 orphaned_objects_gc_test.go:511: - Objects deleted: 2102003 orphaned_objects_gc_test.go:512: - Total GC'd: 2102004--- PASS: TestOrphanedObjectsGCStressTest (26.12s)2005=== CONT TestPinProtectsFromGC20062026/10/01 09:53:01 OK 20251218171726_add_pins.sql (31.84ms)20072026/10/01 09:53:01 INFO lead: acquired remote=192.0.2.1:123420082026/10/01 09:53:01 INFO lead: released remote=192.0.2.1:12342009--- PASS: TestLeadEndsOnShutdown (4.52s)2010=== CONT TestClientSharedPathCommittedMidPush20112026/10/01 09:53:01 INFO Received uploads request method=POST path=/api/pending_closures20122026/10/01 09:53:01 OK 20260628120000_add_object_size_and_stats.sql (51.98ms)20132026/10/01 09:53:01 INFO Received uploads request method=POST path=/api/pending_closures20142026/10/01 09:53:01 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)20152026/10/01 09:53:01 INFO Uploading 5wnz2mv5scjmi9242mn0ldyzqzfa649p-b (248B)20162026/10/01 09:53:01 INFO Uploading 9bzfzpkqy4wxkxi0lky371m52xzwl29j-shared-dep (136B)20172026/10/01 09:53:01 OK 20260905000000_add_claims.sql (24.81ms)20182026/10/01 09:53:01 WARN Failed to register uploaded object key=9bzfzpkqy4wxkxi0lky371m52xzwl29j.ls error="server returned 404: 404 page not found\n"20192026/10/01 09:53:02 WARN Failed to register uploaded object key=nar/0zzr561zzdkks9drp4v8kj0iwywjinakfwzdih9j2g1pi30wnpf7.nar.zst error="server returned 404: 404 page not found\n"20202026/10/01 09:53:02 WARN Failed to register uploaded object key=v0q7slj7gj28zg3z89pll0kwkxrvg0z8.ls error="server returned 404: 404 page not found\n"20212026/10/01 09:53:02 WARN Failed to register uploaded object key=5wnz2mv5scjmi9242mn0ldyzqzfa649p.ls error="server returned 404: 404 page not found\n"20222026/10/01 09:53:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign20232026/10/01 09:53:02 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"20242026/10/01 09:53:02 INFO Signed narinfos id=1 count=220252026/10/01 09:53:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign20262026/10/01 09:53:02 INFO Signed narinfos id=2 count=220272026/10/01 09:53:02 INFO Uploading 4 narinfos20282026/10/01 09:53:02 OK 20260920000000_drop_claims.sql (82.15ms)20292026/10/01 09:53:02 WARN Failed to register uploaded object key=9bzfzpkqy4wxkxi0lky371m52xzwl29j.narinfo error="server returned 404: 404 page not found\n"20302026/10/01 09:53:02 OK 20260923120000_add_pushes.sql (8.55ms)20312026/10/01 09:53:02 goose: successfully migrated database to version: 2026092312000020322026/10/01 09:53:02 OK 1_commit_pending_closure.sql (1.73ms)20332026/10/01 09:53:02 OK 2_object_stats_trigger.sql (245.54µs)20342026/10/01 09:53:02 OK 3_commit_push.sql (189.63µs)20352026/10/01 09:53:02 goose: up to current file version: 320362026/10/01 09:53:02 WARN Failed to register uploaded object key=v0q7slj7gj28zg3z89pll0kwkxrvg0z8.narinfo error="server returned 404: 404 page not found\n"20372026/10/01 09:53:02 WARN Failed to register uploaded object key=5wnz2mv5scjmi9242mn0ldyzqzfa649p.narinfo error="server returned 404: 404 page not found\n"20382026/10/01 09:53:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20392026/10/01 09:53:02 WARN Failed to register uploaded object key=9bzfzpkqy4wxkxi0lky371m52xzwl29j.narinfo error="server returned 404: 404 page not found\n"20402026-10-01 09:53:02.170 UTC [91772] ERROR: relation "goose_db_version" does not exist at character 3620412026-10-01 09:53:02.170 UTC [91772] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20422026/10/01 09:53:02 INFO Completed upload id=120432026/10/01 09:53:02 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete20442026/10/01 09:53:02 INFO Completed upload id=220452026/10/01 09:53:02 INFO Upload complete. (333ms)2046=== NAME TestClientFallsBackToClosures2047 client_pushes_test.go:112: Retrieved narinfo from S3:2048 StorePath: /nix/var/nix/builds/nix-90619-4025703153/TestClientFallsBackToClosures2588165816/001/store/9bzfzpkqy4wxkxi0lky371m52xzwl29j-shared-dep2049 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2050 Compression: zstd2051 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822052 NarSize: 1362053 References: 2054 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2055 client_pushes_test.go:112: Retrieved narinfo from S3:2056 StorePath: /nix/var/nix/builds/nix-90619-4025703153/TestClientFallsBackToClosures2588165816/001/store/v0q7slj7gj28zg3z89pll0kwkxrvg0z8-a2057 URL: nar/0zzr561zzdkks9drp4v8kj0iwywjinakfwzdih9j2g1pi30wnpf7.nar.zst2058 Compression: zstd2059 NarHash: sha256:0zzr561zzdkks9drp4v8kj0iwywjinakfwzdih9j2g1pi30wnpf72060 NarSize: 2482061 References: /nix/var/nix/builds/nix-90619-4025703153/TestClientFallsBackToClosures2588165816/001/store/9bzfzpkqy4wxkxi0lky371m52xzwl29j-shared-dep2062 CA: text:sha256:0n7xnqyjsbi3dvbmyhrzbyy0xbb8gpf2w07id57526si5yxcw6r82063 client_pushes_test.go:112: Retrieved narinfo from S3:2064 StorePath: /nix/var/nix/builds/nix-90619-4025703153/TestClientFallsBackToClosures2588165816/001/store/5wnz2mv5scjmi9242mn0ldyzqzfa649p-b2065 URL: nar/0zzr561zzdkks9drp4v8kj0iwywjinakfwzdih9j2g1pi30wnpf7.nar.zst2066 Compression: zstd2067 NarHash: sha256:0zzr561zzdkks9drp4v8kj0iwywjinakfwzdih9j2g1pi30wnpf72068 NarSize: 2482069 References: /nix/var/nix/builds/nix-90619-4025703153/TestClientFallsBackToClosures2588165816/001/store/9bzfzpkqy4wxkxi0lky371m52xzwl29j-shared-dep2070 CA: text:sha256:0n7xnqyjsbi3dvbmyhrzbyy0xbb8gpf2w07id57526si5yxcw6r820712026/10/01 09:53:02 OK 20241026095416_initial_model.sql (412.89ms)20722026/10/01 09:53:02 OK 20251210153512_drop_unused_gin_index.sql (9.7ms)2073--- PASS: TestClientFallsBackToClosures (6.25s)2074=== CONT TestGCTaskStore_ConflictDifferentParams2075--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)2076=== CONT TestGCTaskStore_GetEmpty2077--- PASS: TestGCTaskStore_GetEmpty (0.00s)2078=== CONT TestCacheConfigHandler2079=== RUN TestCacheConfigHandler/full_config,_no_issuer2080=== PAUSE TestCacheConfigHandler/full_config,_no_issuer2081=== RUN TestCacheConfigHandler/no_cache_url_configured2082=== PAUSE TestCacheConfigHandler/no_cache_url_configured2083=== RUN TestCacheConfigHandler/no_signing_keys2084=== PAUSE TestCacheConfigHandler/no_signing_keys2085=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2086=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2087=== CONT TestClientMultipleUploads20882026/10/01 09:53:02 OK 20251218171726_add_pins.sql (60.69ms)20892026/10/01 09:53:02 OK 20260628120000_add_object_size_and_stats.sql (63.29ms)20902026/10/01 09:53:02 INFO lead: acquired remote=192.0.2.1:123420912026/10/01 09:53:02 OK 20260905000000_add_claims.sql (89.03ms)20922026/10/01 09:53:02 OK 20260920000000_drop_claims.sql (49.55ms)20932026/10/01 09:53:02 OK 20260923120000_add_pushes.sql (21.05ms)20942026/10/01 09:53:02 goose: successfully migrated database to version: 2026092312000020952026/10/01 09:53:02 OK 1_commit_pending_closure.sql (2.25ms)20962026/10/01 09:53:02 OK 2_object_stats_trigger.sql (304.96µs)20972026/10/01 09:53:02 OK 3_commit_push.sql (308.58µs)20982026/10/01 09:53:02 goose: up to current file version: 320992026/10/01 09:53:02 OK 20241026095416_initial_model.sql (292.7ms)21002026/10/01 09:53:02 OK 20251210153512_drop_unused_gin_index.sql (10.29ms)21012026/10/01 09:53:02 INFO lead: released remote=192.0.2.1:123421022026/10/01 09:53:02 OK 20251218171726_add_pins.sql (61.7ms)21032026/10/01 09:53:02 INFO lead: acquired remote=192.0.2.1:123421042026/10/01 09:53:02 INFO lead: released remote=192.0.2.1:12342105--- PASS: TestLeadElectsOneAndHandsOver (4.81s)2106=== CONT TestClientIntegration21072026/10/01 09:53:02 OK 20260628120000_add_object_size_and_stats.sql (33.26ms)21082026/10/01 09:53:02 OK 20260905000000_add_claims.sql (68.28ms)21092026/10/01 09:53:02 OK 20260920000000_drop_claims.sql (38.56ms)21102026/10/01 09:53:02 OK 20260923120000_add_pushes.sql (9.96ms)21112026/10/01 09:53:02 goose: successfully migrated database to version: 2026092312000021122026/10/01 09:53:02 OK 1_commit_pending_closure.sql (1.56ms)21132026/10/01 09:53:02 OK 2_object_stats_trigger.sql (262.83µs)21142026/10/01 09:53:02 OK 3_commit_push.sql (195.21µs)21152026/10/01 09:53:02 goose: up to current file version: 32116--- PASS: TestObjectStatsTrigger (4.63s)2117=== CONT TestClientErrorHandling2118=== RUN TestClientErrorHandling/InvalidStorePath2119=== PAUSE TestClientErrorHandling/InvalidStorePath2120=== RUN TestClientErrorHandling/InvalidAuthToken2121=== PAUSE TestClientErrorHandling/InvalidAuthToken2122=== RUN TestClientErrorHandling/ServerNotAvailable2123=== PAUSE TestClientErrorHandling/ServerNotAvailable2124=== CONT TestService_AuthMiddleware_OIDC21252026/10/01 09:53:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55794/oidc21262026/10/01 09:53:03 INFO Received uploads request method=POST path=/api/pending_closures2127--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (4.70s)2128=== CONT TestService_ReadScope_PublicByDefault21292026-10-01 09:53:04.161 UTC [91809] ERROR: relation "goose_db_version" does not exist at character 3621302026-10-01 09:53:04.161 UTC [91809] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21312026-10-01 09:53:04.363 UTC [91811] ERROR: relation "goose_db_version" does not exist at character 3621322026-10-01 09:53:04.363 UTC [91811] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21332026-10-01 09:53:04.432 UTC [91815] ERROR: relation "goose_db_version" does not exist at character 3621342026-10-01 09:53:04.432 UTC [91815] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21352026/10/01 09:53:04 OK 20241026095416_initial_model.sql (195.58ms)21362026/10/01 09:53:04 OK 20251210153512_drop_unused_gin_index.sql (4.16ms)21372026/10/01 09:53:04 OK 20251218171726_add_pins.sql (28.5ms)21382026/10/01 09:53:04 OK 20241026095416_initial_model.sql (113.51ms)21392026/10/01 09:53:04 OK 20251210153512_drop_unused_gin_index.sql (2.18ms)21402026/10/01 09:53:04 OK 20260628120000_add_object_size_and_stats.sql (34.73ms)21412026/10/01 09:53:04 OK 20260905000000_add_claims.sql (5.34ms)21422026/10/01 09:53:04 OK 20251218171726_add_pins.sql (24.87ms)21432026/10/01 09:53:04 OK 20260920000000_drop_claims.sql (69.49ms)21442026-10-01 09:53:04.702 UTC [91824] ERROR: relation "goose_db_version" does not exist at character 3621452026-10-01 09:53:04.702 UTC [91824] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21462026/10/01 09:53:04 OK 20260923120000_add_pushes.sql (91.73ms)21472026/10/01 09:53:04 goose: successfully migrated database to version: 2026092312000021482026/10/01 09:53:04 OK 1_commit_pending_closure.sql (1.35ms)21492026/10/01 09:53:04 OK 2_object_stats_trigger.sql (328.75µs)21502026/10/01 09:53:04 OK 3_commit_push.sql (253.67µs)21512026/10/01 09:53:04 goose: up to current file version: 321522026/10/01 09:53:04 OK 20260628120000_add_object_size_and_stats.sql (151.62ms)21532026/10/01 09:53:04 OK 20241026095416_initial_model.sql (236.32ms)21542026/10/01 09:53:04 OK 20251210153512_drop_unused_gin_index.sql (36.07ms)21552026/10/01 09:53:04 OK 20251218171726_add_pins.sql (47.43ms)21562026/10/01 09:53:04 OK 20260905000000_add_claims.sql (106.55ms)21572026-10-01 09:53:04.832 UTC [91825] ERROR: relation "goose_db_version" does not exist at character 3621582026-10-01 09:53:04.832 UTC [91825] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21592026/10/01 09:53:04 OK 20260628120000_add_object_size_and_stats.sql (34.87ms)21602026/10/01 09:53:04 OK 20260920000000_drop_claims.sql (109.05ms)21612026/10/01 09:53:04 OK 20260905000000_add_claims.sql (135.67ms)21622026/10/01 09:53:04 OK 20260923120000_add_pushes.sql (40.76ms)21632026/10/01 09:53:04 goose: successfully migrated database to version: 2026092312000021642026/10/01 09:53:04 OK 1_commit_pending_closure.sql (3.23ms)21652026/10/01 09:53:04 OK 2_object_stats_trigger.sql (615.17µs)21662026/10/01 09:53:04 OK 3_commit_push.sql (419.83µs)21672026/10/01 09:53:04 goose: up to current file version: 321682026/10/01 09:53:05 OK 20260920000000_drop_claims.sql (87.87ms)21692026/10/01 09:53:05 OK 20260923120000_add_pushes.sql (48.14ms)21702026/10/01 09:53:05 goose: successfully migrated database to version: 2026092312000021712026/10/01 09:53:05 OK 1_commit_pending_closure.sql (4.71ms)21722026/10/01 09:53:05 OK 2_object_stats_trigger.sql (2.64ms)21732026/10/01 09:53:05 OK 3_commit_push.sql (899.25µs)21742026/10/01 09:53:05 goose: up to current file version: 321752026/10/01 09:53:05 OK 20241026095416_initial_model.sql (416.39ms)21762026-10-01 09:53:05.242 UTC [91826] ERROR: relation "goose_db_version" does not exist at character 3621772026-10-01 09:53:05.242 UTC [91826] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21782026/10/01 09:53:05 OK 20251210153512_drop_unused_gin_index.sql (28.24ms)21792026/10/01 09:53:05 OK 20251218171726_add_pins.sql (93.62ms)2180--- PASS: TestMetricsInventory (4.69s)2181=== CONT TestService_RequireScope_OIDC21822026/10/01 09:53:05 OK 20241026095416_initial_model.sql (463.83ms)21832026/10/01 09:53:05 OK 20260628120000_add_object_size_and_stats.sql (79.15ms)21842026/10/01 09:53:05 OK 20251210153512_drop_unused_gin_index.sql (18.51ms)21852026/10/01 09:53:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55823/oidc21862026/10/01 09:53:05 OK 20251218171726_add_pins.sql (70.71ms)21872026/10/01 09:53:05 OK 20260628120000_add_object_size_and_stats.sql (40.59ms)21882026/10/01 09:53:05 OK 20260905000000_add_claims.sql (119.81ms)21892026/10/01 09:53:05 OK 20260920000000_drop_claims.sql (38.66ms)21902026/10/01 09:53:05 OK 20260923120000_add_pushes.sql (28.25ms)21912026/10/01 09:53:05 goose: successfully migrated database to version: 2026092312000021922026/10/01 09:53:05 OK 1_commit_pending_closure.sql (1.78ms)21932026/10/01 09:53:05 OK 2_object_stats_trigger.sql (442.21µs)21942026/10/01 09:53:05 OK 3_commit_push.sql (339.63µs)21952026/10/01 09:53:05 goose: up to current file version: 321962026/10/01 09:53:05 OK 20260905000000_add_claims.sql (74.84ms)21972026/10/01 09:53:05 OK 20260920000000_drop_claims.sql (50.18ms)21982026/10/01 09:53:05 OK 20260923120000_add_pushes.sql (31.76ms)21992026/10/01 09:53:05 goose: successfully migrated database to version: 2026092312000022002026/10/01 09:53:05 OK 20241026095416_initial_model.sql (309.21ms)22012026/10/01 09:53:05 OK 1_commit_pending_closure.sql (2.88ms)22022026/10/01 09:53:05 OK 2_object_stats_trigger.sql (632.38µs)22032026/10/01 09:53:05 OK 3_commit_push.sql (344.79µs)22042026/10/01 09:53:05 goose: up to current file version: 322052026/10/01 09:53:05 OK 20251210153512_drop_unused_gin_index.sql (11.89ms)22062026/10/01 09:53:05 INFO Received uploads request method=POST path=/api/pending_closures22072026/10/01 09:53:05 OK 20251218171726_add_pins.sql (80.36ms)22082026/10/01 09:53:05 OK 20260628120000_add_object_size_and_stats.sql (83.96ms)22092026/10/01 09:53:05 INFO Received cleanup request method=DELETE path=/api/pending_closures22102026/10/01 09:53:06 INFO Aborted multipart uploads count=122112026/10/01 09:53:06 OK 20260905000000_add_claims.sql (126.23ms)2212--- PASS: TestMultipartCleanup (5.34s)2213=== CONT TestServerTLSConfig2214=== RUN TestServerTLSConfig/no_client_CA2215=== PAUSE TestServerTLSConfig/no_client_CA2216=== RUN TestServerTLSConfig/missing_CA_file2217=== PAUSE TestServerTLSConfig/missing_CA_file2218=== RUN TestServerTLSConfig/not_a_PEM_file2219=== PAUSE TestServerTLSConfig/not_a_PEM_file2220=== CONT TestCacheStatsHandler22212026/10/01 09:53:06 OK 20260920000000_drop_claims.sql (114.74ms)22222026/10/01 09:53:06 OK 20260923120000_add_pushes.sql (38.39ms)22232026/10/01 09:53:06 goose: successfully migrated database to version: 2026092312000022242026/10/01 09:53:06 OK 1_commit_pending_closure.sql (1.67ms)22252026/10/01 09:53:06 OK 2_object_stats_trigger.sql (396.13µs)22262026/10/01 09:53:06 OK 3_commit_push.sql (272.42µs)22272026/10/01 09:53:06 goose: up to current file version: 322282026-10-01 09:53:06.705 UTC [91837] ERROR: relation "goose_db_version" does not exist at character 3622292026-10-01 09:53:06.705 UTC [91837] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2230=== NAME TestNARDeduplicationMetadataUploadBug2231 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-90619-4025703153/TestNARDeduplicationMetadataUploadBug3605270057/001/store/dcxvpvjrk4p2700wdpaw4szq4pgr7dw0-file1.txt22322026/10/01 09:53:06 INFO Received push request method=POST path=/api/pushes22332026/10/01 09:53:07 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)22342026/10/01 09:53:07 INFO Uploading dcxvpvjrk4p2700wdpaw4szq4pgr7dw0-file1.txt (160B)22352026/10/01 09:53:07 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"22362026/10/01 09:53:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22372026/10/01 09:53:07 WARN Failed to register uploaded object key=dcxvpvjrk4p2700wdpaw4szq4pgr7dw0.ls error="server returned 404: 404 page not found\n"22382026/10/01 09:53:07 INFO Signed narinfos id=1 count=122392026/10/01 09:53:07 INFO Uploading 1 narinfos22402026/10/01 09:53:07 INFO Received complete push request method=POST path=/api/pushes/1/complete22412026/10/01 09:53:07 WARN Failed to register uploaded object key=dcxvpvjrk4p2700wdpaw4szq4pgr7dw0.narinfo error="server returned 404: 404 page not found\n"22422026-10-01 09:53:07.100 UTC [91846] ERROR: relation "goose_db_version" does not exist at character 3622432026-10-01 09:53:07.100 UTC [91846] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22442026/10/01 09:53:07 INFO Upload complete. (231ms)2245 metadata_upload_test.go:54: Retrieved narinfo from S3:2246 StorePath: /nix/var/nix/builds/nix-90619-4025703153/TestNARDeduplicationMetadataUploadBug3605270057/001/store/dcxvpvjrk4p2700wdpaw4szq4pgr7dw0-file1.txt2247 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2248 Compression: zstd2249 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2250 NarSize: 1602251 References: 2252 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2253 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2254 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2255 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}22562026/10/01 09:53:07 OK 20241026095416_initial_model.sql (328.17ms)22572026/10/01 09:53:07 OK 20251210153512_drop_unused_gin_index.sql (9.07ms)22582026/10/01 09:53:07 OK 20251218171726_add_pins.sql (53.3ms)22592026/10/01 09:53:07 OK 20260628120000_add_object_size_and_stats.sql (54.27ms)2260 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-90619-4025703153/TestNARDeduplicationMetadataUploadBug3605270057/001/store/z171iihjiaasinvisxyrmrpgcxiigwwf-file2.txt22612026-10-01 09:53:07.246 UTC [91852] ERROR: relation "goose_db_version" does not exist at character 3622622026-10-01 09:53:07.246 UTC [91852] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2263=== NAME TestPinProtectsFromGC2264 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-90619-4025703153/TestPinProtectsFromGC2324708673/001/store/nwq6va437bcr3l0lvqmk1zaq4jji34ai-pinned-file.txt2265 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-90619-4025703153/TestPinProtectsFromGC2324708673/001/store/gwczs8g8sps9i9ba5gfilq40r5s6la6k-unpinned-file.txt22662026/10/01 09:53:07 OK 20260905000000_add_claims.sql (91.91ms)22672026/10/01 09:53:07 INFO Received push request method=POST path=/api/pushes22682026/10/01 09:53:07 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)22692026/10/01 09:53:07 INFO Received push request method=POST path=/api/pushes22702026/10/01 09:53:07 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign22712026/10/01 09:53:07 INFO Signed narinfos id=2 count=122722026/10/01 09:53:07 INFO Uploading 1 narinfos22732026/10/01 09:53:07 WARN Failed to register uploaded object key=z171iihjiaasinvisxyrmrpgcxiigwwf.ls error="server returned 404: 404 page not found\n"22742026/10/01 09:53:07 OK 20260920000000_drop_claims.sql (73.11ms)22752026/10/01 09:53:07 OK 20260923120000_add_pushes.sql (23.47ms)22762026/10/01 09:53:07 goose: successfully migrated database to version: 2026092312000022772026/10/01 09:53:07 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)22782026/10/01 09:53:07 INFO Uploading nwq6va437bcr3l0lvqmk1zaq4jji34ai-pinned-file.txt (128B)22792026/10/01 09:53:07 OK 1_commit_pending_closure.sql (1.13ms)22802026/10/01 09:53:07 OK 2_object_stats_trigger.sql (262.58µs)22812026/10/01 09:53:07 OK 3_commit_push.sql (190.63µs)22822026/10/01 09:53:07 goose: up to current file version: 322832026/10/01 09:53:07 INFO Received complete push request method=POST path=/api/pushes/2/complete22842026/10/01 09:53:07 WARN Failed to register uploaded object key=z171iihjiaasinvisxyrmrpgcxiigwwf.narinfo error="server returned 404: 404 page not found\n"22852026/10/01 09:53:07 INFO Upload complete. (143ms)2286=== NAME TestNARDeduplicationMetadataUploadBug2287 metadata_upload_test.go:76: Retrieved narinfo from S3:2288 StorePath: /nix/var/nix/builds/nix-90619-4025703153/TestNARDeduplicationMetadataUploadBug3605270057/001/store/z171iihjiaasinvisxyrmrpgcxiigwwf-file2.txt2289 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2290 Compression: zstd2291 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2292 NarSize: 1602293 References: 2294 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2295 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2296 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2297 {"version":1,"root":{"type":"regular","size":44}}22982026/10/01 09:53:07 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"22992026/10/01 09:53:07 OK 20241026095416_initial_model.sql (296.08ms)23002026/10/01 09:53:07 WARN Failed to register uploaded object key=nwq6va437bcr3l0lvqmk1zaq4jji34ai.ls error="server returned 404: 404 page not found\n"23012026/10/01 09:53:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23022026/10/01 09:53:07 INFO Signed narinfos id=1 count=123032026/10/01 09:53:07 INFO Uploading 1 narinfos23042026/10/01 09:53:07 OK 20251210153512_drop_unused_gin_index.sql (15.1ms)23052026/10/01 09:53:07 INFO Received complete push request method=POST path=/api/pushes/1/complete23062026/10/01 09:53:07 WARN Failed to register uploaded object key=nwq6va437bcr3l0lvqmk1zaq4jji34ai.narinfo error="server returned 404: 404 page not found\n"23072026/10/01 09:53:07 OK 20251218171726_add_pins.sql (42.23ms)23082026/10/01 09:53:07 INFO Upload complete. (273ms)2309--- PASS: TestNARDeduplicationMetadataUploadBug (6.68s)2310=== CONT TestGCTaskStore_DeduplicateSameParams2311--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)2312=== CONT TestPresentReportsOnlyClosureRoots23132026/10/01 09:53:07 OK 20260628120000_add_object_size_and_stats.sql (53.89ms)23142026/10/01 09:53:07 OK 20241026095416_initial_model.sql (303.22ms)23152026/10/01 09:53:07 OK 20260905000000_add_claims.sql (75.64ms)23162026/10/01 09:53:07 OK 20251210153512_drop_unused_gin_index.sql (11.69ms)23172026/10/01 09:53:07 INFO Received push request method=POST path=/api/pushes23182026/10/01 09:53:07 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)23192026/10/01 09:53:07 INFO Uploading gwczs8g8sps9i9ba5gfilq40r5s6la6k-unpinned-file.txt (128B)23202026-10-01 09:53:07.680 UTC [91871] ERROR: relation "goose_db_version" does not exist at character 3623212026-10-01 09:53:07.680 UTC [91871] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23222026/10/01 09:53:07 WARN Failed to register uploaded object key=gwczs8g8sps9i9ba5gfilq40r5s6la6k.ls error="server returned 404: 404 page not found\n"23232026/10/01 09:53:07 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign23242026/10/01 09:53:07 INFO Signed narinfos id=2 count=123252026/10/01 09:53:07 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"23262026/10/01 09:53:07 INFO Uploading 1 narinfos23272026/10/01 09:53:07 OK 20251218171726_add_pins.sql (53.8ms)23282026/10/01 09:53:07 OK 20260920000000_drop_claims.sql (60.72ms)23292026/10/01 09:53:07 INFO Received complete push request method=POST path=/api/pushes/2/complete23302026/10/01 09:53:07 WARN Failed to register uploaded object key=gwczs8g8sps9i9ba5gfilq40r5s6la6k.narinfo error="server returned 404: 404 page not found\n"23312026/10/01 09:53:07 INFO Upload complete. (108ms)23322026/10/01 09:53:07 OK 20260923120000_add_pushes.sql (15.85ms)23332026/10/01 09:53:07 goose: successfully migrated database to version: 2026092312000023342026/10/01 09:53:07 OK 1_commit_pending_closure.sql (994.54µs)23352026/10/01 09:53:07 OK 2_object_stats_trigger.sql (218.21µs)23362026/10/01 09:53:07 OK 3_commit_push.sql (192.67µs)23372026/10/01 09:53:07 goose: up to current file version: 323382026/10/01 09:53:07 OK 20260628120000_add_object_size_and_stats.sql (47.61ms)23392026/10/01 09:53:07 INFO Starting cleanup of old closures method=DELETE path=/api/closures23402026/10/01 09:53:07 INFO Garbage collection started23412026/10/01 09:53:07 INFO Aborted multipart uploads count=023422026/10/01 09:53:07 WARN Force mode enabled - objects will be deleted immediately without grace period23432026/10/01 09:53:07 OK 20260905000000_add_claims.sql (106.67ms)23442026/10/01 09:53:07 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=023452026/10/01 09:53:07 INFO Vacuumed table table=pending_closures23462026/10/01 09:53:07 OK 20260920000000_drop_claims.sql (97.45ms)23472026/10/01 09:53:07 INFO Vacuumed table table=pending_objects23482026/10/01 09:53:07 INFO Vacuumed table table=multipart_uploads23492026/10/01 09:53:07 OK 20260923120000_add_pushes.sql (26.11ms)23502026/10/01 09:53:07 goose: successfully migrated database to version: 2026092312000023512026/10/01 09:53:07 INFO Vacuumed table table=closures23522026/10/01 09:53:07 OK 1_commit_pending_closure.sql (900.67µs)23532026/10/01 09:53:07 OK 2_object_stats_trigger.sql (221.13µs)23542026/10/01 09:53:07 OK 3_commit_push.sql (185.63µs)23552026/10/01 09:53:07 goose: up to current file version: 323562026/10/01 09:53:08 INFO Vacuumed table table=objects23572026/10/01 09:53:08 INFO Received push request method=POST path=/api/pushes23582026/10/01 09:53:08 OK 20241026095416_initial_model.sql (295.59ms)23592026/10/01 09:53:08 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)23602026/10/01 09:53:08 INFO Uploading lx8kz7q0z1819w1jkxwy3h4fx0qznv11-shared-dep (136B)23612026/10/01 09:53:08 INFO Uploading n11p5fvp0b8l7p97ahcx8z0avs63rff1-b (248B)23622026/10/01 09:53:08 OK 20251210153512_drop_unused_gin_index.sql (17.72ms)23632026/10/01 09:53:08 WARN Failed to register uploaded object key=nar/094gr2v80vbp7246fck4brah3piysqf6zgii2m07zvq3pa70csic.nar.zst error="server returned 404: 404 page not found\n"23642026/10/01 09:53:08 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"23652026/10/01 09:53:08 WARN Failed to register uploaded object key=n11p5fvp0b8l7p97ahcx8z0avs63rff1.ls error="server returned 404: 404 page not found\n"23662026/10/01 09:53:08 WARN Failed to register uploaded object key=mmbkjspgpjas2vdys8mx4fqhdhjgavqj.ls error="server returned 404: 404 page not found\n"23672026/10/01 09:53:08 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23682026/10/01 09:53:08 WARN Failed to register uploaded object key=lx8kz7q0z1819w1jkxwy3h4fx0qznv11.ls error="server returned 404: 404 page not found\n"23692026/10/01 09:53:08 INFO Signed narinfos id=1 count=323702026/10/01 09:53:08 INFO Uploading 3 narinfos23712026/10/01 09:53:08 OK 20251218171726_add_pins.sql (41.11ms)23722026/10/01 09:53:08 WARN Failed to register uploaded object key=n11p5fvp0b8l7p97ahcx8z0avs63rff1.narinfo error="server returned 404: 404 page not found\n"23732026/10/01 09:53:08 WARN Failed to register uploaded object key=lx8kz7q0z1819w1jkxwy3h4fx0qznv11.narinfo error="server returned 404: 404 page not found\n"23742026/10/01 09:53:08 INFO Received push request method=POST path=/api/pushes23752026/10/01 09:53:08 INFO Received complete push request method=POST path=/api/pushes/1/complete23762026/10/01 09:53:08 WARN Failed to register uploaded object key=mmbkjspgpjas2vdys8mx4fqhdhjgavqj.narinfo error="server returned 404: 404 page not found\n"23772026/10/01 09:53:08 OK 20260628120000_add_object_size_and_stats.sql (61.54ms)23782026/10/01 09:53:08 INFO Upload complete. (218ms)2379=== NAME TestClientPushesUseOnePush2380 client_pushes_test.go:97: Retrieved narinfo from S3:2381 StorePath: /nix/var/nix/builds/nix-90619-4025703153/TestClientPushesUseOnePush109312644/001/store/lx8kz7q0z1819w1jkxwy3h4fx0qznv11-shared-dep2382 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2383 Compression: zstd2384 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822385 NarSize: 1362386 References: 2387 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2388 client_pushes_test.go:97: Retrieved narinfo from S3:2389 StorePath: /nix/var/nix/builds/nix-90619-4025703153/TestClientPushesUseOnePush109312644/001/store/mmbkjspgpjas2vdys8mx4fqhdhjgavqj-a2390 URL: nar/094gr2v80vbp7246fck4brah3piysqf6zgii2m07zvq3pa70csic.nar.zst2391 Compression: zstd2392 NarHash: sha256:094gr2v80vbp7246fck4brah3piysqf6zgii2m07zvq3pa70csic2393 NarSize: 2482394 References: /nix/var/nix/builds/nix-90619-4025703153/TestClientPushesUseOnePush109312644/001/store/lx8kz7q0z1819w1jkxwy3h4fx0qznv11-shared-dep2395 CA: text:sha256:03fqjd95rczvdi77y89m84v8mh6wvw70fbg670q8h1n253hdai262396 client_pushes_test.go:97: Retrieved narinfo from S3:2397 StorePath: /nix/var/nix/builds/nix-90619-4025703153/TestClientPushesUseOnePush109312644/001/store/n11p5fvp0b8l7p97ahcx8z0avs63rff1-b2398 URL: nar/094gr2v80vbp7246fck4brah3piysqf6zgii2m07zvq3pa70csic.nar.zst2399 Compression: zstd2400 NarHash: sha256:094gr2v80vbp7246fck4brah3piysqf6zgii2m07zvq3pa70csic2401 NarSize: 2482402 References: /nix/var/nix/builds/nix-90619-4025703153/TestClientPushesUseOnePush109312644/001/store/lx8kz7q0z1819w1jkxwy3h4fx0qznv11-shared-dep2403 CA: text:sha256:03fqjd95rczvdi77y89m84v8mh6wvw70fbg670q8h1n253hdai2624042026/10/01 09:53:08 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)24052026/10/01 09:53:08 INFO Uploading 4s86ljjk1vn6zrs31zb7j9zczlzkan76-shared-dep (136B)24062026/10/01 09:53:08 INFO Uploading i9yyzhcxy1b7nsyx19dgas06p2yhm6za-top (256B)24072026/10/01 09:53:08 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"24082026/10/01 09:53:08 WARN Failed to register uploaded object key=nar/0rjyyv69f0mgp744099ccjkwn64nnzjbxsxg7x7wrfcznl1659kr.nar.zst error="server returned 404: 404 page not found\n"24092026/10/01 09:53:08 WARN Failed to register uploaded object key=4s86ljjk1vn6zrs31zb7j9zczlzkan76.ls error="server returned 404: 404 page not found\n"24102026/10/01 09:53:08 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24112026/10/01 09:53:08 WARN Failed to register uploaded object key=i9yyzhcxy1b7nsyx19dgas06p2yhm6za.ls error="server returned 404: 404 page not found\n"24122026/10/01 09:53:08 INFO Signed narinfos id=1 count=224132026/10/01 09:53:08 INFO Uploading 2 narinfos24142026/10/01 09:53:08 WARN Failed to register uploaded object key=i9yyzhcxy1b7nsyx19dgas06p2yhm6za.narinfo error="server returned 404: 404 page not found\n"24152026/10/01 09:53:08 INFO Received complete push request method=POST path=/api/pushes/1/complete24162026/10/01 09:53:08 WARN Failed to register uploaded object key=4s86ljjk1vn6zrs31zb7j9zczlzkan76.narinfo error="server returned 404: 404 page not found\n"24172026/10/01 09:53:08 OK 20260905000000_add_claims.sql (123.73ms)24182026/10/01 09:53:08 INFO Upload complete. (203ms)2419=== NAME TestClientSharedPathCommittedMidPush2420 client_integration_test.go:680: Retrieved narinfo from S3:2421 StorePath: /nix/var/nix/builds/nix-90619-4025703153/TestClientSharedPathCommittedMidPush1241778471/001/store/4s86ljjk1vn6zrs31zb7j9zczlzkan76-shared-dep2422 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2423 Compression: zstd2424 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822425 NarSize: 1362426 References: 2427 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2428 client_integration_test.go:680: Retrieved narinfo from S3:2429 StorePath: /nix/var/nix/builds/nix-90619-4025703153/TestClientSharedPathCommittedMidPush1241778471/001/store/i9yyzhcxy1b7nsyx19dgas06p2yhm6za-top2430 URL: nar/0rjyyv69f0mgp744099ccjkwn64nnzjbxsxg7x7wrfcznl1659kr.nar.zst2431 Compression: zstd2432 NarHash: sha256:0rjyyv69f0mgp744099ccjkwn64nnzjbxsxg7x7wrfcznl1659kr2433 NarSize: 2562434 References: /nix/var/nix/builds/nix-90619-4025703153/TestClientSharedPathCommittedMidPush1241778471/001/store/4s86ljjk1vn6zrs31zb7j9zczlzkan76-shared-dep2435 CA: text:sha256:0h5r485sc6z3110jrpjswqpb8i5vpr7ab1b4h0dhh8s9pmjr5v7q2436=== NAME TestClientMultipleUploads2437 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-90619-4025703153/TestClientMultipleUploads900171960/001/store/1vqqb85ha1vxc74bchrb6r0rsxp8pakh-test-file-0.txt2438--- PASS: TestClientPushesUseOnePush (6.53s)2439=== CONT TestService_NativeMTLS24402026/10/01 09:53:08 OK 20260920000000_drop_claims.sql (73.98ms)2441--- PASS: TestClientSharedPathCommittedMidPush (6.52s)2442=== CONT TestService_ReadAuthMiddleware24432026/10/01 09:53:08 OK 20260923120000_add_pushes.sql (90.13ms)24442026/10/01 09:53:08 goose: successfully migrated database to version: 2026092312000024452026/10/01 09:53:08 OK 1_commit_pending_closure.sql (959.25µs)24462026/10/01 09:53:08 OK 2_object_stats_trigger.sql (267.83µs)24472026/10/01 09:53:08 OK 3_commit_push.sql (188.75µs)24482026/10/01 09:53:08 goose: up to current file version: 32449=== NAME TestClientMultipleUploads2450 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-90619-4025703153/TestClientMultipleUploads900171960/001/store/9l7fai28x6lr3ra5kwhj2kiqskw8ryw4-test-file-1.txt2451 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-90619-4025703153/TestClientMultipleUploads900171960/001/store/78cawrj2z0nz0ni43csmia2dajipypfh-test-file-2.txt2452=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2453=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2454=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2455=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2456=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2457=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2458=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2459=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2460=== CONT TestService_AuthMiddleware_MTLSBoundSubjects24612026/10/01 09:53:08 INFO Received push request method=POST path=/api/pushes2462=== NAME TestClientIntegration2463 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-90619-4025703153/TestClientIntegration708405376/002/store/c0bx731dgf65f9ad3d5f4rh8fw7z2891-test-file.txt24642026/10/01 09:53:08 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)24652026/10/01 09:53:08 INFO Uploading 9l7fai28x6lr3ra5kwhj2kiqskw8ryw4-test-file-1.txt (160B)24662026/10/01 09:53:08 INFO Uploading 1vqqb85ha1vxc74bchrb6r0rsxp8pakh-test-file-0.txt (160B)24672026/10/01 09:53:08 INFO Uploading 78cawrj2z0nz0ni43csmia2dajipypfh-test-file-2.txt (160B)24682026/10/01 09:53:08 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"24692026/10/01 09:53:08 WARN Failed to register uploaded object key=78cawrj2z0nz0ni43csmia2dajipypfh.ls error="server returned 404: 404 page not found\n"24702026/10/01 09:53:08 WARN Failed to register uploaded object key=9l7fai28x6lr3ra5kwhj2kiqskw8ryw4.ls error="server returned 404: 404 page not found\n"24712026/10/01 09:53:08 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"24722026/10/01 09:53:08 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"24732026/10/01 09:53:08 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24742026/10/01 09:53:08 WARN Failed to register uploaded object key=1vqqb85ha1vxc74bchrb6r0rsxp8pakh.ls error="server returned 404: 404 page not found\n"24752026/10/01 09:53:08 INFO Signed narinfos id=1 count=324762026/10/01 09:53:08 INFO Uploading 3 narinfos24772026/10/01 09:53:08 WARN Failed to register uploaded object key=78cawrj2z0nz0ni43csmia2dajipypfh.narinfo error="server returned 404: 404 page not found\n"24782026/10/01 09:53:08 WARN Failed to register uploaded object key=1vqqb85ha1vxc74bchrb6r0rsxp8pakh.narinfo error="server returned 404: 404 page not found\n"24792026/10/01 09:53:08 INFO Received push request method=POST path=/api/pushes24802026/10/01 09:53:08 INFO Received complete push request method=POST path=/api/pushes/1/complete24812026/10/01 09:53:08 WARN Failed to register uploaded object key=9l7fai28x6lr3ra5kwhj2kiqskw8ryw4.narinfo error="server returned 404: 404 page not found\n"24822026/10/01 09:53:08 INFO Upload complete. (252ms)2483=== NAME TestClientMultipleUploads2484 client_integration_test.go:369: Uploaded 3 paths in 291.294625ms24852026/10/01 09:53:08 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)24862026/10/01 09:53:08 INFO Uploading c0bx731dgf65f9ad3d5f4rh8fw7z2891-test-file.txt (152B)24872026/10/01 09:53:09 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"24882026/10/01 09:53:09 WARN Failed to register uploaded object key=c0bx731dgf65f9ad3d5f4rh8fw7z2891.ls error="server returned 404: 404 page not found\n"24892026/10/01 09:53:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24902026/10/01 09:53:09 INFO Signed narinfos id=1 count=124912026/10/01 09:53:09 INFO Uploading 1 narinfos24922026/10/01 09:53:09 INFO Received complete push request method=POST path=/api/pushes/1/complete24932026/10/01 09:53:09 WARN Failed to register uploaded object key=c0bx731dgf65f9ad3d5f4rh8fw7z2891.narinfo error="server returned 404: 404 page not found\n"24942026/10/01 09:53:09 INFO Upload complete. (283ms)2495--- PASS: TestClientMultipleUploads (6.81s)2496=== CONT TestService_AuthMiddleware_MTLSProxyHeader2497--- PASS: TestService_ReadScope_PublicByDefault (5.71s)2498=== CONT TestClientCADerivations24992026/10/01 09:53:09 INFO All 1 paths already cached2500=== NAME TestClientIntegration2501 client_integration_test.go:312: Retrieved narinfo from S3:2502 StorePath: /nix/var/nix/builds/nix-90619-4025703153/TestClientIntegration708405376/002/store/c0bx731dgf65f9ad3d5f4rh8fw7z2891-test-file.txt2503 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2504 Compression: zstd2505 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12506 NarSize: 1522507 References: 2508 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12509 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2510 client_integration_test.go:313: Decompressed .ls content (64 bytes):2511 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2512 client_integration_test.go:316: Testing garbage collection...25132026/10/01 09:53:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures25142026/10/01 09:53:09 INFO Garbage collection started25152026/10/01 09:53:09 INFO Aborted multipart uploads count=025162026/10/01 09:53:09 WARN Force mode enabled - objects will be deleted immediately without grace period25172026-10-01 09:53:09.296 UTC [91917] ERROR: relation "goose_db_version" does not exist at character 3625182026-10-01 09:53:09.296 UTC [91917] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25192026/10/01 09:53:09 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=025202026/10/01 09:53:09 INFO Vacuumed table table=pending_closures25212026/10/01 09:53:09 INFO Vacuumed table table=pending_objects25222026/10/01 09:53:09 INFO Vacuumed table table=multipart_uploads25232026/10/01 09:53:09 INFO Vacuumed table table=closures25242026/10/01 09:53:09 INFO Vacuumed table table=objects25252026/10/01 09:53:09 OK 20241026095416_initial_model.sql (186.44ms)25262026-10-01 09:53:09.561 UTC [91927] ERROR: relation "goose_db_version" does not exist at character 3625272026-10-01 09:53:09.561 UTC [91927] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25282026/10/01 09:53:09 OK 20251210153512_drop_unused_gin_index.sql (2.63ms)25292026/10/01 09:53:09 OK 20251218171726_add_pins.sql (6.96ms)25302026/10/01 09:53:09 OK 20260628120000_add_object_size_and_stats.sql (38.36ms)25312026/10/01 09:53:09 OK 20260905000000_add_claims.sql (97.2ms)25322026/10/01 09:53:09 OK 20260920000000_drop_claims.sql (65.49ms)25332026/10/01 09:53:09 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=025342026/10/01 09:53:09 INFO Received create pin request method=POST path=/api/pins/myapp25352026/10/01 09:53:09 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-90619-4025703153/TestPinProtectsFromGC2324708673/001/store/nwq6va437bcr3l0lvqmk1zaq4jji34ai-pinned-file.txt narinfo_key=nwq6va437bcr3l0lvqmk1zaq4jji34ai.narinfo25362026/10/01 09:53:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures25372026/10/01 09:53:09 INFO Garbage collection started25382026/10/01 09:53:09 INFO Aborted multipart uploads count=025392026/10/01 09:53:09 WARN Force mode enabled - objects will be deleted immediately without grace period25402026/10/01 09:53:09 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=025412026/10/01 09:53:09 OK 20260923120000_add_pushes.sql (38.39ms)25422026/10/01 09:53:09 goose: successfully migrated database to version: 2026092312000025432026/10/01 09:53:09 INFO Vacuumed table table=pending_closures25442026/10/01 09:53:09 INFO Vacuumed table table=pending_objects25452026/10/01 09:53:09 INFO Vacuumed table table=multipart_uploads25462026/10/01 09:53:09 INFO Vacuumed table table=closures25472026/10/01 09:53:09 OK 1_commit_pending_closure.sql (2.62ms)25482026/10/01 09:53:09 INFO Vacuumed table table=objects25492026/10/01 09:53:09 OK 2_object_stats_trigger.sql (638.54µs)25502026/10/01 09:53:09 OK 3_commit_push.sql (423.63µs)25512026/10/01 09:53:09 goose: up to current file version: 325522026/10/01 09:53:09 OK 20241026095416_initial_model.sql (280.32ms)25532026/10/01 09:53:09 OK 20251210153512_drop_unused_gin_index.sql (13.06ms)25542026/10/01 09:53:09 OK 20251218171726_add_pins.sql (46.88ms)25552026/10/01 09:53:10 OK 20260628120000_add_object_size_and_stats.sql (159.18ms)25562026/10/01 09:53:10 OK 20260905000000_add_claims.sql (95.31ms)25572026/10/01 09:53:10 OK 20260920000000_drop_claims.sql (48.92ms)25582026/10/01 09:53:10 OK 20260923120000_add_pushes.sql (10.94ms)25592026/10/01 09:53:10 goose: successfully migrated database to version: 2026092312000025602026/10/01 09:53:10 OK 1_commit_pending_closure.sql (5ms)25612026/10/01 09:53:10 OK 2_object_stats_trigger.sql (898.83µs)25622026/10/01 09:53:10 OK 3_commit_push.sql (471.54µs)25632026/10/01 09:53:10 goose: up to current file version: 32564=== RUN TestService_RequireScope_OIDC/builder_may_write2565=== PAUSE TestService_RequireScope_OIDC/builder_may_write2566=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2567=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2568=== RUN TestService_RequireScope_OIDC/ops_may_admin2569=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2570=== RUN TestService_RequireScope_OIDC/ops_may_not_write2571=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2572=== RUN TestService_RequireScope_OIDC/reader_may_not_write2573=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2574=== RUN TestService_RequireScope_OIDC/static_token_may_admin2575=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2576=== RUN TestService_RequireScope_OIDC/static_token_may_write2577=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2578=== RUN TestService_RequireScope_OIDC/reader_may_read2579=== PAUSE TestService_RequireScope_OIDC/reader_may_read2580=== RUN TestService_RequireScope_OIDC/writer_implies_read2581=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2582=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2583=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2584=== CONT TestGCTaskStore_StartNew2585--- PASS: TestGCTaskStore_StartNew (0.00s)2586=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows2587--- PASS: TestCacheStatsHandler (4.78s)2588=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check25892026-10-01 09:53:10.963 UTC [91933] ERROR: relation "goose_db_version" does not exist at character 3625902026-10-01 09:53:10.963 UTC [91933] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25912026-10-01 09:53:11.072 UTC [91934] ERROR: relation "goose_db_version" does not exist at character 3625922026-10-01 09:53:11.072 UTC [91934] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25932026/10/01 09:53:11 OK 20241026095416_initial_model.sql (78.23ms)25942026/10/01 09:53:11 OK 20251210153512_drop_unused_gin_index.sql (6.4ms)25952026/10/01 09:53:11 OK 20251218171726_add_pins.sql (20.84ms)25962026-10-01 09:53:11.104 UTC [91935] ERROR: relation "goose_db_version" does not exist at character 3625972026-10-01 09:53:11.104 UTC [91935] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25982026/10/01 09:53:11 OK 20260628120000_add_object_size_and_stats.sql (21.36ms)25992026/10/01 09:53:11 OK 20260905000000_add_claims.sql (12.57ms)26002026/10/01 09:53:11 OK 20260920000000_drop_claims.sql (15.66ms)26012026-10-01 09:53:11.158 UTC [91936] ERROR: relation "goose_db_version" does not exist at character 3626022026-10-01 09:53:11.158 UTC [91936] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26032026/10/01 09:53:11 OK 20260923120000_add_pushes.sql (9.52ms)26042026/10/01 09:53:11 goose: successfully migrated database to version: 2026092312000026052026/10/01 09:53:11 OK 1_commit_pending_closure.sql (4.33ms)26062026/10/01 09:53:11 OK 2_object_stats_trigger.sql (593.33µs)26072026/10/01 09:53:11 OK 3_commit_push.sql (356.96µs)26082026/10/01 09:53:11 goose: up to current file version: 326092026/10/01 09:53:11 OK 20241026095416_initial_model.sql (85.14ms)26102026/10/01 09:53:11 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02611=== NAME TestClientIntegration2612 client_integration_test.go:323: Objects in database after GC:2613 client_integration_test.go:323: Successfully deleted all objects with GC --force26142026/10/01 09:53:11 OK 20251210153512_drop_unused_gin_index.sql (15.68ms)26152026/10/01 09:53:11 OK 20251218171726_add_pins.sql (19.23ms)26162026/10/01 09:53:11 OK 20241026095416_initial_model.sql (120.37ms)2617=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info2618--- PASS: TestClientIntegration (8.55s)26192026/10/01 09:53:11 INFO Received uploads request method=POST path=/2620=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key26212026/10/01 09:53:11 INFO Received complete multipart upload request method=POST path=/2622=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key26232026/10/01 09:53:11 INFO Received request for more parts method=POST path=/2624=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal26252026/10/01 09:53:11 INFO Received uploads request method=POST path=/2626--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2627 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2628 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2629 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2630 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2631=== CONT TestIsValidUploadKey/narinfo2632=== CONT TestIsValidUploadKey/realisation_plus_in_output2633=== CONT TestIsValidUploadKey/unknown_type2634=== CONT TestIsValidUploadKey/empty_key2635=== CONT TestIsValidUploadKey/absolute2636=== CONT TestIsValidUploadKey/traversal_nar2637=== CONT TestIsValidUploadKey/traversal2638=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2639=== CONT TestIsValidUploadKey/index.html2640=== CONT TestIsValidUploadKey/nix-cache-info2641=== CONT TestIsValidUploadKey/build_log_home-manager_file2642=== CONT TestIsValidUploadKey/realisation2643=== CONT TestIsValidUploadKey/build_log_equals2644=== CONT TestIsValidUploadKey/build_log_question_mark2645=== CONT TestIsValidUploadKey/build_log_plus_in_name2646=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2647=== CONT TestIsValidUploadKey/nar_plain2648=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2649=== CONT TestIsValidUploadKey/build_log2650=== CONT TestIsValidUploadKey/listing2651=== CONT TestIsValidUploadKey/nar_xz2652=== CONT TestIsValidUploadKey/nar_zst2653--- PASS: TestIsValidUploadKey (0.00s)2654 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2655 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2656 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2657 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2658 --- PASS: TestIsValidUploadKey/absolute (0.00s)2659 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2660 --- PASS: TestIsValidUploadKey/traversal (0.00s)2661 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2662 --- PASS: TestIsValidUploadKey/index.html (0.00s)2663 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2664 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2665 --- PASS: TestIsValidUploadKey/realisation (0.00s)2666 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2667 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2668 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2669 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2670 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2671 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2672 --- PASS: TestIsValidUploadKey/build_log (0.00s)2673 --- PASS: TestIsValidUploadKey/listing (0.00s)2674 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2675 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2676=== CONT TestProxyWriteTimeout/narinfo2677=== CONT TestProxyWriteTimeout/10_GiB_nar2678=== CONT TestProxyWriteTimeout/unknown_size2679=== CONT TestProxyWriteTimeout/1_GiB_nar2680--- PASS: TestProxyWriteTimeout (0.00s)2681 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2682 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2683 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2684 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2685=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart26862026/10/01 09:53:11 INFO Received complete multipart upload request method=POST path=/26872026/10/01 09:53:11 OK 20260628120000_add_object_size_and_stats.sql (41.51ms)26882026/10/01 09:53:11 OK 20251210153512_drop_unused_gin_index.sql (13.39ms)2689=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure26902026/10/01 09:53:11 INFO Received uploads request method=POST path=/26912026/10/01 09:53:11 OK 20251218171726_add_pins.sql (30.61ms)26922026/10/01 09:53:11 OK 20260905000000_add_claims.sql (49.3ms)26932026/10/01 09:53:11 OK 20260628120000_add_object_size_and_stats.sql (15.1ms)26942026/10/01 09:53:11 OK 20241026095416_initial_model.sql (127.85ms)26952026/10/01 09:53:11 OK 20251210153512_drop_unused_gin_index.sql (6.03ms)26962026/10/01 09:53:11 OK 20260920000000_drop_claims.sql (8.75ms)26972026/10/01 09:53:11 OK 20260923120000_add_pushes.sql (6.31ms)26982026/10/01 09:53:11 goose: successfully migrated database to version: 2026092312000026992026/10/01 09:53:11 OK 20251218171726_add_pins.sql (6.57ms)27002026/10/01 09:53:11 OK 1_commit_pending_closure.sql (1.05ms)27012026/10/01 09:53:11 OK 2_object_stats_trigger.sql (216.25µs)27022026/10/01 09:53:11 OK 3_commit_push.sql (243.38µs)27032026/10/01 09:53:11 goose: up to current file version: 327042026/10/01 09:53:11 OK 20260905000000_add_claims.sql (14.92ms)27052026/10/01 09:53:11 OK 20260628120000_add_object_size_and_stats.sql (9.85ms)27062026/10/01 09:53:11 OK 20260920000000_drop_claims.sql (15.09ms)27072026-10-01 09:53:11.357 UTC [91937] ERROR: relation "goose_db_version" does not exist at character 3627082026-10-01 09:53:11.357 UTC [91937] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27092026/10/01 09:53:11 OK 20260923120000_add_pushes.sql (6.98ms)27102026/10/01 09:53:11 goose: successfully migrated database to version: 2026092312000027112026/10/01 09:53:11 OK 1_commit_pending_closure.sql (863.25µs)27122026/10/01 09:53:11 OK 2_object_stats_trigger.sql (186.17µs)27132026/10/01 09:53:11 OK 3_commit_push.sql (175.38µs)27142026/10/01 09:53:11 goose: up to current file version: 327152026/10/01 09:53:11 OK 20260905000000_add_claims.sql (30.57ms)27162026-10-01 09:53:11.373 UTC [91938] ERROR: relation "goose_db_version" does not exist at character 3627172026-10-01 09:53:11.373 UTC [91938] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27182026/10/01 09:53:11 OK 20260920000000_drop_claims.sql (11.29ms)27192026/10/01 09:53:11 OK 20260923120000_add_pushes.sql (7.55ms)27202026/10/01 09:53:11 goose: successfully migrated database to version: 2026092312000027212026/10/01 09:53:11 OK 1_commit_pending_closure.sql (37.03ms)27222026/10/01 09:53:11 OK 2_object_stats_trigger.sql (337.5µs)27232026/10/01 09:53:11 OK 3_commit_push.sql (182.54µs)27242026/10/01 09:53:11 goose: up to current file version: 32725--- PASS: TestPresentReportsOnlyClosureRoots (3.87s)2726=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts27272026/10/01 09:53:11 INFO Received request for more parts method=POST path=/2728=== CONT TestIsValidCachePath/narinfo2729=== CONT TestIsValidCachePath/index.html2730=== CONT TestIsValidCachePath/nix-cache-info2731=== CONT TestIsValidCachePath/realisation2732=== CONT TestIsValidCachePath/log2733=== CONT TestIsValidCachePath/ls2734=== CONT TestIsValidCachePath/nar_uncompressed2735=== CONT TestIsValidCachePath/nar_bz22736=== CONT TestIsValidCachePath/nar_xz2737=== CONT TestIsValidCachePath/nar_zst2738=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2739=== CONT TestIsValidCachePath/empty2740=== CONT TestIsValidCachePath/traversal_parent2741=== CONT TestIsValidCachePath/random_path2742=== CONT TestIsValidCachePath/invalid_char_u2743=== CONT TestIsValidCachePath/invalid_char_e2744=== CONT TestIsValidCachePath/traversal_in_middle2745=== CONT TestIsValidCachePath/wrong_extension2746=== CONT TestIsValidCachePath/short_hash2747=== CONT TestIsValidCachePath/leading_slash2748--- PASS: TestIsValidCachePath (0.00s)2749 --- PASS: TestIsValidCachePath/narinfo (0.00s)2750 --- PASS: TestIsValidCachePath/index.html (0.00s)2751 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2752 --- PASS: TestIsValidCachePath/realisation (0.00s)2753 --- PASS: TestIsValidCachePath/log (0.00s)2754 --- PASS: TestIsValidCachePath/ls (0.00s)2755 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2756 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2757 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2758 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2759 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2760 --- PASS: TestIsValidCachePath/empty (0.00s)2761 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2762 --- PASS: TestIsValidCachePath/random_path (0.00s)2763 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2764 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2765 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2766 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2767 --- PASS: TestIsValidCachePath/short_hash (0.00s)2768 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2769=== CONT TestParseSingleRange/none2770=== CONT TestParseSingleRange/open-ended2771=== CONT TestParseSingleRange/start_far_past_EOF2772=== CONT TestParseSingleRange/start_past_EOF2773=== CONT TestParseSingleRange/single_byte2774=== CONT TestParseSingleRange/suffix_exceeds_size2775=== CONT TestParseSingleRange/suffix2776=== CONT TestParseSingleRange/end_clamped_to_size2777=== CONT TestParseSingleRange/malformed_both_empty2778=== CONT TestParseSingleRange/closed2779=== CONT TestParseSingleRange/malformed_end_before_start2780=== CONT TestParseSingleRange/multi-range_ignored2781=== CONT TestParseSingleRange/malformed_no_dash2782=== CONT TestParseSingleRange/unknown_unit2783--- PASS: TestParseSingleRange (0.00s)2784 --- PASS: TestParseSingleRange/none (0.00s)2785 --- PASS: TestParseSingleRange/open-ended (0.00s)2786 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2787 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2788 --- PASS: TestParseSingleRange/single_byte (0.00s)2789 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2790 --- PASS: TestParseSingleRange/suffix (0.00s)2791 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2792 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2793 --- PASS: TestParseSingleRange/closed (0.00s)2794 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2795 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2796 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2797 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2798=== CONT TestPush_RejectsBadRequests/no_roots27992026/10/01 09:53:11 INFO Received push request method=POST path=/api/pushes2800=== CONT TestPush_RejectsBadRequests/root_not_in_objects28012026/10/01 09:53:11 INFO Received push request method=POST path=/api/pushes2802=== CONT TestPush_RejectsBadRequests/bad_root28032026/10/01 09:53:11 INFO Received push request method=POST path=/api/pushes2804=== CONT TestPush_RejectsBadRequests/no_objects28052026/10/01 09:53:11 INFO Received push request method=POST path=/api/pushes2806=== CONT TestResolveDBConnectionString/flag_wins2807=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2808=== CONT TestResolveDBConnectionString/nothing_configured2809=== CONT TestResolveDBConnectionString/missing_file_is_an_error2810=== CONT TestResolveDBConnectionString/file_when_flag_empty2811--- PASS: TestPush_RejectsBadRequests (7.80s)2812 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2813 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2814 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2815 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2816=== CONT TestCacheConfigHandler/full_config,_no_issuer2817=== CONT TestCacheConfigHandler/no_signing_keys2818=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2819=== CONT TestCacheConfigHandler/no_cache_url_configured2820--- PASS: TestCacheConfigHandler (0.00s)2821 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2822 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2823 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2824 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2825=== CONT TestClientErrorHandling/InvalidStorePath2826--- PASS: TestResolveDBConnectionString (0.03s)2827 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2828 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2829 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2830 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2831 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)28322026/10/01 09:53:11 OK 20241026095416_initial_model.sql (121.89ms)28332026/10/01 09:53:11 OK 20251210153512_drop_unused_gin_index.sql (5.97ms)28342026/10/01 09:53:11 OK 20251218171726_add_pins.sql (11.66ms)28352026/10/01 09:53:11 OK 20241026095416_initial_model.sql (90.84ms)28362026/10/01 09:53:11 OK 20251210153512_drop_unused_gin_index.sql (7.67ms)28372026/10/01 09:53:11 OK 20260628120000_add_object_size_and_stats.sql (9.48ms)28382026/10/01 09:53:11 OK 20251218171726_add_pins.sql (23.54ms)2839=== CONT TestClientErrorHandling/ServerNotAvailable2840--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)2841 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)2842 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)2843 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.28s)28442026/10/01 09:53:11 OK 20260905000000_add_claims.sql (54.4ms)28452026/10/01 09:53:11 OK 20260628120000_add_object_size_and_stats.sql (31.68ms)28462026/10/01 09:53:11 OK 20260920000000_drop_claims.sql (22.23ms)28472026/10/01 09:53:11 OK 20260923120000_add_pushes.sql (11.09ms)28482026/10/01 09:53:11 goose: successfully migrated database to version: 2026092312000028492026/10/01 09:53:11 OK 20260905000000_add_claims.sql (32.73ms)28502026/10/01 09:53:11 OK 1_commit_pending_closure.sql (973.29µs)28512026/10/01 09:53:11 OK 2_object_stats_trigger.sql (238.79µs)28522026/10/01 09:53:11 OK 3_commit_push.sql (172.42µs)28532026/10/01 09:53:11 goose: up to current file version: 32854--- PASS: TestService_ReadAuthMiddleware (3.20s)2855=== CONT TestClientErrorHandling/InvalidAuthToken28562026/10/01 09:53:11 OK 20260920000000_drop_claims.sql (69.56ms)28572026/10/01 09:53:11 OK 20260923120000_add_pushes.sql (19.92ms)28582026/10/01 09:53:11 goose: successfully migrated database to version: 2026092312000028592026/10/01 09:53:11 OK 1_commit_pending_closure.sql (1.37ms)28602026/10/01 09:53:11 OK 2_object_stats_trigger.sql (240.33µs)28612026/10/01 09:53:11 OK 3_commit_push.sql (197.63µs)28622026/10/01 09:53:11 goose: up to current file version: 32863=== NAME TestPinProtectsFromGC2864 client_integration_test.go:840: Pin successfully protected closure from garbage collection28652026/10/01 09:53:11 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/present2866--- PASS: TestPinProtectsFromGC (9.98s)2867=== CONT TestServerTLSConfig/no_client_CA2868=== CONT TestServerTLSConfig/not_a_PEM_file2869=== CONT TestServerTLSConfig/missing_CA_file2870=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2871--- PASS: TestServerTLSConfig (0.00s)2872 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2873 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.01s)2874 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2875=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected28762026/10/01 09:53:11 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]2877=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected28782026/10/01 09:53:11 WARN Authentication failed token_preview=eyJhbGciOi...0EYAQIOvQA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2879=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2880=== CONT TestService_RequireScope_OIDC/builder_may_write2881=== CONT TestService_RequireScope_OIDC/static_token_may_admin2882=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2883=== CONT TestService_RequireScope_OIDC/writer_implies_read2884=== CONT TestService_RequireScope_OIDC/reader_may_read2885=== CONT TestService_RequireScope_OIDC/static_token_may_write2886=== CONT TestService_RequireScope_OIDC/ops_may_not_write2887=== CONT TestService_RequireScope_OIDC/reader_may_not_write2888=== CONT TestService_RequireScope_OIDC/ops_may_admin2889=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2890--- PASS: TestService_AuthMiddleware_OIDC (5.72s)2891 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2892 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2893 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2894 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2895--- PASS: TestService_RequireScope_OIDC (4.90s)2896 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2897 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2898 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2899 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2900 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2901 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2902 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2903 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2904 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2905 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)29062026/10/01 09:53:11 WARN mTLS auth: subject not in bound subjects subject="CN=reader"29072026/10/01 09:53:11 WARN mTLS auth: subject not in bound subjects subject="CN=reader"2908--- PASS: TestService_NativeMTLS (3.56s)29092026/10/01 09:53:11 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=200.453495ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29102026-10-01 09:53:12.066 UTC [91947] ERROR: relation "goose_db_version" does not exist at character 3629112026-10-01 09:53:12.066 UTC [91947] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29122026/10/01 09:53:12 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=434.671949ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29132026/10/01 09:53:12 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"29142026/10/01 09:53:12 WARN mTLS auth: bound subjects configured but subject DN unavailable29152026/10/01 09:53:12 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2916--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (3.47s)29172026/10/01 09:53:12 OK 20241026095416_initial_model.sql (226.8ms)29182026/10/01 09:53:12 OK 20251210153512_drop_unused_gin_index.sql (5.47ms)29192026/10/01 09:53:12 OK 20251218171726_add_pins.sql (32ms)29202026/10/01 09:53:12 OK 20260628120000_add_object_size_and_stats.sql (31.81ms)29212026/10/01 09:53:12 OK 20260905000000_add_claims.sql (43ms)29222026/10/01 09:53:12 OK 20260920000000_drop_claims.sql (47.43ms)2923--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (3.36s)29242026/10/01 09:53:12 OK 20260923120000_add_pushes.sql (24.4ms)29252026/10/01 09:53:12 goose: successfully migrated database to version: 2026092312000029262026-10-01 09:53:12.525 UTC [91948] ERROR: relation "goose_db_version" does not exist at character 3629272026-10-01 09:53:12.525 UTC [91948] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29282026/10/01 09:53:12 OK 1_commit_pending_closure.sql (6.7ms)29292026/10/01 09:53:12 OK 2_object_stats_trigger.sql (1.01ms)29302026/10/01 09:53:12 OK 3_commit_push.sql (530.79µs)29312026/10/01 09:53:12 goose: up to current file version: 329322026/10/01 09:53:12 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=872.825832ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29332026/10/01 09:53:12 OK 20241026095416_initial_model.sql (200.49ms)29342026/10/01 09:53:12 OK 20251210153512_drop_unused_gin_index.sql (14.43ms)29352026/10/01 09:53:12 OK 20251218171726_add_pins.sql (40.03ms)29362026/10/01 09:53:12 OK 20260628120000_add_object_size_and_stats.sql (58ms)29372026/10/01 09:53:13 OK 20260905000000_add_claims.sql (115.27ms)29382026/10/01 09:53:13 OK 20260920000000_drop_claims.sql (46.78ms)29392026/10/01 09:53:13 OK 20260923120000_add_pushes.sql (6.55ms)29402026/10/01 09:53:13 goose: successfully migrated database to version: 2026092312000029412026/10/01 09:53:13 OK 1_commit_pending_closure.sql (1.14ms)29422026/10/01 09:53:13 OK 2_object_stats_trigger.sql (313.38µs)29432026/10/01 09:53:13 OK 3_commit_push.sql (221.79µs)29442026/10/01 09:53:13 goose: up to current file version: 329452026-10-01 09:53:13.179 UTC [91952] ERROR: relation "goose_db_version" does not exist at character 3629462026-10-01 09:53:13.179 UTC [91952] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29472026/10/01 09:53:13 INFO Received uploads request method=POST path=/api/pending_closures29482026/10/01 09:53:13 INFO Aborted multipart uploads count=029492026/10/01 09:53:13 WARN Force mode enabled - objects will be deleted immediately without grace period29502026/10/01 09:53:13 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=029512026/10/01 09:53:13 INFO Vacuumed table table=pending_closures29522026/10/01 09:53:13 INFO Vacuumed table table=pending_objects29532026/10/01 09:53:13 INFO Vacuumed table table=multipart_uploads29542026/10/01 09:53:13 INFO Vacuumed table table=closures29552026/10/01 09:53:13 INFO Vacuumed table table=objects29562026/10/01 09:53:13 OK 20241026095416_initial_model.sql (110.02ms)29572026/10/01 09:53:13 OK 20251210153512_drop_unused_gin_index.sql (14.59ms)29582026/10/01 09:53:13 OK 20251218171726_add_pins.sql (22.23ms)29592026/10/01 09:53:13 OK 20260628120000_add_object_size_and_stats.sql (31.52ms)2960=== NAME TestClientCADerivations2961 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-90619-4025703153/TestClientCADerivations1098050591/001/store/2ignsv0wdfppc8cd0ily97w1zl50h9yf-ca-test29622026-10-01 09:53:13.444 UTC [91958] ERROR: relation "goose_db_version" does not exist at character 3629632026-10-01 09:53:13.444 UTC [91958] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29642026/10/01 09:53:13 OK 20260905000000_add_claims.sql (67.24ms)29652026/10/01 09:53:13 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.583799189s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2966 client_ca_test.go:139: Found 1 dependencies (including self)29672026/10/01 09:53:13 OK 20260920000000_drop_claims.sql (35.44ms)29682026/10/01 09:53:13 OK 20260923120000_add_pushes.sql (5.72ms)29692026/10/01 09:53:13 goose: successfully migrated database to version: 2026092312000029702026/10/01 09:53:13 OK 1_commit_pending_closure.sql (858.08µs)29712026/10/01 09:53:13 OK 2_object_stats_trigger.sql (240.96µs)29722026/10/01 09:53:13 OK 3_commit_push.sql (202.13µs)29732026/10/01 09:53:13 goose: up to current file version: 329742026/10/01 09:53:13 OK 20241026095416_initial_model.sql (46.64ms)29752026/10/01 09:53:13 OK 20251210153512_drop_unused_gin_index.sql (18.29ms)29762026/10/01 09:53:13 INFO Received uploads request method=POST path=/api/pending_closures29772026/10/01 09:53:13 OK 20251218171726_add_pins.sql (24.44ms)29782026/10/01 09:53:13 INFO Aborted multipart uploads count=029792026/10/01 09:53:13 WARN Force mode enabled - objects will be deleted immediately without grace period29802026/10/01 09:53:13 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=029812026/10/01 09:53:13 INFO Vacuumed table table=pending_closures29822026/10/01 09:53:13 OK 20260628120000_add_object_size_and_stats.sql (19.24ms)29832026/10/01 09:53:13 INFO Vacuumed table table=pending_objects29842026/10/01 09:53:13 INFO Vacuumed table table=multipart_uploads29852026/10/01 09:53:13 INFO Vacuumed table table=closures29862026/10/01 09:53:13 INFO Vacuumed table table=objects29872026/10/01 09:53:13 INFO Received push request method=POST path=/api/pushes2988--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2989 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (3.11s)2990 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (2.83s)29912026/10/01 09:53:13 OK 20260905000000_add_claims.sql (55.45ms)29922026/10/01 09:53:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)29932026/10/01 09:53:13 INFO Uploading 2ignsv0wdfppc8cd0ily97w1zl50h9yf-ca-test (144B)29942026/10/01 09:53:13 WARN Failed to register uploaded object key=2ignsv0wdfppc8cd0ily97w1zl50h9yf.ls error="server returned 404: 404 page not found\n"29952026/10/01 09:53:13 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"29962026/10/01 09:53:13 OK 20260920000000_drop_claims.sql (30.67ms)29972026/10/01 09:53:13 WARN Failed to register uploaded object key=log/fd3v7yhp448qy88s74z1mainskbf2mcq-ca-test.drv error="server returned 404: 404 page not found\n"29982026/10/01 09:53:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign29992026/10/01 09:53:13 INFO Signed narinfos id=1 count=130002026/10/01 09:53:13 INFO Uploading 1 narinfos30012026/10/01 09:53:13 OK 20260923120000_add_pushes.sql (17.11ms)30022026/10/01 09:53:13 goose: successfully migrated database to version: 2026092312000030032026/10/01 09:53:13 OK 1_commit_pending_closure.sql (1.12ms)30042026/10/01 09:53:13 OK 2_object_stats_trigger.sql (248.29µs)30052026/10/01 09:53:13 OK 3_commit_push.sql (202.08µs)30062026/10/01 09:53:13 goose: up to current file version: 330072026/10/01 09:53:13 INFO Received complete push request method=POST path=/api/pushes/1/complete30082026/10/01 09:53:13 WARN Failed to register uploaded object key=2ignsv0wdfppc8cd0ily97w1zl50h9yf.narinfo error="server returned 404: 404 page not found\n"30092026/10/01 09:53:13 INFO Upload complete. (215ms)3010=== NAME TestClientCADerivations3011 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-90619-4025703153/TestClientCADerivations1098050591/001/store/2ignsv0wdfppc8cd0ily97w1zl50h9yf-ca-test3012 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst3013 Compression: zstd3014 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n3015 NarSize: 1443016 References: 3017 Deriver: /nix/var/nix/builds/nix-90619-4025703153/TestClientCADerivations1098050591/001/store/fd3v7yhp448qy88s74z1mainskbf2mcq-ca-test.drv3018 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n3019 client_ca_test.go:185: Checking for realisation files in S3...3020 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations3021 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache3022 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket80?endpoint=http://localhost:55105®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-90619-4025703153/TestClientCADerivations1098050591/001/store'3023 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 13024--- PASS: TestClientCADerivations (4.73s)30252026/10/01 09:53:14 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30262026/10/01 09:53:14 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30272026/10/01 09:53:15 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-config30282026/10/01 09:53:15 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=219.885204ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30292026/10/01 09:53:15 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=381.712047ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30302026/10/01 09:53:15 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=837.204096ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30312026/10/01 09:53:16 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.53246378s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30322026/10/01 09:53:18 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"30332026/10/01 09:53:18 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-config30342026/10/01 09:53:18 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=217.182002ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30352026/10/01 09:53:18 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=408.173181ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30362026/10/01 09:53:18 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=805.417389ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30372026/10/01 09:53:19 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.503311875s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30382026/10/01 09:53:21 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_closures30392026/10/01 09:53:21 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=210.670987ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30402026/10/01 09:53:21 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=385.458372ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30412026/10/01 09:53:21 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=732.524803ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30422026/10/01 09:53:22 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.710026614s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures3043--- PASS: TestClientErrorHandling (0.00s)3044 --- PASS: TestClientErrorHandling/InvalidStorePath (2.38s)3045 --- PASS: TestClientErrorHandling/InvalidAuthToken (2.57s)3046 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.86s)3047PASS3048{"timestamp":"2026-10-01T09:53:24.442538Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:55282","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(10)"}30492026-10-01 09:53:27.048 UTC [90874] LOG: received smart shutdown request30502026-10-01 09:53:27.053 UTC [90874] LOG: background worker "logical replication launcher" (PID 90885) exited with exit code 130512026-10-01 09:53:27.264 UTC [90880] LOG: shutting down30522026-10-01 09:53:27.264 UTC [90880] LOG: checkpoint starting: shutdown immediate30532026/10/01 09:53:34 ERROR failed to kill rustfs error="no such process"30542026-10-01 09:53:36.861 UTC [90880] LOG: checkpoint complete: wrote 12542 buffers (76.6%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 24 recycled; write=6.345 s, sync=2.763 s, total=9.598 s; sync files=28316, longest=0.013 s, average=0.001 s; distance=398717 kB, estimate=398717 kB; lsn=0/19CEC4F8, redo lsn=0/19CEC4F830552026-10-01 09:53:36.959 UTC [90874] LOG: database system is shut down30562026/10/01 09:53:37 ERROR failed to kill rustfs error="no such process"3057Running OIDC tests...3058=== RUN TestAudienceForIssuer3059=== PAUSE TestAudienceForIssuer3060=== RUN TestGlobMatch3061=== PAUSE TestGlobMatch3062=== RUN TestValidateToken_ValidToken3063=== PAUSE TestValidateToken_ValidToken3064=== RUN TestValidateToken_WrongAudience3065=== PAUSE TestValidateToken_WrongAudience3066=== RUN TestValidateToken_Expired3067=== PAUSE TestValidateToken_Expired3068=== RUN TestValidateToken_BoundClaimsMismatch3069=== PAUSE TestValidateToken_BoundClaimsMismatch3070=== RUN TestValidateToken_BoundSubjectMismatch3071=== PAUSE TestValidateToken_BoundSubjectMismatch3072=== RUN TestValidateToken_MultipleProviders3073=== PAUSE TestValidateToken_MultipleProviders3074=== RUN TestValidateToken_NoMatchingProvider3075=== PAUSE TestValidateToken_NoMatchingProvider3076=== RUN TestValidateToken_KubernetesServiceAccount3077=== PAUSE TestValidateToken_KubernetesServiceAccount3078=== RUN TestNewValidator_KubernetesRequiresCA3079=== PAUSE TestNewValidator_KubernetesRequiresCA3080=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3081=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3082=== RUN TestPins_ReservedForMatchingRule3083=== PAUSE TestPins_ReservedForMatchingRule3084=== RUN TestPins_TopLevelShorthand3085=== PAUSE TestPins_TopLevelShorthand3086=== RUN TestPins_ConfigValidation3087=== PAUSE TestPins_ConfigValidation3088=== RUN TestScopes_LegacyProviderDefaultsToWrite3089=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3090=== RUN TestScopes_Rules3091=== PAUSE TestScopes_Rules3092=== RUN TestScopes_ConfigValidation3093=== PAUSE TestScopes_ConfigValidation3094=== CONT TestAudienceForIssuer3095--- PASS: TestAudienceForIssuer (0.00s)3096=== CONT TestScopes_ConfigValidation3097=== CONT TestValidateToken_NoMatchingProvider3098=== CONT TestValidateToken_MultipleProviders3099=== CONT TestValidateToken_BoundSubjectMismatch3100=== CONT TestValidateToken_BoundClaimsMismatch3101=== CONT TestValidateToken_Expired3102=== CONT TestValidateToken_WrongAudience3103=== CONT TestValidateToken_ValidToken3104=== CONT TestGlobMatch3105=== RUN TestGlobMatch/foo_foo3106=== PAUSE TestGlobMatch/foo_foo3107=== RUN TestGlobMatch/foo_bar3108=== PAUSE TestGlobMatch/foo_bar3109=== RUN TestGlobMatch/*_3110=== PAUSE TestGlobMatch/*_3111=== RUN TestGlobMatch/*_anything3112=== PAUSE TestGlobMatch/*_anything3113=== RUN TestGlobMatch/foo*_foo3114=== PAUSE TestGlobMatch/foo*_foo3115=== RUN TestGlobMatch/foo*_foobar3116=== PAUSE TestGlobMatch/foo*_foobar3117=== RUN TestGlobMatch/foo*_bar3118=== PAUSE TestGlobMatch/foo*_bar3119=== RUN TestGlobMatch/*bar_bar3120=== PAUSE TestGlobMatch/*bar_bar3121=== RUN TestGlobMatch/*bar_foobar3122=== PAUSE TestGlobMatch/*bar_foobar3123=== RUN TestGlobMatch/*bar_foo3124=== CONT TestValidateToken_KubernetesServiceAccount3125=== PAUSE TestGlobMatch/*bar_foo3126=== RUN TestGlobMatch/foo*bar_foobar3127=== PAUSE TestGlobMatch/foo*bar_foobar3128=== RUN TestGlobMatch/foo*bar_foo123bar3129=== PAUSE TestGlobMatch/foo*bar_foo123bar3130=== RUN TestGlobMatch/foo*bar_foobarbaz3131=== PAUSE TestGlobMatch/foo*bar_foobarbaz3132=== RUN TestGlobMatch/*/*_foo/bar3133=== PAUSE TestGlobMatch/*/*_foo/bar3134=== RUN TestGlobMatch/*/*_foo3135=== PAUSE TestGlobMatch/*/*_foo3136=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3137=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3138=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03139=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03140=== RUN TestGlobMatch/refs/*/main_refs/heads/main3141=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3142=== RUN TestGlobMatch/fo?_foo3143=== PAUSE TestGlobMatch/fo?_foo3144=== RUN TestGlobMatch/fo?_fo3145=== PAUSE TestGlobMatch/fo?_fo3146=== RUN TestGlobMatch/fo?_fooo3147=== PAUSE TestGlobMatch/fo?_fooo3148=== RUN TestGlobMatch/?oo_foo3149=== PAUSE TestGlobMatch/?oo_foo3150=== RUN TestGlobMatch/?oo_boo3151=== PAUSE TestGlobMatch/?oo_boo3152=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3153=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3154=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3155=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3156=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3157--- PASS: TestScopes_ConfigValidation (0.02s)3158=== CONT TestPins_ReservedForMatchingRule31592026/10/01 09:53:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56562/oidc3160--- PASS: TestValidateToken_Expired (0.05s)3161=== CONT TestNewValidator_KubernetesRequiresCA31622026/10/01 09:53:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56565/oidc3163--- PASS: TestValidateToken_BoundSubjectMismatch (0.05s)3164=== CONT TestPins_TopLevelShorthand31652026/10/01 09:53:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56567/oidc3166--- PASS: TestValidateToken_ValidToken (0.05s)3167=== CONT TestScopes_Rules31682026/10/01 09:53:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56571/oidc31692026/10/01 09:53:49 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:5656931702026/10/01 09:53:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56573/oidc3171--- PASS: TestValidateToken_WrongAudience (0.07s)3172=== CONT TestScopes_LegacyProviderDefaultsToWrite3173--- PASS: TestValidateToken_BoundClaimsMismatch (0.08s)3174=== CONT TestPins_ConfigValidation3175--- PASS: TestValidateToken_KubernetesServiceAccount (0.07s)3176=== CONT TestGlobMatch/foo_foo3177=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3178=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3179=== CONT TestGlobMatch/?oo_boo3180=== CONT TestGlobMatch/?oo_foo3181=== CONT TestGlobMatch/fo?_fooo3182=== CONT TestGlobMatch/fo?_fo3183=== CONT TestGlobMatch/fo?_foo3184=== CONT TestGlobMatch/refs/*/main_refs/heads/main3185=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03186=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3187=== CONT TestGlobMatch/*/*_foo3188=== CONT TestGlobMatch/*/*_foo/bar3189=== CONT TestGlobMatch/foo*bar_foobarbaz3190=== CONT TestGlobMatch/foo*bar_foo123bar3191=== CONT TestGlobMatch/foo*bar_foobar3192=== CONT TestGlobMatch/*bar_foo3193=== CONT TestGlobMatch/*bar_foobar3194=== CONT TestGlobMatch/*bar_bar3195=== CONT TestGlobMatch/foo*_bar3196=== CONT TestGlobMatch/foo*_foobar3197=== CONT TestGlobMatch/foo*_foo3198=== CONT TestGlobMatch/*_anything3199=== CONT TestGlobMatch/*_3200=== CONT TestGlobMatch/foo_bar3201--- PASS: TestGlobMatch (0.00s)3202 --- PASS: TestGlobMatch/foo_foo (0.00s)3203 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3204 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3205 --- PASS: TestGlobMatch/?oo_boo (0.00s)3206 --- PASS: TestGlobMatch/?oo_foo (0.00s)3207 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3208 --- PASS: TestGlobMatch/fo?_fo (0.00s)3209 --- PASS: TestGlobMatch/fo?_foo (0.00s)3210 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3211 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3212 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3213 --- PASS: TestGlobMatch/*/*_foo (0.00s)3214 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3215 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3216 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3217 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3218 --- PASS: TestGlobMatch/*bar_foo (0.00s)3219 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3220 --- PASS: TestGlobMatch/*bar_bar (0.00s)3221 --- PASS: TestGlobMatch/foo*_bar (0.00s)3222 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3223 --- PASS: TestGlobMatch/foo*_foo (0.00s)3224 --- PASS: TestGlobMatch/*_anything (0.00s)3225 --- PASS: TestGlobMatch/*_ (0.00s)3226 --- PASS: TestGlobMatch/foo_bar (0.00s)3227--- PASS: TestPins_ConfigValidation (0.00s)32282026/10/01 09:53:49 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1233229--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.07s)32302026/10/01 09:53:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56578/oidc32312026/10/01 09:53:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56580/oidc3232--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.02s)3233--- PASS: TestScopes_Rules (0.04s)32342026/10/01 09:53:49 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:56564/oidc3235--- PASS: TestValidateToken_NoMatchingProvider (0.10s)32362026/10/01 09:53:49 http: TLS handshake error from 127.0.0.1:56585: remote error: tls: bad certificate3237--- PASS: TestNewValidator_KubernetesRequiresCA (0.06s)32382026/10/01 09:53:50 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56586/oidc3239--- PASS: TestPins_ReservedForMatchingRule (0.13s)32402026/10/01 09:53:50 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56588/oidc3241--- PASS: TestPins_TopLevelShorthand (0.09s)32422026/10/01 09:53:50 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:56575/oidc32432026/10/01 09:53:50 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:56590/oidc3244--- PASS: TestValidateToken_MultipleProviders (0.20s)3245PASS3246Running hook tests...3247=== RUN TestSendPathsEmpty3248=== PAUSE TestSendPathsEmpty3249=== RUN TestQueueEnqueueAndFetch3250=== PAUSE TestQueueEnqueueAndFetch3251=== RUN TestQueueDeduplication3252=== PAUSE TestQueueDeduplication3253=== RUN TestQueueRemove3254=== PAUSE TestQueueRemove3255=== RUN TestQueueFetchBatchLimit3256=== PAUSE TestQueueFetchBatchLimit3257=== RUN TestQueueRetryMovesToBack3258=== PAUSE TestQueueRetryMovesToBack3259=== RUN TestQueueFetchRemoveLifecycle3260=== PAUSE TestQueueFetchRemoveLifecycle3261=== RUN TestQueueConcurrentWriters3262=== PAUSE TestQueueConcurrentWriters3263=== RUN TestQueueRemoveLargeClosure3264=== PAUSE TestQueueRemoveLargeClosure3265=== RUN TestServerClientIntegration3266=== PAUSE TestServerClientIntegration3267=== RUN TestServerQueueError3268=== PAUSE TestServerQueueError3269=== RUN TestGetListenerSocketActivation3270 server_test.go:210: === RUN TestGetListenerSocketActivation3271 --- PASS: TestGetListenerSocketActivation (0.00s)3272 PASS3273 3274--- PASS: TestGetListenerSocketActivation (0.01s)3275=== RUN TestDrainIsolatesPoisonPath3276=== PAUSE TestDrainIsolatesPoisonPath3277=== RUN TestRunNotBlockedByPoisonHead3278=== PAUSE TestRunNotBlockedByPoisonHead3279=== RUN TestDrainGivesUpWhenServerDown3280=== PAUSE TestDrainGivesUpWhenServerDown3281=== RUN TestFailedPathPrunedByLaterClosure3282=== PAUSE TestFailedPathPrunedByLaterClosure3283=== RUN TestWorkerUploadsAndRemoves3284=== PAUSE TestWorkerUploadsAndRemoves3285=== RUN TestWorkerSkipsGCdPaths3286=== PAUSE TestWorkerSkipsGCdPaths3287=== RUN TestWorkerPrunesClosureDeps3288=== PAUSE TestWorkerPrunesClosureDeps3289=== RUN TestDrainTimeout3290=== PAUSE TestDrainTimeout3291=== CONT TestSendPathsEmpty3292=== CONT TestServerQueueError3293--- PASS: TestSendPathsEmpty (0.00s)3294=== CONT TestServerClientIntegration3295=== CONT TestQueueRemoveLargeClosure3296=== CONT TestWorkerUploadsAndRemoves3297=== CONT TestDrainGivesUpWhenServerDown3298=== CONT TestFailedPathPrunedByLaterClosure3299=== CONT TestRunNotBlockedByPoisonHead3300=== CONT TestDrainIsolatesPoisonPath3301=== CONT TestQueueFetchRemoveLifecycle3302=== CONT TestQueueConcurrentWriters33032026/10/01 09:53:50 ERROR Failed to queue paths error="permission denied" count=13304--- PASS: TestServerClientIntegration (0.00s)3305=== CONT TestQueueRetryMovesToBack3306--- PASS: TestServerQueueError (0.00s)3307=== CONT TestWorkerPrunesClosureDeps33082026/10/01 09:53:50 INFO Upload queue status pending=333092026/10/01 09:53:50 INFO Uploading batch count=433102026/10/01 09:53:50 ERROR Upload failed error="upload failed" count=433112026/10/01 09:53:50 INFO Uploading batch count=133122026/10/01 09:53:50 ERROR Upload failed error="upload failed" count=133132026/10/01 09:53:50 INFO Uploading batch count=133142026/10/01 09:53:50 ERROR Upload failed error="upload failed" count=133152026/10/01 09:53:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-90619-4025703153/TestDrainIsolatesPoisonPath1852068760/002/bbb33162026/10/01 09:53:50 INFO Upload queue status pending=233172026/10/01 09:53:50 INFO Uploading batch count=13318--- PASS: TestQueueRetryMovesToBack (0.01s)3319=== CONT TestDrainTimeout33202026/10/01 09:53:50 INFO Uploading batch count=233212026/10/01 09:53:50 INFO Uploading batch count=233222026/10/01 09:53:50 ERROR Upload failed error="upload failed" count=233232026/10/01 09:53:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-90619-4025703153/TestDrainGivesUpWhenServerDown1698000850/002/a33242026/10/01 09:53:50 INFO Uploading batch count=133252026/10/01 09:53:50 INFO Upload queue status pending=233262026/10/01 09:53:50 INFO Uploading batch count=133272026/10/01 09:53:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-90619-4025703153/TestDrainGivesUpWhenServerDown1698000850/002/b3328--- PASS: TestQueueFetchRemoveLifecycle (0.01s)3329=== CONT TestWorkerSkipsGCdPaths33302026/10/01 09:53:50 INFO Uploading batch count=133312026/10/01 09:53:50 ERROR Upload failed error="upload failed" count=133322026/10/01 09:53:50 INFO Uploading batch count=133332026/10/01 09:53:50 INFO Uploading batch count=233342026/10/01 09:53:50 ERROR Upload failed error="upload failed" count=233352026/10/01 09:53:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-90619-4025703153/TestDrainGivesUpWhenServerDown1698000850/002/c33362026/10/01 09:53:50 ERROR Upload failed error="upload failed" count=133372026/10/01 09:53:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-90619-4025703153/TestDrainGivesUpWhenServerDown1698000850/002/d33382026/10/01 09:53:50 INFO Uploading batch count=133392026/10/01 09:53:50 ERROR Upload failed error="upload failed" count=133402026/10/01 09:53:50 INFO Uploading batch count=233412026/10/01 09:53:50 ERROR Upload failed error="upload failed" count=233422026/10/01 09:53:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-90619-4025703153/TestDrainGivesUpWhenServerDown1698000850/002/e33432026/10/01 09:53:50 ERROR Drain finished with paths left in queue remaining=133442026/10/01 09:53:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-90619-4025703153/TestDrainGivesUpWhenServerDown1698000850/002/f3345--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)3346=== CONT TestQueueDeduplication33472026/10/01 09:53:50 ERROR Drain finished with paths left in queue remaining=1033482026/10/01 09:53:50 INFO Uploading batch count=233492026/10/01 09:53:50 INFO Upload queue status pending=233502026/10/01 09:53:50 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-90619-4025703153/TestWorkerSkipsGCdPaths1039984744/002/nonexistent3351--- PASS: TestDrainIsolatesPoisonPath (0.02s)3352=== CONT TestQueueRemove33532026/10/01 09:53:50 INFO Uploading batch count=13354--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3355=== CONT TestQueueEnqueueAndFetch3356--- PASS: TestQueueDeduplication (0.00s)3357=== CONT TestQueueFetchBatchLimit3358--- PASS: TestQueueRemove (0.00s)3359--- PASS: TestQueueEnqueueAndFetch (0.00s)3360--- PASS: TestQueueFetchBatchLimit (0.00s)3361--- PASS: TestWorkerUploadsAndRemoves (0.03s)3362--- PASS: TestWorkerPrunesClosureDeps (0.03s)3363--- PASS: TestWorkerSkipsGCdPaths (0.02s)3364--- PASS: TestQueueRemoveLargeClosure (0.06s)3365--- PASS: TestQueueConcurrentWriters (0.15s)33662026/10/01 09:53:50 ERROR Upload failed error="context deadline exceeded" count=233672026/10/01 09:53:50 ERROR Drain finished with paths left in queue remaining=43368--- PASS: TestDrainTimeout (0.21s)33692026/10/01 09:53:51 INFO Uploading batch count=133702026/10/01 09:53:51 INFO Uploading batch count=133712026/10/01 09:53:51 INFO Uploading batch count=133722026/10/01 09:53:51 ERROR Upload failed error="upload failed" count=133732026/10/01 09:53:51 INFO Uploading batch count=133742026/10/01 09:53:51 ERROR Upload failed error="upload failed" count=133752026/10/01 09:53:51 INFO Uploading batch count=133762026/10/01 09:53:51 ERROR Upload failed error="upload failed" count=133772026/10/01 09:53:51 INFO Uploading batch count=133782026/10/01 09:53:51 ERROR Upload failed error="upload failed" count=133792026/10/01 09:53:51 ERROR Drain finished with paths left in queue remaining=13380--- PASS: TestRunNotBlockedByPoisonHead (1.04s)3381PASS