niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #413
· 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.20s)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 TestSetClientTLSDoesNotMutateDefaultTransport115=== CONT TestScriptTokenNoExpiryRerunsEveryCall116=== CONT TestScriptTokenEmptyCommand117--- PASS: TestScriptTokenEmptyCommand (0.00s)118=== CONT TestClientSignaturesByStorePath119=== CONT TestScriptTokenScriptFails120=== CONT TestScriptTokenBadJSON121=== CONT TestScriptTokenEmptyToken122=== CONT TestScriptTokenCachesUntilRefresh123=== CONT TestDumpPathMatchesNix124=== CONT TestParsePathInfoJSONMultiplePaths125=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths126=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths127=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths128=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths129=== CONT TestStreamPushReportsSignatures130=== CONT TestParsePathInfoJSON131=== RUN TestParsePathInfoJSON/Nix_format132=== PAUSE TestParsePathInfoJSON/Nix_format133=== CONT TestPathInfoHashCompatibility134=== CONT TestConvertHashToNix32135=== CONT TestEncodeNixBase32WithRealHash136=== CONT TestEncodeNixBase32137=== CONT TestDumpPathWriterError138=== CONT TestDumpPathSingleFile139=== CONT TestFileTokenReadsAndCaches140=== CONT TestFileTokenEmpty141=== CONT TestFileTokenMissing142=== CONT TestPathInfoCACompatibility143=== CONT TestSetClientTLS144=== CONT TestStreamPushStopsWhenCanceled145--- PASS: TestClientSignaturesByStorePath (0.00s)146=== CONT TestStreamPushReportsSkippedPaths147=== CONT TestGetStorePathHash148=== RUN TestParsePathInfoJSON/Lix_format149=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)150=== RUN TestConvertHashToNix32/SRI_format_to_Nix32151--- PASS: TestEncodeNixBase32WithRealHash (0.00s)152=== CONT TestStreamPushRequestLine153=== RUN TestEncodeNixBase32/test_string_hash154=== PAUSE TestEncodeNixBase32/test_string_hash155=== RUN TestEncodeNixBase32/empty_input156=== PAUSE TestEncodeNixBase32/empty_input157=== CONT TestStreamPushGivesUpOnDeadServer158=== RUN TestPathInfoCACompatibility/null_ca_field159=== PAUSE TestPathInfoCACompatibility/null_ca_field160=== RUN TestPathInfoCACompatibility/old_string_format_-_text161=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text162=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive163=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive164--- PASS: TestStreamPushStopsWhenCanceled (0.00s)165--- PASS: TestFileTokenMissing (0.00s)166=== CONT TestStreamPushIsolatesFailures167=== CONT TestStreamPushBatchesUnderLoad168--- PASS: TestFileTokenReadsAndCaches (0.00s)169=== CONT TestStreamPushReportsEveryPath170--- PASS: TestStreamPushReportsEveryPath (0.00s)171=== CONT TestShellSplitErrors172--- PASS: TestFileTokenEmpty (0.00s)173=== CONT TestShellSplit174--- PASS: TestShellSplit (0.00s)175=== CONT TestDoWithRetry_FinalResponseBodyReadable176=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix321772026/10/14 16:41:54 ERROR Upload failed error=boom count=1178=== RUN TestPathInfoCACompatibility/new_structured_format_-_text179--- PASS: TestStreamPushReportsSignatures (0.01s)180=== CONT TestFilterOversizedClosures181=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)182=== PAUSE TestParsePathInfoJSON/Lix_format1832026/10/14 16:41:54 ERROR Upload failed error=boom count=11842026/10/14 16:41:54 ERROR Upload failed error="connection refused" count=201852026/10/14 16:41:54 ERROR Server seems unavailable, giving up on batch untried=17186--- PASS: TestStreamPushReportsSkippedPaths (0.00s)187=== CONT TestSupersededNARStillUploadsListing188=== RUN TestSupersededNARStillUploadsListing/small_NAR189=== PAUSE TestSupersededNARStillUploadsListing/small_NAR190=== RUN TestSupersededNARStillUploadsListing/dump_cut_short191=== RUN TestGetStorePathHash/valid_store_path192--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)1932026/10/14 16:41:54 ERROR Upload failed error="bad path" count=3194=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short195=== CONT TestUploadMultipart_SupersededByPeer196=== CONT TestRetryTimeoutOutlastsMaxRetries197--- PASS: TestShellSplitErrors (0.00s)198--- PASS: TestStreamPushIsolatesFailures (0.00s)199=== CONT TestDoWithRetry_BodyReplayedViaGetBody200=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon201--- PASS: TestScriptTokenScriptFails (0.01s)202=== CONT TestResolveStorePath203=== PAUSE TestGetStorePathHash/valid_store_path204=== RUN TestGetStorePathHash/basename_without_hyphen_should_error205=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon206=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error207=== RUN TestParsePathInfoJSON/empty_input208=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI209=== PAUSE TestParsePathInfoJSON/empty_input210=== RUN TestConvertHashToNix32/already_Nix32_format211=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI212=== PAUSE TestConvertHashToNix32/already_Nix32_format213=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails214=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails215=== RUN TestFilterOversizedClosures/no_limit_keeps_everything216=== RUN TestUploadMultipart_SupersededByPeer/exists217=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text218--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)219=== PAUSE TestUploadMultipart_SupersededByPeer/exists220=== RUN TestUploadMultipart_SupersededByPeer/missing221=== PAUSE TestUploadMultipart_SupersededByPeer/missing222=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess2232026/10/14 16:41:54 WARN Rate limiter enabled after throttle name=server-test rate=5224=== CONT TestRateLimiterFeedback225=== RUN TestRateLimiterFeedback/429_enables_limiter226=== PAUSE TestRateLimiterFeedback/429_enables_limiter227=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything228=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped229=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error230=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped231=== RUN TestFilterOversizedClosures/all_closures_skipped232=== PAUSE TestFilterOversizedClosures/all_closures_skipped233=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error234=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error235=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error236=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica237=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer238--- PASS: TestResolveStorePath (0.00s)239=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun240=== CONT TestCaseHackSuffix241=== RUN TestSetClientTLS/rejects_connection_without_client_cert242=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert243=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA244=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA245=== RUN TestSetClientTLS/preserves_debug_logging_transport246=== PAUSE TestSetClientTLS/preserves_debug_logging_transport247=== CONT TestPartSizeForNAR248=== RUN TestPartSizeForNAR/zero_stays_at_minimum249--- PASS: TestDoServerRequestAttachesToken (0.01s)250=== CONT TestUploadMultipart_PartsInParallel251=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum252=== RUN TestPartSizeForNAR/small_stays_at_minimum253=== RUN TestConvertHashToNix32/invalid_format254=== RUN TestParsePathInfoJSON/whitespace_only255=== RUN TestRateLimiterFeedback/503_enables_limiter2562026/10/14 16:41:54 INFO Garbage collection started257=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512258=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method259=== PAUSE TestPartSizeForNAR/small_stays_at_minimum260=== PAUSE TestParsePathInfoJSON/whitespace_only261=== RUN TestParsePathInfoJSON/invalid_JSON262=== PAUSE TestConvertHashToNix32/invalid_format263=== CONT TestRegisterUploadedObjectReusesConnections264=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum265=== PAUSE TestRateLimiterFeedback/503_enables_limiter266=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter267=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter268=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter269=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter270=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry271=== PAUSE TestParsePathInfoJSON/invalid_JSON272=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum273=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512274=== CONT TestStaticToken275--- PASS: TestStaticToken (0.00s)2762026/10/14 16:41:54 WARN Rate limiter enabled after throttle name=server-test rate=52772026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:57468278=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths279=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method280=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths281--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)282 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)283 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)284=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts285=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts286=== RUN TestPartSizeForNAR/1_TiB287=== PAUSE TestPartSizeForNAR/1_TiB288=== RUN TestPartSizeForNAR/5_TiB_S3_max_object289=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object290=== RUN TestPartSizeForNAR/capped_at_5_GiB291=== PAUSE TestPartSizeForNAR/capped_at_5_GiB292=== CONT TestEncodeNixBase32/test_string_hash293=== CONT TestEncodeNixBase32/empty_input294--- PASS: TestEncodeNixBase32 (0.00s)295 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)296 --- PASS: TestEncodeNixBase32/empty_input (0.00s)297=== CONT TestSetClientTLSErrors298=== CONT TestSupersededNARStillUploadsListing/small_NAR299--- PASS: TestScriptTokenEmptyToken (0.02s)300=== CONT TestUploadMultipart_SupersededByPeer/exists301=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails302=== CONT TestSupersededNARStillUploadsListing/dump_cut_short3032026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:574783042026/10/14 16:41:54 INFO Uploading abc-hello (1.0GB)305=== RUN TestSetClientTLSErrors/missing_cert_file3062026/10/14 16:41:54 WARN Rate limiter backed off name=server-test rate=53072026/10/14 16:41:54 INFO Uploading abc-hello (1.0GB)308=== PAUSE TestSetClientTLSErrors/missing_cert_file309=== RUN TestSetClientTLSErrors/missing_key_file310=== PAUSE TestSetClientTLSErrors/missing_key_file311=== RUN TestSetClientTLSErrors/missing_ca_file312=== PAUSE TestSetClientTLSErrors/missing_ca_file313=== RUN TestSetClientTLSErrors/invalid_ca_file314=== PAUSE TestSetClientTLSErrors/invalid_ca_file315--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)316=== CONT TestUploadMultipart_SupersededByPeer/missing317=== CONT TestFilterOversizedClosures/no_limit_keeps_everything318=== CONT TestGetStorePathHash/valid_store_path319=== CONT TestFilterOversizedClosures/all_closures_skipped3202026/10/14 16:41:54 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=50321=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3222026/10/14 16:41:54 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=2000323--- PASS: TestFilterOversizedClosures (0.00s)324 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)325 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)326 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)327=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error328=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error329=== CONT TestGetStorePathHash/basename_without_hyphen_should_error330--- PASS: TestGetStorePathHash (0.00s)331 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)332 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)333 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)334 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)335=== CONT TestSetClientTLS/rejects_connection_without_client_cert3362026/10/14 16:41:54 INFO Garbage collection started337--- PASS: TestScriptTokenBadJSON (0.02s)338=== CONT TestSetClientTLS/preserves_debug_logging_transport3392026/10/14 16:41:54 WARN Rate limiter enabled after throttle name=server-test rate=53402026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:574763412026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:574783422026/10/14 16:41:54 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=0343--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.02s)344=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3452026/10/14 16:41:54 WARN Garbage collection finished on another replica. Its statistics are not available here3462026/10/14 16:41:54 WARN Rate limiter enabled after throttle name=s3-test rate=53472026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:575563482026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:574783492026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:57478350--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)351=== CONT TestConvertHashToNix32/SRI_format_to_Nix32352=== CONT TestConvertHashToNix32/invalid_format353=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter354--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)355 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)356 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)357=== CONT TestRateLimiterFeedback/429_enables_limiter358=== CONT TestConvertHashToNix32/already_Nix32_format359--- PASS: TestConvertHashToNix32 (0.01s)360 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)361 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)362 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)363=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter3642026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:57478365--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.01s)366=== CONT TestRateLimiterFeedback/503_enables_limiter367--- PASS: TestStreamPushRequestLine (0.03s)368=== CONT TestParsePathInfoJSON/Nix_format369=== CONT TestParsePathInfoJSON/invalid_JSON370=== CONT TestParsePathInfoJSON/whitespace_only371=== CONT TestParsePathInfoJSON/Lix_format372=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)373=== CONT TestParsePathInfoJSON/empty_input374--- PASS: TestParsePathInfoJSON (0.02s)375 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)376 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)377 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)378 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)379 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)380=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI381=== CONT TestPathInfoCACompatibility/null_ca_field382=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha5123832026/10/14 16:41:54 WARN Rate limiter enabled after throttle name=server-test rate=53842026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:575693852026/10/14 16:41:54 WARN Rate limiter backed off name=server-test rate=53862026/10/14 16:41:54 WARN Rate limiter enabled after throttle name=server-test rate=53872026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:575743882026/10/14 16:41:54 WARN Rate limiter backed off name=server-test rate=53892026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:57478390=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method391=== CONT TestPartSizeForNAR/capped_at_5_GiB392=== CONT TestPathInfoCACompatibility/new_structured_format_-_text393=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon394=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive395=== CONT TestPathInfoCACompatibility/old_string_format_-_text396=== CONT TestPartSizeForNAR/5_TiB_S3_max_object397=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts398=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum399=== CONT TestSetClientTLSErrors/missing_cert_file400=== CONT TestSetClientTLSErrors/invalid_ca_file401=== CONT TestSetClientTLSErrors/missing_ca_file402=== CONT TestSetClientTLSErrors/missing_key_file403=== CONT TestPartSizeForNAR/zero_stays_at_minimum404=== CONT TestPartSizeForNAR/small_stays_at_minimum405--- PASS: TestRateLimiterFeedback (0.01s)406 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)407 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)408 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)409 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)410=== CONT TestPartSizeForNAR/1_TiB411--- PASS: TestPathInfoCACompatibility (0.02s)412 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)413 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)414 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)415 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)416 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)417--- PASS: TestPathInfoHashCompatibility (0.02s)418 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)419 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)420 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)421 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)422--- PASS: TestPartSizeForNAR (0.01s)423 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)424 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)425 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)426 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)427 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)428 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)429 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)430--- PASS: TestSetClientTLSErrors (0.00s)431 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)432 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)433 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)434 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)4352026/10/14 16:41:54 WARN Rate limiter backed off name=server-test rate=54362026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:57476437--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.03s)4382026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:574784392026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:574784402026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:574784412026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:574784422026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:574784432026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:574784442026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:57478445--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)4462026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:574784472026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:574784482026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:574784492026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:574784502026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:574784512026/10/14 16:41:54 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:57478452--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.06s)453--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)4542026/10/14 16:41:54 http: TLS handshake error from 127.0.0.1:57561: remote error: tls: bad certificate455--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.05s)456--- PASS: TestSetClientTLS (0.01s)457 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)458 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)459 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.03s)460--- PASS: TestDumpPathSingleFile (0.07s)461--- PASS: TestCaseHackSuffix (0.06s)462--- PASS: TestDumpPathWriterError (0.07s)4632026/10/14 16:41:54 INFO Uploading abc-hello (1.0GB)4642026/10/14 16:41:54 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:57553/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:57553/part/24652026/10/14 16:41:54 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"466--- PASS: TestDumpPathMatchesNix (0.10s)467--- PASS: TestStreamPushBatchesUnderLoad (0.10s)468--- PASS: TestSupersededNARStillUploadsListing (0.00s)469 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.01s)470 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.01s)471 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.57s)472--- PASS: TestUploadMultipart_PartsInParallel (0.63s)4732026/10/14 16:41:55 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:57481/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:57481/api/uploads/complete4742026/10/14 16:41:55 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4752026/10/14 16:41:55 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:57481/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:57481/api/uploads/complete476--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4772026/10/14 16:41:55 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4782026/10/14 16:41:55 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:57481/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:57481/api/uploads/complete4792026/10/14 16:41:55 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"480--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)481PASS482Running server tests...483The files belonging to this database system will be owned by user "_tribuchetbld4".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/4/scratch/b6d1f66d5f951280/build/postgres2742462831/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/4/scratch/b6d1f66d5f951280/build/postgres2742462831/data -l logfile start5095102026-10-14 16:41:57.131 UTC [11473] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5112026-10-14 16:41:57.131 UTC [11473] LOG: listening on Unix socket "/private/var/tb/4/scratch/b6d1f66d5f951280/build/postgres2742462831/.s.PGSQL.5432"5122026-10-14 16:41:57.133 UTC [11480] LOG: database system was shut down at 2026-10-14 16:41:57 UTC5132026-10-14 16:41:57.134 UTC [11473] LOG: database system is ready to accept connections514/private/var/tb/4/scratch/b6d1f66d5f951280/build/postgres2742462831:5432 - accepting connections515{"timestamp":"2026-10-14T16:41:59.335434Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"81484fc4-06bb-4714-a333-a548a00bb683","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(5)"}516=== RUN TestService_AuthMiddleware517=== PAUSE TestService_AuthMiddleware518=== RUN TestService_AuthMiddleware_MTLSProxyHeader519=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader520=== RUN TestService_AuthMiddleware_MTLSBoundSubjects521=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects522=== RUN TestService_ReadAuthMiddleware523=== PAUSE TestService_ReadAuthMiddleware524=== RUN TestService_AuthMiddleware_OIDC525=== PAUSE TestService_AuthMiddleware_OIDC526=== RUN TestService_RequireScope_OIDC527=== PAUSE TestService_RequireScope_OIDC528=== RUN TestService_ReadScope_PublicByDefault529=== PAUSE TestService_ReadScope_PublicByDefault530=== RUN TestCacheConfigHandler531=== PAUSE TestCacheConfigHandler532=== RUN TestCacheStatsHandler533=== PAUSE TestCacheStatsHandler534=== RUN TestClientCADerivations535=== PAUSE TestClientCADerivations536=== RUN TestClientErrorHandling537=== PAUSE TestClientErrorHandling538=== RUN TestClientIntegration539=== PAUSE TestClientIntegration540=== RUN TestClientMultipleUploads541=== PAUSE TestClientMultipleUploads542=== RUN TestClientWithDependencies543=== PAUSE TestClientWithDependencies544=== RUN TestClientSharedPathCommittedMidPush545=== PAUSE TestClientSharedPathCommittedMidPush546=== RUN TestPinProtectsFromGC547=== PAUSE TestPinProtectsFromGC548=== RUN TestClientPushesUseOnePush549=== PAUSE TestClientPushesUseOnePush550=== RUN TestClientFallsBackToClosures551=== PAUSE TestClientFallsBackToClosures552=== RUN TestDeleteClosuresRacingPins553=== PAUSE TestDeleteClosuresRacingPins554=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock555=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock556=== RUN TestResolveDBConnectionString557=== PAUSE TestResolveDBConnectionString558=== RUN TestConnectWaitsForAPeerMigration559=== PAUSE TestConnectWaitsForAPeerMigration560=== RUN TestLeadElectsOneAndHandsOver561=== PAUSE TestLeadElectsOneAndHandsOver562=== RUN TestLeadIncumbentWinsAfterRestart5632026/10/14 16:41:59 INFO lead: acquired remote=192.0.2.1:12345642026/10/14 16:42:00 INFO lead: released remote=192.0.2.1:12345652026/10/14 16:42:00 INFO lead: acquired remote=192.0.2.1:12345662026/10/14 16:42:01 INFO lead: released remote=192.0.2.1:1234567--- PASS: TestLeadIncumbentWinsAfterRestart (2.16s)568=== RUN TestLeadIncumbentAnnouncesAtOnce569=== PAUSE TestLeadIncumbentAnnouncesAtOnce570=== RUN TestLeadEndsOnShutdown571=== PAUSE TestLeadEndsOnShutdown572=== RUN TestLeadEndsWhenItsConnectionHangs5732026/10/14 16:42:01 INFO lead: acquired remote=192.0.2.1:12345742026-10-14 16:42:02.973 UTC [11517] FATAL: terminating connection due to administrator command5752026/10/14 16:42:03 INFO lead: acquired remote=192.0.2.1:12345762026/10/14 16:42:04 WARN lead: lock connection lost error="timeout: context deadline exceeded"5772026/10/14 16:42:04 INFO lead: released remote=192.0.2.1:12345782026/10/14 16:42:04 INFO lead: released remote=192.0.2.1:1234579--- PASS: TestLeadEndsWhenItsConnectionHangs (2.76s)580=== RUN TestGCAdvisoryLockBlocksConcurrentRun581=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun582=== RUN TestGCBugBareHashReferences583=== PAUSE TestGCBugBareHashReferences584=== RUN TestGCMetrics585=== PAUSE TestGCMetrics586=== RUN TestPushDedupSurvivesConcurrentGC587=== PAUSE TestPushDedupSurvivesConcurrentGC588=== RUN TestDeduplicatedObjectsRecordedAsPending589=== PAUSE TestDeduplicatedObjectsRecordedAsPending590=== RUN TestGCSweepSkipsPendingObjects591=== PAUSE TestGCSweepSkipsPendingObjects592=== RUN TestTombstonedObjectOfferedWithoutWaiting593=== PAUSE TestTombstonedObjectOfferedWithoutWaiting594=== RUN TestGCSweepDeliversEachKeyOnce595=== PAUSE TestGCSweepDeliversEachKeyOnce596=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection597=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection598=== RUN TestForceGCDuringPushOffersSweptObject599=== PAUSE TestForceGCDuringPushOffersSweptObject600=== RUN TestFailedS3DeleteKeepsTombstone601=== PAUSE TestFailedS3DeleteKeepsTombstone602=== RUN TestSweepSkipsRowsLockedByPush603=== PAUSE TestSweepSkipsRowsLockedByPush604=== RUN TestRegisterCompletedObjectNeedsPendingRow605=== PAUSE TestRegisterCompletedObjectNeedsPendingRow606=== RUN TestGetExistingObjectsLocksRows607=== PAUSE TestGetExistingObjectsLocksRows608=== RUN TestSweepRechecksPendingAfterLocking609=== PAUSE TestSweepRechecksPendingAfterLocking610=== RUN TestPushWaitsForSweepHoldingRow611=== PAUSE TestPushWaitsForSweepHoldingRow612=== RUN TestCommitRacingPendingCleanupKeepsObjects613=== PAUSE TestCommitRacingPendingCleanupKeepsObjects614=== RUN TestGCEndsOnShutdown615=== PAUSE TestGCEndsOnShutdown616=== RUN TestGCTaskStore_StartNew617=== PAUSE TestGCTaskStore_StartNew618=== RUN TestGCTaskStore_DeduplicateSameParams619=== PAUSE TestGCTaskStore_DeduplicateSameParams620=== RUN TestGCTaskStore_ConflictDifferentParams621=== PAUSE TestGCTaskStore_ConflictDifferentParams622=== RUN TestGCTaskStore_GetEmpty623=== PAUSE TestGCTaskStore_GetEmpty624=== RUN TestGCTaskStore_GetReturnsLatest625=== PAUSE TestGCTaskStore_GetReturnsLatest626=== RUN TestGCTaskStore_CompletedAllowsNewTask627=== PAUSE TestGCTaskStore_CompletedAllowsNewTask628=== RUN TestGCTaskStore_PhaseUpdates629=== PAUSE TestGCTaskStore_PhaseUpdates630=== RUN TestGCTaskStore_Fail631=== PAUSE TestGCTaskStore_Fail632=== RUN TestGracefulShutdownDrainsInflight633=== PAUSE TestGracefulShutdownDrainsInflight634=== RUN TestService_healthCheckHandler635=== PAUSE TestService_healthCheckHandler636=== RUN TestService_readinessHandler637=== PAUSE TestService_readinessHandler638=== RUN TestGenerateLandingPage639=== PAUSE TestGenerateLandingPage640=== RUN TestCacheConfigHandlerMaxNarSize641=== PAUSE TestCacheConfigHandlerMaxNarSize642=== RUN TestCreatePendingClosureRejectsOversizedNAR643=== PAUSE TestCreatePendingClosureRejectsOversizedNAR644=== RUN TestNARDeduplicationMetadataUploadBug645=== PAUSE TestNARDeduplicationMetadataUploadBug646=== RUN TestMetricsInventory647=== PAUSE TestMetricsInventory648=== RUN TestMetricsCommit649=== PAUSE TestMetricsCommit650=== RUN TestService_NativeMTLS651=== PAUSE TestService_NativeMTLS652=== RUN TestServerTLSConfig653=== PAUSE TestServerTLSConfig654=== RUN TestMultipartCleanup655=== PAUSE TestMultipartCleanup656=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded657=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded658=== RUN TestPendingCleanupUsesOneCutoff659=== PAUSE TestPendingCleanupUsesOneCutoff660=== RUN TestObjectStatsTrigger661=== PAUSE TestObjectStatsTrigger662=== RUN TestObjectStatsLargeCommit663=== PAUSE TestObjectStatsLargeCommit664=== RUN TestOrphanedObjectsGC665=== PAUSE TestOrphanedObjectsGC666=== RUN TestOrphanedObjectsGCStressTest667=== PAUSE TestOrphanedObjectsGCStressTest668=== RUN TestCreatePin_ReservedPins669=== PAUSE TestCreatePin_ReservedPins670=== RUN TestPresentReportsOnlyClosureRoots671=== PAUSE TestPresentReportsOnlyClosureRoots672=== RUN TestPresentRefreshesOnlyStaleClosures673=== PAUSE TestPresentRefreshesOnlyStaleClosures674=== RUN TestPresentNotReportedWhileGCDeletesClosure675=== PAUSE TestPresentNotReportedWhileGCDeletesClosure676=== RUN TestParseSingleRange677=== PAUSE TestParseSingleRange678=== RUN TestProxyHeadersOnlyTrustedOnSocket6792026/10/14 16:42:04 INFO Starting HTTP server address=127.0.0.1:576386802026/10/14 16:42:04 INFO Starting HTTP server address=proxy.sock6812026/10/14 16:42:04 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6822026/10/14 16:42:04 INFO Shutdown signal received, draining in-flight requests timeout=10s683--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.17s)684=== RUN TestIsValidCachePath685=== PAUSE TestIsValidCachePath686=== RUN TestReadProxyNarinfo687=== PAUSE TestReadProxyNarinfo688=== RUN TestReadProxyNarinfoAlreadyDecompressed689=== PAUSE TestReadProxyNarinfoAlreadyDecompressed690=== RUN TestReadProxyContentNegotiation691=== PAUSE TestReadProxyContentNegotiation692=== RUN TestReadProxyNarStreaming693=== PAUSE TestReadProxyNarStreaming694=== RUN TestReadProxy404695=== PAUSE TestReadProxy404696=== RUN TestReadProxyInvalidPath697=== PAUSE TestReadProxyInvalidPath698=== RUN TestReadProxyHead699=== PAUSE TestReadProxyHead700=== RUN TestReadProxyOutlastsServerWriteTimeout701=== PAUSE TestReadProxyOutlastsServerWriteTimeout702=== RUN TestReadProxyConditionalGet703=== PAUSE TestReadProxyConditionalGet704=== RUN TestReadProxyRootRedirectsToIndexHTML705=== PAUSE TestReadProxyRootRedirectsToIndexHTML706=== RUN TestReadProxyDisabled707=== PAUSE TestReadProxyDisabled708=== RUN TestReadRedirectNar709=== PAUSE TestReadRedirectNar710=== RUN TestReadRedirectKeepsNarinfoProxied711=== PAUSE TestReadRedirectKeepsNarinfoProxied712=== RUN TestReadProxyRangeRequest713=== PAUSE TestReadProxyRangeRequest714=== RUN TestReadRedirectUsesPublicS3URL715=== PAUSE TestReadRedirectUsesPublicS3URL716=== RUN TestPush_OverlappingRootsStoreOneRowPerKey717=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey718=== RUN TestPush_CompleteCommitsEveryRoot719=== PAUSE TestPush_CompleteCommitsEveryRoot720=== RUN TestPush_RepeatedRootCommitsOnce721=== PAUSE TestPush_RepeatedRootCommitsOnce722=== RUN TestPush_CompleteWaitsForCleanupOfThePush723=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush724=== RUN TestPush_RootsAreLockedInByteOrder725=== PAUSE TestPush_RootsAreLockedInByteOrder726=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit727=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit728=== RUN TestPush_RejectsBadRequests729=== PAUSE TestPush_RejectsBadRequests730=== RUN TestPush_SignsNarinfosOfItsPendingObjects731=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects732=== RUN TestRedundantMultipartUpload733=== PAUSE TestRedundantMultipartUpload734=== RUN TestCompleteMultipartUpload_ErrorButObjectExists735=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists736=== RUN TestCompletedNarNotReofferedAcrossClosures737=== PAUSE TestCompletedNarNotReofferedAcrossClosures738=== RUN TestPresignedUploadRegisteredBeforeCommit739=== PAUSE TestPresignedUploadRegisteredBeforeCommit740=== RUN TestService_Rustfstest741=== PAUSE TestService_Rustfstest742=== RUN TestParseSize743=== PAUSE TestParseSize744=== RUN TestSkippedUploadsHandler745=== PAUSE TestSkippedUploadsHandler746=== RUN TestSystemdListenerNotActivated747--- PASS: TestSystemdListenerNotActivated (0.00s)748=== RUN TestWatchdogBeatsWhenHealthy749--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)750=== RUN TestWatchdogSkipsWhenUnhealthy7512026/10/14 16:42:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7522026/10/14 16:42:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7532026/10/14 16:42:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7542026/10/14 16:42:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7552026/10/14 16:42:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7562026/10/14 16:42:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7572026/10/14 16:42:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7582026/10/14 16:42:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7592026/10/14 16:42:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/14 16:42:04 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"761--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)762=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle763=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle764=== RUN TestProxyWriteTimeout765=== PAUSE TestProxyWriteTimeout766=== RUN TestPendingClosureWriteTimeout767=== PAUSE TestPendingClosureWriteTimeout768=== RUN TestIsValidUploadKey769=== PAUSE TestIsValidUploadKey770=== RUN TestUploadHandlersRejectInvalidKeys771=== PAUSE TestUploadHandlersRejectInvalidKeys772=== RUN TestUploadHandlersRejectOversizedBody773=== PAUSE TestUploadHandlersRejectOversizedBody774=== RUN TestService_cleanupPendingClosuresHandler775=== PAUSE TestService_cleanupPendingClosuresHandler776=== RUN TestService_createPendingClosureHandler777=== PAUSE TestService_createPendingClosureHandler778=== RUN TestService_verifyS3Integrity779=== PAUSE TestService_verifyS3Integrity780=== RUN TestCompleteMultipartUnregistered781=== PAUSE TestCompleteMultipartUnregistered782=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT783=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT784=== CONT TestCompletedNarNotReofferedAcrossClosures785=== CONT TestService_verifyS3Integrity786=== CONT TestPush_RepeatedRootCommitsOnce787=== CONT TestIsValidUploadKey788=== RUN TestIsValidUploadKey/narinfo789=== PAUSE TestIsValidUploadKey/narinfo790=== CONT TestRedundantMultipartUpload791=== CONT TestGCTaskStore_DeduplicateSameParams792--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)793=== CONT TestService_AuthMiddleware794=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT795=== CONT TestCompleteMultipartUnregistered796=== CONT TestCompleteMultipartUpload_ErrorButObjectExists797=== CONT TestPush_SignsNarinfosOfItsPendingObjects798=== CONT TestPush_RejectsBadRequests799=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit800=== CONT TestPush_RootsAreLockedInByteOrder801=== CONT TestPush_CompleteWaitsForCleanupOfThePush802=== CONT TestGCTaskStore_GetEmpty803=== CONT TestGCTaskStore_ConflictDifferentParams804--- PASS: TestGCTaskStore_GetEmpty (0.00s)805=== CONT TestGCTaskStore_GetReturnsLatest806=== CONT TestGetExistingObjectsLocksRows807=== CONT TestGCTaskStore_StartNew808=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle809=== CONT TestRegisterCompletedObjectNeedsPendingRow810=== CONT TestProxyWriteTimeout811=== CONT TestCommitRacingPendingCleanupKeepsObjects812=== CONT TestPushWaitsForSweepHoldingRow813=== CONT TestSkippedUploadsHandler814=== CONT TestPendingClosureWriteTimeout815=== RUN TestPendingClosureWriteTimeout/empty816=== RUN TestIsValidUploadKey/nar_zst817=== PAUSE TestPendingClosureWriteTimeout/empty818=== CONT TestSweepRechecksPendingAfterLocking819--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)820--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)821=== CONT TestGCEndsOnShutdown822=== RUN TestGCEndsOnShutdown/before_the_run823=== PAUSE TestGCEndsOnShutdown/before_the_run824=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete825=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete826=== RUN TestPendingClosureWriteTimeout/400_objects827=== PAUSE TestPendingClosureWriteTimeout/400_objects828=== RUN TestProxyWriteTimeout/narinfo829=== PAUSE TestIsValidUploadKey/nar_zst830=== RUN TestIsValidUploadKey/nar_xz831=== RUN TestPendingClosureWriteTimeout/670k_objects832=== PAUSE TestIsValidUploadKey/nar_xz833--- PASS: TestGCTaskStore_StartNew (0.00s)834=== RUN TestIsValidUploadKey/nar_plain835=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark836=== PAUSE TestIsValidUploadKey/nar_plain837=== RUN TestIsValidUploadKey/listing838=== PAUSE TestIsValidUploadKey/listing839=== PAUSE TestProxyWriteTimeout/narinfo840=== RUN TestProxyWriteTimeout/1_GiB_nar841=== PAUSE TestProxyWriteTimeout/1_GiB_nar842=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark843=== PAUSE TestPendingClosureWriteTimeout/670k_objects844=== RUN TestIsValidUploadKey/build_log845=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline846=== PAUSE TestIsValidUploadKey/build_log847=== RUN TestProxyWriteTimeout/10_GiB_nar848=== RUN TestIsValidUploadKey/build_log_home-manager_file849=== PAUSE TestIsValidUploadKey/build_log_home-manager_file8502026/10/14 16:42:04 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000851=== PAUSE TestProxyWriteTimeout/10_GiB_nar852=== RUN TestIsValidUploadKey/build_log_plus_in_name853=== RUN TestProxyWriteTimeout/unknown_size854=== PAUSE TestProxyWriteTimeout/unknown_size855=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline856=== PAUSE TestIsValidUploadKey/build_log_plus_in_name857=== RUN TestIsValidUploadKey/build_log_question_mark858=== CONT TestPush_CompleteCommitsEveryRoot859=== PAUSE TestIsValidUploadKey/build_log_question_mark860=== RUN TestIsValidUploadKey/build_log_equals861=== PAUSE TestIsValidUploadKey/build_log_equals862=== CONT TestPush_OverlappingRootsStoreOneRowPerKey863=== CONT TestPresentReportsOnlyClosureRoots864=== RUN TestIsValidUploadKey/realisation865=== PAUSE TestIsValidUploadKey/realisation866=== RUN TestIsValidUploadKey/realisation_plus_in_output867=== PAUSE TestIsValidUploadKey/realisation_plus_in_output868=== RUN TestIsValidUploadKey/nix-cache-info869=== PAUSE TestIsValidUploadKey/nix-cache-info870=== RUN TestIsValidUploadKey/index.html871=== PAUSE TestIsValidUploadKey/index.html872=== RUN TestIsValidUploadKey/narinfo_key,_nar_type873=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type874=== RUN TestIsValidUploadKey/nar_key,_narinfo_type875=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type876=== RUN TestIsValidUploadKey/listing_key,_narinfo_type877=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type878=== RUN TestIsValidUploadKey/traversal879=== PAUSE TestIsValidUploadKey/traversal880=== RUN TestIsValidUploadKey/traversal_nar881=== PAUSE TestIsValidUploadKey/traversal_nar882=== RUN TestIsValidUploadKey/absolute883=== PAUSE TestIsValidUploadKey/absolute884=== RUN TestIsValidUploadKey/empty_key885=== PAUSE TestIsValidUploadKey/empty_key886=== RUN TestIsValidUploadKey/unknown_type887=== PAUSE TestIsValidUploadKey/unknown_type888=== CONT TestReadRedirectUsesPublicS3URL889--- PASS: TestSkippedUploadsHandler (0.03s)890=== CONT TestLeadElectsOneAndHandsOver891--- PASS: TestPresentReportsOnlyClosureRoots (1.25s)892=== CONT TestReadProxyRangeRequest8932026/10/14 16:42:06 INFO Received uploads request method=POST path=/api/pending_closures8942026/10/14 16:42:06 INFO Received uploads request method=POST path=/api/pending_closures8952026/10/14 16:42:06 INFO Received push request method=POST path=/api/pushes8962026/10/14 16:42:06 INFO Received complete push request method=POST path=/api/pushes/1/complete8972026/10/14 16:42:06 INFO Completed push id=1 objects=6 duration=30.419667ms898--- PASS: TestPush_CompleteCommitsEveryRoot (1.80s)899=== CONT TestConnectWaitsForAPeerMigration9002026/10/14 16:42:06 INFO Received push request method=POST path=/api/pushes9012026/10/14 16:42:06 INFO Received complete push request method=POST path=/api/pushes/1/complete9022026/10/14 16:42:06 INFO Completed push id=1 objects=4 duration=17.991ms903--- PASS: TestPush_RepeatedRootCommitsOnce (2.05s)904=== CONT TestResolveDBConnectionString905=== RUN TestResolveDBConnectionString/flag_wins906=== PAUSE TestResolveDBConnectionString/flag_wins907=== RUN TestResolveDBConnectionString/file_when_flag_empty908=== PAUSE TestResolveDBConnectionString/file_when_flag_empty909=== RUN TestResolveDBConnectionString/missing_file_is_an_error910=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error911=== RUN TestResolveDBConnectionString/PGHOST_allows_empty912=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty913=== RUN TestResolveDBConnectionString/nothing_configured914=== PAUSE TestResolveDBConnectionString/nothing_configured915=== CONT TestSweepSkipsRowsLockedByPush9162026/10/14 16:42:06 INFO Received uploads request method=POST path=/api/pending_closures9172026/10/14 16:42:07 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"918--- PASS: TestService_AuthMiddleware (2.32s)919=== CONT TestFailedS3DeleteKeepsTombstone9202026/10/14 16:42:07 INFO Received push request method=POST path=/api/pushes921--- PASS: TestPushWaitsForSweepHoldingRow (2.68s)922=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock9232026/10/14 16:42:07 INFO Received push request method=POST path=/api/pushes9242026/10/14 16:42:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9252026/10/14 16:42:07 INFO Signed narinfos id=1 count=19262026/10/14 16:42:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9272026/10/14 16:42:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9282026/10/14 16:42:07 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"9292026/10/14 16:42:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9302026/10/14 16:42:07 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"9312026/10/14 16:42:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9322026/10/14 16:42:07 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=19332026/10/14 16:42:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9342026/10/14 16:42:07 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo935--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (2.84s)936=== CONT TestForceGCDuringPushOffersSweptObject937=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows938=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows939=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check940=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check941=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection9422026/10/14 16:42:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9432026-10-14 16:42:07.660 UTC [11606] ERROR: Push does not exist: id=19442026-10-14 16:42:07.660 UTC [11606] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE9452026-10-14 16:42:07.660 UTC [11606] STATEMENT: SELECT commit_push($1)946--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (2.88s)947=== CONT TestGCSweepDeliversEachKeyOnce9482026/10/14 16:42:07 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YjVjYmI1YzItY2EwMS00ZjU1LThmNmItZWNiY2U3MWI2NTdhLmM3ZjJjMGZkLTk2MTItNDlkOC04ZmMzLTZkNWJjMWFlZTE0YngxNzkxOTk2MTI2MzEyNzIzMDAw parts=129492026/10/14 16:42:07 INFO Received uploads request method=POST path=/api/pending_closures9502026/10/14 16:42:07 INFO Received uploads request method=POST path=/api/pending_closures9512026/10/14 16:42:07 INFO Received push request method=POST path=/api/pushes9522026/10/14 16:42:07 INFO Received complete push request method=POST path=/api/pushes/1/complete9532026/10/14 16:42:07 INFO Completed push id=1 objects=4 duration=42.115583ms9542026/10/14 16:42:07 INFO Received push request method=POST path=/api/pushes9552026/10/14 16:42:08 INFO Aborted multipart uploads count=0 kept=09562026/10/14 16:42:08 WARN Force mode enabled - objects will be deleted immediately without grace period9572026/10/14 16:42:08 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=09582026/10/14 16:42:08 INFO Received push request method=POST path=/api/pushes9592026/10/14 16:42:08 INFO Vacuumed table table=pending_closures9602026/10/14 16:42:08 INFO Vacuumed table table=pending_objects9612026/10/14 16:42:08 INFO Vacuumed table table=multipart_uploads962--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (3.42s)963=== CONT TestTombstonedObjectOfferedWithoutWaiting9642026/10/14 16:42:08 INFO Vacuumed table table=closures9652026/10/14 16:42:08 INFO Vacuumed table table=objects9662026/10/14 16:42:08 INFO Received complete push request method=POST path=/api/pushes/2/complete9672026/10/14 16:42:08 INFO Completed push id=2 objects=4 duration=10.058625ms968--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (3.47s)969=== CONT TestGCSweepSkipsPendingObjects9702026/10/14 16:42:08 INFO Aborted multipart uploads count=0 kept=09712026/10/14 16:42:08 WARN Force mode enabled - objects will be deleted immediately without grace period9722026/10/14 16:42:08 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=09732026/10/14 16:42:08 INFO Vacuumed table table=pending_closures9742026/10/14 16:42:08 INFO Vacuumed table table=pending_objects9752026/10/14 16:42:08 INFO Vacuumed table table=multipart_uploads9762026/10/14 16:42:08 INFO Vacuumed table table=closures9772026/10/14 16:42:08 INFO Vacuumed table table=objects978--- PASS: TestSweepRechecksPendingAfterLocking (3.81s)979=== CONT TestDeduplicatedObjectsRecordedAsPending9802026/10/14 16:42:08 INFO Received uploads request method=POST path=/api/pending_closures981--- PASS: TestReadRedirectUsesPublicS3URL (4.20s)982=== CONT TestPushDedupSurvivesConcurrentGC9832026/10/14 16:42:09 INFO Aborted multipart uploads count=0 kept=09842026/10/14 16:42:09 WARN Force mode enabled - objects will be deleted immediately without grace period9852026/10/14 16:42:09 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=09862026/10/14 16:42:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9872026/10/14 16:42:09 INFO Vacuumed table table=pending_closures9882026/10/14 16:42:09 INFO Vacuumed table table=pending_objects9892026/10/14 16:42:09 INFO Vacuumed table table=multipart_uploads9902026/10/14 16:42:09 INFO Vacuumed table table=closures9912026/10/14 16:42:09 INFO Vacuumed table table=objects9922026/10/14 16:42:09 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YjVjYmI1YzItY2EwMS00ZjU1LThmNmItZWNiY2U3MWI2NTdhLjllMzk3MDdkLTI3MDQtNDIwOC1hZjQzLTIwYWQ4MDU3ZWI5NngxNzkxOTk2MTI3Nzc1NjY2MDAw error="Get \"http://127.0.0.1:1/bucket5/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"9932026/10/14 16:42:09 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YjVjYmI1YzItY2EwMS00ZjU1LThmNmItZWNiY2U3MWI2NTdhLmQxMDIwNmJkLThmOGQtNDE3NC1hMDM4LWIwNTcwNjM3MDllOXgxNzkxOTk2MTI3NzQ5MTMxMDAw parts=129942026/10/14 16:42:09 INFO Received cleanup request method=DELETE path=/api/pending_closures9952026/10/14 16:42:09 INFO Aborted multipart uploads count=1 kept=0996--- PASS: TestCommitRacingPendingCleanupKeepsObjects (4.84s)997=== CONT TestGCMetrics9982026/10/14 16:42:09 INFO Received uploads request method=POST path=/api/pending_closures999--- PASS: TestRedundantMultipartUpload (4.86s)1000=== CONT TestGCBugBareHashReferences10012026/10/14 16:42:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10022026/10/14 16:42:09 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1003--- PASS: TestCompleteMultipartUnregistered (5.17s)1004=== CONT TestGCAdvisoryLockBlocksConcurrentRun10052026/10/14 16:42:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10062026/10/14 16:42:10 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjVjYmI1YzItY2EwMS00ZjU1LThmNmItZWNiY2U3MWI2NTdhLmEzNDEwYzE0LTU5MDItNGUyMy1iYjAzLWU3NGNmOWNiODcyNngxNzkxOTk2MTI5NjgxODI0MDAw10072026/10/14 16:42:10 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjVjYmI1YzItY2EwMS00ZjU1LThmNmItZWNiY2U3MWI2NTdhLmEzNDEwYzE0LTU5MDItNGUyMy1iYjAzLWU3NGNmOWNiODcyNngxNzkxOTk2MTI5NjgxODI0MDAw parts=11008--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (5.27s)1009=== CONT TestLeadEndsOnShutdown10102026/10/14 16:42:10 INFO Received uploads request method=POST path=/api/pending_closures10112026/10/14 16:42:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10122026/10/14 16:42:10 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YjVjYmI1YzItY2EwMS00ZjU1LThmNmItZWNiY2U3MWI2NTdhLjRjZGVkYmYzLTYwNTEtNGQ3NS04NmM3LWYyMmQzMWUxOWM4MHgxNzkxOTk2MTI4NzM3MzkzMDAw parts=1010132026/10/14 16:42:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10142026/10/14 16:42:10 INFO Completed upload id=1 objects=2 duration=28.467ms10152026/10/14 16:42:10 INFO Received uploads request method=POST path=/api/pending_closures10162026/10/14 16:42:10 INFO Received uploads request method=POST path=/api/pending_closures10172026/10/14 16:42:10 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10182026/10/14 16:42:10 WARN Found objects in DB but missing from S3, will re-upload count=11019--- PASS: TestService_verifyS3Integrity (5.79s)1020=== CONT TestLeadIncumbentAnnouncesAtOnce10212026/10/14 16:42:10 INFO lead: acquired remote=192.0.2.1:123410222026/10/14 16:42:10 INFO Received uploads request method=POST path=/api/pending_closures1023--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (6.19s)1024=== CONT TestReadRedirectKeepsNarinfoProxied10252026/10/14 16:42:11 INFO Received push request method=POST path=/api/pushes10262026-10-14 16:42:11.377 UTC [11653] ERROR: could not obtain lock on row in relation "closures"10272026-10-14 16:42:11.377 UTC [11653] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10282026-10-14 16:42:11.383 UTC [11653] ERROR: could not obtain lock on row in relation "closures"10292026-10-14 16:42:11.383 UTC [11653] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10302026-10-14 16:42:11.387 UTC [11653] ERROR: could not obtain lock on row in relation "closures"10312026-10-14 16:42:11.387 UTC [11653] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10322026-10-14 16:42:11.388 UTC [11653] ERROR: could not obtain lock on row in relation "closures"10332026-10-14 16:42:11.388 UTC [11653] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10342026-10-14 16:42:11.393 UTC [11653] ERROR: could not obtain lock on row in relation "closures"10352026-10-14 16:42:11.393 UTC [11653] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1036--- PASS: TestPush_RootsAreLockedInByteOrder (6.63s)1037=== CONT TestReadRedirectNar1038--- PASS: TestGetExistingObjectsLocksRows (6.80s)1039=== CONT TestReadProxyDisabled1040--- PASS: TestRegisterCompletedObjectNeedsPendingRow (6.99s)1041=== CONT TestReadProxyRootRedirectsToIndexHTML10422026/10/14 16:42:11 INFO lead: released remote=192.0.2.1:123410432026/10/14 16:42:11 INFO lead: acquired remote=192.0.2.1:12341044=== RUN TestPush_RejectsBadRequests/no_roots1045=== PAUSE TestPush_RejectsBadRequests/no_roots1046=== RUN TestPush_RejectsBadRequests/no_objects1047=== PAUSE TestPush_RejectsBadRequests/no_objects1048=== RUN TestPush_RejectsBadRequests/bad_root1049=== PAUSE TestPush_RejectsBadRequests/bad_root1050=== RUN TestPush_RejectsBadRequests/root_not_in_objects1051=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1052=== CONT TestReadProxyConditionalGet10532026/10/14 16:42:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10542026/10/14 16:42:12 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YjVjYmI1YzItY2EwMS00ZjU1LThmNmItZWNiY2U3MWI2NTdhLjg2OTNkNWRmLWZjMjQtNDFjZC05MTE5LTkwMTk1YmFkM2Y0ZngxNzkxOTk2MTMwMjg3ODA0MDAw parts=1210552026/10/14 16:42:12 INFO Received uploads request method=POST path=/api/pending_closures1056--- PASS: TestCompletedNarNotReofferedAcrossClosures (7.39s)1057=== CONT TestReadProxyOutlastsServerWriteTimeout10582026/10/14 16:42:12 INFO Received uploads request method=POST path=/api/pending_closures1059--- PASS: TestReadProxyRangeRequest (6.70s)1060=== CONT TestReadProxyHead10612026/10/14 16:42:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10622026/10/14 16:42:12 INFO lead: released remote=192.0.2.1:12341063--- PASS: TestLeadElectsOneAndHandsOver (8.11s)1064=== CONT TestReadProxyInvalidPath10652026/10/14 16:42:13 INFO Aborted multipart uploads count=0 kept=010662026/10/14 16:42:13 WARN Force mode enabled - objects will be deleted immediately without grace period10672026/10/14 16:42:13 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010682026/10/14 16:42:13 INFO Vacuumed table table=pending_closures10692026/10/14 16:42:13 INFO Vacuumed table table=pending_objects10702026/10/14 16:42:13 INFO Vacuumed table table=multipart_uploads10712026/10/14 16:42:13 INFO Vacuumed table table=closures10722026/10/14 16:42:13 INFO Vacuumed table table=objects10732026/10/14 16:42:13 INFO Aborted multipart uploads count=0 kept=010742026/10/14 16:42:13 WARN Force mode enabled - objects will be deleted immediately without grace period10752026/10/14 16:42:13 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=010762026/10/14 16:42:13 INFO Vacuumed table table=pending_closures10772026/10/14 16:42:13 INFO Vacuumed table table=pending_objects10782026/10/14 16:42:13 INFO Vacuumed table table=multipart_uploads10792026/10/14 16:42:13 INFO Vacuumed table table=closures10802026/10/14 16:42:13 INFO Received uploads request method=POST path=/api/pending_closures10812026/10/14 16:42:13 INFO Vacuumed table table=objects1082--- PASS: TestSweepSkipsRowsLockedByPush (6.44s)1083=== CONT TestReadProxy40410842026/10/14 16:42:13 INFO Aborted multipart uploads count=0 kept=010852026/10/14 16:42:13 WARN Force mode enabled - objects will be deleted immediately without grace period10862026/10/14 16:42:13 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."10872026/10/14 16:42:13 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1088--- PASS: TestFailedS3DeleteKeepsTombstone (6.56s)1089=== CONT TestReadProxyNarStreaming1090--- PASS: TestConnectWaitsForAPeerMigration (7.11s)1091=== CONT TestReadProxyContentNegotiation10922026/10/14 16:42:14 INFO Received uploads request method=POST path=/api/pending_closures1093--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (6.67s)1094=== CONT TestReadProxyNarinfoAlreadyDecompressed10952026/10/14 16:42:14 INFO Aborted multipart uploads count=0 kept=010962026/10/14 16:42:14 WARN Force mode enabled - objects will be deleted immediately without grace period10972026/10/14 16:42:14 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=010982026/10/14 16:42:14 INFO Vacuumed table table=pending_closures10992026/10/14 16:42:14 INFO Received uploads request method=POST path=/api/pending_closures11002026/10/14 16:42:14 INFO Vacuumed table table=pending_objects11012026/10/14 16:42:14 INFO Vacuumed table table=multipart_uploads11022026/10/14 16:42:14 INFO Vacuumed table table=closures11032026/10/14 16:42:14 INFO Vacuumed table table=objects1104--- PASS: TestGCSweepDeliversEachKeyOnce (7.11s)1105=== CONT TestReadProxyNarinfo11062026/10/14 16:42:14 INFO Aborted multipart uploads count=0 kept=011072026/10/14 16:42:14 WARN Force mode enabled - objects will be deleted immediately without grace period11082026/10/14 16:42:14 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=011092026/10/14 16:42:14 INFO Vacuumed table table=pending_closures11102026/10/14 16:42:15 INFO Vacuumed table table=pending_objects11112026/10/14 16:42:15 INFO Vacuumed table table=multipart_uploads11122026/10/14 16:42:15 INFO Vacuumed table table=closures11132026/10/14 16:42:15 INFO Vacuumed table table=objects1114--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (7.63s)1115=== CONT TestIsValidCachePath1116=== RUN TestIsValidCachePath/narinfo1117=== PAUSE TestIsValidCachePath/narinfo1118=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1119=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1120=== RUN TestIsValidCachePath/nar_zst1121=== PAUSE TestIsValidCachePath/nar_zst1122=== RUN TestIsValidCachePath/nar_xz1123=== PAUSE TestIsValidCachePath/nar_xz1124=== RUN TestIsValidCachePath/nar_bz21125=== PAUSE TestIsValidCachePath/nar_bz21126=== RUN TestIsValidCachePath/nar_uncompressed1127=== PAUSE TestIsValidCachePath/nar_uncompressed1128=== RUN TestIsValidCachePath/ls1129=== PAUSE TestIsValidCachePath/ls1130=== RUN TestIsValidCachePath/log1131=== PAUSE TestIsValidCachePath/log1132=== RUN TestIsValidCachePath/realisation1133=== PAUSE TestIsValidCachePath/realisation1134=== RUN TestIsValidCachePath/nix-cache-info1135=== PAUSE TestIsValidCachePath/nix-cache-info11362026/10/14 16:42:15 INFO Received uploads request method=POST path=/api/pending_closures1137=== RUN TestIsValidCachePath/index.html1138=== PAUSE TestIsValidCachePath/index.html1139=== RUN TestIsValidCachePath/traversal_parent1140=== PAUSE TestIsValidCachePath/traversal_parent1141=== RUN TestIsValidCachePath/traversal_in_middle1142=== PAUSE TestIsValidCachePath/traversal_in_middle1143=== RUN TestIsValidCachePath/invalid_char_e1144=== PAUSE TestIsValidCachePath/invalid_char_e1145=== RUN TestIsValidCachePath/invalid_char_u1146=== PAUSE TestIsValidCachePath/invalid_char_u1147=== RUN TestIsValidCachePath/random_path1148=== PAUSE TestIsValidCachePath/random_path1149=== RUN TestIsValidCachePath/empty1150=== PAUSE TestIsValidCachePath/empty1151=== RUN TestIsValidCachePath/leading_slash1152=== PAUSE TestIsValidCachePath/leading_slash1153=== RUN TestIsValidCachePath/wrong_extension1154=== PAUSE TestIsValidCachePath/wrong_extension1155=== RUN TestIsValidCachePath/short_hash1156=== PAUSE TestIsValidCachePath/short_hash1157--- PASS: TestGCSweepSkipsPendingObjects (6.88s)1158=== CONT TestDeleteClosuresRacingPins1159=== CONT TestClientFallsBackToClosures1160--- PASS: TestTombstonedObjectOfferedWithoutWaiting (6.96s)1161=== CONT TestParseSingleRange1162=== RUN TestParseSingleRange/none1163=== PAUSE TestParseSingleRange/none1164=== RUN TestParseSingleRange/unknown_unit1165=== PAUSE TestParseSingleRange/unknown_unit1166=== RUN TestParseSingleRange/multi-range_ignored1167=== PAUSE TestParseSingleRange/multi-range_ignored1168=== RUN TestParseSingleRange/malformed_no_dash1169=== PAUSE TestParseSingleRange/malformed_no_dash1170=== RUN TestParseSingleRange/malformed_both_empty1171=== PAUSE TestParseSingleRange/malformed_both_empty1172=== RUN TestParseSingleRange/malformed_end_before_start1173=== PAUSE TestParseSingleRange/malformed_end_before_start1174=== RUN TestParseSingleRange/closed1175=== PAUSE TestParseSingleRange/closed1176=== RUN TestParseSingleRange/open-ended1177=== PAUSE TestParseSingleRange/open-ended1178=== RUN TestParseSingleRange/end_clamped_to_size1179=== PAUSE TestParseSingleRange/end_clamped_to_size1180=== RUN TestParseSingleRange/suffix1181=== PAUSE TestParseSingleRange/suffix1182=== RUN TestParseSingleRange/suffix_exceeds_size1183=== PAUSE TestParseSingleRange/suffix_exceeds_size1184=== RUN TestParseSingleRange/single_byte1185=== PAUSE TestParseSingleRange/single_byte1186=== RUN TestParseSingleRange/start_past_EOF1187=== PAUSE TestParseSingleRange/start_past_EOF1188=== RUN TestParseSingleRange/start_far_past_EOF1189=== PAUSE TestParseSingleRange/start_far_past_EOF1190=== CONT TestPresentNotReportedWhileGCDeletesClosure1191=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1192=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1193=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1194=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1195=== CONT TestMetricsCommit11962026/10/14 16:42:15 INFO Received uploads request method=POST path=/api/pending_closures1197--- PASS: TestDeduplicatedObjectsRecordedAsPending (6.90s)1198=== CONT TestPresentRefreshesOnlyStaleClosures11992026/10/14 16:42:15 WARN Rate limiter enabled after throttle name=s3-test rate=512002026/10/14 16:42:15 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1201=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1202 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101203 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001204--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (10.84s)1205=== CONT TestClientPushesUseOnePush12062026/10/14 16:42:15 INFO Received uploads request method=POST path=/api/pending_closures12072026/10/14 16:42:16 INFO Aborted multipart uploads count=0 kept=012082026/10/14 16:42:16 INFO Aborted multipart uploads count=0 kept=012092026/10/14 16:42:16 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=012102026/10/14 16:42:16 WARN Force mode enabled - objects will be deleted immediately without grace period12112026/10/14 16:42:16 INFO Vacuumed table table=pending_closures12122026/10/14 16:42:16 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=012132026/10/14 16:42:16 INFO Vacuumed table table=pending_closures12142026/10/14 16:42:16 INFO Vacuumed table table=pending_objects12152026/10/14 16:42:16 INFO Vacuumed table table=pending_objects12162026/10/14 16:42:16 INFO Vacuumed table table=multipart_uploads12172026/10/14 16:42:16 INFO Vacuumed table table=multipart_uploads12182026/10/14 16:42:16 INFO Vacuumed table table=closures12192026/10/14 16:42:16 INFO Vacuumed table table=objects1220--- PASS: TestGCMetrics (6.66s)1221=== CONT TestPinProtectsFromGC12222026/10/14 16:42:16 INFO Vacuumed table table=closures12232026/10/14 16:42:16 INFO Vacuumed table table=objects12242026/10/14 16:42:16 INFO Aborted multipart uploads count=0 kept=012252026/10/14 16:42:16 WARN Force mode enabled - objects will be deleted immediately without grace period12262026/10/14 16:42:16 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=012272026/10/14 16:42:16 INFO Vacuumed table table=pending_closures12282026/10/14 16:42:16 INFO Vacuumed table table=pending_objects12292026/10/14 16:42:16 INFO Vacuumed table table=multipart_uploads12302026/10/14 16:42:16 INFO Vacuumed table table=closures12312026/10/14 16:42:16 INFO Vacuumed table table=objects1232--- PASS: TestPushDedupSurvivesConcurrentGC (7.37s)1233=== CONT TestClientSharedPathCommittedMidPush12342026/10/14 16:42:16 INFO lead: acquired remote=192.0.2.1:12341235--- PASS: TestGCBugBareHashReferences (7.11s)1236=== CONT TestClientWithDependencies12372026/10/14 16:42:16 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld4 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1238--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (6.95s)1239=== CONT TestClientMultipleUploads12402026/10/14 16:42:17 INFO lead: acquired remote=192.0.2.1:123412412026/10/14 16:42:17 INFO lead: released remote=192.0.2.1:12341242--- PASS: TestLeadIncumbentAnnouncesAtOnce (6.53s)1243=== CONT TestService_readinessHandler1244--- PASS: TestReadRedirectKeepsNarinfoProxied (6.40s)1245=== CONT TestClientIntegration1246--- PASS: TestReadRedirectNar (6.23s)1247=== CONT TestMetricsInventory12482026/10/14 16:42:17 INFO lead: released remote=192.0.2.1:12341249--- PASS: TestLeadEndsOnShutdown (7.71s)1250=== CONT TestNARDeduplicationMetadataUploadBug1251--- PASS: TestReadProxyDisabled (6.24s)1252=== CONT TestCreatePin_ReservedPins12532026/10/14 16:42:17 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57779/oidc1254--- PASS: TestReadProxyRootRedirectsToIndexHTML (6.27s)1255=== CONT TestOrphanedObjectsGCStressTest1256--- PASS: TestReadProxyConditionalGet (6.27s)1257=== CONT TestOrphanedObjectsGC1258--- PASS: TestReadProxyHead (6.06s)1259=== CONT TestCreatePendingClosureRejectsOversizedNAR12602026/10/14 16:42:18 INFO Received uploads request method=POST path=/api/pending_closures1261--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1262=== CONT TestObjectStatsLargeCommit1263--- PASS: TestReadProxyInvalidPath (6.11s)1264=== CONT TestCacheConfigHandlerMaxNarSize1265--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1266=== CONT TestObjectStatsTrigger1267--- PASS: TestReadProxy404 (6.14s)1268=== CONT TestGenerateLandingPage1269--- PASS: TestGenerateLandingPage (0.00s)1270=== CONT TestPendingCleanupUsesOneCutoff1271--- PASS: TestReadProxyNarStreaming (5.94s)1272=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1273--- PASS: TestReadProxyContentNegotiation (6.26s)1274=== CONT TestMultipartCleanup1275--- PASS: TestReadProxyNarinfoAlreadyDecompressed (5.82s)1276=== CONT TestServerTLSConfig1277=== RUN TestServerTLSConfig/no_client_CA1278=== PAUSE TestServerTLSConfig/no_client_CA1279=== RUN TestServerTLSConfig/missing_CA_file1280=== PAUSE TestServerTLSConfig/missing_CA_file1281=== RUN TestServerTLSConfig/not_a_PEM_file1282=== PAUSE TestServerTLSConfig/not_a_PEM_file1283=== CONT TestClientErrorHandling1284=== RUN TestClientErrorHandling/InvalidStorePath1285=== PAUSE TestClientErrorHandling/InvalidStorePath1286=== RUN TestClientErrorHandling/InvalidAuthToken1287=== PAUSE TestClientErrorHandling/InvalidAuthToken1288=== RUN TestClientErrorHandling/ServerNotAvailable1289=== PAUSE TestClientErrorHandling/ServerNotAvailable1290=== CONT TestService_NativeMTLS12912026/10/14 16:42:20 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1292--- PASS: TestReadProxyNarinfo (5.62s)1293=== CONT TestClientCADerivations12942026/10/14 16:42:21 INFO Received push request method=POST path=/api/pushes12952026/10/14 16:42:21 INFO Received complete push request method=POST path=/api/pushes/1/complete12962026/10/14 16:42:21 INFO Completed push id=1 objects=4 duration=14.642334ms12972026/10/14 16:42:21 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12982026/10/14 16:42:21 INFO Completed upload id=2 objects=2 duration=844.583µs1299--- PASS: TestMetricsCommit (5.98s)1300=== CONT TestCacheStatsHandler13012026/10/14 16:42:21 INFO Received uploads request method=POST path=/api/pending_closures13022026/10/14 16:42:21 INFO Received uploads request method=POST path=/api/pending_closures13032026/10/14 16:42:21 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13042026/10/14 16:42:21 INFO Uploading x8l6kk4ch87s8xmzh210l8c2ir4svg4c-shared-dep (136B)13052026/10/14 16:42:21 INFO Uploading w5azam46rgjhb4z93ds9j2jh8n17d5lg-b (256B)13062026/10/14 16:42:21 WARN Failed to register uploaded object key=b176sd8ncwa2v6jwgp5wqdmy2qsgkijq.ls error="server returned 404: 404 page not found\n"13072026/10/14 16:42:21 WARN Failed to register uploaded object key=w5azam46rgjhb4z93ds9j2jh8n17d5lg.ls error="server returned 404: 404 page not found\n"13082026/10/14 16:42:21 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13092026/10/14 16:42:21 WARN Failed to register uploaded object key=x8l6kk4ch87s8xmzh210l8c2ir4svg4c.ls error="server returned 404: 404 page not found\n"13102026/10/14 16:42:21 WARN Failed to register uploaded object key=nar/18j1ka20mr48kjf7kn2bmm4vrakybcd3bjjm16gk7b9br9y8ykbm.nar.zst error="server returned 404: 404 page not found\n"13112026/10/14 16:42:21 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13122026/10/14 16:42:21 INFO Signed narinfos id=1 count=213132026/10/14 16:42:21 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13142026/10/14 16:42:21 INFO Signed narinfos id=2 count=213152026/10/14 16:42:21 INFO Uploading 4 narinfos13162026/10/14 16:42:21 WARN Failed to register uploaded object key=b176sd8ncwa2v6jwgp5wqdmy2qsgkijq.narinfo error="server returned 404: 404 page not found\n"13172026/10/14 16:42:21 WARN Failed to register uploaded object key=x8l6kk4ch87s8xmzh210l8c2ir4svg4c.narinfo error="server returned 404: 404 page not found\n"13182026/10/14 16:42:21 WARN Failed to register uploaded object key=w5azam46rgjhb4z93ds9j2jh8n17d5lg.narinfo error="server returned 404: 404 page not found\n"13192026/10/14 16:42:21 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13202026/10/14 16:42:21 WARN Failed to register uploaded object key=x8l6kk4ch87s8xmzh210l8c2ir4svg4c.narinfo error="server returned 404: 404 page not found\n"13212026/10/14 16:42:21 INFO Completed upload id=1 objects=6 duration=13.80175ms13222026/10/14 16:42:21 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13232026/10/14 16:42:21 INFO Completed upload id=2 objects=6 duration=592.125µs13242026/10/14 16:42:21 INFO Upload complete. (377ms)1325=== NAME TestClientFallsBackToClosures1326 client_pushes_test.go:112: Retrieved narinfo from S3:1327 StorePath: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientFallsBackToClosures3954317696/001/store/x8l6kk4ch87s8xmzh210l8c2ir4svg4c-shared-dep1328 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1329 Compression: zstd1330 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821331 NarSize: 1361332 References: 1333 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1334 client_pushes_test.go:112: Retrieved narinfo from S3:1335 StorePath: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientFallsBackToClosures3954317696/001/store/b176sd8ncwa2v6jwgp5wqdmy2qsgkijq-a1336 URL: nar/18j1ka20mr48kjf7kn2bmm4vrakybcd3bjjm16gk7b9br9y8ykbm.nar.zst1337 Compression: zstd1338 NarHash: sha256:18j1ka20mr48kjf7kn2bmm4vrakybcd3bjjm16gk7b9br9y8ykbm1339 NarSize: 2561340 References: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientFallsBackToClosures3954317696/001/store/x8l6kk4ch87s8xmzh210l8c2ir4svg4c-shared-dep1341 CA: text:sha256:041slnbfg6032l5y4dbbd6nb9ayjlabmvmi5mfdnryr8k08jypzz1342 client_pushes_test.go:112: Retrieved narinfo from S3:1343 StorePath: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientFallsBackToClosures3954317696/001/store/w5azam46rgjhb4z93ds9j2jh8n17d5lg-b1344 URL: nar/18j1ka20mr48kjf7kn2bmm4vrakybcd3bjjm16gk7b9br9y8ykbm.nar.zst1345 Compression: zstd1346 NarHash: sha256:18j1ka20mr48kjf7kn2bmm4vrakybcd3bjjm16gk7b9br9y8ykbm1347 NarSize: 2561348 References: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientFallsBackToClosures3954317696/001/store/x8l6kk4ch87s8xmzh210l8c2ir4svg4c-shared-dep1349 CA: text:sha256:041slnbfg6032l5y4dbbd6nb9ayjlabmvmi5mfdnryr8k08jypzz1350--- PASS: TestClientFallsBackToClosures (6.49s)1351=== CONT TestGCTaskStore_Fail1352--- PASS: TestGCTaskStore_Fail (0.00s)1353=== CONT TestService_Rustfstest1354--- PASS: TestPresentRefreshesOnlyStaleClosures (6.13s)1355=== CONT TestCacheConfigHandler1356=== RUN TestCacheConfigHandler/full_config,_no_issuer1357=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1358=== RUN TestCacheConfigHandler/no_cache_url_configured1359=== PAUSE TestCacheConfigHandler/no_cache_url_configured1360=== RUN TestCacheConfigHandler/no_signing_keys1361=== PAUSE TestCacheConfigHandler/no_signing_keys1362=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1363=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1364=== CONT TestService_healthCheckHandler13652026/10/14 16:42:21 INFO Received push request method=POST path=/api/pushes13662026/10/14 16:42:21 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13672026/10/14 16:42:21 INFO Uploading lbfma4574hiwcrbz5s8avcndc5my0mwy-a (256B)13682026/10/14 16:42:21 INFO Uploading mlbq7bc7cyxf5g5syajz97589afmaqsl-shared-dep (136B)13692026/10/14 16:42:21 WARN Failed to register uploaded object key=mlbq7bc7cyxf5g5syajz97589afmaqsl.ls error="server returned 404: 404 page not found\n"13702026/10/14 16:42:21 WARN Failed to register uploaded object key=lbfma4574hiwcrbz5s8avcndc5my0mwy.ls error="server returned 404: 404 page not found\n"13712026/10/14 16:42:21 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13722026/10/14 16:42:21 WARN Failed to register uploaded object key=cg02i05va3j2b5rff0jc130sxpyvxpm7.ls error="server returned 404: 404 page not found\n"13732026/10/14 16:42:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13742026/10/14 16:42:21 WARN Failed to register uploaded object key=nar/1zyxci015fqzlk73grqy6fcfn595pk0hdfhl1wj4g4ixxhngwxgy.nar.zst error="server returned 404: 404 page not found\n"13752026/10/14 16:42:21 INFO Signed narinfos id=1 count=313762026/10/14 16:42:21 INFO Uploading 3 narinfos13772026/10/14 16:42:21 WARN Failed to register uploaded object key=cg02i05va3j2b5rff0jc130sxpyvxpm7.narinfo error="server returned 404: 404 page not found\n"13782026/10/14 16:42:21 WARN Failed to register uploaded object key=mlbq7bc7cyxf5g5syajz97589afmaqsl.narinfo error="server returned 404: 404 page not found\n"13792026/10/14 16:42:21 INFO Received complete push request method=POST path=/api/pushes/1/complete13802026/10/14 16:42:21 WARN Failed to register uploaded object key=lbfma4574hiwcrbz5s8avcndc5my0mwy.narinfo error="server returned 404: 404 page not found\n"13812026/10/14 16:42:22 INFO Completed push id=1 objects=8 duration=28.896583ms13822026/10/14 16:42:22 INFO Upload complete. (244ms)1383=== NAME TestClientPushesUseOnePush1384 client_pushes_test.go:97: Retrieved narinfo from S3:1385 StorePath: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientPushesUseOnePush2229583398/001/store/mlbq7bc7cyxf5g5syajz97589afmaqsl-shared-dep1386 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1387 Compression: zstd1388 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821389 NarSize: 1361390 References: 1391 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1392 client_pushes_test.go:97: Retrieved narinfo from S3:1393 StorePath: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientPushesUseOnePush2229583398/001/store/lbfma4574hiwcrbz5s8avcndc5my0mwy-a1394 URL: nar/1zyxci015fqzlk73grqy6fcfn595pk0hdfhl1wj4g4ixxhngwxgy.nar.zst1395 Compression: zstd1396 NarHash: sha256:1zyxci015fqzlk73grqy6fcfn595pk0hdfhl1wj4g4ixxhngwxgy1397 NarSize: 2561398 References: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientPushesUseOnePush2229583398/001/store/mlbq7bc7cyxf5g5syajz97589afmaqsl-shared-dep1399 CA: text:sha256:0g9c94xyn56zzb0my0yg7234dda5fcy2y6n8fn9m0n5zrmzqbha71400 client_pushes_test.go:97: Retrieved narinfo from S3:1401 StorePath: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientPushesUseOnePush2229583398/001/store/cg02i05va3j2b5rff0jc130sxpyvxpm7-b1402 URL: nar/1zyxci015fqzlk73grqy6fcfn595pk0hdfhl1wj4g4ixxhngwxgy.nar.zst1403 Compression: zstd1404 NarHash: sha256:1zyxci015fqzlk73grqy6fcfn595pk0hdfhl1wj4g4ixxhngwxgy1405 NarSize: 2561406 References: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientPushesUseOnePush2229583398/001/store/mlbq7bc7cyxf5g5syajz97589afmaqsl-shared-dep1407 CA: text:sha256:0g9c94xyn56zzb0my0yg7234dda5fcy2y6n8fn9m0n5zrmzqbha71408--- PASS: TestClientPushesUseOnePush (6.49s)1409=== CONT TestService_ReadScope_PublicByDefault1410=== NAME TestPinProtectsFromGC1411 client_integration_test.go:731: Pinned store path: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestPinProtectsFromGC2014636750/001/store/jwcvx2jm9asjanvmxf3fwhbxy1zwgkal-pinned-file.txt1412 client_integration_test.go:732: Unpinned store path: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestPinProtectsFromGC2014636750/001/store/fgjyisv6hsx1fk6b6sm8ka5gcsxvb7ra-unpinned-file.txt14132026/10/14 16:42:22 INFO Received push request method=POST path=/api/pushes14142026/10/14 16:42:22 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14152026/10/14 16:42:22 INFO Uploading jwcvx2jm9asjanvmxf3fwhbxy1zwgkal-pinned-file.txt (128B)14162026/10/14 16:42:22 WARN Failed to register uploaded object key=jwcvx2jm9asjanvmxf3fwhbxy1zwgkal.ls error="server returned 404: 404 page not found\n"14172026/10/14 16:42:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14182026/10/14 16:42:22 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14192026/10/14 16:42:22 INFO Signed narinfos id=1 count=114202026/10/14 16:42:22 INFO Uploading 1 narinfos14212026/10/14 16:42:22 INFO Received complete push request method=POST path=/api/pushes/1/complete14222026/10/14 16:42:22 WARN Failed to register uploaded object key=jwcvx2jm9asjanvmxf3fwhbxy1zwgkal.narinfo error="server returned 404: 404 page not found\n"14232026/10/14 16:42:22 INFO Completed push id=1 objects=3 duration=25.336667ms14242026/10/14 16:42:22 INFO Upload complete. (215ms)14252026/10/14 16:42:22 INFO Received push request method=POST path=/api/pushes14262026/10/14 16:42:22 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)14272026/10/14 16:42:22 INFO Received push request method=POST path=/api/pushes14282026/10/14 16:42:22 INFO Uploading xqcvqd2sv97b86c7wnxc02d4zl97240d-shared-dep (136B)14292026/10/14 16:42:22 INFO Uploading wbb49pnb7pvzq1wqiz10bg6a0iz6a52s-top (264B)14302026/10/14 16:42:22 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14312026/10/14 16:42:22 INFO Uploading fgjyisv6hsx1fk6b6sm8ka5gcsxvb7ra-unpinned-file.txt (128B)14322026/10/14 16:42:22 WARN Failed to register uploaded object key=xqcvqd2sv97b86c7wnxc02d4zl97240d.ls error="server returned 404: 404 page not found\n"14332026/10/14 16:42:22 WARN Failed to register uploaded object key=wbb49pnb7pvzq1wqiz10bg6a0iz6a52s.ls error="server returned 404: 404 page not found\n"14342026/10/14 16:42:22 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"14352026/10/14 16:42:22 WARN Failed to register uploaded object key=nar/1pawv3k0lb0cq0nd2j8mzsfdg63xk4glp6yc5ab4j4cfm0bd7246.nar.zst error="server returned 404: 404 page not found\n"14362026/10/14 16:42:22 WARN Failed to register uploaded object key=fgjyisv6hsx1fk6b6sm8ka5gcsxvb7ra.ls error="server returned 404: 404 page not found\n"14372026/10/14 16:42:22 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign14382026/10/14 16:42:22 INFO Signed narinfos id=2 count=114392026/10/14 16:42:22 INFO Uploading 1 narinfos14402026/10/14 16:42:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14412026/10/14 16:42:22 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14422026/10/14 16:42:22 INFO Signed narinfos id=1 count=214432026/10/14 16:42:22 INFO Uploading 2 narinfos14442026/10/14 16:42:22 INFO Received complete push request method=POST path=/api/pushes/2/complete14452026/10/14 16:42:22 WARN Failed to register uploaded object key=fgjyisv6hsx1fk6b6sm8ka5gcsxvb7ra.narinfo error="server returned 404: 404 page not found\n"14462026/10/14 16:42:22 INFO Completed push id=2 objects=3 duration=846.041µs14472026/10/14 16:42:22 INFO Upload complete. (179ms)14482026/10/14 16:42:22 INFO Received complete push request method=POST path=/api/pushes/1/complete14492026/10/14 16:42:22 WARN Failed to register uploaded object key=wbb49pnb7pvzq1wqiz10bg6a0iz6a52s.narinfo error="server returned 404: 404 page not found\n"14502026/10/14 16:42:22 WARN Failed to register uploaded object key=xqcvqd2sv97b86c7wnxc02d4zl97240d.narinfo error="server returned 404: 404 page not found\n"14512026/10/14 16:42:22 INFO Completed push id=1 objects=6 duration=8.619458ms14522026/10/14 16:42:22 INFO Upload complete. (259ms)1453=== NAME TestClientSharedPathCommittedMidPush1454 client_integration_test.go:680: Retrieved narinfo from S3:1455 StorePath: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientSharedPathCommittedMidPush578567071/001/store/xqcvqd2sv97b86c7wnxc02d4zl97240d-shared-dep1456 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1457 Compression: zstd1458 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821459 NarSize: 1361460 References: 1461 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1462 client_integration_test.go:680: Retrieved narinfo from S3:1463 StorePath: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientSharedPathCommittedMidPush578567071/001/store/wbb49pnb7pvzq1wqiz10bg6a0iz6a52s-top1464 URL: nar/1pawv3k0lb0cq0nd2j8mzsfdg63xk4glp6yc5ab4j4cfm0bd7246.nar.zst1465 Compression: zstd1466 NarHash: sha256:1pawv3k0lb0cq0nd2j8mzsfdg63xk4glp6yc5ab4j4cfm0bd72461467 NarSize: 2641468 References: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientSharedPathCommittedMidPush578567071/001/store/xqcvqd2sv97b86c7wnxc02d4zl97240d-shared-dep1469 CA: text:sha256:0jr51izrjfqpnhm7kzpgsq3f26spb5r5sj1jfkikvhxn6kc8bsv614702026/10/14 16:42:22 INFO Starting cleanup of old closures method=DELETE path=/api/closures14712026/10/14 16:42:22 INFO Garbage collection started14722026/10/14 16:42:22 INFO Aborted multipart uploads count=0 kept=014732026/10/14 16:42:22 WARN Force mode enabled - objects will be deleted immediately without grace period1474--- PASS: TestClientSharedPathCommittedMidPush (6.35s)1475=== CONT TestParseSize1476--- PASS: TestParseSize (0.00s)1477=== CONT TestGracefulShutdownDrainsInflight14782026/10/14 16:42:22 INFO Starting HTTP server address=127.0.0.1:5789914792026/10/14 16:42:22 INFO Shutdown signal received, draining in-flight requests timeout=10s1480=== NAME TestClientWithDependencies1481 client_integration_test.go:613: Built derivation: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientWithDependencies2750343625/001/store/zimny3063dfdhnwxw072w22b5b1g41f0-test-script14822026/10/14 16:42:22 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=01483=== NAME TestClientMultipleUploads1484 client_integration_test.go:358: Created store path 0: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientMultipleUploads4147793891/001/store/ix4pk4s83zm6k0xsn19jlwn03p38nlpi-test-file-0.txt14852026/10/14 16:42:22 INFO Vacuumed table table=pending_closures1486=== NAME TestClientWithDependencies1487 client_integration_test.go:615: Found 1 dependencies (including self)1488--- PASS: TestReadProxyOutlastsServerWriteTimeout (10.60s)1489=== CONT TestGCTaskStore_PhaseUpdates1490--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1491=== CONT TestPresignedUploadRegisteredBeforeCommit1492--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1493=== CONT TestService_RequireScope_OIDC14942026/10/14 16:42:22 INFO Vacuumed table table=pending_objects14952026/10/14 16:42:22 INFO Vacuumed table table=multipart_uploads14962026/10/14 16:42:22 INFO Vacuumed table table=closures1497=== NAME TestClientMultipleUploads1498 client_integration_test.go:358: Created store path 1: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientMultipleUploads4147793891/001/store/75kay7a68dy9a0i4cfwpx867wh7xcnxp-test-file-1.txt14992026/10/14 16:42:22 INFO Vacuumed table table=objects15002026/10/14 16:42:22 WARN readiness check failed error="closed pool"1501--- PASS: TestService_readinessHandler (5.73s)1502=== CONT TestService_AuthMiddleware_MTLSBoundSubjects15032026/10/14 16:42:22 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57904/oidc15042026/10/14 16:42:22 INFO Received push request method=POST path=/api/pushes1505=== NAME TestClientMultipleUploads1506 client_integration_test.go:358: Created store path 2: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientMultipleUploads4147793891/001/store/2pji8lxafi7br35jjvvh3y5f1ipg3av3-test-file-2.txt15072026/10/14 16:42:22 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15082026/10/14 16:42:22 INFO Uploading zimny3063dfdhnwxw072w22b5b1g41f0-test-script (136B)15092026/10/14 16:42:22 WARN Failed to register uploaded object key=zimny3063dfdhnwxw072w22b5b1g41f0.ls error="server returned 404: 404 page not found\n"15102026/10/14 16:42:22 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"15112026/10/14 16:42:22 WARN Failed to register uploaded object key=log/f1ggrr963n0z24l18b4hg52f768j3nja-test-script.drv error="server returned 404: 404 page not found\n"15122026/10/14 16:42:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15132026/10/14 16:42:22 INFO Signed narinfos id=1 count=115142026/10/14 16:42:22 INFO Uploading 1 narinfos15152026/10/14 16:42:22 INFO Received push request method=POST path=/api/pushes15162026/10/14 16:42:23 INFO Received complete push request method=POST path=/api/pushes/1/complete15172026/10/14 16:42:23 WARN Failed to register uploaded object key=zimny3063dfdhnwxw072w22b5b1g41f0.narinfo error="server returned 404: 404 page not found\n"15182026/10/14 16:42:23 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)15192026/10/14 16:42:23 INFO Uploading ix4pk4s83zm6k0xsn19jlwn03p38nlpi-test-file-0.txt (160B)15202026/10/14 16:42:23 INFO Uploading 75kay7a68dy9a0i4cfwpx867wh7xcnxp-test-file-1.txt (160B)15212026/10/14 16:42:23 INFO Completed push id=1 objects=4 duration=27.99225ms15222026/10/14 16:42:23 INFO Uploading 2pji8lxafi7br35jjvvh3y5f1ipg3av3-test-file-2.txt (160B)15232026/10/14 16:42:23 INFO Upload complete. (242ms)1524=== NAME TestClientWithDependencies1525 client_integration_test.go:617: Skipping nix copy test - isolated store (/private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientWithDependencies2750343625/001/store) requires matching store prefix15262026/10/14 16:42:23 WARN Failed to register uploaded object key=ix4pk4s83zm6k0xsn19jlwn03p38nlpi.ls error="server returned 404: 404 page not found\n"15272026/10/14 16:42:23 WARN Failed to register uploaded object key=75kay7a68dy9a0i4cfwpx867wh7xcnxp.ls error="server returned 404: 404 page not found\n"15282026/10/14 16:42:23 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"15292026/10/14 16:42:23 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"15302026/10/14 16:42:23 WARN Failed to register uploaded object key=2pji8lxafi7br35jjvvh3y5f1ipg3av3.ls error="server returned 404: 404 page not found\n"15312026/10/14 16:42:23 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15322026/10/14 16:42:23 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"15332026/10/14 16:42:23 INFO Signed narinfos id=1 count=315342026/10/14 16:42:23 INFO Uploading 3 narinfos15352026/10/14 16:42:23 WARN Failed to register uploaded object key=2pji8lxafi7br35jjvvh3y5f1ipg3av3.narinfo error="server returned 404: 404 page not found\n"15362026/10/14 16:42:23 WARN Failed to register uploaded object key=75kay7a68dy9a0i4cfwpx867wh7xcnxp.narinfo error="server returned 404: 404 page not found\n"15372026/10/14 16:42:23 INFO Received complete push request method=POST path=/api/pushes/1/complete15382026/10/14 16:42:23 WARN Failed to register uploaded object key=ix4pk4s83zm6k0xsn19jlwn03p38nlpi.narinfo error="server returned 404: 404 page not found\n"1539--- PASS: TestClientWithDependencies (6.48s)1540=== CONT TestService_ReadAuthMiddleware15412026/10/14 16:42:23 INFO Completed push id=1 objects=9 duration=24.17725ms15422026/10/14 16:42:23 INFO Upload complete. (320ms)1543=== NAME TestClientMultipleUploads1544 client_integration_test.go:369: Uploaded 3 paths in 363.282458ms1545--- PASS: TestClientMultipleUploads (6.40s)1546=== CONT TestService_AuthMiddleware_MTLSProxyHeader1547=== NAME TestClientIntegration1548 client_integration_test.go:286: Created store path: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientIntegration1588308241/002/store/p6xgx710ndkbhcxmqf7mmlyiy1ild065-test-file.txt1549--- PASS: TestMetricsInventory (5.80s)1550=== CONT TestService_cleanupPendingClosuresHandler15512026/10/14 16:42:23 INFO Received push request method=POST path=/api/pushes15522026/10/14 16:42:23 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15532026/10/14 16:42:23 INFO Uploading p6xgx710ndkbhcxmqf7mmlyiy1ild065-test-file.txt (152B)15542026/10/14 16:42:23 WARN Failed to register uploaded object key=p6xgx710ndkbhcxmqf7mmlyiy1ild065.ls error="server returned 404: 404 page not found\n"15552026/10/14 16:42:23 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15562026/10/14 16:42:23 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"15572026/10/14 16:42:23 INFO Signed narinfos id=1 count=115582026/10/14 16:42:23 INFO Uploading 1 narinfos15592026/10/14 16:42:23 INFO Received complete push request method=POST path=/api/pushes/1/complete15602026/10/14 16:42:23 WARN Failed to register uploaded object key=p6xgx710ndkbhcxmqf7mmlyiy1ild065.narinfo error="server returned 404: 404 page not found\n"15612026/10/14 16:42:23 INFO Completed push id=1 objects=3 duration=21.1855ms15622026/10/14 16:42:23 INFO Upload complete. (193ms)15632026/10/14 16:42:23 INFO All 1 paths already cached1564=== NAME TestClientIntegration1565 client_integration_test.go:312: Retrieved narinfo from S3:1566 StorePath: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientIntegration1588308241/002/store/p6xgx710ndkbhcxmqf7mmlyiy1ild065-test-file.txt1567 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1568 Compression: zstd1569 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11570 NarSize: 1521571 References: 1572 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11573 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1574 client_integration_test.go:313: Decompressed .ls content (64 bytes):1575 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1576 client_integration_test.go:316: Testing garbage collection...15772026/10/14 16:42:23 INFO Starting cleanup of old closures method=DELETE path=/api/closures15782026/10/14 16:42:23 INFO Garbage collection started15792026/10/14 16:42:23 INFO Aborted multipart uploads count=0 kept=015802026/10/14 16:42:23 WARN Force mode enabled - objects will be deleted immediately without grace period1581--- PASS: TestDeleteClosuresRacingPins (8.63s)1582=== CONT TestService_AuthMiddleware_OIDC15832026/10/14 16:42:23 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=01584=== NAME TestNARDeduplicationMetadataUploadBug1585 metadata_upload_test.go:48: First store path: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestNARDeduplicationMetadataUploadBug3150356592/001/store/3f8vnwl6pw5vr0s6sbmvsj8f7v9vfmpl-file1.txt15862026/10/14 16:42:23 INFO Vacuumed table table=pending_closures15872026/10/14 16:42:23 INFO Vacuumed table table=pending_objects15882026/10/14 16:42:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57943/oidc15892026/10/14 16:42:23 INFO Vacuumed table table=multipart_uploads15902026/10/14 16:42:23 INFO Vacuumed table table=closures15912026/10/14 16:42:23 INFO Vacuumed table table=objects15922026/10/14 16:42:23 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux15932026/10/14 16:42:23 WARN Refused reserved pin name=worker-x86_64-linux15942026/10/14 16:42:23 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux15952026/10/14 16:42:23 INFO Received create pin request method=POST path=/api/pins/my-app15962026/10/14 16:42:23 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1597--- PASS: TestCreatePin_ReservedPins (6.08s)1598=== CONT TestService_createPendingClosureHandler15992026/10/14 16:42:23 INFO Received push request method=POST path=/api/pushes16002026/10/14 16:42:23 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16012026/10/14 16:42:23 INFO Uploading 3f8vnwl6pw5vr0s6sbmvsj8f7v9vfmpl-file1.txt (160B)16022026/10/14 16:42:24 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16032026/10/14 16:42:24 WARN Failed to register uploaded object key=3f8vnwl6pw5vr0s6sbmvsj8f7v9vfmpl.ls error="server returned 404: 404 page not found\n"16042026/10/14 16:42:24 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"16052026/10/14 16:42:24 INFO Signed narinfos id=1 count=116062026/10/14 16:42:24 INFO Uploading 1 narinfos16072026/10/14 16:42:24 INFO Received complete push request method=POST path=/api/pushes/1/complete16082026/10/14 16:42:24 WARN Failed to register uploaded object key=3f8vnwl6pw5vr0s6sbmvsj8f7v9vfmpl.narinfo error="server returned 404: 404 page not found\n"16092026/10/14 16:42:24 INFO Completed push id=1 objects=3 duration=27.401875ms16102026/10/14 16:42:24 INFO Upload complete. (248ms)1611=== NAME TestNARDeduplicationMetadataUploadBug1612 metadata_upload_test.go:54: Retrieved narinfo from S3:1613 StorePath: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestNARDeduplicationMetadataUploadBug3150356592/001/store/3f8vnwl6pw5vr0s6sbmvsj8f7v9vfmpl-file1.txt1614 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1615 Compression: zstd1616 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1617 NarSize: 1601618 References: 1619 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1620 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1621 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1622 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1623 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestNARDeduplicationMetadataUploadBug3150356592/001/store/5b263n7r2dyihg57q7w3z136mbkvgi9g-file2.txt16242026/10/14 16:42:24 INFO Received push request method=POST path=/api/pushes16252026/10/14 16:42:24 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)16262026/10/14 16:42:24 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16272026/10/14 16:42:24 WARN Failed to register uploaded object key=5b263n7r2dyihg57q7w3z136mbkvgi9g.ls error="server returned 404: 404 page not found\n"16282026/10/14 16:42:24 INFO Signed narinfos id=2 count=116292026/10/14 16:42:24 INFO Uploading 1 narinfos16302026/10/14 16:42:24 INFO Received complete push request method=POST path=/api/pushes/2/complete16312026/10/14 16:42:24 WARN Failed to register uploaded object key=5b263n7r2dyihg57q7w3z136mbkvgi9g.narinfo error="server returned 404: 404 page not found\n"16322026/10/14 16:42:24 INFO Completed push id=2 objects=3 duration=1.366459ms16332026/10/14 16:42:24 INFO Upload complete. (231ms)1634 metadata_upload_test.go:76: Retrieved narinfo from S3:1635 StorePath: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestNARDeduplicationMetadataUploadBug3150356592/001/store/5b263n7r2dyihg57q7w3z136mbkvgi9g-file2.txt1636 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1637 Compression: zstd1638 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1639 NarSize: 1601640 References: 1641 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1642 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1643 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1644 {"version":1,"root":{"type":"regular","size":44}}1645--- PASS: TestNARDeduplicationMetadataUploadBug (6.93s)16462026/10/14 16:42:24 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01647=== CONT TestUploadHandlersRejectOversizedBody16482026/10/14 16:42:24 INFO Received create pin request method=POST path=/api/pins/myapp1649=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1650=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1651=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1652=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1653=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1654=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1655=== CONT TestGCTaskStore_CompletedAllowsNewTask1656--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1657=== CONT TestUploadHandlersRejectInvalidKeys1658=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1659=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1660=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1661=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1662=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1663=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1664=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1665=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1666=== CONT TestGCEndsOnShutdown/before_the_run16672026/10/14 16:42:24 INFO Created/updated pin name=myapp store_path=/private/var/tb/4/scratch/b6d1f66d5f951280/build/TestPinProtectsFromGC2014636750/001/store/jwcvx2jm9asjanvmxf3fwhbxy1zwgkal-pinned-file.txt narinfo_key=jwcvx2jm9asjanvmxf3fwhbxy1zwgkal.narinfo16682026/10/14 16:42:24 INFO Starting cleanup of old closures method=DELETE path=/api/closures16692026/10/14 16:42:24 INFO Garbage collection started16702026/10/14 16:42:24 INFO Aborted multipart uploads count=0 kept=016712026/10/14 16:42:24 WARN Force mode enabled - objects will be deleted immediately without grace period16722026/10/14 16:42: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=016732026/10/14 16:42:24 INFO Vacuumed table table=pending_closures16742026/10/14 16:42:24 INFO Vacuumed table table=pending_objects16752026/10/14 16:42:24 INFO Vacuumed table table=multipart_uploads16762026/10/14 16:42:24 INFO Vacuumed table table=closures16772026/10/14 16:42:24 INFO Vacuumed table table=objects16782026/10/14 16:42:25 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01679=== NAME TestClientIntegration1680 client_integration_test.go:323: Objects in database after GC:1681 client_integration_test.go:323: Successfully deleted all objects with GC --force1682--- PASS: TestObjectStatsTrigger (6.78s)1683=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1684--- PASS: TestClientIntegration (8.57s)1685=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete16862026/10/14 16:42:26 INFO Received uploads request method=POST path=/api/pending_closures16872026/10/14 16:42:26 INFO Received uploads request method=POST path=/api/pending_closures16882026/10/14 16:42:26 INFO Received cleanup request method=DELETE path=/api/pending_closures1689=== NAME TestOrphanedObjectsGC1690 orphaned_objects_gc_test.go:287: GC Test Summary:1691 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1692 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1693 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1694 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1695 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1696--- PASS: TestOrphanedObjectsGC (8.27s)1697=== CONT TestProxyWriteTimeout/narinfo1698=== CONT TestProxyWriteTimeout/unknown_size1699=== CONT TestPendingClosureWriteTimeout/empty1700=== CONT TestProxyWriteTimeout/10_GiB_nar1701=== CONT TestProxyWriteTimeout/1_GiB_nar1702=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1703--- PASS: TestProxyWriteTimeout (0.00s)1704 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1705 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1706 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1707 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1708=== NAME TestPinProtectsFromGC1709 client_integration_test.go:840: Pin successfully protected closure from garbage collection17102026/10/14 16:42:26 INFO Received uploads request method=POST path=/api/pending_closures1711--- PASS: TestPinProtectsFromGC (10.79s)1712=== CONT TestPendingClosureWriteTimeout/670k_objects1713=== CONT TestPendingClosureWriteTimeout/400_objects1714=== CONT TestIsValidUploadKey/narinfo1715=== CONT TestIsValidUploadKey/realisation_plus_in_output1716=== CONT TestIsValidUploadKey/realisation1717=== CONT TestIsValidUploadKey/build_log_equals1718=== CONT TestIsValidUploadKey/build_log1719=== CONT TestIsValidUploadKey/listing1720=== CONT TestIsValidUploadKey/nar_plain1721=== CONT TestIsValidUploadKey/build_log_question_mark1722=== CONT TestIsValidUploadKey/nar_xz1723=== CONT TestIsValidUploadKey/nar_zst1724=== CONT TestIsValidUploadKey/traversal_nar1725=== CONT TestIsValidUploadKey/build_log_plus_in_name1726=== CONT TestIsValidUploadKey/build_log_home-manager_file1727=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1728=== CONT TestIsValidUploadKey/traversal1729=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1730=== CONT TestIsValidUploadKey/nix-cache-info1731=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1732=== CONT TestIsValidUploadKey/index.html1733=== CONT TestIsValidUploadKey/empty_key1734=== CONT TestIsValidUploadKey/unknown_type1735=== CONT TestIsValidUploadKey/absolute1736--- PASS: TestIsValidUploadKey (0.01s)1737 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1738 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1739 --- PASS: TestIsValidUploadKey/realisation (0.00s)1740 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1741 --- PASS: TestIsValidUploadKey/build_log (0.00s)1742 --- PASS: TestIsValidUploadKey/listing (0.00s)1743 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1744 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1745 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1746 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1747 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1748 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1749 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1750 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1751 --- PASS: TestIsValidUploadKey/traversal (0.00s)1752 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1753 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1754 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1755 --- PASS: TestIsValidUploadKey/index.html (0.00s)1756 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1757 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1758 --- PASS: TestIsValidUploadKey/absolute (0.00s)1759=== CONT TestResolveDBConnectionString/flag_wins1760=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1761=== CONT TestResolveDBConnectionString/nothing_configured1762=== CONT TestResolveDBConnectionString/file_when_flag_empty1763=== CONT TestResolveDBConnectionString/missing_file_is_an_error1764=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1765--- PASS: TestResolveDBConnectionString (0.02s)1766 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1767 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1768 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1769 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1770 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1771--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (7.50s)1772=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check17732026/10/14 16:42:27 INFO Received uploads request method=POST path=/api/pending_closures17742026/10/14 16:42:27 INFO Received cleanup request method=DELETE path=/api/pending_closures17752026/10/14 16:42:27 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket76/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""17762026/10/14 16:42:27 INFO Aborted multipart uploads count=0 kept=117772026/10/14 16:42:28 INFO Received cleanup request method=DELETE path=/api/pending_closures17782026/10/14 16:42:28 INFO Aborted multipart uploads count=1 kept=017792026/10/14 16:42:28 WARN mTLS auth: subject not in bound subjects subject="CN=reader"17802026/10/14 16:42:28 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1781--- PASS: TestService_NativeMTLS (8.00s)1782=== CONT TestPush_RejectsBadRequests/no_roots17832026/10/14 16:42:28 INFO Received push request method=POST path=/api/pushes1784=== CONT TestPush_RejectsBadRequests/bad_root17852026/10/14 16:42:28 INFO Received push request method=POST path=/api/pushes1786=== CONT TestPush_RejectsBadRequests/root_not_in_objects17872026/10/14 16:42:28 INFO Received push request method=POST path=/api/pushes1788=== CONT TestPush_RejectsBadRequests/no_objects17892026/10/14 16:42:28 INFO Received push request method=POST path=/api/pushes1790--- PASS: TestMultipartCleanup (8.17s)1791=== CONT TestIsValidCachePath/narinfo1792=== CONT TestIsValidCachePath/traversal_parent1793=== CONT TestIsValidCachePath/wrong_extension1794=== CONT TestIsValidCachePath/short_hash1795=== CONT TestIsValidCachePath/empty1796=== CONT TestIsValidCachePath/random_path1797--- PASS: TestPush_RejectsBadRequests (7.24s)1798 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1799 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1800 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1801 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1802=== CONT TestIsValidCachePath/invalid_char_u1803=== CONT TestIsValidCachePath/leading_slash1804=== CONT TestIsValidCachePath/traversal_in_middle1805=== CONT TestIsValidCachePath/ls1806=== CONT TestIsValidCachePath/index.html1807=== CONT TestIsValidCachePath/nix-cache-info1808=== CONT TestIsValidCachePath/realisation1809=== CONT TestIsValidCachePath/invalid_char_e1810=== CONT TestIsValidCachePath/nar_xz1811=== CONT TestIsValidCachePath/nar_uncompressed1812=== CONT TestIsValidCachePath/nar_bz21813=== CONT TestIsValidCachePath/nar_zst1814=== CONT TestIsValidCachePath/log1815=== CONT TestParseSingleRange/none1816=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1817--- PASS: TestIsValidCachePath (0.05s)1818 --- PASS: TestIsValidCachePath/narinfo (0.00s)1819 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1820 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1821 --- PASS: TestIsValidCachePath/short_hash (0.00s)1822 --- PASS: TestIsValidCachePath/empty (0.00s)1823 --- PASS: TestIsValidCachePath/random_path (0.00s)1824 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1825 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1826 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1827 --- PASS: TestIsValidCachePath/ls (0.00s)1828 --- PASS: TestIsValidCachePath/index.html (0.00s)1829 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1830 --- PASS: TestIsValidCachePath/realisation (0.00s)1831 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1832 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1833 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1834 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1835 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1836 --- PASS: TestIsValidCachePath/log (0.00s)1837 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1838=== CONT TestParseSingleRange/open-ended1839=== CONT TestParseSingleRange/start_past_EOF1840=== CONT TestParseSingleRange/start_far_past_EOF1841=== CONT TestParseSingleRange/suffix_exceeds_size1842=== CONT TestParseSingleRange/suffix1843=== CONT TestParseSingleRange/end_clamped_to_size1844=== CONT TestParseSingleRange/single_byte1845=== CONT TestParseSingleRange/closed1846=== CONT TestParseSingleRange/malformed_both_empty1847=== CONT TestParseSingleRange/unknown_unit1848=== CONT TestParseSingleRange/malformed_end_before_start1849=== CONT TestParseSingleRange/multi-range_ignored1850=== CONT TestParseSingleRange/malformed_no_dash1851--- PASS: TestParseSingleRange (0.00s)1852 --- PASS: TestParseSingleRange/none (0.00s)1853 --- PASS: TestParseSingleRange/open-ended (0.00s)1854 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1855 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1856 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1857 --- PASS: TestParseSingleRange/suffix (0.00s)1858 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1859 --- PASS: TestParseSingleRange/single_byte (0.00s)1860 --- PASS: TestParseSingleRange/closed (0.00s)1861 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1862 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1863 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1864 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1865 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1866=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1867=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1868--- PASS: TestCacheStatsHandler (8.32s)1869=== CONT TestServerTLSConfig/no_client_CA1870=== CONT TestServerTLSConfig/not_a_PEM_file1871=== CONT TestServerTLSConfig/missing_CA_file1872--- PASS: TestServerTLSConfig (0.00s)1873 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1874 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1875 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1876=== CONT TestClientErrorHandling/InvalidStorePath1877--- PASS: TestService_Rustfstest (8.18s)1878=== CONT TestClientErrorHandling/ServerNotAvailable1879=== NAME TestClientCADerivations1880 client_ca_test.go:136: Built CA derivation: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientCADerivations2028616445/001/store/x5xyr183bd3ki4d15ys70g1kllyxkw93-ca-test1881 client_ca_test.go:139: Found 1 dependencies (including self)18822026/10/14 16:42:30 INFO Received push request method=POST path=/api/pushes18832026/10/14 16:42:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18842026/10/14 16:42:30 INFO Uploading x5xyr183bd3ki4d15ys70g1kllyxkw93-ca-test (144B)18852026/10/14 16:42:30 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18862026/10/14 16:42:30 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/present18872026/10/14 16:42:30 WARN Failed to register uploaded object key=x5xyr183bd3ki4d15ys70g1kllyxkw93.ls error="server returned 404: 404 page not found\n"18882026/10/14 16:42:30 WARN Failed to register uploaded object key=log/2c513nk41r946812qdr7q3r93cdzbkwa-ca-test.drv error="server returned 404: 404 page not found\n"18892026/10/14 16:42:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18902026/10/14 16:42:30 INFO Signed narinfos id=1 count=118912026/10/14 16:42:30 INFO Uploading 1 narinfos1892--- PASS: TestService_healthCheckHandler (8.66s)1893=== CONT TestClientErrorHandling/InvalidAuthToken18942026/10/14 16:42:30 INFO Received complete push request method=POST path=/api/pushes/1/complete18952026/10/14 16:42:30 WARN Failed to register uploaded object key=x5xyr183bd3ki4d15ys70g1kllyxkw93.narinfo error="server returned 404: 404 page not found\n"18962026/10/14 16:42:30 WARN Request failed, retrying attempt=2 backoff=206.129585ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18972026/10/14 16:42:30 INFO Completed push id=1 objects=4 duration=90.56025ms18982026/10/14 16:42:30 INFO Upload complete. (530ms)1899=== NAME TestClientCADerivations1900 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientCADerivations2028616445/001/store/x5xyr183bd3ki4d15ys70g1kllyxkw93-ca-test1901 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1902 Compression: zstd1903 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1904 NarSize: 1441905 References: 1906 Deriver: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientCADerivations2028616445/001/store/2c513nk41r946812qdr7q3r93cdzbkwa-ca-test.drv1907 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1908 client_ca_test.go:185: Checking for realisation files in S3...1909 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1910 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache19112026/10/14 16:42:30 WARN Request failed, retrying attempt=3 backoff=367.432394ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1912 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket78?endpoint=http://localhost:57582®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/4/scratch/b6d1f66d5f951280/build/TestClientCADerivations2028616445/001/store'1913 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11914--- PASS: TestService_ReadScope_PublicByDefault (8.69s)1915=== CONT TestCacheConfigHandler/full_config,_no_issuer1916=== CONT TestCacheConfigHandler/no_signing_keys1917=== CONT TestCacheConfigHandler/no_cache_url_configured1918=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1919--- PASS: TestCacheConfigHandler (0.00s)1920 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1921 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1922 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1923 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1924=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19252026/10/14 16:42:30 INFO Received uploads request method=POST path=/1926--- PASS: TestClientCADerivations (10.54s)19272026/10/14 16:42:30 WARN Request failed, retrying attempt=4 backoff=869.332642ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1928=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19292026/10/14 16:42:30 INFO Received request for more parts method=POST path=/1930=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart19312026/10/14 16:42:31 INFO Received complete multipart upload request method=POST path=/1932=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info19332026/10/14 16:42:31 INFO Received uploads request method=POST path=/1934=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key19352026/10/14 16:42:31 INFO Received complete multipart upload request method=POST path=/1936=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key19372026/10/14 16:42:31 INFO Received request for more parts method=POST path=/1938=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal19392026/10/14 16:42:31 INFO Received uploads request method=POST path=/1940--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1941 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1942 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1943 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1944 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1945--- PASS: TestUploadHandlersRejectOversizedBody (0.05s)1946 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.03s)1947 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1948 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.31s)19492026/10/14 16:42:31 INFO Received uploads request method=POST path=/api/pending_closures19502026/10/14 16:42:31 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst19512026/10/14 16:42:31 INFO Received uploads request method=POST path=/api/pending_closures1952--- PASS: TestPresignedUploadRegisteredBeforeCommit (8.67s)1953=== RUN TestService_RequireScope_OIDC/builder_may_write1954=== PAUSE TestService_RequireScope_OIDC/builder_may_write1955=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1956=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1957=== RUN TestService_RequireScope_OIDC/ops_may_admin1958=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1959=== RUN TestService_RequireScope_OIDC/ops_may_not_write1960=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1961=== RUN TestService_RequireScope_OIDC/reader_may_not_write1962=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1963=== RUN TestService_RequireScope_OIDC/static_token_may_admin1964=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1965=== RUN TestService_RequireScope_OIDC/static_token_may_write1966=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1967=== RUN TestService_RequireScope_OIDC/reader_may_read1968=== PAUSE TestService_RequireScope_OIDC/reader_may_read1969=== RUN TestService_RequireScope_OIDC/writer_implies_read1970=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1971=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1972=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1973=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1974=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1975=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1976=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1977=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1978=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1979=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1980=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1981=== CONT TestService_RequireScope_OIDC/builder_may_write1982=== CONT TestService_RequireScope_OIDC/reader_may_read1983=== CONT TestService_RequireScope_OIDC/reader_may_not_write1984=== CONT TestService_RequireScope_OIDC/static_token_may_write1985=== CONT TestService_RequireScope_OIDC/ops_may_not_write1986=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1987=== CONT TestService_RequireScope_OIDC/static_token_may_admin19882026/10/14 16:42:31 WARN Request failed, retrying attempt=5 backoff=1.659711625s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1989=== CONT TestService_RequireScope_OIDC/ops_may_admin1990=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1991=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc19922026/10/14 16:42:31 WARN Authentication failed token_preview=wrong token_length=5 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]1993=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1994=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1995=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1996=== CONT TestService_RequireScope_OIDC/writer_implies_read1997--- PASS: TestService_RequireScope_OIDC (9.06s)1998 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.01s)1999 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2000 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2001 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2002 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2003 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2004 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2005 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2006 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2007 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.01s)2008 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2009 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2010 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2011 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)20122026/10/14 16:42:32 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20132026/10/14 16:42:32 WARN mTLS auth: bound subjects configured but subject DN unavailable20142026/10/14 16:42:32 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2015--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (9.57s)20162026/10/14 16:42:32 INFO Aborted multipart uploads count=1 kept=020172026/10/14 16:42:32 INFO Received cleanup request method=DELETE path=/api/pending_closures20182026/10/14 16:42:32 INFO Aborted multipart uploads count=1 kept=02019--- PASS: TestPendingCleanupUsesOneCutoff (13.24s)2020--- PASS: TestService_ReadAuthMiddleware (9.83s)20212026/10/14 16:42:33 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-config2022--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (10.36s)20232026/10/14 16:42:33 WARN Request failed, retrying attempt=2 backoff=215.722581ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20242026/10/14 16:42:33 WARN Request failed, retrying attempt=3 backoff=435.891277ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20252026/10/14 16:42:34 INFO Received cleanup request method=DELETE path=/api/pending_closures20262026/10/14 16:42:34 INFO Aborted multipart uploads count=0 kept=020272026/10/14 16:42:34 INFO Received uploads request method=POST path=/api/pending_closures20282026/10/14 16:42:34 WARN Request failed, retrying attempt=4 backoff=772.964249ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20292026/10/14 16:42:34 INFO Received cleanup request method=DELETE path=/api/pending_closures20302026/10/14 16:42:34 INFO Aborted multipart uploads count=1 kept=020312026/10/14 16:42:34 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20322026-10-14 16:42:34.533 UTC [12221] ERROR: Closure does not exist: id=120332026-10-14 16:42:34.533 UTC [12221] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE20342026-10-14 16:42:34.533 UTC [12221] STATEMENT: -- name: CommitPendingClosure :one2035 SELECT commit_pending_closure($1::bigint)::bigint2036 2037--- PASS: TestService_cleanupPendingClosuresHandler (11.10s)2038=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2039=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2040=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2041=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2042=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2043=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2044=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2045=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2046=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2047=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20482026/10/14 16:42:34 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]2049=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2050=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20512026/10/14 16:42:34 WARN Authentication failed token_preview=eyJhbGciOi...NpjA3zFOSw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2052--- PASS: TestService_AuthMiddleware_OIDC (11.09s)2053 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)2054 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.01s)2055 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2056 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)20572026/10/14 16:42:35 WARN Request failed, retrying attempt=5 backoff=1.755465405s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20582026/10/14 16:42:35 INFO Received uploads request method=POST path=/api/pending_closures20592026/10/14 16:42:35 INFO Received uploads request method=POST path=/api/pending_closures20602026/10/14 16:42:35 INFO Received uploads request method=POST path=/api/pending_closures20612026/10/14 16:42:36 INFO Aborted multipart uploads count=0 kept=020622026/10/14 16:42:36 WARN Force mode enabled - objects will be deleted immediately without grace period20632026/10/14 16:42:36 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:57582/bucket92/?delete=\": context canceled"20642026/10/14 16:42:36 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"20652026/10/14 16:42:36 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-config20662026/10/14 16:42:37 WARN Request failed, retrying attempt=2 backoff=183.567352ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20672026/10/14 16:42:37 INFO Aborted multipart uploads count=0 kept=020682026/10/14 16:42:37 WARN Force mode enabled - objects will be deleted immediately without grace period20692026-10-14 16:42:37.225 UTC [12727] ERROR: canceling statement due to user request20702026-10-14 16:42:37.225 UTC [12727] STATEMENT: -- name: MarkStaleObjects :execrows2071 WITH RECURSIVE ct AS (2072 SELECT timezone('UTC', now()) AS now2073 ),2074 closure_reach AS (2075 -- Start with all closure keys2076 SELECT o.key, o.refs2077 FROM objects o2078 INNER JOIN closures c ON o.key = c.key2079 UNION2080 -- Recursively add all referenced objects2081 SELECT o.key, o.refs2082 FROM objects o2083 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2084 ),2085 reachable_objects AS (2086 SELECT DISTINCT key FROM closure_reach2087 ),2088 stale_objects AS (2089 SELECT o.key2090 FROM objects AS o, ct2091 WHERE2092 NOT EXISTS (2093 SELECT 12094 FROM reachable_objects ro2095 WHERE ro.key = o.key2096 )2097 AND NOT EXISTS (2098 SELECT 12099 FROM pending_objects AS po2100 WHERE po.key = o.key2101 )2102 AND o.deleted_at IS NULL -- Only mark fresh objects2103 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2104 FOR UPDATE2105 )2106 UPDATE objects2107 SET2108 deleted_at = ct.now,2109 first_deleted_at = COALESCE(first_deleted_at, ct.now)2110 FROM stale_objects, ct2111 WHERE objects.key = stale_objects.key2112 21132026/10/14 16:42:37 WARN Request failed, retrying attempt=3 backoff=370.197228ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2114--- PASS: TestGCEndsOnShutdown (0.00s)2115 --- PASS: TestGCEndsOnShutdown/before_the_run (11.41s)2116 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (10.78s)2117 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (11.44s)21182026/10/14 16:42:37 WARN Request failed, retrying attempt=4 backoff=870.113569ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21192026/10/14 16:42:37 INFO Received uploads request method=POST path=/api/pending_closures21202026/10/14 16:42:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21212026/10/14 16:42:38 INFO Received uploads request method=POST path=/api/pending_closures21222026/10/14 16:42:38 INFO Aborted multipart uploads count=0 kept=021232026/10/14 16:42:38 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YjVjYmI1YzItY2EwMS00ZjU1LThmNmItZWNiY2U3MWI2NTdhLjVjNzEzNmFiLWEwYjUtNDQwNC1hMGNlLWYxNjNlNzkzMjZmNngxNzkxOTk2MTU1NDg3MTMxMDAw parts=1021242026/10/14 16:42:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21252026/10/14 16:42:38 WARN Force mode enabled - objects will be deleted immediately without grace period21262026/10/14 16:42:38 INFO Completed upload id=1 objects=2 duration=15.671791ms21272026/10/14 16:42:38 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000021282026/10/14 16:42:38 INFO Received uploads request method=POST path=/api/pending_closures21292026/10/14 16:42:38 INFO Starting cleanup of old closures method=DELETE path=/api/closures21302026/10/14 16:42:38 INFO Aborted multipart uploads count=0 kept=021312026/10/14 16:42:38 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=021322026/10/14 16:42:38 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=021332026/10/14 16:42:38 INFO Vacuumed table table=pending_closures21342026/10/14 16:42:38 INFO Vacuumed table table=pending_objects21352026/10/14 16:42:38 INFO Vacuumed table table=multipart_uploads21362026/10/14 16:42:38 INFO Vacuumed table table=closures21372026/10/14 16:42:38 INFO Vacuumed table table=pending_closures21382026/10/14 16:42:38 INFO Vacuumed table table=pending_objects21392026/10/14 16:42:38 INFO Vacuumed table table=objects21402026/10/14 16:42:38 WARN Request failed, retrying attempt=5 backoff=1.589352139s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21412026/10/14 16:42:38 INFO Vacuumed table table=multipart_uploads2142--- PASS: TestPendingClosureWriteTimeout (0.00s)2143 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2144 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2145 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2146 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (11.93s)21472026/10/14 16:42:38 INFO Vacuumed table table=closures21482026/10/14 16:42:38 INFO Vacuumed table table=objects21492026/10/14 16:42:38 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000002150--- PASS: TestService_createPendingClosureHandler (14.78s)21512026/10/14 16:42:38 INFO Received uploads request method=POST path=/api/pending_closures21522026/10/14 16:42:38 INFO Aborted multipart uploads count=0 kept=021532026/10/14 16:42:38 WARN Force mode enabled - objects will be deleted immediately without grace period21542026/10/14 16:42:38 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=021552026/10/14 16:42:38 INFO Vacuumed table table=pending_closures21562026/10/14 16:42:38 INFO Vacuumed table table=pending_objects21572026/10/14 16:42:38 INFO Vacuumed table table=multipart_uploads21582026/10/14 16:42:38 INFO Vacuumed table table=closures21592026/10/14 16:42:38 INFO Vacuumed table table=objects2160--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2161 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (11.63s)2162 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (11.97s)21632026/10/14 16:42:40 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_closures2164--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2165 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (11.50s)2166 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (11.97s)21672026/10/14 16:42:40 WARN Request failed, retrying attempt=2 backoff=197.592515ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21682026/10/14 16:42:40 WARN Request failed, retrying attempt=3 backoff=375.110532ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21692026-10-14 16:42:40.658 UTC [11478] LOG: checkpoint starting: wal21702026/10/14 16:42:40 WARN Request failed, retrying attempt=4 backoff=876.75011ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21712026/10/14 16:42:40 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21722026/10/14 16:42:40 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2173--- PASS: TestObjectStatsLargeCommit (22.16s)21742026/10/14 16:42:41 WARN Request failed, retrying attempt=5 backoff=1.480024327s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2175=== NAME TestOrphanedObjectsGCStressTest2176 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2177 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion2178--- PASS: TestClientErrorHandling (0.00s)2179 --- PASS: TestClientErrorHandling/InvalidStorePath (10.60s)2180 --- PASS: TestClientErrorHandling/InvalidAuthToken (10.63s)2181 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.35s)2182=== NAME TestOrphanedObjectsGCStressTest2183 orphaned_objects_gc_test.go:503: Stress test completed successfully:2184 orphaned_objects_gc_test.go:504: - Active objects preserved: 202185 orphaned_objects_gc_test.go:505: - Objects deleted: 2102186 orphaned_objects_gc_test.go:506: - Total GC'd: 2102187--- PASS: TestOrphanedObjectsGCStressTest (25.32s)2188PASS2189{"timestamp":"2026-10-14T16:42:43.377106Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:57699","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2386,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}21902026-10-14 16:42:43.493 UTC [11473] LOG: received smart shutdown request21912026-10-14 16:42:43.494 UTC [11473] LOG: background worker "logical replication launcher" (PID 11483) exited with exit code 121922026-10-14 16:42:44.712 UTC [11478] LOG: checkpoint complete: wrote 12915 buffers (78.8%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=3.324 s, sync=0.633 s, total=4.054 s; sync files=34045, longest=0.002 s, average=0.001 s; distance=532999 kB, estimate=532999 kB; lsn=0/22C57F90, redo lsn=0/2200ED5821932026-10-14 16:42:44.713 UTC [11478] LOG: shutting down21942026-10-14 16:42:44.713 UTC [11478] LOG: checkpoint starting: shutdown immediate21952026-10-14 16:42:44.715 UTC [11478] LOG: checkpoint complete: wrote 173 buffers (1.1%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.002 s; sync files=10, longest=0.001 s, average=0.001 s; distance=12580 kB, estimate=480957 kB; lsn=0/22C58020, redo lsn=0/22C5802021962026-10-14 16:42:44.721 UTC [11473] LOG: database system is shut down2197Running OIDC tests...2198=== RUN TestAudienceForIssuer2199=== PAUSE TestAudienceForIssuer2200=== RUN TestGlobMatch2201=== PAUSE TestGlobMatch2202=== RUN TestValidateToken_ValidToken2203=== PAUSE TestValidateToken_ValidToken2204=== RUN TestValidateToken_WrongAudience2205=== PAUSE TestValidateToken_WrongAudience2206=== RUN TestValidateToken_Expired2207=== PAUSE TestValidateToken_Expired2208=== RUN TestValidateToken_BoundClaimsMismatch2209=== PAUSE TestValidateToken_BoundClaimsMismatch2210=== RUN TestValidateToken_BoundSubjectMismatch2211=== PAUSE TestValidateToken_BoundSubjectMismatch2212=== RUN TestValidateToken_MultipleProviders2213=== PAUSE TestValidateToken_MultipleProviders2214=== RUN TestValidateToken_NoMatchingProvider2215=== PAUSE TestValidateToken_NoMatchingProvider2216=== RUN TestValidateToken_KubernetesServiceAccount2217=== PAUSE TestValidateToken_KubernetesServiceAccount2218=== RUN TestNewValidator_KubernetesRequiresCA2219=== PAUSE TestNewValidator_KubernetesRequiresCA2220=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2221=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2222=== RUN TestPins_ReservedForMatchingRule2223=== PAUSE TestPins_ReservedForMatchingRule2224=== RUN TestPins_TopLevelShorthand2225=== PAUSE TestPins_TopLevelShorthand2226=== RUN TestPins_ConfigValidation2227=== PAUSE TestPins_ConfigValidation2228=== RUN TestScopes_LegacyProviderDefaultsToWrite2229=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2230=== RUN TestScopes_Rules2231=== PAUSE TestScopes_Rules2232=== RUN TestScopes_ConfigValidation2233=== PAUSE TestScopes_ConfigValidation2234=== CONT TestAudienceForIssuer2235--- PASS: TestAudienceForIssuer (0.00s)2236=== CONT TestValidateToken_BoundClaimsMismatch2237=== CONT TestValidateToken_MultipleProviders2238=== CONT TestValidateToken_Expired2239=== CONT TestValidateToken_WrongAudience2240=== CONT TestValidateToken_ValidToken2241=== CONT TestGlobMatch2242=== RUN TestGlobMatch/foo_foo2243=== PAUSE TestGlobMatch/foo_foo2244=== RUN TestGlobMatch/foo_bar2245=== PAUSE TestGlobMatch/foo_bar2246=== RUN TestGlobMatch/*_2247=== PAUSE TestGlobMatch/*_2248=== RUN TestGlobMatch/*_anything2249=== PAUSE TestGlobMatch/*_anything2250=== RUN TestGlobMatch/foo*_foo2251=== PAUSE TestGlobMatch/foo*_foo2252=== RUN TestGlobMatch/foo*_foobar2253=== PAUSE TestGlobMatch/foo*_foobar2254=== RUN TestGlobMatch/foo*_bar2255=== PAUSE TestGlobMatch/foo*_bar2256=== RUN TestGlobMatch/*bar_bar2257=== PAUSE TestGlobMatch/*bar_bar2258=== RUN TestGlobMatch/*bar_foobar2259=== PAUSE TestGlobMatch/*bar_foobar2260=== RUN TestGlobMatch/*bar_foo2261=== PAUSE TestGlobMatch/*bar_foo2262=== RUN TestGlobMatch/foo*bar_foobar2263=== PAUSE TestGlobMatch/foo*bar_foobar2264=== RUN TestGlobMatch/foo*bar_foo123bar2265=== PAUSE TestGlobMatch/foo*bar_foo123bar2266=== RUN TestGlobMatch/foo*bar_foobarbaz2267=== PAUSE TestGlobMatch/foo*bar_foobarbaz2268=== RUN TestGlobMatch/*/*_foo/bar2269=== PAUSE TestGlobMatch/*/*_foo/bar2270=== RUN TestGlobMatch/*/*_foo2271=== PAUSE TestGlobMatch/*/*_foo2272=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2273=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2274=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02275=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02276=== RUN TestGlobMatch/refs/*/main_refs/heads/main2277=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2278=== RUN TestGlobMatch/fo?_foo2279=== PAUSE TestGlobMatch/fo?_foo2280=== RUN TestGlobMatch/fo?_fo2281=== PAUSE TestGlobMatch/fo?_fo2282=== RUN TestGlobMatch/fo?_fooo2283=== PAUSE TestGlobMatch/fo?_fooo2284=== RUN TestGlobMatch/?oo_foo2285=== PAUSE TestGlobMatch/?oo_foo2286=== RUN TestGlobMatch/?oo_boo2287=== PAUSE TestGlobMatch/?oo_boo2288=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2289=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2290=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2291=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2292=== CONT TestGlobMatch/foo_foo2293=== CONT TestPins_ConfigValidation2294=== CONT TestGlobMatch/*/*_foo/bar2295=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2296=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2297=== CONT TestGlobMatch/?oo_boo2298=== CONT TestGlobMatch/?oo_foo2299=== CONT TestGlobMatch/fo?_fooo2300=== CONT TestGlobMatch/fo?_fo2301=== CONT TestGlobMatch/fo?_foo2302=== CONT TestGlobMatch/refs/*/main_refs/heads/main2303=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02304=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2305=== CONT TestGlobMatch/*/*_foo2306=== CONT TestGlobMatch/*bar_bar2307=== CONT TestGlobMatch/foo*bar_foobarbaz2308=== CONT TestGlobMatch/foo*bar_foo123bar2309=== CONT TestGlobMatch/foo*bar_foobar2310=== CONT TestGlobMatch/*bar_foo2311=== CONT TestGlobMatch/*bar_foobar2312=== CONT TestGlobMatch/foo*_foo2313=== CONT TestGlobMatch/foo*_bar2314=== CONT TestGlobMatch/foo*_foobar2315=== CONT TestGlobMatch/*_2316=== CONT TestGlobMatch/*_anything2317=== CONT TestGlobMatch/foo_bar2318--- PASS: TestGlobMatch (0.00s)2319 --- PASS: TestGlobMatch/foo_foo (0.00s)2320 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2321 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2322 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2323 --- PASS: TestGlobMatch/?oo_boo (0.00s)2324 --- PASS: TestGlobMatch/?oo_foo (0.00s)2325 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2326 --- PASS: TestGlobMatch/fo?_fo (0.00s)2327 --- PASS: TestGlobMatch/fo?_foo (0.00s)2328 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2329 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2330 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2331 --- PASS: TestGlobMatch/*/*_foo (0.00s)2332 --- PASS: TestGlobMatch/*bar_bar (0.00s)2333 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2334 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2335 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2336 --- PASS: TestGlobMatch/*bar_foo (0.00s)2337 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2338 --- PASS: TestGlobMatch/foo*_foo (0.00s)2339 --- PASS: TestGlobMatch/foo*_bar (0.00s)2340 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2341 --- PASS: TestGlobMatch/*_ (0.00s)2342 --- PASS: TestGlobMatch/*_anything (0.00s)2343 --- PASS: TestGlobMatch/foo_bar (0.00s)2344=== CONT TestScopes_ConfigValidation2345=== CONT TestScopes_Rules2346--- PASS: TestScopes_ConfigValidation (0.00s)2347--- PASS: TestPins_ConfigValidation (0.00s)2348=== CONT TestScopes_LegacyProviderDefaultsToWrite2349=== CONT TestValidateToken_BoundSubjectMismatch2350=== CONT TestPins_ReservedForMatchingRule2351=== CONT TestPins_TopLevelShorthand2352=== CONT TestValidateToken_NoMatchingProvider2353=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2354=== CONT TestValidateToken_KubernetesServiceAccount2355=== CONT TestNewValidator_KubernetesRequiresCA23562026/10/14 16:42:46 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58096/oidc2357--- PASS: TestValidateToken_WrongAudience (0.04s)23582026/10/14 16:42:46 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58101/oidc2359--- PASS: TestValidateToken_Expired (0.06s)23602026/10/14 16:42:46 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58099/oidc23612026/10/14 16:42:46 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58105/oidc23622026/10/14 16:42:46 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58103/oidc2363--- PASS: TestScopes_Rules (0.06s)2364--- PASS: TestValidateToken_BoundClaimsMismatch (0.07s)23652026/10/14 16:42:46 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58107/oidc2366--- PASS: TestPins_ReservedForMatchingRule (0.06s)2367--- PASS: TestValidateToken_BoundSubjectMismatch (0.07s)23682026/10/14 16:42:46 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58109/oidc2369--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.07s)23702026/10/14 16:42:46 http: TLS handshake error from 127.0.0.1:58112: read tcp 127.0.0.1:58111->127.0.0.1:58112: use of closed network connection2371--- PASS: TestNewValidator_KubernetesRequiresCA (0.08s)23722026/10/14 16:42:46 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58113/oidc2373--- PASS: TestPins_TopLevelShorthand (0.10s)23742026/10/14 16:42:46 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:581152375--- PASS: TestValidateToken_KubernetesServiceAccount (0.10s)23762026/10/14 16:42:46 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58118/oidc2377--- PASS: TestValidateToken_ValidToken (0.12s)23782026/10/14 16:42:46 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232379--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.11s)23802026/10/14 16:42:46 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:58098/oidc23812026/10/14 16:42:46 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:58122/oidc2382--- PASS: TestValidateToken_MultipleProviders (0.13s)23832026/10/14 16:42:46 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:58117/oidc2384--- PASS: TestValidateToken_NoMatchingProvider (0.18s)2385PASS2386Running hook tests...2387=== RUN TestSendPathsEmpty2388=== PAUSE TestSendPathsEmpty2389=== RUN TestQueueEnqueueAndFetch2390=== PAUSE TestQueueEnqueueAndFetch2391=== RUN TestQueueDeduplication2392=== PAUSE TestQueueDeduplication2393=== RUN TestQueueRemove2394=== PAUSE TestQueueRemove2395=== RUN TestQueueFetchBatchLimit2396=== PAUSE TestQueueFetchBatchLimit2397=== RUN TestQueueRetryMovesToBack2398=== PAUSE TestQueueRetryMovesToBack2399=== RUN TestQueueFetchRemoveLifecycle2400=== PAUSE TestQueueFetchRemoveLifecycle2401=== RUN TestQueueConcurrentWriters2402=== PAUSE TestQueueConcurrentWriters2403=== RUN TestQueueRemoveLargeClosure2404=== PAUSE TestQueueRemoveLargeClosure2405=== RUN TestServerClientIntegration2406--- PASS: TestServerClientIntegration (0.00s)2407=== RUN TestServerQueueError24082026/10/14 16:42:46 ERROR Failed to queue paths error="permission denied" count=12409--- PASS: TestServerQueueError (0.00s)2410=== RUN TestGetListenerSocketActivation2411 server_test.go:146: systemd socket activation does not exist on darwin2412--- SKIP: TestGetListenerSocketActivation (0.00s)2413=== RUN TestDrainIsolatesPoisonPath2414=== PAUSE TestDrainIsolatesPoisonPath2415=== RUN TestRunNotBlockedByPoisonHead2416=== PAUSE TestRunNotBlockedByPoisonHead2417=== RUN TestDrainGivesUpWhenServerDown2418=== PAUSE TestDrainGivesUpWhenServerDown2419=== RUN TestFailedPathPrunedByLaterClosure2420=== PAUSE TestFailedPathPrunedByLaterClosure2421=== RUN TestWorkerUploadsAndRemoves2422=== PAUSE TestWorkerUploadsAndRemoves2423=== RUN TestWorkerSkipsGCdPaths2424=== PAUSE TestWorkerSkipsGCdPaths2425=== RUN TestWorkerPrunesClosureDeps2426=== PAUSE TestWorkerPrunesClosureDeps2427=== RUN TestDrainTimeout2428=== PAUSE TestDrainTimeout2429=== CONT TestSendPathsEmpty2430=== CONT TestDrainIsolatesPoisonPath2431--- PASS: TestSendPathsEmpty (0.00s)2432=== CONT TestQueueRemoveLargeClosure2433=== CONT TestQueueConcurrentWriters2434=== CONT TestQueueFetchRemoveLifecycle2435=== CONT TestQueueRetryMovesToBack2436=== CONT TestWorkerUploadsAndRemoves2437=== CONT TestQueueFetchBatchLimit2438=== CONT TestDrainTimeout2439=== CONT TestQueueRemove2440=== CONT TestWorkerPrunesClosureDeps2441=== CONT TestWorkerSkipsGCdPaths2442=== CONT TestQueueDeduplication2443=== CONT TestDrainGivesUpWhenServerDown2444=== CONT TestQueueEnqueueAndFetch2445=== CONT TestFailedPathPrunedByLaterClosure2446=== CONT TestRunNotBlockedByPoisonHead24472026/10/14 16:42:46 INFO Upload queue status pending=324482026/10/14 16:42:46 INFO Upload queue status pending=224492026/10/14 16:42:46 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/b6d1f66d5f951280/build/TestWorkerSkipsGCdPaths1488584837/002/nonexistent2450--- PASS: TestQueueEnqueueAndFetch (0.01s)2451--- PASS: TestQueueFetchBatchLimit (0.01s)24522026/10/14 16:42:46 INFO Uploading batch count=124532026/10/14 16:42:46 ERROR Upload failed error="upload failed" count=124542026/10/14 16:42:46 INFO Uploading batch count=124552026/10/14 16:42:46 INFO Uploading batch count=124562026/10/14 16:42:46 ERROR Upload failed error="upload failed" count=124572026/10/14 16:42:46 INFO Uploading batch count=224582026/10/14 16:42:46 ERROR Upload failed error="upload failed" count=224592026/10/14 16:42:46 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/b6d1f66d5f951280/build/TestDrainGivesUpWhenServerDown3651738945/002/a24602026/10/14 16:42:46 INFO Uploading batch count=424612026/10/14 16:42:46 ERROR Upload failed error="upload failed" count=424622026/10/14 16:42:46 INFO Uploading batch count=224632026/10/14 16:42:46 INFO Upload queue status pending=224642026/10/14 16:42:46 INFO Uploading batch count=12465--- PASS: TestQueueFetchRemoveLifecycle (0.02s)24662026/10/14 16:42:46 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/b6d1f66d5f951280/build/TestDrainGivesUpWhenServerDown3651738945/002/b24672026/10/14 16:42:46 INFO Uploading batch count=124682026/10/14 16:42:46 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/b6d1f66d5f951280/build/TestDrainIsolatesPoisonPath1474887043/002/bbb2469--- PASS: TestQueueRetryMovesToBack (0.02s)24702026/10/14 16:42:46 INFO Upload queue status pending=224712026/10/14 16:42:46 INFO Uploading batch count=22472--- PASS: TestQueueDeduplication (0.02s)24732026/10/14 16:42:46 INFO Uploading batch count=124742026/10/14 16:42:46 INFO Uploading batch count=224752026/10/14 16:42:46 ERROR Upload failed error="upload failed" count=224762026/10/14 16:42:46 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/b6d1f66d5f951280/build/TestDrainGivesUpWhenServerDown3651738945/002/c24772026/10/14 16:42:46 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/b6d1f66d5f951280/build/TestDrainGivesUpWhenServerDown3651738945/002/d2478--- PASS: TestQueueRemove (0.02s)24792026/10/14 16:42:46 INFO Uploading batch count=124802026/10/14 16:42:46 ERROR Upload failed error="upload failed" count=124812026/10/14 16:42:46 INFO Uploading batch count=224822026/10/14 16:42:46 ERROR Upload failed error="upload failed" count=224832026/10/14 16:42:46 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/b6d1f66d5f951280/build/TestDrainGivesUpWhenServerDown3651738945/002/e24842026/10/14 16:42:46 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/b6d1f66d5f951280/build/TestDrainGivesUpWhenServerDown3651738945/002/f24852026/10/14 16:42:46 ERROR Drain finished with paths left in queue remaining=1024862026/10/14 16:42:46 INFO Uploading batch count=124872026/10/14 16:42:46 ERROR Upload failed error="upload failed" count=124882026/10/14 16:42:46 INFO Uploading batch count=124892026/10/14 16:42:46 ERROR Upload failed error="upload failed" count=12490--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)24912026/10/14 16:42:46 ERROR Drain finished with paths left in queue remaining=12492--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2493--- PASS: TestDrainIsolatesPoisonPath (0.02s)2494--- PASS: TestWorkerSkipsGCdPaths (0.04s)2495--- PASS: TestWorkerUploadsAndRemoves (0.04s)2496--- PASS: TestWorkerPrunesClosureDeps (0.04s)2497--- PASS: TestQueueRemoveLargeClosure (0.05s)2498--- PASS: TestQueueConcurrentWriters (0.16s)24992026/10/14 16:42:46 ERROR Upload failed error="context deadline exceeded" count=225002026/10/14 16:42:46 ERROR Drain finished with paths left in queue remaining=42501--- PASS: TestDrainTimeout (0.22s)25022026/10/14 16:42:47 INFO Uploading batch count=125032026/10/14 16:42:47 INFO Uploading batch count=125042026/10/14 16:42:47 INFO Uploading batch count=125052026/10/14 16:42:47 ERROR Upload failed error="upload failed" count=125062026/10/14 16:42:47 INFO Uploading batch count=125072026/10/14 16:42:47 ERROR Upload failed error="upload failed" count=125082026/10/14 16:42:47 INFO Uploading batch count=125092026/10/14 16:42:47 ERROR Upload failed error="upload failed" count=125102026/10/14 16:42:47 INFO Uploading batch count=125112026/10/14 16:42:47 ERROR Upload failed error="upload failed" count=125122026/10/14 16:42:47 ERROR Drain finished with paths left in queue remaining=12513--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2514PASS2515Running signing tests...2516=== RUN TestExternalSigner2517=== PAUSE TestExternalSigner2518=== RUN TestExternalSignerWrongPublicKey2519=== PAUSE TestExternalSignerWrongPublicKey2520=== RUN TestExternalSignerErrors2521=== PAUSE TestExternalSignerErrors2522=== RUN TestExternalSignerRestartsAfterCrash2523=== PAUSE TestExternalSignerRestartsAfterCrash2524=== RUN TestExternalSignerProgramErrorKeepsProcess2525=== PAUSE TestExternalSignerProgramErrorKeepsProcess2526=== RUN TestExternalSignerClose2527=== PAUSE TestExternalSignerClose2528=== RUN TestExternalSignerRejectsInvalidPublicKey2529=== PAUSE TestExternalSignerRejectsInvalidPublicKey2530=== RUN TestExternalSignerCancellation2531=== PAUSE TestExternalSignerCancellation2532=== RUN TestGenerateFingerprint2533=== PAUSE TestGenerateFingerprint2534=== RUN TestParseSigningKey2535=== PAUSE TestParseSigningKey2536=== RUN TestSign2537=== PAUSE TestSign2538=== RUN TestSignBatch2539=== PAUSE TestSignBatch2540=== RUN TestNilKeyPublicKey2541=== PAUSE TestNilKeyPublicKey2542=== RUN TestSignErrors2543=== PAUSE TestSignErrors2544=== CONT TestExternalSigner2545=== CONT TestExternalSignerCancellation2546=== CONT TestSignBatch2547=== CONT TestParseSigningKey2548=== CONT TestSignErrors2549=== CONT TestGenerateFingerprint2550=== RUN TestGenerateFingerprint/basic_with_references2551=== CONT TestExternalSignerProgramErrorKeepsProcess2552=== PAUSE TestGenerateFingerprint/basic_with_references2553=== RUN TestGenerateFingerprint/no_references2554=== PAUSE TestGenerateFingerprint/no_references2555=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2556=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2557=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2558=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2559=== CONT TestExternalSignerRejectsInvalidPublicKey2560=== RUN TestExternalSignerRejectsInvalidPublicKey/#002561=== CONT TestSign2562=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002563=== CONT TestExternalSignerErrors2564=== CONT TestExternalSignerRestartsAfterCrash2565=== RUN TestExternalSignerErrors/exit_on_request2566=== PAUSE TestExternalSignerErrors/exit_on_request2567=== RUN TestExternalSignerErrors/null_signatures2568=== PAUSE TestExternalSignerErrors/null_signatures2569=== RUN TestExternalSignerErrors/wrong_signatures_shape2570=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2571=== RUN TestExternalSignerErrors/too_few_signatures2572=== PAUSE TestExternalSignerErrors/too_few_signatures2573=== RUN TestExternalSignerErrors/wrong_signature_length2574=== CONT TestExternalSignerWrongPublicKey2575=== CONT TestNilKeyPublicKey2576=== RUN TestParseSigningKey/valid_32-byte_key2577=== PAUSE TestParseSigningKey/valid_32-byte_key2578=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2579=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2580=== RUN TestParseSigningKey/no_colon2581=== PAUSE TestParseSigningKey/no_colon2582=== RUN TestParseSigningKey/empty_name2583=== PAUSE TestParseSigningKey/empty_name2584=== RUN TestParseSigningKey/invalid_base642585--- PASS: TestNilKeyPublicKey (0.00s)2586=== PAUSE TestParseSigningKey/invalid_base642587=== RUN TestGenerateFingerprint/invalid_nar_hash_length2588=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2589=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2590=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2591=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2592=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2593=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2594=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2595=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2596=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2597=== CONT TestExternalSignerRejectsInvalidPublicKey/#002598=== CONT TestExternalSignerClose2599=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2600=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2601=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2602=== RUN TestParseSigningKey/wrong_length2603=== PAUSE TestParseSigningKey/wrong_length2604=== CONT TestParseSigningKey/valid_32-byte_key2605=== CONT TestParseSigningKey/invalid_base642606=== CONT TestParseSigningKey/empty_name2607=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2608=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2609=== CONT TestParseSigningKey/wrong_length2610=== CONT TestParseSigningKey/no_colon2611--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2612 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2613 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2614 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2615 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2616 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2617=== PAUSE TestExternalSignerErrors/wrong_signature_length2618=== RUN TestGenerateFingerprint/invalid_store_path_prefix2619=== RUN TestExternalSignerErrors/exit_at_startup2620=== PAUSE TestExternalSignerErrors/exit_at_startup2621=== RUN TestExternalSignerErrors/invalid_JSON2622=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2623=== PAUSE TestExternalSignerErrors/invalid_JSON2624=== RUN TestExternalSignerErrors/null2625=== PAUSE TestExternalSignerErrors/null2626=== RUN TestExternalSignerErrors/unrequested_key2627=== RUN TestGenerateFingerprint/invalid_reference_prefix2628=== PAUSE TestExternalSignerErrors/unrequested_key2629=== RUN TestExternalSignerErrors/program_error2630=== PAUSE TestExternalSignerErrors/program_error2631=== RUN TestExternalSignerErrors/missing_signatures2632=== PAUSE TestExternalSignerErrors/missing_signatures2633=== RUN TestExternalSignerErrors/wrong_shape2634=== PAUSE TestExternalSignerErrors/wrong_shape2635=== RUN TestExternalSignerErrors/wrong_id2636=== PAUSE TestExternalSignerErrors/wrong_id2637=== RUN TestExternalSignerErrors/missing_signature_name2638=== PAUSE TestExternalSignerErrors/missing_signature_name2639=== RUN TestExternalSignerErrors/wrong_signature_name2640=== PAUSE TestExternalSignerErrors/wrong_signature_name2641=== RUN TestExternalSignerErrors/invalid_signature_base642642=== PAUSE TestExternalSignerErrors/invalid_signature_base642643=== CONT TestExternalSignerErrors/exit_on_request2644=== CONT TestExternalSignerErrors/program_error2645=== CONT TestExternalSignerErrors/missing_signature_name2646=== CONT TestExternalSignerErrors/wrong_signature_length2647=== CONT TestExternalSignerErrors/wrong_id2648=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2649=== CONT TestExternalSignerErrors/exit_at_startup2650--- PASS: TestSign (0.00s)2651=== CONT TestGenerateFingerprint/no_references2652--- PASS: TestSignBatch (0.00s)2653=== CONT TestGenerateFingerprint/basic_with_references2654=== CONT TestExternalSignerErrors/missing_signatures2655=== CONT TestExternalSignerErrors/wrong_shape2656=== CONT TestExternalSignerErrors/invalid_signature_base642657=== CONT TestExternalSignerErrors/wrong_signature_name2658=== CONT TestGenerateFingerprint/invalid_reference_prefix2659=== CONT TestExternalSignerErrors/null2660=== CONT TestGenerateFingerprint/invalid_store_path_prefix2661=== CONT TestGenerateFingerprint/invalid_nar_hash_length2662=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2663=== RUN TestSignErrors/nil_key2664=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2665=== CONT TestExternalSignerErrors/null_signatures2666=== CONT TestExternalSignerErrors/too_few_signatures2667--- PASS: TestParseSigningKey (0.00s)2668 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2669 --- PASS: TestParseSigningKey/empty_name (0.00s)2670 --- PASS: TestParseSigningKey/wrong_length (0.00s)2671 --- PASS: TestParseSigningKey/no_colon (0.00s)2672 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2673 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2674=== PAUSE TestSignErrors/nil_key2675=== RUN TestSignErrors/nil_narinfo2676=== CONT TestExternalSignerErrors/unrequested_key2677=== CONT TestExternalSignerErrors/invalid_JSON2678=== CONT TestExternalSignerErrors/wrong_signatures_shape2679--- PASS: TestGenerateFingerprint (0.00s)2680 --- PASS: TestGenerateFingerprint/no_references (0.00s)2681 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2682 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2683 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2684 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2685 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2686 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2687=== PAUSE TestSignErrors/nil_narinfo2688=== RUN TestSignErrors/invalid_narinfo2689=== PAUSE TestSignErrors/invalid_narinfo2690=== RUN TestSignErrors/canceled2691=== PAUSE TestSignErrors/canceled2692=== CONT TestSignErrors/nil_key2693=== CONT TestSignErrors/canceled2694=== CONT TestSignErrors/invalid_narinfo2695=== CONT TestSignErrors/nil_narinfo2696--- PASS: TestSignErrors (0.01s)2697 --- PASS: TestSignErrors/nil_key (0.00s)2698 --- PASS: TestSignErrors/canceled (0.00s)2699 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2700 --- PASS: TestSignErrors/nil_narinfo (0.00s)2701--- PASS: TestExternalSignerCancellation (0.24s)2702--- PASS: TestExternalSignerRestartsAfterCrash (0.43s)2703/private/var/tb/4/scratch/b6d1f66d5f951280/build/TestExternalSignerRestartsAfterCrash1164791717/001/sign program: line 7: /private/var/tb/4/scratch/b6d1f66d5f951280/build/TestExternalSignerRestartsAfterCrash1164791717/001/sign program.starts: No such file or directory2704--- PASS: TestExternalSigner (0.61s)2705--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.78s)2706--- PASS: TestExternalSignerWrongPublicKey (0.97s)2707--- PASS: TestExternalSignerClose (1.15s)2708--- PASS: TestExternalSignerErrors (0.00s)2709 --- PASS: TestExternalSignerErrors/missing_signatures (1.34s)2710 --- PASS: TestExternalSignerErrors/unrequested_key (1.53s)2711 --- PASS: TestExternalSignerErrors/exit_on_request (1.71s)2712 --- PASS: TestExternalSignerErrors/program_error (1.90s)2713 --- PASS: TestExternalSignerErrors/wrong_signature_name (2.09s)2714 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (2.27s)2715 --- PASS: TestExternalSignerErrors/wrong_shape (2.46s)2716 --- PASS: TestExternalSignerErrors/null (2.65s)2717 --- PASS: TestExternalSignerErrors/exit_at_startup (2.84s)2718 --- PASS: TestExternalSignerErrors/wrong_id (3.03s)2719 --- PASS: TestExternalSignerErrors/too_few_signatures (3.21s)2720 --- PASS: TestExternalSignerErrors/wrong_signature_length (3.40s)2721 --- PASS: TestExternalSignerErrors/missing_signature_name (3.59s)2722 --- PASS: TestExternalSignerErrors/null_signatures (3.77s)2723 --- PASS: TestExternalSignerErrors/invalid_JSON (3.96s)2724 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (4.15s)2725PASS2726Running OpenBao signer tests...2727=== RUN TestSign2728=== PAUSE TestSign2729=== RUN TestSignErrors2730=== PAUSE TestSignErrors2731=== RUN TestServe2732=== PAUSE TestServe2733=== RUN TestServeRejectsGarbage2734=== PAUSE TestServeRejectsGarbage2735=== CONT TestSign2736=== CONT TestServeRejectsGarbage2737=== CONT TestSignErrors2738=== CONT TestServe2739=== RUN TestSignErrors/http_error2740=== PAUSE TestSignErrors/http_error2741--- PASS: TestServeRejectsGarbage (0.00s)2742=== RUN TestSignErrors/invalid_json2743=== PAUSE TestSignErrors/invalid_json2744=== RUN TestSignErrors/no_prefix2745=== PAUSE TestSignErrors/no_prefix2746=== RUN TestSignErrors/invalid_base642747=== PAUSE TestSignErrors/invalid_base642748=== CONT TestSignErrors/http_error2749=== CONT TestSignErrors/invalid_json2750=== CONT TestSignErrors/no_prefix2751=== CONT TestSignErrors/invalid_base642752--- PASS: TestServe (0.00s)2753--- PASS: TestSign (0.00s)2754--- PASS: TestSignErrors (0.00s)2755 --- PASS: TestSignErrors/http_error (0.00s)2756 --- PASS: TestSignErrors/invalid_json (0.00s)2757 --- PASS: TestSignErrors/invalid_base64 (0.00s)2758 --- PASS: TestSignErrors/no_prefix (0.00s)2759PASS