niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #460
· 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_FailedPartBufferNotReused20=== PAUSE TestUploadMultipart_FailedPartBufferNotReused21=== RUN TestUploadMultipart_ReturnsAfterDroppedBody22=== PAUSE TestUploadMultipart_ReturnsAfterDroppedBody23=== RUN TestPartSizeForNAR24=== PAUSE TestPartSizeForNAR25=== RUN TestUploadMultipart_SupersededByPeer26=== PAUSE TestUploadMultipart_SupersededByPeer27=== RUN TestDumpPathCaseHackMatchesNix28--- PASS: TestDumpPathCaseHackMatchesNix (0.04s)29=== RUN TestDumpPathCaseHackCollision30--- PASS: TestDumpPathCaseHackCollision (0.00s)31=== RUN TestSupersededNARStillUploadsListing32=== PAUSE TestSupersededNARStillUploadsListing33=== RUN TestDumpPathMatchesNix34=== PAUSE TestDumpPathMatchesNix35=== RUN TestDumpPathSingleFile36=== PAUSE TestDumpPathSingleFile37=== RUN TestDumpPathWriterError38=== PAUSE TestDumpPathWriterError39=== RUN TestEncodeNixBase3240=== PAUSE TestEncodeNixBase3241=== RUN TestEncodeNixBase32WithRealHash42=== PAUSE TestEncodeNixBase32WithRealHash43=== RUN TestConvertHashToNix3244=== PAUSE TestConvertHashToNix3245=== RUN TestGetStorePathHash46=== PAUSE TestGetStorePathHash47=== RUN TestPathInfoHashCompatibility48=== PAUSE TestPathInfoHashCompatibility49=== RUN TestParsePathInfoJSON50=== PAUSE TestParsePathInfoJSON51=== RUN TestParsePathInfoJSONMultiplePaths52=== PAUSE TestParsePathInfoJSONMultiplePaths53=== RUN TestPathInfoCACompatibility54=== PAUSE TestPathInfoCACompatibility55=== RUN TestRateLimiterFeedback56=== PAUSE TestRateLimiterFeedback57=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess58=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess59=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer60=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer61=== 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 TestDumpPathSingleFile120=== CONT TestResolveStorePath121=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer122=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1232026/11/04 20:13:25 WARN Rate limiter enabled after throttle name=server-test rate=5124--- PASS: TestResolveStorePath (0.00s)125=== CONT TestStreamPushIsolatesFailures126=== CONT TestRateLimiterFeedback127=== CONT TestUploadMultipart_PartsInParallel128=== CONT TestDumpPathMatchesNix129=== CONT TestSupersededNARStillUploadsListing130=== CONT TestPathInfoCACompatibility131=== CONT TestUploadMultipart_SupersededByPeer132=== CONT TestParsePathInfoJSONMultiplePaths133=== CONT TestPartSizeForNAR134=== CONT TestUploadMultipart_ReturnsAfterDroppedBody135=== CONT TestParsePathInfoJSON136=== CONT TestPathInfoHashCompatibility137=== CONT TestGetStorePathHash138=== CONT TestConvertHashToNix321392026/11/04 20:13:25 ERROR Upload failed error="bad path" count=3140=== CONT TestUploadMultipart_FailedPartBufferNotReused141=== CONT TestEncodeNixBase32WithRealHash142=== CONT TestEncodeNixBase32143=== CONT TestDumpPathWriterError144=== CONT TestSetClientTLS145=== RUN TestRateLimiterFeedback/429_enables_limiter146--- PASS: TestEncodeNixBase32WithRealHash (0.00s)147=== PAUSE TestRateLimiterFeedback/429_enables_limiter148=== CONT TestStreamPushStopsWhenCanceled149=== RUN TestRateLimiterFeedback/503_enables_limiter150=== RUN TestUploadMultipart_SupersededByPeer/exists151=== RUN TestSupersededNARStillUploadsListing/small_NAR152=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)153=== PAUSE TestSupersededNARStillUploadsListing/small_NAR154=== RUN TestPathInfoCACompatibility/null_ca_field155--- PASS: TestStreamPushStopsWhenCanceled (0.00s)156=== PAUSE TestRateLimiterFeedback/503_enables_limiter157=== PAUSE TestUploadMultipart_SupersededByPeer/exists158=== RUN TestPartSizeForNAR/zero_stays_at_minimum159=== RUN TestParsePathInfoJSON/Nix_format160=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths161=== CONT TestClientSignaturesByStorePath162--- PASS: TestClientSignaturesByStorePath (0.00s)163=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)164=== RUN TestSupersededNARStillUploadsListing/dump_cut_short165=== RUN TestConvertHashToNix32/SRI_format_to_Nix32166=== RUN TestGetStorePathHash/valid_store_path167=== RUN TestUploadMultipart_SupersededByPeer/missing168=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon1692026/11/04 20:13:25 WARN Rate limiter enabled after throttle name=server-test rate=51702026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:46587171=== RUN TestEncodeNixBase32/test_string_hash172--- PASS: TestStreamPushIsolatesFailures (0.03s)173=== CONT TestStreamPushReportsSignatures174=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum175=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter176=== CONT TestStreamPushReportsSkippedPaths177=== PAUSE TestEncodeNixBase32/test_string_hash178=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32179=== PAUSE TestGetStorePathHash/valid_store_path180=== PAUSE TestPathInfoCACompatibility/null_ca_field181=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short182=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter183=== PAUSE TestParsePathInfoJSON/Nix_format1842026/11/04 20:13:25 ERROR Upload failed error=boom count=1185--- PASS: TestStreamPushReportsSignatures (0.03s)186=== CONT TestStreamPushRequestLine1872026/11/04 20:13:25 ERROR Upload failed error=boom count=1188=== PAUSE TestUploadMultipart_SupersededByPeer/missing189=== CONT TestStreamPushGivesUpOnDeadServer190=== RUN TestEncodeNixBase32/empty_input191=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon192=== PAUSE TestEncodeNixBase32/empty_input193=== RUN TestPartSizeForNAR/small_stays_at_minimum1942026/11/04 20:13:25 ERROR Upload failed error="connection refused" count=20195=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun1962026/11/04 20:13:25 ERROR Server seems unavailable, giving up on batch untried=17197=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter1982026/11/04 20:13:25 WARN Rate limiter backed off name=server-test rate=51992026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:46587200=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter201=== CONT TestFilterOversizedClosures202=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI203=== RUN TestParsePathInfoJSON/Lix_format204=== RUN TestFilterOversizedClosures/no_limit_keeps_everything205=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything206=== CONT TestCaseHackSuffix207=== PAUSE TestPartSizeForNAR/small_stays_at_minimum208=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped209=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped210=== RUN TestConvertHashToNix32/already_Nix32_format211=== RUN TestFilterOversizedClosures/all_closures_skipped212=== PAUSE TestFilterOversizedClosures/all_closures_skipped213=== CONT TestRegisterUploadedObjectReusesConnections214=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry2152026/11/04 20:13:25 INFO Garbage collection started216=== CONT TestDoWithRetry_FinalResponseBodyReadable217=== RUN TestSetClientTLS/rejects_connection_without_client_cert218=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert219=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA220=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA221=== RUN TestSetClientTLS/preserves_debug_logging_transport222=== PAUSE TestSetClientTLS/preserves_debug_logging_transport223=== CONT TestShellSplit224=== CONT TestRetryTimeoutOutlastsMaxRetries2252026/11/04 20:13:25 WARN Rate limiter enabled after throttle name=server-test rate=52262026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:344432272026/11/04 20:13:25 WARN Rate limiter backed off name=server-test rate=5228=== CONT TestScriptTokenNoExpiryRerunsEveryCall2292026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:40921230=== PAUSE TestConvertHashToNix32/already_Nix32_format231=== RUN TestGetStorePathHash/basename_without_hyphen_should_error232=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error233=== RUN TestPathInfoCACompatibility/old_string_format_-_text234=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error235=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error236=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error237=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text238=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails239--- PASS: TestStreamPushReportsSkippedPaths (0.00s)240--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)241--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.04s)242--- PASS: TestDoServerRequestAttachesToken (0.07s)243=== CONT TestStreamPushBatchesUnderLoad244=== CONT TestShellSplitErrors245=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI2462026/11/04 20:13:25 WARN Rate limiter enabled after throttle name=s3-test rate=5247=== PAUSE TestParsePathInfoJSON/Lix_format2482026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:37295249=== CONT TestStreamPushReportsEveryPath250=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum251=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica252=== RUN TestConvertHashToNix32/invalid_format253=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512254=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512255=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths256=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths257=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths258=== CONT TestScriptTokenEmptyCommand259=== CONT TestFileTokenMissing2602026/11/04 20:13:25 INFO Garbage collection started2612026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:40921262=== CONT TestScriptTokenEmptyToken263=== CONT TestScriptTokenBadJSON264=== CONT TestScriptTokenScriptFails2652026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:409212662026/11/04 20:13:25 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=02672026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:40921268=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive269=== CONT TestSetClientTLSErrors2702026/11/04 20:13:25 WARN Garbage collection finished on another replica. Its statistics are not available here271=== CONT TestScriptTokenCachesUntilRefresh272=== CONT TestStaticToken273=== CONT TestSetClientTLSDoesNotMutateDefaultTransport2742026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:40921275=== RUN TestSetClientTLSErrors/missing_cert_file276=== PAUSE TestSetClientTLSErrors/missing_cert_file277=== RUN TestSetClientTLSErrors/missing_key_file278=== PAUSE TestSetClientTLSErrors/missing_key_file279=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive280--- PASS: TestDumpPathSingleFile (0.07s)281=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false282=== CONT TestFileTokenReadsAndCaches283=== RUN TestParsePathInfoJSON/empty_input284=== PAUSE TestConvertHashToNix32/invalid_format285=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum286=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error287=== CONT TestFileTokenEmpty288=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails289=== RUN TestSetClientTLSErrors/missing_ca_file290=== PAUSE TestSetClientTLSErrors/missing_ca_file291=== RUN TestSetClientTLSErrors/invalid_ca_file292=== PAUSE TestSetClientTLSErrors/invalid_ca_file293=== CONT TestUploadMultipart_SupersededByPeer/missing294=== CONT TestUploadMultipart_SupersededByPeer/exists295=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false296=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true297=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true298=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts299=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts300=== RUN TestPartSizeForNAR/1_TiB301=== PAUSE TestPartSizeForNAR/1_TiB302=== RUN TestPartSizeForNAR/5_TiB_S3_max_object303=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object304=== RUN TestPartSizeForNAR/capped_at_5_GiB305=== PAUSE TestPartSizeForNAR/capped_at_5_GiB306=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter307=== CONT TestEncodeNixBase32/empty_input308=== CONT TestRateLimiterFeedback/503_enables_limiter309=== RUN TestPathInfoCACompatibility/new_structured_format_-_text310=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text311=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method312=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method313=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter3142026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:40921315=== CONT TestFilterOversizedClosures/all_closures_skipped316=== PAUSE TestParsePathInfoJSON/empty_input3172026/11/04 20:13:25 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50318=== CONT TestSetClientTLS/rejects_connection_without_client_cert3192026/11/04 20:13:25 WARN Rate limiter enabled after throttle name=server-test rate=5320=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha5123212026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:42397322=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon3232026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:40921324=== CONT TestFilterOversizedClosures/no_limit_keeps_everything3252026/11/04 20:13:25 WARN Rate limiter backed off name=server-test rate=5326=== CONT TestRateLimiterFeedback/429_enables_limiter327=== CONT TestEncodeNixBase32/test_string_hash328--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.07s)329=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3302026/11/04 20:13:25 WARN Rate limiter enabled after throttle name=server-test rate=5331=== CONT TestSetClientTLS/preserves_debug_logging_transport3322026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:41657333=== RUN TestParsePathInfoJSON/whitespace_only3342026/11/04 20:13:25 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=2000335=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3362026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:40921337=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)3382026/11/04 20:13:25 WARN Rate limiter backed off name=server-test rate=5339=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI340=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths341=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths342=== CONT TestConvertHashToNix32/SRI_format_to_Nix32343=== CONT TestSetClientTLSErrors/missing_cert_file344--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.00s)345=== PAUSE TestParsePathInfoJSON/whitespace_only346=== RUN TestParsePathInfoJSON/invalid_JSON347=== CONT TestSetClientTLSErrors/invalid_ca_file348=== CONT TestGetStorePathHash/valid_store_path349=== CONT TestSetClientTLSErrors/missing_ca_file350=== CONT TestSupersededNARStillUploadsListing/small_NAR351=== CONT TestConvertHashToNix32/invalid_format352--- PASS: TestShellSplit (0.00s)353--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.00s)354--- PASS: TestShellSplitErrors (0.00s)355--- PASS: TestStreamPushReportsEveryPath (0.00s)356--- PASS: TestScriptTokenEmptyCommand (0.00s)357--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.00s)358--- PASS: TestFileTokenMissing (0.00s)359--- PASS: TestScriptTokenEmptyToken (0.00s)360=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false361--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)3622026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:40921363--- PASS: TestScriptTokenScriptFails (0.01s)364--- PASS: TestStaticToken (0.00s)365--- PASS: TestScriptTokenBadJSON (0.01s)366--- PASS: TestFileTokenEmpty (0.00s)367--- PASS: TestFileTokenReadsAndCaches (0.00s)368--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)369=== CONT TestSupersededNARStillUploadsListing/dump_cut_short3702026/11/04 20:13:25 INFO Uploading abc-hello (1.0GB)371--- PASS: TestUploadMultipart_SupersededByPeer (0.06s)372 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)373 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)374--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.02s)375--- PASS: TestScriptTokenCachesUntilRefresh (0.01s)376=== CONT TestSetClientTLSErrors/missing_key_file377--- PASS: TestEncodeNixBase32 (0.04s)378 --- PASS: TestEncodeNixBase32/empty_input (0.00s)379 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)3802026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:40921381--- PASS: TestParsePathInfoJSONMultiplePaths (0.07s)382 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)383 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)384--- PASS: TestFilterOversizedClosures (0.00s)385 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)386 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)387 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)388=== CONT TestPartSizeForNAR/capped_at_5_GiB389=== CONT TestPartSizeForNAR/1_TiB390=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts391=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum392=== CONT TestPartSizeForNAR/small_stays_at_minimum393=== CONT TestPathInfoCACompatibility/new_structured_format_-_text394=== CONT TestPartSizeForNAR/5_TiB_S3_max_object395=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive396=== CONT TestPathInfoCACompatibility/old_string_format_-_text397=== CONT TestPathInfoCACompatibility/null_ca_field398=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true399=== CONT TestPartSizeForNAR/zero_stays_at_minimum400=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails4012026/11/04 20:13:25 INFO Uploading abc-hello (1.0GB)402=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error4032026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:40921404=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error405=== PAUSE TestParsePathInfoJSON/invalid_JSON406=== CONT TestParsePathInfoJSON/Nix_format407=== CONT TestGetStorePathHash/basename_without_hyphen_should_error408=== CONT TestConvertHashToNix32/already_Nix32_format409--- PASS: TestPathInfoHashCompatibility (0.07s)410 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)411 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)412 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)413 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)414--- PASS: TestRateLimiterFeedback (0.07s)415 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)416 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)417 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)418 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)419=== CONT TestParsePathInfoJSON/empty_input420=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method421=== CONT TestParsePathInfoJSON/invalid_JSON422=== CONT TestParsePathInfoJSON/whitespace_only423=== CONT TestParsePathInfoJSON/Lix_format424--- PASS: TestStreamPushRequestLine (0.03s)425--- PASS: TestPartSizeForNAR (0.08s)426 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)427 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)428 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)429 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)430 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)431 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)432 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)433--- PASS: TestStreamPushBatchesUnderLoad (0.01s)434 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)435 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)436--- PASS: TestGetStorePathHash (0.08s)437 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)438 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)439 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)440 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)441--- PASS: TestConvertHashToNix32 (0.08s)442 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)443 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)444 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)445--- PASS: TestPathInfoCACompatibility (0.08s)446 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)447 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)448 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)449 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)450 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)4512026/11/04 20:13:25 http: TLS handshake error from 127.0.0.1:59422: remote error: tls: bad certificate452--- PASS: TestParsePathInfoJSON (0.10s)453 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)454 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)455 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)456 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)457 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)4582026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:40921459--- PASS: TestSetClientTLSErrors (0.00s)460 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)461 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)462 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)463 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)464--- PASS: TestSetClientTLS (0.03s)465 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)466 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)467 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)4682026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:409214692026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:409214702026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:40921471--- PASS: TestCaseHackSuffix (0.04s)472--- PASS: TestRegisterUploadedObjectReusesConnections (0.04s)4732026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:409214742026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:409214752026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:409214762026/11/04 20:13:25 WARN Rate limiter enabled after throttle name=s3-test rate=54772026/11/04 20:13:25 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:40921478--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.04s)479--- PASS: TestDumpPathWriterError (0.07s)480--- PASS: TestDumpPathMatchesNix (0.16s)4812026/11/04 20:13:25 INFO Uploading abc-hello (1.0GB)4822026/11/04 20:13:25 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:45661/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:45661/part/24832026/11/04 20:13:25 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:45661/part/3\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:45661/part/34842026/11/04 20:13:25 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"485--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.63s)486--- PASS: TestUploadMultipart_PartsInParallel (0.68s)487--- PASS: TestSupersededNARStillUploadsListing (0.08s)488 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.01s)489 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.01s)490 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.68s)4912026/11/04 20:13:26 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:42353/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:42353/api/uploads/complete492--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4932026/11/04 20:13:26 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4942026/11/04 20:13:26 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:42353/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:42353/api/uploads/complete4952026/11/04 20:13:26 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4962026/11/04 20:13:26 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:42353/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:42353/api/uploads/complete4972026/11/04 20:13:26 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"498--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.03s)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/postgres3416424298/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/postgres3416424298/data -l logfile start527528/build/postgres3416424298:5432 - no response5292026-11-04 20:13:27.502 UTC [131] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit5302026-11-04 20:13:27.503 UTC [131] LOG: listening on Unix socket "/build/postgres3416424298/.s.PGSQL.5432"5312026-11-04 20:13:27.509 UTC [138] LOG: database system was shut down at 2026-11-04 20:13:27 UTC5322026-11-04 20:13:27.513 UTC [131] LOG: database system is ready to accept connections533/build/postgres3416424298: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/04 20:13:28 INFO lead: acquired remote=192.0.2.1:12345822026/11/04 20:13:28 INFO lead: released remote=192.0.2.1:12345832026/11/04 20:13:28 INFO lead: acquired remote=192.0.2.1:12345842026/11/04 20:13:29 INFO lead: released remote=192.0.2.1:1234585--- PASS: TestLeadIncumbentWinsAfterRestart (1.91s)586=== RUN TestLeadIncumbentAnnouncesAtOnce587=== PAUSE TestLeadIncumbentAnnouncesAtOnce588=== RUN TestLeadEndsOnShutdown589=== PAUSE TestLeadEndsOnShutdown590=== RUN TestLeadEndsWhenItsConnectionHangs5912026/11/04 20:13:29 INFO lead: acquired remote=192.0.2.1:12345922026-11-04 20:13:31.343 UTC [577] FATAL: terminating connection due to administrator command5932026/11/04 20:13:31 INFO lead: acquired remote=192.0.2.1:12345942026/11/04 20:13:32 WARN lead: lock connection lost error="timeout: context deadline exceeded"5952026/11/04 20:13:32 INFO lead: released remote=192.0.2.1:12345962026/11/04 20:13:32 INFO lead: released remote=192.0.2.1:1234597--- PASS: TestLeadEndsWhenItsConnectionHangs (2.91s)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/04 20:13:32 INFO Starting HTTP server address=127.0.0.1:338036982026/11/04 20:13:32 INFO Starting HTTP server address=proxy.sock6992026/11/04 20:13:32 WARN mTLS auth: subject not in bound subjects subject="CN=someone"7002026/11/04 20:13:32 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/04 20:13:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/11/04 20:13:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/11/04 20:13:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/11/04 20:13:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/11/04 20:13:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/11/04 20:13:33 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7752026/11/04 20:13:33 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7762026/11/04 20:13:33 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7772026/11/04 20:13:33 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7782026/11/04 20:13:33 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 TestReadProxyHead806=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT807=== CONT TestCompleteMultipartUnregistered808=== CONT TestService_verifyS3ReuploadsStaleNarinfo809=== CONT TestService_verifyS3Integrity810=== CONT TestService_createPendingClosureHandler811=== CONT TestService_cleanupPendingClosuresHandler812=== CONT TestUploadHandlersRejectOversizedBody813=== CONT TestUploadHandlersRejectInvalidKeys814=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info815=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info816=== CONT TestIsValidUploadKey817=== RUN TestIsValidUploadKey/narinfo818=== CONT TestPendingClosureWriteTimeout819=== CONT TestProxyWriteTimeout820=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle821=== CONT TestSkippedUploadsHandler822=== CONT TestParseSize823=== CONT TestService_Rustfstest824=== CONT TestPresignedUploadRegisteredBeforeCommit825=== CONT TestCompletedNarNotReofferedAcrossClosures826=== CONT TestCompleteMultipartUpload_ErrorButObjectExists827=== CONT TestRedundantMultipartUpload828=== CONT TestPush_SignsNarinfosOfItsPendingObjects829=== CONT TestPush_RejectsBadRequests830=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit831=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed832=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal833=== PAUSE TestIsValidUploadKey/narinfo834=== RUN TestIsValidUploadKey/nar_zst835=== RUN TestProxyWriteTimeout/narinfo836=== RUN TestPendingClosureWriteTimeout/empty837--- PASS: TestParseSize (0.00s)838=== CONT TestPush_RootsAreLockedInByteOrder839=== PAUSE TestIsValidUploadKey/nar_zst8402026/11/04 20:13:33 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000841=== RUN TestIsValidUploadKey/nar_xz842=== PAUSE TestIsValidUploadKey/nar_xz843=== RUN TestIsValidUploadKey/nar_plain844=== PAUSE TestIsValidUploadKey/nar_plain845=== RUN TestIsValidUploadKey/listing846=== PAUSE TestProxyWriteTimeout/narinfo847=== PAUSE TestIsValidUploadKey/listing848=== RUN TestIsValidUploadKey/build_log849=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed850=== PAUSE TestPendingClosureWriteTimeout/empty851=== RUN TestPendingClosureWriteTimeout/400_objects852=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal853=== RUN TestProxyWriteTimeout/1_GiB_nar854=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed855=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key856--- PASS: TestSkippedUploadsHandler (0.03s)857=== PAUSE TestIsValidUploadKey/build_log858=== PAUSE TestProxyWriteTimeout/1_GiB_nar859=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed860=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key861=== CONT TestCommitRacingPendingCleanupKeepsObjects862=== PAUSE TestPendingClosureWriteTimeout/400_objects863=== RUN TestPendingClosureWriteTimeout/670k_objects864=== PAUSE TestPendingClosureWriteTimeout/670k_objects865=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline866=== RUN TestIsValidUploadKey/build_log_home-manager_file867=== PAUSE TestIsValidUploadKey/build_log_home-manager_file868=== RUN TestProxyWriteTimeout/10_GiB_nar869=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost870=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key871=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key872=== CONT TestPush_CompleteWaitsForCleanupOfThePush873=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline874=== RUN TestIsValidUploadKey/build_log_plus_in_name875=== PAUSE TestIsValidUploadKey/build_log_plus_in_name876=== RUN TestIsValidUploadKey/build_log_question_mark877=== PAUSE TestIsValidUploadKey/build_log_question_mark878=== PAUSE TestProxyWriteTimeout/10_GiB_nar879=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost880=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed881=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed882=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed883=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed884=== CONT TestPush_RepeatedRootCommitsOnce885=== RUN TestIsValidUploadKey/build_log_equals886=== PAUSE TestIsValidUploadKey/build_log_equals887=== RUN TestProxyWriteTimeout/unknown_size888=== PAUSE TestProxyWriteTimeout/unknown_size889=== CONT TestReadProxyInvalidPath890=== RUN TestIsValidUploadKey/realisation891=== PAUSE TestIsValidUploadKey/realisation892=== CONT TestPush_CompleteCommitsEveryRoot893=== RUN TestIsValidUploadKey/realisation_plus_in_output894=== PAUSE TestIsValidUploadKey/realisation_plus_in_output895=== RUN TestIsValidUploadKey/nix-cache-info896=== PAUSE TestIsValidUploadKey/nix-cache-info897=== RUN TestIsValidUploadKey/index.html898=== PAUSE TestIsValidUploadKey/index.html899=== RUN TestIsValidUploadKey/narinfo_key,_nar_type900=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type901=== RUN TestIsValidUploadKey/nar_key,_narinfo_type902=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type903=== RUN TestIsValidUploadKey/listing_key,_narinfo_type904=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type905=== RUN TestIsValidUploadKey/traversal906=== PAUSE TestIsValidUploadKey/traversal907=== RUN TestIsValidUploadKey/traversal_nar908=== PAUSE TestIsValidUploadKey/traversal_nar909=== RUN TestIsValidUploadKey/absolute910=== PAUSE TestIsValidUploadKey/absolute911=== RUN TestIsValidUploadKey/empty_key912=== PAUSE TestIsValidUploadKey/empty_key913=== RUN TestIsValidUploadKey/unknown_type914=== PAUSE TestIsValidUploadKey/unknown_type915=== CONT TestReadProxy404916=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart917=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart918=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts919=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts920=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure921=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure922=== CONT TestPush_OverlappingRootsStoreOneRowPerKey923--- PASS: TestReadProxyHead (0.41s)924=== CONT TestReadRedirectUsesPublicS3URL9252026/11/04 20:13:33 INFO Received cleanup request method=DELETE path=/api/pending_closures9262026/11/04 20:13:33 INFO Aborted multipart uploads count=0 kept=09272026/11/04 20:13:33 INFO Received uploads request method=POST path=/api/pending_closures9282026/11/04 20:13:33 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"929--- PASS: TestService_AuthMiddleware (0.45s)930=== CONT TestReadProxyNarStreaming9312026/11/04 20:13:33 INFO Received cleanup request method=DELETE path=/api/pending_closures9322026/11/04 20:13:33 INFO Aborted multipart uploads count=1 kept=09332026/11/04 20:13:33 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9342026-11-04 20:13:33.550 UTC [650] ERROR: Closure does not exist: id=19352026-11-04 20:13:33.550 UTC [650] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9362026-11-04 20:13:33.550 UTC [650] STATEMENT: -- name: CommitPendingClosure :one937 SELECT commit_pending_closure($1::bigint)::bigint938 939--- PASS: TestService_cleanupPendingClosuresHandler (0.46s)940=== CONT TestReadProxyContentNegotiation9412026/11/04 20:13:33 INFO Received uploads request method=POST path=/api/pending_closures9422026/11/04 20:13:33 INFO Received push request method=POST path=/api/pushes9432026/11/04 20:13:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9442026/11/04 20:13:33 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst945--- PASS: TestCompleteMultipartUnregistered (0.53s)946=== CONT TestReadProxyRangeRequest9472026-11-04 20:13:33.638 UTC [686] ERROR: could not obtain lock on row in relation "closures"9482026-11-04 20:13:33.638 UTC [686] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9492026-11-04 20:13:33.639 UTC [686] ERROR: could not obtain lock on row in relation "closures"9502026-11-04 20:13:33.639 UTC [686] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9512026-11-04 20:13:33.639 UTC [686] ERROR: could not obtain lock on row in relation "closures"9522026-11-04 20:13:33.639 UTC [686] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9532026-11-04 20:13:33.639 UTC [686] ERROR: could not obtain lock on row in relation "closures"9542026-11-04 20:13:33.639 UTC [686] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9552026-11-04 20:13:33.640 UTC [686] ERROR: could not obtain lock on row in relation "closures"9562026-11-04 20:13:33.640 UTC [686] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9572026/11/04 20:13:33 INFO Received uploads request method=POST path=/api/pending_closures958--- PASS: TestPush_RootsAreLockedInByteOrder (0.55s)959=== CONT TestReadProxyNarinfoAlreadyDecompressed960--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.57s)961=== CONT TestReadRedirectKeepsNarinfoProxied9622026/11/04 20:13:33 INFO Received uploads request method=POST path=/api/pending_closures9632026/11/04 20:13:33 INFO Received uploads request method=POST path=/api/pending_closures9642026/11/04 20:13:33 INFO Received uploads request method=POST path=/api/pending_closures9652026/11/04 20:13:33 INFO Received uploads request method=POST path=/api/pending_closures9662026/11/04 20:13:33 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9672026/11/04 20:13:33 INFO Received uploads request method=POST path=/api/pending_closures968--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.61s)969=== CONT TestReadRedirectNar9702026/11/04 20:13:33 INFO Received uploads request method=POST path=/api/pending_closures971--- PASS: TestService_Rustfstest (0.65s)972=== CONT TestReadProxyNarinfo9732026/11/04 20:13:33 INFO Received uploads request method=POST path=/api/pending_closures9742026/11/04 20:13:33 INFO Received uploads request method=POST path=/api/pending_closures9752026/11/04 20:13:33 INFO Received uploads request method=POST path=/api/pending_closures9762026/11/04 20:13:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9772026/11/04 20:13:33 INFO Received push request method=POST path=/api/pushes9782026/11/04 20:13:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9792026/11/04 20:13:33 INFO Signed narinfos id=1 count=19802026/11/04 20:13:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9812026/11/04 20:13:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9822026/11/04 20:13:33 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"9832026/11/04 20:13:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9842026/11/04 20:13:33 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"9852026/11/04 20:13:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9862026/11/04 20:13:33 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=19872026/11/04 20:13:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9882026/11/04 20:13:33 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo989--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.74s)990=== CONT TestReadProxyDisabled9912026/11/04 20:13:33 INFO Received uploads request method=POST path=/api/pending_closures9922026/11/04 20:13:33 INFO Received push request method=POST path=/api/pushes9932026/11/04 20:13:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9942026/11/04 20:13:33 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MDM0ZTMzNGEtZThjYi00YzllLTgwNjItZWNkYzE4ODNlZjkzLmQwMzczYzAzLTY5YTgtNGMzYy05ZTY5LTllMzc1YzE5ODQ0YngxNzkzODIzMjEzODc1MzY5MjQy9952026/11/04 20:13:33 INFO Received complete push request method=POST path=/api/pushes/1/complete9962026/11/04 20:13:33 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MDM0ZTMzNGEtZThjYi00YzllLTgwNjItZWNkYzE4ODNlZjkzLmQwMzczYzAzLTY5YTgtNGMzYy05ZTY5LTllMzc1YzE5ODQ0YngxNzkzODIzMjEzODc1MzY5MjQy parts=1997=== RUN TestPush_RejectsBadRequests/bad_root998=== PAUSE TestPush_RejectsBadRequests/bad_root999=== RUN TestPush_RejectsBadRequests/root_not_in_objects1000=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1001=== RUN TestPush_RejectsBadRequests/no_roots1002=== PAUSE TestPush_RejectsBadRequests/no_roots1003=== RUN TestPush_RejectsBadRequests/no_objects1004=== PAUSE TestPush_RejectsBadRequests/no_objects1005=== CONT TestIsValidCachePath1006=== RUN TestIsValidCachePath/narinfo1007=== PAUSE TestIsValidCachePath/narinfo1008=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1009=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1010=== RUN TestIsValidCachePath/nar_zst1011=== PAUSE TestIsValidCachePath/nar_zst1012=== RUN TestIsValidCachePath/nar_xz1013=== PAUSE TestIsValidCachePath/nar_xz1014=== RUN TestIsValidCachePath/nar_bz21015=== PAUSE TestIsValidCachePath/nar_bz21016=== RUN TestIsValidCachePath/nar_uncompressed1017=== PAUSE TestIsValidCachePath/nar_uncompressed1018=== RUN TestIsValidCachePath/ls1019=== PAUSE TestIsValidCachePath/ls1020=== RUN TestIsValidCachePath/log1021=== PAUSE TestIsValidCachePath/log1022=== RUN TestIsValidCachePath/realisation1023=== PAUSE TestIsValidCachePath/realisation1024=== RUN TestIsValidCachePath/nix-cache-info1025=== PAUSE TestIsValidCachePath/nix-cache-info1026--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.81s)1027=== CONT TestReadProxyRootRedirectsToIndexHTML1028=== RUN TestIsValidCachePath/index.html1029=== PAUSE TestIsValidCachePath/index.html1030=== RUN TestIsValidCachePath/traversal_parent1031=== PAUSE TestIsValidCachePath/traversal_parent1032=== RUN TestIsValidCachePath/traversal_in_middle1033=== PAUSE TestIsValidCachePath/traversal_in_middle1034=== RUN TestIsValidCachePath/invalid_char_e1035=== PAUSE TestIsValidCachePath/invalid_char_e1036=== RUN TestIsValidCachePath/invalid_char_u1037=== PAUSE TestIsValidCachePath/invalid_char_u1038=== RUN TestIsValidCachePath/random_path1039=== PAUSE TestIsValidCachePath/random_path1040=== RUN TestIsValidCachePath/empty1041=== PAUSE TestIsValidCachePath/empty1042=== RUN TestIsValidCachePath/leading_slash1043=== PAUSE TestIsValidCachePath/leading_slash1044=== RUN TestIsValidCachePath/wrong_extension1045=== PAUSE TestIsValidCachePath/wrong_extension1046=== RUN TestIsValidCachePath/short_hash1047=== PAUSE TestIsValidCachePath/short_hash1048=== CONT TestReadProxyConditionalGet10492026/11/04 20:13:33 INFO Completed push id=1 objects=4 duration=7.860596ms10502026/11/04 20:13:33 INFO Received push request method=POST path=/api/pushes10512026/11/04 20:13:33 INFO Received push request method=POST path=/api/pushes10522026/11/04 20:13:33 INFO Received complete push request method=POST path=/api/pushes/1/complete10532026/11/04 20:13:33 INFO Received push request method=POST path=/api/pushes10542026/11/04 20:13:33 INFO Completed push id=1 objects=6 duration=9.814965ms1055--- PASS: TestPush_CompleteCommitsEveryRoot (0.79s)1056=== CONT TestParseSingleRange1057=== RUN TestParseSingleRange/none1058=== PAUSE TestParseSingleRange/none1059=== RUN TestParseSingleRange/unknown_unit1060=== PAUSE TestParseSingleRange/unknown_unit1061=== RUN TestParseSingleRange/multi-range_ignored1062=== PAUSE TestParseSingleRange/multi-range_ignored1063=== RUN TestParseSingleRange/malformed_no_dash1064=== PAUSE TestParseSingleRange/malformed_no_dash1065=== RUN TestParseSingleRange/malformed_both_empty1066=== PAUSE TestParseSingleRange/malformed_both_empty1067=== RUN TestParseSingleRange/malformed_end_before_start1068=== PAUSE TestParseSingleRange/malformed_end_before_start1069=== RUN TestParseSingleRange/closed1070=== PAUSE TestParseSingleRange/closed1071=== RUN TestParseSingleRange/open-ended1072=== PAUSE TestParseSingleRange/open-ended1073=== RUN TestParseSingleRange/end_clamped_to_size1074=== PAUSE TestParseSingleRange/end_clamped_to_size1075=== RUN TestParseSingleRange/suffix1076=== PAUSE TestParseSingleRange/suffix1077=== RUN TestParseSingleRange/suffix_exceeds_size1078=== PAUSE TestParseSingleRange/suffix_exceeds_size1079=== RUN TestParseSingleRange/single_byte1080=== PAUSE TestParseSingleRange/single_byte1081=== RUN TestParseSingleRange/start_past_EOF1082=== PAUSE TestParseSingleRange/start_past_EOF1083=== RUN TestParseSingleRange/start_far_past_EOF1084=== PAUSE TestParseSingleRange/start_far_past_EOF1085=== CONT TestReadProxyOutlastsServerWriteTimeout10862026/11/04 20:13:33 INFO Aborted multipart uploads count=0 kept=010872026/11/04 20:13:33 WARN Force mode enabled - objects will be deleted immediately without grace period10882026/11/04 20:13:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10892026/11/04 20:13:34 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=010902026/11/04 20:13:34 INFO Vacuumed table table=pending_closures10912026/11/04 20:13:34 INFO Received push request method=POST path=/api/pushes10922026/11/04 20:13:34 INFO Vacuumed table table=pending_objects10932026/11/04 20:13:34 INFO Vacuumed table table=multipart_uploads10942026/11/04 20:13:34 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MDM0ZTMzNGEtZThjYi00YzllLTgwNjItZWNkYzE4ODNlZjkzLjZjZmQyNzkyLTE3NzYtNDQzNS1iZGU0LTU2Nzg1NGE2NjgwYXgxNzkzODIzMjEzNTczNjg2NDQ2 parts=1010952026/11/04 20:13:34 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10962026/11/04 20:13:34 INFO Vacuumed table table=closures10972026/11/04 20:13:34 INFO Completed upload id=1 objects=2 duration=3.020769ms10982026/11/04 20:13:34 INFO Vacuumed table table=objects10992026/11/04 20:13:34 INFO Received uploads request method=POST path=/api/pending_closures11002026/11/04 20:13:34 INFO Received complete push request method=POST path=/api/pushes/2/complete11012026/11/04 20:13:34 INFO Received uploads request method=POST path=/api/pending_closures11022026/11/04 20:13:34 INFO Completed push id=2 objects=4 duration=5.292507ms1103--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.94s)1104=== CONT TestPresentNotReportedWhileGCDeletesClosure1105=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1106=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1107=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1108=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1109=== CONT TestNARDeduplicationMetadataUploadBug11102026/11/04 20:13:34 INFO Received complete push request method=POST path=/api/pushes/1/complete11112026/11/04 20:13:34 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo11122026/11/04 20:13:34 WARN Found objects in DB but missing from S3, will re-upload count=11113--- PASS: TestService_verifyS3Integrity (0.96s)1114=== CONT TestCreatePendingClosureRejectsOversizedNAR11152026/11/04 20:13:34 INFO Received uploads request method=POST path=/api/pending_closures1116--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1117=== CONT TestPresentRefreshesOnlyStaleClosures1118--- PASS: TestReadProxyInvalidPath (0.87s)1119=== CONT TestCacheConfigHandlerMaxNarSize1120--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1121=== CONT TestPresentReportsOnlyClosureRoots11222026/11/04 20:13:34 INFO Completed push id=1 objects=4 duration=9.484385ms1123--- PASS: TestPush_RepeatedRootCommitsOnce (0.87s)1124=== CONT TestGenerateLandingPage1125--- PASS: TestGenerateLandingPage (0.00s)1126=== CONT TestCreatePin_ReservedPins1127--- PASS: TestReadProxy404 (0.88s)1128=== CONT TestService_readinessHandler11292026/11/04 20:13:34 INFO Received push request method=POST path=/api/pushes11302026/11/04 20:13:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36577/oidc11312026/11/04 20:13:34 INFO Aborted multipart uploads count=0 kept=011322026/11/04 20:13:34 WARN Force mode enabled - objects will be deleted immediately without grace period11332026/11/04 20:13:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11342026/11/04 20:13:34 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=011352026/11/04 20:13:34 INFO Vacuumed table table=pending_closures11362026/11/04 20:13:34 INFO Vacuumed table table=pending_objects11372026/11/04 20:13:34 INFO Vacuumed table table=multipart_uploads11382026/11/04 20:13:34 INFO Vacuumed table table=closures11392026/11/04 20:13:34 INFO Vacuumed table table=objects1140--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.90s)1141=== CONT TestOrphanedObjectsGCStressTest1142--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.97s)1143=== CONT TestService_healthCheckHandler1144--- PASS: TestReadRedirectUsesPublicS3URL (0.66s)1145=== CONT TestOrphanedObjectsGC11462026/11/04 20:13:34 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MDM0ZTMzNGEtZThjYi00YzllLTgwNjItZWNkYzE4ODNlZjkzLjQzNGUzN2ZkLWZmMjMtNDA4Yy1iNjAxLTgxNTg2YzY4ZThhY3gxNzkzODIzMjEzNzAzMDA0NzU1 parts=1011472026/11/04 20:13:34 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11482026/11/04 20:13:34 INFO Completed upload id=1 objects=2 duration=5.348227ms11492026/11/04 20:13:34 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011502026/11/04 20:13:34 INFO Received uploads request method=POST path=/api/pending_closures11512026/11/04 20:13:34 INFO Starting cleanup of old closures method=DELETE path=/api/closures11522026/11/04 20:13:34 INFO Aborted multipart uploads count=0 kept=01153--- PASS: TestReadProxyNarStreaming (0.66s)1154=== CONT TestGracefulShutdownDrainsInflight11552026/11/04 20:13:34 INFO Starting HTTP server address=127.0.0.1:4305511562026/11/04 20:13:34 INFO Shutdown signal received, draining in-flight requests timeout=10s11572026/11/04 20:13:34 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=011582026/11/04 20:13:34 INFO Vacuumed table table=pending_closures11592026/11/04 20:13:34 INFO Vacuumed table table=pending_objects11602026/11/04 20:13:34 INFO Vacuumed table table=multipart_uploads11612026/11/04 20:13:34 INFO Vacuumed table table=closures11622026/11/04 20:13:34 INFO Vacuumed table table=objects1163--- PASS: TestReadProxyRangeRequest (0.65s)1164=== CONT TestObjectStatsUpdatedOncePerCommit1165--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1166=== CONT TestObjectStatsTrigger11672026/11/04 20:13:34 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001168--- PASS: TestService_createPendingClosureHandler (1.19s)1169=== CONT TestPendingCleanupUsesOneCutoff1170--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.65s)1171=== CONT TestGCTaskStore_Fail1172--- PASS: TestGCTaskStore_Fail (0.00s)1173=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded11742026-11-04 20:13:34.297 UTC [719] ERROR: Push does not exist: id=111752026-11-04 20:13:34.297 UTC [719] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE11762026-11-04 20:13:34.297 UTC [719] STATEMENT: SELECT commit_push($1)1177--- PASS: TestReadProxyContentNegotiation (0.75s)1178=== CONT TestGCTaskStore_CompletedAllowsNewTask1179=== CONT TestMultipartCleanup1180=== CONT TestGCTaskStore_PhaseUpdates1181=== CONT TestGCTaskStore_GetReturnsLatest1182=== CONT TestServerTLSConfig1183=== RUN TestServerTLSConfig/no_client_CA1184=== PAUSE TestServerTLSConfig/no_client_CA1185=== RUN TestServerTLSConfig/missing_CA_file1186=== PAUSE TestServerTLSConfig/missing_CA_file1187=== RUN TestServerTLSConfig/not_a_PEM_file1188=== PAUSE TestServerTLSConfig/not_a_PEM_file1189--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (1.11s)1190--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1191--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1192--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1193=== CONT TestGCTaskStore_GetEmpty1194--- PASS: TestGCTaskStore_GetEmpty (0.00s)1195=== CONT TestService_NativeMTLS1196--- PASS: TestReadRedirectKeepsNarinfoProxied (0.67s)1197=== CONT TestGCTaskStore_ConflictDifferentParams1198--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1199=== CONT TestMetricsCommit12002026/11/04 20:13:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12012026/11/04 20:13:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1202--- PASS: TestReadRedirectNar (0.65s)1203=== CONT TestGCTaskStore_DeduplicateSameParams1204--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1205=== CONT TestMetricsInventory12062026/11/04 20:13:34 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MDM0ZTMzNGEtZThjYi00YzllLTgwNjItZWNkYzE4ODNlZjkzLjY2MjJjMDFmLTFlOGMtNGQzOC04N2RlLTE4YzJkZTA2OWQ1ZngxNzkzODIzMjEzNzkwMTQ3NDU4 parts=1212072026/11/04 20:13:34 INFO Received uploads request method=POST path=/api/pending_closures12082026/11/04 20:13:34 INFO Received uploads request method=POST path=/api/pending_closures12092026/11/04 20:13:34 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MDM0ZTMzNGEtZThjYi00YzllLTgwNjItZWNkYzE4ODNlZjkzLjljMDZhMmM0LTc3NzMtNDk1Yy1iZWQ5LTIyZDJiZWM5ODY1NHgxNzkzODIzMjEzODIwMDc2Mjky parts=1212102026/11/04 20:13:34 INFO Received uploads request method=POST path=/api/pending_closures1211--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.30s)1212=== CONT TestGCTaskStore_StartNew1213--- PASS: TestGCTaskStore_StartNew (0.00s)1214=== CONT TestGCEndsOnShutdown1215=== RUN TestGCEndsOnShutdown/before_the_run1216=== PAUSE TestGCEndsOnShutdown/before_the_run1217=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1218=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1219=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1220=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1221=== CONT TestConnectWaitsForAPeerMigration1222--- PASS: TestReadProxyDisabled (0.55s)1223=== CONT TestTombstonedObjectOfferedWithoutWaiting1224--- PASS: TestReadProxyConditionalGet (0.55s)1225=== CONT TestPushWaitsForSweepHoldingRow12262026/11/04 20:13:34 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1227--- PASS: TestReadProxyNarinfo (0.75s)1228=== CONT TestGCSweepSkipsPendingObjects1229--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.58s)1230=== CONT TestSweepRechecksPendingAfterLocking1231=== NAME TestNARDeduplicationMetadataUploadBug1232 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug3973730528/001/store/8d2wk96ks6k62j9zl5m2h3cmnyw9yj8q-file1.txt1233--- PASS: TestPresentRefreshesOnlyStaleClosures (0.58s)1234=== CONT TestDeduplicatedObjectsRecordedAsPending1235--- PASS: TestPresentReportsOnlyClosureRoots (0.63s)1236=== CONT TestGetExistingObjectsLocksRows12372026/11/04 20:13:34 WARN readiness check failed error="closed pool"1238--- PASS: TestService_readinessHandler (0.63s)1239=== CONT TestRegisterCompletedObjectNeedsPendingRow12402026/11/04 20:13:34 INFO Received push request method=POST path=/api/pushes12412026/11/04 20:13:34 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12422026/11/04 20:13:34 INFO Uploading 8d2wk96ks6k62j9zl5m2h3cmnyw9yj8q-file1.txt (160B)12432026/11/04 20:13:34 WARN Failed to register uploaded object key=8d2wk96ks6k62j9zl5m2h3cmnyw9yj8q.ls error="server returned 404: 404 page not found\n"12442026/11/04 20:13:34 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12452026/11/04 20:13:34 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12462026/11/04 20:13:34 INFO Signed narinfos id=1 count=112472026/11/04 20:13:34 INFO Uploading 1 narinfos12482026/11/04 20:13:34 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12492026/11/04 20:13:34 WARN Refused reserved pin name=worker-x86_64-linux12502026/11/04 20:13:34 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12512026/11/04 20:13:34 INFO Received create pin request method=POST path=/api/pins/my-app12522026/11/04 20:13:34 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1253--- PASS: TestCreatePin_ReservedPins (0.67s)1254=== CONT TestPushDedupSurvivesConcurrentGC12552026/11/04 20:13:34 INFO Received complete push request method=POST path=/api/pushes/1/complete12562026/11/04 20:13:34 WARN Failed to register uploaded object key=8d2wk96ks6k62j9zl5m2h3cmnyw9yj8q.narinfo error="server returned 404: 404 page not found\n"12572026/11/04 20:13:34 INFO Completed push id=1 objects=3 duration=9.584435ms12582026/11/04 20:13:34 INFO Upload complete. (84ms)1259=== NAME TestNARDeduplicationMetadataUploadBug1260 metadata_upload_test.go:54: Retrieved narinfo from S3:1261 StorePath: /build/TestNARDeduplicationMetadataUploadBug3973730528/001/store/8d2wk96ks6k62j9zl5m2h3cmnyw9yj8q-file1.txt1262 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1263 Compression: zstd1264 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1265 NarSize: 1601266 References: 1267 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1268 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1269 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1270 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1271--- PASS: TestService_healthCheckHandler (0.61s)1272=== CONT TestGCMetrics1273=== NAME TestNARDeduplicationMetadataUploadBug1274 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug3973730528/001/store/rhag3rf9s0ps34cayzjlij460102p394-file2.txt12752026/11/04 20:13:34 INFO Received push request method=POST path=/api/pushes12762026/11/04 20:13:34 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12772026/11/04 20:13:34 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12782026/11/04 20:13:34 INFO Signed narinfos id=2 count=112792026/11/04 20:13:34 WARN Failed to register uploaded object key=rhag3rf9s0ps34cayzjlij460102p394.ls error="server returned 404: 404 page not found\n"12802026/11/04 20:13:34 INFO Uploading 1 narinfos1281--- PASS: TestObjectStatsTrigger (0.61s)1282=== CONT TestSweepSkipsRowsLockedByPush12832026/11/04 20:13:34 INFO Received complete push request method=POST path=/api/pushes/2/complete12842026/11/04 20:13:34 WARN Failed to register uploaded object key=rhag3rf9s0ps34cayzjlij460102p394.narinfo error="server returned 404: 404 page not found\n"1285--- PASS: TestObjectStatsUpdatedOncePerCommit (0.62s)1286=== CONT TestFailedS3DeleteKeepsTombstone12872026/11/04 20:13:34 INFO Completed push id=2 objects=3 duration=1.983129ms12882026/11/04 20:13:34 INFO Upload complete. (59ms)12892026/11/04 20:13:34 INFO Received uploads request method=POST path=/api/pending_closures1290=== NAME TestNARDeduplicationMetadataUploadBug1291 metadata_upload_test.go:76: Retrieved narinfo from S3:1292 StorePath: /build/TestNARDeduplicationMetadataUploadBug3973730528/001/store/rhag3rf9s0ps34cayzjlij460102p394-file2.txt1293 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1294 Compression: zstd1295 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1296 NarSize: 1601297 References: 1298 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1299 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1300 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1301 {"version":1,"root":{"type":"regular","size":44}}1302--- PASS: TestNARDeduplicationMetadataUploadBug (0.85s)1303=== CONT TestGCBugBareHashReferences13042026/11/04 20:13:34 INFO Received uploads request method=POST path=/api/pending_closures13052026/11/04 20:13:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13062026/11/04 20:13:34 INFO Received cleanup request method=DELETE path=/api/pending_closures13072026/11/04 20:13:34 WARN mTLS auth: subject not in bound subjects subject="CN=reader"13082026/11/04 20:13:34 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1309--- PASS: TestService_NativeMTLS (0.62s)1310=== CONT TestForceGCDuringPushOffersSweptObject1311=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1312=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1313=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1314=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1315=== CONT TestGCAdvisoryLockBlocksConcurrentRun13162026/11/04 20:13:34 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MDM0ZTMzNGEtZThjYi00YzllLTgwNjItZWNkYzE4ODNlZjkzLjZiMWEyZWU2LWE0NGEtNDE3Yy04OWNjLThkYTJmODdiNzYzN3gxNzkzODIzMjE0MzgyMTMzMzM2 error="Get \"http://127.0.0.1:1/bucket15/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"13172026/11/04 20:13:34 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MDM0ZTMzNGEtZThjYi00YzllLTgwNjItZWNkYzE4ODNlZjkzLjliN2IzMTRmLWRhMjYtNDM5MC05YzFhLThkZTJhNzk3YzVhMngxNzkzODIzMjE0MzcyOTM0MzEx parts=1213182026/11/04 20:13:34 INFO Received cleanup request method=DELETE path=/api/pending_closures13192026/11/04 20:13:34 INFO Aborted multipart uploads count=1 kept=013202026/11/04 20:13:34 INFO Received uploads request method=POST path=/api/pending_closures1321--- PASS: TestRedundantMultipartUpload (1.85s)1322=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection13232026/11/04 20:13:34 INFO Received uploads request method=POST path=/api/pending_closures1324--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.70s)1325=== CONT TestGCSweepDeliversEachKeyOnce13262026/11/04 20:13:35 INFO Received push request method=POST path=/api/pushes13272026/11/04 20:13:35 INFO Received complete push request method=POST path=/api/pushes/1/complete13282026/11/04 20:13:35 INFO Completed push id=1 objects=4 duration=19.791469ms13292026/11/04 20:13:35 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13302026/11/04 20:13:35 INFO Completed upload id=2 objects=2 duration=1.591289ms1331--- PASS: TestMetricsCommit (0.73s)1332=== CONT TestLeadEndsOnShutdown13332026/11/04 20:13:35 INFO Received uploads request method=POST path=/api/pending_closures1334--- PASS: TestMetricsInventory (0.71s)1335=== CONT TestClientIntegration13362026/11/04 20:13:35 INFO Received cleanup request method=DELETE path=/api/pending_closures1337--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.67s)1338=== CONT TestLeadIncumbentAnnouncesAtOnce13392026/11/04 20:13:35 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket52/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""13402026/11/04 20:13:35 INFO Aborted multipart uploads count=0 kept=113412026/11/04 20:13:35 INFO Received cleanup request method=DELETE path=/api/pending_closures13422026/11/04 20:13:35 INFO Aborted multipart uploads count=1 kept=01343--- PASS: TestMultipartCleanup (0.80s)1344=== CONT TestResolveDBConnectionString1345=== RUN TestResolveDBConnectionString/flag_wins1346=== PAUSE TestResolveDBConnectionString/flag_wins1347=== RUN TestResolveDBConnectionString/file_when_flag_empty1348=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1349=== RUN TestResolveDBConnectionString/missing_file_is_an_error1350=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1351=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1352=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1353=== RUN TestResolveDBConnectionString/nothing_configured1354=== PAUSE TestResolveDBConnectionString/nothing_configured1355=== CONT TestLeadElectsOneAndHandsOver13562026/11/04 20:13:35 INFO Received uploads request method=POST path=/api/pending_closures13572026/11/04 20:13:35 INFO Received uploads request method=POST path=/api/pending_closures13582026/11/04 20:13:35 INFO Aborted multipart uploads count=0 kept=013592026/11/04 20:13:35 WARN Force mode enabled - objects will be deleted immediately without grace period13602026/11/04 20:13:35 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=013612026/11/04 20:13:35 INFO Vacuumed table table=pending_closures13622026/11/04 20:13:35 INFO Vacuumed table table=pending_objects13632026/11/04 20:13:35 INFO Vacuumed table table=multipart_uploads13642026/11/04 20:13:35 INFO Vacuumed table table=closures13652026/11/04 20:13:35 INFO Vacuumed table table=objects13662026/11/04 20:13:35 INFO Aborted multipart uploads count=0 kept=01367--- PASS: TestGCSweepSkipsPendingObjects (0.69s)1368=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock13692026/11/04 20:13:35 WARN Force mode enabled - objects will be deleted immediately without grace period1370=== NAME TestOrphanedObjectsGC1371 orphaned_objects_gc_test.go:287: GC Test Summary:1372 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1373 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1374 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1375 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1376 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1377--- PASS: TestOrphanedObjectsGC (1.04s)1378=== CONT TestDeleteClosuresRacingPins13792026/11/04 20:13:35 INFO Received uploads request method=POST path=/api/pending_closures1380--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.58s)1381=== CONT TestClientFallsBackToClosures13822026/11/04 20:13:35 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=013832026/11/04 20:13:35 INFO Vacuumed table table=pending_closures13842026/11/04 20:13:35 INFO Vacuumed table table=pending_objects13852026/11/04 20:13:35 INFO Vacuumed table table=multipart_uploads13862026/11/04 20:13:35 INFO Vacuumed table table=closures13872026/11/04 20:13:35 INFO Vacuumed table table=objects1388--- PASS: TestSweepRechecksPendingAfterLocking (0.72s)1389=== CONT TestService_ReadScope_PublicByDefault1390--- PASS: TestGetExistingObjectsLocksRows (0.56s)1391=== CONT TestClientPushesUseOnePush1392--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.57s)1393=== CONT TestClientErrorHandling1394=== RUN TestClientErrorHandling/InvalidStorePath1395=== PAUSE TestClientErrorHandling/InvalidStorePath1396=== RUN TestClientErrorHandling/InvalidAuthToken1397=== PAUSE TestClientErrorHandling/InvalidAuthToken1398=== RUN TestClientErrorHandling/ServerNotAvailable1399=== PAUSE TestClientErrorHandling/ServerNotAvailable1400=== CONT TestPinProtectsFromGC14012026/11/04 20:13:35 INFO Received uploads request method=POST path=/api/pending_closures14022026/11/04 20:13:35 INFO Aborted multipart uploads count=0 kept=014032026/11/04 20:13:35 WARN Force mode enabled - objects will be deleted immediately without grace period14042026/11/04 20:13:35 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=014052026/11/04 20:13:35 INFO Vacuumed table table=pending_closures14062026/11/04 20:13:35 INFO Vacuumed table table=pending_objects14072026/11/04 20:13:35 INFO Vacuumed table table=multipart_uploads14082026/11/04 20:13:35 INFO Vacuumed table table=closures14092026/11/04 20:13:35 INFO Vacuumed table table=objects1410--- PASS: TestGCMetrics (0.58s)1411=== CONT TestClientCADerivations14122026/11/04 20:13:35 INFO Aborted multipart uploads count=0 kept=014132026/11/04 20:13:35 INFO Received uploads request method=POST path=/api/pending_closures14142026/11/04 20:13:35 WARN Force mode enabled - objects will be deleted immediately without grace period14152026/11/04 20:13:35 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=014162026/11/04 20:13:35 INFO Vacuumed table table=pending_closures14172026/11/04 20:13:35 INFO Vacuumed table table=pending_objects14182026/11/04 20:13:35 INFO Vacuumed table table=multipart_uploads14192026/11/04 20:13:35 INFO Vacuumed table table=closures14202026/11/04 20:13:35 INFO Vacuumed table table=objects14212026/11/04 20:13:35 INFO Aborted multipart uploads count=0 kept=014222026/11/04 20:13:35 INFO Aborted multipart uploads count=0 kept=014232026/11/04 20:13:35 WARN Force mode enabled - objects will be deleted immediately without grace period14242026/11/04 20:13:35 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=014252026/11/04 20:13:35 INFO Vacuumed table table=pending_closures14262026/11/04 20:13:35 INFO Vacuumed table table=pending_objects14272026/11/04 20:13:35 INFO Vacuumed table table=multipart_uploads14282026/11/04 20:13:35 INFO Vacuumed table table=closures14292026/11/04 20:13:35 INFO Vacuumed table table=objects14302026/11/04 20:13:35 INFO Aborted multipart uploads count=0 kept=014312026/11/04 20:13:35 WARN Force mode enabled - objects will be deleted immediately without grace period14322026/11/04 20:13:35 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=014332026/11/04 20:13:35 INFO Vacuumed table table=pending_closures14342026/11/04 20:13:35 INFO Vacuumed table table=pending_objects14352026/11/04 20:13:35 INFO Vacuumed table table=multipart_uploads14362026/11/04 20:13:35 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=014372026/11/04 20:13:35 INFO Vacuumed table table=pending_closures14382026/11/04 20:13:35 INFO Vacuumed table table=pending_objects14392026/11/04 20:13:35 INFO Vacuumed table table=multipart_uploads14402026/11/04 20:13:35 INFO Vacuumed table table=closures14412026/11/04 20:13:35 INFO Vacuumed table table=closures14422026/11/04 20:13:35 INFO Vacuumed table table=objects14432026/11/04 20:13:35 INFO Vacuumed table table=objects1444--- PASS: TestPushDedupSurvivesConcurrentGC (0.72s)1445=== CONT TestClientSharedPathCommittedMidPush1446--- PASS: TestSweepSkipsRowsLockedByPush (0.57s)1447=== CONT TestClientWithDependencies14482026/11/04 20:13:35 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"1449--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.55s)1450=== CONT TestCacheStatsHandler14512026/11/04 20:13:35 INFO Aborted multipart uploads count=0 kept=014522026/11/04 20:13:35 WARN Force mode enabled - objects will be deleted immediately without grace period14532026/11/04 20:13:35 INFO Received uploads request method=POST path=/api/pending_closures14542026/11/04 20:13:35 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."14552026/11/04 20:13:35 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1456--- PASS: TestFailedS3DeleteKeepsTombstone (0.62s)1457=== CONT TestClientMultipleUploads14582026/11/04 20:13:35 INFO lead: acquired remote=192.0.2.1:123414592026/11/04 20:13:35 INFO Aborted multipart uploads count=0 kept=014602026/11/04 20:13:35 WARN Force mode enabled - objects will be deleted immediately without grace period1461--- PASS: TestPushWaitsForSweepHoldingRow (1.13s)1462=== CONT TestCacheConfigHandler1463=== RUN TestCacheConfigHandler/full_config,_no_issuer1464=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1465=== RUN TestCacheConfigHandler/no_cache_url_configured1466=== PAUSE TestCacheConfigHandler/no_cache_url_configured1467=== RUN TestCacheConfigHandler/no_signing_keys1468=== PAUSE TestCacheConfigHandler/no_signing_keys1469=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1470=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1471=== CONT TestService_ReadAuthMiddleware14722026/11/04 20:13:35 INFO lead: acquired remote=192.0.2.1:123414732026/11/04 20:13:35 INFO lead: released remote=192.0.2.1:12341474--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.53s)1475=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14762026/11/04 20:13:35 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=014772026/11/04 20:13:35 INFO Vacuumed table table=pending_closures14782026/11/04 20:13:35 INFO Vacuumed table table=pending_objects14792026/11/04 20:13:35 INFO Vacuumed table table=multipart_uploads14802026/11/04 20:13:35 INFO Vacuumed table table=closures14812026/11/04 20:13:35 INFO Vacuumed table table=objects1482--- PASS: TestGCSweepDeliversEachKeyOnce (0.62s)1483=== CONT TestService_RequireScope_OIDC1484=== NAME TestClientIntegration1485 client_integration_test.go:291: Created store path: /build/TestClientIntegration3707082849/002/store/i8v5nf0q3dfsfx3pnpjdmfzpabcn2kh5-test-file.txt14862026/11/04 20:13:35 INFO lead: acquired remote=192.0.2.1:12341487--- PASS: TestGCBugBareHashReferences (0.77s)1488=== CONT TestService_AuthMiddleware_OIDC14892026/11/04 20:13:35 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43225/oidc1490--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.74s)1491=== CONT TestService_AuthMiddleware_MTLSProxyHeader14922026/11/04 20:13:35 INFO Received push request method=POST path=/api/pushes14932026/11/04 20:13:35 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14942026/11/04 20:13:35 INFO Uploading i8v5nf0q3dfsfx3pnpjdmfzpabcn2kh5-test-file.txt (152B)14952026/11/04 20:13:35 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"14962026/11/04 20:13:35 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14972026/11/04 20:13:35 WARN Failed to register uploaded object key=i8v5nf0q3dfsfx3pnpjdmfzpabcn2kh5.ls error="server returned 404: 404 page not found\n"14982026/11/04 20:13:35 INFO Signed narinfos id=1 count=114992026/11/04 20:13:35 INFO Uploading 1 narinfos15002026/11/04 20:13:35 INFO Received complete push request method=POST path=/api/pushes/1/complete15012026/11/04 20:13:35 WARN Failed to register uploaded object key=i8v5nf0q3dfsfx3pnpjdmfzpabcn2kh5.narinfo error="server returned 404: 404 page not found\n"15022026/11/04 20:13:35 INFO Completed push id=1 objects=3 duration=11.638523ms15032026/11/04 20:13:35 INFO Upload complete. (82ms)1504--- PASS: TestService_ReadScope_PublicByDefault (0.53s)1505=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15062026/11/04 20:13:35 INFO Received uploads request method=POST path=/1507=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15082026/11/04 20:13:35 INFO Received complete multipart upload request method=POST path=/1509=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15102026/11/04 20:13:35 INFO Received request for more parts method=POST path=/1511=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15122026/11/04 20:13:35 INFO Received uploads request method=POST path=/1513--- PASS: TestUploadHandlersRejectInvalidKeys (0.09s)1514 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1515 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1516 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1517 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1518=== CONT TestPendingClosureWriteTimeout/empty1519=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline15202026/11/04 20:13:35 INFO All 1 paths already cached1521=== NAME TestClientIntegration1522 client_integration_test.go:317: Retrieved narinfo from S3:1523 StorePath: /build/TestClientIntegration3707082849/002/store/i8v5nf0q3dfsfx3pnpjdmfzpabcn2kh5-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: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.68s)1534=== CONT TestPendingClosureWriteTimeout/670k_objects1535=== CONT TestPendingClosureWriteTimeout/400_objects1536=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed15372026/11/04 20:13:35 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41963/oidc15382026/11/04 20:13:35 INFO Received push request method=POST path=/api/pushes1539=== NAME TestPinProtectsFromGC1540 client_integration_test.go:778: Pinned store path: /build/TestPinProtectsFromGC1132506959/001/store/kv03jnlvlaaxk4q1x7zikimmg5z0qbdf-pinned-file.txt1541 client_integration_test.go:779: Unpinned store path: /build/TestPinProtectsFromGC1132506959/001/store/fp7k35dqxfynr32n23sa0a5w1ss8nmil-unpinned-file.txt15422026/11/04 20:13:35 INFO Object in database but missing from S3 key=i8v5nf0q3dfsfx3pnpjdmfzpabcn2kh5.ls15432026/11/04 20:13:35 WARN Found objects in DB but missing from S3, will re-upload count=115442026/11/04 20:13:35 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)15452026/11/04 20:13:35 INFO Received complete push request method=POST path=/api/pushes/2/complete15462026/11/04 20:13:35 WARN Failed to register uploaded object key=i8v5nf0q3dfsfx3pnpjdmfzpabcn2kh5.ls error="server returned 404: 404 page not found\n"15472026/11/04 20:13:35 INFO Completed push id=2 objects=3 duration=2.863699ms15482026/11/04 20:13:35 INFO Upload complete. (48ms)1549=== NAME TestClientIntegration1550 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1551 client_integration_test.go:335: Decompressed .ls content (49 bytes):1552 {"version":1,"root":{"type":"regular","size":39}}1553=== NAME TestClientCADerivations1554 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations3623203822/001/store/ackdkj53q3gl6f29cfs4h65xm1mnpkv6-ca-test1555--- PASS: TestCacheStatsHandler (0.48s)1556=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed15572026/11/04 20:13:35 INFO Received uploads request method=POST path=/api/pending_closures1558=== NAME TestClientCADerivations1559 client_ca_test.go:139: Found 1 dependencies (including self)15602026/11/04 20:13:35 INFO Received uploads request method=POST path=/api/pending_closures1561=== NAME TestClientWithDependencies1562 client_integration_test.go:660: Built derivation: /build/TestClientWithDependencies503992025/001/store/6br0nmmxjxrxdax82p6hslhxrqxsyi7h-test-script15632026/11/04 20:13:35 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15642026/11/04 20:13:35 INFO Uploading 44hw00g83rnhlr0fw7c9lkylsfz4ayn4-a (216B)15652026/11/04 20:13:35 INFO Uploading gnvfwqsyd75xp2qqa4znd3i383sj7fbf-shared-dep (136B)15662026/11/04 20:13:35 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15672026/11/04 20:13:35 WARN mTLS auth: bound subjects configured but subject DN unavailable15682026/11/04 20:13:35 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1569--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.37s)1570=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost15712026/11/04 20:13:35 WARN Failed to register uploaded object key=pk93l28ndgf65mccyabgbglsg405phki.ls error="server returned 404: 404 page not found\n"15722026/11/04 20:13:35 WARN Failed to register uploaded object key=gnvfwqsyd75xp2qqa4znd3i383sj7fbf.ls error="server returned 404: 404 page not found\n"15732026/11/04 20:13:35 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15742026/11/04 20:13:35 WARN Failed to register uploaded object key=nar/0yy21sci6dkqc9nj7g0iq1qjphr2m8rrkk9dilddyjzymlikd813.nar.zst error="server returned 404: 404 page not found\n"15752026/11/04 20:13:35 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15762026/11/04 20:13:35 WARN Failed to register uploaded object key=44hw00g83rnhlr0fw7c9lkylsfz4ayn4.ls error="server returned 404: 404 page not found\n"15772026/11/04 20:13:35 INFO Signed narinfos id=1 count=215782026/11/04 20:13:35 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15792026/11/04 20:13:35 INFO Signed narinfos id=2 count=215802026/11/04 20:13:35 INFO Uploading 4 narinfos15812026/11/04 20:13:35 INFO Received push request method=POST path=/api/pushes15822026/11/04 20:13:35 WARN Failed to register uploaded object key=gnvfwqsyd75xp2qqa4znd3i383sj7fbf.narinfo error="server returned 404: 404 page not found\n"15832026/11/04 20:13:35 WARN Failed to register uploaded object key=44hw00g83rnhlr0fw7c9lkylsfz4ayn4.narinfo error="server returned 404: 404 page not found\n"15842026/11/04 20:13:35 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15852026/11/04 20:13:35 INFO Uploading kv03jnlvlaaxk4q1x7zikimmg5z0qbdf-pinned-file.txt (128B)15862026/11/04 20:13:35 WARN Failed to register uploaded object key=pk93l28ndgf65mccyabgbglsg405phki.narinfo error="server returned 404: 404 page not found\n"15872026/11/04 20:13:35 INFO Received push request method=POST path=/api/pushes15882026/11/04 20:13:35 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15892026/11/04 20:13:35 WARN Failed to register uploaded object key=gnvfwqsyd75xp2qqa4znd3i383sj7fbf.narinfo error="server returned 404: 404 page not found\n"15902026/11/04 20:13:35 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15912026/11/04 20:13:35 INFO Uploading bwf8wh6d0pq1dk11riy19w8gna9x8ibi-a (216B)15922026/11/04 20:13:35 INFO Uploading wnxqvkjcpcabbmkbj0bj9h776ncvamdp-shared-dep (136B)15932026/11/04 20:13:35 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15942026/11/04 20:13:35 WARN Failed to register uploaded object key=kv03jnlvlaaxk4q1x7zikimmg5z0qbdf.ls error="server returned 404: 404 page not found\n"15952026/11/04 20:13:35 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"15962026/11/04 20:13:35 INFO Signed narinfos id=1 count=115972026/11/04 20:13:35 INFO Uploading 1 narinfos1598=== NAME TestClientMultipleUploads1599 client_integration_test.go:405: Created store path 0: /build/TestClientMultipleUploads606407016/001/store/57ndvfbm076y6f6fvqyqq9qd2zvynz0w-test-file-0.txt16002026/11/04 20:13:35 INFO Completed upload id=2 objects=6 duration=5.285287ms16012026/11/04 20:13:35 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1602--- PASS: TestService_ReadAuthMiddleware (0.39s)1603=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed16042026/11/04 20:13:35 WARN Failed to register uploaded object key=5nc3jkhc83d5l4z11ib6bwgbkpqlx29w.ls error="server returned 404: 404 page not found\n"16052026/11/04 20:13:35 INFO Completed upload id=1 objects=6 duration=2.641529ms16062026/11/04 20:13:35 INFO Upload complete. (78ms)16072026/11/04 20:13:35 WARN Failed to register uploaded object key=wnxqvkjcpcabbmkbj0bj9h776ncvamdp.ls error="server returned 404: 404 page not found\n"1608=== NAME TestClientFallsBackToClosures1609 client_pushes_test.go:112: Retrieved narinfo from S3:1610 StorePath: /build/TestClientFallsBackToClosures1397299629/001/store/gnvfwqsyd75xp2qqa4znd3i383sj7fbf-shared-dep1611 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1612 Compression: zstd1613 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821614 NarSize: 1361615 References: 1616 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n16172026/11/04 20:13:36 INFO Received complete push request method=POST path=/api/pushes/1/complete16182026/11/04 20:13:36 WARN Failed to register uploaded object key=nar/1np9vppiy6f8cadpm4kcg7zggm0gp1525cy8vgy4yw3wwq1djn5f.nar.zst error="server returned 404: 404 page not found\n"16192026/11/04 20:13:36 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16202026/11/04 20:13:36 WARN Failed to register uploaded object key=kv03jnlvlaaxk4q1x7zikimmg5z0qbdf.narinfo error="server returned 404: 404 page not found\n"16212026/11/04 20:13:36 WARN Failed to register uploaded object key=bwf8wh6d0pq1dk11riy19w8gna9x8ibi.ls error="server returned 404: 404 page not found\n"16222026/11/04 20:13:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16232026/11/04 20:13:36 INFO Signed narinfos id=1 count=316242026/11/04 20:13:36 INFO Uploading 3 narinfos1625 client_pushes_test.go:112: Retrieved narinfo from S3:1626 StorePath: /build/TestClientFallsBackToClosures1397299629/001/store/44hw00g83rnhlr0fw7c9lkylsfz4ayn4-a1627 URL: nar/0yy21sci6dkqc9nj7g0iq1qjphr2m8rrkk9dilddyjzymlikd813.nar.zst1628 Compression: zstd1629 NarHash: sha256:0yy21sci6dkqc9nj7g0iq1qjphr2m8rrkk9dilddyjzymlikd8131630 NarSize: 2161631 References: /build/TestClientFallsBackToClosures1397299629/001/store/gnvfwqsyd75xp2qqa4znd3i383sj7fbf-shared-dep1632 CA: text:sha256:18v3wa0m2g82slr7sax92w68gl04ci3nw3xmkzsi5lyhxa34n5f21633=== NAME TestClientWithDependencies1634 client_integration_test.go:662: Found 1 dependencies (including self)1635=== NAME TestClientFallsBackToClosures1636 client_pushes_test.go:112: Retrieved narinfo from S3:1637 StorePath: /build/TestClientFallsBackToClosures1397299629/001/store/pk93l28ndgf65mccyabgbglsg405phki-b1638 URL: nar/0yy21sci6dkqc9nj7g0iq1qjphr2m8rrkk9dilddyjzymlikd813.nar.zst1639 Compression: zstd1640 NarHash: sha256:0yy21sci6dkqc9nj7g0iq1qjphr2m8rrkk9dilddyjzymlikd8131641 NarSize: 2161642 References: /build/TestClientFallsBackToClosures1397299629/001/store/gnvfwqsyd75xp2qqa4znd3i383sj7fbf-shared-dep1643 CA: text:sha256:18v3wa0m2g82slr7sax92w68gl04ci3nw3xmkzsi5lyhxa34n5f216442026/11/04 20:13:36 WARN Failed to register uploaded object key=5nc3jkhc83d5l4z11ib6bwgbkpqlx29w.narinfo error="server returned 404: 404 page not found\n"16452026/11/04 20:13:36 WARN Failed to register uploaded object key=wnxqvkjcpcabbmkbj0bj9h776ncvamdp.narinfo error="server returned 404: 404 page not found\n"16462026/11/04 20:13:36 INFO Received complete push request method=POST path=/api/pushes/1/complete16472026/11/04 20:13:36 WARN Failed to register uploaded object key=bwf8wh6d0pq1dk11riy19w8gna9x8ibi.narinfo error="server returned 404: 404 page not found\n"1648--- PASS: TestClientFallsBackToClosures (0.80s)1649=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed16502026/11/04 20:13:36 INFO Completed push id=1 objects=3 duration=10.332724ms16512026/11/04 20:13:36 INFO Upload complete. (75ms)16522026/11/04 20:13:36 INFO Completed push id=1 objects=8 duration=5.525987ms16532026/11/04 20:13:36 INFO Upload complete. (68ms)1654=== NAME TestClientPushesUseOnePush1655 client_pushes_test.go:97: Retrieved narinfo from S3:1656 StorePath: /build/TestClientPushesUseOnePush3261527512/001/store/wnxqvkjcpcabbmkbj0bj9h776ncvamdp-shared-dep1657 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1658 Compression: zstd1659 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821660 NarSize: 1361661 References: 1662 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1663 client_pushes_test.go:97: Retrieved narinfo from S3:1664 StorePath: /build/TestClientPushesUseOnePush3261527512/001/store/bwf8wh6d0pq1dk11riy19w8gna9x8ibi-a1665 URL: nar/1np9vppiy6f8cadpm4kcg7zggm0gp1525cy8vgy4yw3wwq1djn5f.nar.zst1666 Compression: zstd1667 NarHash: sha256:1np9vppiy6f8cadpm4kcg7zggm0gp1525cy8vgy4yw3wwq1djn5f1668 NarSize: 2161669 References: /build/TestClientPushesUseOnePush3261527512/001/store/wnxqvkjcpcabbmkbj0bj9h776ncvamdp-shared-dep1670 CA: text:sha256:1rx6r53042826rg9mjkc43kvvkvxdh2drhk90rfa9x1w1yqgh3nv1671 client_pushes_test.go:97: Retrieved narinfo from S3:1672 StorePath: /build/TestClientPushesUseOnePush3261527512/001/store/5nc3jkhc83d5l4z11ib6bwgbkpqlx29w-b1673 URL: nar/1np9vppiy6f8cadpm4kcg7zggm0gp1525cy8vgy4yw3wwq1djn5f.nar.zst1674 Compression: zstd1675 NarHash: sha256:1np9vppiy6f8cadpm4kcg7zggm0gp1525cy8vgy4yw3wwq1djn5f1676 NarSize: 2161677 References: /build/TestClientPushesUseOnePush3261527512/001/store/wnxqvkjcpcabbmkbj0bj9h776ncvamdp-shared-dep1678 CA: text:sha256:1rx6r53042826rg9mjkc43kvvkvxdh2drhk90rfa9x1w1yqgh3nv16792026/11/04 20:13:36 INFO Received push request method=POST path=/api/pushes1680--- PASS: TestClientPushesUseOnePush (0.77s)1681=== CONT TestProxyWriteTimeout/narinfo1682=== CONT TestProxyWriteTimeout/unknown_size1683=== CONT TestProxyWriteTimeout/10_GiB_nar1684=== CONT TestProxyWriteTimeout/1_GiB_nar1685--- PASS: TestProxyWriteTimeout (0.09s)1686 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1687 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1688 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1689 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1690=== CONT TestIsValidUploadKey/narinfo1691=== CONT TestIsValidUploadKey/realisation_plus_in_output1692=== CONT TestIsValidUploadKey/unknown_type1693=== CONT TestIsValidUploadKey/empty_key1694=== CONT TestIsValidUploadKey/absolute1695=== CONT TestIsValidUploadKey/traversal_nar1696=== CONT TestIsValidUploadKey/traversal1697=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1698=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1699=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1700=== CONT TestIsValidUploadKey/index.html1701=== CONT TestIsValidUploadKey/nix-cache-info1702=== CONT TestIsValidUploadKey/build_log_home-manager_file1703=== CONT TestIsValidUploadKey/realisation1704=== CONT TestIsValidUploadKey/build_log_equals1705=== CONT TestIsValidUploadKey/build_log_question_mark1706=== CONT TestIsValidUploadKey/nar_plain1707=== CONT TestIsValidUploadKey/build_log_plus_in_name1708=== CONT TestIsValidUploadKey/build_log1709=== CONT TestIsValidUploadKey/nar_xz1710=== CONT TestIsValidUploadKey/listing1711=== CONT TestIsValidUploadKey/nar_zst1712=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17132026/11/04 20:13:36 INFO Received complete multipart upload request method=POST path=/1714--- PASS: TestIsValidUploadKey (0.10s)1715 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1716 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1717 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1718 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1719 --- PASS: TestIsValidUploadKey/absolute (0.00s)1720 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1721 --- PASS: TestIsValidUploadKey/traversal (0.00s)1722 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1723 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1724 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1725 --- PASS: TestIsValidUploadKey/index.html (0.00s)1726 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1727 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1728 --- PASS: TestIsValidUploadKey/realisation (0.00s)1729 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1730 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1731 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1732 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1733 --- PASS: TestIsValidUploadKey/build_log (0.00s)1734 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1735 --- PASS: TestIsValidUploadKey/listing (0.00s)1736 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)17372026/11/04 20:13:36 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17382026/11/04 20:13:36 INFO Received complete push request method=POST path=/api/pushes/3/complete17392026/11/04 20:13:36 WARN Failed to register uploaded object key=i8v5nf0q3dfsfx3pnpjdmfzpabcn2kh5.ls error="server returned 404: 404 page not found\n"1740=== NAME TestClientMultipleUploads1741 client_integration_test.go:405: Created store path 1: /build/TestClientMultipleUploads606407016/001/store/6025143an10pvkdp673z0adf9bh8wjsh-test-file-1.txt17422026/11/04 20:13:36 INFO Completed push id=3 objects=3 duration=2.516619ms17432026/11/04 20:13:36 INFO Upload complete. (57ms)1744=== NAME TestClientIntegration1745 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1746 client_integration_test.go:352: Decompressed .ls content (49 bytes):1747 {"version":1,"root":{"type":"regular","size":39}}1748 client_integration_test.go:363: Testing garbage collection...1749=== RUN TestService_RequireScope_OIDC/builder_may_write1750=== PAUSE TestService_RequireScope_OIDC/builder_may_write1751=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1752=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1753=== RUN TestService_RequireScope_OIDC/ops_may_admin1754=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1755=== RUN TestService_RequireScope_OIDC/ops_may_not_write1756=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1757=== RUN TestService_RequireScope_OIDC/reader_may_not_write1758=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1759=== RUN TestService_RequireScope_OIDC/static_token_may_admin1760=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1761=== RUN TestService_RequireScope_OIDC/static_token_may_write1762=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1763=== RUN TestService_RequireScope_OIDC/reader_may_read1764=== PAUSE TestService_RequireScope_OIDC/reader_may_read1765=== RUN TestService_RequireScope_OIDC/writer_implies_read1766=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1767=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1768=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1769=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1770=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1771=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1772=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1773=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1774=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1775=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1776=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1777=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17782026/11/04 20:13:36 INFO Received request for more parts method=POST path=/1779--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.34s)1780=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17812026/11/04 20:13:36 INFO Received uploads request method=POST path=/17822026/11/04 20:13:36 INFO Received push request method=POST path=/api/pushes17832026/11/04 20:13:36 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)17842026/11/04 20:13:36 INFO Uploading kq57gzh0zgn2mypixa9la5k5gpwym3kx-shared-dep (136B)17852026/11/04 20:13:36 INFO Uploading fmrjpfxb8rm18s3n06rr53ip08pblvkk-top (224B)17862026/11/04 20:13:36 WARN Failed to register uploaded object key=fmrjpfxb8rm18s3n06rr53ip08pblvkk.ls error="server returned 404: 404 page not found\n"17872026/11/04 20:13:36 WARN Failed to register uploaded object key=nar/0zk2i3mfjx5dy889ph1w9ylwrz56jamix28fnzscapgh56vs3gyk.nar.zst error="server returned 404: 404 page not found\n"17882026/11/04 20:13:36 WARN Failed to register uploaded object key=kq57gzh0zgn2mypixa9la5k5gpwym3kx.ls error="server returned 404: 404 page not found\n"17892026/11/04 20:13:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17902026/11/04 20:13:36 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17912026/11/04 20:13:36 INFO Signed narinfos id=1 count=217922026/11/04 20:13:36 INFO Uploading 2 narinfos1793=== NAME TestClientMultipleUploads1794 client_integration_test.go:405: Created store path 2: /build/TestClientMultipleUploads606407016/001/store/ndlknx6wbrs2c3gb59byxrr1czc9ns69-test-file-2.txt17952026/11/04 20:13:36 INFO Starting cleanup of old closures method=DELETE path=/api/closures17962026/11/04 20:13:36 INFO Garbage collection started17972026/11/04 20:13:36 INFO Received complete push request method=POST path=/api/pushes/1/complete17982026/11/04 20:13:36 WARN Failed to register uploaded object key=kq57gzh0zgn2mypixa9la5k5gpwym3kx.narinfo error="server returned 404: 404 page not found\n"17992026/11/04 20:13:36 WARN Failed to register uploaded object key=fmrjpfxb8rm18s3n06rr53ip08pblvkk.narinfo error="server returned 404: 404 page not found\n"18002026/11/04 20:13:36 INFO Received push request method=POST path=/api/pushes18012026/11/04 20:13:36 INFO Received uploads request method=POST path=/api/pending_closures18022026/11/04 20:13:36 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18032026/11/04 20:13:36 INFO Uploading 6br0nmmxjxrxdax82p6hslhxrqxsyi7h-test-script (136B)18042026/11/04 20:13:36 INFO Aborted multipart uploads count=0 kept=018052026/11/04 20:13:36 INFO Received push request method=POST path=/api/pushes18062026/11/04 20:13:36 INFO Completed push id=1 objects=6 duration=9.521415ms18072026/11/04 20:13:36 INFO Upload complete. (68ms)1808=== NAME TestClientSharedPathCommittedMidPush1809 client_integration_test.go:727: Retrieved narinfo from S3:1810 StorePath: /build/TestClientSharedPathCommittedMidPush962038052/001/store/kq57gzh0zgn2mypixa9la5k5gpwym3kx-shared-dep1811 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1812 Compression: zstd1813 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821814 NarSize: 1361815 References: 1816 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n18172026/11/04 20:13:36 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18182026/11/04 20:13:36 INFO Uploading fp7k35dqxfynr32n23sa0a5w1ss8nmil-unpinned-file.txt (128B)18192026/11/04 20:13:36 WARN Failed to register uploaded object key=log/22m1f9zj5whh44z5i146b64dc7284k30-test-script.drv error="server returned 404: 404 page not found\n"18202026/11/04 20:13:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18212026/11/04 20:13:36 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"18222026/11/04 20:13:36 WARN Failed to register uploaded object key=6br0nmmxjxrxdax82p6hslhxrqxsyi7h.ls error="server returned 404: 404 page not found\n"18232026/11/04 20:13:36 INFO Signed narinfos id=1 count=11824 client_integration_test.go:727: Retrieved narinfo from S3:18252026/11/04 20:13:36 INFO Uploading 1 narinfos1826 StorePath: /build/TestClientSharedPathCommittedMidPush962038052/001/store/fmrjpfxb8rm18s3n06rr53ip08pblvkk-top1827 URL: nar/0zk2i3mfjx5dy889ph1w9ylwrz56jamix28fnzscapgh56vs3gyk.nar.zst1828 Compression: zstd1829 NarHash: sha256:0zk2i3mfjx5dy889ph1w9ylwrz56jamix28fnzscapgh56vs3gyk1830 NarSize: 2241831 References: /build/TestClientSharedPathCommittedMidPush962038052/001/store/kq57gzh0zgn2mypixa9la5k5gpwym3kx-shared-dep1832 CA: text:sha256:00q626gdj9s2s6sbz8l0svr58nx1b79ykszfihj6pr69rbq2ddis18332026/11/04 20:13:36 WARN Force mode enabled - objects will be deleted immediately without grace period18342026/11/04 20:13:36 WARN Failed to register uploaded object key=fp7k35dqxfynr32n23sa0a5w1ss8nmil.ls error="server returned 404: 404 page not found\n"18352026/11/04 20:13:36 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign18362026/11/04 20:13:36 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"18372026/11/04 20:13:36 INFO Signed narinfos id=2 count=118382026/11/04 20:13:36 INFO Uploading 1 narinfos1839=== CONT TestPush_RejectsBadRequests/bad_root1840--- PASS: TestClientSharedPathCommittedMidPush (0.65s)18412026/11/04 20:13:36 INFO Received push request method=POST path=/api/pushes1842=== CONT TestPush_RejectsBadRequests/no_roots18432026/11/04 20:13:36 WARN Failed to register uploaded object key=6br0nmmxjxrxdax82p6hslhxrqxsyi7h.narinfo error="server returned 404: 404 page not found\n"1844=== CONT TestPush_RejectsBadRequests/no_objects18452026/11/04 20:13:36 INFO Received complete push request method=POST path=/api/pushes/1/complete18462026/11/04 20:13:36 INFO Received push request method=POST path=/api/pushes18472026/11/04 20:13:36 INFO Received push request method=POST path=/api/pushes1848=== CONT TestPush_RejectsBadRequests/root_not_in_objects1849=== CONT TestIsValidCachePath/narinfo18502026/11/04 20:13:36 INFO Received push request method=POST path=/api/pushes1851=== CONT TestIsValidCachePath/index.html1852=== CONT TestIsValidCachePath/short_hash1853=== CONT TestIsValidCachePath/leading_slash1854=== CONT TestIsValidCachePath/empty1855=== CONT TestIsValidCachePath/wrong_extension1856=== CONT TestIsValidCachePath/invalid_char_u1857=== CONT TestIsValidCachePath/invalid_char_e1858=== CONT TestIsValidCachePath/traversal_in_middle1859=== CONT TestIsValidCachePath/traversal_parent1860=== CONT TestIsValidCachePath/realisation1861=== CONT TestIsValidCachePath/nar_uncompressed1862=== CONT TestIsValidCachePath/nix-cache-info1863=== CONT TestIsValidCachePath/log1864=== CONT TestIsValidCachePath/ls1865=== CONT TestIsValidCachePath/nar_xz1866=== CONT TestIsValidCachePath/nar_bz21867=== CONT TestIsValidCachePath/nar_zst1868--- PASS: TestPush_RejectsBadRequests (0.81s)1869 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1870 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1871 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1872 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1873=== CONT TestIsValidCachePath/random_path1874=== CONT TestParseSingleRange/none1875=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1876=== CONT TestParseSingleRange/open-ended1877=== CONT TestParseSingleRange/start_far_past_EOF1878=== CONT TestParseSingleRange/single_byte1879=== CONT TestParseSingleRange/suffix_exceeds_size1880=== CONT TestParseSingleRange/suffix1881=== CONT TestParseSingleRange/malformed_both_empty1882=== CONT TestParseSingleRange/closed1883--- PASS: TestIsValidCachePath (0.00s)1884 --- PASS: TestIsValidCachePath/narinfo (0.00s)1885 --- PASS: TestIsValidCachePath/index.html (0.00s)1886 --- PASS: TestIsValidCachePath/short_hash (0.00s)1887 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1888 --- PASS: TestIsValidCachePath/empty (0.00s)1889 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1890 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1891 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1892 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1893 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1894 --- PASS: TestIsValidCachePath/realisation (0.00s)1895 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1896 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1897 --- PASS: TestIsValidCachePath/log (0.00s)1898 --- PASS: TestIsValidCachePath/ls (0.00s)1899 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1900 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1901 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1902 --- PASS: TestIsValidCachePath/random_path (0.00s)1903 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1904=== CONT TestParseSingleRange/start_past_EOF1905=== CONT TestParseSingleRange/end_clamped_to_size1906=== CONT TestParseSingleRange/multi-range_ignored1907=== CONT TestParseSingleRange/malformed_no_dash1908=== CONT TestParseSingleRange/unknown_unit1909=== CONT TestParseSingleRange/malformed_end_before_start1910=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1911--- PASS: TestParseSingleRange (0.00s)1912 --- PASS: TestParseSingleRange/none (0.00s)1913 --- PASS: TestParseSingleRange/open-ended (0.00s)1914 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1915 --- PASS: TestParseSingleRange/single_byte (0.00s)1916 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1917 --- PASS: TestParseSingleRange/suffix (0.00s)1918 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1919 --- PASS: TestParseSingleRange/closed (0.00s)1920 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1921 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1922 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1923 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1924 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1925 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1926=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh19272026/11/04 20:13:36 INFO Received complete push request method=POST path=/api/pushes/2/complete19282026/11/04 20:13:36 WARN Failed to register uploaded object key=fp7k35dqxfynr32n23sa0a5w1ss8nmil.narinfo error="server returned 404: 404 page not found\n"19292026/11/04 20:13:36 INFO Completed push id=2 objects=3 duration=2.376058ms19302026/11/04 20:13:36 INFO Upload complete. (54ms)19312026/11/04 20:13:36 INFO Received uploads request method=POST path=/api/pending_closures19322026/11/04 20:13:36 INFO Completed push id=1 objects=4 duration=8.716425ms19332026/11/04 20:13:36 INFO Upload complete. (65ms)1934=== NAME TestClientWithDependencies1935 client_integration_test.go:664: Skipping nix copy test - isolated store (/build/TestClientWithDependencies503992025/001/store) requires matching store prefix1936--- PASS: TestClientWithDependencies (0.66s)1937=== CONT TestServerTLSConfig/no_client_CA1938=== CONT TestServerTLSConfig/not_a_PEM_file1939=== CONT TestServerTLSConfig/missing_CA_file1940--- PASS: TestServerTLSConfig (0.00s)1941 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1942 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1943 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1944=== CONT TestGCEndsOnShutdown/before_the_run19452026/11/04 20:13:36 INFO Received push request method=POST path=/api/pushes1946=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark19472026/11/04 20:13:36 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19482026/11/04 20:13:36 INFO Uploading ackdkj53q3gl6f29cfs4h65xm1mnpkv6-ca-test (144B)19492026/11/04 20:13:36 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"19502026/11/04 20:13:36 WARN Failed to register uploaded object key=ackdkj53q3gl6f29cfs4h65xm1mnpkv6.ls error="server returned 404: 404 page not found\n"19512026/11/04 20:13:36 WARN Failed to register uploaded object key=log/l8vpi5bs91r4jg7vdfsfn5iqg3rimich-ca-test.drv error="server returned 404: 404 page not found\n"19522026/11/04 20:13:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19532026/11/04 20:13:36 INFO Signed narinfos id=1 count=119542026/11/04 20:13:36 INFO Uploading 1 narinfos19552026/11/04 20:13:36 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=01956=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1957=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1958=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1959=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1960=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1961=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1962=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1963=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1964=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete19652026/11/04 20:13:36 INFO Received complete push request method=POST path=/api/pushes/1/complete19662026/11/04 20:13:36 INFO Vacuumed table table=pending_closures19672026/11/04 20:13:36 WARN Failed to register uploaded object key=ackdkj53q3gl6f29cfs4h65xm1mnpkv6.narinfo error="server returned 404: 404 page not found\n"19682026/11/04 20:13:36 INFO Starting cleanup of old closures method=DELETE path=/api/closures19692026/11/04 20:13:36 INFO Garbage collection started19702026/11/04 20:13:36 INFO Vacuumed table table=pending_objects19712026/11/04 20:13:36 INFO Vacuumed table table=multipart_uploads19722026/11/04 20:13:36 INFO Completed push id=1 objects=4 duration=18.57826ms19732026/11/04 20:13:36 INFO Upload complete. (137ms)19742026/11/04 20:13:36 INFO Vacuumed table table=closures1975=== NAME TestClientCADerivations1976 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations3623203822/001/store/ackdkj53q3gl6f29cfs4h65xm1mnpkv6-ca-test1977 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1978 Compression: zstd1979 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1980 NarSize: 1441981 References: 1982 Deriver: /build/TestClientCADerivations3623203822/001/store/l8vpi5bs91r4jg7vdfsfn5iqg3rimich-ca-test.drv1983 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1984 client_ca_test.go:185: Checking for realisation files in S3...19852026/11/04 20:13:36 INFO Aborted multipart uploads count=0 kept=01986 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1987 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache19882026/11/04 20:13:36 INFO Vacuumed table table=objects19892026/11/04 20:13:36 INFO Received push request method=POST path=/api/pushes19902026/11/04 20:13:36 WARN Force mode enabled - objects will be deleted immediately without grace period19912026/11/04 20:13:36 INFO Received uploads request method=POST path=/api/pending_closures19922026/11/04 20:13:36 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)19932026/11/04 20:13:36 INFO Uploading 6025143an10pvkdp673z0adf9bh8wjsh-test-file-1.txt (160B)19942026/11/04 20:13:36 INFO Uploading 57ndvfbm076y6f6fvqyqq9qd2zvynz0w-test-file-0.txt (160B)19952026/11/04 20:13:36 INFO Uploading ndlknx6wbrs2c3gb59byxrr1czc9ns69-test-file-2.txt (160B)19962026/11/04 20:13:36 WARN Failed to register uploaded object key=6025143an10pvkdp673z0adf9bh8wjsh.ls error="server returned 404: 404 page not found\n"19972026/11/04 20:13:36 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"19982026/11/04 20:13:36 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"19992026/11/04 20:13:36 WARN Failed to register uploaded object key=57ndvfbm076y6f6fvqyqq9qd2zvynz0w.ls error="server returned 404: 404 page not found\n"20002026/11/04 20:13:36 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"20012026/11/04 20:13:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20022026/11/04 20:13:36 WARN Failed to register uploaded object key=ndlknx6wbrs2c3gb59byxrr1czc9ns69.ls error="server returned 404: 404 page not found\n"20032026/11/04 20:13:36 INFO Signed narinfos id=1 count=320042026/11/04 20:13:36 INFO Uploading 3 narinfos20052026/11/04 20:13:36 WARN Failed to register uploaded object key=6025143an10pvkdp673z0adf9bh8wjsh.narinfo error="server returned 404: 404 page not found\n"20062026/11/04 20:13:36 INFO Received complete push request method=POST path=/api/pushes/1/complete20072026/11/04 20:13:36 WARN Failed to register uploaded object key=ndlknx6wbrs2c3gb59byxrr1czc9ns69.narinfo error="server returned 404: 404 page not found\n"20082026/11/04 20:13:36 WARN Failed to register uploaded object key=57ndvfbm076y6f6fvqyqq9qd2zvynz0w.narinfo error="server returned 404: 404 page not found\n"20092026/11/04 20:13:36 INFO Completed push id=1 objects=9 duration=11.865224ms20102026/11/04 20:13:36 INFO Upload complete. (89ms)2011=== NAME TestClientMultipleUploads2012 client_integration_test.go:416: Uploaded 3 paths in 128.85346ms20132026/11/04 20:13:36 INFO Received uploads request method=POST path=/api/pending_closures2014--- PASS: TestClientMultipleUploads (0.72s)2015=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows20162026/11/04 20:13:36 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=020172026/11/04 20:13:36 INFO Vacuumed table table=pending_closures20182026/11/04 20:13:36 INFO Vacuumed table table=pending_objects20192026/11/04 20:13:36 INFO Vacuumed table table=multipart_uploads20202026/11/04 20:13:36 INFO Received uploads request method=POST path=/api/pending_closures20212026/11/04 20:13:36 INFO Vacuumed table table=closures20222026/11/04 20:13:36 INFO Vacuumed table table=objects20232026/11/04 20:13:36 INFO Received uploads request method=POST path=/api/pending_closures2024=== NAME TestClientCADerivations2025 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2026 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2027 error: binary cache 's3://bucket81?endpoint=http://localhost:36067®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations3623203822/001/store'2028 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12029--- PASS: TestClientCADerivations (0.95s)2030=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check2031=== CONT TestResolveDBConnectionString/flag_wins2032=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2033=== CONT TestResolveDBConnectionString/nothing_configured2034=== CONT TestResolveDBConnectionString/missing_file_is_an_error2035=== CONT TestResolveDBConnectionString/file_when_flag_empty2036=== CONT TestClientErrorHandling/InvalidStorePath2037--- PASS: TestResolveDBConnectionString (0.00s)2038 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2039 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2040 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2041 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2042 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)20432026/11/04 20:13:36 INFO Aborted multipart uploads count=0 kept=020442026/11/04 20:13:36 WARN Force mode enabled - objects will be deleted immediately without grace period20452026/11/04 20:13:36 INFO Aborted multipart uploads count=0 kept=02046=== CONT TestClientErrorHandling/ServerNotAvailable20472026/11/04 20:13:36 WARN Force mode enabled - objects will be deleted immediately without grace period20482026/11/04 20:13:36 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:36067/bucket101/?delete=\": context canceled"2049--- PASS: TestGCEndsOnShutdown (0.00s)2050 --- PASS: TestGCEndsOnShutdown/before_the_run (0.27s)2051 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.33s)2052 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.32s)2053=== CONT TestClientErrorHandling/InvalidAuthToken20542026/11/04 20:13:36 INFO Received uploads request method=POST path=/api/pending_closures20552026/11/04 20:13:36 INFO Aborted multipart uploads count=0 kept=020562026/11/04 20:13:36 WARN Force mode enabled - objects will be deleted immediately without grace period20572026/11/04 20:13:36 INFO Received uploads request method=POST path=/api/pending_closures20582026/11/04 20:13:36 INFO Aborted multipart uploads count=0 kept=020592026/11/04 20:13:36 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=020602026/11/04 20:13:36 INFO Vacuumed table table=pending_closures20612026/11/04 20:13:36 INFO Vacuumed table table=pending_objects20622026/11/04 20:13:36 WARN Force mode enabled - objects will be deleted immediately without grace period20632026/11/04 20:13:36 INFO Vacuumed table table=multipart_uploads20642026/11/04 20:13:36 INFO Vacuumed table table=closures20652026/11/04 20:13:36 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=020662026/11/04 20:13:36 INFO Vacuumed table table=objects20672026/11/04 20:13:36 INFO Vacuumed table table=pending_closures20682026/11/04 20:13:36 INFO Vacuumed table table=pending_objects20692026/11/04 20:13:36 INFO Vacuumed table table=multipart_uploads20702026/11/04 20:13:36 INFO Vacuumed table table=closures20712026/11/04 20:13:36 INFO Vacuumed table table=objects20722026/11/04 20:13:36 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/present2073=== CONT TestCacheConfigHandler/full_config,_no_issuer2074--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2075 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.23s)2076 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.31s)2077=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2078=== CONT TestCacheConfigHandler/no_signing_keys2079=== CONT TestCacheConfigHandler/no_cache_url_configured2080=== CONT TestService_RequireScope_OIDC/builder_may_write2081--- PASS: TestCacheConfigHandler (0.00s)2082 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2083 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2084 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2085 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2086=== CONT TestService_RequireScope_OIDC/reader_may_read2087=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2088=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2089=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20902026/11/04 20:13:36 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]2091=== CONT TestService_RequireScope_OIDC/writer_implies_read2092=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2093=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2094=== CONT TestService_RequireScope_OIDC/reader_may_not_write2095=== CONT TestService_RequireScope_OIDC/static_token_may_write2096=== CONT TestService_RequireScope_OIDC/static_token_may_admin2097=== CONT TestService_RequireScope_OIDC/ops_may_admin2098=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2099=== CONT TestService_RequireScope_OIDC/ops_may_not_write2100=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2101=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2102=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected21032026/11/04 20:13:36 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]2104=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2105--- PASS: TestService_RequireScope_OIDC (0.43s)2106 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2107 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2108 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2109 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2110 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2111 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2112 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2113 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2114 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2115 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2116 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2117 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2118 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2119 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)21202026/11/04 20:13:36 WARN Authentication failed token_preview=eyJhbGciOi...nriWvnV-9A token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2121--- PASS: TestService_AuthMiddleware_OIDC (0.47s)2122 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2123 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2124 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2125 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)21262026/11/04 20:13:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21272026/11/04 20:13:36 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=MDM0ZTMzNGEtZThjYi00YzllLTgwNjItZWNkYzE4ODNlZjkzLmU3MTdiODhiLTRlNWEtNDIwNC05YmFkLTIwOGFhNjJiZWUzNXgxNzkzODIzMjE2MTA2MzY2Njk5 parts=1021282026/11/04 20:13:36 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21292026/11/04 20:13:36 INFO Completed upload id=1 objects=3 duration=4.511727ms21302026/11/04 20:13:36 INFO lead: released remote=192.0.2.1:12342131--- PASS: TestLeadEndsOnShutdown (1.53s)21322026/11/04 20:13:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21332026/11/04 20:13:36 INFO Received uploads request method=POST path=/api/pending_closures21342026/11/04 20:13:36 WARN Request failed, retrying attempt=2 backoff=205.010356ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21352026/11/04 20:13:36 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21362026/11/04 20:13:36 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21372026/11/04 20:13:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21382026/11/04 20:13:36 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=MDM0ZTMzNGEtZThjYi00YzllLTgwNjItZWNkYzE4ODNlZjkzLjk5MzU1YzVlLTVmYmYtNDU0Yi1iMmNjLTUyZDU4Y2FmOGNkNXgxNzkzODIzMjE2MTc4MTMxMDAw parts=1021392026/11/04 20:13:36 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21402026/11/04 20:13:36 INFO Completed upload id=1 objects=3 duration=3.356768ms21412026/11/04 20:13:36 INFO Received uploads request method=POST path=/api/pending_closures21422026/11/04 20:13:36 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=MDM0ZTMzNGEtZThjYi00YzllLTgwNjItZWNkYzE4ODNlZjkzLmQzYmRlYmNiLTNlOWUtNDA3MC1hZTU4LTcwNDhjMTViYWVlOHgxNzkzODIzMjE2MjI5OTE0Mzcy parts=1021432026/11/04 20:13:36 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21442026/11/04 20:13:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21452026/11/04 20:13:36 INFO Completed upload id=1 objects=3 duration=3.910108ms21462026/11/04 20:13:36 INFO Received uploads request method=POST path=/api/pending_closures21472026/11/04 20:13:36 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=MDM0ZTMzNGEtZThjYi00YzllLTgwNjItZWNkYzE4ODNlZjkzLjNmYjg2MDY5LWNkMTMtNDZkMS05Nzc1LWM4YzkxMDYxMDgwMXgxNzkzODIzMjE2MjQ4MjQ3NTMy parts=1021482026/11/04 20:13:36 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21492026/11/04 20:13:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21502026/11/04 20:13:36 INFO Completed upload id=1 objects=3 duration=3.141618ms21512026/11/04 20:13:36 INFO Received uploads request method=POST path=/api/pending_closures21522026/11/04 20:13:36 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21532026/11/04 20:13:36 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=MDM0ZTMzNGEtZThjYi00YzllLTgwNjItZWNkYzE4ODNlZjkzLmRmODE1NWY0LWIzNzMtNGQ4YS1iZmYxLTllZmFjNjJiNDczOXgxNzkzODIzMjE2Mjc4MTY2ODE1 parts=102154--- PASS: TestDeleteClosuresRacingPins (1.51s)21552026/11/04 20:13:36 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21562026/11/04 20:13:36 INFO Completed upload id=1 objects=3 duration=3.223699ms2157--- PASS: TestUploadHandlersRejectOversizedBody (0.16s)2158 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.07s)2159 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.07s)2160 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.68s)21612026/11/04 20:13:36 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21622026/11/04 20:13:36 INFO Received uploads request method=POST path=/api/pending_closures21632026/11/04 20:13:36 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst21642026/11/04 20:13:36 WARN Found objects in DB but missing from S3, will re-upload count=121652026/11/04 20:13:36 INFO lead: released remote=192.0.2.1:123421662026/11/04 20:13:36 WARN Request failed, retrying attempt=3 backoff=427.68246ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2167--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2168 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.72s)2169 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.75s)2170=== NAME TestOrphanedObjectsGCStressTest2171 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2172 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion2173--- PASS: TestPendingClosureWriteTimeout (0.09s)2174 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2175 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2176 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2177 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.13s)21782026/11/04 20:13:36 INFO lead: acquired remote=192.0.2.1:123421792026/11/04 20:13:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21802026/11/04 20:13:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21812026/11/04 20:13:37 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=MDM0ZTMzNGEtZThjYi00YzllLTgwNjItZWNkYzE4ODNlZjkzLmUwOTMyZWM1LTU5MjMtNDhiOS1iYWI0LTY3NDIzNzYzZDExM3gxNzkzODIzMjE2NjQ5ODIyNzU0 parts=1021822026/11/04 20:13:37 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete21832026/11/04 20:13:37 INFO Completed upload id=2 objects=3 duration=752.8µs21842026/11/04 20:13:37 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=MDM0ZTMzNGEtZThjYi00YzllLTgwNjItZWNkYzE4ODNlZjkzLjY0MTU2NjI2LTY3YjctNGI3YS1hNzI5LTljZGIxODk0Y2VlNXgxNzkzODIzMjE2NjY4ODg5NTcz parts=1021852026/11/04 20:13:37 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete21862026/11/04 20:13:37 INFO Completed upload id=2 objects=3 duration=1.416609ms21872026/11/04 20:13:37 INFO Received uploads request method=POST path=/api/pending_closures21882026/11/04 20:13:37 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst21892026/11/04 20:13:37 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo21902026/11/04 20:13:37 INFO Received uploads request method=POST path=/api/pending_closures21912026/11/04 20:13:37 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst21922026/11/04 20:13:37 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2193--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.10s)2194 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (0.76s)2195 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (0.70s)2196 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (0.75s)2197 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (1.21s)2198 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (1.20s)21992026/11/04 20:13:37 WARN Request failed, retrying attempt=4 backoff=778.142779ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22002026/11/04 20:13:37 WARN Rate limiter enabled after throttle name=s3-test rate=522012026/11/04 20:13:37 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2202=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2203 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102204 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002205--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.60s)22062026/11/04 20:13:37 INFO lead: released remote=192.0.2.1:12342207--- PASS: TestLeadElectsOneAndHandsOver (2.84s)22082026/11/04 20:13:38 WARN Request failed, retrying attempt=5 backoff=1.569061753s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22092026/11/04 20:13:38 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02210=== NAME TestOrphanedObjectsGCStressTest2211 orphaned_objects_gc_test.go:503: Stress test completed successfully:2212 orphaned_objects_gc_test.go:504: - Active objects preserved: 202213 orphaned_objects_gc_test.go:505: - Objects deleted: 2102214 orphaned_objects_gc_test.go:506: - Total GC'd: 2102215--- PASS: TestOrphanedObjectsGCStressTest (3.91s)2216=== NAME TestClientIntegration2217 client_integration_test.go:370: Objects in database after GC:2218 client_integration_test.go:370: Successfully deleted all objects with GC --force2219--- PASS: TestClientIntegration (3.01s)22202026/11/04 20:13:38 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=022212026/11/04 20:13:38 INFO Received create pin request method=POST path=/api/pins/myapp22222026/11/04 20:13:38 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC1132506959/001/store/kv03jnlvlaaxk4q1x7zikimmg5z0qbdf-pinned-file.txt narinfo_key=kv03jnlvlaaxk4q1x7zikimmg5z0qbdf.narinfo22232026/11/04 20:13:38 INFO Starting cleanup of old closures method=DELETE path=/api/closures22242026/11/04 20:13:38 INFO Garbage collection started22252026/11/04 20:13:38 INFO Aborted multipart uploads count=0 kept=022262026/11/04 20:13:38 WARN Force mode enabled - objects will be deleted immediately without grace period22272026/11/04 20:13:38 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=022282026/11/04 20:13:38 INFO Vacuumed table table=pending_closures22292026/11/04 20:13:38 INFO Vacuumed table table=pending_objects22302026/11/04 20:13:38 INFO Vacuumed table table=multipart_uploads22312026/11/04 20:13:38 INFO Vacuumed table table=closures22322026/11/04 20:13:38 INFO Vacuumed table table=objects2233--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.76s)2234--- PASS: TestConnectWaitsForAPeerMigration (5.16s)22352026/11/04 20:13:39 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-config22362026/11/04 20:13:39 WARN Request failed, retrying attempt=2 backoff=187.824602ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22372026/11/04 20:13:39 WARN Request failed, retrying attempt=3 backoff=375.611457ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2238=== NAME TestPinProtectsFromGC2239 client_integration_test.go:887: Pin successfully protected closure from garbage collection2240--- PASS: TestPinProtectsFromGC (4.89s)22412026/11/04 20:13:40 WARN Request failed, retrying attempt=4 backoff=810.483134ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22422026/11/04 20:13:40 INFO Aborted multipart uploads count=1 kept=022432026/11/04 20:13:40 INFO Received cleanup request method=DELETE path=/api/pending_closures22442026/11/04 20:13:40 INFO Aborted multipart uploads count=1 kept=02245--- PASS: TestPendingCleanupUsesOneCutoff (6.66s)22462026/11/04 20:13:41 WARN Request failed, retrying attempt=5 backoff=1.528641645s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22472026/11/04 20:13:42 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"22482026/11/04 20:13:42 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-config22492026/11/04 20:13:42 WARN Request failed, retrying attempt=2 backoff=198.702842ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22502026/11/04 20:13:42 WARN Request failed, retrying attempt=3 backoff=398.690055ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22512026/11/04 20:13:43 WARN Request failed, retrying attempt=4 backoff=782.860735ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22522026/11/04 20:13:44 WARN Request failed, retrying attempt=5 backoff=1.505775624s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22532026/11/04 20:13:45 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_closures22542026/11/04 20:13:45 WARN Request failed, retrying attempt=2 backoff=202.312642ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22552026/11/04 20:13:45 WARN Request failed, retrying attempt=3 backoff=401.750086ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22562026/11/04 20:13:46 WARN Request failed, retrying attempt=4 backoff=821.678002ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22572026/11/04 20:13:47 WARN Request failed, retrying attempt=5 backoff=1.629045654s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2258--- PASS: TestClientErrorHandling (0.00s)2259 --- PASS: TestClientErrorHandling/InvalidStorePath (0.20s)2260 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.29s)2261 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.39s)2262PASS2263{"timestamp":"2026-11-04T20:13:48.83464323Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:51294","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(395)"}2264{"timestamp":"2026-11-04T20:13:48.83464312Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:52612","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(392)"}2265{"timestamp":"2026-11-04T20:13:48.83463035Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:52636","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(388)"}2266{"timestamp":"2026-11-04T20:13:48.83464742Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:51944","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(399)"}22672026-11-04 20:13:49.189 UTC [131] LOG: received smart shutdown request22682026-11-04 20:13:49.193 UTC [131] LOG: background worker "logical replication launcher" (PID 141) exited with exit code 122692026-11-04 20:13:49.206 UTC [136] LOG: shutting down22702026-11-04 20:13:49.207 UTC [136] LOG: checkpoint starting: shutdown immediate22712026-11-04 20:13:50.619 UTC [136] LOG: checkpoint complete: wrote 10872 buffers (66.4%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.284 s, sync=1.077 s, total=1.413 s; sync files=35725, longest=0.047 s, average=0.001 s; distance=516836 kB, estimate=516836 kB; lsn=0/2101EF80, redo lsn=0/2101EF8022722026-11-04 20:13:50.700 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 TestValidateToken_KubernetesServiceAccount2312=== CONT TestPins_ConfigValidation2313=== CONT TestScopes_ConfigValidation2314=== CONT TestScopes_Rules2315=== CONT TestScopes_LegacyProviderDefaultsToWrite2316=== CONT TestValidateToken_MultipleProviders2317--- PASS: TestAudienceForIssuer (0.00s)2318=== CONT TestValidateToken_NoMatchingProvider2319--- PASS: TestPins_ConfigValidation (0.00s)2320=== CONT TestValidateToken_Expired2321=== CONT TestValidateToken_WrongAudience2322=== CONT TestValidateToken_ValidToken2323=== CONT TestValidateToken_BoundSubjectMismatch2324=== CONT TestGlobMatch2325=== CONT TestPins_ReservedForMatchingRule2326=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2327=== CONT TestPins_TopLevelShorthand2328=== CONT TestNewValidator_KubernetesRequiresCA2329=== CONT TestValidateToken_BoundClaimsMismatch2330--- PASS: TestScopes_ConfigValidation (0.00s)2331=== RUN TestGlobMatch/foo_foo2332=== PAUSE TestGlobMatch/foo_foo2333=== RUN TestGlobMatch/foo_bar2334=== PAUSE TestGlobMatch/foo_bar2335=== RUN TestGlobMatch/*_2336=== PAUSE TestGlobMatch/*_2337=== RUN TestGlobMatch/*_anything2338=== PAUSE TestGlobMatch/*_anything2339=== RUN TestGlobMatch/foo*_foo2340=== PAUSE TestGlobMatch/foo*_foo2341=== RUN TestGlobMatch/foo*_foobar2342=== PAUSE TestGlobMatch/foo*_foobar2343=== RUN TestGlobMatch/foo*_bar2344=== PAUSE TestGlobMatch/foo*_bar2345=== RUN TestGlobMatch/*bar_bar2346=== PAUSE TestGlobMatch/*bar_bar2347=== RUN TestGlobMatch/*bar_foobar2348=== PAUSE TestGlobMatch/*bar_foobar2349=== RUN TestGlobMatch/*bar_foo2350=== PAUSE TestGlobMatch/*bar_foo2351=== RUN TestGlobMatch/foo*bar_foobar2352=== PAUSE TestGlobMatch/foo*bar_foobar2353=== RUN TestGlobMatch/foo*bar_foo123bar2354=== PAUSE TestGlobMatch/foo*bar_foo123bar2355=== RUN TestGlobMatch/foo*bar_foobarbaz2356=== PAUSE TestGlobMatch/foo*bar_foobarbaz2357=== RUN TestGlobMatch/*/*_foo/bar2358=== PAUSE TestGlobMatch/*/*_foo/bar2359=== RUN TestGlobMatch/*/*_foo2360=== PAUSE TestGlobMatch/*/*_foo2361=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2362=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2363=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02364=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02365=== RUN TestGlobMatch/refs/*/main_refs/heads/main2366=== 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/foo*bar_foobarbaz2383=== CONT TestGlobMatch/foo*bar_foo123bar2384=== CONT TestGlobMatch/foo*bar_foobar2385=== CONT TestGlobMatch/*bar_foo2386=== CONT TestGlobMatch/*bar_foobar2387=== CONT TestGlobMatch/*bar_bar2388=== CONT TestGlobMatch/foo*_bar2389=== CONT TestGlobMatch/foo*_foobar2390=== CONT TestGlobMatch/foo*_foo2391=== CONT TestGlobMatch/fo?_foo2392=== CONT TestGlobMatch/foo_bar2393=== CONT TestGlobMatch/*/*_foo/bar2394=== CONT TestGlobMatch/refs/*/main_refs/heads/main2395=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2396=== CONT TestGlobMatch/*/*_foo2397=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2398=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2399=== CONT TestGlobMatch/?oo_boo2400=== CONT TestGlobMatch/?oo_foo2401=== CONT TestGlobMatch/fo?_fooo2402=== CONT TestGlobMatch/fo?_fo2403=== CONT TestGlobMatch/*_anything2404=== CONT TestGlobMatch/*_2405=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02406--- PASS: TestGlobMatch (0.00s)2407 --- PASS: TestGlobMatch/foo_foo (0.00s)2408 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2409 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2410 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2411 --- PASS: TestGlobMatch/*bar_foo (0.00s)2412 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2413 --- PASS: TestGlobMatch/*bar_bar (0.00s)2414 --- PASS: TestGlobMatch/foo*_bar (0.00s)2415 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2416 --- PASS: TestGlobMatch/foo*_foo (0.00s)2417 --- PASS: TestGlobMatch/fo?_foo (0.00s)2418 --- PASS: TestGlobMatch/foo_bar (0.00s)2419 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2420 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2421 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2422 --- PASS: TestGlobMatch/*/*_foo (0.00s)2423 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2424 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2425 --- PASS: TestGlobMatch/?oo_boo (0.00s)2426 --- PASS: TestGlobMatch/?oo_foo (0.00s)2427 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2428 --- PASS: TestGlobMatch/fo?_fo (0.00s)2429 --- PASS: TestGlobMatch/*_anything (0.00s)2430 --- PASS: TestGlobMatch/*_ (0.00s)2431 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)24322026/11/04 20:13:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33841/oidc2433--- PASS: TestValidateToken_BoundSubjectMismatch (0.03s)24342026/11/04 20:13:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:32943/oidc24352026/11/04 20:13:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38879/oidc2436--- PASS: TestValidateToken_ValidToken (0.04s)2437--- PASS: TestPins_TopLevelShorthand (0.04s)24382026/11/04 20:13:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33403/oidc24392026/11/04 20:13:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34067/oidc2440--- PASS: TestValidateToken_Expired (0.06s)2441--- PASS: TestPins_ReservedForMatchingRule (0.06s)24422026/11/04 20:13:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44305/oidc2443--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.07s)24442026/11/04 20:13:53 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:34679/oidc24452026/11/04 20:13:53 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:42775/oidc2446--- PASS: TestValidateToken_MultipleProviders (0.08s)24472026/11/04 20:13:53 http: TLS handshake error from 127.0.0.1:53578: remote error: tls: bad certificate2448--- PASS: TestNewValidator_KubernetesRequiresCA (0.07s)24492026/11/04 20:13:53 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:3415124502026/11/04 20:13:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33307/oidc2451--- PASS: TestValidateToken_KubernetesServiceAccount (0.10s)2452--- PASS: TestScopes_Rules (0.10s)24532026/11/04 20:13:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35033/oidc2454--- PASS: TestValidateToken_WrongAudience (0.11s)24552026/11/04 20:13:53 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232456--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.16s)24572026/11/04 20:13:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40939/oidc24582026/11/04 20:13:53 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:36257/oidc2459--- PASS: TestValidateToken_BoundClaimsMismatch (0.20s)2460--- PASS: TestValidateToken_NoMatchingProvider (0.20s)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/04 20:13:53 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 TestServerStalledClientDoesNotBlockShutdown2518=== CONT TestQueueRemoveLargeClosure2519=== CONT TestWorkerSkipsGCdPaths2520=== CONT TestWorkerUploadsAndRemoves2521=== CONT TestFailedPathPrunedByLaterClosure2522=== CONT TestWorkerKeepsPathItCannotStat2523=== CONT TestDrainGivesUpWhenServerDown2524=== CONT TestWorkerRemoveFailureIsNotProgress2525=== CONT TestRunNotBlockedByPoisonHead2526=== CONT TestDrainTimeout2527=== CONT TestDrainIsolatesPoisonPath2528=== CONT TestServerBacksOffOnAcceptErrors2529=== CONT TestWorkerPrunesClosureDeps25302026/11/04 20:13:53 ERROR Accept failed error="too many open files"2531--- PASS: TestSendPathsEmpty (0.00s)2532=== CONT TestQueueFetchRemoveLifecycle2533=== CONT TestQueueRemove2534=== CONT TestQueueFetchBatchLimit2535=== CONT TestQueueDeduplication2536=== CONT TestQueueConcurrentWriters2537=== CONT TestQueueRetryMovesToBack2538=== CONT TestQueueEnqueueAndFetch25392026/11/04 20:13:53 ERROR Accept failed error="too many open files"25402026/11/04 20:13:53 INFO Upload queue status pending=225412026/11/04 20:13:53 INFO Uploading batch count=125422026/11/04 20:13:53 ERROR Upload failed error="upload failed" count=125432026/11/04 20:13:53 INFO Upload queue status pending=225442026/11/04 20:13:53 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat565601167/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat565601167/002/locked/aaa: permission denied"25452026/11/04 20:13:53 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths2315691218/002/nonexistent25462026/11/04 20:13:53 INFO Upload queue status pending=325472026/11/04 20:13:53 INFO Uploading batch count=125482026/11/04 20:13:53 INFO Uploading batch count=22549--- PASS: TestQueueEnqueueAndFetch (0.01s)25502026/11/04 20:13:53 INFO Uploading batch count=425512026/11/04 20:13:53 ERROR Upload failed error="upload failed" count=125522026/11/04 20:13:53 INFO Upload queue status pending=225532026/11/04 20:13:53 ERROR Accept failed error="too many open files"25542026/11/04 20:13:53 INFO Uploading batch count=225552026/11/04 20:13:53 ERROR Upload failed error="upload failed" count=425562026/11/04 20:13:53 INFO Uploading batch count=125572026/11/04 20:13:53 INFO Uploading batch count=225582026/11/04 20:13:53 ERROR Upload failed error="upload failed" count=22559--- PASS: TestQueueRetryMovesToBack (0.02s)25602026/11/04 20:13:53 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1647330161/002/a25612026/11/04 20:13:53 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat565601167/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat565601167/002/locked/aaa: permission denied"25622026/11/04 20:13:53 INFO Uploading batch count=125632026/11/04 20:13:53 INFO Uploading batch count=12564--- PASS: TestQueueFetchRemoveLifecycle (0.02s)2565--- PASS: TestQueueFetchBatchLimit (0.02s)2566--- PASS: TestQueueDeduplication (0.02s)25672026/11/04 20:13:53 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath3222005899/002/bbb2568--- PASS: TestQueueRemove (0.02s)25692026/11/04 20:13:53 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1647330161/002/b25702026/11/04 20:13:53 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat565601167/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat565601167/002/locked/aaa: permission denied"25712026/11/04 20:13:53 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress3723340484/002/nonexistent25722026/11/04 20:13:53 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125732026/11/04 20:13:53 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress3723340484/002/nonexistent25742026/11/04 20:13:53 INFO Uploading batch count=125752026/11/04 20:13:53 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125762026/11/04 20:13:53 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress3723340484/002/nonexistent25772026/11/04 20:13:53 ERROR Drain finished with paths left in queue remaining=125782026/11/04 20:13:53 INFO Uploading batch count=225792026/11/04 20:13:53 ERROR Upload failed error="upload failed" count=225802026/11/04 20:13:53 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1647330161/002/c25812026/11/04 20:13:53 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125822026/11/04 20:13:53 ERROR Drain finished with paths left in queue remaining=12583--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)25842026/11/04 20:13:53 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1647330161/002/d25852026/11/04 20:13:53 INFO Uploading batch count=125862026/11/04 20:13:53 ERROR Upload failed error="upload failed" count=12587--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)25882026/11/04 20:13:53 INFO Uploading batch count=225892026/11/04 20:13:53 ERROR Upload failed error="upload failed" count=225902026/11/04 20:13:53 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1647330161/002/e25912026/11/04 20:13:53 INFO Uploading batch count=12592--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)25932026/11/04 20:13:53 ERROR Upload failed error="upload failed" count=125942026/11/04 20:13:53 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1647330161/002/f25952026/11/04 20:13:53 INFO Uploading batch count=125962026/11/04 20:13:53 ERROR Upload failed error="upload failed" count=125972026/11/04 20:13:53 ERROR Drain finished with paths left in queue remaining=1025982026/11/04 20:13:53 ERROR Drain finished with paths left in queue remaining=12599--- PASS: TestDrainIsolatesPoisonPath (0.03s)2600--- PASS: TestDrainGivesUpWhenServerDown (0.03s)26012026/11/04 20:13:53 ERROR Accept failed error="too many open files"2602--- PASS: TestWorkerSkipsGCdPaths (0.04s)2603--- PASS: TestWorkerUploadsAndRemoves (0.04s)2604--- PASS: TestWorkerPrunesClosureDeps (0.04s)2605--- PASS: TestQueueRemoveLargeClosure (0.06s)26062026/11/04 20:13:53 ERROR Accept failed error="too many open files"26072026/11/04 20:13:53 ERROR Accept failed error="too many open files"26082026/11/04 20:13:53 ERROR Failed to decode request error="read unix /build/hook2955430905/test.sock->@: i/o timeout"26092026/11/04 20:13:53 ERROR Failed to write response error="write unix /build/hook2955430905/test.sock->@: i/o timeout"2610--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)2611--- PASS: TestQueueConcurrentWriters (0.21s)26122026/11/04 20:13:53 ERROR Upload failed error="context deadline exceeded" count=226132026/11/04 20:13:53 ERROR Drain finished with paths left in queue remaining=42614--- PASS: TestDrainTimeout (0.22s)26152026/11/04 20:13:53 ERROR Accept failed error="too many open files"26162026/11/04 20:13:53 ERROR Accept failed error="too many open files"2617--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26182026/11/04 20:13:54 INFO Uploading batch count=126192026/11/04 20:13:54 INFO Uploading batch count=126202026/11/04 20:13:54 INFO Uploading batch count=126212026/11/04 20:13:54 ERROR Upload failed error="upload failed" count=126222026/11/04 20:13:54 INFO Uploading batch count=126232026/11/04 20:13:54 ERROR Upload failed error="upload failed" count=126242026/11/04 20:13:54 INFO Uploading batch count=126252026/11/04 20:13:54 ERROR Upload failed error="upload failed" count=126262026/11/04 20:13:54 INFO Uploading batch count=126272026/11/04 20:13:54 ERROR Upload failed error="upload failed" count=126282026/11/04 20:13:54 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 TestSignBatch2662=== CONT TestExternalSignerCancellation2663=== CONT TestGenerateFingerprint2664=== CONT TestSign2665=== CONT TestSignErrors2666=== CONT TestExternalSignerProgramErrorKeepsProcess2667=== CONT TestExternalSignerRejectsInvalidPublicKey2668=== RUN TestExternalSignerRejectsInvalidPublicKey/#002669=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002670=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2671=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2672=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2673=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2674=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2675=== CONT TestExternalSignerClose2676=== CONT TestNilKeyPublicKey2677=== CONT TestExternalSignerErrors2678=== CONT TestExternalSignerRestartsAfterCrash2679=== CONT TestExternalSignerWrongPublicKey2680=== CONT TestParseSigningKey2681=== RUN TestGenerateFingerprint/basic_with_references2682=== PAUSE TestGenerateFingerprint/basic_with_references2683=== RUN TestGenerateFingerprint/no_references2684=== PAUSE TestGenerateFingerprint/no_references2685=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2686=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2687=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2688=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2689=== RUN TestGenerateFingerprint/invalid_nar_hash_length2690=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2691=== RUN TestGenerateFingerprint/invalid_store_path_prefix2692=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2693=== RUN TestGenerateFingerprint/invalid_reference_prefix2694=== RUN TestSignErrors/nil_key2695=== PAUSE TestSignErrors/nil_key2696=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2697=== CONT TestGenerateFingerprint/basic_with_references2698=== CONT TestGenerateFingerprint/invalid_store_path_prefix2699=== CONT TestGenerateFingerprint/invalid_nar_hash_length2700=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2701--- PASS: TestSign (0.00s)2702--- PASS: TestNilKeyPublicKey (0.00s)2703=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2704=== RUN TestExternalSignerErrors/wrong_id2705=== RUN TestSignErrors/nil_narinfo2706=== RUN TestParseSigningKey/valid_32-byte_key2707=== PAUSE TestParseSigningKey/valid_32-byte_key2708=== CONT TestGenerateFingerprint/invalid_reference_prefix2709=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2710=== CONT TestGenerateFingerprint/no_references2711--- PASS: TestSignBatch (0.00s)2712=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2713--- PASS: TestGenerateFingerprint (0.00s)2714 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2715 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2716 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2717 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2718 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2719 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2720 --- PASS: TestGenerateFingerprint/no_references (0.00s)2721=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2722=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2723=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2724=== PAUSE TestSignErrors/nil_narinfo2725=== PAUSE TestExternalSignerErrors/wrong_id2726=== RUN TestExternalSignerErrors/unrequested_key2727=== RUN TestSignErrors/invalid_narinfo2728=== PAUSE TestSignErrors/invalid_narinfo2729=== RUN TestSignErrors/canceled2730=== PAUSE TestSignErrors/canceled2731=== CONT TestSignErrors/nil_key2732=== CONT TestSignErrors/invalid_narinfo2733=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2734=== CONT TestSignErrors/canceled2735=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2736=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2737=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2738=== RUN TestParseSigningKey/no_colon2739=== PAUSE TestParseSigningKey/no_colon2740=== RUN TestParseSigningKey/empty_name2741=== PAUSE TestParseSigningKey/empty_name2742=== CONT TestExternalSignerRejectsInvalidPublicKey/#002743=== PAUSE TestExternalSignerErrors/unrequested_key2744=== RUN TestExternalSignerErrors/wrong_signature_name2745=== PAUSE TestExternalSignerErrors/wrong_signature_name2746=== RUN TestExternalSignerErrors/exit_at_startup2747=== PAUSE TestExternalSignerErrors/exit_at_startup2748=== RUN TestExternalSignerErrors/exit_on_request2749=== PAUSE TestExternalSignerErrors/exit_on_request2750=== RUN TestExternalSignerErrors/too_few_signatures2751=== PAUSE TestExternalSignerErrors/too_few_signatures2752=== RUN TestExternalSignerErrors/invalid_signature_base642753=== PAUSE TestExternalSignerErrors/invalid_signature_base642754=== CONT TestSignErrors/nil_narinfo2755=== RUN TestParseSigningKey/invalid_base642756=== PAUSE TestParseSigningKey/invalid_base642757=== RUN TestParseSigningKey/wrong_length2758=== PAUSE TestParseSigningKey/wrong_length2759=== CONT TestParseSigningKey/valid_32-byte_key2760=== CONT TestParseSigningKey/empty_name2761--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2762 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2763 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2764 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2765 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2766 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2767--- PASS: TestSignErrors (0.00s)2768 --- PASS: TestSignErrors/nil_key (0.00s)2769 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2770 --- PASS: TestSignErrors/canceled (0.00s)2771 --- PASS: TestSignErrors/nil_narinfo (0.00s)2772=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2773=== CONT TestParseSigningKey/invalid_base642774=== RUN TestExternalSignerErrors/wrong_shape2775=== PAUSE TestExternalSignerErrors/wrong_shape2776=== CONT TestParseSigningKey/wrong_length2777=== RUN TestExternalSignerErrors/missing_signatures2778=== PAUSE TestExternalSignerErrors/missing_signatures2779=== CONT TestParseSigningKey/no_colon2780=== RUN TestExternalSignerErrors/null_signatures2781--- PASS: TestExternalSignerWrongPublicKey (0.00s)2782--- PASS: TestParseSigningKey (0.00s)2783 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2784 --- PASS: TestParseSigningKey/empty_name (0.00s)2785 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2786 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2787 --- PASS: TestParseSigningKey/wrong_length (0.00s)2788 --- PASS: TestParseSigningKey/no_colon (0.00s)2789=== PAUSE TestExternalSignerErrors/null_signatures2790=== RUN TestExternalSignerErrors/wrong_signature_length2791=== PAUSE TestExternalSignerErrors/wrong_signature_length2792=== RUN TestExternalSignerErrors/program_error2793=== PAUSE TestExternalSignerErrors/program_error2794=== RUN TestExternalSignerErrors/invalid_JSON2795=== PAUSE TestExternalSignerErrors/invalid_JSON2796=== RUN TestExternalSignerErrors/null2797=== PAUSE TestExternalSignerErrors/null2798=== RUN TestExternalSignerErrors/wrong_signatures_shape2799=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2800=== RUN TestExternalSignerErrors/missing_signature_name2801=== PAUSE TestExternalSignerErrors/missing_signature_name2802=== CONT TestExternalSignerErrors/wrong_id2803=== CONT TestExternalSignerErrors/program_error2804=== CONT TestExternalSignerErrors/wrong_signature_name2805=== CONT TestExternalSignerErrors/exit_on_request2806=== CONT TestExternalSignerErrors/missing_signatures2807=== CONT TestExternalSignerErrors/missing_signature_name2808=== CONT TestExternalSignerErrors/wrong_signatures_shape2809=== CONT TestExternalSignerErrors/null2810=== CONT TestExternalSignerErrors/invalid_JSON2811=== CONT TestExternalSignerErrors/wrong_shape2812=== CONT TestExternalSignerErrors/invalid_signature_base642813=== CONT TestExternalSignerErrors/too_few_signatures2814=== CONT TestExternalSignerErrors/exit_at_startup2815=== CONT TestExternalSignerErrors/wrong_signature_length2816=== CONT TestExternalSignerErrors/unrequested_key2817=== CONT TestExternalSignerErrors/null_signatures2818--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.01s)2819--- PASS: TestExternalSignerClose (0.01s)2820--- PASS: TestExternalSigner (0.01s)2821--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2822--- PASS: TestExternalSignerErrors (0.00s)2823 --- PASS: TestExternalSignerErrors/program_error (0.00s)2824 --- PASS: TestExternalSignerErrors/wrong_id (0.00s)2825 --- PASS: TestExternalSignerErrors/missing_signature_name (0.00s)2826 --- PASS: TestExternalSignerErrors/missing_signatures (0.00s)2827 --- PASS: TestExternalSignerErrors/null (0.01s)2828 --- PASS: TestExternalSignerErrors/exit_on_request (0.01s)2829 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)2830 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)2831 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2832 --- PASS: TestExternalSignerErrors/exit_at_startup (0.01s)2833 --- PASS: TestExternalSignerErrors/too_few_signatures (0.01s)2834 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)2835 --- PASS: TestExternalSignerErrors/unrequested_key (0.01s)2836 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)2837 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)2838 --- PASS: TestExternalSignerErrors/wrong_signature_length (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 TestServeRejectsGarbage2853=== CONT TestSignErrors2854=== RUN TestSignErrors/http_error2855=== PAUSE TestSignErrors/http_error2856=== RUN TestSignErrors/invalid_json2857=== PAUSE TestSignErrors/invalid_json2858=== RUN TestSignErrors/no_prefix2859=== PAUSE TestSignErrors/no_prefix2860=== RUN TestSignErrors/invalid_base642861=== PAUSE TestSignErrors/invalid_base642862=== CONT TestSignErrors/http_error2863=== CONT TestSignErrors/no_prefix2864--- PASS: TestServeRejectsGarbage (0.00s)2865--- PASS: TestServe (0.00s)2866=== CONT TestSignErrors/invalid_json2867=== CONT TestSignErrors/invalid_base642868--- PASS: TestSign (0.00s)2869--- PASS: TestSignErrors (0.00s)2870 --- PASS: TestSignErrors/invalid_base64 (0.00s)2871 --- PASS: TestSignErrors/invalid_json (0.00s)2872 --- PASS: TestSignErrors/http_error (0.00s)2873 --- PASS: TestSignErrors/no_prefix (0.00s)2874PASS