niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #488
· 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.06s)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 TestScriptTokenNoExpiryRerunsEveryCall115=== CONT TestDumpPathWriterError116=== CONT TestScriptTokenBadJSON117=== CONT TestScriptTokenEmptyCommand118--- PASS: TestScriptTokenEmptyCommand (0.00s)119=== CONT TestShellSplit120=== CONT TestScriptTokenScriptFails121--- PASS: TestShellSplit (0.00s)122=== CONT TestRegisterUploadedObject_OutlivesPush123=== CONT TestFileTokenEmpty124=== CONT TestFileTokenMissing125=== CONT TestFileTokenReadsAndCaches126=== CONT TestStaticToken127=== CONT TestSetClientTLSErrors128=== CONT TestRetryTimeoutOutlastsMaxRetries129=== CONT TestSetClientTLSDoesNotMutateDefaultTransport130=== CONT TestSetClientTLS131=== CONT TestStreamPushStopsWhenCanceled132=== CONT TestClientSignaturesByStorePath133=== CONT TestStreamPushReportsSkippedPaths134=== CONT TestStreamPushReportsSignatures135=== CONT TestStreamPushRequestLine136=== CONT TestStreamPushGivesUpOnDeadServer137=== CONT TestStreamPushIsolatesFailures138=== CONT TestStreamPushBatchesUnderLoad139=== CONT TestStreamPushReportsEveryPath140=== CONT TestShellSplitErrors141=== CONT TestDoWithRetry_FinalResponseBodyReadable142--- PASS: TestStaticToken (0.00s)143--- PASS: TestFileTokenMissing (0.00s)1442026/11/11 23:21:28 ERROR Upload failed error="bad path" count=31452026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:573811462026/11/11 23:21:28 ERROR Upload failed error=boom count=11472026/11/11 23:21:28 ERROR Upload failed error="connection refused" count=201482026/11/11 23:21:28 ERROR Server seems unavailable, giving up on batch untried=171492026/11/11 23:21:28 ERROR Upload failed error=boom count=1150=== CONT TestDoWithRetry_BodyReplayedViaGetBody151=== CONT TestResolveStorePath152=== CONT TestScriptTokenEmptyToken153=== CONT TestFilterOversizedClosures154=== RUN TestFilterOversizedClosures/no_limit_keeps_everything155--- PASS: TestFileTokenReadsAndCaches (0.00s)156--- PASS: TestStreamPushStopsWhenCanceled (0.00s)157--- PASS: TestClientSignaturesByStorePath (0.00s)158--- PASS: TestStreamPushReportsSkippedPaths (0.00s)159--- PASS: TestStreamPushIsolatesFailures (0.00s)160--- PASS: TestStreamPushReportsSignatures (0.00s)161--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)162--- PASS: TestShellSplitErrors (0.00s)163--- PASS: TestFileTokenEmpty (0.00s)164--- PASS: TestStreamPushReportsEveryPath (0.00s)165--- PASS: TestScriptTokenScriptFails (0.00s)166--- PASS: TestRegisterUploadedObject_OutlivesPush (0.00s)167--- PASS: TestDoServerRequestAttachesToken (0.01s)1682026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:57381169=== CONT TestDumpPathSingleFile170=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess171=== CONT TestDumpPathMatchesNix172=== CONT TestPartSizeForNAR173=== RUN TestPartSizeForNAR/zero_stays_at_minimum174--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)1752026/11/11 23:21:28 WARN Rate limiter enabled after throttle name=server-test rate=51762026/11/11 23:21:28 WARN Rate limiter enabled after throttle name=server-test rate=51772026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:57386178=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false1792026/11/11 23:21:28 WARN Rate limiter enabled after throttle name=server-test rate=51802026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:57385181=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false1822026/11/11 23:21:28 WARN Rate limiter backed off name=server-test rate=51832026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:573851842026/11/11 23:21:28 WARN Rate limiter backed off name=server-test rate=51852026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:57381186=== CONT TestParsePathInfoJSON187=== RUN TestSetClientTLSErrors/missing_cert_file188=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer189=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything190=== CONT TestRateLimiterFeedback191=== CONT TestScriptTokenCachesUntilRefresh192=== CONT TestUploadMultipart_ReturnsAfterDroppedBody193=== CONT TestUploadMultipart_PartsInParallel194=== CONT TestPathInfoCACompatibility195=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum196=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true197=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true198=== RUN TestPathInfoCACompatibility/null_ca_field199=== PAUSE TestPathInfoCACompatibility/null_ca_field200=== RUN TestPathInfoCACompatibility/old_string_format_-_text201=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text202=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive203=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive204=== CONT TestPathInfoHashCompatibility205=== RUN TestPartSizeForNAR/small_stays_at_minimum206=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)207=== RUN TestSetClientTLS/rejects_connection_without_client_cert208=== RUN TestPathInfoCACompatibility/new_structured_format_-_text209--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.00s)210=== CONT TestParsePathInfoJSONMultiplePaths211=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths212=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths213=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths214=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths215=== PAUSE TestSetClientTLSErrors/missing_cert_file216=== RUN TestSetClientTLSErrors/missing_key_file217=== PAUSE TestSetClientTLSErrors/missing_key_file218=== RUN TestSetClientTLSErrors/missing_ca_file219=== CONT TestEncodeNixBase32220=== RUN TestEncodeNixBase32/test_string_hash221=== RUN TestRateLimiterFeedback/429_enables_limiter222=== PAUSE TestEncodeNixBase32/test_string_hash223=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped224=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped225=== RUN TestFilterOversizedClosures/all_closures_skipped226=== PAUSE TestFilterOversizedClosures/all_closures_skipped227=== PAUSE TestRateLimiterFeedback/429_enables_limiter228=== RUN TestRateLimiterFeedback/503_enables_limiter229=== PAUSE TestRateLimiterFeedback/503_enables_limiter230=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter231=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)232=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon233=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon234=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI235=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica236=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI237=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512238=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter239=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter240=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter241=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512242=== CONT TestCaseHackSuffix243=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text244=== CONT TestGetStorePathHash245--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)246=== CONT TestEncodeNixBase32WithRealHash247--- PASS: TestResolveStorePath (0.00s)248--- PASS: TestScriptTokenBadJSON (0.01s)249--- PASS: TestEncodeNixBase32WithRealHash (0.00s)250=== CONT TestRegisterUploadedObjectReusesConnections251=== PAUSE TestSetClientTLSErrors/missing_ca_file252=== RUN TestSetClientTLSErrors/invalid_ca_file253=== PAUSE TestSetClientTLSErrors/invalid_ca_file254=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry255=== RUN TestParsePathInfoJSON/Nix_format256=== PAUSE TestParsePathInfoJSON/Nix_format257=== RUN TestParsePathInfoJSON/Lix_format258=== PAUSE TestParsePathInfoJSON/Lix_format259=== RUN TestEncodeNixBase32/empty_input260=== CONT TestConvertHashToNix32261=== PAUSE TestPartSizeForNAR/small_stays_at_minimum262=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method263=== RUN TestGetStorePathHash/valid_store_path264=== RUN TestParsePathInfoJSON/empty_input265=== PAUSE TestGetStorePathHash/valid_store_path266=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method267=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun268=== PAUSE TestParsePathInfoJSON/empty_input269=== RUN TestParsePathInfoJSON/whitespace_only270=== PAUSE TestParsePathInfoJSON/whitespace_only271=== PAUSE TestEncodeNixBase32/empty_input272=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false273=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert274=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true275=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA276=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA277=== RUN TestSetClientTLS/preserves_debug_logging_transport278=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths2792026/11/11 23:21:28 INFO Garbage collection started280=== PAUSE TestSetClientTLS/preserves_debug_logging_transport281=== RUN TestGetStorePathHash/basename_without_hyphen_should_error282--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.01s)283=== CONT TestFilterOversizedClosures/no_limit_keeps_everything284=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths285=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error286=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2872026/11/11 23:21:28 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=2000288=== RUN TestConvertHashToNix32/SRI_format_to_Nix32289=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32290=== RUN TestConvertHashToNix32/already_Nix32_format291=== PAUSE TestConvertHashToNix32/already_Nix32_format292=== RUN TestConvertHashToNix32/invalid_format293=== PAUSE TestConvertHashToNix32/invalid_format294=== CONT TestRateLimiterFeedback/429_enables_limiter295=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)296=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum297=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum298=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts299=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts300=== RUN TestPartSizeForNAR/1_TiB301=== PAUSE TestPartSizeForNAR/1_TiB302=== RUN TestPartSizeForNAR/5_TiB_S3_max_object303=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object304=== RUN TestPartSizeForNAR/capped_at_5_GiB305=== PAUSE TestPartSizeForNAR/capped_at_5_GiB306=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error307=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error308=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter309=== RUN TestParsePathInfoJSON/invalid_JSON310=== PAUSE TestParsePathInfoJSON/invalid_JSON311=== CONT TestRateLimiterFeedback/503_enables_limiter312=== CONT TestFilterOversizedClosures/all_closures_skipped313--- PASS: TestStreamPushBatchesUnderLoad (0.00s)314 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)315 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)316=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha5123172026/11/11 23:21:28 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=50318--- PASS: TestFilterOversizedClosures (0.01s)319 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)320 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)321 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)322=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon3232026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:573813242026/11/11 23:21:28 WARN Rate limiter enabled after throttle name=server-test rate=53252026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:574543262026/11/11 23:21:28 WARN Rate limiter enabled after throttle name=s3-test rate=53272026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:574713282026/11/11 23:21:28 WARN Rate limiter backed off name=server-test rate=53292026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:573813302026/11/11 23:21:28 INFO Garbage collection started3312026/11/11 23:21:28 WARN Rate limiter enabled after throttle name=server-test rate=53322026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:574233332026/11/11 23:21:28 WARN Rate limiter backed off name=server-test rate=53342026/11/11 23:21:28 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=0335=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error336=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error337--- PASS: TestScriptTokenEmptyToken (0.01s)338=== CONT TestSetClientTLSErrors/invalid_ca_file339=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive340=== CONT TestPathInfoCACompatibility/old_string_format_-_text341=== CONT TestEncodeNixBase32/empty_input342=== CONT TestSetClientTLS/rejects_connection_without_client_cert343=== CONT TestSetClientTLS/preserves_debug_logging_transport3442026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:57381345=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter346=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3472026/11/11 23:21:28 WARN Garbage collection finished on another replica. Its statistics are not available here3482026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:57381349=== CONT TestConvertHashToNix32/SRI_format_to_Nix32350=== CONT TestConvertHashToNix32/invalid_format351=== CONT TestConvertHashToNix32/already_Nix32_format352=== CONT TestPartSizeForNAR/zero_stays_at_minimum353=== CONT TestPartSizeForNAR/5_TiB_S3_max_object354=== CONT TestPartSizeForNAR/1_TiB355=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts356=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum357=== CONT TestPartSizeForNAR/small_stays_at_minimum358=== CONT TestParsePathInfoJSON/Nix_format359=== CONT TestPartSizeForNAR/capped_at_5_GiB360=== CONT TestParsePathInfoJSON/invalid_JSON361=== CONT TestParsePathInfoJSON/whitespace_only362=== CONT TestParsePathInfoJSON/Lix_format363=== CONT TestParsePathInfoJSON/empty_input364=== CONT TestGetStorePathHash/valid_store_path365=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error366=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error367=== CONT TestGetStorePathHash/basename_without_hyphen_should_error3682026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:57381369=== CONT TestSetClientTLSErrors/missing_ca_file370=== CONT TestSetClientTLSErrors/missing_key_file371=== CONT TestPathInfoCACompatibility/null_ca_field372=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI373=== CONT TestSetClientTLSErrors/missing_cert_file374=== CONT TestEncodeNixBase32/test_string_hash375=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method376=== CONT TestPathInfoCACompatibility/new_structured_format_-_text377--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)378 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)379 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.01s)380--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.01s)381--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)382--- PASS: TestStreamPushRequestLine (0.02s)383--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)384--- PASS: TestConvertHashToNix32 (0.00s)385 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)386 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)387 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)388--- PASS: TestPartSizeForNAR (0.01s)389 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)390 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)391 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)392 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)393 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)394 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)395 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)396--- PASS: TestParsePathInfoJSON (0.01s)397 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)398 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)399 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)400 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)401 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)402--- PASS: TestGetStorePathHash (0.01s)403 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)404 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)405 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)406 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)407--- PASS: TestPathInfoHashCompatibility (0.00s)408 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)409 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)410 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)411 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)412--- PASS: TestSetClientTLSErrors (0.01s)413 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)414 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)415 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)416 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)417--- PASS: TestEncodeNixBase32 (0.00s)418 --- PASS: TestEncodeNixBase32/empty_input (0.00s)419 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)420--- PASS: TestPathInfoCACompatibility (0.01s)421 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)422 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)423 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)424 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)425 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)4262026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:573814272026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:57381428--- PASS: TestRateLimiterFeedback (0.00s)429 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)430 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)431 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)432 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)4332026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:573814342026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:573814352026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:573814362026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:573814372026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:57381438--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)4392026/11/11 23:21:28 http: TLS handshake error from 127.0.0.1:57480: remote error: tls: bad certificate4402026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:57381441--- PASS: TestSetClientTLS (0.01s)442 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)443 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)444 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)4452026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:57381446--- PASS: TestDumpPathWriterError (0.05s)4472026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:573814482026/11/11 23:21:28 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:57381449--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)450--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.05s)451--- PASS: TestDumpPathSingleFile (0.05s)452--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)453--- PASS: TestCaseHackSuffix (0.05s)454--- PASS: TestDumpPathMatchesNix (0.08s)4552026/11/11 23:21:28 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:57392/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:57392/api/uploads/complete4562026/11/11 23:21:28 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:57392/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:57392/api/uploads/complete4572026/11/11 23:21:28 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4582026/11/11 23:21:28 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4592026/11/11 23:21:28 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:57392/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:57392/api/uploads/complete4602026/11/11 23:21:28 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"461--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (0.10s)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 "_tribuchetbld8".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/8/scratch/9c621a23873fdf7e/build/postgres2984341448/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/8/scratch/9c621a23873fdf7e/build/postgres2984341448/data -l logfile start492493/private/var/tb/8/scratch/9c621a23873fdf7e/build/postgres2984341448:5432 - no response4942026-11-11 23:21:30.139 UTC [75350] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4952026-11-11 23:21:30.139 UTC [75350] LOG: listening on Unix socket "/private/var/tb/8/scratch/9c621a23873fdf7e/build/postgres2984341448/.s.PGSQL.5432"4962026-11-11 23:21:30.141 UTC [75357] LOG: database system was shut down at 2026-11-11 23:21:30 UTC4972026-11-11 23:21:30.142 UTC [75350] LOG: database system is ready to accept connections498/private/var/tb/8/scratch/9c621a23873fdf7e/build/postgres2984341448:5432 - accepting connections499{"timestamp":"2026-11-11T23:21:30.358091Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"29e8bc3c-c816-48b4-aacc-42b50d725463","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(11)"}500=== RUN TestAbortSucceeded501=== PAUSE TestAbortSucceeded502=== RUN TestService_AuthMiddleware503=== PAUSE TestService_AuthMiddleware504=== RUN TestService_AuthMiddleware_MTLSProxyHeader505=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader506=== RUN TestService_AuthMiddleware_MTLSBoundSubjects507=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects508=== RUN TestService_ReadAuthMiddleware509=== PAUSE TestService_ReadAuthMiddleware510=== RUN TestService_AuthMiddleware_OIDC511=== PAUSE TestService_AuthMiddleware_OIDC512=== RUN TestService_RequireScope_OIDC513=== PAUSE TestService_RequireScope_OIDC514=== RUN TestService_ReadScope_PublicByDefault515=== PAUSE TestService_ReadScope_PublicByDefault516=== RUN TestCacheConfigHandler517=== PAUSE TestCacheConfigHandler518=== RUN TestCacheStatsHandler519=== PAUSE TestCacheStatsHandler520=== RUN TestClientCADerivations521=== PAUSE TestClientCADerivations522=== RUN TestClientErrorHandling523=== PAUSE TestClientErrorHandling524=== RUN TestClientIntegration525=== PAUSE TestClientIntegration526=== RUN TestClientMultipleUploads527=== PAUSE TestClientMultipleUploads528=== RUN TestClientWithDependencies529=== PAUSE TestClientWithDependencies530=== RUN TestClientSharedPathCommittedMidPush531=== PAUSE TestClientSharedPathCommittedMidPush532=== RUN TestPinProtectsFromGC533=== PAUSE TestPinProtectsFromGC534=== RUN TestClientPushesUseOnePush535=== PAUSE TestClientPushesUseOnePush536=== RUN TestClientFallsBackToClosures537=== PAUSE TestClientFallsBackToClosures538=== RUN TestDeleteClosuresRacingPins539=== PAUSE TestDeleteClosuresRacingPins540=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock541=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock542=== RUN TestResolveDBConnectionString543=== PAUSE TestResolveDBConnectionString544=== RUN TestConnectWaitsForAPeerMigration545=== PAUSE TestConnectWaitsForAPeerMigration546=== RUN TestLeadElectsOneAndHandsOver547=== PAUSE TestLeadElectsOneAndHandsOver548=== RUN TestLeadIncumbentWinsAfterRestart5492026/11/11 23:21:30 INFO lead: acquired remote=192.0.2.1:1234 generation=15502026/11/11 23:21:31 INFO lead: released remote=192.0.2.1:1234 generation=15512026/11/11 23:21:31 INFO lead: acquired remote=192.0.2.1:1234 generation=25522026/11/11 23:21:32 INFO lead: released remote=192.0.2.1:1234 generation=2553--- PASS: TestLeadIncumbentWinsAfterRestart (1.87s)554=== RUN TestLeadUnannouncedStandbyYieldsToIncumbent555=== PAUSE TestLeadUnannouncedStandbyYieldsToIncumbent556=== RUN TestLeadIncumbentAnnouncesAtOnce557=== PAUSE TestLeadIncumbentAnnouncesAtOnce558=== RUN TestLeadGenerationGrowsWithEveryGrant559=== PAUSE TestLeadGenerationGrowsWithEveryGrant560=== RUN TestLeadEndsOnShutdown561=== PAUSE TestLeadEndsOnShutdown562=== RUN TestLeadEndsWhenItsConnectionHangs5632026/11/11 23:21:32 INFO lead: acquired remote=192.0.2.1:1234 generation=15642026-11-11 23:21:33.895 UTC [75393] FATAL: terminating connection due to administrator command5652026/11/11 23:21:34 INFO lead: acquired remote=192.0.2.1:1234 generation=25662026/11/11 23:21:35 WARN lead: lock connection lost error="timeout: context deadline exceeded"5672026/11/11 23:21:35 INFO lead: released remote=192.0.2.1:1234 generation=15682026/11/11 23:21:35 INFO lead: released remote=192.0.2.1:1234 generation=2569--- PASS: TestLeadEndsWhenItsConnectionHangs (2.96s)570=== RUN TestGCAdvisoryLockBlocksConcurrentRun571=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun572=== RUN TestGCBugBareHashReferences573=== PAUSE TestGCBugBareHashReferences574=== RUN TestGCMetrics575=== PAUSE TestGCMetrics576=== RUN TestPushDedupSurvivesConcurrentGC577=== PAUSE TestPushDedupSurvivesConcurrentGC578=== RUN TestDeduplicatedObjectsRecordedAsPending579=== PAUSE TestDeduplicatedObjectsRecordedAsPending580=== RUN TestGCSweepSkipsPendingObjects581=== PAUSE TestGCSweepSkipsPendingObjects582=== RUN TestTombstonedObjectOfferedWithoutWaiting583=== PAUSE TestTombstonedObjectOfferedWithoutWaiting584=== RUN TestGCSweepDeliversEachKeyOnce585=== PAUSE TestGCSweepDeliversEachKeyOnce586=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection587=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection588=== RUN TestForceGCDuringPushOffersSweptObject589=== PAUSE TestForceGCDuringPushOffersSweptObject590=== RUN TestFailedS3DeleteKeepsTombstone591=== PAUSE TestFailedS3DeleteKeepsTombstone592=== RUN TestSweepSkipsRowsLockedByPush593=== PAUSE TestSweepSkipsRowsLockedByPush594=== RUN TestRegisterCompletedObjectNeedsPendingRow595=== PAUSE TestRegisterCompletedObjectNeedsPendingRow596=== RUN TestGetExistingObjectsLocksRows597=== PAUSE TestGetExistingObjectsLocksRows598=== RUN TestSweepRechecksPendingAfterLocking599=== PAUSE TestSweepRechecksPendingAfterLocking600=== RUN TestPushWaitsForSweepHoldingRow601=== PAUSE TestPushWaitsForSweepHoldingRow602=== RUN TestCommitRacingPendingCleanupKeepsObjects603=== PAUSE TestCommitRacingPendingCleanupKeepsObjects604=== RUN TestGCEndsOnShutdown605=== PAUSE TestGCEndsOnShutdown606=== RUN TestGCTaskStore_StartNew607=== PAUSE TestGCTaskStore_StartNew608=== RUN TestGCTaskStore_DeduplicateSameParams609=== PAUSE TestGCTaskStore_DeduplicateSameParams610=== RUN TestGCTaskStore_ConflictDifferentParams611=== PAUSE TestGCTaskStore_ConflictDifferentParams612=== RUN TestGCTaskStore_GetEmpty613=== PAUSE TestGCTaskStore_GetEmpty614=== RUN TestGCTaskStore_GetReturnsLatest615=== PAUSE TestGCTaskStore_GetReturnsLatest616=== RUN TestGCTaskStore_CompletedAllowsNewTask617=== PAUSE TestGCTaskStore_CompletedAllowsNewTask618=== RUN TestGCTaskStore_PhaseUpdates619=== PAUSE TestGCTaskStore_PhaseUpdates620=== RUN TestGCTaskStore_Fail621=== PAUSE TestGCTaskStore_Fail622=== RUN TestGracefulShutdownDrainsInflight623=== PAUSE TestGracefulShutdownDrainsInflight624=== RUN TestService_healthCheckHandler625=== PAUSE TestService_healthCheckHandler626=== RUN TestService_readinessHandler627=== PAUSE TestService_readinessHandler628=== RUN TestGenerateLandingPage629=== PAUSE TestGenerateLandingPage630=== RUN TestEnsureAbortUploadsRule631=== PAUSE TestEnsureAbortUploadsRule632=== RUN TestCacheConfigHandlerMaxNarSize633=== PAUSE TestCacheConfigHandlerMaxNarSize634=== RUN TestCreatePendingClosureRejectsOversizedNAR635=== PAUSE TestCreatePendingClosureRejectsOversizedNAR636=== RUN TestNARDeduplicationMetadataUploadBug637=== PAUSE TestNARDeduplicationMetadataUploadBug638=== RUN TestMetricsInventory639=== PAUSE TestMetricsInventory640=== RUN TestMetricsCommit641=== PAUSE TestMetricsCommit642=== RUN TestService_NativeMTLS643=== PAUSE TestService_NativeMTLS644=== RUN TestServerTLSConfig645=== PAUSE TestServerTLSConfig646=== RUN TestMultipartCleanup647=== PAUSE TestMultipartCleanup648=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded649=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded650=== RUN TestPendingCleanupUsesOneCutoff651=== PAUSE TestPendingCleanupUsesOneCutoff652=== RUN TestObjectStatsTrigger653=== PAUSE TestObjectStatsTrigger654=== RUN TestObjectStatsUpdatedOncePerCommit655=== PAUSE TestObjectStatsUpdatedOncePerCommit656=== RUN TestOrphanedObjectsGC657=== PAUSE TestOrphanedObjectsGC658=== RUN TestOrphanedObjectsGCStressTest659=== PAUSE TestOrphanedObjectsGCStressTest660=== RUN TestCreatePin_ReservedPins661=== PAUSE TestCreatePin_ReservedPins662=== RUN TestPresentReportsOnlyClosureRoots663=== PAUSE TestPresentReportsOnlyClosureRoots664=== RUN TestPresentRefreshesOnlyStaleClosures665=== PAUSE TestPresentRefreshesOnlyStaleClosures666=== RUN TestPresentNotReportedWhileGCDeletesClosure667=== PAUSE TestPresentNotReportedWhileGCDeletesClosure668=== RUN TestParseSingleRange669=== PAUSE TestParseSingleRange670=== RUN TestProxyHeadersOnlyTrustedOnSocket6712026/11/11 23:21:35 INFO Starting HTTP server address=127.0.0.1:575036722026/11/11 23:21:35 INFO Starting HTTP server address=proxy.sock6732026/11/11 23:21:35 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6742026/11/11 23:21:35 INFO Shutdown signal received, draining in-flight requests timeout=10s675--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.16s)676=== RUN TestIsValidCachePath677=== PAUSE TestIsValidCachePath678=== RUN TestReadProxyNarinfo679=== PAUSE TestReadProxyNarinfo680=== RUN TestReadProxyNarinfoAlreadyDecompressed681=== PAUSE TestReadProxyNarinfoAlreadyDecompressed682=== RUN TestReadProxyContentNegotiation683=== PAUSE TestReadProxyContentNegotiation684=== RUN TestReadProxyNarStreaming685=== PAUSE TestReadProxyNarStreaming686=== RUN TestReadProxy404687=== PAUSE TestReadProxy404688=== RUN TestReadProxyInvalidPath689=== PAUSE TestReadProxyInvalidPath690=== RUN TestReadProxyHead691=== PAUSE TestReadProxyHead692=== RUN TestReadProxyOutlastsServerWriteTimeout693=== PAUSE TestReadProxyOutlastsServerWriteTimeout694=== RUN TestReadProxyConditionalGet695=== PAUSE TestReadProxyConditionalGet696=== RUN TestReadProxyRootRedirectsToIndexHTML697=== PAUSE TestReadProxyRootRedirectsToIndexHTML698=== RUN TestReadProxyDisabled699=== PAUSE TestReadProxyDisabled700=== RUN TestReadRedirectNar701=== PAUSE TestReadRedirectNar702=== RUN TestReadRedirectKeepsNarinfoProxied703=== PAUSE TestReadRedirectKeepsNarinfoProxied704=== RUN TestReadProxyRangeRequest705=== PAUSE TestReadProxyRangeRequest706=== RUN TestReadRedirectUsesPublicS3URL707=== PAUSE TestReadRedirectUsesPublicS3URL708=== RUN TestPush_OverlappingRootsStoreOneRowPerKey709=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey710=== RUN TestPush_CompleteCommitsEveryRoot711=== PAUSE TestPush_CompleteCommitsEveryRoot712=== RUN TestPush_RepeatedRootCommitsOnce713=== PAUSE TestPush_RepeatedRootCommitsOnce714=== RUN TestPush_CompleteWaitsForCleanupOfThePush715=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush716=== RUN TestPush_RootsAreLockedInByteOrder717=== PAUSE TestPush_RootsAreLockedInByteOrder718=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit719=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit720=== RUN TestPush_RejectsBadRequests721=== PAUSE TestPush_RejectsBadRequests722=== RUN TestPush_SignsNarinfosOfItsPendingObjects723=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects724=== RUN TestSharedNarBothUploadsComplete725=== PAUSE TestSharedNarBothUploadsComplete726=== RUN TestCompleteMultipartUpload_ErrorButObjectExists727=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists728=== RUN TestCompletedNarNotReofferedAcrossClosures729=== PAUSE TestCompletedNarNotReofferedAcrossClosures730=== RUN TestPresignedUploadRegisteredBeforeCommit731=== PAUSE TestPresignedUploadRegisteredBeforeCommit732=== RUN TestService_Rustfstest733=== PAUSE TestService_Rustfstest734=== RUN TestParseSize735=== PAUSE TestParseSize736=== RUN TestSkippedUploadsHandler737=== PAUSE TestSkippedUploadsHandler738=== RUN TestSystemdListenerNotActivated739--- PASS: TestSystemdListenerNotActivated (0.00s)740=== RUN TestWatchdogBeatsWhenHealthy741--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)742=== RUN TestWatchdogSkipsWhenUnhealthy7432026/11/11 23:21:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7442026/11/11 23:21:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7452026/11/11 23:21:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7462026/11/11 23:21:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7472026/11/11 23:21:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7482026/11/11 23:21:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7492026/11/11 23:21:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7502026/11/11 23:21:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7512026/11/11 23:21:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"752--- PASS: TestWatchdogSkipsWhenUnhealthy (0.21s)753=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle754=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle755=== RUN TestProxyWriteTimeout756=== PAUSE TestProxyWriteTimeout757=== RUN TestPendingClosureWriteTimeout758=== PAUSE TestPendingClosureWriteTimeout759=== RUN TestIsValidUploadKey760=== PAUSE TestIsValidUploadKey761=== RUN TestUploadHandlersRejectInvalidKeys762=== PAUSE TestUploadHandlersRejectInvalidKeys763=== RUN TestUploadHandlersRejectOversizedBody764=== PAUSE TestUploadHandlersRejectOversizedBody765=== RUN TestService_cleanupPendingClosuresHandler766=== PAUSE TestService_cleanupPendingClosuresHandler767=== RUN TestService_createPendingClosureHandler768=== PAUSE TestService_createPendingClosureHandler769=== RUN TestService_verifyS3Integrity770=== PAUSE TestService_verifyS3Integrity771=== RUN TestService_verifyS3ReuploadsStaleNarinfo772=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo773=== RUN TestCompleteMultipartUnregistered774=== PAUSE TestCompleteMultipartUnregistered775=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT776=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT777=== CONT TestReadProxy404778=== CONT TestForceGCDuringPushOffersSweptObject779=== CONT TestParseSingleRange780=== CONT TestDeleteClosuresRacingPins781=== CONT TestClientIntegration782=== CONT TestSharedNarBothUploadsComplete783=== CONT TestAbortSucceeded784--- PASS: TestAbortSucceeded (0.00s)785=== CONT TestRegisterCompletedObjectNeedsPendingRow786=== CONT TestPresentRefreshesOnlyStaleClosures787=== CONT TestClientFallsBackToClosures788=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows789=== CONT TestReadProxyNarStreaming790=== CONT TestReadProxyContentNegotiation791=== CONT TestReadProxyNarinfoAlreadyDecompressed792=== CONT TestSweepSkipsRowsLockedByPush793=== CONT TestFailedS3DeleteKeepsTombstone794=== CONT TestReadProxyNarinfo795=== CONT TestIsValidCachePath796=== RUN TestIsValidCachePath/narinfo797=== CONT TestClientPushesUseOnePush798=== CONT TestPinProtectsFromGC799=== RUN TestParseSingleRange/none800=== CONT TestClientSharedPathCommittedMidPush801=== CONT TestClientWithDependencies802=== CONT TestPresentNotReportedWhileGCDeletesClosure803=== CONT TestClientMultipleUploads804=== CONT TestPresentReportsOnlyClosureRoots805=== CONT TestCreatePin_ReservedPins806=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows807=== PAUSE TestParseSingleRange/none808=== PAUSE TestIsValidCachePath/narinfo809=== RUN TestParseSingleRange/unknown_unit810=== PAUSE TestParseSingleRange/unknown_unit811=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check812=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check813=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale814=== CONT TestOrphanedObjectsGCStressTest815=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars816=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars817=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale818=== RUN TestParseSingleRange/multi-range_ignored819=== RUN TestIsValidCachePath/nar_zst820=== PAUSE TestIsValidCachePath/nar_zst821=== PAUSE TestParseSingleRange/multi-range_ignored822=== RUN TestIsValidCachePath/nar_xz823=== RUN TestParseSingleRange/malformed_no_dash824=== PAUSE TestIsValidCachePath/nar_xz825=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh826=== PAUSE TestParseSingleRange/malformed_no_dash827=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh828=== RUN TestIsValidCachePath/nar_bz2829=== CONT TestOrphanedObjectsGC830=== RUN TestParseSingleRange/malformed_both_empty831=== PAUSE TestParseSingleRange/malformed_both_empty832=== RUN TestParseSingleRange/malformed_end_before_start833=== PAUSE TestParseSingleRange/malformed_end_before_start834=== RUN TestParseSingleRange/closed835=== PAUSE TestParseSingleRange/closed836=== RUN TestParseSingleRange/open-ended837=== PAUSE TestIsValidCachePath/nar_bz2838=== PAUSE TestParseSingleRange/open-ended839=== RUN TestParseSingleRange/end_clamped_to_size840=== RUN TestIsValidCachePath/nar_uncompressed841=== PAUSE TestIsValidCachePath/nar_uncompressed842=== PAUSE TestParseSingleRange/end_clamped_to_size843=== RUN TestIsValidCachePath/ls844=== PAUSE TestIsValidCachePath/ls845=== RUN TestIsValidCachePath/log846=== PAUSE TestIsValidCachePath/log847=== RUN TestParseSingleRange/suffix848=== RUN TestIsValidCachePath/realisation849=== PAUSE TestParseSingleRange/suffix850=== PAUSE TestIsValidCachePath/realisation851=== RUN TestIsValidCachePath/nix-cache-info852=== PAUSE TestIsValidCachePath/nix-cache-info853=== RUN TestParseSingleRange/suffix_exceeds_size854=== PAUSE TestParseSingleRange/suffix_exceeds_size855=== RUN TestParseSingleRange/single_byte856=== PAUSE TestParseSingleRange/single_byte857=== RUN TestParseSingleRange/start_past_EOF858=== RUN TestIsValidCachePath/index.html859=== PAUSE TestIsValidCachePath/index.html860=== RUN TestIsValidCachePath/traversal_parent861=== PAUSE TestIsValidCachePath/traversal_parent862=== RUN TestIsValidCachePath/traversal_in_middle863=== PAUSE TestIsValidCachePath/traversal_in_middle864=== RUN TestIsValidCachePath/invalid_char_e865=== PAUSE TestIsValidCachePath/invalid_char_e866=== PAUSE TestParseSingleRange/start_past_EOF867=== RUN TestParseSingleRange/start_far_past_EOF868=== RUN TestIsValidCachePath/invalid_char_u869=== PAUSE TestIsValidCachePath/invalid_char_u870=== RUN TestIsValidCachePath/random_path871=== PAUSE TestIsValidCachePath/random_path872=== RUN TestIsValidCachePath/empty873=== PAUSE TestIsValidCachePath/empty874=== RUN TestIsValidCachePath/leading_slash875=== PAUSE TestIsValidCachePath/leading_slash876=== RUN TestIsValidCachePath/wrong_extension877=== PAUSE TestIsValidCachePath/wrong_extension878=== RUN TestIsValidCachePath/short_hash879=== PAUSE TestIsValidCachePath/short_hash880=== PAUSE TestParseSingleRange/start_far_past_EOF881=== CONT TestObjectStatsUpdatedOncePerCommit882=== CONT TestObjectStatsTrigger8832026/11/11 23:21:35 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57505/oidc8842026/11/11 23:21:37 INFO Received uploads request method=POST path=/api/pending_closures8852026/11/11 23:21:37 INFO Received uploads request method=POST path=/api/pending_closures886--- PASS: TestObjectStatsUpdatedOncePerCommit (1.76s)887=== CONT TestPendingCleanupUsesOneCutoff888=== NAME TestClientIntegration889 client_integration_test.go:292: Created store path: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientIntegration721753220/002/store/7rkdsff47bi39jg9af9v78i5cf5p6jn6-test-file.txt890--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.06s)891=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded8922026/11/11 23:21:37 INFO Received push request method=POST path=/api/pushes8932026/11/11 23:21:37 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8942026/11/11 23:21:37 INFO Uploading 7rkdsff47bi39jg9af9v78i5cf5p6jn6-test-file.txt (152B)8952026/11/11 23:21:37 WARN Failed to register uploaded object key=7rkdsff47bi39jg9af9v78i5cf5p6jn6.ls error="server returned 404: 404 page not found\n"8962026/11/11 23:21:37 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"8972026/11/11 23:21:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8982026/11/11 23:21:37 INFO Signed narinfos id=1 count=18992026/11/11 23:21:37 INFO Uploading 1 narinfos9002026/11/11 23:21:37 INFO Received complete push request method=POST path=/api/pushes/1/complete9012026/11/11 23:21:37 WARN Failed to register uploaded object key=7rkdsff47bi39jg9af9v78i5cf5p6jn6.narinfo error="server returned 404: 404 page not found\n"9022026/11/11 23:21:37 INFO Completed push id=1 objects=3 duration=18.130542ms9032026/11/11 23:21:37 INFO Upload complete. (165ms)9042026/11/11 23:21:37 INFO All 1 paths already cached905=== NAME TestClientIntegration906 client_integration_test.go:318: Retrieved narinfo from S3:907 StorePath: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientIntegration721753220/002/store/7rkdsff47bi39jg9af9v78i5cf5p6jn6-test-file.txt908 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst909 Compression: zstd910 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1911 NarSize: 152912 References: 913 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1914 client_integration_test.go:319: Retrieved .ls file from S3 (compressed size: 77 bytes)915 client_integration_test.go:319: Decompressed .ls content (64 bytes):916 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}9172026/11/11 23:21:38 INFO Received push request method=POST path=/api/pushes9182026/11/11 23:21:38 INFO Object in database but missing from S3 key=7rkdsff47bi39jg9af9v78i5cf5p6jn6.ls9192026/11/11 23:21:38 WARN Found objects in DB but missing from S3, will re-upload count=19202026/11/11 23:21:38 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)9212026/11/11 23:21:38 INFO Received complete push request method=POST path=/api/pushes/2/complete9222026/11/11 23:21:38 WARN Failed to register uploaded object key=7rkdsff47bi39jg9af9v78i5cf5p6jn6.ls error="server returned 404: 404 page not found\n"9232026/11/11 23:21:38 INFO Completed push id=2 objects=3 duration=967.041µs9242026/11/11 23:21:38 INFO Upload complete. (120ms)925 client_integration_test.go:336: Retrieved .ls file from S3 (compressed size: 62 bytes)926 client_integration_test.go:336: Decompressed .ls content (49 bytes):927 {"version":1,"root":{"type":"regular","size":39}}928--- PASS: TestReadProxy404 (2.63s)929=== CONT TestMultipartCleanup9302026/11/11 23:21:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9312026/11/11 23:21:38 INFO Received push request method=POST path=/api/pushes9322026/11/11 23:21:38 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)9332026/11/11 23:21:38 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YjNjMWFiNmEtOTg0ZS00MjcxLThmZGEtOGI2NmIwNDdkZGU4LmE5YWFmYWVjLWNjM2MtNGY2Ni1hMDU0LTg3NGIxMzYxODQzM3gxNzk0NDM5Mjk3MDYzOTg3MDAw parts=129342026/11/11 23:21:38 INFO Received complete push request method=POST path=/api/pushes/3/complete9352026/11/11 23:21:38 WARN Failed to register uploaded object key=7rkdsff47bi39jg9af9v78i5cf5p6jn6.ls error="server returned 404: 404 page not found\n"9362026/11/11 23:21:38 INFO Completed push id=3 objects=3 duration=882µs9372026/11/11 23:21:38 INFO Upload complete. (127ms)938=== NAME TestClientIntegration939 client_integration_test.go:353: Retrieved .ls file from S3 (compressed size: 62 bytes)940 client_integration_test.go:353: Decompressed .ls content (49 bytes):941 {"version":1,"root":{"type":"regular","size":39}}942 client_integration_test.go:364: Testing garbage collection...9432026/11/11 23:21:38 INFO Starting cleanup of old closures method=DELETE path=/api/closures9442026/11/11 23:21:38 INFO Garbage collection started9452026/11/11 23:21:38 INFO Aborted multipart uploads count=0 kept=09462026/11/11 23:21:38 WARN Force mode enabled - objects will be deleted immediately without grace period9472026/11/11 23:21:38 INFO Received push request method=POST path=/api/pushes9482026/11/11 23:21:39 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)9492026/11/11 23:21:39 INFO Uploading pb6m950z1zn0azq5kqdwf83nqjvnz2mx-shared-dep (136B)9502026/11/11 23:21:39 INFO Uploading zkwk3fvaq87vdaffmww1p9y0rdj0qa8i-a (256B)9512026/11/11 23:21:39 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=0952--- PASS: TestObjectStatsTrigger (3.36s)953=== CONT TestServerTLSConfig954=== RUN TestServerTLSConfig/no_client_CA955=== PAUSE TestServerTLSConfig/no_client_CA956=== RUN TestServerTLSConfig/missing_CA_file957=== PAUSE TestServerTLSConfig/missing_CA_file9582026/11/11 23:21:39 WARN Failed to register uploaded object key=zkwk3fvaq87vdaffmww1p9y0rdj0qa8i.ls error="server returned 404: 404 page not found\n"959=== RUN TestServerTLSConfig/not_a_PEM_file960=== PAUSE TestServerTLSConfig/not_a_PEM_file9612026/11/11 23:21:39 WARN Failed to register uploaded object key=pb6m950z1zn0azq5kqdwf83nqjvnz2mx.ls error="server returned 404: 404 page not found\n"962=== CONT TestService_NativeMTLS9632026/11/11 23:21:39 INFO Vacuumed table table=pending_closures9642026/11/11 23:21:39 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"9652026/11/11 23:21:39 WARN Failed to register uploaded object key=nar/0wzpvx6k3z53x5rbh2vgnb5l0hl7kzb6h8wgl9q5f9mxak6mp2k9.nar.zst error="server returned 404: 404 page not found\n"9662026/11/11 23:21:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9672026/11/11 23:21:39 WARN Failed to register uploaded object key=nhb7vfh2cp76a2zp2478wz7771q4imsl.ls error="server returned 404: 404 page not found\n"9682026/11/11 23:21:39 INFO Signed narinfos id=1 count=39692026/11/11 23:21:39 INFO Uploading 3 narinfos9702026/11/11 23:21:39 INFO Vacuumed table table=pending_objects9712026/11/11 23:21:39 INFO Vacuumed table table=multipart_uploads9722026/11/11 23:21:39 INFO Vacuumed table table=closures9732026/11/11 23:21:39 WARN Failed to register uploaded object key=zkwk3fvaq87vdaffmww1p9y0rdj0qa8i.narinfo error="server returned 404: 404 page not found\n"9742026/11/11 23:21:39 WARN Failed to register uploaded object key=pb6m950z1zn0azq5kqdwf83nqjvnz2mx.narinfo error="server returned 404: 404 page not found\n"9752026/11/11 23:21:39 INFO Vacuumed table table=objects9762026/11/11 23:21:39 INFO Received complete push request method=POST path=/api/pushes/1/complete9772026/11/11 23:21:39 WARN Failed to register uploaded object key=nhb7vfh2cp76a2zp2478wz7771q4imsl.narinfo error="server returned 404: 404 page not found\n"9782026/11/11 23:21:39 INFO Completed push id=1 objects=8 duration=17.406084ms9792026/11/11 23:21:39 INFO Upload complete. (345ms)980=== NAME TestClientPushesUseOnePush981 client_pushes_test.go:97: Retrieved narinfo from S3:982 StorePath: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientPushesUseOnePush157888768/001/store/pb6m950z1zn0azq5kqdwf83nqjvnz2mx-shared-dep983 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst984 Compression: zstd985 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82986 NarSize: 136987 References: 988 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n989 client_pushes_test.go:97: Retrieved narinfo from S3:990 StorePath: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientPushesUseOnePush157888768/001/store/zkwk3fvaq87vdaffmww1p9y0rdj0qa8i-a991 URL: nar/0wzpvx6k3z53x5rbh2vgnb5l0hl7kzb6h8wgl9q5f9mxak6mp2k9.nar.zst992 Compression: zstd993 NarHash: sha256:0wzpvx6k3z53x5rbh2vgnb5l0hl7kzb6h8wgl9q5f9mxak6mp2k9994 NarSize: 256995 References: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientPushesUseOnePush157888768/001/store/pb6m950z1zn0azq5kqdwf83nqjvnz2mx-shared-dep996 CA: text:sha256:14xbjv7dgip5yp8m09ssx2vym7a68nc5ka0sr73dc26swn8j57sr997 client_pushes_test.go:97: Retrieved narinfo from S3:998 StorePath: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientPushesUseOnePush157888768/001/store/nhb7vfh2cp76a2zp2478wz7771q4imsl-b999 URL: nar/0wzpvx6k3z53x5rbh2vgnb5l0hl7kzb6h8wgl9q5f9mxak6mp2k9.nar.zst1000 Compression: zstd1001 NarHash: sha256:0wzpvx6k3z53x5rbh2vgnb5l0hl7kzb6h8wgl9q5f9mxak6mp2k91002 NarSize: 2561003 References: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientPushesUseOnePush157888768/001/store/pb6m950z1zn0azq5kqdwf83nqjvnz2mx-shared-dep1004 CA: text:sha256:14xbjv7dgip5yp8m09ssx2vym7a68nc5ka0sr73dc26swn8j57sr10052026/11/11 23:21:39 INFO Received uploads request method=POST path=/api/pending_closures10062026/11/11 23:21:39 INFO Received uploads request method=POST path=/api/pending_closures10072026/11/11 23:21:39 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)10082026/11/11 23:21:39 INFO Uploading 5apa0b98iihks74jr1czga6cx3wapymb-shared-dep (136B)10092026/11/11 23:21:39 INFO Uploading 78dn2s9p0jwivyv77xllrvk8zc7kdhz4-b (256B)1010--- PASS: TestClientPushesUseOnePush (3.56s)1011=== CONT TestMetricsCommit10122026/11/11 23:21:39 WARN Failed to register uploaded object key=5apa0b98iihks74jr1czga6cx3wapymb.ls error="server returned 404: 404 page not found\n"10132026/11/11 23:21:39 WARN Failed to register uploaded object key=1wf9kv5k922v0dbqddb3j2vxavx8s51h.ls error="server returned 404: 404 page not found\n"10142026/11/11 23:21:39 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"10152026/11/11 23:21:39 WARN Failed to register uploaded object key=78dn2s9p0jwivyv77xllrvk8zc7kdhz4.ls error="server returned 404: 404 page not found\n"10162026/11/11 23:21:39 WARN Failed to register uploaded object key=nar/1476iws12s49bp82zppm8vgyv611x8vi2fndqscrvn1432yyc8wk.nar.zst error="server returned 404: 404 page not found\n"10172026/11/11 23:21:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10182026/11/11 23:21:39 INFO Aborted multipart uploads count=0 kept=010192026/11/11 23:21:39 INFO Signed narinfos id=1 count=210202026/11/11 23:21:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign10212026/11/11 23:21:39 INFO Signed narinfos id=2 count=210222026/11/11 23:21:39 INFO Uploading 4 narinfos10232026/11/11 23:21:39 WARN Force mode enabled - objects will be deleted immediately without grace period10242026/11/11 23:21:39 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=010252026/11/11 23:21:39 INFO Vacuumed table table=pending_closures10262026/11/11 23:21:39 WARN Failed to register uploaded object key=5apa0b98iihks74jr1czga6cx3wapymb.narinfo error="server returned 404: 404 page not found\n"10272026/11/11 23:21:39 WARN Failed to register uploaded object key=78dn2s9p0jwivyv77xllrvk8zc7kdhz4.narinfo error="server returned 404: 404 page not found\n"10282026/11/11 23:21:39 INFO Vacuumed table table=pending_objects10292026/11/11 23:21:39 WARN Failed to register uploaded object key=1wf9kv5k922v0dbqddb3j2vxavx8s51h.narinfo error="server returned 404: 404 page not found\n"10302026/11/11 23:21:39 INFO Vacuumed table table=multipart_uploads10312026/11/11 23:21:39 INFO Vacuumed table table=closures10322026/11/11 23:21:39 INFO Vacuumed table table=objects10332026/11/11 23:21:39 INFO Aborted multipart uploads count=0 kept=010342026/11/11 23:21:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10352026/11/11 23:21:39 WARN Failed to register uploaded object key=5apa0b98iihks74jr1czga6cx3wapymb.narinfo error="server returned 404: 404 page not found\n"10362026/11/11 23:21:39 WARN Force mode enabled - objects will be deleted immediately without grace period10372026/11/11 23:21:39 INFO Completed upload id=1 objects=6 duration=16.64625ms10382026/11/11 23:21:39 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10392026/11/11 23:21:39 INFO Completed upload id=2 objects=6 duration=406.542µs10402026/11/11 23:21:39 INFO Upload complete. (293ms)1041=== NAME TestClientFallsBackToClosures1042 client_pushes_test.go:112: Retrieved narinfo from S3:1043 StorePath: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientFallsBackToClosures4188595566/001/store/5apa0b98iihks74jr1czga6cx3wapymb-shared-dep1044 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1045 Compression: zstd1046 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821047 NarSize: 1361048 References: 1049 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1050 client_pushes_test.go:112: Retrieved narinfo from S3:1051 StorePath: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientFallsBackToClosures4188595566/001/store/1wf9kv5k922v0dbqddb3j2vxavx8s51h-a1052 URL: nar/1476iws12s49bp82zppm8vgyv611x8vi2fndqscrvn1432yyc8wk.nar.zst1053 Compression: zstd1054 NarHash: sha256:1476iws12s49bp82zppm8vgyv611x8vi2fndqscrvn1432yyc8wk1055 NarSize: 2561056 References: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientFallsBackToClosures4188595566/001/store/5apa0b98iihks74jr1czga6cx3wapymb-shared-dep1057 CA: text:sha256:0i1ririxhlyn4hg33na2q9jjpf3d09a74hf2sr9l81qr9swl24751058 client_pushes_test.go:112: Retrieved narinfo from S3:1059 StorePath: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientFallsBackToClosures4188595566/001/store/78dn2s9p0jwivyv77xllrvk8zc7kdhz4-b1060 URL: nar/1476iws12s49bp82zppm8vgyv611x8vi2fndqscrvn1432yyc8wk.nar.zst1061 Compression: zstd1062 NarHash: sha256:1476iws12s49bp82zppm8vgyv611x8vi2fndqscrvn1432yyc8wk1063 NarSize: 2561064 References: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientFallsBackToClosures4188595566/001/store/5apa0b98iihks74jr1czga6cx3wapymb-shared-dep1065 CA: text:sha256:0i1ririxhlyn4hg33na2q9jjpf3d09a74hf2sr9l81qr9swl24751066--- PASS: TestClientFallsBackToClosures (3.85s)1067=== CONT TestMetricsInventory10682026/11/11 23:21:39 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=010692026/11/11 23:21:39 INFO Vacuumed table table=pending_closures10702026/11/11 23:21:39 INFO Vacuumed table table=pending_objects10712026/11/11 23:21:39 INFO Vacuumed table table=multipart_uploads10722026/11/11 23:21:39 INFO Vacuumed table table=closures10732026/11/11 23:21:39 INFO Vacuumed table table=objects10742026/11/11 23:21:39 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1075--- PASS: TestReadProxyNarinfo (3.99s)1076=== CONT TestNARDeduplicationMetadataUploadBug1077--- PASS: TestSweepSkipsRowsLockedByPush (3.99s)1078=== CONT TestCreatePendingClosureRejectsOversizedNAR10792026/11/11 23:21:39 INFO Received uploads request method=POST path=/api/pending_closures1080--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1081=== CONT TestCacheConfigHandlerMaxNarSize1082--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1083=== CONT TestEnsureAbortUploadsRule1084--- PASS: TestPresentRefreshesOnlyStaleClosures (4.15s)1085=== CONT TestService_RequireScope_OIDC10862026/11/11 23:21:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57562/oidc10872026/11/11 23:21:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1088--- PASS: TestRegisterCompletedObjectNeedsPendingRow (4.36s)1089=== CONT TestClientErrorHandling1090=== RUN TestClientErrorHandling/InvalidStorePath1091=== PAUSE TestClientErrorHandling/InvalidStorePath1092=== RUN TestClientErrorHandling/InvalidAuthToken1093=== PAUSE TestClientErrorHandling/InvalidAuthToken1094=== RUN TestClientErrorHandling/ServerNotAvailable1095=== PAUSE TestClientErrorHandling/ServerNotAvailable1096=== CONT TestClientCADerivations10972026/11/11 23:21:40 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YjNjMWFiNmEtOTg0ZS00MjcxLThmZGEtOGI2NmIwNDdkZGU4LjI2NWIwYjdiLWI3ODQtNDc0OC1hNGM4LWUzYTk3NGE0ZGNiYngxNzk0NDM5Mjk3MTIxNjgxMDAw parts=121098--- PASS: TestSharedNarBothUploadsComplete (4.41s)1099=== CONT TestCacheStatsHandler1100--- PASS: TestReadProxyNarStreaming (4.55s)1101=== CONT TestGenerateLandingPage1102--- PASS: TestGenerateLandingPage (0.00s)1103=== CONT TestCacheConfigHandler1104=== RUN TestCacheConfigHandler/full_config,_no_issuer1105=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1106=== RUN TestCacheConfigHandler/no_cache_url_configured1107=== PAUSE TestCacheConfigHandler/no_cache_url_configured1108=== RUN TestCacheConfigHandler/no_signing_keys1109=== PAUSE TestCacheConfigHandler/no_signing_keys1110=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1111=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1112=== CONT TestService_ReadScope_PublicByDefault1113--- PASS: TestReadProxyContentNegotiation (4.81s)1114=== CONT TestService_readinessHandler11152026/11/11 23:21:40 INFO Received uploads request method=POST path=/api/pending_closures11162026/11/11 23:21:40 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01117=== NAME TestClientIntegration1118 client_integration_test.go:371: Objects in database after GC:1119 client_integration_test.go:371: Successfully deleted all objects with GC --force1120--- PASS: TestClientIntegration (5.07s)1121=== CONT TestService_healthCheckHandler11222026/11/11 23:21:40 INFO Aborted multipart uploads count=0 kept=011232026/11/11 23:21:40 WARN Force mode enabled - objects will be deleted immediately without grace period11242026/11/11 23:21:40 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."11252026/11/11 23:21:40 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1126--- PASS: TestFailedS3DeleteKeepsTombstone (5.18s)1127=== CONT TestGracefulShutdownDrainsInflight11282026/11/11 23:21:40 INFO Starting HTTP server address=127.0.0.1:5757711292026/11/11 23:21:40 INFO Shutdown signal received, draining in-flight requests timeout=10s1130--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1131=== CONT TestGCTaskStore_Fail1132--- PASS: TestGCTaskStore_Fail (0.00s)1133=== CONT TestGCAdvisoryLockBlocksConcurrentRun1134=== NAME TestClientMultipleUploads1135 client_integration_test.go:406: Created store path 0: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientMultipleUploads1144659117/001/store/rywcbi1nb7fjp72yxl0wl1gwv46zr6gl-test-file-0.txt1136 client_integration_test.go:406: Created store path 1: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientMultipleUploads1144659117/001/store/77nsqi579m4m6dvgl0grwywxsqdp8ms0-test-file-1.txt1137 client_integration_test.go:406: Created store path 2: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientMultipleUploads1144659117/001/store/qmhqn088h4gs725af22khrxwf0rgya21-test-file-2.txt11382026/11/11 23:21:41 INFO Received push request method=POST path=/api/pushes11392026/11/11 23:21:41 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)11402026/11/11 23:21:41 INFO Uploading rywcbi1nb7fjp72yxl0wl1gwv46zr6gl-test-file-0.txt (160B)11412026/11/11 23:21:41 INFO Uploading qmhqn088h4gs725af22khrxwf0rgya21-test-file-2.txt (160B)11422026/11/11 23:21:41 INFO Uploading 77nsqi579m4m6dvgl0grwywxsqdp8ms0-test-file-1.txt (160B)11432026/11/11 23:21:41 WARN Failed to register uploaded object key=77nsqi579m4m6dvgl0grwywxsqdp8ms0.ls error="server returned 404: 404 page not found\n"11442026/11/11 23:21:41 WARN Failed to register uploaded object key=rywcbi1nb7fjp72yxl0wl1gwv46zr6gl.ls error="server returned 404: 404 page not found\n"11452026/11/11 23:21:41 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"11462026/11/11 23:21:41 WARN Failed to register uploaded object key=qmhqn088h4gs725af22khrxwf0rgya21.ls error="server returned 404: 404 page not found\n"11472026/11/11 23:21:41 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"11482026/11/11 23:21:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11492026/11/11 23:21:41 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"11502026/11/11 23:21:41 INFO Signed narinfos id=1 count=311512026/11/11 23:21:41 INFO Uploading 3 narinfos11522026/11/11 23:21:41 INFO Received push request method=POST path=/api/pushes11532026/11/11 23:21:41 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)11542026/11/11 23:21:41 INFO Uploading vpmkci454c07fm28cj7ayhr3wbph2dnl-top (264B)11552026/11/11 23:21:41 INFO Uploading 3g0c5qjb0h3jkvxkcmaghd0a29cjk29k-shared-dep (136B)11562026/11/11 23:21:41 WARN Failed to register uploaded object key=77nsqi579m4m6dvgl0grwywxsqdp8ms0.narinfo error="server returned 404: 404 page not found\n"11572026/11/11 23:21:41 WARN Failed to register uploaded object key=qmhqn088h4gs725af22khrxwf0rgya21.narinfo error="server returned 404: 404 page not found\n"11582026/11/11 23:21:41 INFO Received complete push request method=POST path=/api/pushes/1/complete11592026/11/11 23:21:41 WARN Failed to register uploaded object key=rywcbi1nb7fjp72yxl0wl1gwv46zr6gl.narinfo error="server returned 404: 404 page not found\n"11602026/11/11 23:21:41 WARN Failed to register uploaded object key=vpmkci454c07fm28cj7ayhr3wbph2dnl.ls error="server returned 404: 404 page not found\n"11612026/11/11 23:21:41 INFO Completed push id=1 objects=9 duration=30.451625ms11622026/11/11 23:21:41 INFO Upload complete. (269ms)1163 client_integration_test.go:417: Uploaded 3 paths in 305.601042ms11642026/11/11 23:21:41 WARN Failed to register uploaded object key=3g0c5qjb0h3jkvxkcmaghd0a29cjk29k.ls error="server returned 404: 404 page not found\n"11652026/11/11 23:21:41 WARN Failed to register uploaded object key=nar/0hljl8rxg6z9a9rgkz0hqzjcgb34fg2g2f5n1lvk7yawhlg35q2l.nar.zst error="server returned 404: 404 page not found\n"11662026/11/11 23:21:41 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11672026/11/11 23:21:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11682026/11/11 23:21:41 INFO Signed narinfos id=1 count=211692026/11/11 23:21:41 INFO Uploading 2 narinfos1170--- PASS: TestDeleteClosuresRacingPins (5.78s)1171=== CONT TestGCTaskStore_PhaseUpdates1172--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1173=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection11742026/11/11 23:21:41 WARN Failed to register uploaded object key=vpmkci454c07fm28cj7ayhr3wbph2dnl.narinfo error="server returned 404: 404 page not found\n"11752026/11/11 23:21:41 INFO Received complete push request method=POST path=/api/pushes/1/complete11762026/11/11 23:21:41 WARN Failed to register uploaded object key=3g0c5qjb0h3jkvxkcmaghd0a29cjk29k.narinfo error="server returned 404: 404 page not found\n"11772026/11/11 23:21:41 INFO Completed push id=1 objects=6 duration=15.010834ms11782026/11/11 23:21:41 INFO Upload complete. (259ms)1179=== NAME TestClientSharedPathCommittedMidPush1180 client_integration_test.go:728: Retrieved narinfo from S3:1181 StorePath: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientSharedPathCommittedMidPush630401697/001/store/3g0c5qjb0h3jkvxkcmaghd0a29cjk29k-shared-dep1182 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1183 Compression: zstd1184 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821185 NarSize: 1361186 References: 1187 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1188 client_integration_test.go:728: Retrieved narinfo from S3:1189 StorePath: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientSharedPathCommittedMidPush630401697/001/store/vpmkci454c07fm28cj7ayhr3wbph2dnl-top1190 URL: nar/0hljl8rxg6z9a9rgkz0hqzjcgb34fg2g2f5n1lvk7yawhlg35q2l.nar.zst1191 Compression: zstd1192 NarHash: sha256:0hljl8rxg6z9a9rgkz0hqzjcgb34fg2g2f5n1lvk7yawhlg35q2l1193 NarSize: 2641194 References: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientSharedPathCommittedMidPush630401697/001/store/3g0c5qjb0h3jkvxkcmaghd0a29cjk29k-shared-dep1195 CA: text:sha256:0gf10h0g2mfkpc5laggvhgd5jl72nn6372588pfab8li7h0qyhb31196--- PASS: TestClientMultipleUploads (5.86s)1197=== CONT TestGCSweepDeliversEachKeyOnce1198--- PASS: TestClientSharedPathCommittedMidPush (5.89s)1199=== CONT TestTombstonedObjectOfferedWithoutWaiting1200=== NAME TestPinProtectsFromGC1201 client_integration_test.go:779: Pinned store path: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestPinProtectsFromGC337539253/001/store/rsj4gmxalcdswv7ppaz5qw3hwb456aq5-pinned-file.txt1202 client_integration_test.go:780: Unpinned store path: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestPinProtectsFromGC337539253/001/store/m2l2hxsvqs9215mdm0ixdjy64mi0fx93-unpinned-file.txt12032026/11/11 23:21:41 INFO Received push request method=POST path=/api/pushes12042026/11/11 23:21:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12052026/11/11 23:21:42 INFO Uploading rsj4gmxalcdswv7ppaz5qw3hwb456aq5-pinned-file.txt (128B)12062026/11/11 23:21:42 WARN Failed to register uploaded object key=rsj4gmxalcdswv7ppaz5qw3hwb456aq5.ls error="server returned 404: 404 page not found\n"12072026/11/11 23:21:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12082026/11/11 23:21:42 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"12092026/11/11 23:21:42 INFO Signed narinfos id=1 count=112102026/11/11 23:21:42 INFO Uploading 1 narinfos12112026/11/11 23:21:42 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12122026/11/11 23:21:42 WARN Refused reserved pin name=worker-x86_64-linux12132026/11/11 23:21:42 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12142026/11/11 23:21:42 INFO Received create pin request method=POST path=/api/pins/my-app12152026/11/11 23:21:42 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1216--- PASS: TestCreatePin_ReservedPins (6.40s)1217=== CONT TestGCSweepSkipsPendingObjects12182026/11/11 23:21:42 INFO Received complete push request method=POST path=/api/pushes/1/complete12192026/11/11 23:21:42 WARN Failed to register uploaded object key=rsj4gmxalcdswv7ppaz5qw3hwb456aq5.narinfo error="server returned 404: 404 page not found\n"12202026/11/11 23:21:42 INFO Completed push id=1 objects=3 duration=27.395416ms12212026/11/11 23:21:42 INFO Upload complete. (234ms)12222026/11/11 23:21:42 INFO Received push request method=POST path=/api/pushes12232026/11/11 23:21:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12242026/11/11 23:21:42 INFO Uploading m2l2hxsvqs9215mdm0ixdjy64mi0fx93-unpinned-file.txt (128B)12252026/11/11 23:21:42 WARN Failed to register uploaded object key=m2l2hxsvqs9215mdm0ixdjy64mi0fx93.ls error="server returned 404: 404 page not found\n"12262026/11/11 23:21:42 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12272026/11/11 23:21:42 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"12282026/11/11 23:21:42 INFO Signed narinfos id=2 count=112292026/11/11 23:21:42 INFO Uploading 1 narinfos12302026/11/11 23:21:42 INFO Received complete push request method=POST path=/api/pushes/2/complete12312026/11/11 23:21:42 WARN Failed to register uploaded object key=m2l2hxsvqs9215mdm0ixdjy64mi0fx93.narinfo error="server returned 404: 404 page not found\n"12322026/11/11 23:21:42 INFO Completed push id=2 objects=3 duration=1.050875ms12332026/11/11 23:21:42 INFO Upload complete. (182ms)12342026/11/11 23:21:42 INFO Starting cleanup of old closures method=DELETE path=/api/closures12352026/11/11 23:21:42 INFO Garbage collection started12362026/11/11 23:21:42 INFO Aborted multipart uploads count=0 kept=012372026/11/11 23:21:42 WARN Force mode enabled - objects will be deleted immediately without grace period1238--- PASS: TestPresentReportsOnlyClosureRoots (7.03s)1239=== CONT TestGCTaskStore_CompletedAllowsNewTask1240--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1241=== CONT TestGCTaskStore_GetReturnsLatest1242--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1243=== CONT TestGCTaskStore_GetEmpty1244--- PASS: TestGCTaskStore_GetEmpty (0.00s)1245=== CONT TestGCTaskStore_ConflictDifferentParams1246--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1247=== CONT TestDeduplicatedObjectsRecordedAsPending12482026/11/11 23:21:42 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=012492026/11/11 23:21:42 INFO Vacuumed table table=pending_closures1250=== NAME TestClientWithDependencies1251 client_integration_test.go:661: Built derivation: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientWithDependencies2200607012/001/store/jamph5pcjq411raf9g8br77svzlj891i-test-script12522026/11/11 23:21:42 INFO Vacuumed table table=pending_objects12532026/11/11 23:21:42 INFO Vacuumed table table=multipart_uploads12542026/11/11 23:21:43 INFO Vacuumed table table=closures1255 client_integration_test.go:663: Found 1 dependencies (including self)12562026/11/11 23:21:43 INFO Received uploads request method=POST path=/api/pending_closures12572026/11/11 23:21:43 INFO Vacuumed table table=objects12582026/11/11 23:21:43 INFO Received push request method=POST path=/api/pushes12592026/11/11 23:21:43 INFO Received uploads request method=POST path=/api/pending_closures12602026/11/11 23:21:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12612026/11/11 23:21:43 INFO Uploading jamph5pcjq411raf9g8br77svzlj891i-test-script (136B)12622026/11/11 23:21:43 INFO Received cleanup request method=DELETE path=/api/pending_closures12632026/11/11 23:21:43 WARN Failed to register uploaded object key=jamph5pcjq411raf9g8br77svzlj891i.ls error="server returned 404: 404 page not found\n"12642026/11/11 23:21:43 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"12652026/11/11 23:21:43 WARN Failed to register uploaded object key=log/miqwhd6hjd5lv2vx1zjm8ys16b1h2z9n-test-script.drv error="server returned 404: 404 page not found\n"12662026/11/11 23:21:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12672026/11/11 23:21:43 INFO Signed narinfos id=1 count=112682026/11/11 23:21:43 INFO Uploading 1 narinfos12692026/11/11 23:21:43 INFO Received complete push request method=POST path=/api/pushes/1/complete12702026/11/11 23:21:43 WARN Failed to register uploaded object key=jamph5pcjq411raf9g8br77svzlj891i.narinfo error="server returned 404: 404 page not found\n"12712026/11/11 23:21:43 INFO Completed push id=1 objects=4 duration=33.539083ms12722026/11/11 23:21:43 INFO Upload complete. (320ms)1273 client_integration_test.go:665: Skipping nix copy test - isolated store (/private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientWithDependencies2200607012/001/store) requires matching store prefix12742026/11/11 23:21:43 INFO Received uploads request method=POST path=/api/pending_closures1275--- PASS: TestClientWithDependencies (7.85s)1276=== CONT TestGCTaskStore_DeduplicateSameParams1277--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1278=== CONT TestGCTaskStore_StartNew1279--- PASS: TestGCTaskStore_StartNew (0.00s)1280=== CONT TestGCEndsOnShutdown1281=== RUN TestGCEndsOnShutdown/before_the_run1282=== PAUSE TestGCEndsOnShutdown/before_the_run1283=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1284=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1285=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1286=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1287=== CONT TestCommitRacingPendingCleanupKeepsObjects1288--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (5.90s)1289=== CONT TestPushDedupSurvivesConcurrentGC1290=== NAME TestOrphanedObjectsGC1291 orphaned_objects_gc_test.go:287: GC Test Summary:1292 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1293 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1294 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1295 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1296 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1297--- PASS: TestOrphanedObjectsGC (8.29s)1298=== CONT TestGCMetrics12992026/11/11 23:21:44 INFO Received uploads request method=POST path=/api/pending_closures13002026/11/11 23:21:44 INFO Received cleanup request method=DELETE path=/api/pending_closures13012026/11/11 23:21:44 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket30/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""13022026/11/11 23:21:44 INFO Aborted multipart uploads count=0 kept=113032026/11/11 23:21:44 INFO Received cleanup request method=DELETE path=/api/pending_closures13042026/11/11 23:21:44 INFO Aborted multipart uploads count=1 kept=01305--- PASS: TestMultipartCleanup (6.08s)1306=== CONT TestGCBugBareHashReferences13072026/11/11 23:21:44 WARN mTLS auth: subject not in bound subjects subject="CN=reader"13082026/11/11 23:21:44 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1309--- PASS: TestService_NativeMTLS (5.33s)1310=== CONT TestPushWaitsForSweepHoldingRow13112026/11/11 23:21:44 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=013122026/11/11 23:21:44 INFO Received create pin request method=POST path=/api/pins/myapp13132026/11/11 23:21:44 INFO Created/updated pin name=myapp store_path=/private/var/tb/8/scratch/9c621a23873fdf7e/build/TestPinProtectsFromGC337539253/001/store/rsj4gmxalcdswv7ppaz5qw3hwb456aq5-pinned-file.txt narinfo_key=rsj4gmxalcdswv7ppaz5qw3hwb456aq5.narinfo13142026/11/11 23:21:44 INFO Starting cleanup of old closures method=DELETE path=/api/closures13152026/11/11 23:21:44 INFO Garbage collection started13162026/11/11 23:21:44 INFO Aborted multipart uploads count=0 kept=013172026/11/11 23:21:44 WARN Force mode enabled - objects will be deleted immediately without grace period13182026/11/11 23:21:44 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013192026/11/11 23:21:44 INFO Vacuumed table table=pending_closures13202026/11/11 23:21:44 INFO Vacuumed table table=pending_objects13212026/11/11 23:21:44 INFO Vacuumed table table=multipart_uploads13222026/11/11 23:21:44 INFO Vacuumed table table=closures13232026/11/11 23:21:44 INFO Vacuumed table table=objects13242026/11/11 23:21:44 INFO Received push request method=POST path=/api/pushes13252026/11/11 23:21:44 INFO Received complete push request method=POST path=/api/pushes/1/complete13262026/11/11 23:21:44 INFO Completed push id=1 objects=4 duration=64.880042ms13272026/11/11 23:21:44 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13282026/11/11 23:21:44 INFO Completed upload id=2 objects=2 duration=1.284375ms1329--- PASS: TestMetricsCommit (5.71s)1330=== CONT TestSweepRechecksPendingAfterLocking1331=== NAME TestNARDeduplicationMetadataUploadBug1332 metadata_upload_test.go:48: First store path: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestNARDeduplicationMetadataUploadBug3458380089/001/store/6sbdlhpfcnh5qq5463qvdy9v2cwwwkln-file1.txt1333--- PASS: TestMetricsInventory (5.88s)1334=== CONT TestGetExistingObjectsLocksRows13352026/11/11 23:21:45 INFO Received push request method=POST path=/api/pushes13362026/11/11 23:21:45 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13372026/11/11 23:21:45 INFO Uploading 6sbdlhpfcnh5qq5463qvdy9v2cwwwkln-file1.txt (160B)13382026/11/11 23:21:45 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"13392026/11/11 23:21:45 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13402026/11/11 23:21:45 WARN Failed to register uploaded object key=6sbdlhpfcnh5qq5463qvdy9v2cwwwkln.ls error="server returned 404: 404 page not found\n"13412026/11/11 23:21:45 INFO Signed narinfos id=1 count=113422026/11/11 23:21:45 INFO Uploading 1 narinfos13432026/11/11 23:21:45 INFO Received complete push request method=POST path=/api/pushes/1/complete13442026/11/11 23:21:45 WARN Failed to register uploaded object key=6sbdlhpfcnh5qq5463qvdy9v2cwwwkln.narinfo error="server returned 404: 404 page not found\n"13452026/11/11 23:21:45 INFO Completed push id=1 objects=3 duration=23.512375ms13462026/11/11 23:21:45 INFO Upload complete. (238ms)1347=== NAME TestNARDeduplicationMetadataUploadBug1348 metadata_upload_test.go:54: Retrieved narinfo from S3:1349 StorePath: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestNARDeduplicationMetadataUploadBug3458380089/001/store/6sbdlhpfcnh5qq5463qvdy9v2cwwwkln-file1.txt1350 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1351 Compression: zstd1352 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1353 NarSize: 1601354 References: 1355 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1356 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1357 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1358 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}13592026/11/11 23:21:45 INFO Installed lifecycle rule aborting incomplete NAR uploads bucket=bucket35 days=21360--- PASS: TestEnsureAbortUploadsRule (6.07s)1361=== CONT TestLeadGenerationGrowsWithEveryGrant1362=== NAME TestNARDeduplicationMetadataUploadBug1363 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestNARDeduplicationMetadataUploadBug3458380089/001/store/fa5r2ck9zidchdb78frpb85wv3sq3yy3-file2.txt13642026/11/11 23:21:45 INFO Received push request method=POST path=/api/pushes13652026/11/11 23:21:45 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)13662026/11/11 23:21:45 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13672026/11/11 23:21:45 WARN Failed to register uploaded object key=fa5r2ck9zidchdb78frpb85wv3sq3yy3.ls error="server returned 404: 404 page not found\n"13682026/11/11 23:21:45 INFO Signed narinfos id=2 count=113692026/11/11 23:21:45 INFO Uploading 1 narinfos1370=== RUN TestService_RequireScope_OIDC/builder_may_write1371=== PAUSE TestService_RequireScope_OIDC/builder_may_write1372=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1373=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1374=== RUN TestService_RequireScope_OIDC/ops_may_admin1375=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1376=== RUN TestService_RequireScope_OIDC/ops_may_not_write1377=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1378=== RUN TestService_RequireScope_OIDC/reader_may_not_write1379=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1380=== RUN TestService_RequireScope_OIDC/static_token_may_admin1381=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1382=== RUN TestService_RequireScope_OIDC/static_token_may_write1383=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1384=== RUN TestService_RequireScope_OIDC/reader_may_read1385=== PAUSE TestService_RequireScope_OIDC/reader_may_read1386=== RUN TestService_RequireScope_OIDC/writer_implies_read1387=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1388=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1389=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1390=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1391=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1392=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1393=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1394=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1395=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1396=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1397=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1398=== CONT TestLeadEndsOnShutdown13992026/11/11 23:21:45 INFO Received complete push request method=POST path=/api/pushes/2/complete14002026/11/11 23:21:45 WARN Failed to register uploaded object key=fa5r2ck9zidchdb78frpb85wv3sq3yy3.narinfo error="server returned 404: 404 page not found\n"14012026/11/11 23:21:46 INFO Completed push id=2 objects=3 duration=23.902625ms14022026/11/11 23:21:46 INFO Upload complete. (213ms)1403=== NAME TestNARDeduplicationMetadataUploadBug1404 metadata_upload_test.go:76: Retrieved narinfo from S3:1405 StorePath: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestNARDeduplicationMetadataUploadBug3458380089/001/store/fa5r2ck9zidchdb78frpb85wv3sq3yy3-file2.txt1406 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1407 Compression: zstd1408 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1409 NarSize: 1601410 References: 1411 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1412 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1413 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1414 {"version":1,"root":{"type":"regular","size":44}}1415--- PASS: TestNARDeduplicationMetadataUploadBug (6.48s)1416=== CONT TestLeadUnannouncedStandbyYieldsToIncumbent1417--- PASS: TestCacheStatsHandler (6.19s)1418=== CONT TestLeadIncumbentAnnouncesAtOnce1419=== NAME TestPinProtectsFromGC1420 client_integration_test.go:888: Pin successfully protected closure from garbage collection1421--- PASS: TestPinProtectsFromGC (10.91s)1422=== CONT TestReadRedirectUsesPublicS3URL1423--- PASS: TestService_ReadScope_PublicByDefault (6.57s)1424=== CONT TestPush_SignsNarinfosOfItsPendingObjects1425=== NAME TestClientCADerivations1426 client_ca_test.go:136: Built CA derivation: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientCADerivations2351240200/001/store/df4y2j33vjz4fmp854dfhs60sxl6y3k8-ca-test14272026/11/11 23:21:47 WARN readiness check failed error="closed pool"1428--- PASS: TestService_readinessHandler (6.56s)1429=== CONT TestPush_RejectsBadRequests1430=== NAME TestClientCADerivations1431 client_ca_test.go:139: Found 1 dependencies (including self)14322026/11/11 23:21:47 INFO Received push request method=POST path=/api/pushes14332026/11/11 23:21:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14342026/11/11 23:21:47 INFO Uploading df4y2j33vjz4fmp854dfhs60sxl6y3k8-ca-test (144B)14352026/11/11 23:21:47 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"14362026/11/11 23:21:47 WARN Failed to register uploaded object key=df4y2j33vjz4fmp854dfhs60sxl6y3k8.ls error="server returned 404: 404 page not found\n"14372026/11/11 23:21:47 WARN Failed to register uploaded object key=log/h1xa0hxgrws9wr1cfrpk2w1bj1lbmrbi-ca-test.drv error="server returned 404: 404 page not found\n"14382026/11/11 23:21:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14392026/11/11 23:21:47 INFO Signed narinfos id=1 count=114402026/11/11 23:21:47 INFO Uploading 1 narinfos1441--- PASS: TestService_healthCheckHandler (6.57s)1442=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14432026/11/11 23:21:47 INFO Received complete push request method=POST path=/api/pushes/1/complete14442026/11/11 23:21:47 WARN Failed to register uploaded object key=df4y2j33vjz4fmp854dfhs60sxl6y3k8.narinfo error="server returned 404: 404 page not found\n"14452026/11/11 23:21:47 INFO Completed push id=1 objects=4 duration=20.898209ms14462026/11/11 23:21:47 INFO Upload complete. (278ms)1447=== NAME TestClientCADerivations1448 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientCADerivations2351240200/001/store/df4y2j33vjz4fmp854dfhs60sxl6y3k8-ca-test1449 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1450 Compression: zstd1451 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1452 NarSize: 1441453 References: 1454 Deriver: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientCADerivations2351240200/001/store/h1xa0hxgrws9wr1cfrpk2w1bj1lbmrbi-ca-test.drv1455 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1456 client_ca_test.go:185: Checking for realisation files in S3...1457 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1458 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1459 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket38?endpoint=http://localhost:57487®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/8/scratch/9c621a23873fdf7e/build/TestClientCADerivations2351240200/001/store'1460 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11461--- PASS: TestClientCADerivations (7.54s)1462=== CONT TestService_AuthMiddleware_OIDC14632026/11/11 23:21:47 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57657/oidc14642026/11/11 23:21:47 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld8 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1465--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (6.71s)1466=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit14672026/11/11 23:21:47 INFO Received uploads request method=POST path=/api/pending_closures1468--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (6.67s)1469=== CONT TestService_ReadAuthMiddleware14702026/11/11 23:21:48 INFO Received uploads request method=POST path=/api/pending_closures1471--- PASS: TestTombstonedObjectOfferedWithoutWaiting (6.72s)1472=== CONT TestPush_RootsAreLockedInByteOrder14732026/11/11 23:21:48 INFO Aborted multipart uploads count=0 kept=014742026/11/11 23:21:48 WARN Force mode enabled - objects will be deleted immediately without grace period14752026/11/11 23:21:49 INFO Received uploads request method=POST path=/api/pending_closures14762026/11/11 23:21:49 INFO Aborted multipart uploads count=0 kept=014772026/11/11 23:21:49 WARN Force mode enabled - objects will be deleted immediately without grace period14782026/11/11 23:21:49 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=014792026/11/11 23:21:49 INFO Aborted multipart uploads count=1 kept=014802026/11/11 23:21:49 INFO Vacuumed table table=pending_closures14812026/11/11 23:21:49 INFO Vacuumed table table=pending_objects14822026/11/11 23:21:49 INFO Vacuumed table table=multipart_uploads14832026/11/11 23:21:49 INFO Vacuumed table table=closures14842026/11/11 23:21:49 INFO Received cleanup request method=DELETE path=/api/pending_closures14852026/11/11 23:21:49 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=014862026/11/11 23:21:49 INFO Vacuumed table table=pending_closures14872026/11/11 23:21:49 INFO Aborted multipart uploads count=1 kept=01488--- PASS: TestPendingCleanupUsesOneCutoff (11.91s)1489=== CONT TestIsValidUploadKey1490=== RUN TestIsValidUploadKey/narinfo1491=== PAUSE TestIsValidUploadKey/narinfo1492=== RUN TestIsValidUploadKey/nar_zst1493=== PAUSE TestIsValidUploadKey/nar_zst1494=== RUN TestIsValidUploadKey/nar_xz14952026/11/11 23:21:49 INFO Vacuumed table table=pending_objects1496=== PAUSE TestIsValidUploadKey/nar_xz14972026/11/11 23:21:49 INFO Vacuumed table table=objects1498=== RUN TestIsValidUploadKey/nar_plain1499=== PAUSE TestIsValidUploadKey/nar_plain1500=== RUN TestIsValidUploadKey/listing1501=== PAUSE TestIsValidUploadKey/listing1502=== RUN TestIsValidUploadKey/build_log1503=== PAUSE TestIsValidUploadKey/build_log1504=== RUN TestIsValidUploadKey/build_log_home-manager_file1505=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1506=== RUN TestIsValidUploadKey/build_log_plus_in_name1507=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1508=== RUN TestIsValidUploadKey/build_log_question_mark1509=== PAUSE TestIsValidUploadKey/build_log_question_mark1510=== RUN TestIsValidUploadKey/build_log_equals1511=== PAUSE TestIsValidUploadKey/build_log_equals1512=== RUN TestIsValidUploadKey/realisation15132026/11/11 23:21:49 INFO Vacuumed table table=multipart_uploads1514=== PAUSE TestIsValidUploadKey/realisation1515=== RUN TestIsValidUploadKey/realisation_plus_in_output1516=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1517=== RUN TestIsValidUploadKey/nix-cache-info1518=== PAUSE TestIsValidUploadKey/nix-cache-info1519=== RUN TestIsValidUploadKey/index.html1520=== PAUSE TestIsValidUploadKey/index.html1521=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1522=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1523=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1524=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1525=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1526=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1527=== RUN TestIsValidUploadKey/traversal1528=== PAUSE TestIsValidUploadKey/traversal1529=== RUN TestIsValidUploadKey/traversal_nar1530=== PAUSE TestIsValidUploadKey/traversal_nar1531=== RUN TestIsValidUploadKey/absolute1532=== PAUSE TestIsValidUploadKey/absolute1533=== RUN TestIsValidUploadKey/empty_key1534=== PAUSE TestIsValidUploadKey/empty_key1535=== RUN TestIsValidUploadKey/unknown_type1536=== PAUSE TestIsValidUploadKey/unknown_type1537=== CONT TestPush_CompleteWaitsForCleanupOfThePush15382026/11/11 23:21:49 INFO Vacuumed table table=closures1539--- PASS: TestGCSweepSkipsPendingObjects (7.32s)1540=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT15412026/11/11 23:21:49 INFO Vacuumed table table=objects1542--- PASS: TestGCSweepDeliversEachKeyOnce (7.89s)1543=== CONT TestPush_RepeatedRootCommitsOnce15442026/11/11 23:21:49 INFO Received uploads request method=POST path=/api/pending_closures1545--- PASS: TestDeduplicatedObjectsRecordedAsPending (6.76s)1546=== CONT TestCompleteMultipartUnregistered15472026/11/11 23:21:49 INFO Received uploads request method=POST path=/api/pending_closures15482026/11/11 23:21:50 INFO Aborted multipart uploads count=0 kept=015492026/11/11 23:21:50 INFO Aborted multipart uploads count=0 kept=015502026/11/11 23:21:50 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=015512026/11/11 23:21:50 WARN Force mode enabled - objects will be deleted immediately without grace period15522026/11/11 23:21:50 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=015532026/11/11 23:21:50 INFO Vacuumed table table=pending_closures15542026/11/11 23:21:50 INFO Vacuumed table table=pending_closures15552026/11/11 23:21:50 INFO Vacuumed table table=pending_objects15562026/11/11 23:21:50 INFO Vacuumed table table=multipart_uploads15572026/11/11 23:21:50 INFO Vacuumed table table=closures15582026/11/11 23:21:50 INFO Vacuumed table table=objects15592026/11/11 23:21:50 INFO Vacuumed table table=pending_objects1560--- PASS: TestGCMetrics (6.21s)1561=== CONT TestService_verifyS3ReuploadsStaleNarinfo1562=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1563=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1564=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1565=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1566=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1567=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1568=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1569=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1570=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1571=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1572=== CONT TestPush_CompleteCommitsEveryRoot15732026/11/11 23:21:50 INFO Vacuumed table table=multipart_uploads15742026/11/11 23:21:50 INFO Vacuumed table table=closures15752026/11/11 23:21:50 INFO Vacuumed table table=objects15762026/11/11 23:21:50 INFO Aborted multipart uploads count=0 kept=015772026/11/11 23:21:50 WARN Force mode enabled - objects will be deleted immediately without grace period15782026/11/11 23:21:50 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=015792026/11/11 23:21:50 INFO Vacuumed table table=pending_closures15802026/11/11 23:21:50 INFO Vacuumed table table=pending_objects15812026/11/11 23:21:50 INFO Vacuumed table table=multipart_uploads15822026/11/11 23:21:50 INFO Vacuumed table table=closures15832026/11/11 23:21:50 INFO Vacuumed table table=objects1584--- PASS: TestPushDedupSurvivesConcurrentGC (6.72s)1585=== CONT TestService_verifyS3Integrity15862026/11/11 23:21:50 INFO Aborted multipart uploads count=0 kept=015872026/11/11 23:21:50 WARN Force mode enabled - objects will be deleted immediately without grace period15882026/11/11 23:21:50 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=015892026/11/11 23:21:50 INFO Vacuumed table table=pending_closures15902026/11/11 23:21:50 INFO Vacuumed table table=pending_objects15912026/11/11 23:21:50 INFO Vacuumed table table=multipart_uploads15922026/11/11 23:21:50 INFO Vacuumed table table=closures15932026/11/11 23:21:50 INFO Vacuumed table table=objects1594--- PASS: TestCommitRacingPendingCleanupKeepsObjects (7.18s)1595=== CONT TestService_createPendingClosureHandler1596--- PASS: TestGCBugBareHashReferences (6.67s)1597=== CONT TestPush_OverlappingRootsStoreOneRowPerKey15982026/11/11 23:21:51 INFO Received uploads request method=POST path=/api/pending_closures15992026/11/11 23:21:51 INFO Aborted multipart uploads count=0 kept=016002026/11/11 23:21:51 WARN Force mode enabled - objects will be deleted immediately without grace period16012026/11/11 23:21:51 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=016022026/11/11 23:21:51 INFO Vacuumed table table=pending_closures1603--- PASS: TestPushWaitsForSweepHoldingRow (7.22s)1604=== CONT TestService_cleanupPendingClosuresHandler16052026/11/11 23:21:51 INFO Vacuumed table table=pending_objects16062026/11/11 23:21:51 INFO Vacuumed table table=multipart_uploads16072026/11/11 23:21:51 INFO Vacuumed table table=closures16082026/11/11 23:21:51 INFO Vacuumed table table=objects1609--- PASS: TestSweepRechecksPendingAfterLocking (6.75s)1610=== CONT TestUploadHandlersRejectOversizedBody1611=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1612=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1613=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1614=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1615=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1616=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1617=== CONT TestUploadHandlersRejectInvalidKeys1618=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1619=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1620=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1621=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1622=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1623=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1624=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1625=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1626=== CONT TestReadProxyRootRedirectsToIndexHTML1627--- PASS: TestGetExistingObjectsLocksRows (6.37s)1628=== CONT TestReadProxyOutlastsServerWriteTimeout16292026/11/11 23:21:52 INFO lead: acquired remote=192.0.2.1:1234 generation=116302026/11/11 23:21:52 INFO lead: acquired remote=192.0.2.1:1234 generation=116312026/11/11 23:21:52 INFO lead: acquired remote=192.0.2.1:1234 generation=116322026/11/11 23:21:52 INFO lead: acquired remote=192.0.2.1:1234 generation=116332026/11/11 23:21:52 INFO lead: released remote=192.0.2.1:1234 generation=11634--- PASS: TestLeadIncumbentAnnouncesAtOnce (6.63s)1635=== CONT TestReadProxyRangeRequest1636=== NAME TestOrphanedObjectsGCStressTest1637 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains16382026/11/11 23:21:53 INFO lead: released remote=192.0.2.1:1234 generation=116392026/11/11 23:21:53 INFO lead: acquired remote=192.0.2.1:1234 generation=21640 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion1641--- PASS: TestReadRedirectUsesPublicS3URL (6.63s)1642=== CONT TestReadProxyConditionalGet16432026/11/11 23:21:53 INFO lead: released remote=192.0.2.1:1234 generation=11644--- PASS: TestLeadEndsOnShutdown (7.42s)1645=== CONT TestReadRedirectKeepsNarinfoProxied16462026/11/11 23:21:53 INFO Received push request method=POST path=/api/pushes16472026/11/11 23:21:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16482026/11/11 23:21:53 INFO Signed narinfos id=1 count=116492026/11/11 23:21:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16502026/11/11 23:21:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16512026/11/11 23:21:53 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"16522026/11/11 23:21:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16532026/11/11 23:21:53 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"16542026/11/11 23:21:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16552026/11/11 23:21:53 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=116562026/11/11 23:21:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16572026/11/11 23:21:53 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1658--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (6.89s)1659=== CONT TestReadRedirectNar16602026/11/11 23:21:53 INFO lead: released remote=192.0.2.1:1234 generation=116612026/11/11 23:21:53 INFO lead: acquired remote=192.0.2.1:1234 generation=216622026/11/11 23:21:53 INFO lead: given back to the incumbent remote=192.0.2.1:1234 generation=216632026/11/11 23:21:53 INFO lead: acquired remote=192.0.2.1:1234 generation=31664=== RUN TestPush_RejectsBadRequests/root_not_in_objects1665=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1666=== RUN TestPush_RejectsBadRequests/no_roots1667=== PAUSE TestPush_RejectsBadRequests/no_roots1668=== RUN TestPush_RejectsBadRequests/no_objects1669=== PAUSE TestPush_RejectsBadRequests/no_objects1670=== RUN TestPush_RejectsBadRequests/bad_root1671=== PAUSE TestPush_RejectsBadRequests/bad_root1672=== CONT TestConnectWaitsForAPeerMigration16732026/11/11 23:21:54 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"16742026/11/11 23:21:54 WARN mTLS auth: bound subjects configured but subject DN unavailable16752026/11/11 23:21:54 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1676--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (6.83s)1677=== CONT TestReadProxyDisabled16782026/11/11 23:21:54 INFO lead: released remote=192.0.2.1:1234 generation=216792026/11/11 23:21:54 INFO lead: acquired remote=192.0.2.1:1234 generation=316802026/11/11 23:21:54 INFO lead: released remote=192.0.2.1:1234 generation=31681--- PASS: TestLeadGenerationGrowsWithEveryGrant (8.50s)1682=== CONT TestLeadElectsOneAndHandsOver16832026/11/11 23:21:54 INFO Received push request method=POST path=/api/pushes16842026/11/11 23:21:54 INFO Received complete push request method=POST path=/api/pushes/1/complete16852026/11/11 23:21:54 INFO Completed push id=1 objects=4 duration=36.706166ms16862026/11/11 23:21:54 INFO Received push request method=POST path=/api/pushes16872026/11/11 23:21:54 INFO Aborted multipart uploads count=0 kept=01688=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1689=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1690=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1691=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1692=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1693=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1694=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1695=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured16962026/11/11 23:21:54 WARN Force mode enabled - objects will be deleted immediately without grace period1697=== CONT TestService_AuthMiddleware_MTLSProxyHeader16982026/11/11 23:21:54 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=016992026/11/11 23:21:54 INFO Vacuumed table table=pending_closures17002026/11/11 23:21:54 INFO Vacuumed table table=pending_objects17012026/11/11 23:21:54 INFO Vacuumed table table=multipart_uploads17022026/11/11 23:21:54 INFO Vacuumed table table=closures17032026/11/11 23:21:54 INFO Vacuumed table table=objects17042026/11/11 23:21:54 INFO Received complete push request method=POST path=/api/pushes/2/complete17052026/11/11 23:21:55 INFO Completed push id=2 objects=4 duration=8.421ms1706--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (7.33s)1707=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1708--- PASS: TestService_ReadAuthMiddleware (6.89s)1709=== CONT TestResolveDBConnectionString1710=== RUN TestResolveDBConnectionString/flag_wins1711=== PAUSE TestResolveDBConnectionString/flag_wins1712=== RUN TestResolveDBConnectionString/file_when_flag_empty1713=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1714=== RUN TestResolveDBConnectionString/missing_file_is_an_error1715=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1716=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1717=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1718=== RUN TestResolveDBConnectionString/nothing_configured1719=== PAUSE TestResolveDBConnectionString/nothing_configured1720=== CONT TestReadProxyHead17212026/11/11 23:21:55 INFO Received push request method=POST path=/api/pushes17222026-11-11 23:21:55.589 UTC [75736] ERROR: could not obtain lock on row in relation "closures"17232026-11-11 23:21:55.589 UTC [75736] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17242026-11-11 23:21:55.594 UTC [75736] ERROR: could not obtain lock on row in relation "closures"17252026-11-11 23:21:55.594 UTC [75736] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17262026-11-11 23:21:55.599 UTC [75736] ERROR: could not obtain lock on row in relation "closures"17272026-11-11 23:21:55.599 UTC [75736] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17282026-11-11 23:21:55.603 UTC [75736] ERROR: could not obtain lock on row in relation "closures"17292026-11-11 23:21:55.603 UTC [75736] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17302026-11-11 23:21:55.610 UTC [75736] ERROR: could not obtain lock on row in relation "closures"17312026-11-11 23:21:55.610 UTC [75736] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1732--- PASS: TestPush_RootsAreLockedInByteOrder (7.32s)1733=== CONT TestService_AuthMiddleware17342026/11/11 23:21:55 INFO lead: released remote=192.0.2.1:1234 generation=31735--- PASS: TestLeadUnannouncedStandbyYieldsToIncumbent (9.54s)1736=== CONT TestParseSize1737--- PASS: TestParseSize (0.00s)1738=== CONT TestPendingClosureWriteTimeout1739=== RUN TestPendingClosureWriteTimeout/empty1740=== PAUSE TestPendingClosureWriteTimeout/empty1741=== RUN TestPendingClosureWriteTimeout/400_objects1742=== PAUSE TestPendingClosureWriteTimeout/400_objects1743=== RUN TestPendingClosureWriteTimeout/670k_objects1744=== PAUSE TestPendingClosureWriteTimeout/670k_objects1745=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1746=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1747=== CONT TestPresignedUploadRegisteredBeforeCommit17482026/11/11 23:21:55 INFO Received uploads request method=POST path=/api/pending_closures1749--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (6.56s)1750=== CONT TestProxyWriteTimeout1751=== RUN TestProxyWriteTimeout/narinfo1752=== PAUSE TestProxyWriteTimeout/narinfo1753=== RUN TestProxyWriteTimeout/1_GiB_nar1754=== PAUSE TestProxyWriteTimeout/1_GiB_nar1755=== RUN TestProxyWriteTimeout/10_GiB_nar1756=== PAUSE TestProxyWriteTimeout/10_GiB_nar1757=== RUN TestProxyWriteTimeout/unknown_size1758=== PAUSE TestProxyWriteTimeout/unknown_size1759=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle17602026/11/11 23:21:56 INFO Received push request method=POST path=/api/pushes17612026/11/11 23:21:56 INFO Received push request method=POST path=/api/pushes17622026-11-11 23:21:56.686 UTC [75745] ERROR: Push does not exist: id=117632026-11-11 23:21:56.686 UTC [75745] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE17642026-11-11 23:21:56.686 UTC [75745] STATEMENT: SELECT commit_push($1)1765--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (7.30s)1766=== CONT TestService_Rustfstest17672026/11/11 23:21:56 INFO Received complete push request method=POST path=/api/pushes/1/complete17682026/11/11 23:21:56 INFO Completed push id=1 objects=4 duration=53.144333ms1769--- PASS: TestPush_RepeatedRootCommitsOnce (7.42s)1770=== CONT TestSkippedUploadsHandler17712026/11/11 23:21:56 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001772--- PASS: TestSkippedUploadsHandler (0.01s)1773=== CONT TestCompletedNarNotReofferedAcrossClosures17742026/11/11 23:21:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17752026/11/11 23:21:57 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1776--- PASS: TestCompleteMultipartUnregistered (7.56s)1777=== CONT TestCompleteMultipartUpload_ErrorButObjectExists17782026/11/11 23:21:57 INFO Received push request method=POST path=/api/pushes17792026/11/11 23:21:57 INFO Received complete push request method=POST path=/api/pushes/1/complete17802026/11/11 23:21:57 INFO Completed push id=1 objects=6 duration=47.156792ms1781--- PASS: TestPush_CompleteCommitsEveryRoot (7.43s)1782=== CONT TestReadProxyInvalidPath17832026/11/11 23:21:57 INFO Received uploads request method=POST path=/api/pending_closures17842026/11/11 23:21:58 INFO Received uploads request method=POST path=/api/pending_closures17852026/11/11 23:21:58 INFO Received uploads request method=POST path=/api/pending_closures17862026/11/11 23:21:58 INFO Received uploads request method=POST path=/api/pending_closures17872026/11/11 23:21:58 INFO Received push request method=POST path=/api/pushes1788--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (7.91s)1789=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows17902026/11/11 23:21:59 INFO Received cleanup request method=DELETE path=/api/pending_closures17912026/11/11 23:21:59 INFO Aborted multipart uploads count=0 kept=017922026/11/11 23:21:59 INFO Received uploads request method=POST path=/api/pending_closures17932026/11/11 23:21:59 INFO Received cleanup request method=DELETE path=/api/pending_closures17942026/11/11 23:21:59 INFO Aborted multipart uploads count=1 kept=017952026/11/11 23:21:59 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17962026-11-11 23:21:59.535 UTC [75715] ERROR: Closure does not exist: id=117972026-11-11 23:21:59.535 UTC [75715] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE17982026-11-11 23:21:59.535 UTC [75715] STATEMENT: -- name: CommitPendingClosure :one1799 SELECT commit_pending_closure($1::bigint)::bigint1800 1801--- PASS: TestService_cleanupPendingClosuresHandler (7.89s)1802=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1803--- PASS: TestReadProxyRootRedirectsToIndexHTML (8.04s)1804=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale18052026/11/11 23:22:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18062026/11/11 23:22:00 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YjNjMWFiNmEtOTg0ZS00MjcxLThmZGEtOGI2NmIwNDdkZGU4LmRjMWZiNTFiLTRjMDQtNDYzOS1iMDIzLWE3N2IyMDEwOGM4OHgxNzk0NDM5MzE3ODk2OTA0MDAw parts=1018072026/11/11 23:22:00 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18082026/11/11 23:22:00 INFO Completed upload id=1 objects=2 duration=28.992541ms18092026/11/11 23:22:00 INFO Received uploads request method=POST path=/api/pending_closures18102026/11/11 23:22:00 INFO Received uploads request method=POST path=/api/pending_closures18112026/11/11 23:22:00 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo18122026/11/11 23:22:00 WARN Found objects in DB but missing from S3, will re-upload count=11813--- PASS: TestService_verifyS3Integrity (10.08s)1814=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh18152026/11/11 23:22:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1816--- PASS: TestReadProxyRangeRequest (7.93s)1817=== CONT TestIsValidCachePath/narinfo1818=== CONT TestParseSingleRange/none1819=== CONT TestIsValidCachePath/index.html1820=== CONT TestIsValidCachePath/nix-cache-info1821=== CONT TestIsValidCachePath/traversal_parent1822=== CONT TestIsValidCachePath/realisation1823=== CONT TestIsValidCachePath/log1824=== CONT TestIsValidCachePath/ls1825=== CONT TestIsValidCachePath/nar_uncompressed1826=== CONT TestIsValidCachePath/nar_bz21827=== CONT TestIsValidCachePath/nar_xz1828=== CONT TestIsValidCachePath/nar_zst1829=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1830=== CONT TestParseSingleRange/open-ended1831=== CONT TestParseSingleRange/start_far_past_EOF1832=== CONT TestParseSingleRange/start_past_EOF1833=== CONT TestParseSingleRange/single_byte1834=== CONT TestParseSingleRange/suffix_exceeds_size1835=== CONT TestParseSingleRange/suffix1836=== CONT TestParseSingleRange/end_clamped_to_size1837=== CONT TestParseSingleRange/malformed_both_empty1838=== CONT TestParseSingleRange/closed1839=== CONT TestParseSingleRange/malformed_end_before_start1840=== CONT TestIsValidCachePath/empty1841=== CONT TestIsValidCachePath/short_hash1842=== CONT TestIsValidCachePath/wrong_extension1843=== CONT TestIsValidCachePath/leading_slash1844=== CONT TestParseSingleRange/multi-range_ignored1845=== CONT TestParseSingleRange/malformed_no_dash1846=== CONT TestIsValidCachePath/invalid_char_u1847=== CONT TestIsValidCachePath/random_path1848=== CONT TestParseSingleRange/unknown_unit1849--- PASS: TestParseSingleRange (0.01s)1850 --- PASS: TestParseSingleRange/none (0.00s)1851 --- PASS: TestParseSingleRange/open-ended (0.00s)1852 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1853 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1854 --- PASS: TestParseSingleRange/single_byte (0.00s)1855 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1856 --- PASS: TestParseSingleRange/suffix (0.00s)1857 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1858 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1859 --- PASS: TestParseSingleRange/closed (0.00s)1860 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1861 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1862 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1863 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1864=== CONT TestIsValidCachePath/invalid_char_e1865=== CONT TestIsValidCachePath/traversal_in_middle1866--- PASS: TestIsValidCachePath (0.01s)1867 --- PASS: TestIsValidCachePath/narinfo (0.00s)1868 --- PASS: TestIsValidCachePath/index.html (0.00s)1869 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1870 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1871 --- PASS: TestIsValidCachePath/realisation (0.00s)1872 --- PASS: TestIsValidCachePath/log (0.00s)1873 --- PASS: TestIsValidCachePath/ls (0.00s)1874 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1875 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1876 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1877 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1878 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1879 --- PASS: TestIsValidCachePath/empty (0.00s)1880 --- PASS: TestIsValidCachePath/short_hash (0.00s)1881 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1882 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1883 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1884 --- PASS: TestIsValidCachePath/random_path (0.00s)1885 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1886 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1887=== CONT TestServerTLSConfig/no_client_CA1888=== CONT TestServerTLSConfig/not_a_PEM_file1889=== CONT TestServerTLSConfig/missing_CA_file1890--- PASS: TestServerTLSConfig (0.02s)1891 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1892 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.04s)1893 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1894=== CONT TestClientErrorHandling/InvalidStorePath18952026/11/11 23:22:01 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YjNjMWFiNmEtOTg0ZS00MjcxLThmZGEtOGI2NmIwNDdkZGU4LmYyYzQ3ZWI1LTZiZDgtNDI2NC05MzA3LTMwODE1ZTBjYjNmNXgxNzk0NDM5MzE4MzM4NTM0MDAw parts=1018962026/11/11 23:22:01 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18972026/11/11 23:22:01 INFO Completed upload id=1 objects=2 duration=44.235791ms18982026/11/11 23:22:01 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000018992026/11/11 23:22:01 INFO Received uploads request method=POST path=/api/pending_closures19002026/11/11 23:22:01 INFO Starting cleanup of old closures method=DELETE path=/api/closures19012026/11/11 23:22:01 INFO Aborted multipart uploads count=0 kept=019022026/11/11 23:22:01 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=019032026/11/11 23:22:01 INFO Vacuumed table table=pending_closures19042026/11/11 23:22:01 INFO Vacuumed table table=pending_objects1905--- PASS: TestReadProxyConditionalGet (8.09s)1906=== CONT TestClientErrorHandling/ServerNotAvailable19072026/11/11 23:22:01 INFO Vacuumed table table=multipart_uploads19082026/11/11 23:22:01 INFO Vacuumed table table=closures19092026/11/11 23:22:01 INFO Vacuumed table table=objects19102026/11/11 23:22:01 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001911--- PASS: TestService_createPendingClosureHandler (10.70s)1912=== CONT TestClientErrorHandling/InvalidAuthToken1913--- PASS: TestReadRedirectKeepsNarinfoProxied (8.39s)1914=== CONT TestCacheConfigHandler/full_config,_no_issuer1915=== CONT TestCacheConfigHandler/no_signing_keys1916=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1917=== CONT TestCacheConfigHandler/no_cache_url_configured1918--- PASS: TestCacheConfigHandler (0.00s)1919 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1920 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1921 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1922 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1923=== CONT TestGCEndsOnShutdown/before_the_run19242026/11/11 23:22:01 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19252026/11/11 23:22:01 WARN Request failed, retrying attempt=2 backoff=185.426836ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1926--- PASS: TestReadRedirectNar (8.36s)1927=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark19282026/11/11 23:22:02 WARN Request failed, retrying attempt=3 backoff=361.089112ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19292026/11/11 23:22:02 INFO lead: acquired remote=192.0.2.1:1234 generation=119302026/11/11 23:22:02 WARN Request failed, retrying attempt=4 backoff=763.558598ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1931--- PASS: TestReadProxyDisabled (8.62s)1932=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1933--- PASS: TestConnectWaitsForAPeerMigration (8.90s)1934=== CONT TestService_RequireScope_OIDC/builder_may_write1935=== CONT TestService_RequireScope_OIDC/reader_may_read1936=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1937=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19382026/11/11 23:22:02 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]1939=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1940=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1941=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1942=== CONT TestService_RequireScope_OIDC/writer_implies_read1943=== CONT TestService_RequireScope_OIDC/reader_may_not_write1944=== CONT TestService_RequireScope_OIDC/static_token_may_write1945=== CONT TestService_RequireScope_OIDC/static_token_may_admin1946=== CONT TestService_RequireScope_OIDC/ops_may_admin1947=== CONT TestService_RequireScope_OIDC/ops_may_not_write1948=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1949=== CONT TestIsValidUploadKey/narinfo1950=== CONT TestIsValidUploadKey/realisation_plus_in_output1951=== CONT TestIsValidUploadKey/unknown_type1952=== CONT TestIsValidUploadKey/empty_key1953=== CONT TestIsValidUploadKey/absolute1954=== CONT TestIsValidUploadKey/traversal_nar1955=== CONT TestIsValidUploadKey/traversal1956=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1957=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1958=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1959=== CONT TestIsValidUploadKey/index.html1960--- PASS: TestService_RequireScope_OIDC (6.14s)1961 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1962 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1963 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1964 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.01s)1965 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1966 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1967 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1968 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1969 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1970 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1971 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1972 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1973 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1974 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1975=== CONT TestIsValidUploadKey/nix-cache-info1976=== CONT TestIsValidUploadKey/build_log_home-manager_file1977=== CONT TestIsValidUploadKey/realisation1978=== CONT TestIsValidUploadKey/build_log_equals1979=== CONT TestIsValidUploadKey/build_log_question_mark1980=== CONT TestIsValidUploadKey/build_log_plus_in_name1981=== CONT TestIsValidUploadKey/nar_plain1982=== CONT TestIsValidUploadKey/build_log1983=== CONT TestIsValidUploadKey/listing1984=== CONT TestIsValidUploadKey/nar_xz1985=== CONT TestIsValidUploadKey/nar_zst1986=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1987--- PASS: TestIsValidUploadKey (0.02s)1988 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1989 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1990 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1991 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1992 --- PASS: TestIsValidUploadKey/absolute (0.00s)1993 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1994 --- PASS: TestIsValidUploadKey/traversal (0.00s)1995 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1996 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1997 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1998 --- PASS: TestIsValidUploadKey/index.html (0.00s)1999 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2000 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2001 --- PASS: TestIsValidUploadKey/realisation (0.00s)2002 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2003 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2004 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2005 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2006 --- PASS: TestIsValidUploadKey/build_log (0.00s)2007 --- PASS: TestIsValidUploadKey/listing (0.00s)2008 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2009 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2010--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (8.42s)2011=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed20122026/11/11 23:22:03 WARN Request failed, retrying attempt=5 backoff=1.503158022s error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20132026/11/11 23:22:03 INFO lead: released remote=192.0.2.1:1234 generation=120142026/11/11 23:22:03 INFO lead: acquired remote=192.0.2.1:1234 generation=22015--- PASS: TestReadProxyHead (8.99s)2016=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed20172026/11/11 23:22:04 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"2018--- PASS: TestService_AuthMiddleware (8.73s)2019=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost2020--- PASS: TestReadProxyOutlastsServerWriteTimeout (12.82s)2021=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed20222026/11/11 23:22:04 INFO Received uploads request method=POST path=/api/pending_closures20232026/11/11 23:22:04 INFO lead: released remote=192.0.2.1:1234 generation=22024--- PASS: TestLeadElectsOneAndHandsOver (10.51s)2025=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure20262026/11/11 23:22:04 INFO Received uploads request method=POST path=/20272026/11/11 23:22:04 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20282026/11/11 23:22:04 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst20292026/11/11 23:22:04 INFO Received uploads request method=POST path=/api/pending_closures2030--- PASS: TestPresignedUploadRegisteredBeforeCommit (9.10s)2031=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts20322026/11/11 23:22:04 INFO Received request for more parts method=POST path=/2033=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart20342026/11/11 23:22:04 INFO Received complete multipart upload request method=POST path=/2035=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info20362026/11/11 23:22:04 INFO Received uploads request method=POST path=/2037=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key20382026/11/11 23:22:04 INFO Received complete multipart upload request method=POST path=/2039=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key20402026/11/11 23:22:04 INFO Received request for more parts method=POST path=/2041=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal20422026/11/11 23:22:04 INFO Received uploads request method=POST path=/2043--- PASS: TestUploadHandlersRejectInvalidKeys (0.01s)2044 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.01s)2045 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2046 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2047 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2048=== CONT TestPush_RejectsBadRequests/root_not_in_objects20492026/11/11 23:22:04 INFO Received push request method=POST path=/api/pushes2050=== CONT TestPush_RejectsBadRequests/no_objects20512026/11/11 23:22:04 INFO Received push request method=POST path=/api/pushes2052=== CONT TestPush_RejectsBadRequests/bad_root20532026/11/11 23:22:04 INFO Received push request method=POST path=/api/pushes2054=== CONT TestPush_RejectsBadRequests/no_roots20552026/11/11 23:22:04 INFO Received push request method=POST path=/api/pushes2056--- PASS: TestPush_RejectsBadRequests (6.85s)2057 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.01s)2058 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2059 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2060 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2061=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2062=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20632026/11/11 23:22:04 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]2064=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured20652026/11/11 23:22:04 WARN Request failed, retrying attempt=2 backoff=184.421296ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2066=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20672026/11/11 23:22:04 WARN Authentication failed token_preview=eyJhbGciOi...A11Srb6-bg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2068=== CONT TestResolveDBConnectionString/flag_wins2069=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2070=== CONT TestResolveDBConnectionString/nothing_configured2071=== CONT TestResolveDBConnectionString/missing_file_is_an_error2072=== CONT TestResolveDBConnectionString/file_when_flag_empty2073=== CONT TestPendingClosureWriteTimeout/empty2074=== CONT TestPendingClosureWriteTimeout/670k_objects2075=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline2076--- PASS: TestService_AuthMiddleware_OIDC (7.13s)2077 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2078 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.01s)2079 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2080 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2081--- PASS: TestResolveDBConnectionString (0.04s)2082 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2083 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2084 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2085 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2086 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)20872026/11/11 23:22:05 INFO Received uploads request method=POST path=/api/pending_closures2088=== CONT TestPendingClosureWriteTimeout/400_objects2089--- PASS: TestUploadHandlersRejectOversizedBody (0.04s)2090 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)2091 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2092 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.29s)2093=== CONT TestProxyWriteTimeout/narinfo2094=== CONT TestProxyWriteTimeout/10_GiB_nar2095=== CONT TestProxyWriteTimeout/unknown_size2096=== CONT TestProxyWriteTimeout/1_GiB_nar2097--- PASS: TestProxyWriteTimeout (0.02s)2098 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2099 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2100 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2101 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)21022026/11/11 23:22:05 WARN Request failed, retrying attempt=3 backoff=435.240926ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2103--- PASS: TestService_Rustfstest (8.66s)2104--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (10.36s)21052026/11/11 23:22:05 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21062026/11/11 23:22:05 WARN Request failed, retrying attempt=4 backoff=789.433938ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21072026/11/11 23:22:05 INFO Received uploads request method=POST path=/api/pending_closures21082026/11/11 23:22:06 INFO Received uploads request method=POST path=/api/pending_closures21092026-11-11 23:22:06.156 UTC [75355] LOG: checkpoint starting: wal21102026/11/11 23:22:06 WARN Request failed, retrying attempt=5 backoff=1.631650847s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2111--- PASS: TestReadProxyInvalidPath (8.94s)21122026/11/11 23:22:06 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21132026/11/11 23:22:06 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjNjMWFiNmEtOTg0ZS00MjcxLThmZGEtOGI2NmIwNDdkZGU4LjQ1YmQ1YWYxLTRhZjgtNDkxOS04ZTFkLTgyOGQyZmMwMTdhOXgxNzk0NDM5MzI2MzA5NTEwMDAw21142026/11/11 23:22:06 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjNjMWFiNmEtOTg0ZS00MjcxLThmZGEtOGI2NmIwNDdkZGU4LjQ1YmQ1YWYxLTRhZjgtNDkxOS04ZTFkLTgyOGQyZmMwMTdhOXgxNzk0NDM5MzI2MzA5NTEwMDAw parts=12115--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (9.68s)21162026/11/11 23:22:07 INFO Received uploads request method=POST path=/api/pending_closures21172026/11/11 23:22:07 INFO Aborted multipart uploads count=0 kept=021182026/11/11 23:22:07 WARN Force mode enabled - objects will be deleted immediately without grace period21192026/11/11 23:22:07 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=021202026/11/11 23:22:07 INFO Vacuumed table table=pending_closures21212026/11/11 23:22:07 INFO Vacuumed table table=pending_objects21222026/11/11 23:22:07 INFO Vacuumed table table=multipart_uploads21232026/11/11 23:22:07 INFO Received uploads request method=POST path=/api/pending_closures21242026/11/11 23:22:07 INFO Vacuumed table table=closures21252026/11/11 23:22:07 INFO Aborted multipart uploads count=0 kept=021262026/11/11 23:22:07 INFO Vacuumed table table=objects21272026/11/11 23:22:07 WARN Force mode enabled - objects will be deleted immediately without grace period21282026/11/11 23:22:07 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=021292026/11/11 23:22:07 INFO Vacuumed table table=pending_closures21302026/11/11 23:22:07 INFO Vacuumed table table=pending_objects21312026/11/11 23:22:07 INFO Vacuumed table table=multipart_uploads21322026/11/11 23:22:07 INFO Vacuumed table table=closures21332026/11/11 23:22:07 INFO Vacuumed table table=objects2134--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2135 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (8.75s)2136 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (8.28s)21372026/11/11 23:22:08 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 127.0.0.1:19999: connect: connection refused"21382026/11/11 23:22:08 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21392026/11/11 23:22:08 WARN Request failed, retrying attempt=2 backoff=205.130069ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21402026/11/11 23:22:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21412026/11/11 23:22:08 WARN Request failed, retrying attempt=3 backoff=397.524317ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21422026/11/11 23:22:08 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YjNjMWFiNmEtOTg0ZS00MjcxLThmZGEtOGI2NmIwNDdkZGU4LmE1ZjdmMWE0LWJiMDYtNDFkZi05NmNmLTk5Y2FkN2ZhMjMzY3gxNzk0NDM5MzI1ODI4MTU4MDAw parts=1221432026/11/11 23:22:08 INFO Received uploads request method=POST path=/api/pending_closures2144--- PASS: TestCompletedNarNotReofferedAcrossClosures (11.47s)21452026/11/11 23:22:08 WARN Request failed, retrying attempt=4 backoff=821.808232ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2146--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2147 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (8.62s)2148 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (8.30s)21492026/11/11 23:22:09 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21502026/11/11 23:22:09 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21512026/11/11 23:22:09 INFO Aborted multipart uploads count=0 kept=021522026/11/11 23:22:09 WARN Force mode enabled - objects will be deleted immediately without grace period21532026/11/11 23:22:09 WARN Request failed, retrying attempt=5 backoff=1.53057423s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21542026/11/11 23:22:09 INFO Aborted multipart uploads count=0 kept=021552026/11/11 23:22:09 WARN Force mode enabled - objects will be deleted immediately without grace period21562026/11/11 23:22:09 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:57487/bucket102/?delete=\": context canceled"2157--- PASS: TestGCEndsOnShutdown (0.04s)2158 --- PASS: TestGCEndsOnShutdown/before_the_run (7.31s)2159 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (7.24s)2160 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (6.85s)21612026/11/11 23:22:10 WARN Rate limiter enabled after throttle name=s3-test rate=521622026/11/11 23:22:10 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2163=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2164 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102165 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002166--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (14.12s)21672026/11/11 23:22:10 INFO Received uploads request method=POST path=/api/pending_closures21682026/11/11 23:22:11 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21692026/11/11 23:22:11 WARN Request failed, retrying attempt=2 backoff=185.205842ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21702026/11/11 23:22:11 WARN Request failed, retrying attempt=3 backoff=415.92726ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21712026/11/11 23:22:11 INFO Received uploads request method=POST path=/api/pending_closures21722026/11/11 23:22:11 WARN Request failed, retrying attempt=4 backoff=752.360524ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21732026/11/11 23:22:12 INFO Received uploads request method=POST path=/api/pending_closures21742026/11/11 23:22:12 WARN Request failed, retrying attempt=5 backoff=1.5025618s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21752026/11/11 23:22:13 INFO Received uploads request method=POST path=/api/pending_closures2176--- PASS: TestClientErrorHandling (0.00s)2177 --- PASS: TestClientErrorHandling/InvalidStorePath (7.66s)2178 --- PASS: TestClientErrorHandling/InvalidAuthToken (7.60s)2179 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.93s)21802026/11/11 23:22:14 INFO Received uploads request method=POST path=/api/pending_closures21812026/11/11 23:22:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21822026/11/11 23:22:15 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=YjNjMWFiNmEtOTg0ZS00MjcxLThmZGEtOGI2NmIwNDdkZGU4LjRjMGUzZWI1LWRmOTktNDIyZi04NzAyLTRmMjRjMTM3Zjk4NHgxNzk0NDM5MzMwNDM2OTI1MDAw parts=1021832026/11/11 23:22:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete2184=== NAME TestOrphanedObjectsGCStressTest2185 orphaned_objects_gc_test.go:503: Stress test completed successfully:2186 orphaned_objects_gc_test.go:504: - Active objects preserved: 202187 orphaned_objects_gc_test.go:505: - Objects deleted: 2102188 orphaned_objects_gc_test.go:506: - Total GC'd: 21021892026/11/11 23:22:15 INFO Completed upload id=1 objects=3 duration=16.945792ms2190--- PASS: TestOrphanedObjectsGCStressTest (39.70s)21912026/11/11 23:22:15 INFO Received uploads request method=POST path=/api/pending_closures21922026/11/11 23:22:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21932026/11/11 23:22:15 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=YjNjMWFiNmEtOTg0ZS00MjcxLThmZGEtOGI2NmIwNDdkZGU4LjZjZTZlOTI2LTVmOTQtNDhjYi1iMTk3LTdkNzk1Mjk4ZWQ2ZXgxNzk0NDM5MzMxNDk0Mjc1MDAw parts=1021942026/11/11 23:22:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21952026/11/11 23:22:15 INFO Completed upload id=1 objects=3 duration=18.312708ms21962026/11/11 23:22:15 INFO Received uploads request method=POST path=/api/pending_closures21972026/11/11 23:22:15 INFO Received uploads request method=POST path=/api/pending_closures21982026/11/11 23:22:15 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21992026/11/11 23:22:15 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo22002026/11/11 23:22:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22012026/11/11 23:22:16 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=YjNjMWFiNmEtOTg0ZS00MjcxLThmZGEtOGI2NmIwNDdkZGU4Ljg4M2IwZDI3LTc3NTUtNDliYi05ODJhLWQ3MTBmN2UyMWQ4MngxNzk0NDM5MzMyNTg0MDAwMDAw parts=1022022026/11/11 23:22:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22032026/11/11 23:22:16 INFO Completed upload id=1 objects=3 duration=8.8905ms2204--- PASS: TestPendingClosureWriteTimeout (0.03s)2205 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2206 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2207 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2208 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (11.31s)22092026/11/11 23:22:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22102026/11/11 23:22:16 INFO Received uploads request method=POST path=/api/pending_closures22112026/11/11 23:22:16 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=YjNjMWFiNmEtOTg0ZS00MjcxLThmZGEtOGI2NmIwNDdkZGU4LjNmZDdiNWU1LTcyZjQtNDg1ZS1hZjY4LWZhNmRmYTdmZDE4OXgxNzk0NDM5MzMzNzcwNzc2MDAw parts=1022122026/11/11 23:22:16 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst22132026/11/11 23:22:16 WARN Found objects in DB but missing from S3, will re-upload count=122142026/11/11 23:22:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22152026/11/11 23:22:16 INFO Completed upload id=1 objects=3 duration=9.544375ms22162026/11/11 23:22:16 INFO Received uploads request method=POST path=/api/pending_closures22172026/11/11 23:22:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22182026/11/11 23:22:16 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=YjNjMWFiNmEtOTg0ZS00MjcxLThmZGEtOGI2NmIwNDdkZGU4LjcyZjQ1ZTU0LWMxMDktNDRlYS04N2M0LTRlNmZhNmY5NjEwM3gxNzk0NDM5MzM0OTI2MjE2MDAw parts=1022192026/11/11 23:22:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22202026/11/11 23:22:16 INFO Completed upload id=1 objects=3 duration=9.253458ms22212026/11/11 23:22:16 INFO Received uploads request method=POST path=/api/pending_closures22222026/11/11 23:22:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22232026/11/11 23:22:17 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=YjNjMWFiNmEtOTg0ZS00MjcxLThmZGEtOGI2NmIwNDdkZGU4LjUyZDEzZmZlLWEzZDktNDc2ZS04ODc2LTE1NjAzY2IxYTkxM3gxNzk0NDM5MzM1NzY0NzMyMDAw parts=1022242026/11/11 23:22:17 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22252026/11/11 23:22:17 INFO Completed upload id=2 objects=3 duration=805.084µs22262026/11/11 23:22:17 INFO Received uploads request method=POST path=/api/pending_closures22272026/11/11 23:22:17 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22282026/11/11 23:22:17 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo22292026/11/11 23:22:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22302026/11/11 23:22:17 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=YjNjMWFiNmEtOTg0ZS00MjcxLThmZGEtOGI2NmIwNDdkZGU4LmQ4ZTYxMjIyLTIyMDgtNGIxZS05MzZkLThmMzlhNDEyZWE4YngxNzk0NDM5MzM2NTI0MTcwMDAw parts=1022312026/11/11 23:22:17 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22322026/11/11 23:22:17 INFO Completed upload id=2 objects=3 duration=1.197208ms22332026/11/11 23:22:17 INFO Received uploads request method=POST path=/api/pending_closures22342026/11/11 23:22:17 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22352026/11/11 23:22:17 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2236--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.00s)2237 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (12.96s)2238 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (12.42s)2239 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (12.18s)2240 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (14.14s)2241 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (13.38s)2242PASS2243{"timestamp":"2026-11-11T23:22:17.762804Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:57528","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}2244{"timestamp":"2026-11-11T23:22:17.763092Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:57833","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}22452026-11-11 23:22:17.894 UTC [75350] LOG: received smart shutdown request22462026-11-11 23:22:17.895 UTC [75350] LOG: background worker "logical replication launcher" (PID 75360) exited with exit code 122472026-11-11 23:22:19.192 UTC [75355] LOG: checkpoint complete: wrote 11530 buffers (70.4%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=12.100 s, sync=0.684 s, total=13.037 s; sync files=36842, longest=0.001 s, average=0.001 s; distance=533620 kB, estimate=533620 kB; lsn=0/22891940, redo lsn=0/220AA11022482026-11-11 23:22:19.193 UTC [75355] LOG: shutting down22492026-11-11 23:22:19.194 UTC [75355] LOG: checkpoint starting: shutdown immediate22502026-11-11 23:22:19.245 UTC [75355] LOG: checkpoint complete: wrote 1161 buffers (7.1%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.031 s, sync=0.020 s, total=0.052 s; sync files=471, longest=0.001 s, average=0.001 s; distance=8094 kB, estimate=481067 kB; lsn=0/228919B8, redo lsn=0/228919B822512026-11-11 23:22:19.251 UTC [75350] LOG: database system is shut down2252Running OIDC tests...2253=== RUN TestAudienceForIssuer2254=== PAUSE TestAudienceForIssuer2255=== RUN TestGlobMatch2256=== PAUSE TestGlobMatch2257=== RUN TestValidateToken_ValidToken2258=== PAUSE TestValidateToken_ValidToken2259=== RUN TestValidateToken_WrongAudience2260=== PAUSE TestValidateToken_WrongAudience2261=== RUN TestValidateToken_Expired2262=== PAUSE TestValidateToken_Expired2263=== RUN TestValidateToken_BoundClaimsMismatch2264=== PAUSE TestValidateToken_BoundClaimsMismatch2265=== RUN TestValidateToken_BoundSubjectMismatch2266=== PAUSE TestValidateToken_BoundSubjectMismatch2267=== RUN TestValidateToken_MultipleProviders2268=== PAUSE TestValidateToken_MultipleProviders2269=== RUN TestValidateToken_NoMatchingProvider2270=== PAUSE TestValidateToken_NoMatchingProvider2271=== RUN TestValidateToken_KubernetesServiceAccount2272=== PAUSE TestValidateToken_KubernetesServiceAccount2273=== RUN TestNewValidator_KubernetesRequiresCA2274=== PAUSE TestNewValidator_KubernetesRequiresCA2275=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2276=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2277=== RUN TestPins_ReservedForMatchingRule2278=== PAUSE TestPins_ReservedForMatchingRule2279=== RUN TestPins_TopLevelShorthand2280=== PAUSE TestPins_TopLevelShorthand2281=== RUN TestPins_ConfigValidation2282=== PAUSE TestPins_ConfigValidation2283=== RUN TestScopes_LegacyProviderDefaultsToWrite2284=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2285=== RUN TestScopes_Rules2286=== PAUSE TestScopes_Rules2287=== RUN TestScopes_ConfigValidation2288=== PAUSE TestScopes_ConfigValidation2289=== CONT TestAudienceForIssuer2290=== CONT TestValidateToken_KubernetesServiceAccount2291=== CONT TestPins_ReservedForMatchingRule2292=== CONT TestPins_ConfigValidation2293--- PASS: TestAudienceForIssuer (0.00s)2294=== CONT TestScopes_ConfigValidation2295=== CONT TestScopes_Rules2296=== CONT TestValidateToken_NoMatchingProvider2297=== CONT TestScopes_LegacyProviderDefaultsToWrite2298=== CONT TestValidateToken_MultipleProviders2299=== CONT TestPins_TopLevelShorthand2300--- PASS: TestPins_ConfigValidation (0.01s)2301=== CONT TestValidateToken_BoundSubjectMismatch2302=== CONT TestValidateToken_BoundClaimsMismatch2303=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2304--- PASS: TestScopes_ConfigValidation (0.01s)2305=== CONT TestValidateToken_Expired2306=== CONT TestNewValidator_KubernetesRequiresCA2307=== CONT TestValidateToken_WrongAudience2308=== CONT TestGlobMatch2309=== RUN TestGlobMatch/foo_foo2310=== PAUSE TestGlobMatch/foo_foo2311=== RUN TestGlobMatch/foo_bar2312=== PAUSE TestGlobMatch/foo_bar2313=== RUN TestGlobMatch/*_2314=== PAUSE TestGlobMatch/*_2315=== RUN TestGlobMatch/*_anything2316=== PAUSE TestGlobMatch/*_anything2317=== RUN TestGlobMatch/foo*_foo2318=== PAUSE TestGlobMatch/foo*_foo2319=== RUN TestGlobMatch/foo*_foobar2320=== PAUSE TestGlobMatch/foo*_foobar2321=== RUN TestGlobMatch/foo*_bar2322=== PAUSE TestGlobMatch/foo*_bar2323=== RUN TestGlobMatch/*bar_bar2324=== PAUSE TestGlobMatch/*bar_bar2325=== RUN TestGlobMatch/*bar_foobar2326=== PAUSE TestGlobMatch/*bar_foobar2327=== RUN TestGlobMatch/*bar_foo2328=== PAUSE TestGlobMatch/*bar_foo2329=== RUN TestGlobMatch/foo*bar_foobar2330=== PAUSE TestGlobMatch/foo*bar_foobar2331=== RUN TestGlobMatch/foo*bar_foo123bar2332=== PAUSE TestGlobMatch/foo*bar_foo123bar2333=== RUN TestGlobMatch/foo*bar_foobarbaz2334=== PAUSE TestGlobMatch/foo*bar_foobarbaz2335=== RUN TestGlobMatch/*/*_foo/bar2336=== PAUSE TestGlobMatch/*/*_foo/bar2337=== RUN TestGlobMatch/*/*_foo2338=== PAUSE TestGlobMatch/*/*_foo2339=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2340=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2341=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02342=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02343=== RUN TestGlobMatch/refs/*/main_refs/heads/main2344=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2345=== RUN TestGlobMatch/fo?_foo2346=== PAUSE TestGlobMatch/fo?_foo2347=== RUN TestGlobMatch/fo?_fo2348=== PAUSE TestGlobMatch/fo?_fo2349=== RUN TestGlobMatch/fo?_fooo2350=== PAUSE TestGlobMatch/fo?_fooo2351=== RUN TestGlobMatch/?oo_foo2352=== PAUSE TestGlobMatch/?oo_foo2353=== RUN TestGlobMatch/?oo_boo2354=== PAUSE TestGlobMatch/?oo_boo2355=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2356=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2357=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2358=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2359=== CONT TestGlobMatch/foo_foo2360=== CONT TestValidateToken_ValidToken2361=== CONT TestGlobMatch/*/*_foo/bar2362=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2363=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2364=== CONT TestGlobMatch/?oo_boo2365=== CONT TestGlobMatch/?oo_foo2366=== CONT TestGlobMatch/fo?_fooo2367=== CONT TestGlobMatch/fo?_fo2368=== CONT TestGlobMatch/fo?_foo2369=== CONT TestGlobMatch/refs/*/main_refs/heads/main2370=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02371=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2372=== CONT TestGlobMatch/*/*_foo2373=== CONT TestGlobMatch/*bar_bar2374=== CONT TestGlobMatch/foo*bar_foobarbaz2375=== CONT TestGlobMatch/foo*bar_foo123bar2376=== CONT TestGlobMatch/foo*bar_foobar2377=== CONT TestGlobMatch/*bar_foo2378=== CONT TestGlobMatch/*bar_foobar2379=== CONT TestGlobMatch/foo*_foo2380=== CONT TestGlobMatch/foo*_bar2381=== CONT TestGlobMatch/foo*_foobar2382=== CONT TestGlobMatch/*_2383=== CONT TestGlobMatch/*_anything2384=== CONT TestGlobMatch/foo_bar2385--- PASS: TestGlobMatch (0.00s)2386 --- PASS: TestGlobMatch/foo_foo (0.00s)2387 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2388 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2389 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2390 --- PASS: TestGlobMatch/?oo_boo (0.00s)2391 --- PASS: TestGlobMatch/?oo_foo (0.00s)2392 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2393 --- PASS: TestGlobMatch/fo?_fo (0.00s)2394 --- PASS: TestGlobMatch/fo?_foo (0.00s)2395 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2396 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2397 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2398 --- PASS: TestGlobMatch/*/*_foo (0.00s)2399 --- PASS: TestGlobMatch/*bar_bar (0.00s)2400 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2401 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2402 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2403 --- PASS: TestGlobMatch/*bar_foo (0.00s)2404 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2405 --- PASS: TestGlobMatch/foo*_foo (0.00s)2406 --- PASS: TestGlobMatch/foo*_bar (0.00s)2407 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2408 --- PASS: TestGlobMatch/*_ (0.00s)2409 --- PASS: TestGlobMatch/*_anything (0.00s)2410 --- PASS: TestGlobMatch/foo_bar (0.00s)24112026/11/11 23:22:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57839/oidc24122026/11/11 23:22:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57841/oidc2413--- PASS: TestPins_TopLevelShorthand (0.06s)24142026/11/11 23:22:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57843/oidc2415--- PASS: TestValidateToken_ValidToken (0.05s)24162026/11/11 23:22:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57842/oidc2417--- PASS: TestValidateToken_BoundClaimsMismatch (0.06s)2418--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.07s)24192026/11/11 23:22:21 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232420--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.08s)24212026/11/11 23:22:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57851/oidc24222026/11/11 23:22:21 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:578492423--- PASS: TestValidateToken_Expired (0.08s)24242026/11/11 23:22:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57853/oidc2425--- PASS: TestScopes_Rules (0.09s)2426--- PASS: TestValidateToken_KubernetesServiceAccount (0.09s)24272026/11/11 23:22:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57855/oidc2428--- PASS: TestValidateToken_BoundSubjectMismatch (0.12s)24292026/11/11 23:22:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57859/oidc2430--- PASS: TestValidateToken_WrongAudience (0.14s)24312026/11/11 23:22:21 http: TLS handshake error from 127.0.0.1:57858: remote error: tls: bad certificate2432--- PASS: TestNewValidator_KubernetesRequiresCA (0.14s)24332026/11/11 23:22:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57862/oidc2434--- PASS: TestPins_ReservedForMatchingRule (0.17s)24352026/11/11 23:22:21 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:57861/oidc24362026/11/11 23:22:21 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:57864/oidc2437--- PASS: TestValidateToken_MultipleProviders (0.20s)24382026/11/11 23:22:21 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:57867/oidc2439--- PASS: TestValidateToken_NoMatchingProvider (0.26s)2440PASS2441Running hook tests...2442=== RUN TestSendPathsEmpty2443=== PAUSE TestSendPathsEmpty2444=== RUN TestQueueEnqueueAndFetch2445=== PAUSE TestQueueEnqueueAndFetch2446=== RUN TestQueueDeduplication2447=== PAUSE TestQueueDeduplication2448=== RUN TestQueueRemove2449=== PAUSE TestQueueRemove2450=== RUN TestQueueFetchBatchLimit2451=== PAUSE TestQueueFetchBatchLimit2452=== RUN TestQueueRetryMovesToBack2453=== PAUSE TestQueueRetryMovesToBack2454=== RUN TestQueueFetchRemoveLifecycle2455=== PAUSE TestQueueFetchRemoveLifecycle2456=== RUN TestQueueConcurrentWriters2457=== PAUSE TestQueueConcurrentWriters2458=== RUN TestQueueRemoveLargeClosure2459=== PAUSE TestQueueRemoveLargeClosure2460=== RUN TestServerClientIntegration2461--- PASS: TestServerClientIntegration (0.00s)2462=== RUN TestServerQueueError24632026/11/11 23:22:21 ERROR Failed to queue paths error="permission denied" count=12464--- PASS: TestServerQueueError (0.00s)2465=== RUN TestGetListenerSocketActivation2466 server_test.go:146: systemd socket activation does not exist on darwin2467--- SKIP: TestGetListenerSocketActivation (0.00s)2468=== RUN TestServerStalledClientDoesNotBlockShutdown2469=== PAUSE TestServerStalledClientDoesNotBlockShutdown2470=== RUN TestServerBacksOffOnAcceptErrors2471=== PAUSE TestServerBacksOffOnAcceptErrors2472=== RUN TestDrainIsolatesPoisonPath2473=== PAUSE TestDrainIsolatesPoisonPath2474=== RUN TestRunNotBlockedByPoisonHead2475=== PAUSE TestRunNotBlockedByPoisonHead2476=== RUN TestDrainGivesUpWhenServerDown2477=== PAUSE TestDrainGivesUpWhenServerDown2478=== RUN TestFailedPathPrunedByLaterClosure2479=== PAUSE TestFailedPathPrunedByLaterClosure2480=== RUN TestWorkerUploadsAndRemoves2481=== PAUSE TestWorkerUploadsAndRemoves2482=== RUN TestWorkerSkipsGCdPaths2483=== PAUSE TestWorkerSkipsGCdPaths2484=== RUN TestWorkerPrunesClosureDeps2485=== PAUSE TestWorkerPrunesClosureDeps2486=== RUN TestDrainTimeout2487=== PAUSE TestDrainTimeout2488=== RUN TestWorkerRemoveFailureIsNotProgress2489=== PAUSE TestWorkerRemoveFailureIsNotProgress2490=== RUN TestWorkerKeepsPathItCannotStat2491=== PAUSE TestWorkerKeepsPathItCannotStat2492=== CONT TestSendPathsEmpty2493=== CONT TestWorkerRemoveFailureIsNotProgress2494--- PASS: TestSendPathsEmpty (0.00s)2495=== CONT TestWorkerKeepsPathItCannotStat2496=== CONT TestDrainIsolatesPoisonPath2497=== CONT TestServerBacksOffOnAcceptErrors2498=== CONT TestServerStalledClientDoesNotBlockShutdown24992026/11/11 23:22:21 ERROR Accept failed error="too many open files"2500=== CONT TestQueueFetchBatchLimit2501=== CONT TestQueueRemove2502=== CONT TestQueueDeduplication2503=== CONT TestQueueRetryMovesToBack2504=== CONT TestQueueEnqueueAndFetch2505=== CONT TestQueueRemoveLargeClosure2506=== CONT TestQueueConcurrentWriters2507=== CONT TestWorkerUploadsAndRemoves2508=== CONT TestQueueFetchRemoveLifecycle2509=== CONT TestWorkerSkipsGCdPaths2510=== CONT TestDrainGivesUpWhenServerDown2511=== CONT TestFailedPathPrunedByLaterClosure2512=== CONT TestDrainTimeout2513=== CONT TestRunNotBlockedByPoisonHead2514=== CONT TestWorkerPrunesClosureDeps25152026/11/11 23:22:21 ERROR Accept failed error="too many open files"25162026/11/11 23:22:21 WARN Cannot stat store path, will retry later path=/private/var/tb/8/scratch/9c621a23873fdf7e/build/TestWorkerKeepsPathItCannotStat2267037352/002/locked/aaa error="stat /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestWorkerKeepsPathItCannotStat2267037352/002/locked/aaa: permission denied"25172026/11/11 23:22:21 INFO Upload queue status pending=225182026/11/11 23:22:21 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/8/scratch/9c621a23873fdf7e/build/TestWorkerSkipsGCdPaths3087625700/002/nonexistent25192026/11/11 23:22:21 INFO Upload queue status pending=225202026/11/11 23:22:21 INFO Upload queue status pending=225212026/11/11 23:22:21 INFO Uploading batch count=125222026/11/11 23:22:21 INFO Uploading batch count=125232026/11/11 23:22:21 INFO Uploading batch count=225242026/11/11 23:22:21 ERROR Accept failed error="too many open files"25252026/11/11 23:22:21 INFO Uploading batch count=125262026/11/11 23:22:21 ERROR Upload failed error="upload failed" count=12527--- PASS: TestQueueFetchBatchLimit (0.02s)2528--- PASS: TestQueueEnqueueAndFetch (0.02s)25292026/11/11 23:22:21 INFO Uploading batch count=125302026/11/11 23:22:21 INFO Uploading batch count=425312026/11/11 23:22:21 ERROR Upload failed error="upload failed" count=425322026/11/11 23:22:21 INFO Uploading batch count=225332026/11/11 23:22:21 WARN Cannot stat store path, will retry later path=/private/var/tb/8/scratch/9c621a23873fdf7e/build/TestWorkerKeepsPathItCannotStat2267037352/002/locked/aaa error="stat /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestWorkerKeepsPathItCannotStat2267037352/002/locked/aaa: permission denied"25342026/11/11 23:22:21 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/9c621a23873fdf7e/build/TestDrainIsolatesPoisonPath2787993454/002/bbb25352026/11/11 23:22:21 INFO Upload queue status pending=325362026/11/11 23:22:21 INFO Uploading batch count=125372026/11/11 23:22:21 ERROR Upload failed error="upload failed" count=12538--- PASS: TestQueueDeduplication (0.02s)25392026/11/11 23:22:21 INFO Uploading batch count=125402026/11/11 23:22:21 INFO Uploading batch count=225412026/11/11 23:22:21 WARN Cannot stat store path, will retry later path=/private/var/tb/8/scratch/9c621a23873fdf7e/build/TestWorkerKeepsPathItCannotStat2267037352/002/locked/aaa error="stat /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestWorkerKeepsPathItCannotStat2267037352/002/locked/aaa: permission denied"25422026/11/11 23:22:21 ERROR Upload failed error="upload failed" count=225432026/11/11 23:22:21 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/9c621a23873fdf7e/build/TestDrainGivesUpWhenServerDown1617001131/002/a2544--- PASS: TestQueueRemove (0.02s)25452026/11/11 23:22:21 ERROR Drain finished with paths left in queue remaining=125462026/11/11 23:22:21 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/8/scratch/9c621a23873fdf7e/build/TestWorkerRemoveFailureIsNotProgress1245888344/002/nonexistent2547--- PASS: TestQueueRetryMovesToBack (0.02s)25482026/11/11 23:22:21 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125492026/11/11 23:22:21 INFO Uploading batch count=12550--- PASS: TestQueueFetchRemoveLifecycle (0.02s)25512026/11/11 23:22:21 ERROR Upload failed error="upload failed" count=125522026/11/11 23:22:21 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/9c621a23873fdf7e/build/TestDrainGivesUpWhenServerDown1617001131/002/b25532026/11/11 23:22:21 INFO Uploading batch count=125542026/11/11 23:22:21 ERROR Upload failed error="upload failed" count=125552026/11/11 23:22:21 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/8/scratch/9c621a23873fdf7e/build/TestWorkerRemoveFailureIsNotProgress1245888344/002/nonexistent25562026/11/11 23:22:21 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125572026/11/11 23:22:21 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/8/scratch/9c621a23873fdf7e/build/TestWorkerRemoveFailureIsNotProgress1245888344/002/nonexistent25582026/11/11 23:22:21 INFO Uploading batch count=125592026/11/11 23:22:21 ERROR Upload failed error="upload failed" count=125602026/11/11 23:22:21 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125612026/11/11 23:22:21 INFO Uploading batch count=225622026/11/11 23:22:21 ERROR Upload failed error="upload failed" count=225632026/11/11 23:22:21 ERROR Drain finished with paths left in queue remaining=125642026/11/11 23:22:21 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/9c621a23873fdf7e/build/TestDrainGivesUpWhenServerDown1617001131/002/c25652026/11/11 23:22:21 ERROR Drain finished with paths left in queue remaining=12566--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)25672026/11/11 23:22:21 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/9c621a23873fdf7e/build/TestDrainGivesUpWhenServerDown1617001131/002/d2568--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)25692026/11/11 23:22:21 INFO Uploading batch count=225702026/11/11 23:22:21 ERROR Upload failed error="upload failed" count=225712026/11/11 23:22:21 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/9c621a23873fdf7e/build/TestDrainGivesUpWhenServerDown1617001131/002/e25722026/11/11 23:22:21 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/9c621a23873fdf7e/build/TestDrainGivesUpWhenServerDown1617001131/002/f2573--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)25742026/11/11 23:22:21 ERROR Drain finished with paths left in queue remaining=102575--- PASS: TestDrainIsolatesPoisonPath (0.02s)2576--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2577--- PASS: TestWorkerSkipsGCdPaths (0.03s)25782026/11/11 23:22:21 ERROR Accept failed error="too many open files"2579--- PASS: TestWorkerPrunesClosureDeps (0.03s)2580--- PASS: TestWorkerUploadsAndRemoves (0.03s)2581--- PASS: TestQueueRemoveLargeClosure (0.05s)2582--- PASS: TestQueueConcurrentWriters (0.06s)25832026/11/11 23:22:21 ERROR Accept failed error="too many open files"25842026/11/11 23:22:21 ERROR Accept failed error="too many open files"25852026/11/11 23:22:21 ERROR Failed to decode request error="read unix /private/var/tb/8/scratch/9c621a23873fdf7e/build/hook1978509668/test.sock->: i/o timeout"25862026/11/11 23:22:21 ERROR Failed to write response error="write unix /private/var/tb/8/scratch/9c621a23873fdf7e/build/hook1978509668/test.sock->: i/o timeout"2587--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)25882026/11/11 23:22:21 ERROR Upload failed error="context deadline exceeded" count=225892026/11/11 23:22:21 ERROR Drain finished with paths left in queue remaining=42590--- PASS: TestDrainTimeout (0.22s)25912026/11/11 23:22:21 ERROR Accept failed error="too many open files"25922026/11/11 23:22:22 ERROR Accept failed error="too many open files"2593--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)25942026/11/11 23:22:22 INFO Uploading batch count=125952026/11/11 23:22:22 INFO Uploading batch count=125962026/11/11 23:22:22 INFO Uploading batch count=125972026/11/11 23:22:22 ERROR Upload failed error="upload failed" count=125982026/11/11 23:22:22 INFO Uploading batch count=125992026/11/11 23:22:22 ERROR Upload failed error="upload failed" count=126002026/11/11 23:22:22 INFO Uploading batch count=126012026/11/11 23:22:22 ERROR Upload failed error="upload failed" count=126022026/11/11 23:22:22 INFO Uploading batch count=126032026/11/11 23:22:22 ERROR Upload failed error="upload failed" count=126042026/11/11 23:22:22 ERROR Drain finished with paths left in queue remaining=12605--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2606PASS2607Running signing tests...2608=== RUN TestExternalSigner2609=== PAUSE TestExternalSigner2610=== RUN TestExternalSignerWrongPublicKey2611=== PAUSE TestExternalSignerWrongPublicKey2612=== RUN TestExternalSignerErrors2613=== PAUSE TestExternalSignerErrors2614=== RUN TestExternalSignerRestartsAfterCrash2615=== PAUSE TestExternalSignerRestartsAfterCrash2616=== RUN TestExternalSignerProgramErrorKeepsProcess2617=== PAUSE TestExternalSignerProgramErrorKeepsProcess2618=== RUN TestExternalSignerClose2619=== PAUSE TestExternalSignerClose2620=== RUN TestExternalSignerRejectsInvalidPublicKey2621=== PAUSE TestExternalSignerRejectsInvalidPublicKey2622=== RUN TestExternalSignerCancellation2623=== PAUSE TestExternalSignerCancellation2624=== RUN TestGenerateFingerprint2625=== PAUSE TestGenerateFingerprint2626=== RUN TestParseSigningKey2627=== PAUSE TestParseSigningKey2628=== RUN TestSign2629=== PAUSE TestSign2630=== RUN TestSignBatch2631=== PAUSE TestSignBatch2632=== RUN TestNilKeyPublicKey2633=== PAUSE TestNilKeyPublicKey2634=== RUN TestSignErrors2635=== PAUSE TestSignErrors2636=== CONT TestExternalSigner2637=== CONT TestExternalSignerCancellation2638=== CONT TestSignBatch2639=== CONT TestExternalSignerProgramErrorKeepsProcess2640=== CONT TestSignErrors2641=== CONT TestNilKeyPublicKey2642--- PASS: TestNilKeyPublicKey (0.00s)2643=== CONT TestParseSigningKey2644=== RUN TestParseSigningKey/valid_32-byte_key2645=== PAUSE TestParseSigningKey/valid_32-byte_key2646=== CONT TestSign2647=== CONT TestExternalSignerErrors2648=== RUN TestExternalSignerErrors/wrong_shape2649=== PAUSE TestExternalSignerErrors/wrong_shape2650=== CONT TestExternalSignerRestartsAfterCrash2651=== CONT TestGenerateFingerprint2652=== RUN TestGenerateFingerprint/basic_with_references2653=== PAUSE TestGenerateFingerprint/basic_with_references2654=== RUN TestGenerateFingerprint/no_references2655=== PAUSE TestGenerateFingerprint/no_references2656=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2657=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2658=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2659=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2660=== RUN TestGenerateFingerprint/invalid_nar_hash_length2661=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2662=== RUN TestGenerateFingerprint/invalid_store_path_prefix2663=== CONT TestExternalSignerRejectsInvalidPublicKey2664=== RUN TestExternalSignerRejectsInvalidPublicKey/#002665=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002666=== CONT TestExternalSignerClose2667=== CONT TestExternalSignerWrongPublicKey2668=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2669=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2670=== RUN TestParseSigningKey/no_colon2671=== PAUSE TestParseSigningKey/no_colon2672=== RUN TestParseSigningKey/empty_name2673=== PAUSE TestParseSigningKey/empty_name2674=== RUN TestExternalSignerErrors/missing_signatures2675=== RUN TestParseSigningKey/invalid_base642676=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2677=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2678=== PAUSE TestExternalSignerErrors/missing_signatures2679=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2680=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2681=== RUN TestExternalSignerErrors/unrequested_key2682=== RUN TestGenerateFingerprint/invalid_reference_prefix2683=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2684=== PAUSE TestExternalSignerErrors/unrequested_key2685=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2686=== RUN TestExternalSignerErrors/program_error2687=== PAUSE TestExternalSignerErrors/program_error2688=== RUN TestExternalSignerErrors/wrong_id2689=== PAUSE TestExternalSignerErrors/wrong_id2690=== RUN TestExternalSignerErrors/null_signatures2691=== PAUSE TestExternalSignerErrors/null_signatures2692=== RUN TestExternalSignerErrors/wrong_signature_name2693=== PAUSE TestExternalSignerErrors/wrong_signature_name2694=== RUN TestExternalSignerErrors/wrong_signature_length2695=== PAUSE TestExternalSignerErrors/wrong_signature_length2696=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2697=== CONT TestGenerateFingerprint/basic_with_references2698=== PAUSE TestParseSigningKey/invalid_base642699=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2700=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2701=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2702=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2703=== CONT TestGenerateFingerprint/invalid_reference_prefix2704=== CONT TestGenerateFingerprint/invalid_store_path_prefix2705=== CONT TestGenerateFingerprint/invalid_nar_hash_length2706=== CONT TestGenerateFingerprint/no_references2707--- PASS: TestGenerateFingerprint (0.00s)2708 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2709 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2710 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2711 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2712 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2713 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2714 --- PASS: TestGenerateFingerprint/no_references (0.00s)2715=== RUN TestExternalSignerErrors/null2716=== RUN TestParseSigningKey/wrong_length2717=== PAUSE TestParseSigningKey/wrong_length2718=== CONT TestParseSigningKey/valid_32-byte_key2719=== CONT TestParseSigningKey/no_colon2720=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2721=== CONT TestParseSigningKey/empty_name2722=== CONT TestParseSigningKey/invalid_base642723=== CONT TestParseSigningKey/wrong_length2724=== PAUSE TestExternalSignerErrors/null2725=== RUN TestExternalSignerErrors/wrong_signatures_shape2726=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2727=== RUN TestExternalSignerErrors/exit_on_request2728=== PAUSE TestExternalSignerErrors/exit_on_request2729=== RUN TestExternalSignerErrors/invalid_JSON2730=== PAUSE TestExternalSignerErrors/invalid_JSON2731=== RUN TestExternalSignerErrors/too_few_signatures2732=== PAUSE TestExternalSignerErrors/too_few_signatures2733=== RUN TestExternalSignerErrors/missing_signature_name2734=== PAUSE TestExternalSignerErrors/missing_signature_name2735=== RUN TestExternalSignerErrors/invalid_signature_base642736=== PAUSE TestExternalSignerErrors/invalid_signature_base642737=== RUN TestExternalSignerErrors/exit_at_startup2738=== PAUSE TestExternalSignerErrors/exit_at_startup2739=== CONT TestExternalSignerErrors/wrong_shape2740=== CONT TestExternalSignerErrors/wrong_signatures_shape2741=== CONT TestExternalSignerErrors/null2742=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2743=== CONT TestExternalSignerRejectsInvalidPublicKey/#002744--- PASS: TestSignBatch (0.00s)2745=== CONT TestExternalSignerErrors/exit_at_startup2746=== CONT TestExternalSignerErrors/wrong_id2747=== RUN TestSignErrors/nil_key2748=== PAUSE TestSignErrors/nil_key2749=== RUN TestSignErrors/nil_narinfo2750=== PAUSE TestSignErrors/nil_narinfo2751=== RUN TestSignErrors/invalid_narinfo2752=== PAUSE TestSignErrors/invalid_narinfo2753=== RUN TestSignErrors/canceled2754=== PAUSE TestSignErrors/canceled2755=== CONT TestExternalSignerErrors/invalid_JSON2756=== CONT TestExternalSignerErrors/wrong_signature_name2757=== CONT TestExternalSignerErrors/wrong_signature_length2758=== CONT TestExternalSignerErrors/unrequested_key2759=== CONT TestExternalSignerErrors/program_error2760=== CONT TestExternalSignerErrors/null_signatures2761=== CONT TestExternalSignerErrors/exit_on_request2762=== CONT TestExternalSignerErrors/invalid_signature_base642763=== CONT TestExternalSignerErrors/missing_signature_name2764=== CONT TestExternalSignerErrors/too_few_signatures2765--- PASS: TestSign (0.01s)2766=== CONT TestExternalSignerErrors/missing_signatures2767=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2768=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2769=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2770=== CONT TestSignErrors/nil_key2771=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2772=== CONT TestSignErrors/invalid_narinfo2773=== CONT TestSignErrors/nil_narinfo2774=== CONT TestSignErrors/canceled2775--- PASS: TestParseSigningKey (0.00s)2776 --- PASS: TestParseSigningKey/empty_name (0.00s)2777 --- PASS: TestParseSigningKey/no_colon (0.00s)2778 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2779 --- PASS: TestParseSigningKey/wrong_length (0.00s)2780 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2781 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2782--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2783 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2784 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2785 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2786 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2787 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2788--- PASS: TestSignErrors (0.01s)2789 --- PASS: TestSignErrors/nil_key (0.00s)2790 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2791 --- PASS: TestSignErrors/nil_narinfo (0.00s)2792 --- PASS: TestSignErrors/canceled (0.00s)2793--- PASS: TestExternalSignerCancellation (0.24s)2794--- PASS: TestExternalSignerRestartsAfterCrash (0.42s)2795/private/var/tb/8/scratch/9c621a23873fdf7e/build/TestExternalSignerRestartsAfterCrash139424729/001/sign program: line 7: /private/var/tb/8/scratch/9c621a23873fdf7e/build/TestExternalSignerRestartsAfterCrash139424729/001/sign program.starts: No such file or directory2796--- PASS: TestExternalSigner (0.61s)2797--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.78s)2798--- PASS: TestExternalSignerWrongPublicKey (2.35s)2799--- PASS: TestExternalSignerClose (2.91s)2800--- PASS: TestExternalSignerErrors (0.00s)2801 --- PASS: TestExternalSignerErrors/wrong_id (0.97s)2802 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (1.21s)2803 --- PASS: TestExternalSignerErrors/invalid_JSON (1.40s)2804 --- PASS: TestExternalSignerErrors/too_few_signatures (1.58s)2805 --- PASS: TestExternalSignerErrors/program_error (1.77s)2806 --- PASS: TestExternalSignerErrors/wrong_signature_length (1.96s)2807 --- PASS: TestExternalSignerErrors/unrequested_key (2.15s)2808 --- PASS: TestExternalSignerErrors/null (2.53s)2809 --- PASS: TestExternalSignerErrors/wrong_shape (2.72s)2810 --- PASS: TestExternalSignerErrors/exit_at_startup (3.09s)2811 --- PASS: TestExternalSignerErrors/null_signatures (3.28s)2812 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (3.47s)2813 --- PASS: TestExternalSignerErrors/missing_signatures (3.66s)2814 --- PASS: TestExternalSignerErrors/missing_signature_name (3.85s)2815 --- PASS: TestExternalSignerErrors/exit_on_request (4.04s)2816 --- PASS: TestExternalSignerErrors/wrong_signature_name (4.23s)2817PASS2818Running OpenBao signer tests...2819=== RUN TestSign2820=== PAUSE TestSign2821=== RUN TestSignErrors2822=== PAUSE TestSignErrors2823=== RUN TestServe2824=== PAUSE TestServe2825=== RUN TestServeRejectsGarbage2826=== PAUSE TestServeRejectsGarbage2827=== CONT TestSign2828=== CONT TestServe2829=== CONT TestServeRejectsGarbage2830=== CONT TestSignErrors2831--- PASS: TestServeRejectsGarbage (0.00s)2832=== RUN TestSignErrors/invalid_base642833=== PAUSE TestSignErrors/invalid_base642834=== RUN TestSignErrors/http_error2835=== PAUSE TestSignErrors/http_error2836=== RUN TestSignErrors/invalid_json2837=== PAUSE TestSignErrors/invalid_json2838=== RUN TestSignErrors/no_prefix2839=== PAUSE TestSignErrors/no_prefix2840=== CONT TestSignErrors/invalid_base642841=== CONT TestSignErrors/invalid_json2842=== CONT TestSignErrors/http_error2843=== CONT TestSignErrors/no_prefix2844--- PASS: TestServe (0.00s)2845--- PASS: TestSign (0.00s)2846--- PASS: TestSignErrors (0.00s)2847 --- PASS: TestSignErrors/no_prefix (0.00s)2848 --- PASS: TestSignErrors/invalid_base64 (0.00s)2849 --- PASS: TestSignErrors/http_error (0.00s)2850 --- PASS: TestSignErrors/invalid_json (0.00s)2851PASS