niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #429
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestUploadMultipart_FailedPartBufferNotReused20=== PAUSE TestUploadMultipart_FailedPartBufferNotReused21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestUploadMultipart_SupersededByPeer24=== PAUSE TestUploadMultipart_SupersededByPeer25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (0.03s)27=== RUN TestDumpPathCaseHackCollision28--- PASS: TestDumpPathCaseHackCollision (0.00s)29=== RUN TestSupersededNARStillUploadsListing30=== PAUSE TestSupersededNARStillUploadsListing31=== RUN TestDumpPathMatchesNix32=== PAUSE TestDumpPathMatchesNix33=== RUN TestDumpPathSingleFile34=== PAUSE TestDumpPathSingleFile35=== RUN TestDumpPathWriterError36=== PAUSE TestDumpPathWriterError37=== RUN TestEncodeNixBase3238=== PAUSE TestEncodeNixBase3239=== RUN TestEncodeNixBase32WithRealHash40=== PAUSE TestEncodeNixBase32WithRealHash41=== RUN TestConvertHashToNix3242=== PAUSE TestConvertHashToNix3243=== RUN TestGetStorePathHash44=== PAUSE TestGetStorePathHash45=== RUN TestPathInfoHashCompatibility46=== PAUSE TestPathInfoHashCompatibility47=== RUN TestParsePathInfoJSON48=== PAUSE TestParsePathInfoJSON49=== RUN TestParsePathInfoJSONMultiplePaths50=== PAUSE TestParsePathInfoJSONMultiplePaths51=== RUN TestPathInfoCACompatibility52=== PAUSE TestPathInfoCACompatibility53=== RUN TestRateLimiterFeedback54=== PAUSE TestRateLimiterFeedback55=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess56=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess57=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer58=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer59=== RUN TestResolveStorePath60=== PAUSE TestResolveStorePath61=== RUN TestDoWithRetry_BodyReplayedViaGetBody62=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody63=== RUN TestRetryTimeoutOutlastsMaxRetries64=== PAUSE TestRetryTimeoutOutlastsMaxRetries65=== RUN TestDoWithRetry_FinalResponseBodyReadable66=== PAUSE TestDoWithRetry_FinalResponseBodyReadable67=== RUN TestShellSplit68=== PAUSE TestShellSplit69=== RUN TestShellSplitErrors70=== PAUSE TestShellSplitErrors71=== RUN TestStreamPushReportsEveryPath72=== PAUSE TestStreamPushReportsEveryPath73=== RUN TestStreamPushBatchesUnderLoad74=== PAUSE TestStreamPushBatchesUnderLoad75=== RUN TestStreamPushIsolatesFailures76=== PAUSE TestStreamPushIsolatesFailures77=== RUN TestStreamPushGivesUpOnDeadServer78=== PAUSE TestStreamPushGivesUpOnDeadServer79=== RUN TestStreamPushRequestLine80=== PAUSE TestStreamPushRequestLine81=== RUN TestStreamPushReportsSignatures82=== PAUSE TestStreamPushReportsSignatures83=== RUN TestStreamPushReportsSkippedPaths84=== PAUSE TestStreamPushReportsSkippedPaths85=== RUN TestClientSignaturesByStorePath86=== PAUSE TestClientSignaturesByStorePath87=== RUN TestStreamPushStopsWhenCanceled88=== PAUSE TestStreamPushStopsWhenCanceled89=== RUN TestSetClientTLS90=== PAUSE TestSetClientTLS91=== RUN TestSetClientTLSDoesNotMutateDefaultTransport92=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport93=== RUN TestSetClientTLSErrors94=== PAUSE TestSetClientTLSErrors95=== RUN TestStaticToken96=== PAUSE TestStaticToken97=== RUN TestFileTokenReadsAndCaches98=== PAUSE TestFileTokenReadsAndCaches99=== RUN TestFileTokenMissing100=== PAUSE TestFileTokenMissing101=== RUN TestFileTokenEmpty102=== PAUSE TestFileTokenEmpty103=== RUN TestScriptTokenNoExpiryRerunsEveryCall104=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall105=== RUN TestScriptTokenCachesUntilRefresh106=== PAUSE TestScriptTokenCachesUntilRefresh107=== RUN TestScriptTokenEmptyToken108=== PAUSE TestScriptTokenEmptyToken109=== RUN TestScriptTokenBadJSON110=== PAUSE TestScriptTokenBadJSON111=== RUN TestScriptTokenScriptFails112=== PAUSE TestScriptTokenScriptFails113=== RUN TestScriptTokenEmptyCommand114=== PAUSE TestScriptTokenEmptyCommand115=== CONT TestDoServerRequestAttachesToken116=== CONT TestDoWithRetry_BodyReplayedViaGetBody117=== CONT TestDumpPathWriterError118=== CONT TestResolveStorePath119=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer120=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess121=== CONT TestRateLimiterFeedback122=== RUN TestRateLimiterFeedback/429_enables_limiter123=== PAUSE TestRateLimiterFeedback/429_enables_limiter1242026/10/25 17:15:27 WARN Rate limiter enabled after throttle name=server-test rate=5125=== RUN TestRateLimiterFeedback/503_enables_limiter126=== PAUSE TestRateLimiterFeedback/503_enables_limiter127=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter128=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter129=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter130=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter131=== CONT TestPathInfoCACompatibility132=== RUN TestPathInfoCACompatibility/null_ca_field133=== CONT TestDumpPathSingleFile134=== PAUSE TestPathInfoCACompatibility/null_ca_field135=== CONT TestParsePathInfoJSON136=== CONT TestPathInfoHashCompatibility137=== CONT TestGetStorePathHash138=== CONT TestSetClientTLS139=== CONT TestConvertHashToNix32140=== CONT TestFileTokenEmpty141=== CONT TestEncodeNixBase32WithRealHash142=== CONT TestFileTokenMissing143=== CONT TestFileTokenReadsAndCaches144=== CONT TestEncodeNixBase32145=== CONT TestStaticToken146=== CONT TestSetClientTLSErrors147=== CONT TestUploadMultipart_PartsInParallel148=== CONT TestSetClientTLSDoesNotMutateDefaultTransport149=== CONT TestScriptTokenNoExpiryRerunsEveryCall150=== RUN TestParsePathInfoJSON/Nix_format151=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)152=== RUN TestConvertHashToNix32/SRI_format_to_Nix32153=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32154=== RUN TestConvertHashToNix32/already_Nix32_format155=== PAUSE TestConvertHashToNix32/already_Nix32_format156=== RUN TestConvertHashToNix32/invalid_format157=== PAUSE TestConvertHashToNix32/invalid_format158=== PAUSE TestParsePathInfoJSON/Nix_format159=== RUN TestParsePathInfoJSON/Lix_format160=== PAUSE TestParsePathInfoJSON/Lix_format161=== RUN TestParsePathInfoJSON/empty_input162=== PAUSE TestParsePathInfoJSON/empty_input163=== RUN TestParsePathInfoJSON/whitespace_only164=== PAUSE TestParsePathInfoJSON/whitespace_only165=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)166=== RUN TestGetStorePathHash/valid_store_path167=== PAUSE TestGetStorePathHash/valid_store_path168=== CONT TestPartSizeForNAR169=== CONT TestScriptTokenEmptyCommand170=== CONT TestDumpPathMatchesNix171=== RUN TestParsePathInfoJSON/invalid_JSON172=== RUN TestPartSizeForNAR/zero_stays_at_minimum173=== CONT TestScriptTokenScriptFails174=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum175--- PASS: TestEncodeNixBase32WithRealHash (0.00s)176--- PASS: TestStaticToken (0.00s)177=== CONT TestUploadMultipart_SupersededByPeer178=== RUN TestEncodeNixBase32/test_string_hash179=== RUN TestPathInfoCACompatibility/old_string_format_-_text180=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon181=== RUN TestGetStorePathHash/basename_without_hyphen_should_error182=== PAUSE TestParsePathInfoJSON/invalid_JSON183=== CONT TestParsePathInfoJSONMultiplePaths184=== CONT TestSupersededNARStillUploadsListing185=== RUN TestSupersededNARStillUploadsListing/small_NAR186=== RUN TestPartSizeForNAR/small_stays_at_minimum187=== CONT TestScriptTokenBadJSON188=== RUN TestSetClientTLS/rejects_connection_without_client_cert189--- PASS: TestScriptTokenEmptyCommand (0.00s)190--- PASS: TestFileTokenEmpty (0.00s)191--- PASS: TestFileTokenMissing (0.00s)192--- PASS: TestResolveStorePath (0.01s)193--- PASS: TestScriptTokenScriptFails (0.05s)194=== CONT TestUploadMultipart_FailedPartBufferNotReused1952026/10/25 17:15:27 WARN Rate limiter enabled after throttle name=server-test rate=5196=== CONT TestScriptTokenCachesUntilRefresh1972026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:36893198--- PASS: TestFileTokenReadsAndCaches (0.08s)199=== CONT TestScriptTokenEmptyToken200--- PASS: TestDumpPathSingleFile (0.08s)201=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun202=== RUN TestSetClientTLSErrors/missing_cert_file203=== PAUSE TestSetClientTLSErrors/missing_cert_file204=== RUN TestSetClientTLSErrors/missing_key_file205=== PAUSE TestSetClientTLSErrors/missing_key_file206=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text207=== RUN TestSetClientTLSErrors/missing_ca_file208=== RUN TestUploadMultipart_SupersededByPeer/exists209=== PAUSE TestUploadMultipart_SupersededByPeer/exists210=== PAUSE TestSetClientTLSErrors/missing_ca_file211=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon212=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI213=== PAUSE TestSupersededNARStillUploadsListing/small_NAR214=== PAUSE TestPartSizeForNAR/small_stays_at_minimum215=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum216=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum217=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert2182026/10/25 17:15:27 WARN Rate limiter backed off name=server-test rate=5219=== CONT TestStreamPushReportsSkippedPaths2202026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:36893221=== CONT TestFilterOversizedClosures222=== RUN TestFilterOversizedClosures/no_limit_keeps_everything223=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything224=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths225=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths226=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths227=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths228=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive229=== RUN TestUploadMultipart_SupersededByPeer/missing230=== CONT TestStreamPushStopsWhenCanceled2312026/10/25 17:15:27 INFO Garbage collection started232=== PAUSE TestUploadMultipart_SupersededByPeer/missing233=== PAUSE TestEncodeNixBase32/test_string_hash234=== RUN TestEncodeNixBase32/empty_input235=== PAUSE TestEncodeNixBase32/empty_input236=== CONT TestCaseHackSuffix237=== CONT TestShellSplitErrors238=== CONT TestStreamPushGivesUpOnDeadServer239=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI240=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512241=== RUN TestSupersededNARStillUploadsListing/dump_cut_short242=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512243=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts2442026/10/25 17:15:27 ERROR Upload failed error="connection refused" count=20245=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts2462026/10/25 17:15:27 ERROR Server seems unavailable, giving up on batch untried=17247=== CONT TestDoWithRetry_FinalResponseBodyReadable248=== RUN TestPartSizeForNAR/1_TiB249=== PAUSE TestPartSizeForNAR/1_TiB250=== RUN TestPartSizeForNAR/5_TiB_S3_max_object251=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object252=== RUN TestPartSizeForNAR/capped_at_5_GiB253=== CONT TestStreamPushBatchesUnderLoad254=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA255=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA256=== RUN TestSetClientTLS/preserves_debug_logging_transport257=== PAUSE TestPartSizeForNAR/capped_at_5_GiB258=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped259=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped260=== CONT TestStreamPushRequestLine261=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive262=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error263=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error264=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error265=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error266=== CONT TestStreamPushReportsSignatures267=== RUN TestSetClientTLSErrors/invalid_ca_file2682026/10/25 17:15:27 WARN Rate limiter enabled after throttle name=server-test rate=5269=== CONT TestClientSignaturesByStorePath2702026/10/25 17:15:27 ERROR Upload failed error=boom count=1271=== CONT TestShellSplit272=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short2732026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:36345274=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails275--- PASS: TestDoServerRequestAttachesToken (0.09s)276=== PAUSE TestSetClientTLS/preserves_debug_logging_transport277=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails2782026/10/25 17:15:27 ERROR Upload failed error=boom count=1279=== CONT TestStreamPushReportsEveryPath280=== RUN TestFilterOversizedClosures/all_closures_skipped281=== PAUSE TestFilterOversizedClosures/all_closures_skipped282=== RUN TestPathInfoCACompatibility/new_structured_format_-_text283=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text284=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error285=== PAUSE TestSetClientTLSErrors/invalid_ca_file2862026/10/25 17:15:27 WARN Rate limiter backed off name=server-test rate=5287=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter288=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter289=== CONT TestRetryTimeoutOutlastsMaxRetries290=== CONT TestConvertHashToNix32/SRI_format_to_Nix32291=== CONT TestConvertHashToNix32/invalid_format292=== CONT TestRegisterUploadedObjectReusesConnections293=== CONT TestConvertHashToNix32/already_Nix32_format294=== CONT TestParsePathInfoJSON/Nix_format295--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.08s)296--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.09s)297--- PASS: TestStreamPushStopsWhenCanceled (0.00s)298--- PASS: TestStreamPushReportsSkippedPaths (0.00s)299--- PASS: TestShellSplitErrors (0.00s)300--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)301--- PASS: TestClientSignaturesByStorePath (0.00s)302--- PASS: TestShellSplit (0.00s)303--- PASS: TestStreamPushReportsSignatures (0.00s)304--- PASS: TestStreamPushReportsEveryPath (0.00s)305--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.00s)306--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.00s)307=== CONT TestParsePathInfoJSON/whitespace_only308=== CONT TestParsePathInfoJSON/invalid_JSON309=== CONT TestParsePathInfoJSON/empty_input310=== CONT TestParsePathInfoJSON/Lix_format311=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths312=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths313=== CONT TestUploadMultipart_SupersededByPeer/exists3142026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:33111315=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry316=== CONT TestEncodeNixBase32/test_string_hash317=== CONT TestEncodeNixBase32/empty_input318=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)319=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI320=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512321=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon322=== CONT TestPartSizeForNAR/zero_stays_at_minimum323=== CONT TestPartSizeForNAR/1_TiB324=== CONT TestPartSizeForNAR/5_TiB_S3_max_object325=== CONT TestPartSizeForNAR/capped_at_5_GiB326=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum327=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts328=== CONT TestPartSizeForNAR/small_stays_at_minimum329=== CONT TestSetClientTLS/rejects_connection_without_client_cert330=== CONT TestSupersededNARStillUploadsListing/small_NAR331=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3322026/10/25 17:15:27 INFO Uploading abc-hello (1.0GB)3332026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:33111334=== CONT TestSupersededNARStillUploadsListing/dump_cut_short335=== CONT TestStreamPushIsolatesFailures336=== CONT TestSetClientTLS/preserves_debug_logging_transport3372026/10/25 17:15:27 WARN Rate limiter enabled after throttle name=s3-test rate=53382026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:453273392026/10/25 17:15:27 ERROR Upload failed error="bad path" count=3340=== CONT TestRateLimiterFeedback/429_enables_limiter341=== CONT TestRateLimiterFeedback/503_enables_limiter342=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method343=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica344--- PASS: TestConvertHashToNix32 (0.00s)345 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)346 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)347 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)348=== CONT TestUploadMultipart_SupersededByPeer/missing349=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails3502026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:33111351--- PASS: TestStreamPushIsolatesFailures (0.14s)3522026/10/25 17:15:27 WARN Rate limiter enabled after throttle name=server-test rate=5353--- PASS: TestScriptTokenEmptyToken (0.00s)3542026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:38837355--- PASS: TestScriptTokenBadJSON (0.00s)3562026/10/25 17:15:27 WARN Rate limiter enabled after throttle name=server-test rate=5357--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.09s)3582026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:33109359--- PASS: TestScriptTokenCachesUntilRefresh (0.01s)3602026/10/25 17:15:27 INFO Garbage collection started361--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.01s)3622026/10/25 17:15:27 INFO Uploading abc-hello (1.0GB)363--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)364 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)365 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)3662026/10/25 17:15:27 WARN Rate limiter backed off name=server-test rate=5367--- PASS: TestEncodeNixBase32 (0.08s)368 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)369 --- PASS: TestEncodeNixBase32/empty_input (0.00s)370--- PASS: TestParsePathInfoJSON (0.05s)371 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)372 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)373 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)374 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)375 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)3762026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:33111377--- PASS: TestPathInfoHashCompatibility (0.08s)378 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)379 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)380 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)381 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)3822026/10/25 17:15:27 WARN Rate limiter backed off name=server-test rate=5383--- PASS: TestPartSizeForNAR (0.08s)384 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)385 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)386 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)387 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)388 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)389 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)390 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)391=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped392--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)393 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)394 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)3952026/10/25 17:15:27 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-vm-image nar_size=5000 max_nar_size=2000396--- PASS: TestRateLimiterFeedback (0.00s)397 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)398 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)399 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)400 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.13s)401=== CONT TestSetClientTLSErrors/missing_cert_file402=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error403=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error404=== CONT TestFilterOversizedClosures/no_limit_keeps_everything405=== CONT TestFilterOversizedClosures/all_closures_skipped4062026/10/25 17:15:27 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50407--- PASS: TestFilterOversizedClosures (0.00s)408 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)409 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)410 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)411=== CONT TestGetStorePathHash/valid_store_path412=== CONT TestGetStorePathHash/basename_without_hyphen_should_error413--- PASS: TestGetStorePathHash (0.08s)414 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)415 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)416 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)417 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)418=== CONT TestSetClientTLSErrors/invalid_ca_file419=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method420=== CONT TestPathInfoCACompatibility/null_ca_field421=== CONT TestPathInfoCACompatibility/new_structured_format_-_text422=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive423=== CONT TestSetClientTLSErrors/missing_key_file424=== CONT TestSetClientTLSErrors/missing_ca_file425=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method4262026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:33111427--- PASS: TestCaseHackSuffix (0.14s)428=== CONT TestPathInfoCACompatibility/old_string_format_-_text429--- PASS: TestPathInfoCACompatibility (0.23s)430 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)431 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)432 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)433 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)434 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)435--- PASS: TestSetClientTLSErrors (0.08s)436 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)437 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)438 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)439 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)4402026/10/25 17:15:27 INFO Garbage collection progress phase=running_on_another_replica failed_uploads_deleted=0 old_closures_deleted=0 objects_marked=0 objects_deleted=0 objects_failed=04412026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:331114422026/10/25 17:15:27 http: TLS handshake error from 127.0.0.1:42170: remote error: tls: bad certificate4432026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:331114442026/10/25 17:15:27 WARN Garbage collection finished on another replica. Its statistics are not available here445--- PASS: TestSetClientTLS (0.08s)446 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.14s)447 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.14s)448 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.14s)449--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)4502026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:33111451--- PASS: TestStreamPushRequestLine (0.15s)4522026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:331114532026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:331114542026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:331114552026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:331114562026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:33111457--- PASS: TestRegisterUploadedObjectReusesConnections (0.15s)458--- PASS: TestDumpPathWriterError (0.24s)4592026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:331114602026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:331114612026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:331114622026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:331114632026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:331114642026/10/25 17:15:27 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:33111465--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.16s)4662026/10/25 17:15:27 INFO Uploading abc-hello (1.0GB)4672026/10/25 17:15:27 WARN Rate limiter enabled after throttle name=s3-test rate=5468--- PASS: TestStreamPushBatchesUnderLoad (0.20s)4692026/10/25 17:15:27 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:44571/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:44571/part/2470--- PASS: TestDumpPathMatchesNix (0.29s)4712026/10/25 17:15:27 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:44571/part/3\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:44571/part/34722026/10/25 17:15:27 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"473--- PASS: TestSupersededNARStillUploadsListing (0.03s)474 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.14s)475 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.01s)476 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.70s)477--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.76s)478--- PASS: TestUploadMultipart_PartsInParallel (0.82s)479--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4802026/10/25 17:15:28 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:39059/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:39059/api/uploads/complete4812026/10/25 17:15:28 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4822026/10/25 17:15:28 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:39059/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:39059/api/uploads/complete4832026/10/25 17:15:28 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4842026/10/25 17:15:28 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:39059/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:39059/api/uploads/complete4852026/10/25 17:15:28 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"486--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.01s)487PASS488Running server tests...489The files belonging to this database system will be owned by user "nixbld".490This user must also own the server process.491492The database cluster will be initialized with locale "C".493The default database encoding has accordingly been set to "SQL_ASCII".494The default text search configuration will be set to "english".495496Data page checksums are enabled.497498creating directory /build/postgres3214958112/data ... ok499creating subdirectories ... ok500selecting dynamic shared memory implementation ... posix501selecting default "max_connections" ... 100502selecting default "shared_buffers" ... 128MB503selecting default time zone ... UTC504creating configuration files ... ok505running bootstrap script ... ok506performing post-bootstrap initialization ... ok507syncing data to disk ... ok508509initdb: warning: enabling "trust" authentication for local connections510initdb: 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.511512Success. You can now start the database server using:513514 pg_ctl -D /build/postgres3214958112/data -l logfile start515516/build/postgres3214958112:5432 - no response5172026-10-25 17:15:29.131 UTC [128] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit5182026-10-25 17:15:29.132 UTC [128] LOG: listening on Unix socket "/build/postgres3214958112/.s.PGSQL.5432"5192026-10-25 17:15:29.137 UTC [135] LOG: database system was shut down at 2026-10-25 17:15:28 UTC5202026-10-25 17:15:29.141 UTC [128] LOG: database system is ready to accept connections521/build/postgres3214958112:5432 - accepting connections522=== RUN TestService_AuthMiddleware523=== PAUSE TestService_AuthMiddleware524=== RUN TestService_AuthMiddleware_MTLSProxyHeader525=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader526=== RUN TestService_AuthMiddleware_MTLSBoundSubjects527=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects528=== RUN TestService_ReadAuthMiddleware529=== PAUSE TestService_ReadAuthMiddleware530=== RUN TestService_AuthMiddleware_OIDC531=== PAUSE TestService_AuthMiddleware_OIDC532=== RUN TestService_RequireScope_OIDC533=== PAUSE TestService_RequireScope_OIDC534=== RUN TestService_ReadScope_PublicByDefault535=== PAUSE TestService_ReadScope_PublicByDefault536=== RUN TestCacheConfigHandler537=== PAUSE TestCacheConfigHandler538=== RUN TestCacheStatsHandler539=== PAUSE TestCacheStatsHandler540=== RUN TestClientCADerivations541=== PAUSE TestClientCADerivations542=== RUN TestClientErrorHandling543=== PAUSE TestClientErrorHandling544=== RUN TestClientIntegration545=== PAUSE TestClientIntegration546=== RUN TestClientMultipleUploads547=== PAUSE TestClientMultipleUploads548=== RUN TestClientWithDependencies549=== PAUSE TestClientWithDependencies550=== RUN TestClientSharedPathCommittedMidPush551=== PAUSE TestClientSharedPathCommittedMidPush552=== RUN TestPinProtectsFromGC553=== PAUSE TestPinProtectsFromGC554=== RUN TestClientPushesUseOnePush555=== PAUSE TestClientPushesUseOnePush556=== RUN TestClientFallsBackToClosures557=== PAUSE TestClientFallsBackToClosures558=== RUN TestDeleteClosuresRacingPins559=== PAUSE TestDeleteClosuresRacingPins560=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock561=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock562=== RUN TestResolveDBConnectionString563=== PAUSE TestResolveDBConnectionString564=== RUN TestConnectWaitsForAPeerMigration565=== PAUSE TestConnectWaitsForAPeerMigration566=== RUN TestLeadElectsOneAndHandsOver567=== PAUSE TestLeadElectsOneAndHandsOver568=== RUN TestLeadIncumbentWinsAfterRestart5692026/10/25 17:15:29 INFO lead: acquired remote=192.0.2.1:12345702026/10/25 17:15:30 INFO lead: released remote=192.0.2.1:12345712026/10/25 17:15:30 INFO lead: acquired remote=192.0.2.1:12345722026/10/25 17:15:31 INFO lead: released remote=192.0.2.1:1234573--- PASS: TestLeadIncumbentWinsAfterRestart (1.88s)574=== RUN TestLeadIncumbentAnnouncesAtOnce575=== PAUSE TestLeadIncumbentAnnouncesAtOnce576=== RUN TestLeadEndsOnShutdown577=== PAUSE TestLeadEndsOnShutdown578=== RUN TestLeadEndsWhenItsConnectionHangs5792026/10/25 17:15:31 INFO lead: acquired remote=192.0.2.1:12345802026-10-25 17:15:33.022 UTC [317] FATAL: terminating connection due to administrator command5812026/10/25 17:15:33 INFO lead: acquired remote=192.0.2.1:12345822026/10/25 17:15:34 WARN lead: lock connection lost error="timeout: context deadline exceeded"5832026/10/25 17:15:34 INFO lead: released remote=192.0.2.1:12345842026/10/25 17:15:34 INFO lead: released remote=192.0.2.1:1234585--- PASS: TestLeadEndsWhenItsConnectionHangs (2.91s)586=== RUN TestGCAdvisoryLockBlocksConcurrentRun587=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun588=== RUN TestGCBugBareHashReferences589=== PAUSE TestGCBugBareHashReferences590=== RUN TestGCMetrics591=== PAUSE TestGCMetrics592=== RUN TestPushDedupSurvivesConcurrentGC593=== PAUSE TestPushDedupSurvivesConcurrentGC594=== RUN TestDeduplicatedObjectsRecordedAsPending595=== PAUSE TestDeduplicatedObjectsRecordedAsPending596=== RUN TestGCSweepSkipsPendingObjects597=== PAUSE TestGCSweepSkipsPendingObjects598=== RUN TestTombstonedObjectOfferedWithoutWaiting599=== PAUSE TestTombstonedObjectOfferedWithoutWaiting600=== RUN TestGCSweepDeliversEachKeyOnce601=== PAUSE TestGCSweepDeliversEachKeyOnce602=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection603=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection604=== RUN TestForceGCDuringPushOffersSweptObject605=== PAUSE TestForceGCDuringPushOffersSweptObject606=== RUN TestFailedS3DeleteKeepsTombstone607=== PAUSE TestFailedS3DeleteKeepsTombstone608=== RUN TestSweepSkipsRowsLockedByPush609=== PAUSE TestSweepSkipsRowsLockedByPush610=== RUN TestRegisterCompletedObjectNeedsPendingRow611=== PAUSE TestRegisterCompletedObjectNeedsPendingRow612=== RUN TestGetExistingObjectsLocksRows613=== PAUSE TestGetExistingObjectsLocksRows614=== RUN TestSweepRechecksPendingAfterLocking615=== PAUSE TestSweepRechecksPendingAfterLocking616=== RUN TestPushWaitsForSweepHoldingRow617=== PAUSE TestPushWaitsForSweepHoldingRow618=== RUN TestCommitRacingPendingCleanupKeepsObjects619=== PAUSE TestCommitRacingPendingCleanupKeepsObjects620=== RUN TestGCEndsOnShutdown621=== PAUSE TestGCEndsOnShutdown622=== RUN TestGCTaskStore_StartNew623=== PAUSE TestGCTaskStore_StartNew624=== RUN TestGCTaskStore_DeduplicateSameParams625=== PAUSE TestGCTaskStore_DeduplicateSameParams626=== RUN TestGCTaskStore_ConflictDifferentParams627=== PAUSE TestGCTaskStore_ConflictDifferentParams628=== RUN TestGCTaskStore_GetEmpty629=== PAUSE TestGCTaskStore_GetEmpty630=== RUN TestGCTaskStore_GetReturnsLatest631=== PAUSE TestGCTaskStore_GetReturnsLatest632=== RUN TestGCTaskStore_CompletedAllowsNewTask633=== PAUSE TestGCTaskStore_CompletedAllowsNewTask634=== RUN TestGCTaskStore_PhaseUpdates635=== PAUSE TestGCTaskStore_PhaseUpdates636=== RUN TestGCTaskStore_Fail637=== PAUSE TestGCTaskStore_Fail638=== RUN TestGracefulShutdownDrainsInflight639=== PAUSE TestGracefulShutdownDrainsInflight640=== RUN TestService_healthCheckHandler641=== PAUSE TestService_healthCheckHandler642=== RUN TestService_readinessHandler643=== PAUSE TestService_readinessHandler644=== RUN TestGenerateLandingPage645=== PAUSE TestGenerateLandingPage646=== RUN TestCacheConfigHandlerMaxNarSize647=== PAUSE TestCacheConfigHandlerMaxNarSize648=== RUN TestCreatePendingClosureRejectsOversizedNAR649=== PAUSE TestCreatePendingClosureRejectsOversizedNAR650=== RUN TestNARDeduplicationMetadataUploadBug651=== PAUSE TestNARDeduplicationMetadataUploadBug652=== RUN TestMetricsInventory653=== PAUSE TestMetricsInventory654=== RUN TestMetricsCommit655=== PAUSE TestMetricsCommit656=== RUN TestService_NativeMTLS657=== PAUSE TestService_NativeMTLS658=== RUN TestServerTLSConfig659=== PAUSE TestServerTLSConfig660=== RUN TestMultipartCleanup661=== PAUSE TestMultipartCleanup662=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded663=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded664=== RUN TestPendingCleanupUsesOneCutoff665=== PAUSE TestPendingCleanupUsesOneCutoff666=== RUN TestObjectStatsTrigger667=== PAUSE TestObjectStatsTrigger668=== RUN TestObjectStatsUpdatedOncePerCommit669=== PAUSE TestObjectStatsUpdatedOncePerCommit670=== RUN TestOrphanedObjectsGC671=== PAUSE TestOrphanedObjectsGC672=== RUN TestOrphanedObjectsGCStressTest673=== PAUSE TestOrphanedObjectsGCStressTest674=== RUN TestCreatePin_ReservedPins675=== PAUSE TestCreatePin_ReservedPins676=== RUN TestPresentReportsOnlyClosureRoots677=== PAUSE TestPresentReportsOnlyClosureRoots678=== RUN TestPresentRefreshesOnlyStaleClosures679=== PAUSE TestPresentRefreshesOnlyStaleClosures680=== RUN TestPresentNotReportedWhileGCDeletesClosure681=== PAUSE TestPresentNotReportedWhileGCDeletesClosure682=== RUN TestParseSingleRange683=== PAUSE TestParseSingleRange684=== RUN TestProxyHeadersOnlyTrustedOnSocket6852026/10/25 17:15:34 INFO Starting HTTP server address=127.0.0.1:464376862026/10/25 17:15:34 INFO Starting HTTP server address=proxy.sock6872026/10/25 17:15:34 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6882026/10/25 17:15:34 INFO Shutdown signal received, draining in-flight requests timeout=10s689--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.10s)690=== RUN TestIsValidCachePath691=== PAUSE TestIsValidCachePath692=== RUN TestReadProxyNarinfo693=== PAUSE TestReadProxyNarinfo694=== RUN TestReadProxyNarinfoAlreadyDecompressed695=== PAUSE TestReadProxyNarinfoAlreadyDecompressed696=== RUN TestReadProxyContentNegotiation697=== PAUSE TestReadProxyContentNegotiation698=== RUN TestReadProxyNarStreaming699=== PAUSE TestReadProxyNarStreaming700=== RUN TestReadProxy404701=== PAUSE TestReadProxy404702=== RUN TestReadProxyInvalidPath703=== PAUSE TestReadProxyInvalidPath704=== RUN TestReadProxyHead705=== PAUSE TestReadProxyHead706=== RUN TestReadProxyOutlastsServerWriteTimeout707=== PAUSE TestReadProxyOutlastsServerWriteTimeout708=== RUN TestReadProxyConditionalGet709=== PAUSE TestReadProxyConditionalGet710=== RUN TestReadProxyRootRedirectsToIndexHTML711=== PAUSE TestReadProxyRootRedirectsToIndexHTML712=== RUN TestReadProxyDisabled713=== PAUSE TestReadProxyDisabled714=== RUN TestReadRedirectNar715=== PAUSE TestReadRedirectNar716=== RUN TestReadRedirectKeepsNarinfoProxied717=== PAUSE TestReadRedirectKeepsNarinfoProxied718=== RUN TestReadProxyRangeRequest719=== PAUSE TestReadProxyRangeRequest720=== RUN TestReadRedirectUsesPublicS3URL721=== PAUSE TestReadRedirectUsesPublicS3URL722=== RUN TestPush_OverlappingRootsStoreOneRowPerKey723=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey724=== RUN TestPush_CompleteCommitsEveryRoot725=== PAUSE TestPush_CompleteCommitsEveryRoot726=== RUN TestPush_RepeatedRootCommitsOnce727=== PAUSE TestPush_RepeatedRootCommitsOnce728=== RUN TestPush_CompleteWaitsForCleanupOfThePush729=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush730=== RUN TestPush_RootsAreLockedInByteOrder731=== PAUSE TestPush_RootsAreLockedInByteOrder732=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit733=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit734=== RUN TestPush_RejectsBadRequests735=== PAUSE TestPush_RejectsBadRequests736=== RUN TestPush_SignsNarinfosOfItsPendingObjects737=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects738=== RUN TestRedundantMultipartUpload739=== PAUSE TestRedundantMultipartUpload740=== RUN TestCompleteMultipartUpload_ErrorButObjectExists741=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists742=== RUN TestCompletedNarNotReofferedAcrossClosures743=== PAUSE TestCompletedNarNotReofferedAcrossClosures744=== RUN TestPresignedUploadRegisteredBeforeCommit745=== PAUSE TestPresignedUploadRegisteredBeforeCommit746=== RUN TestService_Rustfstest747=== PAUSE TestService_Rustfstest748=== RUN TestParseSize749=== PAUSE TestParseSize750=== RUN TestSkippedUploadsHandler751=== PAUSE TestSkippedUploadsHandler752=== RUN TestSystemdListenerNotActivated753--- PASS: TestSystemdListenerNotActivated (0.00s)754=== RUN TestWatchdogBeatsWhenHealthy755--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)756=== RUN TestWatchdogSkipsWhenUnhealthy7572026/10/25 17:15:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7582026/10/25 17:15:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7592026/10/25 17:15:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/25 17:15:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7612026/10/25 17:15:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7622026/10/25 17:15:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7632026/10/25 17:15:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7642026/10/25 17:15:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7652026/10/25 17:15:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7662026/10/25 17:15:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"767--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)768=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle769=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle770=== RUN TestProxyWriteTimeout771=== PAUSE TestProxyWriteTimeout772=== RUN TestPendingClosureWriteTimeout773=== PAUSE TestPendingClosureWriteTimeout774=== RUN TestIsValidUploadKey775=== PAUSE TestIsValidUploadKey776=== RUN TestUploadHandlersRejectInvalidKeys777=== PAUSE TestUploadHandlersRejectInvalidKeys778=== RUN TestUploadHandlersRejectOversizedBody779=== PAUSE TestUploadHandlersRejectOversizedBody780=== RUN TestService_cleanupPendingClosuresHandler781=== PAUSE TestService_cleanupPendingClosuresHandler782=== RUN TestService_createPendingClosureHandler783=== PAUSE TestService_createPendingClosureHandler784=== RUN TestService_verifyS3Integrity785=== PAUSE TestService_verifyS3Integrity786=== RUN TestCompleteMultipartUnregistered787=== PAUSE TestCompleteMultipartUnregistered788=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT789=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT790=== CONT TestService_AuthMiddleware791=== CONT TestService_Rustfstest792=== CONT TestDeduplicatedObjectsRecordedAsPending793=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT794=== CONT TestCompleteMultipartUnregistered795=== CONT TestService_verifyS3Integrity796=== CONT TestService_createPendingClosureHandler797=== CONT TestService_cleanupPendingClosuresHandler798=== CONT TestUploadHandlersRejectOversizedBody799=== CONT TestUploadHandlersRejectInvalidKeys800=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info801=== CONT TestIsValidUploadKey802=== CONT TestPendingClosureWriteTimeout803=== CONT TestProxyWriteTimeout804=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle805=== CONT TestSkippedUploadsHandler806=== CONT TestParseSize807=== CONT TestNARDeduplicationMetadataUploadBug808=== CONT TestCreatePendingClosureRejectsOversizedNAR809=== CONT TestCacheConfigHandlerMaxNarSize810=== CONT TestGenerateLandingPage811=== CONT TestService_readinessHandler812=== CONT TestService_healthCheckHandler813=== CONT TestGracefulShutdownDrainsInflight814=== CONT TestMetricsInventory815=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info816=== RUN TestPendingClosureWriteTimeout/empty817=== RUN TestIsValidUploadKey/narinfo818=== PAUSE TestPendingClosureWriteTimeout/empty819=== RUN TestProxyWriteTimeout/narinfo820--- PASS: TestParseSize (0.00s)821=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal8222026/10/25 17:15:34 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000823=== RUN TestPendingClosureWriteTimeout/400_objects824=== CONT TestGCTaskStore_Fail825=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal826=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key827=== PAUSE TestPendingClosureWriteTimeout/400_objects828=== RUN TestPendingClosureWriteTimeout/670k_objects8292026/10/25 17:15:34 INFO Received uploads request method=POST path=/api/pending_closures830=== PAUSE TestIsValidUploadKey/narinfo831=== PAUSE TestPendingClosureWriteTimeout/670k_objects832=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key833=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key834=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key835=== PAUSE TestProxyWriteTimeout/narinfo836=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline837=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline838=== RUN TestProxyWriteTimeout/1_GiB_nar839=== PAUSE TestProxyWriteTimeout/1_GiB_nar840=== RUN TestProxyWriteTimeout/10_GiB_nar841=== RUN TestIsValidUploadKey/nar_zst8422026/10/25 17:15:34 INFO Starting HTTP server address=127.0.0.1:44109843=== PAUSE TestIsValidUploadKey/nar_zst844=== RUN TestIsValidUploadKey/nar_xz845=== PAUSE TestIsValidUploadKey/nar_xz846=== RUN TestIsValidUploadKey/nar_plain847=== PAUSE TestIsValidUploadKey/nar_plain848=== CONT TestGCTaskStore_ConflictDifferentParams849=== CONT TestGCTaskStore_StartNew850--- PASS: TestCacheConfigHandlerMaxNarSize (0.07s)851--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.06s)852--- PASS: TestGCTaskStore_Fail (0.00s)853--- PASS: TestGenerateLandingPage (0.07s)8542026/10/25 17:15:34 INFO Shutdown signal received, draining in-flight requests timeout=10s855--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)856=== CONT TestGCTaskStore_CompletedAllowsNewTask857=== CONT TestGCTaskStore_GetReturnsLatest858=== CONT TestGCTaskStore_GetEmpty859=== CONT TestGCTaskStore_PhaseUpdates860=== PAUSE TestProxyWriteTimeout/10_GiB_nar861=== CONT TestGCTaskStore_DeduplicateSameParams862=== CONT TestRegisterCompletedObjectNeedsPendingRow863=== RUN TestIsValidUploadKey/listing864=== PAUSE TestIsValidUploadKey/listing865=== RUN TestIsValidUploadKey/build_log866=== PAUSE TestIsValidUploadKey/build_log867=== RUN TestIsValidUploadKey/build_log_home-manager_file868=== PAUSE TestIsValidUploadKey/build_log_home-manager_file869=== CONT TestGCEndsOnShutdown870--- PASS: TestGCTaskStore_StartNew (0.00s)871--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)872--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)873=== CONT TestCommitRacingPendingCleanupKeepsObjects874=== CONT TestPushWaitsForSweepHoldingRow875=== CONT TestSweepRechecksPendingAfterLocking876=== CONT TestGetExistingObjectsLocksRows877=== RUN TestProxyWriteTimeout/unknown_size878=== PAUSE TestProxyWriteTimeout/unknown_size879=== CONT TestSweepSkipsRowsLockedByPush880=== RUN TestIsValidUploadKey/build_log_plus_in_name881=== PAUSE TestIsValidUploadKey/build_log_plus_in_name882=== RUN TestIsValidUploadKey/build_log_question_mark883=== PAUSE TestIsValidUploadKey/build_log_question_mark884=== RUN TestIsValidUploadKey/build_log_equals885=== PAUSE TestIsValidUploadKey/build_log_equals886=== RUN TestIsValidUploadKey/realisation887=== PAUSE TestIsValidUploadKey/realisation888=== RUN TestIsValidUploadKey/realisation_plus_in_output889=== RUN TestGCEndsOnShutdown/before_the_run890--- PASS: TestGCTaskStore_GetEmpty (0.00s)891--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)892--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)893=== PAUSE TestIsValidUploadKey/realisation_plus_in_output894=== PAUSE TestGCEndsOnShutdown/before_the_run895=== RUN TestIsValidUploadKey/nix-cache-info896=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete897=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete898=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark899=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark900=== PAUSE TestIsValidUploadKey/nix-cache-info901=== CONT TestFailedS3DeleteKeepsTombstone902=== RUN TestIsValidUploadKey/index.html903=== PAUSE TestIsValidUploadKey/index.html904=== RUN TestIsValidUploadKey/narinfo_key,_nar_type905=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type906=== RUN TestIsValidUploadKey/nar_key,_narinfo_type907=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type908=== RUN TestIsValidUploadKey/listing_key,_narinfo_type909=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type910=== RUN TestIsValidUploadKey/traversal911=== PAUSE TestIsValidUploadKey/traversal912=== RUN TestIsValidUploadKey/traversal_nar913=== PAUSE TestIsValidUploadKey/traversal_nar914=== RUN TestIsValidUploadKey/absolute915=== PAUSE TestIsValidUploadKey/absolute916=== RUN TestIsValidUploadKey/empty_key917=== PAUSE TestIsValidUploadKey/empty_key918=== RUN TestIsValidUploadKey/unknown_type919=== PAUSE TestIsValidUploadKey/unknown_type920=== CONT TestForceGCDuringPushOffersSweptObject921=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows922=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows923=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check924=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check925=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection926--- PASS: TestSkippedUploadsHandler (0.08s)927=== CONT TestGCSweepDeliversEachKeyOnce928--- PASS: TestGracefulShutdownDrainsInflight (0.12s)929=== CONT TestTombstonedObjectOfferedWithoutWaiting930=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure931=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure932=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart933=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart934=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts935=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts936=== CONT TestGCSweepSkipsPendingObjects9372026/10/25 17:15:35 INFO Received uploads request method=POST path=/api/pending_closures938--- PASS: TestService_Rustfstest (0.31s)939=== CONT TestPinProtectsFromGC9402026/10/25 17:15:35 INFO Received uploads request method=POST path=/api/pending_closures941--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.34s)942=== CONT TestPushDedupSurvivesConcurrentGC9432026/10/25 17:15:35 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"944--- PASS: TestService_AuthMiddleware (0.41s)945=== CONT TestGCMetrics9462026/10/25 17:15:35 INFO Received uploads request method=POST path=/api/pending_closures9472026/10/25 17:15:35 INFO Received uploads request method=POST path=/api/pending_closures9482026/10/25 17:15:35 INFO Received uploads request method=POST path=/api/pending_closures9492026/10/25 17:15:35 INFO Received cleanup request method=DELETE path=/api/pending_closures9502026/10/25 17:15:35 INFO Aborted multipart uploads count=0 kept=09512026/10/25 17:15:35 INFO Received uploads request method=POST path=/api/pending_closures9522026/10/25 17:15:35 INFO Received cleanup request method=DELETE path=/api/pending_closures9532026/10/25 17:15:35 INFO Aborted multipart uploads count=1 kept=09542026/10/25 17:15:35 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9552026-10-25 17:15:35.235 UTC [398] ERROR: Closure does not exist: id=19562026-10-25 17:15:35.235 UTC [398] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9572026-10-25 17:15:35.235 UTC [398] STATEMENT: -- name: CommitPendingClosure :one958 SELECT commit_pending_closure($1::bigint)::bigint959 960--- PASS: TestService_cleanupPendingClosuresHandler (0.47s)961=== CONT TestGCBugBareHashReferences9622026/10/25 17:15:35 INFO Received uploads request method=POST path=/api/pending_closures963--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.49s)964=== CONT TestGCAdvisoryLockBlocksConcurrentRun9652026/10/25 17:15:35 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9662026/10/25 17:15:35 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst967--- PASS: TestCompleteMultipartUnregistered (0.50s)968=== CONT TestLeadEndsOnShutdown969--- PASS: TestService_healthCheckHandler (0.51s)970=== CONT TestLeadIncumbentAnnouncesAtOnce9712026/10/25 17:15:35 INFO Received uploads request method=POST path=/api/pending_closures972--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.51s)973=== CONT TestLeadElectsOneAndHandsOver9742026/10/25 17:15:35 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9752026/10/25 17:15:35 INFO Aborted multipart uploads count=0 kept=0976=== NAME TestNARDeduplicationMetadataUploadBug977 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug1359387997/001/store/h10ffqq2n5bsfkhzsg0vn04sphspw6bp-file1.txt9782026/10/25 17:15:35 WARN Force mode enabled - objects will be deleted immediately without grace period9792026/10/25 17:15:35 INFO Received uploads request method=POST path=/api/pending_closures9802026/10/25 17:15:35 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=09812026/10/25 17:15:35 INFO Vacuumed table table=pending_closures9822026/10/25 17:15:35 INFO Vacuumed table table=pending_objects9832026/10/25 17:15:35 INFO Vacuumed table table=multipart_uploads9842026/10/25 17:15:35 INFO Vacuumed table table=closures9852026/10/25 17:15:35 INFO Vacuumed table table=objects986--- PASS: TestSweepRechecksPendingAfterLocking (0.59s)987=== CONT TestConnectWaitsForAPeerMigration9882026/10/25 17:15:35 INFO Received uploads request method=POST path=/api/pending_closures989--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.54s)990=== CONT TestResolveDBConnectionString991=== RUN TestResolveDBConnectionString/flag_wins992=== PAUSE TestResolveDBConnectionString/flag_wins993=== RUN TestResolveDBConnectionString/file_when_flag_empty994=== PAUSE TestResolveDBConnectionString/file_when_flag_empty995=== RUN TestResolveDBConnectionString/missing_file_is_an_error996=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error997=== RUN TestResolveDBConnectionString/PGHOST_allows_empty998=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty999=== RUN TestResolveDBConnectionString/nothing_configured1000=== PAUSE TestResolveDBConnectionString/nothing_configured1001=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock10022026/10/25 17:15:35 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10032026/10/25 17:15:35 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZTA0MTY3MGQtYjk0Ny00MGQwLWI5YmMtZDI3YjhhM2VkMzI1LmZjZjFkY2U5LWIxZGQtNGU5MS04ZDA3LTJkNWY3MjNiMGM4MXgxNzkyOTQ4NTM1MDUyMDM5NzI4 parts=1010042026/10/25 17:15:35 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10052026/10/25 17:15:35 INFO Completed upload id=1 objects=2 duration=2.883459ms10062026/10/25 17:15:35 INFO Aborted multipart uploads count=0 kept=010072026/10/25 17:15:35 INFO Received uploads request method=POST path=/api/pending_closures10082026/10/25 17:15:35 WARN Force mode enabled - objects will be deleted immediately without grace period10092026/10/25 17:15:35 INFO Received push request method=POST path=/api/pushes10102026/10/25 17:15:35 INFO Received uploads request method=POST path=/api/pending_closures10112026/10/25 17:15:35 INFO Received uploads request method=POST path=/api/pending_closures10122026/10/25 17:15:35 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010132026/10/25 17:15:35 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10142026/10/25 17:15:35 WARN Found objects in DB but missing from S3, will re-upload count=11015--- PASS: TestService_verifyS3Integrity (0.73s)1016=== CONT TestDeleteClosuresRacingPins10172026/10/25 17:15:35 INFO Vacuumed table table=pending_closures10182026/10/25 17:15:35 INFO Vacuumed table table=pending_objects10192026/10/25 17:15:35 INFO Vacuumed table table=multipart_uploads10202026/10/25 17:15:35 INFO Vacuumed table table=closures10212026/10/25 17:15:35 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10222026/10/25 17:15:35 INFO Uploading h10ffqq2n5bsfkhzsg0vn04sphspw6bp-file1.txt (160B)10232026/10/25 17:15:35 INFO Vacuumed table table=objects10242026/10/25 17:15:35 INFO Aborted multipart uploads count=0 kept=010252026/10/25 17:15:35 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"10262026/10/25 17:15:35 WARN Failed to register uploaded object key=h10ffqq2n5bsfkhzsg0vn04sphspw6bp.ls error="server returned 404: 404 page not found\n"10272026/10/25 17:15:35 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10282026/10/25 17:15:35 INFO Signed narinfos id=1 count=110292026/10/25 17:15:35 INFO Uploading 1 narinfos10302026/10/25 17:15:35 WARN Force mode enabled - objects will be deleted immediately without grace period10312026/10/25 17:15:35 INFO Received complete push request method=POST path=/api/pushes/1/complete10322026/10/25 17:15:35 WARN Failed to register uploaded object key=h10ffqq2n5bsfkhzsg0vn04sphspw6bp.narinfo error="server returned 404: 404 page not found\n"10332026/10/25 17:15:35 INFO Aborted multipart uploads count=0 kept=010342026/10/25 17:15:35 INFO Completed push id=1 objects=3 duration=5.447869ms10352026/10/25 17:15:35 INFO Upload complete. (66ms)10362026/10/25 17:15:35 WARN Force mode enabled - objects will be deleted immediately without grace period1037=== NAME TestNARDeduplicationMetadataUploadBug1038 metadata_upload_test.go:54: Retrieved narinfo from S3:1039 StorePath: /build/TestNARDeduplicationMetadataUploadBug1359387997/001/store/h10ffqq2n5bsfkhzsg0vn04sphspw6bp-file1.txt1040 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1041 Compression: zstd1042 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1043 NarSize: 1601044 References: 1045 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1046 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1047 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1048 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}10492026/10/25 17:15:35 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010502026/10/25 17:15:35 INFO Vacuumed table table=pending_closures10512026/10/25 17:15:35 INFO Vacuumed table table=pending_objects10522026/10/25 17:15:35 INFO Vacuumed table table=multipart_uploads10532026/10/25 17:15:35 INFO Vacuumed table table=closures10542026/10/25 17:15:35 INFO Vacuumed table table=objects10552026/10/25 17:15:35 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=010562026/10/25 17:15:35 INFO Vacuumed table table=pending_closures10572026/10/25 17:15:35 INFO Vacuumed table table=pending_objects10582026/10/25 17:15:35 INFO Vacuumed table table=multipart_uploads10592026/10/25 17:15:35 INFO Vacuumed table table=closures10602026/10/25 17:15:35 INFO Vacuumed table table=objects1061--- PASS: TestSweepSkipsRowsLockedByPush (0.69s)1062=== CONT TestClientFallsBackToClosures1063--- PASS: TestGCSweepSkipsPendingObjects (0.62s)1064=== CONT TestClientPushesUseOnePush10652026/10/25 17:15:35 INFO Aborted multipart uploads count=0 kept=010662026/10/25 17:15:35 WARN Force mode enabled - objects will be deleted immediately without grace period1067=== NAME TestNARDeduplicationMetadataUploadBug1068 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug1359387997/001/store/wzxj1s2wx3mpfij984r0l935453libz8-file2.txt1069--- PASS: TestMetricsInventory (0.74s)1070=== CONT TestCacheStatsHandler10712026/10/25 17:15:35 WARN readiness check failed error="closed pool"1072--- PASS: TestService_readinessHandler (0.79s)1073=== CONT TestClientSharedPathCommittedMidPush10742026/10/25 17:15:35 INFO Aborted multipart uploads count=0 kept=010752026/10/25 17:15:35 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10762026/10/25 17:15:35 WARN Force mode enabled - objects will be deleted immediately without grace period10772026/10/25 17:15:35 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010782026/10/25 17:15:35 INFO Vacuumed table table=pending_closures10792026/10/25 17:15:35 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=010802026/10/25 17:15:35 INFO Vacuumed table table=pending_closures10812026/10/25 17:15:35 INFO Vacuumed table table=pending_objects10822026/10/25 17:15:35 INFO Vacuumed table table=pending_objects10832026/10/25 17:15:35 INFO Vacuumed table table=multipart_uploads10842026/10/25 17:15:35 INFO Vacuumed table table=multipart_uploads10852026/10/25 17:15:35 INFO Vacuumed table table=closures10862026/10/25 17:15:35 INFO Vacuumed table table=closures10872026/10/25 17:15:35 INFO Vacuumed table table=objects10882026/10/25 17:15:35 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZTA0MTY3MGQtYjk0Ny00MGQwLWI5YmMtZDI3YjhhM2VkMzI1LmRjNDQzMmEwLWNlZmUtNDcxNS1hNDJhLTQ4MjE1NTAzMjE3OHgxNzkyOTQ4NTM1MjAxNjc3NTA1 parts=1010892026/10/25 17:15:35 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10902026/10/25 17:15:35 INFO Vacuumed table table=objects1091--- PASS: TestGCSweepDeliversEachKeyOnce (0.75s)1092=== CONT TestClientWithDependencies10932026/10/25 17:15:35 INFO Completed upload id=1 objects=2 duration=3.60761ms10942026/10/25 17:15:35 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010952026/10/25 17:15:35 INFO Received uploads request method=POST path=/api/pending_closures1096--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.76s)1097=== CONT TestClientMultipleUploads10982026/10/25 17:15:35 INFO Starting cleanup of old closures method=DELETE path=/api/closures10992026/10/25 17:15:35 INFO Received push request method=POST path=/api/pushes11002026/10/25 17:15:35 INFO Aborted multipart uploads count=0 kept=011012026/10/25 17:15:35 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)11022026/10/25 17:15:35 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign11032026/10/25 17:15:35 INFO Signed narinfos id=2 count=111042026/10/25 17:15:35 WARN Failed to register uploaded object key=wzxj1s2wx3mpfij984r0l935453libz8.ls error="server returned 404: 404 page not found\n"11052026/10/25 17:15:35 INFO Uploading 1 narinfos11062026/10/25 17:15:35 INFO Received complete push request method=POST path=/api/pushes/2/complete11072026/10/25 17:15:35 WARN Failed to register uploaded object key=wzxj1s2wx3mpfij984r0l935453libz8.narinfo error="server returned 404: 404 page not found\n"11082026/10/25 17:15:35 INFO Completed push id=2 objects=3 duration=20.344226ms11092026/10/25 17:15:35 INFO Upload complete. (69ms)11102026/10/25 17:15:35 INFO Received uploads request method=POST path=/api/pending_closures1111=== NAME TestNARDeduplicationMetadataUploadBug1112 metadata_upload_test.go:76: Retrieved narinfo from S3:1113 StorePath: /build/TestNARDeduplicationMetadataUploadBug1359387997/001/store/wzxj1s2wx3mpfij984r0l935453libz8-file2.txt1114 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1115 Compression: zstd1116 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1117 NarSize: 1601118 References: 1119 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf11202026/10/25 17:15:35 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=01121 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1122 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1123 {"version":1,"root":{"type":"regular","size":44}}1124--- PASS: TestNARDeduplicationMetadataUploadBug (0.88s)1125=== CONT TestClientIntegration11262026/10/25 17:15:35 INFO Vacuumed table table=pending_closures11272026/10/25 17:15:35 INFO Vacuumed table table=pending_objects1128--- PASS: TestGetExistingObjectsLocksRows (0.82s)1129=== CONT TestClientErrorHandling1130=== RUN TestClientErrorHandling/InvalidStorePath1131=== PAUSE TestClientErrorHandling/InvalidStorePath1132=== RUN TestClientErrorHandling/InvalidAuthToken1133=== PAUSE TestClientErrorHandling/InvalidAuthToken1134=== RUN TestClientErrorHandling/ServerNotAvailable1135=== PAUSE TestClientErrorHandling/ServerNotAvailable1136=== CONT TestClientCADerivations11372026/10/25 17:15:35 INFO Vacuumed table table=multipart_uploads11382026/10/25 17:15:35 INFO Received uploads request method=POST path=/api/pending_closures11392026/10/25 17:15:35 INFO Vacuumed table table=closures11402026/10/25 17:15:35 INFO Vacuumed table table=objects11412026/10/25 17:15:35 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001142--- PASS: TestService_createPendingClosureHandler (0.94s)1143=== CONT TestService_AuthMiddleware_OIDC11442026/10/25 17:15:35 INFO Aborted multipart uploads count=0 kept=011452026/10/25 17:15:35 WARN Force mode enabled - objects will be deleted immediately without grace period11462026/10/25 17:15:35 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011472026/10/25 17:15:35 INFO Vacuumed table table=pending_closures11482026/10/25 17:15:35 INFO Vacuumed table table=pending_objects11492026/10/25 17:15:35 INFO Vacuumed table table=multipart_uploads11502026/10/25 17:15:35 INFO Vacuumed table table=closures11512026/10/25 17:15:35 INFO Vacuumed table table=objects1152--- PASS: TestGCMetrics (0.56s)1153=== CONT TestCacheConfigHandler1154=== RUN TestCacheConfigHandler/full_config,_no_issuer1155=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1156=== RUN TestCacheConfigHandler/no_cache_url_configured1157=== PAUSE TestCacheConfigHandler/no_cache_url_configured1158=== RUN TestCacheConfigHandler/no_signing_keys1159=== PAUSE TestCacheConfigHandler/no_signing_keys1160=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1161=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1162=== CONT TestService_ReadScope_PublicByDefault11632026/10/25 17:15:35 INFO Aborted multipart uploads count=0 kept=011642026/10/25 17:15:35 WARN Force mode enabled - objects will be deleted immediately without grace period11652026/10/25 17:15:35 INFO Received uploads request method=POST path=/api/pending_closures11662026/10/25 17:15:35 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35983/oidc11672026/10/25 17:15:35 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."11682026/10/25 17:15:35 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1169--- PASS: TestFailedS3DeleteKeepsTombstone (0.92s)1170=== CONT TestService_RequireScope_OIDC1171=== NAME TestPinProtectsFromGC1172 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC590273862/001/store/43wc62bic8q2857chid76cd73d500gbg-pinned-file.txt1173 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC590273862/001/store/wgkv6dw2gddcxd59gr40pivwkjmil3vg-unpinned-file.txt11742026/10/25 17:15:35 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"1175--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.52s)1176=== CONT TestReadProxyInvalidPath11772026/10/25 17:15:35 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36107/oidc11782026/10/25 17:15:35 INFO lead: acquired remote=192.0.2.1:123411792026/10/25 17:15:35 INFO lead: acquired remote=192.0.2.1:123411802026/10/25 17:15:35 INFO lead: released remote=192.0.2.1:12341181--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.52s)1182=== CONT TestPresignedUploadRegisteredBeforeCommit1183--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.36s)1184=== CONT TestCompletedNarNotReofferedAcrossClosures11852026/10/25 17:15:35 INFO Aborted multipart uploads count=0 kept=011862026/10/25 17:15:35 INFO lead: acquired remote=192.0.2.1:123411872026/10/25 17:15:35 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=011882026/10/25 17:15:35 INFO Vacuumed table table=pending_closures11892026/10/25 17:15:35 INFO Vacuumed table table=pending_objects11902026/10/25 17:15:35 INFO Received push request method=POST path=/api/pushes11912026/10/25 17:15:35 INFO Vacuumed table table=multipart_uploads11922026/10/25 17:15:35 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11932026/10/25 17:15:35 INFO Uploading 43wc62bic8q2857chid76cd73d500gbg-pinned-file.txt (128B)11942026/10/25 17:15:35 INFO Vacuumed table table=closures11952026/10/25 17:15:35 INFO Vacuumed table table=objects11962026/10/25 17:15:35 WARN Failed to register uploaded object key=43wc62bic8q2857chid76cd73d500gbg.ls error="server returned 404: 404 page not found\n"11972026/10/25 17:15:35 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"11982026/10/25 17:15:35 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11992026/10/25 17:15:35 INFO Signed narinfos id=1 count=112002026/10/25 17:15:35 INFO Uploading 1 narinfos12012026/10/25 17:15:35 INFO Aborted multipart uploads count=0 kept=012022026/10/25 17:15:35 INFO Received complete push request method=POST path=/api/pushes/1/complete12032026/10/25 17:15:35 WARN Failed to register uploaded object key=43wc62bic8q2857chid76cd73d500gbg.narinfo error="server returned 404: 404 page not found\n"12042026/10/25 17:15:35 WARN Force mode enabled - objects will be deleted immediately without grace period12052026/10/25 17:15:35 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=01206--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (1.02s)1207=== CONT TestCompleteMultipartUpload_ErrorButObjectExists12082026/10/25 17:15:35 INFO Completed push id=1 objects=3 duration=19.625757ms12092026/10/25 17:15:35 INFO Upload complete. (68ms)12102026/10/25 17:15:35 INFO Vacuumed table table=pending_closures12112026/10/25 17:15:35 INFO Vacuumed table table=pending_objects12122026/10/25 17:15:35 INFO Vacuumed table table=multipart_uploads12132026/10/25 17:15:35 INFO Vacuumed table table=closures12142026/10/25 17:15:35 INFO Vacuumed table table=objects1215--- PASS: TestPushDedupSurvivesConcurrentGC (0.78s)1216=== CONT TestRedundantMultipartUpload1217--- PASS: TestCacheStatsHandler (0.34s)1218=== CONT TestPush_SignsNarinfosOfItsPendingObjects1219--- PASS: TestPushWaitsForSweepHoldingRow (1.08s)1220=== CONT TestPush_RejectsBadRequests12212026/10/25 17:15:35 INFO Received push request method=POST path=/api/pushes12222026/10/25 17:15:35 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12232026/10/25 17:15:35 INFO Uploading wgkv6dw2gddcxd59gr40pivwkjmil3vg-unpinned-file.txt (128B)12242026/10/25 17:15:35 WARN Failed to register uploaded object key=wgkv6dw2gddcxd59gr40pivwkjmil3vg.ls error="server returned 404: 404 page not found\n"12252026/10/25 17:15:35 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12262026/10/25 17:15:35 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"12272026/10/25 17:15:35 INFO Signed narinfos id=2 count=112282026/10/25 17:15:35 INFO Uploading 1 narinfos12292026/10/25 17:15:35 WARN Failed to register uploaded object key=wgkv6dw2gddcxd59gr40pivwkjmil3vg.narinfo error="server returned 404: 404 page not found\n"12302026/10/25 17:15:35 INFO Received complete push request method=POST path=/api/pushes/2/complete12312026/10/25 17:15:35 INFO Completed push id=2 objects=3 duration=3.22135ms12322026/10/25 17:15:35 INFO Upload complete. (50ms)1233--- PASS: TestGCBugBareHashReferences (0.74s)1234=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit12352026/10/25 17:15:35 INFO Starting cleanup of old closures method=DELETE path=/api/closures12362026/10/25 17:15:35 INFO Garbage collection started1237=== NAME TestClientMultipleUploads1238 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads3429318658/001/store/xpi1251k2l8w2g5z1kwhgx4iir3iyh6x-test-file-0.txt12392026/10/25 17:15:35 INFO Aborted multipart uploads count=0 kept=012402026/10/25 17:15:36 WARN Force mode enabled - objects will be deleted immediately without grace period1241--- PASS: TestService_ReadScope_PublicByDefault (0.28s)1242=== CONT TestPush_RootsAreLockedInByteOrder1243=== NAME TestClientIntegration1244 client_integration_test.go:286: Created store path: /build/TestClientIntegration2732544063/002/store/i3sgy509smi8lbx9frzmfghzcnqfih7q-test-file.txt1245=== NAME TestClientWithDependencies1246 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies3793930106/001/store/kw2rfzlg5sy3cb0kkqp6xbxxd6nk1l7p-test-script1247=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1248=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1249=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1250=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1251=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1252=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1253=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1254=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1255=== CONT TestPush_CompleteWaitsForCleanupOfThePush1256=== NAME TestClientMultipleUploads1257 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads3429318658/001/store/69lmxmjsf67bizf2wdflj4ab48zdzhjd-test-file-1.txt12582026/10/25 17:15:36 INFO Received uploads request method=POST path=/api/pending_closures12592026/10/25 17:15:36 INFO Received uploads request method=POST path=/api/pending_closures12602026/10/25 17:15:36 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)12612026/10/25 17:15:36 INFO Uploading 3bfvb4aswqzpzmpwh5gkq35nrhy94989-b (216B)12622026/10/25 17:15:36 INFO Uploading fxcb8ljmhaaligg3i8zqdmmpjdbq7irs-shared-dep (136B)1263=== NAME TestClientWithDependencies12642026/10/25 17:15:36 WARN Failed to register uploaded object key=fxcb8ljmhaaligg3i8zqdmmpjdbq7irs.ls error="server returned 404: 404 page not found\n"1265 client_integration_test.go:615: Found 1 dependencies (including self)12662026/10/25 17:15:36 WARN Failed to register uploaded object key=3bfvb4aswqzpzmpwh5gkq35nrhy94989.ls error="server returned 404: 404 page not found\n"12672026/10/25 17:15:36 WARN Failed to register uploaded object key=nbi4v3fmnzrpzabq5dsbcaj3gm7vcfdk.ls error="server returned 404: 404 page not found\n"1268--- PASS: TestReadProxyInvalidPath (0.27s)12692026/10/25 17:15:36 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"1270=== CONT TestPush_RepeatedRootCommitsOnce12712026/10/25 17:15:36 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12722026/10/25 17:15:36 WARN Failed to register uploaded object key=nar/1yjfmvsdgc9j0f96a9h7m6s5zywqx4sxzkzxpj8nk62ghwqrp318.nar.zst error="server returned 404: 404 page not found\n"12732026/10/25 17:15:36 INFO Signed narinfos id=1 count=212742026/10/25 17:15:36 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12752026/10/25 17:15:36 INFO Signed narinfos id=2 count=212762026/10/25 17:15:36 INFO Uploading 4 narinfos12772026/10/25 17:15:36 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=012782026/10/25 17:15:36 INFO Received push request method=POST path=/api/pushes12792026/10/25 17:15:36 WARN Failed to register uploaded object key=fxcb8ljmhaaligg3i8zqdmmpjdbq7irs.narinfo error="server returned 404: 404 page not found\n"12802026/10/25 17:15:36 WARN Failed to register uploaded object key=3bfvb4aswqzpzmpwh5gkq35nrhy94989.narinfo error="server returned 404: 404 page not found\n"12812026/10/25 17:15:36 WARN Failed to register uploaded object key=nbi4v3fmnzrpzabq5dsbcaj3gm7vcfdk.narinfo error="server returned 404: 404 page not found\n"12822026/10/25 17:15:36 INFO Received push request method=POST path=/api/pushes12832026/10/25 17:15:36 INFO Vacuumed table table=pending_closures12842026/10/25 17:15:36 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12852026/10/25 17:15:36 WARN Failed to register uploaded object key=fxcb8ljmhaaligg3i8zqdmmpjdbq7irs.narinfo error="server returned 404: 404 page not found\n"12862026/10/25 17:15:36 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)12872026/10/25 17:15:36 INFO Uploading glvdh0555j5k249f95368i4p662ch7sp-top (224B)12882026/10/25 17:15:36 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)12892026/10/25 17:15:36 INFO Uploading 1swf3xk0fpn0md0ailc31929rg66058j-a (216B)12902026/10/25 17:15:36 INFO Uploading dyalja01ykriz11q6f32zzjv5hazqdrr-shared-dep (136B)12912026/10/25 17:15:36 INFO Uploading a6bvjfpnqkmf65n8k6zmm66dfdd5gy0q-shared-dep (136B)12922026/10/25 17:15:36 INFO Vacuumed table table=pending_objects12932026/10/25 17:15:36 INFO Vacuumed table table=multipart_uploads12942026/10/25 17:15:36 INFO Completed upload id=1 objects=6 duration=4.648849ms12952026/10/25 17:15:36 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12962026/10/25 17:15:36 WARN Failed to register uploaded object key=dyalja01ykriz11q6f32zzjv5hazqdrr.ls error="server returned 404: 404 page not found\n"12972026/10/25 17:15:36 WARN Failed to register uploaded object key=01jjjla2glxxv5cr80cv6fqs959m6r23.ls error="server returned 404: 404 page not found\n"12982026/10/25 17:15:36 INFO Vacuumed table table=closures1299=== NAME TestClientMultipleUploads1300 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads3429318658/001/store/i61k8ivlwssv6hdfyy06zrjx3yzfb2si-test-file-2.txt13012026/10/25 17:15:36 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13022026/10/25 17:15:36 INFO Completed upload id=2 objects=6 duration=1.36424ms13032026/10/25 17:15:36 WARN Failed to register uploaded object key=nar/04wxz5b2ncz5sk7dc9kdsvrr2qbm6k213v34g95b0smg0k5p4b0x.nar.zst error="server returned 404: 404 page not found\n"13042026/10/25 17:15:36 WARN Failed to register uploaded object key=glvdh0555j5k249f95368i4p662ch7sp.ls error="server returned 404: 404 page not found\n"13052026/10/25 17:15:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13062026/10/25 17:15:36 WARN Failed to register uploaded object key=a6bvjfpnqkmf65n8k6zmm66dfdd5gy0q.ls error="server returned 404: 404 page not found\n"13072026/10/25 17:15:36 WARN Failed to register uploaded object key=nar/0n7d2s0b8259w8ynambigclcmf6b2i4r2dchqgb7l4hfzjdmv01a.nar.zst error="server returned 404: 404 page not found\n"13082026/10/25 17:15:36 INFO Upload complete. (71ms)13092026/10/25 17:15:36 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13102026/10/25 17:15:36 WARN Failed to register uploaded object key=1swf3xk0fpn0md0ailc31929rg66058j.ls error="server returned 404: 404 page not found\n"13112026/10/25 17:15:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13122026/10/25 17:15:36 INFO Signed narinfos id=1 count=313132026/10/25 17:15:36 INFO Uploading 3 narinfos13142026/10/25 17:15:36 INFO Signed narinfos id=1 count=21315=== NAME TestClientFallsBackToClosures1316 client_pushes_test.go:112: Retrieved narinfo from S3:1317 StorePath: /build/TestClientFallsBackToClosures2516630781/001/store/fxcb8ljmhaaligg3i8zqdmmpjdbq7irs-shared-dep1318 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst13192026/10/25 17:15:36 INFO Uploading 2 narinfos1320 Compression: zstd13212026/10/25 17:15:36 INFO Vacuumed table table=objects1322 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821323 NarSize: 1361324 References: 1325 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1326 client_pushes_test.go:112: Retrieved narinfo from S3:1327 StorePath: /build/TestClientFallsBackToClosures2516630781/001/store/nbi4v3fmnzrpzabq5dsbcaj3gm7vcfdk-a1328 URL: nar/1yjfmvsdgc9j0f96a9h7m6s5zywqx4sxzkzxpj8nk62ghwqrp318.nar.zst1329 Compression: zstd1330 NarHash: sha256:1yjfmvsdgc9j0f96a9h7m6s5zywqx4sxzkzxpj8nk62ghwqrp3181331 NarSize: 2161332 References: /build/TestClientFallsBackToClosures2516630781/001/store/fxcb8ljmhaaligg3i8zqdmmpjdbq7irs-shared-dep1333 CA: text:sha256:1klhd475600d9glrcfsn7s23jngyp3va8j400rmkx91jykwqgyw313342026/10/25 17:15:36 WARN Failed to register uploaded object key=a6bvjfpnqkmf65n8k6zmm66dfdd5gy0q.narinfo error="server returned 404: 404 page not found\n"1335 client_pushes_test.go:112: Retrieved narinfo from S3:1336 StorePath: /build/TestClientFallsBackToClosures2516630781/001/store/3bfvb4aswqzpzmpwh5gkq35nrhy94989-b1337 URL: nar/1yjfmvsdgc9j0f96a9h7m6s5zywqx4sxzkzxpj8nk62ghwqrp318.nar.zst1338 Compression: zstd1339 NarHash: sha256:1yjfmvsdgc9j0f96a9h7m6s5zywqx4sxzkzxpj8nk62ghwqrp3181340 NarSize: 2161341 References: /build/TestClientFallsBackToClosures2516630781/001/store/fxcb8ljmhaaligg3i8zqdmmpjdbq7irs-shared-dep13422026/10/25 17:15:36 WARN Failed to register uploaded object key=dyalja01ykriz11q6f32zzjv5hazqdrr.narinfo error="server returned 404: 404 page not found\n"1343 CA: text:sha256:1klhd475600d9glrcfsn7s23jngyp3va8j400rmkx91jykwqgyw313442026/10/25 17:15:36 INFO Received complete push request method=POST path=/api/pushes/1/complete13452026/10/25 17:15:36 WARN Failed to register uploaded object key=01jjjla2glxxv5cr80cv6fqs959m6r23.narinfo error="server returned 404: 404 page not found\n"13462026/10/25 17:15:36 WARN Failed to register uploaded object key=glvdh0555j5k249f95368i4p662ch7sp.narinfo error="server returned 404: 404 page not found\n"13472026/10/25 17:15:36 INFO Received complete push request method=POST path=/api/pushes/1/complete13482026/10/25 17:15:36 WARN Failed to register uploaded object key=1swf3xk0fpn0md0ailc31929rg66058j.narinfo error="server returned 404: 404 page not found\n"1349--- PASS: TestClientFallsBackToClosures (0.55s)1350=== CONT TestPush_CompleteCommitsEveryRoot1351=== RUN TestService_RequireScope_OIDC/builder_may_write1352=== PAUSE TestService_RequireScope_OIDC/builder_may_write1353=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1354=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1355=== RUN TestService_RequireScope_OIDC/ops_may_admin1356=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1357=== RUN TestService_RequireScope_OIDC/ops_may_not_write1358=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1359=== RUN TestService_RequireScope_OIDC/reader_may_not_write1360=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1361=== RUN TestService_RequireScope_OIDC/static_token_may_admin1362=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1363=== RUN TestService_RequireScope_OIDC/static_token_may_write1364=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1365=== RUN TestService_RequireScope_OIDC/reader_may_read1366=== PAUSE TestService_RequireScope_OIDC/reader_may_read1367=== RUN TestService_RequireScope_OIDC/writer_implies_read1368=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1369=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1370=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1371=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1372=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1373=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1374=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1375=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1376=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1377=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1378=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1379=== CONT TestPush_OverlappingRootsStoreOneRowPerKey13802026/10/25 17:15:36 INFO Completed push id=1 objects=8 duration=6.863419ms13812026/10/25 17:15:36 INFO Upload complete. (60ms)1382=== NAME TestClientCADerivations1383 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations3435203991/001/store/zkfm08d667zzq25sjyswca64fw3w9bwa-ca-test1384=== NAME TestClientPushesUseOnePush1385 client_pushes_test.go:97: Retrieved narinfo from S3:1386 StorePath: /build/TestClientPushesUseOnePush2269773485/001/store/a6bvjfpnqkmf65n8k6zmm66dfdd5gy0q-shared-dep1387 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1388 Compression: zstd1389 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821390 NarSize: 1361391 References: 1392 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n13932026/10/25 17:15:36 INFO Received push request method=POST path=/api/pushes13942026/10/25 17:15:36 INFO Completed push id=1 objects=6 duration=9.818498ms13952026/10/25 17:15:36 INFO Upload complete. (56ms)1396 client_pushes_test.go:97: Retrieved narinfo from S3:1397 StorePath: /build/TestClientPushesUseOnePush2269773485/001/store/1swf3xk0fpn0md0ailc31929rg66058j-a1398 URL: nar/0n7d2s0b8259w8ynambigclcmf6b2i4r2dchqgb7l4hfzjdmv01a.nar.zst1399 Compression: zstd1400 NarHash: sha256:0n7d2s0b8259w8ynambigclcmf6b2i4r2dchqgb7l4hfzjdmv01a1401 NarSize: 2161402 References: /build/TestClientPushesUseOnePush2269773485/001/store/a6bvjfpnqkmf65n8k6zmm66dfdd5gy0q-shared-dep1403 CA: text:sha256:15853jnvvfbqhs2qy04nlns7s46kpnf5az63iknl640vmjkkrg6n1404=== NAME TestClientSharedPathCommittedMidPush1405 client_integration_test.go:680: Retrieved narinfo from S3:1406 StorePath: /build/TestClientSharedPathCommittedMidPush3215449292/001/store/dyalja01ykriz11q6f32zzjv5hazqdrr-shared-dep1407 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1408 Compression: zstd1409 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821410 NarSize: 1361411 References: 1412 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1413=== NAME TestClientPushesUseOnePush1414 client_pushes_test.go:97: Retrieved narinfo from S3:1415 StorePath: /build/TestClientPushesUseOnePush2269773485/001/store/01jjjla2glxxv5cr80cv6fqs959m6r23-b1416 URL: nar/0n7d2s0b8259w8ynambigclcmf6b2i4r2dchqgb7l4hfzjdmv01a.nar.zst1417 Compression: zstd1418 NarHash: sha256:0n7d2s0b8259w8ynambigclcmf6b2i4r2dchqgb7l4hfzjdmv01a1419 NarSize: 2161420 References: /build/TestClientPushesUseOnePush2269773485/001/store/a6bvjfpnqkmf65n8k6zmm66dfdd5gy0q-shared-dep1421 CA: text:sha256:15853jnvvfbqhs2qy04nlns7s46kpnf5az63iknl640vmjkkrg6n1422=== NAME TestClientSharedPathCommittedMidPush14232026/10/25 17:15:36 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)1424 client_integration_test.go:680: Retrieved narinfo from S3:1425 StorePath: /build/TestClientSharedPathCommittedMidPush3215449292/001/store/glvdh0555j5k249f95368i4p662ch7sp-top14262026/10/25 17:15:36 INFO Uploading i3sgy509smi8lbx9frzmfghzcnqfih7q-test-file.txt (152B)1427 URL: nar/04wxz5b2ncz5sk7dc9kdsvrr2qbm6k213v34g95b0smg0k5p4b0x.nar.zst1428 Compression: zstd1429 NarHash: sha256:04wxz5b2ncz5sk7dc9kdsvrr2qbm6k213v34g95b0smg0k5p4b0x1430 NarSize: 2241431 References: /build/TestClientSharedPathCommittedMidPush3215449292/001/store/dyalja01ykriz11q6f32zzjv5hazqdrr-shared-dep1432 CA: text:sha256:1qdn6l8fsg34zndxi3y0g3rlzyc52b6fmm8b8877ngsw6pd4hdwr1433--- PASS: TestClientPushesUseOnePush (0.55s)1434=== CONT TestReadRedirectUsesPublicS3URL1435--- PASS: TestClientSharedPathCommittedMidPush (0.51s)1436=== CONT TestReadProxyRangeRequest14372026/10/25 17:15:36 INFO Received uploads request method=POST path=/api/pending_closures14382026/10/25 17:15:36 WARN Failed to register uploaded object key=i3sgy509smi8lbx9frzmfghzcnqfih7q.ls error="server returned 404: 404 page not found\n"14392026/10/25 17:15:36 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"14402026/10/25 17:15:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14412026/10/25 17:15:36 INFO Signed narinfos id=1 count=114422026/10/25 17:15:36 INFO Uploading 1 narinfos14432026/10/25 17:15:36 INFO Received complete push request method=POST path=/api/pushes/1/complete14442026/10/25 17:15:36 WARN Failed to register uploaded object key=i3sgy509smi8lbx9frzmfghzcnqfih7q.narinfo error="server returned 404: 404 page not found\n"14452026/10/25 17:15:36 INFO Completed push id=1 objects=3 duration=6.440839ms14462026/10/25 17:15:36 INFO Upload complete. (55ms)1447=== NAME TestClientCADerivations1448 client_ca_test.go:139: Found 1 dependencies (including self)14492026/10/25 17:15:36 INFO Received uploads request method=POST path=/api/pending_closures14502026/10/25 17:15:36 INFO Received push request method=POST path=/api/pushes14512026/10/25 17:15:36 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14522026/10/25 17:15:36 INFO Uploading kw2rfzlg5sy3cb0kkqp6xbxxd6nk1l7p-test-script (136B)14532026/10/25 17:15:36 WARN Failed to register uploaded object key=kw2rfzlg5sy3cb0kkqp6xbxxd6nk1l7p.ls error="server returned 404: 404 page not found\n"14542026/10/25 17:15:36 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"14552026/10/25 17:15:36 WARN Failed to register uploaded object key=log/qfszmf2zpskkiwmmvy68yaa9dvxy7x5v-test-script.drv error="server returned 404: 404 page not found\n"14562026/10/25 17:15:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14572026/10/25 17:15:36 INFO Received uploads request method=POST path=/api/pending_closures14582026/10/25 17:15:36 INFO Signed narinfos id=1 count=114592026/10/25 17:15:36 INFO Uploading 1 narinfos14602026/10/25 17:15:36 INFO Received push request method=POST path=/api/pushes14612026/10/25 17:15:36 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst14622026/10/25 17:15:36 INFO All 1 paths already cached14632026/10/25 17:15:36 INFO Received uploads request method=POST path=/api/pending_closures14642026/10/25 17:15:36 INFO Received complete push request method=POST path=/api/pushes/1/complete14652026/10/25 17:15:36 WARN Failed to register uploaded object key=kw2rfzlg5sy3cb0kkqp6xbxxd6nk1l7p.narinfo error="server returned 404: 404 page not found\n"1466=== NAME TestClientIntegration1467 client_integration_test.go:312: Retrieved narinfo from S3:1468 StorePath: /build/TestClientIntegration2732544063/002/store/i3sgy509smi8lbx9frzmfghzcnqfih7q-test-file.txt1469 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1470 Compression: zstd1471 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11472 NarSize: 1521473 References: 1474 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11475 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)14762026/10/25 17:15:36 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)1477 client_integration_test.go:313: Decompressed .ls content (64 bytes):14782026/10/25 17:15:36 INFO Uploading i61k8ivlwssv6hdfyy06zrjx3yzfb2si-test-file-2.txt (160B)1479 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}14802026/10/25 17:15:36 INFO Uploading 69lmxmjsf67bizf2wdflj4ab48zdzhjd-test-file-1.txt (160B)1481 client_integration_test.go:316: Testing garbage collection...14822026/10/25 17:15:36 INFO Uploading xpi1251k2l8w2g5z1kwhgx4iir3iyh6x-test-file-0.txt (160B)1483--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.35s)1484=== CONT TestReadRedirectKeepsNarinfoProxied14852026/10/25 17:15:36 INFO Completed push id=1 objects=4 duration=18.530127ms14862026/10/25 17:15:36 INFO Upload complete. (84ms)1487=== NAME TestClientWithDependencies1488 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies3793930106/001/store) requires matching store prefix1489--- PASS: TestClientWithDependencies (0.57s)1490=== CONT TestReadRedirectNar14912026/10/25 17:15:36 WARN Failed to register uploaded object key=69lmxmjsf67bizf2wdflj4ab48zdzhjd.ls error="server returned 404: 404 page not found\n"14922026/10/25 17:15:36 WARN Failed to register uploaded object key=xpi1251k2l8w2g5z1kwhgx4iir3iyh6x.ls error="server returned 404: 404 page not found\n"14932026/10/25 17:15:36 WARN Failed to register uploaded object key=i61k8ivlwssv6hdfyy06zrjx3yzfb2si.ls error="server returned 404: 404 page not found\n"14942026/10/25 17:15:36 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"14952026/10/25 17:15:36 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"14962026/10/25 17:15:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14972026/10/25 17:15:36 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"14982026/10/25 17:15:36 INFO Signed narinfos id=1 count=314992026/10/25 17:15:36 INFO Uploading 3 narinfos15002026/10/25 17:15:36 INFO Starting cleanup of old closures method=DELETE path=/api/closures15012026/10/25 17:15:36 INFO Garbage collection started15022026/10/25 17:15:36 WARN Failed to register uploaded object key=i61k8ivlwssv6hdfyy06zrjx3yzfb2si.narinfo error="server returned 404: 404 page not found\n"15032026/10/25 17:15:36 WARN Failed to register uploaded object key=xpi1251k2l8w2g5z1kwhgx4iir3iyh6x.narinfo error="server returned 404: 404 page not found\n"15042026/10/25 17:15:36 INFO Received complete push request method=POST path=/api/pushes/1/complete15052026/10/25 17:15:36 WARN Failed to register uploaded object key=69lmxmjsf67bizf2wdflj4ab48zdzhjd.narinfo error="server returned 404: 404 page not found\n"15062026/10/25 17:15:36 INFO Received push request method=POST path=/api/pushes15072026/10/25 17:15:36 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15082026/10/25 17:15:36 INFO Uploading zkfm08d667zzq25sjyswca64fw3w9bwa-ca-test (144B)15092026/10/25 17:15:36 INFO Completed push id=1 objects=9 duration=54.630761ms15102026/10/25 17:15:36 INFO Upload complete. (165ms)1511=== NAME TestClientMultipleUploads1512 client_integration_test.go:369: Uploaded 3 paths in 196.700429ms15132026/10/25 17:15:36 INFO Received uploads request method=POST path=/api/pending_closures15142026/10/25 17:15:36 WARN Failed to register uploaded object key=zkfm08d667zzq25sjyswca64fw3w9bwa.ls error="server returned 404: 404 page not found\n"15152026/10/25 17:15:36 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"15162026/10/25 17:15:36 WARN Failed to register uploaded object key=log/yd5pjgpk87q9r01ysk18mbs0pi237gnf-ca-test.drv error="server returned 404: 404 page not found\n"15172026/10/25 17:15:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15182026/10/25 17:15:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15192026/10/25 17:15:36 INFO Signed narinfos id=1 count=115202026/10/25 17:15:36 INFO Uploading 1 narinfos15212026/10/25 17:15:36 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZTA0MTY3MGQtYjk0Ny00MGQwLWI5YmMtZDI3YjhhM2VkMzI1LjUzNGRhNGMwLTA2MTAtNDM3Yy05OWE5LTkxZDhlOWEzOGM5ZngxNzkyOTQ4NTM2MTM4OTQ2MTQx15222026/10/25 17:15:36 INFO Received complete push request method=POST path=/api/pushes/1/complete15232026/10/25 17:15:36 WARN Failed to register uploaded object key=zkfm08d667zzq25sjyswca64fw3w9bwa.narinfo error="server returned 404: 404 page not found\n"1524--- PASS: TestClientMultipleUploads (0.67s)1525=== CONT TestReadProxyDisabled15262026/10/25 17:15:36 INFO Aborted multipart uploads count=0 kept=015272026/10/25 17:15:36 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZTA0MTY3MGQtYjk0Ny00MGQwLWI5YmMtZDI3YjhhM2VkMzI1LjUzNGRhNGMwLTA2MTAtNDM3Yy05OWE5LTkxZDhlOWEzOGM5ZngxNzkyOTQ4NTM2MTM4OTQ2MTQx parts=115282026/10/25 17:15:36 INFO Completed push id=1 objects=4 duration=6.879059ms1529--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.42s)15302026/10/25 17:15:36 INFO Upload complete. (135ms)1531=== CONT TestReadProxyRootRedirectsToIndexHTML15322026/10/25 17:15:36 INFO Received uploads request method=POST path=/api/pending_closures15332026/10/25 17:15:36 WARN Force mode enabled - objects will be deleted immediately without grace period1534=== NAME TestClientCADerivations1535 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations3435203991/001/store/zkfm08d667zzq25sjyswca64fw3w9bwa-ca-test1536 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1537 Compression: zstd1538 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1539 NarSize: 1441540 References: 1541 Deriver: /build/TestClientCADerivations3435203991/001/store/yd5pjgpk87q9r01ysk18mbs0pi237gnf-ca-test.drv1542 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1543 client_ca_test.go:185: Checking for realisation files in S3...1544 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1545 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache15462026/10/25 17:15:36 INFO Received push request method=POST path=/api/pushes15472026/10/25 17:15:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15482026/10/25 17:15:36 INFO Signed narinfos id=1 count=115492026/10/25 17:15:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15502026/10/25 17:15:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15512026/10/25 17:15:36 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"15522026/10/25 17:15:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15532026/10/25 17:15:36 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"15542026/10/25 17:15:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15552026/10/25 17:15:36 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=115562026/10/25 17:15:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15572026/10/25 17:15:36 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1558--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.40s)1559=== CONT TestReadProxyConditionalGet1560=== RUN TestPush_RejectsBadRequests/no_roots1561=== PAUSE TestPush_RejectsBadRequests/no_roots1562=== RUN TestPush_RejectsBadRequests/no_objects1563=== PAUSE TestPush_RejectsBadRequests/no_objects1564=== RUN TestPush_RejectsBadRequests/bad_root1565=== PAUSE TestPush_RejectsBadRequests/bad_root1566=== RUN TestPush_RejectsBadRequests/root_not_in_objects1567=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1568=== CONT TestReadProxyOutlastsServerWriteTimeout15692026/10/25 17:15:36 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=015702026/10/25 17:15:36 INFO Received push request method=POST path=/api/pushes15712026/10/25 17:15:36 INFO Vacuumed table table=pending_closures15722026/10/25 17:15:36 INFO Vacuumed table table=pending_objects15732026/10/25 17:15:36 INFO Vacuumed table table=multipart_uploads15742026/10/25 17:15:36 INFO Vacuumed table table=closures15752026/10/25 17:15:36 INFO Received complete push request method=POST path=/api/pushes/1/complete15762026/10/25 17:15:36 INFO Vacuumed table table=objects15772026/10/25 17:15:36 INFO Received push request method=POST path=/api/pushes15782026/10/25 17:15:36 INFO Completed push id=1 objects=4 duration=8.208989ms15792026/10/25 17:15:36 INFO Received push request method=POST path=/api/pushes15802026/10/25 17:15:36 INFO Received push request method=POST path=/api/pushes15812026/10/25 17:15:36 INFO Received push request method=POST path=/api/pushes15822026-10-25 17:15:36.407 UTC [1591] ERROR: could not obtain lock on row in relation "closures"15832026-10-25 17:15:36.407 UTC [1591] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT15842026-10-25 17:15:36.407 UTC [1591] ERROR: could not obtain lock on row in relation "closures"15852026-10-25 17:15:36.407 UTC [1591] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT15862026-10-25 17:15:36.407 UTC [1591] ERROR: could not obtain lock on row in relation "closures"15872026-10-25 17:15:36.407 UTC [1591] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT15882026-10-25 17:15:36.407 UTC [1591] ERROR: could not obtain lock on row in relation "closures"15892026-10-25 17:15:36.407 UTC [1591] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT15902026-10-25 17:15:36.408 UTC [1591] ERROR: could not obtain lock on row in relation "closures"15912026-10-25 17:15:36.408 UTC [1591] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1592--- PASS: TestPush_RootsAreLockedInByteOrder (0.40s)1593=== CONT TestReadProxyHead15942026/10/25 17:15:36 INFO Received complete push request method=POST path=/api/pushes/1/complete15952026/10/25 17:15:36 INFO Aborted multipart uploads count=0 kept=015962026/10/25 17:15:36 WARN Force mode enabled - objects will be deleted immediately without grace period15972026/10/25 17:15:36 INFO Received push request method=POST path=/api/pushes15982026/10/25 17:15:36 INFO Completed push id=1 objects=4 duration=7.667159ms1599--- PASS: TestPush_RepeatedRootCommitsOnce (0.38s)1600=== CONT TestCreatePin_ReservedPins16012026/10/25 17:15:36 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=016022026/10/25 17:15:36 INFO Vacuumed table table=pending_closures16032026/10/25 17:15:36 INFO Vacuumed table table=pending_objects1604--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.37s)1605=== CONT TestReadProxy40416062026/10/25 17:15:36 INFO Vacuumed table table=multipart_uploads16072026/10/25 17:15:36 INFO Vacuumed table table=closures16082026/10/25 17:15:36 INFO Vacuumed table table=objects16092026/10/25 17:15:36 INFO Received push request method=POST path=/api/pushes16102026/10/25 17:15:36 INFO Received complete push request method=POST path=/api/pushes/2/complete16112026/10/25 17:15:36 INFO Completed push id=2 objects=4 duration=4.766549ms1612--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.48s)1613=== CONT TestReadProxyNarStreaming16142026/10/25 17:15:36 INFO Received complete push request method=POST path=/api/pushes/1/complete1615=== NAME TestClientCADerivations1616 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1617 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1618 error: binary cache 's3://bucket45?endpoint=http://localhost:39821®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations3435203991/001/store'1619 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11620--- PASS: TestClientCADerivations (0.81s)1621=== CONT TestReadProxyContentNegotiation16222026/10/25 17:15:36 INFO Completed push id=1 objects=6 duration=7.462969ms1623--- PASS: TestPush_CompleteCommitsEveryRoot (0.40s)1624=== CONT TestReadProxyNarinfoAlreadyDecompressed1625--- PASS: TestReadRedirectUsesPublicS3URL (0.41s)1626=== CONT TestReadProxyNarinfo16272026/10/25 17:15:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45037/oidc1628--- PASS: TestReadProxyRangeRequest (0.42s)1629=== CONT TestIsValidCachePath1630=== RUN TestIsValidCachePath/narinfo1631=== PAUSE TestIsValidCachePath/narinfo1632=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1633=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1634=== RUN TestIsValidCachePath/nar_zst1635=== PAUSE TestIsValidCachePath/nar_zst1636=== RUN TestIsValidCachePath/nar_xz1637=== PAUSE TestIsValidCachePath/nar_xz1638=== RUN TestIsValidCachePath/nar_bz21639=== PAUSE TestIsValidCachePath/nar_bz21640=== RUN TestIsValidCachePath/nar_uncompressed1641=== PAUSE TestIsValidCachePath/nar_uncompressed1642=== RUN TestIsValidCachePath/ls1643=== PAUSE TestIsValidCachePath/ls1644=== RUN TestIsValidCachePath/log1645=== PAUSE TestIsValidCachePath/log1646=== RUN TestIsValidCachePath/realisation1647=== PAUSE TestIsValidCachePath/realisation1648=== RUN TestIsValidCachePath/nix-cache-info1649=== PAUSE TestIsValidCachePath/nix-cache-info1650=== RUN TestIsValidCachePath/index.html1651=== PAUSE TestIsValidCachePath/index.html1652=== RUN TestIsValidCachePath/traversal_parent1653=== PAUSE TestIsValidCachePath/traversal_parent1654=== RUN TestIsValidCachePath/traversal_in_middle1655=== PAUSE TestIsValidCachePath/traversal_in_middle1656=== RUN TestIsValidCachePath/invalid_char_e1657=== PAUSE TestIsValidCachePath/invalid_char_e1658=== RUN TestIsValidCachePath/invalid_char_u1659=== PAUSE TestIsValidCachePath/invalid_char_u1660=== RUN TestIsValidCachePath/random_path1661=== PAUSE TestIsValidCachePath/random_path1662=== RUN TestIsValidCachePath/empty1663=== PAUSE TestIsValidCachePath/empty1664=== RUN TestIsValidCachePath/leading_slash1665=== PAUSE TestIsValidCachePath/leading_slash1666=== RUN TestIsValidCachePath/wrong_extension1667=== PAUSE TestIsValidCachePath/wrong_extension1668=== RUN TestIsValidCachePath/short_hash1669=== PAUSE TestIsValidCachePath/short_hash1670=== CONT TestParseSingleRange1671=== RUN TestParseSingleRange/none1672=== PAUSE TestParseSingleRange/none1673=== RUN TestParseSingleRange/unknown_unit1674=== PAUSE TestParseSingleRange/unknown_unit1675=== RUN TestParseSingleRange/multi-range_ignored1676=== PAUSE TestParseSingleRange/multi-range_ignored1677=== RUN TestParseSingleRange/malformed_no_dash1678=== PAUSE TestParseSingleRange/malformed_no_dash1679=== RUN TestParseSingleRange/malformed_both_empty1680=== PAUSE TestParseSingleRange/malformed_both_empty1681=== RUN TestParseSingleRange/malformed_end_before_start1682=== PAUSE TestParseSingleRange/malformed_end_before_start1683=== RUN TestParseSingleRange/closed1684=== PAUSE TestParseSingleRange/closed1685=== RUN TestParseSingleRange/open-ended1686=== PAUSE TestParseSingleRange/open-ended1687=== RUN TestParseSingleRange/end_clamped_to_size1688=== PAUSE TestParseSingleRange/end_clamped_to_size1689=== RUN TestParseSingleRange/suffix1690=== PAUSE TestParseSingleRange/suffix1691=== RUN TestParseSingleRange/suffix_exceeds_size1692=== PAUSE TestParseSingleRange/suffix_exceeds_size1693=== RUN TestParseSingleRange/single_byte1694=== PAUSE TestParseSingleRange/single_byte1695=== RUN TestParseSingleRange/start_past_EOF1696=== PAUSE TestParseSingleRange/start_past_EOF1697=== RUN TestParseSingleRange/start_far_past_EOF1698=== PAUSE TestParseSingleRange/start_far_past_EOF1699=== CONT TestPresentNotReportedWhileGCDeletesClosure1700=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1701=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1702=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1703=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1704=== CONT TestPresentRefreshesOnlyStaleClosures1705--- PASS: TestReadRedirectKeepsNarinfoProxied (0.39s)1706=== CONT TestPresentReportsOnlyClosureRoots1707--- PASS: TestReadRedirectNar (0.39s)1708=== CONT TestService_AuthMiddleware_MTLSProxyHeader1709--- PASS: TestReadProxyDisabled (0.30s)1710=== CONT TestPendingCleanupUsesOneCutoff17112026/10/25 17:15:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1712--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.32s)1713=== CONT TestOrphanedObjectsGCStressTest17142026/10/25 17:15:36 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZTA0MTY3MGQtYjk0Ny00MGQwLWI5YmMtZDI3YjhhM2VkMzI1Ljk2OWMzMmNhLTE4ZmUtNGUzNi1iNzMzLTdiNWMzZWUzNTE5ZHgxNzkyOTQ4NTM2MDkyMDMzMzE4 parts=1217152026/10/25 17:15:36 INFO Received uploads request method=POST path=/api/pending_closures1716--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.80s)1717=== CONT TestOrphanedObjectsGC1718--- PASS: TestReadProxyConditionalGet (0.33s)1719=== CONT TestObjectStatsUpdatedOncePerCommit17202026/10/25 17:15:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1721--- PASS: TestReadProxyHead (0.24s)1722=== CONT TestObjectStatsTrigger17232026/10/25 17:15:36 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZTA0MTY3MGQtYjk0Ny00MGQwLWI5YmMtZDI3YjhhM2VkMzI1Ljc2NGRmYmZmLWE1OWYtNDE1ZS04NWQ1LWY0OWRiYjcwZWU5OHgxNzkyOTQ4NTM2MjY4NzAzNTgx parts=1217242026/10/25 17:15:36 INFO Received uploads request method=POST path=/api/pending_closures1725--- PASS: TestReadProxyNarStreaming (0.24s)1726=== CONT TestServerTLSConfig1727=== RUN TestServerTLSConfig/no_client_CA1728=== PAUSE TestServerTLSConfig/no_client_CA1729=== RUN TestServerTLSConfig/missing_CA_file1730=== PAUSE TestServerTLSConfig/missing_CA_file1731=== RUN TestServerTLSConfig/not_a_PEM_file1732=== PAUSE TestServerTLSConfig/not_a_PEM_file1733=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded17342026/10/25 17:15:36 INFO Received uploads request method=POST path=/api/pending_closures17352026-10-25 17:15:36.707 UTC [1596] ERROR: Push does not exist: id=117362026-10-25 17:15:36.707 UTC [1596] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE17372026-10-25 17:15:36.707 UTC [1596] STATEMENT: SELECT commit_push($1)1738--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (0.68s)1739=== CONT TestMultipartCleanup1740--- PASS: TestReadProxy404 (0.27s)1741=== CONT TestService_ReadAuthMiddleware1742--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.26s)1743=== CONT TestService_NativeMTLS1744--- PASS: TestReadProxyContentNegotiation (0.28s)1745=== CONT TestMetricsCommit17462026/10/25 17:15:36 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux17472026/10/25 17:15:36 WARN Refused reserved pin name=worker-x86_64-linux17482026/10/25 17:15:36 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux17492026/10/25 17:15:36 INFO Received create pin request method=POST path=/api/pins/my-app17502026/10/25 17:15:36 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1751--- PASS: TestCreatePin_ReservedPins (0.33s)1752=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1753--- PASS: TestPresentRefreshesOnlyStaleClosures (0.30s)1754=== CONT TestPendingClosureWriteTimeout/empty1755=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17562026/10/25 17:15:36 INFO Received uploads request method=POST path=/1757=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17582026/10/25 17:15:36 INFO Received request for more parts method=POST path=/1759=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17602026/10/25 17:15:36 INFO Received complete multipart upload request method=POST path=/1761=== CONT TestPendingClosureWriteTimeout/670k_objects1762=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17632026/10/25 17:15:36 INFO Received uploads request method=POST path=/1764--- PASS: TestUploadHandlersRejectInvalidKeys (0.07s)1765 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1766 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1767 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1768 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1769=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1770--- PASS: TestPresentReportsOnlyClosureRoots (0.30s)1771=== CONT TestPendingClosureWriteTimeout/400_objects1772=== CONT TestProxyWriteTimeout/narinfo1773=== CONT TestProxyWriteTimeout/10_GiB_nar1774=== CONT TestProxyWriteTimeout/unknown_size1775=== CONT TestProxyWriteTimeout/1_GiB_nar1776--- PASS: TestProxyWriteTimeout (0.07s)1777 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1778 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1779 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1780 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1781=== CONT TestGCEndsOnShutdown/before_the_run17822026/10/25 17:15:36 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1783--- PASS: TestReadProxyNarinfo (0.38s)1784=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark17852026/10/25 17:15:36 INFO lead: released remote=192.0.2.1:12341786--- PASS: TestLeadEndsOnShutdown (1.62s)1787=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1788--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.36s)1789=== CONT TestIsValidUploadKey/narinfo1790=== CONT TestIsValidUploadKey/realisation_plus_in_output1791=== CONT TestIsValidUploadKey/unknown_type1792=== CONT TestIsValidUploadKey/empty_key1793=== CONT TestIsValidUploadKey/absolute1794=== CONT TestIsValidUploadKey/traversal_nar1795=== CONT TestIsValidUploadKey/traversal1796=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1797=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1798=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1799=== CONT TestIsValidUploadKey/index.html1800=== CONT TestIsValidUploadKey/nix-cache-info1801=== CONT TestIsValidUploadKey/build_log_home-manager_file1802=== CONT TestIsValidUploadKey/realisation1803=== CONT TestIsValidUploadKey/build_log_equals1804=== CONT TestIsValidUploadKey/build_log_question_mark1805=== CONT TestIsValidUploadKey/build_log_plus_in_name1806=== CONT TestIsValidUploadKey/nar_plain1807=== CONT TestIsValidUploadKey/build_log1808=== CONT TestIsValidUploadKey/listing1809=== CONT TestIsValidUploadKey/nar_xz1810=== CONT TestIsValidUploadKey/nar_zst1811--- PASS: TestIsValidUploadKey (0.07s)1812 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1813 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1814 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1815 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1816 --- PASS: TestIsValidUploadKey/absolute (0.00s)1817 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1818 --- PASS: TestIsValidUploadKey/traversal (0.00s)1819 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1820 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1821 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1822 --- PASS: TestIsValidUploadKey/index.html (0.00s)1823 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1824 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1825 --- PASS: TestIsValidUploadKey/realisation (0.00s)1826 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1827 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1828 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1829 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1830 --- PASS: TestIsValidUploadKey/build_log (0.00s)1831 --- PASS: TestIsValidUploadKey/listing (0.00s)1832 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1833 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1834=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows18352026/10/25 17:15:36 INFO Received uploads request method=POST path=/api/pending_closures18362026/10/25 17:15:36 INFO Received uploads request method=POST path=/api/pending_closures1837--- PASS: TestDeleteClosuresRacingPins (1.49s)1838=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check18392026/10/25 17:15:36 INFO Received cleanup request method=DELETE path=/api/pending_closures18402026/10/25 17:15:37 INFO lead: released remote=192.0.2.1:123418412026/10/25 17:15:37 INFO lead: acquired remote=192.0.2.1:12341842--- PASS: TestObjectStatsTrigger (0.42s)1843=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18442026/10/25 17:15:37 INFO Received uploads request method=POST path=/1845--- PASS: TestObjectStatsUpdatedOncePerCommit (0.45s)18462026/10/25 17:15:37 INFO Received uploads request method=POST path=/api/pending_closures1847=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18482026/10/25 17:15:37 INFO Received request for more parts method=POST path=/1849--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.41s)1850=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18512026/10/25 17:15:37 INFO Received complete multipart upload request method=POST path=/1852--- PASS: TestService_ReadAuthMiddleware (0.39s)1853=== CONT TestResolveDBConnectionString/flag_wins1854=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1855=== CONT TestResolveDBConnectionString/nothing_configured1856=== CONT TestResolveDBConnectionString/missing_file_is_an_error1857=== CONT TestResolveDBConnectionString/file_when_flag_empty1858=== CONT TestClientErrorHandling/InvalidStorePath1859--- PASS: TestResolveDBConnectionString (0.00s)1860 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1861 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1862 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1863 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1864 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1865=== CONT TestClientErrorHandling/ServerNotAvailable18662026/10/25 17:15:37 INFO Received uploads request method=POST path=/api/pending_closures1867=== CONT TestClientErrorHandling/InvalidAuthToken18682026/10/25 17:15:37 WARN mTLS auth: subject not in bound subjects subject="CN=reader"18692026/10/25 17:15:37 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1870--- PASS: TestService_NativeMTLS (0.42s)1871=== CONT TestCacheConfigHandler/full_config,_no_issuer1872=== CONT TestCacheConfigHandler/no_signing_keys1873=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1874=== CONT TestCacheConfigHandler/no_cache_url_configured1875--- PASS: TestCacheConfigHandler (0.00s)1876 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1877 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1878 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1879 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1880=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1881=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected18822026/10/25 17:15:37 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]1883=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected18842026/10/25 17:15:37 WARN Authentication failed token_preview=eyJhbGciOi...6cTTPc5aKw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1885=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1886=== CONT TestService_RequireScope_OIDC/builder_may_write1887--- PASS: TestService_AuthMiddleware_OIDC (0.32s)1888 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1889 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1890 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1891 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1892=== CONT TestService_RequireScope_OIDC/reader_may_read1893=== CONT TestService_RequireScope_OIDC/static_token_may_write1894=== CONT TestService_RequireScope_OIDC/static_token_may_admin1895=== CONT TestService_RequireScope_OIDC/reader_may_not_write1896=== CONT TestService_RequireScope_OIDC/ops_may_not_write1897=== CONT TestService_RequireScope_OIDC/ops_may_admin1898=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1899=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19002026/10/25 17:15:37 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]1901=== CONT TestService_RequireScope_OIDC/writer_implies_read1902=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1903=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1904=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1905=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1906=== CONT TestPush_RejectsBadRequests/no_roots19072026/10/25 17:15:37 INFO Received push request method=POST path=/api/pushes1908=== CONT TestPush_RejectsBadRequests/bad_root19092026/10/25 17:15:37 INFO Received push request method=POST path=/api/pushes1910=== CONT TestPush_RejectsBadRequests/root_not_in_objects19112026/10/25 17:15:37 INFO Received push request method=POST path=/api/pushes1912=== CONT TestPush_RejectsBadRequests/no_objects1913--- PASS: TestService_RequireScope_OIDC (0.32s)1914 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1915 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1916 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1917 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1918 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1919 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1920 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1921 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1922 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1923 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1924 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1925 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1926 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1927 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)19282026/10/25 17:15:37 INFO Received push request method=POST path=/api/pushes1929=== CONT TestIsValidCachePath/narinfo1930=== CONT TestIsValidCachePath/wrong_extension1931=== CONT TestIsValidCachePath/leading_slash1932--- PASS: TestPush_RejectsBadRequests (0.40s)1933 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1934 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1935 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1936 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1937=== CONT TestIsValidCachePath/empty1938=== CONT TestIsValidCachePath/short_hash1939=== CONT TestIsValidCachePath/random_path1940=== CONT TestIsValidCachePath/invalid_char_u1941=== CONT TestIsValidCachePath/invalid_char_e1942=== CONT TestIsValidCachePath/traversal_in_middle1943=== CONT TestIsValidCachePath/traversal_parent1944=== CONT TestIsValidCachePath/index.html1945=== CONT TestIsValidCachePath/nix-cache-info1946=== CONT TestIsValidCachePath/realisation1947=== CONT TestIsValidCachePath/log1948=== CONT TestIsValidCachePath/nar_xz1949=== CONT TestIsValidCachePath/nar_zst1950=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1951=== CONT TestIsValidCachePath/ls1952=== CONT TestIsValidCachePath/nar_uncompressed1953=== CONT TestIsValidCachePath/nar_bz21954--- PASS: TestIsValidCachePath (0.00s)1955 --- PASS: TestIsValidCachePath/narinfo (0.00s)1956 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1957 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1958 --- PASS: TestIsValidCachePath/empty (0.00s)1959 --- PASS: TestIsValidCachePath/short_hash (0.00s)1960 --- PASS: TestIsValidCachePath/random_path (0.00s)1961 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1962 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1963 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1964 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1965 --- PASS: TestIsValidCachePath/index.html (0.00s)1966 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1967 --- PASS: TestIsValidCachePath/realisation (0.00s)1968 --- PASS: TestIsValidCachePath/log (0.00s)1969 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1970 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1971 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1972 --- PASS: TestIsValidCachePath/ls (0.00s)1973 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1974 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1975=== CONT TestParseSingleRange/none1976=== CONT TestParseSingleRange/open-ended1977=== CONT TestParseSingleRange/start_far_past_EOF1978=== CONT TestParseSingleRange/start_past_EOF1979=== CONT TestParseSingleRange/single_byte1980=== CONT TestParseSingleRange/suffix_exceeds_size1981=== CONT TestParseSingleRange/suffix1982=== CONT TestParseSingleRange/end_clamped_to_size1983=== CONT TestParseSingleRange/malformed_both_empty1984=== CONT TestParseSingleRange/closed1985=== CONT TestParseSingleRange/malformed_end_before_start1986=== CONT TestParseSingleRange/unknown_unit1987=== CONT TestParseSingleRange/malformed_no_dash1988=== CONT TestParseSingleRange/multi-range_ignored1989--- PASS: TestParseSingleRange (0.00s)1990 --- PASS: TestParseSingleRange/none (0.00s)1991 --- PASS: TestParseSingleRange/open-ended (0.00s)1992 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1993 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1994 --- PASS: TestParseSingleRange/single_byte (0.00s)1995 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1996 --- PASS: TestParseSingleRange/suffix (0.00s)1997 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1998 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1999 --- PASS: TestParseSingleRange/closed (0.00s)2000 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2001 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2002 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2003 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2004=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh20052026/10/25 17:15:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20062026/10/25 17:15:37 INFO Received push request method=POST path=/api/pushes20072026/10/25 17:15:37 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZTA0MTY3MGQtYjk0Ny00MGQwLWI5YmMtZDI3YjhhM2VkMzI1LjA2ZWE4NjNiLTlmNmEtNDNhOC04YTAzLTNiZjI4MjYxYTk4YngxNzkyOTQ4NTM2NzAyMzM5NTg0 error="Get \"http://127.0.0.1:1/bucket53/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"20082026/10/25 17:15:37 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZTA0MTY3MGQtYjk0Ny00MGQwLWI5YmMtZDI3YjhhM2VkMzI1LjYwNTdmZDg5LTBlNTktNDljYy05MjU1LTZmMTQxOTViNTYxYXgxNzkyOTQ4NTM2Njk1ODIzNjE1 parts=1220092026/10/25 17:15:37 INFO Received cleanup request method=DELETE path=/api/pending_closures20102026/10/25 17:15:37 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/present20112026/10/25 17:15:37 INFO Aborted multipart uploads count=1 kept=020122026/10/25 17:15:37 INFO Received complete push request method=POST path=/api/pushes/1/complete20132026/10/25 17:15:37 INFO Received uploads request method=POST path=/api/pending_closures2014--- PASS: TestRedundantMultipartUpload (1.33s)2015=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale20162026/10/25 17:15:37 INFO Completed push id=1 objects=4 duration=18.086317ms20172026/10/25 17:15:37 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete20182026/10/25 17:15:37 INFO Completed upload id=2 objects=2 duration=1.48444ms2019--- PASS: TestMetricsCommit (0.48s)2020=== CONT TestServerTLSConfig/no_client_CA2021=== CONT TestServerTLSConfig/not_a_PEM_file2022=== CONT TestServerTLSConfig/missing_CA_file2023--- PASS: TestServerTLSConfig (0.00s)2024 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2025 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2026 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)20272026/10/25 17:15:37 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20282026/10/25 17:15:37 WARN mTLS auth: bound subjects configured but subject DN unavailable20292026/10/25 17:15:37 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2030--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.47s)20312026/10/25 17:15:37 INFO Received cleanup request method=DELETE path=/api/pending_closures20322026/10/25 17:15:37 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket87/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""20332026/10/25 17:15:37 INFO Aborted multipart uploads count=0 kept=120342026/10/25 17:15:37 INFO Received cleanup request method=DELETE path=/api/pending_closures20352026/10/25 17:15:37 INFO Aborted multipart uploads count=1 kept=02036--- PASS: TestMultipartCleanup (0.55s)20372026/10/25 17:15:37 INFO Aborted multipart uploads count=0 kept=020382026/10/25 17:15:37 WARN Request failed, retrying attempt=2 backoff=180.011977ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20392026/10/25 17:15:37 WARN Force mode enabled - objects will be deleted immediately without grace period20402026/10/25 17:15:37 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:39821/bucket93/?delete=\": context canceled"20412026/10/25 17:15:37 INFO Aborted multipart uploads count=0 kept=020422026/10/25 17:15:37 WARN Force mode enabled - objects will be deleted immediately without grace period20432026/10/25 17:15:37 INFO Received uploads request method=POST path=/api/pending_closures2044--- PASS: TestGCEndsOnShutdown (0.00s)2045 --- PASS: TestGCEndsOnShutdown/before_the_run (0.43s)2046 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.42s)2047 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.46s)20482026/10/25 17:15:37 INFO Aborted multipart uploads count=0 kept=020492026/10/25 17:15:37 WARN Force mode enabled - objects will be deleted immediately without grace period20502026/10/25 17:15:37 INFO Received uploads request method=POST path=/api/pending_closures20512026/10/25 17:15:37 INFO Aborted multipart uploads count=0 kept=020522026/10/25 17:15:37 WARN Force mode enabled - objects will be deleted immediately without grace period20532026/10/25 17:15:37 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=020542026/10/25 17:15:37 INFO Vacuumed table table=pending_closures20552026/10/25 17:15:37 INFO Vacuumed table table=pending_objects20562026/10/25 17:15:37 INFO Vacuumed table table=multipart_uploads20572026/10/25 17:15:37 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=020582026/10/25 17:15:37 INFO Vacuumed table table=closures20592026/10/25 17:15:37 INFO Vacuumed table table=pending_closures2060=== NAME TestOrphanedObjectsGC2061 orphaned_objects_gc_test.go:287: GC Test Summary:2062 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A2063 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B2064 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)2065 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)2066 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects2067--- PASS: TestOrphanedObjectsGC (0.76s)20682026/10/25 17:15:37 INFO Vacuumed table table=objects20692026/10/25 17:15:37 INFO Vacuumed table table=pending_objects20702026/10/25 17:15:37 INFO Vacuumed table table=multipart_uploads20712026/10/25 17:15:37 INFO Vacuumed table table=closures20722026/10/25 17:15:37 INFO Vacuumed table table=objects2073--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2074 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.48s)2075 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.55s)20762026/10/25 17:15:37 WARN Request failed, retrying attempt=3 backoff=417.38441ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20772026/10/25 17:15:37 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20782026/10/25 17:15:37 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2079--- PASS: TestUploadHandlersRejectOversizedBody (0.15s)2080 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)2081 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)2082 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.72s)20832026/10/25 17:15:37 WARN Request failed, retrying attempt=4 backoff=869.209067ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20842026/10/25 17:15:37 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=020852026/10/25 17:15:37 INFO Received create pin request method=POST path=/api/pins/myapp20862026/10/25 17:15:37 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC590273862/001/store/43wc62bic8q2857chid76cd73d500gbg-pinned-file.txt narinfo_key=43wc62bic8q2857chid76cd73d500gbg.narinfo20872026/10/25 17:15:37 INFO Starting cleanup of old closures method=DELETE path=/api/closures20882026/10/25 17:15:37 INFO Garbage collection started2089--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2090 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.82s)2091 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.79s)20922026/10/25 17:15:38 INFO Aborted multipart uploads count=0 kept=02093--- PASS: TestPendingClosureWriteTimeout (0.07s)2094 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2095 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2096 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2097 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.20s)20982026/10/25 17:15:38 WARN Force mode enabled - objects will be deleted immediately without grace period20992026/10/25 17:15:38 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=021002026/10/25 17:15:38 INFO Vacuumed table table=pending_closures21012026/10/25 17:15:38 INFO Vacuumed table table=pending_objects21022026/10/25 17:15:38 INFO Vacuumed table table=multipart_uploads21032026/10/25 17:15:38 INFO Vacuumed table table=closures21042026/10/25 17:15:38 INFO Vacuumed table table=objects21052026/10/25 17:15:38 INFO lead: released remote=192.0.2.1:12342106--- PASS: TestLeadElectsOneAndHandsOver (2.79s)21072026/10/25 17:15:38 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02108=== NAME TestClientIntegration2109 client_integration_test.go:323: Objects in database after GC:2110 client_integration_test.go:323: Successfully deleted all objects with GC --force2111--- PASS: TestClientIntegration (2.55s)2112=== NAME TestOrphanedObjectsGCStressTest2113 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2114 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion21152026/10/25 17:15:38 WARN Request failed, retrying attempt=5 backoff=1.655174061s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21162026/10/25 17:15:39 WARN Rate limiter enabled after throttle name=s3-test rate=521172026/10/25 17:15:39 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2118=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2119 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102120 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002121--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.90s)2122=== NAME TestOrphanedObjectsGCStressTest2123 orphaned_objects_gc_test.go:503: Stress test completed successfully:2124 orphaned_objects_gc_test.go:504: - Active objects preserved: 202125 orphaned_objects_gc_test.go:505: - Objects deleted: 2102126 orphaned_objects_gc_test.go:506: - Total GC'd: 2102127--- PASS: TestOrphanedObjectsGCStressTest (3.22s)2128=== NAME TestPinProtectsFromGC2129 client_integration_test.go:840: Pin successfully protected closure from garbage collection2130--- PASS: TestPinProtectsFromGC (4.94s)21312026/10/25 17:15:40 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-config21322026/10/25 17:15:40 WARN Request failed, retrying attempt=2 backoff=188.5255ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2133--- PASS: TestConnectWaitsForAPeerMigration (5.13s)21342026/10/25 17:15:40 WARN Request failed, retrying attempt=3 backoff=387.971615ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2135--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.51s)21362026/10/25 17:15:41 WARN Request failed, retrying attempt=4 backoff=768.363332ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21372026/10/25 17:15:41 WARN Request failed, retrying attempt=5 backoff=1.608688851s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21382026/10/25 17:15:42 INFO Aborted multipart uploads count=1 kept=021392026/10/25 17:15:43 INFO Received cleanup request method=DELETE path=/api/pending_closures21402026/10/25 17:15:43 INFO Aborted multipart uploads count=1 kept=02141--- PASS: TestPendingCleanupUsesOneCutoff (6.44s)21422026/10/25 17:15:43 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"21432026/10/25 17:15:43 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-config21442026/10/25 17:15:43 WARN Request failed, retrying attempt=2 backoff=210.985266ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21452026/10/25 17:15:43 WARN Request failed, retrying attempt=3 backoff=384.062026ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21462026/10/25 17:15:44 WARN Request failed, retrying attempt=4 backoff=733.800103ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21472026/10/25 17:15:44 WARN Request failed, retrying attempt=5 backoff=1.530282621s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21482026/10/25 17:15:46 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_closures21492026/10/25 17:15:46 WARN Request failed, retrying attempt=2 backoff=214.929186ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21502026/10/25 17:15:46 WARN Request failed, retrying attempt=3 backoff=410.50296ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21512026/10/25 17:15:47 WARN Request failed, retrying attempt=4 backoff=868.370534ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21522026/10/25 17:15:48 WARN Request failed, retrying attempt=5 backoff=1.612897842s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2153--- PASS: TestClientErrorHandling (0.00s)2154 --- PASS: TestClientErrorHandling/InvalidStorePath (0.31s)2155 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.42s)2156 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.59s)2157PASS21582026-10-25 17:15:49.913 UTC [128] LOG: received smart shutdown request21592026-10-25 17:15:49.917 UTC [128] LOG: background worker "logical replication launcher" (PID 138) exited with exit code 121602026-10-25 17:15:49.928 UTC [133] LOG: shutting down21612026-10-25 17:15:49.929 UTC [133] LOG: checkpoint starting: shutdown immediate21622026-10-25 17:15:51.483 UTC [133] LOG: checkpoint complete: wrote 11019 buffers (67.3%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 30 recycled; write=0.231 s, sync=1.285 s, total=1.555 s; sync files=34045, longest=0.002 s, average=0.001 s; distance=493990 kB, estimate=493990 kB; lsn=0/1F9CF720, redo lsn=0/1F9CF72021632026-10-25 17:15:51.552 UTC [128] LOG: database system is shut down2164Running OIDC tests...2165=== RUN TestAudienceForIssuer2166=== PAUSE TestAudienceForIssuer2167=== RUN TestGlobMatch2168=== PAUSE TestGlobMatch2169=== RUN TestValidateToken_ValidToken2170=== PAUSE TestValidateToken_ValidToken2171=== RUN TestValidateToken_WrongAudience2172=== PAUSE TestValidateToken_WrongAudience2173=== RUN TestValidateToken_Expired2174=== PAUSE TestValidateToken_Expired2175=== RUN TestValidateToken_BoundClaimsMismatch2176=== PAUSE TestValidateToken_BoundClaimsMismatch2177=== RUN TestValidateToken_BoundSubjectMismatch2178=== PAUSE TestValidateToken_BoundSubjectMismatch2179=== RUN TestValidateToken_MultipleProviders2180=== PAUSE TestValidateToken_MultipleProviders2181=== RUN TestValidateToken_NoMatchingProvider2182=== PAUSE TestValidateToken_NoMatchingProvider2183=== RUN TestValidateToken_KubernetesServiceAccount2184=== PAUSE TestValidateToken_KubernetesServiceAccount2185=== RUN TestNewValidator_KubernetesRequiresCA2186=== PAUSE TestNewValidator_KubernetesRequiresCA2187=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2188=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2189=== RUN TestPins_ReservedForMatchingRule2190=== PAUSE TestPins_ReservedForMatchingRule2191=== RUN TestPins_TopLevelShorthand2192=== PAUSE TestPins_TopLevelShorthand2193=== RUN TestPins_ConfigValidation2194=== PAUSE TestPins_ConfigValidation2195=== RUN TestScopes_LegacyProviderDefaultsToWrite2196=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2197=== RUN TestScopes_Rules2198=== PAUSE TestScopes_Rules2199=== RUN TestScopes_ConfigValidation2200=== PAUSE TestScopes_ConfigValidation2201=== CONT TestAudienceForIssuer2202=== CONT TestValidateToken_BoundClaimsMismatch2203--- PASS: TestAudienceForIssuer (0.00s)2204=== CONT TestValidateToken_KubernetesServiceAccount2205=== CONT TestValidateToken_Expired2206=== CONT TestScopes_ConfigValidation2207=== CONT TestValidateToken_WrongAudience2208=== CONT TestValidateToken_ValidToken2209=== CONT TestScopes_Rules2210=== CONT TestScopes_LegacyProviderDefaultsToWrite2211=== CONT TestPins_ConfigValidation2212=== CONT TestGlobMatch2213=== RUN TestGlobMatch/foo_foo2214=== PAUSE TestGlobMatch/foo_foo2215=== RUN TestGlobMatch/foo_bar2216=== PAUSE TestGlobMatch/foo_bar2217=== RUN TestGlobMatch/*_2218=== CONT TestPins_TopLevelShorthand2219=== CONT TestPins_ReservedForMatchingRule2220=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2221=== CONT TestNewValidator_KubernetesRequiresCA2222=== CONT TestValidateToken_NoMatchingProvider2223=== CONT TestValidateToken_BoundSubjectMismatch2224=== CONT TestValidateToken_MultipleProviders2225--- PASS: TestScopes_ConfigValidation (0.00s)2226=== PAUSE TestGlobMatch/*_2227=== RUN TestGlobMatch/*_anything2228=== PAUSE TestGlobMatch/*_anything2229=== RUN TestGlobMatch/foo*_foo2230=== PAUSE TestGlobMatch/foo*_foo2231=== RUN TestGlobMatch/foo*_foobar2232=== PAUSE TestGlobMatch/foo*_foobar2233=== RUN TestGlobMatch/foo*_bar2234=== PAUSE TestGlobMatch/foo*_bar2235=== RUN TestGlobMatch/*bar_bar2236=== PAUSE TestGlobMatch/*bar_bar2237--- PASS: TestPins_ConfigValidation (0.00s)2238=== RUN TestGlobMatch/*bar_foobar2239=== PAUSE TestGlobMatch/*bar_foobar2240=== RUN TestGlobMatch/*bar_foo2241=== PAUSE TestGlobMatch/*bar_foo2242=== RUN TestGlobMatch/foo*bar_foobar2243=== PAUSE TestGlobMatch/foo*bar_foobar2244=== RUN TestGlobMatch/foo*bar_foo123bar2245=== PAUSE TestGlobMatch/foo*bar_foo123bar2246=== RUN TestGlobMatch/foo*bar_foobarbaz2247=== PAUSE TestGlobMatch/foo*bar_foobarbaz2248=== RUN TestGlobMatch/*/*_foo/bar2249=== PAUSE TestGlobMatch/*/*_foo/bar2250=== RUN TestGlobMatch/*/*_foo2251=== PAUSE TestGlobMatch/*/*_foo2252=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2253=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2254=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02255=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02256=== RUN TestGlobMatch/refs/*/main_refs/heads/main2257=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2258=== RUN TestGlobMatch/fo?_foo2259=== PAUSE TestGlobMatch/fo?_foo2260=== RUN TestGlobMatch/fo?_fo2261=== PAUSE TestGlobMatch/fo?_fo2262=== RUN TestGlobMatch/fo?_fooo2263=== PAUSE TestGlobMatch/fo?_fooo2264=== RUN TestGlobMatch/?oo_foo2265=== PAUSE TestGlobMatch/?oo_foo2266=== RUN TestGlobMatch/?oo_boo2267=== PAUSE TestGlobMatch/?oo_boo2268=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2269=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2270=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2271=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2272=== CONT TestGlobMatch/foo_foo2273=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2274=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2275=== CONT TestGlobMatch/?oo_boo2276=== CONT TestGlobMatch/?oo_foo2277=== CONT TestGlobMatch/fo?_fooo2278=== CONT TestGlobMatch/fo?_fo2279=== CONT TestGlobMatch/fo?_foo2280=== CONT TestGlobMatch/refs/*/main_refs/heads/main2281=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02282=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2283=== CONT TestGlobMatch/*/*_foo2284=== CONT TestGlobMatch/*/*_foo/bar2285=== CONT TestGlobMatch/foo*bar_foobarbaz2286=== CONT TestGlobMatch/foo*bar_foo123bar2287=== CONT TestGlobMatch/foo*bar_foobar2288=== CONT TestGlobMatch/*bar_foo2289=== CONT TestGlobMatch/*bar_foobar2290=== CONT TestGlobMatch/*bar_bar2291=== CONT TestGlobMatch/foo*_bar2292=== CONT TestGlobMatch/foo*_foobar2293=== CONT TestGlobMatch/foo*_foo2294=== CONT TestGlobMatch/*_anything2295=== CONT TestGlobMatch/*_2296=== CONT TestGlobMatch/foo_bar2297--- PASS: TestGlobMatch (0.00s)2298 --- PASS: TestGlobMatch/foo_foo (0.00s)2299 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2300 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2301 --- PASS: TestGlobMatch/?oo_boo (0.00s)2302 --- PASS: TestGlobMatch/?oo_foo (0.00s)2303 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2304 --- PASS: TestGlobMatch/fo?_fo (0.00s)2305 --- PASS: TestGlobMatch/fo?_foo (0.00s)2306 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2307 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2308 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2309 --- PASS: TestGlobMatch/*/*_foo (0.00s)2310 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2311 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2312 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2313 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2314 --- PASS: TestGlobMatch/*bar_foo (0.00s)2315 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2316 --- PASS: TestGlobMatch/*bar_bar (0.00s)2317 --- PASS: TestGlobMatch/foo*_bar (0.00s)2318 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2319 --- PASS: TestGlobMatch/foo*_foo (0.00s)2320 --- PASS: TestGlobMatch/*_anything (0.00s)2321 --- PASS: TestGlobMatch/*_ (0.00s)2322 --- PASS: TestGlobMatch/foo_bar (0.00s)23232026/10/25 17:15:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45553/oidc23242026/10/25 17:15:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46641/oidc2325--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.03s)2326--- PASS: TestValidateToken_BoundSubjectMismatch (0.03s)23272026/10/25 17:15:53 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:451412328--- PASS: TestValidateToken_KubernetesServiceAccount (0.04s)23292026/10/25 17:15:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34831/oidc23302026/10/25 17:15:53 http: TLS handshake error from 127.0.0.1:54962: remote error: tls: bad certificate2331--- PASS: TestNewValidator_KubernetesRequiresCA (0.05s)2332--- PASS: TestScopes_Rules (0.05s)23332026/10/25 17:15:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37861/oidc2334--- PASS: TestValidateToken_ValidToken (0.07s)23352026/10/25 17:15:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46473/oidc2336--- PASS: TestValidateToken_Expired (0.08s)23372026/10/25 17:15:53 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12323382026/10/25 17:15:53 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:40223/oidc2339--- PASS: TestValidateToken_NoMatchingProvider (0.09s)2340--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.09s)23412026/10/25 17:15:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37119/oidc2342--- PASS: TestValidateToken_BoundClaimsMismatch (0.10s)23432026/10/25 17:15:53 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:36115/oidc23442026/10/25 17:15:53 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:36621/oidc2345--- PASS: TestValidateToken_MultipleProviders (0.13s)23462026/10/25 17:15:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40201/oidc2347--- PASS: TestValidateToken_WrongAudience (0.14s)23482026/10/25 17:15:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46233/oidc2349--- PASS: TestPins_TopLevelShorthand (0.14s)23502026/10/25 17:15:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45529/oidc2351--- PASS: TestPins_ReservedForMatchingRule (0.20s)2352PASS2353Running hook tests...2354=== RUN TestSendPathsEmpty2355=== PAUSE TestSendPathsEmpty2356=== RUN TestQueueEnqueueAndFetch2357=== PAUSE TestQueueEnqueueAndFetch2358=== RUN TestQueueDeduplication2359=== PAUSE TestQueueDeduplication2360=== RUN TestQueueRemove2361=== PAUSE TestQueueRemove2362=== RUN TestQueueFetchBatchLimit2363=== PAUSE TestQueueFetchBatchLimit2364=== RUN TestQueueRetryMovesToBack2365=== PAUSE TestQueueRetryMovesToBack2366=== RUN TestQueueFetchRemoveLifecycle2367=== PAUSE TestQueueFetchRemoveLifecycle2368=== RUN TestQueueConcurrentWriters2369=== PAUSE TestQueueConcurrentWriters2370=== RUN TestQueueRemoveLargeClosure2371=== PAUSE TestQueueRemoveLargeClosure2372=== RUN TestServerClientIntegration2373--- PASS: TestServerClientIntegration (0.00s)2374=== RUN TestServerQueueError23752026/10/25 17:15:53 ERROR Failed to queue paths error="permission denied" count=12376--- PASS: TestServerQueueError (0.00s)2377=== RUN TestGetListenerSocketActivation2378 server_test.go:215: === RUN TestGetListenerSocketActivation2379 --- PASS: TestGetListenerSocketActivation (0.00s)2380 PASS2381 2382--- PASS: TestGetListenerSocketActivation (0.01s)2383=== RUN TestDrainIsolatesPoisonPath2384=== PAUSE TestDrainIsolatesPoisonPath2385=== RUN TestRunNotBlockedByPoisonHead2386=== PAUSE TestRunNotBlockedByPoisonHead2387=== RUN TestDrainGivesUpWhenServerDown2388=== PAUSE TestDrainGivesUpWhenServerDown2389=== RUN TestFailedPathPrunedByLaterClosure2390=== PAUSE TestFailedPathPrunedByLaterClosure2391=== RUN TestWorkerUploadsAndRemoves2392=== PAUSE TestWorkerUploadsAndRemoves2393=== RUN TestWorkerSkipsGCdPaths2394=== PAUSE TestWorkerSkipsGCdPaths2395=== RUN TestWorkerPrunesClosureDeps2396=== PAUSE TestWorkerPrunesClosureDeps2397=== RUN TestDrainTimeout2398=== PAUSE TestDrainTimeout2399=== RUN TestWorkerRemoveFailureIsNotProgress2400=== PAUSE TestWorkerRemoveFailureIsNotProgress2401=== RUN TestWorkerKeepsPathItCannotStat2402=== PAUSE TestWorkerKeepsPathItCannotStat2403=== CONT TestSendPathsEmpty2404=== CONT TestWorkerPrunesClosureDeps2405=== CONT TestWorkerKeepsPathItCannotStat2406=== CONT TestWorkerRemoveFailureIsNotProgress2407=== CONT TestDrainTimeout2408--- PASS: TestSendPathsEmpty (0.00s)2409=== CONT TestRunNotBlockedByPoisonHead2410=== CONT TestDrainIsolatesPoisonPath2411=== CONT TestQueueRemoveLargeClosure2412=== CONT TestQueueConcurrentWriters2413=== CONT TestQueueFetchRemoveLifecycle2414=== CONT TestQueueRetryMovesToBack2415=== CONT TestQueueFetchBatchLimit2416=== CONT TestQueueRemove2417=== CONT TestQueueDeduplication2418=== CONT TestWorkerUploadsAndRemoves2419=== CONT TestQueueEnqueueAndFetch2420=== CONT TestWorkerSkipsGCdPaths2421=== CONT TestDrainGivesUpWhenServerDown2422=== CONT TestFailedPathPrunedByLaterClosure24232026/10/25 17:15:53 INFO Uploading batch count=124242026/10/25 17:15:53 ERROR Upload failed error="upload failed" count=124252026/10/25 17:15:53 INFO Uploading batch count=424262026/10/25 17:15:53 ERROR Upload failed error="upload failed" count=424272026/10/25 17:15:53 INFO Uploading batch count=224282026/10/25 17:15:53 INFO Upload queue status pending=224292026/10/25 17:15:53 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2489750198/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat2489750198/002/locked/aaa: permission denied"24302026/10/25 17:15:53 INFO Upload queue status pending=224312026/10/25 17:15:53 INFO Upload queue status pending=324322026/10/25 17:15:53 INFO Uploading batch count=224332026/10/25 17:15:53 INFO Upload queue status pending=224342026/10/25 17:15:53 INFO Uploading batch count=124352026/10/25 17:15:53 ERROR Upload failed error="upload failed" count=124362026/10/25 17:15:53 INFO Uploading batch count=12437--- PASS: TestQueueFetchBatchLimit (0.02s)24382026/10/25 17:15:53 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2489750198/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat2489750198/002/locked/aaa: permission denied"24392026/10/25 17:15:53 INFO Uploading batch count=22440--- PASS: TestQueueDeduplication (0.02s)24412026/10/25 17:15:53 ERROR Upload failed error="upload failed" count=224422026/10/25 17:15:53 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3399623204/002/a24432026/10/25 17:15:53 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths450448978/002/nonexistent24442026/10/25 17:15:53 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath3521654790/002/bbb2445--- PASS: TestQueueRemove (0.02s)24462026/10/25 17:15:53 INFO Uploading batch count=124472026/10/25 17:15:53 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress635316728/002/nonexistent24482026/10/25 17:15:53 INFO Uploading batch count=12449--- PASS: TestQueueRetryMovesToBack (0.02s)24502026/10/25 17:15:53 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12451--- PASS: TestQueueEnqueueAndFetch (0.02s)24522026/10/25 17:15:53 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3399623204/002/b24532026/10/25 17:15:53 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress635316728/002/nonexistent24542026/10/25 17:15:53 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2489750198/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat2489750198/002/locked/aaa: permission denied"24552026/10/25 17:15:53 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124562026/10/25 17:15:53 INFO Uploading batch count=124572026/10/25 17:15:53 ERROR Drain finished with paths left in queue remaining=124582026/10/25 17:15:53 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress635316728/002/nonexistent2459--- PASS: TestQueueFetchRemoveLifecycle (0.02s)24602026/10/25 17:15:53 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124612026/10/25 17:15:53 ERROR Drain finished with paths left in queue remaining=124622026/10/25 17:15:53 INFO Uploading batch count=224632026/10/25 17:15:53 ERROR Upload failed error="upload failed" count=224642026/10/25 17:15:53 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3399623204/002/c24652026/10/25 17:15:53 INFO Uploading batch count=124662026/10/25 17:15:53 ERROR Upload failed error="upload failed" count=124672026/10/25 17:15:53 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3399623204/002/d2468--- PASS: TestWorkerRemoveFailureIsNotProgress (0.03s)2469--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)24702026/10/25 17:15:53 INFO Uploading batch count=124712026/10/25 17:15:53 ERROR Upload failed error="upload failed" count=124722026/10/25 17:15:53 INFO Uploading batch count=224732026/10/25 17:15:53 ERROR Upload failed error="upload failed" count=224742026/10/25 17:15:53 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3399623204/002/e2475--- PASS: TestWorkerKeepsPathItCannotStat (0.03s)24762026/10/25 17:15:53 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3399623204/002/f24772026/10/25 17:15:53 INFO Uploading batch count=124782026/10/25 17:15:53 ERROR Upload failed error="upload failed" count=124792026/10/25 17:15:53 ERROR Drain finished with paths left in queue remaining=1024802026/10/25 17:15:53 ERROR Drain finished with paths left in queue remaining=12481--- PASS: TestDrainGivesUpWhenServerDown (0.03s)2482--- PASS: TestDrainIsolatesPoisonPath (0.03s)2483--- PASS: TestWorkerPrunesClosureDeps (0.04s)2484--- PASS: TestWorkerUploadsAndRemoves (0.04s)2485--- PASS: TestWorkerSkipsGCdPaths (0.04s)2486--- PASS: TestQueueRemoveLargeClosure (0.06s)24872026/10/25 17:15:53 ERROR Upload failed error="context deadline exceeded" count=224882026/10/25 17:15:53 ERROR Drain finished with paths left in queue remaining=42489--- PASS: TestDrainTimeout (0.22s)2490--- PASS: TestQueueConcurrentWriters (0.23s)24912026/10/25 17:15:54 INFO Uploading batch count=124922026/10/25 17:15:54 INFO Uploading batch count=124932026/10/25 17:15:54 INFO Uploading batch count=124942026/10/25 17:15:54 ERROR Upload failed error="upload failed" count=124952026/10/25 17:15:54 INFO Uploading batch count=124962026/10/25 17:15:54 ERROR Upload failed error="upload failed" count=124972026/10/25 17:15:54 INFO Uploading batch count=124982026/10/25 17:15:54 ERROR Upload failed error="upload failed" count=124992026/10/25 17:15:54 INFO Uploading batch count=125002026/10/25 17:15:54 ERROR Upload failed error="upload failed" count=125012026/10/25 17:15:54 ERROR Drain finished with paths left in queue remaining=12502--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2503PASS2504Running signing tests...2505=== RUN TestExternalSigner2506=== PAUSE TestExternalSigner2507=== RUN TestExternalSignerWrongPublicKey2508=== PAUSE TestExternalSignerWrongPublicKey2509=== RUN TestExternalSignerErrors2510=== PAUSE TestExternalSignerErrors2511=== RUN TestExternalSignerRestartsAfterCrash2512=== PAUSE TestExternalSignerRestartsAfterCrash2513=== RUN TestExternalSignerProgramErrorKeepsProcess2514=== PAUSE TestExternalSignerProgramErrorKeepsProcess2515=== RUN TestExternalSignerClose2516=== PAUSE TestExternalSignerClose2517=== RUN TestExternalSignerRejectsInvalidPublicKey2518=== PAUSE TestExternalSignerRejectsInvalidPublicKey2519=== RUN TestExternalSignerCancellation2520=== PAUSE TestExternalSignerCancellation2521=== RUN TestGenerateFingerprint2522=== PAUSE TestGenerateFingerprint2523=== RUN TestParseSigningKey2524=== PAUSE TestParseSigningKey2525=== RUN TestSign2526=== PAUSE TestSign2527=== RUN TestSignBatch2528=== PAUSE TestSignBatch2529=== RUN TestNilKeyPublicKey2530=== PAUSE TestNilKeyPublicKey2531=== RUN TestSignErrors2532=== PAUSE TestSignErrors2533=== CONT TestExternalSigner2534=== CONT TestExternalSignerProgramErrorKeepsProcess2535=== CONT TestExternalSignerCancellation2536=== CONT TestSignErrors2537=== CONT TestNilKeyPublicKey2538--- PASS: TestNilKeyPublicKey (0.00s)2539=== CONT TestExternalSignerErrors2540=== RUN TestExternalSignerErrors/program_error2541=== PAUSE TestExternalSignerErrors/program_error2542=== CONT TestSignBatch2543=== CONT TestSign2544=== CONT TestParseSigningKey2545=== CONT TestExternalSignerRestartsAfterCrash2546=== CONT TestGenerateFingerprint2547=== CONT TestExternalSignerRejectsInvalidPublicKey2548=== CONT TestExternalSignerWrongPublicKey2549=== CONT TestExternalSignerClose2550=== RUN TestExternalSignerErrors/exit_on_request2551=== RUN TestParseSigningKey/valid_32-byte_key2552=== PAUSE TestExternalSignerErrors/exit_on_request2553=== PAUSE TestParseSigningKey/valid_32-byte_key2554=== RUN TestExternalSignerRejectsInvalidPublicKey/#002555=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2556=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2557=== RUN TestParseSigningKey/no_colon2558=== PAUSE TestParseSigningKey/no_colon2559=== RUN TestParseSigningKey/empty_name2560=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002561=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2562=== RUN TestExternalSignerErrors/wrong_shape2563=== PAUSE TestExternalSignerErrors/wrong_shape2564=== RUN TestGenerateFingerprint/basic_with_references2565=== PAUSE TestParseSigningKey/empty_name2566=== RUN TestParseSigningKey/invalid_base642567=== PAUSE TestParseSigningKey/invalid_base642568=== RUN TestParseSigningKey/wrong_length2569=== PAUSE TestGenerateFingerprint/basic_with_references2570=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2571--- PASS: TestSign (0.00s)2572--- PASS: TestSignBatch (0.00s)2573=== RUN TestExternalSignerErrors/missing_signatures2574=== RUN TestSignErrors/nil_key2575=== PAUSE TestSignErrors/nil_key2576=== RUN TestSignErrors/nil_narinfo2577=== PAUSE TestSignErrors/nil_narinfo2578=== RUN TestSignErrors/invalid_narinfo2579=== PAUSE TestSignErrors/invalid_narinfo2580=== RUN TestSignErrors/canceled2581=== PAUSE TestSignErrors/canceled2582=== CONT TestSignErrors/nil_key2583=== PAUSE TestParseSigningKey/wrong_length2584=== CONT TestParseSigningKey/valid_32-byte_key2585=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2586=== CONT TestSignErrors/canceled2587=== CONT TestParseSigningKey/empty_name2588=== CONT TestParseSigningKey/invalid_base642589=== RUN TestGenerateFingerprint/no_references2590=== PAUSE TestGenerateFingerprint/no_references2591=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2592=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2593=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2594=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2595=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2596=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2597=== CONT TestExternalSignerRejectsInvalidPublicKey/#002598--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2599=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2600=== CONT TestSignErrors/invalid_narinfo2601=== CONT TestSignErrors/nil_narinfo2602=== CONT TestParseSigningKey/wrong_length2603=== CONT TestParseSigningKey/no_colon2604=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2605=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2606=== PAUSE TestExternalSignerErrors/missing_signatures2607=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2608=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2609=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2610=== RUN TestGenerateFingerprint/invalid_nar_hash_length2611=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2612=== RUN TestGenerateFingerprint/invalid_store_path_prefix2613=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2614=== RUN TestGenerateFingerprint/invalid_reference_prefix2615=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2616=== CONT TestGenerateFingerprint/basic_with_references2617=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2618=== CONT TestGenerateFingerprint/invalid_reference_prefix2619=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2620--- PASS: TestSignErrors (0.00s)2621 --- PASS: TestSignErrors/nil_key (0.00s)2622 --- PASS: TestSignErrors/canceled (0.00s)2623 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2624 --- PASS: TestSignErrors/nil_narinfo (0.00s)2625=== RUN TestExternalSignerErrors/wrong_signatures_shape2626=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2627=== RUN TestExternalSignerErrors/missing_signature_name2628=== PAUSE TestExternalSignerErrors/missing_signature_name2629=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2630=== CONT TestGenerateFingerprint/invalid_store_path_prefix2631=== CONT TestGenerateFingerprint/invalid_nar_hash_length2632=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2633=== CONT TestGenerateFingerprint/no_references2634--- PASS: TestParseSigningKey (0.00s)2635 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2636 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2637 --- PASS: TestParseSigningKey/empty_name (0.00s)2638 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2639 --- PASS: TestParseSigningKey/wrong_length (0.00s)2640 --- PASS: TestParseSigningKey/no_colon (0.00s)2641--- PASS: TestExternalSignerClose (0.00s)2642--- PASS: TestExternalSignerWrongPublicKey (0.00s)2643=== RUN TestExternalSignerErrors/wrong_signature_name2644=== PAUSE TestExternalSignerErrors/wrong_signature_name2645--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2646 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2647 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2648 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2649 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2650 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2651=== RUN TestExternalSignerErrors/wrong_id2652=== PAUSE TestExternalSignerErrors/wrong_id2653--- PASS: TestGenerateFingerprint (0.00s)2654 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2655 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2656 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2657 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2658 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2659 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2660 --- PASS: TestGenerateFingerprint/no_references (0.00s)2661=== RUN TestExternalSignerErrors/wrong_signature_length2662=== PAUSE TestExternalSignerErrors/wrong_signature_length2663=== RUN TestExternalSignerErrors/null2664=== PAUSE TestExternalSignerErrors/null2665=== RUN TestExternalSignerErrors/null_signatures2666=== PAUSE TestExternalSignerErrors/null_signatures2667=== RUN TestExternalSignerErrors/too_few_signatures2668=== PAUSE TestExternalSignerErrors/too_few_signatures2669=== RUN TestExternalSignerErrors/invalid_signature_base642670=== PAUSE TestExternalSignerErrors/invalid_signature_base642671=== RUN TestExternalSignerErrors/exit_at_startup2672=== PAUSE TestExternalSignerErrors/exit_at_startup2673=== RUN TestExternalSignerErrors/invalid_JSON2674=== PAUSE TestExternalSignerErrors/invalid_JSON2675=== RUN TestExternalSignerErrors/unrequested_key2676=== PAUSE TestExternalSignerErrors/unrequested_key2677=== CONT TestExternalSignerErrors/program_error2678=== CONT TestExternalSignerErrors/null_signatures2679=== CONT TestExternalSignerErrors/too_few_signatures2680=== CONT TestExternalSignerErrors/unrequested_key2681=== CONT TestExternalSignerErrors/invalid_JSON2682=== CONT TestExternalSignerErrors/exit_at_startup2683=== CONT TestExternalSignerErrors/invalid_signature_base642684=== CONT TestExternalSignerErrors/wrong_signatures_shape2685=== CONT TestExternalSignerErrors/wrong_id2686=== CONT TestExternalSignerErrors/wrong_signature_name2687=== CONT TestExternalSignerErrors/null2688=== CONT TestExternalSignerErrors/missing_signature_name2689=== CONT TestExternalSignerErrors/wrong_shape2690=== CONT TestExternalSignerErrors/missing_signatures2691=== CONT TestExternalSignerErrors/exit_on_request2692=== CONT TestExternalSignerErrors/wrong_signature_length2693--- PASS: TestExternalSigner (0.01s)2694--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2695--- PASS: TestExternalSignerErrors (0.00s)2696 --- PASS: TestExternalSignerErrors/program_error (0.00s)2697 --- PASS: TestExternalSignerErrors/unrequested_key (0.00s)2698 --- PASS: TestExternalSignerErrors/invalid_JSON (0.00s)2699 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.00s)2700 --- PASS: TestExternalSignerErrors/null (0.00s)2701 --- PASS: TestExternalSignerErrors/exit_at_startup (0.01s)2702 --- PASS: TestExternalSignerErrors/exit_on_request (0.00s)2703 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.00s)2704 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)2705 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)2706 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)2707 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)2708 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)2709 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2710 --- PASS: TestExternalSignerErrors/missing_signatures (0.01s)2711 --- PASS: TestExternalSignerErrors/too_few_signatures (0.01s)2712--- PASS: TestExternalSignerCancellation (0.02s)2713PASS2714Running OpenBao signer tests...2715=== RUN TestSign2716=== PAUSE TestSign2717=== RUN TestSignErrors2718=== PAUSE TestSignErrors2719=== RUN TestServe2720=== PAUSE TestServe2721=== RUN TestServeRejectsGarbage2722=== PAUSE TestServeRejectsGarbage2723=== CONT TestSign2724=== CONT TestServeRejectsGarbage2725=== CONT TestSignErrors2726=== CONT TestServe2727--- PASS: TestServeRejectsGarbage (0.00s)2728=== RUN TestSignErrors/http_error2729=== PAUSE TestSignErrors/http_error2730=== RUN TestSignErrors/invalid_json2731=== PAUSE TestSignErrors/invalid_json2732=== RUN TestSignErrors/no_prefix2733=== PAUSE TestSignErrors/no_prefix2734=== RUN TestSignErrors/invalid_base642735=== PAUSE TestSignErrors/invalid_base642736=== CONT TestSignErrors/http_error2737=== CONT TestSignErrors/invalid_json2738=== CONT TestSignErrors/no_prefix2739--- PASS: TestServe (0.00s)2740=== CONT TestSignErrors/invalid_base642741--- PASS: TestSign (0.00s)2742--- PASS: TestSignErrors (0.00s)2743 --- PASS: TestSignErrors/invalid_json (0.00s)2744 --- PASS: TestSignErrors/invalid_base64 (0.00s)2745 --- PASS: TestSignErrors/http_error (0.00s)2746 --- PASS: TestSignErrors/no_prefix (0.00s)2747PASS