niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #476
· raw
1tribuchet: building on mac022Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestUploadMultipart_ReturnsAfterDroppedBody20=== PAUSE TestUploadMultipart_ReturnsAfterDroppedBody21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestDumpPathCaseHackMatchesNix24--- PASS: TestDumpPathCaseHackMatchesNix (0.10s)25=== RUN TestDumpPathCaseHackCollision26--- PASS: TestDumpPathCaseHackCollision (0.00s)27=== RUN TestDumpPathMatchesNix28=== PAUSE TestDumpPathMatchesNix29=== RUN TestDumpPathSingleFile30=== PAUSE TestDumpPathSingleFile31=== RUN TestDumpPathWriterError32=== PAUSE TestDumpPathWriterError33=== RUN TestEncodeNixBase3234=== PAUSE TestEncodeNixBase3235=== RUN TestEncodeNixBase32WithRealHash36=== PAUSE TestEncodeNixBase32WithRealHash37=== RUN TestConvertHashToNix3238=== PAUSE TestConvertHashToNix3239=== RUN TestGetStorePathHash40=== PAUSE TestGetStorePathHash41=== RUN TestPathInfoHashCompatibility42=== PAUSE TestPathInfoHashCompatibility43=== RUN TestParsePathInfoJSON44=== PAUSE TestParsePathInfoJSON45=== RUN TestParsePathInfoJSONMultiplePaths46=== PAUSE TestParsePathInfoJSONMultiplePaths47=== RUN TestPathInfoCACompatibility48=== PAUSE TestPathInfoCACompatibility49=== RUN TestRateLimiterFeedback50=== PAUSE TestRateLimiterFeedback51=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess52=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess53=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer54=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer55=== RUN TestRegisterUploadedObject_OutlivesPush56=== PAUSE TestRegisterUploadedObject_OutlivesPush57=== RUN TestResolveStorePath58=== PAUSE TestResolveStorePath59=== RUN TestDoWithRetry_BodyReplayedViaGetBody60=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody61=== RUN TestRetryTimeoutOutlastsMaxRetries62=== PAUSE TestRetryTimeoutOutlastsMaxRetries63=== RUN TestDoWithRetry_FinalResponseBodyReadable64=== PAUSE TestDoWithRetry_FinalResponseBodyReadable65=== RUN TestShellSplit66=== PAUSE TestShellSplit67=== RUN TestShellSplitErrors68=== PAUSE TestShellSplitErrors69=== RUN TestStreamPushReportsEveryPath70=== PAUSE TestStreamPushReportsEveryPath71=== RUN TestStreamPushBatchesUnderLoad72=== PAUSE TestStreamPushBatchesUnderLoad73=== RUN TestStreamPushIsolatesFailures74=== PAUSE TestStreamPushIsolatesFailures75=== RUN TestStreamPushGivesUpOnDeadServer76=== PAUSE TestStreamPushGivesUpOnDeadServer77=== RUN TestStreamPushRequestLine78=== PAUSE TestStreamPushRequestLine79=== RUN TestStreamPushReportsSignatures80=== PAUSE TestStreamPushReportsSignatures81=== RUN TestStreamPushReportsSkippedPaths82=== PAUSE TestStreamPushReportsSkippedPaths83=== RUN TestClientSignaturesByStorePath84=== PAUSE TestClientSignaturesByStorePath85=== RUN TestStreamPushStopsWhenCanceled86=== PAUSE TestStreamPushStopsWhenCanceled87=== RUN TestSetClientTLS88=== PAUSE TestSetClientTLS89=== RUN TestSetClientTLSDoesNotMutateDefaultTransport90=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport91=== RUN TestSetClientTLSErrors92=== PAUSE TestSetClientTLSErrors93=== RUN TestStaticToken94=== PAUSE TestStaticToken95=== RUN TestFileTokenReadsAndCaches96=== PAUSE TestFileTokenReadsAndCaches97=== RUN TestFileTokenMissing98=== PAUSE TestFileTokenMissing99=== RUN TestFileTokenEmpty100=== PAUSE TestFileTokenEmpty101=== RUN TestScriptTokenNoExpiryRerunsEveryCall102=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall103=== RUN TestScriptTokenCachesUntilRefresh104=== PAUSE TestScriptTokenCachesUntilRefresh105=== RUN TestScriptTokenEmptyToken106=== PAUSE TestScriptTokenEmptyToken107=== RUN TestScriptTokenBadJSON108=== PAUSE TestScriptTokenBadJSON109=== RUN TestScriptTokenScriptFails110=== PAUSE TestScriptTokenScriptFails111=== RUN TestScriptTokenEmptyCommand112=== PAUSE TestScriptTokenEmptyCommand113=== CONT TestDoServerRequestAttachesToken114=== CONT TestRetryTimeoutOutlastsMaxRetries115=== CONT TestFileTokenReadsAndCaches116=== CONT TestSetClientTLS117=== CONT TestScriptTokenNoExpiryRerunsEveryCall118=== CONT TestFileTokenEmpty119=== CONT TestFileTokenMissing120=== CONT TestScriptTokenEmptyCommand121--- PASS: TestScriptTokenEmptyCommand (0.00s)122=== CONT TestDumpPathMatchesNix123=== CONT TestScriptTokenScriptFails124--- PASS: TestFileTokenMissing (0.00s)125=== CONT TestPartSizeForNAR126=== CONT TestScriptTokenBadJSON127=== CONT TestScriptTokenEmptyToken128=== CONT TestScriptTokenCachesUntilRefresh129=== CONT TestStreamPushGivesUpOnDeadServer130=== CONT TestStreamPushStopsWhenCanceled131--- PASS: TestStreamPushStopsWhenCanceled (0.00s)132=== CONT TestUploadMultipart_ReturnsAfterDroppedBody133=== CONT TestClientSignaturesByStorePath134=== CONT TestStreamPushReportsSkippedPaths135=== RUN TestPartSizeForNAR/zero_stays_at_minimum136=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum137--- PASS: TestFileTokenEmpty (0.00s)138=== CONT TestStreamPushReportsEveryPath139=== CONT TestStreamPushReportsSignatures140=== RUN TestPartSizeForNAR/small_stays_at_minimum141=== CONT TestStreamPushRequestLine142=== CONT TestSetClientTLSErrors143=== CONT TestStreamPushBatchesUnderLoad144=== CONT TestStaticToken145=== CONT TestUploadMultipart_PartsInParallel146=== CONT TestEncodeNixBase32147=== CONT TestDumpPathWriterError148=== CONT TestDumpPathSingleFile1492026/11/10 08:16:00 ERROR Upload failed error=boom count=1150=== PAUSE TestPartSizeForNAR/small_stays_at_minimum151--- PASS: TestStreamPushReportsSkippedPaths (0.00s)152=== CONT TestStreamPushIsolatesFailures153=== CONT TestRateLimiterFeedback154=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false155=== RUN TestRateLimiterFeedback/429_enables_limiter156=== RUN TestEncodeNixBase32/test_string_hash1572026/11/10 08:16:00 ERROR Upload failed error="connection refused" count=20158=== PAUSE TestEncodeNixBase32/test_string_hash1592026/11/10 08:16:00 ERROR Server seems unavailable, giving up on batch untried=17160=== PAUSE TestRateLimiterFeedback/429_enables_limiter161=== RUN TestRateLimiterFeedback/503_enables_limiter162=== CONT TestDoWithRetry_BodyReplayedViaGetBody163=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false164=== PAUSE TestRateLimiterFeedback/503_enables_limiter165=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true166=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true167=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum168=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter1692026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:60020170=== CONT TestRegisterUploadedObject_OutlivesPush171=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter172--- PASS: TestStreamPushReportsEveryPath (0.00s)173--- PASS: TestClientSignaturesByStorePath (0.00s)1742026/11/10 08:16:00 ERROR Upload failed error=boom count=1175--- PASS: TestStaticToken (0.00s)176--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)177=== RUN TestEncodeNixBase32/empty_input178=== PAUSE TestEncodeNixBase32/empty_input179=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum180=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts181=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts182=== RUN TestPartSizeForNAR/1_TiB183=== PAUSE TestPartSizeForNAR/1_TiB184=== RUN TestPartSizeForNAR/5_TiB_S3_max_object185=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object186=== RUN TestPartSizeForNAR/capped_at_5_GiB187=== PAUSE TestPartSizeForNAR/capped_at_5_GiB188=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer189=== CONT TestFilterOversizedClosures190=== RUN TestFilterOversizedClosures/no_limit_keeps_everything191=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything192=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped193=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped194=== RUN TestFilterOversizedClosures/all_closures_skipped195=== PAUSE TestFilterOversizedClosures/all_closures_skipped196--- PASS: TestStreamPushReportsSignatures (0.00s)197--- PASS: TestDoServerRequestAttachesToken (0.00s)198=== CONT TestCaseHackSuffix199=== CONT TestResolveStorePath2002026/11/10 08:16:00 ERROR Upload failed error="bad path" count=3201--- PASS: TestStreamPushIsolatesFailures (0.00s)202=== CONT TestShellSplit203--- PASS: TestShellSplit (0.00s)204=== CONT TestShellSplitErrors205--- PASS: TestShellSplitErrors (0.00s)206=== CONT TestDoWithRetry_FinalResponseBodyReadable207=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter208=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess209=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun210=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter211=== CONT TestRegisterUploadedObjectReusesConnections2122026/11/10 08:16:00 WARN Rate limiter enabled after throttle name=server-test rate=52132026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:60024214=== RUN TestSetClientTLSErrors/missing_cert_file215=== PAUSE TestSetClientTLSErrors/missing_cert_file2162026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:600202172026/11/10 08:16:00 WARN Rate limiter enabled after throttle name=server-test rate=52182026/11/10 08:16:00 WARN Rate limiter backed off name=server-test rate=52192026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:60024220=== RUN TestSetClientTLSErrors/missing_key_file221=== PAUSE TestSetClientTLSErrors/missing_key_file222--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.01s)223=== RUN TestSetClientTLSErrors/missing_ca_file224=== PAUSE TestSetClientTLSErrors/missing_ca_file225=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica226--- PASS: TestFileTokenReadsAndCaches (0.01s)227=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry228--- PASS: TestResolveStorePath (0.00s)229=== CONT TestSetClientTLSDoesNotMutateDefaultTransport230--- PASS: TestScriptTokenEmptyToken (0.02s)231=== CONT TestParsePathInfoJSON232=== RUN TestParsePathInfoJSON/Nix_format233=== PAUSE TestParsePathInfoJSON/Nix_format234=== RUN TestParsePathInfoJSON/Lix_format235=== PAUSE TestParsePathInfoJSON/Lix_format236=== RUN TestParsePathInfoJSON/empty_input237=== PAUSE TestParsePathInfoJSON/empty_input238=== RUN TestParsePathInfoJSON/whitespace_only239=== PAUSE TestParsePathInfoJSON/whitespace_only240=== RUN TestParsePathInfoJSON/invalid_JSON241=== PAUSE TestParsePathInfoJSON/invalid_JSON242=== CONT TestPathInfoCACompatibility243=== RUN TestPathInfoCACompatibility/null_ca_field244=== PAUSE TestPathInfoCACompatibility/null_ca_field245=== RUN TestPathInfoCACompatibility/old_string_format_-_text246=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text247=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive248=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive249=== RUN TestPathInfoCACompatibility/new_structured_format_-_text250=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text251=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method252=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method253=== CONT TestParsePathInfoJSONMultiplePaths254=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths255=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths256=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths257=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths258=== CONT TestGetStorePathHash259=== RUN TestGetStorePathHash/valid_store_path260=== PAUSE TestGetStorePathHash/valid_store_path261=== RUN TestGetStorePathHash/basename_without_hyphen_should_error262=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error263=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error264=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error265=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error266=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error267=== CONT TestPathInfoHashCompatibility268=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)269=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)270=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon271=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon272=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI273=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI274=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512275=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512276=== CONT TestConvertHashToNix32277=== RUN TestConvertHashToNix32/SRI_format_to_Nix32278=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32279=== RUN TestConvertHashToNix32/already_Nix32_format280=== PAUSE TestConvertHashToNix32/already_Nix32_format281=== RUN TestConvertHashToNix32/invalid_format282=== PAUSE TestConvertHashToNix32/invalid_format283=== CONT TestEncodeNixBase32WithRealHash284--- PASS: TestEncodeNixBase32WithRealHash (0.00s)285=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false286=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true287--- PASS: TestStreamPushBatchesUnderLoad (0.00s)288 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)289 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)290=== CONT TestEncodeNixBase32/test_string_hash291=== CONT TestPartSizeForNAR/zero_stays_at_minimum292=== CONT TestEncodeNixBase32/empty_input293--- PASS: TestEncodeNixBase32 (0.00s)294 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)295 --- PASS: TestEncodeNixBase32/empty_input (0.00s)296=== CONT TestPartSizeForNAR/capped_at_5_GiB297=== CONT TestPartSizeForNAR/5_TiB_S3_max_object298=== CONT TestPartSizeForNAR/1_TiB299=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts300=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum301=== CONT TestPartSizeForNAR/small_stays_at_minimum302--- PASS: TestPartSizeForNAR (0.00s)303 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)304 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)305 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)306 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)307 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)308 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)309 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)310=== CONT TestFilterOversizedClosures/no_limit_keeps_everything311=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped312=== RUN TestSetClientTLSErrors/invalid_ca_file313=== PAUSE TestSetClientTLSErrors/invalid_ca_file3142026/11/10 08:16:00 INFO Garbage collection started3152026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:60020316--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)317=== CONT TestRateLimiterFeedback/429_enables_limiter318=== CONT TestFilterOversizedClosures/all_closures_skipped319=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter320=== RUN TestSetClientTLS/rejects_connection_without_client_cert321=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert322=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA323=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA324=== RUN TestSetClientTLS/preserves_debug_logging_transport325=== PAUSE TestSetClientTLS/preserves_debug_logging_transport326=== CONT TestRateLimiterFeedback/503_enables_limiter327=== CONT TestParsePathInfoJSON/Nix_format328=== CONT TestPathInfoCACompatibility/null_ca_field329=== CONT TestParsePathInfoJSON/invalid_JSON330=== CONT TestParsePathInfoJSON/whitespace_only331=== CONT TestParsePathInfoJSON/empty_input332=== CONT TestParsePathInfoJSON/Lix_format333=== CONT TestPathInfoCACompatibility/new_structured_format_-_text334=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method335=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths336=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive337=== CONT TestPathInfoCACompatibility/old_string_format_-_text338=== CONT TestGetStorePathHash/valid_store_path339=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths340=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)341=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error342=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error343=== CONT TestGetStorePathHash/basename_without_hyphen_should_error344=== CONT TestConvertHashToNix32/SRI_format_to_Nix32345=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512346=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI347=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon348=== CONT TestConvertHashToNix32/invalid_format349=== CONT TestConvertHashToNix32/already_Nix32_format350=== CONT TestSetClientTLSErrors/missing_cert_file351=== CONT TestSetClientTLSErrors/missing_ca_file352=== CONT TestSetClientTLSErrors/invalid_ca_file353=== CONT TestSetClientTLSErrors/missing_key_file354=== CONT TestSetClientTLS/rejects_connection_without_client_cert3552026/11/10 08:16:00 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=50356=== CONT TestSetClientTLS/preserves_debug_logging_transport357--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)358--- PASS: TestScriptTokenScriptFails (0.02s)359--- PASS: TestScriptTokenBadJSON (0.02s)360=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter3612026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:60020362--- PASS: TestParsePathInfoJSON (0.00s)363 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)364 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)365 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)366 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)367 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)368--- PASS: TestPathInfoCACompatibility (0.00s)369 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)370 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)371 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)372 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)373 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)374--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)375 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)376 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)377--- PASS: TestRegisterUploadedObject_OutlivesPush (0.02s)378=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA379--- PASS: TestGetStorePathHash (0.00s)380 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)381 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)382 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)383 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)384--- PASS: TestPathInfoHashCompatibility (0.00s)385 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)386 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)387 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)388 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)389--- PASS: TestConvertHashToNix32 (0.00s)390 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)391 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)392 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)3932026/11/10 08:16:00 WARN Rate limiter enabled after throttle name=s3-test rate=53942026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:600693952026/11/10 08:16:00 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=20003962026/11/10 08:16:00 INFO Garbage collection started397--- PASS: TestFilterOversizedClosures (0.00s)398 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)399 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)400 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.01s)401--- PASS: TestSetClientTLSErrors (0.02s)402 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)403 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)404 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)405 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)4062026/11/10 08:16:00 WARN Rate limiter enabled after throttle name=server-test rate=54072026/11/10 08:16:00 WARN Rate limiter enabled after throttle name=server-test rate=54082026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:601104092026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:600204102026/11/10 08:16:00 WARN Rate limiter backed off name=server-test rate=54112026/11/10 08:16:00 WARN Rate limiter enabled after throttle name=server-test rate=54122026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:601034132026/11/10 08:16:00 WARN Rate limiter backed off name=server-test rate=54142026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:60031415--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.02s)4162026/11/10 08:16:00 WARN Rate limiter backed off name=server-test rate=54172026/11/10 08:16:00 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=0418--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.02s)419--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.02s)420--- PASS: TestRateLimiterFeedback (0.00s)421 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)422 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)423 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)424 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)425--- PASS: TestStreamPushRequestLine (0.03s)4262026/11/10 08:16:00 WARN Garbage collection finished on another replica. Its statistics are not available here427--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)4282026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:600204292026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:600204302026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:600204312026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:600204322026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:600204332026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:600204342026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:600204352026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:600204362026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:600204372026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:600204382026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:600204392026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:600204402026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:60020441--- PASS: TestRegisterUploadedObjectReusesConnections (0.07s)4422026/11/10 08:16:00 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:60020443--- PASS: TestScriptTokenCachesUntilRefresh (0.08s)4442026/11/10 08:16:00 http: TLS handshake error from 127.0.0.1:60116: read tcp 127.0.0.1:60035->127.0.0.1:60116: use of closed network connection445--- PASS: TestSetClientTLS (0.02s)446 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)447 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)448 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.06s)449--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.08s)450--- PASS: TestDumpPathWriterError (0.09s)4512026/11/10 08:16:00 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:60025/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:60025/api/uploads/complete4522026/11/10 08:16:00 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4532026/11/10 08:16:00 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:60025/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:60025/api/uploads/complete4542026/11/10 08:16:00 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4552026/11/10 08:16:00 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:60025/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:60025/api/uploads/complete4562026/11/10 08:16:00 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"457--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (0.10s)458--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.12s)459--- PASS: TestDumpPathSingleFile (0.13s)460--- PASS: TestCaseHackSuffix (0.14s)461--- PASS: TestDumpPathMatchesNix (0.18s)462--- PASS: TestUploadMultipart_PartsInParallel (0.62s)463--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)464PASS465Running server tests...466The files belonging to this database system will be owned by user "_tribuchetbld5".467This user must also own the server process.468469The database cluster will be initialized with locale "C".470The default database encoding has accordingly been set to "SQL_ASCII".471The default text search configuration will be set to "english".472473Data page checksums are enabled.474475creating directory /private/var/tb/5/scratch/e759ffdaa87b1701/build/postgres2204801716/data ... ok476creating subdirectories ... ok477selecting dynamic shared memory implementation ... posix478selecting default "max_connections" ... 100479selecting default "shared_buffers" ... 128MB480selecting default time zone ... UTC481creating configuration files ... ok482running bootstrap script ... ok483performing post-bootstrap initialization ... ok484syncing data to disk ... ok485486initdb: warning: enabling "trust" authentication for local connections487initdb: 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.488489Success. You can now start the database server using:490491 pg_ctl -D /private/var/tb/5/scratch/e759ffdaa87b1701/build/postgres2204801716/data -l logfile start4924932026-11-10 08:16:03.666 UTC [90555] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4942026-11-10 08:16:03.667 UTC [90555] LOG: listening on Unix socket "/private/var/tb/5/scratch/e759ffdaa87b1701/build/postgres2204801716/.s.PGSQL.5432"4952026-11-10 08:16:03.676 UTC [90565] LOG: database system was shut down at 2026-11-10 08:16:03 UTC4962026-11-10 08:16:03.677 UTC [90555] LOG: database system is ready to accept connections497/private/var/tb/5/scratch/e759ffdaa87b1701/build/postgres2204801716:5432 - accepting connections498{"timestamp":"2026-11-10T08:16:05.937247Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"a73aec36-c67e-41e1-959d-132ad4793a05","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}499{"timestamp":"2026-11-10T08:16:06.041326Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"a9217736-6cd3-4ba1-ac99-47eb04c22df3","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}500{"timestamp":"2026-11-10T08:16:06.143674Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"1f305338-a2f2-4c9e-993b-fc03ceb18db2","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}501=== RUN TestAbortSucceeded502=== PAUSE TestAbortSucceeded503=== RUN TestService_AuthMiddleware504=== PAUSE TestService_AuthMiddleware505=== RUN TestService_AuthMiddleware_MTLSProxyHeader506=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader507=== RUN TestService_AuthMiddleware_MTLSBoundSubjects508=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects509=== RUN TestService_ReadAuthMiddleware510=== PAUSE TestService_ReadAuthMiddleware511=== RUN TestService_AuthMiddleware_OIDC512=== PAUSE TestService_AuthMiddleware_OIDC513=== RUN TestService_RequireScope_OIDC514=== PAUSE TestService_RequireScope_OIDC515=== RUN TestService_ReadScope_PublicByDefault516=== PAUSE TestService_ReadScope_PublicByDefault517=== RUN TestCacheConfigHandler518=== PAUSE TestCacheConfigHandler519=== RUN TestCacheStatsHandler520=== PAUSE TestCacheStatsHandler521=== RUN TestClientCADerivations522=== PAUSE TestClientCADerivations523=== RUN TestClientErrorHandling524=== PAUSE TestClientErrorHandling525=== RUN TestClientIntegration526=== PAUSE TestClientIntegration527=== RUN TestClientMultipleUploads528=== PAUSE TestClientMultipleUploads529=== RUN TestClientWithDependencies530=== PAUSE TestClientWithDependencies531=== RUN TestClientSharedPathCommittedMidPush532=== PAUSE TestClientSharedPathCommittedMidPush533=== RUN TestPinProtectsFromGC534=== PAUSE TestPinProtectsFromGC535=== RUN TestClientPushesUseOnePush536=== PAUSE TestClientPushesUseOnePush537=== RUN TestClientFallsBackToClosures538=== PAUSE TestClientFallsBackToClosures539=== RUN TestDeleteClosuresRacingPins540=== PAUSE TestDeleteClosuresRacingPins541=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock542=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock543=== RUN TestResolveDBConnectionString544=== PAUSE TestResolveDBConnectionString545=== RUN TestConnectWaitsForAPeerMigration546=== PAUSE TestConnectWaitsForAPeerMigration547=== RUN TestLeadElectsOneAndHandsOver548=== PAUSE TestLeadElectsOneAndHandsOver549=== RUN TestLeadIncumbentWinsAfterRestart5502026/11/10 08:16:06 INFO lead: acquired remote=192.0.2.1:12345512026/11/10 08:16:07 INFO lead: released remote=192.0.2.1:12345522026/11/10 08:16:07 INFO lead: acquired remote=192.0.2.1:12345532026/11/10 08:16:08 INFO lead: released remote=192.0.2.1:1234554--- PASS: TestLeadIncumbentWinsAfterRestart (2.20s)555=== RUN TestLeadIncumbentAnnouncesAtOnce556=== PAUSE TestLeadIncumbentAnnouncesAtOnce557=== RUN TestLeadEndsOnShutdown558=== PAUSE TestLeadEndsOnShutdown559=== RUN TestLeadEndsWhenItsConnectionHangs5602026/11/10 08:16:08 INFO lead: acquired remote=192.0.2.1:12345612026-11-10 08:16:10.075 UTC [91344] FATAL: terminating connection due to administrator command5622026/11/10 08:16:10 INFO lead: acquired remote=192.0.2.1:12345632026/11/10 08:16:11 WARN lead: lock connection lost error="timeout: context deadline exceeded"5642026/11/10 08:16:11 INFO lead: released remote=192.0.2.1:12345652026/11/10 08:16:11 INFO lead: released remote=192.0.2.1:1234566--- PASS: TestLeadEndsWhenItsConnectionHangs (3.03s)567=== RUN TestGCAdvisoryLockBlocksConcurrentRun568=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun569=== RUN TestGCBugBareHashReferences570=== PAUSE TestGCBugBareHashReferences571=== RUN TestGCMetrics572=== PAUSE TestGCMetrics573=== RUN TestPushDedupSurvivesConcurrentGC574=== PAUSE TestPushDedupSurvivesConcurrentGC575=== RUN TestDeduplicatedObjectsRecordedAsPending576=== PAUSE TestDeduplicatedObjectsRecordedAsPending577=== RUN TestGCSweepSkipsPendingObjects578=== PAUSE TestGCSweepSkipsPendingObjects579=== RUN TestTombstonedObjectOfferedWithoutWaiting580=== PAUSE TestTombstonedObjectOfferedWithoutWaiting581=== RUN TestGCSweepDeliversEachKeyOnce582=== PAUSE TestGCSweepDeliversEachKeyOnce583=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection584=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection585=== RUN TestForceGCDuringPushOffersSweptObject586=== PAUSE TestForceGCDuringPushOffersSweptObject587=== RUN TestFailedS3DeleteKeepsTombstone588=== PAUSE TestFailedS3DeleteKeepsTombstone589=== RUN TestSweepSkipsRowsLockedByPush590=== PAUSE TestSweepSkipsRowsLockedByPush591=== RUN TestRegisterCompletedObjectNeedsPendingRow592=== PAUSE TestRegisterCompletedObjectNeedsPendingRow593=== RUN TestGetExistingObjectsLocksRows594=== PAUSE TestGetExistingObjectsLocksRows595=== RUN TestSweepRechecksPendingAfterLocking596=== PAUSE TestSweepRechecksPendingAfterLocking597=== RUN TestPushWaitsForSweepHoldingRow598=== PAUSE TestPushWaitsForSweepHoldingRow599=== RUN TestCommitRacingPendingCleanupKeepsObjects600=== PAUSE TestCommitRacingPendingCleanupKeepsObjects601=== RUN TestGCEndsOnShutdown602=== PAUSE TestGCEndsOnShutdown603=== RUN TestGCTaskStore_StartNew604=== PAUSE TestGCTaskStore_StartNew605=== RUN TestGCTaskStore_DeduplicateSameParams606=== PAUSE TestGCTaskStore_DeduplicateSameParams607=== RUN TestGCTaskStore_ConflictDifferentParams608=== PAUSE TestGCTaskStore_ConflictDifferentParams609=== RUN TestGCTaskStore_GetEmpty610=== PAUSE TestGCTaskStore_GetEmpty611=== RUN TestGCTaskStore_GetReturnsLatest612=== PAUSE TestGCTaskStore_GetReturnsLatest613=== RUN TestGCTaskStore_CompletedAllowsNewTask614=== PAUSE TestGCTaskStore_CompletedAllowsNewTask615=== RUN TestGCTaskStore_PhaseUpdates616=== PAUSE TestGCTaskStore_PhaseUpdates617=== RUN TestGCTaskStore_Fail618=== PAUSE TestGCTaskStore_Fail619=== RUN TestGracefulShutdownDrainsInflight620=== PAUSE TestGracefulShutdownDrainsInflight621=== RUN TestService_healthCheckHandler622=== PAUSE TestService_healthCheckHandler623=== RUN TestService_readinessHandler624=== PAUSE TestService_readinessHandler625=== RUN TestGenerateLandingPage626=== PAUSE TestGenerateLandingPage627=== RUN TestEnsureAbortUploadsRule628=== PAUSE TestEnsureAbortUploadsRule629=== RUN TestCacheConfigHandlerMaxNarSize630=== PAUSE TestCacheConfigHandlerMaxNarSize631=== RUN TestCreatePendingClosureRejectsOversizedNAR632=== PAUSE TestCreatePendingClosureRejectsOversizedNAR633=== RUN TestNARDeduplicationMetadataUploadBug634=== PAUSE TestNARDeduplicationMetadataUploadBug635=== RUN TestMetricsInventory636=== PAUSE TestMetricsInventory637=== RUN TestMetricsCommit638=== PAUSE TestMetricsCommit639=== RUN TestService_NativeMTLS640=== PAUSE TestService_NativeMTLS641=== RUN TestServerTLSConfig642=== PAUSE TestServerTLSConfig643=== RUN TestMultipartCleanup644=== PAUSE TestMultipartCleanup645=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded646=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded647=== RUN TestPendingCleanupUsesOneCutoff648=== PAUSE TestPendingCleanupUsesOneCutoff649=== RUN TestObjectStatsTrigger650=== PAUSE TestObjectStatsTrigger651=== RUN TestObjectStatsUpdatedOncePerCommit652=== PAUSE TestObjectStatsUpdatedOncePerCommit653=== RUN TestOrphanedObjectsGC654=== PAUSE TestOrphanedObjectsGC655=== RUN TestOrphanedObjectsGCStressTest656=== PAUSE TestOrphanedObjectsGCStressTest657=== RUN TestCreatePin_ReservedPins658=== PAUSE TestCreatePin_ReservedPins659=== RUN TestPresentReportsOnlyClosureRoots660=== PAUSE TestPresentReportsOnlyClosureRoots661=== RUN TestPresentRefreshesOnlyStaleClosures662=== PAUSE TestPresentRefreshesOnlyStaleClosures663=== RUN TestPresentNotReportedWhileGCDeletesClosure664=== PAUSE TestPresentNotReportedWhileGCDeletesClosure665=== RUN TestParseSingleRange666=== PAUSE TestParseSingleRange667=== RUN TestProxyHeadersOnlyTrustedOnSocket6682026/11/10 08:16:11 INFO Starting HTTP server address=proxy.sock6692026/11/10 08:16:11 INFO Starting HTTP server address=127.0.0.1:601896702026/11/10 08:16:11 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6712026/11/10 08:16:11 INFO Shutdown signal received, draining in-flight requests timeout=10s672--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.26s)673=== RUN TestIsValidCachePath674=== PAUSE TestIsValidCachePath675=== RUN TestReadProxyNarinfo676=== PAUSE TestReadProxyNarinfo677=== RUN TestReadProxyNarinfoAlreadyDecompressed678=== PAUSE TestReadProxyNarinfoAlreadyDecompressed679=== RUN TestReadProxyContentNegotiation680=== PAUSE TestReadProxyContentNegotiation681=== RUN TestReadProxyNarStreaming682=== PAUSE TestReadProxyNarStreaming683=== RUN TestReadProxy404684=== PAUSE TestReadProxy404685=== RUN TestReadProxyInvalidPath686=== PAUSE TestReadProxyInvalidPath687=== RUN TestReadProxyHead688=== PAUSE TestReadProxyHead689=== RUN TestReadProxyOutlastsServerWriteTimeout690=== PAUSE TestReadProxyOutlastsServerWriteTimeout691=== RUN TestReadProxyConditionalGet692=== PAUSE TestReadProxyConditionalGet693=== RUN TestReadProxyRootRedirectsToIndexHTML694=== PAUSE TestReadProxyRootRedirectsToIndexHTML695=== RUN TestReadProxyDisabled696=== PAUSE TestReadProxyDisabled697=== RUN TestReadRedirectNar698=== PAUSE TestReadRedirectNar699=== RUN TestReadRedirectKeepsNarinfoProxied700=== PAUSE TestReadRedirectKeepsNarinfoProxied701=== RUN TestReadProxyRangeRequest702=== PAUSE TestReadProxyRangeRequest703=== RUN TestReadRedirectUsesPublicS3URL704=== PAUSE TestReadRedirectUsesPublicS3URL705=== RUN TestPush_OverlappingRootsStoreOneRowPerKey706=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey707=== RUN TestPush_CompleteCommitsEveryRoot708=== PAUSE TestPush_CompleteCommitsEveryRoot709=== RUN TestPush_RepeatedRootCommitsOnce710=== PAUSE TestPush_RepeatedRootCommitsOnce711=== RUN TestPush_CompleteWaitsForCleanupOfThePush712=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush713=== RUN TestPush_RootsAreLockedInByteOrder714=== PAUSE TestPush_RootsAreLockedInByteOrder715=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit716=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit717=== RUN TestPush_RejectsBadRequests718=== PAUSE TestPush_RejectsBadRequests719=== RUN TestPush_SignsNarinfosOfItsPendingObjects720=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects721=== RUN TestSharedNarBothUploadsComplete722=== PAUSE TestSharedNarBothUploadsComplete723=== RUN TestCompleteMultipartUpload_ErrorButObjectExists724=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists725=== RUN TestCompletedNarNotReofferedAcrossClosures726=== PAUSE TestCompletedNarNotReofferedAcrossClosures727=== RUN TestPresignedUploadRegisteredBeforeCommit728=== PAUSE TestPresignedUploadRegisteredBeforeCommit729=== RUN TestService_Rustfstest730=== PAUSE TestService_Rustfstest731=== RUN TestParseSize732=== PAUSE TestParseSize733=== RUN TestSkippedUploadsHandler734=== PAUSE TestSkippedUploadsHandler735=== RUN TestSystemdListenerNotActivated736--- PASS: TestSystemdListenerNotActivated (0.00s)737=== RUN TestWatchdogBeatsWhenHealthy738--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)739=== RUN TestWatchdogSkipsWhenUnhealthy7402026/11/10 08:16:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7412026/11/10 08:16:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7422026/11/10 08:16:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7432026/11/10 08:16:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7442026/11/10 08:16:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7452026/11/10 08:16:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7462026/11/10 08:16:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7472026/11/10 08:16:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7482026/11/10 08:16:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7492026/11/10 08:16:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"750--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)751=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle752=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle753=== RUN TestProxyWriteTimeout754=== PAUSE TestProxyWriteTimeout755=== RUN TestPendingClosureWriteTimeout756=== PAUSE TestPendingClosureWriteTimeout757=== RUN TestIsValidUploadKey758=== PAUSE TestIsValidUploadKey759=== RUN TestUploadHandlersRejectInvalidKeys760=== PAUSE TestUploadHandlersRejectInvalidKeys761=== RUN TestUploadHandlersRejectOversizedBody762=== PAUSE TestUploadHandlersRejectOversizedBody763=== RUN TestService_cleanupPendingClosuresHandler764=== PAUSE TestService_cleanupPendingClosuresHandler765=== RUN TestService_createPendingClosureHandler766=== PAUSE TestService_createPendingClosureHandler767=== RUN TestService_verifyS3Integrity768=== PAUSE TestService_verifyS3Integrity769=== RUN TestService_verifyS3ReuploadsStaleNarinfo770=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo771=== RUN TestCompleteMultipartUnregistered772=== PAUSE TestCompleteMultipartUnregistered773=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT774=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT775=== CONT TestPush_CompleteWaitsForCleanupOfThePush776=== CONT TestGCTaskStore_StartNew777=== CONT TestReadProxyRootRedirectsToIndexHTML778=== CONT TestConnectWaitsForAPeerMigration779=== CONT TestClientWithDependencies780=== CONT TestPendingCleanupUsesOneCutoff781=== CONT TestResolveDBConnectionString782=== CONT TestGCTaskStore_DeduplicateSameParams783=== CONT TestCompleteMultipartUnregistered784--- PASS: TestGCTaskStore_StartNew (0.00s)785=== CONT TestPush_CompleteCommitsEveryRoot786=== CONT TestPush_RepeatedRootCommitsOnce787=== CONT TestPush_OverlappingRootsStoreOneRowPerKey788=== CONT TestReadRedirectUsesPublicS3URL789=== CONT TestReadProxyRangeRequest790=== CONT TestReadRedirectKeepsNarinfoProxied791=== RUN TestResolveDBConnectionString/flag_wins792=== CONT TestReadRedirectNar793=== CONT TestReadProxyDisabled794=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock795=== CONT TestDeleteClosuresRacingPins796=== CONT TestClientFallsBackToClosures797=== CONT TestClientPushesUseOnePush798=== CONT TestPinProtectsFromGC799=== CONT TestClientSharedPathCommittedMidPush800=== CONT TestAbortSucceeded801=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT802--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)803=== CONT TestIsValidCachePath804=== PAUSE TestResolveDBConnectionString/flag_wins805=== CONT TestService_verifyS3ReuploadsStaleNarinfo806=== RUN TestResolveDBConnectionString/file_when_flag_empty807=== PAUSE TestResolveDBConnectionString/file_when_flag_empty808=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed809--- PASS: TestAbortSucceeded (0.00s)810=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed811=== RUN TestResolveDBConnectionString/missing_file_is_an_error812=== RUN TestIsValidCachePath/narinfo813=== PAUSE TestIsValidCachePath/narinfo814=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars815=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars816=== RUN TestIsValidCachePath/nar_zst817=== PAUSE TestIsValidCachePath/nar_zst818=== RUN TestIsValidCachePath/nar_xz819=== PAUSE TestIsValidCachePath/nar_xz820=== RUN TestIsValidCachePath/nar_bz2821=== PAUSE TestIsValidCachePath/nar_bz2822=== RUN TestIsValidCachePath/nar_uncompressed823=== PAUSE TestIsValidCachePath/nar_uncompressed824=== RUN TestIsValidCachePath/ls825=== PAUSE TestIsValidCachePath/ls826=== RUN TestIsValidCachePath/log827=== PAUSE TestIsValidCachePath/log828=== RUN TestIsValidCachePath/realisation829=== PAUSE TestIsValidCachePath/realisation830=== RUN TestIsValidCachePath/nix-cache-info831=== PAUSE TestIsValidCachePath/nix-cache-info832=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed833=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error834=== RUN TestResolveDBConnectionString/PGHOST_allows_empty835=== RUN TestIsValidCachePath/index.html836=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed837=== PAUSE TestIsValidCachePath/index.html838=== RUN TestIsValidCachePath/traversal_parent839=== PAUSE TestIsValidCachePath/traversal_parent840=== RUN TestIsValidCachePath/traversal_in_middle841=== PAUSE TestIsValidCachePath/traversal_in_middle842=== RUN TestIsValidCachePath/invalid_char_e843=== PAUSE TestIsValidCachePath/invalid_char_e844=== RUN TestIsValidCachePath/invalid_char_u845=== PAUSE TestIsValidCachePath/invalid_char_u846=== RUN TestIsValidCachePath/random_path847=== PAUSE TestIsValidCachePath/random_path848=== RUN TestIsValidCachePath/empty849=== PAUSE TestIsValidCachePath/empty850=== RUN TestIsValidCachePath/leading_slash851=== PAUSE TestIsValidCachePath/leading_slash852=== RUN TestIsValidCachePath/wrong_extension853=== PAUSE TestIsValidCachePath/wrong_extension854=== RUN TestIsValidCachePath/short_hash855=== PAUSE TestIsValidCachePath/short_hash856=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost857=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost858=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed859=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed860=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed861=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed862=== CONT TestService_verifyS3Integrity863=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty864=== RUN TestResolveDBConnectionString/nothing_configured865=== PAUSE TestResolveDBConnectionString/nothing_configured866=== CONT TestService_createPendingClosureHandler867=== CONT TestService_cleanupPendingClosuresHandler868--- PASS: TestConnectWaitsForAPeerMigration (1.46s)869=== CONT TestUploadHandlersRejectOversizedBody870=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure871=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure872=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart873=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart874=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts875=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts876=== CONT TestParseSingleRange877=== RUN TestParseSingleRange/none878=== PAUSE TestParseSingleRange/none879=== RUN TestParseSingleRange/unknown_unit880=== PAUSE TestParseSingleRange/unknown_unit881=== RUN TestParseSingleRange/multi-range_ignored882=== PAUSE TestParseSingleRange/multi-range_ignored883=== RUN TestParseSingleRange/malformed_no_dash884=== PAUSE TestParseSingleRange/malformed_no_dash885=== RUN TestParseSingleRange/malformed_both_empty886=== PAUSE TestParseSingleRange/malformed_both_empty887=== RUN TestParseSingleRange/malformed_end_before_start888=== PAUSE TestParseSingleRange/malformed_end_before_start889=== RUN TestParseSingleRange/closed890=== PAUSE TestParseSingleRange/closed891=== RUN TestParseSingleRange/open-ended892=== PAUSE TestParseSingleRange/open-ended893=== RUN TestParseSingleRange/end_clamped_to_size894=== PAUSE TestParseSingleRange/end_clamped_to_size895=== RUN TestParseSingleRange/suffix896=== PAUSE TestParseSingleRange/suffix897=== RUN TestParseSingleRange/suffix_exceeds_size898=== PAUSE TestParseSingleRange/suffix_exceeds_size899=== RUN TestParseSingleRange/single_byte900=== PAUSE TestParseSingleRange/single_byte901=== RUN TestParseSingleRange/start_past_EOF902=== PAUSE TestParseSingleRange/start_past_EOF903=== RUN TestParseSingleRange/start_far_past_EOF904=== PAUSE TestParseSingleRange/start_far_past_EOF905=== CONT TestUploadHandlersRejectInvalidKeys906=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info907=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info908=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal909=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal910=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key911=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key912=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key913=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key914=== CONT TestPresentNotReportedWhileGCDeletesClosure915=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale916=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale917=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh918=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh919=== CONT TestIsValidUploadKey920=== RUN TestIsValidUploadKey/narinfo921=== PAUSE TestIsValidUploadKey/narinfo922=== RUN TestIsValidUploadKey/nar_zst923=== PAUSE TestIsValidUploadKey/nar_zst924=== RUN TestIsValidUploadKey/nar_xz925=== PAUSE TestIsValidUploadKey/nar_xz926=== RUN TestIsValidUploadKey/nar_plain927=== PAUSE TestIsValidUploadKey/nar_plain928=== RUN TestIsValidUploadKey/listing929=== PAUSE TestIsValidUploadKey/listing930=== RUN TestIsValidUploadKey/build_log931=== PAUSE TestIsValidUploadKey/build_log932=== RUN TestIsValidUploadKey/build_log_home-manager_file933=== PAUSE TestIsValidUploadKey/build_log_home-manager_file934=== RUN TestIsValidUploadKey/build_log_plus_in_name935=== PAUSE TestIsValidUploadKey/build_log_plus_in_name936=== RUN TestIsValidUploadKey/build_log_question_mark937=== PAUSE TestIsValidUploadKey/build_log_question_mark938=== RUN TestIsValidUploadKey/build_log_equals939=== PAUSE TestIsValidUploadKey/build_log_equals940=== RUN TestIsValidUploadKey/realisation941=== PAUSE TestIsValidUploadKey/realisation942=== RUN TestIsValidUploadKey/realisation_plus_in_output943=== PAUSE TestIsValidUploadKey/realisation_plus_in_output944=== RUN TestIsValidUploadKey/nix-cache-info945=== PAUSE TestIsValidUploadKey/nix-cache-info946=== RUN TestIsValidUploadKey/index.html947=== PAUSE TestIsValidUploadKey/index.html948=== RUN TestIsValidUploadKey/narinfo_key,_nar_type949=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type950=== RUN TestIsValidUploadKey/nar_key,_narinfo_type951=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type952=== RUN TestIsValidUploadKey/listing_key,_narinfo_type953=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type954=== RUN TestIsValidUploadKey/traversal955=== PAUSE TestIsValidUploadKey/traversal956=== RUN TestIsValidUploadKey/traversal_nar957=== PAUSE TestIsValidUploadKey/traversal_nar958=== RUN TestIsValidUploadKey/absolute959=== PAUSE TestIsValidUploadKey/absolute960=== RUN TestIsValidUploadKey/empty_key961=== PAUSE TestIsValidUploadKey/empty_key962=== RUN TestIsValidUploadKey/unknown_type963=== PAUSE TestIsValidUploadKey/unknown_type964=== CONT TestPendingClosureWriteTimeout965=== RUN TestPendingClosureWriteTimeout/empty966=== PAUSE TestPendingClosureWriteTimeout/empty967=== RUN TestPendingClosureWriteTimeout/400_objects968=== PAUSE TestPendingClosureWriteTimeout/400_objects969=== RUN TestPendingClosureWriteTimeout/670k_objects970=== PAUSE TestPendingClosureWriteTimeout/670k_objects971=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline972=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline973=== CONT TestProxyWriteTimeout974=== RUN TestProxyWriteTimeout/narinfo975=== PAUSE TestProxyWriteTimeout/narinfo976=== RUN TestProxyWriteTimeout/1_GiB_nar977=== PAUSE TestProxyWriteTimeout/1_GiB_nar978=== RUN TestProxyWriteTimeout/10_GiB_nar979=== PAUSE TestProxyWriteTimeout/10_GiB_nar980=== RUN TestProxyWriteTimeout/unknown_size981=== PAUSE TestProxyWriteTimeout/unknown_size982=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle9832026/11/10 08:16:14 INFO Received push request method=POST path=/api/pushes9842026/11/10 08:16:14 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)9852026/11/10 08:16:14 INFO Uploading fin5phhyr16j4wnriy3wg7jby7ld2cm1-shared-dep (136B)9862026/11/10 08:16:14 INFO Uploading qq94qbralx5gnpfg4jiqc7s1xqrllxjq-top (264B)9872026/11/10 08:16:14 INFO Received uploads request method=POST path=/api/pending_closures9882026/11/10 08:16:14 WARN Failed to register uploaded object key=fin5phhyr16j4wnriy3wg7jby7ld2cm1.ls error="server returned 404: 404 page not found\n"9892026/11/10 08:16:15 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"9902026/11/10 08:16:15 WARN Failed to register uploaded object key=qq94qbralx5gnpfg4jiqc7s1xqrllxjq.ls error="server returned 404: 404 page not found\n"9912026/11/10 08:16:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9922026/11/10 08:16:15 WARN Failed to register uploaded object key=nar/1m8m05k2jnq1aggjnf2bw5mx11lc2xm8m1wlzl8fj4z5swzshdcq.nar.zst error="server returned 404: 404 page not found\n"9932026/11/10 08:16:15 INFO Signed narinfos id=1 count=29942026/11/10 08:16:15 INFO Uploading 2 narinfos9952026/11/10 08:16:15 INFO Received uploads request method=POST path=/api/pending_closures9962026/11/10 08:16:15 WARN Failed to register uploaded object key=fin5phhyr16j4wnriy3wg7jby7ld2cm1.narinfo error="server returned 404: 404 page not found\n"9972026/11/10 08:16:15 INFO Received complete push request method=POST path=/api/pushes/1/complete9982026/11/10 08:16:15 WARN Failed to register uploaded object key=qq94qbralx5gnpfg4jiqc7s1xqrllxjq.narinfo error="server returned 404: 404 page not found\n"9992026/11/10 08:16:15 INFO Completed push id=1 objects=6 duration=22.270166ms10002026/11/10 08:16:15 INFO Upload complete. (416ms)1001=== NAME TestClientSharedPathCommittedMidPush1002 client_integration_test.go:727: Retrieved narinfo from S3:1003 StorePath: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientSharedPathCommittedMidPush1955275669/001/store/fin5phhyr16j4wnriy3wg7jby7ld2cm1-shared-dep1004 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1005 Compression: zstd1006 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821007 NarSize: 1361008 References: 1009 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1010 client_integration_test.go:727: Retrieved narinfo from S3:1011 StorePath: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientSharedPathCommittedMidPush1955275669/001/store/qq94qbralx5gnpfg4jiqc7s1xqrllxjq-top1012 URL: nar/1m8m05k2jnq1aggjnf2bw5mx11lc2xm8m1wlzl8fj4z5swzshdcq.nar.zst1013 Compression: zstd1014 NarHash: sha256:1m8m05k2jnq1aggjnf2bw5mx11lc2xm8m1wlzl8fj4z5swzshdcq1015 NarSize: 2641016 References: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientSharedPathCommittedMidPush1955275669/001/store/fin5phhyr16j4wnriy3wg7jby7ld2cm1-shared-dep1017 CA: text:sha256:1n433gw4yjwzzmlhy9jb5vnn89qmhbyl8jxr0h745sagcl3aalk410182026/11/10 08:16:15 INFO Received cleanup request method=DELETE path=/api/pending_closures1019--- PASS: TestClientSharedPathCommittedMidPush (3.22s)1020=== CONT TestSkippedUploadsHandler10212026/11/10 08:16:15 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001022--- PASS: TestSkippedUploadsHandler (0.00s)1023=== CONT TestParseSize1024--- PASS: TestParseSize (0.00s)1025=== CONT TestPresentRefreshesOnlyStaleClosures1026=== NAME TestClientWithDependencies1027 client_integration_test.go:660: Built derivation: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientWithDependencies1628850077/001/store/vn4y4bci4l3b0p1q9k9ibxdcywsqvi5l-test-script1028 client_integration_test.go:662: Found 1 dependencies (including self)10292026/11/10 08:16:15 INFO Received push request method=POST path=/api/pushes10302026/11/10 08:16:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10312026/11/10 08:16:15 INFO Uploading vn4y4bci4l3b0p1q9k9ibxdcywsqvi5l-test-script (136B)10322026/11/10 08:16:15 WARN Failed to register uploaded object key=vn4y4bci4l3b0p1q9k9ibxdcywsqvi5l.ls error="server returned 404: 404 page not found\n"10332026/11/10 08:16:15 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"10342026/11/10 08:16:15 WARN Failed to register uploaded object key=log/49krsmx907j57wqkip48hp2xf1pxb85q-test-script.drv error="server returned 404: 404 page not found\n"10352026/11/10 08:16:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10362026/11/10 08:16:15 INFO Signed narinfos id=1 count=110372026/11/10 08:16:15 INFO Uploading 1 narinfos10382026/11/10 08:16:15 INFO Received complete push request method=POST path=/api/pushes/1/complete10392026/11/10 08:16:15 WARN Failed to register uploaded object key=vn4y4bci4l3b0p1q9k9ibxdcywsqvi5l.narinfo error="server returned 404: 404 page not found\n"10402026/11/10 08:16:15 INFO Completed push id=1 objects=4 duration=8.438709ms10412026/11/10 08:16:15 INFO Upload complete. (396ms)1042--- PASS: TestReadRedirectNar (3.85s)1043=== CONT TestService_Rustfstest1044=== NAME TestClientWithDependencies1045 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientWithDependencies1628850077/001/store) requires matching store prefix1046--- PASS: TestClientWithDependencies (3.88s)1047=== CONT TestPresentReportsOnlyClosureRoots10482026/11/10 08:16:16 INFO Received uploads request method=POST path=/api/pending_closures10492026/11/10 08:16:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10502026/11/10 08:16:16 INFO Received uploads request method=POST path=/api/pending_closures10512026/11/10 08:16:16 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1052--- PASS: TestCompleteMultipartUnregistered (4.11s)1053=== CONT TestPresignedUploadRegisteredBeforeCommit10542026/11/10 08:16:16 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)10552026/11/10 08:16:16 INFO Uploading xc3igw19mxkf2vlxn7gmi084vbd48ar1-shared-dep (136B)10562026/11/10 08:16:16 INFO Uploading h0l1d3ymwfvzwzp0jfy5fy6hli0r9sfg-b (256B)10572026/11/10 08:16:16 WARN Failed to register uploaded object key=73gmw9ydf4zfpzplrbw0f7dsqcsizgqj.ls error="server returned 404: 404 page not found\n"10582026/11/10 08:16:16 WARN Failed to register uploaded object key=h0l1d3ymwfvzwzp0jfy5fy6hli0r9sfg.ls error="server returned 404: 404 page not found\n"10592026/11/10 08:16:16 WARN Failed to register uploaded object key=xc3igw19mxkf2vlxn7gmi084vbd48ar1.ls error="server returned 404: 404 page not found\n"10602026/11/10 08:16:16 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"10612026/11/10 08:16:16 WARN Failed to register uploaded object key=nar/1417z8kfxgn3p4c8q7qbm4zxci8r1by4jl3psqf1rgyiilg92vbd.nar.zst error="server returned 404: 404 page not found\n"10622026/11/10 08:16:16 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10632026/11/10 08:16:16 INFO Signed narinfos id=1 count=210642026/11/10 08:16:16 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign10652026/11/10 08:16:16 INFO Signed narinfos id=2 count=210662026/11/10 08:16:16 INFO Uploading 4 narinfos10672026/11/10 08:16:16 WARN Failed to register uploaded object key=h0l1d3ymwfvzwzp0jfy5fy6hli0r9sfg.narinfo error="server returned 404: 404 page not found\n"10682026/11/10 08:16:16 WARN Failed to register uploaded object key=xc3igw19mxkf2vlxn7gmi084vbd48ar1.narinfo error="server returned 404: 404 page not found\n"10692026/11/10 08:16:16 WARN Failed to register uploaded object key=73gmw9ydf4zfpzplrbw0f7dsqcsizgqj.narinfo error="server returned 404: 404 page not found\n"10702026/11/10 08:16:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10712026/11/10 08:16:16 WARN Failed to register uploaded object key=xc3igw19mxkf2vlxn7gmi084vbd48ar1.narinfo error="server returned 404: 404 page not found\n"10722026/11/10 08:16:16 INFO Completed upload id=1 objects=6 duration=13.134791ms10732026/11/10 08:16:16 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10742026/11/10 08:16:16 INFO Completed upload id=2 objects=6 duration=1.515166ms10752026/11/10 08:16:16 INFO Upload complete. (595ms)1076=== NAME TestClientFallsBackToClosures1077 client_pushes_test.go:112: Retrieved narinfo from S3:1078 StorePath: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientFallsBackToClosures1920531481/001/store/xc3igw19mxkf2vlxn7gmi084vbd48ar1-shared-dep1079 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1080 Compression: zstd1081 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821082 NarSize: 1361083 References: 1084 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1085 client_pushes_test.go:112: Retrieved narinfo from S3:1086 StorePath: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientFallsBackToClosures1920531481/001/store/73gmw9ydf4zfpzplrbw0f7dsqcsizgqj-a1087 URL: nar/1417z8kfxgn3p4c8q7qbm4zxci8r1by4jl3psqf1rgyiilg92vbd.nar.zst1088 Compression: zstd1089 NarHash: sha256:1417z8kfxgn3p4c8q7qbm4zxci8r1by4jl3psqf1rgyiilg92vbd1090 NarSize: 2561091 References: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientFallsBackToClosures1920531481/001/store/xc3igw19mxkf2vlxn7gmi084vbd48ar1-shared-dep1092 CA: text:sha256:0n068cqs80q7828lz7s4ajpkgnfrnsxnxi2ijfqjmc2qxgca67sw1093 client_pushes_test.go:112: Retrieved narinfo from S3:1094 StorePath: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientFallsBackToClosures1920531481/001/store/h0l1d3ymwfvzwzp0jfy5fy6hli0r9sfg-b1095 URL: nar/1417z8kfxgn3p4c8q7qbm4zxci8r1by4jl3psqf1rgyiilg92vbd.nar.zst1096 Compression: zstd1097 NarHash: sha256:1417z8kfxgn3p4c8q7qbm4zxci8r1by4jl3psqf1rgyiilg92vbd1098 NarSize: 2561099 References: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientFallsBackToClosures1920531481/001/store/xc3igw19mxkf2vlxn7gmi084vbd48ar1-shared-dep1100 CA: text:sha256:0n068cqs80q7828lz7s4ajpkgnfrnsxnxi2ijfqjmc2qxgca67sw1101--- PASS: TestClientFallsBackToClosures (4.58s)1102=== CONT TestCreatePin_ReservedPins11032026/11/10 08:16:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60250/oidc11042026/11/10 08:16:17 INFO Received push request method=POST path=/api/pushes11052026/11/10 08:16:17 INFO Received uploads request method=POST path=/api/pending_closures11062026/11/10 08:16:17 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)11072026/11/10 08:16:17 INFO Uploading npsi4aypfxdjgf3js3885rmyv40s8gs5-b (256B)11082026/11/10 08:16:17 INFO Uploading 5d5fl4ly86b11d8bzvabxj8za1iw6b4g-shared-dep (136B)11092026/11/10 08:16:17 WARN Failed to register uploaded object key=npsi4aypfxdjgf3js3885rmyv40s8gs5.ls error="server returned 404: 404 page not found\n"11102026/11/10 08:16:17 WARN Failed to register uploaded object key=3jbrgx5l6376pxbab8vvvsfh0yprpvs6.ls error="server returned 404: 404 page not found\n"1111--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (5.36s)11122026/11/10 08:16:17 WARN Failed to register uploaded object key=5d5fl4ly86b11d8bzvabxj8za1iw6b4g.ls error="server returned 404: 404 page not found\n"1113=== CONT TestCompletedNarNotReofferedAcrossClosures11142026/11/10 08:16:17 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11152026/11/10 08:16:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11162026/11/10 08:16:17 WARN Failed to register uploaded object key=nar/0abwj6n7fv4xq0jdh6ph3b13z18z336skyb03hm7cdrv0gbwx91k.nar.zst error="server returned 404: 404 page not found\n"11172026/11/10 08:16:17 INFO Signed narinfos id=1 count=311182026/11/10 08:16:17 INFO Uploading 3 narinfos11192026/11/10 08:16:17 WARN Failed to register uploaded object key=3jbrgx5l6376pxbab8vvvsfh0yprpvs6.narinfo error="server returned 404: 404 page not found\n"11202026/11/10 08:16:17 WARN Failed to register uploaded object key=npsi4aypfxdjgf3js3885rmyv40s8gs5.narinfo error="server returned 404: 404 page not found\n"11212026/11/10 08:16:17 INFO Received complete push request method=POST path=/api/pushes/1/complete11222026/11/10 08:16:17 WARN Failed to register uploaded object key=5d5fl4ly86b11d8bzvabxj8za1iw6b4g.narinfo error="server returned 404: 404 page not found\n"11232026/11/10 08:16:17 INFO Completed push id=1 objects=8 duration=16.104792ms11242026/11/10 08:16:17 INFO Upload complete. (407ms)1125=== NAME TestClientPushesUseOnePush1126 client_pushes_test.go:97: Retrieved narinfo from S3:1127 StorePath: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientPushesUseOnePush3384651387/001/store/5d5fl4ly86b11d8bzvabxj8za1iw6b4g-shared-dep1128 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1129 Compression: zstd1130 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821131 NarSize: 1361132 References: 1133 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1134 client_pushes_test.go:97: Retrieved narinfo from S3:1135 StorePath: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientPushesUseOnePush3384651387/001/store/3jbrgx5l6376pxbab8vvvsfh0yprpvs6-a1136 URL: nar/0abwj6n7fv4xq0jdh6ph3b13z18z336skyb03hm7cdrv0gbwx91k.nar.zst1137 Compression: zstd1138 NarHash: sha256:0abwj6n7fv4xq0jdh6ph3b13z18z336skyb03hm7cdrv0gbwx91k1139 NarSize: 2561140 References: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientPushesUseOnePush3384651387/001/store/5d5fl4ly86b11d8bzvabxj8za1iw6b4g-shared-dep1141 CA: text:sha256:1gvywkmhyyappr6xzkkfzwzynnl49dqz1grmfr00p8l7yws0zmnl1142 client_pushes_test.go:97: Retrieved narinfo from S3:1143 StorePath: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientPushesUseOnePush3384651387/001/store/npsi4aypfxdjgf3js3885rmyv40s8gs5-b1144 URL: nar/0abwj6n7fv4xq0jdh6ph3b13z18z336skyb03hm7cdrv0gbwx91k.nar.zst1145 Compression: zstd1146 NarHash: sha256:0abwj6n7fv4xq0jdh6ph3b13z18z336skyb03hm7cdrv0gbwx91k1147 NarSize: 2561148 References: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientPushesUseOnePush3384651387/001/store/5d5fl4ly86b11d8bzvabxj8za1iw6b4g-shared-dep1149 CA: text:sha256:1gvywkmhyyappr6xzkkfzwzynnl49dqz1grmfr00p8l7yws0zmnl1150--- PASS: TestClientPushesUseOnePush (5.51s)1151=== CONT TestCompleteMultipartUpload_ErrorButObjectExists1152--- PASS: TestReadRedirectUsesPublicS3URL (5.55s)1153=== CONT TestSharedNarBothUploadsComplete1154--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (5.58s)1155=== CONT TestPush_SignsNarinfosOfItsPendingObjects1156--- PASS: TestReadProxyRangeRequest (5.70s)1157=== CONT TestPush_RejectsBadRequests11582026/11/10 08:16:17 INFO Received push request method=POST path=/api/pushes11592026/11/10 08:16:17 INFO Received push request method=POST path=/api/pushes11602026/11/10 08:16:18 INFO Received complete push request method=POST path=/api/pushes/1/complete11612026/11/10 08:16:18 INFO Completed push id=1 objects=4 duration=33.344417ms1162--- PASS: TestPush_RepeatedRootCommitsOnce (6.10s)1163=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit11642026-11-10 08:16:18.159 UTC [92403] ERROR: Push does not exist: id=111652026-11-10 08:16:18.159 UTC [92403] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE11662026-11-10 08:16:18.159 UTC [92403] STATEMENT: SELECT commit_push($1)1167--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (6.18s)1168=== CONT TestOrphanedObjectsGCStressTest1169--- PASS: TestReadProxyDisabled (6.22s)1170=== CONT TestPush_RootsAreLockedInByteOrder11712026/11/10 08:16:18 INFO Received push request method=POST path=/api/pushes1172--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (6.51s)1173=== CONT TestOrphanedObjectsGC11742026/11/10 08:16:18 INFO Received push request method=POST path=/api/pushes11752026/11/10 08:16:18 INFO Received complete push request method=POST path=/api/pushes/1/complete11762026/11/10 08:16:18 INFO Completed push id=1 objects=6 duration=22.471792ms1177--- PASS: TestPush_CompleteCommitsEveryRoot (6.80s)1178=== CONT TestObjectStatsUpdatedOncePerCommit11792026/11/10 08:16:18 INFO Received uploads request method=POST path=/api/pending_closures11802026/11/10 08:16:18 INFO Received uploads request method=POST path=/api/pending_closures11812026/11/10 08:16:18 INFO Received uploads request method=POST path=/api/pending_closures11822026/11/10 08:16:19 INFO Received uploads request method=POST path=/api/pending_closures1183--- PASS: TestReadRedirectKeepsNarinfoProxied (7.65s)1184=== CONT TestObjectStatsTrigger1185--- PASS: TestReadProxyRootRedirectsToIndexHTML (8.00s)1186=== CONT TestEnsureAbortUploadsRule11872026/11/10 08:16:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11882026/11/10 08:16:20 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YjAwMDE3NzYtNjJmMS00MDc1LWFjYmEtZDBhZmM2MDBkYjNiLjdjNDI0ZWRjLTRiZGUtNGRkMS1iOTBmLWQxNjc5YmY4MGI3M3gxNzk0Mjk4NTc4OTI5NDE2MDAw parts=1011892026/11/10 08:16:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11902026/11/10 08:16:20 INFO Completed upload id=1 objects=2 duration=19.565041ms11912026/11/10 08:16:20 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011922026/11/10 08:16:20 INFO Received uploads request method=POST path=/api/pending_closures11932026/11/10 08:16:20 INFO Starting cleanup of old closures method=DELETE path=/api/closures11942026/11/10 08:16:20 INFO Aborted multipart uploads count=0 kept=011952026/11/10 08:16:20 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=011962026/11/10 08:16:20 INFO Vacuumed table table=pending_closures1197=== NAME TestPinProtectsFromGC1198 client_integration_test.go:778: Pinned store path: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestPinProtectsFromGC2501125333/001/store/5dnblszd5i86hdrmmn59v8jb423krsxx-pinned-file.txt11992026/11/10 08:16:20 INFO Vacuumed table table=pending_objects1200 client_integration_test.go:779: Unpinned store path: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestPinProtectsFromGC2501125333/001/store/z5ssflzpcfsm3xffsx754shscgrr1gs9-unpinned-file.txt12012026/11/10 08:16:20 INFO Vacuumed table table=multipart_uploads12022026/11/10 08:16:20 INFO Vacuumed table table=closures12032026/11/10 08:16:20 INFO Received cleanup request method=DELETE path=/api/pending_closures12042026/11/10 08:16:20 INFO Vacuumed table table=objects12052026/11/10 08:16:20 INFO Aborted multipart uploads count=0 kept=012062026/11/10 08:16:20 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001207--- PASS: TestService_createPendingClosureHandler (8.81s)1208=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded12092026/11/10 08:16:20 INFO Received uploads request method=POST path=/api/pending_closures12102026/11/10 08:16:21 INFO Received cleanup request method=DELETE path=/api/pending_closures12112026/11/10 08:16:21 INFO Aborted multipart uploads count=1 kept=012122026/11/10 08:16:21 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12132026-11-10 08:16:21.087 UTC [92126] ERROR: Closure does not exist: id=112142026-11-10 08:16:21.087 UTC [92126] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE12152026-11-10 08:16:21.087 UTC [92126] STATEMENT: -- name: CommitPendingClosure :one1216 SELECT commit_pending_closure($1::bigint)::bigint1217 1218--- PASS: TestService_cleanupPendingClosuresHandler (9.10s)1219=== CONT TestGCSweepDeliversEachKeyOnce12202026/11/10 08:16:21 INFO Received push request method=POST path=/api/pushes12212026/11/10 08:16:21 INFO Aborted multipart uploads count=1 kept=012222026/11/10 08:16:21 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12232026/11/10 08:16:21 INFO Uploading 5dnblszd5i86hdrmmn59v8jb423krsxx-pinned-file.txt (128B)12242026/11/10 08:16:21 INFO Received cleanup request method=DELETE path=/api/pending_closures12252026/11/10 08:16:21 INFO Aborted multipart uploads count=1 kept=01226--- PASS: TestPendingCleanupUsesOneCutoff (9.31s)1227=== CONT TestMultipartCleanup12282026/11/10 08:16:21 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"12292026/11/10 08:16:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12302026/11/10 08:16:21 WARN Failed to register uploaded object key=5dnblszd5i86hdrmmn59v8jb423krsxx.ls error="server returned 404: 404 page not found\n"12312026/11/10 08:16:21 INFO Signed narinfos id=1 count=112322026/11/10 08:16:21 INFO Uploading 1 narinfos12332026/11/10 08:16:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12342026/11/10 08:16:21 INFO Received uploads request method=POST path=/api/pending_closures12352026/11/10 08:16:21 INFO Received complete push request method=POST path=/api/pushes/1/complete12362026/11/10 08:16:21 WARN Failed to register uploaded object key=5dnblszd5i86hdrmmn59v8jb423krsxx.narinfo error="server returned 404: 404 page not found\n"12372026/11/10 08:16:21 INFO Completed push id=1 objects=3 duration=30.455167ms12382026/11/10 08:16:21 INFO Upload complete. (468ms)12392026/11/10 08:16:21 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YjAwMDE3NzYtNjJmMS00MDc1LWFjYmEtZDBhZmM2MDBkYjNiLmExMzdkODgwLWY1MzgtNDVlZi04NzZjLTcxOWZlNDg4ZmFlY3gxNzk0Mjk4NTc5MzI0Mzk4MDAw parts=1012402026/11/10 08:16:21 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12412026/11/10 08:16:21 INFO Completed upload id=1 objects=2 duration=59.099833ms12422026/11/10 08:16:21 INFO Received uploads request method=POST path=/api/pending_closures12432026/11/10 08:16:21 INFO Received uploads request method=POST path=/api/pending_closures12442026/11/10 08:16:21 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo12452026/11/10 08:16:21 WARN Found objects in DB but missing from S3, will re-upload count=11246--- PASS: TestService_verifyS3Integrity (9.70s)1247=== CONT TestServerTLSConfig1248=== RUN TestServerTLSConfig/no_client_CA1249=== PAUSE TestServerTLSConfig/no_client_CA1250=== RUN TestServerTLSConfig/missing_CA_file1251=== PAUSE TestServerTLSConfig/missing_CA_file1252=== RUN TestServerTLSConfig/not_a_PEM_file1253=== PAUSE TestServerTLSConfig/not_a_PEM_file1254=== CONT TestService_NativeMTLS12552026/11/10 08:16:21 INFO Received push request method=POST path=/api/pushes12562026/11/10 08:16:21 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12572026/11/10 08:16:21 INFO Uploading z5ssflzpcfsm3xffsx754shscgrr1gs9-unpinned-file.txt (128B)12582026/11/10 08:16:21 WARN Failed to register uploaded object key=z5ssflzpcfsm3xffsx754shscgrr1gs9.ls error="server returned 404: 404 page not found\n"12592026/11/10 08:16:21 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12602026/11/10 08:16:21 INFO Signed narinfos id=2 count=112612026/11/10 08:16:21 INFO Uploading 1 narinfos12622026/11/10 08:16:21 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"1263--- PASS: TestPresentRefreshesOnlyStaleClosures (6.71s)1264=== CONT TestMetricsCommit12652026/11/10 08:16:21 INFO Received complete push request method=POST path=/api/pushes/2/complete12662026/11/10 08:16:21 WARN Failed to register uploaded object key=z5ssflzpcfsm3xffsx754shscgrr1gs9.narinfo error="server returned 404: 404 page not found\n"12672026/11/10 08:16:21 INFO Completed push id=2 objects=3 duration=2.5305ms12682026/11/10 08:16:21 INFO Upload complete. (475ms)12692026/11/10 08:16:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12702026/11/10 08:16:22 INFO Starting cleanup of old closures method=DELETE path=/api/closures12712026/11/10 08:16:22 INFO Garbage collection started12722026/11/10 08:16:22 INFO Aborted multipart uploads count=0 kept=012732026/11/10 08:16:22 WARN Force mode enabled - objects will be deleted immediately without grace period1274--- PASS: TestService_Rustfstest (6.47s)1275=== CONT TestGCEndsOnShutdown1276=== RUN TestGCEndsOnShutdown/before_the_run1277=== PAUSE TestGCEndsOnShutdown/before_the_run1278=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1279=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1280=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1281=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1282=== CONT TestCommitRacingPendingCleanupKeepsObjects1283--- PASS: TestDeleteClosuresRacingPins (10.40s)1284=== CONT TestPushWaitsForSweepHoldingRow12852026/11/10 08:16: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=012862026/11/10 08:16:22 INFO Vacuumed table table=pending_closures1287--- PASS: TestPresentReportsOnlyClosureRoots (6.90s)1288=== CONT TestMetricsInventory12892026/11/10 08:16:22 INFO Vacuumed table table=pending_objects12902026/11/10 08:16:22 INFO Vacuumed table table=multipart_uploads12912026/11/10 08:16:22 INFO Vacuumed table table=closures12922026/11/10 08:16:22 INFO Vacuumed table table=objects12932026/11/10 08:16:22 INFO Received uploads request method=POST path=/api/pending_closures12942026/11/10 08:16:23 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst12952026/11/10 08:16:23 INFO Received uploads request method=POST path=/api/pending_closures1296--- PASS: TestPresignedUploadRegisteredBeforeCommit (7.03s)1297=== CONT TestSweepRechecksPendingAfterLocking12982026/11/10 08:16:23 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12992026/11/10 08:16:23 WARN Refused reserved pin name=worker-x86_64-linux13002026/11/10 08:16:23 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13012026/11/10 08:16:23 INFO Received create pin request method=POST path=/api/pins/my-app13022026/11/10 08:16:23 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1303--- PASS: TestCreatePin_ReservedPins (6.73s)1304=== CONT TestGetExistingObjectsLocksRows13052026/11/10 08:16:23 INFO Received uploads request method=POST path=/api/pending_closures13062026/11/10 08:16:23 INFO Received uploads request method=POST path=/api/pending_closures13072026/11/10 08:16:24 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=013082026/11/10 08:16:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13092026/11/10 08:16:24 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjAwMDE3NzYtNjJmMS00MDc1LWFjYmEtZDBhZmM2MDBkYjNiLjY1NWY5MWIxLTQ3NGQtNDk1MC04ZjA2LTU5ZmU5YmM0MjhiNngxNzk0Mjk4NTgzOTI3NTMxMDAw13102026/11/10 08:16:24 INFO Received create pin request method=POST path=/api/pins/myapp13112026/11/10 08:16:24 INFO Received uploads request method=POST path=/api/pending_closures13122026/11/10 08:16:24 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjAwMDE3NzYtNjJmMS00MDc1LWFjYmEtZDBhZmM2MDBkYjNiLjY1NWY5MWIxLTQ3NGQtNDk1MC04ZjA2LTU5ZmU5YmM0MjhiNngxNzk0Mjk4NTgzOTI3NTMxMDAw parts=11313--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (6.73s)1314=== CONT TestNARDeduplicationMetadataUploadBug13152026/11/10 08:16:24 INFO Created/updated pin name=myapp store_path=/private/var/tb/5/scratch/e759ffdaa87b1701/build/TestPinProtectsFromGC2501125333/001/store/5dnblszd5i86hdrmmn59v8jb423krsxx-pinned-file.txt narinfo_key=5dnblszd5i86hdrmmn59v8jb423krsxx.narinfo13162026/11/10 08:16:24 INFO Starting cleanup of old closures method=DELETE path=/api/closures13172026/11/10 08:16:24 INFO Garbage collection started13182026/11/10 08:16:24 INFO Aborted multipart uploads count=0 kept=013192026/11/10 08:16:24 WARN Force mode enabled - objects will be deleted immediately without grace period13202026/11/10 08:16: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=013212026/11/10 08:16:24 INFO Vacuumed table table=pending_closures13222026/11/10 08:16:24 INFO Vacuumed table table=pending_objects13232026/11/10 08:16:24 INFO Vacuumed table table=multipart_uploads13242026/11/10 08:16:24 INFO Vacuumed table table=closures13252026/11/10 08:16:24 INFO Vacuumed table table=objects13262026/11/10 08:16:24 INFO Received uploads request method=POST path=/api/pending_closures13272026/11/10 08:16:24 INFO Received push request method=POST path=/api/pushes13282026/11/10 08:16:24 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13292026/11/10 08:16:24 INFO Signed narinfos id=1 count=113302026/11/10 08:16:24 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13312026/11/10 08:16:24 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13322026/11/10 08:16:24 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"13332026/11/10 08:16:24 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13342026/11/10 08:16:24 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"13352026/11/10 08:16:24 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13362026/11/10 08:16:24 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=113372026/11/10 08:16:24 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13382026/11/10 08:16:24 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1339--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (7.21s)1340=== CONT TestRegisterCompletedObjectNeedsPendingRow1341=== RUN TestPush_RejectsBadRequests/no_roots1342=== PAUSE TestPush_RejectsBadRequests/no_roots1343=== RUN TestPush_RejectsBadRequests/no_objects1344=== PAUSE TestPush_RejectsBadRequests/no_objects1345=== RUN TestPush_RejectsBadRequests/bad_root1346=== PAUSE TestPush_RejectsBadRequests/bad_root1347=== RUN TestPush_RejectsBadRequests/root_not_in_objects1348=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1349=== CONT TestCreatePendingClosureRejectsOversizedNAR13502026/11/10 08:16:25 INFO Received uploads request method=POST path=/api/pending_closures1351--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1352=== CONT TestSweepSkipsRowsLockedByPush13532026/11/10 08:16:25 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13542026/11/10 08:16:25 INFO Received push request method=POST path=/api/pushes13552026/11/10 08:16:25 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YjAwMDE3NzYtNjJmMS00MDc1LWFjYmEtZDBhZmM2MDBkYjNiLmQxZDBjMDRlLTI0YjQtNGNhNS1iNzI1LTkzYTQwOGJhNzQxOXgxNzk0Mjk4NTgzNTkwNDI1MDAw parts=1213562026/11/10 08:16:25 INFO Received uploads request method=POST path=/api/pending_closures1357--- PASS: TestCompletedNarNotReofferedAcrossClosures (8.51s)1358=== CONT TestCacheConfigHandlerMaxNarSize1359--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1360=== CONT TestFailedS3DeleteKeepsTombstone13612026/11/10 08:16:25 INFO Received complete push request method=POST path=/api/pushes/1/complete13622026/11/10 08:16:26 INFO Completed push id=1 objects=4 duration=48.207542ms13632026/11/10 08:16:26 INFO Received push request method=POST path=/api/pushes13642026/11/10 08:16:26 INFO Aborted multipart uploads count=0 kept=013652026/11/10 08:16:26 WARN Force mode enabled - objects will be deleted immediately without grace period13662026/11/10 08:16:26 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=013672026/11/10 08:16:26 INFO Vacuumed table table=pending_closures13682026/11/10 08:16:26 INFO Received push request method=POST path=/api/pushes13692026/11/10 08:16:26 INFO Vacuumed table table=pending_objects13702026/11/10 08:16:26 INFO Vacuumed table table=multipart_uploads1371=== NAME TestPinProtectsFromGC1372 client_integration_test.go:887: Pin successfully protected closure from garbage collection13732026/11/10 08:16:26 INFO Vacuumed table table=closures13742026/11/10 08:16:26 INFO Vacuumed table table=objects13752026/11/10 08:16:26 INFO Received complete push request method=POST path=/api/pushes/2/complete13762026/11/10 08:16:26 INFO Completed push id=2 objects=4 duration=7.561541ms1377--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (8.31s)1378=== CONT TestForceGCDuringPushOffersSweptObject1379=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1380=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows13812026-11-10 08:16:26.420 UTC [92887] ERROR: could not obtain lock on row in relation "closures"13822026-11-10 08:16:26.420 UTC [92887] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1383=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1384=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1385=== CONT TestService_ReadScope_PublicByDefault13862026-11-10 08:16:26.425 UTC [92887] ERROR: could not obtain lock on row in relation "closures"13872026-11-10 08:16:26.425 UTC [92887] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13882026-11-10 08:16:26.433 UTC [92887] ERROR: could not obtain lock on row in relation "closures"13892026-11-10 08:16:26.433 UTC [92887] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13902026-11-10 08:16:26.434 UTC [92887] ERROR: could not obtain lock on row in relation "closures"13912026-11-10 08:16:26.434 UTC [92887] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13922026-11-10 08:16:26.446 UTC [92887] ERROR: could not obtain lock on row in relation "closures"13932026-11-10 08:16:26.446 UTC [92887] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1394--- PASS: TestPush_RootsAreLockedInByteOrder (8.29s)1395=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1396--- PASS: TestPinProtectsFromGC (14.52s)1397=== CONT TestClientMultipleUploads13982026/11/10 08:16:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13992026/11/10 08:16:26 WARN Rate limiter enabled after throttle name=s3-test rate=514002026/11/10 08:16:26 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1401=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1402 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101403 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001404--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (13.30s)1405=== CONT TestClientIntegration14062026/11/10 08:16:26 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YjAwMDE3NzYtNjJmMS00MDc1LWFjYmEtZDBhZmM2MDBkYjNiLjI0ZDQ2YzRhLTk4NGYtNDgxMy1hM2JkLWE3MjRhMGRhOGViOXgxNzk0Mjk4NTg0MjkzNTE2MDAw parts=121407--- PASS: TestObjectStatsUpdatedOncePerCommit (8.90s)1408=== CONT TestClientCADerivations14092026/11/10 08:16:27 INFO Installed lifecycle rule aborting incomplete NAR uploads bucket=bucket43 days=21410--- PASS: TestEnsureAbortUploadsRule (7.97s)1411=== CONT TestClientErrorHandling1412=== RUN TestClientErrorHandling/InvalidStorePath1413=== PAUSE TestClientErrorHandling/InvalidStorePath1414=== RUN TestClientErrorHandling/InvalidAuthToken1415=== PAUSE TestClientErrorHandling/InvalidAuthToken1416=== RUN TestClientErrorHandling/ServerNotAvailable1417=== PAUSE TestClientErrorHandling/ServerNotAvailable1418=== CONT TestCacheStatsHandler1419--- PASS: TestObjectStatsTrigger (8.81s)1420=== CONT TestCacheConfigHandler1421=== RUN TestCacheConfigHandler/full_config,_no_issuer1422=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1423=== RUN TestCacheConfigHandler/no_cache_url_configured1424=== PAUSE TestCacheConfigHandler/no_cache_url_configured1425=== RUN TestCacheConfigHandler/no_signing_keys1426=== PAUSE TestCacheConfigHandler/no_signing_keys1427=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1428=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1429=== CONT TestReadProxy40414302026/11/10 08:16:28 INFO Received uploads request method=POST path=/api/pending_closures1431--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (8.24s)1432=== CONT TestReadProxyConditionalGet14332026/11/10 08:16:29 INFO Received uploads request method=POST path=/api/pending_closures1434=== NAME TestOrphanedObjectsGC1435 orphaned_objects_gc_test.go:287: GC Test Summary:1436 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1437 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1438 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1439 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1440 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1441--- PASS: TestOrphanedObjectsGC (11.22s)1442=== CONT TestReadProxyContentNegotiation14432026/11/10 08:16:29 INFO Received cleanup request method=DELETE path=/api/pending_closures14442026/11/10 08:16:29 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket46/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""14452026/11/10 08:16:29 INFO Aborted multipart uploads count=0 kept=114462026/11/10 08:16:30 INFO Received cleanup request method=DELETE path=/api/pending_closures14472026/11/10 08:16:30 INFO Aborted multipart uploads count=1 kept=01448--- PASS: TestMultipartCleanup (8.74s)1449=== CONT TestReadProxyNarStreaming14502026/11/10 08:16:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14512026/11/10 08:16:30 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YjAwMDE3NzYtNjJmMS00MDc1LWFjYmEtZDBhZmM2MDBkYjNiLmEzMDhiZDliLTYyMGYtNDk5YS1hOThkLWQ3MDk2N2JjMmRmMXgxNzk0Mjk4NTg0MzQwOTA4MDAw parts=121452--- PASS: TestSharedNarBothUploadsComplete (12.81s)1453=== CONT TestReadProxyOutlastsServerWriteTimeout14542026/11/10 08:16:30 INFO Aborted multipart uploads count=0 kept=014552026/11/10 08:16:30 WARN Force mode enabled - objects will be deleted immediately without grace period14562026/11/10 08:16:30 WARN mTLS auth: subject not in bound subjects subject="CN=reader"14572026/11/10 08:16:30 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1458--- PASS: TestService_NativeMTLS (8.94s)1459=== CONT TestReadProxyHead14602026/11/10 08:16:31 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=014612026/11/10 08:16:31 INFO Vacuumed table table=pending_closures14622026/11/10 08:16:31 INFO Vacuumed table table=pending_objects14632026/11/10 08:16:31 INFO Vacuumed table table=multipart_uploads14642026/11/10 08:16:31 INFO Vacuumed table table=closures14652026/11/10 08:16:31 INFO Received push request method=POST path=/api/pushes14662026/11/10 08:16:31 INFO Vacuumed table table=objects1467--- PASS: TestGCSweepDeliversEachKeyOnce (10.18s)1468=== CONT TestReadProxyNarinfoAlreadyDecompressed14692026/11/10 08:16:31 INFO Received complete push request method=POST path=/api/pushes/1/complete14702026/11/10 08:16:31 INFO Completed push id=1 objects=4 duration=43.018917ms14712026/11/10 08:16:31 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14722026/11/10 08:16:31 INFO Completed upload id=2 objects=2 duration=1.116541ms1473--- PASS: TestMetricsCommit (9.54s)1474=== CONT TestReadProxyInvalidPath14752026/11/10 08:16:31 INFO Aborted multipart uploads count=0 kept=014762026/11/10 08:16:32 WARN Force mode enabled - objects will be deleted immediately without grace period14772026/11/10 08:16:32 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014782026/11/10 08:16:32 INFO Vacuumed table table=pending_closures14792026/11/10 08:16:32 INFO Vacuumed table table=pending_objects14802026/11/10 08:16:32 INFO Vacuumed table table=multipart_uploads14812026/11/10 08:16:32 INFO Received uploads request method=POST path=/api/pending_closures14822026/11/10 08:16:32 INFO Vacuumed table table=closures14832026/11/10 08:16:32 INFO Vacuumed table table=objects1484--- PASS: TestCommitRacingPendingCleanupKeepsObjects (9.91s)1485=== CONT TestGCMetrics1486--- PASS: TestMetricsInventory (9.79s)1487=== CONT TestReadProxyNarinfo1488--- PASS: TestPushWaitsForSweepHoldingRow (10.25s)1489=== CONT TestTombstonedObjectOfferedWithoutWaiting14902026/11/10 08:16:33 INFO Aborted multipart uploads count=0 kept=014912026/11/10 08:16:33 WARN Force mode enabled - objects will be deleted immediately without grace period14922026/11/10 08:16:33 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014932026/11/10 08:16:33 INFO Vacuumed table table=pending_closures14942026/11/10 08:16:33 INFO Vacuumed table table=pending_objects14952026/11/10 08:16:33 INFO Vacuumed table table=multipart_uploads14962026/11/10 08:16:33 INFO Vacuumed table table=closures1497--- PASS: TestGetExistingObjectsLocksRows (9.98s)1498=== CONT TestGCSweepSkipsPendingObjects14992026/11/10 08:16:33 INFO Vacuumed table table=objects1500--- PASS: TestSweepRechecksPendingAfterLocking (10.19s)1501=== CONT TestDeduplicatedObjectsRecordedAsPending1502=== NAME TestNARDeduplicationMetadataUploadBug1503 metadata_upload_test.go:48: First store path: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestNARDeduplicationMetadataUploadBug2687402718/001/store/6r9qaqhw5mkywbc5d803d7mkglxw1cv9-file1.txt1504--- PASS: TestRegisterCompletedObjectNeedsPendingRow (9.24s)1505=== CONT TestPushDedupSurvivesConcurrentGC15062026/11/10 08:16:34 INFO Received push request method=POST path=/api/pushes15072026/11/10 08:16:34 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15082026/11/10 08:16:34 INFO Uploading 6r9qaqhw5mkywbc5d803d7mkglxw1cv9-file1.txt (160B)15092026/11/10 08:16:34 WARN Failed to register uploaded object key=6r9qaqhw5mkywbc5d803d7mkglxw1cv9.ls error="server returned 404: 404 page not found\n"15102026/11/10 08:16:34 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15112026/11/10 08:16:34 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"15122026/11/10 08:16:34 INFO Signed narinfos id=1 count=115132026/11/10 08:16:34 INFO Uploading 1 narinfos15142026/11/10 08:16:34 INFO Received complete push request method=POST path=/api/pushes/1/complete15152026/11/10 08:16:34 WARN Failed to register uploaded object key=6r9qaqhw5mkywbc5d803d7mkglxw1cv9.narinfo error="server returned 404: 404 page not found\n"15162026/11/10 08:16:34 INFO Completed push id=1 objects=3 duration=38.739292ms15172026/11/10 08:16:34 INFO Upload complete. (277ms)1518=== NAME TestNARDeduplicationMetadataUploadBug1519 metadata_upload_test.go:54: Retrieved narinfo from S3:1520 StorePath: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestNARDeduplicationMetadataUploadBug2687402718/001/store/6r9qaqhw5mkywbc5d803d7mkglxw1cv9-file1.txt1521 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1522 Compression: zstd1523 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1524 NarSize: 1601525 References: 1526 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1527 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1528 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1529 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}15302026/11/10 08:16:34 INFO Aborted multipart uploads count=0 kept=01531 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestNARDeduplicationMetadataUploadBug2687402718/001/store/x90q8y9vwds9wngvkdamsyivy7jmcy4d-file2.txt15322026/11/10 08:16:34 WARN Force mode enabled - objects will be deleted immediately without grace period15332026/11/10 08:16:34 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=015342026/11/10 08:16:34 INFO Vacuumed table table=pending_closures15352026/11/10 08:16:34 INFO Vacuumed table table=pending_objects15362026/11/10 08:16:34 INFO Vacuumed table table=multipart_uploads15372026/11/10 08:16:34 INFO Vacuumed table table=closures15382026/11/10 08:16:34 INFO Vacuumed table table=objects15392026/11/10 08:16:34 INFO Aborted multipart uploads count=0 kept=015402026/11/10 08:16:34 WARN Force mode enabled - objects will be deleted immediately without grace period15412026/11/10 08:16:34 INFO Received push request method=POST path=/api/pushes15422026/11/10 08:16:34 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)15432026/11/10 08:16:34 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign15442026/11/10 08:16:34 WARN Failed to register uploaded object key=x90q8y9vwds9wngvkdamsyivy7jmcy4d.ls error="server returned 404: 404 page not found\n"15452026/11/10 08:16:34 INFO Signed narinfos id=2 count=115462026/11/10 08:16:34 INFO Uploading 1 narinfos15472026/11/10 08:16:34 INFO Received complete push request method=POST path=/api/pushes/2/complete15482026/11/10 08:16:34 INFO Received uploads request method=POST path=/api/pending_closures15492026/11/10 08:16:34 WARN Failed to register uploaded object key=x90q8y9vwds9wngvkdamsyivy7jmcy4d.narinfo error="server returned 404: 404 page not found\n"15502026/11/10 08:16:34 INFO Completed push id=2 objects=3 duration=1.141708ms15512026/11/10 08:16:34 INFO Upload complete. (214ms)1552 metadata_upload_test.go:76: Retrieved narinfo from S3:1553 StorePath: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestNARDeduplicationMetadataUploadBug2687402718/001/store/x90q8y9vwds9wngvkdamsyivy7jmcy4d-file2.txt1554 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1555 Compression: zstd1556 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1557 NarSize: 1601558 References: 1559 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1560 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1561 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1562 {"version":1,"root":{"type":"regular","size":44}}15632026/11/10 08:16:34 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=1 objects-failed-to-delete=01564--- PASS: TestNARDeduplicationMetadataUploadBug (10.56s)1565=== CONT TestService_ReadAuthMiddleware15662026/11/10 08:16:34 INFO Vacuumed table table=pending_closures15672026/11/10 08:16:34 INFO Vacuumed table table=pending_objects15682026/11/10 08:16:34 INFO Vacuumed table table=multipart_uploads15692026/11/10 08:16:34 INFO Vacuumed table table=closures15702026/11/10 08:16:34 INFO Vacuumed table table=objects1571--- PASS: TestSweepSkipsRowsLockedByPush (9.83s)1572=== CONT TestGCTaskStore_PhaseUpdates1573--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1574=== CONT TestService_RequireScope_OIDC15752026/11/10 08:16:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60443/oidc15762026/11/10 08:16:34 INFO Aborted multipart uploads count=0 kept=015772026/11/10 08:16:34 WARN Force mode enabled - objects will be deleted immediately without grace period15782026/11/10 08:16:35 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."15792026/11/10 08:16:35 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1580--- PASS: TestFailedS3DeleteKeepsTombstone (9.14s)1581=== CONT TestService_AuthMiddleware_OIDC15822026/11/10 08:16:35 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60451/oidc15832026/11/10 08:16:35 INFO Received uploads request method=POST path=/api/pending_closures1584--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (8.80s)1585=== CONT TestGenerateLandingPage1586--- PASS: TestGenerateLandingPage (0.00s)1587=== CONT TestGCTaskStore_GetEmpty1588--- PASS: TestGCTaskStore_GetEmpty (0.00s)1589=== CONT TestService_readinessHandler1590--- PASS: TestService_ReadScope_PublicByDefault (8.95s)1591=== CONT TestGCTaskStore_CompletedAllowsNewTask1592--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1593=== CONT TestService_healthCheckHandler1594=== NAME TestClientMultipleUploads1595 client_integration_test.go:405: Created store path 0: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientMultipleUploads3086111752/001/store/h4l08fg5zs20drdi2b045ymbv2hywmvg-test-file-0.txt1596 client_integration_test.go:405: Created store path 1: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientMultipleUploads3086111752/001/store/kdw38fs3gwn6iv40f2imvnas6izczdhk-test-file-1.txt1597 client_integration_test.go:405: Created store path 2: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientMultipleUploads3086111752/001/store/4njhhslsjmav7172w9lnxhpcf7pmpc8b-test-file-2.txt1598=== NAME TestClientIntegration1599 client_integration_test.go:291: Created store path: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientIntegration2840852997/002/store/l5q3npqfw23llqxqanagzfl84brdkbj6-test-file.txt16002026/11/10 08:16:36 INFO Received push request method=POST path=/api/pushes16012026/11/10 08:16:36 INFO Received push request method=POST path=/api/pushes16022026/11/10 08:16:36 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16032026/11/10 08:16:36 INFO Uploading l5q3npqfw23llqxqanagzfl84brdkbj6-test-file.txt (152B)16042026/11/10 08:16:36 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16052026/11/10 08:16:36 INFO Uploading h4l08fg5zs20drdi2b045ymbv2hywmvg-test-file-0.txt (160B)16062026/11/10 08:16:36 INFO Uploading kdw38fs3gwn6iv40f2imvnas6izczdhk-test-file-1.txt (160B)16072026/11/10 08:16:36 INFO Uploading 4njhhslsjmav7172w9lnxhpcf7pmpc8b-test-file-2.txt (160B)16082026/11/10 08:16:36 WARN Failed to register uploaded object key=l5q3npqfw23llqxqanagzfl84brdkbj6.ls error="server returned 404: 404 page not found\n"16092026/11/10 08:16:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16102026/11/10 08:16:36 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"16112026/11/10 08:16:36 INFO Signed narinfos id=1 count=116122026/11/10 08:16:36 INFO Uploading 1 narinfos16132026/11/10 08:16:36 WARN Failed to register uploaded object key=kdw38fs3gwn6iv40f2imvnas6izczdhk.ls error="server returned 404: 404 page not found\n"16142026/11/10 08:16:36 WARN Failed to register uploaded object key=h4l08fg5zs20drdi2b045ymbv2hywmvg.ls error="server returned 404: 404 page not found\n"16152026/11/10 08:16:36 WARN Failed to register uploaded object key=4njhhslsjmav7172w9lnxhpcf7pmpc8b.ls error="server returned 404: 404 page not found\n"16162026/11/10 08:16:36 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16172026/11/10 08:16:36 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"16182026/11/10 08:16:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16192026/11/10 08:16:36 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16202026/11/10 08:16:36 INFO Signed narinfos id=1 count=316212026/11/10 08:16:36 INFO Uploading 3 narinfos16222026/11/10 08:16:36 INFO Received complete push request method=POST path=/api/pushes/1/complete16232026/11/10 08:16:36 WARN Failed to register uploaded object key=l5q3npqfw23llqxqanagzfl84brdkbj6.narinfo error="server returned 404: 404 page not found\n"16242026/11/10 08:16:36 INFO Completed push id=1 objects=3 duration=33.84975ms16252026/11/10 08:16:36 INFO Upload complete. (349ms)16262026/11/10 08:16:36 WARN Failed to register uploaded object key=4njhhslsjmav7172w9lnxhpcf7pmpc8b.narinfo error="server returned 404: 404 page not found\n"16272026/11/10 08:16:36 WARN Failed to register uploaded object key=h4l08fg5zs20drdi2b045ymbv2hywmvg.narinfo error="server returned 404: 404 page not found\n"16282026/11/10 08:16:36 INFO Received complete push request method=POST path=/api/pushes/1/complete16292026/11/10 08:16:36 WARN Failed to register uploaded object key=kdw38fs3gwn6iv40f2imvnas6izczdhk.narinfo error="server returned 404: 404 page not found\n"16302026/11/10 08:16:36 INFO Completed push id=1 objects=9 duration=9.429209ms16312026/11/10 08:16:36 INFO Upload complete. (397ms)1632=== NAME TestClientMultipleUploads1633 client_integration_test.go:416: Uploaded 3 paths in 443.048583ms16342026/11/10 08:16:36 INFO All 1 paths already cached1635=== NAME TestClientIntegration1636 client_integration_test.go:317: Retrieved narinfo from S3:1637 StorePath: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientIntegration2840852997/002/store/l5q3npqfw23llqxqanagzfl84brdkbj6-test-file.txt1638 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1639 Compression: zstd1640--- PASS: TestCacheStatsHandler (8.89s)1641=== CONT TestGCTaskStore_GetReturnsLatest1642=== CONT TestGracefulShutdownDrainsInflight1643=== NAME TestClientIntegration1644 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11645 NarSize: 1521646 References: 1647 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11648--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)16492026/11/10 08:16:36 INFO Starting HTTP server address=127.0.0.1:6048816502026/11/10 08:16:36 INFO Shutdown signal received, draining in-flight requests timeout=10s1651=== NAME TestClientIntegration1652 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1653 client_integration_test.go:318: Decompressed .ls content (64 bytes):1654 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1655--- PASS: TestGracefulShutdownDrainsInflight (0.08s)1656=== CONT TestGCTaskStore_Fail1657--- PASS: TestGCTaskStore_Fail (0.00s)1658=== CONT TestService_AuthMiddleware_MTLSProxyHeader1659--- PASS: TestClientMultipleUploads (10.46s)1660=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1661=== NAME TestClientCADerivations1662 client_ca_test.go:136: Built CA derivation: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientCADerivations3755023234/001/store/dqfx20znmd9z0jhg1nxgjb9rmhj10jqy-ca-test1663 client_ca_test.go:139: Found 1 dependencies (including self)16642026/11/10 08:16:37 INFO Received push request method=POST path=/api/pushes16652026/11/10 08:16:37 INFO Object in database but missing from S3 key=l5q3npqfw23llqxqanagzfl84brdkbj6.ls16662026/11/10 08:16:37 WARN Found objects in DB but missing from S3, will re-upload count=116672026/11/10 08:16:37 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)16682026/11/10 08:16:37 INFO Received push request method=POST path=/api/pushes16692026/11/10 08:16:37 INFO Received complete push request method=POST path=/api/pushes/2/complete16702026/11/10 08:16:37 WARN Failed to register uploaded object key=l5q3npqfw23llqxqanagzfl84brdkbj6.ls error="server returned 404: 404 page not found\n"16712026/11/10 08:16:37 INFO Completed push id=2 objects=3 duration=847.75µs16722026/11/10 08:16:37 INFO Upload complete. (136ms)1673=== NAME TestClientIntegration1674 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1675 client_integration_test.go:335: Decompressed .ls content (49 bytes):1676 {"version":1,"root":{"type":"regular","size":39}}16772026/11/10 08:16:37 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16782026/11/10 08:16:37 INFO Uploading dqfx20znmd9z0jhg1nxgjb9rmhj10jqy-ca-test (144B)16792026/11/10 08:16:37 WARN Failed to register uploaded object key=dqfx20znmd9z0jhg1nxgjb9rmhj10jqy.ls error="server returned 404: 404 page not found\n"16802026/11/10 08:16:37 WARN Failed to register uploaded object key=log/105j8dk301sjqwvid702wkvrbr9svphn-ca-test.drv error="server returned 404: 404 page not found\n"16812026/11/10 08:16:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16822026/11/10 08:16:37 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"16832026/11/10 08:16:37 INFO Signed narinfos id=1 count=116842026/11/10 08:16:37 INFO Uploading 1 narinfos16852026/11/10 08:16:37 INFO Received complete push request method=POST path=/api/pushes/1/complete16862026/11/10 08:16:37 WARN Failed to register uploaded object key=dqfx20znmd9z0jhg1nxgjb9rmhj10jqy.narinfo error="server returned 404: 404 page not found\n"16872026/11/10 08:16:37 INFO Completed push id=1 objects=4 duration=48.496167ms16882026/11/10 08:16:37 INFO Upload complete. (418ms)1689=== NAME TestClientCADerivations1690 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientCADerivations3755023234/001/store/dqfx20znmd9z0jhg1nxgjb9rmhj10jqy-ca-test1691 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1692 Compression: zstd1693 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1694 NarSize: 1441695 References: 1696 Deriver: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientCADerivations3755023234/001/store/105j8dk301sjqwvid702wkvrbr9svphn-ca-test.drv1697 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1698 client_ca_test.go:185: Checking for realisation files in S3...1699 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1700 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1701--- PASS: TestReadProxyConditionalGet (8.63s)1702=== CONT TestGCTaskStore_ConflictDifferentParams1703--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1704=== CONT TestService_AuthMiddleware17052026/11/10 08:16:37 INFO Received push request method=POST path=/api/pushes17062026/11/10 08:16:37 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17072026/11/10 08:16:37 INFO Received complete push request method=POST path=/api/pushes/3/complete17082026/11/10 08:16:37 WARN Failed to register uploaded object key=l5q3npqfw23llqxqanagzfl84brdkbj6.ls error="server returned 404: 404 page not found\n"17092026/11/10 08:16:37 INFO Completed push id=3 objects=3 duration=1.317125ms1710=== NAME TestClientCADerivations17112026/11/10 08:16:37 INFO Upload complete. (201ms)1712 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket63?endpoint=http://localhost:60127®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/5/scratch/e759ffdaa87b1701/build/TestClientCADerivations3755023234/001/store'1713 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11714=== NAME TestClientIntegration1715 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1716 client_integration_test.go:352: Decompressed .ls content (49 bytes):1717 {"version":1,"root":{"type":"regular","size":39}}1718 client_integration_test.go:363: Testing garbage collection...17192026/11/10 08:16:37 INFO Starting cleanup of old closures method=DELETE path=/api/closures17202026/11/10 08:16:38 INFO Garbage collection started17212026/11/10 08:16:38 INFO Aborted multipart uploads count=0 kept=01722--- PASS: TestClientCADerivations (10.35s)1723--- PASS: TestReadProxy404 (9.55s)1724=== CONT TestLeadEndsOnShutdown1725=== CONT TestLeadIncumbentAnnouncesAtOnce17262026/11/10 08:16:38 WARN Force mode enabled - objects will be deleted immediately without grace period1727--- PASS: TestReadProxyContentNegotiation (8.64s)1728=== CONT TestGCBugBareHashReferences17292026/11/10 08:16:38 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=017302026/11/10 08:16:38 INFO Vacuumed table table=pending_closures17312026/11/10 08:16:38 INFO Vacuumed table table=pending_objects17322026/11/10 08:16:38 INFO Vacuumed table table=multipart_uploads17332026/11/10 08:16:38 INFO Vacuumed table table=closures17342026/11/10 08:16:38 INFO Vacuumed table table=objects1735--- PASS: TestReadProxyNarStreaming (9.18s)1736=== CONT TestGCAdvisoryLockBlocksConcurrentRun1737--- PASS: TestReadProxyHead (9.04s)1738=== CONT TestLeadElectsOneAndHandsOver17392026/11/10 08:16:40 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01740=== NAME TestClientIntegration1741 client_integration_test.go:370: Objects in database after GC:1742 client_integration_test.go:370: Successfully deleted all objects with GC --force1743--- PASS: TestReadProxyNarinfoAlreadyDecompressed (8.88s)1744=== CONT TestIsValidCachePath/narinfo1745=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1746--- PASS: TestClientIntegration (13.31s)1747=== CONT TestIsValidCachePath/short_hash1748=== CONT TestIsValidCachePath/wrong_extension1749=== CONT TestIsValidCachePath/leading_slash1750=== CONT TestIsValidCachePath/empty1751=== CONT TestIsValidCachePath/random_path1752=== CONT TestIsValidCachePath/invalid_char_u1753=== CONT TestIsValidCachePath/invalid_char_e1754=== CONT TestIsValidCachePath/traversal_in_middle1755=== CONT TestIsValidCachePath/traversal_parent1756=== CONT TestIsValidCachePath/index.html1757=== CONT TestIsValidCachePath/nix-cache-info1758=== CONT TestIsValidCachePath/realisation1759=== CONT TestIsValidCachePath/log1760=== CONT TestIsValidCachePath/ls1761=== CONT TestIsValidCachePath/nar_uncompressed1762=== CONT TestIsValidCachePath/nar_bz21763=== CONT TestIsValidCachePath/nar_xz1764=== CONT TestIsValidCachePath/nar_zst1765=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1766--- PASS: TestIsValidCachePath (0.01s)1767 --- PASS: TestIsValidCachePath/narinfo (0.00s)1768 --- PASS: TestIsValidCachePath/short_hash (0.00s)1769 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1770 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1771 --- PASS: TestIsValidCachePath/empty (0.00s)1772 --- PASS: TestIsValidCachePath/random_path (0.00s)1773 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1774 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1775 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1776 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1777 --- PASS: TestIsValidCachePath/index.html (0.00s)1778 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1779 --- PASS: TestIsValidCachePath/realisation (0.00s)1780 --- PASS: TestIsValidCachePath/log (0.00s)1781 --- PASS: TestIsValidCachePath/ls (0.00s)1782 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1783 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1784 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1785 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1786 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1787=== CONT TestResolveDBConnectionString/flag_wins1788=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1789--- PASS: TestReadProxyInvalidPath (9.08s)1790=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed17912026/11/10 08:16:41 INFO Aborted multipart uploads count=0 kept=017922026/11/10 08:16:41 WARN Force mode enabled - objects will be deleted immediately without grace period17932026/11/10 08:16:41 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=017942026/11/10 08:16:41 INFO Vacuumed table table=pending_closures17952026/11/10 08:16:41 INFO Vacuumed table table=pending_objects17962026/11/10 08:16:41 INFO Vacuumed table table=multipart_uploads17972026/11/10 08:16:41 INFO Vacuumed table table=closures17982026/11/10 08:16:41 INFO Vacuumed table table=objects1799--- PASS: TestGCMetrics (9.02s)1800=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost18012026/11/10 08:16:41 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1802--- PASS: TestReadProxyNarinfo (9.24s)1803=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1804=== NAME TestOrphanedObjectsGCStressTest1805 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1806 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion18072026/11/10 08:16:42 INFO Received uploads request method=POST path=/api/pending_closures1808--- PASS: TestTombstonedObjectOfferedWithoutWaiting (9.68s)1809=== CONT TestResolveDBConnectionString/nothing_configured1810=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1811=== CONT TestResolveDBConnectionString/missing_file_is_an_error1812=== CONT TestResolveDBConnectionString/file_when_flag_empty1813=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18142026/11/10 08:16:42 INFO Received uploads request method=POST path=/1815--- PASS: TestResolveDBConnectionString (0.02s)1816 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1817 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1818 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1819 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1820 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)18212026/11/10 08:16:42 INFO Received uploads request method=POST path=/api/pending_closures1822=== CONT TestParseSingleRange/none1823=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18242026/11/10 08:16:42 INFO Received request for more parts method=POST path=/1825=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18262026/11/10 08:16:42 INFO Received complete multipart upload request method=POST path=/1827--- PASS: TestReadProxyOutlastsServerWriteTimeout (12.61s)1828--- PASS: TestUploadHandlersRejectOversizedBody (0.11s)1829 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.47s)1830 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.05s)1831 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.08s)1832=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info18332026/11/10 08:16:42 INFO Received uploads request method=POST path=/1834=== CONT TestParseSingleRange/start_far_past_EOF1835=== CONT TestParseSingleRange/single_byte1836=== CONT TestParseSingleRange/suffix_exceeds_size1837=== CONT TestParseSingleRange/suffix1838=== CONT TestParseSingleRange/end_clamped_to_size1839=== CONT TestParseSingleRange/open-ended1840=== CONT TestParseSingleRange/closed1841=== CONT TestParseSingleRange/malformed_end_before_start1842=== CONT TestParseSingleRange/malformed_both_empty1843=== CONT TestParseSingleRange/malformed_no_dash1844=== CONT TestParseSingleRange/multi-range_ignored1845=== CONT TestParseSingleRange/unknown_unit1846=== CONT TestParseSingleRange/start_past_EOF1847--- PASS: TestParseSingleRange (0.00s)1848 --- PASS: TestParseSingleRange/none (0.00s)1849 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1850 --- PASS: TestParseSingleRange/single_byte (0.00s)1851 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1852 --- PASS: TestParseSingleRange/suffix (0.00s)1853 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1854 --- PASS: TestParseSingleRange/open-ended (0.00s)1855 --- PASS: TestParseSingleRange/closed (0.00s)1856 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1857 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1858 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1859 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1860 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1861 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1862=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1863=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key18642026/11/10 08:16:42 INFO Received request for more parts method=POST path=/1865=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key18662026/11/10 08:16:43 INFO Received complete multipart upload request method=POST path=/1867=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal18682026/11/10 08:16:43 INFO Aborted multipart uploads count=0 kept=018692026/11/10 08:16:43 INFO Received uploads request method=POST path=/1870=== CONT TestIsValidUploadKey/narinfo1871=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1872--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1873 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1874 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1875 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1876 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)18772026/11/10 08:16:43 WARN Force mode enabled - objects will be deleted immediately without grace period18782026/11/10 08:16:43 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=018792026/11/10 08:16:43 INFO Vacuumed table table=pending_closures18802026/11/10 08:16:43 INFO Vacuumed table table=pending_objects18812026/11/10 08:16:43 INFO Vacuumed table table=multipart_uploads18822026/11/10 08:16:43 INFO Vacuumed table table=closures18832026/11/10 08:16:43 INFO Vacuumed table table=objects1884--- PASS: TestGCSweepSkipsPendingObjects (9.95s)1885=== CONT TestPendingClosureWriteTimeout/empty1886=== CONT TestIsValidUploadKey/unknown_type1887=== CONT TestIsValidUploadKey/empty_key1888=== CONT TestIsValidUploadKey/absolute1889=== CONT TestIsValidUploadKey/traversal_nar1890=== CONT TestIsValidUploadKey/traversal1891=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1892=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1893=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1894=== CONT TestIsValidUploadKey/index.html1895=== CONT TestIsValidUploadKey/nix-cache-info1896=== CONT TestIsValidUploadKey/realisation_plus_in_output1897=== CONT TestIsValidUploadKey/realisation1898=== CONT TestIsValidUploadKey/build_log_equals1899=== CONT TestIsValidUploadKey/build_log_question_mark1900=== CONT TestIsValidUploadKey/build_log_plus_in_name1901=== CONT TestIsValidUploadKey/build_log_home-manager_file1902=== CONT TestIsValidUploadKey/build_log1903=== CONT TestIsValidUploadKey/listing1904=== CONT TestIsValidUploadKey/nar_plain1905=== CONT TestIsValidUploadKey/nar_xz1906=== CONT TestIsValidUploadKey/nar_zst1907--- PASS: TestIsValidUploadKey (0.00s)1908 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1909 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1910 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1911 --- PASS: TestIsValidUploadKey/absolute (0.00s)1912 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1913 --- PASS: TestIsValidUploadKey/traversal (0.00s)1914 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1915 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1916 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1917 --- PASS: TestIsValidUploadKey/index.html (0.00s)1918 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1919 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1920 --- PASS: TestIsValidUploadKey/realisation (0.00s)1921 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1922 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1923 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1924 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1925 --- PASS: TestIsValidUploadKey/build_log (0.00s)1926 --- PASS: TestIsValidUploadKey/listing (0.00s)1927 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1928 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1929 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1930=== CONT TestProxyWriteTimeout/narinfo1931=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline19322026/11/10 08:16:43 INFO Received uploads request method=POST path=/api/pending_closures1933--- PASS: TestDeduplicatedObjectsRecordedAsPending (10.05s)1934=== CONT TestPendingClosureWriteTimeout/670k_objects1935=== CONT TestPendingClosureWriteTimeout/400_objects1936=== CONT TestProxyWriteTimeout/10_GiB_nar1937=== CONT TestProxyWriteTimeout/unknown_size1938=== CONT TestProxyWriteTimeout/1_GiB_nar1939--- PASS: TestProxyWriteTimeout (0.00s)1940 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1941 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1942 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1943 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1944=== CONT TestServerTLSConfig/no_client_CA1945=== CONT TestServerTLSConfig/not_a_PEM_file1946=== CONT TestServerTLSConfig/missing_CA_file1947--- PASS: TestServerTLSConfig (0.01s)1948 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1949 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1950 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1951=== CONT TestGCEndsOnShutdown/before_the_run19522026/11/10 08:16:43 INFO Received uploads request method=POST path=/api/pending_closures1953=== 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 TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark19822026/11/10 08:16:44 INFO Aborted multipart uploads count=0 kept=019832026/11/10 08:16:44 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=019842026/11/10 08:16:44 INFO Vacuumed table table=pending_closures19852026/11/10 08:16:44 INFO Vacuumed table table=pending_objects19862026/11/10 08:16:44 INFO Vacuumed table table=multipart_uploads19872026/11/10 08:16:44 INFO Vacuumed table table=closures19882026/11/10 08:16:44 INFO Vacuumed table table=objects19892026/11/10 08:16:44 INFO Aborted multipart uploads count=0 kept=019902026/11/10 08:16:44 WARN Force mode enabled - objects will be deleted immediately without grace period19912026/11/10 08:16:44 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=019922026/11/10 08:16:44 INFO Vacuumed table table=pending_closures19932026/11/10 08:16:44 INFO Vacuumed table table=pending_objects19942026/11/10 08:16:44 INFO Vacuumed table table=multipart_uploads19952026/11/10 08:16:44 INFO Vacuumed table table=closures1996--- PASS: TestService_ReadAuthMiddleware (9.77s)1997=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete19982026/11/10 08:16:44 INFO Vacuumed table table=objects1999--- PASS: TestPushDedupSurvivesConcurrentGC (10.55s)2000=== CONT TestPush_RejectsBadRequests/no_roots20012026/11/10 08:16:44 INFO Received push request method=POST path=/api/pushes2002=== CONT TestPush_RejectsBadRequests/bad_root20032026/11/10 08:16:44 INFO Received push request method=POST path=/api/pushes2004=== CONT TestPush_RejectsBadRequests/root_not_in_objects20052026/11/10 08:16:44 INFO Received push request method=POST path=/api/pushes2006=== CONT TestPush_RejectsBadRequests/no_objects20072026/11/10 08:16:44 INFO Received push request method=POST path=/api/pushes2008=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows2009--- PASS: TestPush_RejectsBadRequests (7.32s)2010 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2011 --- PASS: TestPush_RejectsBadRequests/bad_root (0.01s)2012 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2013 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2014=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2015=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2016=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2017=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2018=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2019=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2020=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2021=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2022=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check2023--- PASS: TestService_healthCheckHandler (10.01s)2024=== CONT TestClientErrorHandling/InvalidStorePath20252026/11/10 08:16:45 WARN readiness check failed error="closed pool"2026--- PASS: TestService_readinessHandler (10.50s)2027=== CONT TestClientErrorHandling/ServerNotAvailable20282026/11/10 08:16:46 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20292026/11/10 08:16:46 WARN mTLS auth: bound subjects configured but subject DN unavailable20302026/11/10 08:16:46 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2031--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (9.35s)2032=== CONT TestClientErrorHandling/InvalidAuthToken20332026/11/10 08:16:46 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/present20342026/11/10 08:16:46 WARN Request failed, retrying attempt=2 backoff=182.043721ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20352026/11/10 08:16:46 WARN Request failed, retrying attempt=3 backoff=367.92885ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2036--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (9.82s)2037=== CONT TestCacheConfigHandler/full_config,_no_issuer2038=== CONT TestCacheConfigHandler/no_signing_keys2039=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2040=== CONT TestCacheConfigHandler/no_cache_url_configured2041--- PASS: TestCacheConfigHandler (0.04s)2042 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2043 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2044 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2045 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2046=== CONT TestService_RequireScope_OIDC/builder_may_write2047=== CONT TestService_RequireScope_OIDC/reader_may_read2048=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2049=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20502026/11/10 08:16:46 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]2051=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2052=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2053=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2054=== CONT TestService_RequireScope_OIDC/writer_implies_read2055=== CONT TestService_RequireScope_OIDC/reader_may_not_write2056=== CONT TestService_RequireScope_OIDC/static_token_may_write2057=== CONT TestService_RequireScope_OIDC/static_token_may_admin2058=== CONT TestService_RequireScope_OIDC/ops_may_admin2059=== CONT TestService_RequireScope_OIDC/ops_may_not_write2060=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2061=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2062--- PASS: TestService_RequireScope_OIDC (9.35s)2063 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2064 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2065 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2066 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2067 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2068 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2069 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2070 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2071 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2072 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2073 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2074 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2075 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2076 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2077=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20782026/11/10 08:16:46 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]2079=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2080=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20812026/11/10 08:16:46 WARN Authentication failed token_preview=eyJhbGciOi...437mlKGZtQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2082--- PASS: TestService_AuthMiddleware_OIDC (10.04s)2083 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)2084 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2085 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2086 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)20872026/11/10 08:16:47 WARN Request failed, retrying attempt=4 backoff=742.199117ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20882026/11/10 08:16:47 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"2089--- PASS: TestService_AuthMiddleware (9.61s)20902026/11/10 08:16:47 WARN Request failed, retrying attempt=5 backoff=1.737321178s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20912026/11/10 08:16:47 INFO lead: acquired remote=192.0.2.1:123420922026/11/10 08:16:47 INFO lead: released remote=192.0.2.1:12342093--- PASS: TestLeadIncumbentAnnouncesAtOnce (9.73s)20942026/11/10 08:16:48 INFO lead: acquired remote=192.0.2.1:12342095--- PASS: TestGCBugBareHashReferences (10.50s)20962026/11/10 08:16:48 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld5 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"2097--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (9.74s)20982026/11/10 08:16:49 INFO lead: released remote=192.0.2.1:12342099--- PASS: TestLeadEndsOnShutdown (11.19s)21002026/11/10 08:16:49 INFO Received uploads request method=POST path=/api/pending_closures21012026/11/10 08:16:49 INFO lead: acquired remote=192.0.2.1:123421022026/11/10 08:16:49 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-config21032026/11/10 08:16:49 WARN Request failed, retrying attempt=2 backoff=186.279397ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21042026/11/10 08:16:49 INFO Received uploads request method=POST path=/api/pending_closures21052026/11/10 08:16:49 WARN Request failed, retrying attempt=3 backoff=424.859577ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21062026/11/10 08:16:50 INFO Received uploads request method=POST path=/api/pending_closures21072026/11/10 08:16:50 WARN Request failed, retrying attempt=4 backoff=731.40642ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21082026/11/10 08:16:50 INFO Received uploads request method=POST path=/api/pending_closures21092026/11/10 08:16:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21102026/11/10 08:16:50 INFO lead: released remote=192.0.2.1:123421112026/11/10 08:16:50 INFO lead: acquired remote=192.0.2.1:123421122026/11/10 08:16:50 INFO Received uploads request method=POST path=/api/pending_closures21132026/11/10 08:16:50 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=YjAwMDE3NzYtNjJmMS00MDc1LWFjYmEtZDBhZmM2MDBkYjNiLjYwNjc2NzkyLTA3MWUtNDFjZC04OGI1LTY0ZjgwMzhlYWIyNngxNzk0Mjk4NjA5MzU2NDkxMDAw parts=1021142026/11/10 08:16:51 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21152026/11/10 08:16:51 INFO Completed upload id=1 objects=3 duration=17.994583ms21162026/11/10 08:16:51 WARN Request failed, retrying attempt=5 backoff=1.537246489s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21172026/11/10 08:16:51 INFO Received uploads request method=POST path=/api/pending_closures21182026/11/10 08:16:51 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst21192026/11/10 08:16:51 WARN Found objects in DB but missing from S3, will re-upload count=121202026/11/10 08:16:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21212026/11/10 08:16:51 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=YjAwMDE3NzYtNjJmMS00MDc1LWFjYmEtZDBhZmM2MDBkYjNiLmYxMDI3OTNkLWRlOTMtNDFhNy1hYjI0LTQyMjRmMWU4MWFhOHgxNzk0Mjk4NjA5OTE2NDgxMDAw parts=1021222026/11/10 08:16:51 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21232026/11/10 08:16:51 INFO Completed upload id=1 objects=3 duration=6.128792ms21242026/11/10 08:16:51 INFO lead: released remote=192.0.2.1:12342125--- PASS: TestLeadElectsOneAndHandsOver (12.25s)21262026/11/10 08:16:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21272026/11/10 08:16:52 INFO Received uploads request method=POST path=/api/pending_closures21282026/11/10 08:16:52 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=YjAwMDE3NzYtNjJmMS00MDc1LWFjYmEtZDBhZmM2MDBkYjNiLmEyMDJjZDQzLWY4YTEtNDY4OS1hMzQ5LTljODkxNjNjODNmZHgxNzk0Mjk4NjEwMjM4NTkzMDAw parts=102129--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2130 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (8.86s)2131 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (9.21s)21322026/11/10 08:16:52 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21332026/11/10 08:16:52 INFO Completed upload id=1 objects=3 duration=11.68ms21342026/11/10 08:16:52 INFO Received uploads request method=POST path=/api/pending_closures21352026/11/10 08:16:52 INFO Received uploads request method=POST path=/api/pending_closures21362026/11/10 08:16:52 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21372026/11/10 08:16:52 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21382026/11/10 08:16:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21392026/11/10 08:16:52 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=YjAwMDE3NzYtNjJmMS00MDc1LWFjYmEtZDBhZmM2MDBkYjNiLjIzMDlkNWI0LTUyZTQtNGVjMS05YzJiLTJlMDk2M2RiMzBlMHgxNzk0Mjk4NjEwNTY3MjE3MDAw parts=1021402026/11/10 08:16:52 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"21412026/11/10 08:16:52 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-config21422026/11/10 08:16:52 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21432026/11/10 08:16:52 INFO Completed upload id=1 objects=3 duration=16.540291ms21442026/11/10 08:16:52 INFO Received uploads request method=POST path=/api/pending_closures21452026/11/10 08:16:52 WARN Request failed, retrying attempt=2 backoff=181.029129ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21462026/11/10 08:16:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2147--- PASS: TestPendingClosureWriteTimeout (0.00s)2148 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2149 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2150 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2151 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (9.65s)21522026/11/10 08:16:52 INFO Aborted multipart uploads count=0 kept=021532026/11/10 08:16:52 WARN Force mode enabled - objects will be deleted immediately without grace period21542026/11/10 08:16:52 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:60127/bucket101/?delete=\": context canceled"21552026/11/10 08:16:52 WARN Request failed, retrying attempt=3 backoff=418.211892ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21562026/11/10 08:16:52 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=YjAwMDE3NzYtNjJmMS00MDc1LWFjYmEtZDBhZmM2MDBkYjNiLjc1NmExYTgzLTE0NmItNDlkOS1iNWM1LTNkNGZmNmU5ZGE3OHgxNzk0Mjk4NjEwOTI5NjU5MDAw parts=1021572026/11/10 08:16:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21582026/11/10 08:16:53 INFO Completed upload id=1 objects=3 duration=12.623417ms21592026/11/10 08:16:53 INFO Received uploads request method=POST path=/api/pending_closures21602026/11/10 08:16:53 INFO Received uploads request method=POST path=/api/pending_closures21612026/11/10 08:16:53 INFO Aborted multipart uploads count=0 kept=021622026/11/10 08:16:53 WARN Force mode enabled - objects will be deleted immediately without grace period21632026/11/10 08:16:53 WARN Request failed, retrying attempt=4 backoff=774.477418ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21642026/11/10 08:16:53 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=021652026/11/10 08:16:53 INFO Vacuumed table table=pending_closures21662026/11/10 08:16:53 INFO Vacuumed table table=pending_objects21672026/11/10 08:16:53 INFO Vacuumed table table=multipart_uploads21682026/11/10 08:16:53 INFO Vacuumed table table=closures21692026/11/10 08:16:53 INFO Vacuumed table table=objects21702026/11/10 08:16:53 INFO Aborted multipart uploads count=0 kept=021712026/11/10 08:16:53 WARN Force mode enabled - objects will be deleted immediately without grace period21722026-11-10 08:16:53.568 UTC [94027] ERROR: canceling statement due to user request21732026-11-10 08:16:53.568 UTC [94027] STATEMENT: -- name: MarkStaleObjects :execrows2174 WITH RECURSIVE ct AS (2175 SELECT timezone('UTC', now()) AS now2176 ),2177 closure_reach AS (2178 -- Start with all closure keys2179 SELECT o.key, o.refs2180 FROM objects o2181 INNER JOIN closures c ON o.key = c.key2182 UNION2183 -- Recursively add all referenced objects2184 SELECT o.key, o.refs2185 FROM objects o2186 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2187 ),2188 reachable_objects AS (2189 SELECT DISTINCT key FROM closure_reach2190 ),2191 stale_objects AS (2192 SELECT o.key2193 FROM objects AS o, ct2194 WHERE2195 NOT EXISTS (2196 SELECT 12197 FROM reachable_objects ro2198 WHERE ro.key = o.key2199 )2200 AND NOT EXISTS (2201 SELECT 12202 FROM pending_objects AS po2203 WHERE po.key = o.key2204 )2205 AND o.deleted_at IS NULL -- Only mark fresh objects2206 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2207 FOR UPDATE2208 )2209 UPDATE objects2210 SET2211 deleted_at = ct.now,2212 first_deleted_at = COALESCE(first_deleted_at, ct.now)2213 FROM stale_objects, ct2214 WHERE objects.key = stale_objects.key2215 2216--- PASS: TestGCEndsOnShutdown (0.01s)2217 --- PASS: TestGCEndsOnShutdown/before_the_run (9.18s)2218 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (8.37s)2219 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (9.40s)22202026/11/10 08:16:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22212026/11/10 08:16:53 INFO Received uploads request method=POST path=/api/pending_closures22222026/11/10 08:16:53 INFO Aborted multipart uploads count=0 kept=022232026/11/10 08:16:53 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=YjAwMDE3NzYtNjJmMS00MDc1LWFjYmEtZDBhZmM2MDBkYjNiLjY0MDg5MWMzLWM4ZmMtNGI1MS1hMjRmLTM4ZjI0MTZiZWU1Y3gxNzk0Mjk4NjEyMjc4OTg5MDAw parts=1022242026/11/10 08:16:53 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22252026/11/10 08:16:53 WARN Force mode enabled - objects will be deleted immediately without grace period22262026/11/10 08:16:53 INFO Completed upload id=2 objects=3 duration=1.087ms22272026/11/10 08:16:53 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=022282026/11/10 08:16:53 INFO Vacuumed table table=pending_closures22292026/11/10 08:16:53 INFO Vacuumed table table=pending_objects22302026/11/10 08:16:54 INFO Vacuumed table table=multipart_uploads22312026/11/10 08:16:54 INFO Vacuumed table table=closures22322026/11/10 08:16:54 INFO Vacuumed table table=objects2233--- PASS: TestForceGCDuringPushOffersSweptObject (0.01s)2234 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (9.06s)2235 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (9.09s)22362026/11/10 08:16:54 WARN Request failed, retrying attempt=5 backoff=1.48658738s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22372026/11/10 08:16:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22382026/11/10 08:16:54 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=YjAwMDE3NzYtNjJmMS00MDc1LWFjYmEtZDBhZmM2MDBkYjNiLjIwOWRhOTgzLWM5NTktNGQ5ZC1hMTViLTE0MzRmZDliY2M3ZHgxNzk0Mjk4NjEyNzA5NjQzMDAw parts=1022392026/11/10 08:16:54 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22402026/11/10 08:16:54 INFO Completed upload id=2 objects=3 duration=313.708µs22412026/11/10 08:16:54 INFO Received uploads request method=POST path=/api/pending_closures22422026/11/10 08:16:54 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22432026/11/10 08:16:54 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo22442026/11/10 08:16:54 INFO Received uploads request method=POST path=/api/pending_closures22452026/11/10 08:16:54 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22462026/11/10 08:16:54 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2247--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.01s)2248 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (11.45s)2249 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (12.28s)2250 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (11.25s)2251 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (13.74s)2252 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (13.26s)22532026/11/10 08:16:54 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22542026/11/10 08:16:54 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22552026/11/10 08:16:55 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_closures22562026/11/10 08:16:55 WARN Request failed, retrying attempt=2 backoff=189.881082ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22572026/11/10 08:16:55 WARN Request failed, retrying attempt=3 backoff=408.592286ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22582026/11/10 08:16:56 WARN Request failed, retrying attempt=4 backoff=854.909169ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22592026/11/10 08:16:57 WARN Request failed, retrying attempt=5 backoff=1.482652474s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2260--- PASS: TestClientErrorHandling (0.03s)2261 --- PASS: TestClientErrorHandling/InvalidStorePath (8.82s)2262 --- PASS: TestClientErrorHandling/InvalidAuthToken (8.37s)2263 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.17s)2264=== NAME TestOrphanedObjectsGCStressTest2265 orphaned_objects_gc_test.go:503: Stress test completed successfully:2266 orphaned_objects_gc_test.go:504: - Active objects preserved: 202267 orphaned_objects_gc_test.go:505: - Objects deleted: 2102268 orphaned_objects_gc_test.go:506: - Total GC'd: 2102269--- PASS: TestOrphanedObjectsGCStressTest (43.96s)2270PASS2271{"timestamp":"2026-11-10T08:17:02.122491Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:60499","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}2272{"timestamp":"2026-11-10T08:17:02.122582Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:60337","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}2273{"timestamp":"2026-11-10T08:17:02.122665Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:60638","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}2274{"timestamp":"2026-11-10T08:17:02.1229Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:60664","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}2275{"timestamp":"2026-11-10T08:17:02.122801Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:60680","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}22762026-11-10 08:17:02.353 UTC [90555] LOG: received smart shutdown request22772026-11-10 08:17:02.354 UTC [90555] LOG: background worker "logical replication launcher" (PID 90570) exited with exit code 122782026-11-10 08:17:02.384 UTC [90560] LOG: shutting down22792026-11-10 08:17:02.385 UTC [90560] LOG: checkpoint starting: shutdown immediate22802026-11-10 08:17:04.216 UTC [90560] LOG: checkpoint complete: wrote 12051 buffers (73.6%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=1.030 s, sync=0.737 s, total=1.832 s; sync files=36061, longest=0.001 s, average=0.001 s; distance=529844 kB, estimate=529844 kB; lsn=0/21CFA310, redo lsn=0/21CFA31022812026-11-10 08:17:04.223 UTC [90555] LOG: database system is shut down2282Running OIDC tests...2283=== RUN TestAudienceForIssuer2284=== PAUSE TestAudienceForIssuer2285=== RUN TestGlobMatch2286=== PAUSE TestGlobMatch2287=== RUN TestValidateToken_ValidToken2288=== PAUSE TestValidateToken_ValidToken2289=== RUN TestValidateToken_WrongAudience2290=== PAUSE TestValidateToken_WrongAudience2291=== RUN TestValidateToken_Expired2292=== PAUSE TestValidateToken_Expired2293=== RUN TestValidateToken_BoundClaimsMismatch2294=== PAUSE TestValidateToken_BoundClaimsMismatch2295=== RUN TestValidateToken_BoundSubjectMismatch2296=== PAUSE TestValidateToken_BoundSubjectMismatch2297=== RUN TestValidateToken_MultipleProviders2298=== PAUSE TestValidateToken_MultipleProviders2299=== RUN TestValidateToken_NoMatchingProvider2300=== PAUSE TestValidateToken_NoMatchingProvider2301=== RUN TestValidateToken_KubernetesServiceAccount2302=== PAUSE TestValidateToken_KubernetesServiceAccount2303=== RUN TestNewValidator_KubernetesRequiresCA2304=== PAUSE TestNewValidator_KubernetesRequiresCA2305=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2306=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2307=== RUN TestPins_ReservedForMatchingRule2308=== PAUSE TestPins_ReservedForMatchingRule2309=== RUN TestPins_TopLevelShorthand2310=== PAUSE TestPins_TopLevelShorthand2311=== RUN TestPins_ConfigValidation2312=== PAUSE TestPins_ConfigValidation2313=== RUN TestScopes_LegacyProviderDefaultsToWrite2314=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2315=== RUN TestScopes_Rules2316=== PAUSE TestScopes_Rules2317=== RUN TestScopes_ConfigValidation2318=== PAUSE TestScopes_ConfigValidation2319=== CONT TestAudienceForIssuer2320--- PASS: TestAudienceForIssuer (0.00s)2321=== CONT TestValidateToken_NoMatchingProvider2322=== CONT TestScopes_LegacyProviderDefaultsToWrite2323=== CONT TestValidateToken_KubernetesServiceAccount2324=== CONT TestPins_ReservedForMatchingRule2325=== CONT TestPins_TopLevelShorthand2326=== CONT TestValidateToken_Expired2327=== CONT TestValidateToken_BoundSubjectMismatch2328=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2329=== CONT TestValidateToken_MultipleProviders2330=== CONT TestValidateToken_BoundClaimsMismatch2331=== CONT TestValidateToken_ValidToken2332=== CONT TestNewValidator_KubernetesRequiresCA2333=== CONT TestGlobMatch2334=== RUN TestGlobMatch/foo_foo2335=== PAUSE TestGlobMatch/foo_foo2336=== RUN TestGlobMatch/foo_bar2337=== PAUSE TestGlobMatch/foo_bar2338=== RUN TestGlobMatch/*_2339=== PAUSE TestGlobMatch/*_2340=== RUN TestGlobMatch/*_anything2341=== PAUSE TestGlobMatch/*_anything2342=== RUN TestGlobMatch/foo*_foo2343=== PAUSE TestGlobMatch/foo*_foo2344=== RUN TestGlobMatch/foo*_foobar2345=== PAUSE TestGlobMatch/foo*_foobar2346=== RUN TestGlobMatch/foo*_bar2347=== PAUSE TestGlobMatch/foo*_bar2348=== RUN TestGlobMatch/*bar_bar2349=== PAUSE TestGlobMatch/*bar_bar2350=== RUN TestGlobMatch/*bar_foobar2351=== PAUSE TestGlobMatch/*bar_foobar2352=== RUN TestGlobMatch/*bar_foo2353=== PAUSE TestGlobMatch/*bar_foo2354=== RUN TestGlobMatch/foo*bar_foobar2355=== PAUSE TestGlobMatch/foo*bar_foobar2356=== RUN TestGlobMatch/foo*bar_foo123bar2357=== PAUSE TestGlobMatch/foo*bar_foo123bar2358=== RUN TestGlobMatch/foo*bar_foobarbaz2359=== PAUSE TestGlobMatch/foo*bar_foobarbaz2360=== RUN TestGlobMatch/*/*_foo/bar2361=== PAUSE TestGlobMatch/*/*_foo/bar2362=== RUN TestGlobMatch/*/*_foo2363=== PAUSE TestGlobMatch/*/*_foo2364=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2365=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2366=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02367=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02368=== RUN TestGlobMatch/refs/*/main_refs/heads/main2369=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2370=== RUN TestGlobMatch/fo?_foo2371=== PAUSE TestGlobMatch/fo?_foo2372=== RUN TestGlobMatch/fo?_fo2373=== PAUSE TestGlobMatch/fo?_fo2374=== RUN TestGlobMatch/fo?_fooo2375=== PAUSE TestGlobMatch/fo?_fooo2376=== RUN TestGlobMatch/?oo_foo2377=== PAUSE TestGlobMatch/?oo_foo2378=== RUN TestGlobMatch/?oo_boo2379=== PAUSE TestGlobMatch/?oo_boo2380=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2381=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2382=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2383=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2384=== CONT TestGlobMatch/foo_foo2385=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2386=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2387=== CONT TestGlobMatch/?oo_boo2388=== CONT TestGlobMatch/?oo_foo2389=== CONT TestGlobMatch/fo?_fooo2390=== CONT TestGlobMatch/fo?_fo2391=== CONT TestGlobMatch/fo?_foo2392=== CONT TestGlobMatch/refs/*/main_refs/heads/main2393=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02394=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2395=== CONT TestGlobMatch/*/*_foo2396=== CONT TestGlobMatch/*/*_foo/bar2397=== CONT TestGlobMatch/foo*bar_foobarbaz2398=== CONT TestGlobMatch/foo*bar_foo123bar2399=== CONT TestGlobMatch/foo*bar_foobar2400=== CONT TestGlobMatch/*bar_foo2401=== CONT TestGlobMatch/*bar_foobar2402=== CONT TestGlobMatch/*bar_bar2403=== CONT TestGlobMatch/foo*_bar2404=== CONT TestGlobMatch/foo*_foobar2405=== CONT TestGlobMatch/foo*_foo2406=== CONT TestGlobMatch/*_anything2407=== CONT TestGlobMatch/*_2408=== CONT TestGlobMatch/foo_bar2409--- PASS: TestGlobMatch (0.00s)2410 --- PASS: TestGlobMatch/foo_foo (0.00s)2411 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2412 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2413 --- PASS: TestGlobMatch/?oo_boo (0.00s)2414 --- PASS: TestGlobMatch/?oo_foo (0.00s)2415 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2416 --- PASS: TestGlobMatch/fo?_fo (0.00s)2417 --- PASS: TestGlobMatch/fo?_foo (0.00s)2418 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2419 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2420 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2421 --- PASS: TestGlobMatch/*/*_foo (0.00s)2422 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2423 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2424 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2425 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2426 --- PASS: TestGlobMatch/*bar_foo (0.00s)2427 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2428 --- PASS: TestGlobMatch/*bar_bar (0.00s)2429 --- PASS: TestGlobMatch/foo*_bar (0.00s)2430 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2431 --- PASS: TestGlobMatch/foo*_foo (0.00s)2432 --- PASS: TestGlobMatch/*_anything (0.00s)2433 --- PASS: TestGlobMatch/*_ (0.00s)2434 --- PASS: TestGlobMatch/foo_bar (0.00s)2435=== CONT TestValidateToken_WrongAudience2436=== CONT TestPins_ConfigValidation2437=== CONT TestScopes_ConfigValidation2438--- PASS: TestPins_ConfigValidation (0.00s)2439=== CONT TestScopes_Rules2440--- PASS: TestScopes_ConfigValidation (0.00s)24412026/11/10 08:17:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60700/oidc24422026/11/10 08:17:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60702/oidc2443--- PASS: TestValidateToken_Expired (0.07s)2444--- PASS: TestValidateToken_BoundClaimsMismatch (0.07s)24452026/11/10 08:17:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60704/oidc2446--- PASS: TestPins_ReservedForMatchingRule (0.09s)24472026/11/10 08:17:05 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:6070724482026/11/10 08:17:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60709/oidc2449--- PASS: TestPins_TopLevelShorthand (0.10s)2450--- PASS: TestValidateToken_KubernetesServiceAccount (0.10s)24512026/11/10 08:17:05 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232452--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.11s)24532026/11/10 08:17:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60714/oidc24542026/11/10 08:17:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60716/oidc2455--- PASS: TestValidateToken_WrongAudience (0.11s)2456--- PASS: TestScopes_Rules (0.11s)24572026/11/10 08:17:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60720/oidc2458--- PASS: TestValidateToken_BoundSubjectMismatch (0.13s)24592026/11/10 08:17:05 http: TLS handshake error from 127.0.0.1:60719: remote error: tls: bad certificate2460--- PASS: TestNewValidator_KubernetesRequiresCA (0.13s)24612026/11/10 08:17:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60722/oidc2462--- PASS: TestValidateToken_ValidToken (0.13s)24632026/11/10 08:17:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60724/oidc2464--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.15s)24652026/11/10 08:17:05 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:60706/oidc2466--- PASS: TestValidateToken_NoMatchingProvider (0.16s)24672026/11/10 08:17:06 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:60728/oidc24682026/11/10 08:17:06 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:60713/oidc2469--- PASS: TestValidateToken_MultipleProviders (0.17s)2470PASS2471Running hook tests...2472=== RUN TestSendPathsEmpty2473=== PAUSE TestSendPathsEmpty2474=== RUN TestQueueEnqueueAndFetch2475=== PAUSE TestQueueEnqueueAndFetch2476=== RUN TestQueueDeduplication2477=== PAUSE TestQueueDeduplication2478=== RUN TestQueueRemove2479=== PAUSE TestQueueRemove2480=== RUN TestQueueFetchBatchLimit2481=== PAUSE TestQueueFetchBatchLimit2482=== RUN TestQueueRetryMovesToBack2483=== PAUSE TestQueueRetryMovesToBack2484=== RUN TestQueueFetchRemoveLifecycle2485=== PAUSE TestQueueFetchRemoveLifecycle2486=== RUN TestQueueConcurrentWriters2487=== PAUSE TestQueueConcurrentWriters2488=== RUN TestQueueRemoveLargeClosure2489=== PAUSE TestQueueRemoveLargeClosure2490=== RUN TestServerClientIntegration2491--- PASS: TestServerClientIntegration (0.00s)2492=== RUN TestServerQueueError24932026/11/10 08:17:06 ERROR Failed to queue paths error="permission denied" count=12494--- PASS: TestServerQueueError (0.00s)2495=== RUN TestGetListenerSocketActivation2496 server_test.go:145: systemd socket activation does not exist on darwin2497--- SKIP: TestGetListenerSocketActivation (0.00s)2498=== RUN TestServerStalledClientDoesNotBlockShutdown2499=== PAUSE TestServerStalledClientDoesNotBlockShutdown2500=== RUN TestServerBacksOffOnAcceptErrors2501=== PAUSE TestServerBacksOffOnAcceptErrors2502=== RUN TestDrainIsolatesPoisonPath2503=== PAUSE TestDrainIsolatesPoisonPath2504=== RUN TestRunNotBlockedByPoisonHead2505=== PAUSE TestRunNotBlockedByPoisonHead2506=== RUN TestDrainGivesUpWhenServerDown2507=== PAUSE TestDrainGivesUpWhenServerDown2508=== RUN TestFailedPathPrunedByLaterClosure2509=== PAUSE TestFailedPathPrunedByLaterClosure2510=== RUN TestWorkerUploadsAndRemoves2511=== PAUSE TestWorkerUploadsAndRemoves2512=== RUN TestWorkerSkipsGCdPaths2513=== PAUSE TestWorkerSkipsGCdPaths2514=== RUN TestWorkerPrunesClosureDeps2515=== PAUSE TestWorkerPrunesClosureDeps2516=== RUN TestDrainTimeout2517=== PAUSE TestDrainTimeout2518=== RUN TestWorkerRemoveFailureIsNotProgress2519=== PAUSE TestWorkerRemoveFailureIsNotProgress2520=== RUN TestWorkerKeepsPathItCannotStat2521=== PAUSE TestWorkerKeepsPathItCannotStat2522=== CONT TestSendPathsEmpty2523=== CONT TestWorkerKeepsPathItCannotStat2524=== CONT TestWorkerSkipsGCdPaths2525=== CONT TestWorkerRemoveFailureIsNotProgress2526=== CONT TestDrainTimeout2527=== CONT TestWorkerPrunesClosureDeps2528=== CONT TestQueueFetchRemoveLifecycle2529=== CONT TestServerBacksOffOnAcceptErrors2530=== CONT TestServerStalledClientDoesNotBlockShutdown25312026/11/10 08:17:06 ERROR Accept failed error="too many open files"2532=== CONT TestQueueRemoveLargeClosure2533--- PASS: TestSendPathsEmpty (0.00s)2534=== CONT TestDrainIsolatesPoisonPath2535=== CONT TestQueueConcurrentWriters2536=== CONT TestQueueRetryMovesToBack2537=== CONT TestFailedPathPrunedByLaterClosure2538=== CONT TestQueueFetchBatchLimit2539=== CONT TestWorkerUploadsAndRemoves2540=== CONT TestQueueRemove2541=== CONT TestDrainGivesUpWhenServerDown2542=== CONT TestQueueDeduplication2543=== CONT TestQueueEnqueueAndFetch2544=== CONT TestRunNotBlockedByPoisonHead25452026/11/10 08:17:06 ERROR Accept failed error="too many open files"25462026/11/10 08:17:06 WARN Cannot stat store path, will retry later path=/private/var/tb/5/scratch/e759ffdaa87b1701/build/TestWorkerKeepsPathItCannotStat2010419615/002/locked/aaa error="stat /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestWorkerKeepsPathItCannotStat2010419615/002/locked/aaa: permission denied"25472026/11/10 08:17:06 WARN Cannot stat store path, will retry later path=/private/var/tb/5/scratch/e759ffdaa87b1701/build/TestWorkerKeepsPathItCannotStat2010419615/002/locked/aaa error="stat /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestWorkerKeepsPathItCannotStat2010419615/002/locked/aaa: permission denied"2548--- PASS: TestQueueRetryMovesToBack (0.01s)25492026/11/10 08:17:06 INFO Upload queue status pending=225502026/11/10 08:17:06 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/e759ffdaa87b1701/build/TestWorkerSkipsGCdPaths181950098/002/nonexistent25512026/11/10 08:17:06 INFO Uploading batch count=12552--- PASS: TestQueueEnqueueAndFetch (0.01s)2553--- PASS: TestQueueFetchBatchLimit (0.01s)25542026/11/10 08:17:06 INFO Uploading batch count=425552026/11/10 08:17:06 ERROR Upload failed error="upload failed" count=425562026/11/10 08:17:06 INFO Upload queue status pending=225572026/11/10 08:17:06 INFO Upload queue status pending=225582026/11/10 08:17:06 INFO Uploading batch count=125592026/11/10 08:17:06 INFO Uploading batch count=125602026/11/10 08:17:06 ERROR Upload failed error="upload failed" count=125612026/11/10 08:17:06 INFO Uploading batch count=225622026/11/10 08:17:06 INFO Uploading batch count=225632026/11/10 08:17:06 ERROR Upload failed error="upload failed" count=225642026/11/10 08:17:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/e759ffdaa87b1701/build/TestDrainGivesUpWhenServerDown1955714537/002/a25652026/11/10 08:17:06 INFO Uploading batch count=225662026/11/10 08:17:06 WARN Cannot stat store path, will retry later path=/private/var/tb/5/scratch/e759ffdaa87b1701/build/TestWorkerKeepsPathItCannotStat2010419615/002/locked/aaa error="stat /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestWorkerKeepsPathItCannotStat2010419615/002/locked/aaa: permission denied"25672026/11/10 08:17:06 INFO Upload queue status pending=325682026/11/10 08:17:06 INFO Uploading batch count=125692026/11/10 08:17:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/e759ffdaa87b1701/build/TestDrainIsolatesPoisonPath676505399/002/bbb25702026/11/10 08:17:06 INFO Uploading batch count=125712026/11/10 08:17:06 ERROR Upload failed error="upload failed" count=12572--- PASS: TestQueueFetchRemoveLifecycle (0.01s)25732026/11/10 08:17:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/e759ffdaa87b1701/build/TestDrainGivesUpWhenServerDown1955714537/002/b25742026/11/10 08:17:06 ERROR Drain finished with paths left in queue remaining=125752026/11/10 08:17:06 INFO Uploading batch count=125762026/11/10 08:17:06 INFO Uploading batch count=125772026/11/10 08:17:06 ERROR Upload failed error="upload failed" count=125782026/11/10 08:17:06 ERROR Accept failed error="too many open files"2579--- PASS: TestQueueRemove (0.01s)2580--- PASS: TestQueueDeduplication (0.01s)25812026/11/10 08:17:06 INFO Uploading batch count=225822026/11/10 08:17:06 ERROR Upload failed error="upload failed" count=225832026/11/10 08:17:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/e759ffdaa87b1701/build/TestDrainGivesUpWhenServerDown1955714537/002/c25842026/11/10 08:17:06 INFO Uploading batch count=125852026/11/10 08:17:06 ERROR Upload failed error="upload failed" count=125862026/11/10 08:17:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/e759ffdaa87b1701/build/TestDrainGivesUpWhenServerDown1955714537/002/d25872026/11/10 08:17:06 INFO Uploading batch count=125882026/11/10 08:17:06 ERROR Upload failed error="upload failed" count=125892026/11/10 08:17:06 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/e759ffdaa87b1701/build/TestWorkerRemoveFailureIsNotProgress3352253791/002/nonexistent25902026/11/10 08:17:06 INFO Uploading batch count=225912026/11/10 08:17:06 ERROR Upload failed error="upload failed" count=225922026/11/10 08:17:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/e759ffdaa87b1701/build/TestDrainGivesUpWhenServerDown1955714537/002/e25932026/11/10 08:17:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12594--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)25952026/11/10 08:17:06 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/e759ffdaa87b1701/build/TestWorkerRemoveFailureIsNotProgress3352253791/002/nonexistent25962026/11/10 08:17:06 ERROR Drain finished with paths left in queue remaining=125972026/11/10 08:17:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125982026/11/10 08:17:06 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/e759ffdaa87b1701/build/TestWorkerRemoveFailureIsNotProgress3352253791/002/nonexistent25992026/11/10 08:17:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126002026/11/10 08:17:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/e759ffdaa87b1701/build/TestDrainGivesUpWhenServerDown1955714537/002/f26012026/11/10 08:17:06 ERROR Drain finished with paths left in queue remaining=126022026/11/10 08:17:06 ERROR Drain finished with paths left in queue remaining=102603--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2604--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)2605--- PASS: TestDrainIsolatesPoisonPath (0.02s)2606--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2607--- PASS: TestWorkerSkipsGCdPaths (0.03s)2608--- PASS: TestWorkerUploadsAndRemoves (0.03s)2609--- PASS: TestWorkerPrunesClosureDeps (0.03s)26102026/11/10 08:17:06 ERROR Accept failed error="too many open files"2611--- PASS: TestQueueRemoveLargeClosure (0.05s)2612--- PASS: TestQueueConcurrentWriters (0.06s)26132026/11/10 08:17:06 ERROR Accept failed error="too many open files"26142026/11/10 08:17:06 ERROR Accept failed error="too many open files"26152026/11/10 08:17:06 ERROR Failed to decode request error="read unix /private/var/tb/5/scratch/e759ffdaa87b1701/build/hook3234283115/test.sock->: i/o timeout"26162026/11/10 08:17:06 ERROR Failed to write response error="write unix /private/var/tb/5/scratch/e759ffdaa87b1701/build/hook3234283115/test.sock->: i/o timeout"2617--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26182026/11/10 08:17:06 ERROR Upload failed error="context deadline exceeded" count=226192026/11/10 08:17:06 ERROR Drain finished with paths left in queue remaining=42620--- PASS: TestDrainTimeout (0.22s)26212026/11/10 08:17:06 ERROR Accept failed error="too many open files"26222026/11/10 08:17:07 ERROR Accept failed error="too many open files"2623--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26242026/11/10 08:17:07 INFO Uploading batch count=126252026/11/10 08:17:07 INFO Uploading batch count=126262026/11/10 08:17:07 INFO Uploading batch count=126272026/11/10 08:17:07 ERROR Upload failed error="upload failed" count=126282026/11/10 08:17:07 INFO Uploading batch count=126292026/11/10 08:17:07 ERROR Upload failed error="upload failed" count=126302026/11/10 08:17:07 INFO Uploading batch count=126312026/11/10 08:17:07 ERROR Upload failed error="upload failed" count=126322026/11/10 08:17:07 INFO Uploading batch count=126332026/11/10 08:17:07 ERROR Upload failed error="upload failed" count=126342026/11/10 08:17:07 ERROR Drain finished with paths left in queue remaining=12635--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2636PASS2637Running signing tests...2638=== RUN TestExternalSigner2639=== PAUSE TestExternalSigner2640=== RUN TestExternalSignerWrongPublicKey2641=== PAUSE TestExternalSignerWrongPublicKey2642=== RUN TestExternalSignerErrors2643=== PAUSE TestExternalSignerErrors2644=== RUN TestExternalSignerRestartsAfterCrash2645=== PAUSE TestExternalSignerRestartsAfterCrash2646=== RUN TestExternalSignerProgramErrorKeepsProcess2647=== PAUSE TestExternalSignerProgramErrorKeepsProcess2648=== RUN TestExternalSignerClose2649=== PAUSE TestExternalSignerClose2650=== RUN TestExternalSignerRejectsInvalidPublicKey2651=== PAUSE TestExternalSignerRejectsInvalidPublicKey2652=== RUN TestExternalSignerCancellation2653=== PAUSE TestExternalSignerCancellation2654=== RUN TestGenerateFingerprint2655=== PAUSE TestGenerateFingerprint2656=== RUN TestParseSigningKey2657=== PAUSE TestParseSigningKey2658=== RUN TestSign2659=== PAUSE TestSign2660=== RUN TestSignBatch2661=== PAUSE TestSignBatch2662=== RUN TestNilKeyPublicKey2663=== PAUSE TestNilKeyPublicKey2664=== RUN TestSignErrors2665=== PAUSE TestSignErrors2666=== CONT TestExternalSigner2667=== CONT TestExternalSignerProgramErrorKeepsProcess2668=== CONT TestSignBatch2669=== CONT TestExternalSignerCancellation2670=== CONT TestSign2671=== CONT TestParseSigningKey2672=== RUN TestParseSigningKey/valid_32-byte_key2673=== PAUSE TestParseSigningKey/valid_32-byte_key2674=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2675=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2676=== RUN TestParseSigningKey/no_colon2677=== PAUSE TestParseSigningKey/no_colon2678=== RUN TestParseSigningKey/empty_name2679=== PAUSE TestParseSigningKey/empty_name2680=== CONT TestGenerateFingerprint2681=== RUN TestGenerateFingerprint/basic_with_references2682=== PAUSE TestGenerateFingerprint/basic_with_references2683=== CONT TestExternalSignerErrors2684=== RUN TestExternalSignerErrors/exit_on_request2685=== PAUSE TestExternalSignerErrors/exit_on_request2686=== RUN TestExternalSignerErrors/wrong_shape2687=== CONT TestExternalSignerRestartsAfterCrash2688=== CONT TestSignErrors2689=== CONT TestExternalSignerWrongPublicKey2690=== CONT TestExternalSignerRejectsInvalidPublicKey2691=== RUN TestExternalSignerRejectsInvalidPublicKey/#002692=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002693=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2694=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2695=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2696=== CONT TestExternalSignerClose2697=== CONT TestNilKeyPublicKey2698--- PASS: TestNilKeyPublicKey (0.00s)2699=== RUN TestParseSigningKey/invalid_base642700=== RUN TestGenerateFingerprint/no_references2701=== PAUSE TestGenerateFingerprint/no_references2702=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2703=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2704=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2705=== PAUSE TestExternalSignerErrors/wrong_shape2706=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2707=== RUN TestExternalSignerErrors/missing_signature_name2708=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2709=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2710=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2711=== PAUSE TestParseSigningKey/invalid_base642712=== PAUSE TestExternalSignerErrors/missing_signature_name2713=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2714=== RUN TestExternalSignerErrors/invalid_signature_base642715=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2716=== PAUSE TestExternalSignerErrors/invalid_signature_base642717=== RUN TestExternalSignerErrors/program_error2718=== PAUSE TestExternalSignerErrors/program_error2719=== RUN TestGenerateFingerprint/invalid_nar_hash_length2720=== CONT TestExternalSignerRejectsInvalidPublicKey/#002721=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2722=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2723=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2724=== RUN TestExternalSignerErrors/wrong_id2725=== RUN TestGenerateFingerprint/invalid_store_path_prefix2726=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2727=== RUN TestGenerateFingerprint/invalid_reference_prefix2728=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2729=== PAUSE TestExternalSignerErrors/wrong_id2730=== CONT TestGenerateFingerprint/no_references2731=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2732=== RUN TestExternalSignerErrors/too_few_signatures2733=== PAUSE TestExternalSignerErrors/too_few_signatures2734=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2735=== RUN TestExternalSignerErrors/wrong_signature_length2736=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2737=== PAUSE TestExternalSignerErrors/wrong_signature_length2738=== RUN TestParseSigningKey/wrong_length2739=== CONT TestGenerateFingerprint/basic_with_references2740=== PAUSE TestParseSigningKey/wrong_length2741=== CONT TestGenerateFingerprint/invalid_reference_prefix2742=== CONT TestParseSigningKey/valid_32-byte_key2743=== CONT TestGenerateFingerprint/invalid_store_path_prefix2744=== CONT TestGenerateFingerprint/invalid_nar_hash_length2745=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2746--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2747 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2748 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2749 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2750 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2751 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2752=== RUN TestExternalSignerErrors/exit_at_startup2753--- PASS: TestGenerateFingerprint (0.00s)2754 --- PASS: TestGenerateFingerprint/no_references (0.00s)2755 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2756 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2757 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2758 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2759 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2760 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2761=== PAUSE TestExternalSignerErrors/exit_at_startup2762=== CONT TestParseSigningKey/wrong_length2763=== CONT TestParseSigningKey/invalid_base642764=== CONT TestParseSigningKey/no_colon2765=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2766=== CONT TestParseSigningKey/empty_name2767=== RUN TestExternalSignerErrors/invalid_JSON2768=== RUN TestSignErrors/nil_key2769=== PAUSE TestSignErrors/nil_key2770=== RUN TestSignErrors/nil_narinfo2771=== PAUSE TestSignErrors/nil_narinfo2772=== RUN TestSignErrors/invalid_narinfo2773=== PAUSE TestSignErrors/invalid_narinfo2774=== RUN TestSignErrors/canceled2775=== PAUSE TestSignErrors/canceled2776=== CONT TestSignErrors/nil_key2777--- PASS: TestParseSigningKey (0.00s)2778 --- PASS: TestParseSigningKey/wrong_length (0.00s)2779 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2780 --- PASS: TestParseSigningKey/no_colon (0.00s)2781 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2782 --- PASS: TestParseSigningKey/empty_name (0.00s)2783 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2784=== CONT TestSignErrors/invalid_narinfo2785--- PASS: TestSign (0.00s)2786=== PAUSE TestExternalSignerErrors/invalid_JSON2787=== CONT TestSignErrors/nil_narinfo2788=== CONT TestSignErrors/canceled2789--- PASS: TestSignErrors (0.00s)2790 --- PASS: TestSignErrors/nil_key (0.00s)2791 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2792 --- PASS: TestSignErrors/nil_narinfo (0.00s)2793 --- PASS: TestSignErrors/canceled (0.00s)2794=== RUN TestExternalSignerErrors/null2795=== PAUSE TestExternalSignerErrors/null2796--- PASS: TestSignBatch (0.01s)2797=== RUN TestExternalSignerErrors/null_signatures2798=== PAUSE TestExternalSignerErrors/null_signatures2799=== RUN TestExternalSignerErrors/wrong_signatures_shape2800=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2801=== RUN TestExternalSignerErrors/unrequested_key2802=== PAUSE TestExternalSignerErrors/unrequested_key2803=== RUN TestExternalSignerErrors/missing_signatures2804=== PAUSE TestExternalSignerErrors/missing_signatures2805=== RUN TestExternalSignerErrors/wrong_signature_name2806=== PAUSE TestExternalSignerErrors/wrong_signature_name2807=== CONT TestExternalSignerErrors/exit_on_request2808=== CONT TestExternalSignerErrors/exit_at_startup2809=== CONT TestExternalSignerErrors/program_error2810=== CONT TestExternalSignerErrors/missing_signature_name2811=== CONT TestExternalSignerErrors/missing_signatures2812=== CONT TestExternalSignerErrors/wrong_signatures_shape2813=== CONT TestExternalSignerErrors/wrong_signature_name2814=== CONT TestExternalSignerErrors/null_signatures2815=== CONT TestExternalSignerErrors/wrong_signature_length2816=== CONT TestExternalSignerErrors/null2817=== CONT TestExternalSignerErrors/unrequested_key2818=== CONT TestExternalSignerErrors/invalid_JSON2819=== CONT TestExternalSignerErrors/too_few_signatures2820=== CONT TestExternalSignerErrors/invalid_signature_base642821=== CONT TestExternalSignerErrors/wrong_id2822=== CONT TestExternalSignerErrors/wrong_shape2823--- PASS: TestExternalSignerCancellation (0.41s)2824--- PASS: TestExternalSignerRestartsAfterCrash (0.60s)2825/private/var/tb/5/scratch/e759ffdaa87b1701/build/TestExternalSignerRestartsAfterCrash2409072306/001/sign program: line 7: /private/var/tb/5/scratch/e759ffdaa87b1701/build/TestExternalSignerRestartsAfterCrash2409072306/001/sign program.starts: No such file or directory2826--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.76s)2827--- PASS: TestExternalSigner (0.97s)2828--- PASS: TestExternalSignerWrongPublicKey (1.14s)2829--- PASS: TestExternalSignerClose (1.33s)2830--- PASS: TestExternalSignerErrors (0.01s)2831 --- PASS: TestExternalSignerErrors/exit_at_startup (1.51s)2832 --- PASS: TestExternalSignerErrors/program_error (1.69s)2833 --- PASS: TestExternalSignerErrors/wrong_shape (1.88s)2834 --- PASS: TestExternalSignerErrors/wrong_signature_length (2.07s)2835 --- PASS: TestExternalSignerErrors/unrequested_key (2.25s)2836 --- PASS: TestExternalSignerErrors/wrong_signature_name (2.44s)2837 --- PASS: TestExternalSignerErrors/missing_signatures (2.63s)2838 --- PASS: TestExternalSignerErrors/null_signatures (2.81s)2839 --- PASS: TestExternalSignerErrors/exit_on_request (3.00s)2840 --- PASS: TestExternalSignerErrors/null (3.19s)2841 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (3.38s)2842 --- PASS: TestExternalSignerErrors/invalid_JSON (3.79s)2843 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (3.98s)2844 --- PASS: TestExternalSignerErrors/wrong_id (4.17s)2845 --- PASS: TestExternalSignerErrors/too_few_signatures (4.36s)2846 --- PASS: TestExternalSignerErrors/missing_signature_name (4.55s)2847PASS2848Running OpenBao signer tests...2849=== RUN TestSign2850=== PAUSE TestSign2851=== RUN TestSignErrors2852=== PAUSE TestSignErrors2853=== RUN TestServe2854=== PAUSE TestServe2855=== RUN TestServeRejectsGarbage2856=== PAUSE TestServeRejectsGarbage2857=== CONT TestSign2858=== CONT TestServeRejectsGarbage2859=== CONT TestServe2860=== CONT TestSignErrors2861=== RUN TestSignErrors/http_error2862=== PAUSE TestSignErrors/http_error2863=== RUN TestSignErrors/invalid_json2864--- PASS: TestServeRejectsGarbage (0.00s)2865=== PAUSE TestSignErrors/invalid_json2866=== RUN TestSignErrors/no_prefix2867=== PAUSE TestSignErrors/no_prefix2868=== RUN TestSignErrors/invalid_base642869=== PAUSE TestSignErrors/invalid_base642870=== CONT TestSignErrors/http_error2871=== CONT TestSignErrors/no_prefix2872--- PASS: TestServe (0.00s)2873=== CONT TestSignErrors/invalid_base642874=== CONT TestSignErrors/invalid_json2875--- PASS: TestSign (0.01s)2876--- PASS: TestSignErrors (0.00s)2877 --- PASS: TestSignErrors/invalid_base64 (0.01s)2878 --- PASS: TestSignErrors/no_prefix (0.01s)2879 --- PASS: TestSignErrors/http_error (0.01s)2880 --- PASS: TestSignErrors/invalid_json (0.01s)2881PASS