niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #467
· raw
1tribuchet: building on eliza2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestUploadMultipart_ReturnsAfterDroppedBody20=== PAUSE TestUploadMultipart_ReturnsAfterDroppedBody21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestUploadMultipart_SupersededByPeer24=== PAUSE TestUploadMultipart_SupersededByPeer25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (0.24s)27=== RUN TestDumpPathCaseHackCollision28--- PASS: TestDumpPathCaseHackCollision (0.00s)29=== RUN TestSupersededNARStillUploadsListing30=== PAUSE TestSupersededNARStillUploadsListing31=== RUN TestDumpPathMatchesNix32=== PAUSE TestDumpPathMatchesNix33=== RUN TestDumpPathSingleFile34=== PAUSE TestDumpPathSingleFile35=== RUN TestDumpPathWriterError36=== PAUSE TestDumpPathWriterError37=== RUN TestEncodeNixBase3238=== PAUSE TestEncodeNixBase3239=== RUN TestEncodeNixBase32WithRealHash40=== PAUSE TestEncodeNixBase32WithRealHash41=== RUN TestConvertHashToNix3242=== PAUSE TestConvertHashToNix3243=== RUN TestGetStorePathHash44=== PAUSE TestGetStorePathHash45=== RUN TestPathInfoHashCompatibility46=== PAUSE TestPathInfoHashCompatibility47=== RUN TestParsePathInfoJSON48=== PAUSE TestParsePathInfoJSON49=== RUN TestParsePathInfoJSONMultiplePaths50=== PAUSE TestParsePathInfoJSONMultiplePaths51=== RUN TestPathInfoCACompatibility52=== PAUSE TestPathInfoCACompatibility53=== RUN TestRateLimiterFeedback54=== PAUSE TestRateLimiterFeedback55=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess56=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess57=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer58=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer59=== RUN TestRegisterUploadedObject_OutlivesPush60=== PAUSE TestRegisterUploadedObject_OutlivesPush61=== RUN TestResolveStorePath62=== PAUSE TestResolveStorePath63=== RUN TestDoWithRetry_BodyReplayedViaGetBody64=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody65=== RUN TestRetryTimeoutOutlastsMaxRetries66=== PAUSE TestRetryTimeoutOutlastsMaxRetries67=== RUN TestDoWithRetry_FinalResponseBodyReadable68=== PAUSE TestDoWithRetry_FinalResponseBodyReadable69=== RUN TestShellSplit70=== PAUSE TestShellSplit71=== RUN TestShellSplitErrors72=== PAUSE TestShellSplitErrors73=== RUN TestStreamPushReportsEveryPath74=== PAUSE TestStreamPushReportsEveryPath75=== RUN TestStreamPushBatchesUnderLoad76=== PAUSE TestStreamPushBatchesUnderLoad77=== RUN TestStreamPushIsolatesFailures78=== PAUSE TestStreamPushIsolatesFailures79=== RUN TestStreamPushGivesUpOnDeadServer80=== PAUSE TestStreamPushGivesUpOnDeadServer81=== RUN TestStreamPushRequestLine82=== PAUSE TestStreamPushRequestLine83=== RUN TestStreamPushReportsSignatures84=== PAUSE TestStreamPushReportsSignatures85=== RUN TestStreamPushReportsSkippedPaths86=== PAUSE TestStreamPushReportsSkippedPaths87=== RUN TestClientSignaturesByStorePath88=== PAUSE TestClientSignaturesByStorePath89=== RUN TestStreamPushStopsWhenCanceled90=== PAUSE TestStreamPushStopsWhenCanceled91=== RUN TestSetClientTLS92=== PAUSE TestSetClientTLS93=== RUN TestSetClientTLSDoesNotMutateDefaultTransport94=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport95=== RUN TestSetClientTLSErrors96=== PAUSE TestSetClientTLSErrors97=== RUN TestStaticToken98=== PAUSE TestStaticToken99=== RUN TestFileTokenReadsAndCaches100=== PAUSE TestFileTokenReadsAndCaches101=== RUN TestFileTokenMissing102=== PAUSE TestFileTokenMissing103=== RUN TestFileTokenEmpty104=== PAUSE TestFileTokenEmpty105=== RUN TestScriptTokenNoExpiryRerunsEveryCall106=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall107=== RUN TestScriptTokenCachesUntilRefresh108=== PAUSE TestScriptTokenCachesUntilRefresh109=== RUN TestScriptTokenEmptyToken110=== PAUSE TestScriptTokenEmptyToken111=== RUN TestScriptTokenBadJSON112=== PAUSE TestScriptTokenBadJSON113=== RUN TestScriptTokenScriptFails114=== PAUSE TestScriptTokenScriptFails115=== RUN TestScriptTokenEmptyCommand116=== PAUSE TestScriptTokenEmptyCommand117=== CONT TestDoServerRequestAttachesToken118=== CONT TestResolveStorePath119=== CONT TestDumpPathWriterError120--- PASS: TestResolveStorePath (0.00s)121=== CONT TestFilterOversizedClosures122=== RUN TestFilterOversizedClosures/no_limit_keeps_everything123=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything124=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped125=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped126=== RUN TestFilterOversizedClosures/all_closures_skipped127=== PAUSE TestFilterOversizedClosures/all_closures_skipped128=== CONT TestCaseHackSuffix129=== CONT TestRegisterUploadedObject_OutlivesPush130=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer131=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess132=== CONT TestRateLimiterFeedback133=== CONT TestPathInfoCACompatibility134=== CONT TestParsePathInfoJSONMultiplePaths135=== CONT TestParsePathInfoJSON136=== CONT TestPathInfoHashCompatibility137=== CONT TestGetStorePathHash138=== CONT TestConvertHashToNix32139=== CONT TestEncodeNixBase32WithRealHash140=== CONT TestEncodeNixBase32141=== CONT TestUploadMultipart_PartsInParallel142=== CONT TestDumpPathSingleFile143=== CONT TestDumpPathMatchesNix144=== CONT TestSupersededNARStillUploadsListing145=== CONT TestUploadMultipart_SupersededByPeer146=== CONT TestPartSizeForNAR147=== CONT TestUploadMultipart_ReturnsAfterDroppedBody148=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun149=== CONT TestScriptTokenEmptyCommand150=== RUN TestRateLimiterFeedback/429_enables_limiter151=== RUN TestPathInfoCACompatibility/null_ca_field152=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths153=== RUN TestParsePathInfoJSON/Nix_format154=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)155=== RUN TestGetStorePathHash/valid_store_path156=== RUN TestConvertHashToNix32/SRI_format_to_Nix32157--- PASS: TestEncodeNixBase32WithRealHash (0.00s)158=== CONT TestRegisterUploadedObjectReusesConnections159=== RUN TestEncodeNixBase32/test_string_hash160=== PAUSE TestPathInfoCACompatibility/null_ca_field161=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths1622026/11/06 08:15:24 WARN Rate limiter enabled after throttle name=server-test rate=5163=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths164=== PAUSE TestParsePathInfoJSON/Nix_format165=== RUN TestParsePathInfoJSON/Lix_format166=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)167=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon168=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon169=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI170=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI171=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512172=== PAUSE TestEncodeNixBase32/test_string_hash173=== RUN TestEncodeNixBase32/empty_input174=== PAUSE TestEncodeNixBase32/empty_input175=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica176=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32177=== PAUSE TestGetStorePathHash/valid_store_path178=== RUN TestGetStorePathHash/basename_without_hyphen_should_error179=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error180=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error181=== PAUSE TestRateLimiterFeedback/429_enables_limiter182=== RUN TestRateLimiterFeedback/503_enables_limiter183=== PAUSE TestRateLimiterFeedback/503_enables_limiter184=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter185=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter186=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter187=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter188=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths189=== CONT TestStreamPushReportsSkippedPaths190=== CONT TestStreamPushRequestLine191=== CONT TestStreamPushGivesUpOnDeadServer192=== CONT TestStreamPushIsolatesFailures193=== PAUSE TestParsePathInfoJSON/Lix_format194=== RUN TestParsePathInfoJSON/empty_input195=== PAUSE TestParsePathInfoJSON/empty_input196=== RUN TestParsePathInfoJSON/whitespace_only197=== PAUSE TestParsePathInfoJSON/whitespace_only198=== RUN TestParsePathInfoJSON/invalid_JSON199=== PAUSE TestParsePathInfoJSON/invalid_JSON200=== CONT TestStreamPushReportsSignatures201=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512202=== CONT TestShellSplit203=== CONT TestStreamPushReportsEveryPath204=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error205--- PASS: TestScriptTokenEmptyCommand (0.00s)206=== CONT TestStreamPushBatchesUnderLoad207=== RUN TestConvertHashToNix32/already_Nix32_format208=== RUN TestUploadMultipart_SupersededByPeer/exists209=== RUN TestSupersededNARStillUploadsListing/small_NAR210=== RUN TestPartSizeForNAR/zero_stays_at_minimum211=== RUN TestPathInfoCACompatibility/old_string_format_-_text212=== CONT TestClientSignaturesByStorePath213--- PASS: TestCaseHackSuffix (2.12s)2142026/11/06 08:15:26 ERROR Upload failed error="bad path" count=3215--- PASS: TestRegisterUploadedObject_OutlivesPush (2.18s)216--- PASS: TestDoServerRequestAttachesToken (2.20s)2172026/11/06 08:15:26 ERROR Upload failed error="connection refused" count=202182026/11/06 08:15:26 ERROR Server seems unavailable, giving up on batch untried=17219=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false220=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false221=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true222=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true223=== PAUSE TestConvertHashToNix32/already_Nix32_format224=== RUN TestConvertHashToNix32/invalid_format225=== PAUSE TestConvertHashToNix32/invalid_format2262026/11/06 08:15:26 INFO Garbage collection started227=== PAUSE TestUploadMultipart_SupersededByPeer/exists2282026/11/06 08:15:26 INFO Garbage collection started229=== RUN TestUploadMultipart_SupersededByPeer/missing230=== PAUSE TestUploadMultipart_SupersededByPeer/missing231=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum2322026/11/06 08:15:26 ERROR Upload failed error=boom count=12332026/11/06 08:15:27 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:44645/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:44645/api/uploads/complete2342026/11/06 08:15:27 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"235=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text236=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive237=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive238=== RUN TestPathInfoCACompatibility/new_structured_format_-_text239=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text2402026/11/06 08:15:27 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:44645/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:44645/api/uploads/complete241=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method2422026/11/06 08:15:27 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"243=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method244=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error245--- PASS: TestStreamPushReportsEveryPath (0.00s)246--- PASS: TestStreamPushIsolatesFailures (0.00s)247--- PASS: TestShellSplit (0.00s)248--- PASS: TestStreamPushReportsSkippedPaths (0.08s)249--- PASS: TestClientSignaturesByStorePath (0.00s)250--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (2.12s)251=== CONT TestScriptTokenEmptyToken252=== CONT TestShellSplitErrors2532026/11/06 08:15:27 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:44645/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:44645/api/uploads/complete2542026/11/06 08:15:27 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"255=== CONT TestDoWithRetry_FinalResponseBodyReadable256=== PAUSE TestSupersededNARStillUploadsListing/small_NAR257=== CONT TestScriptTokenBadJSON258=== CONT TestScriptTokenScriptFails259=== CONT TestScriptTokenCachesUntilRefresh260=== CONT TestScriptTokenNoExpiryRerunsEveryCall261=== CONT TestFileTokenEmpty262=== CONT TestRetryTimeoutOutlastsMaxRetries263=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error264=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry265--- PASS: TestShellSplitErrors (0.00s)266=== CONT TestDoWithRetry_BodyReplayedViaGetBody267=== RUN TestSupersededNARStillUploadsListing/dump_cut_short268=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short269=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails2702026/11/06 08:15:27 ERROR Upload failed error=boom count=1271--- PASS: TestStreamPushReportsSignatures (0.73s)272=== CONT TestStaticToken273--- PASS: TestStaticToken (0.00s)274=== CONT TestFileTokenMissing275=== RUN TestPartSizeForNAR/small_stays_at_minimum276--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (2.93s)277=== CONT TestFileTokenReadsAndCaches278--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (2.54s)279=== CONT TestSetClientTLSDoesNotMutateDefaultTransport2802026/11/06 08:15:27 WARN Rate limiter enabled after throttle name=server-test rate=52812026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:452392822026/11/06 08:15:27 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=0283--- PASS: TestStreamPushGivesUpOnDeadServer (0.74s)284--- PASS: TestFileTokenEmpty (0.01s)285=== CONT TestSetClientTLSErrors2862026/11/06 08:15:27 WARN Rate limiter backed off name=server-test rate=52872026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:45239288--- PASS: TestFileTokenReadsAndCaches (0.00s)289=== CONT TestStreamPushStopsWhenCanceled2902026/11/06 08:15:27 WARN Rate limiter enabled after throttle name=server-test rate=52912026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:35821292=== CONT TestSetClientTLS293--- PASS: TestStreamPushStopsWhenCanceled (0.00s)294=== CONT TestFilterOversizedClosures/no_limit_keeps_everything295--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)296=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2972026/11/06 08:15:27 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=2000298=== CONT TestEncodeNixBase32/test_string_hash299=== CONT TestEncodeNixBase32/empty_input3002026/11/06 08:15:27 WARN Rate limiter backed off name=server-test rate=5301=== CONT TestFilterOversizedClosures/all_closures_skipped3022026/11/06 08:15:27 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50303=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths304=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter305=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter3062026/11/06 08:15:27 WARN Garbage collection finished on another replica. Its statistics are not available here307=== CONT TestRateLimiterFeedback/503_enables_limiter308=== CONT TestParsePathInfoJSON/Nix_format309=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths310=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)311=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI312=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha5123132026/11/06 08:15:27 WARN Rate limiter enabled after throttle name=server-test rate=5314=== CONT TestParsePathInfoJSON/invalid_JSON3152026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:43249316=== CONT TestParsePathInfoJSON/whitespace_only317=== CONT TestParsePathInfoJSON/empty_input318=== CONT TestParsePathInfoJSON/Lix_format319=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false3202026/11/06 08:15:27 WARN Rate limiter backed off name=server-test rate=5321=== CONT TestConvertHashToNix32/SRI_format_to_Nix32322=== CONT TestUploadMultipart_SupersededByPeer/exists323=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon324=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true325=== CONT TestRateLimiterFeedback/429_enables_limiter326--- PASS: TestEncodeNixBase32 (0.06s)327 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)328 --- PASS: TestEncodeNixBase32/empty_input (0.00s)329--- PASS: TestFilterOversizedClosures (0.00s)330 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)331 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)332 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)333--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)334--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (2.86s)335=== CONT TestConvertHashToNix32/invalid_format336=== CONT TestConvertHashToNix32/already_Nix32_format337=== CONT TestUploadMultipart_SupersededByPeer/missing338--- PASS: TestParsePathInfoJSONMultiplePaths (2.10s)339 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)340 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)341--- PASS: TestParsePathInfoJSON (2.18s)342 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)343 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)344 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)345 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)346 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)347--- PASS: TestConvertHashToNix32 (2.18s)348 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)349 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)350 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)351--- PASS: TestPathInfoHashCompatibility (2.18s)352 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)353 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)354 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)355 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)356--- PASS: TestStreamPushBatchesUnderLoad (0.00s)357 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)358 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)359=== CONT TestPathInfoCACompatibility/null_ca_field360=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method361=== CONT TestPathInfoCACompatibility/new_structured_format_-_text362=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive363=== CONT TestPathInfoCACompatibility/old_string_format_-_text364--- PASS: TestPathInfoCACompatibility (2.91s)365 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)366 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)367 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)368 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)369 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)370=== CONT TestGetStorePathHash/valid_store_path371=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error372=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error373=== CONT TestGetStorePathHash/basename_without_hyphen_should_error374--- PASS: TestGetStorePathHash (2.91s)375 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)376 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)377 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)378 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)3792026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:416733802026/11/06 08:15:27 WARN Rate limiter enabled after throttle name=server-test rate=53812026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:422673822026/11/06 08:15:27 WARN Rate limiter backed off name=server-test rate=5383--- PASS: TestRateLimiterFeedback (2.10s)384 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)385 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)386 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)387 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)388--- PASS: TestScriptTokenBadJSON (0.01s)389--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)390--- PASS: TestScriptTokenEmptyToken (0.01s)391--- PASS: TestScriptTokenScriptFails (0.01s)392=== RUN TestSetClientTLSErrors/missing_cert_file393=== PAUSE TestSetClientTLSErrors/missing_cert_file394=== RUN TestSetClientTLSErrors/missing_key_file395=== PAUSE TestSetClientTLSErrors/missing_key_file396=== RUN TestSetClientTLSErrors/missing_ca_file397=== PAUSE TestSetClientTLSErrors/missing_ca_file3982026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:41673399=== RUN TestSetClientTLSErrors/invalid_ca_file400=== PAUSE TestSetClientTLSErrors/invalid_ca_file401=== CONT TestSetClientTLSErrors/missing_cert_file402--- PASS: TestUploadMultipart_SupersededByPeer (1.81s)403 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)404 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)405=== CONT TestSetClientTLSErrors/missing_ca_file406=== CONT TestSetClientTLSErrors/invalid_ca_file407=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails408=== CONT TestSupersededNARStillUploadsListing/small_NAR409=== CONT TestSetClientTLSErrors/missing_key_file410=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails411=== PAUSE TestPartSizeForNAR/small_stays_at_minimum412=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum413=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum414=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts415=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts416=== RUN TestPartSizeForNAR/1_TiB417=== PAUSE TestPartSizeForNAR/1_TiB418=== RUN TestPartSizeForNAR/5_TiB_S3_max_object419=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object420=== RUN TestPartSizeForNAR/capped_at_5_GiB421=== PAUSE TestPartSizeForNAR/capped_at_5_GiB422=== CONT TestPartSizeForNAR/zero_stays_at_minimum423=== CONT TestSupersededNARStillUploadsListing/dump_cut_short4242026/11/06 08:15:27 INFO Uploading abc-hello (1.0GB)425=== CONT TestPartSizeForNAR/1_TiB4262026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:41673427=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum4282026/11/06 08:15:27 INFO Uploading abc-hello (1.0GB)429=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts430=== CONT TestPartSizeForNAR/capped_at_5_GiB431=== CONT TestPartSizeForNAR/small_stays_at_minimum432=== CONT TestPartSizeForNAR/5_TiB_S3_max_object433--- PASS: TestFileTokenMissing (0.00s)434--- PASS: TestPartSizeForNAR (2.55s)435 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)436 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)437 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)438 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)439 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)440 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)441 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)442--- PASS: TestSetClientTLSErrors (0.01s)443 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)444 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)445 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)446 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)4472026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:416734482026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:41673449=== RUN TestSetClientTLS/rejects_connection_without_client_cert450=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert451=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA452=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA453=== RUN TestSetClientTLS/preserves_debug_logging_transport454=== PAUSE TestSetClientTLS/preserves_debug_logging_transport455=== CONT TestSetClientTLS/rejects_connection_without_client_cert456--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.31s)4572026/11/06 08:15:27 WARN Rate limiter enabled after throttle name=s3-test rate=54582026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:357234592026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:41673460=== CONT TestSetClientTLS/preserves_debug_logging_transport461=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA4622026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:41673463--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.31s)4642026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:416734652026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:416734662026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:416734672026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:41673468--- PASS: TestScriptTokenCachesUntilRefresh (0.32s)469--- PASS: TestRegisterUploadedObjectReusesConnections (3.23s)4702026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:416734712026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:416734722026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:416734732026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:416734742026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:416734752026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:41673476--- PASS: TestStreamPushRequestLine (1.06s)4772026/11/06 08:15:27 http: TLS handshake error from 127.0.0.1:59858: remote error: tls: bad certificate478--- PASS: TestSetClientTLS (0.31s)479 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)480 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)481 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)4822026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:416734832026/11/06 08:15:27 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:41673484--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.32s)4852026/11/06 08:15:27 INFO Uploading abc-hello (1.0GB)486--- PASS: TestDumpPathWriterError (3.27s)4872026/11/06 08:15:27 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:37675/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:37675/part/24882026/11/06 08:15:27 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"489--- PASS: TestDumpPathSingleFile (3.46s)490--- PASS: TestDumpPathMatchesNix (3.41s)491--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (3.71s)492--- PASS: TestSupersededNARStillUploadsListing (2.55s)493 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.30s)494 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.30s)495 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.85s)496--- PASS: TestUploadMultipart_PartsInParallel (3.83s)497PASS498Running server tests...499The files belonging to this database system will be owned by user "nixbld".500This user must also own the server process.501502The database cluster will be initialized with locale "C".503The default database encoding has accordingly been set to "SQL_ASCII".504The default text search configuration will be set to "english".505506Data page checksums are enabled.507508creating directory /build/postgres1651136300/data ... ok509creating subdirectories ... ok510selecting dynamic shared memory implementation ... posix511selecting default "max_connections" ... 100512selecting default "shared_buffers" ... 128MB513selecting default time zone ... UTC514creating configuration files ... ok515running bootstrap script ... ok516performing post-bootstrap initialization ... ok517syncing data to disk ... ok518519initdb: warning: enabling "trust" authentication for local connections520initdb: 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.521522Success. You can now start the database server using:523524 pg_ctl -D /build/postgres1651136300/data -l logfile start525526/build/postgres1651136300:5432 - no response527/build/postgres1651136300:5432 - no response528/build/postgres1651136300:5432 - no response5292026-11-06 08:15:32.854 UTC [129] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit5302026-11-06 08:15:32.855 UTC [129] LOG: listening on Unix socket "/build/postgres1651136300/.s.PGSQL.5432"5312026-11-06 08:15:32.861 UTC [138] LOG: database system was shut down at 2026-11-06 08:15:32 UTC5322026-11-06 08:15:32.865 UTC [129] LOG: database system is ready to accept connections533/build/postgres1651136300:5432 - accepting connections534{"timestamp":"2026-11-06T08:15:47.683588803Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"a0bd40e5-2694-482c-a5e9-7a430bd921f9","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":20,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(198)"}535{"timestamp":"2026-11-06T08:15:47.801186849Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"9b4fba67-18f8-4cd3-be89-00ebf815b70a","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(197)"}536{"timestamp":"2026-11-06T08:15:47.906343098Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"9069cc41-47ee-4a1a-b8f7-ab12bfc38ef6","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(195)"}537{"timestamp":"2026-11-06T08:15:48.011045463Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"6bedd4a1-1dcb-40e0-9af2-c581bf27671f","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":1,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(208)"}538=== RUN TestService_AuthMiddleware539=== PAUSE TestService_AuthMiddleware540=== RUN TestService_AuthMiddleware_MTLSProxyHeader541=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader542=== RUN TestService_AuthMiddleware_MTLSBoundSubjects543=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects544=== RUN TestService_ReadAuthMiddleware545=== PAUSE TestService_ReadAuthMiddleware546=== RUN TestService_AuthMiddleware_OIDC547=== PAUSE TestService_AuthMiddleware_OIDC548=== RUN TestService_RequireScope_OIDC549=== PAUSE TestService_RequireScope_OIDC550=== RUN TestService_ReadScope_PublicByDefault551=== PAUSE TestService_ReadScope_PublicByDefault552=== RUN TestCacheConfigHandler553=== PAUSE TestCacheConfigHandler554=== RUN TestCacheStatsHandler555=== PAUSE TestCacheStatsHandler556=== RUN TestClientCADerivations557=== PAUSE TestClientCADerivations558=== RUN TestClientErrorHandling559=== PAUSE TestClientErrorHandling560=== RUN TestClientIntegration561=== PAUSE TestClientIntegration562=== RUN TestClientMultipleUploads563=== PAUSE TestClientMultipleUploads564=== RUN TestClientWithDependencies565=== PAUSE TestClientWithDependencies566=== RUN TestClientSharedPathCommittedMidPush567=== PAUSE TestClientSharedPathCommittedMidPush568=== RUN TestPinProtectsFromGC569=== PAUSE TestPinProtectsFromGC570=== RUN TestClientPushesUseOnePush571=== PAUSE TestClientPushesUseOnePush572=== RUN TestClientFallsBackToClosures573=== PAUSE TestClientFallsBackToClosures574=== RUN TestDeleteClosuresRacingPins575=== PAUSE TestDeleteClosuresRacingPins576=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock577=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock578=== RUN TestResolveDBConnectionString579=== PAUSE TestResolveDBConnectionString580=== RUN TestConnectWaitsForAPeerMigration581=== PAUSE TestConnectWaitsForAPeerMigration582=== RUN TestLeadElectsOneAndHandsOver583=== PAUSE TestLeadElectsOneAndHandsOver584=== RUN TestLeadIncumbentWinsAfterRestart5852026/11/06 08:15:51 INFO lead: acquired remote=192.0.2.1:12345862026/11/06 08:15:51 INFO lead: released remote=192.0.2.1:12345872026/11/06 08:15:51 INFO lead: acquired remote=192.0.2.1:12345882026/11/06 08:15:53 INFO lead: released remote=192.0.2.1:1234589--- PASS: TestLeadIncumbentWinsAfterRestart (4.89s)590=== RUN TestLeadIncumbentAnnouncesAtOnce591=== PAUSE TestLeadIncumbentAnnouncesAtOnce592=== RUN TestLeadEndsOnShutdown593=== PAUSE TestLeadEndsOnShutdown594=== RUN TestLeadEndsWhenItsConnectionHangs5952026/11/06 08:15:54 INFO lead: acquired remote=192.0.2.1:12345962026-11-06 08:15:55.508 UTC [393] FATAL: terminating connection due to administrator command5972026/11/06 08:15:55 INFO lead: acquired remote=192.0.2.1:12345982026/11/06 08:15:56 WARN lead: lock connection lost error="timeout: context deadline exceeded"5992026/11/06 08:15:56 INFO lead: released remote=192.0.2.1:12346002026/11/06 08:15:57 INFO lead: released remote=192.0.2.1:1234601--- PASS: TestLeadEndsWhenItsConnectionHangs (4.08s)602=== RUN TestGCAdvisoryLockBlocksConcurrentRun603=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun604=== RUN TestGCBugBareHashReferences605=== PAUSE TestGCBugBareHashReferences606=== RUN TestGCMetrics607=== PAUSE TestGCMetrics608=== RUN TestPushDedupSurvivesConcurrentGC609=== PAUSE TestPushDedupSurvivesConcurrentGC610=== RUN TestDeduplicatedObjectsRecordedAsPending611=== PAUSE TestDeduplicatedObjectsRecordedAsPending612=== RUN TestGCSweepSkipsPendingObjects613=== PAUSE TestGCSweepSkipsPendingObjects614=== RUN TestTombstonedObjectOfferedWithoutWaiting615=== PAUSE TestTombstonedObjectOfferedWithoutWaiting616=== RUN TestGCSweepDeliversEachKeyOnce617=== PAUSE TestGCSweepDeliversEachKeyOnce618=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection619=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection620=== RUN TestForceGCDuringPushOffersSweptObject621=== PAUSE TestForceGCDuringPushOffersSweptObject622=== RUN TestFailedS3DeleteKeepsTombstone623=== PAUSE TestFailedS3DeleteKeepsTombstone624=== RUN TestSweepSkipsRowsLockedByPush625=== PAUSE TestSweepSkipsRowsLockedByPush626=== RUN TestRegisterCompletedObjectNeedsPendingRow627=== PAUSE TestRegisterCompletedObjectNeedsPendingRow628=== RUN TestGetExistingObjectsLocksRows629=== PAUSE TestGetExistingObjectsLocksRows630=== RUN TestSweepRechecksPendingAfterLocking631=== PAUSE TestSweepRechecksPendingAfterLocking632=== RUN TestPushWaitsForSweepHoldingRow633=== PAUSE TestPushWaitsForSweepHoldingRow634=== RUN TestCommitRacingPendingCleanupKeepsObjects635=== PAUSE TestCommitRacingPendingCleanupKeepsObjects636=== RUN TestGCEndsOnShutdown637=== PAUSE TestGCEndsOnShutdown638=== RUN TestGCTaskStore_StartNew639=== PAUSE TestGCTaskStore_StartNew640=== RUN TestGCTaskStore_DeduplicateSameParams641=== PAUSE TestGCTaskStore_DeduplicateSameParams642=== RUN TestGCTaskStore_ConflictDifferentParams643=== PAUSE TestGCTaskStore_ConflictDifferentParams644=== RUN TestGCTaskStore_GetEmpty645=== PAUSE TestGCTaskStore_GetEmpty646=== RUN TestGCTaskStore_GetReturnsLatest647=== PAUSE TestGCTaskStore_GetReturnsLatest648=== RUN TestGCTaskStore_CompletedAllowsNewTask649=== PAUSE TestGCTaskStore_CompletedAllowsNewTask650=== RUN TestGCTaskStore_PhaseUpdates651=== PAUSE TestGCTaskStore_PhaseUpdates652=== RUN TestGCTaskStore_Fail653=== PAUSE TestGCTaskStore_Fail654=== RUN TestGracefulShutdownDrainsInflight655=== PAUSE TestGracefulShutdownDrainsInflight656=== RUN TestService_healthCheckHandler657=== PAUSE TestService_healthCheckHandler658=== RUN TestService_readinessHandler659=== PAUSE TestService_readinessHandler660=== RUN TestGenerateLandingPage661=== PAUSE TestGenerateLandingPage662=== RUN TestCacheConfigHandlerMaxNarSize663=== PAUSE TestCacheConfigHandlerMaxNarSize664=== RUN TestCreatePendingClosureRejectsOversizedNAR665=== PAUSE TestCreatePendingClosureRejectsOversizedNAR666=== RUN TestNARDeduplicationMetadataUploadBug667=== PAUSE TestNARDeduplicationMetadataUploadBug668=== RUN TestMetricsInventory669=== PAUSE TestMetricsInventory670=== RUN TestMetricsCommit671=== PAUSE TestMetricsCommit672=== RUN TestService_NativeMTLS673=== PAUSE TestService_NativeMTLS674=== RUN TestServerTLSConfig675=== PAUSE TestServerTLSConfig676=== RUN TestMultipartCleanup677=== PAUSE TestMultipartCleanup678=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded679=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded680=== RUN TestPendingCleanupUsesOneCutoff681=== PAUSE TestPendingCleanupUsesOneCutoff682=== RUN TestObjectStatsTrigger683=== PAUSE TestObjectStatsTrigger684=== RUN TestObjectStatsUpdatedOncePerCommit685=== PAUSE TestObjectStatsUpdatedOncePerCommit686=== RUN TestOrphanedObjectsGC687=== PAUSE TestOrphanedObjectsGC688=== RUN TestOrphanedObjectsGCStressTest689=== PAUSE TestOrphanedObjectsGCStressTest690=== RUN TestCreatePin_ReservedPins691=== PAUSE TestCreatePin_ReservedPins692=== RUN TestPresentReportsOnlyClosureRoots693=== PAUSE TestPresentReportsOnlyClosureRoots694=== RUN TestPresentRefreshesOnlyStaleClosures695=== PAUSE TestPresentRefreshesOnlyStaleClosures696=== RUN TestPresentNotReportedWhileGCDeletesClosure697=== PAUSE TestPresentNotReportedWhileGCDeletesClosure698=== RUN TestParseSingleRange699=== PAUSE TestParseSingleRange700=== RUN TestProxyHeadersOnlyTrustedOnSocket7012026/11/06 08:16:01 INFO Starting HTTP server address=127.0.0.1:398157022026/11/06 08:16:01 INFO Starting HTTP server address=proxy.sock7032026/11/06 08:16:01 WARN mTLS auth: subject not in bound subjects subject="CN=someone"7042026/11/06 08:16:01 INFO Shutdown signal received, draining in-flight requests timeout=10s705--- PASS: TestProxyHeadersOnlyTrustedOnSocket (4.19s)706=== RUN TestIsValidCachePath707=== PAUSE TestIsValidCachePath708=== RUN TestReadProxyNarinfo709=== PAUSE TestReadProxyNarinfo710=== RUN TestReadProxyNarinfoAlreadyDecompressed711=== PAUSE TestReadProxyNarinfoAlreadyDecompressed712=== RUN TestReadProxyContentNegotiation713=== PAUSE TestReadProxyContentNegotiation714=== RUN TestReadProxyNarStreaming715=== PAUSE TestReadProxyNarStreaming716=== RUN TestReadProxy404717=== PAUSE TestReadProxy404718=== RUN TestReadProxyInvalidPath719=== PAUSE TestReadProxyInvalidPath720=== RUN TestReadProxyHead721=== PAUSE TestReadProxyHead722=== RUN TestReadProxyOutlastsServerWriteTimeout723=== PAUSE TestReadProxyOutlastsServerWriteTimeout724=== RUN TestReadProxyConditionalGet725=== PAUSE TestReadProxyConditionalGet726=== RUN TestReadProxyRootRedirectsToIndexHTML727=== PAUSE TestReadProxyRootRedirectsToIndexHTML728=== RUN TestReadProxyDisabled729=== PAUSE TestReadProxyDisabled730=== RUN TestReadRedirectNar731=== PAUSE TestReadRedirectNar732=== RUN TestReadRedirectKeepsNarinfoProxied733=== PAUSE TestReadRedirectKeepsNarinfoProxied734=== RUN TestReadProxyRangeRequest735=== PAUSE TestReadProxyRangeRequest736=== RUN TestReadRedirectUsesPublicS3URL737=== PAUSE TestReadRedirectUsesPublicS3URL738=== RUN TestPush_OverlappingRootsStoreOneRowPerKey739=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey740=== RUN TestPush_CompleteCommitsEveryRoot741=== PAUSE TestPush_CompleteCommitsEveryRoot742=== RUN TestPush_RepeatedRootCommitsOnce743=== PAUSE TestPush_RepeatedRootCommitsOnce744=== RUN TestPush_CompleteWaitsForCleanupOfThePush745=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush746=== RUN TestPush_RootsAreLockedInByteOrder747=== PAUSE TestPush_RootsAreLockedInByteOrder748=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit749=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit750=== RUN TestPush_RejectsBadRequests751=== PAUSE TestPush_RejectsBadRequests752=== RUN TestPush_SignsNarinfosOfItsPendingObjects753=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects754=== RUN TestRedundantMultipartUpload755=== PAUSE TestRedundantMultipartUpload756=== RUN TestCompleteMultipartUpload_ErrorButObjectExists757=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists758=== RUN TestCompletedNarNotReofferedAcrossClosures759=== PAUSE TestCompletedNarNotReofferedAcrossClosures760=== RUN TestPresignedUploadRegisteredBeforeCommit761=== PAUSE TestPresignedUploadRegisteredBeforeCommit762=== RUN TestService_Rustfstest763=== PAUSE TestService_Rustfstest764=== RUN TestParseSize765=== PAUSE TestParseSize766=== RUN TestSkippedUploadsHandler767=== PAUSE TestSkippedUploadsHandler768=== RUN TestSystemdListenerNotActivated769--- PASS: TestSystemdListenerNotActivated (0.00s)770=== RUN TestWatchdogBeatsWhenHealthy771--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)772=== RUN TestWatchdogSkipsWhenUnhealthy7732026/11/06 08:16:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/11/06 08:16:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7752026/11/06 08:16:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7762026/11/06 08:16:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7772026/11/06 08:16:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7782026/11/06 08:16:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7792026/11/06 08:16:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7802026/11/06 08:16:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7812026/11/06 08:16:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7822026/11/06 08:16:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"783--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)784=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle785=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle786=== RUN TestProxyWriteTimeout787=== PAUSE TestProxyWriteTimeout788=== RUN TestPendingClosureWriteTimeout789=== PAUSE TestPendingClosureWriteTimeout790=== RUN TestIsValidUploadKey791=== PAUSE TestIsValidUploadKey792=== RUN TestUploadHandlersRejectInvalidKeys793=== PAUSE TestUploadHandlersRejectInvalidKeys794=== RUN TestUploadHandlersRejectOversizedBody795=== PAUSE TestUploadHandlersRejectOversizedBody796=== RUN TestService_cleanupPendingClosuresHandler797=== PAUSE TestService_cleanupPendingClosuresHandler798=== RUN TestService_createPendingClosureHandler799=== PAUSE TestService_createPendingClosureHandler800=== RUN TestService_verifyS3Integrity801=== PAUSE TestService_verifyS3Integrity802=== RUN TestService_verifyS3ReuploadsStaleNarinfo803=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo804=== RUN TestCompleteMultipartUnregistered805=== PAUSE TestCompleteMultipartUnregistered806=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT807=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT808=== CONT TestPendingClosureWriteTimeout809=== CONT TestParseSize810=== CONT TestService_Rustfstest811=== CONT TestPush_CompleteWaitsForCleanupOfThePush812=== CONT TestService_healthCheckHandler813=== CONT TestGCTaskStore_GetEmpty814=== CONT TestGCTaskStore_DeduplicateSameParams815=== CONT TestReadProxyContentNegotiation816=== CONT TestProxyWriteTimeout817=== RUN TestProxyWriteTimeout/narinfo818=== PAUSE TestProxyWriteTimeout/narinfo819=== RUN TestProxyWriteTimeout/1_GiB_nar820=== PAUSE TestProxyWriteTimeout/1_GiB_nar821=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle822=== CONT TestSkippedUploadsHandler823--- PASS: TestParseSize (0.00s)824=== CONT TestPresignedUploadRegisteredBeforeCommit825=== CONT TestCompletedNarNotReofferedAcrossClosures826=== CONT TestCompleteMultipartUpload_ErrorButObjectExists827=== CONT TestGracefulShutdownDrainsInflight828=== CONT TestRedundantMultipartUpload829=== CONT TestGCTaskStore_Fail830=== CONT TestPush_SignsNarinfosOfItsPendingObjects831=== CONT TestGCTaskStore_PhaseUpdates832=== CONT TestPush_RejectsBadRequests833=== CONT TestGCTaskStore_CompletedAllowsNewTask834=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit835=== CONT TestGCTaskStore_GetReturnsLatest836=== CONT TestPush_RootsAreLockedInByteOrder837=== CONT TestGCTaskStore_ConflictDifferentParams838=== CONT TestService_AuthMiddleware839=== RUN TestPendingClosureWriteTimeout/empty840=== CONT TestObjectStatsTrigger841=== RUN TestProxyWriteTimeout/10_GiB_nar842--- PASS: TestGCTaskStore_GetEmpty (0.00s)843--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)844--- PASS: TestGCTaskStore_Fail (0.00s)845--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)846=== CONT TestGCTaskStore_StartNew847--- PASS: TestGCTaskStore_StartNew (0.00s)848=== CONT TestGCEndsOnShutdown849=== RUN TestGCEndsOnShutdown/before_the_run850=== PAUSE TestGCEndsOnShutdown/before_the_run851=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete852=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete853=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark854=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark855=== CONT TestReadProxyNarinfoAlreadyDecompressed8562026/11/06 08:16:01 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000857--- PASS: TestSkippedUploadsHandler (0.01s)858=== CONT TestCommitRacingPendingCleanupKeepsObjects859=== CONT TestReadProxyNarinfo860--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)861=== CONT TestIsValidCachePath862--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)863=== CONT TestPushWaitsForSweepHoldingRow864=== PAUSE TestProxyWriteTimeout/10_GiB_nar865--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)866=== CONT TestParseSingleRange867=== RUN TestParseSingleRange/none868=== PAUSE TestParseSingleRange/none869=== RUN TestParseSingleRange/unknown_unit870=== PAUSE TestParseSingleRange/unknown_unit8712026/11/06 08:16:03 INFO Starting HTTP server address=127.0.0.1:45041872=== RUN TestIsValidCachePath/narinfo873=== PAUSE TestIsValidCachePath/narinfo874=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars875=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars876=== RUN TestIsValidCachePath/nar_zst877=== PAUSE TestIsValidCachePath/nar_zst878=== RUN TestIsValidCachePath/nar_xz879=== PAUSE TestIsValidCachePath/nar_xz880=== RUN TestIsValidCachePath/nar_bz2881=== PAUSE TestIsValidCachePath/nar_bz2882=== RUN TestIsValidCachePath/nar_uncompressed883=== PAUSE TestIsValidCachePath/nar_uncompressed884=== RUN TestIsValidCachePath/ls885=== PAUSE TestIsValidCachePath/ls886=== RUN TestIsValidCachePath/log887=== PAUSE TestIsValidCachePath/log888=== RUN TestIsValidCachePath/realisation889=== PAUSE TestIsValidCachePath/realisation890=== RUN TestIsValidCachePath/nix-cache-info891=== PAUSE TestIsValidCachePath/nix-cache-info892=== RUN TestIsValidCachePath/index.html893=== PAUSE TestIsValidCachePath/index.html894=== RUN TestIsValidCachePath/traversal_parent895=== PAUSE TestIsValidCachePath/traversal_parent896=== RUN TestIsValidCachePath/traversal_in_middle897=== PAUSE TestIsValidCachePath/traversal_in_middle898=== RUN TestIsValidCachePath/invalid_char_e899=== PAUSE TestIsValidCachePath/invalid_char_e900=== RUN TestIsValidCachePath/invalid_char_u901=== PAUSE TestIsValidCachePath/invalid_char_u902=== RUN TestIsValidCachePath/random_path903=== PAUSE TestIsValidCachePath/random_path904=== RUN TestIsValidCachePath/empty905=== PAUSE TestIsValidCachePath/empty906=== RUN TestIsValidCachePath/leading_slash907=== PAUSE TestIsValidCachePath/leading_slash908=== RUN TestIsValidCachePath/wrong_extension909=== PAUSE TestIsValidCachePath/wrong_extension910=== RUN TestIsValidCachePath/short_hash911=== PAUSE TestIsValidCachePath/short_hash912=== RUN TestProxyWriteTimeout/unknown_size913=== PAUSE TestProxyWriteTimeout/unknown_size914=== CONT TestSweepRechecksPendingAfterLocking9152026/11/06 08:16:03 INFO Shutdown signal received, draining in-flight requests timeout=10s916=== CONT TestPresentNotReportedWhileGCDeletesClosure917=== PAUSE TestPendingClosureWriteTimeout/empty918=== RUN TestPendingClosureWriteTimeout/400_objects919=== PAUSE TestPendingClosureWriteTimeout/400_objects920=== RUN TestParseSingleRange/multi-range_ignored921=== PAUSE TestParseSingleRange/multi-range_ignored922=== RUN TestPendingClosureWriteTimeout/670k_objects923=== PAUSE TestPendingClosureWriteTimeout/670k_objects924=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale925=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale926=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline927=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh928=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh929=== CONT TestGetExistingObjectsLocksRows930=== RUN TestParseSingleRange/malformed_no_dash931=== PAUSE TestParseSingleRange/malformed_no_dash932=== RUN TestParseSingleRange/malformed_both_empty933=== PAUSE TestParseSingleRange/malformed_both_empty934=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline935=== CONT TestPresentRefreshesOnlyStaleClosures936=== RUN TestParseSingleRange/malformed_end_before_start937=== PAUSE TestParseSingleRange/malformed_end_before_start938=== RUN TestParseSingleRange/closed939=== PAUSE TestParseSingleRange/closed940=== RUN TestParseSingleRange/open-ended941=== PAUSE TestParseSingleRange/open-ended942=== RUN TestParseSingleRange/end_clamped_to_size943=== PAUSE TestParseSingleRange/end_clamped_to_size944=== RUN TestParseSingleRange/suffix945=== PAUSE TestParseSingleRange/suffix946=== RUN TestParseSingleRange/suffix_exceeds_size947=== PAUSE TestParseSingleRange/suffix_exceeds_size948=== RUN TestParseSingleRange/single_byte949=== PAUSE TestParseSingleRange/single_byte950=== RUN TestParseSingleRange/start_past_EOF951=== PAUSE TestParseSingleRange/start_past_EOF952=== RUN TestParseSingleRange/start_far_past_EOF953=== PAUSE TestParseSingleRange/start_far_past_EOF954=== CONT TestRegisterCompletedObjectNeedsPendingRow955--- PASS: TestGracefulShutdownDrainsInflight (3.82s)956=== CONT TestPresentReportsOnlyClosureRoots9572026/11/06 08:16:07 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>958=== CONT TestFailedS3DeleteKeepsTombstone959--- PASS: TestReadProxyNarinfo (6.18s)960--- PASS: TestService_Rustfstest (6.25s)961=== CONT TestCreatePin_ReservedPins9622026/11/06 08:16:07 INFO Received uploads request method=POST path=/api/pending_closures9632026/11/06 08:16:07 INFO Received uploads request method=POST path=/api/pending_closures9642026/11/06 08:16:07 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9652026/11/06 08:16:07 INFO Received uploads request method=POST path=/api/pending_closures966--- PASS: TestPresignedUploadRegisteredBeforeCommit (6.35s)967=== CONT TestForceGCDuringPushOffersSweptObject968=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows969=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows970=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check971=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check972=== CONT TestSweepSkipsRowsLockedByPush973--- PASS: TestReadProxyNarinfoAlreadyDecompressed (6.40s)974=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection9752026/11/06 08:16:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36481/oidc9762026/11/06 08:16:07 INFO Received uploads request method=POST path=/api/pending_closures9772026/11/06 08:16:07 INFO Received uploads request method=POST path=/api/pending_closures978--- PASS: TestReadProxyContentNegotiation (6.46s)979=== CONT TestOrphanedObjectsGCStressTest9802026/11/06 08:16:08 INFO Received push request method=POST path=/api/pushes9812026/11/06 08:16:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete982=== RUN TestPush_RejectsBadRequests/no_objects983=== PAUSE TestPush_RejectsBadRequests/no_objects984=== RUN TestPush_RejectsBadRequests/bad_root985=== PAUSE TestPush_RejectsBadRequests/bad_root986=== RUN TestPush_RejectsBadRequests/root_not_in_objects987=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects988=== RUN TestPush_RejectsBadRequests/no_roots989=== PAUSE TestPush_RejectsBadRequests/no_roots990=== CONT TestGCSweepDeliversEachKeyOnce991--- PASS: TestService_healthCheckHandler (6.63s)992=== CONT TestOrphanedObjectsGC9932026/11/06 08:16:08 INFO Aborted multipart uploads count=0 kept=09942026/11/06 08:16:08 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"995--- PASS: TestService_AuthMiddleware (4.74s)996=== CONT TestTombstonedObjectOfferedWithoutWaiting997--- PASS: TestPresentReportsOnlyClosureRoots (0.98s)998=== CONT TestObjectStatsUpdatedOncePerCommit9992026/11/06 08:16:08 INFO Received push request method=POST path=/api/pushes10002026/11/06 08:16:08 INFO Received complete push request method=POST path=/api/pushes/1/complete1001--- PASS: TestGetExistingObjectsLocksRows (4.85s)1002=== CONT TestGCSweepSkipsPendingObjects10032026/11/06 08:16:08 INFO Received uploads request method=POST path=/api/pending_closures10042026/11/06 08:16:08 INFO Received uploads request method=POST path=/api/pending_closures10052026/11/06 08:16:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10062026/11/06 08:16:08 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MmNiYmIxMzAtYjA0OS00ZjM3LWFmNDItNGEzZDJhOGY0M2I0LmY5MjQwYWJlLWQ1NGMtNGMwZC05NDgzLWVlNmUyNDk1ZTRkNXgxNzkzOTUyOTY4MDA2NTU2NDQ110072026/11/06 08:16:08 INFO Aborted multipart uploads count=0 kept=010082026/11/06 08:16:08 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MmNiYmIxMzAtYjA0OS00ZjM3LWFmNDItNGEzZDJhOGY0M2I0LmY5MjQwYWJlLWQ1NGMtNGMwZC05NDgzLWVlNmUyNDk1ZTRkNXgxNzkzOTUyOTY4MDA2NTU2NDQ1 parts=11009--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (6.84s)1010=== CONT TestDeduplicatedObjectsRecordedAsPending10112026-11-06 08:16:08.385 UTC [505] ERROR: Push does not exist: id=110122026-11-06 08:16:08.385 UTC [505] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE10132026-11-06 08:16:08.385 UTC [505] STATEMENT: SELECT commit_push($1)1014--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (6.86s)1015=== CONT TestPushDedupSurvivesConcurrentGC1016--- PASS: TestObjectStatsTrigger (4.97s)1017=== CONT TestMetricsCommit10182026/11/06 08:16:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10192026/11/06 08:16:08 INFO Received uploads request method=POST path=/api/pending_closures10202026/11/06 08:16:08 INFO Received push request method=POST path=/api/pushes10212026/11/06 08:16:08 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MmNiYmIxMzAtYjA0OS00ZjM3LWFmNDItNGEzZDJhOGY0M2I0LmYwNDA5ZDExLTZmNDItNGRkNy1iN2U1LWQ3MDExZDQwMWJjZHgxNzkzOTUyOTY3OTU3NTI0MjQ0 parts=1210222026/11/06 08:16:08 INFO Received uploads request method=POST path=/api/pending_closures10232026/11/06 08:16:08 INFO Received uploads request method=POST path=/api/pending_closures1024--- PASS: TestCompletedNarNotReofferedAcrossClosures (6.97s)1025=== CONT TestGCMetrics10262026/11/06 08:16:08 INFO Received push request method=POST path=/api/pushes10272026/11/06 08:16:08 INFO Aborted multipart uploads count=0 kept=010282026/11/06 08:16:08 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10292026/11/06 08:16:08 INFO Signed narinfos id=1 count=110302026/11/06 08:16:08 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10312026/11/06 08:16:08 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10322026/11/06 08:16:08 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"10332026/11/06 08:16:08 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10342026/11/06 08:16:08 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"10352026/11/06 08:16:08 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10362026/11/06 08:16:08 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=110372026/11/06 08:16:08 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10382026/11/06 08:16:08 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1039--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (5.18s)1040=== CONT TestService_createPendingClosureHandler10412026/11/06 08:16:08 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10422026/11/06 08:16:08 WARN Refused reserved pin name=worker-x86_64-linux10432026/11/06 08:16:08 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10442026/11/06 08:16:08 INFO Received create pin request method=POST path=/api/pins/my-app10452026/11/06 08:16:08 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1046--- PASS: TestCreatePin_ReservedPins (0.87s)1047=== CONT TestPendingCleanupUsesOneCutoff10482026/11/06 08:16:08 INFO Aborted multipart uploads count=0 kept=010492026/11/06 08:16:08 INFO Received uploads request method=POST path=/api/pending_closures1050--- PASS: TestRegisterCompletedObjectNeedsPendingRow (5.34s)1051=== CONT TestGCBugBareHashReferences10522026/11/06 08:16:08 INFO Completed push id=1 objects=4 duration=579.045102ms10532026/11/06 08:16:08 INFO Received push request method=POST path=/api/pushes10542026/11/06 08:16:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10552026/11/06 08:16:08 INFO Aborted multipart uploads count=0 kept=010562026/11/06 08:16:08 WARN Force mode enabled - objects will be deleted immediately without grace period10572026/11/06 08:16:08 WARN Force mode enabled - objects will be deleted immediately without grace period10582026/11/06 08:16:08 WARN Force mode enabled - objects will be deleted immediately without grace period10592026/11/06 08: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=010602026/11/06 08: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=010612026/11/06 08:16:08 INFO Vacuumed table table=pending_closures10622026/11/06 08:16:08 INFO Vacuumed table table=pending_objects10632026/11/06 08:16:08 INFO Vacuumed table table=multipart_uploads10642026/11/06 08:16:08 INFO Vacuumed table table=closures10652026-11-06 08:16:08.941 UTC [549] ERROR: could not obtain lock on row in relation "closures"10662026-11-06 08:16:08.941 UTC [549] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10672026-11-06 08:16:08.942 UTC [549] ERROR: could not obtain lock on row in relation "closures"10682026-11-06 08:16:08.942 UTC [549] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1069--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (1.02s)1070=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT10712026-11-06 08:16:08.942 UTC [549] ERROR: could not obtain lock on row in relation "closures"10722026-11-06 08:16:08.942 UTC [549] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10732026-11-06 08:16:08.942 UTC [549] ERROR: could not obtain lock on row in relation "closures"10742026-11-06 08:16:08.942 UTC [549] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10752026-11-06 08:16:08.942 UTC [549] ERROR: could not obtain lock on row in relation "closures"10762026-11-06 08:16:08.942 UTC [549] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10772026/11/06 08:16:08 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MmNiYmIxMzAtYjA0OS00ZjM3LWFmNDItNGEzZDJhOGY0M2I0LmU3YTdkMmNkLTYwNWQtNDFiMS04MjQzLTk1ZjQwOWFhZWVlMXgxNzkzOTUyOTY4MzE3ODM4Njcw parts=1210782026/11/06 08:16:08 WARN Force mode enabled - objects will be deleted immediately without grace period10792026/11/06 08:16:08 WARN Force mode enabled - objects will be deleted immediately without grace period10802026/11/06 08:16:08 INFO Received uploads request method=POST path=/api/pending_closures10812026/11/06 08:16:08 INFO Vacuumed table table=objects10822026/11/06 08:16:08 INFO Vacuumed table table=pending_closures1083--- PASS: TestPush_RootsAreLockedInByteOrder (5.52s)1084=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1085--- PASS: TestPushWaitsForSweepHoldingRow (5.52s)1086=== CONT TestGCAdvisoryLockBlocksConcurrentRun10872026/11/06 08:16:08 INFO Vacuumed table table=pending_objects10882026/11/06 08:16:08 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."10892026/11/06 08:16:08 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."10902026/11/06 08:16:08 INFO Vacuumed table table=multipart_uploads10912026/11/06 08:16:08 INFO Aborted multipart uploads count=0 kept=010922026/11/06 08:16:08 INFO Vacuumed table table=closures10932026/11/06 08:16:08 INFO Vacuumed table table=objects1094--- PASS: TestFailedS3DeleteKeepsTombstone (1.26s)1095=== CONT TestMultipartCleanup10962026/11/06 08:16:08 INFO Received uploads request method=POST path=/api/pending_closures10972026/11/06 08: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=010982026/11/06 08:16:08 WARN Force mode enabled - objects will be deleted immediately without grace period10992026/11/06 08:16:08 INFO Vacuumed table table=pending_closures11002026/11/06 08:16:09 INFO Vacuumed table table=pending_objects11012026/11/06 08:16:09 INFO Vacuumed table table=multipart_uploads11022026/11/06 08:16:09 INFO Vacuumed table table=closures11032026/11/06 08:16:09 INFO Vacuumed table table=objects1104--- PASS: TestSweepRechecksPendingAfterLocking (5.57s)1105=== CONT TestLeadEndsOnShutdown11062026/11/06 08:16:09 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=011072026/11/06 08:16:09 INFO Vacuumed table table=pending_closures11082026/11/06 08:16:09 INFO Vacuumed table table=pending_objects11092026/11/06 08:16:09 INFO Vacuumed table table=multipart_uploads1110--- PASS: TestPresentRefreshesOnlyStaleClosures (5.62s)1111=== CONT TestServerTLSConfig1112=== RUN TestServerTLSConfig/no_client_CA1113=== PAUSE TestServerTLSConfig/no_client_CA1114=== RUN TestServerTLSConfig/missing_CA_file1115=== PAUSE TestServerTLSConfig/missing_CA_file1116=== RUN TestServerTLSConfig/not_a_PEM_file1117=== PAUSE TestServerTLSConfig/not_a_PEM_file1118=== CONT TestCompleteMultipartUnregistered11192026/11/06 08:16:09 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=011202026/11/06 08:16:09 INFO Vacuumed table table=pending_closures11212026/11/06 08:16:09 INFO Vacuumed table table=pending_objects11222026/11/06 08:16:09 INFO Vacuumed table table=multipart_uploads11232026/11/06 08:16:09 INFO Vacuumed table table=closures11242026/11/06 08:16:09 INFO Vacuumed table table=closures11252026/11/06 08:16:09 INFO Vacuumed table table=objects11262026/11/06 08:16:09 INFO Vacuumed table table=objects11272026/11/06 08:16:09 INFO Received complete push request method=POST path=/api/pushes/2/complete1128--- PASS: TestSweepSkipsRowsLockedByPush (1.21s)1129=== CONT TestLeadIncumbentAnnouncesAtOnce11302026/11/06 08:16:09 INFO Completed push id=2 objects=4 duration=5.872695ms1131--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (5.65s)1132=== CONT TestService_NativeMTLS11332026/11/06 08:16:09 INFO Received uploads request method=POST path=/api/pending_closures11342026/11/06 08:16:09 INFO Received uploads request method=POST path=/api/pending_closures11352026/11/06 08:16:09 INFO Received uploads request method=POST path=/api/pending_closures11362026/11/06 08:16:09 INFO Received cleanup request method=DELETE path=/api/pending_closures11372026/11/06 08:16:09 INFO Aborted multipart uploads count=0 kept=011382026/11/06 08:16:09 INFO Received uploads request method=POST path=/api/pending_closures1139--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.83s)1140=== CONT TestService_verifyS3ReuploadsStaleNarinfo1141=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1142=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1143=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1144=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1145=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1146=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1147=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1148=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1149=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1150=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1151=== CONT TestLeadElectsOneAndHandsOver11522026/11/06 08:16:09 INFO Aborted multipart uploads count=0 kept=011532026/11/06 08:16:09 INFO Received uploads request method=POST path=/api/pending_closures11542026/11/06 08:16:09 INFO Received uploads request method=POST path=/api/pending_closures11552026/11/06 08:16:09 INFO Received uploads request method=POST path=/api/pending_closures11562026/11/06 08:16:09 INFO Received push request method=POST path=/api/pushes11572026/11/06 08:16:09 INFO Received complete push request method=POST path=/api/pushes/1/complete11582026/11/06 08:16:09 INFO Received uploads request method=POST path=/api/pending_closures11592026/11/06 08:16:09 INFO Aborted multipart uploads count=0 kept=011602026/11/06 08:16:09 INFO Received uploads request method=POST path=/api/pending_closures1161--- PASS: TestTombstonedObjectOfferedWithoutWaiting (1.23s)1162=== CONT TestUploadHandlersRejectOversizedBody11632026/11/06 08:16:09 INFO Aborted multipart uploads count=0 kept=01164--- PASS: TestObjectStatsUpdatedOncePerCommit (1.29s)1165=== CONT TestService_verifyS3Integrity11662026/11/06 08:16:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11672026/11/06 08:16:09 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MmNiYmIxMzAtYjA0OS00ZjM3LWFmNDItNGEzZDJhOGY0M2I0LjIzZTlhYTY5LWNiYzgtNDY3Ni1hZDQ2LWJmMTQxZTNiMDRiNngxNzkzOTUyOTY4OTk1NzM2NjIx error="Get \"http://127.0.0.1:1/bucket18/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"11682026/11/06 08:16:09 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MmNiYmIxMzAtYjA0OS00ZjM3LWFmNDItNGEzZDJhOGY0M2I0LjIyODg3MDY2LTUyNGItNDkyYi1iMDUzLWYyYmYzZmRjNTRjMHgxNzkzOTUyOTY4OTYyODg1Mjcy parts=1211692026/11/06 08:16:09 INFO Received cleanup request method=DELETE path=/api/pending_closures11702026/11/06 08:16:09 INFO Aborted multipart uploads count=1 kept=01171--- PASS: TestRedundantMultipartUpload (6.16s)1172=== CONT TestConnectWaitsForAPeerMigration1173--- PASS: TestGCBugBareHashReferences (0.82s)1174=== CONT TestService_cleanupPendingClosuresHandler1175=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1176=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1177=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1178=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1179=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1180=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1181=== CONT TestResolveDBConnectionString1182=== RUN TestResolveDBConnectionString/flag_wins1183=== PAUSE TestResolveDBConnectionString/flag_wins1184=== RUN TestResolveDBConnectionString/file_when_flag_empty1185=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1186=== RUN TestResolveDBConnectionString/missing_file_is_an_error1187=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1188=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1189=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1190=== RUN TestResolveDBConnectionString/nothing_configured1191=== PAUSE TestResolveDBConnectionString/nothing_configured1192=== CONT TestReadProxyDisabled11932026/11/06 08:16:09 WARN Force mode enabled - objects will be deleted immediately without grace period11942026/11/06 08:16:09 WARN Force mode enabled - objects will be deleted immediately without grace period11952026/11/06 08:16:09 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011962026/11/06 08:16:09 INFO Completed push id=1 objects=4 duration=318.536973ms11972026/11/06 08:16:09 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=011982026/11/06 08:16:09 INFO Vacuumed table table=pending_closures1199--- PASS: TestCommitRacingPendingCleanupKeepsObjects (8.09s)1200=== CONT TestClientErrorHandling1201=== RUN TestClientErrorHandling/InvalidStorePath1202=== PAUSE TestClientErrorHandling/InvalidStorePath1203=== RUN TestClientErrorHandling/InvalidAuthToken1204=== PAUSE TestClientErrorHandling/InvalidAuthToken1205=== RUN TestClientErrorHandling/ServerNotAvailable1206=== PAUSE TestClientErrorHandling/ServerNotAvailable1207=== CONT TestClientCADerivations12082026/11/06 08:16:09 INFO Vacuumed table table=pending_closures12092026/11/06 08:16:09 WARN Force mode enabled - objects will be deleted immediately without grace period12102026/11/06 08:16:09 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12112026/11/06 08:16:09 INFO Vacuumed table table=pending_objects12122026/11/06 08:16:09 INFO Vacuumed table table=multipart_uploads12132026/11/06 08:16:09 INFO Vacuumed table table=closures12142026/11/06 08:16:09 INFO Completed upload id=2 objects=2 duration=3.470233ms12152026/11/06 08:16:09 INFO Vacuumed table table=pending_objects12162026/11/06 08:16:09 INFO Vacuumed table table=multipart_uploads12172026/11/06 08:16:09 INFO Vacuumed table table=objects12182026/11/06 08:16:09 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012192026/11/06 08:16:09 INFO Vacuumed table table=pending_closures12202026/11/06 08:16:09 INFO Vacuumed table table=pending_objects12212026/11/06 08:16:09 INFO Vacuumed table table=multipart_uploads1222--- PASS: TestMetricsCommit (1.23s)1223=== CONT TestPush_RepeatedRootCommitsOnce12242026/11/06 08:16:09 INFO Vacuumed table table=closures12252026/11/06 08:16:09 INFO Vacuumed table table=closures12262026/11/06 08:16:09 INFO Vacuumed table table=objects12272026/11/06 08:16:09 INFO Vacuumed table table=objects1228--- PASS: TestGCMetrics (1.14s)1229=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1230--- PASS: TestGCSweepSkipsPendingObjects (1.35s)1231=== CONT TestCacheStatsHandler12322026/11/06 08:16:09 INFO Aborted multipart uploads count=0 kept=012332026/11/06 08:16:09 WARN Force mode enabled - objects will be deleted immediately without grace period12342026/11/06 08:16:09 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012352026/11/06 08:16:09 INFO Vacuumed table table=pending_closures12362026/11/06 08:16:09 INFO Vacuumed table table=pending_objects12372026/11/06 08:16:09 INFO Vacuumed table table=multipart_uploads12382026/11/06 08:16:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12392026/11/06 08:16:09 INFO Vacuumed table table=closures12402026/11/06 08:16:09 INFO Vacuumed table table=objects12412026/11/06 08:16:09 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=01242--- PASS: TestPushDedupSurvivesConcurrentGC (1.29s)1243=== CONT TestPush_CompleteCommitsEveryRoot12442026/11/06 08:16:09 INFO Vacuumed table table=pending_closures12452026/11/06 08:16:09 INFO Vacuumed table table=pending_objects12462026/11/06 08:16:09 INFO Vacuumed table table=multipart_uploads12472026/11/06 08:16:09 INFO Vacuumed table table=closures12482026/11/06 08:16:09 INFO Vacuumed table table=objects1249--- PASS: TestGCSweepDeliversEachKeyOnce (1.60s)1250=== CONT TestDeleteClosuresRacingPins12512026/11/06 08:16:09 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MmNiYmIxMzAtYjA0OS00ZjM3LWFmNDItNGEzZDJhOGY0M2I0LjJmZmFhZmI4LTVhM2QtNDAyYi1iNjYxLWI3OTYyZGQ4MWI3ZngxNzkzOTUyOTY5MjI3NTg4NTk5 parts=1012522026/11/06 08:16:09 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12532026/11/06 08:16:09 INFO Completed upload id=1 objects=2 duration=5.635133ms12542026/11/06 08:16:09 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000012552026/11/06 08:16:09 INFO Received uploads request method=POST path=/api/pending_closures12562026/11/06 08:16:09 INFO Received uploads request method=POST path=/api/pending_closures12572026/11/06 08:16:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures12582026/11/06 08:16:09 INFO Aborted multipart uploads count=0 kept=012592026/11/06 08:16:09 INFO lead: acquired remote=192.0.2.1:123412602026/11/06 08:16:09 INFO lead: acquired remote=192.0.2.1:123412612026/11/06 08:16:09 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12622026/11/06 08:16:09 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1263--- PASS: TestService_NativeMTLS (0.70s)1264=== CONT TestCacheConfigHandler1265=== RUN TestCacheConfigHandler/full_config,_no_issuer1266=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1267=== RUN TestCacheConfigHandler/no_cache_url_configured1268=== PAUSE TestCacheConfigHandler/no_cache_url_configured1269=== RUN TestCacheConfigHandler/no_signing_keys1270=== PAUSE TestCacheConfigHandler/no_signing_keys1271=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1272=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1273=== CONT TestClientFallsBackToClosures12742026/11/06 08:16:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12752026/11/06 08:16:09 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1276--- PASS: TestCompleteMultipartUnregistered (0.74s)1277=== CONT TestPush_OverlappingRootsStoreOneRowPerKey12782026/11/06 08:16:09 INFO lead: acquired remote=192.0.2.1:123412792026/11/06 08:16:09 INFO lead: released remote=192.0.2.1:12341280--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.75s)1281=== CONT TestClientPushesUseOnePush12822026/11/06 08:16:09 INFO Received cleanup request method=DELETE path=/api/pending_closures12832026/11/06 08:16:09 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket45/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""12842026/11/06 08:16:09 INFO Aborted multipart uploads count=0 kept=112852026/11/06 08:16:09 INFO Received cleanup request method=DELETE path=/api/pending_closures12862026/11/06 08:16:09 INFO Aborted multipart uploads count=1 kept=01287--- PASS: TestMultipartCleanup (0.87s)1288=== CONT TestService_ReadScope_PublicByDefault12892026/11/06 08:16:09 INFO Received uploads request method=POST path=/api/pending_closures12902026/11/06 08:16:09 INFO Received uploads request method=POST path=/api/pending_closures1291--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.94s)1292=== CONT TestReadRedirectUsesPublicS3URL1293--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.97s)1294=== CONT TestService_RequireScope_OIDC12952026/11/06 08:16:09 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=nixbld database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1296--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.98s)1297=== CONT TestPinProtectsFromGC12982026/11/06 08:16:09 INFO Received uploads request method=POST path=/api/pending_closures12992026/11/06 08:16:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44525/oidc13002026/11/06 08:16:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13012026/11/06 08:16:10 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MmNiYmIxMzAtYjA0OS00ZjM3LWFmNDItNGEzZDJhOGY0M2I0LmMxNDJhOWVjLTRiYjktNGEwMC1hNjFiLTI1ZTdhNDI3ODYzOXgxNzkzOTUyOTY5OTU5Nzk0NTgw parts=1013022026/11/06 08:16:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13032026/11/06 08:16:10 INFO Completed upload id=1 objects=2 duration=2.663505ms13042026/11/06 08:16:10 INFO Received uploads request method=POST path=/api/pending_closures13052026/11/06 08:16:10 INFO Received uploads request method=POST path=/api/pending_closures13062026/11/06 08:16:10 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo13072026/11/06 08:16:10 WARN Found objects in DB but missing from S3, will re-upload count=11308--- PASS: TestService_verifyS3Integrity (0.91s)1309=== CONT TestService_AuthMiddleware_OIDC13102026/11/06 08:16:10 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45169/oidc13112026/11/06 08:16:10 INFO Received cleanup request method=DELETE path=/api/pending_closures13122026/11/06 08:16:10 INFO Aborted multipart uploads count=0 kept=013132026/11/06 08:16:10 INFO Received push request method=POST path=/api/pushes13142026/11/06 08:16:10 INFO Received uploads request method=POST path=/api/pending_closures13152026/11/06 08:16:10 INFO Received cleanup request method=DELETE path=/api/pending_closures13162026/11/06 08:16:10 INFO Aborted multipart uploads count=1 kept=013172026/11/06 08:16:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13182026-11-06 08:16:10.763 UTC [628] ERROR: Closure does not exist: id=113192026-11-06 08:16:10.763 UTC [628] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE13202026-11-06 08:16:10.763 UTC [628] STATEMENT: -- name: CommitPendingClosure :one1321 SELECT commit_pending_closure($1::bigint)::bigint1322 1323--- PASS: TestService_cleanupPendingClosuresHandler (1.15s)1324=== CONT TestReadProxyRangeRequest13252026/11/06 08:16:10 INFO Received complete push request method=POST path=/api/pushes/1/complete13262026/11/06 08:16:10 INFO lead: released remote=192.0.2.1:12341327--- PASS: TestLeadEndsOnShutdown (1.77s)1328=== CONT TestClientSharedPathCommittedMidPush13292026/11/06 08:16:10 INFO Completed push id=1 objects=6 duration=7.959575ms1330--- PASS: TestPush_CompleteCommitsEveryRoot (1.11s)1331=== CONT TestService_ReadAuthMiddleware13322026/11/06 08:16:11 INFO lead: released remote=192.0.2.1:123413332026/11/06 08:16:11 INFO lead: acquired remote=192.0.2.1:12341334=== NAME TestOrphanedObjectsGCStressTest1335 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains13362026/11/06 08:16:12 WARN Rate limiter enabled after throttle name=s3-test rate=513372026/11/06 08:16:12 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1338=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1339 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101340 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001341--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (10.59s)1342=== CONT TestReadRedirectKeepsNarinfoProxied13432026/11/06 08:16:12 INFO lead: released remote=192.0.2.1:12341344--- PASS: TestLeadElectsOneAndHandsOver (2.98s)1345=== CONT TestClientWithDependencies1346=== NAME TestOrphanedObjectsGCStressTest1347 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion1348=== RUN TestService_RequireScope_OIDC/builder_may_write1349=== PAUSE TestService_RequireScope_OIDC/builder_may_write1350=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1351=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1352=== RUN TestService_RequireScope_OIDC/ops_may_admin1353=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1354=== RUN TestService_RequireScope_OIDC/ops_may_not_write1355=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1356=== RUN TestService_RequireScope_OIDC/reader_may_not_write1357=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1358=== RUN TestService_RequireScope_OIDC/static_token_may_admin1359=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1360=== RUN TestService_RequireScope_OIDC/static_token_may_write1361=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1362=== RUN TestService_RequireScope_OIDC/reader_may_read1363=== PAUSE TestService_RequireScope_OIDC/reader_may_read1364=== RUN TestService_RequireScope_OIDC/writer_implies_read1365=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1366=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1367=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1368=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1369=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1370=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1371=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1372=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1373=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1374=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1375=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1376=== CONT TestService_AuthMiddleware_MTLSBoundSubjects13772026/11/06 08:16:12 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=013782026/11/06 08:16:12 INFO Vacuumed table table=pending_closures13792026/11/06 08:16:12 INFO Vacuumed table table=pending_objects13802026/11/06 08:16:12 INFO Vacuumed table table=multipart_uploads13812026/11/06 08:16:12 INFO Vacuumed table table=closures13822026/11/06 08:16:12 INFO Vacuumed table table=objects13832026/11/06 08:16:12 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001384--- PASS: TestService_createPendingClosureHandler (3.96s)1385=== CONT TestReadRedirectNar1386=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1387=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1388=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1389=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1390=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1391=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1392=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1393=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1394=== CONT TestClientMultipleUploads1395--- PASS: TestReadRedirectKeepsNarinfoProxied (0.53s)1396=== CONT TestService_AuthMiddleware_MTLSProxyHeader1397--- PASS: TestService_ReadAuthMiddleware (1.88s)1398=== CONT TestUploadHandlersRejectInvalidKeys1399=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1400=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1401=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1402=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1403=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1404=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1405=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1406=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1407=== CONT TestClientIntegration1408--- PASS: TestReadRedirectUsesPublicS3URL (2.82s)1409=== CONT TestReadProxyConditionalGet1410--- PASS: TestReadProxyRangeRequest (2.01s)1411=== CONT TestIsValidUploadKey1412=== RUN TestIsValidUploadKey/narinfo1413=== PAUSE TestIsValidUploadKey/narinfo1414=== RUN TestIsValidUploadKey/nar_zst1415=== PAUSE TestIsValidUploadKey/nar_zst1416=== RUN TestIsValidUploadKey/nar_xz1417=== PAUSE TestIsValidUploadKey/nar_xz1418=== RUN TestIsValidUploadKey/nar_plain1419=== PAUSE TestIsValidUploadKey/nar_plain1420=== RUN TestIsValidUploadKey/listing1421=== PAUSE TestIsValidUploadKey/listing1422=== RUN TestIsValidUploadKey/build_log1423=== PAUSE TestIsValidUploadKey/build_log1424=== RUN TestIsValidUploadKey/build_log_home-manager_file1425=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1426=== RUN TestIsValidUploadKey/build_log_plus_in_name1427=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1428=== RUN TestIsValidUploadKey/build_log_question_mark1429=== PAUSE TestIsValidUploadKey/build_log_question_mark1430=== RUN TestIsValidUploadKey/build_log_equals1431=== PAUSE TestIsValidUploadKey/build_log_equals1432=== RUN TestIsValidUploadKey/realisation1433=== PAUSE TestIsValidUploadKey/realisation1434=== RUN TestIsValidUploadKey/realisation_plus_in_output1435=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1436=== RUN TestIsValidUploadKey/nix-cache-info1437=== PAUSE TestIsValidUploadKey/nix-cache-info1438=== RUN TestIsValidUploadKey/index.html1439=== PAUSE TestIsValidUploadKey/index.html1440=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1441=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1442=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1443=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1444=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1445=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1446=== RUN TestIsValidUploadKey/traversal1447=== PAUSE TestIsValidUploadKey/traversal1448=== RUN TestIsValidUploadKey/traversal_nar1449=== PAUSE TestIsValidUploadKey/traversal_nar1450=== RUN TestIsValidUploadKey/absolute1451=== PAUSE TestIsValidUploadKey/absolute1452=== RUN TestIsValidUploadKey/empty_key1453=== PAUSE TestIsValidUploadKey/empty_key1454=== RUN TestIsValidUploadKey/unknown_type1455=== PAUSE TestIsValidUploadKey/unknown_type1456=== CONT TestReadProxyOutlastsServerWriteTimeout1457--- PASS: TestService_ReadScope_PublicByDefault (2.96s)1458=== CONT TestReadProxyRootRedirectsToIndexHTML14592026/11/06 08:16:12 INFO Received push request method=POST path=/api/pushes1460--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (3.13s)1461=== CONT TestCreatePendingClosureRejectsOversizedNAR14622026/11/06 08:16:12 INFO Received uploads request method=POST path=/api/pending_closures1463--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1464=== CONT TestReadProxyHead1465--- PASS: TestCacheStatsHandler (3.31s)1466=== CONT TestGenerateLandingPage1467--- PASS: TestGenerateLandingPage (0.01s)1468=== CONT TestMetricsInventory1469--- PASS: TestReadProxyDisabled (3.37s)1470=== CONT TestCacheConfigHandlerMaxNarSize1471--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1472=== CONT TestNARDeduplicationMetadataUploadBug14732026/11/06 08:16:13 INFO Received push request method=POST path=/api/pushes14742026/11/06 08:16:13 INFO Received complete push request method=POST path=/api/pushes/1/complete14752026/11/06 08:16:13 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"14762026/11/06 08:16:13 WARN mTLS auth: bound subjects configured but subject DN unavailable14772026/11/06 08:16:13 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1478--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.65s)1479=== CONT TestReadProxyNarStreaming14802026/11/06 08:16:13 INFO Completed push id=1 objects=4 duration=158.693632ms1481--- PASS: TestPush_RepeatedRootCommitsOnce (3.57s)1482=== CONT TestReadProxyInvalidPath1483=== NAME TestClientWithDependencies1484 client_integration_test.go:660: Built derivation: /build/TestClientWithDependencies1854408754/001/store/lim80ikw5xr8p0v2cyq6218vj24367nz-test-script1485=== NAME TestPinProtectsFromGC1486 client_integration_test.go:778: Pinned store path: /build/TestPinProtectsFromGC2470471681/001/store/47101hbrxq7kjcjs2bnpv87ammg0ss8c-pinned-file.txt1487 client_integration_test.go:779: Unpinned store path: /build/TestPinProtectsFromGC2470471681/001/store/8h5g6pg6vgjyjzrj159dw3rxwmhvwgla-unpinned-file.txt1488=== NAME TestOrphanedObjectsGC1489 orphaned_objects_gc_test.go:287: GC Test Summary:1490 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1491 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1492 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1493 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1494 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1495--- PASS: TestOrphanedObjectsGC (5.21s)1496=== CONT TestReadProxy40414972026/11/06 08:16:13 INFO Received uploads request method=POST path=/api/pending_closures1498=== NAME TestClientMultipleUploads1499 client_integration_test.go:405: Created store path 0: /build/TestClientMultipleUploads3208319928/001/store/gdwsvaq32bcwvjbizlbblzyzi1y311qg-test-file-0.txt15002026/11/06 08:16:13 INFO Received uploads request method=POST path=/api/pending_closures1501--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.59s)1502=== CONT TestService_readinessHandler15032026/11/06 08:16:13 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15042026/11/06 08:16:13 INFO Uploading k43xp50my77ddrq79znaixxmza13rcd7-b (216B)15052026/11/06 08:16:13 INFO Uploading rqqmkmw6gbk4cfghfqkwdmz49xk22bi6-shared-dep (136B)15062026/11/06 08:16:13 WARN Failed to register uploaded object key=k43xp50my77ddrq79znaixxmza13rcd7.ls error="server returned 404: 404 page not found\n"15072026/11/06 08:16:13 WARN Failed to register uploaded object key=bjhq2r7y5p20isyi68vy6m8wx254znl4.ls error="server returned 404: 404 page not found\n"15082026/11/06 08:16:13 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15092026/11/06 08:16:13 WARN Failed to register uploaded object key=nar/06dmh2x825jv0aalsf5hljfnkxnx7lk924p4699c47vaywjx00f1.nar.zst error="server returned 404: 404 page not found\n"15102026/11/06 08:16:13 WARN Failed to register uploaded object key=rqqmkmw6gbk4cfghfqkwdmz49xk22bi6.ls error="server returned 404: 404 page not found\n"15112026/11/06 08:16:13 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15122026/11/06 08:16:13 INFO Signed narinfos id=2 count=215132026/11/06 08:16:13 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15142026/11/06 08:16:13 INFO Signed narinfos id=1 count=215152026/11/06 08:16:13 INFO Uploading 4 narinfos1516=== NAME TestClientIntegration1517 client_integration_test.go:291: Created store path: /build/TestClientIntegration563876682/002/store/hdrna80l1lm6br96iqy4nr6ax6rqdsz0-test-file.txt15182026/11/06 08:16:13 WARN Failed to register uploaded object key=k43xp50my77ddrq79znaixxmza13rcd7.narinfo error="server returned 404: 404 page not found\n"15192026/11/06 08:16:13 WARN Failed to register uploaded object key=rqqmkmw6gbk4cfghfqkwdmz49xk22bi6.narinfo error="server returned 404: 404 page not found\n"1520--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.78s)1521=== CONT TestGCEndsOnShutdown/before_the_run15222026/11/06 08:16:13 WARN Failed to register uploaded object key=bjhq2r7y5p20isyi68vy6m8wx254znl4.narinfo error="server returned 404: 404 page not found\n"15232026/11/06 08:16:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15242026/11/06 08:16:13 WARN Failed to register uploaded object key=rqqmkmw6gbk4cfghfqkwdmz49xk22bi6.narinfo error="server returned 404: 404 page not found\n"1525=== NAME TestClientMultipleUploads1526 client_integration_test.go:405: Created store path 1: /build/TestClientMultipleUploads3208319928/001/store/q8w07af21hma0dhzz78sk0nfj7ghxg7f-test-file-1.txt15272026/11/06 08:16:13 INFO Completed upload id=1 objects=6 duration=10.59492ms15282026/11/06 08:16:13 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15292026/11/06 08:16:13 INFO Completed upload id=2 objects=6 duration=3.529793ms15302026/11/06 08:16:13 INFO Upload complete. (114ms)1531=== NAME TestClientFallsBackToClosures1532 client_pushes_test.go:112: Retrieved narinfo from S3:1533 StorePath: /build/TestClientFallsBackToClosures3231717869/001/store/rqqmkmw6gbk4cfghfqkwdmz49xk22bi6-shared-dep1534 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1535 Compression: zstd1536 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821537 NarSize: 1361538 References: 1539 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1540 client_pushes_test.go:112: Retrieved narinfo from S3:1541 StorePath: /build/TestClientFallsBackToClosures3231717869/001/store/bjhq2r7y5p20isyi68vy6m8wx254znl4-a1542 URL: nar/06dmh2x825jv0aalsf5hljfnkxnx7lk924p4699c47vaywjx00f1.nar.zst1543 Compression: zstd1544 NarHash: sha256:06dmh2x825jv0aalsf5hljfnkxnx7lk924p4699c47vaywjx00f11545 NarSize: 2161546 References: /build/TestClientFallsBackToClosures3231717869/001/store/rqqmkmw6gbk4cfghfqkwdmz49xk22bi6-shared-dep1547 CA: text:sha256:1fapxqmiih68b41nbf2gih2qkbisz9hhb5cl584z1ywhfdv54lm71548 client_pushes_test.go:112: Retrieved narinfo from S3:1549 StorePath: /build/TestClientFallsBackToClosures3231717869/001/store/k43xp50my77ddrq79znaixxmza13rcd7-b1550 URL: nar/06dmh2x825jv0aalsf5hljfnkxnx7lk924p4699c47vaywjx00f1.nar.zst1551 Compression: zstd1552 NarHash: sha256:06dmh2x825jv0aalsf5hljfnkxnx7lk924p4699c47vaywjx00f11553 NarSize: 2161554 References: /build/TestClientFallsBackToClosures3231717869/001/store/rqqmkmw6gbk4cfghfqkwdmz49xk22bi6-shared-dep1555 CA: text:sha256:1fapxqmiih68b41nbf2gih2qkbisz9hhb5cl584z1ywhfdv54lm71556--- PASS: TestClientFallsBackToClosures (3.69s)1557=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1558--- PASS: TestReadProxyConditionalGet (0.77s)1559=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1560=== NAME TestClientMultipleUploads1561 client_integration_test.go:405: Created store path 2: /build/TestClientMultipleUploads3208319928/001/store/vvjzjpy1vlilypz2d6lkfv0f6dix5lgr-test-file-2.txt1562--- PASS: TestReadRedirectNar (0.95s)1563=== CONT TestIsValidCachePath/narinfo1564=== CONT TestProxyWriteTimeout/narinfo1565=== CONT TestIsValidCachePath/realisation1566=== CONT TestIsValidCachePath/short_hash1567=== CONT TestIsValidCachePath/wrong_extension1568=== CONT TestIsValidCachePath/leading_slash1569=== CONT TestIsValidCachePath/empty1570=== CONT TestIsValidCachePath/random_path1571=== CONT TestIsValidCachePath/invalid_char_u1572=== CONT TestIsValidCachePath/invalid_char_e1573=== CONT TestIsValidCachePath/traversal_in_middle1574=== CONT TestIsValidCachePath/traversal_parent1575=== CONT TestIsValidCachePath/index.html1576=== CONT TestIsValidCachePath/nix-cache-info1577=== CONT TestIsValidCachePath/nar_zst1578=== CONT TestIsValidCachePath/nar_bz21579=== CONT TestIsValidCachePath/nar_xz1580=== CONT TestIsValidCachePath/nar_uncompressed1581=== CONT TestIsValidCachePath/log1582=== CONT TestIsValidCachePath/ls1583=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1584=== CONT TestProxyWriteTimeout/10_GiB_nar1585=== CONT TestProxyWriteTimeout/unknown_size1586=== CONT TestProxyWriteTimeout/1_GiB_nar1587=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1588--- PASS: TestIsValidCachePath (0.00s)1589 --- PASS: TestIsValidCachePath/narinfo (0.00s)1590 --- PASS: TestIsValidCachePath/realisation (0.00s)1591 --- PASS: TestIsValidCachePath/short_hash (0.00s)1592 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1593 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1594 --- PASS: TestIsValidCachePath/empty (0.00s)1595 --- PASS: TestIsValidCachePath/random_path (0.00s)1596 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1597 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1598 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1599 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1600 --- PASS: TestIsValidCachePath/index.html (0.00s)1601 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1602 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1603 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1604 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1605 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1606 --- PASS: TestIsValidCachePath/log (0.00s)1607 --- PASS: TestIsValidCachePath/ls (0.00s)1608 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1609--- PASS: TestProxyWriteTimeout (1.92s)1610 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1611 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1612 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1613 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)16142026/11/06 08:16:15 INFO Aborted multipart uploads count=1 kept=016152026/11/06 08:16:15 INFO Received cleanup request method=DELETE path=/api/pending_closures16162026/11/06 08:16:15 INFO Aborted multipart uploads count=1 kept=01617--- PASS: TestPendingCleanupUsesOneCutoff (6.56s)1618=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1619--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (5.66s)1620=== CONT TestPendingClosureWriteTimeout/empty1621=== CONT TestPendingClosureWriteTimeout/670k_objects1622=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline16232026/11/06 08:16:15 INFO Received push request method=POST path=/api/pushes16242026/11/06 08:16:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16252026/11/06 08:16:15 INFO Uploading 47101hbrxq7kjcjs2bnpv87ammg0ss8c-pinned-file.txt (128B)16262026/11/06 08:16:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16272026/11/06 08:16:15 WARN Failed to register uploaded object key=47101hbrxq7kjcjs2bnpv87ammg0ss8c.ls error="server returned 404: 404 page not found\n"16282026/11/06 08:16:15 INFO Signed narinfos id=1 count=116292026/11/06 08:16:15 INFO Uploading 1 narinfos16302026/11/06 08:16:15 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"1631--- PASS: TestReadProxyHead (2.46s)1632=== CONT TestPendingClosureWriteTimeout/400_objects1633=== CONT TestParseSingleRange/none1634=== CONT TestParseSingleRange/open-ended1635=== CONT TestParseSingleRange/start_far_past_EOF1636=== CONT TestParseSingleRange/start_past_EOF1637=== CONT TestParseSingleRange/single_byte1638=== CONT TestParseSingleRange/suffix_exceeds_size1639=== CONT TestParseSingleRange/suffix1640=== CONT TestParseSingleRange/end_clamped_to_size1641=== CONT TestParseSingleRange/multi-range_ignored1642=== CONT TestParseSingleRange/closed1643=== CONT TestParseSingleRange/malformed_end_before_start1644=== CONT TestParseSingleRange/malformed_both_empty1645=== CONT TestParseSingleRange/malformed_no_dash1646=== CONT TestParseSingleRange/unknown_unit1647--- PASS: TestParseSingleRange (0.00s)1648 --- PASS: TestParseSingleRange/none (0.00s)1649 --- PASS: TestParseSingleRange/open-ended (0.00s)1650 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1651 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1652 --- PASS: TestParseSingleRange/single_byte (0.00s)1653 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1654 --- PASS: TestParseSingleRange/suffix (0.00s)1655 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1656 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1657 --- PASS: TestParseSingleRange/closed (0.00s)1658 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1659 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1660 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1661 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1662=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows16632026/11/06 08:16:15 INFO Received complete push request method=POST path=/api/pushes/1/complete16642026/11/06 08:16:15 WARN Failed to register uploaded object key=47101hbrxq7kjcjs2bnpv87ammg0ss8c.narinfo error="server returned 404: 404 page not found\n"16652026/11/06 08:16:15 INFO Completed push id=1 objects=3 duration=14.825799ms16662026/11/06 08:16:15 INFO Upload complete. (164ms)16672026/11/06 08:16:15 INFO Received push request method=POST path=/api/pushes16682026/11/06 08:16:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16692026/11/06 08:16:15 INFO Uploading hdrna80l1lm6br96iqy4nr6ax6rqdsz0-test-file.txt (152B)1670=== NAME TestOrphanedObjectsGCStressTest1671 orphaned_objects_gc_test.go:503: Stress test completed successfully:1672 orphaned_objects_gc_test.go:504: - Active objects preserved: 201673 orphaned_objects_gc_test.go:505: - Objects deleted: 2101674 orphaned_objects_gc_test.go:506: - Total GC'd: 2101675--- PASS: TestOrphanedObjectsGCStressTest (7.46s)1676=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check16772026/11/06 08:16:15 WARN Failed to register uploaded object key=hdrna80l1lm6br96iqy4nr6ax6rqdsz0.ls error="server returned 404: 404 page not found\n"16782026/11/06 08:16:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16792026/11/06 08:16:15 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"16802026/11/06 08:16:15 INFO Signed narinfos id=1 count=116812026/11/06 08:16:15 INFO Uploading 1 narinfos16822026/11/06 08:16:15 INFO Received complete push request method=POST path=/api/pushes/1/complete16832026/11/06 08:16:15 WARN Failed to register uploaded object key=hdrna80l1lm6br96iqy4nr6ax6rqdsz0.narinfo error="server returned 404: 404 page not found\n"16842026/11/06 08:16:15 INFO Completed push id=1 objects=3 duration=9.960874ms16852026/11/06 08:16:15 INFO Upload complete. (1.984s)1686--- PASS: TestMetricsInventory (2.51s)1687=== CONT TestPush_RejectsBadRequests/no_objects16882026/11/06 08:16:15 INFO Received push request method=POST path=/api/pushes1689=== CONT TestPush_RejectsBadRequests/root_not_in_objects16902026/11/06 08:16:15 INFO Received push request method=POST path=/api/pushes1691=== CONT TestPush_RejectsBadRequests/no_roots16922026/11/06 08:16:15 INFO Received push request method=POST path=/api/pushes1693=== CONT TestPush_RejectsBadRequests/bad_root16942026/11/06 08:16:15 INFO Received push request method=POST path=/api/pushes1695=== CONT TestServerTLSConfig/no_client_CA1696--- PASS: TestPush_RejectsBadRequests (6.55s)1697 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1698 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1699 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1700 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1701=== CONT TestServerTLSConfig/not_a_PEM_file1702=== CONT TestServerTLSConfig/missing_CA_file1703--- PASS: TestServerTLSConfig (0.00s)1704 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1705 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1706 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1707=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1708--- PASS: TestConnectWaitsForAPeerMigration (5.89s)1709=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1710--- PASS: TestReadProxyNarStreaming (2.40s)1711=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1712=== NAME TestClientWithDependencies1713 client_integration_test.go:662: Found 1 dependencies (including self)1714=== NAME TestNARDeduplicationMetadataUploadBug1715 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug2896469596/001/store/mk1hd72gscrqwwjqd966llrbf2s0qja2-file1.txt1716--- PASS: TestReadProxyInvalidPath (2.35s)1717=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed17182026/11/06 08:16:15 WARN readiness check failed error="closed pool"1719--- PASS: TestService_readinessHandler (2.27s)1720=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1721--- PASS: TestReadProxy404 (2.34s)1722=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17232026/11/06 08:16:15 INFO Received uploads request method=POST path=/17242026/11/06 08:16:15 INFO Received uploads request method=POST path=/api/pending_closures17252026/11/06 08:16:15 INFO Aborted multipart uploads count=0 kept=01726=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17272026/11/06 08:16:15 INFO Received request for more parts method=POST path=/1728=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17292026/11/06 08:16:15 INFO Received complete multipart upload request method=POST path=/17302026/11/06 08:16:15 INFO Aborted multipart uploads count=0 kept=017312026/11/06 08:16:15 WARN Force mode enabled - objects will be deleted immediately without grace period1732=== CONT TestResolveDBConnectionString/flag_wins1733=== CONT TestResolveDBConnectionString/missing_file_is_an_error1734=== CONT TestResolveDBConnectionString/file_when_flag_empty1735=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1736=== CONT TestResolveDBConnectionString/nothing_configured1737=== CONT TestClientErrorHandling/InvalidStorePath1738--- PASS: TestResolveDBConnectionString (0.00s)1739 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1740 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1741 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1742 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1743 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1744=== CONT TestClientErrorHandling/InvalidAuthToken17452026/11/06 08:16:15 INFO All 1 paths already cached17462026/11/06 08:16:15 WARN Force mode enabled - objects will be deleted immediately without grace period17472026/11/06 08:16:15 INFO Received uploads request method=POST path=/api/pending_closures1748=== NAME TestClientCADerivations1749 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations2514248451/001/store/x02klrzlbw90y9h6m73h7jzqgq3k9a0f-ca-test1750=== NAME TestClientIntegration1751 client_integration_test.go:317: Retrieved narinfo from S3:1752 StorePath: /build/TestClientIntegration563876682/002/store/hdrna80l1lm6br96iqy4nr6ax6rqdsz0-test-file.txt1753 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1754 Compression: zstd1755 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11756 NarSize: 1521757 References: 1758 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11759 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1760 client_integration_test.go:318: Decompressed .ls content (64 bytes):1761 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}17622026/11/06 08:16:15 INFO Aborted multipart uploads count=0 kept=017632026/11/06 08:16:15 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:42181/bucket93/?delete=\": context canceled"1764=== CONT TestClientErrorHandling/ServerNotAvailable1765--- PASS: TestGCEndsOnShutdown (0.00s)1766 --- PASS: TestGCEndsOnShutdown/before_the_run (2.37s)1767 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (2.44s)1768 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (2.46s)17692026/11/06 08:16:15 INFO Received uploads request method=POST path=/api/pending_closures17702026/11/06 08:16:16 INFO Received uploads request method=POST path=/api/pending_closures17712026/11/06 08:16:16 INFO Received uploads request method=POST path=/api/pending_closures1772=== CONT TestCacheConfigHandler/full_config,_no_issuer1773=== CONT TestCacheConfigHandler/no_signing_keys1774=== CONT TestCacheConfigHandler/no_cache_url_configured1775=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1776--- PASS: TestCacheConfigHandler (0.00s)1777 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1778 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1779 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1780 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1781=== CONT TestService_RequireScope_OIDC/builder_may_write1782=== CONT TestService_RequireScope_OIDC/reader_may_read1783=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1784=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read17852026/11/06 08:16:16 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]1786=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1787=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1788=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1789=== CONT TestService_RequireScope_OIDC/writer_implies_read1790=== CONT TestService_RequireScope_OIDC/reader_may_not_write1791=== CONT TestService_RequireScope_OIDC/static_token_may_write1792=== CONT TestService_RequireScope_OIDC/static_token_may_admin1793=== CONT TestService_RequireScope_OIDC/ops_may_not_write1794=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1795=== CONT TestService_RequireScope_OIDC/ops_may_admin1796=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1797--- PASS: TestService_RequireScope_OIDC (2.54s)1798 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.01s)1799 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1800 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1801 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1802 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1803 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1804 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1805 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1806 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1807 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1808 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1809 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1810 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1811 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1812=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1813=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected18142026/11/06 08:16:16 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]1815=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected18162026/11/06 08:16:16 WARN Authentication failed token_preview=eyJhbGciOi...mS1bv1FweQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1817=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info18182026/11/06 08:16:16 INFO Received uploads request method=POST path=/1819=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key18202026/11/06 08:16:16 INFO Received complete multipart upload request method=POST path=/1821=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key18222026/11/06 08:16:16 INFO Received request for more parts method=POST path=/1823=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal18242026/11/06 08:16:16 INFO Received uploads request method=POST path=/1825--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1826 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1827 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1828 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1829 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1830=== CONT TestIsValidUploadKey/narinfo1831=== CONT TestIsValidUploadKey/absolute1832=== CONT TestIsValidUploadKey/traversal_nar1833=== CONT TestIsValidUploadKey/traversal1834=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1835=== CONT TestIsValidUploadKey/empty_key1836=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1837=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1838=== CONT TestIsValidUploadKey/index.html1839=== CONT TestIsValidUploadKey/nix-cache-info1840=== CONT TestIsValidUploadKey/realisation_plus_in_output1841=== CONT TestIsValidUploadKey/realisation1842=== CONT TestIsValidUploadKey/build_log_equals1843=== CONT TestIsValidUploadKey/build_log_question_mark1844=== CONT TestIsValidUploadKey/build_log_plus_in_name1845=== CONT TestIsValidUploadKey/build_log_home-manager_file1846=== CONT TestIsValidUploadKey/build_log1847=== CONT TestIsValidUploadKey/listing1848=== CONT TestIsValidUploadKey/nar_plain1849=== CONT TestIsValidUploadKey/nar_zst1850=== CONT TestIsValidUploadKey/unknown_type1851=== CONT TestIsValidUploadKey/nar_xz1852--- PASS: TestIsValidUploadKey (0.00s)1853 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1854 --- PASS: TestIsValidUploadKey/absolute (0.00s)1855 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1856 --- PASS: TestIsValidUploadKey/traversal (0.00s)1857 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1858 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1859 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1860 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1861 --- PASS: TestIsValidUploadKey/index.html (0.00s)1862 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1863 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1864 --- PASS: TestIsValidUploadKey/realisation (0.00s)1865 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1866 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1867 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1868 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1869 --- PASS: TestIsValidUploadKey/build_log (0.00s)1870 --- PASS: TestIsValidUploadKey/listing (0.00s)1871 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1872 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1873 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1874 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1875--- PASS: TestService_AuthMiddleware_OIDC (2.21s)1876 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)1877 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1878 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1879 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1880--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)1881 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.94s)1882 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (2.79s)18832026/11/06 08:16:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18842026/11/06 08:16:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18852026/11/06 08:16:16 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=MmNiYmIxMzAtYjA0OS00ZjM3LWFmNDItNGEzZDJhOGY0M2I0LjViMDhmYjQyLWQxNTQtNDNlYy1hMmRlLTJjMTBhNDg3NDdhMHgxNzkzOTUyOTc2MDMwNTgwMzYy parts=1018862026/11/06 08:16:16 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=MmNiYmIxMzAtYjA0OS00ZjM3LWFmNDItNGEzZDJhOGY0M2I0LjgyNTA5ZWJjLWViYjItNGUzMy1hMTg4LWIzZmQ0ZTQ4MzRiY3gxNzkzOTUyOTc1OTg5NzQxODU4 parts=1018872026/11/06 08:16:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18882026/11/06 08:16:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18892026/11/06 08:16:16 INFO Completed upload id=1 objects=3 duration=3.397451ms18902026/11/06 08:16:16 INFO Received uploads request method=POST path=/api/pending_closures18912026/11/06 08:16:16 INFO Completed upload id=1 objects=3 duration=3.321351ms18922026/11/06 08:16:16 INFO Received uploads request method=POST path=/api/pending_closures18932026/11/06 08:16:16 WARN Force mode enabled - objects will be deleted immediately without grace period18942026/11/06 08:16:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18952026/11/06 08:16:16 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=MmNiYmIxMzAtYjA0OS00ZjM3LWFmNDItNGEzZDJhOGY0M2I0LmVjMzA2YjRmLTRlOGMtNDY4ZS05ZjQ3LTU3Y2FhYzhiMmYxYXgxNzkzOTUyOTc2MDc5NTEyODAy parts=101896=== NAME TestClientCADerivations1897 client_ca_test.go:139: Found 1 dependencies (including self)18982026/11/06 08:16:16 INFO Received push request method=POST path=/api/pushes18992026/11/06 08:16:16 INFO Received push request method=POST path=/api/pushes19002026/11/06 08:16:16 INFO Received push request method=POST path=/api/pushes19012026/11/06 08:16:16 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/present19022026/11/06 08:16:16 INFO Received push request method=POST path=/api/pushes1903--- PASS: TestPendingClosureWriteTimeout (1.93s)1904 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)1905 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)1906 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)1907 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.26s)19082026/11/06 08:16:16 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19092026/11/06 08:16:16 INFO Uploading 8h5g6pg6vgjyjzrj159dw3rxwmhvwgla-unpinned-file.txt (128B)19102026/11/06 08:16:16 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=019112026/11/06 08:16:16 INFO Vacuumed table table=pending_closures19122026/11/06 08:16:16 INFO Vacuumed table table=pending_objects19132026/11/06 08:16:16 INFO Vacuumed table table=multipart_uploads19142026/11/06 08:16:16 INFO Vacuumed table table=closures19152026/11/06 08:16:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19162026/11/06 08:16:16 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)19172026/11/06 08:16:16 INFO Uploading ahc09ig5ls2ykqmjj9pla8sxqka7x727-a (208B)19182026/11/06 08:16:16 INFO Uploading 2fjpiaixk4yryq0w1prd1j038xks4jl3-shared-dep (136B)19192026/11/06 08:16:16 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19202026/11/06 08:16:16 INFO Uploading lim80ikw5xr8p0v2cyq6218vj24367nz-test-script (136B)19212026/11/06 08:16:16 INFO Object in database but missing from S3 key=hdrna80l1lm6br96iqy4nr6ax6rqdsz0.ls19222026/11/06 08:16:16 WARN Found objects in DB but missing from S3, will re-upload count=119232026/11/06 08:16:16 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19242026/11/06 08:16:16 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"19252026/11/06 08:16:16 INFO Completed upload id=1 objects=3 duration=6.003697ms19262026/11/06 08:16:16 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign19272026/11/06 08:16:16 INFO Signed narinfos id=2 count=119282026/11/06 08:16:16 WARN Failed to register uploaded object key=8h5g6pg6vgjyjzrj159dw3rxwmhvwgla.ls error="server returned 404: 404 page not found\n"19292026/11/06 08:16:16 INFO Vacuumed table table=objects19302026/11/06 08:16:16 INFO Uploading 1 narinfos19312026/11/06 08:16:16 WARN Failed to register uploaded object key=9iy3n98yv5f052gcsg67g4b3sqflp30w.ls error="server returned 404: 404 page not found\n"19322026/11/06 08:16:16 WARN Failed to register uploaded object key=lim80ikw5xr8p0v2cyq6218vj24367nz.ls error="server returned 404: 404 page not found\n"19332026/11/06 08:16:16 INFO Received complete push request method=POST path=/api/pushes/2/complete19342026/11/06 08:16:16 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"19352026/11/06 08:16:16 WARN Failed to register uploaded object key=nar/040z830axx4q28fvc7lwwz8w3jq112147dn1apqg5dn0xip9rw4m.nar.zst error="server returned 404: 404 page not found\n"19362026/11/06 08:16:16 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"19372026/11/06 08:16:16 WARN Failed to register uploaded object key=ahc09ig5ls2ykqmjj9pla8sxqka7x727.ls error="server returned 404: 404 page not found\n"19382026/11/06 08:16:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19392026/11/06 08:16:16 WARN Failed to register uploaded object key=2fjpiaixk4yryq0w1prd1j038xks4jl3.ls error="server returned 404: 404 page not found\n"19402026/11/06 08:16:16 INFO Signed narinfos id=1 count=319412026/11/06 08:16:16 WARN Failed to register uploaded object key=hdrna80l1lm6br96iqy4nr6ax6rqdsz0.ls error="server returned 404: 404 page not found\n"19422026/11/06 08:16:16 INFO Uploading 3 narinfos19432026/11/06 08:16:16 WARN Failed to register uploaded object key=log/py9lc5qa6jmzi4y1dwyzf4jgc14p3vs0-test-script.drv error="server returned 404: 404 page not found\n"19442026/11/06 08:16:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19452026/11/06 08:16:16 INFO Signed narinfos id=1 count=119462026/11/06 08:16:16 INFO Uploading 1 narinfos19472026/11/06 08:16:16 INFO Completed push id=2 objects=3 duration=3.081029ms19482026/11/06 08:16:16 INFO Upload complete. (120ms)19492026/11/06 08:16:16 INFO Received complete push request method=POST path=/api/pushes/2/complete19502026/11/06 08:16:16 WARN Failed to register uploaded object key=8h5g6pg6vgjyjzrj159dw3rxwmhvwgla.narinfo error="server returned 404: 404 page not found\n"1951=== NAME TestClientIntegration1952 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1953 client_integration_test.go:335: Decompressed .ls content (49 bytes):1954 {"version":1,"root":{"type":"regular","size":39}}19552026/11/06 08:16:16 WARN Failed to register uploaded object key=2fjpiaixk4yryq0w1prd1j038xks4jl3.narinfo error="server returned 404: 404 page not found\n"19562026/11/06 08:16:16 WARN Failed to register uploaded object key=ahc09ig5ls2ykqmjj9pla8sxqka7x727.narinfo error="server returned 404: 404 page not found\n"19572026/11/06 08:16:16 WARN Failed to register uploaded object key=9iy3n98yv5f052gcsg67g4b3sqflp30w.narinfo error="server returned 404: 404 page not found\n"19582026/11/06 08:16:16 INFO Received complete push request method=POST path=/api/pushes/1/complete19592026/11/06 08:16:16 INFO Received push request method=POST path=/api/pushes19602026/11/06 08:16:16 INFO Completed push id=2 objects=3 duration=5.095868ms19612026/11/06 08:16:16 INFO Upload complete. (678ms)19622026/11/06 08:16:16 INFO Received complete push request method=POST path=/api/pushes/1/complete19632026/11/06 08:16:16 WARN Failed to register uploaded object key=lim80ikw5xr8p0v2cyq6218vj24367nz.narinfo error="server returned 404: 404 page not found\n"19642026/11/06 08:16:16 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)19652026/11/06 08:16:16 INFO Uploading vvjzjpy1vlilypz2d6lkfv0f6dix5lgr-test-file-2.txt (160B)19662026/11/06 08:16:16 INFO Uploading gdwsvaq32bcwvjbizlbblzyzi1y311qg-test-file-0.txt (160B)19672026/11/06 08:16:16 INFO Uploading q8w07af21hma0dhzz78sk0nfj7ghxg7f-test-file-1.txt (160B)19682026/11/06 08:16:16 INFO Completed push id=1 objects=8 duration=10.184975ms19692026/11/06 08:16:16 INFO Upload complete. (687ms)1970=== NAME TestClientPushesUseOnePush1971 client_pushes_test.go:97: Retrieved narinfo from S3:1972 StorePath: /build/TestClientPushesUseOnePush116870496/001/store/2fjpiaixk4yryq0w1prd1j038xks4jl3-shared-dep1973 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1974 Compression: zstd1975 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821976 NarSize: 1361977 References: 1978 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n19792026/11/06 08:16:16 INFO Completed push id=1 objects=4 duration=11.286886ms19802026/11/06 08:16:16 WARN Failed to register uploaded object key=vvjzjpy1vlilypz2d6lkfv0f6dix5lgr.ls error="server returned 404: 404 page not found\n"19812026/11/06 08:16:16 INFO Upload complete. (691ms)19822026/11/06 08:16:16 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"19832026/11/06 08:16:16 WARN Failed to register uploaded object key=q8w07af21hma0dhzz78sk0nfj7ghxg7f.ls error="server returned 404: 404 page not found\n"19842026/11/06 08:16:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19852026/11/06 08:16:16 WARN Failed to register uploaded object key=gdwsvaq32bcwvjbizlbblzyzi1y311qg.ls error="server returned 404: 404 page not found\n"19862026/11/06 08:16:16 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"19872026/11/06 08:16:16 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"19882026/11/06 08:16:16 INFO Signed narinfos id=1 count=319892026/11/06 08:16:16 INFO Uploading 3 narinfos1990 client_pushes_test.go:97: Retrieved narinfo from S3:1991 StorePath: /build/TestClientPushesUseOnePush116870496/001/store/ahc09ig5ls2ykqmjj9pla8sxqka7x727-a1992 URL: nar/040z830axx4q28fvc7lwwz8w3jq112147dn1apqg5dn0xip9rw4m.nar.zst1993 Compression: zstd1994 NarHash: sha256:040z830axx4q28fvc7lwwz8w3jq112147dn1apqg5dn0xip9rw4m1995 NarSize: 2081996 References: /build/TestClientPushesUseOnePush116870496/001/store/2fjpiaixk4yryq0w1prd1j038xks4jl3-shared-dep1997 CA: text:sha256:09k4alclsf526ak9pahrnk49sfjzw7yyhjz47bv171avcr0vlsq619982026/11/06 08:16:16 WARN Failed to register uploaded object key=vvjzjpy1vlilypz2d6lkfv0f6dix5lgr.narinfo error="server returned 404: 404 page not found\n"19992026/11/06 08:16:16 WARN Failed to register uploaded object key=q8w07af21hma0dhzz78sk0nfj7ghxg7f.narinfo error="server returned 404: 404 page not found\n"2000=== NAME TestClientWithDependencies2001 client_integration_test.go:664: Skipping nix copy test - isolated store (/build/TestClientWithDependencies1854408754/001/store) requires matching store prefix20022026/11/06 08:16:16 INFO Received complete push request method=POST path=/api/pushes/1/complete20032026/11/06 08:16:16 WARN Failed to register uploaded object key=gdwsvaq32bcwvjbizlbblzyzi1y311qg.narinfo error="server returned 404: 404 page not found\n"2004=== NAME TestClientPushesUseOnePush2005 client_pushes_test.go:97: Retrieved narinfo from S3:2006 StorePath: /build/TestClientPushesUseOnePush116870496/001/store/9iy3n98yv5f052gcsg67g4b3sqflp30w-b2007 URL: nar/040z830axx4q28fvc7lwwz8w3jq112147dn1apqg5dn0xip9rw4m.nar.zst2008 Compression: zstd2009 NarHash: sha256:040z830axx4q28fvc7lwwz8w3jq112147dn1apqg5dn0xip9rw4m2010 NarSize: 2082011 References: /build/TestClientPushesUseOnePush116870496/001/store/2fjpiaixk4yryq0w1prd1j038xks4jl3-shared-dep2012 CA: text:sha256:09k4alclsf526ak9pahrnk49sfjzw7yyhjz47bv171avcr0vlsq620132026/11/06 08:16:16 INFO Completed push id=1 objects=9 duration=10.588479ms20142026/11/06 08:16:16 INFO Upload complete. (1.208s)2015=== NAME TestClientMultipleUploads2016 client_integration_test.go:416: Uploaded 3 paths in 3.142709266s20172026/11/06 08:16:16 INFO Received uploads request method=POST path=/api/pending_closures20182026/11/06 08:16:16 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst20192026/11/06 08:16:16 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo20202026/11/06 08:16:16 INFO Received uploads request method=POST path=/api/pending_closures2021--- PASS: TestClientMultipleUploads (4.01s)20222026/11/06 08:16:16 WARN Request failed, retrying attempt=2 backoff=198.905885ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2023--- PASS: TestClientPushesUseOnePush (6.84s)2024--- PASS: TestClientWithDependencies (4.50s)2025--- PASS: TestUploadHandlersRejectOversizedBody (0.20s)2026 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.05s)2027 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.08s)2028 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (1.09s)20292026/11/06 08:16:16 INFO Received uploads request method=POST path=/api/pending_closures20302026/11/06 08:16:16 WARN Request failed, retrying attempt=3 backoff=427.568014ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20312026/11/06 08:16:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20322026/11/06 08:16:17 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=MmNiYmIxMzAtYjA0OS00ZjM3LWFmNDItNGEzZDJhOGY0M2I0LjRhNzliZjU1LWUwZWYtNDgwMC05YjE4LWNmZDY1ODBhNzc4OXgxNzkzOTUyOTc2NDY2MDYzNzMz parts=1020332026/11/06 08:16:17 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete20342026/11/06 08:16:17 INFO Completed upload id=2 objects=3 duration=3.568533ms20352026/11/06 08:16:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20362026/11/06 08:16:17 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=MmNiYmIxMzAtYjA0OS00ZjM3LWFmNDItNGEzZDJhOGY0M2I0LmY3ZjNjOGFlLWZiYWUtNGU4ZC1hZTdmLTYwMmQwMDljZTgxNXgxNzkzOTUyOTc2NjQ5MzcwMDU1 parts=1020372026/11/06 08:16:17 INFO Received uploads request method=POST path=/api/pending_closures20382026/11/06 08:16:17 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst20392026/11/06 08:16:17 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo20402026/11/06 08:16:17 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20412026/11/06 08:16:17 INFO Completed upload id=1 objects=3 duration=3.973878ms20422026/11/06 08:16:17 INFO Received push request method=POST path=/api/pushes20432026/11/06 08:16:17 INFO Received uploads request method=POST path=/api/pending_closures20442026/11/06 08:16:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20452026/11/06 08:16:17 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)20462026/11/06 08:16:17 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst20472026/11/06 08:16:17 WARN Found objects in DB but missing from S3, will re-upload count=120482026/11/06 08:16:17 INFO Uploading lvsx6m5swsrgpd18gd1yhby01vrigki3-top (224B)20492026/11/06 08:16:17 INFO Uploading iwvqydb0cmzww2n72ics1y29d9nw03cn-shared-dep (136B)20502026/11/06 08:16:17 WARN Failed to register uploaded object key=nar/0rr03ixp7arnxasg7mryhd3nvj95x60gmbb2q13zcg7hgxb874rf.nar.zst error="server returned 404: 404 page not found\n"20512026/11/06 08:16:17 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"20522026/11/06 08:16:17 WARN Failed to register uploaded object key=lvsx6m5swsrgpd18gd1yhby01vrigki3.ls error="server returned 404: 404 page not found\n"20532026/11/06 08:16:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20542026/11/06 08:16:17 WARN Failed to register uploaded object key=iwvqydb0cmzww2n72ics1y29d9nw03cn.ls error="server returned 404: 404 page not found\n"20552026/11/06 08:16:17 INFO Signed narinfos id=1 count=220562026/11/06 08:16:17 INFO Uploading 2 narinfos20572026/11/06 08:16:17 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=MmNiYmIxMzAtYjA0OS00ZjM3LWFmNDItNGEzZDJhOGY0M2I0LjE0NWRkNmI5LWI4M2UtNDAyMi04MDdkLWFkMmNmY2Q0NThiOXgxNzkzOTUyOTc2ODcyNDA4NDEx parts=1020582026/11/06 08:16:17 INFO Received complete push request method=POST path=/api/pushes/1/complete20592026/11/06 08:16:17 WARN Failed to register uploaded object key=iwvqydb0cmzww2n72ics1y29d9nw03cn.narinfo error="server returned 404: 404 page not found\n"20602026/11/06 08:16:17 WARN Failed to register uploaded object key=lvsx6m5swsrgpd18gd1yhby01vrigki3.narinfo error="server returned 404: 404 page not found\n"20612026/11/06 08:16:17 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20622026/11/06 08:16:17 INFO Completed push id=1 objects=6 duration=11.226226ms20632026/11/06 08:16:17 INFO Upload complete. (748ms)20642026/11/06 08:16:17 INFO Completed upload id=1 objects=3 duration=3.379991ms20652026/11/06 08:16:17 INFO Received uploads request method=POST path=/api/pending_closures2066=== NAME TestClientSharedPathCommittedMidPush2067 client_integration_test.go:727: Retrieved narinfo from S3:2068 StorePath: /build/TestClientSharedPathCommittedMidPush2308845464/001/store/iwvqydb0cmzww2n72ics1y29d9nw03cn-shared-dep2069 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2070 Compression: zstd2071 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822072 NarSize: 1362073 References: 2074 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2075 client_integration_test.go:727: Retrieved narinfo from S3:2076 StorePath: /build/TestClientSharedPathCommittedMidPush2308845464/001/store/lvsx6m5swsrgpd18gd1yhby01vrigki3-top2077 URL: nar/0rr03ixp7arnxasg7mryhd3nvj95x60gmbb2q13zcg7hgxb874rf.nar.zst2078 Compression: zstd2079 NarHash: sha256:0rr03ixp7arnxasg7mryhd3nvj95x60gmbb2q13zcg7hgxb874rf2080 NarSize: 2242081 References: /build/TestClientSharedPathCommittedMidPush2308845464/001/store/iwvqydb0cmzww2n72ics1y29d9nw03cn-shared-dep2082 CA: text:sha256:05zf6gm2gnazb8s601byvdzr2rgrv794hgl1jysbgz15z20c7k4520832026/11/06 08:16:17 WARN Request failed, retrying attempt=4 backoff=756.558124ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2084--- PASS: TestClientSharedPathCommittedMidPush (6.51s)20852026/11/06 08:16:17 INFO Received uploads request method=POST path=/api/pending_closures20862026/11/06 08:16:17 INFO Aborted multipart uploads count=0 kept=020872026/11/06 08:16:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20882026/11/06 08:16:17 WARN Force mode enabled - objects will be deleted immediately without grace period20892026/11/06 08:16:17 INFO Received push request method=POST path=/api/pushes20902026/11/06 08:16:17 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=020912026/11/06 08:16:17 INFO Starting cleanup of old closures method=DELETE path=/api/closures20922026/11/06 08:16:17 INFO Garbage collection started20932026/11/06 08:16:17 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20942026/11/06 08:16:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20952026/11/06 08:16:17 INFO Vacuumed table table=pending_closures20962026/11/06 08:16:17 INFO Uploading x02klrzlbw90y9h6m73h7jzqgq3k9a0f-ca-test (144B)20972026/11/06 08:16:17 INFO Vacuumed table table=pending_objects20982026/11/06 08:16:17 INFO Vacuumed table table=multipart_uploads20992026/11/06 08:16:17 INFO Vacuumed table table=closures21002026/11/06 08:16:17 INFO Vacuumed table table=objects21012026/11/06 08:16:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21022026/11/06 08:16:17 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"21032026/11/06 08:16:17 WARN Failed to register uploaded object key=log/qa8i1k1f62753b709v1jmhcmbmfwj9q5-ca-test.drv error="server returned 404: 404 page not found\n"21042026/11/06 08:16:17 INFO Signed narinfos id=1 count=121052026/11/06 08:16:17 INFO Uploading 1 narinfos21062026/11/06 08:16:17 WARN Failed to register uploaded object key=x02klrzlbw90y9h6m73h7jzqgq3k9a0f.ls error="server returned 404: 404 page not found\n"21072026/11/06 08:16:17 INFO Received complete push request method=POST path=/api/pushes/1/complete21082026/11/06 08:16:17 INFO Aborted multipart uploads count=0 kept=021092026/11/06 08:16:17 WARN Failed to register uploaded object key=x02klrzlbw90y9h6m73h7jzqgq3k9a0f.narinfo error="server returned 404: 404 page not found\n"21102026/11/06 08:16:17 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=MmNiYmIxMzAtYjA0OS00ZjM3LWFmNDItNGEzZDJhOGY0M2I0LjFlMGUwN2Y4LTE5MzUtNGY4YS1iNmNjLTNhYWNmMDlhNTVkOHgxNzkzOTUyOTc3Mjg4MTY5MDk2 parts=1021112026/11/06 08:16:17 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete21122026/11/06 08:16:17 INFO Completed upload id=2 objects=3 duration=1.142391ms21132026/11/06 08:16:17 INFO Completed push id=1 objects=4 duration=9.116666ms21142026/11/06 08:16:17 INFO Upload complete. (1.122s)2115--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2116 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (1.21s)2117 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (2.29s)2118=== NAME TestClientCADerivations2119 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations2514248451/001/store/x02klrzlbw90y9h6m73h7jzqgq3k9a0f-ca-test2120 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2121 Compression: zstd2122 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2123 NarSize: 1442124 References: 2125 Deriver: /build/TestClientCADerivations2514248451/001/store/qa8i1k1f62753b709v1jmhcmbmfwj9q5-ca-test.drv2126 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2127 client_ca_test.go:185: Checking for realisation files in S3...2128 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2129 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache21302026/11/06 08:16:17 WARN Force mode enabled - objects will be deleted immediately without grace period21312026/11/06 08:16:17 INFO Received uploads request method=POST path=/api/pending_closures21322026/11/06 08:16:17 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21332026/11/06 08:16:17 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst21342026/11/06 08:16:17 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo2135--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.00s)2136 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (0.91s)2137 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (1.15s)2138 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (1.68s)2139 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (1.58s)2140 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (2.30s)21412026/11/06 08:16:17 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=021422026/11/06 08:16:17 INFO Vacuumed table table=pending_closures21432026/11/06 08:16:17 INFO Vacuumed table table=pending_objects21442026/11/06 08:16:17 INFO Vacuumed table table=multipart_uploads21452026/11/06 08:16:17 INFO Vacuumed table table=closures21462026/11/06 08:16:17 INFO Vacuumed table table=objects21472026/11/06 08:16:17 INFO Received push request method=POST path=/api/pushes21482026/11/06 08:16:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21492026/11/06 08:16:17 INFO Uploading mk1hd72gscrqwwjqd966llrbf2s0qja2-file1.txt (160B)21502026/11/06 08:16:17 WARN Failed to register uploaded object key=mk1hd72gscrqwwjqd966llrbf2s0qja2.ls error="server returned 404: 404 page not found\n"21512026/11/06 08:16:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21522026/11/06 08:16:17 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"21532026/11/06 08:16:17 INFO Signed narinfos id=1 count=121542026/11/06 08:16:17 INFO Uploading 1 narinfos21552026/11/06 08:16:17 INFO Received complete push request method=POST path=/api/pushes/1/complete21562026/11/06 08:16:17 WARN Failed to register uploaded object key=mk1hd72gscrqwwjqd966llrbf2s0qja2.narinfo error="server returned 404: 404 page not found\n"21572026/11/06 08:16:17 INFO Completed push id=1 objects=3 duration=9.199846ms21582026/11/06 08:16:17 INFO Upload complete. (100ms)2159=== NAME TestNARDeduplicationMetadataUploadBug2160 metadata_upload_test.go:54: Retrieved narinfo from S3:2161 StorePath: /build/TestNARDeduplicationMetadataUploadBug2896469596/001/store/mk1hd72gscrqwwjqd966llrbf2s0qja2-file1.txt2162 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2163 Compression: zstd2164 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2165 NarSize: 1602166 References: 2167 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2168 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2169 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2170 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}2171--- PASS: TestDeleteClosuresRacingPins (8.28s)21722026/11/06 08:16:18 WARN Request failed, retrying attempt=5 backoff=1.551461515s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2173--- PASS: TestReadProxyOutlastsServerWriteTimeout (5.47s)21742026/11/06 08:16:19 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=021752026/11/06 08:16:19 INFO Received create pin request method=POST path=/api/pins/myapp21762026/11/06 08:16:19 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2470471681/001/store/47101hbrxq7kjcjs2bnpv87ammg0ss8c-pinned-file.txt narinfo_key=47101hbrxq7kjcjs2bnpv87ammg0ss8c.narinfo21772026/11/06 08:16:19 INFO Starting cleanup of old closures method=DELETE path=/api/closures21782026/11/06 08:16:19 INFO Garbage collection started21792026/11/06 08:16:19 INFO Aborted multipart uploads count=0 kept=021802026/11/06 08:16:20 WARN Force mode enabled - objects will be deleted immediately without grace period21812026/11/06 08:16:20 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=021822026/11/06 08:16:20 INFO Vacuumed table table=pending_closures21832026/11/06 08:16:20 INFO Vacuumed table table=pending_objects21842026/11/06 08:16:20 INFO Vacuumed table table=multipart_uploads21852026/11/06 08:16:20 INFO Vacuumed table table=closures2186=== NAME TestNARDeduplicationMetadataUploadBug2187 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug2896469596/001/store/y59f23ak7llz1g2vc7n7xrw3rcyfc289-file2.txt21882026/11/06 08:16:20 INFO Vacuumed table table=objects21892026/11/06 08:16:20 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-config21902026/11/06 08:16:20 INFO Received push request method=POST path=/api/pushes21912026/11/06 08:16:20 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)21922026/11/06 08:16:20 INFO Received complete push request method=POST path=/api/pushes/3/complete21932026/11/06 08:16:20 WARN Failed to register uploaded object key=hdrna80l1lm6br96iqy4nr6ax6rqdsz0.ls error="server returned 404: 404 page not found\n"21942026/11/06 08:16:20 INFO Completed push id=3 objects=3 duration=2.812086ms21952026/11/06 08:16:20 INFO Upload complete. (2.626s)2196=== NAME TestClientIntegration2197 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)2198 client_integration_test.go:352: Decompressed .ls content (49 bytes):2199 {"version":1,"root":{"type":"regular","size":39}}2200 client_integration_test.go:363: Testing garbage collection...22012026/11/06 08:16:20 WARN Request failed, retrying attempt=2 backoff=194.609247ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22022026/11/06 08:16:20 WARN Request failed, retrying attempt=3 backoff=407.161191ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22032026/11/06 08:16:20 WARN Request failed, retrying attempt=4 backoff=730.930246ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22042026/11/06 08:16:21 INFO Starting cleanup of old closures method=DELETE path=/api/closures22052026/11/06 08:16:21 INFO Garbage collection started22062026/11/06 08:16:21 INFO Aborted multipart uploads count=0 kept=022072026/11/06 08:16:21 WARN Request failed, retrying attempt=5 backoff=1.745538301s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2208=== NAME TestPinProtectsFromGC2209 client_integration_test.go:887: Pin successfully protected closure from garbage collection2210--- PASS: TestPinProtectsFromGC (11.99s)22112026/11/06 08:16:23 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"22122026/11/06 08:16:23 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-config22132026/11/06 08:16:23 INFO Garbage collection progress phase=cleanup_pending_uploads failed_uploads_deleted=0 old_closures_deleted=0 objects_marked=0 objects_deleted=0 objects_failed=022142026/11/06 08:16:23 WARN Request failed, retrying attempt=2 backoff=214.231707ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22152026/11/06 08:16:23 WARN Request failed, retrying attempt=3 backoff=371.943612ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22162026/11/06 08:16:24 WARN Request failed, retrying attempt=4 backoff=809.499824ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22172026/11/06 08:16:24 INFO Received push request method=POST path=/api/pushes22182026/11/06 08:16:24 WARN Force mode enabled - objects will be deleted immediately without grace period22192026/11/06 08:16:24 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)22202026/11/06 08:16:24 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign22212026/11/06 08:16:24 WARN Failed to register uploaded object key=y59f23ak7llz1g2vc7n7xrw3rcyfc289.ls error="server returned 404: 404 page not found\n"22222026/11/06 08:16:24 INFO Signed narinfos id=2 count=122232026/11/06 08:16:24 INFO Uploading 1 narinfos22242026/11/06 08:16:24 INFO Received complete push request method=POST path=/api/pushes/2/complete22252026/11/06 08:16:24 WARN Failed to register uploaded object key=y59f23ak7llz1g2vc7n7xrw3rcyfc289.narinfo error="server returned 404: 404 page not found\n"22262026/11/06 08:16:24 WARN Request failed, retrying attempt=5 backoff=1.718694155s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22272026/11/06 08:16:24 INFO Completed push id=2 objects=3 duration=2.635084ms22282026/11/06 08:16:24 INFO Upload complete. (3.487s)2229=== NAME TestNARDeduplicationMetadataUploadBug2230 metadata_upload_test.go:76: Retrieved narinfo from S3:2231 StorePath: /build/TestNARDeduplicationMetadataUploadBug2896469596/001/store/y59f23ak7llz1g2vc7n7xrw3rcyfc289-file2.txt2232 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2233 Compression: zstd2234 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2235 NarSize: 1602236 References: 2237 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2238 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2239 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2240 {"version":1,"root":{"type":"regular","size":44}}22412026/11/06 08:16:24 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=02242--- PASS: TestNARDeduplicationMetadataUploadBug (12.01s)22432026/11/06 08:16:25 INFO Vacuumed table table=pending_closures22442026/11/06 08:16:25 INFO Vacuumed table table=pending_objects22452026/11/06 08:16:25 INFO Vacuumed table table=multipart_uploads22462026/11/06 08:16:25 INFO Vacuumed table table=closures22472026/11/06 08:16:25 INFO Vacuumed table table=objects22482026/11/06 08:16:25 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02249=== NAME TestClientIntegration2250 client_integration_test.go:370: Objects in database after GC:2251 client_integration_test.go:370: Successfully deleted all objects with GC --force2252--- PASS: TestClientIntegration (12.86s)22532026/11/06 08:16:26 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22542026/11/06 08:16:26 WARN Request failed, retrying attempt=2 backoff=180.432631ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22552026/11/06 08:16:26 WARN Request failed, retrying attempt=3 backoff=361.991469ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22562026/11/06 08:16:27 WARN Request failed, retrying attempt=4 backoff=879.746755ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22572026/11/06 08:16:28 WARN Request failed, retrying attempt=5 backoff=1.530358977s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2258--- PASS: TestClientErrorHandling (0.00s)2259 --- PASS: TestClientErrorHandling/InvalidStorePath (1.86s)2260 --- PASS: TestClientErrorHandling/InvalidAuthToken (1.86s)2261 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.83s)2262=== NAME TestClientCADerivations2263 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2264 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2265 error: binary cache 's3://bucket87?endpoint=http://localhost:42181®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations2514248451/001/store'2266 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12267--- PASS: TestClientCADerivations (23.92s)2268PASS2269{"timestamp":"2026-11-06T08:16:33.560591092Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:48892","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(194)"}2270{"timestamp":"2026-11-06T08:16:33.560589292Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:45484","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(199)"}2271{"timestamp":"2026-11-06T08:16:33.560595052Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:48838","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(200)"}2272{"timestamp":"2026-11-06T08:16:33.560593152Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:48048","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(201)"}2273{"timestamp":"2026-11-06T08:16:33.560596872Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:48776","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(203)"}22742026-11-06 08:16:34.031 UTC [129] LOG: received smart shutdown request22752026-11-06 08:16:34.042 UTC [129] LOG: background worker "logical replication launcher" (PID 141) exited with exit code 122762026-11-06 08:16:34.059 UTC [136] LOG: shutting down22772026-11-06 08:16:34.063 UTC [136] LOG: checkpoint starting: shutdown immediate22782026-11-06 08:16:35.140 UTC [136] LOG: checkpoint complete: wrote 10369 buffers (63.3%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.312 s, sync=0.413 s, total=1.081 s; sync files=35730, longest=0.007 s, average=0.001 s; distance=516901 kB, estimate=516901 kB; lsn=0/2102F118, redo lsn=0/2102F11822792026-11-06 08:16:35.307 UTC [129] LOG: database system is shut down2280Running OIDC tests...2281=== RUN TestAudienceForIssuer2282=== PAUSE TestAudienceForIssuer2283=== RUN TestGlobMatch2284=== PAUSE TestGlobMatch2285=== RUN TestValidateToken_ValidToken2286=== PAUSE TestValidateToken_ValidToken2287=== RUN TestValidateToken_WrongAudience2288=== PAUSE TestValidateToken_WrongAudience2289=== RUN TestValidateToken_Expired2290=== PAUSE TestValidateToken_Expired2291=== RUN TestValidateToken_BoundClaimsMismatch2292=== PAUSE TestValidateToken_BoundClaimsMismatch2293=== RUN TestValidateToken_BoundSubjectMismatch2294=== PAUSE TestValidateToken_BoundSubjectMismatch2295=== RUN TestValidateToken_MultipleProviders2296=== PAUSE TestValidateToken_MultipleProviders2297=== RUN TestValidateToken_NoMatchingProvider2298=== PAUSE TestValidateToken_NoMatchingProvider2299=== RUN TestValidateToken_KubernetesServiceAccount2300=== PAUSE TestValidateToken_KubernetesServiceAccount2301=== RUN TestNewValidator_KubernetesRequiresCA2302=== PAUSE TestNewValidator_KubernetesRequiresCA2303=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2304=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2305=== RUN TestPins_ReservedForMatchingRule2306=== PAUSE TestPins_ReservedForMatchingRule2307=== RUN TestPins_TopLevelShorthand2308=== PAUSE TestPins_TopLevelShorthand2309=== RUN TestPins_ConfigValidation2310=== PAUSE TestPins_ConfigValidation2311=== RUN TestScopes_LegacyProviderDefaultsToWrite2312=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2313=== RUN TestScopes_Rules2314=== PAUSE TestScopes_Rules2315=== RUN TestScopes_ConfigValidation2316=== PAUSE TestScopes_ConfigValidation2317=== CONT TestAudienceForIssuer2318--- PASS: TestAudienceForIssuer (0.00s)2319=== CONT TestScopes_ConfigValidation2320--- PASS: TestScopes_ConfigValidation (0.00s)2321=== CONT TestScopes_Rules2322=== CONT TestScopes_LegacyProviderDefaultsToWrite2323=== CONT TestPins_ConfigValidation2324=== CONT TestPins_TopLevelShorthand2325--- PASS: TestPins_ConfigValidation (0.00s)2326=== CONT TestPins_ReservedForMatchingRule2327=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2328=== CONT TestValidateToken_BoundSubjectMismatch2329=== CONT TestValidateToken_BoundClaimsMismatch2330=== CONT TestNewValidator_KubernetesRequiresCA2331=== CONT TestValidateToken_KubernetesServiceAccount2332=== CONT TestValidateToken_NoMatchingProvider2333=== CONT TestValidateToken_MultipleProviders2334=== CONT TestValidateToken_Expired2335=== CONT TestValidateToken_WrongAudience2336=== CONT TestValidateToken_ValidToken2337=== CONT TestGlobMatch2338=== RUN TestGlobMatch/foo_foo2339=== PAUSE TestGlobMatch/foo_foo2340=== RUN TestGlobMatch/foo_bar2341=== PAUSE TestGlobMatch/foo_bar2342=== RUN TestGlobMatch/*_2343=== PAUSE TestGlobMatch/*_2344=== RUN TestGlobMatch/*_anything2345=== PAUSE TestGlobMatch/*_anything2346=== RUN TestGlobMatch/foo*_foo2347=== PAUSE TestGlobMatch/foo*_foo2348=== RUN TestGlobMatch/foo*_foobar2349=== PAUSE TestGlobMatch/foo*_foobar2350=== RUN TestGlobMatch/foo*_bar2351=== PAUSE TestGlobMatch/foo*_bar2352=== RUN TestGlobMatch/*bar_bar2353=== PAUSE TestGlobMatch/*bar_bar2354=== RUN TestGlobMatch/*bar_foobar2355=== PAUSE TestGlobMatch/*bar_foobar2356=== RUN TestGlobMatch/*bar_foo2357=== PAUSE TestGlobMatch/*bar_foo2358=== RUN TestGlobMatch/foo*bar_foobar2359=== PAUSE TestGlobMatch/foo*bar_foobar2360=== RUN TestGlobMatch/foo*bar_foo123bar2361=== PAUSE TestGlobMatch/foo*bar_foo123bar2362=== RUN TestGlobMatch/foo*bar_foobarbaz2363=== PAUSE TestGlobMatch/foo*bar_foobarbaz2364=== RUN TestGlobMatch/*/*_foo/bar2365=== PAUSE TestGlobMatch/*/*_foo/bar2366=== RUN TestGlobMatch/*/*_foo2367=== PAUSE TestGlobMatch/*/*_foo2368=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2369=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2370=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02371=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02372=== RUN TestGlobMatch/refs/*/main_refs/heads/main2373=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2374=== RUN TestGlobMatch/fo?_foo2375=== PAUSE TestGlobMatch/fo?_foo2376=== RUN TestGlobMatch/fo?_fo2377=== PAUSE TestGlobMatch/fo?_fo2378=== RUN TestGlobMatch/fo?_fooo2379=== PAUSE TestGlobMatch/fo?_fooo2380=== RUN TestGlobMatch/?oo_foo2381=== PAUSE TestGlobMatch/?oo_foo2382=== RUN TestGlobMatch/?oo_boo2383=== PAUSE TestGlobMatch/?oo_boo2384=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2385=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2386=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2387=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2388=== CONT TestGlobMatch/foo_foo2389=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2390=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2391=== CONT TestGlobMatch/?oo_boo2392=== CONT TestGlobMatch/?oo_foo2393=== CONT TestGlobMatch/fo?_fooo2394=== CONT TestGlobMatch/fo?_fo2395=== CONT TestGlobMatch/fo?_foo2396=== CONT TestGlobMatch/refs/*/main_refs/heads/main2397=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02398=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2399=== CONT TestGlobMatch/*/*_foo2400=== CONT TestGlobMatch/*/*_foo/bar2401=== CONT TestGlobMatch/foo*bar_foobarbaz2402=== CONT TestGlobMatch/foo*bar_foo123bar2403=== CONT TestGlobMatch/foo*bar_foobar2404=== CONT TestGlobMatch/*bar_foo2405=== CONT TestGlobMatch/*bar_foobar2406=== CONT TestGlobMatch/*bar_bar2407=== CONT TestGlobMatch/foo*_bar2408=== CONT TestGlobMatch/foo*_foobar2409=== CONT TestGlobMatch/foo*_foo2410=== CONT TestGlobMatch/*_anything2411=== CONT TestGlobMatch/*_2412=== CONT TestGlobMatch/foo_bar2413--- PASS: TestGlobMatch (0.01s)2414 --- PASS: TestGlobMatch/foo_foo (0.00s)2415 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2416 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2417 --- PASS: TestGlobMatch/?oo_boo (0.00s)2418 --- PASS: TestGlobMatch/?oo_foo (0.00s)2419 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2420 --- PASS: TestGlobMatch/fo?_fo (0.00s)2421 --- PASS: TestGlobMatch/fo?_foo (0.00s)2422 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2423 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2424 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2425 --- PASS: TestGlobMatch/*/*_foo (0.00s)2426 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2427 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2428 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2429 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2430 --- PASS: TestGlobMatch/*bar_foo (0.00s)2431 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2432 --- PASS: TestGlobMatch/*bar_bar (0.00s)2433 --- PASS: TestGlobMatch/foo*_bar (0.00s)2434 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2435 --- PASS: TestGlobMatch/foo*_foo (0.00s)2436 --- PASS: TestGlobMatch/*_anything (0.00s)2437 --- PASS: TestGlobMatch/*_ (0.00s)2438 --- PASS: TestGlobMatch/foo_bar (0.00s)24392026/11/06 08:16:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41175/oidc24402026/11/06 08:16:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34957/oidc2441--- PASS: TestPins_ReservedForMatchingRule (1.55s)2442--- PASS: TestScopes_Rules (3.60s)24432026/11/06 08:16:41 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42327/oidc2444--- PASS: TestPins_TopLevelShorthand (3.59s)24452026/11/06 08:16:41 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33341/oidc2446--- PASS: TestValidateToken_BoundSubjectMismatch (3.57s)24472026/11/06 08:16:41 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:32807/oidc2448--- PASS: TestValidateToken_Expired (3.58s)24492026/11/06 08:16:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35709/oidc2450--- PASS: TestValidateToken_ValidToken (2.14s)24512026/11/06 08:16:42 http: TLS handshake error from 127.0.0.1:37322: remote error: tls: bad certificate2452--- PASS: TestNewValidator_KubernetesRequiresCA (2.14s)24532026/11/06 08:16:42 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232454--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (3.67s)24552026/11/06 08:16:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42817/oidc2456--- PASS: TestValidateToken_BoundClaimsMismatch (2.17s)24572026/11/06 08:16:42 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:330512458--- PASS: TestValidateToken_KubernetesServiceAccount (2.19s)24592026/11/06 08:16:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34721/oidc2460--- PASS: TestScopes_LegacyProviderDefaultsToWrite (3.82s)24612026/11/06 08:16:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38677/oidc2462--- PASS: TestValidateToken_WrongAudience (2.36s)24632026/11/06 08:16:42 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:44181/oidc2464--- PASS: TestValidateToken_NoMatchingProvider (2.40s)24652026/11/06 08:16:42 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:35613/oidc24662026/11/06 08:16:42 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:40765/oidc2467--- PASS: TestValidateToken_MultipleProviders (4.04s)2468PASS2469Running hook tests...2470=== RUN TestSendPathsEmpty2471=== PAUSE TestSendPathsEmpty2472=== RUN TestQueueEnqueueAndFetch2473=== PAUSE TestQueueEnqueueAndFetch2474=== RUN TestQueueDeduplication2475=== PAUSE TestQueueDeduplication2476=== RUN TestQueueRemove2477=== PAUSE TestQueueRemove2478=== RUN TestQueueFetchBatchLimit2479=== PAUSE TestQueueFetchBatchLimit2480=== RUN TestQueueRetryMovesToBack2481=== PAUSE TestQueueRetryMovesToBack2482=== RUN TestQueueFetchRemoveLifecycle2483=== PAUSE TestQueueFetchRemoveLifecycle2484=== RUN TestQueueConcurrentWriters2485=== PAUSE TestQueueConcurrentWriters2486=== RUN TestQueueRemoveLargeClosure2487=== PAUSE TestQueueRemoveLargeClosure2488=== RUN TestServerClientIntegration2489--- PASS: TestServerClientIntegration (0.01s)2490=== RUN TestServerQueueError24912026/11/06 08:16:42 ERROR Failed to queue paths error="permission denied" count=12492--- PASS: TestServerQueueError (0.00s)2493=== RUN TestGetListenerSocketActivation2494 server_test.go:218: === RUN TestGetListenerSocketActivation2495 --- PASS: TestGetListenerSocketActivation (0.00s)2496 PASS2497 2498--- PASS: TestGetListenerSocketActivation (0.05s)2499=== RUN TestServerStalledClientDoesNotBlockShutdown2500=== PAUSE TestServerStalledClientDoesNotBlockShutdown2501=== RUN TestServerBacksOffOnAcceptErrors2502=== PAUSE TestServerBacksOffOnAcceptErrors2503=== RUN TestDrainIsolatesPoisonPath2504=== PAUSE TestDrainIsolatesPoisonPath2505=== RUN TestRunNotBlockedByPoisonHead2506=== PAUSE TestRunNotBlockedByPoisonHead2507=== RUN TestDrainGivesUpWhenServerDown2508=== PAUSE TestDrainGivesUpWhenServerDown2509=== RUN TestFailedPathPrunedByLaterClosure2510=== PAUSE TestFailedPathPrunedByLaterClosure2511=== RUN TestWorkerUploadsAndRemoves2512=== PAUSE TestWorkerUploadsAndRemoves2513=== RUN TestWorkerSkipsGCdPaths2514=== PAUSE TestWorkerSkipsGCdPaths2515=== RUN TestWorkerPrunesClosureDeps2516=== PAUSE TestWorkerPrunesClosureDeps2517=== RUN TestDrainTimeout2518=== PAUSE TestDrainTimeout2519=== RUN TestWorkerRemoveFailureIsNotProgress2520=== PAUSE TestWorkerRemoveFailureIsNotProgress2521=== RUN TestWorkerKeepsPathItCannotStat2522=== PAUSE TestWorkerKeepsPathItCannotStat2523=== CONT TestWorkerKeepsPathItCannotStat2524=== CONT TestQueueRetryMovesToBack2525=== CONT TestSendPathsEmpty2526--- PASS: TestSendPathsEmpty (0.00s)2527=== CONT TestWorkerRemoveFailureIsNotProgress2528=== CONT TestDrainTimeout2529=== CONT TestWorkerPrunesClosureDeps2530=== CONT TestWorkerSkipsGCdPaths2531=== CONT TestWorkerUploadsAndRemoves2532=== CONT TestFailedPathPrunedByLaterClosure2533=== CONT TestDrainGivesUpWhenServerDown2534=== CONT TestRunNotBlockedByPoisonHead2535=== CONT TestDrainIsolatesPoisonPath2536=== CONT TestServerBacksOffOnAcceptErrors25372026/11/06 08:16:42 ERROR Accept failed error="too many open files"2538=== CONT TestServerStalledClientDoesNotBlockShutdown2539=== CONT TestQueueFetchBatchLimit2540=== CONT TestQueueRemove2541=== CONT TestQueueDeduplication2542=== CONT TestQueueEnqueueAndFetch2543=== CONT TestQueueConcurrentWriters2544=== CONT TestQueueRemoveLargeClosure2545=== CONT TestQueueFetchRemoveLifecycle25462026/11/06 08:16:42 ERROR Accept failed error="too many open files"25472026/11/06 08:16:42 ERROR Accept failed error="too many open files"2548--- PASS: TestQueueFetchRemoveLifecycle (0.02s)25492026/11/06 08:16:43 ERROR Failed to decode request error="read unix /build/hook2933087980/test.sock->@: i/o timeout"25502026/11/06 08:16:43 ERROR Failed to write response error="write unix /build/hook2933087980/test.sock->@: i/o timeout"25512026/11/06 08:16:43 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress2730819290/002/nonexistent25522026/11/06 08:16:43 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12553--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.54s)25542026/11/06 08:16:43 ERROR Accept failed error="too many open files"25552026/11/06 08:16:43 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress2730819290/002/nonexistent25562026/11/06 08:16:43 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125572026/11/06 08:16:43 INFO Upload queue status pending=225582026/11/06 08:16:43 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths3364317020/002/nonexistent25592026/11/06 08:16:43 INFO Uploading batch count=125602026/11/06 08:16:43 INFO Uploading batch count=225612026/11/06 08:16:43 INFO Upload queue status pending=32562--- PASS: TestQueueFetchBatchLimit (0.55s)25632026/11/06 08:16:43 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress2730819290/002/nonexistent25642026/11/06 08:16:43 INFO Uploading batch count=125652026/11/06 08:16:43 ERROR Upload failed error="upload failed" count=125662026/11/06 08:16:43 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125672026/11/06 08:16:43 ERROR Drain finished with paths left in queue remaining=125682026/11/06 08:16:43 INFO Upload queue status pending=225692026/11/06 08:16:43 INFO Uploading batch count=22570--- PASS: TestWorkerRemoveFailureIsNotProgress (0.56s)25712026/11/06 08:16:43 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2068786101/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat2068786101/002/locked/aaa: permission denied"2572--- PASS: TestQueueRemove (0.56s)25732026/11/06 08:16:43 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2068786101/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat2068786101/002/locked/aaa: permission denied"25742026/11/06 08:16:43 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2068786101/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat2068786101/002/locked/aaa: permission denied"2575--- PASS: TestQueueDeduplication (0.56s)25762026/11/06 08:16:43 ERROR Drain finished with paths left in queue remaining=12577--- PASS: TestWorkerKeepsPathItCannotStat (0.57s)2578--- PASS: TestWorkerSkipsGCdPaths (0.57s)25792026/11/06 08:16:43 ERROR Accept failed error="too many open files"25802026/11/06 08:16:43 ERROR Accept failed error="too many open files"25812026/11/06 08:16:43 ERROR Upload failed error="context deadline exceeded" count=225822026/11/06 08:16:43 ERROR Drain finished with paths left in queue remaining=42583--- PASS: TestDrainTimeout (0.75s)25842026/11/06 08:16:43 ERROR Accept failed error="too many open files"25852026/11/06 08:16:43 ERROR Accept failed error="too many open files"2586--- PASS: TestServerBacksOffOnAcceptErrors (1.15s)25872026/11/06 08:16:43 INFO Uploading batch count=425882026/11/06 08:16:43 ERROR Upload failed error="upload failed" count=425892026/11/06 08:16:43 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath1321899010/002/bbb25902026/11/06 08:16:43 INFO Upload queue status pending=225912026/11/06 08:16:43 INFO Uploading batch count=12592--- PASS: TestQueueEnqueueAndFetch (1.24s)2593--- PASS: TestQueueRetryMovesToBack (1.24s)25942026/11/06 08:16:43 INFO Uploading batch count=125952026/11/06 08:16:43 ERROR Upload failed error="upload failed" count=125962026/11/06 08:16:43 INFO Uploading batch count=125972026/11/06 08:16:43 INFO Uploading batch count=225982026/11/06 08:16:43 ERROR Upload failed error="upload failed" count=225992026/11/06 08:16:43 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4225017020/002/a26002026/11/06 08:16:43 ERROR Upload failed error="upload failed" count=126012026/11/06 08:16:43 INFO Uploading batch count=126022026/11/06 08:16:43 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4225017020/002/b26032026/11/06 08:16:43 INFO Uploading batch count=126042026/11/06 08:16:43 ERROR Upload failed error="upload failed" count=12605--- PASS: TestWorkerUploadsAndRemoves (1.24s)26062026/11/06 08:16:43 INFO Uploading batch count=226072026/11/06 08:16:43 INFO Uploading batch count=126082026/11/06 08:16:43 INFO Uploading batch count=126092026/11/06 08:16:43 ERROR Upload failed error="upload failed" count=126102026/11/06 08:16:43 ERROR Upload failed error="upload failed" count=226112026/11/06 08:16:43 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4225017020/002/c26122026/11/06 08:16:43 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4225017020/002/d26132026/11/06 08:16:43 ERROR Drain finished with paths left in queue remaining=126142026/11/06 08:16:43 INFO Uploading batch count=226152026/11/06 08:16:43 ERROR Upload failed error="upload failed" count=226162026/11/06 08:16:43 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4225017020/002/e26172026/11/06 08:16:43 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4225017020/002/f2618--- PASS: TestFailedPathPrunedByLaterClosure (1.24s)26192026/11/06 08:16:43 ERROR Drain finished with paths left in queue remaining=102620--- PASS: TestDrainIsolatesPoisonPath (1.24s)2621--- PASS: TestDrainGivesUpWhenServerDown (1.25s)2622--- PASS: TestWorkerPrunesClosureDeps (1.26s)2623--- PASS: TestQueueConcurrentWriters (1.33s)26242026/11/06 08:16:44 INFO Uploading batch count=126252026/11/06 08:16:44 INFO Uploading batch count=126262026/11/06 08:16:44 INFO Uploading batch count=126272026/11/06 08:16:44 ERROR Upload failed error="upload failed" count=126282026/11/06 08:16:44 INFO Uploading batch count=126292026/11/06 08:16:44 ERROR Upload failed error="upload failed" count=126302026/11/06 08:16:44 INFO Uploading batch count=126312026/11/06 08:16:44 ERROR Upload failed error="upload failed" count=126322026/11/06 08:16:44 INFO Uploading batch count=126332026/11/06 08:16:44 ERROR Upload failed error="upload failed" count=126342026/11/06 08:16:44 ERROR Drain finished with paths left in queue remaining=12635--- PASS: TestRunNotBlockedByPoisonHead (1.56s)2636--- PASS: TestQueueRemoveLargeClosure (1.72s)2637PASS2638Running signing tests...2639=== RUN TestExternalSigner2640=== PAUSE TestExternalSigner2641=== RUN TestExternalSignerWrongPublicKey2642=== PAUSE TestExternalSignerWrongPublicKey2643=== RUN TestExternalSignerErrors2644=== PAUSE TestExternalSignerErrors2645=== RUN TestExternalSignerRestartsAfterCrash2646=== PAUSE TestExternalSignerRestartsAfterCrash2647=== RUN TestExternalSignerProgramErrorKeepsProcess2648=== PAUSE TestExternalSignerProgramErrorKeepsProcess2649=== RUN TestExternalSignerClose2650=== PAUSE TestExternalSignerClose2651=== RUN TestExternalSignerRejectsInvalidPublicKey2652=== PAUSE TestExternalSignerRejectsInvalidPublicKey2653=== RUN TestExternalSignerCancellation2654=== PAUSE TestExternalSignerCancellation2655=== RUN TestGenerateFingerprint2656=== PAUSE TestGenerateFingerprint2657=== RUN TestParseSigningKey2658=== PAUSE TestParseSigningKey2659=== RUN TestSign2660=== PAUSE TestSign2661=== RUN TestSignBatch2662=== PAUSE TestSignBatch2663=== RUN TestNilKeyPublicKey2664=== PAUSE TestNilKeyPublicKey2665=== RUN TestSignErrors2666=== PAUSE TestSignErrors2667=== CONT TestExternalSigner2668=== CONT TestExternalSignerProgramErrorKeepsProcess2669=== CONT TestExternalSignerClose2670=== CONT TestExternalSignerErrors2671=== CONT TestExternalSignerCancellation2672=== RUN TestExternalSignerErrors/exit_on_request2673=== CONT TestExternalSignerRejectsInvalidPublicKey2674=== RUN TestExternalSignerRejectsInvalidPublicKey/#002675=== CONT TestExternalSignerRestartsAfterCrash2676=== CONT TestSignBatch2677=== CONT TestSignErrors2678=== CONT TestNilKeyPublicKey2679--- PASS: TestNilKeyPublicKey (0.00s)2680=== CONT TestParseSigningKey2681=== RUN TestParseSigningKey/valid_32-byte_key2682=== PAUSE TestParseSigningKey/valid_32-byte_key2683=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2684=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2685=== RUN TestParseSigningKey/no_colon2686=== CONT TestSign2687=== CONT TestExternalSignerWrongPublicKey2688=== CONT TestGenerateFingerprint2689=== RUN TestGenerateFingerprint/basic_with_references2690=== PAUSE TestExternalSignerErrors/exit_on_request2691=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002692=== PAUSE TestParseSigningKey/no_colon2693=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2694=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2695=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2696=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2697=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2698=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2699=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2700=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2701=== CONT TestExternalSignerRejectsInvalidPublicKey/#002702=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2703=== RUN TestParseSigningKey/empty_name2704=== PAUSE TestParseSigningKey/empty_name2705=== RUN TestParseSigningKey/invalid_base642706=== PAUSE TestParseSigningKey/invalid_base642707=== RUN TestParseSigningKey/wrong_length2708=== PAUSE TestParseSigningKey/wrong_length2709=== CONT TestParseSigningKey/valid_32-byte_key2710=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2711=== RUN TestExternalSignerErrors/wrong_signatures_shape2712=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2713=== RUN TestExternalSignerErrors/unrequested_key2714=== CONT TestParseSigningKey/empty_name2715=== CONT TestParseSigningKey/wrong_length2716=== PAUSE TestExternalSignerErrors/unrequested_key2717=== RUN TestExternalSignerErrors/invalid_signature_base642718=== PAUSE TestExternalSignerErrors/invalid_signature_base642719=== RUN TestExternalSignerErrors/wrong_signature_length2720=== PAUSE TestExternalSignerErrors/wrong_signature_length2721=== RUN TestExternalSignerErrors/exit_at_startup2722=== PAUSE TestExternalSignerErrors/exit_at_startup2723=== RUN TestExternalSignerErrors/missing_signatures2724=== PAUSE TestExternalSignerErrors/missing_signatures2725=== RUN TestExternalSignerErrors/too_few_signatures2726=== PAUSE TestExternalSignerErrors/too_few_signatures2727=== RUN TestExternalSignerErrors/wrong_signature_name2728=== PAUSE TestExternalSignerErrors/wrong_signature_name2729=== RUN TestExternalSignerErrors/invalid_JSON2730=== PAUSE TestExternalSignerErrors/invalid_JSON2731=== RUN TestExternalSignerErrors/wrong_shape2732=== PAUSE TestExternalSignerErrors/wrong_shape2733=== RUN TestExternalSignerErrors/null2734=== PAUSE TestExternalSignerErrors/null2735=== RUN TestExternalSignerErrors/wrong_id2736=== PAUSE TestExternalSignerErrors/wrong_id2737=== RUN TestExternalSignerErrors/null_signatures2738=== PAUSE TestExternalSignerErrors/null_signatures2739=== RUN TestExternalSignerErrors/missing_signature_name2740=== PAUSE TestExternalSignerErrors/missing_signature_name2741=== RUN TestExternalSignerErrors/program_error2742=== PAUSE TestExternalSignerErrors/program_error2743=== CONT TestExternalSignerErrors/exit_on_request2744=== CONT TestExternalSignerErrors/invalid_JSON2745=== CONT TestExternalSignerErrors/wrong_signature_name2746=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2747=== CONT TestExternalSignerErrors/program_error2748=== CONT TestExternalSignerErrors/missing_signatures2749=== CONT TestExternalSignerErrors/invalid_signature_base642750=== CONT TestParseSigningKey/no_colon2751=== CONT TestExternalSignerErrors/wrong_id2752=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2753=== PAUSE TestGenerateFingerprint/basic_with_references2754=== CONT TestExternalSignerErrors/wrong_shape2755=== CONT TestParseSigningKey/invalid_base642756=== CONT TestExternalSignerErrors/null2757=== CONT TestExternalSignerErrors/unrequested_key2758=== CONT TestExternalSignerErrors/wrong_signatures_shape2759=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2760=== CONT TestExternalSignerErrors/missing_signature_name2761=== CONT TestExternalSignerErrors/wrong_signature_length2762=== RUN TestSignErrors/nil_key2763--- PASS: TestSign (0.00s)2764=== CONT TestExternalSignerErrors/exit_at_startup2765=== PAUSE TestSignErrors/nil_key2766=== CONT TestExternalSignerErrors/too_few_signatures2767=== CONT TestExternalSignerErrors/null_signatures2768=== RUN TestGenerateFingerprint/no_references2769--- PASS: TestSignBatch (0.00s)2770=== RUN TestSignErrors/nil_narinfo2771--- PASS: TestExternalSignerClose (0.01s)2772--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2773 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2774 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2775 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2776 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2777 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2778--- PASS: TestExternalSignerWrongPublicKey (0.01s)2779--- PASS: TestParseSigningKey (0.00s)2780 --- PASS: TestParseSigningKey/empty_name (0.00s)2781 --- PASS: TestParseSigningKey/wrong_length (0.00s)2782 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2783 --- PASS: TestParseSigningKey/no_colon (0.00s)2784 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2785 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2786=== PAUSE TestSignErrors/nil_narinfo2787=== RUN TestSignErrors/invalid_narinfo2788=== PAUSE TestSignErrors/invalid_narinfo2789=== RUN TestSignErrors/canceled2790=== PAUSE TestSignErrors/canceled2791=== CONT TestSignErrors/nil_key2792=== CONT TestSignErrors/canceled2793=== CONT TestSignErrors/nil_narinfo2794=== CONT TestSignErrors/invalid_narinfo2795--- PASS: TestSignErrors (0.01s)2796 --- PASS: TestSignErrors/nil_key (0.00s)2797 --- PASS: TestSignErrors/canceled (0.00s)2798 --- PASS: TestSignErrors/nil_narinfo (0.00s)2799 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2800=== PAUSE TestGenerateFingerprint/no_references2801=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2802=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2803=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2804=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2805=== RUN TestGenerateFingerprint/invalid_nar_hash_length2806=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2807=== RUN TestGenerateFingerprint/invalid_store_path_prefix2808=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2809=== RUN TestGenerateFingerprint/invalid_reference_prefix2810=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2811--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.01s)2812=== CONT TestGenerateFingerprint/basic_with_references2813=== CONT TestGenerateFingerprint/invalid_reference_prefix2814=== CONT TestGenerateFingerprint/no_references2815=== CONT TestGenerateFingerprint/invalid_store_path_prefix2816=== CONT TestGenerateFingerprint/invalid_nar_hash_length2817=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2818=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2819--- PASS: TestGenerateFingerprint (0.01s)2820 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2821 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2822 --- PASS: TestGenerateFingerprint/no_references (0.00s)2823 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2824 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2825 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2826 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2827--- PASS: TestExternalSignerRestartsAfterCrash (0.02s)2828--- PASS: TestExternalSigner (0.02s)2829--- PASS: TestExternalSignerErrors (0.00s)2830 --- PASS: TestExternalSignerErrors/missing_signatures (0.01s)2831 --- PASS: TestExternalSignerErrors/exit_on_request (0.01s)2832 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)2833 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.01s)2834 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2835 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)2836 --- PASS: TestExternalSignerErrors/program_error (0.01s)2837 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)2838 --- PASS: TestExternalSignerErrors/null (0.01s)2839 --- PASS: TestExternalSignerErrors/unrequested_key (0.01s)2840 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)2841 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)2842 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)2843 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)2844 --- PASS: TestExternalSignerErrors/exit_at_startup (0.01s)2845 --- PASS: TestExternalSignerErrors/too_few_signatures (0.01s)2846--- PASS: TestExternalSignerCancellation (0.02s)2847PASS2848Running OpenBao signer tests...2849=== RUN TestSign2850=== PAUSE TestSign2851=== RUN TestSignErrors2852=== PAUSE TestSignErrors2853=== RUN TestServe2854=== PAUSE TestServe2855=== RUN TestServeRejectsGarbage2856=== PAUSE TestServeRejectsGarbage2857=== CONT TestSign2858=== CONT TestServeRejectsGarbage2859--- PASS: TestServeRejectsGarbage (0.00s)2860=== CONT TestServe2861--- PASS: TestServe (0.00s)2862=== CONT TestSignErrors2863=== RUN TestSignErrors/http_error2864=== PAUSE TestSignErrors/http_error2865=== RUN TestSignErrors/invalid_json2866=== PAUSE TestSignErrors/invalid_json2867=== RUN TestSignErrors/no_prefix2868=== PAUSE TestSignErrors/no_prefix2869=== RUN TestSignErrors/invalid_base642870=== PAUSE TestSignErrors/invalid_base642871=== CONT TestSignErrors/http_error2872=== CONT TestSignErrors/invalid_base642873=== CONT TestSignErrors/no_prefix2874=== CONT TestSignErrors/invalid_json2875--- PASS: TestSign (0.83s)2876--- PASS: TestSignErrors (0.00s)2877 --- PASS: TestSignErrors/invalid_base64 (0.82s)2878 --- PASS: TestSignErrors/no_prefix (0.82s)2879 --- PASS: TestSignErrors/invalid_json (0.82s)2880 --- PASS: TestSignErrors/http_error (0.83s)2881PASS