niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #442
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry5=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry6=== RUN TestRegisterUploadedObjectReusesConnections7=== PAUSE TestRegisterUploadedObjectReusesConnections8=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica9=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica10=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun11=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun12=== RUN TestCaseHackSuffix13=== PAUSE TestCaseHackSuffix14=== RUN TestFilterOversizedClosures15=== PAUSE TestFilterOversizedClosures16=== RUN TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure17=== PAUSE TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure18=== RUN TestUploadMultipart_PartsInParallel19=== PAUSE TestUploadMultipart_PartsInParallel20=== RUN TestUploadMultipart_FailedPartBufferNotReused21=== PAUSE TestUploadMultipart_FailedPartBufferNotReused22=== RUN TestUploadMultipart_ProducerErrorIsNotEOF23=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF24=== RUN TestPartSizeForNAR25=== PAUSE TestPartSizeForNAR26=== RUN TestUploadMultipart_SupersededByPeer27=== PAUSE TestUploadMultipart_SupersededByPeer28=== RUN TestDumpPathCaseHackMatchesNix29--- PASS: TestDumpPathCaseHackMatchesNix (0.04s)30=== RUN TestDumpPathCaseHackCollision31--- PASS: TestDumpPathCaseHackCollision (0.00s)32=== RUN TestSupersededNARStillUploadsListing33=== PAUSE TestSupersededNARStillUploadsListing34=== RUN TestTruncatedNARDumpIsNotCompleted35=== PAUSE TestTruncatedNARDumpIsNotCompleted36=== RUN TestDumpPathMatchesNix37=== PAUSE TestDumpPathMatchesNix38=== RUN TestDumpPathSingleFile39=== PAUSE TestDumpPathSingleFile40=== RUN TestDumpPathWriterError41=== PAUSE TestDumpPathWriterError42=== RUN TestDumpPathWriterErrorStopsReading43 nar_test.go:289: read 188544 of 32768000 bytes44--- PASS: TestDumpPathWriterErrorStopsReading (0.57s)45=== RUN TestEncodeNixBase3246=== PAUSE TestEncodeNixBase3247=== RUN TestEncodeNixBase32WithRealHash48=== PAUSE TestEncodeNixBase32WithRealHash49=== RUN TestConvertHashToNix3250=== PAUSE TestConvertHashToNix3251=== RUN TestGetStorePathHash52=== PAUSE TestGetStorePathHash53=== RUN TestPathInfoHashCompatibility54=== PAUSE TestPathInfoHashCompatibility55=== RUN TestParsePathInfoJSON56=== PAUSE TestParsePathInfoJSON57=== RUN TestParsePathInfoJSONMultiplePaths58=== PAUSE TestParsePathInfoJSONMultiplePaths59=== RUN TestPathInfoCACompatibility60=== PAUSE TestPathInfoCACompatibility61=== RUN TestUploadPendingObjectsStopsStartingAfterFailure62--- PASS: TestUploadPendingObjectsStopsStartingAfterFailure (0.02s)63=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent64=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent65=== RUN TestCompletePendingClosure_NotFoundWithoutKey66=== PAUSE TestCompletePendingClosure_NotFoundWithoutKey67=== RUN TestRateLimiterFeedback68=== PAUSE TestRateLimiterFeedback69=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess70=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess71=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer72=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer73=== RUN TestResolveStorePath74=== PAUSE TestResolveStorePath75=== RUN TestDoWithRetry_BodyReplayedViaGetBody76=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody77=== RUN TestRetryTimeoutOutlastsMaxRetries78=== PAUSE TestRetryTimeoutOutlastsMaxRetries79=== RUN TestDoWithRetry_FinalResponseBodyReadable80=== PAUSE TestDoWithRetry_FinalResponseBodyReadable81=== RUN TestShellSplit82=== PAUSE TestShellSplit83=== RUN TestShellSplitErrors84=== PAUSE TestShellSplitErrors85=== RUN TestStreamPushReportsEveryPath86=== PAUSE TestStreamPushReportsEveryPath87=== RUN TestStreamPushBatchesUnderLoad88=== PAUSE TestStreamPushBatchesUnderLoad89=== RUN TestStreamPushIsolatesFailures90=== PAUSE TestStreamPushIsolatesFailures91=== RUN TestStreamPushGivesUpOnDeadServer92=== PAUSE TestStreamPushGivesUpOnDeadServer93=== RUN TestStreamPushRequestLine94=== PAUSE TestStreamPushRequestLine95=== RUN TestStreamPushReportsSignatures96=== PAUSE TestStreamPushReportsSignatures97=== RUN TestStreamPushReportsSkippedPaths98=== PAUSE TestStreamPushReportsSkippedPaths99=== RUN TestClientSignaturesByStorePath100=== PAUSE TestClientSignaturesByStorePath101=== RUN TestStreamPushStopsWhenCanceled102=== PAUSE TestStreamPushStopsWhenCanceled103=== RUN TestStreamPushStopsOnCancel104=== PAUSE TestStreamPushStopsOnCancel105=== RUN TestStreamPushStartsNothingOnSlotFreedByCancel106=== PAUSE TestStreamPushStartsNothingOnSlotFreedByCancel107=== RUN TestSetClientTLS108=== PAUSE TestSetClientTLS109=== RUN TestSetClientTLSDoesNotMutateDefaultTransport110=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport111=== RUN TestSetClientTLSErrors112=== PAUSE TestSetClientTLSErrors113=== RUN TestStaticToken114=== PAUSE TestStaticToken115=== RUN TestFileTokenReadsAndCaches116=== PAUSE TestFileTokenReadsAndCaches117=== RUN TestFileTokenMissing118=== PAUSE TestFileTokenMissing119=== RUN TestFileTokenEmpty120=== PAUSE TestFileTokenEmpty121=== RUN TestScriptTokenNoExpiryRerunsEveryCall122=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall123=== RUN TestScriptTokenCachesUntilRefresh124=== PAUSE TestScriptTokenCachesUntilRefresh125=== RUN TestScriptTokenEmptyToken126=== PAUSE TestScriptTokenEmptyToken127=== RUN TestScriptTokenBadJSON128=== PAUSE TestScriptTokenBadJSON129=== RUN TestScriptTokenScriptFails130=== PAUSE TestScriptTokenScriptFails131=== RUN TestScriptTokenEmptyCommand132=== PAUSE TestScriptTokenEmptyCommand133=== RUN TestScriptTokenDoesNotWaitForItsChildren134=== PAUSE TestScriptTokenDoesNotWaitForItsChildren135=== CONT TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure136=== CONT TestScriptTokenEmptyCommand137=== CONT TestStreamPushStartsNothingOnSlotFreedByCancel138--- PASS: TestScriptTokenEmptyCommand (0.00s)139=== CONT TestScriptTokenEmptyToken140=== CONT TestStreamPushStopsOnCancel141=== RUN TestStreamPushStopsOnCancel/waiting_for_input142=== CONT TestPathInfoCACompatibility143=== CONT TestRateLimiterFeedback144=== RUN TestPathInfoCACompatibility/null_ca_field145=== RUN TestRateLimiterFeedback/429_enables_limiter146=== CONT TestCompletePendingClosure_NotFoundWithoutKey147=== PAUSE TestRateLimiterFeedback/429_enables_limiter148=== PAUSE TestStreamPushStopsOnCancel/waiting_for_input149=== RUN TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot150=== PAUSE TestPathInfoCACompatibility/null_ca_field151=== CONT TestScriptTokenDoesNotWaitForItsChildren152=== CONT TestScriptTokenScriptFails153=== RUN TestRateLimiterFeedback/503_enables_limiter154=== PAUSE TestRateLimiterFeedback/503_enables_limiter155=== CONT TestScriptTokenBadJSON156=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter157=== CONT TestScriptTokenNoExpiryRerunsEveryCall158=== CONT TestFileTokenEmpty159=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter160=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter161=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter162=== CONT TestStreamPushStopsWhenCanceled163=== CONT TestParsePathInfoJSON164=== CONT TestFileTokenReadsAndCaches165=== CONT TestStaticToken166=== RUN TestParsePathInfoJSON/Nix_format167=== CONT TestStreamPushReportsSkippedPaths168=== CONT TestClientSignaturesByStorePath169=== PAUSE TestParsePathInfoJSON/Nix_format170=== CONT TestSetClientTLSDoesNotMutateDefaultTransport171=== CONT TestFileTokenMissing172=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent173=== CONT TestSetClientTLS174=== CONT TestStreamPushGivesUpOnDeadServer175=== CONT TestParsePathInfoJSONMultiplePaths176=== CONT TestDumpPathMatchesNix177=== PAUSE TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot178=== RUN TestPathInfoCACompatibility/old_string_format_-_text179=== RUN TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs180=== CONT TestScriptTokenCachesUntilRefresh181=== CONT TestResolveStorePath182=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess183--- PASS: TestStreamPushStopsWhenCanceled (0.00s)184=== CONT TestSetClientTLSErrors185=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs186=== CONT TestStreamPushReportsEveryPath187=== CONT TestStreamPushReportsSignatures188=== RUN TestParsePathInfoJSON/Lix_format189=== PAUSE TestParsePathInfoJSON/Lix_format190=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier191=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier192=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up193=== RUN TestParsePathInfoJSON/empty_input194=== CONT TestStreamPushRequestLine195=== CONT TestShellSplit196=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up197=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier198=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier199=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client200=== CONT TestShellSplitErrors201=== CONT TestStreamPushBatchesUnderLoad202=== CONT TestDoWithRetry_FinalResponseBodyReadable203=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client204=== CONT TestDoWithRetry_BodyReplayedViaGetBody205=== CONT TestStreamPushIsolatesFailures206=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths207=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text208--- PASS: TestStaticToken (0.00s)209=== RUN TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout210=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout211=== CONT TestRetryTimeoutOutlastsMaxRetries212=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive213=== RUN TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot214=== PAUSE TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot215=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths216=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths217=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer218=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client219--- PASS: TestFileTokenEmpty (0.00s)220--- PASS: TestClientSignaturesByStorePath (0.00s)221--- PASS: TestStreamPushReportsSkippedPaths (0.00s)222=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client223=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths224=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive225=== PAUSE TestParsePathInfoJSON/empty_input226--- PASS: TestCompletePendingClosure_NotFoundWithoutKey (0.00s)227=== RUN TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot228=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false229=== CONT TestDumpPathSingleFile230--- PASS: TestScriptTokenScriptFails (0.00s)231--- PASS: TestFileTokenReadsAndCaches (0.00s)232--- PASS: TestStreamPushReportsSignatures (0.00s)233=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false234=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true235=== PAUSE TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot236--- PASS: TestStreamPushIsolatesFailures (0.00s)237=== CONT TestPartSizeForNAR238=== RUN TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot239=== RUN TestParsePathInfoJSON/whitespace_only240--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)241=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true242=== CONT TestTruncatedNARDumpIsNotCompleted243=== CONT TestSupersededNARStillUploadsListing244=== RUN TestSupersededNARStillUploadsListing/small_NAR245=== RUN TestPathInfoCACompatibility/new_structured_format_-_text246=== CONT TestUploadMultipart_SupersededByPeer247=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text248=== CONT TestUploadMultipart_PartsInParallel249=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method250=== PAUSE TestParsePathInfoJSON/whitespace_only251=== RUN TestPartSizeForNAR/zero_stays_at_minimum252=== RUN TestParsePathInfoJSON/invalid_JSON253=== PAUSE TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot254=== RUN TestStreamPushStopsOnCancel/lines_read_but_not_taken255=== CONT TestUploadMultipart_FailedPartBufferNotReused256=== PAUSE TestParsePathInfoJSON/invalid_JSON257=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum258=== PAUSE TestStreamPushStopsOnCancel/lines_read_but_not_taken259=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica260=== CONT TestUploadMultipart_ProducerErrorIsNotEOF261=== PAUSE TestSupersededNARStillUploadsListing/small_NAR262=== RUN TestUploadMultipart_SupersededByPeer/exists263=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method264=== PAUSE TestUploadMultipart_SupersededByPeer/exists265--- PASS: TestFileTokenMissing (0.00s)266=== RUN TestPartSizeForNAR/small_stays_at_minimum267=== RUN TestSetClientTLSErrors/missing_cert_file268=== CONT TestFilterOversizedClosures269=== CONT TestCaseHackSuffix270=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part271=== RUN TestSupersededNARStillUploadsListing/dump_cut_short272=== RUN TestFilterOversizedClosures/no_limit_keeps_everything273=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything274=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short275=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails276=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails277=== RUN TestUploadMultipart_SupersededByPeer/missing278--- PASS: TestStreamPushReportsEveryPath (0.00s)279=== CONT TestEncodeNixBase32280=== PAUSE TestUploadMultipart_SupersededByPeer/missing281=== PAUSE TestPartSizeForNAR/small_stays_at_minimum282=== RUN TestEncodeNixBase32/test_string_hash283=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum284=== PAUSE TestEncodeNixBase32/test_string_hash285=== PAUSE TestSetClientTLSErrors/missing_cert_file286--- PASS: TestShellSplit (0.00s)287=== CONT TestGetStorePathHash288--- PASS: TestShellSplitErrors (0.00s)289=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum290=== RUN TestGetStorePathHash/valid_store_path291=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part292=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts293=== PAUSE TestGetStorePathHash/valid_store_path294=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun295=== RUN TestGetStorePathHash/basename_without_hyphen_should_error296=== RUN TestEncodeNixBase32/empty_input297=== CONT TestConvertHashToNix32298=== RUN TestConvertHashToNix32/SRI_format_to_Nix32299=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error300=== RUN TestSetClientTLSErrors/missing_key_file301=== CONT TestDumpPathWriterError302=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error303=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped304=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped305=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error306=== RUN TestFilterOversizedClosures/all_closures_skipped307=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error308=== PAUSE TestFilterOversizedClosures/all_closures_skipped309=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error310=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry311=== CONT TestRegisterUploadedObjectReusesConnections312=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary313--- PASS: TestResolveStorePath (0.00s)314=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32315=== RUN TestConvertHashToNix32/already_Nix32_format316=== PAUSE TestSetClientTLSErrors/missing_key_file317=== RUN TestSetClientTLSErrors/missing_ca_file318=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary319=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts320--- PASS: TestScriptTokenBadJSON (0.00s)321=== CONT TestPathInfoHashCompatibility322--- PASS: TestScriptTokenEmptyToken (0.01s)323=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)324=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)325=== PAUSE TestConvertHashToNix32/already_Nix32_format326=== RUN TestPartSizeForNAR/1_TiB327=== RUN TestConvertHashToNix32/invalid_format328--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.01s)329--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)330=== CONT TestDoServerRequestAttachesToken331=== PAUSE TestSetClientTLSErrors/missing_ca_file332=== RUN TestSetClientTLSErrors/invalid_ca_file333=== PAUSE TestSetClientTLSErrors/invalid_ca_file334=== CONT TestRateLimiterFeedback/429_enables_limiter335=== PAUSE TestConvertHashToNix32/invalid_format336=== PAUSE TestPartSizeForNAR/1_TiB337=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon338=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon339=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI340=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI341=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512342=== PAUSE TestEncodeNixBase32/empty_input343=== CONT TestRateLimiterFeedback/503_enables_limiter344=== RUN TestPartSizeForNAR/5_TiB_S3_max_object345=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512346--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.16s)347=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object348=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter349=== RUN TestPartSizeForNAR/capped_at_5_GiB350=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter351--- PASS: TestScriptTokenCachesUntilRefresh (0.16s)352=== PAUSE TestPartSizeForNAR/capped_at_5_GiB353--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.16s)354--- PASS: TestDumpPathSingleFile (0.16s)355=== CONT TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout356=== CONT TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs357=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier358=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client359--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)360=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client361=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up362--- PASS: TestRateLimiterFeedback (0.00s)363 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)364 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)365 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)366 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)367=== RUN TestSetClientTLS/rejects_connection_without_client_cert368=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert369=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA370=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA371=== RUN TestSetClientTLS/preserves_debug_logging_transport372=== PAUSE TestSetClientTLS/preserves_debug_logging_transport373=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier374=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths375--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.17s)376=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths377--- PASS: TestDoServerRequestAttachesToken (0.02s)378=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false379=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true380=== CONT TestParsePathInfoJSON/Nix_format381=== CONT TestParsePathInfoJSON/empty_input382=== CONT TestParsePathInfoJSON/invalid_JSON383=== CONT TestParsePathInfoJSON/whitespace_only384=== CONT TestParsePathInfoJSON/Lix_format385=== CONT TestStreamPushStopsOnCancel/lines_read_but_not_taken386--- PASS: TestParsePathInfoJSON (0.01s)387 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)388 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)389 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)390 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)391 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)392=== CONT TestStreamPushStopsOnCancel/waiting_for_input393--- PASS: TestStreamPushBatchesUnderLoad (0.00s)394 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)395 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)396=== CONT TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot397=== CONT TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot398=== CONT TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot399--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)400 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)401 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)402=== CONT TestEncodeNixBase32WithRealHash403=== CONT TestPathInfoCACompatibility/null_ca_field404--- PASS: TestEncodeNixBase32WithRealHash (0.00s)405=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method406=== CONT TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot407=== CONT TestPathInfoCACompatibility/new_structured_format_-_text408=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive409=== CONT TestPathInfoCACompatibility/old_string_format_-_text410--- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent (0.00s)411 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier (0.01s)412 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client (0.01s)413 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client (0.01s)414 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier (0.01s)415 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up (0.02s)416=== CONT TestSupersededNARStillUploadsListing/dump_cut_short417=== CONT TestSupersededNARStillUploadsListing/small_NAR418--- PASS: TestPathInfoCACompatibility (0.17s)419 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)420 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)421 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)422 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)423 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)424=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails425=== CONT TestUploadMultipart_SupersededByPeer/exists426=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped427=== CONT TestUploadMultipart_SupersededByPeer/missing428=== CONT TestFilterOversizedClosures/all_closures_skipped429=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error430=== CONT TestGetStorePathHash/basename_without_hyphen_should_error431=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error432=== CONT TestGetStorePathHash/valid_store_path433=== CONT TestFilterOversizedClosures/no_limit_keeps_everything434--- PASS: TestGetStorePathHash (0.00s)435 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)436 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)437 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)438 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)439=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary440=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part441--- PASS: TestFilterOversizedClosures (0.00s)442 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)443 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)444 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)445--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.32s)446=== CONT TestSetClientTLSErrors/missing_cert_file447--- PASS: TestStreamPushStopsOnCancel (0.01s)448 --- PASS: TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot (0.29s)449 --- PASS: TestStreamPushStopsOnCancel/lines_read_but_not_taken (0.29s)450 --- PASS: TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot (0.29s)451 --- PASS: TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot (0.29s)452 --- PASS: TestStreamPushStopsOnCancel/waiting_for_input (0.30s)453 --- PASS: TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot (0.30s)454=== CONT TestConvertHashToNix32/SRI_format_to_Nix32455=== CONT TestSetClientTLSErrors/invalid_ca_file456=== CONT TestSetClientTLSErrors/missing_ca_file457--- PASS: TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure (0.48s)458=== CONT TestSetClientTLSErrors/missing_key_file459=== CONT TestConvertHashToNix32/invalid_format460=== CONT TestConvertHashToNix32/already_Nix32_format461--- PASS: TestConvertHashToNix32 (0.00s)462 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)463 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)464 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)465=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)466=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI467=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512468=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon469=== CONT TestEncodeNixBase32/empty_input470=== CONT TestPartSizeForNAR/zero_stays_at_minimum471--- PASS: TestPathInfoHashCompatibility (0.01s)472 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)473 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)474 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)475 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)476=== CONT TestEncodeNixBase32/test_string_hash477=== CONT TestPartSizeForNAR/capped_at_5_GiB478--- PASS: TestEncodeNixBase32 (0.01s)479 --- PASS: TestEncodeNixBase32/empty_input (0.00s)480 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)481=== CONT TestPartSizeForNAR/5_TiB_S3_max_object482=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts483=== CONT TestPartSizeForNAR/small_stays_at_minimum484=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum485--- PASS: TestCaseHackSuffix (0.32s)486=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA487=== CONT TestSetClientTLS/rejects_connection_without_client_cert488--- PASS: TestSetClientTLSErrors (0.17s)489 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)490 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)491 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)492 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)493=== CONT TestPartSizeForNAR/1_TiB494--- PASS: TestPartSizeForNAR (0.17s)495 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)496 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)497 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)498 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)499 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)500 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)501 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)502=== CONT TestSetClientTLS/preserves_debug_logging_transport503--- PASS: TestUploadMultipart_SupersededByPeer (0.16s)504 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)505 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)506--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.68s)507--- PASS: TestStreamPushStartsNothingOnSlotFreedByCancel (0.73s)508--- PASS: TestDumpPathWriterError (0.57s)509--- PASS: TestSetClientTLS (0.18s)510 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.24s)511 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.24s)512 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.32s)513--- PASS: TestStreamPushRequestLine (0.88s)514--- PASS: TestRegisterUploadedObjectReusesConnections (0.73s)515--- PASS: TestUploadMultipart_ProducerErrorIsNotEOF (0.16s)516 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary (0.44s)517 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part (0.48s)518--- PASS: TestDumpPathMatchesNix (0.96s)519--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)520--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)521--- PASS: TestTruncatedNARDumpIsNotCompleted (1.46s)522--- PASS: TestSupersededNARStillUploadsListing (0.16s)523 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.47s)524 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.20s)525 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (1.28s)526--- PASS: TestUploadMultipart_FailedPartBufferNotReused (1.52s)527--- PASS: TestUploadMultipart_PartsInParallel (1.56s)528--- PASS: TestScriptTokenDoesNotWaitForItsChildren (0.00s)529 --- PASS: TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout (2.01s)530 --- PASS: TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs (2.31s)531PASS532Running server tests...533The files belonging to this database system will be owned by user "nixbld".534This user must also own the server process.535536The database cluster will be initialized with locale "C".537The default database encoding has accordingly been set to "SQL_ASCII".538The default text search configuration will be set to "english".539540Data page checksums are enabled.541542creating directory /build/postgres2635849909/data ... ok543creating subdirectories ... ok544selecting dynamic shared memory implementation ... posix545selecting default "max_connections" ... 100546selecting default "shared_buffers" ... 128MB547selecting default time zone ... UTC548creating configuration files ... ok549running bootstrap script ... ok550performing post-bootstrap initialization ... ok551syncing data to disk ... ok552553initdb: warning: enabling "trust" authentication for local connections554initdb: 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.555556Success. You can now start the database server using:557558 pg_ctl -D /build/postgres2635849909/data -l logfile start559560/build/postgres2635849909:5432 - no response5612026-10-27 08:49:37.131 UTC [169] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit5622026-10-27 08:49:37.132 UTC [169] LOG: listening on Unix socket "/build/postgres2635849909/.s.PGSQL.5432"5632026-10-27 08:49:37.136 UTC [176] LOG: database system was shut down at 2026-10-27 08:49:36 UTC5642026-10-27 08:49:37.139 UTC [169] LOG: database system is ready to accept connections565/build/postgres2635849909:5432 - accepting connections566=== RUN TestService_AuthMiddleware567=== PAUSE TestService_AuthMiddleware568=== RUN TestService_AuthMiddleware_MTLSProxyHeader569=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader570=== RUN TestService_AuthMiddleware_MTLSBoundSubjects571=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects572=== RUN TestService_ReadAuthMiddleware573=== PAUSE TestService_ReadAuthMiddleware574=== RUN TestService_AuthMiddleware_OIDC575=== PAUSE TestService_AuthMiddleware_OIDC576=== RUN TestService_RequireScope_OIDC577=== PAUSE TestService_RequireScope_OIDC578=== RUN TestService_ReadScope_PublicByDefault579=== PAUSE TestService_ReadScope_PublicByDefault580=== RUN TestCacheConfigHandler581=== PAUSE TestCacheConfigHandler582=== RUN TestCacheStatsHandler583=== PAUSE TestCacheStatsHandler584=== RUN TestClientCADerivations585=== PAUSE TestClientCADerivations586=== RUN TestClientErrorHandling587=== PAUSE TestClientErrorHandling588=== RUN TestClientIntegration589=== PAUSE TestClientIntegration590=== RUN TestClientMultipleUploads591=== PAUSE TestClientMultipleUploads592=== RUN TestClientWithDependencies593=== PAUSE TestClientWithDependencies594=== RUN TestClientSharedPathCommittedMidPush595=== PAUSE TestClientSharedPathCommittedMidPush596=== RUN TestPinProtectsFromGC597=== PAUSE TestPinProtectsFromGC598=== RUN TestClientPushesUseOnePush599=== PAUSE TestClientPushesUseOnePush600=== RUN TestClientFallsBackToClosures601=== PAUSE TestClientFallsBackToClosures602=== RUN TestDeleteClosuresRacingPins603=== PAUSE TestDeleteClosuresRacingPins604=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock605=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock606=== RUN TestResolveDBConnectionString607=== PAUSE TestResolveDBConnectionString608=== RUN TestConnectWaitsForAPeerMigration609=== PAUSE TestConnectWaitsForAPeerMigration610=== RUN TestConnectSerialisesConcurrentMigrations611=== PAUSE TestConnectSerialisesConcurrentMigrations612=== RUN TestLeadElectsOneAndHandsOver613=== PAUSE TestLeadElectsOneAndHandsOver614=== RUN TestLeadIncumbentWinsAfterRestart6152026/10/27 08:49:37 INFO lead: acquired remote=192.0.2.1:12346162026/10/27 08:49:38 INFO lead: released remote=192.0.2.1:12346172026/10/27 08:49:38 INFO lead: acquired remote=192.0.2.1:12346182026/10/27 08:49:39 INFO lead: released remote=192.0.2.1:1234619--- PASS: TestLeadIncumbentWinsAfterRestart (1.84s)620=== RUN TestLeadIncumbentAnnouncesAtOnce621=== PAUSE TestLeadIncumbentAnnouncesAtOnce622=== RUN TestLeadEndsOnShutdown623=== PAUSE TestLeadEndsOnShutdown624=== RUN TestLeadEndsWhenItsConnectionHangs6252026/10/27 08:49:39 INFO lead: acquired remote=192.0.2.1:12346262026-10-27 08:49:40.682 UTC [263] FATAL: terminating connection due to administrator command6272026/10/27 08:49:40 INFO lead: acquired remote=192.0.2.1:12346282026/10/27 08:49:41 WARN lead: lock connection lost error="timeout: context deadline exceeded"6292026/10/27 08:49:41 INFO lead: released remote=192.0.2.1:12346302026/10/27 08:49:42 INFO lead: released remote=192.0.2.1:1234631--- PASS: TestLeadEndsWhenItsConnectionHangs (2.92s)632=== RUN TestGCAdvisoryLockBlocksConcurrentRun633=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun634=== RUN TestGCBugBareHashReferences635=== PAUSE TestGCBugBareHashReferences636=== RUN TestGCMetrics637=== PAUSE TestGCMetrics638=== RUN TestPushDedupSurvivesConcurrentGC639=== PAUSE TestPushDedupSurvivesConcurrentGC640=== RUN TestDeduplicatedObjectsRecordedAsPending641=== PAUSE TestDeduplicatedObjectsRecordedAsPending642=== RUN TestGCSweepSkipsPendingObjects643=== PAUSE TestGCSweepSkipsPendingObjects644=== RUN TestTombstonedObjectOfferedWithoutWaiting645=== PAUSE TestTombstonedObjectOfferedWithoutWaiting646=== RUN TestGCSweepDeliversEachKeyOnce647=== PAUSE TestGCSweepDeliversEachKeyOnce648=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection649=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection650=== RUN TestForceGCDuringPushOffersSweptObject651=== PAUSE TestForceGCDuringPushOffersSweptObject652=== RUN TestFailedS3DeleteKeepsTombstone653=== PAUSE TestFailedS3DeleteKeepsTombstone654=== RUN TestSweepSkipsRowsLockedByPush655=== PAUSE TestSweepSkipsRowsLockedByPush656=== RUN TestRegisterCompletedObjectNeedsPendingRow657=== PAUSE TestRegisterCompletedObjectNeedsPendingRow658=== RUN TestGetExistingObjectsLocksRows659=== PAUSE TestGetExistingObjectsLocksRows660=== RUN TestSweepRechecksPendingAfterLocking661=== PAUSE TestSweepRechecksPendingAfterLocking662=== RUN TestPushWaitsForSweepHoldingRow663=== PAUSE TestPushWaitsForSweepHoldingRow664=== RUN TestCommitRacingPendingCleanupKeepsObjects665=== PAUSE TestCommitRacingPendingCleanupKeepsObjects666=== RUN TestGCEndsOnShutdown667=== PAUSE TestGCEndsOnShutdown668=== RUN TestGCTaskStore_StartNew669=== PAUSE TestGCTaskStore_StartNew670=== RUN TestGCTaskStore_DeduplicateSameParams671=== PAUSE TestGCTaskStore_DeduplicateSameParams672=== RUN TestGCTaskStore_ConflictDifferentParams673=== PAUSE TestGCTaskStore_ConflictDifferentParams674=== RUN TestGCTaskStore_GetEmpty675=== PAUSE TestGCTaskStore_GetEmpty676=== RUN TestGCTaskStore_GetReturnsLatest677=== PAUSE TestGCTaskStore_GetReturnsLatest678=== RUN TestGCTaskStore_CompletedAllowsNewTask679=== PAUSE TestGCTaskStore_CompletedAllowsNewTask680=== RUN TestGCTaskStore_PhaseUpdates681=== PAUSE TestGCTaskStore_PhaseUpdates682=== RUN TestGCTaskStore_Fail683=== PAUSE TestGCTaskStore_Fail684=== RUN TestGracefulShutdownDrainsInflight685=== PAUSE TestGracefulShutdownDrainsInflight686=== RUN TestService_healthCheckHandler687=== PAUSE TestService_healthCheckHandler688=== RUN TestService_readinessHandler689=== PAUSE TestService_readinessHandler690=== RUN TestGenerateLandingPage691=== PAUSE TestGenerateLandingPage692=== RUN TestChildrenInheritRaisedFileLimit693=== PAUSE TestChildrenInheritRaisedFileLimit694=== RUN TestCacheConfigHandlerMaxNarSize695=== PAUSE TestCacheConfigHandlerMaxNarSize696=== RUN TestCreatePendingClosureRejectsOversizedNAR697=== PAUSE TestCreatePendingClosureRejectsOversizedNAR698=== RUN TestNARDeduplicationMetadataUploadBug699=== PAUSE TestNARDeduplicationMetadataUploadBug700=== RUN TestMetricsInventory701=== PAUSE TestMetricsInventory702=== RUN TestMetricsCommit703=== PAUSE TestMetricsCommit704=== RUN TestService_NativeMTLS705=== PAUSE TestService_NativeMTLS706=== RUN TestServerTLSConfig707=== PAUSE TestServerTLSConfig708=== RUN TestMultipartCleanup709=== PAUSE TestMultipartCleanup710=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded711=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded712=== RUN TestPendingCleanupUsesOneCutoff713=== PAUSE TestPendingCleanupUsesOneCutoff714=== RUN TestPendingClosureFailureTracksEveryUpload715=== PAUSE TestPendingClosureFailureTracksEveryUpload716=== RUN TestPendingClosureFailureAbortsItsUploads717=== PAUSE TestPendingClosureFailureAbortsItsUploads718=== RUN TestObjectStatsTrigger719=== PAUSE TestObjectStatsTrigger720=== RUN TestObjectStatsUpdatedOncePerCommit721=== PAUSE TestObjectStatsUpdatedOncePerCommit722=== RUN TestReconnectLeavesObjectsUnlocked723=== PAUSE TestReconnectLeavesObjectsUnlocked724=== RUN TestOrphanedObjectsGC725=== PAUSE TestOrphanedObjectsGC726=== RUN TestOrphanedObjectsGCStressTest727=== PAUSE TestOrphanedObjectsGCStressTest728=== RUN TestCreatePin_ReservedPins729=== PAUSE TestCreatePin_ReservedPins730=== RUN TestConcurrentPinUpdatesAgree731=== PAUSE TestConcurrentPinUpdatesAgree732=== RUN TestCreatePinRejectsBadInput733=== PAUSE TestCreatePinRejectsBadInput734=== RUN TestDeletePinKeepsRowWhenS3Fails735=== PAUSE TestDeletePinKeepsRowWhenS3Fails736=== RUN TestPresentReportsOnlyClosureRoots737=== PAUSE TestPresentReportsOnlyClosureRoots738=== RUN TestPresentRefreshesOnlyStaleClosures739=== PAUSE TestPresentRefreshesOnlyStaleClosures740=== RUN TestPresentNotReportedWhileGCDeletesClosure741=== PAUSE TestPresentNotReportedWhileGCDeletesClosure742=== RUN TestParseSingleRange743=== PAUSE TestParseSingleRange744=== RUN TestProxyHeadersOnlyTrustedOnSocket7452026/10/27 08:49:42 INFO Starting HTTP server address=127.0.0.1:458697462026/10/27 08:49:42 INFO Starting HTTP server address=proxy.sock7472026/10/27 08:49:42 WARN mTLS auth: subject not in bound subjects subject="CN=someone"7482026/10/27 08:49:42 INFO Shutdown signal received, draining in-flight requests timeout=10s749--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.10s)750=== RUN TestIsValidCachePath751=== PAUSE TestIsValidCachePath752=== RUN TestReadProxyNarinfo753=== PAUSE TestReadProxyNarinfo754=== RUN TestReadProxyNarinfoAlreadyDecompressed755=== PAUSE TestReadProxyNarinfoAlreadyDecompressed756=== RUN TestReadProxyContentNegotiation757=== PAUSE TestReadProxyContentNegotiation758=== RUN TestReadProxyNarStreaming759=== PAUSE TestReadProxyNarStreaming760=== RUN TestReadProxy404And429761=== PAUSE TestReadProxy404And429762=== RUN TestReadProxyInvalidPath763=== PAUSE TestReadProxyInvalidPath764=== RUN TestReadProxyHead765=== PAUSE TestReadProxyHead766=== RUN TestReadProxyOutlastsServerWriteTimeout767=== PAUSE TestReadProxyOutlastsServerWriteTimeout768=== RUN TestReadProxyConditionalGet769=== PAUSE TestReadProxyConditionalGet770=== RUN TestReadProxyRootRedirectsToIndexHTML771=== PAUSE TestReadProxyRootRedirectsToIndexHTML772=== RUN TestReadProxyDisabled773=== PAUSE TestReadProxyDisabled774=== RUN TestReadRedirectNar775=== PAUSE TestReadRedirectNar776=== RUN TestReadRedirectKeepsNarinfoProxied777=== PAUSE TestReadRedirectKeepsNarinfoProxied778=== RUN TestReadProxyRangeRequest779=== PAUSE TestReadProxyRangeRequest780=== RUN TestReadRedirectUsesPublicS3URL781=== PAUSE TestReadRedirectUsesPublicS3URL782=== RUN TestPush_OverlappingRootsStoreOneRowPerKey783=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey784=== RUN TestPush_CompleteCommitsEveryRoot785=== PAUSE TestPush_CompleteCommitsEveryRoot786=== RUN TestPush_RepeatedRootCommitsOnce787=== PAUSE TestPush_RepeatedRootCommitsOnce788=== RUN TestPush_CompleteWaitsForCleanupOfThePush789=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush790=== RUN TestPush_RootsAreLockedInByteOrder791=== PAUSE TestPush_RootsAreLockedInByteOrder792=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit793=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit794=== RUN TestPush_RejectsBadRequests795=== PAUSE TestPush_RejectsBadRequests796=== RUN TestPush_SignsNarinfosOfItsPendingObjects797=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects798=== RUN TestRedundantMultipartUpload799=== PAUSE TestRedundantMultipartUpload800=== RUN TestCompleteMultipartUpload_ErrorButObjectExists801=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists802=== RUN TestCompletedNarNotReofferedAcrossClosures803=== PAUSE TestCompletedNarNotReofferedAcrossClosures804=== RUN TestPresignedUploadRegisteredBeforeCommit805=== PAUSE TestPresignedUploadRegisteredBeforeCommit806=== RUN TestService_Rustfstest807=== PAUSE TestService_Rustfstest808=== RUN TestParseSize809=== PAUSE TestParseSize810=== RUN TestSkippedUploadsHandler811=== PAUSE TestSkippedUploadsHandler812=== RUN TestSystemdListenerNotActivated813--- PASS: TestSystemdListenerNotActivated (0.00s)814=== RUN TestWatchdogBeatsWhenHealthy815--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)816=== RUN TestWatchdogSkipsWhenUnhealthy8172026/10/27 08:49:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8182026/10/27 08:49:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8192026/10/27 08:49:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8202026/10/27 08:49:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8212026/10/27 08:49:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8222026/10/27 08:49:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8232026/10/27 08:49:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8242026/10/27 08:49:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8252026/10/27 08:49:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8262026/10/27 08:49:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"827--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)828=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle829=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle830=== RUN TestProxyWriteTimeout831=== PAUSE TestProxyWriteTimeout832=== RUN TestPendingClosureWriteTimeout833=== PAUSE TestPendingClosureWriteTimeout834=== RUN TestIsValidUploadKey835=== PAUSE TestIsValidUploadKey836=== RUN TestUploadHandlersRejectInvalidKeys837=== PAUSE TestUploadHandlersRejectInvalidKeys838=== RUN TestUploadHandlersRejectOversizedBody839=== PAUSE TestUploadHandlersRejectOversizedBody840=== RUN TestService_cleanupPendingClosuresHandler841=== PAUSE TestService_cleanupPendingClosuresHandler842=== RUN TestService_createPendingClosureHandler843=== PAUSE TestService_createPendingClosureHandler844=== RUN TestService_verifyS3Integrity845=== PAUSE TestService_verifyS3Integrity846=== RUN TestCompleteMultipartUnregistered847=== PAUSE TestCompleteMultipartUnregistered848=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT849=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT850=== CONT TestPush_RepeatedRootCommitsOnce851=== CONT TestReadProxyRangeRequest852=== CONT TestSkippedUploadsHandler853=== CONT TestPush_RootsAreLockedInByteOrder854=== CONT TestCompleteMultipartUnregistered855=== CONT TestGCTaskStore_GetReturnsLatest856=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit857=== CONT TestCompleteMultipartUpload_ErrorButObjectExists858=== CONT TestOrphanedObjectsGC859=== CONT TestPush_RejectsBadRequests860=== CONT TestPush_OverlappingRootsStoreOneRowPerKey861=== CONT TestPush_CompleteCommitsEveryRoot862=== CONT TestPendingClosureWriteTimeout863=== CONT TestParseSize864=== CONT TestService_Rustfstest865=== CONT TestReadProxyDisabled866=== CONT TestCompletedNarNotReofferedAcrossClosures867=== CONT TestPresignedUploadRegisteredBeforeCommit868=== CONT TestRedundantMultipartUpload869=== CONT TestPush_SignsNarinfosOfItsPendingObjects870=== CONT TestService_cleanupPendingClosuresHandler8712026/10/27 08:49:42 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000872=== CONT TestPush_CompleteWaitsForCleanupOfThePush873=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT874=== CONT TestReadRedirectKeepsNarinfoProxied875--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)876--- PASS: TestParseSize (0.00s)877=== CONT TestReadRedirectUsesPublicS3URL878=== CONT TestService_AuthMiddleware879=== RUN TestPendingClosureWriteTimeout/empty880=== PAUSE TestPendingClosureWriteTimeout/empty881=== RUN TestPendingClosureWriteTimeout/400_objects882=== PAUSE TestPendingClosureWriteTimeout/400_objects883=== RUN TestPendingClosureWriteTimeout/670k_objects884=== PAUSE TestPendingClosureWriteTimeout/670k_objects885=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline886=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline887=== CONT TestReadRedirectNar888--- PASS: TestSkippedUploadsHandler (0.01s)889=== CONT TestServerTLSConfig890=== RUN TestServerTLSConfig/no_client_CA891=== PAUSE TestServerTLSConfig/no_client_CA892=== RUN TestServerTLSConfig/missing_CA_file893=== PAUSE TestServerTLSConfig/missing_CA_file894=== RUN TestServerTLSConfig/not_a_PEM_file895=== PAUSE TestServerTLSConfig/not_a_PEM_file896=== CONT TestReadProxyConditionalGet897=== RUN TestPush_RejectsBadRequests/bad_root898=== PAUSE TestPush_RejectsBadRequests/bad_root899=== RUN TestPush_RejectsBadRequests/root_not_in_objects900=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects901=== RUN TestPush_RejectsBadRequests/no_roots902=== PAUSE TestPush_RejectsBadRequests/no_roots903=== RUN TestPush_RejectsBadRequests/no_objects904=== PAUSE TestPush_RejectsBadRequests/no_objects905=== CONT TestReadProxyRootRedirectsToIndexHTML9062026/10/27 08:49:42 INFO Received push request method=POST path=/api/pushes9072026/10/27 08:49:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9082026/10/27 08:49:42 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst909--- PASS: TestCompleteMultipartUnregistered (0.49s)910=== CONT TestReadProxyInvalidPath9112026/10/27 08:49:42 INFO Received uploads request method=POST path=/api/pending_closures9122026/10/27 08:49:42 INFO Received push request method=POST path=/api/pushes9132026/10/27 08:49:42 INFO Received push request method=POST path=/api/pushes9142026/10/27 08:49:42 INFO Received uploads request method=POST path=/api/pending_closures9152026/10/27 08:49:43 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9162026/10/27 08:49:43 INFO Received uploads request method=POST path=/api/pending_closures9172026/10/27 08:49:43 INFO Received push request method=POST path=/api/pushes9182026/10/27 08:49:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9192026/10/27 08:49:43 INFO Signed narinfos id=1 count=19202026/10/27 08:49:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9212026/10/27 08:49:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9222026/10/27 08:49:43 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"9232026/10/27 08:49:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9242026/10/27 08:49:43 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"9252026/10/27 08:49:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9262026/10/27 08:49:43 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=19272026/10/27 08:49:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9282026/10/27 08:49:43 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo929--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.62s)930=== CONT TestReadProxyHead931=== CONT TestReconnectLeavesObjectsUnlocked932--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.63s)933--- PASS: TestService_Rustfstest (0.64s)934=== CONT TestObjectStatsTrigger9352026/10/27 08:49:43 INFO Received cleanup request method=DELETE path=/api/pending_closures9362026/10/27 08:49:43 INFO Aborted multipart uploads count=0 kept=09372026/10/27 08:49:43 INFO Received uploads request method=POST path=/api/pending_closures938--- PASS: TestReadRedirectNar (0.73s)939=== CONT TestReadProxyNarStreaming9402026/10/27 08:49:43 INFO Received cleanup request method=DELETE path=/api/pending_closures9412026/10/27 08:49:43 INFO Aborted multipart uploads count=1 kept=09422026/10/27 08:49:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9432026-10-27 08:49:43.187 UTC [360] ERROR: Closure does not exist: id=19442026-10-27 08:49:43.187 UTC [360] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9452026-10-27 08:49:43.187 UTC [360] STATEMENT: -- name: CommitPendingClosure :one946 SELECT commit_pending_closure($1::bigint)::bigint947 9482026/10/27 08:49:43 INFO Received push request method=POST path=/api/pushes949--- PASS: TestService_cleanupPendingClosuresHandler (0.80s)950=== CONT TestObjectStatsUpdatedOncePerCommit9512026/10/27 08:49:43 INFO Received uploads request method=POST path=/api/pending_closures952--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.83s)953=== CONT TestReadProxyContentNegotiation954--- PASS: TestReadProxyConditionalGet (0.86s)955=== CONT TestPendingClosureFailureTracksEveryUpload956=== RUN TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false957=== PAUSE TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false958=== RUN TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true959=== PAUSE TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true960=== CONT TestGCAdvisoryLockBlocksConcurrentRun9612026/10/27 08:49:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9622026/10/27 08:49:43 INFO Received push request method=POST path=/api/pushes9632026/10/27 08:49:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9642026/10/27 08:49:43 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLjc1YjFmZDQyLTI2NTItNDBmNC1iODZiLWM0M2Y2ZDYyYTVhM3gxNzkzMDkwOTgyODg3OTAyNDkx parts=109652026/10/27 08:49:43 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLmM0ZTRmYWE0LTU1ZTQtNDY4NC04OGIwLTE5MmQ4NWM0NTk2NXgxNzkzMDkwOTgyOTEzNzA2OTE5966=== NAME TestOrphanedObjectsGC967 orphaned_objects_gc_test.go:287: GC Test Summary:968 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A969 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B970 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)971 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)972 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects973--- PASS: TestOrphanedObjectsGC (0.97s)974=== CONT TestGCTaskStore_PhaseUpdates975--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)976=== CONT TestReadProxy404And4299772026/10/27 08:49:43 INFO Received uploads request method=POST path=/api/pending_closures978--- PASS: TestReadRedirectUsesPublicS3URL (1.02s)979=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded9802026/10/27 08:49:43 INFO Received uploads request method=POST path=/api/pending_closures981=== CONT TestIsValidCachePath982=== RUN TestIsValidCachePath/narinfo983--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.04s)984=== PAUSE TestIsValidCachePath/narinfo985=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars986=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars987=== RUN TestIsValidCachePath/nar_zst988=== PAUSE TestIsValidCachePath/nar_zst989=== RUN TestIsValidCachePath/nar_xz990=== PAUSE TestIsValidCachePath/nar_xz991=== RUN TestIsValidCachePath/nar_bz2992=== PAUSE TestIsValidCachePath/nar_bz2993=== RUN TestIsValidCachePath/nar_uncompressed994=== PAUSE TestIsValidCachePath/nar_uncompressed995=== RUN TestIsValidCachePath/ls996=== PAUSE TestIsValidCachePath/ls997=== RUN TestIsValidCachePath/log998=== PAUSE TestIsValidCachePath/log999=== RUN TestIsValidCachePath/realisation1000=== PAUSE TestIsValidCachePath/realisation1001=== RUN TestIsValidCachePath/nix-cache-info1002=== PAUSE TestIsValidCachePath/nix-cache-info1003=== RUN TestIsValidCachePath/index.html1004=== PAUSE TestIsValidCachePath/index.html1005=== RUN TestIsValidCachePath/traversal_parent1006=== PAUSE TestIsValidCachePath/traversal_parent1007=== RUN TestIsValidCachePath/traversal_in_middle1008=== PAUSE TestIsValidCachePath/traversal_in_middle1009=== RUN TestIsValidCachePath/invalid_char_e1010=== PAUSE TestIsValidCachePath/invalid_char_e1011=== RUN TestIsValidCachePath/invalid_char_u1012=== PAUSE TestIsValidCachePath/invalid_char_u1013=== RUN TestIsValidCachePath/random_path1014=== PAUSE TestIsValidCachePath/random_path1015=== RUN TestIsValidCachePath/empty1016=== PAUSE TestIsValidCachePath/empty1017=== RUN TestIsValidCachePath/leading_slash1018=== PAUSE TestIsValidCachePath/leading_slash1019=== RUN TestIsValidCachePath/wrong_extension1020=== PAUSE TestIsValidCachePath/wrong_extension1021=== RUN TestIsValidCachePath/short_hash1022=== PAUSE TestIsValidCachePath/short_hash1023=== CONT TestPendingCleanupUsesOneCutoff10242026/10/27 08:49:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10252026/10/27 08:49:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10262026/10/27 08:49:43 WARN Failed to abort multipart upload key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLmM0ZTRmYWE0LTU1ZTQtNDY4NC04OGIwLTE5MmQ4NWM0NTk2NXgxNzkzMDkwOTgyOTEzNzA2OTE5 error="Delete \"http://localhost:37077/bucket8/nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst?uploadId=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLmM0ZTRmYWE0LTU1ZTQtNDY4NC04OGIwLTE5MmQ4NWM0NTk2NXgxNzkzMDkwOTgyOTEzNzA2OTE5\": injected: abort refused"10272026/10/27 08:49:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10282026/10/27 08:49:43 INFO Received uploads request method=POST path=/api/pending_closures10292026/10/27 08:49:43 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLmM0ZTRmYWE0LTU1ZTQtNDY4NC04OGIwLTE5MmQ4NWM0NTk2NXgxNzkzMDkwOTgyOTEzNzA2OTE510302026/10/27 08:49:43 ERROR Failed to register completed object error="get pending object \"nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst\": context canceled" object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst10312026/10/27 08:49:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10322026/10/27 08:49:43 INFO Received push request method=POST path=/api/pushes10332026/10/27 08:49:43 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=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLmM0ZTRmYWE0LTU1ZTQtNDY4NC04OGIwLTE5MmQ4NWM0NTk2NXgxNzkzMDkwOTgyOTEzNzA2OTE510342026/10/27 08:49:43 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLjI5YTM0ZjM4LWY3ZjEtNDcwNy04ZmM0LTM0ZGIxODA2OWY2NngxNzkzMDkwOTgyOTY3MjQxNzAx parts=1010352026/10/27 08:49:43 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLjA2MjY2ODUxLTk1YTEtNDkzMS05MWYzLThjZWM2YWI0OWIyY3gxNzkzMDkwOTgyOTc3ODc5NTU3 parts=1010362026/10/27 08:49:43 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLmM0ZTRmYWE0LTU1ZTQtNDY4NC04OGIwLTE5MmQ4NWM0NTk2NXgxNzkzMDkwOTgyOTEzNzA2OTE5 parts=11037=== CONT TestParseSingleRange1038--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.15s)1039=== RUN TestParseSingleRange/none1040=== PAUSE TestParseSingleRange/none1041=== RUN TestParseSingleRange/unknown_unit1042=== PAUSE TestParseSingleRange/unknown_unit1043=== RUN TestParseSingleRange/multi-range_ignored1044=== PAUSE TestParseSingleRange/multi-range_ignored1045=== RUN TestParseSingleRange/malformed_no_dash1046=== PAUSE TestParseSingleRange/malformed_no_dash1047=== RUN TestParseSingleRange/malformed_both_empty1048=== PAUSE TestParseSingleRange/malformed_both_empty1049=== RUN TestParseSingleRange/malformed_end_before_start1050=== PAUSE TestParseSingleRange/malformed_end_before_start1051=== RUN TestParseSingleRange/closed1052=== PAUSE TestParseSingleRange/closed1053=== RUN TestParseSingleRange/open-ended1054=== PAUSE TestParseSingleRange/open-ended1055=== RUN TestParseSingleRange/end_clamped_to_size1056=== PAUSE TestParseSingleRange/end_clamped_to_size1057=== RUN TestParseSingleRange/suffix1058=== PAUSE TestParseSingleRange/suffix1059=== RUN TestParseSingleRange/suffix_exceeds_size1060=== PAUSE TestParseSingleRange/suffix_exceeds_size1061=== RUN TestParseSingleRange/single_byte1062=== PAUSE TestParseSingleRange/single_byte1063=== RUN TestParseSingleRange/start_past_EOF1064=== PAUSE TestParseSingleRange/start_past_EOF1065=== RUN TestParseSingleRange/start_far_past_EOF1066=== PAUSE TestParseSingleRange/start_far_past_EOF1067=== CONT TestGCTaskStore_GetEmpty1068--- PASS: TestGCTaskStore_GetEmpty (0.00s)1069=== CONT TestPresentNotReportedWhileGCDeletesClosure1070=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1071=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1072=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1073=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1074=== CONT TestMetricsCommit1075--- PASS: TestReadRedirectKeepsNarinfoProxied (1.16s)1076=== CONT TestGCTaskStore_StartNew1077=== CONT TestPresentRefreshesOnlyStaleClosures1078--- PASS: TestReadProxyDisabled (1.16s)1079--- PASS: TestGCTaskStore_StartNew (0.00s)1080=== CONT TestTombstonedObjectOfferedWithoutWaiting10812026/10/27 08:49:43 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1082=== CONT TestDeduplicatedObjectsRecordedAsPending1083--- PASS: TestService_AuthMiddleware (1.22s)1084--- PASS: TestReadProxyRangeRequest (1.45s)1085=== CONT TestPushWaitsForSweepHoldingRow1086=== CONT TestUploadHandlersRejectInvalidKeys1087--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.09s)1088=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1089=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1090=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1091=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1092=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1093=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1094=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1095=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1096=== CONT TestSweepRechecksPendingAfterLocking1097--- PASS: TestReadProxyInvalidPath (1.07s)1098=== CONT TestReadProxyNarinfoAlreadyDecompressed10992026/10/27 08:49:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11002026/10/27 08:49:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11012026/10/27 08:49:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11022026/10/27 08:49:44 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLmJkMThjZjQ2LTVjMzYtNDc2Mi1iOTU3LWZlM2I1Mjg2NTM4NXgxNzkzMDkwOTgzMjU0ODk4MTAx parts=1211032026/10/27 08:49:44 INFO Received uploads request method=POST path=/api/pending_closures11042026/10/27 08:49:44 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLmQ0Yzg3ZmEzLTA0YjgtNDFhMy1iOWNiLTE1ZWNlNWY4ZDg3ZHgxNzkzMDkwOTgzMzM5MTcwMjYx parts=1011052026/10/27 08:49:44 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLmI5ODBkNDkwLWRmZGEtNDQxYy04YTVkLWIyNWFiMjU3ZjExYXgxNzkzMDkwOTgyODg3MzA5ODk2 parts=1011062026/10/27 08:49:44 INFO Received complete push request method=POST path=/api/pushes/1/complete11072026/10/27 08:49:44 INFO Completed push id=1 objects=4 duration=5.772937ms1108--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.69s)1109=== CONT TestReadProxyOutlastsServerWriteTimeout1110--- PASS: TestPush_RepeatedRootCommitsOnce (1.72s)1111=== CONT TestConcurrentPinUpdatesAgree1112--- PASS: TestReconnectLeavesObjectsUnlocked (1.08s)1113=== CONT TestForceGCDuringPushOffersSweptObject1114=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1115=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1116=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1117=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1118=== CONT TestCreatePinRejectsBadInput1119--- PASS: TestObjectStatsTrigger (1.12s)1120=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection11212026/10/27 08:49:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11222026/10/27 08:49:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1123--- PASS: TestReadProxyNarStreaming (1.08s)1124=== CONT TestConnectSerialisesConcurrentMigrations11252026/10/27 08:49:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11262026/10/27 08:49:44 INFO Completed multipart upload object_key=nar/ffffffffffffffffffffffffffffffff00000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLmIyN2ExZDU0LWMwYTktNDFmNC05MDAwLTAzMWUyZTAxYWU1ZXgxNzkzMDkwOTgyOTY3MTEyMjMw parts=1011272026/10/27 08:49:44 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLmZhM2U0MTYxLTY3YTEtNDhjYy05MTRhLTdkNWUzOWEyYWY3MXgxNzkzMDkwOTgyOTc3MTI4NDYx parts=1011282026/10/27 08:49:44 INFO Received complete push request method=POST path=/api/pushes/1/complete11292026/10/27 08:49:44 INFO Completed push id=1 objects=4 duration=7.680122ms11302026/10/27 08:49:44 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLjBiY2E0YmYyLWQ2YmYtNDMwNi1iMTNjLTFkZGE0ZTY2MTE3M3gxNzkzMDkwOTgzNTI2NzA5NzQ0 parts=1011312026/10/27 08:49:44 INFO Received push request method=POST path=/api/pushes11322026/10/27 08:49:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11332026/10/27 08:49:44 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLjVkYzBmNDY4LWI5YTktNGY3Mi04NGUwLTU1OWU4MDNjYmEzZXgxNzkzMDkwOTgzNDczNDI2OTQ0 parts=121134--- PASS: TestObjectStatsUpdatedOncePerCommit (1.13s)1135=== CONT TestGCSweepSkipsPendingObjects11362026/10/27 08:49:44 INFO Received uploads request method=POST path=/api/pending_closures1137=== CONT TestService_verifyS3Integrity1138--- PASS: TestReadProxyHead (1.31s)11392026/10/27 08:49:44 INFO Received uploads request method=POST path=/api/pending_closures11402026/10/27 08:49:44 INFO Received uploads request method=POST path=/api/pending_closures11412026-10-27 08:49:44.381 UTC [508] ERROR: Push does not exist: id=111422026-10-27 08:49:44.381 UTC [508] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE11432026-10-27 08:49:44.381 UTC [508] STATEMENT: SELECT commit_push($1)11442026/10/27 08:49:44 INFO Aborted multipart uploads count=0 kept=011452026/10/27 08:49:44 WARN Force mode enabled - objects will be deleted immediately without grace period1146--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (2.00s)1147=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock11482026/10/27 08:49:44 INFO Received uploads request method=POST path=/api/pending_closures1149=== CONT TestClientFallsBackToClosures1150--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (1.02s)11512026/10/27 08:49:44 INFO Received uploads request method=POST path=/api/pending_closures11522026/10/27 08:49:44 INFO Received push request method=POST path=/api/pushes11532026/10/27 08:49:44 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=011542026/10/27 08:49:44 INFO Vacuumed table table=pending_closures11552026/10/27 08:49:44 INFO Vacuumed table table=pending_objects11562026/10/27 08:49:44 INFO Received cleanup request method=DELETE path=/api/pending_closures11572026/10/27 08:49:44 INFO Vacuumed table table=multipart_uploads11582026/10/27 08:49:44 INFO Vacuumed table table=closures11592026/10/27 08:49:44 INFO Vacuumed table table=objects11602026/10/27 08:49:44 INFO Received uploads request method=POST path=/api/pending_closures11612026/10/27 08:49:44 INFO Received uploads request method=POST path=/api/pending_closures1162--- PASS: TestTombstonedObjectOfferedWithoutWaiting (1.03s)1163=== CONT TestGetExistingObjectsLocksRows1164--- PASS: TestDeduplicatedObjectsRecordedAsPending (1.00s)1165=== CONT TestClientSharedPathCommittedMidPush1166=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1167--- PASS: TestPresentRefreshesOnlyStaleClosures (1.11s)11682026/10/27 08:49:45 INFO Received uploads request method=POST path=/api/pending_closures11692026/10/27 08:49:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11702026/10/27 08:49:45 INFO Aborted multipart uploads count=0 kept=011712026/10/27 08:49:45 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggggg00000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLmNiMWUyYWZjLTI5YmItNDU4OC1iMmFkLThiYWYzZWIyYmFiMXgxNzkzMDkwOTgyOTY3NTcyNTk0 parts=1011722026/10/27 08:49:45 WARN Force mode enabled - objects will be deleted immediately without grace period11732026/10/27 08:49:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11742026/10/27 08:49:45 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=011752026/10/27 08:49:45 INFO Vacuumed table table=pending_closures11762026/10/27 08:49:45 INFO Vacuumed table table=pending_objects11772026/10/27 08:49:45 INFO Vacuumed table table=multipart_uploads11782026/10/27 08:49:45 INFO Vacuumed table table=closures11792026/10/27 08:49:45 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLmI3N2VjMWEwLWM3NzktNDEzNy1hMWE2LWZmZTYyZmUzOTZhNXgxNzkzMDkwOTgzNTI2MTkyNDU5 parts=1011802026/10/27 08:49:45 INFO Vacuumed table table=objects1181--- PASS: TestReadProxyNarinfoAlreadyDecompressed (1.24s)1182=== CONT TestClientWithDependencies1183--- PASS: TestSweepRechecksPendingAfterLocking (1.31s)1184=== CONT TestDeleteClosuresRacingPins11852026/10/27 08:49:45 INFO Received create pin request method=POST path=/api/pins/app11862026/10/27 08:49:45 INFO Received create pin request method=POST path=/api/pins/app11872026/10/27 08:49:45 INFO Received create pin request method=POST path=/api/pins/deploy11882026/10/27 08:49:45 INFO Received create pin request method=POST path=/api/pins/deploy11892026/10/27 08:49:45 INFO Received create pin request method=POST path=/api/pins/deploy11902026/10/27 08:49:45 INFO Received create pin request method=POST path=/api/pins/deploy11912026/10/27 08:49:45 INFO Received create pin request method=POST path=/api/pins/deploy11922026/10/27 08:49:45 INFO Received create pin request method=POST path=/api/pins/deploy11932026/10/27 08:49:45 INFO Received create pin request method=POST path=/api/pins/deploy11942026/10/27 08:49:45 INFO Received create pin request method=POST path=/api/pins/deploy11952026/10/27 08:49:45 INFO Received uploads request method=POST path=/api/pending_closures11962026/10/27 08:49:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11972026/10/27 08:49:45 INFO Received create pin request method=POST path=/api/pins/deploy11982026/10/27 08:49:45 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"11992026/10/27 08:49:45 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLjk4ZGQ3NmM5LTlhNDQtNDQ0NS1hODA1LTJjOTM3MmVkOTU2MXgxNzkzMDkwOTg0Mzg1MTU3MzE4 error="Get \"http://127.0.0.1:1/bucket23/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"12002026/10/27 08:49:45 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLjQzNWYzODU1LWNiZTUtNDYzMy1hZDY5LTE4ZTkzMTY5MDA4NHgxNzkzMDkwOTg0MzU0OTQ5MjY0 parts=1212012026/10/27 08:49:45 INFO Received cleanup request method=DELETE path=/api/pending_closures12022026/10/27 08:49:45 INFO Aborted multipart uploads count=1 kept=012032026/10/27 08:49:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12042026/10/27 08:49:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1205--- PASS: TestReadProxyContentNegotiation (2.18s)1206=== CONT TestMetricsInventory12072026/10/27 08:49:45 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLjMwN2Q2MTdhLWI5OWYtNGJjZS04NTMyLTJjNjBjOWQyNGIyNHgxNzkzMDkwOTg0MzA4NDc3NDY5 parts=1012082026/10/27 08:49:45 INFO Received complete push request method=POST path=/api/pushes/2/complete12092026/10/27 08:49:45 INFO Received uploads request method=POST path=/api/pending_closures12102026/10/27 08:49:45 INFO Completed push id=2 objects=4 duration=2.342219ms12112026/10/27 08:49:45 WARN Rate limiter enabled after throttle name=s3-test rate=512122026/10/27 08:49:45 WARN S3 rate limit hit during proxy key=4hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo error="Please reduce your request rate."1213--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (2.15s)1214=== CONT TestClientPushesUseOnePush1215--- PASS: TestRedundantMultipartUpload (3.02s)1216=== CONT TestCacheConfigHandlerMaxNarSize1217--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1218=== CONT TestService_NativeMTLS12192026/10/27 08:49:45 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLjU2NDRiNzE3LWUyYjctNGRkYi1hNWIzLTdiYTA3ZGQ4NDg4OXgxNzkzMDkwOTg0NTA2MTY3MTY0 parts=1012202026/10/27 08:49:45 INFO Received uploads request method=POST path=/api/pending_closures1221--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (3.05s)1222=== CONT TestCreatePendingClosureRejectsOversizedNAR12232026/10/27 08:49:45 INFO Received uploads request method=POST path=/api/pending_closures1224--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1225=== CONT TestMultipartCleanup12262026/10/27 08:49:45 INFO Aborted multipart uploads count=0 kept=012272026/10/27 08:49:45 WARN Force mode enabled - objects will be deleted immediately without grace period12282026/10/27 08:49:45 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=012292026/10/27 08:49:45 INFO Vacuumed table table=pending_closures12302026/10/27 08:49:45 INFO Vacuumed table table=pending_objects12312026/10/27 08:49:45 INFO Vacuumed table table=multipart_uploads12322026/10/27 08:49:45 INFO Vacuumed table table=closures12332026/10/27 08:49:45 WARN Rate limiter backed off name=s3-test rate=512342026/10/27 08:49:45 WARN S3 rate limit hit during proxy key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhh.nar.zst error="Please reduce your request rate."12352026/10/27 08:49:45 INFO Vacuumed table table=objects1236--- PASS: TestReadProxy404And429 (2.14s)1237=== CONT TestGCSweepDeliversEachKeyOnce1238=== CONT TestPushDedupSurvivesConcurrentGC1239--- PASS: TestGCSweepSkipsPendingObjects (1.20s)1240--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (1.41s)1241=== CONT TestGCTaskStore_ConflictDifferentParams1242--- PASS: TestPushWaitsForSweepHoldingRow (1.73s)1243=== CONT TestUploadHandlersRejectOversizedBody1244=== CONT TestService_ReadScope_PublicByDefault1245--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1246--- PASS: TestGetExistingObjectsLocksRows (1.11s)1247=== CONT TestService_RequireScope_OIDC12482026/10/27 08:49:45 INFO Received uploads request method=POST path=/api/pending_closures12492026/10/27 08:49:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12502026/10/27 08:49:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12512026/10/27 08:49:45 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLjc4M2MwNzUxLTEzMzEtNDA3NS1iOTdiLWI0ZjExMDdjOTAxN3gxNzkzMDkwOTgzNTI0NTY2MTQ2 parts=1012522026/10/27 08:49:45 INFO Received complete push request method=POST path=/api/pushes/1/complete12532026/10/27 08:49:45 INFO Completed multipart upload object_key=nar/dddddddddddddddddddddddddddddddd00000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLjU4OWFjYTI5LWUyNjEtNGVmYy04NDUzLWFhNzEwMmY0ODI1Y3gxNzkzMDkwOTgyOTY1OTMyNjIw parts=1012542026/10/27 08:49:45 INFO Completed push id=1 objects=6 duration=7.969994ms12552026/10/27 08:49:45 INFO Created/updated pin name=app store_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-app narinfo_key=aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.narinfo12562026/10/27 08:49:45 INFO Created/updated pin name=app store_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-app narinfo_key=bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb.narinfo1257--- PASS: TestPush_CompleteCommitsEveryRoot (3.39s)1258=== CONT TestClientMultipleUploads1259--- PASS: TestConcurrentPinUpdatesAgree (1.71s)1260=== CONT TestCacheConfigHandler1261=== RUN TestCacheConfigHandler/full_config,_no_issuer1262=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1263=== RUN TestCacheConfigHandler/no_cache_url_configured1264=== PAUSE TestCacheConfigHandler/no_cache_url_configured1265=== RUN TestCacheConfigHandler/no_signing_keys1266=== PAUSE TestCacheConfigHandler/no_signing_keys1267=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1268=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1269=== CONT TestClientErrorHandling1270=== RUN TestClientErrorHandling/InvalidStorePath1271=== PAUSE TestClientErrorHandling/InvalidStorePath1272=== RUN TestClientErrorHandling/InvalidAuthToken1273=== PAUSE TestClientErrorHandling/InvalidAuthToken1274=== RUN TestClientErrorHandling/ServerNotAvailable1275=== PAUSE TestClientErrorHandling/ServerNotAvailable1276=== CONT TestPresentReportsOnlyClosureRoots12772026/10/27 08:49:45 INFO Received uploads request method=POST path=/api/pending_closures12782026/10/27 08:49:45 INFO Received push request method=POST path=/api/pushes12792026/10/27 08:49:45 INFO Received uploads request method=POST path=/api/pending_closures12802026/10/27 08:49:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12812026/10/27 08:49:45 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)12822026/10/27 08:49:45 INFO Uploading 3pljphh9hy1r9zcm2m7r1z2c3hhyf7sv-shared-dep (136B)12832026/10/27 08:49:45 INFO Uploading lvqfbkwmvbgl7grndb81k090kc5id5kf-top (224B)12842026/10/27 08:49:45 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)12852026/10/27 08:49:45 INFO Uploading 61ybkidbs6y9s8gdpsdw0h9r1yb1vnbp-shared-dep (136B)12862026/10/27 08:49:45 INFO Uploading gaj56jnhs2jqlyzdhk8zh7fmvfmnvybl-b (216B)1287=== NAME TestClientWithDependencies1288 client_integration_test.go:722: Built derivation: /build/TestClientWithDependencies2841732480/001/store/cns2n333qjdnqz6bxpq61nlhn5axi1bn-test-script12892026/10/27 08:49:45 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12902026/10/27 08:49:45 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12912026/10/27 08:49:45 WARN Failed to register uploaded object key=nar/1vmbrp5psjp5582n275qh5h6f70d9kb6isd90m3sdr743x5c2z7g.nar.zst error="server returned 404: 404 page not found\n"12922026/10/27 08:49:45 WARN Failed to register uploaded object key=nar/077n0xhxmk3ssc05hprz2sl2ry1dikh027nifkz565dbyqyw0n5p.nar.zst error="server returned 404: 404 page not found\n"12932026/10/27 08:49:45 WARN Failed to register uploaded object key=61ybkidbs6y9s8gdpsdw0h9r1yb1vnbp.ls error="server returned 404: 404 page not found\n"1294--- PASS: TestMetricsInventory (0.52s)1295=== CONT TestService_ReadAuthMiddleware12962026/10/27 08:49:45 WARN Failed to register uploaded object key=3pljphh9hy1r9zcm2m7r1z2c3hhyf7sv.ls error="server returned 404: 404 page not found\n"12972026/10/27 08:49:45 WARN Failed to register uploaded object key=7gql6z2mnf6irjz98yn2mqgzzhq7v0qy.ls error="server returned 404: 404 page not found\n"12982026/10/27 08:49:45 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12992026/10/27 08:49:45 WARN Failed to register uploaded object key=lvqfbkwmvbgl7grndb81k090kc5id5kf.ls error="server returned 404: 404 page not found\n"13002026/10/27 08:49:45 INFO Signed narinfos id=1 count=213012026/10/27 08:49:45 INFO Uploading 2 narinfos13022026/10/27 08:49:45 WARN Failed to register uploaded object key=lvqfbkwmvbgl7grndb81k090kc5id5kf.narinfo error="server returned 404: 404 page not found\n"13032026/10/27 08:49:45 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13042026/10/27 08:49:45 WARN Failed to register uploaded object key=gaj56jnhs2jqlyzdhk8zh7fmvfmnvybl.ls error="server returned 404: 404 page not found\n"13052026/10/27 08:49:45 INFO Received complete push request method=POST path=/api/pushes/1/complete13062026/10/27 08:49:45 WARN Failed to register uploaded object key=3pljphh9hy1r9zcm2m7r1z2c3hhyf7sv.narinfo error="server returned 404: 404 page not found\n"13072026/10/27 08:49:45 INFO Signed narinfos id=1 count=213082026/10/27 08:49:45 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13092026/10/27 08:49:45 INFO Signed narinfos id=2 count=213102026/10/27 08:49:45 INFO Uploading 4 narinfos1311=== NAME TestClientWithDependencies1312 client_integration_test.go:724: Found 1 dependencies (including self)13132026/10/27 08:49:45 INFO Completed push id=1 objects=6 duration=10.589655ms13142026/10/27 08:49:45 INFO Upload complete. (174ms)1315=== NAME TestClientSharedPathCommittedMidPush1316 client_integration_test.go:803: Retrieved narinfo from S3:1317 StorePath: /build/TestClientSharedPathCommittedMidPush2123341557/001/store/3pljphh9hy1r9zcm2m7r1z2c3hhyf7sv-shared-dep1318 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1319 Compression: zstd1320 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821321 NarSize: 1361322 References: 1323 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n13242026/10/27 08:49:45 WARN Failed to register uploaded object key=61ybkidbs6y9s8gdpsdw0h9r1yb1vnbp.narinfo error="server returned 404: 404 page not found\n"13252026/10/27 08:49:45 WARN Failed to register uploaded object key=gaj56jnhs2jqlyzdhk8zh7fmvfmnvybl.narinfo error="server returned 404: 404 page not found\n"13262026/10/27 08:49:45 WARN Failed to register uploaded object key=7gql6z2mnf6irjz98yn2mqgzzhq7v0qy.narinfo error="server returned 404: 404 page not found\n"1327 client_integration_test.go:803: Retrieved narinfo from S3:1328 StorePath: /build/TestClientSharedPathCommittedMidPush2123341557/001/store/lvqfbkwmvbgl7grndb81k090kc5id5kf-top1329 URL: nar/077n0xhxmk3ssc05hprz2sl2ry1dikh027nifkz565dbyqyw0n5p.nar.zst1330 Compression: zstd1331 NarHash: sha256:077n0xhxmk3ssc05hprz2sl2ry1dikh027nifkz565dbyqyw0n5p1332 NarSize: 2241333 References: /build/TestClientSharedPathCommittedMidPush2123341557/001/store/3pljphh9hy1r9zcm2m7r1z2c3hhyf7sv-shared-dep1334 CA: text:sha256:13lczbs5hnrjzv4zp8l9984wbclmxg4672rjmy51xwra33nfw5xx13352026/10/27 08:49:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13362026/10/27 08:49:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13372026/10/27 08:49:46 WARN Failed to register uploaded object key=61ybkidbs6y9s8gdpsdw0h9r1yb1vnbp.narinfo error="server returned 404: 404 page not found\n"13382026/10/27 08:49:46 WARN mTLS auth: subject not in bound subjects subject="CN=reader"13392026/10/27 08:49:46 WARN mTLS auth: subject not in bound subjects subject="CN=reader"13402026/10/27 08:49:46 INFO Completed upload id=1 objects=6 duration=7.841753ms13412026/10/27 08:49:46 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13422026/10/27 08:49:46 INFO Completed upload id=2 objects=6 duration=2.624032ms13432026/10/27 08:49:46 INFO Upload complete. (219ms)1344=== NAME TestClientFallsBackToClosures1345 client_pushes_test.go:112: Retrieved narinfo from S3:1346 StorePath: /build/TestClientFallsBackToClosures3797372302/001/store/61ybkidbs6y9s8gdpsdw0h9r1yb1vnbp-shared-dep1347 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1348 Compression: zstd1349 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821350 NarSize: 1361351 References: 1352 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1353 client_pushes_test.go:112: Retrieved narinfo from S3:1354 StorePath: /build/TestClientFallsBackToClosures3797372302/001/store/7gql6z2mnf6irjz98yn2mqgzzhq7v0qy-a1355 URL: nar/1vmbrp5psjp5582n275qh5h6f70d9kb6isd90m3sdr743x5c2z7g.nar.zst1356 Compression: zstd1357 NarHash: sha256:1vmbrp5psjp5582n275qh5h6f70d9kb6isd90m3sdr743x5c2z7g1358 NarSize: 2161359 References: /build/TestClientFallsBackToClosures3797372302/001/store/61ybkidbs6y9s8gdpsdw0h9r1yb1vnbp-shared-dep1360 CA: text:sha256:1aws401r731id9i8hw21jvgv0gkxs2lqf82qvwk4gycc3a3a9l9813612026/10/27 08:49:46 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLmFjODg3NmVhLWZhYTYtNDhmMC1hZmI4LTM4ZWYwZmQ0ZmIwZngxNzkzMDkwOTg0NTA2MDMxNDkz parts=101362=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1363--- PASS: TestService_NativeMTLS (0.65s)1364=== NAME TestClientFallsBackToClosures1365 client_pushes_test.go:112: Retrieved narinfo from S3:1366 StorePath: /build/TestClientFallsBackToClosures3797372302/001/store/gaj56jnhs2jqlyzdhk8zh7fmvfmnvybl-b1367 URL: nar/1vmbrp5psjp5582n275qh5h6f70d9kb6isd90m3sdr743x5c2z7g.nar.zst1368 Compression: zstd1369 NarHash: sha256:1vmbrp5psjp5582n275qh5h6f70d9kb6isd90m3sdr743x5c2z7g1370 NarSize: 2161371 References: /build/TestClientFallsBackToClosures3797372302/001/store/61ybkidbs6y9s8gdpsdw0h9r1yb1vnbp-shared-dep1372 CA: text:sha256:1aws401r731id9i8hw21jvgv0gkxs2lqf82qvwk4gycc3a3a9l981373--- PASS: TestClientSharedPathCommittedMidPush (1.47s)1374=== CONT TestClientIntegration13752026/10/27 08:49:46 INFO Received complete push request method=POST path=/api/pushes/1/complete13762026/10/27 08:49:46 INFO Completed push id=1 objects=4 duration=9.84998ms13772026/10/27 08:49:46 INFO Received uploads request method=POST path=/api/pending_closures13782026/10/27 08:49:46 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13792026/10/27 08:49:46 INFO Received push request method=POST path=/api/pushes13802026/10/27 08:49:46 INFO Completed upload id=2 objects=2 duration=12.742203ms1381=== CONT TestPendingClosureFailureAbortsItsUploads1382--- PASS: TestClientFallsBackToClosures (1.70s)13832026/10/27 08:49:46 INFO Received create pin request method=POST path=/api/pins/deploy13842026/10/27 08:49:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13852026/10/27 08:49:46 INFO Uploading cns2n333qjdnqz6bxpq61nlhn5axi1bn-test-script (136B)13862026/10/27 08:49:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13872026/10/27 08:49:46 INFO Created/updated pin name=deploy store_path="/nix/store/dddddddddddddddddddddddddddddddd-app-1.0+git_x?y=z" narinfo_key=dddddddddddddddddddddddddddddddd.narinfo13882026/10/27 08:49:46 WARN Failed to register uploaded object key=log/z2jpyfs72gcaw83ycbbsbpmqif59418b-test-script.drv error="server returned 404: 404 page not found\n"1389--- PASS: TestMetricsCommit (2.64s)1390=== CONT TestGCTaskStore_DeduplicateSameParams1391--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1392=== CONT TestDeletePinKeepsRowWhenS3Fails13932026/10/27 08:49:46 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37667/oidc13942026/10/27 08:49:46 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"13952026/10/27 08:49:46 WARN Failed to register uploaded object key=cns2n333qjdnqz6bxpq61nlhn5axi1bn.ls error="server returned 404: 404 page not found\n"13962026/10/27 08:49:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13972026/10/27 08:49:46 INFO Signed narinfos id=1 count=113982026/10/27 08:49:46 INFO Uploading 1 narinfos13992026/10/27 08:49:46 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLmFmZjQ1ZDIxLWU2NjMtNGViYy05ZjFjLWRhNDM0ZGRkNDRkM3gxNzkzMDkwOTg1NDc3NTI5MDU5 parts=1014002026/10/27 08:49:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1401--- PASS: TestCreatePinRejectsBadInput (2.09s)1402=== CONT TestReadProxyNarinfo14032026/10/27 08:49:46 INFO Received complete push request method=POST path=/api/pushes/1/complete14042026/10/27 08:49:46 WARN Failed to register uploaded object key=cns2n333qjdnqz6bxpq61nlhn5axi1bn.narinfo error="server returned 404: 404 page not found\n"14052026/10/27 08:49:46 INFO Completed upload id=1 objects=2 duration=7.962484ms14062026/10/27 08:49:46 INFO Completed push id=1 objects=4 duration=11.497713ms14072026/10/27 08:49:46 INFO Upload complete. (209ms)14082026/10/27 08:49:46 INFO Aborted multipart uploads count=0 kept=014092026/10/27 08:49:46 WARN Force mode enabled - objects will be deleted immediately without grace period14102026/10/27 08:49:46 INFO Aborted multipart uploads count=0 kept=014112026/10/27 08:49: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=014122026/10/27 08:49:46 INFO Received uploads request method=POST path=/api/pending_closures14132026/10/27 08:49:46 WARN Force mode enabled - objects will be deleted immediately without grace period14142026/10/27 08:49:46 INFO Received uploads request method=POST path=/api/pending_closures14152026/10/27 08:49:46 INFO Vacuumed table table=pending_closures14162026/10/27 08:49:46 INFO Received cleanup request method=DELETE path=/api/pending_closures14172026/10/27 08:49:46 INFO Vacuumed table table=pending_objects14182026/10/27 08:49:46 INFO Vacuumed table table=multipart_uploads14192026/10/27 08:49:46 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket64/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""14202026/10/27 08:49:46 INFO Aborted multipart uploads count=0 kept=114212026/10/27 08:49:46 INFO Vacuumed table table=closures14222026/10/27 08:49:46 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo14232026/10/27 08:49:46 WARN Found objects in DB but missing from S3, will re-upload count=114242026/10/27 08:49:46 INFO Vacuumed table table=objects1425=== NAME TestClientWithDependencies1426 client_integration_test.go:740: Skipping nix copy test - isolated store (/build/TestClientWithDependencies2841732480/001/store) requires matching store prefix14272026/10/27 08:49:46 INFO Received cleanup request method=DELETE path=/api/pending_closures14282026/10/27 08:49:46 INFO Aborted multipart uploads count=1 kept=014292026/10/27 08:49:46 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete14302026/10/27 08:49:46 INFO Received uploads request method=POST path=/api/pending_closures14312026/10/27 08:49:46 INFO Completed upload id=3 objects=2 duration=3.974432ms14322026/10/27 08:49:46 INFO Received push request method=POST path=/api/pushes1433--- PASS: TestClientWithDependencies (1.12s)1434=== CONT TestGCEndsOnShutdown1435=== RUN TestGCEndsOnShutdown/before_the_run1436=== PAUSE TestGCEndsOnShutdown/before_the_run1437=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1438=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1439=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1440=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1441=== CONT TestFailedS3DeleteKeepsTombstone1442--- PASS: TestService_ReadScope_PublicByDefault (0.75s)1443=== CONT TestProxyWriteTimeout1444=== RUN TestProxyWriteTimeout/narinfo1445=== PAUSE TestProxyWriteTimeout/narinfo1446=== RUN TestProxyWriteTimeout/1_GiB_nar1447=== PAUSE TestProxyWriteTimeout/1_GiB_nar1448=== RUN TestProxyWriteTimeout/10_GiB_nar1449=== PAUSE TestProxyWriteTimeout/10_GiB_nar1450=== RUN TestProxyWriteTimeout/unknown_size1451=== PAUSE TestProxyWriteTimeout/unknown_size1452=== CONT TestIsValidUploadKey1453=== RUN TestIsValidUploadKey/narinfo1454=== PAUSE TestIsValidUploadKey/narinfo1455=== RUN TestIsValidUploadKey/nar_zst1456=== PAUSE TestIsValidUploadKey/nar_zst1457=== RUN TestIsValidUploadKey/nar_xz1458=== PAUSE TestIsValidUploadKey/nar_xz1459=== RUN TestIsValidUploadKey/nar_plain1460=== PAUSE TestIsValidUploadKey/nar_plain1461=== RUN TestIsValidUploadKey/listing1462=== PAUSE TestIsValidUploadKey/listing1463=== RUN TestIsValidUploadKey/build_log1464=== PAUSE TestIsValidUploadKey/build_log1465=== RUN TestIsValidUploadKey/build_log_home-manager_file1466=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1467=== RUN TestIsValidUploadKey/build_log_plus_in_name1468=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1469=== RUN TestIsValidUploadKey/build_log_question_mark1470=== PAUSE TestIsValidUploadKey/build_log_question_mark1471=== RUN TestIsValidUploadKey/build_log_equals1472=== PAUSE TestIsValidUploadKey/build_log_equals1473=== RUN TestIsValidUploadKey/realisation1474=== PAUSE TestIsValidUploadKey/realisation1475=== RUN TestIsValidUploadKey/realisation_plus_in_output1476=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1477=== RUN TestIsValidUploadKey/nix-cache-info1478=== PAUSE TestIsValidUploadKey/nix-cache-info1479=== RUN TestIsValidUploadKey/index.html1480=== PAUSE TestIsValidUploadKey/index.html1481=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1482=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1483=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1484=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1485=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1486=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1487=== RUN TestIsValidUploadKey/traversal1488=== PAUSE TestIsValidUploadKey/traversal1489=== RUN TestIsValidUploadKey/traversal_nar1490=== PAUSE TestIsValidUploadKey/traversal_nar1491=== RUN TestIsValidUploadKey/absolute1492=== PAUSE TestIsValidUploadKey/absolute1493=== RUN TestIsValidUploadKey/empty_key1494=== PAUSE TestIsValidUploadKey/empty_key1495=== RUN TestIsValidUploadKey/unknown_type1496=== PAUSE TestIsValidUploadKey/unknown_type1497=== CONT TestSweepSkipsRowsLockedByPush1498--- PASS: TestMultipartCleanup (0.88s)1499=== CONT TestGCMetrics1500--- PASS: TestService_verifyS3Integrity (2.00s)1501=== CONT TestPinProtectsFromGC15022026/10/27 08:49:46 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15032026/10/27 08:49:46 INFO Uploading 2yczl2bdnk0qn5av1q958hy81ddq1kr5-shared-dep (136B)15042026/10/27 08:49:46 INFO Uploading 5v4wffmpvmyjajjpf0gaiij9zz3z0h3w-a (216B)15052026/10/27 08:49:46 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=015062026/10/27 08:49:46 INFO Vacuumed table table=pending_closures15072026/10/27 08:49:46 INFO Vacuumed table table=pending_objects15082026/10/27 08:49:46 INFO Vacuumed table table=multipart_uploads15092026/10/27 08:49:46 INFO Vacuumed table table=closures15102026/10/27 08:49:46 INFO Vacuumed table table=objects15112026/10/27 08:49:46 WARN Failed to register uploaded object key=p4fl9fpkib8fh6g09zgsg5ibjzbdpr7d.ls error="server returned 404: 404 page not found\n"15122026/10/27 08:49:46 WARN Failed to register uploaded object key=nar/1j72plxkhphjy8kj0483zgcza6jsr4a3k7is8jh0ymrbf3w95ma3.nar.zst error="server returned 404: 404 page not found\n"15132026/10/27 08:49:46 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15142026/10/27 08:49:46 WARN Failed to register uploaded object key=2yczl2bdnk0qn5av1q958hy81ddq1kr5.ls error="server returned 404: 404 page not found\n"15152026/10/27 08:49:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15162026/10/27 08:49:46 WARN Failed to register uploaded object key=5v4wffmpvmyjajjpf0gaiij9zz3z0h3w.ls error="server returned 404: 404 page not found\n"15172026/10/27 08:49:46 INFO Signed narinfos id=1 count=31518--- PASS: TestGCSweepDeliversEachKeyOnce (0.86s)1519=== CONT TestOrphanedObjectsGCStressTest15202026/10/27 08:49:46 INFO Uploading 3 narinfos15212026/10/27 08:49:46 INFO Aborted multipart uploads count=0 kept=01522--- PASS: TestPresentReportsOnlyClosureRoots (0.58s)1523=== CONT TestCreatePin_ReservedPins15242026/10/27 08:49:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15252026/10/27 08:49:46 WARN Failed to register uploaded object key=2yczl2bdnk0qn5av1q958hy81ddq1kr5.narinfo error="server returned 404: 404 page not found\n"15262026/10/27 08:49:46 WARN Failed to register uploaded object key=p4fl9fpkib8fh6g09zgsg5ibjzbdpr7d.narinfo error="server returned 404: 404 page not found\n"15272026/10/27 08:49:46 INFO Received complete push request method=POST path=/api/pushes/1/complete15282026/10/27 08:49:46 WARN Failed to register uploaded object key=5v4wffmpvmyjajjpf0gaiij9zz3z0h3w.narinfo error="server returned 404: 404 page not found\n"15292026/10/27 08:49:46 INFO Completed push id=1 objects=8 duration=8.928682ms15302026/10/27 08:49:46 INFO Upload complete. (160ms)15312026/10/27 08:49:46 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=01532=== NAME TestClientPushesUseOnePush1533 client_pushes_test.go:97: Retrieved narinfo from S3:1534 StorePath: /build/TestClientPushesUseOnePush1476403771/001/store/2yczl2bdnk0qn5av1q958hy81ddq1kr5-shared-dep1535 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1536 Compression: zstd1537 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821538 NarSize: 1361539 References: 1540 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n15412026/10/27 08:49:46 INFO Vacuumed table table=pending_closures1542 client_pushes_test.go:97: Retrieved narinfo from S3:1543 StorePath: /build/TestClientPushesUseOnePush1476403771/001/store/5v4wffmpvmyjajjpf0gaiij9zz3z0h3w-a1544 URL: nar/1j72plxkhphjy8kj0483zgcza6jsr4a3k7is8jh0ymrbf3w95ma3.nar.zst1545 Compression: zstd1546 NarHash: sha256:1j72plxkhphjy8kj0483zgcza6jsr4a3k7is8jh0ymrbf3w95ma31547 NarSize: 2161548 References: /build/TestClientPushesUseOnePush1476403771/001/store/2yczl2bdnk0qn5av1q958hy81ddq1kr5-shared-dep1549 CA: text:sha256:0f64k6w1zyyv9ydc2fnpp65xps1hiiq7yp85fs68na02qinv26yd1550 client_pushes_test.go:97: Retrieved narinfo from S3:1551 StorePath: /build/TestClientPushesUseOnePush1476403771/001/store/p4fl9fpkib8fh6g09zgsg5ibjzbdpr7d-b1552 URL: nar/1j72plxkhphjy8kj0483zgcza6jsr4a3k7is8jh0ymrbf3w95ma3.nar.zst1553 Compression: zstd1554 NarHash: sha256:1j72plxkhphjy8kj0483zgcza6jsr4a3k7is8jh0ymrbf3w95ma31555 NarSize: 2161556 References: /build/TestClientPushesUseOnePush1476403771/001/store/2yczl2bdnk0qn5av1q958hy81ddq1kr5-shared-dep1557 CA: text:sha256:0f64k6w1zyyv9ydc2fnpp65xps1hiiq7yp85fs68na02qinv26yd15582026/10/27 08:49:46 INFO Vacuumed table table=pending_objects15592026/10/27 08:49:46 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLmRmOTZjOWFiLWNmZWEtNGVkNi1hOGFhLTY5YzMyZmU2MTFlZngxNzkzMDkwOTgyOTY3MzUzNzEy parts=1015602026/10/27 08:49:46 INFO Vacuumed table table=multipart_uploads15612026/10/27 08:49:46 INFO Vacuumed table table=closures15622026/10/27 08:49:46 INFO Vacuumed table table=objects15632026/10/27 08:49:46 INFO Aborted multipart uploads count=0 kept=015642026/10/27 08:49:46 WARN Force mode enabled - objects will be deleted immediately without grace period15652026/10/27 08:49: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=015662026/10/27 08:49:46 INFO Vacuumed table table=pending_closures15672026/10/27 08:49:46 INFO Vacuumed table table=pending_objects15682026/10/27 08:49:46 INFO Vacuumed table table=multipart_uploads15692026/10/27 08:49:46 INFO Vacuumed table table=closures15702026/10/27 08:49:46 INFO Vacuumed table table=objects1571=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1572=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1573=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1574=== NAME TestClientMultipleUploads1575 client_integration_test.go:467: Created store path 0: /build/TestClientMultipleUploads341170158/001/store/cg52fyh2pciyyq00hfhppwzfxg3r2v4y-test-file-0.txt1576=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1577=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1578=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1579=== CONT TestLeadElectsOneAndHandsOver1580--- PASS: TestService_ReadAuthMiddleware (0.62s)1581=== CONT TestGCBugBareHashReferences1582--- PASS: TestPushDedupSurvivesConcurrentGC (1.02s)1583=== CONT TestLeadEndsOnShutdown1584--- PASS: TestClientPushesUseOnePush (1.14s)1585=== CONT TestConnectWaitsForAPeerMigration15862026/10/27 08:49:46 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46485/oidc1587=== NAME TestClientMultipleUploads1588 client_integration_test.go:467: Created store path 1: /build/TestClientMultipleUploads341170158/001/store/1m2hpya95d4czinkcmvy1b661qd6rbs6-test-file-1.txt1589--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (2.16s)1590=== CONT TestService_createPendingClosureHandler15912026/10/27 08:49:46 INFO Received uploads request method=POST path=/api/pending_closures1592=== NAME TestClientMultipleUploads1593 client_integration_test.go:467: Created store path 2: /build/TestClientMultipleUploads341170158/001/store/8cvv6azpx2jrzszqyy0ks8h4v4v7v5sh-test-file-2.txt15942026/10/27 08:49:46 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15952026/10/27 08:49:46 WARN mTLS auth: bound subjects configured but subject DN unavailable15962026/10/27 08:49:46 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1597=== CONT TestLeadIncumbentAnnouncesAtOnce1598--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.56s)1599--- PASS: TestPendingClosureFailureAbortsItsUploads (0.51s)1600=== CONT TestNARDeduplicationMetadataUploadBug16012026/10/27 08:49:46 INFO Received push request method=POST path=/api/pushes16022026/10/27 08:49:46 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16032026/10/27 08:49:46 INFO Uploading cg52fyh2pciyyq00hfhppwzfxg3r2v4y-test-file-0.txt (160B)16042026/10/27 08:49:46 INFO Uploading 8cvv6azpx2jrzszqyy0ks8h4v4v7v5sh-test-file-2.txt (160B)16052026/10/27 08:49:46 INFO Uploading 1m2hpya95d4czinkcmvy1b661qd6rbs6-test-file-1.txt (160B)1606=== NAME TestClientIntegration1607 client_integration_test.go:331: Created store path: /build/TestClientIntegration3340967191/002/store/kbsbfxlkd6zsfgpvwzrr8z59a7f2nx3k-test-file.txt1608=== RUN TestService_RequireScope_OIDC/builder_may_write1609=== PAUSE TestService_RequireScope_OIDC/builder_may_write1610=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1611=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1612=== RUN TestService_RequireScope_OIDC/ops_may_admin1613=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1614=== RUN TestService_RequireScope_OIDC/ops_may_not_write1615=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1616=== RUN TestService_RequireScope_OIDC/reader_may_not_write1617=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1618=== RUN TestService_RequireScope_OIDC/static_token_may_admin1619=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1620=== RUN TestService_RequireScope_OIDC/static_token_may_write1621=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1622=== RUN TestService_RequireScope_OIDC/reader_may_read1623=== PAUSE TestService_RequireScope_OIDC/reader_may_read1624=== RUN TestService_RequireScope_OIDC/writer_implies_read1625=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1626=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1627=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1628=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1629=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1630=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1631=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1632=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1633=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1634=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1635=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1636=== CONT TestChildrenInheritRaisedFileLimit1637=== CONT TestGenerateLandingPage1638--- PASS: TestChildrenInheritRaisedFileLimit (0.00s)16392026/10/27 08:49:46 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16402026/10/27 08:49:46 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16412026/10/27 08:49:46 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"1642--- PASS: TestGenerateLandingPage (0.03s)1643=== CONT TestResolveDBConnectionString1644=== RUN TestResolveDBConnectionString/flag_wins16452026/10/27 08:49:46 WARN Failed to register uploaded object key=1m2hpya95d4czinkcmvy1b661qd6rbs6.ls error="server returned 404: 404 page not found\n"1646=== PAUSE TestResolveDBConnectionString/flag_wins16472026/10/27 08:49:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1648=== RUN TestResolveDBConnectionString/file_when_flag_empty16492026/10/27 08:49:46 WARN Failed to register uploaded object key=cg52fyh2pciyyq00hfhppwzfxg3r2v4y.ls error="server returned 404: 404 page not found\n"16502026/10/27 08:49:46 WARN Failed to register uploaded object key=8cvv6azpx2jrzszqyy0ks8h4v4v7v5sh.ls error="server returned 404: 404 page not found\n"1651=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1652=== RUN TestResolveDBConnectionString/missing_file_is_an_error1653=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1654=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1655=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1656=== RUN TestResolveDBConnectionString/nothing_configured1657=== PAUSE TestResolveDBConnectionString/nothing_configured1658=== CONT TestService_readinessHandler16592026/10/27 08:49:46 INFO Signed narinfos id=1 count=316602026/10/27 08:49:46 INFO Uploading 3 narinfos16612026/10/27 08:49:46 WARN Failed to register uploaded object key=8cvv6azpx2jrzszqyy0ks8h4v4v7v5sh.narinfo error="server returned 404: 404 page not found\n"16622026/10/27 08:49:46 WARN Failed to register uploaded object key=1m2hpya95d4czinkcmvy1b661qd6rbs6.narinfo error="server returned 404: 404 page not found\n"16632026/10/27 08:49:46 INFO Received complete push request method=POST path=/api/pushes/1/complete16642026/10/27 08:49:46 WARN Failed to register uploaded object key=cg52fyh2pciyyq00hfhppwzfxg3r2v4y.narinfo error="server returned 404: 404 page not found\n"16652026/10/27 08:49:46 INFO Received create pin request method=POST path=/api/pins/app16662026/10/27 08:49:46 INFO Completed push id=1 objects=9 duration=6.23112ms16672026/10/27 08:49:46 INFO Upload complete. (148ms)1668=== NAME TestClientMultipleUploads1669 client_integration_test.go:478: Uploaded 3 paths in 193.35522ms16702026/10/27 08:49:46 INFO Created/updated pin name=app store_path=/nix/store/cccccccccccccccccccccccccccccccc-app narinfo_key=cccccccccccccccccccccccccccccccc.narinfo16712026/10/27 08:49:46 INFO Received delete pin request method=DELETE path=/api/pins/app16722026/10/27 08:49:46 ERROR Failed to delete pin from S3 key=pins/app error="Get \"http://127.0.0.1:1/bucket76/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"16732026/10/27 08:49:46 INFO Received delete pin request method=DELETE path=/api/pins/app16742026/10/27 08:49:46 INFO Received push request method=POST path=/api/pushes16752026/10/27 08:49:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16762026/10/27 08:49:46 INFO Uploading kbsbfxlkd6zsfgpvwzrr8z59a7f2nx3k-test-file.txt (152B)16772026/10/27 08:49:46 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"16782026/10/27 08:49:46 INFO Deleted pin name=app1679--- PASS: TestClientMultipleUploads (1.05s)1680=== CONT TestGracefulShutdownDrainsInflight16812026/10/27 08:49:46 INFO Starting HTTP server address=127.0.0.1:4036716822026/10/27 08:49:46 WARN Failed to register uploaded object key=kbsbfxlkd6zsfgpvwzrr8z59a7f2nx3k.ls error="server returned 404: 404 page not found\n"16832026/10/27 08:49:46 INFO Shutdown signal received, draining in-flight requests timeout=10s16842026/10/27 08:49:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16852026/10/27 08:49:46 INFO Signed narinfos id=1 count=116862026/10/27 08:49:46 INFO Uploading 1 narinfos16872026/10/27 08:49:46 INFO Received complete push request method=POST path=/api/pushes/1/complete1688--- PASS: TestDeletePinKeepsRowWhenS3Fails (0.67s)1689=== CONT TestRegisterCompletedObjectNeedsPendingRow16902026/10/27 08:49:46 WARN Failed to register uploaded object key=kbsbfxlkd6zsfgpvwzrr8z59a7f2nx3k.narinfo error="server returned 404: 404 page not found\n"16912026/10/27 08:49:46 INFO Aborted multipart uploads count=0 kept=016922026/10/27 08:49:46 INFO Completed push id=1 objects=3 duration=7.841293ms16932026/10/27 08:49:46 INFO Upload complete. (98ms)16942026/10/27 08:49:46 WARN Force mode enabled - objects will be deleted immediately without grace period16952026/10/27 08:49: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=016962026/10/27 08:49:46 INFO Vacuumed table table=pending_closures16972026/10/27 08:49:46 INFO Vacuumed table table=pending_objects16982026/10/27 08:49:46 INFO Vacuumed table table=multipart_uploads16992026/10/27 08:49:46 INFO Vacuumed table table=closures17002026/10/27 08:49:46 INFO Vacuumed table table=objects1701=== CONT TestGCTaskStore_Fail1702--- PASS: TestGCMetrics (0.57s)1703--- PASS: TestGCTaskStore_Fail (0.00s)1704=== CONT TestService_healthCheckHandler1705=== CONT TestService_AuthMiddleware_MTLSProxyHeader1706--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1707=== NAME TestPinProtectsFromGC1708 client_integration_test.go:854: Pinned store path: /build/TestPinProtectsFromGC2118726534/001/store/fw3wb16rc8y4gl5ifpd8y5p7if1rkdsb-pinned-file.txt17092026/10/27 08:49:46 INFO All 1 paths already cached1710 client_integration_test.go:855: Unpinned store path: /build/TestPinProtectsFromGC2118726534/001/store/ca420znpsmvxdc1c2p2glh23dv1q6x3z-unpinned-file.txt1711=== NAME TestClientIntegration1712 client_integration_test.go:357: Retrieved narinfo from S3:1713 StorePath: /build/TestClientIntegration3340967191/002/store/kbsbfxlkd6zsfgpvwzrr8z59a7f2nx3k-test-file.txt1714 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1715 Compression: zstd1716 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11717 NarSize: 1521718 References: 1719 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11720 client_integration_test.go:358: Retrieved .ls file from S3 (compressed size: 77 bytes)1721 client_integration_test.go:358: Decompressed .ls content (64 bytes):1722 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}17232026/10/27 08:49:46 INFO Aborted multipart uploads count=0 kept=017242026/10/27 08:49:46 INFO Received uploads request method=POST path=/api/pending_closures17252026/10/27 08:49:46 WARN Force mode enabled - objects will be deleted immediately without grace period17262026/10/27 08:49: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=017272026/10/27 08:49:46 INFO Vacuumed table table=pending_closures17282026/10/27 08:49:46 INFO Vacuumed table table=pending_objects17292026/10/27 08:49:46 INFO Vacuumed table table=multipart_uploads17302026/10/27 08:49:46 INFO Vacuumed table table=closures17312026/10/27 08:49:46 INFO Vacuumed table table=objects17322026/10/27 08:49:46 INFO Aborted multipart uploads count=0 kept=017332026/10/27 08:49:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17342026/10/27 08:49:46 WARN Force mode enabled - objects will be deleted immediately without grace period17352026/10/27 08:49:46 INFO lead: acquired remote=192.0.2.1:123417362026/10/27 08:49:46 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLjZhMGI0NWJhLWY1MDktNDdjNS05NTU4LTYyYmQ3MTNlMzE0MngxNzkzMDkwOTgyOTY3MzcyMDQy parts=1017372026/10/27 08:49:47 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=017382026/10/27 08:49:47 INFO Vacuumed table table=pending_closures17392026/10/27 08:49:47 INFO lead: acquired remote=192.0.2.1:123417402026/10/27 08:49:47 INFO Vacuumed table table=pending_objects17412026/10/27 08:49:47 INFO Vacuumed table table=multipart_uploads17422026/10/27 08:49:47 INFO Vacuumed table table=closures17432026/10/27 08:49:47 INFO Vacuumed table table=objects17442026/10/27 08:49:47 INFO Received push request method=POST path=/api/pushes17452026-10-27 08:49:47.010 UTC [377] ERROR: could not obtain lock on row in relation "closures"17462026-10-27 08:49:47.010 UTC [377] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17472026-10-27 08:49:47.012 UTC [377] ERROR: could not obtain lock on row in relation "closures"17482026-10-27 08:49:47.012 UTC [377] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17492026-10-27 08:49:47.013 UTC [377] ERROR: could not obtain lock on row in relation "closures"17502026-10-27 08:49:47.013 UTC [377] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17512026-10-27 08:49:47.014 UTC [377] ERROR: could not obtain lock on row in relation "closures"17522026-10-27 08:49:47.014 UTC [377] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17532026-10-27 08:49:47.015 UTC [377] ERROR: could not obtain lock on row in relation "closures"17542026-10-27 08:49:47.015 UTC [377] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17552026/10/27 08:49:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17562026/10/27 08:49:47 INFO Uploading fw3wb16rc8y4gl5ifpd8y5p7if1rkdsb-pinned-file.txt (128B)1757=== CONT TestGCTaskStore_CompletedAllowsNewTask1758--- PASS: TestSweepSkipsRowsLockedByPush (0.68s)1759--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1760=== CONT TestService_AuthMiddleware_OIDC17612026/10/27 08:49:47 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"17622026/10/27 08:49:47 INFO Received push request method=POST path=/api/pushes17632026/10/27 08:49:47 INFO Aborted multipart uploads count=0 kept=017642026/10/27 08:49:47 WARN Failed to register uploaded object key=fw3wb16rc8y4gl5ifpd8y5p7if1rkdsb.ls error="server returned 404: 404 page not found\n"17652026/10/27 08:49:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17662026/10/27 08:49:47 INFO Signed narinfos id=1 count=117672026/10/27 08:49:47 INFO Object in database but missing from S3 key=kbsbfxlkd6zsfgpvwzrr8z59a7f2nx3k.ls17682026/10/27 08:49:47 WARN Found objects in DB but missing from S3, will re-upload count=117692026/10/27 08:49:47 INFO Uploading 1 narinfos17702026/10/27 08:49:47 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17712026/10/27 08:49:47 WARN Force mode enabled - objects will be deleted immediately without grace period1772--- PASS: TestPush_RootsAreLockedInByteOrder (4.62s)1773=== CONT TestClientCADerivations17742026/10/27 08:49:47 INFO Received complete push request method=POST path=/api/pushes/1/complete17752026/10/27 08:49:47 INFO Received complete push request method=POST path=/api/pushes/2/complete17762026/10/27 08:49:47 WARN Failed to register uploaded object key=fw3wb16rc8y4gl5ifpd8y5p7if1rkdsb.narinfo error="server returned 404: 404 page not found\n"17772026/10/27 08:49:47 WARN Failed to register uploaded object key=kbsbfxlkd6zsfgpvwzrr8z59a7f2nx3k.ls error="server returned 404: 404 page not found\n"17782026/10/27 08:49:47 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."17792026/10/27 08:49:47 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."17802026/10/27 08:49:47 INFO Completed push id=2 objects=3 duration=1.506232ms17812026/10/27 08:49:47 INFO Upload complete. (55ms)1782=== NAME TestClientIntegration1783 client_integration_test.go:375: Retrieved .ls file from S3 (compressed size: 62 bytes)1784 client_integration_test.go:375: Decompressed .ls content (49 bytes):1785 {"version":1,"root":{"type":"regular","size":39}}17862026/10/27 08:49:47 INFO Completed push id=1 objects=3 duration=5.246602ms17872026/10/27 08:49:47 INFO Upload complete. (86ms)17882026/10/27 08:49:47 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux17892026/10/27 08:49:47 WARN Refused reserved pin name=worker-x86_64-linux17902026/10/27 08:49:47 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux17912026/10/27 08:49:47 INFO Received create pin request method=POST path=/api/pins/my-app17922026/10/27 08:49:47 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1793--- PASS: TestFailedS3DeleteKeepsTombstone (0.73s)1794=== CONT TestCacheStatsHandler17952026/10/27 08:49:47 INFO Received uploads request method=POST path=/api/pending_closures17962026/10/27 08:49:47 INFO Received uploads request method=POST path=/api/pending_closures17972026/10/27 08:49:47 INFO Received uploads request method=POST path=/api/pending_closures1798=== CONT TestCommitRacingPendingCleanupKeepsObjects1799--- PASS: TestCreatePin_ReservedPins (0.66s)18002026/10/27 08:49:47 INFO lead: acquired remote=192.0.2.1:123418012026/10/27 08:49:47 INFO lead: released remote=192.0.2.1:12341802=== CONT TestPendingClosureWriteTimeout/empty1803--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.46s)1804=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline18052026/10/27 08:49:47 INFO Received push request method=POST path=/api/pushes18062026/10/27 08:49:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18072026/10/27 08:49:47 INFO Uploading ca420znpsmvxdc1c2p2glh23dv1q6x3z-unpinned-file.txt (128B)18082026/10/27 08:49:47 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41331/oidc18092026/10/27 08:49:47 INFO Received push request method=POST path=/api/pushes18102026/10/27 08:49:47 WARN readiness check failed error="closed pool"18112026/10/27 08:49:47 WARN Failed to register uploaded object key=ca420znpsmvxdc1c2p2glh23dv1q6x3z.ls error="server returned 404: 404 page not found\n"18122026/10/27 08:49:47 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"18132026/10/27 08:49:47 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign18142026/10/27 08:49:47 INFO Signed narinfos id=2 count=118152026/10/27 08:49:47 INFO Uploading 1 narinfos18162026/10/27 08:49:47 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)18172026/10/27 08:49:47 WARN Failed to register uploaded object key=kbsbfxlkd6zsfgpvwzrr8z59a7f2nx3k.ls error="server returned 404: 404 page not found\n"18182026/10/27 08:49:47 INFO Received complete push request method=POST path=/api/pushes/3/complete18192026/10/27 08:49:47 INFO Completed push id=3 objects=3 duration=3.008944ms18202026/10/27 08:49:47 INFO Upload complete. (59ms)18212026/10/27 08:49:47 INFO Received complete push request method=POST path=/api/pushes/2/complete18222026/10/27 08:49:47 WARN Failed to register uploaded object key=ca420znpsmvxdc1c2p2glh23dv1q6x3z.narinfo error="server returned 404: 404 page not found\n"1823=== NAME TestClientIntegration1824 client_integration_test.go:392: Retrieved .ls file from S3 (compressed size: 62 bytes)1825 client_integration_test.go:392: Decompressed .ls content (49 bytes):1826 {"version":1,"root":{"type":"regular","size":39}}1827=== CONT TestPendingClosureWriteTimeout/670k_objects1828--- PASS: TestService_readinessHandler (0.38s)1829=== CONT TestPendingClosureWriteTimeout/400_objects1830=== CONT TestServerTLSConfig/no_client_CA1831=== CONT TestServerTLSConfig/not_a_PEM_file1832=== CONT TestServerTLSConfig/missing_CA_file1833--- PASS: TestServerTLSConfig (0.00s)1834 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1835 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1836 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1837=== CONT TestPush_RejectsBadRequests/bad_root18382026/10/27 08:49:47 INFO Received push request method=POST path=/api/pushes1839=== CONT TestPush_RejectsBadRequests/no_roots18402026/10/27 08:49:47 INFO Completed push id=2 objects=3 duration=3.112075ms18412026/10/27 08:49:47 INFO Received push request method=POST path=/api/pushes18422026/10/27 08:49:47 INFO Upload complete. (82ms)1843=== CONT TestPush_RejectsBadRequests/no_objects18442026/10/27 08:49:47 INFO Received push request method=POST path=/api/pushes1845=== CONT TestPush_RejectsBadRequests/root_not_in_objects18462026/10/27 08:49:47 INFO Received push request method=POST path=/api/pushes1847=== CONT TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false1848=== NAME TestNARDeduplicationMetadataUploadBug1849 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug1827038384/001/store/pp47pcj28qzix37yypjk0s6hf9d5hdyw-file1.txt1850--- PASS: TestPush_RejectsBadRequests (0.44s)1851 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1852 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1853 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1854 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)18552026/10/27 08:49:47 INFO Starting cleanup of old closures method=DELETE path=/api/closures1856--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.34s)1857=== CONT TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true18582026/10/27 08:49:47 INFO Garbage collection started18592026/10/27 08:49:47 INFO Aborted multipart uploads count=0 kept=018602026/10/27 08:49:47 WARN Force mode enabled - objects will be deleted immediately without grace period1861--- PASS: TestService_healthCheckHandler (0.34s)1862=== CONT TestIsValidCachePath/narinfo1863=== CONT TestIsValidCachePath/short_hash1864=== CONT TestIsValidCachePath/wrong_extension1865=== CONT TestIsValidCachePath/empty1866=== CONT TestIsValidCachePath/leading_slash1867=== CONT TestIsValidCachePath/random_path1868=== CONT TestIsValidCachePath/invalid_char_u1869=== CONT TestIsValidCachePath/traversal_in_middle1870=== CONT TestIsValidCachePath/invalid_char_e1871=== CONT TestIsValidCachePath/index.html1872=== CONT TestIsValidCachePath/nix-cache-info1873=== CONT TestIsValidCachePath/traversal_parent1874=== CONT TestIsValidCachePath/realisation1875=== CONT TestIsValidCachePath/log1876=== CONT TestIsValidCachePath/nar_uncompressed1877=== CONT TestIsValidCachePath/nar_bz21878=== CONT TestIsValidCachePath/nar_xz1879=== CONT TestIsValidCachePath/ls1880=== CONT TestIsValidCachePath/nar_zst1881=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1882=== CONT TestParseSingleRange/malformed_both_empty1883=== CONT TestParseSingleRange/suffix18842026/10/27 08:49:47 INFO Received push request method=POST path=/api/pushes1885--- PASS: TestIsValidCachePath (0.00s)1886 --- PASS: TestIsValidCachePath/narinfo (0.00s)1887 --- PASS: TestIsValidCachePath/short_hash (0.00s)1888 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1889 --- PASS: TestIsValidCachePath/empty (0.00s)1890 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1891 --- PASS: TestIsValidCachePath/random_path (0.00s)1892 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1893 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1894 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1895 --- PASS: TestIsValidCachePath/index.html (0.00s)1896 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1897 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1898 --- PASS: TestIsValidCachePath/realisation (0.00s)1899 --- PASS: TestIsValidCachePath/log (0.00s)1900 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1901 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1902 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1903 --- PASS: TestIsValidCachePath/ls (0.00s)1904 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1905 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1906=== CONT TestParseSingleRange/start_past_EOF1907=== CONT TestParseSingleRange/single_byte1908=== CONT TestParseSingleRange/start_far_past_EOF1909=== CONT TestParseSingleRange/suffix_exceeds_size1910=== CONT TestParseSingleRange/end_clamped_to_size1911=== CONT TestParseSingleRange/open-ended1912=== CONT TestParseSingleRange/malformed_no_dash1913=== CONT TestParseSingleRange/closed1914=== CONT TestParseSingleRange/malformed_end_before_start1915=== CONT TestParseSingleRange/unknown_unit1916=== CONT TestParseSingleRange/multi-range_ignored1917=== CONT TestParseSingleRange/none1918=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1919--- PASS: TestParseSingleRange (0.00s)1920 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1921 --- PASS: TestParseSingleRange/suffix (0.00s)1922 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1923 --- PASS: TestParseSingleRange/single_byte (0.00s)1924 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1925 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1926 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1927 --- PASS: TestParseSingleRange/open-ended (0.00s)1928 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1929 --- PASS: TestParseSingleRange/closed (0.00s)1930 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1931 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1932 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1933 --- PASS: TestParseSingleRange/none (0.00s)19342026/10/27 08:49:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19352026/10/27 08:49:47 INFO Uploading pp47pcj28qzix37yypjk0s6hf9d5hdyw-file1.txt (160B)19362026/10/27 08:49:47 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"1937--- PASS: TestGCBugBareHashReferences (0.72s)1938=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale19392026/10/27 08:49:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19402026/10/27 08:49:47 WARN Failed to register uploaded object key=pp47pcj28qzix37yypjk0s6hf9d5hdyw.ls error="server returned 404: 404 page not found\n"19412026/10/27 08:49:47 INFO Signed narinfos id=1 count=119422026/10/27 08:49:47 INFO Uploading 1 narinfos19432026/10/27 08:49:47 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=019442026/10/27 08:49:47 INFO Received push request method=POST path=/api/pushes1945=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1946--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.38s)19472026/10/27 08:49:47 INFO Received uploads request method=POST path=/1948=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key19492026/10/27 08:49:47 INFO Vacuumed table table=pending_closures19502026/10/27 08:49:47 INFO Received complete multipart upload request method=POST path=/1951=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key19522026/10/27 08:49:47 INFO Received request for more parts method=POST path=/1953=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal19542026/10/27 08:49:47 INFO Received uploads request method=POST path=/1955=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1956--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1957 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1958 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1959 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1960 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)19612026/10/27 08:49:47 WARN Failed to register uploaded object key=pp47pcj28qzix37yypjk0s6hf9d5hdyw.narinfo error="server returned 404: 404 page not found\n"19622026/10/27 08:49:47 INFO Received complete push request method=POST path=/api/pushes/1/complete19632026/10/27 08:49:47 INFO Vacuumed table table=pending_objects19642026/10/27 08:49:47 INFO Vacuumed table table=multipart_uploads19652026/10/27 08:49:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19662026/10/27 08:49:47 INFO Uploading akvl3ximcxsr8akj3d5m95vdxgj9vs4v-lost-commit.txt (152B)19672026/10/27 08:49:47 INFO Vacuumed table table=closures19682026/10/27 08:49:47 INFO Completed push id=1 objects=3 duration=11.451642ms19692026/10/27 08:49:47 INFO Upload complete. (123ms)1970=== NAME TestNARDeduplicationMetadataUploadBug1971 metadata_upload_test.go:54: Retrieved narinfo from S3:1972 StorePath: /build/TestNARDeduplicationMetadataUploadBug1827038384/001/store/pp47pcj28qzix37yypjk0s6hf9d5hdyw-file1.txt1973 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1974 Compression: zstd1975 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1976 NarSize: 1601977 References: 1978 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf19792026/10/27 08:49:47 INFO Vacuumed table table=objects1980 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1981 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1982 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}19832026/10/27 08:49:47 WARN Failed to register uploaded object key=nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst error="server returned 404: 404 page not found\n"19842026/10/27 08:49:47 INFO Received sign narinfos request method=POST path=/api/pushes/4/sign19852026/10/27 08:49:47 INFO Signed narinfos id=4 count=119862026/10/27 08:49:47 INFO Uploading 1 narinfos19872026/10/27 08:49:47 WARN Failed to register uploaded object key=akvl3ximcxsr8akj3d5m95vdxgj9vs4v.ls error="server returned 404: 404 page not found\n"1988 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug1827038384/001/store/hwvi8qg9m7pdq96s3db4vv4zc2cprvk3-file2.txt19892026/10/27 08:49:47 INFO Received complete push request method=POST path=/api/pushes/4/complete19902026/10/27 08:49:47 WARN Failed to register uploaded object key=akvl3ximcxsr8akj3d5m95vdxgj9vs4v.narinfo error="server returned 404: 404 page not found\n"19912026/10/27 08:49:47 INFO Completed push id=4 objects=3 duration=4.715128ms19922026/10/27 08:49:47 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:36991/api/pushes/4/complete\": EOF" url=http://127.0.0.1:36991/api/pushes/4/complete1993--- PASS: TestCacheStatsHandler (0.47s)1994=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check19952026/10/27 08:49:47 INFO Received push request method=POST path=/api/pushes19962026/10/27 08:49:47 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)1997=== NAME TestClientCADerivations1998 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations2223343682/001/store/a8gga4qiw5c5was5605j0rwz33d7557k-ca-test19992026/10/27 08:49:47 INFO Received complete push request method=POST path=/api/pushes/4/complete20002026-10-27 08:49:47.568 UTC [979] ERROR: Push does not exist: id=420012026-10-27 08:49:47.568 UTC [979] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE20022026-10-27 08:49:47.568 UTC [979] STATEMENT: -- name: CommitPush :one2003 SELECT commit_push($1::bigint)::bigint2004 20052026/10/27 08:49:47 WARN Push not found id=420062026/10/27 08:49:47 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign20072026/10/27 08:49:47 INFO Signed narinfos id=2 count=120082026/10/27 08:49:47 INFO Uploading 1 narinfos20092026/10/27 08:49:47 WARN Failed to register uploaded object key=hwvi8qg9m7pdq96s3db4vv4zc2cprvk3.ls error="server returned 404: 404 page not found\n"20102026/10/27 08:49:47 INFO Upload complete. (318ms)2011=== NAME TestClientIntegration2012 client_integration_test.go:422: Retrieved narinfo from S3:2013 StorePath: /build/TestClientIntegration3340967191/002/store/akvl3ximcxsr8akj3d5m95vdxgj9vs4v-lost-commit.txt2014 URL: nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst2015 Compression: zstd2016 NarHash: sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl2017 NarSize: 1522018 References: 2019 CA: fixed:r:sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl20202026/10/27 08:49:47 INFO Received complete push request method=POST path=/api/pushes/2/complete20212026/10/27 08:49:47 INFO Received uploads request method=POST path=/api/pending_closures20222026/10/27 08:49:47 WARN Failed to register uploaded object key=hwvi8qg9m7pdq96s3db4vv4zc2cprvk3.narinfo error="server returned 404: 404 page not found\n"20232026/10/27 08:49:47 INFO Completed push id=2 objects=3 duration=2.927364ms2024 client_integration_test.go:425: Testing garbage collection...20252026/10/27 08:49:47 INFO Upload complete. (95ms)2026=== NAME TestNARDeduplicationMetadataUploadBug2027 metadata_upload_test.go:76: Retrieved narinfo from S3:2028 StorePath: /build/TestNARDeduplicationMetadataUploadBug1827038384/001/store/hwvi8qg9m7pdq96s3db4vv4zc2cprvk3-file2.txt2029 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2030 Compression: zstd2031 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2032 NarSize: 1602033 References: 2034 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf20352026/10/27 08:49:47 INFO Aborted multipart uploads count=0 kept=02036 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2037 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2038 {"version":1,"root":{"type":"regular","size":44}}20392026/10/27 08:49:47 WARN Force mode enabled - objects will be deleted immediately without grace period2040=== NAME TestClientCADerivations2041 client_ca_test.go:139: Found 1 dependencies (including self)20422026/10/27 08:49:47 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=020432026/10/27 08:49:47 INFO Vacuumed table table=pending_closures2044--- PASS: TestNARDeduplicationMetadataUploadBug (0.95s)2045=== CONT TestCacheConfigHandler/full_config,_no_issuer20462026/10/27 08:49:47 INFO Vacuumed table table=pending_objects2047=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2048=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2049=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2050=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2051=== CONT TestCacheConfigHandler/no_signing_keys2052=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2053=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2054=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2055=== CONT TestCacheConfigHandler/no_cache_url_configured2056=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2057=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2058=== CONT TestClientErrorHandling/ServerNotAvailable20592026/10/27 08:49:47 INFO Vacuumed table table=multipart_uploads2060=== CONT TestClientErrorHandling/InvalidStorePath2061--- PASS: TestCacheConfigHandler (0.00s)2062 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2063 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2064 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2065 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)20662026/10/27 08:49:47 INFO Vacuumed table table=closures20672026/10/27 08:49:47 INFO Vacuumed table table=objects20682026/10/27 08:49:47 INFO Starting cleanup of old closures method=DELETE path=/api/closures20692026/10/27 08:49:47 INFO Garbage collection started20702026/10/27 08:49:47 INFO Aborted multipart uploads count=0 kept=020712026/10/27 08:49:47 WARN Force mode enabled - objects will be deleted immediately without grace period2072--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.59s)2073=== CONT TestClientErrorHandling/InvalidAuthToken20742026/10/27 08:49:47 INFO Received uploads request method=POST path=/api/pending_closures20752026/10/27 08:49:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20762026/10/27 08:49:47 INFO Received uploads request method=POST path=/api/pending_closures20772026/10/27 08:49:47 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/present20782026/10/27 08:49:47 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=020792026/10/27 08:49:47 INFO Vacuumed table table=pending_closures20802026/10/27 08:49:47 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLjNhMjJkZjc1LTcyOGYtNDBhYy1iMGYzLWJkZWRmYzhkY2Q2MngxNzkzMDkwOTg3MDc5MjEwNTY4 parts=1020812026/10/27 08:49:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20822026/10/27 08:49:47 INFO Vacuumed table table=pending_objects20832026/10/27 08:49:47 INFO Vacuumed table table=multipart_uploads20842026/10/27 08:49:47 INFO Completed upload id=1 objects=2 duration=3.83121ms20852026/10/27 08:49:47 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000020862026/10/27 08:49:47 INFO Vacuumed table table=closures20872026/10/27 08:49:47 INFO Received uploads request method=POST path=/api/pending_closures2088--- PASS: TestDeleteClosuresRacingPins (2.49s)2089=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark20902026/10/27 08:49:47 INFO Vacuumed table table=objects20912026/10/27 08:49:47 INFO Starting cleanup of old closures method=DELETE path=/api/closures20922026/10/27 08:49:47 INFO Received push request method=POST path=/api/pushes20932026/10/27 08:49:47 INFO Aborted multipart uploads count=0 kept=020942026/10/27 08:49:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20952026/10/27 08:49:47 INFO Uploading a8gga4qiw5c5was5605j0rwz33d7557k-ca-test (144B)20962026/10/27 08:49:47 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>20972026/10/27 08:49:47 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=020982026/10/27 08:49:47 INFO Vacuumed table table=pending_closures20992026/10/27 08:49:47 INFO Vacuumed table table=pending_objects21002026/10/27 08:49:47 INFO Vacuumed table table=multipart_uploads21012026/10/27 08:49:47 WARN Failed to register uploaded object key=log/m08dgna82wjb7wn1dj1a8k67ls8lcrqn-ca-test.drv error="server returned 404: 404 page not found\n"21022026/10/27 08:49:47 INFO Vacuumed table table=closures21032026/10/27 08:49:47 INFO Vacuumed table table=objects21042026/10/27 08:49:47 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"21052026/10/27 08:49:47 WARN Failed to register uploaded object key=a8gga4qiw5c5was5605j0rwz33d7557k.ls error="server returned 404: 404 page not found\n"21062026/10/27 08:49:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21072026/10/27 08:49:47 INFO Signed narinfos id=1 count=121082026/10/27 08:49:47 INFO Uploading 1 narinfos2109--- PASS: TestReadProxyNarinfo (1.53s)2110=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete21112026/10/27 08:49:47 INFO Received complete push request method=POST path=/api/pushes/1/complete21122026/10/27 08:49:47 WARN Failed to register uploaded object key=a8gga4qiw5c5was5605j0rwz33d7557k.narinfo error="server returned 404: 404 page not found\n"21132026/10/27 08:49:47 INFO Completed push id=1 objects=4 duration=4.643597ms21142026/10/27 08:49:47 INFO Upload complete. (120ms)21152026/10/27 08:49:47 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000002116=== NAME TestClientCADerivations2117 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations2223343682/001/store/a8gga4qiw5c5was5605j0rwz33d7557k-ca-test2118 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2119 Compression: zstd2120 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2121 NarSize: 1442122 References: 2123 Deriver: /build/TestClientCADerivations2223343682/001/store/m08dgna82wjb7wn1dj1a8k67ls8lcrqn-ca-test.drv2124 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2125 client_ca_test.go:185: Checking for realisation files in S3...2126 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2127 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache21282026/10/27 08:49:47 INFO Received uploads request method=POST path=/api/pending_closures21292026-10-27 08:49:47.785 UTC [174] LOG: checkpoints are occurring too frequently (10 seconds apart)21302026-10-27 08:49:47.785 UTC [174] HINT: Consider increasing the configuration parameter "max_wal_size".21312026-10-27 08:49:47.786 UTC [174] LOG: checkpoint starting: wal2132--- PASS: TestService_createPendingClosureHandler (1.20s)2133=== CONT TestGCEndsOnShutdown/before_the_run21342026/10/27 08:49:47 INFO Aborted multipart uploads count=0 kept=021352026/10/27 08:49:47 WARN Force mode enabled - objects will be deleted immediately without grace period21362026/10/27 08:49:47 INFO Received uploads request method=POST path=/api/pending_closures21372026/10/27 08:49:47 WARN Request failed, retrying attempt=2 backoff=185.113815ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21382026/10/27 08:49:47 INFO Aborted multipart uploads count=0 kept=021392026/10/27 08:49:47 WARN Force mode enabled - objects will be deleted immediately without grace period21402026/10/27 08:49:47 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=021412026/10/27 08:49:47 INFO Vacuumed table table=pending_closures21422026/10/27 08:49:47 INFO Vacuumed table table=pending_objects21432026/10/27 08:49:47 INFO Vacuumed table table=multipart_uploads21442026/10/27 08:49:47 INFO Vacuumed table table=closures21452026/10/27 08:49:47 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=021462026/10/27 08:49:47 INFO Vacuumed table table=pending_closures21472026/10/27 08:49:47 INFO Vacuumed table table=objects21482026/10/27 08:49:47 INFO Vacuumed table table=pending_objects21492026/10/27 08:49:47 INFO Vacuumed table table=multipart_uploads21502026/10/27 08:49:47 INFO Vacuumed table table=closures21512026/10/27 08:49:47 INFO Vacuumed table table=objects2152=== CONT TestProxyWriteTimeout/1_GiB_nar2153=== CONT TestProxyWriteTimeout/unknown_size2154=== CONT TestProxyWriteTimeout/10_GiB_nar2155=== CONT TestIsValidUploadKey/narinfo2156=== CONT TestProxyWriteTimeout/narinfo2157--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2158 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.55s)2159 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.32s)2160=== CONT TestIsValidUploadKey/empty_key2161=== CONT TestIsValidUploadKey/unknown_type2162--- PASS: TestProxyWriteTimeout (0.00s)2163 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2164 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2165 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2166 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2167=== CONT TestIsValidUploadKey/traversal_nar2168=== CONT TestIsValidUploadKey/absolute2169=== CONT TestIsValidUploadKey/traversal2170=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2171=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2172=== CONT TestIsValidUploadKey/index.html2173=== CONT TestIsValidUploadKey/nix-cache-info2174=== CONT TestIsValidUploadKey/realisation_plus_in_output2175=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2176=== CONT TestIsValidUploadKey/realisation2177=== CONT TestIsValidUploadKey/build_log_question_mark2178=== CONT TestIsValidUploadKey/build_log_plus_in_name2179=== CONT TestIsValidUploadKey/build_log_home-manager_file2180=== CONT TestIsValidUploadKey/build_log_equals2181=== CONT TestIsValidUploadKey/build_log2182=== CONT TestIsValidUploadKey/listing2183=== CONT TestIsValidUploadKey/nar_plain2184=== CONT TestIsValidUploadKey/nar_zst2185=== CONT TestIsValidUploadKey/nar_xz2186=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts2187=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart21882026/10/27 08:49:47 INFO Received request for more parts method=POST path=/2189--- PASS: TestIsValidUploadKey (0.00s)2190 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2191 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2192 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2193 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2194 --- PASS: TestIsValidUploadKey/absolute (0.00s)2195 --- PASS: TestIsValidUploadKey/traversal (0.00s)2196 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2197 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2198 --- PASS: TestIsValidUploadKey/index.html (0.00s)2199 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2200 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2201 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2202 --- PASS: TestIsValidUploadKey/realisation (0.00s)2203 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2204 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2205 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2206 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2207 --- PASS: TestIsValidUploadKey/build_log (0.00s)2208 --- PASS: TestIsValidUploadKey/listing (0.00s)2209 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2210 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2211 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)22122026/10/27 08:49:47 INFO Received complete multipart upload request method=POST path=/2213=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure22142026/10/27 08:49:47 INFO Received uploads request method=POST path=/2215=== NAME TestClientCADerivations2216 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2217 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2218 error: binary cache 's3://bucket93?endpoint=http://localhost:37077®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations2223343682/001/store'2219 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12220--- PASS: TestClientCADerivations (0.84s)2221=== CONT TestService_RequireScope_OIDC/ops_may_admin2222=== CONT TestService_RequireScope_OIDC/static_token_may_write2223=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2224=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read22252026/10/27 08:49:47 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]2226=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2227=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2228=== CONT TestService_RequireScope_OIDC/reader_may_read2229=== CONT TestService_RequireScope_OIDC/ops_may_not_write2230=== CONT TestService_RequireScope_OIDC/writer_implies_read2231=== CONT TestService_RequireScope_OIDC/static_token_may_admin2232=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2233=== CONT TestService_RequireScope_OIDC/reader_may_not_write2234=== CONT TestService_RequireScope_OIDC/builder_may_write2235=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2236=== CONT TestResolveDBConnectionString/flag_wins2237=== CONT TestResolveDBConnectionString/missing_file_is_an_error2238=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2239=== CONT TestResolveDBConnectionString/file_when_flag_empty2240=== CONT TestResolveDBConnectionString/nothing_configured2241=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2242--- PASS: TestResolveDBConnectionString (0.00s)2243 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2244 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2245 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2246 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2247 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)22482026/10/27 08:49:47 WARN Authentication failed token_preview=eyJhbGciOi...rri733RtOg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2249=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected22502026/10/27 08:49:47 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]2251=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2252=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token22532026/10/27 08:49:47 INFO Aborted multipart uploads count=0 kept=022542026/10/27 08:49:47 WARN Force mode enabled - objects will be deleted immediately without grace period22552026/10/27 08:49:47 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2256--- PASS: TestService_RequireScope_OIDC (1.05s)2257 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2258 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2259 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2260 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2261 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2262 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2263 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2264 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2265 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2266 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2267 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2268 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2269 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2270 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2271--- PASS: TestService_AuthMiddleware_OIDC (0.61s)2272 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2273 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2274 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2275 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)22762026-10-27 08:49:47.921 UTC [1901] ERROR: canceling statement due to user request22772026-10-27 08:49:47.921 UTC [1901] CONTEXT: SQL statement "UPDATE object_stats s2278 SET object_count = s.object_count + n.n - o.n,2279 total_bytes = s.total_bytes + n.bytes - o.bytes2280 FROM (2281 SELECT count(*) AS n, coalesce(sum(size), 0) AS bytes2282 FROM new_rows WHERE deleted_at IS NULL2283 ) AS n,2284 (2285 SELECT count(*) AS n, coalesce(sum(size), 0) AS bytes2286 FROM old_rows WHERE deleted_at IS NULL2287 ) AS o2288 WHERE s.id AND (n.n <> o.n OR n.bytes <> o.bytes)"2289 PL/pgSQL function object_stats_update() line 3 at SQL statement22902026-10-27 08:49:47.921 UTC [1901] STATEMENT: -- name: MarkStaleObjects :execrows2291 WITH RECURSIVE ct AS (2292 SELECT timezone('UTC', now()) AS now2293 ),2294 closure_reach AS (2295 -- Start with all closure keys2296 SELECT o.key, o.refs2297 FROM objects o2298 INNER JOIN closures c ON o.key = c.key2299 UNION2300 -- Recursively add all referenced objects2301 SELECT o.key, o.refs2302 FROM objects o2303 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2304 ),2305 reachable_objects AS (2306 SELECT DISTINCT key FROM closure_reach2307 ),2308 stale_objects AS (2309 SELECT o.key2310 FROM objects AS o, ct2311 WHERE2312 NOT EXISTS (2313 SELECT 12314 FROM reachable_objects ro2315 WHERE ro.key = o.key2316 )2317 AND NOT EXISTS (2318 SELECT 12319 FROM pending_objects AS po2320 WHERE po.key = o.key2321 )2322 AND o.deleted_at IS NULL -- Only mark fresh objects2323 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2324 FOR UPDATE2325 )2326 UPDATE objects2327 SET2328 deleted_at = ct.now,2329 first_deleted_at = COALESCE(first_deleted_at, ct.now)2330 FROM stale_objects, ct2331 WHERE objects.key = stale_objects.key2332 23332026/10/27 08:49:47 INFO Aborted multipart uploads count=0 kept=023342026/10/27 08:49:47 WARN Force mode enabled - objects will be deleted immediately without grace period23352026/10/27 08:49:47 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:37077/bucket107/?delete=\": context canceled"23362026/10/27 08:49:47 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2337--- PASS: TestGCEndsOnShutdown (0.00s)2338 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.22s)2339 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.19s)2340 --- PASS: TestGCEndsOnShutdown/before_the_run (0.17s)23412026/10/27 08:49:47 WARN Request failed, retrying attempt=3 backoff=413.433918ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present23422026/10/27 08:49:48 INFO lead: released remote=192.0.2.1:12342343--- PASS: TestLeadEndsOnShutdown (1.55s)23442026/10/27 08:49:48 INFO lead: released remote=192.0.2.1:123423452026/10/27 08:49:48 WARN Failed to abort multipart upload key=nar/ssssssssssssssssssssssssssssssssssssssssssssssssssss.nar.zst upload_id=ZDc4MTg0NjQtZGI5Yi00MWJiLTk0N2YtOGQwMDQ4MTc2ZWIyLjliZjI3MTY3LWY0NmUtNDBmMC1hZWI2LWZhNzUzOWFlYjZlYXgxNzkzMDkwOTg3NzA2MjUyNzA1 error="Access Denied"23462026/10/27 08:49:48 WARN keeping failed pending closure for cleanup to retry the abort id=12347--- PASS: TestPendingClosureFailureTracksEveryUpload (0.00s)2348 --- PASS: TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false (1.03s)2349 --- PASS: TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true (1.01s)23502026/10/27 08:49:48 INFO lead: acquired remote=192.0.2.1:12342351--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2352 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.99s)2353 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.99s)2354--- PASS: TestPendingClosureWriteTimeout (0.00s)2355 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2356 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2357 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2358 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.29s)23592026/10/27 08:49:48 WARN Request failed, retrying attempt=4 backoff=742.523208ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2360=== NAME TestOrphanedObjectsGCStressTest2361 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2362 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion2363 orphaned_objects_gc_test.go:503: Stress test completed successfully:2364 orphaned_objects_gc_test.go:504: - Active objects preserved: 202365 orphaned_objects_gc_test.go:505: - Objects deleted: 2102366 orphaned_objects_gc_test.go:506: - Total GC'd: 2102367--- PASS: TestOrphanedObjectsGCStressTest (2.67s)23682026/10/27 08:49:49 WARN Request failed, retrying attempt=5 backoff=1.624773444s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present23692026/10/27 08:49:49 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=023702026/10/27 08:49:49 INFO Received create pin request method=POST path=/api/pins/myapp23712026/10/27 08:49:49 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2118726534/001/store/fw3wb16rc8y4gl5ifpd8y5p7if1rkdsb-pinned-file.txt narinfo_key=fw3wb16rc8y4gl5ifpd8y5p7if1rkdsb.narinfo23722026/10/27 08:49:49 INFO Starting cleanup of old closures method=DELETE path=/api/closures23732026/10/27 08:49:49 INFO Garbage collection started23742026/10/27 08:49:49 INFO Aborted multipart uploads count=0 kept=023752026/10/27 08:49:49 WARN Force mode enabled - objects will be deleted immediately without grace period23762026/10/27 08:49:49 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=023772026/10/27 08:49:49 INFO Vacuumed table table=pending_closures23782026/10/27 08:49:49 INFO Vacuumed table table=pending_objects23792026/10/27 08:49:49 INFO Vacuumed table table=multipart_uploads23802026/10/27 08:49:49 INFO Vacuumed table table=closures23812026/10/27 08:49:49 INFO Vacuumed table table=objects23822026/10/27 08:49:49 INFO lead: released remote=192.0.2.1:12342383--- PASS: TestLeadElectsOneAndHandsOver (2.76s)2384--- PASS: TestConnectSerialisesConcurrentMigrations (5.11s)23852026/10/27 08:49:49 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=2 objects_marked=6 objects_deleted=6 objects_failed=02386=== NAME TestClientIntegration2387 client_integration_test.go:432: Objects in database after GC:2388 client_integration_test.go:432: Successfully deleted all objects with GC --force2389--- PASS: TestReadProxyOutlastsServerWriteTimeout (5.54s)2390--- PASS: TestClientIntegration (3.55s)23912026/10/27 08:49:50 WARN Rate limiter enabled after throttle name=s3-test rate=523922026/10/27 08:49:50 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2393=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2394 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102395 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002396--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.35s)23972026/10/27 08:49:50 INFO Aborted multipart uploads count=1 kept=023982026/10/27 08:49:50 INFO Received cleanup request method=DELETE path=/api/pending_closures23992026/10/27 08:49:50 INFO Aborted multipart uploads count=1 kept=02400--- PASS: TestPendingCleanupUsesOneCutoff (7.08s)24012026/10/27 08:49: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-config24022026/10/27 08:49:50 WARN Request failed, retrying attempt=2 backoff=217.072141ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config24032026/10/27 08:49:51 WARN Request failed, retrying attempt=3 backoff=430.073129ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2404=== NAME TestPinProtectsFromGC2405 client_integration_test.go:963: Pin successfully protected closure from garbage collection2406--- PASS: TestPinProtectsFromGC (5.02s)24072026/10/27 08:49:51 WARN Request failed, retrying attempt=4 backoff=873.938621ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2408--- PASS: TestConnectWaitsForAPeerMigration (5.19s)24092026/10/27 08:49:52 WARN Request failed, retrying attempt=5 backoff=1.607627773s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config24102026/10/27 08:49:54 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"24112026/10/27 08:49:54 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-config24122026/10/27 08:49:54 WARN Request failed, retrying attempt=2 backoff=211.356463ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config24132026/10/27 08:49:54 WARN Request failed, retrying attempt=3 backoff=392.569991ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config24142026/10/27 08:49:54 WARN Request failed, retrying attempt=4 backoff=816.021463ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2415--- PASS: TestUploadHandlersRejectOversizedBody (0.94s)2416 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.49s)2417 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.50s)2418 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (7.02s)24192026/10/27 08:49:55 WARN Request failed, retrying attempt=5 backoff=1.558866084s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config24202026/10/27 08:49:57 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_closures24212026/10/27 08:49:57 WARN Request failed, retrying attempt=2 backoff=192.396534ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures24222026/10/27 08:49:57 WARN Request failed, retrying attempt=3 backoff=388.25164ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures24232026/10/27 08:49:57 WARN Request failed, retrying attempt=4 backoff=790.187225ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures24242026/10/27 08:49:58 WARN Request failed, retrying attempt=5 backoff=1.467816854s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2425--- PASS: TestClientErrorHandling (0.00s)2426 --- PASS: TestClientErrorHandling/InvalidStorePath (0.24s)2427 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.29s)2428 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.46s)2429PASS24302026-10-27 08:50:00.275 UTC [169] LOG: received smart shutdown request24312026-10-27 08:50:00.277 UTC [169] LOG: background worker "logical replication launcher" (PID 179) exited with exit code 124322026-10-27 08:50:01.292 UTC [174] LOG: checkpoint complete: wrote 9454 buffers (57.7%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=12.639 s, sync=0.813 s, total=13.507 s; sync files=37078, longest=0.010 s, average=0.001 s; distance=533181 kB, estimate=533181 kB; lsn=0/229ABBE0, redo lsn=0/220152C824332026-10-27 08:50:01.295 UTC [174] LOG: shutting down24342026-10-27 08:50:01.295 UTC [174] LOG: checkpoint starting: shutdown immediate24352026-10-27 08:50:01.403 UTC [174] LOG: checkpoint complete: wrote 1628 buffers (9.9%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.023 s, sync=0.084 s, total=0.109 s; sync files=530, longest=0.002 s, average=0.001 s; distance=9818 kB, estimate=480845 kB; lsn=0/229ABC58, redo lsn=0/229ABC5824362026-10-27 08:50:01.457 UTC [169] LOG: database system is shut down2437Running OIDC tests...2438=== RUN TestAudienceForIssuer2439=== PAUSE TestAudienceForIssuer2440=== RUN TestHTTPClientForHasTimeouts2441=== PAUSE TestHTTPClientForHasTimeouts2442=== RUN TestGlobMatch2443=== PAUSE TestGlobMatch2444=== RUN TestValidateToken_ValidToken2445=== PAUSE TestValidateToken_ValidToken2446=== RUN TestValidateToken_WrongAudience2447=== PAUSE TestValidateToken_WrongAudience2448=== RUN TestValidateToken_Expired2449=== PAUSE TestValidateToken_Expired2450=== RUN TestValidateToken_BoundClaimsMismatch2451=== PAUSE TestValidateToken_BoundClaimsMismatch2452=== RUN TestValidateToken_BoundSubjectMismatch2453=== PAUSE TestValidateToken_BoundSubjectMismatch2454=== RUN TestValidateToken_MultipleProviders2455=== PAUSE TestValidateToken_MultipleProviders2456=== RUN TestValidateToken_NoMatchingProvider2457=== PAUSE TestValidateToken_NoMatchingProvider2458=== RUN TestValidateToken_KubernetesServiceAccount2459=== PAUSE TestValidateToken_KubernetesServiceAccount2460=== RUN TestNewValidator_KubernetesRequiresCA2461=== PAUSE TestNewValidator_KubernetesRequiresCA2462=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2463=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2464=== RUN TestPins_ReservedForMatchingRule2465=== PAUSE TestPins_ReservedForMatchingRule2466=== RUN TestPins_TopLevelShorthand2467=== PAUSE TestPins_TopLevelShorthand2468=== RUN TestPins_ConfigValidation2469=== PAUSE TestPins_ConfigValidation2470=== RUN TestScopes_LegacyProviderDefaultsToWrite2471=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2472=== RUN TestScopes_Rules2473=== PAUSE TestScopes_Rules2474=== RUN TestScopes_ConfigValidation2475=== PAUSE TestScopes_ConfigValidation2476=== CONT TestAudienceForIssuer2477=== CONT TestScopes_LegacyProviderDefaultsToWrite2478=== CONT TestValidateToken_WrongAudience2479=== CONT TestValidateToken_KubernetesServiceAccount2480=== CONT TestPins_TopLevelShorthand2481=== CONT TestPins_ReservedForMatchingRule2482=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2483=== CONT TestNewValidator_KubernetesRequiresCA2484=== CONT TestScopes_ConfigValidation2485=== CONT TestScopes_Rules2486=== CONT TestGlobMatch2487=== CONT TestValidateToken_ValidToken2488=== CONT TestValidateToken_BoundSubjectMismatch2489=== CONT TestValidateToken_NoMatchingProvider2490=== CONT TestValidateToken_MultipleProviders2491=== CONT TestValidateToken_BoundClaimsMismatch2492=== CONT TestHTTPClientForHasTimeouts2493=== CONT TestValidateToken_Expired2494=== CONT TestPins_ConfigValidation2495--- PASS: TestAudienceForIssuer (0.00s)2496--- PASS: TestScopes_ConfigValidation (0.00s)2497=== RUN TestGlobMatch/foo_foo2498=== PAUSE TestGlobMatch/foo_foo2499=== RUN TestGlobMatch/foo_bar2500=== PAUSE TestGlobMatch/foo_bar2501=== RUN TestGlobMatch/*_2502=== PAUSE TestGlobMatch/*_2503=== RUN TestGlobMatch/*_anything2504=== PAUSE TestGlobMatch/*_anything2505=== RUN TestGlobMatch/foo*_foo2506=== PAUSE TestGlobMatch/foo*_foo2507=== RUN TestGlobMatch/foo*_foobar2508=== PAUSE TestGlobMatch/foo*_foobar2509=== RUN TestGlobMatch/foo*_bar2510=== PAUSE TestGlobMatch/foo*_bar2511=== RUN TestGlobMatch/*bar_bar2512=== PAUSE TestGlobMatch/*bar_bar2513=== RUN TestGlobMatch/*bar_foobar2514=== PAUSE TestGlobMatch/*bar_foobar2515=== RUN TestGlobMatch/*bar_foo2516=== PAUSE TestGlobMatch/*bar_foo2517=== RUN TestGlobMatch/foo*bar_foobar2518=== PAUSE TestGlobMatch/foo*bar_foobar2519=== RUN TestGlobMatch/foo*bar_foo123bar2520=== PAUSE TestGlobMatch/foo*bar_foo123bar2521=== RUN TestGlobMatch/foo*bar_foobarbaz2522=== PAUSE TestGlobMatch/foo*bar_foobarbaz2523=== RUN TestGlobMatch/*/*_foo/bar2524=== PAUSE TestGlobMatch/*/*_foo/bar2525=== RUN TestGlobMatch/*/*_foo2526=== PAUSE TestGlobMatch/*/*_foo2527=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2528=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2529=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02530=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02531=== RUN TestGlobMatch/refs/*/main_refs/heads/main2532=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2533=== RUN TestGlobMatch/fo?_foo2534=== PAUSE TestGlobMatch/fo?_foo2535=== RUN TestGlobMatch/fo?_fo2536=== PAUSE TestGlobMatch/fo?_fo2537=== RUN TestGlobMatch/fo?_fooo2538=== PAUSE TestGlobMatch/fo?_fooo2539=== RUN TestGlobMatch/?oo_foo2540=== PAUSE TestGlobMatch/?oo_foo2541=== RUN TestGlobMatch/?oo_boo2542=== PAUSE TestGlobMatch/?oo_boo2543--- PASS: TestPins_ConfigValidation (0.00s)2544=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2545=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2546=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2547=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2548=== CONT TestGlobMatch/*_anything2549=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2550=== CONT TestGlobMatch/fo?_foo2551=== CONT TestGlobMatch/fo?_fo2552=== CONT TestGlobMatch/*/*_foo/bar2553=== CONT TestGlobMatch/?oo_boo2554=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2555=== CONT TestGlobMatch/refs/*/main_refs/heads/main2556=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02557=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2558=== CONT TestGlobMatch/fo?_fooo2559=== CONT TestGlobMatch/*/*_foo2560=== CONT TestGlobMatch/*bar_foo2561=== CONT TestGlobMatch/*bar_bar2562=== CONT TestGlobMatch/foo_bar2563=== CONT TestGlobMatch/*_2564=== CONT TestGlobMatch/foo_foo2565=== CONT TestGlobMatch/?oo_foo2566=== CONT TestGlobMatch/foo*bar_foobar2567=== CONT TestGlobMatch/foo*_foobar2568=== CONT TestGlobMatch/foo*_bar2569=== CONT TestGlobMatch/foo*bar_foobarbaz2570=== CONT TestGlobMatch/*bar_foobar2571=== CONT TestGlobMatch/foo*_foo2572=== CONT TestGlobMatch/foo*bar_foo123bar2573--- PASS: TestGlobMatch (0.01s)2574 --- PASS: TestGlobMatch/*_anything (0.00s)2575 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2576 --- PASS: TestGlobMatch/fo?_foo (0.00s)2577 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2578 --- PASS: TestGlobMatch/?oo_boo (0.00s)2579 --- PASS: TestGlobMatch/fo?_fo (0.00s)2580 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2581 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2582 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2583 --- PASS: TestGlobMatch/*bar_bar (0.00s)2584 --- PASS: TestGlobMatch/*bar_foo (0.00s)2585 --- PASS: TestGlobMatch/foo_bar (0.00s)2586 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2587 --- PASS: TestGlobMatch/*_ (0.00s)2588 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2589 --- PASS: TestGlobMatch/?oo_foo (0.00s)2590 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2591 --- PASS: TestGlobMatch/foo*_bar (0.00s)2592 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2593 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2594 --- PASS: TestGlobMatch/*/*_foo (0.00s)2595 --- PASS: TestGlobMatch/foo_foo (0.00s)2596 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2597 --- PASS: TestGlobMatch/foo*_foo (0.00s)2598 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)25992026/10/27 08:50:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43093/oidc26002026/10/27 08:50:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36781/oidc2601--- PASS: TestValidateToken_Expired (0.05s)26022026/10/27 08:50:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41567/oidc26032026/10/27 08:50:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42631/oidc2604--- PASS: TestScopes_Rules (0.06s)2605--- PASS: TestValidateToken_WrongAudience (0.06s)2606--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.06s)26072026/10/27 08:50:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36485/oidc2608--- PASS: TestValidateToken_ValidToken (0.07s)26092026/10/27 08:50:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37597/oidc26102026/10/27 08:50:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35297/oidc2611--- PASS: TestValidateToken_BoundSubjectMismatch (0.08s)2612--- PASS: TestPins_ReservedForMatchingRule (0.09s)26132026/10/27 08:50:04 http: TLS handshake error from 127.0.0.1:46082: remote error: tls: bad certificate26142026/10/27 08:50:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45997/oidc2615--- PASS: TestNewValidator_KubernetesRequiresCA (0.10s)2616--- PASS: TestPins_TopLevelShorthand (0.10s)26172026/10/27 08:50:04 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232618--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.18s)26192026/10/27 08:50:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40643/oidc2620--- PASS: TestValidateToken_BoundClaimsMismatch (0.23s)26212026/10/27 08:50:04 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:36377/oidc26222026/10/27 08:50:04 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:39189/oidc2623--- PASS: TestValidateToken_MultipleProviders (0.26s)26242026/10/27 08:50:04 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:359852625--- PASS: TestValidateToken_KubernetesServiceAccount (0.31s)2626--- PASS: TestHTTPClientForHasTimeouts (0.41s)26272026/10/27 08:50:04 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:35999/oidc2628--- PASS: TestValidateToken_NoMatchingProvider (0.46s)2629PASS2630Running hook tests...2631=== RUN TestSendPathsEmpty2632=== PAUSE TestSendPathsEmpty2633=== RUN TestQueueEnqueueAndFetch2634=== PAUSE TestQueueEnqueueAndFetch2635=== RUN TestQueueDeduplication2636=== PAUSE TestQueueDeduplication2637=== RUN TestQueueRemove2638=== PAUSE TestQueueRemove2639=== RUN TestQueueFetchBatchLimit2640=== PAUSE TestQueueFetchBatchLimit2641=== RUN TestQueueRetryMovesToBack2642=== PAUSE TestQueueRetryMovesToBack2643=== RUN TestQueueFetchRemoveLifecycle2644=== PAUSE TestQueueFetchRemoveLifecycle2645=== RUN TestQueueConcurrentWriters2646=== PAUSE TestQueueConcurrentWriters2647=== RUN TestQueueEnqueueWaitsOutSlowWriter2648=== PAUSE TestQueueEnqueueWaitsOutSlowWriter2649=== RUN TestQueueRemoveLargeClosure2650=== PAUSE TestQueueRemoveLargeClosure2651=== RUN TestServerClientIntegration2652--- PASS: TestServerClientIntegration (0.00s)2653=== RUN TestServerQueueError26542026/10/27 08:50:05 ERROR Failed to queue paths error="permission denied" count=12655--- PASS: TestServerQueueError (0.00s)2656=== RUN TestServerRefusesOversizedAndNonStoreRequests2657=== PAUSE TestServerRefusesOversizedAndNonStoreRequests2658=== RUN TestGetListenerSocketActivation2659 server_test.go:309: === RUN TestGetListenerSocketActivation2660 --- PASS: TestGetListenerSocketActivation (0.00s)2661 PASS2662 2663--- PASS: TestGetListenerSocketActivation (1.02s)2664=== RUN TestServerStalledClientDoesNotBlockShutdown2665=== PAUSE TestServerStalledClientDoesNotBlockShutdown2666=== RUN TestServerBacksOffOnAcceptErrors2667=== PAUSE TestServerBacksOffOnAcceptErrors2668=== RUN TestDrainIsolatesPoisonPath2669=== PAUSE TestDrainIsolatesPoisonPath2670=== RUN TestRunNotBlockedByPoisonHead2671=== PAUSE TestRunNotBlockedByPoisonHead2672=== RUN TestDrainGivesUpWhenServerDown2673=== PAUSE TestDrainGivesUpWhenServerDown2674=== RUN TestFailedPathPrunedByLaterClosure2675=== PAUSE TestFailedPathPrunedByLaterClosure2676=== RUN TestWorkerUploadsAndRemoves2677=== PAUSE TestWorkerUploadsAndRemoves2678=== RUN TestWorkerSkipsGCdPaths2679=== PAUSE TestWorkerSkipsGCdPaths2680=== RUN TestWorkerPrunesClosureDeps2681=== PAUSE TestWorkerPrunesClosureDeps2682=== RUN TestWorkerRemovesCachedPathBatchedWithLargerClosure2683=== PAUSE TestWorkerRemovesCachedPathBatchedWithLargerClosure2684=== RUN TestDrainTimeout2685=== PAUSE TestDrainTimeout2686=== RUN TestDrainTimeoutDuringIsolation2687=== PAUSE TestDrainTimeoutDuringIsolation2688=== RUN TestShutdownFinishesInFlightPush2689=== PAUSE TestShutdownFinishesInFlightPush2690=== RUN TestWorkerRemoveFailureIsNotProgress2691=== PAUSE TestWorkerRemoveFailureIsNotProgress2692=== RUN TestWorkerKeepsPathItCannotStat2693=== PAUSE TestWorkerKeepsPathItCannotStat2694=== CONT TestQueueEnqueueAndFetch2695=== CONT TestWorkerKeepsPathItCannotStat2696=== CONT TestDrainTimeoutDuringIsolation2697=== RUN TestDrainTimeoutDuringIsolation/probe_cut_short2698=== CONT TestShutdownFinishesInFlightPush2699=== CONT TestDrainGivesUpWhenServerDown2700=== CONT TestWorkerRemoveFailureIsNotProgress2701=== RUN TestWorkerRemoveFailureIsNotProgress/collected_path2702=== CONT TestWorkerUploadsAndRemoves2703=== CONT TestFailedPathPrunedByLaterClosure2704=== PAUSE TestWorkerRemoveFailureIsNotProgress/collected_path2705=== RUN TestWorkerRemoveFailureIsNotProgress/pushed_batch2706=== CONT TestWorkerRemovesCachedPathBatchedWithLargerClosure2707=== CONT TestQueueEnqueueWaitsOutSlowWriter2708=== CONT TestDrainTimeout2709=== CONT TestWorkerSkipsGCdPaths2710=== CONT TestQueueFetchBatchLimit2711=== CONT TestQueueRemoveLargeClosure2712=== CONT TestQueueFetchRemoveLifecycle2713=== CONT TestServerRefusesOversizedAndNonStoreRequests2714=== CONT TestQueueRetryMovesToBack2715=== CONT TestQueueConcurrentWriters2716=== CONT TestQueueDeduplication2717=== CONT TestRunNotBlockedByPoisonHead2718=== CONT TestWorkerPrunesClosureDeps2719=== CONT TestQueueRemove2720=== CONT TestSendPathsEmpty27212026/10/27 08:50:06 ERROR Refusing path outside the store path=/etc/shadow store=/nix/store2722=== CONT TestServerBacksOffOnAcceptErrors2723=== CONT TestServerStalledClientDoesNotBlockShutdown2724=== RUN TestShutdownFinishesInFlightPush/completes2725--- PASS: TestSendPathsEmpty (0.00s)2726=== PAUSE TestDrainTimeoutDuringIsolation/probe_cut_short2727=== PAUSE TestWorkerRemoveFailureIsNotProgress/pushed_batch2728=== PAUSE TestShutdownFinishesInFlightPush/completes2729=== RUN TestWorkerRemoveFailureIsNotProgress/isolated_paths2730=== RUN TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2731=== PAUSE TestWorkerRemoveFailureIsNotProgress/isolated_paths2732=== PAUSE TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2733=== RUN TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2734=== CONT TestWorkerRemoveFailureIsNotProgress/collected_path27352026/10/27 08:50:06 ERROR Refusing path outside the store path=/nix/store store=/nix/store2736=== CONT TestDrainIsolatesPoisonPath2737=== PAUSE TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2738=== CONT TestWorkerRemoveFailureIsNotProgress/isolated_paths27392026/10/27 08:50:06 ERROR Refusing path outside the store path=/nix/store/ store=/nix/store27402026/10/27 08:50:06 ERROR Accept failed error="too many open files"27412026/10/27 08:50:06 ERROR Refusing path outside the store path=/nix/store/../../etc/shadow store=/nix/store27422026/10/27 08:50:06 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello/bin/sh store=/nix/store27432026/10/27 08:50:06 ERROR Refusing path outside the store path=nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store27442026/10/27 08:50:06 ERROR Refusing path outside the store path=/nix/storeX/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store27452026/10/27 08:50:06 ERROR Refusing path outside the store path=/nix/store/.links store=/nix/store27462026/10/27 08:50:06 ERROR Refusing path outside the store path=/nix/store/aaa-hello store=/nix/store27472026/10/27 08:50:06 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz store=/nix/store27482026/10/27 08:50:06 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz- store=/nix/store27492026/10/27 08:50:06 ERROR Refusing path outside the store path=/nix/store/0123456789ebcdfghijklmnpqrsvwxyz-hello store=/nix/store27502026/10/27 08:50:06 ERROR Refusing path outside the store path="/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel\x00lo" store=/nix/store27512026/10/27 08:50:06 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel/lo store=/nix/store27522026/10/27 08:50:06 ERROR Accept failed error="too many open files"27532026/10/27 08:50:06 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx store=/nix/store27542026/10/27 08:50:06 ERROR Failed to decode request error="unexpected EOF"2755--- PASS: TestServerRefusesOversizedAndNonStoreRequests (0.01s)2756=== CONT TestWorkerRemoveFailureIsNotProgress/pushed_batch27572026/10/27 08:50:06 ERROR Accept failed error="too many open files"27582026/10/27 08:50:06 ERROR Accept failed error="too many open files"27592026/10/27 08:50:06 INFO Uploading batch count=127602026/10/27 08:50:06 INFO Upload queue status pending=327612026/10/27 08:50:06 ERROR Upload failed error="upload failed" count=127622026/10/27 08:50:06 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat3713436890/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat3713436890/002/locked/aaa: permission denied"27632026/10/27 08:50:06 INFO Upload queue status pending=227642026/10/27 08:50:06 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths1054143770/002/nonexistent27652026/10/27 08:50:06 INFO Upload queue status pending=227662026/10/27 08:50:06 INFO Upload queue status pending=227672026/10/27 08:50:06 INFO Uploading batch count=227682026/10/27 08:50:06 INFO Upload queue status pending=327692026/10/27 08:50:06 INFO Uploading batch count=227702026/10/27 08:50:06 INFO Uploading batch count=227712026/10/27 08:50:06 INFO Uploading batch count=127722026/10/27 08:50:06 INFO Uploading batch count=127732026/10/27 08:50:06 INFO Uploading batch count=127742026/10/27 08:50:06 INFO Uploading batch count=227752026/10/27 08:50:06 ERROR Upload failed error="upload failed" count=127762026/10/27 08:50:06 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat3713436890/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat3713436890/002/locked/aaa: permission denied"27772026/10/27 08:50:06 INFO Uploading batch count=427782026/10/27 08:50:06 ERROR Upload failed error="upload failed" count=42779--- PASS: TestQueueFetchBatchLimit (0.06s)2780=== CONT TestDrainTimeoutDuringIsolation/probe_cut_short2781--- PASS: TestQueueEnqueueAndFetch (0.06s)2782=== CONT TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline27832026/10/27 08:50:06 INFO Uploading batch count=127842026/10/27 08:50:06 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat3713436890/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat3713436890/002/locked/aaa: permission denied"27852026/10/27 08:50:06 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath947972779/002/bbb2786--- PASS: TestQueueDeduplication (0.06s)2787=== CONT TestShutdownFinishesInFlightPush/completes27882026/10/27 08:50:06 INFO Uploading batch count=227892026/10/27 08:50:06 ERROR Upload failed error="upload failed" count=227902026/10/27 08:50:06 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown787477774/002/a2791=== CONT TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2792--- PASS: TestQueueRemove (0.06s)27932026/10/27 08:50:06 ERROR Drain finished with paths left in queue remaining=12794--- PASS: TestQueueFetchRemoveLifecycle (0.06s)27952026/10/27 08:50:06 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown787477774/002/b2796--- PASS: TestQueueRetryMovesToBack (0.06s)27972026/10/27 08:50:06 INFO Uploading batch count=227982026/10/27 08:50:06 ERROR Upload failed error="upload failed" count=227992026/10/27 08:50:06 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown787477774/002/c28002026/10/27 08:50:06 INFO Uploading batch count=128012026/10/27 08:50:06 ERROR Upload failed error="upload failed" count=128022026/10/27 08:50:06 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown787477774/002/d2803--- PASS: TestFailedPathPrunedByLaterClosure (0.07s)2804--- PASS: TestWorkerKeepsPathItCannotStat (0.07s)28052026/10/27 08:50:06 INFO Uploading batch count=128062026/10/27 08:50:06 ERROR Upload failed error="upload failed" count=128072026/10/27 08:50:06 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path385266212/001/nonexistent28082026/10/27 08:50:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128092026/10/27 08:50:06 INFO Uploading batch count=228102026/10/27 08:50:06 ERROR Upload failed error="upload failed" count=228112026/10/27 08:50:06 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown787477774/002/e28122026/10/27 08:50:06 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path385266212/001/nonexistent28132026/10/27 08:50:06 INFO Uploading batch count=128142026/10/27 08:50:06 ERROR Upload failed error="upload failed" count=128152026/10/27 08:50:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128162026/10/27 08:50:06 INFO Uploading batch count=228172026/10/27 08:50:06 ERROR Upload failed error="upload failed" count=228182026/10/27 08:50:06 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown787477774/002/f28192026/10/27 08:50:06 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path385266212/001/nonexistent28202026/10/27 08:50:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128212026/10/27 08:50:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128222026/10/27 08:50:06 ERROR Drain finished with paths left in queue remaining=128232026/10/27 08:50:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128242026/10/27 08:50:06 ERROR Drain finished with paths left in queue remaining=128252026/10/27 08:50:06 INFO Uploading batch count=22826--- PASS: TestWorkerSkipsGCdPaths (0.08s)28272026/10/27 08:50:06 INFO Uploading batch count=228282026/10/27 08:50:06 ERROR Upload failed error="upload failed" count=228292026/10/27 08:50:06 ERROR Accept failed error="too many open files"2830--- PASS: TestWorkerRemovesCachedPathBatchedWithLargerClosure (0.08s)28312026/10/27 08:50:06 ERROR Drain finished with paths left in queue remaining=102832--- PASS: TestWorkerUploadsAndRemoves (0.08s)28332026/10/27 08:50:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128342026/10/27 08:50:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128352026/10/27 08:50:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=228362026/10/27 08:50:06 INFO Uploading batch count=228372026/10/27 08:50:06 ERROR Upload failed error="upload failed" count=22838--- PASS: TestWorkerPrunesClosureDeps (0.08s)28392026/10/27 08:50:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128402026/10/27 08:50:06 INFO Uploading batch count=228412026/10/27 08:50:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12842--- PASS: TestDrainIsolatesPoisonPath (0.08s)28432026/10/27 08:50:06 ERROR Drain finished with paths left in queue remaining=228442026/10/27 08:50:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=228452026/10/27 08:50:06 INFO Uploading batch count=428462026/10/27 08:50:06 INFO Upload queue status pending=228472026/10/27 08:50:06 ERROR Upload failed error="upload failed" count=428482026/10/27 08:50:06 INFO Uploading batch count=428492026/10/27 08:50:06 ERROR Upload failed error="upload failed" count=42850--- PASS: TestDrainGivesUpWhenServerDown (0.09s)28512026/10/27 08:50:06 INFO Uploading batch count=228522026/10/27 08:50:06 INFO Uploading batch count=228532026/10/27 08:50:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=228542026/10/27 08:50:06 ERROR Drain finished with paths left in queue remaining=228552026/10/27 08:50:06 INFO Upload queue status pending=228562026/10/27 08:50:06 INFO Uploading batch count=22857--- PASS: TestWorkerRemoveFailureIsNotProgress (0.00s)2858 --- PASS: TestWorkerRemoveFailureIsNotProgress/collected_path (0.08s)2859 --- PASS: TestWorkerRemoveFailureIsNotProgress/isolated_paths (0.08s)2860 --- PASS: TestWorkerRemoveFailureIsNotProgress/pushed_batch (0.08s)28612026/10/27 08:50:07 ERROR Accept failed error="too many open files"28622026/10/27 08:50:07 ERROR Failed to decode request error="read unix /build/hook4238256469/test.sock->@: i/o timeout"28632026/10/27 08:50:07 ERROR Failed to write response error="write unix /build/hook4238256469/test.sock->@: i/o timeout"2864--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)28652026/10/27 08:50:07 ERROR Upload failed error="context canceled" count=228662026/10/27 08:50:07 ERROR Drain finished with paths left in queue remaining=42867--- PASS: TestDrainTimeout (0.26s)28682026/10/27 08:50:07 ERROR Drain finished with paths left in queue remaining=428692026/10/27 08:50:07 ERROR Upload failed error="context canceled" count=228702026/10/27 08:50:07 ERROR Drain finished with paths left in queue remaining=22871--- PASS: TestShutdownFinishesInFlightPush (0.00s)2872 --- PASS: TestShutdownFinishesInFlightPush/completes (0.13s)2873 --- PASS: TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout (0.23s)28742026/10/27 08:50:07 ERROR Accept failed error="too many open files"28752026/10/27 08:50:07 ERROR Drain finished with paths left in queue remaining=32876--- PASS: TestDrainTimeoutDuringIsolation (0.00s)2877 --- PASS: TestDrainTimeoutDuringIsolation/probe_cut_short (0.23s)2878 --- PASS: TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline (0.33s)2879--- PASS: TestQueueConcurrentWriters (0.43s)28802026/10/27 08:50:07 ERROR Accept failed error="too many open files"2881--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)28822026/10/27 08:50:07 INFO Uploading batch count=128832026/10/27 08:50:07 INFO Uploading batch count=128842026/10/27 08:50:07 INFO Uploading batch count=128852026/10/27 08:50:07 ERROR Upload failed error="upload failed" count=128862026/10/27 08:50:07 INFO Uploading batch count=128872026/10/27 08:50:07 ERROR Upload failed error="upload failed" count=128882026/10/27 08:50:07 INFO Uploading batch count=128892026/10/27 08:50:07 ERROR Upload failed error="upload failed" count=128902026/10/27 08:50:07 INFO Uploading batch count=128912026/10/27 08:50:07 ERROR Upload failed error="upload failed" count=128922026/10/27 08:50:07 ERROR Drain finished with paths left in queue remaining=12893--- PASS: TestRunNotBlockedByPoisonHead (1.09s)2894--- PASS: TestQueueRemoveLargeClosure (1.51s)2895--- PASS: TestQueueEnqueueWaitsOutSlowWriter (6.05s)2896PASS2897Running signing tests...2898=== RUN TestExternalSigner2899=== PAUSE TestExternalSigner2900=== RUN TestExternalSignerWrongPublicKey2901=== PAUSE TestExternalSignerWrongPublicKey2902=== RUN TestExternalSignerErrors2903=== PAUSE TestExternalSignerErrors2904=== RUN TestExternalSignerRestartsAfterCrash2905=== PAUSE TestExternalSignerRestartsAfterCrash2906=== RUN TestExternalSignerProgramErrorKeepsProcess2907=== PAUSE TestExternalSignerProgramErrorKeepsProcess2908=== RUN TestExternalSignerClose2909=== PAUSE TestExternalSignerClose2910=== RUN TestExternalSignerRejectsInvalidPublicKey2911=== PAUSE TestExternalSignerRejectsInvalidPublicKey2912=== RUN TestExternalSignerCancellation2913=== PAUSE TestExternalSignerCancellation2914=== RUN TestGenerateFingerprint2915=== PAUSE TestGenerateFingerprint2916=== RUN TestParseSigningKey2917=== PAUSE TestParseSigningKey2918=== RUN TestSign2919=== PAUSE TestSign2920=== RUN TestSignBatch2921=== PAUSE TestSignBatch2922=== RUN TestNilKeyPublicKey2923=== PAUSE TestNilKeyPublicKey2924=== RUN TestSignErrors2925=== PAUSE TestSignErrors2926=== CONT TestExternalSigner2927=== CONT TestExternalSignerCancellation2928=== CONT TestExternalSignerClose2929=== CONT TestSignErrors2930=== CONT TestNilKeyPublicKey2931=== CONT TestSignBatch2932=== CONT TestSign2933=== CONT TestParseSigningKey2934=== CONT TestGenerateFingerprint2935=== RUN TestParseSigningKey/valid_32-byte_key2936=== RUN TestGenerateFingerprint/basic_with_references2937=== CONT TestExternalSignerWrongPublicKey2938=== PAUSE TestParseSigningKey/valid_32-byte_key2939=== PAUSE TestGenerateFingerprint/basic_with_references2940=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2941=== RUN TestGenerateFingerprint/no_references2942=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2943=== RUN TestParseSigningKey/no_colon2944=== PAUSE TestGenerateFingerprint/no_references2945=== PAUSE TestParseSigningKey/no_colon2946=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2947=== RUN TestParseSigningKey/empty_name2948=== CONT TestExternalSignerErrors2949=== CONT TestExternalSignerProgramErrorKeepsProcess2950=== CONT TestExternalSignerRejectsInvalidPublicKey2951--- PASS: TestNilKeyPublicKey (0.00s)2952=== PAUSE TestParseSigningKey/empty_name2953=== CONT TestExternalSignerRestartsAfterCrash2954=== RUN TestExternalSignerErrors/wrong_shape2955=== RUN TestParseSigningKey/invalid_base642956=== PAUSE TestParseSigningKey/invalid_base642957=== RUN TestExternalSignerRejectsInvalidPublicKey/#002958=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2959=== RUN TestParseSigningKey/wrong_length2960=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2961=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002962=== PAUSE TestExternalSignerErrors/wrong_shape2963=== PAUSE TestParseSigningKey/wrong_length2964=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2965=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2966=== CONT TestParseSigningKey/valid_32-byte_key2967=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2968=== RUN TestGenerateFingerprint/invalid_nar_hash_length2969=== CONT TestParseSigningKey/wrong_length2970=== RUN TestExternalSignerErrors/null2971=== CONT TestParseSigningKey/invalid_base642972=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2973=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2974=== RUN TestGenerateFingerprint/invalid_store_path_prefix2975=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2976=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2977=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2978=== RUN TestGenerateFingerprint/invalid_reference_prefix2979=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2980=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2981=== PAUSE TestExternalSignerErrors/null2982=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2983=== CONT TestGenerateFingerprint/no_references2984=== CONT TestGenerateFingerprint/invalid_store_path_prefix2985=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2986=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2987=== CONT TestGenerateFingerprint/invalid_nar_hash_length2988=== CONT TestGenerateFingerprint/invalid_reference_prefix2989=== CONT TestGenerateFingerprint/basic_with_references2990=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2991=== CONT TestParseSigningKey/empty_name2992=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2993=== RUN TestExternalSignerErrors/wrong_signatures_shape2994=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2995=== CONT TestParseSigningKey/no_colon2996=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2997=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2998=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2999=== RUN TestExternalSignerErrors/exit_at_startup3000=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!3001=== CONT TestExternalSignerRejectsInvalidPublicKey/#003002=== RUN TestSignErrors/nil_key3003=== PAUSE TestExternalSignerErrors/exit_at_startup3004--- PASS: TestGenerateFingerprint (0.00s)3005 --- PASS: TestGenerateFingerprint/no_references (0.00s)3006 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)3007 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)3008 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)3009 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)3010 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)3011 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)3012=== PAUSE TestSignErrors/nil_key3013=== RUN TestSignErrors/nil_narinfo3014=== RUN TestExternalSignerErrors/invalid_JSON3015=== PAUSE TestSignErrors/nil_narinfo3016=== PAUSE TestExternalSignerErrors/invalid_JSON3017=== RUN TestSignErrors/invalid_narinfo3018=== PAUSE TestSignErrors/invalid_narinfo3019=== RUN TestExternalSignerErrors/missing_signatures3020=== RUN TestSignErrors/canceled3021--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)3022 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)3023 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)3024 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)3025 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)3026 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)3027=== PAUSE TestSignErrors/canceled3028=== PAUSE TestExternalSignerErrors/missing_signatures3029=== CONT TestSignErrors/nil_key3030=== CONT TestSignErrors/invalid_narinfo3031=== CONT TestSignErrors/canceled3032=== CONT TestSignErrors/nil_narinfo3033--- PASS: TestParseSigningKey (0.00s)3034 --- PASS: TestParseSigningKey/wrong_length (0.00s)3035 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)3036 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)3037 --- PASS: TestParseSigningKey/no_colon (0.00s)3038 --- PASS: TestParseSigningKey/empty_name (0.00s)3039 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)3040=== RUN TestExternalSignerErrors/null_signatures3041--- PASS: TestSign (0.01s)3042=== PAUSE TestExternalSignerErrors/null_signatures3043--- PASS: TestSignErrors (0.00s)3044 --- PASS: TestSignErrors/nil_key (0.00s)3045 --- PASS: TestSignErrors/canceled (0.00s)3046 --- PASS: TestSignErrors/invalid_narinfo (0.00s)3047 --- PASS: TestSignErrors/nil_narinfo (0.00s)3048=== RUN TestExternalSignerErrors/unrequested_key3049=== PAUSE TestExternalSignerErrors/unrequested_key3050=== RUN TestExternalSignerErrors/exit_on_request3051=== PAUSE TestExternalSignerErrors/exit_on_request3052=== RUN TestExternalSignerErrors/wrong_id3053=== PAUSE TestExternalSignerErrors/wrong_id3054=== RUN TestExternalSignerErrors/invalid_signature_base643055=== PAUSE TestExternalSignerErrors/invalid_signature_base643056=== RUN TestExternalSignerErrors/wrong_signature_length3057=== PAUSE TestExternalSignerErrors/wrong_signature_length3058=== RUN TestExternalSignerErrors/too_few_signatures3059=== PAUSE TestExternalSignerErrors/too_few_signatures3060--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.01s)3061=== RUN TestExternalSignerErrors/missing_signature_name3062=== PAUSE TestExternalSignerErrors/missing_signature_name3063=== RUN TestExternalSignerErrors/wrong_signature_name3064=== PAUSE TestExternalSignerErrors/wrong_signature_name3065=== RUN TestExternalSignerErrors/program_error3066=== PAUSE TestExternalSignerErrors/program_error3067=== CONT TestExternalSignerErrors/null3068=== CONT TestExternalSignerErrors/exit_at_startup3069=== CONT TestExternalSignerErrors/missing_signatures3070=== CONT TestExternalSignerErrors/unrequested_key3071=== CONT TestExternalSignerErrors/wrong_signature_length3072=== CONT TestExternalSignerErrors/program_error3073=== CONT TestExternalSignerErrors/missing_signature_name3074=== CONT TestExternalSignerErrors/invalid_signature_base643075=== CONT TestExternalSignerErrors/wrong_id3076=== CONT TestExternalSignerErrors/too_few_signatures3077=== CONT TestExternalSignerErrors/wrong_signature_name3078=== CONT TestExternalSignerErrors/wrong_signatures_shape3079=== CONT TestExternalSignerErrors/null_signatures3080=== CONT TestExternalSignerErrors/invalid_JSON3081=== CONT TestExternalSignerErrors/exit_on_request3082=== CONT TestExternalSignerErrors/wrong_shape3083--- PASS: TestExternalSignerWrongPublicKey (0.01s)3084--- PASS: TestExternalSignerClose (0.01s)3085--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)3086--- PASS: TestSignBatch (0.01s)3087--- PASS: TestExternalSigner (0.02s)3088--- PASS: TestExternalSignerErrors (0.01s)3089 --- PASS: TestExternalSignerErrors/null (0.00s)3090 --- PASS: TestExternalSignerErrors/exit_at_startup (0.00s)3091 --- PASS: TestExternalSignerErrors/missing_signatures (0.00s)3092 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.00s)3093 --- PASS: TestExternalSignerErrors/wrong_id (0.00s)3094 --- PASS: TestExternalSignerErrors/unrequested_key (0.01s)3095 --- PASS: TestExternalSignerErrors/too_few_signatures (0.00s)3096 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)3097 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)3098 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)3099 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)3100 --- PASS: TestExternalSignerErrors/program_error (0.01s)3101 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)3102 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)3103 --- PASS: TestExternalSignerErrors/exit_on_request (0.01s)3104 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)3105--- PASS: TestExternalSignerCancellation (0.02s)3106PASS3107Running OpenBao signer tests...3108=== RUN TestSign3109=== PAUSE TestSign3110=== RUN TestSignErrors3111=== PAUSE TestSignErrors3112=== RUN TestServe3113=== PAUSE TestServe3114=== RUN TestServeRejectsGarbage3115=== PAUSE TestServeRejectsGarbage3116=== CONT TestSignErrors3117=== CONT TestServe3118=== RUN TestSignErrors/invalid_json3119=== CONT TestServeRejectsGarbage3120=== PAUSE TestSignErrors/invalid_json3121=== CONT TestSign3122=== RUN TestSignErrors/no_prefix3123=== PAUSE TestSignErrors/no_prefix3124=== RUN TestSignErrors/invalid_base643125=== PAUSE TestSignErrors/invalid_base643126=== RUN TestSignErrors/http_error3127=== PAUSE TestSignErrors/http_error3128=== CONT TestSignErrors/invalid_json3129--- PASS: TestServeRejectsGarbage (0.00s)3130=== CONT TestSignErrors/invalid_base643131=== CONT TestSignErrors/no_prefix3132=== CONT TestSignErrors/http_error3133--- PASS: TestServe (0.00s)3134--- PASS: TestSign (0.01s)3135--- PASS: TestSignErrors (0.00s)3136 --- PASS: TestSignErrors/invalid_base64 (0.01s)3137 --- PASS: TestSignErrors/http_error (0.01s)3138 --- PASS: TestSignErrors/invalid_json (0.01s)3139 --- PASS: TestSignErrors/no_prefix (0.01s)3140PASS3141Running niks3-hook command tests...3142=== RUN TestServeSecondSignalEndsDrain3143=== PAUSE TestServeSecondSignalEndsDrain3144=== RUN TestServeThenDrainPushesSendAcceptedBeforeShutdown3145=== PAUSE TestServeThenDrainPushesSendAcceptedBeforeShutdown3146=== CONT TestServeThenDrainPushesSendAcceptedBeforeShutdown3147=== CONT TestServeSecondSignalEndsDrain3148--- PASS: TestServeSecondSignalEndsDrain (0.07s)31492026/10/27 08:50:16 INFO Upload queue status pending=131502026/10/27 08:50:16 INFO Uploading batch count=13151--- PASS: TestServeThenDrainPushesSendAcceptedBeforeShutdown (0.13s)3152PASS3153Running rate limiter tests...3154=== RUN TestAdaptiveRateLimiter_ThreadSafety3155=== PAUSE TestAdaptiveRateLimiter_ThreadSafety3156=== CONT TestAdaptiveRateLimiter_ThreadSafety31572026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=7031582026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=4931592026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=34.331602026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=24.00999999999999831612026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=16.80731622026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=11.76489999999999931632026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=8.2354331642026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=5.76480099999999931652026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531662026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531672026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531682026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531692026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531702026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531712026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531722026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531732026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531742026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531752026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531762026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531772026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531782026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531792026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=5.63678500000000131802026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531812026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531822026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531832026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531842026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531852026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531862026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531872026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531882026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531892026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531902026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531912026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531922026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=8.25281691850000431932026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=5.77697184295000331942026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531952026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531962026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531972026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531982026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=531992026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532002026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532012026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532022026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532032026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532042026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532052026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532062026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532072026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532082026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532092026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532102026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532112026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532122026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532132026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=5.12435000000000132142026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532152026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532162026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532172026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=5.63678500000000132182026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532192026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532202026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532212026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532222026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532232026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532242026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532252026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532262026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532272026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532282026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532292026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532302026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532312026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532322026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532332026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532342026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532352026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532362026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532372026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532382026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532392026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532402026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532412026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532422026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532432026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532442026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532452026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532462026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532472026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532482026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532492026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532502026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532512026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532522026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532532026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=7.50256083500000332542026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=5.25179258450000232552026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=532562026/10/27 08:50:17 WARN Rate limiter backed off name=test rate=53257--- PASS: TestAdaptiveRateLimiter_ThreadSafety (0.09s)3258PASS