niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #456
· 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 TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestUploadMultipart_SupersededByPeer24=== PAUSE TestUploadMultipart_SupersededByPeer25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (0.05s)27=== RUN TestDumpPathCaseHackCollision28--- PASS: TestDumpPathCaseHackCollision (0.00s)29=== RUN TestSupersededNARStillUploadsListing30=== PAUSE TestSupersededNARStillUploadsListing31=== RUN TestDumpPathMatchesNix32=== PAUSE TestDumpPathMatchesNix33=== RUN TestDumpPathSingleFile34=== PAUSE TestDumpPathSingleFile35=== RUN TestDumpPathWriterError36=== PAUSE TestDumpPathWriterError37=== RUN TestEncodeNixBase3238=== PAUSE TestEncodeNixBase3239=== RUN TestEncodeNixBase32WithRealHash40=== PAUSE TestEncodeNixBase32WithRealHash41=== RUN TestConvertHashToNix3242=== PAUSE TestConvertHashToNix3243=== RUN TestGetStorePathHash44=== PAUSE TestGetStorePathHash45=== RUN TestPathInfoHashCompatibility46=== PAUSE TestPathInfoHashCompatibility47=== RUN TestParsePathInfoJSON48=== PAUSE TestParsePathInfoJSON49=== RUN TestParsePathInfoJSONMultiplePaths50=== PAUSE TestParsePathInfoJSONMultiplePaths51=== RUN TestPathInfoCACompatibility52=== PAUSE TestPathInfoCACompatibility53=== RUN TestRateLimiterFeedback54=== PAUSE TestRateLimiterFeedback55=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess56=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess57=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer58=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer59=== RUN TestResolveStorePath60=== PAUSE TestResolveStorePath61=== RUN TestDoWithRetry_BodyReplayedViaGetBody62=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody63=== RUN TestRetryTimeoutOutlastsMaxRetries64=== PAUSE TestRetryTimeoutOutlastsMaxRetries65=== RUN TestDoWithRetry_FinalResponseBodyReadable66=== PAUSE TestDoWithRetry_FinalResponseBodyReadable67=== RUN TestShellSplit68=== PAUSE TestShellSplit69=== RUN TestShellSplitErrors70=== PAUSE TestShellSplitErrors71=== RUN TestStreamPushReportsEveryPath72=== PAUSE TestStreamPushReportsEveryPath73=== RUN TestStreamPushBatchesUnderLoad74=== PAUSE TestStreamPushBatchesUnderLoad75=== RUN TestStreamPushIsolatesFailures76=== PAUSE TestStreamPushIsolatesFailures77=== RUN TestStreamPushGivesUpOnDeadServer78=== PAUSE TestStreamPushGivesUpOnDeadServer79=== RUN TestStreamPushRequestLine80=== PAUSE TestStreamPushRequestLine81=== RUN TestStreamPushReportsSignatures82=== PAUSE TestStreamPushReportsSignatures83=== RUN TestStreamPushReportsSkippedPaths84=== PAUSE TestStreamPushReportsSkippedPaths85=== RUN TestClientSignaturesByStorePath86=== PAUSE TestClientSignaturesByStorePath87=== RUN TestStreamPushStopsWhenCanceled88=== PAUSE TestStreamPushStopsWhenCanceled89=== RUN TestSetClientTLS90=== PAUSE TestSetClientTLS91=== RUN TestSetClientTLSDoesNotMutateDefaultTransport92=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport93=== RUN TestSetClientTLSErrors94=== PAUSE TestSetClientTLSErrors95=== RUN TestStaticToken96=== PAUSE TestStaticToken97=== RUN TestFileTokenReadsAndCaches98=== PAUSE TestFileTokenReadsAndCaches99=== RUN TestFileTokenMissing100=== PAUSE TestFileTokenMissing101=== RUN TestFileTokenEmpty102=== PAUSE TestFileTokenEmpty103=== RUN TestScriptTokenNoExpiryRerunsEveryCall104=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall105=== RUN TestScriptTokenCachesUntilRefresh106=== PAUSE TestScriptTokenCachesUntilRefresh107=== RUN TestScriptTokenEmptyToken108=== PAUSE TestScriptTokenEmptyToken109=== RUN TestScriptTokenBadJSON110=== PAUSE TestScriptTokenBadJSON111=== RUN TestScriptTokenScriptFails112=== PAUSE TestScriptTokenScriptFails113=== RUN TestScriptTokenEmptyCommand114=== PAUSE TestScriptTokenEmptyCommand115=== CONT TestDoServerRequestAttachesToken116=== CONT TestConvertHashToNix32117=== RUN TestConvertHashToNix32/SRI_format_to_Nix32118=== CONT TestStreamPushIsolatesFailures119=== CONT TestSetClientTLSErrors120=== CONT TestSetClientTLSDoesNotMutateDefaultTransport121=== CONT TestSetClientTLS122=== CONT TestStreamPushStopsWhenCanceled123=== CONT TestClientSignaturesByStorePath124=== CONT TestParsePathInfoJSONMultiplePaths125=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths1262026/11/02 09:25:59 ERROR Upload failed error="bad path" count=3127=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths128=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths129=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths130=== CONT TestStreamPushReportsSkippedPaths131=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess132=== CONT TestScriptTokenEmptyToken133=== CONT TestScriptTokenBadJSON1342026/11/02 09:25:59 WARN Rate limiter enabled after throttle name=server-test rate=5135=== CONT TestStreamPushReportsSignatures136=== CONT TestStreamPushGivesUpOnDeadServer137=== CONT TestResolveStorePath138=== CONT TestStreamPushBatchesUnderLoad139=== CONT TestStreamPushReportsEveryPath140=== CONT TestShellSplitErrors141=== CONT TestShellSplit142=== CONT TestDoWithRetry_FinalResponseBodyReadable143=== CONT TestRetryTimeoutOutlastsMaxRetries144=== CONT TestStaticToken145=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer146=== CONT TestDoWithRetry_BodyReplayedViaGetBody147=== CONT TestScriptTokenEmptyCommand148=== CONT TestParsePathInfoJSON149=== CONT TestPathInfoCACompatibility1502026/11/02 09:25:59 ERROR Upload failed error=boom count=1151=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32152=== CONT TestScriptTokenCachesUntilRefresh153=== RUN TestConvertHashToNix32/already_Nix32_format154=== RUN TestPathInfoCACompatibility/null_ca_field155=== CONT TestScriptTokenScriptFails156=== CONT TestStreamPushRequestLine1572026/11/02 09:25:59 ERROR Upload failed error="connection refused" count=201582026/11/02 09:25:59 ERROR Server seems unavailable, giving up on batch untried=17159--- PASS: TestStreamPushStopsWhenCanceled (0.00s)160--- PASS: TestClientSignaturesByStorePath (0.00s)161--- PASS: TestStreamPushReportsSkippedPaths (0.00s)162--- PASS: TestStreamPushIsolatesFailures (0.00s)163--- PASS: TestStaticToken (0.00s)164=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false165=== PAUSE TestConvertHashToNix32/already_Nix32_format166=== CONT TestPathInfoHashCompatibility167=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)168=== CONT TestFileTokenEmpty169=== CONT TestScriptTokenNoExpiryRerunsEveryCall170=== CONT TestFileTokenMissing171=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false172=== CONT TestGetStorePathHash173--- PASS: TestStreamPushReportsSignatures (0.00s)174=== RUN TestConvertHashToNix32/invalid_format175=== RUN TestParsePathInfoJSON/Nix_format176--- PASS: TestShellSplitErrors (0.00s)177--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)178--- PASS: TestShellSplit (0.00s)179--- PASS: TestResolveStorePath (0.00s)180--- PASS: TestScriptTokenEmptyCommand (0.00s)181--- PASS: TestStreamPushReportsEveryPath (0.00s)182=== PAUSE TestParsePathInfoJSON/Nix_format183=== RUN TestParsePathInfoJSON/Lix_format184=== PAUSE TestParsePathInfoJSON/Lix_format185=== RUN TestParsePathInfoJSON/empty_input186=== PAUSE TestParsePathInfoJSON/empty_input187=== RUN TestParsePathInfoJSON/whitespace_only188=== PAUSE TestParsePathInfoJSON/whitespace_only189=== RUN TestSetClientTLSErrors/missing_cert_file190=== PAUSE TestSetClientTLSErrors/missing_cert_file191=== PAUSE TestPathInfoCACompatibility/null_ca_field192=== RUN TestParsePathInfoJSON/invalid_JSON193=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true194=== PAUSE TestConvertHashToNix32/invalid_format1952026/11/02 09:25:59 ERROR Upload failed error=boom count=1196=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)197=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon1982026/11/02 09:25:59 WARN Rate limiter enabled after throttle name=server-test rate=5199=== RUN TestGetStorePathHash/valid_store_path2002026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:33281201=== CONT TestUploadMultipart_PartsInParallel2022026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:435852032026/11/02 09:25:59 WARN Rate limiter enabled after throttle name=server-test rate=5204=== PAUSE TestGetStorePathHash/valid_store_path205--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)206--- PASS: TestScriptTokenEmptyToken (0.01s)207--- PASS: TestScriptTokenScriptFails (0.00s)208--- PASS: TestFileTokenMissing (0.00s)209=== CONT TestFileTokenReadsAndCaches2102026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:43905211=== CONT TestRateLimiterFeedback212=== CONT TestEncodeNixBase32WithRealHash213=== CONT TestFilterOversizedClosures214=== CONT TestEncodeNixBase32215=== RUN TestPathInfoCACompatibility/old_string_format_-_text216=== PAUSE TestParsePathInfoJSON/invalid_JSON217=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true218=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon219=== CONT TestPartSizeForNAR220=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI221=== RUN TestPartSizeForNAR/zero_stays_at_minimum222=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI223=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512224=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512225=== RUN TestSetClientTLSErrors/missing_key_file226=== PAUSE TestSetClientTLSErrors/missing_key_file227=== RUN TestSetClientTLSErrors/missing_ca_file228=== PAUSE TestSetClientTLSErrors/missing_ca_file229=== RUN TestSetClientTLSErrors/invalid_ca_file230=== PAUSE TestSetClientTLSErrors/invalid_ca_file231=== CONT TestUploadMultipart_FailedPartBufferNotReused232=== RUN TestRateLimiterFeedback/429_enables_limiter233=== CONT TestDumpPathMatchesNix234=== CONT TestSupersededNARStillUploadsListing235=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica236=== RUN TestGetStorePathHash/basename_without_hyphen_should_error2372026/11/02 09:25:59 WARN Rate limiter backed off name=server-test rate=52382026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:33281239=== CONT TestDumpPathWriterError2402026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:43585241=== PAUSE TestRateLimiterFeedback/429_enables_limiter242=== RUN TestRateLimiterFeedback/503_enables_limiter243--- PASS: TestFileTokenEmpty (0.00s)244--- PASS: TestScriptTokenBadJSON (0.01s)2452026/11/02 09:25:59 WARN Rate limiter backed off name=server-test rate=5246--- PASS: TestEncodeNixBase32WithRealHash (0.00s)247=== CONT TestDumpPathSingleFile248=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum249=== CONT TestCaseHackSuffix250=== CONT TestUploadMultipart_SupersededByPeer251=== RUN TestSupersededNARStillUploadsListing/small_NAR252=== RUN TestFilterOversizedClosures/no_limit_keeps_everything253=== RUN TestEncodeNixBase32/test_string_hash254=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text255=== RUN TestSetClientTLS/rejects_connection_without_client_cert256=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error257=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error258=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun259=== RUN TestUploadMultipart_SupersededByPeer/exists260=== PAUSE TestUploadMultipart_SupersededByPeer/exists261=== RUN TestUploadMultipart_SupersededByPeer/missing262=== PAUSE TestUploadMultipart_SupersededByPeer/missing263=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error264=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error265=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error266=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry267=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths268--- PASS: TestFileTokenReadsAndCaches (0.00s)269--- PASS: TestDoServerRequestAttachesToken (0.01s)270=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths271=== CONT TestConvertHashToNix32/SRI_format_to_Nix32272=== PAUSE TestEncodeNixBase32/test_string_hash2732026/11/02 09:25:59 INFO Garbage collection started274=== RUN TestEncodeNixBase32/empty_input2752026/11/02 09:25:59 INFO Garbage collection started276=== CONT TestRegisterUploadedObjectReusesConnections277=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive278=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive279=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert280=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA281=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA282=== RUN TestSetClientTLS/preserves_debug_logging_transport283=== PAUSE TestSetClientTLS/preserves_debug_logging_transport284=== PAUSE TestRateLimiterFeedback/503_enables_limiter285=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter286=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter287=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter288=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter289=== CONT TestConvertHashToNix32/already_Nix32_format290=== CONT TestParsePathInfoJSON/whitespace_only291=== CONT TestParsePathInfoJSON/invalid_JSON292=== CONT TestParsePathInfoJSON/empty_input293=== CONT TestParsePathInfoJSON/Lix_format2942026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:43585295=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false296=== RUN TestPartSizeForNAR/small_stays_at_minimum297=== PAUSE TestPartSizeForNAR/small_stays_at_minimum298=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum299=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum300=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts301=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts302=== RUN TestPartSizeForNAR/1_TiB303=== PAUSE TestPartSizeForNAR/1_TiB304=== RUN TestPartSizeForNAR/5_TiB_S3_max_object305=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object306=== RUN TestPartSizeForNAR/capped_at_5_GiB307=== PAUSE TestPartSizeForNAR/capped_at_5_GiB308=== CONT TestParsePathInfoJSON/Nix_format309=== PAUSE TestSupersededNARStillUploadsListing/small_NAR310=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true311=== RUN TestSupersededNARStillUploadsListing/dump_cut_short312=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short313=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails314=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails315=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)316=== CONT TestSetClientTLSErrors/invalid_ca_file317=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512318=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI3192026/11/02 09:25:59 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=0320=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon321=== CONT TestSetClientTLSErrors/missing_ca_file322=== CONT TestUploadMultipart_SupersededByPeer/exists3232026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:43585324=== CONT TestGetStorePathHash/valid_store_path325=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error326=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error327=== CONT TestGetStorePathHash/basename_without_hyphen_should_error328=== CONT TestUploadMultipart_SupersededByPeer/missing3292026/11/02 09:25:59 WARN Rate limiter enabled after throttle name=s3-test rate=5330=== CONT TestSetClientTLSErrors/missing_key_file3312026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:46507332=== CONT TestRateLimiterFeedback/429_enables_limiter3332026/11/02 09:25:59 WARN Garbage collection finished on another replica. Its statistics are not available here334=== CONT TestSetClientTLS/rejects_connection_without_client_cert335=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3362026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:43585337=== CONT TestPartSizeForNAR/zero_stays_at_minimum338--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.03s)339=== CONT TestConvertHashToNix32/invalid_format340=== PAUSE TestEncodeNixBase32/empty_input341=== RUN TestPathInfoCACompatibility/new_structured_format_-_text342=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything343=== CONT TestSetClientTLSErrors/missing_cert_file344=== CONT TestSetClientTLS/preserves_debug_logging_transport345--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.03s)3462026/11/02 09:25:59 WARN Rate limiter enabled after throttle name=server-test rate=5347=== CONT TestPartSizeForNAR/5_TiB_S3_max_object3482026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:39257349=== CONT TestPartSizeForNAR/1_TiB350=== CONT TestSupersededNARStillUploadsListing/small_NAR3512026/11/02 09:25:59 WARN Rate limiter backed off name=server-test rate=53522026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:43585353=== CONT TestPartSizeForNAR/small_stays_at_minimum354=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails3552026/11/02 09:25:59 INFO Uploading abc-hello (1.0GB)3562026/11/02 09:25:59 INFO Uploading abc-hello (1.0GB)357=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter358=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum359=== CONT TestSupersededNARStillUploadsListing/dump_cut_short360=== CONT TestRateLimiterFeedback/503_enables_limiter361=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts362=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text363=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped364--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)365 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)366 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)367=== CONT TestPartSizeForNAR/capped_at_5_GiB368=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter369=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method370--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.00s)371--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.03s)372--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)373--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.00s)374--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)375=== CONT TestEncodeNixBase32/test_string_hash376=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method377=== CONT TestPathInfoCACompatibility/null_ca_field378=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped379--- PASS: TestParsePathInfoJSON (0.00s)380 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)381 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)382 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)383 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)384 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)385=== CONT TestEncodeNixBase32/empty_input386=== CONT TestPathInfoCACompatibility/old_string_format_-_text387=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method388=== CONT TestPathInfoCACompatibility/new_structured_format_-_text389=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive390--- PASS: TestPathInfoHashCompatibility (0.00s)391 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)392 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)393 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)394 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)395--- PASS: TestGetStorePathHash (0.03s)396 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)397 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)398 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)399 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)400--- PASS: TestPartSizeForNAR (0.03s)401 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)402 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)403 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)404 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)405 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)406 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)407 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)408--- PASS: TestEncodeNixBase32 (0.03s)409 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)410 --- PASS: TestEncodeNixBase32/empty_input (0.00s)4112026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:43585412--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)413 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)414 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)415=== RUN TestFilterOversizedClosures/all_closures_skipped416=== PAUSE TestFilterOversizedClosures/all_closures_skipped417=== CONT TestFilterOversizedClosures/no_limit_keeps_everything418--- PASS: TestStreamPushBatchesUnderLoad (0.01s)419 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)420 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)421--- PASS: TestPathInfoCACompatibility (0.04s)422 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)423 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)424 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)425 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)426 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)427=== CONT TestFilterOversizedClosures/all_closures_skipped4282026/11/02 09:25:59 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=50429=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped4302026/11/02 09:25:59 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=2000431--- PASS: TestSetClientTLSErrors (0.01s)432 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)433 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)434 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)435 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)436--- PASS: TestFilterOversizedClosures (0.05s)437 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)438 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)439 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)440--- PASS: TestConvertHashToNix32 (0.01s)441 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)442 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)443 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)4442026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:435854452026/11/02 09:25:59 WARN Rate limiter enabled after throttle name=server-test rate=54462026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:387134472026/11/02 09:25:59 WARN Rate limiter backed off name=server-test rate=5448--- PASS: TestRateLimiterFeedback (0.03s)449 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)450 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)451 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)452 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)4532026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:435854542026/11/02 09:25:59 http: TLS handshake error from 127.0.0.1:45512: remote error: tls: bad certificate455--- PASS: TestStreamPushRequestLine (0.05s)4562026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:43585457--- PASS: TestSetClientTLS (0.04s)458 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)459 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)460 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)4612026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:435854622026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:435854632026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:435854642026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:435854652026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:43585466--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)4672026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:43585468--- PASS: TestCaseHackSuffix (0.03s)4692026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:435854702026/11/02 09:25:59 WARN Rate limiter enabled after throttle name=s3-test rate=5471--- PASS: TestDumpPathSingleFile (0.03s)4722026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:435854732026/11/02 09:25:59 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:43585474--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.07s)475--- PASS: TestDumpPathWriterError (0.05s)476--- PASS: TestDumpPathMatchesNix (0.11s)4772026/11/02 09:25:59 INFO Uploading abc-hello (1.0GB)4782026/11/02 09:25:59 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:42593/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:42593/part/24792026/11/02 09:25:59 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:42593/part/3\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:42593/part/34802026/11/02 09:25:59 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:42593/part/4\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:42593/part/44812026/11/02 09:25:59 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"482--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.62s)483--- PASS: TestUploadMultipart_PartsInParallel (0.65s)484--- PASS: TestSupersededNARStillUploadsListing (0.03s)485 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.01s)486 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.01s)487 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.68s)488--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4892026/11/02 09:26:00 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:39155/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:39155/api/uploads/complete4902026/11/02 09:26:00 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4912026/11/02 09:26:00 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:39155/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:39155/api/uploads/complete4922026/11/02 09:26:00 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4932026/11/02 09:26:00 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:39155/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:39155/api/uploads/complete4942026/11/02 09:26:00 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"495--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)496PASS497Running server tests...498The files belonging to this database system will be owned by user "nixbld".499This user must also own the server process.500501The database cluster will be initialized with locale "C".502The default database encoding has accordingly been set to "SQL_ASCII".503The default text search configuration will be set to "english".504505Data page checksums are enabled.506507creating directory /build/postgres149365723/data ... ok508creating subdirectories ... ok509selecting dynamic shared memory implementation ... posix510selecting default "max_connections" ... 100511selecting default "shared_buffers" ... 128MB512selecting default time zone ... UTC513creating configuration files ... ok514running bootstrap script ... ok515performing post-bootstrap initialization ... ok516syncing data to disk ... ok517518initdb: warning: enabling "trust" authentication for local connections519initdb: 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.520521Success. You can now start the database server using:522523 pg_ctl -D /build/postgres149365723/data -l logfile start524525/build/postgres149365723:5432 - no response5262026-11-02 09:26:01.603 UTC [129] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit5272026-11-02 09:26:01.604 UTC [129] LOG: listening on Unix socket "/build/postgres149365723/.s.PGSQL.5432"5282026-11-02 09:26:01.607 UTC [136] LOG: database system was shut down at 2026-11-02 09:26:01 UTC5292026-11-02 09:26:01.611 UTC [129] LOG: database system is ready to accept connections530/build/postgres149365723:5432 - accepting connections531{"timestamp":"2026-11-02T09:26:01.909690847Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"7e35f874-8cf5-4357-9efc-9cf69b4231c9","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(140)"}532=== RUN TestAbortSucceeded533=== PAUSE TestAbortSucceeded534=== 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/02 09:26:02 INFO lead: acquired remote=192.0.2.1:12345822026/11/02 09:26:02 INFO lead: released remote=192.0.2.1:12345832026/11/02 09:26:02 INFO lead: acquired remote=192.0.2.1:12345842026/11/02 09:26:03 INFO lead: released remote=192.0.2.1:1234585--- PASS: TestLeadIncumbentWinsAfterRestart (1.88s)586=== RUN TestLeadIncumbentAnnouncesAtOnce587=== PAUSE TestLeadIncumbentAnnouncesAtOnce588=== RUN TestLeadEndsOnShutdown589=== PAUSE TestLeadEndsOnShutdown590=== RUN TestLeadEndsWhenItsConnectionHangs5912026/11/02 09:26:04 INFO lead: acquired remote=192.0.2.1:12345922026-11-02 09:26:05.404 UTC [320] FATAL: terminating connection due to administrator command5932026/11/02 09:26:05 INFO lead: acquired remote=192.0.2.1:12345942026/11/02 09:26:06 WARN lead: lock connection lost error="timeout: context deadline exceeded"5952026/11/02 09:26:06 INFO lead: released remote=192.0.2.1:12345962026/11/02 09:26:06 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/02 09:26:06 INFO Starting HTTP server address=127.0.0.1:405736982026/11/02 09:26:06 INFO Starting HTTP server address=proxy.sock6992026/11/02 09:26:06 WARN mTLS auth: subject not in bound subjects subject="CN=someone"7002026/11/02 09:26:06 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 TestRedundantAbortSkipsCompletingUpload755=== PAUSE TestRedundantAbortSkipsCompletingUpload756=== RUN TestCompleteRefusedAfterAbortClaim757=== PAUSE TestCompleteRefusedAfterAbortClaim758=== RUN TestCompletedNarNotReofferedAcrossClosures759=== PAUSE TestCompletedNarNotReofferedAcrossClosures760=== RUN TestPresignedUploadRegisteredBeforeCommit761=== PAUSE TestPresignedUploadRegisteredBeforeCommit762=== RUN TestService_Rustfstest763=== PAUSE TestService_Rustfstest764=== RUN TestParseSize765=== PAUSE TestParseSize766=== RUN TestSkippedUploadsHandler767=== PAUSE TestSkippedUploadsHandler768=== RUN TestSystemdListenerNotActivated769--- PASS: TestSystemdListenerNotActivated (0.00s)770=== RUN TestWatchdogBeatsWhenHealthy771--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)772=== RUN TestWatchdogSkipsWhenUnhealthy7732026/11/02 09:26:06 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/11/02 09:26:06 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7752026/11/02 09:26:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7762026/11/02 09:26:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7772026/11/02 09:26:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7782026/11/02 09:26:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7792026/11/02 09:26:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7802026/11/02 09:26:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7812026/11/02 09:26:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7822026/11/02 09:26:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"783--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)784=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle785=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle786=== RUN TestProxyWriteTimeout787=== PAUSE TestProxyWriteTimeout788=== RUN TestPendingClosureWriteTimeout789=== PAUSE TestPendingClosureWriteTimeout790=== RUN TestIsValidUploadKey791=== PAUSE TestIsValidUploadKey792=== RUN TestUploadHandlersRejectInvalidKeys793=== PAUSE TestUploadHandlersRejectInvalidKeys794=== RUN TestUploadHandlersRejectOversizedBody795=== PAUSE TestUploadHandlersRejectOversizedBody796=== RUN TestService_cleanupPendingClosuresHandler797=== PAUSE TestService_cleanupPendingClosuresHandler798=== RUN TestService_createPendingClosureHandler799=== PAUSE TestService_createPendingClosureHandler800=== RUN TestService_verifyS3Integrity801=== PAUSE TestService_verifyS3Integrity802=== RUN TestService_verifyS3ReuploadsStaleNarinfo803=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo804=== RUN TestCompleteMultipartUnregistered805=== PAUSE TestCompleteMultipartUnregistered806=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT807=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT808=== CONT TestAbortSucceeded809--- PASS: TestAbortSucceeded (0.00s)810=== CONT TestReadProxyDisabled811=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT812=== CONT TestCompleteMultipartUnregistered813=== CONT TestService_verifyS3ReuploadsStaleNarinfo814=== CONT TestService_verifyS3Integrity815=== CONT TestService_createPendingClosureHandler816=== CONT TestService_cleanupPendingClosuresHandler817=== CONT TestUploadHandlersRejectOversizedBody818=== CONT TestUploadHandlersRejectInvalidKeys819=== CONT TestIsValidUploadKey820=== RUN TestIsValidUploadKey/narinfo821=== CONT TestPendingClosureWriteTimeout822=== RUN TestPendingClosureWriteTimeout/empty823=== CONT TestProxyWriteTimeout824=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle825=== CONT TestSkippedUploadsHandler826=== CONT TestParseSize827=== CONT TestService_Rustfstest828=== CONT TestPresignedUploadRegisteredBeforeCommit829=== CONT TestCompletedNarNotReofferedAcrossClosures830=== CONT TestCompleteRefusedAfterAbortClaim831=== CONT TestRedundantAbortSkipsCompletingUpload832=== CONT TestCompleteMultipartUpload_ErrorButObjectExists833=== CONT TestRedundantMultipartUpload834=== CONT TestPush_SignsNarinfosOfItsPendingObjects835=== CONT TestPush_RejectsBadRequests836=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed837=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info838=== PAUSE TestIsValidUploadKey/narinfo839=== RUN TestIsValidUploadKey/nar_zst840=== PAUSE TestIsValidUploadKey/nar_zst841=== RUN TestIsValidUploadKey/nar_xz842=== RUN TestProxyWriteTimeout/narinfo8432026/11/02 09:26:07 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000844=== PAUSE TestPendingClosureWriteTimeout/empty845--- PASS: TestParseSize (0.00s)846=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit847=== RUN TestPendingClosureWriteTimeout/400_objects848=== PAUSE TestPendingClosureWriteTimeout/400_objects849=== RUN TestPendingClosureWriteTimeout/670k_objects850--- PASS: TestSkippedUploadsHandler (0.01s)851=== CONT TestPush_RootsAreLockedInByteOrder852=== PAUSE TestProxyWriteTimeout/narinfo853=== RUN TestProxyWriteTimeout/1_GiB_nar854=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info855=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal856=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal857=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key858=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key859=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key860=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key861=== CONT TestPush_CompleteWaitsForCleanupOfThePush862=== PAUSE TestPendingClosureWriteTimeout/670k_objects863=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline864=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed865=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline866=== PAUSE TestProxyWriteTimeout/1_GiB_nar867=== RUN TestProxyWriteTimeout/10_GiB_nar868=== PAUSE TestIsValidUploadKey/nar_xz869=== RUN TestIsValidUploadKey/nar_plain870=== PAUSE TestIsValidUploadKey/nar_plain871=== RUN TestIsValidUploadKey/listing872=== PAUSE TestIsValidUploadKey/listing873=== RUN TestIsValidUploadKey/build_log874=== PAUSE TestIsValidUploadKey/build_log875=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed876=== CONT TestPush_RepeatedRootCommitsOnce877=== PAUSE TestProxyWriteTimeout/10_GiB_nar878=== RUN TestProxyWriteTimeout/unknown_size879=== PAUSE TestProxyWriteTimeout/unknown_size880=== RUN TestIsValidUploadKey/build_log_home-manager_file881=== PAUSE TestIsValidUploadKey/build_log_home-manager_file882=== RUN TestIsValidUploadKey/build_log_plus_in_name883=== PAUSE TestIsValidUploadKey/build_log_plus_in_name884=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed885=== CONT TestPush_CompleteCommitsEveryRoot886=== RUN TestIsValidUploadKey/build_log_question_mark887=== PAUSE TestIsValidUploadKey/build_log_question_mark888=== RUN TestIsValidUploadKey/build_log_equals889=== PAUSE TestIsValidUploadKey/build_log_equals890=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost891=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost892=== RUN TestIsValidUploadKey/realisation893=== PAUSE TestIsValidUploadKey/realisation894=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed895=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed896=== RUN TestIsValidUploadKey/realisation_plus_in_output897=== PAUSE TestIsValidUploadKey/realisation_plus_in_output898=== RUN TestIsValidUploadKey/nix-cache-info899=== PAUSE TestIsValidUploadKey/nix-cache-info900=== RUN TestIsValidUploadKey/index.html901=== PAUSE TestIsValidUploadKey/index.html902=== RUN TestIsValidUploadKey/narinfo_key,_nar_type903=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type904=== RUN TestIsValidUploadKey/nar_key,_narinfo_type905=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type906=== RUN TestIsValidUploadKey/listing_key,_narinfo_type907=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type908=== RUN TestIsValidUploadKey/traversal909=== PAUSE TestIsValidUploadKey/traversal910=== RUN TestIsValidUploadKey/traversal_nar911=== PAUSE TestIsValidUploadKey/traversal_nar912=== RUN TestIsValidUploadKey/absolute913=== PAUSE TestIsValidUploadKey/absolute914=== RUN TestIsValidUploadKey/empty_key915=== PAUSE TestIsValidUploadKey/empty_key916=== RUN TestIsValidUploadKey/unknown_type917=== PAUSE TestIsValidUploadKey/unknown_type918=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed919=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed920=== CONT TestPush_OverlappingRootsStoreOneRowPerKey921=== CONT TestReadRedirectUsesPublicS3URL922=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart923=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart924=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts925=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts926=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure927=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure928=== CONT TestReadProxyRangeRequest9292026/11/02 09:26:07 INFO Received uploads request method=POST path=/api/pending_closures9302026/11/02 09:26:07 INFO Received uploads request method=POST path=/api/pending_closures9312026/11/02 09:26:07 INFO Received uploads request method=POST path=/api/pending_closures9322026/11/02 09:26:07 INFO Received uploads request method=POST path=/api/pending_closures9332026/11/02 09:26:07 INFO Received uploads request method=POST path=/api/pending_closures934--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.43s)935=== CONT TestReadRedirectKeepsNarinfoProxied936--- PASS: TestReadProxyDisabled (0.44s)937=== CONT TestReadRedirectNar9382026/11/02 09:26:07 INFO Received uploads request method=POST path=/api/pending_closures9392026/11/02 09:26:07 INFO Received uploads request method=POST path=/api/pending_closures9402026/11/02 09:26:07 INFO Received uploads request method=POST path=/api/pending_closures9412026/11/02 09:26:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9422026/11/02 09:26:07 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst943--- PASS: TestCompleteMultipartUnregistered (0.61s)944=== CONT TestGCEndsOnShutdown945=== RUN TestGCEndsOnShutdown/before_the_run946=== PAUSE TestGCEndsOnShutdown/before_the_run947=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete948=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete949=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark950=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark951=== CONT TestReadProxyRootRedirectsToIndexHTML9522026/11/02 09:26:07 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9532026/11/02 09:26:07 INFO Received uploads request method=POST path=/api/pending_closures954--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.61s)955=== CONT TestReadProxyConditionalGet9562026/11/02 09:26:07 INFO Received push request method=POST path=/api/pushes9572026/11/02 09:26:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9582026/11/02 09:26:07 INFO Signed narinfos id=1 count=19592026/11/02 09:26:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9602026/11/02 09:26:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9612026/11/02 09:26:07 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"9622026/11/02 09:26:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9632026/11/02 09:26:07 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"9642026/11/02 09:26:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9652026/11/02 09:26:07 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=19662026/11/02 09:26:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9672026/11/02 09:26:07 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo968--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.66s)969=== CONT TestReadProxyOutlastsServerWriteTimeout9702026/11/02 09:26:07 INFO Received uploads request method=POST path=/api/pending_closures971--- PASS: TestService_Rustfstest (0.69s)972=== CONT TestReadProxyHead9732026/11/02 09:26:07 INFO Received uploads request method=POST path=/api/pending_closures9742026/11/02 09:26:07 INFO Received uploads request method=POST path=/api/pending_closures9752026/11/02 09:26:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9762026/11/02 09:26:07 INFO Received cleanup request method=DELETE path=/api/pending_closures9772026/11/02 09:26:07 INFO Aborted multipart uploads count=0 kept=09782026/11/02 09:26:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9792026/11/02 09:26:07 INFO Received uploads request method=POST path=/api/pending_closures9802026/11/02 09:26:07 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5LmE1YzZiOWNjLTcyNzktNDA1Ny05MzlkLTNjZTNlMTZhMDc0OHgxNzkzNjExNTY3OTA5NTg2MzMy9812026/11/02 09:26:07 INFO Received cleanup request method=DELETE path=/api/pending_closures9822026/11/02 09:26:07 INFO Aborted multipart uploads count=1 kept=09832026/11/02 09:26:07 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5LmE1YzZiOWNjLTcyNzktNDA1Ny05MzlkLTNjZTNlMTZhMDc0OHgxNzkzNjExNTY3OTA5NTg2MzMy parts=19842026/11/02 09:26:07 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9852026-11-02 09:26:07.955 UTC [406] ERROR: Closure does not exist: id=19862026-11-02 09:26:07.955 UTC [406] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9872026-11-02 09:26:07.955 UTC [406] STATEMENT: -- name: CommitPendingClosure :one988 SELECT commit_pending_closure($1::bigint)::bigint989 990--- PASS: TestService_cleanupPendingClosuresHandler (0.81s)991=== CONT TestReadProxyInvalidPath992--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.80s)993=== CONT TestReadProxy4049942026/11/02 09:26:07 INFO Received push request method=POST path=/api/pushes9952026/11/02 09:26:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9962026/11/02 09:26:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9972026/11/02 09:26:07 INFO Received push request method=POST path=/api/pushes9982026/11/02 09:26:07 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5LjFjYWEzYjQxLTFiNmMtNDJmNC04YTAwLTM2YzdjM2QyMDVhZHgxNzkzNjExNTY3NTIzNzQyMTgw parts=109992026/11/02 09:26:07 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10002026-11-02 09:26:07.994 UTC [448] ERROR: could not obtain lock on row in relation "closures"10012026-11-02 09:26:07.994 UTC [448] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10022026-11-02 09:26:07.994 UTC [448] ERROR: could not obtain lock on row in relation "closures"10032026-11-02 09:26:07.994 UTC [448] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10042026-11-02 09:26:07.994 UTC [448] ERROR: could not obtain lock on row in relation "closures"10052026-11-02 09:26:07.994 UTC [448] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10062026-11-02 09:26:07.995 UTC [448] ERROR: could not obtain lock on row in relation "closures"10072026-11-02 09:26:07.995 UTC [448] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10082026-11-02 09:26:07.995 UTC [448] ERROR: could not obtain lock on row in relation "closures"10092026-11-02 09:26:07.995 UTC [448] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10102026/11/02 09:26:07 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5LjQxMmM5OGNjLWY4ODQtNDBlOS04NTBiLTljYTdjMGQ5NmZmNngxNzkzNjExNTY3NTQzMTg5MTcy parts=1010112026/11/02 09:26:07 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10122026/11/02 09:26:07 INFO Received complete push request method=POST path=/api/pushes/1/complete10132026/11/02 09:26:07 INFO Completed upload id=1 objects=2 duration=5.059638ms10142026/11/02 09:26:07 INFO Completed upload id=1 objects=2 duration=2.957159ms1015--- PASS: TestPush_RootsAreLockedInByteOrder (0.84s)1016=== CONT TestReadProxyNarStreaming10172026/11/02 09:26:07 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010182026/11/02 09:26:08 INFO Received uploads request method=POST path=/api/pending_closures10192026/11/02 09:26:08 INFO Received uploads request method=POST path=/api/pending_closures10202026/11/02 09:26:08 INFO Starting cleanup of old closures method=DELETE path=/api/closures10212026/11/02 09:26:08 INFO Received uploads request method=POST path=/api/pending_closures10222026/11/02 09:26:08 INFO Completed push id=1 objects=4 duration=7.464227ms1023--- PASS: TestPush_RepeatedRootCommitsOnce (0.76s)10242026/11/02 09:26:08 INFO Received uploads request method=POST path=/api/pending_closures1025=== CONT TestReadProxyContentNegotiation10262026/11/02 09:26:08 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10272026/11/02 09:26:08 WARN Found objects in DB but missing from S3, will re-upload count=11028--- PASS: TestService_verifyS3Integrity (0.86s)1029=== CONT TestReadProxyNarinfoAlreadyDecompressed10302026/11/02 09:26:08 INFO Aborted multipart uploads count=0 kept=010312026/11/02 09:26:08 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=010322026/11/02 09:26:08 INFO Received uploads request method=POST path=/api/pending_closures10332026/11/02 09:26:08 INFO Received push request method=POST path=/api/pushes10342026/11/02 09:26:08 INFO Vacuumed table table=pending_closures10352026/11/02 09:26:08 INFO Vacuumed table table=pending_objects10362026/11/02 09:26:08 INFO Vacuumed table table=multipart_uploads10372026/11/02 09:26:08 INFO Vacuumed table table=closures10382026/11/02 09:26:08 INFO Vacuumed table table=objects10392026/11/02 09:26:08 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001040--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.80s)1041=== CONT TestReadProxyNarinfo1042--- PASS: TestService_createPendingClosureHandler (0.91s)1043=== CONT TestIsValidCachePath1044=== RUN TestIsValidCachePath/narinfo1045=== PAUSE TestIsValidCachePath/narinfo1046=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1047=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1048=== RUN TestIsValidCachePath/nar_zst1049=== PAUSE TestIsValidCachePath/nar_zst1050=== RUN TestIsValidCachePath/nar_xz1051=== PAUSE TestIsValidCachePath/nar_xz1052=== RUN TestIsValidCachePath/nar_bz21053=== PAUSE TestIsValidCachePath/nar_bz21054=== RUN TestIsValidCachePath/nar_uncompressed1055=== PAUSE TestIsValidCachePath/nar_uncompressed1056=== RUN TestIsValidCachePath/ls1057=== PAUSE TestIsValidCachePath/ls1058=== RUN TestIsValidCachePath/log1059=== PAUSE TestIsValidCachePath/log1060=== RUN TestIsValidCachePath/realisation1061=== PAUSE TestIsValidCachePath/realisation1062=== RUN TestIsValidCachePath/nix-cache-info1063=== PAUSE TestIsValidCachePath/nix-cache-info1064=== RUN TestIsValidCachePath/index.html1065=== PAUSE TestIsValidCachePath/index.html1066=== RUN TestIsValidCachePath/traversal_parent1067=== PAUSE TestIsValidCachePath/traversal_parent1068=== RUN TestIsValidCachePath/traversal_in_middle1069=== PAUSE TestIsValidCachePath/traversal_in_middle1070=== RUN TestIsValidCachePath/invalid_char_e1071=== PAUSE TestIsValidCachePath/invalid_char_e1072=== RUN TestIsValidCachePath/invalid_char_u1073=== PAUSE TestIsValidCachePath/invalid_char_u1074=== RUN TestIsValidCachePath/random_path1075=== PAUSE TestIsValidCachePath/random_path1076=== RUN TestIsValidCachePath/empty1077=== PAUSE TestIsValidCachePath/empty1078=== RUN TestIsValidCachePath/leading_slash1079=== PAUSE TestIsValidCachePath/leading_slash1080=== RUN TestIsValidCachePath/wrong_extension1081=== PAUSE TestIsValidCachePath/wrong_extension1082=== RUN TestIsValidCachePath/short_hash1083=== PAUSE TestIsValidCachePath/short_hash1084=== CONT TestParseSingleRange1085=== RUN TestParseSingleRange/none1086=== PAUSE TestParseSingleRange/none1087=== RUN TestParseSingleRange/unknown_unit1088=== PAUSE TestParseSingleRange/unknown_unit1089=== RUN TestParseSingleRange/multi-range_ignored1090=== PAUSE TestParseSingleRange/multi-range_ignored1091=== RUN TestParseSingleRange/malformed_no_dash1092=== PAUSE TestParseSingleRange/malformed_no_dash1093=== RUN TestParseSingleRange/malformed_both_empty1094=== PAUSE TestParseSingleRange/malformed_both_empty1095=== RUN TestParseSingleRange/malformed_end_before_start1096=== PAUSE TestParseSingleRange/malformed_end_before_start1097=== RUN TestParseSingleRange/closed1098=== PAUSE TestParseSingleRange/closed1099=== RUN TestParseSingleRange/open-ended1100=== PAUSE TestParseSingleRange/open-ended1101=== RUN TestParseSingleRange/end_clamped_to_size1102=== PAUSE TestParseSingleRange/end_clamped_to_size1103=== RUN TestParseSingleRange/suffix1104=== PAUSE TestParseSingleRange/suffix1105=== RUN TestParseSingleRange/suffix_exceeds_size1106=== PAUSE TestParseSingleRange/suffix_exceeds_size1107=== RUN TestParseSingleRange/single_byte1108=== PAUSE TestParseSingleRange/single_byte1109=== RUN TestParseSingleRange/start_past_EOF1110=== PAUSE TestParseSingleRange/start_past_EOF1111=== RUN TestParseSingleRange/start_far_past_EOF1112=== PAUSE TestParseSingleRange/start_far_past_EOF1113=== CONT TestPresentNotReportedWhileGCDeletesClosure1114=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1115=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1116=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1117=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1118=== CONT TestPresentRefreshesOnlyStaleClosures1119--- PASS: TestReadRedirectUsesPublicS3URL (0.82s)1120=== CONT TestPresentReportsOnlyClosureRoots1121--- PASS: TestReadProxyRangeRequest (0.76s)1122=== CONT TestCreatePin_ReservedPins1123=== RUN TestPush_RejectsBadRequests/no_roots1124=== PAUSE TestPush_RejectsBadRequests/no_roots1125=== RUN TestPush_RejectsBadRequests/no_objects1126=== PAUSE TestPush_RejectsBadRequests/no_objects1127=== RUN TestPush_RejectsBadRequests/bad_root1128=== PAUSE TestPush_RejectsBadRequests/bad_root1129=== RUN TestPush_RejectsBadRequests/root_not_in_objects1130=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1131=== CONT TestOrphanedObjectsGCStressTest11322026/11/02 09:26:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11332026/11/02 09:26:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46461/oidc11342026/11/02 09:26:08 INFO Received push request method=POST path=/api/pushes11352026/11/02 09:26:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11362026/11/02 09:26:08 ERROR Failed to get multipart upload error="no rows in result set" upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5LmZhNjAxZjM3LWNjMzAtNDdkYS1hYmE5LTI3MzZkOGM2MmE1OHgxNzkzNjExNTY3NjQ2NDI1Nzc5 object_key=nar/gggggggggggggggggggggggggggggg0500000000000000000000.nar.zst11372026/11/02 09:26:08 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0500000000000000000000.nar.zst upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5LjRiYmNmYjQyLTVkNTItNGNkZi05MDRkLTNkMTQ0ZTY3NmE5Y3gxNzkzNjExNTY3NjE2ODU2NDMx parts=121138--- PASS: TestCompleteRefusedAfterAbortClaim (1.00s)1139=== CONT TestOrphanedObjectsGC11402026/11/02 09:26:08 INFO Received uploads request method=POST path=/api/pending_closures11412026/11/02 09:26:08 INFO Received uploads request method=POST path=/api/pending_closures11422026/11/02 09:26:08 INFO Received push request method=POST path=/api/pushes11432026/11/02 09:26:08 INFO Received complete push request method=POST path=/api/pushes/1/complete11442026/11/02 09:26:08 INFO Completed push id=1 objects=6 duration=8.322046ms1145--- PASS: TestPush_CompleteCommitsEveryRoot (0.98s)1146=== CONT TestObjectStatsUpdatedOncePerCommit11472026/11/02 09:26:08 INFO Received push request method=POST path=/api/pushes11482026/11/02 09:26:08 INFO Received complete push request method=POST path=/api/pushes/1/complete11492026/11/02 09:26:08 INFO Completed push id=1 objects=4 duration=10.990936ms11502026/11/02 09:26:08 INFO Received push request method=POST path=/api/pushes1151--- PASS: TestReadRedirectNar (0.68s)1152=== CONT TestObjectStatsTrigger1153--- PASS: TestReadRedirectKeepsNarinfoProxied (0.72s)1154=== CONT TestPendingCleanupUsesOneCutoff11552026/11/02 09:26:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1156--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.56s)1157=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded11582026/11/02 09:26:08 INFO Aborted multipart uploads count=0 kept=011592026/11/02 09:26:08 WARN Force mode enabled - objects will be deleted immediately without grace period11602026/11/02 09:26:08 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5LjU2YmUxZTkxLWE3MmMtNGMzNS04MDVmLTYwZDc3MjI2NTQwN3gxNzkzNjExNTY3ODgxMDUzNDk0 parts=1211612026/11/02 09:26:08 INFO Received uploads request method=POST path=/api/pending_closures1162--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.19s)1163=== CONT TestMultipartCleanup11642026/11/02 09:26:08 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=011652026/11/02 09:26:08 INFO Vacuumed table table=pending_closures11662026/11/02 09:26:08 INFO Vacuumed table table=pending_objects11672026/11/02 09:26:08 INFO Vacuumed table table=multipart_uploads1168--- PASS: TestReadProxyConditionalGet (0.60s)1169=== CONT TestServerTLSConfig1170=== RUN TestServerTLSConfig/no_client_CA1171=== PAUSE TestServerTLSConfig/no_client_CA1172=== RUN TestServerTLSConfig/missing_CA_file1173=== PAUSE TestServerTLSConfig/missing_CA_file1174=== RUN TestServerTLSConfig/not_a_PEM_file1175=== PAUSE TestServerTLSConfig/not_a_PEM_file1176=== CONT TestService_NativeMTLS11772026/11/02 09:26:08 INFO Vacuumed table table=closures11782026/11/02 09:26:08 INFO Vacuumed table table=objects11792026/11/02 09:26:08 INFO Received complete push request method=POST path=/api/pushes/2/complete11802026/11/02 09:26:08 INFO Completed push id=2 objects=4 duration=5.102018ms1181--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (1.22s)1182=== CONT TestMetricsCommit1183--- PASS: TestReadProxyHead (0.57s)1184=== CONT TestMetricsInventory1185--- PASS: TestReadProxyInvalidPath (0.50s)1186=== CONT TestNARDeduplicationMetadataUploadBug11872026-11-02 09:26:08.477 UTC [490] ERROR: Push does not exist: id=111882026-11-02 09:26:08.477 UTC [490] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE11892026-11-02 09:26:08.477 UTC [490] STATEMENT: SELECT commit_push($1)1190--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (1.23s)1191=== CONT TestCreatePendingClosureRejectsOversizedNAR11922026/11/02 09:26:08 INFO Received uploads request method=POST path=/api/pending_closures1193--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1194=== CONT TestCacheConfigHandlerMaxNarSize1195--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1196=== CONT TestGenerateLandingPage1197--- PASS: TestGenerateLandingPage (0.00s)1198=== CONT TestService_readinessHandler1199--- PASS: TestReadProxyNarStreaming (0.49s)1200=== CONT TestService_healthCheckHandler1201--- PASS: TestReadProxy404 (0.53s)1202=== CONT TestGracefulShutdownDrainsInflight12032026/11/02 09:26:08 INFO Starting HTTP server address=127.0.0.1:3685912042026/11/02 09:26:08 INFO Shutdown signal received, draining in-flight requests timeout=10s12052026/11/02 09:26:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1206--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.50s)1207=== CONT TestGCTaskStore_Fail1208--- PASS: TestGCTaskStore_Fail (0.00s)1209=== CONT TestGCTaskStore_PhaseUpdates1210--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1211=== CONT TestGCTaskStore_CompletedAllowsNewTask1212--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1213=== CONT TestGCTaskStore_GetReturnsLatest1214--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1215=== CONT TestGCTaskStore_GetEmpty1216--- PASS: TestGCTaskStore_GetEmpty (0.00s)1217=== CONT TestGCTaskStore_ConflictDifferentParams1218--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1219=== CONT TestGCTaskStore_DeduplicateSameParams1220--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1221=== CONT TestGCTaskStore_StartNew1222--- PASS: TestGCTaskStore_StartNew (0.00s)1223=== CONT TestResolveDBConnectionString1224=== RUN TestResolveDBConnectionString/flag_wins1225=== PAUSE TestResolveDBConnectionString/flag_wins1226=== RUN TestResolveDBConnectionString/file_when_flag_empty1227=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1228=== RUN TestResolveDBConnectionString/missing_file_is_an_error1229=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1230=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1231=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1232=== RUN TestResolveDBConnectionString/nothing_configured1233=== PAUSE TestResolveDBConnectionString/nothing_configured1234=== CONT TestCommitRacingPendingCleanupKeepsObjects12352026/11/02 09:26:08 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5LjBkZTIxMzdhLWY0N2EtNDljOC04YjUxLTIzYzBiMGRlZTA1NngxNzkzNjExNTY4MDIyNjAxNjA2 parts=1212362026/11/02 09:26:08 INFO Received uploads request method=POST path=/api/pending_closures1237--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1238=== CONT TestPushWaitsForSweepHoldingRow12392026/11/02 09:26:08 INFO Received uploads request method=POST path=/api/pending_closures1240--- PASS: TestReadProxyContentNegotiation (0.57s)1241=== CONT TestSweepRechecksPendingAfterLocking1242--- PASS: TestPresentRefreshesOnlyStaleClosures (0.54s)1243=== CONT TestGetExistingObjectsLocksRows1244--- PASS: TestPresentReportsOnlyClosureRoots (0.56s)1245=== CONT TestRegisterCompletedObjectNeedsPendingRow12462026/11/02 09:26:08 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1247--- PASS: TestReadProxyNarinfo (0.58s)1248=== CONT TestSweepSkipsRowsLockedByPush12492026/11/02 09:26:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12502026/11/02 09:26:08 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12512026/11/02 09:26:08 WARN Refused reserved pin name=worker-x86_64-linux12522026/11/02 09:26:08 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12532026/11/02 09:26:08 INFO Received create pin request method=POST path=/api/pins/my-app12542026/11/02 09:26:08 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1255--- PASS: TestCreatePin_ReservedPins (0.57s)1256=== CONT TestFailedS3DeleteKeepsTombstone12572026/11/02 09:26:08 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0400000000000000000000.nar.zst upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5LmExMjU2ZGY0LWVmMTgtNGRlZC1iYjlhLTc5YTdkNmQ5ZTZiOXgxNzkzNjExNTY4MTgxMTc4MTcx parts=121258--- PASS: TestObjectStatsUpdatedOncePerCommit (0.53s)1259=== CONT TestForceGCDuringPushOffersSweptObject1260=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1261=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1262=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1263=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1264=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1265--- PASS: TestObjectStatsTrigger (0.52s)1266=== CONT TestGCSweepDeliversEachKeyOnce12672026/11/02 09:26:08 INFO Received uploads request method=POST path=/api/pending_closures12682026/11/02 09:26:08 INFO Received uploads request method=POST path=/api/pending_closures12692026/11/02 09:26:08 INFO Received uploads request method=POST path=/api/pending_closures12702026/11/02 09:26:08 INFO Received cleanup request method=DELETE path=/api/pending_closures1271--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.52s)1272=== CONT TestTombstonedObjectOfferedWithoutWaiting12732026/11/02 09:26:08 INFO Received uploads request method=POST path=/api/pending_closures12742026/11/02 09:26:08 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12752026/11/02 09:26:08 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1276--- PASS: TestService_NativeMTLS (0.51s)1277=== CONT TestGCSweepSkipsPendingObjects12782026/11/02 09:26:08 INFO Received push request method=POST path=/api/pushes12792026/11/02 09:26:08 INFO Received complete push request method=POST path=/api/pushes/1/complete12802026/11/02 09:26:08 INFO Completed push id=1 objects=4 duration=8.572756ms12812026/11/02 09:26:08 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12822026/11/02 09:26:08 INFO Completed upload id=2 objects=2 duration=1.566309ms1283--- PASS: TestMetricsCommit (0.57s)1284=== CONT TestDeduplicatedObjectsRecordedAsPending1285--- PASS: TestMetricsInventory (0.54s)1286=== CONT TestPushDedupSurvivesConcurrentGC12872026/11/02 09:26:08 INFO Received cleanup request method=DELETE path=/api/pending_closures12882026/11/02 09:26:08 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket49/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""12892026/11/02 09:26:08 INFO Aborted multipart uploads count=0 kept=112902026/11/02 09:26:08 INFO Received cleanup request method=DELETE path=/api/pending_closures12912026/11/02 09:26:08 INFO Aborted multipart uploads count=1 kept=01292--- PASS: TestMultipartCleanup (0.63s)1293=== CONT TestGCMetrics1294--- PASS: TestService_healthCheckHandler (0.49s)1295=== CONT TestGCBugBareHashReferences1296=== NAME TestNARDeduplicationMetadataUploadBug1297 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug2704070244/001/store/7j9gy61ry1bdzwzibkv99qawzxvv2ng9-file1.txt12982026/11/02 09:26:09 WARN readiness check failed error="closed pool"1299--- PASS: TestService_readinessHandler (0.52s)1300=== CONT TestGCAdvisoryLockBlocksConcurrentRun13012026/11/02 09:26:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13022026/11/02 09:26:09 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5LmEwYWEyNTY0LWMzZDItNGM4MS1iYmYyLWU3MmE5OTYwOTQwYngxNzkzNjExNTY4NTYzNTUzNTI1 error="Get \"http://127.0.0.1:1/bucket19/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"13032026/11/02 09:26:09 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5LmNlM2Y0NTczLWFhODQtNGQxZS1hZDNjLTBkNjhhMjEzYTMzZHgxNzkzNjExNTY4NTU1MDY3OTM4 parts=1213042026/11/02 09:26:09 INFO Received cleanup request method=DELETE path=/api/pending_closures13052026/11/02 09:26:09 INFO Received uploads request method=POST path=/api/pending_closures13062026/11/02 09:26:09 INFO Aborted multipart uploads count=1 kept=01307--- PASS: TestRedundantMultipartUpload (1.82s)1308=== CONT TestLeadEndsOnShutdown13092026/11/02 09:26:09 INFO Received push request method=POST path=/api/pushes13102026/11/02 09:26:09 INFO Aborted multipart uploads count=0 kept=013112026/11/02 09:26:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13122026/11/02 09:26:09 INFO Uploading 7j9gy61ry1bdzwzibkv99qawzxvv2ng9-file1.txt (160B)13132026/11/02 09:26:09 WARN Force mode enabled - objects will be deleted immediately without grace period13142026/11/02 09:26:09 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=013152026/11/02 09:26:09 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"13162026/11/02 09:26:09 WARN Failed to register uploaded object key=7j9gy61ry1bdzwzibkv99qawzxvv2ng9.ls error="server returned 404: 404 page not found\n"13172026/11/02 09:26:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13182026/11/02 09:26:09 INFO Signed narinfos id=1 count=113192026/11/02 09:26:09 INFO Uploading 1 narinfos13202026/11/02 09:26:09 INFO Vacuumed table table=pending_closures13212026/11/02 09:26:09 INFO Vacuumed table table=pending_objects13222026/11/02 09:26:09 INFO Vacuumed table table=multipart_uploads13232026/11/02 09:26:09 INFO Received complete push request method=POST path=/api/pushes/1/complete13242026/11/02 09:26:09 WARN Failed to register uploaded object key=7j9gy61ry1bdzwzibkv99qawzxvv2ng9.narinfo error="server returned 404: 404 page not found\n"13252026/11/02 09:26:09 INFO Vacuumed table table=closures13262026/11/02 09:26:09 INFO Vacuumed table table=objects1327--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.58s)1328=== CONT TestLeadIncumbentAnnouncesAtOnce13292026/11/02 09:26:09 INFO Completed push id=1 objects=3 duration=12.077655ms1330=== NAME TestOrphanedObjectsGC13312026/11/02 09:26:09 INFO Upload complete. (67ms)1332 orphaned_objects_gc_test.go:287: GC Test Summary:1333 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1334 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1335 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1336 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1337 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1338--- PASS: TestOrphanedObjectsGC (0.95s)1339=== CONT TestLeadElectsOneAndHandsOver1340=== NAME TestNARDeduplicationMetadataUploadBug1341 metadata_upload_test.go:54: Retrieved narinfo from S3:1342 StorePath: /build/TestNARDeduplicationMetadataUploadBug2704070244/001/store/7j9gy61ry1bdzwzibkv99qawzxvv2ng9-file1.txt1343 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1344 Compression: zstd1345 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1346 NarSize: 1601347 References: 1348 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf13492026/11/02 09:26:09 INFO Aborted multipart uploads count=0 kept=01350 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1351 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1352 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}13532026/11/02 09:26:09 WARN Force mode enabled - objects will be deleted immediately without grace period13542026/11/02 09:26:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13552026/11/02 09:26:09 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=01356--- PASS: TestGetExistingObjectsLocksRows (0.52s)1357=== CONT TestConnectWaitsForAPeerMigration13582026/11/02 09:26:09 INFO Vacuumed table table=pending_closures13592026/11/02 09:26:09 INFO Vacuumed table table=pending_objects13602026/11/02 09:26:09 INFO Vacuumed table table=multipart_uploads13612026/11/02 09:26:09 INFO Vacuumed table table=closures13622026/11/02 09:26:09 INFO Vacuumed table table=objects1363--- PASS: TestSweepRechecksPendingAfterLocking (0.55s)1364=== CONT TestService_AuthMiddleware_OIDC1365--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.51s)1366=== CONT TestCacheStatsHandler13672026/11/02 09:26:09 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0400000000000000000000.nar.zst upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5LjkwZGQ5MTFhLTEyZjktNDEwYy04NTkxLWMxMWIwN2YxNDg2M3gxNzkzNjExNTY4MTg5NDA1MzI4 parts=121368--- PASS: TestRedundantAbortSkipsCompletingUpload (1.89s)1369=== CONT TestCacheConfigHandler1370=== RUN TestCacheConfigHandler/full_config,_no_issuer1371=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1372=== RUN TestCacheConfigHandler/no_cache_url_configured1373=== PAUSE TestCacheConfigHandler/no_cache_url_configured1374=== RUN TestCacheConfigHandler/no_signing_keys1375=== PAUSE TestCacheConfigHandler/no_signing_keys1376=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1377=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1378=== CONT TestService_ReadScope_PublicByDefault1379=== NAME TestNARDeduplicationMetadataUploadBug1380 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug2704070244/001/store/ixcxvzvai830fdmhvlfc0kfypp4b2vir-file2.txt13812026/11/02 09:26:09 INFO Received uploads request method=POST path=/api/pending_closures13822026/11/02 09:26:09 INFO Aborted multipart uploads count=0 kept=013832026/11/02 09:26:09 WARN Force mode enabled - objects will be deleted immediately without grace period13842026/11/02 09:26:09 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=013852026/11/02 09:26:09 INFO Vacuumed table table=pending_closures13862026/11/02 09:26:09 INFO Vacuumed table table=pending_objects13872026/11/02 09:26:09 INFO Vacuumed table table=multipart_uploads13882026/11/02 09:26:09 INFO Vacuumed table table=closures13892026/11/02 09:26:09 INFO Vacuumed table table=objects13902026/11/02 09:26:09 INFO Received uploads request method=POST path=/api/pending_closures13912026/11/02 09:26:09 INFO Aborted multipart uploads count=0 kept=013922026/11/02 09:26:09 WARN Force mode enabled - objects will be deleted immediately without grace period13932026/11/02 09:26:09 INFO Received push request method=POST path=/api/pushes13942026/11/02 09:26:09 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)13952026/11/02 09:26:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40213/oidc13962026/11/02 09:26:09 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13972026/11/02 09:26:09 WARN Failed to register uploaded object key=ixcxvzvai830fdmhvlfc0kfypp4b2vir.ls error="server returned 404: 404 page not found\n"13982026/11/02 09:26:09 INFO Signed narinfos id=2 count=113992026/11/02 09:26:09 INFO Uploading 1 narinfos14002026/11/02 09:26:09 INFO Received complete push request method=POST path=/api/pushes/2/complete14012026/11/02 09:26:09 WARN Failed to register uploaded object key=ixcxvzvai830fdmhvlfc0kfypp4b2vir.narinfo error="server returned 404: 404 page not found\n"14022026/11/02 09:26:09 INFO Completed push id=2 objects=3 duration=3.773499ms14032026/11/02 09:26:09 INFO Upload complete. (53ms)1404 metadata_upload_test.go:76: Retrieved narinfo from S3:1405 StorePath: /build/TestNARDeduplicationMetadataUploadBug2704070244/001/store/ixcxvzvai830fdmhvlfc0kfypp4b2vir-file2.txt1406 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1407 Compression: zstd1408 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1409 NarSize: 1601410 References: 1411 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1412 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1413 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1414 {"version":1,"root":{"type":"regular","size":44}}1415--- PASS: TestNARDeduplicationMetadataUploadBug (0.77s)1416=== CONT TestService_RequireScope_OIDC14172026/11/02 09:26:09 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=014182026/11/02 09:26:09 INFO Vacuumed table table=pending_closures14192026/11/02 09:26:09 INFO Vacuumed table table=pending_objects14202026/11/02 09:26:09 INFO Vacuumed table table=multipart_uploads14212026/11/02 09:26:09 INFO Vacuumed table table=closures14222026/11/02 09:26:09 INFO Vacuumed table table=objects14232026/11/02 09:26:09 INFO Received uploads request method=POST path=/api/pending_closures1424--- PASS: TestSweepSkipsRowsLockedByPush (0.60s)1425=== CONT TestPinProtectsFromGC1426--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.40s)1427=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock14282026/11/02 09:26:09 INFO Aborted multipart uploads count=0 kept=014292026/11/02 09:26:09 INFO Aborted multipart uploads count=0 kept=014302026/11/02 09:26:09 WARN Force mode enabled - objects will be deleted immediately without grace period14312026/11/02 09:26:09 WARN Force mode enabled - objects will be deleted immediately without grace period14322026/11/02 09:26:09 INFO Received uploads request method=POST path=/api/pending_closures14332026/11/02 09:26:09 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."14342026/11/02 09:26:09 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1435--- PASS: TestFailedS3DeleteKeepsTombstone (0.59s)1436=== CONT TestDeleteClosuresRacingPins14372026/11/02 09:26:09 INFO Received uploads request method=POST path=/api/pending_closures14382026/11/02 09:26:09 INFO Aborted multipart uploads count=0 kept=014392026/11/02 09:26:09 WARN Force mode enabled - objects will be deleted immediately without grace period1440--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.35s)1441=== CONT TestClientFallsBackToClosures14422026/11/02 09:26:09 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=014432026/11/02 09:26:09 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=014442026/11/02 09:26:09 INFO Vacuumed table table=pending_closures14452026/11/02 09:26:09 INFO Vacuumed table table=pending_objects14462026/11/02 09:26:09 INFO Vacuumed table table=multipart_uploads14472026/11/02 09:26:09 INFO Vacuumed table table=pending_closures14482026/11/02 09:26:09 INFO Vacuumed table table=closures14492026/11/02 09:26:09 INFO Vacuumed table table=pending_objects14502026/11/02 09:26:09 INFO Vacuumed table table=multipart_uploads14512026/11/02 09:26:09 INFO Vacuumed table table=closures14522026/11/02 09:26:09 INFO Vacuumed table table=objects1453--- PASS: TestGCSweepDeliversEachKeyOnce (0.52s)1454=== CONT TestClientCADerivations14552026/11/02 09:26:09 INFO Vacuumed table table=objects1456--- PASS: TestGCSweepSkipsPendingObjects (0.44s)1457=== CONT TestClientPushesUseOnePush14582026/11/02 09:26:09 INFO Received uploads request method=POST path=/api/pending_closures14592026/11/02 09:26:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45231/oidc14602026/11/02 09:26:09 INFO Aborted multipart uploads count=0 kept=014612026/11/02 09:26:09 WARN Force mode enabled - objects will be deleted immediately without grace period14622026/11/02 09:26:09 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=014632026/11/02 09:26:09 INFO Vacuumed table table=pending_closures14642026/11/02 09:26:09 INFO Vacuumed table table=pending_objects14652026/11/02 09:26:09 INFO Vacuumed table table=multipart_uploads14662026/11/02 09:26:09 INFO Vacuumed table table=closures14672026/11/02 09:26:09 INFO Vacuumed table table=objects1468--- PASS: TestGCMetrics (0.39s)1469=== CONT TestClientSharedPathCommittedMidPush14702026/11/02 09:26:09 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"1471--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.39s)1472=== CONT TestClientMultipleUploads1473--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.65s)1474=== CONT TestService_ReadAuthMiddleware14752026/11/02 09:26:09 INFO lead: acquired remote=192.0.2.1:123414762026/11/02 09:26:09 INFO Aborted multipart uploads count=0 kept=014772026/11/02 09:26:09 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=014782026/11/02 09:26:09 INFO Vacuumed table table=pending_closures14792026/11/02 09:26:09 INFO Vacuumed table table=pending_objects14802026/11/02 09:26:09 INFO Vacuumed table table=multipart_uploads14812026/11/02 09:26:09 INFO lead: acquired remote=192.0.2.1:123414822026/11/02 09:26:09 INFO lead: released remote=192.0.2.1:12341483--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.34s)1484=== CONT TestClientWithDependencies14852026/11/02 09:26:09 INFO Vacuumed table table=closures14862026/11/02 09:26:09 INFO Vacuumed table table=objects14872026/11/02 09:26:09 INFO Aborted multipart uploads count=0 kept=014882026/11/02 09:26:09 WARN Force mode enabled - objects will be deleted immediately without grace period14892026/11/02 09:26:09 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=014902026/11/02 09:26:09 INFO Vacuumed table table=pending_closures14912026/11/02 09:26:09 INFO Vacuumed table table=pending_objects14922026/11/02 09:26:09 INFO Vacuumed table table=multipart_uploads14932026/11/02 09:26:09 INFO Vacuumed table table=closures14942026/11/02 09:26:09 INFO Vacuumed table table=objects1495--- PASS: TestPushDedupSurvivesConcurrentGC (0.51s)1496=== CONT TestClientIntegration14972026/11/02 09:26:09 INFO lead: acquired remote=192.0.2.1:12341498--- PASS: TestCacheStatsHandler (0.37s)1499=== CONT TestService_AuthMiddleware1500--- PASS: TestService_ReadScope_PublicByDefault (0.37s)1501=== CONT TestService_AuthMiddleware_MTLSProxyHeader1502=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1503=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1504=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1505=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1506=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1507=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1508=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1509=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1510=== CONT TestClientErrorHandling1511=== RUN TestClientErrorHandling/InvalidStorePath1512=== PAUSE TestClientErrorHandling/InvalidStorePath1513=== RUN TestClientErrorHandling/InvalidAuthToken1514=== PAUSE TestClientErrorHandling/InvalidAuthToken1515=== RUN TestClientErrorHandling/ServerNotAvailable1516=== PAUSE TestClientErrorHandling/ServerNotAvailable1517=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1518--- PASS: TestPushWaitsForSweepHoldingRow (1.01s)1519=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15202026/11/02 09:26:09 INFO Received uploads request method=POST path=/1521=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15222026/11/02 09:26:09 INFO Received complete multipart upload request method=POST path=/1523=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15242026/11/02 09:26:09 INFO Received request for more parts method=POST path=/1525=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15262026/11/02 09:26:09 INFO Received uploads request method=POST path=/1527--- PASS: TestUploadHandlersRejectInvalidKeys (0.10s)1528 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1529 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1530 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1531 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1532=== CONT TestPendingClosureWriteTimeout/empty1533=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1534--- PASS: TestGCBugBareHashReferences (0.62s)1535=== CONT TestPendingClosureWriteTimeout/670k_objects1536=== CONT TestPendingClosureWriteTimeout/400_objects1537=== CONT TestProxyWriteTimeout/narinfo1538=== CONT TestProxyWriteTimeout/unknown_size1539=== CONT TestProxyWriteTimeout/1_GiB_nar1540=== CONT TestProxyWriteTimeout/10_GiB_nar1541--- PASS: TestProxyWriteTimeout (0.10s)1542 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1543 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1544 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1545 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1546=== CONT TestIsValidUploadKey/narinfo1547=== CONT TestIsValidUploadKey/unknown_type1548=== CONT TestIsValidUploadKey/empty_key1549=== CONT TestIsValidUploadKey/absolute1550=== CONT TestIsValidUploadKey/traversal_nar1551=== CONT TestIsValidUploadKey/traversal1552=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1553=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1554=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1555=== CONT TestIsValidUploadKey/index.html1556=== CONT TestIsValidUploadKey/nix-cache-info1557=== CONT TestIsValidUploadKey/realisation_plus_in_output1558=== CONT TestIsValidUploadKey/build_log1559=== CONT TestIsValidUploadKey/listing1560=== CONT TestIsValidUploadKey/nar_plain1561=== CONT TestIsValidUploadKey/nar_xz1562=== CONT TestIsValidUploadKey/nar_zst1563=== CONT TestIsValidUploadKey/build_log_equals1564=== CONT TestIsValidUploadKey/realisation1565=== CONT TestIsValidUploadKey/build_log_question_mark1566=== CONT TestIsValidUploadKey/build_log_plus_in_name1567=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1568=== NAME TestPinProtectsFromGC1569 client_integration_test.go:778: Pinned store path: /build/TestPinProtectsFromGC2566843812/001/store/7ripsh9ps20s7358wlkrmaxdg84ll3s6-pinned-file.txt1570 client_integration_test.go:779: Unpinned store path: /build/TestPinProtectsFromGC2566843812/001/store/ijlcl4s0lynpca5nyzwv8jcm38lbnidh-unpinned-file.txt1571=== RUN TestService_RequireScope_OIDC/builder_may_write1572=== PAUSE TestService_RequireScope_OIDC/builder_may_write1573=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1574=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1575=== RUN TestService_RequireScope_OIDC/ops_may_admin1576=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1577=== RUN TestService_RequireScope_OIDC/ops_may_not_write1578=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1579=== RUN TestService_RequireScope_OIDC/reader_may_not_write1580=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1581=== RUN TestService_RequireScope_OIDC/static_token_may_admin1582=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1583=== RUN TestService_RequireScope_OIDC/static_token_may_write1584=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1585=== RUN TestService_RequireScope_OIDC/reader_may_read1586=== PAUSE TestService_RequireScope_OIDC/reader_may_read1587=== RUN TestService_RequireScope_OIDC/writer_implies_read1588=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1589=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1590=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1591=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1592=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1593=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1594=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1595=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1596=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1597=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1598=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1599=== CONT TestIsValidUploadKey/build_log_home-manager_file1600--- PASS: TestIsValidUploadKey (0.10s)1601 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1602 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1603 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1604 --- PASS: TestIsValidUploadKey/absolute (0.00s)1605 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1606 --- PASS: TestIsValidUploadKey/traversal (0.00s)1607 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1608 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1609 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1610 --- PASS: TestIsValidUploadKey/index.html (0.00s)1611 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1612 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1613 --- PASS: TestIsValidUploadKey/build_log (0.00s)1614 --- PASS: TestIsValidUploadKey/listing (0.00s)1615 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1616 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1617 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1618 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1619 --- PASS: TestIsValidUploadKey/realisation (0.00s)1620 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1621 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1622 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1623=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed16242026/11/02 09:26:09 INFO Received push request method=POST path=/api/pushes1625--- PASS: TestService_ReadAuthMiddleware (0.31s)1626=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1627=== NAME TestClientCADerivations1628 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations906459504/001/store/ypga41s2lwbhapa28ibd0vi5k41wdjpj-ca-test16292026/11/02 09:26:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16302026/11/02 09:26:09 INFO Uploading 7ripsh9ps20s7358wlkrmaxdg84ll3s6-pinned-file.txt (128B)16312026/11/02 09:26:09 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16322026/11/02 09:26:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16332026/11/02 09:26:09 WARN Failed to register uploaded object key=7ripsh9ps20s7358wlkrmaxdg84ll3s6.ls error="server returned 404: 404 page not found\n"16342026/11/02 09:26:09 INFO Signed narinfos id=1 count=116352026/11/02 09:26:09 INFO Uploading 1 narinfos16362026/11/02 09:26:09 INFO Received complete push request method=POST path=/api/pushes/1/complete16372026/11/02 09:26:09 WARN Failed to register uploaded object key=7ripsh9ps20s7358wlkrmaxdg84ll3s6.narinfo error="server returned 404: 404 page not found\n"1638--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.49s)1639=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost16402026/11/02 09:26:09 INFO Completed push id=1 objects=3 duration=7.301687ms1641=== NAME TestClientMultipleUploads16422026/11/02 09:26:09 INFO Upload complete. (70ms)1643 client_integration_test.go:405: Created store path 0: /build/TestClientMultipleUploads2776370162/001/store/dbw98yq6as7bz9npd7lixj2y1hdx0p91-test-file-0.txt1644=== NAME TestClientCADerivations1645 client_ca_test.go:139: Found 1 dependencies (including self)16462026/11/02 09:26:09 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1647--- PASS: TestService_AuthMiddleware (0.27s)1648=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1649=== NAME TestClientMultipleUploads1650 client_integration_test.go:405: Created store path 1: /build/TestClientMultipleUploads2776370162/001/store/0y9x33jhkg9lqwynysj1bn9aka38b9sv-test-file-1.txt1651--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.28s)1652=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16532026/11/02 09:26:09 INFO Received complete multipart upload request method=POST path=/1654=== NAME TestClientIntegration1655 client_integration_test.go:291: Created store path: /build/TestClientIntegration198026238/002/store/xqpnjclfv741jkhrb1n904gzmr53nkma-test-file.txt16562026/11/02 09:26:09 INFO Received uploads request method=POST path=/api/pending_closures16572026/11/02 09:26:09 INFO Received uploads request method=POST path=/api/pending_closures16582026/11/02 09:26:09 INFO Received push request method=POST path=/api/pushes16592026/11/02 09:26:09 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16602026/11/02 09:26:09 INFO Uploading ysx0bmwkir20p85gm0gxnh1gbb2lcd8x-shared-dep (136B)16612026/11/02 09:26:09 INFO Uploading laxgv9ykl5wdy5p45dxhjll22z5g4kxf-a (216B)16622026/11/02 09:26:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16632026/11/02 09:26:09 INFO Uploading ijlcl4s0lynpca5nyzwv8jcm38lbnidh-unpinned-file.txt (128B)16642026/11/02 09:26:09 WARN Failed to register uploaded object key=cmc9gpm1v9x7yawad89i68nchyjfmyga.ls error="server returned 404: 404 page not found\n"16652026/11/02 09:26:09 WARN Failed to register uploaded object key=ysx0bmwkir20p85gm0gxnh1gbb2lcd8x.ls error="server returned 404: 404 page not found\n"16662026/11/02 09:26:09 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16672026/11/02 09:26:09 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"16682026/11/02 09:26:09 WARN mTLS auth: bound subjects configured but subject DN unavailable16692026/11/02 09:26:09 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1670--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.28s)16712026/11/02 09:26:09 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"1672=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16732026/11/02 09:26:09 WARN Failed to register uploaded object key=ijlcl4s0lynpca5nyzwv8jcm38lbnidh.ls error="server returned 404: 404 page not found\n"1674=== NAME TestClientMultipleUploads16752026/11/02 09:26:09 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign1676 client_integration_test.go:405: Created store path 2: /build/TestClientMultipleUploads2776370162/001/store/kn820m76q5ylfsq4znic2gpri35hlvyq-test-file-2.txt16772026/11/02 09:26:09 INFO Received uploads request method=POST path=/16782026/11/02 09:26:09 INFO Signed narinfos id=2 count=116792026/11/02 09:26:09 INFO Uploading 1 narinfos16802026/11/02 09:26:09 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16812026/11/02 09:26:09 WARN Failed to register uploaded object key=nar/0nd00f47xiqvg3hvbvd76yabv0ajxkx1nljzf25yn6piy004fm3q.nar.zst error="server returned 404: 404 page not found\n"16822026/11/02 09:26:09 WARN Failed to register uploaded object key=laxgv9ykl5wdy5p45dxhjll22z5g4kxf.ls error="server returned 404: 404 page not found\n"16832026/11/02 09:26:09 INFO Signed narinfos id=1 count=216842026/11/02 09:26:09 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16852026/11/02 09:26:09 INFO Signed narinfos id=2 count=216862026/11/02 09:26:09 INFO Uploading 4 narinfos16872026/11/02 09:26:09 INFO Received complete push request method=POST path=/api/pushes/2/complete16882026/11/02 09:26:09 WARN Failed to register uploaded object key=ijlcl4s0lynpca5nyzwv8jcm38lbnidh.narinfo error="server returned 404: 404 page not found\n"16892026/11/02 09:26:09 WARN Failed to register uploaded object key=cmc9gpm1v9x7yawad89i68nchyjfmyga.narinfo error="server returned 404: 404 page not found\n"16902026/11/02 09:26:09 WARN Failed to register uploaded object key=ysx0bmwkir20p85gm0gxnh1gbb2lcd8x.narinfo error="server returned 404: 404 page not found\n"16912026/11/02 09:26:09 INFO Completed push id=2 objects=3 duration=1.734119ms16922026/11/02 09:26:09 INFO Upload complete. (48ms)1693=== NAME TestClientWithDependencies16942026/11/02 09:26:09 WARN Failed to register uploaded object key=laxgv9ykl5wdy5p45dxhjll22z5g4kxf.narinfo error="server returned 404: 404 page not found\n"1695 client_integration_test.go:660: Built derivation: /build/TestClientWithDependencies4086263997/001/store/ggxi0kawdw0zc5rsjwqfihpy9zy236b5-test-script16962026/11/02 09:26:09 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16972026/11/02 09:26:09 WARN Failed to register uploaded object key=ysx0bmwkir20p85gm0gxnh1gbb2lcd8x.narinfo error="server returned 404: 404 page not found\n"16982026/11/02 09:26:09 INFO Received push request method=POST path=/api/pushes16992026/11/02 09:26:09 INFO Completed upload id=1 objects=6 duration=5.791998ms17002026/11/02 09:26:09 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17012026/11/02 09:26:09 INFO Received push request method=POST path=/api/pushes17022026/11/02 09:26:09 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)17032026/11/02 09:26:09 INFO Uploading b3z8l0wakqz1sx37yqw8hxngip5mn0m4-b (216B)17042026/11/02 09:26:09 INFO Uploading 23j95ip8whm1cc823b2rsjr095mls4jm-shared-dep (136B)17052026/11/02 09:26:09 INFO Completed upload id=2 objects=6 duration=1.994839ms17062026/11/02 09:26:09 INFO Upload complete. (79ms)1707=== NAME TestClientFallsBackToClosures1708 client_pushes_test.go:112: Retrieved narinfo from S3:1709 StorePath: /build/TestClientFallsBackToClosures808215362/001/store/ysx0bmwkir20p85gm0gxnh1gbb2lcd8x-shared-dep1710 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1711 Compression: zstd1712 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821713 NarSize: 1361714 References: 1715 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n17162026/11/02 09:26:09 INFO Received uploads request method=POST path=/api/pending_closures1717 client_pushes_test.go:112: Retrieved narinfo from S3:1718 StorePath: /build/TestClientFallsBackToClosures808215362/001/store/laxgv9ykl5wdy5p45dxhjll22z5g4kxf-a1719 URL: nar/0nd00f47xiqvg3hvbvd76yabv0ajxkx1nljzf25yn6piy004fm3q.nar.zst1720 Compression: zstd1721 NarHash: sha256:0nd00f47xiqvg3hvbvd76yabv0ajxkx1nljzf25yn6piy004fm3q1722 NarSize: 2161723 References: /build/TestClientFallsBackToClosures808215362/001/store/ysx0bmwkir20p85gm0gxnh1gbb2lcd8x-shared-dep1724 CA: text:sha256:1lr4y31mj1r7qzbbcj30k1hw3acmq82dp191r8jdl6j8azws964v1725=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17262026/11/02 09:26:09 INFO Received request for more parts method=POST path=/17272026/11/02 09:26:09 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)17282026/11/02 09:26:09 INFO Uploading 5kkqfjgfwvifhzpzxbkzymxby23rlwpd-top (224B)17292026/11/02 09:26:09 INFO Uploading 971w9wlpxm54055ji0gkd16zcczaw0ns-shared-dep (136B)17302026/11/02 09:26:09 WARN Failed to register uploaded object key=3gi5inibj26sjwnp2z4lm477q9zl4r99.ls error="server returned 404: 404 page not found\n"17312026/11/02 09:26:09 WARN Failed to register uploaded object key=23j95ip8whm1cc823b2rsjr095mls4jm.ls error="server returned 404: 404 page not found\n"1732=== NAME TestClientFallsBackToClosures1733 client_pushes_test.go:112: Retrieved narinfo from S3:17342026/11/02 09:26:09 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"1735 StorePath: /build/TestClientFallsBackToClosures808215362/001/store/cmc9gpm1v9x7yawad89i68nchyjfmyga-b17362026/11/02 09:26:09 WARN Failed to register uploaded object key=b3z8l0wakqz1sx37yqw8hxngip5mn0m4.ls error="server returned 404: 404 page not found\n"1737 URL: nar/0nd00f47xiqvg3hvbvd76yabv0ajxkx1nljzf25yn6piy004fm3q.nar.zst1738 Compression: zstd1739 NarHash: sha256:0nd00f47xiqvg3hvbvd76yabv0ajxkx1nljzf25yn6piy004fm3q1740 NarSize: 2161741 References: /build/TestClientFallsBackToClosures808215362/001/store/ysx0bmwkir20p85gm0gxnh1gbb2lcd8x-shared-dep17422026/11/02 09:26:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1743 CA: text:sha256:1lr4y31mj1r7qzbbcj30k1hw3acmq82dp191r8jdl6j8azws964v17442026/11/02 09:26:09 WARN Failed to register uploaded object key=nar/04msvwr29blizv1cvqky2095lvhqd59xd6w1rin86rd0cwarlyk0.nar.zst error="server returned 404: 404 page not found\n"17452026/11/02 09:26:09 INFO Signed narinfos id=1 count=317462026/11/02 09:26:09 INFO Uploading 3 narinfos1747--- PASS: TestClientFallsBackToClosures (0.55s)1748=== CONT TestGCEndsOnShutdown/before_the_run17492026/11/02 09:26:09 WARN Failed to register uploaded object key=5kkqfjgfwvifhzpzxbkzymxby23rlwpd.ls error="server returned 404: 404 page not found\n"17502026/11/02 09:26:09 WARN Failed to register uploaded object key=971w9wlpxm54055ji0gkd16zcczaw0ns.ls error="server returned 404: 404 page not found\n"17512026/11/02 09:26:09 WARN Failed to register uploaded object key=nar/0fm83s9xn1j389l3h1xmkm9jl0nhh4lj4f32i7n6yj9yhfavx5br.nar.zst error="server returned 404: 404 page not found\n"17522026/11/02 09:26:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17532026/11/02 09:26:09 WARN Failed to register uploaded object key=23j95ip8whm1cc823b2rsjr095mls4jm.narinfo error="server returned 404: 404 page not found\n"17542026/11/02 09:26:09 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17552026/11/02 09:26:09 INFO Signed narinfos id=1 count=217562026/11/02 09:26:09 INFO Uploading 2 narinfos17572026/11/02 09:26:09 WARN Failed to register uploaded object key=3gi5inibj26sjwnp2z4lm477q9zl4r99.narinfo error="server returned 404: 404 page not found\n"17582026/11/02 09:26:09 INFO Received complete push request method=POST path=/api/pushes/1/complete17592026/11/02 09:26:09 WARN Failed to register uploaded object key=b3z8l0wakqz1sx37yqw8hxngip5mn0m4.narinfo error="server returned 404: 404 page not found\n"17602026/11/02 09:26:09 WARN Failed to register uploaded object key=971w9wlpxm54055ji0gkd16zcczaw0ns.narinfo error="server returned 404: 404 page not found\n"17612026/11/02 09:26:09 INFO Received complete push request method=POST path=/api/pushes/1/complete17622026/11/02 09:26:09 WARN Failed to register uploaded object key=5kkqfjgfwvifhzpzxbkzymxby23rlwpd.narinfo error="server returned 404: 404 page not found\n"17632026/11/02 09:26:09 INFO Received push request method=POST path=/api/pushes1764=== NAME TestClientWithDependencies1765 client_integration_test.go:662: Found 1 dependencies (including self)17662026/11/02 09:26:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17672026/11/02 09:26:09 INFO Uploading ypga41s2lwbhapa28ibd0vi5k41wdjpj-ca-test (144B)17682026/11/02 09:26:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures17692026/11/02 09:26:09 INFO Garbage collection started17702026/11/02 09:26:09 INFO Completed push id=1 objects=6 duration=5.516047ms17712026/11/02 09:26:09 INFO Upload complete. (58ms)1772=== NAME TestClientSharedPathCommittedMidPush1773 client_integration_test.go:727: Retrieved narinfo from S3:1774 StorePath: /build/TestClientSharedPathCommittedMidPush2609294231/001/store/971w9wlpxm54055ji0gkd16zcczaw0ns-shared-dep1775 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1776 Compression: zstd1777 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821778 NarSize: 1361779 References: 1780 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n17812026/11/02 09:26:09 INFO Completed push id=1 objects=8 duration=12.681055ms17822026/11/02 09:26:09 INFO Upload complete. (65ms)1783 client_integration_test.go:727: Retrieved narinfo from S3:1784 StorePath: /build/TestClientSharedPathCommittedMidPush2609294231/001/store/5kkqfjgfwvifhzpzxbkzymxby23rlwpd-top1785 URL: nar/0fm83s9xn1j389l3h1xmkm9jl0nhh4lj4f32i7n6yj9yhfavx5br.nar.zst1786 Compression: zstd1787 NarHash: sha256:0fm83s9xn1j389l3h1xmkm9jl0nhh4lj4f32i7n6yj9yhfavx5br1788 NarSize: 2241789 References: /build/TestClientSharedPathCommittedMidPush2609294231/001/store/971w9wlpxm54055ji0gkd16zcczaw0ns-shared-dep1790 CA: text:sha256:0s6vyqpg78r7xpsms3h4v4mda6qx01vyr9h371fx5i7zjwnsj77c1791=== NAME TestClientPushesUseOnePush1792 client_pushes_test.go:97: Retrieved narinfo from S3:1793 StorePath: /build/TestClientPushesUseOnePush3691437686/001/store/23j95ip8whm1cc823b2rsjr095mls4jm-shared-dep1794 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1795 Compression: zstd1796 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821797 NarSize: 1361798 References: 1799 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n18002026/11/02 09:26:09 WARN Failed to register uploaded object key=ypga41s2lwbhapa28ibd0vi5k41wdjpj.ls error="server returned 404: 404 page not found\n"18012026/11/02 09:26:09 WARN Failed to register uploaded object key=log/30h1wvp74l6aw5d30s5zyqyx5gsv79sg-ca-test.drv error="server returned 404: 404 page not found\n"18022026/11/02 09:26:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18032026/11/02 09:26:09 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18042026/11/02 09:26:09 INFO Signed narinfos id=1 count=11805 client_pushes_test.go:97: Retrieved narinfo from S3:18062026/11/02 09:26:09 INFO Received uploads request method=POST path=/api/pending_closures1807 StorePath: /build/TestClientPushesUseOnePush3691437686/001/store/3gi5inibj26sjwnp2z4lm477q9zl4r99-a18082026/11/02 09:26:09 INFO Uploading 1 narinfos1809 URL: nar/04msvwr29blizv1cvqky2095lvhqd59xd6w1rin86rd0cwarlyk0.nar.zst1810 Compression: zstd1811 NarHash: sha256:04msvwr29blizv1cvqky2095lvhqd59xd6w1rin86rd0cwarlyk01812 NarSize: 2161813 References: /build/TestClientPushesUseOnePush3691437686/001/store/23j95ip8whm1cc823b2rsjr095mls4jm-shared-dep1814 CA: text:sha256:07mrhqixw582lsnh6gc7kdxpnjdkmfqfkvmjnnq0vf43d7zii1qg1815--- PASS: TestClientSharedPathCommittedMidPush (0.49s)1816=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1817=== NAME TestClientPushesUseOnePush1818 client_pushes_test.go:97: Retrieved narinfo from S3:1819 StorePath: /build/TestClientPushesUseOnePush3691437686/001/store/b3z8l0wakqz1sx37yqw8hxngip5mn0m4-b1820 URL: nar/04msvwr29blizv1cvqky2095lvhqd59xd6w1rin86rd0cwarlyk0.nar.zst1821 Compression: zstd1822 NarHash: sha256:04msvwr29blizv1cvqky2095lvhqd59xd6w1rin86rd0cwarlyk01823 NarSize: 2161824 References: /build/TestClientPushesUseOnePush3691437686/001/store/23j95ip8whm1cc823b2rsjr095mls4jm-shared-dep1825 CA: text:sha256:07mrhqixw582lsnh6gc7kdxpnjdkmfqfkvmjnnq0vf43d7zii1qg18262026/11/02 09:26:09 INFO Aborted multipart uploads count=0 kept=018272026/11/02 09:26:09 INFO Received push request method=POST path=/api/pushes18282026/11/02 09:26:09 INFO Received complete push request method=POST path=/api/pushes/1/complete18292026/11/02 09:26:09 WARN Failed to register uploaded object key=ypga41s2lwbhapa28ibd0vi5k41wdjpj.narinfo error="server returned 404: 404 page not found\n"1830--- PASS: TestClientPushesUseOnePush (0.55s)1831=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete18322026/11/02 09:26:09 WARN Force mode enabled - objects will be deleted immediately without grace period18332026/11/02 09:26:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18342026/11/02 09:26:09 INFO Uploading xqpnjclfv741jkhrb1n904gzmr53nkma-test-file.txt (152B)1835=== CONT TestIsValidCachePath/narinfo1836=== CONT TestIsValidCachePath/index.html1837=== CONT TestIsValidCachePath/short_hash1838=== CONT TestIsValidCachePath/wrong_extension1839=== CONT TestIsValidCachePath/leading_slash1840=== CONT TestIsValidCachePath/empty1841=== CONT TestIsValidCachePath/random_path1842=== CONT TestIsValidCachePath/invalid_char_u1843=== CONT TestIsValidCachePath/nar_uncompressed1844=== CONT TestIsValidCachePath/nix-cache-info1845=== CONT TestIsValidCachePath/invalid_char_e1846=== CONT TestIsValidCachePath/realisation1847=== CONT TestIsValidCachePath/log1848=== CONT TestIsValidCachePath/traversal_in_middle1849=== CONT TestIsValidCachePath/ls1850=== CONT TestIsValidCachePath/traversal_parent1851=== CONT TestIsValidCachePath/nar_xz1852=== CONT TestIsValidCachePath/nar_bz21853=== CONT TestIsValidCachePath/nar_zst1854=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1855--- PASS: TestIsValidCachePath (0.00s)1856 --- PASS: TestIsValidCachePath/narinfo (0.00s)1857 --- PASS: TestIsValidCachePath/index.html (0.00s)1858 --- PASS: TestIsValidCachePath/short_hash (0.00s)1859 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1860 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1861 --- PASS: TestIsValidCachePath/empty (0.00s)1862 --- PASS: TestIsValidCachePath/random_path (0.00s)1863 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1864 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1865 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1866 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1867 --- PASS: TestIsValidCachePath/realisation (0.00s)1868 --- PASS: TestIsValidCachePath/log (0.00s)1869 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1870 --- PASS: TestIsValidCachePath/ls (0.00s)1871 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1872 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1873 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1874 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1875 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1876=== CONT TestParseSingleRange/none1877=== CONT TestParseSingleRange/open-ended1878=== CONT TestParseSingleRange/start_far_past_EOF1879=== CONT TestParseSingleRange/start_past_EOF1880=== CONT TestParseSingleRange/single_byte1881=== CONT TestParseSingleRange/suffix_exceeds_size1882=== CONT TestParseSingleRange/suffix1883=== CONT TestParseSingleRange/end_clamped_to_size1884=== CONT TestParseSingleRange/malformed_both_empty1885=== CONT TestParseSingleRange/closed1886=== CONT TestParseSingleRange/malformed_end_before_start1887=== CONT TestParseSingleRange/multi-range_ignored1888=== CONT TestParseSingleRange/malformed_no_dash1889=== CONT TestParseSingleRange/unknown_unit1890--- PASS: TestParseSingleRange (0.00s)1891 --- PASS: TestParseSingleRange/none (0.00s)1892 --- PASS: TestParseSingleRange/open-ended (0.00s)1893 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1894 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1895 --- PASS: TestParseSingleRange/single_byte (0.00s)1896 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1897 --- PASS: TestParseSingleRange/suffix (0.00s)1898 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1899 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1900 --- PASS: TestParseSingleRange/closed (0.00s)1901 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1902 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1903 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1904 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1905=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale19062026/11/02 09:26:09 INFO Completed push id=1 objects=4 duration=6.273957ms19072026/11/02 09:26:09 INFO Upload complete. (86ms)1908=== NAME TestClientCADerivations1909 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations906459504/001/store/ypga41s2lwbhapa28ibd0vi5k41wdjpj-ca-test1910 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1911 Compression: zstd1912 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1913 NarSize: 1441914 References: 1915 Deriver: /build/TestClientCADerivations906459504/001/store/30h1wvp74l6aw5d30s5zyqyx5gsv79sg-ca-test.drv1916 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1917 client_ca_test.go:185: Checking for realisation files in S3...19182026/11/02 09:26:09 WARN Failed to register uploaded object key=xqpnjclfv741jkhrb1n904gzmr53nkma.ls error="server returned 404: 404 page not found\n"19192026/11/02 09:26:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19202026/11/02 09:26:09 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"1921 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations19222026/11/02 09:26:09 INFO Signed narinfos id=1 count=11923 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache19242026/11/02 09:26:09 INFO Uploading 1 narinfos19252026/11/02 09:26:09 INFO Received complete push request method=POST path=/api/pushes/1/complete19262026/11/02 09:26:09 WARN Failed to register uploaded object key=xqpnjclfv741jkhrb1n904gzmr53nkma.narinfo error="server returned 404: 404 page not found\n"19272026/11/02 09:26:09 INFO Received push request method=POST path=/api/pushes19282026/11/02 09:26:09 INFO Received uploads request method=POST path=/api/pending_closures19292026/11/02 09:26:09 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)19302026/11/02 09:26:09 INFO Uploading kn820m76q5ylfsq4znic2gpri35hlvyq-test-file-2.txt (160B)19312026/11/02 09:26:09 INFO Uploading 0y9x33jhkg9lqwynysj1bn9aka38b9sv-test-file-1.txt (160B)19322026/11/02 09:26:09 INFO Uploading dbw98yq6as7bz9npd7lixj2y1hdx0p91-test-file-0.txt (160B)19332026/11/02 09:26:09 INFO Completed push id=1 objects=3 duration=8.851426ms19342026/11/02 09:26:09 INFO Upload complete. (61ms)19352026/11/02 09:26:09 WARN Failed to register uploaded object key=kn820m76q5ylfsq4znic2gpri35hlvyq.ls error="server returned 404: 404 page not found\n"19362026/11/02 09:26:09 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"19372026/11/02 09:26:09 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"19382026/11/02 09:26:09 WARN Failed to register uploaded object key=dbw98yq6as7bz9npd7lixj2y1hdx0p91.ls error="server returned 404: 404 page not found\n"19392026/11/02 09:26:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19402026/11/02 09:26:09 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"19412026/11/02 09:26:09 WARN Failed to register uploaded object key=0y9x33jhkg9lqwynysj1bn9aka38b9sv.ls error="server returned 404: 404 page not found\n"19422026/11/02 09:26:09 INFO Signed narinfos id=1 count=319432026/11/02 09:26:09 INFO Uploading 3 narinfos19442026/11/02 09:26:09 WARN Failed to register uploaded object key=kn820m76q5ylfsq4znic2gpri35hlvyq.narinfo error="server returned 404: 404 page not found\n"19452026/11/02 09:26:09 WARN Failed to register uploaded object key=0y9x33jhkg9lqwynysj1bn9aka38b9sv.narinfo error="server returned 404: 404 page not found\n"19462026/11/02 09:26:09 INFO Received complete push request method=POST path=/api/pushes/1/complete19472026/11/02 09:26:09 WARN Failed to register uploaded object key=dbw98yq6as7bz9npd7lixj2y1hdx0p91.narinfo error="server returned 404: 404 page not found\n"19482026/11/02 09:26:09 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=019492026/11/02 09:26:09 INFO Completed push id=1 objects=9 duration=9.867336ms19502026/11/02 09:26:09 INFO Upload complete. (64ms)1951=== NAME TestClientMultipleUploads1952 client_integration_test.go:416: Uploaded 3 paths in 95.055321ms19532026/11/02 09:26:09 INFO Received uploads request method=POST path=/api/pending_closures19542026/11/02 09:26:09 INFO Vacuumed table table=pending_closures19552026/11/02 09:26:09 INFO Received push request method=POST path=/api/pushes19562026/11/02 09:26:09 INFO Vacuumed table table=pending_objects19572026/11/02 09:26:09 INFO Vacuumed table table=multipart_uploads19582026/11/02 09:26:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19592026/11/02 09:26:09 INFO Uploading ggxi0kawdw0zc5rsjwqfihpy9zy236b5-test-script (136B)19602026/11/02 09:26:09 INFO Vacuumed table table=closures19612026/11/02 09:26:09 INFO Vacuumed table table=objects1962--- PASS: TestClientMultipleUploads (0.53s)1963=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh19642026/11/02 09:26:09 WARN Failed to register uploaded object key=ggxi0kawdw0zc5rsjwqfihpy9zy236b5.ls error="server returned 404: 404 page not found\n"19652026/11/02 09:26:09 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"19662026/11/02 09:26:09 INFO All 1 paths already cached19672026/11/02 09:26:09 WARN Failed to register uploaded object key=log/bjmcah9zb87g2wnyw3fqicr6a4kxq737-test-script.drv error="server returned 404: 404 page not found\n"19682026/11/02 09:26:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19692026/11/02 09:26:09 INFO Signed narinfos id=1 count=11970=== NAME TestClientIntegration1971 client_integration_test.go:317: Retrieved narinfo from S3:1972 StorePath: /build/TestClientIntegration198026238/002/store/xqpnjclfv741jkhrb1n904gzmr53nkma-test-file.txt19732026/11/02 09:26:09 INFO Uploading 1 narinfos1974 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1975 Compression: zstd1976 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11977 NarSize: 1521978 References: 1979 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11980 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1981 client_integration_test.go:318: Decompressed .ls content (64 bytes):1982 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}19832026/11/02 09:26:09 INFO Received complete push request method=POST path=/api/pushes/1/complete19842026/11/02 09:26:09 WARN Failed to register uploaded object key=ggxi0kawdw0zc5rsjwqfihpy9zy236b5.narinfo error="server returned 404: 404 page not found\n"19852026/11/02 09:26:09 INFO Completed push id=1 objects=4 duration=18.385963ms1986=== NAME TestClientCADerivations1987 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1988 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable19892026/11/02 09:26:09 INFO Upload complete. (106ms)1990 error: binary cache 's3://bucket82?endpoint=http://localhost:38731®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations906459504/001/store'1991 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 119922026/11/02 09:26:09 INFO Received uploads request method=POST path=/api/pending_closures1993=== NAME TestClientWithDependencies1994 client_integration_test.go:664: Skipping nix copy test - isolated store (/build/TestClientWithDependencies4086263997/001/store) requires matching store prefix1995--- PASS: TestClientCADerivations (0.69s)1996=== CONT TestPush_RejectsBadRequests/no_roots19972026/11/02 09:26:09 INFO Received push request method=POST path=/api/pushes1998=== CONT TestPush_RejectsBadRequests/bad_root19992026/11/02 09:26:09 INFO Received push request method=POST path=/api/pushes2000=== CONT TestPush_RejectsBadRequests/root_not_in_objects20012026/11/02 09:26:09 INFO Received push request method=POST path=/api/pushes2002=== CONT TestPush_RejectsBadRequests/no_objects20032026/11/02 09:26:09 INFO Received push request method=POST path=/api/pushes2004=== CONT TestServerTLSConfig/no_client_CA2005=== CONT TestServerTLSConfig/not_a_PEM_file2006--- PASS: TestPush_RejectsBadRequests (0.96s)2007 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2008 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2009 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2010 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2011=== CONT TestServerTLSConfig/missing_CA_file2012--- PASS: TestServerTLSConfig (0.00s)2013 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2014 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2015 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2016=== CONT TestResolveDBConnectionString/flag_wins2017=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2018=== CONT TestResolveDBConnectionString/missing_file_is_an_error2019=== CONT TestResolveDBConnectionString/nothing_configured2020=== CONT TestResolveDBConnectionString/file_when_flag_empty2021=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows2022--- PASS: TestResolveDBConnectionString (0.00s)2023 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2024 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2025 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2026 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2027 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2028--- PASS: TestClientWithDependencies (0.56s)2029=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check20302026/11/02 09:26:10 INFO Received uploads request method=POST path=/api/pending_closures20312026/11/02 09:26:10 INFO Received push request method=POST path=/api/pushes20322026/11/02 09:26:10 INFO Object in database but missing from S3 key=xqpnjclfv741jkhrb1n904gzmr53nkma.ls20332026/11/02 09:26:10 WARN Found objects in DB but missing from S3, will re-upload count=120342026/11/02 09:26:10 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20352026/11/02 09:26:10 INFO Received complete push request method=POST path=/api/pushes/2/complete20362026/11/02 09:26:10 WARN Failed to register uploaded object key=xqpnjclfv741jkhrb1n904gzmr53nkma.ls error="server returned 404: 404 page not found\n"20372026/11/02 09:26:10 INFO Completed push id=2 objects=3 duration=2.433819ms20382026/11/02 09:26:10 INFO Upload complete. (48ms)2039=== NAME TestClientIntegration2040 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)2041 client_integration_test.go:335: Decompressed .ls content (49 bytes):2042 {"version":1,"root":{"type":"regular","size":39}}20432026/11/02 09:26:10 INFO Aborted multipart uploads count=0 kept=020442026/11/02 09:26:10 WARN Force mode enabled - objects will be deleted immediately without grace period20452026/11/02 09:26:10 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:38731/bucket100/?delete=\": context canceled"2046=== CONT TestCacheConfigHandler/full_config,_no_issuer2047=== CONT TestCacheConfigHandler/no_signing_keys2048=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2049=== CONT TestCacheConfigHandler/no_cache_url_configured2050--- PASS: TestCacheConfigHandler (0.00s)2051 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2052 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2053 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2054 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2055=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2056=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20572026/11/02 09:26:10 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]2058=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20592026/11/02 09:26:10 WARN Authentication failed token_preview=eyJhbGciOi...JID0NRkbDQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2060=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2061=== CONT TestClientErrorHandling/InvalidStorePath2062--- PASS: TestService_AuthMiddleware_OIDC (0.40s)2063 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2064 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2065 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2066 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)20672026/11/02 09:26:10 INFO Aborted multipart uploads count=0 kept=020682026/11/02 09:26:10 INFO Received push request method=POST path=/api/pushes20692026/11/02 09:26:10 WARN Force mode enabled - objects will be deleted immediately without grace period20702026/11/02 09:26:10 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20712026/11/02 09:26:10 INFO Received complete push request method=POST path=/api/pushes/3/complete20722026/11/02 09:26:10 WARN Failed to register uploaded object key=xqpnjclfv741jkhrb1n904gzmr53nkma.ls error="server returned 404: 404 page not found\n"20732026/11/02 09:26:10 INFO Completed push id=3 objects=3 duration=2.551259ms20742026/11/02 09:26:10 INFO Upload complete. (47ms)2075=== NAME TestClientIntegration2076 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)2077 client_integration_test.go:352: Decompressed .ls content (49 bytes):2078 {"version":1,"root":{"type":"regular","size":39}}2079 client_integration_test.go:363: Testing garbage collection...2080=== CONT TestClientErrorHandling/ServerNotAvailable2081--- PASS: TestGCEndsOnShutdown (0.00s)2082 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.26s)2083 --- PASS: TestGCEndsOnShutdown/before_the_run (0.33s)2084 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.31s)2085=== CONT TestClientErrorHandling/InvalidAuthToken20862026/11/02 09:26:10 INFO Starting cleanup of old closures method=DELETE path=/api/closures20872026/11/02 09:26:10 INFO Garbage collection started20882026/11/02 09:26:10 INFO Aborted multipart uploads count=0 kept=020892026/11/02 09:26:10 WARN Force mode enabled - objects will be deleted immediately without grace period20902026/11/02 09:26:10 INFO Received uploads request method=POST path=/api/pending_closures20912026/11/02 09:26:10 INFO Aborted multipart uploads count=0 kept=020922026/11/02 09:26:10 WARN Force mode enabled - objects will be deleted immediately without grace period20932026/11/02 09:26:10 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/present20942026/11/02 09:26:10 INFO Received uploads request method=POST path=/api/pending_closures20952026/11/02 09:26:10 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=020962026/11/02 09:26:10 INFO Vacuumed table table=pending_closures20972026/11/02 09:26:10 INFO Aborted multipart uploads count=0 kept=020982026/11/02 09:26:10 INFO Vacuumed table table=pending_objects20992026/11/02 09:26:10 INFO Vacuumed table table=multipart_uploads21002026/11/02 09:26:10 INFO Vacuumed table table=closures21012026/11/02 09:26:10 INFO Vacuumed table table=objects21022026/11/02 09:26:10 WARN Force mode enabled - objects will be deleted immediately without grace period2103=== CONT TestService_RequireScope_OIDC/builder_may_write21042026/11/02 09:26:10 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=02105=== CONT TestService_RequireScope_OIDC/reader_may_read2106=== CONT TestService_RequireScope_OIDC/static_token_may_write2107=== CONT TestService_RequireScope_OIDC/static_token_may_admin2108=== CONT TestService_RequireScope_OIDC/reader_may_not_write2109=== CONT TestService_RequireScope_OIDC/ops_may_not_write2110=== CONT TestService_RequireScope_OIDC/ops_may_admin2111=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2112=== CONT TestService_RequireScope_OIDC/writer_implies_read2113=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read21142026/11/02 09:26:10 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]2115=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2116=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2117=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2118=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2119--- PASS: TestService_RequireScope_OIDC (0.46s)2120 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2121 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2122 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2123 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2124 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2125 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2126 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2127 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2128 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2129 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2130 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2131 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2132 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2133 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)21342026/11/02 09:26:10 INFO Vacuumed table table=pending_closures21352026/11/02 09:26:10 INFO Vacuumed table table=pending_objects21362026/11/02 09:26:10 INFO Vacuumed table table=multipart_uploads21372026/11/02 09:26:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21382026/11/02 09:26:10 INFO Vacuumed table table=closures21392026/11/02 09:26:10 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=021402026/11/02 09:26:10 INFO Vacuumed table table=pending_closures21412026/11/02 09:26:10 INFO Vacuumed table table=objects21422026/11/02 09:26:10 INFO Vacuumed table table=pending_objects21432026/11/02 09:26:10 INFO Vacuumed table table=multipart_uploads21442026/11/02 09:26:10 INFO Vacuumed table table=closures21452026/11/02 09:26:10 INFO Vacuumed table table=objects21462026/11/02 09:26:10 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5LjQ5NDQ1MDAzLWI3ZTItNDE0YS1iYmRmLWY4YThlOGI2YjQ2ZXgxNzkzNjExNTY5ODYxMzEwMzcz parts=1021472026/11/02 09:26:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21482026/11/02 09:26:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21492026/11/02 09:26:10 INFO Completed upload id=1 objects=3 duration=2.539129ms2150--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2151 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.26s)2152 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.30s)21532026/11/02 09:26:10 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5Ljg0MDZmMWEzLTA0NTUtNGY0OS05OWEzLTNjOTkzYjJkYjQxNngxNzkzNjExNTY5ODg3MzczNTYy parts=1021542026/11/02 09:26:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21552026/11/02 09:26:10 INFO Completed upload id=1 objects=3 duration=2.693459ms21562026/11/02 09:26:10 INFO Received uploads request method=POST path=/api/pending_closures21572026/11/02 09:26:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21582026/11/02 09:26:10 INFO Received uploads request method=POST path=/api/pending_closures21592026/11/02 09:26:10 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21602026/11/02 09:26:10 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21612026/11/02 09:26:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21622026/11/02 09:26:10 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5LjY3YTU4MTg5LTc4NWQtNDlhMC04NzM5LTFkOTRhMWUzNmUxMXgxNzkzNjExNTY5OTE1Mzc2NDYx parts=1021632026/11/02 09:26:10 WARN Request failed, retrying attempt=2 backoff=201.637025ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21642026/11/02 09:26:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21652026/11/02 09:26:10 INFO Completed upload id=1 objects=3 duration=2.636889ms21662026/11/02 09:26:10 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5LjYyMGQ4NmYxLTAwMWUtNDFjZS1iOTZhLWRhZTg4ZTM3Y2I1YXgxNzkzNjExNTY5OTg3MjY3ODQx parts=1021672026/11/02 09:26:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21682026/11/02 09:26:10 INFO Completed upload id=1 objects=3 duration=2.931528ms21692026/11/02 09:26:10 INFO Received uploads request method=POST path=/api/pending_closures21702026/11/02 09:26:10 INFO Received uploads request method=POST path=/api/pending_closures21712026/11/02 09:26:10 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst21722026/11/02 09:26:10 WARN Found objects in DB but missing from S3, will re-upload count=121732026/11/02 09:26:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21742026/11/02 09:26:10 WARN Rate limiter enabled after throttle name=s3-test rate=521752026/11/02 09:26:10 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2176=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2177 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102178 throttle_test.go:215: Rate limiter: enabled=true, rate=5.0021792026/11/02 09:26:10 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2180--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (3.23s)21812026/11/02 09:26:10 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5LjA2ODA5OGM1LTk5ZGItNDljZS05ZjE3LTMyN2I3ZmE4ZmNkZHgxNzkzNjExNTcwMDE3ODIyNTY4 parts=1021822026/11/02 09:26:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21832026/11/02 09:26:10 INFO Completed upload id=1 objects=3 duration=1.838189ms21842026/11/02 09:26:10 INFO Received uploads request method=POST path=/api/pending_closures21852026/11/02 09:26:10 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2186--- PASS: TestUploadHandlersRejectOversizedBody (0.19s)2187 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)2188 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.03s)2189 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.64s)2190=== NAME TestOrphanedObjectsGCStressTest2191 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains21922026/11/02 09:26:10 INFO lead: released remote=192.0.2.1:12342193--- PASS: TestLeadEndsOnShutdown (1.39s)2194=== NAME TestOrphanedObjectsGCStressTest2195 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion2196--- PASS: TestDeleteClosuresRacingPins (1.22s)21972026/11/02 09:26:10 WARN Request failed, retrying attempt=3 backoff=404.502986ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2198--- PASS: TestPendingClosureWriteTimeout (0.10s)2199 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2200 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2201 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2202 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.07s)22032026/11/02 09:26:10 INFO lead: released remote=192.0.2.1:12342204--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2205 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.71s)2206 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.77s)22072026/11/02 09:26:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22082026/11/02 09:26:10 INFO lead: acquired remote=192.0.2.1:123422092026/11/02 09:26:10 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5LjJiNjI5N2U2LTc1Y2YtNDAxZC05NzdjLWZkOGIwMGQwZmY2NHgxNzkzNjExNTcwMzE1MDE5NjE2 parts=1022102026/11/02 09:26:10 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22112026/11/02 09:26:10 INFO Completed upload id=2 objects=3 duration=1.27153ms22122026/11/02 09:26:10 INFO Received uploads request method=POST path=/api/pending_closures22132026/11/02 09:26:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22142026/11/02 09:26:10 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22152026/11/02 09:26:10 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo22162026/11/02 09:26:10 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=MzY5YjdlNWQtMjk2Mi00ZGQwLTgxMTMtYjUzMDY5NTNlNDM5LjUzMTAzOGMwLTFhZTctNGMxNy04ZmY0LTBhYzI4NTRlNjE5MXgxNzkzNjExNTcwMzU1MTQzODc5 parts=1022172026/11/02 09:26:10 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22182026/11/02 09:26:10 INFO Completed upload id=2 objects=3 duration=1.25648ms22192026/11/02 09:26:10 INFO Received uploads request method=POST path=/api/pending_closures22202026/11/02 09:26:10 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22212026/11/02 09:26:10 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2222--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.11s)2223 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (0.73s)2224 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (0.65s)2225 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (0.62s)2226 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (1.07s)2227 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (1.07s)22282026/11/02 09:26:10 WARN Request failed, retrying attempt=4 backoff=832.086917ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2229=== NAME TestOrphanedObjectsGCStressTest2230 orphaned_objects_gc_test.go:503: Stress test completed successfully:2231 orphaned_objects_gc_test.go:504: - Active objects preserved: 202232 orphaned_objects_gc_test.go:505: - Objects deleted: 2102233 orphaned_objects_gc_test.go:506: - Total GC'd: 2102234--- PASS: TestOrphanedObjectsGCStressTest (3.48s)22352026/11/02 09:26:11 INFO lead: released remote=192.0.2.1:12342236--- PASS: TestLeadElectsOneAndHandsOver (2.67s)22372026/11/02 09:26:11 WARN Request failed, retrying attempt=5 backoff=1.667612502s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22382026/11/02 09:26:11 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=022392026/11/02 09:26:11 INFO Received create pin request method=POST path=/api/pins/myapp22402026/11/02 09:26:11 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2566843812/001/store/7ripsh9ps20s7358wlkrmaxdg84ll3s6-pinned-file.txt narinfo_key=7ripsh9ps20s7358wlkrmaxdg84ll3s6.narinfo22412026/11/02 09:26:11 INFO Starting cleanup of old closures method=DELETE path=/api/closures22422026/11/02 09:26:11 INFO Garbage collection started22432026/11/02 09:26:11 INFO Aborted multipart uploads count=0 kept=022442026/11/02 09:26:11 WARN Force mode enabled - objects will be deleted immediately without grace period22452026/11/02 09:26:11 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=022462026/11/02 09:26:11 INFO Vacuumed table table=pending_closures22472026/11/02 09:26:11 INFO Vacuumed table table=pending_objects22482026/11/02 09:26:11 INFO Vacuumed table table=multipart_uploads22492026/11/02 09:26:11 INFO Vacuumed table table=closures22502026/11/02 09:26:11 INFO Vacuumed table table=objects22512026/11/02 09:26:12 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02252=== NAME TestClientIntegration2253 client_integration_test.go:370: Objects in database after GC:2254 client_integration_test.go:370: Successfully deleted all objects with GC --force2255--- PASS: TestClientIntegration (2.74s)2256--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.78s)22572026/11/02 09:26:13 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-config22582026/11/02 09:26:13 WARN Request failed, retrying attempt=2 backoff=204.013117ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22592026/11/02 09:26:13 WARN Request failed, retrying attempt=3 backoff=410.234959ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2260=== NAME TestPinProtectsFromGC2261 client_integration_test.go:887: Pin successfully protected closure from garbage collection2262--- PASS: TestPinProtectsFromGC (4.63s)22632026/11/02 09:26:14 WARN Request failed, retrying attempt=4 backoff=778.399775ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2264--- PASS: TestConnectWaitsForAPeerMigration (5.17s)22652026/11/02 09:26:14 INFO Aborted multipart uploads count=1 kept=022662026/11/02 09:26:14 INFO Received cleanup request method=DELETE path=/api/pending_closures22672026/11/02 09:26:14 INFO Aborted multipart uploads count=1 kept=02268--- PASS: TestPendingCleanupUsesOneCutoff (6.56s)22692026/11/02 09:26:14 WARN Request failed, retrying attempt=5 backoff=1.442381376s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22702026/11/02 09:26:16 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"22712026/11/02 09:26:16 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-config22722026/11/02 09:26:16 WARN Request failed, retrying attempt=2 backoff=216.640681ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22732026/11/02 09:26:16 WARN Request failed, retrying attempt=3 backoff=429.296115ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22742026/11/02 09:26:17 WARN Request failed, retrying attempt=4 backoff=856.754784ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22752026/11/02 09:26:18 WARN Request failed, retrying attempt=5 backoff=1.521070555s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22762026/11/02 09:26:19 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_closures22772026/11/02 09:26:19 WARN Request failed, retrying attempt=2 backoff=203.340875ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22782026/11/02 09:26:19 WARN Request failed, retrying attempt=3 backoff=386.557234ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22792026/11/02 09:26:20 WARN Request failed, retrying attempt=4 backoff=787.458851ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22802026/11/02 09:26:21 WARN Request failed, retrying attempt=5 backoff=1.6272716s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2281--- PASS: TestClientErrorHandling (0.00s)2282 --- PASS: TestClientErrorHandling/InvalidStorePath (0.17s)2283 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.24s)2284 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.51s)2285PASS2286{"timestamp":"2026-11-02T09:26:22.677664984Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56564","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(145)"}2287{"timestamp":"2026-11-02T09:26:22.677698604Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56670","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(130)"}22882026-11-02 09:26:22.955 UTC [129] LOG: received smart shutdown request22892026-11-02 09:26:22.959 UTC [129] LOG: background worker "logical replication launcher" (PID 139) exited with exit code 122902026-11-02 09:26:22.966 UTC [134] LOG: shutting down22912026-11-02 09:26:22.967 UTC [134] LOG: checkpoint starting: shutdown immediate22922026-11-02 09:26:24.691 UTC [134] LOG: checkpoint complete: wrote 10753 buffers (65.6%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.238 s, sync=1.422 s, total=1.726 s; sync files=36397, longest=0.014 s, average=0.001 s; distance=526617 kB, estimate=526617 kB; lsn=0/219AC488, redo lsn=0/219AC48822932026-11-02 09:26:24.768 UTC [129] LOG: database system is shut down2294Running OIDC tests...2295=== RUN TestAudienceForIssuer2296=== PAUSE TestAudienceForIssuer2297=== RUN TestGlobMatch2298=== PAUSE TestGlobMatch2299=== RUN TestValidateToken_ValidToken2300=== PAUSE TestValidateToken_ValidToken2301=== RUN TestValidateToken_WrongAudience2302=== PAUSE TestValidateToken_WrongAudience2303=== RUN TestValidateToken_Expired2304=== PAUSE TestValidateToken_Expired2305=== RUN TestValidateToken_BoundClaimsMismatch2306=== PAUSE TestValidateToken_BoundClaimsMismatch2307=== RUN TestValidateToken_BoundSubjectMismatch2308=== PAUSE TestValidateToken_BoundSubjectMismatch2309=== RUN TestValidateToken_MultipleProviders2310=== PAUSE TestValidateToken_MultipleProviders2311=== RUN TestValidateToken_NoMatchingProvider2312=== PAUSE TestValidateToken_NoMatchingProvider2313=== RUN TestValidateToken_KubernetesServiceAccount2314=== PAUSE TestValidateToken_KubernetesServiceAccount2315=== RUN TestNewValidator_KubernetesRequiresCA2316=== PAUSE TestNewValidator_KubernetesRequiresCA2317=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2318=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2319=== RUN TestPins_ReservedForMatchingRule2320=== PAUSE TestPins_ReservedForMatchingRule2321=== RUN TestPins_TopLevelShorthand2322=== PAUSE TestPins_TopLevelShorthand2323=== RUN TestPins_ConfigValidation2324=== PAUSE TestPins_ConfigValidation2325=== RUN TestScopes_LegacyProviderDefaultsToWrite2326=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2327=== RUN TestScopes_Rules2328=== PAUSE TestScopes_Rules2329=== RUN TestScopes_ConfigValidation2330=== PAUSE TestScopes_ConfigValidation2331=== CONT TestAudienceForIssuer2332=== CONT TestPins_ConfigValidation2333--- PASS: TestAudienceForIssuer (0.00s)2334=== CONT TestValidateToken_NoMatchingProvider2335=== CONT TestValidateToken_KubernetesServiceAccount2336=== CONT TestValidateToken_MultipleProviders2337=== CONT TestValidateToken_BoundSubjectMismatch2338--- PASS: TestPins_ConfigValidation (0.00s)2339=== CONT TestValidateToken_BoundClaimsMismatch2340=== CONT TestValidateToken_Expired2341=== CONT TestValidateToken_WrongAudience2342=== CONT TestValidateToken_ValidToken2343=== CONT TestPins_TopLevelShorthand2344=== CONT TestPins_ReservedForMatchingRule2345=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2346=== CONT TestGlobMatch2347=== CONT TestNewValidator_KubernetesRequiresCA2348=== CONT TestScopes_LegacyProviderDefaultsToWrite2349=== CONT TestScopes_ConfigValidation2350=== CONT TestScopes_Rules2351=== RUN TestGlobMatch/foo_foo2352=== PAUSE TestGlobMatch/foo_foo2353=== RUN TestGlobMatch/foo_bar2354=== PAUSE TestGlobMatch/foo_bar2355=== RUN TestGlobMatch/*_2356=== PAUSE TestGlobMatch/*_2357=== RUN TestGlobMatch/*_anything2358--- PASS: TestScopes_ConfigValidation (0.00s)2359=== PAUSE TestGlobMatch/*_anything2360=== RUN TestGlobMatch/foo*_foo2361=== PAUSE TestGlobMatch/foo*_foo2362=== RUN TestGlobMatch/foo*_foobar2363=== PAUSE TestGlobMatch/foo*_foobar2364=== RUN TestGlobMatch/foo*_bar2365=== PAUSE TestGlobMatch/foo*_bar2366=== RUN TestGlobMatch/*bar_bar2367=== PAUSE TestGlobMatch/*bar_bar2368=== RUN TestGlobMatch/*bar_foobar2369=== PAUSE TestGlobMatch/*bar_foobar2370=== RUN TestGlobMatch/*bar_foo2371=== PAUSE TestGlobMatch/*bar_foo2372=== RUN TestGlobMatch/foo*bar_foobar2373=== PAUSE TestGlobMatch/foo*bar_foobar2374=== RUN TestGlobMatch/foo*bar_foo123bar2375=== PAUSE TestGlobMatch/foo*bar_foo123bar2376=== RUN TestGlobMatch/foo*bar_foobarbaz2377=== PAUSE TestGlobMatch/foo*bar_foobarbaz2378=== RUN TestGlobMatch/*/*_foo/bar2379=== PAUSE TestGlobMatch/*/*_foo/bar2380=== RUN TestGlobMatch/*/*_foo2381=== PAUSE TestGlobMatch/*/*_foo2382=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2383=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2384=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02385=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02386=== RUN TestGlobMatch/refs/*/main_refs/heads/main2387=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2388=== RUN TestGlobMatch/fo?_foo2389=== PAUSE TestGlobMatch/fo?_foo2390=== RUN TestGlobMatch/fo?_fo2391=== PAUSE TestGlobMatch/fo?_fo2392=== RUN TestGlobMatch/fo?_fooo2393=== PAUSE TestGlobMatch/fo?_fooo2394=== RUN TestGlobMatch/?oo_foo2395=== PAUSE TestGlobMatch/?oo_foo2396=== RUN TestGlobMatch/?oo_boo2397=== PAUSE TestGlobMatch/?oo_boo2398=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2399=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2400=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2401=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2402=== CONT TestGlobMatch/foo_foo2403=== CONT TestGlobMatch/foo*_bar2404=== CONT TestGlobMatch/foo*_foobar2405=== CONT TestGlobMatch/foo*_foo2406=== CONT TestGlobMatch/refs/*/main_refs/heads/main2407=== CONT TestGlobMatch/*_2408=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2409=== CONT TestGlobMatch/foo*bar_foobar2410=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2411=== CONT TestGlobMatch/?oo_boo2412=== CONT TestGlobMatch/*bar_foo2413=== CONT TestGlobMatch/*bar_foobar2414=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2415=== CONT TestGlobMatch/?oo_foo2416=== CONT TestGlobMatch/*/*_foo2417=== CONT TestGlobMatch/*bar_bar2418=== CONT TestGlobMatch/fo?_fooo2419=== CONT TestGlobMatch/fo?_fo2420=== CONT TestGlobMatch/fo?_foo2421=== CONT TestGlobMatch/*/*_foo/bar2422=== CONT TestGlobMatch/*_anything2423=== CONT TestGlobMatch/foo_bar2424=== CONT TestGlobMatch/foo*bar_foobarbaz2425=== CONT TestGlobMatch/foo*bar_foo123bar2426=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02427--- PASS: TestGlobMatch (0.00s)2428 --- PASS: TestGlobMatch/foo_foo (0.00s)2429 --- PASS: TestGlobMatch/foo*_bar (0.00s)2430 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2431 --- PASS: TestGlobMatch/foo*_foo (0.00s)2432 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2433 --- PASS: TestGlobMatch/*_ (0.00s)2434 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2435 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2436 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2437 --- PASS: TestGlobMatch/?oo_boo (0.00s)2438 --- PASS: TestGlobMatch/*bar_foo (0.00s)2439 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2440 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2441 --- PASS: TestGlobMatch/?oo_foo (0.00s)2442 --- PASS: TestGlobMatch/*/*_foo (0.00s)2443 --- PASS: TestGlobMatch/*bar_bar (0.00s)2444 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2445 --- PASS: TestGlobMatch/fo?_fo (0.00s)2446 --- PASS: TestGlobMatch/fo?_foo (0.00s)2447 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2448 --- PASS: TestGlobMatch/*_anything (0.00s)2449 --- PASS: TestGlobMatch/foo_bar (0.00s)2450 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2451 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2452 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)24532026/11/02 09:26:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42341/oidc2454--- PASS: TestValidateToken_ValidToken (0.02s)24552026/11/02 09:26:27 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:40713/oidc24562026/11/02 09:26:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38271/oidc24572026/11/02 09:26:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39649/oidc2458--- PASS: TestValidateToken_NoMatchingProvider (0.04s)2459--- PASS: TestPins_TopLevelShorthand (0.04s)24602026/11/02 09:26:27 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:402632461--- PASS: TestPins_ReservedForMatchingRule (0.04s)2462--- PASS: TestValidateToken_KubernetesServiceAccount (0.05s)24632026/11/02 09:26:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34887/oidc24642026/11/02 09:26:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45953/oidc24652026/11/02 09:26:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42525/oidc2466--- PASS: TestValidateToken_Expired (0.06s)2467--- PASS: TestValidateToken_BoundClaimsMismatch (0.06s)2468--- PASS: TestValidateToken_BoundSubjectMismatch (0.07s)24692026/11/02 09:26:27 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12324702026/11/02 09:26:27 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:37695/oidc24712026/11/02 09:26:27 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:36245/oidc24722026/11/02 09:26:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39081/oidc2473--- PASS: TestValidateToken_MultipleProviders (0.07s)2474--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.07s)24752026/11/02 09:26:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44263/oidc2476--- PASS: TestScopes_Rules (0.07s)2477--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.07s)24782026/11/02 09:26:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38563/oidc2479--- PASS: TestValidateToken_WrongAudience (0.08s)24802026/11/02 09:26:27 http: TLS handshake error from 127.0.0.1:51574: remote error: tls: bad certificate2481--- PASS: TestNewValidator_KubernetesRequiresCA (0.12s)2482PASS2483Running hook tests...2484=== RUN TestSendPathsEmpty2485=== PAUSE TestSendPathsEmpty2486=== RUN TestQueueEnqueueAndFetch2487=== PAUSE TestQueueEnqueueAndFetch2488=== RUN TestQueueDeduplication2489=== PAUSE TestQueueDeduplication2490=== RUN TestQueueRemove2491=== PAUSE TestQueueRemove2492=== RUN TestQueueFetchBatchLimit2493=== PAUSE TestQueueFetchBatchLimit2494=== RUN TestQueueRetryMovesToBack2495=== PAUSE TestQueueRetryMovesToBack2496=== RUN TestQueueFetchRemoveLifecycle2497=== PAUSE TestQueueFetchRemoveLifecycle2498=== RUN TestQueueConcurrentWriters2499=== PAUSE TestQueueConcurrentWriters2500=== RUN TestQueueRemoveLargeClosure2501=== PAUSE TestQueueRemoveLargeClosure2502=== RUN TestServerClientIntegration2503--- PASS: TestServerClientIntegration (0.00s)2504=== RUN TestServerQueueError25052026/11/02 09:26:27 ERROR Failed to queue paths error="permission denied" count=12506--- PASS: TestServerQueueError (0.00s)2507=== RUN TestGetListenerSocketActivation2508 server_test.go:218: === RUN TestGetListenerSocketActivation2509 --- PASS: TestGetListenerSocketActivation (0.00s)2510 PASS2511 2512--- PASS: TestGetListenerSocketActivation (0.01s)2513=== RUN TestServerStalledClientDoesNotBlockShutdown2514=== PAUSE TestServerStalledClientDoesNotBlockShutdown2515=== RUN TestServerBacksOffOnAcceptErrors2516=== PAUSE TestServerBacksOffOnAcceptErrors2517=== RUN TestDrainIsolatesPoisonPath2518=== PAUSE TestDrainIsolatesPoisonPath2519=== RUN TestRunNotBlockedByPoisonHead2520=== PAUSE TestRunNotBlockedByPoisonHead2521=== RUN TestDrainGivesUpWhenServerDown2522=== PAUSE TestDrainGivesUpWhenServerDown2523=== RUN TestFailedPathPrunedByLaterClosure2524=== PAUSE TestFailedPathPrunedByLaterClosure2525=== RUN TestWorkerUploadsAndRemoves2526=== PAUSE TestWorkerUploadsAndRemoves2527=== RUN TestWorkerSkipsGCdPaths2528=== PAUSE TestWorkerSkipsGCdPaths2529=== RUN TestWorkerPrunesClosureDeps2530=== PAUSE TestWorkerPrunesClosureDeps2531=== RUN TestDrainTimeout2532=== PAUSE TestDrainTimeout2533=== RUN TestWorkerRemoveFailureIsNotProgress2534=== PAUSE TestWorkerRemoveFailureIsNotProgress2535=== RUN TestWorkerKeepsPathItCannotStat2536=== PAUSE TestWorkerKeepsPathItCannotStat2537=== CONT TestSendPathsEmpty2538=== CONT TestDrainGivesUpWhenServerDown2539--- PASS: TestSendPathsEmpty (0.00s)2540=== CONT TestWorkerKeepsPathItCannotStat2541=== CONT TestWorkerRemoveFailureIsNotProgress2542=== CONT TestFailedPathPrunedByLaterClosure2543=== CONT TestDrainIsolatesPoisonPath2544=== CONT TestServerBacksOffOnAcceptErrors2545=== CONT TestServerStalledClientDoesNotBlockShutdown25462026/11/02 09:26:27 ERROR Accept failed error="too many open files"2547=== CONT TestWorkerUploadsAndRemoves2548=== CONT TestQueueRemoveLargeClosure2549=== CONT TestQueueConcurrentWriters2550=== CONT TestDrainTimeout2551=== CONT TestQueueFetchRemoveLifecycle2552=== CONT TestWorkerPrunesClosureDeps2553=== CONT TestQueueDeduplication2554=== CONT TestWorkerSkipsGCdPaths2555=== CONT TestQueueEnqueueAndFetch2556=== CONT TestQueueRemove2557=== CONT TestQueueRetryMovesToBack2558=== CONT TestRunNotBlockedByPoisonHead2559=== CONT TestQueueFetchBatchLimit25602026/11/02 09:26:27 ERROR Accept failed error="too many open files"25612026/11/02 09:26:27 INFO Uploading batch count=425622026/11/02 09:26:27 INFO Upload queue status pending=225632026/11/02 09:26:27 ERROR Upload failed error="upload failed" count=425642026/11/02 09:26:27 INFO Uploading batch count=225652026/11/02 09:26:27 INFO Upload queue status pending=225662026/11/02 09:26:27 INFO Uploading batch count=225672026/11/02 09:26:27 INFO Uploading batch count=125682026/11/02 09:26:27 ERROR Upload failed error="upload failed" count=125692026/11/02 09:26:27 INFO Upload queue status pending=225702026/11/02 09:26:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath4005948003/002/bbb25712026/11/02 09:26:27 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat1320149137/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat1320149137/002/locked/aaa: permission denied"25722026/11/02 09:26:27 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths3333074515/002/nonexistent25732026/11/02 09:26:27 INFO Uploading batch count=125742026/11/02 09:26:27 INFO Uploading batch count=225752026/11/02 09:26:27 ERROR Upload failed error="upload failed" count=225762026/11/02 09:26:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2255211962/002/a2577--- PASS: TestQueueRemove (0.01s)25782026/11/02 09:26:27 INFO Uploading batch count=125792026/11/02 09:26:27 INFO Upload queue status pending=325802026/11/02 09:26:27 INFO Uploading batch count=125812026/11/02 09:26:27 ERROR Upload failed error="upload failed" count=12582--- PASS: TestQueueFetchRemoveLifecycle (0.02s)2583--- PASS: TestQueueFetchBatchLimit (0.01s)25842026/11/02 09:26:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2255211962/002/b2585--- PASS: TestQueueEnqueueAndFetch (0.01s)25862026/11/02 09:26:27 ERROR Accept failed error="too many open files"25872026/11/02 09:26:27 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat1320149137/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat1320149137/002/locked/aaa: permission denied"25882026/11/02 09:26:27 INFO Uploading batch count=125892026/11/02 09:26:27 INFO Uploading batch count=225902026/11/02 09:26:27 ERROR Upload failed error="upload failed" count=22591--- PASS: TestQueueDeduplication (0.02s)25922026/11/02 09:26:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2255211962/002/c25932026/11/02 09:26:27 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress1212602694/002/nonexistent25942026/11/02 09:26:27 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12595--- PASS: TestQueueRetryMovesToBack (0.02s)25962026/11/02 09:26:27 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat1320149137/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat1320149137/002/locked/aaa: permission denied"25972026/11/02 09:26:27 INFO Uploading batch count=125982026/11/02 09:26:27 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress1212602694/002/nonexistent25992026/11/02 09:26:27 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126002026/11/02 09:26:27 INFO Uploading batch count=126012026/11/02 09:26:27 ERROR Upload failed error="upload failed" count=126022026/11/02 09:26:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2255211962/002/d26032026/11/02 09:26:27 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress1212602694/002/nonexistent26042026/11/02 09:26:27 ERROR Drain finished with paths left in queue remaining=126052026/11/02 09:26:27 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126062026/11/02 09:26:27 ERROR Drain finished with paths left in queue remaining=126072026/11/02 09:26:27 INFO Uploading batch count=126082026/11/02 09:26:27 ERROR Upload failed error="upload failed" count=126092026/11/02 09:26:27 INFO Uploading batch count=226102026/11/02 09:26:27 ERROR Upload failed error="upload failed" count=226112026/11/02 09:26:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2255211962/002/e2612--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)26132026/11/02 09:26:27 INFO Uploading batch count=126142026/11/02 09:26:27 ERROR Upload failed error="upload failed" count=126152026/11/02 09:26:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2255211962/002/f2616--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)26172026/11/02 09:26:27 ERROR Drain finished with paths left in queue remaining=1026182026/11/02 09:26:27 ERROR Drain finished with paths left in queue remaining=12619--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)2620--- PASS: TestDrainIsolatesPoisonPath (0.02s)2621--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2622--- PASS: TestWorkerUploadsAndRemoves (0.03s)2623--- PASS: TestWorkerSkipsGCdPaths (0.03s)2624--- PASS: TestWorkerPrunesClosureDeps (0.03s)26252026/11/02 09:26:27 ERROR Accept failed error="too many open files"2626--- PASS: TestQueueRemoveLargeClosure (0.05s)26272026/11/02 09:26:27 ERROR Accept failed error="too many open files"26282026/11/02 09:26:27 ERROR Accept failed error="too many open files"26292026/11/02 09:26:27 ERROR Failed to decode request error="read unix /build/hook1391539544/test.sock->@: i/o timeout"26302026/11/02 09:26:27 ERROR Failed to write response error="write unix /build/hook1391539544/test.sock->@: i/o timeout"2631--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)2632--- PASS: TestQueueConcurrentWriters (0.20s)26332026/11/02 09:26:27 ERROR Upload failed error="context deadline exceeded" count=226342026/11/02 09:26:27 ERROR Drain finished with paths left in queue remaining=42635--- PASS: TestDrainTimeout (0.22s)26362026/11/02 09:26:27 ERROR Accept failed error="too many open files"26372026/11/02 09:26:27 ERROR Accept failed error="too many open files"2638--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26392026/11/02 09:26:28 INFO Uploading batch count=126402026/11/02 09:26:28 INFO Uploading batch count=126412026/11/02 09:26:28 INFO Uploading batch count=126422026/11/02 09:26:28 ERROR Upload failed error="upload failed" count=126432026/11/02 09:26:28 INFO Uploading batch count=126442026/11/02 09:26:28 ERROR Upload failed error="upload failed" count=126452026/11/02 09:26:28 INFO Uploading batch count=126462026/11/02 09:26:28 ERROR Upload failed error="upload failed" count=126472026/11/02 09:26:28 INFO Uploading batch count=126482026/11/02 09:26:28 ERROR Upload failed error="upload failed" count=126492026/11/02 09:26:28 ERROR Drain finished with paths left in queue remaining=12650--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2651PASS2652Running signing tests...2653=== RUN TestExternalSigner2654=== PAUSE TestExternalSigner2655=== RUN TestExternalSignerWrongPublicKey2656=== PAUSE TestExternalSignerWrongPublicKey2657=== RUN TestExternalSignerErrors2658=== PAUSE TestExternalSignerErrors2659=== RUN TestExternalSignerRestartsAfterCrash2660=== PAUSE TestExternalSignerRestartsAfterCrash2661=== RUN TestExternalSignerProgramErrorKeepsProcess2662=== PAUSE TestExternalSignerProgramErrorKeepsProcess2663=== RUN TestExternalSignerClose2664=== PAUSE TestExternalSignerClose2665=== RUN TestExternalSignerRejectsInvalidPublicKey2666=== PAUSE TestExternalSignerRejectsInvalidPublicKey2667=== RUN TestExternalSignerCancellation2668=== PAUSE TestExternalSignerCancellation2669=== RUN TestGenerateFingerprint2670=== PAUSE TestGenerateFingerprint2671=== RUN TestParseSigningKey2672=== PAUSE TestParseSigningKey2673=== RUN TestSign2674=== PAUSE TestSign2675=== RUN TestSignBatch2676=== PAUSE TestSignBatch2677=== RUN TestNilKeyPublicKey2678=== PAUSE TestNilKeyPublicKey2679=== RUN TestSignErrors2680=== PAUSE TestSignErrors2681=== CONT TestExternalSigner2682=== CONT TestExternalSignerCancellation2683=== CONT TestSignBatch2684=== CONT TestSign2685=== CONT TestParseSigningKey2686=== RUN TestParseSigningKey/valid_32-byte_key2687=== CONT TestGenerateFingerprint2688=== CONT TestExternalSignerErrors2689=== CONT TestExternalSignerRestartsAfterCrash2690=== RUN TestExternalSignerErrors/missing_signature_name2691=== PAUSE TestExternalSignerErrors/missing_signature_name2692=== RUN TestExternalSignerErrors/null_signatures2693=== PAUSE TestExternalSignerErrors/null_signatures2694=== RUN TestExternalSignerErrors/wrong_signature_name2695=== CONT TestExternalSignerWrongPublicKey2696=== CONT TestSignErrors2697=== CONT TestNilKeyPublicKey2698=== CONT TestExternalSignerRejectsInvalidPublicKey2699=== CONT TestExternalSignerClose2700=== CONT TestExternalSignerProgramErrorKeepsProcess2701=== PAUSE TestExternalSignerErrors/wrong_signature_name2702=== RUN TestExternalSignerErrors/exit_at_startup2703=== RUN TestGenerateFingerprint/basic_with_references2704=== PAUSE TestGenerateFingerprint/basic_with_references2705=== RUN TestGenerateFingerprint/no_references2706=== PAUSE TestGenerateFingerprint/no_references2707=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2708=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2709=== RUN TestExternalSignerRejectsInvalidPublicKey/#002710=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002711=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2712=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2713=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2714=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2715=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2716=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2717=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2718=== PAUSE TestExternalSignerErrors/exit_at_startup2719=== PAUSE TestParseSigningKey/valid_32-byte_key2720--- PASS: TestNilKeyPublicKey (0.00s)2721--- PASS: TestSign (0.00s)2722=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2723=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2724=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2725=== CONT TestExternalSignerRejectsInvalidPublicKey/#002726=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2727=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2728=== RUN TestExternalSignerErrors/exit_on_request2729=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2730--- PASS: TestSignBatch (0.00s)2731=== RUN TestGenerateFingerprint/invalid_nar_hash_length2732=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2733=== RUN TestSignErrors/nil_key2734=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2735=== PAUSE TestSignErrors/nil_key2736=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2737--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2738 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2739 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2740 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2741 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2742 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2743=== PAUSE TestExternalSignerErrors/exit_on_request2744=== RUN TestExternalSignerErrors/invalid_signature_base642745=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2746=== RUN TestGenerateFingerprint/invalid_store_path_prefix2747=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2748=== RUN TestSignErrors/nil_narinfo2749=== PAUSE TestSignErrors/nil_narinfo2750=== PAUSE TestExternalSignerErrors/invalid_signature_base642751=== RUN TestParseSigningKey/no_colon2752=== PAUSE TestParseSigningKey/no_colon2753=== RUN TestGenerateFingerprint/invalid_reference_prefix2754=== RUN TestParseSigningKey/empty_name2755=== PAUSE TestParseSigningKey/empty_name2756=== RUN TestParseSigningKey/invalid_base642757=== PAUSE TestParseSigningKey/invalid_base642758=== RUN TestParseSigningKey/wrong_length2759=== PAUSE TestParseSigningKey/wrong_length2760=== CONT TestParseSigningKey/valid_32-byte_key2761=== CONT TestParseSigningKey/invalid_base642762=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2763=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2764=== CONT TestGenerateFingerprint/basic_with_references2765=== CONT TestParseSigningKey/no_colon2766=== CONT TestGenerateFingerprint/invalid_nar_hash_length2767=== RUN TestExternalSignerErrors/program_error2768=== PAUSE TestExternalSignerErrors/program_error2769=== RUN TestExternalSignerErrors/wrong_shape2770=== RUN TestSignErrors/invalid_narinfo2771=== PAUSE TestSignErrors/invalid_narinfo2772=== RUN TestSignErrors/canceled2773=== PAUSE TestSignErrors/canceled2774=== CONT TestSignErrors/nil_key2775=== CONT TestSignErrors/invalid_narinfo2776=== CONT TestParseSigningKey/empty_name2777=== CONT TestSignErrors/canceled2778=== CONT TestParseSigningKey/wrong_length2779=== CONT TestGenerateFingerprint/invalid_reference_prefix2780=== CONT TestGenerateFingerprint/invalid_store_path_prefix2781=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2782=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2783=== CONT TestGenerateFingerprint/no_references2784=== PAUSE TestExternalSignerErrors/wrong_shape2785=== RUN TestExternalSignerErrors/null2786--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2787=== CONT TestSignErrors/nil_narinfo2788=== PAUSE TestExternalSignerErrors/null2789=== RUN TestExternalSignerErrors/wrong_id2790=== PAUSE TestExternalSignerErrors/wrong_id2791--- PASS: TestParseSigningKey (0.00s)2792 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2793 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2794 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2795 --- PASS: TestParseSigningKey/no_colon (0.00s)2796 --- PASS: TestParseSigningKey/empty_name (0.00s)2797 --- PASS: TestParseSigningKey/wrong_length (0.00s)2798=== RUN TestExternalSignerErrors/missing_signatures2799=== PAUSE TestExternalSignerErrors/missing_signatures2800=== RUN TestExternalSignerErrors/wrong_signatures_shape2801=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2802=== RUN TestExternalSignerErrors/too_few_signatures2803=== PAUSE TestExternalSignerErrors/too_few_signatures2804=== RUN TestExternalSignerErrors/wrong_signature_length2805=== PAUSE TestExternalSignerErrors/wrong_signature_length2806=== RUN TestExternalSignerErrors/invalid_JSON2807=== PAUSE TestExternalSignerErrors/invalid_JSON2808--- PASS: TestExternalSignerWrongPublicKey (0.00s)2809=== RUN TestExternalSignerErrors/unrequested_key2810--- PASS: TestGenerateFingerprint (0.00s)2811 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2812 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2813 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2814 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2815 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2816 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2817 --- PASS: TestGenerateFingerprint/no_references (0.00s)2818=== PAUSE TestExternalSignerErrors/unrequested_key2819--- PASS: TestExternalSignerClose (0.00s)2820=== CONT TestExternalSignerErrors/missing_signature_name2821=== CONT TestExternalSignerErrors/null2822=== CONT TestExternalSignerErrors/invalid_signature_base642823=== CONT TestExternalSignerErrors/exit_on_request2824=== CONT TestExternalSignerErrors/missing_signatures2825=== CONT TestExternalSignerErrors/unrequested_key2826=== CONT TestExternalSignerErrors/wrong_shape2827=== CONT TestExternalSignerErrors/invalid_JSON2828=== CONT TestExternalSignerErrors/wrong_signature_length2829=== CONT TestExternalSignerErrors/too_few_signatures2830=== CONT TestExternalSignerErrors/program_error2831--- PASS: TestSignErrors (0.00s)2832 --- PASS: TestSignErrors/nil_key (0.00s)2833 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2834 --- PASS: TestSignErrors/canceled (0.00s)2835 --- PASS: TestSignErrors/nil_narinfo (0.00s)2836=== CONT TestExternalSignerErrors/wrong_signatures_shape2837=== CONT TestExternalSignerErrors/wrong_signature_name2838=== CONT TestExternalSignerErrors/null_signatures2839=== CONT TestExternalSignerErrors/exit_at_startup2840=== CONT TestExternalSignerErrors/wrong_id2841--- PASS: TestExternalSigner (0.01s)2842--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2843--- PASS: TestExternalSignerErrors (0.01s)2844 --- PASS: TestExternalSignerErrors/missing_signature_name (0.00s)2845 --- PASS: TestExternalSignerErrors/null (0.00s)2846 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.00s)2847 --- PASS: TestExternalSignerErrors/exit_on_request (0.00s)2848 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.00s)2849 --- PASS: TestExternalSignerErrors/unrequested_key (0.00s)2850 --- PASS: TestExternalSignerErrors/wrong_shape (0.00s)2851 --- PASS: TestExternalSignerErrors/invalid_JSON (0.00s)2852 --- PASS: TestExternalSignerErrors/exit_at_startup (0.00s)2853 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.00s)2854 --- PASS: TestExternalSignerErrors/missing_signatures (0.01s)2855 --- PASS: TestExternalSignerErrors/too_few_signatures (0.01s)2856 --- PASS: TestExternalSignerErrors/null_signatures (0.00s)2857 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2858 --- PASS: TestExternalSignerErrors/wrong_id (0.00s)2859 --- PASS: TestExternalSignerErrors/program_error (0.01s)2860--- PASS: TestExternalSignerCancellation (0.02s)2861PASS2862Running OpenBao signer tests...2863=== RUN TestSign2864=== PAUSE TestSign2865=== RUN TestSignErrors2866=== PAUSE TestSignErrors2867=== RUN TestServe2868=== PAUSE TestServe2869=== RUN TestServeRejectsGarbage2870=== PAUSE TestServeRejectsGarbage2871=== CONT TestSign2872=== CONT TestServe2873=== CONT TestSignErrors2874=== CONT TestServeRejectsGarbage2875=== RUN TestSignErrors/http_error2876=== PAUSE TestSignErrors/http_error2877--- PASS: TestServeRejectsGarbage (0.00s)2878--- PASS: TestServe (0.00s)2879=== RUN TestSignErrors/invalid_json2880=== PAUSE TestSignErrors/invalid_json2881=== RUN TestSignErrors/no_prefix2882=== PAUSE TestSignErrors/no_prefix2883=== RUN TestSignErrors/invalid_base642884=== PAUSE TestSignErrors/invalid_base642885=== CONT TestSignErrors/http_error2886=== CONT TestSignErrors/no_prefix2887=== CONT TestSignErrors/invalid_base642888=== CONT TestSignErrors/invalid_json2889--- PASS: TestSign (0.00s)2890--- PASS: TestSignErrors (0.00s)2891 --- PASS: TestSignErrors/invalid_json (0.00s)2892 --- PASS: TestSignErrors/http_error (0.00s)2893 --- PASS: TestSignErrors/invalid_base64 (0.00s)2894 --- PASS: TestSignErrors/no_prefix (0.00s)2895PASS