niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #467
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestUploadMultipart_ReturnsAfterDroppedBody20=== PAUSE TestUploadMultipart_ReturnsAfterDroppedBody21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestUploadMultipart_SupersededByPeer24=== PAUSE TestUploadMultipart_SupersededByPeer25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (0.03s)27=== RUN TestDumpPathCaseHackCollision28--- PASS: TestDumpPathCaseHackCollision (0.00s)29=== RUN TestSupersededNARStillUploadsListing30=== PAUSE TestSupersededNARStillUploadsListing31=== RUN TestDumpPathMatchesNix32=== PAUSE TestDumpPathMatchesNix33=== RUN TestDumpPathSingleFile34=== PAUSE TestDumpPathSingleFile35=== RUN TestDumpPathWriterError36=== PAUSE TestDumpPathWriterError37=== RUN TestEncodeNixBase3238=== PAUSE TestEncodeNixBase3239=== RUN TestEncodeNixBase32WithRealHash40=== PAUSE TestEncodeNixBase32WithRealHash41=== RUN TestConvertHashToNix3242=== PAUSE TestConvertHashToNix3243=== RUN TestGetStorePathHash44=== PAUSE TestGetStorePathHash45=== RUN TestPathInfoHashCompatibility46=== PAUSE TestPathInfoHashCompatibility47=== RUN TestParsePathInfoJSON48=== PAUSE TestParsePathInfoJSON49=== RUN TestParsePathInfoJSONMultiplePaths50=== PAUSE TestParsePathInfoJSONMultiplePaths51=== RUN TestPathInfoCACompatibility52=== PAUSE TestPathInfoCACompatibility53=== RUN TestRateLimiterFeedback54=== PAUSE TestRateLimiterFeedback55=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess56=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess57=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer58=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer59=== RUN TestRegisterUploadedObject_OutlivesPush60=== PAUSE TestRegisterUploadedObject_OutlivesPush61=== RUN TestResolveStorePath62=== PAUSE TestResolveStorePath63=== RUN TestDoWithRetry_BodyReplayedViaGetBody64=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody65=== RUN TestRetryTimeoutOutlastsMaxRetries66=== PAUSE TestRetryTimeoutOutlastsMaxRetries67=== RUN TestDoWithRetry_FinalResponseBodyReadable68=== PAUSE TestDoWithRetry_FinalResponseBodyReadable69=== RUN TestShellSplit70=== PAUSE TestShellSplit71=== RUN TestShellSplitErrors72=== PAUSE TestShellSplitErrors73=== RUN TestStreamPushReportsEveryPath74=== PAUSE TestStreamPushReportsEveryPath75=== RUN TestStreamPushBatchesUnderLoad76=== PAUSE TestStreamPushBatchesUnderLoad77=== RUN TestStreamPushIsolatesFailures78=== PAUSE TestStreamPushIsolatesFailures79=== RUN TestStreamPushGivesUpOnDeadServer80=== PAUSE TestStreamPushGivesUpOnDeadServer81=== RUN TestStreamPushRequestLine82=== PAUSE TestStreamPushRequestLine83=== RUN TestStreamPushReportsSignatures84=== PAUSE TestStreamPushReportsSignatures85=== RUN TestStreamPushReportsSkippedPaths86=== PAUSE TestStreamPushReportsSkippedPaths87=== RUN TestClientSignaturesByStorePath88=== PAUSE TestClientSignaturesByStorePath89=== RUN TestStreamPushStopsWhenCanceled90=== PAUSE TestStreamPushStopsWhenCanceled91=== RUN TestSetClientTLS92=== PAUSE TestSetClientTLS93=== RUN TestSetClientTLSDoesNotMutateDefaultTransport94=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport95=== RUN TestSetClientTLSErrors96=== PAUSE TestSetClientTLSErrors97=== RUN TestStaticToken98=== PAUSE TestStaticToken99=== RUN TestFileTokenReadsAndCaches100=== PAUSE TestFileTokenReadsAndCaches101=== RUN TestFileTokenMissing102=== PAUSE TestFileTokenMissing103=== RUN TestFileTokenEmpty104=== PAUSE TestFileTokenEmpty105=== RUN TestScriptTokenNoExpiryRerunsEveryCall106=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall107=== RUN TestScriptTokenCachesUntilRefresh108=== PAUSE TestScriptTokenCachesUntilRefresh109=== RUN TestScriptTokenEmptyToken110=== PAUSE TestScriptTokenEmptyToken111=== RUN TestScriptTokenBadJSON112=== PAUSE TestScriptTokenBadJSON113=== RUN TestScriptTokenScriptFails114=== PAUSE TestScriptTokenScriptFails115=== RUN TestScriptTokenEmptyCommand116=== PAUSE TestScriptTokenEmptyCommand117=== CONT TestDoServerRequestAttachesToken118=== CONT TestDoWithRetry_BodyReplayedViaGetBody119=== CONT TestDumpPathWriterError120=== CONT TestResolveStorePath121=== CONT TestRegisterUploadedObject_OutlivesPush122=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer123=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess124=== CONT TestRateLimiterFeedback125=== RUN TestRateLimiterFeedback/429_enables_limiter126=== PAUSE TestRateLimiterFeedback/429_enables_limiter127=== CONT TestPathInfoCACompatibility128=== CONT TestParsePathInfoJSONMultiplePaths129=== CONT TestParsePathInfoJSON130=== CONT TestPathInfoHashCompatibility131=== CONT TestSetClientTLS132=== CONT TestGetStorePathHash133=== CONT TestScriptTokenEmptyCommand134=== CONT TestConvertHashToNix32135=== CONT TestScriptTokenScriptFails136=== CONT TestEncodeNixBase32WithRealHash137=== CONT TestScriptTokenBadJSON138=== CONT TestScriptTokenEmptyToken139=== CONT TestScriptTokenCachesUntilRefresh140=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths141=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths142=== RUN TestGetStorePathHash/valid_store_path143=== CONT TestFileTokenReadsAndCaches144=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)1452026/11/06 08:13:31 WARN Rate limiter enabled after throttle name=server-test rate=5146=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)147=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon148=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon149=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI150=== CONT TestFileTokenEmpty151--- PASS: TestResolveStorePath (0.00s)152--- PASS: TestScriptTokenEmptyCommand (0.00s)153=== CONT TestFileTokenMissing154=== RUN TestRateLimiterFeedback/503_enables_limiter155=== RUN TestParsePathInfoJSON/Nix_format156=== CONT TestScriptTokenNoExpiryRerunsEveryCall157=== PAUSE TestGetStorePathHash/valid_store_path158=== RUN TestPathInfoCACompatibility/null_ca_field159=== RUN TestConvertHashToNix32/SRI_format_to_Nix32160=== CONT TestEncodeNixBase32161=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths162--- PASS: TestEncodeNixBase32WithRealHash (0.00s)163=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI164=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512165=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512166--- PASS: TestFileTokenReadsAndCaches (0.00s)167=== CONT TestDumpPathSingleFile168=== CONT TestStaticToken169--- PASS: TestStaticToken (0.00s)170=== CONT TestDumpPathMatchesNix171=== PAUSE TestParsePathInfoJSON/Nix_format172=== CONT TestSupersededNARStillUploadsListing173=== RUN TestSupersededNARStillUploadsListing/small_NAR174=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32175=== CONT TestSetClientTLSErrors176=== RUN TestConvertHashToNix32/already_Nix32_format177=== PAUSE TestSupersededNARStillUploadsListing/small_NAR178=== RUN TestSupersededNARStillUploadsListing/dump_cut_short179=== PAUSE TestPathInfoCACompatibility/null_ca_field180=== RUN TestGetStorePathHash/basename_without_hyphen_should_error181=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error1822026/11/06 08:13:31 WARN Rate limiter enabled after throttle name=server-test rate=5183=== PAUSE TestRateLimiterFeedback/503_enables_limiter184--- PASS: TestScriptTokenScriptFails (0.00s)185=== PAUSE TestConvertHashToNix32/already_Nix32_format186=== RUN TestEncodeNixBase32/test_string_hash187=== RUN TestParsePathInfoJSON/Lix_format188=== CONT TestSetClientTLSDoesNotMutateDefaultTransport189=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths190=== CONT TestStreamPushIsolatesFailures191=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short192=== RUN TestPathInfoCACompatibility/old_string_format_-_text193=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text194=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive1952026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:42385196=== CONT TestStreamPushStopsWhenCanceled197=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error198--- PASS: TestFileTokenMissing (0.00s)199=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails200=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter201=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive202=== RUN TestConvertHashToNix32/invalid_format203=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun204=== CONT TestClientSignaturesByStorePath205=== RUN TestPathInfoCACompatibility/new_structured_format_-_text2062026/11/06 08:13:31 ERROR Upload failed error="bad path" count=3207=== CONT TestStreamPushReportsSkippedPaths208=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error2092026/11/06 08:13:31 WARN Rate limiter backed off name=server-test rate=5210=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text2112026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:42385212=== PAUSE TestParsePathInfoJSON/Lix_format213--- PASS: TestFileTokenEmpty (0.00s)214=== CONT TestFilterOversizedClosures215=== RUN TestParsePathInfoJSON/empty_input216=== RUN TestFilterOversizedClosures/no_limit_keeps_everything217=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything218=== CONT TestStreamPushReportsSignatures219=== CONT TestCaseHackSuffix220=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails221=== CONT TestPartSizeForNAR222=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter223=== PAUSE TestConvertHashToNix32/invalid_format224=== PAUSE TestEncodeNixBase32/test_string_hash225=== RUN TestPartSizeForNAR/zero_stays_at_minimum226=== RUN TestSetClientTLSErrors/missing_cert_file227=== CONT TestUploadMultipart_ReturnsAfterDroppedBody2282026/11/06 08:13:31 INFO Garbage collection started229=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error2302026/11/06 08:13:31 ERROR Upload failed error=boom count=1231=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error232=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum233--- PASS: TestStreamPushReportsSkippedPaths (0.00s)234=== CONT TestStreamPushGivesUpOnDeadServer235=== PAUSE TestParsePathInfoJSON/empty_input236=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped237=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter238=== CONT TestStreamPushRequestLine239=== CONT TestUploadMultipart_SupersededByPeer240=== PAUSE TestSetClientTLSErrors/missing_cert_file241=== RUN TestEncodeNixBase32/empty_input242=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method243=== CONT TestShellSplitErrors244=== PAUSE TestEncodeNixBase32/empty_input245=== RUN TestUploadMultipart_SupersededByPeer/exists246=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter2472026/11/06 08:13:31 ERROR Upload failed error="connection refused" count=20248=== PAUSE TestUploadMultipart_SupersededByPeer/exists249=== CONT TestRegisterUploadedObjectReusesConnections2502026/11/06 08:13:31 ERROR Server seems unavailable, giving up on batch untried=17251=== RUN TestPartSizeForNAR/small_stays_at_minimum252=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped253=== RUN TestFilterOversizedClosures/all_closures_skipped254=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method255=== CONT TestStreamPushBatchesUnderLoad256=== CONT TestShellSplit257=== CONT TestRetryTimeoutOutlastsMaxRetries258=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false259=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false260=== RUN TestSetClientTLSErrors/missing_key_file261=== RUN TestParsePathInfoJSON/whitespace_only262=== CONT TestStreamPushReportsEveryPath263--- PASS: TestScriptTokenEmptyToken (0.01s)264=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry265=== RUN TestUploadMultipart_SupersededByPeer/missing266=== CONT TestDoWithRetry_FinalResponseBodyReadable267=== PAUSE TestParsePathInfoJSON/whitespace_only268--- PASS: TestStreamPushStopsWhenCanceled (0.00s)269--- PASS: TestDoServerRequestAttachesToken (0.01s)270--- PASS: TestScriptTokenBadJSON (0.01s)271--- PASS: TestClientSignaturesByStorePath (0.00s)272--- PASS: TestRegisterUploadedObject_OutlivesPush (0.01s)273--- PASS: TestStreamPushIsolatesFailures (0.00s)274--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)275--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)276--- PASS: TestStreamPushReportsSignatures (0.00s)277--- PASS: TestShellSplitErrors (0.00s)278--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)279--- PASS: TestShellSplit (0.00s)280=== RUN TestSetClientTLS/rejects_connection_without_client_cert281=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica2822026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:41661283=== RUN TestParsePathInfoJSON/invalid_JSON284=== PAUSE TestParsePathInfoJSON/invalid_JSON285=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true286=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true287=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI2882026/11/06 08:13:31 ERROR Upload failed error=boom count=1289=== PAUSE TestSetClientTLSErrors/missing_key_file290=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon291=== RUN TestSetClientTLSErrors/missing_ca_file292=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths293=== PAUSE TestSetClientTLSErrors/missing_ca_file294--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)295=== CONT TestUploadMultipart_PartsInParallel2962026/11/06 08:13:31 INFO Garbage collection started2972026/11/06 08:13:31 WARN Rate limiter enabled after throttle name=server-test rate=5298=== PAUSE TestUploadMultipart_SupersededByPeer/missing299=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert300=== CONT TestSupersededNARStillUploadsListing/small_NAR3012026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:37255302=== PAUSE TestPartSizeForNAR/small_stays_at_minimum303=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)304=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum305=== CONT TestSupersededNARStillUploadsListing/dump_cut_short3062026/11/06 08:13:31 WARN Rate limiter backed off name=server-test rate=5307=== RUN TestSetClientTLSErrors/invalid_ca_file308=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths309--- PASS: TestStreamPushReportsEveryPath (0.00s)310=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA311=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails312=== PAUSE TestSetClientTLSErrors/invalid_ca_file313=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512314--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.01s)315--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.00s)316=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum317=== CONT TestConvertHashToNix32/SRI_format_to_Nix32318--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)319 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)320 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)321=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error322=== PAUSE TestFilterOversizedClosures/all_closures_skipped323=== CONT TestGetStorePathHash/valid_store_path3242026/11/06 08:13:31 INFO Uploading abc-hello (1.0GB)325--- PASS: TestPathInfoHashCompatibility (0.00s)326 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)327 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)328 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)329 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)3302026/11/06 08:13:31 INFO Uploading abc-hello (1.0GB)331=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA332=== CONT TestConvertHashToNix32/invalid_format333=== CONT TestConvertHashToNix32/already_Nix32_format334=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error335=== CONT TestGetStorePathHash/basename_without_hyphen_should_error336=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter337--- PASS: TestScriptTokenCachesUntilRefresh (0.02s)338=== RUN TestSetClientTLS/preserves_debug_logging_transport339=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts340=== CONT TestRateLimiterFeedback/429_enables_limiter341=== PAUSE TestSetClientTLS/preserves_debug_logging_transport3422026/11/06 08:13:31 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:35057/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:35057/api/uploads/complete343=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter3442026/11/06 08:13:31 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"345=== CONT TestPathInfoCACompatibility/new_structured_format_-_text3462026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:41661347=== CONT TestEncodeNixBase32/test_string_hash348=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive349=== CONT TestPathInfoCACompatibility/old_string_format_-_text350=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method351=== CONT TestParsePathInfoJSON/invalid_JSON352=== CONT TestEncodeNixBase32/empty_input3532026/11/06 08:13:31 WARN Rate limiter enabled after throttle name=s3-test rate=5354--- PASS: TestConvertHashToNix32 (0.01s)355 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)356 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)357 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)3582026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:39047359=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false3602026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:41661361=== CONT TestRateLimiterFeedback/503_enables_limiter3622026/11/06 08:13:31 WARN Rate limiter enabled after throttle name=server-test rate=5363=== CONT TestPathInfoCACompatibility/null_ca_field3642026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:40501365=== CONT TestSetClientTLSErrors/missing_ca_file3662026/11/06 08:13:31 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=03672026/11/06 08:13:31 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:35057/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:35057/api/uploads/complete368=== CONT TestParsePathInfoJSON/Nix_format3692026/11/06 08:13:31 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"3702026/11/06 08:13:31 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:35057/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:35057/api/uploads/complete3712026/11/06 08:13:31 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"372=== CONT TestSetClientTLSErrors/missing_key_file3732026/11/06 08:13:31 WARN Rate limiter backed off name=server-test rate=5374=== CONT TestFilterOversizedClosures/no_limit_keeps_everything375=== CONT TestFilterOversizedClosures/all_closures_skipped3762026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:41661377=== CONT TestParsePathInfoJSON/empty_input3782026/11/06 08:13:31 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=50379=== CONT TestSetClientTLS/preserves_debug_logging_transport3802026/11/06 08:13:31 WARN Rate limiter enabled after throttle name=server-test rate=53812026/11/06 08:13:31 WARN Garbage collection finished on another replica. Its statistics are not available here382=== CONT TestParsePathInfoJSON/Lix_format3832026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:34387384=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3852026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:416613862026/11/06 08:13:31 WARN Rate limiter backed off name=server-test rate=5387=== CONT TestParsePathInfoJSON/whitespace_only388=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts389=== RUN TestPartSizeForNAR/1_TiB390--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.17s)391=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true392=== CONT TestUploadMultipart_SupersededByPeer/exists393=== CONT TestUploadMultipart_SupersededByPeer/missing394=== CONT TestSetClientTLSErrors/missing_cert_file395=== CONT TestSetClientTLSErrors/invalid_ca_file396=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped397=== CONT TestSetClientTLS/rejects_connection_without_client_cert398=== PAUSE TestPartSizeForNAR/1_TiB399=== RUN TestPartSizeForNAR/5_TiB_S3_max_object400=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object401=== RUN TestPartSizeForNAR/capped_at_5_GiB402=== PAUSE TestPartSizeForNAR/capped_at_5_GiB403=== CONT TestPartSizeForNAR/zero_stays_at_minimum404--- PASS: TestEncodeNixBase32 (0.01s)405 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)406 --- PASS: TestEncodeNixBase32/empty_input (0.00s)407--- PASS: TestCaseHackSuffix (0.17s)4082026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:41661409--- PASS: TestDumpPathSingleFile (0.17s)4102026/11/06 08:13:31 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=2000411--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.16s)412--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (0.18s)413=== CONT TestPartSizeForNAR/capped_at_5_GiB414=== CONT TestPartSizeForNAR/5_TiB_S3_max_object415=== CONT TestPartSizeForNAR/1_TiB416=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts417=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum418=== CONT TestPartSizeForNAR/small_stays_at_minimum419--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.17s)420--- PASS: TestRateLimiterFeedback (0.02s)421 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)422 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.13s)423 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)424 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)425--- PASS: TestParsePathInfoJSON (0.02s)426 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)427 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)428 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)429 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)430 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)431--- PASS: TestStreamPushBatchesUnderLoad (0.00s)432 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)433 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)4342026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:41661435--- PASS: TestPathInfoCACompatibility (0.02s)436 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)437 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)438 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)439 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)440 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)441--- PASS: TestGetStorePathHash (0.01s)442 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)443 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)444 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)445 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.13s)446--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)447 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)448 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)449--- PASS: TestFilterOversizedClosures (0.01s)450 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)451 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)452 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)453--- PASS: TestPartSizeForNAR (0.17s)454 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)455 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)456 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)457 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)458 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)459 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)460 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)461--- PASS: TestSetClientTLSErrors (0.02s)462 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)463 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)464 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)465 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)4662026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:416614672026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:416614682026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:416614692026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:416614702026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:41661471--- PASS: TestStreamPushRequestLine (0.18s)4722026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:416614732026/11/06 08:13:31 http: TLS handshake error from 127.0.0.1:58494: remote error: tls: bad certificate4742026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:41661475--- PASS: TestSetClientTLS (0.18s)476 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)477 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)478 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)4792026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:41661480--- PASS: TestDumpPathWriterError (0.21s)4812026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:416614822026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:416614832026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:416614842026/11/06 08:13:31 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:41661485--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.20s)4862026/11/06 08:13:31 INFO Uploading abc-hello (1.0GB)487--- PASS: TestRegisterUploadedObjectReusesConnections (0.20s)488--- PASS: TestDumpPathMatchesNix (0.25s)4892026/11/06 08:13:32 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:43609/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:43609/part/24902026/11/06 08:13:32 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:43609/part/3\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:43609/part/34912026/11/06 08:13:32 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:43609/part/4\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:43609/part/44922026/11/06 08:13:32 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"493--- PASS: TestSupersededNARStillUploadsListing (0.01s)494 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.16s)495 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.16s)496 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.74s)497--- PASS: TestUploadMultipart_PartsInParallel (0.79s)498--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.01s)499PASS500Running server tests...501The files belonging to this database system will be owned by user "nixbld".502This user must also own the server process.503504The database cluster will be initialized with locale "C".505The default database encoding has accordingly been set to "SQL_ASCII".506The default text search configuration will be set to "english".507508Data page checksums are enabled.509510creating directory /build/postgres1352176702/data ... ok511creating subdirectories ... ok512selecting dynamic shared memory implementation ... posix513selecting default "max_connections" ... 100514selecting default "shared_buffers" ... 128MB515selecting default time zone ... UTC516creating configuration files ... ok517running bootstrap script ... ok518performing post-bootstrap initialization ... ok519syncing data to disk ... ok520521initdb: warning: enabling "trust" authentication for local connections522initdb: 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.523524Success. You can now start the database server using:525526 pg_ctl -D /build/postgres1352176702/data -l logfile start527528/build/postgres1352176702:5432 - no response5292026-11-06 08:13:33.635 UTC [131] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit5302026-11-06 08:13:33.636 UTC [131] LOG: listening on Unix socket "/build/postgres1352176702/.s.PGSQL.5432"5312026-11-06 08:13:33.640 UTC [138] LOG: database system was shut down at 2026-11-06 08:13:33 UTC5322026-11-06 08:13:33.644 UTC [131] LOG: database system is ready to accept connections533/build/postgres1352176702:5432 - accepting connections534=== RUN TestService_AuthMiddleware535=== PAUSE TestService_AuthMiddleware536=== RUN TestService_AuthMiddleware_MTLSProxyHeader537=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader538=== RUN TestService_AuthMiddleware_MTLSBoundSubjects539=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects540=== RUN TestService_ReadAuthMiddleware541=== PAUSE TestService_ReadAuthMiddleware542=== RUN TestService_AuthMiddleware_OIDC543=== PAUSE TestService_AuthMiddleware_OIDC544=== RUN TestService_RequireScope_OIDC545=== PAUSE TestService_RequireScope_OIDC546=== RUN TestService_ReadScope_PublicByDefault547=== PAUSE TestService_ReadScope_PublicByDefault548=== RUN TestCacheConfigHandler549=== PAUSE TestCacheConfigHandler550=== RUN TestCacheStatsHandler551=== PAUSE TestCacheStatsHandler552=== RUN TestClientCADerivations553=== PAUSE TestClientCADerivations554=== RUN TestClientErrorHandling555=== PAUSE TestClientErrorHandling556=== RUN TestClientIntegration557=== PAUSE TestClientIntegration558=== RUN TestClientMultipleUploads559=== PAUSE TestClientMultipleUploads560=== RUN TestClientWithDependencies561=== PAUSE TestClientWithDependencies562=== RUN TestClientSharedPathCommittedMidPush563=== PAUSE TestClientSharedPathCommittedMidPush564=== RUN TestPinProtectsFromGC565=== PAUSE TestPinProtectsFromGC566=== RUN TestClientPushesUseOnePush567=== PAUSE TestClientPushesUseOnePush568=== RUN TestClientFallsBackToClosures569=== PAUSE TestClientFallsBackToClosures570=== RUN TestDeleteClosuresRacingPins571=== PAUSE TestDeleteClosuresRacingPins572=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock573=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock574=== RUN TestResolveDBConnectionString575=== PAUSE TestResolveDBConnectionString576=== RUN TestConnectWaitsForAPeerMigration577=== PAUSE TestConnectWaitsForAPeerMigration578=== RUN TestLeadElectsOneAndHandsOver579=== PAUSE TestLeadElectsOneAndHandsOver580=== RUN TestLeadIncumbentWinsAfterRestart5812026/11/06 08:13:34 INFO lead: acquired remote=192.0.2.1:12345822026/11/06 08:13:34 INFO lead: released remote=192.0.2.1:12345832026/11/06 08:13:35 INFO lead: acquired remote=192.0.2.1:12345842026/11/06 08:13:36 INFO lead: released remote=192.0.2.1:1234585--- PASS: TestLeadIncumbentWinsAfterRestart (1.88s)586=== RUN TestLeadIncumbentAnnouncesAtOnce587=== PAUSE TestLeadIncumbentAnnouncesAtOnce588=== RUN TestLeadEndsOnShutdown589=== PAUSE TestLeadEndsOnShutdown590=== RUN TestLeadEndsWhenItsConnectionHangs5912026/11/06 08:13:36 INFO lead: acquired remote=192.0.2.1:12345922026-11-06 08:13:37.642 UTC [574] FATAL: terminating connection due to administrator command5932026/11/06 08:13:37 INFO lead: acquired remote=192.0.2.1:12345942026/11/06 08:13:38 WARN lead: lock connection lost error="timeout: context deadline exceeded"5952026/11/06 08:13:38 INFO lead: released remote=192.0.2.1:12345962026/11/06 08:13:39 INFO lead: released remote=192.0.2.1:1234597--- PASS: TestLeadEndsWhenItsConnectionHangs (3.12s)598=== RUN TestGCAdvisoryLockBlocksConcurrentRun599=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun600=== RUN TestGCBugBareHashReferences601=== PAUSE TestGCBugBareHashReferences602=== RUN TestGCMetrics603=== PAUSE TestGCMetrics604=== RUN TestPushDedupSurvivesConcurrentGC605=== PAUSE TestPushDedupSurvivesConcurrentGC606=== RUN TestDeduplicatedObjectsRecordedAsPending607=== PAUSE TestDeduplicatedObjectsRecordedAsPending608=== RUN TestGCSweepSkipsPendingObjects609=== PAUSE TestGCSweepSkipsPendingObjects610=== RUN TestTombstonedObjectOfferedWithoutWaiting611=== PAUSE TestTombstonedObjectOfferedWithoutWaiting612=== RUN TestGCSweepDeliversEachKeyOnce613=== PAUSE TestGCSweepDeliversEachKeyOnce614=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection615=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection616=== RUN TestForceGCDuringPushOffersSweptObject617=== PAUSE TestForceGCDuringPushOffersSweptObject618=== RUN TestFailedS3DeleteKeepsTombstone619=== PAUSE TestFailedS3DeleteKeepsTombstone620=== RUN TestSweepSkipsRowsLockedByPush621=== PAUSE TestSweepSkipsRowsLockedByPush622=== RUN TestRegisterCompletedObjectNeedsPendingRow623=== PAUSE TestRegisterCompletedObjectNeedsPendingRow624=== RUN TestGetExistingObjectsLocksRows625=== PAUSE TestGetExistingObjectsLocksRows626=== RUN TestSweepRechecksPendingAfterLocking627=== PAUSE TestSweepRechecksPendingAfterLocking628=== RUN TestPushWaitsForSweepHoldingRow629=== PAUSE TestPushWaitsForSweepHoldingRow630=== RUN TestCommitRacingPendingCleanupKeepsObjects631=== PAUSE TestCommitRacingPendingCleanupKeepsObjects632=== RUN TestGCEndsOnShutdown633=== PAUSE TestGCEndsOnShutdown634=== RUN TestGCTaskStore_StartNew635=== PAUSE TestGCTaskStore_StartNew636=== RUN TestGCTaskStore_DeduplicateSameParams637=== PAUSE TestGCTaskStore_DeduplicateSameParams638=== RUN TestGCTaskStore_ConflictDifferentParams639=== PAUSE TestGCTaskStore_ConflictDifferentParams640=== RUN TestGCTaskStore_GetEmpty641=== PAUSE TestGCTaskStore_GetEmpty642=== RUN TestGCTaskStore_GetReturnsLatest643=== PAUSE TestGCTaskStore_GetReturnsLatest644=== RUN TestGCTaskStore_CompletedAllowsNewTask645=== PAUSE TestGCTaskStore_CompletedAllowsNewTask646=== RUN TestGCTaskStore_PhaseUpdates647=== PAUSE TestGCTaskStore_PhaseUpdates648=== RUN TestGCTaskStore_Fail649=== PAUSE TestGCTaskStore_Fail650=== RUN TestGracefulShutdownDrainsInflight651=== PAUSE TestGracefulShutdownDrainsInflight652=== RUN TestService_healthCheckHandler653=== PAUSE TestService_healthCheckHandler654=== RUN TestService_readinessHandler655=== PAUSE TestService_readinessHandler656=== RUN TestGenerateLandingPage657=== PAUSE TestGenerateLandingPage658=== RUN TestCacheConfigHandlerMaxNarSize659=== PAUSE TestCacheConfigHandlerMaxNarSize660=== RUN TestCreatePendingClosureRejectsOversizedNAR661=== PAUSE TestCreatePendingClosureRejectsOversizedNAR662=== RUN TestNARDeduplicationMetadataUploadBug663=== PAUSE TestNARDeduplicationMetadataUploadBug664=== RUN TestMetricsInventory665=== PAUSE TestMetricsInventory666=== RUN TestMetricsCommit667=== PAUSE TestMetricsCommit668=== RUN TestService_NativeMTLS669=== PAUSE TestService_NativeMTLS670=== RUN TestServerTLSConfig671=== PAUSE TestServerTLSConfig672=== RUN TestMultipartCleanup673=== PAUSE TestMultipartCleanup674=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded675=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded676=== RUN TestPendingCleanupUsesOneCutoff677=== PAUSE TestPendingCleanupUsesOneCutoff678=== RUN TestObjectStatsTrigger679=== PAUSE TestObjectStatsTrigger680=== RUN TestObjectStatsUpdatedOncePerCommit681=== PAUSE TestObjectStatsUpdatedOncePerCommit682=== RUN TestOrphanedObjectsGC683=== PAUSE TestOrphanedObjectsGC684=== RUN TestOrphanedObjectsGCStressTest685=== PAUSE TestOrphanedObjectsGCStressTest686=== RUN TestCreatePin_ReservedPins687=== PAUSE TestCreatePin_ReservedPins688=== RUN TestPresentReportsOnlyClosureRoots689=== PAUSE TestPresentReportsOnlyClosureRoots690=== RUN TestPresentRefreshesOnlyStaleClosures691=== PAUSE TestPresentRefreshesOnlyStaleClosures692=== RUN TestPresentNotReportedWhileGCDeletesClosure693=== PAUSE TestPresentNotReportedWhileGCDeletesClosure694=== RUN TestParseSingleRange695=== PAUSE TestParseSingleRange696=== RUN TestProxyHeadersOnlyTrustedOnSocket6972026/11/06 08:13:39 INFO Starting HTTP server address=proxy.sock6982026/11/06 08:13:39 INFO Starting HTTP server address=127.0.0.1:463376992026/11/06 08:13:39 WARN mTLS auth: subject not in bound subjects subject="CN=someone"7002026/11/06 08:13:39 INFO Shutdown signal received, draining in-flight requests timeout=10s701--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.11s)702=== RUN TestIsValidCachePath703=== PAUSE TestIsValidCachePath704=== RUN TestReadProxyNarinfo705=== PAUSE TestReadProxyNarinfo706=== RUN TestReadProxyNarinfoAlreadyDecompressed707=== PAUSE TestReadProxyNarinfoAlreadyDecompressed708=== RUN TestReadProxyContentNegotiation709=== PAUSE TestReadProxyContentNegotiation710=== RUN TestReadProxyNarStreaming711=== PAUSE TestReadProxyNarStreaming712=== RUN TestReadProxy404713=== PAUSE TestReadProxy404714=== RUN TestReadProxyInvalidPath715=== PAUSE TestReadProxyInvalidPath716=== RUN TestReadProxyHead717=== PAUSE TestReadProxyHead718=== RUN TestReadProxyOutlastsServerWriteTimeout719=== PAUSE TestReadProxyOutlastsServerWriteTimeout720=== RUN TestReadProxyConditionalGet721=== PAUSE TestReadProxyConditionalGet722=== RUN TestReadProxyRootRedirectsToIndexHTML723=== PAUSE TestReadProxyRootRedirectsToIndexHTML724=== RUN TestReadProxyDisabled725=== PAUSE TestReadProxyDisabled726=== RUN TestReadRedirectNar727=== PAUSE TestReadRedirectNar728=== RUN TestReadRedirectKeepsNarinfoProxied729=== PAUSE TestReadRedirectKeepsNarinfoProxied730=== RUN TestReadProxyRangeRequest731=== PAUSE TestReadProxyRangeRequest732=== RUN TestReadRedirectUsesPublicS3URL733=== PAUSE TestReadRedirectUsesPublicS3URL734=== RUN TestPush_OverlappingRootsStoreOneRowPerKey735=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey736=== RUN TestPush_CompleteCommitsEveryRoot737=== PAUSE TestPush_CompleteCommitsEveryRoot738=== RUN TestPush_RepeatedRootCommitsOnce739=== PAUSE TestPush_RepeatedRootCommitsOnce740=== RUN TestPush_CompleteWaitsForCleanupOfThePush741=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush742=== RUN TestPush_RootsAreLockedInByteOrder743=== PAUSE TestPush_RootsAreLockedInByteOrder744=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit745=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit746=== RUN TestPush_RejectsBadRequests747=== PAUSE TestPush_RejectsBadRequests748=== RUN TestPush_SignsNarinfosOfItsPendingObjects749=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects750=== RUN TestRedundantMultipartUpload751=== PAUSE TestRedundantMultipartUpload752=== RUN TestCompleteMultipartUpload_ErrorButObjectExists753=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists754=== RUN TestCompletedNarNotReofferedAcrossClosures755=== PAUSE TestCompletedNarNotReofferedAcrossClosures756=== RUN TestPresignedUploadRegisteredBeforeCommit757=== PAUSE TestPresignedUploadRegisteredBeforeCommit758=== RUN TestService_Rustfstest759=== PAUSE TestService_Rustfstest760=== RUN TestParseSize761=== PAUSE TestParseSize762=== RUN TestSkippedUploadsHandler763=== PAUSE TestSkippedUploadsHandler764=== RUN TestSystemdListenerNotActivated765--- PASS: TestSystemdListenerNotActivated (0.00s)766=== RUN TestWatchdogBeatsWhenHealthy767--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)768=== RUN TestWatchdogSkipsWhenUnhealthy7692026/11/06 08:13:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/11/06 08:13:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/11/06 08:13:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/11/06 08:13:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/11/06 08:13:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/11/06 08:13:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7752026/11/06 08:13:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7762026/11/06 08:13:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7772026/11/06 08:13:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7782026/11/06 08:13:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"779--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)780=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle781=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle782=== RUN TestProxyWriteTimeout783=== PAUSE TestProxyWriteTimeout784=== RUN TestPendingClosureWriteTimeout785=== PAUSE TestPendingClosureWriteTimeout786=== RUN TestIsValidUploadKey787=== PAUSE TestIsValidUploadKey788=== RUN TestUploadHandlersRejectInvalidKeys789=== PAUSE TestUploadHandlersRejectInvalidKeys790=== RUN TestUploadHandlersRejectOversizedBody791=== PAUSE TestUploadHandlersRejectOversizedBody792=== RUN TestService_cleanupPendingClosuresHandler793=== PAUSE TestService_cleanupPendingClosuresHandler794=== RUN TestService_createPendingClosureHandler795=== PAUSE TestService_createPendingClosureHandler796=== RUN TestService_verifyS3Integrity797=== PAUSE TestService_verifyS3Integrity798=== RUN TestService_verifyS3ReuploadsStaleNarinfo799=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo800=== RUN TestCompleteMultipartUnregistered801=== PAUSE TestCompleteMultipartUnregistered802=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT803=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT804=== CONT TestService_AuthMiddleware805=== CONT TestPendingClosureWriteTimeout806=== RUN TestPendingClosureWriteTimeout/empty807=== PAUSE TestPendingClosureWriteTimeout/empty808=== RUN TestPendingClosureWriteTimeout/400_objects809=== PAUSE TestPendingClosureWriteTimeout/400_objects810=== RUN TestPendingClosureWriteTimeout/670k_objects811=== PAUSE TestPendingClosureWriteTimeout/670k_objects812=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline813=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline814=== CONT TestSweepSkipsRowsLockedByPush815=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT816=== CONT TestCompleteMultipartUnregistered817=== CONT TestService_verifyS3ReuploadsStaleNarinfo818=== CONT TestService_verifyS3Integrity819=== CONT TestService_createPendingClosureHandler820=== CONT TestService_cleanupPendingClosuresHandler821=== CONT TestUploadHandlersRejectOversizedBody822=== CONT TestUploadHandlersRejectInvalidKeys823=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info824=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info825=== CONT TestIsValidUploadKey826=== CONT TestPresentReportsOnlyClosureRoots827=== CONT TestCreatePin_ReservedPins828=== CONT TestOrphanedObjectsGCStressTest829=== CONT TestOrphanedObjectsGC830=== CONT TestObjectStatsUpdatedOncePerCommit831=== CONT TestObjectStatsTrigger832=== CONT TestPendingCleanupUsesOneCutoff833=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded834=== CONT TestMultipartCleanup835=== CONT TestServerTLSConfig836=== CONT TestService_NativeMTLS837=== CONT TestPresentRefreshesOnlyStaleClosures838=== CONT TestMetricsCommit839=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed840=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal841=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal842=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key843=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key844=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key845=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key846=== CONT TestMetricsInventory847=== RUN TestServerTLSConfig/no_client_CA848=== PAUSE TestServerTLSConfig/no_client_CA849=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed850=== RUN TestIsValidUploadKey/narinfo851=== RUN TestServerTLSConfig/missing_CA_file852=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed853=== PAUSE TestIsValidUploadKey/narinfo854=== PAUSE TestServerTLSConfig/missing_CA_file855=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed856=== RUN TestIsValidUploadKey/nar_zst857=== PAUSE TestIsValidUploadKey/nar_zst858=== RUN TestIsValidUploadKey/nar_xz859=== PAUSE TestIsValidUploadKey/nar_xz860=== RUN TestIsValidUploadKey/nar_plain861=== PAUSE TestIsValidUploadKey/nar_plain862=== RUN TestIsValidUploadKey/listing863=== RUN TestServerTLSConfig/not_a_PEM_file864=== PAUSE TestServerTLSConfig/not_a_PEM_file865=== PAUSE TestIsValidUploadKey/listing866=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost867=== CONT TestNARDeduplicationMetadataUploadBug868=== RUN TestIsValidUploadKey/build_log869=== PAUSE TestIsValidUploadKey/build_log870=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost871=== RUN TestIsValidUploadKey/build_log_home-manager_file872=== PAUSE TestIsValidUploadKey/build_log_home-manager_file873=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed874=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed875=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed876=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed877=== RUN TestIsValidUploadKey/build_log_plus_in_name878=== PAUSE TestIsValidUploadKey/build_log_plus_in_name879=== RUN TestIsValidUploadKey/build_log_question_mark880=== PAUSE TestIsValidUploadKey/build_log_question_mark881=== RUN TestIsValidUploadKey/build_log_equals882=== PAUSE TestIsValidUploadKey/build_log_equals883=== RUN TestIsValidUploadKey/realisation884=== PAUSE TestIsValidUploadKey/realisation885=== RUN TestIsValidUploadKey/realisation_plus_in_output886=== PAUSE TestIsValidUploadKey/realisation_plus_in_output887=== CONT TestCreatePendingClosureRejectsOversizedNAR888=== RUN TestIsValidUploadKey/nix-cache-info889=== PAUSE TestIsValidUploadKey/nix-cache-info890=== RUN TestIsValidUploadKey/index.html891=== PAUSE TestIsValidUploadKey/index.html892=== RUN TestIsValidUploadKey/narinfo_key,_nar_type893=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type894=== RUN TestIsValidUploadKey/nar_key,_narinfo_type895=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type896=== RUN TestIsValidUploadKey/listing_key,_narinfo_type897=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type898=== RUN TestIsValidUploadKey/traversal8992026/11/06 08:13:39 INFO Received uploads request method=POST path=/api/pending_closures900=== PAUSE TestIsValidUploadKey/traversal901=== RUN TestIsValidUploadKey/traversal_nar902=== PAUSE TestIsValidUploadKey/traversal_nar903=== RUN TestIsValidUploadKey/absolute904=== PAUSE TestIsValidUploadKey/absolute905=== RUN TestIsValidUploadKey/empty_key906=== PAUSE TestIsValidUploadKey/empty_key907=== RUN TestIsValidUploadKey/unknown_type908=== PAUSE TestIsValidUploadKey/unknown_type909=== CONT TestCacheConfigHandlerMaxNarSize910--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)911--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)912=== CONT TestGenerateLandingPage913=== CONT TestService_readinessHandler914--- PASS: TestGenerateLandingPage (0.00s)915=== CONT TestService_healthCheckHandler9162026/11/06 08:13:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41849/oidc917=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure918=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure919=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart920=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart921=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts922=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts923=== CONT TestGracefulShutdownDrainsInflight9242026/11/06 08:13:39 INFO Starting HTTP server address=127.0.0.1:444699252026/11/06 08:13:39 INFO Shutdown signal received, draining in-flight requests timeout=10s926--- PASS: TestGracefulShutdownDrainsInflight (0.07s)927=== CONT TestGCTaskStore_Fail928--- PASS: TestGCTaskStore_Fail (0.00s)929=== CONT TestGCTaskStore_PhaseUpdates930--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)931=== CONT TestGCTaskStore_CompletedAllowsNewTask932=== CONT TestGCTaskStore_GetReturnsLatest933=== CONT TestGCTaskStore_GetEmpty934=== CONT TestGCTaskStore_ConflictDifferentParams935=== CONT TestGCTaskStore_DeduplicateSameParams936=== CONT TestGCTaskStore_StartNew937=== CONT TestGCEndsOnShutdown938=== RUN TestGCEndsOnShutdown/before_the_run939--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)940--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)941--- PASS: TestGCTaskStore_GetEmpty (0.00s)942--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)943--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)944--- PASS: TestGCTaskStore_StartNew (0.00s)945=== PAUSE TestGCEndsOnShutdown/before_the_run946=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete947=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete948=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark949=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark950=== CONT TestCommitRacingPendingCleanupKeepsObjects9512026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures9522026/11/06 08:13:40 INFO Aborted multipart uploads count=0 kept=09532026/11/06 08:13:40 WARN Force mode enabled - objects will be deleted immediately without grace period9542026/11/06 08:13:40 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=09552026/11/06 08:13:40 INFO Vacuumed table table=pending_closures9562026/11/06 08:13:40 INFO Vacuumed table table=pending_objects9572026/11/06 08:13:40 INFO Vacuumed table table=multipart_uploads9582026/11/06 08:13:40 INFO Vacuumed table table=closures9592026/11/06 08:13:40 INFO Vacuumed table table=objects960--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.44s)961=== CONT TestPushWaitsForSweepHoldingRow9622026/11/06 08:13:40 INFO Aborted multipart uploads count=0 kept=09632026/11/06 08:13:40 WARN Force mode enabled - objects will be deleted immediately without grace period9642026/11/06 08:13:40 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"965--- PASS: TestService_AuthMiddleware (0.45s)966=== CONT TestSweepRechecksPendingAfterLocking9672026/11/06 08:13:40 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=09682026/11/06 08:13:40 INFO Vacuumed table table=pending_closures9692026/11/06 08:13:40 INFO Vacuumed table table=pending_objects9702026/11/06 08:13:40 INFO Vacuumed table table=multipart_uploads9712026/11/06 08:13:40 INFO Vacuumed table table=closures9722026/11/06 08:13:40 INFO Vacuumed table table=objects973--- PASS: TestSweepSkipsRowsLockedByPush (0.47s)974=== CONT TestGetExistingObjectsLocksRows975--- PASS: TestMetricsInventory (0.48s)976=== CONT TestRegisterCompletedObjectNeedsPendingRow9772026/11/06 08:13:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9782026/11/06 08:13:40 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst979--- PASS: TestCompleteMultipartUnregistered (0.51s)980=== CONT TestDeleteClosuresRacingPins981--- PASS: TestObjectStatsTrigger (0.51s)982=== CONT TestFailedS3DeleteKeepsTombstone9832026/11/06 08:13:40 INFO Received cleanup request method=DELETE path=/api/pending_closures9842026/11/06 08:13:40 INFO Aborted multipart uploads count=0 kept=09852026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures9862026/11/06 08:13:40 WARN mTLS auth: subject not in bound subjects subject="CN=reader"9872026/11/06 08:13:40 WARN mTLS auth: subject not in bound subjects subject="CN=reader"988--- PASS: TestService_NativeMTLS (0.55s)989=== CONT TestForceGCDuringPushOffersSweptObject990=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows991=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows992=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check993=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check994=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection9952026/11/06 08:13:40 INFO Received cleanup request method=DELETE path=/api/pending_closures9962026/11/06 08:13:40 INFO Aborted multipart uploads count=1 kept=09972026/11/06 08:13:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9982026-11-06 08:13:40.163 UTC [650] ERROR: Closure does not exist: id=19992026-11-06 08:13:40.163 UTC [650] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10002026-11-06 08:13:40.163 UTC [650] STATEMENT: -- name: CommitPendingClosure :one1001 SELECT commit_pending_closure($1::bigint)::bigint1002 1003--- PASS: TestService_cleanupPendingClosuresHandler (0.58s)1004=== CONT TestGCSweepDeliversEachKeyOnce10052026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures10062026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures10072026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures10082026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures10092026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures1010--- PASS: TestPresentReportsOnlyClosureRoots (0.66s)1011=== CONT TestTombstonedObjectOfferedWithoutWaiting10122026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures1013--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.70s)1014=== CONT TestGCSweepSkipsPendingObjects1015--- PASS: TestPresentRefreshesOnlyStaleClosures (0.75s)1016=== CONT TestDeduplicatedObjectsRecordedAsPending1017--- PASS: TestObjectStatsUpdatedOncePerCommit (0.76s)1018=== CONT TestPushDedupSurvivesConcurrentGC1019--- PASS: TestService_healthCheckHandler (0.67s)1020=== CONT TestGCMetrics10212026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures10222026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures1023=== NAME TestNARDeduplicationMetadataUploadBug1024 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug3755085081/001/store/2c8nixz40dcs74ngscxgxngi49fl5z67-file1.txt10252026/11/06 08:13:40 INFO Received cleanup request method=DELETE path=/api/pending_closures10262026/11/06 08:13:40 WARN readiness check failed error="closed pool"1027--- PASS: TestService_readinessHandler (0.75s)1028=== CONT TestGCBugBareHashReferences10292026/11/06 08:13:40 INFO Received push request method=POST path=/api/pushes10302026/11/06 08:13:40 INFO Received push request method=POST path=/api/pushes10312026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures10322026/11/06 08:13:40 INFO Received complete push request method=POST path=/api/pushes/1/complete10332026/11/06 08:13:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10342026/11/06 08:13:40 INFO Uploading 2c8nixz40dcs74ngscxgxngi49fl5z67-file1.txt (160B)10352026/11/06 08:13:40 INFO Completed push id=1 objects=4 duration=8.405208ms10362026/11/06 08:13:40 WARN Failed to register uploaded object key=2c8nixz40dcs74ngscxgxngi49fl5z67.ls error="server returned 404: 404 page not found\n"10372026/11/06 08:13:40 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"10382026/11/06 08:13:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10392026/11/06 08:13:40 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10402026/11/06 08:13:40 INFO Signed narinfos id=1 count=110412026/11/06 08:13:40 INFO Uploading 1 narinfos10422026/11/06 08:13:40 INFO Completed upload id=2 objects=2 duration=985.449µs10432026/11/06 08:13:40 INFO Received complete push request method=POST path=/api/pushes/1/complete10442026/11/06 08:13:40 WARN Failed to register uploaded object key=2c8nixz40dcs74ngscxgxngi49fl5z67.narinfo error="server returned 404: 404 page not found\n"1045--- PASS: TestMetricsCommit (0.94s)1046=== CONT TestGCAdvisoryLockBlocksConcurrentRun10472026/11/06 08:13:40 INFO Completed push id=1 objects=3 duration=9.344587ms10482026/11/06 08:13:40 INFO Upload complete. (72ms)1049=== NAME TestNARDeduplicationMetadataUploadBug1050 metadata_upload_test.go:54: Retrieved narinfo from S3:1051 StorePath: /build/TestNARDeduplicationMetadataUploadBug3755085081/001/store/2c8nixz40dcs74ngscxgxngi49fl5z67-file1.txt1052 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1053 Compression: zstd1054 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1055 NarSize: 1601056 References: 1057 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1058 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1059 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1060 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1061 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug3755085081/001/store/21pgqc95w881byzsxviawrjaag1zxjpb-file2.txt10622026/11/06 08:13:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10632026/11/06 08:13:40 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10642026/11/06 08:13:40 WARN Refused reserved pin name=worker-x86_64-linux10652026/11/06 08:13:40 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10662026/11/06 08:13:40 INFO Received create pin request method=POST path=/api/pins/my-app10672026/11/06 08:13:40 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1068--- PASS: TestCreatePin_ReservedPins (1.02s)1069=== CONT TestLeadEndsOnShutdown10702026/11/06 08:13:40 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MDU5MTMyZDMtZmQ2My00Yjk5LTgzZmItMjRkNTljZWI2NjQ5LmI3ZWNmMWY4LTVlYzktNDcxYy1hYzc3LTI3MzhjMTY4Y2FmOXgxNzkzOTUyODIwMTc1MDk5MzM0 parts=1010712026/11/06 08:13:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10722026/11/06 08:13:40 INFO Completed upload id=1 objects=2 duration=3.897999ms10732026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures10742026/11/06 08:13:40 INFO Received cleanup request method=DELETE path=/api/pending_closures10752026/11/06 08:13:40 INFO Aborted multipart uploads count=0 kept=010762026/11/06 08:13:40 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket24/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""10772026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures10782026/11/06 08:13:40 INFO Aborted multipart uploads count=0 kept=110792026/11/06 08:13:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10802026/11/06 08:13:40 WARN Force mode enabled - objects will be deleted immediately without grace period10812026/11/06 08:13:40 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10822026/11/06 08:13:40 WARN Found objects in DB but missing from S3, will re-upload count=11083--- PASS: TestService_verifyS3Integrity (1.05s)1084=== CONT TestLeadIncumbentAnnouncesAtOnce10852026/11/06 08:13:40 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=010862026/11/06 08:13:40 INFO Received cleanup request method=DELETE path=/api/pending_closures10872026/11/06 08:13:40 INFO Aborted multipart uploads count=1 kept=010882026/11/06 08:13:40 INFO Vacuumed table table=pending_closures10892026/11/06 08:13:40 INFO Vacuumed table table=pending_objects10902026/11/06 08:13:40 INFO Vacuumed table table=multipart_uploads10912026/11/06 08:13:40 INFO Vacuumed table table=closures1092--- PASS: TestMultipartCleanup (1.05s)1093=== CONT TestLeadElectsOneAndHandsOver10942026/11/06 08:13:40 INFO Vacuumed table table=objects10952026/11/06 08:13:40 INFO Received push request method=POST path=/api/pushes10962026/11/06 08:13:40 INFO Aborted multipart uploads count=0 kept=01097--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.81s)1098=== CONT TestConnectWaitsForAPeerMigration10992026/11/06 08:13:40 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)11002026/11/06 08:13:40 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MDU5MTMyZDMtZmQ2My00Yjk5LTgzZmItMjRkNTljZWI2NjQ5LjM1NTE4ZDJkLTM4OGItNDFiMi05Y2E3LWQxMGNhOWNmODE2MXgxNzkzOTUyODIwMjAzODQyMjU1 parts=1011012026/11/06 08:13:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11022026/11/06 08:13:40 WARN Force mode enabled - objects will be deleted immediately without grace period11032026/11/06 08:13:40 INFO Completed upload id=1 objects=2 duration=4.927148ms11042026/11/06 08:13:40 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011052026/11/06 08:13:40 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign11062026/11/06 08:13:40 WARN Failed to register uploaded object key=21pgqc95w881byzsxviawrjaag1zxjpb.ls error="server returned 404: 404 page not found\n"11072026/11/06 08:13:40 INFO Signed narinfos id=2 count=111082026/11/06 08:13:40 INFO Uploading 1 narinfos11092026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures11102026/11/06 08:13:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures11112026/11/06 08:13:40 INFO Received complete push request method=POST path=/api/pushes/2/complete11122026/11/06 08:13:40 WARN Failed to register uploaded object key=21pgqc95w881byzsxviawrjaag1zxjpb.narinfo error="server returned 404: 404 page not found\n"11132026/11/06 08:13:40 INFO Completed push id=2 objects=3 duration=3.188069ms11142026/11/06 08:13:40 INFO Upload complete. (56ms)1115=== NAME TestNARDeduplicationMetadataUploadBug1116 metadata_upload_test.go:76: Retrieved narinfo from S3:1117 StorePath: /build/TestNARDeduplicationMetadataUploadBug3755085081/001/store/21pgqc95w881byzsxviawrjaag1zxjpb-file2.txt1118 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1119 Compression: zstd1120 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1121 NarSize: 1601122 References: 1123 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1124--- PASS: TestGetExistingObjectsLocksRows (0.61s)1125=== CONT TestResolveDBConnectionString1126=== RUN TestResolveDBConnectionString/flag_wins1127=== PAUSE TestResolveDBConnectionString/flag_wins1128=== RUN TestResolveDBConnectionString/file_when_flag_empty1129=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1130=== RUN TestResolveDBConnectionString/missing_file_is_an_error1131=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1132=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1133=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1134=== RUN TestResolveDBConnectionString/nothing_configured1135=== PAUSE TestResolveDBConnectionString/nothing_configured1136=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1137=== NAME TestNARDeduplicationMetadataUploadBug1138 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1139 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1140 {"version":1,"root":{"type":"regular","size":44}}11412026/11/06 08:13:40 INFO Aborted multipart uploads count=0 kept=011422026/11/06 08:13:40 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=011432026/11/06 08:13:40 INFO Vacuumed table table=pending_closures1144--- PASS: TestNARDeduplicationMetadataUploadBug (1.00s)1145=== CONT TestClientCADerivations11462026/11/06 08:13:40 INFO Vacuumed table table=pending_objects11472026/11/06 08:13:40 INFO Vacuumed table table=multipart_uploads11482026/11/06 08:13:40 INFO Vacuumed table table=closures11492026/11/06 08:13:40 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=011502026/11/06 08:13:40 INFO Vacuumed table table=objects1151--- PASS: TestSweepRechecksPendingAfterLocking (0.66s)1152=== CONT TestClientFallsBackToClosures1153--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.62s)1154=== CONT TestClientPushesUseOnePush11552026/11/06 08:13:40 INFO Vacuumed table table=pending_closures11562026/11/06 08:13:40 INFO Vacuumed table table=pending_objects11572026/11/06 08:13:40 INFO Vacuumed table table=multipart_uploads11582026/11/06 08:13:40 INFO Vacuumed table table=closures11592026/11/06 08:13:40 INFO Vacuumed table table=objects11602026/11/06 08:13:40 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001161--- PASS: TestService_createPendingClosureHandler (1.13s)1162=== CONT TestPinProtectsFromGC1163--- PASS: TestPushWaitsForSweepHoldingRow (0.71s)1164=== CONT TestClientSharedPathCommittedMidPush11652026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures11662026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures11672026/11/06 08:13:40 INFO Aborted multipart uploads count=0 kept=011682026/11/06 08:13:40 WARN Force mode enabled - objects will be deleted immediately without grace period11692026/11/06 08:13:40 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."11702026/11/06 08:13:40 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1171--- PASS: TestFailedS3DeleteKeepsTombstone (0.75s)1172=== CONT TestClientWithDependencies11732026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures1174--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.61s)1175=== CONT TestClientMultipleUploads11762026/11/06 08:13:40 INFO Aborted multipart uploads count=0 kept=011772026/11/06 08:13:40 WARN Force mode enabled - objects will be deleted immediately without grace period11782026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures1179=== NAME TestOrphanedObjectsGC1180 orphaned_objects_gc_test.go:287: GC Test Summary:1181 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1182 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1183 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1184 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1185 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1186--- PASS: TestOrphanedObjectsGC (1.32s)1187=== CONT TestClientIntegration11882026/11/06 08:13:40 INFO Aborted multipart uploads count=0 kept=011892026/11/06 08:13:40 WARN Force mode enabled - objects will be deleted immediately without grace period11902026/11/06 08:13:40 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=011912026/11/06 08:13:40 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=011922026/11/06 08:13:40 INFO Vacuumed table table=pending_closures11932026/11/06 08:13:40 INFO Vacuumed table table=pending_closures11942026/11/06 08:13:40 INFO Vacuumed table table=pending_objects11952026/11/06 08:13:40 INFO Vacuumed table table=multipart_uploads11962026/11/06 08:13:40 INFO Received uploads request method=POST path=/api/pending_closures11972026/11/06 08:13:40 INFO Vacuumed table table=closures11982026/11/06 08:13:40 INFO Vacuumed table table=pending_objects11992026/11/06 08:13:40 INFO Vacuumed table table=multipart_uploads12002026/11/06 08:13:40 INFO Vacuumed table table=objects12012026/11/06 08:13:40 INFO Vacuumed table table=closures1202--- PASS: TestGCSweepDeliversEachKeyOnce (0.76s)1203=== CONT TestClientErrorHandling1204=== RUN TestClientErrorHandling/InvalidStorePath1205=== PAUSE TestClientErrorHandling/InvalidStorePath1206=== RUN TestClientErrorHandling/InvalidAuthToken1207=== PAUSE TestClientErrorHandling/InvalidAuthToken1208=== RUN TestClientErrorHandling/ServerNotAvailable1209=== PAUSE TestClientErrorHandling/ServerNotAvailable1210=== CONT TestReadRedirectUsesPublicS3URL12112026/11/06 08:13:40 INFO Vacuumed table table=objects1212--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.59s)1213=== CONT TestProxyWriteTimeout1214=== RUN TestProxyWriteTimeout/narinfo1215=== PAUSE TestProxyWriteTimeout/narinfo1216=== RUN TestProxyWriteTimeout/1_GiB_nar1217=== PAUSE TestProxyWriteTimeout/1_GiB_nar1218=== RUN TestProxyWriteTimeout/10_GiB_nar1219=== PAUSE TestProxyWriteTimeout/10_GiB_nar1220=== RUN TestProxyWriteTimeout/unknown_size1221=== PAUSE TestProxyWriteTimeout/unknown_size1222=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1223--- PASS: TestGCSweepSkipsPendingObjects (0.65s)1224=== CONT TestSkippedUploadsHandler12252026/11/06 08:13:40 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001226--- PASS: TestSkippedUploadsHandler (0.01s)1227=== CONT TestParseSize1228--- PASS: TestParseSize (0.00s)1229=== CONT TestService_Rustfstest12302026/11/06 08:13:40 INFO Aborted multipart uploads count=0 kept=012312026/11/06 08:13:40 WARN Force mode enabled - objects will be deleted immediately without grace period12322026/11/06 08:13:40 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=012332026/11/06 08:13:40 INFO Vacuumed table table=pending_closures12342026/11/06 08:13:40 INFO Vacuumed table table=pending_objects12352026/11/06 08:13:40 INFO Vacuumed table table=multipart_uploads12362026/11/06 08:13:40 INFO Vacuumed table table=closures12372026/11/06 08:13:40 INFO Vacuumed table table=objects1238--- PASS: TestGCMetrics (0.62s)1239=== CONT TestPresignedUploadRegisteredBeforeCommit1240--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.85s)1241=== CONT TestCompletedNarNotReofferedAcrossClosures12422026/11/06 08:13:41 INFO Received uploads request method=POST path=/api/pending_closures12432026/11/06 08:13:41 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"1244--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.50s)1245=== CONT TestCompleteMultipartUpload_ErrorButObjectExists12462026/11/06 08:13:41 INFO lead: acquired remote=192.0.2.1:123412472026/11/06 08:13:41 INFO lead: acquired remote=192.0.2.1:123412482026/11/06 08:13:41 INFO lead: released remote=192.0.2.1:12341249--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.45s)1250=== CONT TestRedundantMultipartUpload12512026/11/06 08:13:41 INFO Aborted multipart uploads count=0 kept=012522026/11/06 08:13:41 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=012532026/11/06 08:13:41 INFO lead: acquired remote=192.0.2.1:123412542026/11/06 08:13:41 INFO Vacuumed table table=pending_closures12552026/11/06 08:13:41 INFO Vacuumed table table=pending_objects12562026/11/06 08:13:41 INFO Vacuumed table table=multipart_uploads12572026/11/06 08:13:41 INFO Vacuumed table table=closures12582026/11/06 08:13:41 INFO Vacuumed table table=objects12592026/11/06 08:13:41 INFO Aborted multipart uploads count=0 kept=012602026/11/06 08:13:41 WARN Force mode enabled - objects will be deleted immediately without grace period12612026/11/06 08:13:41 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012622026/11/06 08:13:41 INFO Vacuumed table table=pending_closures12632026/11/06 08:13:41 INFO Vacuumed table table=pending_objects12642026/11/06 08:13:41 INFO Vacuumed table table=multipart_uploads12652026/11/06 08:13:41 INFO Vacuumed table table=closures12662026/11/06 08:13:41 INFO Vacuumed table table=objects1267--- PASS: TestPushDedupSurvivesConcurrentGC (0.79s)1268=== CONT TestPush_SignsNarinfosOfItsPendingObjects1269--- PASS: TestGCBugBareHashReferences (0.81s)1270=== CONT TestPush_RejectsBadRequests1271=== NAME TestClientCADerivations1272 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations1112751105/001/store/nnb0dy1p4yrghfl45ah8fp3cfqsp3m54-ca-test1273 client_ca_test.go:139: Found 1 dependencies (including self)1274--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.65s)1275=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit1276=== NAME TestPinProtectsFromGC1277 client_integration_test.go:778: Pinned store path: /build/TestPinProtectsFromGC1956704854/001/store/pg3r70ggaacdxazyqsn4vvpaxs5dxmlz-pinned-file.txt1278 client_integration_test.go:779: Unpinned store path: /build/TestPinProtectsFromGC1956704854/001/store/yk9wzzp23xgbn7j4apqfyvz1axf6dz76-unpinned-file.txt1279=== NAME TestClientMultipleUploads1280 client_integration_test.go:405: Created store path 0: /build/TestClientMultipleUploads2958464783/001/store/6x5l0h1lwr8gsn9m4aqkclg0mzl205dy-test-file-0.txt1281=== NAME TestClientWithDependencies1282 client_integration_test.go:660: Built derivation: /build/TestClientWithDependencies4084087447/001/store/avviyr4qqpk4qigxhv598zmkjldg7dxk-test-script1283--- PASS: TestReadRedirectUsesPublicS3URL (0.46s)1284=== CONT TestPush_RootsAreLockedInByteOrder1285=== NAME TestClientIntegration1286 client_integration_test.go:291: Created store path: /build/TestClientIntegration2763138284/002/store/j0vsh40i9g731j36n0gj6yjn4l4za0la-test-file.txt12872026/11/06 08:13:41 INFO Received push request method=POST path=/api/pushes1288=== NAME TestClientMultipleUploads1289 client_integration_test.go:405: Created store path 1: /build/TestClientMultipleUploads2958464783/001/store/m284s78wncd982svqyk7c7f0w8vkz95z-test-file-1.txt12902026/11/06 08:13:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12912026/11/06 08:13:41 INFO Uploading pg3r70ggaacdxazyqsn4vvpaxs5dxmlz-pinned-file.txt (128B)12922026/11/06 08:13:41 INFO Received uploads request method=POST path=/api/pending_closures12932026/11/06 08:13:41 INFO Received push request method=POST path=/api/pushes12942026/11/06 08:13:41 WARN Failed to register uploaded object key=pg3r70ggaacdxazyqsn4vvpaxs5dxmlz.ls error="server returned 404: 404 page not found\n"12952026/11/06 08:13:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12962026/11/06 08:13:41 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"12972026/11/06 08:13:41 INFO Signed narinfos id=1 count=112982026/11/06 08:13:41 INFO Uploading 1 narinfos12992026/11/06 08:13:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13002026/11/06 08:13:41 INFO Uploading nnb0dy1p4yrghfl45ah8fp3cfqsp3m54-ca-test (144B)13012026/11/06 08:13:41 INFO Received push request method=POST path=/api/pushes13022026/11/06 08:13:41 INFO Received complete push request method=POST path=/api/pushes/1/complete13032026/11/06 08:13:41 WARN Failed to register uploaded object key=pg3r70ggaacdxazyqsn4vvpaxs5dxmlz.narinfo error="server returned 404: 404 page not found\n"1304=== NAME TestClientWithDependencies1305 client_integration_test.go:662: Found 1 dependencies (including self)13062026/11/06 08:13:41 INFO Received uploads request method=POST path=/api/pending_closures13072026/11/06 08:13:41 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13082026/11/06 08:13:41 INFO Uploading bkzpqijzhwz8l3396n6q44jsblql8pm1-shared-dep (136B)13092026/11/06 08:13:41 INFO Uploading 328ix3511qf93sdsad8mdj6dqmlrw3id-b (216B)13102026/11/06 08:13:41 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"13112026/11/06 08:13:41 WARN Failed to register uploaded object key=nnb0dy1p4yrghfl45ah8fp3cfqsp3m54.ls error="server returned 404: 404 page not found\n"13122026/11/06 08:13:41 WARN Failed to register uploaded object key=log/v2prn9h8z9wl8446whppsmvdl5466mm3-ca-test.drv error="server returned 404: 404 page not found\n"13132026/11/06 08:13:41 INFO Received uploads request method=POST path=/api/pending_closures13142026/11/06 08:13:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13152026/11/06 08:13:41 INFO Signed narinfos id=1 count=113162026/11/06 08:13:41 INFO Uploading 1 narinfos13172026/11/06 08:13:41 INFO Completed push id=1 objects=3 duration=9.862307ms13182026/11/06 08:13:41 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13192026/11/06 08:13:41 INFO Uploading vc9fhz90fr3lc9l2d6h9cvaa5lm3vaa4-a (216B)13202026/11/06 08:13:41 INFO Upload complete. (69ms)13212026/11/06 08:13:41 INFO Uploading 80684b6v09n4pl60frf9abzfjg1filf3-shared-dep (136B)13222026/11/06 08:13:41 WARN Failed to register uploaded object key=328ix3511qf93sdsad8mdj6dqmlrw3id.ls error="server returned 404: 404 page not found\n"13232026/11/06 08:13:41 WARN Failed to register uploaded object key=d4lbzg3k6navc88rwzi8dpjs5yq12zi0.ls error="server returned 404: 404 page not found\n"13242026/11/06 08:13:41 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13252026/11/06 08:13:41 WARN Failed to register uploaded object key=nar/0zainplprmkhn78hm1zdm5mnfhifza1a3j3k74r3312bp06w8klx.nar.zst error="server returned 404: 404 page not found\n"13262026/11/06 08:13:41 WARN Failed to register uploaded object key=bkzpqijzhwz8l3396n6q44jsblql8pm1.ls error="server returned 404: 404 page not found\n"13272026/11/06 08:13:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13282026/11/06 08:13:41 INFO Signed narinfos id=1 count=313292026/11/06 08:13:41 INFO Uploading 3 narinfos13302026/11/06 08:13:41 INFO Received push request method=POST path=/api/pushes13312026/11/06 08:13:41 INFO Received complete push request method=POST path=/api/pushes/1/complete13322026/11/06 08:13:41 WARN Failed to register uploaded object key=nnb0dy1p4yrghfl45ah8fp3cfqsp3m54.narinfo error="server returned 404: 404 page not found\n"1333--- PASS: TestService_Rustfstest (0.49s)1334=== CONT TestPush_CompleteWaitsForCleanupOfThePush13352026/11/06 08:13:41 WARN Failed to register uploaded object key=8ryi7cnzcfnd8lky2lcavar9akc8viwq.ls error="server returned 404: 404 page not found\n"13362026/11/06 08:13:41 WARN Failed to register uploaded object key=vc9fhz90fr3lc9l2d6h9cvaa5lm3vaa4.ls error="server returned 404: 404 page not found\n"13372026/11/06 08:13:41 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13382026/11/06 08:13:41 WARN Failed to register uploaded object key=80684b6v09n4pl60frf9abzfjg1filf3.ls error="server returned 404: 404 page not found\n"13392026/11/06 08:13:41 WARN Failed to register uploaded object key=d4lbzg3k6navc88rwzi8dpjs5yq12zi0.narinfo error="server returned 404: 404 page not found\n"13402026/11/06 08:13:41 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13412026/11/06 08:13:41 WARN Failed to register uploaded object key=nar/01adnck3v7l1227m93mwp07n6yf7h0xbzhbyn0yfv8w17lyf3814.nar.zst error="server returned 404: 404 page not found\n"13422026/11/06 08:13:41 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)13432026/11/06 08:13:41 INFO Uploading j0pd6ga2r49pvqxsfdcjpqf254vyjlvg-top (224B)13442026/11/06 08:13:41 INFO Uploading 6amkx82nz7d9zfjb5xshphz80axhgk0b-shared-dep (136B)13452026/11/06 08:13:41 INFO Signed narinfos id=1 count=213462026/11/06 08:13:41 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13472026/11/06 08:13:41 WARN Failed to register uploaded object key=328ix3511qf93sdsad8mdj6dqmlrw3id.narinfo error="server returned 404: 404 page not found\n"13482026/11/06 08:13:41 INFO Signed narinfos id=2 count=213492026/11/06 08:13:41 INFO Uploading 4 narinfos13502026/11/06 08:13:41 INFO Received complete push request method=POST path=/api/pushes/1/complete13512026/11/06 08:13:41 WARN Failed to register uploaded object key=bkzpqijzhwz8l3396n6q44jsblql8pm1.narinfo error="server returned 404: 404 page not found\n"1352=== NAME TestClientMultipleUploads1353 client_integration_test.go:405: Created store path 2: /build/TestClientMultipleUploads2958464783/001/store/vf1nd600y4f130rplp9kp186zw9dw7w3-test-file-2.txt13542026/11/06 08:13:41 INFO Completed push id=1 objects=4 duration=8.114067ms13552026/11/06 08:13:41 INFO Upload complete. (113ms)13562026/11/06 08:13:41 WARN Failed to register uploaded object key=nar/1yahzjwr6ivjj03zh1j0l6lz3j3cma3c73g0dzh6mjm0n4h4gqsl.nar.zst error="server returned 404: 404 page not found\n"13572026/11/06 08:13:41 WARN Failed to register uploaded object key=6amkx82nz7d9zfjb5xshphz80axhgk0b.ls error="server returned 404: 404 page not found\n"13582026/11/06 08:13:41 WARN Failed to register uploaded object key=80684b6v09n4pl60frf9abzfjg1filf3.narinfo error="server returned 404: 404 page not found\n"13592026/11/06 08:13:41 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13602026/11/06 08:13:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13612026/11/06 08:13:41 WARN Failed to register uploaded object key=j0pd6ga2r49pvqxsfdcjpqf254vyjlvg.ls error="server returned 404: 404 page not found\n"13622026/11/06 08:13:41 INFO Signed narinfos id=1 count=213632026/11/06 08:13:41 INFO Uploading 2 narinfos13642026/11/06 08:13:41 INFO Completed push id=1 objects=8 duration=5.860748ms1365=== NAME TestClientCADerivations13662026/11/06 08:13:41 INFO Upload complete. (66ms)1367 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations1112751105/001/store/nnb0dy1p4yrghfl45ah8fp3cfqsp3m54-ca-test1368 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1369 Compression: zstd1370 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1371 NarSize: 1441372 References: 1373 Deriver: /build/TestClientCADerivations1112751105/001/store/v2prn9h8z9wl8446whppsmvdl5466mm3-ca-test.drv1374 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1375 client_ca_test.go:185: Checking for realisation files in S3...13762026/11/06 08:13:41 WARN Failed to register uploaded object key=8ryi7cnzcfnd8lky2lcavar9akc8viwq.narinfo error="server returned 404: 404 page not found\n"1377=== NAME TestClientPushesUseOnePush1378 client_pushes_test.go:97: Retrieved narinfo from S3:1379 StorePath: /build/TestClientPushesUseOnePush3875564811/001/store/bkzpqijzhwz8l3396n6q44jsblql8pm1-shared-dep1380 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1381 Compression: zstd1382 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821383 NarSize: 1361384 References: 1385 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n13862026/11/06 08:13:41 WARN Failed to register uploaded object key=vc9fhz90fr3lc9l2d6h9cvaa5lm3vaa4.narinfo error="server returned 404: 404 page not found\n"1387=== NAME TestClientCADerivations13882026/11/06 08:13:41 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1389 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations13902026/11/06 08:13:41 WARN Failed to register uploaded object key=80684b6v09n4pl60frf9abzfjg1filf3.narinfo error="server returned 404: 404 page not found\n"1391 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache13922026/11/06 08:13:41 INFO Received complete push request method=POST path=/api/pushes/1/complete13932026/11/06 08:13:41 WARN Failed to register uploaded object key=j0pd6ga2r49pvqxsfdcjpqf254vyjlvg.narinfo error="server returned 404: 404 page not found\n"13942026/11/06 08:13:41 WARN Failed to register uploaded object key=6amkx82nz7d9zfjb5xshphz80axhgk0b.narinfo error="server returned 404: 404 page not found\n"1395=== NAME TestClientPushesUseOnePush1396 client_pushes_test.go:97: Retrieved narinfo from S3:1397 StorePath: /build/TestClientPushesUseOnePush3875564811/001/store/d4lbzg3k6navc88rwzi8dpjs5yq12zi0-a1398 URL: nar/0zainplprmkhn78hm1zdm5mnfhifza1a3j3k74r3312bp06w8klx.nar.zst1399 Compression: zstd1400 NarHash: sha256:0zainplprmkhn78hm1zdm5mnfhifza1a3j3k74r3312bp06w8klx1401 NarSize: 2161402 References: /build/TestClientPushesUseOnePush3875564811/001/store/bkzpqijzhwz8l3396n6q44jsblql8pm1-shared-dep1403 CA: text:sha256:1fm69j599m985z2s1y3v4bsvcc1kvw18gm2h2gdsbc7gq8n96vzd1404 client_pushes_test.go:97: Retrieved narinfo from S3:1405 StorePath: /build/TestClientPushesUseOnePush3875564811/001/store/328ix3511qf93sdsad8mdj6dqmlrw3id-b1406 URL: nar/0zainplprmkhn78hm1zdm5mnfhifza1a3j3k74r3312bp06w8klx.nar.zst1407 Compression: zstd1408 NarHash: sha256:0zainplprmkhn78hm1zdm5mnfhifza1a3j3k74r3312bp06w8klx1409 NarSize: 2161410 References: /build/TestClientPushesUseOnePush3875564811/001/store/bkzpqijzhwz8l3396n6q44jsblql8pm1-shared-dep1411 CA: text:sha256:1fm69j599m985z2s1y3v4bsvcc1kvw18gm2h2gdsbc7gq8n96vzd14122026/11/06 08:13:41 INFO Completed upload id=1 objects=6 duration=10.057156ms14132026/11/06 08:13:41 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14142026/11/06 08:13:41 INFO Received uploads request method=POST path=/api/pending_closures14152026/11/06 08:13:41 INFO Completed push id=1 objects=6 duration=10.164627ms1416--- PASS: TestClientPushesUseOnePush (0.77s)14172026/11/06 08:13:41 INFO Upload complete. (67ms)1418=== CONT TestPush_RepeatedRootCommitsOnce14192026/11/06 08:13:41 INFO Completed upload id=2 objects=6 duration=2.554049ms14202026/11/06 08:13:41 INFO Upload complete. (81ms)1421=== NAME TestClientSharedPathCommittedMidPush1422 client_integration_test.go:727: Retrieved narinfo from S3:1423 StorePath: /build/TestClientSharedPathCommittedMidPush2923439227/001/store/6amkx82nz7d9zfjb5xshphz80axhgk0b-shared-dep1424 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1425 Compression: zstd1426 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821427 NarSize: 1361428 References: 1429 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1430=== NAME TestClientFallsBackToClosures1431 client_pushes_test.go:112: Retrieved narinfo from S3:1432 StorePath: /build/TestClientFallsBackToClosures1840218096/001/store/80684b6v09n4pl60frf9abzfjg1filf3-shared-dep1433 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1434 Compression: zstd1435 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821436 NarSize: 1361437 References: 1438 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1439=== NAME TestClientSharedPathCommittedMidPush1440 client_integration_test.go:727: Retrieved narinfo from S3:1441 StorePath: /build/TestClientSharedPathCommittedMidPush2923439227/001/store/j0pd6ga2r49pvqxsfdcjpqf254vyjlvg-top1442 URL: nar/1yahzjwr6ivjj03zh1j0l6lz3j3cma3c73g0dzh6mjm0n4h4gqsl.nar.zst1443 Compression: zstd1444 NarHash: sha256:1yahzjwr6ivjj03zh1j0l6lz3j3cma3c73g0dzh6mjm0n4h4gqsl1445 NarSize: 2241446 References: /build/TestClientSharedPathCommittedMidPush2923439227/001/store/6amkx82nz7d9zfjb5xshphz80axhgk0b-shared-dep1447 CA: text:sha256:0v5zs1wbkz6chv78gx6zqbvi7g7wmb1gwy6qhlagr0sg5h3v4fax1448=== NAME TestClientFallsBackToClosures14492026/11/06 08:13:41 INFO Received push request method=POST path=/api/pushes1450 client_pushes_test.go:112: Retrieved narinfo from S3:1451 StorePath: /build/TestClientFallsBackToClosures1840218096/001/store/vc9fhz90fr3lc9l2d6h9cvaa5lm3vaa4-a1452 URL: nar/01adnck3v7l1227m93mwp07n6yf7h0xbzhbyn0yfv8w17lyf3814.nar.zst1453 Compression: zstd1454 NarHash: sha256:01adnck3v7l1227m93mwp07n6yf7h0xbzhbyn0yfv8w17lyf38141455 NarSize: 2161456 References: /build/TestClientFallsBackToClosures1840218096/001/store/80684b6v09n4pl60frf9abzfjg1filf3-shared-dep1457 CA: text:sha256:0ikd3ipy7v7aip7dn4d4p66vvqyxqgkmihp5y4cpc6w5yb1y69nq1458 client_pushes_test.go:112: Retrieved narinfo from S3:1459 StorePath: /build/TestClientFallsBackToClosures1840218096/001/store/8ryi7cnzcfnd8lky2lcavar9akc8viwq-b1460 URL: nar/01adnck3v7l1227m93mwp07n6yf7h0xbzhbyn0yfv8w17lyf3814.nar.zst1461 Compression: zstd1462 NarHash: sha256:01adnck3v7l1227m93mwp07n6yf7h0xbzhbyn0yfv8w17lyf38141463 NarSize: 2161464 References: /build/TestClientFallsBackToClosures1840218096/001/store/80684b6v09n4pl60frf9abzfjg1filf3-shared-dep1465 CA: text:sha256:0ikd3ipy7v7aip7dn4d4p66vvqyxqgkmihp5y4cpc6w5yb1y69nq14662026/11/06 08:13:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14672026/11/06 08:13:41 INFO Uploading j0vsh40i9g731j36n0gj6yjn4l4za0la-test-file.txt (152B)1468--- PASS: TestClientSharedPathCommittedMidPush (0.73s)1469=== CONT TestPush_CompleteCommitsEveryRoot1470--- PASS: TestClientFallsBackToClosures (0.78s)1471=== CONT TestPush_OverlappingRootsStoreOneRowPerKey14722026/11/06 08:13:41 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst14732026/11/06 08:13:41 INFO Received uploads request method=POST path=/api/pending_closures14742026/11/06 08:13:41 WARN Failed to register uploaded object key=j0vsh40i9g731j36n0gj6yjn4l4za0la.ls error="server returned 404: 404 page not found\n"14752026/11/06 08:13:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14762026/11/06 08:13:41 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"14772026/11/06 08:13:41 INFO Signed narinfos id=1 count=114782026/11/06 08:13:41 INFO Uploading 1 narinfos1479--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.50s)1480=== CONT TestReadProxyInvalidPath14812026/11/06 08:13:41 INFO Received complete push request method=POST path=/api/pushes/1/complete14822026/11/06 08:13:41 WARN Failed to register uploaded object key=j0vsh40i9g731j36n0gj6yjn4l4za0la.narinfo error="server returned 404: 404 page not found\n"14832026/11/06 08:13:41 INFO Completed push id=1 objects=3 duration=4.376839ms14842026/11/06 08:13:41 INFO Upload complete. (58ms)14852026/11/06 08:13:41 INFO Received push request method=POST path=/api/pushes14862026/11/06 08:13:41 INFO Received uploads request method=POST path=/api/pending_closures14872026/11/06 08:13:41 INFO Received push request method=POST path=/api/pushes14882026/11/06 08:13:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14892026/11/06 08:13:41 INFO Uploading avviyr4qqpk4qigxhv598zmkjldg7dxk-test-script (136B)14902026/11/06 08:13:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14912026/11/06 08:13:41 INFO Uploading yk9wzzp23xgbn7j4apqfyvz1axf6dz76-unpinned-file.txt (128B)14922026/11/06 08:13:41 WARN Failed to register uploaded object key=avviyr4qqpk4qigxhv598zmkjldg7dxk.ls error="server returned 404: 404 page not found\n"14932026/11/06 08:13:41 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"14942026/11/06 08:13:41 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"14952026/11/06 08:13:41 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign14962026/11/06 08:13:41 WARN Failed to register uploaded object key=log/wh9kr8hl2fcsnq2dl869qhs26gq3ymig-test-script.drv error="server returned 404: 404 page not found\n"14972026/11/06 08:13:41 WARN Failed to register uploaded object key=yk9wzzp23xgbn7j4apqfyvz1axf6dz76.ls error="server returned 404: 404 page not found\n"14982026/11/06 08:13:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14992026/11/06 08:13:41 INFO Signed narinfos id=2 count=115002026/11/06 08:13:41 INFO Uploading 1 narinfos15012026/11/06 08:13:41 INFO Signed narinfos id=1 count=115022026/11/06 08:13:41 INFO Uploading 1 narinfos15032026/11/06 08:13:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15042026/11/06 08:13:41 INFO Received complete push request method=POST path=/api/pushes/2/complete15052026/11/06 08:13:41 WARN Failed to register uploaded object key=yk9wzzp23xgbn7j4apqfyvz1axf6dz76.narinfo error="server returned 404: 404 page not found\n"15062026/11/06 08:13:41 INFO Received complete push request method=POST path=/api/pushes/1/complete15072026/11/06 08:13:41 WARN Failed to register uploaded object key=avviyr4qqpk4qigxhv598zmkjldg7dxk.narinfo error="server returned 404: 404 page not found\n"15082026/11/06 08:13:41 INFO Received uploads request method=POST path=/api/pending_closures15092026/11/06 08:13:41 INFO Received push request method=POST path=/api/pushes15102026/11/06 08:13:41 INFO Completed push id=2 objects=3 duration=19.791784ms15112026/11/06 08:13:41 INFO Completed push id=1 objects=4 duration=19.478234ms15122026/11/06 08:13:41 INFO Upload complete. (67ms)15132026/11/06 08:13:41 INFO Upload complete. (76ms)15142026/11/06 08:13:41 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)15152026/11/06 08:13:41 INFO Uploading m284s78wncd982svqyk7c7f0w8vkz95z-test-file-1.txt (160B)15162026/11/06 08:13:41 INFO Uploading vf1nd600y4f130rplp9kp186zw9dw7w3-test-file-2.txt (160B)15172026/11/06 08:13:41 INFO All 1 paths already cached15182026/11/06 08:13:41 INFO Uploading 6x5l0h1lwr8gsn9m4aqkclg0mzl205dy-test-file-0.txt (160B)1519=== NAME TestClientWithDependencies1520 client_integration_test.go:664: Skipping nix copy test - isolated store (/build/TestClientWithDependencies4084087447/001/store) requires matching store prefix1521=== NAME TestClientIntegration1522 client_integration_test.go:317: Retrieved narinfo from S3:1523 StorePath: /build/TestClientIntegration2763138284/002/store/j0vsh40i9g731j36n0gj6yjn4l4za0la-test-file.txt1524 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1525 Compression: zstd1526 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11527 NarSize: 1521528 References: 1529 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11530 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1531 client_integration_test.go:318: Decompressed .ls content (64 bytes):1532 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1533--- PASS: TestClientWithDependencies (0.68s)1534=== CONT TestReadProxyRangeRequest15352026/11/06 08:13:41 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"15362026/11/06 08:13:41 WARN Failed to register uploaded object key=vf1nd600y4f130rplp9kp186zw9dw7w3.ls error="server returned 404: 404 page not found\n"15372026/11/06 08:13:41 WARN Failed to register uploaded object key=m284s78wncd982svqyk7c7f0w8vkz95z.ls error="server returned 404: 404 page not found\n"15382026/11/06 08:13:41 WARN Failed to register uploaded object key=6x5l0h1lwr8gsn9m4aqkclg0mzl205dy.ls error="server returned 404: 404 page not found\n"15392026/11/06 08:13:41 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"15402026/11/06 08:13:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15412026/11/06 08:13:41 INFO Received uploads request method=POST path=/api/pending_closures15422026/11/06 08:13:41 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"15432026/11/06 08:13:41 INFO Signed narinfos id=1 count=315442026/11/06 08:13:41 INFO Uploading 3 narinfos15452026/11/06 08:13:41 WARN Failed to register uploaded object key=m284s78wncd982svqyk7c7f0w8vkz95z.narinfo error="server returned 404: 404 page not found\n"15462026/11/06 08:13:41 WARN Failed to register uploaded object key=vf1nd600y4f130rplp9kp186zw9dw7w3.narinfo error="server returned 404: 404 page not found\n"15472026/11/06 08:13:41 INFO Received complete push request method=POST path=/api/pushes/1/complete15482026/11/06 08:13:41 WARN Failed to register uploaded object key=6x5l0h1lwr8gsn9m4aqkclg0mzl205dy.narinfo error="server returned 404: 404 page not found\n"15492026/11/06 08:13:41 INFO Received uploads request method=POST path=/api/pending_closures15502026/11/06 08:13:41 INFO Completed push id=1 objects=9 duration=6.720438ms15512026/11/06 08:13:41 INFO Upload complete. (77ms)1552=== NAME TestClientMultipleUploads1553 client_integration_test.go:416: Uploaded 3 paths in 112.213214ms15542026/11/06 08:13:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15552026/11/06 08:13:41 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MDU5MTMyZDMtZmQ2My00Yjk5LTgzZmItMjRkNTljZWI2NjQ5LmRlZDY1YjI3LTFkZmYtNDIwZC1iNDM5LTQzMzExM2ExZTUwNXgxNzkzOTUyODIxNTI3NjA0MDY515562026/11/06 08:13:41 INFO Received push request method=POST path=/api/pushes1557--- PASS: TestClientMultipleUploads (0.69s)1558=== CONT TestReadRedirectKeepsNarinfoProxied15592026/11/06 08:13:41 INFO Starting cleanup of old closures method=DELETE path=/api/closures15602026/11/06 08:13:41 INFO Garbage collection started15612026/11/06 08:13:41 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MDU5MTMyZDMtZmQ2My00Yjk5LTgzZmItMjRkNTljZWI2NjQ5LmRlZDY1YjI3LTFkZmYtNDIwZC1iNDM5LTQzMzExM2ExZTUwNXgxNzkzOTUyODIxNTI3NjA0MDY5 parts=11562--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.53s)1563=== CONT TestReadRedirectNar15642026/11/06 08:13:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15652026/11/06 08:13:41 INFO Signed narinfos id=1 count=115662026/11/06 08:13:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15672026/11/06 08:13:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15682026/11/06 08:13:41 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"15692026/11/06 08:13:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15702026/11/06 08:13:41 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"15712026/11/06 08:13:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15722026/11/06 08:13:41 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=115732026/11/06 08:13:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15742026/11/06 08:13:41 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1575--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.44s)1576=== CONT TestReadProxyDisabled1577=== RUN TestPush_RejectsBadRequests/root_not_in_objects1578=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1579=== RUN TestPush_RejectsBadRequests/no_roots1580=== PAUSE TestPush_RejectsBadRequests/no_roots1581=== RUN TestPush_RejectsBadRequests/no_objects1582=== PAUSE TestPush_RejectsBadRequests/no_objects1583=== RUN TestPush_RejectsBadRequests/bad_root1584=== PAUSE TestPush_RejectsBadRequests/bad_root1585=== CONT TestReadProxyRootRedirectsToIndexHTML15862026/11/06 08:13:41 INFO Aborted multipart uploads count=0 kept=015872026/11/06 08:13:41 WARN Force mode enabled - objects will be deleted immediately without grace period15882026/11/06 08:13:41 INFO Received push request method=POST path=/api/pushes15892026/11/06 08:13:41 INFO Received push request method=POST path=/api/pushes15902026/11/06 08:13:41 INFO Object in database but missing from S3 key=j0vsh40i9g731j36n0gj6yjn4l4za0la.ls15912026/11/06 08:13:41 WARN Found objects in DB but missing from S3, will re-upload count=115922026/11/06 08:13:41 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)1593=== NAME TestClientCADerivations1594 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1595 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1596 error: binary cache 's3://bucket47?endpoint=http://localhost:37517®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations1112751105/001/store'1597 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 115982026/11/06 08:13:41 INFO Received complete push request method=POST path=/api/pushes/2/complete15992026/11/06 08:13:41 WARN Failed to register uploaded object key=j0vsh40i9g731j36n0gj6yjn4l4za0la.ls error="server returned 404: 404 page not found\n"1600--- PASS: TestClientCADerivations (0.94s)1601=== CONT TestReadProxyConditionalGet16022026/11/06 08:13:41 INFO Completed push id=2 objects=3 duration=3.637939ms16032026/11/06 08:13:41 INFO Upload complete. (45ms)1604=== NAME TestClientIntegration16052026/11/06 08:13:41 INFO Received complete push request method=POST path=/api/pushes/1/complete1606 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)16072026/11/06 08:13:41 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=01608 client_integration_test.go:335: Decompressed .ls content (49 bytes):1609 {"version":1,"root":{"type":"regular","size":39}}16102026/11/06 08:13:41 INFO Vacuumed table table=pending_closures16112026/11/06 08:13:41 INFO Received push request method=POST path=/api/pushes16122026/11/06 08:13:41 INFO Completed push id=1 objects=4 duration=7.706997ms16132026/11/06 08:13:41 INFO Received push request method=POST path=/api/pushes16142026/11/06 08:13:41 INFO Vacuumed table table=pending_objects16152026/11/06 08:13:41 INFO Vacuumed table table=multipart_uploads16162026/11/06 08:13:41 INFO Vacuumed table table=closures16172026/11/06 08:13:41 INFO Vacuumed table table=objects16182026/11/06 08:13:41 INFO Received push request method=POST path=/api/pushes16192026/11/06 08:13:41 INFO Received push request method=POST path=/api/pushes16202026-11-06 08:13:41.675 UTC [1958] ERROR: could not obtain lock on row in relation "closures"16212026-11-06 08:13:41.675 UTC [1958] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT16222026-11-06 08:13:41.676 UTC [1958] ERROR: could not obtain lock on row in relation "closures"16232026-11-06 08:13:41.676 UTC [1958] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT16242026-11-06 08:13:41.676 UTC [1958] ERROR: could not obtain lock on row in relation "closures"16252026-11-06 08:13:41.676 UTC [1958] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT16262026-11-06 08:13:41.676 UTC [1958] ERROR: could not obtain lock on row in relation "closures"16272026-11-06 08:13:41.676 UTC [1958] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT16282026-11-06 08:13:41.677 UTC [1958] ERROR: could not obtain lock on row in relation "closures"16292026-11-06 08:13:41.677 UTC [1958] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1630--- PASS: TestPush_RootsAreLockedInByteOrder (0.29s)1631=== CONT TestReadProxyOutlastsServerWriteTimeout16322026/11/06 08:13:41 INFO Received complete push request method=POST path=/api/pushes/1/complete1633--- PASS: TestReadProxyInvalidPath (0.22s)1634=== CONT TestReadProxyHead16352026/11/06 08:13:41 INFO Completed push id=1 objects=4 duration=6.589288ms1636--- PASS: TestPush_RepeatedRootCommitsOnce (0.24s)1637=== CONT TestService_RequireScope_OIDC16382026/11/06 08:13:41 INFO Aborted multipart uploads count=0 kept=016392026/11/06 08:13:41 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45271/oidc16402026/11/06 08:13:41 INFO Received push request method=POST path=/api/pushes16412026/11/06 08:13:41 WARN Force mode enabled - objects will be deleted immediately without grace period16422026/11/06 08:13:41 INFO Received push request method=POST path=/api/pushes16432026/11/06 08:13:41 INFO Received push request method=POST path=/api/pushes16442026/11/06 08:13:41 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=016452026/11/06 08:13:41 INFO Received complete push request method=POST path=/api/pushes/1/complete16462026/11/06 08:13:41 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)16472026/11/06 08:13:41 INFO Vacuumed table table=pending_closures16482026/11/06 08:13:41 INFO Received complete push request method=POST path=/api/pushes/3/complete16492026/11/06 08:13:41 WARN Failed to register uploaded object key=j0vsh40i9g731j36n0gj6yjn4l4za0la.ls error="server returned 404: 404 page not found\n"16502026/11/06 08:13:41 INFO Completed push id=1 objects=6 duration=8.251417ms16512026/11/06 08:13:41 INFO Vacuumed table table=pending_objects1652--- PASS: TestPush_CompleteCommitsEveryRoot (0.28s)1653=== CONT TestCacheStatsHandler16542026/11/06 08:13:41 INFO Completed push id=3 objects=3 duration=2.450599ms16552026/11/06 08:13:41 INFO Upload complete. (59ms)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/06 08:13:41 INFO Vacuumed table table=multipart_uploads16622026/11/06 08:13:41 INFO Vacuumed table table=closures1663--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.28s)1664=== CONT TestCacheConfigHandler1665=== RUN TestCacheConfigHandler/full_config,_no_issuer1666=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1667=== RUN TestCacheConfigHandler/no_cache_url_configured1668=== PAUSE TestCacheConfigHandler/no_cache_url_configured1669=== RUN TestCacheConfigHandler/no_signing_keys1670=== PAUSE TestCacheConfigHandler/no_signing_keys1671=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1672=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1673=== CONT TestService_ReadScope_PublicByDefault16742026/11/06 08:13:41 INFO Vacuumed table table=objects16752026/11/06 08:13:41 INFO Received complete push request method=POST path=/api/pushes/2/complete16762026/11/06 08:13:41 INFO Completed push id=2 objects=4 duration=3.743118ms1677--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.44s)1678=== CONT TestReadProxyNarinfoAlreadyDecompressed1679--- PASS: TestReadProxyRangeRequest (0.23s)1680=== CONT TestReadProxy40416812026/11/06 08:13:41 INFO Starting cleanup of old closures method=DELETE path=/api/closures16822026/11/06 08:13:41 INFO Garbage collection started1683--- PASS: TestReadRedirectKeepsNarinfoProxied (0.23s)1684=== CONT TestReadProxyNarStreaming16852026/11/06 08:13:41 INFO Aborted multipart uploads count=0 kept=01686--- PASS: TestReadProxyDisabled (0.22s)1687=== CONT TestReadProxyContentNegotiation16882026/11/06 08:13:41 WARN Force mode enabled - objects will be deleted immediately without grace period1689--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.25s)1690=== CONT TestService_ReadAuthMiddleware1691--- PASS: TestDeleteClosuresRacingPins (1.73s)1692=== CONT TestService_AuthMiddleware_OIDC16932026/11/06 08:13:41 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=01694--- PASS: TestReadRedirectNar (0.30s)1695=== CONT TestService_AuthMiddleware_MTLSBoundSubjects16962026/11/06 08:13:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16972026/11/06 08:13:41 INFO Vacuumed table table=pending_closures16982026/11/06 08:13:41 INFO Vacuumed table table=pending_objects16992026/11/06 08:13:41 INFO Vacuumed table table=multipart_uploads17002026/11/06 08:13:41 INFO Vacuumed table table=closures17012026/11/06 08:13:41 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34635/oidc17022026/11/06 08:13:41 INFO Vacuumed table table=objects1703--- PASS: TestReadProxyConditionalGet (0.29s)1704=== CONT TestParseSingleRange1705=== RUN TestParseSingleRange/none1706=== PAUSE TestParseSingleRange/none1707=== RUN TestParseSingleRange/unknown_unit1708=== PAUSE TestParseSingleRange/unknown_unit1709=== RUN TestParseSingleRange/multi-range_ignored1710=== PAUSE TestParseSingleRange/multi-range_ignored1711=== RUN TestParseSingleRange/malformed_no_dash1712=== PAUSE TestParseSingleRange/malformed_no_dash1713=== RUN TestParseSingleRange/malformed_both_empty1714=== PAUSE TestParseSingleRange/malformed_both_empty1715=== RUN TestParseSingleRange/malformed_end_before_start1716=== PAUSE TestParseSingleRange/malformed_end_before_start1717=== RUN TestParseSingleRange/closed1718=== PAUSE TestParseSingleRange/closed1719=== RUN TestParseSingleRange/open-ended1720=== PAUSE TestParseSingleRange/open-ended1721=== RUN TestParseSingleRange/end_clamped_to_size1722=== PAUSE TestParseSingleRange/end_clamped_to_size1723=== RUN TestParseSingleRange/suffix1724=== PAUSE TestParseSingleRange/suffix1725=== RUN TestParseSingleRange/suffix_exceeds_size1726=== PAUSE TestParseSingleRange/suffix_exceeds_size1727=== RUN TestParseSingleRange/single_byte1728=== PAUSE TestParseSingleRange/single_byte1729=== RUN TestParseSingleRange/start_past_EOF1730=== PAUSE TestParseSingleRange/start_past_EOF1731=== RUN TestParseSingleRange/start_far_past_EOF1732=== PAUSE TestParseSingleRange/start_far_past_EOF1733=== CONT TestService_AuthMiddleware_MTLSProxyHeader17342026/11/06 08:13:41 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MDU5MTMyZDMtZmQ2My00Yjk5LTgzZmItMjRkNTljZWI2NjQ5LmI3MmZkMjFmLWIxMmEtNGRmZC1iMjMzLWI2MDEwMzI0Y2UzNHgxNzkzOTUyODIxNDk0NTEyNTQw parts=1217352026/11/06 08:13:41 INFO Received uploads request method=POST path=/api/pending_closures1736--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.92s)1737=== CONT TestPresentNotReportedWhileGCDeletesClosure1738=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1739=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1740=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1741=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1742=== CONT TestReadProxyNarinfo1743--- PASS: TestReadProxyHead (0.27s)1744=== CONT TestIsValidCachePath1745=== RUN TestIsValidCachePath/narinfo1746=== PAUSE TestIsValidCachePath/narinfo1747=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1748=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1749=== RUN TestIsValidCachePath/nar_zst1750=== PAUSE TestIsValidCachePath/nar_zst1751=== RUN TestIsValidCachePath/nar_xz1752=== PAUSE TestIsValidCachePath/nar_xz1753=== RUN TestIsValidCachePath/nar_bz21754=== PAUSE TestIsValidCachePath/nar_bz21755=== RUN TestIsValidCachePath/nar_uncompressed1756=== PAUSE TestIsValidCachePath/nar_uncompressed1757=== RUN TestIsValidCachePath/ls1758=== PAUSE TestIsValidCachePath/ls1759=== RUN TestIsValidCachePath/log1760=== PAUSE TestIsValidCachePath/log1761=== RUN TestIsValidCachePath/realisation1762=== PAUSE TestIsValidCachePath/realisation1763=== RUN TestIsValidCachePath/nix-cache-info1764=== PAUSE TestIsValidCachePath/nix-cache-info1765=== RUN TestIsValidCachePath/index.html1766=== PAUSE TestIsValidCachePath/index.html1767=== RUN TestIsValidCachePath/traversal_parent1768=== PAUSE TestIsValidCachePath/traversal_parent1769=== RUN TestIsValidCachePath/traversal_in_middle1770=== PAUSE TestIsValidCachePath/traversal_in_middle1771=== RUN TestIsValidCachePath/invalid_char_e1772=== PAUSE TestIsValidCachePath/invalid_char_e1773=== RUN TestIsValidCachePath/invalid_char_u1774=== PAUSE TestIsValidCachePath/invalid_char_u1775=== RUN TestIsValidCachePath/random_path1776=== PAUSE TestIsValidCachePath/random_path1777=== RUN TestIsValidCachePath/empty1778=== PAUSE TestIsValidCachePath/empty1779=== RUN TestIsValidCachePath/leading_slash1780=== PAUSE TestIsValidCachePath/leading_slash1781=== RUN TestIsValidCachePath/wrong_extension1782=== PAUSE TestIsValidCachePath/wrong_extension1783=== RUN TestIsValidCachePath/short_hash1784=== PAUSE TestIsValidCachePath/short_hash1785=== CONT TestPendingClosureWriteTimeout/empty1786=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline17872026-11-06 08:13:41.969 UTC [1964] ERROR: Push does not exist: id=117882026-11-06 08:13:41.969 UTC [1964] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE17892026-11-06 08:13:41.969 UTC [1964] STATEMENT: SELECT commit_push($1)1790--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (0.54s)1791=== CONT TestPendingClosureWriteTimeout/670k_objects1792=== CONT TestPendingClosureWriteTimeout/400_objects1793=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17942026/11/06 08:13:41 INFO Received uploads request method=POST path=/1795=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17962026/11/06 08:13:41 INFO Received request for more parts method=POST path=/1797=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17982026/11/06 08:13:41 INFO Received complete multipart upload request method=POST path=/1799=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal18002026/11/06 08:13:41 INFO Received uploads request method=POST path=/1801--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1802 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1803 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1804 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1805 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1806=== CONT TestServerTLSConfig/no_client_CA1807=== CONT TestServerTLSConfig/missing_CA_file1808=== CONT TestServerTLSConfig/not_a_PEM_file1809=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1810--- PASS: TestServerTLSConfig (0.09s)1811 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1812 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1813 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)18142026/11/06 08:13:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1815=== RUN TestService_RequireScope_OIDC/builder_may_write1816=== PAUSE TestService_RequireScope_OIDC/builder_may_write1817=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1818=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1819=== RUN TestService_RequireScope_OIDC/ops_may_admin1820=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1821=== RUN TestService_RequireScope_OIDC/ops_may_not_write1822=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1823=== RUN TestService_RequireScope_OIDC/reader_may_not_write1824=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1825=== RUN TestService_RequireScope_OIDC/static_token_may_admin1826=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1827=== RUN TestService_RequireScope_OIDC/static_token_may_write1828=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1829=== RUN TestService_RequireScope_OIDC/reader_may_read1830=== PAUSE TestService_RequireScope_OIDC/reader_may_read1831=== RUN TestService_RequireScope_OIDC/writer_implies_read1832=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1833=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1834=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1835=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1836=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1837=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1838=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1839=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1840=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1841=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1842=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1843=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed18442026/11/06 08:13:42 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MDU5MTMyZDMtZmQ2My00Yjk5LTgzZmItMjRkNTljZWI2NjQ5LmU2MWQ1M2I5LTIxMjUtNGM4NC04N2M3LThjOGVjNzZkODY1ZHgxNzkzOTUyODIxNTQyNDA3MDM0 parts=1218452026/11/06 08:13:42 INFO Received uploads request method=POST path=/api/pending_closures18462026/11/06 08:13:42 INFO Received uploads request method=POST path=/api/pending_closures1847--- PASS: TestCacheStatsHandler (0.28s)1848=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1849--- PASS: TestService_ReadScope_PublicByDefault (0.28s)1850=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1851--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.33s)1852=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost18532026/11/06 08:13:42 INFO lead: released remote=192.0.2.1:12341854--- PASS: TestLeadEndsOnShutdown (1.49s)1855=== CONT TestIsValidUploadKey/narinfo1856=== CONT TestIsValidUploadKey/unknown_type1857=== CONT TestIsValidUploadKey/empty_key1858=== CONT TestIsValidUploadKey/absolute1859=== CONT TestIsValidUploadKey/traversal_nar1860=== CONT TestIsValidUploadKey/traversal1861=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1862=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1863=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1864=== CONT TestIsValidUploadKey/index.html1865=== CONT TestIsValidUploadKey/nix-cache-info1866=== CONT TestIsValidUploadKey/realisation_plus_in_output1867=== CONT TestIsValidUploadKey/realisation1868=== CONT TestIsValidUploadKey/build_log_equals1869=== CONT TestIsValidUploadKey/build_log_question_mark1870=== CONT TestIsValidUploadKey/build_log_plus_in_name1871=== CONT TestIsValidUploadKey/build_log_home-manager_file1872=== CONT TestIsValidUploadKey/build_log1873=== CONT TestIsValidUploadKey/listing1874=== CONT TestIsValidUploadKey/nar_plain1875=== CONT TestIsValidUploadKey/nar_xz1876=== CONT TestIsValidUploadKey/nar_zst1877--- PASS: TestIsValidUploadKey (0.10s)1878 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1879 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1880 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1881 --- PASS: TestIsValidUploadKey/absolute (0.00s)1882 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1883 --- PASS: TestIsValidUploadKey/traversal (0.00s)1884 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1885 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1886 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1887 --- PASS: TestIsValidUploadKey/index.html (0.00s)1888 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1889 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1890 --- PASS: TestIsValidUploadKey/realisation (0.00s)1891 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1892 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1893 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1894 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1895 --- PASS: TestIsValidUploadKey/build_log (0.00s)1896 --- PASS: TestIsValidUploadKey/listing (0.00s)1897 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1898 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1899 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1900=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19012026/11/06 08:13:42 INFO Received uploads request method=POST path=/1902--- PASS: TestReadProxy404 (0.35s)1903=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart19042026/11/06 08:13:42 INFO Received complete multipart upload request method=POST path=/1905--- PASS: TestReadProxyNarStreaming (0.33s)1906=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19072026/11/06 08:13:42 INFO Received request for more parts method=POST path=/1908--- PASS: TestService_ReadAuthMiddleware (0.34s)1909=== CONT TestGCEndsOnShutdown/before_the_run1910=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark19112026/11/06 08:13:42 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19122026/11/06 08:13:42 WARN mTLS auth: bound subjects configured but subject DN unavailable19132026/11/06 08:13:42 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1914--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.32s)1915=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1916--- PASS: TestReadProxyContentNegotiation (0.39s)1917=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1918=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1919=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1920=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1921=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1922=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1923=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1924=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1925=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1926=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1927=== CONT TestResolveDBConnectionString/flag_wins1928=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1929=== CONT TestResolveDBConnectionString/nothing_configured1930=== CONT TestResolveDBConnectionString/missing_file_is_an_error1931=== CONT TestResolveDBConnectionString/file_when_flag_empty1932=== CONT TestClientErrorHandling/InvalidStorePath1933--- PASS: TestResolveDBConnectionString (0.00s)1934 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1935 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1936 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1937 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1938 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1939--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.36s)1940=== CONT TestClientErrorHandling/ServerNotAvailable19412026/11/06 08:13:42 INFO Received uploads request method=POST path=/api/pending_closures19422026/11/06 08:13:42 INFO Received uploads request method=POST path=/api/pending_closures19432026/11/06 08:13:42 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/present19442026/11/06 08:13:42 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>19452026/11/06 08:13:42 INFO Received uploads request method=POST path=/api/pending_closures1946--- PASS: TestReadProxyNarinfo (0.44s)1947=== CONT TestClientErrorHandling/InvalidAuthToken19482026/11/06 08:13:42 INFO lead: released remote=192.0.2.1:123419492026/11/06 08:13:42 INFO Received uploads request method=POST path=/api/pending_closures19502026/11/06 08:13:42 INFO Received uploads request method=POST path=/api/pending_closures19512026/11/06 08:13:42 INFO lead: acquired remote=192.0.2.1:123419522026/11/06 08:13:42 INFO Received uploads request method=POST path=/api/pending_closures19532026/11/06 08:13:42 WARN Request failed, retrying attempt=2 backoff=187.511855ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1954=== CONT TestProxyWriteTimeout/narinfo1955=== CONT TestProxyWriteTimeout/unknown_size1956=== CONT TestProxyWriteTimeout/10_GiB_nar1957=== CONT TestProxyWriteTimeout/1_GiB_nar1958--- PASS: TestProxyWriteTimeout (0.00s)1959 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1960 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1961 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1962 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1963=== CONT TestPush_RejectsBadRequests/root_not_in_objects19642026/11/06 08:13:42 INFO Received push request method=POST path=/api/pushes1965=== CONT TestPush_RejectsBadRequests/no_objects19662026/11/06 08:13:42 INFO Received push request method=POST path=/api/pushes1967=== CONT TestPush_RejectsBadRequests/bad_root19682026/11/06 08:13:42 INFO Received push request method=POST path=/api/pushes1969=== CONT TestPush_RejectsBadRequests/no_roots19702026/11/06 08:13:42 INFO Received push request method=POST path=/api/pushes1971=== CONT TestCacheConfigHandler/full_config,_no_issuer1972--- PASS: TestPush_RejectsBadRequests (0.33s)1973 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1974 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1975 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1976 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1977=== CONT TestCacheConfigHandler/no_signing_keys1978=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1979=== CONT TestCacheConfigHandler/no_cache_url_configured1980--- PASS: TestCacheConfigHandler (0.00s)1981 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1982 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1983 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1984 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1985=== CONT TestParseSingleRange/none1986=== CONT TestParseSingleRange/open-ended1987=== CONT TestParseSingleRange/start_far_past_EOF1988=== CONT TestParseSingleRange/start_past_EOF1989=== CONT TestParseSingleRange/single_byte1990=== CONT TestParseSingleRange/suffix_exceeds_size1991=== CONT TestParseSingleRange/suffix1992=== CONT TestParseSingleRange/end_clamped_to_size1993=== CONT TestParseSingleRange/malformed_both_empty1994=== CONT TestParseSingleRange/closed1995=== CONT TestParseSingleRange/multi-range_ignored1996=== CONT TestParseSingleRange/malformed_end_before_start1997=== CONT TestParseSingleRange/malformed_no_dash1998=== CONT TestParseSingleRange/unknown_unit1999--- PASS: TestParseSingleRange (0.00s)2000 --- PASS: TestParseSingleRange/none (0.00s)2001 --- PASS: TestParseSingleRange/open-ended (0.00s)2002 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2003 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2004 --- PASS: TestParseSingleRange/single_byte (0.00s)2005 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2006 --- PASS: TestParseSingleRange/suffix (0.00s)2007 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2008 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2009 --- PASS: TestParseSingleRange/closed (0.00s)2010 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2011 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2012 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2013 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2014=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale20152026/11/06 08:13:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20162026/11/06 08:13:42 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MDU5MTMyZDMtZmQ2My00Yjk5LTgzZmItMjRkNTljZWI2NjQ5LjQ1ODE2YmZmLWFjYjAtNGVhOC1hM2MzLWQyNDk1YTU4NDI2NHgxNzkzOTUyODIyMDE3NzAzNzU4 error="Get \"http://127.0.0.1:1/bucket61/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"20172026/11/06 08:13:42 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MDU5MTMyZDMtZmQ2My00Yjk5LTgzZmItMjRkNTljZWI2NjQ5LjVkZGMwMjEzLTJiZDYtNDhlOS1hODcxLWNkZGUyNzBhMzQ3N3gxNzkzOTUyODIyMDEwNTcxNzkw parts=1220182026/11/06 08:13:42 INFO Received cleanup request method=DELETE path=/api/pending_closures20192026/11/06 08:13:42 INFO Aborted multipart uploads count=1 kept=02020--- PASS: TestRedundantMultipartUpload (1.43s)2021=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh20222026/11/06 08:13:42 INFO Aborted multipart uploads count=0 kept=020232026/11/06 08:13:42 WARN Force mode enabled - objects will be deleted immediately without grace period2024=== CONT TestIsValidCachePath/narinfo2025=== CONT TestIsValidCachePath/index.html2026=== CONT TestIsValidCachePath/nix-cache-info2027=== CONT TestIsValidCachePath/realisation2028=== CONT TestIsValidCachePath/log2029=== CONT TestIsValidCachePath/ls2030=== CONT TestIsValidCachePath/nar_uncompressed2031=== CONT TestIsValidCachePath/nar_bz22032=== CONT TestIsValidCachePath/nar_xz2033=== CONT TestIsValidCachePath/nar_zst2034=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2035=== CONT TestIsValidCachePath/traversal_parent2036=== CONT TestIsValidCachePath/empty2037=== CONT TestIsValidCachePath/random_path2038=== CONT TestIsValidCachePath/invalid_char_u2039=== CONT TestIsValidCachePath/invalid_char_e2040=== CONT TestIsValidCachePath/traversal_in_middle2041=== CONT TestIsValidCachePath/leading_slash2042=== CONT TestIsValidCachePath/wrong_extension2043=== CONT TestIsValidCachePath/short_hash2044=== CONT TestService_RequireScope_OIDC/builder_may_write2045--- PASS: TestIsValidCachePath (0.00s)2046 --- PASS: TestIsValidCachePath/narinfo (0.00s)2047 --- PASS: TestIsValidCachePath/index.html (0.00s)2048 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2049 --- PASS: TestIsValidCachePath/realisation (0.00s)2050 --- PASS: TestIsValidCachePath/log (0.00s)2051 --- PASS: TestIsValidCachePath/ls (0.00s)2052 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2053 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2054 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2055 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2056 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2057 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2058 --- PASS: TestIsValidCachePath/empty (0.00s)2059 --- PASS: TestIsValidCachePath/random_path (0.00s)2060 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2061 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2062 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2063 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2064 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2065 --- PASS: TestIsValidCachePath/short_hash (0.00s)2066=== CONT TestService_RequireScope_OIDC/reader_may_read2067=== CONT TestService_RequireScope_OIDC/static_token_may_write2068=== CONT TestService_RequireScope_OIDC/static_token_may_admin2069=== CONT TestService_RequireScope_OIDC/reader_may_not_write2070=== CONT TestService_RequireScope_OIDC/ops_may_not_write2071=== CONT TestService_RequireScope_OIDC/ops_may_admin2072=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2073=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20742026/11/06 08:13:42 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]2075=== CONT TestService_RequireScope_OIDC/writer_implies_read2076=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2077=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2078=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2079=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2080=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token20812026/11/06 08:13:42 INFO Aborted multipart uploads count=0 kept=02082--- PASS: TestService_RequireScope_OIDC (0.31s)2083 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2084 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2085 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2086 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2087 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2088 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2089 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2090 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2091 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2092 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2093 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2094 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2095 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2096 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2097=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20982026/11/06 08:13:42 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]2099=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2100=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected21012026/11/06 08:13:42 WARN Force mode enabled - objects will be deleted immediately without grace period21022026/11/06 08:13:42 WARN Authentication failed token_preview=eyJhbGciOi...hKi-Aw_sXQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2103--- PASS: TestService_AuthMiddleware_OIDC (0.39s)2104 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2105 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2106 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2107 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)21082026/11/06 08:13:42 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:37517/bucket99/?delete=\": context canceled"2109--- PASS: TestGCEndsOnShutdown (0.00s)2110 --- PASS: TestGCEndsOnShutdown/before_the_run (0.31s)2111 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.35s)2112 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.35s)21132026/11/06 08:13:42 INFO Received uploads request method=POST path=/api/pending_closures21142026/11/06 08:13:42 INFO Aborted multipart uploads count=0 kept=021152026/11/06 08:13:42 WARN Force mode enabled - objects will be deleted immediately without grace period21162026/11/06 08:13:42 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=021172026/11/06 08:13:42 INFO Vacuumed table table=pending_closures2118=== NAME TestOrphanedObjectsGCStressTest2119 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains21202026/11/06 08:13:42 INFO Vacuumed table table=pending_objects21212026/11/06 08:13:42 INFO Vacuumed table table=multipart_uploads21222026/11/06 08:13:42 INFO Vacuumed table table=closures21232026/11/06 08:13:42 INFO Vacuumed table table=objects21242026/11/06 08:13:42 INFO Received uploads request method=POST path=/api/pending_closures21252026/11/06 08:13:42 INFO Aborted multipart uploads count=0 kept=021262026/11/06 08:13:42 WARN Force mode enabled - objects will be deleted immediately without grace period2127 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion21282026/11/06 08:13:42 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/06 08:13:42 INFO Vacuumed table table=pending_closures21302026/11/06 08:13:42 INFO Vacuumed table table=pending_objects21312026/11/06 08:13:42 INFO Vacuumed table table=multipart_uploads21322026/11/06 08:13:42 INFO Vacuumed table table=closures21332026/11/06 08:13:42 INFO Vacuumed table table=objects21342026/11/06 08:13:42 WARN Request failed, retrying attempt=3 backoff=417.813671ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2135--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2136 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.40s)2137 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.45s)21382026/11/06 08:13:42 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21392026/11/06 08:13:42 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21402026/11/06 08:13:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2141--- PASS: TestUploadHandlersRejectOversizedBody (0.18s)2142 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.07s)2143 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.07s)2144 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.64s)21452026/11/06 08:13:42 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=MDU5MTMyZDMtZmQ2My00Yjk5LTgzZmItMjRkNTljZWI2NjQ5LjgyYmZkMWRhLWY5N2ItNGQwMS1iYTRmLTgzNjhiMzM3ZmQzNngxNzkzOTUyODIyMzM2MDIzMTQz parts=1021462026/11/06 08:13:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21472026/11/06 08:13:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21482026/11/06 08:13:42 INFO Completed upload id=1 objects=3 duration=3.183259ms21492026/11/06 08:13:42 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=MDU5MTMyZDMtZmQ2My00Yjk5LTgzZmItMjRkNTljZWI2NjQ5LmM0Y2EwMjU2LTczODctNGE4NS04YzBlLTBjZDY5MjMyNmRkZngxNzkzOTUyODIyMzYzMzAwNzA0 parts=1021502026/11/06 08:13:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21512026/11/06 08:13:42 INFO Completed upload id=1 objects=3 duration=3.009739ms21522026/11/06 08:13:42 INFO Received uploads request method=POST path=/api/pending_closures21532026/11/06 08:13:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21542026/11/06 08:13:42 INFO Received uploads request method=POST path=/api/pending_closures21552026/11/06 08:13:42 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21562026/11/06 08:13:42 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21572026/11/06 08:13:42 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=MDU5MTMyZDMtZmQ2My00Yjk5LTgzZmItMjRkNTljZWI2NjQ5Ljg4ZmM1MTUwLWNmZmYtNGYzMi05YjRmLWE0ZDc5MWU5Nzc1ZXgxNzkzOTUyODIyMzg4ODc0Mjg2 parts=1021582026/11/06 08:13:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21592026/11/06 08:13:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21602026/11/06 08:13:42 INFO Completed upload id=1 objects=3 duration=3.014659ms21612026/11/06 08:13:42 INFO Received uploads request method=POST path=/api/pending_closures21622026/11/06 08:13:42 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=MDU5MTMyZDMtZmQ2My00Yjk5LTgzZmItMjRkNTljZWI2NjQ5LjllMGFiNjhhLTFhMDAtNDRlMy1iODU4LThhYmQ0MzlmNWEyNXgxNzkzOTUyODIyNDE2ODY0NDE2 parts=1021632026/11/06 08:13:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21642026/11/06 08:13:42 INFO Completed upload id=1 objects=3 duration=3.035919ms21652026/11/06 08:13:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21662026/11/06 08:13:42 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=MDU5MTMyZDMtZmQ2My00Yjk5LTgzZmItMjRkNTljZWI2NjQ5LjY3OGFmNzVmLTcxNDAtNDVkYS05ZDdmLTNmY2Y5Zjk2OGUxZngxNzkzOTUyODIyNDQzODg3NTU4 parts=1021672026/11/06 08:13:42 INFO Received uploads request method=POST path=/api/pending_closures21682026/11/06 08:13:42 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst21692026/11/06 08:13:42 WARN Found objects in DB but missing from S3, will re-upload count=121702026/11/06 08:13:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21712026/11/06 08:13:42 INFO Completed upload id=1 objects=3 duration=2.831829ms21722026/11/06 08:13:42 INFO Received uploads request method=POST path=/api/pending_closures21732026/11/06 08:13:43 WARN Request failed, retrying attempt=4 backoff=805.709765ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2174--- PASS: TestPendingClosureWriteTimeout (0.00s)2175 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2176 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2177 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2178 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.14s)2179--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2180 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.68s)2181 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.67s)21822026/11/06 08:13:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21832026/11/06 08:13:43 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=MDU5MTMyZDMtZmQ2My00Yjk5LTgzZmItMjRkNTljZWI2NjQ5LjY1ZjA0MmVhLWFjYTItNDYwYS1hNjM4LTM5Nzk2MjY5YzU2OHgxNzkzOTUyODIyNzkxMzcxNzgz parts=1021842026/11/06 08:13:43 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete21852026/11/06 08:13:43 INFO Completed upload id=2 objects=3 duration=1.39129ms21862026/11/06 08:13:43 INFO Received uploads request method=POST path=/api/pending_closures21872026/11/06 08:13:43 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst21882026/11/06 08:13:43 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo21892026/11/06 08:13:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21902026/11/06 08:13:43 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=MDU5MTMyZDMtZmQ2My00Yjk5LTgzZmItMjRkNTljZWI2NjQ5Ljg4ODIzMzRiLTYyYjEtNGZhZi1iNDgwLTM0ZTA4Y2Y5Y2Q5ZXgxNzkzOTUyODIyODk0MzMwNzg5 parts=1021912026/11/06 08:13:43 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete21922026/11/06 08:13:43 INFO Completed upload id=2 objects=3 duration=1.33488ms21932026/11/06 08:13:43 INFO Received uploads request method=POST path=/api/pending_closures21942026/11/06 08:13:43 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst21952026/11/06 08:13:43 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2196--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.10s)2197 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (0.83s)2198 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (0.80s)2199 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (0.86s)2200 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (1.28s)2201 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (1.31s)22022026/11/06 08:13:43 INFO lead: released remote=192.0.2.1:12342203--- PASS: TestLeadElectsOneAndHandsOver (2.83s)22042026/11/06 08:13:43 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=022052026/11/06 08:13:43 INFO Received create pin request method=POST path=/api/pins/myapp22062026/11/06 08:13:43 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC1956704854/001/store/pg3r70ggaacdxazyqsn4vvpaxs5dxmlz-pinned-file.txt narinfo_key=pg3r70ggaacdxazyqsn4vvpaxs5dxmlz.narinfo22072026/11/06 08:13:43 INFO Starting cleanup of old closures method=DELETE path=/api/closures22082026/11/06 08:13:43 INFO Garbage collection started22092026/11/06 08:13:43 INFO Aborted multipart uploads count=0 kept=022102026/11/06 08:13:43 WARN Force mode enabled - objects will be deleted immediately without grace period22112026/11/06 08:13:43 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=022122026/11/06 08:13:43 INFO Vacuumed table table=pending_closures22132026/11/06 08:13:43 INFO Vacuumed table table=pending_objects22142026/11/06 08:13:43 INFO Vacuumed table table=multipart_uploads22152026/11/06 08:13:43 INFO Vacuumed table table=closures22162026/11/06 08:13:43 INFO Vacuumed table table=objects22172026/11/06 08:13:43 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02218=== NAME TestClientIntegration2219 client_integration_test.go:370: Objects in database after GC:2220 client_integration_test.go:370: Successfully deleted all objects with GC --force2221--- PASS: TestClientIntegration (2.89s)2222=== NAME TestOrphanedObjectsGCStressTest2223 orphaned_objects_gc_test.go:503: Stress test completed successfully:2224 orphaned_objects_gc_test.go:504: - Active objects preserved: 202225 orphaned_objects_gc_test.go:505: - Objects deleted: 2102226 orphaned_objects_gc_test.go:506: - Total GC'd: 2102227--- PASS: TestOrphanedObjectsGCStressTest (4.25s)22282026/11/06 08:13:43 WARN Request failed, retrying attempt=5 backoff=1.522384513s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22292026/11/06 08:13:45 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-config22302026/11/06 08:13:45 WARN Request failed, retrying attempt=2 backoff=197.376507ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2231=== NAME TestPinProtectsFromGC2232 client_integration_test.go:887: Pin successfully protected closure from garbage collection2233--- PASS: TestPinProtectsFromGC (4.88s)22342026/11/06 08:13:45 WARN Request failed, retrying attempt=3 backoff=439.750248ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22352026/11/06 08:13:45 WARN Rate limiter enabled after throttle name=s3-test rate=522362026/11/06 08:13:45 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2237=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2238 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102239 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002240--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.88s)2241--- PASS: TestConnectWaitsForAPeerMigration (5.21s)2242--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.46s)22432026/11/06 08:13:46 WARN Request failed, retrying attempt=4 backoff=784.86232ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22442026/11/06 08:13:46 INFO Aborted multipart uploads count=1 kept=022452026/11/06 08:13:46 INFO Received cleanup request method=DELETE path=/api/pending_closures22462026/11/06 08:13:46 INFO Aborted multipart uploads count=1 kept=02247--- PASS: TestPendingCleanupUsesOneCutoff (6.87s)22482026/11/06 08:13:46 WARN Request failed, retrying attempt=5 backoff=1.446372225s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22492026/11/06 08:13:48 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"22502026/11/06 08:13:48 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22512026/11/06 08:13:48 WARN Request failed, retrying attempt=2 backoff=181.543551ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22522026/11/06 08:13:48 WARN Request failed, retrying attempt=3 backoff=399.863268ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22532026/11/06 08:13:49 WARN Request failed, retrying attempt=4 backoff=802.660425ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22542026/11/06 08:13:49 WARN Request failed, retrying attempt=5 backoff=1.586714189s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22552026/11/06 08:13:51 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22562026/11/06 08:13:51 WARN Request failed, retrying attempt=2 backoff=219.651723ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22572026/11/06 08:13:51 WARN Request failed, retrying attempt=3 backoff=395.374029ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22582026/11/06 08:13:52 WARN Request failed, retrying attempt=4 backoff=809.275485ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22592026/11/06 08:13:53 WARN Request failed, retrying attempt=5 backoff=1.471898591s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2260--- PASS: TestClientErrorHandling (0.00s)2261 --- PASS: TestClientErrorHandling/InvalidStorePath (0.41s)2262 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.37s)2263 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.22s)2264PASS2265{"timestamp":"2026-11-06T08:13:54.496379311Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56032","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(397)"}2266{"timestamp":"2026-11-06T08:13:54.496642081Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:55126","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(401)"}22672026-11-06 08:13:54.852 UTC [131] LOG: received smart shutdown request22682026-11-06 08:13:54.857 UTC [131] LOG: background worker "logical replication launcher" (PID 141) exited with exit code 122692026-11-06 08:13:54.870 UTC [136] LOG: shutting down22702026-11-06 08:13:54.871 UTC [136] LOG: checkpoint starting: shutdown immediate22712026-11-06 08:13:56.758 UTC [136] LOG: checkpoint complete: wrote 11328 buffers (69.1%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.248 s, sync=1.578 s, total=1.888 s; sync files=35725, longest=0.002 s, average=0.001 s; distance=516895 kB, estimate=516895 kB; lsn=0/2102DC38, redo lsn=0/2102DC3822722026-11-06 08:13:56.840 UTC [131] LOG: database system is shut down2273Running OIDC tests...2274=== RUN TestAudienceForIssuer2275=== PAUSE TestAudienceForIssuer2276=== RUN TestGlobMatch2277=== PAUSE TestGlobMatch2278=== RUN TestValidateToken_ValidToken2279=== PAUSE TestValidateToken_ValidToken2280=== RUN TestValidateToken_WrongAudience2281=== PAUSE TestValidateToken_WrongAudience2282=== RUN TestValidateToken_Expired2283=== PAUSE TestValidateToken_Expired2284=== RUN TestValidateToken_BoundClaimsMismatch2285=== PAUSE TestValidateToken_BoundClaimsMismatch2286=== RUN TestValidateToken_BoundSubjectMismatch2287=== PAUSE TestValidateToken_BoundSubjectMismatch2288=== RUN TestValidateToken_MultipleProviders2289=== PAUSE TestValidateToken_MultipleProviders2290=== RUN TestValidateToken_NoMatchingProvider2291=== PAUSE TestValidateToken_NoMatchingProvider2292=== RUN TestValidateToken_KubernetesServiceAccount2293=== PAUSE TestValidateToken_KubernetesServiceAccount2294=== RUN TestNewValidator_KubernetesRequiresCA2295=== PAUSE TestNewValidator_KubernetesRequiresCA2296=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2297=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2298=== RUN TestPins_ReservedForMatchingRule2299=== PAUSE TestPins_ReservedForMatchingRule2300=== RUN TestPins_TopLevelShorthand2301=== PAUSE TestPins_TopLevelShorthand2302=== RUN TestPins_ConfigValidation2303=== PAUSE TestPins_ConfigValidation2304=== RUN TestScopes_LegacyProviderDefaultsToWrite2305=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2306=== RUN TestScopes_Rules2307=== PAUSE TestScopes_Rules2308=== RUN TestScopes_ConfigValidation2309=== PAUSE TestScopes_ConfigValidation2310=== CONT TestAudienceForIssuer2311=== CONT TestPins_ConfigValidation2312--- PASS: TestAudienceForIssuer (0.00s)2313=== CONT TestValidateToken_Expired2314=== CONT TestValidateToken_WrongAudience2315=== CONT TestValidateToken_ValidToken2316=== CONT TestValidateToken_KubernetesServiceAccount2317=== CONT TestPins_TopLevelShorthand2318=== CONT TestGlobMatch2319=== CONT TestPins_ReservedForMatchingRule2320=== CONT TestValidateToken_MultipleProviders2321=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2322=== CONT TestValidateToken_NoMatchingProvider2323=== CONT TestNewValidator_KubernetesRequiresCA2324=== CONT TestScopes_Rules2325=== CONT TestValidateToken_BoundSubjectMismatch2326=== CONT TestScopes_ConfigValidation2327=== CONT TestScopes_LegacyProviderDefaultsToWrite2328=== CONT TestValidateToken_BoundClaimsMismatch2329--- PASS: TestPins_ConfigValidation (0.00s)2330=== RUN TestGlobMatch/foo_foo2331=== PAUSE TestGlobMatch/foo_foo2332=== RUN TestGlobMatch/foo_bar2333=== PAUSE TestGlobMatch/foo_bar2334=== RUN TestGlobMatch/*_2335=== PAUSE TestGlobMatch/*_2336=== RUN TestGlobMatch/*_anything2337=== PAUSE TestGlobMatch/*_anything2338=== RUN TestGlobMatch/foo*_foo2339=== PAUSE TestGlobMatch/foo*_foo2340=== RUN TestGlobMatch/foo*_foobar2341=== PAUSE TestGlobMatch/foo*_foobar2342=== RUN TestGlobMatch/foo*_bar2343=== PAUSE TestGlobMatch/foo*_bar2344=== RUN TestGlobMatch/*bar_bar2345=== PAUSE TestGlobMatch/*bar_bar2346=== RUN TestGlobMatch/*bar_foobar2347=== PAUSE TestGlobMatch/*bar_foobar2348=== RUN TestGlobMatch/*bar_foo2349=== PAUSE TestGlobMatch/*bar_foo2350=== RUN TestGlobMatch/foo*bar_foobar2351=== PAUSE TestGlobMatch/foo*bar_foobar2352=== RUN TestGlobMatch/foo*bar_foo123bar2353=== PAUSE TestGlobMatch/foo*bar_foo123bar2354=== RUN TestGlobMatch/foo*bar_foobarbaz2355=== PAUSE TestGlobMatch/foo*bar_foobarbaz2356=== RUN TestGlobMatch/*/*_foo/bar2357=== PAUSE TestGlobMatch/*/*_foo/bar2358=== RUN TestGlobMatch/*/*_foo2359=== PAUSE TestGlobMatch/*/*_foo2360=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2361=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2362=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02363=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02364=== RUN TestGlobMatch/refs/*/main_refs/heads/main2365--- PASS: TestScopes_ConfigValidation (0.00s)2366=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2367=== RUN TestGlobMatch/fo?_foo2368=== PAUSE TestGlobMatch/fo?_foo2369=== RUN TestGlobMatch/fo?_fo2370=== PAUSE TestGlobMatch/fo?_fo2371=== RUN TestGlobMatch/fo?_fooo2372=== PAUSE TestGlobMatch/fo?_fooo2373=== RUN TestGlobMatch/?oo_foo2374=== PAUSE TestGlobMatch/?oo_foo2375=== RUN TestGlobMatch/?oo_boo2376=== PAUSE TestGlobMatch/?oo_boo2377=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2378=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2379=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2380=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2381=== CONT TestGlobMatch/foo_foo2382=== CONT TestGlobMatch/*bar_bar2383=== CONT TestGlobMatch/*_anything2384=== CONT TestGlobMatch/*_2385=== CONT TestGlobMatch/foo_bar2386=== CONT TestGlobMatch/foo*_bar2387=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2388=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2389=== CONT TestGlobMatch/?oo_foo2390=== CONT TestGlobMatch/foo*bar_foobar2391=== CONT TestGlobMatch/foo*bar_foobarbaz2392=== CONT TestGlobMatch/foo*bar_foo123bar2393=== CONT TestGlobMatch/*bar_foo2394=== CONT TestGlobMatch/fo?_fooo2395=== CONT TestGlobMatch/*bar_foobar2396=== CONT TestGlobMatch/fo?_fo2397=== CONT TestGlobMatch/fo?_foo2398=== CONT TestGlobMatch/refs/*/main_refs/heads/main2399=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02400=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2401=== CONT TestGlobMatch/*/*_foo2402=== CONT TestGlobMatch/foo*_foobar2403=== CONT TestGlobMatch/foo*_foo2404=== CONT TestGlobMatch/*/*_foo/bar2405=== CONT TestGlobMatch/?oo_boo2406--- PASS: TestGlobMatch (0.01s)2407 --- PASS: TestGlobMatch/foo_foo (0.00s)2408 --- PASS: TestGlobMatch/*bar_bar (0.00s)2409 --- PASS: TestGlobMatch/*_anything (0.00s)2410 --- PASS: TestGlobMatch/*_ (0.00s)2411 --- PASS: TestGlobMatch/foo_bar (0.00s)2412 --- PASS: TestGlobMatch/foo*_bar (0.00s)2413 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2414 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2415 --- PASS: TestGlobMatch/?oo_foo (0.00s)2416 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2417 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2418 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2419 --- PASS: TestGlobMatch/*bar_foo (0.00s)2420 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2421 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2422 --- PASS: TestGlobMatch/fo?_fo (0.00s)2423 --- PASS: TestGlobMatch/fo?_foo (0.00s)2424 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2425 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2426 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2427 --- PASS: TestGlobMatch/*/*_foo (0.00s)2428 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2429 --- PASS: TestGlobMatch/foo*_foo (0.00s)2430 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2431 --- PASS: TestGlobMatch/?oo_boo (0.00s)24322026/11/06 08:13:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37199/oidc24332026/11/06 08:13:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39359/oidc24342026/11/06 08:13:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34143/oidc2435--- PASS: TestValidateToken_BoundSubjectMismatch (0.02s)2436--- PASS: TestValidateToken_WrongAudience (0.02s)2437--- PASS: TestScopes_Rules (0.02s)24382026/11/06 08:13:59 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12324392026/11/06 08:13:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44993/oidc2440--- PASS: TestValidateToken_Expired (0.06s)24412026/11/06 08:13:59 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:418972442--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.06s)2443--- PASS: TestValidateToken_KubernetesServiceAccount (0.06s)24442026/11/06 08:13:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33067/oidc2445--- PASS: TestValidateToken_ValidToken (0.07s)24462026/11/06 08:13:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43891/oidc24472026/11/06 08:13:59 http: TLS handshake error from 127.0.0.1:39716: remote error: tls: bad certificate2448--- PASS: TestNewValidator_KubernetesRequiresCA (0.09s)2449--- PASS: TestPins_TopLevelShorthand (0.09s)24502026/11/06 08:13:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40029/oidc2451--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.13s)24522026/11/06 08:13:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37843/oidc2453--- PASS: TestValidateToken_BoundClaimsMismatch (0.14s)24542026/11/06 08:13:59 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:35149/oidc2455--- PASS: TestValidateToken_NoMatchingProvider (0.15s)24562026/11/06 08:13:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40451/oidc2457--- PASS: TestPins_ReservedForMatchingRule (0.17s)24582026/11/06 08:13:59 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:32961/oidc24592026/11/06 08:13:59 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:38527/oidc2460--- PASS: TestValidateToken_MultipleProviders (0.19s)2461PASS2462Running hook tests...2463=== RUN TestSendPathsEmpty2464=== PAUSE TestSendPathsEmpty2465=== RUN TestQueueEnqueueAndFetch2466=== PAUSE TestQueueEnqueueAndFetch2467=== RUN TestQueueDeduplication2468=== PAUSE TestQueueDeduplication2469=== RUN TestQueueRemove2470=== PAUSE TestQueueRemove2471=== RUN TestQueueFetchBatchLimit2472=== PAUSE TestQueueFetchBatchLimit2473=== RUN TestQueueRetryMovesToBack2474=== PAUSE TestQueueRetryMovesToBack2475=== RUN TestQueueFetchRemoveLifecycle2476=== PAUSE TestQueueFetchRemoveLifecycle2477=== RUN TestQueueConcurrentWriters2478=== PAUSE TestQueueConcurrentWriters2479=== RUN TestQueueRemoveLargeClosure2480=== PAUSE TestQueueRemoveLargeClosure2481=== RUN TestServerClientIntegration2482--- PASS: TestServerClientIntegration (0.00s)2483=== RUN TestServerQueueError24842026/11/06 08:13:59 ERROR Failed to queue paths error="permission denied" count=12485--- PASS: TestServerQueueError (0.00s)2486=== RUN TestGetListenerSocketActivation2487 server_test.go:218: === RUN TestGetListenerSocketActivation2488 --- PASS: TestGetListenerSocketActivation (0.00s)2489 PASS2490 2491--- PASS: TestGetListenerSocketActivation (0.01s)2492=== RUN TestServerStalledClientDoesNotBlockShutdown2493=== PAUSE TestServerStalledClientDoesNotBlockShutdown2494=== RUN TestServerBacksOffOnAcceptErrors2495=== PAUSE TestServerBacksOffOnAcceptErrors2496=== RUN TestDrainIsolatesPoisonPath2497=== PAUSE TestDrainIsolatesPoisonPath2498=== RUN TestRunNotBlockedByPoisonHead2499=== PAUSE TestRunNotBlockedByPoisonHead2500=== RUN TestDrainGivesUpWhenServerDown2501=== PAUSE TestDrainGivesUpWhenServerDown2502=== RUN TestFailedPathPrunedByLaterClosure2503=== PAUSE TestFailedPathPrunedByLaterClosure2504=== RUN TestWorkerUploadsAndRemoves2505=== PAUSE TestWorkerUploadsAndRemoves2506=== RUN TestWorkerSkipsGCdPaths2507=== PAUSE TestWorkerSkipsGCdPaths2508=== RUN TestWorkerPrunesClosureDeps2509=== PAUSE TestWorkerPrunesClosureDeps2510=== RUN TestDrainTimeout2511=== PAUSE TestDrainTimeout2512=== RUN TestWorkerRemoveFailureIsNotProgress2513=== PAUSE TestWorkerRemoveFailureIsNotProgress2514=== RUN TestWorkerKeepsPathItCannotStat2515=== PAUSE TestWorkerKeepsPathItCannotStat2516=== CONT TestSendPathsEmpty2517=== CONT TestWorkerPrunesClosureDeps2518--- PASS: TestSendPathsEmpty (0.00s)2519=== CONT TestWorkerKeepsPathItCannotStat2520=== CONT TestWorkerRemoveFailureIsNotProgress2521=== CONT TestDrainTimeout2522=== CONT TestDrainIsolatesPoisonPath2523=== CONT TestServerBacksOffOnAcceptErrors2524=== CONT TestServerStalledClientDoesNotBlockShutdown25252026/11/06 08:13:59 ERROR Accept failed error="too many open files"2526=== CONT TestQueueRemoveLargeClosure2527=== CONT TestQueueConcurrentWriters2528=== CONT TestQueueFetchRemoveLifecycle2529=== CONT TestQueueRetryMovesToBack2530=== CONT TestQueueFetchBatchLimit2531=== CONT TestQueueRemove2532=== CONT TestQueueDeduplication2533=== CONT TestQueueEnqueueAndFetch2534=== CONT TestDrainGivesUpWhenServerDown2535=== CONT TestFailedPathPrunedByLaterClosure2536=== CONT TestRunNotBlockedByPoisonHead2537=== CONT TestWorkerUploadsAndRemoves2538=== CONT TestWorkerSkipsGCdPaths25392026/11/06 08:13:59 ERROR Accept failed error="too many open files"25402026/11/06 08:13:59 INFO Upload queue status pending=225412026/11/06 08:13:59 INFO Uploading batch count=125422026/11/06 08:13:59 INFO Upload queue status pending=225432026/11/06 08:13:59 INFO Uploading batch count=225442026/11/06 08:13:59 INFO Uploading batch count=125452026/11/06 08:13:59 ERROR Upload failed error="upload failed" count=125462026/11/06 08:13:59 INFO Upload queue status pending=225472026/11/06 08:13:59 INFO Uploading batch count=425482026/11/06 08:13:59 ERROR Upload failed error="upload failed" count=425492026/11/06 08:13:59 INFO Upload queue status pending=325502026/11/06 08:13:59 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat1923387002/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat1923387002/002/locked/aaa: permission denied"25512026/11/06 08:13:59 INFO Uploading batch count=225522026/11/06 08:13:59 ERROR Upload failed error="upload failed" count=225532026/11/06 08:13:59 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3224863179/002/a25542026/11/06 08:13:59 INFO Uploading batch count=225552026/11/06 08:13:59 ERROR Accept failed error="too many open files"25562026/11/06 08:13:59 INFO Uploading batch count=12557--- PASS: TestQueueFetchBatchLimit (0.02s)25582026/11/06 08:13:59 ERROR Upload failed error="upload failed" count=12559--- PASS: TestQueueEnqueueAndFetch (0.02s)25602026/11/06 08:13:59 INFO Uploading batch count=125612026/11/06 08:13:59 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths3173119539/002/nonexistent2562--- PASS: TestQueueFetchRemoveLifecycle (0.02s)25632026/11/06 08:13:59 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3224863179/002/b25642026/11/06 08:13:59 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat1923387002/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat1923387002/002/locked/aaa: permission denied"25652026/11/06 08:13:59 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath2671984611/002/bbb2566--- PASS: TestQueueRemove (0.02s)25672026/11/06 08:13:59 INFO Uploading batch count=12568--- PASS: TestQueueRetryMovesToBack (0.02s)25692026/11/06 08:13:59 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress1865841398/002/nonexistent25702026/11/06 08:13:59 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125712026/11/06 08:13:59 INFO Uploading batch count=22572--- PASS: TestQueueDeduplication (0.02s)25732026/11/06 08:13:59 ERROR Upload failed error="upload failed" count=225742026/11/06 08:13:59 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3224863179/002/c25752026/11/06 08:13:59 INFO Uploading batch count=125762026/11/06 08:13:59 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress1865841398/002/nonexistent25772026/11/06 08:13:59 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125782026/11/06 08:13:59 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress1865841398/002/nonexistent25792026/11/06 08:13:59 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat1923387002/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat1923387002/002/locked/aaa: permission denied"25802026/11/06 08:13:59 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125812026/11/06 08:13:59 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3224863179/002/d25822026/11/06 08:13:59 ERROR Drain finished with paths left in queue remaining=125832026/11/06 08:13:59 INFO Uploading batch count=225842026/11/06 08:13:59 ERROR Upload failed error="upload failed" count=225852026/11/06 08:13:59 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3224863179/002/e25862026/11/06 08:13:59 ERROR Drain finished with paths left in queue remaining=125872026/11/06 08:13:59 INFO Uploading batch count=125882026/11/06 08:13:59 ERROR Upload failed error="upload failed" count=12589--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)25902026/11/06 08:13:59 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3224863179/002/f2591--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)25922026/11/06 08:13:59 INFO Uploading batch count=125932026/11/06 08:13:59 ERROR Upload failed error="upload failed" count=125942026/11/06 08:13:59 ERROR Drain finished with paths left in queue remaining=1025952026/11/06 08:13:59 INFO Uploading batch count=125962026/11/06 08:13:59 ERROR Upload failed error="upload failed" count=12597--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)25982026/11/06 08:13:59 ERROR Drain finished with paths left in queue remaining=12599--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2600--- PASS: TestDrainIsolatesPoisonPath (0.03s)2601--- PASS: TestWorkerPrunesClosureDeps (0.04s)26022026/11/06 08:13:59 ERROR Accept failed error="too many open files"2603--- PASS: TestWorkerSkipsGCdPaths (0.03s)2604--- PASS: TestWorkerUploadsAndRemoves (0.03s)2605--- PASS: TestQueueRemoveLargeClosure (0.05s)26062026/11/06 08:13:59 ERROR Accept failed error="too many open files"2607--- PASS: TestQueueConcurrentWriters (0.15s)26082026/11/06 08:13:59 ERROR Accept failed error="too many open files"26092026/11/06 08:13:59 ERROR Failed to decode request error="read unix /build/hook3607556614/test.sock->@: i/o timeout"26102026/11/06 08:13:59 ERROR Failed to write response error="write unix /build/hook3607556614/test.sock->@: i/o timeout"2611--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26122026/11/06 08:13:59 ERROR Upload failed error="context deadline exceeded" count=226132026/11/06 08:13:59 ERROR Drain finished with paths left in queue remaining=42614--- PASS: TestDrainTimeout (0.22s)26152026/11/06 08:13:59 ERROR Accept failed error="too many open files"26162026/11/06 08:14:00 ERROR Accept failed error="too many open files"2617--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26182026/11/06 08:14:00 INFO Uploading batch count=126192026/11/06 08:14:00 INFO Uploading batch count=126202026/11/06 08:14:00 INFO Uploading batch count=126212026/11/06 08:14:00 ERROR Upload failed error="upload failed" count=126222026/11/06 08:14:00 INFO Uploading batch count=126232026/11/06 08:14:00 ERROR Upload failed error="upload failed" count=126242026/11/06 08:14:00 INFO Uploading batch count=126252026/11/06 08:14:00 ERROR Upload failed error="upload failed" count=126262026/11/06 08:14:00 INFO Uploading batch count=126272026/11/06 08:14:00 ERROR Upload failed error="upload failed" count=126282026/11/06 08:14:00 ERROR Drain finished with paths left in queue remaining=12629--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2630PASS2631Running signing tests...2632=== RUN TestExternalSigner2633=== PAUSE TestExternalSigner2634=== RUN TestExternalSignerWrongPublicKey2635=== PAUSE TestExternalSignerWrongPublicKey2636=== RUN TestExternalSignerErrors2637=== PAUSE TestExternalSignerErrors2638=== RUN TestExternalSignerRestartsAfterCrash2639=== PAUSE TestExternalSignerRestartsAfterCrash2640=== RUN TestExternalSignerProgramErrorKeepsProcess2641=== PAUSE TestExternalSignerProgramErrorKeepsProcess2642=== RUN TestExternalSignerClose2643=== PAUSE TestExternalSignerClose2644=== RUN TestExternalSignerRejectsInvalidPublicKey2645=== PAUSE TestExternalSignerRejectsInvalidPublicKey2646=== RUN TestExternalSignerCancellation2647=== PAUSE TestExternalSignerCancellation2648=== RUN TestGenerateFingerprint2649=== PAUSE TestGenerateFingerprint2650=== RUN TestParseSigningKey2651=== PAUSE TestParseSigningKey2652=== RUN TestSign2653=== PAUSE TestSign2654=== RUN TestSignBatch2655=== PAUSE TestSignBatch2656=== RUN TestNilKeyPublicKey2657=== PAUSE TestNilKeyPublicKey2658=== RUN TestSignErrors2659=== PAUSE TestSignErrors2660=== CONT TestExternalSigner2661=== CONT TestExternalSignerCancellation2662=== CONT TestSignErrors2663=== CONT TestSignBatch2664=== CONT TestSign2665=== CONT TestNilKeyPublicKey2666=== CONT TestParseSigningKey2667=== RUN TestParseSigningKey/valid_32-byte_key2668=== CONT TestExternalSignerProgramErrorKeepsProcess2669=== PAUSE TestParseSigningKey/valid_32-byte_key2670=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2671=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2672=== CONT TestExternalSignerRejectsInvalidPublicKey2673=== CONT TestGenerateFingerprint2674=== CONT TestExternalSignerClose2675=== CONT TestExternalSignerErrors2676=== CONT TestExternalSignerRestartsAfterCrash2677=== CONT TestExternalSignerWrongPublicKey2678--- PASS: TestNilKeyPublicKey (0.00s)2679--- PASS: TestSign (0.00s)2680--- PASS: TestSignBatch (0.00s)2681=== RUN TestGenerateFingerprint/basic_with_references2682=== RUN TestExternalSignerErrors/null2683=== PAUSE TestExternalSignerErrors/null2684=== RUN TestExternalSignerErrors/invalid_signature_base642685=== PAUSE TestExternalSignerErrors/invalid_signature_base642686=== RUN TestExternalSignerErrors/wrong_signature_length2687=== PAUSE TestExternalSignerErrors/wrong_signature_length2688=== PAUSE TestGenerateFingerprint/basic_with_references2689=== RUN TestSignErrors/nil_key2690=== PAUSE TestSignErrors/nil_key2691=== RUN TestSignErrors/nil_narinfo2692=== RUN TestExternalSignerRejectsInvalidPublicKey/#002693=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002694=== RUN TestParseSigningKey/no_colon2695=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2696=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2697=== PAUSE TestParseSigningKey/no_colon2698=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2699=== RUN TestParseSigningKey/empty_name2700=== PAUSE TestParseSigningKey/empty_name2701=== RUN TestParseSigningKey/invalid_base642702=== PAUSE TestParseSigningKey/invalid_base642703=== RUN TestParseSigningKey/wrong_length2704=== PAUSE TestParseSigningKey/wrong_length2705=== RUN TestGenerateFingerprint/no_references2706=== PAUSE TestSignErrors/nil_narinfo2707=== RUN TestSignErrors/invalid_narinfo2708=== PAUSE TestSignErrors/invalid_narinfo2709=== RUN TestSignErrors/canceled2710=== RUN TestExternalSignerErrors/exit_at_startup2711=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2712=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2713=== CONT TestParseSigningKey/valid_32-byte_key2714=== CONT TestParseSigningKey/wrong_length2715=== CONT TestParseSigningKey/invalid_base642716=== CONT TestParseSigningKey/empty_name2717=== CONT TestParseSigningKey/no_colon2718=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2719--- PASS: TestParseSigningKey (0.00s)2720 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2721 --- PASS: TestParseSigningKey/wrong_length (0.00s)2722 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2723 --- PASS: TestParseSigningKey/empty_name (0.00s)2724 --- PASS: TestParseSigningKey/no_colon (0.00s)2725 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2726=== PAUSE TestGenerateFingerprint/no_references2727=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2728=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2729=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2730=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2731=== RUN TestGenerateFingerprint/invalid_nar_hash_length2732=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2733=== RUN TestGenerateFingerprint/invalid_store_path_prefix2734=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2735=== RUN TestGenerateFingerprint/invalid_reference_prefix2736=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2737=== CONT TestGenerateFingerprint/basic_with_references2738=== PAUSE TestSignErrors/canceled2739=== CONT TestSignErrors/nil_key2740=== CONT TestGenerateFingerprint/invalid_reference_prefix2741=== CONT TestGenerateFingerprint/invalid_store_path_prefix2742=== CONT TestGenerateFingerprint/invalid_nar_hash_length2743=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2744=== CONT TestGenerateFingerprint/no_references2745=== PAUSE TestExternalSignerErrors/exit_at_startup2746=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2747=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2748=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2749=== CONT TestExternalSignerRejectsInvalidPublicKey/#002750=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2751=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2752--- PASS: TestGenerateFingerprint (0.00s)2753 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2754 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2755 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2756 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2757 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2758 --- PASS: TestGenerateFingerprint/no_references (0.00s)2759 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2760=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2761=== CONT TestSignErrors/canceled2762=== CONT TestSignErrors/invalid_narinfo2763=== CONT TestSignErrors/nil_narinfo2764--- PASS: TestSignErrors (0.00s)2765 --- PASS: TestSignErrors/nil_key (0.00s)2766 --- PASS: TestSignErrors/canceled (0.00s)2767 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2768 --- PASS: TestSignErrors/nil_narinfo (0.00s)2769=== RUN TestExternalSignerErrors/exit_on_request2770=== PAUSE TestExternalSignerErrors/exit_on_request2771=== RUN TestExternalSignerErrors/invalid_JSON2772=== PAUSE TestExternalSignerErrors/invalid_JSON2773=== RUN TestExternalSignerErrors/missing_signatures2774=== PAUSE TestExternalSignerErrors/missing_signatures2775=== RUN TestExternalSignerErrors/too_few_signatures2776=== PAUSE TestExternalSignerErrors/too_few_signatures2777=== RUN TestExternalSignerErrors/unrequested_key2778=== PAUSE TestExternalSignerErrors/unrequested_key2779=== RUN TestExternalSignerErrors/missing_signature_name2780=== PAUSE TestExternalSignerErrors/missing_signature_name2781=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2782=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2783--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2784 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2785 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2786 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2787 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2788 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2789=== RUN TestExternalSignerErrors/program_error2790=== PAUSE TestExternalSignerErrors/program_error2791=== RUN TestExternalSignerErrors/wrong_shape2792=== PAUSE TestExternalSignerErrors/wrong_shape2793=== RUN TestExternalSignerErrors/wrong_id2794=== PAUSE TestExternalSignerErrors/wrong_id2795=== RUN TestExternalSignerErrors/null_signatures2796=== PAUSE TestExternalSignerErrors/null_signatures2797=== RUN TestExternalSignerErrors/wrong_signatures_shape2798=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2799=== RUN TestExternalSignerErrors/wrong_signature_name2800=== PAUSE TestExternalSignerErrors/wrong_signature_name2801=== CONT TestExternalSignerErrors/null2802=== CONT TestExternalSignerErrors/missing_signatures2803=== CONT TestExternalSignerErrors/too_few_signatures2804=== CONT TestExternalSignerErrors/wrong_signature_name2805=== CONT TestExternalSignerErrors/wrong_signatures_shape2806=== CONT TestExternalSignerErrors/exit_on_request2807=== CONT TestExternalSignerErrors/wrong_id2808=== CONT TestExternalSignerErrors/wrong_shape2809=== CONT TestExternalSignerErrors/program_error2810=== CONT TestExternalSignerErrors/missing_signature_name2811=== CONT TestExternalSignerErrors/unrequested_key2812=== CONT TestExternalSignerErrors/wrong_signature_length2813=== CONT TestExternalSignerErrors/exit_at_startup2814=== CONT TestExternalSignerErrors/invalid_JSON2815=== CONT TestExternalSignerErrors/null_signatures2816=== CONT TestExternalSignerErrors/invalid_signature_base642817--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2818--- PASS: TestExternalSignerWrongPublicKey (0.00s)2819--- PASS: TestExternalSignerClose (0.00s)2820--- PASS: TestExternalSigner (0.01s)2821--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2822--- PASS: TestExternalSignerErrors (0.00s)2823 --- PASS: TestExternalSignerErrors/missing_signatures (0.00s)2824 --- PASS: TestExternalSignerErrors/too_few_signatures (0.00s)2825 --- PASS: TestExternalSignerErrors/null (0.00s)2826 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.00s)2827 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)2828 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2829 --- PASS: TestExternalSignerErrors/exit_on_request (0.01s)2830 --- PASS: TestExternalSignerErrors/exit_at_startup (0.01s)2831 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)2832 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)2833 --- PASS: TestExternalSignerErrors/program_error (0.01s)2834 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)2835 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)2836 --- PASS: TestExternalSignerErrors/unrequested_key (0.01s)2837 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.01s)2838 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)2839--- PASS: TestExternalSignerCancellation (0.02s)2840PASS2841Running OpenBao signer tests...2842=== RUN TestSign2843=== PAUSE TestSign2844=== RUN TestSignErrors2845=== PAUSE TestSignErrors2846=== RUN TestServe2847=== PAUSE TestServe2848=== RUN TestServeRejectsGarbage2849=== PAUSE TestServeRejectsGarbage2850=== CONT TestSign2851=== CONT TestServe2852=== CONT TestSignErrors2853=== CONT TestServeRejectsGarbage2854=== RUN TestSignErrors/http_error2855=== PAUSE TestSignErrors/http_error2856--- PASS: TestServe (0.00s)2857=== RUN TestSignErrors/invalid_json2858=== PAUSE TestSignErrors/invalid_json2859--- PASS: TestServeRejectsGarbage (0.00s)2860=== RUN TestSignErrors/no_prefix2861=== PAUSE TestSignErrors/no_prefix2862=== RUN TestSignErrors/invalid_base642863=== PAUSE TestSignErrors/invalid_base642864=== CONT TestSignErrors/http_error2865=== CONT TestSignErrors/invalid_json2866=== CONT TestSignErrors/no_prefix2867=== CONT TestSignErrors/invalid_base642868--- PASS: TestSign (0.00s)2869--- PASS: TestSignErrors (0.00s)2870 --- PASS: TestSignErrors/no_prefix (0.00s)2871 --- PASS: TestSignErrors/invalid_base64 (0.00s)2872 --- PASS: TestSignErrors/http_error (0.00s)2873 --- PASS: TestSignErrors/invalid_json (0.00s)2874PASS