niks3-go-unit-tests log

succeeded `niks3-go-unit-tests` `checks.aarch64-darwin.go-unit-tests` · build #480 · raw

1tribuchet: building on mac022Running client tests...3=== RUN TestPushPathsRefusesUntrustedClosure4--- PASS: TestPushPathsRefusesUntrustedClosure (0.11s)5=== RUN TestDoServerRequestAttachesToken6=== PAUSE TestDoServerRequestAttachesToken7=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry8=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry9=== RUN TestRegisterUploadedObjectReusesConnections10=== PAUSE TestRegisterUploadedObjectReusesConnections11=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica12=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica13=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun14=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun15=== RUN TestCaseHackSuffix16=== PAUSE TestCaseHackSuffix17=== RUN TestFilterOversizedClosures18=== PAUSE TestFilterOversizedClosures19=== RUN TestUploadMultipart_PartsInParallel20=== PAUSE TestUploadMultipart_PartsInParallel21=== RUN TestUploadMultipart_ReturnsAfterDroppedBody22=== PAUSE TestUploadMultipart_ReturnsAfterDroppedBody23=== RUN TestPartSizeForNAR24=== PAUSE TestPartSizeForNAR25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (0.05s)27=== RUN TestDumpPathCaseHackCollision28--- PASS: TestDumpPathCaseHackCollision (0.00s)29=== RUN TestDumpPathMatchesNix30=== PAUSE TestDumpPathMatchesNix31=== RUN TestDumpPathSingleFile32=== PAUSE TestDumpPathSingleFile33=== RUN TestDumpPathWriterError34=== PAUSE TestDumpPathWriterError35=== RUN TestEncodeNixBase3236=== PAUSE TestEncodeNixBase3237=== RUN TestEncodeNixBase32WithRealHash38=== PAUSE TestEncodeNixBase32WithRealHash39=== RUN TestConvertHashToNix3240=== PAUSE TestConvertHashToNix3241=== RUN TestGetStorePathHash42=== PAUSE TestGetStorePathHash43=== RUN TestPathInfoHashCompatibility44=== PAUSE TestPathInfoHashCompatibility45=== RUN TestParsePathInfoJSON46=== PAUSE TestParsePathInfoJSON47=== RUN TestParsePathInfoJSONMultiplePaths48=== PAUSE TestParsePathInfoJSONMultiplePaths49=== RUN TestPathInfoCACompatibility50=== PAUSE TestPathInfoCACompatibility51=== RUN TestRateLimiterFeedback52=== PAUSE TestRateLimiterFeedback53=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess54=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess55=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer56=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer57=== RUN TestRegisterUploadedObject_OutlivesPush58=== PAUSE TestRegisterUploadedObject_OutlivesPush59=== RUN TestResolveStorePath60=== PAUSE TestResolveStorePath61=== RUN TestDoWithRetry_BodyReplayedViaGetBody62=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody63=== RUN TestRetryTimeoutOutlastsMaxRetries64=== PAUSE TestRetryTimeoutOutlastsMaxRetries65=== RUN TestDoWithRetry_FinalResponseBodyReadable66=== PAUSE TestDoWithRetry_FinalResponseBodyReadable67=== RUN TestShellSplit68=== PAUSE TestShellSplit69=== RUN TestShellSplitErrors70=== PAUSE TestShellSplitErrors71=== RUN TestStreamPushReportsEveryPath72=== PAUSE TestStreamPushReportsEveryPath73=== RUN TestStreamPushBatchesUnderLoad74=== PAUSE TestStreamPushBatchesUnderLoad75=== RUN TestStreamPushIsolatesFailures76=== PAUSE TestStreamPushIsolatesFailures77=== RUN TestStreamPushGivesUpOnDeadServer78=== PAUSE TestStreamPushGivesUpOnDeadServer79=== RUN TestStreamPushRequestLine80=== PAUSE TestStreamPushRequestLine81=== RUN TestStreamPushReportsSignatures82=== PAUSE TestStreamPushReportsSignatures83=== RUN TestStreamPushReportsSkippedPaths84=== PAUSE TestStreamPushReportsSkippedPaths85=== RUN TestClientSignaturesByStorePath86=== PAUSE TestClientSignaturesByStorePath87=== RUN TestStreamPushStopsWhenCanceled88=== PAUSE TestStreamPushStopsWhenCanceled89=== RUN TestSetClientTLS90=== PAUSE TestSetClientTLS91=== RUN TestSetClientTLSDoesNotMutateDefaultTransport92=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport93=== RUN TestSetClientTLSErrors94=== PAUSE TestSetClientTLSErrors95=== RUN TestStaticToken96=== PAUSE TestStaticToken97=== RUN TestFileTokenReadsAndCaches98=== PAUSE TestFileTokenReadsAndCaches99=== RUN TestFileTokenMissing100=== PAUSE TestFileTokenMissing101=== RUN TestFileTokenEmpty102=== PAUSE TestFileTokenEmpty103=== RUN TestScriptTokenNoExpiryRerunsEveryCall104=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall105=== RUN TestScriptTokenCachesUntilRefresh106=== PAUSE TestScriptTokenCachesUntilRefresh107=== RUN TestScriptTokenEmptyToken108=== PAUSE TestScriptTokenEmptyToken109=== RUN TestScriptTokenBadJSON110=== PAUSE TestScriptTokenBadJSON111=== RUN TestScriptTokenScriptFails112=== PAUSE TestScriptTokenScriptFails113=== RUN TestScriptTokenEmptyCommand114=== PAUSE TestScriptTokenEmptyCommand115=== RUN TestUntrustedPaths116=== PAUSE TestUntrustedPaths117=== RUN TestUntrustedPathsContentAddressed118=== PAUSE TestUntrustedPathsContentAddressed119=== RUN TestParsePathInfoUltimate120=== PAUSE TestParsePathInfoUltimate121=== CONT TestDoServerRequestAttachesToken122=== CONT TestDoWithRetry_FinalResponseBodyReadable123=== CONT TestSetClientTLSErrors124=== CONT TestStreamPushRequestLine125=== CONT TestStreamPushBatchesUnderLoad126=== CONT TestStreamPushReportsSignatures127=== CONT TestClientSignaturesByStorePath128--- PASS: TestClientSignaturesByStorePath (0.00s)129=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false130=== CONT TestStreamPushGivesUpOnDeadServer131=== CONT TestStreamPushIsolatesFailures1322026/11/10 21:15:37 ERROR Upload failed error=boom count=1133=== CONT TestUploadMultipart_PartsInParallel1342026/11/10 21:15:37 ERROR Upload failed error="connection refused" count=201352026/11/10 21:15:37 ERROR Server seems unavailable, giving up on batch untried=17136=== CONT TestEncodeNixBase321372026/11/10 21:15:37 ERROR Upload failed error="bad path" count=3138=== RUN TestEncodeNixBase32/test_string_hash1392026/11/10 21:15:37 ERROR Upload failed error=boom count=1140=== CONT TestScriptTokenBadJSON141=== CONT TestDumpPathWriterError142=== CONT TestDumpPathSingleFile143=== CONT TestDumpPathMatchesNix144=== CONT TestPartSizeForNAR145=== RUN TestPartSizeForNAR/zero_stays_at_minimum146=== CONT TestUploadMultipart_ReturnsAfterDroppedBody1472026/11/10 21:15:37 WARN Rate limiter enabled after throttle name=server-test rate=5148=== CONT TestShellSplitErrors1492026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:53421150=== CONT TestFilterOversizedClosures151=== CONT TestStreamPushReportsEveryPath152=== CONT TestShellSplit153=== CONT TestScriptTokenEmptyToken154=== CONT TestParsePathInfoUltimate155=== CONT TestScriptTokenCachesUntilRefresh156=== CONT TestUntrustedPathsContentAddressed157=== CONT TestUntrustedPaths158=== CONT TestEncodeNixBase32WithRealHash159=== CONT TestScriptTokenEmptyCommand160=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false161--- PASS: TestStreamPushReportsSignatures (0.00s)162=== CONT TestScriptTokenScriptFails163=== PAUSE TestEncodeNixBase32/test_string_hash164=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun165=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum166=== RUN TestPartSizeForNAR/small_stays_at_minimum167=== PAUSE TestPartSizeForNAR/small_stays_at_minimum168=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum169=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum170=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts171=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts172=== RUN TestPartSizeForNAR/1_TiB173=== PAUSE TestPartSizeForNAR/1_TiB174=== RUN TestPartSizeForNAR/5_TiB_S3_max_object175=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object176=== RUN TestPartSizeForNAR/capped_at_5_GiB177=== PAUSE TestPartSizeForNAR/capped_at_5_GiB1782026/11/10 21:15:37 WARN Rate limiter backed off name=server-test rate=5179=== CONT TestSetClientTLSDoesNotMutateDefaultTransport180=== RUN TestSetClientTLSErrors/missing_cert_file181=== PAUSE TestSetClientTLSErrors/missing_cert_file182=== RUN TestSetClientTLSErrors/missing_key_file183=== PAUSE TestSetClientTLSErrors/missing_key_file184=== RUN TestSetClientTLSErrors/missing_ca_file185=== PAUSE TestSetClientTLSErrors/missing_ca_file186=== RUN TestSetClientTLSErrors/invalid_ca_file187=== PAUSE TestSetClientTLSErrors/invalid_ca_file188=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica189=== CONT TestRegisterUploadedObjectReusesConnections190=== RUN TestUntrustedPaths/server_without_policy_accepts_anything191=== PAUSE TestUntrustedPaths/server_without_policy_accepts_anything192=== RUN TestUntrustedPaths/built_locally193=== PAUSE TestUntrustedPaths/built_locally194=== RUN TestUntrustedPaths/signed_by_the_server_key195=== PAUSE TestUntrustedPaths/signed_by_the_server_key196=== RUN TestUntrustedPaths/signed_by_an_upstream_key197=== PAUSE TestUntrustedPaths/signed_by_an_upstream_key198=== RUN TestFilterOversizedClosures/no_limit_keeps_everything199=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything200=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped201=== CONT TestSetClientTLS202=== RUN TestEncodeNixBase32/empty_input203=== PAUSE TestEncodeNixBase32/empty_input204--- PASS: TestStreamPushIsolatesFailures (0.00s)205--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)206--- PASS: TestShellSplitErrors (0.00s)207--- PASS: TestDoServerRequestAttachesToken (0.01s)208--- PASS: TestEncodeNixBase32WithRealHash (0.00s)209=== CONT TestFileTokenMissing210--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.00s)211=== CONT TestStaticToken212--- PASS: TestStaticToken (0.00s)213=== CONT TestRateLimiterFeedback214=== RUN TestRateLimiterFeedback/429_enables_limiter215=== PAUSE TestRateLimiterFeedback/429_enables_limiter216=== RUN TestRateLimiterFeedback/503_enables_limiter217=== PAUSE TestRateLimiterFeedback/503_enables_limiter218=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter219=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter220=== CONT TestRetryTimeoutOutlastsMaxRetries221=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true222=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true223=== CONT TestFileTokenReadsAndCaches224=== CONT TestResolveStorePath225=== CONT TestRegisterUploadedObject_OutlivesPush226=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer227=== CONT TestDoWithRetry_BodyReplayedViaGetBody228=== CONT TestCaseHackSuffix2292026/11/10 21:15:37 INFO Garbage collection started230=== CONT TestScriptTokenNoExpiryRerunsEveryCall231=== CONT TestFileTokenEmpty232=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped233=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter234=== RUN TestUntrustedPaths/unsigned_substitute235--- PASS: TestScriptTokenEmptyCommand (0.00s)236--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)237--- PASS: TestParsePathInfoUltimate (0.00s)238--- PASS: TestStreamPushReportsEveryPath (0.00s)239--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)240--- PASS: TestUntrustedPathsContentAddressed (0.00s)241--- PASS: TestFileTokenReadsAndCaches (0.00s)242--- PASS: TestFileTokenMissing (0.00s)243--- PASS: TestShellSplit (0.00s)244=== RUN TestFilterOversizedClosures/all_closures_skipped245--- PASS: TestResolveStorePath (0.00s)246=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess247--- PASS: TestFileTokenEmpty (0.00s)248=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry2492026/11/10 21:15:37 WARN Rate limiter enabled after throttle name=server-test rate=52502026/11/10 21:15:37 WARN Rate limiter enabled after throttle name=server-test rate=52512026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:534582522026/11/10 21:15:37 INFO Garbage collection started2532026/11/10 21:15:37 WARN Rate limiter backed off name=server-test rate=52542026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:534582552026/11/10 21:15:37 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=0256=== PAUSE TestUntrustedPaths/unsigned_substitute257=== RUN TestUntrustedPaths/signed_only_by_another_key258=== PAUSE TestUntrustedPaths/signed_only_by_another_key259=== RUN TestUntrustedPaths/another_key's_signature_under_the_server_key_name260=== PAUSE TestUntrustedPaths/another_key's_signature_under_the_server_key_name261=== RUN TestUntrustedPaths/server_signature_over_different_contents262=== PAUSE TestFilterOversizedClosures/all_closures_skipped263--- PASS: TestScriptTokenBadJSON (0.01s)264=== CONT TestPathInfoCACompatibility265=== CONT TestStreamPushStopsWhenCanceled266=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter267=== CONT TestParsePathInfoJSON268--- PASS: TestStreamPushStopsWhenCanceled (0.00s)269=== CONT TestParsePathInfoJSONMultiplePaths270=== CONT TestGetStorePathHash271=== RUN TestParsePathInfoJSON/Nix_format272=== RUN TestGetStorePathHash/valid_store_path273=== PAUSE TestParsePathInfoJSON/Nix_format274=== RUN TestParsePathInfoJSON/Lix_format275=== PAUSE TestParsePathInfoJSON/Lix_format276=== RUN TestParsePathInfoJSON/empty_input277=== PAUSE TestParsePathInfoJSON/empty_input278=== RUN TestParsePathInfoJSON/whitespace_only279=== PAUSE TestParsePathInfoJSON/whitespace_only280=== RUN TestParsePathInfoJSON/invalid_JSON281=== PAUSE TestParsePathInfoJSON/invalid_JSON282=== PAUSE TestGetStorePathHash/valid_store_path283=== RUN TestGetStorePathHash/basename_without_hyphen_should_error284=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error285=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error286=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error287=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error288=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error289=== CONT TestPathInfoHashCompatibility290=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)291=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)292=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon293=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon294=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI295=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI296=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths297=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths298=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths299=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths300=== RUN TestPathInfoCACompatibility/null_ca_field301=== PAUSE TestPathInfoCACompatibility/null_ca_field302=== RUN TestPathInfoCACompatibility/old_string_format_-_text303=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text304=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive305=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive306=== RUN TestPathInfoCACompatibility/new_structured_format_-_text307=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text308=== CONT TestConvertHashToNix32309=== RUN TestConvertHashToNix32/SRI_format_to_Nix32310=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32311=== RUN TestConvertHashToNix32/already_Nix32_format312=== PAUSE TestConvertHashToNix32/already_Nix32_format313=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method314=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method315=== CONT TestStreamPushReportsSkippedPaths316=== RUN TestConvertHashToNix32/invalid_format317=== PAUSE TestConvertHashToNix32/invalid_format318=== CONT TestPartSizeForNAR/zero_stays_at_minimum319=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512320=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512321--- PASS: TestStreamPushReportsSkippedPaths (0.00s)322--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)323=== CONT TestSetClientTLSErrors/missing_cert_file324=== CONT TestSetClientTLSErrors/missing_ca_file325=== CONT TestPartSizeForNAR/5_TiB_S3_max_object326=== CONT TestPartSizeForNAR/capped_at_5_GiB327=== CONT TestEncodeNixBase32/test_string_hash328=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts329=== CONT TestPartSizeForNAR/1_TiB330=== CONT TestEncodeNixBase32/empty_input331--- PASS: TestEncodeNixBase32 (0.01s)332 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)333 --- PASS: TestEncodeNixBase32/empty_input (0.00s)334=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false335=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true336=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum337=== CONT TestPartSizeForNAR/small_stays_at_minimum338--- PASS: TestPartSizeForNAR (0.00s)339 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)340 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)341 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)342 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)343 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)344 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)345 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)346=== CONT TestSetClientTLSErrors/invalid_ca_file347=== CONT TestFilterOversizedClosures/no_limit_keeps_everything348=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3492026/11/10 21:15:37 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=2000350=== CONT TestFilterOversizedClosures/all_closures_skipped3512026/11/10 21:15:37 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=50352--- PASS: TestFilterOversizedClosures (0.01s)353 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)354 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)355 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)356=== CONT TestRateLimiterFeedback/429_enables_limiter3572026/11/10 21:15:37 WARN Garbage collection finished on another replica. Its statistics are not available here358--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)359=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter3602026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:53441361--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)362=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter363=== PAUSE TestUntrustedPaths/server_signature_over_different_contents364--- PASS: TestStreamPushBatchesUnderLoad (0.01s)365 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)366 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)367=== CONT TestRateLimiterFeedback/503_enables_limiter368=== CONT TestSetClientTLSErrors/missing_key_file369=== CONT TestParsePathInfoJSON/Nix_format370=== CONT TestGetStorePathHash/valid_store_path371=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths372=== CONT TestParsePathInfoJSON/invalid_JSON373=== CONT TestParsePathInfoJSON/empty_input374=== CONT TestParsePathInfoJSON/Lix_format375=== CONT TestParsePathInfoJSON/whitespace_only376--- PASS: TestParsePathInfoJSON (0.00s)377 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)378 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)379 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)380 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)381 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)382=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths383--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)384 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)385 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)386=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error387=== CONT TestPathInfoCACompatibility/null_ca_field388=== CONT TestGetStorePathHash/basename_without_hyphen_should_error389=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method390=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error391=== CONT TestPathInfoCACompatibility/old_string_format_-_text392--- PASS: TestGetStorePathHash (0.00s)393 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)394 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)395 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)396 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)397=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive398=== CONT TestConvertHashToNix32/SRI_format_to_Nix32399--- PASS: TestRegisterUploadedObject_OutlivesPush (0.01s)400=== CONT TestConvertHashToNix32/already_Nix32_format401=== CONT TestPathInfoCACompatibility/new_structured_format_-_text402--- PASS: TestPathInfoCACompatibility (0.00s)403 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)404 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)405 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)406 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)407 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)408=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)409=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512410=== CONT TestUntrustedPaths/server_without_policy_accepts_anything411=== CONT TestConvertHashToNix32/invalid_format412--- PASS: TestConvertHashToNix32 (0.00s)413 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)414 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)415 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)416=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI417=== CONT TestUntrustedPaths/signed_only_by_another_key418=== CONT TestUntrustedPaths/unsigned_substitute419=== CONT TestUntrustedPaths/signed_by_an_upstream_key420=== CONT TestUntrustedPaths/signed_by_the_server_key4212026/11/10 21:15:37 WARN Rate limiter enabled after throttle name=server-test rate=54222026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:53514423=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon424--- PASS: TestPathInfoHashCompatibility (0.00s)425 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)426 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)427 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)428 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)429=== CONT TestUntrustedPaths/server_signature_over_different_contents430=== CONT TestUntrustedPaths/another_key's_signature_under_the_server_key_name431=== CONT TestUntrustedPaths/built_locally432--- PASS: TestUntrustedPaths (0.01s)433 --- PASS: TestUntrustedPaths/server_without_policy_accepts_anything (0.00s)434 --- PASS: TestUntrustedPaths/unsigned_substitute (0.00s)435 --- PASS: TestUntrustedPaths/signed_only_by_another_key (0.00s)436 --- PASS: TestUntrustedPaths/signed_by_the_server_key (0.00s)437 --- PASS: TestUntrustedPaths/signed_by_an_upstream_key (0.00s)438 --- PASS: TestUntrustedPaths/server_signature_over_different_contents (0.00s)439 --- PASS: TestUntrustedPaths/built_locally (0.00s)440 --- PASS: TestUntrustedPaths/another_key's_signature_under_the_server_key_name (0.00s)4412026/11/10 21:15:37 WARN Rate limiter enabled after throttle name=server-test rate=54422026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:535074432026/11/10 21:15:37 WARN Rate limiter backed off name=server-test rate=54442026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:53441445--- PASS: TestSetClientTLSErrors (0.01s)446 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)447 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)448 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)449 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)4502026/11/10 21:15:37 WARN Rate limiter backed off name=server-test rate=5451--- PASS: TestRateLimiterFeedback (0.01s)452 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)453 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)454 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)455 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)4562026/11/10 21:15:37 WARN Rate limiter enabled after throttle name=s3-test rate=54572026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:535204582026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:53441459--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.01s)460=== RUN TestSetClientTLS/rejects_connection_without_client_cert461=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert462=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA463=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA464=== RUN TestSetClientTLS/preserves_debug_logging_transport465=== PAUSE TestSetClientTLS/preserves_debug_logging_transport466=== CONT TestSetClientTLS/rejects_connection_without_client_cert467=== CONT TestSetClientTLS/preserves_debug_logging_transport468=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA4692026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:53441470--- PASS: TestStreamPushRequestLine (0.03s)4712026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:53441472--- PASS: TestScriptTokenScriptFails (0.02s)4732026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:534414742026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:534414752026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:534414762026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:53441477--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)4782026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:53441479--- PASS: TestScriptTokenEmptyToken (0.04s)4802026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:534414812026/11/10 21:15:37 http: TLS handshake error from 127.0.0.1:53523: remote error: tls: bad certificate4822026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:53441483--- PASS: TestSetClientTLS (0.02s)484 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)485 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)486 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)4872026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:534414882026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:534414892026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:534414902026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:53441491--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)4922026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:534414932026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:53441494--- PASS: TestDumpPathWriterError (0.06s)495--- PASS: TestDumpPathSingleFile (0.06s)4962026/11/10 21:15:37 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:53441497--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.05s)498--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)499--- PASS: TestCaseHackSuffix (0.06s)500--- PASS: TestDumpPathMatchesNix (0.09s)5012026/11/10 21:15:37 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:53456/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:53456/api/uploads/complete5022026/11/10 21:15:37 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"5032026/11/10 21:15:37 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:53456/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:53456/api/uploads/complete5042026/11/10 21:15:37 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"5052026/11/10 21:15:37 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:53456/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:53456/api/uploads/complete5062026/11/10 21:15:37 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"507--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (0.10s)508--- PASS: TestUploadMultipart_PartsInParallel (0.62s)509--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)510PASS511Running server tests...512The files belonging to this database system will be owned by user "_tribuchetbld4".513This user must also own the server process.514515The database cluster will be initialized with locale "C".516The default database encoding has accordingly been set to "SQL_ASCII".517The default text search configuration will be set to "english".518519Data page checksums are enabled.520521creating directory /private/var/tb/4/scratch/b3a0d46031104912/build/postgres3961358236/data ... ok522creating subdirectories ... ok523selecting dynamic shared memory implementation ... posix524selecting default "max_connections" ... 100525selecting default "shared_buffers" ... 128MB526selecting default time zone ... UTC527creating configuration files ... ok528running bootstrap script ... ok529performing post-bootstrap initialization ... ok530syncing data to disk ... ok531532initdb: warning: enabling "trust" authentication for local connections533initdb: 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.534535Success. You can now start the database server using:536537 pg_ctl -D /private/var/tb/4/scratch/b3a0d46031104912/build/postgres3961358236/data -l logfile start538539/private/var/tb/4/scratch/b3a0d46031104912/build/postgres3961358236:5432 - no response5402026-11-10 21:15:39.546 UTC [97797] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5412026-11-10 21:15:39.546 UTC [97797] LOG: listening on Unix socket "/private/var/tb/4/scratch/b3a0d46031104912/build/postgres3961358236/.s.PGSQL.5432"5422026-11-10 21:15:39.548 UTC [97804] LOG: database system was shut down at 2026-11-10 21:15:39 UTC5432026-11-10 21:15:39.549 UTC [97797] LOG: database system is ready to accept connections544/private/var/tb/4/scratch/b3a0d46031104912/build/postgres3961358236:5432 - accepting connections545{"timestamp":"2026-11-10T21:15:39.762993Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"c00e535f-0248-43d2-87a1-661ca63b6b3d","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":502,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}546=== RUN TestAbortSucceeded547=== PAUSE TestAbortSucceeded548=== RUN TestService_AuthMiddleware549=== PAUSE TestService_AuthMiddleware550=== RUN TestService_AuthMiddleware_MTLSProxyHeader551=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader552=== RUN TestService_AuthMiddleware_MTLSBoundSubjects553=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects554=== RUN TestService_ReadAuthMiddleware555=== PAUSE TestService_ReadAuthMiddleware556=== RUN TestService_AuthMiddleware_OIDC557=== PAUSE TestService_AuthMiddleware_OIDC558=== RUN TestService_RequireScope_OIDC559=== PAUSE TestService_RequireScope_OIDC560=== RUN TestService_ReadScope_PublicByDefault561=== PAUSE TestService_ReadScope_PublicByDefault562=== RUN TestCacheConfigHandler563=== PAUSE TestCacheConfigHandler564=== RUN TestCacheStatsHandler565=== PAUSE TestCacheStatsHandler566=== RUN TestClientCADerivations567=== PAUSE TestClientCADerivations568=== RUN TestClientErrorHandling569=== PAUSE TestClientErrorHandling570=== RUN TestClientIntegration571=== PAUSE TestClientIntegration572=== RUN TestClientMultipleUploads573=== PAUSE TestClientMultipleUploads574=== RUN TestClientWithDependencies575=== PAUSE TestClientWithDependencies576=== RUN TestClientSharedPathCommittedMidPush577=== PAUSE TestClientSharedPathCommittedMidPush578=== RUN TestPinProtectsFromGC579=== PAUSE TestPinProtectsFromGC580=== RUN TestClientPushesUseOnePush581=== PAUSE TestClientPushesUseOnePush582=== RUN TestClientFallsBackToClosures583=== PAUSE TestClientFallsBackToClosures584=== RUN TestDeleteClosuresRacingPins585=== PAUSE TestDeleteClosuresRacingPins586=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock587=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock588=== RUN TestResolveDBConnectionString589=== PAUSE TestResolveDBConnectionString590=== RUN TestConnectWaitsForAPeerMigration591=== PAUSE TestConnectWaitsForAPeerMigration592=== RUN TestLeadElectsOneAndHandsOver593=== PAUSE TestLeadElectsOneAndHandsOver594=== RUN TestLeadIncumbentWinsAfterRestart5952026/11/10 21:15:40 INFO lead: acquired remote=192.0.2.1:12345962026/11/10 21:15:40 INFO lead: released remote=192.0.2.1:12345972026/11/10 21:15:40 INFO lead: acquired remote=192.0.2.1:12345982026/11/10 21:15:41 INFO lead: released remote=192.0.2.1:1234599--- PASS: TestLeadIncumbentWinsAfterRestart (1.99s)600=== RUN TestLeadIncumbentAnnouncesAtOnce601=== PAUSE TestLeadIncumbentAnnouncesAtOnce602=== RUN TestLeadEndsOnShutdown603=== PAUSE TestLeadEndsOnShutdown604=== RUN TestLeadEndsWhenItsConnectionHangs6052026/11/10 21:15:42 INFO lead: acquired remote=192.0.2.1:12346062026-11-10 21:15:43.220 UTC [97850] FATAL: terminating connection due to administrator command6072026/11/10 21:15:43 INFO lead: acquired remote=192.0.2.1:12346082026/11/10 21:15:44 WARN lead: lock connection lost error="timeout: context deadline exceeded"6092026/11/10 21:15:44 INFO lead: released remote=192.0.2.1:12346102026/11/10 21:15:44 INFO lead: released remote=192.0.2.1:1234611--- PASS: TestLeadEndsWhenItsConnectionHangs (2.75s)612=== RUN TestGCAdvisoryLockBlocksConcurrentRun613=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun614=== RUN TestGCBugBareHashReferences615=== PAUSE TestGCBugBareHashReferences616=== RUN TestGCMetrics617=== PAUSE TestGCMetrics618=== RUN TestPushDedupSurvivesConcurrentGC619=== PAUSE TestPushDedupSurvivesConcurrentGC620=== RUN TestDeduplicatedObjectsRecordedAsPending621=== PAUSE TestDeduplicatedObjectsRecordedAsPending622=== RUN TestGCSweepSkipsPendingObjects623=== PAUSE TestGCSweepSkipsPendingObjects624=== RUN TestTombstonedObjectOfferedWithoutWaiting625=== PAUSE TestTombstonedObjectOfferedWithoutWaiting626=== RUN TestGCSweepDeliversEachKeyOnce627=== PAUSE TestGCSweepDeliversEachKeyOnce628=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection629=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection630=== RUN TestForceGCDuringPushOffersSweptObject631=== PAUSE TestForceGCDuringPushOffersSweptObject632=== RUN TestFailedS3DeleteKeepsTombstone633=== PAUSE TestFailedS3DeleteKeepsTombstone634=== RUN TestSweepSkipsRowsLockedByPush635=== PAUSE TestSweepSkipsRowsLockedByPush636=== RUN TestRegisterCompletedObjectNeedsPendingRow637=== PAUSE TestRegisterCompletedObjectNeedsPendingRow638=== RUN TestGetExistingObjectsLocksRows639=== PAUSE TestGetExistingObjectsLocksRows640=== RUN TestSweepRechecksPendingAfterLocking641=== PAUSE TestSweepRechecksPendingAfterLocking642=== RUN TestPushWaitsForSweepHoldingRow643=== PAUSE TestPushWaitsForSweepHoldingRow644=== RUN TestCommitRacingPendingCleanupKeepsObjects645=== PAUSE TestCommitRacingPendingCleanupKeepsObjects646=== RUN TestGCEndsOnShutdown647=== PAUSE TestGCEndsOnShutdown648=== RUN TestGCTaskStore_StartNew649=== PAUSE TestGCTaskStore_StartNew650=== RUN TestGCTaskStore_DeduplicateSameParams651=== PAUSE TestGCTaskStore_DeduplicateSameParams652=== RUN TestGCTaskStore_ConflictDifferentParams653=== PAUSE TestGCTaskStore_ConflictDifferentParams654=== RUN TestGCTaskStore_GetEmpty655=== PAUSE TestGCTaskStore_GetEmpty656=== RUN TestGCTaskStore_GetReturnsLatest657=== PAUSE TestGCTaskStore_GetReturnsLatest658=== RUN TestGCTaskStore_CompletedAllowsNewTask659=== PAUSE TestGCTaskStore_CompletedAllowsNewTask660=== RUN TestGCTaskStore_PhaseUpdates661=== PAUSE TestGCTaskStore_PhaseUpdates662=== RUN TestGCTaskStore_Fail663=== PAUSE TestGCTaskStore_Fail664=== RUN TestGracefulShutdownDrainsInflight665=== PAUSE TestGracefulShutdownDrainsInflight666=== RUN TestService_healthCheckHandler667=== PAUSE TestService_healthCheckHandler668=== RUN TestService_readinessHandler669=== PAUSE TestService_readinessHandler670=== RUN TestGenerateLandingPage671=== PAUSE TestGenerateLandingPage672=== RUN TestEnsureAbortUploadsRule673=== PAUSE TestEnsureAbortUploadsRule674=== RUN TestCacheConfigHandlerMaxNarSize675=== PAUSE TestCacheConfigHandlerMaxNarSize676=== RUN TestCreatePendingClosureRejectsOversizedNAR677=== PAUSE TestCreatePendingClosureRejectsOversizedNAR678=== RUN TestNARDeduplicationMetadataUploadBug679=== PAUSE TestNARDeduplicationMetadataUploadBug680=== RUN TestMetricsInventory681=== PAUSE TestMetricsInventory682=== RUN TestMetricsCommit683=== PAUSE TestMetricsCommit684=== RUN TestService_NativeMTLS685=== PAUSE TestService_NativeMTLS686=== RUN TestServerTLSConfig687=== PAUSE TestServerTLSConfig688=== RUN TestMultipartCleanup689=== PAUSE TestMultipartCleanup690=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded691=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded692=== RUN TestPendingCleanupUsesOneCutoff693=== PAUSE TestPendingCleanupUsesOneCutoff694=== RUN TestObjectStatsTrigger695=== PAUSE TestObjectStatsTrigger696=== RUN TestObjectStatsUpdatedOncePerCommit697=== PAUSE TestObjectStatsUpdatedOncePerCommit698=== RUN TestOrphanedObjectsGC699=== PAUSE TestOrphanedObjectsGC700=== RUN TestOrphanedObjectsGCStressTest701=== PAUSE TestOrphanedObjectsGCStressTest702=== RUN TestCreatePin_ReservedPins703=== PAUSE TestCreatePin_ReservedPins704=== RUN TestPresentReportsOnlyClosureRoots705=== PAUSE TestPresentReportsOnlyClosureRoots706=== RUN TestPresentRefreshesOnlyStaleClosures707=== PAUSE TestPresentRefreshesOnlyStaleClosures708=== RUN TestPresentNotReportedWhileGCDeletesClosure709=== PAUSE TestPresentNotReportedWhileGCDeletesClosure710=== RUN TestParseSingleRange711=== PAUSE TestParseSingleRange712=== RUN TestProxyHeadersOnlyTrustedOnSocket7132026/11/10 21:15:44 INFO Starting HTTP server address=127.0.0.1:535487142026/11/10 21:15:44 INFO Starting HTTP server address=proxy.sock7152026/11/10 21:15:44 WARN mTLS auth: subject not in bound subjects subject="CN=someone"7162026/11/10 21:15:44 INFO Shutdown signal received, draining in-flight requests timeout=10s717--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.17s)718=== RUN TestIsValidCachePath719=== PAUSE TestIsValidCachePath720=== RUN TestReadProxyNarinfo721=== PAUSE TestReadProxyNarinfo722=== RUN TestReadProxyNarinfoAlreadyDecompressed723=== PAUSE TestReadProxyNarinfoAlreadyDecompressed724=== RUN TestReadProxyContentNegotiation725=== PAUSE TestReadProxyContentNegotiation726=== RUN TestReadProxyNarStreaming727=== PAUSE TestReadProxyNarStreaming728=== RUN TestReadProxy404729=== PAUSE TestReadProxy404730=== RUN TestReadProxyInvalidPath731=== PAUSE TestReadProxyInvalidPath732=== RUN TestReadProxyHead733=== PAUSE TestReadProxyHead734=== RUN TestReadProxyOutlastsServerWriteTimeout735=== PAUSE TestReadProxyOutlastsServerWriteTimeout736=== RUN TestReadProxyConditionalGet737=== PAUSE TestReadProxyConditionalGet738=== RUN TestReadProxyRootRedirectsToIndexHTML739=== PAUSE TestReadProxyRootRedirectsToIndexHTML740=== RUN TestReadProxyDisabled741=== PAUSE TestReadProxyDisabled742=== RUN TestReadRedirectNar743=== PAUSE TestReadRedirectNar744=== RUN TestReadRedirectKeepsNarinfoProxied745=== PAUSE TestReadRedirectKeepsNarinfoProxied746=== RUN TestReadProxyRangeRequest747=== PAUSE TestReadProxyRangeRequest748=== RUN TestReadRedirectUsesPublicS3URL749=== PAUSE TestReadRedirectUsesPublicS3URL750=== RUN TestPush_OverlappingRootsStoreOneRowPerKey751=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey752=== RUN TestPush_CompleteCommitsEveryRoot753=== PAUSE TestPush_CompleteCommitsEveryRoot754=== RUN TestPush_RepeatedRootCommitsOnce755=== PAUSE TestPush_RepeatedRootCommitsOnce756=== RUN TestPush_CompleteWaitsForCleanupOfThePush757=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush758=== RUN TestPush_RootsAreLockedInByteOrder759=== PAUSE TestPush_RootsAreLockedInByteOrder760=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit761=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit762=== RUN TestPush_RejectsBadRequests763=== PAUSE TestPush_RejectsBadRequests764=== RUN TestPush_SignsNarinfosOfItsPendingObjects765=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects766=== RUN TestSharedNarBothUploadsComplete767=== PAUSE TestSharedNarBothUploadsComplete768=== RUN TestCompleteMultipartUpload_ErrorButObjectExists769=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists770=== RUN TestCompletedNarNotReofferedAcrossClosures771=== PAUSE TestCompletedNarNotReofferedAcrossClosures772=== RUN TestPresignedUploadRegisteredBeforeCommit773=== PAUSE TestPresignedUploadRegisteredBeforeCommit774=== RUN TestService_Rustfstest775=== PAUSE TestService_Rustfstest776=== RUN TestParseSize777=== PAUSE TestParseSize778=== RUN TestSkippedUploadsHandler779=== PAUSE TestSkippedUploadsHandler780=== RUN TestSystemdListenerNotActivated781--- PASS: TestSystemdListenerNotActivated (0.00s)782=== RUN TestWatchdogBeatsWhenHealthy783--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)784=== RUN TestWatchdogSkipsWhenUnhealthy7852026/11/10 21:15:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7862026/11/10 21:15:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7872026/11/10 21:15:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7882026/11/10 21:15:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7892026/11/10 21:15:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7902026/11/10 21:15:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7912026/11/10 21:15:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7922026/11/10 21:15:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7932026/11/10 21:15:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7942026/11/10 21:15:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"795--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)796=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle797=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle798=== RUN TestProxyWriteTimeout799=== PAUSE TestProxyWriteTimeout800=== RUN TestPendingClosureWriteTimeout801=== PAUSE TestPendingClosureWriteTimeout802=== RUN TestIsValidUploadKey803=== PAUSE TestIsValidUploadKey804=== RUN TestUploadHandlersRejectInvalidKeys805=== PAUSE TestUploadHandlersRejectInvalidKeys806=== RUN TestUploadHandlersRejectOversizedBody807=== PAUSE TestUploadHandlersRejectOversizedBody808=== RUN TestService_cleanupPendingClosuresHandler809=== PAUSE TestService_cleanupPendingClosuresHandler810=== RUN TestService_createPendingClosureHandler811=== PAUSE TestService_createPendingClosureHandler812=== RUN TestService_verifyS3Integrity813=== PAUSE TestService_verifyS3Integrity814=== RUN TestService_verifyS3ReuploadsStaleNarinfo815=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo816=== RUN TestCompleteMultipartUnregistered817=== PAUSE TestCompleteMultipartUnregistered818=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT819=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT820=== CONT TestPush_CompleteCommitsEveryRoot821=== CONT TestReadProxyInvalidPath822=== CONT TestAbortSucceeded823--- PASS: TestAbortSucceeded (0.00s)824=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT825=== CONT TestPush_OverlappingRootsStoreOneRowPerKey826=== CONT TestReadRedirectUsesPublicS3URL827=== CONT TestReadProxyRangeRequest828=== CONT TestReadRedirectKeepsNarinfoProxied829=== CONT TestReadRedirectNar830=== CONT TestReadProxyDisabled831=== CONT TestReadProxyRootRedirectsToIndexHTML832=== CONT TestReadProxyConditionalGet833=== CONT TestReadProxyOutlastsServerWriteTimeout834=== CONT TestSkippedUploadsHandler835=== CONT TestReadProxyHead836=== CONT TestCompleteMultipartUnregistered837=== CONT TestService_verifyS3ReuploadsStaleNarinfo838=== CONT TestService_verifyS3Integrity839=== CONT TestService_createPendingClosureHandler840=== CONT TestService_cleanupPendingClosuresHandler841=== CONT TestUploadHandlersRejectOversizedBody842=== CONT TestUploadHandlersRejectInvalidKeys843=== CONT TestIsValidUploadKey844=== CONT TestPendingClosureWriteTimeout8452026/11/10 21:15:45 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000846=== CONT TestProxyWriteTimeout847=== RUN TestIsValidUploadKey/narinfo848=== PAUSE TestIsValidUploadKey/narinfo849=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed850=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info851=== RUN TestPendingClosureWriteTimeout/empty852=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info853=== PAUSE TestPendingClosureWriteTimeout/empty854=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal855=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal856=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key857=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key858=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key859=== RUN TestPendingClosureWriteTimeout/400_objects860=== RUN TestProxyWriteTimeout/narinfo861=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed862=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed863=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key864=== RUN TestIsValidUploadKey/nar_zst865=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle866=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed867=== PAUSE TestPendingClosureWriteTimeout/400_objects868=== PAUSE TestProxyWriteTimeout/narinfo869=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost870=== RUN TestProxyWriteTimeout/1_GiB_nar871=== PAUSE TestIsValidUploadKey/nar_zst872=== RUN TestIsValidUploadKey/nar_xz873=== RUN TestPendingClosureWriteTimeout/670k_objects874--- PASS: TestSkippedUploadsHandler (0.01s)875=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost876=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed877=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed878=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed879=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed880=== PAUSE TestProxyWriteTimeout/1_GiB_nar881=== RUN TestProxyWriteTimeout/10_GiB_nar882=== PAUSE TestProxyWriteTimeout/10_GiB_nar883=== RUN TestProxyWriteTimeout/unknown_size884=== PAUSE TestProxyWriteTimeout/unknown_size885=== CONT TestParseSize886--- PASS: TestParseSize (0.00s)887=== CONT TestPresignedUploadRegisteredBeforeCommit888=== PAUSE TestIsValidUploadKey/nar_xz889=== PAUSE TestPendingClosureWriteTimeout/670k_objects890=== RUN TestIsValidUploadKey/nar_plain891=== CONT TestSharedNarBothUploadsComplete892=== PAUSE TestIsValidUploadKey/nar_plain893=== CONT TestService_Rustfstest894=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline895=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline896=== RUN TestIsValidUploadKey/listing897=== PAUSE TestIsValidUploadKey/listing898=== RUN TestIsValidUploadKey/build_log899=== PAUSE TestIsValidUploadKey/build_log900=== RUN TestIsValidUploadKey/build_log_home-manager_file901=== PAUSE TestIsValidUploadKey/build_log_home-manager_file902=== RUN TestIsValidUploadKey/build_log_plus_in_name903=== PAUSE TestIsValidUploadKey/build_log_plus_in_name904=== RUN TestIsValidUploadKey/build_log_question_mark905=== PAUSE TestIsValidUploadKey/build_log_question_mark906=== RUN TestIsValidUploadKey/build_log_equals907=== PAUSE TestIsValidUploadKey/build_log_equals908=== RUN TestIsValidUploadKey/realisation909=== PAUSE TestIsValidUploadKey/realisation910=== RUN TestIsValidUploadKey/realisation_plus_in_output911=== PAUSE TestIsValidUploadKey/realisation_plus_in_output912=== RUN TestIsValidUploadKey/nix-cache-info913=== PAUSE TestIsValidUploadKey/nix-cache-info914=== RUN TestIsValidUploadKey/index.html915=== PAUSE TestIsValidUploadKey/index.html916=== RUN TestIsValidUploadKey/narinfo_key,_nar_type917=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type918=== RUN TestIsValidUploadKey/nar_key,_narinfo_type919=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type920=== RUN TestIsValidUploadKey/listing_key,_narinfo_type921=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type922=== RUN TestIsValidUploadKey/traversal923=== PAUSE TestIsValidUploadKey/traversal924=== RUN TestIsValidUploadKey/traversal_nar925=== PAUSE TestIsValidUploadKey/traversal_nar926=== RUN TestIsValidUploadKey/absolute927=== PAUSE TestIsValidUploadKey/absolute928=== RUN TestIsValidUploadKey/empty_key929=== PAUSE TestIsValidUploadKey/empty_key930=== RUN TestIsValidUploadKey/unknown_type931=== PAUSE TestIsValidUploadKey/unknown_type932=== CONT TestCompletedNarNotReofferedAcrossClosures933=== CONT TestCompleteMultipartUpload_ErrorButObjectExists934=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure935=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure936=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart937=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart938=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts939=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts940=== CONT TestPush_SignsNarinfosOfItsPendingObjects9412026/11/10 21:15:45 INFO Received push request method=POST path=/api/pushes9422026/11/10 21:15:45 INFO Received complete push request method=POST path=/api/pushes/1/complete9432026/11/10 21:15:46 INFO Completed push id=1 objects=6 duration=55.07175ms944--- PASS: TestPush_CompleteCommitsEveryRoot (0.99s)945=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit9462026/11/10 21:15:46 INFO Received uploads request method=POST path=/api/pending_closures947--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.22s)948=== CONT TestPush_CompleteWaitsForCleanupOfThePush949--- PASS: TestReadProxyInvalidPath (1.32s)950=== CONT TestPush_RejectsBadRequests951--- PASS: TestReadProxyRangeRequest (1.62s)952=== CONT TestPush_RootsAreLockedInByteOrder953--- PASS: TestReadRedirectUsesPublicS3URL (1.98s)954=== CONT TestPush_RepeatedRootCommitsOnce9552026/11/10 21:15:47 INFO Received push request method=POST path=/api/pushes956--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (2.36s)957=== CONT TestPushWaitsForSweepHoldingRow958--- PASS: TestReadRedirectKeepsNarinfoProxied (2.53s)959=== CONT TestReadProxy404960--- PASS: TestReadProxyDisabled (2.67s)961=== CONT TestReadProxyNarStreaming962--- PASS: TestReadProxyHead (2.89s)963=== CONT TestReadProxyContentNegotiation964--- PASS: TestReadRedirectNar (3.12s)965=== CONT TestReadProxyNarinfoAlreadyDecompressed9662026/11/10 21:15:48 INFO Received uploads request method=POST path=/api/pending_closures9672026/11/10 21:15:48 INFO Received uploads request method=POST path=/api/pending_closures9682026/11/10 21:15:48 INFO Received uploads request method=POST path=/api/pending_closures9692026/11/10 21:15:48 INFO Received uploads request method=POST path=/api/pending_closures9702026/11/10 21:15:48 INFO Received cleanup request method=DELETE path=/api/pending_closures9712026/11/10 21:15:48 INFO Aborted multipart uploads count=0 kept=09722026/11/10 21:15:48 INFO Received uploads request method=POST path=/api/pending_closures9732026/11/10 21:15:48 INFO Received cleanup request method=DELETE path=/api/pending_closures9742026/11/10 21:15:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9752026/11/10 21:15:48 INFO Aborted multipart uploads count=1 kept=09762026/11/10 21:15:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9772026-11-10 21:15:48.936 UTC [97977] ERROR: Closure does not exist: id=19782026-11-10 21:15:48.936 UTC [97977] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9792026-11-10 21:15:48.936 UTC [97977] STATEMENT: -- name: CommitPendingClosure :one980 SELECT commit_pending_closure($1::bigint)::bigint981 982--- PASS: TestService_cleanupPendingClosuresHandler (3.89s)983=== CONT TestReadProxyNarinfo9842026/11/10 21:15:49 INFO Received uploads request method=POST path=/api/pending_closures9852026/11/10 21:15:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete986--- PASS: TestReadProxyConditionalGet (4.65s)987=== CONT TestIsValidCachePath988=== RUN TestIsValidCachePath/narinfo989=== PAUSE TestIsValidCachePath/narinfo990=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars991=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars992=== RUN TestIsValidCachePath/nar_zst993=== PAUSE TestIsValidCachePath/nar_zst994=== RUN TestIsValidCachePath/nar_xz995=== PAUSE TestIsValidCachePath/nar_xz996=== RUN TestIsValidCachePath/nar_bz2997=== PAUSE TestIsValidCachePath/nar_bz2998=== RUN TestIsValidCachePath/nar_uncompressed999=== PAUSE TestIsValidCachePath/nar_uncompressed1000=== RUN TestIsValidCachePath/ls1001=== PAUSE TestIsValidCachePath/ls1002=== RUN TestIsValidCachePath/log1003=== PAUSE TestIsValidCachePath/log1004=== RUN TestIsValidCachePath/realisation1005=== PAUSE TestIsValidCachePath/realisation1006=== RUN TestIsValidCachePath/nix-cache-info1007=== PAUSE TestIsValidCachePath/nix-cache-info1008=== RUN TestIsValidCachePath/index.html1009=== PAUSE TestIsValidCachePath/index.html1010=== RUN TestIsValidCachePath/traversal_parent1011=== PAUSE TestIsValidCachePath/traversal_parent1012=== RUN TestIsValidCachePath/traversal_in_middle1013=== PAUSE TestIsValidCachePath/traversal_in_middle1014=== RUN TestIsValidCachePath/invalid_char_e1015=== PAUSE TestIsValidCachePath/invalid_char_e1016=== RUN TestIsValidCachePath/invalid_char_u1017=== PAUSE TestIsValidCachePath/invalid_char_u1018=== RUN TestIsValidCachePath/random_path1019=== PAUSE TestIsValidCachePath/random_path1020=== RUN TestIsValidCachePath/empty1021=== PAUSE TestIsValidCachePath/empty1022=== RUN TestIsValidCachePath/leading_slash1023=== PAUSE TestIsValidCachePath/leading_slash1024=== RUN TestIsValidCachePath/wrong_extension1025=== PAUSE TestIsValidCachePath/wrong_extension1026=== RUN TestIsValidCachePath/short_hash1027=== PAUSE TestIsValidCachePath/short_hash1028=== CONT TestParseSingleRange1029=== RUN TestParseSingleRange/none1030=== PAUSE TestParseSingleRange/none1031=== RUN TestParseSingleRange/unknown_unit1032=== PAUSE TestParseSingleRange/unknown_unit1033=== RUN TestParseSingleRange/multi-range_ignored1034=== PAUSE TestParseSingleRange/multi-range_ignored1035=== RUN TestParseSingleRange/malformed_no_dash1036=== PAUSE TestParseSingleRange/malformed_no_dash1037=== RUN TestParseSingleRange/malformed_both_empty1038=== PAUSE TestParseSingleRange/malformed_both_empty1039=== RUN TestParseSingleRange/malformed_end_before_start1040=== PAUSE TestParseSingleRange/malformed_end_before_start1041=== RUN TestParseSingleRange/closed1042=== PAUSE TestParseSingleRange/closed1043=== RUN TestParseSingleRange/open-ended1044=== PAUSE TestParseSingleRange/open-ended1045=== RUN TestParseSingleRange/end_clamped_to_size1046=== PAUSE TestParseSingleRange/end_clamped_to_size1047=== RUN TestParseSingleRange/suffix1048=== PAUSE TestParseSingleRange/suffix1049=== RUN TestParseSingleRange/suffix_exceeds_size1050=== PAUSE TestParseSingleRange/suffix_exceeds_size1051=== RUN TestParseSingleRange/single_byte1052=== PAUSE TestParseSingleRange/single_byte1053=== RUN TestParseSingleRange/start_past_EOF1054=== PAUSE TestParseSingleRange/start_past_EOF1055=== RUN TestParseSingleRange/start_far_past_EOF1056=== PAUSE TestParseSingleRange/start_far_past_EOF1057=== CONT TestPresentNotReportedWhileGCDeletesClosure1058=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1059=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1060=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1061=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1062=== CONT TestPresentRefreshesOnlyStaleClosures10632026/11/10 21:15:49 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NGI2NDRjOTMtM2QxNC00MjNmLTg5MDItMTI3MTM4ZWFjM2ZjLmEzMTIyZTE3LTU1MTMtNDVlMi1iNWM4LWU0MmE1ZGNjYTRlOHgxNzk0MzQ1MzQ4MzMzMjg2MDAw parts=1010642026/11/10 21:15:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10652026/11/10 21:15:49 INFO Completed upload id=1 objects=2 duration=10.257458ms10662026/11/10 21:15:49 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010672026/11/10 21:15:49 INFO Received uploads request method=POST path=/api/pending_closures10682026/11/10 21:15:49 INFO Starting cleanup of old closures method=DELETE path=/api/closures10692026/11/10 21:15:49 INFO Aborted multipart uploads count=0 kept=010702026/11/10 21:15:49 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=010712026/11/10 21:15:49 INFO Vacuumed table table=pending_closures10722026/11/10 21:15:49 INFO Vacuumed table table=pending_objects10732026/11/10 21:15:49 INFO Vacuumed table table=multipart_uploads10742026/11/10 21:15:49 INFO Vacuumed table table=closures10752026/11/10 21:15:49 INFO Vacuumed table table=objects10762026/11/10 21:15:49 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001077--- PASS: TestService_createPendingClosureHandler (4.90s)1078=== CONT TestPresentReportsOnlyClosureRoots1079--- PASS: TestReadProxyRootRedirectsToIndexHTML (4.92s)1080=== CONT TestResolveDBConnectionString1081=== RUN TestResolveDBConnectionString/flag_wins1082=== PAUSE TestResolveDBConnectionString/flag_wins1083=== RUN TestResolveDBConnectionString/file_when_flag_empty1084=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1085=== RUN TestResolveDBConnectionString/missing_file_is_an_error1086=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1087=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1088=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1089=== RUN TestResolveDBConnectionString/nothing_configured1090=== PAUSE TestResolveDBConnectionString/nothing_configured1091=== CONT TestDeduplicatedObjectsRecordedAsPending10922026/11/10 21:15:50 INFO Received uploads request method=POST path=/api/pending_closures1093--- PASS: TestService_Rustfstest (5.32s)1094=== CONT TestCreatePin_ReservedPins10952026/11/10 21:15:50 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53633/oidc10962026/11/10 21:15:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10972026/11/10 21:15:50 INFO Received uploads request method=POST path=/api/pending_closures10982026/11/10 21:15:50 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NGI2NDRjOTMtM2QxNC00MjNmLTg5MDItMTI3MTM4ZWFjM2ZjLjQ2ZjRjNTBkLWVhNzEtNDQ4OS1hNDg0LTk5N2E0ZWRjMTc5MngxNzk0MzQ1MzQ5Mzg5NTE2MDAw parts=1010992026/11/10 21:15:50 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11002026/11/10 21:15:50 INFO Completed upload id=1 objects=2 duration=25.602791ms11012026/11/10 21:15:50 INFO Received uploads request method=POST path=/api/pending_closures11022026/11/10 21:15:50 INFO Received uploads request method=POST path=/api/pending_closures11032026/11/10 21:15:50 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo11042026/11/10 21:15:50 WARN Found objects in DB but missing from S3, will re-upload count=11105--- PASS: TestService_verifyS3Integrity (5.76s)1106=== CONT TestPushDedupSurvivesConcurrentGC11072026/11/10 21:15:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11082026/11/10 21:15:50 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NGI2NDRjOTMtM2QxNC00MjNmLTg5MDItMTI3MTM4ZWFjM2ZjLmY3ZGYwYjViLWZiODItNDlhYy04NDA4LTBkNjhmN2Q4ZGUzMngxNzk0MzQ1MzUwNzI1MDc4MDAw11092026/11/10 21:15:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11102026/11/10 21:15:50 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1111--- PASS: TestCompleteMultipartUnregistered (5.95s)11122026/11/10 21:15:50 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NGI2NDRjOTMtM2QxNC00MjNmLTg5MDItMTI3MTM4ZWFjM2ZjLmY3ZGYwYjViLWZiODItNDlhYy04NDA4LTBkNjhmN2Q4ZGUzMngxNzk0MzQ1MzUwNzI1MDc4MDAw parts=11113=== CONT TestOrphanedObjectsGCStressTest1114--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (5.90s)1115=== CONT TestGCMetrics11162026/11/10 21:15:51 INFO Received uploads request method=POST path=/api/pending_closures11172026/11/10 21:15:51 INFO Received uploads request method=POST path=/api/pending_closures11182026/11/10 21:15:51 INFO Received uploads request method=POST path=/api/pending_closures11192026/11/10 21:15:51 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst11202026/11/10 21:15:51 INFO Received uploads request method=POST path=/api/pending_closures1121--- PASS: TestPresignedUploadRegisteredBeforeCommit (6.52s)1122=== CONT TestOrphanedObjectsGC11232026/11/10 21:15:51 INFO Received push request method=POST path=/api/pushes11242026/11/10 21:15:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11252026/11/10 21:15:51 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11262026/11/10 21:15:51 INFO Signed narinfos id=1 count=111272026/11/10 21:15:51 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11282026/11/10 21:15:51 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11292026/11/10 21:15:51 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"11302026/11/10 21:15:51 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11312026/11/10 21:15:51 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"11322026/11/10 21:15:51 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11332026/11/10 21:15:51 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=111342026/11/10 21:15:51 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11352026/11/10 21:15:51 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1136--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (6.78s)1137=== CONT TestGCBugBareHashReferences11382026/11/10 21:15:51 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NGI2NDRjOTMtM2QxNC00MjNmLTg5MDItMTI3MTM4ZWFjM2ZjLmM1NjJmOWUzLTQxYmMtNGUwZS04MmJlLTdmN2FlZGU5MzU5NHgxNzk0MzQ1MzUwMTg1MjE4MDAw parts=1211392026/11/10 21:15:51 INFO Received uploads request method=POST path=/api/pending_closures1140--- PASS: TestCompletedNarNotReofferedAcrossClosures (6.85s)1141=== CONT TestObjectStatsUpdatedOncePerCommit11422026/11/10 21:15:52 INFO Received push request method=POST path=/api/pushes11432026-11-10 21:15:52.288 UTC [98056] ERROR: could not obtain lock on row in relation "closures"11442026-11-10 21:15:52.288 UTC [98056] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11452026-11-10 21:15:52.290 UTC [98056] ERROR: could not obtain lock on row in relation "closures"11462026-11-10 21:15:52.290 UTC [98056] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11472026-11-10 21:15:52.292 UTC [98056] ERROR: could not obtain lock on row in relation "closures"11482026-11-10 21:15:52.292 UTC [98056] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11492026-11-10 21:15:52.300 UTC [98056] ERROR: could not obtain lock on row in relation "closures"11502026-11-10 21:15:52.300 UTC [98056] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11512026-11-10 21:15:52.301 UTC [98056] ERROR: could not obtain lock on row in relation "closures"11522026-11-10 21:15:52.301 UTC [98056] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1153--- PASS: TestPush_RootsAreLockedInByteOrder (5.65s)1154=== CONT TestGCSweepSkipsPendingObjects11552026/11/10 21:15:52 INFO Received push request method=POST path=/api/pushes11562026/11/10 21:15:52 WARN Rate limiter enabled after throttle name=s3-test rate=511572026/11/10 21:15:52 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1158=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1159 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101160 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001161--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (7.48s)1162=== CONT TestGCAdvisoryLockBlocksConcurrentRun11632026/11/10 21:15:52 INFO Received push request method=POST path=/api/pushes11642026-11-10 21:15:52.825 UTC [98063] ERROR: Push does not exist: id=111652026-11-10 21:15:52.825 UTC [98063] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE11662026-11-10 21:15:52.825 UTC [98063] STATEMENT: SELECT commit_push($1)1167--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (6.57s)1168=== CONT TestObjectStatsTrigger11692026/11/10 21:15:52 INFO Received complete push request method=POST path=/api/pushes/1/complete11702026/11/10 21:15:52 INFO Completed push id=1 objects=4 duration=43.331166ms11712026/11/10 21:15:52 INFO Received push request method=POST path=/api/pushes11722026/11/10 21:15:52 INFO Aborted multipart uploads count=0 kept=011732026/11/10 21:15:52 WARN Force mode enabled - objects will be deleted immediately without grace period11742026/11/10 21:15:53 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=011752026/11/10 21:15:53 INFO Vacuumed table table=pending_closures11762026/11/10 21:15:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11772026/11/10 21:15:53 INFO Vacuumed table table=pending_objects1178=== RUN TestPush_RejectsBadRequests/no_roots1179=== PAUSE TestPush_RejectsBadRequests/no_roots1180=== RUN TestPush_RejectsBadRequests/no_objects1181=== PAUSE TestPush_RejectsBadRequests/no_objects1182=== RUN TestPush_RejectsBadRequests/bad_root1183=== PAUSE TestPush_RejectsBadRequests/bad_root1184=== RUN TestPush_RejectsBadRequests/root_not_in_objects1185=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects11862026/11/10 21:15:53 INFO Vacuumed table table=multipart_uploads1187=== CONT TestLeadEndsOnShutdown11882026/11/10 21:15:53 INFO Vacuumed table table=closures11892026/11/10 21:15:53 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NGI2NDRjOTMtM2QxNC00MjNmLTg5MDItMTI3MTM4ZWFjM2ZjLjg1NmJmMGVlLWY3MTgtNGFhYy1hNTRkLTE2Y2UzMWRmYzMxM3gxNzk0MzQ1MzUxMjM2NDYyMDAw parts=1211902026/11/10 21:15:53 INFO Vacuumed table table=objects11912026/11/10 21:15:53 INFO Received complete push request method=POST path=/api/pushes/2/complete11922026/11/10 21:15:53 INFO Completed push id=2 objects=4 duration=17.193625ms1193--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (7.29s)1194=== CONT TestSweepRechecksPendingAfterLocking1195--- PASS: TestReadProxyOutlastsServerWriteTimeout (8.34s)1196=== CONT TestLeadIncumbentAnnouncesAtOnce11972026/11/10 21:15:53 INFO Received push request method=POST path=/api/pushes11982026/11/10 21:15:53 INFO Received complete push request method=POST path=/api/pushes/1/complete11992026/11/10 21:15:53 INFO Completed push id=1 objects=4 duration=38.898917ms1200--- PASS: TestPush_RepeatedRootCommitsOnce (6.61s)1201=== CONT TestLeadElectsOneAndHandsOver12022026/11/10 21:15:53 INFO Received uploads request method=POST path=/api/pending_closures1203--- PASS: TestPushWaitsForSweepHoldingRow (6.96s)1204=== CONT TestConnectWaitsForAPeerMigration1205--- PASS: TestReadProxyNarStreaming (7.02s)1206=== CONT TestPendingCleanupUsesOneCutoff1207--- PASS: TestReadProxy404 (7.42s)1208=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1209--- PASS: TestReadProxyContentNegotiation (7.38s)1210=== CONT TestMultipartCleanup12112026/11/10 21:15:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1212--- PASS: TestReadProxyNarinfoAlreadyDecompressed (7.41s)1213=== CONT TestServerTLSConfig1214=== RUN TestServerTLSConfig/no_client_CA1215=== PAUSE TestServerTLSConfig/no_client_CA1216=== RUN TestServerTLSConfig/missing_CA_file1217=== PAUSE TestServerTLSConfig/missing_CA_file1218=== RUN TestServerTLSConfig/not_a_PEM_file12192026/11/10 21:15:55 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NGI2NDRjOTMtM2QxNC00MjNmLTg5MDItMTI3MTM4ZWFjM2ZjLmFhMDI3MjA5LTZmMzgtNDc3Mi1iY2ZlLWVmNzUyMjhmNDVmZXgxNzk0MzQ1MzUxMjYxMDMyMDAw parts=121220=== PAUSE TestServerTLSConfig/not_a_PEM_file1221=== CONT TestClientErrorHandling1222=== RUN TestClientErrorHandling/InvalidStorePath1223=== PAUSE TestClientErrorHandling/InvalidStorePath1224=== RUN TestClientErrorHandling/InvalidAuthToken1225=== PAUSE TestClientErrorHandling/InvalidAuthToken1226=== RUN TestClientErrorHandling/ServerNotAvailable1227=== PAUSE TestClientErrorHandling/ServerNotAvailable1228=== CONT TestGetExistingObjectsLocksRows1229--- PASS: TestSharedNarBothUploadsComplete (10.51s)1230=== CONT TestClientSharedPathCommittedMidPush12312026/11/10 21:15:56 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1232--- PASS: TestReadProxyNarinfo (7.16s)1233=== CONT TestRegisterCompletedObjectNeedsPendingRow1234--- PASS: TestPresentRefreshesOnlyStaleClosures (6.62s)1235=== CONT TestClientWithDependencies1236--- PASS: TestPresentReportsOnlyClosureRoots (6.68s)1237=== CONT TestService_NativeMTLS12382026/11/10 21:15:56 INFO Received uploads request method=POST path=/api/pending_closures1239--- PASS: TestDeduplicatedObjectsRecordedAsPending (6.92s)1240=== CONT TestMetricsCommit12412026/11/10 21:15:57 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12422026/11/10 21:15:57 WARN Refused reserved pin name=worker-x86_64-linux12432026/11/10 21:15:57 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12442026/11/10 21:15:57 INFO Received create pin request method=POST path=/api/pins/my-app12452026/11/10 21:15:57 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1246--- PASS: TestCreatePin_ReservedPins (6.69s)1247=== CONT TestMetricsInventory12482026/11/10 21:15:57 INFO Received uploads request method=POST path=/api/pending_closures12492026/11/10 21:15:57 INFO Aborted multipart uploads count=0 kept=012502026/11/10 21:15:57 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=012512026/11/10 21:15:57 INFO Aborted multipart uploads count=0 kept=012522026/11/10 21:15:57 WARN Force mode enabled - objects will be deleted immediately without grace period12532026/11/10 21:15:57 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=012542026/11/10 21:15:57 INFO Vacuumed table table=pending_closures12552026/11/10 21:15:57 INFO Vacuumed table table=pending_closures12562026/11/10 21:15:57 INFO Vacuumed table table=pending_objects12572026/11/10 21:15:57 INFO Vacuumed table table=multipart_uploads12582026/11/10 21:15:57 INFO Vacuumed table table=pending_objects12592026/11/10 21:15:57 INFO Vacuumed table table=closures12602026/11/10 21:15:57 INFO Vacuumed table table=multipart_uploads12612026/11/10 21:15:57 INFO Vacuumed table table=objects1262--- PASS: TestGCMetrics (7.00s)1263=== CONT TestNARDeduplicationMetadataUploadBug12642026/11/10 21:15:58 INFO Vacuumed table table=closures12652026/11/10 21:15:58 INFO Vacuumed table table=objects12662026/11/10 21:15:58 INFO Aborted multipart uploads count=0 kept=012672026/11/10 21:15:58 WARN Force mode enabled - objects will be deleted immediately without grace period12682026/11/10 21:15:58 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=012692026/11/10 21:15:58 INFO Vacuumed table table=pending_closures12702026/11/10 21:15:58 INFO Vacuumed table table=pending_objects12712026/11/10 21:15:58 INFO Vacuumed table table=multipart_uploads12722026/11/10 21:15:58 INFO Vacuumed table table=closures12732026/11/10 21:15:58 INFO Vacuumed table table=objects1274--- PASS: TestPushDedupSurvivesConcurrentGC (7.34s)1275=== CONT TestPinProtectsFromGC1276--- PASS: TestObjectStatsUpdatedOncePerCommit (7.04s)1277=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1278--- PASS: TestGCBugBareHashReferences (7.59s)1279=== CONT TestCreatePendingClosureRejectsOversizedNAR12802026/11/10 21:15:59 INFO Received uploads request method=POST path=/api/pending_closures1281--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1282=== CONT TestSweepSkipsRowsLockedByPush12832026/11/10 21:15:59 INFO Received uploads request method=POST path=/api/pending_closures12842026/11/10 21:15:59 INFO Aborted multipart uploads count=0 kept=012852026/11/10 21:15:59 WARN Force mode enabled - objects will be deleted immediately without grace period12862026/11/10 21:15:59 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=012872026/11/10 21:15:59 INFO Vacuumed table table=pending_closures12882026/11/10 21:15:59 INFO Vacuumed table table=pending_objects12892026/11/10 21:15:59 INFO Vacuumed table table=multipart_uploads12902026/11/10 21:15:59 INFO Vacuumed table table=closures12912026/11/10 21:15:59 INFO Vacuumed table table=objects1292--- PASS: TestGCSweepSkipsPendingObjects (7.71s)1293=== CONT TestCacheConfigHandlerMaxNarSize1294--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1295=== CONT TestFailedS3DeleteKeepsTombstone1296--- PASS: TestObjectStatsTrigger (7.25s)1297=== CONT TestEnsureAbortUploadsRule12982026/11/10 21:16:00 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld4 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1299--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (8.05s)1300=== CONT TestForceGCDuringPushOffersSweptObject1301=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1302=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1303=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1304=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1305=== CONT TestGenerateLandingPage1306--- PASS: TestGenerateLandingPage (0.00s)1307=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1308=== NAME TestOrphanedObjectsGC1309 orphaned_objects_gc_test.go:287: GC Test Summary:1310 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1311 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1312 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1313 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1314 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1315--- PASS: TestOrphanedObjectsGC (9.22s)1316=== CONT TestService_readinessHandler13172026/11/10 21:16:01 INFO lead: acquired remote=192.0.2.1:123413182026/11/10 21:16:01 INFO Aborted multipart uploads count=0 kept=013192026/11/10 21:16:01 WARN Force mode enabled - objects will be deleted immediately without grace period13202026/11/10 21:16: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=013212026/11/10 21:16:01 INFO Vacuumed table table=pending_closures13222026/11/10 21:16:01 INFO Vacuumed table table=pending_objects13232026/11/10 21:16:01 INFO Vacuumed table table=multipart_uploads13242026/11/10 21:16:01 INFO Vacuumed table table=closures13252026/11/10 21:16:01 INFO Vacuumed table table=objects1326--- PASS: TestSweepRechecksPendingAfterLocking (8.23s)1327=== CONT TestGCSweepDeliversEachKeyOnce13282026/11/10 21:16:01 INFO lead: acquired remote=192.0.2.1:123413292026/11/10 21:16:01 INFO lead: released remote=192.0.2.1:12341330--- PASS: TestLeadIncumbentAnnouncesAtOnce (8.26s)1331=== CONT TestTombstonedObjectOfferedWithoutWaiting13322026/11/10 21:16:01 INFO lead: acquired remote=192.0.2.1:123413332026/11/10 21:16:02 INFO lead: released remote=192.0.2.1:12341334--- PASS: TestLeadEndsOnShutdown (8.92s)1335=== CONT TestService_healthCheckHandler13362026/11/10 21:16:02 INFO Received uploads request method=POST path=/api/pending_closures13372026/11/10 21:16:02 INFO Received uploads request method=POST path=/api/pending_closures13382026/11/10 21:16:02 INFO Received cleanup request method=DELETE path=/api/pending_closures1339--- PASS: TestConnectWaitsForAPeerMigration (8.13s)1340=== CONT TestClientMultipleUploads13412026/11/10 21:16:02 INFO Received uploads request method=POST path=/api/pending_closures1342--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (7.80s)1343=== CONT TestGracefulShutdownDrainsInflight13442026/11/10 21:16:02 INFO Starting HTTP server address=127.0.0.1:5375113452026/11/10 21:16:02 INFO Shutdown signal received, draining in-flight requests timeout=10s1346--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1347=== CONT TestClientFallsBackToClosures13482026/11/10 21:16:02 INFO Received uploads request method=POST path=/api/pending_closures13492026/11/10 21:16:03 INFO Received cleanup request method=DELETE path=/api/pending_closures13502026/11/10 21:16:03 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket58/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""13512026/11/10 21:16:03 INFO lead: released remote=192.0.2.1:123413522026/11/10 21:16:03 INFO Aborted multipart uploads count=0 kept=113532026/11/10 21:16:03 INFO Received cleanup request method=DELETE path=/api/pending_closures13542026/11/10 21:16:03 INFO Aborted multipart uploads count=1 kept=013552026/11/10 21:16:03 INFO lead: acquired remote=192.0.2.1:12341356--- PASS: TestMultipartCleanup (7.90s)1357=== CONT TestGCTaskStore_Fail1358--- PASS: TestGCTaskStore_Fail (0.00s)1359=== CONT TestDeleteClosuresRacingPins1360--- PASS: TestGetExistingObjectsLocksRows (7.75s)1361=== CONT TestGCTaskStore_PhaseUpdates1362--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1363=== CONT TestClientPushesUseOnePush1364--- PASS: TestRegisterCompletedObjectNeedsPendingRow (7.81s)1365=== CONT TestGCTaskStore_ConflictDifferentParams1366--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1367=== CONT TestClientIntegration13682026/11/10 21:16:04 INFO Received push request method=POST path=/api/pushes13692026/11/10 21:16:04 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)13702026/11/10 21:16:04 INFO Uploading z4iq0vxl0ih2mfzsk0nqmhrg3k97br1d-top (264B)13712026/11/10 21:16:04 INFO Uploading b0qrhksngrpbsdbyjr9hdnliz1c2nysl-shared-dep (136B)13722026/11/10 21:16:04 WARN Failed to register uploaded object key=z4iq0vxl0ih2mfzsk0nqmhrg3k97br1d.ls error="server returned 404: 404 page not found\n"13732026/11/10 21:16:04 WARN Failed to register uploaded object key=b0qrhksngrpbsdbyjr9hdnliz1c2nysl.ls error="server returned 404: 404 page not found\n"13742026/11/10 21:16:04 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13752026/11/10 21:16:04 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13762026/11/10 21:16:04 WARN Failed to register uploaded object key=nar/0bh3v5npmnscnvpxwfwkpbg9sq3j2r4qwgvfxwhny273i6s68faz.nar.zst error="server returned 404: 404 page not found\n"13772026/11/10 21:16:04 INFO Signed narinfos id=1 count=213782026/11/10 21:16:04 INFO Uploading 2 narinfos13792026/11/10 21:16:04 WARN Failed to register uploaded object key=z4iq0vxl0ih2mfzsk0nqmhrg3k97br1d.narinfo error="server returned 404: 404 page not found\n"13802026/11/10 21:16:04 INFO Received complete push request method=POST path=/api/pushes/1/complete13812026/11/10 21:16:04 WARN Failed to register uploaded object key=b0qrhksngrpbsdbyjr9hdnliz1c2nysl.narinfo error="server returned 404: 404 page not found\n"13822026/11/10 21:16:04 INFO lead: released remote=192.0.2.1:12341383--- PASS: TestLeadElectsOneAndHandsOver (10.63s)1384=== CONT TestGCTaskStore_DeduplicateSameParams1385--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1386=== CONT TestGCTaskStore_StartNew1387--- PASS: TestGCTaskStore_StartNew (0.00s)1388=== CONT TestGCTaskStore_CompletedAllowsNewTask1389--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1390=== CONT TestGCEndsOnShutdown1391=== RUN TestGCEndsOnShutdown/before_the_run1392=== PAUSE TestGCEndsOnShutdown/before_the_run1393=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1394=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1395=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1396=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1397=== CONT TestGCTaskStore_GetReturnsLatest1398--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1399=== CONT TestGCTaskStore_GetEmpty1400--- PASS: TestGCTaskStore_GetEmpty (0.00s)1401=== CONT TestCommitRacingPendingCleanupKeepsObjects14022026/11/10 21:16:04 INFO Completed push id=1 objects=6 duration=38.543917ms14032026/11/10 21:16:04 INFO Upload complete. (295ms)1404=== NAME TestClientSharedPathCommittedMidPush1405 client_integration_test.go:727: Retrieved narinfo from S3:1406 StorePath: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientSharedPathCommittedMidPush649104547/001/store/b0qrhksngrpbsdbyjr9hdnliz1c2nysl-shared-dep1407 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1408 Compression: zstd1409 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821410 NarSize: 1361411 References: 1412 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1413 client_integration_test.go:727: Retrieved narinfo from S3:1414 StorePath: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientSharedPathCommittedMidPush649104547/001/store/z4iq0vxl0ih2mfzsk0nqmhrg3k97br1d-top1415 URL: nar/0bh3v5npmnscnvpxwfwkpbg9sq3j2r4qwgvfxwhny273i6s68faz.nar.zst1416 Compression: zstd1417 NarHash: sha256:0bh3v5npmnscnvpxwfwkpbg9sq3j2r4qwgvfxwhny273i6s68faz1418 NarSize: 2641419 References: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientSharedPathCommittedMidPush649104547/001/store/b0qrhksngrpbsdbyjr9hdnliz1c2nysl-shared-dep1420 CA: text:sha256:0d7sqiki5j1dmj0aaxpnzpcm7ndwp15vijv2hik3lz6ar4wki7d71421--- PASS: TestClientSharedPathCommittedMidPush (8.79s)1422=== CONT TestService_AuthMiddleware_MTLSProxyHeader14232026/11/10 21:16:04 WARN mTLS auth: subject not in bound subjects subject="CN=reader"14242026/11/10 21:16:04 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1425--- PASS: TestService_NativeMTLS (7.89s)1426=== CONT TestCacheStatsHandler1427=== NAME TestClientWithDependencies1428 client_integration_test.go:660: Built derivation: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientWithDependencies730423400/001/store/s6nhqkvwn0z468j8m5bx9aa5ykvd4ay7-test-script14292026/11/10 21:16:04 INFO Received push request method=POST path=/api/pushes1430 client_integration_test.go:662: Found 1 dependencies (including self)14312026/11/10 21:16:04 INFO Received complete push request method=POST path=/api/pushes/1/complete14322026/11/10 21:16:04 INFO Received push request method=POST path=/api/pushes14332026/11/10 21:16:04 INFO Completed push id=1 objects=4 duration=30.973041ms14342026/11/10 21:16:04 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14352026/11/10 21:16:04 INFO Completed upload id=2 objects=2 duration=578.583µs1436--- PASS: TestMetricsCommit (8.04s)1437=== CONT TestClientCADerivations14382026/11/10 21:16:04 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14392026/11/10 21:16:04 INFO Uploading s6nhqkvwn0z468j8m5bx9aa5ykvd4ay7-test-script (136B)14402026/11/10 21:16:05 WARN Failed to register uploaded object key=s6nhqkvwn0z468j8m5bx9aa5ykvd4ay7.ls error="server returned 404: 404 page not found\n"14412026/11/10 21:16:05 WARN Failed to register uploaded object key=log/5va5avzyck1jf1hvfl5789s92x0zsgg9-test-script.drv error="server returned 404: 404 page not found\n"14422026/11/10 21:16:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14432026/11/10 21:16:05 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"14442026/11/10 21:16:05 INFO Signed narinfos id=1 count=114452026/11/10 21:16:05 INFO Uploading 1 narinfos14462026/11/10 21:16:05 INFO Received complete push request method=POST path=/api/pushes/1/complete14472026/11/10 21:16:05 WARN Failed to register uploaded object key=s6nhqkvwn0z468j8m5bx9aa5ykvd4ay7.narinfo error="server returned 404: 404 page not found\n"14482026/11/10 21:16:05 INFO Completed push id=1 objects=4 duration=35.231833ms14492026/11/10 21:16:05 INFO Upload complete. (264ms)1450=== NAME TestClientWithDependencies1451 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/4/scratch/b3a0d46031104912/build/TestClientWithDependencies730423400/001/store) requires matching store prefix1452--- PASS: TestMetricsInventory (8.12s)1453=== CONT TestService_AuthMiddleware1454--- PASS: TestClientWithDependencies (8.91s)1455=== CONT TestCacheConfigHandler1456=== RUN TestCacheConfigHandler/full_config,_no_issuer1457=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1458=== RUN TestCacheConfigHandler/no_cache_url_configured1459=== PAUSE TestCacheConfigHandler/no_cache_url_configured1460=== RUN TestCacheConfigHandler/no_signing_keys1461=== PAUSE TestCacheConfigHandler/no_signing_keys1462=== RUN TestCacheConfigHandler/upstream_keys_advertised1463=== PAUSE TestCacheConfigHandler/upstream_keys_advertised1464=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1465=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1466=== CONT TestService_ReadScope_PublicByDefault1467=== NAME TestPinProtectsFromGC1468 client_integration_test.go:778: Pinned store path: /private/var/tb/4/scratch/b3a0d46031104912/build/TestPinProtectsFromGC2106326844/001/store/rlcp3qf5jk1ywib08ky709bislv8bl88-pinned-file.txt1469 client_integration_test.go:779: Unpinned store path: /private/var/tb/4/scratch/b3a0d46031104912/build/TestPinProtectsFromGC2106326844/001/store/20w5y848cakmkylvhddp6qpyvn3pvszy-unpinned-file.txt14702026/11/10 21:16:05 INFO Received push request method=POST path=/api/pushes1471=== NAME TestNARDeduplicationMetadataUploadBug1472 metadata_upload_test.go:48: First store path: /private/var/tb/4/scratch/b3a0d46031104912/build/TestNARDeduplicationMetadataUploadBug4243900830/001/store/c3g23rrgybpcv6q5pdz28wnpm9d8w9jr-file1.txt14732026/11/10 21:16:05 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14742026/11/10 21:16:05 INFO Uploading rlcp3qf5jk1ywib08ky709bislv8bl88-pinned-file.txt (128B)14752026/11/10 21:16:06 WARN Failed to register uploaded object key=rlcp3qf5jk1ywib08ky709bislv8bl88.ls error="server returned 404: 404 page not found\n"14762026/11/10 21:16:06 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14772026/11/10 21:16:06 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14782026/11/10 21:16:06 INFO Signed narinfos id=1 count=114792026/11/10 21:16:06 INFO Uploading 1 narinfos14802026/11/10 21:16:06 INFO Received push request method=POST path=/api/pushes14812026/11/10 21:16:06 INFO Received complete push request method=POST path=/api/pushes/1/complete14822026/11/10 21:16:06 WARN Failed to register uploaded object key=rlcp3qf5jk1ywib08ky709bislv8bl88.narinfo error="server returned 404: 404 page not found\n"14832026/11/10 21:16:06 INFO Completed push id=1 objects=3 duration=32.542834ms14842026/11/10 21:16:06 INFO Upload complete. (256ms)14852026/11/10 21:16:06 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14862026/11/10 21:16:06 INFO Uploading c3g23rrgybpcv6q5pdz28wnpm9d8w9jr-file1.txt (160B)14872026/11/10 21:16:06 WARN Failed to register uploaded object key=c3g23rrgybpcv6q5pdz28wnpm9d8w9jr.ls error="server returned 404: 404 page not found\n"14882026/11/10 21:16:06 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14892026/11/10 21:16:06 INFO Signed narinfos id=1 count=114902026/11/10 21:16:06 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"14912026/11/10 21:16:06 INFO Uploading 1 narinfos14922026/11/10 21:16:06 INFO Received push request method=POST path=/api/pushes14932026/11/10 21:16:06 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14942026/11/10 21:16:06 INFO Uploading 20w5y848cakmkylvhddp6qpyvn3pvszy-unpinned-file.txt (128B)14952026/11/10 21:16:06 INFO Received complete push request method=POST path=/api/pushes/1/complete14962026/11/10 21:16:06 WARN Failed to register uploaded object key=c3g23rrgybpcv6q5pdz28wnpm9d8w9jr.narinfo error="server returned 404: 404 page not found\n"14972026/11/10 21:16:06 WARN Failed to register uploaded object key=20w5y848cakmkylvhddp6qpyvn3pvszy.ls error="server returned 404: 404 page not found\n"14982026/11/10 21:16:06 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign14992026/11/10 21:16:06 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"15002026/11/10 21:16:06 INFO Signed narinfos id=2 count=115012026/11/10 21:16:06 INFO Uploading 1 narinfos15022026/11/10 21:16:06 INFO Completed push id=1 objects=3 duration=35.36025ms15032026/11/10 21:16:06 INFO Upload complete. (321ms)1504 metadata_upload_test.go:54: Retrieved narinfo from S3:1505 StorePath: /private/var/tb/4/scratch/b3a0d46031104912/build/TestNARDeduplicationMetadataUploadBug4243900830/001/store/c3g23rrgybpcv6q5pdz28wnpm9d8w9jr-file1.txt1506 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1507 Compression: zstd1508 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1509 NarSize: 1601510 References: 1511 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1512 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1513 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1514 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}15152026/11/10 21:16:06 INFO Received complete push request method=POST path=/api/pushes/2/complete15162026/11/10 21:16:06 WARN Failed to register uploaded object key=20w5y848cakmkylvhddp6qpyvn3pvszy.narinfo error="server returned 404: 404 page not found\n"15172026/11/10 21:16:06 INFO Completed push id=2 objects=3 duration=821µs15182026/11/10 21:16:06 INFO Upload complete. (197ms)15192026/11/10 21:16:06 INFO Starting cleanup of old closures method=DELETE path=/api/closures15202026/11/10 21:16:06 INFO Garbage collection started15212026/11/10 21:16:06 INFO Aborted multipart uploads count=0 kept=01522 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/4/scratch/b3a0d46031104912/build/TestNARDeduplicationMetadataUploadBug4243900830/001/store/pqdfh26nr6r6sg1biz1ncaxaa7d7rh6f-file2.txt15232026/11/10 21:16:06 WARN Force mode enabled - objects will be deleted immediately without grace period15242026/11/10 21:16:06 INFO Received push request method=POST path=/api/pushes15252026/11/10 21:16:06 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)15262026/11/10 21:16:06 INFO Aborted multipart uploads count=0 kept=015272026/11/10 21:16:06 WARN Force mode enabled - objects will be deleted immediately without grace period15282026/11/10 21:16:06 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign15292026/11/10 21:16:06 WARN Failed to register uploaded object key=pqdfh26nr6r6sg1biz1ncaxaa7d7rh6f.ls error="server returned 404: 404 page not found\n"15302026/11/10 21:16:06 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=015312026/11/10 21:16:06 INFO Signed narinfos id=2 count=115322026/11/10 21:16:06 INFO Uploading 1 narinfos15332026/11/10 21:16:06 INFO Vacuumed table table=pending_closures15342026/11/10 21:16:06 INFO Vacuumed table table=pending_objects15352026/11/10 21:16:06 INFO Vacuumed table table=multipart_uploads15362026/11/10 21:16:06 INFO Vacuumed table table=closures15372026/11/10 21:16:06 INFO Received complete push request method=POST path=/api/pushes/2/complete15382026/11/10 21:16:06 WARN Failed to register uploaded object key=pqdfh26nr6r6sg1biz1ncaxaa7d7rh6f.narinfo error="server returned 404: 404 page not found\n"15392026/11/10 21:16:06 INFO Completed push id=2 objects=3 duration=845.833µs15402026/11/10 21:16:06 INFO Upload complete. (203ms)1541 metadata_upload_test.go:76: Retrieved narinfo from S3:1542 StorePath: /private/var/tb/4/scratch/b3a0d46031104912/build/TestNARDeduplicationMetadataUploadBug4243900830/001/store/pqdfh26nr6r6sg1biz1ncaxaa7d7rh6f-file2.txt1543 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1544 Compression: zstd1545 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1546 NarSize: 1601547 References: 1548 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1549 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1550 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1551 {"version":1,"root":{"type":"regular","size":44}}15522026/11/10 21:16:06 INFO Vacuumed table table=objects15532026/11/10 21:16:06 INFO Aborted multipart uploads count=0 kept=015542026/11/10 21:16:06 WARN Force mode enabled - objects will be deleted immediately without grace period1555--- PASS: TestNARDeduplicationMetadataUploadBug (8.87s)1556=== CONT TestService_AuthMiddleware_OIDC15572026/11/10 21:16:06 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53827/oidc15582026/11/10 21:16:06 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=015592026/11/10 21:16:07 INFO Installed lifecycle rule aborting incomplete NAR uploads bucket=bucket70 days=21560--- PASS: TestEnsureAbortUploadsRule (6.92s)1561=== CONT TestService_ReadAuthMiddleware15622026/11/10 21:16:07 INFO Vacuumed table table=pending_closures15632026/11/10 21:16:07 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=015642026/11/10 21:16:07 INFO Vacuumed table table=pending_objects15652026/11/10 21:16:07 INFO Vacuumed table table=pending_closures15662026/11/10 21:16:07 INFO Vacuumed table table=pending_objects15672026/11/10 21:16:07 INFO Vacuumed table table=multipart_uploads15682026/11/10 21:16:07 INFO Vacuumed table table=multipart_uploads15692026/11/10 21:16:07 INFO Vacuumed table table=closures15702026/11/10 21:16:07 INFO Vacuumed table table=objects1571--- PASS: TestSweepSkipsRowsLockedByPush (7.57s)1572=== CONT TestService_RequireScope_OIDC15732026/11/10 21:16:07 INFO Vacuumed table table=closures15742026/11/10 21:16:07 INFO Vacuumed table table=objects15752026/11/10 21:16:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53829/oidc15762026/11/10 21:16:07 INFO Received uploads request method=POST path=/api/pending_closures15772026/11/10 21:16:07 INFO Aborted multipart uploads count=0 kept=015782026/11/10 21:16:07 WARN Force mode enabled - objects will be deleted immediately without grace period1579--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (8.60s)15802026/11/10 21:16:07 INFO Received uploads request method=POST path=/api/pending_closures1581=== CONT TestService_AuthMiddleware_MTLSBoundSubjects15822026/11/10 21:16:07 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."15832026/11/10 21:16:07 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1584--- PASS: TestFailedS3DeleteKeepsTombstone (7.57s)1585=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15862026/11/10 21:16:07 INFO Received uploads request method=POST path=/1587=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15882026/11/10 21:16:07 INFO Received request for more parts method=POST path=/1589=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15902026/11/10 21:16:07 INFO Received complete multipart upload request method=POST path=/1591=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15922026/11/10 21:16:07 INFO Received uploads request method=POST path=/1593--- PASS: TestUploadHandlersRejectInvalidKeys (0.01s)1594 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1595 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1596 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1597 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1598=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed15992026/11/10 21:16:07 WARN readiness check failed error="closed pool"1600--- PASS: TestService_readinessHandler (6.98s)1601=== CONT TestProxyWriteTimeout/narinfo1602=== CONT TestProxyWriteTimeout/unknown_size1603=== CONT TestProxyWriteTimeout/10_GiB_nar1604=== CONT TestProxyWriteTimeout/1_GiB_nar1605=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1606--- PASS: TestProxyWriteTimeout (0.05s)1607 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1608 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1609 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1610 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1611--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (7.21s)1612=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed16132026/11/10 21:16:08 INFO Aborted multipart uploads count=0 kept=016142026/11/10 21:16:08 WARN Force mode enabled - objects will be deleted immediately without grace period16152026/11/10 21:16:08 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=016162026/11/10 21:16:08 INFO Received create pin request method=POST path=/api/pins/myapp16172026/11/10 21:16:08 INFO Created/updated pin name=myapp store_path=/private/var/tb/4/scratch/b3a0d46031104912/build/TestPinProtectsFromGC2106326844/001/store/rlcp3qf5jk1ywib08ky709bislv8bl88-pinned-file.txt narinfo_key=rlcp3qf5jk1ywib08ky709bislv8bl88.narinfo16182026/11/10 21:16:08 INFO Aborted multipart uploads count=1 kept=016192026/11/10 21:16:08 INFO Starting cleanup of old closures method=DELETE path=/api/closures16202026/11/10 21:16:08 INFO Received uploads request method=POST path=/api/pending_closures16212026/11/10 21:16:08 INFO Garbage collection started16222026/11/10 21:16:08 INFO Aborted multipart uploads count=0 kept=016232026/11/10 21:16:08 WARN Force mode enabled - objects will be deleted immediately without grace period16242026/11/10 21:16:08 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=016252026/11/10 21:16:08 INFO Vacuumed table table=pending_closures16262026/11/10 21:16:08 INFO Vacuumed table table=pending_objects16272026/11/10 21:16:08 INFO Vacuumed table table=multipart_uploads16282026/11/10 21:16:08 INFO Vacuumed table table=closures16292026/11/10 21:16:08 INFO Vacuumed table table=objects1630--- PASS: TestTombstonedObjectOfferedWithoutWaiting (6.93s)16312026/11/10 21:16:08 INFO Received cleanup request method=DELETE path=/api/pending_closures1632=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed16332026/11/10 21:16:08 INFO Aborted multipart uploads count=1 kept=01634--- PASS: TestPendingCleanupUsesOneCutoff (13.88s)1635=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1636--- PASS: TestService_healthCheckHandler (6.79s)1637=== CONT TestPendingClosureWriteTimeout/empty1638=== CONT TestIsValidUploadKey/narinfo1639=== CONT TestIsValidUploadKey/index.html1640=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline16412026/11/10 21:16:08 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=016422026/11/10 21:16:08 INFO Vacuumed table table=pending_closures16432026/11/10 21:16:08 INFO Vacuumed table table=pending_objects16442026/11/10 21:16:08 INFO Vacuumed table table=multipart_uploads16452026/11/10 21:16:08 INFO Vacuumed table table=closures16462026/11/10 21:16:09 INFO Vacuumed table table=objects1647--- PASS: TestGCSweepDeliversEachKeyOnce (7.45s)1648=== CONT TestPendingClosureWriteTimeout/670k_objects1649=== CONT TestPendingClosureWriteTimeout/400_objects1650=== CONT TestIsValidUploadKey/empty_key1651=== CONT TestIsValidUploadKey/unknown_type1652=== CONT TestIsValidUploadKey/absolute1653=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1654=== CONT TestIsValidUploadKey/traversal1655=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1656=== CONT TestIsValidUploadKey/realisation1657=== CONT TestIsValidUploadKey/nix-cache-info1658=== CONT TestIsValidUploadKey/realisation_plus_in_output1659=== CONT TestIsValidUploadKey/build_log_plus_in_name1660=== CONT TestIsValidUploadKey/build_log_equals1661=== CONT TestIsValidUploadKey/build_log_question_mark1662=== CONT TestIsValidUploadKey/listing1663=== CONT TestIsValidUploadKey/build_log_home-manager_file1664=== CONT TestIsValidUploadKey/build_log1665=== CONT TestIsValidUploadKey/nar_xz1666=== CONT TestIsValidUploadKey/nar_plain1667=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1668=== CONT TestIsValidUploadKey/nar_zst1669=== CONT TestIsValidUploadKey/traversal_nar1670--- PASS: TestIsValidUploadKey (0.05s)1671 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1672 --- PASS: TestIsValidUploadKey/index.html (0.00s)1673 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1674 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1675 --- PASS: TestIsValidUploadKey/absolute (0.00s)1676 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1677 --- PASS: TestIsValidUploadKey/traversal (0.00s)1678 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1679 --- PASS: TestIsValidUploadKey/realisation (0.00s)1680 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1681 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1682 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1683 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1684 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1685 --- PASS: TestIsValidUploadKey/listing (0.00s)1686 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1687 --- PASS: TestIsValidUploadKey/build_log (0.00s)1688 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1689 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1690 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1691 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1692 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1693=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16942026/11/10 21:16:09 INFO Received uploads request method=POST path=/1695=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16962026/11/10 21:16:09 INFO Received request for more parts method=POST path=/1697=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16982026/11/10 21:16:09 INFO Received complete multipart upload request method=POST path=/1699--- PASS: TestUploadHandlersRejectOversizedBody (0.11s)1700 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.31s)1701 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1702 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1703=== CONT TestIsValidCachePath/narinfo1704=== CONT TestIsValidCachePath/index.html1705=== CONT TestIsValidCachePath/short_hash1706=== CONT TestIsValidCachePath/wrong_extension1707=== CONT TestIsValidCachePath/leading_slash1708=== CONT TestIsValidCachePath/empty1709=== CONT TestIsValidCachePath/random_path1710=== CONT TestIsValidCachePath/invalid_char_u1711=== CONT TestIsValidCachePath/invalid_char_e1712=== CONT TestIsValidCachePath/traversal_in_middle1713=== CONT TestIsValidCachePath/traversal_parent1714=== CONT TestIsValidCachePath/nar_uncompressed1715=== CONT TestIsValidCachePath/nix-cache-info1716=== CONT TestIsValidCachePath/realisation1717=== CONT TestIsValidCachePath/log1718=== CONT TestIsValidCachePath/ls1719=== CONT TestIsValidCachePath/nar_xz1720=== CONT TestIsValidCachePath/nar_bz21721=== CONT TestIsValidCachePath/nar_zst1722=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1723--- PASS: TestIsValidCachePath (0.02s)1724 --- PASS: TestIsValidCachePath/narinfo (0.00s)1725 --- PASS: TestIsValidCachePath/index.html (0.00s)1726 --- PASS: TestIsValidCachePath/short_hash (0.00s)1727 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1728 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1729 --- PASS: TestIsValidCachePath/empty (0.00s)1730 --- PASS: TestIsValidCachePath/random_path (0.00s)1731 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1732 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1733 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1734 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1735 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1736 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1737 --- PASS: TestIsValidCachePath/realisation (0.00s)1738 --- PASS: TestIsValidCachePath/log (0.00s)1739 --- PASS: TestIsValidCachePath/ls (0.00s)1740 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1741 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1742 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1743 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1744=== CONT TestParseSingleRange/none1745=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1746=== NAME TestClientMultipleUploads1747 client_integration_test.go:405: Created store path 0: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientMultipleUploads1656999415/001/store/ghxdirmyb4na2i9ldv09xyxb8261wfak-test-file-0.txt1748 client_integration_test.go:405: Created store path 1: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientMultipleUploads1656999415/001/store/siddzs930x0vwdbbyaj3p9xayj9lpv4i-test-file-1.txt1749 client_integration_test.go:405: Created store path 2: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientMultipleUploads1656999415/001/store/d6ccgi7ljvv4navs22kcy8mhy7zajssm-test-file-2.txt17502026/11/10 21:16:09 INFO Received push request method=POST path=/api/pushes17512026/11/10 21:16:09 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)17522026/11/10 21:16:09 INFO Uploading ghxdirmyb4na2i9ldv09xyxb8261wfak-test-file-0.txt (160B)17532026/11/10 21:16:09 INFO Uploading d6ccgi7ljvv4navs22kcy8mhy7zajssm-test-file-2.txt (160B)17542026/11/10 21:16:09 INFO Uploading siddzs930x0vwdbbyaj3p9xayj9lpv4i-test-file-1.txt (160B)17552026/11/10 21:16:09 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"17562026/11/10 21:16:09 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"17572026/11/10 21:16:09 WARN Failed to register uploaded object key=ghxdirmyb4na2i9ldv09xyxb8261wfak.ls error="server returned 404: 404 page not found\n"17582026/11/10 21:16:09 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"17592026/11/10 21:16:09 WARN Failed to register uploaded object key=d6ccgi7ljvv4navs22kcy8mhy7zajssm.ls error="server returned 404: 404 page not found\n"17602026/11/10 21:16:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17612026/11/10 21:16:09 WARN Failed to register uploaded object key=siddzs930x0vwdbbyaj3p9xayj9lpv4i.ls error="server returned 404: 404 page not found\n"17622026/11/10 21:16:09 INFO Signed narinfos id=1 count=317632026/11/10 21:16:09 INFO Uploading 3 narinfos17642026/11/10 21:16:09 WARN Failed to register uploaded object key=d6ccgi7ljvv4navs22kcy8mhy7zajssm.narinfo error="server returned 404: 404 page not found\n"17652026/11/10 21:16:10 WARN Failed to register uploaded object key=ghxdirmyb4na2i9ldv09xyxb8261wfak.narinfo error="server returned 404: 404 page not found\n"17662026/11/10 21:16:10 INFO Received complete push request method=POST path=/api/pushes/1/complete17672026/11/10 21:16:10 WARN Failed to register uploaded object key=siddzs930x0vwdbbyaj3p9xayj9lpv4i.narinfo error="server returned 404: 404 page not found\n"17682026/11/10 21:16:10 INFO Completed push id=1 objects=9 duration=25.777125ms17692026/11/10 21:16:10 INFO Upload complete. (383ms)1770 client_integration_test.go:416: Uploaded 3 paths in 425.450667ms1771--- PASS: TestClientMultipleUploads (7.65s)1772=== CONT TestParseSingleRange/start_far_past_EOF1773=== CONT TestParseSingleRange/start_past_EOF1774=== CONT TestParseSingleRange/single_byte1775=== CONT TestParseSingleRange/suffix_exceeds_size1776=== CONT TestParseSingleRange/suffix1777=== CONT TestParseSingleRange/end_clamped_to_size1778=== CONT TestParseSingleRange/open-ended1779=== CONT TestParseSingleRange/closed1780=== CONT TestParseSingleRange/malformed_end_before_start1781=== CONT TestParseSingleRange/malformed_both_empty1782=== CONT TestParseSingleRange/malformed_no_dash1783=== CONT TestParseSingleRange/multi-range_ignored1784=== CONT TestParseSingleRange/unknown_unit1785--- PASS: TestParseSingleRange (0.00s)1786 --- PASS: TestParseSingleRange/none (0.00s)1787 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1788 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1789 --- PASS: TestParseSingleRange/single_byte (0.00s)1790 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1791 --- PASS: TestParseSingleRange/suffix (0.00s)1792 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1793 --- PASS: TestParseSingleRange/open-ended (0.00s)1794 --- PASS: TestParseSingleRange/closed (0.00s)1795 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1796 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1797 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1798 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1799 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1800=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh18012026/11/10 21:16:10 INFO Received uploads request method=POST path=/api/pending_closures18022026/11/10 21:16:10 INFO Received uploads request method=POST path=/api/pending_closures18032026/11/10 21:16:10 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)18042026/11/10 21:16:10 INFO Uploading r8nmxf534f061vds5pz66lq1fh39pf8c-shared-dep (136B)18052026/11/10 21:16:10 INFO Uploading ca24dxg2p7r7pkiacsxqxablgw3flnia-b (256B)18062026/11/10 21:16:10 WARN Failed to register uploaded object key=r83pim7fpc4awfmi45x5c1mmvsv7pgdw.ls error="server returned 404: 404 page not found\n"18072026/11/10 21:16:10 WARN Failed to register uploaded object key=r8nmxf534f061vds5pz66lq1fh39pf8c.ls error="server returned 404: 404 page not found\n"18082026/11/10 21:16:10 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18092026/11/10 21:16:10 WARN Failed to register uploaded object key=ca24dxg2p7r7pkiacsxqxablgw3flnia.ls error="server returned 404: 404 page not found\n"18102026/11/10 21:16:10 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign18112026/11/10 21:16:10 WARN Failed to register uploaded object key=nar/1j7zfi41n61pm56j1mpmbdfjrrrgmj4640hqib8x6ml6ipy43qkq.nar.zst error="server returned 404: 404 page not found\n"18122026/11/10 21:16:10 INFO Signed narinfos id=2 count=21813=== NAME TestPinProtectsFromGC1814 client_integration_test.go:887: Pin successfully protected closure from garbage collection18152026/11/10 21:16:10 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18162026/11/10 21:16:10 INFO Signed narinfos id=1 count=218172026/11/10 21:16:10 INFO Uploading 4 narinfos18182026/11/10 21:16:10 WARN Failed to register uploaded object key=r83pim7fpc4awfmi45x5c1mmvsv7pgdw.narinfo error="server returned 404: 404 page not found\n"18192026/11/10 21:16:10 WARN Failed to register uploaded object key=r8nmxf534f061vds5pz66lq1fh39pf8c.narinfo error="server returned 404: 404 page not found\n"18202026/11/10 21:16:10 WARN Failed to register uploaded object key=ca24dxg2p7r7pkiacsxqxablgw3flnia.narinfo error="server returned 404: 404 page not found\n"18212026/11/10 21:16:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18222026/11/10 21:16:10 WARN Failed to register uploaded object key=r8nmxf534f061vds5pz66lq1fh39pf8c.narinfo error="server returned 404: 404 page not found\n"1823--- PASS: TestPinProtectsFromGC (12.55s)1824=== CONT TestResolveDBConnectionString/flag_wins1825=== CONT TestResolveDBConnectionString/missing_file_is_an_error1826=== CONT TestResolveDBConnectionString/file_when_flag_empty1827=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1828=== CONT TestResolveDBConnectionString/nothing_configured1829--- PASS: TestResolveDBConnectionString (0.01s)1830 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1831 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1832 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1833 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1834 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1835=== CONT TestPush_RejectsBadRequests/no_roots18362026/11/10 21:16:10 INFO Received push request method=POST path=/api/pushes1837=== CONT TestPush_RejectsBadRequests/bad_root18382026/11/10 21:16:10 INFO Received push request method=POST path=/api/pushes1839=== CONT TestPush_RejectsBadRequests/root_not_in_objects18402026/11/10 21:16:10 INFO Received push request method=POST path=/api/pushes1841=== CONT TestPush_RejectsBadRequests/no_objects18422026/11/10 21:16:10 INFO Received push request method=POST path=/api/pushes1843--- PASS: TestPush_RejectsBadRequests (6.78s)1844 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1845 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1846 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1847 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1848=== CONT TestServerTLSConfig/no_client_CA1849=== CONT TestServerTLSConfig/not_a_PEM_file1850=== CONT TestServerTLSConfig/missing_CA_file1851--- PASS: TestServerTLSConfig (0.01s)1852 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1853 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1854 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1855=== CONT TestClientErrorHandling/InvalidStorePath18562026/11/10 21:16:10 INFO Completed upload id=1 objects=6 duration=46.134416ms18572026/11/10 21:16:10 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete18582026/11/10 21:16:10 INFO Completed upload id=2 objects=6 duration=2.588125ms18592026/11/10 21:16:10 INFO Upload complete. (458ms)1860=== NAME TestClientFallsBackToClosures1861 client_pushes_test.go:112: Retrieved narinfo from S3:1862 StorePath: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientFallsBackToClosures326619293/001/store/r8nmxf534f061vds5pz66lq1fh39pf8c-shared-dep1863 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1864 Compression: zstd1865 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821866 NarSize: 1361867 References: 1868 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1869 client_pushes_test.go:112: Retrieved narinfo from S3:1870 StorePath: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientFallsBackToClosures326619293/001/store/r83pim7fpc4awfmi45x5c1mmvsv7pgdw-a1871 URL: nar/1j7zfi41n61pm56j1mpmbdfjrrrgmj4640hqib8x6ml6ipy43qkq.nar.zst1872 Compression: zstd1873 NarHash: sha256:1j7zfi41n61pm56j1mpmbdfjrrrgmj4640hqib8x6ml6ipy43qkq1874 NarSize: 2561875 References: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientFallsBackToClosures326619293/001/store/r8nmxf534f061vds5pz66lq1fh39pf8c-shared-dep1876 CA: text:sha256:1dg9xfqisxh005shbzv9hpwijxl3z8qjsbmv3rv1s3yfn927mxph1877 client_pushes_test.go:112: Retrieved narinfo from S3:1878 StorePath: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientFallsBackToClosures326619293/001/store/ca24dxg2p7r7pkiacsxqxablgw3flnia-b1879 URL: nar/1j7zfi41n61pm56j1mpmbdfjrrrgmj4640hqib8x6ml6ipy43qkq.nar.zst1880 Compression: zstd1881 NarHash: sha256:1j7zfi41n61pm56j1mpmbdfjrrrgmj4640hqib8x6ml6ipy43qkq1882 NarSize: 2561883 References: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientFallsBackToClosures326619293/001/store/r8nmxf534f061vds5pz66lq1fh39pf8c-shared-dep1884 CA: text:sha256:1dg9xfqisxh005shbzv9hpwijxl3z8qjsbmv3rv1s3yfn927mxph1885--- PASS: TestClientFallsBackToClosures (7.98s)1886=== CONT TestClientErrorHandling/ServerNotAvailable18872026/11/10 21:16:11 INFO Received push request method=POST path=/api/pushes1888=== NAME TestClientIntegration1889 client_integration_test.go:291: Created store path: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientIntegration950093228/002/store/q03qy2csk01sssmqhvvcybjkybxkxv0q-test-file.txt18902026/11/10 21:16:11 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)18912026/11/10 21:16:11 INFO Uploading qsscfh8441xc8qy48x5cxdm5dxrfyjsc-a (256B)18922026/11/10 21:16:11 INFO Uploading klrxkydcslv8c4ci2nmn5z6azwa4w0qw-shared-dep (136B)18932026/11/10 21:16:11 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18942026/11/10 21:16:11 WARN Failed to register uploaded object key=nar/0m7sw4la65pmy245l5i2w0ly9lcic8g1k5x87dkbilbryyy26jvp.nar.zst error="server returned 404: 404 page not found\n"18952026/11/10 21:16:11 WARN Failed to register uploaded object key=qsscfh8441xc8qy48x5cxdm5dxrfyjsc.ls error="server returned 404: 404 page not found\n"18962026/11/10 21:16:11 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18972026/11/10 21:16:11 WARN Failed to register uploaded object key=q6fxflvpi4rnlg2760bv6ac3ajflil6n.ls error="server returned 404: 404 page not found\n"18982026/11/10 21:16:11 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18992026/11/10 21:16:11 WARN Failed to register uploaded object key=klrxkydcslv8c4ci2nmn5z6azwa4w0qw.ls error="server returned 404: 404 page not found\n"19002026/11/10 21:16:11 INFO Signed narinfos id=1 count=319012026/11/10 21:16:11 INFO Uploading 3 narinfos19022026/11/10 21:16:11 WARN Request failed, retrying attempt=2 backoff=196.578622ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19032026/11/10 21:16:11 WARN Failed to register uploaded object key=qsscfh8441xc8qy48x5cxdm5dxrfyjsc.narinfo error="server returned 404: 404 page not found\n"19042026/11/10 21:16:11 WARN Failed to register uploaded object key=q6fxflvpi4rnlg2760bv6ac3ajflil6n.narinfo error="server returned 404: 404 page not found\n"19052026/11/10 21:16:11 INFO Received push request method=POST path=/api/pushes19062026/11/10 21:16:11 INFO Received complete push request method=POST path=/api/pushes/1/complete19072026/11/10 21:16:11 WARN Failed to register uploaded object key=klrxkydcslv8c4ci2nmn5z6azwa4w0qw.narinfo error="server returned 404: 404 page not found\n"19082026/11/10 21:16:11 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19092026/11/10 21:16:11 INFO Uploading q03qy2csk01sssmqhvvcybjkybxkxv0q-test-file.txt (152B)19102026/11/10 21:16:11 INFO Completed push id=1 objects=8 duration=34.074625ms19112026/11/10 21:16:11 INFO Upload complete. (369ms)1912=== NAME TestClientPushesUseOnePush1913 client_pushes_test.go:97: Retrieved narinfo from S3:1914 StorePath: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientPushesUseOnePush1484699897/001/store/klrxkydcslv8c4ci2nmn5z6azwa4w0qw-shared-dep1915 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1916 Compression: zstd1917 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821918 NarSize: 1361919 References: 1920 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1921 client_pushes_test.go:97: Retrieved narinfo from S3:1922 StorePath: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientPushesUseOnePush1484699897/001/store/qsscfh8441xc8qy48x5cxdm5dxrfyjsc-a1923 URL: nar/0m7sw4la65pmy245l5i2w0ly9lcic8g1k5x87dkbilbryyy26jvp.nar.zst1924 Compression: zstd1925 NarHash: sha256:0m7sw4la65pmy245l5i2w0ly9lcic8g1k5x87dkbilbryyy26jvp1926 NarSize: 2561927 References: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientPushesUseOnePush1484699897/001/store/klrxkydcslv8c4ci2nmn5z6azwa4w0qw-shared-dep1928 CA: text:sha256:0s6fyw2kp6hm22dgkii9yzcbcfdisbnlb31kkg4nb2gkw9fqdhm31929 client_pushes_test.go:97: Retrieved narinfo from S3:1930 StorePath: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientPushesUseOnePush1484699897/001/store/q6fxflvpi4rnlg2760bv6ac3ajflil6n-b1931 URL: nar/0m7sw4la65pmy245l5i2w0ly9lcic8g1k5x87dkbilbryyy26jvp.nar.zst1932 Compression: zstd1933 NarHash: sha256:0m7sw4la65pmy245l5i2w0ly9lcic8g1k5x87dkbilbryyy26jvp1934 NarSize: 2561935 References: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientPushesUseOnePush1484699897/001/store/klrxkydcslv8c4ci2nmn5z6azwa4w0qw-shared-dep1936 CA: text:sha256:0s6fyw2kp6hm22dgkii9yzcbcfdisbnlb31kkg4nb2gkw9fqdhm319372026/11/10 21:16:11 INFO Aborted multipart uploads count=0 kept=019382026/11/10 21:16:11 WARN Failed to register uploaded object key=q03qy2csk01sssmqhvvcybjkybxkxv0q.ls error="server returned 404: 404 page not found\n"19392026/11/10 21:16:11 WARN Force mode enabled - objects will be deleted immediately without grace period19402026/11/10 21:16:11 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19412026/11/10 21:16:11 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"19422026/11/10 21:16: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=019432026/11/10 21:16:11 INFO Signed narinfos id=1 count=119442026/11/10 21:16:11 INFO Uploading 1 narinfos19452026/11/10 21:16:11 INFO Vacuumed table table=pending_closures19462026/11/10 21:16:11 INFO Received complete push request method=POST path=/api/pushes/1/complete19472026/11/10 21:16:11 WARN Request failed, retrying attempt=3 backoff=421.463665ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19482026/11/10 21:16:11 WARN Failed to register uploaded object key=q03qy2csk01sssmqhvvcybjkybxkxv0q.narinfo error="server returned 404: 404 page not found\n"19492026/11/10 21:16:11 INFO Vacuumed table table=pending_objects19502026/11/10 21:16:11 INFO Completed push id=1 objects=3 duration=29.954959ms19512026/11/10 21:16:11 INFO Upload complete. (345ms)1952--- PASS: TestClientPushesUseOnePush (8.16s)1953=== CONT TestClientErrorHandling/InvalidAuthToken19542026/11/10 21:16:11 INFO Vacuumed table table=multipart_uploads19552026/11/10 21:16:11 INFO Vacuumed table table=closures19562026/11/10 21:16:11 INFO Vacuumed table table=objects19572026/11/10 21:16:11 INFO All 1 paths already cached1958=== NAME TestClientIntegration1959 client_integration_test.go:317: Retrieved narinfo from S3:1960 StorePath: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientIntegration950093228/002/store/q03qy2csk01sssmqhvvcybjkybxkxv0q-test-file.txt1961 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1962 Compression: zstd1963 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11964 NarSize: 1521965 References: 1966 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11967=== NAME TestOrphanedObjectsGCStressTest1968 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1969=== NAME TestClientIntegration1970 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1971--- PASS: TestCommitRacingPendingCleanupKeepsObjects (7.29s)1972=== NAME TestClientIntegration1973 client_integration_test.go:318: Decompressed .ls content (64 bytes):1974 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1975=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1976--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (7.22s)1977=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1978=== NAME TestOrphanedObjectsGCStressTest1979 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion19802026/11/10 21:16:11 WARN Request failed, retrying attempt=4 backoff=807.441247ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19812026/11/10 21:16:11 INFO Received push request method=POST path=/api/pushes19822026/11/10 21:16:11 INFO Object in database but missing from S3 key=q03qy2csk01sssmqhvvcybjkybxkxv0q.ls19832026/11/10 21:16:11 WARN Found objects in DB but missing from S3, will re-upload count=119842026/11/10 21:16:11 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19852026/11/10 21:16:12 INFO Received complete push request method=POST path=/api/pushes/2/complete19862026/11/10 21:16:12 WARN Failed to register uploaded object key=q03qy2csk01sssmqhvvcybjkybxkxv0q.ls error="server returned 404: 404 page not found\n"19872026/11/10 21:16:12 INFO Completed push id=2 objects=3 duration=772.541µs19882026/11/10 21:16:12 INFO Upload complete. (123ms)1989--- PASS: TestCacheStatsHandler (7.55s)1990=== CONT TestGCEndsOnShutdown/before_the_run1991=== NAME TestClientIntegration1992 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1993 client_integration_test.go:335: Decompressed .ls content (49 bytes):1994 {"version":1,"root":{"type":"regular","size":39}}19952026/11/10 21:16:12 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1996--- PASS: TestService_AuthMiddleware (7.13s)1997=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark19982026/11/10 21:16:12 INFO Received push request method=POST path=/api/pushes19992026/11/10 21:16:12 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20002026/11/10 21:16:12 INFO Received complete push request method=POST path=/api/pushes/3/complete20012026/11/10 21:16:12 WARN Failed to register uploaded object key=q03qy2csk01sssmqhvvcybjkybxkxv0q.ls error="server returned 404: 404 page not found\n"20022026/11/10 21:16:12 INFO Completed push id=3 objects=3 duration=693.584µs20032026/11/10 21:16:12 INFO Upload complete. (143ms)2004=== NAME TestClientIntegration2005 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)2006 client_integration_test.go:352: Decompressed .ls content (49 bytes):2007 {"version":1,"root":{"type":"regular","size":39}}2008 client_integration_test.go:363: Testing garbage collection...20092026/11/10 21:16:12 INFO Starting cleanup of old closures method=DELETE path=/api/closures20102026/11/10 21:16:12 INFO Garbage collection started20112026/11/10 21:16:12 INFO Aborted multipart uploads count=0 kept=020122026/11/10 21:16:12 WARN Force mode enabled - objects will be deleted immediately without grace period20132026/11/10 21:16:12 WARN Request failed, retrying attempt=5 backoff=1.725270447s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2014--- PASS: TestService_ReadScope_PublicByDefault (7.81s)2015=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete20162026/11/10 21:16:13 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=020172026/11/10 21:16:13 INFO Vacuumed table table=pending_closures20182026/11/10 21:16:13 INFO Vacuumed table table=pending_objects20192026/11/10 21:16:13 INFO Vacuumed table table=multipart_uploads20202026/11/10 21:16:13 INFO Vacuumed table table=closures20212026/11/10 21:16:13 INFO Vacuumed table table=objects2022=== NAME TestClientCADerivations2023 client_ca_test.go:136: Built CA derivation: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientCADerivations943256862/001/store/a8ka41l4nbdnnsvn3yy7wz80s97mcip0-ca-test2024=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2025=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2026=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2027=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2028=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2029=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2030=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2031=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2032=== CONT TestCacheConfigHandler/full_config,_no_issuer2033=== CONT TestCacheConfigHandler/upstream_keys_advertised2034=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2035=== CONT TestCacheConfigHandler/no_signing_keys2036=== CONT TestCacheConfigHandler/no_cache_url_configured2037--- PASS: TestCacheConfigHandler (0.00s)2038 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2039 --- PASS: TestCacheConfigHandler/upstream_keys_advertised (0.00s)2040 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2041 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2042 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2043=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2044=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20452026/11/10 21:16:13 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]2046=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2047=== NAME TestClientCADerivations20482026/11/10 21:16:13 WARN Authentication failed token_preview=eyJhbGciOi...PQvxyw-SbA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2049 client_ca_test.go:139: Found 1 dependencies (including self)2050=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2051--- PASS: TestService_AuthMiddleware_OIDC (6.53s)2052 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2053 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2054 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)2055 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)20562026/11/10 21:16:13 INFO Received push request method=POST path=/api/pushes20572026/11/10 21:16:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20582026/11/10 21:16:13 INFO Uploading a8ka41l4nbdnnsvn3yy7wz80s97mcip0-ca-test (144B)20592026/11/10 21:16:13 WARN Failed to register uploaded object key=a8ka41l4nbdnnsvn3yy7wz80s97mcip0.ls error="server returned 404: 404 page not found\n"20602026/11/10 21:16:13 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"20612026/11/10 21:16:13 WARN Failed to register uploaded object key=log/jn9r2znr61s7b2ssk1d7wiij3v1hiwsp-ca-test.drv error="server returned 404: 404 page not found\n"20622026/11/10 21:16:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20632026/11/10 21:16:13 INFO Signed narinfos id=1 count=120642026/11/10 21:16:13 INFO Uploading 1 narinfos2065--- PASS: TestService_ReadAuthMiddleware (6.71s)20662026/11/10 21:16:13 INFO Received complete push request method=POST path=/api/pushes/1/complete20672026/11/10 21:16:13 WARN Failed to register uploaded object key=a8ka41l4nbdnnsvn3yy7wz80s97mcip0.narinfo error="server returned 404: 404 page not found\n"20682026/11/10 21:16:13 INFO Completed push id=1 objects=4 duration=36.460083ms20692026/11/10 21:16:13 INFO Upload complete. (381ms)2070=== NAME TestClientCADerivations2071 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientCADerivations943256862/001/store/a8ka41l4nbdnnsvn3yy7wz80s97mcip0-ca-test2072 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2073 Compression: zstd2074 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2075 NarSize: 1442076 References: 2077 Deriver: /private/var/tb/4/scratch/b3a0d46031104912/build/TestClientCADerivations943256862/001/store/jn9r2znr61s7b2ssk1d7wiij3v1hiwsp-ca-test.drv2078 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2079 client_ca_test.go:185: Checking for realisation files in S3...2080 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2081 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache2082 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket86?endpoint=http://localhost:53528&region=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/4/scratch/b3a0d46031104912/build/TestClientCADerivations943256862/001/store'2083 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12084=== RUN TestService_RequireScope_OIDC/builder_may_write2085=== PAUSE TestService_RequireScope_OIDC/builder_may_write2086=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2087=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2088=== RUN TestService_RequireScope_OIDC/ops_may_admin2089=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2090=== RUN TestService_RequireScope_OIDC/ops_may_not_write2091=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2092=== RUN TestService_RequireScope_OIDC/reader_may_not_write2093=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2094=== RUN TestService_RequireScope_OIDC/static_token_may_admin2095=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2096=== RUN TestService_RequireScope_OIDC/static_token_may_write2097=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2098=== RUN TestService_RequireScope_OIDC/reader_may_read2099=== PAUSE TestService_RequireScope_OIDC/reader_may_read2100=== RUN TestService_RequireScope_OIDC/writer_implies_read2101=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2102=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2103=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2104=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc2105=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc2106=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2107=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2108=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2109=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2110=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2111=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2112=== CONT TestService_RequireScope_OIDC/builder_may_write2113=== CONT TestService_RequireScope_OIDC/reader_may_read2114=== CONT TestService_RequireScope_OIDC/reader_may_not_write2115=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2116=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2117=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2118=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2119=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc21202026/11/10 21:16:14 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]2121=== CONT TestService_RequireScope_OIDC/static_token_may_write2122=== CONT TestService_RequireScope_OIDC/ops_may_not_write2123=== CONT TestService_RequireScope_OIDC/ops_may_admin2124=== CONT TestService_RequireScope_OIDC/writer_implies_read2125=== CONT TestService_RequireScope_OIDC/static_token_may_admin2126=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2127--- PASS: TestService_RequireScope_OIDC (7.04s)2128 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2129 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2130 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2131 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2132 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2133 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2134 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2135 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2136 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2137 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2138 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2139 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2140 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2141 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2142--- PASS: TestClientCADerivations (9.24s)21432026/11/10 21:16:14 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"21442026/11/10 21:16:14 WARN mTLS auth: bound subjects configured but subject DN unavailable21452026/11/10 21:16:14 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2146--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (6.91s)21472026/11/10 21:16:14 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21482026/11/10 21:16:14 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02149=== NAME TestClientIntegration2150 client_integration_test.go:370: Objects in database after GC:2151 client_integration_test.go:370: Successfully deleted all objects with GC --force21522026/11/10 21:16:14 WARN Request failed, retrying attempt=2 backoff=204.177756ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2153--- PASS: TestClientIntegration (10.77s)21542026/11/10 21:16:14 WARN Request failed, retrying attempt=3 backoff=372.153411ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21552026/11/10 21:16:14 INFO Received uploads request method=POST path=/api/pending_closures21562026/11/10 21:16:15 WARN Request failed, retrying attempt=4 backoff=781.185574ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21572026/11/10 21:16:15 INFO Received uploads request method=POST path=/api/pending_closures2158--- PASS: TestDeleteClosuresRacingPins (12.50s)21592026/11/10 21:16:15 INFO Received uploads request method=POST path=/api/pending_closures21602026/11/10 21:16:16 WARN Request failed, retrying attempt=5 backoff=1.501517049s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21612026/11/10 21:16:16 INFO Received uploads request method=POST path=/api/pending_closures21622026/11/10 21:16:16 INFO Received uploads request method=POST path=/api/pending_closures21632026/11/10 21:16:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21642026/11/10 21:16:17 INFO Received uploads request method=POST path=/api/pending_closures21652026/11/10 21:16:17 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=NGI2NDRjOTMtM2QxNC00MjNmLTg5MDItMTI3MTM4ZWFjM2ZjLjM4MGUxMjNlLTQ3OTQtNDRhOS05NDY4LWIwZWQxOTg0YmFhMngxNzk0MzQ1Mzc0OTU5OTU5MDAw parts=1021662026/11/10 21:16:17 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21672026/11/10 21:16:17 INFO Completed upload id=1 objects=3 duration=31.787792ms21682026/11/10 21:16:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21692026/11/10 21:16:17 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=NGI2NDRjOTMtM2QxNC00MjNmLTg5MDItMTI3MTM4ZWFjM2ZjLjA0ZTA3MGY3LTA2OTQtNDIyYi05MDNhLWI4OGU0ZjM1NGFlY3gxNzk0MzQ1Mzc1NDA5MDI4MDAw parts=1021702026/11/10 21:16:17 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21712026/11/10 21:16:17 INFO Completed upload id=1 objects=3 duration=19.359ms2172--- PASS: TestPendingClosureWriteTimeout (0.05s)2173 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2174 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2175 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2176 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (9.11s)21772026/11/10 21:16:17 INFO Received uploads request method=POST path=/api/pending_closures21782026/11/10 21:16:17 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21792026/11/10 21:16:17 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21802026/11/10 21:16:18 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21812026/11/10 21:16:18 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=NGI2NDRjOTMtM2QxNC00MjNmLTg5MDItMTI3MTM4ZWFjM2ZjLjJmMTJmOGJiLWViYTYtNGQ0YS04MGU5LTY4NjVhZjcwNzUyY3gxNzk0MzQ1Mzc1ODA2NzUxMDAw parts=1021822026/11/10 21:16:18 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21832026/11/10 21:16:18 INFO Completed upload id=1 objects=3 duration=23.212042ms21842026/11/10 21:16:18 INFO Received uploads request method=POST path=/api/pending_closures21852026/11/10 21:16:18 INFO Received uploads request method=POST path=/api/pending_closures21862026/11/10 21:16:18 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst21872026/11/10 21:16:18 WARN Found objects in DB but missing from S3, will re-upload count=121882026/11/10 21:16:18 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2189--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2190 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (8.78s)2191 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (8.49s)21922026/11/10 21:16:18 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=NGI2NDRjOTMtM2QxNC00MjNmLTg5MDItMTI3MTM4ZWFjM2ZjLmFmZTE0NGIyLTU1ZjUtNDk1Yy1hZjI0LTgzODdjMjZlOGY5YngxNzk0MzQ1Mzc2MjcyNTE0MDAw parts=1021932026/11/10 21:16:18 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21942026/11/10 21:16:18 INFO Completed upload id=1 objects=3 duration=10.464334ms21952026/11/10 21:16:18 INFO Received uploads request method=POST path=/api/pending_closures21962026/11/10 21:16:19 INFO Received uploads request method=POST path=/api/pending_closures21972026/11/10 21:16:19 INFO Aborted multipart uploads count=0 kept=021982026/11/10 21:16:19 WARN Force mode enabled - objects will be deleted immediately without grace period21992026/11/10 21:16:19 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22002026/11/10 21:16:19 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=NGI2NDRjOTMtM2QxNC00MjNmLTg5MDItMTI3MTM4ZWFjM2ZjLmQzODFiNzUyLTVlN2EtNDEyMi04YWVlLThhMjJlZjc5YTk3YXgxNzk0MzQ1Mzc2NzAzNDUyMDAw parts=1022012026/11/10 21:16:19 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22022026/11/10 21:16:19 INFO Completed upload id=1 objects=3 duration=23.311792ms22032026/11/10 21:16:19 INFO Received uploads request method=POST path=/api/pending_closures22042026/11/10 21:16:19 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=022052026/11/10 21:16:19 INFO Vacuumed table table=pending_closures22062026/11/10 21:16:19 INFO Vacuumed table table=pending_objects22072026/11/10 21:16:19 INFO Vacuumed table table=multipart_uploads22082026/11/10 21:16:19 INFO Vacuumed table table=closures22092026/11/10 21:16:19 INFO Vacuumed table table=objects22102026/11/10 21:16:19 INFO Received uploads request method=POST path=/api/pending_closures22112026/11/10 21:16:19 INFO Aborted multipart uploads count=0 kept=022122026/11/10 21:16:19 WARN Force mode enabled - objects will be deleted immediately without grace period22132026/11/10 21:16:19 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=022142026/11/10 21:16:19 INFO Vacuumed table table=pending_closures22152026/11/10 21:16:19 INFO Vacuumed table table=pending_objects22162026/11/10 21:16:19 INFO Vacuumed table table=multipart_uploads22172026/11/10 21:16:19 INFO Vacuumed table table=closures22182026/11/10 21:16:19 INFO Vacuumed table table=objects2219--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2220 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (8.15s)2221 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (8.17s)22222026/11/10 21:16:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22232026/11/10 21:16:20 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22242026/11/10 21:16:20 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=NGI2NDRjOTMtM2QxNC00MjNmLTg5MDItMTI3MTM4ZWFjM2ZjLjU0MDU5ODk1LWNmNTItNDQ5Yy1iNDg2LTkxZjk0MjZiMjhkNHgxNzk0MzQ1Mzc4MzUxNzI5MDAw parts=1022252026/11/10 21:16:20 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22262026/11/10 21:16:20 INFO Completed upload id=2 objects=3 duration=304.666µs22272026/11/10 21:16:20 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2228--- PASS: TestClientErrorHandling (0.00s)2229 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.85s)2230 --- PASS: TestClientErrorHandling/InvalidStorePath (7.96s)2231 --- PASS: TestClientErrorHandling/InvalidAuthToken (8.81s)22322026/11/10 21:16:20 INFO Aborted multipart uploads count=0 kept=022332026/11/10 21:16:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22342026/11/10 21:16:20 WARN Force mode enabled - objects will be deleted immediately without grace period22352026-11-10 21:16:20.563 UTC [98358] ERROR: canceling statement due to user request22362026-11-10 21:16:20.563 UTC [98358] STATEMENT: -- name: MarkStaleObjects :execrows2237 WITH RECURSIVE ct AS (2238 SELECT timezone('UTC', now()) AS now2239 ),2240 closure_reach AS (2241 -- Start with all closure keys2242 SELECT o.key, o.refs2243 FROM objects o2244 INNER JOIN closures c ON o.key = c.key2245 UNION2246 -- Recursively add all referenced objects2247 SELECT o.key, o.refs2248 FROM objects o2249 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2250 ),2251 reachable_objects AS (2252 SELECT DISTINCT key FROM closure_reach2253 ),2254 stale_objects AS (2255 SELECT o.key2256 FROM objects AS o, ct2257 WHERE2258 NOT EXISTS (2259 SELECT 12260 FROM reachable_objects ro2261 WHERE ro.key = o.key2262 )2263 AND NOT EXISTS (2264 SELECT 12265 FROM pending_objects AS po2266 WHERE po.key = o.key2267 )2268 AND o.deleted_at IS NULL -- Only mark fresh objects2269 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2270 FOR UPDATE2271 )2272 UPDATE objects2273 SET2274 deleted_at = ct.now,2275 first_deleted_at = COALESCE(first_deleted_at, ct.now)2276 FROM stale_objects, ct2277 WHERE objects.key = stale_objects.key2278 22792026/11/10 21:16:20 INFO Received uploads request method=POST path=/api/pending_closures22802026/11/10 21:16:20 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22812026/11/10 21:16:20 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo22822026/11/10 21:16:20 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=NGI2NDRjOTMtM2QxNC00MjNmLTg5MDItMTI3MTM4ZWFjM2ZjLjNkYWIxODI0LTMzODgtNDNjNy04Mjc5LWQ3NWNjNzZiMGQ0M3gxNzk0MzQ1Mzc4ODM5MTY3MDAw parts=1022832026/11/10 21:16:20 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22842026/11/10 21:16:20 INFO Completed upload id=2 objects=3 duration=968.917µs22852026/11/10 21:16:20 INFO Aborted multipart uploads count=0 kept=022862026/11/10 21:16:20 WARN Force mode enabled - objects will be deleted immediately without grace period22872026/11/10 21:16:20 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:53528/bucket106/?delete=\": context canceled"2288--- PASS: TestGCEndsOnShutdown (0.01s)2289 --- PASS: TestGCEndsOnShutdown/before_the_run (8.13s)2290 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (8.22s)2291 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (7.72s)22922026/11/10 21:16:20 INFO Received uploads request method=POST path=/api/pending_closures22932026/11/10 21:16:20 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22942026/11/10 21:16:20 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2295--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.05s)2296 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (10.45s)2297 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (10.64s)2298 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (10.83s)2299 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (12.75s)2300 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (12.35s)2301=== NAME TestOrphanedObjectsGCStressTest2302 orphaned_objects_gc_test.go:503: Stress test completed successfully:2303 orphaned_objects_gc_test.go:504: - Active objects preserved: 202304 orphaned_objects_gc_test.go:505: - Objects deleted: 2102305 orphaned_objects_gc_test.go:506: - Total GC'd: 2102306--- PASS: TestOrphanedObjectsGCStressTest (37.52s)2307PASS2308{"timestamp":"2026-11-10T21:16:28.51663Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:54013","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}2309{"timestamp":"2026-11-10T21:16:28.51663Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:53639","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(6)"}2310{"timestamp":"2026-11-10T21:16:28.517314Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:53926","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}2311{"timestamp":"2026-11-10T21:16:28.517332Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:53925","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}2312{"timestamp":"2026-11-10T21:16:28.517716Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:54038","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}23132026-11-10 21:16:28.662 UTC [97797] LOG: received smart shutdown request23142026-11-10 21:16:28.663 UTC [97797] LOG: background worker "logical replication launcher" (PID 97807) exited with exit code 123152026-11-10 21:16:28.667 UTC [97802] LOG: shutting down23162026-11-10 21:16:28.668 UTC [97802] LOG: checkpoint starting: shutdown immediate23172026-11-10 21:16:30.047 UTC [97802] LOG: checkpoint complete: wrote 11548 buffers (70.5%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.629 s, sync=0.736 s, total=1.380 s; sync files=36061, longest=0.034 s, average=0.001 s; distance=529927 kB, estimate=529927 kB; lsn=0/21D0ED10, redo lsn=0/21D0ED1023182026-11-10 21:16:30.054 UTC [97797] LOG: database system is shut down2319Running OIDC tests...2320=== RUN TestAudienceForIssuer2321=== PAUSE TestAudienceForIssuer2322=== RUN TestGlobMatch2323=== PAUSE TestGlobMatch2324=== RUN TestValidateToken_ValidToken2325=== PAUSE TestValidateToken_ValidToken2326=== RUN TestValidateToken_WrongAudience2327=== PAUSE TestValidateToken_WrongAudience2328=== RUN TestValidateToken_Expired2329=== PAUSE TestValidateToken_Expired2330=== RUN TestValidateToken_BoundClaimsMismatch2331=== PAUSE TestValidateToken_BoundClaimsMismatch2332=== RUN TestValidateToken_BoundSubjectMismatch2333=== PAUSE TestValidateToken_BoundSubjectMismatch2334=== RUN TestValidateToken_MultipleProviders2335=== PAUSE TestValidateToken_MultipleProviders2336=== RUN TestValidateToken_NoMatchingProvider2337=== PAUSE TestValidateToken_NoMatchingProvider2338=== RUN TestValidateToken_KubernetesServiceAccount2339=== PAUSE TestValidateToken_KubernetesServiceAccount2340=== RUN TestNewValidator_KubernetesRequiresCA2341=== PAUSE TestNewValidator_KubernetesRequiresCA2342=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2343=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2344=== RUN TestPins_ReservedForMatchingRule2345=== PAUSE TestPins_ReservedForMatchingRule2346=== RUN TestPins_TopLevelShorthand2347=== PAUSE TestPins_TopLevelShorthand2348=== RUN TestPins_ConfigValidation2349=== PAUSE TestPins_ConfigValidation2350=== RUN TestScopes_LegacyProviderDefaultsToWrite2351=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2352=== RUN TestScopes_Rules2353=== PAUSE TestScopes_Rules2354=== RUN TestScopes_ConfigValidation2355=== PAUSE TestScopes_ConfigValidation2356=== CONT TestAudienceForIssuer2357--- PASS: TestAudienceForIssuer (0.00s)2358=== CONT TestValidateToken_NoMatchingProvider2359=== CONT TestPins_ReservedForMatchingRule2360=== CONT TestValidateToken_Expired2361=== CONT TestScopes_ConfigValidation2362=== CONT TestScopes_Rules2363=== CONT TestScopes_LegacyProviderDefaultsToWrite2364--- PASS: TestScopes_ConfigValidation (0.00s)2365=== CONT TestPins_TopLevelShorthand2366=== CONT TestValidateToken_BoundClaimsMismatch2367=== CONT TestValidateToken_WrongAudience2368=== CONT TestValidateToken_ValidToken2369=== CONT TestGlobMatch2370=== RUN TestGlobMatch/foo_foo2371=== PAUSE TestGlobMatch/foo_foo2372=== RUN TestGlobMatch/foo_bar2373=== PAUSE TestGlobMatch/foo_bar2374=== RUN TestGlobMatch/*_2375=== PAUSE TestGlobMatch/*_2376=== RUN TestGlobMatch/*_anything2377=== PAUSE TestGlobMatch/*_anything2378=== RUN TestGlobMatch/foo*_foo2379=== PAUSE TestGlobMatch/foo*_foo2380=== RUN TestGlobMatch/foo*_foobar2381=== PAUSE TestGlobMatch/foo*_foobar2382=== RUN TestGlobMatch/foo*_bar2383=== PAUSE TestGlobMatch/foo*_bar2384=== RUN TestGlobMatch/*bar_bar2385=== PAUSE TestGlobMatch/*bar_bar2386=== RUN TestGlobMatch/*bar_foobar2387=== PAUSE TestGlobMatch/*bar_foobar2388=== RUN TestGlobMatch/*bar_foo2389=== PAUSE TestGlobMatch/*bar_foo2390=== RUN TestGlobMatch/foo*bar_foobar2391=== PAUSE TestGlobMatch/foo*bar_foobar2392=== RUN TestGlobMatch/foo*bar_foo123bar2393=== PAUSE TestGlobMatch/foo*bar_foo123bar2394=== RUN TestGlobMatch/foo*bar_foobarbaz2395=== PAUSE TestGlobMatch/foo*bar_foobarbaz2396=== RUN TestGlobMatch/*/*_foo/bar2397=== PAUSE TestGlobMatch/*/*_foo/bar2398=== RUN TestGlobMatch/*/*_foo2399=== PAUSE TestGlobMatch/*/*_foo2400=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2401=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2402=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02403=== CONT TestPins_ConfigValidation2404=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2405--- PASS: TestPins_ConfigValidation (0.00s)2406=== CONT TestValidateToken_MultipleProviders2407=== CONT TestNewValidator_KubernetesRequiresCA2408=== CONT TestValidateToken_BoundSubjectMismatch2409=== CONT TestValidateToken_KubernetesServiceAccount2410=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02411=== RUN TestGlobMatch/refs/*/main_refs/heads/main2412=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2413=== RUN TestGlobMatch/fo?_foo2414=== PAUSE TestGlobMatch/fo?_foo2415=== RUN TestGlobMatch/fo?_fo2416=== PAUSE TestGlobMatch/fo?_fo2417=== RUN TestGlobMatch/fo?_fooo2418=== PAUSE TestGlobMatch/fo?_fooo2419=== RUN TestGlobMatch/?oo_foo2420=== PAUSE TestGlobMatch/?oo_foo2421=== RUN TestGlobMatch/?oo_boo2422=== PAUSE TestGlobMatch/?oo_boo2423=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2424=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2425=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2426=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2427=== CONT TestGlobMatch/foo_foo2428=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2429=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2430=== CONT TestGlobMatch/?oo_boo2431=== CONT TestGlobMatch/?oo_foo2432=== CONT TestGlobMatch/fo?_fooo2433=== CONT TestGlobMatch/fo?_fo2434=== CONT TestGlobMatch/fo?_foo2435=== CONT TestGlobMatch/refs/*/main_refs/heads/main2436=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02437=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2438=== CONT TestGlobMatch/*/*_foo2439=== CONT TestGlobMatch/*/*_foo/bar2440=== CONT TestGlobMatch/foo*bar_foobarbaz2441=== CONT TestGlobMatch/foo*bar_foo123bar2442=== CONT TestGlobMatch/foo*bar_foobar2443=== CONT TestGlobMatch/*bar_foo2444=== CONT TestGlobMatch/*bar_foobar2445=== CONT TestGlobMatch/*bar_bar2446=== CONT TestGlobMatch/foo*_bar2447=== CONT TestGlobMatch/foo*_foobar2448=== CONT TestGlobMatch/foo*_foo2449=== CONT TestGlobMatch/*_anything2450=== CONT TestGlobMatch/*_2451=== CONT TestGlobMatch/foo_bar2452--- PASS: TestGlobMatch (0.02s)2453 --- PASS: TestGlobMatch/foo_foo (0.00s)2454 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2455 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2456 --- PASS: TestGlobMatch/?oo_boo (0.00s)2457 --- PASS: TestGlobMatch/?oo_foo (0.00s)2458 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2459 --- PASS: TestGlobMatch/fo?_fo (0.00s)2460 --- PASS: TestGlobMatch/fo?_foo (0.00s)2461 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2462 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2463 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2464 --- PASS: TestGlobMatch/*/*_foo (0.00s)2465 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2466 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2467 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2468 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2469 --- PASS: TestGlobMatch/*bar_foo (0.00s)2470 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2471 --- PASS: TestGlobMatch/*bar_bar (0.00s)2472 --- PASS: TestGlobMatch/foo*_bar (0.00s)2473 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2474 --- PASS: TestGlobMatch/foo*_foo (0.00s)2475 --- PASS: TestGlobMatch/*_anything (0.00s)2476 --- PASS: TestGlobMatch/*_ (0.00s)2477 --- PASS: TestGlobMatch/foo_bar (0.00s)24782026/11/10 21:16:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54043/oidc2479--- PASS: TestPins_ReservedForMatchingRule (0.05s)24802026/11/10 21:16:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54046/oidc24812026/11/10 21:16:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54045/oidc24822026/11/10 21:16:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54049/oidc2483--- PASS: TestValidateToken_Expired (0.08s)2484--- PASS: TestValidateToken_BoundSubjectMismatch (0.06s)2485--- PASS: TestValidateToken_BoundClaimsMismatch (0.08s)24862026/11/10 21:16:31 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12324872026/11/10 21:16:31 http: TLS handshake error from 127.0.0.1:54053: read tcp 127.0.0.1:54051->127.0.0.1:54053: use of closed network connection2488--- PASS: TestNewValidator_KubernetesRequiresCA (0.09s)24892026/11/10 21:16:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54055/oidc2490--- PASS: TestValidateToken_WrongAudience (0.09s)24912026/11/10 21:16:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54058/oidc2492--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.09s)2493--- PASS: TestScopes_Rules (0.11s)24942026/11/10 21:16:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54062/oidc2495--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.13s)24962026/11/10 21:16:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54064/oidc2497--- PASS: TestValidateToken_ValidToken (0.12s)24982026/11/10 21:16:31 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:54052/oidc2499--- PASS: TestValidateToken_NoMatchingProvider (0.14s)25002026/11/10 21:16:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54068/oidc25012026/11/10 21:16:31 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:54061/oidc25022026/11/10 21:16:31 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:54070/oidc2503--- PASS: TestPins_TopLevelShorthand (0.14s)2504--- PASS: TestValidateToken_MultipleProviders (0.14s)25052026/11/10 21:16:31 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:540732506--- PASS: TestValidateToken_KubernetesServiceAccount (0.15s)2507PASS2508Running hook tests...2509=== RUN TestSendPathsEmpty2510=== PAUSE TestSendPathsEmpty2511=== RUN TestQueueEnqueueAndFetch2512=== PAUSE TestQueueEnqueueAndFetch2513=== RUN TestQueueDeduplication2514=== PAUSE TestQueueDeduplication2515=== RUN TestQueueRemove2516=== PAUSE TestQueueRemove2517=== RUN TestQueueFetchBatchLimit2518=== PAUSE TestQueueFetchBatchLimit2519=== RUN TestQueueRetryMovesToBack2520=== PAUSE TestQueueRetryMovesToBack2521=== RUN TestQueueFetchRemoveLifecycle2522=== PAUSE TestQueueFetchRemoveLifecycle2523=== RUN TestQueueConcurrentWriters2524=== PAUSE TestQueueConcurrentWriters2525=== RUN TestQueueRemoveLargeClosure2526=== PAUSE TestQueueRemoveLargeClosure2527=== RUN TestServerClientIntegration2528--- PASS: TestServerClientIntegration (0.00s)2529=== RUN TestServerQueueError25302026/11/10 21:16:32 ERROR Failed to queue paths error="permission denied" count=12531--- PASS: TestServerQueueError (0.00s)2532=== RUN TestGetListenerSocketActivation2533 server_test.go:145: systemd socket activation does not exist on darwin2534--- SKIP: TestGetListenerSocketActivation (0.00s)2535=== RUN TestServerStalledClientDoesNotBlockShutdown2536=== PAUSE TestServerStalledClientDoesNotBlockShutdown2537=== RUN TestServerBacksOffOnAcceptErrors2538=== PAUSE TestServerBacksOffOnAcceptErrors2539=== RUN TestDrainIsolatesPoisonPath2540=== PAUSE TestDrainIsolatesPoisonPath2541=== RUN TestRunNotBlockedByPoisonHead2542=== PAUSE TestRunNotBlockedByPoisonHead2543=== RUN TestDrainGivesUpWhenServerDown2544=== PAUSE TestDrainGivesUpWhenServerDown2545=== RUN TestFailedPathPrunedByLaterClosure2546=== PAUSE TestFailedPathPrunedByLaterClosure2547=== RUN TestWorkerUploadsAndRemoves2548=== PAUSE TestWorkerUploadsAndRemoves2549=== RUN TestWorkerSkipsGCdPaths2550=== PAUSE TestWorkerSkipsGCdPaths2551=== RUN TestWorkerPrunesClosureDeps2552=== PAUSE TestWorkerPrunesClosureDeps2553=== RUN TestDrainTimeout2554=== PAUSE TestDrainTimeout2555=== RUN TestWorkerRemoveFailureIsNotProgress2556=== PAUSE TestWorkerRemoveFailureIsNotProgress2557=== RUN TestWorkerKeepsPathItCannotStat2558=== PAUSE TestWorkerKeepsPathItCannotStat2559=== CONT TestSendPathsEmpty2560=== CONT TestWorkerSkipsGCdPaths2561--- PASS: TestSendPathsEmpty (0.00s)2562=== CONT TestWorkerKeepsPathItCannotStat2563=== CONT TestWorkerRemoveFailureIsNotProgress2564=== CONT TestDrainTimeout2565=== CONT TestWorkerPrunesClosureDeps2566=== CONT TestDrainIsolatesPoisonPath2567=== CONT TestServerBacksOffOnAcceptErrors2568=== CONT TestServerStalledClientDoesNotBlockShutdown25692026/11/10 21:16:32 ERROR Accept failed error="too many open files"2570=== CONT TestQueueRemoveLargeClosure2571=== CONT TestQueueConcurrentWriters2572=== CONT TestFailedPathPrunedByLaterClosure2573=== CONT TestQueueFetchRemoveLifecycle2574=== CONT TestWorkerUploadsAndRemoves2575=== CONT TestQueueRetryMovesToBack2576=== CONT TestDrainGivesUpWhenServerDown2577=== CONT TestQueueFetchBatchLimit2578=== CONT TestRunNotBlockedByPoisonHead2579=== CONT TestQueueRemove2580=== CONT TestQueueDeduplication2581=== CONT TestQueueEnqueueAndFetch25822026/11/10 21:16:32 ERROR Accept failed error="too many open files"25832026/11/10 21:16:32 INFO Upload queue status pending=225842026/11/10 21:16:32 INFO Uploading batch count=22585--- PASS: TestQueueEnqueueAndFetch (0.01s)2586--- PASS: TestQueueRemove (0.01s)25872026/11/10 21:16:32 INFO Upload queue status pending=225882026/11/10 21:16:32 INFO Upload queue status pending=325892026/11/10 21:16:32 INFO Upload queue status pending=22590--- PASS: TestQueueFetchBatchLimit (0.01s)25912026/11/10 21:16:32 INFO Uploading batch count=125922026/11/10 21:16:32 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/b3a0d46031104912/build/TestWorkerSkipsGCdPaths1864715282/002/nonexistent2593--- PASS: TestQueueFetchRemoveLifecycle (0.01s)25942026/11/10 21:16:32 INFO Uploading batch count=225952026/11/10 21:16:32 ERROR Upload failed error="upload failed" count=225962026/11/10 21:16:32 INFO Uploading batch count=425972026/11/10 21:16:32 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/b3a0d46031104912/build/TestDrainGivesUpWhenServerDown573630038/002/a25982026/11/10 21:16:32 ERROR Upload failed error="upload failed" count=425992026/11/10 21:16:32 INFO Uploading batch count=226002026/11/10 21:16:32 INFO Uploading batch count=126012026/11/10 21:16:32 INFO Uploading batch count=126022026/11/10 21:16:32 ERROR Upload failed error="upload failed" count=126032026/11/10 21:16:32 INFO Uploading batch count=126042026/11/10 21:16:32 ERROR Upload failed error="upload failed" count=12605--- PASS: TestQueueDeduplication (0.01s)26062026/11/10 21:16:32 WARN Cannot stat store path, will retry later path=/private/var/tb/4/scratch/b3a0d46031104912/build/TestWorkerKeepsPathItCannotStat2143873608/002/locked/aaa error="stat /private/var/tb/4/scratch/b3a0d46031104912/build/TestWorkerKeepsPathItCannotStat2143873608/002/locked/aaa: permission denied"26072026/11/10 21:16:32 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/b3a0d46031104912/build/TestDrainGivesUpWhenServerDown573630038/002/b2608--- PASS: TestQueueRetryMovesToBack (0.01s)26092026/11/10 21:16:32 INFO Uploading batch count=126102026/11/10 21:16:32 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/b3a0d46031104912/build/TestWorkerRemoveFailureIsNotProgress604919771/002/nonexistent26112026/11/10 21:16:32 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126122026/11/10 21:16:32 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/b3a0d46031104912/build/TestWorkerRemoveFailureIsNotProgress604919771/002/nonexistent26132026/11/10 21:16:32 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/b3a0d46031104912/build/TestDrainIsolatesPoisonPath2847920934/002/bbb26142026/11/10 21:16:32 WARN Cannot stat store path, will retry later path=/private/var/tb/4/scratch/b3a0d46031104912/build/TestWorkerKeepsPathItCannotStat2143873608/002/locked/aaa error="stat /private/var/tb/4/scratch/b3a0d46031104912/build/TestWorkerKeepsPathItCannotStat2143873608/002/locked/aaa: permission denied"26152026/11/10 21:16:32 INFO Uploading batch count=226162026/11/10 21:16:32 ERROR Upload failed error="upload failed" count=226172026/11/10 21:16:32 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/b3a0d46031104912/build/TestDrainGivesUpWhenServerDown573630038/002/c26182026/11/10 21:16:32 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126192026/11/10 21:16:32 INFO Uploading batch count=126202026/11/10 21:16:32 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/b3a0d46031104912/build/TestWorkerRemoveFailureIsNotProgress604919771/002/nonexistent26212026/11/10 21:16:32 WARN Cannot stat store path, will retry later path=/private/var/tb/4/scratch/b3a0d46031104912/build/TestWorkerKeepsPathItCannotStat2143873608/002/locked/aaa error="stat /private/var/tb/4/scratch/b3a0d46031104912/build/TestWorkerKeepsPathItCannotStat2143873608/002/locked/aaa: permission denied"26222026/11/10 21:16:32 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/b3a0d46031104912/build/TestDrainGivesUpWhenServerDown573630038/002/d26232026/11/10 21:16:32 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126242026/11/10 21:16:32 ERROR Drain finished with paths left in queue remaining=126252026/11/10 21:16:32 ERROR Drain finished with paths left in queue remaining=126262026/11/10 21:16:32 INFO Uploading batch count=226272026/11/10 21:16:32 ERROR Upload failed error="upload failed" count=226282026/11/10 21:16:32 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/b3a0d46031104912/build/TestDrainGivesUpWhenServerDown573630038/002/e26292026/11/10 21:16:32 INFO Uploading batch count=126302026/11/10 21:16:32 ERROR Upload failed error="upload failed" count=126312026/11/10 21:16:32 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/b3a0d46031104912/build/TestDrainGivesUpWhenServerDown573630038/002/f26322026/11/10 21:16:32 ERROR Accept failed error="too many open files"26332026/11/10 21:16:32 INFO Uploading batch count=126342026/11/10 21:16:32 ERROR Upload failed error="upload failed" count=126352026/11/10 21:16:32 ERROR Drain finished with paths left in queue remaining=102636--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)26372026/11/10 21:16:32 INFO Uploading batch count=126382026/11/10 21:16:32 ERROR Upload failed error="upload failed" count=126392026/11/10 21:16:32 ERROR Drain finished with paths left in queue remaining=12640--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2641--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)2642--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2643--- PASS: TestDrainIsolatesPoisonPath (0.02s)2644--- PASS: TestWorkerUploadsAndRemoves (0.03s)2645--- PASS: TestWorkerPrunesClosureDeps (0.03s)2646--- PASS: TestWorkerSkipsGCdPaths (0.03s)26472026/11/10 21:16:32 ERROR Accept failed error="too many open files"2648--- PASS: TestQueueRemoveLargeClosure (0.05s)2649--- PASS: TestQueueConcurrentWriters (0.05s)26502026/11/10 21:16:32 ERROR Accept failed error="too many open files"26512026/11/10 21:16:32 ERROR Accept failed error="too many open files"26522026/11/10 21:16:32 ERROR Failed to decode request error="read unix /private/var/tb/4/scratch/b3a0d46031104912/build/hook3577841414/test.sock->: i/o timeout"26532026/11/10 21:16:32 ERROR Failed to write response error="write unix /private/var/tb/4/scratch/b3a0d46031104912/build/hook3577841414/test.sock->: i/o timeout"2654--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26552026/11/10 21:16:32 ERROR Upload failed error="context deadline exceeded" count=226562026/11/10 21:16:32 ERROR Drain finished with paths left in queue remaining=42657--- PASS: TestDrainTimeout (0.22s)26582026/11/10 21:16:32 ERROR Accept failed error="too many open files"26592026/11/10 21:16:32 ERROR Accept failed error="too many open files"2660--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26612026/11/10 21:16:33 INFO Uploading batch count=126622026/11/10 21:16:33 INFO Uploading batch count=126632026/11/10 21:16:33 INFO Uploading batch count=126642026/11/10 21:16:33 ERROR Upload failed error="upload failed" count=126652026/11/10 21:16:33 INFO Uploading batch count=126662026/11/10 21:16:33 ERROR Upload failed error="upload failed" count=126672026/11/10 21:16:33 INFO Uploading batch count=126682026/11/10 21:16:33 ERROR Upload failed error="upload failed" count=126692026/11/10 21:16:33 INFO Uploading batch count=126702026/11/10 21:16:33 ERROR Upload failed error="upload failed" count=126712026/11/10 21:16:33 ERROR Drain finished with paths left in queue remaining=12672--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2673PASS2674Running signing tests...2675=== RUN TestExternalSigner2676=== PAUSE TestExternalSigner2677=== RUN TestExternalSignerWrongPublicKey2678=== PAUSE TestExternalSignerWrongPublicKey2679=== RUN TestExternalSignerErrors2680=== PAUSE TestExternalSignerErrors2681=== RUN TestExternalSignerRestartsAfterCrash2682=== PAUSE TestExternalSignerRestartsAfterCrash2683=== RUN TestExternalSignerProgramErrorKeepsProcess2684=== PAUSE TestExternalSignerProgramErrorKeepsProcess2685=== RUN TestExternalSignerClose2686=== PAUSE TestExternalSignerClose2687=== RUN TestExternalSignerRejectsInvalidPublicKey2688=== PAUSE TestExternalSignerRejectsInvalidPublicKey2689=== RUN TestExternalSignerCancellation2690=== PAUSE TestExternalSignerCancellation2691=== RUN TestGenerateFingerprint2692=== PAUSE TestGenerateFingerprint2693=== RUN TestParseSigningKey2694=== PAUSE TestParseSigningKey2695=== RUN TestSign2696=== PAUSE TestSign2697=== RUN TestSignBatch2698=== PAUSE TestSignBatch2699=== RUN TestNilKeyPublicKey2700=== PAUSE TestNilKeyPublicKey2701=== RUN TestSignErrors2702=== PAUSE TestSignErrors2703=== RUN TestValidatePublicKeys2704=== PAUSE TestValidatePublicKeys2705=== CONT TestExternalSigner2706=== CONT TestNilKeyPublicKey2707=== CONT TestExternalSignerProgramErrorKeepsProcess2708--- PASS: TestNilKeyPublicKey (0.00s)2709=== CONT TestSign2710=== CONT TestParseSigningKey2711=== RUN TestParseSigningKey/valid_32-byte_key2712=== CONT TestExternalSignerErrors2713=== PAUSE TestParseSigningKey/valid_32-byte_key2714=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2715=== RUN TestExternalSignerErrors/exit_at_startup2716=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2717=== RUN TestParseSigningKey/no_colon2718=== CONT TestExternalSignerRestartsAfterCrash2719=== CONT TestExternalSignerCancellation2720=== CONT TestExternalSignerWrongPublicKey2721=== CONT TestValidatePublicKeys2722--- PASS: TestValidatePublicKeys (0.00s)2723=== CONT TestExternalSignerClose2724=== CONT TestSignErrors2725=== CONT TestGenerateFingerprint2726=== RUN TestGenerateFingerprint/basic_with_references2727=== CONT TestSignBatch2728=== PAUSE TestExternalSignerErrors/exit_at_startup2729=== CONT TestExternalSignerRejectsInvalidPublicKey2730=== RUN TestExternalSignerErrors/wrong_signatures_shape2731=== PAUSE TestParseSigningKey/no_colon2732=== PAUSE TestGenerateFingerprint/basic_with_references2733=== RUN TestParseSigningKey/empty_name2734=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2735=== RUN TestGenerateFingerprint/no_references2736=== RUN TestExternalSignerErrors/missing_signature_name2737=== PAUSE TestGenerateFingerprint/no_references2738=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2739=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2740=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2741=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2742=== RUN TestGenerateFingerprint/invalid_nar_hash_length2743=== PAUSE TestExternalSignerErrors/missing_signature_name2744=== RUN TestExternalSignerErrors/invalid_signature_base642745=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2746=== RUN TestGenerateFingerprint/invalid_store_path_prefix2747=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2748=== RUN TestGenerateFingerprint/invalid_reference_prefix2749=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2750=== CONT TestGenerateFingerprint/basic_with_references2751=== CONT TestGenerateFingerprint/no_references2752=== PAUSE TestExternalSignerErrors/invalid_signature_base642753=== RUN TestExternalSignerErrors/invalid_JSON2754=== CONT TestGenerateFingerprint/invalid_nar_hash_length2755=== RUN TestExternalSignerRejectsInvalidPublicKey/#002756=== PAUSE TestParseSigningKey/empty_name2757=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002758=== RUN TestParseSigningKey/invalid_base642759=== PAUSE TestParseSigningKey/invalid_base642760=== CONT TestGenerateFingerprint/invalid_reference_prefix2761=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2762=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2763=== PAUSE TestExternalSignerErrors/invalid_JSON2764=== RUN TestParseSigningKey/wrong_length2765=== PAUSE TestParseSigningKey/wrong_length2766=== CONT TestParseSigningKey/invalid_base642767=== CONT TestParseSigningKey/no_colon2768=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2769=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2770=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2771=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2772=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2773=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2774=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2775=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2776=== RUN TestExternalSignerErrors/null2777=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2778=== PAUSE TestExternalSignerErrors/null2779=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2780=== CONT TestParseSigningKey/valid_32-byte_key2781--- PASS: TestSign (0.00s)2782=== RUN TestSignErrors/nil_key2783=== CONT TestGenerateFingerprint/invalid_store_path_prefix2784--- PASS: TestGenerateFingerprint (0.00s)2785 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2786 --- PASS: TestGenerateFingerprint/no_references (0.00s)2787 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2788 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2789 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2790 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2791 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2792=== CONT TestExternalSignerRejectsInvalidPublicKey/#002793=== CONT TestParseSigningKey/empty_name2794=== CONT TestParseSigningKey/wrong_length2795--- PASS: TestParseSigningKey (0.00s)2796 --- PASS: TestParseSigningKey/no_colon (0.00s)2797 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2798 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2799 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2800 --- PASS: TestParseSigningKey/empty_name (0.00s)2801 --- PASS: TestParseSigningKey/wrong_length (0.00s)2802=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2803=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2804=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2805--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2806 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2807 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2808 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2809 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2810 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2811=== RUN TestExternalSignerErrors/wrong_id2812=== PAUSE TestExternalSignerErrors/wrong_id2813=== RUN TestExternalSignerErrors/null_signatures2814=== PAUSE TestExternalSignerErrors/null_signatures2815=== RUN TestExternalSignerErrors/unrequested_key2816=== PAUSE TestExternalSignerErrors/unrequested_key2817=== RUN TestExternalSignerErrors/exit_on_request2818=== PAUSE TestExternalSignerErrors/exit_on_request2819=== RUN TestExternalSignerErrors/missing_signatures2820=== PAUSE TestExternalSignerErrors/missing_signatures2821=== RUN TestExternalSignerErrors/too_few_signatures2822=== PAUSE TestExternalSignerErrors/too_few_signatures2823=== RUN TestExternalSignerErrors/wrong_signature_name2824=== PAUSE TestExternalSignerErrors/wrong_signature_name2825=== RUN TestExternalSignerErrors/program_error2826=== PAUSE TestExternalSignerErrors/program_error2827=== RUN TestExternalSignerErrors/wrong_shape2828=== PAUSE TestExternalSignerErrors/wrong_shape2829=== RUN TestExternalSignerErrors/wrong_signature_length2830=== PAUSE TestExternalSignerErrors/wrong_signature_length2831=== PAUSE TestSignErrors/nil_key2832=== CONT TestExternalSignerErrors/missing_signature_name2833=== RUN TestSignErrors/nil_narinfo2834=== CONT TestExternalSignerErrors/wrong_signatures_shape2835=== PAUSE TestSignErrors/nil_narinfo2836=== RUN TestSignErrors/invalid_narinfo2837=== PAUSE TestSignErrors/invalid_narinfo2838=== RUN TestSignErrors/canceled2839=== PAUSE TestSignErrors/canceled2840=== CONT TestSignErrors/nil_key2841=== CONT TestExternalSignerErrors/exit_at_startup2842=== CONT TestSignErrors/canceled2843--- PASS: TestSignBatch (0.00s)2844=== CONT TestExternalSignerErrors/wrong_shape2845=== CONT TestSignErrors/invalid_narinfo2846=== CONT TestSignErrors/nil_narinfo2847--- PASS: TestSignErrors (0.00s)2848 --- PASS: TestSignErrors/nil_key (0.00s)2849 --- PASS: TestSignErrors/canceled (0.00s)2850 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2851 --- PASS: TestSignErrors/nil_narinfo (0.00s)2852=== CONT TestExternalSignerErrors/wrong_signature_length2853=== CONT TestExternalSignerErrors/wrong_signature_name2854=== CONT TestExternalSignerErrors/too_few_signatures2855=== CONT TestExternalSignerErrors/missing_signatures2856=== CONT TestExternalSignerErrors/exit_on_request2857=== CONT TestExternalSignerErrors/unrequested_key2858=== CONT TestExternalSignerErrors/null_signatures2859=== CONT TestExternalSignerErrors/wrong_id2860=== CONT TestExternalSignerErrors/null2861=== CONT TestExternalSignerErrors/invalid_JSON2862=== CONT TestExternalSignerErrors/invalid_signature_base642863=== CONT TestExternalSignerErrors/program_error2864--- PASS: TestExternalSigner (0.11s)2865--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.17s)2866--- PASS: TestExternalSignerClose (0.25s)2867--- PASS: TestExternalSignerCancellation (0.58s)2868--- PASS: TestExternalSignerRestartsAfterCrash (0.93s)2869/private/var/tb/4/scratch/b3a0d46031104912/build/TestExternalSignerRestartsAfterCrash2460727016/001/sign program: line 7: /private/var/tb/4/scratch/b3a0d46031104912/build/TestExternalSignerRestartsAfterCrash2460727016/001/sign program.starts: No such file or directory2870--- PASS: TestExternalSignerWrongPublicKey (0.99s)2871--- PASS: TestExternalSignerErrors (0.00s)2872 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.32s)2873 --- PASS: TestExternalSignerErrors/invalid_JSON (0.40s)2874 --- PASS: TestExternalSignerErrors/exit_on_request (0.48s)2875 --- PASS: TestExternalSignerErrors/exit_at_startup (0.64s)2876 --- PASS: TestExternalSignerErrors/too_few_signatures (0.79s)2877 --- PASS: TestExternalSignerErrors/wrong_id (0.83s)2878 --- PASS: TestExternalSignerErrors/null (1.07s)2879 --- PASS: TestExternalSignerErrors/wrong_signature_name (1.14s)2880 --- PASS: TestExternalSignerErrors/wrong_shape (1.22s)2881 --- PASS: TestExternalSignerErrors/null_signatures (1.30s)2882 --- PASS: TestExternalSignerErrors/missing_signatures (1.37s)2883 --- PASS: TestExternalSignerErrors/missing_signature_name (1.45s)2884 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (1.52s)2885 --- PASS: TestExternalSignerErrors/wrong_signature_length (1.60s)2886 --- PASS: TestExternalSignerErrors/program_error (1.67s)2887 --- PASS: TestExternalSignerErrors/unrequested_key (1.75s)2888PASS2889Running OpenBao signer tests...2890=== RUN TestSign2891=== PAUSE TestSign2892=== RUN TestSignErrors2893=== PAUSE TestSignErrors2894=== RUN TestServe2895=== PAUSE TestServe2896=== RUN TestServeRejectsGarbage2897=== PAUSE TestServeRejectsGarbage2898=== CONT TestSign2899=== CONT TestServe2900=== CONT TestSignErrors2901=== RUN TestSignErrors/invalid_base642902=== PAUSE TestSignErrors/invalid_base642903=== CONT TestServeRejectsGarbage2904--- PASS: TestServeRejectsGarbage (0.00s)2905=== RUN TestSignErrors/http_error2906=== PAUSE TestSignErrors/http_error2907=== RUN TestSignErrors/invalid_json2908=== PAUSE TestSignErrors/invalid_json2909=== RUN TestSignErrors/no_prefix2910=== PAUSE TestSignErrors/no_prefix2911=== CONT TestSignErrors/invalid_base642912=== CONT TestSignErrors/invalid_json2913=== CONT TestSignErrors/no_prefix2914=== CONT TestSignErrors/http_error2915--- PASS: TestServe (0.00s)2916--- PASS: TestSign (0.00s)2917--- PASS: TestSignErrors (0.00s)2918 --- PASS: TestSignErrors/invalid_base64 (0.00s)2919 --- PASS: TestSignErrors/no_prefix (0.00s)2920 --- PASS: TestSignErrors/invalid_json (0.00s)2921 --- PASS: TestSignErrors/http_error (0.00s)2922PASS

succeeded niks3-go-unit-tests checks.aarch64-darwin.go-unit-tests · build #480 · raw

succeeded `niks3-go-unit-tests` `checks.aarch64-darwin.go-unit-tests` · build #480 · raw