niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #473
· raw
1tribuchet: building on eliza2Running 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.03s)25=== RUN TestDumpPathCaseHackCollision26--- PASS: TestDumpPathCaseHackCollision (0.00s)27=== RUN TestDumpPathMatchesNix28=== PAUSE TestDumpPathMatchesNix29=== RUN TestDumpPathSingleFile30=== PAUSE TestDumpPathSingleFile31=== RUN TestDumpPathWriterError32=== PAUSE TestDumpPathWriterError33=== RUN TestEncodeNixBase3234=== PAUSE TestEncodeNixBase3235=== RUN TestEncodeNixBase32WithRealHash36=== PAUSE TestEncodeNixBase32WithRealHash37=== RUN TestConvertHashToNix3238=== PAUSE TestConvertHashToNix3239=== RUN TestGetStorePathHash40=== PAUSE TestGetStorePathHash41=== RUN TestPathInfoHashCompatibility42=== PAUSE TestPathInfoHashCompatibility43=== RUN TestParsePathInfoJSON44=== PAUSE TestParsePathInfoJSON45=== RUN TestParsePathInfoJSONMultiplePaths46=== PAUSE TestParsePathInfoJSONMultiplePaths47=== RUN TestPathInfoCACompatibility48=== PAUSE TestPathInfoCACompatibility49=== RUN TestRateLimiterFeedback50=== PAUSE TestRateLimiterFeedback51=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess52=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess53=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer54=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer55=== RUN TestRegisterUploadedObject_OutlivesPush56=== PAUSE TestRegisterUploadedObject_OutlivesPush57=== RUN TestResolveStorePath58=== PAUSE TestResolveStorePath59=== RUN TestDoWithRetry_BodyReplayedViaGetBody60=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody61=== RUN TestRetryTimeoutOutlastsMaxRetries62=== PAUSE TestRetryTimeoutOutlastsMaxRetries63=== RUN TestDoWithRetry_FinalResponseBodyReadable64=== PAUSE TestDoWithRetry_FinalResponseBodyReadable65=== RUN TestShellSplit66=== PAUSE TestShellSplit67=== RUN TestShellSplitErrors68=== PAUSE TestShellSplitErrors69=== RUN TestStreamPushReportsEveryPath70=== PAUSE TestStreamPushReportsEveryPath71=== RUN TestStreamPushBatchesUnderLoad72=== PAUSE TestStreamPushBatchesUnderLoad73=== RUN TestStreamPushIsolatesFailures74=== PAUSE TestStreamPushIsolatesFailures75=== RUN TestStreamPushGivesUpOnDeadServer76=== PAUSE TestStreamPushGivesUpOnDeadServer77=== RUN TestStreamPushRequestLine78=== PAUSE TestStreamPushRequestLine79=== RUN TestStreamPushReportsSignatures80=== PAUSE TestStreamPushReportsSignatures81=== RUN TestStreamPushReportsSkippedPaths82=== PAUSE TestStreamPushReportsSkippedPaths83=== RUN TestClientSignaturesByStorePath84=== PAUSE TestClientSignaturesByStorePath85=== RUN TestStreamPushStopsWhenCanceled86=== PAUSE TestStreamPushStopsWhenCanceled87=== RUN TestSetClientTLS88=== PAUSE TestSetClientTLS89=== RUN TestSetClientTLSDoesNotMutateDefaultTransport90=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport91=== RUN TestSetClientTLSErrors92=== PAUSE TestSetClientTLSErrors93=== RUN TestStaticToken94=== PAUSE TestStaticToken95=== RUN TestFileTokenReadsAndCaches96=== PAUSE TestFileTokenReadsAndCaches97=== RUN TestFileTokenMissing98=== PAUSE TestFileTokenMissing99=== RUN TestFileTokenEmpty100=== PAUSE TestFileTokenEmpty101=== RUN TestScriptTokenNoExpiryRerunsEveryCall102=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall103=== RUN TestScriptTokenCachesUntilRefresh104=== PAUSE TestScriptTokenCachesUntilRefresh105=== RUN TestScriptTokenEmptyToken106=== PAUSE TestScriptTokenEmptyToken107=== RUN TestScriptTokenBadJSON108=== PAUSE TestScriptTokenBadJSON109=== RUN TestScriptTokenScriptFails110=== PAUSE TestScriptTokenScriptFails111=== RUN TestScriptTokenEmptyCommand112=== PAUSE TestScriptTokenEmptyCommand113=== CONT TestDoServerRequestAttachesToken114=== CONT TestRetryTimeoutOutlastsMaxRetries115=== CONT TestSetClientTLS116=== CONT TestFileTokenEmpty117=== CONT TestFileTokenMissing118=== CONT TestFileTokenReadsAndCaches119--- PASS: TestFileTokenEmpty (0.00s)120=== CONT TestPathInfoHashCompatibility121=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)122=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)123=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon124=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon125=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI126=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI127=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512128=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512129--- PASS: TestFileTokenMissing (0.00s)130=== CONT TestSetClientTLSErrors131--- PASS: TestFileTokenReadsAndCaches (0.00s)132=== CONT TestScriptTokenCachesUntilRefresh133=== CONT TestStaticToken134=== CONT TestEncodeNixBase32WithRealHash135=== CONT TestStreamPushStopsWhenCanceled136=== CONT TestDoWithRetry_BodyReplayedViaGetBody137=== CONT TestResolveStorePath138=== CONT TestScriptTokenNoExpiryRerunsEveryCall1392026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:46777140=== CONT TestRegisterUploadedObject_OutlivesPush141=== CONT TestScriptTokenEmptyCommand142=== CONT TestDumpPathSingleFile143=== CONT TestStreamPushReportsSkippedPaths144=== RUN TestSetClientTLSErrors/missing_cert_file145=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer146=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess147=== CONT TestScriptTokenScriptFails148=== CONT TestRateLimiterFeedback149=== CONT TestPathInfoCACompatibility150=== CONT TestScriptTokenBadJSON151=== CONT TestParsePathInfoJSONMultiplePaths152=== CONT TestParsePathInfoJSON153=== CONT TestScriptTokenEmptyToken154=== CONT TestGetStorePathHash155=== CONT TestConvertHashToNix32156=== CONT TestSetClientTLSDoesNotMutateDefaultTransport157--- PASS: TestStaticToken (0.00s)158=== CONT TestStreamPushGivesUpOnDeadServer159=== CONT TestClientSignaturesByStorePath160=== CONT TestEncodeNixBase32161=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths162=== RUN TestEncodeNixBase32/test_string_hash1632026/11/09 12:09:53 WARN Rate limiter enabled after throttle name=server-test rate=51642026/11/09 12:09:53 WARN Rate limiter enabled after throttle name=server-test rate=51652026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:34287166--- PASS: TestEncodeNixBase32WithRealHash (0.00s)167=== PAUSE TestSetClientTLSErrors/missing_cert_file168=== PAUSE TestEncodeNixBase32/test_string_hash169=== RUN TestSetClientTLSErrors/missing_key_file170=== RUN TestRateLimiterFeedback/429_enables_limiter171=== PAUSE TestSetClientTLSErrors/missing_key_file172=== RUN TestParsePathInfoJSON/Nix_format1732026/11/09 12:09:53 ERROR Upload failed error="connection refused" count=20174=== PAUSE TestParsePathInfoJSON/Nix_format1752026/11/09 12:09:53 ERROR Server seems unavailable, giving up on batch untried=17176=== RUN TestParsePathInfoJSON/Lix_format177=== RUN TestGetStorePathHash/valid_store_path178=== RUN TestConvertHashToNix32/SRI_format_to_Nix32179=== CONT TestStreamPushReportsSignatures180=== CONT TestDumpPathWriterError181=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths182--- PASS: TestStreamPushStopsWhenCanceled (0.00s)183=== RUN TestPathInfoCACompatibility/null_ca_field184=== RUN TestEncodeNixBase32/empty_input185=== PAUSE TestEncodeNixBase32/empty_input1862026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:46777187=== CONT TestPartSizeForNAR1882026/11/09 12:09:53 WARN Rate limiter backed off name=server-test rate=5189=== RUN TestPartSizeForNAR/zero_stays_at_minimum1902026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:342871912026/11/09 12:09:53 ERROR Upload failed error=boom count=1192--- PASS: TestScriptTokenEmptyCommand (0.00s)193=== PAUSE TestPathInfoCACompatibility/null_ca_field194=== RUN TestSetClientTLSErrors/missing_ca_file195=== PAUSE TestParsePathInfoJSON/Lix_format196=== PAUSE TestGetStorePathHash/valid_store_path197=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32198=== CONT TestStreamPushRequestLine199=== PAUSE TestRateLimiterFeedback/429_enables_limiter200=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths201=== RUN TestSetClientTLS/rejects_connection_without_client_cert202=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun203=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum204=== CONT TestDumpPathMatchesNix205--- PASS: TestDoServerRequestAttachesToken (0.00s)206=== RUN TestPathInfoCACompatibility/old_string_format_-_text207--- PASS: TestResolveStorePath (0.00s)208--- PASS: TestStreamPushReportsSkippedPaths (0.00s)209--- PASS: TestClientSignaturesByStorePath (0.00s)210--- PASS: TestScriptTokenScriptFails (0.00s)211--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)212--- PASS: TestRegisterUploadedObject_OutlivesPush (0.00s)213--- PASS: TestStreamPushReportsSignatures (0.00s)214--- PASS: TestScriptTokenBadJSON (0.00s)215--- PASS: TestScriptTokenEmptyToken (0.00s)216=== CONT TestFilterOversizedClosures217=== RUN TestFilterOversizedClosures/no_limit_keeps_everything218=== PAUSE TestSetClientTLSErrors/missing_ca_file219=== RUN TestRateLimiterFeedback/503_enables_limiter220=== RUN TestSetClientTLSErrors/invalid_ca_file221=== PAUSE TestSetClientTLSErrors/invalid_ca_file222=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything223=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped224=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2252026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:46777226=== RUN TestFilterOversizedClosures/all_closures_skipped227=== PAUSE TestRateLimiterFeedback/503_enables_limiter228=== RUN TestGetStorePathHash/basename_without_hyphen_should_error229=== CONT TestCaseHackSuffix230=== RUN TestConvertHashToNix32/already_Nix32_format231=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error232=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter233=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error234=== PAUSE TestConvertHashToNix32/already_Nix32_format235=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter236=== RUN TestConvertHashToNix32/invalid_format237=== CONT TestStreamPushIsolatesFailures2382026/11/09 12:09:53 ERROR Upload failed error=boom count=12392026/11/09 12:09:53 ERROR Upload failed error="bad path" count=3240=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert2412026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:46777242=== RUN TestPartSizeForNAR/small_stays_at_minimum243=== RUN TestParsePathInfoJSON/empty_input244=== PAUSE TestFilterOversizedClosures/all_closures_skipped245--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)246=== CONT TestStreamPushBatchesUnderLoad247=== CONT TestStreamPushReportsEveryPath248=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text249=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error250=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter251=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths252=== CONT TestUploadMultipart_ReturnsAfterDroppedBody253=== PAUSE TestConvertHashToNix32/invalid_format254=== CONT TestShellSplitErrors255=== CONT TestShellSplit256=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA257=== PAUSE TestPartSizeForNAR/small_stays_at_minimum258--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)259=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry260=== PAUSE TestParsePathInfoJSON/empty_input261--- PASS: TestScriptTokenCachesUntilRefresh (0.01s)262--- PASS: TestStreamPushIsolatesFailures (0.00s)263--- PASS: TestStreamPushReportsEveryPath (0.00s)264=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum265=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum266=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts267=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive2682026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:46777269=== CONT TestRegisterUploadedObjectReusesConnections270=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error271=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter272=== CONT TestDoWithRetry_FinalResponseBodyReadable273=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica274=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false275--- PASS: TestShellSplitErrors (0.00s)276--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.02s)277--- PASS: TestShellSplit (0.00s)278=== CONT TestUploadMultipart_PartsInParallel2792026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:46777280=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA281=== RUN TestSetClientTLS/preserves_debug_logging_transport282=== RUN TestParsePathInfoJSON/whitespace_only283=== PAUSE TestParsePathInfoJSON/whitespace_only284=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts285=== RUN TestPartSizeForNAR/1_TiB286=== PAUSE TestPartSizeForNAR/1_TiB287=== RUN TestPartSizeForNAR/5_TiB_S3_max_object2882026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:46777289=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object290=== RUN TestPartSizeForNAR/capped_at_5_GiB291=== PAUSE TestPartSizeForNAR/capped_at_5_GiB292=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)293=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive294=== CONT TestEncodeNixBase32/test_string_hash2952026/11/09 12:09:53 WARN Rate limiter enabled after throttle name=server-test rate=52962026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:467772972026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:399392982026/11/09 12:09:53 INFO Garbage collection started2992026/11/09 12:09:53 WARN Rate limiter backed off name=server-test rate=53002026/11/09 12:09:53 INFO Garbage collection started301=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512302=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI303=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error304=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false305=== PAUSE TestSetClientTLS/preserves_debug_logging_transport306=== RUN TestPathInfoCACompatibility/new_structured_format_-_text307=== RUN TestParsePathInfoJSON/invalid_JSON308=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon309--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.04s)310=== CONT TestEncodeNixBase32/empty_input311=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths3122026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:46777313=== CONT TestConvertHashToNix32/invalid_format314=== CONT TestConvertHashToNix32/already_Nix32_format315=== CONT TestRateLimiterFeedback/429_enables_limiter316--- PASS: TestDumpPathSingleFile (0.05s)3172026/11/09 12:09:53 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=0318--- PASS: TestCaseHackSuffix (0.04s)319--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.03s)320--- PASS: TestEncodeNixBase32 (0.00s)321 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)322 --- PASS: TestEncodeNixBase32/empty_input (0.00s)323=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter324--- PASS: TestPathInfoHashCompatibility (0.00s)325 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)326 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)327 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)328 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)329=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths3302026/11/09 12:09:53 WARN Rate limiter enabled after throttle name=s3-test rate=5331=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter3322026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:403933332026/11/09 12:09:53 WARN Rate limiter enabled after throttle name=server-test rate=53342026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:39383335--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)336 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)337 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)338=== CONT TestSetClientTLSErrors/invalid_ca_file339--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.04s)340=== CONT TestRateLimiterFeedback/503_enables_limiter341=== CONT TestPartSizeForNAR/zero_stays_at_minimum342=== CONT TestSetClientTLSErrors/missing_key_file3432026/11/09 12:09:53 WARN Rate limiter backed off name=server-test rate=5344=== CONT TestPartSizeForNAR/capped_at_5_GiB345=== CONT TestPartSizeForNAR/1_TiB346=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts3472026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:46777348=== CONT TestSetClientTLSErrors/missing_ca_file3492026/11/09 12:09:53 WARN Rate limiter enabled after throttle name=server-test rate=5350=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true3512026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:42047352=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text353=== CONT TestFilterOversizedClosures/all_closures_skipped354=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped355=== PAUSE TestParsePathInfoJSON/invalid_JSON356=== CONT TestSetClientTLSErrors/missing_cert_file357=== CONT TestFilterOversizedClosures/no_limit_keeps_everything3582026/11/09 12:09:53 WARN Rate limiter backed off name=server-test rate=5359=== CONT TestConvertHashToNix32/SRI_format_to_Nix32360=== CONT TestPartSizeForNAR/5_TiB_S3_max_object361=== CONT TestSetClientTLS/preserves_debug_logging_transport362=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3632026/11/09 12:09:53 WARN Garbage collection finished on another replica. Its statistics are not available here364=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error365=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error366=== CONT TestGetStorePathHash/basename_without_hyphen_should_error367=== CONT TestParsePathInfoJSON/Nix_format368=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true369=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false370=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method371=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method372=== CONT TestPathInfoCACompatibility/null_ca_field3732026/11/09 12:09:53 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=50374=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum3752026/11/09 12:09:53 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=2000376=== CONT TestPartSizeForNAR/small_stays_at_minimum377=== CONT TestParsePathInfoJSON/Lix_format378--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.04s)379=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true380=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method381=== CONT TestPathInfoCACompatibility/new_structured_format_-_text382=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive383=== CONT TestPathInfoCACompatibility/old_string_format_-_text384=== CONT TestSetClientTLS/rejects_connection_without_client_cert3852026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:46777386--- PASS: TestRateLimiterFeedback (0.02s)387 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)388 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)389 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)390 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)391=== CONT TestParsePathInfoJSON/invalid_JSON392=== CONT TestParsePathInfoJSON/whitespace_only393=== CONT TestParsePathInfoJSON/empty_input394=== CONT TestGetStorePathHash/valid_store_path395--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.03s)396--- PASS: TestGetStorePathHash (0.05s)397 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)398 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)399 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)400 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)401--- PASS: TestPathInfoCACompatibility (0.05s)402 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)403 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)404 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)405 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)406 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)407--- PASS: TestStreamPushBatchesUnderLoad (0.04s)408 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)409 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)410--- PASS: TestSetClientTLSErrors (0.01s)411 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)412 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)413 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)414 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)415--- PASS: TestConvertHashToNix32 (0.02s)416 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)417 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)418 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)419--- PASS: TestFilterOversizedClosures (0.00s)420 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)421 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)422 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)423--- PASS: TestPartSizeForNAR (0.02s)424 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)425 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)426 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)427 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)428 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)429 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)430 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)431--- PASS: TestParsePathInfoJSON (0.05s)432 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)433 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)434 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)435 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)436 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)4372026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:467774382026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:467774392026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:467774402026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:467774412026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:467774422026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:467774432026/11/09 12:09:53 http: TLS handshake error from 127.0.0.1:52508: remote error: tls: bad certificate4442026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:46777445--- PASS: TestSetClientTLS (0.05s)446 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)447 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)448 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)4492026/11/09 12:09:53 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:46777450--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.08s)451--- PASS: TestRegisterUploadedObjectReusesConnections (0.06s)452--- PASS: TestStreamPushRequestLine (0.07s)453--- PASS: TestDumpPathWriterError (0.07s)4542026/11/09 12:09:53 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:44163/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:44163/api/uploads/complete4552026/11/09 12:09:53 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4562026/11/09 12:09:53 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:44163/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:44163/api/uploads/complete4572026/11/09 12:09:53 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4582026/11/09 12:09:53 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:44163/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:44163/api/uploads/complete4592026/11/09 12:09:53 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"460--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (0.10s)461--- PASS: TestDumpPathMatchesNix (0.11s)462--- PASS: TestUploadMultipart_PartsInParallel (0.66s)463--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)464PASS465Running server tests...466The files belonging to this database system will be owned by user "nixbld".467This user must also own the server process.468469The database cluster will be initialized with locale "C".470The default database encoding has accordingly been set to "SQL_ASCII".471The default text search configuration will be set to "english".472473Data page checksums are enabled.474475creating directory /build/postgres289046971/data ... ok476creating subdirectories ... ok477selecting dynamic shared memory implementation ... posix478selecting default "max_connections" ... 100479selecting default "shared_buffers" ... 128MB480selecting default time zone ... UTC481creating configuration files ... ok482running bootstrap script ... ok483performing post-bootstrap initialization ... ok484syncing data to disk ... ok485486initdb: warning: enabling "trust" authentication for local connections487initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.488489Success. You can now start the database server using:490491 pg_ctl -D /build/postgres289046971/data -l logfile start492493/build/postgres289046971:5432 - no response4942026-11-09 12:09:55.636 UTC [129] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit4952026-11-09 12:09:55.636 UTC [129] LOG: listening on Unix socket "/build/postgres289046971/.s.PGSQL.5432"4962026-11-09 12:09:55.643 UTC [136] LOG: database system was shut down at 2026-11-09 12:09:55 UTC4972026-11-09 12:09:55.646 UTC [129] LOG: database system is ready to accept connections498/build/postgres289046971:5432 - accepting connections499=== RUN TestAbortSucceeded500=== PAUSE TestAbortSucceeded501=== RUN TestService_AuthMiddleware502=== PAUSE TestService_AuthMiddleware503=== RUN TestService_AuthMiddleware_MTLSProxyHeader504=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader505=== RUN TestService_AuthMiddleware_MTLSBoundSubjects506=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects507=== RUN TestService_ReadAuthMiddleware508=== PAUSE TestService_ReadAuthMiddleware509=== RUN TestService_AuthMiddleware_OIDC510=== PAUSE TestService_AuthMiddleware_OIDC511=== RUN TestService_RequireScope_OIDC512=== PAUSE TestService_RequireScope_OIDC513=== RUN TestService_ReadScope_PublicByDefault514=== PAUSE TestService_ReadScope_PublicByDefault515=== RUN TestCacheConfigHandler516=== PAUSE TestCacheConfigHandler517=== RUN TestCacheStatsHandler518=== PAUSE TestCacheStatsHandler519=== RUN TestClientCADerivations520=== PAUSE TestClientCADerivations521=== RUN TestClientErrorHandling522=== PAUSE TestClientErrorHandling523=== RUN TestClientIntegration524=== PAUSE TestClientIntegration525=== RUN TestClientMultipleUploads526=== PAUSE TestClientMultipleUploads527=== RUN TestClientWithDependencies528=== PAUSE TestClientWithDependencies529=== RUN TestClientSharedPathCommittedMidPush530=== PAUSE TestClientSharedPathCommittedMidPush531=== RUN TestPinProtectsFromGC532=== PAUSE TestPinProtectsFromGC533=== RUN TestClientPushesUseOnePush534=== PAUSE TestClientPushesUseOnePush535=== RUN TestClientFallsBackToClosures536=== PAUSE TestClientFallsBackToClosures537=== RUN TestDeleteClosuresRacingPins538=== PAUSE TestDeleteClosuresRacingPins539=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock540=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock541=== RUN TestResolveDBConnectionString542=== PAUSE TestResolveDBConnectionString543=== RUN TestConnectWaitsForAPeerMigration544=== PAUSE TestConnectWaitsForAPeerMigration545=== RUN TestLeadElectsOneAndHandsOver546=== PAUSE TestLeadElectsOneAndHandsOver547=== RUN TestLeadIncumbentWinsAfterRestart5482026/11/09 12:09:56 INFO lead: acquired remote=192.0.2.1:12345492026/11/09 12:09:56 INFO lead: released remote=192.0.2.1:12345502026/11/09 12:09:56 INFO lead: acquired remote=192.0.2.1:12345512026/11/09 12:09:57 INFO lead: released remote=192.0.2.1:1234552--- PASS: TestLeadIncumbentWinsAfterRestart (1.89s)553=== RUN TestLeadIncumbentAnnouncesAtOnce554=== PAUSE TestLeadIncumbentAnnouncesAtOnce555=== RUN TestLeadEndsOnShutdown556=== PAUSE TestLeadEndsOnShutdown557=== RUN TestLeadEndsWhenItsConnectionHangs5582026/11/09 12:09:57 INFO lead: acquired remote=192.0.2.1:12345592026-11-09 12:09:59.339 UTC [381] FATAL: terminating connection due to administrator command5602026/11/09 12:09:59 INFO lead: acquired remote=192.0.2.1:12345612026/11/09 12:10:00 WARN lead: lock connection lost error="timeout: context deadline exceeded"5622026/11/09 12:10:00 INFO lead: released remote=192.0.2.1:12345632026/11/09 12:10:00 INFO lead: released remote=192.0.2.1:1234564--- PASS: TestLeadEndsWhenItsConnectionHangs (2.92s)565=== RUN TestGCAdvisoryLockBlocksConcurrentRun566=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun567=== RUN TestGCBugBareHashReferences568=== PAUSE TestGCBugBareHashReferences569=== RUN TestGCMetrics570=== PAUSE TestGCMetrics571=== RUN TestPushDedupSurvivesConcurrentGC572=== PAUSE TestPushDedupSurvivesConcurrentGC573=== RUN TestDeduplicatedObjectsRecordedAsPending574=== PAUSE TestDeduplicatedObjectsRecordedAsPending575=== RUN TestGCSweepSkipsPendingObjects576=== PAUSE TestGCSweepSkipsPendingObjects577=== RUN TestTombstonedObjectOfferedWithoutWaiting578=== PAUSE TestTombstonedObjectOfferedWithoutWaiting579=== RUN TestGCSweepDeliversEachKeyOnce580=== PAUSE TestGCSweepDeliversEachKeyOnce581=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection582=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection583=== RUN TestForceGCDuringPushOffersSweptObject584=== PAUSE TestForceGCDuringPushOffersSweptObject585=== RUN TestFailedS3DeleteKeepsTombstone586=== PAUSE TestFailedS3DeleteKeepsTombstone587=== RUN TestSweepSkipsRowsLockedByPush588=== PAUSE TestSweepSkipsRowsLockedByPush589=== RUN TestRegisterCompletedObjectNeedsPendingRow590=== PAUSE TestRegisterCompletedObjectNeedsPendingRow591=== RUN TestGetExistingObjectsLocksRows592=== PAUSE TestGetExistingObjectsLocksRows593=== RUN TestSweepRechecksPendingAfterLocking594=== PAUSE TestSweepRechecksPendingAfterLocking595=== RUN TestPushWaitsForSweepHoldingRow596=== PAUSE TestPushWaitsForSweepHoldingRow597=== RUN TestCommitRacingPendingCleanupKeepsObjects598=== PAUSE TestCommitRacingPendingCleanupKeepsObjects599=== RUN TestGCEndsOnShutdown600=== PAUSE TestGCEndsOnShutdown601=== RUN TestGCTaskStore_StartNew602=== PAUSE TestGCTaskStore_StartNew603=== RUN TestGCTaskStore_DeduplicateSameParams604=== PAUSE TestGCTaskStore_DeduplicateSameParams605=== RUN TestGCTaskStore_ConflictDifferentParams606=== PAUSE TestGCTaskStore_ConflictDifferentParams607=== RUN TestGCTaskStore_GetEmpty608=== PAUSE TestGCTaskStore_GetEmpty609=== RUN TestGCTaskStore_GetReturnsLatest610=== PAUSE TestGCTaskStore_GetReturnsLatest611=== RUN TestGCTaskStore_CompletedAllowsNewTask612=== PAUSE TestGCTaskStore_CompletedAllowsNewTask613=== RUN TestGCTaskStore_PhaseUpdates614=== PAUSE TestGCTaskStore_PhaseUpdates615=== RUN TestGCTaskStore_Fail616=== PAUSE TestGCTaskStore_Fail617=== RUN TestGracefulShutdownDrainsInflight618=== PAUSE TestGracefulShutdownDrainsInflight619=== RUN TestService_healthCheckHandler620=== PAUSE TestService_healthCheckHandler621=== RUN TestService_readinessHandler622=== PAUSE TestService_readinessHandler623=== RUN TestGenerateLandingPage624=== PAUSE TestGenerateLandingPage625=== RUN TestEnsureAbortUploadsRule626=== PAUSE TestEnsureAbortUploadsRule627=== RUN TestCacheConfigHandlerMaxNarSize628=== PAUSE TestCacheConfigHandlerMaxNarSize629=== RUN TestCreatePendingClosureRejectsOversizedNAR630=== PAUSE TestCreatePendingClosureRejectsOversizedNAR631=== RUN TestNARDeduplicationMetadataUploadBug632=== PAUSE TestNARDeduplicationMetadataUploadBug633=== RUN TestMetricsInventory634=== PAUSE TestMetricsInventory635=== RUN TestMetricsCommit636=== PAUSE TestMetricsCommit637=== RUN TestService_NativeMTLS638=== PAUSE TestService_NativeMTLS639=== RUN TestServerTLSConfig640=== PAUSE TestServerTLSConfig641=== RUN TestMultipartCleanup642=== PAUSE TestMultipartCleanup643=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded644=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded645=== RUN TestPendingCleanupUsesOneCutoff646=== PAUSE TestPendingCleanupUsesOneCutoff647=== RUN TestObjectStatsTrigger648=== PAUSE TestObjectStatsTrigger649=== RUN TestObjectStatsUpdatedOncePerCommit650=== PAUSE TestObjectStatsUpdatedOncePerCommit651=== RUN TestOrphanedObjectsGC652=== PAUSE TestOrphanedObjectsGC653=== RUN TestOrphanedObjectsGCStressTest654=== PAUSE TestOrphanedObjectsGCStressTest655=== RUN TestCreatePin_ReservedPins656=== PAUSE TestCreatePin_ReservedPins657=== RUN TestPresentReportsOnlyClosureRoots658=== PAUSE TestPresentReportsOnlyClosureRoots659=== RUN TestPresentRefreshesOnlyStaleClosures660=== PAUSE TestPresentRefreshesOnlyStaleClosures661=== RUN TestPresentNotReportedWhileGCDeletesClosure662=== PAUSE TestPresentNotReportedWhileGCDeletesClosure663=== RUN TestParseSingleRange664=== PAUSE TestParseSingleRange665=== RUN TestProxyHeadersOnlyTrustedOnSocket6662026/11/09 12:10:01 INFO Starting HTTP server address=127.0.0.1:463136672026/11/09 12:10:01 INFO Starting HTTP server address=proxy.sock6682026/11/09 12:10:01 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6692026/11/09 12:10:01 INFO Shutdown signal received, draining in-flight requests timeout=10s670--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.28s)671=== RUN TestIsValidCachePath672=== PAUSE TestIsValidCachePath673=== RUN TestReadProxyNarinfo674=== PAUSE TestReadProxyNarinfo675=== RUN TestReadProxyNarinfoAlreadyDecompressed676=== PAUSE TestReadProxyNarinfoAlreadyDecompressed677=== RUN TestReadProxyContentNegotiation678=== PAUSE TestReadProxyContentNegotiation679=== RUN TestReadProxyNarStreaming680=== PAUSE TestReadProxyNarStreaming681=== RUN TestReadProxy404682=== PAUSE TestReadProxy404683=== RUN TestReadProxyInvalidPath684=== PAUSE TestReadProxyInvalidPath685=== RUN TestReadProxyHead686=== PAUSE TestReadProxyHead687=== RUN TestReadProxyOutlastsServerWriteTimeout688=== PAUSE TestReadProxyOutlastsServerWriteTimeout689=== RUN TestReadProxyConditionalGet690=== PAUSE TestReadProxyConditionalGet691=== RUN TestReadProxyRootRedirectsToIndexHTML692=== PAUSE TestReadProxyRootRedirectsToIndexHTML693=== RUN TestReadProxyDisabled694=== PAUSE TestReadProxyDisabled695=== RUN TestReadRedirectNar696=== PAUSE TestReadRedirectNar697=== RUN TestReadRedirectKeepsNarinfoProxied698=== PAUSE TestReadRedirectKeepsNarinfoProxied699=== RUN TestReadProxyRangeRequest700=== PAUSE TestReadProxyRangeRequest701=== RUN TestReadRedirectUsesPublicS3URL702=== PAUSE TestReadRedirectUsesPublicS3URL703=== RUN TestPush_OverlappingRootsStoreOneRowPerKey704=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey705=== RUN TestPush_CompleteCommitsEveryRoot706=== PAUSE TestPush_CompleteCommitsEveryRoot707=== RUN TestPush_RepeatedRootCommitsOnce708=== PAUSE TestPush_RepeatedRootCommitsOnce709=== RUN TestPush_CompleteWaitsForCleanupOfThePush710=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush711=== RUN TestPush_RootsAreLockedInByteOrder712=== PAUSE TestPush_RootsAreLockedInByteOrder713=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit714=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit715=== RUN TestPush_RejectsBadRequests716=== PAUSE TestPush_RejectsBadRequests717=== RUN TestPush_SignsNarinfosOfItsPendingObjects718=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects719=== RUN TestSharedNarBothUploadsComplete720=== PAUSE TestSharedNarBothUploadsComplete721=== RUN TestCompleteMultipartUpload_ErrorButObjectExists722=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists723=== RUN TestCompletedNarNotReofferedAcrossClosures724=== PAUSE TestCompletedNarNotReofferedAcrossClosures725=== RUN TestPresignedUploadRegisteredBeforeCommit726=== PAUSE TestPresignedUploadRegisteredBeforeCommit727=== RUN TestService_Rustfstest728=== PAUSE TestService_Rustfstest729=== RUN TestParseSize730=== PAUSE TestParseSize731=== RUN TestSkippedUploadsHandler732=== PAUSE TestSkippedUploadsHandler733=== RUN TestSystemdListenerNotActivated734--- PASS: TestSystemdListenerNotActivated (0.00s)735=== RUN TestWatchdogBeatsWhenHealthy736--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)737=== RUN TestWatchdogSkipsWhenUnhealthy7382026/11/09 12:10:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7392026/11/09 12:10:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7402026/11/09 12:10:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7412026/11/09 12:10:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7422026/11/09 12:10:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7432026/11/09 12:10:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7442026/11/09 12:10:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7452026/11/09 12:10:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7462026/11/09 12:10:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7472026/11/09 12:10:01 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"748--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)749=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle750=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle751=== RUN TestProxyWriteTimeout752=== PAUSE TestProxyWriteTimeout753=== RUN TestPendingClosureWriteTimeout754=== PAUSE TestPendingClosureWriteTimeout755=== RUN TestIsValidUploadKey756=== PAUSE TestIsValidUploadKey757=== RUN TestUploadHandlersRejectInvalidKeys758=== PAUSE TestUploadHandlersRejectInvalidKeys759=== RUN TestUploadHandlersRejectOversizedBody760=== PAUSE TestUploadHandlersRejectOversizedBody761=== RUN TestService_cleanupPendingClosuresHandler762=== PAUSE TestService_cleanupPendingClosuresHandler763=== RUN TestService_createPendingClosureHandler764=== PAUSE TestService_createPendingClosureHandler765=== RUN TestService_verifyS3Integrity766=== PAUSE TestService_verifyS3Integrity767=== RUN TestService_verifyS3ReuploadsStaleNarinfo768=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo769=== RUN TestCompleteMultipartUnregistered770=== PAUSE TestCompleteMultipartUnregistered771=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT772=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT773=== CONT TestIsValidUploadKey774=== CONT TestProxyWriteTimeout775=== RUN TestProxyWriteTimeout/narinfo776=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle777=== RUN TestIsValidUploadKey/narinfo778=== PAUSE TestIsValidUploadKey/narinfo779=== RUN TestIsValidUploadKey/nar_zst780=== PAUSE TestIsValidUploadKey/nar_zst781=== RUN TestIsValidUploadKey/nar_xz782=== CONT TestService_verifyS3ReuploadsStaleNarinfo783=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed784=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed785=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed786=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed787=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost788=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost789=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed790=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed791=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed792=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed793=== CONT TestPendingClosureWriteTimeout794=== RUN TestPendingClosureWriteTimeout/empty795=== PAUSE TestPendingClosureWriteTimeout/empty796=== RUN TestPendingClosureWriteTimeout/400_objects797=== PAUSE TestPendingClosureWriteTimeout/400_objects798=== RUN TestPendingClosureWriteTimeout/670k_objects799=== PAUSE TestPendingClosureWriteTimeout/670k_objects800=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline801=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline802=== CONT TestResolveDBConnectionString803=== RUN TestResolveDBConnectionString/flag_wins804=== PAUSE TestResolveDBConnectionString/flag_wins805=== RUN TestResolveDBConnectionString/file_when_flag_empty806=== PAUSE TestResolveDBConnectionString/file_when_flag_empty807=== RUN TestResolveDBConnectionString/missing_file_is_an_error808=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error809=== RUN TestResolveDBConnectionString/PGHOST_allows_empty810=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty811=== RUN TestResolveDBConnectionString/nothing_configured812=== PAUSE TestResolveDBConnectionString/nothing_configured813=== CONT TestAbortSucceeded814--- PASS: TestAbortSucceeded (0.00s)815=== CONT TestGCTaskStore_GetReturnsLatest816--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)817=== CONT TestDeleteClosuresRacingPins818=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock819=== CONT TestService_readinessHandler820=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT821=== CONT TestCompleteMultipartUnregistered822=== CONT TestService_verifyS3Integrity823=== CONT TestService_createPendingClosureHandler824=== CONT TestUploadHandlersRejectInvalidKeys825=== PAUSE TestProxyWriteTimeout/narinfo826=== CONT TestService_cleanupPendingClosuresHandler827=== CONT TestService_healthCheckHandler828=== CONT TestGCAdvisoryLockBlocksConcurrentRun829=== CONT TestLeadEndsOnShutdown830=== CONT TestGracefulShutdownDrainsInflight831=== CONT TestLeadIncumbentAnnouncesAtOnce832=== CONT TestGCTaskStore_Fail833=== CONT TestLeadElectsOneAndHandsOver834=== CONT TestGCTaskStore_PhaseUpdates835=== CONT TestConnectWaitsForAPeerMigration836=== CONT TestGCTaskStore_CompletedAllowsNewTask837=== CONT TestUploadHandlersRejectOversizedBody838=== PAUSE TestIsValidUploadKey/nar_xz839=== CONT TestGCTaskStore_GetEmpty840--- PASS: TestGCTaskStore_GetEmpty (0.00s)841=== CONT TestGCTaskStore_ConflictDifferentParams842--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)843=== CONT TestClientFallsBackToClosures844--- PASS: TestGCTaskStore_Fail (0.00s)845=== CONT TestGCTaskStore_DeduplicateSameParams846--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)847=== CONT TestClientPushesUseOnePush848=== RUN TestIsValidUploadKey/nar_plain849=== PAUSE TestIsValidUploadKey/nar_plain850=== RUN TestIsValidUploadKey/listing851=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info852=== RUN TestProxyWriteTimeout/1_GiB_nar853=== PAUSE TestIsValidUploadKey/listing854--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)855=== RUN TestIsValidUploadKey/build_log856=== PAUSE TestIsValidUploadKey/build_log857=== RUN TestIsValidUploadKey/build_log_home-manager_file858=== PAUSE TestIsValidUploadKey/build_log_home-manager_file859=== RUN TestIsValidUploadKey/build_log_plus_in_name860=== PAUSE TestIsValidUploadKey/build_log_plus_in_name861=== RUN TestIsValidUploadKey/build_log_question_mark862=== PAUSE TestIsValidUploadKey/build_log_question_mark863=== RUN TestIsValidUploadKey/build_log_equals864=== CONT TestGCSweepSkipsPendingObjects865=== PAUSE TestIsValidUploadKey/build_log_equals866=== RUN TestIsValidUploadKey/realisation867=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info8682026/11/09 12:10:02 INFO Starting HTTP server address=127.0.0.1:40543869=== PAUSE TestProxyWriteTimeout/1_GiB_nar870--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)8712026/11/09 12:10:02 INFO Shutdown signal received, draining in-flight requests timeout=10s872=== CONT TestPinProtectsFromGC873=== PAUSE TestIsValidUploadKey/realisation874=== RUN TestIsValidUploadKey/realisation_plus_in_output875=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal876=== RUN TestProxyWriteTimeout/10_GiB_nar877=== PAUSE TestProxyWriteTimeout/10_GiB_nar878=== RUN TestProxyWriteTimeout/unknown_size879=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal880=== PAUSE TestIsValidUploadKey/realisation_plus_in_output881=== RUN TestIsValidUploadKey/nix-cache-info882=== PAUSE TestIsValidUploadKey/nix-cache-info883=== PAUSE TestProxyWriteTimeout/unknown_size884=== RUN TestIsValidUploadKey/index.html885=== PAUSE TestIsValidUploadKey/index.html886=== CONT TestClientSharedPathCommittedMidPush887=== RUN TestIsValidUploadKey/narinfo_key,_nar_type888=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type889=== RUN TestIsValidUploadKey/nar_key,_narinfo_type890=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type891=== RUN TestIsValidUploadKey/listing_key,_narinfo_type892=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type893=== RUN TestIsValidUploadKey/traversal894=== PAUSE TestIsValidUploadKey/traversal895=== RUN TestIsValidUploadKey/traversal_nar896=== PAUSE TestIsValidUploadKey/traversal_nar897=== RUN TestIsValidUploadKey/absolute898=== PAUSE TestIsValidUploadKey/absolute899=== RUN TestIsValidUploadKey/empty_key900=== PAUSE TestIsValidUploadKey/empty_key901=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key902=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key903=== RUN TestIsValidUploadKey/unknown_type904=== PAUSE TestIsValidUploadKey/unknown_type905=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key906=== CONT TestForceGCDuringPushOffersSweptObject907=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows908--- PASS: TestGracefulShutdownDrainsInflight (0.07s)909=== CONT TestDeduplicatedObjectsRecordedAsPending910=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure911=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure912=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart913=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key914=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart915=== CONT TestClientWithDependencies916=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts917=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts918=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection919=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows920=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check921=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check922=== CONT TestPushDedupSurvivesConcurrentGC9232026/11/09 12:10:03 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9242026/11/09 12:10:03 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst925--- PASS: TestCompleteMultipartUnregistered (2.05s)926=== CONT TestClientMultipleUploads9272026/11/09 12:10:03 INFO Received uploads request method=POST path=/api/pending_closures928--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.57s)929=== CONT TestGCSweepDeliversEachKeyOnce9302026/11/09 12:10:03 INFO lead: acquired remote=192.0.2.1:12349312026/11/09 12:10:03 INFO lead: acquired remote=192.0.2.1:12349322026/11/09 12:10:03 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"933--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.75s)934=== CONT TestGCMetrics9352026/11/09 12:10:03 INFO Received uploads request method=POST path=/api/pending_closures9362026/11/09 12:10:03 INFO Received uploads request method=POST path=/api/pending_closures9372026/11/09 12:10:03 INFO Received uploads request method=POST path=/api/pending_closures9382026/11/09 12:10:03 INFO Received uploads request method=POST path=/api/pending_closures9392026/11/09 12:10:03 INFO Received uploads request method=POST path=/api/pending_closures9402026/11/09 12:10:03 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9412026/11/09 12:10:03 INFO Received uploads request method=POST path=/api/pending_closures942--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (2.42s)943=== CONT TestClientIntegration9442026/11/09 12:10:03 INFO Received uploads request method=POST path=/api/pending_closures945--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (2.44s)946=== CONT TestGCBugBareHashReferences947--- PASS: TestService_healthCheckHandler (0.98s)948=== CONT TestTombstonedObjectOfferedWithoutWaiting9492026/11/09 12:10:03 INFO Aborted multipart uploads count=0 kept=09502026/11/09 12:10:03 INFO Received uploads request method=POST path=/api/pending_closures9512026/11/09 12:10:03 INFO lead: acquired remote=192.0.2.1:12349522026/11/09 12:10:03 INFO lead: released remote=192.0.2.1:1234953--- PASS: TestLeadIncumbentAnnouncesAtOnce (2.53s)954=== CONT TestClientErrorHandling955=== RUN TestClientErrorHandling/InvalidStorePath956=== PAUSE TestClientErrorHandling/InvalidStorePath957=== RUN TestClientErrorHandling/InvalidAuthToken958=== PAUSE TestClientErrorHandling/InvalidAuthToken959=== RUN TestClientErrorHandling/ServerNotAvailable960=== PAUSE TestClientErrorHandling/ServerNotAvailable961=== CONT TestService_AuthMiddleware_MTLSProxyHeader962=== NAME TestPinProtectsFromGC963 client_integration_test.go:778: Pinned store path: /build/TestPinProtectsFromGC62026700/001/store/s83mxvz5ng4k45jnqh2dwfhwiywi2w0y-pinned-file.txt964 client_integration_test.go:779: Unpinned store path: /build/TestPinProtectsFromGC62026700/001/store/xfq3ha1afzpkmqzj43ihr2wskcc9qkw2-unpinned-file.txt9652026/11/09 12:10:03 INFO Received uploads request method=POST path=/api/pending_closures966--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (1.09s)967=== CONT TestService_AuthMiddleware9682026/11/09 12:10:03 INFO Aborted multipart uploads count=0 kept=09692026/11/09 12:10:03 WARN readiness check failed error="closed pool"970--- PASS: TestService_readinessHandler (2.74s)971=== CONT TestService_AuthMiddleware_OIDC9722026/11/09 12:10:03 WARN Force mode enabled - objects will be deleted immediately without grace period9732026/11/09 12:10:04 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=09742026/11/09 12:10:04 INFO Vacuumed table table=pending_closures9752026/11/09 12:10:04 INFO Vacuumed table table=pending_objects9762026/11/09 12:10:04 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9772026/11/09 12:10:04 INFO Vacuumed table table=multipart_uploads9782026/11/09 12:10:04 INFO Vacuumed table table=closures9792026/11/09 12:10:04 INFO Vacuumed table table=objects980--- PASS: TestGCSweepSkipsPendingObjects (1.29s)981=== CONT TestService_ReadAuthMiddleware9822026/11/09 12:10:04 INFO Received cleanup request method=DELETE path=/api/pending_closures9832026/11/09 12:10:04 INFO Aborted multipart uploads count=0 kept=09842026/11/09 12:10:04 INFO Received uploads request method=POST path=/api/pending_closures9852026/11/09 12:10:04 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZmE2ZTA3NDgtNzlhZC00MmJjLTkzMzQtZWQzYjc0ZTA3NTVhLjBmZTRmMGMzLWQ5ZDYtNGU5YS04YjliLWU4OTNkYjZkOTZlZngxNzk0MjI2MjAzNTUxODk2MjY0 parts=109862026/11/09 12:10:04 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9872026/11/09 12:10:04 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9882026/11/09 12:10:04 INFO Completed upload id=1 objects=2 duration=5.869613ms9892026/11/09 12:10:04 INFO Received uploads request method=POST path=/api/pending_closures9902026/11/09 12:10:04 INFO Received cleanup request method=DELETE path=/api/pending_closures9912026/11/09 12:10:04 INFO Aborted multipart uploads count=1 kept=09922026/11/09 12:10:04 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9932026-11-09 12:10:04.061 UTC [445] ERROR: Closure does not exist: id=19942026-11-09 12:10:04.061 UTC [445] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9952026-11-09 12:10:04.061 UTC [445] STATEMENT: -- name: CommitPendingClosure :one996 SELECT commit_pending_closure($1::bigint)::bigint997 9982026/11/09 12:10:04 INFO Received uploads request method=POST path=/api/pending_closures999--- PASS: TestService_cleanupPendingClosuresHandler (2.80s)1000=== CONT TestFailedS3DeleteKeepsTombstone10012026/11/09 12:10:04 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZmE2ZTA3NDgtNzlhZC00MmJjLTkzMzQtZWQzYjc0ZTA3NTVhLjUwOTU2MmEwLTkxMWYtNDExOS1hNWM0LWRkNjYxZTIwYjdlYXgxNzk0MjI2MjAzNTcwMDY2NTg5 parts=1010022026/11/09 12:10:04 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10032026/11/09 12:10:04 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10042026/11/09 12:10:04 WARN Found objects in DB but missing from S3, will re-upload count=11005--- PASS: TestService_verifyS3Integrity (2.80s)1006=== CONT TestClientCADerivations10072026/11/09 12:10:04 INFO Completed upload id=1 objects=2 duration=8.158434ms10082026/11/09 12:10:04 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010092026/11/09 12:10:04 INFO Received uploads request method=POST path=/api/pending_closures10102026/11/09 12:10:04 INFO Starting cleanup of old closures method=DELETE path=/api/closures10112026/11/09 12:10:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42263/oidc10122026/11/09 12:10:04 INFO Aborted multipart uploads count=0 kept=010132026/11/09 12:10:04 INFO Aborted multipart uploads count=0 kept=010142026/11/09 12:10:04 INFO Aborted multipart uploads count=0 kept=010152026/11/09 12:10:04 WARN Force mode enabled - objects will be deleted immediately without grace period10162026/11/09 12:10:04 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=010172026/11/09 12:10:04 INFO Vacuumed table table=pending_closures10182026/11/09 12:10:04 INFO Vacuumed table table=pending_objects10192026/11/09 12:10:04 INFO Vacuumed table table=multipart_uploads10202026/11/09 12:10:04 INFO Vacuumed table table=closures10212026/11/09 12:10:04 INFO Vacuumed table table=objects10222026/11/09 12:10:04 WARN Force mode enabled - objects will be deleted immediately without grace period1023--- PASS: TestGCMetrics (0.69s)1024=== CONT TestService_AuthMiddleware_MTLSBoundSubjects10252026/11/09 12:10:04 INFO Received uploads request method=POST path=/api/pending_closures1026--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.49s)1027=== CONT TestCacheStatsHandler10282026/11/09 12:10:04 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=010292026/11/09 12:10:04 INFO Vacuumed table table=pending_closures10302026/11/09 12:10:04 INFO Vacuumed table table=pending_objects10312026/11/09 12:10:04 INFO Vacuumed table table=multipart_uploads10322026/11/09 12:10:04 INFO Vacuumed table table=closures10332026/11/09 12:10:04 INFO Vacuumed table table=objects1034--- PASS: TestGCSweepDeliversEachKeyOnce (0.85s)1035=== CONT TestService_ReadScope_PublicByDefault1036--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.51s)1037=== CONT TestService_RequireScope_OIDC10382026/11/09 12:10:04 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1039--- PASS: TestService_AuthMiddleware (0.42s)1040=== CONT TestSweepRechecksPendingAfterLocking10412026/11/09 12:10:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38151/oidc1042=== NAME TestClientIntegration1043 client_integration_test.go:291: Created store path: /build/TestClientIntegration768943202/002/store/x667i3r20rpsyp5f0vg13zvlqz1j4111-test-file.txt10442026/11/09 12:10:04 INFO Received push request method=POST path=/api/pushes10452026/11/09 12:10:04 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10462026/11/09 12:10:04 INFO Uploading s83mxvz5ng4k45jnqh2dwfhwiywi2w0y-pinned-file.txt (128B)10472026/11/09 12:10:04 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=01048--- PASS: TestService_ReadAuthMiddleware (0.41s)1049=== CONT TestCacheConfigHandler1050=== RUN TestCacheConfigHandler/full_config,_no_issuer1051=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1052=== RUN TestCacheConfigHandler/no_cache_url_configured1053=== PAUSE TestCacheConfigHandler/no_cache_url_configured1054=== RUN TestCacheConfigHandler/no_signing_keys1055=== PAUSE TestCacheConfigHandler/no_signing_keys1056=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1057=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1058=== CONT TestGCEndsOnShutdown1059=== RUN TestGCEndsOnShutdown/before_the_run1060=== PAUSE TestGCEndsOnShutdown/before_the_run1061=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1062=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1063=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1064=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1065=== CONT TestCommitRacingPendingCleanupKeepsObjects10662026/11/09 12:10:04 WARN Failed to register uploaded object key=s83mxvz5ng4k45jnqh2dwfhwiywi2w0y.ls error="server returned 404: 404 page not found\n"10672026/11/09 12:10:04 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"10682026/11/09 12:10:04 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10692026/11/09 12:10:04 INFO Signed narinfos id=1 count=110702026/11/09 12:10:04 INFO Uploading 1 narinfos10712026/11/09 12:10:04 INFO Vacuumed table table=pending_closures10722026/11/09 12:10:04 INFO Vacuumed table table=pending_objects10732026/11/09 12:10:04 INFO Received complete push request method=POST path=/api/pushes/1/complete10742026/11/09 12:10:04 WARN Failed to register uploaded object key=s83mxvz5ng4k45jnqh2dwfhwiywi2w0y.narinfo error="server returned 404: 404 page not found\n"10752026/11/09 12:10:04 INFO Vacuumed table table=multipart_uploads10762026/11/09 12:10:04 INFO Vacuumed table table=closures10772026/11/09 12:10:04 INFO Completed push id=1 objects=3 duration=10.215592ms10782026/11/09 12:10:04 INFO Upload complete. (440ms)10792026/11/09 12:10:04 INFO Vacuumed table table=objects10802026/11/09 12:10:04 INFO Received uploads request method=POST path=/api/pending_closures1081--- PASS: TestGCBugBareHashReferences (0.79s)1082=== CONT TestRegisterCompletedObjectNeedsPendingRow10832026/11/09 12:10:04 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010842026/11/09 12:10:04 INFO lead: released remote=192.0.2.1:12341085--- PASS: TestLeadEndsOnShutdown (1.77s)1086=== CONT TestPushWaitsForSweepHoldingRow1087--- PASS: TestService_createPendingClosureHandler (3.26s)1088=== NAME TestClientWithDependencies1089 client_integration_test.go:660: Built derivation: /build/TestClientWithDependencies2958960629/001/store/k87hfz1b7j42kswqcb3mw7bn2hly164y-test-script1090=== CONT TestGetExistingObjectsLocksRows1091--- PASS: TestService_ReadScope_PublicByDefault (0.29s)1092=== CONT TestReadProxy40410932026/11/09 12:10:04 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"10942026/11/09 12:10:04 WARN mTLS auth: bound subjects configured but subject DN unavailable10952026/11/09 12:10:04 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1096--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.38s)1097=== CONT TestPush_RepeatedRootCommitsOnce1098=== NAME TestClientWithDependencies1099 client_integration_test.go:662: Found 1 dependencies (including self)11002026/11/09 12:10:04 INFO Aborted multipart uploads count=0 kept=011012026/11/09 12:10:04 INFO Received push request method=POST path=/api/pushes11022026/11/09 12:10:04 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)11032026/11/09 12:10:04 INFO Uploading nqmqfnr98jhy9x31gnvl6lc81q0r7qrh-a (216B)11042026/11/09 12:10:04 INFO Uploading sb3h0a98lf3didg9p57sy62z2z662zzb-shared-dep (136B)1105--- PASS: TestCacheStatsHandler (0.41s)1106=== CONT TestPush_CompleteCommitsEveryRoot11072026/11/09 12:10:04 WARN Failed to register uploaded object key=sb3h0a98lf3didg9p57sy62z2z662zzb.ls error="server returned 404: 404 page not found\n"11082026/11/09 12:10:04 WARN Failed to register uploaded object key=2v1fjqi6riv0vabbmr5jcs8ibd3xpncz.ls error="server returned 404: 404 page not found\n"11092026/11/09 12:10:04 WARN Failed to register uploaded object key=nar/0bsvaqrdzdhgib8g2l1l429wpsy3frgizildd48qnd40mv6x4yfs.nar.zst error="server returned 404: 404 page not found\n"11102026/11/09 12:10:04 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11112026/11/09 12:10:04 INFO lead: released remote=192.0.2.1:12341112=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1113=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1114=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1115=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1116=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1117=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1118=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1119=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1120=== CONT TestSkippedUploadsHandler11212026/11/09 12:10:04 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001122--- PASS: TestSkippedUploadsHandler (0.00s)1123=== CONT TestReadProxyRootRedirectsToIndexHTML11242026/11/09 12:10:04 INFO lead: acquired remote=192.0.2.1:12341125--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.24s)1126=== CONT TestParseSize1127--- PASS: TestParseSize (0.00s)1128=== CONT TestReadProxyConditionalGet11292026/11/09 12:10:04 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11302026/11/09 12:10:04 WARN Failed to register uploaded object key=nqmqfnr98jhy9x31gnvl6lc81q0r7qrh.ls error="server returned 404: 404 page not found\n"11312026/11/09 12:10:04 INFO Signed narinfos id=1 count=311322026/11/09 12:10:04 INFO Uploading 3 narinfos11332026/11/09 12:10:04 WARN Force mode enabled - objects will be deleted immediately without grace period11342026/11/09 12:10:04 WARN Failed to register uploaded object key=2v1fjqi6riv0vabbmr5jcs8ibd3xpncz.narinfo error="server returned 404: 404 page not found\n"11352026/11/09 12:10:04 WARN Failed to register uploaded object key=nqmqfnr98jhy9x31gnvl6lc81q0r7qrh.narinfo error="server returned 404: 404 page not found\n"11362026/11/09 12:10:04 INFO Received complete push request method=POST path=/api/pushes/1/complete11372026/11/09 12:10:04 WARN Failed to register uploaded object key=sb3h0a98lf3didg9p57sy62z2z662zzb.narinfo error="server returned 404: 404 page not found\n"11382026/11/09 12:10:04 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=01139=== RUN TestService_RequireScope_OIDC/builder_may_write1140=== PAUSE TestService_RequireScope_OIDC/builder_may_write1141=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1142=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1143=== RUN TestService_RequireScope_OIDC/ops_may_admin1144=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1145=== RUN TestService_RequireScope_OIDC/ops_may_not_write1146=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1147=== RUN TestService_RequireScope_OIDC/reader_may_not_write1148=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1149=== RUN TestService_RequireScope_OIDC/static_token_may_admin1150=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1151=== RUN TestService_RequireScope_OIDC/static_token_may_write1152=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1153=== RUN TestService_RequireScope_OIDC/reader_may_read1154=== PAUSE TestService_RequireScope_OIDC/reader_may_read1155=== RUN TestService_RequireScope_OIDC/writer_implies_read1156=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1157=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1158=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1159=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1160=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1161=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1162=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1163=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1164=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1165=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1166=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1167=== CONT TestService_Rustfstest11682026/11/09 12:10:04 INFO Completed push id=1 objects=8 duration=9.726149ms11692026/11/09 12:10:04 INFO Upload complete. (265ms)11702026/11/09 12:10:04 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."11712026/11/09 12:10:04 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1172=== NAME TestClientPushesUseOnePush1173 client_pushes_test.go:97: Retrieved narinfo from S3:1174 StorePath: /build/TestClientPushesUseOnePush3106465336/001/store/sb3h0a98lf3didg9p57sy62z2z662zzb-shared-dep1175 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1176 Compression: zstd1177 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821178 NarSize: 1361179 References: 1180 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n11812026/11/09 12:10:04 INFO Vacuumed table table=pending_closures1182 client_pushes_test.go:97: Retrieved narinfo from S3:1183 StorePath: /build/TestClientPushesUseOnePush3106465336/001/store/nqmqfnr98jhy9x31gnvl6lc81q0r7qrh-a1184 URL: nar/0bsvaqrdzdhgib8g2l1l429wpsy3frgizildd48qnd40mv6x4yfs.nar.zst1185 Compression: zstd1186 NarHash: sha256:0bsvaqrdzdhgib8g2l1l429wpsy3frgizildd48qnd40mv6x4yfs1187 NarSize: 2161188 References: /build/TestClientPushesUseOnePush3106465336/001/store/sb3h0a98lf3didg9p57sy62z2z662zzb-shared-dep1189 CA: text:sha256:1j6ins9ggdj9jfsnxnjnd93brfhix1m0psag33qw7inr0jfda6d21190--- PASS: TestFailedS3DeleteKeepsTombstone (0.75s)1191=== CONT TestReadProxyOutlastsServerWriteTimeout11922026/11/09 12:10:04 INFO Vacuumed table table=pending_objects11932026/11/09 12:10:04 INFO Vacuumed table table=multipart_uploads1194=== NAME TestClientPushesUseOnePush1195 client_pushes_test.go:97: Retrieved narinfo from S3:1196 StorePath: /build/TestClientPushesUseOnePush3106465336/001/store/2v1fjqi6riv0vabbmr5jcs8ibd3xpncz-b1197 URL: nar/0bsvaqrdzdhgib8g2l1l429wpsy3frgizildd48qnd40mv6x4yfs.nar.zst1198 Compression: zstd1199 NarHash: sha256:0bsvaqrdzdhgib8g2l1l429wpsy3frgizildd48qnd40mv6x4yfs1200 NarSize: 2161201 References: /build/TestClientPushesUseOnePush3106465336/001/store/sb3h0a98lf3didg9p57sy62z2z662zzb-shared-dep1202 CA: text:sha256:1j6ins9ggdj9jfsnxnjnd93brfhix1m0psag33qw7inr0jfda6d21203--- PASS: TestClientPushesUseOnePush (3.56s)12042026/11/09 12:10:04 INFO Received push request method=POST path=/api/pushes1205=== CONT TestPresignedUploadRegisteredBeforeCommit12062026/11/09 12:10:04 INFO Vacuumed table table=closures12072026/11/09 12:10:04 INFO Aborted multipart uploads count=0 kept=012082026/11/09 12:10:04 INFO Vacuumed table table=objects12092026/11/09 12:10:04 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12102026/11/09 12:10:04 INFO Uploading x667i3r20rpsyp5f0vg13zvlqz1j4111-test-file.txt (152B)12112026/11/09 12:10:04 INFO Received push request method=POST path=/api/pushes12122026/11/09 12:10:04 INFO Aborted multipart uploads count=0 kept=012132026/11/09 12:10:04 WARN Force mode enabled - objects will be deleted immediately without grace period12142026/11/09 12:10:04 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=012152026/11/09 12:10:04 WARN Failed to register uploaded object key=x667i3r20rpsyp5f0vg13zvlqz1j4111.ls error="server returned 404: 404 page not found\n"12162026/11/09 12:10:04 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12172026/11/09 12:10:04 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"12182026/11/09 12:10:04 INFO Signed narinfos id=1 count=112192026/11/09 12:10:04 INFO Uploading 1 narinfos12202026/11/09 12:10:04 INFO Received push request method=POST path=/api/pushes12212026/11/09 12:10:04 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12222026/11/09 12:10:04 INFO Uploading xfq3ha1afzpkmqzj43ihr2wskcc9qkw2-unpinned-file.txt (128B)12232026/11/09 12:10:04 INFO Received push request method=POST path=/api/pushes12242026/11/09 12:10:04 WARN Force mode enabled - objects will be deleted immediately without grace period12252026/11/09 12:10:04 INFO Received complete push request method=POST path=/api/pushes/1/complete12262026/11/09 12:10:04 WARN Failed to register uploaded object key=x667i3r20rpsyp5f0vg13zvlqz1j4111.narinfo error="server returned 404: 404 page not found\n"12272026/11/09 12:10:04 INFO Vacuumed table table=pending_closures12282026/11/09 12:10:04 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)12292026/11/09 12:10:04 INFO Uploading xprpf3g5vd3b9jhj63a3aw141v5gh9nr-top (224B)12302026/11/09 12:10:04 INFO Uploading f24a5vfgzj44kvcjk9x1hj593kb5n4jn-shared-dep (136B)12312026/11/09 12:10:04 INFO Vacuumed table table=pending_objects12322026/11/09 12:10:04 WARN Failed to register uploaded object key=xfq3ha1afzpkmqzj43ihr2wskcc9qkw2.ls error="server returned 404: 404 page not found\n"12332026/11/09 12:10:04 INFO Vacuumed table table=multipart_uploads12342026/11/09 12:10:04 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12352026/11/09 12:10:04 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12362026/11/09 12:10:04 INFO Uploading k87hfz1b7j42kswqcb3mw7bn2hly164y-test-script (136B)12372026/11/09 12:10:04 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"12382026/11/09 12:10:04 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=012392026/11/09 12:10:04 INFO Signed narinfos id=2 count=112402026/11/09 12:10:04 INFO Uploading 1 narinfos12412026/11/09 12:10:04 INFO Vacuumed table table=closures12422026/11/09 12:10:04 INFO Vacuumed table table=objects12432026/11/09 12:10:04 INFO Vacuumed table table=pending_closures12442026/11/09 12:10:04 INFO Completed push id=1 objects=3 duration=14.788474ms12452026/11/09 12:10:04 INFO Upload complete. (117ms)1246--- PASS: TestPushDedupSurvivesConcurrentGC (2.01s)1247=== CONT TestReadProxyHead12482026/11/09 12:10:04 INFO Received complete push request method=POST path=/api/pushes/2/complete12492026/11/09 12:10:04 WARN Failed to register uploaded object key=xfq3ha1afzpkmqzj43ihr2wskcc9qkw2.narinfo error="server returned 404: 404 page not found\n"12502026/11/09 12:10:04 WARN Failed to register uploaded object key=nar/1m7c44j2p0nd8jrqvgg1x1fix3h1q6iw6i8w44x1xar5zkkdib38.nar.zst error="server returned 404: 404 page not found\n"12512026/11/09 12:10:04 INFO Vacuumed table table=pending_objects12522026/11/09 12:10:04 WARN Failed to register uploaded object key=f24a5vfgzj44kvcjk9x1hj593kb5n4jn.ls error="server returned 404: 404 page not found\n"12532026/11/09 12:10:04 INFO Vacuumed table table=multipart_uploads12542026/11/09 12:10:04 WARN Failed to register uploaded object key=xprpf3g5vd3b9jhj63a3aw141v5gh9nr.ls error="server returned 404: 404 page not found\n"12552026/11/09 12:10:04 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"12562026/11/09 12:10:04 WARN Failed to register uploaded object key=log/zvjygkpp15yjflpvj0zwk0v2ndcgcg8l-test-script.drv error="server returned 404: 404 page not found\n"12572026/11/09 12:10:04 INFO Completed push id=2 objects=3 duration=3.34073ms12582026/11/09 12:10:04 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12592026/11/09 12:10:04 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12602026/11/09 12:10:04 INFO Upload complete. (93ms)12612026/11/09 12:10:04 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12622026/11/09 12:10:04 WARN Failed to register uploaded object key=k87hfz1b7j42kswqcb3mw7bn2hly164y.ls error="server returned 404: 404 page not found\n"12632026/11/09 12:10:04 INFO Signed narinfos id=1 count=112642026/11/09 12:10:04 INFO Signed narinfos id=1 count=212652026/11/09 12:10:04 INFO Uploading 1 narinfos12662026/11/09 12:10:04 INFO Uploading 2 narinfos12672026/11/09 12:10:04 INFO Vacuumed table table=closures12682026/11/09 12:10:04 INFO Vacuumed table table=objects12692026/11/09 12:10:04 INFO Received complete push request method=POST path=/api/pushes/1/complete12702026/11/09 12:10:04 WARN Failed to register uploaded object key=f24a5vfgzj44kvcjk9x1hj593kb5n4jn.narinfo error="server returned 404: 404 page not found\n"12712026/11/09 12:10:04 WARN Failed to register uploaded object key=xprpf3g5vd3b9jhj63a3aw141v5gh9nr.narinfo error="server returned 404: 404 page not found\n"12722026/11/09 12:10:04 INFO Received complete push request method=POST path=/api/pushes/1/complete12732026/11/09 12:10:04 WARN Failed to register uploaded object key=k87hfz1b7j42kswqcb3mw7bn2hly164y.narinfo error="server returned 404: 404 page not found\n"12742026/11/09 12:10:04 INFO Completed push id=1 objects=4 duration=12.785195ms12752026/11/09 12:10:04 INFO Completed push id=1 objects=6 duration=12.950457ms12762026/11/09 12:10:04 INFO Upload complete. (132ms)12772026/11/09 12:10:04 INFO Upload complete. (135ms)1278=== NAME TestClientSharedPathCommittedMidPush1279 client_integration_test.go:727: Retrieved narinfo from S3:1280 StorePath: /build/TestClientSharedPathCommittedMidPush198924230/001/store/f24a5vfgzj44kvcjk9x1hj593kb5n4jn-shared-dep1281 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1282 Compression: zstd1283 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821284 NarSize: 1361285 References: 1286 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1287=== NAME TestClientWithDependencies1288 client_integration_test.go:664: Skipping nix copy test - isolated store (/build/TestClientWithDependencies2958960629/001/store) requires matching store prefix1289=== NAME TestClientSharedPathCommittedMidPush1290 client_integration_test.go:727: Retrieved narinfo from S3:1291 StorePath: /build/TestClientSharedPathCommittedMidPush198924230/001/store/xprpf3g5vd3b9jhj63a3aw141v5gh9nr-top1292 URL: nar/1m7c44j2p0nd8jrqvgg1x1fix3h1q6iw6i8w44x1xar5zkkdib38.nar.zst1293 Compression: zstd1294 NarHash: sha256:1m7c44j2p0nd8jrqvgg1x1fix3h1q6iw6i8w44x1xar5zkkdib381295 NarSize: 2241296 References: /build/TestClientSharedPathCommittedMidPush198924230/001/store/f24a5vfgzj44kvcjk9x1hj593kb5n4jn-shared-dep1297 CA: text:sha256:1wkxk7fh5p7l5j8gz3672viyf190311g23g28bdizr2iknd6zqz61298--- PASS: TestClientWithDependencies (2.04s)1299=== CONT TestCompletedNarNotReofferedAcrossClosures1300--- PASS: TestClientSharedPathCommittedMidPush (2.13s)1301=== CONT TestReadProxyInvalidPath13022026/11/09 12:10:04 INFO Received uploads request method=POST path=/api/pending_closures13032026/11/09 12:10:04 INFO All 1 paths already cached1304=== NAME TestClientIntegration1305 client_integration_test.go:317: Retrieved narinfo from S3:1306 StorePath: /build/TestClientIntegration768943202/002/store/x667i3r20rpsyp5f0vg13zvlqz1j4111-test-file.txt1307 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1308 Compression: zstd1309 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11310 NarSize: 1521311 References: 1312 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk113132026/11/09 12:10:04 INFO Received push request method=POST path=/api/pushes1314 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1315 client_integration_test.go:318: Decompressed .ls content (64 bytes):1316 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}13172026/11/09 12:10:04 INFO Received complete push request method=POST path=/api/pushes/1/complete1318--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.57s)1319=== CONT TestCompleteMultipartUpload_ErrorButObjectExists13202026/11/09 12:10:05 INFO Starting cleanup of old closures method=DELETE path=/api/closures13212026/11/09 12:10:05 INFO Garbage collection started13222026/11/09 12:10:05 INFO Completed push id=1 objects=4 duration=24.805845ms1323--- PASS: TestPush_RepeatedRootCommitsOnce (0.47s)1324=== CONT TestReadProxyDisabled13252026/11/09 12:10:05 INFO Aborted multipart uploads count=0 kept=013262026/11/09 12:10:05 INFO Received uploads request method=POST path=/api/pending_closures13272026/11/09 12:10:05 WARN Force mode enabled - objects will be deleted immediately without grace period13282026/11/09 12:10:05 INFO Received uploads request method=POST path=/api/pending_closures13292026/11/09 12:10:05 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13302026/11/09 12:10:05 INFO Uploading 07xrrwkxfkzqhlgb4j8kldlkkbxaky4y-shared-dep (136B)13312026/11/09 12:10:05 INFO Uploading wwfxhwdjhkimna0711gqgc7dkhhr3zc2-b (216B)13322026/11/09 12:10:05 WARN Failed to register uploaded object key=wwfxhwdjhkimna0711gqgc7dkhhr3zc2.ls error="server returned 404: 404 page not found\n"13332026/11/09 12:10:05 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13342026/11/09 12:10:05 WARN Failed to register uploaded object key=nar/0j6bflr26w232pvsn1mzyr0z80slcvv4y49zf16ykvxl9yysrg2j.nar.zst error="server returned 404: 404 page not found\n"13352026/11/09 12:10:05 WARN Failed to register uploaded object key=07xrrwkxfkzqhlgb4j8kldlkkbxaky4y.ls error="server returned 404: 404 page not found\n"13362026/11/09 12:10:05 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13372026/11/09 12:10:05 WARN Failed to register uploaded object key=ixfv4i8b5qjdb1w7bl8g4idkq3yd6f2w.ls error="server returned 404: 404 page not found\n"13382026/11/09 12:10:05 INFO Signed narinfos id=2 count=213392026/11/09 12:10:05 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13402026/11/09 12:10:05 INFO Signed narinfos id=1 count=213412026/11/09 12:10:05 INFO Uploading 4 narinfos13422026/11/09 12:10:05 WARN Failed to register uploaded object key=07xrrwkxfkzqhlgb4j8kldlkkbxaky4y.narinfo error="server returned 404: 404 page not found\n"13432026/11/09 12:10:05 WARN Failed to register uploaded object key=wwfxhwdjhkimna0711gqgc7dkhhr3zc2.narinfo error="server returned 404: 404 page not found\n"13442026/11/09 12:10:05 WARN Failed to register uploaded object key=ixfv4i8b5qjdb1w7bl8g4idkq3yd6f2w.narinfo error="server returned 404: 404 page not found\n"13452026/11/09 12:10:05 WARN Failed to register uploaded object key=07xrrwkxfkzqhlgb4j8kldlkkbxaky4y.narinfo error="server returned 404: 404 page not found\n"13462026/11/09 12:10:05 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1347--- PASS: TestReadProxy404 (0.60s)1348=== CONT TestObjectStatsUpdatedOncePerCommit13492026/11/09 12:10:05 INFO Completed upload id=1 objects=6 duration=8.015352ms13502026/11/09 12:10:05 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13512026/11/09 12:10:05 INFO Completed upload id=2 objects=6 duration=1.134551ms13522026/11/09 12:10:05 INFO Upload complete. (158ms)13532026/11/09 12:10:05 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=01354=== NAME TestClientFallsBackToClosures1355 client_pushes_test.go:112: Retrieved narinfo from S3:1356 StorePath: /build/TestClientFallsBackToClosures1863804812/001/store/07xrrwkxfkzqhlgb4j8kldlkkbxaky4y-shared-dep1357 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1358 Compression: zstd1359 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821360 NarSize: 1361361 References: 1362 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n13632026/11/09 12:10:05 INFO Vacuumed table table=pending_closures1364 client_pushes_test.go:112: Retrieved narinfo from S3:1365 StorePath: /build/TestClientFallsBackToClosures1863804812/001/store/ixfv4i8b5qjdb1w7bl8g4idkq3yd6f2w-a1366 URL: nar/0j6bflr26w232pvsn1mzyr0z80slcvv4y49zf16ykvxl9yysrg2j.nar.zst1367 Compression: zstd1368 NarHash: sha256:0j6bflr26w232pvsn1mzyr0z80slcvv4y49zf16ykvxl9yysrg2j1369 NarSize: 2161370 References: /build/TestClientFallsBackToClosures1863804812/001/store/07xrrwkxfkzqhlgb4j8kldlkkbxaky4y-shared-dep1371 CA: text:sha256:11pvzrd7gcb989ddnn7583jhvccyqcypjjm3nz8m71dl2dcwh13c13722026/11/09 12:10:05 INFO Vacuumed table table=pending_objects13732026/11/09 12:10:05 INFO Aborted multipart uploads count=0 kept=013742026/11/09 12:10:05 INFO Vacuumed table table=multipart_uploads1375 client_pushes_test.go:112: Retrieved narinfo from S3:1376 StorePath: /build/TestClientFallsBackToClosures1863804812/001/store/wwfxhwdjhkimna0711gqgc7dkhhr3zc2-b1377 URL: nar/0j6bflr26w232pvsn1mzyr0z80slcvv4y49zf16ykvxl9yysrg2j.nar.zst1378 Compression: zstd1379 NarHash: sha256:0j6bflr26w232pvsn1mzyr0z80slcvv4y49zf16ykvxl9yysrg2j1380 NarSize: 2161381 References: /build/TestClientFallsBackToClosures1863804812/001/store/07xrrwkxfkzqhlgb4j8kldlkkbxaky4y-shared-dep1382 CA: text:sha256:11pvzrd7gcb989ddnn7583jhvccyqcypjjm3nz8m71dl2dcwh13c13832026/11/09 12:10:05 INFO Vacuumed table table=closures13842026/11/09 12:10:05 INFO Vacuumed table table=objects1385--- PASS: TestClientFallsBackToClosures (3.88s)1386=== CONT TestReadProxyNarStreaming1387--- PASS: TestGetExistingObjectsLocksRows (0.66s)1388=== CONT TestPush_OverlappingRootsStoreOneRowPerKey13892026/11/09 12:10:05 INFO Received uploads request method=POST path=/api/pending_closures13902026/11/09 12:10:05 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst13912026/11/09 12:10:05 INFO Received uploads request method=POST path=/api/pending_closures1392--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.37s)1393=== CONT TestReadProxyContentNegotiation13942026/11/09 12:10:05 INFO Received push request method=POST path=/api/pushes13952026/11/09 12:10:05 INFO Received complete push request method=POST path=/api/pushes/1/complete1396--- PASS: TestReadProxyConditionalGet (0.54s)1397=== CONT TestReadRedirectUsesPublicS3URL1398--- PASS: TestService_Rustfstest (0.47s)1399=== CONT TestReadProxyNarinfoAlreadyDecompressed1400--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.67s)1401=== CONT TestReadProxyRangeRequest1402--- PASS: TestReadProxyHead (0.45s)1403=== CONT TestReadProxyNarinfo1404--- PASS: TestPushWaitsForSweepHoldingRow (0.94s)1405=== CONT TestReadRedirectKeepsNarinfoProxied14062026/11/09 12:10:05 INFO lead: released remote=192.0.2.1:12341407--- PASS: TestLeadElectsOneAndHandsOver (4.47s)1408=== CONT TestIsValidCachePath1409=== RUN TestIsValidCachePath/narinfo1410=== PAUSE TestIsValidCachePath/narinfo1411=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1412=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1413=== RUN TestIsValidCachePath/nar_zst1414=== PAUSE TestIsValidCachePath/nar_zst1415=== RUN TestIsValidCachePath/nar_xz1416=== PAUSE TestIsValidCachePath/nar_xz1417=== RUN TestIsValidCachePath/nar_bz21418=== PAUSE TestIsValidCachePath/nar_bz21419=== RUN TestIsValidCachePath/nar_uncompressed1420=== PAUSE TestIsValidCachePath/nar_uncompressed1421=== RUN TestIsValidCachePath/ls1422=== PAUSE TestIsValidCachePath/ls1423=== RUN TestIsValidCachePath/log1424=== PAUSE TestIsValidCachePath/log1425=== RUN TestIsValidCachePath/realisation1426=== PAUSE TestIsValidCachePath/realisation1427=== RUN TestIsValidCachePath/nix-cache-info1428=== PAUSE TestIsValidCachePath/nix-cache-info1429=== RUN TestIsValidCachePath/index.html1430=== PAUSE TestIsValidCachePath/index.html1431=== RUN TestIsValidCachePath/traversal_parent1432=== PAUSE TestIsValidCachePath/traversal_parent1433=== RUN TestIsValidCachePath/traversal_in_middle1434=== PAUSE TestIsValidCachePath/traversal_in_middle1435=== RUN TestIsValidCachePath/invalid_char_e1436=== PAUSE TestIsValidCachePath/invalid_char_e1437=== RUN TestIsValidCachePath/invalid_char_u1438=== PAUSE TestIsValidCachePath/invalid_char_u1439=== RUN TestIsValidCachePath/random_path1440=== PAUSE TestIsValidCachePath/random_path1441=== RUN TestIsValidCachePath/empty1442=== PAUSE TestIsValidCachePath/empty1443=== RUN TestIsValidCachePath/leading_slash1444=== PAUSE TestIsValidCachePath/leading_slash1445=== RUN TestIsValidCachePath/wrong_extension1446=== PAUSE TestIsValidCachePath/wrong_extension1447=== RUN TestIsValidCachePath/short_hash1448=== PAUSE TestIsValidCachePath/short_hash1449=== CONT TestReadRedirectNar1450=== NAME TestClientMultipleUploads1451 client_integration_test.go:405: Created store path 0: /build/TestClientMultipleUploads1763194385/001/store/66a8c404mm175l9g6mkdkm1krlwvss71-test-file-0.txt14522026/11/09 12:10:05 INFO Completed push id=1 objects=6 duration=691.52837ms1453--- PASS: TestPush_CompleteCommitsEveryRoot (1.32s)1454=== CONT TestParseSingleRange1455=== RUN TestParseSingleRange/none1456=== PAUSE TestParseSingleRange/none1457=== RUN TestParseSingleRange/unknown_unit1458=== PAUSE TestParseSingleRange/unknown_unit1459=== RUN TestParseSingleRange/multi-range_ignored1460=== PAUSE TestParseSingleRange/multi-range_ignored1461=== RUN TestParseSingleRange/malformed_no_dash1462=== PAUSE TestParseSingleRange/malformed_no_dash1463=== RUN TestParseSingleRange/malformed_both_empty1464=== PAUSE TestParseSingleRange/malformed_both_empty1465=== RUN TestParseSingleRange/malformed_end_before_start1466=== PAUSE TestParseSingleRange/malformed_end_before_start1467=== RUN TestParseSingleRange/closed1468=== PAUSE TestParseSingleRange/closed1469=== RUN TestParseSingleRange/open-ended1470=== PAUSE TestParseSingleRange/open-ended1471=== RUN TestParseSingleRange/end_clamped_to_size1472=== PAUSE TestParseSingleRange/end_clamped_to_size1473=== RUN TestParseSingleRange/suffix1474=== PAUSE TestParseSingleRange/suffix1475=== RUN TestParseSingleRange/suffix_exceeds_size1476=== PAUSE TestParseSingleRange/suffix_exceeds_size1477=== RUN TestParseSingleRange/single_byte1478=== PAUSE TestParseSingleRange/single_byte1479=== RUN TestParseSingleRange/start_past_EOF1480=== PAUSE TestParseSingleRange/start_past_EOF1481=== RUN TestParseSingleRange/start_far_past_EOF1482=== PAUSE TestParseSingleRange/start_far_past_EOF1483=== CONT TestPresentNotReportedWhileGCDeletesClosure1484=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1485=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1486=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1487=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1488=== CONT TestMetricsCommit1489=== NAME TestClientMultipleUploads1490 client_integration_test.go:405: Created store path 1: /build/TestClientMultipleUploads1763194385/001/store/maaxy0hckh5q55blsp9nq5m9skdvnx55-test-file-1.txt1491--- PASS: TestReadProxyNarStreaming (0.89s)1492=== CONT TestPresentRefreshesOnlyStaleClosures14932026/11/09 12:10:06 WARN Force mode enabled - objects will be deleted immediately without grace period1494--- PASS: TestReadRedirectUsesPublicS3URL (0.85s)1495=== CONT TestObjectStatsTrigger1496--- PASS: TestReadProxyInvalidPath (1.19s)1497=== CONT TestPresentReportsOnlyClosureRoots1498=== NAME TestClientCADerivations1499 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations2666827775/001/store/qlqyc7s3z24jf0l16l9x4i7ac7zkzd1s-ca-test15002026/11/09 12:10:06 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=015012026/11/09 12:10:06 INFO Vacuumed table table=pending_closures15022026/11/09 12:10:06 INFO Vacuumed table table=pending_objects15032026/11/09 12:10:06 INFO Vacuumed table table=multipart_uploads15042026/11/09 12:10:06 INFO Vacuumed table table=closures15052026/11/09 12:10:06 INFO Vacuumed table table=objects1506--- PASS: TestSweepRechecksPendingAfterLocking (1.77s)1507=== CONT TestPendingCleanupUsesOneCutoff1508--- PASS: TestReadProxyDisabled (1.14s)1509=== CONT TestCreatePin_ReservedPins1510--- PASS: TestReadRedirectKeepsNarinfoProxied (0.78s)1511=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded15122026/11/09 12:10:06 INFO Received push request method=POST path=/api/pushes1513--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (1.09s)1514=== CONT TestOrphanedObjectsGCStressTest15152026/11/09 12:10:06 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41065/oidc1516--- PASS: TestReadProxyRangeRequest (0.98s)1517=== CONT TestMultipartCleanup1518--- PASS: TestObjectStatsUpdatedOncePerCommit (1.19s)1519=== CONT TestOrphanedObjectsGC1520=== NAME TestClientMultipleUploads1521 client_integration_test.go:405: Created store path 2: /build/TestClientMultipleUploads1763194385/001/store/69w3f18g07sncsi78f9bmmgsbzc1amr8-test-file-2.txt1522--- PASS: TestReadProxyNarinfoAlreadyDecompressed (1.22s)1523=== CONT TestServerTLSConfig1524=== RUN TestServerTLSConfig/no_client_CA1525=== PAUSE TestServerTLSConfig/no_client_CA1526=== RUN TestServerTLSConfig/missing_CA_file1527=== PAUSE TestServerTLSConfig/missing_CA_file1528=== RUN TestServerTLSConfig/not_a_PEM_file1529=== PAUSE TestServerTLSConfig/not_a_PEM_file1530=== CONT TestService_NativeMTLS1531--- PASS: TestReadRedirectNar (0.80s)1532=== CONT TestCreatePendingClosureRejectsOversizedNAR15332026/11/09 12:10:06 INFO Received uploads request method=POST path=/api/pending_closures1534--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1535=== CONT TestMetricsInventory1536--- PASS: TestReadProxyContentNegotiation (1.35s)1537=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit15382026/11/09 12:10:06 INFO Received push request method=POST path=/api/pushes15392026/11/09 12:10:06 INFO Received complete push request method=POST path=/api/pushes/1/complete15402026/11/09 12:10:06 INFO Completed push id=1 objects=4 duration=11.248002ms15412026/11/09 12:10:06 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1542--- PASS: TestReadProxyNarinfo (1.33s)1543=== CONT TestNARDeduplicationMetadataUploadBug15442026/11/09 12:10:06 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15452026/11/09 12:10:06 INFO Completed upload id=2 objects=2 duration=1.253011ms1546--- PASS: TestMetricsCommit (0.75s)1547=== CONT TestPush_SignsNarinfosOfItsPendingObjects15482026/11/09 12:10:06 INFO Received uploads request method=POST path=/api/pending_closures15492026/11/09 12:10:06 INFO Received uploads request method=POST path=/api/pending_closures1550--- PASS: TestPresentRefreshesOnlyStaleClosures (0.73s)1551=== CONT TestPush_RejectsBadRequests15522026/11/09 12:10:06 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15532026/11/09 12:10:06 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZmE2ZTA3NDgtNzlhZC00MmJjLTkzMzQtZWQzYjc0ZTA3NTVhLjQyYTFlMTYxLTZlMjYtNDVhZS05ZGRiLTJmYjdhMjA0ZGFhNXgxNzk0MjI2MjA2NzE4ODM3ODgw15542026/11/09 12:10:06 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZmE2ZTA3NDgtNzlhZC00MmJjLTkzMzQtZWQzYjc0ZTA3NTVhLjQyYTFlMTYxLTZlMjYtNDVhZS05ZGRiLTJmYjdhMjA0ZGFhNXgxNzk0MjI2MjA2NzE4ODM3ODgw parts=11555--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.80s)1556=== CONT TestPush_RootsAreLockedInByteOrder15572026/11/09 12:10:06 INFO Received push request method=POST path=/api/pushes1558=== NAME TestClientCADerivations1559 client_ca_test.go:139: Found 1 dependencies (including self)15602026/11/09 12:10:06 INFO Object in database but missing from S3 key=x667i3r20rpsyp5f0vg13zvlqz1j4111.ls15612026/11/09 12:10:06 WARN Found objects in DB but missing from S3, will re-upload count=115622026/11/09 12:10:06 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)1563--- PASS: TestObjectStatsTrigger (0.77s)1564=== CONT TestPush_CompleteWaitsForCleanupOfThePush15652026/11/09 12:10:06 INFO Received complete push request method=POST path=/api/pushes/2/complete15662026/11/09 12:10:06 WARN Failed to register uploaded object key=x667i3r20rpsyp5f0vg13zvlqz1j4111.ls error="server returned 404: 404 page not found\n"15672026/11/09 12:10:06 INFO Completed push id=2 objects=3 duration=6.737961ms15682026/11/09 12:10:06 INFO Upload complete. (973ms)1569=== NAME TestClientIntegration1570 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1571 client_integration_test.go:335: Decompressed .ls content (49 bytes):1572 {"version":1,"root":{"type":"regular","size":39}}15732026/11/09 12:10:06 INFO Received uploads request method=POST path=/api/pending_closures15742026/11/09 12:10:06 INFO Received push request method=POST path=/api/pushes15752026/11/09 12:10:06 INFO Received uploads request method=POST path=/api/pending_closures15762026/11/09 12:10:06 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)15772026/11/09 12:10:06 INFO Uploading 66a8c404mm175l9g6mkdkm1krlwvss71-test-file-0.txt (160B)15782026/11/09 12:10:06 INFO Uploading maaxy0hckh5q55blsp9nq5m9skdvnx55-test-file-1.txt (160B)15792026/11/09 12:10:06 INFO Uploading 69w3f18g07sncsi78f9bmmgsbzc1amr8-test-file-2.txt (160B)15802026/11/09 12:10:06 INFO Received uploads request method=POST path=/api/pending_closures15812026/11/09 12:10:06 INFO Received cleanup request method=DELETE path=/api/pending_closures15822026/11/09 12:10:06 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"15832026/11/09 12:10:06 WARN Failed to register uploaded object key=69w3f18g07sncsi78f9bmmgsbzc1amr8.ls error="server returned 404: 404 page not found\n"15842026/11/09 12:10:06 WARN Failed to register uploaded object key=66a8c404mm175l9g6mkdkm1krlwvss71.ls error="server returned 404: 404 page not found\n"15852026/11/09 12:10:06 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"15862026/11/09 12:10:06 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"15872026/11/09 12:10:06 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15882026/11/09 12:10:06 WARN Failed to register uploaded object key=maaxy0hckh5q55blsp9nq5m9skdvnx55.ls error="server returned 404: 404 page not found\n"15892026/11/09 12:10:06 INFO Signed narinfos id=1 count=315902026/11/09 12:10:06 INFO Uploading 3 narinfos15912026/11/09 12:10:06 WARN Failed to register uploaded object key=maaxy0hckh5q55blsp9nq5m9skdvnx55.narinfo error="server returned 404: 404 page not found\n"15922026/11/09 12:10:06 WARN Failed to register uploaded object key=69w3f18g07sncsi78f9bmmgsbzc1amr8.narinfo error="server returned 404: 404 page not found\n"15932026/11/09 12:10:06 INFO Received complete push request method=POST path=/api/pushes/1/complete15942026/11/09 12:10:06 WARN Failed to register uploaded object key=66a8c404mm175l9g6mkdkm1krlwvss71.narinfo error="server returned 404: 404 page not found\n"15952026/11/09 12:10:06 INFO Completed push id=1 objects=9 duration=11.811447ms15962026/11/09 12:10:06 INFO Upload complete. (120ms)1597=== NAME TestClientMultipleUploads1598 client_integration_test.go:416: Uploaded 3 paths in 514.509305ms1599--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.76s)1600=== CONT TestEnsureAbortUploadsRule1601--- PASS: TestClientMultipleUploads (3.69s)1602=== CONT TestCacheConfigHandlerMaxNarSize1603--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1604=== CONT TestGenerateLandingPage1605--- PASS: TestGenerateLandingPage (0.00s)1606=== CONT TestGCTaskStore_StartNew1607--- PASS: TestGCTaskStore_StartNew (0.00s)1608=== CONT TestSharedNarBothUploadsComplete16092026/11/09 12:10:07 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=016102026/11/09 12:10:07 INFO Received push request method=POST path=/api/pushes16112026/11/09 12:10:07 INFO Received create pin request method=POST path=/api/pins/myapp16122026/11/09 12:10:07 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16132026/11/09 12:10:07 INFO Uploading qlqyc7s3z24jf0l16l9x4i7ac7zkzd1s-ca-test (144B)16142026/11/09 12:10:07 WARN Failed to register uploaded object key=qlqyc7s3z24jf0l16l9x4i7ac7zkzd1s.ls error="server returned 404: 404 page not found\n"16152026/11/09 12:10:07 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"16162026/11/09 12:10:07 WARN Failed to register uploaded object key=log/kjb7vamalr8cwgxz3k0gf39kph42qnxf-ca-test.drv error="server returned 404: 404 page not found\n"16172026/11/09 12:10:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16182026/11/09 12:10:07 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC62026700/001/store/s83mxvz5ng4k45jnqh2dwfhwiywi2w0y-pinned-file.txt narinfo_key=s83mxvz5ng4k45jnqh2dwfhwiywi2w0y.narinfo16192026/11/09 12:10:07 INFO Signed narinfos id=1 count=116202026/11/09 12:10:07 INFO Uploading 1 narinfos16212026/11/09 12:10:07 INFO Starting cleanup of old closures method=DELETE path=/api/closures16222026/11/09 12:10:07 INFO Garbage collection started16232026/11/09 12:10:07 INFO Received complete push request method=POST path=/api/pushes/1/complete16242026/11/09 12:10:07 WARN Failed to register uploaded object key=qlqyc7s3z24jf0l16l9x4i7ac7zkzd1s.narinfo error="server returned 404: 404 page not found\n"16252026/11/09 12:10:07 INFO Aborted multipart uploads count=0 kept=016262026/11/09 12:10:07 INFO Completed push id=1 objects=4 duration=10.284174ms16272026/11/09 12:10:07 INFO Upload complete. (141ms)16282026/11/09 12:10:07 WARN Force mode enabled - objects will be deleted immediately without grace period16292026/11/09 12:10:07 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=01630=== NAME TestClientCADerivations1631 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations2666827775/001/store/qlqyc7s3z24jf0l16l9x4i7ac7zkzd1s-ca-test1632 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1633 Compression: zstd1634 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1635 NarSize: 1441636 References: 1637 Deriver: /build/TestClientCADerivations2666827775/001/store/kjb7vamalr8cwgxz3k0gf39kph42qnxf-ca-test.drv1638 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1639 client_ca_test.go:185: Checking for realisation files in S3...16402026/11/09 12:10:07 INFO Vacuumed table table=pending_closures16412026/11/09 12:10:07 INFO Vacuumed table table=pending_objects16422026/11/09 12:10:07 INFO Vacuumed table table=multipart_uploads1643 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1644 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache16452026/11/09 12:10:07 INFO Vacuumed table table=closures16462026/11/09 12:10:07 INFO Vacuumed table table=objects16472026/11/09 12:10:07 INFO Received push request method=POST path=/api/pushes1648--- PASS: TestMetricsInventory (0.64s)1649=== CONT TestSweepSkipsRowsLockedByPush16502026/11/09 12:10:07 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)16512026/11/09 12:10:07 INFO Received complete push request method=POST path=/api/pushes/3/complete16522026/11/09 12:10:07 WARN Failed to register uploaded object key=x667i3r20rpsyp5f0vg13zvlqz1j4111.ls error="server returned 404: 404 page not found\n"16532026/11/09 12:10:07 INFO Received push request method=POST path=/api/pushes16542026/11/09 12:10:07 INFO Completed push id=3 objects=3 duration=3.978696ms16552026/11/09 12:10:07 INFO Upload complete. (205ms)1656=== NAME TestClientIntegration1657 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1658 client_integration_test.go:352: Decompressed .ls content (49 bytes):1659 {"version":1,"root":{"type":"regular","size":39}}1660 client_integration_test.go:363: Testing garbage collection...16612026/11/09 12:10:07 WARN Rate limiter enabled after throttle name=s3-test rate=516622026/11/09 12:10:07 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1663=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1664 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101665 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001666--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.96s)1667=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed16682026/11/09 12:10:07 INFO Received complete push request method=POST path=/api/pushes/1/complete1669--- PASS: TestPresentReportsOnlyClosureRoots (1.16s)1670=== CONT TestPendingClosureWriteTimeout/empty1671=== CONT TestResolveDBConnectionString/flag_wins1672=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed16732026/11/09 12:10:07 INFO Received uploads request method=POST path=/api/pending_closures16742026/11/09 12:10:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16752026/11/09 12:10:07 WARN mTLS auth: subject not in bound subjects subject="CN=reader"16762026/11/09 12:10:07 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1677--- PASS: TestService_NativeMTLS (0.85s)1678=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed16792026/11/09 12:10:07 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZmE2ZTA3NDgtNzlhZC00MmJjLTkzMzQtZWQzYjc0ZTA3NTVhLjViMDc5ODhkLTc0M2ItNDAyNi05MjQ1LTJjY2Q2Mjc0ZDVlZXgxNzk0MjI2MjA2Njg3NDUyNDM2 parts=1216802026/11/09 12:10:07 INFO Received uploads request method=POST path=/api/pending_closures1681--- PASS: TestCompletedNarNotReofferedAcrossClosures (2.44s)1682=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost16832026/11/09 12:10:07 INFO Received push request method=POST path=/api/pushes16842026/11/09 12:10:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16852026/11/09 12:10:07 INFO Signed narinfos id=1 count=116862026/11/09 12:10:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16872026/11/09 12:10:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16882026/11/09 12:10:07 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"16892026/11/09 12:10:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16902026/11/09 12:10:07 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"16912026/11/09 12:10:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16922026/11/09 12:10:07 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=116932026/11/09 12:10:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16942026/11/09 12:10:07 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo16952026/11/09 12:10:07 INFO Completed push id=1 objects=4 duration=164.732774ms1696--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.71s)1697=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed16982026/11/09 12:10:07 INFO Received push request method=POST path=/api/pushes1699--- PASS: TestDeleteClosuresRacingPins (6.14s)1700=== CONT TestResolveDBConnectionString/nothing_configured1701=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1702=== NAME TestNARDeduplicationMetadataUploadBug1703 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug2627766507/001/store/6bp977qfsm2bj2r6707ksb54mppy3bpk-file1.txt17042026/11/09 12:10:07 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux17052026/11/09 12:10:07 WARN Refused reserved pin name=worker-x86_64-linux17062026/11/09 12:10:07 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux17072026/11/09 12:10:07 INFO Received create pin request method=POST path=/api/pins/my-app17082026/11/09 12:10:07 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1709--- PASS: TestCreatePin_ReservedPins (1.26s)1710=== CONT TestPendingClosureWriteTimeout/670k_objects1711=== CONT TestPendingClosureWriteTimeout/400_objects1712=== CONT TestResolveDBConnectionString/file_when_flag_empty1713=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1714=== CONT TestResolveDBConnectionString/missing_file_is_an_error1715=== CONT TestProxyWriteTimeout/narinfo1716=== CONT TestProxyWriteTimeout/unknown_size1717=== CONT TestProxyWriteTimeout/10_GiB_nar1718=== CONT TestProxyWriteTimeout/1_GiB_nar1719--- PASS: TestProxyWriteTimeout (1.55s)1720 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1721 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1722 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1723 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1724=== CONT TestIsValidUploadKey/narinfo1725=== CONT TestIsValidUploadKey/unknown_type1726=== CONT TestIsValidUploadKey/empty_key1727=== CONT TestIsValidUploadKey/absolute1728=== CONT TestIsValidUploadKey/traversal_nar1729=== CONT TestIsValidUploadKey/traversal1730--- PASS: TestResolveDBConnectionString (0.00s)1731 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1732 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1733 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1734 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1735 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1736=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1737=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1738=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1739=== CONT TestIsValidUploadKey/index.html1740=== CONT TestIsValidUploadKey/nix-cache-info1741=== CONT TestIsValidUploadKey/realisation_plus_in_output1742=== CONT TestIsValidUploadKey/realisation1743=== CONT TestIsValidUploadKey/build_log_equals1744=== CONT TestIsValidUploadKey/build_log_question_mark1745=== CONT TestIsValidUploadKey/nar_plain1746=== CONT TestIsValidUploadKey/listing1747=== CONT TestIsValidUploadKey/nar_xz1748=== CONT TestIsValidUploadKey/build_log_plus_in_name1749=== CONT TestIsValidUploadKey/nar_zst1750=== CONT TestIsValidUploadKey/build_log_home-manager_file1751=== CONT TestIsValidUploadKey/build_log1752--- PASS: TestIsValidUploadKey (1.55s)1753 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1754 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1755 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1756 --- PASS: TestIsValidUploadKey/absolute (0.00s)1757 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1758 --- PASS: TestIsValidUploadKey/traversal (0.00s)1759 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1760 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1761 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1762 --- PASS: TestIsValidUploadKey/index.html (0.00s)1763 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1764 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1765 --- PASS: TestIsValidUploadKey/realisation (0.00s)1766 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1767 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1768 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1769 --- PASS: TestIsValidUploadKey/listing (0.00s)1770 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1771 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1772 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1773 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1774 --- PASS: TestIsValidUploadKey/build_log (0.00s)1775=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17762026/11/09 12:10:07 INFO Received uploads request method=POST path=/1777=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17782026/11/09 12:10:07 INFO Received request for more parts method=POST path=/1779=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17802026/11/09 12:10:07 INFO Received complete multipart upload request method=POST path=/1781=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17822026/11/09 12:10:07 INFO Received uploads request method=POST path=/1783=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure1784--- PASS: TestUploadHandlersRejectInvalidKeys (1.62s)1785 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1786 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1787 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1788 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)17892026/11/09 12:10:07 INFO Received uploads request method=POST path=/17902026/11/09 12:10:07 INFO Received cleanup request method=DELETE path=/api/pending_closures17912026/11/09 12:10:07 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket82/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""17922026/11/09 12:10:07 INFO Aborted multipart uploads count=0 kept=117932026/11/09 12:10:07 INFO Received cleanup request method=DELETE path=/api/pending_closures17942026/11/09 12:10:07 INFO Aborted multipart uploads count=1 kept=01795=== RUN TestPush_RejectsBadRequests/root_not_in_objects1796=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1797=== RUN TestPush_RejectsBadRequests/no_roots1798=== PAUSE TestPush_RejectsBadRequests/no_roots1799=== RUN TestPush_RejectsBadRequests/no_objects1800=== PAUSE TestPush_RejectsBadRequests/no_objects1801=== RUN TestPush_RejectsBadRequests/bad_root1802=== PAUSE TestPush_RejectsBadRequests/bad_root1803=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18042026/11/09 12:10:07 INFO Received request for more parts method=POST path=/1805--- PASS: TestMultipartCleanup (1.16s)1806=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18072026/11/09 12:10:07 INFO Received complete multipart upload request method=POST path=/18082026/11/09 12:10:07 INFO Aborted multipart uploads count=0 kept=018092026/11/09 12:10:07 WARN Force mode enabled - objects will be deleted immediately without grace period18102026/11/09 12:10:07 INFO Received push request method=POST path=/api/pushes1811=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows18122026/11/09 12:10:07 INFO Received push request method=POST path=/api/pushes1813=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check18142026/11/09 12:10:07 INFO Installed lifecycle rule aborting incomplete NAR uploads bucket=bucket89 days=21815--- PASS: TestEnsureAbortUploadsRule (0.56s)1816=== CONT TestClientErrorHandling/InvalidStorePath18172026/11/09 12:10:07 INFO Starting cleanup of old closures method=DELETE path=/api/closures18182026/11/09 12:10:07 INFO Garbage collection started18192026/11/09 12:10:07 INFO Received uploads request method=POST path=/api/pending_closures18202026-11-09 12:10:07.556 UTC [1616] ERROR: could not obtain lock on row in relation "closures"18212026-11-09 12:10:07.556 UTC [1616] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT18222026-11-09 12:10:07.557 UTC [1616] ERROR: could not obtain lock on row in relation "closures"18232026-11-09 12:10:07.557 UTC [1616] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT18242026-11-09 12:10:07.557 UTC [1616] ERROR: could not obtain lock on row in relation "closures"18252026-11-09 12:10:07.557 UTC [1616] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT18262026-11-09 12:10:07.557 UTC [1616] ERROR: could not obtain lock on row in relation "closures"18272026-11-09 12:10:07.557 UTC [1616] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT18282026-11-09 12:10:07.558 UTC [1616] ERROR: could not obtain lock on row in relation "closures"18292026-11-09 12:10:07.558 UTC [1616] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT18302026/11/09 12:10:07 INFO Aborted multipart uploads count=0 kept=018312026/11/09 12:10:07 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=01832--- PASS: TestPush_RootsAreLockedInByteOrder (0.78s)1833=== CONT TestClientErrorHandling/ServerNotAvailable18342026/11/09 12:10:07 INFO Vacuumed table table=pending_closures18352026/11/09 12:10:07 INFO Vacuumed table table=pending_objects18362026/11/09 12:10:07 INFO Vacuumed table table=multipart_uploads18372026/11/09 12:10:07 INFO Received uploads request method=POST path=/api/pending_closures18382026/11/09 12:10:07 INFO Vacuumed table table=closures18392026/11/09 12:10:07 INFO Vacuumed table table=objects18402026/11/09 12:10:07 INFO Received complete push request method=POST path=/api/pushes/2/complete18412026/11/09 12:10:07 INFO Completed push id=2 objects=4 duration=6.065895ms1842--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (1.05s)1843=== CONT TestClientErrorHandling/InvalidAuthToken18442026/11/09 12:10:07 WARN Force mode enabled - objects will be deleted immediately without grace period18452026/11/09 12:10:07 INFO Aborted multipart uploads count=0 kept=018462026/11/09 12:10:07 WARN Force mode enabled - objects will be deleted immediately without grace period18472026/11/09 12:10:07 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=018482026/11/09 12:10:07 INFO Vacuumed table table=pending_closures18492026/11/09 12:10:07 INFO Vacuumed table table=pending_objects18502026/11/09 12:10:07 INFO Vacuumed table table=multipart_uploads18512026/11/09 12:10:07 INFO Vacuumed table table=closures18522026/11/09 12:10:07 INFO Vacuumed table table=objects18532026/11/09 12:10:07 INFO Received uploads request method=POST path=/api/pending_closures18542026/11/09 12:10:07 INFO Aborted multipart uploads count=0 kept=01855=== NAME TestOrphanedObjectsGC1856 orphaned_objects_gc_test.go:287: GC Test Summary:1857 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1858 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1859 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1860 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1861 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1862--- PASS: TestOrphanedObjectsGC (1.37s)1863=== CONT TestCacheConfigHandler/full_config,_no_issuer1864=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1865=== CONT TestCacheConfigHandler/no_signing_keys1866=== CONT TestCacheConfigHandler/no_cache_url_configured1867--- PASS: TestCacheConfigHandler (0.00s)1868 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1869 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1870 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1871 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1872=== CONT TestGCEndsOnShutdown/before_the_run18732026/11/09 12:10:07 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/present18742026/11/09 12:10:07 INFO Received uploads request method=POST path=/api/pending_closures18752026/11/09 12:10:07 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=018762026/11/09 12:10:07 INFO Vacuumed table table=pending_closures18772026/11/09 12:10:07 INFO Vacuumed table table=pending_objects18782026/11/09 12:10:07 INFO Vacuumed table table=multipart_uploads18792026/11/09 12:10:07 INFO Vacuumed table table=closures18802026/11/09 12:10:07 WARN Force mode enabled - objects will be deleted immediately without grace period18812026/11/09 12:10:07 INFO Vacuumed table table=objects18822026/11/09 12:10:07 INFO Received push request method=POST path=/api/pushes18832026/11/09 12:10:07 INFO Received uploads request method=POST path=/api/pending_closures18842026/11/09 12:10:07 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18852026/11/09 12:10:07 INFO Uploading 6bp977qfsm2bj2r6707ksb54mppy3bpk-file1.txt (160B)18862026/11/09 12:10:07 WARN Failed to register uploaded object key=6bp977qfsm2bj2r6707ksb54mppy3bpk.ls error="server returned 404: 404 page not found\n"18872026/11/09 12:10:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18882026/11/09 12:10:07 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"18892026/11/09 12:10:07 INFO Signed narinfos id=1 count=118902026/11/09 12:10:07 INFO Uploading 1 narinfos18912026/11/09 12:10:07 WARN Request failed, retrying attempt=2 backoff=215.493903ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18922026/11/09 12:10:07 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=018932026-11-09 12:10:07.841 UTC [1623] ERROR: Push does not exist: id=118942026-11-09 12:10:07.841 UTC [1623] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE18952026-11-09 12:10:07.841 UTC [1623] STATEMENT: SELECT commit_push($1)18962026/11/09 12:10:07 INFO Vacuumed table table=pending_closures1897--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (0.95s)18982026/11/09 12:10:07 INFO Received complete push request method=POST path=/api/pushes/1/complete1899=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark19002026/11/09 12:10:07 WARN Failed to register uploaded object key=6bp977qfsm2bj2r6707ksb54mppy3bpk.narinfo error="server returned 404: 404 page not found\n"19012026/11/09 12:10:07 INFO Vacuumed table table=pending_objects19022026/11/09 12:10:07 INFO Vacuumed table table=multipart_uploads19032026/11/09 12:10:07 INFO Vacuumed table table=closures19042026/11/09 12:10:07 INFO Vacuumed table table=objects1905--- PASS: TestSweepSkipsRowsLockedByPush (0.68s)1906=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete19072026/11/09 12:10:07 INFO Completed push id=1 objects=3 duration=7.174645ms19082026/11/09 12:10:07 INFO Upload complete. (236ms)1909=== NAME TestNARDeduplicationMetadataUploadBug1910 metadata_upload_test.go:54: Retrieved narinfo from S3:1911 StorePath: /build/TestNARDeduplicationMetadataUploadBug2627766507/001/store/6bp977qfsm2bj2r6707ksb54mppy3bpk-file1.txt1912 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1913 Compression: zstd1914 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1915 NarSize: 1601916 References: 1917 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1918 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1919 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1920 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}19212026/11/09 12:10:07 INFO Received uploads request method=POST path=/api/pending_closures19222026/11/09 12:10:07 INFO Received uploads request method=POST path=/api/pending_closures19232026/11/09 12:10:07 INFO Received uploads request method=POST path=/api/pending_closures1924--- PASS: TestConnectWaitsForAPeerMigration (6.71s)1925=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1926=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19272026/11/09 12:10:07 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]1928=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1929=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19302026/11/09 12:10:07 WARN Authentication failed token_preview=eyJhbGciOi...AweECKEyOg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1931--- PASS: TestService_AuthMiddleware_OIDC (0.64s)1932 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1933 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1934 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1935 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1936=== CONT TestService_RequireScope_OIDC/builder_may_write1937=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1938=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1939=== CONT TestService_RequireScope_OIDC/writer_implies_read1940=== CONT TestService_RequireScope_OIDC/reader_may_read1941=== CONT TestService_RequireScope_OIDC/static_token_may_write1942=== CONT TestService_RequireScope_OIDC/static_token_may_admin1943=== CONT TestService_RequireScope_OIDC/reader_may_not_write1944=== CONT TestService_RequireScope_OIDC/ops_may_not_write1945=== CONT TestService_RequireScope_OIDC/ops_may_admin1946=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1947=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19482026/11/09 12:10:07 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]1949=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1950=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1951=== CONT TestIsValidCachePath/narinfo1952=== CONT TestIsValidCachePath/index.html1953=== CONT TestIsValidCachePath/short_hash1954=== CONT TestIsValidCachePath/wrong_extension1955=== CONT TestIsValidCachePath/leading_slash1956=== CONT TestIsValidCachePath/empty1957=== CONT TestIsValidCachePath/random_path1958=== CONT TestIsValidCachePath/invalid_char_u1959=== CONT TestIsValidCachePath/invalid_char_e1960=== CONT TestIsValidCachePath/traversal_in_middle1961=== CONT TestIsValidCachePath/traversal_parent1962=== CONT TestIsValidCachePath/realisation1963=== CONT TestIsValidCachePath/nix-cache-info1964=== CONT TestIsValidCachePath/log1965=== CONT TestIsValidCachePath/nar_xz1966=== CONT TestIsValidCachePath/nar_bz21967=== CONT TestIsValidCachePath/nar_uncompressed1968=== CONT TestIsValidCachePath/ls1969=== CONT TestIsValidCachePath/nar_zst1970=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1971--- PASS: TestIsValidCachePath (0.00s)1972 --- PASS: TestIsValidCachePath/narinfo (0.00s)1973 --- PASS: TestIsValidCachePath/index.html (0.00s)1974 --- PASS: TestIsValidCachePath/short_hash (0.00s)1975 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1976 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1977 --- PASS: TestIsValidCachePath/empty (0.00s)1978 --- PASS: TestIsValidCachePath/random_path (0.00s)1979 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1980 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1981 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1982 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1983 --- PASS: TestIsValidCachePath/realisation (0.00s)1984 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1985 --- PASS: TestIsValidCachePath/log (0.00s)1986 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1987 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1988 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1989 --- PASS: TestIsValidCachePath/ls (0.00s)1990 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1991 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1992=== CONT TestParseSingleRange/none1993=== CONT TestParseSingleRange/open-ended1994--- PASS: TestService_RequireScope_OIDC (0.51s)1995 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1996 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1997 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1998 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1999 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2000 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2001 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2002 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2003 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2004 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2005 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2006 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2007 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2008 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2009=== CONT TestParseSingleRange/start_far_past_EOF2010=== CONT TestParseSingleRange/start_past_EOF2011=== CONT TestParseSingleRange/single_byte2012=== CONT TestParseSingleRange/suffix_exceeds_size2013=== CONT TestParseSingleRange/suffix2014=== CONT TestParseSingleRange/end_clamped_to_size2015=== CONT TestParseSingleRange/malformed_both_empty2016=== CONT TestParseSingleRange/closed2017=== CONT TestParseSingleRange/malformed_end_before_start2018=== CONT TestParseSingleRange/multi-range_ignored2019=== CONT TestParseSingleRange/malformed_no_dash2020=== CONT TestParseSingleRange/unknown_unit2021--- PASS: TestParseSingleRange (0.00s)2022 --- PASS: TestParseSingleRange/none (0.00s)2023 --- PASS: TestParseSingleRange/open-ended (0.00s)2024 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2025 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2026 --- PASS: TestParseSingleRange/single_byte (0.00s)2027 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2028 --- PASS: TestParseSingleRange/suffix (0.00s)2029 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2030 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2031 --- PASS: TestParseSingleRange/closed (0.00s)2032 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2033 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2034 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2035 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2036=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh2037=== NAME TestNARDeduplicationMetadataUploadBug2038 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug2627766507/001/store/84y71bsh6rh5wp5kf28ilzwi79az81ln-file2.txt20392026/11/09 12:10:08 WARN Request failed, retrying attempt=3 backoff=362.732809ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20402026/11/09 12:10:08 INFO Received uploads request method=POST path=/api/pending_closures20412026/11/09 12:10:08 INFO Aborted multipart uploads count=0 kept=020422026/11/09 12:10:08 INFO Received uploads request method=POST path=/api/pending_closures20432026/11/09 12:10:08 INFO Aborted multipart uploads count=0 kept=020442026/11/09 12:10:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20452026/11/09 12:10:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2046=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale20472026/11/09 12:10:08 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=ZmE2ZTA3NDgtNzlhZC00MmJjLTkzMzQtZWQzYjc0ZTA3NTVhLjRlNTNkZDNkLWFmNDgtNGIzMS04ZDE4LWZhZjhlZThjZmI0ZXgxNzk0MjI2MjA3NjYwNTkzMDQw parts=1020482026/11/09 12:10:08 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZmE2ZTA3NDgtNzlhZC00MmJjLTkzMzQtZWQzYjc0ZTA3NTVhLjJmYzkyYzhmLWU4NDItNGE4NC1iNWQwLTNjODYyNTM4ZjJiYXgxNzk0MjI2MjA3NTY5ODM1MDM3 parts=1220492026/11/09 12:10:08 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20502026/11/09 12:10:08 INFO Completed upload id=1 objects=3 duration=2.915506ms2051--- PASS: TestUploadHandlersRejectOversizedBody (1.61s)2052 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.05s)2053 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.06s)2054 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.86s)2055=== CONT TestServerTLSConfig/no_client_CA2056=== CONT TestServerTLSConfig/not_a_PEM_file20572026/11/09 12:10:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20582026/11/09 12:10:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20592026/11/09 12:10:08 INFO Received uploads request method=POST path=/api/pending_closures20602026/11/09 12:10:08 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=ZmE2ZTA3NDgtNzlhZC00MmJjLTkzMzQtZWQzYjc0ZTA3NTVhLjAzMjJmNTQzLWIwODQtNDU2Yy04MjlhLTU1MWRiMmZmN2UwN3gxNzk0MjI2MjA3NzUyNzEyODM1 parts=1020612026/11/09 12:10:08 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=ZmE2ZTA3NDgtNzlhZC00MmJjLTkzMzQtZWQzYjc0ZTA3NTVhLjk2Mjk4MzVhLWUwODEtNDI2MC1hMmIzLWVjNTgxMzVjNjBmN3gxNzk0MjI2MjA3Nzg1MzQ3ODMx parts=1020622026/11/09 12:10:08 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst20632026/11/09 12:10:08 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo20642026/11/09 12:10:08 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20652026/11/09 12:10:08 INFO Completed upload id=1 objects=3 duration=2.347001ms20662026/11/09 12:10:08 INFO Received uploads request method=POST path=/api/pending_closures20672026/11/09 12:10:08 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20682026/11/09 12:10:08 INFO Completed upload id=1 objects=3 duration=2.272041ms20692026/11/09 12:10:08 INFO Received uploads request method=POST path=/api/pending_closures2070=== CONT TestServerTLSConfig/missing_CA_file2071--- PASS: TestServerTLSConfig (0.00s)2072 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2073 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.04s)2074 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2075=== CONT TestPush_RejectsBadRequests/root_not_in_objects20762026/11/09 12:10:08 INFO Received push request method=POST path=/api/pushes2077=== CONT TestPush_RejectsBadRequests/no_objects20782026/11/09 12:10:08 INFO Received push request method=POST path=/api/pushes2079=== CONT TestPush_RejectsBadRequests/bad_root20802026/11/09 12:10:08 INFO Received push request method=POST path=/api/pushes2081=== CONT TestPush_RejectsBadRequests/no_roots20822026/11/09 12:10:08 INFO Received push request method=POST path=/api/pushes2083--- PASS: TestPush_RejectsBadRequests (0.69s)2084 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2085 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2086 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2087 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)20882026/11/09 12:10:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20892026/11/09 12:10:08 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=ZmE2ZTA3NDgtNzlhZC00MmJjLTkzMzQtZWQzYjc0ZTA3NTVhLjM5ZTI5NjJkLTFlNjYtNGViYS05NGE2LThkYWI1OGVlZjAzMHgxNzk0MjI2MjA3ODg1MTExMjM1 parts=1020902026/11/09 12:10:08 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20912026/11/09 12:10:08 INFO Completed upload id=1 objects=3 duration=5.568991ms20922026/11/09 12:10:08 INFO Received uploads request method=POST path=/api/pending_closures20932026/11/09 12:10:08 INFO Aborted multipart uploads count=0 kept=020942026/11/09 12:10:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20952026/11/09 12:10:08 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=ZmE2ZTA3NDgtNzlhZC00MmJjLTkzMzQtZWQzYjc0ZTA3NTVhLjk2YmU2YTA2LWQzM2QtNDczOC1iYzdjLTlhYmYzZmFiNTlmMXgxNzk0MjI2MjA3OTM3NDkzODEx parts=1020962026/11/09 12:10:08 WARN Request failed, retrying attempt=4 backoff=771.186526ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20972026/11/09 12:10:08 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20982026/11/09 12:10:08 INFO Completed upload id=1 objects=3 duration=2.736724ms20992026/11/09 12:10:08 INFO Received uploads request method=POST path=/api/pending_closures21002026/11/09 12:10:08 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst21012026/11/09 12:10:08 WARN Found objects in DB but missing from S3, will re-upload count=121022026/11/09 12:10:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21032026/11/09 12:10:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21042026/11/09 12:10:08 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=ZmE2ZTA3NDgtNzlhZC00MmJjLTkzMzQtZWQzYjc0ZTA3NTVhLjMzMjAzZDEwLTdkNDctNDRlZC1iNmEwLTZlOWVhYmEwMmEyOHgxNzk0MjI2MjA4MzI4NDg4NjU2 parts=1021052026/11/09 12:10:08 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete21062026/11/09 12:10:08 INFO Completed upload id=2 objects=3 duration=1.455473ms21072026/11/09 12:10:08 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZmE2ZTA3NDgtNzlhZC00MmJjLTkzMzQtZWQzYjc0ZTA3NTVhLjczYzAwZDkyLWRjMWEtNGM5MS1iMDM5LWZiMDZhOThiMTU4OXgxNzk0MjI2MjA3NTg4MjU0ODg0 parts=122108--- PASS: TestSharedNarBothUploadsComplete (1.68s)21092026/11/09 12:10:08 INFO Received uploads request method=POST path=/api/pending_closures21102026/11/09 12:10:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21112026/11/09 12:10:08 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst21122026/11/09 12:10:08 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo21132026/11/09 12:10:08 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=ZmE2ZTA3NDgtNzlhZC00MmJjLTkzMzQtZWQzYjc0ZTA3NTVhLjA3MzA2MmY5LTRlMjgtNGUxMi04M2E2LWIxYTExNTA0NzA5MngxNzk0MjI2MjA4Mzg0MDEyNTc5 parts=1021142026/11/09 12:10:08 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete21152026/11/09 12:10:08 INFO Completed upload id=2 objects=3 duration=1.16509ms21162026/11/09 12:10:08 INFO Received uploads request method=POST path=/api/pending_closures21172026/11/09 12:10:08 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst21182026/11/09 12:10:08 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2119--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.00s)2120 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (1.13s)2121 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (0.95s)2122 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (1.21s)2123 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (1.37s)2124 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (1.38s)21252026/11/09 12:10:08 WARN Force mode enabled - objects will be deleted immediately without grace period21262026/11/09 12:10:08 WARN Force mode enabled - objects will be deleted immediately without grace period21272026/11/09 12:10:08 WARN Force mode enabled - objects will be deleted immediately without grace period21282026/11/09 12:10:08 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=021292026/11/09 12:10:08 INFO Vacuumed table table=pending_closures21302026/11/09 12:10:08 INFO Vacuumed table table=pending_objects21312026/11/09 12:10:08 INFO Vacuumed table table=multipart_uploads21322026/11/09 12:10:08 INFO Vacuumed table table=closures21332026/11/09 12:10:08 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=02134--- PASS: TestPendingClosureWriteTimeout (0.00s)2135 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2136 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2137 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2138 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.40s)21392026/11/09 12:10:08 INFO Vacuumed table table=pending_closures21402026/11/09 12:10:08 INFO Vacuumed table table=objects21412026/11/09 12:10:08 INFO Vacuumed table table=pending_objects21422026/11/09 12:10:08 INFO Vacuumed table table=multipart_uploads21432026/11/09 12:10:08 INFO Vacuumed table table=closures21442026/11/09 12:10:08 INFO Vacuumed table table=objects2145--- PASS: TestForceGCDuringPushOffersSweptObject (0.08s)2146 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (1.30s)2147 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (1.34s)21482026/11/09 12:10:08 INFO Aborted multipart uploads count=0 kept=02149=== NAME TestClientCADerivations2150 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2151 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2152 error: binary cache 's3://bucket46?endpoint=http://localhost:33589®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations2666827775/001/store'2153 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 121542026/11/09 12:10:08 WARN Force mode enabled - objects will be deleted immediately without grace period2155--- PASS: TestClientCADerivations (4.83s)21562026/11/09 12:10:08 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:33589/bucket105/?delete=\": context canceled"2157--- PASS: TestGCEndsOnShutdown (0.00s)2158 --- PASS: TestGCEndsOnShutdown/before_the_run (0.58s)2159 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.95s)2160 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (1.06s)21612026/11/09 12:10:08 INFO Received push request method=POST path=/api/pushes21622026/11/09 12:10:08 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)21632026/11/09 12:10:08 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign21642026/11/09 12:10:08 WARN Failed to register uploaded object key=84y71bsh6rh5wp5kf28ilzwi79az81ln.ls error="server returned 404: 404 page not found\n"21652026/11/09 12:10:08 INFO Signed narinfos id=2 count=121662026/11/09 12:10:08 INFO Uploading 1 narinfos21672026/11/09 12:10:08 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21682026/11/09 12:10:08 INFO Received complete push request method=POST path=/api/pushes/2/complete21692026/11/09 12:10:08 WARN Failed to register uploaded object key=84y71bsh6rh5wp5kf28ilzwi79az81ln.narinfo error="server returned 404: 404 page not found\n"21702026/11/09 12:10:08 INFO Completed push id=2 objects=3 duration=2.339521ms21712026/11/09 12:10:08 INFO Upload complete. (178ms)2172=== NAME TestNARDeduplicationMetadataUploadBug2173 metadata_upload_test.go:76: Retrieved narinfo from S3:2174 StorePath: /build/TestNARDeduplicationMetadataUploadBug2627766507/001/store/84y71bsh6rh5wp5kf28ilzwi79az81ln-file2.txt2175 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2176 Compression: zstd2177 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2178 NarSize: 1602179 References: 2180 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2181 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2182 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2183 {"version":1,"root":{"type":"regular","size":44}}2184--- PASS: TestNARDeduplicationMetadataUploadBug (2.31s)21852026/11/09 12:10:09 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2186=== NAME TestPinProtectsFromGC2187 client_integration_test.go:887: Pin successfully protected closure from garbage collection2188--- PASS: TestPinProtectsFromGC (6.31s)21892026/11/09 12:10:09 WARN Request failed, retrying attempt=5 backoff=1.692161307s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2190=== NAME TestOrphanedObjectsGCStressTest2191 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2192 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion2193--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2194 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (1.10s)2195 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (1.40s)2196--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.63s)21972026/11/09 12:10:09 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02198=== NAME TestClientIntegration2199 client_integration_test.go:370: Objects in database after GC:2200 client_integration_test.go:370: Successfully deleted all objects with GC --force2201--- PASS: TestClientIntegration (5.89s)2202=== NAME TestOrphanedObjectsGCStressTest2203 orphaned_objects_gc_test.go:503: Stress test completed successfully:2204 orphaned_objects_gc_test.go:504: - Active objects preserved: 202205 orphaned_objects_gc_test.go:505: - Objects deleted: 2102206 orphaned_objects_gc_test.go:506: - Total GC'd: 2102207--- PASS: TestOrphanedObjectsGCStressTest (3.87s)22082026/11/09 12:10:10 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-config22092026/11/09 12:10:11 WARN Request failed, retrying attempt=2 backoff=193.255861ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22102026/11/09 12:10:11 WARN Request failed, retrying attempt=3 backoff=386.680526ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22112026/11/09 12:10:11 WARN Request failed, retrying attempt=4 backoff=735.916386ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22122026/11/09 12:10:12 WARN Request failed, retrying attempt=5 backoff=1.620902538s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22132026/11/09 12:10:12 INFO Aborted multipart uploads count=1 kept=022142026/11/09 12:10:12 INFO Received cleanup request method=DELETE path=/api/pending_closures22152026/11/09 12:10:12 INFO Aborted multipart uploads count=1 kept=02216--- PASS: TestPendingCleanupUsesOneCutoff (6.81s)22172026/11/09 12:10:14 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"22182026/11/09 12:10:14 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-config22192026/11/09 12:10:14 WARN Request failed, retrying attempt=2 backoff=215.096371ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22202026/11/09 12:10:14 WARN Request failed, retrying attempt=3 backoff=421.777907ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22212026/11/09 12:10:14 WARN Request failed, retrying attempt=4 backoff=741.993357ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22222026/11/09 12:10:15 WARN Request failed, retrying attempt=5 backoff=1.67987046s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22232026/11/09 12:10:17 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_closures22242026/11/09 12:10:17 WARN Request failed, retrying attempt=2 backoff=186.137742ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22252026/11/09 12:10:17 WARN Request failed, retrying attempt=3 backoff=360.473362ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22262026/11/09 12:10:17 WARN Request failed, retrying attempt=4 backoff=722.712174ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22272026/11/09 12:10:18 WARN Request failed, retrying attempt=5 backoff=1.745570472s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2228--- PASS: TestClientErrorHandling (0.00s)2229 --- PASS: TestClientErrorHandling/InvalidStorePath (1.23s)2230 --- PASS: TestClientErrorHandling/InvalidAuthToken (1.43s)2231 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.74s)2232PASS2233{"timestamp":"2026-11-09T12:10:20.304691939Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:41030","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(199)"}2234{"timestamp":"2026-11-09T12:10:20.304704559Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:40490","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(208)"}2235{"timestamp":"2026-11-09T12:10:20.304542038Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:41048","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(194)"}22362026-11-09 12:10:20.588 UTC [129] LOG: received smart shutdown request22372026-11-09 12:10:20.599 UTC [129] LOG: background worker "logical replication launcher" (PID 139) exited with exit code 122382026-11-09 12:10:20.610 UTC [134] LOG: shutting down22392026-11-09 12:10:20.611 UTC [134] LOG: checkpoint starting: shutdown immediate22402026-11-09 12:10:21.719 UTC [134] LOG: checkpoint complete: wrote 11162 buffers (68.1%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.211 s, sync=0.853 s, total=1.109 s; sync files=36061, longest=0.006 s, average=0.001 s; distance=521612 kB, estimate=521612 kB; lsn=0/214C90A8, redo lsn=0/214C90A822412026-11-09 12:10:21.825 UTC [129] LOG: database system is shut down2242Running OIDC tests...2243=== RUN TestAudienceForIssuer2244=== PAUSE TestAudienceForIssuer2245=== RUN TestGlobMatch2246=== PAUSE TestGlobMatch2247=== RUN TestValidateToken_ValidToken2248=== PAUSE TestValidateToken_ValidToken2249=== RUN TestValidateToken_WrongAudience2250=== PAUSE TestValidateToken_WrongAudience2251=== RUN TestValidateToken_Expired2252=== PAUSE TestValidateToken_Expired2253=== RUN TestValidateToken_BoundClaimsMismatch2254=== PAUSE TestValidateToken_BoundClaimsMismatch2255=== RUN TestValidateToken_BoundSubjectMismatch2256=== PAUSE TestValidateToken_BoundSubjectMismatch2257=== RUN TestValidateToken_MultipleProviders2258=== PAUSE TestValidateToken_MultipleProviders2259=== RUN TestValidateToken_NoMatchingProvider2260=== PAUSE TestValidateToken_NoMatchingProvider2261=== RUN TestValidateToken_KubernetesServiceAccount2262=== PAUSE TestValidateToken_KubernetesServiceAccount2263=== RUN TestNewValidator_KubernetesRequiresCA2264=== PAUSE TestNewValidator_KubernetesRequiresCA2265=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2266=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2267=== RUN TestPins_ReservedForMatchingRule2268=== PAUSE TestPins_ReservedForMatchingRule2269=== RUN TestPins_TopLevelShorthand2270=== PAUSE TestPins_TopLevelShorthand2271=== RUN TestPins_ConfigValidation2272=== PAUSE TestPins_ConfigValidation2273=== RUN TestScopes_LegacyProviderDefaultsToWrite2274=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2275=== RUN TestScopes_Rules2276=== PAUSE TestScopes_Rules2277=== RUN TestScopes_ConfigValidation2278=== PAUSE TestScopes_ConfigValidation2279=== CONT TestAudienceForIssuer2280--- PASS: TestAudienceForIssuer (0.00s)2281=== CONT TestScopes_ConfigValidation2282=== CONT TestValidateToken_KubernetesServiceAccount2283=== CONT TestPins_TopLevelShorthand2284--- PASS: TestScopes_ConfigValidation (0.00s)2285=== CONT TestValidateToken_NoMatchingProvider2286=== CONT TestValidateToken_MultipleProviders2287=== CONT TestScopes_Rules2288=== CONT TestPins_ReservedForMatchingRule2289=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2290=== CONT TestNewValidator_KubernetesRequiresCA2291=== CONT TestValidateToken_BoundSubjectMismatch2292=== CONT TestValidateToken_BoundClaimsMismatch2293=== CONT TestValidateToken_Expired2294=== CONT TestValidateToken_WrongAudience2295=== CONT TestScopes_LegacyProviderDefaultsToWrite2296=== CONT TestPins_ConfigValidation2297--- PASS: TestPins_ConfigValidation (0.00s)2298=== CONT TestValidateToken_ValidToken2299=== CONT TestGlobMatch2300=== RUN TestGlobMatch/foo_foo2301=== PAUSE TestGlobMatch/foo_foo2302=== RUN TestGlobMatch/foo_bar2303=== PAUSE TestGlobMatch/foo_bar2304=== RUN TestGlobMatch/*_2305=== PAUSE TestGlobMatch/*_2306=== RUN TestGlobMatch/*_anything2307=== PAUSE TestGlobMatch/*_anything2308=== RUN TestGlobMatch/foo*_foo2309=== PAUSE TestGlobMatch/foo*_foo2310=== RUN TestGlobMatch/foo*_foobar2311=== PAUSE TestGlobMatch/foo*_foobar2312=== RUN TestGlobMatch/foo*_bar2313=== PAUSE TestGlobMatch/foo*_bar2314=== RUN TestGlobMatch/*bar_bar2315=== PAUSE TestGlobMatch/*bar_bar2316=== RUN TestGlobMatch/*bar_foobar2317=== PAUSE TestGlobMatch/*bar_foobar2318=== RUN TestGlobMatch/*bar_foo2319=== PAUSE TestGlobMatch/*bar_foo2320=== RUN TestGlobMatch/foo*bar_foobar2321=== PAUSE TestGlobMatch/foo*bar_foobar2322=== RUN TestGlobMatch/foo*bar_foo123bar2323=== PAUSE TestGlobMatch/foo*bar_foo123bar2324=== RUN TestGlobMatch/foo*bar_foobarbaz2325=== PAUSE TestGlobMatch/foo*bar_foobarbaz2326=== RUN TestGlobMatch/*/*_foo/bar2327=== PAUSE TestGlobMatch/*/*_foo/bar2328=== RUN TestGlobMatch/*/*_foo2329=== PAUSE TestGlobMatch/*/*_foo2330=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2331=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2332=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02333=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02334=== RUN TestGlobMatch/refs/*/main_refs/heads/main2335=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2336=== RUN TestGlobMatch/fo?_foo2337=== PAUSE TestGlobMatch/fo?_foo2338=== RUN TestGlobMatch/fo?_fo2339=== PAUSE TestGlobMatch/fo?_fo2340=== RUN TestGlobMatch/fo?_fooo2341=== PAUSE TestGlobMatch/fo?_fooo2342=== RUN TestGlobMatch/?oo_foo2343=== PAUSE TestGlobMatch/?oo_foo2344=== RUN TestGlobMatch/?oo_boo2345=== PAUSE TestGlobMatch/?oo_boo2346=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2347=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2348=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2349=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2350=== CONT TestGlobMatch/foo_foo2351=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2352=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2353=== CONT TestGlobMatch/?oo_boo2354=== CONT TestGlobMatch/?oo_foo2355=== CONT TestGlobMatch/fo?_fooo2356=== CONT TestGlobMatch/fo?_fo2357=== CONT TestGlobMatch/fo?_foo2358=== CONT TestGlobMatch/refs/*/main_refs/heads/main2359=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02360=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2361=== CONT TestGlobMatch/*/*_foo2362=== CONT TestGlobMatch/*/*_foo/bar2363=== CONT TestGlobMatch/foo*bar_foobarbaz2364=== CONT TestGlobMatch/foo*bar_foo123bar2365=== CONT TestGlobMatch/foo*bar_foobar2366=== CONT TestGlobMatch/*bar_foo2367=== CONT TestGlobMatch/*bar_foobar2368=== CONT TestGlobMatch/*bar_bar2369=== CONT TestGlobMatch/foo*_bar2370=== CONT TestGlobMatch/*_2371=== CONT TestGlobMatch/foo_bar2372=== CONT TestGlobMatch/foo*_foobar2373=== CONT TestGlobMatch/*_anything2374=== CONT TestGlobMatch/foo*_foo2375--- PASS: TestGlobMatch (0.00s)2376 --- PASS: TestGlobMatch/foo_foo (0.00s)2377 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2378 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2379 --- PASS: TestGlobMatch/?oo_boo (0.00s)2380 --- PASS: TestGlobMatch/?oo_foo (0.00s)2381 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2382 --- PASS: TestGlobMatch/fo?_fo (0.00s)2383 --- PASS: TestGlobMatch/fo?_foo (0.00s)2384 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2385 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2386 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2387 --- PASS: TestGlobMatch/*/*_foo (0.00s)2388 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2389 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2390 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2391 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2392 --- PASS: TestGlobMatch/*bar_foo (0.00s)2393 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2394 --- PASS: TestGlobMatch/*bar_bar (0.00s)2395 --- PASS: TestGlobMatch/foo*_bar (0.00s)2396 --- PASS: TestGlobMatch/*_ (0.00s)2397 --- PASS: TestGlobMatch/foo_bar (0.00s)2398 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2399 --- PASS: TestGlobMatch/*_anything (0.00s)2400 --- PASS: TestGlobMatch/foo*_foo (0.00s)24012026/11/09 12:10:25 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:4627724022026/11/09 12:10:25 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37281/oidc2403--- PASS: TestValidateToken_KubernetesServiceAccount (1.84s)24042026/11/09 12:10:25 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39055/oidc24052026/11/09 12:10:25 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46441/oidc24062026/11/09 12:10:25 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36361/oidc2407--- PASS: TestValidateToken_Expired (1.59s)24082026/11/09 12:10:25 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40435/oidc24092026/11/09 12:10:25 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232410--- PASS: TestValidateToken_BoundSubjectMismatch (1.64s)2411--- PASS: TestScopes_LegacyProviderDefaultsToWrite (1.42s)2412--- PASS: TestPins_TopLevelShorthand (1.85s)2413--- PASS: TestValidateToken_BoundClaimsMismatch (1.62s)24142026/11/09 12:10:25 http: TLS handshake error from 127.0.0.1:41504: read tcp 127.0.0.1:43809->127.0.0.1:41504: use of closed network connection2415--- PASS: TestNewValidator_KubernetesRequiresCA (1.64s)2416--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (1.83s)24172026/11/09 12:10:25 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44765/oidc2418--- PASS: TestPins_ReservedForMatchingRule (1.85s)24192026/11/09 12:10:25 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41329/oidc2420--- PASS: TestValidateToken_WrongAudience (1.47s)24212026/11/09 12:10:25 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:40609/oidc24222026/11/09 12:10:25 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:46755/oidc24232026/11/09 12:10:25 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35325/oidc2424--- PASS: TestValidateToken_MultipleProviders (1.93s)2425--- PASS: TestScopes_Rules (1.93s)24262026/11/09 12:10:25 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35673/oidc2427--- PASS: TestValidateToken_ValidToken (1.29s)24282026/11/09 12:10:26 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:37449/oidc2429--- PASS: TestValidateToken_NoMatchingProvider (2.07s)2430PASS2431Running hook tests...2432=== RUN TestSendPathsEmpty2433=== PAUSE TestSendPathsEmpty2434=== RUN TestQueueEnqueueAndFetch2435=== PAUSE TestQueueEnqueueAndFetch2436=== RUN TestQueueDeduplication2437=== PAUSE TestQueueDeduplication2438=== RUN TestQueueRemove2439=== PAUSE TestQueueRemove2440=== RUN TestQueueFetchBatchLimit2441=== PAUSE TestQueueFetchBatchLimit2442=== RUN TestQueueRetryMovesToBack2443=== PAUSE TestQueueRetryMovesToBack2444=== RUN TestQueueFetchRemoveLifecycle2445=== PAUSE TestQueueFetchRemoveLifecycle2446=== RUN TestQueueConcurrentWriters2447=== PAUSE TestQueueConcurrentWriters2448=== RUN TestQueueRemoveLargeClosure2449=== PAUSE TestQueueRemoveLargeClosure2450=== RUN TestServerClientIntegration2451--- PASS: TestServerClientIntegration (0.00s)2452=== RUN TestServerQueueError24532026/11/09 12:10:26 ERROR Failed to queue paths error="permission denied" count=12454--- PASS: TestServerQueueError (0.00s)2455=== RUN TestGetListenerSocketActivation2456 server_test.go:218: === RUN TestGetListenerSocketActivation2457 --- PASS: TestGetListenerSocketActivation (0.00s)2458 PASS2459 2460--- PASS: TestGetListenerSocketActivation (0.18s)2461=== RUN TestServerStalledClientDoesNotBlockShutdown2462=== PAUSE TestServerStalledClientDoesNotBlockShutdown2463=== RUN TestServerBacksOffOnAcceptErrors2464=== PAUSE TestServerBacksOffOnAcceptErrors2465=== RUN TestDrainIsolatesPoisonPath2466=== PAUSE TestDrainIsolatesPoisonPath2467=== RUN TestRunNotBlockedByPoisonHead2468=== PAUSE TestRunNotBlockedByPoisonHead2469=== RUN TestDrainGivesUpWhenServerDown2470=== PAUSE TestDrainGivesUpWhenServerDown2471=== RUN TestFailedPathPrunedByLaterClosure2472=== PAUSE TestFailedPathPrunedByLaterClosure2473=== RUN TestWorkerUploadsAndRemoves2474=== PAUSE TestWorkerUploadsAndRemoves2475=== RUN TestWorkerSkipsGCdPaths2476=== PAUSE TestWorkerSkipsGCdPaths2477=== RUN TestWorkerPrunesClosureDeps2478=== PAUSE TestWorkerPrunesClosureDeps2479=== RUN TestDrainTimeout2480=== PAUSE TestDrainTimeout2481=== RUN TestWorkerRemoveFailureIsNotProgress2482=== PAUSE TestWorkerRemoveFailureIsNotProgress2483=== RUN TestWorkerKeepsPathItCannotStat2484=== PAUSE TestWorkerKeepsPathItCannotStat2485=== CONT TestSendPathsEmpty2486--- PASS: TestSendPathsEmpty (0.00s)2487=== CONT TestWorkerPrunesClosureDeps2488=== CONT TestWorkerKeepsPathItCannotStat2489=== CONT TestWorkerRemoveFailureIsNotProgress2490=== CONT TestServerStalledClientDoesNotBlockShutdown2491=== CONT TestWorkerSkipsGCdPaths2492=== CONT TestWorkerUploadsAndRemoves2493=== CONT TestFailedPathPrunedByLaterClosure2494=== CONT TestDrainGivesUpWhenServerDown2495=== CONT TestRunNotBlockedByPoisonHead2496=== CONT TestDrainIsolatesPoisonPath2497=== CONT TestServerBacksOffOnAcceptErrors24982026/11/09 12:10:26 ERROR Accept failed error="too many open files"2499=== CONT TestQueueRetryMovesToBack2500=== CONT TestQueueRemoveLargeClosure2501=== CONT TestQueueConcurrentWriters2502=== CONT TestQueueFetchRemoveLifecycle2503=== CONT TestQueueDeduplication2504=== CONT TestQueueEnqueueAndFetch2505=== CONT TestQueueFetchBatchLimit25062026/11/09 12:10:26 ERROR Accept failed error="too many open files"2507=== CONT TestQueueRemove25082026/11/09 12:10:26 ERROR Accept failed error="too many open files"2509=== CONT TestDrainTimeout25102026/11/09 12:10:26 INFO Upload queue status pending=225112026/11/09 12:10:26 INFO Uploading batch count=12512--- PASS: TestQueueFetchBatchLimit (0.16s)2513--- PASS: TestQueueEnqueueAndFetch (0.16s)25142026/11/09 12:10:26 ERROR Accept failed error="too many open files"25152026/11/09 12:10:26 ERROR Failed to decode request error="read unix /build/hook1064288167/test.sock->@: i/o timeout"25162026/11/09 12:10:26 ERROR Failed to write response error="write unix /build/hook1064288167/test.sock->@: i/o timeout"2517--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)25182026/11/09 12:10:26 ERROR Accept failed error="too many open files"25192026/11/09 12:10:26 INFO Upload queue status pending=225202026/11/09 12:10:26 INFO Uploading batch count=225212026/11/09 12:10:26 INFO Uploading batch count=125222026/11/09 12:10:26 ERROR Upload failed error="upload failed" count=125232026/11/09 12:10:26 INFO Uploading batch count=225242026/11/09 12:10:26 INFO Upload queue status pending=225252026/11/09 12:10:26 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat509763072/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat509763072/002/locked/aaa: permission denied"25262026/11/09 12:10:26 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths3669993839/002/nonexistent25272026/11/09 12:10:26 INFO Uploading batch count=425282026/11/09 12:10:26 ERROR Upload failed error="upload failed" count=425292026/11/09 12:10:26 INFO Upload queue status pending=325302026/11/09 12:10:26 INFO Uploading batch count=225312026/11/09 12:10:26 ERROR Upload failed error="upload failed" count=225322026/11/09 12:10:26 INFO Uploading batch count=12533--- PASS: TestQueueFetchRemoveLifecycle (0.26s)25342026/11/09 12:10:26 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath1912500668/002/bbb25352026/11/09 12:10:26 INFO Uploading batch count=125362026/11/09 12:10:26 ERROR Upload failed error="upload failed" count=125372026/11/09 12:10:26 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown560777811/002/a25382026/11/09 12:10:26 INFO Uploading batch count=125392026/11/09 12:10:26 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat509763072/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat509763072/002/locked/aaa: permission denied"2540--- PASS: TestQueueRemove (0.25s)2541--- PASS: TestWorkerPrunesClosureDeps (0.26s)25422026/11/09 12:10:26 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown560777811/002/b2543--- PASS: TestQueueDeduplication (0.26s)25442026/11/09 12:10:26 INFO Uploading batch count=125452026/11/09 12:10:26 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress1831750584/002/nonexistent25462026/11/09 12:10:26 INFO Uploading batch count=225472026/11/09 12:10:26 ERROR Upload failed error="upload failed" count=225482026/11/09 12:10:26 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown560777811/002/c25492026/11/09 12:10:26 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat509763072/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat509763072/002/locked/aaa: permission denied"25502026/11/09 12:10:26 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125512026/11/09 12:10:26 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress1831750584/002/nonexistent25522026/11/09 12:10:26 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125532026/11/09 12:10:26 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress1831750584/002/nonexistent25542026/11/09 12:10:26 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown560777811/002/d25552026/11/09 12:10:26 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125562026/11/09 12:10:26 ERROR Drain finished with paths left in queue remaining=125572026/11/09 12:10:26 INFO Uploading batch count=125582026/11/09 12:10:26 ERROR Upload failed error="upload failed" count=125592026/11/09 12:10:26 ERROR Drain finished with paths left in queue remaining=125602026/11/09 12:10:26 INFO Uploading batch count=225612026/11/09 12:10:26 ERROR Upload failed error="upload failed" count=225622026/11/09 12:10:26 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown560777811/002/e2563--- PASS: TestWorkerRemoveFailureIsNotProgress (0.27s)25642026/11/09 12:10:26 INFO Uploading batch count=125652026/11/09 12:10:26 ERROR Upload failed error="upload failed" count=125662026/11/09 12:10:26 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown560777811/002/f2567--- PASS: TestFailedPathPrunedByLaterClosure (0.27s)25682026/11/09 12:10:26 INFO Uploading batch count=12569--- PASS: TestQueueRetryMovesToBack (0.27s)25702026/11/09 12:10:26 ERROR Upload failed error="upload failed" count=125712026/11/09 12:10:26 ERROR Drain finished with paths left in queue remaining=102572--- PASS: TestWorkerKeepsPathItCannotStat (0.27s)25732026/11/09 12:10:26 ERROR Drain finished with paths left in queue remaining=12574--- PASS: TestDrainGivesUpWhenServerDown (0.28s)2575--- PASS: TestDrainIsolatesPoisonPath (0.28s)2576--- PASS: TestWorkerUploadsAndRemoves (0.29s)2577--- PASS: TestWorkerSkipsGCdPaths (0.29s)25782026/11/09 12:10:26 ERROR Accept failed error="too many open files"2579--- PASS: TestQueueRemoveLargeClosure (0.38s)25802026/11/09 12:10:26 ERROR Accept failed error="too many open files"25812026/11/09 12:10:26 ERROR Upload failed error="context deadline exceeded" count=225822026/11/09 12:10:26 ERROR Drain finished with paths left in queue remaining=42583--- PASS: TestDrainTimeout (0.31s)2584--- PASS: TestQueueConcurrentWriters (0.46s)25852026/11/09 12:10:27 ERROR Accept failed error="too many open files"2586--- PASS: TestServerBacksOffOnAcceptErrors (0.78s)25872026/11/09 12:10:27 INFO Uploading batch count=125882026/11/09 12:10:27 INFO Uploading batch count=125892026/11/09 12:10:27 INFO Uploading batch count=125902026/11/09 12:10:27 ERROR Upload failed error="upload failed" count=125912026/11/09 12:10:27 INFO Uploading batch count=125922026/11/09 12:10:27 ERROR Upload failed error="upload failed" count=125932026/11/09 12:10:27 INFO Uploading batch count=125942026/11/09 12:10:27 ERROR Upload failed error="upload failed" count=125952026/11/09 12:10:27 INFO Uploading batch count=125962026/11/09 12:10:27 ERROR Upload failed error="upload failed" count=125972026/11/09 12:10:27 ERROR Drain finished with paths left in queue remaining=12598--- PASS: TestRunNotBlockedByPoisonHead (1.28s)2599PASS2600Running signing tests...2601=== RUN TestExternalSigner2602=== PAUSE TestExternalSigner2603=== RUN TestExternalSignerWrongPublicKey2604=== PAUSE TestExternalSignerWrongPublicKey2605=== RUN TestExternalSignerErrors2606=== PAUSE TestExternalSignerErrors2607=== RUN TestExternalSignerRestartsAfterCrash2608=== PAUSE TestExternalSignerRestartsAfterCrash2609=== RUN TestExternalSignerProgramErrorKeepsProcess2610=== PAUSE TestExternalSignerProgramErrorKeepsProcess2611=== RUN TestExternalSignerClose2612=== PAUSE TestExternalSignerClose2613=== RUN TestExternalSignerRejectsInvalidPublicKey2614=== PAUSE TestExternalSignerRejectsInvalidPublicKey2615=== RUN TestExternalSignerCancellation2616=== PAUSE TestExternalSignerCancellation2617=== RUN TestGenerateFingerprint2618=== PAUSE TestGenerateFingerprint2619=== RUN TestParseSigningKey2620=== PAUSE TestParseSigningKey2621=== RUN TestSign2622=== PAUSE TestSign2623=== RUN TestSignBatch2624=== PAUSE TestSignBatch2625=== RUN TestNilKeyPublicKey2626=== PAUSE TestNilKeyPublicKey2627=== RUN TestSignErrors2628=== PAUSE TestSignErrors2629=== CONT TestExternalSigner2630=== CONT TestSignBatch2631=== CONT TestSignErrors2632=== CONT TestExternalSignerCancellation2633=== CONT TestGenerateFingerprint2634=== CONT TestParseSigningKey2635=== CONT TestNilKeyPublicKey2636--- PASS: TestNilKeyPublicKey (0.00s)2637=== CONT TestExternalSignerErrors2638=== CONT TestExternalSignerRestartsAfterCrash2639=== CONT TestExternalSignerWrongPublicKey2640=== CONT TestExternalSignerRejectsInvalidPublicKey2641=== RUN TestExternalSignerRejectsInvalidPublicKey/#002642=== CONT TestExternalSignerClose2643=== CONT TestExternalSignerProgramErrorKeepsProcess2644=== CONT TestSign2645=== RUN TestGenerateFingerprint/basic_with_references2646=== PAUSE TestGenerateFingerprint/basic_with_references2647=== RUN TestGenerateFingerprint/no_references2648=== PAUSE TestGenerateFingerprint/no_references2649=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2650=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2651=== RUN TestParseSigningKey/valid_32-byte_key2652=== RUN TestExternalSignerErrors/program_error2653=== PAUSE TestExternalSignerErrors/program_error2654=== RUN TestExternalSignerErrors/exit_at_startup2655=== PAUSE TestExternalSignerErrors/exit_at_startup2656=== RUN TestExternalSignerErrors/exit_on_request2657=== PAUSE TestExternalSignerErrors/exit_on_request2658=== RUN TestExternalSignerErrors/invalid_signature_base642659=== PAUSE TestExternalSignerErrors/invalid_signature_base642660=== RUN TestExternalSignerErrors/null2661=== PAUSE TestExternalSignerErrors/null2662=== RUN TestExternalSignerErrors/missing_signatures2663=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2664=== PAUSE TestExternalSignerErrors/missing_signatures2665=== PAUSE TestParseSigningKey/valid_32-byte_key2666=== RUN TestExternalSignerErrors/null_signatures2667=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2668=== PAUSE TestExternalSignerErrors/null_signatures2669=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002670=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2671=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2672=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2673=== RUN TestParseSigningKey/no_colon2674=== PAUSE TestParseSigningKey/no_colon2675=== RUN TestParseSigningKey/empty_name2676=== PAUSE TestParseSigningKey/empty_name2677=== RUN TestParseSigningKey/invalid_base642678=== PAUSE TestParseSigningKey/invalid_base642679=== RUN TestParseSigningKey/wrong_length2680=== PAUSE TestParseSigningKey/wrong_length2681=== CONT TestParseSigningKey/valid_32-byte_key2682=== RUN TestGenerateFingerprint/invalid_nar_hash_length2683=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2684=== RUN TestGenerateFingerprint/invalid_store_path_prefix2685=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2686=== RUN TestGenerateFingerprint/invalid_reference_prefix2687=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2688=== CONT TestGenerateFingerprint/basic_with_references2689=== CONT TestParseSigningKey/wrong_length2690=== CONT TestParseSigningKey/invalid_base642691=== CONT TestParseSigningKey/empty_name2692=== CONT TestParseSigningKey/no_colon2693=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2694=== RUN TestExternalSignerErrors/wrong_signatures_shape2695=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2696=== RUN TestExternalSignerErrors/wrong_signature_name2697=== PAUSE TestExternalSignerErrors/wrong_signature_name2698=== RUN TestExternalSignerErrors/wrong_signature_length2699=== PAUSE TestExternalSignerErrors/wrong_signature_length2700=== RUN TestExternalSignerErrors/invalid_JSON2701=== CONT TestGenerateFingerprint/no_references2702=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2703=== PAUSE TestExternalSignerErrors/invalid_JSON2704=== CONT TestGenerateFingerprint/invalid_reference_prefix2705=== CONT TestGenerateFingerprint/invalid_store_path_prefix2706=== RUN TestSignErrors/nil_key2707=== CONT TestGenerateFingerprint/invalid_nar_hash_length2708=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2709=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2710=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2711=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2712--- PASS: TestSign (0.00s)2713=== RUN TestExternalSignerErrors/wrong_shape2714=== PAUSE TestExternalSignerErrors/wrong_shape2715=== PAUSE TestSignErrors/nil_key2716=== RUN TestSignErrors/nil_narinfo2717=== PAUSE TestSignErrors/nil_narinfo2718=== RUN TestSignErrors/invalid_narinfo2719=== PAUSE TestSignErrors/invalid_narinfo2720=== RUN TestSignErrors/canceled2721=== PAUSE TestSignErrors/canceled2722=== CONT TestSignErrors/nil_key2723=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2724=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2725=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2726=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2727=== CONT TestExternalSignerRejectsInvalidPublicKey/#002728=== CONT TestSignErrors/canceled2729=== CONT TestSignErrors/invalid_narinfo2730=== CONT TestSignErrors/nil_narinfo2731--- PASS: TestParseSigningKey (0.00s)2732 --- PASS: TestParseSigningKey/wrong_length (0.00s)2733 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2734 --- PASS: TestParseSigningKey/empty_name (0.00s)2735 --- PASS: TestParseSigningKey/no_colon (0.00s)2736 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2737 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2738--- PASS: TestGenerateFingerprint (0.00s)2739 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2740 --- PASS: TestGenerateFingerprint/no_references (0.00s)2741 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2742 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2743 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2744 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2745 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2746=== RUN TestExternalSignerErrors/wrong_id2747=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2748=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2749=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2750--- PASS: TestSignBatch (0.00s)2751=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2752=== PAUSE TestExternalSignerErrors/wrong_id2753--- PASS: TestSignErrors (0.00s)2754 --- PASS: TestSignErrors/nil_key (0.00s)2755 --- PASS: TestSignErrors/canceled (0.00s)2756 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2757 --- PASS: TestSignErrors/nil_narinfo (0.00s)2758--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2759 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2760 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2761 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2762 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2763 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2764=== RUN TestExternalSignerErrors/too_few_signatures2765=== PAUSE TestExternalSignerErrors/too_few_signatures2766=== RUN TestExternalSignerErrors/unrequested_key2767=== PAUSE TestExternalSignerErrors/unrequested_key2768=== RUN TestExternalSignerErrors/missing_signature_name2769=== PAUSE TestExternalSignerErrors/missing_signature_name2770=== CONT TestExternalSignerErrors/unrequested_key2771=== CONT TestExternalSignerErrors/program_error2772--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2773=== CONT TestExternalSignerErrors/too_few_signatures2774=== CONT TestExternalSignerErrors/wrong_id2775=== CONT TestExternalSignerErrors/wrong_shape2776--- PASS: TestExternalSignerWrongPublicKey (0.00s)2777=== CONT TestExternalSignerErrors/invalid_JSON2778--- PASS: TestExternalSignerClose (0.00s)2779=== CONT TestExternalSignerErrors/wrong_signature_length2780=== CONT TestExternalSignerErrors/wrong_signature_name2781=== CONT TestExternalSignerErrors/wrong_signatures_shape2782=== CONT TestExternalSignerErrors/null_signatures2783=== CONT TestExternalSignerErrors/missing_signatures2784=== CONT TestExternalSignerErrors/null2785=== CONT TestExternalSignerErrors/invalid_signature_base642786=== CONT TestExternalSignerErrors/exit_on_request2787=== CONT TestExternalSignerErrors/exit_at_startup2788=== CONT TestExternalSignerErrors/missing_signature_name2789--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2790--- PASS: TestExternalSigner (0.01s)2791--- PASS: TestExternalSignerErrors (0.00s)2792 --- PASS: TestExternalSignerErrors/unrequested_key (0.00s)2793 --- PASS: TestExternalSignerErrors/too_few_signatures (0.00s)2794 --- PASS: TestExternalSignerErrors/program_error (0.00s)2795 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.00s)2796 --- PASS: TestExternalSignerErrors/wrong_shape (0.00s)2797 --- PASS: TestExternalSignerErrors/wrong_id (0.00s)2798 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.00s)2799 --- PASS: TestExternalSignerErrors/null_signatures (0.00s)2800 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.00s)2801 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)2802 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.00s)2803 --- PASS: TestExternalSignerErrors/exit_on_request (0.00s)2804 --- PASS: TestExternalSignerErrors/exit_at_startup (0.00s)2805 --- PASS: TestExternalSignerErrors/null (0.01s)2806 --- PASS: TestExternalSignerErrors/missing_signatures (0.01s)2807 --- PASS: TestExternalSignerErrors/missing_signature_name (0.00s)2808--- PASS: TestExternalSignerCancellation (0.02s)2809PASS2810Running OpenBao signer tests...2811=== RUN TestSign2812=== PAUSE TestSign2813=== RUN TestSignErrors2814=== PAUSE TestSignErrors2815=== RUN TestServe2816=== PAUSE TestServe2817=== RUN TestServeRejectsGarbage2818=== PAUSE TestServeRejectsGarbage2819=== CONT TestSign2820=== CONT TestServeRejectsGarbage2821--- PASS: TestServeRejectsGarbage (0.00s)2822=== CONT TestServe2823--- PASS: TestServe (0.00s)2824=== CONT TestSignErrors2825=== RUN TestSignErrors/no_prefix2826=== PAUSE TestSignErrors/no_prefix2827=== RUN TestSignErrors/invalid_base642828=== PAUSE TestSignErrors/invalid_base642829=== RUN TestSignErrors/http_error2830=== PAUSE TestSignErrors/http_error2831=== RUN TestSignErrors/invalid_json2832=== PAUSE TestSignErrors/invalid_json2833=== CONT TestSignErrors/no_prefix2834=== CONT TestSignErrors/invalid_json2835=== CONT TestSignErrors/http_error2836=== CONT TestSignErrors/invalid_base642837--- PASS: TestSign (0.01s)2838--- PASS: TestSignErrors (0.00s)2839 --- PASS: TestSignErrors/http_error (0.00s)2840 --- PASS: TestSignErrors/invalid_base64 (0.00s)2841 --- PASS: TestSignErrors/no_prefix (0.01s)2842 --- PASS: TestSignErrors/invalid_json (0.00s)2843PASS