niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #415
· 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 TestPartSizeForNAR20=== PAUSE TestPartSizeForNAR21=== RUN TestUploadMultipart_SupersededByPeer22=== PAUSE TestUploadMultipart_SupersededByPeer23=== RUN TestDumpPathCaseHackMatchesNix24--- PASS: TestDumpPathCaseHackMatchesNix (0.06s)25=== RUN TestDumpPathCaseHackCollision26--- PASS: TestDumpPathCaseHackCollision (0.00s)27=== RUN TestSupersededNARStillUploadsListing28=== PAUSE TestSupersededNARStillUploadsListing29=== RUN TestDumpPathMatchesNix30=== PAUSE TestDumpPathMatchesNix31=== RUN TestDumpPathSingleFile32=== PAUSE TestDumpPathSingleFile33=== RUN TestDumpPathWriterError34=== PAUSE TestDumpPathWriterError35=== RUN TestEncodeNixBase3236=== PAUSE TestEncodeNixBase3237=== RUN TestEncodeNixBase32WithRealHash38=== PAUSE TestEncodeNixBase32WithRealHash39=== RUN TestConvertHashToNix3240=== PAUSE TestConvertHashToNix3241=== RUN TestGetStorePathHash42=== PAUSE TestGetStorePathHash43=== RUN TestPathInfoHashCompatibility44=== PAUSE TestPathInfoHashCompatibility45=== RUN TestParsePathInfoJSON46=== PAUSE TestParsePathInfoJSON47=== RUN TestParsePathInfoJSONMultiplePaths48=== PAUSE TestParsePathInfoJSONMultiplePaths49=== RUN TestPathInfoCACompatibility50=== PAUSE TestPathInfoCACompatibility51=== RUN TestRateLimiterFeedback52=== PAUSE TestRateLimiterFeedback53=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess54=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess55=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer56=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer57=== RUN TestResolveStorePath58=== PAUSE TestResolveStorePath59=== RUN TestDoWithRetry_BodyReplayedViaGetBody60=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody61=== RUN TestRetryTimeoutOutlastsMaxRetries62=== PAUSE TestRetryTimeoutOutlastsMaxRetries63=== RUN TestDoWithRetry_FinalResponseBodyReadable64=== PAUSE TestDoWithRetry_FinalResponseBodyReadable65=== RUN TestShellSplit66=== PAUSE TestShellSplit67=== RUN TestShellSplitErrors68=== PAUSE TestShellSplitErrors69=== RUN TestStreamPushReportsEveryPath70=== PAUSE TestStreamPushReportsEveryPath71=== RUN TestStreamPushBatchesUnderLoad72=== PAUSE TestStreamPushBatchesUnderLoad73=== RUN TestStreamPushIsolatesFailures74=== PAUSE TestStreamPushIsolatesFailures75=== RUN TestStreamPushGivesUpOnDeadServer76=== PAUSE TestStreamPushGivesUpOnDeadServer77=== RUN TestStreamPushRequestLine78=== PAUSE TestStreamPushRequestLine79=== RUN TestStreamPushReportsSignatures80=== PAUSE TestStreamPushReportsSignatures81=== RUN TestStreamPushReportsSkippedPaths82=== PAUSE TestStreamPushReportsSkippedPaths83=== RUN TestClientSignaturesByStorePath84=== PAUSE TestClientSignaturesByStorePath85=== RUN TestStreamPushStopsWhenCanceled86=== PAUSE TestStreamPushStopsWhenCanceled87=== RUN TestSetClientTLS88=== PAUSE TestSetClientTLS89=== RUN TestSetClientTLSDoesNotMutateDefaultTransport90=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport91=== RUN TestSetClientTLSErrors92=== PAUSE TestSetClientTLSErrors93=== RUN TestStaticToken94=== PAUSE TestStaticToken95=== RUN TestFileTokenReadsAndCaches96=== PAUSE TestFileTokenReadsAndCaches97=== RUN TestFileTokenMissing98=== PAUSE TestFileTokenMissing99=== RUN TestFileTokenEmpty100=== PAUSE TestFileTokenEmpty101=== RUN TestScriptTokenNoExpiryRerunsEveryCall102=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall103=== RUN TestScriptTokenCachesUntilRefresh104=== PAUSE TestScriptTokenCachesUntilRefresh105=== RUN TestScriptTokenEmptyToken106=== PAUSE TestScriptTokenEmptyToken107=== RUN TestScriptTokenBadJSON108=== PAUSE TestScriptTokenBadJSON109=== RUN TestScriptTokenScriptFails110=== PAUSE TestScriptTokenScriptFails111=== RUN TestScriptTokenEmptyCommand112=== PAUSE TestScriptTokenEmptyCommand113=== CONT TestDoServerRequestAttachesToken114=== CONT TestRetryTimeoutOutlastsMaxRetries115=== CONT TestStreamPushGivesUpOnDeadServer116=== CONT TestSetClientTLS117=== CONT TestScriptTokenEmptyCommand118=== CONT TestEncodeNixBase32119--- PASS: TestScriptTokenEmptyCommand (0.00s)120=== RUN TestEncodeNixBase32/test_string_hash121=== PAUSE TestEncodeNixBase32/test_string_hash122=== CONT TestParsePathInfoJSON123=== RUN TestParsePathInfoJSON/Nix_format124=== CONT TestScriptTokenScriptFails125=== RUN TestEncodeNixBase32/empty_input126=== PAUSE TestEncodeNixBase32/empty_input127=== CONT TestPathInfoHashCompatibility1282026/10/14 16:44:55 ERROR Upload failed error="connection refused" count=201292026/10/14 16:44:55 ERROR Server seems unavailable, giving up on batch untried=17130=== CONT TestScriptTokenCachesUntilRefresh131=== CONT TestScriptTokenNoExpiryRerunsEveryCall132=== CONT TestFileTokenEmpty133=== CONT TestFileTokenMissing134=== CONT TestFileTokenReadsAndCaches135--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)136=== CONT TestGetStorePathHash137=== RUN TestGetStorePathHash/valid_store_path138=== PAUSE TestGetStorePathHash/valid_store_path139=== RUN TestGetStorePathHash/basename_without_hyphen_should_error140=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error141=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error142=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error143=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error144=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error145=== CONT TestConvertHashToNix32146=== RUN TestConvertHashToNix32/SRI_format_to_Nix32147=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32148=== RUN TestConvertHashToNix32/already_Nix32_format149=== PAUSE TestConvertHashToNix32/already_Nix32_format150=== RUN TestConvertHashToNix32/invalid_format151=== PAUSE TestConvertHashToNix32/invalid_format152=== CONT TestStaticToken153=== CONT TestSetClientTLSErrors154=== CONT TestSetClientTLSDoesNotMutateDefaultTransport155=== CONT TestDoWithRetry_BodyReplayedViaGetBody156=== CONT TestResolveStorePath157=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer158=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess159=== CONT TestRateLimiterFeedback160=== CONT TestPathInfoCACompatibility161=== CONT TestParsePathInfoJSONMultiplePaths162=== CONT TestScriptTokenBadJSON163=== CONT TestScriptTokenEmptyToken164=== PAUSE TestParsePathInfoJSON/Nix_format165=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)166=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)167=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon168=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon169=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI170=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI171=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512172=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha5121732026/10/14 16:44:55 WARN Rate limiter enabled after throttle name=server-test rate=5174=== RUN TestRateLimiterFeedback/429_enables_limiter175=== PAUSE TestRateLimiterFeedback/429_enables_limiter176=== RUN TestRateLimiterFeedback/503_enables_limiter177=== PAUSE TestRateLimiterFeedback/503_enables_limiter178=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter179=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter180=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter181=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter182=== RUN TestPathInfoCACompatibility/null_ca_field183=== PAUSE TestPathInfoCACompatibility/null_ca_field184=== RUN TestPathInfoCACompatibility/old_string_format_-_text185=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text186=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive187=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive188=== RUN TestPathInfoCACompatibility/new_structured_format_-_text189=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text190=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method191=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method192=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths193=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths194=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths195=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths196=== CONT TestStreamPushStopsWhenCanceled197--- PASS: TestStaticToken (0.00s)198=== CONT TestClientSignaturesByStorePath199--- PASS: TestStreamPushStopsWhenCanceled (0.00s)200=== CONT TestUploadMultipart_PartsInParallel201--- PASS: TestClientSignaturesByStorePath (0.00s)202--- PASS: TestFileTokenEmpty (0.00s)203=== RUN TestParsePathInfoJSON/Lix_format204--- PASS: TestFileTokenMissing (0.00s)205=== CONT TestDumpPathMatchesNix206=== RUN TestSetClientTLSErrors/missing_cert_file207=== PAUSE TestSetClientTLSErrors/missing_cert_file208=== RUN TestSetClientTLSErrors/missing_key_file209=== PAUSE TestSetClientTLSErrors/missing_key_file210=== RUN TestSetClientTLSErrors/missing_ca_file211=== CONT TestSupersededNARStillUploadsListing212=== RUN TestSupersededNARStillUploadsListing/small_NAR213=== PAUSE TestSupersededNARStillUploadsListing/small_NAR214=== RUN TestSupersededNARStillUploadsListing/dump_cut_short215=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short216=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails217=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails218=== CONT TestStreamPushReportsSkippedPaths219=== CONT TestDumpPathSingleFile220--- PASS: TestStreamPushReportsSkippedPaths (0.00s)221=== CONT TestStreamPushReportsSignatures222=== CONT TestDumpPathWriterError223=== PAUSE TestParsePathInfoJSON/Lix_format224=== RUN TestParsePathInfoJSON/empty_input225=== PAUSE TestParsePathInfoJSON/empty_input226=== RUN TestParsePathInfoJSON/whitespace_only227=== PAUSE TestParsePathInfoJSON/whitespace_only228=== RUN TestParsePathInfoJSON/invalid_JSON229=== PAUSE TestParsePathInfoJSON/invalid_JSON230=== CONT TestStreamPushRequestLine2312026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:58181232--- PASS: TestResolveStorePath (0.01s)233=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun2342026/10/14 16:44:55 ERROR Upload failed error=boom count=12352026/10/14 16:44:55 ERROR Upload failed error=boom count=12362026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:58181237=== CONT TestUploadMultipart_SupersededByPeer238=== RUN TestUploadMultipart_SupersededByPeer/exists239=== PAUSE TestUploadMultipart_SupersededByPeer/exists240=== RUN TestUploadMultipart_SupersededByPeer/missing241=== CONT TestEncodeNixBase32WithRealHash242=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica243=== RUN TestSetClientTLS/rejects_connection_without_client_cert2442026/10/14 16:44:55 WARN Rate limiter enabled after throttle name=server-test rate=52452026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:58188246=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert247--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)248--- PASS: TestScriptTokenScriptFails (0.01s)249=== CONT TestPartSizeForNAR250=== RUN TestPartSizeForNAR/zero_stays_at_minimum251=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum252=== RUN TestPartSizeForNAR/small_stays_at_minimum253=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA2542026/10/14 16:44:55 WARN Rate limiter backed off name=server-test rate=5255=== PAUSE TestPartSizeForNAR/small_stays_at_minimum2562026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:58188257=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA258=== RUN TestSetClientTLS/preserves_debug_logging_transport259=== CONT TestFilterOversizedClosures260=== CONT TestRegisterUploadedObjectReusesConnections261=== PAUSE TestSetClientTLSErrors/missing_ca_file262=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry263=== RUN TestSetClientTLSErrors/invalid_ca_file264--- PASS: TestStreamPushReportsSignatures (0.01s)265--- PASS: TestEncodeNixBase32WithRealHash (0.00s)266--- PASS: TestDoServerRequestAttachesToken (0.01s)267=== PAUSE TestUploadMultipart_SupersededByPeer/missing268=== CONT TestCaseHackSuffix269=== CONT TestStreamPushReportsEveryPath270--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)271=== CONT TestStreamPushIsolatesFailures272--- PASS: TestStreamPushReportsEveryPath (0.00s)273=== RUN TestFilterOversizedClosures/no_limit_keeps_everything274=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything275=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped276=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped277=== RUN TestFilterOversizedClosures/all_closures_skipped278=== PAUSE TestFilterOversizedClosures/all_closures_skipped279=== CONT TestStreamPushBatchesUnderLoad280=== PAUSE TestSetClientTLS/preserves_debug_logging_transport281=== CONT TestShellSplit282--- PASS: TestShellSplit (0.00s)283=== CONT TestDoWithRetry_FinalResponseBodyReadable284=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum285=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum286=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts287=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts288=== RUN TestPartSizeForNAR/1_TiB289=== PAUSE TestPartSizeForNAR/1_TiB290=== RUN TestPartSizeForNAR/5_TiB_S3_max_object291=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object292=== RUN TestPartSizeForNAR/capped_at_5_GiB293=== PAUSE TestPartSizeForNAR/capped_at_5_GiB294=== PAUSE TestSetClientTLSErrors/invalid_ca_file295=== CONT TestShellSplitErrors296=== CONT TestEncodeNixBase32/test_string_hash297=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error298--- PASS: TestShellSplitErrors (0.00s)299=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error300=== CONT TestGetStorePathHash/basename_without_hyphen_should_error301=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)302=== CONT TestGetStorePathHash/valid_store_path303--- PASS: TestGetStorePathHash (0.00s)304 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)305 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)306 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)307 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)308=== CONT TestRateLimiterFeedback/429_enables_limiter309=== CONT TestEncodeNixBase32/empty_input310=== CONT TestConvertHashToNix32/SRI_format_to_Nix323112026/10/14 16:44:55 INFO Garbage collection started3122026/10/14 16:44:55 ERROR Upload failed error="bad path" count=3313--- PASS: TestEncodeNixBase32 (0.00s)314 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)315 --- PASS: TestEncodeNixBase32/empty_input (0.00s)316--- PASS: TestStreamPushIsolatesFailures (0.00s)317=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths318=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter319=== CONT TestRateLimiterFeedback/503_enables_limiter320=== CONT TestPathInfoCACompatibility/null_ca_field3212026/10/14 16:44:55 WARN Rate limiter enabled after throttle name=server-test rate=53222026/10/14 16:44:55 INFO Garbage collection started3232026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:581813242026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:581983252026/10/14 16:44:55 WARN Rate limiter backed off name=server-test rate=5326--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.00s)327=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method328=== CONT TestPathInfoCACompatibility/new_structured_format_-_text329=== CONT TestPathInfoCACompatibility/old_string_format_-_text330=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths331--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)332 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)333 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)334=== CONT TestConvertHashToNix32/invalid_format335=== CONT TestConvertHashToNix32/already_Nix32_format336--- PASS: TestConvertHashToNix32 (0.00s)337 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)338 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)339 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)340=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI341=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512342=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon343--- PASS: TestPathInfoHashCompatibility (0.00s)344 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)345 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)346 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)347 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)348=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter349=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive350--- PASS: TestPathInfoCACompatibility (0.00s)351 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)352 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)353 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)354 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)355 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)356=== CONT TestSupersededNARStillUploadsListing/small_NAR357--- PASS: TestScriptTokenEmptyToken (0.01s)358=== CONT TestParsePathInfoJSON/Nix_format359=== CONT TestParsePathInfoJSON/invalid_JSON360=== CONT TestParsePathInfoJSON/whitespace_only361=== CONT TestParsePathInfoJSON/empty_input362=== CONT TestParsePathInfoJSON/Lix_format363--- PASS: TestParsePathInfoJSON (0.01s)364 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)365 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)366 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)367 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)368 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)369=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails370--- PASS: TestFileTokenReadsAndCaches (0.02s)371=== CONT TestSupersededNARStillUploadsListing/dump_cut_short3722026/10/14 16:44:55 INFO Uploading abc-hello (1.0GB)3732026/10/14 16:44:55 INFO Uploading abc-hello (1.0GB)374=== CONT TestUploadMultipart_SupersededByPeer/exists3752026/10/14 16:44:55 WARN Rate limiter enabled after throttle name=s3-test rate=5376=== CONT TestUploadMultipart_SupersededByPeer/missing3772026/10/14 16:44:55 WARN Rate limiter enabled after throttle name=server-test rate=53782026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:582053792026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:582063802026/10/14 16:44:55 WARN Rate limiter enabled after throttle name=server-test rate=53812026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:582593822026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:581813832026/10/14 16:44:55 WARN Rate limiter backed off name=server-test rate=5384=== CONT TestFilterOversizedClosures/no_limit_keeps_everything385--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.02s)386=== CONT TestPartSizeForNAR/zero_stays_at_minimum387=== CONT TestFilterOversizedClosures/all_closures_skipped3882026/10/14 16:44:55 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=503892026/10/14 16:44:55 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=03902026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:581813912026/10/14 16:44:55 WARN Rate limiter backed off name=server-test rate=5392--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.01s)393=== CONT TestSetClientTLS/preserves_debug_logging_transport394--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)395 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)396 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)397=== CONT TestSetClientTLS/rejects_connection_without_client_cert398--- PASS: TestScriptTokenBadJSON (0.03s)399=== CONT TestPartSizeForNAR/capped_at_5_GiB400=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum401=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts402=== CONT TestPartSizeForNAR/5_TiB_S3_max_object403=== CONT TestSetClientTLSErrors/missing_ca_file404=== CONT TestSetClientTLSErrors/missing_key_file405=== CONT TestPartSizeForNAR/small_stays_at_minimum406--- PASS: TestRateLimiterFeedback (0.00s)407 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)408 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)409 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)410 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)411=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA412=== CONT TestSetClientTLSErrors/invalid_ca_file413=== CONT TestPartSizeForNAR/1_TiB414--- PASS: TestPartSizeForNAR (0.00s)415 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)416 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)417 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)418 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)419 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)420 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)421 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)422=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped4232026/10/14 16:44:55 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=2000424--- PASS: TestFilterOversizedClosures (0.00s)425 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)426 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)427 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)428=== CONT TestSetClientTLSErrors/missing_cert_file429--- PASS: TestStreamPushRequestLine (0.02s)430--- PASS: TestSetClientTLSErrors (0.01s)431 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)432 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)433 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)434 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)4352026/10/14 16:44:55 WARN Garbage collection finished on another replica. Its statistics are not available here436--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)4372026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:581814382026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:581814392026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:581814402026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:581814412026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:581814422026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:581814432026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:58181444--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)4452026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:581814462026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:581814472026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:581814482026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:58181449--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)4502026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:581814512026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:581814522026/10/14 16:44:55 http: TLS handshake error from 127.0.0.1:58290: remote error: tls: bad certificate453--- PASS: TestSetClientTLS (0.01s)454 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)455 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)456 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)4572026/10/14 16:44:55 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:58181458--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)459--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.06s)460--- PASS: TestCaseHackSuffix (0.06s)4612026/10/14 16:44:55 INFO Uploading abc-hello (1.0GB)462--- PASS: TestDumpPathSingleFile (0.07s)463--- PASS: TestDumpPathWriterError (0.08s)4642026/10/14 16:44:55 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:58250/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:58250/part/24652026/10/14 16:44:55 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"466--- PASS: TestDumpPathMatchesNix (0.11s)467--- PASS: TestStreamPushBatchesUnderLoad (0.10s)468--- PASS: TestSupersededNARStillUploadsListing (0.00s)469 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.01s)470 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.02s)471 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.57s)472--- PASS: TestUploadMultipart_PartsInParallel (0.63s)4732026/10/14 16:44:56 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:58184/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:58184/api/uploads/complete4742026/10/14 16:44:56 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"475--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4762026/10/14 16:44:56 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:58184/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:58184/api/uploads/complete4772026/10/14 16:44:56 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4782026/10/14 16:44:56 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:58184/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:58184/api/uploads/complete4792026/10/14 16:44:56 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"480--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.01s)481PASS482Running server tests...483The files belonging to this database system will be owned by user "_tribuchetbld2".484This user must also own the server process.485486The database cluster will be initialized with locale "C".487The default database encoding has accordingly been set to "SQL_ASCII".488The default text search configuration will be set to "english".489490Data page checksums are enabled.491492creating directory /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/postgres2071143966/data ... ok493creating subdirectories ... ok494selecting dynamic shared memory implementation ... posix495selecting default "max_connections" ... 100496selecting default "shared_buffers" ... 128MB497selecting default time zone ... UTC498creating configuration files ... ok499running bootstrap script ... ok500performing post-bootstrap initialization ... ok501syncing data to disk ... ok502503initdb: warning: enabling "trust" authentication for local connections504initdb: 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.505506Success. You can now start the database server using:507508 pg_ctl -D /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/postgres2071143966/data -l logfile start509510/private/var/tb/2/scratch/87fbd2159ad6a6e3/build/postgres2071143966:5432 - no response5112026-10-14 16:44:57.072 UTC [20269] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5122026-10-14 16:44:57.072 UTC [20269] LOG: listening on Unix socket "/private/var/tb/2/scratch/87fbd2159ad6a6e3/build/postgres2071143966/.s.PGSQL.5432"5132026-10-14 16:44:57.074 UTC [20276] LOG: database system was shut down at 2026-10-14 16:44:57 UTC5142026-10-14 16:44:57.075 UTC [20269] LOG: database system is ready to accept connections515/private/var/tb/2/scratch/87fbd2159ad6a6e3/build/postgres2071143966:5432 - accepting connections516{"timestamp":"2026-10-14T16:44:59.242858Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"f3d9d4f8-0dc1-449d-b726-ff344d6a8e2f","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":1,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(10)"}517=== RUN TestService_AuthMiddleware518=== PAUSE TestService_AuthMiddleware519=== RUN TestService_AuthMiddleware_MTLSProxyHeader520=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader521=== RUN TestService_AuthMiddleware_MTLSBoundSubjects522=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects523=== RUN TestService_ReadAuthMiddleware524=== PAUSE TestService_ReadAuthMiddleware525=== RUN TestService_AuthMiddleware_OIDC526=== PAUSE TestService_AuthMiddleware_OIDC527=== RUN TestService_RequireScope_OIDC528=== PAUSE TestService_RequireScope_OIDC529=== RUN TestService_ReadScope_PublicByDefault530=== PAUSE TestService_ReadScope_PublicByDefault531=== RUN TestCacheConfigHandler532=== PAUSE TestCacheConfigHandler533=== RUN TestCacheStatsHandler534=== PAUSE TestCacheStatsHandler535=== RUN TestClientCADerivations536=== PAUSE TestClientCADerivations537=== RUN TestClientErrorHandling538=== PAUSE TestClientErrorHandling539=== RUN TestClientIntegration540=== PAUSE TestClientIntegration541=== RUN TestClientMultipleUploads542=== PAUSE TestClientMultipleUploads543=== RUN TestClientWithDependencies544=== PAUSE TestClientWithDependencies545=== RUN TestClientSharedPathCommittedMidPush546=== PAUSE TestClientSharedPathCommittedMidPush547=== RUN TestPinProtectsFromGC548=== PAUSE TestPinProtectsFromGC549=== RUN TestClientPushesUseOnePush550=== PAUSE TestClientPushesUseOnePush551=== RUN TestClientFallsBackToClosures552=== PAUSE TestClientFallsBackToClosures553=== RUN TestDeleteClosuresRacingPins554=== PAUSE TestDeleteClosuresRacingPins555=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock556=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock557=== RUN TestResolveDBConnectionString558=== PAUSE TestResolveDBConnectionString559=== RUN TestConnectWaitsForAPeerMigration560=== PAUSE TestConnectWaitsForAPeerMigration561=== RUN TestLeadElectsOneAndHandsOver562=== PAUSE TestLeadElectsOneAndHandsOver563=== RUN TestLeadIncumbentWinsAfterRestart5642026/10/14 16:44:59 INFO lead: acquired remote=192.0.2.1:12345652026/10/14 16:45:00 INFO lead: released remote=192.0.2.1:12345662026/10/14 16:45:00 INFO lead: acquired remote=192.0.2.1:12345672026/10/14 16:45:01 INFO lead: released remote=192.0.2.1:1234568--- PASS: TestLeadIncumbentWinsAfterRestart (1.97s)569=== RUN TestLeadIncumbentAnnouncesAtOnce570=== PAUSE TestLeadIncumbentAnnouncesAtOnce571=== RUN TestLeadEndsOnShutdown572=== PAUSE TestLeadEndsOnShutdown573=== RUN TestLeadEndsWhenItsConnectionHangs5742026/10/14 16:45:01 INFO lead: acquired remote=192.0.2.1:12345752026-10-14 16:45:02.661 UTC [20380] FATAL: terminating connection due to administrator command5762026/10/14 16:45:02 INFO lead: acquired remote=192.0.2.1:12345772026/10/14 16:45:03 WARN lead: lock connection lost error="timeout: context deadline exceeded"5782026/10/14 16:45:03 INFO lead: released remote=192.0.2.1:12345792026/10/14 16:45:04 INFO lead: released remote=192.0.2.1:1234580--- PASS: TestLeadEndsWhenItsConnectionHangs (2.74s)581=== RUN TestGCAdvisoryLockBlocksConcurrentRun582=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun583=== RUN TestGCBugBareHashReferences584=== PAUSE TestGCBugBareHashReferences585=== RUN TestGCMetrics586=== PAUSE TestGCMetrics587=== RUN TestPushDedupSurvivesConcurrentGC588=== PAUSE TestPushDedupSurvivesConcurrentGC589=== RUN TestDeduplicatedObjectsRecordedAsPending590=== PAUSE TestDeduplicatedObjectsRecordedAsPending591=== RUN TestGCSweepSkipsPendingObjects592=== PAUSE TestGCSweepSkipsPendingObjects593=== RUN TestTombstonedObjectOfferedWithoutWaiting594=== PAUSE TestTombstonedObjectOfferedWithoutWaiting595=== RUN TestGCSweepDeliversEachKeyOnce596=== PAUSE TestGCSweepDeliversEachKeyOnce597=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection598=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection599=== RUN TestForceGCDuringPushOffersSweptObject600=== PAUSE TestForceGCDuringPushOffersSweptObject601=== RUN TestFailedS3DeleteKeepsTombstone602=== PAUSE TestFailedS3DeleteKeepsTombstone603=== RUN TestSweepSkipsRowsLockedByPush604=== PAUSE TestSweepSkipsRowsLockedByPush605=== RUN TestRegisterCompletedObjectNeedsPendingRow606=== PAUSE TestRegisterCompletedObjectNeedsPendingRow607=== RUN TestGetExistingObjectsLocksRows608=== PAUSE TestGetExistingObjectsLocksRows609=== RUN TestSweepRechecksPendingAfterLocking610=== PAUSE TestSweepRechecksPendingAfterLocking611=== RUN TestPushWaitsForSweepHoldingRow612=== PAUSE TestPushWaitsForSweepHoldingRow613=== RUN TestCommitRacingPendingCleanupKeepsObjects614=== PAUSE TestCommitRacingPendingCleanupKeepsObjects615=== RUN TestGCEndsOnShutdown616=== PAUSE TestGCEndsOnShutdown617=== RUN TestGCTaskStore_StartNew618=== PAUSE TestGCTaskStore_StartNew619=== RUN TestGCTaskStore_DeduplicateSameParams620=== PAUSE TestGCTaskStore_DeduplicateSameParams621=== RUN TestGCTaskStore_ConflictDifferentParams622=== PAUSE TestGCTaskStore_ConflictDifferentParams623=== RUN TestGCTaskStore_GetEmpty624=== PAUSE TestGCTaskStore_GetEmpty625=== RUN TestGCTaskStore_GetReturnsLatest626=== PAUSE TestGCTaskStore_GetReturnsLatest627=== RUN TestGCTaskStore_CompletedAllowsNewTask628=== PAUSE TestGCTaskStore_CompletedAllowsNewTask629=== RUN TestGCTaskStore_PhaseUpdates630=== PAUSE TestGCTaskStore_PhaseUpdates631=== RUN TestGCTaskStore_Fail632=== PAUSE TestGCTaskStore_Fail633=== RUN TestGracefulShutdownDrainsInflight634=== PAUSE TestGracefulShutdownDrainsInflight635=== RUN TestService_healthCheckHandler636=== PAUSE TestService_healthCheckHandler637=== RUN TestService_readinessHandler638=== PAUSE TestService_readinessHandler639=== RUN TestGenerateLandingPage640=== PAUSE TestGenerateLandingPage641=== RUN TestCacheConfigHandlerMaxNarSize642=== PAUSE TestCacheConfigHandlerMaxNarSize643=== RUN TestCreatePendingClosureRejectsOversizedNAR644=== PAUSE TestCreatePendingClosureRejectsOversizedNAR645=== RUN TestNARDeduplicationMetadataUploadBug646=== PAUSE TestNARDeduplicationMetadataUploadBug647=== RUN TestMetricsInventory648=== PAUSE TestMetricsInventory649=== RUN TestMetricsCommit650=== PAUSE TestMetricsCommit651=== RUN TestService_NativeMTLS652=== PAUSE TestService_NativeMTLS653=== RUN TestServerTLSConfig654=== PAUSE TestServerTLSConfig655=== RUN TestMultipartCleanup656=== PAUSE TestMultipartCleanup657=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded658=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded659=== RUN TestPendingCleanupUsesOneCutoff660=== PAUSE TestPendingCleanupUsesOneCutoff661=== RUN TestObjectStatsTrigger662=== PAUSE TestObjectStatsTrigger663=== RUN TestObjectStatsLargeCommit664=== PAUSE TestObjectStatsLargeCommit665=== RUN TestOrphanedObjectsGC666=== PAUSE TestOrphanedObjectsGC667=== RUN TestOrphanedObjectsGCStressTest668=== PAUSE TestOrphanedObjectsGCStressTest669=== RUN TestCreatePin_ReservedPins670=== PAUSE TestCreatePin_ReservedPins671=== RUN TestPresentReportsOnlyClosureRoots672=== PAUSE TestPresentReportsOnlyClosureRoots673=== RUN TestPresentRefreshesOnlyStaleClosures674=== PAUSE TestPresentRefreshesOnlyStaleClosures675=== RUN TestPresentNotReportedWhileGCDeletesClosure676=== PAUSE TestPresentNotReportedWhileGCDeletesClosure677=== RUN TestParseSingleRange678=== PAUSE TestParseSingleRange679=== RUN TestProxyHeadersOnlyTrustedOnSocket6802026/10/14 16:45:04 INFO Starting HTTP server address=127.0.0.1:583566812026/10/14 16:45:04 INFO Starting HTTP server address=proxy.sock6822026/10/14 16:45:04 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6832026/10/14 16:45:04 INFO Shutdown signal received, draining in-flight requests timeout=10s684--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.17s)685=== RUN TestIsValidCachePath686=== PAUSE TestIsValidCachePath687=== RUN TestReadProxyNarinfo688=== PAUSE TestReadProxyNarinfo689=== RUN TestReadProxyNarinfoAlreadyDecompressed690=== PAUSE TestReadProxyNarinfoAlreadyDecompressed691=== RUN TestReadProxyContentNegotiation692=== PAUSE TestReadProxyContentNegotiation693=== RUN TestReadProxyNarStreaming694=== PAUSE TestReadProxyNarStreaming695=== RUN TestReadProxy404696=== PAUSE TestReadProxy404697=== RUN TestReadProxyInvalidPath698=== PAUSE TestReadProxyInvalidPath699=== RUN TestReadProxyHead700=== PAUSE TestReadProxyHead701=== RUN TestReadProxyOutlastsServerWriteTimeout702=== PAUSE TestReadProxyOutlastsServerWriteTimeout703=== RUN TestReadProxyConditionalGet704=== PAUSE TestReadProxyConditionalGet705=== RUN TestReadProxyRootRedirectsToIndexHTML706=== PAUSE TestReadProxyRootRedirectsToIndexHTML707=== RUN TestReadProxyDisabled708=== PAUSE TestReadProxyDisabled709=== RUN TestReadRedirectNar710=== PAUSE TestReadRedirectNar711=== RUN TestReadRedirectKeepsNarinfoProxied712=== PAUSE TestReadRedirectKeepsNarinfoProxied713=== RUN TestReadProxyRangeRequest714=== PAUSE TestReadProxyRangeRequest715=== RUN TestReadRedirectUsesPublicS3URL716=== PAUSE TestReadRedirectUsesPublicS3URL717=== RUN TestPush_OverlappingRootsStoreOneRowPerKey718=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey719=== RUN TestPush_CompleteCommitsEveryRoot720=== PAUSE TestPush_CompleteCommitsEveryRoot721=== RUN TestPush_RepeatedRootCommitsOnce722=== PAUSE TestPush_RepeatedRootCommitsOnce723=== RUN TestPush_CompleteWaitsForCleanupOfThePush724=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush725=== RUN TestPush_RootsAreLockedInByteOrder726=== PAUSE TestPush_RootsAreLockedInByteOrder727=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit728=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit729=== RUN TestPush_RejectsBadRequests730=== PAUSE TestPush_RejectsBadRequests731=== RUN TestPush_SignsNarinfosOfItsPendingObjects732=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects733=== RUN TestRedundantMultipartUpload734=== PAUSE TestRedundantMultipartUpload735=== RUN TestCompleteMultipartUpload_ErrorButObjectExists736=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists737=== RUN TestCompletedNarNotReofferedAcrossClosures738=== PAUSE TestCompletedNarNotReofferedAcrossClosures739=== RUN TestPresignedUploadRegisteredBeforeCommit740=== PAUSE TestPresignedUploadRegisteredBeforeCommit741=== RUN TestService_Rustfstest742=== PAUSE TestService_Rustfstest743=== RUN TestParseSize744=== PAUSE TestParseSize745=== RUN TestSkippedUploadsHandler746=== PAUSE TestSkippedUploadsHandler747=== RUN TestSystemdListenerNotActivated748--- PASS: TestSystemdListenerNotActivated (0.00s)749=== RUN TestWatchdogBeatsWhenHealthy750--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)751=== RUN TestWatchdogSkipsWhenUnhealthy7522026/10/14 16:45:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7532026/10/14 16:45:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7542026/10/14 16:45:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7552026/10/14 16:45:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7562026/10/14 16:45:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7572026/10/14 16:45:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7582026/10/14 16:45:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7592026/10/14 16:45:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/14 16:45:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7612026/10/14 16:45:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"762--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)763=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle764=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle765=== RUN TestProxyWriteTimeout766=== PAUSE TestProxyWriteTimeout767=== RUN TestPendingClosureWriteTimeout768=== PAUSE TestPendingClosureWriteTimeout769=== RUN TestIsValidUploadKey770=== PAUSE TestIsValidUploadKey771=== RUN TestUploadHandlersRejectInvalidKeys772=== PAUSE TestUploadHandlersRejectInvalidKeys773=== RUN TestUploadHandlersRejectOversizedBody774=== PAUSE TestUploadHandlersRejectOversizedBody775=== RUN TestService_cleanupPendingClosuresHandler776=== PAUSE TestService_cleanupPendingClosuresHandler777=== RUN TestService_createPendingClosureHandler778=== PAUSE TestService_createPendingClosureHandler779=== RUN TestService_verifyS3Integrity780=== PAUSE TestService_verifyS3Integrity781=== RUN TestCompleteMultipartUnregistered782=== PAUSE TestCompleteMultipartUnregistered783=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT784=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT785=== CONT TestService_AuthMiddleware786=== CONT TestMetricsInventory787=== CONT TestService_Rustfstest788=== CONT TestReadRedirectKeepsNarinfoProxied789=== CONT TestParseSingleRange790=== RUN TestParseSingleRange/none791=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT792=== PAUSE TestParseSingleRange/none793=== CONT TestCompleteMultipartUnregistered794=== CONT TestService_verifyS3Integrity795=== CONT TestService_createPendingClosureHandler796=== CONT TestService_cleanupPendingClosuresHandler797=== CONT TestUploadHandlersRejectOversizedBody798=== CONT TestUploadHandlersRejectInvalidKeys799=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info800=== CONT TestIsValidUploadKey801=== CONT TestPendingClosureWriteTimeout802=== CONT TestProxyWriteTimeout803=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle804=== RUN TestPendingClosureWriteTimeout/empty805=== CONT TestSkippedUploadsHandler806=== CONT TestReadRedirectNar807=== CONT TestReadProxyDisabled808=== CONT TestReadProxyRootRedirectsToIndexHTML809=== CONT TestReadProxyConditionalGet810=== CONT TestReadProxyOutlastsServerWriteTimeout811=== CONT TestReadProxyHead812=== RUN TestParseSingleRange/unknown_unit813=== PAUSE TestParseSingleRange/unknown_unit814=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info815=== RUN TestIsValidUploadKey/narinfo816=== RUN TestParseSingleRange/multi-range_ignored817=== PAUSE TestParseSingleRange/multi-range_ignored818=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal819=== RUN TestProxyWriteTimeout/narinfo820=== PAUSE TestIsValidUploadKey/narinfo8212026/10/14 16:45:04 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000822=== RUN TestIsValidUploadKey/nar_zst823=== RUN TestParseSingleRange/malformed_no_dash824=== CONT TestParseSize825=== PAUSE TestProxyWriteTimeout/narinfo826=== RUN TestProxyWriteTimeout/1_GiB_nar827=== PAUSE TestPendingClosureWriteTimeout/empty828=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal829=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key830=== PAUSE TestIsValidUploadKey/nar_zst831=== RUN TestIsValidUploadKey/nar_xz832=== PAUSE TestIsValidUploadKey/nar_xz833=== RUN TestIsValidUploadKey/nar_plain834=== PAUSE TestIsValidUploadKey/nar_plain835=== RUN TestIsValidUploadKey/listing836=== PAUSE TestIsValidUploadKey/listing837=== RUN TestIsValidUploadKey/build_log838=== PAUSE TestIsValidUploadKey/build_log839=== RUN TestIsValidUploadKey/build_log_home-manager_file840=== PAUSE TestIsValidUploadKey/build_log_home-manager_file841=== RUN TestIsValidUploadKey/build_log_plus_in_name842=== PAUSE TestIsValidUploadKey/build_log_plus_in_name843=== RUN TestIsValidUploadKey/build_log_question_mark844=== PAUSE TestIsValidUploadKey/build_log_question_mark845=== RUN TestIsValidUploadKey/build_log_equals846=== PAUSE TestIsValidUploadKey/build_log_equals847=== RUN TestIsValidUploadKey/realisation848=== PAUSE TestIsValidUploadKey/realisation849=== RUN TestIsValidUploadKey/realisation_plus_in_output850=== PAUSE TestIsValidUploadKey/realisation_plus_in_output851=== RUN TestIsValidUploadKey/nix-cache-info852=== PAUSE TestIsValidUploadKey/nix-cache-info853=== RUN TestIsValidUploadKey/index.html854=== PAUSE TestIsValidUploadKey/index.html855=== RUN TestIsValidUploadKey/narinfo_key,_nar_type856=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type857=== RUN TestIsValidUploadKey/nar_key,_narinfo_type858=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type859=== RUN TestIsValidUploadKey/listing_key,_narinfo_type860=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type861=== PAUSE TestParseSingleRange/malformed_no_dash862--- PASS: TestParseSize (0.00s)863=== PAUSE TestProxyWriteTimeout/1_GiB_nar864=== RUN TestParseSingleRange/malformed_both_empty865=== PAUSE TestParseSingleRange/malformed_both_empty866=== RUN TestIsValidUploadKey/traversal867=== PAUSE TestIsValidUploadKey/traversal868=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key869=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key870=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key871=== RUN TestProxyWriteTimeout/10_GiB_nar872=== PAUSE TestProxyWriteTimeout/10_GiB_nar873=== RUN TestProxyWriteTimeout/unknown_size874=== PAUSE TestProxyWriteTimeout/unknown_size875=== CONT TestReadProxy404876--- PASS: TestSkippedUploadsHandler (0.04s)877=== CONT TestReadProxyContentNegotiation878=== RUN TestIsValidUploadKey/traversal_nar879=== PAUSE TestIsValidUploadKey/traversal_nar880=== RUN TestIsValidUploadKey/absolute881=== PAUSE TestIsValidUploadKey/absolute882=== RUN TestIsValidUploadKey/empty_key883=== PAUSE TestIsValidUploadKey/empty_key884=== RUN TestIsValidUploadKey/unknown_type885=== PAUSE TestIsValidUploadKey/unknown_type886=== RUN TestPendingClosureWriteTimeout/400_objects887=== PAUSE TestPendingClosureWriteTimeout/400_objects888=== RUN TestPendingClosureWriteTimeout/670k_objects889=== PAUSE TestPendingClosureWriteTimeout/670k_objects890=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline891=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline892=== CONT TestReadProxyNarinfoAlreadyDecompressed893=== RUN TestParseSingleRange/malformed_end_before_start894=== PAUSE TestParseSingleRange/malformed_end_before_start895=== RUN TestParseSingleRange/closed896=== PAUSE TestParseSingleRange/closed897=== RUN TestParseSingleRange/open-ended898=== PAUSE TestParseSingleRange/open-ended899=== RUN TestParseSingleRange/end_clamped_to_size900=== PAUSE TestParseSingleRange/end_clamped_to_size901=== RUN TestParseSingleRange/suffix902=== PAUSE TestParseSingleRange/suffix903=== RUN TestParseSingleRange/suffix_exceeds_size904=== PAUSE TestParseSingleRange/suffix_exceeds_size905=== RUN TestParseSingleRange/single_byte906=== PAUSE TestParseSingleRange/single_byte907=== RUN TestParseSingleRange/start_past_EOF908=== PAUSE TestParseSingleRange/start_past_EOF909=== RUN TestParseSingleRange/start_far_past_EOF910=== PAUSE TestParseSingleRange/start_far_past_EOF911=== CONT TestReadProxyNarinfo912=== CONT TestReadProxyInvalidPath913=== CONT TestIsValidCachePath914=== RUN TestIsValidCachePath/narinfo915=== PAUSE TestIsValidCachePath/narinfo916=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars917=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars918=== RUN TestIsValidCachePath/nar_zst919=== PAUSE TestIsValidCachePath/nar_zst920=== RUN TestIsValidCachePath/nar_xz921=== PAUSE TestIsValidCachePath/nar_xz922=== RUN TestIsValidCachePath/nar_bz2923=== PAUSE TestIsValidCachePath/nar_bz2924=== RUN TestIsValidCachePath/nar_uncompressed925=== PAUSE TestIsValidCachePath/nar_uncompressed926=== RUN TestIsValidCachePath/ls927=== PAUSE TestIsValidCachePath/ls928=== RUN TestIsValidCachePath/log929=== PAUSE TestIsValidCachePath/log930=== RUN TestIsValidCachePath/realisation931=== PAUSE TestIsValidCachePath/realisation932=== RUN TestIsValidCachePath/nix-cache-info933=== PAUSE TestIsValidCachePath/nix-cache-info934=== RUN TestIsValidCachePath/index.html935=== PAUSE TestIsValidCachePath/index.html936=== RUN TestIsValidCachePath/traversal_parent937=== PAUSE TestIsValidCachePath/traversal_parent938=== RUN TestIsValidCachePath/traversal_in_middle939=== PAUSE TestIsValidCachePath/traversal_in_middle940=== RUN TestIsValidCachePath/invalid_char_e941=== PAUSE TestIsValidCachePath/invalid_char_e942=== RUN TestIsValidCachePath/invalid_char_u943=== PAUSE TestIsValidCachePath/invalid_char_u944=== RUN TestIsValidCachePath/random_path945=== PAUSE TestIsValidCachePath/random_path946=== RUN TestIsValidCachePath/empty947=== PAUSE TestIsValidCachePath/empty948=== RUN TestIsValidCachePath/leading_slash949=== PAUSE TestIsValidCachePath/leading_slash950=== RUN TestIsValidCachePath/wrong_extension951=== PAUSE TestIsValidCachePath/wrong_extension952=== RUN TestIsValidCachePath/short_hash953=== PAUSE TestIsValidCachePath/short_hash954=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit955=== CONT TestReadProxyNarStreaming956=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart957=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart958=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts959=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts960=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure961=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure962=== CONT TestCompleteMultipartUpload_ErrorButObjectExists9632026/10/14 16:45:05 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"964--- PASS: TestService_AuthMiddleware (0.99s)965=== CONT TestPresignedUploadRegisteredBeforeCommit966--- PASS: TestMetricsInventory (1.44s)967=== CONT TestRedundantMultipartUpload9682026/10/14 16:45:06 INFO Received uploads request method=POST path=/api/pending_closures969--- PASS: TestService_Rustfstest (2.13s)970=== CONT TestCompletedNarNotReofferedAcrossClosures971--- PASS: TestReadProxyDisabled (2.44s)972=== CONT TestPush_SignsNarinfosOfItsPendingObjects973--- PASS: TestReadRedirectNar (2.72s)974=== CONT TestPush_RejectsBadRequests9752026/10/14 16:45:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9762026/10/14 16:45:07 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst977--- PASS: TestCompleteMultipartUnregistered (2.93s)978=== CONT TestObjectStatsLargeCommit9792026/10/14 16:45:07 INFO Received uploads request method=POST path=/api/pending_closures9802026/10/14 16:45:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9812026/10/14 16:45:07 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MzFmYjJkMGYtZmFiMC00OTFhLWIwNzUtNTA0MGM2M2VkYTAyLmQ5MzhjMDdmLWQwMTctNDdmNy05NmFiLWJhYjM5OTg5OWYwMngxNzkxOTk2MzA2MjQwNzQ1MDAw parts=109822026/10/14 16:45:07 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9832026/10/14 16:45:07 INFO Completed upload id=1 objects=2 duration=10.405584ms9842026/10/14 16:45:07 INFO Received uploads request method=POST path=/api/pending_closures9852026/10/14 16:45:07 INFO Received uploads request method=POST path=/api/pending_closures9862026/10/14 16:45:07 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9872026/10/14 16:45:07 WARN Found objects in DB but missing from S3, will re-upload count=1988--- PASS: TestService_verifyS3Integrity (3.31s)989=== CONT TestPresentNotReportedWhileGCDeletesClosure990=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale991=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale992=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh993=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh994=== CONT TestPresentRefreshesOnlyStaleClosures995--- PASS: TestReadRedirectKeepsNarinfoProxied (3.49s)996=== CONT TestDeduplicatedObjectsRecordedAsPending9972026/10/14 16:45:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9982026/10/14 16:45:08 INFO Received uploads request method=POST path=/api/pending_closures999--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (3.76s)1000=== CONT TestPresentReportsOnlyClosureRoots10012026/10/14 16:45:08 INFO Received uploads request method=POST path=/api/pending_closures10022026/10/14 16:45:08 INFO Received uploads request method=POST path=/api/pending_closures10032026/10/14 16:45:08 INFO Received uploads request method=POST path=/api/pending_closures10042026/10/14 16:45:08 INFO Received cleanup request method=DELETE path=/api/pending_closures10052026/10/14 16:45:08 INFO Aborted multipart uploads count=0 kept=010062026/10/14 16:45:08 INFO Received uploads request method=POST path=/api/pending_closures10072026/10/14 16:45:08 INFO Received cleanup request method=DELETE path=/api/pending_closures10082026/10/14 16:45:08 INFO Aborted multipart uploads count=1 kept=010092026/10/14 16:45:08 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10102026-10-14 16:45:08.722 UTC [20451] ERROR: Closure does not exist: id=110112026-10-14 16:45:08.722 UTC [20451] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10122026-10-14 16:45:08.722 UTC [20451] STATEMENT: -- name: CommitPendingClosure :one1013 SELECT commit_pending_closure($1::bigint)::bigint1014 1015--- PASS: TestService_cleanupPendingClosuresHandler (4.25s)1016=== CONT TestGCTaskStore_StartNew1017--- PASS: TestGCTaskStore_StartNew (0.00s)1018=== CONT TestGCTaskStore_DeduplicateSameParams1019--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1020=== CONT TestCreatePin_ReservedPins10212026/10/14 16:45:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58405/oidc1022--- PASS: TestReadProxyConditionalGet (4.41s)1023=== CONT TestOrphanedObjectsGCStressTest1024--- PASS: TestReadProxyHead (4.67s)1025=== CONT TestOrphanedObjectsGC1026--- PASS: TestReadProxyInvalidPath (5.16s)1027=== CONT TestGCEndsOnShutdown1028=== RUN TestGCEndsOnShutdown/before_the_run1029=== PAUSE TestGCEndsOnShutdown/before_the_run1030=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1031=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1032=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1033=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1034=== CONT TestNARDeduplicationMetadataUploadBug10352026/10/14 16:45:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10362026/10/14 16:45:09 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MzFmYjJkMGYtZmFiMC00OTFhLWIwNzUtNTA0MGM2M2VkYTAyLjc4MWY1ZDEzLTkxN2QtNDZmYi04MDY2LWFmYjNmYTQzOTk4ZngxNzkxOTk2MzA4NDIwMzIzMDAw parts=1010372026/10/14 16:45:09 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10382026/10/14 16:45:09 INFO Completed upload id=1 objects=2 duration=13.467167ms10392026/10/14 16:45:09 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010402026/10/14 16:45:09 INFO Received uploads request method=POST path=/api/pending_closures10412026/10/14 16:45:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures10422026/10/14 16:45:09 INFO Aborted multipart uploads count=0 kept=010432026/10/14 16:45:09 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=010442026/10/14 16:45:09 INFO Vacuumed table table=pending_closures10452026/10/14 16:45:09 INFO Vacuumed table table=pending_objects1046--- PASS: TestReadProxyRootRedirectsToIndexHTML (5.49s)1047=== CONT TestPinProtectsFromGC10482026/10/14 16:45:09 INFO Vacuumed table table=multipart_uploads10492026/10/14 16:45:10 INFO Vacuumed table table=closures10502026/10/14 16:45:10 INFO Vacuumed table table=objects10512026/10/14 16:45:10 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001052--- PASS: TestService_createPendingClosureHandler (5.60s)1053=== CONT TestCreatePendingClosureRejectsOversizedNAR10542026/10/14 16:45:10 INFO Received uploads request method=POST path=/api/pending_closures1055--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1056=== CONT TestCommitRacingPendingCleanupKeepsObjects1057--- PASS: TestReadProxyContentNegotiation (5.75s)1058=== CONT TestCacheConfigHandlerMaxNarSize1059--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1060=== CONT TestPushWaitsForSweepHoldingRow1061--- PASS: TestReadProxyNarStreaming (5.88s)1062=== CONT TestSweepRechecksPendingAfterLocking1063--- PASS: TestReadProxy404 (6.21s)1064=== CONT TestGetExistingObjectsLocksRows1065--- PASS: TestReadProxyNarinfoAlreadyDecompressed (6.40s)1066=== CONT TestPushDedupSurvivesConcurrentGC10672026/10/14 16:45:11 INFO Received push request method=POST path=/api/pushes10682026/10/14 16:45:11 INFO Received complete push request method=POST path=/api/pushes/1/complete10692026/10/14 16:45:11 INFO Completed push id=1 objects=4 duration=56.267958ms10702026/10/14 16:45:11 INFO Received push request method=POST path=/api/pushes10712026/10/14 16:45:11 INFO Aborted multipart uploads count=0 kept=010722026/10/14 16:45:11 WARN Force mode enabled - objects will be deleted immediately without grace period10732026/10/14 16:45:11 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=010742026/10/14 16:45:11 INFO Vacuumed table table=pending_closures10752026/10/14 16:45:11 INFO Vacuumed table table=pending_objects10762026/10/14 16:45:11 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1077--- PASS: TestReadProxyNarinfo (7.05s)1078=== CONT TestGCMetrics10792026/10/14 16:45:11 INFO Vacuumed table table=multipart_uploads10802026/10/14 16:45:11 INFO Vacuumed table table=closures10812026/10/14 16:45:11 INFO Vacuumed table table=objects10822026/10/14 16:45:11 INFO Received complete push request method=POST path=/api/pushes/2/complete10832026/10/14 16:45:11 INFO Completed push id=2 objects=4 duration=2.679125ms1084--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (7.14s)1085=== CONT TestGenerateLandingPage1086--- PASS: TestGenerateLandingPage (0.00s)1087=== CONT TestGCBugBareHashReferences10882026/10/14 16:45:11 INFO Received uploads request method=POST path=/api/pending_closures10892026/10/14 16:45:12 INFO Received uploads request method=POST path=/api/pending_closures10902026/10/14 16:45:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10912026/10/14 16:45:12 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MzFmYjJkMGYtZmFiMC00OTFhLWIwNzUtNTA0MGM2M2VkYTAyLjBjN2IyZmFmLTE4ZWItNDdiMC1hMzZhLWQ5MDFiYzJiOWY1NHgxNzkxOTk2MzExODE4Njk5MDAw10922026/10/14 16:45:12 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MzFmYjJkMGYtZmFiMC00OTFhLWIwNzUtNTA0MGM2M2VkYTAyLjBjN2IyZmFmLTE4ZWItNDdiMC1hMzZhLWQ5MDFiYzJiOWY1NHgxNzkxOTk2MzExODE4Njk5MDAw parts=11093--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (7.64s)1094=== CONT TestRegisterCompletedObjectNeedsPendingRow10952026/10/14 16:45:12 INFO Received uploads request method=POST path=/api/pending_closures10962026/10/14 16:45:12 INFO Received uploads request method=POST path=/api/pending_closures10972026/10/14 16:45:12 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10982026/10/14 16:45:12 INFO Received uploads request method=POST path=/api/pending_closures1099--- PASS: TestPresignedUploadRegisteredBeforeCommit (7.04s)1100=== CONT TestGCAdvisoryLockBlocksConcurrentRun11012026/10/14 16:45:12 WARN Rate limiter enabled after throttle name=s3-test rate=511022026/10/14 16:45:12 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1103=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1104 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101105 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001106--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (8.07s)1107=== CONT TestSweepSkipsRowsLockedByPush11082026/10/14 16:45:12 INFO Received uploads request method=POST path=/api/pending_closures11092026/10/14 16:45:13 INFO Received push request method=POST path=/api/pushes11102026/10/14 16:45:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11112026/10/14 16:45:13 INFO Signed narinfos id=1 count=111122026/10/14 16:45:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11132026/10/14 16:45:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11142026/10/14 16:45:13 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"11152026/10/14 16:45:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11162026/10/14 16:45:13 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"11172026/10/14 16:45:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11182026/10/14 16:45:13 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=111192026/10/14 16:45:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11202026/10/14 16:45:13 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1121--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (6.38s)1122=== CONT TestLeadEndsOnShutdown1123=== RUN TestPush_RejectsBadRequests/no_roots1124=== PAUSE TestPush_RejectsBadRequests/no_roots1125=== RUN TestPush_RejectsBadRequests/no_objects1126=== PAUSE TestPush_RejectsBadRequests/no_objects1127=== RUN TestPush_RejectsBadRequests/bad_root1128=== PAUSE TestPush_RejectsBadRequests/bad_root1129=== RUN TestPush_RejectsBadRequests/root_not_in_objects1130=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1131=== CONT TestFailedS3DeleteKeepsTombstone1132--- PASS: TestReadProxyOutlastsServerWriteTimeout (9.17s)1133=== CONT TestService_readinessHandler11342026/10/14 16:45:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1135--- PASS: TestPresentRefreshesOnlyStaleClosures (6.57s)1136=== CONT TestLeadIncumbentAnnouncesAtOnce11372026/10/14 16:45:14 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MzFmYjJkMGYtZmFiMC00OTFhLWIwNzUtNTA0MGM2M2VkYTAyLjFhYjUwNzg3LTViM2QtNDU4ZC05ZjZlLWE3NGRhZGYyZDIyOHgxNzkxOTk2MzEyMTkzMzY5MDAw parts=1211382026/10/14 16:45:14 INFO Received uploads request method=POST path=/api/pending_closures11392026/10/14 16:45:14 INFO Received uploads request method=POST path=/api/pending_closures11402026/10/14 16:45:14 INFO Received uploads request method=POST path=/api/pending_closures1141--- PASS: TestDeduplicatedObjectsRecordedAsPending (6.74s)1142=== CONT TestForceGCDuringPushOffersSweptObject1143=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1144=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1145=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1146=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1147=== CONT TestService_healthCheckHandler11482026/10/14 16:45:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1149--- PASS: TestPresentReportsOnlyClosureRoots (6.97s)1150=== CONT TestLeadElectsOneAndHandsOver11512026/10/14 16:45:15 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MzFmYjJkMGYtZmFiMC00OTFhLWIwNzUtNTA0MGM2M2VkYTAyLmQzZjZjM2M4LWFjOTYtNDNlOS1iY2U0LWFkMmE4YTM4ZWI4OHgxNzkxOTk2MzEyODM3NjgwMDAw parts=1211522026/10/14 16:45:15 INFO Received uploads request method=POST path=/api/pending_closures1153--- PASS: TestCompletedNarNotReofferedAcrossClosures (8.64s)1154=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection11552026/10/14 16:45:15 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11562026/10/14 16:45:15 WARN Refused reserved pin name=worker-x86_64-linux11572026/10/14 16:45:15 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11582026/10/14 16:45:15 INFO Received create pin request method=POST path=/api/pins/my-app11592026/10/14 16:45:15 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1160--- PASS: TestCreatePin_ReservedPins (6.79s)1161=== CONT TestGracefulShutdownDrainsInflight11622026/10/14 16:45:15 INFO Starting HTTP server address=127.0.0.1:5849111632026/10/14 16:45:15 INFO Shutdown signal received, draining in-flight requests timeout=10s1164--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1165=== CONT TestConnectWaitsForAPeerMigration11662026/10/14 16:45:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11672026/10/14 16:45:16 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MzFmYjJkMGYtZmFiMC00OTFhLWIwNzUtNTA0MGM2M2VkYTAyLmZiZDRhMDZiLWU3NDgtNGQxMi04Mjk4LWNmNDNkMGZiODRhYXgxNzkxOTk2MzE0NDU5Mzc3MDAw error="Get \"http://127.0.0.1:1/bucket28/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"11682026/10/14 16:45:16 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MzFmYjJkMGYtZmFiMC00OTFhLWIwNzUtNTA0MGM2M2VkYTAyLjhmM2JiNGU3LWIwZjItNDVmMS1iZTk3LWM5ODIyNTJhMDVhNngxNzkxOTk2MzE0MzkzMjEwMDAw parts=1211692026/10/14 16:45:16 INFO Received cleanup request method=DELETE path=/api/pending_closures11702026/10/14 16:45:16 INFO Aborted multipart uploads count=1 kept=01171--- PASS: TestRedundantMultipartUpload (10.83s)1172=== CONT TestGCTaskStore_Fail1173--- PASS: TestGCTaskStore_Fail (0.00s)1174=== CONT TestGCSweepDeliversEachKeyOnce1175=== NAME TestNARDeduplicationMetadataUploadBug1176 metadata_upload_test.go:48: First store path: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestNARDeduplicationMetadataUploadBug2156620840/001/store/5ndmgwjqicj06xva36n7s63xifw68vss-file1.txt11772026/10/14 16:45:17 INFO Received push request method=POST path=/api/pushes11782026/10/14 16:45:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11792026/10/14 16:45:17 INFO Uploading 5ndmgwjqicj06xva36n7s63xifw68vss-file1.txt (160B)11802026/10/14 16:45:17 WARN Failed to register uploaded object key=5ndmgwjqicj06xva36n7s63xifw68vss.ls error="server returned 404: 404 page not found\n"11812026/10/14 16:45:17 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11822026/10/14 16:45:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11832026/10/14 16:45:17 INFO Signed narinfos id=1 count=111842026/10/14 16:45:17 INFO Uploading 1 narinfos11852026/10/14 16:45:17 INFO Received complete push request method=POST path=/api/pushes/1/complete1186=== NAME TestOrphanedObjectsGC1187 orphaned_objects_gc_test.go:287: GC Test Summary:1188 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1189 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1190 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1191 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1192 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1193--- PASS: TestOrphanedObjectsGC (7.98s)1194=== CONT TestResolveDBConnectionString11952026/10/14 16:45:17 WARN Failed to register uploaded object key=5ndmgwjqicj06xva36n7s63xifw68vss.narinfo error="server returned 404: 404 page not found\n"1196=== RUN TestResolveDBConnectionString/flag_wins1197=== PAUSE TestResolveDBConnectionString/flag_wins1198=== RUN TestResolveDBConnectionString/file_when_flag_empty1199=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1200=== RUN TestResolveDBConnectionString/missing_file_is_an_error1201=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1202=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1203=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1204=== RUN TestResolveDBConnectionString/nothing_configured1205=== PAUSE TestResolveDBConnectionString/nothing_configured1206=== CONT TestGCTaskStore_PhaseUpdates1207--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1208=== CONT TestTombstonedObjectOfferedWithoutWaiting12092026/10/14 16:45:17 INFO Completed push id=1 objects=3 duration=41.115666ms12102026/10/14 16:45:17 INFO Upload complete. (219ms)1211=== NAME TestNARDeduplicationMetadataUploadBug1212 metadata_upload_test.go:54: Retrieved narinfo from S3:1213 StorePath: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestNARDeduplicationMetadataUploadBug2156620840/001/store/5ndmgwjqicj06xva36n7s63xifw68vss-file1.txt1214 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1215 Compression: zstd1216 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1217 NarSize: 1601218 References: 1219 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1220 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1221 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1222 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1223 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestNARDeduplicationMetadataUploadBug2156620840/001/store/avqbl8hp3wsarsigwi2ysbswa6p6bib4-file2.txt1224=== NAME TestPinProtectsFromGC1225 client_integration_test.go:731: Pinned store path: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestPinProtectsFromGC3670699370/001/store/4wzyw8596xj1clzjrc5iq1p55hjpkc42-pinned-file.txt1226 client_integration_test.go:732: Unpinned store path: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestPinProtectsFromGC3670699370/001/store/9raqrq0avr439799hkarqihf3ym72xib-unpinned-file.txt12272026/10/14 16:45:17 INFO Received push request method=POST path=/api/pushes12282026/10/14 16:45:17 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12292026/10/14 16:45:17 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12302026/10/14 16:45:17 WARN Failed to register uploaded object key=avqbl8hp3wsarsigwi2ysbswa6p6bib4.ls error="server returned 404: 404 page not found\n"12312026/10/14 16:45:17 INFO Signed narinfos id=2 count=112322026/10/14 16:45:17 INFO Uploading 1 narinfos12332026/10/14 16:45:17 INFO Aborted multipart uploads count=0 kept=012342026/10/14 16:45:17 INFO Received complete push request method=POST path=/api/pushes/2/complete12352026/10/14 16:45:17 WARN Failed to register uploaded object key=avqbl8hp3wsarsigwi2ysbswa6p6bib4.narinfo error="server returned 404: 404 page not found\n"12362026/10/14 16:45:17 INFO Completed push id=2 objects=3 duration=1.18ms12372026/10/14 16:45:17 INFO Upload complete. (106ms)1238=== NAME TestNARDeduplicationMetadataUploadBug1239 metadata_upload_test.go:76: Retrieved narinfo from S3:1240 StorePath: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestNARDeduplicationMetadataUploadBug2156620840/001/store/avqbl8hp3wsarsigwi2ysbswa6p6bib4-file2.txt1241 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1242 Compression: zstd1243 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1244 NarSize: 1601245 References: 1246 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf12472026/10/14 16:45:17 WARN Force mode enabled - objects will be deleted immediately without grace period1248 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1249 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1250 {"version":1,"root":{"type":"regular","size":44}}12512026/10/14 16:45:17 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012522026/10/14 16:45:17 INFO Received push request method=POST path=/api/pushes12532026/10/14 16:45:17 INFO Vacuumed table table=pending_closures12542026/10/14 16:45:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12552026/10/14 16:45:17 INFO Uploading 4wzyw8596xj1clzjrc5iq1p55hjpkc42-pinned-file.txt (128B)1256--- PASS: TestNARDeduplicationMetadataUploadBug (7.80s)1257=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock12582026/10/14 16:45:17 WARN Failed to register uploaded object key=4wzyw8596xj1clzjrc5iq1p55hjpkc42.ls error="server returned 404: 404 page not found\n"12592026/10/14 16:45:17 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"12602026/10/14 16:45:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12612026/10/14 16:45:17 INFO Vacuumed table table=pending_objects12622026/10/14 16:45:17 INFO Signed narinfos id=1 count=112632026/10/14 16:45:17 INFO Vacuumed table table=multipart_uploads12642026/10/14 16:45:17 INFO Uploading 1 narinfos12652026/10/14 16:45:17 INFO Vacuumed table table=closures12662026/10/14 16:45:17 INFO Received complete push request method=POST path=/api/pushes/1/complete12672026/10/14 16:45:17 WARN Failed to register uploaded object key=4wzyw8596xj1clzjrc5iq1p55hjpkc42.narinfo error="server returned 404: 404 page not found\n"12682026/10/14 16:45:17 INFO Vacuumed table table=objects1269--- PASS: TestCommitRacingPendingCleanupKeepsObjects (7.47s)1270=== CONT TestGCTaskStore_CompletedAllowsNewTask1271--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1272=== CONT TestGCSweepSkipsPendingObjects12732026/10/14 16:45:17 INFO Completed push id=1 objects=3 duration=46.680833ms12742026/10/14 16:45:17 INFO Upload complete. (216ms)12752026/10/14 16:45:17 INFO Received uploads request method=POST path=/api/pending_closures12762026/10/14 16:45:17 INFO Received push request method=POST path=/api/pushes12772026/10/14 16:45:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12782026/10/14 16:45:17 INFO Uploading 9raqrq0avr439799hkarqihf3ym72xib-unpinned-file.txt (128B)12792026/10/14 16:45:17 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"12802026/10/14 16:45:17 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12812026/10/14 16:45:17 WARN Failed to register uploaded object key=9raqrq0avr439799hkarqihf3ym72xib.ls error="server returned 404: 404 page not found\n"12822026/10/14 16:45:17 INFO Signed narinfos id=2 count=112832026/10/14 16:45:17 INFO Uploading 1 narinfos12842026/10/14 16:45:17 INFO Received complete push request method=POST path=/api/pushes/2/complete12852026/10/14 16:45:17 WARN Failed to register uploaded object key=9raqrq0avr439799hkarqihf3ym72xib.narinfo error="server returned 404: 404 page not found\n"12862026/10/14 16:45:17 INFO Completed push id=2 objects=3 duration=871.333µs12872026/10/14 16:45:17 INFO Upload complete. (118ms)12882026/10/14 16:45:17 INFO Starting cleanup of old closures method=DELETE path=/api/closures12892026/10/14 16:45:17 INFO Garbage collection started12902026/10/14 16:45:17 INFO Aborted multipart uploads count=0 kept=012912026/10/14 16:45:17 WARN Force mode enabled - objects will be deleted immediately without grace period12922026/10/14 16:45:17 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=012932026/10/14 16:45:17 INFO Aborted multipart uploads count=0 kept=012942026/10/14 16:45:17 INFO Vacuumed table table=pending_closures12952026/10/14 16:45:17 WARN Force mode enabled - objects will be deleted immediately without grace period12962026/10/14 16:45:17 INFO Vacuumed table table=pending_objects12972026/10/14 16:45:17 INFO Vacuumed table table=multipart_uploads12982026/10/14 16:45:17 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012992026/10/14 16:45:17 INFO Vacuumed table table=closures13002026/10/14 16:45:18 INFO Vacuumed table table=objects13012026/10/14 16:45:18 INFO Vacuumed table table=pending_closures13022026/10/14 16:45:18 INFO Vacuumed table table=pending_objects13032026/10/14 16:45:18 INFO Vacuumed table table=multipart_uploads13042026/10/14 16:45:18 INFO Vacuumed table table=closures13052026/10/14 16:45:18 INFO Vacuumed table table=objects1306--- PASS: TestSweepRechecksPendingAfterLocking (7.66s)1307=== CONT TestGCTaskStore_GetReturnsLatest1308--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1309=== CONT TestDeleteClosuresRacingPins1310--- PASS: TestPushWaitsForSweepHoldingRow (7.83s)1311=== CONT TestMultipartCleanup1312--- PASS: TestGetExistingObjectsLocksRows (7.47s)1313=== CONT TestGCTaskStore_GetEmpty1314--- PASS: TestGCTaskStore_GetEmpty (0.00s)1315=== CONT TestClientFallsBackToClosures13162026/10/14 16:45:18 INFO Received uploads request method=POST path=/api/pending_closures13172026/10/14 16:45:18 INFO Aborted multipart uploads count=0 kept=013182026/10/14 16:45:18 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=013192026/10/14 16:45:18 INFO Vacuumed table table=pending_closures13202026/10/14 16:45:18 INFO Vacuumed table table=pending_objects13212026/10/14 16:45:18 INFO Vacuumed table table=multipart_uploads13222026/10/14 16:45:18 INFO Aborted multipart uploads count=0 kept=013232026/10/14 16:45:18 INFO Vacuumed table table=closures13242026/10/14 16:45:18 WARN Force mode enabled - objects will be deleted immediately without grace period13252026/10/14 16:45:18 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=013262026/10/14 16:45:18 INFO Vacuumed table table=objects13272026/10/14 16:45:18 INFO Vacuumed table table=pending_closures13282026/10/14 16:45:18 INFO Vacuumed table table=pending_objects13292026/10/14 16:45:18 INFO Vacuumed table table=multipart_uploads13302026/10/14 16:45:18 INFO Vacuumed table table=closures13312026/10/14 16:45:18 INFO Aborted multipart uploads count=0 kept=013322026/10/14 16:45:18 WARN Force mode enabled - objects will be deleted immediately without grace period13332026/10/14 16:45:18 INFO Vacuumed table table=objects1334--- PASS: TestGCMetrics (7.29s)13352026/10/14 16:45:18 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=01336=== CONT TestObjectStatsTrigger13372026/10/14 16:45:18 INFO Vacuumed table table=pending_closures13382026/10/14 16:45:18 INFO Vacuumed table table=pending_objects13392026/10/14 16:45:18 INFO Vacuumed table table=multipart_uploads13402026/10/14 16:45:18 INFO Vacuumed table table=closures13412026/10/14 16:45:18 INFO Vacuumed table table=objects1342--- PASS: TestPushDedupSurvivesConcurrentGC (7.99s)1343=== CONT TestGCTaskStore_ConflictDifferentParams1344--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1345=== CONT TestClientPushesUseOnePush1346--- PASS: TestGCBugBareHashReferences (7.69s)1347=== CONT TestPendingCleanupUsesOneCutoff1348--- PASS: TestRegisterCompletedObjectNeedsPendingRow (7.16s)1349=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded13502026/10/14 16:45:19 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld2 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1351--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (7.20s)1352=== CONT TestService_NativeMTLS13532026/10/14 16:45:19 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=013542026/10/14 16:45:19 INFO Received create pin request method=POST path=/api/pins/myapp13552026/10/14 16:45:19 INFO Created/updated pin name=myapp store_path=/private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestPinProtectsFromGC3670699370/001/store/4wzyw8596xj1clzjrc5iq1p55hjpkc42-pinned-file.txt narinfo_key=4wzyw8596xj1clzjrc5iq1p55hjpkc42.narinfo13562026/10/14 16:45:19 INFO Starting cleanup of old closures method=DELETE path=/api/closures13572026/10/14 16:45:19 INFO Garbage collection started13582026/10/14 16:45:19 INFO Aborted multipart uploads count=0 kept=013592026/10/14 16:45:19 WARN Force mode enabled - objects will be deleted immediately without grace period13602026/10/14 16:45:19 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013612026/10/14 16:45:19 INFO Vacuumed table table=pending_closures13622026/10/14 16:45:19 INFO Vacuumed table table=pending_objects13632026/10/14 16:45:19 INFO Vacuumed table table=multipart_uploads13642026/10/14 16:45:19 INFO Vacuumed table table=closures13652026/10/14 16:45:19 INFO Vacuumed table table=objects13662026/10/14 16:45:20 INFO Aborted multipart uploads count=0 kept=013672026/10/14 16:45:20 WARN Force mode enabled - objects will be deleted immediately without grace period13682026/10/14 16:45:20 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=013692026/10/14 16:45:20 INFO Vacuumed table table=pending_closures13702026/10/14 16:45:20 INFO Vacuumed table table=pending_objects13712026/10/14 16:45:20 INFO Vacuumed table table=multipart_uploads13722026/10/14 16:45:20 INFO Vacuumed table table=closures13732026/10/14 16:45:20 INFO Vacuumed table table=objects13742026/10/14 16:45:20 INFO Aborted multipart uploads count=0 kept=013752026/10/14 16:45:20 WARN Force mode enabled - objects will be deleted immediately without grace period13762026/10/14 16:45:20 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=013772026/10/14 16:45:20 INFO Vacuumed table table=pending_closures13782026/10/14 16:45:20 INFO Vacuumed table table=pending_objects13792026/10/14 16:45:20 INFO Vacuumed table table=multipart_uploads13802026/10/14 16:45:20 INFO Vacuumed table table=closures13812026/10/14 16:45:20 INFO Vacuumed table table=objects1382--- PASS: TestSweepSkipsRowsLockedByPush (7.77s)1383=== CONT TestMetricsCommit13842026/10/14 16:45:20 INFO lead: acquired remote=192.0.2.1:123413852026/10/14 16:45:20 INFO Received uploads request method=POST path=/api/pending_closures13862026/10/14 16:45:20 INFO Aborted multipart uploads count=0 kept=013872026/10/14 16:45:20 WARN Force mode enabled - objects will be deleted immediately without grace period13882026/10/14 16:45:20 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."13892026/10/14 16:45:20 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1390--- PASS: TestFailedS3DeleteKeepsTombstone (7.46s)1391=== CONT TestServerTLSConfig1392=== RUN TestServerTLSConfig/no_client_CA1393=== PAUSE TestServerTLSConfig/no_client_CA1394=== RUN TestServerTLSConfig/missing_CA_file1395=== PAUSE TestServerTLSConfig/missing_CA_file1396=== RUN TestServerTLSConfig/not_a_PEM_file1397=== PAUSE TestServerTLSConfig/not_a_PEM_file1398=== CONT TestService_AuthMiddleware_OIDC13992026/10/14 16:45:21 WARN readiness check failed error="closed pool"1400--- PASS: TestService_readinessHandler (7.35s)1401=== CONT TestPush_CompleteCommitsEveryRoot14022026/10/14 16:45:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58558/oidc14032026/10/14 16:45:21 INFO lead: acquired remote=192.0.2.1:123414042026/10/14 16:45:21 INFO lead: released remote=192.0.2.1:12341405--- PASS: TestLeadIncumbentAnnouncesAtOnce (6.93s)1406=== CONT TestCacheStatsHandler14072026/10/14 16:45:21 INFO lead: released remote=192.0.2.1:12341408--- PASS: TestLeadEndsOnShutdown (8.08s)1409=== CONT TestPush_RootsAreLockedInByteOrder1410--- PASS: TestService_healthCheckHandler (6.92s)1411=== CONT TestCacheConfigHandler1412=== RUN TestCacheConfigHandler/full_config,_no_issuer1413=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1414=== RUN TestCacheConfigHandler/no_cache_url_configured1415=== PAUSE TestCacheConfigHandler/no_cache_url_configured1416=== RUN TestCacheConfigHandler/no_signing_keys1417=== PAUSE TestCacheConfigHandler/no_signing_keys1418=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1419=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1420=== CONT TestClientSharedPathCommittedMidPush1421=== NAME TestPinProtectsFromGC1422 client_integration_test.go:840: Pin successfully protected closure from garbage collection1423--- PASS: TestPinProtectsFromGC (12.03s)1424=== CONT TestPush_CompleteWaitsForCleanupOfThePush14252026/10/14 16:45:22 INFO Received uploads request method=POST path=/api/pending_closures1426--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (7.12s)1427=== CONT TestService_ReadScope_PublicByDefault14282026/10/14 16:45:22 INFO lead: acquired remote=192.0.2.1:123414292026/10/14 16:45:23 INFO Aborted multipart uploads count=0 kept=014302026/10/14 16:45:23 WARN Force mode enabled - objects will be deleted immediately without grace period1431=== NAME TestOrphanedObjectsGCStressTest1432 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains14332026/10/14 16:45:23 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=014342026/10/14 16:45:23 INFO Vacuumed table table=pending_closures14352026/10/14 16:45:23 INFO Vacuumed table table=pending_objects14362026/10/14 16:45:23 INFO Vacuumed table table=multipart_uploads14372026/10/14 16:45:23 INFO Vacuumed table table=closures14382026/10/14 16:45:23 INFO Received uploads request method=POST path=/api/pending_closures1439 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion14402026/10/14 16:45:23 INFO Vacuumed table table=objects1441--- PASS: TestGCSweepDeliversEachKeyOnce (6.61s)1442=== CONT TestPush_RepeatedRootCommitsOnce1443=== CONT TestService_RequireScope_OIDC1444--- PASS: TestTombstonedObjectOfferedWithoutWaiting (6.22s)14452026/10/14 16:45:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58573/oidc1446--- PASS: TestConnectWaitsForAPeerMigration (7.96s)1447=== CONT TestClientIntegration14482026/10/14 16:45:23 INFO lead: released remote=192.0.2.1:123414492026/10/14 16:45:23 INFO lead: acquired remote=192.0.2.1:123414502026/10/14 16:45:24 INFO Received uploads request method=POST path=/api/pending_closures14512026/10/14 16:45:24 INFO Aborted multipart uploads count=0 kept=014522026/10/14 16:45:24 WARN Force mode enabled - objects will be deleted immediately without grace period14532026/10/14 16:45:24 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=014542026/10/14 16:45:24 INFO Vacuumed table table=pending_closures14552026/10/14 16:45:24 INFO Vacuumed table table=pending_objects14562026/10/14 16:45:24 INFO Vacuumed table table=multipart_uploads14572026/10/14 16:45:24 INFO Vacuumed table table=closures14582026/10/14 16:45:24 INFO Vacuumed table table=objects14592026/10/14 16:45:24 INFO Received uploads request method=POST path=/api/pending_closures1460--- PASS: TestGCSweepSkipsPendingObjects (6.83s)1461=== CONT TestClientMultipleUploads14622026/10/14 16:45:24 INFO Received cleanup request method=DELETE path=/api/pending_closures14632026/10/14 16:45:24 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket63/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""14642026/10/14 16:45:24 INFO Aborted multipart uploads count=0 kept=114652026/10/14 16:45:24 INFO Received cleanup request method=DELETE path=/api/pending_closures14662026/10/14 16:45:24 INFO Aborted multipart uploads count=1 kept=01467--- PASS: TestMultipartCleanup (6.61s)1468=== CONT TestClientWithDependencies14692026/10/14 16:45:24 INFO lead: released remote=192.0.2.1:12341470--- PASS: TestLeadElectsOneAndHandsOver (9.58s)1471=== CONT TestClientErrorHandling1472=== RUN TestClientErrorHandling/InvalidStorePath1473=== PAUSE TestClientErrorHandling/InvalidStorePath1474=== RUN TestClientErrorHandling/InvalidAuthToken1475=== PAUSE TestClientErrorHandling/InvalidAuthToken1476=== RUN TestClientErrorHandling/ServerNotAvailable1477=== PAUSE TestClientErrorHandling/ServerNotAvailable1478=== CONT TestClientCADerivations1479--- PASS: TestObjectStatsLargeCommit (17.39s)1480=== CONT TestReadRedirectUsesPublicS3URL1481--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (7.62s)1482=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1483--- PASS: TestObjectStatsTrigger (6.59s)1484=== CONT TestPush_OverlappingRootsStoreOneRowPerKey14852026/10/14 16:45:25 INFO Received uploads request method=POST path=/api/pending_closures14862026/10/14 16:45:25 INFO Received uploads request method=POST path=/api/pending_closures14872026/10/14 16:45:25 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14882026/10/14 16:45:25 INFO Uploading 32jkvsyz6iala6w9s8xm3abni4lmis2g-a (256B)14892026/10/14 16:45:25 INFO Uploading vs0dhy0mf2xv9sndvnnlhl9zx44d45l6-shared-dep (136B)14902026/10/14 16:45:25 WARN Failed to register uploaded object key=xja5z7ywh8c8901bmz3lgs6ncjs6925g.ls error="server returned 404: 404 page not found\n"14912026/10/14 16:45:25 WARN Failed to register uploaded object key=32jkvsyz6iala6w9s8xm3abni4lmis2g.ls error="server returned 404: 404 page not found\n"14922026/10/14 16:45:25 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14932026/10/14 16:45:25 WARN Failed to register uploaded object key=vs0dhy0mf2xv9sndvnnlhl9zx44d45l6.ls error="server returned 404: 404 page not found\n"14942026/10/14 16:45:25 WARN Failed to register uploaded object key=nar/1l8x3avcdb7m2a81lan26vf9hl1l9376yyc91s9f0zgnv1xfamx5.nar.zst error="server returned 404: 404 page not found\n"14952026/10/14 16:45:25 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14962026/10/14 16:45:25 INFO Signed narinfos id=1 count=214972026/10/14 16:45:25 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14982026/10/14 16:45:25 INFO Signed narinfos id=2 count=214992026/10/14 16:45:25 INFO Uploading 4 narinfos15002026/10/14 16:45:25 WARN Failed to register uploaded object key=xja5z7ywh8c8901bmz3lgs6ncjs6925g.narinfo error="server returned 404: 404 page not found\n"15012026/10/14 16:45:25 WARN Failed to register uploaded object key=vs0dhy0mf2xv9sndvnnlhl9zx44d45l6.narinfo error="server returned 404: 404 page not found\n"15022026/10/14 16:45:25 WARN Failed to register uploaded object key=32jkvsyz6iala6w9s8xm3abni4lmis2g.narinfo error="server returned 404: 404 page not found\n"15032026/10/14 16:45:25 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15042026/10/14 16:45:25 WARN Failed to register uploaded object key=vs0dhy0mf2xv9sndvnnlhl9zx44d45l6.narinfo error="server returned 404: 404 page not found\n"15052026/10/14 16:45:25 INFO Completed upload id=1 objects=6 duration=26.188417ms15062026/10/14 16:45:25 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15072026/10/14 16:45:25 INFO Completed upload id=2 objects=6 duration=742.125µs15082026/10/14 16:45:25 INFO Upload complete. (344ms)1509=== NAME TestClientFallsBackToClosures1510 client_pushes_test.go:112: Retrieved narinfo from S3:1511 StorePath: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientFallsBackToClosures1845379349/001/store/vs0dhy0mf2xv9sndvnnlhl9zx44d45l6-shared-dep1512 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1513 Compression: zstd1514 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821515 NarSize: 1361516 References: 1517 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1518 client_pushes_test.go:112: Retrieved narinfo from S3:1519 StorePath: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientFallsBackToClosures1845379349/001/store/32jkvsyz6iala6w9s8xm3abni4lmis2g-a1520 URL: nar/1l8x3avcdb7m2a81lan26vf9hl1l9376yyc91s9f0zgnv1xfamx5.nar.zst1521 Compression: zstd1522 NarHash: sha256:1l8x3avcdb7m2a81lan26vf9hl1l9376yyc91s9f0zgnv1xfamx51523 NarSize: 2561524 References: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientFallsBackToClosures1845379349/001/store/vs0dhy0mf2xv9sndvnnlhl9zx44d45l6-shared-dep1525 CA: text:sha256:18wk75qp95hy9xwwhi7wjrw6h6nkz2n70cbv3lijr71d8p7g61nv1526 client_pushes_test.go:112: Retrieved narinfo from S3:1527 StorePath: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientFallsBackToClosures1845379349/001/store/xja5z7ywh8c8901bmz3lgs6ncjs6925g-b1528 URL: nar/1l8x3avcdb7m2a81lan26vf9hl1l9376yyc91s9f0zgnv1xfamx5.nar.zst1529 Compression: zstd1530 NarHash: sha256:1l8x3avcdb7m2a81lan26vf9hl1l9376yyc91s9f0zgnv1xfamx51531 NarSize: 2561532 References: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientFallsBackToClosures1845379349/001/store/vs0dhy0mf2xv9sndvnnlhl9zx44d45l6-shared-dep1533 CA: text:sha256:18wk75qp95hy9xwwhi7wjrw6h6nkz2n70cbv3lijr71d8p7g61nv15342026/10/14 16:45:26 INFO Received uploads request method=POST path=/api/pending_closures1535--- PASS: TestClientFallsBackToClosures (7.89s)1536=== CONT TestService_AuthMiddleware_MTLSProxyHeader15372026/10/14 16:45:26 INFO Received uploads request method=POST path=/api/pending_closures15382026/10/14 16:45:26 INFO Received cleanup request method=DELETE path=/api/pending_closures15392026/10/14 16:45:26 INFO Received uploads request method=POST path=/api/pending_closures15402026/10/14 16:45:26 INFO Received push request method=POST path=/api/pushes15412026/10/14 16:45:26 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15422026/10/14 16:45:26 INFO Uploading qkdgvkr6jlrzngdnhp3hhmhdin2zla5x-b (256B)15432026/10/14 16:45:26 INFO Uploading 06kivsmgvabra9hw7abgz6195fzmfj5p-shared-dep (136B)15442026/10/14 16:45:26 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15452026/10/14 16:45:26 WARN Failed to register uploaded object key=06kivsmgvabra9hw7abgz6195fzmfj5p.ls error="server returned 404: 404 page not found\n"15462026/10/14 16:45:26 WARN Failed to register uploaded object key=nar/0rnbxryx7knkd8y5g4595z20khi0gc27hii3im08brf725v3aw87.nar.zst error="server returned 404: 404 page not found\n"15472026/10/14 16:45:26 WARN Failed to register uploaded object key=0b6jj4gllfhw93qmcvnaqa6nnladfgdf.ls error="server returned 404: 404 page not found\n"15482026/10/14 16:45:26 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15492026/10/14 16:45:26 WARN Failed to register uploaded object key=qkdgvkr6jlrzngdnhp3hhmhdin2zla5x.ls error="server returned 404: 404 page not found\n"15502026/10/14 16:45:26 INFO Signed narinfos id=1 count=31551--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (7.14s)1552=== CONT TestService_ReadAuthMiddleware15532026/10/14 16:45:26 INFO Uploading 3 narinfos15542026/10/14 16:45:26 WARN Failed to register uploaded object key=06kivsmgvabra9hw7abgz6195fzmfj5p.narinfo error="server returned 404: 404 page not found\n"15552026/10/14 16:45:26 WARN Failed to register uploaded object key=qkdgvkr6jlrzngdnhp3hhmhdin2zla5x.narinfo error="server returned 404: 404 page not found\n"15562026/10/14 16:45:26 INFO Received complete push request method=POST path=/api/pushes/1/complete15572026/10/14 16:45:26 WARN Failed to register uploaded object key=0b6jj4gllfhw93qmcvnaqa6nnladfgdf.narinfo error="server returned 404: 404 page not found\n"15582026/10/14 16:45:26 INFO Completed push id=1 objects=8 duration=24.64625ms15592026/10/14 16:45:26 INFO Upload complete. (211ms)1560=== NAME TestClientPushesUseOnePush1561 client_pushes_test.go:97: Retrieved narinfo from S3:1562 StorePath: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientPushesUseOnePush730667800/001/store/06kivsmgvabra9hw7abgz6195fzmfj5p-shared-dep1563 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1564 Compression: zstd1565 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821566 NarSize: 1361567 References: 1568 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1569 client_pushes_test.go:97: Retrieved narinfo from S3:1570 StorePath: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientPushesUseOnePush730667800/001/store/0b6jj4gllfhw93qmcvnaqa6nnladfgdf-a1571 URL: nar/0rnbxryx7knkd8y5g4595z20khi0gc27hii3im08brf725v3aw87.nar.zst1572 Compression: zstd1573 NarHash: sha256:0rnbxryx7knkd8y5g4595z20khi0gc27hii3im08brf725v3aw871574 NarSize: 2561575 References: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientPushesUseOnePush730667800/001/store/06kivsmgvabra9hw7abgz6195fzmfj5p-shared-dep1576 CA: text:sha256:0lg8mwxg35psz5s67x9afifzbwhn9xfvcpgx89w9p41r0cbhr5l91577 client_pushes_test.go:97: Retrieved narinfo from S3:1578 StorePath: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientPushesUseOnePush730667800/001/store/qkdgvkr6jlrzngdnhp3hhmhdin2zla5x-b1579 URL: nar/0rnbxryx7knkd8y5g4595z20khi0gc27hii3im08brf725v3aw87.nar.zst1580 Compression: zstd1581 NarHash: sha256:0rnbxryx7knkd8y5g4595z20khi0gc27hii3im08brf725v3aw871582 NarSize: 2561583 References: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientPushesUseOnePush730667800/001/store/06kivsmgvabra9hw7abgz6195fzmfj5p-shared-dep1584 CA: text:sha256:0lg8mwxg35psz5s67x9afifzbwhn9xfvcpgx89w9p41r0cbhr5l91585--- PASS: TestClientPushesUseOnePush (7.72s)1586=== CONT TestReadProxyRangeRequest15872026/10/14 16:45:26 WARN mTLS auth: subject not in bound subjects subject="CN=reader"15882026/10/14 16:45:26 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1589--- PASS: TestService_NativeMTLS (7.02s)1590=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15912026/10/14 16:45:26 INFO Received uploads request method=POST path=/1592=== CONT TestProxyWriteTimeout/narinfo1593=== CONT TestIsValidUploadKey/narinfo1594=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15952026/10/14 16:45:26 INFO Received request for more parts method=POST path=/1596=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15972026/10/14 16:45:26 INFO Received complete multipart upload request method=POST path=/1598=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15992026/10/14 16:45:26 INFO Received uploads request method=POST path=/1600--- PASS: TestUploadHandlersRejectInvalidKeys (0.05s)1601 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1602 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1603 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1604 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1605=== CONT TestPendingClosureWriteTimeout/empty1606=== CONT TestIsValidUploadKey/unknown_type1607=== CONT TestIsValidUploadKey/empty_key1608=== CONT TestIsValidUploadKey/absolute1609=== CONT TestIsValidUploadKey/traversal_nar1610=== CONT TestIsValidUploadKey/traversal1611=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1612=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1613=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1614=== CONT TestIsValidUploadKey/index.html1615=== CONT TestIsValidUploadKey/nix-cache-info1616=== CONT TestIsValidUploadKey/realisation_plus_in_output1617=== CONT TestIsValidUploadKey/realisation1618=== CONT TestIsValidUploadKey/build_log_equals1619=== CONT TestIsValidUploadKey/build_log_question_mark1620=== CONT TestIsValidUploadKey/build_log_plus_in_name1621=== CONT TestIsValidUploadKey/build_log_home-manager_file1622=== CONT TestIsValidUploadKey/build_log1623=== CONT TestIsValidUploadKey/listing1624=== CONT TestIsValidUploadKey/nar_plain1625=== CONT TestIsValidUploadKey/nar_xz1626=== CONT TestIsValidUploadKey/nar_zst1627--- PASS: TestIsValidUploadKey (0.05s)1628 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1629 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1630 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1631 --- PASS: TestIsValidUploadKey/absolute (0.00s)1632 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1633 --- PASS: TestIsValidUploadKey/traversal (0.00s)1634 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1635 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1636 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1637 --- PASS: TestIsValidUploadKey/index.html (0.00s)1638 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1639 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1640 --- PASS: TestIsValidUploadKey/realisation (0.00s)1641 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1642 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1643 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1644 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1645 --- PASS: TestIsValidUploadKey/build_log (0.00s)1646 --- PASS: TestIsValidUploadKey/listing (0.00s)1647 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1648 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1649 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1650=== CONT TestParseSingleRange/none1651=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline16522026/10/14 16:45:26 INFO Received push request method=POST path=/api/pushes16532026/10/14 16:45:27 INFO Received complete push request method=POST path=/api/pushes/1/complete16542026/10/14 16:45:27 INFO Completed push id=1 objects=4 duration=43.287125ms16552026/10/14 16:45:27 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16562026/10/14 16:45:27 INFO Completed upload id=2 objects=2 duration=1.143792ms1657--- PASS: TestMetricsCommit (6.82s)1658=== CONT TestPendingClosureWriteTimeout/670k_objects1659=== CONT TestPendingClosureWriteTimeout/400_objects1660=== CONT TestIsValidCachePath/narinfo1661=== CONT TestParseSingleRange/start_far_past_EOF1662=== CONT TestParseSingleRange/start_past_EOF1663=== CONT TestParseSingleRange/single_byte1664=== CONT TestParseSingleRange/suffix_exceeds_size1665=== CONT TestParseSingleRange/suffix1666=== CONT TestParseSingleRange/end_clamped_to_size1667=== CONT TestParseSingleRange/open-ended1668=== CONT TestParseSingleRange/closed1669=== CONT TestParseSingleRange/malformed_end_before_start1670=== CONT TestParseSingleRange/malformed_both_empty1671=== CONT TestParseSingleRange/malformed_no_dash1672=== CONT TestParseSingleRange/multi-range_ignored1673=== CONT TestParseSingleRange/unknown_unit1674--- PASS: TestParseSingleRange (0.05s)1675 --- PASS: TestParseSingleRange/none (0.00s)1676 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1677 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1678 --- PASS: TestParseSingleRange/single_byte (0.00s)1679 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1680 --- PASS: TestParseSingleRange/suffix (0.00s)1681 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1682 --- PASS: TestParseSingleRange/open-ended (0.00s)1683 --- PASS: TestParseSingleRange/closed (0.00s)1684 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1685 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1686 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1687 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1688 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1689=== CONT TestIsValidCachePath/index.html1690=== CONT TestIsValidCachePath/short_hash1691=== CONT TestIsValidCachePath/wrong_extension1692=== CONT TestIsValidCachePath/leading_slash1693=== CONT TestIsValidCachePath/empty1694=== CONT TestProxyWriteTimeout/unknown_size1695=== CONT TestIsValidCachePath/random_path1696=== CONT TestIsValidCachePath/invalid_char_u1697=== CONT TestIsValidCachePath/invalid_char_e1698=== CONT TestIsValidCachePath/traversal_in_middle1699=== CONT TestIsValidCachePath/traversal_parent1700=== CONT TestIsValidCachePath/nar_uncompressed1701=== CONT TestIsValidCachePath/nix-cache-info1702=== CONT TestIsValidCachePath/realisation1703=== CONT TestIsValidCachePath/log1704=== CONT TestIsValidCachePath/ls1705=== CONT TestProxyWriteTimeout/1_GiB_nar1706=== CONT TestProxyWriteTimeout/10_GiB_nar1707--- PASS: TestProxyWriteTimeout (0.05s)1708 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1709 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1710 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1711 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1712=== CONT TestIsValidCachePath/nar_xz1713=== CONT TestIsValidCachePath/nar_bz21714=== CONT TestIsValidCachePath/nar_zst1715=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1716--- PASS: TestIsValidCachePath (0.00s)1717 --- PASS: TestIsValidCachePath/narinfo (0.00s)1718 --- PASS: TestIsValidCachePath/index.html (0.00s)1719 --- PASS: TestIsValidCachePath/short_hash (0.00s)1720 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1721 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1722 --- PASS: TestIsValidCachePath/empty (0.00s)1723 --- PASS: TestIsValidCachePath/random_path (0.00s)1724 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1725 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1726 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1727 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1728 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1729 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1730 --- PASS: TestIsValidCachePath/realisation (0.00s)1731 --- PASS: TestIsValidCachePath/log (0.00s)1732 --- PASS: TestIsValidCachePath/ls (0.00s)1733 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1734 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1735 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1736 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1737=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17382026/10/14 16:45:27 INFO Received complete multipart upload request method=POST path=/1739=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17402026/10/14 16:45:27 INFO Received uploads request method=POST path=/1741=== NAME TestOrphanedObjectsGCStressTest1742 orphaned_objects_gc_test.go:503: Stress test completed successfully:1743 orphaned_objects_gc_test.go:504: - Active objects preserved: 201744 orphaned_objects_gc_test.go:505: - Objects deleted: 2101745 orphaned_objects_gc_test.go:506: - Total GC'd: 2101746--- PASS: TestOrphanedObjectsGCStressTest (18.35s)1747=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17482026/10/14 16:45:27 INFO Received request for more parts method=POST path=/17492026/10/14 16:45:27 INFO Received push request method=POST path=/api/pushes1750=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale17512026/10/14 16:45:27 INFO Received complete push request method=POST path=/api/pushes/1/complete17522026/10/14 16:45:27 INFO Completed push id=1 objects=6 duration=11.248333ms1753--- PASS: TestPush_CompleteCommitsEveryRoot (6.39s)1754=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1755=== CONT TestGCEndsOnShutdown/before_the_run1756--- PASS: TestUploadHandlersRejectOversizedBody (0.08s)1757 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.03s)1758 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1759 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.29s)1760=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1761=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1762=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1763=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1764=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1765=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1766=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1767=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1768=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1769--- PASS: TestCacheStatsHandler (6.51s)1770=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark17712026/10/14 16:45:28 INFO Received push request method=POST path=/api/pushes17722026-10-14 16:45:28.232 UTC [20754] ERROR: could not obtain lock on row in relation "closures"17732026-10-14 16:45:28.232 UTC [20754] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17742026-10-14 16:45:28.238 UTC [20754] ERROR: could not obtain lock on row in relation "closures"17752026-10-14 16:45:28.238 UTC [20754] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17762026-10-14 16:45:28.238 UTC [20754] ERROR: could not obtain lock on row in relation "closures"17772026-10-14 16:45:28.238 UTC [20754] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17782026-10-14 16:45:28.244 UTC [20754] ERROR: could not obtain lock on row in relation "closures"17792026-10-14 16:45:28.244 UTC [20754] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17802026-10-14 16:45:28.247 UTC [20754] ERROR: could not obtain lock on row in relation "closures"17812026-10-14 16:45:28.247 UTC [20754] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1782--- PASS: TestPush_RootsAreLockedInByteOrder (6.86s)1783=== CONT TestPush_RejectsBadRequests/no_roots17842026/10/14 16:45:28 INFO Received push request method=POST path=/api/pushes1785=== CONT TestPush_RejectsBadRequests/bad_root17862026/10/14 16:45:28 INFO Received push request method=POST path=/api/pushes1787=== CONT TestPush_RejectsBadRequests/root_not_in_objects17882026/10/14 16:45:28 INFO Received push request method=POST path=/api/pushes1789=== CONT TestPush_RejectsBadRequests/no_objects17902026/10/14 16:45:28 INFO Received push request method=POST path=/api/pushes1791=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1792--- PASS: TestPush_RejectsBadRequests (6.31s)1793 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1794 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1795 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1796 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)17972026/10/14 16:45:28 INFO Received push request method=POST path=/api/pushes1798--- PASS: TestService_ReadScope_PublicByDefault (6.35s)1799=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check18002026-10-14 16:45:28.835 UTC [20758] ERROR: Push does not exist: id=118012026-10-14 16:45:28.835 UTC [20758] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE18022026-10-14 16:45:28.835 UTC [20758] STATEMENT: SELECT commit_push($1)1803--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (6.83s)1804=== CONT TestResolveDBConnectionString/flag_wins1805=== CONT TestResolveDBConnectionString/nothing_configured1806=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1807=== CONT TestResolveDBConnectionString/missing_file_is_an_error1808=== CONT TestResolveDBConnectionString/file_when_flag_empty1809=== CONT TestServerTLSConfig/no_client_CA1810=== CONT TestServerTLSConfig/not_a_PEM_file1811--- PASS: TestResolveDBConnectionString (0.04s)1812 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1813 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1814 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1815 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1816 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1817=== CONT TestServerTLSConfig/missing_CA_file1818--- PASS: TestServerTLSConfig (0.01s)1819 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1820 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1821 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1822=== CONT TestCacheConfigHandler/full_config,_no_issuer1823=== CONT TestCacheConfigHandler/no_signing_keys1824=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1825=== CONT TestCacheConfigHandler/no_cache_url_configured1826--- PASS: TestCacheConfigHandler (0.00s)1827 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1828 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1829 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1830 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1831=== CONT TestClientErrorHandling/InvalidStorePath1832--- PASS: TestDeleteClosuresRacingPins (10.85s)1833=== CONT TestClientErrorHandling/ServerNotAvailable18342026/10/14 16:45:29 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/present18352026/10/14 16:45:29 INFO Received push request method=POST path=/api/pushes18362026/10/14 16:45:29 WARN Request failed, retrying attempt=2 backoff=198.922292ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18372026/10/14 16:45:29 INFO Received complete push request method=POST path=/api/pushes/1/complete18382026/10/14 16:45:29 INFO Completed push id=1 objects=4 duration=41.807833ms1839--- PASS: TestPush_RepeatedRootCommitsOnce (6.18s)1840=== CONT TestClientErrorHandling/InvalidAuthToken18412026/10/14 16:45:29 WARN Request failed, retrying attempt=3 backoff=411.14966ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18422026/10/14 16:45:29 INFO Received push request method=POST path=/api/pushes18432026/10/14 16:45:29 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)18442026/10/14 16:45:29 INFO Uploading yykk5xa94bgajgcdvb2rbf3w2b4wzyp5-shared-dep (136B)18452026/10/14 16:45:29 INFO Uploading nb3y5qb0h59r0431na9x2bvf85r01vpl-top (264B)18462026/10/14 16:45:29 WARN Failed to register uploaded object key=yykk5xa94bgajgcdvb2rbf3w2b4wzyp5.ls error="server returned 404: 404 page not found\n"18472026/10/14 16:45:29 WARN Failed to register uploaded object key=nar/183fs2r2858lhpbrv3gfay1qzywh402zk6ii4fgvn0d6b26ifvhy.nar.zst error="server returned 404: 404 page not found\n"18482026/10/14 16:45:29 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18492026/10/14 16:45:29 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18502026/10/14 16:45:29 WARN Failed to register uploaded object key=nb3y5qb0h59r0431na9x2bvf85r01vpl.ls error="server returned 404: 404 page not found\n"18512026/10/14 16:45:29 INFO Signed narinfos id=1 count=218522026/10/14 16:45:29 INFO Uploading 2 narinfos18532026/10/14 16:45:29 WARN Failed to register uploaded object key=yykk5xa94bgajgcdvb2rbf3w2b4wzyp5.narinfo error="server returned 404: 404 page not found\n"18542026/10/14 16:45:29 INFO Received complete push request method=POST path=/api/pushes/1/complete18552026/10/14 16:45:29 WARN Failed to register uploaded object key=nb3y5qb0h59r0431na9x2bvf85r01vpl.narinfo error="server returned 404: 404 page not found\n"18562026/10/14 16:45:29 INFO Completed push id=1 objects=6 duration=24.14825ms18572026/10/14 16:45:29 INFO Upload complete. (213ms)1858=== NAME TestClientSharedPathCommittedMidPush1859 client_integration_test.go:680: Retrieved narinfo from S3:1860 StorePath: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientSharedPathCommittedMidPush1917272014/001/store/yykk5xa94bgajgcdvb2rbf3w2b4wzyp5-shared-dep1861 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1862 Compression: zstd1863 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821864 NarSize: 1361865 References: 1866 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1867 client_integration_test.go:680: Retrieved narinfo from S3:1868 StorePath: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientSharedPathCommittedMidPush1917272014/001/store/nb3y5qb0h59r0431na9x2bvf85r01vpl-top1869 URL: nar/183fs2r2858lhpbrv3gfay1qzywh402zk6ii4fgvn0d6b26ifvhy.nar.zst1870 Compression: zstd1871 NarHash: sha256:183fs2r2858lhpbrv3gfay1qzywh402zk6ii4fgvn0d6b26ifvhy1872 NarSize: 2641873 References: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientSharedPathCommittedMidPush1917272014/001/store/yykk5xa94bgajgcdvb2rbf3w2b4wzyp5-shared-dep1874 CA: text:sha256:14mbddly4qchii8j4px8v39d8whgy947rxmrxjcm2zrgvnvblldm1875--- PASS: TestClientSharedPathCommittedMidPush (8.22s)1876=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1877=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected18782026/10/14 16:45:29 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]1879=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1880=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected18812026/10/14 16:45:29 WARN Authentication failed token_preview=eyJhbGciOi...2BKqJgDzSQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1882--- PASS: TestService_AuthMiddleware_OIDC (6.53s)1883 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1884 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1885 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1886 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)1887=== NAME TestClientIntegration1888 client_integration_test.go:286: Created store path: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientIntegration2106993345/002/store/fd81qlqw454h8q6jas31ii1x4zn5mdnl-test-file.txt1889=== RUN TestService_RequireScope_OIDC/builder_may_write1890=== PAUSE TestService_RequireScope_OIDC/builder_may_write1891=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1892=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1893=== RUN TestService_RequireScope_OIDC/ops_may_admin1894=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1895=== RUN TestService_RequireScope_OIDC/ops_may_not_write1896=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write18972026/10/14 16:45:30 WARN Request failed, retrying attempt=4 backoff=755.808323ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1898=== RUN TestService_RequireScope_OIDC/reader_may_not_write1899=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1900=== RUN TestService_RequireScope_OIDC/static_token_may_admin1901=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1902=== RUN TestService_RequireScope_OIDC/static_token_may_write1903=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1904=== RUN TestService_RequireScope_OIDC/reader_may_read1905=== PAUSE TestService_RequireScope_OIDC/reader_may_read1906=== RUN TestService_RequireScope_OIDC/writer_implies_read1907=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1908=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1909=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1910=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1911=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1912=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1913=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1914=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1915=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1916=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1917=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1918=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1919=== CONT TestService_RequireScope_OIDC/builder_may_write1920=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1921=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19222026/10/14 16:45:30 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]1923=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1924=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1925=== CONT TestService_RequireScope_OIDC/reader_may_not_write1926=== CONT TestService_RequireScope_OIDC/writer_implies_read1927=== CONT TestService_RequireScope_OIDC/ops_may_admin1928=== CONT TestService_RequireScope_OIDC/ops_may_not_write1929=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1930=== CONT TestService_RequireScope_OIDC/static_token_may_write1931=== CONT TestService_RequireScope_OIDC/reader_may_read1932=== CONT TestService_RequireScope_OIDC/static_token_may_admin1933--- PASS: TestService_RequireScope_OIDC (6.67s)1934 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1935 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1936 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1937 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1938 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1939 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1940 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1941 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1942 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1943 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1944 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1945 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1946 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1947 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)19482026-10-14 16:45:30.094 UTC [20274] LOG: checkpoint starting: wal19492026/10/14 16:45:30 INFO Received push request method=POST path=/api/pushes19502026/10/14 16:45:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19512026/10/14 16:45:30 INFO Uploading fd81qlqw454h8q6jas31ii1x4zn5mdnl-test-file.txt (152B)19522026/10/14 16:45:30 WARN Failed to register uploaded object key=fd81qlqw454h8q6jas31ii1x4zn5mdnl.ls error="server returned 404: 404 page not found\n"19532026/10/14 16:45:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19542026/10/14 16:45:30 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"19552026/10/14 16:45:30 INFO Signed narinfos id=1 count=119562026/10/14 16:45:30 INFO Uploading 1 narinfos19572026/10/14 16:45:30 INFO Received complete push request method=POST path=/api/pushes/1/complete19582026/10/14 16:45:30 WARN Failed to register uploaded object key=fd81qlqw454h8q6jas31ii1x4zn5mdnl.narinfo error="server returned 404: 404 page not found\n"19592026/10/14 16:45:30 INFO Completed push id=1 objects=3 duration=36.608833ms19602026/10/14 16:45:30 INFO Upload complete. (214ms)19612026/10/14 16:45:30 INFO All 1 paths already cached1962=== NAME TestClientIntegration1963 client_integration_test.go:312: Retrieved narinfo from S3:1964 StorePath: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientIntegration2106993345/002/store/fd81qlqw454h8q6jas31ii1x4zn5mdnl-test-file.txt1965 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1966 Compression: zstd1967 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11968 NarSize: 1521969 References: 1970 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11971 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1972 client_integration_test.go:313: Decompressed .ls content (64 bytes):1973 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1974 client_integration_test.go:316: Testing garbage collection...19752026/10/14 16:45:30 INFO Starting cleanup of old closures method=DELETE path=/api/closures19762026/10/14 16:45:30 INFO Garbage collection started19772026/10/14 16:45:30 INFO Aborted multipart uploads count=0 kept=019782026/10/14 16:45:30 WARN Force mode enabled - objects will be deleted immediately without grace period19792026/10/14 16:45:30 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=019802026/10/14 16:45:30 INFO Vacuumed table table=pending_closures19812026/10/14 16:45:30 INFO Vacuumed table table=pending_objects19822026/10/14 16:45:30 INFO Vacuumed table table=multipart_uploads1983=== NAME TestClientMultipleUploads1984 client_integration_test.go:358: Created store path 0: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientMultipleUploads2483991632/001/store/dkydx2wn5j2zcz6lk5pgx9qwj4mhwhza-test-file-0.txt19852026/10/14 16:45:30 INFO Vacuumed table table=closures19862026/10/14 16:45:30 INFO Vacuumed table table=objects1987 client_integration_test.go:358: Created store path 1: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientMultipleUploads2483991632/001/store/ddrs61ii3r1rnchc6mmb9fbc30a370ic-test-file-1.txt19882026/10/14 16:45:30 WARN Request failed, retrying attempt=5 backoff=1.468698611s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1989 client_integration_test.go:358: Created store path 2: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientMultipleUploads2483991632/001/store/vm4l4yksi3caszg7yk0wbmdmhvsiqxvr-test-file-2.txt1990{"timestamp":"2026-10-14T16:45:30.848697Z","level":"ERROR","message":"Scanner cycle completed without a durable data usage snapshot","event":"scanner_persist_state","component":"scanner","subsystem":"runtime","cycle":5,"outcome":"NoUpdate","state":"usage_not_durable","target":"rustfs::scanner","filename":"crates/scanner/src/scanner.rs","line_number":2350,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}19912026/10/14 16:45:30 INFO Received push request method=POST path=/api/pushes19922026/10/14 16:45:30 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)19932026/10/14 16:45:30 INFO Uploading dkydx2wn5j2zcz6lk5pgx9qwj4mhwhza-test-file-0.txt (160B)19942026/10/14 16:45:30 INFO Uploading ddrs61ii3r1rnchc6mmb9fbc30a370ic-test-file-1.txt (160B)19952026/10/14 16:45:30 INFO Uploading vm4l4yksi3caszg7yk0wbmdmhvsiqxvr-test-file-2.txt (160B)19962026/10/14 16:45:31 WARN Failed to register uploaded object key=ddrs61ii3r1rnchc6mmb9fbc30a370ic.ls error="server returned 404: 404 page not found\n"19972026/10/14 16:45:31 WARN Failed to register uploaded object key=dkydx2wn5j2zcz6lk5pgx9qwj4mhwhza.ls error="server returned 404: 404 page not found\n"19982026/10/14 16:45:31 WARN Failed to register uploaded object key=vm4l4yksi3caszg7yk0wbmdmhvsiqxvr.ls error="server returned 404: 404 page not found\n"19992026/10/14 16:45:31 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"20002026/10/14 16:45:31 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"20012026/10/14 16:45:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20022026/10/14 16:45:31 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"20032026/10/14 16:45:31 INFO Signed narinfos id=1 count=320042026/10/14 16:45:31 INFO Uploading 3 narinfos20052026/10/14 16:45:31 WARN Failed to register uploaded object key=ddrs61ii3r1rnchc6mmb9fbc30a370ic.narinfo error="server returned 404: 404 page not found\n"20062026/10/14 16:45:31 WARN Failed to register uploaded object key=dkydx2wn5j2zcz6lk5pgx9qwj4mhwhza.narinfo error="server returned 404: 404 page not found\n"20072026/10/14 16:45:31 INFO Received complete push request method=POST path=/api/pushes/1/complete20082026/10/14 16:45:31 WARN Failed to register uploaded object key=vm4l4yksi3caszg7yk0wbmdmhvsiqxvr.narinfo error="server returned 404: 404 page not found\n"20092026/10/14 16:45:31 INFO Completed push id=1 objects=9 duration=20.758ms20102026/10/14 16:45:31 INFO Upload complete. (201ms)2011 client_integration_test.go:369: Uploaded 3 paths in 237.606875ms2012=== NAME TestClientCADerivations2013 client_ca_test.go:136: Built CA derivation: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientCADerivations4097288600/001/store/djbg39vn0sga25pd0lzaf3ms44qsgsx6-ca-test2014--- PASS: TestClientMultipleUploads (6.82s)2015=== NAME TestClientCADerivations2016 client_ca_test.go:139: Found 1 dependencies (including self)2017--- PASS: TestReadRedirectUsesPublicS3URL (6.46s)20182026/10/14 16:45:31 INFO Received push request method=POST path=/api/pushes2019=== NAME TestClientWithDependencies2020 client_integration_test.go:613: Built derivation: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientWithDependencies1232964371/001/store/hwikf3pgqw7cdd9ankivjkl9mfvhr40q-test-script20212026/10/14 16:45:31 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20222026/10/14 16:45:31 INFO Uploading djbg39vn0sga25pd0lzaf3ms44qsgsx6-ca-test (144B)20232026/10/14 16:45:31 WARN Failed to register uploaded object key=djbg39vn0sga25pd0lzaf3ms44qsgsx6.ls error="server returned 404: 404 page not found\n"20242026/10/14 16:45:31 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"20252026/10/14 16:45:31 WARN Failed to register uploaded object key=log/2659v3jmdqvhif5lvxg387npaxi047ig-ca-test.drv error="server returned 404: 404 page not found\n"20262026/10/14 16:45:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20272026/10/14 16:45:31 INFO Signed narinfos id=1 count=120282026/10/14 16:45:31 INFO Uploading 1 narinfos2029 client_integration_test.go:615: Found 1 dependencies (including self)20302026/10/14 16:45:31 INFO Received complete push request method=POST path=/api/pushes/1/complete20312026/10/14 16:45:31 WARN Failed to register uploaded object key=djbg39vn0sga25pd0lzaf3ms44qsgsx6.narinfo error="server returned 404: 404 page not found\n"20322026/10/14 16:45:31 INFO Completed push id=1 objects=4 duration=11.390584ms20332026/10/14 16:45:31 INFO Upload complete. (195ms)2034=== NAME TestClientCADerivations2035 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientCADerivations4097288600/001/store/djbg39vn0sga25pd0lzaf3ms44qsgsx6-ca-test2036 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2037 Compression: zstd2038 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2039 NarSize: 1442040 References: 2041 Deriver: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientCADerivations4097288600/001/store/2659v3jmdqvhif5lvxg387npaxi047ig-ca-test.drv2042 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2043 client_ca_test.go:185: Checking for realisation files in S3...2044 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2045 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache20462026/10/14 16:45:31 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20472026/10/14 16:45:31 WARN mTLS auth: bound subjects configured but subject DN unavailable20482026/10/14 16:45:31 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2049--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (6.38s)20502026/10/14 16:45:31 INFO Received push request method=POST path=/api/pushes20512026/10/14 16:45:31 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20522026/10/14 16:45:31 INFO Uploading hwikf3pgqw7cdd9ankivjkl9mfvhr40q-test-script (136B)20532026/10/14 16:45:31 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"20542026/10/14 16:45:31 WARN Failed to register uploaded object key=hwikf3pgqw7cdd9ankivjkl9mfvhr40q.ls error="server returned 404: 404 page not found\n"20552026/10/14 16:45:31 WARN Failed to register uploaded object key=log/y9i4zgzz4sxpmsqc8axxd6jvmdlbbm87-test-script.drv error="server returned 404: 404 page not found\n"2056=== NAME TestClientCADerivations2057 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket83?endpoint=http://localhost:58298®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientCADerivations4097288600/001/store'2058 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 120592026/10/14 16:45:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20602026/10/14 16:45:31 INFO Signed narinfos id=1 count=120612026/10/14 16:45:31 INFO Uploading 1 narinfos20622026/10/14 16:45:31 INFO Received complete push request method=POST path=/api/pushes/1/complete20632026/10/14 16:45:31 WARN Failed to register uploaded object key=hwikf3pgqw7cdd9ankivjkl9mfvhr40q.narinfo error="server returned 404: 404 page not found\n"20642026/10/14 16:45:31 INFO Completed push id=1 objects=4 duration=14.28925ms20652026/10/14 16:45:31 INFO Upload complete. (140ms)2066=== NAME TestClientWithDependencies2067 client_integration_test.go:617: Skipping nix copy test - isolated store (/private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestClientWithDependencies1232964371/001/store) requires matching store prefix2068--- PASS: TestClientCADerivations (6.86s)2069--- PASS: TestClientWithDependencies (6.99s)20702026/10/14 16:45:31 INFO Received push request method=POST path=/api/pushes2071--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (6.36s)2072--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (5.85s)2073--- PASS: TestService_ReadAuthMiddleware (5.65s)20742026/10/14 16:45:32 INFO Aborted multipart uploads count=1 kept=020752026/10/14 16:45:32 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-config20762026/10/14 16:45:32 INFO Received cleanup request method=DELETE path=/api/pending_closures20772026/10/14 16:45:32 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02078=== NAME TestClientIntegration2079 client_integration_test.go:323: Objects in database after GC:2080 client_integration_test.go:323: Successfully deleted all objects with GC --force20812026/10/14 16:45:32 INFO Aborted multipart uploads count=1 kept=02082--- PASS: TestPendingCleanupUsesOneCutoff (13.01s)2083--- PASS: TestReadProxyRangeRequest (5.73s)2084--- PASS: TestClientIntegration (8.88s)20852026/10/14 16:45:32 WARN Request failed, retrying attempt=2 backoff=218.192544ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20862026/10/14 16:45:32 INFO Received uploads request method=POST path=/api/pending_closures20872026/10/14 16:45:32 WARN Request failed, retrying attempt=3 backoff=416.54297ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20882026/10/14 16:45:33 WARN Request failed, retrying attempt=4 backoff=790.855603ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20892026/10/14 16:45:33 INFO Aborted multipart uploads count=0 kept=020902026/10/14 16:45:33 WARN Force mode enabled - objects will be deleted immediately without grace period20912026/10/14 16:45:33 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:58298/bucket95/?delete=\": context canceled"2092--- PASS: TestPendingClosureWriteTimeout (0.05s)2093 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2094 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2095 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2096 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (6.62s)2097--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2098 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (5.99s)2099 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (6.01s)21002026/10/14 16:45:33 INFO Aborted multipart uploads count=0 kept=021012026/10/14 16:45:33 WARN Force mode enabled - objects will be deleted immediately without grace period2102--- PASS: TestGCEndsOnShutdown (0.00s)2103 --- PASS: TestGCEndsOnShutdown/before_the_run (5.67s)2104 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (5.84s)2105 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (5.78s)21062026/10/14 16:45:33 INFO Received uploads request method=POST path=/api/pending_closures21072026/10/14 16:45:33 INFO Aborted multipart uploads count=0 kept=021082026/10/14 16:45:33 WARN Force mode enabled - objects will be deleted immediately without grace period21092026/10/14 16:45:33 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=021102026/10/14 16:45:33 INFO Vacuumed table table=pending_closures21112026/10/14 16:45:33 INFO Vacuumed table table=pending_objects21122026/10/14 16:45:33 INFO Vacuumed table table=multipart_uploads21132026/10/14 16:45:33 INFO Vacuumed table table=closures21142026/10/14 16:45:33 INFO Vacuumed table table=objects21152026/10/14 16:45:33 WARN Request failed, retrying attempt=5 backoff=1.505005458s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21162026/10/14 16:45:34 INFO Received uploads request method=POST path=/api/pending_closures21172026/10/14 16:45:34 INFO Aborted multipart uploads count=0 kept=021182026/10/14 16:45:34 WARN Force mode enabled - objects will be deleted immediately without grace period21192026/10/14 16:45: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=021202026/10/14 16:45:34 INFO Vacuumed table table=pending_closures21212026/10/14 16:45:34 INFO Vacuumed table table=pending_objects21222026/10/14 16:45:34 INFO Vacuumed table table=multipart_uploads21232026/10/14 16:45:34 INFO Vacuumed table table=closures21242026/10/14 16:45:34 INFO Vacuumed table table=objects2125--- PASS: TestForceGCDuringPushOffersSweptObject (0.01s)2126 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (5.61s)2127 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (5.57s)21282026/10/14 16:45:34 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21292026/10/14 16:45:34 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21302026/10/14 16:45:35 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"21312026/10/14 16:45:35 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21322026/10/14 16:45:35 WARN Request failed, retrying attempt=2 backoff=201.76902ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21332026/10/14 16:45:35 WARN Request failed, retrying attempt=3 backoff=429.810933ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21342026/10/14 16:45:36 WARN Request failed, retrying attempt=4 backoff=739.829089ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21352026/10/14 16:45:36 WARN Request failed, retrying attempt=5 backoff=1.49893088s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2136{"timestamp":"2026-10-14T16:45:37.354073Z","level":"ERROR","message":"Scanner cycle completed without a durable data usage snapshot","event":"scanner_persist_state","component":"scanner","subsystem":"runtime","cycle":5,"outcome":"NoUpdate","state":"usage_not_durable","target":"rustfs::scanner","filename":"crates/scanner/src/scanner.rs","line_number":2350,"threadName":"rustfs-worker","threadId":"ThreadId(10)"}21372026/10/14 16:45:38 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_closures21382026/10/14 16:45:38 WARN Request failed, retrying attempt=2 backoff=208.632572ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21392026/10/14 16:45:38 WARN Request failed, retrying attempt=3 backoff=399.359239ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21402026/10/14 16:45:39 WARN Request failed, retrying attempt=4 backoff=866.047645ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21412026/10/14 16:45:39 WARN Request failed, retrying attempt=5 backoff=1.445892924s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2142--- PASS: TestClientErrorHandling (0.01s)2143 --- PASS: TestClientErrorHandling/InvalidStorePath (5.13s)2144 --- PASS: TestClientErrorHandling/InvalidAuthToken (4.99s)2145 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.53s)2146PASS21472026-10-14 16:45:41.616 UTC [20269] LOG: received smart shutdown request21482026-10-14 16:45:41.617 UTC [20269] LOG: background worker "logical replication launcher" (PID 20279) exited with exit code 121492026-10-14 16:45:42.755 UTC [20274] LOG: checkpoint complete: wrote 10307 buffers (62.9%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=11.925 s, sync=0.645 s, total=12.661 s; sync files=34045, longest=0.020 s, average=0.001 s; distance=533103 kB, estimate=533103 kB; lsn=0/228434C0, redo lsn=0/22028C1021502026-10-14 16:45:42.756 UTC [20274] LOG: shutting down21512026-10-14 16:45:42.756 UTC [20274] LOG: checkpoint starting: shutdown immediate21522026-10-14 16:45:42.813 UTC [20274] LOG: checkpoint complete: wrote 1377 buffers (8.4%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.038 s, sync=0.019 s, total=0.057 s; sync files=511, longest=0.001 s, average=0.001 s; distance=8298 kB, estimate=480622 kB; lsn=0/22843538, redo lsn=0/2284353821532026-10-14 16:45:42.820 UTC [20269] LOG: database system is shut down2154Running OIDC tests...2155=== RUN TestAudienceForIssuer2156=== PAUSE TestAudienceForIssuer2157=== RUN TestGlobMatch2158=== PAUSE TestGlobMatch2159=== RUN TestValidateToken_ValidToken2160=== PAUSE TestValidateToken_ValidToken2161=== RUN TestValidateToken_WrongAudience2162=== PAUSE TestValidateToken_WrongAudience2163=== RUN TestValidateToken_Expired2164=== PAUSE TestValidateToken_Expired2165=== RUN TestValidateToken_BoundClaimsMismatch2166=== PAUSE TestValidateToken_BoundClaimsMismatch2167=== RUN TestValidateToken_BoundSubjectMismatch2168=== PAUSE TestValidateToken_BoundSubjectMismatch2169=== RUN TestValidateToken_MultipleProviders2170=== PAUSE TestValidateToken_MultipleProviders2171=== RUN TestValidateToken_NoMatchingProvider2172=== PAUSE TestValidateToken_NoMatchingProvider2173=== RUN TestValidateToken_KubernetesServiceAccount2174=== PAUSE TestValidateToken_KubernetesServiceAccount2175=== RUN TestNewValidator_KubernetesRequiresCA2176=== PAUSE TestNewValidator_KubernetesRequiresCA2177=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2178=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2179=== RUN TestPins_ReservedForMatchingRule2180=== PAUSE TestPins_ReservedForMatchingRule2181=== RUN TestPins_TopLevelShorthand2182=== PAUSE TestPins_TopLevelShorthand2183=== RUN TestPins_ConfigValidation2184=== PAUSE TestPins_ConfigValidation2185=== RUN TestScopes_LegacyProviderDefaultsToWrite2186=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2187=== RUN TestScopes_Rules2188=== PAUSE TestScopes_Rules2189=== RUN TestScopes_ConfigValidation2190=== PAUSE TestScopes_ConfigValidation2191=== CONT TestAudienceForIssuer2192=== CONT TestValidateToken_KubernetesServiceAccount2193=== CONT TestNewValidator_KubernetesRequiresCA2194--- PASS: TestAudienceForIssuer (0.00s)2195=== CONT TestValidateToken_Expired2196=== CONT TestValidateToken_WrongAudience2197=== CONT TestValidateToken_ValidToken2198=== CONT TestGlobMatch2199=== RUN TestGlobMatch/foo_foo2200=== PAUSE TestGlobMatch/foo_foo2201=== RUN TestGlobMatch/foo_bar2202=== PAUSE TestGlobMatch/foo_bar2203=== RUN TestGlobMatch/*_2204=== PAUSE TestGlobMatch/*_2205=== RUN TestGlobMatch/*_anything2206=== PAUSE TestGlobMatch/*_anything2207=== RUN TestGlobMatch/foo*_foo2208=== PAUSE TestGlobMatch/foo*_foo2209=== RUN TestGlobMatch/foo*_foobar2210=== PAUSE TestGlobMatch/foo*_foobar2211=== RUN TestGlobMatch/foo*_bar2212=== PAUSE TestGlobMatch/foo*_bar2213=== RUN TestGlobMatch/*bar_bar2214=== PAUSE TestGlobMatch/*bar_bar2215=== RUN TestGlobMatch/*bar_foobar2216=== PAUSE TestGlobMatch/*bar_foobar2217=== RUN TestGlobMatch/*bar_foo2218=== PAUSE TestGlobMatch/*bar_foo2219=== RUN TestGlobMatch/foo*bar_foobar2220=== PAUSE TestGlobMatch/foo*bar_foobar2221=== RUN TestGlobMatch/foo*bar_foo123bar2222=== PAUSE TestGlobMatch/foo*bar_foo123bar2223=== RUN TestGlobMatch/foo*bar_foobarbaz2224=== PAUSE TestGlobMatch/foo*bar_foobarbaz2225=== RUN TestGlobMatch/*/*_foo/bar2226=== PAUSE TestGlobMatch/*/*_foo/bar2227=== RUN TestGlobMatch/*/*_foo2228=== PAUSE TestGlobMatch/*/*_foo2229=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2230=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2231=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02232=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02233=== RUN TestGlobMatch/refs/*/main_refs/heads/main2234=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2235=== RUN TestGlobMatch/fo?_foo2236=== PAUSE TestGlobMatch/fo?_foo2237=== RUN TestGlobMatch/fo?_fo2238=== PAUSE TestGlobMatch/fo?_fo2239=== RUN TestGlobMatch/fo?_fooo2240=== PAUSE TestGlobMatch/fo?_fooo2241=== RUN TestGlobMatch/?oo_foo2242=== PAUSE TestGlobMatch/?oo_foo2243=== RUN TestGlobMatch/?oo_boo2244=== PAUSE TestGlobMatch/?oo_boo2245=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2246=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2247=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2248=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2249=== CONT TestGlobMatch/foo_foo2250=== CONT TestPins_ConfigValidation2251=== CONT TestGlobMatch/*/*_foo/bar2252=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2253=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2254=== CONT TestGlobMatch/?oo_boo2255=== CONT TestGlobMatch/?oo_foo2256=== CONT TestGlobMatch/fo?_fooo2257=== CONT TestGlobMatch/fo?_fo2258=== CONT TestGlobMatch/fo?_foo2259=== CONT TestGlobMatch/refs/*/main_refs/heads/main2260=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02261=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2262=== CONT TestGlobMatch/*/*_foo2263=== CONT TestGlobMatch/*bar_bar2264=== CONT TestGlobMatch/foo*bar_foobarbaz2265=== CONT TestGlobMatch/foo*bar_foo123bar2266=== CONT TestGlobMatch/foo*bar_foobar2267=== CONT TestGlobMatch/*bar_foobar2268=== CONT TestGlobMatch/foo*_foo2269=== CONT TestGlobMatch/foo*_bar2270=== CONT TestGlobMatch/foo*_foobar2271=== CONT TestGlobMatch/*_2272=== CONT TestGlobMatch/*_anything2273=== CONT TestGlobMatch/foo_bar2274=== CONT TestGlobMatch/*bar_foo2275--- PASS: TestGlobMatch (0.00s)2276 --- PASS: TestGlobMatch/foo_foo (0.00s)2277 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2278 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2279 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2280 --- PASS: TestGlobMatch/?oo_boo (0.00s)2281 --- PASS: TestGlobMatch/?oo_foo (0.00s)2282 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2283 --- PASS: TestGlobMatch/fo?_fo (0.00s)2284 --- PASS: TestGlobMatch/fo?_foo (0.00s)2285 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2286 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2287 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2288 --- PASS: TestGlobMatch/*/*_foo (0.00s)2289 --- PASS: TestGlobMatch/*bar_bar (0.00s)2290 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2291 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2292 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2293 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2294 --- PASS: TestGlobMatch/foo*_foo (0.00s)2295 --- PASS: TestGlobMatch/foo*_bar (0.00s)2296 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2297 --- PASS: TestGlobMatch/*_ (0.00s)2298 --- PASS: TestGlobMatch/*_anything (0.00s)2299 --- PASS: TestGlobMatch/foo_bar (0.00s)2300 --- PASS: TestGlobMatch/*bar_foo (0.00s)2301=== CONT TestScopes_ConfigValidation2302--- PASS: TestPins_ConfigValidation (0.00s)2303=== CONT TestScopes_Rules2304--- PASS: TestScopes_ConfigValidation (0.00s)2305=== CONT TestScopes_LegacyProviderDefaultsToWrite2306=== CONT TestValidateToken_MultipleProviders2307=== CONT TestValidateToken_NoMatchingProvider2308=== CONT TestPins_ReservedForMatchingRule2309=== CONT TestPins_TopLevelShorthand2310=== CONT TestValidateToken_BoundSubjectMismatch2311=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2312=== CONT TestValidateToken_BoundClaimsMismatch23132026/10/14 16:45:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58832/oidc23142026/10/14 16:45:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58831/oidc23152026/10/14 16:45:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58833/oidc2316--- PASS: TestValidateToken_ValidToken (0.08s)23172026/10/14 16:45:44 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:588342318--- PASS: TestScopes_Rules (0.08s)23192026/10/14 16:45:44 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232320--- PASS: TestValidateToken_Expired (0.09s)2321--- PASS: TestValidateToken_KubernetesServiceAccount (0.09s)23222026/10/14 16:45:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58841/oidc2323--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.08s)2324--- PASS: TestPins_TopLevelShorthand (0.08s)23252026/10/14 16:45:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58844/oidc2326--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.09s)23272026/10/14 16:45:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58846/oidc2328--- PASS: TestValidateToken_BoundSubjectMismatch (0.10s)23292026/10/14 16:45:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58850/oidc23302026/10/14 16:45:44 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:58830/oidc2331--- PASS: TestPins_ReservedForMatchingRule (0.12s)23322026/10/14 16:45:44 http: TLS handshake error from 127.0.0.1:58849: read tcp 127.0.0.1:58848->127.0.0.1:58849: use of closed network connection2333--- PASS: TestNewValidator_KubernetesRequiresCA (0.13s)2334--- PASS: TestValidateToken_NoMatchingProvider (0.12s)23352026/10/14 16:45:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58855/oidc2336--- PASS: TestValidateToken_WrongAudience (0.14s)23372026/10/14 16:45:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58858/oidc2338--- PASS: TestValidateToken_BoundClaimsMismatch (0.18s)23392026/10/14 16:45:44 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:58860/oidc23402026/10/14 16:45:44 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:58857/oidc2341--- PASS: TestValidateToken_MultipleProviders (0.20s)2342PASS2343Running hook tests...2344=== RUN TestSendPathsEmpty2345=== PAUSE TestSendPathsEmpty2346=== RUN TestQueueEnqueueAndFetch2347=== PAUSE TestQueueEnqueueAndFetch2348=== RUN TestQueueDeduplication2349=== PAUSE TestQueueDeduplication2350=== RUN TestQueueRemove2351=== PAUSE TestQueueRemove2352=== RUN TestQueueFetchBatchLimit2353=== PAUSE TestQueueFetchBatchLimit2354=== RUN TestQueueRetryMovesToBack2355=== PAUSE TestQueueRetryMovesToBack2356=== RUN TestQueueFetchRemoveLifecycle2357=== PAUSE TestQueueFetchRemoveLifecycle2358=== RUN TestQueueConcurrentWriters2359=== PAUSE TestQueueConcurrentWriters2360=== RUN TestQueueRemoveLargeClosure2361=== PAUSE TestQueueRemoveLargeClosure2362=== RUN TestServerClientIntegration2363--- PASS: TestServerClientIntegration (0.00s)2364=== RUN TestServerQueueError23652026/10/14 16:45:44 ERROR Failed to queue paths error="permission denied" count=12366--- PASS: TestServerQueueError (0.00s)2367=== RUN TestGetListenerSocketActivation2368 server_test.go:146: systemd socket activation does not exist on darwin2369--- SKIP: TestGetListenerSocketActivation (0.00s)2370=== RUN TestDrainIsolatesPoisonPath2371=== PAUSE TestDrainIsolatesPoisonPath2372=== RUN TestRunNotBlockedByPoisonHead2373=== PAUSE TestRunNotBlockedByPoisonHead2374=== RUN TestDrainGivesUpWhenServerDown2375=== PAUSE TestDrainGivesUpWhenServerDown2376=== RUN TestFailedPathPrunedByLaterClosure2377=== PAUSE TestFailedPathPrunedByLaterClosure2378=== RUN TestWorkerUploadsAndRemoves2379=== PAUSE TestWorkerUploadsAndRemoves2380=== RUN TestWorkerSkipsGCdPaths2381=== PAUSE TestWorkerSkipsGCdPaths2382=== RUN TestWorkerPrunesClosureDeps2383=== PAUSE TestWorkerPrunesClosureDeps2384=== RUN TestDrainTimeout2385=== PAUSE TestDrainTimeout2386=== CONT TestSendPathsEmpty2387=== CONT TestDrainTimeout2388--- PASS: TestSendPathsEmpty (0.00s)2389=== CONT TestDrainIsolatesPoisonPath2390=== CONT TestQueueRemoveLargeClosure2391=== CONT TestQueueConcurrentWriters2392=== CONT TestQueueFetchRemoveLifecycle2393=== CONT TestWorkerUploadsAndRemoves2394=== CONT TestWorkerPrunesClosureDeps2395=== CONT TestQueueRetryMovesToBack2396=== CONT TestWorkerSkipsGCdPaths2397=== CONT TestQueueFetchBatchLimit2398=== CONT TestQueueDeduplication2399=== CONT TestQueueEnqueueAndFetch2400=== CONT TestQueueRemove2401=== CONT TestDrainGivesUpWhenServerDown2402=== CONT TestRunNotBlockedByPoisonHead2403=== CONT TestFailedPathPrunedByLaterClosure24042026/10/14 16:45:44 INFO Uploading batch count=124052026/10/14 16:45:44 ERROR Upload failed error="upload failed" count=12406--- PASS: TestQueueFetchBatchLimit (0.01s)24072026/10/14 16:45:44 INFO Upload queue status pending=224082026/10/14 16:45:44 INFO Uploading batch count=124092026/10/14 16:45:44 INFO Uploading batch count=424102026/10/14 16:45:44 ERROR Upload failed error="upload failed" count=424112026/10/14 16:45:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestDrainIsolatesPoisonPath4291237134/002/bbb2412--- PASS: TestQueueEnqueueAndFetch (0.01s)24132026/10/14 16:45:44 INFO Upload queue status pending=224142026/10/14 16:45:44 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestWorkerSkipsGCdPaths361233836/002/nonexistent2415--- PASS: TestQueueDeduplication (0.01s)24162026/10/14 16:45:44 INFO Upload queue status pending=224172026/10/14 16:45:44 INFO Uploading batch count=124182026/10/14 16:45:44 INFO Uploading batch count=224192026/10/14 16:45:44 INFO Uploading batch count=12420--- PASS: TestQueueRemove (0.01s)24212026/10/14 16:45:44 INFO Uploading batch count=224222026/10/14 16:45:44 INFO Uploading batch count=124232026/10/14 16:45:44 INFO Upload queue status pending=324242026/10/14 16:45:44 INFO Uploading batch count=12425--- PASS: TestQueueRetryMovesToBack (0.01s)24262026/10/14 16:45:44 INFO Uploading batch count=224272026/10/14 16:45:44 ERROR Upload failed error="upload failed" count=124282026/10/14 16:45:44 ERROR Upload failed error="upload failed" count=224292026/10/14 16:45:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestDrainGivesUpWhenServerDown1824585891/002/a24302026/10/14 16:45:44 INFO Uploading batch count=124312026/10/14 16:45:44 ERROR Upload failed error="upload failed" count=12432--- PASS: TestQueueFetchRemoveLifecycle (0.02s)24332026/10/14 16:45:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestDrainGivesUpWhenServerDown1824585891/002/b24342026/10/14 16:45:44 INFO Uploading batch count=124352026/10/14 16:45:44 ERROR Upload failed error="upload failed" count=124362026/10/14 16:45:44 INFO Uploading batch count=224372026/10/14 16:45:44 ERROR Upload failed error="upload failed" count=224382026/10/14 16:45:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestDrainGivesUpWhenServerDown1824585891/002/c24392026/10/14 16:45:44 INFO Uploading batch count=124402026/10/14 16:45:44 ERROR Upload failed error="upload failed" count=124412026/10/14 16:45:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestDrainGivesUpWhenServerDown1824585891/002/d24422026/10/14 16:45:44 ERROR Drain finished with paths left in queue remaining=12443--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)24442026/10/14 16:45:44 INFO Uploading batch count=224452026/10/14 16:45:44 ERROR Upload failed error="upload failed" count=224462026/10/14 16:45:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestDrainGivesUpWhenServerDown1824585891/002/e24472026/10/14 16:45:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestDrainGivesUpWhenServerDown1824585891/002/f24482026/10/14 16:45:44 ERROR Drain finished with paths left in queue remaining=102449--- PASS: TestDrainIsolatesPoisonPath (0.02s)2450--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2451--- PASS: TestWorkerPrunesClosureDeps (0.03s)2452--- PASS: TestWorkerSkipsGCdPaths (0.03s)2453--- PASS: TestWorkerUploadsAndRemoves (0.03s)2454--- PASS: TestQueueRemoveLargeClosure (0.05s)2455--- PASS: TestQueueConcurrentWriters (0.13s)24562026/10/14 16:45:44 ERROR Upload failed error="context deadline exceeded" count=224572026/10/14 16:45:44 ERROR Drain finished with paths left in queue remaining=42458--- PASS: TestDrainTimeout (0.22s)24592026/10/14 16:45:45 INFO Uploading batch count=124602026/10/14 16:45:45 INFO Uploading batch count=124612026/10/14 16:45:45 INFO Uploading batch count=124622026/10/14 16:45:45 ERROR Upload failed error="upload failed" count=124632026/10/14 16:45:45 INFO Uploading batch count=124642026/10/14 16:45:45 ERROR Upload failed error="upload failed" count=124652026/10/14 16:45:45 INFO Uploading batch count=124662026/10/14 16:45:45 ERROR Upload failed error="upload failed" count=124672026/10/14 16:45:45 INFO Uploading batch count=124682026/10/14 16:45:45 ERROR Upload failed error="upload failed" count=124692026/10/14 16:45:45 ERROR Drain finished with paths left in queue remaining=12470--- PASS: TestRunNotBlockedByPoisonHead (1.02s)2471PASS2472Running signing tests...2473=== RUN TestExternalSigner2474=== PAUSE TestExternalSigner2475=== RUN TestExternalSignerWrongPublicKey2476=== PAUSE TestExternalSignerWrongPublicKey2477=== RUN TestExternalSignerErrors2478=== PAUSE TestExternalSignerErrors2479=== RUN TestExternalSignerRestartsAfterCrash2480=== PAUSE TestExternalSignerRestartsAfterCrash2481=== RUN TestExternalSignerProgramErrorKeepsProcess2482=== PAUSE TestExternalSignerProgramErrorKeepsProcess2483=== RUN TestExternalSignerClose2484=== PAUSE TestExternalSignerClose2485=== RUN TestExternalSignerRejectsInvalidPublicKey2486=== PAUSE TestExternalSignerRejectsInvalidPublicKey2487=== RUN TestExternalSignerCancellation2488=== PAUSE TestExternalSignerCancellation2489=== RUN TestGenerateFingerprint2490=== PAUSE TestGenerateFingerprint2491=== RUN TestParseSigningKey2492=== PAUSE TestParseSigningKey2493=== RUN TestSign2494=== PAUSE TestSign2495=== RUN TestSignBatch2496=== PAUSE TestSignBatch2497=== RUN TestNilKeyPublicKey2498=== PAUSE TestNilKeyPublicKey2499=== RUN TestSignErrors2500=== PAUSE TestSignErrors2501=== CONT TestExternalSigner2502=== CONT TestExternalSignerProgramErrorKeepsProcess2503=== CONT TestExternalSignerCancellation2504=== CONT TestSignBatch2505=== CONT TestSign2506=== CONT TestParseSigningKey2507=== RUN TestParseSigningKey/valid_32-byte_key2508=== PAUSE TestParseSigningKey/valid_32-byte_key2509=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2510=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2511=== CONT TestGenerateFingerprint2512=== RUN TestGenerateFingerprint/basic_with_references2513=== PAUSE TestGenerateFingerprint/basic_with_references2514=== RUN TestGenerateFingerprint/no_references2515=== CONT TestExternalSignerErrors2516=== CONT TestExternalSignerRestartsAfterCrash2517=== RUN TestExternalSignerErrors/wrong_signatures_shape2518=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2519=== RUN TestExternalSignerErrors/program_error2520=== PAUSE TestExternalSignerErrors/program_error2521=== RUN TestExternalSignerErrors/invalid_JSON2522=== PAUSE TestExternalSignerErrors/invalid_JSON2523=== RUN TestExternalSignerErrors/missing_signatures2524=== CONT TestSignErrors2525=== CONT TestNilKeyPublicKey2526--- PASS: TestNilKeyPublicKey (0.00s)2527=== CONT TestExternalSignerWrongPublicKey2528=== CONT TestExternalSignerRejectsInvalidPublicKey2529=== RUN TestExternalSignerRejectsInvalidPublicKey/#002530=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002531=== CONT TestExternalSignerClose2532=== RUN TestParseSigningKey/no_colon2533=== PAUSE TestParseSigningKey/no_colon2534=== PAUSE TestGenerateFingerprint/no_references2535=== PAUSE TestExternalSignerErrors/missing_signatures2536=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2537=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2538=== RUN TestParseSigningKey/empty_name2539=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2540=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2541=== PAUSE TestParseSigningKey/empty_name2542=== RUN TestExternalSignerErrors/too_few_signatures2543=== PAUSE TestExternalSignerErrors/too_few_signatures2544=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2545=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2546=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2547=== RUN TestParseSigningKey/invalid_base642548=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2549=== PAUSE TestParseSigningKey/invalid_base642550=== RUN TestParseSigningKey/wrong_length2551=== RUN TestExternalSignerErrors/wrong_id2552=== PAUSE TestExternalSignerErrors/wrong_id2553=== RUN TestExternalSignerErrors/null_signatures2554=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2555=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2556=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2557=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2558=== CONT TestExternalSignerRejectsInvalidPublicKey/#002559=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2560=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2561=== PAUSE TestExternalSignerErrors/null_signatures2562=== RUN TestExternalSignerErrors/unrequested_key2563=== PAUSE TestParseSigningKey/wrong_length2564=== PAUSE TestExternalSignerErrors/unrequested_key2565=== RUN TestExternalSignerErrors/exit_at_startup2566=== CONT TestParseSigningKey/valid_32-byte_key2567=== PAUSE TestExternalSignerErrors/exit_at_startup2568=== RUN TestExternalSignerErrors/exit_on_request2569=== CONT TestParseSigningKey/invalid_base642570=== RUN TestGenerateFingerprint/invalid_nar_hash_length2571=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2572=== RUN TestGenerateFingerprint/invalid_store_path_prefix2573=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2574=== RUN TestGenerateFingerprint/invalid_reference_prefix2575=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2576=== CONT TestGenerateFingerprint/basic_with_references2577=== CONT TestParseSigningKey/empty_name2578=== CONT TestParseSigningKey/no_colon2579=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2580=== PAUSE TestExternalSignerErrors/exit_on_request2581=== RUN TestExternalSignerErrors/null2582=== PAUSE TestExternalSignerErrors/null2583=== RUN TestExternalSignerErrors/missing_signature_name2584=== PAUSE TestExternalSignerErrors/missing_signature_name2585=== RUN TestExternalSignerErrors/wrong_signature_name2586=== PAUSE TestExternalSignerErrors/wrong_signature_name2587=== RUN TestExternalSignerErrors/invalid_signature_base642588=== PAUSE TestExternalSignerErrors/invalid_signature_base642589=== RUN TestExternalSignerErrors/wrong_signature_length2590=== PAUSE TestExternalSignerErrors/wrong_signature_length2591=== RUN TestExternalSignerErrors/wrong_shape2592=== PAUSE TestExternalSignerErrors/wrong_shape2593=== CONT TestGenerateFingerprint/invalid_store_path_prefix2594=== CONT TestExternalSignerErrors/exit_on_request2595=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2596=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2597=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2598=== CONT TestExternalSignerErrors/missing_signature_name2599=== CONT TestParseSigningKey/wrong_length2600=== CONT TestExternalSignerErrors/exit_at_startup2601=== CONT TestExternalSignerErrors/wrong_id2602=== CONT TestGenerateFingerprint/invalid_nar_hash_length2603=== CONT TestExternalSignerErrors/unrequested_key2604=== CONT TestExternalSignerErrors/null2605=== CONT TestExternalSignerErrors/wrong_signatures_shape2606--- PASS: TestSign (0.00s)2607=== RUN TestSignErrors/nil_key2608=== PAUSE TestSignErrors/nil_key2609=== RUN TestSignErrors/nil_narinfo2610=== CONT TestGenerateFingerprint/invalid_reference_prefix2611=== CONT TestExternalSignerErrors/missing_signatures2612--- PASS: TestParseSigningKey (0.00s)2613 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2614 --- PASS: TestParseSigningKey/empty_name (0.00s)2615 --- PASS: TestParseSigningKey/no_colon (0.00s)2616 --- PASS: TestParseSigningKey/wrong_length (0.00s)2617 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2618 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2619=== CONT TestExternalSignerErrors/too_few_signatures2620--- PASS: TestSignBatch (0.00s)2621=== CONT TestExternalSignerErrors/invalid_JSON2622=== CONT TestGenerateFingerprint/no_references2623--- PASS: TestGenerateFingerprint (0.00s)2624 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2625 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2626 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2627 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2628 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2629 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2630 --- PASS: TestGenerateFingerprint/no_references (0.00s)2631=== CONT TestExternalSignerErrors/program_error2632=== PAUSE TestSignErrors/nil_narinfo2633=== RUN TestSignErrors/invalid_narinfo2634=== CONT TestExternalSignerErrors/wrong_signature_length2635=== CONT TestExternalSignerErrors/invalid_signature_base642636=== CONT TestExternalSignerErrors/wrong_signature_name2637=== CONT TestExternalSignerErrors/null_signatures2638=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2639--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2640 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2641 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2642 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2643 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2644 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2645=== CONT TestExternalSignerErrors/wrong_shape2646=== PAUSE TestSignErrors/invalid_narinfo2647=== RUN TestSignErrors/canceled2648=== PAUSE TestSignErrors/canceled2649=== CONT TestSignErrors/nil_key2650=== CONT TestSignErrors/canceled2651=== CONT TestSignErrors/invalid_narinfo2652=== CONT TestSignErrors/nil_narinfo2653--- PASS: TestSignErrors (0.00s)2654 --- PASS: TestSignErrors/nil_key (0.00s)2655 --- PASS: TestSignErrors/canceled (0.00s)2656 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2657 --- PASS: TestSignErrors/nil_narinfo (0.00s)2658--- PASS: TestExternalSigner (0.11s)2659--- PASS: TestExternalSignerCancellation (0.20s)2660--- PASS: TestExternalSignerClose (0.81s)2661--- PASS: TestExternalSignerWrongPublicKey (0.89s)2662--- PASS: TestExternalSignerRestartsAfterCrash (0.98s)2663/private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestExternalSignerRestartsAfterCrash2744794847/001/sign program: line 7: /private/var/tb/2/scratch/87fbd2159ad6a6e3/build/TestExternalSignerRestartsAfterCrash2744794847/001/sign program.starts: No such file or directory2664--- PASS: TestExternalSignerProgramErrorKeepsProcess (1.04s)2665--- PASS: TestExternalSignerErrors (0.00s)2666 --- PASS: TestExternalSignerErrors/program_error (0.25s)2667 --- PASS: TestExternalSignerErrors/too_few_signatures (0.33s)2668 --- PASS: TestExternalSignerErrors/exit_at_startup (0.40s)2669 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.48s)2670 --- PASS: TestExternalSignerErrors/wrong_id (0.56s)2671 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.64s)2672 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.73s)2673 --- PASS: TestExternalSignerErrors/unrequested_key (1.12s)2674 --- PASS: TestExternalSignerErrors/invalid_JSON (1.19s)2675 --- PASS: TestExternalSignerErrors/exit_on_request (1.28s)2676 --- PASS: TestExternalSignerErrors/null_signatures (1.35s)2677 --- PASS: TestExternalSignerErrors/null (1.43s)2678 --- PASS: TestExternalSignerErrors/wrong_signature_name (1.50s)2679 --- PASS: TestExternalSignerErrors/missing_signature_name (1.58s)2680 --- PASS: TestExternalSignerErrors/missing_signatures (1.66s)2681 --- PASS: TestExternalSignerErrors/wrong_shape (1.74s)2682PASS2683Running OpenBao signer tests...2684=== RUN TestSign2685=== PAUSE TestSign2686=== RUN TestSignErrors2687=== PAUSE TestSignErrors2688=== RUN TestServe2689=== PAUSE TestServe2690=== RUN TestServeRejectsGarbage2691=== PAUSE TestServeRejectsGarbage2692=== CONT TestSign2693=== CONT TestServe2694=== CONT TestSignErrors2695=== RUN TestSignErrors/http_error2696=== CONT TestServeRejectsGarbage2697=== PAUSE TestSignErrors/http_error2698=== RUN TestSignErrors/invalid_json2699=== PAUSE TestSignErrors/invalid_json2700--- PASS: TestServeRejectsGarbage (0.00s)2701=== RUN TestSignErrors/no_prefix2702=== PAUSE TestSignErrors/no_prefix2703=== RUN TestSignErrors/invalid_base642704=== PAUSE TestSignErrors/invalid_base642705=== CONT TestSignErrors/http_error2706=== CONT TestSignErrors/no_prefix2707=== CONT TestSignErrors/invalid_base642708=== CONT TestSignErrors/invalid_json2709--- PASS: TestServe (0.00s)2710--- PASS: TestSign (0.00s)2711--- PASS: TestSignErrors (0.00s)2712 --- PASS: TestSignErrors/http_error (0.00s)2713 --- PASS: TestSignErrors/no_prefix (0.00s)2714 --- PASS: TestSignErrors/invalid_json (0.00s)2715 --- PASS: TestSignErrors/invalid_base64 (0.00s)2716PASS