niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #471
· raw
1tribuchet: building on jamie2Running 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.04s)25=== RUN TestDumpPathCaseHackCollision26--- PASS: TestDumpPathCaseHackCollision (0.00s)27=== RUN TestCaseHackPathIsRefusedWithoutStrip28--- PASS: TestCaseHackPathIsRefusedWithoutStrip (0.00s)29=== RUN TestDumpPathMatchesNix30=== PAUSE TestDumpPathMatchesNix31=== RUN TestDumpPathSingleFile32=== PAUSE TestDumpPathSingleFile33=== RUN TestDumpPathWriterError34=== PAUSE TestDumpPathWriterError35=== RUN TestEncodeNixBase3236=== PAUSE TestEncodeNixBase3237=== RUN TestEncodeNixBase32WithRealHash38=== PAUSE TestEncodeNixBase32WithRealHash39=== RUN TestConvertHashToNix3240=== PAUSE TestConvertHashToNix3241=== RUN TestGetStorePathHash42=== PAUSE TestGetStorePathHash43=== RUN TestPathInfoHashCompatibility44=== PAUSE TestPathInfoHashCompatibility45=== RUN TestParsePathInfoJSON46=== PAUSE TestParsePathInfoJSON47=== RUN TestParsePathInfoJSONMultiplePaths48=== PAUSE TestParsePathInfoJSONMultiplePaths49=== RUN TestPathInfoCACompatibility50=== PAUSE TestPathInfoCACompatibility51=== RUN TestRateLimiterFeedback52=== PAUSE TestRateLimiterFeedback53=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess54=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess55=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer56=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer57=== RUN TestRegisterUploadedObject_OutlivesPush58=== PAUSE TestRegisterUploadedObject_OutlivesPush59=== RUN TestResolveStorePath60=== PAUSE TestResolveStorePath61=== RUN TestDoWithRetry_BodyReplayedViaGetBody62=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody63=== RUN TestRetryTimeoutOutlastsMaxRetries64=== PAUSE TestRetryTimeoutOutlastsMaxRetries65=== RUN TestDoWithRetry_FinalResponseBodyReadable66=== PAUSE TestDoWithRetry_FinalResponseBodyReadable67=== RUN TestShellSplit68=== PAUSE TestShellSplit69=== RUN TestShellSplitErrors70=== PAUSE TestShellSplitErrors71=== RUN TestStreamPushReportsEveryPath72=== PAUSE TestStreamPushReportsEveryPath73=== RUN TestStreamPushBatchesUnderLoad74=== PAUSE TestStreamPushBatchesUnderLoad75=== RUN TestStreamPushIsolatesFailures76=== PAUSE TestStreamPushIsolatesFailures77=== RUN TestStreamPushGivesUpOnDeadServer78=== PAUSE TestStreamPushGivesUpOnDeadServer79=== RUN TestStreamPushRequestLine80=== PAUSE TestStreamPushRequestLine81=== RUN TestStreamPushReportsSignatures82=== PAUSE TestStreamPushReportsSignatures83=== RUN TestStreamPushReportsSkippedPaths84=== PAUSE TestStreamPushReportsSkippedPaths85=== RUN TestClientSignaturesByStorePath86=== PAUSE TestClientSignaturesByStorePath87=== RUN TestStreamPushStopsWhenCanceled88=== PAUSE TestStreamPushStopsWhenCanceled89=== RUN TestSetClientTLS90=== PAUSE TestSetClientTLS91=== RUN TestSetClientTLSDoesNotMutateDefaultTransport92=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport93=== RUN TestSetClientTLSErrors94=== PAUSE TestSetClientTLSErrors95=== RUN TestStaticToken96=== PAUSE TestStaticToken97=== RUN TestFileTokenReadsAndCaches98=== PAUSE TestFileTokenReadsAndCaches99=== RUN TestFileTokenMissing100=== PAUSE TestFileTokenMissing101=== RUN TestFileTokenEmpty102=== PAUSE TestFileTokenEmpty103=== RUN TestScriptTokenNoExpiryRerunsEveryCall104=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall105=== RUN TestScriptTokenCachesUntilRefresh106=== PAUSE TestScriptTokenCachesUntilRefresh107=== RUN TestScriptTokenEmptyToken108=== PAUSE TestScriptTokenEmptyToken109=== RUN TestScriptTokenBadJSON110=== PAUSE TestScriptTokenBadJSON111=== RUN TestScriptTokenScriptFails112=== PAUSE TestScriptTokenScriptFails113=== RUN TestScriptTokenEmptyCommand114=== PAUSE TestScriptTokenEmptyCommand115=== CONT TestDoServerRequestAttachesToken116=== CONT TestRetryTimeoutOutlastsMaxRetries117=== CONT TestStreamPushGivesUpOnDeadServer118=== CONT TestEncodeNixBase32WithRealHash119--- PASS: TestEncodeNixBase32WithRealHash (0.00s)120=== CONT TestGetStorePathHash121=== RUN TestGetStorePathHash/valid_store_path122=== CONT TestSetClientTLS123=== CONT TestDoWithRetry_BodyReplayedViaGetBody124=== CONT TestScriptTokenEmptyCommand125--- PASS: TestScriptTokenEmptyCommand (0.00s)126=== CONT TestStaticToken127--- PASS: TestStaticToken (0.00s)128=== CONT TestConvertHashToNix32129=== RUN TestConvertHashToNix32/SRI_format_to_Nix32130=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32131=== RUN TestConvertHashToNix32/already_Nix32_format1322026/11/09 11:52:34 ERROR Upload failed error="connection refused" count=20133=== PAUSE TestConvertHashToNix32/already_Nix32_format1342026/11/09 11:52:34 ERROR Server seems unavailable, giving up on batch untried=17135=== RUN TestConvertHashToNix32/invalid_format136=== PAUSE TestConvertHashToNix32/invalid_format137=== CONT TestResolveStorePath138=== CONT TestScriptTokenScriptFails139=== CONT TestSetClientTLSErrors140=== CONT TestRegisterUploadedObject_OutlivesPush141=== CONT TestScriptTokenBadJSON142=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer143=== CONT TestScriptTokenEmptyToken144=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess145=== CONT TestScriptTokenCachesUntilRefresh146=== CONT TestRateLimiterFeedback147=== CONT TestPathInfoCACompatibility148=== CONT TestScriptTokenNoExpiryRerunsEveryCall149=== CONT TestParsePathInfoJSONMultiplePaths150=== CONT TestFileTokenEmpty151=== CONT TestParsePathInfoJSON152=== CONT TestFileTokenMissing153=== CONT TestPathInfoHashCompatibility154=== CONT TestFileTokenReadsAndCaches155=== PAUSE TestGetStorePathHash/valid_store_path156=== RUN TestRateLimiterFeedback/429_enables_limiter157=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths158=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths159=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths160=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths161=== CONT TestStreamPushReportsEveryPath162=== RUN TestPathInfoCACompatibility/null_ca_field163=== PAUSE TestPathInfoCACompatibility/null_ca_field164=== RUN TestPathInfoCACompatibility/old_string_format_-_text165=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text166--- PASS: TestResolveStorePath (0.01s)167=== CONT TestSetClientTLSDoesNotMutateDefaultTransport1682026/11/09 11:52:34 WARN Rate limiter enabled after throttle name=server-test rate=5169=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive170--- PASS: TestStreamPushReportsEveryPath (0.00s)171=== CONT TestStreamPushIsolatesFailures172=== RUN TestParsePathInfoJSON/Nix_format173=== PAUSE TestParsePathInfoJSON/Nix_format174--- PASS: TestFileTokenMissing (0.00s)175=== RUN TestGetStorePathHash/basename_without_hyphen_should_error176=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)177=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)178=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon179=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon180=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI181=== CONT TestStreamPushReportsSkippedPaths182=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error183=== CONT TestStreamPushStopsWhenCanceled1842026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:44235185=== CONT TestShellSplit186=== CONT TestClientSignaturesByStorePath187=== CONT TestShellSplitErrors188=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive189=== CONT TestStreamPushReportsSignatures190=== PAUSE TestRateLimiterFeedback/429_enables_limiter191=== CONT TestStreamPushRequestLine192=== RUN TestParsePathInfoJSON/Lix_format193=== PAUSE TestParsePathInfoJSON/Lix_format1942026/11/09 11:52:34 ERROR Upload failed error="bad path" count=21952026/11/09 11:52:34 ERROR Upload failed error=boom count=11962026/11/09 11:52:34 WARN Rate limiter enabled after throttle name=server-test rate=5197--- PASS: TestFileTokenEmpty (0.00s)1982026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:43501199=== CONT TestStreamPushBatchesUnderLoad200=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false201=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false202=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true2032026/11/09 11:52:34 ERROR Upload failed error=boom count=1204=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI205=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error206=== RUN TestPathInfoCACompatibility/new_structured_format_-_text207=== CONT TestDoWithRetry_FinalResponseBodyReadable208=== CONT TestUploadMultipart_PartsInParallel209=== RUN TestParsePathInfoJSON/empty_input210=== RUN TestRateLimiterFeedback/503_enables_limiter211=== CONT TestDumpPathMatchesNix212=== CONT TestDumpPathSingleFile213--- PASS: TestStreamPushGivesUpOnDeadServer (0.01s)214--- PASS: TestStreamPushStopsWhenCanceled (0.00s)215--- PASS: TestStreamPushReportsSkippedPaths (0.00s)2162026/11/09 11:52:34 WARN Rate limiter backed off name=server-test rate=52172026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:43501218=== PAUSE TestParsePathInfoJSON/empty_input219=== CONT TestEncodeNixBase32220=== RUN TestSetClientTLSErrors/missing_cert_file221=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512222=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error223=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text224=== CONT TestPartSizeForNAR225--- PASS: TestShellSplit (0.00s)226=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true227=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun2282026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:44235229--- PASS: TestScriptTokenScriptFails (0.00s)230--- PASS: TestShellSplitErrors (0.00s)231=== PAUSE TestRateLimiterFeedback/503_enables_limiter232=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter233=== CONT TestFilterOversizedClosures234=== RUN TestFilterOversizedClosures/no_limit_keeps_everything2352026/11/09 11:52:34 WARN Rate limiter enabled after throttle name=server-test rate=52362026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:402112372026/11/09 11:52:34 WARN Rate limiter backed off name=server-test rate=5238=== CONT TestUploadMultipart_ReturnsAfterDroppedBody239=== CONT TestDumpPathWriterError240=== RUN TestParsePathInfoJSON/whitespace_only2412026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:44235242=== PAUSE TestParsePathInfoJSON/whitespace_only243=== RUN TestEncodeNixBase32/test_string_hash244=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error245=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method246=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512247=== PAUSE TestSetClientTLSErrors/missing_cert_file248=== RUN TestPartSizeForNAR/zero_stays_at_minimum249--- PASS: TestDoServerRequestAttachesToken (0.02s)250=== RUN TestSetClientTLS/rejects_connection_without_client_cert251=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter252=== RUN TestSetClientTLSErrors/missing_key_file253=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert254=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA255--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)256--- PASS: TestClientSignaturesByStorePath (0.00s)257--- PASS: TestStreamPushReportsSignatures (0.01s)258--- PASS: TestStreamPushIsolatesFailures (0.01s)259--- PASS: TestFileTokenReadsAndCaches (0.01s)260--- PASS: TestScriptTokenEmptyToken (0.01s)261--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)262--- PASS: TestRegisterUploadedObject_OutlivesPush (0.01s)263--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)264--- PASS: TestScriptTokenBadJSON (0.01s)265--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.03s)266=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry267=== CONT TestCaseHackSuffix268 listing_test.go:25: case hack suffixes are only stripped where nix enables use-case-hack by default269--- SKIP: TestCaseHackSuffix (0.00s)2702026/11/09 11:52:34 INFO Garbage collection started271=== CONT TestConvertHashToNix32/SRI_format_to_Nix32272=== CONT TestRegisterUploadedObjectReusesConnections273=== CONT TestConvertHashToNix32/invalid_format274=== PAUSE TestEncodeNixBase32/test_string_hash275=== RUN TestEncodeNixBase32/empty_input276=== PAUSE TestEncodeNixBase32/empty_input277=== RUN TestParsePathInfoJSON/invalid_JSON278=== PAUSE TestParsePathInfoJSON/invalid_JSON279=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths280=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error281=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths282--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)283 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)284 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)285=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false286=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method287=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true288=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)289=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum290=== RUN TestPartSizeForNAR/small_stays_at_minimum291=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512292=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon293=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI294--- PASS: TestPathInfoHashCompatibility (0.04s)295 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)296 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)297 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)298 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)299=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica300=== CONT TestEncodeNixBase32/test_string_hash301=== PAUSE TestPartSizeForNAR/small_stays_at_minimum302=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum303=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum304=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts305=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts306=== RUN TestPartSizeForNAR/1_TiB307=== PAUSE TestPartSizeForNAR/1_TiB308=== CONT TestParsePathInfoJSON/Nix_format3092026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:44235310=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter311=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter312=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything313=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped314=== CONT TestParsePathInfoJSON/whitespace_only315=== CONT TestParsePathInfoJSON/empty_input316=== CONT TestPathInfoCACompatibility/null_ca_field317=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error318=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error319=== CONT TestGetStorePathHash/basename_without_hyphen_should_error320=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method3212026/11/09 11:52:34 INFO Garbage collection started322=== CONT TestPathInfoCACompatibility/new_structured_format_-_text323=== CONT TestPathInfoCACompatibility/old_string_format_-_text324=== PAUSE TestSetClientTLSErrors/missing_key_file325=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive326=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter327=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter328=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3292026/11/09 11:52:34 WARN Rate limiter enabled after throttle name=s3-test rate=5330=== RUN TestPartSizeForNAR/5_TiB_S3_max_object3312026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:36143332=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object3332026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:44235334=== CONT TestConvertHashToNix32/already_Nix32_format3352026/11/09 11:52:34 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=0336=== CONT TestEncodeNixBase32/empty_input337=== CONT TestGetStorePathHash/valid_store_path338--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.00s)339=== CONT TestParsePathInfoJSON/Lix_format340=== CONT TestParsePathInfoJSON/invalid_JSON341=== CONT TestRateLimiterFeedback/429_enables_limiter342=== RUN TestFilterOversizedClosures/all_closures_skipped343=== PAUSE TestFilterOversizedClosures/all_closures_skipped344=== CONT TestFilterOversizedClosures/no_limit_keeps_everything345=== RUN TestSetClientTLSErrors/missing_ca_file346=== PAUSE TestSetClientTLSErrors/missing_ca_file347=== RUN TestSetClientTLSErrors/invalid_ca_file348--- PASS: TestEncodeNixBase32 (0.03s)349 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)350 --- PASS: TestEncodeNixBase32/empty_input (0.00s)3512026/11/09 11:52:34 WARN Rate limiter enabled after throttle name=server-test rate=5352=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA3532026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:42643354=== CONT TestRateLimiterFeedback/503_enables_limiter3552026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:44235356=== RUN TestPartSizeForNAR/capped_at_5_GiB3572026/11/09 11:52:34 WARN Garbage collection finished on another replica. Its statistics are not available here358=== PAUSE TestPartSizeForNAR/capped_at_5_GiB359=== CONT TestFilterOversizedClosures/all_closures_skipped360=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3612026/11/09 11:52:34 WARN Rate limiter backed off name=server-test rate=5362=== PAUSE TestSetClientTLSErrors/invalid_ca_file3632026/11/09 11:52:34 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=50364--- PASS: TestStreamPushBatchesUnderLoad (0.00s)365 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)366 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)3672026/11/09 11:52:34 WARN Rate limiter enabled after throttle name=server-test rate=5368=== RUN TestSetClientTLS/preserves_debug_logging_transport3692026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:37299370=== CONT TestPartSizeForNAR/zero_stays_at_minimum3712026/11/09 11:52:34 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=2000372=== CONT TestPartSizeForNAR/capped_at_5_GiB373=== CONT TestPartSizeForNAR/5_TiB_S3_max_object374=== CONT TestPartSizeForNAR/1_TiB375=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts3762026/11/09 11:52:34 WARN Rate limiter backed off name=server-test rate=5377=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum378=== CONT TestPartSizeForNAR/small_stays_at_minimum379=== CONT TestSetClientTLSErrors/missing_cert_file380=== CONT TestSetClientTLSErrors/invalid_ca_file3812026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:44235382=== CONT TestSetClientTLSErrors/missing_ca_file383=== CONT TestSetClientTLSErrors/missing_key_file384--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.03s)385=== PAUSE TestSetClientTLS/preserves_debug_logging_transport386=== CONT TestSetClientTLS/rejects_connection_without_client_cert387--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.00s)3882026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:442353892026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:44235390--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.00s)391=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA392=== CONT TestSetClientTLS/preserves_debug_logging_transport393--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)394--- PASS: TestPathInfoCACompatibility (0.04s)395 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)396 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)397 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)398 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)399 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)400--- PASS: TestConvertHashToNix32 (0.00s)401 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)402 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)403 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)4042026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:44235405--- PASS: TestParsePathInfoJSON (0.04s)406 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)407 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)408 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)409 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)410 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)411--- PASS: TestGetStorePathHash (0.05s)412 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)413 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)414 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)415 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)416--- PASS: TestPartSizeForNAR (0.04s)417 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)418 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)419 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)420 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)421 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)422 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)423 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)424--- PASS: TestFilterOversizedClosures (0.03s)425 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)426 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)427 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)428--- PASS: TestRateLimiterFeedback (0.04s)429 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)430 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)431 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)432 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)433--- PASS: TestSetClientTLSErrors (0.05s)434 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)435 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)436 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)437 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)438--- PASS: TestStreamPushRequestLine (0.05s)4392026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:442354402026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:442354412026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:442354422026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:442354432026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:442354442026/11/09 11:52:34 http: TLS handshake error from 127.0.0.1:35020: remote error: tls: bad certificate4452026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:44235446--- PASS: TestSetClientTLS (0.06s)447 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)448 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)449 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)4502026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:442354512026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:442354522026/11/09 11:52:34 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:44235453--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.08s)454--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)455--- PASS: TestDumpPathSingleFile (0.06s)456--- PASS: TestDumpPathWriterError (0.04s)4572026/11/09 11:52:34 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:41873/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:41873/api/uploads/complete4582026/11/09 11:52:34 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:41873/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:41873/api/uploads/complete4592026/11/09 11:52:34 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4602026/11/09 11:52:34 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:41873/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:41873/api/uploads/complete4612026/11/09 11:52:34 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4622026/11/09 11:52:34 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"463--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (0.10s)464--- PASS: TestDumpPathMatchesNix (0.11s)465--- PASS: TestUploadMultipart_PartsInParallel (0.66s)466--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)467PASS468Running server tests...469The files belonging to this database system will be owned by user "nixbld".470This user must also own the server process.471472The database cluster will be initialized with locale "C".473The default database encoding has accordingly been set to "SQL_ASCII".474The default text search configuration will be set to "english".475476Data page checksums are enabled.477478creating directory /build/postgres91289707/data ... ok479creating subdirectories ... ok480selecting dynamic shared memory implementation ... posix481selecting default "max_connections" ... 100482selecting default "shared_buffers" ... 128MB483selecting default time zone ... UTC484creating configuration files ... ok485running bootstrap script ... ok486performing post-bootstrap initialization ... ok487syncing data to disk ... ok488489initdb: warning: enabling "trust" authentication for local connections490initdb: 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.491492Success. You can now start the database server using:493494 pg_ctl -D /build/postgres91289707/data -l logfile start495496/build/postgres91289707:5432 - no response4972026-11-09 11:52:36.547 UTC [111] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit4982026-11-09 11:52:36.548 UTC [111] LOG: listening on Unix socket "/build/postgres91289707/.s.PGSQL.5432"4992026-11-09 11:52:36.552 UTC [118] LOG: database system was shut down at 2026-11-09 11:52:36 UTC5002026-11-09 11:52:36.556 UTC [111] LOG: database system is ready to accept connections501/build/postgres91289707:5432 - accepting connections502=== RUN TestAbortSucceeded503=== PAUSE TestAbortSucceeded504=== RUN TestService_AuthMiddleware505=== PAUSE TestService_AuthMiddleware506=== RUN TestService_AuthMiddleware_MTLSProxyHeader507=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader508=== RUN TestService_AuthMiddleware_MTLSBoundSubjects509=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects510=== RUN TestService_ReadAuthMiddleware511=== PAUSE TestService_ReadAuthMiddleware512=== RUN TestService_AuthMiddleware_OIDC513=== PAUSE TestService_AuthMiddleware_OIDC514=== RUN TestService_RequireScope_OIDC515=== PAUSE TestService_RequireScope_OIDC516=== RUN TestService_ReadScope_PublicByDefault517=== PAUSE TestService_ReadScope_PublicByDefault518=== RUN TestCacheConfigHandler519=== PAUSE TestCacheConfigHandler520=== RUN TestCacheStatsHandler521=== PAUSE TestCacheStatsHandler522=== RUN TestClientCADerivations523=== PAUSE TestClientCADerivations524=== RUN TestClientErrorHandling525=== PAUSE TestClientErrorHandling526=== RUN TestClientIntegration527=== PAUSE TestClientIntegration528=== RUN TestClientMultipleUploads529=== PAUSE TestClientMultipleUploads530=== RUN TestClientWithDependencies531=== PAUSE TestClientWithDependencies532=== RUN TestClientSharedPathCommittedMidPush533=== PAUSE TestClientSharedPathCommittedMidPush534=== RUN TestPinProtectsFromGC535=== PAUSE TestPinProtectsFromGC536=== RUN TestClientPushesUseOnePush537=== PAUSE TestClientPushesUseOnePush538=== RUN TestClientFallsBackToClosures539=== PAUSE TestClientFallsBackToClosures540=== RUN TestDeleteClosuresRacingPins541=== PAUSE TestDeleteClosuresRacingPins542=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock543=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock544=== RUN TestRetryableCompletionError545=== PAUSE TestRetryableCompletionError546=== RUN TestCompleteMultipartUploadRetriesTransientFailure547=== PAUSE TestCompleteMultipartUploadRetriesTransientFailure548=== RUN TestResolveDBConnectionString549=== PAUSE TestResolveDBConnectionString550=== RUN TestConnectWaitsForAPeerMigration551=== PAUSE TestConnectWaitsForAPeerMigration552=== RUN TestLeadElectsOneAndHandsOver553=== PAUSE TestLeadElectsOneAndHandsOver554=== RUN TestLeadIncumbentWinsAfterRestart5552026/11/09 11:52:37 INFO lead: acquired remote=192.0.2.1:12345562026/11/09 11:52:37 INFO lead: released remote=192.0.2.1:12345572026/11/09 11:52:37 INFO lead: acquired remote=192.0.2.1:12345582026/11/09 11:52:39 INFO lead: released remote=192.0.2.1:1234559--- PASS: TestLeadIncumbentWinsAfterRestart (1.94s)560=== RUN TestLeadIncumbentAnnouncesAtOnce561=== PAUSE TestLeadIncumbentAnnouncesAtOnce562=== RUN TestLeadEndsOnShutdown563=== PAUSE TestLeadEndsOnShutdown564=== RUN TestLeadEndsWhenItsConnectionHangs5652026/11/09 11:52:39 INFO lead: acquired remote=192.0.2.1:12345662026-11-09 11:52:40.619 UTC [560] FATAL: terminating connection due to administrator command5672026/11/09 11:52:40 INFO lead: acquired remote=192.0.2.1:12345682026/11/09 11:52:41 WARN lead: lock connection lost error="timeout: context deadline exceeded"5692026/11/09 11:52:41 INFO lead: released remote=192.0.2.1:12345702026/11/09 11:52:42 INFO lead: released remote=192.0.2.1:1234571--- PASS: TestLeadEndsWhenItsConnectionHangs (2.92s)572=== RUN TestGCAdvisoryLockBlocksConcurrentRun573=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun574=== RUN TestGCBugBareHashReferences575=== PAUSE TestGCBugBareHashReferences576=== RUN TestGCMetrics577=== PAUSE TestGCMetrics578=== RUN TestPushDedupSurvivesConcurrentGC579=== PAUSE TestPushDedupSurvivesConcurrentGC580=== RUN TestDeduplicatedObjectsRecordedAsPending581=== PAUSE TestDeduplicatedObjectsRecordedAsPending582=== RUN TestGCSweepSkipsPendingObjects583=== PAUSE TestGCSweepSkipsPendingObjects584=== RUN TestTombstonedObjectOfferedWithoutWaiting585=== PAUSE TestTombstonedObjectOfferedWithoutWaiting586=== RUN TestGCSweepDeliversEachKeyOnce587=== PAUSE TestGCSweepDeliversEachKeyOnce588=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection589=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection590=== RUN TestForceGCDuringPushOffersSweptObject591=== PAUSE TestForceGCDuringPushOffersSweptObject592=== RUN TestFailedS3DeleteKeepsTombstone593=== PAUSE TestFailedS3DeleteKeepsTombstone594=== RUN TestSweepSkipsRowsLockedByPush595=== PAUSE TestSweepSkipsRowsLockedByPush596=== RUN TestRegisterCompletedObjectNeedsPendingRow597=== PAUSE TestRegisterCompletedObjectNeedsPendingRow598=== RUN TestGetExistingObjectsLocksRows599=== PAUSE TestGetExistingObjectsLocksRows600=== RUN TestSweepRechecksPendingAfterLocking601=== PAUSE TestSweepRechecksPendingAfterLocking602=== RUN TestPushWaitsForSweepHoldingRow603=== PAUSE TestPushWaitsForSweepHoldingRow604=== RUN TestCommitRacingPendingCleanupKeepsObjects605=== PAUSE TestCommitRacingPendingCleanupKeepsObjects606=== RUN TestGCEndsOnShutdown607=== PAUSE TestGCEndsOnShutdown608=== RUN TestGCTaskStore_StartNew609=== PAUSE TestGCTaskStore_StartNew610=== RUN TestGCTaskStore_DeduplicateSameParams611=== PAUSE TestGCTaskStore_DeduplicateSameParams612=== RUN TestGCTaskStore_ConflictDifferentParams613=== PAUSE TestGCTaskStore_ConflictDifferentParams614=== RUN TestGCTaskStore_GetEmpty615=== PAUSE TestGCTaskStore_GetEmpty616=== RUN TestGCTaskStore_GetReturnsLatest617=== PAUSE TestGCTaskStore_GetReturnsLatest618=== RUN TestGCTaskStore_CompletedAllowsNewTask619=== PAUSE TestGCTaskStore_CompletedAllowsNewTask620=== RUN TestGCTaskStore_PhaseUpdates621=== PAUSE TestGCTaskStore_PhaseUpdates622=== RUN TestGCTaskStore_Fail623=== PAUSE TestGCTaskStore_Fail624=== RUN TestGracefulShutdownDrainsInflight625=== PAUSE TestGracefulShutdownDrainsInflight626=== RUN TestService_healthCheckHandler627=== PAUSE TestService_healthCheckHandler628=== RUN TestService_readinessHandler629=== PAUSE TestService_readinessHandler630=== RUN TestGenerateLandingPage631=== PAUSE TestGenerateLandingPage632=== RUN TestEnsureAbortUploadsRule633=== PAUSE TestEnsureAbortUploadsRule634=== RUN TestCacheConfigHandlerMaxNarSize635=== PAUSE TestCacheConfigHandlerMaxNarSize636=== RUN TestCreatePendingClosureRejectsOversizedNAR637=== PAUSE TestCreatePendingClosureRejectsOversizedNAR638=== RUN TestNARDeduplicationMetadataUploadBug639=== PAUSE TestNARDeduplicationMetadataUploadBug640=== RUN TestMetricsInventory641=== PAUSE TestMetricsInventory642=== RUN TestMetricsCommit643=== PAUSE TestMetricsCommit644=== RUN TestService_NativeMTLS645=== PAUSE TestService_NativeMTLS646=== RUN TestServerTLSConfig647=== PAUSE TestServerTLSConfig648=== RUN TestMultipartCleanup649=== PAUSE TestMultipartCleanup650=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded651=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded652=== RUN TestPendingCleanupUsesOneCutoff653=== PAUSE TestPendingCleanupUsesOneCutoff654=== RUN TestObjectStatsTrigger655=== PAUSE TestObjectStatsTrigger656=== RUN TestObjectStatsUpdatedOncePerCommit657=== PAUSE TestObjectStatsUpdatedOncePerCommit658=== RUN TestOrphanedObjectsGC659=== PAUSE TestOrphanedObjectsGC660=== RUN TestOrphanedObjectsGCStressTest661=== PAUSE TestOrphanedObjectsGCStressTest662=== RUN TestCreatePin_ReservedPins663=== PAUSE TestCreatePin_ReservedPins664=== RUN TestPresentReportsOnlyClosureRoots665=== PAUSE TestPresentReportsOnlyClosureRoots666=== RUN TestPresentRefreshesOnlyStaleClosures667=== PAUSE TestPresentRefreshesOnlyStaleClosures668=== RUN TestPresentNotReportedWhileGCDeletesClosure669=== PAUSE TestPresentNotReportedWhileGCDeletesClosure670=== RUN TestParseSingleRange671=== PAUSE TestParseSingleRange672=== RUN TestProxyHeadersOnlyTrustedOnSocket6732026/11/09 11:52:42 INFO Starting HTTP server address=127.0.0.1:397576742026/11/09 11:52:42 INFO Starting HTTP server address=proxy.sock6752026/11/09 11:52:42 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6762026/11/09 11:52:42 INFO Shutdown signal received, draining in-flight requests timeout=10s677--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.11s)678=== RUN TestIsValidCachePath679=== PAUSE TestIsValidCachePath680=== RUN TestReadProxyNarinfo681=== PAUSE TestReadProxyNarinfo682=== RUN TestReadProxyNarinfoAlreadyDecompressed683=== PAUSE TestReadProxyNarinfoAlreadyDecompressed684=== RUN TestReadProxyContentNegotiation685=== PAUSE TestReadProxyContentNegotiation686=== RUN TestReadProxyNarStreaming687=== PAUSE TestReadProxyNarStreaming688=== RUN TestReadProxy404689=== PAUSE TestReadProxy404690=== RUN TestReadProxyInvalidPath691=== PAUSE TestReadProxyInvalidPath692=== RUN TestReadProxyHead693=== PAUSE TestReadProxyHead694=== RUN TestReadProxyOutlastsServerWriteTimeout695=== PAUSE TestReadProxyOutlastsServerWriteTimeout696=== RUN TestReadProxyConditionalGet697=== PAUSE TestReadProxyConditionalGet698=== RUN TestReadProxyRootRedirectsToIndexHTML699=== PAUSE TestReadProxyRootRedirectsToIndexHTML700=== RUN TestReadProxyDisabled701=== PAUSE TestReadProxyDisabled702=== RUN TestReadRedirectNar703=== PAUSE TestReadRedirectNar704=== RUN TestReadRedirectKeepsNarinfoProxied705=== PAUSE TestReadRedirectKeepsNarinfoProxied706=== RUN TestReadProxyRangeRequest707=== PAUSE TestReadProxyRangeRequest708=== RUN TestReadRedirectUsesPublicS3URL709=== PAUSE TestReadRedirectUsesPublicS3URL710=== RUN TestPush_OverlappingRootsStoreOneRowPerKey711=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey712=== RUN TestPush_CompleteCommitsEveryRoot713=== PAUSE TestPush_CompleteCommitsEveryRoot714=== RUN TestPush_RepeatedRootCommitsOnce715=== PAUSE TestPush_RepeatedRootCommitsOnce716=== RUN TestPush_CompleteWaitsForCleanupOfThePush717=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush718=== RUN TestPush_RootsAreLockedInByteOrder719=== PAUSE TestPush_RootsAreLockedInByteOrder720=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit721=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit722=== RUN TestPush_RejectsBadRequests723=== PAUSE TestPush_RejectsBadRequests724=== RUN TestPush_SignsNarinfosOfItsPendingObjects725=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects726=== RUN TestSharedNarBothUploadsComplete727=== PAUSE TestSharedNarBothUploadsComplete728=== RUN TestCompleteMultipartUpload_ErrorButObjectExists729=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists730=== RUN TestCompletedNarNotReofferedAcrossClosures731=== PAUSE TestCompletedNarNotReofferedAcrossClosures732=== RUN TestPresignedUploadRegisteredBeforeCommit733=== PAUSE TestPresignedUploadRegisteredBeforeCommit734=== RUN TestService_Rustfstest735=== PAUSE TestService_Rustfstest736=== RUN TestParseSize737=== PAUSE TestParseSize738=== RUN TestSkippedUploadsHandler739=== PAUSE TestSkippedUploadsHandler740=== RUN TestSystemdListenerNotActivated741--- PASS: TestSystemdListenerNotActivated (0.00s)742=== RUN TestWatchdogBeatsWhenHealthy743--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)744=== RUN TestWatchdogSkipsWhenUnhealthy7452026/11/09 11:52:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7462026/11/09 11:52:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7472026/11/09 11:52:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7482026/11/09 11:52:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7492026/11/09 11:52:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7502026/11/09 11:52:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7512026/11/09 11:52:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7522026/11/09 11:52:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7532026/11/09 11:52:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7542026/11/09 11:52:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"755--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)756=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle757=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle758=== RUN TestProxyWriteTimeout759=== PAUSE TestProxyWriteTimeout760=== RUN TestPendingClosureWriteTimeout761=== PAUSE TestPendingClosureWriteTimeout762=== RUN TestIsValidUploadKey763=== PAUSE TestIsValidUploadKey764=== RUN TestUploadHandlersRejectInvalidKeys765=== PAUSE TestUploadHandlersRejectInvalidKeys766=== RUN TestUploadHandlersRejectOversizedBody767=== PAUSE TestUploadHandlersRejectOversizedBody768=== RUN TestService_cleanupPendingClosuresHandler769=== PAUSE TestService_cleanupPendingClosuresHandler770=== RUN TestService_createPendingClosureHandler771=== PAUSE TestService_createPendingClosureHandler772=== RUN TestService_verifyS3Integrity773=== PAUSE TestService_verifyS3Integrity774=== RUN TestService_verifyS3ReuploadsStaleNarinfo775=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo776=== RUN TestCompleteMultipartUnregistered777=== PAUSE TestCompleteMultipartUnregistered778=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT779=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT780=== CONT TestAbortSucceeded781=== CONT TestIsValidUploadKey782--- PASS: TestAbortSucceeded (0.00s)783=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT784=== CONT TestCompleteMultipartUnregistered785=== CONT TestService_verifyS3ReuploadsStaleNarinfo786=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed787=== CONT TestService_verifyS3Integrity788=== CONT TestService_createPendingClosureHandler789=== CONT TestService_cleanupPendingClosuresHandler790=== CONT TestUploadHandlersRejectOversizedBody791=== CONT TestUploadHandlersRejectInvalidKeys792=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded793=== CONT TestMultipartCleanup794=== CONT TestServerTLSConfig795=== RUN TestServerTLSConfig/no_client_CA796=== CONT TestService_NativeMTLS797=== CONT TestMetricsCommit798=== CONT TestMetricsInventory799=== CONT TestNARDeduplicationMetadataUploadBug800=== CONT TestCreatePendingClosureRejectsOversizedNAR801=== CONT TestCacheConfigHandlerMaxNarSize802=== CONT TestEnsureAbortUploadsRule8032026/11/09 11:52:42 INFO Received uploads request method=POST path=/api/pending_closures804--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)805=== CONT TestGCTaskStore_PhaseUpdates806=== CONT TestGenerateLandingPage807=== CONT TestService_readinessHandler808=== CONT TestService_healthCheckHandler809=== CONT TestGracefulShutdownDrainsInflight810=== CONT TestGCTaskStore_Fail811=== CONT TestGCTaskStore_GetEmpty812=== CONT TestGCTaskStore_ConflictDifferentParams813=== CONT TestGCTaskStore_DeduplicateSameParams814=== CONT TestGCTaskStore_StartNew815=== RUN TestIsValidUploadKey/narinfo816=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed817=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info818=== PAUSE TestServerTLSConfig/no_client_CA819--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)820--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)821=== CONT TestGCTaskStore_CompletedAllowsNewTask822=== CONT TestGCTaskStore_GetReturnsLatest823=== CONT TestGCEndsOnShutdown824=== CONT TestRetryableCompletionError825=== CONT TestCompleteMultipartUploadRetriesTransientFailure826=== RUN TestServerTLSConfig/missing_CA_file827--- PASS: TestGCTaskStore_Fail (0.00s)828--- PASS: TestGCTaskStore_GetEmpty (0.00s)829--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)830=== RUN TestGCEndsOnShutdown/before_the_run831=== RUN TestRetryableCompletionError/context_canceled832=== PAUSE TestGCEndsOnShutdown/before_the_run833--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)834=== PAUSE TestRetryableCompletionError/context_canceled835=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete836=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete837--- PASS: TestGCTaskStore_StartNew (0.00s)838--- PASS: TestGenerateLandingPage (0.00s)839=== RUN TestRetryableCompletionError/nil840=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark841--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)842--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)843=== PAUSE TestIsValidUploadKey/narinfo8442026/11/09 11:52:42 INFO Starting HTTP server address=127.0.0.1:45767845=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark8462026/11/09 11:52:42 INFO Shutdown signal received, draining in-flight requests timeout=10s847=== RUN TestIsValidUploadKey/nar_zst848=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info849=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal850=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal851=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key852=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock853=== PAUSE TestServerTLSConfig/missing_CA_file854=== PAUSE TestRetryableCompletionError/nil855=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed856=== CONT TestDeleteClosuresRacingPins857=== RUN TestRetryableCompletionError/degraded_quorum858=== PAUSE TestIsValidUploadKey/nar_zst859=== RUN TestIsValidUploadKey/nar_xz860=== PAUSE TestIsValidUploadKey/nar_xz861=== RUN TestIsValidUploadKey/nar_plain862=== PAUSE TestIsValidUploadKey/nar_plain863=== RUN TestIsValidUploadKey/listing864=== PAUSE TestIsValidUploadKey/listing865=== RUN TestIsValidUploadKey/build_log866=== PAUSE TestIsValidUploadKey/build_log867=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key868=== RUN TestServerTLSConfig/not_a_PEM_file869=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key870=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key871=== CONT TestClientFallsBackToClosures872=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed873=== PAUSE TestRetryableCompletionError/degraded_quorum874=== RUN TestRetryableCompletionError/bad_gateway875=== PAUSE TestRetryableCompletionError/bad_gateway876=== RUN TestRetryableCompletionError/no_such_upload877=== PAUSE TestRetryableCompletionError/no_such_upload878=== RUN TestRetryableCompletionError/invalid_part879=== PAUSE TestRetryableCompletionError/invalid_part880=== RUN TestIsValidUploadKey/build_log_home-manager_file881=== PAUSE TestIsValidUploadKey/build_log_home-manager_file882=== PAUSE TestServerTLSConfig/not_a_PEM_file883=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost884=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost885=== RUN TestRetryableCompletionError/throttled886=== PAUSE TestRetryableCompletionError/throttled887=== RUN TestIsValidUploadKey/build_log_plus_in_name888=== PAUSE TestIsValidUploadKey/build_log_plus_in_name889=== RUN TestIsValidUploadKey/build_log_question_mark890=== PAUSE TestIsValidUploadKey/build_log_question_mark891=== RUN TestIsValidUploadKey/build_log_equals892=== PAUSE TestIsValidUploadKey/build_log_equals893=== RUN TestIsValidUploadKey/realisation894=== PAUSE TestIsValidUploadKey/realisation895=== CONT TestClientPushesUseOnePush896=== RUN TestIsValidUploadKey/realisation_plus_in_output897=== PAUSE TestIsValidUploadKey/realisation_plus_in_output898=== RUN TestIsValidUploadKey/nix-cache-info899=== PAUSE TestIsValidUploadKey/nix-cache-info900=== RUN TestIsValidUploadKey/index.html901=== PAUSE TestIsValidUploadKey/index.html902=== RUN TestIsValidUploadKey/narinfo_key,_nar_type903=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type904=== RUN TestIsValidUploadKey/nar_key,_narinfo_type905=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed906=== RUN TestRetryableCompletionError/deadline_exceeded907=== PAUSE TestRetryableCompletionError/deadline_exceeded908=== RUN TestRetryableCompletionError/transport_failure909=== PAUSE TestRetryableCompletionError/transport_failure910=== RUN TestRetryableCompletionError/access_denied911=== PAUSE TestRetryableCompletionError/access_denied912=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type913=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed914=== CONT TestPinProtectsFromGC915=== RUN TestIsValidUploadKey/listing_key,_narinfo_type916=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type917=== RUN TestIsValidUploadKey/traversal918=== PAUSE TestIsValidUploadKey/traversal919=== RUN TestIsValidUploadKey/traversal_nar920=== PAUSE TestIsValidUploadKey/traversal_nar921=== RUN TestIsValidUploadKey/absolute922=== PAUSE TestIsValidUploadKey/absolute923=== RUN TestIsValidUploadKey/empty_key924=== PAUSE TestIsValidUploadKey/empty_key925=== RUN TestIsValidUploadKey/unknown_type926=== PAUSE TestIsValidUploadKey/unknown_type927=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed928=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed929=== CONT TestClientSharedPathCommittedMidPush930=== CONT TestClientWithDependencies931--- PASS: TestGracefulShutdownDrainsInflight (0.15s)932=== CONT TestClientMultipleUploads933=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure934=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure935=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart936=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart937=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts938=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts939=== CONT TestClientIntegration9402026/11/09 11:52:42 INFO Received uploads request method=POST path=/api/pending_closures9412026/11/09 11:52:42 INFO Received uploads request method=POST path=/api/pending_closures942--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.45s)943=== CONT TestClientErrorHandling944=== RUN TestClientErrorHandling/InvalidStorePath945=== PAUSE TestClientErrorHandling/InvalidStorePath946=== RUN TestClientErrorHandling/InvalidAuthToken947=== PAUSE TestClientErrorHandling/InvalidAuthToken948=== RUN TestClientErrorHandling/ServerNotAvailable949=== PAUSE TestClientErrorHandling/ServerNotAvailable950=== CONT TestClientCADerivations9512026/11/09 11:52:42 INFO Received uploads request method=POST path=/api/pending_closures9522026/11/09 11:52:42 INFO Received uploads request method=POST path=/api/pending_closures9532026/11/09 11:52:42 INFO Received uploads request method=POST path=/api/pending_closures9542026/11/09 11:52:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9552026/11/09 11:52:42 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst956--- PASS: TestCompleteMultipartUnregistered (0.48s)957=== CONT TestCacheStatsHandler958--- PASS: TestMetricsInventory (0.52s)959=== CONT TestCacheConfigHandler960=== RUN TestCacheConfigHandler/full_config,_no_issuer961=== PAUSE TestCacheConfigHandler/full_config,_no_issuer962=== RUN TestCacheConfigHandler/no_cache_url_configured963=== PAUSE TestCacheConfigHandler/no_cache_url_configured964=== RUN TestCacheConfigHandler/no_signing_keys965=== PAUSE TestCacheConfigHandler/no_signing_keys966=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator967=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator968=== CONT TestService_ReadScope_PublicByDefault9692026/11/09 11:52:42 INFO Received uploads request method=POST path=/api/pending_closures9702026/11/09 11:52:42 INFO Installed lifecycle rule aborting incomplete NAR uploads bucket=bucket10 days=2971--- PASS: TestEnsureAbortUploadsRule (0.56s)972=== CONT TestService_RequireScope_OIDC9732026/11/09 11:52:42 INFO Received cleanup request method=DELETE path=/api/pending_closures9742026/11/09 11:52:42 INFO Aborted multipart uploads count=0 kept=09752026/11/09 11:52:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45345/oidc9762026/11/09 11:52:42 INFO Received uploads request method=POST path=/api/pending_closures9772026/11/09 11:52:42 INFO Received cleanup request method=DELETE path=/api/pending_closures9782026/11/09 11:52:42 INFO Aborted multipart uploads count=1 kept=09792026/11/09 11:52:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9802026-11-09 11:52:42.955 UTC [640] ERROR: Closure does not exist: id=19812026-11-09 11:52:42.955 UTC [640] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9822026-11-09 11:52:42.955 UTC [640] STATEMENT: -- name: CommitPendingClosure :one983 SELECT commit_pending_closure($1::bigint)::bigint984 985--- PASS: TestService_cleanupPendingClosuresHandler (0.60s)986=== CONT TestService_AuthMiddleware_OIDC9872026/11/09 11:52:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39009/oidc9882026/11/09 11:52:42 INFO Received push request method=POST path=/api/pushes9892026/11/09 11:52:43 INFO Received cleanup request method=DELETE path=/api/pending_closures9902026/11/09 11:52:43 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket9/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""9912026/11/09 11:52:43 INFO Aborted multipart uploads count=0 kept=19922026/11/09 11:52:43 INFO Received complete push request method=POST path=/api/pushes/1/complete9932026/11/09 11:52:43 INFO Received uploads request method=POST path=/api/pending_closures994=== NAME TestNARDeduplicationMetadataUploadBug995 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug2065772017/001/store/ap5albm9dmmhqckranw5vicad8553ap3-file1.txt9962026/11/09 11:52:43 INFO Received cleanup request method=DELETE path=/api/pending_closures9972026/11/09 11:52:43 INFO Completed push id=1 objects=4 duration=7.383202ms9982026/11/09 11:52:43 INFO Aborted multipart uploads count=1 kept=09992026/11/09 11:52:43 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10002026/11/09 11:52:43 INFO Completed upload id=2 objects=2 duration=1.408201ms1001--- PASS: TestMultipartCleanup (0.66s)1002=== CONT TestService_ReadAuthMiddleware1003--- PASS: TestMetricsCommit (0.66s)1004=== CONT TestService_AuthMiddleware_MTLSBoundSubjects10052026/11/09 11:52:43 WARN mTLS auth: subject not in bound subjects subject="CN=reader"10062026/11/09 11:52:43 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1007--- PASS: TestService_NativeMTLS (0.67s)1008=== CONT TestResolveDBConnectionString1009=== RUN TestResolveDBConnectionString/flag_wins1010=== PAUSE TestResolveDBConnectionString/flag_wins1011=== RUN TestResolveDBConnectionString/file_when_flag_empty1012=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1013=== RUN TestResolveDBConnectionString/missing_file_is_an_error1014=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1015=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1016=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1017=== RUN TestResolveDBConnectionString/nothing_configured1018=== PAUSE TestResolveDBConnectionString/nothing_configured1019=== CONT TestService_AuthMiddleware_MTLSProxyHeader10202026/11/09 11:52:43 INFO Received uploads request method=POST path=/api/pending_closures1021--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.72s)1022=== CONT TestCommitRacingPendingCleanupKeepsObjects10232026/11/09 11:52:43 WARN readiness check failed error="closed pool"1024--- PASS: TestService_readinessHandler (0.72s)1025=== CONT TestService_AuthMiddleware10262026/11/09 11:52:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10272026/11/09 11:52:43 INFO Received push request method=POST path=/api/pushes10282026/11/09 11:52:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10292026/11/09 11:52:43 INFO Uploading ap5albm9dmmhqckranw5vicad8553ap3-file1.txt (160B)10302026/11/09 11:52:43 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"10312026/11/09 11:52:43 WARN Failed to register uploaded object key=ap5albm9dmmhqckranw5vicad8553ap3.ls error="server returned 404: 404 page not found\n"10322026/11/09 11:52:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10332026/11/09 11:52:43 INFO Signed narinfos id=1 count=110342026/11/09 11:52:43 INFO Uploading 1 narinfos10352026/11/09 11:52:43 WARN Failed to register uploaded object key=ap5albm9dmmhqckranw5vicad8553ap3.narinfo error="server returned 404: 404 page not found\n"10362026/11/09 11:52:43 INFO Received complete push request method=POST path=/api/pushes/1/complete10372026/11/09 11:52:43 INFO Completed push id=1 objects=3 duration=11.206793ms10382026/11/09 11:52:43 INFO Upload complete. (82ms)1039=== NAME TestNARDeduplicationMetadataUploadBug1040 metadata_upload_test.go:54: Retrieved narinfo from S3:1041 StorePath: /build/TestNARDeduplicationMetadataUploadBug2065772017/001/store/ap5albm9dmmhqckranw5vicad8553ap3-file1.txt1042 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1043 Compression: zstd1044 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1045 NarSize: 1601046 References: 1047 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1048 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1049 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1050 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}10512026/11/09 11:52:43 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccc0100000000000000000000.nar.zst upload_id=MmMwYmJkYzQtMDU4YS00YzQ3LWFmZTItYjU3ZDNkOWY5NjAzLjI0M2ZlZDM3LTNkMmUtNDg4Yi1iZmViLTE2YTY1MWIzNjA4Y3gxNzk0MjI1MTYzMDE0MzAxMDk5 parts=21052--- PASS: TestCompleteMultipartUploadRetriesTransientFailure (0.80s)1053=== CONT TestPushWaitsForSweepHoldingRow1054=== NAME TestNARDeduplicationMetadataUploadBug1055 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug2065772017/001/store/9vzd0dv0srlrbs0nvdk16mpdqv9i4s64-file2.txt10562026/11/09 11:52:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1057=== NAME TestPinProtectsFromGC1058 client_integration_test.go:778: Pinned store path: /build/TestPinProtectsFromGC3549268432/001/store/jgkd36a0pkk799klvn3cdgwzk3rvfmn4-pinned-file.txt1059 client_integration_test.go:779: Unpinned store path: /build/TestPinProtectsFromGC3549268432/001/store/c4wpb0j8671nrkia6zxflad8648myj4w-unpinned-file.txt10602026/11/09 11:52:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1061--- PASS: TestService_healthCheckHandler (0.86s)1062=== CONT TestSweepRechecksPendingAfterLocking10632026/11/09 11:52:43 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MmMwYmJkYzQtMDU4YS00YzQ3LWFmZTItYjU3ZDNkOWY5NjAzLjUxZDEzMDM4LTQwNGQtNDI1MC04OTU4LWY1NjYxYzhjYjgwYXgxNzk0MjI1MTYyNzgyOTExOTAx parts=1010642026/11/09 11:52:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10652026/11/09 11:52:43 INFO Completed upload id=1 objects=2 duration=4.581822ms10662026/11/09 11:52:43 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MmMwYmJkYzQtMDU4YS00YzQ3LWFmZTItYjU3ZDNkOWY5NjAzLjcyM2VjMmE1LWVkYmItNDQyMy1iNDE4LThkZDY1OGI5OTA1NngxNzk0MjI1MTYyODI1MDc1MTQz parts=1010672026/11/09 11:52:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10682026/11/09 11:52:43 INFO Received uploads request method=POST path=/api/pending_closures10692026/11/09 11:52:43 INFO Completed upload id=1 objects=2 duration=17.192735ms10702026/11/09 11:52:43 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010712026/11/09 11:52:43 INFO Received uploads request method=POST path=/api/pending_closures10722026/11/09 11:52:43 INFO Received uploads request method=POST path=/api/pending_closures10732026/11/09 11:52:43 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10742026/11/09 11:52:43 WARN Found objects in DB but missing from S3, will re-upload count=11075--- PASS: TestService_verifyS3Integrity (0.90s)1076=== CONT TestReadRedirectNar10772026/11/09 11:52:43 INFO Starting cleanup of old closures method=DELETE path=/api/closures10782026/11/09 11:52:43 INFO Received push request method=POST path=/api/pushes10792026/11/09 11:52:43 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)10802026/11/09 11:52:43 INFO Aborted multipart uploads count=0 kept=010812026/11/09 11:52:43 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign10822026/11/09 11:52:43 WARN Failed to register uploaded object key=9vzd0dv0srlrbs0nvdk16mpdqv9i4s64.ls error="server returned 404: 404 page not found\n"10832026/11/09 11:52:43 INFO Signed narinfos id=2 count=110842026/11/09 11:52:43 INFO Uploading 1 narinfos10852026/11/09 11:52:43 INFO Received push request method=POST path=/api/pushes10862026/11/09 11:52:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10872026/11/09 11:52:43 INFO Uploading jgkd36a0pkk799klvn3cdgwzk3rvfmn4-pinned-file.txt (128B)10882026/11/09 11:52:43 INFO Received complete push request method=POST path=/api/pushes/2/complete10892026/11/09 11:52:43 WARN Failed to register uploaded object key=9vzd0dv0srlrbs0nvdk16mpdqv9i4s64.narinfo error="server returned 404: 404 page not found\n"10902026/11/09 11:52:43 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=010912026/11/09 11:52:43 INFO Completed push id=2 objects=3 duration=1.812511ms10922026/11/09 11:52:43 INFO Upload complete. (52ms)1093=== NAME TestNARDeduplicationMetadataUploadBug1094 metadata_upload_test.go:76: Retrieved narinfo from S3:1095 StorePath: /build/TestNARDeduplicationMetadataUploadBug2065772017/001/store/9vzd0dv0srlrbs0nvdk16mpdqv9i4s64-file2.txt1096 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1097 Compression: zstd1098 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1099 NarSize: 1601100 References: 1101 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf11022026/11/09 11:52:43 INFO Vacuumed table table=pending_closures11032026/11/09 11:52:43 WARN Failed to register uploaded object key=jgkd36a0pkk799klvn3cdgwzk3rvfmn4.ls error="server returned 404: 404 page not found\n"1104 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1105 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1106 {"version":1,"root":{"type":"regular","size":44}}11072026/11/09 11:52:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11082026/11/09 11:52:43 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"11092026/11/09 11:52:43 INFO Signed narinfos id=1 count=111102026/11/09 11:52:43 INFO Uploading 1 narinfos11112026/11/09 11:52:43 INFO Vacuumed table table=pending_objects1112--- PASS: TestNARDeduplicationMetadataUploadBug (0.92s)1113=== CONT TestGetExistingObjectsLocksRows11142026/11/09 11:52:43 INFO Vacuumed table table=multipart_uploads11152026/11/09 11:52:43 INFO Received complete push request method=POST path=/api/pushes/1/complete11162026/11/09 11:52:43 WARN Failed to register uploaded object key=jgkd36a0pkk799klvn3cdgwzk3rvfmn4.narinfo error="server returned 404: 404 page not found\n"11172026/11/09 11:52:43 INFO Completed push id=1 objects=3 duration=6.450292ms11182026/11/09 11:52:43 INFO Vacuumed table table=closures11192026/11/09 11:52:43 INFO Upload complete. (59ms)11202026/11/09 11:52:43 INFO Vacuumed table table=objects1121=== NAME TestClientIntegration1122 client_integration_test.go:291: Created store path: /build/TestClientIntegration972091094/002/store/law5jl284q3dnqfdc8kw1wfyyp49m9i2-test-file.txt11232026/11/09 11:52:43 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001124--- PASS: TestService_createPendingClosureHandler (0.95s)1125=== CONT TestPendingClosureWriteTimeout1126=== RUN TestPendingClosureWriteTimeout/empty1127=== PAUSE TestPendingClosureWriteTimeout/empty1128=== RUN TestPendingClosureWriteTimeout/400_objects1129=== PAUSE TestPendingClosureWriteTimeout/400_objects1130=== RUN TestPendingClosureWriteTimeout/670k_objects1131=== PAUSE TestPendingClosureWriteTimeout/670k_objects1132=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1133=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1134=== CONT TestRegisterCompletedObjectNeedsPendingRow11352026/11/09 11:52:43 INFO Received push request method=POST path=/api/pushes11362026/11/09 11:52:43 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)11372026/11/09 11:52:43 INFO Uploading cfzy4jqjzy5dxnlpxr5iy4i88945qpj1-a (208B)11382026/11/09 11:52:43 INFO Uploading z6ag0a3flgm75gnmds5x2p6jalm15bmy-shared-dep (136B)11392026/11/09 11:52:43 WARN Failed to register uploaded object key=hl5wxvzh59q9ix9b177ldar8a7vw6wcg.ls error="server returned 404: 404 page not found\n"11402026/11/09 11:52:43 WARN Failed to register uploaded object key=cfzy4jqjzy5dxnlpxr5iy4i88945qpj1.ls error="server returned 404: 404 page not found\n"11412026/11/09 11:52:43 WARN Failed to register uploaded object key=nar/1i3phmdq7p24hwvkyv2vfj9zjx8g3w9qaawvqsl24jgg4qn9s5l4.nar.zst error="server returned 404: 404 page not found\n"11422026/11/09 11:52:43 WARN Failed to register uploaded object key=z6ag0a3flgm75gnmds5x2p6jalm15bmy.ls error="server returned 404: 404 page not found\n"11432026/11/09 11:52:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11442026/11/09 11:52:43 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11452026/11/09 11:52:43 INFO Signed narinfos id=1 count=311462026/11/09 11:52:43 INFO Uploading 3 narinfos11472026/11/09 11:52:43 INFO Received complete push request method=POST path=/api/pushes/1/complete11482026/11/09 11:52:43 WARN Failed to register uploaded object key=cfzy4jqjzy5dxnlpxr5iy4i88945qpj1.narinfo error="server returned 404: 404 page not found\n"11492026/11/09 11:52:43 WARN Failed to register uploaded object key=z6ag0a3flgm75gnmds5x2p6jalm15bmy.narinfo error="server returned 404: 404 page not found\n"11502026/11/09 11:52:43 WARN Failed to register uploaded object key=hl5wxvzh59q9ix9b177ldar8a7vw6wcg.narinfo error="server returned 404: 404 page not found\n"11512026/11/09 11:52:43 INFO Completed push id=1 objects=8 duration=5.767442ms11522026/11/09 11:52:43 INFO Upload complete. (57ms)1153=== NAME TestClientPushesUseOnePush1154 client_pushes_test.go:97: Retrieved narinfo from S3:1155 StorePath: /build/TestClientPushesUseOnePush413646639/001/store/z6ag0a3flgm75gnmds5x2p6jalm15bmy-shared-dep1156 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1157 Compression: zstd1158 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821159 NarSize: 1361160 References: 1161 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1162 client_pushes_test.go:97: Retrieved narinfo from S3:1163 StorePath: /build/TestClientPushesUseOnePush413646639/001/store/cfzy4jqjzy5dxnlpxr5iy4i88945qpj1-a1164 URL: nar/1i3phmdq7p24hwvkyv2vfj9zjx8g3w9qaawvqsl24jgg4qn9s5l4.nar.zst1165 Compression: zstd1166 NarHash: sha256:1i3phmdq7p24hwvkyv2vfj9zjx8g3w9qaawvqsl24jgg4qn9s5l41167 NarSize: 2081168 References: /build/TestClientPushesUseOnePush413646639/001/store/z6ag0a3flgm75gnmds5x2p6jalm15bmy-shared-dep1169 CA: text:sha256:1glwkfwha4zf3p5z3370f7brmg9zqcp92r8ql10lk0l84rvdnbbk1170 client_pushes_test.go:97: Retrieved narinfo from S3:1171 StorePath: /build/TestClientPushesUseOnePush413646639/001/store/hl5wxvzh59q9ix9b177ldar8a7vw6wcg-b1172 URL: nar/1i3phmdq7p24hwvkyv2vfj9zjx8g3w9qaawvqsl24jgg4qn9s5l4.nar.zst1173 Compression: zstd1174 NarHash: sha256:1i3phmdq7p24hwvkyv2vfj9zjx8g3w9qaawvqsl24jgg4qn9s5l41175 NarSize: 2081176 References: /build/TestClientPushesUseOnePush413646639/001/store/z6ag0a3flgm75gnmds5x2p6jalm15bmy-shared-dep1177 CA: text:sha256:1glwkfwha4zf3p5z3370f7brmg9zqcp92r8ql10lk0l84rvdnbbk11782026/11/09 11:52:43 INFO Received push request method=POST path=/api/pushes1179--- PASS: TestClientPushesUseOnePush (0.91s)1180=== CONT TestSweepSkipsRowsLockedByPush11812026/11/09 11:52:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11822026/11/09 11:52:43 INFO Received push request method=POST path=/api/pushes11832026/11/09 11:52:43 INFO Uploading c4wpb0j8671nrkia6zxflad8648myj4w-unpinned-file.txt (128B)11842026/11/09 11:52:43 WARN Failed to register uploaded object key=c4wpb0j8671nrkia6zxflad8648myj4w.ls error="server returned 404: 404 page not found\n"11852026/11/09 11:52:43 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign11862026/11/09 11:52:43 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"11872026/11/09 11:52:43 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)11882026/11/09 11:52:43 INFO Uploading 35vb9s1iciqsric3l9spzb564dfdrf3a-top (224B)11892026/11/09 11:52:43 INFO Signed narinfos id=2 count=111902026/11/09 11:52:43 INFO Uploading lb4h1n88p0aingfcw2vvcadi4w5d5lwv-shared-dep (136B)11912026/11/09 11:52:43 INFO Uploading 1 narinfos11922026/11/09 11:52:43 INFO Received uploads request method=POST path=/api/pending_closures11932026/11/09 11:52:43 INFO Received complete push request method=POST path=/api/pushes/2/complete11942026/11/09 11:52:43 WARN Failed to register uploaded object key=c4wpb0j8671nrkia6zxflad8648myj4w.narinfo error="server returned 404: 404 page not found\n"11952026/11/09 11:52:43 WARN Failed to register uploaded object key=nar/05928fz9bgr193sirvmxgwfa6fn8lb541z40mdw4gxhm1arpqvsj.nar.zst error="server returned 404: 404 page not found\n"11962026/11/09 11:52:43 INFO Received push request method=POST path=/api/pushes11972026/11/09 11:52:43 WARN Failed to register uploaded object key=lb4h1n88p0aingfcw2vvcadi4w5d5lwv.ls error="server returned 404: 404 page not found\n"11982026/11/09 11:52:43 WARN Failed to register uploaded object key=35vb9s1iciqsric3l9spzb564dfdrf3a.ls error="server returned 404: 404 page not found\n"11992026/11/09 11:52:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12002026/11/09 11:52:43 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"1201=== NAME TestClientMultipleUploads12022026/11/09 11:52:43 INFO Signed narinfos id=1 count=21203 client_integration_test.go:405: Created store path 0: /build/TestClientMultipleUploads2760124176/001/store/x7mpjvz7sn59lsl78jfczij566rmrdxp-test-file-0.txt12042026/11/09 11:52:43 INFO Uploading 2 narinfos12052026/11/09 11:52:43 INFO Completed push id=2 objects=3 duration=2.474381ms12062026/11/09 11:52:43 INFO Upload complete. (47ms)12072026/11/09 11:52:43 INFO Received uploads request method=POST path=/api/pending_closures12082026/11/09 11:52:43 WARN Failed to register uploaded object key=lb4h1n88p0aingfcw2vvcadi4w5d5lwv.narinfo error="server returned 404: 404 page not found\n"12092026/11/09 11:52:43 INFO Received complete push request method=POST path=/api/pushes/1/complete12102026/11/09 11:52:43 WARN Failed to register uploaded object key=35vb9s1iciqsric3l9spzb564dfdrf3a.narinfo error="server returned 404: 404 page not found\n"12112026/11/09 11:52:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12122026/11/09 11:52:43 INFO Uploading law5jl284q3dnqfdc8kw1wfyyp49m9i2-test-file.txt (152B)12132026/11/09 11:52:43 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)12142026/11/09 11:52:43 INFO Uploading k30zidm7l6zag03m4z4h6qmnfvbxfxiy-b (216B)12152026/11/09 11:52:43 INFO Uploading 4ywspl64c0z8bj81klmz4zmvyin66xmj-shared-dep (136B)12162026/11/09 11:52:43 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"12172026/11/09 11:52:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12182026/11/09 11:52:43 WARN Failed to register uploaded object key=law5jl284q3dnqfdc8kw1wfyyp49m9i2.ls error="server returned 404: 404 page not found\n"12192026/11/09 11:52:43 WARN Failed to register uploaded object key=96ccdks1i2p51cqblx8nsh7mwc7z3l1s.ls error="server returned 404: 404 page not found\n"12202026/11/09 11:52:43 WARN Failed to register uploaded object key=nar/1r1fpv25ydz93f58mn8w6i28xf6q4wm4f8g9yi5rsv0r7810qbkz.nar.zst error="server returned 404: 404 page not found\n"12212026/11/09 11:52:43 INFO Signed narinfos id=1 count=112222026/11/09 11:52:43 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12232026/11/09 11:52:43 INFO Uploading 1 narinfos12242026/11/09 11:52:43 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12252026/11/09 11:52:43 WARN Failed to register uploaded object key=k30zidm7l6zag03m4z4h6qmnfvbxfxiy.ls error="server returned 404: 404 page not found\n"12262026/11/09 11:52:43 WARN Failed to register uploaded object key=4ywspl64c0z8bj81klmz4zmvyin66xmj.ls error="server returned 404: 404 page not found\n"12272026/11/09 11:52:43 INFO Completed push id=1 objects=6 duration=6.356732ms12282026/11/09 11:52:43 INFO Signed narinfos id=1 count=212292026/11/09 11:52:43 INFO Upload complete. (70ms)12302026/11/09 11:52:43 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12312026/11/09 11:52:43 INFO Signed narinfos id=2 count=212322026/11/09 11:52:43 INFO Uploading 4 narinfos1233=== NAME TestClientSharedPathCommittedMidPush1234 client_integration_test.go:727: Retrieved narinfo from S3:1235 StorePath: /build/TestClientSharedPathCommittedMidPush1551809854/001/store/lb4h1n88p0aingfcw2vvcadi4w5d5lwv-shared-dep1236 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1237 Compression: zstd1238 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821239 NarSize: 1361240 References: 1241 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1242--- PASS: TestCacheStatsHandler (0.55s)1243=== CONT TestProxyWriteTimeout1244=== RUN TestProxyWriteTimeout/narinfo1245=== PAUSE TestProxyWriteTimeout/narinfo1246=== RUN TestProxyWriteTimeout/1_GiB_nar12472026/11/09 11:52:43 INFO Received complete push request method=POST path=/api/pushes/1/complete1248=== PAUSE TestProxyWriteTimeout/1_GiB_nar12492026/11/09 11:52:43 WARN Failed to register uploaded object key=law5jl284q3dnqfdc8kw1wfyyp49m9i2.narinfo error="server returned 404: 404 page not found\n"1250=== RUN TestProxyWriteTimeout/10_GiB_nar1251=== PAUSE TestProxyWriteTimeout/10_GiB_nar1252=== RUN TestProxyWriteTimeout/unknown_size1253=== PAUSE TestProxyWriteTimeout/unknown_size1254=== NAME TestClientSharedPathCommittedMidPush1255 client_integration_test.go:727: Retrieved narinfo from S3:1256 StorePath: /build/TestClientSharedPathCommittedMidPush1551809854/001/store/35vb9s1iciqsric3l9spzb564dfdrf3a-top1257 URL: nar/05928fz9bgr193sirvmxgwfa6fn8lb541z40mdw4gxhm1arpqvsj.nar.zst1258 Compression: zstd1259 NarHash: sha256:05928fz9bgr193sirvmxgwfa6fn8lb541z40mdw4gxhm1arpqvsj1260 NarSize: 2241261 References: /build/TestClientSharedPathCommittedMidPush1551809854/001/store/lb4h1n88p0aingfcw2vvcadi4w5d5lwv-shared-dep1262 CA: text:sha256:0ma5jbp59w9853s2ag0bgld287hnqlfab9x4gpay6rzqf7ilzm5012632026/11/09 11:52:43 WARN Failed to register uploaded object key=k30zidm7l6zag03m4z4h6qmnfvbxfxiy.narinfo error="server returned 404: 404 page not found\n"1264=== CONT TestFailedS3DeleteKeepsTombstone12652026/11/09 11:52:43 WARN Failed to register uploaded object key=96ccdks1i2p51cqblx8nsh7mwc7z3l1s.narinfo error="server returned 404: 404 page not found\n"12662026/11/09 11:52:43 WARN Failed to register uploaded object key=4ywspl64c0z8bj81klmz4zmvyin66xmj.narinfo error="server returned 404: 404 page not found\n"12672026/11/09 11:52:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12682026/11/09 11:52:43 WARN Failed to register uploaded object key=4ywspl64c0z8bj81klmz4zmvyin66xmj.narinfo error="server returned 404: 404 page not found\n"1269--- PASS: TestService_ReadScope_PublicByDefault (0.51s)1270=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1271--- PASS: TestClientSharedPathCommittedMidPush (0.95s)1272=== CONT TestForceGCDuringPushOffersSweptObject1273=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1274=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1275=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1276=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1277=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection12782026/11/09 11:52:43 INFO Completed push id=1 objects=3 duration=9.612953ms12792026/11/09 11:52:43 INFO Upload complete. (64ms)12802026/11/09 11:52:43 INFO Completed upload id=1 objects=6 duration=8.040773ms12812026/11/09 11:52:43 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12822026/11/09 11:52:43 INFO Completed upload id=2 objects=6 duration=1.78996ms12832026/11/09 11:52:43 INFO Upload complete. (72ms)1284=== NAME TestClientFallsBackToClosures1285 client_pushes_test.go:112: Retrieved narinfo from S3:1286 StorePath: /build/TestClientFallsBackToClosures3152836679/001/store/4ywspl64c0z8bj81klmz4zmvyin66xmj-shared-dep1287 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1288 Compression: zstd1289 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821290 NarSize: 1361291 References: 1292 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n12932026/11/09 11:52:43 INFO Starting cleanup of old closures method=DELETE path=/api/closures1294=== NAME TestClientMultipleUploads12952026/11/09 11:52:43 INFO Garbage collection started1296 client_integration_test.go:405: Created store path 1: /build/TestClientMultipleUploads2760124176/001/store/yl11igflp35hjc42ybrw3a7cq6v74p9w-test-file-1.txt1297=== NAME TestClientFallsBackToClosures1298 client_pushes_test.go:112: Retrieved narinfo from S3:1299 StorePath: /build/TestClientFallsBackToClosures3152836679/001/store/96ccdks1i2p51cqblx8nsh7mwc7z3l1s-a1300 URL: nar/1r1fpv25ydz93f58mn8w6i28xf6q4wm4f8g9yi5rsv0r7810qbkz.nar.zst1301 Compression: zstd1302 NarHash: sha256:1r1fpv25ydz93f58mn8w6i28xf6q4wm4f8g9yi5rsv0r7810qbkz1303 NarSize: 2161304 References: /build/TestClientFallsBackToClosures3152836679/001/store/4ywspl64c0z8bj81klmz4zmvyin66xmj-shared-dep1305 CA: text:sha256:10wzpnidbj98a9yy9ldb3phcri75zqcb91ddpf2k3ynx20f8lpi81306 client_pushes_test.go:112: Retrieved narinfo from S3:1307 StorePath: /build/TestClientFallsBackToClosures3152836679/001/store/k30zidm7l6zag03m4z4h6qmnfvbxfxiy-b1308 URL: nar/1r1fpv25ydz93f58mn8w6i28xf6q4wm4f8g9yi5rsv0r7810qbkz.nar.zst1309 Compression: zstd1310 NarHash: sha256:1r1fpv25ydz93f58mn8w6i28xf6q4wm4f8g9yi5rsv0r7810qbkz1311 NarSize: 2161312 References: /build/TestClientFallsBackToClosures3152836679/001/store/4ywspl64c0z8bj81klmz4zmvyin66xmj-shared-dep1313 CA: text:sha256:10wzpnidbj98a9yy9ldb3phcri75zqcb91ddpf2k3ynx20f8lpi81314--- PASS: TestClientFallsBackToClosures (0.97s)1315=== CONT TestSkippedUploadsHandler13162026/11/09 11:52:43 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001317--- PASS: TestSkippedUploadsHandler (0.00s)1318=== CONT TestGCSweepDeliversEachKeyOnce13192026/11/09 11:52:43 INFO Aborted multipart uploads count=0 kept=01320=== NAME TestClientWithDependencies1321 client_integration_test.go:660: Built derivation: /build/TestClientWithDependencies1594033747/001/store/66p8dkqc47zpapiyc8aa11gim3gyb0qj-test-script1322=== RUN TestService_RequireScope_OIDC/builder_may_write1323=== PAUSE TestService_RequireScope_OIDC/builder_may_write1324=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1325=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1326=== RUN TestService_RequireScope_OIDC/ops_may_admin1327=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1328=== RUN TestService_RequireScope_OIDC/ops_may_not_write1329=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1330=== RUN TestService_RequireScope_OIDC/reader_may_not_write1331=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1332=== RUN TestService_RequireScope_OIDC/static_token_may_admin1333=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1334=== RUN TestService_RequireScope_OIDC/static_token_may_write1335=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1336=== RUN TestService_RequireScope_OIDC/reader_may_read1337=== PAUSE TestService_RequireScope_OIDC/reader_may_read1338=== RUN TestService_RequireScope_OIDC/writer_implies_read1339=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1340=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1341=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1342=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1343=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1344=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1345=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1346=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1347=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1348=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1349=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1350=== CONT TestParseSize1351--- PASS: TestParseSize (0.00s)1352=== CONT TestTombstonedObjectOfferedWithoutWaiting13532026/11/09 11:52:43 WARN Force mode enabled - objects will be deleted immediately without grace period13542026/11/09 11:52:43 INFO All 1 paths already cached1355=== NAME TestClientIntegration1356 client_integration_test.go:317: Retrieved narinfo from S3:1357 StorePath: /build/TestClientIntegration972091094/002/store/law5jl284q3dnqfdc8kw1wfyyp49m9i2-test-file.txt1358 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1359 Compression: zstd1360 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11361 NarSize: 1521362 References: 1363 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11364 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1365 client_integration_test.go:318: Decompressed .ls content (64 bytes):1366 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1367=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1368=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1369=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1370=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1371=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1372=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1373=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1374=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1375=== CONT TestGCSweepSkipsPendingObjects1376=== NAME TestClientMultipleUploads1377 client_integration_test.go:405: Created store path 2: /build/TestClientMultipleUploads2760124176/001/store/hr52y0r1gyb1ywv8z1m6zrwjadwgijh6-test-file-2.txt1378=== NAME TestClientCADerivations1379 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations4196015928/001/store/x526ydq39brrkz64h1nszpj13cwh3a7h-ca-test1380=== NAME TestClientWithDependencies1381 client_integration_test.go:662: Found 1 dependencies (including self)13822026/11/09 11:52:43 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"13832026/11/09 11:52:43 WARN mTLS auth: bound subjects configured but subject DN unavailable13842026/11/09 11:52:43 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1385--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.45s)1386=== CONT TestService_Rustfstest13872026/11/09 11:52:43 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=01388=== NAME TestClientCADerivations1389 client_ca_test.go:139: Found 1 dependencies (including self)1390--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.45s)1391=== CONT TestDeduplicatedObjectsRecordedAsPending13922026/11/09 11:52:43 INFO Vacuumed table table=pending_closures13932026/11/09 11:52:43 INFO Vacuumed table table=pending_objects13942026/11/09 11:52:43 INFO Vacuumed table table=multipart_uploads13952026/11/09 11:52:43 INFO Vacuumed table table=closures13962026/11/09 11:52:43 INFO Vacuumed table table=objects1397--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (1.06s)1398=== CONT TestPushDedupSurvivesConcurrentGC1399--- PASS: TestService_ReadAuthMiddleware (0.49s)1400=== CONT TestPresignedUploadRegisteredBeforeCommit14012026/11/09 11:52:43 INFO Received push request method=POST path=/api/pushes14022026/11/09 11:52:43 INFO Received push request method=POST path=/api/pushes14032026/11/09 11:52:43 INFO Received push request method=POST path=/api/pushes14042026/11/09 11:52:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14052026/11/09 11:52:43 INFO Uploading 66p8dkqc47zpapiyc8aa11gim3gyb0qj-test-script (136B)14062026/11/09 11:52:43 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)14072026/11/09 11:52:43 INFO Uploading yl11igflp35hjc42ybrw3a7cq6v74p9w-test-file-1.txt (160B)14082026/11/09 11:52:43 INFO Uploading hr52y0r1gyb1ywv8z1m6zrwjadwgijh6-test-file-2.txt (160B)14092026/11/09 11:52:43 INFO Uploading x7mpjvz7sn59lsl78jfczij566rmrdxp-test-file-0.txt (160B)14102026/11/09 11:52:43 INFO Object in database but missing from S3 key=law5jl284q3dnqfdc8kw1wfyyp49m9i2.ls14112026/11/09 11:52:43 WARN Found objects in DB but missing from S3, will re-upload count=114122026/11/09 11:52:43 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)14132026/11/09 11:52:43 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"14142026/11/09 11:52:43 WARN Failed to register uploaded object key=log/khp9n6qksgv0xp2zs1ji9h53pzvm3rrs-test-script.drv error="server returned 404: 404 page not found\n"14152026/11/09 11:52:43 WARN Failed to register uploaded object key=yl11igflp35hjc42ybrw3a7cq6v74p9w.ls error="server returned 404: 404 page not found\n"14162026/11/09 11:52:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14172026/11/09 11:52:43 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"14182026/11/09 11:52:43 WARN Failed to register uploaded object key=66p8dkqc47zpapiyc8aa11gim3gyb0qj.ls error="server returned 404: 404 page not found\n"14192026/11/09 11:52:43 INFO Signed narinfos id=1 count=114202026/11/09 11:52:43 INFO Uploading 1 narinfos14212026/11/09 11:52:43 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"14222026/11/09 11:52:43 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"14232026/11/09 11:52:43 WARN Failed to register uploaded object key=x7mpjvz7sn59lsl78jfczij566rmrdxp.ls error="server returned 404: 404 page not found\n"14242026/11/09 11:52:43 INFO Received complete push request method=POST path=/api/pushes/2/complete14252026/11/09 11:52:43 WARN Failed to register uploaded object key=law5jl284q3dnqfdc8kw1wfyyp49m9i2.ls error="server returned 404: 404 page not found\n"14262026/11/09 11:52:43 INFO Received complete push request method=POST path=/api/pushes/1/complete14272026/11/09 11:52:43 WARN Failed to register uploaded object key=66p8dkqc47zpapiyc8aa11gim3gyb0qj.narinfo error="server returned 404: 404 page not found\n"14282026/11/09 11:52:43 INFO Completed push id=2 objects=3 duration=3.643531ms14292026/11/09 11:52:43 INFO Upload complete. (54ms)1430=== NAME TestClientIntegration1431 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1432 client_integration_test.go:335: Decompressed .ls content (49 bytes):1433 {"version":1,"root":{"type":"regular","size":39}}14342026/11/09 11:52:43 INFO Completed push id=1 objects=4 duration=12.312514ms14352026/11/09 11:52:43 INFO Upload complete. (74ms)1436=== NAME TestClientWithDependencies1437 client_integration_test.go:664: Skipping nix copy test - isolated store (/build/TestClientWithDependencies1594033747/001/store) requires matching store prefix1438--- PASS: TestClientWithDependencies (1.12s)1439=== CONT TestGCMetrics14402026/11/09 11:52:43 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1441--- PASS: TestService_AuthMiddleware (0.49s)1442=== CONT TestCompletedNarNotReofferedAcrossClosures14432026/11/09 11:52:43 INFO Aborted multipart uploads count=0 kept=014442026/11/09 11:52:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14452026/11/09 11:52:43 WARN Failed to register uploaded object key=hr52y0r1gyb1ywv8z1m6zrwjadwgijh6.ls error="server returned 404: 404 page not found\n"14462026/11/09 11:52:43 INFO Signed narinfos id=1 count=314472026/11/09 11:52:43 INFO Uploading 3 narinfos14482026/11/09 11:52:43 WARN Force mode enabled - objects will be deleted immediately without grace period14492026/11/09 11:52:43 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014502026/11/09 11:52:43 WARN Failed to register uploaded object key=hr52y0r1gyb1ywv8z1m6zrwjadwgijh6.narinfo error="server returned 404: 404 page not found\n"14512026/11/09 11:52:43 WARN Failed to register uploaded object key=x7mpjvz7sn59lsl78jfczij566rmrdxp.narinfo error="server returned 404: 404 page not found\n"14522026/11/09 11:52:43 INFO Received complete push request method=POST path=/api/pushes/1/complete14532026/11/09 11:52:43 WARN Failed to register uploaded object key=yl11igflp35hjc42ybrw3a7cq6v74p9w.narinfo error="server returned 404: 404 page not found\n"14542026/11/09 11:52:43 INFO Vacuumed table table=pending_closures14552026/11/09 11:52:43 INFO Received push request method=POST path=/api/pushes14562026/11/09 11:52:43 INFO Completed push id=1 objects=9 duration=15.929024ms14572026/11/09 11:52:43 INFO Vacuumed table table=pending_objects14582026/11/09 11:52:43 INFO Upload complete. (123ms)1459=== NAME TestClientMultipleUploads1460 client_integration_test.go:416: Uploaded 3 paths in 162.215427ms14612026/11/09 11:52:43 INFO Vacuumed table table=multipart_uploads14622026/11/09 11:52:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14632026/11/09 11:52:43 INFO Uploading x526ydq39brrkz64h1nszpj13cwh3a7h-ca-test (144B)14642026/11/09 11:52:43 INFO Received uploads request method=POST path=/api/pending_closures14652026/11/09 11:52:43 INFO Vacuumed table table=closures14662026/11/09 11:52:43 INFO Vacuumed table table=objects14672026/11/09 11:52:43 WARN Failed to register uploaded object key=x526ydq39brrkz64h1nszpj13cwh3a7h.ls error="server returned 404: 404 page not found\n"14682026/11/09 11:52:43 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"14692026/11/09 11:52:43 WARN Failed to register uploaded object key=log/vars40qnid5ygh45k3y8rbx91kjfwhkj-ca-test.drv error="server returned 404: 404 page not found\n"14702026/11/09 11:52:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14712026/11/09 11:52:43 INFO Signed narinfos id=1 count=114722026/11/09 11:52:43 INFO Uploading 1 narinfos1473--- PASS: TestClientMultipleUploads (1.10s)1474=== CONT TestCompleteMultipartUpload_ErrorButObjectExists14752026/11/09 11:52:43 INFO Received complete push request method=POST path=/api/pushes/1/complete14762026/11/09 11:52:43 WARN Failed to register uploaded object key=x526ydq39brrkz64h1nszpj13cwh3a7h.narinfo error="server returned 404: 404 page not found\n"1477--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.54s)1478=== CONT TestGCBugBareHashReferences14792026/11/09 11:52:43 INFO Completed push id=1 objects=4 duration=6.310482ms14802026/11/09 11:52:43 INFO Upload complete. (107ms)1481=== NAME TestClientCADerivations1482 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations4196015928/001/store/x526ydq39brrkz64h1nszpj13cwh3a7h-ca-test1483 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1484 Compression: zstd1485 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1486 NarSize: 1441487 References: 1488 Deriver: /build/TestClientCADerivations4196015928/001/store/vars40qnid5ygh45k3y8rbx91kjfwhkj-ca-test.drv1489 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1490 client_ca_test.go:185: Checking for realisation files in S3...1491 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1492 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache14932026/11/09 11:52:43 INFO Aborted multipart uploads count=0 kept=014942026/11/09 11:52:43 WARN Force mode enabled - objects will be deleted immediately without grace period1495--- PASS: TestReadRedirectNar (0.40s)1496=== CONT TestSharedNarBothUploadsComplete14972026/11/09 11:52:43 INFO Received push request method=POST path=/api/pushes14982026/11/09 11:52:43 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014992026/11/09 11:52:43 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)15002026/11/09 11:52:43 INFO Vacuumed table table=pending_closures15012026/11/09 11:52:43 INFO Received complete push request method=POST path=/api/pushes/3/complete15022026/11/09 11:52:43 WARN Failed to register uploaded object key=law5jl284q3dnqfdc8kw1wfyyp49m9i2.ls error="server returned 404: 404 page not found\n"1503--- PASS: TestGetExistingObjectsLocksRows (0.41s)1504=== CONT TestGCAdvisoryLockBlocksConcurrentRun15052026/11/09 11:52:43 INFO Vacuumed table table=pending_objects15062026/11/09 11:52:43 INFO Vacuumed table table=multipart_uploads15072026/11/09 11:52:43 INFO Vacuumed table table=closures15082026/11/09 11:52:43 INFO Completed push id=3 objects=3 duration=4.280721ms15092026/11/09 11:52:43 INFO Upload complete. (48ms)1510=== NAME TestClientIntegration1511 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1512 client_integration_test.go:352: Decompressed .ls content (49 bytes):1513 {"version":1,"root":{"type":"regular","size":39}}15142026/11/09 11:52:43 INFO Vacuumed table table=objects1515 client_integration_test.go:363: Testing garbage collection...1516--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.39s)1517=== CONT TestPush_SignsNarinfosOfItsPendingObjects1518--- PASS: TestSweepRechecksPendingAfterLocking (0.47s)1519=== CONT TestLeadEndsOnShutdown15202026/11/09 11:52:43 INFO Starting cleanup of old closures method=DELETE path=/api/closures15212026/11/09 11:52:43 INFO Garbage collection started15222026/11/09 11:52:43 INFO Received uploads request method=POST path=/api/pending_closures15232026/11/09 11:52:43 INFO Aborted multipart uploads count=0 kept=015242026/11/09 11:52:43 WARN Force mode enabled - objects will be deleted immediately without grace period15252026/11/09 11:52:43 INFO Aborted multipart uploads count=0 kept=015262026/11/09 11:52:43 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=015272026/11/09 11:52:43 INFO Vacuumed table table=pending_closures15282026/11/09 11:52:43 INFO Vacuumed table table=pending_objects15292026/11/09 11:52:43 INFO Vacuumed table table=multipart_uploads15302026/11/09 11:52:43 INFO Vacuumed table table=closures15312026/11/09 11:52:43 INFO Vacuumed table table=objects15322026/11/09 11:52:43 WARN Force mode enabled - objects will be deleted immediately without grace period15332026/11/09 11:52:43 INFO Aborted multipart uploads count=0 kept=015342026/11/09 11:52:43 WARN Force mode enabled - objects will be deleted immediately without grace period15352026/11/09 11:52:43 INFO Received uploads request method=POST path=/api/pending_closures15362026/11/09 11:52:43 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=015372026/11/09 11:52:43 INFO Vacuumed table table=pending_closures15382026/11/09 11:52:43 INFO Vacuumed table table=pending_objects15392026/11/09 11:52:43 INFO Vacuumed table table=multipart_uploads15402026/11/09 11:52:43 INFO Vacuumed table table=closures15412026/11/09 11:52:43 INFO Vacuumed table table=objects1542--- PASS: TestSweepSkipsRowsLockedByPush (0.44s)1543=== CONT TestPush_RejectsBadRequests15442026/11/09 11:52:43 INFO Received uploads request method=POST path=/api/pending_closures15452026/11/09 11:52:43 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=015462026/11/09 11:52:43 INFO Vacuumed table table=pending_closures15472026/11/09 11:52:43 INFO Vacuumed table table=pending_objects15482026/11/09 11:52:43 INFO Vacuumed table table=multipart_uploads15492026/11/09 11:52:43 INFO Vacuumed table table=closures15502026/11/09 11:52:43 INFO Vacuumed table table=objects1551=== NAME TestClientCADerivations1552 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1553 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1554 error: binary cache 's3://bucket28?endpoint=http://localhost:44485®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations4196015928/001/store'1555 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11556--- PASS: TestClientCADerivations (1.01s)1557=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit15582026/11/09 11:52:43 INFO Received uploads request method=POST path=/api/pending_closures1559--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.41s)1560=== CONT TestLeadIncumbentAnnouncesAtOnce15612026/11/09 11:52:43 INFO Aborted multipart uploads count=0 kept=015622026/11/09 11:52:43 WARN Force mode enabled - objects will be deleted immediately without grace period15632026/11/09 11:52:43 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."15642026/11/09 11:52:43 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1565--- PASS: TestFailedS3DeleteKeepsTombstone (0.48s)1566=== CONT TestPush_RootsAreLockedInByteOrder15672026/11/09 11:52:43 INFO Received uploads request method=POST path=/api/pending_closures15682026/11/09 11:52:43 INFO Aborted multipart uploads count=0 kept=015692026/11/09 11:52:43 WARN Force mode enabled - objects will be deleted immediately without grace period15702026/11/09 11:52:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15712026/11/09 11:52:43 INFO Aborted multipart uploads count=0 kept=015722026/11/09 11:52:43 INFO Received uploads request method=POST path=/api/pending_closures15732026/11/09 11:52:43 WARN Force mode enabled - objects will be deleted immediately without grace period15742026/11/09 11:52:43 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=01575--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.43s)1576=== CONT TestPush_CompleteWaitsForCleanupOfThePush15772026/11/09 11:52:43 INFO Vacuumed table table=pending_closures15782026/11/09 11:52:43 INFO Vacuumed table table=pending_objects1579--- PASS: TestService_Rustfstest (0.45s)15802026/11/09 11:52:43 INFO Vacuumed table table=multipart_uploads1581=== CONT TestPush_RepeatedRootCommitsOnce15822026/11/09 11:52:43 INFO Vacuumed table table=closures15832026/11/09 11:52:43 INFO Vacuumed table table=objects15842026/11/09 11:52:43 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=015852026/11/09 11:52:43 INFO Vacuumed table table=pending_closures15862026/11/09 11:52:43 INFO Vacuumed table table=pending_objects15872026/11/09 11:52:43 INFO Vacuumed table table=multipart_uploads15882026/11/09 11:52:43 INFO Vacuumed table table=closures15892026/11/09 11:52:43 INFO Vacuumed table table=objects1590--- PASS: TestGCSweepDeliversEachKeyOnce (0.51s)1591=== CONT TestLeadElectsOneAndHandsOver1592--- PASS: TestGCSweepSkipsPendingObjects (0.49s)1593=== CONT TestConnectWaitsForAPeerMigration15942026/11/09 11:52:43 INFO Received uploads request method=POST path=/api/pending_closures15952026/11/09 11:52:43 INFO Received uploads request method=POST path=/api/pending_closures1596--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.59s)1597=== CONT TestPush_CompleteCommitsEveryRoot15982026/11/09 11:52:43 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst15992026/11/09 11:52:43 INFO Received uploads request method=POST path=/api/pending_closures1600--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.49s)1601=== CONT TestPush_OverlappingRootsStoreOneRowPerKey16022026/11/09 11:52:43 INFO Received uploads request method=POST path=/api/pending_closures16032026/11/09 11:52:44 INFO Aborted multipart uploads count=0 kept=016042026/11/09 11:52:44 INFO Aborted multipart uploads count=0 kept=016052026/11/09 11:52:44 WARN Force mode enabled - objects will be deleted immediately without grace period16062026/11/09 11:52: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=016072026/11/09 11:52:44 INFO Vacuumed table table=pending_closures16082026/11/09 11:52:44 INFO Vacuumed table table=pending_objects16092026/11/09 11:52:44 INFO Vacuumed table table=multipart_uploads16102026/11/09 11:52:44 INFO Vacuumed table table=closures16112026/11/09 11:52:44 INFO Vacuumed table table=objects16122026/11/09 11:52:44 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=016132026/11/09 11:52:44 INFO Vacuumed table table=pending_closures16142026/11/09 11:52:44 INFO Vacuumed table table=pending_objects16152026/11/09 11:52:44 INFO Vacuumed table table=multipart_uploads1616--- PASS: TestGCMetrics (0.51s)1617=== CONT TestReadRedirectUsesPublicS3URL16182026/11/09 11:52:44 INFO Vacuumed table table=closures16192026/11/09 11:52:44 INFO Vacuumed table table=objects16202026/11/09 11:52:44 INFO Aborted multipart uploads count=0 kept=016212026/11/09 11:52:44 WARN Force mode enabled - objects will be deleted immediately without grace period16222026/11/09 11:52: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=016232026/11/09 11:52:44 INFO Vacuumed table table=pending_closures16242026/11/09 11:52:44 INFO Received uploads request method=POST path=/api/pending_closures16252026/11/09 11:52:44 INFO Vacuumed table table=pending_objects16262026/11/09 11:52:44 INFO Vacuumed table table=multipart_uploads16272026/11/09 11:52:44 INFO Vacuumed table table=closures16282026/11/09 11:52:44 INFO Vacuumed table table=objects1629--- PASS: TestPushWaitsForSweepHoldingRow (0.94s)1630=== CONT TestReadProxyRangeRequest1631--- PASS: TestPushDedupSurvivesConcurrentGC (0.61s)1632=== CONT TestReadRedirectKeepsNarinfoProxied16332026/11/09 11:52:44 INFO Received uploads request method=POST path=/api/pending_closures16342026/11/09 11:52:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16352026/11/09 11:52:44 INFO Received uploads request method=POST path=/api/pending_closures16362026/11/09 11:52:44 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MmMwYmJkYzQtMDU4YS00YzQ3LWFmZTItYjU3ZDNkOWY5NjAzLjljNjQ1ZTlkLTE1OGEtNDM2NS1iNTY4LTA3YTY5OTQ5MmY1MXgxNzk0MjI1MTY0MTE1ODkxODIx16372026/11/09 11:52:44 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MmMwYmJkYzQtMDU4YS00YzQ3LWFmZTItYjU3ZDNkOWY5NjAzLjljNjQ1ZTlkLTE1OGEtNDM2NS1iNTY4LTA3YTY5OTQ5MmY1MXgxNzk0MjI1MTY0MTE1ODkxODIx parts=11638--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.54s)1639=== CONT TestReadProxyNarinfo16402026/11/09 11:52:44 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=nixbld database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1641--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.48s)1642=== CONT TestReadProxyHead16432026/11/09 11:52:44 INFO Received push request method=POST path=/api/pushes16442026/11/09 11:52:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16452026/11/09 11:52:44 INFO Signed narinfos id=1 count=116462026/11/09 11:52:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16472026/11/09 11:52:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16482026/11/09 11:52:44 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"16492026/11/09 11:52:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16502026/11/09 11:52:44 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"16512026/11/09 11:52:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16522026/11/09 11:52:44 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=116532026/11/09 11:52:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16542026/11/09 11:52:44 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1655--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.50s)1656=== CONT TestReadProxyInvalidPath16572026/11/09 11:52:44 INFO lead: acquired remote=192.0.2.1:12341658=== RUN TestPush_RejectsBadRequests/bad_root1659=== PAUSE TestPush_RejectsBadRequests/bad_root1660=== RUN TestPush_RejectsBadRequests/root_not_in_objects1661=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1662=== RUN TestPush_RejectsBadRequests/no_roots1663=== PAUSE TestPush_RejectsBadRequests/no_roots1664=== RUN TestPush_RejectsBadRequests/no_objects1665=== PAUSE TestPush_RejectsBadRequests/no_objects1666=== CONT TestReadProxyDisabled16672026/11/09 11:52:44 INFO Received push request method=POST path=/api/pushes16682026/11/09 11:52:44 INFO Received complete push request method=POST path=/api/pushes/1/complete16692026/11/09 11:52:44 INFO lead: acquired remote=192.0.2.1:123416702026/11/09 11:52:44 INFO lead: released remote=192.0.2.1:12341671--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.46s)1672=== CONT TestReadProxyRootRedirectsToIndexHTML16732026/11/09 11:52:44 INFO Completed push id=1 objects=4 duration=9.233573ms16742026/11/09 11:52:44 INFO Received push request method=POST path=/api/pushes1675--- PASS: TestGCBugBareHashReferences (0.70s)1676=== CONT TestReadProxy40416772026/11/09 11:52:44 INFO Received push request method=POST path=/api/pushes1678--- PASS: TestDeleteClosuresRacingPins (1.91s)1679=== CONT TestReadProxyConditionalGet16802026/11/09 11:52:44 INFO Received push request method=POST path=/api/pushes16812026/11/09 11:52:44 INFO Aborted multipart uploads count=0 kept=016822026-11-09 11:52:44.376 UTC [2002] ERROR: could not obtain lock on row in relation "closures"16832026-11-09 11:52:44.376 UTC [2002] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT16842026-11-09 11:52:44.377 UTC [2002] ERROR: could not obtain lock on row in relation "closures"16852026-11-09 11:52:44.377 UTC [2002] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT16862026-11-09 11:52:44.377 UTC [2002] ERROR: could not obtain lock on row in relation "closures"16872026-11-09 11:52:44.377 UTC [2002] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT16882026-11-09 11:52:44.378 UTC [2002] ERROR: could not obtain lock on row in relation "closures"16892026-11-09 11:52:44.378 UTC [2002] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT16902026-11-09 11:52:44.378 UTC [2002] ERROR: could not obtain lock on row in relation "closures"16912026-11-09 11:52:44.378 UTC [2002] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT16922026/11/09 11:52:44 WARN Force mode enabled - objects will be deleted immediately without grace period1693--- PASS: TestPush_RootsAreLockedInByteOrder (0.52s)1694=== CONT TestReadProxyNarStreaming16952026/11/09 11:52:44 INFO Received push request method=POST path=/api/pushes16962026/11/09 11:52:44 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=016972026/11/09 11:52:44 INFO Vacuumed table table=pending_closures16982026/11/09 11:52:44 INFO Vacuumed table table=pending_objects16992026/11/09 11:52:44 INFO Vacuumed table table=multipart_uploads17002026/11/09 11:52:44 INFO Vacuumed table table=closures17012026/11/09 11:52:44 INFO Received complete push request method=POST path=/api/pushes/1/complete17022026/11/09 11:52:44 INFO Vacuumed table table=objects17032026/11/09 11:52:44 INFO Received complete push request method=POST path=/api/pushes/2/complete17042026/11/09 11:52:44 INFO Completed push id=2 objects=4 duration=3.159381ms1705--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.60s)1706=== CONT TestReadProxyOutlastsServerWriteTimeout17072026/11/09 11:52:44 INFO lead: acquired remote=192.0.2.1:123417082026/11/09 11:52:44 INFO Completed push id=1 objects=4 duration=9.345462ms1709--- PASS: TestPush_RepeatedRootCommitsOnce (0.50s)1710=== CONT TestReadProxyContentNegotiation17112026/11/09 11:52:44 INFO Received push request method=POST path=/api/pushes17122026/11/09 11:52:44 INFO Received complete push request method=POST path=/api/pushes/1/complete17132026/11/09 11:52:44 INFO Received push request method=POST path=/api/pushes17142026/11/09 11:52:44 INFO Completed push id=1 objects=6 duration=9.912803ms1715--- PASS: TestPush_CompleteCommitsEveryRoot (0.49s)1716=== CONT TestReadProxyNarinfoAlreadyDecompressed1717--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.51s)1718=== CONT TestCreatePin_ReservedPins17192026/11/09 11:52:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1720--- PASS: TestReadRedirectUsesPublicS3URL (0.45s)1721=== CONT TestIsValidCachePath1722=== RUN TestIsValidCachePath/narinfo1723=== PAUSE TestIsValidCachePath/narinfo1724=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1725=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1726=== RUN TestIsValidCachePath/nar_zst1727=== PAUSE TestIsValidCachePath/nar_zst1728=== RUN TestIsValidCachePath/nar_xz1729=== PAUSE TestIsValidCachePath/nar_xz1730=== RUN TestIsValidCachePath/nar_bz21731=== PAUSE TestIsValidCachePath/nar_bz21732=== RUN TestIsValidCachePath/nar_uncompressed1733=== PAUSE TestIsValidCachePath/nar_uncompressed1734=== RUN TestIsValidCachePath/ls1735=== PAUSE TestIsValidCachePath/ls1736=== RUN TestIsValidCachePath/log1737=== PAUSE TestIsValidCachePath/log1738=== RUN TestIsValidCachePath/realisation1739=== PAUSE TestIsValidCachePath/realisation1740=== RUN TestIsValidCachePath/nix-cache-info1741=== PAUSE TestIsValidCachePath/nix-cache-info1742=== RUN TestIsValidCachePath/index.html1743=== PAUSE TestIsValidCachePath/index.html1744=== RUN TestIsValidCachePath/traversal_parent1745=== PAUSE TestIsValidCachePath/traversal_parent1746=== RUN TestIsValidCachePath/traversal_in_middle1747=== PAUSE TestIsValidCachePath/traversal_in_middle1748=== RUN TestIsValidCachePath/invalid_char_e1749=== PAUSE TestIsValidCachePath/invalid_char_e1750=== RUN TestIsValidCachePath/invalid_char_u1751=== PAUSE TestIsValidCachePath/invalid_char_u1752=== RUN TestIsValidCachePath/random_path1753=== PAUSE TestIsValidCachePath/random_path1754=== RUN TestIsValidCachePath/empty1755=== PAUSE TestIsValidCachePath/empty1756=== RUN TestIsValidCachePath/leading_slash1757=== PAUSE TestIsValidCachePath/leading_slash1758=== RUN TestIsValidCachePath/wrong_extension1759=== PAUSE TestIsValidCachePath/wrong_extension1760=== RUN TestIsValidCachePath/short_hash1761=== PAUSE TestIsValidCachePath/short_hash1762=== CONT TestObjectStatsUpdatedOncePerCommit17632026/11/09 11:52:44 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MmMwYmJkYzQtMDU4YS00YzQ3LWFmZTItYjU3ZDNkOWY5NjAzLjI0MDhhMzM2LTQzNDktNGJhNS1hM2Y2LWQxNDA3ODg2NWRiZngxNzk0MjI1MTY0MDA2MjE4ODY5 parts=1217642026/11/09 11:52:44 INFO Received uploads request method=POST path=/api/pending_closures1765--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.97s)1766=== CONT TestParseSingleRange1767=== RUN TestParseSingleRange/none1768=== PAUSE TestParseSingleRange/none1769=== RUN TestParseSingleRange/unknown_unit1770=== PAUSE TestParseSingleRange/unknown_unit1771=== RUN TestParseSingleRange/multi-range_ignored1772=== PAUSE TestParseSingleRange/multi-range_ignored1773=== RUN TestParseSingleRange/malformed_no_dash1774=== PAUSE TestParseSingleRange/malformed_no_dash1775=== RUN TestParseSingleRange/malformed_both_empty1776=== PAUSE TestParseSingleRange/malformed_both_empty1777=== RUN TestParseSingleRange/malformed_end_before_start1778=== PAUSE TestParseSingleRange/malformed_end_before_start1779=== RUN TestParseSingleRange/closed1780=== PAUSE TestParseSingleRange/closed1781=== RUN TestParseSingleRange/open-ended1782=== PAUSE TestParseSingleRange/open-ended1783=== RUN TestParseSingleRange/end_clamped_to_size1784=== PAUSE TestParseSingleRange/end_clamped_to_size1785=== RUN TestParseSingleRange/suffix1786=== PAUSE TestParseSingleRange/suffix1787=== RUN TestParseSingleRange/suffix_exceeds_size1788=== PAUSE TestParseSingleRange/suffix_exceeds_size1789=== RUN TestParseSingleRange/single_byte1790=== PAUSE TestParseSingleRange/single_byte1791=== RUN TestParseSingleRange/start_past_EOF1792=== PAUSE TestParseSingleRange/start_past_EOF1793=== RUN TestParseSingleRange/start_far_past_EOF1794=== PAUSE TestParseSingleRange/start_far_past_EOF1795=== CONT TestPresentNotReportedWhileGCDeletesClosure1796=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1797=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1798=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1799=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1800=== CONT TestOrphanedObjectsGCStressTest1801--- PASS: TestReadProxyRangeRequest (0.44s)1802=== CONT TestOrphanedObjectsGC18032026/11/09 11:52:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40643/oidc1804--- PASS: TestReadRedirectKeepsNarinfoProxied (0.47s)1805=== CONT TestPresentRefreshesOnlyStaleClosures1806--- PASS: TestReadProxyHead (0.46s)1807=== CONT TestObjectStatsTrigger18082026/11/09 11:52:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1809--- PASS: TestReadProxyInvalidPath (0.45s)1810=== CONT TestPendingCleanupUsesOneCutoff18112026/11/09 11:52:44 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MmMwYmJkYzQtMDU4YS00YzQ3LWFmZTItYjU3ZDNkOWY5NjAzLjY0NzA5MDQ0LTY4NjMtNDZlNy04MjE0LWZkZDQzZTU5MDg3NXgxNzk0MjI1MTY0MTM3NTg4MjM3 parts=1218122026-11-09 11:52:44.682 UTC [2008] ERROR: Push does not exist: id=118132026-11-09 11:52:44.682 UTC [2008] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE18142026-11-09 11:52:44.682 UTC [2008] STATEMENT: SELECT commit_push($1)1815--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (0.77s)1816=== CONT TestPresentReportsOnlyClosureRoots1817--- PASS: TestReadProxyDisabled (0.45s)1818=== CONT TestGCEndsOnShutdown/before_the_run18192026/11/09 11:52:44 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1820--- PASS: TestReadProxyNarinfo (0.54s)1821=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1822--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.42s)1823=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1824--- PASS: TestReadProxyConditionalGet (0.43s)1825=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info18262026/11/09 11:52:44 INFO Received uploads request method=POST path=/1827=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key18282026/11/09 11:52:44 INFO Received complete multipart upload request method=POST path=/1829=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key18302026/11/09 11:52:44 INFO Received request for more parts method=POST path=/1831=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal18322026/11/09 11:52:44 INFO Received uploads request method=POST path=/1833--- PASS: TestUploadHandlersRejectInvalidKeys (0.09s)1834 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1835 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1836 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1837 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1838=== CONT TestServerTLSConfig/no_client_CA1839=== CONT TestServerTLSConfig/not_a_PEM_file1840=== CONT TestServerTLSConfig/missing_CA_file1841--- PASS: TestServerTLSConfig (0.08s)1842 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1843 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1844 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1845=== CONT TestRetryableCompletionError/context_canceled1846=== CONT TestRetryableCompletionError/access_denied1847=== CONT TestRetryableCompletionError/transport_failure1848=== CONT TestRetryableCompletionError/deadline_exceeded1849=== CONT TestRetryableCompletionError/throttled1850=== CONT TestRetryableCompletionError/degraded_quorum1851=== CONT TestRetryableCompletionError/nil1852=== CONT TestRetryableCompletionError/bad_gateway1853=== CONT TestRetryableCompletionError/invalid_part1854=== CONT TestRetryableCompletionError/no_such_upload1855=== CONT TestIsValidUploadKey/empty_key1856--- PASS: TestRetryableCompletionError (0.08s)1857 --- PASS: TestRetryableCompletionError/context_canceled (0.00s)1858 --- PASS: TestRetryableCompletionError/access_denied (0.00s)1859 --- PASS: TestRetryableCompletionError/transport_failure (0.00s)1860 --- PASS: TestRetryableCompletionError/deadline_exceeded (0.00s)1861 --- PASS: TestRetryableCompletionError/throttled (0.00s)1862 --- PASS: TestRetryableCompletionError/degraded_quorum (0.00s)1863 --- PASS: TestRetryableCompletionError/nil (0.00s)1864 --- PASS: TestRetryableCompletionError/bad_gateway (0.00s)1865 --- PASS: TestRetryableCompletionError/invalid_part (0.00s)1866 --- PASS: TestRetryableCompletionError/no_such_upload (0.00s)1867=== CONT TestIsValidUploadKey/narinfo1868=== CONT TestIsValidUploadKey/absolute1869=== CONT TestIsValidUploadKey/traversal_nar1870=== CONT TestIsValidUploadKey/traversal1871=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1872=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1873=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1874=== CONT TestIsValidUploadKey/index.html1875=== CONT TestIsValidUploadKey/nix-cache-info1876=== CONT TestIsValidUploadKey/realisation_plus_in_output1877=== CONT TestIsValidUploadKey/realisation1878=== CONT TestIsValidUploadKey/build_log_equals1879=== CONT TestIsValidUploadKey/build_log_question_mark1880=== CONT TestIsValidUploadKey/build_log_plus_in_name1881=== CONT TestIsValidUploadKey/build_log_home-manager_file1882=== CONT TestIsValidUploadKey/build_log1883=== CONT TestIsValidUploadKey/listing1884=== CONT TestIsValidUploadKey/nar_plain1885=== CONT TestIsValidUploadKey/nar_xz1886=== CONT TestIsValidUploadKey/nar_zst1887=== CONT TestIsValidUploadKey/unknown_type1888--- PASS: TestIsValidUploadKey (0.09s)1889 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1890 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1891 --- PASS: TestIsValidUploadKey/absolute (0.00s)1892 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1893 --- PASS: TestIsValidUploadKey/traversal (0.00s)1894 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1895 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1896 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1897 --- PASS: TestIsValidUploadKey/index.html (0.00s)1898 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1899 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1900 --- PASS: TestIsValidUploadKey/realisation (0.00s)1901 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1902 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1903 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1904 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1905 --- PASS: TestIsValidUploadKey/build_log (0.00s)1906 --- PASS: TestIsValidUploadKey/listing (0.00s)1907 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1908 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1909 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1910 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1911=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1912--- PASS: TestReadProxy404 (0.49s)1913=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1914--- PASS: TestReadProxyNarStreaming (0.43s)1915=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1916--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.43s)1917=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1918--- PASS: TestReadProxyContentNegotiation (0.51s)1919=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1920--- PASS: TestObjectStatsUpdatedOncePerCommit (0.47s)1921=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19222026/11/09 11:52:44 INFO Received uploads request method=POST path=/19232026/11/09 11:52:45 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux19242026/11/09 11:52:45 WARN Refused reserved pin name=worker-x86_64-linux19252026/11/09 11:52:45 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux19262026/11/09 11:52:45 INFO Received create pin request method=POST path=/api/pins/my-app19272026/11/09 11:52:45 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1928--- PASS: TestCreatePin_ReservedPins (0.52s)1929=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19302026/11/09 11:52:45 INFO Received request for more parts method=POST path=/1931--- PASS: TestPresentRefreshesOnlyStaleClosures (0.47s)1932=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart19332026/11/09 11:52:45 INFO Received complete multipart upload request method=POST path=/1934=== CONT TestClientErrorHandling/InvalidStorePath1935--- PASS: TestObjectStatsTrigger (0.45s)1936=== CONT TestClientErrorHandling/ServerNotAvailable1937=== CONT TestClientErrorHandling/InvalidAuthToken19382026/11/09 11:52:45 INFO Received uploads request method=POST path=/api/pending_closures19392026/11/09 11:52:45 INFO Received uploads request method=POST path=/api/pending_closures19402026/11/09 11:52:45 INFO Received cleanup request method=DELETE path=/api/pending_closures1941--- PASS: TestPresentReportsOnlyClosureRoots (0.46s)1942=== CONT TestCacheConfigHandler/full_config,_no_issuer1943=== CONT TestCacheConfigHandler/no_signing_keys1944=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1945=== CONT TestCacheConfigHandler/no_cache_url_configured1946--- PASS: TestCacheConfigHandler (0.00s)1947 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1948 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1949 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1950 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1951=== CONT TestResolveDBConnectionString/flag_wins1952=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1953=== CONT TestResolveDBConnectionString/nothing_configured1954=== CONT TestResolveDBConnectionString/missing_file_is_an_error1955=== CONT TestResolveDBConnectionString/file_when_flag_empty1956=== CONT TestPendingClosureWriteTimeout/empty1957=== CONT TestPendingClosureWriteTimeout/670k_objects1958=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1959--- PASS: TestResolveDBConnectionString (0.00s)1960 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1961 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1962 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1963 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1964 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)19652026/11/09 11:52:45 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1966=== CONT TestPendingClosureWriteTimeout/400_objects1967=== CONT TestProxyWriteTimeout/narinfo1968=== CONT TestProxyWriteTimeout/unknown_size1969=== CONT TestProxyWriteTimeout/1_GiB_nar1970=== CONT TestProxyWriteTimeout/10_GiB_nar1971--- PASS: TestProxyWriteTimeout (0.00s)1972 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1973 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1974 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1975 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1976=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows19772026/11/09 11:52:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19782026/11/09 11:52:45 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MmMwYmJkYzQtMDU4YS00YzQ3LWFmZTItYjU3ZDNkOWY5NjAzLjk1YzU1NGZkLTdkOTYtNDgyZi1iODMxLTQ1ZGJiMDc4ZTdlZngxNzk0MjI1MTY0MTQ4NDc0MzMw parts=121979--- PASS: TestSharedNarBothUploadsComplete (1.54s)1980=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check19812026/11/09 11:52:45 INFO Aborted multipart uploads count=0 kept=019822026/11/09 11:52:45 WARN Force mode enabled - objects will be deleted immediately without grace period1983=== CONT TestService_RequireScope_OIDC/builder_may_write19842026/11/09 11:52:45 INFO Aborted multipart uploads count=0 kept=01985=== CONT TestService_RequireScope_OIDC/reader_may_read1986=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1987=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19882026/11/09 11:52:45 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]1989=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1990=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1991=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1992=== CONT TestService_RequireScope_OIDC/writer_implies_read1993=== CONT TestService_RequireScope_OIDC/reader_may_not_write1994=== CONT TestService_RequireScope_OIDC/static_token_may_write1995=== CONT TestService_RequireScope_OIDC/static_token_may_admin1996=== CONT TestService_RequireScope_OIDC/ops_may_admin1997=== CONT TestService_RequireScope_OIDC/ops_may_not_write1998=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1999=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2000--- PASS: TestService_RequireScope_OIDC (0.51s)2001 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2002 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2003 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2004 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2005 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2006 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2007 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2008 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2009 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2010 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2011 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2012 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2013 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2014 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)20152026/11/09 11:52:45 WARN Force mode enabled - objects will be deleted immediately without grace period2016=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20172026/11/09 11:52:45 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]2018=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2019=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20202026/11/09 11:52:45 WARN Authentication failed token_preview=eyJhbGciOi...xmK1TQgk6Q token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2021=== CONT TestPush_RejectsBadRequests/bad_root20222026/11/09 11:52:45 INFO Received push request method=POST path=/api/pushes2023=== CONT TestPush_RejectsBadRequests/no_objects20242026/11/09 11:52:45 INFO Received push request method=POST path=/api/pushes2025=== CONT TestPush_RejectsBadRequests/no_roots20262026/11/09 11:52:45 INFO Received push request method=POST path=/api/pushes2027=== CONT TestPush_RejectsBadRequests/root_not_in_objects20282026/11/09 11:52:45 INFO Received push request method=POST path=/api/pushes2029--- PASS: TestService_AuthMiddleware_OIDC (0.49s)2030 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2031 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2032 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2033 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2034=== CONT TestIsValidCachePath/narinfo2035=== CONT TestIsValidCachePath/index.html2036=== CONT TestIsValidCachePath/short_hash2037=== CONT TestIsValidCachePath/wrong_extension2038=== CONT TestIsValidCachePath/leading_slash2039=== CONT TestIsValidCachePath/empty2040=== CONT TestIsValidCachePath/traversal_in_middle2041=== CONT TestIsValidCachePath/traversal_parent2042=== CONT TestIsValidCachePath/invalid_char_e2043--- PASS: TestPush_RejectsBadRequests (0.44s)2044 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2045 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2046 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2047 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2048=== CONT TestIsValidCachePath/nar_uncompressed20492026/11/09 11:52:45 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:44485/bucket95/?delete=\": context canceled"2050=== CONT TestIsValidCachePath/nix-cache-info2051=== CONT TestIsValidCachePath/random_path20522026/11/09 11:52:45 INFO Received uploads request method=POST path=/api/pending_closures2053=== CONT TestIsValidCachePath/realisation2054=== CONT TestIsValidCachePath/invalid_char_u2055=== CONT TestIsValidCachePath/log2056=== CONT TestIsValidCachePath/nar_bz22057=== CONT TestIsValidCachePath/ls2058=== CONT TestIsValidCachePath/nar_xz2059=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2060=== CONT TestParseSingleRange/none2061=== CONT TestParseSingleRange/open-ended2062=== CONT TestParseSingleRange/start_far_past_EOF2063=== CONT TestParseSingleRange/start_past_EOF2064=== CONT TestParseSingleRange/single_byte2065=== CONT TestParseSingleRange/suffix_exceeds_size2066=== CONT TestParseSingleRange/end_clamped_to_size2067=== CONT TestParseSingleRange/malformed_both_empty2068=== CONT TestParseSingleRange/closed2069=== CONT TestParseSingleRange/suffix2070=== CONT TestParseSingleRange/malformed_end_before_start2071=== CONT TestParseSingleRange/unknown_unit2072=== CONT TestParseSingleRange/multi-range_ignored2073=== CONT TestParseSingleRange/malformed_no_dash2074--- PASS: TestGCEndsOnShutdown (0.07s)2075 --- PASS: TestGCEndsOnShutdown/before_the_run (0.48s)2076 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.53s)2077 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.52s)2078=== CONT TestIsValidCachePath/nar_zst2079=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh2080--- PASS: TestIsValidCachePath (0.00s)2081 --- PASS: TestIsValidCachePath/narinfo (0.00s)2082 --- PASS: TestIsValidCachePath/index.html (0.00s)2083 --- PASS: TestIsValidCachePath/short_hash (0.00s)2084 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2085 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2086 --- PASS: TestIsValidCachePath/empty (0.00s)2087 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2088 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2089 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2090 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2091 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2092 --- PASS: TestIsValidCachePath/random_path (0.00s)2093 --- PASS: TestIsValidCachePath/realisation (0.00s)2094 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2095 --- PASS: TestIsValidCachePath/log (0.00s)2096 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2097 --- PASS: TestIsValidCachePath/ls (0.00s)2098 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2099 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2100 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2101--- PASS: TestParseSingleRange (0.00s)2102 --- PASS: TestParseSingleRange/none (0.00s)2103 --- PASS: TestParseSingleRange/open-ended (0.00s)2104 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2105 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2106 --- PASS: TestParseSingleRange/single_byte (0.00s)2107 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2108 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2109 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2110 --- PASS: TestParseSingleRange/closed (0.00s)2111 --- PASS: TestParseSingleRange/suffix (0.00s)2112 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2113 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2114 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2115 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2116=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale21172026/11/09 11:52:45 INFO lead: released remote=192.0.2.1:12342118--- PASS: TestLeadEndsOnShutdown (1.70s)21192026/11/09 11:52:45 INFO Received uploads request method=POST path=/api/pending_closures21202026/11/09 11:52:45 WARN Request failed, retrying attempt=2 backoff=208.645736ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21212026/11/09 11:52:45 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=021222026/11/09 11:52:45 INFO Received create pin request method=POST path=/api/pins/myapp21232026/11/09 11:52:45 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC3549268432/001/store/jgkd36a0pkk799klvn3cdgwzk3rvfmn4-pinned-file.txt narinfo_key=jgkd36a0pkk799klvn3cdgwzk3rvfmn4.narinfo21242026/11/09 11:52:45 INFO Starting cleanup of old closures method=DELETE path=/api/closures21252026/11/09 11:52:45 INFO Garbage collection started21262026/11/09 11:52:45 INFO Received uploads request method=POST path=/api/pending_closures21272026/11/09 11:52:45 INFO Aborted multipart uploads count=0 kept=021282026/11/09 11:52:45 WARN Force mode enabled - objects will be deleted immediately without grace period21292026/11/09 11:52:45 INFO Received uploads request method=POST path=/api/pending_closures21302026/11/09 11:52:45 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=021312026/11/09 11:52:45 INFO Vacuumed table table=pending_closures21322026/11/09 11:52:45 INFO Vacuumed table table=pending_objects21332026/11/09 11:52:45 INFO Vacuumed table table=multipart_uploads21342026/11/09 11:52:45 INFO Vacuumed table table=closures21352026/11/09 11:52:45 INFO Vacuumed table table=objects21362026/11/09 11:52:45 INFO Received uploads request method=POST path=/api/pending_closures2137=== NAME TestOrphanedObjectsGC2138 orphaned_objects_gc_test.go:287: GC Test Summary:2139 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A2140 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B2141 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)2142 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)2143 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects2144--- PASS: TestOrphanedObjectsGC (0.97s)21452026/11/09 11:52:45 INFO Received uploads request method=POST path=/api/pending_closures21462026/11/09 11:52:45 INFO Received uploads request method=POST path=/api/pending_closures21472026/11/09 11:52:45 INFO Aborted multipart uploads count=0 kept=021482026/11/09 11:52:45 WARN Force mode enabled - objects will be deleted immediately without grace period21492026/11/09 11:52:45 WARN Request failed, retrying attempt=3 backoff=415.54795ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21502026/11/09 11:52:45 INFO Received uploads request method=POST path=/api/pending_closures21512026/11/09 11:52:45 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21522026/11/09 11:52:45 INFO lead: released remote=192.0.2.1:123421532026/11/09 11:52:45 INFO Aborted multipart uploads count=0 kept=021542026/11/09 11:52:45 WARN Force mode enabled - objects will be deleted immediately without grace period21552026/11/09 11:52:45 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=021562026/11/09 11:52:45 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=021572026/11/09 11:52:45 INFO Vacuumed table table=pending_closures21582026/11/09 11:52:45 INFO Vacuumed table table=pending_objects21592026/11/09 11:52:45 INFO Vacuumed table table=pending_closures21602026/11/09 11:52:45 INFO Vacuumed table table=multipart_uploads21612026/11/09 11:52:45 INFO Vacuumed table table=closures21622026/11/09 11:52:45 INFO Vacuumed table table=pending_objects21632026/11/09 11:52:45 INFO Vacuumed table table=multipart_uploads21642026/11/09 11:52:45 INFO Vacuumed table table=objects21652026/11/09 11:52:45 INFO Vacuumed table table=closures21662026/11/09 11:52:45 INFO Vacuumed table table=objects21672026/11/09 11:52:45 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2168--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2169 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.45s)2170 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.48s)21712026/11/09 11:52:45 INFO lead: acquired remote=192.0.2.1:123421722026/11/09 11:52:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21732026/11/09 11:52:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21742026/11/09 11:52:45 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02175=== NAME TestClientIntegration2176 client_integration_test.go:370: Objects in database after GC:2177 client_integration_test.go:370: Successfully deleted all objects with GC --force21782026/11/09 11:52:45 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=MmMwYmJkYzQtMDU4YS00YzQ3LWFmZTItYjU3ZDNkOWY5NjAzLjA5Zjg3MjU0LTZhZTMtNDg5MC1iZWJmLThiY2NhMTc3MTU1ZngxNzk0MjI1MTY1MjUxMjkxNjcz parts=1021792026/11/09 11:52:45 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=MmMwYmJkYzQtMDU4YS00YzQ3LWFmZTItYjU3ZDNkOWY5NjAzLmYzMTNkMDFmLWI4YjktNDMzZC05MzVkLTAzODg1MjkwYWFkN3gxNzk0MjI1MTY1NDAyNjg2MzQ3 parts=102180--- PASS: TestClientIntegration (3.21s)21812026/11/09 11:52:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21822026/11/09 11:52:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21832026/11/09 11:52:45 INFO Completed upload id=1 objects=3 duration=2.840411ms21842026/11/09 11:52:45 INFO Completed upload id=1 objects=3 duration=3.303171ms21852026/11/09 11:52:45 INFO Received uploads request method=POST path=/api/pending_closures21862026/11/09 11:52:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21872026/11/09 11:52:45 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=MmMwYmJkYzQtMDU4YS00YzQ3LWFmZTItYjU3ZDNkOWY5NjAzLjIzNDgwZWE0LWJmNzMtNDAyMi04ZWJiLWU4Y2NkNjgyMjYzNHgxNzk0MjI1MTY1NDMzNDg2MTM2 parts=1021882026/11/09 11:52:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21892026/11/09 11:52:45 INFO Received uploads request method=POST path=/api/pending_closures21902026/11/09 11:52:45 INFO Completed upload id=1 objects=3 duration=3.207081ms21912026/11/09 11:52:45 INFO Received uploads request method=POST path=/api/pending_closures21922026/11/09 11:52:45 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21932026/11/09 11:52:45 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21942026/11/09 11:52:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2195--- PASS: TestUploadHandlersRejectOversizedBody (0.17s)2196 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.05s)2197 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)2198 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.79s)21992026/11/09 11:52:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22002026/11/09 11:52:45 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=MmMwYmJkYzQtMDU4YS00YzQ3LWFmZTItYjU3ZDNkOWY5NjAzLjBhZWM5NWE1LTQxNDUtNDIzYi05OTVhLTkwOGQxMmRmNzYxOHgxNzk0MjI1MTY1NDU5OTU0NDM0 parts=1022012026/11/09 11:52:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22022026/11/09 11:52:45 INFO Completed upload id=1 objects=3 duration=1.55925ms22032026/11/09 11:52:45 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=MmMwYmJkYzQtMDU4YS00YzQ3LWFmZTItYjU3ZDNkOWY5NjAzLmU2NmRiYjIxLTBlNmQtNGZlMS1iOTc0LTliNjlhZTIyODEyYXgxNzk0MjI1MTY1NDg0NTA0Mzcx parts=1022042026/11/09 11:52:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22052026/11/09 11:52:45 INFO Completed upload id=1 objects=3 duration=1.66065ms22062026/11/09 11:52:45 INFO Received uploads request method=POST path=/api/pending_closures22072026/11/09 11:52:45 INFO Received uploads request method=POST path=/api/pending_closures22082026/11/09 11:52:45 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst22092026/11/09 11:52:45 WARN Found objects in DB but missing from S3, will re-upload count=122102026/11/09 11:52:46 WARN Request failed, retrying attempt=4 backoff=793.222972ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22112026/11/09 11:52:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22122026/11/09 11:52:46 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=MmMwYmJkYzQtMDU4YS00YzQ3LWFmZTItYjU3ZDNkOWY5NjAzLmVkNjI5NzM3LTE5Y2MtNDBmZC05YTU4LTg2NGRmMWFiZmZmMHgxNzk0MjI1MTY1Nzc1NDM1Mjk2 parts=1022132026/11/09 11:52:46 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22142026/11/09 11:52:46 INFO Completed upload id=2 objects=3 duration=1.242291ms22152026/11/09 11:52:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22162026/11/09 11:52:46 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=MmMwYmJkYzQtMDU4YS00YzQ3LWFmZTItYjU3ZDNkOWY5NjAzLjY3NDAyMjg1LTVlMDgtNGIwMi1hYmI0LTE2YmVmYTQ5N2ZkMngxNzk0MjI1MTY1ODA5ODUyNzM2 parts=1022172026/11/09 11:52:46 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22182026/11/09 11:52:46 INFO Completed upload id=2 objects=3 duration=902.26µs22192026/11/09 11:52:46 INFO Received uploads request method=POST path=/api/pending_closures22202026/11/09 11:52:46 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22212026/11/09 11:52:46 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo22222026/11/09 11:52:46 INFO Received uploads request method=POST path=/api/pending_closures22232026/11/09 11:52:46 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22242026/11/09 11:52:46 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo2225--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.09s)2226 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (0.94s)2227 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (0.99s)2228 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (0.92s)2229 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (1.27s)2230 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (1.17s)2231--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2232 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.89s)2233 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.90s)2234=== NAME TestOrphanedObjectsGCStressTest2235 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2236--- PASS: TestPendingClosureWriteTimeout (0.00s)2237 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2238 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2239 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2240 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.22s)2241=== NAME TestOrphanedObjectsGCStressTest2242 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion22432026/11/09 11:52:46 INFO lead: released remote=192.0.2.1:12342244--- PASS: TestLeadElectsOneAndHandsOver (2.85s)22452026/11/09 11:52:46 WARN Request failed, retrying attempt=5 backoff=1.668164286s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22462026/11/09 11:52:47 WARN Rate limiter enabled after throttle name=s3-test rate=522472026/11/09 11:52:47 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2248=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2249 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102250 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002251--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (3.69s)2252=== NAME TestOrphanedObjectsGCStressTest2253 orphaned_objects_gc_test.go:503: Stress test completed successfully:2254 orphaned_objects_gc_test.go:504: - Active objects preserved: 202255 orphaned_objects_gc_test.go:505: - Objects deleted: 2102256 orphaned_objects_gc_test.go:506: - Total GC'd: 2102257--- PASS: TestOrphanedObjectsGCStressTest (2.74s)2258=== NAME TestPinProtectsFromGC2259 client_integration_test.go:887: Pin successfully protected closure from garbage collection2260--- PASS: TestPinProtectsFromGC (4.99s)22612026/11/09 11:52:48 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22622026/11/09 11:52:48 WARN Request failed, retrying attempt=2 backoff=181.78461ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22632026/11/09 11:52:48 WARN Request failed, retrying attempt=3 backoff=421.862588ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2264--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.64s)2265--- PASS: TestConnectWaitsForAPeerMigration (5.21s)22662026/11/09 11:52:49 WARN Request failed, retrying attempt=4 backoff=733.58637ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22672026/11/09 11:52:49 WARN Request failed, retrying attempt=5 backoff=1.508227719s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22682026/11/09 11:52:51 INFO Aborted multipart uploads count=1 kept=022692026/11/09 11:52:51 INFO Received cleanup request method=DELETE path=/api/pending_closures22702026/11/09 11:52:51 INFO Aborted multipart uploads count=1 kept=02271--- PASS: TestPendingCleanupUsesOneCutoff (6.49s)22722026/11/09 11:52:51 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"22732026/11/09 11:52:51 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22742026/11/09 11:52:51 WARN Request failed, retrying attempt=2 backoff=188.28705ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22752026/11/09 11:52:51 WARN Request failed, retrying attempt=3 backoff=405.472195ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22762026/11/09 11:52:52 WARN Request failed, retrying attempt=4 backoff=826.03791ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22772026/11/09 11:52:53 WARN Request failed, retrying attempt=5 backoff=1.634508491s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22782026/11/09 11:52:54 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22792026/11/09 11:52:54 WARN Request failed, retrying attempt=2 backoff=190.343857ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22802026/11/09 11:52:54 WARN Request failed, retrying attempt=3 backoff=383.024903ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22812026/11/09 11:52:55 WARN Request failed, retrying attempt=4 backoff=761.897676ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22822026/11/09 11:52:56 WARN Request failed, retrying attempt=5 backoff=1.463935781s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2283--- PASS: TestClientErrorHandling (0.00s)2284 --- PASS: TestClientErrorHandling/InvalidStorePath (0.48s)2285 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.56s)2286 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.46s)2287PASS2288{"timestamp":"2026-11-09T11:52:57.557302493Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:59836","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(401)"}2289{"timestamp":"2026-11-09T11:52:57.557456464Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:60832","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(391)"}2290{"timestamp":"2026-11-09T11:52:57.557378453Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:59430","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(396)"}2291{"timestamp":"2026-11-09T11:52:57.556900673Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:60886","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(398)"}22922026-11-09 11:52:57.956 UTC [111] LOG: received smart shutdown request22932026-11-09 11:52:57.961 UTC [111] LOG: background worker "logical replication launcher" (PID 121) exited with exit code 122942026-11-09 11:52:57.969 UTC [116] LOG: shutting down22952026-11-09 11:52:57.970 UTC [116] LOG: checkpoint starting: shutdown immediate22962026-11-09 11:52:59.712 UTC [116] LOG: checkpoint complete: wrote 11301 buffers (69.0%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.258 s, sync=1.434 s, total=1.743 s; sync files=36397, longest=0.020 s, average=0.001 s; distance=525986 kB, estimate=525986 kB; lsn=0/2190E4F0, redo lsn=0/2190E4F022972026-11-09 11:52:59.796 UTC [111] LOG: database system is shut down2298Running OIDC tests...2299=== RUN TestAudienceForIssuer2300=== PAUSE TestAudienceForIssuer2301=== RUN TestGlobMatch2302=== PAUSE TestGlobMatch2303=== RUN TestValidateToken_ValidToken2304=== PAUSE TestValidateToken_ValidToken2305=== RUN TestValidateToken_WrongAudience2306=== PAUSE TestValidateToken_WrongAudience2307=== RUN TestValidateToken_Expired2308=== PAUSE TestValidateToken_Expired2309=== RUN TestValidateToken_BoundClaimsMismatch2310=== PAUSE TestValidateToken_BoundClaimsMismatch2311=== RUN TestValidateToken_BoundSubjectMismatch2312=== PAUSE TestValidateToken_BoundSubjectMismatch2313=== RUN TestValidateToken_MultipleProviders2314=== PAUSE TestValidateToken_MultipleProviders2315=== RUN TestValidateToken_NoMatchingProvider2316=== PAUSE TestValidateToken_NoMatchingProvider2317=== RUN TestValidateToken_KubernetesServiceAccount2318=== PAUSE TestValidateToken_KubernetesServiceAccount2319=== RUN TestNewValidator_KubernetesRequiresCA2320=== PAUSE TestNewValidator_KubernetesRequiresCA2321=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2322=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2323=== RUN TestPins_ReservedForMatchingRule2324=== PAUSE TestPins_ReservedForMatchingRule2325=== RUN TestPins_TopLevelShorthand2326=== PAUSE TestPins_TopLevelShorthand2327=== RUN TestPins_ConfigValidation2328=== PAUSE TestPins_ConfigValidation2329=== RUN TestScopes_LegacyProviderDefaultsToWrite2330=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2331=== RUN TestScopes_Rules2332=== PAUSE TestScopes_Rules2333=== RUN TestScopes_ConfigValidation2334=== PAUSE TestScopes_ConfigValidation2335=== CONT TestAudienceForIssuer2336=== CONT TestValidateToken_KubernetesServiceAccount2337--- PASS: TestAudienceForIssuer (0.00s)2338=== CONT TestValidateToken_Expired2339=== CONT TestValidateToken_WrongAudience2340=== CONT TestValidateToken_ValidToken2341=== CONT TestGlobMatch2342=== RUN TestGlobMatch/foo_foo2343=== PAUSE TestGlobMatch/foo_foo2344=== RUN TestGlobMatch/foo_bar2345=== PAUSE TestGlobMatch/foo_bar2346=== RUN TestGlobMatch/*_2347=== PAUSE TestGlobMatch/*_2348=== RUN TestGlobMatch/*_anything2349=== PAUSE TestGlobMatch/*_anything2350=== RUN TestGlobMatch/foo*_foo2351=== PAUSE TestGlobMatch/foo*_foo2352=== RUN TestGlobMatch/foo*_foobar2353=== PAUSE TestGlobMatch/foo*_foobar2354=== RUN TestGlobMatch/foo*_bar2355=== PAUSE TestGlobMatch/foo*_bar2356=== RUN TestGlobMatch/*bar_bar2357=== PAUSE TestGlobMatch/*bar_bar2358=== RUN TestGlobMatch/*bar_foobar2359=== PAUSE TestGlobMatch/*bar_foobar2360=== RUN TestGlobMatch/*bar_foo2361=== PAUSE TestGlobMatch/*bar_foo2362=== RUN TestGlobMatch/foo*bar_foobar2363=== PAUSE TestGlobMatch/foo*bar_foobar2364=== RUN TestGlobMatch/foo*bar_foo123bar2365=== PAUSE TestGlobMatch/foo*bar_foo123bar2366=== RUN TestGlobMatch/foo*bar_foobarbaz2367=== PAUSE TestGlobMatch/foo*bar_foobarbaz2368=== RUN TestGlobMatch/*/*_foo/bar2369=== PAUSE TestGlobMatch/*/*_foo/bar2370=== RUN TestGlobMatch/*/*_foo2371=== PAUSE TestGlobMatch/*/*_foo2372=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2373=== CONT TestPins_ReservedForMatchingRule2374=== CONT TestPins_TopLevelShorthand2375=== CONT TestValidateToken_MultipleProviders2376=== CONT TestValidateToken_NoMatchingProvider2377=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2378=== CONT TestScopes_Rules2379=== CONT TestScopes_ConfigValidation2380=== CONT TestPins_ConfigValidation2381=== CONT TestValidateToken_BoundSubjectMismatch2382=== CONT TestScopes_LegacyProviderDefaultsToWrite2383=== CONT TestNewValidator_KubernetesRequiresCA2384=== CONT TestValidateToken_BoundClaimsMismatch2385--- PASS: TestScopes_ConfigValidation (0.00s)2386=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2387=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02388=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02389=== RUN TestGlobMatch/refs/*/main_refs/heads/main2390=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2391=== RUN TestGlobMatch/fo?_foo2392=== PAUSE TestGlobMatch/fo?_foo2393=== RUN TestGlobMatch/fo?_fo2394=== PAUSE TestGlobMatch/fo?_fo2395=== RUN TestGlobMatch/fo?_fooo2396=== PAUSE TestGlobMatch/fo?_fooo2397=== RUN TestGlobMatch/?oo_foo2398=== PAUSE TestGlobMatch/?oo_foo2399=== RUN TestGlobMatch/?oo_boo2400=== PAUSE TestGlobMatch/?oo_boo2401=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2402=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2403=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2404=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2405=== CONT TestGlobMatch/foo_foo2406=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2407=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2408=== CONT TestGlobMatch/foo*bar_foo123bar2409=== CONT TestGlobMatch/foo*bar_foobar2410=== CONT TestGlobMatch/*bar_foo2411=== CONT TestGlobMatch/*bar_foobar2412=== CONT TestGlobMatch/*bar_bar2413=== CONT TestGlobMatch/foo*_bar2414=== CONT TestGlobMatch/foo*_foobar2415=== CONT TestGlobMatch/foo*_foo2416=== CONT TestGlobMatch/fo?_fooo2417=== CONT TestGlobMatch/fo?_foo2418=== CONT TestGlobMatch/refs/*/main_refs/heads/main2419=== CONT TestGlobMatch/*/*_foo2420=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2421=== CONT TestGlobMatch/*/*_foo/bar2422=== CONT TestGlobMatch/?oo_boo2423=== CONT TestGlobMatch/?oo_foo2424=== CONT TestGlobMatch/foo*bar_foobarbaz2425=== CONT TestGlobMatch/*_anything2426=== CONT TestGlobMatch/*_2427=== CONT TestGlobMatch/foo_bar2428=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02429=== CONT TestGlobMatch/fo?_fo2430--- PASS: TestGlobMatch (0.01s)2431 --- PASS: TestGlobMatch/foo_foo (0.00s)2432 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2433 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2434 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2435 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2436 --- PASS: TestGlobMatch/*bar_foo (0.00s)2437 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2438 --- PASS: TestGlobMatch/*bar_bar (0.00s)2439 --- PASS: TestGlobMatch/foo*_bar (0.00s)2440 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2441 --- PASS: TestGlobMatch/foo*_foo (0.00s)2442 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2443 --- PASS: TestGlobMatch/fo?_foo (0.00s)2444 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2445 --- PASS: TestGlobMatch/*/*_foo (0.00s)2446 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2447 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2448 --- PASS: TestGlobMatch/?oo_boo (0.00s)2449 --- PASS: TestGlobMatch/?oo_foo (0.00s)2450 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2451 --- PASS: TestGlobMatch/*_anything (0.00s)2452 --- PASS: TestGlobMatch/*_ (0.00s)2453 --- PASS: TestGlobMatch/foo_bar (0.00s)2454 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2455 --- PASS: TestGlobMatch/fo?_fo (0.00s)2456--- PASS: TestPins_ConfigValidation (0.00s)24572026/11/09 11:53:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38517/oidc24582026/11/09 11:53:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35045/oidc2459--- PASS: TestPins_ReservedForMatchingRule (0.03s)2460--- PASS: TestScopes_Rules (0.03s)24612026/11/09 11:53:02 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:331652462--- PASS: TestValidateToken_KubernetesServiceAccount (0.05s)24632026/11/09 11:53:02 http: TLS handshake error from 127.0.0.1:46922: remote error: tls: bad certificate24642026/11/09 11:53:02 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232465--- PASS: TestNewValidator_KubernetesRequiresCA (0.04s)24662026/11/09 11:53:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36081/oidc24672026/11/09 11:53:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41019/oidc24682026/11/09 11:53:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38263/oidc2469--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.05s)2470--- PASS: TestValidateToken_ValidToken (0.05s)2471--- PASS: TestPins_TopLevelShorthand (0.05s)2472--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.05s)24732026/11/09 11:53:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40653/oidc2474--- PASS: TestValidateToken_WrongAudience (0.06s)24752026/11/09 11:53:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43999/oidc2476--- PASS: TestValidateToken_BoundClaimsMismatch (0.06s)24772026/11/09 11:53:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37571/oidc2478--- PASS: TestValidateToken_Expired (0.07s)24792026/11/09 11:53:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38779/oidc2480--- PASS: TestValidateToken_BoundSubjectMismatch (0.07s)24812026/11/09 11:53:02 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:36009/oidc24822026/11/09 11:53:02 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:38505/oidc2483--- PASS: TestValidateToken_MultipleProviders (0.15s)24842026/11/09 11:53:02 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:36759/oidc2485--- PASS: TestValidateToken_NoMatchingProvider (0.21s)2486PASS2487Running hook tests...2488=== RUN TestSendPathsEmpty2489=== PAUSE TestSendPathsEmpty2490=== RUN TestQueueEnqueueAndFetch2491=== PAUSE TestQueueEnqueueAndFetch2492=== RUN TestQueueDeduplication2493=== PAUSE TestQueueDeduplication2494=== RUN TestQueueRemove2495=== PAUSE TestQueueRemove2496=== RUN TestQueueFetchBatchLimit2497=== PAUSE TestQueueFetchBatchLimit2498=== RUN TestQueueRetryMovesToBack2499=== PAUSE TestQueueRetryMovesToBack2500=== RUN TestQueueFetchRemoveLifecycle2501=== PAUSE TestQueueFetchRemoveLifecycle2502=== RUN TestQueueConcurrentWriters2503=== PAUSE TestQueueConcurrentWriters2504=== RUN TestQueueRemoveLargeClosure2505=== PAUSE TestQueueRemoveLargeClosure2506=== RUN TestServerClientIntegration2507--- PASS: TestServerClientIntegration (0.00s)2508=== RUN TestServerQueueError25092026/11/09 11:53:02 ERROR Failed to queue paths error="permission denied" count=12510--- PASS: TestServerQueueError (0.00s)2511=== RUN TestGetListenerSocketActivation2512 server_test.go:218: === RUN TestGetListenerSocketActivation2513 --- PASS: TestGetListenerSocketActivation (0.00s)2514 PASS2515 2516--- PASS: TestGetListenerSocketActivation (0.01s)2517=== RUN TestServerStalledClientDoesNotBlockShutdown2518=== PAUSE TestServerStalledClientDoesNotBlockShutdown2519=== RUN TestServerBacksOffOnAcceptErrors2520=== PAUSE TestServerBacksOffOnAcceptErrors2521=== RUN TestDrainIsolatesPoisonPath2522=== PAUSE TestDrainIsolatesPoisonPath2523=== RUN TestRunNotBlockedByPoisonHead2524=== PAUSE TestRunNotBlockedByPoisonHead2525=== RUN TestDrainGivesUpWhenServerDown2526=== PAUSE TestDrainGivesUpWhenServerDown2527=== RUN TestFailedPathPrunedByLaterClosure2528=== PAUSE TestFailedPathPrunedByLaterClosure2529=== RUN TestWorkerUploadsAndRemoves2530=== PAUSE TestWorkerUploadsAndRemoves2531=== RUN TestWorkerSkipsGCdPaths2532=== PAUSE TestWorkerSkipsGCdPaths2533=== RUN TestWorkerPrunesClosureDeps2534=== PAUSE TestWorkerPrunesClosureDeps2535=== RUN TestDrainTimeout2536=== PAUSE TestDrainTimeout2537=== RUN TestWorkerRemoveFailureIsNotProgress2538=== PAUSE TestWorkerRemoveFailureIsNotProgress2539=== RUN TestWorkerKeepsPathItCannotStat2540=== PAUSE TestWorkerKeepsPathItCannotStat2541=== CONT TestSendPathsEmpty2542=== CONT TestQueueRemove2543=== CONT TestDrainIsolatesPoisonPath2544=== CONT TestWorkerKeepsPathItCannotStat2545=== CONT TestWorkerRemoveFailureIsNotProgress2546=== CONT TestDrainTimeout2547=== CONT TestWorkerPrunesClosureDeps2548=== CONT TestWorkerSkipsGCdPaths2549=== CONT TestWorkerUploadsAndRemoves2550=== CONT TestFailedPathPrunedByLaterClosure2551=== CONT TestQueueFetchRemoveLifecycle2552=== CONT TestDrainGivesUpWhenServerDown2553=== CONT TestServerBacksOffOnAcceptErrors2554=== CONT TestServerStalledClientDoesNotBlockShutdown25552026/11/09 11:53:02 ERROR Accept failed error="too many open files"2556=== CONT TestRunNotBlockedByPoisonHead2557=== CONT TestQueueConcurrentWriters2558--- PASS: TestSendPathsEmpty (0.00s)2559=== CONT TestQueueDeduplication2560=== CONT TestQueueEnqueueAndFetch2561=== CONT TestQueueRetryMovesToBack2562=== CONT TestQueueFetchBatchLimit2563=== CONT TestQueueRemoveLargeClosure25642026/11/09 11:53:02 ERROR Accept failed error="too many open files"25652026/11/09 11:53:02 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat871828866/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat871828866/002/locked/aaa: permission denied"25662026/11/09 11:53:02 INFO Uploading batch count=425672026/11/09 11:53:02 ERROR Upload failed error="upload failed" count=425682026/11/09 11:53:02 INFO Upload queue status pending=225692026/11/09 11:53:02 INFO Upload queue status pending=225702026/11/09 11:53:02 INFO Uploading batch count=125712026/11/09 11:53:02 INFO Upload queue status pending=325722026/11/09 11:53:02 INFO Uploading batch count=225732026/11/09 11:53:02 ERROR Upload failed error="upload failed" count=225742026/11/09 11:53:02 INFO Uploading batch count=125752026/11/09 11:53:02 ERROR Upload failed error="upload failed" count=125762026/11/09 11:53:02 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4292939061/002/a25772026/11/09 11:53:02 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat871828866/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat871828866/002/locked/aaa: permission denied"25782026/11/09 11:53:02 INFO Upload queue status pending=225792026/11/09 11:53:02 INFO Uploading batch count=225802026/11/09 11:53:02 INFO Uploading batch count=125812026/11/09 11:53:02 ERROR Upload failed error="upload failed" count=125822026/11/09 11:53:02 INFO Uploading batch count=225832026/11/09 11:53:02 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath2287278449/002/bbb25842026/11/09 11:53:02 ERROR Accept failed error="too many open files"25852026/11/09 11:53:02 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths3814089534/002/nonexistent2586--- PASS: TestQueueDeduplication (0.02s)25872026/11/09 11:53:02 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress1683055490/002/nonexistent25882026/11/09 11:53:02 INFO Uploading batch count=12589--- PASS: TestQueueEnqueueAndFetch (0.02s)25902026/11/09 11:53:02 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12591--- PASS: TestQueueFetchBatchLimit (0.02s)25922026/11/09 11:53:02 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat871828866/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat871828866/002/locked/aaa: permission denied"25932026/11/09 11:53:02 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4292939061/002/b25942026/11/09 11:53:02 INFO Uploading batch count=125952026/11/09 11:53:02 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress1683055490/002/nonexistent25962026/11/09 11:53:02 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125972026/11/09 11:53:02 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress1683055490/002/nonexistent25982026/11/09 11:53:02 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12599--- PASS: TestQueueFetchRemoveLifecycle (0.02s)26002026/11/09 11:53:02 ERROR Drain finished with paths left in queue remaining=12601--- PASS: TestQueueRemove (0.02s)26022026/11/09 11:53:02 INFO Uploading batch count=12603--- PASS: TestQueueRetryMovesToBack (0.02s)26042026/11/09 11:53:02 INFO Uploading batch count=226052026/11/09 11:53:02 ERROR Upload failed error="upload failed" count=226062026/11/09 11:53:02 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4292939061/002/c26072026/11/09 11:53:02 ERROR Drain finished with paths left in queue remaining=126082026/11/09 11:53:02 INFO Uploading batch count=126092026/11/09 11:53:02 ERROR Upload failed error="upload failed" count=12610--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)26112026/11/09 11:53:02 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4292939061/002/d26122026/11/09 11:53:02 INFO Uploading batch count=126132026/11/09 11:53:02 ERROR Upload failed error="upload failed" count=126142026/11/09 11:53:02 INFO Uploading batch count=226152026/11/09 11:53:02 ERROR Upload failed error="upload failed" count=226162026/11/09 11:53:02 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4292939061/002/e2617--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)26182026/11/09 11:53:02 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4292939061/002/f26192026/11/09 11:53:02 INFO Uploading batch count=12620--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)26212026/11/09 11:53:02 ERROR Upload failed error="upload failed" count=126222026/11/09 11:53:02 ERROR Drain finished with paths left in queue remaining=1026232026/11/09 11:53:02 ERROR Drain finished with paths left in queue remaining=12624--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2625--- PASS: TestDrainIsolatesPoisonPath (0.03s)2626--- PASS: TestWorkerPrunesClosureDeps (0.04s)2627--- PASS: TestWorkerSkipsGCdPaths (0.04s)2628--- PASS: TestWorkerUploadsAndRemoves (0.04s)26292026/11/09 11:53:02 ERROR Accept failed error="too many open files"2630--- PASS: TestQueueRemoveLargeClosure (0.05s)26312026/11/09 11:53:02 ERROR Accept failed error="too many open files"26322026/11/09 11:53:02 ERROR Accept failed error="too many open files"2633--- PASS: TestQueueConcurrentWriters (0.16s)26342026/11/09 11:53:02 ERROR Failed to decode request error="read unix /build/hook2170945535/test.sock->@: i/o timeout"26352026/11/09 11:53:02 ERROR Failed to write response error="write unix /build/hook2170945535/test.sock->@: i/o timeout"2636--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26372026/11/09 11:53:02 ERROR Upload failed error="context deadline exceeded" count=226382026/11/09 11:53:02 ERROR Drain finished with paths left in queue remaining=42639--- PASS: TestDrainTimeout (0.22s)26402026/11/09 11:53:02 ERROR Accept failed error="too many open files"26412026/11/09 11:53:03 ERROR Accept failed error="too many open files"2642--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26432026/11/09 11:53:03 INFO Uploading batch count=126442026/11/09 11:53:03 INFO Uploading batch count=126452026/11/09 11:53:03 INFO Uploading batch count=126462026/11/09 11:53:03 ERROR Upload failed error="upload failed" count=126472026/11/09 11:53:03 INFO Uploading batch count=126482026/11/09 11:53:03 ERROR Upload failed error="upload failed" count=126492026/11/09 11:53:03 INFO Uploading batch count=126502026/11/09 11:53:03 ERROR Upload failed error="upload failed" count=126512026/11/09 11:53:03 INFO Uploading batch count=126522026/11/09 11:53:03 ERROR Upload failed error="upload failed" count=126532026/11/09 11:53:03 ERROR Drain finished with paths left in queue remaining=12654--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2655PASS2656Running signing tests...2657=== RUN TestExternalSigner2658=== PAUSE TestExternalSigner2659=== RUN TestExternalSignerWrongPublicKey2660=== PAUSE TestExternalSignerWrongPublicKey2661=== RUN TestExternalSignerErrors2662=== PAUSE TestExternalSignerErrors2663=== RUN TestExternalSignerRestartsAfterCrash2664=== PAUSE TestExternalSignerRestartsAfterCrash2665=== RUN TestExternalSignerProgramErrorKeepsProcess2666=== PAUSE TestExternalSignerProgramErrorKeepsProcess2667=== RUN TestExternalSignerClose2668=== PAUSE TestExternalSignerClose2669=== RUN TestExternalSignerRejectsInvalidPublicKey2670=== PAUSE TestExternalSignerRejectsInvalidPublicKey2671=== RUN TestExternalSignerCancellation2672=== PAUSE TestExternalSignerCancellation2673=== RUN TestGenerateFingerprint2674=== PAUSE TestGenerateFingerprint2675=== RUN TestParseSigningKey2676=== PAUSE TestParseSigningKey2677=== RUN TestSign2678=== PAUSE TestSign2679=== RUN TestSignBatch2680=== PAUSE TestSignBatch2681=== RUN TestNilKeyPublicKey2682=== PAUSE TestNilKeyPublicKey2683=== RUN TestSignErrors2684=== PAUSE TestSignErrors2685=== CONT TestExternalSigner2686=== CONT TestExternalSignerCancellation2687=== CONT TestExternalSignerProgramErrorKeepsProcess2688=== CONT TestExternalSignerRejectsInvalidPublicKey2689=== CONT TestExternalSignerClose2690=== CONT TestExternalSignerRestartsAfterCrash2691=== CONT TestExternalSignerWrongPublicKey2692=== CONT TestSign2693=== CONT TestNilKeyPublicKey2694--- PASS: TestNilKeyPublicKey (0.00s)2695=== CONT TestSignBatch2696=== CONT TestSignErrors2697=== CONT TestParseSigningKey2698=== CONT TestGenerateFingerprint2699=== CONT TestExternalSignerErrors2700=== RUN TestExternalSignerRejectsInvalidPublicKey/#002701=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002702=== RUN TestGenerateFingerprint/basic_with_references2703=== PAUSE TestGenerateFingerprint/basic_with_references2704=== RUN TestGenerateFingerprint/no_references2705=== PAUSE TestGenerateFingerprint/no_references2706=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2707=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2708=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2709=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2710=== RUN TestParseSigningKey/valid_32-byte_key2711=== PAUSE TestParseSigningKey/valid_32-byte_key2712=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2713=== RUN TestExternalSignerErrors/wrong_shape2714=== PAUSE TestExternalSignerErrors/wrong_shape2715=== RUN TestGenerateFingerprint/invalid_nar_hash_length2716=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2717--- PASS: TestSign (0.00s)2718=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2719=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2720=== RUN TestParseSigningKey/no_colon2721=== PAUSE TestParseSigningKey/no_colon2722--- PASS: TestSignBatch (0.00s)2723=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2724=== RUN TestSignErrors/nil_key2725=== PAUSE TestSignErrors/nil_key2726=== RUN TestSignErrors/nil_narinfo2727=== PAUSE TestSignErrors/nil_narinfo2728=== RUN TestSignErrors/invalid_narinfo2729=== PAUSE TestSignErrors/invalid_narinfo2730=== RUN TestSignErrors/canceled2731=== PAUSE TestSignErrors/canceled2732=== CONT TestSignErrors/nil_key2733=== RUN TestExternalSignerErrors/missing_signatures2734=== PAUSE TestExternalSignerErrors/missing_signatures2735=== RUN TestExternalSignerErrors/too_few_signatures2736=== CONT TestSignErrors/canceled2737=== RUN TestGenerateFingerprint/invalid_store_path_prefix2738=== RUN TestParseSigningKey/empty_name2739=== PAUSE TestParseSigningKey/empty_name2740=== RUN TestParseSigningKey/invalid_base642741=== PAUSE TestParseSigningKey/invalid_base642742=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2743=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2744=== CONT TestSignErrors/invalid_narinfo2745=== CONT TestSignErrors/nil_narinfo2746--- PASS: TestSignErrors (0.00s)2747 --- PASS: TestSignErrors/nil_key (0.00s)2748 --- PASS: TestSignErrors/canceled (0.00s)2749 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2750 --- PASS: TestSignErrors/nil_narinfo (0.00s)2751=== PAUSE TestExternalSignerErrors/too_few_signatures2752=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2753=== RUN TestParseSigningKey/wrong_length2754=== PAUSE TestParseSigningKey/wrong_length2755=== CONT TestParseSigningKey/valid_32-byte_key2756=== CONT TestParseSigningKey/invalid_base642757=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2758=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2759=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2760=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2761=== CONT TestExternalSignerRejectsInvalidPublicKey/#002762=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2763=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2764=== RUN TestExternalSignerErrors/exit_at_startup2765=== PAUSE TestExternalSignerErrors/exit_at_startup2766=== RUN TestExternalSignerErrors/null2767=== PAUSE TestExternalSignerErrors/null2768=== RUN TestExternalSignerErrors/invalid_signature_base642769=== PAUSE TestExternalSignerErrors/invalid_signature_base642770=== RUN TestExternalSignerErrors/program_error2771=== PAUSE TestExternalSignerErrors/program_error2772=== RUN TestExternalSignerErrors/null_signatures2773=== PAUSE TestExternalSignerErrors/null_signatures2774=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2775=== RUN TestGenerateFingerprint/invalid_reference_prefix2776=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2777=== CONT TestParseSigningKey/no_colon2778=== CONT TestParseSigningKey/empty_name2779=== CONT TestParseSigningKey/wrong_length2780=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2781=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2782=== RUN TestExternalSignerErrors/wrong_signatures_shape2783=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2784=== RUN TestExternalSignerErrors/missing_signature_name2785=== CONT TestGenerateFingerprint/basic_with_references2786=== CONT TestGenerateFingerprint/invalid_reference_prefix2787=== CONT TestGenerateFingerprint/invalid_store_path_prefix2788=== CONT TestGenerateFingerprint/invalid_nar_hash_length2789=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2790=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2791=== CONT TestGenerateFingerprint/no_references2792--- PASS: TestExternalSignerWrongPublicKey (0.00s)2793--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.01s)2794--- PASS: TestParseSigningKey (0.00s)2795 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2796 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2797 --- PASS: TestParseSigningKey/no_colon (0.00s)2798 --- PASS: TestParseSigningKey/empty_name (0.00s)2799 --- PASS: TestParseSigningKey/wrong_length (0.00s)2800 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2801=== PAUSE TestExternalSignerErrors/missing_signature_name2802=== RUN TestExternalSignerErrors/wrong_signature_name2803--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2804 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2805 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2806 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2807 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2808 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2809=== PAUSE TestExternalSignerErrors/wrong_signature_name2810=== RUN TestExternalSignerErrors/exit_on_request2811=== PAUSE TestExternalSignerErrors/exit_on_request2812=== RUN TestExternalSignerErrors/invalid_JSON2813=== PAUSE TestExternalSignerErrors/invalid_JSON2814--- PASS: TestExternalSignerClose (0.00s)2815=== RUN TestExternalSignerErrors/wrong_id2816=== PAUSE TestExternalSignerErrors/wrong_id2817=== RUN TestExternalSignerErrors/unrequested_key2818=== PAUSE TestExternalSignerErrors/unrequested_key2819=== RUN TestExternalSignerErrors/wrong_signature_length2820=== PAUSE TestExternalSignerErrors/wrong_signature_length2821--- PASS: TestGenerateFingerprint (0.00s)2822 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2823 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2824 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2825 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2826 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2827 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2828 --- PASS: TestGenerateFingerprint/no_references (0.00s)2829=== CONT TestExternalSignerErrors/wrong_shape2830=== CONT TestExternalSignerErrors/wrong_signature_length2831=== CONT TestExternalSignerErrors/unrequested_key2832=== CONT TestExternalSignerErrors/wrong_id2833=== CONT TestExternalSignerErrors/program_error2834=== CONT TestExternalSignerErrors/invalid_signature_base642835=== CONT TestExternalSignerErrors/null_signatures2836=== CONT TestExternalSignerErrors/null2837=== CONT TestExternalSignerErrors/invalid_JSON2838=== CONT TestExternalSignerErrors/exit_at_startup2839=== CONT TestExternalSignerErrors/exit_on_request2840=== CONT TestExternalSignerErrors/too_few_signatures2841=== CONT TestExternalSignerErrors/wrong_signature_name2842=== CONT TestExternalSignerErrors/missing_signatures2843=== CONT TestExternalSignerErrors/missing_signature_name2844=== CONT TestExternalSignerErrors/wrong_signatures_shape2845--- PASS: TestExternalSigner (0.01s)2846--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2847--- PASS: TestExternalSignerErrors (0.00s)2848 --- PASS: TestExternalSignerErrors/wrong_shape (0.00s)2849 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.00s)2850 --- PASS: TestExternalSignerErrors/exit_at_startup (0.00s)2851 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)2852 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)2853 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2854 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)2855 --- PASS: TestExternalSignerErrors/unrequested_key (0.01s)2856 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)2857 --- PASS: TestExternalSignerErrors/exit_on_request (0.01s)2858 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)2859 --- PASS: TestExternalSignerErrors/too_few_signatures (0.01s)2860 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)2861 --- PASS: TestExternalSignerErrors/null (0.01s)2862 --- PASS: TestExternalSignerErrors/program_error (0.01s)2863 --- PASS: TestExternalSignerErrors/missing_signatures (0.01s)2864--- PASS: TestExternalSignerCancellation (0.02s)2865PASS2866Running OpenBao signer tests...2867=== RUN TestSign2868=== PAUSE TestSign2869=== RUN TestSignErrors2870=== PAUSE TestSignErrors2871=== RUN TestServe2872=== PAUSE TestServe2873=== RUN TestServeRejectsGarbage2874=== PAUSE TestServeRejectsGarbage2875=== CONT TestSign2876=== CONT TestServe2877=== CONT TestSignErrors2878=== CONT TestServeRejectsGarbage2879=== RUN TestSignErrors/http_error2880=== PAUSE TestSignErrors/http_error2881--- PASS: TestServeRejectsGarbage (0.00s)2882--- PASS: TestServe (0.00s)2883=== RUN TestSignErrors/invalid_json2884=== PAUSE TestSignErrors/invalid_json2885=== RUN TestSignErrors/no_prefix2886=== PAUSE TestSignErrors/no_prefix2887=== RUN TestSignErrors/invalid_base642888=== PAUSE TestSignErrors/invalid_base642889=== CONT TestSignErrors/http_error2890=== CONT TestSignErrors/no_prefix2891=== CONT TestSignErrors/invalid_base642892=== CONT TestSignErrors/invalid_json2893--- PASS: TestSign (0.00s)2894--- PASS: TestSignErrors (0.00s)2895 --- PASS: TestSignErrors/no_prefix (0.00s)2896 --- PASS: TestSignErrors/http_error (0.00s)2897 --- PASS: TestSignErrors/invalid_base64 (0.00s)2898 --- PASS: TestSignErrors/invalid_json (0.00s)2899PASS