niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #450
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestUploadMultipart_FailedPartBufferNotReused20=== PAUSE TestUploadMultipart_FailedPartBufferNotReused21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestUploadMultipart_SupersededByPeer24=== PAUSE TestUploadMultipart_SupersededByPeer25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (0.05s)27=== RUN TestDumpPathCaseHackCollision28--- PASS: TestDumpPathCaseHackCollision (0.00s)29=== RUN TestSupersededNARStillUploadsListing30=== PAUSE TestSupersededNARStillUploadsListing31=== RUN TestDumpPathMatchesNix32=== PAUSE TestDumpPathMatchesNix33=== RUN TestDumpPathSingleFile34=== PAUSE TestDumpPathSingleFile35=== RUN TestDumpPathWriterError36=== PAUSE TestDumpPathWriterError37=== RUN TestEncodeNixBase3238=== PAUSE TestEncodeNixBase3239=== RUN TestEncodeNixBase32WithRealHash40=== PAUSE TestEncodeNixBase32WithRealHash41=== RUN TestConvertHashToNix3242=== PAUSE TestConvertHashToNix3243=== RUN TestGetStorePathHash44=== PAUSE TestGetStorePathHash45=== RUN TestPathInfoHashCompatibility46=== PAUSE TestPathInfoHashCompatibility47=== RUN TestParsePathInfoJSON48=== PAUSE TestParsePathInfoJSON49=== RUN TestParsePathInfoJSONMultiplePaths50=== PAUSE TestParsePathInfoJSONMultiplePaths51=== RUN TestPathInfoCACompatibility52=== PAUSE TestPathInfoCACompatibility53=== RUN TestRateLimiterFeedback54=== PAUSE TestRateLimiterFeedback55=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess56=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess57=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer58=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer59=== RUN TestResolveStorePath60=== PAUSE TestResolveStorePath61=== RUN TestDoWithRetry_BodyReplayedViaGetBody62=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody63=== RUN TestRetryTimeoutOutlastsMaxRetries64=== PAUSE TestRetryTimeoutOutlastsMaxRetries65=== RUN TestDoWithRetry_FinalResponseBodyReadable66=== PAUSE TestDoWithRetry_FinalResponseBodyReadable67=== RUN TestShellSplit68=== PAUSE TestShellSplit69=== RUN TestShellSplitErrors70=== PAUSE TestShellSplitErrors71=== RUN TestStreamPushReportsEveryPath72=== PAUSE TestStreamPushReportsEveryPath73=== RUN TestStreamPushBatchesUnderLoad74=== PAUSE TestStreamPushBatchesUnderLoad75=== RUN TestStreamPushIsolatesFailures76=== PAUSE TestStreamPushIsolatesFailures77=== RUN TestStreamPushGivesUpOnDeadServer78=== PAUSE TestStreamPushGivesUpOnDeadServer79=== RUN TestStreamPushRequestLine80=== PAUSE TestStreamPushRequestLine81=== RUN TestStreamPushReportsSignatures82=== PAUSE TestStreamPushReportsSignatures83=== RUN TestStreamPushReportsSkippedPaths84=== PAUSE TestStreamPushReportsSkippedPaths85=== RUN TestClientSignaturesByStorePath86=== PAUSE TestClientSignaturesByStorePath87=== RUN TestStreamPushStopsWhenCanceled88=== PAUSE TestStreamPushStopsWhenCanceled89=== RUN TestSetClientTLS90=== PAUSE TestSetClientTLS91=== RUN TestSetClientTLSDoesNotMutateDefaultTransport92=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport93=== RUN TestSetClientTLSErrors94=== PAUSE TestSetClientTLSErrors95=== RUN TestStaticToken96=== PAUSE TestStaticToken97=== RUN TestFileTokenReadsAndCaches98=== PAUSE TestFileTokenReadsAndCaches99=== RUN TestFileTokenMissing100=== PAUSE TestFileTokenMissing101=== RUN TestFileTokenEmpty102=== PAUSE TestFileTokenEmpty103=== RUN TestScriptTokenNoExpiryRerunsEveryCall104=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall105=== RUN TestScriptTokenCachesUntilRefresh106=== PAUSE TestScriptTokenCachesUntilRefresh107=== RUN TestScriptTokenEmptyToken108=== PAUSE TestScriptTokenEmptyToken109=== RUN TestScriptTokenBadJSON110=== PAUSE TestScriptTokenBadJSON111=== RUN TestScriptTokenScriptFails112=== PAUSE TestScriptTokenScriptFails113=== RUN TestScriptTokenEmptyCommand114=== PAUSE TestScriptTokenEmptyCommand115=== CONT TestDoServerRequestAttachesToken116=== CONT TestSetClientTLSErrors117=== CONT TestEncodeNixBase32WithRealHash118--- PASS: TestEncodeNixBase32WithRealHash (0.00s)119=== CONT TestParsePathInfoJSON120=== RUN TestParsePathInfoJSON/Nix_format121=== PAUSE TestParsePathInfoJSON/Nix_format122=== RUN TestParsePathInfoJSON/Lix_format123=== PAUSE TestParsePathInfoJSON/Lix_format124=== RUN TestParsePathInfoJSON/empty_input125=== PAUSE TestParsePathInfoJSON/empty_input126=== RUN TestParsePathInfoJSON/whitespace_only127=== PAUSE TestParsePathInfoJSON/whitespace_only128=== RUN TestParsePathInfoJSON/invalid_JSON129=== PAUSE TestParsePathInfoJSON/invalid_JSON130=== CONT TestStreamPushReportsEveryPath131=== CONT TestShellSplitErrors132--- PASS: TestShellSplitErrors (0.00s)133=== CONT TestStreamPushBatchesUnderLoad134=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false135=== CONT TestSetClientTLSDoesNotMutateDefaultTransport136=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false137=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true138=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true139=== CONT TestGetStorePathHash140=== RUN TestGetStorePathHash/valid_store_path141=== PAUSE TestGetStorePathHash/valid_store_path142=== RUN TestGetStorePathHash/basename_without_hyphen_should_error143=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error144=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error145=== CONT TestShellSplit146--- PASS: TestShellSplit (0.00s)147=== CONT TestSetClientTLS148=== CONT TestDoWithRetry_FinalResponseBodyReadable149=== CONT TestStreamPushStopsWhenCanceled150=== CONT TestRetryTimeoutOutlastsMaxRetries151=== CONT TestClientSignaturesByStorePath152=== CONT TestDoWithRetry_BodyReplayedViaGetBody153=== CONT TestStreamPushReportsSkippedPaths154=== CONT TestResolveStorePath155=== CONT TestStreamPushReportsSignatures156=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer157=== CONT TestStreamPushRequestLine158=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess159=== CONT TestRateLimiterFeedback160=== CONT TestStreamPushGivesUpOnDeadServer161=== CONT TestPathInfoCACompatibility162=== CONT TestParsePathInfoJSONMultiplePaths163=== CONT TestStreamPushIsolatesFailures164=== CONT TestPathInfoHashCompatibility165=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error166=== CONT TestConvertHashToNix32167=== RUN TestConvertHashToNix32/SRI_format_to_Nix32168=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32169--- PASS: TestClientSignaturesByStorePath (0.00s)170=== RUN TestConvertHashToNix32/already_Nix32_format171=== CONT TestUploadMultipart_FailedPartBufferNotReused172=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error173=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error174=== CONT TestEncodeNixBase32175=== RUN TestEncodeNixBase32/test_string_hash176=== PAUSE TestEncodeNixBase32/test_string_hash177=== RUN TestEncodeNixBase32/empty_input178=== PAUSE TestEncodeNixBase32/empty_input179=== CONT TestFileTokenMissing180=== RUN TestRateLimiterFeedback/429_enables_limiter1812026/11/01 16:18:48 WARN Rate limiter enabled after throttle name=server-test rate=5182=== PAUSE TestRateLimiterFeedback/429_enables_limiter183=== RUN TestRateLimiterFeedback/503_enables_limiter184--- PASS: TestFileTokenMissing (0.00s)185--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)186=== RUN TestSetClientTLS/rejects_connection_without_client_cert187--- PASS: TestStreamPushStopsWhenCanceled (0.03s)188=== PAUSE TestRateLimiterFeedback/503_enables_limiter189=== RUN TestPathInfoCACompatibility/null_ca_field1902026/11/01 16:18:48 ERROR Upload failed error="bad path" count=3191=== CONT TestDumpPathWriterError1922026/11/01 16:18:48 ERROR Upload failed error="connection refused" count=201932026/11/01 16:18:48 ERROR Server seems unavailable, giving up on batch untried=17194=== PAUSE TestConvertHashToNix32/already_Nix32_format195=== RUN TestConvertHashToNix32/invalid_format196=== PAUSE TestConvertHashToNix32/invalid_format197=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)198=== CONT TestScriptTokenNoExpiryRerunsEveryCall199=== PAUSE TestPathInfoCACompatibility/null_ca_field200=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)201=== CONT TestDumpPathSingleFile202=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert203=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA204=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter205--- PASS: TestStreamPushIsolatesFailures (0.00s)206=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter207=== CONT TestPartSizeForNAR208=== CONT TestFileTokenEmpty209=== RUN TestPartSizeForNAR/zero_stays_at_minimum210=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter211=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter2122026/11/01 16:18:48 ERROR Upload failed error=boom count=1213--- PASS: TestStreamPushReportsEveryPath (0.03s)214--- PASS: TestStreamPushReportsSkippedPaths (0.03s)215=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun2162026/11/01 16:18:48 WARN Rate limiter enabled after throttle name=server-test rate=52172026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:37801218=== CONT TestDumpPathMatchesNix2192026/11/01 16:18:48 ERROR Upload failed error=boom count=12202026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:33333221=== RUN TestSetClientTLSErrors/missing_cert_file222=== PAUSE TestSetClientTLSErrors/missing_cert_file223=== RUN TestPathInfoCACompatibility/old_string_format_-_text2242026/11/01 16:18:48 WARN Rate limiter enabled after throttle name=server-test rate=5225=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text2262026/11/01 16:18:48 WARN Rate limiter backed off name=server-test rate=5227=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon2282026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:378012292026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:40919230=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon231=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA2322026/11/01 16:18:48 WARN Rate limiter backed off name=server-test rate=5233=== CONT TestSupersededNARStillUploadsListing234=== RUN TestSupersededNARStillUploadsListing/small_NAR235=== CONT TestStaticToken236=== CONT TestUploadMultipart_SupersededByPeer2372026/11/01 16:18:48 INFO Garbage collection started238=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica239=== RUN TestUploadMultipart_SupersededByPeer/exists240=== PAUSE TestUploadMultipart_SupersededByPeer/exists241=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths242=== CONT TestUploadMultipart_PartsInParallel243=== RUN TestUploadMultipart_SupersededByPeer/missing244=== PAUSE TestUploadMultipart_SupersededByPeer/missing245=== CONT TestFileTokenReadsAndCaches246--- PASS: TestResolveStorePath (0.03s)247--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)248=== RUN TestSetClientTLSErrors/missing_key_file249=== PAUSE TestSetClientTLSErrors/missing_key_file250=== RUN TestSetClientTLSErrors/missing_ca_file251=== PAUSE TestSetClientTLSErrors/missing_ca_file252=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive253=== CONT TestFilterOversizedClosures254=== RUN TestFilterOversizedClosures/no_limit_keeps_everything255=== CONT TestCaseHackSuffix256=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI257=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI258=== RUN TestSetClientTLS/preserves_debug_logging_transport259=== PAUSE TestSupersededNARStillUploadsListing/small_NAR260=== CONT TestRegisterUploadedObjectReusesConnections2612026/11/01 16:18:48 INFO Garbage collection started262=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum2632026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:33333264=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths265=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry266--- PASS: TestStreamPushReportsSignatures (0.03s)267=== RUN TestSetClientTLSErrors/invalid_ca_file268=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive269=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything270=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512271=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512272=== CONT TestScriptTokenEmptyCommand273=== CONT TestScriptTokenCachesUntilRefresh274=== RUN TestSupersededNARStillUploadsListing/dump_cut_short275=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short276=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails277=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails278=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths279=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths280=== CONT TestParsePathInfoJSON/Nix_format281=== CONT TestParsePathInfoJSON/whitespace_only282=== CONT TestParsePathInfoJSON/empty_input283=== CONT TestParsePathInfoJSON/Lix_format284=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false285=== CONT TestScriptTokenScriptFails2862026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:333332872026/11/01 16:18:48 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=0288=== CONT TestParsePathInfoJSON/invalid_JSON289=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true290=== CONT TestGetStorePathHash/valid_store_path291=== CONT TestEncodeNixBase32/test_string_hash292=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error293=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error294=== CONT TestGetStorePathHash/basename_without_hyphen_should_error295=== CONT TestEncodeNixBase32/empty_input296=== CONT TestConvertHashToNix32/SRI_format_to_Nix32297=== CONT TestConvertHashToNix32/invalid_format298=== CONT TestConvertHashToNix32/already_Nix32_format299=== CONT TestRateLimiterFeedback/429_enables_limiter300=== RUN TestPartSizeForNAR/small_stays_at_minimum301=== PAUSE TestPartSizeForNAR/small_stays_at_minimum302=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum303=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum304=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts305=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts306=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter307--- PASS: TestDoServerRequestAttachesToken (0.04s)308=== CONT TestScriptTokenBadJSON309--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.03s)310--- PASS: TestFileTokenEmpty (0.00s)311--- PASS: TestStaticToken (0.00s)312--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.03s)313=== RUN TestPathInfoCACompatibility/new_structured_format_-_text314=== RUN TestPartSizeForNAR/1_TiB315=== PAUSE TestPartSizeForNAR/1_TiB316=== RUN TestPartSizeForNAR/5_TiB_S3_max_object317=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object318=== RUN TestPartSizeForNAR/capped_at_5_GiB319=== PAUSE TestPartSizeForNAR/capped_at_5_GiB320=== PAUSE TestSetClientTLS/preserves_debug_logging_transport321=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter3222026/11/01 16:18:48 WARN Rate limiter enabled after throttle name=server-test rate=5323=== CONT TestScriptTokenEmptyToken3242026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:45583325=== CONT TestUploadMultipart_SupersededByPeer/exists326=== CONT TestRateLimiterFeedback/503_enables_limiter3272026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:333333282026/11/01 16:18:48 WARN Garbage collection finished on another replica. Its statistics are not available here329=== CONT TestUploadMultipart_SupersededByPeer/missing3302026/11/01 16:18:48 WARN Rate limiter backed off name=server-test rate=53312026/11/01 16:18:48 WARN Rate limiter enabled after throttle name=s3-test rate=53322026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:38935333=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha5123342026/11/01 16:18:48 WARN Rate limiter enabled after throttle name=server-test rate=5335=== PAUSE TestSetClientTLSErrors/invalid_ca_file3362026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:38249337--- PASS: TestFileTokenReadsAndCaches (0.03s)338=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)339=== CONT TestSupersededNARStillUploadsListing/small_NAR3402026/11/01 16:18:48 WARN Rate limiter backed off name=server-test rate=5341=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths342=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails3432026/11/01 16:18:48 INFO Uploading abc-hello (1.0GB)344=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths345=== CONT TestPartSizeForNAR/zero_stays_at_minimum346=== CONT TestSetClientTLS/rejects_connection_without_client_cert347--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.04s)348--- PASS: TestDumpPathSingleFile (0.04s)349--- PASS: TestScriptTokenEmptyCommand (0.00s)350=== CONT TestPartSizeForNAR/5_TiB_S3_max_object351=== CONT TestPartSizeForNAR/1_TiB3522026/11/01 16:18:48 INFO Uploading abc-hello (1.0GB)353=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts354=== CONT TestPartSizeForNAR/small_stays_at_minimum355=== CONT TestSetClientTLS/preserves_debug_logging_transport356=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3572026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:33333358=== CONT TestSetClientTLSErrors/missing_cert_file359=== CONT TestSetClientTLSErrors/invalid_ca_file360=== CONT TestSupersededNARStillUploadsListing/dump_cut_short361=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum362=== CONT TestSetClientTLSErrors/missing_ca_file363=== CONT TestSetClientTLSErrors/missing_key_file364=== CONT TestPartSizeForNAR/capped_at_5_GiB365=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped366=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped367=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI368=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon369=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text370--- PASS: TestParsePathInfoJSON (0.00s)371 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)372 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)373 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)374 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)375 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)376--- PASS: TestScriptTokenScriptFails (0.00s)377--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.04s)378--- PASS: TestScriptTokenBadJSON (0.00s)379--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.00s)380--- PASS: TestScriptTokenEmptyToken (0.00s)381--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)382--- PASS: TestStreamPushBatchesUnderLoad (0.13s)383 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)384 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)3852026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:33333386=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method387=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method388=== RUN TestFilterOversizedClosures/all_closures_skipped389=== PAUSE TestFilterOversizedClosures/all_closures_skipped390=== CONT TestFilterOversizedClosures/no_limit_keeps_everything391--- PASS: TestEncodeNixBase32 (0.13s)392 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)393 --- PASS: TestEncodeNixBase32/empty_input (0.00s)394--- PASS: TestConvertHashToNix32 (0.16s)395 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)396 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)397 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)398--- PASS: TestGetStorePathHash (0.13s)399 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)400 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)401 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)402 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)403--- PASS: TestUploadMultipart_SupersededByPeer (0.13s)404 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)405 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)406--- PASS: TestParsePathInfoJSONMultiplePaths (0.17s)407 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)408 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)409--- PASS: TestRateLimiterFeedback (0.16s)410 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)411 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)412 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)413 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)414=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped4152026/11/01 16:18:48 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=2000416=== CONT TestPathInfoCACompatibility/null_ca_field417=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method418=== CONT TestPathInfoCACompatibility/new_structured_format_-_text4192026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:33333420=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive421=== CONT TestPathInfoCACompatibility/old_string_format_-_text422--- PASS: TestPathInfoCACompatibility (0.17s)423 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)424 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)425 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)426 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)427 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)428=== CONT TestFilterOversizedClosures/all_closures_skipped4292026/11/01 16:18:48 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50430--- PASS: TestFilterOversizedClosures (0.17s)431 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)432 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)433 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)4342026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:33333435--- PASS: TestPartSizeForNAR (0.17s)436 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)437 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)438 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)439 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)440 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)441 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)442 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)4432026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:33333444--- PASS: TestSetClientTLSErrors (0.21s)445 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)446 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)447 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)448 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)449--- PASS: TestPathInfoHashCompatibility (0.17s)450 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)451 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)452 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)453 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)4542026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:33333455--- PASS: TestCaseHackSuffix (0.17s)456--- PASS: TestScriptTokenCachesUntilRefresh (0.14s)4572026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:333334582026/11/01 16:18:48 http: TLS handshake error from 127.0.0.1:46606: remote error: tls: bad certificate459--- PASS: TestSetClientTLS (0.07s)460 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.13s)461 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.14s)462 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.14s)4632026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:333334642026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:33333465--- PASS: TestStreamPushRequestLine (0.21s)4662026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:333334672026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:33333468--- PASS: TestRegisterUploadedObjectReusesConnections (0.15s)4692026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:333334702026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:333334712026/11/01 16:18:48 WARN Rate limiter enabled after throttle name=s3-test rate=54722026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:333334732026/11/01 16:18:48 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:33333474--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.23s)4752026/11/01 16:18:48 INFO Uploading abc-hello (1.0GB)476--- PASS: TestDumpPathWriterError (0.21s)4772026/11/01 16:18:48 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:35541/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:35541/part/24782026/11/01 16:18:48 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"479--- PASS: TestDumpPathMatchesNix (0.25s)480--- PASS: TestSupersededNARStillUploadsListing (0.03s)481 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.14s)482 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.14s)483 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.69s)484--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.77s)485--- PASS: TestUploadMultipart_PartsInParallel (0.77s)486--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4872026/11/01 16:18:49 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:41843/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:41843/api/uploads/complete4882026/11/01 16:18:49 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4892026/11/01 16:18:49 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:41843/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:41843/api/uploads/complete4902026/11/01 16:18:49 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4912026/11/01 16:18:49 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:41843/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:41843/api/uploads/complete4922026/11/01 16:18:49 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"493--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)494PASS495Running server tests...496The files belonging to this database system will be owned by user "nixbld".497This user must also own the server process.498499The database cluster will be initialized with locale "C".500The default database encoding has accordingly been set to "SQL_ASCII".501The default text search configuration will be set to "english".502503Data page checksums are enabled.504505creating directory /build/postgres804912531/data ... ok506creating subdirectories ... ok507selecting dynamic shared memory implementation ... posix508selecting default "max_connections" ... 100509selecting default "shared_buffers" ... 128MB510selecting default time zone ... UTC511creating configuration files ... ok512running bootstrap script ... ok513performing post-bootstrap initialization ... ok514syncing data to disk ... ok515516initdb: warning: enabling "trust" authentication for local connections517initdb: 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.518519Success. You can now start the database server using:520521 pg_ctl -D /build/postgres804912531/data -l logfile start522523/build/postgres804912531:5432 - no response5242026-11-01 16:18:50.579 UTC [128] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit5252026-11-01 16:18:50.579 UTC [128] LOG: listening on Unix socket "/build/postgres804912531/.s.PGSQL.5432"5262026-11-01 16:18:50.583 UTC [135] LOG: database system was shut down at 2026-11-01 16:18:50 UTC5272026-11-01 16:18:50.586 UTC [128] LOG: database system is ready to accept connections528/build/postgres804912531:5432 - accepting connections529=== RUN TestService_AuthMiddleware530=== PAUSE TestService_AuthMiddleware531=== RUN TestService_AuthMiddleware_MTLSProxyHeader532=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader533=== RUN TestService_AuthMiddleware_MTLSBoundSubjects534=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects535=== RUN TestService_ReadAuthMiddleware536=== PAUSE TestService_ReadAuthMiddleware537=== RUN TestService_AuthMiddleware_OIDC538=== PAUSE TestService_AuthMiddleware_OIDC539=== RUN TestService_RequireScope_OIDC540=== PAUSE TestService_RequireScope_OIDC541=== RUN TestService_ReadScope_PublicByDefault542=== PAUSE TestService_ReadScope_PublicByDefault543=== RUN TestCacheConfigHandler544=== PAUSE TestCacheConfigHandler545=== RUN TestCacheStatsHandler546=== PAUSE TestCacheStatsHandler547=== RUN TestClientCADerivations548=== PAUSE TestClientCADerivations549=== RUN TestClientErrorHandling550=== PAUSE TestClientErrorHandling551=== RUN TestClientIntegration552=== PAUSE TestClientIntegration553=== RUN TestClientMultipleUploads554=== PAUSE TestClientMultipleUploads555=== RUN TestClientWithDependencies556=== PAUSE TestClientWithDependencies557=== RUN TestClientSharedPathCommittedMidPush558=== PAUSE TestClientSharedPathCommittedMidPush559=== RUN TestPinProtectsFromGC560=== PAUSE TestPinProtectsFromGC561=== RUN TestClientPushesUseOnePush562=== PAUSE TestClientPushesUseOnePush563=== RUN TestClientFallsBackToClosures564=== PAUSE TestClientFallsBackToClosures565=== RUN TestDeleteClosuresRacingPins566=== PAUSE TestDeleteClosuresRacingPins567=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock568=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock569=== RUN TestResolveDBConnectionString570=== PAUSE TestResolveDBConnectionString571=== RUN TestConnectWaitsForAPeerMigration572=== PAUSE TestConnectWaitsForAPeerMigration573=== RUN TestLeadElectsOneAndHandsOver574=== PAUSE TestLeadElectsOneAndHandsOver575=== RUN TestLeadIncumbentWinsAfterRestart5762026/11/01 16:18:51 INFO lead: acquired remote=192.0.2.1:12345772026/11/01 16:18:51 INFO lead: released remote=192.0.2.1:12345782026/11/01 16:18:51 INFO lead: acquired remote=192.0.2.1:12345792026/11/01 16:18:52 INFO lead: released remote=192.0.2.1:1234580--- PASS: TestLeadIncumbentWinsAfterRestart (1.89s)581=== RUN TestLeadIncumbentAnnouncesAtOnce582=== PAUSE TestLeadIncumbentAnnouncesAtOnce583=== RUN TestLeadEndsOnShutdown584=== PAUSE TestLeadEndsOnShutdown585=== RUN TestLeadEndsWhenItsConnectionHangs5862026/11/01 16:18:53 INFO lead: acquired remote=192.0.2.1:12345872026-11-01 16:18:54.869 UTC [315] FATAL: terminating connection due to administrator command5882026/11/01 16:18:55 INFO lead: acquired remote=192.0.2.1:12345892026/11/01 16:18:56 WARN lead: lock connection lost error="timeout: context deadline exceeded"5902026/11/01 16:18:56 INFO lead: released remote=192.0.2.1:12345912026/11/01 16:18:56 INFO lead: released remote=192.0.2.1:1234592--- PASS: TestLeadEndsWhenItsConnectionHangs (3.69s)593=== RUN TestGCAdvisoryLockBlocksConcurrentRun594=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun595=== RUN TestGCBugBareHashReferences596=== PAUSE TestGCBugBareHashReferences597=== RUN TestGCMetrics598=== PAUSE TestGCMetrics599=== RUN TestPushDedupSurvivesConcurrentGC600=== PAUSE TestPushDedupSurvivesConcurrentGC601=== RUN TestDeduplicatedObjectsRecordedAsPending602=== PAUSE TestDeduplicatedObjectsRecordedAsPending603=== RUN TestGCSweepSkipsPendingObjects604=== PAUSE TestGCSweepSkipsPendingObjects605=== RUN TestTombstonedObjectOfferedWithoutWaiting606=== PAUSE TestTombstonedObjectOfferedWithoutWaiting607=== RUN TestGCSweepDeliversEachKeyOnce608=== PAUSE TestGCSweepDeliversEachKeyOnce609=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection610=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection611=== RUN TestForceGCDuringPushOffersSweptObject612=== PAUSE TestForceGCDuringPushOffersSweptObject613=== RUN TestFailedS3DeleteKeepsTombstone614=== PAUSE TestFailedS3DeleteKeepsTombstone615=== RUN TestSweepSkipsRowsLockedByPush616=== PAUSE TestSweepSkipsRowsLockedByPush617=== RUN TestRegisterCompletedObjectNeedsPendingRow618=== PAUSE TestRegisterCompletedObjectNeedsPendingRow619=== RUN TestGetExistingObjectsLocksRows620=== PAUSE TestGetExistingObjectsLocksRows621=== RUN TestSweepRechecksPendingAfterLocking622=== PAUSE TestSweepRechecksPendingAfterLocking623=== RUN TestPushWaitsForSweepHoldingRow624=== PAUSE TestPushWaitsForSweepHoldingRow625=== RUN TestCommitRacingPendingCleanupKeepsObjects626=== PAUSE TestCommitRacingPendingCleanupKeepsObjects627=== RUN TestGCEndsOnShutdown628=== PAUSE TestGCEndsOnShutdown629=== RUN TestGCTaskStore_StartNew630=== PAUSE TestGCTaskStore_StartNew631=== RUN TestGCTaskStore_DeduplicateSameParams632=== PAUSE TestGCTaskStore_DeduplicateSameParams633=== RUN TestGCTaskStore_ConflictDifferentParams634=== PAUSE TestGCTaskStore_ConflictDifferentParams635=== RUN TestGCTaskStore_GetEmpty636=== PAUSE TestGCTaskStore_GetEmpty637=== RUN TestGCTaskStore_GetReturnsLatest638=== PAUSE TestGCTaskStore_GetReturnsLatest639=== RUN TestGCTaskStore_CompletedAllowsNewTask640=== PAUSE TestGCTaskStore_CompletedAllowsNewTask641=== RUN TestGCTaskStore_PhaseUpdates642=== PAUSE TestGCTaskStore_PhaseUpdates643=== RUN TestGCTaskStore_Fail644=== PAUSE TestGCTaskStore_Fail645=== RUN TestGracefulShutdownDrainsInflight646=== PAUSE TestGracefulShutdownDrainsInflight647=== RUN TestService_healthCheckHandler648=== PAUSE TestService_healthCheckHandler649=== RUN TestService_readinessHandler650=== PAUSE TestService_readinessHandler651=== RUN TestGenerateLandingPage652=== PAUSE TestGenerateLandingPage653=== RUN TestCacheConfigHandlerMaxNarSize654=== PAUSE TestCacheConfigHandlerMaxNarSize655=== RUN TestCreatePendingClosureRejectsOversizedNAR656=== PAUSE TestCreatePendingClosureRejectsOversizedNAR657=== RUN TestNARDeduplicationMetadataUploadBug658=== PAUSE TestNARDeduplicationMetadataUploadBug659=== RUN TestMetricsInventory660=== PAUSE TestMetricsInventory661=== RUN TestMetricsCommit662=== PAUSE TestMetricsCommit663=== RUN TestService_NativeMTLS664=== PAUSE TestService_NativeMTLS665=== RUN TestServerTLSConfig666=== PAUSE TestServerTLSConfig667=== RUN TestMultipartCleanup668=== PAUSE TestMultipartCleanup669=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded670=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded671=== RUN TestPendingCleanupUsesOneCutoff672=== PAUSE TestPendingCleanupUsesOneCutoff673=== RUN TestObjectStatsTrigger674=== PAUSE TestObjectStatsTrigger675=== RUN TestObjectStatsUpdatedOncePerCommit676=== PAUSE TestObjectStatsUpdatedOncePerCommit677=== RUN TestOrphanedObjectsGC678=== PAUSE TestOrphanedObjectsGC679=== RUN TestOrphanedObjectsGCStressTest680=== PAUSE TestOrphanedObjectsGCStressTest681=== RUN TestCreatePin_ReservedPins682=== PAUSE TestCreatePin_ReservedPins683=== RUN TestPresentReportsOnlyClosureRoots684=== PAUSE TestPresentReportsOnlyClosureRoots685=== RUN TestPresentRefreshesOnlyStaleClosures686=== PAUSE TestPresentRefreshesOnlyStaleClosures687=== RUN TestPresentNotReportedWhileGCDeletesClosure688=== PAUSE TestPresentNotReportedWhileGCDeletesClosure689=== RUN TestParseSingleRange690=== PAUSE TestParseSingleRange691=== RUN TestProxyHeadersOnlyTrustedOnSocket6922026/11/01 16:18:56 INFO Starting HTTP server address=proxy.sock6932026/11/01 16:18:56 INFO Starting HTTP server address=127.0.0.1:350536942026/11/01 16:18:56 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6952026/11/01 16:18:56 INFO Shutdown signal received, draining in-flight requests timeout=10s696--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.20s)697=== RUN TestIsValidCachePath698=== PAUSE TestIsValidCachePath699=== RUN TestReadProxyNarinfo700=== PAUSE TestReadProxyNarinfo701=== RUN TestReadProxyNarinfoAlreadyDecompressed702=== PAUSE TestReadProxyNarinfoAlreadyDecompressed703=== RUN TestReadProxyContentNegotiation704=== PAUSE TestReadProxyContentNegotiation705=== RUN TestReadProxyNarStreaming706=== PAUSE TestReadProxyNarStreaming707=== RUN TestReadProxy404708=== PAUSE TestReadProxy404709=== RUN TestReadProxyInvalidPath710=== PAUSE TestReadProxyInvalidPath711=== RUN TestReadProxyHead712=== PAUSE TestReadProxyHead713=== RUN TestReadProxyOutlastsServerWriteTimeout714=== PAUSE TestReadProxyOutlastsServerWriteTimeout715=== RUN TestReadProxyConditionalGet716=== PAUSE TestReadProxyConditionalGet717=== RUN TestReadProxyRootRedirectsToIndexHTML718=== PAUSE TestReadProxyRootRedirectsToIndexHTML719=== RUN TestReadProxyDisabled720=== PAUSE TestReadProxyDisabled721=== RUN TestReadRedirectNar722=== PAUSE TestReadRedirectNar723=== RUN TestReadRedirectKeepsNarinfoProxied724=== PAUSE TestReadRedirectKeepsNarinfoProxied725=== RUN TestReadProxyRangeRequest726=== PAUSE TestReadProxyRangeRequest727=== RUN TestReadRedirectUsesPublicS3URL728=== PAUSE TestReadRedirectUsesPublicS3URL729=== RUN TestPush_OverlappingRootsStoreOneRowPerKey730=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey731=== RUN TestPush_CompleteCommitsEveryRoot732=== PAUSE TestPush_CompleteCommitsEveryRoot733=== RUN TestPush_RepeatedRootCommitsOnce734=== PAUSE TestPush_RepeatedRootCommitsOnce735=== RUN TestPush_CompleteWaitsForCleanupOfThePush736=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush737=== RUN TestPush_RootsAreLockedInByteOrder738=== PAUSE TestPush_RootsAreLockedInByteOrder739=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit740=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit741=== RUN TestPush_RejectsBadRequests742=== PAUSE TestPush_RejectsBadRequests743=== RUN TestPush_SignsNarinfosOfItsPendingObjects744=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects745=== RUN TestRedundantMultipartUpload746=== PAUSE TestRedundantMultipartUpload747=== RUN TestCompleteMultipartUpload_ErrorButObjectExists748=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists749=== RUN TestCompletedNarNotReofferedAcrossClosures750=== PAUSE TestCompletedNarNotReofferedAcrossClosures751=== RUN TestPresignedUploadRegisteredBeforeCommit752=== PAUSE TestPresignedUploadRegisteredBeforeCommit753=== RUN TestService_Rustfstest754=== PAUSE TestService_Rustfstest755=== RUN TestParseSize756=== PAUSE TestParseSize757=== RUN TestSkippedUploadsHandler758=== PAUSE TestSkippedUploadsHandler759=== RUN TestSystemdListenerNotActivated760--- PASS: TestSystemdListenerNotActivated (0.00s)761=== RUN TestWatchdogBeatsWhenHealthy762--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)763=== RUN TestWatchdogSkipsWhenUnhealthy7642026/11/01 16:18:56 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7652026/11/01 16:18:56 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7662026/11/01 16:18:56 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7672026/11/01 16:18:56 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7682026/11/01 16:18:56 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7692026/11/01 16:18:56 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/11/01 16:18:56 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/11/01 16:18:56 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/11/01 16:18:56 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/11/01 16:18:56 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"774--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)775=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle776=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle777=== RUN TestProxyWriteTimeout778=== PAUSE TestProxyWriteTimeout779=== RUN TestPendingClosureWriteTimeout780=== PAUSE TestPendingClosureWriteTimeout781=== RUN TestIsValidUploadKey782=== PAUSE TestIsValidUploadKey783=== RUN TestUploadHandlersRejectInvalidKeys784=== PAUSE TestUploadHandlersRejectInvalidKeys785=== RUN TestUploadHandlersRejectOversizedBody786=== PAUSE TestUploadHandlersRejectOversizedBody787=== RUN TestService_cleanupPendingClosuresHandler788=== PAUSE TestService_cleanupPendingClosuresHandler789=== RUN TestService_createPendingClosureHandler790=== PAUSE TestService_createPendingClosureHandler791=== RUN TestService_verifyS3Integrity792=== PAUSE TestService_verifyS3Integrity793=== RUN TestCompleteMultipartUnregistered794=== PAUSE TestCompleteMultipartUnregistered795=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT796=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT797=== CONT TestService_AuthMiddleware798=== CONT TestMetricsInventory799=== CONT TestDeduplicatedObjectsRecordedAsPending800=== CONT TestNARDeduplicationMetadataUploadBug801=== CONT TestCreatePendingClosureRejectsOversizedNAR802=== CONT TestCacheConfigHandlerMaxNarSize8032026/11/01 16:18:56 INFO Received uploads request method=POST path=/api/pending_closures804=== CONT TestGenerateLandingPage805=== CONT TestService_readinessHandler806=== CONT TestService_healthCheckHandler807=== CONT TestGracefulShutdownDrainsInflight808=== CONT TestGCTaskStore_Fail809=== CONT TestPushDedupSurvivesConcurrentGC810=== CONT TestGCTaskStore_PhaseUpdates811=== CONT TestFailedS3DeleteKeepsTombstone8122026/11/01 16:18:56 INFO Starting HTTP server address=127.0.0.1:40665813=== CONT TestGCTaskStore_CompletedAllowsNewTask814=== CONT TestGCTaskStore_GetReturnsLatest815=== CONT TestGCTaskStore_GetEmpty816=== CONT TestGCTaskStore_ConflictDifferentParams817=== CONT TestGCTaskStore_DeduplicateSameParams818=== CONT TestGCTaskStore_StartNew819=== CONT TestGCEndsOnShutdown820=== CONT TestCommitRacingPendingCleanupKeepsObjects821=== CONT TestPushWaitsForSweepHoldingRow822=== CONT TestSweepRechecksPendingAfterLocking823=== CONT TestGetExistingObjectsLocksRows824=== CONT TestPinProtectsFromGC825--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)826=== CONT TestRegisterCompletedObjectNeedsPendingRow827=== CONT TestSweepSkipsRowsLockedByPush828=== CONT TestGCMetrics8292026/11/01 16:18:56 INFO Shutdown signal received, draining in-flight requests timeout=10s830--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)831--- PASS: TestGCTaskStore_Fail (0.00s)832--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)833--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)834--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)835--- PASS: TestGCTaskStore_GetEmpty (0.00s)836--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)837--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)838--- PASS: TestGCTaskStore_StartNew (0.00s)839=== CONT TestForceGCDuringPushOffersSweptObject840=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows841=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows842=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check843=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check844=== CONT TestGCBugBareHashReferences845=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection846=== CONT TestGCAdvisoryLockBlocksConcurrentRun847=== CONT TestLeadEndsOnShutdown848=== CONT TestGCSweepDeliversEachKeyOnce849=== RUN TestGCEndsOnShutdown/before_the_run850=== PAUSE TestGCEndsOnShutdown/before_the_run851=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete852=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete853=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark854=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark855=== CONT TestTombstonedObjectOfferedWithoutWaiting856--- PASS: TestGenerateLandingPage (0.01s)857=== CONT TestLeadIncumbentAnnouncesAtOnce858--- PASS: TestGracefulShutdownDrainsInflight (0.07s)859=== CONT TestGCSweepSkipsPendingObjects8602026/11/01 16:18:57 WARN readiness check failed error="closed pool"861--- PASS: TestService_readinessHandler (0.27s)862=== CONT TestLeadElectsOneAndHandsOver8632026/11/01 16:18:57 INFO Received uploads request method=POST path=/api/pending_closures864--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.32s)865=== CONT TestConnectWaitsForAPeerMigration8662026/11/01 16:18:57 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"867--- PASS: TestService_AuthMiddleware (0.33s)868=== CONT TestReadRedirectKeepsNarinfoProxied869=== NAME TestNARDeduplicationMetadataUploadBug870 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug2148381510/001/store/fwvhls5gfwac7qh01xiy7hlkd67i9la0-file1.txt871--- PASS: TestMetricsInventory (0.38s)872=== CONT TestResolveDBConnectionString873=== RUN TestResolveDBConnectionString/flag_wins874=== PAUSE TestResolveDBConnectionString/flag_wins875=== RUN TestResolveDBConnectionString/file_when_flag_empty876=== PAUSE TestResolveDBConnectionString/file_when_flag_empty877=== RUN TestResolveDBConnectionString/missing_file_is_an_error878=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error879=== RUN TestResolveDBConnectionString/PGHOST_allows_empty880=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty881=== RUN TestResolveDBConnectionString/nothing_configured882=== PAUSE TestResolveDBConnectionString/nothing_configured883=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock8842026/11/01 16:18:57 INFO Received uploads request method=POST path=/api/pending_closures8852026/11/01 16:18:57 INFO Aborted multipart uploads count=0 kept=08862026/11/01 16:18:57 WARN Force mode enabled - objects will be deleted immediately without grace period8872026/11/01 16:18:57 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=08882026/11/01 16:18:57 INFO Vacuumed table table=pending_closures8892026/11/01 16:18:57 INFO Vacuumed table table=pending_objects8902026/11/01 16:18:57 INFO Vacuumed table table=multipart_uploads8912026/11/01 16:18:57 INFO Vacuumed table table=closures8922026/11/01 16:18:57 INFO Received push request method=POST path=/api/pushes8932026/11/01 16:18:57 INFO Vacuumed table table=objects894--- PASS: TestService_healthCheckHandler (0.44s)895=== CONT TestDeleteClosuresRacingPins896--- PASS: TestGCMetrics (0.44s)897=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT8982026/11/01 16:18:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8992026/11/01 16:18:57 INFO Uploading fwvhls5gfwac7qh01xiy7hlkd67i9la0-file1.txt (160B)9002026/11/01 16:18:57 WARN Failed to register uploaded object key=fwvhls5gfwac7qh01xiy7hlkd67i9la0.ls error="server returned 404: 404 page not found\n"901=== NAME TestPinProtectsFromGC902 client_integration_test.go:778: Pinned store path: /build/TestPinProtectsFromGC2707395788/001/store/1xfy07s83flxakfdlw7cn0lr74lqfcwc-pinned-file.txt903 client_integration_test.go:779: Unpinned store path: /build/TestPinProtectsFromGC2707395788/001/store/rksh0f2cbs2s3yhyizjld8yd9lgqdsia-unpinned-file.txt9042026/11/01 16:18:57 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"9052026/11/01 16:18:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9062026/11/01 16:18:57 INFO Signed narinfos id=1 count=19072026/11/01 16:18:57 INFO Uploading 1 narinfos9082026/11/01 16:18:57 INFO Received uploads request method=POST path=/api/pending_closures9092026/11/01 16:18:57 INFO Received complete push request method=POST path=/api/pushes/1/complete9102026/11/01 16:18:57 WARN Failed to register uploaded object key=fwvhls5gfwac7qh01xiy7hlkd67i9la0.narinfo error="server returned 404: 404 page not found\n"9112026/11/01 16:18:57 INFO Completed push id=1 objects=3 duration=5.991718ms9122026/11/01 16:18:57 INFO Upload complete. (77ms)913=== NAME TestNARDeduplicationMetadataUploadBug914 metadata_upload_test.go:54: Retrieved narinfo from S3:915 StorePath: /build/TestNARDeduplicationMetadataUploadBug2148381510/001/store/fwvhls5gfwac7qh01xiy7hlkd67i9la0-file1.txt916 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst917 Compression: zstd918 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf919 NarSize: 160920 References: 921 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf922 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)923 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):924 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}9252026/11/01 16:18:57 INFO Aborted multipart uploads count=0 kept=09262026/11/01 16:18:57 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=09272026/11/01 16:18:57 INFO Vacuumed table table=pending_closures9282026/11/01 16:18:57 INFO Vacuumed table table=pending_objects9292026/11/01 16:18:57 INFO Vacuumed table table=multipart_uploads9302026/11/01 16:18:57 INFO Aborted multipart uploads count=0 kept=09312026/11/01 16:18:57 WARN Force mode enabled - objects will be deleted immediately without grace period9322026/11/01 16:18:57 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=09332026/11/01 16:18:57 INFO Vacuumed table table=pending_closures9342026/11/01 16:18:57 INFO Vacuumed table table=closures9352026/11/01 16:18:57 INFO Vacuumed table table=pending_objects9362026/11/01 16:18:57 INFO Vacuumed table table=multipart_uploads9372026/11/01 16:18:57 INFO Vacuumed table table=closures9382026/11/01 16:18:57 INFO Vacuumed table table=objects9392026/11/01 16:18:57 INFO Vacuumed table table=objects9402026/11/01 16:18:57 INFO lead: acquired remote=192.0.2.1:1234941 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug2148381510/001/store/yksw5b95ndwf2nfa8ad2gpb8rvxcv7ik-file2.txt9422026/11/01 16:18:57 INFO Aborted multipart uploads count=0 kept=09432026/11/01 16:18:57 WARN Force mode enabled - objects will be deleted immediately without grace period9442026/11/01 16:18:57 INFO Aborted multipart uploads count=0 kept=09452026/11/01 16:18:57 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=09462026/11/01 16:18:57 INFO Vacuumed table table=pending_closures9472026/11/01 16:18:57 WARN Force mode enabled - objects will be deleted immediately without grace period9482026/11/01 16:18:57 INFO Vacuumed table table=pending_objects9492026/11/01 16:18:57 INFO Vacuumed table table=multipart_uploads9502026/11/01 16:18:57 INFO Received push request method=POST path=/api/pushes9512026/11/01 16:18:57 INFO Vacuumed table table=closures9522026/11/01 16:18:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9532026/11/01 16:18:57 INFO Vacuumed table table=objects9542026/11/01 16:18:57 INFO Uploading 1xfy07s83flxakfdlw7cn0lr74lqfcwc-pinned-file.txt (128B)955--- PASS: TestPushDedupSurvivesConcurrentGC (0.54s)956=== CONT TestClientFallsBackToClosures9572026/11/01 16:18:57 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"9582026/11/01 16:18:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9592026/11/01 16:18:57 INFO Signed narinfos id=1 count=19602026/11/01 16:18:57 WARN Failed to register uploaded object key=1xfy07s83flxakfdlw7cn0lr74lqfcwc.ls error="server returned 404: 404 page not found\n"9612026/11/01 16:18:57 INFO Uploading 1 narinfos9622026/11/01 16:18:57 INFO Received complete push request method=POST path=/api/pushes/1/complete9632026/11/01 16:18:57 WARN Failed to register uploaded object key=1xfy07s83flxakfdlw7cn0lr74lqfcwc.narinfo error="server returned 404: 404 page not found\n"9642026/11/01 16:18:57 INFO Completed push id=1 objects=3 duration=14.174564ms9652026/11/01 16:18:57 INFO Upload complete. (88ms)9662026/11/01 16:18:57 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=09672026/11/01 16:18:57 INFO Vacuumed table table=pending_closures9682026/11/01 16:18:57 INFO Vacuumed table table=pending_objects9692026/11/01 16:18:57 INFO Vacuumed table table=multipart_uploads9702026/11/01 16:18:57 INFO Vacuumed table table=closures9712026/11/01 16:18:57 INFO Vacuumed table table=objects972--- PASS: TestSweepSkipsRowsLockedByPush (0.60s)973=== CONT TestCompleteMultipartUnregistered9742026/11/01 16:18:57 INFO Received push request method=POST path=/api/pushes9752026/11/01 16:18:57 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)9762026/11/01 16:18:57 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign9772026/11/01 16:18:57 INFO Signed narinfos id=2 count=19782026/11/01 16:18:57 WARN Failed to register uploaded object key=yksw5b95ndwf2nfa8ad2gpb8rvxcv7ik.ls error="server returned 404: 404 page not found\n"9792026/11/01 16:18:57 INFO Uploading 1 narinfos9802026/11/01 16:18:57 INFO Received complete push request method=POST path=/api/pushes/2/complete9812026/11/01 16:18:57 WARN Failed to register uploaded object key=yksw5b95ndwf2nfa8ad2gpb8rvxcv7ik.narinfo error="server returned 404: 404 page not found\n"9822026/11/01 16:18:57 INFO Completed push id=2 objects=3 duration=2.114749ms9832026/11/01 16:18:57 INFO Upload complete. (63ms)9842026/11/01 16:18:57 INFO Received uploads request method=POST path=/api/pending_closures985=== NAME TestNARDeduplicationMetadataUploadBug986 metadata_upload_test.go:76: Retrieved narinfo from S3:987 StorePath: /build/TestNARDeduplicationMetadataUploadBug2148381510/001/store/yksw5b95ndwf2nfa8ad2gpb8rvxcv7ik-file2.txt988 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst989 Compression: zstd990 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf991 NarSize: 160992 References: 993 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf994 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)995 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):996 {"version":1,"root":{"type":"regular","size":44}}997--- PASS: TestNARDeduplicationMetadataUploadBug (0.64s)998=== CONT TestClientPushesUseOnePush9992026/11/01 16:18:57 INFO Aborted multipart uploads count=0 kept=010002026/11/01 16:18:57 INFO Received push request method=POST path=/api/pushes10012026/11/01 16:18:57 WARN Force mode enabled - objects will be deleted immediately without grace period10022026/11/01 16:18:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10032026/11/01 16:18:57 INFO Uploading rksh0f2cbs2s3yhyizjld8yd9lgqdsia-unpinned-file.txt (128B)10042026/11/01 16:18:57 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=010052026/11/01 16:18:57 INFO Vacuumed table table=pending_closures10062026/11/01 16:18:57 WARN Failed to register uploaded object key=rksh0f2cbs2s3yhyizjld8yd9lgqdsia.ls error="server returned 404: 404 page not found\n"10072026/11/01 16:18:57 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign10082026/11/01 16:18:57 INFO Signed narinfos id=2 count=110092026/11/01 16:18:57 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"10102026/11/01 16:18:57 INFO Uploading 1 narinfos10112026/11/01 16:18:57 INFO Vacuumed table table=pending_objects10122026/11/01 16:18:57 INFO Vacuumed table table=multipart_uploads10132026/11/01 16:18:57 INFO Vacuumed table table=closures10142026/11/01 16:18:57 INFO Vacuumed table table=objects10152026/11/01 16:18:57 INFO Received complete push request method=POST path=/api/pushes/2/complete10162026/11/01 16:18:57 WARN Failed to register uploaded object key=rksh0f2cbs2s3yhyizjld8yd9lgqdsia.narinfo error="server returned 404: 404 page not found\n"10172026/11/01 16:18:57 INFO Completed push id=2 objects=3 duration=2.071349ms10182026/11/01 16:18:57 INFO Upload complete. (49ms)1019--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.67s)1020=== CONT TestService_verifyS3Integrity10212026/11/01 16:18:57 INFO Aborted multipart uploads count=0 kept=010222026/11/01 16:18:57 WARN Force mode enabled - objects will be deleted immediately without grace period10232026/11/01 16:18:57 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=010242026/11/01 16:18:57 INFO Starting cleanup of old closures method=DELETE path=/api/closures10252026/11/01 16:18:57 INFO Garbage collection started10262026/11/01 16:18:57 INFO Vacuumed table table=pending_closures10272026/11/01 16:18:57 INFO Vacuumed table table=pending_objects10282026/11/01 16:18:57 INFO Vacuumed table table=multipart_uploads10292026/11/01 16:18:57 INFO Vacuumed table table=closures10302026/11/01 16:18:57 INFO Vacuumed table table=objects1031--- PASS: TestSweepRechecksPendingAfterLocking (0.71s)1032=== CONT TestCompletedNarNotReofferedAcrossClosures10332026/11/01 16:18:57 INFO Aborted multipart uploads count=0 kept=010342026/11/01 16:18:57 WARN Force mode enabled - objects will be deleted immediately without grace period10352026/11/01 16:18:57 INFO Aborted multipart uploads count=0 kept=010362026/11/01 16:18:57 WARN Force mode enabled - objects will be deleted immediately without grace period10372026/11/01 16:18:57 INFO Aborted multipart uploads count=0 kept=010382026/11/01 16:18:57 WARN Force mode enabled - objects will be deleted immediately without grace period10392026/11/01 16:18:57 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."10402026/11/01 16:18:57 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1041--- PASS: TestFailedS3DeleteKeepsTombstone (0.74s)1042=== CONT TestCompleteMultipartUpload_ErrorButObjectExists10432026/11/01 16:18:57 INFO Received uploads request method=POST path=/api/pending_closures10442026/11/01 16:18:57 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=01045--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.75s)1046=== CONT TestService_createPendingClosureHandler10472026/11/01 16:18:57 INFO Vacuumed table table=pending_closures10482026/11/01 16:18:57 INFO lead: acquired remote=192.0.2.1:123410492026/11/01 16:18:57 INFO lead: released remote=192.0.2.1:12341050--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.76s)1051=== CONT TestRedundantMultipartUpload10522026/11/01 16:18:57 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=010532026/11/01 16:18:57 INFO Vacuumed table table=pending_closures10542026/11/01 16:18:57 INFO Vacuumed table table=pending_objects10552026/11/01 16:18:57 INFO Vacuumed table table=multipart_uploads10562026/11/01 16:18:57 INFO Vacuumed table table=closures10572026/11/01 16:18:57 INFO Vacuumed table table=pending_objects10582026/11/01 16:18:57 INFO Vacuumed table table=multipart_uploads10592026/11/01 16:18:57 INFO Vacuumed table table=closures10602026/11/01 16:18:57 INFO Vacuumed table table=objects10612026/11/01 16:18:57 INFO Vacuumed table table=objects1062--- PASS: TestGCSweepDeliversEachKeyOnce (0.78s)1063=== CONT TestService_cleanupPendingClosuresHandler10642026/11/01 16:18:57 INFO Received uploads request method=POST path=/api/pending_closures10652026/11/01 16:18:57 INFO Aborted multipart uploads count=0 kept=010662026/11/01 16:18:57 WARN Force mode enabled - objects will be deleted immediately without grace period10672026/11/01 16:18:57 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=010682026/11/01 16:18:57 INFO Vacuumed table table=pending_closures10692026/11/01 16:18:57 INFO Vacuumed table table=pending_objects10702026/11/01 16:18:57 INFO Vacuumed table table=multipart_uploads10712026/11/01 16:18:57 INFO Vacuumed table table=closures10722026/11/01 16:18:57 INFO Vacuumed table table=objects10732026/11/01 16:18:57 INFO Received uploads request method=POST path=/api/pending_closures1074--- PASS: TestGCSweepSkipsPendingObjects (0.81s)1075=== CONT TestPush_SignsNarinfosOfItsPendingObjects1076--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.89s)1077=== CONT TestUploadHandlersRejectOversizedBody1078--- PASS: TestPushWaitsForSweepHoldingRow (0.99s)1079=== CONT TestPush_RejectsBadRequests1080--- PASS: TestGCBugBareHashReferences (1.00s)1081=== CONT TestUploadHandlersRejectInvalidKeys1082=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1083=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1084=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1085=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1086=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1087=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1088=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1089=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1090--- PASS: TestGetExistingObjectsLocksRows (1.00s)1091=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit1092=== CONT TestPush_RootsAreLockedInByteOrder10932026/11/01 16:18:57 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"1094--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (1.03s)1095=== CONT TestIsValidUploadKey1096=== RUN TestIsValidUploadKey/narinfo1097=== PAUSE TestIsValidUploadKey/narinfo1098=== RUN TestIsValidUploadKey/nar_zst1099=== PAUSE TestIsValidUploadKey/nar_zst1100=== RUN TestIsValidUploadKey/nar_xz1101=== PAUSE TestIsValidUploadKey/nar_xz1102=== RUN TestIsValidUploadKey/nar_plain1103=== PAUSE TestIsValidUploadKey/nar_plain1104=== RUN TestIsValidUploadKey/listing1105=== PAUSE TestIsValidUploadKey/listing1106=== RUN TestIsValidUploadKey/build_log1107=== PAUSE TestIsValidUploadKey/build_log1108=== RUN TestIsValidUploadKey/build_log_home-manager_file1109=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1110=== RUN TestIsValidUploadKey/build_log_plus_in_name1111=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1112=== RUN TestIsValidUploadKey/build_log_question_mark1113=== PAUSE TestIsValidUploadKey/build_log_question_mark1114=== RUN TestIsValidUploadKey/build_log_equals1115=== PAUSE TestIsValidUploadKey/build_log_equals1116=== RUN TestIsValidUploadKey/realisation1117=== PAUSE TestIsValidUploadKey/realisation1118=== RUN TestIsValidUploadKey/realisation_plus_in_output1119=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1120=== RUN TestIsValidUploadKey/nix-cache-info1121=== PAUSE TestIsValidUploadKey/nix-cache-info1122=== RUN TestIsValidUploadKey/index.html1123=== PAUSE TestIsValidUploadKey/index.html1124=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1125=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1126=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1127=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1128=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1129=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1130=== RUN TestIsValidUploadKey/traversal1131=== PAUSE TestIsValidUploadKey/traversal1132=== RUN TestIsValidUploadKey/traversal_nar1133=== PAUSE TestIsValidUploadKey/traversal_nar1134=== RUN TestIsValidUploadKey/absolute1135=== PAUSE TestIsValidUploadKey/absolute1136=== RUN TestIsValidUploadKey/empty_key1137=== PAUSE TestIsValidUploadKey/empty_key1138=== RUN TestIsValidUploadKey/unknown_type1139=== PAUSE TestIsValidUploadKey/unknown_type1140=== CONT TestPush_CompleteWaitsForCleanupOfThePush11412026/11/01 16:18:57 INFO lead: acquired remote=192.0.2.1:12341142=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1143=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1144=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1145=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1146=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1147=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1148=== CONT TestPendingClosureWriteTimeout1149=== RUN TestPendingClosureWriteTimeout/empty1150=== PAUSE TestPendingClosureWriteTimeout/empty1151=== RUN TestPendingClosureWriteTimeout/400_objects1152=== PAUSE TestPendingClosureWriteTimeout/400_objects1153=== RUN TestPendingClosureWriteTimeout/670k_objects1154=== PAUSE TestPendingClosureWriteTimeout/670k_objects1155=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1156=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1157=== CONT TestProxyWriteTimeout1158=== RUN TestProxyWriteTimeout/narinfo1159=== PAUSE TestProxyWriteTimeout/narinfo1160=== RUN TestProxyWriteTimeout/1_GiB_nar1161=== PAUSE TestProxyWriteTimeout/1_GiB_nar1162=== RUN TestProxyWriteTimeout/10_GiB_nar1163=== PAUSE TestProxyWriteTimeout/10_GiB_nar1164=== RUN TestProxyWriteTimeout/unknown_size1165=== PAUSE TestProxyWriteTimeout/unknown_size1166=== CONT TestPush_RepeatedRootCommitsOnce1167--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (1.08s)1168=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1169--- PASS: TestReadRedirectKeepsNarinfoProxied (0.77s)1170=== CONT TestPush_CompleteCommitsEveryRoot11712026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures1172--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.72s)1173=== CONT TestPush_OverlappingRootsStoreOneRowPerKey11742026/11/01 16:18:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11752026/11/01 16:18:58 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1176--- PASS: TestCompleteMultipartUnregistered (0.61s)1177=== CONT TestSkippedUploadsHandler11782026/11/01 16:18:58 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001179--- PASS: TestSkippedUploadsHandler (0.00s)1180=== CONT TestReadRedirectUsesPublicS3URL11812026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures11822026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures11832026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures1184--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.93s)1185=== CONT TestReadProxyRangeRequest11862026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures11872026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures11882026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures11892026/11/01 16:18:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11902026/11/01 16:18:58 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NTMzOTg2NGUtOTM1ZC00N2M5LTk4YTctNWFlOTViN2JlYjBiLmIyYTM0M2FiLTk5M2ItNGY5YS1iOGUyLTMxNjZlNjBlYzkyNHgxNzkzNTQ5OTM4MjE5NTk2MDYz11912026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures11922026/11/01 16:18:58 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NTMzOTg2NGUtOTM1ZC00N2M5LTk4YTctNWFlOTViN2JlYjBiLmIyYTM0M2FiLTk5M2ItNGY5YS1iOGUyLTMxNjZlNjBlYzkyNHgxNzkzNTQ5OTM4MjE5NTk2MDYz parts=11193--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.61s)1194=== CONT TestParseSize1195--- PASS: TestParseSize (0.00s)1196=== CONT TestPresignedUploadRegisteredBeforeCommit11972026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures11982026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures11992026/11/01 16:18:58 INFO Received push request method=POST path=/api/pushes12002026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures12012026/11/01 16:18:58 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)12022026/11/01 16:18:58 INFO Uploading 7pqz7l3h9avi0h43pnwny6pkxh8anhpi-shared-dep (136B)12032026/11/01 16:18:58 INFO Uploading wb9ay1ln75ll97la06wg0w04a52x2g80-b (216B)12042026/11/01 16:18:58 WARN Failed to register uploaded object key=qq0cqmcpkislgdqc7dd2yq5adj116dbb.ls error="server returned 404: 404 page not found\n"12052026/11/01 16:18:58 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12062026/11/01 16:18:58 INFO Signed narinfos id=1 count=112072026/11/01 16:18:58 WARN Failed to register uploaded object key=7pqz7l3h9avi0h43pnwny6pkxh8anhpi.ls error="server returned 404: 404 page not found\n"12082026/11/01 16:18:58 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12092026/11/01 16:18:58 WARN Failed to register uploaded object key=wb9ay1ln75ll97la06wg0w04a52x2g80.ls error="server returned 404: 404 page not found\n"12102026/11/01 16:18:58 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12112026/11/01 16:18:58 WARN Failed to register uploaded object key=nar/0lfdxa10iji9q8y7mr7g151gwypcyrxg91n01fnhlv337i92xsg4.nar.zst error="server returned 404: 404 page not found\n"12122026/11/01 16:18:58 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12132026/11/01 16:18:58 INFO Signed narinfos id=1 count=212142026/11/01 16:18:58 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12152026/11/01 16:18:58 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"12162026/11/01 16:18:58 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12172026/11/01 16:18:58 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12182026/11/01 16:18:58 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"12192026/11/01 16:18:58 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12202026/11/01 16:18:58 INFO Signed narinfos id=2 count=212212026/11/01 16:18:58 INFO Uploading 4 narinfos12222026/11/01 16:18:58 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=112232026/11/01 16:18:58 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12242026/11/01 16:18:58 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1225--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.50s)1226=== CONT TestService_Rustfstest12272026/11/01 16:18:58 WARN Failed to register uploaded object key=qq0cqmcpkislgdqc7dd2yq5adj116dbb.narinfo error="server returned 404: 404 page not found\n"12282026/11/01 16:18:58 WARN Failed to register uploaded object key=wb9ay1ln75ll97la06wg0w04a52x2g80.narinfo error="server returned 404: 404 page not found\n"12292026/11/01 16:18:58 WARN Failed to register uploaded object key=7pqz7l3h9avi0h43pnwny6pkxh8anhpi.narinfo error="server returned 404: 404 page not found\n"12302026/11/01 16:18:58 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12312026/11/01 16:18:58 WARN Failed to register uploaded object key=7pqz7l3h9avi0h43pnwny6pkxh8anhpi.narinfo error="server returned 404: 404 page not found\n"12322026/11/01 16:18:58 INFO Received cleanup request method=DELETE path=/api/pending_closures12332026/11/01 16:18:58 INFO Completed upload id=1 objects=6 duration=4.761848ms12342026/11/01 16:18:58 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12352026/11/01 16:18:58 INFO Aborted multipart uploads count=0 kept=012362026/11/01 16:18:58 INFO Completed upload id=2 objects=6 duration=1.205069ms12372026/11/01 16:18:58 INFO Upload complete. (70ms)1238=== NAME TestClientFallsBackToClosures1239 client_pushes_test.go:112: Retrieved narinfo from S3:1240 StorePath: /build/TestClientFallsBackToClosures3581805792/001/store/7pqz7l3h9avi0h43pnwny6pkxh8anhpi-shared-dep1241 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1242 Compression: zstd1243 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821244 NarSize: 1361245 References: 1246 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1247 client_pushes_test.go:112: Retrieved narinfo from S3:1248 StorePath: /build/TestClientFallsBackToClosures3581805792/001/store/qq0cqmcpkislgdqc7dd2yq5adj116dbb-a1249 URL: nar/0lfdxa10iji9q8y7mr7g151gwypcyrxg91n01fnhlv337i92xsg4.nar.zst1250 Compression: zstd1251 NarHash: sha256:0lfdxa10iji9q8y7mr7g151gwypcyrxg91n01fnhlv337i92xsg41252 NarSize: 2161253 References: /build/TestClientFallsBackToClosures3581805792/001/store/7pqz7l3h9avi0h43pnwny6pkxh8anhpi-shared-dep1254 CA: text:sha256:0y4xlyhs2qx1421466gkwh2vaaydn40hhl1arswqnp1fx0qf1sbn1255 client_pushes_test.go:112: Retrieved narinfo from S3:1256 StorePath: /build/TestClientFallsBackToClosures3581805792/001/store/wb9ay1ln75ll97la06wg0w04a52x2g80-b1257 URL: nar/0lfdxa10iji9q8y7mr7g151gwypcyrxg91n01fnhlv337i92xsg4.nar.zst1258 Compression: zstd1259 NarHash: sha256:0lfdxa10iji9q8y7mr7g151gwypcyrxg91n01fnhlv337i92xsg412602026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures1261 NarSize: 2161262 References: /build/TestClientFallsBackToClosures3581805792/001/store/7pqz7l3h9avi0h43pnwny6pkxh8anhpi-shared-dep1263 CA: text:sha256:0y4xlyhs2qx1421466gkwh2vaaydn40hhl1arswqnp1fx0qf1sbn1264--- PASS: TestClientFallsBackToClosures (0.86s)1265=== CONT TestClientMultipleUploads12662026/11/01 16:18:58 INFO Received cleanup request method=DELETE path=/api/pending_closures12672026/11/01 16:18:58 INFO Received push request method=POST path=/api/pushes12682026/11/01 16:18:58 INFO Aborted multipart uploads count=1 kept=012692026/11/01 16:18:58 INFO Received push request method=POST path=/api/pushes12702026/11/01 16:18:58 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12712026-11-01 16:18:58.325 UTC [714] ERROR: Closure does not exist: id=112722026-11-01 16:18:58.325 UTC [714] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE12732026-11-01 16:18:58.325 UTC [714] STATEMENT: -- name: CommitPendingClosure :one1274 SELECT commit_pending_closure($1::bigint)::bigint1275 1276--- PASS: TestService_cleanupPendingClosuresHandler (0.64s)1277=== CONT TestClientWithDependencies12782026/11/01 16:18:58 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)12792026/11/01 16:18:58 INFO Uploading 7z6dadrpswzs5043vcr53aqyljvihpj7-shared-dep (136B)12802026/11/01 16:18:58 INFO Uploading msvszd75qi8rnx7a0hzag0xsmjyddnq9-b (216B)12812026/11/01 16:18:58 WARN Failed to register uploaded object key=gha48zhjjcw0qxmylajb6xz7gidzwxyr.ls error="server returned 404: 404 page not found\n"12822026/11/01 16:18:58 WARN Failed to register uploaded object key=msvszd75qi8rnx7a0hzag0xsmjyddnq9.ls error="server returned 404: 404 page not found\n"12832026/11/01 16:18:58 WARN Failed to register uploaded object key=7z6dadrpswzs5043vcr53aqyljvihpj7.ls error="server returned 404: 404 page not found\n"12842026/11/01 16:18:58 WARN Failed to register uploaded object key=nar/0afq7z09aah1w5s8n3vfy42ck990zbc0h8lnpyz62j978861s44n.nar.zst error="server returned 404: 404 page not found\n"12852026/11/01 16:18:58 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12862026/11/01 16:18:58 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12872026/11/01 16:18:58 INFO Signed narinfos id=1 count=312882026/11/01 16:18:58 INFO Uploading 3 narinfos12892026/11/01 16:18:58 WARN Failed to register uploaded object key=msvszd75qi8rnx7a0hzag0xsmjyddnq9.narinfo error="server returned 404: 404 page not found\n"12902026/11/01 16:18:58 INFO Received complete push request method=POST path=/api/pushes/1/complete12912026/11/01 16:18:58 WARN Failed to register uploaded object key=gha48zhjjcw0qxmylajb6xz7gidzwxyr.narinfo error="server returned 404: 404 page not found\n"12922026/11/01 16:18:58 WARN Failed to register uploaded object key=7z6dadrpswzs5043vcr53aqyljvihpj7.narinfo error="server returned 404: 404 page not found\n"12932026/11/01 16:18:58 INFO Received complete push request method=POST path=/api/pushes/1/complete12942026/11/01 16:18:58 INFO Received push request method=POST path=/api/pushes12952026/11/01 16:18:58 INFO Completed push id=1 objects=8 duration=9.749416ms12962026/11/01 16:18:58 INFO Upload complete. (65ms)1297=== NAME TestClientPushesUseOnePush1298 client_pushes_test.go:97: Retrieved narinfo from S3:1299 StorePath: /build/TestClientPushesUseOnePush1760306628/001/store/7z6dadrpswzs5043vcr53aqyljvihpj7-shared-dep1300 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1301 Compression: zstd1302 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821303 NarSize: 1361304 References: 1305 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n13062026/11/01 16:18:58 INFO Completed push id=1 objects=4 duration=7.422457ms13072026/11/01 16:18:58 INFO Received push request method=POST path=/api/pushes1308 client_pushes_test.go:97: Retrieved narinfo from S3:1309 StorePath: /build/TestClientPushesUseOnePush1760306628/001/store/gha48zhjjcw0qxmylajb6xz7gidzwxyr-a1310 URL: nar/0afq7z09aah1w5s8n3vfy42ck990zbc0h8lnpyz62j978861s44n.nar.zst1311 Compression: zstd1312 NarHash: sha256:0afq7z09aah1w5s8n3vfy42ck990zbc0h8lnpyz62j978861s44n1313 NarSize: 2161314 References: /build/TestClientPushesUseOnePush1760306628/001/store/7z6dadrpswzs5043vcr53aqyljvihpj7-shared-dep1315 CA: text:sha256:0lp1wxzh6dghcv0i3p4vlq2ws6wq75vcvc3wiyi38ikksix9xk7r1316 client_pushes_test.go:97: Retrieved narinfo from S3:1317 StorePath: /build/TestClientPushesUseOnePush1760306628/001/store/msvszd75qi8rnx7a0hzag0xsmjyddnq9-b1318 URL: nar/0afq7z09aah1w5s8n3vfy42ck990zbc0h8lnpyz62j978861s44n.nar.zst1319 Compression: zstd1320 NarHash: sha256:0afq7z09aah1w5s8n3vfy42ck990zbc0h8lnpyz62j978861s44n1321 NarSize: 2161322 References: /build/TestClientPushesUseOnePush1760306628/001/store/7z6dadrpswzs5043vcr53aqyljvihpj7-shared-dep1323 CA: text:sha256:0lp1wxzh6dghcv0i3p4vlq2ws6wq75vcvc3wiyi38ikksix9xk7r1324--- PASS: TestClientPushesUseOnePush (0.82s)1325=== CONT TestClientSharedPathCommittedMidPush1326=== RUN TestPush_RejectsBadRequests/root_not_in_objects1327=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1328=== RUN TestPush_RejectsBadRequests/no_roots1329=== PAUSE TestPush_RejectsBadRequests/no_roots1330=== RUN TestPush_RejectsBadRequests/no_objects1331=== PAUSE TestPush_RejectsBadRequests/no_objects1332=== RUN TestPush_RejectsBadRequests/bad_root1333=== PAUSE TestPush_RejectsBadRequests/bad_root1334=== CONT TestService_AuthMiddleware_OIDC13352026/11/01 16:18:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34441/oidc13362026/11/01 16:18:58 INFO Received push request method=POST path=/api/pushes13372026-11-01 16:18:58.394 UTC [957] ERROR: could not obtain lock on row in relation "closures"13382026-11-01 16:18:58.394 UTC [957] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13392026-11-01 16:18:58.394 UTC [957] ERROR: could not obtain lock on row in relation "closures"13402026-11-01 16:18:58.394 UTC [957] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13412026-11-01 16:18:58.394 UTC [957] ERROR: could not obtain lock on row in relation "closures"13422026-11-01 16:18:58.394 UTC [957] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13432026-11-01 16:18:58.395 UTC [957] ERROR: could not obtain lock on row in relation "closures"13442026-11-01 16:18:58.395 UTC [957] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13452026-11-01 16:18:58.395 UTC [957] ERROR: could not obtain lock on row in relation "closures"13462026-11-01 16:18:58.395 UTC [957] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1347--- PASS: TestPush_RootsAreLockedInByteOrder (0.49s)1348=== CONT TestService_ReadScope_PublicByDefault13492026/11/01 16:18:58 INFO Aborted multipart uploads count=0 kept=013502026/11/01 16:18:58 WARN Force mode enabled - objects will be deleted immediately without grace period13512026/11/01 16:18:58 INFO Received push request method=POST path=/api/pushes13522026/11/01 16:18:58 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=013532026/11/01 16:18:58 INFO Vacuumed table table=pending_closures13542026/11/01 16:18:58 INFO Vacuumed table table=pending_objects13552026/11/01 16:18:58 INFO Vacuumed table table=multipart_uploads13562026/11/01 16:18:58 INFO Received complete push request method=POST path=/api/pushes/1/complete13572026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures13582026/11/01 16:18:58 INFO Vacuumed table table=closures13592026/11/01 16:18:58 INFO Vacuumed table table=objects13602026/11/01 16:18:58 INFO Received complete push request method=POST path=/api/pushes/2/complete13612026/11/01 16:18:58 INFO Completed push id=1 objects=4 duration=8.546066ms1362--- PASS: TestPush_RepeatedRootCommitsOnce (0.49s)1363=== CONT TestService_RequireScope_OIDC13642026/11/01 16:18:58 INFO Completed push id=2 objects=4 duration=4.607898ms1365--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.55s)1366=== CONT TestCacheConfigHandler1367=== RUN TestCacheConfigHandler/full_config,_no_issuer1368=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1369=== RUN TestCacheConfigHandler/no_cache_url_configured1370=== PAUSE TestCacheConfigHandler/no_cache_url_configured1371=== RUN TestCacheConfigHandler/no_signing_keys1372=== PAUSE TestCacheConfigHandler/no_signing_keys1373=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1374=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1375=== CONT TestCacheStatsHandler13762026/11/01 16:18:58 INFO Received push request method=POST path=/api/pushes13772026/11/01 16:18:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13782026/11/01 16:18:58 INFO lead: released remote=192.0.2.1:12341379--- PASS: TestLeadEndsOnShutdown (1.57s)1380=== CONT TestService_AuthMiddleware_MTLSBoundSubjects13812026/11/01 16:18:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39055/oidc13822026/11/01 16:18:58 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NTMzOTg2NGUtOTM1ZC00N2M5LTk4YTctNWFlOTViN2JlYjBiLjIzZDgzODY3LTg2OTItNGE0NC1hOGM1LTU5OTgyNWY4NzNlYngxNzkzNTQ5OTM4MTY4NTg5ODk1 parts=1013832026/11/01 16:18:58 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13842026/11/01 16:18:58 INFO Received complete push request method=POST path=/api/pushes/1/complete13852026/11/01 16:18:58 INFO Received push request method=POST path=/api/pushes13862026/11/01 16:18:58 INFO Completed upload id=1 objects=2 duration=4.652438ms13872026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures13882026/11/01 16:18:58 INFO Completed push id=1 objects=6 duration=11.579976ms1389--- PASS: TestPush_CompleteCommitsEveryRoot (0.51s)1390=== CONT TestClientErrorHandling1391=== RUN TestClientErrorHandling/InvalidStorePath1392=== PAUSE TestClientErrorHandling/InvalidStorePath1393=== RUN TestClientErrorHandling/InvalidAuthToken1394=== PAUSE TestClientErrorHandling/InvalidAuthToken1395=== RUN TestClientErrorHandling/ServerNotAvailable1396=== PAUSE TestClientErrorHandling/ServerNotAvailable13972026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures1398=== CONT TestClientCADerivations13992026/11/01 16:18:58 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo14002026/11/01 16:18:58 WARN Found objects in DB but missing from S3, will re-upload count=11401--- PASS: TestService_verifyS3Integrity (0.94s)1402=== CONT TestService_ReadAuthMiddleware14032026/11/01 16:18:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1404--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.46s)1405=== CONT TestClientIntegration14062026/11/01 16:18:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1407--- PASS: TestReadRedirectUsesPublicS3URL (0.42s)1408=== CONT TestService_AuthMiddleware_MTLSProxyHeader14092026/11/01 16:18:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1410--- PASS: TestReadProxyRangeRequest (0.35s)1411=== CONT TestParseSingleRange1412=== RUN TestParseSingleRange/none1413=== PAUSE TestParseSingleRange/none1414=== RUN TestParseSingleRange/unknown_unit1415=== PAUSE TestParseSingleRange/unknown_unit1416=== RUN TestParseSingleRange/multi-range_ignored1417=== PAUSE TestParseSingleRange/multi-range_ignored1418=== RUN TestParseSingleRange/malformed_no_dash1419=== PAUSE TestParseSingleRange/malformed_no_dash1420=== RUN TestParseSingleRange/malformed_both_empty1421=== PAUSE TestParseSingleRange/malformed_both_empty1422=== RUN TestParseSingleRange/malformed_end_before_start1423=== PAUSE TestParseSingleRange/malformed_end_before_start1424=== RUN TestParseSingleRange/closed1425=== PAUSE TestParseSingleRange/closed1426=== RUN TestParseSingleRange/open-ended1427=== PAUSE TestParseSingleRange/open-ended1428=== RUN TestParseSingleRange/end_clamped_to_size1429=== PAUSE TestParseSingleRange/end_clamped_to_size1430=== RUN TestParseSingleRange/suffix1431=== PAUSE TestParseSingleRange/suffix1432=== RUN TestParseSingleRange/suffix_exceeds_size1433=== PAUSE TestParseSingleRange/suffix_exceeds_size14342026/11/01 16:18:58 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NTMzOTg2NGUtOTM1ZC00N2M5LTk4YTctNWFlOTViN2JlYjBiLjliYmUyY2VhLTA4YjItNDc0My1iNjk4LWJiYjQ2NTU3MTY1YXgxNzkzNTQ5OTM4MjM5MTQ3MDY0 parts=101435=== RUN TestParseSingleRange/single_byte14362026/11/01 16:18:58 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1437=== PAUSE TestParseSingleRange/single_byte1438=== RUN TestParseSingleRange/start_past_EOF1439=== PAUSE TestParseSingleRange/start_past_EOF1440=== RUN TestParseSingleRange/start_far_past_EOF1441=== PAUSE TestParseSingleRange/start_far_past_EOF1442=== CONT TestObjectStatsUpdatedOncePerCommit14432026/11/01 16:18:58 INFO Completed upload id=1 objects=2 duration=5.233348ms14442026/11/01 16:18:58 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000014452026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures14462026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures14472026/11/01 16:18:58 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NTMzOTg2NGUtOTM1ZC00N2M5LTk4YTctNWFlOTViN2JlYjBiLmViOWUxYTdhLTRlOTItNGExZC1hN2IwLTVhY2M0NjlkMGYxNngxNzkzNTQ5OTM4MjAwOTIxMjUx parts=1214482026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures14492026/11/01 16:18:58 INFO Starting cleanup of old closures method=DELETE path=/api/closures14502026/11/01 16:18:58 INFO Aborted multipart uploads count=0 kept=01451--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.99s)1452=== CONT TestPresentReportsOnlyClosureRoots14532026/11/01 16:18:58 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=01454--- PASS: TestService_Rustfstest (0.32s)1455=== CONT TestCreatePin_ReservedPins14562026/11/01 16:18:58 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst14572026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures14582026/11/01 16:18:58 INFO Vacuumed table table=pending_closures14592026/11/01 16:18:58 INFO Vacuumed table table=pending_objects1460--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.36s)1461=== CONT TestReadRedirectNar14622026/11/01 16:18:58 INFO Vacuumed table table=multipart_uploads14632026/11/01 16:18:58 INFO Vacuumed table table=closures14642026/11/01 16:18:58 INFO Vacuumed table table=objects14652026/11/01 16:18:58 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001466--- PASS: TestService_createPendingClosureHandler (0.98s)1467=== CONT TestOrphanedObjectsGCStressTest14682026/11/01 16:18:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1469=== NAME TestClientMultipleUploads1470 client_integration_test.go:405: Created store path 0: /build/TestClientMultipleUploads1788272096/001/store/zsrdq5rzbrqjggf18wbcs1rlssrv22n5-test-file-0.txt14712026/11/01 16:18:58 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NTMzOTg2NGUtOTM1ZC00N2M5LTk4YTctNWFlOTViN2JlYjBiLjA5NzBkM2Q4LTg2MzYtNGRmZi1iOWEwLWU1YjZmMTA3MzZkNngxNzkzNTQ5OTM4MjU3MTQ1MDE2 parts=1214722026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures14732026/11/01 16:18:58 INFO Received uploads request method=POST path=/api/pending_closures1474=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1475=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1476=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1477=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1478=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1479=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1480=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1481=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1482=== CONT TestReadProxyDisabled14832026/11/01 16:18:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40801/oidc1484=== NAME TestClientMultipleUploads1485 client_integration_test.go:405: Created store path 1: /build/TestClientMultipleUploads1788272096/001/store/21jkn0sq3if0h8nvi9bv5m2idmrcj51j-test-file-1.txt14862026-11-01 16:18:58.710 UTC [968] ERROR: Push does not exist: id=114872026-11-01 16:18:58.710 UTC [968] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE14882026-11-01 16:18:58.710 UTC [968] STATEMENT: SELECT commit_push($1)1489--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (0.77s)1490=== CONT TestOrphanedObjectsGC1491--- PASS: TestService_ReadScope_PublicByDefault (0.32s)1492=== CONT TestPresentNotReportedWhileGCDeletesClosure1493=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1494=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1495=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1496=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1497=== CONT TestReadProxyRootRedirectsToIndexHTML1498=== NAME TestClientWithDependencies1499 client_integration_test.go:660: Built derivation: /build/TestClientWithDependencies1083837061/001/store/pnj8c06qcyzmczvsv2kl6i53xnhb7dg6-test-script1500=== NAME TestClientMultipleUploads1501 client_integration_test.go:405: Created store path 2: /build/TestClientMultipleUploads1788272096/001/store/rrbdj50hi8kc94ixzaxka0436awvw3fk-test-file-2.txt1502--- PASS: TestCacheStatsHandler (0.31s)1503=== CONT TestPresentRefreshesOnlyStaleClosures1504=== NAME TestClientWithDependencies1505 client_integration_test.go:662: Found 1 dependencies (including self)15062026/11/01 16:18:58 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15072026/11/01 16:18:58 WARN mTLS auth: bound subjects configured but subject DN unavailable15082026/11/01 16:18:58 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1509--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.30s)1510=== CONT TestReadProxy4041511=== RUN TestService_RequireScope_OIDC/builder_may_write1512=== PAUSE TestService_RequireScope_OIDC/builder_may_write1513=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1514=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1515=== RUN TestService_RequireScope_OIDC/ops_may_admin1516=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1517=== RUN TestService_RequireScope_OIDC/ops_may_not_write1518=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1519=== RUN TestService_RequireScope_OIDC/reader_may_not_write1520=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1521=== RUN TestService_RequireScope_OIDC/static_token_may_admin1522=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1523=== RUN TestService_RequireScope_OIDC/static_token_may_write1524=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1525=== RUN TestService_RequireScope_OIDC/reader_may_read1526=== PAUSE TestService_RequireScope_OIDC/reader_may_read1527=== RUN TestService_RequireScope_OIDC/writer_implies_read1528=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1529=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1530=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1531=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1532=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1533=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1534=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1535=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1536=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1537=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1538=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1539=== CONT TestReadProxyNarStreaming15402026/11/01 16:18:58 INFO Received push request method=POST path=/api/pushes15412026/11/01 16:18:58 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)15422026/11/01 16:18:58 INFO Uploading rrbdj50hi8kc94ixzaxka0436awvw3fk-test-file-2.txt (160B)15432026/11/01 16:18:58 INFO Uploading 21jkn0sq3if0h8nvi9bv5m2idmrcj51j-test-file-1.txt (160B)15442026/11/01 16:18:58 INFO Uploading zsrdq5rzbrqjggf18wbcs1rlssrv22n5-test-file-0.txt (160B)15452026/11/01 16:18:58 WARN Failed to register uploaded object key=21jkn0sq3if0h8nvi9bv5m2idmrcj51j.ls error="server returned 404: 404 page not found\n"15462026/11/01 16:18:58 WARN Failed to register uploaded object key=rrbdj50hi8kc94ixzaxka0436awvw3fk.ls error="server returned 404: 404 page not found\n"1547--- PASS: TestService_ReadAuthMiddleware (0.31s)1548=== CONT TestMultipartCleanup15492026/11/01 16:18:58 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"15502026/11/01 16:18:58 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"15512026/11/01 16:18:58 WARN Failed to register uploaded object key=zsrdq5rzbrqjggf18wbcs1rlssrv22n5.ls error="server returned 404: 404 page not found\n"15522026/11/01 16:18:58 INFO Received push request method=POST path=/api/pushes15532026/11/01 16:18:58 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15542026/11/01 16:18:58 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"15552026/11/01 16:18:58 INFO Signed narinfos id=1 count=315562026/11/01 16:18:58 INFO Uploading 3 narinfos15572026/11/01 16:18:58 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)15582026/11/01 16:18:58 INFO Uploading gb1m2c4n2myxk9kga6yydbj3vkf5wfi4-top (224B)15592026/11/01 16:18:58 INFO Uploading mq8ld9d3a9qia4ayqxf8h5lz4vzbbvc2-shared-dep (136B)15602026/11/01 16:18:58 WARN Failed to register uploaded object key=rrbdj50hi8kc94ixzaxka0436awvw3fk.narinfo error="server returned 404: 404 page not found\n"15612026/11/01 16:18:58 WARN Failed to register uploaded object key=21jkn0sq3if0h8nvi9bv5m2idmrcj51j.narinfo error="server returned 404: 404 page not found\n"15622026/11/01 16:18:58 INFO Received complete push request method=POST path=/api/pushes/1/complete15632026/11/01 16:18:58 WARN Failed to register uploaded object key=zsrdq5rzbrqjggf18wbcs1rlssrv22n5.narinfo error="server returned 404: 404 page not found\n"15642026/11/01 16:18:58 INFO Received push request method=POST path=/api/pushes15652026/11/01 16:18:58 WARN Failed to register uploaded object key=mq8ld9d3a9qia4ayqxf8h5lz4vzbbvc2.ls error="server returned 404: 404 page not found\n"15662026/11/01 16:18:58 WARN Failed to register uploaded object key=gb1m2c4n2myxk9kga6yydbj3vkf5wfi4.ls error="server returned 404: 404 page not found\n"15672026/11/01 16:18:58 INFO Completed push id=1 objects=9 duration=6.768617ms15682026/11/01 16:18:58 INFO Upload complete. (64ms)1569=== NAME TestClientMultipleUploads1570 client_integration_test.go:416: Uploaded 3 paths in 95.788368ms15712026/11/01 16:18:58 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15722026/11/01 16:18:58 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15732026/11/01 16:18:58 WARN Failed to register uploaded object key=nar/06zy9j85j053n84pvwk7m40xxhzs2l3qlfmc57v01svj9ixv3y1l.nar.zst error="server returned 404: 404 page not found\n"15742026/11/01 16:18:58 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15752026/11/01 16:18:58 INFO Uploading pnj8c06qcyzmczvsv2kl6i53xnhb7dg6-test-script (136B)15762026/11/01 16:18:58 INFO Signed narinfos id=1 count=215772026/11/01 16:18:58 INFO Uploading 2 narinfos15782026/11/01 16:18:58 INFO Received complete push request method=POST path=/api/pushes/1/complete15792026/11/01 16:18:58 WARN Failed to register uploaded object key=pnj8c06qcyzmczvsv2kl6i53xnhb7dg6.ls error="server returned 404: 404 page not found\n"15802026/11/01 16:18:58 WARN Failed to register uploaded object key=mq8ld9d3a9qia4ayqxf8h5lz4vzbbvc2.narinfo error="server returned 404: 404 page not found\n"15812026/11/01 16:18:58 WARN Failed to register uploaded object key=gb1m2c4n2myxk9kga6yydbj3vkf5wfi4.narinfo error="server returned 404: 404 page not found\n"15822026/11/01 16:18:58 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"15832026/11/01 16:18:58 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15842026/11/01 16:18:58 WARN Failed to register uploaded object key=log/9vz2ji33yqjmlihy7b3irxa7sjy9wh28-test-script.drv error="server returned 404: 404 page not found\n"15852026/11/01 16:18:58 INFO Signed narinfos id=1 count=11586--- PASS: TestClientMultipleUploads (0.54s)15872026/11/01 16:18:58 INFO Uploading 1 narinfos1588=== CONT TestReadProxyConditionalGet15892026/11/01 16:18:58 INFO Received complete push request method=POST path=/api/pushes/1/complete15902026/11/01 16:18:58 WARN Failed to register uploaded object key=pnj8c06qcyzmczvsv2kl6i53xnhb7dg6.narinfo error="server returned 404: 404 page not found\n"15912026/11/01 16:18:58 INFO Completed push id=1 objects=4 duration=12.930304ms15922026/11/01 16:18:58 INFO Completed push id=1 objects=6 duration=19.368981ms15932026/11/01 16:18:58 INFO Upload complete. (72ms)15942026/11/01 16:18:58 INFO Upload complete. (78ms)1595=== NAME TestClientSharedPathCommittedMidPush1596 client_integration_test.go:727: Retrieved narinfo from S3:1597 StorePath: /build/TestClientSharedPathCommittedMidPush2455833128/001/store/mq8ld9d3a9qia4ayqxf8h5lz4vzbbvc2-shared-dep1598 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1599 Compression: zstd1600 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821601 NarSize: 1361602 References: 1603 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1604=== NAME TestClientWithDependencies1605 client_integration_test.go:664: Skipping nix copy test - isolated store (/build/TestClientWithDependencies1083837061/001/store) requires matching store prefix1606=== NAME TestClientSharedPathCommittedMidPush1607 client_integration_test.go:727: Retrieved narinfo from S3:1608 StorePath: /build/TestClientSharedPathCommittedMidPush2455833128/001/store/gb1m2c4n2myxk9kga6yydbj3vkf5wfi4-top1609 URL: nar/06zy9j85j053n84pvwk7m40xxhzs2l3qlfmc57v01svj9ixv3y1l.nar.zst1610 Compression: zstd1611 NarHash: sha256:06zy9j85j053n84pvwk7m40xxhzs2l3qlfmc57v01svj9ixv3y1l1612 NarSize: 2241613 References: /build/TestClientSharedPathCommittedMidPush2455833128/001/store/mq8ld9d3a9qia4ayqxf8h5lz4vzbbvc2-shared-dep1614 CA: text:sha256:05lrp1hs12njd792yij9qagyxklpzv1flgww48d6vhymgs7h84k21615--- PASS: TestClientWithDependencies (0.55s)1616=== CONT TestReadProxyContentNegotiation1617--- PASS: TestClientSharedPathCommittedMidPush (0.52s)1618=== CONT TestObjectStatsTrigger1619--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.37s)1620=== CONT TestReadProxyOutlastsServerWriteTimeout1621--- PASS: TestDeleteClosuresRacingPins (1.60s)1622=== CONT TestPendingCleanupUsesOneCutoff1623=== NAME TestClientCADerivations1624 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations2580299290/001/store/6lrdqa13pbrdvviwcdq4372w43p7pq59-ca-test1625=== NAME TestClientIntegration1626 client_integration_test.go:291: Created store path: /build/TestClientIntegration716268053/002/store/07sk42xszqal4w1bkgzkpl9vsvbzfhg8-test-file.txt1627=== NAME TestClientCADerivations1628 client_ca_test.go:139: Found 1 dependencies (including self)1629--- PASS: TestObjectStatsUpdatedOncePerCommit (0.46s)1630=== CONT TestReadProxyNarinfoAlreadyDecompressed1631--- PASS: TestPresentReportsOnlyClosureRoots (0.49s)1632=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded16332026/11/01 16:18:59 INFO Received push request method=POST path=/api/pushes1634--- PASS: TestReadRedirectNar (0.49s)1635=== CONT TestService_NativeMTLS16362026/11/01 16:18:59 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16372026/11/01 16:18:59 INFO Uploading 07sk42xszqal4w1bkgzkpl9vsvbzfhg8-test-file.txt (152B)16382026/11/01 16:18:59 WARN Failed to register uploaded object key=07sk42xszqal4w1bkgzkpl9vsvbzfhg8.ls error="server returned 404: 404 page not found\n"16392026/11/01 16:18:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16402026/11/01 16:18:59 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"16412026/11/01 16:18:59 INFO Signed narinfos id=1 count=116422026/11/01 16:18:59 INFO Uploading 1 narinfos16432026/11/01 16:18:59 INFO Received complete push request method=POST path=/api/pushes/1/complete16442026/11/01 16:18:59 WARN Failed to register uploaded object key=07sk42xszqal4w1bkgzkpl9vsvbzfhg8.narinfo error="server returned 404: 404 page not found\n"16452026/11/01 16:18:59 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16462026/11/01 16:18:59 INFO Received push request method=POST path=/api/pushes1647--- PASS: TestReadProxyDisabled (0.44s)1648=== CONT TestReadProxyNarinfo16492026/11/01 16:18:59 INFO Completed push id=1 objects=3 duration=13.144924ms16502026/11/01 16:18:59 INFO Upload complete. (75ms)16512026/11/01 16:18:59 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16522026/11/01 16:18:59 INFO Uploading 6lrdqa13pbrdvviwcdq4372w43p7pq59-ca-test (144B)16532026/11/01 16:18:59 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NTMzOTg2NGUtOTM1ZC00N2M5LTk4YTctNWFlOTViN2JlYjBiLjY5NDZjZWYwLWFhZGItNDcxMS04NGZkLWExZjA2NTBiMDA0ZXgxNzkzNTQ5OTM4Njg5ODk1OTU5 error="Get \"http://127.0.0.1:1/bucket40/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"16542026/11/01 16:18:59 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NTMzOTg2NGUtOTM1ZC00N2M5LTk4YTctNWFlOTViN2JlYjBiLjFkZThjNDdlLTUxYTktNDhiOC1hZDNkLTc0MmJhMmEwYTYwN3gxNzkzNTQ5OTM4NjgwNzQ0NDUy parts=1216552026/11/01 16:18:59 INFO Received cleanup request method=DELETE path=/api/pending_closures16562026/11/01 16:18:59 WARN Failed to register uploaded object key=6lrdqa13pbrdvviwcdq4372w43p7pq59.ls error="server returned 404: 404 page not found\n"16572026/11/01 16:18:59 INFO lead: released remote=192.0.2.1:123416582026/11/01 16:18:59 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"16592026/11/01 16:18:59 WARN Failed to register uploaded object key=log/qa6ixx1241x2h3bw3y2dwsrp7j43r3jd-ca-test.drv error="server returned 404: 404 page not found\n"16602026/11/01 16:18:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16612026/11/01 16:18:59 INFO Signed narinfos id=1 count=116622026/11/01 16:18:59 INFO Uploading 1 narinfos16632026/11/01 16:18:59 INFO Aborted multipart uploads count=1 kept=016642026/11/01 16:18:59 INFO Received complete push request method=POST path=/api/pushes/1/complete16652026/11/01 16:18:59 WARN Failed to register uploaded object key=6lrdqa13pbrdvviwcdq4372w43p7pq59.narinfo error="server returned 404: 404 page not found\n"1666--- PASS: TestRedundantMultipartUpload (1.49s)1667=== CONT TestServerTLSConfig1668=== RUN TestServerTLSConfig/no_client_CA1669=== PAUSE TestServerTLSConfig/no_client_CA1670=== RUN TestServerTLSConfig/missing_CA_file1671=== PAUSE TestServerTLSConfig/missing_CA_file1672=== RUN TestServerTLSConfig/not_a_PEM_file1673=== PAUSE TestServerTLSConfig/not_a_PEM_file1674=== CONT TestReadProxyHead16752026/11/01 16:18:59 INFO Completed push id=1 objects=4 duration=6.981517ms16762026/11/01 16:18:59 INFO Upload complete. (95ms)1677=== NAME TestClientCADerivations1678 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations2580299290/001/store/6lrdqa13pbrdvviwcdq4372w43p7pq59-ca-test1679 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1680 Compression: zstd1681 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1682 NarSize: 1441683 References: 1684 Deriver: /build/TestClientCADerivations2580299290/001/store/qa6ixx1241x2h3bw3y2dwsrp7j43r3jd-ca-test.drv1685 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1686 client_ca_test.go:185: Checking for realisation files in S3...1687 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1688 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache16892026/11/01 16:18:59 INFO All 1 paths already cached1690=== NAME TestClientIntegration1691 client_integration_test.go:317: Retrieved narinfo from S3:1692 StorePath: /build/TestClientIntegration716268053/002/store/07sk42xszqal4w1bkgzkpl9vsvbzfhg8-test-file.txt1693 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1694 Compression: zstd1695 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11696 NarSize: 1521697 References: 1698 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11699 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1700 client_integration_test.go:318: Decompressed .ls content (64 bytes):1701 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1702--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.47s)1703=== CONT TestMetricsCommit17042026/11/01 16:18:59 INFO lead: acquired remote=192.0.2.1:123417052026/11/01 16:18:59 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux17062026/11/01 16:18:59 WARN Refused reserved pin name=worker-x86_64-linux17072026/11/01 16:18:59 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux17082026/11/01 16:18:59 INFO Received create pin request method=POST path=/api/pins/my-app17092026/11/01 16:18:59 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1710--- PASS: TestCreatePin_ReservedPins (0.61s)1711=== CONT TestIsValidCachePath1712=== RUN TestIsValidCachePath/narinfo1713=== PAUSE TestIsValidCachePath/narinfo1714=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1715=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1716=== RUN TestIsValidCachePath/nar_zst1717=== PAUSE TestIsValidCachePath/nar_zst1718=== RUN TestIsValidCachePath/nar_xz1719=== PAUSE TestIsValidCachePath/nar_xz1720=== RUN TestIsValidCachePath/nar_bz21721=== PAUSE TestIsValidCachePath/nar_bz21722=== RUN TestIsValidCachePath/nar_uncompressed1723=== PAUSE TestIsValidCachePath/nar_uncompressed1724=== RUN TestIsValidCachePath/ls1725=== PAUSE TestIsValidCachePath/ls1726=== RUN TestIsValidCachePath/log1727=== PAUSE TestIsValidCachePath/log1728=== RUN TestIsValidCachePath/realisation1729=== PAUSE TestIsValidCachePath/realisation1730=== RUN TestIsValidCachePath/nix-cache-info1731=== PAUSE TestIsValidCachePath/nix-cache-info1732=== RUN TestIsValidCachePath/index.html1733=== PAUSE TestIsValidCachePath/index.html1734=== RUN TestIsValidCachePath/traversal_parent1735=== PAUSE TestIsValidCachePath/traversal_parent1736=== RUN TestIsValidCachePath/traversal_in_middle1737=== PAUSE TestIsValidCachePath/traversal_in_middle1738=== RUN TestIsValidCachePath/invalid_char_e1739=== PAUSE TestIsValidCachePath/invalid_char_e1740=== RUN TestIsValidCachePath/invalid_char_u1741=== PAUSE TestIsValidCachePath/invalid_char_u1742=== RUN TestIsValidCachePath/random_path1743=== PAUSE TestIsValidCachePath/random_path1744=== RUN TestIsValidCachePath/empty1745=== PAUSE TestIsValidCachePath/empty1746=== RUN TestIsValidCachePath/leading_slash1747=== PAUSE TestIsValidCachePath/leading_slash1748=== RUN TestIsValidCachePath/wrong_extension1749=== PAUSE TestIsValidCachePath/wrong_extension1750=== RUN TestIsValidCachePath/short_hash1751=== PAUSE TestIsValidCachePath/short_hash1752=== CONT TestReadProxyInvalidPath1753--- PASS: TestPresentRefreshesOnlyStaleClosures (0.48s)1754=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows17552026/11/01 16:18:59 INFO Received push request method=POST path=/api/pushes17562026/11/01 16:18:59 INFO Object in database but missing from S3 key=07sk42xszqal4w1bkgzkpl9vsvbzfhg8.ls17572026/11/01 16:18:59 WARN Found objects in DB but missing from S3, will re-upload count=117582026/11/01 16:18:59 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17592026/11/01 16:18:59 INFO Received complete push request method=POST path=/api/pushes/2/complete17602026/11/01 16:18:59 WARN Failed to register uploaded object key=07sk42xszqal4w1bkgzkpl9vsvbzfhg8.ls error="server returned 404: 404 page not found\n"17612026/11/01 16:18:59 INFO Completed push id=2 objects=3 duration=1.92189ms17622026/11/01 16:18:59 INFO Upload complete. (40ms)1763=== NAME TestClientIntegration1764 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1765 client_integration_test.go:335: Decompressed .ls content (49 bytes):1766 {"version":1,"root":{"type":"regular","size":39}}1767--- PASS: TestReadProxyNarStreaming (0.48s)1768=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1769=== NAME TestClientCADerivations1770 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1771 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1772 error: binary cache 's3://bucket64?endpoint=http://localhost:39857®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations2580299290/001/store'1773 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11774--- PASS: TestClientCADerivations (0.79s)1775=== CONT TestGCEndsOnShutdown/before_the_run17762026/11/01 16:18:59 INFO Received uploads request method=POST path=/api/pending_closures1777--- PASS: TestReadProxy404 (0.54s)1778=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1779--- PASS: TestReadProxyConditionalGet (0.49s)1780=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete17812026/11/01 16:18:59 INFO Received push request method=POST path=/api/pushes17822026/11/01 16:18:59 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17832026/11/01 16:18:59 INFO Received complete push request method=POST path=/api/pushes/3/complete17842026/11/01 16:18:59 WARN Failed to register uploaded object key=07sk42xszqal4w1bkgzkpl9vsvbzfhg8.ls error="server returned 404: 404 page not found\n"17852026/11/01 16:18:59 INFO Completed push id=3 objects=3 duration=3.298139ms17862026/11/01 16:18:59 INFO Upload complete. (44ms)1787=== NAME TestClientIntegration1788 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1789 client_integration_test.go:352: Decompressed .ls content (49 bytes):1790 {"version":1,"root":{"type":"regular","size":39}}1791 client_integration_test.go:363: Testing garbage collection...1792--- PASS: TestReadProxyContentNegotiation (0.51s)1793=== CONT TestResolveDBConnectionString/flag_wins1794=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1795=== CONT TestResolveDBConnectionString/nothing_configured1796=== CONT TestResolveDBConnectionString/missing_file_is_an_error1797=== CONT TestResolveDBConnectionString/file_when_flag_empty1798=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17992026/11/01 16:18:59 INFO Received uploads request method=POST path=/1800--- PASS: TestResolveDBConnectionString (0.00s)1801 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1802 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1803 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1804 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1805 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1806=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key18072026/11/01 16:18:59 INFO Received request for more parts method=POST path=/1808=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key18092026/11/01 16:18:59 INFO Received complete multipart upload request method=POST path=/1810=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal18112026/11/01 16:18:59 INFO Received uploads request method=POST path=/1812--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1813 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1814 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1815 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1816 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1817=== CONT TestIsValidUploadKey/narinfo1818=== CONT TestIsValidUploadKey/realisation_plus_in_output1819=== CONT TestIsValidUploadKey/realisation1820=== CONT TestIsValidUploadKey/build_log_equals1821=== CONT TestIsValidUploadKey/build_log_question_mark1822=== CONT TestIsValidUploadKey/build_log_plus_in_name1823=== CONT TestIsValidUploadKey/build_log_home-manager_file1824=== CONT TestIsValidUploadKey/build_log1825=== CONT TestIsValidUploadKey/listing1826=== CONT TestIsValidUploadKey/nar_plain1827=== CONT TestIsValidUploadKey/nar_xz1828=== CONT TestIsValidUploadKey/nix-cache-info1829=== CONT TestIsValidUploadKey/nar_zst1830=== CONT TestIsValidUploadKey/traversal1831=== CONT TestIsValidUploadKey/unknown_type1832=== CONT TestIsValidUploadKey/empty_key1833=== CONT TestIsValidUploadKey/absolute1834=== CONT TestIsValidUploadKey/traversal_nar1835=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1836=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1837=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1838=== CONT TestIsValidUploadKey/index.html1839--- PASS: TestIsValidUploadKey (0.00s)1840 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1841 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1842 --- PASS: TestIsValidUploadKey/realisation (0.00s)1843 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1844 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1845 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1846 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1847 --- PASS: TestIsValidUploadKey/build_log (0.00s)1848 --- PASS: TestIsValidUploadKey/listing (0.00s)1849 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1850 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1851 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1852 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1853 --- PASS: TestIsValidUploadKey/traversal (0.00s)1854 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1855 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1856 --- PASS: TestIsValidUploadKey/absolute (0.00s)1857 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1858 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1859 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1860 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1861 --- PASS: TestIsValidUploadKey/index.html (0.00s)1862=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18632026/11/01 16:18:59 INFO Received uploads request method=POST path=/1864--- PASS: TestObjectStatsTrigger (0.51s)1865=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18662026/11/01 16:18:59 INFO Received request for more parts method=POST path=/18672026/11/01 16:18:59 INFO Starting cleanup of old closures method=DELETE path=/api/closures18682026/11/01 16:18:59 INFO Garbage collection started18692026/11/01 16:18:59 INFO Received uploads request method=POST path=/api/pending_closures18702026/11/01 16:18:59 INFO Aborted multipart uploads count=0 kept=018712026/11/01 16:18:59 INFO Received uploads request method=POST path=/api/pending_closures18722026/11/01 16:18:59 WARN Force mode enabled - objects will be deleted immediately without grace period18732026/11/01 16:18:59 INFO Received cleanup request method=DELETE path=/api/pending_closures18742026/11/01 16:18:59 INFO Received cleanup request method=DELETE path=/api/pending_closures18752026/11/01 16:18:59 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket78/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""18762026/11/01 16:18:59 INFO Aborted multipart uploads count=0 kept=11877=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18782026/11/01 16:18:59 INFO Received complete multipart upload request method=POST path=/1879--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.41s)1880=== CONT TestPendingClosureWriteTimeout/empty1881=== CONT TestPendingClosureWriteTimeout/670k_objects1882=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline18832026/11/01 16:18:59 INFO Received cleanup request method=DELETE path=/api/pending_closures18842026/11/01 16:18:59 INFO Aborted multipart uploads count=1 kept=01885--- PASS: TestMultipartCleanup (0.62s)1886=== CONT TestPendingClosureWriteTimeout/400_objects1887=== CONT TestProxyWriteTimeout/narinfo1888=== CONT TestProxyWriteTimeout/10_GiB_nar1889=== CONT TestProxyWriteTimeout/unknown_size1890=== CONT TestProxyWriteTimeout/1_GiB_nar1891--- PASS: TestProxyWriteTimeout (0.00s)1892 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1893 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1894 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1895 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1896=== CONT TestPush_RejectsBadRequests/root_not_in_objects18972026/11/01 16:18:59 INFO Received push request method=POST path=/api/pushes1898=== CONT TestPush_RejectsBadRequests/no_objects18992026/11/01 16:18:59 INFO Received push request method=POST path=/api/pushes1900=== CONT TestPush_RejectsBadRequests/bad_root19012026/11/01 16:18:59 INFO Received push request method=POST path=/api/pushes1902=== CONT TestPush_RejectsBadRequests/no_roots19032026/11/01 16:18:59 INFO Received push request method=POST path=/api/pushes1904=== CONT TestCacheConfigHandler/full_config,_no_issuer1905--- PASS: TestPush_RejectsBadRequests (0.47s)1906 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1907 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1908 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1909 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1910=== CONT TestCacheConfigHandler/no_signing_keys1911=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1912=== CONT TestCacheConfigHandler/no_cache_url_configured1913--- PASS: TestCacheConfigHandler (0.00s)1914 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1915 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1916 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1917 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1918=== CONT TestClientErrorHandling/InvalidStorePath19192026/11/01 16:18:59 INFO Received uploads request method=POST path=/api/pending_closures19202026/11/01 16:18:59 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=019212026/11/01 16:18:59 INFO Vacuumed table table=pending_closures19222026/11/01 16:18:59 INFO Vacuumed table table=pending_objects19232026/11/01 16:18:59 INFO Vacuumed table table=multipart_uploads1924--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.38s)1925=== CONT TestClientErrorHandling/ServerNotAvailable19262026/11/01 16:18:59 INFO Vacuumed table table=closures19272026/11/01 16:18:59 INFO Vacuumed table table=objects19282026/11/01 16:18:59 WARN mTLS auth: subject not in bound subjects subject="CN=reader"19292026/11/01 16:18:59 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1930--- PASS: TestService_NativeMTLS (0.36s)1931=== CONT TestClientErrorHandling/InvalidAuthToken1932=== CONT TestParseSingleRange/none1933=== CONT TestParseSingleRange/open-ended1934=== CONT TestParseSingleRange/start_far_past_EOF1935=== CONT TestParseSingleRange/start_past_EOF1936=== CONT TestParseSingleRange/single_byte1937=== CONT TestParseSingleRange/suffix_exceeds_size1938=== CONT TestParseSingleRange/suffix1939=== CONT TestParseSingleRange/end_clamped_to_size1940=== CONT TestParseSingleRange/malformed_both_empty1941=== CONT TestParseSingleRange/closed1942=== CONT TestParseSingleRange/malformed_end_before_start1943=== CONT TestParseSingleRange/multi-range_ignored1944=== CONT TestParseSingleRange/malformed_no_dash1945=== CONT TestParseSingleRange/unknown_unit1946--- PASS: TestParseSingleRange (0.00s)1947 --- PASS: TestParseSingleRange/none (0.00s)1948 --- PASS: TestParseSingleRange/open-ended (0.00s)1949 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1950 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1951 --- PASS: TestParseSingleRange/single_byte (0.00s)1952 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1953 --- PASS: TestParseSingleRange/suffix (0.00s)1954 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1955 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1956 --- PASS: TestParseSingleRange/closed (0.00s)1957 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1958 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1959 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1960 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1961=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1962=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19632026/11/01 16:18:59 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]1964=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1965=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19662026/11/01 16:18:59 WARN Authentication failed token_preview=eyJhbGciOi...scnH7ZEMmA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1967=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1968--- PASS: TestService_AuthMiddleware_OIDC (0.33s)1969 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1970 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1971 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1972 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1973--- PASS: TestReadProxyHead (0.36s)1974=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1975=== NAME TestOrphanedObjectsGC1976 orphaned_objects_gc_test.go:287: GC Test Summary:1977 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1978 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1979 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1980 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1981 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1982--- PASS: TestOrphanedObjectsGC (0.82s)1983=== CONT TestService_RequireScope_OIDC/builder_may_write1984=== CONT TestService_RequireScope_OIDC/reader_may_read1985=== CONT TestService_RequireScope_OIDC/static_token_may_write1986=== CONT TestService_RequireScope_OIDC/static_token_may_admin1987=== CONT TestService_RequireScope_OIDC/reader_may_not_write1988=== CONT TestService_RequireScope_OIDC/ops_may_not_write1989=== CONT TestService_RequireScope_OIDC/ops_may_admin1990=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1991=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19922026/11/01 16:18:59 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]1993=== CONT TestService_RequireScope_OIDC/writer_implies_read1994=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1995=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1996=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1997=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1998=== CONT TestServerTLSConfig/no_client_CA1999=== CONT TestServerTLSConfig/not_a_PEM_file20002026/11/01 16:18:59 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/present20012026/11/01 16:18:59 INFO Received push request method=POST path=/api/pushes2002--- PASS: TestService_RequireScope_OIDC (0.35s)2003 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2004 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2005 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2006 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2007 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2008 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2009 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2010 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2011 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2012 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2013 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2014 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2015 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2016 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2017=== CONT TestServerTLSConfig/missing_CA_file2018--- PASS: TestServerTLSConfig (0.00s)2019 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2020 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2021 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2022=== CONT TestIsValidCachePath/narinfo2023=== CONT TestIsValidCachePath/leading_slash2024=== CONT TestIsValidCachePath/wrong_extension2025=== CONT TestIsValidCachePath/empty2026=== CONT TestIsValidCachePath/random_path2027=== CONT TestIsValidCachePath/invalid_char_u2028=== CONT TestIsValidCachePath/invalid_char_e2029=== CONT TestIsValidCachePath/traversal_in_middle2030=== CONT TestIsValidCachePath/traversal_parent2031=== CONT TestIsValidCachePath/index.html2032=== CONT TestIsValidCachePath/nix-cache-info2033=== CONT TestIsValidCachePath/realisation2034=== CONT TestIsValidCachePath/log2035=== CONT TestIsValidCachePath/ls2036=== CONT TestIsValidCachePath/nar_uncompressed2037=== CONT TestIsValidCachePath/nar_bz22038=== CONT TestIsValidCachePath/nar_xz2039=== CONT TestIsValidCachePath/nar_zst2040=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2041=== CONT TestIsValidCachePath/short_hash2042--- PASS: TestIsValidCachePath (0.00s)2043 --- PASS: TestIsValidCachePath/narinfo (0.00s)2044 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2045 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2046 --- PASS: TestIsValidCachePath/empty (0.00s)2047 --- PASS: TestIsValidCachePath/random_path (0.00s)2048 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2049 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2050 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2051 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2052 --- PASS: TestIsValidCachePath/index.html (0.00s)2053 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2054 --- PASS: TestIsValidCachePath/realisation (0.00s)2055 --- PASS: TestIsValidCachePath/log (0.00s)2056 --- PASS: TestIsValidCachePath/ls (0.00s)2057 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2058 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2059 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2060 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2061 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2062 --- PASS: TestIsValidCachePath/short_hash (0.00s)20632026/11/01 16:18:59 INFO Received complete push request method=POST path=/api/pushes/1/complete2064--- PASS: TestReadProxyInvalidPath (0.34s)20652026/11/01 16:18:59 INFO Completed push id=1 objects=4 duration=7.578776ms20662026/11/01 16:18:59 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete20672026/11/01 16:18:59 INFO Completed upload id=2 objects=2 duration=2.264889ms20682026/11/01 16:18:59 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>2069--- PASS: TestReadProxyNarinfo (0.44s)2070--- PASS: TestMetricsCommit (0.39s)20712026/11/01 16:18:59 INFO Received uploads request method=POST path=/api/pending_closures20722026/11/01 16:18:59 INFO Aborted multipart uploads count=0 kept=020732026/11/01 16:18:59 WARN Force mode enabled - objects will be deleted immediately without grace period20742026/11/01 16:18:59 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=020752026/11/01 16:18:59 INFO Received create pin request method=POST path=/api/pins/myapp20762026/11/01 16:18:59 INFO Received uploads request method=POST path=/api/pending_closures20772026/11/01 16:18:59 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2707395788/001/store/1xfy07s83flxakfdlw7cn0lr74lqfcwc-pinned-file.txt narinfo_key=1xfy07s83flxakfdlw7cn0lr74lqfcwc.narinfo20782026/11/01 16:18:59 INFO Starting cleanup of old closures method=DELETE path=/api/closures20792026/11/01 16:18:59 INFO Garbage collection started20802026/11/01 16:18:59 INFO Aborted multipart uploads count=0 kept=020812026/11/01 16:18:59 WARN Force mode enabled - objects will be deleted immediately without grace period20822026/11/01 16:18:59 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=020832026/11/01 16:18:59 INFO Aborted multipart uploads count=0 kept=020842026/11/01 16:18:59 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/11/01 16:18:59 INFO Vacuumed table table=pending_closures20862026/11/01 16:18:59 INFO Vacuumed table table=pending_closures20872026/11/01 16:18:59 INFO Vacuumed table table=pending_objects20882026/11/01 16:18:59 INFO Vacuumed table table=multipart_uploads20892026/11/01 16:18:59 INFO Vacuumed table table=closures20902026/11/01 16:18:59 INFO Vacuumed table table=pending_objects20912026/11/01 16:18:59 INFO Vacuumed table table=multipart_uploads20922026/11/01 16:18:59 INFO Vacuumed table table=closures20932026/11/01 16:18:59 INFO Vacuumed table table=objects20942026/11/01 16:18:59 INFO Vacuumed table table=objects20952026/11/01 16:18:59 WARN Force mode enabled - objects will be deleted immediately without grace period20962026/11/01 16:18:59 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=020972026/11/01 16:18:59 WARN Request failed, retrying attempt=2 backoff=212.253243ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20982026/11/01 16:18:59 INFO Vacuumed table table=pending_closures20992026/11/01 16:18:59 INFO Vacuumed table table=pending_objects21002026/11/01 16:18:59 INFO Vacuumed table table=multipart_uploads21012026/11/01 16:18:59 INFO Vacuumed table table=closures21022026/11/01 16:18:59 INFO Vacuumed table table=objects2103--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2104 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.36s)2105 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.41s)21062026/11/01 16:18:59 INFO Aborted multipart uploads count=0 kept=021072026/11/01 16:18:59 WARN Force mode enabled - objects will be deleted immediately without grace period21082026/11/01 16:18:59 INFO Aborted multipart uploads count=0 kept=021092026/11/01 16:18:59 WARN Force mode enabled - objects will be deleted immediately without grace period21102026/11/01 16:18:59 INFO Received uploads request method=POST path=/api/pending_closures21112026/11/01 16:18:59 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:39857/bucket95/?delete=\": context canceled"2112--- PASS: TestGCEndsOnShutdown (0.00s)2113 --- PASS: TestGCEndsOnShutdown/before_the_run (0.34s)2114 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.37s)2115 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.35s)21162026/11/01 16:18:59 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21172026/11/01 16:18:59 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21182026/11/01 16:18:59 WARN Request failed, retrying attempt=3 backoff=413.965515ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2119--- PASS: TestUploadHandlersRejectOversizedBody (0.16s)2120 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)2121 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.06s)2122 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.65s)21232026/11/01 16:19:00 WARN Request failed, retrying attempt=4 backoff=731.828947ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2124--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2125 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.76s)2126 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.75s)21272026/11/01 16:19:00 INFO lead: released remote=192.0.2.1:12342128--- PASS: TestLeadElectsOneAndHandsOver (3.14s)2129--- PASS: TestPendingClosureWriteTimeout (0.00s)2130 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2131 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2132 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2133 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.06s)2134=== NAME TestOrphanedObjectsGCStressTest2135 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2136 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion21372026/11/01 16:19:01 WARN Request failed, retrying attempt=5 backoff=1.73414627s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21382026/11/01 16:19:01 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02139=== NAME TestClientIntegration2140 client_integration_test.go:370: Objects in database after GC:2141 client_integration_test.go:370: Successfully deleted all objects with GC --force2142--- PASS: TestClientIntegration (2.89s)2143=== NAME TestPinProtectsFromGC2144 client_integration_test.go:887: Pin successfully protected closure from garbage collection2145--- PASS: TestPinProtectsFromGC (4.72s)2146=== NAME TestOrphanedObjectsGCStressTest2147 orphaned_objects_gc_test.go:503: Stress test completed successfully:2148 orphaned_objects_gc_test.go:504: - Active objects preserved: 202149 orphaned_objects_gc_test.go:505: - Objects deleted: 2102150 orphaned_objects_gc_test.go:506: - Total GC'd: 2102151--- PASS: TestOrphanedObjectsGCStressTest (3.53s)2152--- PASS: TestConnectWaitsForAPeerMigration (5.17s)21532026/11/01 16:19:02 WARN Rate limiter enabled after throttle name=s3-test rate=521542026/11/01 16:19:02 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2155=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2156 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102157 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002158--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.66s)21592026/11/01 16:19:02 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-config21602026/11/01 16:19:02 WARN Request failed, retrying attempt=2 backoff=198.879049ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21612026/11/01 16:19:03 WARN Request failed, retrying attempt=3 backoff=366.963534ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21622026/11/01 16:19:03 WARN Request failed, retrying attempt=4 backoff=723.874192ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2163--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.69s)21642026/11/01 16:19:04 WARN Request failed, retrying attempt=5 backoff=1.625786133s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21652026/11/01 16:19:05 INFO Aborted multipart uploads count=1 kept=021662026/11/01 16:19:05 INFO Received cleanup request method=DELETE path=/api/pending_closures21672026/11/01 16:19:05 INFO Aborted multipart uploads count=1 kept=02168--- PASS: TestPendingCleanupUsesOneCutoff (6.50s)21692026/11/01 16:19:05 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"21702026/11/01 16:19:05 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-config21712026/11/01 16:19:05 WARN Request failed, retrying attempt=2 backoff=196.786104ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21722026/11/01 16:19:06 WARN Request failed, retrying attempt=3 backoff=404.219151ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21732026/11/01 16:19:06 WARN Request failed, retrying attempt=4 backoff=753.673137ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21742026/11/01 16:19:07 WARN Request failed, retrying attempt=5 backoff=1.703107158s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21752026/11/01 16:19:08 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_closures21762026/11/01 16:19:09 WARN Request failed, retrying attempt=2 backoff=181.582658ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21772026/11/01 16:19:09 WARN Request failed, retrying attempt=3 backoff=417.136532ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21782026/11/01 16:19:09 WARN Request failed, retrying attempt=4 backoff=813.718132ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21792026/11/01 16:19:10 WARN Request failed, retrying attempt=5 backoff=1.488033648s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2180--- PASS: TestClientErrorHandling (0.00s)2181 --- PASS: TestClientErrorHandling/InvalidStorePath (0.30s)2182 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.36s)2183 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.50s)2184PASS2185{"timestamp":"2026-11-01T16:19:11.97144086Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:42244","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(140)"}2186{"timestamp":"2026-11-01T16:19:11.97164406Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:41776","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(132)"}21872026-11-01 16:19:12.185 UTC [128] LOG: received smart shutdown request21882026-11-01 16:19:12.187 UTC [128] LOG: background worker "logical replication launcher" (PID 138) exited with exit code 121892026-11-01 16:19:12.200 UTC [133] LOG: shutting down21902026-11-01 16:19:12.200 UTC [133] LOG: checkpoint starting: shutdown immediate21912026-11-01 16:19:14.320 UTC [133] LOG: checkpoint complete: wrote 10967 buffers (66.9%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 30 recycled; write=0.313 s, sync=1.740 s, total=2.121 s; sync files=34045, longest=0.094 s, average=0.001 s; distance=494036 kB, estimate=494036 kB; lsn=0/1F9DB018, redo lsn=0/1F9DB01821922026-11-01 16:19:14.397 UTC [128] LOG: database system is shut down2193Running OIDC tests...2194=== RUN TestAudienceForIssuer2195=== PAUSE TestAudienceForIssuer2196=== RUN TestGlobMatch2197=== PAUSE TestGlobMatch2198=== RUN TestValidateToken_ValidToken2199=== PAUSE TestValidateToken_ValidToken2200=== RUN TestValidateToken_WrongAudience2201=== PAUSE TestValidateToken_WrongAudience2202=== RUN TestValidateToken_Expired2203=== PAUSE TestValidateToken_Expired2204=== RUN TestValidateToken_BoundClaimsMismatch2205=== PAUSE TestValidateToken_BoundClaimsMismatch2206=== RUN TestValidateToken_BoundSubjectMismatch2207=== PAUSE TestValidateToken_BoundSubjectMismatch2208=== RUN TestValidateToken_MultipleProviders2209=== PAUSE TestValidateToken_MultipleProviders2210=== RUN TestValidateToken_NoMatchingProvider2211=== PAUSE TestValidateToken_NoMatchingProvider2212=== RUN TestValidateToken_KubernetesServiceAccount2213=== PAUSE TestValidateToken_KubernetesServiceAccount2214=== RUN TestNewValidator_KubernetesRequiresCA2215=== PAUSE TestNewValidator_KubernetesRequiresCA2216=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2217=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2218=== RUN TestPins_ReservedForMatchingRule2219=== PAUSE TestPins_ReservedForMatchingRule2220=== RUN TestPins_TopLevelShorthand2221=== PAUSE TestPins_TopLevelShorthand2222=== RUN TestPins_ConfigValidation2223=== PAUSE TestPins_ConfigValidation2224=== RUN TestScopes_LegacyProviderDefaultsToWrite2225=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2226=== RUN TestScopes_Rules2227=== PAUSE TestScopes_Rules2228=== RUN TestScopes_ConfigValidation2229=== PAUSE TestScopes_ConfigValidation2230=== CONT TestAudienceForIssuer2231=== CONT TestValidateToken_KubernetesServiceAccount2232=== CONT TestValidateToken_BoundClaimsMismatch2233--- PASS: TestAudienceForIssuer (0.00s)2234=== CONT TestValidateToken_NoMatchingProvider2235=== CONT TestValidateToken_ValidToken2236=== CONT TestValidateToken_MultipleProviders2237=== CONT TestGlobMatch2238=== RUN TestGlobMatch/foo_foo2239=== PAUSE TestGlobMatch/foo_foo2240=== CONT TestValidateToken_BoundSubjectMismatch2241=== CONT TestPins_ConfigValidation2242=== CONT TestScopes_ConfigValidation2243=== CONT TestScopes_Rules2244=== CONT TestScopes_LegacyProviderDefaultsToWrite2245=== CONT TestValidateToken_Expired2246=== CONT TestPins_ReservedForMatchingRule2247=== CONT TestPins_TopLevelShorthand2248=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2249=== CONT TestNewValidator_KubernetesRequiresCA2250=== CONT TestValidateToken_WrongAudience2251=== RUN TestGlobMatch/foo_bar2252=== PAUSE TestGlobMatch/foo_bar2253=== RUN TestGlobMatch/*_2254=== PAUSE TestGlobMatch/*_2255=== RUN TestGlobMatch/*_anything2256=== PAUSE TestGlobMatch/*_anything2257=== RUN TestGlobMatch/foo*_foo2258=== PAUSE TestGlobMatch/foo*_foo2259=== RUN TestGlobMatch/foo*_foobar2260=== PAUSE TestGlobMatch/foo*_foobar2261=== RUN TestGlobMatch/foo*_bar2262=== PAUSE TestGlobMatch/foo*_bar2263=== RUN TestGlobMatch/*bar_bar2264=== PAUSE TestGlobMatch/*bar_bar2265=== RUN TestGlobMatch/*bar_foobar2266=== PAUSE TestGlobMatch/*bar_foobar2267=== RUN TestGlobMatch/*bar_foo2268=== PAUSE TestGlobMatch/*bar_foo2269=== RUN TestGlobMatch/foo*bar_foobar2270=== PAUSE TestGlobMatch/foo*bar_foobar2271=== RUN TestGlobMatch/foo*bar_foo123bar2272=== PAUSE TestGlobMatch/foo*bar_foo123bar2273=== RUN TestGlobMatch/foo*bar_foobarbaz2274=== PAUSE TestGlobMatch/foo*bar_foobarbaz2275=== RUN TestGlobMatch/*/*_foo/bar2276=== PAUSE TestGlobMatch/*/*_foo/bar2277=== RUN TestGlobMatch/*/*_foo2278=== PAUSE TestGlobMatch/*/*_foo2279=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2280=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2281=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02282=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02283=== RUN TestGlobMatch/refs/*/main_refs/heads/main2284=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2285=== RUN TestGlobMatch/fo?_foo2286--- PASS: TestScopes_ConfigValidation (0.00s)2287=== PAUSE TestGlobMatch/fo?_foo2288=== RUN TestGlobMatch/fo?_fo2289=== PAUSE TestGlobMatch/fo?_fo2290=== RUN TestGlobMatch/fo?_fooo2291=== PAUSE TestGlobMatch/fo?_fooo2292=== RUN TestGlobMatch/?oo_foo2293=== PAUSE TestGlobMatch/?oo_foo2294=== RUN TestGlobMatch/?oo_boo2295=== PAUSE TestGlobMatch/?oo_boo2296=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2297=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2298=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2299=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2300=== CONT TestGlobMatch/foo_foo2301=== CONT TestGlobMatch/*/*_foo/bar2302=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02303=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2304=== CONT TestGlobMatch/*/*_foo2305=== CONT TestGlobMatch/*bar_bar2306=== CONT TestGlobMatch/*bar_foo2307=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2308=== CONT TestGlobMatch/foo*_foo2309=== CONT TestGlobMatch/foo*_bar2310=== CONT TestGlobMatch/foo*_foobar2311=== CONT TestGlobMatch/foo*bar_foobarbaz2312=== CONT TestGlobMatch/foo*bar_foo123bar2313=== CONT TestGlobMatch/*_2314=== CONT TestGlobMatch/*_anything2315=== CONT TestGlobMatch/foo_bar2316=== CONT TestGlobMatch/?oo_boo2317=== CONT TestGlobMatch/?oo_foo2318=== CONT TestGlobMatch/fo?_fooo2319=== CONT TestGlobMatch/fo?_fo2320=== CONT TestGlobMatch/fo?_foo2321=== CONT TestGlobMatch/refs/*/main_refs/heads/main2322=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2323=== CONT TestGlobMatch/*bar_foobar2324=== CONT TestGlobMatch/foo*bar_foobar2325--- PASS: TestGlobMatch (0.00s)2326 --- PASS: TestGlobMatch/foo_foo (0.00s)2327 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2328 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2329 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2330 --- PASS: TestGlobMatch/*/*_foo (0.00s)2331 --- PASS: TestGlobMatch/*bar_bar (0.00s)2332 --- PASS: TestGlobMatch/*bar_foo (0.00s)2333 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2334 --- PASS: TestGlobMatch/foo*_foo (0.00s)2335 --- PASS: TestGlobMatch/foo*_bar (0.00s)2336 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2337 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2338 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2339 --- PASS: TestGlobMatch/*_ (0.00s)2340 --- PASS: TestGlobMatch/*_anything (0.00s)2341 --- PASS: TestGlobMatch/foo_bar (0.00s)2342 --- PASS: TestGlobMatch/?oo_boo (0.00s)2343 --- PASS: TestGlobMatch/?oo_foo (0.00s)2344 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2345 --- PASS: TestGlobMatch/fo?_fo (0.00s)2346 --- PASS: TestGlobMatch/fo?_foo (0.00s)2347 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2348 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2349 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2350 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2351--- PASS: TestPins_ConfigValidation (0.00s)23522026/11/01 16:19:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33253/oidc23532026/11/01 16:19:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43653/oidc23542026/11/01 16:19:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36265/oidc2355--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.03s)2356--- PASS: TestValidateToken_BoundSubjectMismatch (0.03s)2357--- PASS: TestScopes_Rules (0.04s)23582026/11/01 16:19:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37911/oidc2359--- PASS: TestValidateToken_BoundClaimsMismatch (0.05s)23602026/11/01 16:19:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42597/oidc2361--- PASS: TestValidateToken_ValidToken (0.06s)23622026/11/01 16:19:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37593/oidc2363--- PASS: TestPins_TopLevelShorthand (0.06s)23642026/11/01 16:19:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35923/oidc2365--- PASS: TestValidateToken_WrongAudience (0.07s)23662026/11/01 16:19:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40141/oidc2367--- PASS: TestValidateToken_Expired (0.07s)23682026/11/01 16:19:16 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:40947/oidc2369--- PASS: TestValidateToken_NoMatchingProvider (0.08s)23702026/11/01 16:19:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41363/oidc23712026/11/01 16:19:16 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:427812372--- PASS: TestPins_ReservedForMatchingRule (0.08s)2373--- PASS: TestValidateToken_KubernetesServiceAccount (0.09s)23742026/11/01 16:19:16 http: TLS handshake error from 127.0.0.1:34314: remote error: tls: bad certificate2375--- PASS: TestNewValidator_KubernetesRequiresCA (0.10s)23762026/11/01 16:19:16 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232377--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.16s)23782026/11/01 16:19:16 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:46831/oidc23792026/11/01 16:19:16 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:35193/oidc2380--- PASS: TestValidateToken_MultipleProviders (0.24s)2381PASS2382Running hook tests...2383=== RUN TestSendPathsEmpty2384=== PAUSE TestSendPathsEmpty2385=== RUN TestQueueEnqueueAndFetch2386=== PAUSE TestQueueEnqueueAndFetch2387=== RUN TestQueueDeduplication2388=== PAUSE TestQueueDeduplication2389=== RUN TestQueueRemove2390=== PAUSE TestQueueRemove2391=== RUN TestQueueFetchBatchLimit2392=== PAUSE TestQueueFetchBatchLimit2393=== RUN TestQueueRetryMovesToBack2394=== PAUSE TestQueueRetryMovesToBack2395=== RUN TestQueueFetchRemoveLifecycle2396=== PAUSE TestQueueFetchRemoveLifecycle2397=== RUN TestQueueConcurrentWriters2398=== PAUSE TestQueueConcurrentWriters2399=== RUN TestQueueRemoveLargeClosure2400=== PAUSE TestQueueRemoveLargeClosure2401=== RUN TestQueueSingleOwnerAcrossModes2402=== PAUSE TestQueueSingleOwnerAcrossModes2403=== RUN TestQueueRoots2404=== RUN TestQueueRoots/false2405 retention_integration_test.go:23: set NIKS3_TEST_NIX_GC=1 to test with a disposable Nix store2406=== RUN TestQueueRoots/true2407 retention_integration_test.go:23: set NIKS3_TEST_NIX_GC=1 to test with a disposable Nix store2408--- PASS: TestQueueRoots (0.00s)2409 --- SKIP: TestQueueRoots/false (0.00s)2410 --- SKIP: TestQueueRoots/true (0.00s)2411=== RUN TestQueueRootRecovery2412 retention_integration_test.go:101: set NIKS3_TEST_NIX_GC=1 to test with a disposable Nix store2413--- SKIP: TestQueueRootRecovery (0.00s)2414=== RUN TestServerClientIntegration2415--- PASS: TestServerClientIntegration (0.00s)2416=== RUN TestServerQueueError24172026/11/01 16:19:16 ERROR Failed to queue paths error="permission denied" count=12418--- PASS: TestServerQueueError (0.00s)2419=== RUN TestGetListenerSocketActivation2420 server_test.go:218: === RUN TestGetListenerSocketActivation2421 --- PASS: TestGetListenerSocketActivation (0.00s)2422 PASS2423 2424--- PASS: TestGetListenerSocketActivation (0.01s)2425=== RUN TestServerStalledClientDoesNotBlockShutdown2426=== PAUSE TestServerStalledClientDoesNotBlockShutdown2427=== RUN TestServerBacksOffOnAcceptErrors2428=== PAUSE TestServerBacksOffOnAcceptErrors2429=== RUN TestDrainIsolatesPoisonPath2430=== PAUSE TestDrainIsolatesPoisonPath2431=== RUN TestRunNotBlockedByPoisonHead2432=== PAUSE TestRunNotBlockedByPoisonHead2433=== RUN TestDrainGivesUpWhenServerDown2434=== PAUSE TestDrainGivesUpWhenServerDown2435=== RUN TestFailedPathPrunedByLaterClosure2436=== PAUSE TestFailedPathPrunedByLaterClosure2437=== RUN TestWorkerUploadsAndRemoves2438=== PAUSE TestWorkerUploadsAndRemoves2439=== RUN TestWorkerSkipsGCdPaths2440=== PAUSE TestWorkerSkipsGCdPaths2441=== RUN TestWorkerPrunesClosureDeps2442=== PAUSE TestWorkerPrunesClosureDeps2443=== RUN TestDrainTimeout2444=== PAUSE TestDrainTimeout2445=== RUN TestWorkerRemoveFailureIsNotProgress2446=== PAUSE TestWorkerRemoveFailureIsNotProgress2447=== RUN TestWorkerKeepsPathItCannotStat2448=== PAUSE TestWorkerKeepsPathItCannotStat2449=== CONT TestSendPathsEmpty2450=== CONT TestFailedPathPrunedByLaterClosure2451--- PASS: TestSendPathsEmpty (0.00s)2452=== CONT TestWorkerKeepsPathItCannotStat2453=== CONT TestWorkerRemoveFailureIsNotProgress2454=== CONT TestServerBacksOffOnAcceptErrors2455=== CONT TestServerStalledClientDoesNotBlockShutdown24562026/11/01 16:19:16 ERROR Accept failed error="too many open files"2457=== CONT TestWorkerUploadsAndRemoves2458=== CONT TestQueueSingleOwnerAcrossModes2459=== CONT TestDrainTimeout2460=== CONT TestQueueRemoveLargeClosure2461=== CONT TestQueueConcurrentWriters2462=== CONT TestWorkerPrunesClosureDeps2463=== CONT TestQueueFetchRemoveLifecycle2464=== CONT TestQueueRetryMovesToBack2465=== CONT TestQueueFetchBatchLimit2466=== CONT TestQueueRemove2467=== CONT TestQueueDeduplication2468=== CONT TestWorkerSkipsGCdPaths2469=== CONT TestQueueEnqueueAndFetch2470=== CONT TestDrainIsolatesPoisonPath2471=== CONT TestDrainGivesUpWhenServerDown2472=== CONT TestRunNotBlockedByPoisonHead24732026/11/01 16:19:16 ERROR Accept failed error="too many open files"24742026/11/01 16:19:16 INFO Upload queue status pending=324752026/11/01 16:19:16 INFO Upload queue status pending=224762026/11/01 16:19:16 INFO Uploading batch count=124772026/11/01 16:19:16 ERROR Upload failed error="upload failed" count=124782026/11/01 16:19:16 INFO Uploading batch count=124792026/11/01 16:19:16 ERROR Upload failed error="upload failed" count=124802026/11/01 16:19:16 INFO Uploading batch count=124812026/11/01 16:19:16 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2083093830/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat2083093830/002/locked/aaa: permission denied"24822026/11/01 16:19:16 INFO Upload queue status pending=224832026/11/01 16:19:16 INFO Uploading batch count=424842026/11/01 16:19:16 ERROR Upload failed error="upload failed" count=424852026/11/01 16:19:16 ERROR Accept failed error="too many open files"2486--- PASS: TestQueueFetchBatchLimit (0.02s)24872026/11/01 16:19:16 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath2141546541/002/bbb24882026/11/01 16:19:16 INFO Uploading batch count=224892026/11/01 16:19:16 INFO Upload queue status pending=22490--- PASS: TestQueueEnqueueAndFetch (0.02s)24912026/11/01 16:19:16 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths3578906911/002/nonexistent24922026/11/01 16:19:16 INFO Uploading batch count=124932026/11/01 16:19:16 INFO Uploading batch count=22494--- PASS: TestQueueRetryMovesToBack (0.02s)24952026/11/01 16:19:16 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2083093830/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat2083093830/002/locked/aaa: permission denied"24962026/11/01 16:19:16 INFO Uploading batch count=224972026/11/01 16:19:16 ERROR Upload failed error="upload failed" count=224982026/11/01 16:19:16 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2016890061/002/a2499--- PASS: TestQueueDeduplication (0.02s)2500--- PASS: TestQueueFetchRemoveLifecycle (0.02s)25012026/11/01 16:19:16 INFO Uploading batch count=125022026/11/01 16:19:16 INFO Uploading batch count=125032026/11/01 16:19:16 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2083093830/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat2083093830/002/locked/aaa: permission denied"2504--- PASS: TestQueueRemove (0.02s)25052026/11/01 16:19:16 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2016890061/002/b25062026/11/01 16:19:16 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress679167165/002/nonexistent25072026/11/01 16:19:16 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125082026/11/01 16:19:16 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress679167165/002/nonexistent25092026/11/01 16:19:16 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12510--- PASS: TestQueueSingleOwnerAcrossModes (0.02s)25112026/11/01 16:19:16 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress679167165/002/nonexistent25122026/11/01 16:19:16 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125132026/11/01 16:19:16 ERROR Drain finished with paths left in queue remaining=125142026/11/01 16:19:16 ERROR Drain finished with paths left in queue remaining=125152026/11/01 16:19:16 INFO Uploading batch count=125162026/11/01 16:19:16 ERROR Upload failed error="upload failed" count=125172026/11/01 16:19:16 INFO Uploading batch count=225182026/11/01 16:19:16 ERROR Upload failed error="upload failed" count=225192026/11/01 16:19:16 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2016890061/002/c25202026/11/01 16:19:16 INFO Uploading batch count=12521--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)25222026/11/01 16:19:16 ERROR Upload failed error="upload failed" count=125232026/11/01 16:19:16 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2016890061/002/d2524--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)25252026/11/01 16:19:16 INFO Uploading batch count=125262026/11/01 16:19:16 ERROR Upload failed error="upload failed" count=125272026/11/01 16:19:16 INFO Uploading batch count=225282026/11/01 16:19:16 ERROR Upload failed error="upload failed" count=225292026/11/01 16:19:16 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2016890061/002/e2530--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)25312026/11/01 16:19:16 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2016890061/002/f25322026/11/01 16:19:16 ERROR Drain finished with paths left in queue remaining=125332026/11/01 16:19:16 ERROR Drain finished with paths left in queue remaining=102534--- PASS: TestDrainIsolatesPoisonPath (0.02s)2535--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2536--- PASS: TestWorkerPrunesClosureDeps (0.04s)2537--- PASS: TestWorkerUploadsAndRemoves (0.04s)25382026/11/01 16:19:16 ERROR Accept failed error="too many open files"2539--- PASS: TestWorkerSkipsGCdPaths (0.04s)2540--- PASS: TestQueueRemoveLargeClosure (0.05s)25412026/11/01 16:19:16 ERROR Accept failed error="too many open files"25422026/11/01 16:19:16 ERROR Accept failed error="too many open files"25432026/11/01 16:19:16 ERROR Failed to decode request error="read unix /build/hook1767863775/test.sock->@: i/o timeout"25442026/11/01 16:19:16 ERROR Failed to write response error="write unix /build/hook1767863775/test.sock->@: i/o timeout"2545--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)2546--- PASS: TestQueueConcurrentWriters (0.21s)25472026/11/01 16:19:16 ERROR Upload failed error="context deadline exceeded" count=225482026/11/01 16:19:16 ERROR Drain finished with paths left in queue remaining=42549--- PASS: TestDrainTimeout (0.22s)25502026/11/01 16:19:17 ERROR Accept failed error="too many open files"25512026/11/01 16:19:17 ERROR Accept failed error="too many open files"2552--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)25532026/11/01 16:19:17 INFO Uploading batch count=125542026/11/01 16:19:17 INFO Uploading batch count=125552026/11/01 16:19:17 INFO Uploading batch count=125562026/11/01 16:19:17 ERROR Upload failed error="upload failed" count=125572026/11/01 16:19:17 INFO Uploading batch count=125582026/11/01 16:19:17 ERROR Upload failed error="upload failed" count=125592026/11/01 16:19:17 INFO Uploading batch count=125602026/11/01 16:19:17 ERROR Upload failed error="upload failed" count=125612026/11/01 16:19:17 INFO Uploading batch count=125622026/11/01 16:19:17 ERROR Upload failed error="upload failed" count=125632026/11/01 16:19:17 ERROR Drain finished with paths left in queue remaining=12564--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2565PASS2566Running signing tests...2567=== RUN TestExternalSigner2568=== PAUSE TestExternalSigner2569=== RUN TestExternalSignerWrongPublicKey2570=== PAUSE TestExternalSignerWrongPublicKey2571=== RUN TestExternalSignerErrors2572=== PAUSE TestExternalSignerErrors2573=== RUN TestExternalSignerRestartsAfterCrash2574=== PAUSE TestExternalSignerRestartsAfterCrash2575=== RUN TestExternalSignerProgramErrorKeepsProcess2576=== PAUSE TestExternalSignerProgramErrorKeepsProcess2577=== RUN TestExternalSignerClose2578=== PAUSE TestExternalSignerClose2579=== RUN TestExternalSignerRejectsInvalidPublicKey2580=== PAUSE TestExternalSignerRejectsInvalidPublicKey2581=== RUN TestExternalSignerCancellation2582=== PAUSE TestExternalSignerCancellation2583=== RUN TestGenerateFingerprint2584=== PAUSE TestGenerateFingerprint2585=== RUN TestParseSigningKey2586=== PAUSE TestParseSigningKey2587=== RUN TestSign2588=== PAUSE TestSign2589=== RUN TestSignBatch2590=== PAUSE TestSignBatch2591=== RUN TestNilKeyPublicKey2592=== PAUSE TestNilKeyPublicKey2593=== RUN TestSignErrors2594=== PAUSE TestSignErrors2595=== CONT TestExternalSigner2596=== CONT TestExternalSignerCancellation2597=== CONT TestGenerateFingerprint2598=== CONT TestExternalSignerErrors2599=== CONT TestExternalSignerRejectsInvalidPublicKey2600=== RUN TestExternalSignerErrors/exit_at_startup2601=== PAUSE TestExternalSignerErrors/exit_at_startup2602=== RUN TestExternalSignerErrors/wrong_shape2603=== PAUSE TestExternalSignerErrors/wrong_shape2604=== RUN TestExternalSignerErrors/missing_signatures2605=== PAUSE TestExternalSignerErrors/missing_signatures2606=== RUN TestExternalSignerErrors/too_few_signatures2607=== RUN TestExternalSignerRejectsInvalidPublicKey/#002608=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002609=== CONT TestSignBatch2610=== CONT TestSignErrors2611=== CONT TestNilKeyPublicKey2612=== CONT TestParseSigningKey2613=== CONT TestSign2614=== CONT TestExternalSignerWrongPublicKey2615=== CONT TestExternalSignerRestartsAfterCrash2616=== CONT TestExternalSignerProgramErrorKeepsProcess2617=== RUN TestGenerateFingerprint/basic_with_references2618=== CONT TestExternalSignerClose2619=== PAUSE TestExternalSignerErrors/too_few_signatures2620=== RUN TestParseSigningKey/valid_32-byte_key2621=== PAUSE TestParseSigningKey/valid_32-byte_key2622=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2623=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2624=== RUN TestParseSigningKey/no_colon2625=== PAUSE TestParseSigningKey/no_colon2626=== RUN TestParseSigningKey/empty_name2627=== PAUSE TestParseSigningKey/empty_name2628=== PAUSE TestGenerateFingerprint/basic_with_references2629=== RUN TestExternalSignerErrors/invalid_signature_base642630=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2631--- PASS: TestNilKeyPublicKey (0.00s)2632=== RUN TestParseSigningKey/invalid_base642633=== PAUSE TestParseSigningKey/invalid_base642634=== RUN TestGenerateFingerprint/no_references2635=== RUN TestParseSigningKey/wrong_length2636=== PAUSE TestParseSigningKey/wrong_length2637=== CONT TestParseSigningKey/valid_32-byte_key2638=== PAUSE TestGenerateFingerprint/no_references2639=== CONT TestParseSigningKey/invalid_base642640=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2641=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2642=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2643=== PAUSE TestExternalSignerErrors/invalid_signature_base642644=== CONT TestParseSigningKey/empty_name2645=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2646=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2647=== CONT TestParseSigningKey/wrong_length2648=== CONT TestParseSigningKey/no_colon2649=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2650=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2651=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2652=== RUN TestSignErrors/nil_key2653=== PAUSE TestSignErrors/nil_key2654=== RUN TestSignErrors/nil_narinfo2655=== PAUSE TestSignErrors/nil_narinfo2656=== RUN TestSignErrors/invalid_narinfo2657=== PAUSE TestSignErrors/invalid_narinfo2658=== RUN TestSignErrors/canceled2659=== PAUSE TestSignErrors/canceled2660=== CONT TestSignErrors/nil_key2661=== CONT TestSignErrors/canceled2662--- PASS: TestSign (0.00s)2663=== CONT TestSignErrors/invalid_narinfo2664=== RUN TestExternalSignerErrors/invalid_JSON2665=== PAUSE TestExternalSignerErrors/invalid_JSON2666=== RUN TestExternalSignerErrors/wrong_id2667=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2668=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2669=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2670=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2671=== CONT TestExternalSignerRejectsInvalidPublicKey/#002672=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2673=== RUN TestGenerateFingerprint/invalid_nar_hash_length2674=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2675=== RUN TestGenerateFingerprint/invalid_store_path_prefix2676=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2677=== RUN TestGenerateFingerprint/invalid_reference_prefix2678=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2679=== CONT TestGenerateFingerprint/basic_with_references2680=== CONT TestGenerateFingerprint/invalid_store_path_prefix2681=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2682=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2683=== CONT TestGenerateFingerprint/invalid_nar_hash_length2684=== CONT TestSignErrors/nil_narinfo2685--- PASS: TestSignBatch (0.00s)2686=== PAUSE TestExternalSignerErrors/wrong_id2687=== RUN TestExternalSignerErrors/null_signatures2688=== PAUSE TestExternalSignerErrors/null_signatures2689=== RUN TestExternalSignerErrors/unrequested_key2690=== PAUSE TestExternalSignerErrors/unrequested_key2691=== RUN TestExternalSignerErrors/program_error2692=== PAUSE TestExternalSignerErrors/program_error2693=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2694=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2695=== CONT TestGenerateFingerprint/invalid_reference_prefix2696=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2697=== CONT TestGenerateFingerprint/no_references2698--- PASS: TestParseSigningKey (0.00s)2699 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2700 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2701 --- PASS: TestParseSigningKey/empty_name (0.00s)2702 --- PASS: TestParseSigningKey/wrong_length (0.00s)2703 --- PASS: TestParseSigningKey/no_colon (0.00s)2704 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2705=== RUN TestExternalSignerErrors/exit_on_request2706--- PASS: TestExternalSignerWrongPublicKey (0.00s)2707=== PAUSE TestExternalSignerErrors/exit_on_request2708=== RUN TestExternalSignerErrors/null2709=== PAUSE TestExternalSignerErrors/null2710--- PASS: TestSignErrors (0.00s)2711 --- PASS: TestSignErrors/nil_key (0.00s)2712 --- PASS: TestSignErrors/canceled (0.00s)2713 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2714 --- PASS: TestSignErrors/nil_narinfo (0.00s)2715=== RUN TestExternalSignerErrors/wrong_signatures_shape2716=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2717=== RUN TestExternalSignerErrors/missing_signature_name2718=== PAUSE TestExternalSignerErrors/missing_signature_name2719=== RUN TestExternalSignerErrors/wrong_signature_name2720=== PAUSE TestExternalSignerErrors/wrong_signature_name2721=== RUN TestExternalSignerErrors/wrong_signature_length2722=== PAUSE TestExternalSignerErrors/wrong_signature_length2723=== CONT TestExternalSignerErrors/exit_at_startup2724=== CONT TestExternalSignerErrors/missing_signatures2725--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2726 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2727 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2728 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2729 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2730 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2731--- PASS: TestGenerateFingerprint (0.00s)2732 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2733 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2734 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2735 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2736 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2737 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2738 --- PASS: TestGenerateFingerprint/no_references (0.00s)2739=== CONT TestExternalSignerErrors/program_error2740--- PASS: TestExternalSignerClose (0.00s)2741=== CONT TestExternalSignerErrors/wrong_signature_length2742=== CONT TestExternalSignerErrors/null2743=== CONT TestExternalSignerErrors/wrong_signatures_shape2744=== CONT TestExternalSignerErrors/wrong_signature_name2745=== CONT TestExternalSignerErrors/exit_on_request2746=== CONT TestExternalSignerErrors/invalid_JSON2747=== CONT TestExternalSignerErrors/missing_signature_name2748=== CONT TestExternalSignerErrors/too_few_signatures2749=== CONT TestExternalSignerErrors/null_signatures2750--- PASS: TestExternalSigner (0.01s)2751=== CONT TestExternalSignerErrors/wrong_id2752--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2753=== CONT TestExternalSignerErrors/invalid_signature_base642754=== CONT TestExternalSignerErrors/unrequested_key2755=== CONT TestExternalSignerErrors/wrong_shape2756--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2757--- PASS: TestExternalSignerErrors (0.00s)2758 --- PASS: TestExternalSignerErrors/exit_at_startup (0.00s)2759 --- PASS: TestExternalSignerErrors/missing_signatures (0.00s)2760 --- PASS: TestExternalSignerErrors/program_error (0.00s)2761 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.00s)2762 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.00s)2763 --- PASS: TestExternalSignerErrors/wrong_id (0.00s)2764 --- PASS: TestExternalSignerErrors/null_signatures (0.00s)2765 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)2766 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)2767 --- PASS: TestExternalSignerErrors/unrequested_key (0.00s)2768 --- PASS: TestExternalSignerErrors/null (0.01s)2769 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)2770 --- PASS: TestExternalSignerErrors/too_few_signatures (0.01s)2771 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.00s)2772 --- PASS: TestExternalSignerErrors/exit_on_request (0.01s)2773 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)2774--- PASS: TestExternalSignerCancellation (0.02s)2775PASS2776Running OpenBao signer tests...2777=== RUN TestSign2778=== PAUSE TestSign2779=== RUN TestSignErrors2780=== PAUSE TestSignErrors2781=== RUN TestServe2782=== PAUSE TestServe2783=== RUN TestServeRejectsGarbage2784=== PAUSE TestServeRejectsGarbage2785=== CONT TestSign2786=== CONT TestServeRejectsGarbage2787=== CONT TestSignErrors2788=== CONT TestServe2789--- PASS: TestServeRejectsGarbage (0.00s)2790=== RUN TestSignErrors/http_error2791=== PAUSE TestSignErrors/http_error2792=== RUN TestSignErrors/invalid_json2793=== PAUSE TestSignErrors/invalid_json2794=== RUN TestSignErrors/no_prefix2795=== PAUSE TestSignErrors/no_prefix2796=== RUN TestSignErrors/invalid_base642797=== PAUSE TestSignErrors/invalid_base642798=== CONT TestSignErrors/http_error2799=== CONT TestSignErrors/no_prefix2800--- PASS: TestServe (0.00s)2801=== CONT TestSignErrors/invalid_json2802=== CONT TestSignErrors/invalid_base642803--- PASS: TestSign (0.00s)2804--- PASS: TestSignErrors (0.00s)2805 --- PASS: TestSignErrors/no_prefix (0.00s)2806 --- PASS: TestSignErrors/invalid_json (0.00s)2807 --- PASS: TestSignErrors/invalid_base64 (0.00s)2808 --- PASS: TestSignErrors/http_error (0.00s)2809PASS