niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #441
· raw
1tribuchet: building on mac022Running 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 TestRetryTimeoutOutlastsMaxRetries118=== CONT TestScriptTokenCachesUntilRefresh119=== CONT TestSupersededNARStillUploadsListing120=== RUN TestSupersededNARStillUploadsListing/small_NAR121=== PAUSE TestSupersededNARStillUploadsListing/small_NAR122=== RUN TestSupersededNARStillUploadsListing/dump_cut_short123=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short124=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails125=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails126=== CONT TestScriptTokenScriptFails127=== CONT TestParsePathInfoJSONMultiplePaths128=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths129=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths130=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths131=== CONT TestScriptTokenBadJSON132=== CONT TestScriptTokenEmptyCommand133--- PASS: TestScriptTokenEmptyCommand (0.00s)134=== CONT TestParsePathInfoJSON135=== RUN TestParsePathInfoJSON/Nix_format136=== PAUSE TestParsePathInfoJSON/Nix_format137=== RUN TestParsePathInfoJSON/Lix_format138=== CONT TestScriptTokenEmptyToken139=== CONT TestSetClientTLSDoesNotMutateDefaultTransport140=== CONT TestSetClientTLS141=== CONT TestStreamPushStopsWhenCanceled142=== CONT TestClientSignaturesByStorePath143--- PASS: TestClientSignaturesByStorePath (0.00s)144=== CONT TestStreamPushReportsSkippedPaths145--- PASS: TestStreamPushStopsWhenCanceled (0.00s)146=== CONT TestGetStorePathHash147=== RUN TestGetStorePathHash/valid_store_path148=== PAUSE TestGetStorePathHash/valid_store_path149=== RUN TestGetStorePathHash/basename_without_hyphen_should_error150=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error151=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error152=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error153=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error154=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error155=== CONT TestConvertHashToNix32156=== RUN TestConvertHashToNix32/SRI_format_to_Nix32157=== CONT TestStreamPushReportsSignatures158=== CONT TestStreamPushRequestLine159=== CONT TestStreamPushGivesUpOnDeadServer160=== CONT TestStreamPushIsolatesFailures161=== CONT TestStreamPushBatchesUnderLoad162=== CONT TestStreamPushReportsEveryPath163=== CONT TestShellSplitErrors164=== CONT TestShellSplit165=== CONT TestDoWithRetry_FinalResponseBodyReadable166=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths167=== PAUSE TestParsePathInfoJSON/Lix_format168=== CONT TestPathInfoCACompatibility169=== CONT TestPathInfoHashCompatibility170=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)171=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)172=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon173=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon174=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI175=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI176=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512177=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512178=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32179=== CONT TestDumpPathWriterError180=== RUN TestConvertHashToNix32/already_Nix32_format181=== PAUSE TestConvertHashToNix32/already_Nix32_format182=== RUN TestConvertHashToNix32/invalid_format183=== PAUSE TestConvertHashToNix32/invalid_format184=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false185=== CONT TestEncodeNixBase32186=== RUN TestPathInfoCACompatibility/null_ca_field187=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false188=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true189=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true190--- PASS: TestShellSplitErrors (0.00s)191--- PASS: TestShellSplit (0.00s)192=== CONT TestDumpPathSingleFile193=== CONT TestEncodeNixBase32WithRealHash194=== RUN TestParsePathInfoJSON/empty_input195=== CONT TestDumpPathMatchesNix196--- PASS: TestEncodeNixBase32WithRealHash (0.00s)197=== CONT TestDoWithRetry_BodyReplayedViaGetBody198=== PAUSE TestParsePathInfoJSON/empty_input199=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer200--- PASS: TestScriptTokenScriptFails (0.00s)201=== CONT TestResolveStorePath2022026/10/27 08:43:10 ERROR Upload failed error="connection refused" count=202032026/10/27 08:43:10 ERROR Server seems unavailable, giving up on batch untried=17204=== PAUSE TestPathInfoCACompatibility/null_ca_field205--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)206=== CONT TestScriptTokenNoExpiryRerunsEveryCall207--- PASS: TestStreamPushReportsSkippedPaths (0.00s)208=== CONT TestFileTokenReadsAndCaches2092026/10/27 08:43:10 WARN Rate limiter enabled after throttle name=server-test rate=52102026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:640672112026/10/27 08:43:10 WARN Rate limiter backed off name=server-test rate=5212--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.00s)213=== CONT TestStaticToken214--- PASS: TestStaticToken (0.00s)215=== CONT TestFilterOversizedClosures216--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)217=== CONT TestFileTokenMissing218--- PASS: TestFileTokenReadsAndCaches (0.00s)219=== CONT TestFileTokenEmpty220--- PASS: TestFileTokenMissing (0.00s)221=== CONT TestUploadMultipart_SupersededByPeer222=== RUN TestEncodeNixBase32/test_string_hash223=== PAUSE TestEncodeNixBase32/test_string_hash224=== RUN TestEncodeNixBase32/empty_input225=== PAUSE TestEncodeNixBase32/empty_input226=== RUN TestSetClientTLSErrors/missing_cert_file227=== PAUSE TestSetClientTLSErrors/missing_cert_file228=== RUN TestSetClientTLSErrors/missing_key_file229=== PAUSE TestSetClientTLSErrors/missing_key_file230=== RUN TestSetClientTLSErrors/missing_ca_file231=== PAUSE TestSetClientTLSErrors/missing_ca_file232=== RUN TestSetClientTLSErrors/invalid_ca_file233=== PAUSE TestSetClientTLSErrors/invalid_ca_file234=== CONT TestUploadMultipart_PartsInParallel235=== RUN TestParsePathInfoJSON/whitespace_only236=== PAUSE TestParsePathInfoJSON/whitespace_only237=== RUN TestParsePathInfoJSON/invalid_JSON238=== PAUSE TestParsePathInfoJSON/invalid_JSON239=== CONT TestPartSizeForNAR2402026/10/27 08:43:10 ERROR Upload failed error=boom count=12412026/10/27 08:43:10 ERROR Upload failed error="bad path" count=3242--- PASS: TestStreamPushReportsEveryPath (0.01s)243=== CONT TestRateLimiterFeedback244=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess245=== RUN TestPathInfoCACompatibility/old_string_format_-_text246--- PASS: TestFileTokenEmpty (0.00s)247--- PASS: TestResolveStorePath (0.01s)2482026/10/27 08:43:10 ERROR Upload failed error=boom count=1249--- PASS: TestStreamPushIsolatesFailures (0.01s)250--- PASS: TestStreamPushReportsSignatures (0.01s)251=== CONT TestRegisterUploadedObjectReusesConnections252=== RUN TestSetClientTLS/rejects_connection_without_client_cert253=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert254=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA255=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA256=== RUN TestSetClientTLS/preserves_debug_logging_transport257=== PAUSE TestSetClientTLS/preserves_debug_logging_transport258=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry259=== RUN TestFilterOversizedClosures/no_limit_keeps_everything2602026/10/27 08:43:10 WARN Rate limiter enabled after throttle name=server-test rate=5261=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything262=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped263=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped264=== RUN TestFilterOversizedClosures/all_closures_skipped265=== PAUSE TestFilterOversizedClosures/all_closures_skipped266=== RUN TestUploadMultipart_SupersededByPeer/exists267=== PAUSE TestUploadMultipart_SupersededByPeer/exists268=== RUN TestUploadMultipart_SupersededByPeer/missing269=== PAUSE TestUploadMultipart_SupersededByPeer/missing270=== CONT TestUploadMultipart_FailedPartBufferNotReused271=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text272=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive273=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive2742026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:64063275=== RUN TestPathInfoCACompatibility/new_structured_format_-_text276=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica277=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun278=== CONT TestCaseHackSuffix279--- PASS: TestDoServerRequestAttachesToken (0.01s)280=== CONT TestSupersededNARStillUploadsListing/small_NAR281=== CONT TestSupersededNARStillUploadsListing/dump_cut_short282=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails283--- PASS: TestScriptTokenEmptyToken (0.01s)284--- PASS: TestScriptTokenBadJSON (0.02s)285=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text286=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method287=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method288=== CONT TestGetStorePathHash/valid_store_path289=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)290=== RUN TestPartSizeForNAR/zero_stays_at_minimum291=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum292=== RUN TestPartSizeForNAR/small_stays_at_minimum293=== PAUSE TestPartSizeForNAR/small_stays_at_minimum294=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum295=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum296=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts297=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts298=== RUN TestPartSizeForNAR/1_TiB299=== PAUSE TestPartSizeForNAR/1_TiB300=== RUN TestPartSizeForNAR/5_TiB_S3_max_object301=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object302=== RUN TestPartSizeForNAR/capped_at_5_GiB303=== PAUSE TestPartSizeForNAR/capped_at_5_GiB304=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error305=== CONT TestConvertHashToNix32/SRI_format_to_Nix32306=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error307=== CONT TestConvertHashToNix32/already_Nix32_format308=== RUN TestRateLimiterFeedback/429_enables_limiter309=== PAUSE TestRateLimiterFeedback/429_enables_limiter310=== RUN TestRateLimiterFeedback/503_enables_limiter311=== PAUSE TestRateLimiterFeedback/503_enables_limiter312=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter313=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter314=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter315=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter316=== CONT TestGetStorePathHash/basename_without_hyphen_should_error317--- PASS: TestGetStorePathHash (0.00s)318 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)319 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)320 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)321 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)322=== CONT TestConvertHashToNix32/invalid_format323--- PASS: TestConvertHashToNix32 (0.00s)324 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)325 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)326 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)327=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths328=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths329--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)330 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)331 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)332=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI333=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true334=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512335=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false336=== CONT TestSetClientTLSErrors/missing_cert_file337=== CONT TestEncodeNixBase32/test_string_hash338=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon339=== CONT TestSetClientTLSErrors/missing_ca_file340--- PASS: TestStreamPushBatchesUnderLoad (0.00s)341 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)342 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)343=== CONT TestSetClientTLSErrors/invalid_ca_file344--- PASS: TestPathInfoHashCompatibility (0.00s)345 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)346 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)347 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)348 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)349=== CONT TestParsePathInfoJSON/Nix_format350=== CONT TestSetClientTLSErrors/missing_key_file351=== CONT TestParsePathInfoJSON/whitespace_only352=== CONT TestParsePathInfoJSON/invalid_JSON353=== CONT TestParsePathInfoJSON/empty_input354=== CONT TestParsePathInfoJSON/Lix_format355=== CONT TestSetClientTLS/rejects_connection_without_client_cert356--- PASS: TestParsePathInfoJSON (0.01s)357 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)358 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)359 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)360 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)361 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)362=== CONT TestFilterOversizedClosures/no_limit_keeps_everything363=== CONT TestUploadMultipart_SupersededByPeer/exists3642026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:640633652026/10/27 08:43:10 WARN Rate limiter enabled after throttle name=s3-test rate=53662026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:641003672026/10/27 08:43:10 WARN Rate limiter enabled after throttle name=server-test rate=5368=== CONT TestEncodeNixBase32/empty_input3692026/10/27 08:43:10 INFO Uploading abc-hello (1.0GB)370--- PASS: TestEncodeNixBase32 (0.01s)371 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)372 --- PASS: TestEncodeNixBase32/empty_input (0.00s)373=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA374=== CONT TestSetClientTLS/preserves_debug_logging_transport3752026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:640683762026/10/27 08:43:10 INFO Garbage collection started3772026/10/27 08:43:10 WARN Rate limiter backed off name=server-test rate=53782026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:640683792026/10/27 08:43:10 INFO Uploading abc-hello (1.0GB)3802026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:64063381--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.03s)382=== CONT TestFilterOversizedClosures/all_closures_skipped3832026/10/27 08:43:10 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-small nar_size=1000 max_nar_size=50384--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.02s)385=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped386=== CONT TestUploadMultipart_SupersededByPeer/missing3872026/10/27 08:43:10 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=2000388--- PASS: TestFilterOversizedClosures (0.01s)389 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)390 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)391 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)392=== CONT TestPathInfoCACompatibility/null_ca_field393=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method394=== CONT TestPartSizeForNAR/zero_stays_at_minimum395=== CONT TestRateLimiterFeedback/429_enables_limiter396--- PASS: TestSetClientTLSErrors (0.01s)397 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)398 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)399 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)400 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)4012026/10/27 08:43:10 INFO Garbage collection started402--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)403=== CONT TestPartSizeForNAR/capped_at_5_GiB404=== CONT TestPartSizeForNAR/5_TiB_S3_max_object405=== CONT TestPartSizeForNAR/1_TiB406=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts407=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum408=== CONT TestPartSizeForNAR/small_stays_at_minimum409--- PASS: TestPartSizeForNAR (0.01s)410 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)411 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)412 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)413 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)414 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)415 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)416 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)4172026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:64063418--- PASS: TestStreamPushRequestLine (0.03s)419=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive420=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter421=== CONT TestPathInfoCACompatibility/new_structured_format_-_text422=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter4232026/10/27 08:43:10 WARN Rate limiter enabled after throttle name=server-test rate=54242026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:641644252026/10/27 08:43:10 WARN Rate limiter enabled after throttle name=s3-test rate=5426=== CONT TestRateLimiterFeedback/503_enables_limiter427=== CONT TestPathInfoCACompatibility/old_string_format_-_text428--- PASS: TestPathInfoCACompatibility (0.02s)429 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)430 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)431 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)432 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)433 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)4342026/10/27 08:43:10 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=0435--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)436 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)437 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)4382026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:640634392026/10/27 08:43:10 WARN Rate limiter backed off name=server-test rate=54402026/10/27 08:43:10 WARN Rate limiter enabled after throttle name=server-test rate=54412026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:641794422026/10/27 08:43:10 WARN Rate limiter backed off name=server-test rate=5443--- PASS: TestRateLimiterFeedback (0.01s)444 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)445 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)446 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)447 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)4482026/10/27 08:43:10 WARN Garbage collection finished on another replica. Its statistics are not available here449--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)4502026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:640634512026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:640634522026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:640634532026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:640634542026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:640634552026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:64063456--- PASS: TestRegisterUploadedObjectReusesConnections (0.04s)4572026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:640634582026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:640634592026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:64063460--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)461--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)4622026/10/27 08:43:10 http: TLS handshake error from 127.0.0.1:64162: remote error: tls: bad certificate4632026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:64063464--- PASS: TestSetClientTLS (0.01s)465 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)466 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)467 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.03s)4682026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:64063469--- PASS: TestDumpPathSingleFile (0.05s)4702026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:640634712026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:640634722026/10/27 08:43:10 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:64063473--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.06s)4742026/10/27 08:43:10 INFO Uploading abc-hello (1.0GB)475--- PASS: TestCaseHackSuffix (0.06s)476--- PASS: TestDumpPathWriterError (0.07s)4772026/10/27 08:43:10 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:64107/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:64107/part/24782026/10/27 08:43:10 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"479--- PASS: TestDumpPathMatchesNix (0.10s)480--- PASS: TestSupersededNARStillUploadsListing (0.00s)481 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.02s)482 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.02s)483 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.56s)484--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.57s)485--- PASS: TestUploadMultipart_PartsInParallel (0.63s)4862026/10/27 08:43:11 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:64069/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:64069/api/uploads/complete4872026/10/27 08:43:11 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:64069/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:64069/api/uploads/complete4882026/10/27 08:43:11 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4892026/10/27 08:43:11 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4902026/10/27 08:43:11 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:64069/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:64069/api/uploads/complete4912026/10/27 08:43:11 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"492--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)493--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)494PASS495Running server tests...496The files belonging to this database system will be owned by user "_tribuchetbld5".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 /private/var/tb/5/scratch/a23fa3231491b957/build/postgres1828401662/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 /private/var/tb/5/scratch/a23fa3231491b957/build/postgres1828401662/data -l logfile start522523/private/var/tb/5/scratch/a23fa3231491b957/build/postgres1828401662:5432 - no response5242026-10-27 08:43:12.048 UTC [78900] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5252026-10-27 08:43:12.048 UTC [78900] LOG: listening on Unix socket "/private/var/tb/5/scratch/a23fa3231491b957/build/postgres1828401662/.s.PGSQL.5432"5262026-10-27 08:43:12.050 UTC [78907] LOG: database system was shut down at 2026-10-27 08:43:12 UTC5272026-10-27 08:43:12.051 UTC [78900] LOG: database system is ready to accept connections528/private/var/tb/5/scratch/a23fa3231491b957/build/postgres1828401662:5432 - accepting connections529{"timestamp":"2026-10-27T08:43:12.2673Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"8e97592c-ce43-49ab-96a7-ad39bb08396c","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}530=== RUN TestService_AuthMiddleware531=== PAUSE TestService_AuthMiddleware532=== RUN TestService_AuthMiddleware_MTLSProxyHeader533=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader534=== RUN TestService_AuthMiddleware_MTLSBoundSubjects535=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects536=== RUN TestService_ReadAuthMiddleware537=== PAUSE TestService_ReadAuthMiddleware538=== RUN TestService_AuthMiddleware_OIDC539=== PAUSE TestService_AuthMiddleware_OIDC540=== RUN TestService_RequireScope_OIDC541=== PAUSE TestService_RequireScope_OIDC542=== RUN TestService_ReadScope_PublicByDefault543=== PAUSE TestService_ReadScope_PublicByDefault544=== RUN TestCacheConfigHandler545=== PAUSE TestCacheConfigHandler546=== RUN TestCacheStatsHandler547=== PAUSE TestCacheStatsHandler548=== RUN TestClientCADerivations549=== PAUSE TestClientCADerivations550=== RUN TestClientErrorHandling551=== PAUSE TestClientErrorHandling552=== RUN TestClientIntegration553=== PAUSE TestClientIntegration554=== RUN TestClientMultipleUploads555=== PAUSE TestClientMultipleUploads556=== RUN TestClientWithDependencies557=== PAUSE TestClientWithDependencies558=== RUN TestClientSharedPathCommittedMidPush559=== PAUSE TestClientSharedPathCommittedMidPush560=== RUN TestPinProtectsFromGC561=== PAUSE TestPinProtectsFromGC562=== RUN TestClientPushesUseOnePush563=== PAUSE TestClientPushesUseOnePush564=== RUN TestClientFallsBackToClosures565=== PAUSE TestClientFallsBackToClosures566=== RUN TestDeleteClosuresRacingPins567=== PAUSE TestDeleteClosuresRacingPins568=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock569=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock570=== RUN TestResolveDBConnectionString571=== PAUSE TestResolveDBConnectionString572=== RUN TestConnectWaitsForAPeerMigration573=== PAUSE TestConnectWaitsForAPeerMigration574=== RUN TestLeadElectsOneAndHandsOver575=== PAUSE TestLeadElectsOneAndHandsOver576=== RUN TestLeadIncumbentWinsAfterRestart5772026/10/27 08:43:12 INFO lead: acquired remote=192.0.2.1:12345782026/10/27 08:43:13 INFO lead: released remote=192.0.2.1:12345792026/10/27 08:43:13 INFO lead: acquired remote=192.0.2.1:12345802026/10/27 08:43:14 INFO lead: released remote=192.0.2.1:1234581--- PASS: TestLeadIncumbentWinsAfterRestart (1.89s)582=== RUN TestLeadIncumbentAnnouncesAtOnce583=== PAUSE TestLeadIncumbentAnnouncesAtOnce584=== RUN TestLeadEndsOnShutdown585=== PAUSE TestLeadEndsOnShutdown586=== RUN TestLeadEndsWhenItsConnectionHangs5872026/10/27 08:43:14 INFO lead: acquired remote=192.0.2.1:12345882026-10-27 08:43:15.610 UTC [78956] FATAL: terminating connection due to administrator command5892026/10/27 08:43:15 INFO lead: acquired remote=192.0.2.1:12345902026/10/27 08:43:16 WARN lead: lock connection lost error="timeout: context deadline exceeded"5912026/10/27 08:43:16 INFO lead: released remote=192.0.2.1:12345922026/10/27 08:43:17 INFO lead: released remote=192.0.2.1:1234593--- PASS: TestLeadEndsWhenItsConnectionHangs (2.74s)594=== RUN TestGCAdvisoryLockBlocksConcurrentRun595=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun596=== RUN TestGCBugBareHashReferences597=== PAUSE TestGCBugBareHashReferences598=== RUN TestGCMetrics599=== PAUSE TestGCMetrics600=== RUN TestPushDedupSurvivesConcurrentGC601=== PAUSE TestPushDedupSurvivesConcurrentGC602=== RUN TestDeduplicatedObjectsRecordedAsPending603=== PAUSE TestDeduplicatedObjectsRecordedAsPending604=== RUN TestGCSweepSkipsPendingObjects605=== PAUSE TestGCSweepSkipsPendingObjects606=== RUN TestTombstonedObjectOfferedWithoutWaiting607=== PAUSE TestTombstonedObjectOfferedWithoutWaiting608=== RUN TestGCSweepDeliversEachKeyOnce609=== PAUSE TestGCSweepDeliversEachKeyOnce610=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection611=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection612=== RUN TestForceGCDuringPushOffersSweptObject613=== PAUSE TestForceGCDuringPushOffersSweptObject614=== RUN TestFailedS3DeleteKeepsTombstone615=== PAUSE TestFailedS3DeleteKeepsTombstone616=== RUN TestSweepSkipsRowsLockedByPush617=== PAUSE TestSweepSkipsRowsLockedByPush618=== RUN TestRegisterCompletedObjectNeedsPendingRow619=== PAUSE TestRegisterCompletedObjectNeedsPendingRow620=== RUN TestGetExistingObjectsLocksRows621=== PAUSE TestGetExistingObjectsLocksRows622=== RUN TestSweepRechecksPendingAfterLocking623=== PAUSE TestSweepRechecksPendingAfterLocking624=== RUN TestPushWaitsForSweepHoldingRow625=== PAUSE TestPushWaitsForSweepHoldingRow626=== RUN TestCommitRacingPendingCleanupKeepsObjects627=== PAUSE TestCommitRacingPendingCleanupKeepsObjects628=== RUN TestGCEndsOnShutdown629=== PAUSE TestGCEndsOnShutdown630=== RUN TestGCTaskStore_StartNew631=== PAUSE TestGCTaskStore_StartNew632=== RUN TestGCTaskStore_DeduplicateSameParams633=== PAUSE TestGCTaskStore_DeduplicateSameParams634=== RUN TestGCTaskStore_ConflictDifferentParams635=== PAUSE TestGCTaskStore_ConflictDifferentParams636=== RUN TestGCTaskStore_GetEmpty637=== PAUSE TestGCTaskStore_GetEmpty638=== RUN TestGCTaskStore_GetReturnsLatest639=== PAUSE TestGCTaskStore_GetReturnsLatest640=== RUN TestGCTaskStore_CompletedAllowsNewTask641=== PAUSE TestGCTaskStore_CompletedAllowsNewTask642=== RUN TestGCTaskStore_PhaseUpdates643=== PAUSE TestGCTaskStore_PhaseUpdates644=== RUN TestGCTaskStore_Fail645=== PAUSE TestGCTaskStore_Fail646=== RUN TestGracefulShutdownDrainsInflight647=== PAUSE TestGracefulShutdownDrainsInflight648=== RUN TestService_healthCheckHandler649=== PAUSE TestService_healthCheckHandler650=== RUN TestService_readinessHandler651=== PAUSE TestService_readinessHandler652=== RUN TestGenerateLandingPage653=== PAUSE TestGenerateLandingPage654=== RUN TestCacheConfigHandlerMaxNarSize655=== PAUSE TestCacheConfigHandlerMaxNarSize656=== RUN TestCreatePendingClosureRejectsOversizedNAR657=== PAUSE TestCreatePendingClosureRejectsOversizedNAR658=== RUN TestNARDeduplicationMetadataUploadBug659=== PAUSE TestNARDeduplicationMetadataUploadBug660=== RUN TestMetricsInventory661=== PAUSE TestMetricsInventory662=== RUN TestMetricsCommit663=== PAUSE TestMetricsCommit664=== RUN TestService_NativeMTLS665=== PAUSE TestService_NativeMTLS666=== RUN TestServerTLSConfig667=== PAUSE TestServerTLSConfig668=== RUN TestMultipartCleanup669=== PAUSE TestMultipartCleanup670=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded671=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded672=== RUN TestPendingCleanupUsesOneCutoff673=== PAUSE TestPendingCleanupUsesOneCutoff674=== RUN TestObjectStatsTrigger675=== PAUSE TestObjectStatsTrigger676=== RUN TestObjectStatsUpdatedOncePerCommit677=== PAUSE TestObjectStatsUpdatedOncePerCommit678=== RUN TestOrphanedObjectsGC679=== PAUSE TestOrphanedObjectsGC680=== RUN TestOrphanedObjectsGCStressTest681=== PAUSE TestOrphanedObjectsGCStressTest682=== RUN TestCreatePin_ReservedPins683=== PAUSE TestCreatePin_ReservedPins684=== RUN TestPresentReportsOnlyClosureRoots685=== PAUSE TestPresentReportsOnlyClosureRoots686=== RUN TestPresentRefreshesOnlyStaleClosures687=== PAUSE TestPresentRefreshesOnlyStaleClosures688=== RUN TestPresentNotReportedWhileGCDeletesClosure689=== PAUSE TestPresentNotReportedWhileGCDeletesClosure690=== RUN TestParseSingleRange691=== PAUSE TestParseSingleRange692=== RUN TestProxyHeadersOnlyTrustedOnSocket6932026/10/27 08:43:17 INFO Starting HTTP server address=127.0.0.1:642056942026/10/27 08:43:17 INFO Starting HTTP server address=proxy.sock6952026/10/27 08:43:17 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6962026/10/27 08:43:17 INFO Shutdown signal received, draining in-flight requests timeout=10s697--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.16s)698=== RUN TestIsValidCachePath699=== PAUSE TestIsValidCachePath700=== RUN TestReadProxyNarinfo701=== PAUSE TestReadProxyNarinfo702=== RUN TestReadProxyNarinfoAlreadyDecompressed703=== PAUSE TestReadProxyNarinfoAlreadyDecompressed704=== RUN TestReadProxyContentNegotiation705=== PAUSE TestReadProxyContentNegotiation706=== RUN TestReadProxyNarStreaming707=== PAUSE TestReadProxyNarStreaming708=== RUN TestReadProxy404709=== PAUSE TestReadProxy404710=== RUN TestReadProxyInvalidPath711=== PAUSE TestReadProxyInvalidPath712=== RUN TestReadProxyHead713=== PAUSE TestReadProxyHead714=== RUN TestReadProxyOutlastsServerWriteTimeout715=== PAUSE TestReadProxyOutlastsServerWriteTimeout716=== RUN TestReadProxyConditionalGet717=== PAUSE TestReadProxyConditionalGet718=== RUN TestReadProxyRootRedirectsToIndexHTML719=== PAUSE TestReadProxyRootRedirectsToIndexHTML720=== RUN TestReadProxyDisabled721=== PAUSE TestReadProxyDisabled722=== RUN TestReadRedirectNar723=== PAUSE TestReadRedirectNar724=== RUN TestReadRedirectKeepsNarinfoProxied725=== PAUSE TestReadRedirectKeepsNarinfoProxied726=== RUN TestReadProxyRangeRequest727=== PAUSE TestReadProxyRangeRequest728=== RUN TestReadRedirectUsesPublicS3URL729=== PAUSE TestReadRedirectUsesPublicS3URL730=== RUN TestPush_OverlappingRootsStoreOneRowPerKey731=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey732=== RUN TestPush_CompleteCommitsEveryRoot733=== PAUSE TestPush_CompleteCommitsEveryRoot734=== RUN TestPush_RepeatedRootCommitsOnce735=== PAUSE TestPush_RepeatedRootCommitsOnce736=== RUN TestPush_CompleteWaitsForCleanupOfThePush737=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush738=== RUN TestPush_RootsAreLockedInByteOrder739=== PAUSE TestPush_RootsAreLockedInByteOrder740=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit741=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit742=== RUN TestPush_RejectsBadRequests743=== PAUSE TestPush_RejectsBadRequests744=== RUN TestPush_SignsNarinfosOfItsPendingObjects745=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects746=== RUN TestRedundantMultipartUpload747=== PAUSE TestRedundantMultipartUpload748=== RUN TestCompleteMultipartUpload_ErrorButObjectExists749=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists750=== RUN TestCompletedNarNotReofferedAcrossClosures751=== PAUSE TestCompletedNarNotReofferedAcrossClosures752=== RUN TestPresignedUploadRegisteredBeforeCommit753=== PAUSE TestPresignedUploadRegisteredBeforeCommit754=== RUN TestService_Rustfstest755=== PAUSE TestService_Rustfstest756=== RUN TestParseSize757=== PAUSE TestParseSize758=== RUN TestSkippedUploadsHandler759=== PAUSE TestSkippedUploadsHandler760=== RUN TestSystemdListenerNotActivated761--- PASS: TestSystemdListenerNotActivated (0.00s)762=== RUN TestWatchdogBeatsWhenHealthy763--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)764=== RUN TestWatchdogSkipsWhenUnhealthy7652026/10/27 08:43:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7662026/10/27 08:43:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7672026/10/27 08:43:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7682026/10/27 08:43:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7692026/10/27 08:43:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/10/27 08:43:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/10/27 08:43:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/10/27 08:43:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/10/27 08:43:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/10/27 08:43:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"775--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)776=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle777=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle778=== RUN TestProxyWriteTimeout779=== PAUSE TestProxyWriteTimeout780=== RUN TestPendingClosureWriteTimeout781=== PAUSE TestPendingClosureWriteTimeout782=== RUN TestIsValidUploadKey783=== PAUSE TestIsValidUploadKey784=== RUN TestUploadHandlersRejectInvalidKeys785=== PAUSE TestUploadHandlersRejectInvalidKeys786=== RUN TestUploadHandlersRejectOversizedBody787=== PAUSE TestUploadHandlersRejectOversizedBody788=== RUN TestService_cleanupPendingClosuresHandler789=== PAUSE TestService_cleanupPendingClosuresHandler790=== RUN TestService_createPendingClosureHandler791=== PAUSE TestService_createPendingClosureHandler792=== RUN TestService_verifyS3Integrity793=== PAUSE TestService_verifyS3Integrity794=== RUN TestCompleteMultipartUnregistered795=== PAUSE TestCompleteMultipartUnregistered796=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT797=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT798=== CONT TestReadProxyRangeRequest799=== CONT TestUploadHandlersRejectOversizedBody800=== CONT TestReadProxyNarinfo801=== CONT TestPresignedUploadRegisteredBeforeCommit802=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit803=== CONT TestReadRedirectKeepsNarinfoProxied804=== CONT TestService_AuthMiddleware805=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT806=== CONT TestService_verifyS3Integrity807=== CONT TestCompleteMultipartUnregistered808=== CONT TestService_createPendingClosureHandler809=== CONT TestReadRedirectNar810=== CONT TestReadProxyDisabled811=== CONT TestReadProxyRootRedirectsToIndexHTML812=== CONT TestReadProxyConditionalGet813=== CONT TestReadProxyOutlastsServerWriteTimeout814=== CONT TestReadProxyHead815=== CONT TestReadProxyInvalidPath816=== CONT TestReadProxy404817=== CONT TestReadProxyNarStreaming818=== CONT TestReadProxyContentNegotiation819=== CONT TestReadProxyNarinfoAlreadyDecompressed820=== CONT TestService_Rustfstest821=== CONT TestService_cleanupPendingClosuresHandler822=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart823=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart824=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts825=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts826=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure827=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure828=== CONT TestPush_RepeatedRootCommitsOnce8292026/10/27 08:43:18 INFO Received uploads request method=POST path=/api/pending_closures8302026/10/27 08:43:18 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst8312026/10/27 08:43:18 INFO Received uploads request method=POST path=/api/pending_closures832--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.74s)833=== CONT TestPush_RootsAreLockedInByteOrder834--- PASS: TestReadProxyRangeRequest (0.91s)835=== CONT TestPush_CompleteWaitsForCleanupOfThePush836--- PASS: TestReadRedirectKeepsNarinfoProxied (1.17s)837=== CONT TestPush_OverlappingRootsStoreOneRowPerKey8382026/10/27 08:43:18 INFO Received uploads request method=POST path=/api/pending_closures839--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.88s)840=== CONT TestPush_CompleteCommitsEveryRoot8412026/10/27 08:43:19 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>842--- PASS: TestReadProxyNarinfo (2.23s)843=== CONT TestReadRedirectUsesPublicS3URL8442026/10/27 08:43:19 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"845--- PASS: TestService_AuthMiddleware (2.39s)846=== CONT TestProxyWriteTimeout847=== RUN TestProxyWriteTimeout/narinfo848=== PAUSE TestProxyWriteTimeout/narinfo849=== RUN TestProxyWriteTimeout/1_GiB_nar850=== PAUSE TestProxyWriteTimeout/1_GiB_nar851=== RUN TestProxyWriteTimeout/10_GiB_nar852=== PAUSE TestProxyWriteTimeout/10_GiB_nar853=== RUN TestProxyWriteTimeout/unknown_size854=== PAUSE TestProxyWriteTimeout/unknown_size855=== CONT TestUploadHandlersRejectInvalidKeys856=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info857=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info858=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal859=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal860=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key861=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key862=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key863=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key864=== CONT TestIsValidUploadKey865=== RUN TestIsValidUploadKey/narinfo866=== PAUSE TestIsValidUploadKey/narinfo867=== RUN TestIsValidUploadKey/nar_zst868=== PAUSE TestIsValidUploadKey/nar_zst869=== RUN TestIsValidUploadKey/nar_xz870=== PAUSE TestIsValidUploadKey/nar_xz871=== RUN TestIsValidUploadKey/nar_plain872=== PAUSE TestIsValidUploadKey/nar_plain873=== RUN TestIsValidUploadKey/listing874=== PAUSE TestIsValidUploadKey/listing875=== RUN TestIsValidUploadKey/build_log876=== PAUSE TestIsValidUploadKey/build_log877=== RUN TestIsValidUploadKey/build_log_home-manager_file878=== PAUSE TestIsValidUploadKey/build_log_home-manager_file879=== RUN TestIsValidUploadKey/build_log_plus_in_name880=== PAUSE TestIsValidUploadKey/build_log_plus_in_name881=== RUN TestIsValidUploadKey/build_log_question_mark882=== PAUSE TestIsValidUploadKey/build_log_question_mark883=== RUN TestIsValidUploadKey/build_log_equals884=== PAUSE TestIsValidUploadKey/build_log_equals885=== RUN TestIsValidUploadKey/realisation886=== PAUSE TestIsValidUploadKey/realisation887=== RUN TestIsValidUploadKey/realisation_plus_in_output888=== PAUSE TestIsValidUploadKey/realisation_plus_in_output889=== RUN TestIsValidUploadKey/nix-cache-info890=== PAUSE TestIsValidUploadKey/nix-cache-info891=== RUN TestIsValidUploadKey/index.html892=== PAUSE TestIsValidUploadKey/index.html893=== RUN TestIsValidUploadKey/narinfo_key,_nar_type894=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type895=== RUN TestIsValidUploadKey/nar_key,_narinfo_type896=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type897=== RUN TestIsValidUploadKey/listing_key,_narinfo_type898=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type899=== RUN TestIsValidUploadKey/traversal900=== PAUSE TestIsValidUploadKey/traversal901=== RUN TestIsValidUploadKey/traversal_nar902=== PAUSE TestIsValidUploadKey/traversal_nar903=== RUN TestIsValidUploadKey/absolute904=== PAUSE TestIsValidUploadKey/absolute905=== RUN TestIsValidUploadKey/empty_key906=== PAUSE TestIsValidUploadKey/empty_key907=== RUN TestIsValidUploadKey/unknown_type908=== PAUSE TestIsValidUploadKey/unknown_type909=== CONT TestPendingClosureWriteTimeout910=== RUN TestPendingClosureWriteTimeout/empty911=== PAUSE TestPendingClosureWriteTimeout/empty912=== RUN TestPendingClosureWriteTimeout/400_objects913=== PAUSE TestPendingClosureWriteTimeout/400_objects914=== RUN TestPendingClosureWriteTimeout/670k_objects915=== PAUSE TestPendingClosureWriteTimeout/670k_objects916=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline917=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline918=== CONT TestSkippedUploadsHandler9192026/10/27 08:43:19 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000920--- PASS: TestSkippedUploadsHandler (0.00s)921=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle9222026/10/27 08:43:20 INFO Received push request method=POST path=/api/pushes9232026/10/27 08:43:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9242026/10/27 08:43:20 INFO Received complete push request method=POST path=/api/pushes/1/complete9252026/10/27 08:43:20 INFO Completed push id=1 objects=4 duration=52.170917ms9262026/10/27 08:43:20 INFO Received push request method=POST path=/api/pushes9272026/10/27 08:43:20 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YWQwNDlhMjUtOGE1OC00ZTc3LWI2ZGYtZjdkY2UzYTlmNzgxLmFlMTRlMjlhLWNkZGItNGEwYy1hODkxLTNkMTQ2YWU2ZGFmM3gxNzkzMDkwNTk4ODQ4NjQ5MDAw parts=109282026/10/27 08:43:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9292026/10/27 08:43:20 INFO Completed upload id=1 objects=2 duration=18.319667ms9302026/10/27 08:43:20 INFO Received uploads request method=POST path=/api/pending_closures9312026/10/27 08:43:20 INFO Received uploads request method=POST path=/api/pending_closures9322026/10/27 08:43:20 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9332026/10/27 08:43:20 WARN Found objects in DB but missing from S3, will re-upload count=1934--- PASS: TestService_verifyS3Integrity (2.82s)935=== CONT TestParseSize936--- PASS: TestParseSize (0.00s)937=== CONT TestRedundantMultipartUpload9382026/10/27 08:43:20 INFO Aborted multipart uploads count=0 kept=09392026/10/27 08:43:20 WARN Force mode enabled - objects will be deleted immediately without grace period9402026/10/27 08:43:20 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=09412026/10/27 08:43:20 INFO Vacuumed table table=pending_closures9422026/10/27 08:43:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9432026/10/27 08:43:20 INFO Vacuumed table table=pending_objects9442026/10/27 08:43:20 INFO Vacuumed table table=multipart_uploads9452026/10/27 08:43:20 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst946--- PASS: TestCompleteMultipartUnregistered (2.89s)947=== CONT TestCompletedNarNotReofferedAcrossClosures9482026/10/27 08:43:20 INFO Vacuumed table table=closures9492026/10/27 08:43:20 INFO Vacuumed table table=objects9502026/10/27 08:43:20 INFO Received complete push request method=POST path=/api/pushes/2/complete9512026/10/27 08:43:20 INFO Completed push id=2 objects=4 duration=5.864291ms952--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (2.94s)953=== CONT TestCompleteMultipartUpload_ErrorButObjectExists954--- PASS: TestReadRedirectNar (3.13s)955=== CONT TestGetExistingObjectsLocksRows956--- PASS: TestReadProxyNarStreaming (3.25s)957=== CONT TestIsValidCachePath958=== RUN TestIsValidCachePath/narinfo959=== PAUSE TestIsValidCachePath/narinfo960=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars961=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars962=== RUN TestIsValidCachePath/nar_zst963=== PAUSE TestIsValidCachePath/nar_zst964=== RUN TestIsValidCachePath/nar_xz965=== PAUSE TestIsValidCachePath/nar_xz966=== RUN TestIsValidCachePath/nar_bz2967=== PAUSE TestIsValidCachePath/nar_bz2968=== RUN TestIsValidCachePath/nar_uncompressed969=== PAUSE TestIsValidCachePath/nar_uncompressed970=== RUN TestIsValidCachePath/ls971=== PAUSE TestIsValidCachePath/ls972=== RUN TestIsValidCachePath/log973=== PAUSE TestIsValidCachePath/log974=== RUN TestIsValidCachePath/realisation975=== PAUSE TestIsValidCachePath/realisation976=== RUN TestIsValidCachePath/nix-cache-info977=== PAUSE TestIsValidCachePath/nix-cache-info978=== RUN TestIsValidCachePath/index.html979=== PAUSE TestIsValidCachePath/index.html980=== RUN TestIsValidCachePath/traversal_parent981=== PAUSE TestIsValidCachePath/traversal_parent982=== RUN TestIsValidCachePath/traversal_in_middle983=== PAUSE TestIsValidCachePath/traversal_in_middle984=== RUN TestIsValidCachePath/invalid_char_e985=== PAUSE TestIsValidCachePath/invalid_char_e986=== RUN TestIsValidCachePath/invalid_char_u987=== PAUSE TestIsValidCachePath/invalid_char_u988=== RUN TestIsValidCachePath/random_path989=== PAUSE TestIsValidCachePath/random_path990=== RUN TestIsValidCachePath/empty991=== PAUSE TestIsValidCachePath/empty992=== RUN TestIsValidCachePath/leading_slash993=== PAUSE TestIsValidCachePath/leading_slash994=== RUN TestIsValidCachePath/wrong_extension995=== PAUSE TestIsValidCachePath/wrong_extension996=== RUN TestIsValidCachePath/short_hash997=== PAUSE TestIsValidCachePath/short_hash998=== CONT TestParseSingleRange999=== RUN TestParseSingleRange/none1000=== PAUSE TestParseSingleRange/none1001=== RUN TestParseSingleRange/unknown_unit1002=== PAUSE TestParseSingleRange/unknown_unit1003=== RUN TestParseSingleRange/multi-range_ignored1004=== PAUSE TestParseSingleRange/multi-range_ignored1005=== RUN TestParseSingleRange/malformed_no_dash1006=== PAUSE TestParseSingleRange/malformed_no_dash1007=== RUN TestParseSingleRange/malformed_both_empty1008=== PAUSE TestParseSingleRange/malformed_both_empty1009=== RUN TestParseSingleRange/malformed_end_before_start1010=== PAUSE TestParseSingleRange/malformed_end_before_start1011=== RUN TestParseSingleRange/closed1012=== PAUSE TestParseSingleRange/closed1013=== RUN TestParseSingleRange/open-ended1014=== PAUSE TestParseSingleRange/open-ended1015=== RUN TestParseSingleRange/end_clamped_to_size1016=== PAUSE TestParseSingleRange/end_clamped_to_size1017=== RUN TestParseSingleRange/suffix1018=== PAUSE TestParseSingleRange/suffix1019=== RUN TestParseSingleRange/suffix_exceeds_size1020=== PAUSE TestParseSingleRange/suffix_exceeds_size1021=== RUN TestParseSingleRange/single_byte1022=== PAUSE TestParseSingleRange/single_byte1023=== RUN TestParseSingleRange/start_past_EOF1024=== PAUSE TestParseSingleRange/start_past_EOF1025=== RUN TestParseSingleRange/start_far_past_EOF1026=== PAUSE TestParseSingleRange/start_far_past_EOF1027=== CONT TestPresentNotReportedWhileGCDeletesClosure1028=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1029=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1030=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1031=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1032=== CONT TestPresentRefreshesOnlyStaleClosures10332026/10/27 08:43:20 INFO Received uploads request method=POST path=/api/pending_closures10342026/10/27 08:43:20 INFO Received uploads request method=POST path=/api/pending_closures10352026/10/27 08:43:20 INFO Received uploads request method=POST path=/api/pending_closures10362026/10/27 08:43:21 INFO Received uploads request method=POST path=/api/pending_closures1037--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (3.70s)1038=== CONT TestPresentReportsOnlyClosureRoots1039--- PASS: TestService_Rustfstest (3.81s)1040=== CONT TestCreatePin_ReservedPins10412026/10/27 08:43:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64265/oidc1042--- PASS: TestReadProxyInvalidPath (4.07s)1043=== CONT TestOrphanedObjectsGCStressTest1044--- PASS: TestReadProxyNarinfoAlreadyDecompressed (4.32s)1045=== CONT TestOrphanedObjectsGC10462026/10/27 08:43:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1047--- PASS: TestReadProxyConditionalGet (4.55s)1048=== CONT TestObjectStatsUpdatedOncePerCommit10492026/10/27 08:43:22 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YWQwNDlhMjUtOGE1OC00ZTc3LWI2ZGYtZjdkY2UzYTlmNzgxLmVlM2VkNGM1LTNkYzItNDAyOS05MjNjLTBmZWY5MDBiMjQyMngxNzkzMDkwNjAwODYzMTI5MDAw parts=1010502026/10/27 08:43:22 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10512026/10/27 08:43:22 INFO Completed upload id=1 objects=2 duration=6.64825ms10522026/10/27 08:43:22 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010532026/10/27 08:43:22 INFO Received uploads request method=POST path=/api/pending_closures10542026/10/27 08:43:22 INFO Starting cleanup of old closures method=DELETE path=/api/closures10552026/10/27 08:43:22 INFO Aborted multipart uploads count=0 kept=010562026/10/27 08:43:22 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=010572026/10/27 08:43:22 INFO Vacuumed table table=pending_closures10582026/10/27 08:43:22 INFO Vacuumed table table=pending_objects10592026/10/27 08:43:22 INFO Vacuumed table table=multipart_uploads10602026/10/27 08:43:22 INFO Vacuumed table table=closures10612026/10/27 08:43:22 INFO Vacuumed table table=objects10622026/10/27 08:43:22 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001063--- PASS: TestService_createPendingClosureHandler (4.81s)1064=== CONT TestObjectStatsTrigger1065--- PASS: TestReadProxyDisabled (4.95s)1066=== CONT TestPendingCleanupUsesOneCutoff1067--- PASS: TestReadProxy404 (5.08s)1068=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1069--- PASS: TestReadProxyHead (5.20s)1070=== CONT TestMultipartCleanup1071--- PASS: TestReadProxyContentNegotiation (5.73s)1072=== CONT TestServerTLSConfig1073=== RUN TestServerTLSConfig/no_client_CA1074=== PAUSE TestServerTLSConfig/no_client_CA1075=== RUN TestServerTLSConfig/missing_CA_file1076=== PAUSE TestServerTLSConfig/missing_CA_file1077=== RUN TestServerTLSConfig/not_a_PEM_file1078=== PAUSE TestServerTLSConfig/not_a_PEM_file1079=== CONT TestService_NativeMTLS10802026/10/27 08:43:23 INFO Received cleanup request method=DELETE path=/api/pending_closures10812026/10/27 08:43:23 INFO Aborted multipart uploads count=0 kept=010822026/10/27 08:43:23 INFO Received uploads request method=POST path=/api/pending_closures10832026/10/27 08:43:23 INFO Received cleanup request method=DELETE path=/api/pending_closures10842026/10/27 08:43:23 INFO Aborted multipart uploads count=1 kept=010852026/10/27 08:43:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10862026-10-27 08:43:23.334 UTC [79045] ERROR: Closure does not exist: id=110872026-10-27 08:43:23.334 UTC [79045] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10882026-10-27 08:43:23.334 UTC [79045] STATEMENT: -- name: CommitPendingClosure :one1089 SELECT commit_pending_closure($1::bigint)::bigint1090 1091--- PASS: TestService_cleanupPendingClosuresHandler (5.85s)1092=== CONT TestMetricsCommit10932026/10/27 08:43:23 INFO Received push request method=POST path=/api/pushes10942026/10/27 08:43:23 INFO Received complete push request method=POST path=/api/pushes/1/complete10952026/10/27 08:43:23 INFO Completed push id=1 objects=4 duration=37.868167ms1096--- PASS: TestPush_RepeatedRootCommitsOnce (6.07s)1097=== CONT TestMetricsInventory10982026/10/27 08:43:23 INFO Received push request method=POST path=/api/pushes1099--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (5.21s)1100=== CONT TestNARDeduplicationMetadataUploadBug11012026/10/27 08:43:23 INFO Received push request method=POST path=/api/pushes11022026/10/27 08:43:24 INFO Received push request method=POST path=/api/pushes11032026-10-27 08:43:24.167 UTC [79117] ERROR: could not obtain lock on row in relation "closures"11042026-10-27 08:43:24.167 UTC [79117] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11052026-10-27 08:43:24.171 UTC [79117] ERROR: could not obtain lock on row in relation "closures"11062026-10-27 08:43:24.171 UTC [79117] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11072026-10-27 08:43:24.175 UTC [79117] ERROR: could not obtain lock on row in relation "closures"11082026-10-27 08:43:24.175 UTC [79117] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11092026-10-27 08:43:24.176 UTC [79117] ERROR: could not obtain lock on row in relation "closures"11102026-10-27 08:43:24.176 UTC [79117] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11112026-10-27 08:43:24.179 UTC [79117] ERROR: could not obtain lock on row in relation "closures"11122026-10-27 08:43:24.179 UTC [79117] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1113--- PASS: TestPush_RootsAreLockedInByteOrder (6.03s)1114=== CONT TestCreatePendingClosureRejectsOversizedNAR11152026/10/27 08:43:24 INFO Received uploads request method=POST path=/api/pending_closures1116--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1117=== CONT TestCacheConfigHandlerMaxNarSize1118--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1119=== CONT TestGenerateLandingPage1120--- PASS: TestGenerateLandingPage (0.00s)1121=== CONT TestService_readinessHandler11222026-10-27 08:43:24.228 UTC [79112] ERROR: Push does not exist: id=111232026-10-27 08:43:24.228 UTC [79112] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE11242026-10-27 08:43:24.228 UTC [79112] STATEMENT: SELECT commit_push($1)1125--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (5.91s)1126=== CONT TestService_healthCheckHandler11272026/10/27 08:43:24 INFO Received push request method=POST path=/api/pushes11282026/10/27 08:43:24 INFO Received complete push request method=POST path=/api/pushes/1/complete11292026/10/27 08:43:24 INFO Completed push id=1 objects=6 duration=23.300167ms1130--- PASS: TestPush_CompleteCommitsEveryRoot (5.05s)1131=== CONT TestGracefulShutdownDrainsInflight11322026/10/27 08:43:24 INFO Starting HTTP server address=127.0.0.1:6433611332026/10/27 08:43:24 INFO Shutdown signal received, draining in-flight requests timeout=10s1134=== CONT TestGCTaskStore_Fail1135=== CONT TestGCTaskStore_PhaseUpdates1136=== CONT TestGCTaskStore_CompletedAllowsNewTask1137=== CONT TestGCTaskStore_GetReturnsLatest1138=== CONT TestGCTaskStore_GetEmpty1139=== CONT TestGCTaskStore_ConflictDifferentParams1140=== CONT TestGCTaskStore_DeduplicateSameParams1141=== CONT TestGCTaskStore_StartNew1142=== CONT TestGCEndsOnShutdown1143=== RUN TestGCEndsOnShutdown/before_the_run1144--- PASS: TestGracefulShutdownDrainsInflight (0.08s)1145--- PASS: TestGCTaskStore_Fail (0.00s)1146--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1147--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1148--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1149--- PASS: TestGCTaskStore_GetEmpty (0.00s)1150--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1151--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1152--- PASS: TestGCTaskStore_StartNew (0.00s)1153=== PAUSE TestGCEndsOnShutdown/before_the_run1154=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1155=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1156=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1157=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1158=== CONT TestCommitRacingPendingCleanupKeepsObjects1159--- PASS: TestReadRedirectUsesPublicS3URL (4.91s)1160=== CONT TestPushWaitsForSweepHoldingRow11612026/10/27 08:43:24 INFO Received uploads request method=POST path=/api/pending_closures11622026/10/27 08:43:25 INFO Received uploads request method=POST path=/api/pending_closures11632026/10/27 08:43:25 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11642026/10/27 08:43:25 INFO Received uploads request method=POST path=/api/pending_closures11652026/10/27 08:43:25 INFO Received uploads request method=POST path=/api/pending_closures11662026/10/27 08:43:25 INFO Received uploads request method=POST path=/api/pending_closures1167--- PASS: TestGetExistingObjectsLocksRows (5.52s)1168=== CONT TestSweepRechecksPendingAfterLocking11692026/10/27 08:43:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11702026/10/27 08:43:26 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YWQwNDlhMjUtOGE1OC00ZTc3LWI2ZGYtZjdkY2UzYTlmNzgxLjNlZGM3ZTFjLWNlNmEtNDAzMS04NTAwLTk0OWVlYTBhMzAyZXgxNzkzMDkwNjA1NzQ0NzYwMDAw11712026/10/27 08:43:26 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YWQwNDlhMjUtOGE1OC00ZTc3LWI2ZGYtZjdkY2UzYTlmNzgxLjNlZGM3ZTFjLWNlNmEtNDAzMS04NTAwLTk0OWVlYTBhMzAyZXgxNzkzMDkwNjA1NzQ0NzYwMDAw parts=11172--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (5.78s)1173=== CONT TestPush_SignsNarinfosOfItsPendingObjects1174--- PASS: TestPresentRefreshesOnlyStaleClosures (5.79s)1175=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1176--- PASS: TestPresentReportsOnlyClosureRoots (5.71s)1177=== CONT TestRegisterCompletedObjectNeedsPendingRow11782026/10/27 08:43:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1179--- PASS: TestReadProxyOutlastsServerWriteTimeout (9.64s)1180=== CONT TestSweepSkipsRowsLockedByPush11812026/10/27 08:43:27 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11822026/10/27 08:43:27 WARN Refused reserved pin name=worker-x86_64-linux11832026/10/27 08:43:27 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11842026/10/27 08:43:27 INFO Received create pin request method=POST path=/api/pins/my-app11852026/10/27 08:43:27 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1186--- PASS: TestCreatePin_ReservedPins (5.83s)1187=== CONT TestFailedS3DeleteKeepsTombstone11882026/10/27 08:43:27 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YWQwNDlhMjUtOGE1OC00ZTc3LWI2ZGYtZjdkY2UzYTlmNzgxLjVjNjdmYTEyLTI0MGUtNGUyMS1hNjI5LTc1YzRhMTk2ZWU2OHgxNzkzMDkwNjA1MTE2OTAwMDAw parts=1211892026/10/27 08:43:27 INFO Received uploads request method=POST path=/api/pending_closures11902026/10/27 08:43:27 INFO Received uploads request method=POST path=/api/pending_closures11912026/10/27 08:43:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11922026/10/27 08:43:27 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YWQwNDlhMjUtOGE1OC00ZTc3LWI2ZGYtZjdkY2UzYTlmNzgxLmMxZmQxNWVlLTk3MzEtNGI4ZC1hNjM1LWY4M2QzNjhkYWUxY3gxNzkzMDkwNjA1MzgxMDE3MDAw parts=1211932026/10/27 08:43:27 INFO Received uploads request method=POST path=/api/pending_closures1194--- PASS: TestCompletedNarNotReofferedAcrossClosures (7.22s)1195=== CONT TestForceGCDuringPushOffersSweptObject1196=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1197=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1198=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1199=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1200=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1201--- PASS: TestObjectStatsUpdatedOncePerCommit (6.38s)1202=== CONT TestGCSweepDeliversEachKeyOnce1203--- PASS: TestObjectStatsTrigger (6.30s)1204=== CONT TestTombstonedObjectOfferedWithoutWaiting12052026/10/27 08:43:28 INFO Received uploads request method=POST path=/api/pending_closures12062026/10/27 08:43:29 INFO Received uploads request method=POST path=/api/pending_closures12072026/10/27 08:43:29 INFO Received cleanup request method=DELETE path=/api/pending_closures12082026/10/27 08:43:29 INFO Received uploads request method=POST path=/api/pending_closures12092026/10/27 08:43:29 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1210--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (7.01s)1211=== CONT TestGCSweepSkipsPendingObjects12122026/10/27 08:43:29 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YWQwNDlhMjUtOGE1OC00ZTc3LWI2ZGYtZjdkY2UzYTlmNzgxLjc4MDVlMmRlLTNkYTgtNDMwZC1iMjJlLTBhY2Y4NjA3ODkxZHgxNzkzMDkwNjA3MjQ1ODgzMDAw error="Get \"http://127.0.0.1:1/bucket34/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"12132026/10/27 08:43:29 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YWQwNDlhMjUtOGE1OC00ZTc3LWI2ZGYtZjdkY2UzYTlmNzgxLjE1N2E3MjQxLTQ4OTEtNGM5OC1hYWIzLTIyOWRhZWRlMWFlNXgxNzkzMDkwNjA3MjAxOTkzMDAw parts=1212142026/10/27 08:43:29 INFO Received cleanup request method=DELETE path=/api/pending_closures12152026/10/27 08:43:29 INFO Aborted multipart uploads count=1 kept=01216--- PASS: TestRedundantMultipartUpload (9.43s)1217=== CONT TestDeduplicatedObjectsRecordedAsPending12182026/10/27 08:43:29 INFO Received uploads request method=POST path=/api/pending_closures1219=== NAME TestOrphanedObjectsGC1220 orphaned_objects_gc_test.go:287: GC Test Summary:1221 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1222 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B12232026/10/27 08:43:30 INFO Received cleanup request method=DELETE path=/api/pending_closures1224 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)12252026/10/27 08:43:30 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket47/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""1226 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)12272026/10/27 08:43:30 INFO Aborted multipart uploads count=0 kept=11228 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1229--- PASS: TestOrphanedObjectsGC (8.51s)1230=== CONT TestPushDedupSurvivesConcurrentGC12312026/10/27 08:43:30 INFO Received cleanup request method=DELETE path=/api/pending_closures12322026/10/27 08:43:30 INFO Aborted multipart uploads count=1 kept=01233--- PASS: TestMultipartCleanup (7.69s)1234=== CONT TestGCMetrics12352026/10/27 08:43:30 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12362026/10/27 08:43:30 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1237--- PASS: TestService_NativeMTLS (7.28s)1238=== CONT TestGCBugBareHashReferences12392026/10/27 08:43:30 INFO Received push request method=POST path=/api/pushes12402026/10/27 08:43:30 WARN Rate limiter enabled after throttle name=s3-test rate=512412026/10/27 08:43:30 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1242=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1243 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101244 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001245--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (11.13s)1246=== CONT TestGCAdvisoryLockBlocksConcurrentRun12472026/10/27 08:43:30 INFO Received complete push request method=POST path=/api/pushes/1/complete12482026/10/27 08:43:31 INFO Completed push id=1 objects=4 duration=53.233875ms12492026/10/27 08:43:31 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12502026/10/27 08:43:31 INFO Completed upload id=2 objects=2 duration=1.566292ms1251--- PASS: TestMetricsCommit (7.72s)1252=== CONT TestLeadEndsOnShutdown1253--- PASS: TestMetricsInventory (7.69s)1254=== CONT TestLeadIncumbentAnnouncesAtOnce1255=== NAME TestNARDeduplicationMetadataUploadBug1256 metadata_upload_test.go:48: First store path: /private/var/tb/5/scratch/a23fa3231491b957/build/TestNARDeduplicationMetadataUploadBug3472371167/001/store/bdq4viicajdkddwkdn5f0f48rxy4aanl-file1.txt12572026/10/27 08:43:31 WARN readiness check failed error="closed pool"1258--- PASS: TestService_readinessHandler (7.53s)1259=== CONT TestLeadElectsOneAndHandsOver12602026/10/27 08:43:31 INFO Received push request method=POST path=/api/pushes12612026/10/27 08:43:31 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12622026/10/27 08:43:31 INFO Uploading bdq4viicajdkddwkdn5f0f48rxy4aanl-file1.txt (160B)12632026/10/27 08:43:31 WARN Failed to register uploaded object key=bdq4viicajdkddwkdn5f0f48rxy4aanl.ls error="server returned 404: 404 page not found\n"12642026/10/27 08:43:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12652026/10/27 08:43:31 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12662026/10/27 08:43:31 INFO Signed narinfos id=1 count=112672026/10/27 08:43:31 INFO Uploading 1 narinfos12682026/10/27 08:43:31 INFO Received complete push request method=POST path=/api/pushes/1/complete12692026/10/27 08:43:31 WARN Failed to register uploaded object key=bdq4viicajdkddwkdn5f0f48rxy4aanl.narinfo error="server returned 404: 404 page not found\n"12702026/10/27 08:43:32 INFO Completed push id=1 objects=3 duration=24.656041ms12712026/10/27 08:43:32 INFO Upload complete. (247ms)1272=== NAME TestNARDeduplicationMetadataUploadBug1273 metadata_upload_test.go:54: Retrieved narinfo from S3:1274 StorePath: /private/var/tb/5/scratch/a23fa3231491b957/build/TestNARDeduplicationMetadataUploadBug3472371167/001/store/bdq4viicajdkddwkdn5f0f48rxy4aanl-file1.txt1275 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1276 Compression: zstd1277 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1278 NarSize: 1601279 References: 1280 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1281 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1282 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1283 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1284--- PASS: TestService_healthCheckHandler (7.80s)1285=== CONT TestConnectWaitsForAPeerMigration1286=== NAME TestNARDeduplicationMetadataUploadBug1287 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/5/scratch/a23fa3231491b957/build/TestNARDeduplicationMetadataUploadBug3472371167/001/store/3kn5g8w0025y7i6ldfsw71j235yd3vwa-file2.txt12882026/10/27 08:43:32 INFO Received push request method=POST path=/api/pushes12892026/10/27 08:43:32 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12902026/10/27 08:43:32 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12912026/10/27 08:43:32 WARN Failed to register uploaded object key=3kn5g8w0025y7i6ldfsw71j235yd3vwa.ls error="server returned 404: 404 page not found\n"12922026/10/27 08:43:32 INFO Signed narinfos id=2 count=112932026/10/27 08:43:32 INFO Uploading 1 narinfos12942026/10/27 08:43:32 INFO Received complete push request method=POST path=/api/pushes/2/complete12952026/10/27 08:43:32 WARN Failed to register uploaded object key=3kn5g8w0025y7i6ldfsw71j235yd3vwa.narinfo error="server returned 404: 404 page not found\n"12962026/10/27 08:43:32 INFO Completed push id=2 objects=3 duration=847.833µs12972026/10/27 08:43:32 INFO Upload complete. (176ms)1298 metadata_upload_test.go:76: Retrieved narinfo from S3:1299 StorePath: /private/var/tb/5/scratch/a23fa3231491b957/build/TestNARDeduplicationMetadataUploadBug3472371167/001/store/3kn5g8w0025y7i6ldfsw71j235yd3vwa-file2.txt1300 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1301 Compression: zstd1302 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1303 NarSize: 1601304 References: 1305 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1306 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1307 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1308 {"version":1,"root":{"type":"regular","size":44}}13092026/10/27 08:43:32 INFO Received uploads request method=POST path=/api/pending_closures1310--- PASS: TestNARDeduplicationMetadataUploadBug (8.62s)1311=== CONT TestResolveDBConnectionString1312=== RUN TestResolveDBConnectionString/flag_wins1313=== PAUSE TestResolveDBConnectionString/flag_wins1314=== RUN TestResolveDBConnectionString/file_when_flag_empty1315=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1316=== RUN TestResolveDBConnectionString/missing_file_is_an_error1317=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1318=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1319=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1320=== RUN TestResolveDBConnectionString/nothing_configured1321=== PAUSE TestResolveDBConnectionString/nothing_configured1322=== CONT TestClientErrorHandling1323=== RUN TestClientErrorHandling/InvalidStorePath1324=== PAUSE TestClientErrorHandling/InvalidStorePath1325=== RUN TestClientErrorHandling/InvalidAuthToken1326=== PAUSE TestClientErrorHandling/InvalidAuthToken1327=== RUN TestClientErrorHandling/ServerNotAvailable1328=== PAUSE TestClientErrorHandling/ServerNotAvailable1329=== CONT TestDeleteClosuresRacingPins13302026/10/27 08:43:32 INFO Aborted multipart uploads count=0 kept=01331--- PASS: TestPushWaitsForSweepHoldingRow (8.31s)13322026/10/27 08:43:32 WARN Force mode enabled - objects will be deleted immediately without grace period1333=== CONT TestClientFallsBackToClosures13342026/10/27 08:43:32 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=013352026/10/27 08:43:32 INFO Vacuumed table table=pending_closures13362026/10/27 08:43:32 INFO Vacuumed table table=pending_objects13372026/10/27 08:43:32 INFO Vacuumed table table=multipart_uploads13382026/10/27 08:43:32 INFO Vacuumed table table=closures13392026/10/27 08:43:32 INFO Vacuumed table table=objects1340--- PASS: TestCommitRacingPendingCleanupKeepsObjects (8.55s)1341=== CONT TestClientPushesUseOnePush13422026/10/27 08:43:33 INFO Aborted multipart uploads count=0 kept=013432026/10/27 08:43:33 WARN Force mode enabled - objects will be deleted immediately without grace period13442026/10/27 08:43:33 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013452026/10/27 08:43:33 INFO Vacuumed table table=pending_closures13462026/10/27 08:43:33 INFO Vacuumed table table=pending_objects13472026/10/27 08:43:33 INFO Vacuumed table table=multipart_uploads13482026/10/27 08:43:33 INFO Vacuumed table table=closures13492026/10/27 08:43:33 INFO Vacuumed table table=objects1350--- PASS: TestSweepRechecksPendingAfterLocking (7.10s)1351=== CONT TestPush_RejectsBadRequests13522026/10/27 08:43:33 INFO Received push request method=POST path=/api/pushes13532026/10/27 08:43:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13542026/10/27 08:43:33 INFO Signed narinfos id=1 count=113552026/10/27 08:43:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13562026/10/27 08:43:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13572026/10/27 08:43:33 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"13582026/10/27 08:43:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13592026/10/27 08:43:33 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"13602026/10/27 08:43:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13612026/10/27 08:43:33 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=113622026/10/27 08:43:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13632026/10/27 08:43:33 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1364--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (7.18s)1365=== CONT TestClientWithDependencies1366--- PASS: TestRegisterCompletedObjectNeedsPendingRow (6.99s)1367=== CONT TestClientSharedPathCommittedMidPush13682026/10/27 08:43:34 INFO Received uploads request method=POST path=/api/pending_closures13692026/10/27 08:43:34 INFO Aborted multipart uploads count=0 kept=013702026/10/27 08:43:34 WARN Force mode enabled - objects will be deleted immediately without grace period13712026/10/27 08:43:34 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."13722026/10/27 08:43:34 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1373--- PASS: TestFailedS3DeleteKeepsTombstone (7.27s)1374=== CONT TestService_RequireScope_OIDC13752026/10/27 08:43:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64438/oidc13762026/10/27 08:43:34 INFO Aborted multipart uploads count=0 kept=013772026/10/27 08:43:34 WARN Force mode enabled - objects will be deleted immediately without grace period13782026/10/27 08:43:34 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=013792026/10/27 08:43:34 INFO Vacuumed table table=pending_closures13802026/10/27 08:43:34 INFO Vacuumed table table=pending_objects13812026/10/27 08:43:34 INFO Vacuumed table table=multipart_uploads13822026/10/27 08:43:34 INFO Vacuumed table table=closures13832026/10/27 08:43:34 INFO Vacuumed table table=objects13842026/10/27 08:43:34 INFO Aborted multipart uploads count=0 kept=013852026/10/27 08:43:34 WARN Force mode enabled - objects will be deleted immediately without grace period13862026/10/27 08:43:34 INFO Received uploads request method=POST path=/api/pending_closures13872026/10/27 08:43:34 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=013882026/10/27 08:43:34 INFO Vacuumed table table=pending_closures13892026/10/27 08:43:34 INFO Vacuumed table table=pending_objects1390--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (8.34s)13912026/10/27 08:43:34 INFO Vacuumed table table=multipart_uploads1392=== CONT TestPinProtectsFromGC13932026/10/27 08:43:34 INFO Vacuumed table table=closures13942026/10/27 08:43:34 INFO Vacuumed table table=objects1395--- PASS: TestSweepSkipsRowsLockedByPush (7.78s)1396=== CONT TestClientMultipleUploads1397--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (7.47s)1398=== CONT TestClientCADerivations13992026/10/27 08:43:35 INFO Received uploads request method=POST path=/api/pending_closures1400--- PASS: TestTombstonedObjectOfferedWithoutWaiting (6.54s)1401=== CONT TestClientIntegration14022026/10/27 08:43:35 INFO Aborted multipart uploads count=1 kept=014032026/10/27 08:43:35 INFO Received cleanup request method=DELETE path=/api/pending_closures14042026/10/27 08:43:35 INFO Aborted multipart uploads count=1 kept=01405--- PASS: TestPendingCleanupUsesOneCutoff (12.87s)1406=== CONT TestCacheStatsHandler14072026/10/27 08:43:35 INFO Aborted multipart uploads count=0 kept=014082026/10/27 08:43:35 WARN Force mode enabled - objects will be deleted immediately without grace period14092026/10/27 08:43:35 INFO Received uploads request method=POST path=/api/pending_closures14102026/10/27 08:43:35 INFO Aborted multipart uploads count=0 kept=014112026/10/27 08:43:35 WARN Force mode enabled - objects will be deleted immediately without grace period14122026/10/27 08:43:35 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014132026/10/27 08:43:35 INFO Vacuumed table table=pending_closures14142026/10/27 08:43:36 INFO Vacuumed table table=pending_objects14152026/10/27 08:43:36 INFO Vacuumed table table=multipart_uploads14162026/10/27 08:43:36 INFO Vacuumed table table=closures14172026/10/27 08:43:36 INFO Vacuumed table table=objects14182026/10/27 08:43:36 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=014192026/10/27 08:43:36 INFO Vacuumed table table=pending_closures14202026/10/27 08:43:36 INFO Vacuumed table table=pending_objects14212026/10/27 08:43:36 INFO Received uploads request method=POST path=/api/pending_closures14222026/10/27 08:43:36 INFO Vacuumed table table=multipart_uploads14232026/10/27 08:43:36 INFO Vacuumed table table=closures1424--- PASS: TestGCSweepSkipsPendingObjects (6.58s)1425=== CONT TestCacheConfigHandler1426=== RUN TestCacheConfigHandler/full_config,_no_issuer1427=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1428=== RUN TestCacheConfigHandler/no_cache_url_configured1429=== PAUSE TestCacheConfigHandler/no_cache_url_configured1430=== RUN TestCacheConfigHandler/no_signing_keys1431=== PAUSE TestCacheConfigHandler/no_signing_keys1432=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1433=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1434=== CONT TestService_ReadScope_PublicByDefault14352026/10/27 08:43:36 INFO Vacuumed table table=objects1436--- PASS: TestGCSweepDeliversEachKeyOnce (7.78s)1437=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1438--- PASS: TestDeduplicatedObjectsRecordedAsPending (6.50s)1439=== CONT TestService_AuthMiddleware_MTLSProxyHeader14402026/10/27 08:43:36 INFO Received uploads request method=POST path=/api/pending_closures14412026/10/27 08:43:36 INFO Aborted multipart uploads count=0 kept=014422026/10/27 08:43:36 INFO Aborted multipart uploads count=0 kept=014432026/10/27 08:43:36 WARN Force mode enabled - objects will be deleted immediately without grace period14442026/10/27 08:43:36 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=014452026/10/27 08:43:36 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=014462026/10/27 08:43:36 INFO Vacuumed table table=pending_closures14472026/10/27 08:43:36 INFO Vacuumed table table=pending_closures14482026/10/27 08:43:36 INFO Vacuumed table table=pending_objects14492026/10/27 08:43:36 INFO Vacuumed table table=multipart_uploads14502026/10/27 08:43:36 INFO Vacuumed table table=closures14512026/10/27 08:43:36 INFO Vacuumed table table=objects14522026/10/27 08:43:36 INFO Vacuumed table table=pending_objects1453--- PASS: TestGCMetrics (6.53s)1454=== CONT TestService_ReadAuthMiddleware14552026/10/27 08:43:36 INFO Vacuumed table table=multipart_uploads14562026/10/27 08:43:36 INFO Vacuumed table table=closures14572026/10/27 08:43:36 INFO Vacuumed table table=objects14582026/10/27 08:43:36 INFO Aborted multipart uploads count=0 kept=014592026/10/27 08:43:36 WARN Force mode enabled - objects will be deleted immediately without grace period14602026/10/27 08:43:36 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=014612026/10/27 08:43:36 INFO Vacuumed table table=pending_closures14622026/10/27 08:43:36 INFO Vacuumed table table=pending_objects14632026/10/27 08:43:36 INFO Vacuumed table table=multipart_uploads14642026/10/27 08:43:36 INFO Vacuumed table table=closures14652026/10/27 08:43:36 INFO Vacuumed table table=objects1466--- PASS: TestPushDedupSurvivesConcurrentGC (6.69s)1467=== CONT TestService_AuthMiddleware_OIDC14682026/10/27 08:43:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64457/oidc14692026/10/27 08:43:37 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld5 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1470--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (6.44s)1471=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart14722026/10/27 08:43:37 INFO Received complete multipart upload request method=POST path=/1473--- PASS: TestGCBugBareHashReferences (6.94s)1474=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure14752026/10/27 08:43:37 INFO Received uploads request method=POST path=/1476=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts14772026/10/27 08:43:37 INFO Received request for more parts method=POST path=/1478=== CONT TestProxyWriteTimeout/narinfo1479=== CONT TestProxyWriteTimeout/10_GiB_nar1480=== CONT TestProxyWriteTimeout/unknown_size1481=== CONT TestProxyWriteTimeout/1_GiB_nar1482--- PASS: TestProxyWriteTimeout (0.00s)1483 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1484 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1485 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1486 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1487=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info14882026/10/27 08:43:37 INFO Received uploads request method=POST path=/1489=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key14902026/10/27 08:43:37 INFO Received complete multipart upload request method=POST path=/1491=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key14922026/10/27 08:43:37 INFO Received request for more parts method=POST path=/1493=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal14942026/10/27 08:43:37 INFO Received uploads request method=POST path=/1495--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1496 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.01s)1497 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1498 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1499 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1500=== CONT TestIsValidUploadKey/narinfo1501=== CONT TestIsValidUploadKey/realisation_plus_in_output1502=== CONT TestIsValidUploadKey/unknown_type1503=== CONT TestIsValidUploadKey/empty_key1504=== CONT TestIsValidUploadKey/absolute1505=== CONT TestIsValidUploadKey/traversal_nar1506=== CONT TestIsValidUploadKey/traversal1507=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1508=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1509=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1510=== CONT TestIsValidUploadKey/index.html1511=== CONT TestIsValidUploadKey/nix-cache-info1512=== CONT TestIsValidUploadKey/build_log_home-manager_file1513=== CONT TestIsValidUploadKey/realisation1514=== CONT TestIsValidUploadKey/build_log_equals1515=== CONT TestIsValidUploadKey/build_log_question_mark1516=== CONT TestIsValidUploadKey/build_log_plus_in_name1517=== CONT TestIsValidUploadKey/nar_plain1518=== CONT TestIsValidUploadKey/build_log1519=== CONT TestIsValidUploadKey/listing1520=== CONT TestIsValidUploadKey/nar_xz1521=== CONT TestIsValidUploadKey/nar_zst1522--- PASS: TestIsValidUploadKey (0.00s)1523 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1524 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1525 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1526 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1527 --- PASS: TestIsValidUploadKey/absolute (0.00s)1528 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1529 --- PASS: TestIsValidUploadKey/traversal (0.00s)1530 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1531 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1532 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1533 --- PASS: TestIsValidUploadKey/index.html (0.00s)1534 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1535 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1536 --- PASS: TestIsValidUploadKey/realisation (0.00s)1537 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1538 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1539 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1540 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1541 --- PASS: TestIsValidUploadKey/build_log (0.00s)1542 --- PASS: TestIsValidUploadKey/listing (0.00s)1543 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1544 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1545=== CONT TestPendingClosureWriteTimeout/empty1546=== CONT TestPendingClosureWriteTimeout/670k_objects1547=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline15482026/10/27 08:43:37 INFO lead: acquired remote=192.0.2.1:12341549--- PASS: TestUploadHandlersRejectOversizedBody (0.09s)1550 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)1551 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1552 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.30s)1553=== CONT TestPendingClosureWriteTimeout/400_objects1554=== CONT TestIsValidCachePath/narinfo1555=== CONT TestIsValidCachePath/index.html1556=== CONT TestIsValidCachePath/short_hash1557=== CONT TestIsValidCachePath/wrong_extension1558=== CONT TestIsValidCachePath/leading_slash1559=== CONT TestIsValidCachePath/empty1560=== CONT TestIsValidCachePath/random_path1561=== CONT TestIsValidCachePath/invalid_char_u1562=== CONT TestIsValidCachePath/invalid_char_e1563=== CONT TestIsValidCachePath/traversal_in_middle1564=== CONT TestIsValidCachePath/traversal_parent1565=== CONT TestIsValidCachePath/nar_uncompressed1566=== CONT TestIsValidCachePath/nix-cache-info1567=== CONT TestIsValidCachePath/realisation1568=== CONT TestIsValidCachePath/log1569=== CONT TestIsValidCachePath/ls1570=== CONT TestIsValidCachePath/nar_xz1571=== CONT TestIsValidCachePath/nar_bz21572=== CONT TestIsValidCachePath/nar_zst1573=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1574--- PASS: TestIsValidCachePath (0.00s)1575 --- PASS: TestIsValidCachePath/narinfo (0.00s)1576 --- PASS: TestIsValidCachePath/index.html (0.00s)1577 --- PASS: TestIsValidCachePath/short_hash (0.00s)1578 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1579 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1580 --- PASS: TestIsValidCachePath/empty (0.00s)1581 --- PASS: TestIsValidCachePath/random_path (0.00s)1582 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1583 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1584 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1585 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1586 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1587 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1588 --- PASS: TestIsValidCachePath/realisation (0.00s)1589 --- PASS: TestIsValidCachePath/log (0.00s)1590 --- PASS: TestIsValidCachePath/ls (0.00s)1591 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1592 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1593 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1594 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1595=== CONT TestParseSingleRange/none1596=== CONT TestParseSingleRange/open-ended1597=== CONT TestParseSingleRange/start_far_past_EOF1598=== CONT TestParseSingleRange/start_past_EOF1599=== CONT TestParseSingleRange/single_byte1600=== CONT TestParseSingleRange/suffix_exceeds_size1601=== CONT TestParseSingleRange/suffix1602=== CONT TestParseSingleRange/end_clamped_to_size1603=== CONT TestParseSingleRange/malformed_both_empty1604=== CONT TestParseSingleRange/closed1605=== CONT TestParseSingleRange/malformed_end_before_start1606=== CONT TestParseSingleRange/multi-range_ignored1607=== CONT TestParseSingleRange/malformed_no_dash1608=== CONT TestParseSingleRange/unknown_unit1609--- PASS: TestParseSingleRange (0.00s)1610 --- PASS: TestParseSingleRange/none (0.00s)1611 --- PASS: TestParseSingleRange/open-ended (0.00s)1612 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1613 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1614 --- PASS: TestParseSingleRange/single_byte (0.00s)1615 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1616 --- PASS: TestParseSingleRange/suffix (0.00s)1617 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1618 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1619 --- PASS: TestParseSingleRange/closed (0.00s)1620 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1621 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1622 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1623 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1624=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale16252026/10/27 08:43:37 INFO lead: acquired remote=192.0.2.1:123416262026/10/27 08:43:37 INFO lead: released remote=192.0.2.1:12341627--- PASS: TestLeadIncumbentAnnouncesAtOnce (6.61s)1628=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh16292026/10/27 08:43:38 INFO lead: acquired remote=192.0.2.1:123416302026/10/27 08:43:38 INFO lead: released remote=192.0.2.1:12341631--- PASS: TestLeadEndsOnShutdown (7.62s)1632=== CONT TestServerTLSConfig/no_client_CA1633=== CONT TestServerTLSConfig/not_a_PEM_file1634=== CONT TestServerTLSConfig/missing_CA_file1635--- PASS: TestServerTLSConfig (0.00s)1636 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1637 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.01s)1638 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1639=== CONT TestGCEndsOnShutdown/before_the_run16402026/10/27 08:43:39 INFO Received uploads request method=POST path=/api/pending_closures1641=== RUN TestPush_RejectsBadRequests/no_roots1642=== PAUSE TestPush_RejectsBadRequests/no_roots1643=== RUN TestPush_RejectsBadRequests/no_objects1644=== PAUSE TestPush_RejectsBadRequests/no_objects1645=== RUN TestPush_RejectsBadRequests/bad_root1646=== PAUSE TestPush_RejectsBadRequests/bad_root1647=== RUN TestPush_RejectsBadRequests/root_not_in_objects1648=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1649=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark16502026/10/27 08:43:39 INFO Received uploads request method=POST path=/api/pending_closures16512026/10/27 08:43:39 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16522026/10/27 08:43:39 INFO Uploading xnbkbd76i4py252s48n0fhgfihlx25vs-shared-dep (136B)16532026/10/27 08:43:39 INFO Uploading rc0yknmha6cb0qn10yfx1lwgd5xhpq5n-b (256B)16542026/10/27 08:43:39 WARN Failed to register uploaded object key=9f3xvapv3cfam4nrg8jrc6wl32glxj96.ls error="server returned 404: 404 page not found\n"16552026/10/27 08:43:39 INFO lead: released remote=192.0.2.1:123416562026/10/27 08:43:39 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16572026/10/27 08:43:39 WARN Failed to register uploaded object key=xnbkbd76i4py252s48n0fhgfihlx25vs.ls error="server returned 404: 404 page not found\n"16582026/10/27 08:43:39 WARN Failed to register uploaded object key=rc0yknmha6cb0qn10yfx1lwgd5xhpq5n.ls error="server returned 404: 404 page not found\n"16592026/10/27 08:43:39 WARN Failed to register uploaded object key=nar/0g2mapfc245s9jjfb3ipdyhglic2lq1s9gaxj1x3sknfran0wv7x.nar.zst error="server returned 404: 404 page not found\n"16602026/10/27 08:43:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16612026/10/27 08:43:39 INFO Signed narinfos id=1 count=216622026/10/27 08:43:39 INFO lead: acquired remote=192.0.2.1:123416632026/10/27 08:43:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16642026/10/27 08:43:39 INFO Signed narinfos id=2 count=216652026/10/27 08:43:39 INFO Uploading 4 narinfos1666--- PASS: TestConnectWaitsForAPeerMigration (7.39s)1667=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete16682026/10/27 08:43:39 WARN Failed to register uploaded object key=xnbkbd76i4py252s48n0fhgfihlx25vs.narinfo error="server returned 404: 404 page not found\n"16692026/10/27 08:43:39 WARN Failed to register uploaded object key=rc0yknmha6cb0qn10yfx1lwgd5xhpq5n.narinfo error="server returned 404: 404 page not found\n"16702026/10/27 08:43:39 WARN Failed to register uploaded object key=9f3xvapv3cfam4nrg8jrc6wl32glxj96.narinfo error="server returned 404: 404 page not found\n"16712026/10/27 08:43:39 INFO Received push request method=POST path=/api/pushes16722026/10/27 08:43:39 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16732026/10/27 08:43:39 INFO Uploading ygbrjf3n6z159wp4d5hf1hhkvxanv6bh-shared-dep (136B)16742026/10/27 08:43:39 INFO Uploading cwfhynhpzn0likkim2xxjgv1qp7gx42m-b (256B)16752026/10/27 08:43:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16762026/10/27 08:43:39 WARN Failed to register uploaded object key=xnbkbd76i4py252s48n0fhgfihlx25vs.narinfo error="server returned 404: 404 page not found\n"16772026/10/27 08:43:39 INFO Completed upload id=1 objects=6 duration=23.783042ms16782026/10/27 08:43:39 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16792026/10/27 08:43:39 INFO Completed upload id=2 objects=6 duration=357.042µs16802026/10/27 08:43:39 INFO Upload complete. (394ms)1681=== NAME TestClientFallsBackToClosures1682 client_pushes_test.go:112: Retrieved narinfo from S3:1683 StorePath: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientFallsBackToClosures2150513312/001/store/xnbkbd76i4py252s48n0fhgfihlx25vs-shared-dep1684 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1685 Compression: zstd1686 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821687 NarSize: 1361688 References: 1689 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n16902026/10/27 08:43:39 WARN Failed to register uploaded object key=abbaad7awymk3kn4a9cp4777d8nd9398.ls error="server returned 404: 404 page not found\n"1691 client_pushes_test.go:112: Retrieved narinfo from S3:1692 StorePath: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientFallsBackToClosures2150513312/001/store/9f3xvapv3cfam4nrg8jrc6wl32glxj96-a1693 URL: nar/0g2mapfc245s9jjfb3ipdyhglic2lq1s9gaxj1x3sknfran0wv7x.nar.zst1694 Compression: zstd1695 NarHash: sha256:0g2mapfc245s9jjfb3ipdyhglic2lq1s9gaxj1x3sknfran0wv7x1696 NarSize: 2561697 References: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientFallsBackToClosures2150513312/001/store/xnbkbd76i4py252s48n0fhgfihlx25vs-shared-dep1698 CA: text:sha256:0wfbv8xvg90fha3zbl4snkyll0lzxlzjfsmzr0sjh41ilfdqb6vc16992026/10/27 08:43:39 WARN Failed to register uploaded object key=cwfhynhpzn0likkim2xxjgv1qp7gx42m.ls error="server returned 404: 404 page not found\n"1700 client_pushes_test.go:112: Retrieved narinfo from S3:1701 StorePath: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientFallsBackToClosures2150513312/001/store/rc0yknmha6cb0qn10yfx1lwgd5xhpq5n-b1702 URL: nar/0g2mapfc245s9jjfb3ipdyhglic2lq1s9gaxj1x3sknfran0wv7x.nar.zst1703 Compression: zstd1704 NarHash: sha256:0g2mapfc245s9jjfb3ipdyhglic2lq1s9gaxj1x3sknfran0wv7x1705 NarSize: 2561706 References: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientFallsBackToClosures2150513312/001/store/xnbkbd76i4py252s48n0fhgfihlx25vs-shared-dep1707 CA: text:sha256:0wfbv8xvg90fha3zbl4snkyll0lzxlzjfsmzr0sjh41ilfdqb6vc17082026/10/27 08:43:39 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17092026/10/27 08:43:39 WARN Failed to register uploaded object key=ygbrjf3n6z159wp4d5hf1hhkvxanv6bh.ls error="server returned 404: 404 page not found\n"17102026/10/27 08:43:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17112026/10/27 08:43:39 WARN Failed to register uploaded object key=nar/11vrgcv0w2r8zdbv9riw78zhxcmngxwsq0qwmqg37q4s728s7h8z.nar.zst error="server returned 404: 404 page not found\n"17122026/10/27 08:43:39 INFO Signed narinfos id=1 count=317132026/10/27 08:43:39 INFO Uploading 3 narinfos17142026/10/27 08:43:39 WARN Failed to register uploaded object key=cwfhynhpzn0likkim2xxjgv1qp7gx42m.narinfo error="server returned 404: 404 page not found\n"17152026/10/27 08:43:39 INFO Received complete push request method=POST path=/api/pushes/1/complete17162026/10/27 08:43:39 WARN Failed to register uploaded object key=ygbrjf3n6z159wp4d5hf1hhkvxanv6bh.narinfo error="server returned 404: 404 page not found\n"17172026/10/27 08:43:39 WARN Failed to register uploaded object key=abbaad7awymk3kn4a9cp4777d8nd9398.narinfo error="server returned 404: 404 page not found\n"1718--- PASS: TestClientFallsBackToClosures (6.79s)1719=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows17202026/10/27 08:43:39 INFO Completed push id=1 objects=8 duration=19.988084ms17212026/10/27 08:43:39 INFO Upload complete. (283ms)1722=== NAME TestClientPushesUseOnePush1723 client_pushes_test.go:97: Retrieved narinfo from S3:1724 StorePath: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientPushesUseOnePush3075359360/001/store/ygbrjf3n6z159wp4d5hf1hhkvxanv6bh-shared-dep1725 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1726 Compression: zstd1727 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821728 NarSize: 1361729 References: 1730 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1731 client_pushes_test.go:97: Retrieved narinfo from S3:1732 StorePath: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientPushesUseOnePush3075359360/001/store/abbaad7awymk3kn4a9cp4777d8nd9398-a1733 URL: nar/11vrgcv0w2r8zdbv9riw78zhxcmngxwsq0qwmqg37q4s728s7h8z.nar.zst1734 Compression: zstd1735 NarHash: sha256:11vrgcv0w2r8zdbv9riw78zhxcmngxwsq0qwmqg37q4s728s7h8z1736 NarSize: 2561737 References: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientPushesUseOnePush3075359360/001/store/ygbrjf3n6z159wp4d5hf1hhkvxanv6bh-shared-dep1738 CA: text:sha256:1a18kbqjrhirxalxk81bk7cdxpnw1v9dwxbrvizqz8q0hfcm03x11739 client_pushes_test.go:97: Retrieved narinfo from S3:1740 StorePath: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientPushesUseOnePush3075359360/001/store/cwfhynhpzn0likkim2xxjgv1qp7gx42m-b1741 URL: nar/11vrgcv0w2r8zdbv9riw78zhxcmngxwsq0qwmqg37q4s728s7h8z.nar.zst1742 Compression: zstd1743 NarHash: sha256:11vrgcv0w2r8zdbv9riw78zhxcmngxwsq0qwmqg37q4s728s7h8z1744 NarSize: 2561745 References: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientPushesUseOnePush3075359360/001/store/ygbrjf3n6z159wp4d5hf1hhkvxanv6bh-shared-dep1746 CA: text:sha256:1a18kbqjrhirxalxk81bk7cdxpnw1v9dwxbrvizqz8q0hfcm03x11747--- PASS: TestClientPushesUseOnePush (6.71s)1748=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1749=== NAME TestOrphanedObjectsGCStressTest1750 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1751 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion1752=== NAME TestClientWithDependencies1753 client_integration_test.go:660: Built derivation: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientWithDependencies592795948/001/store/q0nik5g3s19vyvjlfyfpa2jn28qkhn1g-test-script1754 client_integration_test.go:662: Found 1 dependencies (including self)1755=== RUN TestService_RequireScope_OIDC/builder_may_write1756=== PAUSE TestService_RequireScope_OIDC/builder_may_write1757=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1758=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1759=== RUN TestService_RequireScope_OIDC/ops_may_admin1760=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1761=== RUN TestService_RequireScope_OIDC/ops_may_not_write1762=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1763=== RUN TestService_RequireScope_OIDC/reader_may_not_write1764=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1765=== RUN TestService_RequireScope_OIDC/static_token_may_admin1766=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1767=== RUN TestService_RequireScope_OIDC/static_token_may_write1768=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1769=== RUN TestService_RequireScope_OIDC/reader_may_read1770=== PAUSE TestService_RequireScope_OIDC/reader_may_read1771=== RUN TestService_RequireScope_OIDC/writer_implies_read1772=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1773=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1774=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1775=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1776=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1777=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1778=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1779=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1780=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1781=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1782=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1783=== CONT TestResolveDBConnectionString/flag_wins1784=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1785=== CONT TestResolveDBConnectionString/nothing_configured1786=== CONT TestResolveDBConnectionString/missing_file_is_an_error1787=== CONT TestResolveDBConnectionString/file_when_flag_empty1788=== CONT TestClientErrorHandling/InvalidStorePath1789--- PASS: TestResolveDBConnectionString (0.02s)1790 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1791 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1792 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1793 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1794 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)17952026/10/27 08:43:40 INFO Received push request method=POST path=/api/pushes17962026/10/27 08:43:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17972026/10/27 08:43:40 INFO Uploading q0nik5g3s19vyvjlfyfpa2jn28qkhn1g-test-script (136B)17982026/10/27 08:43:40 WARN Failed to register uploaded object key=q0nik5g3s19vyvjlfyfpa2jn28qkhn1g.ls error="server returned 404: 404 page not found\n"17992026/10/27 08:43:40 INFO Received push request method=POST path=/api/pushes18002026/10/27 08:43:40 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"18012026/10/27 08:43:40 WARN Failed to register uploaded object key=log/hbd0aypf8dkvrcv56axb6nsglwzncsw0-test-script.drv error="server returned 404: 404 page not found\n"18022026/10/27 08:43:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18032026/10/27 08:43:40 INFO Signed narinfos id=1 count=118042026/10/27 08:43:40 INFO Uploading 1 narinfos18052026/10/27 08:43:40 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)18062026/10/27 08:43:40 INFO Uploading c14gc0z9a18rckslh30j74jsn9bprwz6-shared-dep (136B)18072026/10/27 08:43:40 INFO Uploading w6w2lqp19adaf6m4w385m23cnkzbgl4r-top (264B)18082026/10/27 08:43:40 INFO Received complete push request method=POST path=/api/pushes/1/complete18092026/10/27 08:43:40 WARN Failed to register uploaded object key=q0nik5g3s19vyvjlfyfpa2jn28qkhn1g.narinfo error="server returned 404: 404 page not found\n"18102026/10/27 08:43:40 WARN Failed to register uploaded object key=c14gc0z9a18rckslh30j74jsn9bprwz6.ls error="server returned 404: 404 page not found\n"18112026/10/27 08:43:40 INFO Completed push id=1 objects=4 duration=32.559208ms18122026/10/27 08:43:40 INFO Upload complete. (260ms)1813=== NAME TestClientWithDependencies1814 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/5/scratch/a23fa3231491b957/build/TestClientWithDependencies592795948/001/store) requires matching store prefix18152026/10/27 08:43:40 WARN Failed to register uploaded object key=w6w2lqp19adaf6m4w385m23cnkzbgl4r.ls error="server returned 404: 404 page not found\n"18162026/10/27 08:43:40 WARN Failed to register uploaded object key=nar/10sgswrn8nssbcr9xlj4szli4k73q30vmnxwrmljhm46kyn0r81q.nar.zst error="server returned 404: 404 page not found\n"18172026/10/27 08:43:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18182026/10/27 08:43:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18192026/10/27 08:43:40 INFO Signed narinfos id=1 count=218202026/10/27 08:43:40 INFO Uploading 2 narinfos18212026/10/27 08:43:40 INFO lead: released remote=192.0.2.1:12341822--- PASS: TestLeadElectsOneAndHandsOver (8.69s)1823=== CONT TestClientErrorHandling/ServerNotAvailable18242026/10/27 08:43:40 WARN Failed to register uploaded object key=c14gc0z9a18rckslh30j74jsn9bprwz6.narinfo error="server returned 404: 404 page not found\n"18252026/10/27 08:43:40 INFO Received complete push request method=POST path=/api/pushes/1/complete18262026/10/27 08:43:40 WARN Failed to register uploaded object key=w6w2lqp19adaf6m4w385m23cnkzbgl4r.narinfo error="server returned 404: 404 page not found\n"18272026/10/27 08:43:40 INFO Completed push id=1 objects=6 duration=13.662583ms18282026/10/27 08:43:40 INFO Upload complete. (293ms)1829=== NAME TestClientSharedPathCommittedMidPush1830 client_integration_test.go:727: Retrieved narinfo from S3:1831 StorePath: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientSharedPathCommittedMidPush1731906676/001/store/c14gc0z9a18rckslh30j74jsn9bprwz6-shared-dep1832 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1833 Compression: zstd1834 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821835 NarSize: 1361836 References: 1837 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1838--- PASS: TestClientWithDependencies (7.18s)1839=== CONT TestClientErrorHandling/InvalidAuthToken1840=== NAME TestClientSharedPathCommittedMidPush1841 client_integration_test.go:727: Retrieved narinfo from S3:1842 StorePath: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientSharedPathCommittedMidPush1731906676/001/store/w6w2lqp19adaf6m4w385m23cnkzbgl4r-top1843 URL: nar/10sgswrn8nssbcr9xlj4szli4k73q30vmnxwrmljhm46kyn0r81q.nar.zst1844 Compression: zstd1845 NarHash: sha256:10sgswrn8nssbcr9xlj4szli4k73q30vmnxwrmljhm46kyn0r81q1846 NarSize: 2641847 References: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientSharedPathCommittedMidPush1731906676/001/store/c14gc0z9a18rckslh30j74jsn9bprwz6-shared-dep1848 CA: text:sha256:0iyb2zhjsc03kgxki93nya7gv9djf06yc5z845n365awpn35ivj61849--- PASS: TestClientSharedPathCommittedMidPush (6.78s)1850=== CONT TestCacheConfigHandler/full_config,_no_issuer1851=== CONT TestCacheConfigHandler/no_signing_keys1852=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1853=== CONT TestCacheConfigHandler/no_cache_url_configured1854--- PASS: TestCacheConfigHandler (0.00s)1855 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1856 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1857 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1858 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1859=== CONT TestPush_RejectsBadRequests/no_roots18602026/10/27 08:43:40 INFO Received push request method=POST path=/api/pushes1861=== CONT TestPush_RejectsBadRequests/bad_root18622026/10/27 08:43:40 INFO Received push request method=POST path=/api/pushes1863=== CONT TestPush_RejectsBadRequests/root_not_in_objects18642026/10/27 08:43:40 INFO Received push request method=POST path=/api/pushes1865=== CONT TestPush_RejectsBadRequests/no_objects18662026/10/27 08:43:40 INFO Received push request method=POST path=/api/pushes1867=== CONT TestService_RequireScope_OIDC/builder_may_write1868--- PASS: TestPush_RejectsBadRequests (6.08s)1869 --- PASS: TestPush_RejectsBadRequests/no_roots (0.01s)1870 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1871 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.01s)1872 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1873=== CONT TestService_RequireScope_OIDC/reader_may_read1874=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1875=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read18762026/10/27 08:43:40 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]1877=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1878=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1879=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1880=== CONT TestService_RequireScope_OIDC/writer_implies_read1881=== CONT TestService_RequireScope_OIDC/reader_may_not_write1882=== CONT TestService_RequireScope_OIDC/static_token_may_write1883=== CONT TestService_RequireScope_OIDC/static_token_may_admin1884=== CONT TestService_RequireScope_OIDC/ops_may_admin1885=== CONT TestService_RequireScope_OIDC/ops_may_not_write1886=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1887--- PASS: TestService_RequireScope_OIDC (5.74s)1888 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1889 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1890 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1891 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1892 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1893 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1894 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1895 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1896 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1897 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1898 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1899 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1900 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1901 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)19022026/10/27 08:43:40 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/present19032026/10/27 08:43:40 WARN Request failed, retrying attempt=2 backoff=211.059627ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1904=== NAME TestPinProtectsFromGC1905 client_integration_test.go:778: Pinned store path: /private/var/tb/5/scratch/a23fa3231491b957/build/TestPinProtectsFromGC693184652/001/store/1arbp5pslhbz9s8g8ab9nw5amm8x8bk3-pinned-file.txt1906 client_integration_test.go:779: Unpinned store path: /private/var/tb/5/scratch/a23fa3231491b957/build/TestPinProtectsFromGC693184652/001/store/xcq9kkgia6xwf7yrffhr8gmdgip8mvd4-unpinned-file.txt19072026/10/27 08:43:41 INFO Received push request method=POST path=/api/pushes19082026/10/27 08:43:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19092026/10/27 08:43:41 INFO Uploading 1arbp5pslhbz9s8g8ab9nw5amm8x8bk3-pinned-file.txt (128B)19102026/10/27 08:43:41 WARN Request failed, retrying attempt=3 backoff=371.424024ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19112026/10/27 08:43:41 WARN Failed to register uploaded object key=1arbp5pslhbz9s8g8ab9nw5amm8x8bk3.ls error="server returned 404: 404 page not found\n"19122026/10/27 08:43:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19132026/10/27 08:43:41 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"19142026/10/27 08:43:41 INFO Signed narinfos id=1 count=119152026/10/27 08:43:41 INFO Uploading 1 narinfos1916=== NAME TestClientMultipleUploads1917 client_integration_test.go:405: Created store path 0: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientMultipleUploads4029751045/001/store/1vjj538i1pmq27x3hz6jvnrf5rnnjrnw-test-file-0.txt19182026/10/27 08:43:41 INFO Received complete push request method=POST path=/api/pushes/1/complete19192026/10/27 08:43:41 WARN Failed to register uploaded object key=1arbp5pslhbz9s8g8ab9nw5amm8x8bk3.narinfo error="server returned 404: 404 page not found\n"19202026/10/27 08:43:41 INFO Completed push id=1 objects=3 duration=21.944875ms19212026/10/27 08:43:41 INFO Upload complete. (289ms)1922 client_integration_test.go:405: Created store path 1: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientMultipleUploads4029751045/001/store/dpm4b06d6fszmz63313x5k7b951hx8ck-test-file-1.txt19232026/10/27 08:43:41 INFO Received push request method=POST path=/api/pushes19242026/10/27 08:43:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19252026/10/27 08:43:41 INFO Uploading xcq9kkgia6xwf7yrffhr8gmdgip8mvd4-unpinned-file.txt (128B)19262026/10/27 08:43:41 WARN Failed to register uploaded object key=xcq9kkgia6xwf7yrffhr8gmdgip8mvd4.ls error="server returned 404: 404 page not found\n"19272026/10/27 08:43:41 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign19282026/10/27 08:43:41 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"19292026/10/27 08:43:41 INFO Signed narinfos id=2 count=119302026/10/27 08:43:41 INFO Uploading 1 narinfos1931 client_integration_test.go:405: Created store path 2: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientMultipleUploads4029751045/001/store/fsnzwsc9i4gj5vir37ag07afgc0mipp1-test-file-2.txt19322026/10/27 08:43:41 INFO Received complete push request method=POST path=/api/pushes/2/complete19332026/10/27 08:43:41 WARN Failed to register uploaded object key=xcq9kkgia6xwf7yrffhr8gmdgip8mvd4.narinfo error="server returned 404: 404 page not found\n"19342026/10/27 08:43:41 INFO Completed push id=2 objects=3 duration=1.032042ms19352026/10/27 08:43:41 WARN Request failed, retrying attempt=4 backoff=836.858184ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19362026/10/27 08:43:41 INFO Upload complete. (188ms)1937=== NAME TestClientIntegration1938 client_integration_test.go:291: Created store path: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientIntegration2713656878/002/store/cnmnz3rlmlwhby6jhj6a7hy8g46vr6pm-test-file.txt19392026/10/27 08:43:41 INFO Received push request method=POST path=/api/pushes19402026/10/27 08:43:41 INFO Starting cleanup of old closures method=DELETE path=/api/closures19412026/10/27 08:43:41 INFO Garbage collection started19422026/10/27 08:43:41 INFO Aborted multipart uploads count=0 kept=019432026/10/27 08:43:41 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)19442026/10/27 08:43:41 INFO Uploading fsnzwsc9i4gj5vir37ag07afgc0mipp1-test-file-2.txt (160B)19452026/10/27 08:43:41 WARN Force mode enabled - objects will be deleted immediately without grace period19462026/10/27 08:43:41 INFO Uploading 1vjj538i1pmq27x3hz6jvnrf5rnnjrnw-test-file-0.txt (160B)19472026/10/27 08:43:41 INFO Uploading dpm4b06d6fszmz63313x5k7b951hx8ck-test-file-1.txt (160B)19482026/10/27 08:43:41 INFO Received push request method=POST path=/api/pushes19492026/10/27 08:43:41 WARN Failed to register uploaded object key=dpm4b06d6fszmz63313x5k7b951hx8ck.ls error="server returned 404: 404 page not found\n"19502026/10/27 08:43:41 WARN Failed to register uploaded object key=1vjj538i1pmq27x3hz6jvnrf5rnnjrnw.ls error="server returned 404: 404 page not found\n"19512026/10/27 08:43:41 WARN Failed to register uploaded object key=fsnzwsc9i4gj5vir37ag07afgc0mipp1.ls error="server returned 404: 404 page not found\n"19522026/10/27 08:43:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19532026/10/27 08:43:41 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"19542026/10/27 08:43:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19552026/10/27 08:43:41 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"19562026/10/27 08:43:41 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"19572026/10/27 08:43:41 INFO Uploading cnmnz3rlmlwhby6jhj6a7hy8g46vr6pm-test-file.txt (152B)19582026/10/27 08:43:41 INFO Signed narinfos id=1 count=319592026/10/27 08:43:41 INFO Uploading 3 narinfos19602026/10/27 08:43:41 WARN Failed to register uploaded object key=cnmnz3rlmlwhby6jhj6a7hy8g46vr6pm.ls error="server returned 404: 404 page not found\n"19612026/10/27 08:43:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19622026/10/27 08:43:41 WARN Failed to register uploaded object key=dpm4b06d6fszmz63313x5k7b951hx8ck.narinfo error="server returned 404: 404 page not found\n"19632026/10/27 08:43:41 WARN Failed to register uploaded object key=fsnzwsc9i4gj5vir37ag07afgc0mipp1.narinfo error="server returned 404: 404 page not found\n"19642026/10/27 08:43:41 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"19652026/10/27 08:43:41 INFO Received complete push request method=POST path=/api/pushes/1/complete19662026/10/27 08:43:41 WARN Failed to register uploaded object key=1vjj538i1pmq27x3hz6jvnrf5rnnjrnw.narinfo error="server returned 404: 404 page not found\n"19672026/10/27 08:43:41 INFO Signed narinfos id=1 count=119682026/10/27 08:43:41 INFO Uploading 1 narinfos19692026/10/27 08:43:41 INFO Completed push id=1 objects=9 duration=41.732792ms19702026/10/27 08:43:41 INFO Upload complete. (361ms)1971=== NAME TestClientMultipleUploads1972 client_integration_test.go:416: Uploaded 3 paths in 406.075583ms19732026/10/27 08:43:41 INFO Received complete push request method=POST path=/api/pushes/1/complete19742026/10/27 08:43:41 WARN Failed to register uploaded object key=cnmnz3rlmlwhby6jhj6a7hy8g46vr6pm.narinfo error="server returned 404: 404 page not found\n"19752026/10/27 08:43:41 INFO Completed push id=1 objects=3 duration=47.568375ms19762026/10/27 08:43:41 INFO Upload complete. (385ms)19772026/10/27 08:43:41 INFO All 1 paths already cached1978=== NAME TestClientIntegration1979 client_integration_test.go:317: Retrieved narinfo from S3:1980 StorePath: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientIntegration2713656878/002/store/cnmnz3rlmlwhby6jhj6a7hy8g46vr6pm-test-file.txt1981 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1982 Compression: zstd1983 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11984 NarSize: 1521985 References: 1986 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11987 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1988 client_integration_test.go:318: Decompressed .ls content (64 bytes):1989 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1990--- PASS: TestClientMultipleUploads (7.15s)1991--- PASS: TestCacheStatsHandler (6.88s)19922026/10/27 08:43:42 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=019932026/10/27 08:43:42 INFO Vacuumed table table=pending_closures19942026/10/27 08:43:42 INFO Vacuumed table table=pending_objects19952026/10/27 08:43:42 INFO Vacuumed table table=multipart_uploads19962026/10/27 08:43:42 INFO Vacuumed table table=closures19972026/10/27 08:43:42 INFO Vacuumed table table=objects19982026/10/27 08:43:42 WARN Request failed, retrying attempt=5 backoff=1.464676767s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1999--- PASS: TestService_ReadScope_PublicByDefault (6.24s)20002026/10/27 08:43:42 INFO Received push request method=POST path=/api/pushes20012026/10/27 08:43:42 INFO Object in database but missing from S3 key=cnmnz3rlmlwhby6jhj6a7hy8g46vr6pm.ls20022026/10/27 08:43:42 WARN Found objects in DB but missing from S3, will re-upload count=120032026/10/27 08:43:42 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20042026/10/27 08:43:42 INFO Received complete push request method=POST path=/api/pushes/2/complete20052026/10/27 08:43:42 WARN Failed to register uploaded object key=cnmnz3rlmlwhby6jhj6a7hy8g46vr6pm.ls error="server returned 404: 404 page not found\n"20062026/10/27 08:43:42 INFO Completed push id=2 objects=3 duration=667.708µs2007=== NAME TestClientCADerivations2008 client_ca_test.go:136: Built CA derivation: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientCADerivations1329304173/001/store/vap2ilzjj02jyjb1840b0l2p9y1wss9p-ca-test20092026/10/27 08:43:42 INFO Upload complete. (116ms)2010=== NAME TestClientIntegration2011 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)2012 client_integration_test.go:335: Decompressed .ls content (49 bytes):2013 {"version":1,"root":{"type":"regular","size":39}}2014=== NAME TestClientCADerivations2015 client_ca_test.go:139: Found 1 dependencies (including self)20162026/10/27 08:43:42 INFO Received push request method=POST path=/api/pushes20172026/10/27 08:43:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20182026/10/27 08:43:42 INFO Uploading vap2ilzjj02jyjb1840b0l2p9y1wss9p-ca-test (144B)20192026/10/27 08:43:42 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20202026/10/27 08:43:42 WARN mTLS auth: bound subjects configured but subject DN unavailable20212026/10/27 08:43:42 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2022--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (6.55s)20232026/10/27 08:43:42 WARN Failed to register uploaded object key=vap2ilzjj02jyjb1840b0l2p9y1wss9p.ls error="server returned 404: 404 page not found\n"20242026/10/27 08:43:42 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"20252026/10/27 08:43:42 WARN Failed to register uploaded object key=log/hhi4j3x01mwzzs651aj2m67n0rp8kylg-ca-test.drv error="server returned 404: 404 page not found\n"20262026/10/27 08:43:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20272026/10/27 08:43:42 INFO Signed narinfos id=1 count=120282026/10/27 08:43:42 INFO Uploading 1 narinfos20292026/10/27 08:43:42 INFO Received push request method=POST path=/api/pushes20302026/10/27 08:43:42 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20312026/10/27 08:43:42 INFO Received complete push request method=POST path=/api/pushes/1/complete20322026/10/27 08:43:42 WARN Failed to register uploaded object key=vap2ilzjj02jyjb1840b0l2p9y1wss9p.narinfo error="server returned 404: 404 page not found\n"20332026/10/27 08:43:42 INFO Received complete push request method=POST path=/api/pushes/3/complete20342026/10/27 08:43:42 WARN Failed to register uploaded object key=cnmnz3rlmlwhby6jhj6a7hy8g46vr6pm.ls error="server returned 404: 404 page not found\n"20352026/10/27 08:43:42 INFO Completed push id=3 objects=3 duration=10.944625ms20362026/10/27 08:43:42 INFO Completed push id=1 objects=4 duration=49.779833ms20372026/10/27 08:43:42 INFO Upload complete. (132ms)20382026/10/27 08:43:42 INFO Upload complete. (346ms)2039=== NAME TestClientIntegration2040 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)2041=== NAME TestClientCADerivations2042 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientCADerivations1329304173/001/store/vap2ilzjj02jyjb1840b0l2p9y1wss9p-ca-test2043 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2044 Compression: zstd2045 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2046 NarSize: 1442047 References: 2048 Deriver: /private/var/tb/5/scratch/a23fa3231491b957/build/TestClientCADerivations1329304173/001/store/hhi4j3x01mwzzs651aj2m67n0rp8kylg-ca-test.drv2049 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2050 client_ca_test.go:185: Checking for realisation files in S3...2051=== NAME TestClientIntegration2052 client_integration_test.go:352: Decompressed .ls content (49 bytes):2053 {"version":1,"root":{"type":"regular","size":39}}2054=== NAME TestClientCADerivations2055 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2056 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache2057=== NAME TestClientIntegration2058 client_integration_test.go:363: Testing garbage collection...20592026/10/27 08:43:42 INFO Starting cleanup of old closures method=DELETE path=/api/closures20602026/10/27 08:43:42 INFO Garbage collection started20612026/10/27 08:43:42 INFO Aborted multipart uploads count=0 kept=020622026/10/27 08:43:42 WARN Force mode enabled - objects will be deleted immediately without grace period2063--- PASS: TestDeleteClosuresRacingPins (10.56s)2064=== NAME TestClientCADerivations2065 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket84?endpoint=http://localhost:64185®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/5/scratch/a23fa3231491b957/build/TestClientCADerivations1329304173/001/store'2066 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12067--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (6.84s)2068--- PASS: TestClientCADerivations (8.08s)20692026/10/27 08:43:43 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=02070--- PASS: TestService_ReadAuthMiddleware (6.48s)20712026/10/27 08:43:43 INFO Vacuumed table table=pending_closures20722026/10/27 08:43:43 INFO Vacuumed table table=pending_objects20732026/10/27 08:43:43 INFO Vacuumed table table=multipart_uploads20742026/10/27 08:43:43 INFO Vacuumed table table=closures20752026/10/27 08:43:43 INFO Vacuumed table table=objects20762026/10/27 08:43:43 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=020772026/10/27 08:43:43 INFO Received create pin request method=POST path=/api/pins/myapp2078=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2079=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2080=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2081=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2082=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2083=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2084=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2085=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2086=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token20872026/10/27 08:43:43 INFO Created/updated pin name=myapp store_path=/private/var/tb/5/scratch/a23fa3231491b957/build/TestPinProtectsFromGC693184652/001/store/1arbp5pslhbz9s8g8ab9nw5amm8x8bk3-pinned-file.txt narinfo_key=1arbp5pslhbz9s8g8ab9nw5amm8x8bk3.narinfo2088=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20892026/10/27 08:43:43 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]2090=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2091=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20922026/10/27 08:43:43 INFO Starting cleanup of old closures method=DELETE path=/api/closures20932026/10/27 08:43:43 INFO Garbage collection started20942026/10/27 08:43:43 WARN Authentication failed token_preview=eyJhbGciOi...s6GmrXHlZQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]20952026/10/27 08:43:43 INFO Aborted multipart uploads count=0 kept=02096--- PASS: TestService_AuthMiddleware_OIDC (6.57s)2097 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2098 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2099 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.01s)2100 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)21012026/10/27 08:43:43 WARN Force mode enabled - objects will be deleted immediately without grace period21022026/10/27 08:43:43 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=021032026/10/27 08:43:43 INFO Vacuumed table table=pending_closures21042026/10/27 08:43:43 INFO Vacuumed table table=pending_objects21052026/10/27 08:43:43 INFO Vacuumed table table=multipart_uploads21062026/10/27 08:43:43 INFO Vacuumed table table=closures21072026/10/27 08:43:43 INFO Vacuumed table table=objects21082026/10/27 08:43:43 INFO Received uploads request method=POST path=/api/pending_closures21092026/10/27 08:43:43 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21102026/10/27 08:43:43 WARN Request failed, retrying attempt=2 backoff=194.284476ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21112026/10/27 08:43:44 WARN Request failed, retrying attempt=3 backoff=379.400016ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21122026/10/27 08:43:44 WARN Request failed, retrying attempt=4 backoff=747.669679ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2113--- PASS: TestPendingClosureWriteTimeout (0.00s)2114 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2115 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2116 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2117 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (7.12s)2118--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2119 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (6.77s)2120 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (6.85s)21212026/10/27 08:43:44 INFO Aborted multipart uploads count=0 kept=021222026/10/27 08:43:44 WARN Force mode enabled - objects will be deleted immediately without grace period21232026-10-27 08:43:44.890 UTC [79373] ERROR: canceling statement due to user request21242026-10-27 08:43:44.890 UTC [79373] STATEMENT: -- name: MarkStaleObjects :execrows2125 WITH RECURSIVE ct AS (2126 SELECT timezone('UTC', now()) AS now2127 ),2128 closure_reach AS (2129 -- Start with all closure keys2130 SELECT o.key, o.refs2131 FROM objects o2132 INNER JOIN closures c ON o.key = c.key2133 UNION2134 -- Recursively add all referenced objects2135 SELECT o.key, o.refs2136 FROM objects o2137 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2138 ),2139 reachable_objects AS (2140 SELECT DISTINCT key FROM closure_reach2141 ),2142 stale_objects AS (2143 SELECT o.key2144 FROM objects AS o, ct2145 WHERE2146 NOT EXISTS (2147 SELECT 12148 FROM reachable_objects ro2149 WHERE ro.key = o.key2150 )2151 AND NOT EXISTS (2152 SELECT 12153 FROM pending_objects AS po2154 WHERE po.key = o.key2155 )2156 AND o.deleted_at IS NULL -- Only mark fresh objects2157 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2158 FOR UPDATE2159 )2160 UPDATE objects2161 SET2162 deleted_at = ct.now,2163 first_deleted_at = COALESCE(first_deleted_at, ct.now)2164 FROM stale_objects, ct2165 WHERE objects.key = stale_objects.key2166 21672026/10/27 08:43:44 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02168=== NAME TestClientIntegration2169 client_integration_test.go:370: Objects in database after GC:2170 client_integration_test.go:370: Successfully deleted all objects with GC --force2171--- PASS: TestClientIntegration (9.92s)21722026/10/27 08:43:45 INFO Aborted multipart uploads count=0 kept=021732026/10/27 08:43:45 WARN Force mode enabled - objects will be deleted immediately without grace period21742026/10/27 08:43:45 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:64185/bucket96/?delete=\": context canceled"2175--- PASS: TestGCEndsOnShutdown (0.01s)2176 --- PASS: TestGCEndsOnShutdown/before_the_run (5.84s)2177 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (5.66s)2178 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (5.70s)21792026/10/27 08:43:45 WARN Request failed, retrying attempt=5 backoff=1.554955999s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21802026/10/27 08:43:45 INFO Received uploads request method=POST path=/api/pending_closures21812026/10/27 08:43:45 INFO Aborted multipart uploads count=0 kept=021822026/10/27 08:43:45 WARN Force mode enabled - objects will be deleted immediately without grace period21832026/10/27 08:43:45 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=021842026/10/27 08:43:45 INFO Vacuumed table table=pending_closures21852026/10/27 08:43:45 INFO Vacuumed table table=pending_objects21862026/10/27 08:43:45 INFO Vacuumed table table=multipart_uploads21872026/10/27 08:43:45 INFO Vacuumed table table=closures21882026/10/27 08:43:45 INFO Vacuumed table table=objects2189=== NAME TestPinProtectsFromGC2190 client_integration_test.go:887: Pin successfully protected closure from garbage collection21912026/10/27 08:43:45 INFO Received uploads request method=POST path=/api/pending_closures21922026/10/27 08:43:45 INFO Aborted multipart uploads count=0 kept=021932026/10/27 08:43:45 WARN Force mode enabled - objects will be deleted immediately without grace period21942026/10/27 08:43:45 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=021952026/10/27 08:43:45 INFO Vacuumed table table=pending_closures2196--- PASS: TestPinProtectsFromGC (10.80s)21972026/10/27 08:43:45 INFO Vacuumed table table=pending_objects21982026/10/27 08:43:45 INFO Vacuumed table table=multipart_uploads21992026/10/27 08:43:45 INFO Vacuumed table table=closures22002026/10/27 08:43:45 INFO Vacuumed table table=objects2201--- PASS: TestForceGCDuringPushOffersSweptObject (0.01s)2202 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (6.00s)2203 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (6.01s)22042026/10/27 08:43:46 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22052026/10/27 08:43:46 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22062026/10/27 08:43:46 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"22072026/10/27 08:43:46 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-config22082026/10/27 08:43:46 WARN Request failed, retrying attempt=2 backoff=204.835659ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22092026/10/27 08:43:47 WARN Request failed, retrying attempt=3 backoff=392.356233ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22102026/10/27 08:43:47 WARN Request failed, retrying attempt=4 backoff=773.845016ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22112026/10/27 08:43:48 WARN Request failed, retrying attempt=5 backoff=1.477038632s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22122026/10/27 08:43:49 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_closures22132026/10/27 08:43:49 WARN Request failed, retrying attempt=2 backoff=189.663838ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22142026/10/27 08:43:50 WARN Request failed, retrying attempt=3 backoff=362.577799ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22152026/10/27 08:43:50 WARN Request failed, retrying attempt=4 backoff=778.69573ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22162026/10/27 08:43:51 WARN Request failed, retrying attempt=5 backoff=1.643540431s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2217=== NAME TestOrphanedObjectsGCStressTest2218 orphaned_objects_gc_test.go:503: Stress test completed successfully:2219 orphaned_objects_gc_test.go:504: - Active objects preserved: 202220 orphaned_objects_gc_test.go:505: - Objects deleted: 2102221 orphaned_objects_gc_test.go:506: - Total GC'd: 2102222--- PASS: TestOrphanedObjectsGCStressTest (30.53s)2223--- PASS: TestClientErrorHandling (0.00s)2224 --- PASS: TestClientErrorHandling/InvalidStorePath (5.72s)2225 --- PASS: TestClientErrorHandling/InvalidAuthToken (5.67s)2226 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.52s)2227PASS2228{"timestamp":"2026-10-27T08:43:52.951356Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:64595","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(3)"}22292026-10-27 08:43:53.056 UTC [78900] LOG: received smart shutdown request22302026-10-27 08:43:53.057 UTC [78900] LOG: background worker "logical replication launcher" (PID 78910) exited with exit code 122312026-10-27 08:43:53.084 UTC [78905] LOG: shutting down22322026-10-27 08:43:53.084 UTC [78905] LOG: checkpoint starting: shutdown immediate22332026-10-27 08:43:54.298 UTC [78905] LOG: checkpoint complete: wrote 11647 buffers (71.1%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 31 recycled; write=0.522 s, sync=0.655 s, total=1.215 s; sync files=34045, longest=0.001 s, average=0.001 s; distance=501975 kB, estimate=501975 kB; lsn=0/201C2C38, redo lsn=0/201C2C3822342026-10-27 08:43:54.305 UTC [78900] LOG: database system is shut down2235Running OIDC tests...2236=== RUN TestAudienceForIssuer2237=== PAUSE TestAudienceForIssuer2238=== RUN TestGlobMatch2239=== PAUSE TestGlobMatch2240=== RUN TestValidateToken_ValidToken2241=== PAUSE TestValidateToken_ValidToken2242=== RUN TestValidateToken_WrongAudience2243=== PAUSE TestValidateToken_WrongAudience2244=== RUN TestValidateToken_Expired2245=== PAUSE TestValidateToken_Expired2246=== RUN TestValidateToken_BoundClaimsMismatch2247=== PAUSE TestValidateToken_BoundClaimsMismatch2248=== RUN TestValidateToken_BoundSubjectMismatch2249=== PAUSE TestValidateToken_BoundSubjectMismatch2250=== RUN TestValidateToken_MultipleProviders2251=== PAUSE TestValidateToken_MultipleProviders2252=== RUN TestValidateToken_NoMatchingProvider2253=== PAUSE TestValidateToken_NoMatchingProvider2254=== RUN TestValidateToken_KubernetesServiceAccount2255=== PAUSE TestValidateToken_KubernetesServiceAccount2256=== RUN TestNewValidator_KubernetesRequiresCA2257=== PAUSE TestNewValidator_KubernetesRequiresCA2258=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2259=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2260=== RUN TestPins_ReservedForMatchingRule2261=== PAUSE TestPins_ReservedForMatchingRule2262=== RUN TestPins_TopLevelShorthand2263=== PAUSE TestPins_TopLevelShorthand2264=== RUN TestPins_ConfigValidation2265=== PAUSE TestPins_ConfigValidation2266=== RUN TestScopes_LegacyProviderDefaultsToWrite2267=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2268=== RUN TestScopes_Rules2269=== PAUSE TestScopes_Rules2270=== RUN TestScopes_ConfigValidation2271=== PAUSE TestScopes_ConfigValidation2272=== CONT TestAudienceForIssuer2273--- PASS: TestAudienceForIssuer (0.00s)2274=== CONT TestPins_ConfigValidation2275=== CONT TestScopes_Rules2276=== CONT TestValidateToken_NoMatchingProvider2277=== CONT TestValidateToken_MultipleProviders2278=== CONT TestValidateToken_BoundSubjectMismatch2279=== CONT TestValidateToken_BoundClaimsMismatch2280--- PASS: TestPins_ConfigValidation (0.00s)2281=== CONT TestValidateToken_Expired2282=== CONT TestValidateToken_WrongAudience2283=== CONT TestValidateToken_ValidToken2284=== CONT TestGlobMatch2285=== RUN TestGlobMatch/foo_foo2286=== PAUSE TestGlobMatch/foo_foo2287=== RUN TestGlobMatch/foo_bar2288=== PAUSE TestGlobMatch/foo_bar2289=== RUN TestGlobMatch/*_2290=== PAUSE TestGlobMatch/*_2291=== RUN TestGlobMatch/*_anything2292=== PAUSE TestGlobMatch/*_anything2293=== RUN TestGlobMatch/foo*_foo2294=== PAUSE TestGlobMatch/foo*_foo2295=== RUN TestGlobMatch/foo*_foobar2296=== PAUSE TestGlobMatch/foo*_foobar2297=== RUN TestGlobMatch/foo*_bar2298=== PAUSE TestGlobMatch/foo*_bar2299=== RUN TestGlobMatch/*bar_bar2300=== PAUSE TestGlobMatch/*bar_bar2301=== RUN TestGlobMatch/*bar_foobar2302=== PAUSE TestGlobMatch/*bar_foobar2303=== RUN TestGlobMatch/*bar_foo2304=== PAUSE TestGlobMatch/*bar_foo2305=== RUN TestGlobMatch/foo*bar_foobar2306=== PAUSE TestGlobMatch/foo*bar_foobar2307=== RUN TestGlobMatch/foo*bar_foo123bar2308=== PAUSE TestGlobMatch/foo*bar_foo123bar2309=== RUN TestGlobMatch/foo*bar_foobarbaz2310=== PAUSE TestGlobMatch/foo*bar_foobarbaz2311=== RUN TestGlobMatch/*/*_foo/bar2312=== PAUSE TestGlobMatch/*/*_foo/bar2313=== RUN TestGlobMatch/*/*_foo2314=== PAUSE TestGlobMatch/*/*_foo2315=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2316=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2317=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02318=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02319=== RUN TestGlobMatch/refs/*/main_refs/heads/main2320=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2321=== RUN TestGlobMatch/fo?_foo2322=== PAUSE TestGlobMatch/fo?_foo2323=== RUN TestGlobMatch/fo?_fo2324=== PAUSE TestGlobMatch/fo?_fo2325=== RUN TestGlobMatch/fo?_fooo2326=== PAUSE TestGlobMatch/fo?_fooo2327=== RUN TestGlobMatch/?oo_foo2328=== PAUSE TestGlobMatch/?oo_foo2329=== RUN TestGlobMatch/?oo_boo2330=== PAUSE TestGlobMatch/?oo_boo2331=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2332=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2333=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2334=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2335=== CONT TestGlobMatch/foo_foo2336=== CONT TestPins_ReservedForMatchingRule2337=== CONT TestGlobMatch/*/*_foo/bar2338=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2339=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2340=== CONT TestGlobMatch/?oo_boo2341=== CONT TestGlobMatch/?oo_foo2342=== CONT TestGlobMatch/fo?_fooo2343=== CONT TestGlobMatch/fo?_fo2344=== CONT TestGlobMatch/fo?_foo2345=== CONT TestGlobMatch/refs/*/main_refs/heads/main2346=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02347=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2348=== CONT TestGlobMatch/*/*_foo2349=== CONT TestGlobMatch/*bar_bar2350=== CONT TestGlobMatch/foo*bar_foobarbaz2351=== CONT TestGlobMatch/foo*bar_foo123bar2352=== CONT TestGlobMatch/foo*bar_foobar2353=== CONT TestGlobMatch/*bar_foo2354=== CONT TestGlobMatch/*bar_foobar2355=== CONT TestGlobMatch/foo*_foo2356=== CONT TestGlobMatch/foo*_bar2357=== CONT TestGlobMatch/foo*_foobar2358=== CONT TestGlobMatch/*_2359=== CONT TestGlobMatch/*_anything2360=== CONT TestGlobMatch/foo_bar2361--- PASS: TestGlobMatch (0.00s)2362 --- PASS: TestGlobMatch/foo_foo (0.00s)2363 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2364 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2365 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2366 --- PASS: TestGlobMatch/?oo_boo (0.00s)2367 --- PASS: TestGlobMatch/?oo_foo (0.00s)2368 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2369 --- PASS: TestGlobMatch/fo?_fo (0.00s)2370 --- PASS: TestGlobMatch/fo?_foo (0.00s)2371 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2372 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2373 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2374 --- PASS: TestGlobMatch/*/*_foo (0.00s)2375 --- PASS: TestGlobMatch/*bar_bar (0.00s)2376 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2377 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2378 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2379 --- PASS: TestGlobMatch/*bar_foo (0.00s)2380 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2381 --- PASS: TestGlobMatch/foo*_foo (0.00s)2382 --- PASS: TestGlobMatch/foo*_bar (0.00s)2383 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2384 --- PASS: TestGlobMatch/*_ (0.00s)2385 --- PASS: TestGlobMatch/*_anything (0.00s)2386 --- PASS: TestGlobMatch/foo_bar (0.00s)2387=== CONT TestPins_TopLevelShorthand2388=== CONT TestScopes_ConfigValidation2389--- PASS: TestScopes_ConfigValidation (0.00s)2390=== CONT TestScopes_LegacyProviderDefaultsToWrite2391=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2392=== CONT TestNewValidator_KubernetesRequiresCA2393=== CONT TestValidateToken_KubernetesServiceAccount23942026/10/27 08:43:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64686/oidc23952026/10/27 08:43:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64689/oidc2396--- PASS: TestValidateToken_WrongAudience (0.05s)23972026/10/27 08:43:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64691/oidc2398--- PASS: TestScopes_Rules (0.06s)2399--- PASS: TestValidateToken_Expired (0.05s)24002026/10/27 08:43:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64693/oidc24012026/10/27 08:43:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64695/oidc2402--- PASS: TestPins_TopLevelShorthand (0.05s)2403--- PASS: TestValidateToken_ValidToken (0.06s)24042026/10/27 08:43:55 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:646972405--- PASS: TestValidateToken_KubernetesServiceAccount (0.05s)24062026/10/27 08:43:55 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12324072026/10/27 08:43:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64701/oidc2408--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.07s)2409--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.08s)24102026/10/27 08:43:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64703/oidc2411--- PASS: TestValidateToken_BoundSubjectMismatch (0.10s)24122026/10/27 08:43:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64705/oidc2413--- PASS: TestValidateToken_BoundClaimsMismatch (0.10s)24142026/10/27 08:43:55 http: TLS handshake error from 127.0.0.1:64708: read tcp 127.0.0.1:64707->127.0.0.1:64708: use of closed network connection2415--- PASS: TestNewValidator_KubernetesRequiresCA (0.09s)24162026/10/27 08:43:55 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:64688/oidc2417--- PASS: TestValidateToken_NoMatchingProvider (0.12s)24182026/10/27 08:43:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64712/oidc2419--- PASS: TestPins_ReservedForMatchingRule (0.15s)24202026/10/27 08:43:55 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:64711/oidc24212026/10/27 08:43:55 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:64714/oidc2422--- PASS: TestValidateToken_MultipleProviders (0.20s)2423PASS2424Running hook tests...2425=== RUN TestSendPathsEmpty2426=== PAUSE TestSendPathsEmpty2427=== RUN TestQueueEnqueueAndFetch2428=== PAUSE TestQueueEnqueueAndFetch2429=== RUN TestQueueDeduplication2430=== PAUSE TestQueueDeduplication2431=== RUN TestQueueRemove2432=== PAUSE TestQueueRemove2433=== RUN TestQueueFetchBatchLimit2434=== PAUSE TestQueueFetchBatchLimit2435=== RUN TestQueueRetryMovesToBack2436=== PAUSE TestQueueRetryMovesToBack2437=== RUN TestQueueFetchRemoveLifecycle2438=== PAUSE TestQueueFetchRemoveLifecycle2439=== RUN TestQueueConcurrentWriters2440=== PAUSE TestQueueConcurrentWriters2441=== RUN TestQueueRemoveLargeClosure2442=== PAUSE TestQueueRemoveLargeClosure2443=== RUN TestServerClientIntegration2444--- PASS: TestServerClientIntegration (0.00s)2445=== RUN TestServerQueueError24462026/10/27 08:43:56 ERROR Failed to queue paths error="permission denied" count=12447--- PASS: TestServerQueueError (0.00s)2448=== RUN TestGetListenerSocketActivation2449 server_test.go:145: systemd socket activation does not exist on darwin2450--- SKIP: TestGetListenerSocketActivation (0.00s)2451=== RUN TestServerStalledClientDoesNotBlockShutdown2452=== PAUSE TestServerStalledClientDoesNotBlockShutdown2453=== RUN TestServerBacksOffOnAcceptErrors2454=== PAUSE TestServerBacksOffOnAcceptErrors2455=== RUN TestDrainIsolatesPoisonPath2456=== PAUSE TestDrainIsolatesPoisonPath2457=== RUN TestRunNotBlockedByPoisonHead2458=== PAUSE TestRunNotBlockedByPoisonHead2459=== RUN TestDrainGivesUpWhenServerDown2460=== PAUSE TestDrainGivesUpWhenServerDown2461=== RUN TestFailedPathPrunedByLaterClosure2462=== PAUSE TestFailedPathPrunedByLaterClosure2463=== RUN TestWorkerUploadsAndRemoves2464=== PAUSE TestWorkerUploadsAndRemoves2465=== RUN TestWorkerSkipsGCdPaths2466=== PAUSE TestWorkerSkipsGCdPaths2467=== RUN TestWorkerPrunesClosureDeps2468=== PAUSE TestWorkerPrunesClosureDeps2469=== RUN TestDrainTimeout2470=== PAUSE TestDrainTimeout2471=== RUN TestWorkerRemoveFailureIsNotProgress2472=== PAUSE TestWorkerRemoveFailureIsNotProgress2473=== RUN TestWorkerKeepsPathItCannotStat2474=== PAUSE TestWorkerKeepsPathItCannotStat2475=== CONT TestSendPathsEmpty2476=== CONT TestWorkerRemoveFailureIsNotProgress2477--- PASS: TestSendPathsEmpty (0.00s)2478=== CONT TestWorkerKeepsPathItCannotStat2479=== CONT TestDrainIsolatesPoisonPath2480=== CONT TestServerBacksOffOnAcceptErrors2481=== CONT TestServerStalledClientDoesNotBlockShutdown24822026/10/27 08:43:56 ERROR Accept failed error="too many open files"2483=== CONT TestQueueRemoveLargeClosure2484=== CONT TestQueueRemove2485=== CONT TestQueueDeduplication2486=== CONT TestQueueEnqueueAndFetch2487=== CONT TestQueueFetchBatchLimit2488=== CONT TestQueueFetchRemoveLifecycle2489=== CONT TestQueueRetryMovesToBack2490=== CONT TestQueueConcurrentWriters2491=== CONT TestWorkerUploadsAndRemoves2492=== CONT TestDrainTimeout2493=== CONT TestWorkerPrunesClosureDeps2494=== CONT TestWorkerSkipsGCdPaths2495=== CONT TestDrainGivesUpWhenServerDown2496=== CONT TestFailedPathPrunedByLaterClosure2497=== CONT TestRunNotBlockedByPoisonHead24982026/10/27 08:43:56 ERROR Accept failed error="too many open files"24992026/10/27 08:43:56 INFO Uploading batch count=425002026/10/27 08:43:56 ERROR Upload failed error="upload failed" count=425012026/10/27 08:43:56 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/a23fa3231491b957/build/TestDrainIsolatesPoisonPath2988590524/002/bbb25022026/10/27 08:43:56 INFO Uploading batch count=125032026/10/27 08:43:56 ERROR Upload failed error="upload failed" count=125042026/10/27 08:43:56 INFO Uploading batch count=125052026/10/27 08:43:56 WARN Cannot stat store path, will retry later path=/private/var/tb/5/scratch/a23fa3231491b957/build/TestWorkerKeepsPathItCannotStat132905566/002/locked/aaa error="stat /private/var/tb/5/scratch/a23fa3231491b957/build/TestWorkerKeepsPathItCannotStat132905566/002/locked/aaa: permission denied"25062026/10/27 08:43:56 INFO Uploading batch count=225072026/10/27 08:43:56 ERROR Upload failed error="upload failed" count=225082026/10/27 08:43:56 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/a23fa3231491b957/build/TestDrainGivesUpWhenServerDown901300235/002/a25092026/10/27 08:43:56 INFO Uploading batch count=12510--- PASS: TestQueueDeduplication (0.01s)25112026/10/27 08:43:56 INFO Uploading batch count=125122026/10/27 08:43:56 ERROR Upload failed error="upload failed" count=125132026/10/27 08:43:56 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/a23fa3231491b957/build/TestDrainGivesUpWhenServerDown901300235/002/b25142026/10/27 08:43:56 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/a23fa3231491b957/build/TestWorkerRemoveFailureIsNotProgress328682597/002/nonexistent25152026/10/27 08:43:56 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125162026/10/27 08:43:56 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/a23fa3231491b957/build/TestWorkerRemoveFailureIsNotProgress328682597/002/nonexistent25172026/10/27 08:43:56 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125182026/10/27 08:43:56 INFO Uploading batch count=125192026/10/27 08:43:56 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/a23fa3231491b957/build/TestWorkerRemoveFailureIsNotProgress328682597/002/nonexistent25202026/10/27 08:43:56 ERROR Upload failed error="upload failed" count=125212026/10/27 08:43:56 INFO Uploading batch count=225222026/10/27 08:43:56 ERROR Upload failed error="upload failed" count=225232026/10/27 08:43:56 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/a23fa3231491b957/build/TestDrainGivesUpWhenServerDown901300235/002/c25242026/10/27 08:43:56 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125252026/10/27 08:43:56 ERROR Drain finished with paths left in queue remaining=125262026/10/27 08:43:56 INFO Upload queue status pending=325272026/10/27 08:43:56 INFO Uploading batch count=125282026/10/27 08:43:56 ERROR Upload failed error="upload failed" count=12529--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)2530--- PASS: TestWorkerRemoveFailureIsNotProgress (0.01s)25312026/10/27 08:43:56 INFO Upload queue status pending=225322026/10/27 08:43:56 INFO Uploading batch count=225332026/10/27 08:43:56 ERROR Accept failed error="too many open files"2534--- PASS: TestQueueEnqueueAndFetch (0.02s)25352026/10/27 08:43:56 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/a23fa3231491b957/build/TestDrainGivesUpWhenServerDown901300235/002/d2536--- PASS: TestQueueFetchBatchLimit (0.02s)25372026/10/27 08:43:56 INFO Uploading batch count=125382026/10/27 08:43:56 ERROR Upload failed error="upload failed" count=125392026/10/27 08:43:56 INFO Uploading batch count=225402026/10/27 08:43:56 ERROR Upload failed error="upload failed" count=225412026/10/27 08:43:56 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/a23fa3231491b957/build/TestDrainGivesUpWhenServerDown901300235/002/e25422026/10/27 08:43:56 WARN Cannot stat store path, will retry later path=/private/var/tb/5/scratch/a23fa3231491b957/build/TestWorkerKeepsPathItCannotStat132905566/002/locked/aaa error="stat /private/var/tb/5/scratch/a23fa3231491b957/build/TestWorkerKeepsPathItCannotStat132905566/002/locked/aaa: permission denied"25432026/10/27 08:43:56 ERROR Drain finished with paths left in queue remaining=125442026/10/27 08:43:56 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/a23fa3231491b957/build/TestDrainGivesUpWhenServerDown901300235/002/f2545--- PASS: TestQueueRemove (0.02s)25462026/10/27 08:43:56 ERROR Drain finished with paths left in queue remaining=1025472026/10/27 08:43:56 INFO Upload queue status pending=225482026/10/27 08:43:56 WARN Cannot stat store path, will retry later path=/private/var/tb/5/scratch/a23fa3231491b957/build/TestWorkerKeepsPathItCannotStat132905566/002/locked/aaa error="stat /private/var/tb/5/scratch/a23fa3231491b957/build/TestWorkerKeepsPathItCannotStat132905566/002/locked/aaa: permission denied"25492026/10/27 08:43:56 INFO Uploading batch count=12550--- PASS: TestQueueFetchRemoveLifecycle (0.02s)25512026/10/27 08:43:56 INFO Uploading batch count=225522026/10/27 08:43:56 ERROR Drain finished with paths left in queue remaining=125532026/10/27 08:43:56 INFO Upload queue status pending=225542026/10/27 08:43:56 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/a23fa3231491b957/build/TestWorkerSkipsGCdPaths1130039728/002/nonexistent2555--- PASS: TestDrainIsolatesPoisonPath (0.02s)2556--- PASS: TestQueueRetryMovesToBack (0.02s)25572026/10/27 08:43:56 INFO Uploading batch count=12558--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)2559--- PASS: TestDrainGivesUpWhenServerDown (0.02s)25602026/10/27 08:43:56 ERROR Accept failed error="too many open files"2561--- PASS: TestWorkerUploadsAndRemoves (0.04s)2562--- PASS: TestWorkerPrunesClosureDeps (0.04s)2563--- PASS: TestWorkerSkipsGCdPaths (0.04s)2564--- PASS: TestQueueRemoveLargeClosure (0.05s)25652026/10/27 08:43:56 ERROR Accept failed error="too many open files"25662026/10/27 08:43:56 ERROR Accept failed error="too many open files"2567--- PASS: TestQueueConcurrentWriters (0.16s)25682026/10/27 08:43:56 ERROR Failed to decode request error="read unix /private/var/tb/5/scratch/a23fa3231491b957/build/hook818935414/test.sock->: i/o timeout"25692026/10/27 08:43:56 ERROR Failed to write response error="write unix /private/var/tb/5/scratch/a23fa3231491b957/build/hook818935414/test.sock->: i/o timeout"2570--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)25712026/10/27 08:43:56 ERROR Upload failed error="context deadline exceeded" count=225722026/10/27 08:43:56 ERROR Drain finished with paths left in queue remaining=42573--- PASS: TestDrainTimeout (0.22s)25742026/10/27 08:43:56 ERROR Accept failed error="too many open files"25752026/10/27 08:43:56 ERROR Accept failed error="too many open files"2576--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)25772026/10/27 08:43:57 INFO Uploading batch count=125782026/10/27 08:43:57 INFO Uploading batch count=125792026/10/27 08:43:57 INFO Uploading batch count=125802026/10/27 08:43:57 ERROR Upload failed error="upload failed" count=125812026/10/27 08:43:57 INFO Uploading batch count=125822026/10/27 08:43:57 ERROR Upload failed error="upload failed" count=125832026/10/27 08:43:57 INFO Uploading batch count=125842026/10/27 08:43:57 ERROR Upload failed error="upload failed" count=125852026/10/27 08:43:57 INFO Uploading batch count=125862026/10/27 08:43:57 ERROR Upload failed error="upload failed" count=125872026/10/27 08:43:57 ERROR Drain finished with paths left in queue remaining=12588--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2589PASS2590Running signing tests...2591=== RUN TestExternalSigner2592=== PAUSE TestExternalSigner2593=== RUN TestExternalSignerWrongPublicKey2594=== PAUSE TestExternalSignerWrongPublicKey2595=== RUN TestExternalSignerErrors2596=== PAUSE TestExternalSignerErrors2597=== RUN TestExternalSignerRestartsAfterCrash2598=== PAUSE TestExternalSignerRestartsAfterCrash2599=== RUN TestExternalSignerProgramErrorKeepsProcess2600=== PAUSE TestExternalSignerProgramErrorKeepsProcess2601=== RUN TestExternalSignerClose2602=== PAUSE TestExternalSignerClose2603=== RUN TestExternalSignerRejectsInvalidPublicKey2604=== PAUSE TestExternalSignerRejectsInvalidPublicKey2605=== RUN TestExternalSignerCancellation2606=== PAUSE TestExternalSignerCancellation2607=== RUN TestGenerateFingerprint2608=== PAUSE TestGenerateFingerprint2609=== RUN TestParseSigningKey2610=== PAUSE TestParseSigningKey2611=== RUN TestSign2612=== PAUSE TestSign2613=== RUN TestSignBatch2614=== PAUSE TestSignBatch2615=== RUN TestNilKeyPublicKey2616=== PAUSE TestNilKeyPublicKey2617=== RUN TestSignErrors2618=== PAUSE TestSignErrors2619=== CONT TestExternalSigner2620=== CONT TestExternalSignerCancellation2621=== CONT TestSignBatch2622=== CONT TestSignErrors2623=== CONT TestSign2624=== CONT TestNilKeyPublicKey2625--- PASS: TestNilKeyPublicKey (0.00s)2626=== CONT TestExternalSignerRestartsAfterCrash2627=== CONT TestParseSigningKey2628=== RUN TestParseSigningKey/valid_32-byte_key2629=== PAUSE TestParseSigningKey/valid_32-byte_key2630=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2631=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2632=== RUN TestParseSigningKey/no_colon2633=== PAUSE TestParseSigningKey/no_colon2634=== RUN TestParseSigningKey/empty_name2635=== PAUSE TestParseSigningKey/empty_name2636=== RUN TestParseSigningKey/invalid_base642637=== PAUSE TestParseSigningKey/invalid_base642638=== RUN TestParseSigningKey/wrong_length2639=== PAUSE TestParseSigningKey/wrong_length2640=== CONT TestParseSigningKey/valid_32-byte_key2641=== CONT TestExternalSignerProgramErrorKeepsProcess2642=== CONT TestParseSigningKey/empty_name2643=== CONT TestParseSigningKey/wrong_length2644=== CONT TestParseSigningKey/invalid_base642645=== CONT TestParseSigningKey/no_colon2646=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2647=== CONT TestExternalSignerRejectsInvalidPublicKey2648=== RUN TestExternalSignerRejectsInvalidPublicKey/#002649=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002650=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2651=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2652=== CONT TestExternalSignerClose2653=== CONT TestGenerateFingerprint2654=== RUN TestGenerateFingerprint/basic_with_references2655=== PAUSE TestGenerateFingerprint/basic_with_references2656=== RUN TestGenerateFingerprint/no_references2657=== CONT TestExternalSignerErrors2658=== RUN TestExternalSignerErrors/invalid_JSON2659=== PAUSE TestExternalSignerErrors/invalid_JSON2660=== CONT TestExternalSignerWrongPublicKey2661=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2662=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2663=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2664=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2665=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2666=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2667=== CONT TestExternalSignerRejectsInvalidPublicKey/#002668=== PAUSE TestGenerateFingerprint/no_references2669=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2670=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2671=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2672=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2673=== RUN TestGenerateFingerprint/invalid_nar_hash_length2674=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2675=== RUN TestGenerateFingerprint/invalid_store_path_prefix2676=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2677=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2678=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2679=== RUN TestGenerateFingerprint/invalid_reference_prefix2680=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2681=== RUN TestExternalSignerErrors/wrong_shape2682=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2683--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2684 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2685 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2686 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2687 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2688 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2689=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2690=== CONT TestGenerateFingerprint/basic_with_references2691=== PAUSE TestExternalSignerErrors/wrong_shape2692=== RUN TestExternalSignerErrors/null2693=== CONT TestGenerateFingerprint/invalid_nar_hash_length2694=== PAUSE TestExternalSignerErrors/null2695=== RUN TestExternalSignerErrors/missing_signatures2696=== PAUSE TestExternalSignerErrors/missing_signatures2697=== RUN TestExternalSignerErrors/null_signatures2698=== PAUSE TestExternalSignerErrors/null_signatures2699=== RUN TestExternalSignerErrors/program_error2700=== CONT TestGenerateFingerprint/invalid_reference_prefix2701=== RUN TestSignErrors/nil_key2702=== PAUSE TestSignErrors/nil_key2703=== RUN TestSignErrors/nil_narinfo2704=== PAUSE TestSignErrors/nil_narinfo2705=== PAUSE TestExternalSignerErrors/program_error2706=== RUN TestExternalSignerErrors/missing_signature_name2707=== RUN TestSignErrors/invalid_narinfo2708=== CONT TestGenerateFingerprint/invalid_store_path_prefix2709=== PAUSE TestSignErrors/invalid_narinfo2710=== RUN TestSignErrors/canceled2711=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2712=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2713=== CONT TestGenerateFingerprint/no_references2714=== PAUSE TestExternalSignerErrors/missing_signature_name2715=== RUN TestExternalSignerErrors/wrong_signature_name2716=== PAUSE TestExternalSignerErrors/wrong_signature_name2717=== RUN TestExternalSignerErrors/wrong_signature_length2718=== PAUSE TestExternalSignerErrors/wrong_signature_length2719--- PASS: TestSign (0.00s)2720=== PAUSE TestSignErrors/canceled2721--- PASS: TestParseSigningKey (0.00s)2722 --- PASS: TestParseSigningKey/empty_name (0.00s)2723 --- PASS: TestParseSigningKey/wrong_length (0.00s)2724 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2725 --- PASS: TestParseSigningKey/no_colon (0.00s)2726 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2727 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2728--- PASS: TestSignBatch (0.00s)2729=== CONT TestSignErrors/nil_key2730=== RUN TestExternalSignerErrors/exit_at_startup2731=== CONT TestSignErrors/canceled2732=== PAUSE TestExternalSignerErrors/exit_at_startup2733=== RUN TestExternalSignerErrors/too_few_signatures2734=== CONT TestSignErrors/invalid_narinfo2735=== CONT TestSignErrors/nil_narinfo2736--- PASS: TestGenerateFingerprint (0.00s)2737 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2738 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2739 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2740 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2741 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2742 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2743 --- PASS: TestGenerateFingerprint/no_references (0.00s)2744=== PAUSE TestExternalSignerErrors/too_few_signatures2745=== RUN TestExternalSignerErrors/unrequested_key2746--- PASS: TestSignErrors (0.00s)2747 --- PASS: TestSignErrors/nil_key (0.00s)2748 --- PASS: TestSignErrors/canceled (0.00s)2749 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2750 --- PASS: TestSignErrors/nil_narinfo (0.00s)2751=== PAUSE TestExternalSignerErrors/unrequested_key2752=== RUN TestExternalSignerErrors/exit_on_request2753=== PAUSE TestExternalSignerErrors/exit_on_request2754=== RUN TestExternalSignerErrors/wrong_id2755=== PAUSE TestExternalSignerErrors/wrong_id2756=== RUN TestExternalSignerErrors/wrong_signatures_shape2757=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2758=== RUN TestExternalSignerErrors/invalid_signature_base642759=== PAUSE TestExternalSignerErrors/invalid_signature_base642760=== CONT TestExternalSignerErrors/invalid_JSON2761=== CONT TestExternalSignerErrors/exit_on_request2762=== CONT TestExternalSignerErrors/wrong_signatures_shape2763=== CONT TestExternalSignerErrors/invalid_signature_base642764=== CONT TestExternalSignerErrors/wrong_id2765=== CONT TestExternalSignerErrors/too_few_signatures2766=== CONT TestExternalSignerErrors/exit_at_startup2767=== CONT TestExternalSignerErrors/unrequested_key2768=== CONT TestExternalSignerErrors/wrong_signature_length2769=== CONT TestExternalSignerErrors/missing_signatures2770=== CONT TestExternalSignerErrors/program_error2771=== CONT TestExternalSignerErrors/null2772=== CONT TestExternalSignerErrors/null_signatures2773=== CONT TestExternalSignerErrors/wrong_signature_name2774=== CONT TestExternalSignerErrors/wrong_shape2775=== CONT TestExternalSignerErrors/missing_signature_name2776--- PASS: TestExternalSignerCancellation (0.12s)2777--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.17s)2778--- PASS: TestExternalSigner (0.26s)2779--- PASS: TestExternalSignerRestartsAfterCrash (0.34s)2780/private/var/tb/5/scratch/a23fa3231491b957/build/TestExternalSignerRestartsAfterCrash1769512032/001/sign program: line 7: /private/var/tb/5/scratch/a23fa3231491b957/build/TestExternalSignerRestartsAfterCrash1769512032/001/sign program.starts: No such file or directory2781--- PASS: TestExternalSignerWrongPublicKey (1.08s)2782--- PASS: TestExternalSignerClose (1.39s)2783--- PASS: TestExternalSignerErrors (0.00s)2784 --- PASS: TestExternalSignerErrors/invalid_JSON (0.40s)2785 --- PASS: TestExternalSignerErrors/program_error (0.47s)2786 --- PASS: TestExternalSignerErrors/too_few_signatures (0.55s)2787 --- PASS: TestExternalSignerErrors/missing_signatures (0.63s)2788 --- PASS: TestExternalSignerErrors/exit_on_request (0.70s)2789 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.78s)2790 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.85s)2791 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.93s)2792 --- PASS: TestExternalSignerErrors/unrequested_key (1.00s)2793 --- PASS: TestExternalSignerErrors/missing_signature_name (1.16s)2794 --- PASS: TestExternalSignerErrors/null_signatures (1.23s)2795 --- PASS: TestExternalSignerErrors/wrong_id (1.31s)2796 --- PASS: TestExternalSignerErrors/wrong_signature_length (1.46s)2797 --- PASS: TestExternalSignerErrors/null (1.53s)2798 --- PASS: TestExternalSignerErrors/wrong_shape (1.61s)2799 --- PASS: TestExternalSignerErrors/exit_at_startup (1.70s)2800PASS2801Running OpenBao signer tests...2802=== RUN TestSign2803=== PAUSE TestSign2804=== RUN TestSignErrors2805=== PAUSE TestSignErrors2806=== RUN TestServe2807=== PAUSE TestServe2808=== RUN TestServeRejectsGarbage2809=== PAUSE TestServeRejectsGarbage2810=== CONT TestSign2811=== CONT TestSignErrors2812=== CONT TestServe2813=== CONT TestServeRejectsGarbage2814--- PASS: TestServeRejectsGarbage (0.00s)2815=== RUN TestSignErrors/no_prefix2816=== PAUSE TestSignErrors/no_prefix2817=== RUN TestSignErrors/invalid_base642818=== PAUSE TestSignErrors/invalid_base642819=== RUN TestSignErrors/http_error2820=== PAUSE TestSignErrors/http_error2821=== RUN TestSignErrors/invalid_json2822=== PAUSE TestSignErrors/invalid_json2823=== CONT TestSignErrors/no_prefix2824=== CONT TestSignErrors/http_error2825=== CONT TestSignErrors/invalid_base642826=== CONT TestSignErrors/invalid_json2827--- PASS: TestServe (0.00s)2828--- PASS: TestSign (0.01s)2829--- PASS: TestSignErrors (0.00s)2830 --- PASS: TestSignErrors/invalid_base64 (0.00s)2831 --- PASS: TestSignErrors/http_error (0.00s)2832 --- PASS: TestSignErrors/invalid_json (0.00s)2833 --- PASS: TestSignErrors/no_prefix (0.01s)2834PASS