niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #440
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry5=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry6=== RUN TestRegisterUploadedObjectReusesConnections7=== PAUSE TestRegisterUploadedObjectReusesConnections8=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica9=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica10=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun11=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun12=== RUN TestCaseHackSuffix13=== PAUSE TestCaseHackSuffix14=== RUN TestFilterOversizedClosures15=== PAUSE TestFilterOversizedClosures16=== RUN TestUploadMultipart_PartsInParallel17=== PAUSE TestUploadMultipart_PartsInParallel18=== RUN TestUploadMultipart_FailedPartBufferNotReused19=== PAUSE TestUploadMultipart_FailedPartBufferNotReused20=== RUN TestPartSizeForNAR21=== PAUSE TestPartSizeForNAR22=== RUN TestUploadMultipart_SupersededByPeer23=== PAUSE TestUploadMultipart_SupersededByPeer24=== RUN TestDumpPathCaseHackMatchesNix25--- PASS: TestDumpPathCaseHackMatchesNix (0.04s)26=== RUN TestDumpPathCaseHackCollision27--- PASS: TestDumpPathCaseHackCollision (0.00s)28=== RUN TestSupersededNARStillUploadsListing29=== PAUSE TestSupersededNARStillUploadsListing30=== RUN TestDumpPathMatchesNix31=== PAUSE TestDumpPathMatchesNix32=== RUN TestDumpPathSingleFile33=== PAUSE TestDumpPathSingleFile34=== RUN TestDumpPathWriterError35=== PAUSE TestDumpPathWriterError36=== RUN TestEncodeNixBase3237=== PAUSE TestEncodeNixBase3238=== RUN TestEncodeNixBase32WithRealHash39=== PAUSE TestEncodeNixBase32WithRealHash40=== RUN TestConvertHashToNix3241=== PAUSE TestConvertHashToNix3242=== RUN TestGetStorePathHash43=== PAUSE TestGetStorePathHash44=== RUN TestPathInfoHashCompatibility45=== PAUSE TestPathInfoHashCompatibility46=== RUN TestParsePathInfoJSON47=== PAUSE TestParsePathInfoJSON48=== RUN TestParsePathInfoJSONMultiplePaths49=== PAUSE TestParsePathInfoJSONMultiplePaths50=== RUN TestPathInfoCACompatibility51=== PAUSE TestPathInfoCACompatibility52=== RUN TestRateLimiterFeedback53=== PAUSE TestRateLimiterFeedback54=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess55=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess56=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer57=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer58=== RUN TestResolveStorePath59=== PAUSE TestResolveStorePath60=== RUN TestDoWithRetry_BodyReplayedViaGetBody61=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody62=== RUN TestRetryTimeoutOutlastsMaxRetries63=== PAUSE TestRetryTimeoutOutlastsMaxRetries64=== RUN TestDoWithRetry_FinalResponseBodyReadable65=== PAUSE TestDoWithRetry_FinalResponseBodyReadable66=== RUN TestShellSplit67=== PAUSE TestShellSplit68=== RUN TestShellSplitErrors69=== PAUSE TestShellSplitErrors70=== RUN TestStreamPushReportsEveryPath71=== PAUSE TestStreamPushReportsEveryPath72=== RUN TestStreamPushBatchesUnderLoad73=== PAUSE TestStreamPushBatchesUnderLoad74=== RUN TestStreamPushIsolatesFailures75=== PAUSE TestStreamPushIsolatesFailures76=== RUN TestStreamPushGivesUpOnDeadServer77=== PAUSE TestStreamPushGivesUpOnDeadServer78=== RUN TestStreamPushRequestLine79=== PAUSE TestStreamPushRequestLine80=== RUN TestStreamPushReportsSignatures81=== PAUSE TestStreamPushReportsSignatures82=== RUN TestStreamPushReportsSkippedPaths83=== PAUSE TestStreamPushReportsSkippedPaths84=== RUN TestClientSignaturesByStorePath85=== PAUSE TestClientSignaturesByStorePath86=== RUN TestStreamPushStopsWhenCanceled87=== PAUSE TestStreamPushStopsWhenCanceled88=== RUN TestSetClientTLS89=== PAUSE TestSetClientTLS90=== RUN TestSetClientTLSDoesNotMutateDefaultTransport91=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport92=== RUN TestSetClientTLSErrors93=== PAUSE TestSetClientTLSErrors94=== RUN TestStaticToken95=== PAUSE TestStaticToken96=== RUN TestFileTokenReadsAndCaches97=== PAUSE TestFileTokenReadsAndCaches98=== RUN TestFileTokenMissing99=== PAUSE TestFileTokenMissing100=== RUN TestFileTokenEmpty101=== PAUSE TestFileTokenEmpty102=== RUN TestScriptTokenNoExpiryRerunsEveryCall103=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall104=== RUN TestScriptTokenCachesUntilRefresh105=== PAUSE TestScriptTokenCachesUntilRefresh106=== RUN TestScriptTokenEmptyToken107=== PAUSE TestScriptTokenEmptyToken108=== RUN TestScriptTokenBadJSON109=== PAUSE TestScriptTokenBadJSON110=== RUN TestScriptTokenScriptFails111=== PAUSE TestScriptTokenScriptFails112=== RUN TestScriptTokenEmptyCommand113=== PAUSE TestScriptTokenEmptyCommand114=== CONT TestDoServerRequestAttachesToken115=== CONT TestDoWithRetry_BodyReplayedViaGetBody116=== CONT TestDumpPathWriterError117=== CONT TestUploadMultipart_PartsInParallel118=== CONT TestParsePathInfoJSONMultiplePaths119=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths120=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths121=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths122=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths123=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths124=== CONT TestResolveStorePath125=== CONT TestParsePathInfoJSON126=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer127=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess128=== CONT TestRateLimiterFeedback129=== CONT TestPathInfoHashCompatibility130=== CONT TestPathInfoCACompatibility131=== CONT TestSupersededNARStillUploadsListing132=== CONT TestDumpPathSingleFile133=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths134=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica135=== CONT TestDumpPathMatchesNix136=== CONT TestFilterOversizedClosures137=== CONT TestCaseHackSuffix138=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry139=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun140=== CONT TestRegisterUploadedObjectReusesConnections141=== CONT TestUploadMultipart_SupersededByPeer142=== CONT TestGetStorePathHash143=== RUN TestRateLimiterFeedback/429_enables_limiter144=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)1452026/10/27 08:39:37 WARN Rate limiter enabled after throttle name=server-test rate=5146=== CONT TestEncodeNixBase32WithRealHash147=== RUN TestPathInfoCACompatibility/null_ca_field148=== PAUSE TestPathInfoCACompatibility/null_ca_field149=== RUN TestPathInfoCACompatibility/old_string_format_-_text150=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text151=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive152=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive153=== RUN TestPathInfoCACompatibility/new_structured_format_-_text154=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text155=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method156=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method157=== CONT TestConvertHashToNix32158=== RUN TestConvertHashToNix32/SRI_format_to_Nix32159=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32160=== RUN TestConvertHashToNix32/already_Nix32_format161=== PAUSE TestConvertHashToNix32/already_Nix32_format162=== RUN TestConvertHashToNix32/invalid_format1632026/10/27 08:39:37 WARN Rate limiter enabled after throttle name=server-test rate=51642026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:35319165--- PASS: TestResolveStorePath (0.03s)166=== CONT TestPartSizeForNAR167--- PASS: TestDoServerRequestAttachesToken (0.03s)168=== CONT TestUploadMultipart_FailedPartBufferNotReused169=== RUN TestPartSizeForNAR/zero_stays_at_minimum170=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum171=== RUN TestPartSizeForNAR/small_stays_at_minimum172=== PAUSE TestPartSizeForNAR/small_stays_at_minimum173=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum174=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum175=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts176=== RUN TestParsePathInfoJSON/Nix_format177=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)178=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon179=== RUN TestUploadMultipart_SupersededByPeer/exists180=== PAUSE TestConvertHashToNix32/invalid_format181=== PAUSE TestUploadMultipart_SupersededByPeer/exists182=== RUN TestGetStorePathHash/valid_store_path183=== RUN TestUploadMultipart_SupersededByPeer/missing184=== PAUSE TestGetStorePathHash/valid_store_path185=== PAUSE TestUploadMultipart_SupersededByPeer/missing186=== RUN TestGetStorePathHash/basename_without_hyphen_should_error187=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts188=== PAUSE TestParsePathInfoJSON/Nix_format189=== RUN TestParsePathInfoJSON/Lix_format190=== PAUSE TestParsePathInfoJSON/Lix_format191=== RUN TestParsePathInfoJSON/empty_input192=== PAUSE TestParsePathInfoJSON/empty_input193=== RUN TestParsePathInfoJSON/whitespace_only194=== CONT TestScriptTokenEmptyCommand195=== PAUSE TestParsePathInfoJSON/whitespace_only196=== RUN TestParsePathInfoJSON/invalid_JSON197=== PAUSE TestParsePathInfoJSON/invalid_JSON198=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon199=== CONT TestScriptTokenBadJSON200=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI201=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI202=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512203=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512204=== CONT TestScriptTokenEmptyToken205=== CONT TestEncodeNixBase32206=== RUN TestEncodeNixBase32/test_string_hash207=== CONT TestSetClientTLS208=== RUN TestFilterOversizedClosures/no_limit_keeps_everything209=== CONT TestScriptTokenScriptFails210--- PASS: TestEncodeNixBase32WithRealHash (0.00s)211--- PASS: TestScriptTokenEmptyCommand (0.00s)212=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error213=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error214=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error215=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error216=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error217=== RUN TestSupersededNARStillUploadsListing/small_NAR218=== PAUSE TestSupersededNARStillUploadsListing/small_NAR219=== CONT TestStreamPushIsolatesFailures220=== RUN TestSupersededNARStillUploadsListing/dump_cut_short221=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short222=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails223=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails224=== RUN TestPartSizeForNAR/1_TiB225=== PAUSE TestPartSizeForNAR/1_TiB226=== RUN TestPartSizeForNAR/5_TiB_S3_max_object227=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object228=== RUN TestPartSizeForNAR/capped_at_5_GiB229=== PAUSE TestPartSizeForNAR/capped_at_5_GiB230=== CONT TestStreamPushStopsWhenCanceled2312026/10/27 08:39:37 WARN Rate limiter backed off name=server-test rate=52322026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:35319233=== PAUSE TestEncodeNixBase32/test_string_hash234=== RUN TestEncodeNixBase32/empty_input235=== PAUSE TestEncodeNixBase32/empty_input236=== CONT TestScriptTokenCachesUntilRefresh237=== CONT TestScriptTokenNoExpiryRerunsEveryCall238--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.07s)239=== CONT TestClientSignaturesByStorePath240--- PASS: TestClientSignaturesByStorePath (0.00s)241=== CONT TestFileTokenEmpty242--- PASS: TestFileTokenEmpty (0.00s)243=== CONT TestStreamPushReportsSkippedPaths244=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything245=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped246=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped247=== RUN TestFilterOversizedClosures/all_closures_skipped248=== PAUSE TestFilterOversizedClosures/all_closures_skipped249=== CONT TestFileTokenMissing250--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)251 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.03s)252 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.03s)253=== CONT TestStreamPushReportsSignatures254--- PASS: TestStreamPushStopsWhenCanceled (0.00s)255=== CONT TestFileTokenReadsAndCaches256=== PAUSE TestRateLimiterFeedback/429_enables_limiter257=== RUN TestRateLimiterFeedback/503_enables_limiter258=== PAUSE TestRateLimiterFeedback/503_enables_limiter259=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter260=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter261=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter262=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter263=== CONT TestStreamPushRequestLine2642026/10/27 08:39:37 INFO Garbage collection started265--- PASS: TestFileTokenMissing (0.00s)266=== CONT TestStreamPushGivesUpOnDeadServer267--- PASS: TestStreamPushReportsSkippedPaths (0.00s)268=== CONT TestStaticToken269--- PASS: TestStaticToken (0.00s)270=== CONT TestSetClientTLSErrors271--- PASS: TestFileTokenReadsAndCaches (0.00s)272=== CONT TestSetClientTLSDoesNotMutateDefaultTransport2732026/10/27 08:39:37 ERROR Upload failed error="bad path" count=3274--- PASS: TestStreamPushIsolatesFailures (0.00s)275=== CONT TestShellSplitErrors276--- PASS: TestShellSplitErrors (0.00s)277=== CONT TestStreamPushBatchesUnderLoad278=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false279=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false280=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true281=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true282=== CONT TestDoWithRetry_FinalResponseBodyReadable2832026/10/27 08:39:37 INFO Garbage collection started2842026/10/27 08:39:37 WARN Rate limiter enabled after throttle name=server-test rate=52852026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:342052862026/10/27 08:39:37 WARN Rate limiter backed off name=server-test rate=5287--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.00s)288=== CONT TestStreamPushReportsEveryPath289--- PASS: TestStreamPushReportsEveryPath (0.00s)290=== CONT TestShellSplit291--- PASS: TestScriptTokenEmptyToken (0.01s)292=== CONT TestRetryTimeoutOutlastsMaxRetries2932026/10/27 08:39:37 ERROR Upload failed error=boom count=1294--- PASS: TestStreamPushReportsSignatures (0.00s)295=== CONT TestPathInfoCACompatibility/null_ca_field296=== CONT TestPathInfoCACompatibility/new_structured_format_-_text297=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method298=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive299=== CONT TestPathInfoCACompatibility/old_string_format_-_text300--- PASS: TestPathInfoCACompatibility (0.00s)301 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)302 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)303 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)304 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)305 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)306=== CONT TestConvertHashToNix32/SRI_format_to_Nix32307=== CONT TestConvertHashToNix32/invalid_format308=== CONT TestConvertHashToNix32/already_Nix32_format309--- PASS: TestConvertHashToNix32 (0.03s)310 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)311 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)312 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)313=== CONT TestUploadMultipart_SupersededByPeer/exists3142026/10/27 08:39:37 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=0315--- PASS: TestScriptTokenScriptFails (0.01s)3162026/10/27 08:39:37 ERROR Upload failed error="connection refused" count=20317=== CONT TestUploadMultipart_SupersededByPeer/missing3182026/10/27 08:39:37 ERROR Server seems unavailable, giving up on batch untried=173192026/10/27 08:39:37 ERROR Upload failed error=boom count=1320--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)321=== CONT TestParsePathInfoJSON/Nix_format322--- PASS: TestScriptTokenBadJSON (0.01s)323=== CONT TestParsePathInfoJSON/whitespace_only324=== CONT TestParsePathInfoJSON/invalid_JSON325=== CONT TestParsePathInfoJSON/Lix_format326=== CONT TestParsePathInfoJSON/empty_input327=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)328=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512329--- PASS: TestParsePathInfoJSON (0.03s)330 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)331 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)332 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)333 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)334 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)335=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI336=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon337=== CONT TestGetStorePathHash/valid_store_path338--- PASS: TestPathInfoHashCompatibility (0.03s)339 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)340 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)341 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)342 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)343=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error344=== CONT TestGetStorePathHash/basename_without_hyphen_should_error345=== CONT TestSupersededNARStillUploadsListing/small_NAR3462026/10/27 08:39:37 INFO Uploading abc-hello (1.0GB)347--- PASS: TestShellSplit (0.00s)3482026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:39085349=== CONT TestPartSizeForNAR/capped_at_5_GiB350=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails3512026/10/27 08:39:37 INFO Uploading abc-hello (1.0GB)3522026/10/27 08:39:37 WARN Garbage collection finished on another replica. Its statistics are not available here353--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.04s)354--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.05s)3552026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:390853562026/10/27 08:39:37 WARN Rate limiter enabled after throttle name=s3-test rate=53572026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:35849358--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.05s)3592026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:39085360=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error361--- PASS: TestGetStorePathHash (0.00s)362 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)363 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)364 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)365 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)366=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts367=== CONT TestPartSizeForNAR/1_TiB368=== CONT TestEncodeNixBase32/empty_input369=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum370=== CONT TestPartSizeForNAR/small_stays_at_minimum371=== CONT TestFilterOversizedClosures/no_limit_keeps_everything372=== CONT TestPartSizeForNAR/5_TiB_S3_max_object373=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3742026/10/27 08:39:37 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=2000375=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter376=== CONT TestRateLimiterFeedback/429_enables_limiter377=== CONT TestFilterOversizedClosures/all_closures_skipped3782026/10/27 08:39:37 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=50379=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter380--- PASS: TestScriptTokenCachesUntilRefresh (0.01s)381--- PASS: TestFilterOversizedClosures (0.03s)382 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)383 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)384 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)385=== RUN TestSetClientTLS/rejects_connection_without_client_cert386=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert387=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA388=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA389=== RUN TestSetClientTLS/preserves_debug_logging_transport390=== PAUSE TestSetClientTLS/preserves_debug_logging_transport391=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false3922026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:39085393=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true394=== CONT TestSetClientTLS/rejects_connection_without_client_cert3952026/10/27 08:39:37 WARN Rate limiter enabled after throttle name=server-test rate=53962026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:46061397--- PASS: TestStreamPushBatchesUnderLoad (0.00s)398 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)399 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)400=== CONT TestPartSizeForNAR/zero_stays_at_minimum401--- PASS: TestPartSizeForNAR (0.03s)402 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)403 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)404 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)405 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)406 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)407 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)408 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)409=== RUN TestSetClientTLSErrors/missing_cert_file410=== PAUSE TestSetClientTLSErrors/missing_cert_file411=== RUN TestSetClientTLSErrors/missing_key_file412=== PAUSE TestSetClientTLSErrors/missing_key_file413=== RUN TestSetClientTLSErrors/missing_ca_file414=== PAUSE TestSetClientTLSErrors/missing_ca_file415=== RUN TestSetClientTLSErrors/invalid_ca_file416=== PAUSE TestSetClientTLSErrors/invalid_ca_file417=== CONT TestSetClientTLSErrors/missing_cert_file418=== CONT TestSupersededNARStillUploadsListing/dump_cut_short419=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA4202026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:390854212026/10/27 08:39:37 WARN Rate limiter backed off name=server-test rate=5422=== CONT TestEncodeNixBase32/test_string_hash423=== CONT TestRateLimiterFeedback/503_enables_limiter424=== CONT TestSetClientTLSErrors/invalid_ca_file425=== CONT TestSetClientTLS/preserves_debug_logging_transport426=== CONT TestSetClientTLSErrors/missing_ca_file427=== CONT TestSetClientTLSErrors/missing_key_file428--- PASS: TestEncodeNixBase32 (0.00s)429 --- PASS: TestEncodeNixBase32/empty_input (0.00s)430 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)431--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.17s)432--- PASS: TestUploadMultipart_SupersededByPeer (0.03s)433 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)434 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.17s)435--- PASS: TestDumpPathSingleFile (0.21s)4362026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:39085437--- PASS: TestSetClientTLSErrors (0.01s)438 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)439 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)440 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.15s)441 --- PASS: TestSetClientTLSErrors/missing_key_file (0.16s)442--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.17s)4432026/10/27 08:39:37 WARN Rate limiter enabled after throttle name=server-test rate=54442026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:458554452026/10/27 08:39:37 WARN Rate limiter backed off name=server-test rate=5446--- PASS: TestRateLimiterFeedback (0.04s)447 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)448 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)449 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)450 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.16s)4512026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:39085452--- PASS: TestCaseHackSuffix (0.20s)4532026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:390854542026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:390854552026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:390854562026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:390854572026/10/27 08:39:37 http: TLS handshake error from 127.0.0.1:45688: remote error: tls: bad certificate4582026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:39085459--- PASS: TestSetClientTLS (0.02s)460 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.16s)461 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.16s)462 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.17s)4632026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:390854642026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:390854652026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:390854662026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:390854672026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:390854682026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:390854692026/10/27 08:39:37 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:39085470--- PASS: TestStreamPushRequestLine (0.20s)4712026/10/27 08:39:37 INFO Uploading abc-hello (1.0GB)472--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.19s)473--- PASS: TestRegisterUploadedObjectReusesConnections (0.23s)474--- PASS: TestDumpPathWriterError (0.27s)4752026/10/27 08:39:37 WARN Rate limiter enabled after throttle name=s3-test rate=54762026/10/27 08:39:37 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:44063/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:44063/part/24772026/10/27 08:39:37 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"478--- PASS: TestDumpPathMatchesNix (0.28s)479--- PASS: TestSupersededNARStillUploadsListing (0.03s)480 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.17s)481 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.17s)482 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.70s)483--- PASS: TestUploadMultipart_PartsInParallel (0.82s)484--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.80s)4852026/10/27 08:39:38 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:35599/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:35599/api/uploads/complete4862026/10/27 08:39:38 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:35599/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:35599/api/uploads/complete4872026/10/27 08:39:38 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4882026/10/27 08:39:38 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4892026/10/27 08:39:38 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:35599/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:35599/api/uploads/complete4902026/10/27 08:39:38 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"491--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.03s)492--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)493PASS494Running server tests...495The files belonging to this database system will be owned by user "nixbld".496This user must also own the server process.497498The database cluster will be initialized with locale "C".499The default database encoding has accordingly been set to "SQL_ASCII".500The default text search configuration will be set to "english".501502Data page checksums are enabled.503504creating directory /build/postgres636952582/data ... ok505creating subdirectories ... ok506selecting dynamic shared memory implementation ... posix507selecting default "max_connections" ... 100508selecting default "shared_buffers" ... 128MB509selecting default time zone ... UTC510creating configuration files ... ok511running bootstrap script ... ok512performing post-bootstrap initialization ... ok513syncing data to disk ... ok514515initdb: warning: enabling "trust" authentication for local connections516initdb: 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.517518Success. You can now start the database server using:519520 pg_ctl -D /build/postgres636952582/data -l logfile start521522/build/postgres636952582:5432 - no response5232026-10-27 08:39:38.992 UTC [128] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit5242026-10-27 08:39:38.992 UTC [128] LOG: listening on Unix socket "/build/postgres636952582/.s.PGSQL.5432"5252026-10-27 08:39:38.996 UTC [135] LOG: database system was shut down at 2026-10-27 08:39:38 UTC5262026-10-27 08:39:38.999 UTC [128] LOG: database system is ready to accept connections527/build/postgres636952582:5432 - accepting connections528=== RUN TestService_AuthMiddleware529=== PAUSE TestService_AuthMiddleware530=== RUN TestService_AuthMiddleware_MTLSProxyHeader531=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader532=== RUN TestService_AuthMiddleware_MTLSBoundSubjects533=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects534=== RUN TestService_ReadAuthMiddleware535=== PAUSE TestService_ReadAuthMiddleware536=== RUN TestService_AuthMiddleware_OIDC537=== PAUSE TestService_AuthMiddleware_OIDC538=== RUN TestService_RequireScope_OIDC539=== PAUSE TestService_RequireScope_OIDC540=== RUN TestService_ReadScope_PublicByDefault541=== PAUSE TestService_ReadScope_PublicByDefault542=== RUN TestCacheConfigHandler543=== PAUSE TestCacheConfigHandler544=== RUN TestCacheStatsHandler545=== PAUSE TestCacheStatsHandler546=== RUN TestClientCADerivations547=== PAUSE TestClientCADerivations548=== RUN TestClientErrorHandling549=== PAUSE TestClientErrorHandling550=== RUN TestClientIntegration551=== PAUSE TestClientIntegration552=== RUN TestClientMultipleUploads553=== PAUSE TestClientMultipleUploads554=== RUN TestClientWithDependencies555=== PAUSE TestClientWithDependencies556=== RUN TestClientSharedPathCommittedMidPush557=== PAUSE TestClientSharedPathCommittedMidPush558=== RUN TestPinProtectsFromGC559=== PAUSE TestPinProtectsFromGC560=== RUN TestClientPushesUseOnePush561=== PAUSE TestClientPushesUseOnePush562=== RUN TestClientFallsBackToClosures563=== PAUSE TestClientFallsBackToClosures564=== RUN TestDeleteClosuresRacingPins565=== PAUSE TestDeleteClosuresRacingPins566=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock567=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock568=== RUN TestResolveDBConnectionString569=== PAUSE TestResolveDBConnectionString570=== RUN TestConnectWaitsForAPeerMigration571=== PAUSE TestConnectWaitsForAPeerMigration572=== RUN TestLeadElectsOneAndHandsOver573=== PAUSE TestLeadElectsOneAndHandsOver574=== RUN TestLeadIncumbentWinsAfterRestart5752026/10/27 08:39:39 INFO lead: acquired remote=192.0.2.1:12345762026/10/27 08:39:39 INFO lead: released remote=192.0.2.1:12345772026/10/27 08:39:39 INFO lead: acquired remote=192.0.2.1:12345782026/10/27 08:39:41 INFO lead: released remote=192.0.2.1:1234579--- PASS: TestLeadIncumbentWinsAfterRestart (1.84s)580=== RUN TestLeadIncumbentAnnouncesAtOnce581=== PAUSE TestLeadIncumbentAnnouncesAtOnce582=== RUN TestLeadEndsOnShutdown583=== PAUSE TestLeadEndsOnShutdown584=== RUN TestLeadEndsWhenItsConnectionHangs5852026/10/27 08:39:41 INFO lead: acquired remote=192.0.2.1:12345862026-10-27 08:39:42.547 UTC [213] FATAL: terminating connection due to administrator command5872026/10/27 08:39:42 INFO lead: acquired remote=192.0.2.1:12345882026/10/27 08:39:43 WARN lead: lock connection lost error="timeout: context deadline exceeded"5892026/10/27 08:39:43 INFO lead: released remote=192.0.2.1:12345902026/10/27 08:39:44 INFO lead: released remote=192.0.2.1:1234591--- PASS: TestLeadEndsWhenItsConnectionHangs (3.11s)592=== RUN TestGCAdvisoryLockBlocksConcurrentRun593=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun594=== RUN TestGCBugBareHashReferences595=== PAUSE TestGCBugBareHashReferences596=== RUN TestGCMetrics597=== PAUSE TestGCMetrics598=== RUN TestPushDedupSurvivesConcurrentGC599=== PAUSE TestPushDedupSurvivesConcurrentGC600=== RUN TestDeduplicatedObjectsRecordedAsPending601=== PAUSE TestDeduplicatedObjectsRecordedAsPending602=== RUN TestGCSweepSkipsPendingObjects603=== PAUSE TestGCSweepSkipsPendingObjects604=== RUN TestTombstonedObjectOfferedWithoutWaiting605=== PAUSE TestTombstonedObjectOfferedWithoutWaiting606=== RUN TestGCSweepDeliversEachKeyOnce607=== PAUSE TestGCSweepDeliversEachKeyOnce608=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection609=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection610=== RUN TestForceGCDuringPushOffersSweptObject611=== PAUSE TestForceGCDuringPushOffersSweptObject612=== RUN TestFailedS3DeleteKeepsTombstone613=== PAUSE TestFailedS3DeleteKeepsTombstone614=== RUN TestSweepSkipsRowsLockedByPush615=== PAUSE TestSweepSkipsRowsLockedByPush616=== RUN TestRegisterCompletedObjectNeedsPendingRow617=== PAUSE TestRegisterCompletedObjectNeedsPendingRow618=== RUN TestGetExistingObjectsLocksRows619=== PAUSE TestGetExistingObjectsLocksRows620=== RUN TestSweepRechecksPendingAfterLocking621=== PAUSE TestSweepRechecksPendingAfterLocking622=== RUN TestPushWaitsForSweepHoldingRow623=== PAUSE TestPushWaitsForSweepHoldingRow624=== RUN TestCommitRacingPendingCleanupKeepsObjects625=== PAUSE TestCommitRacingPendingCleanupKeepsObjects626=== RUN TestGCEndsOnShutdown627=== PAUSE TestGCEndsOnShutdown628=== RUN TestGCTaskStore_StartNew629=== PAUSE TestGCTaskStore_StartNew630=== RUN TestGCTaskStore_DeduplicateSameParams631=== PAUSE TestGCTaskStore_DeduplicateSameParams632=== RUN TestGCTaskStore_ConflictDifferentParams633=== PAUSE TestGCTaskStore_ConflictDifferentParams634=== RUN TestGCTaskStore_GetEmpty635=== PAUSE TestGCTaskStore_GetEmpty636=== RUN TestGCTaskStore_GetReturnsLatest637=== PAUSE TestGCTaskStore_GetReturnsLatest638=== RUN TestGCTaskStore_CompletedAllowsNewTask639=== PAUSE TestGCTaskStore_CompletedAllowsNewTask640=== RUN TestGCTaskStore_PhaseUpdates641=== PAUSE TestGCTaskStore_PhaseUpdates642=== RUN TestGCTaskStore_Fail643=== PAUSE TestGCTaskStore_Fail644=== RUN TestGracefulShutdownDrainsInflight645=== PAUSE TestGracefulShutdownDrainsInflight646=== RUN TestService_healthCheckHandler647=== PAUSE TestService_healthCheckHandler648=== RUN TestService_readinessHandler649=== PAUSE TestService_readinessHandler650=== RUN TestGenerateLandingPage651=== PAUSE TestGenerateLandingPage652=== RUN TestCacheConfigHandlerMaxNarSize653=== PAUSE TestCacheConfigHandlerMaxNarSize654=== RUN TestCreatePendingClosureRejectsOversizedNAR655=== PAUSE TestCreatePendingClosureRejectsOversizedNAR656=== RUN TestNARDeduplicationMetadataUploadBug657=== PAUSE TestNARDeduplicationMetadataUploadBug658=== RUN TestMetricsInventory659=== PAUSE TestMetricsInventory660=== RUN TestMetricsCommit661=== PAUSE TestMetricsCommit662=== RUN TestService_NativeMTLS663=== PAUSE TestService_NativeMTLS664=== RUN TestServerTLSConfig665=== PAUSE TestServerTLSConfig666=== RUN TestMultipartCleanup667=== PAUSE TestMultipartCleanup668=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded669=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded670=== RUN TestPendingCleanupUsesOneCutoff671=== PAUSE TestPendingCleanupUsesOneCutoff672=== RUN TestObjectStatsTrigger673=== PAUSE TestObjectStatsTrigger674=== RUN TestObjectStatsUpdatedOncePerCommit675=== PAUSE TestObjectStatsUpdatedOncePerCommit676=== RUN TestOrphanedObjectsGC677=== PAUSE TestOrphanedObjectsGC678=== RUN TestOrphanedObjectsGCStressTest679=== PAUSE TestOrphanedObjectsGCStressTest680=== RUN TestCreatePin_ReservedPins681=== PAUSE TestCreatePin_ReservedPins682=== RUN TestPresentReportsOnlyClosureRoots683=== PAUSE TestPresentReportsOnlyClosureRoots684=== RUN TestPresentRefreshesOnlyStaleClosures685=== PAUSE TestPresentRefreshesOnlyStaleClosures686=== RUN TestPresentNotReportedWhileGCDeletesClosure687=== PAUSE TestPresentNotReportedWhileGCDeletesClosure688=== RUN TestParseSingleRange689=== PAUSE TestParseSingleRange690=== RUN TestProxyHeadersOnlyTrustedOnSocket6912026/10/27 08:39:44 INFO Starting HTTP server address=127.0.0.1:427176922026/10/27 08:39:44 INFO Starting HTTP server address=proxy.sock6932026/10/27 08:39:44 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6942026/10/27 08:39:44 INFO Shutdown signal received, draining in-flight requests timeout=10s695--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.09s)696=== RUN TestIsValidCachePath697=== PAUSE TestIsValidCachePath698=== RUN TestReadProxyNarinfo699=== PAUSE TestReadProxyNarinfo700=== RUN TestReadProxyNarinfoAlreadyDecompressed701=== PAUSE TestReadProxyNarinfoAlreadyDecompressed702=== RUN TestReadProxyContentNegotiation703=== PAUSE TestReadProxyContentNegotiation704=== RUN TestReadProxyNarStreaming705=== PAUSE TestReadProxyNarStreaming706=== RUN TestReadProxy404707=== PAUSE TestReadProxy404708=== RUN TestReadProxyInvalidPath709=== PAUSE TestReadProxyInvalidPath710=== RUN TestReadProxyHead711=== PAUSE TestReadProxyHead712=== RUN TestReadProxyOutlastsServerWriteTimeout713=== PAUSE TestReadProxyOutlastsServerWriteTimeout714=== RUN TestReadProxyConditionalGet715=== PAUSE TestReadProxyConditionalGet716=== RUN TestReadProxyRootRedirectsToIndexHTML717=== PAUSE TestReadProxyRootRedirectsToIndexHTML718=== RUN TestReadProxyDisabled719=== PAUSE TestReadProxyDisabled720=== RUN TestReadRedirectNar721=== PAUSE TestReadRedirectNar722=== RUN TestReadRedirectKeepsNarinfoProxied723=== PAUSE TestReadRedirectKeepsNarinfoProxied724=== RUN TestReadProxyRangeRequest725=== PAUSE TestReadProxyRangeRequest726=== RUN TestReadRedirectUsesPublicS3URL727=== PAUSE TestReadRedirectUsesPublicS3URL728=== RUN TestPush_OverlappingRootsStoreOneRowPerKey729=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey730=== RUN TestPush_CompleteCommitsEveryRoot731=== PAUSE TestPush_CompleteCommitsEveryRoot732=== RUN TestPush_RepeatedRootCommitsOnce733=== PAUSE TestPush_RepeatedRootCommitsOnce734=== RUN TestPush_CompleteWaitsForCleanupOfThePush735=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush736=== RUN TestPush_RootsAreLockedInByteOrder737=== PAUSE TestPush_RootsAreLockedInByteOrder738=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit739=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit740=== RUN TestPush_RejectsBadRequests741=== PAUSE TestPush_RejectsBadRequests742=== RUN TestPush_SignsNarinfosOfItsPendingObjects743=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects744=== RUN TestRedundantMultipartUpload745=== PAUSE TestRedundantMultipartUpload746=== RUN TestCompleteMultipartUpload_ErrorButObjectExists747=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists748=== RUN TestCompletedNarNotReofferedAcrossClosures749=== PAUSE TestCompletedNarNotReofferedAcrossClosures750=== RUN TestPresignedUploadRegisteredBeforeCommit751=== PAUSE TestPresignedUploadRegisteredBeforeCommit752=== RUN TestService_Rustfstest753=== PAUSE TestService_Rustfstest754=== RUN TestParseSize755=== PAUSE TestParseSize756=== RUN TestSkippedUploadsHandler757=== PAUSE TestSkippedUploadsHandler758=== RUN TestSystemdListenerNotActivated759--- PASS: TestSystemdListenerNotActivated (0.00s)760=== RUN TestWatchdogBeatsWhenHealthy761--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)762=== RUN TestWatchdogSkipsWhenUnhealthy7632026/10/27 08:39:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7642026/10/27 08:39:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7652026/10/27 08:39:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7662026/10/27 08:39:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7672026/10/27 08:39:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7682026/10/27 08:39:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7692026/10/27 08:39:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/10/27 08:39:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/10/27 08:39:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/10/27 08:39:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"773--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)774=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle775=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle776=== RUN TestProxyWriteTimeout777=== PAUSE TestProxyWriteTimeout778=== RUN TestPendingClosureWriteTimeout779=== PAUSE TestPendingClosureWriteTimeout780=== RUN TestIsValidUploadKey781=== PAUSE TestIsValidUploadKey782=== RUN TestUploadHandlersRejectInvalidKeys783=== PAUSE TestUploadHandlersRejectInvalidKeys784=== RUN TestUploadHandlersRejectOversizedBody785=== PAUSE TestUploadHandlersRejectOversizedBody786=== RUN TestService_cleanupPendingClosuresHandler787=== PAUSE TestService_cleanupPendingClosuresHandler788=== RUN TestService_createPendingClosureHandler789=== PAUSE TestService_createPendingClosureHandler790=== RUN TestService_verifyS3Integrity791=== PAUSE TestService_verifyS3Integrity792=== RUN TestCompleteMultipartUnregistered793=== PAUSE TestCompleteMultipartUnregistered794=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT795=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT796=== CONT TestPush_RepeatedRootCommitsOnce797=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle798=== CONT TestService_AuthMiddleware799=== CONT TestPush_CompleteCommitsEveryRoot800=== CONT TestPush_OverlappingRootsStoreOneRowPerKey801=== CONT TestReadRedirectUsesPublicS3URL802=== CONT TestReadProxyRangeRequest803=== CONT TestReadRedirectKeepsNarinfoProxied804=== CONT TestSkippedUploadsHandler805=== CONT TestReadRedirectNar8062026/10/27 08:39:44 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000807=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT808=== CONT TestCompleteMultipartUnregistered809=== CONT TestReadProxyDisabled810=== CONT TestService_verifyS3Integrity811=== CONT TestReadProxyRootRedirectsToIndexHTML812=== CONT TestService_createPendingClosureHandler813=== CONT TestService_cleanupPendingClosuresHandler814=== CONT TestUploadHandlersRejectOversizedBody815--- PASS: TestSkippedUploadsHandler (0.00s)816=== CONT TestReadProxyHead817=== CONT TestUploadHandlersRejectInvalidKeys818=== CONT TestIsValidUploadKey819=== CONT TestReadProxyConditionalGet820=== CONT TestPendingClosureWriteTimeout821=== CONT TestReadProxyOutlastsServerWriteTimeout822=== RUN TestPendingClosureWriteTimeout/empty823=== PAUSE TestPendingClosureWriteTimeout/empty824=== RUN TestPendingClosureWriteTimeout/400_objects825=== PAUSE TestPendingClosureWriteTimeout/400_objects826=== CONT TestProxyWriteTimeout827=== RUN TestProxyWriteTimeout/narinfo828=== RUN TestPendingClosureWriteTimeout/670k_objects829=== PAUSE TestPendingClosureWriteTimeout/670k_objects830=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline831=== RUN TestIsValidUploadKey/narinfo832=== PAUSE TestIsValidUploadKey/narinfo833=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info834=== PAUSE TestProxyWriteTimeout/narinfo835=== RUN TestProxyWriteTimeout/1_GiB_nar836=== PAUSE TestProxyWriteTimeout/1_GiB_nar837=== RUN TestProxyWriteTimeout/10_GiB_nar838=== PAUSE TestProxyWriteTimeout/10_GiB_nar839=== RUN TestProxyWriteTimeout/unknown_size840=== PAUSE TestProxyWriteTimeout/unknown_size841=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info842=== CONT TestReadProxyInvalidPath843=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal844=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal845=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key846=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key847=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key848=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline849=== RUN TestIsValidUploadKey/nar_zst850=== CONT TestReadProxy404851=== PAUSE TestIsValidUploadKey/nar_zst852=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key853=== RUN TestIsValidUploadKey/nar_xz854=== PAUSE TestIsValidUploadKey/nar_xz855=== CONT TestReadProxyNarStreaming856=== RUN TestIsValidUploadKey/nar_plain857=== PAUSE TestIsValidUploadKey/nar_plain858=== RUN TestIsValidUploadKey/listing859=== PAUSE TestIsValidUploadKey/listing860=== RUN TestIsValidUploadKey/build_log861=== PAUSE TestIsValidUploadKey/build_log862=== RUN TestIsValidUploadKey/build_log_home-manager_file863=== PAUSE TestIsValidUploadKey/build_log_home-manager_file864=== RUN TestIsValidUploadKey/build_log_plus_in_name865=== PAUSE TestIsValidUploadKey/build_log_plus_in_name866=== RUN TestIsValidUploadKey/build_log_question_mark867=== PAUSE TestIsValidUploadKey/build_log_question_mark868=== RUN TestIsValidUploadKey/build_log_equals869=== PAUSE TestIsValidUploadKey/build_log_equals870=== RUN TestIsValidUploadKey/realisation871=== PAUSE TestIsValidUploadKey/realisation872=== RUN TestIsValidUploadKey/realisation_plus_in_output873=== PAUSE TestIsValidUploadKey/realisation_plus_in_output874=== RUN TestIsValidUploadKey/nix-cache-info875=== PAUSE TestIsValidUploadKey/nix-cache-info876=== RUN TestIsValidUploadKey/index.html877=== PAUSE TestIsValidUploadKey/index.html878=== RUN TestIsValidUploadKey/narinfo_key,_nar_type879=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type880=== RUN TestIsValidUploadKey/nar_key,_narinfo_type881=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type882=== RUN TestIsValidUploadKey/listing_key,_narinfo_type883=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type884=== RUN TestIsValidUploadKey/traversal885=== PAUSE TestIsValidUploadKey/traversal886=== RUN TestIsValidUploadKey/traversal_nar887=== PAUSE TestIsValidUploadKey/traversal_nar888=== RUN TestIsValidUploadKey/absolute889=== PAUSE TestIsValidUploadKey/absolute890=== RUN TestIsValidUploadKey/empty_key891=== PAUSE TestIsValidUploadKey/empty_key892=== RUN TestIsValidUploadKey/unknown_type893=== PAUSE TestIsValidUploadKey/unknown_type894=== CONT TestRedundantMultipartUpload895=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart896=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart897=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts898=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts899=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure900=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure901=== CONT TestReadProxyContentNegotiation9022026/10/27 08:39:44 INFO Received uploads request method=POST path=/api/pending_closures903--- PASS: TestReadProxyRangeRequest (0.46s)904=== CONT TestParseSize905--- PASS: TestParseSize (0.00s)906=== CONT TestReadProxyNarinfoAlreadyDecompressed9072026/10/27 08:39:44 INFO Received push request method=POST path=/api/pushes908--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.49s)909=== CONT TestService_Rustfstest910--- PASS: TestReadRedirectUsesPublicS3URL (0.50s)911=== CONT TestPresignedUploadRegisteredBeforeCommit9122026/10/27 08:39:44 INFO Received push request method=POST path=/api/pushes9132026/10/27 08:39:44 INFO Received complete push request method=POST path=/api/pushes/1/complete9142026/10/27 08:39:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9152026/10/27 08:39:44 INFO Received uploads request method=POST path=/api/pending_closures9162026/10/27 08:39:44 INFO Completed push id=1 objects=4 duration=7.308249ms917--- PASS: TestPush_RepeatedRootCommitsOnce (0.53s)918=== CONT TestReadProxyNarinfo9192026/10/27 08:39:45 INFO Received uploads request method=POST path=/api/pending_closures920--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.56s)921=== CONT TestCompletedNarNotReofferedAcrossClosures9222026/10/27 08:39:45 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"923--- PASS: TestService_AuthMiddleware (0.58s)924=== CONT TestIsValidCachePath925=== RUN TestIsValidCachePath/narinfo926=== PAUSE TestIsValidCachePath/narinfo927=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars928=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars929=== RUN TestIsValidCachePath/nar_zst930=== PAUSE TestIsValidCachePath/nar_zst931=== RUN TestIsValidCachePath/nar_xz932=== PAUSE TestIsValidCachePath/nar_xz933=== RUN TestIsValidCachePath/nar_bz2934=== PAUSE TestIsValidCachePath/nar_bz2935=== RUN TestIsValidCachePath/nar_uncompressed936=== PAUSE TestIsValidCachePath/nar_uncompressed937=== RUN TestIsValidCachePath/ls938=== PAUSE TestIsValidCachePath/ls939=== RUN TestIsValidCachePath/log940=== PAUSE TestIsValidCachePath/log941=== RUN TestIsValidCachePath/realisation942=== PAUSE TestIsValidCachePath/realisation943=== RUN TestIsValidCachePath/nix-cache-info944=== PAUSE TestIsValidCachePath/nix-cache-info945=== RUN TestIsValidCachePath/index.html946=== PAUSE TestIsValidCachePath/index.html947=== RUN TestIsValidCachePath/traversal_parent948=== PAUSE TestIsValidCachePath/traversal_parent949=== RUN TestIsValidCachePath/traversal_in_middle950=== PAUSE TestIsValidCachePath/traversal_in_middle951=== RUN TestIsValidCachePath/invalid_char_e952=== PAUSE TestIsValidCachePath/invalid_char_e953=== RUN TestIsValidCachePath/invalid_char_u954=== PAUSE TestIsValidCachePath/invalid_char_u955=== RUN TestIsValidCachePath/random_path956=== PAUSE TestIsValidCachePath/random_path957=== RUN TestIsValidCachePath/empty958=== PAUSE TestIsValidCachePath/empty959=== RUN TestIsValidCachePath/leading_slash960=== PAUSE TestIsValidCachePath/leading_slash961=== RUN TestIsValidCachePath/wrong_extension962=== PAUSE TestIsValidCachePath/wrong_extension963=== RUN TestIsValidCachePath/short_hash964=== PAUSE TestIsValidCachePath/short_hash965=== CONT TestCompleteMultipartUpload_ErrorButObjectExists966--- PASS: TestReadRedirectKeepsNarinfoProxied (0.70s)967=== CONT TestParseSingleRange968=== RUN TestParseSingleRange/none969=== PAUSE TestParseSingleRange/none970=== RUN TestParseSingleRange/unknown_unit971=== PAUSE TestParseSingleRange/unknown_unit972=== RUN TestParseSingleRange/multi-range_ignored973=== PAUSE TestParseSingleRange/multi-range_ignored974=== RUN TestParseSingleRange/malformed_no_dash975=== PAUSE TestParseSingleRange/malformed_no_dash976=== RUN TestParseSingleRange/malformed_both_empty977=== PAUSE TestParseSingleRange/malformed_both_empty978=== RUN TestParseSingleRange/malformed_end_before_start979=== PAUSE TestParseSingleRange/malformed_end_before_start980=== RUN TestParseSingleRange/closed981=== PAUSE TestParseSingleRange/closed982=== RUN TestParseSingleRange/open-ended983=== PAUSE TestParseSingleRange/open-ended984=== RUN TestParseSingleRange/end_clamped_to_size985=== PAUSE TestParseSingleRange/end_clamped_to_size986=== RUN TestParseSingleRange/suffix987=== PAUSE TestParseSingleRange/suffix988=== RUN TestParseSingleRange/suffix_exceeds_size989=== PAUSE TestParseSingleRange/suffix_exceeds_size990=== RUN TestParseSingleRange/single_byte991=== PAUSE TestParseSingleRange/single_byte992=== RUN TestParseSingleRange/start_past_EOF993=== PAUSE TestParseSingleRange/start_past_EOF994=== RUN TestParseSingleRange/start_far_past_EOF995=== PAUSE TestParseSingleRange/start_far_past_EOF996=== CONT TestPresentNotReportedWhileGCDeletesClosure997=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale998=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale999=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1000=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1001=== CONT TestPresentRefreshesOnlyStaleClosures1002--- PASS: TestReadRedirectNar (0.74s)1003=== CONT TestPush_RootsAreLockedInByteOrder10042026/10/27 08:39:45 INFO Received push request method=POST path=/api/pushes10052026/10/27 08:39:45 INFO Received complete push request method=POST path=/api/pushes/1/complete1006--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.78s)1007=== CONT TestPresentReportsOnlyClosureRoots10082026/10/27 08:39:45 INFO Completed push id=1 objects=6 duration=10.122473ms1009--- PASS: TestPush_CompleteCommitsEveryRoot (0.79s)1010=== CONT TestFailedS3DeleteKeepsTombstone10112026/10/27 08:39:45 INFO Received cleanup request method=DELETE path=/api/pending_closures10122026/10/27 08:39:45 INFO Aborted multipart uploads count=0 kept=010132026/10/27 08:39:45 INFO Received uploads request method=POST path=/api/pending_closures10142026/10/27 08:39:45 INFO Received cleanup request method=DELETE path=/api/pending_closures10152026/10/27 08:39:45 INFO Aborted multipart uploads count=1 kept=010162026/10/27 08:39:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10172026-10-27 08:39:45.279 UTC [295] ERROR: Closure does not exist: id=110182026-10-27 08:39:45.279 UTC [295] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10192026-10-27 08:39:45.279 UTC [295] STATEMENT: -- name: CommitPendingClosure :one1020 SELECT commit_pending_closure($1::bigint)::bigint1021 1022--- PASS: TestService_cleanupPendingClosuresHandler (0.81s)1023=== CONT TestCreatePin_ReservedPins1024--- PASS: TestReadProxyNarStreaming (0.76s)1025=== CONT TestForceGCDuringPushOffersSweptObject1026=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1027=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1028=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1029=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1030=== CONT TestOrphanedObjectsGCStressTest10312026/10/27 08:39:45 INFO Received uploads request method=POST path=/api/pending_closures10322026/10/27 08:39:45 INFO Received uploads request method=POST path=/api/pending_closures10332026/10/27 08:39:45 INFO Received uploads request method=POST path=/api/pending_closures10342026/10/27 08:39:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10352026/10/27 08:39:45 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1036--- PASS: TestCompleteMultipartUnregistered (0.88s)1037=== CONT TestOrphanedObjectsGC10382026/10/27 08:39:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10392026/10/27 08:39:45 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35855/oidc1040--- PASS: TestReadProxyDisabled (0.90s)1041=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection10422026/10/27 08:39:45 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YzQzY2I4MzEtMTNjZS00MGE4LThmZDYtNmJlNDQ5OGY2MTViLjFlNDY1YmRiLTg4ZDktNGUzMy05MzgxLTI2NTk4OGFiMmMwZHgxNzkzMDkwMzg1MDAxMzMwMzE4 parts=1010432026/10/27 08:39:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10442026/10/27 08:39:45 INFO Completed upload id=1 objects=2 duration=3.712741ms10452026/10/27 08:39:45 INFO Received uploads request method=POST path=/api/pending_closures10462026/10/27 08:39:45 INFO Received uploads request method=POST path=/api/pending_closures10472026/10/27 08:39:45 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10482026/10/27 08:39:45 WARN Found objects in DB but missing from S3, will re-upload count=11049--- PASS: TestService_verifyS3Integrity (0.92s)1050=== CONT TestObjectStatsUpdatedOncePerCommit1051--- PASS: TestReadProxyHead (0.94s)1052=== CONT TestGCSweepDeliversEachKeyOnce1053--- PASS: TestReadProxyConditionalGet (0.94s)1054=== CONT TestObjectStatsTrigger1055--- PASS: TestReadProxy404 (0.96s)1056=== CONT TestTombstonedObjectOfferedWithoutWaiting10572026/10/27 08:39:45 INFO Received uploads request method=POST path=/api/pending_closures10582026/10/27 08:39:45 INFO Received uploads request method=POST path=/api/pending_closures1059--- PASS: TestReadProxyInvalidPath (1.00s)1060=== CONT TestPendingCleanupUsesOneCutoff1061--- PASS: TestReadProxyContentNegotiation (0.92s)1062=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded10632026/10/27 08:39:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1064--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.68s)1065=== CONT TestMultipartCleanup10662026/10/27 08:39:45 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YzQzY2I4MzEtMTNjZS00MGE4LThmZDYtNmJlNDQ5OGY2MTViLjAyYWM4NzUxLTRmOTItNDE5MS05ZGRmLTEwNDJiNTdkZDI5NHgxNzkzMDkwMzg1MzIxNjU3NjMz parts=1010672026/10/27 08:39:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10682026/10/27 08:39:45 INFO Completed upload id=1 objects=2 duration=2.949464ms10692026/10/27 08:39:45 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010702026/10/27 08:39:45 INFO Received uploads request method=POST path=/api/pending_closures10712026/10/27 08:39:45 INFO Starting cleanup of old closures method=DELETE path=/api/closures1072--- PASS: TestService_Rustfstest (0.66s)1073=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit10742026/10/27 08:39:45 INFO Aborted multipart uploads count=0 kept=010752026/10/27 08:39:45 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=010762026/10/27 08:39:45 INFO Vacuumed table table=pending_closures10772026/10/27 08:39:45 INFO Vacuumed table table=pending_objects10782026/10/27 08:39:45 INFO Vacuumed table table=multipart_uploads10792026/10/27 08:39:45 INFO Received uploads request method=POST path=/api/pending_closures10802026/10/27 08:39:45 INFO Vacuumed table table=closures10812026/10/27 08:39:45 INFO Vacuumed table table=objects10822026/10/27 08:39:45 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10832026/10/27 08:39:45 INFO Received uploads request method=POST path=/api/pending_closures1084--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.69s)1085=== CONT TestServerTLSConfig1086=== RUN TestServerTLSConfig/no_client_CA1087=== PAUSE TestServerTLSConfig/no_client_CA1088=== RUN TestServerTLSConfig/missing_CA_file1089=== PAUSE TestServerTLSConfig/missing_CA_file1090=== RUN TestServerTLSConfig/not_a_PEM_file1091=== PAUSE TestServerTLSConfig/not_a_PEM_file1092=== CONT TestPush_SignsNarinfosOfItsPendingObjects10932026/10/27 08:39:45 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001094--- PASS: TestService_createPendingClosureHandler (1.20s)1095=== CONT TestService_NativeMTLS10962026/10/27 08:39:45 INFO Received uploads request method=POST path=/api/pending_closures10972026/10/27 08:39:45 INFO Received uploads request method=POST path=/api/pending_closures10982026/10/27 08:39:45 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1099--- PASS: TestReadProxyNarinfo (0.73s)1100=== CONT TestPush_RejectsBadRequests1101--- PASS: TestPresentRefreshesOnlyStaleClosures (0.58s)1102=== CONT TestMetricsCommit11032026/10/27 08:39:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11042026/10/27 08:39:45 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YzQzY2I4MzEtMTNjZS00MGE4LThmZDYtNmJlNDQ5OGY2MTViLmQ3NTk1ZTI3LTM3MTYtNGYxOC1iYzdmLTMzZDI4MjA2Mzc0YngxNzkzMDkwMzg1NzI0NzAwNDEx11052026/10/27 08:39:45 INFO Received push request method=POST path=/api/pushes11062026/10/27 08:39:45 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YzQzY2I4MzEtMTNjZS00MGE4LThmZDYtNmJlNDQ5OGY2MTViLmQ3NTk1ZTI3LTM3MTYtNGYxOC1iYzdmLTMzZDI4MjA2Mzc0YngxNzkzMDkwMzg1NzI0NzAwNDEx parts=11107--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.73s)1108=== CONT TestGCSweepSkipsPendingObjects11092026-10-27 08:39:45.811 UTC [420] ERROR: could not obtain lock on row in relation "closures"11102026-10-27 08:39:45.811 UTC [420] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11112026-10-27 08:39:45.811 UTC [420] ERROR: could not obtain lock on row in relation "closures"11122026-10-27 08:39:45.811 UTC [420] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11132026-10-27 08:39:45.812 UTC [420] ERROR: could not obtain lock on row in relation "closures"11142026-10-27 08:39:45.812 UTC [420] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11152026-10-27 08:39:45.812 UTC [420] ERROR: could not obtain lock on row in relation "closures"11162026-10-27 08:39:45.812 UTC [420] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11172026-10-27 08:39:45.812 UTC [420] ERROR: could not obtain lock on row in relation "closures"11182026-10-27 08:39:45.812 UTC [420] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1119--- PASS: TestPresentReportsOnlyClosureRoots (0.57s)1120=== CONT TestGCTaskStore_GetReturnsLatest1121--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1122=== CONT TestDeduplicatedObjectsRecordedAsPending1123--- PASS: TestPush_RootsAreLockedInByteOrder (0.62s)1124=== CONT TestMetricsInventory11252026/10/27 08:39:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11262026/10/27 08:39:45 INFO Received uploads request method=POST path=/api/pending_closures11272026/10/27 08:39:45 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YzQzY2I4MzEtMTNjZS00MGE4LThmZDYtNmJlNDQ5OGY2MTViLmEyMTgyZWY3LTY1YmMtNGY5Zi1hNDMyLTJhYWU5NzA0ZTZhNngxNzkzMDkwMzg1NTE4ODYwMjY3 parts=1211282026/10/27 08:39:45 INFO Received uploads request method=POST path=/api/pending_closures11292026/10/27 08:39:45 INFO Received uploads request method=POST path=/api/pending_closures11302026/10/27 08:39:45 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11312026/10/27 08:39:45 WARN Refused reserved pin name=worker-x86_64-linux11322026/10/27 08:39:45 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11332026/10/27 08:39:45 INFO Received create pin request method=POST path=/api/pins/my-app11342026/10/27 08:39:45 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1135--- PASS: TestCreatePin_ReservedPins (0.65s)1136=== CONT TestPushDedupSurvivesConcurrentGC11372026/10/27 08:39:45 INFO Aborted multipart uploads count=0 kept=011382026/10/27 08:39:45 WARN Force mode enabled - objects will be deleted immediately without grace period11392026/10/27 08:39:45 INFO Received uploads request method=POST path=/api/pending_closures11402026/10/27 08:39:45 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."11412026/10/27 08:39:45 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1142--- PASS: TestFailedS3DeleteKeepsTombstone (0.71s)1143=== CONT TestNARDeduplicationMetadataUploadBug1144--- PASS: TestObjectStatsUpdatedOncePerCommit (0.61s)1145=== CONT TestGCTaskStore_GetEmpty1146--- PASS: TestGCTaskStore_GetEmpty (0.00s)1147=== CONT TestGCMetrics11482026/10/27 08:39:46 INFO Aborted multipart uploads count=0 kept=011492026/10/27 08:39:46 WARN Force mode enabled - objects will be deleted immediately without grace period1150--- PASS: TestObjectStatsTrigger (0.56s)1151=== CONT TestCreatePendingClosureRejectsOversizedNAR11522026/10/27 08:39:46 INFO Received uploads request method=POST path=/api/pending_closures1153--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1154=== CONT TestGCTaskStore_ConflictDifferentParams1155--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1156=== CONT TestCacheConfigHandlerMaxNarSize1157--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1158=== CONT TestGenerateLandingPage1159--- PASS: TestGenerateLandingPage (0.00s)1160=== CONT TestGCBugBareHashReferences11612026/10/27 08:39:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11622026/10/27 08:39:46 INFO Received uploads request method=POST path=/api/pending_closures1163--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.57s)1164=== CONT TestService_readinessHandler11652026/10/27 08:39:46 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YzQzY2I4MzEtMTNjZS00MGE4LThmZDYtNmJlNDQ5OGY2MTViLmRkYmU5YjE2LTM5ZDktNDUzYy1hOWViLTYyMDkzOTg5ZWU5NngxNzkzMDkwMzg1Njk3NjM0OTUw parts=1211662026/10/27 08:39:46 INFO Received uploads request method=POST path=/api/pending_closures11672026/10/27 08:39:46 INFO Received uploads request method=POST path=/api/pending_closures1168--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.79s)1169=== CONT TestGCTaskStore_DeduplicateSameParams1170--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1171=== CONT TestService_healthCheckHandler1172--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.13s)1173=== CONT TestGCAdvisoryLockBlocksConcurrentRun11742026/10/27 08:39:46 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=011752026/10/27 08:39:46 INFO Vacuumed table table=pending_closures11762026/10/27 08:39:46 INFO Vacuumed table table=pending_objects11772026/10/27 08:39:46 INFO Vacuumed table table=multipart_uploads11782026/10/27 08:39:46 INFO Vacuumed table table=closures11792026/10/27 08:39:46 INFO Vacuumed table table=objects1180--- PASS: TestGCSweepDeliversEachKeyOnce (0.77s)1181=== CONT TestGracefulShutdownDrainsInflight11822026/10/27 08:39:46 INFO Starting HTTP server address=127.0.0.1:4465311832026/10/27 08:39:46 INFO Shutdown signal received, draining in-flight requests timeout=10s11842026/10/27 08:39:46 INFO Received uploads request method=POST path=/api/pending_closures11852026/10/27 08:39:46 INFO Received cleanup request method=DELETE path=/api/pending_closures11862026/10/27 08:39:46 INFO Received uploads request method=POST path=/api/pending_closures1187--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.68s)1188=== CONT TestGCTaskStore_StartNew1189--- PASS: TestGCTaskStore_StartNew (0.00s)1190=== CONT TestGCEndsOnShutdown1191=== RUN TestGCEndsOnShutdown/before_the_run1192=== PAUSE TestGCEndsOnShutdown/before_the_run1193=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1194=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1195=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1196=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1197=== CONT TestGCTaskStore_Fail1198--- PASS: TestGCTaskStore_Fail (0.00s)1199=== CONT TestLeadEndsOnShutdown12002026/10/27 08:39:46 INFO Received uploads request method=POST path=/api/pending_closures1201--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1202=== CONT TestCommitRacingPendingCleanupKeepsObjects12032026/10/27 08:39:46 INFO Received push request method=POST path=/api/pushes12042026/10/27 08:39:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12052026/10/27 08:39:46 INFO Received complete push request method=POST path=/api/pushes/1/complete12062026/10/27 08:39:46 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12072026/10/27 08:39:46 INFO Completed push id=1 objects=4 duration=6.763436ms12082026/10/27 08:39:46 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1209--- PASS: TestService_NativeMTLS (0.62s)12102026/10/27 08:39:46 INFO Received push request method=POST path=/api/pushes1211=== CONT TestGCTaskStore_PhaseUpdates1212--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1213=== CONT TestLeadIncumbentAnnouncesAtOnce12142026/10/27 08:39:46 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YzQzY2I4MzEtMTNjZS00MGE4LThmZDYtNmJlNDQ5OGY2MTViLjYwMGJlODI5LTVlZWEtNGQwZi04OGZlLTZjODdmNjIxNGM0YXgxNzkzMDkwMzg1ODk1MjQwMTg3 error="Get \"http://127.0.0.1:1/bucket25/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"12152026/10/27 08:39:46 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YzQzY2I4MzEtMTNjZS00MGE4LThmZDYtNmJlNDQ5OGY2MTViLjRiOTk0NTIyLTRjMjItNDE2Mi1hMzk5LWU3MDNmZTRlM2NiNHgxNzkzMDkwMzg1ODgxOTQ3MjI5 parts=1212162026/10/27 08:39:46 INFO Received cleanup request method=DELETE path=/api/pending_closures12172026/10/27 08:39:46 INFO Aborted multipart uploads count=1 kept=01218--- PASS: TestRedundantMultipartUpload (1.76s)1219=== CONT TestPushWaitsForSweepHoldingRow12202026/10/27 08:39:46 INFO Received push request method=POST path=/api/pushes12212026/10/27 08:39:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12222026/10/27 08:39:46 INFO Signed narinfos id=1 count=112232026/10/27 08:39:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12242026/10/27 08:39:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12252026/10/27 08:39:46 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"12262026/10/27 08:39:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12272026/10/27 08:39:46 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"12282026/10/27 08:39:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12292026/10/27 08:39:46 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=112302026/10/27 08:39:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12312026/10/27 08:39:46 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1232--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.67s)1233=== CONT TestGCTaskStore_CompletedAllowsNewTask1234--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1235=== CONT TestSweepRechecksPendingAfterLocking1236=== NAME TestOrphanedObjectsGC1237 orphaned_objects_gc_test.go:287: GC Test Summary:1238 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1239 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1240 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1241 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1242 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1243--- PASS: TestOrphanedObjectsGC (0.99s)1244=== CONT TestLeadElectsOneAndHandsOver1245=== RUN TestPush_RejectsBadRequests/no_roots1246=== PAUSE TestPush_RejectsBadRequests/no_roots1247=== RUN TestPush_RejectsBadRequests/no_objects1248=== PAUSE TestPush_RejectsBadRequests/no_objects1249=== RUN TestPush_RejectsBadRequests/bad_root1250=== PAUSE TestPush_RejectsBadRequests/bad_root1251=== RUN TestPush_RejectsBadRequests/root_not_in_objects1252=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1253=== CONT TestPush_CompleteWaitsForCleanupOfThePush12542026/10/27 08:39:46 INFO Aborted multipart uploads count=0 kept=012552026/10/27 08:39:46 WARN Force mode enabled - objects will be deleted immediately without grace period12562026/10/27 08:39:46 INFO Received cleanup request method=DELETE path=/api/pending_closures12572026/10/27 08:39:46 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket48/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""12582026/10/27 08:39:46 INFO Aborted multipart uploads count=0 kept=112592026/10/27 08:39:46 INFO Received push request method=POST path=/api/pushes12602026/10/27 08:39:46 INFO Received cleanup request method=DELETE path=/api/pending_closures12612026/10/27 08:39:46 INFO Aborted multipart uploads count=1 kept=012622026/10/27 08:39:46 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=01263--- PASS: TestMultipartCleanup (0.77s)1264=== CONT TestConnectWaitsForAPeerMigration12652026/10/27 08:39:46 INFO Vacuumed table table=pending_closures12662026/10/27 08:39:46 INFO Vacuumed table table=pending_objects12672026/10/27 08:39:46 INFO Vacuumed table table=multipart_uploads12682026/10/27 08:39:46 INFO Vacuumed table table=closures12692026/10/27 08:39:46 INFO Vacuumed table table=objects12702026/10/27 08:39:46 INFO Received complete push request method=POST path=/api/pushes/2/complete12712026/10/27 08:39:46 INFO Received complete push request method=POST path=/api/pushes/1/complete12722026/10/27 08:39:46 INFO Completed push id=2 objects=4 duration=3.308877ms1273--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.77s)1274=== CONT TestGetExistingObjectsLocksRows12752026/10/27 08:39:46 INFO Completed push id=1 objects=4 duration=10.848198ms12762026/10/27 08:39:46 INFO Received uploads request method=POST path=/api/pending_closures12772026/10/27 08:39:46 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12782026/10/27 08:39:46 INFO Completed upload id=2 objects=2 duration=2.526331ms1279--- PASS: TestMetricsCommit (0.65s)1280=== CONT TestClientIntegration12812026/10/27 08:39:46 INFO Received uploads request method=POST path=/api/pending_closures12822026/10/27 08:39:46 INFO Aborted multipart uploads count=0 kept=01283--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.61s)1284=== CONT TestClientErrorHandling1285=== RUN TestClientErrorHandling/InvalidStorePath1286=== PAUSE TestClientErrorHandling/InvalidStorePath1287=== RUN TestClientErrorHandling/InvalidAuthToken1288=== PAUSE TestClientErrorHandling/InvalidAuthToken1289=== RUN TestClientErrorHandling/ServerNotAvailable1290=== PAUSE TestClientErrorHandling/ServerNotAvailable1291=== CONT TestResolveDBConnectionString1292=== RUN TestResolveDBConnectionString/flag_wins1293=== PAUSE TestResolveDBConnectionString/flag_wins1294=== RUN TestResolveDBConnectionString/file_when_flag_empty1295=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1296=== RUN TestResolveDBConnectionString/missing_file_is_an_error1297=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1298=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1299=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1300=== RUN TestResolveDBConnectionString/nothing_configured1301=== PAUSE TestResolveDBConnectionString/nothing_configured1302=== CONT TestRegisterCompletedObjectNeedsPendingRow13032026/10/27 08:39:46 WARN Force mode enabled - objects will be deleted immediately without grace period13042026/10/27 08:39:46 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013052026/10/27 08:39:46 INFO Vacuumed table table=pending_closures13062026/10/27 08:39:46 INFO Vacuumed table table=pending_objects13072026/10/27 08:39:46 INFO Vacuumed table table=multipart_uploads13082026/10/27 08:39:46 INFO Vacuumed table table=closures13092026/10/27 08:39:46 INFO Vacuumed table table=objects1310--- PASS: TestGCSweepSkipsPendingObjects (0.67s)1311=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1312--- PASS: TestMetricsInventory (0.64s)1313=== CONT TestSweepSkipsRowsLockedByPush13142026/10/27 08:39:46 INFO Received uploads request method=POST path=/api/pending_closures13152026/10/27 08:39:46 INFO Aborted multipart uploads count=0 kept=013162026/10/27 08:39:46 WARN Force mode enabled - objects will be deleted immediately without grace period13172026/10/27 08:39:46 WARN readiness check failed error="closed pool"1318--- PASS: TestService_readinessHandler (0.46s)1319=== CONT TestClientCADerivations13202026/10/27 08:39:46 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013212026/10/27 08:39:46 INFO Vacuumed table table=pending_closures13222026/10/27 08:39:46 INFO Vacuumed table table=pending_objects13232026/10/27 08:39:46 INFO Vacuumed table table=multipart_uploads13242026/10/27 08:39:46 INFO Vacuumed table table=closures1325=== NAME TestNARDeduplicationMetadataUploadBug1326 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug164975920/001/store/vgnkhpvm0z3xlh8kxlkhcjjq887fzsj9-file1.txt13272026/10/27 08:39:46 INFO Vacuumed table table=objects1328--- PASS: TestGCMetrics (0.53s)1329=== CONT TestPinProtectsFromGC13302026/10/27 08:39:46 INFO Aborted multipart uploads count=0 kept=013312026/10/27 08:39:46 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"1332--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.42s)1333=== CONT TestClientSharedPathCommittedMidPush13342026/10/27 08:39:46 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013352026/10/27 08:39:46 INFO Vacuumed table table=pending_closures13362026/10/27 08:39:46 INFO Vacuumed table table=pending_objects13372026/10/27 08:39:46 INFO Vacuumed table table=multipart_uploads13382026/10/27 08:39:46 INFO Vacuumed table table=closures13392026/10/27 08:39:46 INFO Vacuumed table table=objects1340--- PASS: TestService_healthCheckHandler (0.43s)1341=== CONT TestClientWithDependencies13422026/10/27 08:39:46 INFO Aborted multipart uploads count=0 kept=013432026/10/27 08:39:46 WARN Force mode enabled - objects will be deleted immediately without grace period13442026/10/27 08:39:46 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013452026/10/27 08:39:46 INFO Vacuumed table table=pending_closures13462026/10/27 08:39:46 INFO Vacuumed table table=pending_objects13472026/10/27 08:39:46 INFO Vacuumed table table=multipart_uploads13482026/10/27 08:39:46 INFO Vacuumed table table=closures13492026/10/27 08:39:46 INFO Vacuumed table table=objects1350--- PASS: TestPushDedupSurvivesConcurrentGC (0.67s)1351=== CONT TestDeleteClosuresRacingPins13522026/10/27 08:39:46 INFO Received push request method=POST path=/api/pushes13532026/10/27 08:39:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13542026/10/27 08:39:46 INFO Uploading vgnkhpvm0z3xlh8kxlkhcjjq887fzsj9-file1.txt (160B)13552026/10/27 08:39:46 INFO lead: acquired remote=192.0.2.1:123413562026/10/27 08:39:46 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"13572026/10/27 08:39:46 WARN Failed to register uploaded object key=vgnkhpvm0z3xlh8kxlkhcjjq887fzsj9.ls error="server returned 404: 404 page not found\n"13582026/10/27 08:39:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13592026/10/27 08:39:46 INFO Signed narinfos id=1 count=113602026/10/27 08:39:46 INFO Uploading 1 narinfos13612026/10/27 08:39:46 INFO Received complete push request method=POST path=/api/pushes/1/complete13622026/10/27 08:39:46 WARN Failed to register uploaded object key=vgnkhpvm0z3xlh8kxlkhcjjq887fzsj9.narinfo error="server returned 404: 404 page not found\n"13632026/10/27 08:39:46 INFO Completed push id=1 objects=3 duration=5.160051ms13642026/10/27 08:39:46 INFO Upload complete. (56ms)1365=== NAME TestNARDeduplicationMetadataUploadBug1366 metadata_upload_test.go:54: Retrieved narinfo from S3:1367 StorePath: /build/TestNARDeduplicationMetadataUploadBug164975920/001/store/vgnkhpvm0z3xlh8kxlkhcjjq887fzsj9-file1.txt1368 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1369 Compression: zstd1370 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1371 NarSize: 1601372 References: 1373 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1374 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1375 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1376 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}13772026/10/27 08:39:46 INFO lead: acquired remote=192.0.2.1:123413782026/10/27 08:39:46 INFO lead: released remote=192.0.2.1:12341379--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.37s)1380=== CONT TestClientMultipleUploads13812026/10/27 08:39:46 INFO Aborted multipart uploads count=0 kept=01382=== NAME TestNARDeduplicationMetadataUploadBug1383 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug164975920/001/store/lw27nizh6md0ickvw38amxfsjapy4g4x-file2.txt13842026/10/27 08:39:46 WARN Force mode enabled - objects will be deleted immediately without grace period13852026/10/27 08:39:46 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013862026/10/27 08:39:46 INFO Vacuumed table table=pending_closures13872026/10/27 08:39:46 INFO Vacuumed table table=pending_objects13882026/10/27 08:39:46 INFO Vacuumed table table=multipart_uploads13892026/10/27 08:39:46 INFO Vacuumed table table=closures13902026/10/27 08:39:46 INFO Vacuumed table table=objects13912026/10/27 08:39:46 INFO Received uploads request method=POST path=/api/pending_closures1392--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.44s)1393=== CONT TestClientFallsBackToClosures13942026/10/27 08:39:46 INFO Aborted multipart uploads count=0 kept=013952026/10/27 08:39:46 WARN Force mode enabled - objects will be deleted immediately without grace period13962026/10/27 08:39:46 INFO lead: acquired remote=192.0.2.1:123413972026/10/27 08:39:46 INFO Received push request method=POST path=/api/pushes13982026/10/27 08:39:46 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)13992026/10/27 08:39:46 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014002026/10/27 08:39:46 INFO Vacuumed table table=pending_closures14012026/10/27 08:39:46 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign14022026/10/27 08:39:46 INFO Vacuumed table table=pending_objects14032026/10/27 08:39:46 INFO Signed narinfos id=2 count=114042026/10/27 08:39:46 WARN Failed to register uploaded object key=lw27nizh6md0ickvw38amxfsjapy4g4x.ls error="server returned 404: 404 page not found\n"14052026/10/27 08:39:46 INFO Uploading 1 narinfos14062026/10/27 08:39:46 INFO Vacuumed table table=multipart_uploads14072026/10/27 08:39:46 INFO Received push request method=POST path=/api/pushes14082026/10/27 08:39:46 INFO Vacuumed table table=closures14092026/10/27 08:39:46 INFO Vacuumed table table=objects1410--- PASS: TestSweepRechecksPendingAfterLocking (0.42s)1411=== CONT TestCacheStatsHandler14122026/10/27 08:39:46 INFO Received complete push request method=POST path=/api/pushes/2/complete14132026/10/27 08:39:46 WARN Failed to register uploaded object key=lw27nizh6md0ickvw38amxfsjapy4g4x.narinfo error="server returned 404: 404 page not found\n"14142026/10/27 08:39:46 INFO Completed push id=2 objects=3 duration=2.052697ms14152026/10/27 08:39:46 INFO Upload complete. (47ms)1416=== NAME TestNARDeduplicationMetadataUploadBug1417 metadata_upload_test.go:76: Retrieved narinfo from S3:1418 StorePath: /build/TestNARDeduplicationMetadataUploadBug164975920/001/store/lw27nizh6md0ickvw38amxfsjapy4g4x-file2.txt1419 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1420 Compression: zstd1421 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1422 NarSize: 1601423 References: 1424 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1425 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1426 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1427 {"version":1,"root":{"type":"regular","size":44}}1428--- PASS: TestNARDeduplicationMetadataUploadBug (0.79s)1429=== CONT TestClientPushesUseOnePush1430--- PASS: TestGetExistingObjectsLocksRows (0.39s)1431=== CONT TestCacheConfigHandler1432=== RUN TestCacheConfigHandler/full_config,_no_issuer1433=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1434=== RUN TestCacheConfigHandler/no_cache_url_configured1435=== PAUSE TestCacheConfigHandler/no_cache_url_configured1436=== RUN TestCacheConfigHandler/no_signing_keys1437=== PAUSE TestCacheConfigHandler/no_signing_keys1438=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1439=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1440=== CONT TestService_AuthMiddleware_OIDC1441--- PASS: TestGCBugBareHashReferences (0.74s)1442=== CONT TestService_ReadAuthMiddleware1443--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.38s)1444=== CONT TestService_RequireScope_OIDC14452026/10/27 08:39:46 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45569/oidc1446=== NAME TestClientIntegration1447 client_integration_test.go:291: Created store path: /build/TestClientIntegration3870684232/002/store/ynfihz1m4k8gwdzx54fk9dzk8r61zk14-test-file.txt14482026/10/27 08:39:46 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37163/oidc14492026/10/27 08:39:46 INFO Aborted multipart uploads count=0 kept=014502026/10/27 08:39:46 WARN Force mode enabled - objects will be deleted immediately without grace period14512026/10/27 08:39:46 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014522026/10/27 08:39:46 INFO Vacuumed table table=pending_closures14532026/10/27 08:39:46 INFO Vacuumed table table=pending_objects14542026/10/27 08:39:46 INFO Vacuumed table table=multipart_uploads14552026/10/27 08:39:46 INFO Vacuumed table table=closures14562026/10/27 08:39:46 INFO Vacuumed table table=objects14572026/10/27 08:39:46 INFO Aborted multipart uploads count=0 kept=014582026/10/27 08:39:46 WARN Force mode enabled - objects will be deleted immediately without grace period14592026/10/27 08:39:46 INFO Received push request method=POST path=/api/pushes14602026/10/27 08:39:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14612026/10/27 08:39:46 INFO Uploading ynfihz1m4k8gwdzx54fk9dzk8r61zk14-test-file.txt (152B)14622026/10/27 08:39:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14632026/10/27 08:39:46 WARN Failed to register uploaded object key=ynfihz1m4k8gwdzx54fk9dzk8r61zk14.ls error="server returned 404: 404 page not found\n"14642026/10/27 08:39:46 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"14652026/10/27 08:39:46 INFO Signed narinfos id=1 count=114662026/10/27 08:39:46 INFO Uploading 1 narinfos14672026/10/27 08:39:46 INFO Received complete push request method=POST path=/api/pushes/1/complete14682026/10/27 08:39:46 WARN Failed to register uploaded object key=ynfihz1m4k8gwdzx54fk9dzk8r61zk14.narinfo error="server returned 404: 404 page not found\n"14692026/10/27 08:39:46 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=014702026/10/27 08:39:46 INFO Vacuumed table table=pending_closures14712026/10/27 08:39:46 INFO Vacuumed table table=pending_objects14722026/10/27 08:39:46 INFO Vacuumed table table=multipart_uploads14732026/10/27 08:39:46 INFO Vacuumed table table=closures14742026/10/27 08:39:46 INFO Vacuumed table table=objects14752026/10/27 08:39:46 INFO Completed push id=1 objects=3 duration=8.806672ms14762026/10/27 08:39:46 INFO Upload complete. (65ms)1477--- PASS: TestSweepSkipsRowsLockedByPush (0.47s)1478=== CONT TestService_ReadScope_PublicByDefault14792026/10/27 08:39:46 INFO All 1 paths already cached1480=== NAME TestClientIntegration1481 client_integration_test.go:317: Retrieved narinfo from S3:1482 StorePath: /build/TestClientIntegration3870684232/002/store/ynfihz1m4k8gwdzx54fk9dzk8r61zk14-test-file.txt1483 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1484 Compression: zstd1485 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11486 NarSize: 1521487 References: 1488 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11489 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1490 client_integration_test.go:318: Decompressed .ls content (64 bytes):1491 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1492=== NAME TestClientCADerivations1493 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations1254947065/001/store/pppw1k1kc37yl3a02a3qc944v7pircd6-ca-test1494=== NAME TestPinProtectsFromGC1495 client_integration_test.go:778: Pinned store path: /build/TestPinProtectsFromGC268857326/001/store/3hqw1dy0v9fg9lh9j3ypmfmmmvjr22gh-pinned-file.txt1496 client_integration_test.go:779: Unpinned store path: /build/TestPinProtectsFromGC268857326/001/store/p2q7zcsw6fry1r09zc4l3wmsgwf2rwyq-unpinned-file.txt1497=== NAME TestClientCADerivations1498 client_ca_test.go:139: Found 1 dependencies (including self)14992026/10/27 08:39:47 INFO Received push request method=POST path=/api/pushes1500=== NAME TestClientWithDependencies1501 client_integration_test.go:660: Built derivation: /build/TestClientWithDependencies2848500469/001/store/iklhi3z0f5b42jw51f2gaf5jiik0iw6g-test-script1502=== NAME TestClientMultipleUploads1503 client_integration_test.go:405: Created store path 0: /build/TestClientMultipleUploads3112144477/001/store/ankkxjiskn8w45hq3qjj2c9gy538mhbx-test-file-0.txt15042026/10/27 08:39:47 INFO Received push request method=POST path=/api/pushes1505--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.61s)1506=== CONT TestService_AuthMiddleware_MTLSBoundSubjects15072026-10-27 08:39:47.061 UTC [663] ERROR: Push does not exist: id=115082026-10-27 08:39:47.061 UTC [663] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE15092026-10-27 08:39:47.061 UTC [663] STATEMENT: SELECT commit_push($1)1510--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (0.73s)1511=== CONT TestService_AuthMiddleware_MTLSProxyHeader15122026/10/27 08:39:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15132026/10/27 08:39:47 INFO Uploading 3hqw1dy0v9fg9lh9j3ypmfmmmvjr22gh-pinned-file.txt (128B)15142026/10/27 08:39:47 INFO Object in database but missing from S3 key=ynfihz1m4k8gwdzx54fk9dzk8r61zk14.ls15152026/10/27 08:39:47 WARN Found objects in DB but missing from S3, will re-upload count=115162026/10/27 08:39:47 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)15172026/10/27 08:39:47 INFO Received complete push request method=POST path=/api/pushes/2/complete15182026/10/27 08:39:47 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"15192026/10/27 08:39:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15202026/10/27 08:39:47 WARN Failed to register uploaded object key=ynfihz1m4k8gwdzx54fk9dzk8r61zk14.ls error="server returned 404: 404 page not found\n"15212026/10/27 08:39:47 WARN Failed to register uploaded object key=3hqw1dy0v9fg9lh9j3ypmfmmmvjr22gh.ls error="server returned 404: 404 page not found\n"15222026/10/27 08:39:47 INFO Signed narinfos id=1 count=115232026/10/27 08:39:47 INFO Uploading 1 narinfos15242026/10/27 08:39:47 INFO Completed push id=2 objects=3 duration=2.620391ms15252026/10/27 08:39:47 INFO Upload complete. (59ms)1526=== NAME TestClientIntegration1527 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1528 client_integration_test.go:335: Decompressed .ls content (49 bytes):1529 {"version":1,"root":{"type":"regular","size":39}}15302026/10/27 08:39:47 INFO Received complete push request method=POST path=/api/pushes/1/complete15312026/10/27 08:39:47 WARN Failed to register uploaded object key=3hqw1dy0v9fg9lh9j3ypmfmmmvjr22gh.narinfo error="server returned 404: 404 page not found\n"15322026/10/27 08:39:47 INFO Received push request method=POST path=/api/pushes15332026/10/27 08:39:47 INFO Completed push id=1 objects=3 duration=6.529683ms15342026/10/27 08:39:47 INFO Upload complete. (74ms)1535=== NAME TestClientWithDependencies1536 client_integration_test.go:662: Found 1 dependencies (including self)15372026/10/27 08:39:47 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)15382026/10/27 08:39:47 INFO Uploading mxg5spfhh5206pgihhf8wzqgd1z7s93i-top (224B)15392026/10/27 08:39:47 INFO Uploading cm7ylblvs6z95wism3c4d0v877gia3y3-shared-dep (136B)1540--- PASS: TestCacheStatsHandler (0.35s)1541=== CONT TestProxyWriteTimeout/narinfo1542=== CONT TestProxyWriteTimeout/10_GiB_nar1543=== CONT TestProxyWriteTimeout/unknown_size1544=== CONT TestProxyWriteTimeout/1_GiB_nar1545--- PASS: TestProxyWriteTimeout (0.00s)1546 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1547 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1548 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1549 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1550=== CONT TestPendingClosureWriteTimeout/empty1551=== CONT TestPendingClosureWriteTimeout/670k_objects1552=== CONT TestPendingClosureWriteTimeout/400_objects1553=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1554=== NAME TestClientMultipleUploads1555 client_integration_test.go:405: Created store path 1: /build/TestClientMultipleUploads3112144477/001/store/z7bsfk16vplhlxaw8gfd702fdlwksbp1-test-file-1.txt15562026/10/27 08:39:47 WARN Failed to register uploaded object key=cm7ylblvs6z95wism3c4d0v877gia3y3.ls error="server returned 404: 404 page not found\n"15572026/10/27 08:39:47 WARN Failed to register uploaded object key=mxg5spfhh5206pgihhf8wzqgd1z7s93i.ls error="server returned 404: 404 page not found\n"15582026/10/27 08:39:47 WARN Failed to register uploaded object key=nar/1vncffasx4lnip1xkavs18izmd1k2g9d45qcdbhf0amipcgi9idg.nar.zst error="server returned 404: 404 page not found\n"15592026/10/27 08:39:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15602026/10/27 08:39:47 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15612026/10/27 08:39:47 INFO Signed narinfos id=1 count=215622026/10/27 08:39:47 INFO Uploading 2 narinfos15632026/10/27 08:39:47 WARN Failed to register uploaded object key=cm7ylblvs6z95wism3c4d0v877gia3y3.narinfo error="server returned 404: 404 page not found\n"15642026/10/27 08:39:47 INFO Received complete push request method=POST path=/api/pushes/1/complete15652026/10/27 08:39:47 WARN Failed to register uploaded object key=mxg5spfhh5206pgihhf8wzqgd1z7s93i.narinfo error="server returned 404: 404 page not found\n"15662026/10/27 08:39:47 INFO Received push request method=POST path=/api/pushes15672026/10/27 08:39:47 INFO Completed push id=1 objects=6 duration=8.028525ms15682026/10/27 08:39:47 INFO Upload complete. (82ms)1569=== NAME TestClientSharedPathCommittedMidPush1570 client_integration_test.go:727: Retrieved narinfo from S3:1571 StorePath: /build/TestClientSharedPathCommittedMidPush1152969901/001/store/cm7ylblvs6z95wism3c4d0v877gia3y3-shared-dep1572 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1573 Compression: zstd1574 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821575 NarSize: 1361576 References: 1577 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n15782026/10/27 08:39:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15792026/10/27 08:39:47 INFO Uploading pppw1k1kc37yl3a02a3qc944v7pircd6-ca-test (144B)1580 client_integration_test.go:727: Retrieved narinfo from S3:1581 StorePath: /build/TestClientSharedPathCommittedMidPush1152969901/001/store/mxg5spfhh5206pgihhf8wzqgd1z7s93i-top1582 URL: nar/1vncffasx4lnip1xkavs18izmd1k2g9d45qcdbhf0amipcgi9idg.nar.zst1583 Compression: zstd1584 NarHash: sha256:1vncffasx4lnip1xkavs18izmd1k2g9d45qcdbhf0amipcgi9idg1585 NarSize: 2241586 References: /build/TestClientSharedPathCommittedMidPush1152969901/001/store/cm7ylblvs6z95wism3c4d0v877gia3y3-shared-dep1587 CA: text:sha256:15k02zc5r2rwnqsyjism4cn3n7i7m7r51bv1ip3s0nz5kgzzv5af1588--- PASS: TestClientSharedPathCommittedMidPush (0.56s)1589=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15902026/10/27 08:39:47 INFO Received uploads request method=POST path=/1591=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15922026/10/27 08:39:47 INFO Received complete multipart upload request method=POST path=/1593=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15942026/10/27 08:39:47 INFO Received uploads request method=POST path=/1595=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15962026/10/27 08:39:47 INFO Received request for more parts method=POST path=/1597--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1598 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1599 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1600 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1601 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1602=== CONT TestIsValidUploadKey/narinfo1603=== CONT TestIsValidUploadKey/realisation_plus_in_output1604=== CONT TestIsValidUploadKey/unknown_type1605=== CONT TestIsValidUploadKey/empty_key1606=== CONT TestIsValidUploadKey/absolute1607=== CONT TestIsValidUploadKey/traversal_nar1608=== CONT TestIsValidUploadKey/traversal1609=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1610=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1611=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1612=== CONT TestIsValidUploadKey/index.html1613=== CONT TestIsValidUploadKey/nix-cache-info1614=== CONT TestIsValidUploadKey/build_log_home-manager_file1615=== CONT TestIsValidUploadKey/realisation1616=== CONT TestIsValidUploadKey/build_log_equals1617=== CONT TestIsValidUploadKey/build_log_question_mark1618=== CONT TestIsValidUploadKey/build_log_plus_in_name1619=== CONT TestIsValidUploadKey/nar_plain1620=== CONT TestIsValidUploadKey/build_log1621=== CONT TestIsValidUploadKey/listing16222026/10/27 08:39:47 WARN Failed to register uploaded object key=pppw1k1kc37yl3a02a3qc944v7pircd6.ls error="server returned 404: 404 page not found\n"1623=== CONT TestIsValidUploadKey/nar_xz1624=== CONT TestIsValidUploadKey/nar_zst1625--- PASS: TestIsValidUploadKey (0.00s)1626 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1627 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1628 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1629 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1630 --- PASS: TestIsValidUploadKey/absolute (0.00s)1631 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1632 --- PASS: TestIsValidUploadKey/traversal (0.00s)1633 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1634 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1635 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1636 --- PASS: TestIsValidUploadKey/index.html (0.00s)1637 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1638 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1639 --- PASS: TestIsValidUploadKey/realisation (0.00s)1640 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1641 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1642 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1643 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1644 --- PASS: TestIsValidUploadKey/build_log (0.00s)1645 --- PASS: TestIsValidUploadKey/listing (0.00s)1646 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1647 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1648=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16492026/10/27 08:39:47 INFO Received complete multipart upload request method=POST path=/16502026/10/27 08:39:47 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"16512026/10/27 08:39:47 WARN Failed to register uploaded object key=log/ys1zm711syxp81mvyg0d8pkgkvbdvm9x-ca-test.drv error="server returned 404: 404 page not found\n"16522026/10/27 08:39:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16532026/10/27 08:39:47 INFO Signed narinfos id=1 count=116542026/10/27 08:39:47 INFO Uploading 1 narinfos1655=== NAME TestClientMultipleUploads1656 client_integration_test.go:405: Created store path 2: /build/TestClientMultipleUploads3112144477/001/store/v48v6ccpwmg8s6rhr3ba6w87qd0bd0cm-test-file-2.txt16572026/10/27 08:39:47 INFO Received complete push request method=POST path=/api/pushes/1/complete16582026/10/27 08:39:47 WARN Failed to register uploaded object key=pppw1k1kc37yl3a02a3qc944v7pircd6.narinfo error="server returned 404: 404 page not found\n"16592026/10/27 08:39:47 INFO Completed push id=1 objects=4 duration=7.269139ms16602026/10/27 08:39:47 INFO Upload complete. (118ms)1661=== NAME TestClientCADerivations1662 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations1254947065/001/store/pppw1k1kc37yl3a02a3qc944v7pircd6-ca-test1663 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1664 Compression: zstd1665 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1666 NarSize: 1441667 References: 1668 Deriver: /build/TestClientCADerivations1254947065/001/store/ys1zm711syxp81mvyg0d8pkgkvbdvm9x-ca-test.drv1669 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1670 client_ca_test.go:185: Checking for realisation files in S3...1671 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1672 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1673--- PASS: TestService_ReadAuthMiddleware (0.39s)1674=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16752026/10/27 08:39:47 INFO Received uploads request method=POST path=/16762026/10/27 08:39:47 INFO Received push request method=POST path=/api/pushes16772026/10/27 08:39:47 INFO Received push request method=POST path=/api/pushes1678=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16792026/10/27 08:39:47 INFO Received request for more parts method=POST path=/16802026/10/27 08:39:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16812026/10/27 08:39:47 INFO Uploading p2q7zcsw6fry1r09zc4l3wmsgwf2rwyq-unpinned-file.txt (128B)16822026/10/27 08:39:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16832026/10/27 08:39:47 INFO Uploading iklhi3z0f5b42jw51f2gaf5jiik0iw6g-test-script (136B)1684--- PASS: TestPushWaitsForSweepHoldingRow (0.89s)1685=== CONT TestIsValidCachePath/narinfo1686=== CONT TestIsValidCachePath/index.html1687=== CONT TestIsValidCachePath/short_hash1688=== CONT TestIsValidCachePath/wrong_extension1689=== CONT TestIsValidCachePath/leading_slash1690=== CONT TestIsValidCachePath/empty1691=== CONT TestIsValidCachePath/random_path1692=== CONT TestIsValidCachePath/invalid_char_u1693=== CONT TestIsValidCachePath/invalid_char_e1694=== CONT TestIsValidCachePath/traversal_in_middle1695=== CONT TestIsValidCachePath/traversal_parent1696=== CONT TestIsValidCachePath/nar_uncompressed1697=== CONT TestIsValidCachePath/nix-cache-info1698=== CONT TestIsValidCachePath/realisation1699=== CONT TestIsValidCachePath/log1700=== CONT TestIsValidCachePath/ls1701=== CONT TestIsValidCachePath/nar_xz1702=== CONT TestIsValidCachePath/nar_bz21703=== CONT TestIsValidCachePath/nar_zst1704=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1705--- PASS: TestIsValidCachePath (0.00s)1706 --- PASS: TestIsValidCachePath/narinfo (0.00s)1707 --- PASS: TestIsValidCachePath/index.html (0.00s)1708 --- PASS: TestIsValidCachePath/short_hash (0.00s)1709 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1710 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1711 --- PASS: TestIsValidCachePath/empty (0.00s)1712 --- PASS: TestIsValidCachePath/random_path (0.00s)1713 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1714 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1715 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1716 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1717 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1718 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1719 --- PASS: TestIsValidCachePath/realisation (0.00s)1720 --- PASS: TestIsValidCachePath/log (0.00s)1721 --- PASS: TestIsValidCachePath/ls (0.00s)1722 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1723 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1724 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1725 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1726=== CONT TestParseSingleRange/none1727=== CONT TestParseSingleRange/open-ended1728=== CONT TestParseSingleRange/start_far_past_EOF1729=== CONT TestParseSingleRange/start_past_EOF1730=== CONT TestParseSingleRange/single_byte1731=== CONT TestParseSingleRange/suffix_exceeds_size1732=== CONT TestParseSingleRange/suffix1733=== CONT TestParseSingleRange/end_clamped_to_size1734=== CONT TestParseSingleRange/malformed_both_empty1735=== CONT TestParseSingleRange/closed1736=== CONT TestParseSingleRange/malformed_end_before_start1737=== CONT TestParseSingleRange/multi-range_ignored1738=== CONT TestParseSingleRange/malformed_no_dash1739=== CONT TestParseSingleRange/unknown_unit1740--- PASS: TestParseSingleRange (0.00s)1741 --- PASS: TestParseSingleRange/none (0.00s)1742 --- PASS: TestParseSingleRange/open-ended (0.00s)1743 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1744 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1745 --- PASS: TestParseSingleRange/single_byte (0.00s)1746 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1747 --- PASS: TestParseSingleRange/suffix (0.00s)1748 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1749 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1750 --- PASS: TestParseSingleRange/closed (0.00s)1751 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1752 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1753 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1754 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1755=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale17562026/10/27 08:39:47 WARN Failed to register uploaded object key=p2q7zcsw6fry1r09zc4l3wmsgwf2rwyq.ls error="server returned 404: 404 page not found\n"17572026/10/27 08:39:47 WARN Failed to register uploaded object key=iklhi3z0f5b42jw51f2gaf5jiik0iw6g.ls error="server returned 404: 404 page not found\n"17582026/10/27 08:39:47 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"17592026/10/27 08:39:47 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17602026/10/27 08:39:47 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"17612026/10/27 08:39:47 INFO Signed narinfos id=2 count=117622026/10/27 08:39:47 INFO Uploading 1 narinfos17632026/10/27 08:39:47 INFO Received push request method=POST path=/api/pushes17642026/10/27 08:39:47 WARN Failed to register uploaded object key=log/jdrl7i5cwnzc33nhj0vjr096fsxl0al8-test-script.drv error="server returned 404: 404 page not found\n"17652026/10/27 08:39:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17662026/10/27 08:39:47 INFO Signed narinfos id=1 count=117672026/10/27 08:39:47 INFO Uploading 1 narinfos17682026/10/27 08:39:47 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17692026/10/27 08:39:47 INFO Received complete push request method=POST path=/api/pushes/2/complete17702026/10/27 08:39:47 WARN Failed to register uploaded object key=p2q7zcsw6fry1r09zc4l3wmsgwf2rwyq.narinfo error="server returned 404: 404 page not found\n"17712026/10/27 08:39:47 INFO Completed push id=2 objects=3 duration=1.705284ms17722026/10/27 08:39:47 INFO Upload complete. (74ms)17732026/10/27 08:39:47 INFO Received complete push request method=POST path=/api/pushes/1/complete17742026/10/27 08:39:47 WARN Failed to register uploaded object key=iklhi3z0f5b42jw51f2gaf5jiik0iw6g.narinfo error="server returned 404: 404 page not found\n"17752026/10/27 08:39:47 INFO Received complete push request method=POST path=/api/pushes/3/complete1776=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1777=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1778=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1779=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1780=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1781=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1782=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1783=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1784=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh17852026/10/27 08:39:47 WARN Failed to register uploaded object key=ynfihz1m4k8gwdzx54fk9dzk8r61zk14.ls error="server returned 404: 404 page not found\n"17862026/10/27 08:39:47 INFO Completed push id=1 objects=4 duration=9.495887ms17872026/10/27 08:39:47 INFO Upload complete. (92ms)17882026/10/27 08:39:47 INFO Completed push id=3 objects=3 duration=4.528867ms17892026/10/27 08:39:47 INFO Upload complete. (71ms)1790=== NAME TestClientIntegration1791 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1792 client_integration_test.go:352: Decompressed .ls content (49 bytes):1793 {"version":1,"root":{"type":"regular","size":39}}1794=== NAME TestClientWithDependencies1795 client_integration_test.go:664: Skipping nix copy test - isolated store (/build/TestClientWithDependencies2848500469/001/store) requires matching store prefix17962026/10/27 08:39:47 INFO Received push request method=POST path=/api/pushes1797=== NAME TestClientIntegration1798 client_integration_test.go:363: Testing garbage collection...1799--- PASS: TestClientWithDependencies (0.64s)1800=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1801=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check18022026/10/27 08:39:47 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)18032026/10/27 08:39:47 INFO Uploading v48v6ccpwmg8s6rhr3ba6w87qd0bd0cm-test-file-2.txt (160B)18042026/10/27 08:39:47 INFO Uploading z7bsfk16vplhlxaw8gfd702fdlwksbp1-test-file-1.txt (160B)18052026/10/27 08:39:47 INFO Uploading ankkxjiskn8w45hq3qjj2c9gy538mhbx-test-file-0.txt (160B)18062026/10/27 08:39:47 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"18072026/10/27 08:39:47 WARN Failed to register uploaded object key=ankkxjiskn8w45hq3qjj2c9gy538mhbx.ls error="server returned 404: 404 page not found\n"18082026/10/27 08:39:47 WARN Failed to register uploaded object key=v48v6ccpwmg8s6rhr3ba6w87qd0bd0cm.ls error="server returned 404: 404 page not found\n"18092026/10/27 08:39:47 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"18102026/10/27 08:39:47 WARN Failed to register uploaded object key=z7bsfk16vplhlxaw8gfd702fdlwksbp1.ls error="server returned 404: 404 page not found\n"18112026/10/27 08:39:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18122026/10/27 08:39:47 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"18132026/10/27 08:39:47 INFO Signed narinfos id=1 count=318142026/10/27 08:39:47 INFO Uploading 3 narinfos18152026/10/27 08:39:47 WARN Failed to register uploaded object key=v48v6ccpwmg8s6rhr3ba6w87qd0bd0cm.narinfo error="server returned 404: 404 page not found\n"18162026/10/27 08:39:47 WARN Failed to register uploaded object key=ankkxjiskn8w45hq3qjj2c9gy538mhbx.narinfo error="server returned 404: 404 page not found\n"18172026/10/27 08:39:47 INFO Received complete push request method=POST path=/api/pushes/1/complete18182026/10/27 08:39:47 WARN Failed to register uploaded object key=z7bsfk16vplhlxaw8gfd702fdlwksbp1.narinfo error="server returned 404: 404 page not found\n"18192026/10/27 08:39:47 INFO Starting cleanup of old closures method=DELETE path=/api/closures18202026/10/27 08:39:47 INFO Garbage collection started18212026/10/27 08:39:47 INFO Completed push id=1 objects=9 duration=11.573354ms18222026/10/27 08:39:47 INFO Upload complete. (95ms)1823=== NAME TestClientMultipleUploads1824 client_integration_test.go:416: Uploaded 3 paths in 133.372175ms18252026/10/27 08:39:47 INFO Aborted multipart uploads count=0 kept=018262026/10/27 08:39:47 INFO Starting cleanup of old closures method=DELETE path=/api/closures18272026/10/27 08:39:47 INFO Garbage collection started18282026/10/27 08:39:47 INFO Received uploads request method=POST path=/api/pending_closures1829=== NAME TestClientCADerivations1830 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1831 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1832 error: binary cache 's3://bucket76?endpoint=http://localhost:35005®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations1254947065/001/store'1833 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11834--- PASS: TestClientCADerivations (0.76s)1835=== CONT TestServerTLSConfig/no_client_CA1836=== CONT TestServerTLSConfig/not_a_PEM_file18372026/10/27 08:39:47 WARN Force mode enabled - objects will be deleted immediately without grace period18382026/10/27 08:39:47 INFO Received uploads request method=POST path=/api/pending_closures1839=== CONT TestServerTLSConfig/missing_CA_file1840--- PASS: TestServerTLSConfig (0.00s)1841 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1842 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1843 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1844=== CONT TestGCEndsOnShutdown/before_the_run1845=== RUN TestService_RequireScope_OIDC/builder_may_write1846=== PAUSE TestService_RequireScope_OIDC/builder_may_write1847=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1848=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1849=== RUN TestService_RequireScope_OIDC/ops_may_admin1850=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1851=== RUN TestService_RequireScope_OIDC/ops_may_not_write1852=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1853=== RUN TestService_RequireScope_OIDC/reader_may_not_write1854=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1855=== RUN TestService_RequireScope_OIDC/static_token_may_admin1856=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1857=== RUN TestService_RequireScope_OIDC/static_token_may_write1858=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1859=== RUN TestService_RequireScope_OIDC/reader_may_read1860=== PAUSE TestService_RequireScope_OIDC/reader_may_read1861=== RUN TestService_RequireScope_OIDC/writer_implies_read1862=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1863=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1864=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1865=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1866=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1867=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1868=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1869=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1870=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1871=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1872=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1873=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1874--- PASS: TestClientMultipleUploads (0.64s)1875=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete18762026/10/27 08:39:47 INFO Aborted multipart uploads count=0 kept=018772026/10/27 08:39:47 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)18782026/10/27 08:39:47 INFO Uploading kwmp4z2sk8xsjr2fwdypnf63a1bn193n-a (216B)18792026/10/27 08:39:47 INFO Uploading 5ls8kn3v2nl82w1crw5hl93dimn1z8hm-shared-dep (136B)18802026/10/27 08:39:47 WARN Failed to register uploaded object key=kwmp4z2sk8xsjr2fwdypnf63a1bn193n.ls error="server returned 404: 404 page not found\n"18812026/10/27 08:39:47 WARN Failed to register uploaded object key=jy9xsdas7x8w38clwhl7pk4nxj734bck.ls error="server returned 404: 404 page not found\n"18822026/10/27 08:39:47 WARN Failed to register uploaded object key=5ls8kn3v2nl82w1crw5hl93dimn1z8hm.ls error="server returned 404: 404 page not found\n"18832026/10/27 08:39:47 WARN Failed to register uploaded object key=nar/1alqmcdjfgwrq06pbzsgi6fdi7016hwmqkg8f3jwbw6453krms4d.nar.zst error="server returned 404: 404 page not found\n"18842026/10/27 08:39:47 WARN Force mode enabled - objects will be deleted immediately without grace period18852026/10/27 08:39:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18862026/10/27 08:39:47 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18872026/10/27 08:39:47 INFO Signed narinfos id=1 count=218882026/10/27 08:39:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign18892026/10/27 08:39:47 INFO Signed narinfos id=2 count=218902026/10/27 08:39:47 INFO Uploading 4 narinfos18912026/10/27 08:39:47 WARN Failed to register uploaded object key=jy9xsdas7x8w38clwhl7pk4nxj734bck.narinfo error="server returned 404: 404 page not found\n"18922026/10/27 08:39:47 WARN Failed to register uploaded object key=kwmp4z2sk8xsjr2fwdypnf63a1bn193n.narinfo error="server returned 404: 404 page not found\n"18932026/10/27 08:39:47 WARN Failed to register uploaded object key=5ls8kn3v2nl82w1crw5hl93dimn1z8hm.narinfo error="server returned 404: 404 page not found\n"18942026/10/27 08:39:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18952026/10/27 08:39:47 WARN Failed to register uploaded object key=5ls8kn3v2nl82w1crw5hl93dimn1z8hm.narinfo error="server returned 404: 404 page not found\n"1896--- PASS: TestService_ReadScope_PublicByDefault (0.40s)1897=== CONT TestPush_RejectsBadRequests/no_roots18982026/10/27 08:39:47 INFO Received push request method=POST path=/api/pushes1899=== CONT TestPush_RejectsBadRequests/bad_root19002026/10/27 08:39:47 INFO Received push request method=POST path=/api/pushes1901=== CONT TestPush_RejectsBadRequests/root_not_in_objects19022026/10/27 08:39:47 INFO Received push request method=POST path=/api/pushes1903=== CONT TestPush_RejectsBadRequests/no_objects19042026/10/27 08:39:47 INFO Received push request method=POST path=/api/pushes1905--- PASS: TestPush_RejectsBadRequests (0.61s)1906 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1907 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1908 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1909 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1910=== CONT TestClientErrorHandling/InvalidStorePath19112026/10/27 08:39:47 INFO Completed upload id=1 objects=6 duration=12.160079ms19122026/10/27 08:39:47 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete19132026/10/27 08:39:47 INFO Completed upload id=2 objects=6 duration=3.149055ms19142026/10/27 08:39:47 INFO Upload complete. (106ms)1915=== NAME TestClientFallsBackToClosures1916 client_pushes_test.go:112: Retrieved narinfo from S3:1917 StorePath: /build/TestClientFallsBackToClosures4008115076/001/store/5ls8kn3v2nl82w1crw5hl93dimn1z8hm-shared-dep1918 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1919 Compression: zstd1920 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821921 NarSize: 1361922 References: 1923 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1924 client_pushes_test.go:112: Retrieved narinfo from S3:1925 StorePath: /build/TestClientFallsBackToClosures4008115076/001/store/kwmp4z2sk8xsjr2fwdypnf63a1bn193n-a1926 URL: nar/1alqmcdjfgwrq06pbzsgi6fdi7016hwmqkg8f3jwbw6453krms4d.nar.zst1927 Compression: zstd1928 NarHash: sha256:1alqmcdjfgwrq06pbzsgi6fdi7016hwmqkg8f3jwbw6453krms4d1929 NarSize: 2161930 References: /build/TestClientFallsBackToClosures4008115076/001/store/5ls8kn3v2nl82w1crw5hl93dimn1z8hm-shared-dep1931 CA: text:sha256:0ggxpjkrzbzglr06y5prd2s0ij7ih2mncpnkqv72cjj3hrfm80cn1932 client_pushes_test.go:112: Retrieved narinfo from S3:1933 StorePath: /build/TestClientFallsBackToClosures4008115076/001/store/jy9xsdas7x8w38clwhl7pk4nxj734bck-b1934 URL: nar/1alqmcdjfgwrq06pbzsgi6fdi7016hwmqkg8f3jwbw6453krms4d.nar.zst1935 Compression: zstd1936 NarHash: sha256:1alqmcdjfgwrq06pbzsgi6fdi7016hwmqkg8f3jwbw6453krms4d1937 NarSize: 2161938 References: /build/TestClientFallsBackToClosures4008115076/001/store/5ls8kn3v2nl82w1crw5hl93dimn1z8hm-shared-dep1939 CA: text:sha256:0ggxpjkrzbzglr06y5prd2s0ij7ih2mncpnkqv72cjj3hrfm80cn1940--- PASS: TestClientFallsBackToClosures (0.66s)1941=== CONT TestClientErrorHandling/ServerNotAvailable19422026/10/27 08:39:47 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=019432026/10/27 08:39:47 INFO Vacuumed table table=pending_closures1944--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.30s)1945=== CONT TestClientErrorHandling/InvalidAuthToken19462026/10/27 08:39:47 INFO Vacuumed table table=pending_objects19472026/10/27 08:39:47 INFO Vacuumed table table=multipart_uploads19482026/10/27 08:39:47 INFO Received push request method=POST path=/api/pushes19492026/10/27 08:39:47 INFO Vacuumed table table=closures19502026/10/27 08:39:47 INFO Vacuumed table table=objects19512026/10/27 08:39:47 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)19522026/10/27 08:39:47 INFO Uploading y8hx9kxsy4y00rwqnrg9xhhjah7nhrwi-b (216B)19532026/10/27 08:39:47 INFO Uploading shclf2lmjdr776dxx4x7xlkmcbgvb5xh-shared-dep (136B)19542026/10/27 08:39:47 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=019552026/10/27 08:39:47 INFO Vacuumed table table=pending_closures19562026/10/27 08:39:47 WARN Failed to register uploaded object key=blwhb32y7gcczdn39lzb79k8kljjzqhn.ls error="server returned 404: 404 page not found\n"19572026/10/27 08:39:47 WARN Failed to register uploaded object key=nar/1jr6x69d4230sdmg9ncgxrj1sxnmfyxap4fhhb40zi5a8pb489zk.nar.zst error="server returned 404: 404 page not found\n"19582026/10/27 08:39:47 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"19592026/10/27 08:39:47 WARN Failed to register uploaded object key=shclf2lmjdr776dxx4x7xlkmcbgvb5xh.ls error="server returned 404: 404 page not found\n"19602026/10/27 08:39:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19612026/10/27 08:39:47 WARN Failed to register uploaded object key=y8hx9kxsy4y00rwqnrg9xhhjah7nhrwi.ls error="server returned 404: 404 page not found\n"19622026/10/27 08:39:47 INFO Signed narinfos id=1 count=319632026/10/27 08:39:47 INFO Uploading 3 narinfos19642026/10/27 08:39:47 INFO Vacuumed table table=pending_objects19652026/10/27 08:39:47 WARN Failed to register uploaded object key=shclf2lmjdr776dxx4x7xlkmcbgvb5xh.narinfo error="server returned 404: 404 page not found\n"19662026/10/27 08:39:47 WARN Failed to register uploaded object key=blwhb32y7gcczdn39lzb79k8kljjzqhn.narinfo error="server returned 404: 404 page not found\n"19672026/10/27 08:39:47 INFO Received complete push request method=POST path=/api/pushes/1/complete19682026/10/27 08:39:47 WARN Failed to register uploaded object key=y8hx9kxsy4y00rwqnrg9xhhjah7nhrwi.narinfo error="server returned 404: 404 page not found\n"19692026/10/27 08:39:47 INFO Vacuumed table table=multipart_uploads19702026/10/27 08:39:47 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19712026/10/27 08:39:47 WARN mTLS auth: bound subjects configured but subject DN unavailable19722026/10/27 08:39:47 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1973--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.41s)1974=== CONT TestResolveDBConnectionString/flag_wins1975=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1976=== CONT TestResolveDBConnectionString/nothing_configured1977=== CONT TestResolveDBConnectionString/missing_file_is_an_error1978=== CONT TestResolveDBConnectionString/file_when_flag_empty1979=== CONT TestCacheConfigHandler/full_config,_no_issuer1980=== CONT TestCacheConfigHandler/no_signing_keys1981=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1982=== CONT TestCacheConfigHandler/no_cache_url_configured1983--- PASS: TestCacheConfigHandler (0.00s)1984 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1985 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1986 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1987 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1988--- PASS: TestResolveDBConnectionString (0.00s)1989 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1990 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1991 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1992 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1993 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1994=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1995=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19962026/10/27 08:39:47 INFO Vacuumed table table=closures19972026/10/27 08:39:47 WARN Authentication failed token_preview=not-a-valid-jwt token_length=15 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]1998=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1999=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20002026/10/27 08:39:47 WARN Authentication failed token_preview=eyJhbGciOi...hbSsZTzOOw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2001=== CONT TestService_RequireScope_OIDC/builder_may_write2002--- PASS: TestService_AuthMiddleware_OIDC (0.45s)2003 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.02s)2004 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2005 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2006 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2007=== CONT TestService_RequireScope_OIDC/reader_may_read2008=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2009=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20102026/10/27 08:39:47 WARN Authentication failed token_preview=wrong token_length=5 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]2011=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2012=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2013=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2014=== CONT TestService_RequireScope_OIDC/writer_implies_read2015=== CONT TestService_RequireScope_OIDC/reader_may_not_write2016=== CONT TestService_RequireScope_OIDC/static_token_may_write2017=== CONT TestService_RequireScope_OIDC/static_token_may_admin2018=== CONT TestService_RequireScope_OIDC/ops_may_admin2019=== CONT TestService_RequireScope_OIDC/ops_may_not_write2020=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2021--- PASS: TestService_RequireScope_OIDC (0.49s)2022 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2023 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2024 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2025 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2026 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2027 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2028 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2029 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2030 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2031 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2032 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2033 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2034 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2035 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)20362026/10/27 08:39:47 INFO Completed push id=1 objects=8 duration=62.389287ms20372026/10/27 08:39:47 INFO Upload complete. (196ms)20382026/10/27 08:39:47 INFO Vacuumed table table=objects20392026/10/27 08:39:47 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2040=== NAME TestClientPushesUseOnePush2041 client_pushes_test.go:97: Retrieved narinfo from S3:2042 StorePath: /build/TestClientPushesUseOnePush1776423535/001/store/shclf2lmjdr776dxx4x7xlkmcbgvb5xh-shared-dep2043 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2044 Compression: zstd2045 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822046 NarSize: 1362047 References: 2048 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2049 client_pushes_test.go:97: Retrieved narinfo from S3:2050 StorePath: /build/TestClientPushesUseOnePush1776423535/001/store/blwhb32y7gcczdn39lzb79k8kljjzqhn-a2051 URL: nar/1jr6x69d4230sdmg9ncgxrj1sxnmfyxap4fhhb40zi5a8pb489zk.nar.zst2052 Compression: zstd2053 NarHash: sha256:1jr6x69d4230sdmg9ncgxrj1sxnmfyxap4fhhb40zi5a8pb489zk2054 NarSize: 2162055 References: /build/TestClientPushesUseOnePush1776423535/001/store/shclf2lmjdr776dxx4x7xlkmcbgvb5xh-shared-dep2056 CA: text:sha256:12xmyvab6pwbaxgi5wm96lqqfkma0r5rcqajwn1v2b9c7ysx72q52057 client_pushes_test.go:97: Retrieved narinfo from S3:2058 StorePath: /build/TestClientPushesUseOnePush1776423535/001/store/y8hx9kxsy4y00rwqnrg9xhhjah7nhrwi-b2059 URL: nar/1jr6x69d4230sdmg9ncgxrj1sxnmfyxap4fhhb40zi5a8pb489zk.nar.zst2060 Compression: zstd2061 NarHash: sha256:1jr6x69d4230sdmg9ncgxrj1sxnmfyxap4fhhb40zi5a8pb489zk2062 NarSize: 2162063 References: /build/TestClientPushesUseOnePush1776423535/001/store/shclf2lmjdr776dxx4x7xlkmcbgvb5xh-shared-dep2064 CA: text:sha256:12xmyvab6pwbaxgi5wm96lqqfkma0r5rcqajwn1v2b9c7ysx72q52065--- PASS: TestClientPushesUseOnePush (0.79s)20662026/10/27 08:39:47 INFO Received uploads request method=POST path=/api/pending_closures20672026/10/27 08:39:47 WARN Request failed, retrying attempt=2 backoff=213.886075ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20682026/10/27 08:39:47 INFO Received uploads request method=POST path=/api/pending_closures20692026/10/27 08:39:47 INFO Aborted multipart uploads count=0 kept=020702026/10/27 08:39:47 WARN Force mode enabled - objects will be deleted immediately without grace period20712026/10/27 08:39:47 INFO lead: released remote=192.0.2.1:12342072--- PASS: TestLeadEndsOnShutdown (1.44s)20732026/10/27 08:39:47 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=020742026/10/27 08:39:47 INFO Vacuumed table table=pending_closures20752026/10/27 08:39:47 INFO Vacuumed table table=pending_objects20762026/10/27 08:39:47 INFO Vacuumed table table=multipart_uploads20772026/10/27 08:39:47 INFO Vacuumed table table=closures20782026/10/27 08:39:47 INFO Vacuumed table table=objects20792026/10/27 08:39:47 INFO Received uploads request method=POST path=/api/pending_closures20802026/10/27 08:39:47 INFO Aborted multipart uploads count=0 kept=020812026/10/27 08:39:47 WARN Force mode enabled - objects will be deleted immediately without grace period20822026/10/27 08:39:47 INFO Aborted multipart uploads count=0 kept=020832026/10/27 08:39:47 WARN Force mode enabled - objects will be deleted immediately without grace period20842026/10/27 08:39:47 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=020852026/10/27 08:39:47 INFO Vacuumed table table=pending_closures20862026/10/27 08:39:47 INFO Vacuumed table table=pending_objects20872026/10/27 08:39:47 INFO Vacuumed table table=multipart_uploads20882026/10/27 08:39:47 INFO Vacuumed table table=closures20892026/10/27 08:39:47 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:35005/bucket96/?delete=\": context canceled"20902026/10/27 08:39:47 INFO Vacuumed table table=objects2091--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2092 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.45s)2093 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.50s)20942026/10/27 08:39:47 INFO Aborted multipart uploads count=0 kept=020952026/10/27 08:39:47 WARN Force mode enabled - objects will be deleted immediately without grace period20962026-10-27 08:39:47.762 UTC [1622] ERROR: canceling statement due to user request20972026-10-27 08:39:47.762 UTC [1622] CONTEXT: PL/pgSQL expression "NULL"2098 PL/pgSQL function object_stats_update() line 16 at RETURN20992026-10-27 08:39:47.762 UTC [1622] STATEMENT: -- name: MarkStaleObjects :execrows2100 WITH RECURSIVE ct AS (2101 SELECT timezone('UTC', now()) AS now2102 ),2103 closure_reach AS (2104 -- Start with all closure keys2105 SELECT o.key, o.refs2106 FROM objects o2107 INNER JOIN closures c ON o.key = c.key2108 UNION2109 -- Recursively add all referenced objects2110 SELECT o.key, o.refs2111 FROM objects o2112 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2113 ),2114 reachable_objects AS (2115 SELECT DISTINCT key FROM closure_reach2116 ),2117 stale_objects AS (2118 SELECT o.key2119 FROM objects AS o, ct2120 WHERE2121 NOT EXISTS (2122 SELECT 12123 FROM reachable_objects ro2124 WHERE ro.key = o.key2125 )2126 AND NOT EXISTS (2127 SELECT 12128 FROM pending_objects AS po2129 WHERE po.key = o.key2130 )2131 AND o.deleted_at IS NULL -- Only mark fresh objects2132 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2133 FOR UPDATE2134 )2135 UPDATE objects2136 SET2137 deleted_at = ct.now,2138 first_deleted_at = COALESCE(first_deleted_at, ct.now)2139 FROM stale_objects, ct2140 WHERE objects.key = stale_objects.key2141 2142--- PASS: TestGCEndsOnShutdown (0.00s)2143 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.43s)2144 --- PASS: TestGCEndsOnShutdown/before_the_run (0.44s)2145 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.48s)2146--- PASS: TestUploadHandlersRejectOversizedBody (0.16s)2147 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.05s)2148 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.06s)2149 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.73s)21502026/10/27 08:39:47 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21512026/10/27 08:39:47 WARN Request failed, retrying attempt=3 backoff=408.87689ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21522026/10/27 08:39:47 INFO lead: released remote=192.0.2.1:123421532026/10/27 08:39:47 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2154=== NAME TestOrphanedObjectsGCStressTest2155 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2156 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion21572026/10/27 08:39:47 INFO lead: acquired remote=192.0.2.1:123421582026/10/27 08:39:48 WARN Rate limiter enabled after throttle name=s3-test rate=521592026/10/27 08:39:48 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2160=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2161 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102162 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002163--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (3.54s)2164--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2165 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.94s)2166 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.95s)2167--- PASS: TestDeleteClosuresRacingPins (1.66s)21682026/10/27 08:39:48 WARN Request failed, retrying attempt=4 backoff=821.52725ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2169--- PASS: TestPendingClosureWriteTimeout (0.00s)2170 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2171 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2172 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2173 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.28s)2174=== NAME TestOrphanedObjectsGCStressTest2175 orphaned_objects_gc_test.go:503: Stress test completed successfully:2176 orphaned_objects_gc_test.go:504: - Active objects preserved: 202177 orphaned_objects_gc_test.go:505: - Objects deleted: 2102178 orphaned_objects_gc_test.go:506: - Total GC'd: 2102179--- PASS: TestOrphanedObjectsGCStressTest (3.28s)21802026/10/27 08:39:49 INFO lead: released remote=192.0.2.1:12342181--- PASS: TestLeadElectsOneAndHandsOver (2.69s)21822026/10/27 08:39:49 WARN Request failed, retrying attempt=5 backoff=1.6240877s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21832026/10/27 08:39:49 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=021842026/10/27 08:39:49 INFO Received create pin request method=POST path=/api/pins/myapp21852026/10/27 08:39:49 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC268857326/001/store/3hqw1dy0v9fg9lh9j3ypmfmmmvjr22gh-pinned-file.txt narinfo_key=3hqw1dy0v9fg9lh9j3ypmfmmmvjr22gh.narinfo21862026/10/27 08:39:49 INFO Starting cleanup of old closures method=DELETE path=/api/closures21872026/10/27 08:39:49 INFO Garbage collection started21882026/10/27 08:39:49 INFO Aborted multipart uploads count=0 kept=021892026/10/27 08:39:49 WARN Force mode enabled - objects will be deleted immediately without grace period21902026/10/27 08:39:49 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=021912026/10/27 08:39:49 INFO Vacuumed table table=pending_closures21922026/10/27 08:39:49 INFO Vacuumed table table=pending_objects21932026/10/27 08:39:49 INFO Vacuumed table table=multipart_uploads21942026/10/27 08:39:49 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=021952026/10/27 08:39:49 INFO Vacuumed table table=closures2196=== NAME TestClientIntegration2197 client_integration_test.go:370: Objects in database after GC:2198 client_integration_test.go:370: Successfully deleted all objects with GC --force21992026/10/27 08:39:49 INFO Vacuumed table table=objects2200--- PASS: TestClientIntegration (2.89s)2201--- PASS: TestReadProxyOutlastsServerWriteTimeout (5.24s)22022026/10/27 08:39:50 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22032026/10/27 08:39:50 WARN Request failed, retrying attempt=2 backoff=189.655713ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22042026/10/27 08:39:51 WARN Request failed, retrying attempt=3 backoff=363.149125ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2205=== NAME TestPinProtectsFromGC2206 client_integration_test.go:887: Pin successfully protected closure from garbage collection2207--- PASS: TestPinProtectsFromGC (4.74s)22082026/10/27 08:39:51 WARN Request failed, retrying attempt=4 backoff=853.220758ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2209--- PASS: TestConnectWaitsForAPeerMigration (5.12s)22102026/10/27 08:39:52 INFO Aborted multipart uploads count=1 kept=022112026/10/27 08:39:52 INFO Received cleanup request method=DELETE path=/api/pending_closures22122026/10/27 08:39:52 INFO Aborted multipart uploads count=1 kept=02213--- PASS: TestPendingCleanupUsesOneCutoff (6.68s)22142026/10/27 08:39:52 WARN Request failed, retrying attempt=5 backoff=1.546212846s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22152026/10/27 08:39:53 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"22162026/10/27 08:39:53 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-config22172026/10/27 08:39:53 WARN Request failed, retrying attempt=2 backoff=214.513323ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22182026/10/27 08:39:54 WARN Request failed, retrying attempt=3 backoff=365.464133ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22192026/10/27 08:39:54 WARN Request failed, retrying attempt=4 backoff=810.251555ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22202026/10/27 08:39:55 WARN Request failed, retrying attempt=5 backoff=1.669933691s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22212026/10/27 08:39:57 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22222026/10/27 08:39:57 WARN Request failed, retrying attempt=2 backoff=183.889905ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22232026/10/27 08:39:57 WARN Request failed, retrying attempt=3 backoff=388.538329ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22242026/10/27 08:39:57 WARN Request failed, retrying attempt=4 backoff=865.362092ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22252026/10/27 08:39:58 WARN Request failed, retrying attempt=5 backoff=1.737301413s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2226--- PASS: TestClientErrorHandling (0.00s)2227 --- PASS: TestClientErrorHandling/InvalidStorePath (0.46s)2228 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.56s)2229 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.94s)2230PASS22312026-10-27 08:40:00.413 UTC [128] LOG: received smart shutdown request22322026-10-27 08:40:00.418 UTC [128] LOG: background worker "logical replication launcher" (PID 138) exited with exit code 122332026-10-27 08:40:00.425 UTC [133] LOG: shutting down22342026-10-27 08:40:00.426 UTC [133] LOG: checkpoint starting: shutdown immediate22352026-10-27 08:40:01.528 UTC [133] LOG: checkpoint complete: wrote 10714 buffers (65.4%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 30 recycled; write=0.172 s, sync=0.886 s, total=1.103 s; sync files=34045, longest=0.004 s, average=0.001 s; distance=493999 kB, estimate=493999 kB; lsn=0/1F9D19B0, redo lsn=0/1F9D19B022362026-10-27 08:40:01.579 UTC [128] LOG: database system is shut down2237Running OIDC tests...2238=== RUN TestAudienceForIssuer2239=== PAUSE TestAudienceForIssuer2240=== RUN TestGlobMatch2241=== PAUSE TestGlobMatch2242=== RUN TestValidateToken_ValidToken2243=== PAUSE TestValidateToken_ValidToken2244=== RUN TestValidateToken_WrongAudience2245=== PAUSE TestValidateToken_WrongAudience2246=== RUN TestValidateToken_Expired2247=== PAUSE TestValidateToken_Expired2248=== RUN TestValidateToken_BoundClaimsMismatch2249=== PAUSE TestValidateToken_BoundClaimsMismatch2250=== RUN TestValidateToken_BoundSubjectMismatch2251=== PAUSE TestValidateToken_BoundSubjectMismatch2252=== RUN TestValidateToken_MultipleProviders2253=== PAUSE TestValidateToken_MultipleProviders2254=== RUN TestValidateToken_NoMatchingProvider2255=== PAUSE TestValidateToken_NoMatchingProvider2256=== RUN TestValidateToken_KubernetesServiceAccount2257=== PAUSE TestValidateToken_KubernetesServiceAccount2258=== RUN TestNewValidator_KubernetesRequiresCA2259=== PAUSE TestNewValidator_KubernetesRequiresCA2260=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2261=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2262=== RUN TestPins_ReservedForMatchingRule2263=== PAUSE TestPins_ReservedForMatchingRule2264=== RUN TestPins_TopLevelShorthand2265=== PAUSE TestPins_TopLevelShorthand2266=== RUN TestPins_ConfigValidation2267=== PAUSE TestPins_ConfigValidation2268=== RUN TestScopes_LegacyProviderDefaultsToWrite2269=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2270=== RUN TestScopes_Rules2271=== PAUSE TestScopes_Rules2272=== RUN TestScopes_ConfigValidation2273=== PAUSE TestScopes_ConfigValidation2274=== CONT TestAudienceForIssuer2275=== CONT TestPins_ConfigValidation2276=== CONT TestValidateToken_Expired2277=== CONT TestValidateToken_KubernetesServiceAccount2278=== CONT TestValidateToken_BoundClaimsMismatch2279=== CONT TestPins_ReservedForMatchingRule2280=== CONT TestScopes_Rules2281=== CONT TestValidateToken_ValidToken2282=== CONT TestValidateToken_MultipleProviders2283=== CONT TestScopes_ConfigValidation2284=== CONT TestGlobMatch2285=== RUN TestGlobMatch/foo_foo2286=== CONT TestPins_TopLevelShorthand2287=== PAUSE TestGlobMatch/foo_foo2288=== RUN TestGlobMatch/foo_bar2289=== PAUSE TestGlobMatch/foo_bar2290=== RUN TestGlobMatch/*_2291=== PAUSE TestGlobMatch/*_2292=== RUN TestGlobMatch/*_anything2293=== CONT TestValidateToken_WrongAudience2294=== CONT TestNewValidator_KubernetesRequiresCA2295--- PASS: TestAudienceForIssuer (0.00s)2296=== CONT TestScopes_LegacyProviderDefaultsToWrite2297=== PAUSE TestGlobMatch/*_anything2298=== RUN TestGlobMatch/foo*_foo2299=== PAUSE TestGlobMatch/foo*_foo2300=== RUN TestGlobMatch/foo*_foobar2301=== PAUSE TestGlobMatch/foo*_foobar2302=== RUN TestGlobMatch/foo*_bar2303=== PAUSE TestGlobMatch/foo*_bar2304=== RUN TestGlobMatch/*bar_bar2305=== PAUSE TestGlobMatch/*bar_bar2306=== RUN TestGlobMatch/*bar_foobar2307=== CONT TestValidateToken_NoMatchingProvider2308=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2309=== CONT TestValidateToken_BoundSubjectMismatch2310=== PAUSE TestGlobMatch/*bar_foobar2311--- PASS: TestScopes_ConfigValidation (0.00s)2312=== RUN TestGlobMatch/*bar_foo2313=== PAUSE TestGlobMatch/*bar_foo2314=== RUN TestGlobMatch/foo*bar_foobar2315=== PAUSE TestGlobMatch/foo*bar_foobar2316=== RUN TestGlobMatch/foo*bar_foo123bar2317=== PAUSE TestGlobMatch/foo*bar_foo123bar2318=== RUN TestGlobMatch/foo*bar_foobarbaz2319=== PAUSE TestGlobMatch/foo*bar_foobarbaz2320=== RUN TestGlobMatch/*/*_foo/bar2321--- PASS: TestPins_ConfigValidation (0.00s)2322=== PAUSE TestGlobMatch/*/*_foo/bar2323=== RUN TestGlobMatch/*/*_foo2324=== PAUSE TestGlobMatch/*/*_foo2325=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2326=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2327=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02328=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02329=== RUN TestGlobMatch/refs/*/main_refs/heads/main2330=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2331=== RUN TestGlobMatch/fo?_foo2332=== PAUSE TestGlobMatch/fo?_foo2333=== RUN TestGlobMatch/fo?_fo2334=== PAUSE TestGlobMatch/fo?_fo2335=== RUN TestGlobMatch/fo?_fooo2336=== PAUSE TestGlobMatch/fo?_fooo2337=== RUN TestGlobMatch/?oo_foo2338=== PAUSE TestGlobMatch/?oo_foo2339=== RUN TestGlobMatch/?oo_boo2340=== PAUSE TestGlobMatch/?oo_boo2341=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2342=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2343=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2344=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2345=== CONT TestGlobMatch/foo_foo2346=== CONT TestGlobMatch/foo*bar_foobarbaz2347=== CONT TestGlobMatch/*/*_foo/bar2348=== CONT TestGlobMatch/foo*_foobar2349=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2350=== CONT TestGlobMatch/fo?_fooo2351=== CONT TestGlobMatch/foo*_foo2352=== CONT TestGlobMatch/*_anything2353=== CONT TestGlobMatch/*_2354=== CONT TestGlobMatch/foo_bar2355=== CONT TestGlobMatch/foo*_bar2356=== CONT TestGlobMatch/*/*_foo2357=== CONT TestGlobMatch/*bar_foo2358=== CONT TestGlobMatch/fo?_fo2359=== CONT TestGlobMatch/foo*bar_foo123bar2360=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2361=== CONT TestGlobMatch/*bar_foobar2362=== CONT TestGlobMatch/foo*bar_foobar2363=== CONT TestGlobMatch/*bar_bar2364=== CONT TestGlobMatch/?oo_foo2365=== CONT TestGlobMatch/refs/*/main_refs/heads/main2366=== CONT TestGlobMatch/fo?_foo2367=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02368=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2369=== CONT TestGlobMatch/?oo_boo2370--- PASS: TestGlobMatch (0.00s)2371 --- PASS: TestGlobMatch/foo_foo (0.00s)2372 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2373 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2374 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2375 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2376 --- PASS: TestGlobMatch/*_ (0.00s)2377 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2378 --- PASS: TestGlobMatch/foo*_foo (0.00s)2379 --- PASS: TestGlobMatch/foo_bar (0.00s)2380 --- PASS: TestGlobMatch/*_anything (0.00s)2381 --- PASS: TestGlobMatch/*/*_foo (0.00s)2382 --- PASS: TestGlobMatch/*bar_foo (0.00s)2383 --- PASS: TestGlobMatch/foo*_bar (0.00s)2384 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2385 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2386 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2387 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2388 --- PASS: TestGlobMatch/*bar_bar (0.00s)2389 --- PASS: TestGlobMatch/fo?_fo (0.00s)2390 --- PASS: TestGlobMatch/?oo_foo (0.00s)2391 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2392 --- PASS: TestGlobMatch/fo?_foo (0.00s)2393 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2394 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2395 --- PASS: TestGlobMatch/?oo_boo (0.00s)23962026/10/27 08:40:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43219/oidc2397--- PASS: TestValidateToken_BoundSubjectMismatch (0.03s)23982026/10/27 08:40:03 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:349152399--- PASS: TestValidateToken_KubernetesServiceAccount (0.04s)24002026/10/27 08:40:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34653/oidc24012026/10/27 08:40:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42579/oidc2402--- PASS: TestValidateToken_WrongAudience (0.04s)2403--- PASS: TestScopes_Rules (0.05s)24042026/10/27 08:40:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40751/oidc2405--- PASS: TestPins_TopLevelShorthand (0.07s)24062026/10/27 08:40:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38469/oidc2407--- PASS: TestPins_ReservedForMatchingRule (0.08s)24082026/10/27 08:40:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43551/oidc2409--- PASS: TestValidateToken_BoundClaimsMismatch (0.10s)24102026/10/27 08:40:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43949/oidc2411--- PASS: TestValidateToken_ValidToken (0.11s)24122026/10/27 08:40:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35621/oidc2413--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.12s)24142026/10/27 08:40:03 http: TLS handshake error from 127.0.0.1:42062: remote error: tls: bad certificate2415--- PASS: TestNewValidator_KubernetesRequiresCA (0.14s)24162026/10/27 08:40:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43589/oidc2417--- PASS: TestValidateToken_Expired (0.15s)24182026/10/27 08:40:03 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:46213/oidc2419--- PASS: TestValidateToken_NoMatchingProvider (0.16s)24202026/10/27 08:40:03 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:38007/oidc24212026/10/27 08:40:03 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:34303/oidc2422--- PASS: TestValidateToken_MultipleProviders (0.22s)24232026/10/27 08:40:03 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232424--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.25s)2425PASS2426Running hook tests...2427=== RUN TestSendPathsEmpty2428=== PAUSE TestSendPathsEmpty2429=== RUN TestQueueEnqueueAndFetch2430=== PAUSE TestQueueEnqueueAndFetch2431=== RUN TestQueueDeduplication2432=== PAUSE TestQueueDeduplication2433=== RUN TestQueueRemove2434=== PAUSE TestQueueRemove2435=== RUN TestQueueFetchBatchLimit2436=== PAUSE TestQueueFetchBatchLimit2437=== RUN TestQueueRetryMovesToBack2438=== PAUSE TestQueueRetryMovesToBack2439=== RUN TestQueueFetchRemoveLifecycle2440=== PAUSE TestQueueFetchRemoveLifecycle2441=== RUN TestQueueConcurrentWriters2442=== PAUSE TestQueueConcurrentWriters2443=== RUN TestQueueRemoveLargeClosure2444=== PAUSE TestQueueRemoveLargeClosure2445=== RUN TestServerClientIntegration2446--- PASS: TestServerClientIntegration (0.00s)2447=== RUN TestServerQueueError24482026/10/27 08:40:03 ERROR Failed to queue paths error="permission denied" count=12449--- PASS: TestServerQueueError (0.00s)2450=== RUN TestGetListenerSocketActivation2451 server_test.go:218: === RUN TestGetListenerSocketActivation2452 --- PASS: TestGetListenerSocketActivation (0.00s)2453 PASS2454 2455--- PASS: TestGetListenerSocketActivation (0.00s)2456=== RUN TestServerStalledClientDoesNotBlockShutdown2457=== PAUSE TestServerStalledClientDoesNotBlockShutdown2458=== RUN TestServerBacksOffOnAcceptErrors2459=== PAUSE TestServerBacksOffOnAcceptErrors2460=== RUN TestDrainIsolatesPoisonPath2461=== PAUSE TestDrainIsolatesPoisonPath2462=== RUN TestRunNotBlockedByPoisonHead2463=== PAUSE TestRunNotBlockedByPoisonHead2464=== RUN TestDrainGivesUpWhenServerDown2465=== PAUSE TestDrainGivesUpWhenServerDown2466=== RUN TestFailedPathPrunedByLaterClosure2467=== PAUSE TestFailedPathPrunedByLaterClosure2468=== RUN TestWorkerUploadsAndRemoves2469=== PAUSE TestWorkerUploadsAndRemoves2470=== RUN TestWorkerSkipsGCdPaths2471=== PAUSE TestWorkerSkipsGCdPaths2472=== RUN TestWorkerPrunesClosureDeps2473=== PAUSE TestWorkerPrunesClosureDeps2474=== RUN TestDrainTimeout2475=== PAUSE TestDrainTimeout2476=== RUN TestWorkerRemoveFailureIsNotProgress2477=== PAUSE TestWorkerRemoveFailureIsNotProgress2478=== RUN TestWorkerKeepsPathItCannotStat2479=== PAUSE TestWorkerKeepsPathItCannotStat2480=== CONT TestSendPathsEmpty2481=== CONT TestWorkerKeepsPathItCannotStat2482=== CONT TestRunNotBlockedByPoisonHead2483=== CONT TestWorkerRemoveFailureIsNotProgress2484=== CONT TestWorkerPrunesClosureDeps2485=== CONT TestQueueFetchBatchLimit2486=== CONT TestQueueEnqueueAndFetch2487--- PASS: TestSendPathsEmpty (0.00s)2488=== CONT TestQueueFetchRemoveLifecycle2489=== CONT TestWorkerUploadsAndRemoves2490=== CONT TestFailedPathPrunedByLaterClosure2491=== CONT TestDrainGivesUpWhenServerDown2492=== CONT TestDrainTimeout2493=== CONT TestDrainIsolatesPoisonPath2494=== CONT TestServerBacksOffOnAcceptErrors2495=== CONT TestServerStalledClientDoesNotBlockShutdown2496=== CONT TestQueueRemoveLargeClosure24972026/10/27 08:40:03 ERROR Accept failed error="too many open files"2498=== CONT TestQueueConcurrentWriters2499=== CONT TestQueueRemove2500=== CONT TestQueueRetryMovesToBack2501=== CONT TestWorkerSkipsGCdPaths2502=== CONT TestQueueDeduplication25032026/10/27 08:40:03 ERROR Accept failed error="too many open files"25042026/10/27 08:40:03 INFO Upload queue status pending=225052026/10/27 08:40:03 INFO Uploading batch count=425062026/10/27 08:40:03 ERROR Upload failed error="upload failed" count=425072026/10/27 08:40:03 INFO Upload queue status pending=225082026/10/27 08:40:03 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths3827131675/002/nonexistent25092026/10/27 08:40:03 INFO Uploading batch count=22510--- PASS: TestQueueFetchBatchLimit (0.02s)25112026/10/27 08:40:03 INFO Uploading batch count=125122026/10/27 08:40:03 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat1526333499/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat1526333499/002/locked/aaa: permission denied"2513--- PASS: TestQueueEnqueueAndFetch (0.02s)2514--- PASS: TestQueueFetchRemoveLifecycle (0.02s)25152026/10/27 08:40:03 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath3163939853/002/bbb25162026/10/27 08:40:03 INFO Uploading batch count=125172026/10/27 08:40:03 ERROR Upload failed error="upload failed" count=125182026/10/27 08:40:03 ERROR Accept failed error="too many open files"25192026/10/27 08:40:03 INFO Uploading batch count=225202026/10/27 08:40:03 INFO Uploading batch count=225212026/10/27 08:40:03 ERROR Upload failed error="upload failed" count=225222026/10/27 08:40:03 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1464363572/002/a25232026/10/27 08:40:03 INFO Upload queue status pending=325242026/10/27 08:40:03 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat1526333499/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat1526333499/002/locked/aaa: permission denied"25252026/10/27 08:40:03 INFO Upload queue status pending=225262026/10/27 08:40:03 INFO Uploading batch count=125272026/10/27 08:40:03 INFO Uploading batch count=125282026/10/27 08:40:03 ERROR Upload failed error="upload failed" count=12529--- PASS: TestQueueDeduplication (0.02s)25302026/10/27 08:40:03 INFO Uploading batch count=125312026/10/27 08:40:03 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1464363572/002/b25322026/10/27 08:40:03 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress2394931067/002/nonexistent25332026/10/27 08:40:03 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125342026/10/27 08:40:03 INFO Uploading batch count=225352026/10/27 08:40:03 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress2394931067/002/nonexistent25362026/10/27 08:40:03 ERROR Upload failed error="upload failed" count=225372026/10/27 08:40:03 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1464363572/002/c25382026/10/27 08:40:03 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125392026/10/27 08:40:03 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat1526333499/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat1526333499/002/locked/aaa: permission denied"25402026/10/27 08:40:03 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress2394931067/002/nonexistent25412026/10/27 08:40:03 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125422026/10/27 08:40:03 ERROR Drain finished with paths left in queue remaining=12543--- PASS: TestQueueRetryMovesToBack (0.02s)25442026/10/27 08:40:03 INFO Uploading batch count=125452026/10/27 08:40:03 ERROR Upload failed error="upload failed" count=125462026/10/27 08:40:03 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1464363572/002/d25472026/10/27 08:40:03 INFO Uploading batch count=12548--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)25492026/10/27 08:40:03 ERROR Drain finished with paths left in queue remaining=12550--- PASS: TestQueueRemove (0.02s)25512026/10/27 08:40:03 INFO Uploading batch count=225522026/10/27 08:40:03 ERROR Upload failed error="upload failed" count=225532026/10/27 08:40:03 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1464363572/002/e25542026/10/27 08:40:03 INFO Uploading batch count=125552026/10/27 08:40:03 ERROR Upload failed error="upload failed" count=125562026/10/27 08:40:03 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1464363572/002/f25572026/10/27 08:40:03 INFO Uploading batch count=125582026/10/27 08:40:03 ERROR Upload failed error="upload failed" count=125592026/10/27 08:40:03 ERROR Drain finished with paths left in queue remaining=102560--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)25612026/10/27 08:40:03 ERROR Drain finished with paths left in queue remaining=12562--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2563--- PASS: TestDrainIsolatesPoisonPath (0.02s)2564--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2565--- PASS: TestWorkerSkipsGCdPaths (0.03s)2566--- PASS: TestWorkerUploadsAndRemoves (0.03s)25672026/10/27 08:40:03 ERROR Accept failed error="too many open files"2568--- PASS: TestWorkerPrunesClosureDeps (0.04s)2569--- PASS: TestQueueRemoveLargeClosure (0.06s)25702026/10/27 08:40:03 ERROR Accept failed error="too many open files"25712026/10/27 08:40:03 ERROR Accept failed error="too many open files"25722026/10/27 08:40:03 ERROR Failed to decode request error="read unix /build/hook158749097/test.sock->@: i/o timeout"25732026/10/27 08:40:03 ERROR Failed to write response error="write unix /build/hook158749097/test.sock->@: i/o timeout"2574--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)2575--- PASS: TestQueueConcurrentWriters (0.21s)25762026/10/27 08:40:03 ERROR Upload failed error="context deadline exceeded" count=225772026/10/27 08:40:03 ERROR Drain finished with paths left in queue remaining=42578--- PASS: TestDrainTimeout (0.22s)25792026/10/27 08:40:03 ERROR Accept failed error="too many open files"25802026/10/27 08:40:03 ERROR Accept failed error="too many open files"2581--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)25822026/10/27 08:40:04 INFO Uploading batch count=125832026/10/27 08:40:04 INFO Uploading batch count=125842026/10/27 08:40:04 INFO Uploading batch count=125852026/10/27 08:40:04 ERROR Upload failed error="upload failed" count=125862026/10/27 08:40:04 INFO Uploading batch count=125872026/10/27 08:40:04 ERROR Upload failed error="upload failed" count=125882026/10/27 08:40:04 INFO Uploading batch count=125892026/10/27 08:40:04 ERROR Upload failed error="upload failed" count=125902026/10/27 08:40:04 INFO Uploading batch count=125912026/10/27 08:40:04 ERROR Upload failed error="upload failed" count=125922026/10/27 08:40:04 ERROR Drain finished with paths left in queue remaining=12593--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2594PASS2595Running signing tests...2596=== RUN TestExternalSigner2597=== PAUSE TestExternalSigner2598=== RUN TestExternalSignerWrongPublicKey2599=== PAUSE TestExternalSignerWrongPublicKey2600=== RUN TestExternalSignerErrors2601=== PAUSE TestExternalSignerErrors2602=== RUN TestExternalSignerRestartsAfterCrash2603=== PAUSE TestExternalSignerRestartsAfterCrash2604=== RUN TestExternalSignerProgramErrorKeepsProcess2605=== PAUSE TestExternalSignerProgramErrorKeepsProcess2606=== RUN TestExternalSignerClose2607=== PAUSE TestExternalSignerClose2608=== RUN TestExternalSignerRejectsInvalidPublicKey2609=== PAUSE TestExternalSignerRejectsInvalidPublicKey2610=== RUN TestExternalSignerCancellation2611=== PAUSE TestExternalSignerCancellation2612=== RUN TestGenerateFingerprint2613=== PAUSE TestGenerateFingerprint2614=== RUN TestParseSigningKey2615=== PAUSE TestParseSigningKey2616=== RUN TestSign2617=== PAUSE TestSign2618=== RUN TestSignBatch2619=== PAUSE TestSignBatch2620=== RUN TestNilKeyPublicKey2621=== PAUSE TestNilKeyPublicKey2622=== RUN TestSignErrors2623=== PAUSE TestSignErrors2624=== CONT TestExternalSigner2625=== CONT TestExternalSignerCancellation2626=== CONT TestSignBatch2627=== CONT TestNilKeyPublicKey2628=== CONT TestExternalSignerProgramErrorKeepsProcess2629=== CONT TestExternalSignerRejectsInvalidPublicKey2630=== CONT TestSignErrors2631=== RUN TestExternalSignerRejectsInvalidPublicKey/#002632=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002633=== CONT TestExternalSignerClose2634=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2635=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2636=== CONT TestParseSigningKey2637=== RUN TestParseSigningKey/valid_32-byte_key2638=== PAUSE TestParseSigningKey/valid_32-byte_key2639--- PASS: TestNilKeyPublicKey (0.00s)2640=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2641=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2642=== RUN TestParseSigningKey/no_colon2643=== PAUSE TestParseSigningKey/no_colon2644=== RUN TestParseSigningKey/empty_name2645=== PAUSE TestParseSigningKey/empty_name2646=== RUN TestParseSigningKey/invalid_base642647=== PAUSE TestParseSigningKey/invalid_base642648=== RUN TestParseSigningKey/wrong_length2649=== PAUSE TestParseSigningKey/wrong_length2650=== CONT TestParseSigningKey/valid_32-byte_key2651=== CONT TestParseSigningKey/wrong_length2652=== CONT TestParseSigningKey/invalid_base642653=== CONT TestSign2654=== CONT TestGenerateFingerprint2655=== CONT TestParseSigningKey/no_colon2656=== CONT TestExternalSignerErrors2657=== RUN TestExternalSignerErrors/invalid_JSON2658=== PAUSE TestExternalSignerErrors/invalid_JSON2659=== CONT TestExternalSignerRestartsAfterCrash2660=== RUN TestExternalSignerErrors/too_few_signatures2661=== PAUSE TestExternalSignerErrors/too_few_signatures2662=== RUN TestExternalSignerErrors/unrequested_key2663=== PAUSE TestExternalSignerErrors/unrequested_key2664=== RUN TestExternalSignerErrors/wrong_signature_name2665=== PAUSE TestExternalSignerErrors/wrong_signature_name2666=== RUN TestExternalSignerErrors/exit_on_request2667=== CONT TestExternalSignerWrongPublicKey2668=== PAUSE TestExternalSignerErrors/exit_on_request2669=== RUN TestExternalSignerErrors/wrong_shape2670=== PAUSE TestExternalSignerErrors/wrong_shape2671=== RUN TestExternalSignerErrors/exit_at_startup2672=== PAUSE TestExternalSignerErrors/exit_at_startup2673=== RUN TestExternalSignerErrors/null_signatures2674=== PAUSE TestExternalSignerErrors/null_signatures2675=== RUN TestExternalSignerErrors/missing_signature_name2676=== PAUSE TestExternalSignerErrors/missing_signature_name2677=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2678=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2679=== CONT TestParseSigningKey/empty_name2680=== RUN TestGenerateFingerprint/basic_with_references2681=== RUN TestExternalSignerErrors/program_error2682=== PAUSE TestGenerateFingerprint/basic_with_references2683=== PAUSE TestExternalSignerErrors/program_error2684=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2685=== RUN TestGenerateFingerprint/no_references2686=== PAUSE TestGenerateFingerprint/no_references2687=== RUN TestExternalSignerErrors/null2688=== PAUSE TestExternalSignerErrors/null2689=== RUN TestExternalSignerErrors/wrong_id2690=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2691=== PAUSE TestExternalSignerErrors/wrong_id2692=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2693=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2694=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2695=== RUN TestExternalSignerErrors/missing_signatures2696=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2697=== PAUSE TestExternalSignerErrors/missing_signatures2698=== RUN TestExternalSignerErrors/wrong_signatures_shape2699=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2700=== RUN TestSignErrors/nil_key2701=== CONT TestExternalSignerRejectsInvalidPublicKey/#002702=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2703=== PAUSE TestSignErrors/nil_key2704=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2705=== RUN TestSignErrors/nil_narinfo2706=== PAUSE TestSignErrors/nil_narinfo2707=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2708=== RUN TestSignErrors/invalid_narinfo2709=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2710=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2711=== RUN TestGenerateFingerprint/invalid_nar_hash_length2712=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2713=== RUN TestGenerateFingerprint/invalid_store_path_prefix2714=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2715=== RUN TestExternalSignerErrors/invalid_signature_base642716=== PAUSE TestSignErrors/invalid_narinfo2717=== RUN TestSignErrors/canceled2718=== PAUSE TestSignErrors/canceled2719=== CONT TestSignErrors/nil_key2720=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2721=== PAUSE TestExternalSignerErrors/invalid_signature_base642722=== CONT TestSignErrors/canceled2723=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2724=== RUN TestGenerateFingerprint/invalid_reference_prefix2725=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2726=== CONT TestGenerateFingerprint/basic_with_references2727=== RUN TestExternalSignerErrors/wrong_signature_length2728=== CONT TestGenerateFingerprint/invalid_store_path_prefix2729=== PAUSE TestExternalSignerErrors/wrong_signature_length2730=== CONT TestSignErrors/invalid_narinfo2731=== CONT TestSignErrors/nil_narinfo2732=== CONT TestExternalSignerErrors/missing_signatures2733=== CONT TestExternalSignerErrors/wrong_signature_name2734=== CONT TestExternalSignerErrors/invalid_JSON2735=== CONT TestGenerateFingerprint/invalid_reference_prefix2736=== CONT TestExternalSignerErrors/too_few_signatures2737=== CONT TestExternalSignerErrors/null2738=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2739=== CONT TestExternalSignerErrors/wrong_id2740=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2741=== CONT TestExternalSignerErrors/program_error2742=== CONT TestGenerateFingerprint/no_references2743=== CONT TestExternalSignerErrors/missing_signature_name2744=== CONT TestGenerateFingerprint/invalid_nar_hash_length2745=== CONT TestExternalSignerErrors/wrong_signature_length2746=== CONT TestExternalSignerErrors/invalid_signature_base642747=== CONT TestExternalSignerErrors/wrong_signatures_shape2748=== CONT TestExternalSignerErrors/exit_at_startup2749=== CONT TestExternalSignerErrors/null_signatures2750=== CONT TestExternalSignerErrors/wrong_shape2751=== CONT TestExternalSignerErrors/exit_on_request2752=== CONT TestExternalSignerErrors/unrequested_key2753--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2754 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2755 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2756 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2757 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2758 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2759--- PASS: TestSignErrors (0.00s)2760 --- PASS: TestSignErrors/nil_key (0.00s)2761 --- PASS: TestSignErrors/canceled (0.00s)2762 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2763 --- PASS: TestSignErrors/nil_narinfo (0.00s)2764--- PASS: TestSign (0.00s)2765--- PASS: TestSignBatch (0.00s)2766--- PASS: TestGenerateFingerprint (0.00s)2767 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2768 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2769 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2770 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2771 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2772 --- PASS: TestGenerateFingerprint/no_references (0.00s)2773 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2774--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2775--- PASS: TestParseSigningKey (0.00s)2776 --- PASS: TestParseSigningKey/wrong_length (0.00s)2777 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2778 --- PASS: TestParseSigningKey/no_colon (0.00s)2779 --- PASS: TestParseSigningKey/empty_name (0.00s)2780 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2781 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2782--- PASS: TestExternalSignerClose (0.00s)2783--- PASS: TestExternalSignerWrongPublicKey (0.00s)2784--- PASS: TestExternalSigner (0.01s)2785--- PASS: TestExternalSignerErrors (0.00s)2786 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.00s)2787 --- PASS: TestExternalSignerErrors/missing_signatures (0.00s)2788 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.00s)2789 --- PASS: TestExternalSignerErrors/invalid_JSON (0.00s)2790 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.00s)2791 --- PASS: TestExternalSignerErrors/null_signatures (0.00s)2792 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)2793 --- PASS: TestExternalSignerErrors/exit_on_request (0.00s)2794 --- PASS: TestExternalSignerErrors/exit_at_startup (0.00s)2795 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)2796 --- PASS: TestExternalSignerErrors/unrequested_key (0.00s)2797 --- PASS: TestExternalSignerErrors/too_few_signatures (0.01s)2798 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.01s)2799 --- PASS: TestExternalSignerErrors/wrong_shape (0.00s)2800 --- PASS: TestExternalSignerErrors/program_error (0.01s)2801 --- PASS: TestExternalSignerErrors/null (0.01s)2802--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2803--- PASS: TestExternalSignerCancellation (0.02s)2804PASS2805Running OpenBao signer tests...2806=== RUN TestSign2807=== PAUSE TestSign2808=== RUN TestSignErrors2809=== PAUSE TestSignErrors2810=== RUN TestServe2811=== PAUSE TestServe2812=== RUN TestServeRejectsGarbage2813=== PAUSE TestServeRejectsGarbage2814=== CONT TestSign2815=== CONT TestServe2816=== CONT TestSignErrors2817=== RUN TestSignErrors/no_prefix2818=== CONT TestServeRejectsGarbage2819=== PAUSE TestSignErrors/no_prefix2820=== RUN TestSignErrors/invalid_base642821=== PAUSE TestSignErrors/invalid_base642822=== RUN TestSignErrors/http_error2823=== PAUSE TestSignErrors/http_error2824=== RUN TestSignErrors/invalid_json2825=== PAUSE TestSignErrors/invalid_json2826=== CONT TestSignErrors/no_prefix2827=== CONT TestSignErrors/invalid_base642828=== CONT TestSignErrors/invalid_json2829--- PASS: TestServeRejectsGarbage (0.00s)2830=== CONT TestSignErrors/http_error2831--- PASS: TestServe (0.00s)2832--- PASS: TestSign (0.00s)2833--- PASS: TestSignErrors (0.00s)2834 --- PASS: TestSignErrors/http_error (0.00s)2835 --- PASS: TestSignErrors/no_prefix (0.00s)2836 --- PASS: TestSignErrors/invalid_json (0.00s)2837 --- PASS: TestSignErrors/invalid_base64 (0.00s)2838PASS