niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #477
· 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.05s)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 TestPathInfoCACompatibility116=== RUN TestPathInfoCACompatibility/null_ca_field117=== PAUSE TestPathInfoCACompatibility/null_ca_field118=== CONT TestSetClientTLS119=== CONT TestStreamPushGivesUpOnDeadServer120=== CONT TestScriptTokenEmptyCommand121--- PASS: TestScriptTokenEmptyCommand (0.00s)122=== CONT TestStreamPushStopsWhenCanceled123--- PASS: TestStreamPushStopsWhenCanceled (0.00s)124=== CONT TestClientSignaturesByStorePath125=== CONT TestScriptTokenScriptFails126=== CONT TestScriptTokenBadJSON127=== CONT TestScriptTokenEmptyToken128=== CONT TestScriptTokenCachesUntilRefresh1292026/11/10 08:17:06 ERROR Upload failed error="connection refused" count=20130=== CONT TestScriptTokenNoExpiryRerunsEveryCall1312026/11/10 08:17:06 ERROR Server seems unavailable, giving up on batch untried=17132=== CONT TestFileTokenEmpty133=== CONT TestFileTokenMissing134=== CONT TestStreamPushReportsSignatures135=== CONT TestFileTokenReadsAndCaches136=== CONT TestStaticToken1372026/11/10 08:17:06 ERROR Upload failed error=boom count=1138=== CONT TestStreamPushRequestLine139=== CONT TestUploadMultipart_PartsInParallel140=== CONT TestSetClientTLSErrors141=== CONT TestSetClientTLSDoesNotMutateDefaultTransport142=== CONT TestEncodeNixBase32WithRealHash1432026/11/10 08:17:06 ERROR Upload failed error=boom count=1144=== CONT TestDoWithRetry_BodyReplayedViaGetBody145=== CONT TestResolveStorePath146=== CONT TestRegisterUploadedObject_OutlivesPush147=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer148=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess149=== CONT TestRateLimiterFeedback150=== RUN TestPathInfoCACompatibility/old_string_format_-_text151--- PASS: TestClientSignaturesByStorePath (0.00s)152=== CONT TestStreamPushReportsSkippedPaths153=== CONT TestEncodeNixBase32154=== RUN TestRateLimiterFeedback/429_enables_limiter155=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text156=== RUN TestEncodeNixBase32/test_string_hash157=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive158--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)159--- PASS: TestStreamPushReportsSignatures (0.00s)160--- PASS: TestStaticToken (0.00s)161--- PASS: TestEncodeNixBase32WithRealHash (0.00s)1622026/11/10 08:17:06 WARN Rate limiter enabled after throttle name=server-test rate=5163=== RUN TestSetClientTLSErrors/missing_cert_file164--- PASS: TestFileTokenMissing (0.00s)165--- PASS: TestScriptTokenScriptFails (0.01s)166=== CONT TestDumpPathSingleFile167--- PASS: TestFileTokenEmpty (0.00s)168=== CONT TestDumpPathMatchesNix169--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)170=== CONT TestPartSizeForNAR171=== RUN TestPartSizeForNAR/zero_stays_at_minimum172=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum173=== RUN TestPartSizeForNAR/small_stays_at_minimum174--- PASS: TestResolveStorePath (0.00s)175=== CONT TestUploadMultipart_ReturnsAfterDroppedBody176=== PAUSE TestEncodeNixBase32/test_string_hash177=== PAUSE TestRateLimiterFeedback/429_enables_limiter178=== CONT TestDumpPathWriterError179=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive180=== PAUSE TestPartSizeForNAR/small_stays_at_minimum181=== PAUSE TestSetClientTLSErrors/missing_cert_file182=== RUN TestEncodeNixBase32/empty_input183=== PAUSE TestEncodeNixBase32/empty_input184=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun185=== RUN TestSetClientTLS/rejects_connection_without_client_cert186=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert187=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA188=== RUN TestRateLimiterFeedback/503_enables_limiter189--- PASS: TestStreamPushReportsSkippedPaths (0.01s)190=== PAUSE TestRateLimiterFeedback/503_enables_limiter191=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter192=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter193=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter194=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter195=== CONT TestFilterOversizedClosures196=== RUN TestFilterOversizedClosures/no_limit_keeps_everything197=== CONT TestCaseHackSuffix198--- PASS: TestScriptTokenEmptyToken (0.01s)199=== CONT TestPathInfoHashCompatibility200=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum201=== RUN TestSetClientTLSErrors/missing_key_file202=== PAUSE TestSetClientTLSErrors/missing_key_file203=== RUN TestSetClientTLSErrors/missing_ca_file204=== PAUSE TestSetClientTLSErrors/missing_ca_file205=== RUN TestSetClientTLSErrors/invalid_ca_file206=== PAUSE TestSetClientTLSErrors/invalid_ca_file207=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA208=== RUN TestSetClientTLS/preserves_debug_logging_transport209=== PAUSE TestSetClientTLS/preserves_debug_logging_transport210=== CONT TestParsePathInfoJSONMultiplePaths211--- PASS: TestDoServerRequestAttachesToken (0.01s)212=== CONT TestStreamPushReportsEveryPath213=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths214=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths215=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths216=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths217=== CONT TestStreamPushIsolatesFailures218=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything219=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped220=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped221=== RUN TestFilterOversizedClosures/all_closures_skipped222=== PAUSE TestFilterOversizedClosures/all_closures_skipped223--- PASS: TestStreamPushReportsEveryPath (0.00s)224=== CONT TestShellSplit225=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)226--- PASS: TestShellSplit (0.00s)227=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)228=== RUN TestPathInfoCACompatibility/new_structured_format_-_text229=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text230=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method231=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method232=== CONT TestParsePathInfoJSON233=== RUN TestParsePathInfoJSON/Nix_format234=== PAUSE TestParsePathInfoJSON/Nix_format235=== RUN TestParsePathInfoJSON/Lix_format236=== PAUSE TestParsePathInfoJSON/Lix_format237=== RUN TestParsePathInfoJSON/empty_input238=== PAUSE TestParsePathInfoJSON/empty_input239=== RUN TestParsePathInfoJSON/whitespace_only240=== PAUSE TestParsePathInfoJSON/whitespace_only241=== RUN TestParsePathInfoJSON/invalid_JSON242=== PAUSE TestParsePathInfoJSON/invalid_JSON243=== CONT TestRegisterUploadedObjectReusesConnections244--- PASS: TestFileTokenReadsAndCaches (0.01s)245=== CONT TestDoWithRetry_FinalResponseBodyReadable246=== CONT TestStreamPushBatchesUnderLoad247=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false248=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false249=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true250=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true251=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica252--- PASS: TestScriptTokenBadJSON (0.01s)253=== CONT TestConvertHashToNix32254=== RUN TestConvertHashToNix32/SRI_format_to_Nix32255=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32256=== RUN TestConvertHashToNix32/already_Nix32_format257=== PAUSE TestConvertHashToNix32/already_Nix32_format258=== RUN TestConvertHashToNix32/invalid_format259=== PAUSE TestConvertHashToNix32/invalid_format260=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry2612026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:607312622026/11/10 08:17:06 INFO Garbage collection started2632026/11/10 08:17:06 ERROR Upload failed error="bad path" count=3264--- PASS: TestStreamPushIsolatesFailures (0.00s)265=== CONT TestEncodeNixBase32/test_string_hash266=== CONT TestEncodeNixBase32/empty_input267--- PASS: TestEncodeNixBase32 (0.01s)268 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)269 --- PASS: TestEncodeNixBase32/empty_input (0.00s)270=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum271=== CONT TestShellSplitErrors272=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon273=== CONT TestGetStorePathHash274=== CONT TestRateLimiterFeedback/429_enables_limiter275=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts276--- PASS: TestShellSplitErrors (0.00s)277=== RUN TestGetStorePathHash/valid_store_path278=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon279=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI280=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI281=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512282=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512283=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts284=== RUN TestPartSizeForNAR/1_TiB285=== PAUSE TestPartSizeForNAR/1_TiB286=== RUN TestPartSizeForNAR/5_TiB_S3_max_object287=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object288=== RUN TestPartSizeForNAR/capped_at_5_GiB289=== PAUSE TestPartSizeForNAR/capped_at_5_GiB290=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter2912026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:60731292=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter293=== PAUSE TestGetStorePathHash/valid_store_path294=== RUN TestGetStorePathHash/basename_without_hyphen_should_error295=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error296=== CONT TestRateLimiterFeedback/503_enables_limiter297=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error298=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error299=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error300=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error301--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)302=== CONT TestSetClientTLSErrors/missing_cert_file303=== CONT TestSetClientTLS/rejects_connection_without_client_cert304=== CONT TestSetClientTLSErrors/invalid_ca_file3052026/11/10 08:17:06 WARN Rate limiter enabled after throttle name=server-test rate=53062026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:60783307=== CONT TestSetClientTLSErrors/missing_ca_file308=== CONT TestSetClientTLSErrors/missing_key_file3092026/11/10 08:17:06 WARN Rate limiter enabled after throttle name=server-test rate=53102026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:60753311=== CONT TestSetClientTLS/preserves_debug_logging_transport312=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA313--- PASS: TestSetClientTLSErrors (0.01s)314 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)315 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)316 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)317 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)3182026/11/10 08:17:06 WARN Rate limiter backed off name=server-test rate=5319--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)320=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths321=== CONT TestFilterOversizedClosures/no_limit_keeps_everything322=== CONT TestFilterOversizedClosures/all_closures_skipped3232026/11/10 08:17:06 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=50324=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3252026/11/10 08:17:06 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=2000326--- PASS: TestFilterOversizedClosures (0.00s)327 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)328 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)329 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)330=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths331=== CONT TestPathInfoCACompatibility/null_ca_field332--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)333 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)334 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)335=== CONT TestParsePathInfoJSON/Nix_format336=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method337=== CONT TestPathInfoCACompatibility/new_structured_format_-_text338=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive339=== CONT TestPathInfoCACompatibility/old_string_format_-_text340--- PASS: TestPathInfoCACompatibility (0.01s)341 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)342 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)343 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)344 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)345 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)346=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false3472026/11/10 08:17:06 WARN Rate limiter enabled after throttle name=server-test rate=53482026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:607383492026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:60731350=== CONT TestParsePathInfoJSON/invalid_JSON351--- PASS: TestRegisterUploadedObject_OutlivesPush (0.01s)352=== CONT TestParsePathInfoJSON/whitespace_only353=== CONT TestConvertHashToNix32/SRI_format_to_Nix32354=== CONT TestParsePathInfoJSON/empty_input355=== CONT TestConvertHashToNix32/already_Nix32_format356=== CONT TestConvertHashToNix32/invalid_format357--- PASS: TestConvertHashToNix32 (0.00s)358 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)359 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)360 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)361=== CONT TestParsePathInfoJSON/Lix_format362--- 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=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true369--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.01s)370=== CONT TestPartSizeForNAR/capped_at_5_GiB371=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512372=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI373--- PASS: TestStreamPushBatchesUnderLoad (0.00s)374 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)375 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)376=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon377=== CONT TestPartSizeForNAR/1_TiB378=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts379=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum380=== CONT TestPartSizeForNAR/small_stays_at_minimum381=== CONT TestGetStorePathHash/valid_store_path382=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)383--- PASS: TestPathInfoHashCompatibility (0.00s)384 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)385 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)386 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)387 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)388=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error389=== CONT TestGetStorePathHash/basename_without_hyphen_should_error390=== CONT TestPartSizeForNAR/zero_stays_at_minimum391=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error392--- PASS: TestGetStorePathHash (0.00s)393 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)394 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)395 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)396 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)397=== CONT TestPartSizeForNAR/5_TiB_S3_max_object398--- PASS: TestPartSizeForNAR (0.01s)399 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)400 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)401 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)402 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)403 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)404 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)405 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)4062026/11/10 08:17:06 WARN Rate limiter enabled after throttle name=server-test rate=54072026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:607944082026/11/10 08:17:06 WARN Rate limiter backed off name=server-test rate=54092026/11/10 08:17:06 INFO Garbage collection started4102026/11/10 08:17:06 WARN Rate limiter backed off name=server-test rate=54112026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:607384122026/11/10 08:17:06 WARN Rate limiter enabled after throttle name=s3-test rate=54132026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:607794142026/11/10 08:17:06 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=04152026/11/10 08:17:06 WARN Rate limiter backed off name=server-test rate=5416--- PASS: TestRateLimiterFeedback (0.01s)417 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)418 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)419 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)420 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)4212026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:60731422--- PASS: TestStreamPushRequestLine (0.02s)423--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.01s)424--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)4252026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:607314262026/11/10 08:17:06 WARN Garbage collection finished on another replica. Its statistics are not available here427--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)4282026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:607314292026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:607314302026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:607314312026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:607314322026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:607314332026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:607314342026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:607314352026/11/10 08:17:06 http: TLS handshake error from 127.0.0.1:60804: remote error: tls: bad certificate436--- PASS: TestSetClientTLS (0.01s)437 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)438 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)439 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)4402026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:60731441--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)4422026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:607314432026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:607314442026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:607314452026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:607314462026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:60731447--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)4482026/11/10 08:17:06 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:60731449--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)450--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.05s)451--- PASS: TestDumpPathWriterError (0.04s)452--- PASS: TestDumpPathSingleFile (0.05s)453--- PASS: TestCaseHackSuffix (0.05s)454--- PASS: TestDumpPathMatchesNix (0.07s)4552026/11/10 08:17:06 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:60736/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:60736/api/uploads/complete4562026/11/10 08:17:06 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4572026/11/10 08:17:06 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:60736/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:60736/api/uploads/complete4582026/11/10 08:17:06 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4592026/11/10 08:17:06 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:60736/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:60736/api/uploads/complete4602026/11/10 08:17:06 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"461--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (0.11s)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 "_tribuchetbld6".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/6/scratch/e12f70b2f235e287/build/postgres1582677697/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/6/scratch/e12f70b2f235e287/build/postgres1582677697/data -l logfile start492493/private/var/tb/6/scratch/e12f70b2f235e287/build/postgres1582677697:5432 - no response4942026-11-10 08:17:08.064 UTC [94276] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4952026-11-10 08:17:08.064 UTC [94276] LOG: listening on Unix socket "/private/var/tb/6/scratch/e12f70b2f235e287/build/postgres1582677697/.s.PGSQL.5432"4962026-11-10 08:17:08.066 UTC [94283] LOG: database system was shut down at 2026-11-10 08:17:08 UTC4972026-11-10 08:17:08.067 UTC [94276] LOG: database system is ready to accept connections498/private/var/tb/6/scratch/e12f70b2f235e287/build/postgres1582677697:5432 - accepting connections499{"timestamp":"2026-11-10T08:17:14.55276Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"4f46912a-76a7-4128-a4ef-192f49d0c4e8","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":1,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}500{"timestamp":"2026-11-10T08:17:14.65735Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"de6dcaf9-af6d-4052-b060-b6b1304029f3","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}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:17:14 INFO lead: acquired remote=192.0.2.1:12345512026/11/10 08:17:15 INFO lead: released remote=192.0.2.1:12345522026/11/10 08:17:15 INFO lead: acquired remote=192.0.2.1:12345532026/11/10 08:17:16 INFO lead: released remote=192.0.2.1:1234554--- PASS: TestLeadIncumbentWinsAfterRestart (1.92s)555=== RUN TestLeadIncumbentAnnouncesAtOnce556=== PAUSE TestLeadIncumbentAnnouncesAtOnce557=== RUN TestLeadEndsOnShutdown558=== PAUSE TestLeadEndsOnShutdown559=== RUN TestLeadEndsWhenItsConnectionHangs5602026/11/10 08:17:16 INFO lead: acquired remote=192.0.2.1:12345612026-11-10 08:17:18.052 UTC [94334] FATAL: terminating connection due to administrator command5622026/11/10 08:17:18 INFO lead: acquired remote=192.0.2.1:12345632026/11/10 08:17:19 WARN lead: lock connection lost error="timeout: context deadline exceeded"5642026/11/10 08:17:19 INFO lead: released remote=192.0.2.1:12345652026/11/10 08:17:19 INFO lead: released remote=192.0.2.1:1234566--- PASS: TestLeadEndsWhenItsConnectionHangs (2.76s)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:17:19 INFO Starting HTTP server address=127.0.0.1:609936692026/11/10 08:17:19 INFO Starting HTTP server address=proxy.sock6702026/11/10 08:17:19 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6712026/11/10 08:17:19 INFO Shutdown signal received, draining in-flight requests timeout=10s672--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.16s)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.03s)739=== RUN TestWatchdogSkipsWhenUnhealthy7402026/11/10 08:17:19 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7412026/11/10 08:17:19 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7422026/11/10 08:17:19 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7432026/11/10 08:17:19 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7442026/11/10 08:17:19 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7452026/11/10 08:17:19 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7462026/11/10 08:17:19 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7472026/11/10 08:17:19 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7482026/11/10 08:17:19 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7492026/11/10 08:17:19 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 TestReadProxyNarinfoAlreadyDecompressed776=== CONT TestCompleteMultipartUnregistered777=== CONT TestPush_RootsAreLockedInByteOrder778=== CONT TestParseSingleRange779=== RUN TestParseSingleRange/none780=== CONT TestReadProxyNarinfo781=== CONT TestIsValidCachePath782=== RUN TestIsValidCachePath/narinfo783=== CONT TestPush_SignsNarinfosOfItsPendingObjects784=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT785=== CONT TestPresentNotReportedWhileGCDeletesClosure786=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale787=== CONT TestPresentRefreshesOnlyStaleClosures788=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale789=== CONT TestPresentReportsOnlyClosureRoots790=== CONT TestCreatePin_ReservedPins791=== CONT TestOrphanedObjectsGCStressTest792=== CONT TestOrphanedObjectsGC793=== CONT TestObjectStatsUpdatedOncePerCommit794=== CONT TestObjectStatsTrigger795=== CONT TestPendingCleanupUsesOneCutoff796=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded797=== CONT TestReadRedirectKeepsNarinfoProxied798=== CONT TestMultipartCleanup799=== CONT TestPush_RejectsBadRequests800=== CONT TestServerTLSConfig801=== RUN TestServerTLSConfig/no_client_CA802=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit803=== PAUSE TestServerTLSConfig/no_client_CA804=== CONT TestAbortSucceeded805=== RUN TestServerTLSConfig/missing_CA_file806--- PASS: TestAbortSucceeded (0.00s)807=== PAUSE TestParseSingleRange/none808=== RUN TestParseSingleRange/unknown_unit809=== PAUSE TestServerTLSConfig/missing_CA_file810=== PAUSE TestParseSingleRange/unknown_unit811=== CONT TestService_NativeMTLS812=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh813=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh814=== RUN TestServerTLSConfig/not_a_PEM_file815=== CONT TestMetricsCommit816=== PAUSE TestServerTLSConfig/not_a_PEM_file817=== PAUSE TestIsValidCachePath/narinfo818=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars819=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars820=== RUN TestIsValidCachePath/nar_zst821=== PAUSE TestIsValidCachePath/nar_zst822=== RUN TestIsValidCachePath/nar_xz823=== RUN TestParseSingleRange/multi-range_ignored824=== PAUSE TestIsValidCachePath/nar_xz825=== CONT TestMetricsInventory826=== RUN TestIsValidCachePath/nar_bz2827=== PAUSE TestIsValidCachePath/nar_bz2828=== RUN TestIsValidCachePath/nar_uncompressed829=== PAUSE TestParseSingleRange/multi-range_ignored830=== PAUSE TestIsValidCachePath/nar_uncompressed831=== RUN TestIsValidCachePath/ls832=== RUN TestParseSingleRange/malformed_no_dash833=== PAUSE TestParseSingleRange/malformed_no_dash834=== PAUSE TestIsValidCachePath/ls835=== RUN TestIsValidCachePath/log836=== PAUSE TestIsValidCachePath/log837=== RUN TestIsValidCachePath/realisation838=== PAUSE TestIsValidCachePath/realisation839=== RUN TestIsValidCachePath/nix-cache-info840=== PAUSE TestIsValidCachePath/nix-cache-info841=== RUN TestIsValidCachePath/index.html842=== PAUSE TestIsValidCachePath/index.html843=== RUN TestIsValidCachePath/traversal_parent844=== PAUSE TestIsValidCachePath/traversal_parent845=== RUN TestIsValidCachePath/traversal_in_middle846=== RUN TestParseSingleRange/malformed_both_empty847=== PAUSE TestIsValidCachePath/traversal_in_middle848=== PAUSE TestParseSingleRange/malformed_both_empty849=== RUN TestIsValidCachePath/invalid_char_e850=== PAUSE TestIsValidCachePath/invalid_char_e851=== RUN TestIsValidCachePath/invalid_char_u852=== PAUSE TestIsValidCachePath/invalid_char_u853=== RUN TestIsValidCachePath/random_path854=== RUN TestParseSingleRange/malformed_end_before_start855=== PAUSE TestIsValidCachePath/random_path856=== RUN TestIsValidCachePath/empty857=== PAUSE TestIsValidCachePath/empty858=== RUN TestIsValidCachePath/leading_slash859=== PAUSE TestIsValidCachePath/leading_slash860=== RUN TestIsValidCachePath/wrong_extension861=== PAUSE TestIsValidCachePath/wrong_extension862=== RUN TestIsValidCachePath/short_hash863=== PAUSE TestIsValidCachePath/short_hash864=== PAUSE TestParseSingleRange/malformed_end_before_start865=== CONT TestNARDeduplicationMetadataUploadBug866=== RUN TestParseSingleRange/closed867=== PAUSE TestParseSingleRange/closed868=== RUN TestParseSingleRange/open-ended869=== PAUSE TestParseSingleRange/open-ended870=== RUN TestParseSingleRange/end_clamped_to_size871=== PAUSE TestParseSingleRange/end_clamped_to_size872=== RUN TestParseSingleRange/suffix873=== PAUSE TestParseSingleRange/suffix874=== RUN TestParseSingleRange/suffix_exceeds_size875=== PAUSE TestParseSingleRange/suffix_exceeds_size876=== RUN TestParseSingleRange/single_byte877=== PAUSE TestParseSingleRange/single_byte878=== RUN TestParseSingleRange/start_past_EOF879=== PAUSE TestParseSingleRange/start_past_EOF880=== RUN TestParseSingleRange/start_far_past_EOF881=== PAUSE TestParseSingleRange/start_far_past_EOF882=== CONT TestCreatePendingClosureRejectsOversizedNAR8832026/11/10 08:17:19 INFO Received uploads request method=POST path=/api/pending_closures884--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)885=== CONT TestCacheConfigHandlerMaxNarSize886--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)887=== CONT TestEnsureAbortUploadsRule8882026/11/10 08:17:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60995/oidc8892026/11/10 08:17:20 INFO Received uploads request method=POST path=/api/pending_closures890--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.96s)891=== CONT TestGenerateLandingPage892--- PASS: TestGenerateLandingPage (0.00s)893=== CONT TestService_readinessHandler8942026/11/10 08:17:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8952026/11/10 08:17:21 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst896--- PASS: TestCompleteMultipartUnregistered (1.20s)897=== CONT TestService_healthCheckHandler898--- PASS: TestReadProxyNarinfoAlreadyDecompressed (1.53s)899=== CONT TestGracefulShutdownDrainsInflight9002026/11/10 08:17:21 INFO Starting HTTP server address=127.0.0.1:610119012026/11/10 08:17:21 INFO Shutdown signal received, draining in-flight requests timeout=10s902--- PASS: TestGracefulShutdownDrainsInflight (0.08s)903=== CONT TestGCTaskStore_Fail904--- PASS: TestGCTaskStore_Fail (0.00s)905=== CONT TestGCTaskStore_PhaseUpdates906--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)907=== CONT TestGCTaskStore_CompletedAllowsNewTask908--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)909=== CONT TestGCTaskStore_GetReturnsLatest910--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)911=== CONT TestGCTaskStore_GetEmpty912--- PASS: TestGCTaskStore_GetEmpty (0.00s)913=== CONT TestGCTaskStore_ConflictDifferentParams914--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)915=== CONT TestPush_CompleteCommitsEveryRoot916--- PASS: TestPresentReportsOnlyClosureRoots (1.87s)917=== CONT TestPush_CompleteWaitsForCleanupOfThePush9182026/11/10 08:17:21 INFO Received push request method=POST path=/api/pushes9192026/11/10 08:17:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9202026/11/10 08:17:21 INFO Signed narinfos id=1 count=19212026/11/10 08:17:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9222026/11/10 08:17:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9232026/11/10 08:17:21 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"9242026/11/10 08:17:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9252026/11/10 08:17:21 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"9262026/11/10 08:17:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9272026/11/10 08:17:21 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=19282026/11/10 08:17:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9292026/11/10 08:17:21 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo930--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (2.10s)931=== CONT TestGCTaskStore_DeduplicateSameParams932--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)933=== CONT TestPush_RepeatedRootCommitsOnce934=== RUN TestPush_RejectsBadRequests/no_objects935=== PAUSE TestPush_RejectsBadRequests/no_objects936=== RUN TestPush_RejectsBadRequests/bad_root937=== PAUSE TestPush_RejectsBadRequests/bad_root938=== RUN TestPush_RejectsBadRequests/root_not_in_objects939=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects940=== RUN TestPush_RejectsBadRequests/no_roots941=== PAUSE TestPush_RejectsBadRequests/no_roots942=== CONT TestGCTaskStore_StartNew943--- PASS: TestGCTaskStore_StartNew (0.00s)944=== CONT TestReadRedirectUsesPublicS3URL945--- PASS: TestPresentRefreshesOnlyStaleClosures (2.61s)946=== CONT TestGCEndsOnShutdown947=== RUN TestGCEndsOnShutdown/before_the_run948=== PAUSE TestGCEndsOnShutdown/before_the_run949=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete950=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete951=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark952=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark953=== CONT TestPush_OverlappingRootsStoreOneRowPerKey9542026/11/10 08:17:22 INFO Received uploads request method=POST path=/api/pending_closures9552026/11/10 08:17:22 INFO Received uploads request method=POST path=/api/pending_closures9562026/11/10 08:17:22 INFO Received cleanup request method=DELETE path=/api/pending_closures957--- PASS: TestObjectStatsUpdatedOncePerCommit (3.24s)958=== CONT TestCommitRacingPendingCleanupKeepsObjects9592026/11/10 08:17:23 INFO Received uploads request method=POST path=/api/pending_closures960--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (3.40s)961=== CONT TestProxyWriteTimeout962=== RUN TestProxyWriteTimeout/narinfo963=== PAUSE TestProxyWriteTimeout/narinfo964=== RUN TestProxyWriteTimeout/1_GiB_nar965=== PAUSE TestProxyWriteTimeout/1_GiB_nar966=== RUN TestProxyWriteTimeout/10_GiB_nar967=== PAUSE TestProxyWriteTimeout/10_GiB_nar968=== RUN TestProxyWriteTimeout/unknown_size969=== PAUSE TestProxyWriteTimeout/unknown_size970=== CONT TestService_verifyS3ReuploadsStaleNarinfo971=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed972=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed973=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed974=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed975=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost976=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost977=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed978=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed979=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed980=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed981=== CONT TestService_verifyS3Integrity982--- PASS: TestReadRedirectKeepsNarinfoProxied (3.68s)983=== CONT TestService_createPendingClosureHandler984=== NAME TestOrphanedObjectsGC985 orphaned_objects_gc_test.go:287: GC Test Summary:986 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A987 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B988 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)989 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)990 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects991--- PASS: TestOrphanedObjectsGC (4.05s)992=== CONT TestService_cleanupPendingClosuresHandler9932026/11/10 08:17:24 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>994--- PASS: TestReadProxyNarinfo (4.40s)995=== CONT TestUploadHandlersRejectOversizedBody996=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure997=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure998=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart999=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1000=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1001=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1002=== CONT TestUploadHandlersRejectInvalidKeys1003=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1004=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1005=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1006=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1007=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1008=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1009=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1010=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1011=== CONT TestIsValidUploadKey1012=== RUN TestIsValidUploadKey/narinfo1013=== PAUSE TestIsValidUploadKey/narinfo1014=== RUN TestIsValidUploadKey/nar_zst1015=== PAUSE TestIsValidUploadKey/nar_zst1016=== RUN TestIsValidUploadKey/nar_xz1017=== PAUSE TestIsValidUploadKey/nar_xz1018=== RUN TestIsValidUploadKey/nar_plain1019=== PAUSE TestIsValidUploadKey/nar_plain1020=== RUN TestIsValidUploadKey/listing1021=== PAUSE TestIsValidUploadKey/listing1022=== RUN TestIsValidUploadKey/build_log1023=== PAUSE TestIsValidUploadKey/build_log1024=== RUN TestIsValidUploadKey/build_log_home-manager_file1025=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1026=== RUN TestIsValidUploadKey/build_log_plus_in_name1027=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1028=== RUN TestIsValidUploadKey/build_log_question_mark1029=== PAUSE TestIsValidUploadKey/build_log_question_mark1030=== RUN TestIsValidUploadKey/build_log_equals1031=== PAUSE TestIsValidUploadKey/build_log_equals1032=== RUN TestIsValidUploadKey/realisation1033=== PAUSE TestIsValidUploadKey/realisation1034=== RUN TestIsValidUploadKey/realisation_plus_in_output1035=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1036=== RUN TestIsValidUploadKey/nix-cache-info1037=== PAUSE TestIsValidUploadKey/nix-cache-info1038=== RUN TestIsValidUploadKey/index.html1039=== PAUSE TestIsValidUploadKey/index.html1040=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1041=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1042=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1043=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1044=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1045=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1046=== RUN TestIsValidUploadKey/traversal1047=== PAUSE TestIsValidUploadKey/traversal1048=== RUN TestIsValidUploadKey/traversal_nar1049=== PAUSE TestIsValidUploadKey/traversal_nar1050=== RUN TestIsValidUploadKey/absolute1051=== PAUSE TestIsValidUploadKey/absolute1052=== RUN TestIsValidUploadKey/empty_key1053=== PAUSE TestIsValidUploadKey/empty_key1054=== RUN TestIsValidUploadKey/unknown_type1055=== PAUSE TestIsValidUploadKey/unknown_type1056=== CONT TestPendingClosureWriteTimeout1057=== RUN TestPendingClosureWriteTimeout/empty1058=== PAUSE TestPendingClosureWriteTimeout/empty1059=== RUN TestPendingClosureWriteTimeout/400_objects1060=== PAUSE TestPendingClosureWriteTimeout/400_objects1061=== RUN TestPendingClosureWriteTimeout/670k_objects1062=== PAUSE TestPendingClosureWriteTimeout/670k_objects1063=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1064=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1065=== CONT TestPushWaitsForSweepHoldingRow10662026/11/10 08:17:24 WARN mTLS auth: subject not in bound subjects subject="CN=reader"10672026/11/10 08:17:24 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1068--- PASS: TestService_NativeMTLS (4.51s)1069=== CONT TestSweepRechecksPendingAfterLocking1070--- PASS: TestObjectStatsTrigger (4.76s)1071=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock10722026/11/10 08:17:24 INFO Installed lifecycle rule aborting incomplete NAR uploads bucket=bucket20 days=21073--- PASS: TestEnsureAbortUploadsRule (5.10s)1074=== CONT TestGetExistingObjectsLocksRows1075--- PASS: TestMetricsInventory (5.30s)1076=== CONT TestRegisterCompletedObjectNeedsPendingRow10772026/11/10 08:17:25 INFO Received push request method=POST path=/api/pushes10782026-11-10 08:17:25.493 UTC [94489] ERROR: could not obtain lock on row in relation "closures"10792026-11-10 08:17:25.493 UTC [94489] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10802026-11-10 08:17:25.498 UTC [94489] ERROR: could not obtain lock on row in relation "closures"10812026-11-10 08:17:25.498 UTC [94489] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10822026-11-10 08:17:25.503 UTC [94489] ERROR: could not obtain lock on row in relation "closures"10832026-11-10 08:17:25.503 UTC [94489] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10842026-11-10 08:17:25.505 UTC [94489] ERROR: could not obtain lock on row in relation "closures"10852026-11-10 08:17:25.505 UTC [94489] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10862026-11-10 08:17:25.506 UTC [94489] ERROR: could not obtain lock on row in relation "closures"10872026-11-10 08:17:25.506 UTC [94489] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1088--- PASS: TestPush_RootsAreLockedInByteOrder (5.65s)1089=== CONT TestDeleteClosuresRacingPins10902026/11/10 08:17:25 INFO Received push request method=POST path=/api/pushes10912026/11/10 08:17:25 INFO Received complete push request method=POST path=/api/pushes/1/complete10922026/11/10 08:17:25 INFO Completed push id=1 objects=4 duration=21.604208ms10932026/11/10 08:17:25 INFO Received push request method=POST path=/api/pushes10942026/11/10 08:17:25 INFO Aborted multipart uploads count=0 kept=010952026/11/10 08:17:25 WARN Force mode enabled - objects will be deleted immediately without grace period10962026/11/10 08:17:25 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=010972026/11/10 08:17:25 INFO Vacuumed table table=pending_closures10982026/11/10 08:17:25 INFO Received push request method=POST path=/api/pushes10992026/11/10 08:17:25 INFO Vacuumed table table=pending_objects11002026/11/10 08:17:26 INFO Vacuumed table table=multipart_uploads11012026/11/10 08:17:26 INFO Vacuumed table table=closures11022026/11/10 08:17:26 INFO Received complete push request method=POST path=/api/pushes/1/complete11032026/11/10 08:17:26 INFO Vacuumed table table=objects11042026/11/10 08:17:26 INFO Received complete push request method=POST path=/api/pushes/2/complete11052026/11/10 08:17:26 INFO Completed push id=1 objects=4 duration=34.882334ms11062026/11/10 08:17:26 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11072026/11/10 08:17:26 INFO Completed push id=2 objects=4 duration=17.405667ms11082026/11/10 08:17:26 INFO Completed upload id=2 objects=2 duration=1.694209ms1109--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (6.26s)1110=== CONT TestClientFallsBackToClosures1111=== CONT TestSweepSkipsRowsLockedByPush1112--- PASS: TestMetricsCommit (6.26s)11132026/11/10 08:17:26 INFO Received uploads request method=POST path=/api/pending_closures11142026/11/10 08:17:26 INFO Received cleanup request method=DELETE path=/api/pending_closures11152026/11/10 08:17:26 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket25/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""11162026/11/10 08:17:26 INFO Aborted multipart uploads count=0 kept=111172026/11/10 08:17:26 INFO Received cleanup request method=DELETE path=/api/pending_closures11182026/11/10 08:17:26 INFO Aborted multipart uploads count=1 kept=01119--- PASS: TestMultipartCleanup (6.70s)1120=== CONT TestFailedS3DeleteKeepsTombstone1121=== NAME TestNARDeduplicationMetadataUploadBug1122 metadata_upload_test.go:48: First store path: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestNARDeduplicationMetadataUploadBug2025010327/001/store/c03lqqdhlvsdkzghlgf1hr6bxznyx3vq-file1.txt11232026/11/10 08:17:26 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11242026/11/10 08:17:26 WARN Refused reserved pin name=worker-x86_64-linux11252026/11/10 08:17:26 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11262026/11/10 08:17:26 INFO Received create pin request method=POST path=/api/pins/my-app11272026/11/10 08:17:26 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1128--- PASS: TestCreatePin_ReservedPins (6.96s)1129=== CONT TestForceGCDuringPushOffersSweptObject1130=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1131=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1132=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1133=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1134=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection11352026/11/10 08:17:26 INFO Received push request method=POST path=/api/pushes11362026/11/10 08:17:26 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11372026/11/10 08:17:26 INFO Uploading c03lqqdhlvsdkzghlgf1hr6bxznyx3vq-file1.txt (160B)11382026/11/10 08:17:26 WARN Failed to register uploaded object key=c03lqqdhlvsdkzghlgf1hr6bxznyx3vq.ls error="server returned 404: 404 page not found\n"11392026/11/10 08:17:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11402026/11/10 08:17:27 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11412026/11/10 08:17:27 INFO Signed narinfos id=1 count=111422026/11/10 08:17:27 INFO Uploading 1 narinfos11432026/11/10 08:17:27 WARN readiness check failed error="closed pool"1144--- PASS: TestService_readinessHandler (6.21s)1145=== CONT TestClientPushesUseOnePush11462026/11/10 08:17:27 INFO Received complete push request method=POST path=/api/pushes/1/complete11472026/11/10 08:17:27 WARN Failed to register uploaded object key=c03lqqdhlvsdkzghlgf1hr6bxznyx3vq.narinfo error="server returned 404: 404 page not found\n"11482026/11/10 08:17:27 INFO Completed push id=1 objects=3 duration=33.251917ms11492026/11/10 08:17:27 INFO Upload complete. (248ms)1150=== NAME TestNARDeduplicationMetadataUploadBug1151 metadata_upload_test.go:54: Retrieved narinfo from S3:1152 StorePath: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestNARDeduplicationMetadataUploadBug2025010327/001/store/c03lqqdhlvsdkzghlgf1hr6bxznyx3vq-file1.txt1153 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1154 Compression: zstd1155 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1156 NarSize: 1601157 References: 1158 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1159 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1160 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1161 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1162 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/6/scratch/e12f70b2f235e287/build/TestNARDeduplicationMetadataUploadBug2025010327/001/store/hsvwh9k7bzvgd660gq83c6cmgcsjzbc3-file2.txt11632026/11/10 08:17:27 INFO Received push request method=POST path=/api/pushes11642026/11/10 08:17:27 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)11652026/11/10 08:17:27 INFO Received push request method=POST path=/api/pushes11662026/11/10 08:17:27 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign11672026/11/10 08:17:27 WARN Failed to register uploaded object key=hsvwh9k7bzvgd660gq83c6cmgcsjzbc3.ls error="server returned 404: 404 page not found\n"11682026/11/10 08:17:27 INFO Signed narinfos id=2 count=111692026/11/10 08:17:27 INFO Uploading 1 narinfos11702026/11/10 08:17:27 INFO Received complete push request method=POST path=/api/pushes/2/complete11712026/11/10 08:17:27 WARN Failed to register uploaded object key=hsvwh9k7bzvgd660gq83c6cmgcsjzbc3.narinfo error="server returned 404: 404 page not found\n"11722026/11/10 08:17:27 INFO Completed push id=2 objects=3 duration=1.136416ms11732026/11/10 08:17:27 INFO Upload complete. (176ms)11742026/11/10 08:17:27 INFO Received complete push request method=POST path=/api/pushes/1/complete1175 metadata_upload_test.go:76: Retrieved narinfo from S3:1176 StorePath: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestNARDeduplicationMetadataUploadBug2025010327/001/store/hsvwh9k7bzvgd660gq83c6cmgcsjzbc3-file2.txt1177 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1178 Compression: zstd1179 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1180 NarSize: 1601181 References: 1182 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1183 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1184 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1185 {"version":1,"root":{"type":"regular","size":44}}11862026/11/10 08:17:27 INFO Completed push id=1 objects=6 duration=40.5015ms1187--- PASS: TestPush_CompleteCommitsEveryRoot (5.96s)1188=== CONT TestPinProtectsFromGC1189--- PASS: TestNARDeduplicationMetadataUploadBug (7.59s)1190=== CONT TestService_Rustfstest1191--- PASS: TestService_healthCheckHandler (6.48s)1192=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle11932026/11/10 08:17:27 INFO Received push request method=POST path=/api/pushes11942026/11/10 08:17:28 INFO Received push request method=POST path=/api/pushes11952026-11-10 08:17:28.202 UTC [94534] ERROR: Push does not exist: id=111962026-11-10 08:17:28.202 UTC [94534] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE11972026-11-10 08:17:28.202 UTC [94534] STATEMENT: SELECT commit_push($1)1198--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (6.47s)1199=== CONT TestSkippedUploadsHandler12002026/11/10 08:17:28 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001201--- PASS: TestSkippedUploadsHandler (0.00s)1202=== CONT TestGCSweepDeliversEachKeyOnce12032026/11/10 08:17:28 INFO Received complete push request method=POST path=/api/pushes/1/complete12042026/11/10 08:17:28 INFO Completed push id=1 objects=4 duration=31.94625ms1205--- PASS: TestPush_RepeatedRootCommitsOnce (6.31s)1206=== CONT TestParseSize1207--- PASS: TestParseSize (0.00s)1208=== CONT TestTombstonedObjectOfferedWithoutWaiting1209--- PASS: TestReadRedirectUsesPublicS3URL (6.39s)1210=== CONT TestCompletedNarNotReofferedAcrossClosures12112026/11/10 08:17:28 INFO Received push request method=POST path=/api/pushes12122026/11/10 08:17:28 INFO Aborted multipart uploads count=1 kept=01213--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (6.32s)1214=== CONT TestGCSweepSkipsPendingObjects12152026/11/10 08:17:28 INFO Received cleanup request method=DELETE path=/api/pending_closures12162026/11/10 08:17:28 INFO Aborted multipart uploads count=1 kept=01217--- PASS: TestPendingCleanupUsesOneCutoff (8.98s)1218=== CONT TestDeduplicatedObjectsRecordedAsPending12192026/11/10 08:17:29 INFO Aborted multipart uploads count=0 kept=012202026/11/10 08:17:29 WARN Force mode enabled - objects will be deleted immediately without grace period12212026/11/10 08:17:29 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=012222026/11/10 08:17:29 INFO Vacuumed table table=pending_closures12232026/11/10 08:17:29 INFO Vacuumed table table=pending_objects12242026/11/10 08:17:29 INFO Vacuumed table table=multipart_uploads12252026/11/10 08:17:29 INFO Vacuumed table table=closures12262026/11/10 08:17:29 INFO Vacuumed table table=objects12272026/11/10 08:17:29 INFO Received uploads request method=POST path=/api/pending_closures1228--- PASS: TestCommitRacingPendingCleanupKeepsObjects (6.31s)1229=== CONT TestPresignedUploadRegisteredBeforeCommit12302026/11/10 08:17:29 INFO Received uploads request method=POST path=/api/pending_closures12312026/11/10 08:17:29 INFO Received uploads request method=POST path=/api/pending_closures12322026/11/10 08:17:29 INFO Received uploads request method=POST path=/api/pending_closures12332026/11/10 08:17:30 INFO Received cleanup request method=DELETE path=/api/pending_closures12342026/11/10 08:17:30 INFO Aborted multipart uploads count=0 kept=012352026/11/10 08:17:30 INFO Received uploads request method=POST path=/api/pending_closures12362026/11/10 08:17:30 INFO Received cleanup request method=DELETE path=/api/pending_closures12372026/11/10 08:17:30 INFO Aborted multipart uploads count=1 kept=012382026/11/10 08:17:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12392026-11-10 08:17:30.300 UTC [94486] ERROR: Closure does not exist: id=112402026-11-10 08:17:30.300 UTC [94486] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE12412026-11-10 08:17:30.300 UTC [94486] STATEMENT: -- name: CommitPendingClosure :one1242 SELECT commit_pending_closure($1::bigint)::bigint1243 1244--- PASS: TestService_cleanupPendingClosuresHandler (6.40s)1245=== CONT TestPushDedupSurvivesConcurrentGC12462026/11/10 08:17:30 INFO Received uploads request method=POST path=/api/pending_closures1247--- PASS: TestPushWaitsForSweepHoldingRow (6.77s)1248=== CONT TestReadProxyRangeRequest12492026/11/10 08:17:31 INFO Aborted multipart uploads count=0 kept=012502026/11/10 08:17:31 WARN Force mode enabled - objects will be deleted immediately without grace period12512026/11/10 08:17:31 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012522026/11/10 08:17:31 INFO Vacuumed table table=pending_closures12532026/11/10 08:17:31 INFO Vacuumed table table=pending_objects12542026/11/10 08:17:31 INFO Vacuumed table table=multipart_uploads12552026/11/10 08:17:31 INFO Vacuumed table table=closures12562026/11/10 08:17:31 INFO Vacuumed table table=objects1257--- PASS: TestSweepRechecksPendingAfterLocking (6.98s)1258=== CONT TestGCMetrics12592026/11/10 08:17:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12602026/11/10 08:17:31 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NDE3MDRhN2YtZTZiZC00NWQ5LThkZDEtZDdkZjI1MzM5MThmLjJmYzI4ZTU4LTlmZmQtNDNkMy04MzBlLTcyMWUyNWRhODBjOHgxNzk0Mjk4NjQ5NDA2NTE5MDAw parts=1012612026/11/10 08:17:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12622026/11/10 08:17:31 INFO Completed upload id=1 objects=2 duration=37.835708ms12632026/11/10 08:17:31 INFO Received uploads request method=POST path=/api/pending_closures12642026/11/10 08:17:31 INFO Received uploads request method=POST path=/api/pending_closures12652026/11/10 08:17:31 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo12662026/11/10 08:17:31 WARN Found objects in DB but missing from S3, will re-upload count=11267--- PASS: TestService_verifyS3Integrity (8.31s)1268=== CONT TestGCBugBareHashReferences12692026/11/10 08:17:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1270--- PASS: TestGetExistingObjectsLocksRows (6.92s)1271=== CONT TestGCAdvisoryLockBlocksConcurrentRun12722026/11/10 08:17:31 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NDE3MDRhN2YtZTZiZC00NWQ5LThkZDEtZDdkZjI1MzM5MThmLjYwMDFlNWViLTU2NTItNDAwNy05YzgzLWExMjZlZDYwMWFkM3gxNzk0Mjk4NjQ5Njc1MDc2MDAw parts=1012732026/11/10 08:17:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12742026/11/10 08:17:31 INFO Completed upload id=1 objects=2 duration=23.332792ms12752026/11/10 08:17:31 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000012762026/11/10 08:17:32 INFO Received uploads request method=POST path=/api/pending_closures12772026/11/10 08:17:32 INFO Starting cleanup of old closures method=DELETE path=/api/closures12782026/11/10 08:17:32 INFO Aborted multipart uploads count=0 kept=012792026/11/10 08:17:32 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=012802026/11/10 08:17:32 INFO Vacuumed table table=pending_closures12812026/11/10 08:17:32 INFO Vacuumed table table=pending_objects1282--- PASS: TestRegisterCompletedObjectNeedsPendingRow (7.00s)12832026/11/10 08:17:32 INFO Vacuumed table table=multipart_uploads1284=== CONT TestClientSharedPathCommittedMidPush12852026/11/10 08:17:32 INFO Vacuumed table table=closures12862026/11/10 08:17:32 INFO Vacuumed table table=objects12872026/11/10 08:17:32 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001288--- PASS: TestService_createPendingClosureHandler (8.73s)1289=== CONT TestService_ReadScope_PublicByDefault12902026/11/10 08:17:33 INFO Aborted multipart uploads count=0 kept=012912026/11/10 08:17:33 WARN Force mode enabled - objects will be deleted immediately without grace period12922026/11/10 08:17: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=012932026/11/10 08:17:33 INFO Vacuumed table table=pending_closures12942026/11/10 08:17:33 INFO Vacuumed table table=pending_objects12952026/11/10 08:17:33 INFO Vacuumed table table=multipart_uploads12962026/11/10 08:17:33 INFO Vacuumed table table=closures12972026/11/10 08:17:33 INFO Vacuumed table table=objects12982026/11/10 08:17:33 INFO Aborted multipart uploads count=0 kept=012992026/11/10 08:17:33 WARN Force mode enabled - objects will be deleted immediately without grace period1300--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (8.52s)1301=== CONT TestCacheConfigHandler1302=== RUN TestCacheConfigHandler/full_config,_no_issuer1303=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1304=== RUN TestCacheConfigHandler/no_cache_url_configured1305=== PAUSE TestCacheConfigHandler/no_cache_url_configured1306=== RUN TestCacheConfigHandler/no_signing_keys1307=== PAUSE TestCacheConfigHandler/no_signing_keys1308=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1309=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1310=== CONT TestClientWithDependencies13112026/11/10 08:17:33 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=013122026/11/10 08:17:33 INFO Vacuumed table table=pending_closures13132026/11/10 08:17:33 INFO Vacuumed table table=pending_objects13142026/11/10 08:17:33 INFO Vacuumed table table=multipart_uploads13152026/11/10 08:17:33 INFO Vacuumed table table=closures13162026/11/10 08:17:33 INFO Vacuumed table table=objects1317--- PASS: TestSweepSkipsRowsLockedByPush (7.27s)1318=== CONT TestLeadEndsOnShutdown13192026/11/10 08:17:33 INFO Received uploads request method=POST path=/api/pending_closures13202026/11/10 08:17:33 INFO Received uploads request method=POST path=/api/pending_closures13212026/11/10 08:17:33 INFO Aborted multipart uploads count=0 kept=013222026/11/10 08:17:33 WARN Force mode enabled - objects will be deleted immediately without grace period13232026/11/10 08:17:33 INFO Received uploads request method=POST path=/api/pending_closures13242026/11/10 08:17:33 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."13252026/11/10 08:17:33 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."13262026/11/10 08:17:33 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)1327--- PASS: TestFailedS3DeleteKeepsTombstone (7.24s)1328=== CONT TestLeadIncumbentAnnouncesAtOnce13292026/11/10 08:17:33 INFO Uploading is73l18p776mk6jbm77mr4qwvv68wlib-shared-dep (136B)13302026/11/10 08:17:33 INFO Uploading 53vj78lfqkqkqyd5819z1gih11z9f2pa-b (256B)13312026/11/10 08:17:33 WARN Failed to register uploaded object key=53vj78lfqkqkqyd5819z1gih11z9f2pa.ls error="server returned 404: 404 page not found\n"13322026/11/10 08:17:33 WARN Failed to register uploaded object key=34q08ssiip5vd1dd3lpmngx3ks1srrda.ls error="server returned 404: 404 page not found\n"13332026/11/10 08:17:33 WARN Failed to register uploaded object key=nar/0qgxfpnkamjdvb7snbzj1hkl54wajlwy49r6vra744ky62kpcgh8.nar.zst error="server returned 404: 404 page not found\n"13342026/11/10 08:17:33 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13352026/11/10 08:17:33 INFO Received uploads request method=POST path=/api/pending_closures13362026/11/10 08:17:33 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13372026/11/10 08:17:33 WARN Failed to register uploaded object key=is73l18p776mk6jbm77mr4qwvv68wlib.ls error="server returned 404: 404 page not found\n"13382026/11/10 08:17:33 INFO Signed narinfos id=1 count=213392026/11/10 08:17:33 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13402026/11/10 08:17:33 INFO Signed narinfos id=2 count=213412026/11/10 08:17:33 INFO Uploading 4 narinfos13422026/11/10 08:17:34 WARN Failed to register uploaded object key=is73l18p776mk6jbm77mr4qwvv68wlib.narinfo error="server returned 404: 404 page not found\n"13432026/11/10 08:17:34 WARN Failed to register uploaded object key=34q08ssiip5vd1dd3lpmngx3ks1srrda.narinfo error="server returned 404: 404 page not found\n"13442026/11/10 08:17:34 WARN Failed to register uploaded object key=53vj78lfqkqkqyd5819z1gih11z9f2pa.narinfo error="server returned 404: 404 page not found\n"13452026/11/10 08:17:34 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13462026/11/10 08:17:34 WARN Failed to register uploaded object key=is73l18p776mk6jbm77mr4qwvv68wlib.narinfo error="server returned 404: 404 page not found\n"13472026/11/10 08:17:34 INFO Completed upload id=1 objects=6 duration=16.857ms13482026/11/10 08:17:34 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13492026/11/10 08:17:34 INFO Completed upload id=2 objects=6 duration=917.166µs13502026/11/10 08:17:34 INFO Upload complete. (419ms)1351=== NAME TestClientFallsBackToClosures1352 client_pushes_test.go:112: Retrieved narinfo from S3:1353 StorePath: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientFallsBackToClosures2869696228/001/store/is73l18p776mk6jbm77mr4qwvv68wlib-shared-dep1354 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1355 Compression: zstd1356 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821357 NarSize: 1361358 References: 1359 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1360 client_pushes_test.go:112: Retrieved narinfo from S3:1361 StorePath: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientFallsBackToClosures2869696228/001/store/34q08ssiip5vd1dd3lpmngx3ks1srrda-a1362 URL: nar/0qgxfpnkamjdvb7snbzj1hkl54wajlwy49r6vra744ky62kpcgh8.nar.zst1363 Compression: zstd1364 NarHash: sha256:0qgxfpnkamjdvb7snbzj1hkl54wajlwy49r6vra744ky62kpcgh81365 NarSize: 2561366 References: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientFallsBackToClosures2869696228/001/store/is73l18p776mk6jbm77mr4qwvv68wlib-shared-dep1367 CA: text:sha256:0ahg4sav81kmy7yilrrpcwhilaz54yypa0xkyqfdg7qkihcqacxd1368 client_pushes_test.go:112: Retrieved narinfo from S3:1369 StorePath: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientFallsBackToClosures2869696228/001/store/53vj78lfqkqkqyd5819z1gih11z9f2pa-b1370 URL: nar/0qgxfpnkamjdvb7snbzj1hkl54wajlwy49r6vra744ky62kpcgh8.nar.zst1371 Compression: zstd1372 NarHash: sha256:0qgxfpnkamjdvb7snbzj1hkl54wajlwy49r6vra744ky62kpcgh81373 NarSize: 2561374 References: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientFallsBackToClosures2869696228/001/store/is73l18p776mk6jbm77mr4qwvv68wlib-shared-dep1375 CA: text:sha256:0ahg4sav81kmy7yilrrpcwhilaz54yypa0xkyqfdg7qkihcqacxd1376--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (7.32s)1377=== CONT TestLeadElectsOneAndHandsOver1378--- PASS: TestClientFallsBackToClosures (8.02s)1379=== CONT TestConnectWaitsForAPeerMigration13802026/11/10 08:17:34 INFO Received push request method=POST path=/api/pushes13812026/11/10 08:17:34 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13822026/11/10 08:17:34 INFO Uploading xid9ghpkrlxb2gxcfk1sm5jazgz5kdp3-shared-dep (136B)13832026/11/10 08:17:34 INFO Uploading 4q27v8i00slaa5l1ziqcgy84qqc1d86d-b (256B)1384=== NAME TestPinProtectsFromGC1385 client_integration_test.go:778: Pinned store path: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestPinProtectsFromGC3721609482/001/store/45ncb1pgdjpf41c7nbyrgj7fy3m5xb3n-pinned-file.txt1386 client_integration_test.go:779: Unpinned store path: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestPinProtectsFromGC3721609482/001/store/y5h5xv7ba9whc9fmxz406ifa0zv7kqyl-unpinned-file.txt1387--- PASS: TestService_Rustfstest (7.34s)1388=== CONT TestResolveDBConnectionString13892026/11/10 08:17:34 WARN Failed to register uploaded object key=xid9ghpkrlxb2gxcfk1sm5jazgz5kdp3.ls error="server returned 404: 404 page not found\n"13902026/11/10 08:17:34 WARN Failed to register uploaded object key=1qqd9d4yqb6gva4w7463j60k0a7yrlxd.ls error="server returned 404: 404 page not found\n"1391=== RUN TestResolveDBConnectionString/flag_wins1392=== PAUSE TestResolveDBConnectionString/flag_wins1393=== RUN TestResolveDBConnectionString/file_when_flag_empty1394=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1395=== RUN TestResolveDBConnectionString/missing_file_is_an_error1396=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1397=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1398=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1399=== RUN TestResolveDBConnectionString/nothing_configured1400=== PAUSE TestResolveDBConnectionString/nothing_configured1401=== CONT TestReadProxyOutlastsServerWriteTimeout14022026/11/10 08:17:34 WARN Failed to register uploaded object key=nar/0r21f6hc2bihhncpiz5v9rsc0gmj8wkfq4jpscplda09dv6g5jmx.nar.zst error="server returned 404: 404 page not found\n"14032026/11/10 08:17:34 WARN Failed to register uploaded object key=4q27v8i00slaa5l1ziqcgy84qqc1d86d.ls error="server returned 404: 404 page not found\n"14042026/11/10 08:17:34 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14052026/11/10 08:17:34 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14062026/11/10 08:17:34 INFO Signed narinfos id=1 count=314072026/11/10 08:17:34 INFO Uploading 3 narinfos14082026/11/10 08:17:34 WARN Failed to register uploaded object key=4q27v8i00slaa5l1ziqcgy84qqc1d86d.narinfo error="server returned 404: 404 page not found\n"14092026/11/10 08:17:34 WARN Failed to register uploaded object key=1qqd9d4yqb6gva4w7463j60k0a7yrlxd.narinfo error="server returned 404: 404 page not found\n"14102026/11/10 08:17:34 INFO Received push request method=POST path=/api/pushes14112026/11/10 08:17:34 INFO Received complete push request method=POST path=/api/pushes/1/complete14122026/11/10 08:17:34 WARN Failed to register uploaded object key=xid9ghpkrlxb2gxcfk1sm5jazgz5kdp3.narinfo error="server returned 404: 404 page not found\n"14132026/11/10 08:17:34 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14142026/11/10 08:17:34 INFO Uploading 45ncb1pgdjpf41c7nbyrgj7fy3m5xb3n-pinned-file.txt (128B)14152026/11/10 08:17:34 INFO Completed push id=1 objects=8 duration=40.176792ms14162026/11/10 08:17:34 INFO Upload complete. (295ms)1417=== NAME TestClientPushesUseOnePush1418 client_pushes_test.go:97: Retrieved narinfo from S3:1419 StorePath: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientPushesUseOnePush2119992367/001/store/xid9ghpkrlxb2gxcfk1sm5jazgz5kdp3-shared-dep1420 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1421 Compression: zstd1422 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821423 NarSize: 1361424 References: 1425 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1426 client_pushes_test.go:97: Retrieved narinfo from S3:1427 StorePath: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientPushesUseOnePush2119992367/001/store/1qqd9d4yqb6gva4w7463j60k0a7yrlxd-a1428 URL: nar/0r21f6hc2bihhncpiz5v9rsc0gmj8wkfq4jpscplda09dv6g5jmx.nar.zst1429 Compression: zstd1430 NarHash: sha256:0r21f6hc2bihhncpiz5v9rsc0gmj8wkfq4jpscplda09dv6g5jmx1431 NarSize: 2561432 References: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientPushesUseOnePush2119992367/001/store/xid9ghpkrlxb2gxcfk1sm5jazgz5kdp3-shared-dep1433 CA: text:sha256:1wwmgkcyghmk4836wrw6n9qzlfz7sy0nnyr1db3nkbkjkjpl78ma1434 client_pushes_test.go:97: Retrieved narinfo from S3:1435 StorePath: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientPushesUseOnePush2119992367/001/store/4q27v8i00slaa5l1ziqcgy84qqc1d86d-b1436 URL: nar/0r21f6hc2bihhncpiz5v9rsc0gmj8wkfq4jpscplda09dv6g5jmx.nar.zst1437 Compression: zstd1438 NarHash: sha256:0r21f6hc2bihhncpiz5v9rsc0gmj8wkfq4jpscplda09dv6g5jmx1439 NarSize: 2561440 References: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientPushesUseOnePush2119992367/001/store/xid9ghpkrlxb2gxcfk1sm5jazgz5kdp3-shared-dep1441 CA: text:sha256:1wwmgkcyghmk4836wrw6n9qzlfz7sy0nnyr1db3nkbkjkjpl78ma14422026/11/10 08:17:35 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14432026/11/10 08:17:35 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14442026/11/10 08:17:35 WARN Failed to register uploaded object key=45ncb1pgdjpf41c7nbyrgj7fy3m5xb3n.ls error="server returned 404: 404 page not found\n"14452026/11/10 08:17:35 INFO Signed narinfos id=1 count=114462026/11/10 08:17:35 INFO Uploading 1 narinfos14472026/11/10 08:17:35 INFO Received complete push request method=POST path=/api/pushes/1/complete14482026/11/10 08:17:35 WARN Failed to register uploaded object key=45ncb1pgdjpf41c7nbyrgj7fy3m5xb3n.narinfo error="server returned 404: 404 page not found\n"1449--- PASS: TestClientPushesUseOnePush (8.02s)1450=== CONT TestReadRedirectNar14512026/11/10 08:17:35 INFO Received uploads request method=POST path=/api/pending_closures14522026/11/10 08:17:35 INFO Completed push id=1 objects=3 duration=37.443708ms14532026/11/10 08:17:35 INFO Upload complete. (287ms)14542026/11/10 08:17:35 INFO Received push request method=POST path=/api/pushes14552026/11/10 08:17:35 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14562026/11/10 08:17:35 INFO Uploading y5h5xv7ba9whc9fmxz406ifa0zv7kqyl-unpinned-file.txt (128B)14572026/11/10 08:17:35 WARN Failed to register uploaded object key=y5h5xv7ba9whc9fmxz406ifa0zv7kqyl.ls error="server returned 404: 404 page not found\n"14582026/11/10 08:17:35 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign14592026/11/10 08:17:35 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"14602026/11/10 08:17:35 INFO Signed narinfos id=2 count=114612026/11/10 08:17:35 INFO Uploading 1 narinfos14622026/11/10 08:17:35 INFO Received complete push request method=POST path=/api/pushes/2/complete14632026/11/10 08:17:35 WARN Failed to register uploaded object key=y5h5xv7ba9whc9fmxz406ifa0zv7kqyl.narinfo error="server returned 404: 404 page not found\n"14642026/11/10 08:17:35 INFO Completed push id=2 objects=3 duration=972.167µs14652026/11/10 08:17:35 INFO Upload complete. (192ms)14662026/11/10 08:17:35 INFO Starting cleanup of old closures method=DELETE path=/api/closures14672026/11/10 08:17:35 INFO Garbage collection started14682026/11/10 08:17:35 INFO Received uploads request method=POST path=/api/pending_closures14692026/11/10 08:17:35 INFO Aborted multipart uploads count=0 kept=014702026/11/10 08:17:35 WARN Force mode enabled - objects will be deleted immediately without grace period14712026/11/10 08:17:35 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1472--- PASS: TestTombstonedObjectOfferedWithoutWaiting (7.19s)1473=== CONT TestReadProxyDisabled1474=== NAME TestOrphanedObjectsGCStressTest1475 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1476 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion14772026/11/10 08:17:35 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=014782026/11/10 08:17:35 INFO Vacuumed table table=pending_closures14792026/11/10 08:17:35 INFO Aborted multipart uploads count=0 kept=014802026/11/10 08:17:35 WARN Force mode enabled - objects will be deleted immediately without grace period14812026/11/10 08:17:35 INFO Vacuumed table table=pending_objects14822026/11/10 08:17:36 INFO Vacuumed table table=multipart_uploads14832026/11/10 08:17:36 INFO Vacuumed table table=closures14842026/11/10 08:17:36 INFO Vacuumed table table=objects14852026/11/10 08:17:36 INFO Received uploads request method=POST path=/api/pending_closures14862026/11/10 08:17:36 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=014872026/11/10 08:17:36 INFO Vacuumed table table=pending_closures14882026/11/10 08:17:36 INFO Vacuumed table table=pending_objects14892026/11/10 08:17:36 INFO Vacuumed table table=multipart_uploads14902026/11/10 08:17:36 INFO Vacuumed table table=closures14912026/11/10 08:17:36 INFO Received uploads request method=POST path=/api/pending_closures14922026/11/10 08:17:36 INFO Vacuumed table table=objects1493--- PASS: TestGCSweepDeliversEachKeyOnce (8.37s)1494=== CONT TestService_RequireScope_OIDC1495--- PASS: TestDeduplicatedObjectsRecordedAsPending (7.78s)1496=== CONT TestReadProxyRootRedirectsToIndexHTML14972026/11/10 08:17:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61213/oidc14982026/11/10 08:17:36 INFO Received uploads request method=POST path=/api/pending_closures14992026/11/10 08:17:37 INFO Aborted multipart uploads count=0 kept=015002026/11/10 08:17:37 WARN Force mode enabled - objects will be deleted immediately without grace period15012026/11/10 08:17:37 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=015022026/11/10 08:17:37 INFO Vacuumed table table=pending_closures15032026/11/10 08:17:37 INFO Vacuumed table table=pending_objects15042026/11/10 08:17:37 INFO Vacuumed table table=multipart_uploads15052026/11/10 08:17:37 INFO Vacuumed table table=closures15062026/11/10 08:17:37 INFO Vacuumed table table=objects15072026/11/10 08:17:37 INFO Received uploads request method=POST path=/api/pending_closures1508--- PASS: TestGCSweepSkipsPendingObjects (8.44s)1509=== CONT TestService_AuthMiddleware_OIDC15102026/11/10 08:17:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61223/oidc15112026/11/10 08:17:37 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=015122026/11/10 08:17:37 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst15132026/11/10 08:17:37 INFO Received uploads request method=POST path=/api/pending_closures15142026/11/10 08:17:37 INFO Received create pin request method=POST path=/api/pins/myapp1515--- PASS: TestPresignedUploadRegisteredBeforeCommit (8.02s)1516=== CONT TestReadProxyConditionalGet15172026/11/10 08:17:37 INFO Created/updated pin name=myapp store_path=/private/var/tb/6/scratch/e12f70b2f235e287/build/TestPinProtectsFromGC3721609482/001/store/45ncb1pgdjpf41c7nbyrgj7fy3m5xb3n-pinned-file.txt narinfo_key=45ncb1pgdjpf41c7nbyrgj7fy3m5xb3n.narinfo15182026/11/10 08:17:37 INFO Starting cleanup of old closures method=DELETE path=/api/closures15192026/11/10 08:17:37 INFO Garbage collection started15202026/11/10 08:17:37 INFO Aborted multipart uploads count=0 kept=015212026/11/10 08:17:37 WARN Force mode enabled - objects will be deleted immediately without grace period15222026/11/10 08:17:37 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=015232026/11/10 08:17:37 INFO Vacuumed table table=pending_closures15242026/11/10 08:17:37 INFO Vacuumed table table=pending_objects15252026/11/10 08:17:37 INFO Vacuumed table table=multipart_uploads15262026/11/10 08:17:37 INFO Vacuumed table table=closures15272026/11/10 08:17:37 INFO Vacuumed table table=objects15282026/11/10 08:17:37 INFO Received uploads request method=POST path=/api/pending_closures15292026/11/10 08:17:38 INFO Aborted multipart uploads count=0 kept=01530--- PASS: TestReadProxyRangeRequest (6.97s)1531=== CONT TestService_ReadAuthMiddleware15322026/11/10 08:17:38 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=015332026/11/10 08:17:38 INFO Vacuumed table table=pending_closures1534--- PASS: TestDeleteClosuresRacingPins (12.58s)1535=== CONT TestService_AuthMiddleware_MTLSBoundSubjects15362026/11/10 08:17:38 INFO Vacuumed table table=pending_objects15372026/11/10 08:17:38 INFO Vacuumed table table=multipart_uploads15382026/11/10 08:17:38 INFO Vacuumed table table=closures15392026/11/10 08:17:38 INFO Vacuumed table table=objects15402026/11/10 08:17:38 INFO Aborted multipart uploads count=0 kept=015412026/11/10 08:17:38 WARN Force mode enabled - objects will be deleted immediately without grace period15422026/11/10 08:17:38 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=015432026/11/10 08:17:38 INFO Vacuumed table table=pending_closures15442026/11/10 08:17:38 INFO Vacuumed table table=pending_objects15452026/11/10 08:17:38 INFO Vacuumed table table=multipart_uploads15462026/11/10 08:17:38 INFO Vacuumed table table=closures15472026/11/10 08:17:38 INFO Vacuumed table table=objects1548--- PASS: TestPushDedupSurvivesConcurrentGC (7.97s)1549=== CONT TestService_AuthMiddleware_MTLSProxyHeader15502026/11/10 08:17:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15512026/11/10 08:17:38 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NDE3MDRhN2YtZTZiZC00NWQ5LThkZDEtZDdkZjI1MzM5MThmLjY4MTU3YjRjLTcyNjUtNDk2Ny04MGUxLWNhMTA4MDY4NTg2NHgxNzk0Mjk4NjU2MTgwOTI5MDAw parts=1215522026/11/10 08:17:38 INFO Received uploads request method=POST path=/api/pending_closures1553--- PASS: TestCompletedNarNotReofferedAcrossClosures (9.98s)1554=== CONT TestService_AuthMiddleware1555--- PASS: TestGCBugBareHashReferences (7.08s)1556=== CONT TestCompleteMultipartUpload_ErrorButObjectExists15572026/11/10 08:17:38 INFO Aborted multipart uploads count=0 kept=015582026/11/10 08:17:38 WARN Force mode enabled - objects will be deleted immediately without grace period15592026/11/10 08:17:38 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=015602026/11/10 08:17:38 INFO Vacuumed table table=pending_closures15612026/11/10 08:17:38 INFO Vacuumed table table=pending_objects15622026/11/10 08:17:38 INFO Vacuumed table table=multipart_uploads15632026/11/10 08:17:38 INFO Vacuumed table table=closures15642026/11/10 08:17:38 INFO Vacuumed table table=objects1565--- PASS: TestGCMetrics (7.41s)1566=== CONT TestClientCADerivations15672026/11/10 08:17:39 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld6 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1568--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (7.16s)1569=== CONT TestReadProxy40415702026/11/10 08:17:39 WARN Rate limiter enabled after throttle name=s3-test rate=515712026/11/10 08:17:39 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1572=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1573 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101574 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001575--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (11.65s)1576=== CONT TestReadProxyHead1577=== NAME TestPinProtectsFromGC1578 client_integration_test.go:887: Pin successfully protected closure from garbage collection1579--- PASS: TestPinProtectsFromGC (12.15s)1580=== CONT TestReadProxyInvalidPath1581--- PASS: TestService_ReadScope_PublicByDefault (7.41s)1582=== CONT TestClientMultipleUploads15832026/11/10 08:17:39 INFO Received push request method=POST path=/api/pushes15842026/11/10 08:17:39 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)15852026/11/10 08:17:39 INFO Uploading akn1y41f7sgba7iy3s7s46fz5fmd8d0w-top (264B)15862026/11/10 08:17:39 INFO Uploading j1r78xhd0jxsvplq3ig24m5w4l6vgvsd-shared-dep (136B)15872026/11/10 08:17:40 WARN Failed to register uploaded object key=akn1y41f7sgba7iy3s7s46fz5fmd8d0w.ls error="server returned 404: 404 page not found\n"15882026/11/10 08:17:40 WARN Failed to register uploaded object key=nar/0csf80kx387gqx3yffnwy1cnk9dg9czsingg0vrva03v4wf6b3v6.nar.zst error="server returned 404: 404 page not found\n"15892026/11/10 08:17:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15902026/11/10 08:17:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15912026/11/10 08:17:40 WARN Failed to register uploaded object key=j1r78xhd0jxsvplq3ig24m5w4l6vgvsd.ls error="server returned 404: 404 page not found\n"15922026/11/10 08:17:40 INFO Signed narinfos id=1 count=215932026/11/10 08:17:40 INFO Uploading 2 narinfos15942026/11/10 08:17:40 INFO Received complete push request method=POST path=/api/pushes/1/complete15952026/11/10 08:17:40 WARN Failed to register uploaded object key=j1r78xhd0jxsvplq3ig24m5w4l6vgvsd.narinfo error="server returned 404: 404 page not found\n"15962026/11/10 08:17:40 WARN Failed to register uploaded object key=akn1y41f7sgba7iy3s7s46fz5fmd8d0w.narinfo error="server returned 404: 404 page not found\n"15972026/11/10 08:17:40 INFO Completed push id=1 objects=6 duration=80.578417ms15982026/11/10 08:17:40 INFO Upload complete. (337ms)1599=== NAME TestClientSharedPathCommittedMidPush1600 client_integration_test.go:727: Retrieved narinfo from S3:1601 StorePath: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientSharedPathCommittedMidPush3669760757/001/store/j1r78xhd0jxsvplq3ig24m5w4l6vgvsd-shared-dep1602 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1603 Compression: zstd1604 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821605 NarSize: 1361606 References: 1607 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1608 client_integration_test.go:727: Retrieved narinfo from S3:1609 StorePath: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientSharedPathCommittedMidPush3669760757/001/store/akn1y41f7sgba7iy3s7s46fz5fmd8d0w-top1610 URL: nar/0csf80kx387gqx3yffnwy1cnk9dg9czsingg0vrva03v4wf6b3v6.nar.zst1611 Compression: zstd1612 NarHash: sha256:0csf80kx387gqx3yffnwy1cnk9dg9czsingg0vrva03v4wf6b3v61613 NarSize: 2641614 References: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientSharedPathCommittedMidPush3669760757/001/store/j1r78xhd0jxsvplq3ig24m5w4l6vgvsd-shared-dep1615 CA: text:sha256:0pyvmsnc18bh3dn53ivwcgwzbccjgpwslbhzkly7wk31y6qky4g71616--- PASS: TestClientSharedPathCommittedMidPush (8.11s)1617=== CONT TestClientIntegration16182026/11/10 08:17:40 INFO lead: acquired remote=192.0.2.1:12341619=== NAME TestClientWithDependencies1620 client_integration_test.go:660: Built derivation: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientWithDependencies2511658631/001/store/qzvjcjl46rh8fcl29md9myqxv0fz8fr9-test-script1621 client_integration_test.go:662: Found 1 dependencies (including self)16222026/11/10 08:17:40 INFO lead: acquired remote=192.0.2.1:123416232026/11/10 08:17:40 INFO Received push request method=POST path=/api/pushes16242026/11/10 08:17:40 INFO lead: released remote=192.0.2.1:12341625--- PASS: TestLeadIncumbentAnnouncesAtOnce (6.90s)1626=== CONT TestReadProxyNarStreaming16272026/11/10 08:17:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16282026/11/10 08:17:40 INFO Uploading qzvjcjl46rh8fcl29md9myqxv0fz8fr9-test-script (136B)16292026/11/10 08:17:40 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"16302026/11/10 08:17:40 WARN Failed to register uploaded object key=qzvjcjl46rh8fcl29md9myqxv0fz8fr9.ls error="server returned 404: 404 page not found\n"16312026/11/10 08:17:40 WARN Failed to register uploaded object key=log/wxbkj32c541p9kzdkx90s1z9kiaf3hbr-test-script.drv error="server returned 404: 404 page not found\n"16322026/11/10 08:17:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16332026/11/10 08:17:40 INFO Signed narinfos id=1 count=116342026/11/10 08:17:40 INFO Uploading 1 narinfos16352026/11/10 08:17:40 INFO Received complete push request method=POST path=/api/pushes/1/complete16362026/11/10 08:17:40 WARN Failed to register uploaded object key=qzvjcjl46rh8fcl29md9myqxv0fz8fr9.narinfo error="server returned 404: 404 page not found\n"16372026/11/10 08:17:40 INFO Completed push id=1 objects=4 duration=26.07075ms16382026/11/10 08:17:40 INFO Upload complete. (290ms)1639=== NAME TestClientWithDependencies1640 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientWithDependencies2511658631/001/store) requires matching store prefix1641--- PASS: TestClientWithDependencies (7.90s)1642=== CONT TestReadProxyContentNegotiation16432026/11/10 08:17:41 INFO lead: acquired remote=192.0.2.1:123416442026/11/10 08:17:41 INFO lead: released remote=192.0.2.1:12341645--- PASS: TestLeadEndsOnShutdown (8.06s)1646=== CONT TestSharedNarBothUploadsComplete1647--- PASS: TestReadRedirectNar (6.90s)1648=== CONT TestClientErrorHandling1649=== RUN TestClientErrorHandling/InvalidStorePath1650=== PAUSE TestClientErrorHandling/InvalidStorePath1651=== RUN TestClientErrorHandling/InvalidAuthToken1652=== PAUSE TestClientErrorHandling/InvalidAuthToken1653=== RUN TestClientErrorHandling/ServerNotAvailable1654=== PAUSE TestClientErrorHandling/ServerNotAvailable1655=== CONT TestCacheStatsHandler16562026/11/10 08:17:42 INFO lead: released remote=192.0.2.1:12341657--- PASS: TestReadProxyDisabled (6.79s)1658=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale16592026/11/10 08:17:42 INFO lead: acquired remote=192.0.2.1:12341660--- PASS: TestConnectWaitsForAPeerMigration (8.35s)1661=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1662--- PASS: TestReadProxyRootRedirectsToIndexHTML (6.08s)1663=== CONT TestServerTLSConfig/no_client_CA1664=== CONT TestServerTLSConfig/not_a_PEM_file1665=== CONT TestServerTLSConfig/missing_CA_file1666--- PASS: TestServerTLSConfig (0.00s)1667 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1668 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.01s)1669 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1670=== CONT TestIsValidCachePath/narinfo1671=== CONT TestIsValidCachePath/index.html1672=== CONT TestIsValidCachePath/short_hash1673=== CONT TestIsValidCachePath/wrong_extension1674=== CONT TestIsValidCachePath/leading_slash1675=== CONT TestIsValidCachePath/empty1676=== CONT TestIsValidCachePath/random_path1677=== CONT TestIsValidCachePath/invalid_char_u1678=== CONT TestIsValidCachePath/invalid_char_e1679=== CONT TestIsValidCachePath/traversal_in_middle1680=== CONT TestIsValidCachePath/traversal_parent1681=== CONT TestIsValidCachePath/nar_uncompressed1682=== CONT TestIsValidCachePath/nix-cache-info1683=== CONT TestIsValidCachePath/realisation1684=== CONT TestIsValidCachePath/log1685=== CONT TestIsValidCachePath/ls1686=== CONT TestIsValidCachePath/nar_xz1687=== CONT TestIsValidCachePath/nar_bz21688=== CONT TestIsValidCachePath/nar_zst1689=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1690--- PASS: TestIsValidCachePath (0.01s)1691 --- PASS: TestIsValidCachePath/narinfo (0.00s)1692 --- PASS: TestIsValidCachePath/index.html (0.00s)1693 --- PASS: TestIsValidCachePath/short_hash (0.00s)1694 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1695 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1696 --- PASS: TestIsValidCachePath/empty (0.00s)1697 --- PASS: TestIsValidCachePath/random_path (0.00s)1698 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1699 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1700 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1701 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1702 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1703 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1704 --- PASS: TestIsValidCachePath/realisation (0.00s)1705 --- PASS: TestIsValidCachePath/log (0.00s)1706 --- PASS: TestIsValidCachePath/ls (0.00s)1707 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1708 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1709 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1710 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1711=== CONT TestParseSingleRange/none1712=== CONT TestParseSingleRange/open-ended1713=== CONT TestParseSingleRange/start_far_past_EOF1714=== CONT TestParseSingleRange/start_past_EOF1715=== CONT TestParseSingleRange/single_byte1716=== CONT TestParseSingleRange/suffix_exceeds_size1717=== CONT TestParseSingleRange/suffix1718=== CONT TestParseSingleRange/end_clamped_to_size1719=== CONT TestParseSingleRange/malformed_both_empty1720=== CONT TestParseSingleRange/closed1721=== CONT TestParseSingleRange/malformed_end_before_start1722=== CONT TestParseSingleRange/multi-range_ignored1723=== CONT TestParseSingleRange/malformed_no_dash1724=== CONT TestParseSingleRange/unknown_unit1725--- PASS: TestParseSingleRange (0.01s)1726 --- PASS: TestParseSingleRange/none (0.00s)1727 --- PASS: TestParseSingleRange/open-ended (0.00s)1728 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1729 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1730 --- PASS: TestParseSingleRange/single_byte (0.00s)1731 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1732 --- PASS: TestParseSingleRange/suffix (0.00s)1733 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1734 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1735 --- PASS: TestParseSingleRange/closed (0.00s)1736 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1737 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1738 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1739 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1740=== CONT TestPush_RejectsBadRequests/no_objects17412026/11/10 08:17:42 INFO Received push request method=POST path=/api/pushes1742=== CONT TestPush_RejectsBadRequests/root_not_in_objects17432026/11/10 08:17:42 INFO Received push request method=POST path=/api/pushes1744=== CONT TestPush_RejectsBadRequests/no_roots17452026/11/10 08:17:42 INFO Received push request method=POST path=/api/pushes1746=== CONT TestPush_RejectsBadRequests/bad_root17472026/11/10 08:17:42 INFO Received push request method=POST path=/api/pushes1748--- PASS: TestPush_RejectsBadRequests (2.21s)1749 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1750 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1751 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1752 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1753=== CONT TestGCEndsOnShutdown/before_the_run1754=== RUN TestService_RequireScope_OIDC/builder_may_write1755=== PAUSE TestService_RequireScope_OIDC/builder_may_write1756=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1757=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1758=== RUN TestService_RequireScope_OIDC/ops_may_admin1759=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1760=== RUN TestService_RequireScope_OIDC/ops_may_not_write1761=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1762=== RUN TestService_RequireScope_OIDC/reader_may_not_write1763=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1764=== RUN TestService_RequireScope_OIDC/static_token_may_admin1765=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1766=== RUN TestService_RequireScope_OIDC/static_token_may_write1767=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1768=== RUN TestService_RequireScope_OIDC/reader_may_read1769=== PAUSE TestService_RequireScope_OIDC/reader_may_read1770=== RUN TestService_RequireScope_OIDC/writer_implies_read1771=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1772=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1773=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1774=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1775=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1776=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1777=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1778=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1779=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1780=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1781=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1782=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark17832026/11/10 08:17:43 INFO lead: released remote=192.0.2.1:12341784--- PASS: TestLeadElectsOneAndHandsOver (9.22s)1785=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1786--- PASS: TestReadProxyConditionalGet (6.02s)1787=== CONT TestProxyWriteTimeout/narinfo1788=== CONT TestProxyWriteTimeout/10_GiB_nar1789=== CONT TestProxyWriteTimeout/unknown_size1790=== CONT TestProxyWriteTimeout/1_GiB_nar1791--- PASS: TestProxyWriteTimeout (0.00s)1792 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1793 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1794 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1795 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1796=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1797=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1798=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1799=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1800=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1801=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1802=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1803=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1804=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1805=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1806--- PASS: TestService_ReadAuthMiddleware (6.10s)1807=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost18082026/11/10 08:17:44 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"18092026/11/10 08:17:44 WARN mTLS auth: bound subjects configured but subject DN unavailable18102026/11/10 08:17:44 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1811--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (6.43s)1812=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1813--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (6.63s)1814=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed18152026/11/10 08:17:45 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1816--- PASS: TestService_AuthMiddleware (6.82s)1817=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18182026/11/10 08:17:45 INFO Received uploads request method=POST path=/18192026/11/10 08:17:45 INFO Received uploads request method=POST path=/api/pending_closures1820=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18212026/11/10 08:17:45 INFO Received request for more parts method=POST path=/1822=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18232026/11/10 08:17:45 INFO Received complete multipart upload request method=POST path=/1824--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)1825 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.30s)1826 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1827 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1828=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info18292026/11/10 08:17:45 INFO Received uploads request method=POST path=/1830=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key18312026/11/10 08:17:45 INFO Received complete multipart upload request method=POST path=/1832=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key18332026/11/10 08:17:45 INFO Received request for more parts method=POST path=/1834=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal18352026/11/10 08:17:45 INFO Received uploads request method=POST path=/1836--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1837 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1838 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1839 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1840 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1841=== CONT TestIsValidUploadKey/narinfo1842=== CONT TestPendingClosureWriteTimeout/empty1843=== CONT TestIsValidUploadKey/unknown_type1844=== CONT TestIsValidUploadKey/empty_key1845=== CONT TestIsValidUploadKey/absolute1846=== CONT TestIsValidUploadKey/traversal_nar1847=== CONT TestIsValidUploadKey/traversal1848=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1849=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1850=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1851=== CONT TestIsValidUploadKey/index.html1852=== CONT TestIsValidUploadKey/nix-cache-info1853=== CONT TestIsValidUploadKey/realisation_plus_in_output1854=== CONT TestIsValidUploadKey/realisation1855=== CONT TestIsValidUploadKey/build_log_equals1856=== CONT TestIsValidUploadKey/build_log_question_mark1857=== CONT TestIsValidUploadKey/build_log_plus_in_name1858=== CONT TestIsValidUploadKey/build_log_home-manager_file1859=== CONT TestIsValidUploadKey/build_log1860=== CONT TestIsValidUploadKey/listing1861=== CONT TestIsValidUploadKey/nar_plain1862=== CONT TestIsValidUploadKey/nar_xz1863=== CONT TestIsValidUploadKey/nar_zst1864--- PASS: TestIsValidUploadKey (0.00s)1865 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1866 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1867 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1868 --- PASS: TestIsValidUploadKey/absolute (0.00s)1869 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1870 --- PASS: TestIsValidUploadKey/traversal (0.00s)1871 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1872 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1873 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1874 --- PASS: TestIsValidUploadKey/index.html (0.00s)1875 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1876 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1877 --- PASS: TestIsValidUploadKey/realisation (0.00s)1878 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1879 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1880 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1881 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1882 --- PASS: TestIsValidUploadKey/build_log (0.00s)1883 --- PASS: TestIsValidUploadKey/listing (0.00s)1884 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1885 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1886 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1887=== CONT TestPendingClosureWriteTimeout/670k_objects1888=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1889--- PASS: TestReadProxyOutlastsServerWriteTimeout (10.98s)1890=== CONT TestPendingClosureWriteTimeout/400_objects1891=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows18922026/11/10 08:17:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18932026/11/10 08:17:45 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NDE3MDRhN2YtZTZiZC00NWQ5LThkZDEtZDdkZjI1MzM5MThmLmNjYzg1ODQ1LWQ2M2MtNDY4Yy1iY2Q0LWVjYzE2YjcyYzhkMngxNzk0Mjk4NjY1NjIwMTMzMDAw18942026/11/10 08:17:45 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NDE3MDRhN2YtZTZiZC00NWQ5LThkZDEtZDdkZjI1MzM5MThmLmNjYzg1ODQ1LWQ2M2MtNDY4Yy1iY2Q0LWVjYzE2YjcyYzhkMngxNzk0Mjk4NjY1NjIwMTMzMDAw parts=11895--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (7.32s)1896=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1897--- PASS: TestReadProxyHead (7.10s)1898=== CONT TestCacheConfigHandler/full_config,_no_issuer1899=== CONT TestCacheConfigHandler/no_signing_keys1900=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1901=== CONT TestCacheConfigHandler/no_cache_url_configured1902--- PASS: TestCacheConfigHandler (0.01s)1903 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1904 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1905 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1906 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1907=== CONT TestResolveDBConnectionString/flag_wins1908=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1909=== CONT TestResolveDBConnectionString/nothing_configured1910=== CONT TestResolveDBConnectionString/missing_file_is_an_error1911=== CONT TestResolveDBConnectionString/file_when_flag_empty1912=== CONT TestClientErrorHandling/InvalidStorePath1913--- PASS: TestResolveDBConnectionString (0.02s)1914 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1915 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1916 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1917 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1918 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1919=== NAME TestClientCADerivations1920 client_ca_test.go:136: Built CA derivation: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientCADerivations4027855819/001/store/8jzmrwwdhk4fi89y2rb8b9b3i0vdbn7i-ca-test1921 client_ca_test.go:139: Found 1 dependencies (including self)19222026/11/10 08:17:46 INFO Received push request method=POST path=/api/pushes19232026/11/10 08:17:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19242026/11/10 08:17:46 INFO Uploading 8jzmrwwdhk4fi89y2rb8b9b3i0vdbn7i-ca-test (144B)19252026/11/10 08:17:46 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"19262026/11/10 08:17:46 WARN Failed to register uploaded object key=8jzmrwwdhk4fi89y2rb8b9b3i0vdbn7i.ls error="server returned 404: 404 page not found\n"19272026/11/10 08:17:46 WARN Failed to register uploaded object key=log/wdrv0p528fjrma715wxrnspiyxjrp4qd-ca-test.drv error="server returned 404: 404 page not found\n"19282026/11/10 08:17:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19292026/11/10 08:17:46 INFO Signed narinfos id=1 count=119302026/11/10 08:17:46 INFO Uploading 1 narinfos19312026/11/10 08:17:46 INFO Received complete push request method=POST path=/api/pushes/1/complete19322026/11/10 08:17:46 WARN Failed to register uploaded object key=8jzmrwwdhk4fi89y2rb8b9b3i0vdbn7i.narinfo error="server returned 404: 404 page not found\n"19332026/11/10 08:17:47 INFO Completed push id=1 objects=4 duration=22.748625ms19342026/11/10 08:17:47 INFO Upload complete. (393ms)1935 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientCADerivations4027855819/001/store/8jzmrwwdhk4fi89y2rb8b9b3i0vdbn7i-ca-test1936 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1937 Compression: zstd1938 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1939 NarSize: 1441940 References: 1941 Deriver: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientCADerivations4027855819/001/store/wdrv0p528fjrma715wxrnspiyxjrp4qd-ca-test.drv1942 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1943 client_ca_test.go:185: Checking for realisation files in S3...1944 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1945 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1946--- PASS: TestReadProxy404 (8.14s)1947=== CONT TestClientErrorHandling/ServerNotAvailable1948=== NAME TestClientCADerivations1949 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket82?endpoint=http://localhost:60839®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientCADerivations4027855819/001/store'1950 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11951--- PASS: TestReadProxyInvalidPath (7.68s)1952=== CONT TestClientErrorHandling/InvalidAuthToken1953=== NAME TestClientMultipleUploads1954 client_integration_test.go:405: Created store path 0: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientMultipleUploads1839851518/001/store/6lf51kkpnb7n2rhphhscfqzscw0vrcvd-test-file-0.txt1955--- PASS: TestClientCADerivations (8.55s)1956=== CONT TestService_RequireScope_OIDC/builder_may_write1957=== CONT TestService_RequireScope_OIDC/reader_may_read1958=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1959=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19602026/11/10 08:17:47 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]1961=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1962=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1963=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1964=== CONT TestService_RequireScope_OIDC/writer_implies_read1965=== CONT TestService_RequireScope_OIDC/reader_may_not_write1966=== CONT TestService_RequireScope_OIDC/static_token_may_write1967=== CONT TestService_RequireScope_OIDC/static_token_may_admin1968=== CONT TestService_RequireScope_OIDC/ops_may_admin1969=== CONT TestService_RequireScope_OIDC/ops_may_not_write1970=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1971=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1972=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19732026/11/10 08:17:47 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]1974=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1975=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1976--- PASS: TestService_RequireScope_OIDC (6.44s)1977 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1978 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1979 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1980 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.01s)1981 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1982 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1983 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1984 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1985 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1986 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1987 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1988 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1989 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1990 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)19912026/11/10 08:17:47 WARN Authentication failed token_preview=eyJhbGciOi...HcmdEfntJQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1992--- PASS: TestService_AuthMiddleware_OIDC (6.53s)1993 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1994 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1995 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1996 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)1997=== NAME TestClientMultipleUploads1998 client_integration_test.go:405: Created store path 1: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientMultipleUploads1839851518/001/store/4jf49f11f2zccbb4f6nqcky5b67ywrhp-test-file-1.txt1999 client_integration_test.go:405: Created store path 2: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientMultipleUploads1839851518/001/store/bpsfywpyhrqzr9q66yzkg96kcv3j275k-test-file-2.txt20002026/11/10 08:17:47 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20012026/11/10 08:17:47 WARN Request failed, retrying attempt=2 backoff=187.490292ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20022026/11/10 08:17:47 INFO Received push request method=POST path=/api/pushes20032026/11/10 08:17:47 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)20042026/11/10 08:17:47 INFO Uploading 4jf49f11f2zccbb4f6nqcky5b67ywrhp-test-file-1.txt (160B)20052026/11/10 08:17:47 INFO Uploading 6lf51kkpnb7n2rhphhscfqzscw0vrcvd-test-file-0.txt (160B)20062026/11/10 08:17:47 INFO Uploading bpsfywpyhrqzr9q66yzkg96kcv3j275k-test-file-2.txt (160B)20072026/11/10 08:17:47 WARN Failed to register uploaded object key=6lf51kkpnb7n2rhphhscfqzscw0vrcvd.ls error="server returned 404: 404 page not found\n"20082026/11/10 08:17:47 WARN Failed to register uploaded object key=bpsfywpyhrqzr9q66yzkg96kcv3j275k.ls error="server returned 404: 404 page not found\n"20092026/11/10 08:17:47 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"20102026/11/10 08:17:47 WARN Failed to register uploaded object key=4jf49f11f2zccbb4f6nqcky5b67ywrhp.ls error="server returned 404: 404 page not found\n"20112026/11/10 08:17:47 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"20122026/11/10 08:17:47 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"20132026/11/10 08:17:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20142026/11/10 08:17:47 INFO Signed narinfos id=1 count=320152026/11/10 08:17:47 INFO Uploading 3 narinfos20162026/11/10 08:17:47 WARN Request failed, retrying attempt=3 backoff=397.650838ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20172026/11/10 08:17:47 WARN Failed to register uploaded object key=bpsfywpyhrqzr9q66yzkg96kcv3j275k.narinfo error="server returned 404: 404 page not found\n"20182026/11/10 08:17:47 WARN Failed to register uploaded object key=4jf49f11f2zccbb4f6nqcky5b67ywrhp.narinfo error="server returned 404: 404 page not found\n"20192026/11/10 08:17:47 INFO Received complete push request method=POST path=/api/pushes/1/complete20202026/11/10 08:17:47 WARN Failed to register uploaded object key=6lf51kkpnb7n2rhphhscfqzscw0vrcvd.narinfo error="server returned 404: 404 page not found\n"20212026/11/10 08:17:47 INFO Completed push id=1 objects=9 duration=27.47225ms20222026/11/10 08:17:47 INFO Upload complete. (377ms)2023 client_integration_test.go:416: Uploaded 3 paths in 412.205167ms2024=== NAME TestClientIntegration2025 client_integration_test.go:291: Created store path: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientIntegration4239902650/002/store/q16r52m84d2ns69d0kgr4zpdp9lzpy65-test-file.txt2026--- PASS: TestReadProxyNarStreaming (7.28s)2027--- PASS: TestClientMultipleUploads (8.33s)20282026/11/10 08:17:48 INFO Received push request method=POST path=/api/pushes20292026/11/10 08:17:48 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20302026/11/10 08:17:48 INFO Uploading q16r52m84d2ns69d0kgr4zpdp9lzpy65-test-file.txt (152B)20312026/11/10 08:17:48 WARN Failed to register uploaded object key=q16r52m84d2ns69d0kgr4zpdp9lzpy65.ls error="server returned 404: 404 page not found\n"20322026/11/10 08:17:48 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20332026/11/10 08:17:48 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"20342026/11/10 08:17:48 INFO Signed narinfos id=1 count=120352026/11/10 08:17:48 INFO Uploading 1 narinfos20362026/11/10 08:17:48 WARN Request failed, retrying attempt=4 backoff=859.880097ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20372026/11/10 08:17:48 INFO Received complete push request method=POST path=/api/pushes/1/complete20382026/11/10 08:17:48 WARN Failed to register uploaded object key=q16r52m84d2ns69d0kgr4zpdp9lzpy65.narinfo error="server returned 404: 404 page not found\n"20392026/11/10 08:17:48 INFO Completed push id=1 objects=3 duration=18.84375ms20402026/11/10 08:17:48 INFO Upload complete. (283ms)20412026/11/10 08:17:48 INFO All 1 paths already cached2042=== NAME TestClientIntegration2043 client_integration_test.go:317: Retrieved narinfo from S3:2044 StorePath: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestClientIntegration4239902650/002/store/q16r52m84d2ns69d0kgr4zpdp9lzpy65-test-file.txt2045 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2046 Compression: zstd2047 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12048 NarSize: 1522049 References: 2050 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12051 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)2052 client_integration_test.go:318: Decompressed .ls content (64 bytes):2053 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2054--- PASS: TestReadProxyContentNegotiation (7.37s)20552026/11/10 08:17:48 INFO Received uploads request method=POST path=/api/pending_closures20562026/11/10 08:17:48 INFO Received uploads request method=POST path=/api/pending_closures20572026/11/10 08:17:48 INFO Received push request method=POST path=/api/pushes20582026/11/10 08:17:48 INFO Object in database but missing from S3 key=q16r52m84d2ns69d0kgr4zpdp9lzpy65.ls20592026/11/10 08:17:48 WARN Found objects in DB but missing from S3, will re-upload count=120602026/11/10 08:17:48 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20612026/11/10 08:17:48 INFO Received complete push request method=POST path=/api/pushes/2/complete20622026/11/10 08:17:48 WARN Failed to register uploaded object key=q16r52m84d2ns69d0kgr4zpdp9lzpy65.ls error="server returned 404: 404 page not found\n"20632026/11/10 08:17:48 INFO Completed push id=2 objects=3 duration=718.042µs20642026/11/10 08:17:48 INFO Upload complete. (136ms)2065=== NAME TestClientIntegration2066 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)2067 client_integration_test.go:335: Decompressed .ls content (49 bytes):2068 {"version":1,"root":{"type":"regular","size":39}}2069--- PASS: TestCacheStatsHandler (6.99s)20702026/11/10 08:17:49 WARN Request failed, retrying attempt=5 backoff=1.544851078s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20712026/11/10 08:17:49 INFO Received push request method=POST path=/api/pushes20722026/11/10 08:17:49 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20732026/11/10 08:17:49 INFO Received complete push request method=POST path=/api/pushes/3/complete20742026/11/10 08:17:49 WARN Failed to register uploaded object key=q16r52m84d2ns69d0kgr4zpdp9lzpy65.ls error="server returned 404: 404 page not found\n"20752026/11/10 08:17:49 INFO Completed push id=3 objects=3 duration=527.417µs20762026/11/10 08:17:49 INFO Upload complete. (104ms)2077=== NAME TestClientIntegration2078 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)2079 client_integration_test.go:352: Decompressed .ls content (49 bytes):2080 {"version":1,"root":{"type":"regular","size":39}}2081 client_integration_test.go:363: Testing garbage collection...20822026/11/10 08:17:49 INFO Starting cleanup of old closures method=DELETE path=/api/closures20832026/11/10 08:17:49 INFO Garbage collection started20842026/11/10 08:17:49 INFO Aborted multipart uploads count=0 kept=020852026/11/10 08:17:49 WARN Force mode enabled - objects will be deleted immediately without grace period20862026/11/10 08:17:49 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=020872026/11/10 08:17:49 INFO Vacuumed table table=pending_closures20882026/11/10 08:17:49 INFO Vacuumed table table=pending_objects20892026/11/10 08:17:49 INFO Vacuumed table table=multipart_uploads20902026/11/10 08:17:49 INFO Vacuumed table table=closures20912026/11/10 08:17:49 INFO Vacuumed table table=objects2092--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2093 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (7.46s)2094 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (7.48s)20952026/11/10 08:17:50 INFO Aborted multipart uploads count=0 kept=020962026/11/10 08:17:50 WARN Force mode enabled - objects will be deleted immediately without grace period20972026-11-10 08:17:50.130 UTC [94800] ERROR: canceling statement due to user request20982026-11-10 08:17:50.130 UTC [94800] STATEMENT: -- name: MarkStaleObjects :execrows2099 WITH RECURSIVE ct AS (2100 SELECT timezone('UTC', now()) AS now2101 ),2102 closure_reach AS (2103 -- Start with all closure keys2104 SELECT o.key, o.refs2105 FROM objects o2106 INNER JOIN closures c ON o.key = c.key2107 UNION2108 -- Recursively add all referenced objects2109 SELECT o.key, o.refs2110 FROM objects o2111 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2112 ),2113 reachable_objects AS (2114 SELECT DISTINCT key FROM closure_reach2115 ),2116 stale_objects AS (2117 SELECT o.key2118 FROM objects AS o, ct2119 WHERE2120 NOT EXISTS (2121 SELECT 12122 FROM reachable_objects ro2123 WHERE ro.key = o.key2124 )2125 AND NOT EXISTS (2126 SELECT 12127 FROM pending_objects AS po2128 WHERE po.key = o.key2129 )2130 AND o.deleted_at IS NULL -- Only mark fresh objects2131 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2132 FOR UPDATE2133 )2134 UPDATE objects2135 SET2136 deleted_at = ct.now,2137 first_deleted_at = COALESCE(first_deleted_at, ct.now)2138 FROM stale_objects, ct2139 WHERE objects.key = stale_objects.key2140 21412026/11/10 08:17:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21422026/11/10 08:17:50 INFO Received uploads request method=POST path=/api/pending_closures21432026/11/10 08:17:50 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NDE3MDRhN2YtZTZiZC00NWQ5LThkZDEtZDdkZjI1MzM5MThmLmJiYTA0Mzg5LWNhZDUtNDg5OS05NDgxLWExOWJjZjE5ZTBlMXgxNzk0Mjk4NjY4NjM1MTUzMDAw parts=1221442026/11/10 08:17:50 INFO Aborted multipart uploads count=0 kept=021452026/11/10 08:17:50 WARN Force mode enabled - objects will be deleted immediately without grace period21462026/11/10 08:17:50 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:60839/bucket97/?delete=\": context canceled"2147--- PASS: TestGCEndsOnShutdown (0.00s)2148 --- PASS: TestGCEndsOnShutdown/before_the_run (7.12s)2149 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (7.09s)2150 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (7.30s)21512026/11/10 08:17:50 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-config21522026/11/10 08:17:50 WARN Request failed, retrying attempt=2 backoff=213.185997ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21532026/11/10 08:17:50 INFO Received uploads request method=POST path=/api/pending_closures21542026/11/10 08:17:51 WARN Request failed, retrying attempt=3 backoff=435.646918ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21552026/11/10 08:17:51 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02156=== NAME TestClientIntegration2157 client_integration_test.go:370: Objects in database after GC:2158 client_integration_test.go:370: Successfully deleted all objects with GC --force2159--- PASS: TestClientIntegration (11.18s)21602026/11/10 08:17:51 WARN Request failed, retrying attempt=4 backoff=745.105228ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21612026/11/10 08:17:51 INFO Received uploads request method=POST path=/api/pending_closures21622026/11/10 08:17:52 WARN Request failed, retrying attempt=5 backoff=1.733908438s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21632026/11/10 08:17:52 INFO Received uploads request method=POST path=/api/pending_closures21642026/11/10 08:17:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21652026/11/10 08:17:53 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=NDE3MDRhN2YtZTZiZC00NWQ5LThkZDEtZDdkZjI1MzM5MThmLjA0OTk5ODQzLTViNmQtNDZmZS1iNTQwLTVmYjY5Y2I0YjJmZHgxNzk0Mjk4NjcwMzQxMjg3MDAw parts=1021662026/11/10 08:17:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21672026/11/10 08:17:53 INFO Completed upload id=1 objects=3 duration=24.745875ms21682026/11/10 08:17:53 INFO Received uploads request method=POST path=/api/pending_closures21692026/11/10 08:17:53 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"21702026/11/10 08:17:53 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21712026/11/10 08:17:54 WARN Request failed, retrying attempt=2 backoff=212.570062ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21722026/11/10 08:17:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21732026/11/10 08:17:54 WARN Request failed, retrying attempt=3 backoff=361.942202ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21742026/11/10 08:17:54 WARN Request failed, retrying attempt=4 backoff=773.890608ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21752026/11/10 08:17:54 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NDE3MDRhN2YtZTZiZC00NWQ5LThkZDEtZDdkZjI1MzM5MThmLjMxZDc1MTIyLTkzOTctNGZhOS1iNjdlLWUxZTY2MjYyNDc1MXgxNzk0Mjk4NjY4NjczMjEwMDAw parts=1221762026/11/10 08:17:54 INFO Received uploads request method=POST path=/api/pending_closures2177--- PASS: TestSharedNarBothUploadsComplete (13.31s)21782026/11/10 08:17:54 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21792026/11/10 08:17:54 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21802026/11/10 08:17:55 INFO Received uploads request method=POST path=/api/pending_closures21812026/11/10 08:17:55 INFO Aborted multipart uploads count=0 kept=021822026/11/10 08:17:55 WARN Force mode enabled - objects will be deleted immediately without grace period21832026/11/10 08:17:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21842026/11/10 08:17:55 WARN Request failed, retrying attempt=5 backoff=1.580627957s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21852026/11/10 08:17:55 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=NDE3MDRhN2YtZTZiZC00NWQ5LThkZDEtZDdkZjI1MzM5MThmLjM4ZGE2OTM4LWVmMjQtNGY2Ni04ZDE2LTFhYThhZDZkZGIzMXgxNzk0Mjk4NjcwODg1NDYzMDAw parts=1021862026/11/10 08:17:55 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=021872026/11/10 08:17:55 INFO Vacuumed table table=pending_closures21882026/11/10 08:17:55 INFO Vacuumed table table=pending_objects21892026/11/10 08:17:55 INFO Vacuumed table table=multipart_uploads21902026/11/10 08:17:55 INFO Vacuumed table table=closures21912026/11/10 08:17:55 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21922026/11/10 08:17:55 INFO Completed upload id=1 objects=3 duration=30.398ms21932026/11/10 08:17:55 INFO Received uploads request method=POST path=/api/pending_closures21942026/11/10 08:17:55 INFO Vacuumed table table=objects21952026/11/10 08:17:56 INFO Received uploads request method=POST path=/api/pending_closures21962026/11/10 08:17:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21972026/11/10 08:17:56 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=NDE3MDRhN2YtZTZiZC00NWQ5LThkZDEtZDdkZjI1MzM5MThmLjZmMmI0YmE3LWU3NzktNGViNC1iMjhjLWIyNmRmNjUwNTEwZXgxNzk0Mjk4NjcxNjQ0OTA4MDAw parts=1021982026/11/10 08:17:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete2199=== NAME TestOrphanedObjectsGCStressTest2200 orphaned_objects_gc_test.go:503: Stress test completed successfully:22012026/11/10 08:17:56 INFO Completed upload id=1 objects=3 duration=6.840917ms22022026/11/10 08:17:56 INFO Received uploads request method=POST path=/api/pending_closures2203 orphaned_objects_gc_test.go:504: - Active objects preserved: 202204 orphaned_objects_gc_test.go:505: - Objects deleted: 2102205 orphaned_objects_gc_test.go:506: - Total GC'd: 2102206--- PASS: TestOrphanedObjectsGCStressTest (36.71s)22072026/11/10 08:17:56 INFO Received uploads request method=POST path=/api/pending_closures22082026/11/10 08:17:56 INFO Aborted multipart uploads count=0 kept=022092026/11/10 08:17:56 WARN Force mode enabled - objects will be deleted immediately without grace period22102026/11/10 08:17:56 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=022112026/11/10 08:17:56 INFO Vacuumed table table=pending_closures22122026/11/10 08:17:56 INFO Vacuumed table table=pending_objects22132026/11/10 08:17:56 INFO Vacuumed table table=multipart_uploads22142026/11/10 08:17:56 INFO Vacuumed table table=closures22152026/11/10 08:17:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2216--- PASS: TestPendingClosureWriteTimeout (0.00s)2217 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2218 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2219 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2220 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (11.20s)22212026/11/10 08:17:56 INFO Vacuumed table table=objects22222026/11/10 08:17:56 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=NDE3MDRhN2YtZTZiZC00NWQ5LThkZDEtZDdkZjI1MzM5MThmLjg4Y2E1NmVhLTg0MTMtNDIwZS04YjE2LThjYzk1ODRlMmU3NngxNzk0Mjk4NjcyNjcwMTcyMDAw parts=102223--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2224 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (10.64s)2225 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (10.95s)22262026/11/10 08:17:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22272026/11/10 08:17:56 INFO Completed upload id=1 objects=3 duration=9.393375ms22282026/11/10 08:17:56 INFO Received uploads request method=POST path=/api/pending_closures22292026/11/10 08:17:57 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_closures22302026/11/10 08:17:57 WARN Request failed, retrying attempt=2 backoff=184.690928ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22312026/11/10 08:17:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22322026/11/10 08:17:57 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=NDE3MDRhN2YtZTZiZC00NWQ5LThkZDEtZDdkZjI1MzM5MThmLjAyZDQ2YzA1LTYzYmYtNGE1Yy1iOWUyLTk1YjBiYjMwNGIwNHgxNzk0Mjk4NjczODM3MjExMDAw parts=1022332026/11/10 08:17:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22342026/11/10 08:17:57 INFO Completed upload id=1 objects=3 duration=1.648959ms22352026/11/10 08:17:57 WARN Request failed, retrying attempt=3 backoff=376.470175ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22362026/11/10 08:17:57 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22372026/11/10 08:17:57 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22382026/11/10 08:17:57 INFO Received uploads request method=POST path=/api/pending_closures22392026/11/10 08:17:57 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst22402026/11/10 08:17:57 WARN Found objects in DB but missing from S3, will re-upload count=122412026/11/10 08:17:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22422026/11/10 08:17:57 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=NDE3MDRhN2YtZTZiZC00NWQ5LThkZDEtZDdkZjI1MzM5MThmLjJhYTViNTU2LWExY2EtNGRkZS1hYjc0LWJlY2IwZTdmZTA2OHgxNzk0Mjk4Njc1OTU5MTg1MDAw parts=1022432026/11/10 08:17:57 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22442026/11/10 08:17:57 INFO Completed upload id=2 objects=3 duration=360.208µs22452026/11/10 08:17:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22462026/11/10 08:17:57 WARN Request failed, retrying attempt=4 backoff=853.957139ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22472026/11/10 08:17:57 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=NDE3MDRhN2YtZTZiZC00NWQ5LThkZDEtZDdkZjI1MzM5MThmLjdhNGJhMzIyLTRmMmItNDg0MS04OGE4LWY4NjkxMzhiZWQxYXgxNzk0Mjk4Njc2NTc5ODEwMDAw parts=1022482026/11/10 08:17:57 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22492026/11/10 08:17:57 INFO Completed upload id=2 objects=3 duration=659.625µs22502026/11/10 08:17:57 INFO Received uploads request method=POST path=/api/pending_closures22512026/11/10 08:17:57 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22522026/11/10 08:17:57 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo22532026/11/10 08:17:57 INFO Received uploads request method=POST path=/api/pending_closures22542026/11/10 08:17:57 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22552026/11/10 08:17:57 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo2256--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.01s)2257 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (11.45s)2258 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (12.49s)2259 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (12.64s)2260 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (13.77s)2261 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (14.17s)22622026/11/10 08:17:58 WARN Request failed, retrying attempt=5 backoff=1.462482595s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2263--- PASS: TestClientErrorHandling (0.00s)2264 --- PASS: TestClientErrorHandling/InvalidStorePath (10.73s)2265 --- PASS: TestClientErrorHandling/InvalidAuthToken (10.27s)2266 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.85s)2267PASS2268{"timestamp":"2026-11-10T08:18:00.057323Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:61477","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(7)"}2269{"timestamp":"2026-11-10T08:18:00.057591Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:61496","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(5)"}2270{"timestamp":"2026-11-10T08:18:00.058084Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:61134","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}2271{"timestamp":"2026-11-10T08:18:00.058314Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:61390","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}22722026-11-10 08:18:00.152 UTC [94276] LOG: received smart shutdown request22732026-11-10 08:18:00.152 UTC [94276] LOG: background worker "logical replication launcher" (PID 94286) exited with exit code 122742026-11-10 08:18:00.181 UTC [94281] LOG: shutting down22752026-11-10 08:18:00.181 UTC [94281] LOG: checkpoint starting: shutdown immediate22762026-11-10 08:18:01.560 UTC [94281] LOG: checkpoint complete: wrote 12221 buffers (74.6%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.639 s, sync=0.702 s, total=1.380 s; sync files=36061, longest=0.001 s, average=0.001 s; distance=529951 kB, estimate=529951 kB; lsn=0/21D14F48, redo lsn=0/21D14F4822772026-11-10 08:18:01.567 UTC [94276] LOG: database system is shut down2278Running OIDC tests...2279=== RUN TestAudienceForIssuer2280=== PAUSE TestAudienceForIssuer2281=== RUN TestGlobMatch2282=== PAUSE TestGlobMatch2283=== RUN TestValidateToken_ValidToken2284=== PAUSE TestValidateToken_ValidToken2285=== RUN TestValidateToken_WrongAudience2286=== PAUSE TestValidateToken_WrongAudience2287=== RUN TestValidateToken_Expired2288=== PAUSE TestValidateToken_Expired2289=== RUN TestValidateToken_BoundClaimsMismatch2290=== PAUSE TestValidateToken_BoundClaimsMismatch2291=== RUN TestValidateToken_BoundSubjectMismatch2292=== PAUSE TestValidateToken_BoundSubjectMismatch2293=== RUN TestValidateToken_MultipleProviders2294=== PAUSE TestValidateToken_MultipleProviders2295=== RUN TestValidateToken_NoMatchingProvider2296=== PAUSE TestValidateToken_NoMatchingProvider2297=== RUN TestValidateToken_KubernetesServiceAccount2298=== PAUSE TestValidateToken_KubernetesServiceAccount2299=== RUN TestNewValidator_KubernetesRequiresCA2300=== PAUSE TestNewValidator_KubernetesRequiresCA2301=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2302=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2303=== RUN TestPins_ReservedForMatchingRule2304=== PAUSE TestPins_ReservedForMatchingRule2305=== RUN TestPins_TopLevelShorthand2306=== PAUSE TestPins_TopLevelShorthand2307=== RUN TestPins_ConfigValidation2308=== PAUSE TestPins_ConfigValidation2309=== RUN TestScopes_LegacyProviderDefaultsToWrite2310=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2311=== RUN TestScopes_Rules2312=== PAUSE TestScopes_Rules2313=== RUN TestScopes_ConfigValidation2314=== PAUSE TestScopes_ConfigValidation2315=== CONT TestAudienceForIssuer2316--- PASS: TestAudienceForIssuer (0.00s)2317=== CONT TestPins_ConfigValidation2318=== CONT TestScopes_Rules2319=== CONT TestValidateToken_NoMatchingProvider2320=== CONT TestValidateToken_MultipleProviders2321=== CONT TestValidateToken_BoundSubjectMismatch2322=== CONT TestValidateToken_BoundClaimsMismatch2323=== CONT TestValidateToken_Expired2324=== CONT TestValidateToken_WrongAudience2325--- PASS: TestPins_ConfigValidation (0.00s)2326=== CONT TestValidateToken_ValidToken2327=== CONT TestGlobMatch2328=== RUN TestGlobMatch/foo_foo2329=== PAUSE TestGlobMatch/foo_foo2330=== RUN TestGlobMatch/foo_bar2331=== PAUSE TestGlobMatch/foo_bar2332=== RUN TestGlobMatch/*_2333=== PAUSE TestGlobMatch/*_2334=== CONT TestScopes_ConfigValidation2335=== CONT TestScopes_LegacyProviderDefaultsToWrite2336--- PASS: TestScopes_ConfigValidation (0.00s)2337=== CONT TestPins_ReservedForMatchingRule2338=== CONT TestPins_TopLevelShorthand2339=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2340=== CONT TestNewValidator_KubernetesRequiresCA2341=== CONT TestValidateToken_KubernetesServiceAccount2342=== RUN TestGlobMatch/*_anything2343=== PAUSE TestGlobMatch/*_anything2344=== RUN TestGlobMatch/foo*_foo2345=== PAUSE TestGlobMatch/foo*_foo2346=== RUN TestGlobMatch/foo*_foobar2347=== PAUSE TestGlobMatch/foo*_foobar2348=== RUN TestGlobMatch/foo*_bar2349=== PAUSE TestGlobMatch/foo*_bar2350=== RUN TestGlobMatch/*bar_bar2351=== PAUSE TestGlobMatch/*bar_bar2352=== RUN TestGlobMatch/*bar_foobar2353=== PAUSE TestGlobMatch/*bar_foobar2354=== RUN TestGlobMatch/*bar_foo2355=== PAUSE TestGlobMatch/*bar_foo2356=== RUN TestGlobMatch/foo*bar_foobar2357=== PAUSE TestGlobMatch/foo*bar_foobar2358=== RUN TestGlobMatch/foo*bar_foo123bar2359=== PAUSE TestGlobMatch/foo*bar_foo123bar2360=== RUN TestGlobMatch/foo*bar_foobarbaz2361=== PAUSE TestGlobMatch/foo*bar_foobarbaz2362=== RUN TestGlobMatch/*/*_foo/bar2363=== PAUSE TestGlobMatch/*/*_foo/bar2364=== RUN TestGlobMatch/*/*_foo2365=== PAUSE TestGlobMatch/*/*_foo2366=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2367=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2368=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02369=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02370=== RUN TestGlobMatch/refs/*/main_refs/heads/main2371=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2372=== RUN TestGlobMatch/fo?_foo2373=== PAUSE TestGlobMatch/fo?_foo2374=== RUN TestGlobMatch/fo?_fo2375=== PAUSE TestGlobMatch/fo?_fo2376=== RUN TestGlobMatch/fo?_fooo2377=== PAUSE TestGlobMatch/fo?_fooo2378=== RUN TestGlobMatch/?oo_foo2379=== PAUSE TestGlobMatch/?oo_foo2380=== RUN TestGlobMatch/?oo_boo2381=== PAUSE TestGlobMatch/?oo_boo2382=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2383=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2384=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2385=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2386=== CONT TestGlobMatch/foo_foo2387=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2388=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2389=== CONT TestGlobMatch/?oo_boo2390=== CONT TestGlobMatch/?oo_foo2391=== CONT TestGlobMatch/fo?_fooo2392=== CONT TestGlobMatch/fo?_fo2393=== CONT TestGlobMatch/fo?_foo2394=== CONT TestGlobMatch/refs/*/main_refs/heads/main2395=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02396=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2397=== CONT TestGlobMatch/*/*_foo2398=== CONT TestGlobMatch/*/*_foo/bar2399=== CONT TestGlobMatch/foo*bar_foobarbaz2400=== CONT TestGlobMatch/foo*bar_foo123bar2401=== CONT TestGlobMatch/foo*bar_foobar2402=== CONT TestGlobMatch/*bar_foo2403=== CONT TestGlobMatch/*bar_foobar2404=== CONT TestGlobMatch/*bar_bar2405=== CONT TestGlobMatch/foo*_bar2406=== CONT TestGlobMatch/foo*_foobar2407=== CONT TestGlobMatch/foo*_foo2408=== CONT TestGlobMatch/*_anything2409=== CONT TestGlobMatch/*_2410=== CONT TestGlobMatch/foo_bar2411--- PASS: TestGlobMatch (0.01s)2412 --- PASS: TestGlobMatch/foo_foo (0.00s)2413 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2414 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2415 --- PASS: TestGlobMatch/?oo_boo (0.00s)2416 --- PASS: TestGlobMatch/?oo_foo (0.00s)2417 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2418 --- PASS: TestGlobMatch/fo?_fo (0.00s)2419 --- PASS: TestGlobMatch/fo?_foo (0.00s)2420 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2421 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2422 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2423 --- PASS: TestGlobMatch/*/*_foo (0.00s)2424 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2425 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2426 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2427 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2428 --- PASS: TestGlobMatch/*bar_foo (0.00s)2429 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2430 --- PASS: TestGlobMatch/*bar_bar (0.00s)2431 --- PASS: TestGlobMatch/foo*_bar (0.00s)2432 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2433 --- PASS: TestGlobMatch/foo*_foo (0.00s)2434 --- PASS: TestGlobMatch/*_anything (0.00s)2435 --- PASS: TestGlobMatch/*_ (0.00s)2436 --- PASS: TestGlobMatch/foo_bar (0.00s)24372026/11/10 08:18:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61513/oidc2438--- PASS: TestValidateToken_BoundSubjectMismatch (0.04s)24392026/11/10 08:18:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61515/oidc24402026/11/10 08:18:03 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232441--- PASS: TestScopes_Rules (0.07s)24422026/11/10 08:18:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61519/oidc2443--- PASS: TestValidateToken_Expired (0.08s)24442026/11/10 08:18:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61522/oidc24452026/11/10 08:18:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61521/oidc24462026/11/10 08:18:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61525/oidc2447--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.07s)2448--- PASS: TestValidateToken_BoundClaimsMismatch (0.08s)2449--- PASS: TestValidateToken_WrongAudience (0.08s)2450--- PASS: TestPins_ReservedForMatchingRule (0.08s)24512026/11/10 08:18:03 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:615312452--- PASS: TestValidateToken_KubernetesServiceAccount (0.08s)24532026/11/10 08:18:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61534/oidc2454--- PASS: TestValidateToken_ValidToken (0.09s)24552026/11/10 08:18:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61536/oidc2456--- PASS: TestPins_TopLevelShorthand (0.12s)24572026/11/10 08:18:03 http: TLS handshake error from 127.0.0.1:61539: remote error: tls: bad certificate2458--- PASS: TestNewValidator_KubernetesRequiresCA (0.12s)24592026/11/10 08:18:03 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:61530/oidc24602026/11/10 08:18:03 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:61540/oidc2461--- PASS: TestValidateToken_MultipleProviders (0.16s)24622026/11/10 08:18:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61543/oidc2463--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.16s)24642026/11/10 08:18:03 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:61533/oidc2465--- PASS: TestValidateToken_NoMatchingProvider (0.18s)2466PASS2467Running hook tests...2468=== RUN TestSendPathsEmpty2469=== PAUSE TestSendPathsEmpty2470=== RUN TestQueueEnqueueAndFetch2471=== PAUSE TestQueueEnqueueAndFetch2472=== RUN TestQueueDeduplication2473=== PAUSE TestQueueDeduplication2474=== RUN TestQueueRemove2475=== PAUSE TestQueueRemove2476=== RUN TestQueueFetchBatchLimit2477=== PAUSE TestQueueFetchBatchLimit2478=== RUN TestQueueRetryMovesToBack2479=== PAUSE TestQueueRetryMovesToBack2480=== RUN TestQueueFetchRemoveLifecycle2481=== PAUSE TestQueueFetchRemoveLifecycle2482=== RUN TestQueueConcurrentWriters2483=== PAUSE TestQueueConcurrentWriters2484=== RUN TestQueueRemoveLargeClosure2485=== PAUSE TestQueueRemoveLargeClosure2486=== RUN TestServerClientIntegration2487--- PASS: TestServerClientIntegration (0.00s)2488=== RUN TestServerQueueError24892026/11/10 08:18:03 ERROR Failed to queue paths error="permission denied" count=12490--- PASS: TestServerQueueError (0.00s)2491=== RUN TestGetListenerSocketActivation2492 server_test.go:145: systemd socket activation does not exist on darwin2493--- SKIP: TestGetListenerSocketActivation (0.00s)2494=== RUN TestServerStalledClientDoesNotBlockShutdown2495=== PAUSE TestServerStalledClientDoesNotBlockShutdown2496=== RUN TestServerBacksOffOnAcceptErrors2497=== PAUSE TestServerBacksOffOnAcceptErrors2498=== RUN TestDrainIsolatesPoisonPath2499=== PAUSE TestDrainIsolatesPoisonPath2500=== RUN TestRunNotBlockedByPoisonHead2501=== PAUSE TestRunNotBlockedByPoisonHead2502=== RUN TestDrainGivesUpWhenServerDown2503=== PAUSE TestDrainGivesUpWhenServerDown2504=== RUN TestFailedPathPrunedByLaterClosure2505=== PAUSE TestFailedPathPrunedByLaterClosure2506=== RUN TestWorkerUploadsAndRemoves2507=== PAUSE TestWorkerUploadsAndRemoves2508=== RUN TestWorkerSkipsGCdPaths2509=== PAUSE TestWorkerSkipsGCdPaths2510=== RUN TestWorkerPrunesClosureDeps2511=== PAUSE TestWorkerPrunesClosureDeps2512=== RUN TestDrainTimeout2513=== PAUSE TestDrainTimeout2514=== RUN TestWorkerRemoveFailureIsNotProgress2515=== PAUSE TestWorkerRemoveFailureIsNotProgress2516=== RUN TestWorkerKeepsPathItCannotStat2517=== PAUSE TestWorkerKeepsPathItCannotStat2518=== CONT TestSendPathsEmpty2519=== CONT TestWorkerKeepsPathItCannotStat2520--- PASS: TestSendPathsEmpty (0.00s)2521=== CONT TestDrainIsolatesPoisonPath2522=== CONT TestServerBacksOffOnAcceptErrors2523=== CONT TestServerStalledClientDoesNotBlockShutdown25242026/11/10 08:18:03 ERROR Accept failed error="too many open files"2525=== CONT TestQueueRemoveLargeClosure2526=== CONT TestQueueConcurrentWriters2527=== CONT TestQueueRemove2528=== CONT TestQueueDeduplication2529=== CONT TestQueueEnqueueAndFetch2530=== CONT TestQueueFetchBatchLimit2531=== CONT TestQueueFetchRemoveLifecycle2532=== CONT TestWorkerSkipsGCdPaths2533=== CONT TestQueueRetryMovesToBack2534=== CONT TestWorkerRemoveFailureIsNotProgress2535=== CONT TestDrainTimeout2536=== CONT TestFailedPathPrunedByLaterClosure2537=== CONT TestWorkerPrunesClosureDeps2538=== CONT TestWorkerUploadsAndRemoves2539=== CONT TestDrainGivesUpWhenServerDown2540=== CONT TestRunNotBlockedByPoisonHead25412026/11/10 08:18:03 ERROR Accept failed error="too many open files"25422026/11/10 08:18:03 INFO Upload queue status pending=225432026/11/10 08:18:03 INFO Upload queue status pending=225442026/11/10 08:18:03 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/6/scratch/e12f70b2f235e287/build/TestWorkerSkipsGCdPaths2217223245/002/nonexistent25452026/11/10 08:18:03 INFO Uploading batch count=225462026/11/10 08:18:03 WARN Cannot stat store path, will retry later path=/private/var/tb/6/scratch/e12f70b2f235e287/build/TestWorkerKeepsPathItCannotStat507112122/002/locked/aaa error="stat /private/var/tb/6/scratch/e12f70b2f235e287/build/TestWorkerKeepsPathItCannotStat507112122/002/locked/aaa: permission denied"25472026/11/10 08:18:03 WARN Cannot stat store path, will retry later path=/private/var/tb/6/scratch/e12f70b2f235e287/build/TestWorkerKeepsPathItCannotStat507112122/002/locked/aaa error="stat /private/var/tb/6/scratch/e12f70b2f235e287/build/TestWorkerKeepsPathItCannotStat507112122/002/locked/aaa: permission denied"25482026/11/10 08:18:03 INFO Uploading batch count=125492026/11/10 08:18:03 INFO Uploading batch count=125502026/11/10 08:18:03 ERROR Upload failed error="upload failed" count=125512026/11/10 08:18:03 WARN Cannot stat store path, will retry later path=/private/var/tb/6/scratch/e12f70b2f235e287/build/TestWorkerKeepsPathItCannotStat507112122/002/locked/aaa error="stat /private/var/tb/6/scratch/e12f70b2f235e287/build/TestWorkerKeepsPathItCannotStat507112122/002/locked/aaa: permission denied"25522026/11/10 08:18:03 INFO Upload queue status pending=32553--- PASS: TestQueueFetchBatchLimit (0.01s)25542026/11/10 08:18:03 INFO Uploading batch count=225552026/11/10 08:18:03 INFO Uploading batch count=225562026/11/10 08:18:03 ERROR Upload failed error="upload failed" count=225572026/11/10 08:18:03 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/e12f70b2f235e287/build/TestDrainGivesUpWhenServerDown2449902085/002/a25582026/11/10 08:18:03 INFO Uploading batch count=125592026/11/10 08:18:03 INFO Uploading batch count=425602026/11/10 08:18:03 ERROR Upload failed error="upload failed" count=425612026/11/10 08:18:03 INFO Uploading batch count=125622026/11/10 08:18:03 ERROR Upload failed error="upload failed" count=12563--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2564--- PASS: TestQueueEnqueueAndFetch (0.01s)25652026/11/10 08:18:03 ERROR Drain finished with paths left in queue remaining=125662026/11/10 08:18:03 INFO Upload queue status pending=225672026/11/10 08:18:03 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/e12f70b2f235e287/build/TestDrainGivesUpWhenServerDown2449902085/002/b25682026/11/10 08:18:03 INFO Uploading batch count=125692026/11/10 08:18:03 INFO Uploading batch count=125702026/11/10 08:18:03 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/6/scratch/e12f70b2f235e287/build/TestWorkerRemoveFailureIsNotProgress1939755952/002/nonexistent25712026/11/10 08:18:03 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/e12f70b2f235e287/build/TestDrainIsolatesPoisonPath672240240/002/bbb25722026/11/10 08:18:03 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125732026/11/10 08:18:03 INFO Uploading batch count=225742026/11/10 08:18:03 ERROR Upload failed error="upload failed" count=225752026/11/10 08:18:03 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/e12f70b2f235e287/build/TestDrainGivesUpWhenServerDown2449902085/002/c2576--- PASS: TestQueueRemove (0.02s)25772026/11/10 08:18:03 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/6/scratch/e12f70b2f235e287/build/TestWorkerRemoveFailureIsNotProgress1939755952/002/nonexistent25782026/11/10 08:18:03 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125792026/11/10 08:18:03 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/6/scratch/e12f70b2f235e287/build/TestWorkerRemoveFailureIsNotProgress1939755952/002/nonexistent25802026/11/10 08:18:03 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125812026/11/10 08:18:03 ERROR Drain finished with paths left in queue remaining=125822026/11/10 08:18:03 ERROR Accept failed error="too many open files"25832026/11/10 08:18:03 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/e12f70b2f235e287/build/TestDrainGivesUpWhenServerDown2449902085/002/d25842026/11/10 08:18:03 INFO Uploading batch count=125852026/11/10 08:18:03 ERROR Upload failed error="upload failed" count=12586--- PASS: TestQueueRetryMovesToBack (0.02s)25872026/11/10 08:18:03 INFO Uploading batch count=225882026/11/10 08:18:03 ERROR Upload failed error="upload failed" count=225892026/11/10 08:18:03 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/e12f70b2f235e287/build/TestDrainGivesUpWhenServerDown2449902085/002/e25902026/11/10 08:18:03 INFO Uploading batch count=125912026/11/10 08:18:03 ERROR Upload failed error="upload failed" count=12592--- PASS: TestQueueDeduplication (0.02s)25932026/11/10 08:18:03 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/e12f70b2f235e287/build/TestDrainGivesUpWhenServerDown2449902085/002/f2594--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)25952026/11/10 08:18:03 INFO Uploading batch count=125962026/11/10 08:18:03 ERROR Upload failed error="upload failed" count=125972026/11/10 08:18:03 ERROR Drain finished with paths left in queue remaining=1025982026/11/10 08:18:03 ERROR Drain finished with paths left in queue remaining=12599--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)2600--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2601--- PASS: TestDrainIsolatesPoisonPath (0.02s)2602--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2603--- PASS: TestWorkerSkipsGCdPaths (0.03s)2604--- PASS: TestWorkerUploadsAndRemoves (0.03s)2605--- PASS: TestWorkerPrunesClosureDeps (0.03s)26062026/11/10 08:18:03 ERROR Accept failed error="too many open files"2607--- PASS: TestQueueRemoveLargeClosure (0.05s)2608--- PASS: TestQueueConcurrentWriters (0.06s)26092026/11/10 08:18:03 ERROR Accept failed error="too many open files"26102026/11/10 08:18:03 ERROR Accept failed error="too many open files"26112026/11/10 08:18:03 ERROR Failed to decode request error="read unix /private/var/tb/6/scratch/e12f70b2f235e287/build/hook2095108917/test.sock->: i/o timeout"26122026/11/10 08:18:03 ERROR Failed to write response error="write unix /private/var/tb/6/scratch/e12f70b2f235e287/build/hook2095108917/test.sock->: i/o timeout"2613--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26142026/11/10 08:18:03 ERROR Upload failed error="context deadline exceeded" count=226152026/11/10 08:18:03 ERROR Drain finished with paths left in queue remaining=42616--- PASS: TestDrainTimeout (0.22s)26172026/11/10 08:18:03 ERROR Accept failed error="too many open files"26182026/11/10 08:18:04 ERROR Accept failed error="too many open files"2619--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26202026/11/10 08:18:04 INFO Uploading batch count=126212026/11/10 08:18:04 INFO Uploading batch count=126222026/11/10 08:18:04 INFO Uploading batch count=126232026/11/10 08:18:04 ERROR Upload failed error="upload failed" count=126242026/11/10 08:18:04 INFO Uploading batch count=126252026/11/10 08:18:04 ERROR Upload failed error="upload failed" count=126262026/11/10 08:18:04 INFO Uploading batch count=126272026/11/10 08:18:04 ERROR Upload failed error="upload failed" count=126282026/11/10 08:18:04 INFO Uploading batch count=126292026/11/10 08:18:04 ERROR Upload failed error="upload failed" count=126302026/11/10 08:18:04 ERROR Drain finished with paths left in queue remaining=12631--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2632PASS2633Running signing tests...2634=== RUN TestExternalSigner2635=== PAUSE TestExternalSigner2636=== RUN TestExternalSignerWrongPublicKey2637=== PAUSE TestExternalSignerWrongPublicKey2638=== RUN TestExternalSignerErrors2639=== PAUSE TestExternalSignerErrors2640=== RUN TestExternalSignerRestartsAfterCrash2641=== PAUSE TestExternalSignerRestartsAfterCrash2642=== RUN TestExternalSignerProgramErrorKeepsProcess2643=== PAUSE TestExternalSignerProgramErrorKeepsProcess2644=== RUN TestExternalSignerClose2645=== PAUSE TestExternalSignerClose2646=== RUN TestExternalSignerRejectsInvalidPublicKey2647=== PAUSE TestExternalSignerRejectsInvalidPublicKey2648=== RUN TestExternalSignerCancellation2649=== PAUSE TestExternalSignerCancellation2650=== RUN TestGenerateFingerprint2651=== PAUSE TestGenerateFingerprint2652=== RUN TestParseSigningKey2653=== PAUSE TestParseSigningKey2654=== RUN TestSign2655=== PAUSE TestSign2656=== RUN TestSignBatch2657=== PAUSE TestSignBatch2658=== RUN TestNilKeyPublicKey2659=== PAUSE TestNilKeyPublicKey2660=== RUN TestSignErrors2661=== PAUSE TestSignErrors2662=== CONT TestExternalSigner2663=== CONT TestSignErrors2664=== CONT TestGenerateFingerprint2665=== CONT TestExternalSignerCancellation2666=== CONT TestExternalSignerProgramErrorKeepsProcess2667=== CONT TestExternalSignerRejectsInvalidPublicKey2668=== RUN TestExternalSignerRejectsInvalidPublicKey/#002669=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002670=== CONT TestExternalSignerClose2671=== CONT TestExternalSignerRestartsAfterCrash2672=== CONT TestExternalSignerWrongPublicKey2673=== CONT TestSign2674=== CONT TestNilKeyPublicKey2675--- PASS: TestNilKeyPublicKey (0.00s)2676=== CONT TestSignBatch2677=== CONT TestParseSigningKey2678=== RUN TestParseSigningKey/valid_32-byte_key2679=== RUN TestGenerateFingerprint/basic_with_references2680=== PAUSE TestParseSigningKey/valid_32-byte_key2681=== PAUSE TestGenerateFingerprint/basic_with_references2682=== CONT TestExternalSignerErrors2683=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2684=== RUN TestGenerateFingerprint/no_references2685=== PAUSE TestGenerateFingerprint/no_references2686=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2687=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2688=== RUN TestExternalSignerErrors/missing_signature_name2689=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2690=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2691=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2692=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2693=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2694=== PAUSE TestExternalSignerErrors/missing_signature_name2695=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2696=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2697=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2698=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2699=== RUN TestParseSigningKey/no_colon2700=== PAUSE TestParseSigningKey/no_colon2701=== RUN TestParseSigningKey/empty_name2702=== RUN TestExternalSignerErrors/wrong_signature_name2703=== PAUSE TestExternalSignerErrors/wrong_signature_name2704=== PAUSE TestParseSigningKey/empty_name2705=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2706=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2707=== RUN TestExternalSignerErrors/invalid_signature_base642708=== CONT TestExternalSignerRejectsInvalidPublicKey/#002709=== PAUSE TestExternalSignerErrors/invalid_signature_base642710=== RUN TestGenerateFingerprint/invalid_nar_hash_length2711=== RUN TestSignErrors/nil_key2712=== PAUSE TestSignErrors/nil_key2713=== RUN TestSignErrors/nil_narinfo2714=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2715=== RUN TestGenerateFingerprint/invalid_store_path_prefix2716=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2717=== PAUSE TestSignErrors/nil_narinfo2718=== RUN TestGenerateFingerprint/invalid_reference_prefix2719=== RUN TestParseSigningKey/invalid_base642720=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2721=== CONT TestGenerateFingerprint/basic_with_references2722=== CONT TestGenerateFingerprint/invalid_reference_prefix2723=== PAUSE TestParseSigningKey/invalid_base642724=== CONT TestGenerateFingerprint/invalid_store_path_prefix2725=== CONT TestGenerateFingerprint/no_references2726--- PASS: TestSign (0.00s)2727=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2728=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2729=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2730=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2731--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2732 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2733 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2734 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2735 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2736 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2737=== RUN TestExternalSignerErrors/program_error2738=== PAUSE TestExternalSignerErrors/program_error2739=== RUN TestExternalSignerErrors/null2740=== PAUSE TestExternalSignerErrors/null2741=== RUN TestExternalSignerErrors/missing_signatures2742=== PAUSE TestExternalSignerErrors/missing_signatures2743=== RUN TestExternalSignerErrors/null_signatures2744=== PAUSE TestExternalSignerErrors/null_signatures2745=== RUN TestExternalSignerErrors/wrong_signature_length2746=== PAUSE TestExternalSignerErrors/wrong_signature_length2747=== RUN TestExternalSignerErrors/exit_at_startup2748=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2749=== PAUSE TestExternalSignerErrors/exit_at_startup2750--- PASS: TestSignBatch (0.00s)2751=== CONT TestGenerateFingerprint/invalid_nar_hash_length2752=== RUN TestSignErrors/invalid_narinfo2753=== RUN TestParseSigningKey/wrong_length2754=== PAUSE TestSignErrors/invalid_narinfo2755=== PAUSE TestParseSigningKey/wrong_length2756=== RUN TestSignErrors/canceled2757=== PAUSE TestSignErrors/canceled2758=== CONT TestParseSigningKey/no_colon2759=== CONT TestSignErrors/nil_key2760=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2761=== CONT TestParseSigningKey/valid_32-byte_key2762=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2763=== RUN TestExternalSignerErrors/wrong_shape2764--- PASS: TestGenerateFingerprint (0.00s)2765 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2766 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2767 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2768 --- PASS: TestGenerateFingerprint/no_references (0.00s)2769 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2770 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2771 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2772=== CONT TestParseSigningKey/wrong_length2773=== PAUSE TestExternalSignerErrors/wrong_shape2774=== CONT TestParseSigningKey/invalid_base642775=== RUN TestExternalSignerErrors/too_few_signatures2776=== PAUSE TestExternalSignerErrors/too_few_signatures2777=== RUN TestExternalSignerErrors/wrong_signatures_shape2778=== CONT TestParseSigningKey/empty_name2779--- PASS: TestParseSigningKey (0.00s)2780 --- PASS: TestParseSigningKey/no_colon (0.00s)2781 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2782 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2783 --- PASS: TestParseSigningKey/wrong_length (0.00s)2784 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2785 --- PASS: TestParseSigningKey/empty_name (0.00s)2786=== CONT TestSignErrors/canceled2787=== CONT TestSignErrors/invalid_narinfo2788=== CONT TestSignErrors/nil_narinfo2789--- PASS: TestSignErrors (0.01s)2790 --- PASS: TestSignErrors/nil_key (0.00s)2791 --- PASS: TestSignErrors/canceled (0.00s)2792 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2793 --- PASS: TestSignErrors/nil_narinfo (0.00s)2794=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2795=== RUN TestExternalSignerErrors/unrequested_key2796=== PAUSE TestExternalSignerErrors/unrequested_key2797=== RUN TestExternalSignerErrors/exit_on_request2798=== PAUSE TestExternalSignerErrors/exit_on_request2799=== RUN TestExternalSignerErrors/invalid_JSON2800=== PAUSE TestExternalSignerErrors/invalid_JSON2801=== RUN TestExternalSignerErrors/wrong_id2802=== PAUSE TestExternalSignerErrors/wrong_id2803=== CONT TestExternalSignerErrors/missing_signature_name2804=== CONT TestExternalSignerErrors/unrequested_key2805=== CONT TestExternalSignerErrors/null2806=== CONT TestExternalSignerErrors/null_signatures2807=== CONT TestExternalSignerErrors/wrong_signature_length2808=== CONT TestExternalSignerErrors/missing_signatures2809=== CONT TestExternalSignerErrors/wrong_signature_name2810=== CONT TestExternalSignerErrors/exit_at_startup2811=== CONT TestExternalSignerErrors/invalid_JSON2812=== CONT TestExternalSignerErrors/wrong_signatures_shape2813=== CONT TestExternalSignerErrors/exit_on_request2814=== CONT TestExternalSignerErrors/wrong_shape2815=== CONT TestExternalSignerErrors/wrong_id2816=== CONT TestExternalSignerErrors/too_few_signatures2817=== CONT TestExternalSignerErrors/invalid_signature_base642818=== CONT TestExternalSignerErrors/program_error2819--- PASS: TestExternalSignerClose (0.10s)2820--- PASS: TestExternalSignerCancellation (0.19s)2821--- PASS: TestExternalSignerWrongPublicKey (0.25s)2822--- PASS: TestExternalSignerRestartsAfterCrash (0.34s)2823/private/var/tb/6/scratch/e12f70b2f235e287/build/TestExternalSignerRestartsAfterCrash609445751/001/sign program: line 7: /private/var/tb/6/scratch/e12f70b2f235e287/build/TestExternalSignerRestartsAfterCrash609445751/001/sign program.starts: No such file or directory2824--- PASS: TestExternalSigner (0.41s)2825--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.48s)2826--- PASS: TestExternalSignerErrors (0.00s)2827 --- PASS: TestExternalSignerErrors/missing_signatures (0.55s)2828 --- PASS: TestExternalSignerErrors/missing_signature_name (0.62s)2829 --- PASS: TestExternalSignerErrors/invalid_JSON (0.70s)2830 --- PASS: TestExternalSignerErrors/null (0.78s)2831 --- PASS: TestExternalSignerErrors/exit_on_request (0.85s)2832 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.93s)2833 --- PASS: TestExternalSignerErrors/null_signatures (1.01s)2834 --- PASS: TestExternalSignerErrors/unrequested_key (1.08s)2835 --- PASS: TestExternalSignerErrors/exit_at_startup (1.16s)2836 --- PASS: TestExternalSignerErrors/wrong_id (1.23s)2837 --- PASS: TestExternalSignerErrors/wrong_shape (1.31s)2838 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (1.38s)2839 --- PASS: TestExternalSignerErrors/wrong_signature_name (1.46s)2840 --- PASS: TestExternalSignerErrors/too_few_signatures (1.54s)2841 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (1.62s)2842 --- PASS: TestExternalSignerErrors/program_error (1.70s)2843PASS2844Running OpenBao signer tests...2845=== RUN TestSign2846=== PAUSE TestSign2847=== RUN TestSignErrors2848=== PAUSE TestSignErrors2849=== RUN TestServe2850=== PAUSE TestServe2851=== RUN TestServeRejectsGarbage2852=== PAUSE TestServeRejectsGarbage2853=== CONT TestSign2854=== CONT TestServe2855=== CONT TestSignErrors2856=== RUN TestSignErrors/http_error2857=== PAUSE TestSignErrors/http_error2858=== RUN TestSignErrors/invalid_json2859=== CONT TestServeRejectsGarbage2860--- PASS: TestServeRejectsGarbage (0.00s)2861=== PAUSE TestSignErrors/invalid_json2862=== RUN TestSignErrors/no_prefix2863=== PAUSE TestSignErrors/no_prefix2864=== RUN TestSignErrors/invalid_base642865=== PAUSE TestSignErrors/invalid_base642866=== CONT TestSignErrors/http_error2867=== CONT TestSignErrors/no_prefix2868=== CONT TestSignErrors/invalid_base642869=== CONT TestSignErrors/invalid_json2870--- PASS: TestServe (0.00s)2871--- PASS: TestSign (0.00s)2872--- PASS: TestSignErrors (0.00s)2873 --- PASS: TestSignErrors/http_error (0.00s)2874 --- PASS: TestSignErrors/invalid_json (0.00s)2875 --- PASS: TestSignErrors/invalid_base64 (0.00s)2876 --- PASS: TestSignErrors/no_prefix (0.00s)2877PASS