niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #422
· 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.04s)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 TestFileTokenEmpty117=== CONT TestScriptTokenBadJSON118=== CONT TestScriptTokenEmptyCommand119--- PASS: TestScriptTokenEmptyCommand (0.00s)120=== CONT TestPathInfoCACompatibility121=== RUN TestPathInfoCACompatibility/null_ca_field122=== PAUSE TestPathInfoCACompatibility/null_ca_field123=== CONT TestScriptTokenScriptFails124--- PASS: TestFileTokenEmpty (0.00s)125=== CONT TestSetClientTLSErrors126=== CONT TestScriptTokenEmptyToken127=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess128=== CONT TestFileTokenMissing129=== CONT TestFileTokenReadsAndCaches130=== CONT TestStreamPushIsolatesFailures131=== CONT TestStreamPushBatchesUnderLoad1322026/10/25 13:22:06 WARN Rate limiter enabled after throttle name=server-test rate=5133=== CONT TestStreamPushReportsEveryPath134=== CONT TestShellSplitErrors135--- PASS: TestShellSplitErrors (0.00s)136=== CONT TestParsePathInfoJSONMultiplePaths137=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths138=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths139=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths140=== CONT TestShellSplit141--- PASS: TestScriptTokenScriptFails (0.00s)142=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths143=== CONT TestSetClientTLSDoesNotMutateDefaultTransport144--- PASS: TestFileTokenMissing (0.00s)145--- PASS: TestShellSplit (0.00s)146=== CONT TestSetClientTLS1472026/10/25 13:22:06 ERROR Upload failed error="bad path" count=3148=== CONT TestParsePathInfoJSON149=== RUN TestParsePathInfoJSON/Nix_format150=== CONT TestRetryTimeoutOutlastsMaxRetries151=== CONT TestDoWithRetry_BodyReplayedViaGetBody152=== CONT TestResolveStorePath153=== CONT TestScriptTokenCachesUntilRefresh154=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer155=== CONT TestDumpPathMatchesNix156=== CONT TestPathInfoHashCompatibility157=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)158=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)159=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon160=== CONT TestStreamPushStopsWhenCanceled161=== CONT TestRateLimiterFeedback162=== RUN TestRateLimiterFeedback/429_enables_limiter163=== PAUSE TestRateLimiterFeedback/429_enables_limiter164=== RUN TestRateLimiterFeedback/503_enables_limiter165=== PAUSE TestRateLimiterFeedback/503_enables_limiter166=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter167=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter168=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter169=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter170--- PASS: TestFileTokenReadsAndCaches (0.00s)171=== RUN TestPathInfoCACompatibility/old_string_format_-_text172=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text173=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive174=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive175=== RUN TestPathInfoCACompatibility/new_structured_format_-_text176=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text177=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method178=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method179=== CONT TestConvertHashToNix32180=== RUN TestConvertHashToNix32/SRI_format_to_Nix32181=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32182=== PAUSE TestParsePathInfoJSON/Nix_format183=== CONT TestGetStorePathHash184=== CONT TestDoWithRetry_FinalResponseBodyReadable185=== CONT TestFilterOversizedClosures186=== CONT TestStaticToken187--- PASS: TestScriptTokenBadJSON (0.00s)188=== RUN TestGetStorePathHash/valid_store_path189=== RUN TestConvertHashToNix32/already_Nix32_format190=== CONT TestEncodeNixBase32WithRealHash191--- PASS: TestStreamPushReportsEveryPath (0.00s)192--- PASS: TestStreamPushIsolatesFailures (0.00s)193--- PASS: TestScriptTokenEmptyToken (0.01s)194--- PASS: TestStreamPushStopsWhenCanceled (0.00s)195--- PASS: TestStaticToken (0.00s)196--- PASS: TestResolveStorePath (0.00s)197=== PAUSE TestGetStorePathHash/valid_store_path198=== CONT TestSupersededNARStillUploadsListing199--- PASS: TestEncodeNixBase32WithRealHash (0.00s)200=== CONT TestUploadMultipart_FailedPartBufferNotReused201=== RUN TestSupersededNARStillUploadsListing/small_NAR202=== RUN TestGetStorePathHash/basename_without_hyphen_should_error203=== CONT TestDumpPathWriterError2042026/10/25 13:22:06 WARN Rate limiter enabled after throttle name=server-test rate=52052026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:373112062026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:34377207=== CONT TestDumpPathSingleFile2082026/10/25 13:22:06 WARN Rate limiter backed off name=server-test rate=52092026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:373112102026/10/25 13:22:06 WARN Rate limiter enabled after throttle name=server-test rate=5211=== CONT TestStreamPushReportsSkippedPaths212=== RUN TestParsePathInfoJSON/Lix_format213=== CONT TestEncodeNixBase322142026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:35745215=== CONT TestUploadMultipart_SupersededByPeer216=== CONT TestPartSizeForNAR217=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon218--- PASS: TestDoServerRequestAttachesToken (0.01s)219=== CONT TestUploadMultipart_PartsInParallel220=== PAUSE TestSupersededNARStillUploadsListing/small_NAR221=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error222=== RUN TestSetClientTLSErrors/missing_cert_file223=== RUN TestFilterOversizedClosures/no_limit_keeps_everything224=== RUN TestSetClientTLS/rejects_connection_without_client_cert225=== PAUSE TestConvertHashToNix32/already_Nix32_format2262026/10/25 13:22:06 WARN Rate limiter backed off name=server-test rate=5227=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything228=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped229=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped230=== RUN TestFilterOversizedClosures/all_closures_skipped231=== CONT TestStreamPushReportsSignatures232=== CONT TestScriptTokenNoExpiryRerunsEveryCall233=== PAUSE TestParsePathInfoJSON/Lix_format234=== RUN TestEncodeNixBase32/test_string_hash235=== RUN TestParsePathInfoJSON/empty_input236=== RUN TestPartSizeForNAR/zero_stays_at_minimum237=== RUN TestUploadMultipart_SupersededByPeer/exists238=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI239--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)240=== RUN TestSupersededNARStillUploadsListing/dump_cut_short241=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error242=== RUN TestConvertHashToNix32/invalid_format243=== PAUSE TestSetClientTLSErrors/missing_cert_file244=== CONT TestClientSignaturesByStorePath245=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert246=== PAUSE TestFilterOversizedClosures/all_closures_skipped247=== PAUSE TestEncodeNixBase32/test_string_hash248=== PAUSE TestParsePathInfoJSON/empty_input2492026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:343772502026/10/25 13:22:06 ERROR Upload failed error=boom count=1251--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.03s)252--- PASS: TestStreamPushReportsSkippedPaths (0.00s)253--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.03s)254--- PASS: TestStreamPushReportsSignatures (0.04s)255--- PASS: TestClientSignaturesByStorePath (0.00s)256=== PAUSE TestUploadMultipart_SupersededByPeer/exists257=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum258=== RUN TestPartSizeForNAR/small_stays_at_minimum259=== PAUSE TestPartSizeForNAR/small_stays_at_minimum260=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum261=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum262=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short263=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI264=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error265=== PAUSE TestConvertHashToNix32/invalid_format266=== CONT TestStreamPushRequestLine267=== RUN TestSetClientTLSErrors/missing_key_file268=== PAUSE TestSetClientTLSErrors/missing_key_file269=== RUN TestSetClientTLSErrors/missing_ca_file270=== PAUSE TestSetClientTLSErrors/missing_ca_file271=== RUN TestSetClientTLSErrors/invalid_ca_file272=== CONT TestCaseHackSuffix273--- PASS: TestDumpPathSingleFile (0.04s)274=== CONT TestRegisterUploadedObjectReusesConnections275=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica2762026/10/25 13:22:06 ERROR Upload failed error=boom count=1277=== RUN TestEncodeNixBase32/empty_input278=== PAUSE TestEncodeNixBase32/empty_input279=== RUN TestParsePathInfoJSON/whitespace_only280=== PAUSE TestParsePathInfoJSON/whitespace_only281=== RUN TestParsePathInfoJSON/invalid_JSON282=== PAUSE TestParsePathInfoJSON/invalid_JSON283=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry284=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts2852026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:34377286=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts287=== RUN TestPartSizeForNAR/1_TiB288=== PAUSE TestPartSizeForNAR/1_TiB289=== RUN TestPartSizeForNAR/5_TiB_S3_max_object290=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object291=== RUN TestPartSizeForNAR/capped_at_5_GiB292=== PAUSE TestPartSizeForNAR/capped_at_5_GiB293=== RUN TestUploadMultipart_SupersededByPeer/missing294=== PAUSE TestUploadMultipart_SupersededByPeer/missing295=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths2962026/10/25 13:22:06 INFO Garbage collection started297=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails298=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails299=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths300--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)301 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)302 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)303=== CONT TestRateLimiterFeedback/429_enables_limiter304=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512305=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter306=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512307=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun3082026/10/25 13:22:06 WARN Rate limiter enabled after throttle name=server-test rate=5309=== CONT TestRateLimiterFeedback/503_enables_limiter3102026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:40959311=== PAUSE TestSetClientTLSErrors/invalid_ca_file312=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA313=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA314=== RUN TestSetClientTLS/preserves_debug_logging_transport315=== PAUSE TestSetClientTLS/preserves_debug_logging_transport3162026/10/25 13:22:06 WARN Rate limiter backed off name=server-test rate=5317=== CONT TestPathInfoCACompatibility/null_ca_field318=== CONT TestStreamPushGivesUpOnDeadServer319=== CONT TestPathInfoCACompatibility/new_structured_format_-_text3202026/10/25 13:22:06 INFO Garbage collection started321=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter322=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method3232026/10/25 13:22:06 WARN Rate limiter enabled after throttle name=server-test rate=53242026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:395673252026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:34377326=== CONT TestFilterOversizedClosures/all_closures_skipped3272026/10/25 13:22:06 ERROR Upload failed error="connection refused" count=203282026/10/25 13:22:06 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=50329=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3302026/10/25 13:22:06 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=0331=== CONT TestFilterOversizedClosures/no_limit_keeps_everything3322026/10/25 13:22:06 ERROR Server seems unavailable, giving up on batch untried=17333=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive334=== CONT TestConvertHashToNix32/already_Nix32_format335=== CONT TestEncodeNixBase32/test_string_hash3362026/10/25 13:22:06 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=2000337--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)3382026/10/25 13:22:06 WARN Rate limiter backed off name=server-test rate=5339=== CONT TestParsePathInfoJSON/Nix_format3402026/10/25 13:22:06 WARN Rate limiter enabled after throttle name=s3-test rate=5341=== CONT TestParsePathInfoJSON/invalid_JSON3422026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:37291343=== CONT TestPartSizeForNAR/capped_at_5_GiB344=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error3452026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:34377346=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error347=== CONT TestUploadMultipart_SupersededByPeer/exists3482026/10/25 13:22:06 WARN Garbage collection finished on another replica. Its statistics are not available here349=== CONT TestConvertHashToNix32/SRI_format_to_Nix32350=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum351=== CONT TestConvertHashToNix32/invalid_format352=== CONT TestPathInfoCACompatibility/old_string_format_-_text353=== CONT TestEncodeNixBase32/empty_input354=== CONT TestParsePathInfoJSON/empty_input355=== CONT TestParsePathInfoJSON/whitespace_only356--- PASS: TestRateLimiterFeedback (0.00s)357 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)358 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)359 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)360 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)361=== CONT TestPartSizeForNAR/zero_stays_at_minimum362=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512363=== CONT TestPartSizeForNAR/5_TiB_S3_max_object364=== CONT TestPartSizeForNAR/1_TiB365=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI3662026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:34377367=== CONT TestSetClientTLS/preserves_debug_logging_transport368=== CONT TestSetClientTLSErrors/missing_cert_file369=== CONT TestPartSizeForNAR/small_stays_at_minimum370=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA371=== CONT TestSupersededNARStillUploadsListing/small_NAR372=== CONT TestUploadMultipart_SupersededByPeer/missing373=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails374=== CONT TestSupersededNARStillUploadsListing/dump_cut_short375=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)376=== CONT TestParsePathInfoJSON/Lix_format377--- PASS: TestFilterOversizedClosures (0.04s)378 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)379 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)380 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)381=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon382=== CONT TestSetClientTLS/rejects_connection_without_client_cert383=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts384=== CONT TestSetClientTLSErrors/invalid_ca_file385=== CONT TestSetClientTLSErrors/missing_ca_file386=== CONT TestGetStorePathHash/valid_store_path387=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error388=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error389=== CONT TestSetClientTLSErrors/missing_key_file3902026/10/25 13:22:06 INFO Uploading abc-hello (1.0GB)391=== CONT TestGetStorePathHash/basename_without_hyphen_should_error392--- PASS: TestScriptTokenCachesUntilRefresh (0.07s)393--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.00s)394--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.00s)395--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.00s)396--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)397--- PASS: TestEncodeNixBase32 (0.17s)398 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)399 --- PASS: TestEncodeNixBase32/empty_input (0.00s)400--- PASS: TestParsePathInfoJSON (0.20s)401 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)402 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)403 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)404 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)405 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)406--- PASS: TestPathInfoCACompatibility (0.13s)407 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)408 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)409 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)410 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)411 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)412--- PASS: TestConvertHashToNix32 (0.20s)413 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)414 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)415 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)416--- PASS: TestPathInfoHashCompatibility (0.07s)417 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)418 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)419 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)420 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)421--- PASS: TestPartSizeForNAR (0.17s)422 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)423 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)424 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)425 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)426 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)427 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)428 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)429--- PASS: TestGetStorePathHash (0.20s)430 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)431 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)432 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)433 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)4342026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:34377435--- PASS: TestSetClientTLSErrors (0.20s)436 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)437 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)438 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)439 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)4402026/10/25 13:22:06 INFO Uploading abc-hello (1.0GB)441--- PASS: TestUploadMultipart_SupersededByPeer (0.04s)442 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)443 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.13s)4442026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:343774452026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:34377446--- PASS: TestStreamPushBatchesUnderLoad (0.21s)447--- PASS: TestCaseHackSuffix (0.14s)4482026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:343774492026/10/25 13:22:06 http: TLS handshake error from 127.0.0.1:56406: remote error: tls: bad certificate4502026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:34377451--- PASS: TestSetClientTLS (0.07s)452 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.13s)453 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.13s)454 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.14s)455--- PASS: TestStreamPushRequestLine (0.14s)4562026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:343774572026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:343774582026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:34377459--- PASS: TestRegisterUploadedObjectReusesConnections (0.15s)4602026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:343774612026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:343774622026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:343774632026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:343774642026/10/25 13:22:06 WARN Rate limiter enabled after throttle name=s3-test rate=54652026/10/25 13:22:06 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:34377466--- PASS: TestDumpPathWriterError (0.22s)467--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.22s)4682026/10/25 13:22:06 INFO Uploading abc-hello (1.0GB)4692026/10/25 13:22:06 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:46573/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:46573/part/24702026/10/25 13:22:06 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"471--- PASS: TestDumpPathMatchesNix (0.26s)472--- PASS: TestSupersededNARStillUploadsListing (0.07s)473 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.14s)474 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.14s)475 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.67s)476--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.77s)477--- PASS: TestUploadMultipart_PartsInParallel (0.78s)478--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4792026/10/25 13:22:07 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:36611/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:36611/api/uploads/complete4802026/10/25 13:22:07 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4812026/10/25 13:22:07 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:36611/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:36611/api/uploads/complete4822026/10/25 13:22:07 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4832026/10/25 13:22:07 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:36611/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:36611/api/uploads/complete4842026/10/25 13:22:07 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"485--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)486PASS487Running server tests...488The files belonging to this database system will be owned by user "nixbld".489This user must also own the server process.490491The database cluster will be initialized with locale "C".492The default database encoding has accordingly been set to "SQL_ASCII".493The default text search configuration will be set to "english".494495Data page checksums are enabled.496497creating directory /build/postgres3673288814/data ... ok498creating subdirectories ... ok499selecting dynamic shared memory implementation ... posix500selecting default "max_connections" ... 100501selecting default "shared_buffers" ... 128MB502selecting default time zone ... UTC503creating configuration files ... ok504running bootstrap script ... ok505performing post-bootstrap initialization ... ok506syncing data to disk ... ok507508initdb: warning: enabling "trust" authentication for local connections509initdb: 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.510511Success. You can now start the database server using:512513 pg_ctl -D /build/postgres3673288814/data -l logfile start514515/build/postgres3673288814:5432 - no response5162026-10-25 13:22:08.527 UTC [127] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit5172026-10-25 13:22:08.528 UTC [127] LOG: listening on Unix socket "/build/postgres3673288814/.s.PGSQL.5432"5182026-10-25 13:22:08.532 UTC [134] LOG: database system was shut down at 2026-10-25 13:22:08 UTC5192026-10-25 13:22:08.535 UTC [127] LOG: database system is ready to accept connections520/build/postgres3673288814:5432 - accepting connections521=== RUN TestService_AuthMiddleware522=== PAUSE TestService_AuthMiddleware523=== RUN TestService_AuthMiddleware_MTLSProxyHeader524=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader525=== RUN TestService_AuthMiddleware_MTLSBoundSubjects526=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects527=== RUN TestService_ReadAuthMiddleware528=== PAUSE TestService_ReadAuthMiddleware529=== RUN TestService_AuthMiddleware_OIDC530=== PAUSE TestService_AuthMiddleware_OIDC531=== RUN TestService_RequireScope_OIDC532=== PAUSE TestService_RequireScope_OIDC533=== RUN TestService_ReadScope_PublicByDefault534=== PAUSE TestService_ReadScope_PublicByDefault535=== RUN TestCacheConfigHandler536=== PAUSE TestCacheConfigHandler537=== RUN TestCacheStatsHandler538=== PAUSE TestCacheStatsHandler539=== RUN TestClientCADerivations540=== PAUSE TestClientCADerivations541=== RUN TestClientErrorHandling542=== PAUSE TestClientErrorHandling543=== RUN TestClientIntegration544=== PAUSE TestClientIntegration545=== RUN TestClientMultipleUploads546=== PAUSE TestClientMultipleUploads547=== RUN TestClientWithDependencies548=== PAUSE TestClientWithDependencies549=== RUN TestClientSharedPathCommittedMidPush550=== PAUSE TestClientSharedPathCommittedMidPush551=== RUN TestPinProtectsFromGC552=== PAUSE TestPinProtectsFromGC553=== RUN TestClientPushesUseOnePush554=== PAUSE TestClientPushesUseOnePush555=== RUN TestClientFallsBackToClosures556=== PAUSE TestClientFallsBackToClosures557=== RUN TestDeleteClosuresRacingPins558=== PAUSE TestDeleteClosuresRacingPins559=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock560=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock561=== RUN TestResolveDBConnectionString562=== PAUSE TestResolveDBConnectionString563=== RUN TestConnectWaitsForAPeerMigration564=== PAUSE TestConnectWaitsForAPeerMigration565=== RUN TestLeadElectsOneAndHandsOver566=== PAUSE TestLeadElectsOneAndHandsOver567=== RUN TestLeadIncumbentWinsAfterRestart5682026/10/25 13:22:09 INFO lead: acquired remote=192.0.2.1:12345692026/10/25 13:22:09 INFO lead: released remote=192.0.2.1:12345702026/10/25 13:22:09 INFO lead: acquired remote=192.0.2.1:12345712026/10/25 13:22:10 INFO lead: released remote=192.0.2.1:1234572--- PASS: TestLeadIncumbentWinsAfterRestart (1.88s)573=== RUN TestLeadIncumbentAnnouncesAtOnce574=== PAUSE TestLeadIncumbentAnnouncesAtOnce575=== RUN TestLeadEndsOnShutdown576=== PAUSE TestLeadEndsOnShutdown577=== RUN TestLeadEndsWhenItsConnectionHangs5782026/10/25 13:22:11 INFO lead: acquired remote=192.0.2.1:12345792026-10-25 13:22:12.691 UTC [318] FATAL: terminating connection due to administrator command5802026/10/25 13:22:12 INFO lead: acquired remote=192.0.2.1:12345812026/10/25 13:22:13 WARN lead: lock connection lost error="timeout: context deadline exceeded"5822026/10/25 13:22:13 INFO lead: released remote=192.0.2.1:12345832026/10/25 13:22:14 INFO lead: released remote=192.0.2.1:1234584--- PASS: TestLeadEndsWhenItsConnectionHangs (3.18s)585=== RUN TestGCAdvisoryLockBlocksConcurrentRun586=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun587=== RUN TestGCBugBareHashReferences588=== PAUSE TestGCBugBareHashReferences589=== RUN TestGCMetrics590=== PAUSE TestGCMetrics591=== RUN TestPushDedupSurvivesConcurrentGC592=== PAUSE TestPushDedupSurvivesConcurrentGC593=== RUN TestDeduplicatedObjectsRecordedAsPending594=== PAUSE TestDeduplicatedObjectsRecordedAsPending595=== RUN TestGCSweepSkipsPendingObjects596=== PAUSE TestGCSweepSkipsPendingObjects597=== RUN TestTombstonedObjectOfferedWithoutWaiting598=== PAUSE TestTombstonedObjectOfferedWithoutWaiting599=== RUN TestGCSweepDeliversEachKeyOnce600=== PAUSE TestGCSweepDeliversEachKeyOnce601=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection602=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection603=== RUN TestForceGCDuringPushOffersSweptObject604=== PAUSE TestForceGCDuringPushOffersSweptObject605=== RUN TestFailedS3DeleteKeepsTombstone606=== PAUSE TestFailedS3DeleteKeepsTombstone607=== RUN TestSweepSkipsRowsLockedByPush608=== PAUSE TestSweepSkipsRowsLockedByPush609=== RUN TestRegisterCompletedObjectNeedsPendingRow610=== PAUSE TestRegisterCompletedObjectNeedsPendingRow611=== RUN TestGetExistingObjectsLocksRows612=== PAUSE TestGetExistingObjectsLocksRows613=== RUN TestSweepRechecksPendingAfterLocking614=== PAUSE TestSweepRechecksPendingAfterLocking615=== RUN TestPushWaitsForSweepHoldingRow616=== PAUSE TestPushWaitsForSweepHoldingRow617=== RUN TestCommitRacingPendingCleanupKeepsObjects618=== PAUSE TestCommitRacingPendingCleanupKeepsObjects619=== RUN TestGCEndsOnShutdown620=== PAUSE TestGCEndsOnShutdown621=== RUN TestGCTaskStore_StartNew622=== PAUSE TestGCTaskStore_StartNew623=== RUN TestGCTaskStore_DeduplicateSameParams624=== PAUSE TestGCTaskStore_DeduplicateSameParams625=== RUN TestGCTaskStore_ConflictDifferentParams626=== PAUSE TestGCTaskStore_ConflictDifferentParams627=== RUN TestGCTaskStore_GetEmpty628=== PAUSE TestGCTaskStore_GetEmpty629=== RUN TestGCTaskStore_GetReturnsLatest630=== PAUSE TestGCTaskStore_GetReturnsLatest631=== RUN TestGCTaskStore_CompletedAllowsNewTask632=== PAUSE TestGCTaskStore_CompletedAllowsNewTask633=== RUN TestGCTaskStore_PhaseUpdates634=== PAUSE TestGCTaskStore_PhaseUpdates635=== RUN TestGCTaskStore_Fail636=== PAUSE TestGCTaskStore_Fail637=== RUN TestGracefulShutdownDrainsInflight638=== PAUSE TestGracefulShutdownDrainsInflight639=== RUN TestService_healthCheckHandler640=== PAUSE TestService_healthCheckHandler641=== RUN TestService_readinessHandler642=== PAUSE TestService_readinessHandler643=== RUN TestGenerateLandingPage644=== PAUSE TestGenerateLandingPage645=== RUN TestCacheConfigHandlerMaxNarSize646=== PAUSE TestCacheConfigHandlerMaxNarSize647=== RUN TestCreatePendingClosureRejectsOversizedNAR648=== PAUSE TestCreatePendingClosureRejectsOversizedNAR649=== RUN TestNARDeduplicationMetadataUploadBug650=== PAUSE TestNARDeduplicationMetadataUploadBug651=== RUN TestMetricsInventory652=== PAUSE TestMetricsInventory653=== RUN TestMetricsCommit654=== PAUSE TestMetricsCommit655=== RUN TestService_NativeMTLS656=== PAUSE TestService_NativeMTLS657=== RUN TestServerTLSConfig658=== PAUSE TestServerTLSConfig659=== RUN TestMultipartCleanup660=== PAUSE TestMultipartCleanup661=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded662=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded663=== RUN TestPendingCleanupUsesOneCutoff664=== PAUSE TestPendingCleanupUsesOneCutoff665=== RUN TestObjectStatsTrigger666=== PAUSE TestObjectStatsTrigger667=== RUN TestObjectStatsLargeCommit668=== PAUSE TestObjectStatsLargeCommit669=== RUN TestOrphanedObjectsGC670=== PAUSE TestOrphanedObjectsGC671=== RUN TestOrphanedObjectsGCStressTest672=== PAUSE TestOrphanedObjectsGCStressTest673=== RUN TestCreatePin_ReservedPins674=== PAUSE TestCreatePin_ReservedPins675=== RUN TestPresentReportsOnlyClosureRoots676=== PAUSE TestPresentReportsOnlyClosureRoots677=== RUN TestPresentRefreshesOnlyStaleClosures678=== PAUSE TestPresentRefreshesOnlyStaleClosures679=== RUN TestPresentNotReportedWhileGCDeletesClosure680=== PAUSE TestPresentNotReportedWhileGCDeletesClosure681=== RUN TestParseSingleRange682=== PAUSE TestParseSingleRange683=== RUN TestProxyHeadersOnlyTrustedOnSocket6842026/10/25 13:22:14 INFO Starting HTTP server address=proxy.sock6852026/10/25 13:22:14 INFO Starting HTTP server address=127.0.0.1:439576862026/10/25 13:22:14 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6872026/10/25 13:22:14 INFO Shutdown signal received, draining in-flight requests timeout=10s688--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.09s)689=== RUN TestIsValidCachePath690=== PAUSE TestIsValidCachePath691=== RUN TestReadProxyNarinfo692=== PAUSE TestReadProxyNarinfo693=== RUN TestReadProxyNarinfoAlreadyDecompressed694=== PAUSE TestReadProxyNarinfoAlreadyDecompressed695=== RUN TestReadProxyContentNegotiation696=== PAUSE TestReadProxyContentNegotiation697=== RUN TestReadProxyNarStreaming698=== PAUSE TestReadProxyNarStreaming699=== RUN TestReadProxy404700=== PAUSE TestReadProxy404701=== RUN TestReadProxyInvalidPath702=== PAUSE TestReadProxyInvalidPath703=== RUN TestReadProxyHead704=== PAUSE TestReadProxyHead705=== RUN TestReadProxyOutlastsServerWriteTimeout706=== PAUSE TestReadProxyOutlastsServerWriteTimeout707=== RUN TestReadProxyConditionalGet708=== PAUSE TestReadProxyConditionalGet709=== RUN TestReadProxyRootRedirectsToIndexHTML710=== PAUSE TestReadProxyRootRedirectsToIndexHTML711=== RUN TestReadProxyDisabled712=== PAUSE TestReadProxyDisabled713=== RUN TestReadRedirectNar714=== PAUSE TestReadRedirectNar715=== RUN TestReadRedirectKeepsNarinfoProxied716=== PAUSE TestReadRedirectKeepsNarinfoProxied717=== RUN TestReadProxyRangeRequest718=== PAUSE TestReadProxyRangeRequest719=== RUN TestReadRedirectUsesPublicS3URL720=== PAUSE TestReadRedirectUsesPublicS3URL721=== RUN TestPush_OverlappingRootsStoreOneRowPerKey722=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey723=== RUN TestPush_CompleteCommitsEveryRoot724=== PAUSE TestPush_CompleteCommitsEveryRoot725=== RUN TestPush_RepeatedRootCommitsOnce726=== PAUSE TestPush_RepeatedRootCommitsOnce727=== RUN TestPush_CompleteWaitsForCleanupOfThePush728=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush729=== RUN TestPush_RootsAreLockedInByteOrder730=== PAUSE TestPush_RootsAreLockedInByteOrder731=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit732=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit733=== RUN TestPush_RejectsBadRequests734=== PAUSE TestPush_RejectsBadRequests735=== RUN TestPush_SignsNarinfosOfItsPendingObjects736=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects737=== RUN TestRedundantMultipartUpload738=== PAUSE TestRedundantMultipartUpload739=== RUN TestCompleteMultipartUpload_ErrorButObjectExists740=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists741=== RUN TestCompletedNarNotReofferedAcrossClosures742=== PAUSE TestCompletedNarNotReofferedAcrossClosures743=== RUN TestPresignedUploadRegisteredBeforeCommit744=== PAUSE TestPresignedUploadRegisteredBeforeCommit745=== RUN TestService_Rustfstest746=== PAUSE TestService_Rustfstest747=== RUN TestParseSize748=== PAUSE TestParseSize749=== RUN TestSkippedUploadsHandler750=== PAUSE TestSkippedUploadsHandler751=== RUN TestSystemdListenerNotActivated752--- PASS: TestSystemdListenerNotActivated (0.00s)753=== RUN TestWatchdogBeatsWhenHealthy754--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)755=== RUN TestWatchdogSkipsWhenUnhealthy7562026/10/25 13:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7572026/10/25 13:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7582026/10/25 13:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7592026/10/25 13:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/25 13:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7612026/10/25 13:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7622026/10/25 13:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7632026/10/25 13:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7642026/10/25 13:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7652026/10/25 13:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"766--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)767=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle768=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle769=== RUN TestProxyWriteTimeout770=== PAUSE TestProxyWriteTimeout771=== RUN TestPendingClosureWriteTimeout772=== PAUSE TestPendingClosureWriteTimeout773=== RUN TestIsValidUploadKey774=== PAUSE TestIsValidUploadKey775=== RUN TestUploadHandlersRejectInvalidKeys776=== PAUSE TestUploadHandlersRejectInvalidKeys777=== RUN TestUploadHandlersRejectOversizedBody778=== PAUSE TestUploadHandlersRejectOversizedBody779=== RUN TestService_cleanupPendingClosuresHandler780=== PAUSE TestService_cleanupPendingClosuresHandler781=== RUN TestService_createPendingClosureHandler782=== PAUSE TestService_createPendingClosureHandler783=== RUN TestService_verifyS3Integrity784=== PAUSE TestService_verifyS3Integrity785=== RUN TestCompleteMultipartUnregistered786=== PAUSE TestCompleteMultipartUnregistered787=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT788=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT789=== CONT TestService_AuthMiddleware790=== CONT TestPendingClosureWriteTimeout791=== CONT TestServerTLSConfig792=== RUN TestServerTLSConfig/no_client_CA793=== PAUSE TestServerTLSConfig/no_client_CA794=== RUN TestServerTLSConfig/missing_CA_file795=== PAUSE TestServerTLSConfig/missing_CA_file796=== CONT TestTombstonedObjectOfferedWithoutWaiting797=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT798=== CONT TestCompleteMultipartUnregistered799=== CONT TestService_verifyS3Integrity800=== CONT TestService_createPendingClosureHandler801=== CONT TestService_cleanupPendingClosuresHandler802=== CONT TestUploadHandlersRejectOversizedBody803=== CONT TestUploadHandlersRejectInvalidKeys804=== CONT TestIsValidUploadKey805=== CONT TestService_NativeMTLS806=== CONT TestMetricsCommit807=== CONT TestMetricsInventory808=== CONT TestNARDeduplicationMetadataUploadBug809=== CONT TestCreatePendingClosureRejectsOversizedNAR810=== CONT TestCacheConfigHandlerMaxNarSize811=== CONT TestGenerateLandingPage812=== CONT TestService_readinessHandler813=== CONT TestService_healthCheckHandler814--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)815=== CONT TestGCTaskStore_CompletedAllowsNewTask8162026/10/25 13:22:14 INFO Received uploads request method=POST path=/api/pending_closures817=== CONT TestGracefulShutdownDrainsInflight818=== CONT TestGCTaskStore_Fail819=== CONT TestRegisterCompletedObjectNeedsPendingRow820=== CONT TestGCTaskStore_PhaseUpdates821=== RUN TestPendingClosureWriteTimeout/empty822=== RUN TestServerTLSConfig/not_a_PEM_file823=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info824=== RUN TestIsValidUploadKey/narinfo825--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)826--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)827--- PASS: TestGCTaskStore_Fail (0.00s)828--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)829=== PAUSE TestIsValidUploadKey/narinfo830=== CONT TestGetExistingObjectsLocksRows831=== CONT TestSweepSkipsRowsLockedByPush832=== PAUSE TestPendingClosureWriteTimeout/empty833=== PAUSE TestServerTLSConfig/not_a_PEM_file834=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info835=== CONT TestSweepRechecksPendingAfterLocking836=== RUN TestIsValidUploadKey/nar_zst837=== RUN TestPendingClosureWriteTimeout/400_objects838=== CONT TestFailedS3DeleteKeepsTombstone839=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal840--- PASS: TestGenerateLandingPage (0.00s)8412026/10/25 13:22:14 INFO Starting HTTP server address=127.0.0.1:34947842=== PAUSE TestIsValidUploadKey/nar_zst843=== PAUSE TestPendingClosureWriteTimeout/400_objects844=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal845=== CONT TestForceGCDuringPushOffersSweptObject8462026/10/25 13:22:14 INFO Shutdown signal received, draining in-flight requests timeout=10s847=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows848=== RUN TestIsValidUploadKey/nar_xz849=== PAUSE TestIsValidUploadKey/nar_xz850=== RUN TestPendingClosureWriteTimeout/670k_objects851=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key852=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows853=== RUN TestIsValidUploadKey/nar_plain854=== PAUSE TestIsValidUploadKey/nar_plain855=== PAUSE TestPendingClosureWriteTimeout/670k_objects856=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline857=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline858=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key859=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key860=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key861=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check862=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check863=== 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=== RUN TestIsValidUploadKey/build_log_plus_in_name870=== PAUSE TestIsValidUploadKey/build_log_plus_in_name871=== RUN TestIsValidUploadKey/build_log_question_mark872=== PAUSE TestIsValidUploadKey/build_log_question_mark873=== RUN TestIsValidUploadKey/build_log_equals874=== PAUSE TestIsValidUploadKey/build_log_equals875=== RUN TestIsValidUploadKey/realisation876=== PAUSE TestIsValidUploadKey/realisation877=== RUN TestIsValidUploadKey/realisation_plus_in_output878=== PAUSE TestIsValidUploadKey/realisation_plus_in_output879=== RUN TestIsValidUploadKey/nix-cache-info880=== PAUSE TestIsValidUploadKey/nix-cache-info881=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection882=== CONT TestGCSweepDeliversEachKeyOnce883=== CONT TestGCTaskStore_DeduplicateSameParams884--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)885=== RUN TestIsValidUploadKey/index.html886=== PAUSE TestIsValidUploadKey/index.html887=== RUN TestIsValidUploadKey/narinfo_key,_nar_type888=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type889=== CONT TestGCTaskStore_GetReturnsLatest890--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)891=== CONT TestPushWaitsForSweepHoldingRow892=== RUN TestIsValidUploadKey/nar_key,_narinfo_type893=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type894=== RUN TestIsValidUploadKey/listing_key,_narinfo_type895=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type896=== RUN TestIsValidUploadKey/traversal897=== PAUSE TestIsValidUploadKey/traversal898=== RUN TestIsValidUploadKey/traversal_nar899=== PAUSE TestIsValidUploadKey/traversal_nar900=== RUN TestIsValidUploadKey/absolute901=== PAUSE TestIsValidUploadKey/absolute902=== RUN TestIsValidUploadKey/empty_key903=== PAUSE TestIsValidUploadKey/empty_key904=== RUN TestIsValidUploadKey/unknown_type905=== PAUSE TestIsValidUploadKey/unknown_type906=== CONT TestGCTaskStore_GetEmpty907--- PASS: TestGCTaskStore_GetEmpty (0.00s)908=== CONT TestGCTaskStore_ConflictDifferentParams909--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)910=== CONT TestGCTaskStore_StartNew911--- PASS: TestGCTaskStore_StartNew (0.00s)912=== CONT TestReadProxyRootRedirectsToIndexHTML913--- PASS: TestGracefulShutdownDrainsInflight (0.14s)914=== CONT TestGCEndsOnShutdown915=== RUN TestGCEndsOnShutdown/before_the_run916=== PAUSE TestGCEndsOnShutdown/before_the_run917=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete918=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete919=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark920=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark921=== CONT TestProxyWriteTimeout922=== RUN TestProxyWriteTimeout/narinfo923=== PAUSE TestProxyWriteTimeout/narinfo924=== RUN TestProxyWriteTimeout/1_GiB_nar925=== PAUSE TestProxyWriteTimeout/1_GiB_nar926=== RUN TestProxyWriteTimeout/10_GiB_nar927=== PAUSE TestProxyWriteTimeout/10_GiB_nar928=== RUN TestProxyWriteTimeout/unknown_size929=== PAUSE TestProxyWriteTimeout/unknown_size930=== CONT TestCommitRacingPendingCleanupKeepsObjects931=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts932=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts933=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure934=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure935=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart936=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart937=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle9382026/10/25 13:22:14 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"939--- PASS: TestService_AuthMiddleware (0.30s)940=== CONT TestSkippedUploadsHandler9412026/10/25 13:22:14 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000942--- PASS: TestSkippedUploadsHandler (0.01s)943=== CONT TestClientPushesUseOnePush9442026/10/25 13:22:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9452026/10/25 13:22:14 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst946--- PASS: TestCompleteMultipartUnregistered (0.32s)947=== CONT TestParseSize948--- PASS: TestParseSize (0.00s)949=== CONT TestGCSweepSkipsPendingObjects9502026/10/25 13:22:14 INFO Received uploads request method=POST path=/api/pending_closures9512026/10/25 13:22:14 INFO Received uploads request method=POST path=/api/pending_closures952--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.37s)953=== CONT TestService_Rustfstest9542026/10/25 13:22:14 INFO Received uploads request method=POST path=/api/pending_closures9552026/10/25 13:22:14 INFO Received uploads request method=POST path=/api/pending_closures9562026/10/25 13:22:14 INFO Received uploads request method=POST path=/api/pending_closures9572026/10/25 13:22:14 INFO Received cleanup request method=DELETE path=/api/pending_closures9582026/10/25 13:22:14 INFO Aborted multipart uploads count=0 kept=09592026/10/25 13:22:14 INFO Received uploads request method=POST path=/api/pending_closures9602026/10/25 13:22:14 INFO Received cleanup request method=DELETE path=/api/pending_closures9612026/10/25 13:22:14 INFO Aborted multipart uploads count=1 kept=09622026/10/25 13:22:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9632026-10-25 13:22:14.830 UTC [398] ERROR: Closure does not exist: id=19642026-10-25 13:22:14.830 UTC [398] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9652026-10-25 13:22:14.830 UTC [398] STATEMENT: -- name: CommitPendingClosure :one966 SELECT commit_pending_closure($1::bigint)::bigint967 968--- PASS: TestService_cleanupPendingClosuresHandler (0.41s)969=== CONT TestDeduplicatedObjectsRecordedAsPending9702026/10/25 13:22:14 INFO Received push request method=POST path=/api/pushes9712026/10/25 13:22:14 INFO Received complete push request method=POST path=/api/pushes/1/complete9722026/10/25 13:22:14 WARN mTLS auth: subject not in bound subjects subject="CN=reader"9732026/10/25 13:22:14 WARN mTLS auth: subject not in bound subjects subject="CN=reader"974--- PASS: TestService_NativeMTLS (0.43s)975=== CONT TestPresignedUploadRegisteredBeforeCommit9762026/10/25 13:22:14 INFO Completed push id=1 objects=4 duration=7.890901ms9772026/10/25 13:22:14 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete9782026/10/25 13:22:14 INFO Completed upload id=2 objects=2 duration=2.04279ms979--- PASS: TestMetricsCommit (0.44s)980=== CONT TestCompletedNarNotReofferedAcrossClosures9812026/10/25 13:22:14 INFO Received uploads request method=POST path=/api/pending_closures9822026/10/25 13:22:14 WARN readiness check failed error="closed pool"983--- PASS: TestService_readinessHandler (0.46s)984=== CONT TestPushDedupSurvivesConcurrentGC985--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.47s)986=== CONT TestCompleteMultipartUpload_ErrorButObjectExists987--- PASS: TestMetricsInventory (0.51s)988=== CONT TestGCMetrics9892026/10/25 13:22:14 INFO Received uploads request method=POST path=/api/pending_closures990=== NAME TestNARDeduplicationMetadataUploadBug991 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug420985264/001/store/brcd9amh8n5a0k4idkkl4dgrr945dfc0-file1.txt992--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.53s)993=== CONT TestRedundantMultipartUpload994--- PASS: TestService_healthCheckHandler (0.68s)995=== CONT TestPush_SignsNarinfosOfItsPendingObjects9962026/10/25 13:22:15 INFO Received push request method=POST path=/api/pushes9972026/10/25 13:22:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9982026/10/25 13:22:15 INFO Uploading brcd9amh8n5a0k4idkkl4dgrr945dfc0-file1.txt (160B)9992026/10/25 13:22:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10002026/10/25 13:22:15 WARN Failed to register uploaded object key=brcd9amh8n5a0k4idkkl4dgrr945dfc0.ls error="server returned 404: 404 page not found\n"10012026/10/25 13:22:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10022026/10/25 13:22:15 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"10032026/10/25 13:22:15 INFO Signed narinfos id=1 count=110042026/10/25 13:22:15 INFO Uploading 1 narinfos10052026/10/25 13:22:15 INFO Received complete push request method=POST path=/api/pushes/1/complete10062026/10/25 13:22:15 WARN Failed to register uploaded object key=brcd9amh8n5a0k4idkkl4dgrr945dfc0.narinfo error="server returned 404: 404 page not found\n"10072026/10/25 13:22:15 INFO Completed push id=1 objects=3 duration=11.115312ms10082026/10/25 13:22:15 INFO Upload complete. (118ms)1009=== NAME TestNARDeduplicationMetadataUploadBug1010 metadata_upload_test.go:54: Retrieved narinfo from S3:1011 StorePath: /build/TestNARDeduplicationMetadataUploadBug420985264/001/store/brcd9amh8n5a0k4idkkl4dgrr945dfc0-file1.txt1012 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1013 Compression: zstd1014 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1015 NarSize: 1601016 References: 1017 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1018 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1019 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1020 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}10212026/10/25 13:22:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10222026/10/25 13:22:15 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NTg5ZDlhNTgtZDY5Zi00NmEzLTllMTEtYzRjMDVkMzI2YzhmLjFhYTI1NGM5LTZiNDItNDM4OS1hOTAyLTY5ZGU1MmI1ZDE2OXgxNzkyOTM0NTM0NzgwMDI2NDg5 parts=1010232026/10/25 13:22:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10242026/10/25 13:22:15 INFO Completed upload id=1 objects=2 duration=2.142691ms10252026/10/25 13:22:15 INFO Received uploads request method=POST path=/api/pending_closures10262026/10/25 13:22:15 INFO Received uploads request method=POST path=/api/pending_closures10272026/10/25 13:22:15 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10282026/10/25 13:22:15 WARN Found objects in DB but missing from S3, will re-upload count=110292026/10/25 13:22:15 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NTg5ZDlhNTgtZDY5Zi00NmEzLTllMTEtYzRjMDVkMzI2YzhmLmE3YWQ4MTE4LTA0OWYtNDdlYi1iZWYzLWMwY2ZmNmMxZTA0NngxNzkyOTM0NTM0ODAyODk1OTUy parts=1010302026/10/25 13:22:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1031--- PASS: TestService_verifyS3Integrity (0.84s)1032=== CONT TestPush_RejectsBadRequests1033--- PASS: TestGetExistingObjectsLocksRows (0.84s)1034=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit10352026/10/25 13:22:15 INFO Completed upload id=1 objects=2 duration=1.877591ms10362026/10/25 13:22:15 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010372026/10/25 13:22:15 INFO Received uploads request method=POST path=/api/pending_closures10382026/10/25 13:22:15 INFO Starting cleanup of old closures method=DELETE path=/api/closures10392026/10/25 13:22:15 INFO Aborted multipart uploads count=0 kept=01040=== NAME TestNARDeduplicationMetadataUploadBug1041 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug420985264/001/store/b20hj4l8xjdxcfdqwjs2fmvi06w9qf42-file2.txt10422026/10/25 13:22:15 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=010432026/10/25 13:22:15 INFO Vacuumed table table=pending_closures10442026/10/25 13:22:15 INFO Vacuumed table table=pending_objects10452026/10/25 13:22:15 INFO Vacuumed table table=multipart_uploads10462026/10/25 13:22:15 INFO Aborted multipart uploads count=0 kept=010472026/10/25 13:22:15 INFO Vacuumed table table=closures10482026/10/25 13:22:15 INFO Vacuumed table table=objects10492026/10/25 13:22:15 WARN Force mode enabled - objects will be deleted immediately without grace period10502026/10/25 13:22:15 INFO Received uploads request method=POST path=/api/pending_closures10512026/10/25 13:22:15 INFO Aborted multipart uploads count=0 kept=010522026/10/25 13:22:15 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=010532026/10/25 13:22:15 INFO Vacuumed table table=pending_closures10542026/10/25 13:22:15 INFO Vacuumed table table=pending_objects10552026/10/25 13:22:15 INFO Vacuumed table table=multipart_uploads10562026/10/25 13:22:15 INFO Vacuumed table table=closures10572026/10/25 13:22:15 WARN Force mode enabled - objects will be deleted immediately without grace period10582026/10/25 13:22:15 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001059--- PASS: TestService_createPendingClosureHandler (0.90s)1060=== CONT TestGCBugBareHashReferences10612026/10/25 13:22:15 INFO Vacuumed table table=objects1062--- PASS: TestGCSweepDeliversEachKeyOnce (0.82s)10632026/10/25 13:22:15 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=01064=== CONT TestPush_RootsAreLockedInByteOrder10652026/10/25 13:22:15 INFO Vacuumed table table=pending_closures10662026/10/25 13:22:15 INFO Vacuumed table table=pending_objects10672026/10/25 13:22:15 INFO Vacuumed table table=multipart_uploads10682026/10/25 13:22:15 INFO Vacuumed table table=closures10692026/10/25 13:22:15 INFO Vacuumed table table=objects10702026/10/25 13:22:15 INFO Aborted multipart uploads count=0 kept=010712026/10/25 13:22:15 WARN Force mode enabled - objects will be deleted immediately without grace period10722026/10/25 13:22:15 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=010732026/10/25 13:22:15 INFO Vacuumed table table=pending_closures10742026/10/25 13:22:15 INFO Vacuumed table table=pending_objects10752026/10/25 13:22:15 INFO Vacuumed table table=multipart_uploads10762026/10/25 13:22:15 INFO Vacuumed table table=closures10772026/10/25 13:22:15 INFO Aborted multipart uploads count=0 kept=010782026/10/25 13:22:15 INFO Vacuumed table table=objects10792026/10/25 13:22:15 INFO Received push request method=POST path=/api/pushes1080--- PASS: TestSweepSkipsRowsLockedByPush (0.92s)1081=== CONT TestGCAdvisoryLockBlocksConcurrentRun10822026/10/25 13:22:15 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)10832026/10/25 13:22:15 WARN Force mode enabled - objects will be deleted immediately without grace period1084--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.85s)1085=== CONT TestPush_CompleteWaitsForCleanupOfThePush10862026/10/25 13:22:15 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign10872026/10/25 13:22:15 WARN Failed to register uploaded object key=b20hj4l8xjdxcfdqwjs2fmvi06w9qf42.ls error="server returned 404: 404 page not found\n"10882026/10/25 13:22:15 INFO Signed narinfos id=2 count=110892026/10/25 13:22:15 INFO Uploading 1 narinfos10902026/10/25 13:22:15 INFO Received complete push request method=POST path=/api/pushes/2/complete10912026/10/25 13:22:15 WARN Failed to register uploaded object key=b20hj4l8xjdxcfdqwjs2fmvi06w9qf42.narinfo error="server returned 404: 404 page not found\n"10922026/10/25 13:22:15 INFO Completed push id=2 objects=3 duration=1.88009ms10932026/10/25 13:22:15 INFO Upload complete. (50ms)1094=== NAME TestNARDeduplicationMetadataUploadBug1095 metadata_upload_test.go:76: Retrieved narinfo from S3:1096 StorePath: /build/TestNARDeduplicationMetadataUploadBug420985264/001/store/b20hj4l8xjdxcfdqwjs2fmvi06w9qf42-file2.txt1097 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1098 Compression: zstd1099 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1100 NarSize: 1601101 References: 1102 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1103 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1104 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1105 {"version":1,"root":{"type":"regular","size":44}}11062026/10/25 13:22:15 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=01107--- PASS: TestNARDeduplicationMetadataUploadBug (0.94s)1108=== CONT TestPush_RepeatedRootCommitsOnce11092026/10/25 13:22:15 INFO Vacuumed table table=pending_closures11102026/10/25 13:22:15 INFO Vacuumed table table=pending_objects11112026/10/25 13:22:15 INFO Vacuumed table table=multipart_uploads11122026/10/25 13:22:15 INFO Vacuumed table table=closures11132026/10/25 13:22:15 INFO Vacuumed table table=objects1114--- PASS: TestSweepRechecksPendingAfterLocking (0.94s)1115=== CONT TestLeadEndsOnShutdown11162026/10/25 13:22:15 INFO Received uploads request method=POST path=/api/pending_closures11172026/10/25 13:22:15 INFO Aborted multipart uploads count=0 kept=011182026/10/25 13:22:15 WARN Force mode enabled - objects will be deleted immediately without grace period11192026/10/25 13:22:15 INFO Received uploads request method=POST path=/api/pending_closures11202026/10/25 13:22:15 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."11212026/10/25 13:22:15 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1122--- PASS: TestFailedS3DeleteKeepsTombstone (0.98s)1123=== CONT TestPush_CompleteCommitsEveryRoot11242026/10/25 13:22:15 INFO Aborted multipart uploads count=0 kept=011252026/10/25 13:22:15 WARN Force mode enabled - objects will be deleted immediately without grace period11262026/10/25 13:22:15 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=011272026/10/25 13:22:15 INFO Vacuumed table table=pending_closures11282026/10/25 13:22:15 INFO Vacuumed table table=pending_objects11292026/10/25 13:22:15 INFO Vacuumed table table=multipart_uploads11302026/10/25 13:22:15 INFO Vacuumed table table=closures11312026/10/25 13:22:15 INFO Vacuumed table table=objects1132--- PASS: TestPushWaitsForSweepHoldingRow (0.95s)1133=== CONT TestLeadIncumbentAnnouncesAtOnce11342026/10/25 13:22:15 INFO Received uploads request method=POST path=/api/pending_closures1135--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.89s)1136=== CONT TestPush_OverlappingRootsStoreOneRowPerKey1137--- PASS: TestService_Rustfstest (0.68s)1138=== CONT TestLeadElectsOneAndHandsOver11392026/10/25 13:22:15 INFO Aborted multipart uploads count=0 kept=011402026/10/25 13:22:15 WARN Force mode enabled - objects will be deleted immediately without grace period11412026/10/25 13:22:15 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=011422026/10/25 13:22:15 INFO Vacuumed table table=pending_closures11432026/10/25 13:22:15 INFO Vacuumed table table=pending_objects11442026/10/25 13:22:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11452026/10/25 13:22:15 INFO Vacuumed table table=multipart_uploads11462026/10/25 13:22:15 INFO Vacuumed table table=closures11472026/10/25 13:22:15 INFO Vacuumed table table=objects11482026/10/25 13:22:15 INFO Received uploads request method=POST path=/api/pending_closures1149--- PASS: TestGCSweepSkipsPendingObjects (0.75s)1150=== CONT TestReadRedirectUsesPublicS3URL1151--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.67s)1152=== CONT TestReadProxyRangeRequest11532026/10/25 13:22:15 INFO Received uploads request method=POST path=/api/pending_closures11542026/10/25 13:22:15 INFO Received uploads request method=POST path=/api/pending_closures11552026/10/25 13:22:15 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst11562026/10/25 13:22:15 INFO Received uploads request method=POST path=/api/pending_closures1157--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.69s)1158=== CONT TestConnectWaitsForAPeerMigration11592026/10/25 13:22:15 INFO Received uploads request method=POST path=/api/pending_closures11602026/10/25 13:22:15 INFO Aborted multipart uploads count=0 kept=011612026/10/25 13:22:15 WARN Force mode enabled - objects will be deleted immediately without grace period11622026/10/25 13:22:15 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=011632026/10/25 13:22:15 INFO Vacuumed table table=pending_closures11642026/10/25 13:22:15 INFO Vacuumed table table=pending_objects11652026/10/25 13:22:15 INFO Vacuumed table table=multipart_uploads11662026/10/25 13:22:15 INFO Received uploads request method=POST path=/api/pending_closures11672026/10/25 13:22:15 INFO Vacuumed table table=closures11682026/10/25 13:22:15 INFO Vacuumed table table=objects1169--- PASS: TestGCMetrics (0.65s)1170=== CONT TestReadRedirectKeepsNarinfoProxied1171--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (1.10s)1172=== CONT TestResolveDBConnectionString1173=== RUN TestResolveDBConnectionString/flag_wins1174=== PAUSE TestResolveDBConnectionString/flag_wins1175=== RUN TestResolveDBConnectionString/file_when_flag_empty1176=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1177=== RUN TestResolveDBConnectionString/missing_file_is_an_error1178=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1179=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1180=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1181=== RUN TestResolveDBConnectionString/nothing_configured1182=== PAUSE TestResolveDBConnectionString/nothing_configured1183=== CONT TestReadRedirectNar11842026/10/25 13:22:15 INFO Received push request method=POST path=/api/pushes11852026/10/25 13:22:15 INFO Received uploads request method=POST path=/api/pending_closures11862026/10/25 13:22:15 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)11872026/10/25 13:22:15 INFO Uploading 2n4jm8z5x112kfnxl48fvpxbi0y6018z-shared-dep (136B)11882026/10/25 13:22:15 INFO Uploading yjsn0hi4npxq2sbmrz4h315s4v11k5cz-b (216B)11892026/10/25 13:22:15 WARN Failed to register uploaded object key=72qw8nh7qrmarx4hxa7j0pq5bysr0a8d.ls error="server returned 404: 404 page not found\n"11902026/10/25 13:22:15 WARN Failed to register uploaded object key=yjsn0hi4npxq2sbmrz4h315s4v11k5cz.ls error="server returned 404: 404 page not found\n"11912026/10/25 13:22:15 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11922026/10/25 13:22:15 WARN Failed to register uploaded object key=2n4jm8z5x112kfnxl48fvpxbi0y6018z.ls error="server returned 404: 404 page not found\n"11932026/10/25 13:22:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11942026/10/25 13:22:15 WARN Failed to register uploaded object key=nar/189lx86m61q4d7dkznx1i59qn4nh1yhaz3g8vky9pxhfllz5cc20.nar.zst error="server returned 404: 404 page not found\n"11952026/10/25 13:22:15 INFO Signed narinfos id=1 count=311962026/10/25 13:22:15 INFO Uploading 3 narinfos11972026/10/25 13:22:15 INFO Received uploads request method=POST path=/api/pending_closures11982026/10/25 13:22:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11992026/10/25 13:22:15 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NTg5ZDlhNTgtZDY5Zi00NmEzLTllMTEtYzRjMDVkMzI2YzhmLjdmMzRkNzJhLTBmYjYtNGM2MS1hMDExLTJiYWEwNGY0NGZiY3gxNzkyOTM0NTM1NTk2MDI2NTQx12002026/10/25 13:22:15 WARN Failed to register uploaded object key=2n4jm8z5x112kfnxl48fvpxbi0y6018z.narinfo error="server returned 404: 404 page not found\n"12012026/10/25 13:22:15 INFO Received complete push request method=POST path=/api/pushes/1/complete12022026/10/25 13:22:15 WARN Failed to register uploaded object key=72qw8nh7qrmarx4hxa7j0pq5bysr0a8d.narinfo error="server returned 404: 404 page not found\n"12032026/10/25 13:22:15 WARN Failed to register uploaded object key=yjsn0hi4npxq2sbmrz4h315s4v11k5cz.narinfo error="server returned 404: 404 page not found\n"12042026/10/25 13:22:15 INFO Completed push id=1 objects=8 duration=5.53525ms12052026/10/25 13:22:15 INFO Upload complete. (58ms)1206=== NAME TestClientPushesUseOnePush1207 client_pushes_test.go:97: Retrieved narinfo from S3:1208 StorePath: /build/TestClientPushesUseOnePush4061816681/001/store/2n4jm8z5x112kfnxl48fvpxbi0y6018z-shared-dep1209 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1210 Compression: zstd1211 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821212 NarSize: 1361213 References: 1214 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n12152026/10/25 13:22:15 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NTg5ZDlhNTgtZDY5Zi00NmEzLTllMTEtYzRjMDVkMzI2YzhmLjdmMzRkNzJhLTBmYjYtNGM2MS1hMDExLTJiYWEwNGY0NGZiY3gxNzkyOTM0NTM1NTk2MDI2NTQx parts=112162026/10/25 13:22:15 INFO Received push request method=POST path=/api/pushes1217--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.74s)1218=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1219=== NAME TestClientPushesUseOnePush1220 client_pushes_test.go:97: Retrieved narinfo from S3:1221 StorePath: /build/TestClientPushesUseOnePush4061816681/001/store/72qw8nh7qrmarx4hxa7j0pq5bysr0a8d-a1222 URL: nar/189lx86m61q4d7dkznx1i59qn4nh1yhaz3g8vky9pxhfllz5cc20.nar.zst1223 Compression: zstd1224 NarHash: sha256:189lx86m61q4d7dkznx1i59qn4nh1yhaz3g8vky9pxhfllz5cc201225 NarSize: 2161226 References: /build/TestClientPushesUseOnePush4061816681/001/store/2n4jm8z5x112kfnxl48fvpxbi0y6018z-shared-dep1227 CA: text:sha256:0iyki3zrfxf8jjg2chzw3ab47hdmwhg4h3i9nldd80fgpfkj77br1228 client_pushes_test.go:97: Retrieved narinfo from S3:1229 StorePath: /build/TestClientPushesUseOnePush4061816681/001/store/yjsn0hi4npxq2sbmrz4h315s4v11k5cz-b1230 URL: nar/189lx86m61q4d7dkznx1i59qn4nh1yhaz3g8vky9pxhfllz5cc20.nar.zst1231 Compression: zstd1232 NarHash: sha256:189lx86m61q4d7dkznx1i59qn4nh1yhaz3g8vky9pxhfllz5cc201233 NarSize: 2161234 References: /build/TestClientPushesUseOnePush4061816681/001/store/2n4jm8z5x112kfnxl48fvpxbi0y6018z-shared-dep1235 CA: text:sha256:0iyki3zrfxf8jjg2chzw3ab47hdmwhg4h3i9nldd80fgpfkj77br1236--- PASS: TestClientPushesUseOnePush (0.90s)1237=== CONT TestReadProxyDisabled12382026/10/25 13:22:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12392026/10/25 13:22:15 INFO Signed narinfos id=1 count=112402026/10/25 13:22:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12412026/10/25 13:22:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12422026/10/25 13:22:15 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"12432026/10/25 13:22:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12442026/10/25 13:22:15 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"12452026/10/25 13:22:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12462026/10/25 13:22:15 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=112472026/10/25 13:22:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12482026/10/25 13:22:15 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1249--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.53s)1250=== CONT TestDeleteClosuresRacingPins12512026/10/25 13:22:15 INFO Aborted multipart uploads count=0 kept=01252=== RUN TestPush_RejectsBadRequests/no_roots1253=== PAUSE TestPush_RejectsBadRequests/no_roots1254=== RUN TestPush_RejectsBadRequests/no_objects1255=== PAUSE TestPush_RejectsBadRequests/no_objects1256=== RUN TestPush_RejectsBadRequests/bad_root1257=== PAUSE TestPush_RejectsBadRequests/bad_root1258=== RUN TestPush_RejectsBadRequests/root_not_in_objects1259=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1260=== CONT TestClientFallsBackToClosures12612026/10/25 13:22:15 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=012622026/10/25 13:22:15 INFO Vacuumed table table=pending_closures12632026/10/25 13:22:15 INFO Vacuumed table table=pending_objects12642026/10/25 13:22:15 INFO Vacuumed table table=multipart_uploads12652026/10/25 13:22:15 INFO Received push request method=POST path=/api/pushes12662026/10/25 13:22:15 INFO Vacuumed table table=closures12672026/10/25 13:22:15 INFO Vacuumed table table=objects12682026/10/25 13:22:15 INFO Aborted multipart uploads count=0 kept=012692026/10/25 13:22:15 WARN Force mode enabled - objects will be deleted immediately without grace period12702026/10/25 13:22:15 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=012712026/10/25 13:22:15 INFO Vacuumed table table=pending_closures12722026/10/25 13:22:15 INFO Vacuumed table table=pending_objects12732026/10/25 13:22:15 INFO Vacuumed table table=multipart_uploads12742026/10/25 13:22:15 INFO Vacuumed table table=closures12752026/10/25 13:22:15 INFO Received complete push request method=POST path=/api/pushes/1/complete12762026/10/25 13:22:15 INFO Vacuumed table table=objects1277--- PASS: TestPushDedupSurvivesConcurrentGC (0.83s)1278=== CONT TestService_AuthMiddleware_OIDC12792026/10/25 13:22:15 INFO Received push request method=POST path=/api/pushes12802026/10/25 13:22:15 INFO Completed push id=1 objects=4 duration=19.716253ms12812026/10/25 13:22:15 INFO Received push request method=POST path=/api/pushes12822026/10/25 13:22:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42527/oidc12832026-10-25 13:22:15.842 UTC [745] ERROR: could not obtain lock on row in relation "closures"12842026-10-25 13:22:15.842 UTC [745] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT12852026-10-25 13:22:15.842 UTC [745] ERROR: could not obtain lock on row in relation "closures"12862026-10-25 13:22:15.842 UTC [745] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT12872026-10-25 13:22:15.843 UTC [745] ERROR: could not obtain lock on row in relation "closures"12882026-10-25 13:22:15.843 UTC [745] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT12892026-10-25 13:22:15.843 UTC [745] ERROR: could not obtain lock on row in relation "closures"12902026-10-25 13:22:15.843 UTC [745] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT12912026-10-25 13:22:15.843 UTC [745] ERROR: could not obtain lock on row in relation "closures"12922026-10-25 13:22:15.843 UTC [745] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1293--- PASS: TestPush_RootsAreLockedInByteOrder (0.55s)1294=== CONT TestService_ReadScope_PublicByDefault12952026/10/25 13:22:15 INFO Aborted multipart uploads count=0 kept=012962026/10/25 13:22:15 WARN Force mode enabled - objects will be deleted immediately without grace period1297--- PASS: TestGCBugBareHashReferences (0.69s)1298=== CONT TestService_RequireScope_OIDC12992026/10/25 13:22:16 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"1300--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.67s)1301=== CONT TestCacheConfigHandler1302=== RUN TestCacheConfigHandler/full_config,_no_issuer1303=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1304=== RUN TestCacheConfigHandler/no_cache_url_configured1305=== PAUSE TestCacheConfigHandler/no_cache_url_configured1306=== RUN TestCacheConfigHandler/no_signing_keys1307=== PAUSE TestCacheConfigHandler/no_signing_keys1308=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1309=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1310=== CONT TestService_AuthMiddleware_MTLSBoundSubjects13112026/10/25 13:22:16 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=013122026/10/25 13:22:16 INFO Vacuumed table table=pending_closures13132026/10/25 13:22:16 INFO Vacuumed table table=pending_objects13142026/10/25 13:22:16 INFO Vacuumed table table=multipart_uploads13152026/10/25 13:22:16 INFO Vacuumed table table=closures13162026/10/25 13:22:16 INFO Received push request method=POST path=/api/pushes13172026/10/25 13:22:16 INFO Vacuumed table table=objects13182026/10/25 13:22:16 INFO Received complete push request method=POST path=/api/pushes/2/complete13192026/10/25 13:22:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43509/oidc13202026/10/25 13:22:16 INFO Completed push id=2 objects=4 duration=6.382311ms1321--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.78s)1322=== CONT TestService_AuthMiddleware_MTLSProxyHeader13232026/10/25 13:22:16 INFO Received push request method=POST path=/api/pushes13242026/10/25 13:22:16 INFO lead: acquired remote=192.0.2.1:123413252026/10/25 13:22:16 INFO Received complete push request method=POST path=/api/pushes/1/complete13262026/10/25 13:22:16 INFO Completed push id=1 objects=4 duration=18.336932ms1327--- PASS: TestPush_RepeatedRootCommitsOnce (0.74s)1328=== CONT TestService_ReadAuthMiddleware13292026/10/25 13:22:16 INFO Received push request method=POST path=/api/pushes13302026/10/25 13:22:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13312026/10/25 13:22:16 INFO Received complete push request method=POST path=/api/pushes/1/complete13322026/10/25 13:22:16 INFO lead: acquired remote=192.0.2.1:123413332026/10/25 13:22:16 INFO lead: released remote=192.0.2.1:12341334--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.67s)1335=== CONT TestCacheStatsHandler13362026/10/25 13:22:16 INFO Completed push id=1 objects=6 duration=7.476061ms1337--- PASS: TestPush_CompleteCommitsEveryRoot (0.71s)1338=== CONT TestClientSharedPathCommittedMidPush13392026/10/25 13:22:16 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NTg5ZDlhNTgtZDY5Zi00NmEzLTllMTEtYzRjMDVkMzI2YzhmLmFhNTg3MzdiLTI1ZDgtNDc2NS1hNTFiLTVhOTc2Y2RjZWM4NngxNzkyOTM0NTM1NTM0MjA0OTc0 parts=1213402026/10/25 13:22:16 INFO Received uploads request method=POST path=/api/pending_closures1341--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.26s)1342=== CONT TestClientMultipleUploads1343--- PASS: TestService_ReadScope_PublicByDefault (0.28s)1344=== CONT TestClientIntegration13452026/10/25 13:22:16 INFO Received push request method=POST path=/api/pushes13462026/10/25 13:22:16 INFO lead: acquired remote=192.0.2.1:12341347--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.74s)1348=== CONT TestPinProtectsFromGC1349--- PASS: TestReadRedirectUsesPublicS3URL (0.73s)1350=== CONT TestClientWithDependencies13512026/10/25 13:22:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1352--- PASS: TestReadProxyRangeRequest (0.75s)1353=== CONT TestClientErrorHandling1354=== RUN TestClientErrorHandling/InvalidStorePath1355=== PAUSE TestClientErrorHandling/InvalidStorePath1356=== RUN TestClientErrorHandling/InvalidAuthToken1357=== PAUSE TestClientErrorHandling/InvalidAuthToken1358=== RUN TestClientErrorHandling/ServerNotAvailable1359=== PAUSE TestClientErrorHandling/ServerNotAvailable1360=== CONT TestClientCADerivations13612026/10/25 13:22:16 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NTg5ZDlhNTgtZDY5Zi00NmEzLTllMTEtYzRjMDVkMzI2YzhmLmNhNTI5NjBmLTI2NDgtNGJkOC04MWZlLTljODFjZWQzZGEyZXgxNzkyOTM0NTM1NjExNjMyOTgz parts=121362--- PASS: TestReadRedirectKeepsNarinfoProxied (0.68s)1363=== CONT TestParseSingleRange1364=== RUN TestParseSingleRange/none1365=== PAUSE TestParseSingleRange/none1366=== RUN TestParseSingleRange/unknown_unit1367=== PAUSE TestParseSingleRange/unknown_unit1368=== RUN TestParseSingleRange/multi-range_ignored1369=== PAUSE TestParseSingleRange/multi-range_ignored13702026/10/25 13:22:16 INFO Received uploads request method=POST path=/api/pending_closures1371=== RUN TestParseSingleRange/malformed_no_dash1372=== PAUSE TestParseSingleRange/malformed_no_dash1373=== RUN TestParseSingleRange/malformed_both_empty1374=== PAUSE TestParseSingleRange/malformed_both_empty1375=== RUN TestParseSingleRange/malformed_end_before_start1376=== PAUSE TestParseSingleRange/malformed_end_before_start1377=== RUN TestParseSingleRange/closed1378=== PAUSE TestParseSingleRange/closed1379=== RUN TestParseSingleRange/open-ended1380=== PAUSE TestParseSingleRange/open-ended1381=== RUN TestParseSingleRange/end_clamped_to_size1382=== PAUSE TestParseSingleRange/end_clamped_to_size1383=== RUN TestParseSingleRange/suffix1384=== PAUSE TestParseSingleRange/suffix1385=== RUN TestParseSingleRange/suffix_exceeds_size1386=== PAUSE TestParseSingleRange/suffix_exceeds_size1387=== RUN TestParseSingleRange/single_byte1388=== PAUSE TestParseSingleRange/single_byte1389=== RUN TestParseSingleRange/start_past_EOF1390=== PAUSE TestParseSingleRange/start_past_EOF1391=== RUN TestParseSingleRange/start_far_past_EOF1392=== PAUSE TestParseSingleRange/start_far_past_EOF1393=== CONT TestOrphanedObjectsGC13942026/10/25 13:22:16 INFO Received uploads request method=POST path=/api/pending_closures1395--- PASS: TestReadRedirectNar (0.68s)1396=== CONT TestReadProxy4041397--- PASS: TestReadProxyDisabled (0.66s)1398=== CONT TestReadProxyNarStreaming13992026-10-25 13:22:16.357 UTC [762] ERROR: Push does not exist: id=114002026-10-25 13:22:16.357 UTC [762] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE14012026-10-25 13:22:16.357 UTC [762] STATEMENT: SELECT commit_push($1)1402--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (1.01s)1403=== CONT TestPresentNotReportedWhileGCDeletesClosure1404=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1405=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1406=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1407=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1408=== CONT TestReadProxyConditionalGet1409=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1410=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1411=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1412=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1413=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1414=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1415=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1416=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1417=== CONT TestReadProxyContentNegotiation14182026/10/25 13:22:16 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"14192026/10/25 13:22:16 WARN mTLS auth: bound subjects configured but subject DN unavailable14202026/10/25 13:22:16 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1421--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.40s)1422=== CONT TestPresentRefreshesOnlyStaleClosures1423--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.39s)1424=== CONT TestReadProxyOutlastsServerWriteTimeout1425=== RUN TestService_RequireScope_OIDC/builder_may_write1426=== PAUSE TestService_RequireScope_OIDC/builder_may_write1427=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1428=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1429=== RUN TestService_RequireScope_OIDC/ops_may_admin1430=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1431=== RUN TestService_RequireScope_OIDC/ops_may_not_write1432=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1433=== RUN TestService_RequireScope_OIDC/reader_may_not_write1434=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1435=== RUN TestService_RequireScope_OIDC/static_token_may_admin1436=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1437=== RUN TestService_RequireScope_OIDC/static_token_may_write1438=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1439=== RUN TestService_RequireScope_OIDC/reader_may_read1440=== PAUSE TestService_RequireScope_OIDC/reader_may_read1441=== RUN TestService_RequireScope_OIDC/writer_implies_read1442=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1443=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1444=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1445=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1446=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1447=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1448=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1449=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1450=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1451=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1452=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1453=== CONT TestPresentReportsOnlyClosureRoots1454--- PASS: TestService_ReadAuthMiddleware (0.38s)1455=== CONT TestOrphanedObjectsGCStressTest1456--- PASS: TestCacheStatsHandler (0.40s)1457=== CONT TestReadProxyNarinfo14582026/10/25 13:22:16 INFO Received uploads request method=POST path=/api/pending_closures14592026/10/25 13:22:16 INFO Received uploads request method=POST path=/api/pending_closures14602026/10/25 13:22:16 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14612026/10/25 13:22:16 INFO Uploading zcnx7g72lzpb78ny2snlh4kacl3j1l7b-shared-dep (136B)14622026/10/25 13:22:16 INFO Uploading j0w79d1spr39q4br07hjv03zasymabra-b (216B)14632026/10/25 13:22:16 WARN Failed to register uploaded object key=zcnx7g72lzpb78ny2snlh4kacl3j1l7b.ls error="server returned 404: 404 page not found\n"14642026/10/25 13:22:16 WARN Failed to register uploaded object key=bnxlrm607pmc46raxq3mwyd10q5v2snd.ls error="server returned 404: 404 page not found\n"14652026/10/25 13:22:16 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14662026/10/25 13:22:16 WARN Failed to register uploaded object key=nar/1ckdzx2krf30hbxkn2slzjkvr9q9b6bnlbxdagrh7w8kl6smja94.nar.zst error="server returned 404: 404 page not found\n"14672026/10/25 13:22:16 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14682026/10/25 13:22:16 WARN Failed to register uploaded object key=j0w79d1spr39q4br07hjv03zasymabra.ls error="server returned 404: 404 page not found\n"14692026/10/25 13:22:16 INFO Signed narinfos id=2 count=214702026/10/25 13:22:16 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14712026/10/25 13:22:16 INFO Signed narinfos id=1 count=214722026/10/25 13:22:16 INFO Uploading 4 narinfos14732026/10/25 13:22:16 WARN Failed to register uploaded object key=zcnx7g72lzpb78ny2snlh4kacl3j1l7b.narinfo error="server returned 404: 404 page not found\n"14742026/10/25 13:22:16 WARN Failed to register uploaded object key=bnxlrm607pmc46raxq3mwyd10q5v2snd.narinfo error="server returned 404: 404 page not found\n"14752026/10/25 13:22:16 WARN Failed to register uploaded object key=j0w79d1spr39q4br07hjv03zasymabra.narinfo error="server returned 404: 404 page not found\n"14762026/10/25 13:22:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14772026/10/25 13:22:16 WARN Failed to register uploaded object key=zcnx7g72lzpb78ny2snlh4kacl3j1l7b.narinfo error="server returned 404: 404 page not found\n"14782026/10/25 13:22:16 INFO Completed upload id=1 objects=6 duration=6.896171ms14792026/10/25 13:22:16 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14802026/10/25 13:22:16 INFO Completed upload id=2 objects=6 duration=2.11862ms14812026/10/25 13:22:16 INFO Upload complete. (70ms)1482=== NAME TestClientFallsBackToClosures1483 client_pushes_test.go:112: Retrieved narinfo from S3:1484 StorePath: /build/TestClientFallsBackToClosures959573404/001/store/zcnx7g72lzpb78ny2snlh4kacl3j1l7b-shared-dep1485 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1486 Compression: zstd1487 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821488 NarSize: 1361489 References: 1490 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1491 client_pushes_test.go:112: Retrieved narinfo from S3:1492 StorePath: /build/TestClientFallsBackToClosures959573404/001/store/bnxlrm607pmc46raxq3mwyd10q5v2snd-a1493 URL: nar/1ckdzx2krf30hbxkn2slzjkvr9q9b6bnlbxdagrh7w8kl6smja94.nar.zst1494 Compression: zstd1495 NarHash: sha256:1ckdzx2krf30hbxkn2slzjkvr9q9b6bnlbxdagrh7w8kl6smja941496 NarSize: 2161497 References: /build/TestClientFallsBackToClosures959573404/001/store/zcnx7g72lzpb78ny2snlh4kacl3j1l7b-shared-dep1498 CA: text:sha256:01kfxzycq23hjw4qp7ixz2mzva0dqrpcrxmb604yv55lh856klc11499 client_pushes_test.go:112: Retrieved narinfo from S3:1500 StorePath: /build/TestClientFallsBackToClosures959573404/001/store/j0w79d1spr39q4br07hjv03zasymabra-b1501 URL: nar/1ckdzx2krf30hbxkn2slzjkvr9q9b6bnlbxdagrh7w8kl6smja94.nar.zst1502 Compression: zstd1503 NarHash: sha256:1ckdzx2krf30hbxkn2slzjkvr9q9b6bnlbxdagrh7w8kl6smja941504 NarSize: 2161505 References: /build/TestClientFallsBackToClosures959573404/001/store/zcnx7g72lzpb78ny2snlh4kacl3j1l7b-shared-dep1506 CA: text:sha256:01kfxzycq23hjw4qp7ixz2mzva0dqrpcrxmb604yv55lh856klc11507--- PASS: TestClientFallsBackToClosures (0.94s)1508=== CONT TestReadProxyHead1509--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.97s)1510=== CONT TestIsValidCachePath1511=== RUN TestIsValidCachePath/narinfo1512=== PAUSE TestIsValidCachePath/narinfo1513=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1514=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1515=== RUN TestIsValidCachePath/nar_zst1516=== PAUSE TestIsValidCachePath/nar_zst1517=== RUN TestIsValidCachePath/nar_xz1518=== PAUSE TestIsValidCachePath/nar_xz1519=== RUN TestIsValidCachePath/nar_bz21520=== PAUSE TestIsValidCachePath/nar_bz21521=== RUN TestIsValidCachePath/nar_uncompressed1522=== PAUSE TestIsValidCachePath/nar_uncompressed1523=== RUN TestIsValidCachePath/ls1524=== PAUSE TestIsValidCachePath/ls1525=== RUN TestIsValidCachePath/log1526=== PAUSE TestIsValidCachePath/log1527=== RUN TestIsValidCachePath/realisation1528=== PAUSE TestIsValidCachePath/realisation1529=== RUN TestIsValidCachePath/nix-cache-info1530=== PAUSE TestIsValidCachePath/nix-cache-info1531=== RUN TestIsValidCachePath/index.html1532=== PAUSE TestIsValidCachePath/index.html1533=== RUN TestIsValidCachePath/traversal_parent1534=== PAUSE TestIsValidCachePath/traversal_parent1535=== RUN TestIsValidCachePath/traversal_in_middle1536=== PAUSE TestIsValidCachePath/traversal_in_middle1537=== RUN TestIsValidCachePath/invalid_char_e1538=== PAUSE TestIsValidCachePath/invalid_char_e1539=== RUN TestIsValidCachePath/invalid_char_u1540=== PAUSE TestIsValidCachePath/invalid_char_u1541=== RUN TestIsValidCachePath/random_path1542=== PAUSE TestIsValidCachePath/random_path1543=== RUN TestIsValidCachePath/empty1544=== PAUSE TestIsValidCachePath/empty1545=== RUN TestIsValidCachePath/leading_slash1546=== PAUSE TestIsValidCachePath/leading_slash1547=== RUN TestIsValidCachePath/wrong_extension1548=== PAUSE TestIsValidCachePath/wrong_extension1549=== RUN TestIsValidCachePath/short_hash1550=== PAUSE TestIsValidCachePath/short_hash1551=== CONT TestReadProxyInvalidPath1552=== NAME TestClientMultipleUploads1553 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads2918427772/001/store/nj3pcqmsxd5j9mzswh2aphk84g4dka53-test-file-0.txt1554=== NAME TestClientIntegration1555 client_integration_test.go:286: Created store path: /build/TestClientIntegration3549606541/002/store/p09x132b2zksll9xjz7jqgcqzsag676s-test-file.txt1556=== NAME TestClientMultipleUploads1557 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads2918427772/001/store/sk7rsy1jwvh514wkd8yc8abgrb5m5aml-test-file-1.txt15582026/10/25 13:22:16 INFO Received push request method=POST path=/api/pushes15592026/10/25 13:22:16 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)15602026/10/25 13:22:16 INFO Uploading rw2pcrjwcad4yvmzlj8pjlwlwqm0sgl4-shared-dep (136B)15612026/10/25 13:22:16 INFO Uploading 1kv4z9cbbf2x5kmhjkyk5l02vrvmh2lv-top (224B)15622026/10/25 13:22:16 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15632026/10/25 13:22:16 WARN Failed to register uploaded object key=rw2pcrjwcad4yvmzlj8pjlwlwqm0sgl4.ls error="server returned 404: 404 page not found\n"15642026/10/25 13:22:16 WARN Failed to register uploaded object key=nar/0jvb5xvmmgqdrqzxj2dm5cw939655xx476m2dwg6szgnyj7fx9dy.nar.zst error="server returned 404: 404 page not found\n"15652026/10/25 13:22:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15662026/10/25 13:22:16 WARN Failed to register uploaded object key=1kv4z9cbbf2x5kmhjkyk5l02vrvmh2lv.ls error="server returned 404: 404 page not found\n"15672026/10/25 13:22:16 INFO Signed narinfos id=1 count=215682026/10/25 13:22:16 INFO Uploading 2 narinfos15692026/10/25 13:22:16 WARN Failed to register uploaded object key=rw2pcrjwcad4yvmzlj8pjlwlwqm0sgl4.narinfo error="server returned 404: 404 page not found\n"15702026/10/25 13:22:16 INFO Received complete push request method=POST path=/api/pushes/1/complete15712026/10/25 13:22:16 WARN Failed to register uploaded object key=1kv4z9cbbf2x5kmhjkyk5l02vrvmh2lv.narinfo error="server returned 404: 404 page not found\n"15722026/10/25 13:22:16 INFO Completed push id=1 objects=6 duration=7.432721ms15732026/10/25 13:22:16 INFO Upload complete. (60ms)1574=== NAME TestClientSharedPathCommittedMidPush1575 client_integration_test.go:680: Retrieved narinfo from S3:1576 StorePath: /build/TestClientSharedPathCommittedMidPush2675929389/001/store/rw2pcrjwcad4yvmzlj8pjlwlwqm0sgl4-shared-dep1577 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1578 Compression: zstd1579 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821580 NarSize: 1361581 References: 1582 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1583 client_integration_test.go:680: Retrieved narinfo from S3:1584 StorePath: /build/TestClientSharedPathCommittedMidPush2675929389/001/store/1kv4z9cbbf2x5kmhjkyk5l02vrvmh2lv-top1585 URL: nar/0jvb5xvmmgqdrqzxj2dm5cw939655xx476m2dwg6szgnyj7fx9dy.nar.zst1586 Compression: zstd1587 NarHash: sha256:0jvb5xvmmgqdrqzxj2dm5cw939655xx476m2dwg6szgnyj7fx9dy1588 NarSize: 2241589 References: /build/TestClientSharedPathCommittedMidPush2675929389/001/store/rw2pcrjwcad4yvmzlj8pjlwlwqm0sgl4-shared-dep1590 CA: text:sha256:18z4nm31m03jd4am55n0yzz8wrz8sg467y361kzcmfxc8pbanwqy15912026/10/25 13:22:16 INFO Received push request method=POST path=/api/pushes1592--- PASS: TestClientSharedPathCommittedMidPush (0.69s)1593=== CONT TestCreatePin_ReservedPins15942026/10/25 13:22:16 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15952026/10/25 13:22:16 INFO Uploading p09x132b2zksll9xjz7jqgcqzsag676s-test-file.txt (152B)1596=== NAME TestClientMultipleUploads1597 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads2918427772/001/store/3f24i69mw4z0lc6pmgf75xc8a2300a2k-test-file-2.txt15982026/10/25 13:22:16 WARN Failed to register uploaded object key=p09x132b2zksll9xjz7jqgcqzsag676s.ls error="server returned 404: 404 page not found\n"15992026/10/25 13:22:16 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"16002026/10/25 13:22:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16012026/10/25 13:22:16 INFO Signed narinfos id=1 count=116022026/10/25 13:22:16 INFO Uploading 1 narinfos16032026/10/25 13:22:16 INFO Received complete push request method=POST path=/api/pushes/1/complete16042026/10/25 13:22:16 WARN Failed to register uploaded object key=p09x132b2zksll9xjz7jqgcqzsag676s.narinfo error="server returned 404: 404 page not found\n"16052026/10/25 13:22:16 INFO Completed push id=1 objects=3 duration=6.078791ms16062026/10/25 13:22:16 INFO Upload complete. (59ms)16072026/10/25 13:22:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16082026/10/25 13:22:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39081/oidc1609=== NAME TestPinProtectsFromGC16102026/10/25 13:22:16 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NTg5ZDlhNTgtZDY5Zi00NmEzLTllMTEtYzRjMDVkMzI2YzhmLjk3ZmY4NDNkLWJkNDgtNDI0YS1hNTI4LTBmMTk4YzgzMGU2NngxNzkyOTM0NTM2Mjc2MzY5MTk3 error="Get \"http://127.0.0.1:1/bucket37/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"1611 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC3247563235/001/store/v2zs2b9byr18p2631r01pxn5zkg6xhmv-pinned-file.txt16122026/10/25 13:22:16 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NTg5ZDlhNTgtZDY5Zi00NmEzLTllMTEtYzRjMDVkMzI2YzhmLjkyZjZkOTI4LWZkMjYtNGRhMC1hZDdiLWI4MjA0YThhMWYyMXgxNzkyOTM0NTM2MjcwMDYwOTI3 parts=121613 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC3247563235/001/store/gyjy40dx55wg81vp48ph02ljr71pz54p-unpinned-file.txt16142026/10/25 13:22:16 INFO Received cleanup request method=DELETE path=/api/pending_closures16152026/10/25 13:22:16 INFO Aborted multipart uploads count=1 kept=01616--- PASS: TestRedundantMultipartUpload (1.91s)1617=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded16182026/10/25 13:22:16 INFO All 1 paths already cached1619=== NAME TestClientIntegration1620 client_integration_test.go:312: Retrieved narinfo from S3:1621 StorePath: /build/TestClientIntegration3549606541/002/store/p09x132b2zksll9xjz7jqgcqzsag676s-test-file.txt1622 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1623 Compression: zstd1624 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11625 NarSize: 1521626 References: 1627 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11628 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1629 client_integration_test.go:313: Decompressed .ls content (64 bytes):1630 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1631 client_integration_test.go:316: Testing garbage collection...1632--- PASS: TestReadProxy404 (0.59s)1633=== CONT TestReadProxyNarinfoAlreadyDecompressed16342026/10/25 13:22:16 INFO Received push request method=POST path=/api/pushes1635--- PASS: TestReadProxyNarStreaming (0.59s)1636=== CONT TestMultipartCleanup1637=== NAME TestClientWithDependencies1638 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies123844963/001/store/yl56sapw7x40215fpjqnbbnd5wl9icpj-test-script16392026/10/25 13:22:16 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16402026/10/25 13:22:16 INFO Uploading nj3pcqmsxd5j9mzswh2aphk84g4dka53-test-file-0.txt (160B)16412026/10/25 13:22:16 INFO Uploading 3f24i69mw4z0lc6pmgf75xc8a2300a2k-test-file-2.txt (160B)16422026/10/25 13:22:16 INFO Uploading sk7rsy1jwvh514wkd8yc8abgrb5m5aml-test-file-1.txt (160B)16432026/10/25 13:22:16 WARN Failed to register uploaded object key=nj3pcqmsxd5j9mzswh2aphk84g4dka53.ls error="server returned 404: 404 page not found\n"16442026/10/25 13:22:16 WARN Failed to register uploaded object key=3f24i69mw4z0lc6pmgf75xc8a2300a2k.ls error="server returned 404: 404 page not found\n"16452026/10/25 13:22:16 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"16462026/10/25 13:22:16 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16472026/10/25 13:22:16 WARN Failed to register uploaded object key=sk7rsy1jwvh514wkd8yc8abgrb5m5aml.ls error="server returned 404: 404 page not found\n"16482026/10/25 13:22:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16492026/10/25 13:22:16 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16502026/10/25 13:22:16 INFO Signed narinfos id=1 count=316512026/10/25 13:22:16 INFO Uploading 3 narinfos16522026/10/25 13:22:16 WARN Failed to register uploaded object key=3f24i69mw4z0lc6pmgf75xc8a2300a2k.narinfo error="server returned 404: 404 page not found\n"16532026/10/25 13:22:16 INFO Received complete push request method=POST path=/api/pushes/1/complete16542026/10/25 13:22:16 WARN Failed to register uploaded object key=nj3pcqmsxd5j9mzswh2aphk84g4dka53.narinfo error="server returned 404: 404 page not found\n"16552026/10/25 13:22:16 WARN Failed to register uploaded object key=sk7rsy1jwvh514wkd8yc8abgrb5m5aml.narinfo error="server returned 404: 404 page not found\n"16562026/10/25 13:22:16 INFO Starting cleanup of old closures method=DELETE path=/api/closures16572026/10/25 13:22:16 INFO Garbage collection started1658--- PASS: TestReadProxyConditionalGet (0.55s)1659=== CONT TestPendingCleanupUsesOneCutoff16602026/10/25 13:22:16 INFO Completed push id=1 objects=9 duration=7.402501ms16612026/10/25 13:22:16 INFO Upload complete. (61ms)1662=== NAME TestClientMultipleUploads1663 client_integration_test.go:369: Uploaded 3 paths in 94.852891ms1664=== NAME TestClientCADerivations1665 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations291575301/001/store/v4q02wq3nssy0wpg1d3i5aalgsnqdl3b-ca-test16662026/10/25 13:22:16 INFO Aborted multipart uploads count=0 kept=016672026/10/25 13:22:16 WARN Force mode enabled - objects will be deleted immediately without grace period1668--- PASS: TestClientMultipleUploads (0.79s)1669=== CONT TestObjectStatsTrigger1670=== NAME TestClientWithDependencies1671 client_integration_test.go:615: Found 1 dependencies (including self)16722026/10/25 13:22:16 INFO Received push request method=POST path=/api/pushes16732026/10/25 13:22:16 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=016742026/10/25 13:22:16 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16752026/10/25 13:22:16 INFO Uploading v2zs2b9byr18p2631r01pxn5zkg6xhmv-pinned-file.txt (128B)1676=== NAME TestClientCADerivations1677 client_ca_test.go:139: Found 1 dependencies (including self)16782026/10/25 13:22:16 INFO Vacuumed table table=pending_closures16792026/10/25 13:22:16 WARN Failed to register uploaded object key=v2zs2b9byr18p2631r01pxn5zkg6xhmv.ls error="server returned 404: 404 page not found\n"16802026/10/25 13:22:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16812026/10/25 13:22:16 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16822026/10/25 13:22:16 INFO Signed narinfos id=1 count=116832026/10/25 13:22:16 INFO Uploading 1 narinfos16842026/10/25 13:22:16 INFO Vacuumed table table=pending_objects16852026/10/25 13:22:16 INFO Vacuumed table table=multipart_uploads1686--- PASS: TestPresentRefreshesOnlyStaleClosures (0.55s)1687=== CONT TestObjectStatsLargeCommit16882026/10/25 13:22:16 INFO Received complete push request method=POST path=/api/pushes/1/complete16892026/10/25 13:22:16 WARN Failed to register uploaded object key=v2zs2b9byr18p2631r01pxn5zkg6xhmv.narinfo error="server returned 404: 404 page not found\n"1690--- PASS: TestReadProxyContentNegotiation (0.58s)1691=== CONT TestServerTLSConfig/no_client_CA1692=== CONT TestServerTLSConfig/not_a_PEM_file1693=== CONT TestServerTLSConfig/missing_CA_file1694--- PASS: TestServerTLSConfig (0.01s)1695 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1696 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1697 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1698=== CONT TestPendingClosureWriteTimeout/empty1699=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline17002026/10/25 13:22:16 INFO Vacuumed table table=closures17012026/10/25 13:22:16 INFO Completed push id=1 objects=3 duration=6.385591ms17022026/10/25 13:22:16 INFO Upload complete. (81ms)17032026/10/25 13:22:16 INFO Vacuumed table table=objects17042026/10/25 13:22:17 INFO Received push request method=POST path=/api/pushes17052026/10/25 13:22:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17062026/10/25 13:22:17 INFO Uploading yl56sapw7x40215fpjqnbbnd5wl9icpj-test-script (136B)1707--- PASS: TestPresentReportsOnlyClosureRoots (0.54s)1708=== CONT TestPendingClosureWriteTimeout/670k_objects1709=== CONT TestPendingClosureWriteTimeout/400_objects1710=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17112026/10/25 13:22:17 INFO Received uploads request method=POST path=/1712=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17132026/10/25 13:22:17 INFO Received request for more parts method=POST path=/1714=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17152026/10/25 13:22:17 INFO Received complete multipart upload request method=POST path=/1716=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17172026/10/25 13:22:17 INFO Received uploads request method=POST path=/1718--- PASS: TestUploadHandlersRejectInvalidKeys (0.07s)1719 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1720 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1721 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1722 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1723=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows17242026/10/25 13:22:17 WARN Failed to register uploaded object key=yl56sapw7x40215fpjqnbbnd5wl9icpj.ls error="server returned 404: 404 page not found\n"17252026/10/25 13:22:17 WARN Failed to register uploaded object key=log/4xbknxw7zy69imdfj1451xfn33fnga1f-test-script.drv error="server returned 404: 404 page not found\n"17262026/10/25 13:22:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17272026/10/25 13:22:17 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"17282026/10/25 13:22:17 INFO Signed narinfos id=1 count=117292026/10/25 13:22:17 INFO Uploading 1 narinfos17302026/10/25 13:22:17 INFO Received complete push request method=POST path=/api/pushes/1/complete17312026/10/25 13:22:17 WARN Failed to register uploaded object key=yl56sapw7x40215fpjqnbbnd5wl9icpj.narinfo error="server returned 404: 404 page not found\n"17322026/10/25 13:22:17 INFO Completed push id=1 objects=4 duration=7.017901ms17332026/10/25 13:22:17 INFO Upload complete. (61ms)1734=== NAME TestClientWithDependencies1735 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies123844963/001/store) requires matching store prefix17362026/10/25 13:22:17 INFO Received push request method=POST path=/api/pushes1737--- PASS: TestClientWithDependencies (0.80s)1738=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check17392026/10/25 13:22:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17402026/10/25 13:22:17 INFO Uploading gyjy40dx55wg81vp48ph02ljr71pz54p-unpinned-file.txt (128B)17412026/10/25 13:22:17 WARN Failed to register uploaded object key=gyjy40dx55wg81vp48ph02ljr71pz54p.ls error="server returned 404: 404 page not found\n"17422026/10/25 13:22:17 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17432026/10/25 13:22:17 INFO Signed narinfos id=2 count=117442026/10/25 13:22:17 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"17452026/10/25 13:22:17 INFO Uploading 1 narinfos17462026/10/25 13:22:17 INFO Received complete push request method=POST path=/api/pushes/2/complete17472026/10/25 13:22:17 WARN Failed to register uploaded object key=gyjy40dx55wg81vp48ph02ljr71pz54p.narinfo error="server returned 404: 404 page not found\n"1748--- PASS: TestReadProxyInvalidPath (0.45s)1749=== CONT TestIsValidUploadKey/narinfo1750=== CONT TestIsValidUploadKey/realisation_plus_in_output1751=== CONT TestIsValidUploadKey/unknown_type1752=== CONT TestIsValidUploadKey/empty_key1753=== CONT TestIsValidUploadKey/absolute1754=== CONT TestIsValidUploadKey/traversal_nar1755=== CONT TestIsValidUploadKey/traversal1756=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1757=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1758=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1759=== CONT TestIsValidUploadKey/index.html1760=== CONT TestIsValidUploadKey/nix-cache-info1761=== CONT TestIsValidUploadKey/build_log_equals1762=== CONT TestIsValidUploadKey/realisation1763=== CONT TestIsValidUploadKey/build_log_question_mark1764=== CONT TestIsValidUploadKey/build_log_plus_in_name1765=== CONT TestIsValidUploadKey/nar_plain1766=== CONT TestIsValidUploadKey/build_log1767=== CONT TestIsValidUploadKey/listing1768=== CONT TestIsValidUploadKey/nar_xz1769=== CONT TestIsValidUploadKey/nar_zst1770=== CONT TestIsValidUploadKey/build_log_home-manager_file1771--- PASS: TestIsValidUploadKey (0.08s)1772 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1773 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1774 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1775 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1776 --- PASS: TestIsValidUploadKey/absolute (0.00s)1777 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1778 --- PASS: TestIsValidUploadKey/traversal (0.00s)1779 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1780 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1781 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1782 --- PASS: TestIsValidUploadKey/index.html (0.00s)1783 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1784 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1785 --- PASS: TestIsValidUploadKey/realisation (0.00s)1786 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1787 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1788 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1789 --- PASS: TestIsValidUploadKey/build_log (0.00s)1790 --- PASS: TestIsValidUploadKey/listing (0.00s)1791 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1792 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1793 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1794=== CONT TestGCEndsOnShutdown/before_the_run17952026/10/25 13:22:17 INFO Completed push id=2 objects=3 duration=2.77681ms17962026/10/25 13:22:17 INFO Upload complete. (50ms)17972026/10/25 13:22:17 INFO Received push request method=POST path=/api/pushes17982026/10/25 13:22:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17992026/10/25 13:22:17 INFO Uploading v4q02wq3nssy0wpg1d3i5aalgsnqdl3b-ca-test (144B)18002026/10/25 13:22:17 WARN Failed to register uploaded object key=v4q02wq3nssy0wpg1d3i5aalgsnqdl3b.ls error="server returned 404: 404 page not found\n"18012026/10/25 13:22:17 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18022026/10/25 13:22:17 WARN Failed to register uploaded object key=log/3f9wwbh2kla40pl97yxmjnijxakzxmbg-ca-test.drv error="server returned 404: 404 page not found\n"18032026/10/25 13:22:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18042026/10/25 13:22:17 INFO Signed narinfos id=1 count=118052026/10/25 13:22:17 INFO Uploading 1 narinfos18062026/10/25 13:22:17 INFO Received complete push request method=POST path=/api/pushes/1/complete18072026/10/25 13:22:17 WARN Failed to register uploaded object key=v4q02wq3nssy0wpg1d3i5aalgsnqdl3b.narinfo error="server returned 404: 404 page not found\n"1808--- PASS: TestReadProxyHead (0.48s)1809=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark18102026/10/25 13:22:17 INFO Starting cleanup of old closures method=DELETE path=/api/closures18112026/10/25 13:22:17 INFO Garbage collection started18122026/10/25 13:22:17 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1813--- PASS: TestReadProxyNarinfo (0.56s)1814=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete18152026/10/25 13:22:17 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux18162026/10/25 13:22:17 WARN Refused reserved pin name=worker-x86_64-linux18172026/10/25 13:22:17 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux18182026/10/25 13:22:17 INFO Received create pin request method=POST path=/api/pins/my-app18192026/10/25 13:22:17 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1820--- PASS: TestCreatePin_ReservedPins (0.28s)1821=== CONT TestProxyWriteTimeout/narinfo1822=== CONT TestProxyWriteTimeout/10_GiB_nar1823=== CONT TestProxyWriteTimeout/unknown_size1824=== CONT TestProxyWriteTimeout/1_GiB_nar1825--- PASS: TestProxyWriteTimeout (0.00s)1826 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1827 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1828 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1829 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1830=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18312026/10/25 13:22:17 INFO Received request for more parts method=POST path=/18322026/10/25 13:22:17 INFO Completed push id=1 objects=4 duration=18.420362ms18332026/10/25 13:22:17 INFO Upload complete. (104ms)1834=== NAME TestClientCADerivations1835 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations291575301/001/store/v4q02wq3nssy0wpg1d3i5aalgsnqdl3b-ca-test1836 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1837 Compression: zstd1838 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1839 NarSize: 1441840 References: 1841 Deriver: /build/TestClientCADerivations291575301/001/store/3f9wwbh2kla40pl97yxmjnijxakzxmbg-ca-test.drv1842 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1843 client_ca_test.go:185: Checking for realisation files in S3...1844 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1845 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache18462026/10/25 13:22:17 INFO Received uploads request method=POST path=/api/pending_closures18472026/10/25 13:22:17 INFO Aborted multipart uploads count=0 kept=018482026/10/25 13:22:17 WARN Force mode enabled - objects will be deleted immediately without grace period1849--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.25s)1850=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18512026/10/25 13:22:17 INFO Received complete multipart upload request method=POST path=/18522026/10/25 13:22:17 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=018532026/10/25 13:22:17 INFO lead: released remote=192.0.2.1:12341854--- PASS: TestLeadEndsOnShutdown (1.76s)1855=== CONT TestResolveDBConnectionString/flag_wins1856=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1857=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18582026/10/25 13:22:17 INFO Received uploads request method=POST path=/1859--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.25s)1860=== CONT TestResolveDBConnectionString/nothing_configured1861=== CONT TestResolveDBConnectionString/missing_file_is_an_error1862=== CONT TestResolveDBConnectionString/file_when_flag_empty1863=== CONT TestPush_RejectsBadRequests/no_roots18642026/10/25 13:22:17 INFO Received push request method=POST path=/api/pushes1865=== CONT TestPush_RejectsBadRequests/bad_root18662026/10/25 13:22:17 INFO Received push request method=POST path=/api/pushes1867=== CONT TestPush_RejectsBadRequests/root_not_in_objects18682026/10/25 13:22:17 INFO Received push request method=POST path=/api/pushes1869=== CONT TestPush_RejectsBadRequests/no_objects18702026/10/25 13:22:17 INFO Received push request method=POST path=/api/pushes1871=== CONT TestCacheConfigHandler/full_config,_no_issuer18722026/10/25 13:22:17 INFO Vacuumed table table=pending_closures1873=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1874=== CONT TestCacheConfigHandler/no_cache_url_configured1875=== CONT TestClientErrorHandling/InvalidStorePath1876--- PASS: TestResolveDBConnectionString (0.00s)1877 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1878 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1879 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1880 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1881 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1882=== CONT TestCacheConfigHandler/no_signing_keys1883=== CONT TestClientErrorHandling/ServerNotAvailable1884--- PASS: TestPush_RejectsBadRequests (0.38s)1885 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1886 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1887 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1888 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1889--- PASS: TestCacheConfigHandler (0.00s)1890 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1891 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1892 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1893 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)18942026/10/25 13:22:17 INFO Vacuumed table table=pending_objects18952026/10/25 13:22:17 INFO Vacuumed table table=multipart_uploads18962026/10/25 13:22:17 INFO Received uploads request method=POST path=/api/pending_closures18972026/10/25 13:22:17 INFO Vacuumed table table=closures18982026/10/25 13:22:17 INFO Vacuumed table table=objects1899=== CONT TestClientErrorHandling/InvalidAuthToken19002026/10/25 13:22:17 INFO Received uploads request method=POST path=/api/pending_closures19012026/10/25 13:22:17 INFO Received uploads request method=POST path=/api/pending_closures1902=== NAME TestOrphanedObjectsGC1903 orphaned_objects_gc_test.go:287: GC Test Summary:1904 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1905 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1906 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1907 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1908 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1909--- PASS: TestOrphanedObjectsGC (0.91s)1910=== CONT TestParseSingleRange/none1911=== CONT TestParseSingleRange/open-ended1912=== CONT TestParseSingleRange/start_far_past_EOF1913=== CONT TestParseSingleRange/suffix1914=== CONT TestParseSingleRange/end_clamped_to_size1915=== CONT TestParseSingleRange/suffix_exceeds_size1916=== CONT TestParseSingleRange/malformed_both_empty1917=== CONT TestParseSingleRange/start_past_EOF1918=== CONT TestParseSingleRange/closed1919=== CONT TestParseSingleRange/single_byte1920=== CONT TestParseSingleRange/malformed_end_before_start1921=== CONT TestParseSingleRange/multi-range_ignored1922=== CONT TestParseSingleRange/malformed_no_dash1923=== CONT TestParseSingleRange/unknown_unit1924--- PASS: TestParseSingleRange (0.00s)1925 --- PASS: TestParseSingleRange/none (0.00s)1926 --- PASS: TestParseSingleRange/open-ended (0.00s)1927 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1928 --- PASS: TestParseSingleRange/suffix (0.00s)1929 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1930 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1931 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1932 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1933 --- PASS: TestParseSingleRange/closed (0.00s)1934 --- PASS: TestParseSingleRange/single_byte (0.00s)1935 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1936 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1937 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1938 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1939=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh19402026/10/25 13:22:17 INFO Received cleanup request method=DELETE path=/api/pending_closures1941--- PASS: TestObjectStatsTrigger (0.27s)1942=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale19432026/10/25 13:22:17 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/present19442026/10/25 13:22:17 INFO Received uploads request method=POST path=/api/pending_closures19452026/10/25 13:22:17 INFO Received uploads request method=POST path=/api/pending_closures19462026/10/25 13:22:17 INFO Aborted multipart uploads count=0 kept=019472026/10/25 13:22:17 WARN Force mode enabled - objects will be deleted immediately without grace period19482026/10/25 13:22:17 INFO Received cleanup request method=DELETE path=/api/pending_closures19492026/10/25 13:22:17 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=""19502026/10/25 13:22:17 INFO Aborted multipart uploads count=0 kept=119512026/10/25 13:22:17 INFO Received uploads request method=POST path=/api/pending_closures19522026/10/25 13:22:17 INFO Received cleanup request method=DELETE path=/api/pending_closures19532026/10/25 13:22:17 INFO Aborted multipart uploads count=1 kept=019542026/10/25 13:22:17 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=01955--- PASS: TestMultipartCleanup (0.38s)1956=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token19572026/10/25 13:22:17 INFO Vacuumed table table=pending_closures19582026/10/25 13:22:17 INFO Vacuumed table table=pending_objects19592026/10/25 13:22:17 INFO Vacuumed table table=multipart_uploads19602026/10/25 13:22:17 INFO Vacuumed table table=closures1961=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19622026/10/25 13:22:17 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]1963=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1964=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19652026/10/25 13:22:17 WARN Authentication failed token_preview=eyJhbGciOi...k-NCOT6qaw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1966=== CONT TestService_RequireScope_OIDC/builder_may_write1967--- PASS: TestService_AuthMiddleware_OIDC (0.68s)1968 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1969 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1970 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1971 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1972=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1973=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19742026/10/25 13:22:17 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]1975=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1976=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc19772026/10/25 13:22:17 INFO Aborted multipart uploads count=0 kept=01978=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1979=== CONT TestService_RequireScope_OIDC/writer_implies_read1980=== CONT TestService_RequireScope_OIDC/reader_may_read1981=== CONT TestService_RequireScope_OIDC/static_token_may_write1982=== CONT TestService_RequireScope_OIDC/static_token_may_admin1983=== CONT TestService_RequireScope_OIDC/reader_may_not_write1984=== CONT TestService_RequireScope_OIDC/ops_may_not_write1985=== CONT TestService_RequireScope_OIDC/ops_may_admin1986=== CONT TestService_RequireScope_OIDC/builder_may_not_admin19872026/10/25 13:22:17 INFO Vacuumed table table=objects1988=== CONT TestIsValidCachePath/narinfo1989=== CONT TestIsValidCachePath/index.html1990=== CONT TestIsValidCachePath/nix-cache-info1991=== CONT TestIsValidCachePath/realisation1992=== CONT TestIsValidCachePath/log1993=== CONT TestIsValidCachePath/ls1994=== CONT TestIsValidCachePath/nar_uncompressed1995=== CONT TestIsValidCachePath/nar_bz21996=== CONT TestIsValidCachePath/nar_xz1997=== CONT TestIsValidCachePath/nar_zst1998--- PASS: TestService_RequireScope_OIDC (0.47s)1999 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2000 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2001 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2002 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2003 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2004 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2005 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2006 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2007 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2008 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2009 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2010 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2011 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2012 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2013=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2014=== CONT TestIsValidCachePath/empty2015=== CONT TestIsValidCachePath/traversal_parent2016=== CONT TestIsValidCachePath/random_path2017=== CONT TestIsValidCachePath/invalid_char_u2018=== CONT TestIsValidCachePath/invalid_char_e2019=== CONT TestIsValidCachePath/traversal_in_middle2020=== CONT TestIsValidCachePath/wrong_extension2021=== CONT TestIsValidCachePath/short_hash2022=== CONT TestIsValidCachePath/leading_slash2023--- PASS: TestIsValidCachePath (0.00s)2024 --- PASS: TestIsValidCachePath/narinfo (0.00s)2025 --- PASS: TestIsValidCachePath/index.html (0.00s)2026 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2027 --- PASS: TestIsValidCachePath/realisation (0.00s)2028 --- PASS: TestIsValidCachePath/log (0.00s)2029 --- PASS: TestIsValidCachePath/ls (0.00s)2030 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2031 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2032 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2033 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2034 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2035 --- PASS: TestIsValidCachePath/empty (0.00s)2036 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2037 --- PASS: TestIsValidCachePath/random_path (0.00s)2038 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2039 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2040 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2041 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2042 --- PASS: TestIsValidCachePath/short_hash (0.00s)2043 --- PASS: TestIsValidCachePath/leading_slash (0.00s)20442026/10/25 13:22:17 WARN Force mode enabled - objects will be deleted immediately without grace period20452026/10/25 13:22:17 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=020462026/10/25 13:22:17 INFO Vacuumed table table=pending_closures20472026/10/25 13:22:17 INFO Vacuumed table table=pending_objects20482026/10/25 13:22:17 INFO Vacuumed table table=multipart_uploads20492026/10/25 13:22:17 INFO Vacuumed table table=closures20502026/10/25 13:22:17 INFO Vacuumed table table=objects2051--- PASS: TestDeleteClosuresRacingPins (1.65s)2052--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2053 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.27s)2054 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.26s)20552026/10/25 13:22:17 INFO Aborted multipart uploads count=0 kept=020562026/10/25 13:22:17 WARN Force mode enabled - objects will be deleted immediately without grace period20572026/10/25 13:22:17 WARN Request failed, retrying attempt=2 backoff=215.905497ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20582026/10/25 13:22:17 INFO Aborted multipart uploads count=0 kept=020592026/10/25 13:22:17 WARN Force mode enabled - objects will be deleted immediately without grace period20602026/10/25 13:22:17 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:45751/bucket96/?delete=\": context canceled"2061--- PASS: TestGCEndsOnShutdown (0.00s)2062 --- PASS: TestGCEndsOnShutdown/before_the_run (0.23s)2063 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.24s)2064 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.26s)2065=== NAME TestClientCADerivations20662026/10/25 13:22:17 INFO lead: released remote=192.0.2.1:12342067 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features20682026/10/25 13:22:17 INFO lead: acquired remote=192.0.2.1:12342069 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2070 error: binary cache 's3://bucket71?endpoint=http://localhost:45751®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations291575301/001/store'2071 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12072--- PASS: TestClientCADerivations (1.26s)20732026/10/25 13:22:17 WARN Request failed, retrying attempt=3 backoff=396.16091ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20742026/10/25 13:22:17 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20752026/10/25 13:22:17 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2076--- PASS: TestUploadHandlersRejectOversizedBody (0.18s)2077 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)2078 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)2079 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.69s)2080--- PASS: TestObjectStatsLargeCommit (0.87s)2081--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2082 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.68s)2083 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.67s)20842026/10/25 13:22:17 WARN Request failed, retrying attempt=4 backoff=735.196774ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2085--- PASS: TestPendingClosureWriteTimeout (0.08s)2086 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2087 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2088 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2089 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.06s)2090=== NAME TestOrphanedObjectsGCStressTest2091 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2092 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion2093 orphaned_objects_gc_test.go:503: Stress test completed successfully:2094 orphaned_objects_gc_test.go:504: - Active objects preserved: 202095 orphaned_objects_gc_test.go:505: - Objects deleted: 2102096 orphaned_objects_gc_test.go:506: - Total GC'd: 2102097--- PASS: TestOrphanedObjectsGCStressTest (2.00s)20982026/10/25 13:22:18 INFO lead: released remote=192.0.2.1:12342099--- PASS: TestLeadElectsOneAndHandsOver (3.12s)21002026/10/25 13:22:18 WARN Request failed, retrying attempt=5 backoff=1.501559924s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21012026/10/25 13:22:18 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02102=== NAME TestClientIntegration2103 client_integration_test.go:323: Objects in database after GC:2104 client_integration_test.go:323: Successfully deleted all objects with GC --force2105--- PASS: TestClientIntegration (2.77s)21062026/10/25 13:22:19 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=021072026/10/25 13:22:19 INFO Received create pin request method=POST path=/api/pins/myapp21082026/10/25 13:22:19 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC3247563235/001/store/v2zs2b9byr18p2631r01pxn5zkg6xhmv-pinned-file.txt narinfo_key=v2zs2b9byr18p2631r01pxn5zkg6xhmv.narinfo21092026/10/25 13:22:19 INFO Starting cleanup of old closures method=DELETE path=/api/closures21102026/10/25 13:22:19 INFO Garbage collection started21112026/10/25 13:22:19 INFO Aborted multipart uploads count=0 kept=021122026/10/25 13:22:19 WARN Force mode enabled - objects will be deleted immediately without grace period21132026/10/25 13:22:19 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=021142026/10/25 13:22:19 INFO Vacuumed table table=pending_closures21152026/10/25 13:22:19 INFO Vacuumed table table=pending_objects21162026/10/25 13:22:19 INFO Vacuumed table table=multipart_uploads21172026/10/25 13:22:19 INFO Vacuumed table table=closures21182026/10/25 13:22:19 INFO Vacuumed table table=objects21192026/10/25 13:22:19 WARN Rate limiter enabled after throttle name=s3-test rate=521202026/10/25 13:22:19 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2121=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2122 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102123 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002124--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.83s)21252026/10/25 13:22:20 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21262026/10/25 13:22:20 WARN Request failed, retrying attempt=2 backoff=218.239278ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21272026/10/25 13:22:20 WARN Request failed, retrying attempt=3 backoff=362.755988ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2128--- PASS: TestConnectWaitsForAPeerMigration (5.15s)21292026/10/25 13:22:20 WARN Request failed, retrying attempt=4 backoff=824.747313ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2130=== NAME TestPinProtectsFromGC2131 client_integration_test.go:840: Pin successfully protected closure from garbage collection2132--- PASS: TestPinProtectsFromGC (4.91s)2133--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.74s)21342026/10/25 13:22:21 WARN Request failed, retrying attempt=5 backoff=1.612540131s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21352026/10/25 13:22:23 INFO Aborted multipart uploads count=1 kept=021362026/10/25 13:22:23 INFO Received cleanup request method=DELETE path=/api/pending_closures21372026/10/25 13:22:23 INFO Aborted multipart uploads count=1 kept=02138--- PASS: TestPendingCleanupUsesOneCutoff (6.28s)21392026/10/25 13:22:23 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"21402026/10/25 13:22:23 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21412026/10/25 13:22:23 WARN Request failed, retrying attempt=2 backoff=194.7713ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21422026/10/25 13:22:23 WARN Request failed, retrying attempt=3 backoff=436.936639ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21432026/10/25 13:22:24 WARN Request failed, retrying attempt=4 backoff=794.946399ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21442026/10/25 13:22:24 WARN Request failed, retrying attempt=5 backoff=1.580192853s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21452026/10/25 13:22:26 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21462026/10/25 13:22:26 WARN Request failed, retrying attempt=2 backoff=188.262287ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21472026/10/25 13:22:26 WARN Request failed, retrying attempt=3 backoff=398.081601ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21482026/10/25 13:22:27 WARN Request failed, retrying attempt=4 backoff=838.237295ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21492026/10/25 13:22:27 WARN Request failed, retrying attempt=5 backoff=1.605933109s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2150--- PASS: TestClientErrorHandling (0.00s)2151 --- PASS: TestClientErrorHandling/InvalidStorePath (0.22s)2152 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.41s)2153 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.45s)2154PASS21552026-10-25 13:22:29.829 UTC [127] LOG: received smart shutdown request21562026-10-25 13:22:29.831 UTC [127] LOG: background worker "logical replication launcher" (PID 137) exited with exit code 121572026-10-25 13:22:29.838 UTC [132] LOG: shutting down21582026-10-25 13:22:29.839 UTC [132] LOG: checkpoint starting: shutdown immediate21592026-10-25 13:22:31.082 UTC [132] LOG: checkpoint complete: wrote 11507 buffers (70.2%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.228 s, sync=0.977 s, total=1.244 s; sync files=34046, longest=0.019 s, average=0.001 s; distance=531580 kB, estimate=531580 kB; lsn=0/21E84E70, redo lsn=0/21E84E7021602026-10-25 13:22:31.139 UTC [127] LOG: database system is shut down2161Running OIDC tests...2162=== RUN TestAudienceForIssuer2163=== PAUSE TestAudienceForIssuer2164=== RUN TestGlobMatch2165=== PAUSE TestGlobMatch2166=== RUN TestValidateToken_ValidToken2167=== PAUSE TestValidateToken_ValidToken2168=== RUN TestValidateToken_WrongAudience2169=== PAUSE TestValidateToken_WrongAudience2170=== RUN TestValidateToken_Expired2171=== PAUSE TestValidateToken_Expired2172=== RUN TestValidateToken_BoundClaimsMismatch2173=== PAUSE TestValidateToken_BoundClaimsMismatch2174=== RUN TestValidateToken_BoundSubjectMismatch2175=== PAUSE TestValidateToken_BoundSubjectMismatch2176=== RUN TestValidateToken_MultipleProviders2177=== PAUSE TestValidateToken_MultipleProviders2178=== RUN TestValidateToken_NoMatchingProvider2179=== PAUSE TestValidateToken_NoMatchingProvider2180=== RUN TestValidateToken_KubernetesServiceAccount2181=== PAUSE TestValidateToken_KubernetesServiceAccount2182=== RUN TestNewValidator_KubernetesRequiresCA2183=== PAUSE TestNewValidator_KubernetesRequiresCA2184=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2185=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2186=== RUN TestPins_ReservedForMatchingRule2187=== PAUSE TestPins_ReservedForMatchingRule2188=== RUN TestPins_TopLevelShorthand2189=== PAUSE TestPins_TopLevelShorthand2190=== RUN TestPins_ConfigValidation2191=== PAUSE TestPins_ConfigValidation2192=== RUN TestScopes_LegacyProviderDefaultsToWrite2193=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2194=== RUN TestScopes_Rules2195=== PAUSE TestScopes_Rules2196=== RUN TestScopes_ConfigValidation2197=== PAUSE TestScopes_ConfigValidation2198=== CONT TestAudienceForIssuer2199=== CONT TestValidateToken_KubernetesServiceAccount2200--- PASS: TestAudienceForIssuer (0.00s)2201=== CONT TestValidateToken_BoundClaimsMismatch2202=== CONT TestValidateToken_Expired2203=== CONT TestValidateToken_WrongAudience2204=== CONT TestValidateToken_ValidToken2205=== CONT TestValidateToken_BoundSubjectMismatch2206=== CONT TestGlobMatch2207=== RUN TestGlobMatch/foo_foo2208=== PAUSE TestGlobMatch/foo_foo2209=== RUN TestGlobMatch/foo_bar2210=== CONT TestPins_ConfigValidation2211=== CONT TestScopes_ConfigValidation2212=== CONT TestScopes_Rules2213=== CONT TestValidateToken_NoMatchingProvider2214=== CONT TestScopes_LegacyProviderDefaultsToWrite2215=== CONT TestPins_ReservedForMatchingRule2216=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2217=== CONT TestPins_TopLevelShorthand2218=== CONT TestNewValidator_KubernetesRequiresCA2219=== CONT TestValidateToken_MultipleProviders2220=== PAUSE TestGlobMatch/foo_bar2221=== RUN TestGlobMatch/*_2222=== PAUSE TestGlobMatch/*_2223=== RUN TestGlobMatch/*_anything2224=== PAUSE TestGlobMatch/*_anything2225=== RUN TestGlobMatch/foo*_foo2226=== PAUSE TestGlobMatch/foo*_foo2227=== RUN TestGlobMatch/foo*_foobar2228=== PAUSE TestGlobMatch/foo*_foobar2229=== RUN TestGlobMatch/foo*_bar2230=== PAUSE TestGlobMatch/foo*_bar2231=== RUN TestGlobMatch/*bar_bar2232=== PAUSE TestGlobMatch/*bar_bar2233=== RUN TestGlobMatch/*bar_foobar2234=== PAUSE TestGlobMatch/*bar_foobar2235=== RUN TestGlobMatch/*bar_foo2236=== PAUSE TestGlobMatch/*bar_foo2237=== RUN TestGlobMatch/foo*bar_foobar2238=== PAUSE TestGlobMatch/foo*bar_foobar2239=== RUN TestGlobMatch/foo*bar_foo123bar2240=== PAUSE TestGlobMatch/foo*bar_foo123bar2241=== RUN TestGlobMatch/foo*bar_foobarbaz2242=== PAUSE TestGlobMatch/foo*bar_foobarbaz2243=== RUN TestGlobMatch/*/*_foo/bar2244=== PAUSE TestGlobMatch/*/*_foo/bar2245=== RUN TestGlobMatch/*/*_foo2246=== PAUSE TestGlobMatch/*/*_foo2247=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2248=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2249=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02250=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02251=== RUN TestGlobMatch/refs/*/main_refs/heads/main2252=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2253=== RUN TestGlobMatch/fo?_foo2254=== PAUSE TestGlobMatch/fo?_foo2255=== RUN TestGlobMatch/fo?_fo2256=== PAUSE TestGlobMatch/fo?_fo2257=== RUN TestGlobMatch/fo?_fooo2258=== PAUSE TestGlobMatch/fo?_fooo2259=== RUN TestGlobMatch/?oo_foo2260=== PAUSE TestGlobMatch/?oo_foo2261=== RUN TestGlobMatch/?oo_boo2262=== PAUSE TestGlobMatch/?oo_boo2263=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2264=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2265=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2266=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2267=== CONT TestGlobMatch/foo_foo2268=== CONT TestGlobMatch/refs/*/main_refs/heads/main2269=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02270=== CONT TestGlobMatch/fo?_foo2271=== CONT TestGlobMatch/*bar_foobar2272=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2273=== CONT TestGlobMatch/foo*_bar2274=== CONT TestGlobMatch/foo*_foobar2275=== CONT TestGlobMatch/foo*_foo2276=== CONT TestGlobMatch/*/*_foo2277=== CONT TestGlobMatch/*_2278=== CONT TestGlobMatch/foo_bar2279=== CONT TestGlobMatch/*/*_foo/bar2280=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2281=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2282=== CONT TestGlobMatch/fo?_fooo2283=== CONT TestGlobMatch/?oo_foo2284=== CONT TestGlobMatch/fo?_fo2285=== CONT TestGlobMatch/foo*bar_foobarbaz2286=== CONT TestGlobMatch/foo*bar_foo123bar2287--- PASS: TestScopes_ConfigValidation (0.01s)2288=== CONT TestGlobMatch/foo*bar_foobar2289=== CONT TestGlobMatch/*bar_foo2290=== CONT TestGlobMatch/*bar_bar2291=== CONT TestGlobMatch/*_anything2292=== CONT TestGlobMatch/?oo_boo2293--- PASS: TestPins_ConfigValidation (0.00s)2294--- PASS: TestGlobMatch (0.01s)2295 --- PASS: TestGlobMatch/foo_foo (0.00s)2296 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2297 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2298 --- PASS: TestGlobMatch/fo?_foo (0.00s)2299 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2300 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2301 --- PASS: TestGlobMatch/foo*_bar (0.00s)2302 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2303 --- PASS: TestGlobMatch/foo*_foo (0.00s)2304 --- PASS: TestGlobMatch/*/*_foo (0.00s)2305 --- PASS: TestGlobMatch/*_ (0.00s)2306 --- PASS: TestGlobMatch/foo_bar (0.00s)2307 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2308 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2309 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2310 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2311 --- PASS: TestGlobMatch/?oo_foo (0.00s)2312 --- PASS: TestGlobMatch/fo?_fo (0.00s)2313 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2314 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2315 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2316 --- PASS: TestGlobMatch/*bar_foo (0.00s)2317 --- PASS: TestGlobMatch/*bar_bar (0.00s)2318 --- PASS: TestGlobMatch/*_anything (0.00s)2319 --- PASS: TestGlobMatch/?oo_boo (0.00s)23202026/10/25 13:22:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41597/oidc23212026/10/25 13:22:32 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232322--- PASS: TestPins_TopLevelShorthand (0.02s)2323--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.03s)23242026/10/25 13:22:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46387/oidc2325--- PASS: TestValidateToken_BoundSubjectMismatch (0.04s)23262026/10/25 13:22:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42539/oidc23272026/10/25 13:22:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39681/oidc2328--- PASS: TestValidateToken_ValidToken (0.05s)23292026/10/25 13:22:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43597/oidc2330--- PASS: TestScopes_Rules (0.04s)23312026/10/25 13:22:32 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:366172332--- PASS: TestPins_ReservedForMatchingRule (0.05s)23332026/10/25 13:22:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37743/oidc2334--- PASS: TestValidateToken_KubernetesServiceAccount (0.06s)2335--- PASS: TestValidateToken_WrongAudience (0.06s)23362026/10/25 13:22:32 http: TLS handshake error from 127.0.0.1:40824: remote error: tls: bad certificate2337--- PASS: TestNewValidator_KubernetesRequiresCA (0.06s)23382026/10/25 13:22:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37941/oidc2339--- PASS: TestValidateToken_BoundClaimsMismatch (0.09s)23402026/10/25 13:22:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39301/oidc2341--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.08s)23422026/10/25 13:22:32 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:43971/oidc2343--- PASS: TestValidateToken_NoMatchingProvider (0.11s)23442026/10/25 13:22:32 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37227/oidc2345--- PASS: TestValidateToken_Expired (0.14s)23462026/10/25 13:22:33 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:46519/oidc23472026/10/25 13:22:33 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:33455/oidc2348--- PASS: TestValidateToken_MultipleProviders (0.19s)2349PASS2350Running hook tests...2351=== RUN TestSendPathsEmpty2352=== PAUSE TestSendPathsEmpty2353=== RUN TestQueueEnqueueAndFetch2354=== PAUSE TestQueueEnqueueAndFetch2355=== RUN TestQueueDeduplication2356=== PAUSE TestQueueDeduplication2357=== RUN TestQueueRemove2358=== PAUSE TestQueueRemove2359=== RUN TestQueueFetchBatchLimit2360=== PAUSE TestQueueFetchBatchLimit2361=== RUN TestQueueRetryMovesToBack2362=== PAUSE TestQueueRetryMovesToBack2363=== RUN TestQueueFetchRemoveLifecycle2364=== PAUSE TestQueueFetchRemoveLifecycle2365=== RUN TestQueueConcurrentWriters2366=== PAUSE TestQueueConcurrentWriters2367=== RUN TestQueueRemoveLargeClosure2368=== PAUSE TestQueueRemoveLargeClosure2369=== RUN TestServerClientIntegration2370--- PASS: TestServerClientIntegration (0.00s)2371=== RUN TestServerQueueError23722026/10/25 13:22:33 ERROR Failed to queue paths error="permission denied" count=12373--- PASS: TestServerQueueError (0.00s)2374=== RUN TestGetListenerSocketActivation2375 server_test.go:219: === RUN TestGetListenerSocketActivation2376 --- PASS: TestGetListenerSocketActivation (0.00s)2377 PASS2378 2379--- PASS: TestGetListenerSocketActivation (0.01s)2380=== RUN TestDrainIsolatesPoisonPath2381=== PAUSE TestDrainIsolatesPoisonPath2382=== RUN TestRunNotBlockedByPoisonHead2383=== PAUSE TestRunNotBlockedByPoisonHead2384=== RUN TestDrainGivesUpWhenServerDown2385=== PAUSE TestDrainGivesUpWhenServerDown2386=== RUN TestFailedPathPrunedByLaterClosure2387=== PAUSE TestFailedPathPrunedByLaterClosure2388=== RUN TestWorkerUploadsAndRemoves2389=== PAUSE TestWorkerUploadsAndRemoves2390=== RUN TestWorkerSkipsGCdPaths2391=== PAUSE TestWorkerSkipsGCdPaths2392=== RUN TestWorkerPrunesClosureDeps2393=== PAUSE TestWorkerPrunesClosureDeps2394=== RUN TestDrainTimeout2395=== PAUSE TestDrainTimeout2396=== RUN TestWorkerRemoveFailureIsNotProgress2397=== PAUSE TestWorkerRemoveFailureIsNotProgress2398=== RUN TestWorkerKeepsPathItCannotStat2399=== PAUSE TestWorkerKeepsPathItCannotStat2400=== CONT TestSendPathsEmpty2401=== CONT TestQueueFetchRemoveLifecycle2402=== CONT TestRunNotBlockedByPoisonHead2403=== CONT TestWorkerKeepsPathItCannotStat2404=== CONT TestWorkerRemoveFailureIsNotProgress2405=== CONT TestDrainTimeout2406=== CONT TestWorkerPrunesClosureDeps2407=== CONT TestFailedPathPrunedByLaterClosure2408=== CONT TestWorkerUploadsAndRemoves2409=== CONT TestDrainGivesUpWhenServerDown2410=== CONT TestQueueRetryMovesToBack2411=== CONT TestWorkerSkipsGCdPaths2412=== CONT TestDrainIsolatesPoisonPath2413=== CONT TestQueueRemoveLargeClosure2414=== CONT TestQueueConcurrentWriters2415--- PASS: TestSendPathsEmpty (0.00s)2416=== CONT TestQueueDeduplication2417=== CONT TestQueueEnqueueAndFetch2418=== CONT TestQueueFetchBatchLimit2419=== CONT TestQueueRemove24202026/10/25 13:22:33 INFO Uploading batch count=124212026/10/25 13:22:33 ERROR Upload failed error="upload failed" count=124222026/10/25 13:22:33 INFO Uploading batch count=224232026/10/25 13:22:33 ERROR Upload failed error="upload failed" count=224242026/10/25 13:22:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3200995835/002/a24252026/10/25 13:22:33 INFO Uploading batch count=424262026/10/25 13:22:33 ERROR Upload failed error="upload failed" count=424272026/10/25 13:22:33 INFO Upload queue status pending=224282026/10/25 13:22:33 INFO Uploading batch count=124292026/10/25 13:22:33 INFO Upload queue status pending=224302026/10/25 13:22:33 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat4054475164/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat4054475164/002/locked/aaa: permission denied"24312026/10/25 13:22:33 INFO Uploading batch count=12432--- PASS: TestQueueFetchBatchLimit (0.01s)24332026/10/25 13:22:33 INFO Upload queue status pending=32434--- PASS: TestQueueEnqueueAndFetch (0.01s)24352026/10/25 13:22:33 INFO Uploading batch count=124362026/10/25 13:22:33 ERROR Upload failed error="upload failed" count=124372026/10/25 13:22:33 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths278802581/002/nonexistent2438--- PASS: TestQueueRetryMovesToBack (0.01s)24392026/10/25 13:22:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3200995835/002/b24402026/10/25 13:22:33 INFO Uploading batch count=224412026/10/25 13:22:33 INFO Upload queue status pending=224422026/10/25 13:22:33 INFO Uploading batch count=12443--- PASS: TestQueueRemove (0.01s)24442026/10/25 13:22:33 INFO Uploading batch count=224452026/10/25 13:22:33 INFO Uploading batch count=12446--- PASS: TestQueueFetchRemoveLifecycle (0.02s)2447--- PASS: TestQueueDeduplication (0.02s)24482026/10/25 13:22:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath1977463620/002/bbb24492026/10/25 13:22:33 INFO Uploading batch count=224502026/10/25 13:22:33 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress2441676958/002/nonexistent24512026/10/25 13:22:33 ERROR Upload failed error="upload failed" count=224522026/10/25 13:22:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3200995835/002/c24532026/10/25 13:22:33 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat4054475164/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat4054475164/002/locked/aaa: permission denied"24542026/10/25 13:22:33 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124552026/10/25 13:22:33 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress2441676958/002/nonexistent24562026/10/25 13:22:33 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124572026/10/25 13:22:33 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress2441676958/002/nonexistent24582026/10/25 13:22:33 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124592026/10/25 13:22:33 ERROR Drain finished with paths left in queue remaining=124602026/10/25 13:22:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3200995835/002/d24612026/10/25 13:22:33 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat4054475164/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat4054475164/002/locked/aaa: permission denied"2462--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)24632026/10/25 13:22:33 INFO Uploading batch count=124642026/10/25 13:22:33 ERROR Upload failed error="upload failed" count=12465--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)24662026/10/25 13:22:33 ERROR Drain finished with paths left in queue remaining=124672026/10/25 13:22:33 INFO Uploading batch count=224682026/10/25 13:22:33 ERROR Upload failed error="upload failed" count=224692026/10/25 13:22:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3200995835/002/e24702026/10/25 13:22:33 INFO Uploading batch count=124712026/10/25 13:22:33 ERROR Upload failed error="upload failed" count=124722026/10/25 13:22:33 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3200995835/002/f24732026/10/25 13:22:33 INFO Uploading batch count=124742026/10/25 13:22:33 ERROR Upload failed error="upload failed" count=12475--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)24762026/10/25 13:22:33 ERROR Drain finished with paths left in queue remaining=1024772026/10/25 13:22:33 ERROR Drain finished with paths left in queue remaining=12478--- PASS: TestDrainIsolatesPoisonPath (0.02s)2479--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2480--- PASS: TestWorkerSkipsGCdPaths (0.03s)2481--- PASS: TestWorkerPrunesClosureDeps (0.03s)2482--- PASS: TestWorkerUploadsAndRemoves (0.04s)2483--- PASS: TestQueueRemoveLargeClosure (0.05s)24842026/10/25 13:22:33 ERROR Upload failed error="context deadline exceeded" count=224852026/10/25 13:22:33 ERROR Drain finished with paths left in queue remaining=42486--- PASS: TestDrainTimeout (0.22s)2487--- PASS: TestQueueConcurrentWriters (0.27s)24882026/10/25 13:22:34 INFO Uploading batch count=124892026/10/25 13:22:34 INFO Uploading batch count=124902026/10/25 13:22:34 INFO Uploading batch count=124912026/10/25 13:22:34 ERROR Upload failed error="upload failed" count=124922026/10/25 13:22:34 INFO Uploading batch count=124932026/10/25 13:22:34 ERROR Upload failed error="upload failed" count=124942026/10/25 13:22:34 INFO Uploading batch count=124952026/10/25 13:22:34 ERROR Upload failed error="upload failed" count=124962026/10/25 13:22:34 INFO Uploading batch count=124972026/10/25 13:22:34 ERROR Upload failed error="upload failed" count=124982026/10/25 13:22:34 ERROR Drain finished with paths left in queue remaining=12499--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2500PASS2501Running signing tests...2502=== RUN TestExternalSigner2503=== PAUSE TestExternalSigner2504=== RUN TestExternalSignerWrongPublicKey2505=== PAUSE TestExternalSignerWrongPublicKey2506=== RUN TestExternalSignerErrors2507=== PAUSE TestExternalSignerErrors2508=== RUN TestExternalSignerRestartsAfterCrash2509=== PAUSE TestExternalSignerRestartsAfterCrash2510=== RUN TestExternalSignerProgramErrorKeepsProcess2511=== PAUSE TestExternalSignerProgramErrorKeepsProcess2512=== RUN TestExternalSignerClose2513=== PAUSE TestExternalSignerClose2514=== RUN TestExternalSignerRejectsInvalidPublicKey2515=== PAUSE TestExternalSignerRejectsInvalidPublicKey2516=== RUN TestExternalSignerCancellation2517=== PAUSE TestExternalSignerCancellation2518=== RUN TestGenerateFingerprint2519=== PAUSE TestGenerateFingerprint2520=== RUN TestParseSigningKey2521=== PAUSE TestParseSigningKey2522=== RUN TestSign2523=== PAUSE TestSign2524=== RUN TestSignBatch2525=== PAUSE TestSignBatch2526=== RUN TestNilKeyPublicKey2527=== PAUSE TestNilKeyPublicKey2528=== RUN TestSignErrors2529=== PAUSE TestSignErrors2530=== CONT TestExternalSigner2531=== CONT TestExternalSignerCancellation2532=== CONT TestExternalSignerProgramErrorKeepsProcess2533=== CONT TestSignErrors2534=== CONT TestNilKeyPublicKey2535=== CONT TestExternalSignerRejectsInvalidPublicKey2536=== RUN TestExternalSignerRejectsInvalidPublicKey/#002537=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002538=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2539=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2540=== CONT TestSignBatch2541=== CONT TestSign2542=== CONT TestExternalSignerErrors2543=== CONT TestParseSigningKey2544=== CONT TestExternalSignerRestartsAfterCrash2545=== RUN TestParseSigningKey/valid_32-byte_key2546=== CONT TestGenerateFingerprint2547=== CONT TestExternalSignerWrongPublicKey2548=== RUN TestSignErrors/nil_key2549=== PAUSE TestSignErrors/nil_key2550=== CONT TestExternalSignerClose2551--- PASS: TestNilKeyPublicKey (0.00s)2552--- PASS: TestSign (0.00s)2553=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2554=== RUN TestExternalSignerErrors/wrong_signatures_shape2555=== PAUSE TestParseSigningKey/valid_32-byte_key2556=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2557=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2558=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2559=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2560=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2561--- PASS: TestSignBatch (0.00s)2562=== RUN TestSignErrors/nil_narinfo2563=== PAUSE TestSignErrors/nil_narinfo2564=== RUN TestSignErrors/invalid_narinfo2565=== PAUSE TestSignErrors/invalid_narinfo2566=== RUN TestSignErrors/canceled2567=== PAUSE TestSignErrors/canceled2568=== CONT TestSignErrors/nil_key2569=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2570=== RUN TestExternalSignerErrors/too_few_signatures2571=== CONT TestSignErrors/invalid_narinfo2572=== PAUSE TestExternalSignerErrors/too_few_signatures2573=== RUN TestExternalSignerErrors/exit_at_startup2574=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2575=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2576=== CONT TestExternalSignerRejectsInvalidPublicKey/#002577=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2578=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2579=== CONT TestSignErrors/nil_narinfo2580=== CONT TestSignErrors/canceled2581--- PASS: TestSignErrors (0.00s)2582 --- PASS: TestSignErrors/nil_key (0.00s)2583 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2584 --- PASS: TestSignErrors/nil_narinfo (0.00s)2585 --- PASS: TestSignErrors/canceled (0.00s)2586=== PAUSE TestExternalSignerErrors/exit_at_startup2587=== RUN TestParseSigningKey/no_colon2588=== PAUSE TestParseSigningKey/no_colon2589=== RUN TestGenerateFingerprint/basic_with_references2590=== PAUSE TestGenerateFingerprint/basic_with_references2591=== RUN TestGenerateFingerprint/no_references2592=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2593=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2594--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2595 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2596 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2597 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2598 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2599 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2600=== RUN TestExternalSignerErrors/exit_on_request2601=== PAUSE TestExternalSignerErrors/exit_on_request2602=== RUN TestExternalSignerErrors/null2603=== PAUSE TestExternalSignerErrors/null2604=== RUN TestExternalSignerErrors/null_signatures2605=== PAUSE TestExternalSignerErrors/null_signatures2606=== RUN TestExternalSignerErrors/unrequested_key2607=== PAUSE TestExternalSignerErrors/unrequested_key2608=== RUN TestParseSigningKey/empty_name2609=== PAUSE TestGenerateFingerprint/no_references2610--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2611=== RUN TestExternalSignerErrors/wrong_signature_name2612=== PAUSE TestExternalSignerErrors/wrong_signature_name2613=== PAUSE TestParseSigningKey/empty_name2614=== RUN TestParseSigningKey/invalid_base642615=== PAUSE TestParseSigningKey/invalid_base642616=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2617=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2618=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2619=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2620=== RUN TestGenerateFingerprint/invalid_nar_hash_length2621=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2622=== RUN TestGenerateFingerprint/invalid_store_path_prefix2623=== RUN TestExternalSignerErrors/program_error2624=== RUN TestParseSigningKey/wrong_length2625=== PAUSE TestParseSigningKey/wrong_length2626=== CONT TestParseSigningKey/valid_32-byte_key2627=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2628=== RUN TestGenerateFingerprint/invalid_reference_prefix2629=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2630=== CONT TestParseSigningKey/empty_name2631--- PASS: TestExternalSignerWrongPublicKey (0.00s)2632=== CONT TestParseSigningKey/wrong_length2633=== CONT TestParseSigningKey/invalid_base642634=== PAUSE TestExternalSignerErrors/program_error2635=== RUN TestExternalSignerErrors/wrong_id2636=== PAUSE TestExternalSignerErrors/wrong_id2637=== CONT TestParseSigningKey/no_colon2638--- PASS: TestParseSigningKey (0.00s)2639 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2640 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2641 --- PASS: TestParseSigningKey/empty_name (0.00s)2642 --- PASS: TestParseSigningKey/wrong_length (0.00s)2643 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2644 --- PASS: TestParseSigningKey/no_colon (0.00s)2645=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2646=== CONT TestGenerateFingerprint/basic_with_references2647=== CONT TestGenerateFingerprint/no_references2648=== RUN TestExternalSignerErrors/missing_signatures2649=== PAUSE TestExternalSignerErrors/missing_signatures2650=== RUN TestExternalSignerErrors/missing_signature_name2651=== PAUSE TestExternalSignerErrors/missing_signature_name2652=== RUN TestExternalSignerErrors/wrong_signature_length2653=== PAUSE TestExternalSignerErrors/wrong_signature_length2654=== RUN TestExternalSignerErrors/invalid_JSON2655=== PAUSE TestExternalSignerErrors/invalid_JSON2656=== RUN TestExternalSignerErrors/wrong_shape2657=== PAUSE TestExternalSignerErrors/wrong_shape2658--- PASS: TestExternalSignerClose (0.00s)2659=== CONT TestGenerateFingerprint/invalid_nar_hash_length2660=== RUN TestExternalSignerErrors/invalid_signature_base642661=== PAUSE TestExternalSignerErrors/invalid_signature_base642662=== CONT TestExternalSignerErrors/wrong_signatures_shape2663=== CONT TestExternalSignerErrors/exit_on_request2664=== CONT TestExternalSignerErrors/wrong_shape2665=== CONT TestExternalSignerErrors/too_few_signatures2666=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2667=== CONT TestGenerateFingerprint/invalid_store_path_prefix2668=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2669=== CONT TestGenerateFingerprint/invalid_reference_prefix2670--- PASS: TestGenerateFingerprint (0.00s)2671 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2672 --- PASS: TestGenerateFingerprint/no_references (0.00s)2673 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2674 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2675 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2676 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2677 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2678=== CONT TestExternalSignerErrors/invalid_signature_base642679=== CONT TestExternalSignerErrors/wrong_signature_name2680=== CONT TestExternalSignerErrors/invalid_JSON2681=== CONT TestExternalSignerErrors/wrong_signature_length2682=== CONT TestExternalSignerErrors/missing_signature_name2683=== CONT TestExternalSignerErrors/missing_signatures2684=== CONT TestExternalSignerErrors/null2685=== CONT TestExternalSignerErrors/wrong_id2686=== CONT TestExternalSignerErrors/unrequested_key2687=== CONT TestExternalSignerErrors/program_error2688=== CONT TestExternalSignerErrors/null_signatures2689=== CONT TestExternalSignerErrors/exit_at_startup2690--- PASS: TestExternalSigner (0.01s)2691--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2692--- PASS: TestExternalSignerErrors (0.00s)2693 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.00s)2694 --- PASS: TestExternalSignerErrors/invalid_JSON (0.00s)2695 --- PASS: TestExternalSignerErrors/wrong_shape (0.00s)2696 --- PASS: TestExternalSignerErrors/missing_signature_name (0.00s)2697 --- PASS: TestExternalSignerErrors/exit_on_request (0.00s)2698 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.00s)2699 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.00s)2700 --- PASS: TestExternalSignerErrors/null (0.00s)2701 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.00s)2702 --- PASS: TestExternalSignerErrors/exit_at_startup (0.00s)2703 --- PASS: TestExternalSignerErrors/missing_signatures (0.00s)2704 --- PASS: TestExternalSignerErrors/too_few_signatures (0.01s)2705 --- PASS: TestExternalSignerErrors/program_error (0.00s)2706 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)2707 --- PASS: TestExternalSignerErrors/unrequested_key (0.01s)2708 --- PASS: TestExternalSignerErrors/null_signatures (0.00s)2709--- PASS: TestExternalSignerCancellation (0.02s)2710PASS2711Running OpenBao signer tests...2712=== RUN TestSign2713=== PAUSE TestSign2714=== RUN TestSignErrors2715=== PAUSE TestSignErrors2716=== RUN TestServe2717=== PAUSE TestServe2718=== RUN TestServeRejectsGarbage2719=== PAUSE TestServeRejectsGarbage2720=== CONT TestSign2721=== CONT TestServe2722=== CONT TestSignErrors2723=== CONT TestServeRejectsGarbage2724=== RUN TestSignErrors/http_error2725=== PAUSE TestSignErrors/http_error2726--- PASS: TestServeRejectsGarbage (0.00s)2727=== RUN TestSignErrors/invalid_json2728--- PASS: TestServe (0.00s)2729=== PAUSE TestSignErrors/invalid_json2730=== RUN TestSignErrors/no_prefix2731=== PAUSE TestSignErrors/no_prefix2732=== RUN TestSignErrors/invalid_base642733=== PAUSE TestSignErrors/invalid_base642734=== CONT TestSignErrors/http_error2735=== CONT TestSignErrors/no_prefix2736=== CONT TestSignErrors/invalid_base642737=== CONT TestSignErrors/invalid_json2738--- PASS: TestSign (0.00s)2739--- PASS: TestSignErrors (0.00s)2740 --- PASS: TestSignErrors/invalid_json (0.00s)2741 --- PASS: TestSignErrors/invalid_base64 (0.00s)2742 --- PASS: TestSignErrors/http_error (0.00s)2743 --- PASS: TestSignErrors/no_prefix (0.00s)2744PASS