niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #355
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestRegisterUploadedObjectReusesConnections5=== PAUSE TestRegisterUploadedObjectReusesConnections6=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica7=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica8=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun9=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun10=== RUN TestCaseHackSuffix11=== PAUSE TestCaseHackSuffix12=== RUN TestFilterOversizedClosures13=== PAUSE TestFilterOversizedClosures14=== RUN TestUploadMultipart_PartsInParallel15=== PAUSE TestUploadMultipart_PartsInParallel16=== RUN TestPartSizeForNAR17=== PAUSE TestPartSizeForNAR18=== RUN TestUploadMultipart_SupersededByPeer19=== PAUSE TestUploadMultipart_SupersededByPeer20=== RUN TestDumpPathCaseHackMatchesNix21--- PASS: TestDumpPathCaseHackMatchesNix (0.06s)22=== RUN TestDumpPathCaseHackCollision23--- PASS: TestDumpPathCaseHackCollision (0.00s)24=== RUN TestDumpPathMatchesNix25=== PAUSE TestDumpPathMatchesNix26=== RUN TestDumpPathSingleFile27=== PAUSE TestDumpPathSingleFile28=== RUN TestDumpPathWriterError29=== PAUSE TestDumpPathWriterError30=== RUN TestEncodeNixBase3231=== PAUSE TestEncodeNixBase3232=== RUN TestEncodeNixBase32WithRealHash33=== PAUSE TestEncodeNixBase32WithRealHash34=== RUN TestConvertHashToNix3235=== PAUSE TestConvertHashToNix3236=== RUN TestGetStorePathHash37=== PAUSE TestGetStorePathHash38=== RUN TestPathInfoHashCompatibility39=== PAUSE TestPathInfoHashCompatibility40=== RUN TestParsePathInfoJSON41=== PAUSE TestParsePathInfoJSON42=== RUN TestParsePathInfoJSONMultiplePaths43=== PAUSE TestParsePathInfoJSONMultiplePaths44=== RUN TestPathInfoCACompatibility45=== PAUSE TestPathInfoCACompatibility46=== RUN TestRateLimiterFeedback47=== PAUSE TestRateLimiterFeedback48=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess49=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess50=== RUN TestResolveStorePath51=== PAUSE TestResolveStorePath52=== RUN TestDoWithRetry_BodyReplayedViaGetBody53=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody54=== RUN TestShellSplit55=== PAUSE TestShellSplit56=== RUN TestShellSplitErrors57=== PAUSE TestShellSplitErrors58=== RUN TestStreamPushReportsEveryPath59=== PAUSE TestStreamPushReportsEveryPath60=== RUN TestStreamPushBatchesUnderLoad61=== PAUSE TestStreamPushBatchesUnderLoad62=== RUN TestStreamPushIsolatesFailures63=== PAUSE TestStreamPushIsolatesFailures64=== RUN TestStreamPushGivesUpOnDeadServer65=== PAUSE TestStreamPushGivesUpOnDeadServer66=== RUN TestStreamPushRequestLine67=== PAUSE TestStreamPushRequestLine68=== RUN TestStreamPushReportsSignatures69=== PAUSE TestStreamPushReportsSignatures70=== RUN TestClientSignaturesByStorePath71=== PAUSE TestClientSignaturesByStorePath72=== RUN TestSetClientTLS73=== PAUSE TestSetClientTLS74=== RUN TestSetClientTLSDoesNotMutateDefaultTransport75=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport76=== RUN TestSetClientTLSErrors77=== PAUSE TestSetClientTLSErrors78=== RUN TestStaticToken79=== PAUSE TestStaticToken80=== RUN TestFileTokenReadsAndCaches81=== PAUSE TestFileTokenReadsAndCaches82=== RUN TestFileTokenMissing83=== PAUSE TestFileTokenMissing84=== RUN TestFileTokenEmpty85=== PAUSE TestFileTokenEmpty86=== RUN TestScriptTokenNoExpiryRerunsEveryCall87=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall88=== RUN TestScriptTokenCachesUntilRefresh89=== PAUSE TestScriptTokenCachesUntilRefresh90=== RUN TestScriptTokenEmptyToken91=== PAUSE TestScriptTokenEmptyToken92=== RUN TestScriptTokenBadJSON93=== PAUSE TestScriptTokenBadJSON94=== RUN TestScriptTokenScriptFails95=== PAUSE TestScriptTokenScriptFails96=== RUN TestScriptTokenEmptyCommand97=== PAUSE TestScriptTokenEmptyCommand98=== CONT TestDoServerRequestAttachesToken99=== CONT TestDoWithRetry_BodyReplayedViaGetBody100=== CONT TestScriptTokenEmptyCommand101=== CONT TestStreamPushGivesUpOnDeadServer102--- PASS: TestScriptTokenEmptyCommand (0.00s)103=== CONT TestScriptTokenScriptFails104=== CONT TestStreamPushReportsEveryPath105=== CONT TestSetClientTLSErrors1062026/10/04 20:06:39 ERROR Upload failed error="connection refused" count=201072026/10/04 20:06:39 ERROR Server seems unavailable, giving up on batch untried=17108=== CONT TestSetClientTLSDoesNotMutateDefaultTransport109--- PASS: TestStreamPushReportsEveryPath (0.00s)110=== CONT TestStreamPushRequestLine111=== CONT TestSetClientTLS1122026/10/04 20:06:39 ERROR Upload failed error=boom count=1113=== CONT TestClientSignaturesByStorePath114--- PASS: TestClientSignaturesByStorePath (0.00s)115=== CONT TestStreamPushIsolatesFailures116=== CONT TestStreamPushReportsSignatures1172026/10/04 20:06:39 ERROR Upload failed error="bad path" count=3118--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)119--- PASS: TestStreamPushIsolatesFailures (0.00s)120=== CONT TestStreamPushBatchesUnderLoad1212026/10/04 20:06:39 ERROR Upload failed error=boom count=1122=== CONT TestEncodeNixBase32123=== RUN TestEncodeNixBase32/test_string_hash124--- PASS: TestStreamPushReportsSignatures (0.00s)125=== CONT TestParsePathInfoJSON126=== RUN TestParsePathInfoJSON/Nix_format127=== PAUSE TestParsePathInfoJSON/Nix_format128=== RUN TestParsePathInfoJSON/Lix_format129=== PAUSE TestParsePathInfoJSON/Lix_format130=== RUN TestParsePathInfoJSON/empty_input131=== PAUSE TestParsePathInfoJSON/empty_input132=== RUN TestParsePathInfoJSON/whitespace_only133=== PAUSE TestParsePathInfoJSON/whitespace_only134=== RUN TestParsePathInfoJSON/invalid_JSON135=== PAUSE TestParsePathInfoJSON/invalid_JSON136=== CONT TestPathInfoHashCompatibility137=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)138=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)139=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon140=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon141=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI142=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI143=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512144=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512145=== CONT TestGetStorePathHash146=== RUN TestGetStorePathHash/valid_store_path147=== PAUSE TestGetStorePathHash/valid_store_path148=== RUN TestGetStorePathHash/basename_without_hyphen_should_error149=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error150=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error151=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error152=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error153=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error154=== CONT TestConvertHashToNix32155=== RUN TestConvertHashToNix32/SRI_format_to_Nix32156=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32157=== RUN TestConvertHashToNix32/already_Nix32_format158=== PAUSE TestConvertHashToNix32/already_Nix32_format159=== RUN TestConvertHashToNix32/invalid_format160=== PAUSE TestConvertHashToNix32/invalid_format161=== CONT TestEncodeNixBase32WithRealHash162--- PASS: TestEncodeNixBase32WithRealHash (0.00s)163=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1642026/10/04 20:06:39 WARN Rate limiter enabled after throttle name=server-test rate=5165=== PAUSE TestEncodeNixBase32/test_string_hash166=== RUN TestEncodeNixBase32/empty_input167=== PAUSE TestEncodeNixBase32/empty_input168=== CONT TestResolveStorePath1692026/10/04 20:06:39 WARN Rate limiter enabled after throttle name=server-test rate=51702026/10/04 20:06:39 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:50604171--- PASS: TestDoServerRequestAttachesToken (0.00s)172=== CONT TestShellSplitErrors173--- PASS: TestShellSplitErrors (0.00s)174=== CONT TestScriptTokenNoExpiryRerunsEveryCall1752026/10/04 20:06:39 WARN Rate limiter backed off name=server-test rate=51762026/10/04 20:06:39 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:50604177--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)178=== CONT TestScriptTokenEmptyToken179--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)180=== CONT TestScriptTokenBadJSON181--- PASS: TestScriptTokenScriptFails (0.00s)182=== RUN TestSetClientTLSErrors/missing_cert_file183=== PAUSE TestSetClientTLSErrors/missing_cert_file184=== CONT TestScriptTokenCachesUntilRefresh185=== RUN TestSetClientTLSErrors/missing_key_file186=== PAUSE TestSetClientTLSErrors/missing_key_file187=== RUN TestSetClientTLSErrors/missing_ca_file188=== PAUSE TestSetClientTLSErrors/missing_ca_file189=== RUN TestSetClientTLSErrors/invalid_ca_file190=== PAUSE TestSetClientTLSErrors/invalid_ca_file191=== CONT TestRateLimiterFeedback192=== RUN TestRateLimiterFeedback/429_enables_limiter193=== PAUSE TestRateLimiterFeedback/429_enables_limiter194=== RUN TestRateLimiterFeedback/503_enables_limiter195=== PAUSE TestRateLimiterFeedback/503_enables_limiter196=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter197=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter198=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter199=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter200=== CONT TestShellSplit201--- PASS: TestShellSplit (0.00s)202=== CONT TestPathInfoCACompatibility203=== RUN TestPathInfoCACompatibility/null_ca_field204=== PAUSE TestPathInfoCACompatibility/null_ca_field205=== RUN TestPathInfoCACompatibility/old_string_format_-_text206=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text207=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive208=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive209=== RUN TestPathInfoCACompatibility/new_structured_format_-_text210=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text211=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method212=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method213=== CONT TestFileTokenMissing214=== CONT TestFileTokenEmpty215--- PASS: TestResolveStorePath (0.00s)216--- PASS: TestFileTokenMissing (0.00s)217=== CONT TestFileTokenReadsAndCaches218=== RUN TestSetClientTLS/rejects_connection_without_client_cert219=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert220=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA221=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA222=== RUN TestSetClientTLS/preserves_debug_logging_transport223=== PAUSE TestSetClientTLS/preserves_debug_logging_transport224=== CONT TestStaticToken225--- PASS: TestStaticToken (0.00s)226=== CONT TestUploadMultipart_PartsInParallel227--- PASS: TestFileTokenEmpty (0.00s)228=== CONT TestDumpPathWriterError229--- PASS: TestFileTokenReadsAndCaches (0.00s)230=== CONT TestDumpPathSingleFile231--- PASS: TestScriptTokenEmptyToken (0.01s)232--- PASS: TestScriptTokenBadJSON (0.01s)233=== CONT TestDumpPathMatchesNix234=== CONT TestUploadMultipart_SupersededByPeer235=== RUN TestUploadMultipart_SupersededByPeer/exists236=== PAUSE TestUploadMultipart_SupersededByPeer/exists237=== RUN TestUploadMultipart_SupersededByPeer/missing238=== PAUSE TestUploadMultipart_SupersededByPeer/missing239=== CONT TestPartSizeForNAR240=== RUN TestPartSizeForNAR/zero_stays_at_minimum241=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum242=== RUN TestPartSizeForNAR/small_stays_at_minimum243=== PAUSE TestPartSizeForNAR/small_stays_at_minimum244=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum245=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum246=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts247=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts248=== RUN TestPartSizeForNAR/1_TiB249=== PAUSE TestPartSizeForNAR/1_TiB250=== RUN TestPartSizeForNAR/5_TiB_S3_max_object251=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object252=== RUN TestPartSizeForNAR/capped_at_5_GiB253=== PAUSE TestPartSizeForNAR/capped_at_5_GiB254=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun2552026/10/04 20:06:39 INFO Garbage collection started256--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.00s)257=== CONT TestFilterOversizedClosures258=== RUN TestFilterOversizedClosures/no_limit_keeps_everything259=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything260=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped261=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped262=== RUN TestFilterOversizedClosures/all_closures_skipped263=== PAUSE TestFilterOversizedClosures/all_closures_skipped264=== CONT TestCaseHackSuffix265--- PASS: TestStreamPushRequestLine (0.02s)266=== CONT TestRegisterUploadedObjectReusesConnections267--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)268=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica2692026/10/04 20:06:39 INFO Garbage collection started2702026/10/04 20:06:39 INFO Garbage collection progress phase=running_on_another_replica failed_uploads_deleted=0 old_closures_deleted=0 objects_marked=0 objects_deleted=0 objects_failed=0271--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)272=== CONT TestParsePathInfoJSONMultiplePaths273=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths274=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths275=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths276=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths277=== CONT TestParsePathInfoJSON/Nix_format278=== CONT TestParsePathInfoJSON/whitespace_only279=== CONT TestParsePathInfoJSON/invalid_JSON280=== CONT TestParsePathInfoJSON/empty_input281=== CONT TestParsePathInfoJSON/Lix_format282--- PASS: TestParsePathInfoJSON (0.00s)283 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)284 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)285 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)286 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)287 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)288=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)289=== CONT TestGetStorePathHash/valid_store_path290=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512291=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI292=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon293--- PASS: TestPathInfoHashCompatibility (0.00s)294 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)295 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)296 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)297 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)298=== CONT TestConvertHashToNix32/SRI_format_to_Nix32299=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error300=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error301=== CONT TestGetStorePathHash/b2026/10/04 20:06:39 WARN Garbage collection finished on another replica. Its statistics are not available here302asename_without_hyphen_should_error303--- PASS: TestDumpPathWriterError (0.04s)304=== CONT TestConvertHashToNix32/invalid_format305=== CONT TestEncodeNixBase32/test_string_hash306=== CONT TestEncodeNixBase32/empty_input307=== CONT TestSetClientTLSErrors/missing_cert_file308=== CONT TestSetClientTLSErrors/missing_ca_file309=== CONT TestSetClientTLSErrors/invalid_ca_file310=== CONT TestConvertHashToNix32/already_Nix32_format311--- PASS: TestGetStorePathHash (0.00s)312 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)313 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)314 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)315 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)316--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.00s)317=== CONT TestSetClientTLSErrors/missing_key_file318--- PASS: TestEncodeNixBase32 (0.00s)319 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)320 --- PASS: TestEncodeNixBase32/empty_input (0.00s)321--- PASS: TestConvertHashToNix32 (0.00s)322 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)323 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)324 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)325=== CONT TestRateLimiterFeedback/429_enables_limiter326=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter327=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter3282026/10/04 20:06:39 WARN Rate limiter enabled after throttle name=server-test rate=53292026/10/04 20:06:39 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:50684330=== CONT TestRateLimiterFeedback/503_enables_limiter331=== CONT TestPathInfoCACompatibility/null_ca_field332=== CONT TestPathInfoCACompatibility/new_structured_format_-_text3332026/10/04 20:06:39 WARN Rate limiter backed off name=server-test rate=5334=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method335=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive336=== CONT TestPathInfoCACompatibility/old_string_format_-_text337=== CONT TestSetClientTLS/rejects_connection_without_client_cert338--- PASS: TestPathInfoCACompatibility (0.00s)339 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)340 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)341 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)342 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)343 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)344=== CONT TestSetClientTLS/preserves_debug_logging_transport345--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)3462026/10/04 20:06:39 WARN Rate limiter enabled after throttle name=server-test rate=5347=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3482026/10/04 20:06:39 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:50690349--- PASS: TestSetClientTLSErrors (0.00s)350 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)351 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)352 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)353 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)3542026/10/04 20:06:39 WARN Rate limiter backed off name=server-test rate=5355--- PASS: TestRateLimiterFeedback (0.00s)356 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)357 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)358 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)359 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)360=== CONT TestUploadMultipart_SupersededByPeer/exists361=== CONT TestUploadMultipart_SupersededByPeer/missing362--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)363 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)364 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)365=== CONT TestPartSizeForNAR/zero_stays_at_minimum366=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts367=== CONT TestPartSizeForNAR/capped_at_5_GiB368=== CONT TestPartSizeForNAR/5_TiB_S3_max_object369=== CONT TestPartSizeForNAR/1_TiB370=== CONT TestPartSizeForNAR/small_stays_at_minimum371=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum372--- PASS: TestPartSizeForNAR (0.00s)373 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)374 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)375 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)376 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)377 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)378 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)379 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)380=== CONT TestFilterOversizedClosures/no_limit_keeps_everything381=== CONT TestFilterOversizedClosures/all_closures_skipped3822026/10/04 20:06:39 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=50383=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3842026/10/04 20:06:39 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=2000385--- PASS: TestFilterOversizedClosures (0.00s)386 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)387 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)388 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)389=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths390=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths391--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)392 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)393 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)3942026/10/04 20:06:39 http: TLS handshake error from 127.0.0.1:50692: remote error: tls: bad certificate395--- PASS: TestSetClientTLS (0.01s)396 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)397 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)398 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)399--- PASS: TestDumpPathSingleFile (0.05s)400--- PASS: TestCaseHackSuffix (0.04s)401--- PASS: TestDumpPathMatchesNix (0.07s)402--- PASS: TestStreamPushBatchesUnderLoad (0.10s)403--- PASS: TestUploadMultipart_PartsInParallel (0.61s)404--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)405PASS406Running server tests...407The files belonging to this database system will be owned by user "_nixbld1".408This user must also own the server process.409410The database cluster will be initialized with locale "C".411The default database encoding has accordingly been set to "SQL_ASCII".412The default text search configuration will be set to "english".413414Data page checksums are enabled.415416creating directory /nix/var/nix/builds/nix-13370-2378689625/postgres4064857684/data ... ok417creating subdirectories ... ok418selecting dynamic shared memory implementation ... posix419selecting default "max_connections" ... 100420selecting default "shared_buffers" ... 128MB421selecting default time zone ... UTC422creating configuration files ... ok423running bootstrap script ... ok424performing post-bootstrap initialization ... ok425syncing data to disk ... ok426427initdb: warning: enabling "trust" authentication for local connections428initdb: 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.429430Success. You can now start the database server using:431432 pg_ctl -D /nix/var/nix/builds/nix-13370-2378689625/postgres4064857684/data -l logfile start433434/nix/var/nix/builds/nix-13370-2378689625/postgres4064857684:5432 - no response4352026-10-04 20:06:40.970 UTC [13441] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4362026-10-04 20:06:40.970 UTC [13441] LOG: listening on Unix socket "/nix/var/nix/builds/nix-13370-2378689625/postgres4064857684/.s.PGSQL.5432"4372026-10-04 20:06:40.972 UTC [13448] LOG: database system was shut down at 2026-10-04 20:06:40 UTC4382026-10-04 20:06:40.973 UTC [13441] LOG: database system is ready to accept connections439/nix/var/nix/builds/nix-13370-2378689625/postgres4064857684:5432 - accepting connections440{"timestamp":"2026-10-04T20:06:41.187963Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"9a9328ce-3435-4a8f-814d-377efcff3fa9","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(9)"}441=== RUN TestService_AuthMiddleware442=== PAUSE TestService_AuthMiddleware443=== RUN TestService_AuthMiddleware_MTLSProxyHeader444=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader445=== RUN TestService_AuthMiddleware_MTLSBoundSubjects446=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects447=== RUN TestService_ReadAuthMiddleware448=== PAUSE TestService_ReadAuthMiddleware449=== RUN TestService_AuthMiddleware_OIDC450=== PAUSE TestService_AuthMiddleware_OIDC451=== RUN TestService_RequireScope_OIDC452=== PAUSE TestService_RequireScope_OIDC453=== RUN TestService_ReadScope_PublicByDefault454=== PAUSE TestService_ReadScope_PublicByDefault455=== RUN TestCacheConfigHandler456=== PAUSE TestCacheConfigHandler457=== RUN TestCacheStatsHandler458=== PAUSE TestCacheStatsHandler459=== RUN TestClientCADerivations460=== PAUSE TestClientCADerivations461=== RUN TestClientErrorHandling462=== PAUSE TestClientErrorHandling463=== RUN TestClientIntegration464=== PAUSE TestClientIntegration465=== RUN TestClientMultipleUploads466=== PAUSE TestClientMultipleUploads467=== RUN TestClientWithDependencies468=== PAUSE TestClientWithDependencies469=== RUN TestClientSharedPathCommittedMidPush470=== PAUSE TestClientSharedPathCommittedMidPush471=== RUN TestPinProtectsFromGC472=== PAUSE TestPinProtectsFromGC473=== RUN TestClientPushesUseOnePush474=== PAUSE TestClientPushesUseOnePush475=== RUN TestClientFallsBackToClosures476=== PAUSE TestClientFallsBackToClosures477=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock478=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock479=== RUN TestResolveDBConnectionString480=== PAUSE TestResolveDBConnectionString481=== RUN TestConnectWaitsForAPeerMigration482=== PAUSE TestConnectWaitsForAPeerMigration483=== RUN TestLeadElectsOneAndHandsOver484=== PAUSE TestLeadElectsOneAndHandsOver485=== RUN TestLeadIncumbentWinsAfterRestart4862026/10/04 20:06:41 INFO lead: acquired remote=192.0.2.1:12344872026/10/04 20:06:42 INFO lead: released remote=192.0.2.1:12344882026/10/04 20:06:42 INFO lead: acquired remote=192.0.2.1:12344892026/10/04 20:06:43 INFO lead: released remote=192.0.2.1:1234490--- PASS: TestLeadIncumbentWinsAfterRestart (2.40s)491=== RUN TestLeadEndsOnShutdown492=== PAUSE TestLeadEndsOnShutdown493=== RUN TestLeadEndsWhenItsConnectionHangs4942026/10/04 20:06:43 INFO lead: acquired remote=192.0.2.1:12344952026-10-04 20:06:45.250 UTC [13535] FATAL: terminating connection due to administrator command4962026/10/04 20:06:45 INFO lead: acquired remote=192.0.2.1:12344972026/10/04 20:06:46 WARN lead: lock connection lost error="timeout: context deadline exceeded"4982026/10/04 20:06:46 INFO lead: released remote=192.0.2.1:12344992026/10/04 20:06:46 INFO lead: released remote=192.0.2.1:1234500--- PASS: TestLeadEndsWhenItsConnectionHangs (2.96s)501=== RUN TestGCAdvisoryLockBlocksConcurrentRun502=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun503=== RUN TestGCBugBareHashReferences504=== PAUSE TestGCBugBareHashReferences505=== RUN TestGCMetrics506=== PAUSE TestGCMetrics507=== RUN TestPushDedupSurvivesConcurrentGC508=== PAUSE TestPushDedupSurvivesConcurrentGC509=== RUN TestDeduplicatedObjectsRecordedAsPending510=== PAUSE TestDeduplicatedObjectsRecordedAsPending511=== RUN TestGCSweepSkipsPendingObjects512=== PAUSE TestGCSweepSkipsPendingObjects513=== RUN TestTombstonedObjectOfferedWithoutWaiting514=== PAUSE TestTombstonedObjectOfferedWithoutWaiting515=== RUN TestGCSweepDeliversEachKeyOnce516=== PAUSE TestGCSweepDeliversEachKeyOnce517=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection518=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection519=== RUN TestForceGCDuringPushOffersSweptObject520=== PAUSE TestForceGCDuringPushOffersSweptObject521=== RUN TestFailedS3DeleteKeepsTombstone522=== PAUSE TestFailedS3DeleteKeepsTombstone523=== RUN TestSweepSkipsRowsLockedByPush524=== PAUSE TestSweepSkipsRowsLockedByPush525=== RUN TestRegisterCompletedObjectNeedsPendingRow526=== PAUSE TestRegisterCompletedObjectNeedsPendingRow527=== RUN TestGetExistingObjectsLocksRows528=== PAUSE TestGetExistingObjectsLocksRows529=== RUN TestSweepRechecksPendingAfterLocking530=== PAUSE TestSweepRechecksPendingAfterLocking531=== RUN TestPushWaitsForSweepHoldingRow532=== PAUSE TestPushWaitsForSweepHoldingRow533=== RUN TestCommitRacingPendingCleanupKeepsObjects534=== PAUSE TestCommitRacingPendingCleanupKeepsObjects535=== RUN TestGCEndsOnShutdown536=== PAUSE TestGCEndsOnShutdown537=== RUN TestGCTaskStore_StartNew538=== PAUSE TestGCTaskStore_StartNew539=== RUN TestGCTaskStore_DeduplicateSameParams540=== PAUSE TestGCTaskStore_DeduplicateSameParams541=== RUN TestGCTaskStore_ConflictDifferentParams542=== PAUSE TestGCTaskStore_ConflictDifferentParams543=== RUN TestGCTaskStore_GetEmpty544=== PAUSE TestGCTaskStore_GetEmpty545=== RUN TestGCTaskStore_GetReturnsLatest546=== PAUSE TestGCTaskStore_GetReturnsLatest547=== RUN TestGCTaskStore_CompletedAllowsNewTask548=== PAUSE TestGCTaskStore_CompletedAllowsNewTask549=== RUN TestGCTaskStore_PhaseUpdates550=== PAUSE TestGCTaskStore_PhaseUpdates551=== RUN TestGCTaskStore_Fail552=== PAUSE TestGCTaskStore_Fail553=== RUN TestGracefulShutdownDrainsInflight554=== PAUSE TestGracefulShutdownDrainsInflight555=== RUN TestService_healthCheckHandler556=== PAUSE TestService_healthCheckHandler557=== RUN TestService_readinessHandler558=== PAUSE TestService_readinessHandler559=== RUN TestGenerateLandingPage560=== PAUSE TestGenerateLandingPage561=== RUN TestCacheConfigHandlerMaxNarSize562=== PAUSE TestCacheConfigHandlerMaxNarSize563=== RUN TestCreatePendingClosureRejectsOversizedNAR564=== PAUSE TestCreatePendingClosureRejectsOversizedNAR565=== RUN TestNARDeduplicationMetadataUploadBug566=== PAUSE TestNARDeduplicationMetadataUploadBug567=== RUN TestMetricsInventory568=== PAUSE TestMetricsInventory569=== RUN TestService_NativeMTLS570=== PAUSE TestService_NativeMTLS571=== RUN TestServerTLSConfig572=== PAUSE TestServerTLSConfig573=== RUN TestMultipartCleanup574=== PAUSE TestMultipartCleanup575=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded576=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded577=== RUN TestPendingCleanupUsesOneCutoff578=== PAUSE TestPendingCleanupUsesOneCutoff579=== RUN TestObjectStatsTrigger580=== PAUSE TestObjectStatsTrigger581=== RUN TestOrphanedObjectsGC582=== PAUSE TestOrphanedObjectsGC583=== RUN TestOrphanedObjectsGCStressTest584=== PAUSE TestOrphanedObjectsGCStressTest585=== RUN TestCreatePin_ReservedPins586=== PAUSE TestCreatePin_ReservedPins587=== RUN TestPresentReportsOnlyClosureRoots588=== PAUSE TestPresentReportsOnlyClosureRoots589=== RUN TestPresentNotReportedWhileGCDeletesClosure590=== PAUSE TestPresentNotReportedWhileGCDeletesClosure591=== RUN TestParseSingleRange592=== PAUSE TestParseSingleRange593=== RUN TestProxyHeadersOnlyTrustedOnSocket594=== PAUSE TestProxyHeadersOnlyTrustedOnSocket595=== RUN TestIsValidCachePath596=== PAUSE TestIsValidCachePath597=== RUN TestReadProxyNarinfo598=== PAUSE TestReadProxyNarinfo599=== RUN TestReadProxyNarinfoAlreadyDecompressed600=== PAUSE TestReadProxyNarinfoAlreadyDecompressed601=== RUN TestReadProxyNarStreaming602=== PAUSE TestReadProxyNarStreaming603=== RUN TestReadProxy404604=== PAUSE TestReadProxy404605=== RUN TestReadProxyInvalidPath606=== PAUSE TestReadProxyInvalidPath607=== RUN TestReadProxyHead608=== PAUSE TestReadProxyHead609=== RUN TestReadProxyOutlastsServerWriteTimeout610=== PAUSE TestReadProxyOutlastsServerWriteTimeout611=== RUN TestReadProxyConditionalGet612=== PAUSE TestReadProxyConditionalGet613=== RUN TestReadProxyRootRedirectsToIndexHTML614=== PAUSE TestReadProxyRootRedirectsToIndexHTML615=== RUN TestReadProxyDisabled616=== PAUSE TestReadProxyDisabled617=== RUN TestReadRedirectNar618=== PAUSE TestReadRedirectNar619=== RUN TestReadRedirectKeepsNarinfoProxied620=== PAUSE TestReadRedirectKeepsNarinfoProxied621=== RUN TestReadProxyRangeRequest622=== PAUSE TestReadProxyRangeRequest623=== RUN TestReadRedirectUsesPublicS3URL624=== PAUSE TestReadRedirectUsesPublicS3URL625=== RUN TestPush_OverlappingRootsStoreOneRowPerKey626=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey627=== RUN TestPush_CompleteCommitsEveryRoot628=== PAUSE TestPush_CompleteCommitsEveryRoot629=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit630=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit631=== RUN TestPush_RejectsBadRequests632=== PAUSE TestPush_RejectsBadRequests633=== RUN TestPush_SignsNarinfosOfItsPendingObjects634=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects635=== RUN TestRedundantMultipartUpload636=== PAUSE TestRedundantMultipartUpload637=== RUN TestCompleteMultipartUpload_ErrorButObjectExists638=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists639=== RUN TestCompletedNarNotReofferedAcrossClosures640=== PAUSE TestCompletedNarNotReofferedAcrossClosures641=== RUN TestPresignedUploadRegisteredBeforeCommit642=== PAUSE TestPresignedUploadRegisteredBeforeCommit643=== RUN TestService_Rustfstest644=== PAUSE TestService_Rustfstest645=== RUN TestParseSize646=== PAUSE TestParseSize647=== RUN TestSkippedUploadsHandler648=== PAUSE TestSkippedUploadsHandler649=== RUN TestSystemdListenerNotActivated650--- PASS: TestSystemdListenerNotActivated (0.00s)651=== RUN TestWatchdogBeatsWhenHealthy652--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)653=== RUN TestWatchdogSkipsWhenUnhealthy6542026/10/04 20:06:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6552026/10/04 20:06:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6562026/10/04 20:06:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6572026/10/04 20:06:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6582026/10/04 20:06:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6592026/10/04 20:06:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6602026/10/04 20:06:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6612026/10/04 20:06:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6622026/10/04 20:06:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"663--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)664=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle665=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle666=== RUN TestProxyWriteTimeout667=== PAUSE TestProxyWriteTimeout668=== RUN TestPendingClosureWriteTimeout669=== PAUSE TestPendingClosureWriteTimeout670=== RUN TestIsValidUploadKey671=== PAUSE TestIsValidUploadKey672=== RUN TestUploadHandlersRejectInvalidKeys673=== PAUSE TestUploadHandlersRejectInvalidKeys674=== RUN TestUploadHandlersRejectOversizedBody675=== PAUSE TestUploadHandlersRejectOversizedBody676=== RUN TestService_cleanupPendingClosuresHandler677=== PAUSE TestService_cleanupPendingClosuresHandler678=== RUN TestService_createPendingClosureHandler679=== PAUSE TestService_createPendingClosureHandler680=== RUN TestService_verifyS3Integrity681=== PAUSE TestService_verifyS3Integrity682=== RUN TestCompleteMultipartUnregistered683=== PAUSE TestCompleteMultipartUnregistered684=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT685=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT686=== CONT TestProxyWriteTimeout687=== CONT TestMultipartCleanup688=== RUN TestProxyWriteTimeout/narinfo689=== CONT TestGCSweepDeliversEachKeyOnce690=== CONT TestDeduplicatedObjectsRecordedAsPending691=== PAUSE TestProxyWriteTimeout/narinfo692=== RUN TestProxyWriteTimeout/1_GiB_nar693=== CONT TestReadProxyRootRedirectsToIndexHTML694=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT695=== CONT TestClientSharedPathCommittedMidPush696=== CONT TestService_AuthMiddleware697=== PAUSE TestProxyWriteTimeout/1_GiB_nar698=== CONT TestGCSweepSkipsPendingObjects699=== CONT TestTombstonedObjectOfferedWithoutWaiting700=== RUN TestProxyWriteTimeout/10_GiB_nar701=== PAUSE TestProxyWriteTimeout/10_GiB_nar702=== RUN TestProxyWriteTimeout/unknown_size703=== PAUSE TestProxyWriteTimeout/unknown_size704=== CONT TestService_cleanupPendingClosuresHandler7052026/10/04 20:06:47 INFO Aborted multipart uploads count=0 kept=07062026/10/04 20:06:47 WARN Force mode enabled - objects will be deleted immediately without grace period7072026/10/04 20:06:47 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=07082026/10/04 20:06:47 INFO Vacuumed table table=pending_closures7092026/10/04 20:06:47 INFO Vacuumed table table=pending_objects7102026/10/04 20:06:47 INFO Vacuumed table table=multipart_uploads7112026/10/04 20:06:47 INFO Vacuumed table table=closures7122026/10/04 20:06:47 INFO Vacuumed table table=objects713--- PASS: TestGCSweepDeliversEachKeyOnce (0.52s)714=== CONT TestCompleteMultipartUnregistered7152026/10/04 20:06:47 INFO Received uploads request method=POST path=/api/pending_closures7162026/10/04 20:06:47 INFO Aborted multipart uploads count=0 kept=07172026/10/04 20:06:47 WARN Force mode enabled - objects will be deleted immediately without grace period7182026/10/04 20:06:47 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=07192026/10/04 20:06:47 INFO Vacuumed table table=pending_closures7202026/10/04 20:06:47 INFO Vacuumed table table=pending_objects7212026/10/04 20:06:47 INFO Vacuumed table table=multipart_uploads7222026/10/04 20:06:47 INFO Vacuumed table table=closures7232026/10/04 20:06:47 INFO Vacuumed table table=objects724--- PASS: TestGCSweepSkipsPendingObjects (0.75s)725=== CONT TestService_verifyS3Integrity7262026/10/04 20:06:47 INFO Received uploads request method=POST path=/api/pending_closures727--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.82s)728=== CONT TestService_createPendingClosureHandler7292026/10/04 20:06:47 INFO Received uploads request method=POST path=/api/pending_closures730--- PASS: TestTombstonedObjectOfferedWithoutWaiting (1.08s)731=== CONT TestProxyHeadersOnlyTrustedOnSocket7322026/10/04 20:06:48 INFO Received uploads request method=POST path=/api/pending_closures7332026/10/04 20:06:48 INFO Received cleanup request method=DELETE path=/api/pending_closures7342026/10/04 20:06:48 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket7/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""7352026/10/04 20:06:48 INFO Aborted multipart uploads count=0 kept=17362026/10/04 20:06:48 INFO Received cleanup request method=DELETE path=/api/pending_closures7372026/10/04 20:06:48 INFO Aborted multipart uploads count=1 kept=0738--- PASS: TestMultipartCleanup (1.42s)739=== CONT TestReadProxyConditionalGet7402026/10/04 20:06:48 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"741--- PASS: TestService_AuthMiddleware (1.46s)742=== CONT TestReadProxyOutlastsServerWriteTimeout7432026/10/04 20:06:48 INFO Received uploads request method=POST path=/api/pending_closures744--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (2.01s)745=== CONT TestReadProxyHead7462026/10/04 20:06:49 INFO Received push request method=POST path=/api/pushes7472026/10/04 20:06:49 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)7482026/10/04 20:06:49 INFO Uploading frsq9qsj07yqgbp19dbplh7x4453xn50-shared-dep (136B)7492026/10/04 20:06:49 INFO Uploading 4mbxd4kyjirn64zx0lisz1nfbcj3k0ip-top (256B)7502026/10/04 20:06:49 WARN Failed to register uploaded object key=4mbxd4kyjirn64zx0lisz1nfbcj3k0ip.ls error="server returned 404: 404 page not found\n"751--- PASS: TestReadProxyRootRedirectsToIndexHTML (2.20s)752=== CONT TestReadProxyInvalidPath7532026/10/04 20:06:49 WARN Failed to register uploaded object key=frsq9qsj07yqgbp19dbplh7x4453xn50.ls error="server returned 404: 404 page not found\n"7542026/10/04 20:06:49 WARN Failed to register uploaded object key=nar/028yyrsmz1wl88ylk257lrjap2ddwj7pca7hmwms9ilv01ag25zp.nar.zst error="server returned 404: 404 page not found\n"7552026/10/04 20:06:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign7562026/10/04 20:06:49 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"7572026/10/04 20:06:49 INFO Signed narinfos id=1 count=27582026/10/04 20:06:49 INFO Uploading 2 narinfos7592026/10/04 20:06:49 WARN Failed to register uploaded object key=4mbxd4kyjirn64zx0lisz1nfbcj3k0ip.narinfo error="server returned 404: 404 page not found\n"7602026/10/04 20:06:49 INFO Received complete push request method=POST path=/api/pushes/1/complete7612026/10/04 20:06:49 WARN Failed to register uploaded object key=frsq9qsj07yqgbp19dbplh7x4453xn50.narinfo error="server returned 404: 404 page not found\n"7622026/10/04 20:06:49 INFO Upload complete. (199ms)763=== NAME TestClientSharedPathCommittedMidPush764 client_integration_test.go:680: Retrieved narinfo from S3:765 StorePath: /nix/var/nix/builds/nix-13370-2378689625/TestClientSharedPathCommittedMidPush1081435030/001/store/frsq9qsj07yqgbp19dbplh7x4453xn50-shared-dep766 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst767 Compression: zstd768 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82769 NarSize: 136770 References: 771 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n772 client_integration_test.go:680: Retrieved narinfo from S3:773 StorePath: /nix/var/nix/builds/nix-13370-2378689625/TestClientSharedPathCommittedMidPush1081435030/001/store/4mbxd4kyjirn64zx0lisz1nfbcj3k0ip-top774 URL: nar/028yyrsmz1wl88ylk257lrjap2ddwj7pca7hmwms9ilv01ag25zp.nar.zst775 Compression: zstd776 NarHash: sha256:028yyrsmz1wl88ylk257lrjap2ddwj7pca7hmwms9ilv01ag25zp777 NarSize: 256778 References: /nix/var/nix/builds/nix-13370-2378689625/TestClientSharedPathCommittedMidPush1081435030/001/store/frsq9qsj07yqgbp19dbplh7x4453xn50-shared-dep779 CA: text:sha256:0a9li7xi48dn2yzsbiy0144yi0kqi51kl4m135jzvhrc04327ync780--- PASS: TestClientSharedPathCommittedMidPush (2.34s)781=== CONT TestReadProxy4047822026/10/04 20:06:49 INFO Received cleanup request method=DELETE path=/api/pending_closures7832026/10/04 20:06:49 INFO Aborted multipart uploads count=0 kept=07842026/10/04 20:06:49 INFO Received uploads request method=POST path=/api/pending_closures7852026/10/04 20:06:49 INFO Received cleanup request method=DELETE path=/api/pending_closures7862026/10/04 20:06:49 INFO Aborted multipart uploads count=1 kept=07872026/10/04 20:06:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7882026-10-04 20:06:49.455 UTC [13570] ERROR: Closure does not exist: id=17892026-10-04 20:06:49.455 UTC [13570] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE7902026-10-04 20:06:49.455 UTC [13570] STATEMENT: -- name: CommitPendingClosure :exec791 SELECT commit_pending_closure($1::bigint)792 793--- PASS: TestService_cleanupPendingClosuresHandler (2.57s)794=== CONT TestReadProxyNarStreaming7952026/10/04 20:06:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7962026/10/04 20:06:49 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst797--- PASS: TestCompleteMultipartUnregistered (2.19s)798=== CONT TestReadProxyNarinfoAlreadyDecompressed7992026/10/04 20:06:49 INFO Received uploads request method=POST path=/api/pending_closures8002026/10/04 20:06:50 INFO Received uploads request method=POST path=/api/pending_closures8012026/10/04 20:06:50 INFO Received uploads request method=POST path=/api/pending_closures8022026/10/04 20:06:50 INFO Received uploads request method=POST path=/api/pending_closures8032026/10/04 20:06:50 INFO Starting HTTP server address=/nix/var/nix/builds/nix-13370-2378689625/TestProxyHeadersOnlyTrustedOnSocket3092487188/001/proxy.sock8042026/10/04 20:06:50 INFO Starting HTTP server address=127.0.0.1:508928052026/10/04 20:06:50 WARN mTLS auth: subject not in bound subjects subject="CN=someone"8062026/10/04 20:06:50 INFO Shutdown signal received, draining in-flight requests timeout=10s807--- PASS: TestProxyHeadersOnlyTrustedOnSocket (2.73s)808=== CONT TestReadProxyNarinfo8092026/10/04 20:06:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8102026/10/04 20:06:51 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MjI1NTI1OWEtYTE5Mi00MmJlLWI0NzEtN2Y4NmJhZGVlN2Q3LmViNGVlYzA4LWJlZTUtNDk3Yi05ZjQwLWQ5ZDlmNTRiYjMwM3gxNzkxMTQ0NDA5ODk2NTcxMDAw parts=108112026/10/04 20:06:51 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8122026/10/04 20:06:51 INFO Completed upload id=18132026/10/04 20:06:51 INFO Received uploads request method=POST path=/api/pending_closures8142026/10/04 20:06:51 INFO Received uploads request method=POST path=/api/pending_closures8152026/10/04 20:06:51 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo8162026/10/04 20:06:51 WARN Found objects in DB but missing from S3, will re-upload count=1817--- PASS: TestService_verifyS3Integrity (4.28s)818=== CONT TestIsValidCachePath819=== RUN TestIsValidCachePath/narinfo820=== PAUSE TestIsValidCachePath/narinfo821=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars822=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars823=== RUN TestIsValidCachePath/nar_zst824=== PAUSE TestIsValidCachePath/nar_zst825=== RUN TestIsValidCachePath/nar_xz826=== PAUSE TestIsValidCachePath/nar_xz827=== RUN TestIsValidCachePath/nar_bz2828=== PAUSE TestIsValidCachePath/nar_bz2829=== RUN TestIsValidCachePath/nar_uncompressed830=== PAUSE TestIsValidCachePath/nar_uncompressed831=== RUN TestIsValidCachePath/ls832=== PAUSE TestIsValidCachePath/ls833=== RUN TestIsValidCachePath/log834=== PAUSE TestIsValidCachePath/log835=== RUN TestIsValidCachePath/realisation836=== PAUSE TestIsValidCachePath/realisation837=== RUN TestIsValidCachePath/nix-cache-info838=== PAUSE TestIsValidCachePath/nix-cache-info839=== RUN TestIsValidCachePath/index.html840=== PAUSE TestIsValidCachePath/index.html841=== RUN TestIsValidCachePath/traversal_parent842=== PAUSE TestIsValidCachePath/traversal_parent843=== RUN TestIsValidCachePath/traversal_in_middle844=== PAUSE TestIsValidCachePath/traversal_in_middle845=== RUN TestIsValidCachePath/invalid_char_e846=== PAUSE TestIsValidCachePath/invalid_char_e847=== RUN TestIsValidCachePath/invalid_char_u848=== PAUSE TestIsValidCachePath/invalid_char_u849=== RUN TestIsValidCachePath/random_path850=== PAUSE TestIsValidCachePath/random_path851=== RUN TestIsValidCachePath/empty852=== PAUSE TestIsValidCachePath/empty853=== RUN TestIsValidCachePath/leading_slash854=== PAUSE TestIsValidCachePath/leading_slash855=== RUN TestIsValidCachePath/wrong_extension856=== PAUSE TestIsValidCachePath/wrong_extension857=== RUN TestIsValidCachePath/short_hash858=== PAUSE TestIsValidCachePath/short_hash859=== CONT TestGCTaskStore_GetReturnsLatest860--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)861=== CONT TestServerTLSConfig862=== RUN TestServerTLSConfig/no_client_CA863=== PAUSE TestServerTLSConfig/no_client_CA864=== RUN TestServerTLSConfig/missing_CA_file865=== PAUSE TestServerTLSConfig/missing_CA_file866=== RUN TestServerTLSConfig/not_a_PEM_file867=== PAUSE TestServerTLSConfig/not_a_PEM_file868=== CONT TestService_NativeMTLS8692026/10/04 20:06:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8702026/10/04 20:06:52 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MjI1NTI1OWEtYTE5Mi00MmJlLWI0NzEtN2Y4NmJhZGVlN2Q3LmZhNzY5MTgwLTYyNzQtNGIyOS1iYWU0LTE5YzUwNDEzY2ZiZngxNzkxMTQ0NDEwMjYwNzg0MDAw parts=108712026/10/04 20:06:52 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8722026/10/04 20:06:52 INFO Completed upload id=18732026/10/04 20:06:52 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000008742026/10/04 20:06:52 INFO Received uploads request method=POST path=/api/pending_closures8752026/10/04 20:06:52 INFO Starting cleanup of old closures method=DELETE path=/api/closures8762026/10/04 20:06:52 INFO Aborted multipart uploads count=0 kept=08772026/10/04 20:06:52 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=08782026/10/04 20:06:52 INFO Vacuumed table table=pending_closures8792026/10/04 20:06:52 INFO Vacuumed table table=pending_objects8802026/10/04 20:06:52 INFO Vacuumed table table=multipart_uploads8812026/10/04 20:06:52 INFO Vacuumed table table=closures8822026/10/04 20:06:52 INFO Vacuumed table table=objects8832026/10/04 20:06:52 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000884--- PASS: TestService_createPendingClosureHandler (4.79s)885=== CONT TestMetricsInventory886--- PASS: TestReadProxyConditionalGet (4.24s)887=== CONT TestNARDeduplicationMetadataUploadBug888--- PASS: TestReadProxyHead (4.04s)889=== CONT TestCreatePendingClosureRejectsOversizedNAR8902026/10/04 20:06:52 INFO Received uploads request method=POST path=/api/pending_closures891--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)892=== CONT TestCacheConfigHandlerMaxNarSize893--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)894=== CONT TestGenerateLandingPage895--- PASS: TestGenerateLandingPage (0.01s)896=== CONT TestService_readinessHandler897--- PASS: TestReadProxyInvalidPath (4.29s)898=== CONT TestService_healthCheckHandler899--- PASS: TestReadProxy404 (4.70s)900=== CONT TestGracefulShutdownDrainsInflight9012026/10/04 20:06:53 INFO Starting HTTP server address=127.0.0.1:509549022026/10/04 20:06:53 INFO Shutdown signal received, draining in-flight requests timeout=10s903--- PASS: TestGracefulShutdownDrainsInflight (0.07s)904=== CONT TestGCTaskStore_Fail905--- PASS: TestGCTaskStore_Fail (0.00s)906=== CONT TestGCTaskStore_PhaseUpdates907--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)908=== CONT TestGCTaskStore_CompletedAllowsNewTask909--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)910=== CONT TestUploadHandlersRejectInvalidKeys911=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info912=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info913=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal914=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal915=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key916=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key917=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key918=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key919=== CONT TestUploadHandlersRejectOversizedBody920=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure921=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure922=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart923=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart924=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts925=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts926=== CONT TestClientWithDependencies927--- PASS: TestReadProxyNarStreaming (4.71s)928=== CONT TestLeadElectsOneAndHandsOver929--- PASS: TestReadProxyNarinfoAlreadyDecompressed (4.91s)930=== CONT TestPushDedupSurvivesConcurrentGC9312026/10/04 20:06:55 ERROR Failed to decompress narinfo error="decompressed size exceeds configured limit"9322026/10/04 20:06:55 ERROR Refusing narinfo larger than the limit key=5hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216933--- PASS: TestReadProxyNarinfo (5.15s)934=== CONT TestGCMetrics935--- PASS: TestReadProxyOutlastsServerWriteTimeout (7.95s)936=== CONT TestGCBugBareHashReferences9372026/10/04 20:06:57 WARN mTLS auth: subject not in bound subjects subject="CN=reader"9382026/10/04 20:06:57 WARN mTLS auth: subject not in bound subjects subject="CN=reader"939--- PASS: TestService_NativeMTLS (5.27s)940=== CONT TestGCAdvisoryLockBlocksConcurrentRun941--- PASS: TestMetricsInventory (5.34s)942=== CONT TestLeadEndsOnShutdown9432026/10/04 20:06:58 WARN readiness check failed error="closed pool"944--- PASS: TestService_readinessHandler (5.80s)945=== CONT TestIsValidUploadKey946=== RUN TestIsValidUploadKey/narinfo947=== PAUSE TestIsValidUploadKey/narinfo948=== RUN TestIsValidUploadKey/nar_zst949=== PAUSE TestIsValidUploadKey/nar_zst950=== RUN TestIsValidUploadKey/nar_xz951=== PAUSE TestIsValidUploadKey/nar_xz952=== RUN TestIsValidUploadKey/nar_plain953=== PAUSE TestIsValidUploadKey/nar_plain954=== RUN TestIsValidUploadKey/listing955=== PAUSE TestIsValidUploadKey/listing956=== RUN TestIsValidUploadKey/build_log957=== PAUSE TestIsValidUploadKey/build_log958=== RUN TestIsValidUploadKey/build_log_home-manager_file959=== PAUSE TestIsValidUploadKey/build_log_home-manager_file960=== RUN TestIsValidUploadKey/build_log_plus_in_name961=== PAUSE TestIsValidUploadKey/build_log_plus_in_name962=== RUN TestIsValidUploadKey/build_log_question_mark963=== PAUSE TestIsValidUploadKey/build_log_question_mark964=== RUN TestIsValidUploadKey/build_log_equals965=== PAUSE TestIsValidUploadKey/build_log_equals966=== RUN TestIsValidUploadKey/realisation967=== PAUSE TestIsValidUploadKey/realisation968=== RUN TestIsValidUploadKey/realisation_plus_in_output969=== PAUSE TestIsValidUploadKey/realisation_plus_in_output970=== RUN TestIsValidUploadKey/nix-cache-info971=== PAUSE TestIsValidUploadKey/nix-cache-info972=== RUN TestIsValidUploadKey/index.html973=== PAUSE TestIsValidUploadKey/index.html974=== RUN TestIsValidUploadKey/narinfo_key,_nar_type975=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type976=== RUN TestIsValidUploadKey/nar_key,_narinfo_type977=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type978=== RUN TestIsValidUploadKey/listing_key,_narinfo_type979=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type980=== RUN TestIsValidUploadKey/traversal981=== PAUSE TestIsValidUploadKey/traversal982=== RUN TestIsValidUploadKey/traversal_nar983=== PAUSE TestIsValidUploadKey/traversal_nar984=== RUN TestIsValidUploadKey/absolute985=== PAUSE TestIsValidUploadKey/absolute986=== RUN TestIsValidUploadKey/empty_key987=== PAUSE TestIsValidUploadKey/empty_key988=== RUN TestIsValidUploadKey/unknown_type989=== PAUSE TestIsValidUploadKey/unknown_type990=== CONT TestPendingClosureWriteTimeout991=== RUN TestPendingClosureWriteTimeout/empty992=== PAUSE TestPendingClosureWriteTimeout/empty993=== RUN TestPendingClosureWriteTimeout/400_objects994=== PAUSE TestPendingClosureWriteTimeout/400_objects995=== RUN TestPendingClosureWriteTimeout/670k_objects996=== PAUSE TestPendingClosureWriteTimeout/670k_objects997=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline998=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline999=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1000=== NAME TestNARDeduplicationMetadataUploadBug1001 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-13370-2378689625/TestNARDeduplicationMetadataUploadBug2436864689/001/store/r6wyjsxj30771c0rw0aq41hv49wwb820-file1.txt10022026/10/04 20:06:58 INFO Received push request method=POST path=/api/pushes10032026/10/04 20:06:58 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10042026/10/04 20:06:58 INFO Uploading r6wyjsxj30771c0rw0aq41hv49wwb820-file1.txt (160B)10052026/10/04 20:06:59 WARN Failed to register uploaded object key=r6wyjsxj30771c0rw0aq41hv49wwb820.ls error="server returned 404: 404 page not found\n"10062026/10/04 20:06:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10072026/10/04 20:06:59 INFO Signed narinfos id=1 count=110082026/10/04 20:06:59 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"10092026/10/04 20:06:59 INFO Uploading 1 narinfos10102026/10/04 20:06:59 INFO Received complete push request method=POST path=/api/pushes/1/complete10112026/10/04 20:06:59 WARN Failed to register uploaded object key=r6wyjsxj30771c0rw0aq41hv49wwb820.narinfo error="server returned 404: 404 page not found\n"10122026/10/04 20:06:59 INFO Upload complete. (261ms)1013 metadata_upload_test.go:54: Retrieved narinfo from S3:1014 StorePath: /nix/var/nix/builds/nix-13370-2378689625/TestNARDeduplicationMetadataUploadBug2436864689/001/store/r6wyjsxj30771c0rw0aq41hv49wwb820-file1.txt1015 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1016 Compression: zstd1017 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1018 NarSize: 1601019 References: 1020 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1021 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1022 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1023 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1024--- PASS: TestService_healthCheckHandler (5.95s)1025=== CONT TestConnectWaitsForAPeerMigration1026=== NAME TestNARDeduplicationMetadataUploadBug1027 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-13370-2378689625/TestNARDeduplicationMetadataUploadBug2436864689/001/store/q203bhm15nks2b5sfbsz91mdvnjc6wxl-file2.txt10282026/10/04 20:06:59 INFO Received push request method=POST path=/api/pushes10292026/10/04 20:06:59 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)10302026/10/04 20:06:59 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign10312026/10/04 20:06:59 INFO Signed narinfos id=2 count=110322026/10/04 20:06:59 WARN Failed to register uploaded object key=q203bhm15nks2b5sfbsz91mdvnjc6wxl.ls error="server returned 404: 404 page not found\n"10332026/10/04 20:06:59 INFO Uploading 1 narinfos10342026/10/04 20:06:59 INFO Received complete push request method=POST path=/api/pushes/2/complete10352026/10/04 20:06:59 WARN Failed to register uploaded object key=q203bhm15nks2b5sfbsz91mdvnjc6wxl.narinfo error="server returned 404: 404 page not found\n"10362026/10/04 20:06:59 INFO Upload complete. (102ms)1037 metadata_upload_test.go:76: Retrieved narinfo from S3:1038 StorePath: /nix/var/nix/builds/nix-13370-2378689625/TestNARDeduplicationMetadataUploadBug2436864689/001/store/q203bhm15nks2b5sfbsz91mdvnjc6wxl-file2.txt1039 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1040 Compression: zstd1041 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1042 NarSize: 1601043 References: 1044 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1045 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1046 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1047 {"version":1,"root":{"type":"regular","size":44}}1048=== CONT TestResolveDBConnectionString1049--- PASS: TestNARDeduplicationMetadataUploadBug (7.03s)1050=== RUN TestResolveDBConnectionString/flag_wins1051=== PAUSE TestResolveDBConnectionString/flag_wins1052=== RUN TestResolveDBConnectionString/file_when_flag_empty1053=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1054=== RUN TestResolveDBConnectionString/missing_file_is_an_error1055=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1056=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1057=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1058=== RUN TestResolveDBConnectionString/nothing_configured1059=== PAUSE TestResolveDBConnectionString/nothing_configured1060=== CONT TestPush_SignsNarinfosOfItsPendingObjects10612026/10/04 20:07:00 INFO lead: acquired remote=192.0.2.1:12341062=== NAME TestClientWithDependencies1063 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-13370-2378689625/TestClientWithDependencies3039998348/001/store/n2yb6kg8b8wjms7bkff3xyqjq260g842-test-script1064 client_integration_test.go:615: Found 1 dependencies (including self)10652026/10/04 20:07:00 INFO Received push request method=POST path=/api/pushes10662026/10/04 20:07:00 INFO Received uploads request method=POST path=/api/pending_closures10672026/10/04 20:07:00 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10682026/10/04 20:07:00 INFO Uploading n2yb6kg8b8wjms7bkff3xyqjq260g842-test-script (136B)10692026/10/04 20:07:00 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"10702026/10/04 20:07:00 WARN Failed to register uploaded object key=n2yb6kg8b8wjms7bkff3xyqjq260g842.ls error="server returned 404: 404 page not found\n"10712026/10/04 20:07:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10722026/10/04 20:07:00 WARN Failed to register uploaded object key=log/h5wjb3af1pbbaqfc80560bqixly57jwy-test-script.drv error="server returned 404: 404 page not found\n"10732026/10/04 20:07:00 INFO Signed narinfos id=1 count=110742026/10/04 20:07:00 INFO Uploading 1 narinfos10752026/10/04 20:07:00 INFO Received complete push request method=POST path=/api/pushes/1/complete10762026/10/04 20:07:00 WARN Failed to register uploaded object key=n2yb6kg8b8wjms7bkff3xyqjq260g842.narinfo error="server returned 404: 404 page not found\n"10772026/10/04 20:07:00 INFO Aborted multipart uploads count=0 kept=010782026/10/04 20:07: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=010792026/10/04 20:07:00 INFO Upload complete. (254ms)1080 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-13370-2378689625/TestClientWithDependencies3039998348/001/store) requires matching store prefix10812026/10/04 20:07:00 INFO Vacuumed table table=pending_closures10822026/10/04 20:07:00 INFO Vacuumed table table=pending_objects10832026/10/04 20:07:00 INFO Vacuumed table table=multipart_uploads10842026/10/04 20:07:00 INFO Vacuumed table table=closures1085--- PASS: TestClientWithDependencies (6.94s)1086=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle10872026/10/04 20:07:00 INFO Vacuumed table table=objects10882026/10/04 20:07:01 INFO Aborted multipart uploads count=0 kept=010892026/10/04 20:07:01 WARN Force mode enabled - objects will be deleted immediately without grace period10902026/10/04 20:07:01 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=010912026/10/04 20:07:01 INFO Vacuumed table table=pending_closures10922026/10/04 20:07:01 INFO Aborted multipart uploads count=0 kept=010932026/10/04 20:07:01 INFO Vacuumed table table=pending_objects10942026/10/04 20:07:01 INFO Vacuumed table table=multipart_uploads10952026/10/04 20:07:01 WARN Force mode enabled - objects will be deleted immediately without grace period10962026/10/04 20:07:01 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=010972026/10/04 20:07:01 INFO Vacuumed table table=pending_closures10982026/10/04 20:07:01 INFO Vacuumed table table=pending_objects10992026/10/04 20:07:01 INFO Vacuumed table table=multipart_uploads11002026/10/04 20:07:01 INFO Vacuumed table table=closures11012026/10/04 20:07:01 INFO Vacuumed table table=objects1102--- PASS: TestGCMetrics (5.23s)1103=== CONT TestSkippedUploadsHandler11042026/10/04 20:07:01 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001105--- PASS: TestSkippedUploadsHandler (0.00s)1106=== CONT TestParseSize1107--- PASS: TestParseSize (0.00s)1108=== CONT TestService_Rustfstest11092026/10/04 20:07:01 INFO Vacuumed table table=closures11102026/10/04 20:07:01 INFO Vacuumed table table=objects1111--- PASS: TestPushDedupSurvivesConcurrentGC (6.61s)1112=== CONT TestGCTaskStore_GetEmpty1113--- PASS: TestGCTaskStore_GetEmpty (0.00s)1114=== CONT TestPresignedUploadRegisteredBeforeCommit11152026/10/04 20:07:01 INFO lead: released remote=192.0.2.1:123411162026/10/04 20:07:01 INFO lead: acquired remote=192.0.2.1:12341117--- PASS: TestGCBugBareHashReferences (5.47s)1118=== CONT TestGCTaskStore_ConflictDifferentParams1119--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1120=== CONT TestCompletedNarNotReofferedAcrossClosures11212026/10/04 20:07:02 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_nixbld1 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1122--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (5.03s)1123=== CONT TestGCTaskStore_DeduplicateSameParams1124--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1125=== CONT TestClientMultipleUploads11262026/10/04 20:07:02 INFO lead: released remote=192.0.2.1:12341127--- PASS: TestLeadElectsOneAndHandsOver (8.37s)1128=== CONT TestCompleteMultipartUpload_ErrorButObjectExists11292026/10/04 20:07:02 INFO lead: acquired remote=192.0.2.1:123411302026/10/04 20:07:03 INFO lead: released remote=192.0.2.1:12341131--- PASS: TestLeadEndsOnShutdown (5.83s)1132=== CONT TestGCTaskStore_StartNew1133--- PASS: TestGCTaskStore_StartNew (0.00s)1134=== CONT TestClientIntegration11352026/10/04 20:07:04 INFO Received push request method=POST path=/api/pushes11362026/10/04 20:07:04 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11372026/10/04 20:07:04 INFO Signed narinfos id=1 count=11138--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (4.62s)1139=== CONT TestRedundantMultipartUpload1140--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (6.11s)1141=== CONT TestGCEndsOnShutdown1142--- PASS: TestService_Rustfstest (3.95s)1143=== CONT TestCommitRacingPendingCleanupKeepsObjects11442026/10/04 20:07:05 INFO Received uploads request method=POST path=/api/pending_closures11452026/10/04 20:07:06 INFO Received uploads request method=POST path=/api/pending_closures11462026/10/04 20:07:06 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst11472026/10/04 20:07:06 INFO Received uploads request method=POST path=/api/pending_closures1148--- PASS: TestPresignedUploadRegisteredBeforeCommit (5.04s)1149=== CONT TestOrphanedObjectsGCStressTest11502026/10/04 20:07:06 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11512026/10/04 20:07:06 INFO Received uploads request method=POST path=/api/pending_closures11522026/10/04 20:07:07 INFO Received uploads request method=POST path=/api/pending_closures1153=== NAME TestClientMultipleUploads1154 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-13370-2378689625/TestClientMultipleUploads4162372489/001/store/q31ki0gyv23g98lk5nf9yaxg71rjh4i1-test-file-0.txt1155 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-13370-2378689625/TestClientMultipleUploads4162372489/001/store/j50khylx1xsgid22346p8ca0ggp6j1f8-test-file-1.txt11562026/10/04 20:07:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11572026/10/04 20:07:07 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MjI1NTI1OWEtYTE5Mi00MmJlLWI0NzEtN2Y4NmJhZGVlN2Q3LjZjZTVlZDhkLWJjMGQtNGIxMy05NDAyLWUzZWNjYzBhYjBiY3gxNzkxMTQ0NDI3Mzc3Mzk4MDAw11582026/10/04 20:07:07 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MjI1NTI1OWEtYTE5Mi00MmJlLWI0NzEtN2Y4NmJhZGVlN2Q3LjZjZTVlZDhkLWJjMGQtNGIxMy05NDAyLWUzZWNjYzBhYjBiY3gxNzkxMTQ0NDI3Mzc3Mzk4MDAw parts=11159--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (5.17s)1160=== CONT TestPushWaitsForSweepHoldingRow1161=== NAME TestClientMultipleUploads1162 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-13370-2378689625/TestClientMultipleUploads4162372489/001/store/ac67p8v0hg0ib2p4q53wp8k4amyb3l5s-test-file-2.txt11632026/10/04 20:07:07 INFO Received push request method=POST path=/api/pushes11642026/10/04 20:07:07 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)11652026/10/04 20:07:07 INFO Uploading q31ki0gyv23g98lk5nf9yaxg71rjh4i1-test-file-0.txt (160B)11662026/10/04 20:07:07 INFO Uploading ac67p8v0hg0ib2p4q53wp8k4amyb3l5s-test-file-2.txt (160B)11672026/10/04 20:07:07 INFO Uploading j50khylx1xsgid22346p8ca0ggp6j1f8-test-file-1.txt (160B)11682026/10/04 20:07:07 WARN Failed to register uploaded object key=j50khylx1xsgid22346p8ca0ggp6j1f8.ls error="server returned 404: 404 page not found\n"11692026/10/04 20:07:07 WARN Failed to register uploaded object key=q31ki0gyv23g98lk5nf9yaxg71rjh4i1.ls error="server returned 404: 404 page not found\n"11702026/10/04 20:07:07 WARN Failed to register uploaded object key=ac67p8v0hg0ib2p4q53wp8k4amyb3l5s.ls error="server returned 404: 404 page not found\n"11712026/10/04 20:07:07 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"11722026/10/04 20:07:07 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"11732026/10/04 20:07:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11742026/10/04 20:07:07 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"11752026/10/04 20:07:07 INFO Signed narinfos id=1 count=311762026/10/04 20:07:07 INFO Uploading 3 narinfos11772026/10/04 20:07:08 WARN Failed to register uploaded object key=q31ki0gyv23g98lk5nf9yaxg71rjh4i1.narinfo error="server returned 404: 404 page not found\n"11782026/10/04 20:07:08 WARN Failed to register uploaded object key=j50khylx1xsgid22346p8ca0ggp6j1f8.narinfo error="server returned 404: 404 page not found\n"11792026/10/04 20:07:08 INFO Received complete push request method=POST path=/api/pushes/1/complete11802026/10/04 20:07:08 WARN Failed to register uploaded object key=ac67p8v0hg0ib2p4q53wp8k4amyb3l5s.narinfo error="server returned 404: 404 page not found\n"11812026/10/04 20:07:08 INFO Upload complete. (256ms)1182 client_integration_test.go:369: Uploaded 3 paths in 293.444416ms1183--- PASS: TestClientMultipleUploads (6.02s)1184=== CONT TestParseSingleRange1185=== RUN TestParseSingleRange/none1186=== PAUSE TestParseSingleRange/none1187=== RUN TestParseSingleRange/unknown_unit1188=== PAUSE TestParseSingleRange/unknown_unit1189=== RUN TestParseSingleRange/multi-range_ignored1190=== PAUSE TestParseSingleRange/multi-range_ignored1191=== RUN TestParseSingleRange/malformed_no_dash1192=== PAUSE TestParseSingleRange/malformed_no_dash1193=== RUN TestParseSingleRange/malformed_both_empty1194=== PAUSE TestParseSingleRange/malformed_both_empty1195=== RUN TestParseSingleRange/malformed_end_before_start1196=== PAUSE TestParseSingleRange/malformed_end_before_start1197=== RUN TestParseSingleRange/closed1198=== PAUSE TestParseSingleRange/closed1199=== RUN TestParseSingleRange/open-ended1200=== PAUSE TestParseSingleRange/open-ended1201=== RUN TestParseSingleRange/end_clamped_to_size1202=== PAUSE TestParseSingleRange/end_clamped_to_size1203=== RUN TestParseSingleRange/suffix1204=== PAUSE TestParseSingleRange/suffix1205=== RUN TestParseSingleRange/suffix_exceeds_size1206=== PAUSE TestParseSingleRange/suffix_exceeds_size1207=== RUN TestParseSingleRange/single_byte1208=== PAUSE TestParseSingleRange/single_byte1209=== RUN TestParseSingleRange/start_past_EOF1210=== PAUSE TestParseSingleRange/start_past_EOF1211=== RUN TestParseSingleRange/start_far_past_EOF1212=== PAUSE TestParseSingleRange/start_far_past_EOF1213=== CONT TestSweepRechecksPendingAfterLocking1214--- PASS: TestConnectWaitsForAPeerMigration (9.10s)1215=== CONT TestPresentNotReportedWhileGCDeletesClosure12162026/10/04 20:07:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12172026/10/04 20:07:09 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MjI1NTI1OWEtYTE5Mi00MmJlLWI0NzEtN2Y4NmJhZGVlN2Q3LjRjMzgyMzk4LTA3NzQtNGQ5Ny1iNjEyLTQxMmZlZWFiNmVhOXgxNzkxMTQ0NDI2NTc0MzczMDAw parts=1212182026/10/04 20:07:09 INFO Received uploads request method=POST path=/api/pending_closures1219--- PASS: TestCompletedNarNotReofferedAcrossClosures (7.25s)1220=== CONT TestGetExistingObjectsLocksRows12212026/10/04 20:07:09 INFO Received uploads request method=POST path=/api/pending_closures1222=== NAME TestClientIntegration1223 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-13370-2378689625/TestClientIntegration3935917578/002/store/8p5jll7nqcpbl8b9mnyxwsjvi2ghg0jr-test-file.txt12242026/10/04 20:07:09 INFO Received uploads request method=POST path=/api/pending_closures12252026/10/04 20:07:09 INFO Received push request method=POST path=/api/pushes12262026/10/04 20:07:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12272026/10/04 20:07:09 INFO Uploading 8p5jll7nqcpbl8b9mnyxwsjvi2ghg0jr-test-file.txt (152B)12282026/10/04 20:07:09 WARN Failed to register uploaded object key=8p5jll7nqcpbl8b9mnyxwsjvi2ghg0jr.ls error="server returned 404: 404 page not found\n"12292026/10/04 20:07:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12302026/10/04 20:07:09 INFO Signed narinfos id=1 count=112312026/10/04 20:07:09 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"12322026/10/04 20:07:09 INFO Uploading 1 narinfos12332026/10/04 20:07:09 INFO Received complete push request method=POST path=/api/pushes/1/complete12342026/10/04 20:07:09 WARN Failed to register uploaded object key=8p5jll7nqcpbl8b9mnyxwsjvi2ghg0jr.narinfo error="server returned 404: 404 page not found\n"12352026/10/04 20:07:09 INFO Upload complete. (284ms)12362026/10/04 20:07:09 INFO All 1 paths already cached1237 client_integration_test.go:312: Retrieved narinfo from S3:1238 StorePath: /nix/var/nix/builds/nix-13370-2378689625/TestClientIntegration3935917578/002/store/8p5jll7nqcpbl8b9mnyxwsjvi2ghg0jr-test-file.txt1239 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1240 Compression: zstd1241 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11242 NarSize: 1521243 References: 1244 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11245 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1246 client_integration_test.go:313: Decompressed .ls content (64 bytes):1247 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1248 client_integration_test.go:316: Testing garbage collection...12492026/10/04 20:07:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures12502026/10/04 20:07:09 INFO Garbage collection started12512026/10/04 20:07:09 INFO Aborted multipart uploads count=0 kept=012522026/10/04 20:07:09 WARN Force mode enabled - objects will be deleted immediately without grace period12532026/10/04 20:07: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=012542026/10/04 20:07:09 INFO Vacuumed table table=pending_closures12552026/10/04 20:07:10 INFO Vacuumed table table=pending_objects12562026/10/04 20:07:10 INFO Vacuumed table table=multipart_uploads12572026/10/04 20:07:10 INFO Vacuumed table table=closures12582026/10/04 20:07:10 INFO Vacuumed table table=objects1259--- PASS: TestGCEndsOnShutdown (5.76s)1260=== CONT TestPresentReportsOnlyClosureRoots12612026/10/04 20:07:11 WARN Rate limiter enabled after throttle name=s3-test rate=512622026/10/04 20:07:11 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1263=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1264 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101265 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001266--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (10.10s)1267=== CONT TestCreatePin_ReservedPins12682026/10/04 20:07:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51180/oidc12692026/10/04 20:07:11 INFO Aborted multipart uploads count=0 kept=012702026/10/04 20:07:11 WARN Force mode enabled - objects will be deleted immediately without grace period12712026/10/04 20:07:11 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=012722026/10/04 20:07:11 INFO Vacuumed table table=pending_closures12732026/10/04 20:07:11 INFO Vacuumed table table=pending_objects12742026/10/04 20:07:11 INFO Vacuumed table table=multipart_uploads12752026/10/04 20:07:11 INFO Vacuumed table table=closures12762026/10/04 20:07:11 INFO Vacuumed table table=objects1277--- PASS: TestCommitRacingPendingCleanupKeepsObjects (6.60s)1278=== CONT TestClientPushesUseOnePush12792026/10/04 20:07:11 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01280=== NAME TestClientIntegration1281 client_integration_test.go:323: Objects in database after GC:1282 client_integration_test.go:323: Successfully deleted all objects with GC --force1283--- PASS: TestClientIntegration (8.23s)1284=== CONT TestClientFallsBackToClosures12852026/10/04 20:07:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12862026/10/04 20:07:12 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MjI1NTI1OWEtYTE5Mi00MmJlLWI0NzEtN2Y4NmJhZGVlN2Q3LmQ2YThhMWZiLWZmZTMtNGNmNC1hOGI0LTgxNzFkN2RhMTkyMHgxNzkxMTQ0NDI5MzM5NTQ3MDAw parts=1212872026/10/04 20:07:12 INFO Received uploads request method=POST path=/api/pending_closures12882026/10/04 20:07:12 INFO Received uploads request method=POST path=/api/pending_closures12892026/10/04 20:07:14 INFO Received uploads request method=POST path=/api/pending_closures1290--- PASS: TestPushWaitsForSweepHoldingRow (7.58s)1291=== CONT TestRegisterCompletedObjectNeedsPendingRow12922026/10/04 20:07:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12932026/10/04 20:07:15 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MjI1NTI1OWEtYTE5Mi00MmJlLWI0NzEtN2Y4NmJhZGVlN2Q3LjNiMjNlOWJmLWRlODEtNDUyZi1hZTcyLWVkNGFlODYxMzM5NngxNzkxMTQ0NDMyNTY2MDgyMDAw error="Get \"http://127.0.0.1:1/bucket46/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"12942026/10/04 20:07:15 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MjI1NTI1OWEtYTE5Mi00MmJlLWI0NzEtN2Y4NmJhZGVlN2Q3LjNlOTViMGZiLThmNTYtNDRiYi04YTM2LWY2YWJmZDZhNzEzOHgxNzkxMTQ0NDMyNDg3NzAzMDAw parts=1212952026/10/04 20:07:15 INFO Received cleanup request method=DELETE path=/api/pending_closures12962026/10/04 20:07:15 INFO Aborted multipart uploads count=1 kept=01297--- PASS: TestPresentNotReportedWhileGCDeletesClosure (7.49s)1298=== CONT TestObjectStatsTrigger1299--- PASS: TestRedundantMultipartUpload (11.71s)1300=== CONT TestSweepSkipsRowsLockedByPush13012026/10/04 20:07:16 INFO Aborted multipart uploads count=0 kept=013022026/10/04 20:07:16 WARN Force mode enabled - objects will be deleted immediately without grace period13032026/10/04 20:07:16 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=013042026/10/04 20:07:16 INFO Vacuumed table table=pending_closures13052026/10/04 20:07:16 INFO Vacuumed table table=pending_objects13062026/10/04 20:07:16 INFO Vacuumed table table=multipart_uploads13072026/10/04 20:07:16 INFO Vacuumed table table=closures13082026/10/04 20:07:16 INFO Vacuumed table table=objects1309--- PASS: TestSweepRechecksPendingAfterLocking (8.00s)1310=== CONT TestOrphanedObjectsGC1311--- PASS: TestGetExistingObjectsLocksRows (7.46s)1312=== CONT TestFailedS3DeleteKeepsTombstone1313--- PASS: TestPresentReportsOnlyClosureRoots (6.30s)1314=== CONT TestForceGCDuringPushOffersSweptObject1315=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1316=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1317=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1318=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1319=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection13202026/10/04 20:07:17 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13212026/10/04 20:07:17 WARN Refused reserved pin name=worker-x86_64-linux13222026/10/04 20:07:17 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13232026/10/04 20:07:17 INFO Received create pin request method=POST path=/api/pins/my-app13242026/10/04 20:07:17 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1325--- PASS: TestCreatePin_ReservedPins (6.21s)1326=== CONT TestReadRedirectUsesPublicS3URL13272026/10/04 20:07:18 INFO Received push request method=POST path=/api/pushes13282026/10/04 20:07:18 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13292026/10/04 20:07:18 INFO Uploading grg6iyv1zaai2iyb5hm5147ympj9f76b-shared-dep (136B)13302026/10/04 20:07:18 INFO Uploading wpzqsafciwcbpwq86fgl7f20fh8kzir4-a (248B)13312026/10/04 20:07:18 WARN Failed to register uploaded object key=grg6iyv1zaai2iyb5hm5147ympj9f76b.ls error="server returned 404: 404 page not found\n"13322026/10/04 20:07:18 WARN Failed to register uploaded object key=wpzqsafciwcbpwq86fgl7f20fh8kzir4.ls error="server returned 404: 404 page not found\n"13332026/10/04 20:07:18 WARN Failed to register uploaded object key=nar/1l87dxfka13rgyspqv64fix8q4rvxlbrk4yc960p20q0l3x8pqh6.nar.zst error="server returned 404: 404 page not found\n"13342026/10/04 20:07:18 WARN Failed to register uploaded object key=fgyidv7l43id98wmpw3xp8cpacpgd3fy.ls error="server returned 404: 404 page not found\n"13352026/10/04 20:07:18 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13362026/10/04 20:07:18 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13372026/10/04 20:07:18 INFO Signed narinfos id=1 count=313382026/10/04 20:07:18 INFO Uploading 3 narinfos13392026/10/04 20:07:18 WARN Failed to register uploaded object key=wpzqsafciwcbpwq86fgl7f20fh8kzir4.narinfo error="server returned 404: 404 page not found\n"13402026/10/04 20:07:18 WARN Failed to register uploaded object key=fgyidv7l43id98wmpw3xp8cpacpgd3fy.narinfo error="server returned 404: 404 page not found\n"13412026/10/04 20:07:18 INFO Received complete push request method=POST path=/api/pushes/1/complete13422026/10/04 20:07:18 WARN Failed to register uploaded object key=grg6iyv1zaai2iyb5hm5147ympj9f76b.narinfo error="server returned 404: 404 page not found\n"13432026/10/04 20:07:18 INFO Upload complete. (181ms)1344=== NAME TestClientPushesUseOnePush1345 client_pushes_test.go:97: Retrieved narinfo from S3:1346 StorePath: /nix/var/nix/builds/nix-13370-2378689625/TestClientPushesUseOnePush2605067422/001/store/grg6iyv1zaai2iyb5hm5147ympj9f76b-shared-dep1347 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1348 Compression: zstd1349 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821350 NarSize: 1361351 References: 1352 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1353 client_pushes_test.go:97: Retrieved narinfo from S3:1354 StorePath: /nix/var/nix/builds/nix-13370-2378689625/TestClientPushesUseOnePush2605067422/001/store/wpzqsafciwcbpwq86fgl7f20fh8kzir4-a1355 URL: nar/1l87dxfka13rgyspqv64fix8q4rvxlbrk4yc960p20q0l3x8pqh6.nar.zst1356 Compression: zstd1357 NarHash: sha256:1l87dxfka13rgyspqv64fix8q4rvxlbrk4yc960p20q0l3x8pqh61358 NarSize: 2481359 References: /nix/var/nix/builds/nix-13370-2378689625/TestClientPushesUseOnePush2605067422/001/store/grg6iyv1zaai2iyb5hm5147ympj9f76b-shared-dep1360 CA: text:sha256:0h00bs3xqx8l25xq14mg2mlklwn37z418jxmi48aviyf3bhjwhjj1361 client_pushes_test.go:97: Retrieved narinfo from S3:1362 StorePath: /nix/var/nix/builds/nix-13370-2378689625/TestClientPushesUseOnePush2605067422/001/store/fgyidv7l43id98wmpw3xp8cpacpgd3fy-b1363 URL: nar/1l87dxfka13rgyspqv64fix8q4rvxlbrk4yc960p20q0l3x8pqh6.nar.zst1364 Compression: zstd1365 NarHash: sha256:1l87dxfka13rgyspqv64fix8q4rvxlbrk4yc960p20q0l3x8pqh61366 NarSize: 2481367 References: /nix/var/nix/builds/nix-13370-2378689625/TestClientPushesUseOnePush2605067422/001/store/grg6iyv1zaai2iyb5hm5147ympj9f76b-shared-dep1368 CA: text:sha256:0h00bs3xqx8l25xq14mg2mlklwn37z418jxmi48aviyf3bhjwhjj1369--- PASS: TestClientPushesUseOnePush (7.02s)1370=== CONT TestPush_RejectsBadRequests13712026/10/04 20:07:18 INFO Received uploads request method=POST path=/api/pending_closures13722026/10/04 20:07:18 INFO Received uploads request method=POST path=/api/pending_closures13732026/10/04 20:07:18 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13742026/10/04 20:07:18 INFO Uploading sv9d82fm4vqvysvgwiw9a0i3hlz7mjip-b (248B)13752026/10/04 20:07:18 INFO Uploading 33zv9amrz8l0sqjiixb6zsgf1xh5dgks-shared-dep (136B)13762026/10/04 20:07:18 WARN Failed to register uploaded object key=33zv9amrz8l0sqjiixb6zsgf1xh5dgks.ls error="server returned 404: 404 page not found\n"13772026/10/04 20:07:18 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13782026/10/04 20:07:18 WARN Failed to register uploaded object key=ivcm0j9zq5vkg1dfhixbvdjyjcdzng4p.ls error="server returned 404: 404 page not found\n"13792026/10/04 20:07:18 WARN Failed to register uploaded object key=nar/05j61r80l652xhjlknm8dc69pd1r6vxcmhhk9x5hyxprslbkmbcw.nar.zst error="server returned 404: 404 page not found\n"13802026/10/04 20:07:18 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13812026/10/04 20:07:18 WARN Failed to register uploaded object key=sv9d82fm4vqvysvgwiw9a0i3hlz7mjip.ls error="server returned 404: 404 page not found\n"13822026/10/04 20:07:18 INFO Signed narinfos id=1 count=213832026/10/04 20:07:18 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13842026/10/04 20:07:18 INFO Signed narinfos id=2 count=213852026/10/04 20:07:18 INFO Uploading 4 narinfos13862026/10/04 20:07:18 WARN Failed to register uploaded object key=sv9d82fm4vqvysvgwiw9a0i3hlz7mjip.narinfo error="server returned 404: 404 page not found\n"13872026/10/04 20:07:18 WARN Failed to register uploaded object key=33zv9amrz8l0sqjiixb6zsgf1xh5dgks.narinfo error="server returned 404: 404 page not found\n"13882026/10/04 20:07:18 WARN Failed to register uploaded object key=ivcm0j9zq5vkg1dfhixbvdjyjcdzng4p.narinfo error="server returned 404: 404 page not found\n"13892026/10/04 20:07:18 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13902026/10/04 20:07:18 WARN Failed to register uploaded object key=33zv9amrz8l0sqjiixb6zsgf1xh5dgks.narinfo error="server returned 404: 404 page not found\n"13912026/10/04 20:07:18 INFO Completed upload id=113922026/10/04 20:07:18 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13932026/10/04 20:07:18 INFO Completed upload id=213942026/10/04 20:07:18 INFO Upload complete. (243ms)1395=== NAME TestClientFallsBackToClosures1396 client_pushes_test.go:112: Retrieved narinfo from S3:1397 StorePath: /nix/var/nix/builds/nix-13370-2378689625/TestClientFallsBackToClosures280424683/001/store/33zv9amrz8l0sqjiixb6zsgf1xh5dgks-shared-dep1398 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1399 Compression: zstd1400 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821401 NarSize: 1361402 References: 1403 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1404 client_pushes_test.go:112: Retrieved narinfo from S3:1405 StorePath: /nix/var/nix/builds/nix-13370-2378689625/TestClientFallsBackToClosures280424683/001/store/ivcm0j9zq5vkg1dfhixbvdjyjcdzng4p-a1406 URL: nar/05j61r80l652xhjlknm8dc69pd1r6vxcmhhk9x5hyxprslbkmbcw.nar.zst1407 Compression: zstd1408 NarHash: sha256:05j61r80l652xhjlknm8dc69pd1r6vxcmhhk9x5hyxprslbkmbcw1409 NarSize: 2481410 References: /nix/var/nix/builds/nix-13370-2378689625/TestClientFallsBackToClosures280424683/001/store/33zv9amrz8l0sqjiixb6zsgf1xh5dgks-shared-dep1411 CA: text:sha256:1r8cmhrdb870icq1smz3cglr8sn6p775k4d0kzqgb14r12vwbf061412 client_pushes_test.go:112: Retrieved narinfo from S3:1413 StorePath: /nix/var/nix/builds/nix-13370-2378689625/TestClientFallsBackToClosures280424683/001/store/sv9d82fm4vqvysvgwiw9a0i3hlz7mjip-b1414 URL: nar/05j61r80l652xhjlknm8dc69pd1r6vxcmhhk9x5hyxprslbkmbcw.nar.zst1415 Compression: zstd1416 NarHash: sha256:05j61r80l652xhjlknm8dc69pd1r6vxcmhhk9x5hyxprslbkmbcw1417 NarSize: 2481418 References: /nix/var/nix/builds/nix-13370-2378689625/TestClientFallsBackToClosures280424683/001/store/33zv9amrz8l0sqjiixb6zsgf1xh5dgks-shared-dep1419 CA: text:sha256:1r8cmhrdb870icq1smz3cglr8sn6p775k4d0kzqgb14r12vwbf061420--- PASS: TestClientFallsBackToClosures (7.04s)1421=== CONT TestPendingCleanupUsesOneCutoff1422--- PASS: TestRegisterCompletedObjectNeedsPendingRow (4.53s)1423=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit14242026/10/04 20:07:20 INFO Aborted multipart uploads count=0 kept=014252026/10/04 20:07:20 WARN Force mode enabled - objects will be deleted immediately without grace period14262026/10/04 20:07:20 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=014272026/10/04 20:07:20 INFO Vacuumed table table=pending_closures14282026/10/04 20:07:20 INFO Vacuumed table table=pending_objects14292026/10/04 20:07:20 INFO Vacuumed table table=multipart_uploads14302026/10/04 20:07:20 INFO Vacuumed table table=closures14312026/10/04 20:07:20 INFO Vacuumed table table=objects14322026/10/04 20:07:20 INFO Aborted multipart uploads count=0 kept=014332026/10/04 20:07:20 WARN Force mode enabled - objects will be deleted immediately without grace period14342026/10/04 20:07:20 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=014352026/10/04 20:07:20 INFO Vacuumed table table=pending_closures14362026/10/04 20:07:20 INFO Vacuumed table table=pending_objects14372026/10/04 20:07:20 INFO Vacuumed table table=multipart_uploads14382026/10/04 20:07:20 INFO Vacuumed table table=closures14392026/10/04 20:07:20 INFO Vacuumed table table=objects1440--- PASS: TestSweepSkipsRowsLockedByPush (4.60s)1441=== CONT TestPush_CompleteCommitsEveryRoot1442--- PASS: TestObjectStatsTrigger (5.39s)1443=== CONT TestPush_OverlappingRootsStoreOneRowPerKey14442026/10/04 20:07:21 INFO Received uploads request method=POST path=/api/pending_closures1445=== NAME TestOrphanedObjectsGC1446 orphaned_objects_gc_test.go:290: GC Test Summary:1447 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1448 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1449 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1450 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1451 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1452--- PASS: TestOrphanedObjectsGC (5.61s)1453=== CONT TestReadRedirectNar14542026/10/04 20:07:21 INFO Aborted multipart uploads count=0 kept=014552026/10/04 20:07:21 WARN Force mode enabled - objects will be deleted immediately without grace period14562026/10/04 20:07:21 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."14572026/10/04 20:07:21 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1458--- PASS: TestFailedS3DeleteKeepsTombstone (5.47s)1459=== CONT TestReadRedirectKeepsNarinfoProxied14602026/10/04 20:07:22 INFO Received uploads request method=POST path=/api/pending_closures1461--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (5.44s)1462=== CONT TestReadProxyRangeRequest1463--- PASS: TestReadRedirectUsesPublicS3URL (5.35s)1464=== CONT TestReadProxyDisabled1465=== NAME TestOrphanedObjectsGCStressTest1466 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1467 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion1468=== RUN TestPush_RejectsBadRequests/no_roots1469=== PAUSE TestPush_RejectsBadRequests/no_roots1470=== RUN TestPush_RejectsBadRequests/no_objects1471=== PAUSE TestPush_RejectsBadRequests/no_objects1472=== RUN TestPush_RejectsBadRequests/bad_root1473=== PAUSE TestPush_RejectsBadRequests/bad_root1474=== RUN TestPush_RejectsBadRequests/root_not_in_objects1475=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1476=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded14772026/10/04 20:07:24 INFO Received uploads request method=POST path=/api/pending_closures14782026/10/04 20:07:24 INFO Received uploads request method=POST path=/api/pending_closures14792026/10/04 20:07:24 INFO Received cleanup request method=DELETE path=/api/pending_closures14802026/10/04 20:07:24 INFO Received push request method=POST path=/api/pushes14812026/10/04 20:07:24 INFO Received complete push request method=POST path=/api/pushes/1/complete14822026/10/04 20:07:24 INFO Received push request method=POST path=/api/pushes14832026/10/04 20:07:24 INFO Aborted multipart uploads count=0 kept=014842026/10/04 20:07:24 WARN Force mode enabled - objects will be deleted immediately without grace period14852026/10/04 20:07:24 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=014862026/10/04 20:07:24 INFO Vacuumed table table=pending_closures14872026/10/04 20:07:24 INFO Vacuumed table table=pending_objects14882026/10/04 20:07:24 INFO Vacuumed table table=multipart_uploads14892026/10/04 20:07:24 INFO Vacuumed table table=closures14902026/10/04 20:07:24 INFO Vacuumed table table=objects14912026/10/04 20:07:24 INFO Received complete push request method=POST path=/api/pushes/2/complete1492--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (5.13s)1493=== CONT TestService_ReadAuthMiddleware14942026/10/04 20:07:25 INFO Received push request method=POST path=/api/pushes14952026/10/04 20:07:25 INFO Received complete push request method=POST path=/api/pushes/1/complete1496--- PASS: TestPush_CompleteCommitsEveryRoot (4.91s)1497=== CONT TestService_AuthMiddleware_OIDC14982026/10/04 20:07:25 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51410/oidc14992026/10/04 20:07:26 INFO Received push request method=POST path=/api/pushes1500--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (5.04s)1501=== CONT TestPinProtectsFromGC1502--- PASS: TestReadRedirectNar (4.95s)1503=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1504--- PASS: TestReadRedirectKeepsNarinfoProxied (5.33s)1505=== CONT TestCacheStatsHandler1506--- PASS: TestReadProxyRangeRequest (5.30s)1507=== CONT TestClientCADerivations1508--- PASS: TestReadProxyDisabled (5.36s)1509=== CONT TestCacheConfigHandler1510=== RUN TestCacheConfigHandler/full_config,_no_issuer1511=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1512=== RUN TestCacheConfigHandler/no_cache_url_configured1513=== PAUSE TestCacheConfigHandler/no_cache_url_configured1514=== RUN TestCacheConfigHandler/no_signing_keys1515=== PAUSE TestCacheConfigHandler/no_signing_keys1516=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1517=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1518=== CONT TestService_AuthMiddleware_MTLSProxyHeader1519=== NAME TestOrphanedObjectsGCStressTest1520 orphaned_objects_gc_test.go:509: Stress test completed successfully:1521 orphaned_objects_gc_test.go:510: - Active objects preserved: 201522 orphaned_objects_gc_test.go:511: - Objects deleted: 2101523 orphaned_objects_gc_test.go:512: - Total GC'd: 2101524--- PASS: TestOrphanedObjectsGCStressTest (22.19s)1525=== CONT TestService_ReadScope_PublicByDefault15262026/10/04 20:07:28 INFO Received uploads request method=POST path=/api/pending_closures1527--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (4.99s)1528=== CONT TestClientErrorHandling1529=== RUN TestClientErrorHandling/InvalidStorePath1530=== PAUSE TestClientErrorHandling/InvalidStorePath1531=== RUN TestClientErrorHandling/InvalidAuthToken1532=== PAUSE TestClientErrorHandling/InvalidAuthToken1533=== RUN TestClientErrorHandling/ServerNotAvailable1534=== PAUSE TestClientErrorHandling/ServerNotAvailable1535=== CONT TestService_RequireScope_OIDC15362026/10/04 20:07:28 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51461/oidc1537--- PASS: TestService_ReadAuthMiddleware (4.30s)1538=== CONT TestProxyWriteTimeout/narinfo1539=== CONT TestProxyWriteTimeout/10_GiB_nar1540=== CONT TestProxyWriteTimeout/unknown_size1541=== CONT TestProxyWriteTimeout/1_GiB_nar1542--- PASS: TestProxyWriteTimeout (0.00s)1543 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1544 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1545 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1546 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1547=== CONT TestIsValidCachePath/narinfo1548=== CONT TestIsValidCachePath/index.html1549=== CONT TestIsValidCachePath/short_hash1550=== CONT TestIsValidCachePath/wrong_extension1551=== CONT TestIsValidCachePath/leading_slash1552=== CONT TestIsValidCachePath/empty1553=== CONT TestIsValidCachePath/random_path1554=== CONT TestIsValidCachePath/invalid_char_u1555=== CONT TestIsValidCachePath/invalid_char_e1556=== CONT TestIsValidCachePath/traversal_in_middle1557=== CONT TestIsValidCachePath/traversal_parent1558=== CONT TestIsValidCachePath/nar_uncompressed1559=== CONT TestIsValidCachePath/nix-cache-info1560=== CONT TestIsValidCachePath/realisation1561=== CONT TestIsValidCachePath/log1562=== CONT TestIsValidCachePath/ls1563=== CONT TestIsValidCachePath/nar_bz21564=== CONT TestIsValidCachePath/nar_zst1565=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1566=== CONT TestIsValidCachePath/nar_xz1567--- PASS: TestIsValidCachePath (0.00s)1568 --- PASS: TestIsValidCachePath/narinfo (0.00s)1569 --- PASS: TestIsValidCachePath/index.html (0.00s)1570 --- PASS: TestIsValidCachePath/short_hash (0.00s)1571 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1572 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1573 --- PASS: TestIsValidCachePath/empty (0.00s)1574 --- PASS: TestIsValidCachePath/random_path (0.00s)1575 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1576 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1577 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1578 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1579 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1580 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1581 --- PASS: TestIsValidCachePath/realisation (0.00s)1582 --- PASS: TestIsValidCachePath/log (0.00s)1583 --- PASS: TestIsValidCachePath/ls (0.00s)1584 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1585 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1586 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1587 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1588=== CONT TestServerTLSConfig/no_client_CA1589=== CONT TestServerTLSConfig/not_a_PEM_file1590=== CONT TestServerTLSConfig/missing_CA_file1591=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1592--- PASS: TestServerTLSConfig (0.00s)1593 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1594 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.05s)1595 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)15962026/10/04 20:07:29 INFO Received uploads request method=POST path=/1597=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15982026/10/04 20:07:29 INFO Received complete multipart upload request method=POST path=/1599=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16002026/10/04 20:07:29 INFO Received request for more parts method=POST path=/1601=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16022026/10/04 20:07:29 INFO Received uploads request method=POST path=/1603--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1604 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1605 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1606 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1607 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1608=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16092026/10/04 20:07:29 INFO Received uploads request method=POST path=/1610=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16112026/10/04 20:07:29 INFO Received request for more parts method=POST path=/1612=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16132026/10/04 20:07:29 INFO Received complete multipart upload request method=POST path=/1614=== CONT TestIsValidUploadKey/narinfo1615=== CONT TestIsValidUploadKey/realisation_plus_in_output1616=== CONT TestIsValidUploadKey/unknown_type1617=== CONT TestIsValidUploadKey/empty_key1618--- PASS: TestUploadHandlersRejectOversizedBody (0.04s)1619 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.29s)1620 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1621 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1622=== CONT TestIsValidUploadKey/absolute1623=== CONT TestIsValidUploadKey/traversal_nar1624=== CONT TestIsValidUploadKey/traversal1625=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1626=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1627=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1628=== CONT TestIsValidUploadKey/index.html1629=== CONT TestIsValidUploadKey/nix-cache-info1630=== CONT TestIsValidUploadKey/build_log_home-manager_file1631=== CONT TestIsValidUploadKey/realisation1632=== CONT TestIsValidUploadKey/build_log_equals1633=== CONT TestIsValidUploadKey/build_log_question_mark1634=== CONT TestIsValidUploadKey/build_log_plus_in_name1635=== CONT TestIsValidUploadKey/nar_plain1636=== CONT TestIsValidUploadKey/build_log1637=== CONT TestIsValidUploadKey/listing1638=== CONT TestIsValidUploadKey/nar_xz1639=== CONT TestIsValidUploadKey/nar_zst1640--- PASS: TestIsValidUploadKey (0.00s)1641 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1642 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1643 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1644 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1645 --- PASS: TestIsValidUploadKey/absolute (0.00s)1646 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1647 --- PASS: TestIsValidUploadKey/traversal (0.00s)1648 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1649 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1650 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1651 --- PASS: TestIsValidUploadKey/index.html (0.00s)1652 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1653 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1654 --- PASS: TestIsValidUploadKey/realisation (0.00s)1655 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1656 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1657 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1658 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1659 --- PASS: TestIsValidUploadKey/build_log (0.00s)1660 --- PASS: TestIsValidUploadKey/listing (0.00s)1661 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1662 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1663=== CONT TestPendingClosureWriteTimeout/empty1664=== CONT TestPendingClosureWriteTimeout/670k_objects1665=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1666=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1667=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1668=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1669=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1670=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1671=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1672=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1673=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1674=== CONT TestPendingClosureWriteTimeout/400_objects1675=== CONT TestResolveDBConnectionString/flag_wins1676=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1677=== CONT TestResolveDBConnectionString/nothing_configured1678=== CONT TestResolveDBConnectionString/missing_file_is_an_error1679=== CONT TestResolveDBConnectionString/file_when_flag_empty1680=== CONT TestParseSingleRange/none1681=== CONT TestParseSingleRange/open-ended1682=== CONT TestParseSingleRange/start_far_past_EOF1683=== CONT TestParseSingleRange/start_past_EOF1684=== CONT TestParseSingleRange/single_byte1685=== CONT TestParseSingleRange/suffix_exceeds_size1686=== CONT TestParseSingleRange/suffix1687=== CONT TestParseSingleRange/end_clamped_to_size1688=== CONT TestParseSingleRange/malformed_both_empty1689=== CONT TestParseSingleRange/closed1690=== CONT TestParseSingleRange/malformed_end_before_start1691=== CONT TestParseSingleRange/multi-range_ignored1692=== CONT TestParseSingleRange/malformed_no_dash1693=== CONT TestParseSingleRange/unknown_unit1694--- PASS: TestParseSingleRange (0.00s)1695 --- PASS: TestParseSingleRange/none (0.00s)1696 --- PASS: TestParseSingleRange/open-ended (0.00s)1697 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1698 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1699 --- PASS: TestParseSingleRange/single_byte (0.00s)1700 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1701 --- PASS: TestParseSingleRange/suffix (0.00s)1702 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1703 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1704 --- PASS: TestParseSingleRange/closed (0.00s)1705 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1706 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1707 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1708 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1709=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1710--- PASS: TestResolveDBConnectionString (0.03s)1711 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1712 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1713 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1714 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1715 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)17162026/10/04 20:07:30 INFO Aborted multipart uploads count=1 kept=017172026/10/04 20:07:30 INFO Received cleanup request method=DELETE path=/api/pending_closures17182026/10/04 20:07:30 INFO Aborted multipart uploads count=1 kept=01719--- PASS: TestPendingCleanupUsesOneCutoff (11.40s)1720=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1721{"timestamp":"2026-10-04T20:07:30.848248Z","level":"ERROR","message":"Scanner cycle completed without a durable data usage snapshot","event":"scanner_persist_state","component":"scanner","subsystem":"runtime","cycle":5,"outcome":"NoUpdate","state":"usage_not_durable","target":"rustfs::scanner","filename":"crates/scanner/src/scanner.rs","line_number":2350,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}17222026/10/04 20:07:31 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"17232026/10/04 20:07:31 WARN mTLS auth: bound subjects configured but subject DN unavailable17242026/10/04 20:07:31 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1725--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (4.88s)1726=== CONT TestPush_RejectsBadRequests/no_roots17272026/10/04 20:07:31 INFO Received push request method=POST path=/api/pushes1728=== CONT TestPush_RejectsBadRequests/bad_root17292026/10/04 20:07:31 INFO Received push request method=POST path=/api/pushes1730=== CONT TestPush_RejectsBadRequests/no_objects17312026/10/04 20:07:31 INFO Received push request method=POST path=/api/pushes1732=== CONT TestPush_RejectsBadRequests/root_not_in_objects17332026/10/04 20:07:31 INFO Received push request method=POST path=/api/pushes1734=== CONT TestCacheConfigHandler/full_config,_no_issuer1735--- PASS: TestPush_RejectsBadRequests (5.00s)1736 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1737 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1738 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1739 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1740=== CONT TestCacheConfigHandler/no_signing_keys1741=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1742=== CONT TestCacheConfigHandler/no_cache_url_configured1743--- PASS: TestCacheConfigHandler (0.00s)1744 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1745 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1746 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1747 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1748=== CONT TestClientErrorHandling/InvalidStorePath1749=== NAME TestPinProtectsFromGC1750 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-13370-2378689625/TestPinProtectsFromGC2230307907/001/store/6kgdn0ylqk7r5a4331im211csxjyhqwj-pinned-file.txt1751 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-13370-2378689625/TestPinProtectsFromGC2230307907/001/store/wh8lpa9zj6yvxzq72nga1qpg42f25zq3-unpinned-file.txt17522026/10/04 20:07:32 INFO Received push request method=POST path=/api/pushes17532026/10/04 20:07:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17542026/10/04 20:07:32 INFO Uploading 6kgdn0ylqk7r5a4331im211csxjyhqwj-pinned-file.txt (128B)17552026/10/04 20:07:32 WARN Failed to register uploaded object key=6kgdn0ylqk7r5a4331im211csxjyhqwj.ls error="server returned 404: 404 page not found\n"17562026/10/04 20:07:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17572026/10/04 20:07:32 INFO Signed narinfos id=1 count=117582026/10/04 20:07:32 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"1759--- PASS: TestCacheStatsHandler (4.86s)17602026/10/04 20:07:32 INFO Uploading 1 narinfos1761=== CONT TestClientErrorHandling/ServerNotAvailable17622026/10/04 20:07:32 INFO Received complete push request method=POST path=/api/pushes/1/complete17632026/10/04 20:07:32 WARN Failed to register uploaded object key=6kgdn0ylqk7r5a4331im211csxjyhqwj.narinfo error="server returned 404: 404 page not found\n"17642026/10/04 20:07:32 INFO Upload complete. (218ms)17652026/10/04 20:07:32 INFO Received push request method=POST path=/api/pushes17662026/10/04 20:07:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17672026/10/04 20:07:32 INFO Uploading wh8lpa9zj6yvxzq72nga1qpg42f25zq3-unpinned-file.txt (128B)17682026/10/04 20:07:32 WARN Failed to register uploaded object key=wh8lpa9zj6yvxzq72nga1qpg42f25zq3.ls error="server returned 404: 404 page not found\n"17692026/10/04 20:07:32 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"17702026/10/04 20:07:32 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17712026/10/04 20:07:32 INFO Signed narinfos id=2 count=117722026/10/04 20:07:32 INFO Uploading 1 narinfos17732026/10/04 20:07:32 INFO Received complete push request method=POST path=/api/pushes/2/complete17742026/10/04 20:07:32 WARN Failed to register uploaded object key=wh8lpa9zj6yvxzq72nga1qpg42f25zq3.narinfo error="server returned 404: 404 page not found\n"17752026/10/04 20:07:32 INFO Upload complete. (154ms)17762026/10/04 20:07:32 INFO Starting cleanup of old closures method=DELETE path=/api/closures17772026/10/04 20:07:32 INFO Garbage collection started17782026/10/04 20:07:32 INFO Aborted multipart uploads count=0 kept=017792026/10/04 20:07:32 WARN Force mode enabled - objects will be deleted immediately without grace period17802026/10/04 20:07:32 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=017812026/10/04 20:07:32 INFO Vacuumed table table=pending_closures17822026/10/04 20:07:32 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/present17832026/10/04 20:07:32 INFO Vacuumed table table=pending_objects17842026/10/04 20:07:32 INFO Vacuumed table table=multipart_uploads17852026/10/04 20:07:32 INFO Vacuumed table table=closures17862026/10/04 20:07:32 INFO Vacuumed table table=objects17872026/10/04 20:07:32 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=215.68343ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1788--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (4.85s)1789=== CONT TestClientErrorHandling/InvalidAuthToken17902026/10/04 20:07:32 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=372.94784ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1791=== NAME TestClientCADerivations1792 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-13370-2378689625/TestClientCADerivations4054926003/001/store/vnbl6i2kkfa8sfxzm9yc5ck91l39vfqm-ca-test1793 client_ca_test.go:139: Found 1 dependencies (including self)1794--- PASS: TestService_ReadScope_PublicByDefault (4.94s)1795=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1796=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected17972026/10/04 20:07:33 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]1798=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1799=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected18002026/10/04 20:07:33 WARN Authentication failed token_preview=eyJhbGciOi...-yGv7QO1hA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1801--- PASS: TestService_AuthMiddleware_OIDC (4.56s)1802 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1803 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1804 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1805 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)18062026/10/04 20:07:33 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=745.351562ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18072026/10/04 20:07:33 INFO Received push request method=POST path=/api/pushes18082026/10/04 20:07:33 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18092026/10/04 20:07:33 INFO Uploading vnbl6i2kkfa8sfxzm9yc5ck91l39vfqm-ca-test (144B)18102026/10/04 20:07:33 WARN Failed to register uploaded object key=vnbl6i2kkfa8sfxzm9yc5ck91l39vfqm.ls error="server returned 404: 404 page not found\n"18112026/10/04 20:07:33 WARN Failed to register uploaded object key=log/d3r29xwwfm27w2dxzaj4ri318lkkjhyh-ca-test.drv error="server returned 404: 404 page not found\n"18122026/10/04 20:07:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18132026/10/04 20:07:33 INFO Signed narinfos id=1 count=118142026/10/04 20:07:33 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18152026/10/04 20:07:33 INFO Uploading 1 narinfos18162026/10/04 20:07:33 INFO Received complete push request method=POST path=/api/pushes/1/complete18172026/10/04 20:07:33 WARN Failed to register uploaded object key=vnbl6i2kkfa8sfxzm9yc5ck91l39vfqm.narinfo error="server returned 404: 404 page not found\n"18182026/10/04 20:07:33 INFO Upload complete. (310ms)1819=== NAME TestClientCADerivations1820 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-13370-2378689625/TestClientCADerivations4054926003/001/store/vnbl6i2kkfa8sfxzm9yc5ck91l39vfqm-ca-test1821 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1822 Compression: zstd1823 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1824 NarSize: 1441825 References: 1826 Deriver: /nix/var/nix/builds/nix-13370-2378689625/TestClientCADerivations4054926003/001/store/d3r29xwwfm27w2dxzaj4ri318lkkjhyh-ca-test.drv1827 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1828 client_ca_test.go:185: Checking for realisation files in S3...1829 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1830 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1831 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket80?endpoint=http://localhost:50801®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-13370-2378689625/TestClientCADerivations4054926003/001/store'1832 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11833=== RUN TestService_RequireScope_OIDC/builder_may_write1834=== PAUSE TestService_RequireScope_OIDC/builder_may_write1835=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1836=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1837=== RUN TestService_RequireScope_OIDC/ops_may_admin1838=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1839=== RUN TestService_RequireScope_OIDC/ops_may_not_write1840=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1841=== RUN TestService_RequireScope_OIDC/reader_may_not_write1842=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1843=== RUN TestService_RequireScope_OIDC/static_token_may_admin1844=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1845=== RUN TestService_RequireScope_OIDC/static_token_may_write1846=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1847=== RUN TestService_RequireScope_OIDC/reader_may_read1848=== PAUSE TestService_RequireScope_OIDC/reader_may_read1849=== RUN TestService_RequireScope_OIDC/writer_implies_read1850=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1851=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1852=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1853=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1854=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1855=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1856=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1857=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1858=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1859=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1860=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1861=== CONT TestService_RequireScope_OIDC/builder_may_write1862=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1863=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1864=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1865=== CONT TestService_RequireScope_OIDC/static_token_may_admin1866=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read18672026/10/04 20:07:33 WARN Authentication failed token_preview=wrong token_length=5 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]1868=== CONT TestService_RequireScope_OIDC/writer_implies_read1869=== CONT TestService_RequireScope_OIDC/reader_may_read1870=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1871=== CONT TestService_RequireScope_OIDC/ops_may_not_write1872=== CONT TestService_RequireScope_OIDC/static_token_may_write1873=== CONT TestService_RequireScope_OIDC/reader_may_not_write1874=== CONT TestService_RequireScope_OIDC/ops_may_admin1875=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1876--- PASS: TestService_RequireScope_OIDC (5.11s)1877 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1878 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1879 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1880 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1881 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1882 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1883 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1884 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1885 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1886 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1887 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1888 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1889 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1890 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1891--- PASS: TestClientCADerivations (6.21s)18922026/10/04 20:07:34 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.519817454s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18932026/10/04 20:07:34 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=018942026/10/04 20:07:34 INFO Received create pin request method=POST path=/api/pins/myapp18952026/10/04 20:07:34 INFO Received uploads request method=POST path=/api/pending_closures18962026/10/04 20:07:34 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-13370-2378689625/TestPinProtectsFromGC2230307907/001/store/6kgdn0ylqk7r5a4331im211csxjyhqwj-pinned-file.txt narinfo_key=6kgdn0ylqk7r5a4331im211csxjyhqwj.narinfo18972026/10/04 20:07:34 INFO Starting cleanup of old closures method=DELETE path=/api/closures18982026/10/04 20:07:34 INFO Garbage collection started18992026/10/04 20:07:34 INFO Aborted multipart uploads count=0 kept=019002026/10/04 20:07:34 WARN Force mode enabled - objects will be deleted immediately without grace period19012026/10/04 20:07:34 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=019022026/10/04 20:07:34 INFO Vacuumed table table=pending_closures19032026/10/04 20:07:34 INFO Vacuumed table table=pending_objects19042026/10/04 20:07:34 INFO Vacuumed table table=multipart_uploads19052026/10/04 20:07:34 INFO Vacuumed table table=closures19062026/10/04 20:07:34 INFO Vacuumed table table=objects19072026/10/04 20:07:34 INFO Received uploads request method=POST path=/api/pending_closures19082026/10/04 20:07:35 INFO Aborted multipart uploads count=0 kept=019092026/10/04 20:07:35 WARN Force mode enabled - objects will be deleted immediately without grace period19102026/10/04 20:07:35 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=019112026/10/04 20:07:35 INFO Vacuumed table table=pending_closures19122026/10/04 20:07:35 INFO Vacuumed table table=pending_objects19132026/10/04 20:07:35 INFO Vacuumed table table=multipart_uploads19142026/10/04 20:07:35 INFO Vacuumed table table=closures19152026/10/04 20:07:35 INFO Vacuumed table table=objects1916--- PASS: TestPendingClosureWriteTimeout (0.00s)1917 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)1918 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)1919 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)1920 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (5.68s)19212026/10/04 20:07:35 INFO Received uploads request method=POST path=/api/pending_closures19222026/10/04 20:07:35 INFO Aborted multipart uploads count=0 kept=019232026/10/04 20:07:35 WARN Force mode enabled - objects will be deleted immediately without grace period19242026/10/04 20:07:35 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=019252026/10/04 20:07:35 INFO Vacuumed table table=pending_closures19262026/10/04 20:07:35 INFO Vacuumed table table=pending_objects19272026/10/04 20:07:35 INFO Vacuumed table table=multipart_uploads19282026/10/04 20:07:35 INFO Vacuumed table table=closures19292026/10/04 20:07:35 INFO Vacuumed table table=objects19302026/10/04 20:07:35 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-config1931--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)1932 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (5.38s)1933 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (5.35s)19342026/10/04 20:07:35 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=196.086663ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19352026/10/04 20:07:35 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=363.421436ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19362026/10/04 20:07:36 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=811.525412ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1937=== NAME TestPinProtectsFromGC1938 client_integration_test.go:840: Pin successfully protected closure from garbage collection1939--- PASS: TestPinProtectsFromGC (10.28s)19402026/10/04 20:07:37 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.642922807s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19412026/10/04 20:07:37 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"19422026/10/04 20:07:37 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"19432026/10/04 20:07:38 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"19442026/10/04 20:07:38 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-config19452026/10/04 20:07:38 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=180.245312ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19462026/10/04 20:07:39 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=388.168416ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19472026/10/04 20:07:39 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=824.034852ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19482026/10/04 20:07:40 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.572790943s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19492026/10/04 20:07:41 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_closures19502026/10/04 20:07:41 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=208.562132ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19512026/10/04 20:07:42 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=425.805798ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1952{"timestamp":"2026-10-04T20:07:42.480135Z","level":"ERROR","message":"Scanner cycle completed without a durable data usage snapshot","event":"scanner_persist_state","component":"scanner","subsystem":"runtime","cycle":5,"outcome":"NoUpdate","state":"usage_not_durable","target":"rustfs::scanner","filename":"crates/scanner/src/scanner.rs","line_number":2350,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}19532026/10/04 20:07:42 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=753.886181ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19542026/10/04 20:07:43 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.74883236s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1955--- PASS: TestClientErrorHandling (0.00s)1956 --- PASS: TestClientErrorHandling/InvalidStorePath (4.83s)1957 --- PASS: TestClientErrorHandling/InvalidAuthToken (5.07s)1958 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.99s)1959PASS1960{"timestamp":"2026-10-04T20:07:45.12711Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:50917","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(11)"}19612026-10-04 20:07:45.266 UTC [13441] LOG: received smart shutdown request19622026-10-04 20:07:45.267 UTC [13441] LOG: background worker "logical replication launcher" (PID 13451) exited with exit code 119632026-10-04 20:07:45.270 UTC [13446] LOG: shutting down19642026-10-04 20:07:45.270 UTC [13446] LOG: checkpoint starting: shutdown immediate19652026-10-04 20:07:46.588 UTC [13446] LOG: checkpoint complete: wrote 12898 buffers (78.7%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 26 recycled; write=0.770 s, sync=0.538 s, total=1.319 s; sync files=29997, longest=0.022 s, average=0.001 s; distance=421833 kB, estimate=421833 kB; lsn=0/1B37F578, redo lsn=0/1B37F57819662026-10-04 20:07:46.594 UTC [13441] LOG: database system is shut down1967Running OIDC tests...1968=== RUN TestAudienceForIssuer1969=== PAUSE TestAudienceForIssuer1970=== RUN TestGlobMatch1971=== PAUSE TestGlobMatch1972=== RUN TestValidateToken_ValidToken1973=== PAUSE TestValidateToken_ValidToken1974=== RUN TestValidateToken_WrongAudience1975=== PAUSE TestValidateToken_WrongAudience1976=== RUN TestValidateToken_Expired1977=== PAUSE TestValidateToken_Expired1978=== RUN TestValidateToken_BoundClaimsMismatch1979=== PAUSE TestValidateToken_BoundClaimsMismatch1980=== RUN TestValidateToken_BoundSubjectMismatch1981=== PAUSE TestValidateToken_BoundSubjectMismatch1982=== RUN TestValidateToken_MultipleProviders1983=== PAUSE TestValidateToken_MultipleProviders1984=== RUN TestValidateToken_NoMatchingProvider1985=== PAUSE TestValidateToken_NoMatchingProvider1986=== RUN TestValidateToken_KubernetesServiceAccount1987=== PAUSE TestValidateToken_KubernetesServiceAccount1988=== RUN TestNewValidator_KubernetesRequiresCA1989=== PAUSE TestNewValidator_KubernetesRequiresCA1990=== RUN TestValidateToken_KubernetesIssuerFromOwnToken1991=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken1992=== RUN TestPins_ReservedForMatchingRule1993=== PAUSE TestPins_ReservedForMatchingRule1994=== RUN TestPins_TopLevelShorthand1995=== PAUSE TestPins_TopLevelShorthand1996=== RUN TestPins_ConfigValidation1997=== PAUSE TestPins_ConfigValidation1998=== RUN TestScopes_LegacyProviderDefaultsToWrite1999=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2000=== RUN TestScopes_Rules2001=== PAUSE TestScopes_Rules2002=== RUN TestScopes_ConfigValidation2003=== PAUSE TestScopes_ConfigValidation2004=== CONT TestAudienceForIssuer2005--- PASS: TestAudienceForIssuer (0.00s)2006=== CONT TestPins_ConfigValidation2007=== CONT TestValidateToken_KubernetesServiceAccount2008=== CONT TestValidateToken_NoMatchingProvider2009=== CONT TestValidateToken_MultipleProviders2010=== CONT TestValidateToken_BoundSubjectMismatch2011=== CONT TestValidateToken_BoundClaimsMismatch2012=== CONT TestValidateToken_Expired2013=== CONT TestValidateToken_WrongAudience2014--- PASS: TestPins_ConfigValidation (0.01s)2015=== CONT TestScopes_ConfigValidation2016--- PASS: TestScopes_ConfigValidation (0.00s)2017=== CONT TestScopes_LegacyProviderDefaultsToWrite2018=== CONT TestValidateToken_ValidToken2019=== CONT TestGlobMatch2020=== RUN TestGlobMatch/foo_foo2021=== PAUSE TestGlobMatch/foo_foo2022=== RUN TestGlobMatch/foo_bar2023=== PAUSE TestGlobMatch/foo_bar2024=== RUN TestGlobMatch/*_2025=== PAUSE TestGlobMatch/*_2026=== RUN TestGlobMatch/*_anything2027=== PAUSE TestGlobMatch/*_anything2028=== RUN TestGlobMatch/foo*_foo2029=== PAUSE TestGlobMatch/foo*_foo2030=== RUN TestGlobMatch/foo*_foobar2031=== PAUSE TestGlobMatch/foo*_foobar2032=== RUN TestGlobMatch/foo*_bar2033=== PAUSE TestGlobMatch/foo*_bar2034=== RUN TestGlobMatch/*bar_bar2035=== PAUSE TestGlobMatch/*bar_bar2036=== RUN TestGlobMatch/*bar_foobar2037=== PAUSE TestGlobMatch/*bar_foobar2038=== RUN TestGlobMatch/*bar_foo2039=== PAUSE TestGlobMatch/*bar_foo2040=== RUN TestGlobMatch/foo*bar_foobar2041=== PAUSE TestGlobMatch/foo*bar_foobar2042=== RUN TestGlobMatch/foo*bar_foo123bar2043=== PAUSE TestGlobMatch/foo*bar_foo123bar2044=== RUN TestGlobMatch/foo*bar_foobarbaz2045=== PAUSE TestGlobMatch/foo*bar_foobarbaz2046=== RUN TestGlobMatch/*/*_foo/bar2047=== PAUSE TestGlobMatch/*/*_foo/bar2048=== RUN TestGlobMatch/*/*_foo2049=== PAUSE TestGlobMatch/*/*_foo2050=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2051=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2052=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02053=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02054=== RUN TestGlobMatch/refs/*/main_refs/heads/main2055=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2056=== RUN TestGlobMatch/fo?_foo2057=== PAUSE TestGlobMatch/fo?_foo2058=== RUN TestGlobMatch/fo?_fo2059=== PAUSE TestGlobMatch/fo?_fo2060=== RUN TestGlobMatch/fo?_fooo2061=== PAUSE TestGlobMatch/fo?_fooo2062=== RUN TestGlobMatch/?oo_foo2063=== PAUSE TestGlobMatch/?oo_foo2064=== RUN TestGlobMatch/?oo_boo2065=== PAUSE TestGlobMatch/?oo_boo2066=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2067=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2068=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2069=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2070=== CONT TestPins_ReservedForMatchingRule20712026/10/04 20:07:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51696/oidc2072--- PASS: TestValidateToken_BoundSubjectMismatch (0.03s)2073=== CONT TestPins_TopLevelShorthand20742026/10/04 20:07:48 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:51695/oidc20752026/10/04 20:07:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51700/oidc2076--- PASS: TestValidateToken_Expired (0.05s)2077=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2078--- PASS: TestValidateToken_NoMatchingProvider (0.06s)2079=== CONT TestNewValidator_KubernetesRequiresCA20802026/10/04 20:07:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51702/oidc2081--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.05s)2082=== CONT TestScopes_Rules20832026/10/04 20:07:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51704/oidc2084--- PASS: TestValidateToken_ValidToken (0.05s)2085=== CONT TestGlobMatch/foo_foo2086=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2087=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2088=== CONT TestGlobMatch/?oo_boo2089=== CONT TestGlobMatch/?oo_foo2090=== CONT TestGlobMatch/fo?_fooo2091=== CONT TestGlobMatch/fo?_fo2092=== CONT TestGlobMatch/fo?_foo2093=== CONT TestGlobMatch/refs/*/main_refs/heads/main2094=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02095=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2096=== CONT TestGlobMatch/*/*_foo2097=== CONT TestGlobMatch/*/*_foo/bar2098=== CONT TestGlobMatch/foo*bar_foobarbaz2099=== CONT TestGlobMatch/foo*bar_foo123bar2100=== CONT TestGlobMatch/foo*bar_foobar2101=== CONT TestGlobMatch/*bar_foo2102=== CONT TestGlobMatch/*bar_foobar2103=== CONT TestGlobMatch/*bar_bar2104=== CONT TestGlobMatch/foo*_bar2105=== CONT TestGlobMatch/foo*_foobar2106=== CONT TestGlobMatch/foo*_foo2107=== CONT TestGlobMatch/*_anything2108=== CONT TestGlobMatch/*_2109=== CONT TestGlobMatch/foo_bar2110--- PASS: TestGlobMatch (0.00s)2111 --- PASS: TestGlobMatch/foo_foo (0.00s)2112 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2113 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2114 --- PASS: TestGlobMatch/?oo_boo (0.00s)2115 --- PASS: TestGlobMatch/?oo_foo (0.00s)2116 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2117 --- PASS: TestGlobMatch/fo?_fo (0.00s)2118 --- PASS: TestGlobMatch/fo?_foo (0.00s)2119 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2120 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2121 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2122 --- PASS: TestGlobMatch/*/*_foo (0.00s)2123 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2124 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2125 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2126 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2127 --- PASS: TestGlobMatch/*bar_foo (0.00s)2128 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2129 --- PASS: TestGlobMatch/*bar_bar (0.00s)2130 --- PASS: TestGlobMatch/foo*_bar (0.00s)2131 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2132 --- PASS: TestGlobMatch/foo*_foo (0.00s)2133 --- PASS: TestGlobMatch/*_anything (0.00s)2134 --- PASS: TestGlobMatch/*_ (0.00s)2135 --- PASS: TestGlobMatch/foo_bar (0.00s)21362026/10/04 20:07:48 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:517072137--- PASS: TestValidateToken_KubernetesServiceAccount (0.08s)21382026/10/04 20:07:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51709/oidc2139--- PASS: TestPins_TopLevelShorthand (0.06s)21402026/10/04 20:07:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51711/oidc2141--- PASS: TestValidateToken_BoundClaimsMismatch (0.10s)21422026/10/04 20:07:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51713/oidc2143--- PASS: TestValidateToken_WrongAudience (0.10s)21442026/10/04 20:07:48 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:51706/oidc21452026/10/04 20:07:48 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:51717/oidc2146--- PASS: TestValidateToken_MultipleProviders (0.12s)21472026/10/04 20:07:48 http: TLS handshake error from 127.0.0.1:51716: remote error: tls: bad certificate2148--- PASS: TestNewValidator_KubernetesRequiresCA (0.07s)21492026/10/04 20:07:48 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12321502026/10/04 20:07:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51721/oidc2151--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.09s)2152--- PASS: TestScopes_Rules (0.09s)21532026/10/04 20:07:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51724/oidc2154--- PASS: TestPins_ReservedForMatchingRule (0.18s)2155PASS2156Running hook tests...2157=== RUN TestSendPathsEmpty2158=== PAUSE TestSendPathsEmpty2159=== RUN TestQueueEnqueueAndFetch2160=== PAUSE TestQueueEnqueueAndFetch2161=== RUN TestQueueDeduplication2162=== PAUSE TestQueueDeduplication2163=== RUN TestQueueRemove2164=== PAUSE TestQueueRemove2165=== RUN TestQueueFetchBatchLimit2166=== PAUSE TestQueueFetchBatchLimit2167=== RUN TestQueueRetryMovesToBack2168=== PAUSE TestQueueRetryMovesToBack2169=== RUN TestQueueFetchRemoveLifecycle2170=== PAUSE TestQueueFetchRemoveLifecycle2171=== RUN TestQueueConcurrentWriters2172=== PAUSE TestQueueConcurrentWriters2173=== RUN TestQueueRemoveLargeClosure2174=== PAUSE TestQueueRemoveLargeClosure2175=== RUN TestServerClientIntegration2176=== PAUSE TestServerClientIntegration2177=== RUN TestServerQueueError2178=== PAUSE TestServerQueueError2179=== RUN TestGetListenerSocketActivation2180 server_test.go:210: === RUN TestGetListenerSocketActivation2181 --- PASS: TestGetListenerSocketActivation (0.00s)2182 PASS2183 2184--- PASS: TestGetListenerSocketActivation (0.01s)2185=== RUN TestDrainIsolatesPoisonPath2186=== PAUSE TestDrainIsolatesPoisonPath2187=== RUN TestRunNotBlockedByPoisonHead2188=== PAUSE TestRunNotBlockedByPoisonHead2189=== RUN TestDrainGivesUpWhenServerDown2190=== PAUSE TestDrainGivesUpWhenServerDown2191=== RUN TestFailedPathPrunedByLaterClosure2192=== PAUSE TestFailedPathPrunedByLaterClosure2193=== RUN TestWorkerUploadsAndRemoves2194=== PAUSE TestWorkerUploadsAndRemoves2195=== RUN TestWorkerSkipsGCdPaths2196=== PAUSE TestWorkerSkipsGCdPaths2197=== RUN TestWorkerPrunesClosureDeps2198=== PAUSE TestWorkerPrunesClosureDeps2199=== RUN TestDrainTimeout2200=== PAUSE TestDrainTimeout2201=== CONT TestSendPathsEmpty2202=== CONT TestDrainTimeout2203--- PASS: TestSendPathsEmpty (0.00s)2204=== CONT TestServerClientIntegration2205=== CONT TestQueueFetchBatchLimit2206=== CONT TestFailedPathPrunedByLaterClosure2207=== CONT TestQueueDeduplication2208=== CONT TestQueueConcurrentWriters2209=== CONT TestQueueFetchRemoveLifecycle2210=== CONT TestQueueRetryMovesToBack2211=== CONT TestQueueRemove2212=== CONT TestQueueRemoveLargeClosure2213--- PASS: TestServerClientIntegration (0.00s)2214=== CONT TestWorkerSkipsGCdPaths22152026/10/04 20:07:48 INFO Upload queue status pending=222162026/10/04 20:07:48 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-13370-2378689625/TestWorkerSkipsGCdPaths774653718/002/nonexistent2217--- PASS: TestQueueDeduplication (0.01s)2218=== CONT TestWorkerPrunesClosureDeps22192026/10/04 20:07:48 INFO Uploading batch count=122202026/10/04 20:07:48 ERROR Upload failed error="upload failed" count=12221--- PASS: TestQueueRemove (0.01s)2222=== CONT TestRunNotBlockedByPoisonHead22232026/10/04 20:07:48 INFO Uploading batch count=12224--- PASS: TestQueueFetchBatchLimit (0.01s)2225=== CONT TestDrainGivesUpWhenServerDown22262026/10/04 20:07:48 INFO Uploading batch count=222272026/10/04 20:07:48 INFO Uploading batch count=122282026/10/04 20:07:48 INFO Uploading batch count=12229--- PASS: TestQueueRetryMovesToBack (0.01s)2230=== CONT TestWorkerUploadsAndRemoves2231--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2232=== CONT TestDrainIsolatesPoisonPath2233--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)2234=== CONT TestServerQueueError22352026/10/04 20:07:48 ERROR Failed to queue paths error="permission denied" count=122362026/10/04 20:07:48 INFO Upload queue status pending=322372026/10/04 20:07:48 INFO Upload queue status pending=222382026/10/04 20:07:48 INFO Uploading batch count=122392026/10/04 20:07:48 ERROR Upload failed error="upload failed" count=122402026/10/04 20:07:48 INFO Uploading batch count=12241--- PASS: TestServerQueueError (0.00s)2242=== CONT TestQueueEnqueueAndFetch22432026/10/04 20:07:48 INFO Uploading batch count=422442026/10/04 20:07:48 ERROR Upload failed error="upload failed" count=422452026/10/04 20:07:48 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-13370-2378689625/TestDrainIsolatesPoisonPath4018976103/002/bbb22462026/10/04 20:07:48 INFO Upload queue status pending=222472026/10/04 20:07:48 INFO Uploading batch count=222482026/10/04 20:07:48 INFO Uploading batch count=122492026/10/04 20:07:48 ERROR Upload failed error="upload failed" count=122502026/10/04 20:07:48 INFO Uploading batch count=222512026/10/04 20:07:48 ERROR Upload failed error="upload failed" count=222522026/10/04 20:07:48 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-13370-2378689625/TestDrainGivesUpWhenServerDown1090900535/002/a22532026/10/04 20:07:48 INFO Uploading batch count=122542026/10/04 20:07:48 ERROR Upload failed error="upload failed" count=122552026/10/04 20:07:48 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-13370-2378689625/TestDrainGivesUpWhenServerDown1090900535/002/b22562026/10/04 20:07:48 INFO Uploading batch count=222572026/10/04 20:07:48 ERROR Upload failed error="upload failed" count=222582026/10/04 20:07:48 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-13370-2378689625/TestDrainGivesUpWhenServerDown1090900535/002/c22592026/10/04 20:07:48 INFO Uploading batch count=122602026/10/04 20:07:48 ERROR Upload failed error="upload failed" count=122612026/10/04 20:07:48 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-13370-2378689625/TestDrainGivesUpWhenServerDown1090900535/002/d22622026/10/04 20:07:48 ERROR Drain finished with paths left in queue remaining=122632026/10/04 20:07:48 INFO Uploading batch count=222642026/10/04 20:07:48 ERROR Upload failed error="upload failed" count=222652026/10/04 20:07:48 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-13370-2378689625/TestDrainGivesUpWhenServerDown1090900535/002/e2266--- PASS: TestQueueEnqueueAndFetch (0.00s)22672026/10/04 20:07:48 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-13370-2378689625/TestDrainGivesUpWhenServerDown1090900535/002/f22682026/10/04 20:07:48 ERROR Drain finished with paths left in queue remaining=102269--- PASS: TestDrainIsolatesPoisonPath (0.01s)2270--- PASS: TestDrainGivesUpWhenServerDown (0.01s)2271--- PASS: TestWorkerSkipsGCdPaths (0.03s)2272--- PASS: TestWorkerPrunesClosureDeps (0.02s)2273--- PASS: TestWorkerUploadsAndRemoves (0.02s)2274--- PASS: TestQueueRemoveLargeClosure (0.06s)2275--- PASS: TestQueueConcurrentWriters (0.20s)22762026/10/04 20:07:48 ERROR Upload failed error="context deadline exceeded" count=222772026/10/04 20:07:48 ERROR Drain finished with paths left in queue remaining=42278--- PASS: TestDrainTimeout (0.21s)22792026/10/04 20:07:49 INFO Uploading batch count=122802026/10/04 20:07:49 INFO Uploading batch count=122812026/10/04 20:07:49 INFO Uploading batch count=122822026/10/04 20:07:49 ERROR Upload failed error="upload failed" count=122832026/10/04 20:07:49 INFO Uploading batch count=122842026/10/04 20:07:49 ERROR Upload failed error="upload failed" count=122852026/10/04 20:07:49 INFO Uploading batch count=122862026/10/04 20:07:49 ERROR Upload failed error="upload failed" count=122872026/10/04 20:07:49 INFO Uploading batch count=122882026/10/04 20:07:49 ERROR Upload failed error="upload failed" count=122892026/10/04 20:07:49 ERROR Drain finished with paths left in queue remaining=12290--- PASS: TestRunNotBlockedByPoisonHead (1.01s)2291PASS