niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #437
· 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 TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure18=== PAUSE TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure19=== RUN TestUploadMultipart_PartsInParallel20=== PAUSE TestUploadMultipart_PartsInParallel21=== RUN TestUploadMultipart_FailedPartBufferNotReused22=== PAUSE TestUploadMultipart_FailedPartBufferNotReused23=== RUN TestUploadMultipart_ProducerErrorIsNotEOF24=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF25=== RUN TestPartSizeForNAR26=== PAUSE TestPartSizeForNAR27=== RUN TestUploadMultipart_SupersededByPeer28=== PAUSE TestUploadMultipart_SupersededByPeer29=== RUN TestDumpPathCaseHackMatchesNix30--- PASS: TestDumpPathCaseHackMatchesNix (0.13s)31=== RUN TestDumpPathCaseHackCollision32--- PASS: TestDumpPathCaseHackCollision (0.00s)33=== RUN TestSupersededNARStillUploadsListing34=== PAUSE TestSupersededNARStillUploadsListing35=== RUN TestTruncatedNARDumpIsNotCompleted36=== PAUSE TestTruncatedNARDumpIsNotCompleted37=== RUN TestDumpPathMatchesNix38=== PAUSE TestDumpPathMatchesNix39=== RUN TestDumpPathSingleFile40=== PAUSE TestDumpPathSingleFile41=== RUN TestDumpPathWriterError42=== PAUSE TestDumpPathWriterError43=== RUN TestDumpPathWriterErrorStopsReading44 nar_test.go:289: read 121 of 32768000 bytes45--- PASS: TestDumpPathWriterErrorStopsReading (0.62s)46=== RUN TestEncodeNixBase3247=== PAUSE TestEncodeNixBase3248=== RUN TestEncodeNixBase32WithRealHash49=== PAUSE TestEncodeNixBase32WithRealHash50=== RUN TestConvertHashToNix3251=== PAUSE TestConvertHashToNix3252=== RUN TestGetStorePathHash53=== PAUSE TestGetStorePathHash54=== RUN TestPathInfoHashCompatibility55=== PAUSE TestPathInfoHashCompatibility56=== RUN TestParsePathInfoJSON57=== PAUSE TestParsePathInfoJSON58=== RUN TestParsePathInfoJSONMultiplePaths59=== PAUSE TestParsePathInfoJSONMultiplePaths60=== RUN TestPathInfoCACompatibility61=== PAUSE TestPathInfoCACompatibility62=== RUN TestUploadPendingObjectsStopsStartingAfterFailure63--- PASS: TestUploadPendingObjectsStopsStartingAfterFailure (0.02s)64=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent65=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent66=== RUN TestCompletePendingClosure_NotFoundWithoutKey67=== PAUSE TestCompletePendingClosure_NotFoundWithoutKey68=== RUN TestRateLimiterFeedback69=== PAUSE TestRateLimiterFeedback70=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess71=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess72=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer73=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer74=== RUN TestResolveStorePath75=== PAUSE TestResolveStorePath76=== RUN TestDoWithRetry_BodyReplayedViaGetBody77=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody78=== RUN TestRetryTimeoutOutlastsMaxRetries79=== PAUSE TestRetryTimeoutOutlastsMaxRetries80=== RUN TestDoWithRetry_FinalResponseBodyReadable81=== PAUSE TestDoWithRetry_FinalResponseBodyReadable82=== RUN TestShellSplit83=== PAUSE TestShellSplit84=== RUN TestShellSplitErrors85=== PAUSE TestShellSplitErrors86=== RUN TestStreamPushReportsEveryPath87=== PAUSE TestStreamPushReportsEveryPath88=== RUN TestStreamPushBatchesUnderLoad89=== PAUSE TestStreamPushBatchesUnderLoad90=== RUN TestStreamPushIsolatesFailures91=== PAUSE TestStreamPushIsolatesFailures92=== RUN TestStreamPushGivesUpOnDeadServer93=== PAUSE TestStreamPushGivesUpOnDeadServer94=== RUN TestStreamPushRequestLine95=== PAUSE TestStreamPushRequestLine96=== RUN TestStreamPushReportsSignatures97=== PAUSE TestStreamPushReportsSignatures98=== RUN TestStreamPushReportsSkippedPaths99=== PAUSE TestStreamPushReportsSkippedPaths100=== RUN TestClientSignaturesByStorePath101=== PAUSE TestClientSignaturesByStorePath102=== RUN TestStreamPushStopsWhenCanceled103=== PAUSE TestStreamPushStopsWhenCanceled104=== RUN TestStreamPushStopsOnCancel105=== PAUSE TestStreamPushStopsOnCancel106=== RUN TestStreamPushStartsNothingOnSlotFreedByCancel107=== PAUSE TestStreamPushStartsNothingOnSlotFreedByCancel108=== RUN TestSetClientTLS109=== PAUSE TestSetClientTLS110=== RUN TestSetClientTLSDoesNotMutateDefaultTransport111=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport112=== RUN TestSetClientTLSErrors113=== PAUSE TestSetClientTLSErrors114=== RUN TestStaticToken115=== PAUSE TestStaticToken116=== RUN TestFileTokenReadsAndCaches117=== PAUSE TestFileTokenReadsAndCaches118=== RUN TestFileTokenMissing119=== PAUSE TestFileTokenMissing120=== RUN TestFileTokenEmpty121=== PAUSE TestFileTokenEmpty122=== RUN TestScriptTokenNoExpiryRerunsEveryCall123=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall124=== RUN TestScriptTokenCachesUntilRefresh125=== PAUSE TestScriptTokenCachesUntilRefresh126=== RUN TestScriptTokenEmptyToken127=== PAUSE TestScriptTokenEmptyToken128=== RUN TestScriptTokenBadJSON129=== PAUSE TestScriptTokenBadJSON130=== RUN TestScriptTokenScriptFails131=== PAUSE TestScriptTokenScriptFails132=== RUN TestScriptTokenEmptyCommand133=== PAUSE TestScriptTokenEmptyCommand134=== RUN TestScriptTokenDoesNotWaitForItsChildren135=== PAUSE TestScriptTokenDoesNotWaitForItsChildren136=== CONT TestStreamPushStartsNothingOnSlotFreedByCancel137=== CONT TestScriptTokenEmptyToken138=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun139=== CONT TestDoWithRetry_BodyReplayedViaGetBody140=== CONT TestRateLimiterFeedback141=== RUN TestRateLimiterFeedback/429_enables_limiter142=== CONT TestPathInfoHashCompatibility143=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)144=== PAUSE TestRateLimiterFeedback/429_enables_limiter145=== RUN TestRateLimiterFeedback/503_enables_limiter146=== CONT TestParsePathInfoJSON147=== RUN TestParsePathInfoJSON/Nix_format148=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)149=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon150=== CONT TestGetStorePathHash151=== PAUSE TestRateLimiterFeedback/503_enables_limiter152=== CONT TestShellSplit153=== CONT TestConvertHashToNix32154=== CONT TestDoWithRetry_FinalResponseBodyReadable155=== CONT TestStreamPushIsolatesFailures156=== CONT TestStreamPushGivesUpOnDeadServer157=== CONT TestStreamPushReportsSignatures158=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess159=== CONT TestScriptTokenEmptyCommand160=== CONT TestSetClientTLSDoesNotMutateDefaultTransport161=== CONT TestSetClientTLS162=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica163=== CONT TestCompletePendingClosure_NotFoundWithoutKey164=== CONT TestFileTokenMissing165=== CONT TestRegisterUploadedObjectReusesConnections166=== CONT TestUploadMultipart_SupersededByPeer167=== CONT TestSupersededNARStillUploadsListing168=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon169=== PAUSE TestParsePathInfoJSON/Nix_format170=== RUN TestGetStorePathHash/valid_store_path171=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter172--- PASS: TestShellSplit (0.00s)173=== RUN TestConvertHashToNix32/SRI_format_to_Nix32174=== CONT TestShellSplitErrors175=== CONT TestScriptTokenNoExpiryRerunsEveryCall176=== CONT TestScriptTokenCachesUntilRefresh177=== CONT TestCaseHackSuffix178=== CONT TestStreamPushStopsOnCancel179=== RUN TestUploadMultipart_SupersededByPeer/exists180=== PAUSE TestGetStorePathHash/valid_store_path181=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI182--- PASS: TestScriptTokenEmptyCommand (0.00s)183=== RUN TestSupersededNARStillUploadsListing/small_NAR184=== RUN TestParsePathInfoJSON/Lix_format185=== CONT TestEncodeNixBase32186=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter187=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32188=== RUN TestStreamPushStopsOnCancel/waiting_for_input189=== CONT TestClientSignaturesByStorePath190=== PAUSE TestUploadMultipart_SupersededByPeer/exists191=== CONT TestEncodeNixBase32WithRealHash192=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI193--- PASS: TestScriptTokenEmptyToken (0.01s)194=== RUN TestGetStorePathHash/basename_without_hyphen_should_error195=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter196=== RUN TestEncodeNixBase32/test_string_hash197=== PAUSE TestParsePathInfoJSON/Lix_format198=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent199=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error200=== RUN TestConvertHashToNix32/already_Nix32_format201--- PASS: TestEncodeNixBase32WithRealHash (0.00s)202=== CONT TestStreamPushStopsWhenCanceled203=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512204=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier205=== RUN TestUploadMultipart_SupersededByPeer/missing206=== PAUSE TestSupersededNARStillUploadsListing/small_NAR207=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter208=== PAUSE TestEncodeNixBase32/test_string_hash209=== PAUSE TestStreamPushStopsOnCancel/waiting_for_input210--- PASS: TestFileTokenMissing (0.00s)211=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512212=== RUN TestSupersededNARStillUploadsListing/dump_cut_short213=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier214=== CONT TestResolveStorePath215=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up216=== RUN TestEncodeNixBase32/empty_input217=== PAUSE TestUploadMultipart_SupersededByPeer/missing218=== RUN TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot219--- PASS: TestStreamPushIsolatesFailures (0.01s)220--- PASS: TestShellSplitErrors (0.00s)221=== CONT TestScriptTokenBadJSON222=== CONT TestStreamPushReportsSkippedPaths223=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short224=== CONT TestStreamPushBatchesUnderLoad225=== RUN TestParsePathInfoJSON/empty_input226=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer227=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error228=== PAUSE TestConvertHashToNix32/already_Nix32_format229=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up230=== PAUSE TestEncodeNixBase32/empty_input231=== CONT TestStaticToken232=== PAUSE TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot233--- PASS: TestStreamPushGivesUpOnDeadServer (0.02s)234=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails235=== RUN TestStreamPushBatchesUnderLoad/together236=== CONT TestScriptTokenScriptFails237=== CONT TestFileTokenEmpty238=== CONT TestScriptTokenDoesNotWaitForItsChildren239=== CONT TestRetryTimeoutOutlastsMaxRetries240=== PAUSE TestParsePathInfoJSON/empty_input241=== CONT TestStreamPushRequestLine242=== CONT TestPathInfoCACompatibility243=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier244=== CONT TestStreamPushReportsEveryPath245=== CONT TestUploadMultipart_PartsInParallel246--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.02s)247=== RUN TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot248=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier249=== PAUSE TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot250--- PASS: TestClientSignaturesByStorePath (0.00s)251=== CONT TestParsePathInfoJSONMultiplePaths252=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails253=== PAUSE TestStreamPushBatchesUnderLoad/together254=== RUN TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs255=== RUN TestParsePathInfoJSON/whitespace_only256=== RUN TestPathInfoCACompatibility/null_ca_field257=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client258=== RUN TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot259=== CONT TestFileTokenReadsAndCaches260=== CONT TestDoServerRequestAttachesToken261--- PASS: TestStreamPushStopsWhenCanceled (0.00s)262=== CONT TestUploadMultipart_FailedPartBufferNotReused263=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs264=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client265--- PASS: TestCompletePendingClosure_NotFoundWithoutKey (0.05s)266--- PASS: TestStreamPushReportsSignatures (0.06s)267=== RUN TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout268=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client269=== PAUSE TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot270=== PAUSE TestPathInfoCACompatibility/null_ca_field271=== RUN TestStreamPushBatchesUnderLoad/one_at_a_time272=== PAUSE TestParsePathInfoJSON/whitespace_only273=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths274=== CONT TestDumpPathWriterError275=== RUN TestConvertHashToNix32/invalid_format276=== CONT TestTruncatedNARDumpIsNotCompleted277--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)278=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout279--- PASS: TestStreamPushReportsSkippedPaths (0.00s)280=== RUN TestPathInfoCACompatibility/old_string_format_-_text281=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text282=== PAUSE TestStreamPushBatchesUnderLoad/one_at_a_time283=== RUN TestSetClientTLS/rejects_connection_without_client_cert284=== CONT TestDumpPathSingleFile285=== RUN TestParsePathInfoJSON/invalid_JSON286=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive287=== CONT TestSetClientTLSErrors288=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert289=== PAUSE TestParsePathInfoJSON/invalid_JSON290=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA291=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA292=== RUN TestSetClientTLS/preserves_debug_logging_transport293=== PAUSE TestSetClientTLS/preserves_debug_logging_transport294=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive295=== CONT TestFilterOversizedClosures296=== RUN TestFilterOversizedClosures/no_limit_keeps_everything297=== RUN TestPathInfoCACompatibility/new_structured_format_-_text298=== CONT TestDumpPathMatchesNix299=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text300=== CONT TestUploadMultipart_ProducerErrorIsNotEOF301=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part302=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method303=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry304=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part305=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary306=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error307=== RUN TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot308=== RUN TestSetClientTLSErrors/missing_cert_file309=== PAUSE TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot310=== PAUSE TestConvertHashToNix32/invalid_format311=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything312=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method313=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error314=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error315=== CONT TestPartSizeForNAR316=== CONT TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure317=== CONT TestRateLimiterFeedback/503_enables_limiter318=== RUN TestStreamPushStopsOnCancel/lines_read_but_not_taken319=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped320=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped321=== RUN TestFilterOversizedClosures/all_closures_skipped322=== PAUSE TestFilterOversizedClosures/all_closures_skipped323=== PAUSE TestStreamPushStopsOnCancel/lines_read_but_not_taken324=== RUN TestPartSizeForNAR/zero_stays_at_minimum325=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter326=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths327=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths328=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary329=== PAUSE TestSetClientTLSErrors/missing_cert_file330=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client331=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths332=== RUN TestSetClientTLSErrors/missing_key_file333=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum334=== CONT TestRateLimiterFeedback/429_enables_limiter335=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512336=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter337=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon338=== CONT TestUploadMultipart_SupersededByPeer/missing339=== PAUSE TestSetClientTLSErrors/missing_key_file340=== RUN TestSetClientTLSErrors/missing_ca_file341=== RUN TestPartSizeForNAR/small_stays_at_minimum342=== PAUSE TestSetClientTLSErrors/missing_ca_file343=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)344=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI345=== PAUSE TestPartSizeForNAR/small_stays_at_minimum346=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum347=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum348=== CONT TestUploadMultipart_SupersededByPeer/exists349=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts350=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts351=== RUN TestPartSizeForNAR/1_TiB352=== PAUSE TestPartSizeForNAR/1_TiB353=== RUN TestPartSizeForNAR/5_TiB_S3_max_object354=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object355=== CONT TestEncodeNixBase32/test_string_hash356=== CONT TestSupersededNARStillUploadsListing/dump_cut_short357=== CONT TestSupersededNARStillUploadsListing/small_NAR358=== RUN TestSetClientTLSErrors/invalid_ca_file359=== RUN TestPartSizeForNAR/capped_at_5_GiB360=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails361=== PAUSE TestPartSizeForNAR/capped_at_5_GiB362=== PAUSE TestSetClientTLSErrors/invalid_ca_file363=== CONT TestEncodeNixBase32/empty_input364=== CONT TestStreamPushBatchesUnderLoad/together365=== CONT TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout366--- PASS: TestResolveStorePath (0.01s)367--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.07s)368--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.07s)369--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.08s)370--- PASS: TestStaticToken (0.00s)371=== CONT TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs372=== CONT TestParsePathInfoJSON/invalid_JSON373=== CONT TestParsePathInfoJSON/empty_input374=== CONT TestParsePathInfoJSON/Lix_format375--- PASS: TestScriptTokenBadJSON (0.02s)376--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.07s)377--- PASS: TestFileTokenEmpty (0.00s)378--- PASS: TestStreamPushReportsEveryPath (0.00s)379--- PASS: TestScriptTokenScriptFails (0.00s)380--- PASS: TestFileTokenReadsAndCaches (0.00s)381--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.09s)382--- PASS: TestDoServerRequestAttachesToken (0.01s)383=== CONT TestParsePathInfoJSON/Nix_format384=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA385--- PASS: TestDumpPathSingleFile (0.53s)386=== CONT TestSetClientTLS/preserves_debug_logging_transport387=== CONT TestSetClientTLS/rejects_connection_without_client_cert388=== CONT TestParsePathInfoJSON/whitespace_only389--- PASS: TestCaseHackSuffix (0.60s)390=== CONT TestStreamPushBatchesUnderLoad/one_at_a_time391=== CONT TestPathInfoCACompatibility/null_ca_field392--- PASS: TestEncodeNixBase32 (0.02s)393 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)394 --- PASS: TestEncodeNixBase32/empty_input (0.00s)395--- PASS: TestPathInfoHashCompatibility (0.05s)396 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)397 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)398 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)399 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)400=== CONT TestConvertHashToNix32/SRI_format_to_Nix32401--- PASS: TestRateLimiterFeedback (0.05s)402 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)403 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)404 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)405 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.53s)406=== CONT TestPathInfoCACompatibility/old_string_format_-_text407=== CONT TestGetStorePathHash/valid_store_path408--- PASS: TestParsePathInfoJSON (0.09s)409 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)410 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)411 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)412 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)413 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)414--- PASS: TestUploadMultipart_SupersededByPeer (0.05s)415 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.53s)416 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.53s)417=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method418=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive419=== CONT TestPathInfoCACompatibility/new_structured_format_-_text420=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error421=== CONT TestGetStorePathHash/basename_without_hyphen_should_error422=== CONT TestConvertHashToNix32/invalid_format423--- PASS: TestStreamPushBatchesUnderLoad (0.03s)424 --- PASS: TestStreamPushBatchesUnderLoad/together (0.28s)425 --- PASS: TestStreamPushBatchesUnderLoad/one_at_a_time (0.00s)426=== CONT TestConvertHashToNix32/already_Nix32_format427=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error428=== CONT TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot429=== CONT TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot430=== CONT TestStreamPushStopsOnCancel/lines_read_but_not_taken431--- PASS: TestPathInfoCACompatibility (0.01s)432 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)433 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)434 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)435 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)436 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)437--- PASS: TestGetStorePathHash (0.10s)438 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)439 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)440 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)441 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)442--- PASS: TestConvertHashToNix32 (0.10s)443 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)444 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)445 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)446--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.54s)447=== CONT TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot448=== CONT TestFilterOversizedClosures/all_closures_skipped449=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped450=== CONT TestFilterOversizedClosures/no_limit_keeps_everything451=== CONT TestStreamPushStopsOnCancel/waiting_for_input452=== CONT TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot453--- PASS: TestFilterOversizedClosures (0.00s)454 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)455 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)456 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)457=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client458=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths459=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part460=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier461=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths462=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary463=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up464--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)465 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)466 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)467=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client468=== CONT TestPartSizeForNAR/1_TiB469=== CONT TestSetClientTLSErrors/missing_cert_file470=== CONT TestPartSizeForNAR/capped_at_5_GiB471=== CONT TestPartSizeForNAR/5_TiB_S3_max_object472=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier473=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum474=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts475=== CONT TestPartSizeForNAR/small_stays_at_minimum476=== CONT TestPartSizeForNAR/zero_stays_at_minimum477=== CONT TestSetClientTLSErrors/invalid_ca_file478--- PASS: TestPartSizeForNAR (0.01s)479 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)480 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)481 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)482 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)483 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)484 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)485 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)486=== CONT TestSetClientTLSErrors/missing_key_file487=== CONT TestSetClientTLSErrors/missing_ca_file488--- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent (0.05s)489 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client (0.00s)490 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier (0.01s)491 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up (0.01s)492 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client (0.00s)493 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier (0.00s)494--- PASS: TestSetClientTLSErrors (0.25s)495 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)496 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)497 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)498 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)499--- PASS: TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure (0.63s)500--- PASS: TestStreamPushStopsOnCancel (0.08s)501 --- PASS: TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot (0.08s)502 --- PASS: TestStreamPushStopsOnCancel/waiting_for_input (0.07s)503 --- PASS: TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot (0.07s)504 --- PASS: TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot (0.09s)505 --- PASS: TestStreamPushStopsOnCancel/lines_read_but_not_taken (0.09s)506 --- PASS: TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot (0.10s)507--- PASS: TestDumpPathWriterError (0.65s)508--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.66s)509--- PASS: TestStreamPushStartsNothingOnSlotFreedByCancel (0.91s)510--- PASS: TestSetClientTLS (0.09s)511 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.02s)512 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.02s)513 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.33s)514--- PASS: TestUploadMultipart_ProducerErrorIsNotEOF (0.00s)515 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part (0.26s)516 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary (0.30s)517--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)518--- PASS: TestRegisterUploadedObjectReusesConnections (1.00s)519--- PASS: TestDumpPathMatchesNix (0.93s)520--- PASS: TestStreamPushRequestLine (0.98s)521--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)522--- PASS: TestSupersededNARStillUploadsListing (0.07s)523 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.54s)524 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.54s)525 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (1.48s)526--- PASS: TestUploadMultipart_PartsInParallel (1.50s)527--- PASS: TestUploadMultipart_FailedPartBufferNotReused (1.52s)528--- PASS: TestTruncatedNARDumpIsNotCompleted (1.58s)529--- PASS: TestScriptTokenDoesNotWaitForItsChildren (0.01s)530 --- PASS: TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout (2.28s)531 --- PASS: TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs (2.24s)532PASS533Running server tests...534The files belonging to this database system will be owned by user "nixbld".535This user must also own the server process.536537The database cluster will be initialized with locale "C".538The default database encoding has accordingly been set to "SQL_ASCII".539The default text search configuration will be set to "english".540541Data page checksums are enabled.542543creating directory /build/postgres1393074924/data ... ok544creating subdirectories ... ok545selecting dynamic shared memory implementation ... posix546selecting default "max_connections" ... 100547selecting default "shared_buffers" ... 128MB548selecting default time zone ... UTC549creating configuration files ... ok550running bootstrap script ... ok551performing post-bootstrap initialization ... ok552syncing data to disk ... ok553554initdb: warning: enabling "trust" authentication for local connections555initdb: 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.556557Success. You can now start the database server using:558559 pg_ctl -D /build/postgres1393074924/data -l logfile start560561/build/postgres1393074924:5432 - no response5622026-10-26 22:36:32.380 UTC [170] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit5632026-10-26 22:36:32.380 UTC [170] LOG: listening on Unix socket "/build/postgres1393074924/.s.PGSQL.5432"5642026-10-26 22:36:32.385 UTC [178] LOG: database system was shut down at 2026-10-26 22:36:32 UTC5652026-10-26 22:36:32.385 UTC [179] FATAL: the database system is starting up566/build/postgres1393074924:5432 - rejecting connections5672026-10-26 22:36:32.388 UTC [170] LOG: database system is ready to accept connections568/build/postgres1393074924:5432 - accepting connections569{"timestamp":"2026-10-26T22:36:33.936457846Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"5aaf6fd5-6e70-484b-9c8b-89a8f5431f48","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":3,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(197)"}570=== RUN TestService_AuthMiddleware571=== PAUSE TestService_AuthMiddleware572=== RUN TestService_AuthMiddleware_MTLSProxyHeader573=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader574=== RUN TestService_AuthMiddleware_MTLSBoundSubjects575=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects576=== RUN TestService_ReadAuthMiddleware577=== PAUSE TestService_ReadAuthMiddleware578=== RUN TestService_AuthMiddleware_OIDC579=== PAUSE TestService_AuthMiddleware_OIDC580=== RUN TestService_RequireScope_OIDC581=== PAUSE TestService_RequireScope_OIDC582=== RUN TestService_ReadScope_PublicByDefault583=== PAUSE TestService_ReadScope_PublicByDefault584=== RUN TestCacheConfigHandler585=== PAUSE TestCacheConfigHandler586=== RUN TestCacheStatsHandler587=== PAUSE TestCacheStatsHandler588=== RUN TestClientCADerivations589=== PAUSE TestClientCADerivations590=== RUN TestClientErrorHandling591=== PAUSE TestClientErrorHandling592=== RUN TestClientIntegration593=== PAUSE TestClientIntegration594=== RUN TestClientMultipleUploads595=== PAUSE TestClientMultipleUploads596=== RUN TestClientWithDependencies597=== PAUSE TestClientWithDependencies598=== RUN TestClientSharedPathCommittedMidPush599=== PAUSE TestClientSharedPathCommittedMidPush600=== RUN TestPinProtectsFromGC601=== PAUSE TestPinProtectsFromGC602=== RUN TestClientPushesUseOnePush603=== PAUSE TestClientPushesUseOnePush604=== RUN TestClientFallsBackToClosures605=== PAUSE TestClientFallsBackToClosures606=== RUN TestDeleteClosuresRacingPins607=== PAUSE TestDeleteClosuresRacingPins608=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock609=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock610=== RUN TestResolveDBConnectionString611=== PAUSE TestResolveDBConnectionString612=== RUN TestConnectWaitsForAPeerMigration613=== PAUSE TestConnectWaitsForAPeerMigration614=== RUN TestConnectSerialisesConcurrentMigrations615=== PAUSE TestConnectSerialisesConcurrentMigrations616=== RUN TestLeadElectsOneAndHandsOver617=== PAUSE TestLeadElectsOneAndHandsOver618=== RUN TestLeadIncumbentWinsAfterRestart6192026/10/26 22:36:34 INFO lead: acquired remote=192.0.2.1:12346202026/10/26 22:36:34 INFO lead: released remote=192.0.2.1:12346212026/10/26 22:36:34 INFO lead: acquired remote=192.0.2.1:12346222026/10/26 22:36:35 INFO lead: released remote=192.0.2.1:1234623--- PASS: TestLeadIncumbentWinsAfterRestart (1.94s)624=== RUN TestLeadIncumbentAnnouncesAtOnce625=== PAUSE TestLeadIncumbentAnnouncesAtOnce626=== RUN TestLeadEndsOnShutdown627=== PAUSE TestLeadEndsOnShutdown628=== RUN TestLeadEndsWhenItsConnectionHangs6292026/10/26 22:36:36 INFO lead: acquired remote=192.0.2.1:12346302026-10-26 22:36:37.533 UTC [432] FATAL: terminating connection due to administrator command6312026/10/26 22:36:37 INFO lead: acquired remote=192.0.2.1:12346322026/10/26 22:36:38 WARN lead: lock connection lost error="timeout: context deadline exceeded"6332026/10/26 22:36:38 INFO lead: released remote=192.0.2.1:12346342026/10/26 22:36:38 INFO lead: released remote=192.0.2.1:1234635--- PASS: TestLeadEndsWhenItsConnectionHangs (2.96s)636=== RUN TestGCAdvisoryLockBlocksConcurrentRun637=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun638=== RUN TestGCBugBareHashReferences639=== PAUSE TestGCBugBareHashReferences640=== RUN TestGCMetrics641=== PAUSE TestGCMetrics642=== RUN TestPushDedupSurvivesConcurrentGC643=== PAUSE TestPushDedupSurvivesConcurrentGC644=== RUN TestDeduplicatedObjectsRecordedAsPending645=== PAUSE TestDeduplicatedObjectsRecordedAsPending646=== RUN TestGCSweepSkipsPendingObjects647=== PAUSE TestGCSweepSkipsPendingObjects648=== RUN TestTombstonedObjectOfferedWithoutWaiting649=== PAUSE TestTombstonedObjectOfferedWithoutWaiting650=== RUN TestGCSweepDeliversEachKeyOnce651=== PAUSE TestGCSweepDeliversEachKeyOnce652=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection653=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection654=== RUN TestForceGCDuringPushOffersSweptObject655=== PAUSE TestForceGCDuringPushOffersSweptObject656=== RUN TestFailedS3DeleteKeepsTombstone657=== PAUSE TestFailedS3DeleteKeepsTombstone658=== RUN TestSweepSkipsRowsLockedByPush659=== PAUSE TestSweepSkipsRowsLockedByPush660=== RUN TestRegisterCompletedObjectNeedsPendingRow661=== PAUSE TestRegisterCompletedObjectNeedsPendingRow662=== RUN TestGetExistingObjectsLocksRows663=== PAUSE TestGetExistingObjectsLocksRows664=== RUN TestSweepRechecksPendingAfterLocking665=== PAUSE TestSweepRechecksPendingAfterLocking666=== RUN TestPushWaitsForSweepHoldingRow667=== PAUSE TestPushWaitsForSweepHoldingRow668=== RUN TestCommitRacingPendingCleanupKeepsObjects669=== PAUSE TestCommitRacingPendingCleanupKeepsObjects670=== RUN TestGCEndsOnShutdown671=== PAUSE TestGCEndsOnShutdown672=== RUN TestGCTaskStore_StartNew673=== PAUSE TestGCTaskStore_StartNew674=== RUN TestGCTaskStore_DeduplicateSameParams675=== PAUSE TestGCTaskStore_DeduplicateSameParams676=== RUN TestGCTaskStore_ConflictDifferentParams677=== PAUSE TestGCTaskStore_ConflictDifferentParams678=== RUN TestGCTaskStore_GetEmpty679=== PAUSE TestGCTaskStore_GetEmpty680=== RUN TestGCTaskStore_GetReturnsLatest681=== PAUSE TestGCTaskStore_GetReturnsLatest682=== RUN TestGCTaskStore_CompletedAllowsNewTask683=== PAUSE TestGCTaskStore_CompletedAllowsNewTask684=== RUN TestGCTaskStore_PhaseUpdates685=== PAUSE TestGCTaskStore_PhaseUpdates686=== RUN TestGCTaskStore_Fail687=== PAUSE TestGCTaskStore_Fail688=== RUN TestGracefulShutdownDrainsInflight689=== PAUSE TestGracefulShutdownDrainsInflight690=== RUN TestService_healthCheckHandler691=== PAUSE TestService_healthCheckHandler692=== RUN TestService_readinessHandler693=== PAUSE TestService_readinessHandler694=== RUN TestGenerateLandingPage695=== PAUSE TestGenerateLandingPage696=== RUN TestChildrenInheritRaisedFileLimit697=== PAUSE TestChildrenInheritRaisedFileLimit698=== RUN TestCacheConfigHandlerMaxNarSize699=== PAUSE TestCacheConfigHandlerMaxNarSize700=== RUN TestCreatePendingClosureRejectsOversizedNAR701=== PAUSE TestCreatePendingClosureRejectsOversizedNAR702=== RUN TestNARDeduplicationMetadataUploadBug703=== PAUSE TestNARDeduplicationMetadataUploadBug704=== RUN TestMetricsInventory705=== PAUSE TestMetricsInventory706=== RUN TestMetricsCommit707=== PAUSE TestMetricsCommit708=== RUN TestService_NativeMTLS709=== PAUSE TestService_NativeMTLS710=== RUN TestServerTLSConfig711=== PAUSE TestServerTLSConfig712=== RUN TestMultipartCleanup713=== PAUSE TestMultipartCleanup714=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded715=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded716=== RUN TestPendingCleanupUsesOneCutoff717=== PAUSE TestPendingCleanupUsesOneCutoff718=== RUN TestPendingClosureFailureTracksEveryUpload719=== PAUSE TestPendingClosureFailureTracksEveryUpload720=== RUN TestPendingClosureFailureAbortsItsUploads721=== PAUSE TestPendingClosureFailureAbortsItsUploads722=== RUN TestObjectStatsTrigger723=== PAUSE TestObjectStatsTrigger724=== RUN TestObjectStatsUpdatedOncePerCommit725=== PAUSE TestObjectStatsUpdatedOncePerCommit726=== RUN TestReconnectLeavesObjectsUnlocked727=== PAUSE TestReconnectLeavesObjectsUnlocked728=== RUN TestOrphanedObjectsGC729=== PAUSE TestOrphanedObjectsGC730=== RUN TestOrphanedObjectsGCStressTest731=== PAUSE TestOrphanedObjectsGCStressTest732=== RUN TestCreatePin_ReservedPins733=== PAUSE TestCreatePin_ReservedPins734=== RUN TestConcurrentPinUpdatesAgree735=== PAUSE TestConcurrentPinUpdatesAgree736=== RUN TestCreatePinRejectsBadInput737=== PAUSE TestCreatePinRejectsBadInput738=== RUN TestDeletePinKeepsRowWhenS3Fails739=== PAUSE TestDeletePinKeepsRowWhenS3Fails740=== RUN TestPresentReportsOnlyClosureRoots741=== PAUSE TestPresentReportsOnlyClosureRoots742=== RUN TestPresentRefreshesOnlyStaleClosures743=== PAUSE TestPresentRefreshesOnlyStaleClosures744=== RUN TestPresentNotReportedWhileGCDeletesClosure745=== PAUSE TestPresentNotReportedWhileGCDeletesClosure746=== RUN TestParseSingleRange747=== PAUSE TestParseSingleRange748=== RUN TestProxyHeadersOnlyTrustedOnSocket7492026/10/26 22:36:39 INFO Starting HTTP server address=127.0.0.1:365817502026/10/26 22:36:39 INFO Starting HTTP server address=proxy.sock7512026/10/26 22:36:39 WARN mTLS auth: subject not in bound subjects subject="CN=someone"7522026/10/26 22:36:39 INFO Shutdown signal received, draining in-flight requests timeout=10s753--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.27s)754=== RUN TestIsValidCachePath755=== PAUSE TestIsValidCachePath756=== RUN TestReadProxyNarinfo757=== PAUSE TestReadProxyNarinfo758=== RUN TestReadProxyNarinfoAlreadyDecompressed759=== PAUSE TestReadProxyNarinfoAlreadyDecompressed760=== RUN TestReadProxyContentNegotiation761=== PAUSE TestReadProxyContentNegotiation762=== RUN TestReadProxyNarStreaming763=== PAUSE TestReadProxyNarStreaming764=== RUN TestReadProxy404And429765=== PAUSE TestReadProxy404And429766=== RUN TestReadProxyInvalidPath767=== PAUSE TestReadProxyInvalidPath768=== RUN TestReadProxyHead769=== PAUSE TestReadProxyHead770=== RUN TestReadProxyOutlastsServerWriteTimeout771=== PAUSE TestReadProxyOutlastsServerWriteTimeout772=== RUN TestReadProxyConditionalGet773=== PAUSE TestReadProxyConditionalGet774=== RUN TestReadProxyRootRedirectsToIndexHTML775=== PAUSE TestReadProxyRootRedirectsToIndexHTML776=== RUN TestReadProxyDisabled777=== PAUSE TestReadProxyDisabled778=== RUN TestReadRedirectNar779=== PAUSE TestReadRedirectNar780=== RUN TestReadRedirectKeepsNarinfoProxied781=== PAUSE TestReadRedirectKeepsNarinfoProxied782=== RUN TestReadProxyRangeRequest783=== PAUSE TestReadProxyRangeRequest784=== RUN TestReadRedirectUsesPublicS3URL785=== PAUSE TestReadRedirectUsesPublicS3URL786=== RUN TestPush_OverlappingRootsStoreOneRowPerKey787=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey788=== RUN TestPush_CompleteCommitsEveryRoot789=== PAUSE TestPush_CompleteCommitsEveryRoot790=== RUN TestPush_RepeatedRootCommitsOnce791=== PAUSE TestPush_RepeatedRootCommitsOnce792=== RUN TestPush_CompleteWaitsForCleanupOfThePush793=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush794=== RUN TestPush_RootsAreLockedInByteOrder795=== PAUSE TestPush_RootsAreLockedInByteOrder796=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit797=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit798=== RUN TestPush_RejectsBadRequests799=== PAUSE TestPush_RejectsBadRequests800=== RUN TestPush_SignsNarinfosOfItsPendingObjects801=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects802=== RUN TestRedundantMultipartUpload803=== PAUSE TestRedundantMultipartUpload804=== RUN TestCompleteMultipartUpload_ErrorButObjectExists805=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists806=== RUN TestCompletedNarNotReofferedAcrossClosures807=== PAUSE TestCompletedNarNotReofferedAcrossClosures808=== RUN TestPresignedUploadRegisteredBeforeCommit809=== PAUSE TestPresignedUploadRegisteredBeforeCommit810=== RUN TestService_Rustfstest811=== PAUSE TestService_Rustfstest812=== RUN TestParseSize813=== PAUSE TestParseSize814=== RUN TestSkippedUploadsHandler815=== PAUSE TestSkippedUploadsHandler816=== RUN TestSystemdListenerNotActivated817--- PASS: TestSystemdListenerNotActivated (0.00s)818=== RUN TestWatchdogBeatsWhenHealthy819--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)820=== RUN TestWatchdogSkipsWhenUnhealthy8212026/10/26 22:36:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8222026/10/26 22:36:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8232026/10/26 22:36:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8242026/10/26 22:36:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8252026/10/26 22:36:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8262026/10/26 22:36:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8272026/10/26 22:36:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8282026/10/26 22:36:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8292026/10/26 22:36:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8302026/10/26 22:36:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"831--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)832=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle833=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle834=== RUN TestProxyWriteTimeout835=== PAUSE TestProxyWriteTimeout836=== RUN TestPendingClosureWriteTimeout837=== PAUSE TestPendingClosureWriteTimeout838=== RUN TestIsValidUploadKey839=== PAUSE TestIsValidUploadKey840=== RUN TestUploadHandlersRejectInvalidKeys841=== PAUSE TestUploadHandlersRejectInvalidKeys842=== RUN TestUploadHandlersRejectOversizedBody843=== PAUSE TestUploadHandlersRejectOversizedBody844=== RUN TestService_cleanupPendingClosuresHandler845=== PAUSE TestService_cleanupPendingClosuresHandler846=== RUN TestService_createPendingClosureHandler847=== PAUSE TestService_createPendingClosureHandler848=== RUN TestService_verifyS3Integrity849=== PAUSE TestService_verifyS3Integrity850=== RUN TestCompleteMultipartUnregistered851=== PAUSE TestCompleteMultipartUnregistered852=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT853=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT854=== CONT TestProxyWriteTimeout855=== CONT TestReadRedirectUsesPublicS3URL856=== CONT TestService_cleanupPendingClosuresHandler857=== CONT TestCreatePin_ReservedPins858=== CONT TestCompletedNarNotReofferedAcrossClosures859=== CONT TestService_AuthMiddleware860=== CONT TestSkippedUploadsHandler861=== CONT TestDeletePinKeepsRowWhenS3Fails862=== CONT TestReadProxyRangeRequest863=== CONT TestOrphanedObjectsGCStressTest864=== CONT TestParseSize865=== CONT TestOrphanedObjectsGC866=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle867=== CONT TestConcurrentPinUpdatesAgree868=== CONT TestService_Rustfstest869=== CONT TestObjectStatsUpdatedOncePerCommit870=== CONT TestObjectStatsTrigger871=== CONT TestPendingClosureFailureAbortsItsUploads8722026/10/26 22:36:39 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000873=== CONT TestCompleteMultipartUpload_ErrorButObjectExists874=== CONT TestPresignedUploadRegisteredBeforeCommit875=== CONT TestPush_SignsNarinfosOfItsPendingObjects876=== RUN TestProxyWriteTimeout/narinfo877=== CONT TestReconnectLeavesObjectsUnlocked878=== PAUSE TestProxyWriteTimeout/narinfo879=== CONT TestIsValidCachePath880=== CONT TestRedundantMultipartUpload881--- PASS: TestParseSize (0.00s)882=== CONT TestPendingCleanupUsesOneCutoff883=== RUN TestProxyWriteTimeout/1_GiB_nar884=== RUN TestIsValidCachePath/narinfo885=== PAUSE TestProxyWriteTimeout/1_GiB_nar886=== RUN TestProxyWriteTimeout/10_GiB_nar887=== PAUSE TestProxyWriteTimeout/10_GiB_nar888=== PAUSE TestIsValidCachePath/narinfo889=== RUN TestProxyWriteTimeout/unknown_size890=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars891=== PAUSE TestProxyWriteTimeout/unknown_size892=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars893=== RUN TestIsValidCachePath/nar_zst894=== PAUSE TestIsValidCachePath/nar_zst895=== RUN TestIsValidCachePath/nar_xz896=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit897=== PAUSE TestIsValidCachePath/nar_xz898=== RUN TestIsValidCachePath/nar_bz2899=== PAUSE TestIsValidCachePath/nar_bz2900=== RUN TestIsValidCachePath/nar_uncompressed901=== PAUSE TestIsValidCachePath/nar_uncompressed902=== RUN TestIsValidCachePath/ls903=== PAUSE TestIsValidCachePath/ls904=== RUN TestIsValidCachePath/log905=== PAUSE TestIsValidCachePath/log906=== RUN TestIsValidCachePath/realisation907=== PAUSE TestIsValidCachePath/realisation908=== RUN TestIsValidCachePath/nix-cache-info909=== PAUSE TestIsValidCachePath/nix-cache-info910=== RUN TestIsValidCachePath/index.html911=== PAUSE TestIsValidCachePath/index.html912=== RUN TestIsValidCachePath/traversal_parent913=== PAUSE TestIsValidCachePath/traversal_parent914=== RUN TestIsValidCachePath/traversal_in_middle915=== PAUSE TestIsValidCachePath/traversal_in_middle916=== RUN TestIsValidCachePath/invalid_char_e917=== PAUSE TestIsValidCachePath/invalid_char_e918=== RUN TestIsValidCachePath/invalid_char_u919=== PAUSE TestIsValidCachePath/invalid_char_u920=== RUN TestIsValidCachePath/random_path921=== PAUSE TestIsValidCachePath/random_path922=== RUN TestIsValidCachePath/empty923=== PAUSE TestIsValidCachePath/empty924=== RUN TestIsValidCachePath/leading_slash925=== PAUSE TestIsValidCachePath/leading_slash926=== RUN TestIsValidCachePath/wrong_extension927=== PAUSE TestIsValidCachePath/wrong_extension928=== RUN TestIsValidCachePath/short_hash929=== PAUSE TestIsValidCachePath/short_hash930=== CONT TestIsValidUploadKey931=== RUN TestIsValidUploadKey/narinfo932=== PAUSE TestIsValidUploadKey/narinfo933=== RUN TestIsValidUploadKey/nar_zst934=== PAUSE TestIsValidUploadKey/nar_zst935=== RUN TestIsValidUploadKey/nar_xz936=== PAUSE TestIsValidUploadKey/nar_xz937=== RUN TestIsValidUploadKey/nar_plain938=== PAUSE TestIsValidUploadKey/nar_plain939=== RUN TestIsValidUploadKey/listing940=== PAUSE TestIsValidUploadKey/listing941=== RUN TestIsValidUploadKey/build_log942=== PAUSE TestIsValidUploadKey/build_log943=== RUN TestIsValidUploadKey/build_log_home-manager_file944=== PAUSE TestIsValidUploadKey/build_log_home-manager_file945=== RUN TestIsValidUploadKey/build_log_plus_in_name946=== PAUSE TestIsValidUploadKey/build_log_plus_in_name947=== RUN TestIsValidUploadKey/build_log_question_mark948=== PAUSE TestIsValidUploadKey/build_log_question_mark949=== RUN TestIsValidUploadKey/build_log_equals950=== PAUSE TestIsValidUploadKey/build_log_equals951=== RUN TestIsValidUploadKey/realisation952=== PAUSE TestIsValidUploadKey/realisation953=== RUN TestIsValidUploadKey/realisation_plus_in_output954=== PAUSE TestIsValidUploadKey/realisation_plus_in_output955=== RUN TestIsValidUploadKey/nix-cache-info956=== PAUSE TestIsValidUploadKey/nix-cache-info957=== RUN TestIsValidUploadKey/index.html958=== PAUSE TestIsValidUploadKey/index.html959=== RUN TestIsValidUploadKey/narinfo_key,_nar_type960=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type961=== RUN TestIsValidUploadKey/nar_key,_narinfo_type962=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type963=== RUN TestIsValidUploadKey/listing_key,_narinfo_type964=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type965=== RUN TestIsValidUploadKey/traversal966=== PAUSE TestIsValidUploadKey/traversal967=== RUN TestIsValidUploadKey/traversal_nar968=== PAUSE TestIsValidUploadKey/traversal_nar969=== RUN TestIsValidUploadKey/absolute970=== PAUSE TestIsValidUploadKey/absolute971=== RUN TestIsValidUploadKey/empty_key972=== PAUSE TestIsValidUploadKey/empty_key973=== RUN TestIsValidUploadKey/unknown_type974=== PAUSE TestIsValidUploadKey/unknown_type975=== CONT TestPendingClosureFailureTracksEveryUpload976=== RUN TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false977=== PAUSE TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false978=== RUN TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true979=== PAUSE TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true980=== CONT TestUploadHandlersRejectOversizedBody981--- PASS: TestSkippedUploadsHandler (0.06s)982=== CONT TestMultipartCleanup9832026/10/26 22:36:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37321/oidc9842026/10/26 22:36:39 INFO Received uploads request method=POST path=/api/pending_closures9852026/10/26 22:36:39 INFO Received cleanup request method=DELETE path=/api/pending_closures9862026/10/26 22:36:39 INFO Aborted multipart uploads count=0 kept=09872026/10/26 22:36:39 INFO Received uploads request method=POST path=/api/pending_closures9882026/10/26 22:36:39 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"9892026/10/26 22:36:39 INFO Received cleanup request method=DELETE path=/api/pending_closures9902026/10/26 22:36:39 INFO Aborted multipart uploads count=1 kept=09912026/10/26 22:36:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9922026-10-26 22:36:39.796 UTC [501] ERROR: Closure does not exist: id=19932026-10-26 22:36:39.796 UTC [501] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9942026-10-26 22:36:39.796 UTC [501] STATEMENT: -- name: CommitPendingClosure :one995 SELECT commit_pending_closure($1::bigint)::bigint996 997--- PASS: TestService_AuthMiddleware (0.34s)998=== CONT TestPendingClosureWriteTimeout999=== RUN TestPendingClosureWriteTimeout/empty1000=== PAUSE TestPendingClosureWriteTimeout/empty1001=== RUN TestPendingClosureWriteTimeout/400_objects1002=== PAUSE TestPendingClosureWriteTimeout/400_objects1003=== RUN TestPendingClosureWriteTimeout/670k_objects1004=== PAUSE TestPendingClosureWriteTimeout/670k_objects1005=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1006=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1007=== CONT TestPush_CompleteCommitsEveryRoot1008--- PASS: TestService_cleanupPendingClosuresHandler (0.36s)1009=== CONT TestPush_CompleteWaitsForCleanupOfThePush1010--- PASS: TestReadProxyRangeRequest (0.40s)1011=== CONT TestPush_RepeatedRootCommitsOnce1012=== CONT TestMetricsCommit1013--- PASS: TestReadRedirectUsesPublicS3URL (0.44s)1014=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1015=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1016=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1017=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1018=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1019=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1020=== CONT TestReadProxy404And42910212026/10/26 22:36:40 INFO Received uploads request method=POST path=/api/pending_closures10222026/10/26 22:36:40 INFO Received create pin request method=POST path=/api/pins/app10232026/10/26 22:36:40 INFO Received create pin request method=POST path=/api/pins/app10242026/10/26 22:36:40 INFO Received uploads request method=POST path=/api/pending_closures10252026/10/26 22:36:40 INFO Received uploads request method=POST path=/api/pending_closures10262026/10/26 22:36:40 INFO Received uploads request method=POST path=/api/pending_closures1027=== NAME TestOrphanedObjectsGC1028 orphaned_objects_gc_test.go:287: GC Test Summary:1029 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1030 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1031 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1032 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1033 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects10342026/10/26 22:36:40 INFO Received cleanup request method=DELETE path=/api/pending_closures1035--- PASS: TestOrphanedObjectsGC (0.81s)1036=== CONT TestReadProxyNarinfoAlreadyDecompressed10372026/10/26 22:36:40 INFO Received cleanup request method=DELETE path=/api/pending_closures10382026/10/26 22:36:40 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket10/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""10392026/10/26 22:36:40 INFO Aborted multipart uploads count=0 kept=110402026/10/26 22:36:40 INFO Received cleanup request method=DELETE path=/api/pending_closures10412026/10/26 22:36:40 INFO Aborted multipart uploads count=1 kept=010422026/10/26 22:36:40 INFO Received push request method=POST path=/api/pushes10432026/10/26 22:36:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10442026/10/26 22:36:40 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjA0OTY4M2ExLTk0ODAtNGMxMi04M2UxLTdiMDVlOGM1YzBiZXgxNzkzMDU0MjAwMjYyOTIxNjEw1045--- PASS: TestObjectStatsTrigger (0.85s)1046=== CONT TestReadProxyRootRedirectsToIndexHTML1047=== CONT TestPresentNotReportedWhileGCDeletesClosure1048--- PASS: TestMultipartCleanup (0.79s)1049=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1050=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1051=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1052=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1053=== CONT TestService_readinessHandler10542026/10/26 22:36:40 INFO Received push request method=POST path=/api/pushes10552026/10/26 22:36:40 INFO Received push request method=POST path=/api/pushes10562026/10/26 22:36:40 INFO Received push request method=POST path=/api/pushes10572026/10/26 22:36:40 WARN Failed to abort multipart upload key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjA0OTY4M2ExLTk0ODAtNGMxMi04M2UxLTdiMDVlOGM1YzBiZXgxNzkzMDU0MjAwMjYyOTIxNjEw error="Delete \"http://localhost:37221/bucket15/nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst?uploadId=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjA0OTY4M2ExLTk0ODAtNGMxMi04M2UxLTdiMDVlOGM1YzBiZXgxNzkzMDU0MjAwMjYyOTIxNjEw\": injected: abort refused"10582026/10/26 22:36:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10592026/10/26 22:36:40 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjA0OTY4M2ExLTk0ODAtNGMxMi04M2UxLTdiMDVlOGM1YzBiZXgxNzkzMDU0MjAwMjYyOTIxNjEw10602026/10/26 22:36:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10612026/10/26 22:36:40 ERROR Failed to register completed object error="get pending object \"nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst\": context canceled" object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst10622026/10/26 22:36:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1063--- PASS: TestObjectStatsUpdatedOncePerCommit (0.95s)1064=== CONT TestParseSingleRange1065=== RUN TestParseSingleRange/none1066=== PAUSE TestParseSingleRange/none1067=== RUN TestParseSingleRange/unknown_unit1068=== PAUSE TestParseSingleRange/unknown_unit1069=== RUN TestParseSingleRange/multi-range_ignored1070=== PAUSE TestParseSingleRange/multi-range_ignored1071=== RUN TestParseSingleRange/malformed_no_dash10722026/10/26 22:36:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1073=== PAUSE TestParseSingleRange/malformed_no_dash1074=== RUN TestParseSingleRange/malformed_both_empty1075=== PAUSE TestParseSingleRange/malformed_both_empty1076=== RUN TestParseSingleRange/malformed_end_before_start1077=== PAUSE TestParseSingleRange/malformed_end_before_start1078=== RUN TestParseSingleRange/closed1079=== PAUSE TestParseSingleRange/closed1080=== RUN TestParseSingleRange/open-ended1081=== PAUSE TestParseSingleRange/open-ended1082=== RUN TestParseSingleRange/end_clamped_to_size1083=== PAUSE TestParseSingleRange/end_clamped_to_size1084=== RUN TestParseSingleRange/suffix1085=== PAUSE TestParseSingleRange/suffix1086=== RUN TestParseSingleRange/suffix_exceeds_size1087=== PAUSE TestParseSingleRange/suffix_exceeds_size1088=== RUN TestParseSingleRange/single_byte1089=== PAUSE TestParseSingleRange/single_byte1090=== RUN TestParseSingleRange/start_past_EOF1091=== PAUSE TestParseSingleRange/start_past_EOF1092=== RUN TestParseSingleRange/start_far_past_EOF1093=== PAUSE TestParseSingleRange/start_far_past_EOF1094=== CONT TestConnectSerialisesConcurrentMigrations10952026/10/26 22:36:40 INFO Received uploads request method=POST path=/api/pending_closures10962026/10/26 22:36:40 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified multipart upload does not exist. The upload ID may be invalid, or the upload may have been aborted or completed." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjA0OTY4M2ExLTk0ODAtNGMxMi04M2UxLTdiMDVlOGM1YzBiZXgxNzkzMDU0MjAwMjYyOTIxNjEw10972026/10/26 22:36:40 INFO Signed narinfos id=1 count=110982026/10/26 22:36:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10992026/10/26 22:36:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11002026/10/26 22:36:40 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"11012026/10/26 22:36:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11022026/10/26 22:36:40 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"11032026/10/26 22:36:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11042026/10/26 22:36:40 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjA0OTY4M2ExLTk0ODAtNGMxMi04M2UxLTdiMDVlOGM1YzBiZXgxNzkzMDU0MjAwMjYyOTIxNjEw parts=111052026/10/26 22:36:40 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=111062026/10/26 22:36:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11072026/10/26 22:36:40 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo11082026/10/26 22:36:40 INFO Received uploads request method=POST path=/api/pending_closures11092026/10/26 22:36:40 INFO Received uploads request method=POST path=/api/pending_closures11102026/10/26 22:36:40 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLmRlYjEyMGQ0LWQ1NDUtNDA2NC1hYWI5LTY2OTQ5YmMwOGNmZXgxNzkzMDU0MTk5NzQyNjM1MDIx parts=1211112026/10/26 22:36:40 INFO Received uploads request method=POST path=/api/pending_closures1112--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.98s)1113=== CONT TestGCTaskStore_PhaseUpdates1114--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1115=== CONT TestForceGCDuringPushOffersSweptObject1116=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1117=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1118=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1119=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1120=== CONT TestGetExistingObjectsLocksRows1121--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.99s)1122=== CONT TestLeadIncumbentAnnouncesAtOnce1123--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.02s)1124=== CONT TestService_AuthMiddleware_OIDC1125=== CONT TestClientPushesUseOnePush1126--- PASS: TestService_Rustfstest (1.03s)11272026/10/26 22:36:40 INFO Received push request method=POST path=/api/pushes11282026/10/26 22:36:40 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11292026/10/26 22:36:40 WARN Refused reserved pin name=worker-x86_64-linux11302026-10-26 22:36:40.547 UTC [604] ERROR: relation "goose_db_version" already exists11312026-10-26 22:36:40.547 UTC [604] STATEMENT: CREATE TABLE goose_db_version (1132 id integer PRIMARY KEY GENERATED BY DEFAULT AS IDENTITY,1133 version_id bigint NOT NULL,1134 is_applied boolean NOT NULL,1135 tstamp timestamp NOT NULL DEFAULT now()1136 )11372026/10/26 22:36:40 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11382026/10/26 22:36:40 INFO Received create pin request method=POST path=/api/pins/my-app11392026/10/26 22:36:40 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11402026/10/26 22:36:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1141--- PASS: TestCreatePin_ReservedPins (1.11s)1142=== CONT TestClientWithDependencies11432026/10/26 22:36:40 INFO Received uploads request method=POST path=/api/pending_closures1144--- PASS: TestReconnectLeavesObjectsUnlocked (1.14s)1145=== CONT TestClientFallsBackToClosures11462026/10/26 22:36:40 INFO Received uploads request method=POST path=/api/pending_closures1147--- PASS: TestPendingClosureFailureAbortsItsUploads (1.18s)1148=== CONT TestSweepRechecksPendingAfterLocking11492026/10/26 22:36:40 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst11502026/10/26 22:36:40 INFO Received uploads request method=POST path=/api/pending_closures11512026/10/26 22:36:40 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44549/oidc11522026/10/26 22:36:40 INFO Created/updated pin name=app store_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-app narinfo_key=aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.narinfo11532026/10/26 22:36:40 INFO Received push request method=POST path=/api/pushes11542026/10/26 22:36:40 INFO Created/updated pin name=app store_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-app narinfo_key=bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb.narinfo1155--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.24s)1156=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1157--- PASS: TestConcurrentPinUpdatesAgree (1.28s)1158=== CONT TestUploadHandlersRejectInvalidKeys1159=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1160=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1161=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1162=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1163=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1164=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1165=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1166=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1167=== CONT TestGCTaskStore_CompletedAllowsNewTask1168=== CONT TestPresentRefreshesOnlyStaleClosures1169--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)11702026/10/26 22:36:40 INFO Received create pin request method=POST path=/api/pins/app11712026/10/26 22:36:40 INFO Created/updated pin name=app store_path=/nix/store/cccccccccccccccccccccccccccccccc-app narinfo_key=cccccccccccccccccccccccccccccccc.narinfo11722026/10/26 22:36:40 INFO Received delete pin request method=DELETE path=/api/pins/app11732026/10/26 22:36:40 ERROR Failed to delete pin from S3 key=pins/app error="Get \"http://127.0.0.1:1/bucket30/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"11742026/10/26 22:36:40 INFO Received delete pin request method=DELETE path=/api/pins/app11752026/10/26 22:36:40 INFO Deleted pin name=app1176=== CONT TestPush_RootsAreLockedInByteOrder1177--- PASS: TestDeletePinKeepsRowWhenS3Fails (1.35s)1178--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.55s)1179=== CONT TestPush_RejectsBadRequests11802026/10/26 22:36:40 WARN readiness check failed error="closed pool"11812026/10/26 22:36:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11822026/10/26 22:36:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11832026/10/26 22:36:40 INFO lead: acquired remote=192.0.2.1:123411842026/10/26 22:36:40 INFO lead: released remote=192.0.2.1:12341185=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1186--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.46s)1187=== CONT TestServerTLSConfig1188=== RUN TestServerTLSConfig/no_client_CA1189=== CONT TestService_NativeMTLS1190--- PASS: TestService_readinessHandler (0.60s)1191=== PAUSE TestServerTLSConfig/no_client_CA1192--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.60s)1193=== RUN TestServerTLSConfig/missing_CA_file1194=== PAUSE TestServerTLSConfig/missing_CA_file1195=== RUN TestServerTLSConfig/not_a_PEM_file1196=== PAUSE TestServerTLSConfig/not_a_PEM_file1197=== CONT TestPush_OverlappingRootsStoreOneRowPerKey1198=== CONT TestReadProxyConditionalGet1199--- PASS: TestGetExistingObjectsLocksRows (0.49s)12002026/10/26 22:36:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12012026/10/26 22:36:40 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjQ5YzFiZWYxLThkMmUtNDQxNC1iYmM4LWVhYmE3YmNhZTEwM3gxNzkzMDU0MjAwMzg3NzE3ODQ0 parts=1012022026/10/26 22:36:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12032026/10/26 22:36:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12042026/10/26 22:36:41 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLmFhYzM4NjI4LWViZmUtNDM1Mi04ZGRlLTE2NTM5YjFlOTg0ZngxNzkzMDU0MjAwNDM0MjgwMDg3 parts=1212052026/10/26 22:36:41 INFO Received uploads request method=POST path=/api/pending_closures12062026/10/26 22:36:41 INFO Received uploads request method=POST path=/api/pending_closures12072026/10/26 22:36:41 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLmQ5YTUxYWFhLTAyZjAtNGQzYi04ZGJjLTVhNTc5NjA3ZDQ0OXgxNzkzMDU0MjAwMzE1MTc3OTI1 parts=1012082026/10/26 22:36:41 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjQ3Zjg3Yzk1LTU5OTAtNGFhYS1iNjA0LTQ0ZGFmY2FkMDFjN3gxNzkzMDU0MjAwNTE0NDE2MzU2 parts=1012092026/10/26 22:36:41 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLmY5NWQ2YzI3LWU0ZGItNDg5OS1hODc5LWY5ZjIzMGI3YTcwMHgxNzkzMDU0MjAwMzQyMTc2NzMw parts=1012102026/10/26 22:36:41 WARN Rate limiter enabled after throttle name=s3-test rate=512112026/10/26 22:36:41 WARN S3 rate limit hit during proxy key=4hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo error="Please reduce your request rate."12122026/10/26 22:36:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12132026/10/26 22:36:41 INFO Aborted multipart uploads count=0 kept=012142026/10/26 22:36:41 WARN Force mode enabled - objects will be deleted immediately without grace period1215=== NAME TestClientWithDependencies1216 client_integration_test.go:722: Built derivation: /build/TestClientWithDependencies3153003358/001/store/j9ci7yjnp49azrz27lgh0amdivlf1q21-test-script12172026/10/26 22:36:41 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjk1NzE0OGMzLTVmYWYtNDYwMC1hZmJkLWQ5MDMzOGJkZDg5ZXgxNzkzMDU0MjAwNzIzNTg1MTc3 parts=1012182026/10/26 22:36:41 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12192026/10/26 22:36:41 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12202026/10/26 22:36:41 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=012212026/10/26 22:36:41 INFO Vacuumed table table=pending_closures12222026/10/26 22:36:41 INFO Vacuumed table table=pending_objects12232026/10/26 22:36:41 INFO Vacuumed table table=multipart_uploads12242026/10/26 22:36:41 INFO Vacuumed table table=closures12252026/10/26 22:36:41 INFO Vacuumed table table=objects1226=== CONT TestReadProxyNarinfo1227--- PASS: TestService_NativeMTLS (0.37s)12282026-10-26 22:36:41.290 UTC [665] ERROR: Push does not exist: id=112292026-10-26 22:36:41.290 UTC [665] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE12302026-10-26 22:36:41.290 UTC [665] STATEMENT: SELECT commit_push($1)1231=== CONT TestReadRedirectNar1232--- PASS: TestSweepRechecksPendingAfterLocking (0.66s)1233--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (1.50s)1234=== CONT TestCreatePinRejectsBadInput1235=== NAME TestClientWithDependencies1236 client_integration_test.go:724: Found 1 dependencies (including self)12372026/10/26 22:36:41 INFO Received push request method=POST path=/api/pushes12382026/10/26 22:36:41 WARN Rate limiter backed off name=s3-test rate=512392026/10/26 22:36:41 WARN S3 rate limit hit during proxy key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhh.nar.zst error="Please reduce your request rate."12402026/10/26 22:36:41 INFO Received uploads request method=POST path=/api/pending_closures1241--- PASS: TestReadProxy404And429 (1.42s)1242=== CONT TestMetricsInventory12432026/10/26 22:36:41 INFO Received uploads request method=POST path=/api/pending_closures12442026/10/26 22:36:41 INFO Received push request method=POST path=/api/pushes12452026/10/26 22:36:41 INFO Received push request method=POST path=/api/pushes12462026/10/26 22:36:41 INFO Received uploads request method=POST path=/api/pending_closures12472026/10/26 22:36:41 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)12482026/10/26 22:36:41 INFO Uploading kqamdb0r4xjk8kmxn5rfpx0w7r70vf8s-b (216B)12492026/10/26 22:36:41 INFO Uploading ilk7ij7zrb0mmb3820hx7yxq7w75xxqa-shared-dep (136B)12502026/10/26 22:36:41 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)12512026/10/26 22:36:41 INFO Uploading a0yidk18bkf78420khk727p3v9vnjrzv-shared-dep (136B)12522026/10/26 22:36:41 INFO Uploading zgn9dydfijflpxx7r2bbf9ir9gx0iwyl-a (216B)1253=== CONT TestReadProxyNarStreaming1254--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.51s)12552026/10/26 22:36:41 WARN Failed to register uploaded object key=77s1kay094sv74mav9rlq8zm8nmpglwf.ls error="server returned 404: 404 page not found\n"12562026/10/26 22:36:41 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12572026/10/26 22:36:41 WARN Failed to register uploaded object key=nar/00h5bhy22d50zkh2nqhihmiw6yg10zdcxjczwzw8476dgf4bcq9x.nar.zst error="server returned 404: 404 page not found\n"1258=== RUN TestPush_RejectsBadRequests/no_objects1259=== PAUSE TestPush_RejectsBadRequests/no_objects1260=== RUN TestPush_RejectsBadRequests/bad_root1261=== PAUSE TestPush_RejectsBadRequests/bad_root1262=== RUN TestPush_RejectsBadRequests/root_not_in_objects1263=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects12642026/10/26 22:36:41 WARN Failed to register uploaded object key=snixj5dnwdd8gxk40rfzkh7rx7znfhqv.ls error="server returned 404: 404 page not found\n"1265=== RUN TestPush_RejectsBadRequests/no_roots1266=== PAUSE TestPush_RejectsBadRequests/no_roots1267=== CONT TestReadProxyDisabled12682026/10/26 22:36:41 WARN Failed to register uploaded object key=kqamdb0r4xjk8kmxn5rfpx0w7r70vf8s.ls error="server returned 404: 404 page not found\n"12692026/10/26 22:36:41 WARN Failed to register uploaded object key=ilk7ij7zrb0mmb3820hx7yxq7w75xxqa.ls error="server returned 404: 404 page not found\n"12702026/10/26 22:36:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12712026/10/26 22:36:41 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12722026/10/26 22:36:41 WARN Failed to register uploaded object key=nar/0w6vnrx0f4an8bc5g9zigxnwsgvdnfzm5azrvjbhzswrvn988yw5.nar.zst error="server returned 404: 404 page not found\n"12732026/10/26 22:36:41 WARN Failed to register uploaded object key=a0yidk18bkf78420khk727p3v9vnjrzv.ls error="server returned 404: 404 page not found\n"12742026/10/26 22:36:41 WARN Failed to register uploaded object key=zgn9dydfijflpxx7r2bbf9ir9gx0iwyl.ls error="server returned 404: 404 page not found\n"12752026/10/26 22:36:41 INFO Signed narinfos id=1 count=312762026/10/26 22:36:41 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12772026/10/26 22:36:41 INFO Uploading 3 narinfos1278=== CONT TestNARDeduplicationMetadataUploadBug1279--- PASS: TestReadProxyConditionalGet (0.50s)12802026/10/26 22:36:41 INFO Signed narinfos id=2 count=212812026/10/26 22:36:41 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12822026/10/26 22:36:41 INFO Signed narinfos id=1 count=212832026/10/26 22:36:41 INFO Uploading 4 narinfos12842026/10/26 22:36:41 WARN Failed to register uploaded object key=77s1kay094sv74mav9rlq8zm8nmpglwf.narinfo error="server returned 404: 404 page not found\n"12852026/10/26 22:36:41 WARN Failed to register uploaded object key=a0yidk18bkf78420khk727p3v9vnjrzv.narinfo error="server returned 404: 404 page not found\n"12862026/10/26 22:36:41 INFO Received complete push request method=POST path=/api/pushes/1/complete12872026/10/26 22:36:41 WARN Failed to register uploaded object key=ilk7ij7zrb0mmb3820hx7yxq7w75xxqa.narinfo error="server returned 404: 404 page not found\n"12882026/10/26 22:36:41 WARN Failed to register uploaded object key=kqamdb0r4xjk8kmxn5rfpx0w7r70vf8s.narinfo error="server returned 404: 404 page not found\n"1289--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.54s)1290=== CONT TestCacheConfigHandlerMaxNarSize1291=== CONT TestReadRedirectKeepsNarinfoProxied1292--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)12932026/10/26 22:36:41 WARN Failed to register uploaded object key=snixj5dnwdd8gxk40rfzkh7rx7znfhqv.narinfo error="server returned 404: 404 page not found\n"12942026/10/26 22:36:41 WARN Failed to register uploaded object key=zgn9dydfijflpxx7r2bbf9ir9gx0iwyl.narinfo error="server returned 404: 404 page not found\n"12952026/10/26 22:36:41 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12962026/10/26 22:36:41 WARN Failed to register uploaded object key=a0yidk18bkf78420khk727p3v9vnjrzv.narinfo error="server returned 404: 404 page not found\n"12972026/10/26 22:36:41 INFO Completed push id=1 objects=8 duration=8.135995ms12982026/10/26 22:36:41 INFO Upload complete. (128ms)12992026/10/26 22:36:41 INFO Completed upload id=2 objects=6 duration=7.412648ms13002026/10/26 22:36:41 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1301=== NAME TestClientPushesUseOnePush1302 client_pushes_test.go:97: Retrieved narinfo from S3:1303 StorePath: /build/TestClientPushesUseOnePush1165349482/001/store/ilk7ij7zrb0mmb3820hx7yxq7w75xxqa-shared-dep1304 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1305 Compression: zstd1306 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821307 NarSize: 1361308 References: 1309 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n13102026/10/26 22:36:41 INFO Completed upload id=1 objects=6 duration=2.133459ms13112026/10/26 22:36:41 INFO Upload complete. (133ms)1312=== NAME TestClientFallsBackToClosures1313 client_pushes_test.go:112: Retrieved narinfo from S3:1314 StorePath: /build/TestClientFallsBackToClosures2587048692/001/store/a0yidk18bkf78420khk727p3v9vnjrzv-shared-dep1315 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1316 Compression: zstd1317 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821318 NarSize: 1361319 References: 1320 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1321=== NAME TestClientPushesUseOnePush1322 client_pushes_test.go:97: Retrieved narinfo from S3:1323 StorePath: /build/TestClientPushesUseOnePush1165349482/001/store/77s1kay094sv74mav9rlq8zm8nmpglwf-a1324 URL: nar/00h5bhy22d50zkh2nqhihmiw6yg10zdcxjczwzw8476dgf4bcq9x.nar.zst1325 Compression: zstd1326 NarHash: sha256:00h5bhy22d50zkh2nqhihmiw6yg10zdcxjczwzw8476dgf4bcq9x1327 NarSize: 2161328 References: /build/TestClientPushesUseOnePush1165349482/001/store/ilk7ij7zrb0mmb3820hx7yxq7w75xxqa-shared-dep1329 CA: text:sha256:16r5hnf7mlx801zz330jam01fq2lrwp6067iz28200l9pnjs2nkf1330=== NAME TestClientFallsBackToClosures1331 client_pushes_test.go:112: Retrieved narinfo from S3:1332 StorePath: /build/TestClientFallsBackToClosures2587048692/001/store/zgn9dydfijflpxx7r2bbf9ir9gx0iwyl-a1333 URL: nar/0w6vnrx0f4an8bc5g9zigxnwsgvdnfzm5azrvjbhzswrvn988yw5.nar.zst1334 Compression: zstd1335 NarHash: sha256:0w6vnrx0f4an8bc5g9zigxnwsgvdnfzm5azrvjbhzswrvn988yw51336 NarSize: 2161337 References: /build/TestClientFallsBackToClosures2587048692/001/store/a0yidk18bkf78420khk727p3v9vnjrzv-shared-dep1338 CA: text:sha256:1w0hldhllrraygq1d47lgcdjklxfikjd15qqhj1mxsh3x9ym56p31339=== NAME TestClientPushesUseOnePush1340 client_pushes_test.go:97: Retrieved narinfo from S3:1341 StorePath: /build/TestClientPushesUseOnePush1165349482/001/store/kqamdb0r4xjk8kmxn5rfpx0w7r70vf8s-b1342 URL: nar/00h5bhy22d50zkh2nqhihmiw6yg10zdcxjczwzw8476dgf4bcq9x.nar.zst1343 Compression: zstd1344 NarHash: sha256:00h5bhy22d50zkh2nqhihmiw6yg10zdcxjczwzw8476dgf4bcq9x1345 NarSize: 2161346 References: /build/TestClientPushesUseOnePush1165349482/001/store/ilk7ij7zrb0mmb3820hx7yxq7w75xxqa-shared-dep1347 CA: text:sha256:16r5hnf7mlx801zz330jam01fq2lrwp6067iz28200l9pnjs2nkf1348=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1349=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1350=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1351=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1352=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1353=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1354=== NAME TestClientFallsBackToClosures1355 client_pushes_test.go:112: Retrieved narinfo from S3:1356 StorePath: /build/TestClientFallsBackToClosures2587048692/001/store/snixj5dnwdd8gxk40rfzkh7rx7znfhqv-b1357 URL: nar/0w6vnrx0f4an8bc5g9zigxnwsgvdnfzm5azrvjbhzswrvn988yw5.nar.zst1358 Compression: zstd1359 NarHash: sha256:0w6vnrx0f4an8bc5g9zigxnwsgvdnfzm5azrvjbhzswrvn988yw51360 NarSize: 2161361 References: /build/TestClientFallsBackToClosures2587048692/001/store/a0yidk18bkf78420khk727p3v9vnjrzv-shared-dep1362 CA: text:sha256:1w0hldhllrraygq1d47lgcdjklxfikjd15qqhj1mxsh3x9ym56p31363=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1364=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1365=== CONT TestReadProxyHead1366=== CONT TestCreatePendingClosureRejectsOversizedNAR1367--- PASS: TestPresentRefreshesOnlyStaleClosures (0.75s)13682026/10/26 22:36:41 INFO Received uploads request method=POST path=/api/pending_closures1369--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1370=== CONT TestChildrenInheritRaisedFileLimit1371--- PASS: TestChildrenInheritRaisedFileLimit (0.00s)1372=== CONT TestReadProxyContentNegotiation1373--- PASS: TestClientPushesUseOnePush (1.03s)1374=== CONT TestGCAdvisoryLockBlocksConcurrentRun1375--- PASS: TestClientFallsBackToClosures (0.92s)1376=== CONT TestPresentReportsOnlyClosureRoots1377=== CONT TestReadProxyInvalidPath1378--- PASS: TestConnectSerialisesConcurrentMigrations (1.16s)13792026/10/26 22:36:41 INFO Received create pin request method=POST path=/api/pins/deploy13802026/10/26 22:36:41 INFO Received create pin request method=POST path=/api/pins/deploy13812026/10/26 22:36:41 INFO Received create pin request method=POST path=/api/pins/deploy13822026/10/26 22:36:41 INFO Received create pin request method=POST path=/api/pins/deploy13832026/10/26 22:36:41 INFO Received create pin request method=POST path=/api/pins/deploy13842026/10/26 22:36:41 INFO Received create pin request method=POST path=/api/pins/deploy13852026/10/26 22:36:41 INFO Received create pin request method=POST path=/api/pins/deploy13862026/10/26 22:36:41 INFO Received create pin request method=POST path=/api/pins/deploy1387--- PASS: TestReadRedirectNar (0.35s)1388=== CONT TestClientMultipleUploads13892026/10/26 22:36:41 INFO Received create pin request method=POST path=/api/pins/deploy13902026/10/26 22:36:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13912026/10/26 22:36:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13922026/10/26 22:36:41 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjI5ZTcyYWY3LWMxZGUtNDczMi04MDc0LTJmMTc5YmExMzBiNXgxNzkzMDU0MjAwMzE0NzcwMjYx parts=1013932026/10/26 22:36:41 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLmIwYTFhNzAxLTI3YTEtNDU1Mi04ZTVlLWU4NmRmNjI5NzQwNHgxNzkzMDU0MjAwNTE0ODI5Njk5 parts=1013942026/10/26 22:36:41 INFO Received complete push request method=POST path=/api/pushes/1/complete13952026/10/26 22:36:41 INFO Completed push id=1 objects=4 duration=8.656239ms13962026/10/26 22:36:41 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13972026/10/26 22:36:41 INFO Completed upload id=2 objects=2 duration=2.805806ms13982026/10/26 22:36:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13992026/10/26 22:36:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14002026/10/26 22:36:41 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLmFmMjg5M2U2LWFlN2EtNDAwMi1iN2Q2LTIzNGJmZDAwM2QxM3gxNzkzMDU0MjAwMzQyNjczNzc1 parts=1014012026/10/26 22:36:41 INFO Received complete push request method=POST path=/api/pushes/1/complete14022026/10/26 22:36:41 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLmI0MTcyZjlkLTEyMzctNDdhYS1hZDMwLTNkMjZhZDA1MmEwNXgxNzkzMDU0MjAxMTE5Njk3MDc3 error="Get \"http://127.0.0.1:1/bucket21/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"14032026/10/26 22:36:41 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjJhODIxNDQ0LTYwMmQtNDhkNy1iNzMyLWJkYzEzYTIxZTdjZHgxNzkzMDU0MjAxMDk5NDMwMDEz parts=1214042026/10/26 22:36:41 INFO Received cleanup request method=DELETE path=/api/pending_closures14052026/10/26 22:36:41 INFO Completed push id=1 objects=4 duration=7.043024ms14062026/10/26 22:36:41 INFO Aborted multipart uploads count=1 kept=01407--- PASS: TestPush_RepeatedRootCommitsOnce (1.93s)1408=== CONT TestCompleteMultipartUnregistered1409--- PASS: TestMetricsCommit (1.91s)1410=== CONT TestLeadEndsOnShutdown1411=== CONT TestService_healthCheckHandler1412--- PASS: TestRedundantMultipartUpload (2.33s)1413--- PASS: TestPresentReportsOnlyClosureRoots (0.30s)1414=== CONT TestGCBugBareHashReferences14152026/10/26 22:36:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1416--- PASS: TestReadProxyInvalidPath (0.27s)1417=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT14182026/10/26 22:36:41 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjJmMzZkNWU1LWE4MWItNDQ5Ni1iNmU0LWQ1OTc5M2FiNGEzM3gxNzkzMDU0MjAwNzI0Mzk1MTI0 parts=1014192026/10/26 22:36:41 INFO Received complete push request method=POST path=/api/pushes/1/complete14202026/10/26 22:36:41 INFO Completed push id=1 objects=4 duration=9.647628ms14212026/10/26 22:36:41 INFO Received push request method=POST path=/api/pushes14222026/10/26 22:36:41 INFO Received push request method=POST path=/api/pushes14232026/10/26 22:36:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14242026/10/26 22:36:41 INFO Uploading j9ci7yjnp49azrz27lgh0amdivlf1q21-test-script (136B)14252026/10/26 22:36:41 WARN Failed to register uploaded object key=log/0qscp4mn3spp19cxxa5m65dikzz10wwr-test-script.drv error="server returned 404: 404 page not found\n"14262026/10/26 22:36:41 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"14272026/10/26 22:36:41 WARN Failed to register uploaded object key=j9ci7yjnp49azrz27lgh0amdivlf1q21.ls error="server returned 404: 404 page not found\n"14282026/10/26 22:36:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14292026/10/26 22:36:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14302026/10/26 22:36:41 INFO Signed narinfos id=1 count=114312026/10/26 22:36:41 INFO Uploading 1 narinfos14322026/10/26 22:36:41 INFO Aborted multipart uploads count=0 kept=014332026/10/26 22:36:41 INFO Received complete push request method=POST path=/api/pushes/1/complete14342026/10/26 22:36:41 WARN Failed to register uploaded object key=j9ci7yjnp49azrz27lgh0amdivlf1q21.narinfo error="server returned 404: 404 page not found\n"14352026/10/26 22:36:41 WARN Force mode enabled - objects will be deleted immediately without grace period14362026/10/26 22:36:41 INFO Completed push id=1 objects=4 duration=9.785929ms14372026/10/26 22:36:41 INFO Upload complete. (551ms)14382026/10/26 22:36:41 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLmExZmQ2MzJjLWUzYTYtNGE4MC05MDY5LWMyNjg4MDc2YzIzNHgxNzkzMDU0MjAxMzQ0OTI4NjA0 parts=101439=== NAME TestClientMultipleUploads1440 client_integration_test.go:467: Created store path 0: /build/TestClientMultipleUploads2618902246/001/store/hpcifzls0kd9bghn4mnmf5frh8p2v3jk-test-file-0.txt1441--- PASS: TestReadProxyDisabled (0.56s)1442=== CONT TestLeadElectsOneAndHandsOver14432026/10/26 22:36:41 INFO Aborted multipart uploads count=0 kept=014442026/10/26 22:36:42 WARN Force mode enabled - objects will be deleted immediately without grace period1445=== NAME TestClientMultipleUploads1446 client_integration_test.go:467: Created store path 1: /build/TestClientMultipleUploads2618902246/001/store/dzv2m7q6b73wh21rga5mwz8rhdsjd8s6-test-file-1.txt14472026/10/26 22:36:42 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014482026/10/26 22:36:42 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=014492026/10/26 22:36:42 INFO Vacuumed table table=pending_closures14502026/10/26 22:36:42 INFO Vacuumed table table=pending_closures14512026/10/26 22:36:42 INFO Vacuumed table table=pending_objects14522026/10/26 22:36:42 INFO Vacuumed table table=pending_objects14532026/10/26 22:36:42 INFO Vacuumed table table=multipart_uploads14542026/10/26 22:36:42 INFO Vacuumed table table=multipart_uploads14552026/10/26 22:36:42 INFO Vacuumed table table=closures14562026/10/26 22:36:42 INFO Vacuumed table table=closures14572026/10/26 22:36:42 INFO Vacuumed table table=objects14582026/10/26 22:36:42 INFO Vacuumed table table=objects1459=== NAME TestClientWithDependencies1460 client_integration_test.go:740: Skipping nix copy test - isolated store (/build/TestClientWithDependencies3153003358/001/store) requires matching store prefix1461=== CONT TestService_verifyS3Integrity1462--- PASS: TestClientWithDependencies (1.50s)1463=== NAME TestClientMultipleUploads1464 client_integration_test.go:467: Created store path 2: /build/TestClientMultipleUploads2618902246/001/store/qf7kymyi082x8dcjhxjx0z6kf0jkbvp8-test-file-2.txt1465--- PASS: TestMetricsInventory (0.72s)1466=== CONT TestClientIntegration14672026/10/26 22:36:42 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"1468--- PASS: TestReadProxyNarStreaming (0.71s)1469=== CONT TestGCEndsOnShutdown1470=== RUN TestGCEndsOnShutdown/before_the_run1471=== PAUSE TestGCEndsOnShutdown/before_the_run1472=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1473=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1474=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1475=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1476--- PASS: TestReadProxyHead (0.64s)1477=== CONT TestClientCADerivations1478=== CONT TestGenerateLandingPage1479--- PASS: TestGenerateLandingPage (0.01s)1480=== CONT TestService_createPendingClosureHandler1481--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.64s)1482=== CONT TestGracefulShutdownDrainsInflight14832026/10/26 22:36:42 INFO Starting HTTP server address=127.0.0.1:4269714842026/10/26 22:36:42 INFO Shutdown signal received, draining in-flight requests timeout=10s1485--- PASS: TestService_healthCheckHandler (0.40s)1486=== CONT TestGCTaskStore_Fail1487--- PASS: TestGCTaskStore_Fail (0.00s)1488=== CONT TestFailedS3DeleteKeepsTombstone14892026/10/26 22:36:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14902026/10/26 22:36:42 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1491=== CONT TestGCSweepDeliversEachKeyOnce1492--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1493--- PASS: TestCompleteMultipartUnregistered (0.45s)1494=== CONT TestSweepSkipsRowsLockedByPush14952026/10/26 22:36:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14962026/10/26 22:36:42 INFO lead: acquired remote=192.0.2.1:123414972026/10/26 22:36:42 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjg0OWI4ZGY3LTU4OWUtNGZlNS1hNDdiLWJmNjViOTc4NzliYngxNzkzMDU0MjAwMzE1MzgwNTI3 parts=1014982026/10/26 22:36:42 INFO Received complete push request method=POST path=/api/pushes/1/complete14992026/10/26 22:36:42 INFO Received uploads request method=POST path=/api/pending_closures15002026/10/26 22:36:42 INFO Completed push id=1 objects=6 duration=10.473435ms1501=== CONT TestReadProxyOutlastsServerWriteTimeout1502--- PASS: TestReadRedirectKeepsNarinfoProxied (0.87s)15032026/10/26 22:36:42 INFO lead: acquired remote=192.0.2.1:12341504--- PASS: TestPush_CompleteCommitsEveryRoot (2.56s)1505=== CONT TestService_AuthMiddleware_MTLSProxyHeader1506=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1507--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.53s)1508--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (1.73s)1509=== CONT TestRegisterCompletedObjectNeedsPendingRow15102026/10/26 22:36:42 INFO Received uploads request method=POST path=/api/pending_closures15112026/10/26 22:36:42 INFO Received uploads request method=POST path=/api/pending_closures15122026/10/26 22:36:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15132026/10/26 22:36:42 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjkxMzMyNzVkLTYzMjAtNDcxMS05M2UxLTBjMTFiYTRkNzM0N3gxNzkzMDU0MjAxMzQzMzMwNTkw parts=101514=== CONT TestService_ReadAuthMiddleware1515--- PASS: TestGCBugBareHashReferences (0.70s)15162026/10/26 22:36:42 INFO Received push request method=POST path=/api/pushes15172026/10/26 22:36:42 INFO Aborted multipart uploads count=0 kept=015182026/10/26 22:36:42 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)15192026/10/26 22:36:42 INFO Uploading hpcifzls0kd9bghn4mnmf5frh8p2v3jk-test-file-0.txt (160B)15202026/10/26 22:36:42 INFO Uploading qf7kymyi082x8dcjhxjx0z6kf0jkbvp8-test-file-2.txt (160B)15212026/10/26 22:36:42 INFO Uploading dzv2m7q6b73wh21rga5mwz8rhdsjd8s6-test-file-1.txt (160B)15222026/10/26 22:36:42 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"15232026/10/26 22:36:42 WARN Force mode enabled - objects will be deleted immediately without grace period15242026/10/26 22:36:42 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"15252026/10/26 22:36:42 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"15262026/10/26 22:36:42 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=015272026/10/26 22:36:42 WARN Failed to register uploaded object key=hpcifzls0kd9bghn4mnmf5frh8p2v3jk.ls error="server returned 404: 404 page not found\n"15282026/10/26 22:36:42 WARN Failed to register uploaded object key=dzv2m7q6b73wh21rga5mwz8rhdsjd8s6.ls error="server returned 404: 404 page not found\n"15292026/10/26 22:36:42 WARN Failed to register uploaded object key=qf7kymyi082x8dcjhxjx0z6kf0jkbvp8.ls error="server returned 404: 404 page not found\n"15302026/10/26 22:36:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15312026/10/26 22:36:42 INFO Aborted multipart uploads count=0 kept=015322026/10/26 22:36:42 INFO Vacuumed table table=pending_closures15332026/10/26 22:36:42 INFO Vacuumed table table=pending_objects15342026/10/26 22:36:42 INFO Vacuumed table table=multipart_uploads15352026/10/26 22:36:42 INFO Aborted multipart uploads count=0 kept=015362026/10/26 22:36:42 INFO Signed narinfos id=1 count=315372026/10/26 22:36:42 INFO Vacuumed table table=closures15382026/10/26 22:36:42 INFO Uploading 3 narinfos15392026/10/26 22:36:42 INFO Vacuumed table table=objects15402026/10/26 22:36:42 WARN Force mode enabled - objects will be deleted immediately without grace period15412026/10/26 22:36:42 INFO Aborted multipart uploads count=0 kept=015422026/10/26 22:36:42 WARN Force mode enabled - objects will be deleted immediately without grace period15432026/10/26 22:36:42 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>15442026/10/26 22:36:42 WARN Failed to register uploaded object key=dzv2m7q6b73wh21rga5mwz8rhdsjd8s6.narinfo error="server returned 404: 404 page not found\n"15452026/10/26 22:36:42 INFO Received complete push request method=POST path=/api/pushes/1/complete15462026/10/26 22:36:42 WARN Failed to register uploaded object key=qf7kymyi082x8dcjhxjx0z6kf0jkbvp8.narinfo error="server returned 404: 404 page not found\n"15472026/10/26 22:36:42 WARN Force mode enabled - objects will be deleted immediately without grace period15482026/10/26 22:36:42 WARN Failed to register uploaded object key=hpcifzls0kd9bghn4mnmf5frh8p2v3jk.narinfo error="server returned 404: 404 page not found\n"15492026/10/26 22:36:42 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."15502026/10/26 22:36:42 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."15512026/10/26 22:36:42 INFO Completed push id=1 objects=9 duration=7.237326ms15522026/10/26 22:36:42 INFO Upload complete. (502ms)1553=== NAME TestClientMultipleUploads1554 client_integration_test.go:478: Uploaded 3 paths in 579.297966ms15552026/10/26 22:36:42 INFO Received uploads request method=POST path=/api/pending_closures15562026/10/26 22:36:42 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=015572026/10/26 22:36:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15582026/10/26 22:36:42 INFO Vacuumed table table=pending_closures15592026/10/26 22:36:42 INFO Vacuumed table table=pending_objects1560--- PASS: TestReadProxyNarinfo (1.38s)15612026/10/26 22:36:42 INFO Vacuumed table table=multipart_uploads1562=== CONT TestGCTaskStore_StartNew1563=== CONT TestGCTaskStore_GetReturnsLatest1564--- PASS: TestGCTaskStore_StartNew (0.00s)1565=== CONT TestGCSweepSkipsPendingObjects15662026/10/26 22:36:42 INFO Vacuumed table table=closures1567--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)15682026/10/26 22:36:42 INFO Vacuumed table table=objects15692026/10/26 22:36:42 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=01570--- PASS: TestFailedS3DeleteKeepsTombstone (0.47s)1571=== CONT TestTombstonedObjectOfferedWithoutWaiting15722026/10/26 22:36:42 INFO Vacuumed table table=pending_closures15732026/10/26 22:36:42 INFO Vacuumed table table=pending_objects15742026/10/26 22:36:42 INFO Vacuumed table table=multipart_uploads15752026/10/26 22:36:42 INFO Vacuumed table table=closures15762026/10/26 22:36:42 INFO Vacuumed table table=objects15772026/10/26 22:36:42 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLmFjMjBlMmIxLTVlOTItNDFhYi1iMTQ0LWY5NzFkMzk1MzgxZHgxNzkzMDU0MjAxODg5NDM3NTU0 parts=1015782026/10/26 22:36:42 INFO Received complete push request method=POST path=/api/pushes/2/complete1579=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1580--- PASS: TestReadProxyContentNegotiation (1.18s)15812026/10/26 22:36:42 INFO Completed push id=2 objects=4 duration=3.539612ms1582--- PASS: TestGCSweepDeliversEachKeyOnce (0.45s)1583=== CONT TestGCTaskStore_ConflictDifferentParams1584--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1585=== CONT TestGCTaskStore_DeduplicateSameParams1586--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1587=== CONT TestDeduplicatedObjectsRecordedAsPending1588--- PASS: TestSweepSkipsRowsLockedByPush (0.46s)1589=== CONT TestCommitRacingPendingCleanupKeepsObjects1590=== CONT TestGCTaskStore_GetEmpty1591--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.33s)1592=== CONT TestDeleteClosuresRacingPins1593--- PASS: TestGCTaskStore_GetEmpty (0.00s)1594--- PASS: TestClientMultipleUploads (1.04s)1595=== CONT TestGCMetrics1596=== CONT TestConnectWaitsForAPeerMigration1597--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (3.23s)1598=== NAME TestOrphanedObjectsGCStressTest1599 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains16002026/10/26 22:36:42 INFO Received create pin request method=POST path=/api/pins/deploy16012026/10/26 22:36:42 INFO Received uploads request method=POST path=/api/pending_closures16022026/10/26 22:36:42 INFO Received uploads request method=POST path=/api/pending_closures16032026/10/26 22:36:42 INFO Received uploads request method=POST path=/api/pending_closures16042026/10/26 22:36:42 INFO Created/updated pin name=deploy store_path="/nix/store/dddddddddddddddddddddddddddddddd-app-1.0+git_x?y=z" narinfo_key=dddddddddddddddddddddddddddddddd.narinfo1605=== NAME TestClientIntegration1606 client_integration_test.go:331: Created store path: /build/TestClientIntegration1293881247/002/store/ih1i5c1bkb2i3w013l6r38c3q2vpp4wp-test-file.txt1607=== CONT TestResolveDBConnectionString1608--- PASS: TestCreatePinRejectsBadInput (1.46s)1609=== RUN TestResolveDBConnectionString/flag_wins1610=== PAUSE TestResolveDBConnectionString/flag_wins1611=== RUN TestResolveDBConnectionString/file_when_flag_empty1612=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1613=== RUN TestResolveDBConnectionString/missing_file_is_an_error1614=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1615=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1616=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1617=== RUN TestResolveDBConnectionString/nothing_configured1618=== PAUSE TestResolveDBConnectionString/nothing_configured1619=== CONT TestPushDedupSurvivesConcurrentGC1620=== NAME TestOrphanedObjectsGCStressTest1621 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion1622=== CONT TestPinProtectsFromGC1623--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.36s)1624=== NAME TestNARDeduplicationMetadataUploadBug1625 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug854439436/001/store/24hfxbf6grch6w59csip2408s8hj65nh-file1.txt1626--- PASS: TestService_ReadAuthMiddleware (0.35s)1627=== CONT TestClientSharedPathCommittedMidPush16282026/10/26 22:36:42 INFO Received uploads request method=POST path=/api/pending_closures1629=== CONT TestClientErrorHandling1630=== RUN TestClientErrorHandling/InvalidStorePath1631--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.52s)1632=== PAUSE TestClientErrorHandling/InvalidStorePath1633=== RUN TestClientErrorHandling/InvalidAuthToken1634=== PAUSE TestClientErrorHandling/InvalidAuthToken1635=== RUN TestClientErrorHandling/ServerNotAvailable1636=== PAUSE TestClientErrorHandling/ServerNotAvailable1637=== CONT TestPushWaitsForSweepHoldingRow16382026/10/26 22:36:42 INFO Received uploads request method=POST path=/api/pending_closures16392026/10/26 22:36:42 INFO Aborted multipart uploads count=0 kept=016402026/10/26 22:36:42 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"16412026/10/26 22:36:42 WARN mTLS auth: bound subjects configured but subject DN unavailable16422026/10/26 22:36:42 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1643--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.28s)1644=== CONT TestService_ReadScope_PublicByDefault1645--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.29s)1646=== CONT TestCacheConfigHandler1647=== RUN TestCacheConfigHandler/full_config,_no_issuer1648=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1649=== RUN TestCacheConfigHandler/no_cache_url_configured1650=== PAUSE TestCacheConfigHandler/no_cache_url_configured1651=== RUN TestCacheConfigHandler/no_signing_keys1652=== PAUSE TestCacheConfigHandler/no_signing_keys1653=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1654=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1655=== CONT TestService_RequireScope_OIDC16562026/10/26 22:36:42 INFO Received uploads request method=POST path=/api/pending_closures1657--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.32s)1658=== CONT TestCacheStatsHandler16592026/10/26 22:36:43 INFO Aborted multipart uploads count=0 kept=016602026/10/26 22:36:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16612026/10/26 22:36:43 INFO Aborted multipart uploads count=0 kept=016622026/10/26 22:36:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16632026/10/26 22:36:43 INFO Completed multipart upload object_key=nar/ffffffffffffffffffffffffffffffff00000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjYwZGYxZDk0LTIxY2QtNDIxNy05Y2U0LTE5OTM0YTBhZDA5Y3gxNzkzMDU0MjAxMzQzMjMyMDg5 parts=1016642026/10/26 22:36:43 WARN Force mode enabled - objects will be deleted immediately without grace period16652026/10/26 22:36:43 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjUyY2Y0YTk4LTk1MjUtNGRiOS04NjRmLWUwNzQ5OTk3OGFkOXgxNzkzMDU0MjAyNDc4NzUzMDUw parts=1016662026/10/26 22:36:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16672026/10/26 22:36:43 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=016682026/10/26 22:36:43 INFO Vacuumed table table=pending_closures16692026/10/26 22:36:43 INFO Completed upload id=1 objects=2 duration=3.665593ms16702026/10/26 22:36:43 INFO Vacuumed table table=pending_objects16712026/10/26 22:36:43 INFO Vacuumed table table=multipart_uploads16722026/10/26 22:36:43 INFO Vacuumed table table=closures16732026/10/26 22:36:43 INFO Vacuumed table table=objects16742026/10/26 22:36:43 INFO Received uploads request method=POST path=/api/pending_closures16752026/10/26 22:36:43 INFO Received uploads request method=POST path=/api/pending_closures16762026/10/26 22:36:43 WARN Force mode enabled - objects will be deleted immediately without grace period16772026/10/26 22:36:43 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=016782026/10/26 22:36:43 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo16792026/10/26 22:36:43 WARN Found objects in DB but missing from S3, will re-upload count=116802026/10/26 22:36:43 INFO Vacuumed table table=pending_closures16812026/10/26 22:36:43 INFO Vacuumed table table=pending_objects16822026/10/26 22:36:43 INFO Vacuumed table table=multipart_uploads16832026/10/26 22:36:43 INFO Vacuumed table table=closures16842026/10/26 22:36:43 INFO Vacuumed table table=objects16852026/10/26 22:36:43 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete16862026/10/26 22:36:43 INFO Completed upload id=3 objects=2 duration=1.623315ms1687--- PASS: TestGCMetrics (0.49s)1688=== CONT TestProxyWriteTimeout/1_GiB_nar1689=== CONT TestProxyWriteTimeout/10_GiB_nar1690=== CONT TestProxyWriteTimeout/unknown_size1691=== CONT TestProxyWriteTimeout/narinfo1692=== CONT TestIsValidCachePath/narinfo1693--- PASS: TestProxyWriteTimeout (0.02s)1694 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1695 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1696 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1697 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1698=== CONT TestIsValidCachePath/short_hash1699=== CONT TestIsValidCachePath/wrong_extension1700=== CONT TestIsValidCachePath/realisation1701=== CONT TestIsValidCachePath/leading_slash1702=== CONT TestIsValidCachePath/traversal_in_middle1703=== CONT TestIsValidCachePath/traversal_parent1704=== CONT TestIsValidCachePath/index.html1705=== CONT TestIsValidCachePath/invalid_char_e1706=== CONT TestIsValidCachePath/empty1707=== CONT TestIsValidCachePath/invalid_char_u1708=== CONT TestIsValidCachePath/random_path1709=== CONT TestIsValidCachePath/nar_bz21710=== CONT TestIsValidCachePath/ls1711=== CONT TestIsValidCachePath/nar_xz1712=== CONT TestIsValidCachePath/log1713=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1714=== CONT TestIsValidCachePath/nar_zst1715=== CONT TestIsValidCachePath/nar_uncompressed1716=== CONT TestIsValidCachePath/nix-cache-info1717=== CONT TestIsValidUploadKey/nar_zst1718--- PASS: TestIsValidCachePath (0.00s)1719 --- PASS: TestIsValidCachePath/narinfo (0.00s)1720 --- PASS: TestIsValidCachePath/short_hash (0.00s)1721 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1722 --- PASS: TestIsValidCachePath/realisation (0.00s)1723 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1724 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1725 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1726 --- PASS: TestIsValidCachePath/index.html (0.00s)1727 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1728 --- PASS: TestIsValidCachePath/empty (0.00s)1729 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1730 --- PASS: TestIsValidCachePath/random_path (0.00s)1731 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1732 --- PASS: TestIsValidCachePath/ls (0.00s)1733 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1734 --- PASS: TestIsValidCachePath/log (0.00s)1735 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1736 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1737 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1738 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1739=== CONT TestIsValidUploadKey/unknown_type1740=== CONT TestIsValidUploadKey/empty_key1741=== CONT TestIsValidUploadKey/traversal_nar1742=== CONT TestIsValidUploadKey/absolute1743=== CONT TestIsValidUploadKey/build_log_question_mark1744=== CONT TestIsValidUploadKey/build_log_home-manager_file1745=== CONT TestIsValidUploadKey/build_log_plus_in_name1746=== CONT TestIsValidUploadKey/build_log1747=== CONT TestIsValidUploadKey/nar_plain1748=== CONT TestIsValidUploadKey/listing1749=== CONT TestIsValidUploadKey/nix-cache-info1750=== CONT TestIsValidUploadKey/nar_xz1751=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1752=== CONT TestIsValidUploadKey/narinfo1753=== CONT TestIsValidUploadKey/traversal1754=== CONT TestIsValidUploadKey/index.html1755=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1756=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1757=== CONT TestIsValidUploadKey/build_log_equals1758=== CONT TestIsValidUploadKey/realisation_plus_in_output1759=== CONT TestIsValidUploadKey/realisation1760=== CONT TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true1761--- PASS: TestIsValidUploadKey (0.00s)1762 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1763 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1764 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1765 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1766 --- PASS: TestIsValidUploadKey/absolute (0.00s)1767 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1768 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1769 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1770 --- PASS: TestIsValidUploadKey/build_log (0.00s)1771 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1772 --- PASS: TestIsValidUploadKey/listing (0.00s)1773 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1774 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1775 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1776 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1777 --- PASS: TestIsValidUploadKey/traversal (0.00s)1778 --- PASS: TestIsValidUploadKey/index.html (0.00s)1779 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1780 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1781 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1782 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1783 --- PASS: TestIsValidUploadKey/realisation (0.00s)1784--- PASS: TestService_verifyS3Integrity (1.13s)1785=== CONT TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false1786--- PASS: TestService_ReadScope_PublicByDefault (0.25s)1787=== CONT TestPendingClosureWriteTimeout/670k_objects1788=== CONT TestPendingClosureWriteTimeout/400_objects1789=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1790--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.53s)1791=== CONT TestPendingClosureWriteTimeout/empty1792=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17932026/10/26 22:36:43 INFO Received request for more parts method=POST path=/1794=== NAME TestClientCADerivations1795 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations2878443604/001/store/jwysyjn1azmmf5brchkqb6fqsb965n69-ca-test17962026/10/26 22:36:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1797 client_ca_test.go:139: Found 1 dependencies (including self)1798=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart1799--- PASS: TestCacheStatsHandler (0.28s)18002026/10/26 22:36:43 INFO Received complete multipart upload request method=POST path=/18012026/10/26 22:36:43 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjRlYmZlMzdlLWUxODgtNDU5YS1iYzEyLTlhYWViMGJlMGQ4MXgxNzkzMDU0MjAyNzQ2NzIyMTQ2 parts=1018022026/10/26 22:36:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18032026/10/26 22:36:43 INFO Completed upload id=1 objects=2 duration=3.641973ms18042026/10/26 22:36:43 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000018052026/10/26 22:36:43 INFO Received uploads request method=POST path=/api/pending_closures18062026/10/26 22:36:43 INFO Starting cleanup of old closures method=DELETE path=/api/closures18072026/10/26 22:36:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46295/oidc18082026/10/26 22:36:43 INFO Aborted multipart uploads count=0 kept=018092026/10/26 22:36:43 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=018102026/10/26 22:36:43 INFO Vacuumed table table=pending_closures18112026/10/26 22:36:43 INFO Vacuumed table table=pending_objects18122026/10/26 22:36:43 INFO Vacuumed table table=multipart_uploads18132026/10/26 22:36:43 INFO Vacuumed table table=closures18142026/10/26 22:36:43 INFO Vacuumed table table=objects18152026/10/26 22:36:43 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000018162026/10/26 22:36:43 WARN Force mode enabled - objects will be deleted immediately without grace period18172026/10/26 22:36:43 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=018182026/10/26 22:36:43 INFO Received push request method=POST path=/api/pushes18192026/10/26 22:36:43 INFO lead: released remote=192.0.2.1:123418202026/10/26 22:36:43 INFO Vacuumed table table=pending_closures18212026/10/26 22:36:43 INFO Vacuumed table table=pending_objects18222026/10/26 22:36:43 INFO Vacuumed table table=multipart_uploads18232026/10/26 22:36:43 INFO Vacuumed table table=closures18242026/10/26 22:36:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18252026/10/26 22:36:43 INFO Uploading ih1i5c1bkb2i3w013l6r38c3q2vpp4wp-test-file.txt (152B)18262026/10/26 22:36:43 INFO Vacuumed table table=objects1827--- PASS: TestService_createPendingClosureHandler (1.24s)1828=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18292026/10/26 22:36:43 INFO Received uploads request method=POST path=/18302026/10/26 22:36:43 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"18312026/10/26 22:36:43 WARN Failed to register uploaded object key=ih1i5c1bkb2i3w013l6r38c3q2vpp4wp.ls error="server returned 404: 404 page not found\n"1832=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh18332026/10/26 22:36:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1834--- PASS: TestLeadEndsOnShutdown (1.60s)18352026/10/26 22:36:43 INFO Signed narinfos id=1 count=118362026/10/26 22:36:43 INFO Uploading 1 narinfos1837--- PASS: TestGCSweepSkipsPendingObjects (0.74s)1838=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale18392026/10/26 22:36:43 INFO Received complete push request method=POST path=/api/pushes/1/complete18402026/10/26 22:36:43 WARN Failed to register uploaded object key=ih1i5c1bkb2i3w013l6r38c3q2vpp4wp.narinfo error="server returned 404: 404 page not found\n"18412026/10/26 22:36:43 INFO Received push request method=POST path=/api/pushes18422026/10/26 22:36:43 INFO Completed push id=1 objects=3 duration=11.860088ms18432026/10/26 22:36:43 INFO Upload complete. (583ms)18442026/10/26 22:36:43 INFO Received push request method=POST path=/api/pushes18452026/10/26 22:36:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18462026/10/26 22:36:43 INFO Uploading 24hfxbf6grch6w59csip2408s8hj65nh-file1.txt (160B)18472026/10/26 22:36:43 INFO Received uploads request method=POST path=/api/pending_closures18482026/10/26 22:36:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18492026/10/26 22:36:43 INFO Uploading jwysyjn1azmmf5brchkqb6fqsb965n69-ca-test (144B)18502026/10/26 22:36:43 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"18512026/10/26 22:36:43 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18522026/10/26 22:36:43 WARN Failed to register uploaded object key=log/zva42vs8yv8wd109mszbyd07zi1vmh15-ca-test.drv error="server returned 404: 404 page not found\n"18532026/10/26 22:36:43 WARN Failed to register uploaded object key=24hfxbf6grch6w59csip2408s8hj65nh.ls error="server returned 404: 404 page not found\n"18542026/10/26 22:36:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18552026/10/26 22:36:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18562026/10/26 22:36:43 WARN Failed to register uploaded object key=jwysyjn1azmmf5brchkqb6fqsb965n69.ls error="server returned 404: 404 page not found\n"18572026/10/26 22:36:43 INFO Signed narinfos id=1 count=118582026/10/26 22:36:43 INFO Signed narinfos id=1 count=118592026/10/26 22:36:43 INFO Uploading 1 narinfos18602026/10/26 22:36:43 INFO Uploading 1 narinfos18612026/10/26 22:36:43 INFO Received uploads request method=POST path=/api/pending_closures18622026/10/26 22:36:43 INFO Received complete push request method=POST path=/api/pushes/1/complete18632026/10/26 22:36:43 INFO Received complete push request method=POST path=/api/pushes/1/complete18642026/10/26 22:36:43 WARN Failed to register uploaded object key=jwysyjn1azmmf5brchkqb6fqsb965n69.narinfo error="server returned 404: 404 page not found\n"18652026/10/26 22:36:43 WARN Failed to register uploaded object key=24hfxbf6grch6w59csip2408s8hj65nh.narinfo error="server returned 404: 404 page not found\n"18662026/10/26 22:36:43 INFO Completed push id=1 objects=4 duration=6.982343ms18672026/10/26 22:36:43 INFO Upload complete. (134ms)18682026/10/26 22:36:43 INFO Completed push id=1 objects=3 duration=7.789231ms18692026/10/26 22:36:43 INFO Upload complete. (103ms)1870=== NAME TestNARDeduplicationMetadataUploadBug1871 metadata_upload_test.go:54: Retrieved narinfo from S3:1872 StorePath: /build/TestNARDeduplicationMetadataUploadBug854439436/001/store/24hfxbf6grch6w59csip2408s8hj65nh-file1.txt1873 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1874 Compression: zstd1875 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1876 NarSize: 1601877 References: 1878 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1879=== NAME TestClientCADerivations1880 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations2878443604/001/store/jwysyjn1azmmf5brchkqb6fqsb965n69-ca-test1881 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1882 Compression: zstd1883 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1884 NarSize: 1441885 References: 1886 Deriver: /build/TestClientCADerivations2878443604/001/store/zva42vs8yv8wd109mszbyd07zi1vmh15-ca-test.drv1887 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1888 client_ca_test.go:185: Checking for realisation files in S3...1889=== NAME TestNARDeduplicationMetadataUploadBug1890 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1891 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1892 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1893=== NAME TestClientCADerivations1894 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1895 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache18962026/10/26 22:36:43 INFO Received uploads request method=POST path=/api/pending_closures18972026/10/26 22:36:43 INFO All 1 paths already cached1898=== NAME TestClientIntegration1899 client_integration_test.go:357: Retrieved narinfo from S3:1900 StorePath: /build/TestClientIntegration1293881247/002/store/ih1i5c1bkb2i3w013l6r38c3q2vpp4wp-test-file.txt1901 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1902 Compression: zstd1903 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11904 NarSize: 1521905 References: 1906 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11907 client_integration_test.go:358: Retrieved .ls file from S3 (compressed size: 77 bytes)1908 client_integration_test.go:358: Decompressed .ls content (64 bytes):1909 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1910=== NAME TestNARDeduplicationMetadataUploadBug1911 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug854439436/001/store/sclhnn3v3k2bivmpc4d4avq190pj1pdj-file2.txt19122026/10/26 22:36:43 INFO Received uploads request method=POST path=/api/pending_closures19132026/10/26 22:36:43 INFO lead: released remote=192.0.2.1:123419142026/10/26 22:36:43 INFO lead: acquired remote=192.0.2.1:123419152026/10/26 22:36:43 INFO Received uploads request method=POST path=/api/pending_closures1916=== RUN TestService_RequireScope_OIDC/builder_may_write1917=== PAUSE TestService_RequireScope_OIDC/builder_may_write1918=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1919=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1920=== RUN TestService_RequireScope_OIDC/ops_may_admin1921=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1922=== RUN TestService_RequireScope_OIDC/ops_may_not_write1923=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1924=== RUN TestService_RequireScope_OIDC/reader_may_not_write1925=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1926=== RUN TestService_RequireScope_OIDC/static_token_may_admin1927=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1928=== RUN TestService_RequireScope_OIDC/static_token_may_write1929=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1930=== RUN TestService_RequireScope_OIDC/reader_may_read1931=== PAUSE TestService_RequireScope_OIDC/reader_may_read1932=== RUN TestService_RequireScope_OIDC/writer_implies_read1933=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1934=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1935=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1936=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1937=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1938=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1939=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1940=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1941=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1942=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1943=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1944=== CONT TestParseSingleRange/none1945=== CONT TestParseSingleRange/open-ended1946=== CONT TestParseSingleRange/start_far_past_EOF1947=== CONT TestParseSingleRange/closed1948=== CONT TestParseSingleRange/single_byte1949=== CONT TestParseSingleRange/multi-range_ignored1950=== CONT TestParseSingleRange/suffix_exceeds_size1951=== CONT TestParseSingleRange/unknown_unit1952=== CONT TestParseSingleRange/start_past_EOF1953=== CONT TestParseSingleRange/suffix1954=== CONT TestParseSingleRange/malformed_end_before_start1955=== CONT TestParseSingleRange/malformed_both_empty1956=== CONT TestParseSingleRange/end_clamped_to_size1957=== CONT TestParseSingleRange/malformed_no_dash1958=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1959--- PASS: TestParseSingleRange (0.00s)1960 --- PASS: TestParseSingleRange/none (0.00s)1961 --- PASS: TestParseSingleRange/open-ended (0.00s)1962 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1963 --- PASS: TestParseSingleRange/closed (0.00s)1964 --- PASS: TestParseSingleRange/single_byte (0.00s)1965 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1966 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1967 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1968 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1969 --- PASS: TestParseSingleRange/suffix (0.00s)1970 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1971 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1972 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1973 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)19742026/10/26 22:36:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19752026/10/26 22:36:43 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLmI5OTVlOTZkLTU1YmUtNDIyNi1iMzhjLWRmOGI1ZDc2OGU1MXgxNzkzMDU0MjAxMzQzOTYxMDM2 parts=1019762026/10/26 22:36:43 INFO Received push request method=POST path=/api/pushes19772026/10/26 22:36:43 INFO Object in database but missing from S3 key=ih1i5c1bkb2i3w013l6r38c3q2vpp4wp.ls19782026/10/26 22:36:43 WARN Found objects in DB but missing from S3, will re-upload count=119792026/10/26 22:36:43 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19802026/10/26 22:36:43 INFO Received complete push request method=POST path=/api/pushes/2/complete19812026/10/26 22:36:43 WARN Failed to register uploaded object key=ih1i5c1bkb2i3w013l6r38c3q2vpp4wp.ls error="server returned 404: 404 page not found\n"19822026/10/26 22:36:43 INFO Completed push id=2 objects=3 duration=2.938587ms19832026/10/26 22:36:43 INFO Upload complete. (61ms)19842026/10/26 22:36:43 INFO Aborted multipart uploads count=0 kept=01985=== NAME TestClientIntegration1986 client_integration_test.go:375: Retrieved .ls file from S3 (compressed size: 62 bytes)1987 client_integration_test.go:375: Decompressed .ls content (49 bytes):1988 {"version":1,"root":{"type":"regular","size":39}}19892026/10/26 22:36:43 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=019902026/10/26 22:36:43 INFO Vacuumed table table=pending_closures19912026/10/26 22:36:43 INFO Vacuumed table table=pending_objects19922026/10/26 22:36:43 INFO Vacuumed table table=multipart_uploads19932026/10/26 22:36:43 INFO Vacuumed table table=closures19942026/10/26 22:36:43 INFO Vacuumed table table=objects19952026/10/26 22:36:43 INFO Aborted multipart uploads count=0 kept=019962026/10/26 22:36:43 WARN Force mode enabled - objects will be deleted immediately without grace period19972026/10/26 22:36:43 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=019982026/10/26 22:36:43 INFO Vacuumed table table=pending_closures19992026/10/26 22:36:43 INFO Vacuumed table table=pending_objects20002026/10/26 22:36:43 INFO Vacuumed table table=multipart_uploads20012026/10/26 22:36:43 INFO Vacuumed table table=closures20022026/10/26 22:36:43 INFO Vacuumed table table=objects2003--- PASS: TestPushDedupSurvivesConcurrentGC (1.06s)2004=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows20052026/10/26 22:36:43 WARN Rate limiter enabled after throttle name=s3-test rate=520062026/10/26 22:36:43 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2007=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2008 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102009 throttle_test.go:215: Rate limiter: enabled=true, rate=5.0020102026/10/26 22:36:43 INFO Received uploads request method=POST path=/api/pending_closures20112026/10/26 22:36:43 INFO Received push request method=POST path=/api/pushes20122026/10/26 22:36:43 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)2013=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal2014--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.41s)20152026/10/26 22:36:43 INFO Received uploads request method=POST path=/2016=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key20172026/10/26 22:36:43 INFO Received complete multipart upload request method=POST path=/2018=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info20192026/10/26 22:36:43 INFO Received uploads request method=POST path=/2020=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key20212026/10/26 22:36:43 INFO Aborted multipart uploads count=0 kept=020222026/10/26 22:36:43 INFO Received request for more parts method=POST path=/2023=== CONT TestServerTLSConfig/not_a_PEM_file2024--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2025 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2026 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2027 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2028 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2029=== CONT TestServerTLSConfig/missing_CA_file2030=== CONT TestServerTLSConfig/no_client_CA2031=== CONT TestPush_RejectsBadRequests/no_objects2032--- PASS: TestServerTLSConfig (0.00s)2033 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2034 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2035 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)20362026/10/26 22:36:43 INFO Received push request method=POST path=/api/pushes2037=== CONT TestPush_RejectsBadRequests/root_not_in_objects20382026/10/26 22:36:43 INFO Received push request method=POST path=/api/pushes2039=== CONT TestPush_RejectsBadRequests/bad_root20402026/10/26 22:36:43 INFO Received push request method=POST path=/api/pushes2041=== CONT TestPush_RejectsBadRequests/no_roots20422026/10/26 22:36:43 INFO Received push request method=POST path=/api/pushes2043=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20442026/10/26 22:36:43 INFO Received complete push request method=POST path=/api/pushes/3/complete20452026/10/26 22:36:43 WARN Failed to register uploaded object key=ih1i5c1bkb2i3w013l6r38c3q2vpp4wp.ls error="server returned 404: 404 page not found\n"20462026/10/26 22:36:43 WARN Force mode enabled - objects will be deleted immediately without grace period20472026/10/26 22:36:43 INFO Completed push id=3 objects=3 duration=4.36318ms20482026/10/26 22:36:43 INFO Upload complete. (68ms)20492026/10/26 22:36:43 WARN Authentication failed token_preview=eyJhbGciOi...pzstgdIcBw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2050=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2051=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20522026/10/26 22:36:43 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]2053=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2054=== NAME TestClientIntegration2055 client_integration_test.go:392: Retrieved .ls file from S3 (compressed size: 62 bytes)2056 client_integration_test.go:392: Decompressed .ls content (49 bytes):2057 {"version":1,"root":{"type":"regular","size":39}}2058=== CONT TestGCEndsOnShutdown/before_the_run20592026/10/26 22:36:43 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=020602026/10/26 22:36:43 INFO Vacuumed table table=pending_closures20612026/10/26 22:36:43 INFO Vacuumed table table=pending_objects20622026/10/26 22:36:43 INFO Received push request method=POST path=/api/pushes20632026/10/26 22:36:43 INFO Vacuumed table table=multipart_uploads20642026/10/26 22:36:43 INFO Vacuumed table table=closures20652026/10/26 22:36:43 INFO Vacuumed table table=objects20662026/10/26 22:36:43 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)2067--- PASS: TestPush_RejectsBadRequests (0.64s)2068 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2069 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2070 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2071 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)20722026/10/26 22:36:43 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign20732026/10/26 22:36:43 WARN Failed to register uploaded object key=sclhnn3v3k2bivmpc4d4avq190pj1pdj.ls error="server returned 404: 404 page not found\n"20742026/10/26 22:36:43 INFO Signed narinfos id=2 count=120752026/10/26 22:36:43 INFO Uploading 1 narinfos2076--- PASS: TestService_AuthMiddleware_OIDC (1.04s)2077 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)2078 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2079 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2080 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)20812026/10/26 22:36:43 INFO Received complete push request method=POST path=/api/pushes/2/complete20822026/10/26 22:36:43 WARN Failed to register uploaded object key=sclhnn3v3k2bivmpc4d4avq190pj1pdj.narinfo error="server returned 404: 404 page not found\n"20832026/10/26 22:36:43 INFO Completed push id=2 objects=3 duration=4.383ms20842026/10/26 22:36:43 INFO Upload complete. (83ms)2085=== NAME TestNARDeduplicationMetadataUploadBug2086 metadata_upload_test.go:76: Retrieved narinfo from S3:2087 StorePath: /build/TestNARDeduplicationMetadataUploadBug854439436/001/store/sclhnn3v3k2bivmpc4d4avq190pj1pdj-file2.txt2088 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2089 Compression: zstd2090 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2091 NarSize: 1602092 References: 2093 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2094 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2095 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2096 {"version":1,"root":{"type":"regular","size":44}}2097=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark2098=== NAME TestOrphanedObjectsGCStressTest2099 orphaned_objects_gc_test.go:503: Stress test completed successfully:2100 orphaned_objects_gc_test.go:504: - Active objects preserved: 202101 orphaned_objects_gc_test.go:505: - Objects deleted: 2102102 orphaned_objects_gc_test.go:506: - Total GC'd: 2102103--- PASS: TestNARDeduplicationMetadataUploadBug (2.53s)2104=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete21052026/10/26 22:36:44 INFO Received push request method=POST path=/api/pushes2106=== NAME TestPinProtectsFromGC2107 client_integration_test.go:854: Pinned store path: /build/TestPinProtectsFromGC2379307103/001/store/k3lzqfqg8xs8jrj3725alwsg4h4jyx15-pinned-file.txt2108 client_integration_test.go:855: Unpinned store path: /build/TestPinProtectsFromGC2379307103/001/store/sihas9srrmqyjvyxbif6p0ci3c62y8q5-unpinned-file.txt2109=== CONT TestResolveDBConnectionString/flag_wins2110--- PASS: TestOrphanedObjectsGCStressTest (4.54s)21112026/10/26 22:36:44 WARN Failed to abort multipart upload key=nar/ssssssssssssssssssssssssssssssssssssssssssssssssssss.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjU0ZDA3NjFhLTUyN2EtNGVjZS05NWQ3LWEwNmI4NjZkN2ZmNHgxNzkzMDU0MjAzNTAyMTIyNzUy error="Access Denied"2112=== CONT TestResolveDBConnectionString/nothing_configured21132026/10/26 22:36:44 WARN keeping failed pending closure for cleanup to retry the abort id=12114=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2115=== CONT TestResolveDBConnectionString/missing_file_is_an_error2116=== CONT TestResolveDBConnectionString/file_when_flag_empty2117=== CONT TestClientErrorHandling/InvalidAuthToken2118--- PASS: TestResolveDBConnectionString (0.00s)2119 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2120 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2121 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2122 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2123 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)21242026/10/26 22:36:44 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)21252026/10/26 22:36:44 INFO Uploading qfalfqxj593ny4hk31zlrwm6gkr7j4x0-shared-dep (136B)21262026/10/26 22:36:44 INFO Uploading imalc6al3z86041j7bd30p1v0r16fns7-top (224B)21272026/10/26 22:36:44 WARN Failed to register uploaded object key=nar/1l1912qggzr4mi6mivv7fc9smhdj0qpzz55l18msqc4n36x7nd8b.nar.zst error="server returned 404: 404 page not found\n"21282026/10/26 22:36:44 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"21292026/10/26 22:36:44 WARN Failed to register uploaded object key=imalc6al3z86041j7bd30p1v0r16fns7.ls error="server returned 404: 404 page not found\n"21302026/10/26 22:36:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign2131=== CONT TestClientErrorHandling/ServerNotAvailable21322026/10/26 22:36:44 WARN Failed to register uploaded object key=qfalfqxj593ny4hk31zlrwm6gkr7j4x0.ls error="server returned 404: 404 page not found\n"21332026/10/26 22:36:44 INFO Signed narinfos id=1 count=221342026/10/26 22:36:44 INFO Uploading 2 narinfos2135=== CONT TestClientErrorHandling/InvalidStorePath2136--- PASS: TestPendingClosureFailureTracksEveryUpload (0.00s)2137 --- PASS: TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false (0.82s)2138 --- PASS: TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true (0.84s)21392026/10/26 22:36:44 WARN Failed to register uploaded object key=imalc6al3z86041j7bd30p1v0r16fns7.narinfo error="server returned 404: 404 page not found\n"21402026/10/26 22:36:44 INFO Received complete push request method=POST path=/api/pushes/1/complete21412026/10/26 22:36:44 WARN Failed to register uploaded object key=qfalfqxj593ny4hk31zlrwm6gkr7j4x0.narinfo error="server returned 404: 404 page not found\n"21422026/10/26 22:36:44 INFO Received uploads request method=POST path=/api/pending_closures21432026/10/26 22:36:44 INFO Completed push id=1 objects=6 duration=12.480974ms21442026/10/26 22:36:44 INFO Upload complete. (102ms)21452026/10/26 22:36:44 INFO Aborted multipart uploads count=0 kept=02146=== NAME TestClientSharedPathCommittedMidPush2147 client_integration_test.go:803: Retrieved narinfo from S3:2148 StorePath: /build/TestClientSharedPathCommittedMidPush1015701020/001/store/qfalfqxj593ny4hk31zlrwm6gkr7j4x0-shared-dep2149 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2150 Compression: zstd2151 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822152 NarSize: 1362153 References: 2154 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n21552026/10/26 22:36:44 INFO Received push request method=POST path=/api/pushes21562026/10/26 22:36:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)2157 client_integration_test.go:803: Retrieved narinfo from S3:21582026/10/26 22:36:44 INFO Uploading vzv7hk39r0464vprkhanhdfnd33am8q9-lost-commit.txt (152B)2159 StorePath: /build/TestClientSharedPathCommittedMidPush1015701020/001/store/imalc6al3z86041j7bd30p1v0r16fns7-top2160 URL: nar/1l1912qggzr4mi6mivv7fc9smhdj0qpzz55l18msqc4n36x7nd8b.nar.zst2161 Compression: zstd2162 NarHash: sha256:1l1912qggzr4mi6mivv7fc9smhdj0qpzz55l18msqc4n36x7nd8b2163 NarSize: 2242164 References: /build/TestClientSharedPathCommittedMidPush1015701020/001/store/qfalfqxj593ny4hk31zlrwm6gkr7j4x0-shared-dep2165 CA: text:sha256:0znpfl0i9cx8ymjhkzkmpk96xgs6ijfkcfr02vwa48qfr0lr7vyl21662026/10/26 22:36:44 WARN Force mode enabled - objects will be deleted immediately without grace period21672026/10/26 22:36:44 WARN Failed to register uploaded object key=nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst error="server returned 404: 404 page not found\n"21682026/10/26 22:36:44 INFO Received sign narinfos request method=POST path=/api/pushes/4/sign21692026/10/26 22:36:44 WARN Failed to register uploaded object key=vzv7hk39r0464vprkhanhdfnd33am8q9.ls error="server returned 404: 404 page not found\n"21702026/10/26 22:36:44 INFO Signed narinfos id=4 count=121712026/10/26 22:36:44 INFO Uploading 1 narinfos21722026/10/26 22:36:44 INFO Received complete push request method=POST path=/api/pushes/4/complete2173=== CONT TestCacheConfigHandler/no_cache_url_configured2174--- PASS: TestPushWaitsForSweepHoldingRow (1.19s)2175=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator21762026/10/26 22:36:44 WARN Failed to register uploaded object key=vzv7hk39r0464vprkhanhdfnd33am8q9.narinfo error="server returned 404: 404 page not found\n"2177=== CONT TestCacheConfigHandler/no_signing_keys2178=== CONT TestCacheConfigHandler/full_config,_no_issuer2179=== CONT TestService_RequireScope_OIDC/ops_may_not_write2180--- PASS: TestCacheConfigHandler (0.00s)2181 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2182 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2183 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2184 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)21852026-10-26 22:36:44.093 UTC [176] LOG: checkpoints are occurring too frequently (12 seconds apart)21862026-10-26 22:36:44.093 UTC [176] HINT: Consider increasing the configuration parameter "max_wal_size".21872026-10-26 22:36:44.093 UTC [176] LOG: checkpoint starting: wal2188=== CONT TestService_RequireScope_OIDC/writer_implies_read2189=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2190=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read21912026/10/26 22:36:44 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]2192=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2193=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2194=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2195=== CONT TestService_RequireScope_OIDC/reader_may_read2196--- PASS: TestClientSharedPathCommittedMidPush (1.22s)2197=== CONT TestService_RequireScope_OIDC/static_token_may_admin2198=== CONT TestService_RequireScope_OIDC/static_token_may_write2199=== CONT TestService_RequireScope_OIDC/ops_may_admin2200=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2201=== CONT TestService_RequireScope_OIDC/builder_may_write2202=== CONT TestService_RequireScope_OIDC/reader_may_not_write22032026/10/26 22:36:44 INFO Completed push id=4 objects=3 duration=10.037131ms22042026/10/26 22:36:44 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:37253/api/pushes/4/complete\": EOF" url=http://127.0.0.1:37253/api/pushes/4/complete22052026/10/26 22:36:44 INFO Received push request method=POST path=/api/pushes22062026/10/26 22:36:44 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=022072026/10/26 22:36:44 INFO Vacuumed table table=pending_closures22082026/10/26 22:36:44 INFO Vacuumed table table=pending_objects22092026/10/26 22:36:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)22102026/10/26 22:36:44 INFO Vacuumed table table=multipart_uploads22112026/10/26 22:36:44 INFO Uploading k3lzqfqg8xs8jrj3725alwsg4h4jyx15-pinned-file.txt (128B)22122026/10/26 22:36:44 INFO Vacuumed table table=closures22132026/10/26 22:36:44 INFO Vacuumed table table=objects2214--- PASS: TestService_RequireScope_OIDC (0.73s)2215 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2216 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2217 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2218 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2219 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2220 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2221 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2222 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2223 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2224 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2225 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2226 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2227 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2228 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)22292026/10/26 22:36:44 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"22302026/10/26 22:36:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22312026/10/26 22:36:44 WARN Failed to register uploaded object key=k3lzqfqg8xs8jrj3725alwsg4h4jyx15.ls error="server returned 404: 404 page not found\n"22322026/10/26 22:36:44 INFO Signed narinfos id=1 count=122332026/10/26 22:36:44 INFO Uploading 1 narinfos22342026/10/26 22:36:44 INFO Received complete push request method=POST path=/api/pushes/1/complete22352026/10/26 22:36:44 WARN Failed to register uploaded object key=k3lzqfqg8xs8jrj3725alwsg4h4jyx15.narinfo error="server returned 404: 404 page not found\n"22362026/10/26 22:36:44 INFO Completed push id=1 objects=3 duration=8.892821ms22372026/10/26 22:36:44 INFO Upload complete. (102ms)2238--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2239 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.27s)2240 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.32s)22412026/10/26 22:36:44 INFO Aborted multipart uploads count=0 kept=022422026/10/26 22:36:44 INFO Aborted multipart uploads count=0 kept=022432026/10/26 22:36:44 INFO Received complete push request method=POST path=/api/pushes/4/complete22442026-10-26 22:36:44.203 UTC [1112] ERROR: Push does not exist: id=422452026-10-26 22:36:44.203 UTC [1112] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE22462026-10-26 22:36:44.203 UTC [1112] STATEMENT: -- name: CommitPush :one2247 SELECT commit_push($1::bigint)::bigint2248 22492026/10/26 22:36:44 WARN Push not found id=422502026/10/26 22:36:44 INFO Upload complete. (190ms)2251=== NAME TestClientIntegration2252 client_integration_test.go:422: Retrieved narinfo from S3:2253 StorePath: /build/TestClientIntegration1293881247/002/store/vzv7hk39r0464vprkhanhdfnd33am8q9-lost-commit.txt2254 URL: nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst2255 Compression: zstd2256 NarHash: sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl2257 NarSize: 1522258 References: 2259 CA: fixed:r:sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl2260 client_integration_test.go:425: Testing garbage collection...2261--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2262 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.84s)2263 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.85s)2264--- PASS: TestPendingClosureWriteTimeout (0.00s)2265 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2266 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2267 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2268 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.06s)22692026/10/26 22:36:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22702026/10/26 22:36:44 INFO Completed multipart upload object_key=nar/dddddddddddddddddddddddddddddddd00000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjBmNjQ4MGQ4LTdhZjItNGI4Yi04YTk0LTZhYWM2ZmQ5ODJmM3gxNzkzMDU0MjAxMzM5MTAwOTcy parts=1022712026/10/26 22:36:44 WARN Force mode enabled - objects will be deleted immediately without grace period22722026/10/26 22:36:44 WARN Force mode enabled - objects will be deleted immediately without grace period22732026/10/26 22:36:44 INFO Starting cleanup of old closures method=DELETE path=/api/closures22742026/10/26 22:36:44 INFO Garbage collection started22752026/10/26 22:36:44 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:37221/bucket106/?delete=\": context canceled"22762026/10/26 22:36:44 INFO Aborted multipart uploads count=0 kept=022772026/10/26 22:36:44 WARN Force mode enabled - objects will be deleted immediately without grace period2278--- PASS: TestGCEndsOnShutdown (0.00s)2279 --- PASS: TestGCEndsOnShutdown/before_the_run (0.24s)2280 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.37s)2281 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.40s)22822026/10/26 22:36:44 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/present22832026/10/26 22:36:44 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=2 objects-marked-for-deletion=6 objects-deleted-after-grace-period=6 objects-failed-to-delete=022842026/10/26 22:36:44 INFO Vacuumed table table=pending_closures22852026/10/26 22:36:44 INFO Vacuumed table table=pending_objects22862026/10/26 22:36:44 INFO Vacuumed table table=multipart_uploads22872026/10/26 22:36:44 INFO Vacuumed table table=closures22882026/10/26 22:36:44 INFO Vacuumed table table=objects22892026/10/26 22:36:44 WARN Request failed, retrying attempt=2 backoff=201.432113ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2290--- PASS: TestDeleteClosuresRacingPins (1.87s)22912026/10/26 22:36:44 INFO Received push request method=POST path=/api/pushes22922026/10/26 22:36:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)22932026/10/26 22:36:44 INFO Uploading sihas9srrmqyjvyxbif6p0ci3c62y8q5-unpinned-file.txt (128B)22942026/10/26 22:36:44 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22952026/10/26 22:36:44 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"22962026/10/26 22:36:44 WARN Failed to register uploaded object key=sihas9srrmqyjvyxbif6p0ci3c62y8q5.ls error="server returned 404: 404 page not found\n"22972026/10/26 22:36:44 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign22982026/10/26 22:36:44 INFO Signed narinfos id=2 count=122992026/10/26 22:36:44 INFO Uploading 1 narinfos23002026/10/26 22:36:44 INFO Received complete push request method=POST path=/api/pushes/2/complete23012026/10/26 22:36:44 WARN Failed to register uploaded object key=sihas9srrmqyjvyxbif6p0ci3c62y8q5.narinfo error="server returned 404: 404 page not found\n"23022026/10/26 22:36:44 INFO Completed push id=2 objects=3 duration=2.712825ms23032026/10/26 22:36:44 INFO Upload complete. (246ms)23042026/10/26 22:36:44 WARN Request failed, retrying attempt=3 backoff=420.643361ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present23052026/10/26 22:36:44 INFO lead: released remote=192.0.2.1:12342306--- PASS: TestLeadElectsOneAndHandsOver (2.74s)23072026/10/26 22:36:44 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"23082026/10/26 22:36:44 INFO Starting cleanup of old closures method=DELETE path=/api/closures23092026/10/26 22:36:44 INFO Garbage collection started23102026/10/26 22:36:44 INFO Aborted multipart uploads count=0 kept=023112026/10/26 22:36:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete23122026/10/26 22:36:44 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggggg00000000000000000000.nar.zst upload_id=M2Q1NTcyNzYtN2I5Yy00NjkyLWFkZmQtNjExMTU2MTYxMzBiLjY2ZGY4NzEwLTE0ZmYtNGMxOC1hOTIzLTE2MTMzOTFlM2FmMngxNzkzMDU0MjAxMzQ0OTUxNDg1 parts=1023132026-10-26 22:36:44.967 UTC [875] ERROR: could not obtain lock on row in relation "closures"23142026-10-26 22:36:44.967 UTC [875] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT23152026/10/26 22:36:44 WARN Force mode enabled - objects will be deleted immediately without grace period23162026-10-26 22:36:44.967 UTC [875] ERROR: could not obtain lock on row in relation "closures"23172026-10-26 22:36:44.967 UTC [875] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT23182026-10-26 22:36:44.968 UTC [875] ERROR: could not obtain lock on row in relation "closures"23192026-10-26 22:36:44.968 UTC [875] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT23202026-10-26 22:36:44.968 UTC [875] ERROR: could not obtain lock on row in relation "closures"23212026-10-26 22:36:44.968 UTC [875] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT23222026-10-26 22:36:44.968 UTC [875] ERROR: could not obtain lock on row in relation "closures"23232026-10-26 22:36:44.968 UTC [875] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT2324=== NAME TestClientCADerivations2325 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2326 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2327 error: binary cache 's3://bucket79?endpoint=http://localhost:37221®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations2878443604/001/store'2328 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 123292026/10/26 22:36:44 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=023302026/10/26 22:36:44 INFO Vacuumed table table=pending_closures2331--- PASS: TestPush_RootsAreLockedInByteOrder (4.18s)23322026/10/26 22:36:44 INFO Vacuumed table table=pending_objects23332026/10/26 22:36:44 INFO Vacuumed table table=multipart_uploads23342026/10/26 22:36:44 INFO Vacuumed table table=closures23352026/10/26 22:36:45 INFO Vacuumed table table=objects2336--- PASS: TestClientCADerivations (2.87s)23372026/10/26 22:36:45 WARN Request failed, retrying attempt=4 backoff=731.566362ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present23382026/10/26 22:36:45 WARN Request failed, retrying attempt=5 backoff=1.663460622s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present23392026/10/26 22:36:46 INFO Aborted multipart uploads count=1 kept=023402026/10/26 22:36:46 INFO Received cleanup request method=DELETE path=/api/pending_closures23412026/10/26 22:36:46 INFO Aborted multipart uploads count=1 kept=02342--- PASS: TestPendingCleanupUsesOneCutoff (6.83s)23432026/10/26 22:36:46 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=2 objects_marked=6 objects_deleted=6 objects_failed=02344=== NAME TestClientIntegration2345 client_integration_test.go:432: Objects in database after GC:2346 client_integration_test.go:432: Successfully deleted all objects with GC --force2347--- PASS: TestClientIntegration (4.25s)23482026/10/26 22:36:46 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=023492026/10/26 22:36:46 INFO Received create pin request method=POST path=/api/pins/myapp23502026/10/26 22:36:46 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2379307103/001/store/k3lzqfqg8xs8jrj3725alwsg4h4jyx15-pinned-file.txt narinfo_key=k3lzqfqg8xs8jrj3725alwsg4h4jyx15.narinfo23512026/10/26 22:36:46 INFO Starting cleanup of old closures method=DELETE path=/api/closures23522026/10/26 22:36:46 INFO Garbage collection started23532026/10/26 22:36:46 INFO Aborted multipart uploads count=0 kept=023542026/10/26 22:36:46 WARN Force mode enabled - objects will be deleted immediately without grace period23552026/10/26 22:36:46 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=023562026/10/26 22:36:46 INFO Vacuumed table table=pending_closures23572026/10/26 22:36:46 INFO Vacuumed table table=pending_objects23582026/10/26 22:36:46 INFO Vacuumed table table=multipart_uploads23592026/10/26 22:36:46 INFO Vacuumed table table=closures23602026/10/26 22:36:46 INFO Vacuumed table table=objects2361--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.63s)23622026/10/26 22:36:47 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-config23632026/10/26 22:36:47 WARN Request failed, retrying attempt=2 backoff=213.040004ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23642026/10/26 22:36:47 WARN Request failed, retrying attempt=3 backoff=362.526575ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2365--- PASS: TestConnectWaitsForAPeerMigration (5.20s)23662026/10/26 22:36:48 WARN Request failed, retrying attempt=4 backoff=765.223581ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2367=== NAME TestPinProtectsFromGC2368 client_integration_test.go:963: Pin successfully protected closure from garbage collection2369--- PASS: TestPinProtectsFromGC (6.01s)23702026/10/26 22:36:48 WARN Request failed, retrying attempt=5 backoff=1.578251808s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23712026/10/26 22:36:50 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"23722026/10/26 22:36:50 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-config23732026/10/26 22:36:50 WARN Request failed, retrying attempt=2 backoff=189.96079ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23742026/10/26 22:36:50 WARN Request failed, retrying attempt=3 backoff=372.048247ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23752026/10/26 22:36:51 WARN Request failed, retrying attempt=4 backoff=830.521851ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23762026/10/26 22:36:52 WARN Request failed, retrying attempt=5 backoff=1.739387515s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23772026/10/26 22:36:53 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_closures23782026/10/26 22:36:53 WARN Request failed, retrying attempt=2 backoff=212.817226ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23792026/10/26 22:36:54 WARN Request failed, retrying attempt=3 backoff=403.143911ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23802026/10/26 22:36:54 WARN Request failed, retrying attempt=4 backoff=757.941472ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23812026/10/26 22:36:55 WARN Request failed, retrying attempt=5 backoff=1.689486772s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2382--- PASS: TestUploadHandlersRejectOversizedBody (0.47s)2383 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.89s)2384 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.91s)2385 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (13.15s)2386--- PASS: TestClientErrorHandling (0.00s)2387 --- PASS: TestClientErrorHandling/InvalidStorePath (0.74s)2388 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.78s)2389 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.97s)2390PASS2391{"timestamp":"2026-10-26T22:36:56.999230425Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:51516","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(209)"}2392{"timestamp":"2026-10-26T22:36:56.999234405Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:52026","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(206)"}2393{"timestamp":"2026-10-26T22:36:56.999232565Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:51838","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)"}2394{"timestamp":"2026-10-26T22:36:56.999229265Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:51528","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)"}23952026-10-26 22:36:57.277 UTC [170] LOG: received smart shutdown request23962026-10-26 22:36:57.282 UTC [170] LOG: background worker "logical replication launcher" (PID 182) exited with exit code 123972026-10-26 22:36:58.278 UTC [176] LOG: checkpoint complete: wrote 10339 buffers (63.1%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=13.418 s, sync=0.707 s, total=14.185 s; sync files=37078, longest=0.002 s, average=0.001 s; distance=534593 kB, estimate=534593 kB; lsn=0/22B16FE8, redo lsn=0/2217646823982026-10-26 22:36:58.283 UTC [176] LOG: shutting down23992026-10-26 22:36:58.284 UTC [176] LOG: checkpoint starting: shutdown immediate24002026-10-26 22:36:58.308 UTC [176] LOG: checkpoint complete: wrote 251 buffers (1.5%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.008 s, sync=0.016 s, total=0.026 s; sync files=173, longest=0.001 s, average=0.001 s; distance=9858 kB, estimate=482120 kB; lsn=0/22B17060, redo lsn=0/22B1706024012026-10-26 22:36:58.389 UTC [170] LOG: database system is shut down2402Running OIDC tests...2403=== RUN TestAudienceForIssuer2404=== PAUSE TestAudienceForIssuer2405=== RUN TestHTTPClientForHasTimeouts2406=== PAUSE TestHTTPClientForHasTimeouts2407=== RUN TestGlobMatch2408=== PAUSE TestGlobMatch2409=== RUN TestValidateToken_ValidToken2410=== PAUSE TestValidateToken_ValidToken2411=== RUN TestValidateToken_WrongAudience2412=== PAUSE TestValidateToken_WrongAudience2413=== RUN TestValidateToken_Expired2414=== PAUSE TestValidateToken_Expired2415=== RUN TestValidateToken_BoundClaimsMismatch2416=== PAUSE TestValidateToken_BoundClaimsMismatch2417=== RUN TestValidateToken_BoundSubjectMismatch2418=== PAUSE TestValidateToken_BoundSubjectMismatch2419=== RUN TestValidateToken_MultipleProviders2420=== PAUSE TestValidateToken_MultipleProviders2421=== RUN TestValidateToken_NoMatchingProvider2422=== PAUSE TestValidateToken_NoMatchingProvider2423=== RUN TestValidateToken_KubernetesServiceAccount2424=== PAUSE TestValidateToken_KubernetesServiceAccount2425=== RUN TestNewValidator_KubernetesRequiresCA2426=== PAUSE TestNewValidator_KubernetesRequiresCA2427=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2428=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2429=== RUN TestPins_ReservedForMatchingRule2430=== PAUSE TestPins_ReservedForMatchingRule2431=== RUN TestPins_TopLevelShorthand2432=== PAUSE TestPins_TopLevelShorthand2433=== RUN TestPins_ConfigValidation2434=== PAUSE TestPins_ConfigValidation2435=== RUN TestScopes_LegacyProviderDefaultsToWrite2436=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2437=== RUN TestScopes_Rules2438=== PAUSE TestScopes_Rules2439=== RUN TestScopes_ConfigValidation2440=== PAUSE TestScopes_ConfigValidation2441=== CONT TestAudienceForIssuer2442--- PASS: TestAudienceForIssuer (0.00s)2443=== CONT TestScopes_ConfigValidation2444=== CONT TestScopes_Rules2445--- PASS: TestScopes_ConfigValidation (0.00s)2446=== CONT TestValidateToken_KubernetesServiceAccount2447=== CONT TestPins_ConfigValidation2448=== CONT TestValidateToken_BoundClaimsMismatch2449--- PASS: TestPins_ConfigValidation (0.00s)2450=== CONT TestPins_TopLevelShorthand2451=== CONT TestValidateToken_Expired2452=== CONT TestValidateToken_BoundSubjectMismatch2453=== CONT TestValidateToken_ValidToken2454=== CONT TestGlobMatch2455=== RUN TestGlobMatch/foo_foo2456=== CONT TestHTTPClientForHasTimeouts2457=== CONT TestValidateToken_WrongAudience2458=== CONT TestScopes_LegacyProviderDefaultsToWrite2459=== CONT TestPins_ReservedForMatchingRule2460=== PAUSE TestGlobMatch/foo_foo2461=== RUN TestGlobMatch/foo_bar2462=== PAUSE TestGlobMatch/foo_bar2463=== CONT TestNewValidator_KubernetesRequiresCA2464=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2465=== CONT TestValidateToken_NoMatchingProvider2466=== CONT TestValidateToken_MultipleProviders2467=== RUN TestGlobMatch/*_2468=== PAUSE TestGlobMatch/*_2469=== RUN TestGlobMatch/*_anything2470=== PAUSE TestGlobMatch/*_anything2471=== RUN TestGlobMatch/foo*_foo2472=== PAUSE TestGlobMatch/foo*_foo2473=== RUN TestGlobMatch/foo*_foobar2474=== PAUSE TestGlobMatch/foo*_foobar2475=== RUN TestGlobMatch/foo*_bar2476=== PAUSE TestGlobMatch/foo*_bar2477=== RUN TestGlobMatch/*bar_bar2478=== PAUSE TestGlobMatch/*bar_bar2479=== RUN TestGlobMatch/*bar_foobar2480=== PAUSE TestGlobMatch/*bar_foobar2481=== RUN TestGlobMatch/*bar_foo2482=== PAUSE TestGlobMatch/*bar_foo2483=== RUN TestGlobMatch/foo*bar_foobar2484=== PAUSE TestGlobMatch/foo*bar_foobar2485=== RUN TestGlobMatch/foo*bar_foo123bar2486=== PAUSE TestGlobMatch/foo*bar_foo123bar2487=== RUN TestGlobMatch/foo*bar_foobarbaz2488=== PAUSE TestGlobMatch/foo*bar_foobarbaz2489=== RUN TestGlobMatch/*/*_foo/bar2490=== PAUSE TestGlobMatch/*/*_foo/bar2491=== RUN TestGlobMatch/*/*_foo2492=== PAUSE TestGlobMatch/*/*_foo2493=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2494=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2495=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02496=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02497=== RUN TestGlobMatch/refs/*/main_refs/heads/main2498=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2499=== RUN TestGlobMatch/fo?_foo2500=== PAUSE TestGlobMatch/fo?_foo2501=== RUN TestGlobMatch/fo?_fo2502=== PAUSE TestGlobMatch/fo?_fo2503=== RUN TestGlobMatch/fo?_fooo2504=== PAUSE TestGlobMatch/fo?_fooo2505=== RUN TestGlobMatch/?oo_foo2506=== PAUSE TestGlobMatch/?oo_foo2507=== RUN TestGlobMatch/?oo_boo2508=== PAUSE TestGlobMatch/?oo_boo2509=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2510=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2511=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2512=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2513=== CONT TestGlobMatch/foo_foo2514=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2515=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2516=== CONT TestGlobMatch/?oo_boo2517=== CONT TestGlobMatch/?oo_foo2518=== CONT TestGlobMatch/fo?_fooo2519=== CONT TestGlobMatch/fo?_fo2520=== CONT TestGlobMatch/refs/*/main_refs/heads/main2521=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02522=== CONT TestGlobMatch/fo?_foo2523=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2524=== CONT TestGlobMatch/*/*_foo2525=== CONT TestGlobMatch/foo*bar_foobarbaz2526=== CONT TestGlobMatch/foo*bar_foo123bar2527=== CONT TestGlobMatch/foo*bar_foobar2528=== CONT TestGlobMatch/*/*_foo/bar2529=== CONT TestGlobMatch/*bar_foo2530=== CONT TestGlobMatch/*bar_bar2531=== CONT TestGlobMatch/foo*_bar2532=== CONT TestGlobMatch/foo*_foobar2533=== CONT TestGlobMatch/foo*_foo2534=== CONT TestGlobMatch/*_anything2535=== CONT TestGlobMatch/*_2536=== CONT TestGlobMatch/foo_bar2537=== CONT TestGlobMatch/*bar_foobar2538--- PASS: TestGlobMatch (0.10s)2539 --- PASS: TestGlobMatch/foo_foo (0.00s)2540 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2541 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2542 --- PASS: TestGlobMatch/?oo_boo (0.00s)2543 --- PASS: TestGlobMatch/?oo_foo (0.00s)2544 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2545 --- PASS: TestGlobMatch/fo?_fo (0.00s)2546 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2547 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2548 --- PASS: TestGlobMatch/fo?_foo (0.00s)2549 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2550 --- PASS: TestGlobMatch/*/*_foo (0.00s)2551 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2552 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2553 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2554 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2555 --- PASS: TestGlobMatch/*bar_foo (0.00s)2556 --- PASS: TestGlobMatch/*bar_bar (0.00s)2557 --- PASS: TestGlobMatch/foo*_bar (0.00s)2558 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2559 --- PASS: TestGlobMatch/foo*_foo (0.00s)2560 --- PASS: TestGlobMatch/*_anything (0.00s)2561 --- PASS: TestGlobMatch/*_ (0.00s)2562 --- PASS: TestGlobMatch/foo_bar (0.00s)2563 --- PASS: TestGlobMatch/*bar_foobar (0.00s)25642026/10/26 22:37:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34709/oidc25652026/10/26 22:37:02 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:329812566--- PASS: TestHTTPClientForHasTimeouts (1.25s)25672026/10/26 22:37:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43433/oidc2568--- PASS: TestValidateToken_KubernetesServiceAccount (1.40s)25692026/10/26 22:37:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37867/oidc2570--- PASS: TestValidateToken_BoundClaimsMismatch (1.39s)2571--- PASS: TestValidateToken_ValidToken (1.33s)25722026/10/26 22:37:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40915/oidc2573--- PASS: TestValidateToken_Expired (1.40s)2574--- PASS: TestScopes_Rules (1.43s)25752026/10/26 22:37:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:32887/oidc2576--- PASS: TestValidateToken_WrongAudience (1.36s)25772026/10/26 22:37:03 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:36721/oidc25782026/10/26 22:37:03 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:36591/oidc2579--- PASS: TestValidateToken_MultipleProviders (1.30s)25802026/10/26 22:37:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34159/oidc2581--- PASS: TestPins_ReservedForMatchingRule (1.37s)25822026/10/26 22:37:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39665/oidc2583--- PASS: TestPins_TopLevelShorthand (1.50s)25842026/10/26 22:37:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37621/oidc2585--- PASS: TestValidateToken_BoundSubjectMismatch (1.48s)25862026/10/26 22:37:03 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232587--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (1.40s)25882026/10/26 22:37:03 http: TLS handshake error from 127.0.0.1:56316: remote error: tls: bad certificate2589--- PASS: TestNewValidator_KubernetesRequiresCA (1.46s)25902026/10/26 22:37:03 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:37201/oidc2591--- PASS: TestValidateToken_NoMatchingProvider (1.44s)25922026/10/26 22:37:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44475/oidc2593--- PASS: TestScopes_LegacyProviderDefaultsToWrite (1.52s)2594PASS2595Running hook tests...2596=== RUN TestSendPathsEmpty2597=== PAUSE TestSendPathsEmpty2598=== RUN TestQueueEnqueueAndFetch2599=== PAUSE TestQueueEnqueueAndFetch2600=== RUN TestQueueDeduplication2601=== PAUSE TestQueueDeduplication2602=== RUN TestQueueRemove2603=== PAUSE TestQueueRemove2604=== RUN TestQueueFetchBatchLimit2605=== PAUSE TestQueueFetchBatchLimit2606=== RUN TestQueueRetryMovesToBack2607=== PAUSE TestQueueRetryMovesToBack2608=== RUN TestQueueFetchRemoveLifecycle2609=== PAUSE TestQueueFetchRemoveLifecycle2610=== RUN TestQueueConcurrentWriters2611=== PAUSE TestQueueConcurrentWriters2612=== RUN TestQueueEnqueueWaitsOutSlowWriter2613=== PAUSE TestQueueEnqueueWaitsOutSlowWriter2614=== RUN TestQueueRemoveLargeClosure2615=== PAUSE TestQueueRemoveLargeClosure2616=== RUN TestServerClientIntegration2617--- PASS: TestServerClientIntegration (0.01s)2618=== RUN TestServerQueueError26192026/10/26 22:37:04 ERROR Failed to queue paths error="permission denied" count=12620--- PASS: TestServerQueueError (0.00s)2621=== RUN TestServerRefusesOversizedAndNonStoreRequests2622=== PAUSE TestServerRefusesOversizedAndNonStoreRequests2623=== RUN TestGetListenerSocketActivation2624 server_test.go:309: === RUN TestGetListenerSocketActivation2625 --- PASS: TestGetListenerSocketActivation (0.00s)2626 PASS2627 2628--- PASS: TestGetListenerSocketActivation (1.02s)2629=== RUN TestServerStalledClientDoesNotBlockShutdown2630=== PAUSE TestServerStalledClientDoesNotBlockShutdown2631=== RUN TestServerBacksOffOnAcceptErrors2632=== PAUSE TestServerBacksOffOnAcceptErrors2633=== RUN TestDrainIsolatesPoisonPath2634=== PAUSE TestDrainIsolatesPoisonPath2635=== RUN TestRunNotBlockedByPoisonHead2636=== PAUSE TestRunNotBlockedByPoisonHead2637=== RUN TestDrainGivesUpWhenServerDown2638=== PAUSE TestDrainGivesUpWhenServerDown2639=== RUN TestFailedPathPrunedByLaterClosure2640=== PAUSE TestFailedPathPrunedByLaterClosure2641=== RUN TestWorkerUploadsAndRemoves2642=== PAUSE TestWorkerUploadsAndRemoves2643=== RUN TestWorkerSkipsGCdPaths2644=== PAUSE TestWorkerSkipsGCdPaths2645=== RUN TestWorkerPrunesClosureDeps2646=== PAUSE TestWorkerPrunesClosureDeps2647=== RUN TestWorkerRemovesCachedPathBatchedWithLargerClosure2648=== PAUSE TestWorkerRemovesCachedPathBatchedWithLargerClosure2649=== RUN TestDrainTimeout2650=== PAUSE TestDrainTimeout2651=== RUN TestDrainTimeoutDuringIsolation2652=== PAUSE TestDrainTimeoutDuringIsolation2653=== RUN TestShutdownFinishesInFlightPush2654=== PAUSE TestShutdownFinishesInFlightPush2655=== RUN TestWorkerRemoveFailureIsNotProgress2656=== PAUSE TestWorkerRemoveFailureIsNotProgress2657=== RUN TestWorkerKeepsPathItCannotStat2658=== PAUSE TestWorkerKeepsPathItCannotStat2659=== CONT TestQueueConcurrentWriters2660=== CONT TestServerBacksOffOnAcceptErrors26612026/10/26 22:37:05 ERROR Accept failed error="too many open files"2662=== CONT TestDrainTimeout2663=== CONT TestShutdownFinishesInFlightPush2664=== RUN TestShutdownFinishesInFlightPush/completes2665=== CONT TestDrainGivesUpWhenServerDown2666=== CONT TestFailedPathPrunedByLaterClosure2667=== CONT TestWorkerPrunesClosureDeps2668=== CONT TestWorkerUploadsAndRemoves2669=== PAUSE TestShutdownFinishesInFlightPush/completes2670=== CONT TestDrainTimeoutDuringIsolation2671=== CONT TestQueueFetchRemoveLifecycle2672=== CONT TestWorkerKeepsPathItCannotStat2673=== CONT TestRunNotBlockedByPoisonHead2674=== CONT TestWorkerRemoveFailureIsNotProgress2675=== CONT TestServerRefusesOversizedAndNonStoreRequests2676=== CONT TestDrainIsolatesPoisonPath2677=== CONT TestServerStalledClientDoesNotBlockShutdown2678=== CONT TestQueueRemove2679=== CONT TestQueueEnqueueWaitsOutSlowWriter2680=== CONT TestQueueRetryMovesToBack2681=== CONT TestQueueRemoveLargeClosure2682=== CONT TestQueueFetchBatchLimit2683=== CONT TestQueueEnqueueAndFetch2684=== CONT TestWorkerRemovesCachedPathBatchedWithLargerClosure2685=== CONT TestWorkerSkipsGCdPaths2686=== RUN TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2687=== RUN TestDrainTimeoutDuringIsolation/probe_cut_short26882026/10/26 22:37:05 ERROR Refusing path outside the store path=/etc/shadow store=/nix/store2689=== RUN TestWorkerRemoveFailureIsNotProgress/collected_path2690=== PAUSE TestWorkerRemoveFailureIsNotProgress/collected_path2691=== PAUSE TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2692=== PAUSE TestDrainTimeoutDuringIsolation/probe_cut_short2693=== RUN TestWorkerRemoveFailureIsNotProgress/pushed_batch2694=== CONT TestSendPathsEmpty2695=== PAUSE TestWorkerRemoveFailureIsNotProgress/pushed_batch2696=== RUN TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2697=== RUN TestWorkerRemoveFailureIsNotProgress/isolated_paths2698=== CONT TestQueueDeduplication2699=== PAUSE TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2700=== CONT TestShutdownFinishesInFlightPush/completes2701=== PAUSE TestWorkerRemoveFailureIsNotProgress/isolated_paths2702--- PASS: TestSendPathsEmpty (0.00s)27032026/10/26 22:37:05 ERROR Refusing path outside the store path=/nix/store store=/nix/store2704=== CONT TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout27052026/10/26 22:37:05 ERROR Accept failed error="too many open files"27062026/10/26 22:37:05 ERROR Refusing path outside the store path=/nix/store/ store=/nix/store27072026/10/26 22:37:05 ERROR Refusing path outside the store path=/nix/store/../../etc/shadow store=/nix/store27082026/10/26 22:37:05 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello/bin/sh store=/nix/store27092026/10/26 22:37:05 ERROR Refusing path outside the store path=nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store27102026/10/26 22:37:05 ERROR Refusing path outside the store path=/nix/storeX/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store27112026/10/26 22:37:05 ERROR Refusing path outside the store path=/nix/store/.links store=/nix/store27122026/10/26 22:37:05 ERROR Refusing path outside the store path=/nix/store/aaa-hello store=/nix/store27132026/10/26 22:37:05 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz store=/nix/store27142026/10/26 22:37:05 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz- store=/nix/store27152026/10/26 22:37:05 ERROR Refusing path outside the store path=/nix/store/0123456789ebcdfghijklmnpqrsvwxyz-hello store=/nix/store27162026/10/26 22:37:05 ERROR Refusing path outside the store path="/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel\x00lo" store=/nix/store27172026/10/26 22:37:05 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel/lo store=/nix/store27182026/10/26 22:37:05 ERROR Accept failed error="too many open files"27192026/10/26 22:37:05 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx store=/nix/store27202026/10/26 22:37:05 ERROR Failed to decode request error="unexpected EOF"2721--- PASS: TestServerRefusesOversizedAndNonStoreRequests (0.02s)2722=== CONT TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline27232026/10/26 22:37:05 ERROR Accept failed error="too many open files"27242026/10/26 22:37:05 ERROR Accept failed error="too many open files"27252026/10/26 22:37:05 INFO Upload queue status pending=227262026/10/26 22:37:05 INFO Uploading batch count=127272026/10/26 22:37:05 ERROR Upload failed error="upload failed" count=127282026/10/26 22:37:05 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat4223219478/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat4223219478/002/locked/aaa: permission denied"27292026/10/26 22:37:05 INFO Upload queue status pending=227302026/10/26 22:37:05 INFO Uploading batch count=227312026/10/26 22:37:05 INFO Uploading batch count=227322026/10/26 22:37:05 INFO Uploading batch count=227332026/10/26 22:37:05 ERROR Upload failed error="upload failed" count=227342026/10/26 22:37:05 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1498716168/002/a27352026/10/26 22:37:05 INFO Upload queue status pending=227362026/10/26 22:37:05 INFO Upload queue status pending=327372026/10/26 22:37:05 INFO Uploading batch count=427382026/10/26 22:37:05 INFO Uploading batch count=427392026/10/26 22:37:05 ERROR Upload failed error="upload failed" count=427402026/10/26 22:37:05 ERROR Upload failed error="upload failed" count=42741=== CONT TestDrainTimeoutDuringIsolation/probe_cut_short2742--- PASS: TestQueueDeduplication (0.08s)27432026/10/26 22:37:05 INFO Uploading batch count=127442026/10/26 22:37:05 INFO Uploading batch count=227452026/10/26 22:37:05 INFO Upload queue status pending=327462026/10/26 22:37:05 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat4223219478/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat4223219478/002/locked/aaa: permission denied"27472026/10/26 22:37:05 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths1976446700/002/nonexistent27482026/10/26 22:37:05 INFO Uploading batch count=227492026/10/26 22:37:05 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath2056051011/002/bbb27502026/10/26 22:37:05 INFO Uploading batch count=127512026/10/26 22:37:05 ERROR Upload failed error="upload failed" count=127522026/10/26 22:37:05 INFO Upload queue status pending=227532026/10/26 22:37:05 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1498716168/002/b27542026/10/26 22:37:05 INFO Uploading batch count=227552026/10/26 22:37:05 INFO Uploading batch count=227562026/10/26 22:37:05 INFO Upload queue status pending=227572026/10/26 22:37:05 INFO Uploading batch count=127582026/10/26 22:37:05 INFO Uploading batch count=127592026/10/26 22:37:05 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat4223219478/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat4223219478/002/locked/aaa: permission denied"2760--- PASS: TestQueueRetryMovesToBack (0.10s)2761=== CONT TestWorkerRemoveFailureIsNotProgress/isolated_paths27622026/10/26 22:37:05 ERROR Drain finished with paths left in queue remaining=127632026/10/26 22:37:05 INFO Uploading batch count=227642026/10/26 22:37:05 ERROR Upload failed error="upload failed" count=227652026/10/26 22:37:05 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1498716168/002/c2766--- PASS: TestQueueEnqueueAndFetch (0.10s)2767=== CONT TestWorkerRemoveFailureIsNotProgress/pushed_batch2768--- PASS: TestQueueFetchBatchLimit (0.10s)2769=== CONT TestWorkerRemoveFailureIsNotProgress/collected_path27702026/10/26 22:37:05 INFO Uploading batch count=127712026/10/26 22:37:05 ERROR Upload failed error="upload failed" count=12772--- PASS: TestQueueRemove (0.10s)27732026/10/26 22:37:05 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1498716168/002/d27742026/10/26 22:37:05 INFO Uploading batch count=127752026/10/26 22:37:05 ERROR Upload failed error="upload failed" count=127762026/10/26 22:37:05 INFO Uploading batch count=227772026/10/26 22:37:05 ERROR Upload failed error="upload failed" count=227782026/10/26 22:37:05 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1498716168/002/e27792026/10/26 22:37:05 INFO Uploading batch count=127802026/10/26 22:37:05 ERROR Upload failed error="upload failed" count=12781--- PASS: TestQueueFetchRemoveLifecycle (0.11s)2782--- PASS: TestFailedPathPrunedByLaterClosure (0.11s)2783--- PASS: TestWorkerKeepsPathItCannotStat (0.11s)27842026/10/26 22:37:05 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1498716168/002/f2785--- PASS: TestWorkerSkipsGCdPaths (0.11s)27862026/10/26 22:37:05 ERROR Drain finished with paths left in queue remaining=12787--- PASS: TestWorkerRemovesCachedPathBatchedWithLargerClosure (0.11s)27882026/10/26 22:37:05 INFO Uploading batch count=427892026/10/26 22:37:05 ERROR Upload failed error="upload failed" count=427902026/10/26 22:37:05 ERROR Drain finished with paths left in queue remaining=102791--- PASS: TestWorkerUploadsAndRemoves (0.12s)2792--- PASS: TestDrainIsolatesPoisonPath (0.12s)2793--- PASS: TestWorkerPrunesClosureDeps (0.12s)2794--- PASS: TestDrainGivesUpWhenServerDown (0.12s)27952026/10/26 22:37:05 INFO Uploading batch count=227962026/10/26 22:37:05 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=227972026/10/26 22:37:05 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path903877792/001/nonexistent27982026/10/26 22:37:05 INFO Uploading batch count=227992026/10/26 22:37:05 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128002026/10/26 22:37:05 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=228012026/10/26 22:37:05 INFO Uploading batch count=228022026/10/26 22:37:05 ERROR Upload failed error="upload failed" count=228032026/10/26 22:37:05 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path903877792/001/nonexistent28042026/10/26 22:37:05 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128052026/10/26 22:37:05 INFO Uploading batch count=228062026/10/26 22:37:05 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128072026/10/26 22:37:05 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128082026/10/26 22:37:05 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=228092026/10/26 22:37:05 ERROR Drain finished with paths left in queue remaining=228102026/10/26 22:37:05 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path903877792/001/nonexistent28112026/10/26 22:37:05 INFO Uploading batch count=228122026/10/26 22:37:05 ERROR Upload failed error="upload failed" count=228132026/10/26 22:37:05 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128142026/10/26 22:37:05 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128152026/10/26 22:37:05 ERROR Drain finished with paths left in queue remaining=128162026/10/26 22:37:05 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128172026/10/26 22:37:05 INFO Uploading batch count=228182026/10/26 22:37:05 ERROR Upload failed error="upload failed" count=228192026/10/26 22:37:05 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128202026/10/26 22:37:05 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128212026/10/26 22:37:05 ERROR Drain finished with paths left in queue remaining=22822--- PASS: TestWorkerRemoveFailureIsNotProgress (0.00s)2823 --- PASS: TestWorkerRemoveFailureIsNotProgress/pushed_batch (0.04s)2824 --- PASS: TestWorkerRemoveFailureIsNotProgress/collected_path (0.04s)2825 --- PASS: TestWorkerRemoveFailureIsNotProgress/isolated_paths (0.05s)28262026/10/26 22:37:05 ERROR Accept failed error="too many open files"28272026/10/26 22:37:05 ERROR Failed to decode request error="read unix /build/hook4063506860/test.sock->@: i/o timeout"28282026/10/26 22:37:05 ERROR Failed to write response error="write unix /build/hook4063506860/test.sock->@: i/o timeout"2829--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)28302026/10/26 22:37:05 ERROR Upload failed error="context canceled" count=228312026/10/26 22:37:05 ERROR Upload failed error="context canceled" count=228322026/10/26 22:37:05 ERROR Drain finished with paths left in queue remaining=228332026/10/26 22:37:05 ERROR Drain finished with paths left in queue remaining=42834--- PASS: TestShutdownFinishesInFlightPush (0.00s)2835 --- PASS: TestShutdownFinishesInFlightPush/completes (0.19s)2836 --- PASS: TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout (0.28s)2837--- PASS: TestDrainTimeout (0.29s)28382026/10/26 22:37:05 ERROR Drain finished with paths left in queue remaining=428392026/10/26 22:37:05 ERROR Accept failed error="too many open files"28402026/10/26 22:37:05 ERROR Drain finished with paths left in queue remaining=32841--- PASS: TestDrainTimeoutDuringIsolation (0.00s)2842 --- PASS: TestDrainTimeoutDuringIsolation/probe_cut_short (0.23s)2843 --- PASS: TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline (0.37s)2844--- PASS: TestQueueConcurrentWriters (0.56s)28452026/10/26 22:37:05 ERROR Accept failed error="too many open files"2846--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)28472026/10/26 22:37:06 INFO Uploading batch count=128482026/10/26 22:37:06 INFO Uploading batch count=128492026/10/26 22:37:06 INFO Uploading batch count=128502026/10/26 22:37:06 ERROR Upload failed error="upload failed" count=128512026/10/26 22:37:06 INFO Uploading batch count=128522026/10/26 22:37:06 ERROR Upload failed error="upload failed" count=128532026/10/26 22:37:06 INFO Uploading batch count=128542026/10/26 22:37:06 ERROR Upload failed error="upload failed" count=128552026/10/26 22:37:06 INFO Uploading batch count=128562026/10/26 22:37:06 ERROR Upload failed error="upload failed" count=128572026/10/26 22:37:06 ERROR Drain finished with paths left in queue remaining=12858--- PASS: TestRunNotBlockedByPoisonHead (1.11s)2859--- PASS: TestQueueRemoveLargeClosure (2.51s)2860--- PASS: TestQueueEnqueueWaitsOutSlowWriter (6.08s)2861PASS2862Running signing tests...2863=== RUN TestExternalSigner2864=== PAUSE TestExternalSigner2865=== RUN TestExternalSignerWrongPublicKey2866=== PAUSE TestExternalSignerWrongPublicKey2867=== RUN TestExternalSignerErrors2868=== PAUSE TestExternalSignerErrors2869=== RUN TestExternalSignerRestartsAfterCrash2870=== PAUSE TestExternalSignerRestartsAfterCrash2871=== RUN TestExternalSignerProgramErrorKeepsProcess2872=== PAUSE TestExternalSignerProgramErrorKeepsProcess2873=== RUN TestExternalSignerClose2874=== PAUSE TestExternalSignerClose2875=== RUN TestExternalSignerRejectsInvalidPublicKey2876=== PAUSE TestExternalSignerRejectsInvalidPublicKey2877=== RUN TestExternalSignerCancellation2878=== PAUSE TestExternalSignerCancellation2879=== RUN TestGenerateFingerprint2880=== PAUSE TestGenerateFingerprint2881=== RUN TestParseSigningKey2882=== PAUSE TestParseSigningKey2883=== RUN TestSign2884=== PAUSE TestSign2885=== RUN TestSignBatch2886=== PAUSE TestSignBatch2887=== RUN TestNilKeyPublicKey2888=== PAUSE TestNilKeyPublicKey2889=== RUN TestSignErrors2890=== PAUSE TestSignErrors2891=== CONT TestExternalSignerWrongPublicKey2892=== CONT TestExternalSignerRejectsInvalidPublicKey2893=== RUN TestExternalSignerRejectsInvalidPublicKey/#002894=== CONT TestSignBatch2895=== CONT TestNilKeyPublicKey2896=== CONT TestExternalSignerClose2897--- PASS: TestNilKeyPublicKey (0.00s)2898=== CONT TestParseSigningKey2899=== RUN TestParseSigningKey/valid_32-byte_key2900=== CONT TestExternalSignerProgramErrorKeepsProcess2901=== CONT TestExternalSignerRestartsAfterCrash2902=== CONT TestExternalSignerErrors2903=== CONT TestExternalSigner2904=== CONT TestGenerateFingerprint2905=== CONT TestSign2906=== CONT TestExternalSignerCancellation2907=== CONT TestSignErrors2908=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002909=== PAUSE TestParseSigningKey/valid_32-byte_key2910=== RUN TestGenerateFingerprint/basic_with_references2911=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2912=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2913=== PAUSE TestGenerateFingerprint/basic_with_references2914=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2915=== RUN TestExternalSignerErrors/wrong_signatures_shape2916=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2917=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2918=== RUN TestExternalSignerErrors/wrong_signature_name2919=== RUN TestGenerateFingerprint/no_references2920=== PAUSE TestGenerateFingerprint/no_references2921=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2922=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2923=== RUN TestParseSigningKey/no_colon2924=== PAUSE TestParseSigningKey/no_colon2925=== PAUSE TestExternalSignerErrors/wrong_signature_name2926=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2927=== RUN TestExternalSignerErrors/wrong_signature_length2928=== RUN TestParseSigningKey/empty_name2929=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2930=== PAUSE TestExternalSignerErrors/wrong_signature_length2931=== RUN TestExternalSignerErrors/exit_at_startup2932=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2933=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2934=== PAUSE TestExternalSignerErrors/exit_at_startup2935=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2936=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2937=== PAUSE TestParseSigningKey/empty_name2938=== RUN TestGenerateFingerprint/invalid_nar_hash_length2939=== RUN TestExternalSignerErrors/invalid_JSON2940=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2941=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2942=== RUN TestParseSigningKey/invalid_base642943=== PAUSE TestParseSigningKey/invalid_base642944=== RUN TestParseSigningKey/wrong_length2945=== PAUSE TestParseSigningKey/wrong_length2946=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2947=== CONT TestParseSigningKey/empty_name2948=== PAUSE TestExternalSignerErrors/invalid_JSON2949=== RUN TestGenerateFingerprint/invalid_store_path_prefix2950=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2951=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2952=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2953=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2954=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2955=== CONT TestParseSigningKey/invalid_base642956=== RUN TestGenerateFingerprint/invalid_reference_prefix2957=== CONT TestParseSigningKey/valid_32-byte_key2958=== RUN TestExternalSignerErrors/missing_signature_name2959=== PAUSE TestExternalSignerErrors/missing_signature_name2960=== CONT TestExternalSignerRejectsInvalidPublicKey/#002961=== CONT TestParseSigningKey/wrong_length2962=== RUN TestExternalSignerErrors/invalid_signature_base642963--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2964 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2965 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2966 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2967 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2968 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2969=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2970=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2971=== CONT TestParseSigningKey/no_colon2972=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2973=== CONT TestGenerateFingerprint/invalid_store_path_prefix2974=== PAUSE TestExternalSignerErrors/invalid_signature_base642975=== CONT TestGenerateFingerprint/invalid_nar_hash_length2976=== RUN TestExternalSignerErrors/wrong_shape2977=== CONT TestGenerateFingerprint/no_references2978=== PAUSE TestExternalSignerErrors/wrong_shape2979=== RUN TestExternalSignerErrors/null2980=== PAUSE TestExternalSignerErrors/null2981=== CONT TestGenerateFingerprint/invalid_reference_prefix2982=== CONT TestGenerateFingerprint/basic_with_references2983=== RUN TestExternalSignerErrors/wrong_id2984=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2985=== PAUSE TestExternalSignerErrors/wrong_id2986=== RUN TestExternalSignerErrors/missing_signatures2987--- PASS: TestGenerateFingerprint (0.00s)2988 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2989 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2990 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2991 --- PASS: TestGenerateFingerprint/no_references (0.00s)2992 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2993 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2994 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2995=== PAUSE TestExternalSignerErrors/missing_signatures2996=== RUN TestExternalSignerErrors/too_few_signatures2997--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2998=== PAUSE TestExternalSignerErrors/too_few_signatures2999=== RUN TestExternalSignerErrors/program_error3000=== PAUSE TestExternalSignerErrors/program_error3001=== RUN TestExternalSignerErrors/exit_on_request3002=== PAUSE TestExternalSignerErrors/exit_on_request3003=== RUN TestExternalSignerErrors/unrequested_key3004=== PAUSE TestExternalSignerErrors/unrequested_key3005=== RUN TestExternalSignerErrors/null_signatures3006=== PAUSE TestExternalSignerErrors/null_signatures3007=== CONT TestExternalSignerErrors/wrong_signatures_shape3008=== CONT TestExternalSignerErrors/invalid_signature_base643009=== CONT TestExternalSignerErrors/missing_signatures3010=== CONT TestExternalSignerErrors/null_signatures3011=== CONT TestExternalSignerErrors/exit_on_request3012=== CONT TestExternalSignerErrors/missing_signature_name3013=== CONT TestExternalSignerErrors/program_error3014=== CONT TestExternalSignerErrors/wrong_shape3015=== CONT TestExternalSignerErrors/too_few_signatures3016=== CONT TestExternalSignerErrors/wrong_id3017=== CONT TestExternalSignerErrors/null3018=== CONT TestExternalSignerErrors/wrong_signature_length3019=== CONT TestExternalSignerErrors/exit_at_startup3020=== CONT TestExternalSignerErrors/unrequested_key3021=== CONT TestExternalSignerErrors/invalid_JSON3022=== CONT TestExternalSignerErrors/wrong_signature_name3023--- PASS: TestExternalSignerWrongPublicKey (0.03s)3024--- PASS: TestExternalSignerClose (0.03s)3025=== RUN TestSignErrors/nil_key3026=== PAUSE TestSignErrors/nil_key3027=== RUN TestSignErrors/nil_narinfo3028=== PAUSE TestSignErrors/nil_narinfo3029=== RUN TestSignErrors/invalid_narinfo3030=== PAUSE TestSignErrors/invalid_narinfo3031--- PASS: TestParseSigningKey (0.00s)3032 --- PASS: TestParseSigningKey/empty_name (0.00s)3033 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)3034 --- PASS: TestParseSigningKey/wrong_length (0.00s)3035 --- PASS: TestParseSigningKey/no_colon (0.00s)3036 --- PASS: TestParseSigningKey/valid_32-byte_key (0.03s)3037 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.03s)3038=== RUN TestSignErrors/canceled3039=== PAUSE TestSignErrors/canceled3040=== CONT TestSignErrors/nil_key3041=== CONT TestSignErrors/canceled3042=== CONT TestSignErrors/invalid_narinfo3043=== CONT TestSignErrors/nil_narinfo3044--- PASS: TestSignErrors (0.04s)3045 --- PASS: TestSignErrors/nil_key (0.00s)3046 --- PASS: TestSignErrors/invalid_narinfo (0.00s)3047 --- PASS: TestSignErrors/canceled (0.00s)3048 --- PASS: TestSignErrors/nil_narinfo (0.00s)3049--- PASS: TestExternalSignerErrors (0.00s)3050 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.03s)3051 --- PASS: TestExternalSignerErrors/missing_signatures (0.03s)3052 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.03s)3053 --- PASS: TestExternalSignerErrors/null_signatures (0.03s)3054 --- PASS: TestExternalSignerErrors/exit_on_request (0.03s)3055 --- PASS: TestExternalSignerErrors/program_error (0.03s)3056 --- PASS: TestExternalSignerErrors/exit_at_startup (0.03s)3057 --- PASS: TestExternalSignerErrors/missing_signature_name (0.03s)3058 --- PASS: TestExternalSignerErrors/null (0.03s)3059 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.01s)3060 --- PASS: TestExternalSignerErrors/too_few_signatures (0.03s)3061 --- PASS: TestExternalSignerErrors/wrong_shape (0.03s)3062 --- PASS: TestExternalSignerErrors/unrequested_key (0.01s)3063 --- PASS: TestExternalSignerErrors/wrong_id (0.03s)3064 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)3065 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)3066--- PASS: TestSign (0.04s)3067--- PASS: TestExternalSignerCancellation (0.04s)3068--- PASS: TestExternalSignerRestartsAfterCrash (0.04s)3069--- PASS: TestExternalSigner (0.05s)3070--- PASS: TestSignBatch (0.05s)3071PASS3072Running OpenBao signer tests...3073=== RUN TestSign3074=== PAUSE TestSign3075=== RUN TestSignErrors3076=== PAUSE TestSignErrors3077=== RUN TestServe3078=== PAUSE TestServe3079=== RUN TestServeRejectsGarbage3080=== PAUSE TestServeRejectsGarbage3081=== CONT TestServeRejectsGarbage3082=== CONT TestSignErrors3083=== CONT TestServe3084=== CONT TestSign3085=== RUN TestSignErrors/http_error3086=== PAUSE TestSignErrors/http_error3087--- PASS: TestServeRejectsGarbage (0.00s)3088--- PASS: TestServe (0.00s)3089=== RUN TestSignErrors/invalid_json3090=== PAUSE TestSignErrors/invalid_json3091=== RUN TestSignErrors/no_prefix3092=== PAUSE TestSignErrors/no_prefix3093=== RUN TestSignErrors/invalid_base643094=== PAUSE TestSignErrors/invalid_base643095=== CONT TestSignErrors/no_prefix3096=== CONT TestSignErrors/invalid_json3097=== CONT TestSignErrors/http_error3098=== CONT TestSignErrors/invalid_base643099--- PASS: TestSign (0.01s)3100--- PASS: TestSignErrors (0.00s)3101 --- PASS: TestSignErrors/http_error (0.00s)3102 --- PASS: TestSignErrors/invalid_base64 (0.00s)3103 --- PASS: TestSignErrors/no_prefix (0.00s)3104 --- PASS: TestSignErrors/invalid_json (0.00s)3105PASS3106Running niks3-hook command tests...3107=== RUN TestServeSecondSignalEndsDrain3108=== PAUSE TestServeSecondSignalEndsDrain3109=== RUN TestServeThenDrainPushesSendAcceptedBeforeShutdown3110=== PAUSE TestServeThenDrainPushesSendAcceptedBeforeShutdown3111=== CONT TestServeThenDrainPushesSendAcceptedBeforeShutdown3112=== CONT TestServeSecondSignalEndsDrain3113--- PASS: TestServeSecondSignalEndsDrain (0.09s)31142026/10/26 22:37:14 INFO Upload queue status pending=131152026/10/26 22:37:14 INFO Uploading batch count=13116--- PASS: TestServeThenDrainPushesSendAcceptedBeforeShutdown (0.14s)3117PASS3118Running rate limiter tests...3119=== RUN TestAdaptiveRateLimiter_ThreadSafety3120=== PAUSE TestAdaptiveRateLimiter_ThreadSafety3121=== CONT TestAdaptiveRateLimiter_ThreadSafety31222026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=93.1700000000000331232026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=65.2190000000000231242026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=45.65330000000001631252026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=31.9573100000000131262026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=22.37011700000000831272026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=15.65908190000000431282026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=10.96135733000000231292026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=7.67295013100000131302026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=5.371065091731312026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531322026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531332026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531342026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531352026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531362026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531372026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531382026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531392026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531402026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531412026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531422026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531432026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531442026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531452026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531462026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531472026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531482026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531492026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531502026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=16.08240545225027431512026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=11.25768381657519231522026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=7.88037867160263331532026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=5.51626507012184331542026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531552026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531562026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531572026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531582026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531592026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=5.12435000000000131602026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531612026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531622026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531632026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531642026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531652026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531662026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531672026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531682026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531692026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531702026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531712026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531722026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531732026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531742026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531752026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531762026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531772026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=5.12435000000000131782026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531792026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531802026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531812026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531822026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531832026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531842026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531852026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531862026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=5.12435000000000131872026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531882026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531892026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531902026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531912026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531922026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531932026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531942026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531952026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531962026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531972026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=531982026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=5.12435000000000131992026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532002026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532012026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532022026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532032026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532042026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532052026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532062026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532072026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532082026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532092026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532102026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532112026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532122026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532132026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532142026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532152026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532162026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=5.63678500000000132172026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532182026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532192026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532202026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=532212026/10/26 22:37:15 WARN Rate limiter backed off name=test rate=53222--- PASS: TestAdaptiveRateLimiter_ThreadSafety (0.05s)3223PASS