niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #435
· raw
1tribuchet: building on mac022Running 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.09s)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 TestScriptTokenBadJSON117=== CONT TestScriptTokenEmptyCommand118--- PASS: TestScriptTokenEmptyCommand (0.00s)119=== CONT TestShellSplitErrors120--- PASS: TestShellSplitErrors (0.00s)121=== CONT TestShellSplit122=== CONT TestScriptTokenScriptFails123--- PASS: TestShellSplit (0.00s)124=== CONT TestDoWithRetry_FinalResponseBodyReadable125=== CONT TestResolveStorePath126=== CONT TestScriptTokenEmptyToken127=== CONT TestScriptTokenCachesUntilRefresh128=== CONT TestScriptTokenNoExpiryRerunsEveryCall129=== CONT TestFileTokenEmpty130=== CONT TestFileTokenMissing131=== CONT TestFileTokenReadsAndCaches132=== CONT TestStaticToken133--- PASS: TestStaticToken (0.00s)134=== CONT TestRetryTimeoutOutlastsMaxRetries135=== CONT TestSetClientTLSErrors136=== CONT TestSetClientTLSDoesNotMutateDefaultTransport137=== CONT TestSetClientTLS138=== CONT TestStreamPushStopsWhenCanceled139=== CONT TestDumpPathSingleFile140=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer1412026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:57233142=== CONT TestClientSignaturesByStorePath143=== CONT TestStreamPushReportsSkippedPaths144=== CONT TestRateLimiterFeedback145=== RUN TestRateLimiterFeedback/429_enables_limiter146=== PAUSE TestRateLimiterFeedback/429_enables_limiter147=== RUN TestRateLimiterFeedback/503_enables_limiter148=== PAUSE TestRateLimiterFeedback/503_enables_limiter149=== CONT TestPathInfoCACompatibility150=== RUN TestPathInfoCACompatibility/null_ca_field151=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter1522026/10/25 19:40:15 WARN Rate limiter enabled after throttle name=server-test rate=51532026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:57232154=== CONT TestStreamPushRequestLine155=== CONT TestStreamPushGivesUpOnDeadServer156=== CONT TestPathInfoHashCompatibility157=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)158=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)159=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon160=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon161=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI162=== CONT TestStreamPushIsolatesFailures163=== CONT TestStreamPushBatchesUnderLoad164=== CONT TestStreamPushReportsEveryPath165--- PASS: TestFileTokenEmpty (0.00s)166=== CONT TestDoWithRetry_BodyReplayedViaGetBody167=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess168=== PAUSE TestPathInfoCACompatibility/null_ca_field169=== RUN TestPathInfoCACompatibility/old_string_format_-_text170=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text171=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive1722026/10/25 19:40:15 WARN Rate limiter backed off name=server-test rate=5173=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive1742026/10/25 19:40:15 ERROR Upload failed error="connection refused" count=201752026/10/25 19:40:15 ERROR Server seems unavailable, giving up on batch untried=17176=== RUN TestPathInfoCACompatibility/new_structured_format_-_text1772026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:57233178=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI179=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512180=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512181=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text182=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method183=== CONT TestParsePathInfoJSONMultiplePaths184=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths185=== CONT TestConvertHashToNix32186=== CONT TestParsePathInfoJSON1872026/10/25 19:40:15 ERROR Upload failed error=boom count=1188=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter189--- PASS: TestStreamPushStopsWhenCanceled (0.00s)190--- PASS: TestFileTokenReadsAndCaches (0.00s)191--- PASS: TestClientSignaturesByStorePath (0.00s)192--- PASS: TestFileTokenMissing (0.00s)193--- PASS: TestStreamPushReportsSkippedPaths (0.00s)194--- PASS: TestResolveStorePath (0.01s)195--- PASS: TestScriptTokenScriptFails (0.01s)196--- PASS: TestDoServerRequestAttachesToken (0.01s)197=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter1982026/10/25 19:40:15 WARN Rate limiter enabled after throttle name=server-test rate=5199=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter200=== RUN TestConvertHashToNix32/SRI_format_to_Nix32201=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32202=== RUN TestConvertHashToNix32/already_Nix32_format203=== PAUSE TestConvertHashToNix32/already_Nix32_format204=== RUN TestConvertHashToNix32/invalid_format205=== PAUSE TestConvertHashToNix32/invalid_format206=== CONT TestGetStorePathHash207=== CONT TestEncodeNixBase32WithRealHash208=== RUN TestSetClientTLSErrors/missing_cert_file209=== PAUSE TestSetClientTLSErrors/missing_cert_file210=== CONT TestEncodeNixBase32211=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method212=== RUN TestGetStorePathHash/valid_store_path213=== PAUSE TestGetStorePathHash/valid_store_path2142026/10/25 19:40:15 ERROR Upload failed error="bad path" count=3215=== RUN TestGetStorePathHash/basename_without_hyphen_should_error216=== RUN TestEncodeNixBase32/test_string_hash217=== PAUSE TestEncodeNixBase32/test_string_hash218=== RUN TestEncodeNixBase32/empty_input219=== PAUSE TestEncodeNixBase32/empty_input220=== CONT TestPartSizeForNAR221=== RUN TestPartSizeForNAR/zero_stays_at_minimum222=== RUN TestSetClientTLS/rejects_connection_without_client_cert223=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert224=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA225=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA226=== CONT TestSupersededNARStillUploadsListing227=== CONT TestUploadMultipart_SupersededByPeer228=== RUN TestSupersededNARStillUploadsListing/small_NAR229=== PAUSE TestSupersededNARStillUploadsListing/small_NAR230=== RUN TestSupersededNARStillUploadsListing/dump_cut_short231=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short232=== RUN TestUploadMultipart_SupersededByPeer/exists233=== PAUSE TestUploadMultipart_SupersededByPeer/exists234=== RUN TestUploadMultipart_SupersededByPeer/missing235=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails236=== PAUSE TestUploadMultipart_SupersededByPeer/missing237=== RUN TestParsePathInfoJSON/Nix_format238--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)239--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)240=== CONT TestDumpPathWriterError241=== RUN TestSetClientTLSErrors/missing_key_file242=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths243=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error244=== CONT TestUploadMultipart_FailedPartBufferNotReused245=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum246=== CONT TestUploadMultipart_PartsInParallel247=== CONT TestDumpPathMatchesNix248=== RUN TestSetClientTLS/preserves_debug_logging_transport249=== CONT TestStreamPushReportsSignatures250=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails251=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun252--- PASS: TestStreamPushReportsEveryPath (0.00s)253--- PASS: TestEncodeNixBase32WithRealHash (0.00s)254--- PASS: TestStreamPushIsolatesFailures (0.00s)255--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)256--- PASS: TestScriptTokenBadJSON (0.01s)257=== CONT TestCaseHackSuffix258=== PAUSE TestSetClientTLSErrors/missing_key_file259=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths260=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths2612026/10/25 19:40:15 WARN Rate limiter enabled after throttle name=server-test rate=5262=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error2632026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:57241264=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error265=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error266=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error267=== RUN TestSetClientTLSErrors/missing_ca_file268=== PAUSE TestSetClientTLSErrors/missing_ca_file269=== RUN TestSetClientTLSErrors/invalid_ca_file270=== PAUSE TestSetClientTLSErrors/invalid_ca_file271=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica272=== CONT TestRegisterUploadedObjectReusesConnections2732026/10/25 19:40:15 ERROR Upload failed error=boom count=12742026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:572332752026/10/25 19:40:15 WARN Rate limiter backed off name=server-test rate=52762026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:572412772026/10/25 19:40:15 INFO Garbage collection started278=== PAUSE TestParsePathInfoJSON/Nix_format279=== PAUSE TestSetClientTLS/preserves_debug_logging_transport280=== RUN TestParsePathInfoJSON/Lix_format281--- PASS: TestStreamPushReportsSignatures (0.00s)282=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)283=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512284=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry285=== CONT TestFilterOversizedClosures286=== RUN TestPartSizeForNAR/small_stays_at_minimum287=== PAUSE TestPartSizeForNAR/small_stays_at_minimum288=== PAUSE TestParsePathInfoJSON/Lix_format289=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI290=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum291=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter292=== CONT TestRateLimiterFeedback/429_enables_limiter293--- PASS: TestScriptTokenEmptyToken (0.01s)294--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)295=== RUN TestParsePathInfoJSON/empty_input296=== PAUSE TestParsePathInfoJSON/empty_input297=== RUN TestParsePathInfoJSON/whitespace_only298=== PAUSE TestParsePathInfoJSON/whitespace_only299=== RUN TestParsePathInfoJSON/invalid_JSON300=== PAUSE TestParsePathInfoJSON/invalid_JSON301=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum302=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts303=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts304=== RUN TestPartSizeForNAR/1_TiB305=== PAUSE TestPartSizeForNAR/1_TiB306=== RUN TestPartSizeForNAR/5_TiB_S3_max_object307=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object308=== RUN TestPartSizeForNAR/capped_at_5_GiB309=== PAUSE TestPartSizeForNAR/capped_at_5_GiB310=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon311=== CONT TestConvertHashToNix32/SRI_format_to_Nix32312=== CONT TestRateLimiterFeedback/503_enables_limiter313=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter314=== CONT TestConvertHashToNix32/invalid_format315=== CONT TestConvertHashToNix32/already_Nix32_format316--- PASS: TestConvertHashToNix32 (0.00s)317 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)318 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)319 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)320=== CONT TestPathInfoCACompatibility/null_ca_field321=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method322=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive323=== CONT TestPathInfoCACompatibility/new_structured_format_-_text324=== CONT TestPathInfoCACompatibility/old_string_format_-_text325--- PASS: TestPathInfoCACompatibility (0.00s)326 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)327 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)328 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)329 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)330 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)331=== CONT TestEncodeNixBase32/test_string_hash332=== CONT TestEncodeNixBase32/empty_input333--- PASS: TestEncodeNixBase32 (0.00s)334 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)335 --- PASS: TestEncodeNixBase32/empty_input (0.00s)336=== CONT TestUploadMultipart_SupersededByPeer/exists337=== RUN TestFilterOversizedClosures/no_limit_keeps_everything338=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything339=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped340=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped341=== RUN TestFilterOversizedClosures/all_closures_skipped342=== PAUSE TestFilterOversizedClosures/all_closures_skipped343=== CONT TestUploadMultipart_SupersededByPeer/missing344--- PASS: TestPathInfoHashCompatibility (0.00s)345 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)346 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)347 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)348 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)349=== CONT TestSupersededNARStillUploadsListing/small_NAR3502026/10/25 19:40:15 INFO Uploading abc-hello (1.0GB)3512026/10/25 19:40:15 INFO Garbage collection started3522026/10/25 19:40:15 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=03532026/10/25 19:40:15 WARN Rate limiter enabled after throttle name=server-test rate=53542026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:573163552026/10/25 19:40:15 WARN Rate limiter backed off name=server-test rate=5356=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails357--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)358=== CONT TestSupersededNARStillUploadsListing/dump_cut_short359--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)360 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)361 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)362=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths363=== CONT TestGetStorePathHash/valid_store_path364=== CONT TestSetClientTLSErrors/missing_cert_file365=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error366=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error367=== CONT TestGetStorePathHash/basename_without_hyphen_should_error368--- PASS: TestGetStorePathHash (0.00s)369 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)370 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)371 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)372 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)373=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths3742026/10/25 19:40:15 WARN Garbage collection finished on another replica. Its statistics are not available here375--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)376 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)377 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)378=== CONT TestSetClientTLSErrors/invalid_ca_file379--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)380=== CONT TestSetClientTLSErrors/missing_ca_file3812026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:57233382=== CONT TestSetClientTLSErrors/missing_key_file383=== CONT TestSetClientTLS/rejects_connection_without_client_cert384=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA385=== CONT TestSetClientTLS/preserves_debug_logging_transport386=== CONT TestParsePathInfoJSON/Nix_format387=== CONT TestParsePathInfoJSON/Lix_format388=== CONT TestPartSizeForNAR/zero_stays_at_minimum389=== CONT TestParsePathInfoJSON/empty_input390=== CONT TestPartSizeForNAR/capped_at_5_GiB391=== CONT TestPartSizeForNAR/5_TiB_S3_max_object392=== CONT TestPartSizeForNAR/1_TiB393=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts394=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum395=== CONT TestPartSizeForNAR/small_stays_at_minimum396--- PASS: TestSetClientTLSErrors (0.01s)397 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)398 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)399 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)400 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)401--- PASS: TestPartSizeForNAR (0.01s)402 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)403 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)404 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)405 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)406 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)407 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)408 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)409=== CONT TestParsePathInfoJSON/invalid_JSON410=== CONT TestParsePathInfoJSON/whitespace_only411--- PASS: TestParsePathInfoJSON (0.01s)412 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)413 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)414 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)415 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)416 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)417=== CONT TestFilterOversizedClosures/no_limit_keeps_everything418=== CONT TestFilterOversizedClosures/all_closures_skipped4192026/10/25 19:40:15 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=50420=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped4212026/10/25 19:40:15 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=2000422--- PASS: TestFilterOversizedClosures (0.00s)423 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)424 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)425 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)4262026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:572334272026/10/25 19:40:15 INFO Uploading abc-hello (1.0GB)4282026/10/25 19:40:15 WARN Rate limiter enabled after throttle name=server-test rate=54292026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:57311430--- PASS: TestStreamPushRequestLine (0.03s)4312026/10/25 19:40:15 WARN Rate limiter backed off name=server-test rate=5432--- PASS: TestRateLimiterFeedback (0.00s)433 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)434 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)435 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)436 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)4372026/10/25 19:40:15 WARN Rate limiter enabled after throttle name=s3-test rate=54382026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:57319439--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.02s)4402026/10/25 19:40:15 WARN Rate limiter enabled after throttle name=s3-test rate=54412026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:572334422026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:57233443--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)4442026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:572334452026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:572334462026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:572334472026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:57233448--- PASS: TestRegisterUploadedObjectReusesConnections (0.04s)4492026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:572334502026/10/25 19:40:15 http: TLS handshake error from 127.0.0.1:57331: read tcp 127.0.0.1:57244->127.0.0.1:57331: use of closed network connection451--- PASS: TestSetClientTLS (0.01s)452 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)453 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)454 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.03s)4552026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:57233456--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)4572026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:572334582026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:57233459--- PASS: TestDumpPathSingleFile (0.05s)4602026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:57233461--- PASS: TestCaseHackSuffix (0.05s)4622026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:572334632026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:572334642026/10/25 19:40:15 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:57233465--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.07s)466--- PASS: TestDumpPathWriterError (0.06s)4672026/10/25 19:40:15 INFO Uploading abc-hello (1.0GB)4682026/10/25 19:40:15 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:57328/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:57328/part/24692026/10/25 19:40:15 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"470--- PASS: TestDumpPathMatchesNix (0.09s)471--- PASS: TestStreamPushBatchesUnderLoad (0.10s)472--- PASS: TestSupersededNARStillUploadsListing (0.00s)473 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.01s)474 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.01s)475 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.55s)476--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.57s)477--- PASS: TestUploadMultipart_PartsInParallel (0.62s)4782026/10/25 19:40:16 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:57237/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:57237/api/uploads/complete4792026/10/25 19:40:16 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4802026/10/25 19:40:16 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:57237/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:57237/api/uploads/complete4812026/10/25 19:40:16 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:57237/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:57237/api/uploads/complete4822026/10/25 19:40:16 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4832026/10/25 19:40:16 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"484--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)485--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)486PASS487Running server tests...488The files belonging to this database system will be owned by user "_tribuchetbld1".489This user must also own the server process.490491The database cluster will be initialized with locale "C".492The default database encoding has accordingly been set to "SQL_ASCII".493The default text search configuration will be set to "english".494495Data page checksums are enabled.496497creating directory /private/var/tb/1/scratch/bd884a333ef9104d/build/postgres2711059402/data ... ok498creating subdirectories ... ok499selecting dynamic shared memory implementation ... posix500selecting default "max_connections" ... 100501selecting default "shared_buffers" ... 128MB502selecting default time zone ... UTC503creating configuration files ... ok504running bootstrap script ... ok505performing post-bootstrap initialization ... ok506syncing data to disk ... ok507508initdb: warning: enabling "trust" authentication for local connections509initdb: 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.510511Success. You can now start the database server using:512513 pg_ctl -D /private/var/tb/1/scratch/bd884a333ef9104d/build/postgres2711059402/data -l logfile start514515/private/var/tb/1/scratch/bd884a333ef9104d/build/postgres2711059402:5432 - no response5162026-10-25 19:40:17.288 UTC [47882] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5172026-10-25 19:40:17.289 UTC [47882] LOG: listening on Unix socket "/private/var/tb/1/scratch/bd884a333ef9104d/build/postgres2711059402/.s.PGSQL.5432"5182026-10-25 19:40:17.291 UTC [47890] LOG: database system was shut down at 2026-10-25 19:40:17 UTC5192026-10-25 19:40:17.292 UTC [47882] LOG: database system is ready to accept connections520/private/var/tb/1/scratch/bd884a333ef9104d/build/postgres2711059402:5432 - accepting connections521{"timestamp":"2026-10-25T19:40:17.523266Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"76bd3d1d-3f77-46fc-8688-ccadb1641e55","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":11,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}522{"timestamp":"2026-10-25T19:40:17.629972Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"acea8dac-0ff0-4312-86fe-bf248513a25c","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(7)"}523{"timestamp":"2026-10-25T19:40:17.733588Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"8a457f8e-1232-4a95-b1a8-05cd62704ece","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(3)"}524=== RUN TestService_AuthMiddleware525=== PAUSE TestService_AuthMiddleware526=== RUN TestService_AuthMiddleware_MTLSProxyHeader527=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader528=== RUN TestService_AuthMiddleware_MTLSBoundSubjects529=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects530=== RUN TestService_ReadAuthMiddleware531=== PAUSE TestService_ReadAuthMiddleware532=== RUN TestService_AuthMiddleware_OIDC533=== PAUSE TestService_AuthMiddleware_OIDC534=== RUN TestService_RequireScope_OIDC535=== PAUSE TestService_RequireScope_OIDC536=== RUN TestService_ReadScope_PublicByDefault537=== PAUSE TestService_ReadScope_PublicByDefault538=== RUN TestCacheConfigHandler539=== PAUSE TestCacheConfigHandler540=== RUN TestCacheStatsHandler541=== PAUSE TestCacheStatsHandler542=== RUN TestClientCADerivations543=== PAUSE TestClientCADerivations544=== RUN TestClientErrorHandling545=== PAUSE TestClientErrorHandling546=== RUN TestClientIntegration547=== PAUSE TestClientIntegration548=== RUN TestClientMultipleUploads549=== PAUSE TestClientMultipleUploads550=== RUN TestClientWithDependencies551=== PAUSE TestClientWithDependencies552=== RUN TestClientSharedPathCommittedMidPush553=== PAUSE TestClientSharedPathCommittedMidPush554=== RUN TestPinProtectsFromGC555=== PAUSE TestPinProtectsFromGC556=== RUN TestClientPushesUseOnePush557=== PAUSE TestClientPushesUseOnePush558=== RUN TestClientFallsBackToClosures559=== PAUSE TestClientFallsBackToClosures560=== RUN TestDeleteClosuresRacingPins561=== PAUSE TestDeleteClosuresRacingPins562=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock563=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock564=== RUN TestResolveDBConnectionString565=== PAUSE TestResolveDBConnectionString566=== RUN TestConnectWaitsForAPeerMigration567=== PAUSE TestConnectWaitsForAPeerMigration568=== RUN TestLeadElectsOneAndHandsOver569=== PAUSE TestLeadElectsOneAndHandsOver570=== RUN TestLeadIncumbentWinsAfterRestart5712026/10/25 19:40:18 INFO lead: acquired remote=192.0.2.1:12345722026/10/25 19:40:18 INFO lead: released remote=192.0.2.1:12345732026/10/25 19:40:18 INFO lead: acquired remote=192.0.2.1:12345742026/10/25 19:40:19 INFO lead: released remote=192.0.2.1:1234575--- PASS: TestLeadIncumbentWinsAfterRestart (1.88s)576=== RUN TestLeadIncumbentAnnouncesAtOnce577=== PAUSE TestLeadIncumbentAnnouncesAtOnce578=== RUN TestLeadEndsOnShutdown579=== PAUSE TestLeadEndsOnShutdown580=== RUN TestLeadEndsWhenItsConnectionHangs5812026/10/25 19:40:19 INFO lead: acquired remote=192.0.2.1:12345822026-10-25 19:40:21.281 UTC [48000] FATAL: terminating connection due to administrator command5832026/10/25 19:40:21 INFO lead: acquired remote=192.0.2.1:12345842026/10/25 19:40:22 WARN lead: lock connection lost error="timeout: context deadline exceeded"5852026/10/25 19:40:22 INFO lead: released remote=192.0.2.1:12345862026/10/25 19:40:22 INFO lead: released remote=192.0.2.1:1234587--- PASS: TestLeadEndsWhenItsConnectionHangs (2.96s)588=== RUN TestGCAdvisoryLockBlocksConcurrentRun589=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun590=== RUN TestGCBugBareHashReferences591=== PAUSE TestGCBugBareHashReferences592=== RUN TestGCMetrics593=== PAUSE TestGCMetrics594=== RUN TestPushDedupSurvivesConcurrentGC595=== PAUSE TestPushDedupSurvivesConcurrentGC596=== RUN TestDeduplicatedObjectsRecordedAsPending597=== PAUSE TestDeduplicatedObjectsRecordedAsPending598=== RUN TestGCSweepSkipsPendingObjects599=== PAUSE TestGCSweepSkipsPendingObjects600=== RUN TestTombstonedObjectOfferedWithoutWaiting601=== PAUSE TestTombstonedObjectOfferedWithoutWaiting602=== RUN TestGCSweepDeliversEachKeyOnce603=== PAUSE TestGCSweepDeliversEachKeyOnce604=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection605=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection606=== RUN TestForceGCDuringPushOffersSweptObject607=== PAUSE TestForceGCDuringPushOffersSweptObject608=== RUN TestFailedS3DeleteKeepsTombstone609=== PAUSE TestFailedS3DeleteKeepsTombstone610=== RUN TestSweepSkipsRowsLockedByPush611=== PAUSE TestSweepSkipsRowsLockedByPush612=== RUN TestRegisterCompletedObjectNeedsPendingRow613=== PAUSE TestRegisterCompletedObjectNeedsPendingRow614=== RUN TestGetExistingObjectsLocksRows615=== PAUSE TestGetExistingObjectsLocksRows616=== RUN TestSweepRechecksPendingAfterLocking617=== PAUSE TestSweepRechecksPendingAfterLocking618=== RUN TestPushWaitsForSweepHoldingRow619=== PAUSE TestPushWaitsForSweepHoldingRow620=== RUN TestCommitRacingPendingCleanupKeepsObjects621=== PAUSE TestCommitRacingPendingCleanupKeepsObjects622=== RUN TestGCEndsOnShutdown623=== PAUSE TestGCEndsOnShutdown624=== RUN TestGCTaskStore_StartNew625=== PAUSE TestGCTaskStore_StartNew626=== RUN TestGCTaskStore_DeduplicateSameParams627=== PAUSE TestGCTaskStore_DeduplicateSameParams628=== RUN TestGCTaskStore_ConflictDifferentParams629=== PAUSE TestGCTaskStore_ConflictDifferentParams630=== RUN TestGCTaskStore_GetEmpty631=== PAUSE TestGCTaskStore_GetEmpty632=== RUN TestGCTaskStore_GetReturnsLatest633=== PAUSE TestGCTaskStore_GetReturnsLatest634=== RUN TestGCTaskStore_CompletedAllowsNewTask635=== PAUSE TestGCTaskStore_CompletedAllowsNewTask636=== RUN TestGCTaskStore_PhaseUpdates637=== PAUSE TestGCTaskStore_PhaseUpdates638=== RUN TestGCTaskStore_Fail639=== PAUSE TestGCTaskStore_Fail640=== RUN TestGracefulShutdownDrainsInflight641=== PAUSE TestGracefulShutdownDrainsInflight642=== RUN TestService_healthCheckHandler643=== PAUSE TestService_healthCheckHandler644=== RUN TestService_readinessHandler645=== PAUSE TestService_readinessHandler646=== RUN TestGenerateLandingPage647=== PAUSE TestGenerateLandingPage648=== RUN TestCacheConfigHandlerMaxNarSize649=== PAUSE TestCacheConfigHandlerMaxNarSize650=== RUN TestCreatePendingClosureRejectsOversizedNAR651=== PAUSE TestCreatePendingClosureRejectsOversizedNAR652=== RUN TestNARDeduplicationMetadataUploadBug653=== PAUSE TestNARDeduplicationMetadataUploadBug654=== RUN TestMetricsInventory655=== PAUSE TestMetricsInventory656=== RUN TestMetricsCommit657=== PAUSE TestMetricsCommit658=== RUN TestService_NativeMTLS659=== PAUSE TestService_NativeMTLS660=== RUN TestServerTLSConfig661=== PAUSE TestServerTLSConfig662=== RUN TestMultipartCleanup663=== PAUSE TestMultipartCleanup664=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded665=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded666=== RUN TestPendingCleanupUsesOneCutoff667=== PAUSE TestPendingCleanupUsesOneCutoff668=== RUN TestObjectStatsTrigger669=== PAUSE TestObjectStatsTrigger670=== RUN TestObjectStatsUpdatedOncePerCommit671=== PAUSE TestObjectStatsUpdatedOncePerCommit672=== RUN TestOrphanedObjectsGC673=== PAUSE TestOrphanedObjectsGC674=== RUN TestOrphanedObjectsGCStressTest675=== PAUSE TestOrphanedObjectsGCStressTest676=== RUN TestCreatePin_ReservedPins677=== PAUSE TestCreatePin_ReservedPins678=== RUN TestPresentReportsOnlyClosureRoots679=== PAUSE TestPresentReportsOnlyClosureRoots680=== RUN TestPresentRefreshesOnlyStaleClosures681=== PAUSE TestPresentRefreshesOnlyStaleClosures682=== RUN TestPresentNotReportedWhileGCDeletesClosure683=== PAUSE TestPresentNotReportedWhileGCDeletesClosure684=== RUN TestParseSingleRange685=== PAUSE TestParseSingleRange686=== RUN TestProxyHeadersOnlyTrustedOnSocket6872026/10/25 19:40:22 INFO Starting HTTP server address=proxy.sock6882026/10/25 19:40:22 INFO Starting HTTP server address=127.0.0.1:575166892026/10/25 19:40:22 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6902026/10/25 19:40:22 INFO Shutdown signal received, draining in-flight requests timeout=10s691--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.14s)692=== RUN TestIsValidCachePath693=== PAUSE TestIsValidCachePath694=== RUN TestReadProxyNarinfo695=== PAUSE TestReadProxyNarinfo696=== RUN TestReadProxyNarinfoAlreadyDecompressed697=== PAUSE TestReadProxyNarinfoAlreadyDecompressed698=== RUN TestReadProxyContentNegotiation699=== PAUSE TestReadProxyContentNegotiation700=== RUN TestReadProxyNarStreaming701=== PAUSE TestReadProxyNarStreaming702=== RUN TestReadProxy404703=== PAUSE TestReadProxy404704=== RUN TestReadProxyInvalidPath705=== PAUSE TestReadProxyInvalidPath706=== RUN TestReadProxyHead707=== PAUSE TestReadProxyHead708=== RUN TestReadProxyOutlastsServerWriteTimeout709=== PAUSE TestReadProxyOutlastsServerWriteTimeout710=== RUN TestReadProxyConditionalGet711=== PAUSE TestReadProxyConditionalGet712=== RUN TestReadProxyRootRedirectsToIndexHTML713=== PAUSE TestReadProxyRootRedirectsToIndexHTML714=== RUN TestReadProxyDisabled715=== PAUSE TestReadProxyDisabled716=== RUN TestReadRedirectNar717=== PAUSE TestReadRedirectNar718=== RUN TestReadRedirectKeepsNarinfoProxied719=== PAUSE TestReadRedirectKeepsNarinfoProxied720=== RUN TestReadProxyRangeRequest721=== PAUSE TestReadProxyRangeRequest722=== RUN TestReadRedirectUsesPublicS3URL723=== PAUSE TestReadRedirectUsesPublicS3URL724=== RUN TestPush_OverlappingRootsStoreOneRowPerKey725=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey726=== RUN TestPush_CompleteCommitsEveryRoot727=== PAUSE TestPush_CompleteCommitsEveryRoot728=== RUN TestPush_RepeatedRootCommitsOnce729=== PAUSE TestPush_RepeatedRootCommitsOnce730=== RUN TestPush_CompleteWaitsForCleanupOfThePush731=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush732=== RUN TestPush_RootsAreLockedInByteOrder733=== PAUSE TestPush_RootsAreLockedInByteOrder734=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit735=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit736=== RUN TestPush_RejectsBadRequests737=== PAUSE TestPush_RejectsBadRequests738=== RUN TestPush_SignsNarinfosOfItsPendingObjects739=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects740=== RUN TestRedundantMultipartUpload741=== PAUSE TestRedundantMultipartUpload742=== RUN TestCompleteMultipartUpload_ErrorButObjectExists743=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists744=== RUN TestCompletedNarNotReofferedAcrossClosures745=== PAUSE TestCompletedNarNotReofferedAcrossClosures746=== RUN TestPresignedUploadRegisteredBeforeCommit747=== PAUSE TestPresignedUploadRegisteredBeforeCommit748=== RUN TestService_Rustfstest749=== PAUSE TestService_Rustfstest750=== RUN TestParseSize751=== PAUSE TestParseSize752=== RUN TestSkippedUploadsHandler753=== PAUSE TestSkippedUploadsHandler754=== RUN TestSystemdListenerNotActivated755--- PASS: TestSystemdListenerNotActivated (0.00s)756=== RUN TestWatchdogBeatsWhenHealthy757--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)758=== RUN TestWatchdogSkipsWhenUnhealthy7592026/10/25 19:40:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/25 19:40:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7612026/10/25 19:40:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7622026/10/25 19:40:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7632026/10/25 19:40:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7642026/10/25 19:40:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7652026/10/25 19:40:23 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7662026/10/25 19:40:23 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7672026/10/25 19:40:23 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7682026/10/25 19:40:23 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"769--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)770=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle771=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle772=== RUN TestProxyWriteTimeout773=== PAUSE TestProxyWriteTimeout774=== RUN TestPendingClosureWriteTimeout775=== PAUSE TestPendingClosureWriteTimeout776=== RUN TestIsValidUploadKey777=== PAUSE TestIsValidUploadKey778=== RUN TestUploadHandlersRejectInvalidKeys779=== PAUSE TestUploadHandlersRejectInvalidKeys780=== RUN TestUploadHandlersRejectOversizedBody781=== PAUSE TestUploadHandlersRejectOversizedBody782=== RUN TestService_cleanupPendingClosuresHandler783=== PAUSE TestService_cleanupPendingClosuresHandler784=== RUN TestService_createPendingClosureHandler785=== PAUSE TestService_createPendingClosureHandler786=== RUN TestService_verifyS3Integrity787=== PAUSE TestService_verifyS3Integrity788=== RUN TestCompleteMultipartUnregistered789=== PAUSE TestCompleteMultipartUnregistered790=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT791=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT792=== CONT TestCompletedNarNotReofferedAcrossClosures793=== CONT TestGCTaskStore_Fail794=== CONT TestGetExistingObjectsLocksRows795--- PASS: TestGCTaskStore_Fail (0.00s)796=== CONT TestGCTaskStore_GetEmpty797--- PASS: TestGCTaskStore_GetEmpty (0.00s)798=== CONT TestPushDedupSurvivesConcurrentGC799=== CONT TestDeduplicatedObjectsRecordedAsPending800=== CONT TestGCTaskStore_PhaseUpdates801--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)802=== CONT TestGCTaskStore_CompletedAllowsNewTask803--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)804=== CONT TestGCBugBareHashReferences805=== CONT TestGCMetrics806=== CONT TestGCTaskStore_GetReturnsLatest807--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)808=== CONT TestGCTaskStore_ConflictDifferentParams809=== CONT TestIsValidUploadKey810=== CONT TestLeadEndsOnShutdown811=== RUN TestIsValidUploadKey/narinfo812=== CONT TestGCTaskStore_DeduplicateSameParams813=== CONT TestLeadIncumbentAnnouncesAtOnce814=== CONT TestGCTaskStore_StartNew815=== CONT TestLeadElectsOneAndHandsOver816=== CONT TestGCEndsOnShutdown817=== RUN TestGCEndsOnShutdown/before_the_run818=== PAUSE TestGCEndsOnShutdown/before_the_run819=== CONT TestCommitRacingPendingCleanupKeepsObjects820=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete821=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete822=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark823=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark824=== CONT TestConnectWaitsForAPeerMigration825=== CONT TestPushWaitsForSweepHoldingRow826=== CONT TestSweepRechecksPendingAfterLocking827=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT828=== CONT TestCompleteMultipartUnregistered829=== CONT TestService_verifyS3Integrity830=== CONT TestService_createPendingClosureHandler831=== CONT TestService_cleanupPendingClosuresHandler832=== CONT TestUploadHandlersRejectOversizedBody833=== CONT TestUploadHandlersRejectInvalidKeys834=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock835=== CONT TestService_AuthMiddleware836=== CONT TestGCAdvisoryLockBlocksConcurrentRun837--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)838--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)839--- PASS: TestGCTaskStore_StartNew (0.00s)840=== PAUSE TestIsValidUploadKey/narinfo841=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info842=== RUN TestIsValidUploadKey/nar_zst843=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info844=== PAUSE TestIsValidUploadKey/nar_zst845=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal846=== RUN TestIsValidUploadKey/nar_xz847=== PAUSE TestIsValidUploadKey/nar_xz848=== RUN TestIsValidUploadKey/nar_plain849=== PAUSE TestIsValidUploadKey/nar_plain850=== RUN TestIsValidUploadKey/listing851=== PAUSE TestIsValidUploadKey/listing852=== RUN TestIsValidUploadKey/build_log853=== PAUSE TestIsValidUploadKey/build_log854=== RUN TestIsValidUploadKey/build_log_home-manager_file855=== PAUSE TestIsValidUploadKey/build_log_home-manager_file856=== RUN TestIsValidUploadKey/build_log_plus_in_name857=== PAUSE TestIsValidUploadKey/build_log_plus_in_name858=== RUN TestIsValidUploadKey/build_log_question_mark859=== PAUSE TestIsValidUploadKey/build_log_question_mark860=== RUN TestIsValidUploadKey/build_log_equals861=== PAUSE TestIsValidUploadKey/build_log_equals862=== RUN TestIsValidUploadKey/realisation863=== PAUSE TestIsValidUploadKey/realisation864=== RUN TestIsValidUploadKey/realisation_plus_in_output865=== PAUSE TestIsValidUploadKey/realisation_plus_in_output866=== RUN TestIsValidUploadKey/nix-cache-info867=== PAUSE TestIsValidUploadKey/nix-cache-info868=== RUN TestIsValidUploadKey/index.html869=== PAUSE TestIsValidUploadKey/index.html870=== RUN TestIsValidUploadKey/narinfo_key,_nar_type871=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal872=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key873=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key874=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key875=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key876=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type877=== RUN TestIsValidUploadKey/nar_key,_narinfo_type878=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type879=== RUN TestIsValidUploadKey/listing_key,_narinfo_type880=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type881=== RUN TestIsValidUploadKey/traversal882=== PAUSE TestIsValidUploadKey/traversal883=== RUN TestIsValidUploadKey/traversal_nar884=== PAUSE TestIsValidUploadKey/traversal_nar885=== RUN TestIsValidUploadKey/absolute886=== PAUSE TestIsValidUploadKey/absolute887=== RUN TestIsValidUploadKey/empty_key888=== PAUSE TestIsValidUploadKey/empty_key889=== RUN TestIsValidUploadKey/unknown_type890=== PAUSE TestIsValidUploadKey/unknown_type891=== CONT TestResolveDBConnectionString892=== CONT TestReadProxyNarinfo893=== RUN TestResolveDBConnectionString/flag_wins894=== PAUSE TestResolveDBConnectionString/flag_wins895=== RUN TestResolveDBConnectionString/file_when_flag_empty896=== PAUSE TestResolveDBConnectionString/file_when_flag_empty897=== RUN TestResolveDBConnectionString/missing_file_is_an_error898=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error899=== RUN TestResolveDBConnectionString/PGHOST_allows_empty900=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty901=== RUN TestResolveDBConnectionString/nothing_configured902=== PAUSE TestResolveDBConnectionString/nothing_configured903=== CONT TestCompleteMultipartUpload_ErrorButObjectExists904=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure905=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure906=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart907=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart908=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts909=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts910=== CONT TestRedundantMultipartUpload9112026/10/25 19:40:23 INFO Received uploads request method=POST path=/api/pending_closures912--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.70s)913=== CONT TestPush_SignsNarinfosOfItsPendingObjects9142026/10/25 19:40:23 INFO Received uploads request method=POST path=/api/pending_closures915--- PASS: TestGetExistingObjectsLocksRows (1.21s)916=== CONT TestPush_RejectsBadRequests9172026/10/25 19:40:24 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"918--- PASS: TestService_AuthMiddleware (1.40s)919=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit9202026/10/25 19:40:24 INFO lead: acquired remote=192.0.2.1:12349212026/10/25 19:40:25 INFO Aborted multipart uploads count=0 kept=09222026/10/25 19:40:25 WARN Force mode enabled - objects will be deleted immediately without grace period9232026/10/25 19:40:25 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=09242026/10/25 19:40:25 INFO Vacuumed table table=pending_closures9252026/10/25 19:40:25 INFO Vacuumed table table=pending_objects9262026/10/25 19:40:25 INFO Vacuumed table table=multipart_uploads9272026/10/25 19:40:25 INFO Vacuumed table table=closures9282026/10/25 19:40:25 INFO Vacuumed table table=objects929--- PASS: TestGCMetrics (2.19s)930=== CONT TestPush_RootsAreLockedInByteOrder9312026/10/25 19:40:25 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9322026/10/25 19:40:25 INFO lead: released remote=192.0.2.1:1234933--- PASS: TestLeadEndsOnShutdown (2.77s)934=== CONT TestPush_CompleteWaitsForCleanupOfThePush9352026/10/25 19:40:25 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MGE2Yzc0ZTYtZGM4MS00ZDA2LWFiYWQtZjU1ZjRkZDQ2NmI5LjQ3ODNlNzljLTUyN2QtNDkzNC04OWEwLWZjMGQyZWIxMzdmM3gxNzkyOTU3MjI0MDMyNjcwMDAw parts=129362026/10/25 19:40:25 INFO Received uploads request method=POST path=/api/pending_closures937--- PASS: TestCompletedNarNotReofferedAcrossClosures (2.81s)938=== CONT TestPush_RepeatedRootCommitsOnce9392026/10/25 19:40:25 INFO lead: acquired remote=192.0.2.1:1234940--- PASS: TestGCBugBareHashReferences (2.96s)941=== CONT TestPush_CompleteCommitsEveryRoot9422026/10/25 19:40:26 INFO lead: acquired remote=192.0.2.1:12349432026/10/25 19:40:26 INFO lead: released remote=192.0.2.1:1234944--- PASS: TestLeadIncumbentAnnouncesAtOnce (3.10s)945=== CONT TestPush_OverlappingRootsStoreOneRowPerKey946--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (3.21s)947=== CONT TestReadRedirectUsesPublicS3URL9482026/10/25 19:40:26 INFO Aborted multipart uploads count=0 kept=09492026/10/25 19:40:26 WARN Force mode enabled - objects will be deleted immediately without grace period9502026/10/25 19:40:26 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=09512026/10/25 19:40:26 INFO Vacuumed table table=pending_closures9522026/10/25 19:40:26 INFO Vacuumed table table=pending_objects9532026/10/25 19:40:26 INFO Vacuumed table table=multipart_uploads9542026/10/25 19:40:26 INFO Vacuumed table table=closures9552026/10/25 19:40:26 INFO Vacuumed table table=objects956--- PASS: TestCommitRacingPendingCleanupKeepsObjects (3.44s)957=== CONT TestReadProxyRangeRequest9582026/10/25 19:40:26 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>959--- PASS: TestReadProxyNarinfo (3.47s)960=== CONT TestReadRedirectKeepsNarinfoProxied9612026/10/25 19:40:26 INFO Received uploads request method=POST path=/api/pending_closures9622026/10/25 19:40:26 INFO Received uploads request method=POST path=/api/pending_closures9632026/10/25 19:40:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9642026/10/25 19:40:26 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MGE2Yzc0ZTYtZGM4MS00ZDA2LWFiYWQtZjU1ZjRkZDQ2NmI5LmQ2N2MwOTczLTY5NTAtNGU1ZS05ZDkwLTJiNzA0NzM2NTY1YngxNzkyOTU3MjI2Njk4MTQ2MDAw9652026/10/25 19:40:26 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MGE2Yzc0ZTYtZGM4MS00ZDA2LWFiYWQtZjU1ZjRkZDQ2NmI5LmQ2N2MwOTczLTY5NTAtNGU1ZS05ZDkwLTJiNzA0NzM2NTY1YngxNzkyOTU3MjI2Njk4MTQ2MDAw parts=1966--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (3.86s)967=== CONT TestReadRedirectNar9682026/10/25 19:40:27 INFO Received uploads request method=POST path=/api/pending_closures9692026/10/25 19:40:27 INFO Received uploads request method=POST path=/api/pending_closures9702026/10/25 19:40:27 INFO Received uploads request method=POST path=/api/pending_closures9712026/10/25 19:40:27 INFO lead: released remote=192.0.2.1:12349722026/10/25 19:40:27 INFO lead: acquired remote=192.0.2.1:12349732026/10/25 19:40:27 INFO Received uploads request method=POST path=/api/pending_closures974--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (4.31s)975=== CONT TestReadProxyDisabled976--- PASS: TestPushWaitsForSweepHoldingRow (4.34s)977=== CONT TestReadProxyRootRedirectsToIndexHTML9782026/10/25 19:40:27 INFO Aborted multipart uploads count=0 kept=09792026/10/25 19:40:27 WARN Force mode enabled - objects will be deleted immediately without grace period9802026/10/25 19:40:27 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=09812026/10/25 19:40:27 INFO Vacuumed table table=pending_closures9822026/10/25 19:40:27 INFO Vacuumed table table=pending_objects9832026/10/25 19:40:27 INFO Vacuumed table table=multipart_uploads9842026/10/25 19:40:27 INFO Vacuumed table table=closures9852026/10/25 19:40:27 INFO Vacuumed table table=objects986--- PASS: TestSweepRechecksPendingAfterLocking (4.73s)987=== CONT TestReadProxyConditionalGet9882026/10/25 19:40:27 INFO Received uploads request method=POST path=/api/pending_closures9892026/10/25 19:40:27 INFO Received uploads request method=POST path=/api/pending_closures9902026/10/25 19:40:28 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9912026/10/25 19:40:28 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst992--- PASS: TestCompleteMultipartUnregistered (5.00s)993=== CONT TestReadProxyOutlastsServerWriteTimeout9942026/10/25 19:40:28 INFO lead: released remote=192.0.2.1:1234995--- PASS: TestLeadElectsOneAndHandsOver (5.21s)996=== CONT TestReadProxyHead9972026/10/25 19:40:28 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld1 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"998--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (5.28s)999=== CONT TestReadProxyInvalidPath10002026/10/25 19:40:28 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10012026/10/25 19:40:28 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MGE2Yzc0ZTYtZGM4MS00ZDA2LWFiYWQtZjU1ZjRkZDQ2NmI5LmQ1OGRkOGVmLWUyMWItNDk0ZC1iZGJkLWZkMDA2YzU4YWIxNXgxNzkyOTU3MjI3MTExMjQzMDAw parts=1010022026/10/25 19:40:28 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10032026/10/25 19:40:28 INFO Completed upload id=1 objects=2 duration=17.675083ms10042026/10/25 19:40:28 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010052026/10/25 19:40:28 INFO Received uploads request method=POST path=/api/pending_closures10062026/10/25 19:40:28 INFO Starting cleanup of old closures method=DELETE path=/api/closures10072026/10/25 19:40:28 INFO Aborted multipart uploads count=0 kept=010082026/10/25 19:40:28 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=010092026/10/25 19:40:28 INFO Vacuumed table table=pending_closures10102026/10/25 19:40:28 INFO Vacuumed table table=pending_objects10112026/10/25 19:40:28 INFO Vacuumed table table=multipart_uploads10122026/10/25 19:40:28 INFO Vacuumed table table=closures10132026/10/25 19:40:28 INFO Vacuumed table table=objects10142026/10/25 19:40:28 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001015--- PASS: TestService_createPendingClosureHandler (5.56s)1016=== CONT TestReadProxy40410172026/10/25 19:40:28 INFO Received uploads request method=POST path=/api/pending_closures10182026/10/25 19:40:28 INFO Received uploads request method=POST path=/api/pending_closures10192026/10/25 19:40:28 INFO Aborted multipart uploads count=0 kept=010202026/10/25 19:40:28 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=010212026/10/25 19:40:29 INFO Vacuumed table table=pending_closures10222026/10/25 19:40:29 INFO Vacuumed table table=pending_objects10232026/10/25 19:40:29 INFO Vacuumed table table=multipart_uploads10242026/10/25 19:40:29 INFO Vacuumed table table=closures10252026/10/25 19:40:29 INFO Vacuumed table table=objects10262026/10/25 19:40:29 INFO Aborted multipart uploads count=0 kept=010272026/10/25 19:40:29 WARN Force mode enabled - objects will be deleted immediately without grace period10282026/10/25 19:40:29 INFO Received cleanup request method=DELETE path=/api/pending_closures10292026/10/25 19:40:29 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=010302026/10/25 19:40:29 INFO Aborted multipart uploads count=0 kept=010312026/10/25 19:40:29 INFO Vacuumed table table=pending_closures10322026/10/25 19:40:29 INFO Vacuumed table table=pending_objects10332026/10/25 19:40:29 INFO Vacuumed table table=multipart_uploads10342026/10/25 19:40:29 INFO Received uploads request method=POST path=/api/pending_closures10352026/10/25 19:40:29 INFO Vacuumed table table=closures10362026/10/25 19:40:29 INFO Vacuumed table table=objects1037--- PASS: TestPushDedupSurvivesConcurrentGC (6.18s)1038=== CONT TestReadProxyNarStreaming10392026/10/25 19:40:29 INFO Received cleanup request method=DELETE path=/api/pending_closures10402026/10/25 19:40:29 INFO Aborted multipart uploads count=1 kept=010412026/10/25 19:40:29 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10422026-10-25 19:40:29.346 UTC [48195] ERROR: Closure does not exist: id=110432026-10-25 19:40:29.346 UTC [48195] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10442026-10-25 19:40:29.346 UTC [48195] STATEMENT: -- name: CommitPendingClosure :one1045 SELECT commit_pending_closure($1::bigint)::bigint1046 1047--- PASS: TestService_cleanupPendingClosuresHandler (6.29s)1048=== CONT TestReadProxyContentNegotiation10492026/10/25 19:40:29 INFO Received push request method=POST path=/api/pushes10502026/10/25 19:40:29 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10512026/10/25 19:40:29 INFO Received complete push request method=POST path=/api/pushes/1/complete10522026/10/25 19:40:29 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MGE2Yzc0ZTYtZGM4MS00ZDA2LWFiYWQtZjU1ZjRkZDQ2NmI5LjlhYjdhNmFlLTgyZmQtNDk0OC05YmQ3LWNjYzY5Mjk2MDAwOXgxNzkyOTU3MjI3ODQ2NTQxMDAw parts=1210532026/10/25 19:40:29 INFO Received uploads request method=POST path=/api/pending_closures10542026/10/25 19:40:29 INFO Completed push id=1 objects=4 duration=36.720375ms10552026/10/25 19:40:29 INFO Received push request method=POST path=/api/pushes10562026/10/25 19:40:29 INFO Received uploads request method=POST path=/api/pending_closures10572026/10/25 19:40:29 INFO Aborted multipart uploads count=0 kept=010582026/10/25 19:40:29 WARN Force mode enabled - objects will be deleted immediately without grace period10592026/10/25 19:40:29 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=01060=== RUN TestPush_RejectsBadRequests/no_roots1061=== PAUSE TestPush_RejectsBadRequests/no_roots1062=== RUN TestPush_RejectsBadRequests/no_objects1063=== PAUSE TestPush_RejectsBadRequests/no_objects1064=== RUN TestPush_RejectsBadRequests/bad_root1065=== PAUSE TestPush_RejectsBadRequests/bad_root1066=== RUN TestPush_RejectsBadRequests/root_not_in_objects1067=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1068=== CONT TestReadProxyNarinfoAlreadyDecompressed10692026/10/25 19:40:29 INFO Vacuumed table table=pending_closures10702026/10/25 19:40:29 INFO Vacuumed table table=pending_objects10712026/10/25 19:40:29 INFO Vacuumed table table=multipart_uploads10722026/10/25 19:40:29 INFO Vacuumed table table=closures10732026/10/25 19:40:29 INFO Vacuumed table table=objects10742026/10/25 19:40:29 INFO Received complete push request method=POST path=/api/pushes/2/complete10752026/10/25 19:40:30 INFO Completed push id=2 objects=4 duration=6.13275ms1076--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (5.55s)1077=== CONT TestForceGCDuringPushOffersSweptObject1078=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1079=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1080=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1081=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1082=== CONT TestRegisterCompletedObjectNeedsPendingRow10832026/10/25 19:40:30 INFO Received push request method=POST path=/api/pushes10842026/10/25 19:40:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10852026/10/25 19:40:30 INFO Signed narinfos id=1 count=110862026/10/25 19:40:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10872026/10/25 19:40:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10882026/10/25 19:40:30 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"10892026/10/25 19:40:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10902026/10/25 19:40:30 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"10912026/10/25 19:40:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10922026/10/25 19:40:30 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=110932026/10/25 19:40:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10942026/10/25 19:40:30 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1095--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (6.57s)1096=== CONT TestSweepSkipsRowsLockedByPush1097--- PASS: TestConnectWaitsForAPeerMigration (7.30s)1098=== CONT TestFailedS3DeleteKeepsTombstone10992026/10/25 19:40:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11002026/10/25 19:40:30 INFO Received push request method=POST path=/api/pushes11012026/10/25 19:40:30 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MGE2Yzc0ZTYtZGM4MS00ZDA2LWFiYWQtZjU1ZjRkZDQ2NmI5LjIzZmNjOTFhLTA0ZGItNDE1Mi04ZWIzLTQxODg0MWRlMmEzY3gxNzkyOTU3MjI4OTI1NzYyMDAw parts=1011022026/10/25 19:40:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11032026/10/25 19:40:30 INFO Completed upload id=1 objects=2 duration=30.372125ms11042026/10/25 19:40:30 INFO Received uploads request method=POST path=/api/pending_closures11052026/10/25 19:40:30 INFO Received uploads request method=POST path=/api/pending_closures11062026/10/25 19:40:30 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo11072026/10/25 19:40:30 WARN Found objects in DB but missing from S3, will re-upload count=11108--- PASS: TestService_verifyS3Integrity (7.73s)1109=== CONT TestGCSweepDeliversEachKeyOnce11102026-10-25 19:40:30.862 UTC [48383] ERROR: could not obtain lock on row in relation "closures"11112026-10-25 19:40:30.862 UTC [48383] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11122026-10-25 19:40:30.868 UTC [48383] ERROR: could not obtain lock on row in relation "closures"11132026-10-25 19:40:30.868 UTC [48383] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11142026-10-25 19:40:30.868 UTC [48383] ERROR: could not obtain lock on row in relation "closures"11152026-10-25 19:40:30.868 UTC [48383] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11162026-10-25 19:40:30.874 UTC [48383] ERROR: could not obtain lock on row in relation "closures"11172026-10-25 19:40:30.874 UTC [48383] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11182026-10-25 19:40:30.880 UTC [48383] ERROR: could not obtain lock on row in relation "closures"11192026-10-25 19:40:30.880 UTC [48383] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1120--- PASS: TestPush_RootsAreLockedInByteOrder (5.68s)1121=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection11222026/10/25 19:40:31 INFO Received push request method=POST path=/api/pushes11232026/10/25 19:40:31 INFO Received push request method=POST path=/api/pushes11242026/10/25 19:40:31 INFO Received complete push request method=POST path=/api/pushes/1/complete11252026/10/25 19:40:31 INFO Completed push id=1 objects=4 duration=24.748ms1126--- PASS: TestPush_RepeatedRootCommitsOnce (5.67s)1127=== CONT TestClientErrorHandling1128=== RUN TestClientErrorHandling/InvalidStorePath1129=== PAUSE TestClientErrorHandling/InvalidStorePath1130=== RUN TestClientErrorHandling/InvalidAuthToken1131=== PAUSE TestClientErrorHandling/InvalidAuthToken1132=== RUN TestClientErrorHandling/ServerNotAvailable1133=== PAUSE TestClientErrorHandling/ServerNotAvailable1134=== CONT TestDeleteClosuresRacingPins11352026-10-25 19:40:31.566 UTC [48403] ERROR: Push does not exist: id=111362026-10-25 19:40:31.566 UTC [48403] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE11372026-10-25 19:40:31.566 UTC [48403] STATEMENT: SELECT commit_push($1)1138--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (5.74s)1139=== CONT TestClientFallsBackToClosures11402026/10/25 19:40:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11412026/10/25 19:40:31 INFO Received push request method=POST path=/api/pushes11422026/10/25 19:40:31 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MGE2Yzc0ZTYtZGM4MS00ZDA2LWFiYWQtZjU1ZjRkZDQ2NmI5LmM1Nzg3NWM5LWM0ZjMtNDVhZC05NDI3LTUzNWQyYWMwYTE2Y3gxNzkyOTU3MjI5Njg4MjA5MDAw error="Get \"http://127.0.0.1:1/bucket21/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"11432026/10/25 19:40:31 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MGE2Yzc0ZTYtZGM4MS00ZDA2LWFiYWQtZjU1ZjRkZDQ2NmI5LmI3ZDA3OGUzLTIyN2MtNDIzNy04NDQzLTJkMjQxZWI0NTNmZngxNzkyOTU3MjI5NjQ5MDAzMDAw parts=1211442026/10/25 19:40:31 INFO Received cleanup request method=DELETE path=/api/pending_closures11452026/10/25 19:40:31 INFO Aborted multipart uploads count=1 kept=01146--- PASS: TestRedundantMultipartUpload (8.76s)1147=== CONT TestClientPushesUseOnePush11482026/10/25 19:40:31 INFO Received complete push request method=POST path=/api/pushes/1/complete11492026/10/25 19:40:31 INFO Completed push id=1 objects=6 duration=38.118166ms1150--- PASS: TestPush_CompleteCommitsEveryRoot (5.92s)1151=== CONT TestPinProtectsFromGC11522026/10/25 19:40:32 INFO Received push request method=POST path=/api/pushes1153--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (6.03s)1154=== CONT TestClientSharedPathCommittedMidPush1155--- PASS: TestReadRedirectUsesPublicS3URL (6.20s)1156=== CONT TestClientWithDependencies1157--- PASS: TestReadProxyRangeRequest (6.26s)1158=== CONT TestClientMultipleUploads1159--- PASS: TestReadRedirectKeepsNarinfoProxied (6.48s)1160=== CONT TestClientIntegration1161--- PASS: TestReadRedirectNar (6.37s)1162=== CONT TestTombstonedObjectOfferedWithoutWaiting1163--- PASS: TestReadProxyDisabled (6.22s)1164=== CONT TestGCSweepSkipsPendingObjects1165--- PASS: TestReadProxyRootRedirectsToIndexHTML (6.44s)1166=== CONT TestService_RequireScope_OIDC11672026/10/25 19:40:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57868/oidc1168--- PASS: TestReadProxyConditionalGet (6.27s)1169=== CONT TestClientCADerivations1170--- PASS: TestReadProxyHead (6.24s)1171=== CONT TestCacheStatsHandler1172--- PASS: TestReadProxyInvalidPath (6.42s)1173=== CONT TestCacheConfigHandler1174=== RUN TestCacheConfigHandler/full_config,_no_issuer1175=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1176=== RUN TestCacheConfigHandler/no_cache_url_configured1177=== PAUSE TestCacheConfigHandler/no_cache_url_configured1178=== RUN TestCacheConfigHandler/no_signing_keys1179=== PAUSE TestCacheConfigHandler/no_signing_keys1180=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1181=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1182=== CONT TestService_ReadScope_PublicByDefault1183--- PASS: TestReadProxyContentNegotiation (6.17s)1184=== CONT TestMultipartCleanup1185--- PASS: TestReadProxy404 (6.98s)1186=== CONT TestIsValidCachePath1187=== RUN TestIsValidCachePath/narinfo1188=== PAUSE TestIsValidCachePath/narinfo1189=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1190=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1191=== RUN TestIsValidCachePath/nar_zst1192=== PAUSE TestIsValidCachePath/nar_zst1193=== RUN TestIsValidCachePath/nar_xz1194=== PAUSE TestIsValidCachePath/nar_xz1195=== RUN TestIsValidCachePath/nar_bz21196=== PAUSE TestIsValidCachePath/nar_bz21197=== RUN TestIsValidCachePath/nar_uncompressed1198=== PAUSE TestIsValidCachePath/nar_uncompressed1199=== RUN TestIsValidCachePath/ls1200=== PAUSE TestIsValidCachePath/ls1201=== RUN TestIsValidCachePath/log1202=== PAUSE TestIsValidCachePath/log1203=== RUN TestIsValidCachePath/realisation1204=== PAUSE TestIsValidCachePath/realisation1205=== RUN TestIsValidCachePath/nix-cache-info1206=== PAUSE TestIsValidCachePath/nix-cache-info1207=== RUN TestIsValidCachePath/index.html1208=== PAUSE TestIsValidCachePath/index.html1209=== RUN TestIsValidCachePath/traversal_parent1210=== PAUSE TestIsValidCachePath/traversal_parent1211=== RUN TestIsValidCachePath/traversal_in_middle1212=== PAUSE TestIsValidCachePath/traversal_in_middle1213=== RUN TestIsValidCachePath/invalid_char_e1214=== PAUSE TestIsValidCachePath/invalid_char_e1215=== RUN TestIsValidCachePath/invalid_char_u1216=== PAUSE TestIsValidCachePath/invalid_char_u1217=== RUN TestIsValidCachePath/random_path1218=== PAUSE TestIsValidCachePath/random_path1219=== RUN TestIsValidCachePath/empty1220=== PAUSE TestIsValidCachePath/empty1221=== RUN TestIsValidCachePath/leading_slash1222=== PAUSE TestIsValidCachePath/leading_slash1223=== RUN TestIsValidCachePath/wrong_extension1224=== PAUSE TestIsValidCachePath/wrong_extension1225=== RUN TestIsValidCachePath/short_hash1226=== PAUSE TestIsValidCachePath/short_hash1227=== CONT TestParseSingleRange1228=== RUN TestParseSingleRange/none1229=== PAUSE TestParseSingleRange/none1230=== RUN TestParseSingleRange/unknown_unit1231=== PAUSE TestParseSingleRange/unknown_unit1232=== RUN TestParseSingleRange/multi-range_ignored1233=== PAUSE TestParseSingleRange/multi-range_ignored1234=== RUN TestParseSingleRange/malformed_no_dash1235=== PAUSE TestParseSingleRange/malformed_no_dash1236=== RUN TestParseSingleRange/malformed_both_empty1237=== PAUSE TestParseSingleRange/malformed_both_empty1238=== RUN TestParseSingleRange/malformed_end_before_start1239=== PAUSE TestParseSingleRange/malformed_end_before_start1240=== RUN TestParseSingleRange/closed1241=== PAUSE TestParseSingleRange/closed1242=== RUN TestParseSingleRange/open-ended1243=== PAUSE TestParseSingleRange/open-ended1244=== RUN TestParseSingleRange/end_clamped_to_size1245=== PAUSE TestParseSingleRange/end_clamped_to_size1246=== RUN TestParseSingleRange/suffix1247=== PAUSE TestParseSingleRange/suffix1248=== RUN TestParseSingleRange/suffix_exceeds_size1249=== PAUSE TestParseSingleRange/suffix_exceeds_size1250=== RUN TestParseSingleRange/single_byte1251=== PAUSE TestParseSingleRange/single_byte1252=== RUN TestParseSingleRange/start_past_EOF1253=== PAUSE TestParseSingleRange/start_past_EOF1254=== RUN TestParseSingleRange/start_far_past_EOF1255=== PAUSE TestParseSingleRange/start_far_past_EOF1256=== CONT TestPresentNotReportedWhileGCDeletesClosure1257=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1258=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1259=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1260=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1261=== CONT TestPresentRefreshesOnlyStaleClosures1262--- PASS: TestReadProxyNarStreaming (6.51s)1263=== CONT TestPresentReportsOnlyClosureRoots1264--- PASS: TestReadProxyNarinfoAlreadyDecompressed (6.09s)1265=== CONT TestCreatePin_ReservedPins12662026/10/25 19:40:35 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57945/oidc1267--- PASS: TestRegisterCompletedObjectNeedsPendingRow (6.07s)1268=== CONT TestOrphanedObjectsGCStressTest12692026/10/25 19:40:36 INFO Aborted multipart uploads count=0 kept=012702026/10/25 19:40:36 WARN Force mode enabled - objects will be deleted immediately without grace period12712026/10/25 19:40:36 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012722026/10/25 19:40:36 INFO Vacuumed table table=pending_closures12732026/10/25 19:40:36 INFO Vacuumed table table=pending_objects12742026/10/25 19:40:36 INFO Vacuumed table table=multipart_uploads12752026/10/25 19:40:36 INFO Vacuumed table table=closures12762026/10/25 19:40:36 INFO Vacuumed table table=objects12772026/10/25 19:40:36 INFO Aborted multipart uploads count=0 kept=012782026/10/25 19:40:36 WARN Force mode enabled - objects will be deleted immediately without grace period12792026/10/25 19:40:36 INFO Received uploads request method=POST path=/api/pending_closures12802026/10/25 19:40:36 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=012812026/10/25 19:40:36 INFO Vacuumed table table=pending_closures12822026/10/25 19:40:36 INFO Vacuumed table table=pending_objects12832026/10/25 19:40:36 INFO Vacuumed table table=multipart_uploads12842026/10/25 19:40:36 INFO Vacuumed table table=closures12852026/10/25 19:40:36 INFO Vacuumed table table=objects1286--- PASS: TestSweepSkipsRowsLockedByPush (6.33s)1287=== CONT TestOrphanedObjectsGC12882026/10/25 19:40:36 INFO Aborted multipart uploads count=0 kept=012892026/10/25 19:40:36 WARN Force mode enabled - objects will be deleted immediately without grace period12902026/10/25 19:40:36 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."12912026/10/25 19:40:36 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1292--- PASS: TestFailedS3DeleteKeepsTombstone (6.38s)1293=== CONT TestObjectStatsUpdatedOncePerCommit12942026/10/25 19:40:36 INFO Aborted multipart uploads count=0 kept=012952026/10/25 19:40:36 WARN Force mode enabled - objects will be deleted immediately without grace period12962026/10/25 19:40:37 INFO Received uploads request method=POST path=/api/pending_closures1297--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (6.36s)1298=== CONT TestObjectStatsTrigger12992026/10/25 19:40:37 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=013002026/10/25 19:40:37 INFO Vacuumed table table=pending_closures13012026/10/25 19:40:37 INFO Vacuumed table table=pending_objects13022026/10/25 19:40:37 INFO Vacuumed table table=multipart_uploads13032026/10/25 19:40:37 INFO Vacuumed table table=closures13042026/10/25 19:40:37 INFO Vacuumed table table=objects1305--- PASS: TestGCSweepDeliversEachKeyOnce (6.60s)1306=== CONT TestPendingCleanupUsesOneCutoff13072026/10/25 19:40:37 INFO Received uploads request method=POST path=/api/pending_closures13082026/10/25 19:40:37 INFO Received uploads request method=POST path=/api/pending_closures13092026/10/25 19:40:37 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13102026/10/25 19:40:37 INFO Uploading knyb7bg8yrya9kbz9vk5yzk5cxjr4xsk-shared-dep (136B)13112026/10/25 19:40:37 INFO Uploading vfzyljrkfs14mf9x44dbx50grf6wcn5s-a (256B)13122026/10/25 19:40:37 WARN Failed to register uploaded object key=vfzyljrkfs14mf9x44dbx50grf6wcn5s.ls error="server returned 404: 404 page not found\n"13132026/10/25 19:40:37 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13142026/10/25 19:40:37 WARN Failed to register uploaded object key=qhq7s5qpwc9ky8cmkla7c5bqvmac2mk2.ls error="server returned 404: 404 page not found\n"13152026/10/25 19:40:37 WARN Failed to register uploaded object key=knyb7bg8yrya9kbz9vk5yzk5cxjr4xsk.ls error="server returned 404: 404 page not found\n"13162026/10/25 19:40:37 WARN Failed to register uploaded object key=nar/1kdaxwmpiy6ycqyvihsnk96fn6vx48pyr0sw8pby5j1rm1a778js.nar.zst error="server returned 404: 404 page not found\n"13172026/10/25 19:40:37 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13182026/10/25 19:40:37 INFO Signed narinfos id=2 count=213192026/10/25 19:40:37 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13202026/10/25 19:40:37 INFO Signed narinfos id=1 count=213212026/10/25 19:40:37 INFO Uploading 4 narinfos13222026/10/25 19:40:37 WARN Failed to register uploaded object key=qhq7s5qpwc9ky8cmkla7c5bqvmac2mk2.narinfo error="server returned 404: 404 page not found\n"13232026/10/25 19:40:37 WARN Failed to register uploaded object key=knyb7bg8yrya9kbz9vk5yzk5cxjr4xsk.narinfo error="server returned 404: 404 page not found\n"13242026/10/25 19:40:37 WARN Failed to register uploaded object key=vfzyljrkfs14mf9x44dbx50grf6wcn5s.narinfo error="server returned 404: 404 page not found\n"13252026/10/25 19:40:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13262026/10/25 19:40:37 WARN Failed to register uploaded object key=knyb7bg8yrya9kbz9vk5yzk5cxjr4xsk.narinfo error="server returned 404: 404 page not found\n"13272026/10/25 19:40:37 INFO Completed upload id=1 objects=6 duration=16.373834ms13282026/10/25 19:40:37 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13292026/10/25 19:40:37 INFO Completed upload id=2 objects=6 duration=266.125µs13302026/10/25 19:40:37 INFO Upload complete. (304ms)1331=== NAME TestClientFallsBackToClosures1332 client_pushes_test.go:112: Retrieved narinfo from S3:1333 StorePath: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientFallsBackToClosures4183344996/001/store/knyb7bg8yrya9kbz9vk5yzk5cxjr4xsk-shared-dep1334 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1335 Compression: zstd1336 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821337 NarSize: 1361338 References: 1339 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1340 client_pushes_test.go:112: Retrieved narinfo from S3:1341 StorePath: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientFallsBackToClosures4183344996/001/store/vfzyljrkfs14mf9x44dbx50grf6wcn5s-a1342 URL: nar/1kdaxwmpiy6ycqyvihsnk96fn6vx48pyr0sw8pby5j1rm1a778js.nar.zst1343 Compression: zstd1344 NarHash: sha256:1kdaxwmpiy6ycqyvihsnk96fn6vx48pyr0sw8pby5j1rm1a778js1345 NarSize: 2561346 References: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientFallsBackToClosures4183344996/001/store/knyb7bg8yrya9kbz9vk5yzk5cxjr4xsk-shared-dep1347 CA: text:sha256:17ppg1sf7izkpdqaibngyqgpg8himkv0zw5wr749sz8m3x3gaxgf1348 client_pushes_test.go:112: Retrieved narinfo from S3:1349 StorePath: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientFallsBackToClosures4183344996/001/store/qhq7s5qpwc9ky8cmkla7c5bqvmac2mk2-b1350 URL: nar/1kdaxwmpiy6ycqyvihsnk96fn6vx48pyr0sw8pby5j1rm1a778js.nar.zst1351 Compression: zstd1352 NarHash: sha256:1kdaxwmpiy6ycqyvihsnk96fn6vx48pyr0sw8pby5j1rm1a778js1353 NarSize: 2561354 References: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientFallsBackToClosures4183344996/001/store/knyb7bg8yrya9kbz9vk5yzk5cxjr4xsk-shared-dep1355 CA: text:sha256:17ppg1sf7izkpdqaibngyqgpg8himkv0zw5wr749sz8m3x3gaxgf1356=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1357--- PASS: TestClientFallsBackToClosures (6.44s)13582026/10/25 19:40:38 INFO Received push request method=POST path=/api/pushes13592026/10/25 19:40:38 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13602026/10/25 19:40:38 INFO Uploading 06kvy87vs23nhmlkyd0iwmsi559xad49-shared-dep (136B)13612026/10/25 19:40:38 INFO Uploading 5fpcz3jd9q1p1lxna80gkkmb6g9g5lqs-b (256B)1362=== NAME TestPinProtectsFromGC1363 client_integration_test.go:778: Pinned store path: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestPinProtectsFromGC2178557501/001/store/81gm29r13936adk83c0q4qi1yhz1f35f-pinned-file.txt1364 client_integration_test.go:779: Unpinned store path: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestPinProtectsFromGC2178557501/001/store/czk8dkdwgy8dbnf2ky6yr1aaaq8lgm45-unpinned-file.txt13652026/10/25 19:40:38 WARN Failed to register uploaded object key=5fpcz3jd9q1p1lxna80gkkmb6g9g5lqs.ls error="server returned 404: 404 page not found\n"13662026/10/25 19:40:38 WARN Failed to register uploaded object key=06kvy87vs23nhmlkyd0iwmsi559xad49.ls error="server returned 404: 404 page not found\n"13672026/10/25 19:40:38 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13682026/10/25 19:40:38 WARN Failed to register uploaded object key=0b633w69g53vgxsj41fd32cqsqzhkwy9.ls error="server returned 404: 404 page not found\n"13692026/10/25 19:40:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13702026/10/25 19:40:38 WARN Failed to register uploaded object key=nar/1dlras2rbfmhz4cg2aq57ghifnx0irliwb5vl43qqhw4dil60w1n.nar.zst error="server returned 404: 404 page not found\n"13712026/10/25 19:40:38 INFO Received push request method=POST path=/api/pushes13722026/10/25 19:40:38 INFO Signed narinfos id=1 count=313732026/10/25 19:40:38 INFO Uploading 3 narinfos13742026/10/25 19:40:38 WARN Failed to register uploaded object key=06kvy87vs23nhmlkyd0iwmsi559xad49.narinfo error="server returned 404: 404 page not found\n"13752026/10/25 19:40:38 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13762026/10/25 19:40:38 INFO Uploading 81gm29r13936adk83c0q4qi1yhz1f35f-pinned-file.txt (128B)13772026/10/25 19:40:38 WARN Failed to register uploaded object key=5fpcz3jd9q1p1lxna80gkkmb6g9g5lqs.narinfo error="server returned 404: 404 page not found\n"13782026/10/25 19:40:38 INFO Received complete push request method=POST path=/api/pushes/1/complete13792026/10/25 19:40:38 WARN Failed to register uploaded object key=0b633w69g53vgxsj41fd32cqsqzhkwy9.narinfo error="server returned 404: 404 page not found\n"13802026/10/25 19:40:38 WARN Failed to register uploaded object key=81gm29r13936adk83c0q4qi1yhz1f35f.ls error="server returned 404: 404 page not found\n"13812026/10/25 19:40:38 INFO Completed push id=1 objects=8 duration=18.188042ms13822026/10/25 19:40:38 INFO Upload complete. (298ms)1383=== NAME TestClientPushesUseOnePush1384 client_pushes_test.go:97: Retrieved narinfo from S3:1385 StorePath: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientPushesUseOnePush941537965/001/store/06kvy87vs23nhmlkyd0iwmsi559xad49-shared-dep1386 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1387 Compression: zstd1388 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821389 NarSize: 1361390 References: 1391 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1392 client_pushes_test.go:97: Retrieved narinfo from S3:1393 StorePath: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientPushesUseOnePush941537965/001/store/0b633w69g53vgxsj41fd32cqsqzhkwy9-a13942026/10/25 19:40:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1395 URL: nar/1dlras2rbfmhz4cg2aq57ghifnx0irliwb5vl43qqhw4dil60w1n.nar.zst1396 Compression: zstd13972026/10/25 19:40:38 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"1398 NarHash: sha256:1dlras2rbfmhz4cg2aq57ghifnx0irliwb5vl43qqhw4dil60w1n1399 NarSize: 2561400 References: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientPushesUseOnePush941537965/001/store/06kvy87vs23nhmlkyd0iwmsi559xad49-shared-dep1401 CA: text:sha256:019ax4lcp8y4kr7fxdda6c63y47pr6vzkz43nm5z928335x4ksla14022026/10/25 19:40:38 INFO Signed narinfos id=1 count=114032026/10/25 19:40:38 INFO Uploading 1 narinfos1404 client_pushes_test.go:97: Retrieved narinfo from S3:1405 StorePath: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientPushesUseOnePush941537965/001/store/5fpcz3jd9q1p1lxna80gkkmb6g9g5lqs-b1406 URL: nar/1dlras2rbfmhz4cg2aq57ghifnx0irliwb5vl43qqhw4dil60w1n.nar.zst1407 Compression: zstd1408 NarHash: sha256:1dlras2rbfmhz4cg2aq57ghifnx0irliwb5vl43qqhw4dil60w1n1409 NarSize: 2561410 References: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientPushesUseOnePush941537965/001/store/06kvy87vs23nhmlkyd0iwmsi559xad49-shared-dep1411 CA: text:sha256:019ax4lcp8y4kr7fxdda6c63y47pr6vzkz43nm5z928335x4ksla14122026/10/25 19:40:38 INFO Received complete push request method=POST path=/api/pushes/1/complete14132026/10/25 19:40:38 WARN Failed to register uploaded object key=81gm29r13936adk83c0q4qi1yhz1f35f.narinfo error="server returned 404: 404 page not found\n"1414--- PASS: TestClientPushesUseOnePush (6.52s)1415=== CONT TestService_ReadAuthMiddleware14162026/10/25 19:40:38 INFO Completed push id=1 objects=3 duration=11.360458ms14172026/10/25 19:40:38 INFO Upload complete. (230ms)14182026/10/25 19:40:38 INFO Received push request method=POST path=/api/pushes14192026/10/25 19:40:38 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14202026/10/25 19:40:38 INFO Uploading czk8dkdwgy8dbnf2ky6yr1aaaq8lgm45-unpinned-file.txt (128B)1421--- PASS: TestReadProxyOutlastsServerWriteTimeout (10.44s)1422=== CONT TestService_AuthMiddleware_OIDC14232026/10/25 19:40:38 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58065/oidc14242026/10/25 19:40:38 WARN Failed to register uploaded object key=czk8dkdwgy8dbnf2ky6yr1aaaq8lgm45.ls error="server returned 404: 404 page not found\n"14252026/10/25 19:40:38 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign14262026/10/25 19:40:38 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"14272026/10/25 19:40:38 INFO Signed narinfos id=2 count=114282026/10/25 19:40:38 INFO Uploading 1 narinfos14292026/10/25 19:40:38 INFO Received complete push request method=POST path=/api/pushes/2/complete14302026/10/25 19:40:38 WARN Failed to register uploaded object key=czk8dkdwgy8dbnf2ky6yr1aaaq8lgm45.narinfo error="server returned 404: 404 page not found\n"14312026/10/25 19:40:38 INFO Completed push id=2 objects=3 duration=1.040375ms14322026/10/25 19:40:38 INFO Upload complete. (135ms)14332026/10/25 19:40:38 INFO Received push request method=POST path=/api/pushes14342026/10/25 19:40:38 INFO Starting cleanup of old closures method=DELETE path=/api/closures14352026/10/25 19:40:38 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)14362026/10/25 19:40:38 INFO Uploading 6zl7ax39xcjnhscl0rnn4kg5nrizvmcp-top (264B)14372026/10/25 19:40:38 INFO Uploading ycrnjbpjfccr0ss4p0vflcxpji23ps83-shared-dep (136B)14382026/10/25 19:40:38 INFO Garbage collection started14392026/10/25 19:40:38 INFO Aborted multipart uploads count=0 kept=014402026/10/25 19:40:38 WARN Force mode enabled - objects will be deleted immediately without grace period14412026/10/25 19:40:38 WARN Failed to register uploaded object key=nar/11qalyihzrrgm4pylkr1cc6zzq74yza0nhnqvskywl579ff9vaqn.nar.zst error="server returned 404: 404 page not found\n"14422026/10/25 19:40:38 WARN Failed to register uploaded object key=ycrnjbpjfccr0ss4p0vflcxpji23ps83.ls error="server returned 404: 404 page not found\n"14432026/10/25 19:40:38 WARN Failed to register uploaded object key=6zl7ax39xcjnhscl0rnn4kg5nrizvmcp.ls error="server returned 404: 404 page not found\n"14442026/10/25 19:40:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14452026/10/25 19:40:38 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14462026/10/25 19:40:38 INFO Signed narinfos id=1 count=214472026/10/25 19:40:38 INFO Uploading 2 narinfos14482026/10/25 19:40:38 WARN Failed to register uploaded object key=6zl7ax39xcjnhscl0rnn4kg5nrizvmcp.narinfo error="server returned 404: 404 page not found\n"14492026/10/25 19:40:38 INFO Received complete push request method=POST path=/api/pushes/1/complete14502026/10/25 19:40:38 WARN Failed to register uploaded object key=ycrnjbpjfccr0ss4p0vflcxpji23ps83.narinfo error="server returned 404: 404 page not found\n"14512026/10/25 19:40:38 INFO Completed push id=1 objects=6 duration=18.765292ms14522026/10/25 19:40:38 INFO Upload complete. (229ms)1453=== NAME TestClientSharedPathCommittedMidPush1454 client_integration_test.go:727: Retrieved narinfo from S3:1455 StorePath: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientSharedPathCommittedMidPush917290676/001/store/ycrnjbpjfccr0ss4p0vflcxpji23ps83-shared-dep1456 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1457 Compression: zstd1458 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821459 NarSize: 1361460 References: 1461 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1462 client_integration_test.go:727: Retrieved narinfo from S3:1463 StorePath: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientSharedPathCommittedMidPush917290676/001/store/6zl7ax39xcjnhscl0rnn4kg5nrizvmcp-top1464 URL: nar/11qalyihzrrgm4pylkr1cc6zzq74yza0nhnqvskywl579ff9vaqn.nar.zst1465 Compression: zstd1466 NarHash: sha256:11qalyihzrrgm4pylkr1cc6zzq74yza0nhnqvskywl579ff9vaqn1467 NarSize: 2641468 References: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientSharedPathCommittedMidPush917290676/001/store/ycrnjbpjfccr0ss4p0vflcxpji23ps83-shared-dep1469 CA: text:sha256:18yka548v4nhh1kjsynqaf0x8ijan5j0v3caydl117ni4225fnws1470--- PASS: TestClientSharedPathCommittedMidPush (6.63s)1471=== CONT TestCreatePendingClosureRejectsOversizedNAR14722026/10/25 19:40:38 INFO Received uploads request method=POST path=/api/pending_closures1473--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1474=== CONT TestServerTLSConfig1475=== RUN TestServerTLSConfig/no_client_CA1476=== PAUSE TestServerTLSConfig/no_client_CA1477=== RUN TestServerTLSConfig/missing_CA_file1478=== PAUSE TestServerTLSConfig/missing_CA_file1479=== RUN TestServerTLSConfig/not_a_PEM_file1480=== PAUSE TestServerTLSConfig/not_a_PEM_file1481=== CONT TestService_NativeMTLS1482=== NAME TestClientWithDependencies1483 client_integration_test.go:660: Built derivation: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientWithDependencies1631144122/001/store/n1cfsy9n7k2k0gxb94296wq0b7s091ca-test-script1484 client_integration_test.go:662: Found 1 dependencies (including self)14852026/10/25 19:40:38 INFO Received push request method=POST path=/api/pushes1486=== NAME TestClientMultipleUploads1487 client_integration_test.go:405: Created store path 0: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientMultipleUploads423174702/001/store/0gvivhxf4id2z6qdiq4v46gfg0qxvqsb-test-file-0.txt14882026/10/25 19:40:39 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=014892026/10/25 19:40:39 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14902026/10/25 19:40:39 INFO Uploading n1cfsy9n7k2k0gxb94296wq0b7s091ca-test-script (136B)14912026/10/25 19:40:39 INFO Vacuumed table table=pending_closures14922026/10/25 19:40:39 WARN Failed to register uploaded object key=n1cfsy9n7k2k0gxb94296wq0b7s091ca.ls error="server returned 404: 404 page not found\n"14932026/10/25 19:40:39 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"14942026/10/25 19:40:39 INFO Vacuumed table table=pending_objects14952026/10/25 19:40:39 INFO Vacuumed table table=multipart_uploads14962026/10/25 19:40:39 WARN Failed to register uploaded object key=log/k2r7y66l33kkzgy1x5kw95p7vy4cizww-test-script.drv error="server returned 404: 404 page not found\n"14972026/10/25 19:40:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14982026/10/25 19:40:39 INFO Signed narinfos id=1 count=11499 client_integration_test.go:405: Created store path 1: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientMultipleUploads423174702/001/store/8gmlgw8p2widp61j3727nayhn73bjkf3-test-file-1.txt15002026/10/25 19:40:39 INFO Uploading 1 narinfos15012026/10/25 19:40:39 INFO Vacuumed table table=closures15022026/10/25 19:40:39 INFO Vacuumed table table=objects15032026/10/25 19:40:39 INFO Received complete push request method=POST path=/api/pushes/1/complete15042026/10/25 19:40:39 WARN Failed to register uploaded object key=n1cfsy9n7k2k0gxb94296wq0b7s091ca.narinfo error="server returned 404: 404 page not found\n"1505 client_integration_test.go:405: Created store path 2: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientMultipleUploads423174702/001/store/5ixai562w385zk3pmy320bn0wfni48b5-test-file-2.txt15062026/10/25 19:40:39 INFO Completed push id=1 objects=4 duration=13.601209ms15072026/10/25 19:40:39 INFO Upload complete. (259ms)1508=== NAME TestClientWithDependencies1509 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientWithDependencies1631144122/001/store) requires matching store prefix1510=== NAME TestClientIntegration1511 client_integration_test.go:291: Created store path: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientIntegration2278475623/002/store/4krzgvyjwlmzf7n6gjq0fxpv4c4gqkfm-test-file.txt1512--- PASS: TestClientWithDependencies (6.74s)1513=== CONT TestMetricsCommit15142026/10/25 19:40:39 INFO Received push request method=POST path=/api/pushes15152026/10/25 19:40:39 INFO Received push request method=POST path=/api/pushes15162026/10/25 19:40:39 INFO Received uploads request method=POST path=/api/pending_closures15172026/10/25 19:40:39 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)15182026/10/25 19:40:39 INFO Uploading 8gmlgw8p2widp61j3727nayhn73bjkf3-test-file-1.txt (160B)15192026/10/25 19:40:39 INFO Uploading 5ixai562w385zk3pmy320bn0wfni48b5-test-file-2.txt (160B)15202026/10/25 19:40:39 INFO Uploading 0gvivhxf4id2z6qdiq4v46gfg0qxvqsb-test-file-0.txt (160B)15212026/10/25 19:40:39 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15222026/10/25 19:40:39 INFO Uploading 4krzgvyjwlmzf7n6gjq0fxpv4c4gqkfm-test-file.txt (152B)1523--- PASS: TestTombstonedObjectOfferedWithoutWaiting (5.95s)1524=== CONT TestMetricsInventory15252026/10/25 19:40:39 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"15262026/10/25 19:40:39 WARN Failed to register uploaded object key=5ixai562w385zk3pmy320bn0wfni48b5.ls error="server returned 404: 404 page not found\n"15272026/10/25 19:40:39 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"15282026/10/25 19:40:39 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"15292026/10/25 19:40:39 WARN Failed to register uploaded object key=8gmlgw8p2widp61j3727nayhn73bjkf3.ls error="server returned 404: 404 page not found\n"15302026/10/25 19:40:39 WARN Failed to register uploaded object key=0gvivhxf4id2z6qdiq4v46gfg0qxvqsb.ls error="server returned 404: 404 page not found\n"15312026/10/25 19:40:39 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"15322026/10/25 19:40:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15332026/10/25 19:40:39 INFO Signed narinfos id=1 count=315342026/10/25 19:40:39 INFO Uploading 3 narinfos15352026/10/25 19:40:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15362026/10/25 19:40:39 WARN Failed to register uploaded object key=4krzgvyjwlmzf7n6gjq0fxpv4c4gqkfm.ls error="server returned 404: 404 page not found\n"15372026/10/25 19:40:39 INFO Signed narinfos id=1 count=115382026/10/25 19:40:39 INFO Uploading 1 narinfos15392026/10/25 19:40:39 WARN Failed to register uploaded object key=0gvivhxf4id2z6qdiq4v46gfg0qxvqsb.narinfo error="server returned 404: 404 page not found\n"15402026/10/25 19:40:39 WARN Failed to register uploaded object key=8gmlgw8p2widp61j3727nayhn73bjkf3.narinfo error="server returned 404: 404 page not found\n"15412026/10/25 19:40:39 INFO Received complete push request method=POST path=/api/pushes/1/complete15422026/10/25 19:40:39 WARN Failed to register uploaded object key=4krzgvyjwlmzf7n6gjq0fxpv4c4gqkfm.narinfo error="server returned 404: 404 page not found\n"15432026/10/25 19:40:39 INFO Received complete push request method=POST path=/api/pushes/1/complete15442026/10/25 19:40:39 WARN Failed to register uploaded object key=5ixai562w385zk3pmy320bn0wfni48b5.narinfo error="server returned 404: 404 page not found\n"15452026/10/25 19:40:39 INFO Completed push id=1 objects=3 duration=5.134958ms15462026/10/25 19:40:39 INFO Upload complete. (209ms)15472026/10/25 19:40:39 INFO Completed push id=1 objects=9 duration=18.118875ms15482026/10/25 19:40:39 INFO Upload complete. (242ms)1549=== NAME TestClientMultipleUploads1550 client_integration_test.go:416: Uploaded 3 paths in 280.044167ms15512026/10/25 19:40:39 INFO All 1 paths already cached1552=== NAME TestClientIntegration1553 client_integration_test.go:317: Retrieved narinfo from S3:1554 StorePath: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientIntegration2278475623/002/store/4krzgvyjwlmzf7n6gjq0fxpv4c4gqkfm-test-file.txt1555 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1556 Compression: zstd1557 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11558 NarSize: 1521559 References: 1560 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11561--- PASS: TestClientMultipleUploads (6.72s)1562=== CONT TestNARDeduplicationMetadataUploadBug1563=== NAME TestClientIntegration1564 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1565 client_integration_test.go:318: Decompressed .ls content (64 bytes):1566 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}15672026/10/25 19:40:39 INFO Received uploads request method=POST path=/api/pending_closures15682026/10/25 19:40:39 INFO Aborted multipart uploads count=0 kept=015692026/10/25 19:40:39 WARN Force mode enabled - objects will be deleted immediately without grace period15702026/10/25 19:40:39 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=015712026/10/25 19:40:39 INFO Vacuumed table table=pending_closures15722026/10/25 19:40:39 INFO Vacuumed table table=pending_objects15732026/10/25 19:40:39 INFO Vacuumed table table=multipart_uploads15742026/10/25 19:40:39 INFO Vacuumed table table=closures15752026/10/25 19:40:39 INFO Vacuumed table table=objects15762026/10/25 19:40:39 INFO Received push request method=POST path=/api/pushes15772026/10/25 19:40:39 INFO Object in database but missing from S3 key=4krzgvyjwlmzf7n6gjq0fxpv4c4gqkfm.ls15782026/10/25 19:40:39 WARN Found objects in DB but missing from S3, will re-upload count=115792026/10/25 19:40:39 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)1580--- PASS: TestGCSweepSkipsPendingObjects (6.18s)1581=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1582=== RUN TestService_RequireScope_OIDC/builder_may_write1583=== PAUSE TestService_RequireScope_OIDC/builder_may_write1584=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1585=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1586=== RUN TestService_RequireScope_OIDC/ops_may_admin1587=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1588=== RUN TestService_RequireScope_OIDC/ops_may_not_write1589=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1590=== RUN TestService_RequireScope_OIDC/reader_may_not_write1591=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1592=== RUN TestService_RequireScope_OIDC/static_token_may_admin1593=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1594=== RUN TestService_RequireScope_OIDC/static_token_may_write1595=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1596=== RUN TestService_RequireScope_OIDC/reader_may_read1597=== PAUSE TestService_RequireScope_OIDC/reader_may_read1598=== RUN TestService_RequireScope_OIDC/writer_implies_read1599=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1600=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1601=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1602=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1603=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1604=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1605=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1606=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1607=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1608=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1609=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1610=== CONT TestService_AuthMiddleware_MTLSProxyHeader16112026/10/25 19:40:39 INFO Received complete push request method=POST path=/api/pushes/2/complete16122026/10/25 19:40:39 WARN Failed to register uploaded object key=4krzgvyjwlmzf7n6gjq0fxpv4c4gqkfm.ls error="server returned 404: 404 page not found\n"16132026/10/25 19:40:39 INFO Completed push id=2 objects=3 duration=854.625µs16142026/10/25 19:40:39 INFO Upload complete. (95ms)1615=== NAME TestClientIntegration1616 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1617 client_integration_test.go:335: Decompressed .ls content (49 bytes):1618 {"version":1,"root":{"type":"regular","size":39}}16192026/10/25 19:40:40 INFO Received push request method=POST path=/api/pushes16202026/10/25 19:40:40 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)16212026/10/25 19:40:40 INFO Received complete push request method=POST path=/api/pushes/3/complete16222026/10/25 19:40:40 WARN Failed to register uploaded object key=4krzgvyjwlmzf7n6gjq0fxpv4c4gqkfm.ls error="server returned 404: 404 page not found\n"16232026/10/25 19:40:40 INFO Completed push id=3 objects=3 duration=885.416µs16242026/10/25 19:40:40 INFO Upload complete. (74ms)1625 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1626 client_integration_test.go:352: Decompressed .ls content (49 bytes):1627 {"version":1,"root":{"type":"regular","size":39}}1628 client_integration_test.go:363: Testing garbage collection...16292026/10/25 19:40:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures16302026/10/25 19:40:40 INFO Garbage collection started16312026/10/25 19:40:40 INFO Aborted multipart uploads count=0 kept=016322026/10/25 19:40:40 WARN Force mode enabled - objects will be deleted immediately without grace period1633--- PASS: TestCacheStatsHandler (5.81s)1634=== CONT TestService_readinessHandler1635=== NAME TestClientCADerivations1636 client_ca_test.go:136: Built CA derivation: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientCADerivations2345444961/001/store/9cfmmzc6cfcbmi1bxhp0vx04vn6qlgws-ca-test1637 client_ca_test.go:139: Found 1 dependencies (including self)1638--- PASS: TestDeleteClosuresRacingPins (8.97s)1639=== CONT TestCacheConfigHandlerMaxNarSize1640--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1641=== CONT TestGenerateLandingPage1642--- PASS: TestGenerateLandingPage (0.00s)1643=== CONT TestSkippedUploadsHandler16442026/10/25 19:40:40 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001645--- PASS: TestSkippedUploadsHandler (0.01s)1646=== CONT TestPendingClosureWriteTimeout1647=== RUN TestPendingClosureWriteTimeout/empty1648=== PAUSE TestPendingClosureWriteTimeout/empty1649=== RUN TestPendingClosureWriteTimeout/400_objects1650=== PAUSE TestPendingClosureWriteTimeout/400_objects1651=== RUN TestPendingClosureWriteTimeout/670k_objects1652=== PAUSE TestPendingClosureWriteTimeout/670k_objects1653=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1654=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1655=== CONT TestProxyWriteTimeout1656=== RUN TestProxyWriteTimeout/narinfo1657=== PAUSE TestProxyWriteTimeout/narinfo1658=== RUN TestProxyWriteTimeout/1_GiB_nar1659=== PAUSE TestProxyWriteTimeout/1_GiB_nar1660=== RUN TestProxyWriteTimeout/10_GiB_nar1661=== PAUSE TestProxyWriteTimeout/10_GiB_nar1662=== RUN TestProxyWriteTimeout/unknown_size1663=== PAUSE TestProxyWriteTimeout/unknown_size1664=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle16652026/10/25 19:40:40 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=016662026/10/25 19:40:40 INFO Vacuumed table table=pending_closures16672026/10/25 19:40:40 INFO Received push request method=POST path=/api/pushes16682026/10/25 19:40:40 INFO Vacuumed table table=pending_objects1669--- PASS: TestService_ReadScope_PublicByDefault (5.84s)1670=== CONT TestGracefulShutdownDrainsInflight16712026/10/25 19:40:40 INFO Starting HTTP server address=127.0.0.1:5817716722026/10/25 19:40:40 INFO Shutdown signal received, draining in-flight requests timeout=10s16732026/10/25 19:40:40 INFO Vacuumed table table=multipart_uploads16742026/10/25 19:40:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16752026/10/25 19:40:40 INFO Uploading 9cfmmzc6cfcbmi1bxhp0vx04vn6qlgws-ca-test (144B)16762026/10/25 19:40:40 INFO Vacuumed table table=closures16772026/10/25 19:40:40 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=016782026/10/25 19:40:40 INFO Received create pin request method=POST path=/api/pins/myapp16792026/10/25 19:40:40 WARN Failed to register uploaded object key=9cfmmzc6cfcbmi1bxhp0vx04vn6qlgws.ls error="server returned 404: 404 page not found\n"16802026/10/25 19:40:40 WARN Failed to register uploaded object key=log/g83w8lfnyxg8h6vmrq7zdvwagqdv10sf-ca-test.drv error="server returned 404: 404 page not found\n"16812026/10/25 19:40:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16822026/10/25 19:40:40 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"1683--- PASS: TestGracefulShutdownDrainsInflight (0.08s)16842026/10/25 19:40:40 INFO Signed narinfos id=1 count=11685=== CONT TestService_healthCheckHandler16862026/10/25 19:40:40 INFO Vacuumed table table=objects16872026/10/25 19:40:40 INFO Uploading 1 narinfos16882026/10/25 19:40:40 INFO Created/updated pin name=myapp store_path=/private/var/tb/1/scratch/bd884a333ef9104d/build/TestPinProtectsFromGC2178557501/001/store/81gm29r13936adk83c0q4qi1yhz1f35f-pinned-file.txt narinfo_key=81gm29r13936adk83c0q4qi1yhz1f35f.narinfo16892026/10/25 19:40:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures16902026/10/25 19:40:40 INFO Garbage collection started16912026/10/25 19:40:40 INFO Received complete push request method=POST path=/api/pushes/1/complete16922026/10/25 19:40:40 WARN Failed to register uploaded object key=9cfmmzc6cfcbmi1bxhp0vx04vn6qlgws.narinfo error="server returned 404: 404 page not found\n"16932026/10/25 19:40:40 INFO Aborted multipart uploads count=0 kept=016942026/10/25 19:40:40 WARN Force mode enabled - objects will be deleted immediately without grace period16952026/10/25 19:40:40 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=016962026/10/25 19:40:40 INFO Vacuumed table table=pending_closures16972026/10/25 19:40:40 INFO Vacuumed table table=pending_objects16982026/10/25 19:40:40 INFO Completed push id=1 objects=4 duration=16.540542ms16992026/10/25 19:40:40 INFO Upload complete. (244ms)17002026/10/25 19:40:40 INFO Vacuumed table table=multipart_uploads17012026/10/25 19:40:40 INFO Vacuumed table table=closures17022026/10/25 19:40:40 INFO Vacuumed table table=objects1703=== NAME TestClientCADerivations1704 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientCADerivations2345444961/001/store/9cfmmzc6cfcbmi1bxhp0vx04vn6qlgws-ca-test1705 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1706 Compression: zstd1707 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1708 NarSize: 1441709 References: 1710 Deriver: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientCADerivations2345444961/001/store/g83w8lfnyxg8h6vmrq7zdvwagqdv10sf-ca-test.drv1711 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1712 client_ca_test.go:185: Checking for realisation files in S3...1713 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1714 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1715 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket65?endpoint=http://localhost:57380®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/1/scratch/bd884a333ef9104d/build/TestClientCADerivations2345444961/001/store'1716 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11717--- PASS: TestClientCADerivations (6.81s)1718=== CONT TestService_Rustfstest1719--- PASS: TestPresentRefreshesOnlyStaleClosures (5.29s)1720=== CONT TestParseSize1721--- PASS: TestParseSize (0.00s)1722=== CONT TestPresignedUploadRegisteredBeforeCommit17232026/10/25 19:40:41 INFO Received uploads request method=POST path=/api/pending_closures17242026/10/25 19:40:41 INFO Received cleanup request method=DELETE path=/api/pending_closures17252026/10/25 19:40:41 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket69/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""17262026/10/25 19:40:41 INFO Aborted multipart uploads count=0 kept=117272026/10/25 19:40:41 INFO Received cleanup request method=DELETE path=/api/pending_closures17282026/10/25 19:40:41 INFO Aborted multipart uploads count=1 kept=01729--- PASS: TestMultipartCleanup (5.73s)1730=== CONT TestGCEndsOnShutdown/before_the_run1731--- PASS: TestPresentReportsOnlyClosureRoots (5.51s)1732=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark17332026/10/25 19:40:41 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux17342026/10/25 19:40:41 WARN Refused reserved pin name=worker-x86_64-linux17352026/10/25 19:40:41 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux17362026/10/25 19:40:41 INFO Received create pin request method=POST path=/api/pins/my-app17372026/10/25 19:40:41 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1738--- PASS: TestCreatePin_ReservedPins (5.50s)1739=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete17402026/10/25 19:40:42 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01741=== NAME TestClientIntegration1742 client_integration_test.go:370: Objects in database after GC:1743 client_integration_test.go:370: Successfully deleted all objects with GC --force1744--- PASS: TestClientIntegration (9.15s)1745=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17462026/10/25 19:40:42 INFO Received uploads request method=POST path=/1747=== CONT TestIsValidUploadKey/narinfo1748=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1749=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17502026/10/25 19:40:42 INFO Received request for more parts method=POST path=/1751=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17522026/10/25 19:40:42 INFO Received complete multipart upload request method=POST path=/1753=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17542026/10/25 19:40:42 INFO Received uploads request method=POST path=/1755--- PASS: TestUploadHandlersRejectInvalidKeys (0.04s)1756 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1757 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1758 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1759 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1760=== CONT TestIsValidUploadKey/traversal_nar1761=== CONT TestResolveDBConnectionString/flag_wins1762=== CONT TestIsValidUploadKey/index.html1763=== CONT TestIsValidUploadKey/nix-cache-info1764=== CONT TestIsValidUploadKey/realisation_plus_in_output1765=== CONT TestIsValidUploadKey/realisation1766=== CONT TestIsValidUploadKey/build_log_equals1767=== CONT TestIsValidUploadKey/build_log_question_mark1768=== CONT TestIsValidUploadKey/build_log_plus_in_name1769=== CONT TestIsValidUploadKey/build_log_home-manager_file1770=== CONT TestIsValidUploadKey/build_log1771=== CONT TestIsValidUploadKey/listing1772=== CONT TestIsValidUploadKey/nar_plain1773=== CONT TestIsValidUploadKey/nar_xz1774=== CONT TestIsValidUploadKey/nar_zst1775=== CONT TestIsValidUploadKey/empty_key1776=== CONT TestIsValidUploadKey/unknown_type1777=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1778=== CONT TestIsValidUploadKey/traversal1779=== CONT TestIsValidUploadKey/absolute1780=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1781--- PASS: TestIsValidUploadKey (0.04s)1782 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1783 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1784 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1785 --- PASS: TestIsValidUploadKey/index.html (0.00s)1786 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1787 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1788 --- PASS: TestIsValidUploadKey/realisation (0.00s)1789 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1790 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1791 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1792 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1793 --- PASS: TestIsValidUploadKey/build_log (0.00s)1794 --- PASS: TestIsValidUploadKey/listing (0.00s)1795 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1796 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1797 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1798 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1799 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1800 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1801 --- PASS: TestIsValidUploadKey/traversal (0.00s)1802 --- PASS: TestIsValidUploadKey/absolute (0.00s)1803 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1804=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1805=== CONT TestResolveDBConnectionString/nothing_configured1806=== CONT TestResolveDBConnectionString/missing_file_is_an_error1807=== CONT TestResolveDBConnectionString/file_when_flag_empty1808=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18092026/10/25 19:40:42 INFO Received uploads request method=POST path=/1810--- PASS: TestResolveDBConnectionString (0.00s)1811 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1812 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1813 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1814 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1815 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1816--- PASS: TestObjectStatsUpdatedOncePerCommit (5.57s)1817=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18182026/10/25 19:40:42 INFO Received request for more parts method=POST path=/1819=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18202026/10/25 19:40:42 INFO Received complete multipart upload request method=POST path=/1821=== CONT TestPush_RejectsBadRequests/no_roots18222026/10/25 19:40:42 INFO Received push request method=POST path=/api/pushes1823=== CONT TestPush_RejectsBadRequests/bad_root18242026/10/25 19:40:42 INFO Received push request method=POST path=/api/pushes1825=== CONT TestPush_RejectsBadRequests/root_not_in_objects18262026/10/25 19:40:42 INFO Received push request method=POST path=/api/pushes1827=== CONT TestPush_RejectsBadRequests/no_objects18282026/10/25 19:40:42 INFO Received push request method=POST path=/api/pushes1829--- PASS: TestPush_RejectsBadRequests (5.57s)1830 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1831 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1832 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1833 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1834=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1835--- PASS: TestObjectStatsTrigger (5.22s)1836--- PASS: TestUploadHandlersRejectOversizedBody (0.06s)1837 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1838 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.03s)1839 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.30s)1840=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1841=== CONT TestClientErrorHandling/InvalidStorePath1842=== NAME TestPinProtectsFromGC1843 client_integration_test.go:887: Pin successfully protected closure from garbage collection18442026/10/25 19:40:42 INFO Received uploads request method=POST path=/api/pending_closures1845--- PASS: TestPinProtectsFromGC (10.86s)1846=== CONT TestClientErrorHandling/ServerNotAvailable18472026/10/25 19:40:42 INFO Received uploads request method=POST path=/api/pending_closures18482026/10/25 19:40:42 INFO Received cleanup request method=DELETE path=/api/pending_closures18492026/10/25 19:40:43 INFO Received uploads request method=POST path=/api/pending_closures1850--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (5.31s)1851=== CONT TestClientErrorHandling/InvalidAuthToken18522026/10/25 19:40:43 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/present18532026/10/25 19:40:43 WARN Request failed, retrying attempt=2 backoff=199.535879ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1854--- PASS: TestService_ReadAuthMiddleware (5.14s)1855=== CONT TestCacheConfigHandler/full_config,_no_issuer1856=== CONT TestCacheConfigHandler/no_signing_keys1857=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1858=== CONT TestCacheConfigHandler/no_cache_url_configured1859--- PASS: TestCacheConfigHandler (0.01s)1860 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1861 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1862 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1863 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1864=== CONT TestIsValidCachePath/narinfo1865=== CONT TestIsValidCachePath/index.html1866=== CONT TestIsValidCachePath/short_hash1867=== CONT TestIsValidCachePath/wrong_extension1868=== CONT TestIsValidCachePath/leading_slash1869=== CONT TestIsValidCachePath/empty1870=== CONT TestIsValidCachePath/random_path1871=== CONT TestIsValidCachePath/invalid_char_u1872=== CONT TestIsValidCachePath/invalid_char_e1873=== CONT TestIsValidCachePath/traversal_in_middle1874=== CONT TestIsValidCachePath/traversal_parent1875=== CONT TestIsValidCachePath/nar_uncompressed1876=== CONT TestIsValidCachePath/nix-cache-info1877=== CONT TestIsValidCachePath/realisation1878=== CONT TestIsValidCachePath/log1879=== CONT TestIsValidCachePath/ls1880=== CONT TestIsValidCachePath/nar_xz1881=== CONT TestIsValidCachePath/nar_bz21882=== CONT TestIsValidCachePath/nar_zst1883=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1884--- PASS: TestIsValidCachePath (0.01s)1885 --- PASS: TestIsValidCachePath/narinfo (0.00s)1886 --- PASS: TestIsValidCachePath/index.html (0.00s)1887 --- PASS: TestIsValidCachePath/short_hash (0.00s)1888 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1889 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1890 --- PASS: TestIsValidCachePath/empty (0.00s)1891 --- PASS: TestIsValidCachePath/random_path (0.00s)1892 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1893 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1894 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1895 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1896 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1897 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1898 --- PASS: TestIsValidCachePath/realisation (0.00s)1899 --- PASS: TestIsValidCachePath/log (0.00s)1900 --- PASS: TestIsValidCachePath/ls (0.00s)1901 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1902 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1903 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1904 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1905=== CONT TestParseSingleRange/none1906=== CONT TestParseSingleRange/open-ended1907=== CONT TestParseSingleRange/start_far_past_EOF1908=== CONT TestParseSingleRange/start_past_EOF1909=== CONT TestParseSingleRange/single_byte1910=== CONT TestParseSingleRange/suffix_exceeds_size1911=== CONT TestParseSingleRange/suffix1912=== CONT TestParseSingleRange/end_clamped_to_size1913=== CONT TestParseSingleRange/malformed_both_empty1914=== CONT TestParseSingleRange/closed1915=== CONT TestParseSingleRange/malformed_end_before_start1916=== CONT TestParseSingleRange/multi-range_ignored1917=== CONT TestParseSingleRange/malformed_no_dash1918=== CONT TestParseSingleRange/unknown_unit1919=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1920--- PASS: TestParseSingleRange (0.03s)1921 --- PASS: TestParseSingleRange/none (0.00s)1922 --- PASS: TestParseSingleRange/open-ended (0.00s)1923 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1924 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1925 --- PASS: TestParseSingleRange/single_byte (0.00s)1926 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1927 --- PASS: TestParseSingleRange/suffix (0.00s)1928 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1929 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1930 --- PASS: TestParseSingleRange/closed (0.00s)1931 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1932 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1933 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1934 --- PASS: TestParseSingleRange/unknown_unit (0.00s)19352026/10/25 19:40:43 WARN Request failed, retrying attempt=3 backoff=427.501237ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1936=== NAME TestOrphanedObjectsGC1937 orphaned_objects_gc_test.go:287: GC Test Summary:1938 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1939 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1940 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1941 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1942 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1943--- PASS: TestOrphanedObjectsGC (7.38s)1944=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh19452026/10/25 19:40:44 WARN Request failed, retrying attempt=4 backoff=782.134349ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1946=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1947=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1948=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1949=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1950=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1951=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1952=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1953=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1954=== CONT TestServerTLSConfig/no_client_CA1955=== CONT TestServerTLSConfig/not_a_PEM_file1956=== CONT TestServerTLSConfig/missing_CA_file1957--- PASS: TestServerTLSConfig (0.00s)1958 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1959 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)1960 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1961=== CONT TestService_RequireScope_OIDC/builder_may_write1962=== CONT TestService_RequireScope_OIDC/reader_may_read1963=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1964=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19652026/10/25 19:40:44 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]1966=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1967=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1968=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1969=== CONT TestService_RequireScope_OIDC/writer_implies_read1970=== CONT TestService_RequireScope_OIDC/reader_may_not_write1971=== CONT TestService_RequireScope_OIDC/static_token_may_write1972=== CONT TestService_RequireScope_OIDC/static_token_may_admin1973=== CONT TestService_RequireScope_OIDC/ops_may_admin1974=== CONT TestService_RequireScope_OIDC/ops_may_not_write1975=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1976=== CONT TestPendingClosureWriteTimeout/empty1977=== CONT TestPendingClosureWriteTimeout/670k_objects1978=== CONT TestPendingClosureWriteTimeout/400_objects1979=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1980--- PASS: TestService_RequireScope_OIDC (5.97s)1981 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1982 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1983 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1984 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1985 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1986 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1987 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1988 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1989 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1990 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1991 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1992 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1993 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1994 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)19952026/10/25 19:40:44 WARN mTLS auth: subject not in bound subjects subject="CN=reader"19962026/10/25 19:40:44 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1997--- PASS: TestService_NativeMTLS (5.62s)1998=== CONT TestProxyWriteTimeout/narinfo1999=== CONT TestProxyWriteTimeout/10_GiB_nar2000=== CONT TestProxyWriteTimeout/unknown_size2001=== CONT TestProxyWriteTimeout/1_GiB_nar2002--- PASS: TestProxyWriteTimeout (0.00s)2003 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2004 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2005 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2006 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2007=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2008=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20092026/10/25 19:40:44 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]2010=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2011=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20122026/10/25 19:40:44 WARN Authentication failed token_preview=eyJhbGciOi...ITJ6KJRiGQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2013--- PASS: TestService_AuthMiddleware_OIDC (5.63s)2014 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2015 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2016 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2017 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)20182026/10/25 19:40:44 INFO Received push request method=POST path=/api/pushes20192026/10/25 19:40:44 INFO Received complete push request method=POST path=/api/pushes/1/complete20202026/10/25 19:40:44 INFO Completed push id=1 objects=4 duration=19.933708ms20212026/10/25 19:40:44 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete20222026/10/25 19:40:44 INFO Completed upload id=2 objects=2 duration=1.862458ms2023--- PASS: TestMetricsCommit (5.65s)20242026/10/25 19:40:44 WARN Request failed, retrying attempt=5 backoff=1.681217813s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2025--- PASS: TestMetricsInventory (5.77s)2026--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (5.87s)2027=== NAME TestNARDeduplicationMetadataUploadBug2028 metadata_upload_test.go:48: First store path: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestNARDeduplicationMetadataUploadBug4115692288/001/store/vflwfh25fgwwa2nxnkjjlk9glxqzxslj-file1.txt20292026/10/25 19:40:45 INFO Received push request method=POST path=/api/pushes20302026/10/25 19:40:45 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20312026/10/25 19:40:45 INFO Uploading vflwfh25fgwwa2nxnkjjlk9glxqzxslj-file1.txt (160B)20322026/10/25 19:40:45 WARN Failed to register uploaded object key=vflwfh25fgwwa2nxnkjjlk9glxqzxslj.ls error="server returned 404: 404 page not found\n"20332026/10/25 19:40:45 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20342026/10/25 19:40:45 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"20352026/10/25 19:40:45 INFO Signed narinfos id=1 count=120362026/10/25 19:40:45 INFO Uploading 1 narinfos20372026/10/25 19:40:45 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20382026/10/25 19:40:45 WARN mTLS auth: bound subjects configured but subject DN unavailable20392026/10/25 19:40:45 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2040--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (6.18s)20412026/10/25 19:40:45 INFO Received complete push request method=POST path=/api/pushes/1/complete20422026/10/25 19:40:45 WARN Failed to register uploaded object key=vflwfh25fgwwa2nxnkjjlk9glxqzxslj.narinfo error="server returned 404: 404 page not found\n"20432026/10/25 19:40:45 INFO Completed push id=1 objects=3 duration=20.538292ms20442026/10/25 19:40:45 INFO Upload complete. (240ms)2045=== NAME TestNARDeduplicationMetadataUploadBug2046 metadata_upload_test.go:54: Retrieved narinfo from S3:2047 StorePath: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestNARDeduplicationMetadataUploadBug4115692288/001/store/vflwfh25fgwwa2nxnkjjlk9glxqzxslj-file1.txt2048 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2049 Compression: zstd2050 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2051 NarSize: 1602052 References: 2053 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2054 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2055 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2056 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}2057 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/1/scratch/bd884a333ef9104d/build/TestNARDeduplicationMetadataUploadBug4115692288/001/store/g5rpgky80643nm38d7r2ja7n0gz69gnp-file2.txt20582026/10/25 19:40:46 INFO Received push request method=POST path=/api/pushes20592026/10/25 19:40:46 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20602026/10/25 19:40:46 INFO Received uploads request method=POST path=/api/pending_closures20612026/10/25 19:40:46 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign20622026/10/25 19:40:46 WARN Failed to register uploaded object key=g5rpgky80643nm38d7r2ja7n0gz69gnp.ls error="server returned 404: 404 page not found\n"20632026/10/25 19:40:46 INFO Signed narinfos id=2 count=120642026/10/25 19:40:46 INFO Uploading 1 narinfos20652026/10/25 19:40:46 INFO Received complete push request method=POST path=/api/pushes/2/complete20662026/10/25 19:40:46 WARN Failed to register uploaded object key=g5rpgky80643nm38d7r2ja7n0gz69gnp.narinfo error="server returned 404: 404 page not found\n"20672026/10/25 19:40:46 INFO Completed push id=2 objects=3 duration=628.166µs20682026/10/25 19:40:46 INFO Upload complete. (167ms)2069 metadata_upload_test.go:76: Retrieved narinfo from S3:2070 StorePath: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestNARDeduplicationMetadataUploadBug4115692288/001/store/g5rpgky80643nm38d7r2ja7n0gz69gnp-file2.txt2071 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2072 Compression: zstd2073 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2074 NarSize: 1602075 References: 2076 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2077 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2078 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2079 {"version":1,"root":{"type":"regular","size":44}}2080--- PASS: TestNARDeduplicationMetadataUploadBug (6.91s)20812026/10/25 19:40:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20822026/10/25 19:40:46 WARN readiness check failed error="closed pool"2083--- PASS: TestService_readinessHandler (6.19s)20842026/10/25 19:40:46 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-config2085--- PASS: TestService_healthCheckHandler (6.05s)20862026/10/25 19:40:46 WARN Request failed, retrying attempt=2 backoff=189.641894ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20872026/10/25 19:40:46 WARN Request failed, retrying attempt=3 backoff=388.516029ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20882026/10/25 19:40:46 INFO Received uploads request method=POST path=/api/pending_closures20892026/10/25 19:40:47 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst20902026/10/25 19:40:47 INFO Received uploads request method=POST path=/api/pending_closures2091--- PASS: TestPresignedUploadRegisteredBeforeCommit (6.11s)2092--- PASS: TestService_Rustfstest (6.29s)20932026/10/25 19:40:47 WARN Request failed, retrying attempt=4 backoff=862.943141ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20942026/10/25 19:40:47 INFO Aborted multipart uploads count=0 kept=020952026/10/25 19:40:47 WARN Force mode enabled - objects will be deleted immediately without grace period20962026-10-25 19:40:47.773 UTC [48956] ERROR: canceling statement due to user request20972026-10-25 19:40:47.773 UTC [48956] STATEMENT: -- name: MarkStaleObjects :execrows2098 WITH RECURSIVE ct AS (2099 SELECT timezone('UTC', now()) AS now2100 ),2101 closure_reach AS (2102 -- Start with all closure keys2103 SELECT o.key, o.refs2104 FROM objects o2105 INNER JOIN closures c ON o.key = c.key2106 UNION2107 -- Recursively add all referenced objects2108 SELECT o.key, o.refs2109 FROM objects o2110 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2111 ),2112 reachable_objects AS (2113 SELECT DISTINCT key FROM closure_reach2114 ),2115 stale_objects AS (2116 SELECT o.key2117 FROM objects AS o, ct2118 WHERE2119 NOT EXISTS (2120 SELECT 12121 FROM reachable_objects ro2122 WHERE ro.key = o.key2123 )2124 AND NOT EXISTS (2125 SELECT 12126 FROM pending_objects AS po2127 WHERE po.key = o.key2128 )2129 AND o.deleted_at IS NULL -- Only mark fresh objects2130 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2131 FOR UPDATE2132 )2133 UPDATE objects2134 SET2135 deleted_at = ct.now,2136 first_deleted_at = COALESCE(first_deleted_at, ct.now)2137 FROM stale_objects, ct2138 WHERE objects.key = stale_objects.key2139 21402026/10/25 19:40:47 INFO Aborted multipart uploads count=0 kept=021412026/10/25 19:40:47 WARN Force mode enabled - objects will be deleted immediately without grace period21422026/10/25 19:40:47 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:57380/bucket93/?delete=\": context canceled"2143--- PASS: TestGCEndsOnShutdown (0.00s)2144 --- PASS: TestGCEndsOnShutdown/before_the_run (6.24s)2145 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (6.51s)2146 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (6.50s)21472026/10/25 19:40:48 INFO Received uploads request method=POST path=/api/pending_closures21482026/10/25 19:40:48 INFO Aborted multipart uploads count=0 kept=021492026/10/25 19:40:48 WARN Force mode enabled - objects will be deleted immediately without grace period21502026/10/25 19:40:48 WARN Request failed, retrying attempt=5 backoff=1.575487036s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21512026/10/25 19:40:48 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=021522026/10/25 19:40:48 INFO Vacuumed table table=pending_closures21532026/10/25 19:40:48 INFO Vacuumed table table=pending_objects21542026/10/25 19:40:48 INFO Vacuumed table table=multipart_uploads21552026/10/25 19:40:48 INFO Vacuumed table table=closures21562026/10/25 19:40:48 INFO Vacuumed table table=objects21572026/10/25 19:40:48 INFO Received uploads request method=POST path=/api/pending_closures21582026/10/25 19:40:48 INFO Aborted multipart uploads count=0 kept=021592026/10/25 19:40:48 WARN Force mode enabled - objects will be deleted immediately without grace period21602026/10/25 19:40:48 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=021612026/10/25 19:40:48 INFO Vacuumed table table=pending_closures21622026/10/25 19:40:48 INFO Vacuumed table table=pending_objects21632026/10/25 19:40:48 INFO Vacuumed table table=multipart_uploads21642026/10/25 19:40:48 INFO Vacuumed table table=closures21652026/10/25 19:40:48 INFO Vacuumed table table=objects2166--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2167 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (6.20s)2168 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (6.42s)21692026/10/25 19:40:48 INFO Aborted multipart uploads count=1 kept=021702026/10/25 19:40:49 INFO Received cleanup request method=DELETE path=/api/pending_closures21712026/10/25 19:40:49 INFO Aborted multipart uploads count=1 kept=02172--- PASS: TestPendingCleanupUsesOneCutoff (11.61s)21732026/10/25 19:40:49 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21742026/10/25 19:40:49 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21752026/10/25 19:40:49 INFO Received uploads request method=POST path=/api/pending_closures21762026/10/25 19:40:49 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"21772026/10/25 19:40:49 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-config21782026/10/25 19:40:49 WARN Request failed, retrying attempt=2 backoff=194.102002ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2179--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2180 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (6.11s)2181 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (5.88s)21822026/10/25 19:40:50 WARN Request failed, retrying attempt=3 backoff=428.853457ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2183--- PASS: TestPendingClosureWriteTimeout (0.00s)2184 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2185 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2186 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2187 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (6.27s)21882026/10/25 19:40:50 WARN Request failed, retrying attempt=4 backoff=754.712083ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21892026/10/25 19:40:50 WARN Rate limiter enabled after throttle name=s3-test rate=521902026/10/25 19:40:50 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2191=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2192 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102193 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002194--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (10.20s)2195=== NAME TestOrphanedObjectsGCStressTest2196 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2197 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion21982026/10/25 19:40:51 WARN Request failed, retrying attempt=5 backoff=1.561068055s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21992026/10/25 19:40:52 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_closures22002026/10/25 19:40:52 WARN Request failed, retrying attempt=2 backoff=212.10663ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22012026/10/25 19:40:53 WARN Request failed, retrying attempt=3 backoff=430.484645ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22022026/10/25 19:40:53 WARN Request failed, retrying attempt=4 backoff=854.595157ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22032026/10/25 19:40:54 WARN Request failed, retrying attempt=5 backoff=1.721497686s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2204--- PASS: TestClientErrorHandling (0.00s)2205 --- PASS: TestClientErrorHandling/InvalidStorePath (5.96s)2206 --- PASS: TestClientErrorHandling/InvalidAuthToken (5.92s)2207 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.63s)2208=== NAME TestOrphanedObjectsGCStressTest2209 orphaned_objects_gc_test.go:503: Stress test completed successfully:2210 orphaned_objects_gc_test.go:504: - Active objects preserved: 202211 orphaned_objects_gc_test.go:505: - Objects deleted: 2102212 orphaned_objects_gc_test.go:506: - Total GC'd: 2102213--- PASS: TestOrphanedObjectsGCStressTest (25.22s)2214PASS2215{"timestamp":"2026-10-25T19:41:01.31727Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:57755","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(8)"}2216{"timestamp":"2026-10-25T19:41:01.318631Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:58143","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(4)"}22172026-10-25 19:41:01.429 UTC [47882] LOG: received smart shutdown request22182026-10-25 19:41:01.430 UTC [47882] LOG: background worker "logical replication launcher" (PID 47893) exited with exit code 122192026-10-25 19:41:01.449 UTC [47888] LOG: shutting down22202026-10-25 19:41:01.449 UTC [47888] LOG: checkpoint starting: shutdown immediate22212026-10-25 19:41:02.718 UTC [47888] LOG: checkpoint complete: wrote 11941 buffers (72.9%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 31 recycled; write=0.569 s, sync=0.663 s, total=1.270 s; sync files=34045, longest=0.013 s, average=0.001 s; distance=502083 kB, estimate=502083 kB; lsn=0/201DDC30, redo lsn=0/201DDC3022222026-10-25 19:41:02.729 UTC [47882] LOG: database system is shut down2223Running OIDC tests...2224=== RUN TestAudienceForIssuer2225=== PAUSE TestAudienceForIssuer2226=== RUN TestGlobMatch2227=== PAUSE TestGlobMatch2228=== RUN TestValidateToken_ValidToken2229=== PAUSE TestValidateToken_ValidToken2230=== RUN TestValidateToken_WrongAudience2231=== PAUSE TestValidateToken_WrongAudience2232=== RUN TestValidateToken_Expired2233=== PAUSE TestValidateToken_Expired2234=== RUN TestValidateToken_BoundClaimsMismatch2235=== PAUSE TestValidateToken_BoundClaimsMismatch2236=== RUN TestValidateToken_BoundSubjectMismatch2237=== PAUSE TestValidateToken_BoundSubjectMismatch2238=== RUN TestValidateToken_MultipleProviders2239=== PAUSE TestValidateToken_MultipleProviders2240=== RUN TestValidateToken_NoMatchingProvider2241=== PAUSE TestValidateToken_NoMatchingProvider2242=== RUN TestValidateToken_KubernetesServiceAccount2243=== PAUSE TestValidateToken_KubernetesServiceAccount2244=== RUN TestNewValidator_KubernetesRequiresCA2245=== PAUSE TestNewValidator_KubernetesRequiresCA2246=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2247=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2248=== RUN TestPins_ReservedForMatchingRule2249=== PAUSE TestPins_ReservedForMatchingRule2250=== RUN TestPins_TopLevelShorthand2251=== PAUSE TestPins_TopLevelShorthand2252=== RUN TestPins_ConfigValidation2253=== PAUSE TestPins_ConfigValidation2254=== RUN TestScopes_LegacyProviderDefaultsToWrite2255=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2256=== RUN TestScopes_Rules2257=== PAUSE TestScopes_Rules2258=== RUN TestScopes_ConfigValidation2259=== PAUSE TestScopes_ConfigValidation2260=== CONT TestAudienceForIssuer2261--- PASS: TestAudienceForIssuer (0.00s)2262=== CONT TestPins_TopLevelShorthand2263=== CONT TestValidateToken_KubernetesServiceAccount2264=== CONT TestScopes_Rules2265=== CONT TestPins_ConfigValidation2266=== CONT TestScopes_LegacyProviderDefaultsToWrite2267=== CONT TestScopes_ConfigValidation2268=== CONT TestPins_ReservedForMatchingRule2269=== CONT TestValidateToken_MultipleProviders2270--- PASS: TestScopes_ConfigValidation (0.01s)2271=== CONT TestNewValidator_KubernetesRequiresCA2272--- PASS: TestPins_ConfigValidation (0.01s)2273=== CONT TestValidateToken_NoMatchingProvider2274=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2275=== CONT TestValidateToken_BoundSubjectMismatch2276=== CONT TestValidateToken_BoundClaimsMismatch2277=== CONT TestValidateToken_ValidToken2278=== CONT TestValidateToken_WrongAudience2279=== CONT TestGlobMatch2280=== RUN TestGlobMatch/foo_foo2281=== PAUSE TestGlobMatch/foo_foo2282=== RUN TestGlobMatch/foo_bar2283=== PAUSE TestGlobMatch/foo_bar2284=== RUN TestGlobMatch/*_2285=== PAUSE TestGlobMatch/*_2286=== RUN TestGlobMatch/*_anything2287=== PAUSE TestGlobMatch/*_anything2288=== RUN TestGlobMatch/foo*_foo2289=== PAUSE TestGlobMatch/foo*_foo2290=== RUN TestGlobMatch/foo*_foobar2291=== PAUSE TestGlobMatch/foo*_foobar2292=== RUN TestGlobMatch/foo*_bar2293=== PAUSE TestGlobMatch/foo*_bar2294=== RUN TestGlobMatch/*bar_bar2295=== PAUSE TestGlobMatch/*bar_bar2296=== RUN TestGlobMatch/*bar_foobar2297=== PAUSE TestGlobMatch/*bar_foobar2298=== RUN TestGlobMatch/*bar_foo2299=== PAUSE TestGlobMatch/*bar_foo2300=== RUN TestGlobMatch/foo*bar_foobar2301=== PAUSE TestGlobMatch/foo*bar_foobar2302=== RUN TestGlobMatch/foo*bar_foo123bar2303=== PAUSE TestGlobMatch/foo*bar_foo123bar2304=== RUN TestGlobMatch/foo*bar_foobarbaz2305=== PAUSE TestGlobMatch/foo*bar_foobarbaz2306=== RUN TestGlobMatch/*/*_foo/bar2307=== PAUSE TestGlobMatch/*/*_foo/bar2308=== RUN TestGlobMatch/*/*_foo2309=== PAUSE TestGlobMatch/*/*_foo2310=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2311=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2312=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02313=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02314=== RUN TestGlobMatch/refs/*/main_refs/heads/main2315=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2316=== RUN TestGlobMatch/fo?_foo2317=== PAUSE TestGlobMatch/fo?_foo2318=== RUN TestGlobMatch/fo?_fo2319=== PAUSE TestGlobMatch/fo?_fo2320=== RUN TestGlobMatch/fo?_fooo2321=== PAUSE TestGlobMatch/fo?_fooo2322=== RUN TestGlobMatch/?oo_foo2323=== PAUSE TestGlobMatch/?oo_foo2324=== RUN TestGlobMatch/?oo_boo2325=== PAUSE TestGlobMatch/?oo_boo2326=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2327=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2328=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2329=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2330=== CONT TestGlobMatch/foo_foo2331=== CONT TestValidateToken_Expired2332=== CONT TestGlobMatch/*/*_foo/bar2333=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2334=== CONT TestGlobMatch/*/*_foo2335=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2336=== CONT TestGlobMatch/fo?_foo2337=== CONT TestGlobMatch/*_2338=== CONT TestGlobMatch/foo*_foobar2339=== CONT TestGlobMatch/foo*_foo2340=== CONT TestGlobMatch/*_anything2341=== CONT TestGlobMatch/*bar_bar2342=== CONT TestGlobMatch/?oo_foo2343=== CONT TestGlobMatch/refs/*/main_refs/heads/main2344=== CONT TestGlobMatch/fo?_fooo2345=== CONT TestGlobMatch/foo_bar2346=== CONT TestGlobMatch/fo?_fo2347=== CONT TestGlobMatch/foo*_bar2348=== CONT TestGlobMatch/foo*bar_foo123bar2349=== CONT TestGlobMatch/foo*bar_foobarbaz2350=== CONT TestGlobMatch/*bar_foo2351=== CONT TestGlobMatch/?oo_boo2352=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2353=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02354=== CONT TestGlobMatch/foo*bar_foobar2355=== CONT TestGlobMatch/*bar_foobar2356--- PASS: TestGlobMatch (0.00s)2357 --- PASS: TestGlobMatch/foo_foo (0.00s)2358 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2359 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2360 --- PASS: TestGlobMatch/*/*_foo (0.00s)2361 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2362 --- PASS: TestGlobMatch/fo?_foo (0.00s)2363 --- PASS: TestGlobMatch/*_ (0.00s)2364 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2365 --- PASS: TestGlobMatch/foo*_foo (0.00s)2366 --- PASS: TestGlobMatch/*_anything (0.00s)2367 --- PASS: TestGlobMatch/*bar_bar (0.00s)2368 --- PASS: TestGlobMatch/?oo_foo (0.00s)2369 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2370 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2371 --- PASS: TestGlobMatch/foo_bar (0.00s)2372 --- PASS: TestGlobMatch/fo?_fo (0.00s)2373 --- PASS: TestGlobMatch/foo*_bar (0.00s)2374 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2375 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2376 --- PASS: TestGlobMatch/*bar_foo (0.00s)2377 --- PASS: TestGlobMatch/?oo_boo (0.00s)2378 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2379 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2380 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2381 --- PASS: TestGlobMatch/*bar_foobar (0.00s)23822026/10/25 19:41:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58654/oidc23832026/10/25 19:41:04 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:586562384--- PASS: TestValidateToken_ValidToken (0.05s)23852026/10/25 19:41:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58658/oidc23862026/10/25 19:41:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58660/oidc2387--- PASS: TestValidateToken_KubernetesServiceAccount (0.09s)2388--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.09s)23892026/10/25 19:41:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58662/oidc2390--- PASS: TestValidateToken_BoundClaimsMismatch (0.07s)2391--- PASS: TestValidateToken_WrongAudience (0.07s)23922026/10/25 19:41:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58666/oidc23932026/10/25 19:41:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58665/oidc2394--- PASS: TestPins_TopLevelShorthand (0.10s)2395--- PASS: TestPins_ReservedForMatchingRule (0.11s)23962026/10/25 19:41:04 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:58653/oidc2397--- PASS: TestValidateToken_NoMatchingProvider (0.11s)23982026/10/25 19:41:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58671/oidc2399--- PASS: TestValidateToken_BoundSubjectMismatch (0.11s)24002026/10/25 19:41:04 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232401--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.12s)24022026/10/25 19:41:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58675/oidc2403--- PASS: TestScopes_Rules (0.15s)24042026/10/25 19:41:04 http: TLS handshake error from 127.0.0.1:58678: remote error: tls: bad certificate2405--- PASS: TestNewValidator_KubernetesRequiresCA (0.15s)24062026/10/25 19:41:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58679/oidc2407--- PASS: TestValidateToken_Expired (0.17s)24082026/10/25 19:41:04 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:58681/oidc24092026/10/25 19:41:04 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:58682/oidc2410--- PASS: TestValidateToken_MultipleProviders (0.22s)2411PASS2412Running hook tests...2413=== RUN TestSendPathsEmpty2414=== PAUSE TestSendPathsEmpty2415=== RUN TestQueueEnqueueAndFetch2416=== PAUSE TestQueueEnqueueAndFetch2417=== RUN TestQueueDeduplication2418=== PAUSE TestQueueDeduplication2419=== RUN TestQueueRemove2420=== PAUSE TestQueueRemove2421=== RUN TestQueueFetchBatchLimit2422=== PAUSE TestQueueFetchBatchLimit2423=== RUN TestQueueRetryMovesToBack2424=== PAUSE TestQueueRetryMovesToBack2425=== RUN TestQueueFetchRemoveLifecycle2426=== PAUSE TestQueueFetchRemoveLifecycle2427=== RUN TestQueueConcurrentWriters2428=== PAUSE TestQueueConcurrentWriters2429=== RUN TestQueueRemoveLargeClosure2430=== PAUSE TestQueueRemoveLargeClosure2431=== RUN TestServerClientIntegration2432--- PASS: TestServerClientIntegration (0.00s)2433=== RUN TestServerQueueError24342026/10/25 19:41:04 ERROR Failed to queue paths error="permission denied" count=12435--- PASS: TestServerQueueError (0.00s)2436=== RUN TestGetListenerSocketActivation2437 server_test.go:145: systemd socket activation does not exist on darwin2438--- SKIP: TestGetListenerSocketActivation (0.00s)2439=== RUN TestServerStalledClientDoesNotBlockShutdown2440=== PAUSE TestServerStalledClientDoesNotBlockShutdown2441=== RUN TestServerBacksOffOnAcceptErrors2442=== PAUSE TestServerBacksOffOnAcceptErrors2443=== RUN TestDrainIsolatesPoisonPath2444=== PAUSE TestDrainIsolatesPoisonPath2445=== RUN TestRunNotBlockedByPoisonHead2446=== PAUSE TestRunNotBlockedByPoisonHead2447=== RUN TestDrainGivesUpWhenServerDown2448=== PAUSE TestDrainGivesUpWhenServerDown2449=== RUN TestFailedPathPrunedByLaterClosure2450=== PAUSE TestFailedPathPrunedByLaterClosure2451=== RUN TestWorkerUploadsAndRemoves2452=== PAUSE TestWorkerUploadsAndRemoves2453=== RUN TestWorkerSkipsGCdPaths2454=== PAUSE TestWorkerSkipsGCdPaths2455=== RUN TestWorkerPrunesClosureDeps2456=== PAUSE TestWorkerPrunesClosureDeps2457=== RUN TestDrainTimeout2458=== PAUSE TestDrainTimeout2459=== RUN TestWorkerRemoveFailureIsNotProgress2460=== PAUSE TestWorkerRemoveFailureIsNotProgress2461=== RUN TestWorkerKeepsPathItCannotStat2462=== PAUSE TestWorkerKeepsPathItCannotStat2463=== CONT TestWorkerKeepsPathItCannotStat2464=== CONT TestSendPathsEmpty2465--- PASS: TestSendPathsEmpty (0.00s)2466=== CONT TestWorkerRemoveFailureIsNotProgress2467=== CONT TestDrainTimeout2468=== CONT TestWorkerPrunesClosureDeps2469=== CONT TestWorkerSkipsGCdPaths2470=== CONT TestWorkerUploadsAndRemoves2471=== CONT TestFailedPathPrunedByLaterClosure2472=== CONT TestDrainGivesUpWhenServerDown2473=== CONT TestRunNotBlockedByPoisonHead2474=== CONT TestDrainIsolatesPoisonPath2475=== CONT TestServerBacksOffOnAcceptErrors2476=== CONT TestServerStalledClientDoesNotBlockShutdown2477=== CONT TestQueueRemoveLargeClosure2478=== CONT TestQueueConcurrentWriters24792026/10/25 19:41:04 ERROR Accept failed error="too many open files"2480=== CONT TestQueueRemove2481=== CONT TestQueueDeduplication2482=== CONT TestQueueFetchBatchLimit2483=== CONT TestQueueEnqueueAndFetch2484=== CONT TestQueueFetchRemoveLifecycle2485=== CONT TestQueueRetryMovesToBack24862026/10/25 19:41:04 ERROR Accept failed error="too many open files"2487--- PASS: TestQueueEnqueueAndFetch (0.01s)2488--- PASS: TestQueueRemove (0.01s)24892026/10/25 19:41:04 INFO Upload queue status pending=224902026/10/25 19:41:04 INFO Uploading batch count=224912026/10/25 19:41:04 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/bd884a333ef9104d/build/TestWorkerSkipsGCdPaths695265962/002/nonexistent24922026/10/25 19:41:04 INFO Uploading batch count=12493--- PASS: TestQueueDeduplication (0.01s)24942026/10/25 19:41:04 INFO Uploading batch count=224952026/10/25 19:41:04 ERROR Upload failed error="upload failed" count=224962026/10/25 19:41:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/bd884a333ef9104d/build/TestDrainGivesUpWhenServerDown2850008851/002/a24972026/10/25 19:41:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/bd884a333ef9104d/build/TestDrainGivesUpWhenServerDown2850008851/002/b24982026/10/25 19:41:04 INFO Uploading batch count=224992026/10/25 19:41:04 ERROR Upload failed error="upload failed" count=225002026/10/25 19:41:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/bd884a333ef9104d/build/TestDrainGivesUpWhenServerDown2850008851/002/c25012026/10/25 19:41:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/bd884a333ef9104d/build/TestDrainGivesUpWhenServerDown2850008851/002/d25022026/10/25 19:41:04 INFO Upload queue status pending=325032026/10/25 19:41:04 INFO Uploading batch count=125042026/10/25 19:41:04 ERROR Upload failed error="upload failed" count=125052026/10/25 19:41:04 INFO Upload queue status pending=225062026/10/25 19:41:04 INFO Uploading batch count=12507--- PASS: TestQueueFetchRemoveLifecycle (0.01s)25082026/10/25 19:41:04 INFO Uploading batch count=425092026/10/25 19:41:04 ERROR Upload failed error="upload failed" count=425102026/10/25 19:41:04 ERROR Accept failed error="too many open files"25112026/10/25 19:41:04 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/bd884a333ef9104d/build/TestWorkerRemoveFailureIsNotProgress2822247293/002/nonexistent25122026/10/25 19:41:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/bd884a333ef9104d/build/TestDrainIsolatesPoisonPath1732335532/002/bbb25132026/10/25 19:41:04 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125142026/10/25 19:41:04 INFO Uploading batch count=125152026/10/25 19:41:04 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/bd884a333ef9104d/build/TestWorkerRemoveFailureIsNotProgress2822247293/002/nonexistent2516--- PASS: TestQueueRetryMovesToBack (0.01s)25172026/10/25 19:41:04 ERROR Upload failed error="upload failed" count=125182026/10/25 19:41:04 WARN Cannot stat store path, will retry later path=/private/var/tb/1/scratch/bd884a333ef9104d/build/TestWorkerKeepsPathItCannotStat1573571115/002/locked/aaa error="stat /private/var/tb/1/scratch/bd884a333ef9104d/build/TestWorkerKeepsPathItCannotStat1573571115/002/locked/aaa: permission denied"25192026/10/25 19:41:04 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125202026/10/25 19:41:04 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/bd884a333ef9104d/build/TestWorkerRemoveFailureIsNotProgress2822247293/002/nonexistent25212026/10/25 19:41:04 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125222026/10/25 19:41:04 ERROR Drain finished with paths left in queue remaining=125232026/10/25 19:41:04 WARN Cannot stat store path, will retry later path=/private/var/tb/1/scratch/bd884a333ef9104d/build/TestWorkerKeepsPathItCannotStat1573571115/002/locked/aaa error="stat /private/var/tb/1/scratch/bd884a333ef9104d/build/TestWorkerKeepsPathItCannotStat1573571115/002/locked/aaa: permission denied"25242026/10/25 19:41:04 INFO Uploading batch count=125252026/10/25 19:41:04 INFO Uploading batch count=125262026/10/25 19:41:04 ERROR Upload failed error="upload failed" count=125272026/10/25 19:41:04 INFO Uploading batch count=225282026/10/25 19:41:04 ERROR Upload failed error="upload failed" count=225292026/10/25 19:41:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/bd884a333ef9104d/build/TestDrainGivesUpWhenServerDown2850008851/002/e25302026/10/25 19:41:04 INFO Upload queue status pending=225312026/10/25 19:41:04 WARN Cannot stat store path, will retry later path=/private/var/tb/1/scratch/bd884a333ef9104d/build/TestWorkerKeepsPathItCannotStat1573571115/002/locked/aaa error="stat /private/var/tb/1/scratch/bd884a333ef9104d/build/TestWorkerKeepsPathItCannotStat1573571115/002/locked/aaa: permission denied"25322026/10/25 19:41:04 INFO Uploading batch count=225332026/10/25 19:41:04 INFO Uploading batch count=125342026/10/25 19:41:04 INFO Uploading batch count=125352026/10/25 19:41:04 ERROR Upload failed error="upload failed" count=12536--- PASS: TestQueueFetchBatchLimit (0.02s)25372026/10/25 19:41:04 ERROR Drain finished with paths left in queue remaining=125382026/10/25 19:41:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/bd884a333ef9104d/build/TestDrainGivesUpWhenServerDown2850008851/002/f25392026/10/25 19:41:04 INFO Uploading batch count=125402026/10/25 19:41:04 ERROR Upload failed error="upload failed" count=12541--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)25422026/10/25 19:41:04 ERROR Drain finished with paths left in queue remaining=1025432026/10/25 19:41:04 ERROR Drain finished with paths left in queue remaining=12544--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)2545--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2546--- PASS: TestDrainIsolatesPoisonPath (0.02s)2547--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2548--- PASS: TestWorkerSkipsGCdPaths (0.03s)2549--- PASS: TestWorkerPrunesClosureDeps (0.03s)25502026/10/25 19:41:04 ERROR Accept failed error="too many open files"2551--- PASS: TestWorkerUploadsAndRemoves (0.04s)2552--- PASS: TestQueueRemoveLargeClosure (0.06s)25532026/10/25 19:41:04 ERROR Accept failed error="too many open files"25542026/10/25 19:41:04 ERROR Accept failed error="too many open files"2555--- PASS: TestQueueConcurrentWriters (0.16s)25562026/10/25 19:41:04 ERROR Failed to decode request error="read unix /private/var/tb/1/scratch/bd884a333ef9104d/build/hook1379733491/test.sock->: i/o timeout"25572026/10/25 19:41:04 ERROR Failed to write response error="write unix /private/var/tb/1/scratch/bd884a333ef9104d/build/hook1379733491/test.sock->: i/o timeout"2558--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)25592026/10/25 19:41:04 ERROR Upload failed error="context deadline exceeded" count=225602026/10/25 19:41:04 ERROR Drain finished with paths left in queue remaining=42561--- PASS: TestDrainTimeout (0.21s)25622026/10/25 19:41:05 ERROR Accept failed error="too many open files"25632026/10/25 19:41:05 ERROR Accept failed error="too many open files"2564--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)25652026/10/25 19:41:05 INFO Uploading batch count=125662026/10/25 19:41:05 INFO Uploading batch count=125672026/10/25 19:41:05 INFO Uploading batch count=125682026/10/25 19:41:05 ERROR Upload failed error="upload failed" count=125692026/10/25 19:41:05 INFO Uploading batch count=125702026/10/25 19:41:05 ERROR Upload failed error="upload failed" count=125712026/10/25 19:41:05 INFO Uploading batch count=125722026/10/25 19:41:05 ERROR Upload failed error="upload failed" count=125732026/10/25 19:41:05 INFO Uploading batch count=125742026/10/25 19:41:05 ERROR Upload failed error="upload failed" count=125752026/10/25 19:41:05 ERROR Drain finished with paths left in queue remaining=12576--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2577PASS2578Running signing tests...2579=== RUN TestExternalSigner2580=== PAUSE TestExternalSigner2581=== RUN TestExternalSignerWrongPublicKey2582=== PAUSE TestExternalSignerWrongPublicKey2583=== RUN TestExternalSignerErrors2584=== PAUSE TestExternalSignerErrors2585=== RUN TestExternalSignerRestartsAfterCrash2586=== PAUSE TestExternalSignerRestartsAfterCrash2587=== RUN TestExternalSignerProgramErrorKeepsProcess2588=== PAUSE TestExternalSignerProgramErrorKeepsProcess2589=== RUN TestExternalSignerClose2590=== PAUSE TestExternalSignerClose2591=== RUN TestExternalSignerRejectsInvalidPublicKey2592=== PAUSE TestExternalSignerRejectsInvalidPublicKey2593=== RUN TestExternalSignerCancellation2594=== PAUSE TestExternalSignerCancellation2595=== RUN TestGenerateFingerprint2596=== PAUSE TestGenerateFingerprint2597=== RUN TestParseSigningKey2598=== PAUSE TestParseSigningKey2599=== RUN TestSign2600=== PAUSE TestSign2601=== RUN TestSignBatch2602=== PAUSE TestSignBatch2603=== RUN TestNilKeyPublicKey2604=== PAUSE TestNilKeyPublicKey2605=== RUN TestSignErrors2606=== PAUSE TestSignErrors2607=== CONT TestExternalSigner2608=== CONT TestExternalSignerCancellation2609=== CONT TestSign2610=== CONT TestExternalSignerErrors2611=== RUN TestExternalSignerErrors/wrong_shape2612=== CONT TestGenerateFingerprint2613=== PAUSE TestExternalSignerErrors/wrong_shape2614=== CONT TestExternalSignerRejectsInvalidPublicKey2615=== RUN TestGenerateFingerprint/basic_with_references2616=== RUN TestExternalSignerErrors/invalid_signature_base642617=== CONT TestExternalSignerWrongPublicKey2618=== RUN TestExternalSignerRejectsInvalidPublicKey/#002619=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002620=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2621=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2622=== CONT TestExternalSignerRestartsAfterCrash2623=== CONT TestSignBatch2624=== CONT TestSignErrors2625=== CONT TestNilKeyPublicKey2626--- PASS: TestNilKeyPublicKey (0.00s)2627=== CONT TestParseSigningKey2628=== RUN TestParseSigningKey/valid_32-byte_key2629=== PAUSE TestParseSigningKey/valid_32-byte_key2630=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2631=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2632=== RUN TestParseSigningKey/no_colon2633=== PAUSE TestParseSigningKey/no_colon2634=== RUN TestParseSigningKey/empty_name2635=== PAUSE TestParseSigningKey/empty_name2636=== RUN TestParseSigningKey/invalid_base642637=== PAUSE TestParseSigningKey/invalid_base642638=== RUN TestParseSigningKey/wrong_length2639=== PAUSE TestParseSigningKey/wrong_length2640=== CONT TestParseSigningKey/valid_32-byte_key2641=== CONT TestExternalSignerClose2642=== CONT TestParseSigningKey/empty_name2643=== CONT TestParseSigningKey/wrong_length2644=== CONT TestParseSigningKey/invalid_base642645=== CONT TestParseSigningKey/no_colon2646=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2647=== PAUSE TestGenerateFingerprint/basic_with_references2648=== RUN TestGenerateFingerprint/no_references2649=== PAUSE TestExternalSignerErrors/invalid_signature_base642650=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2651=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2652=== PAUSE TestGenerateFingerprint/no_references2653=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2654=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2655=== RUN TestExternalSignerErrors/program_error2656=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2657=== PAUSE TestExternalSignerErrors/program_error2658=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2659=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2660=== RUN TestExternalSignerErrors/exit_on_request2661=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2662=== PAUSE TestExternalSignerErrors/exit_on_request2663=== RUN TestExternalSignerErrors/wrong_id2664=== PAUSE TestExternalSignerErrors/wrong_id2665=== RUN TestExternalSignerErrors/too_few_signatures2666=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2667=== PAUSE TestExternalSignerErrors/too_few_signatures2668=== RUN TestGenerateFingerprint/invalid_nar_hash_length2669=== CONT TestExternalSignerProgramErrorKeepsProcess2670=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2671=== RUN TestGenerateFingerprint/invalid_store_path_prefix2672=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2673=== RUN TestGenerateFingerprint/invalid_reference_prefix2674=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2675=== CONT TestGenerateFingerprint/basic_with_references2676=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2677=== CONT TestExternalSignerRejectsInvalidPublicKey/#002678=== CONT TestGenerateFingerprint/invalid_reference_prefix2679=== CONT TestGenerateFingerprint/invalid_store_path_prefix2680=== CONT TestGenerateFingerprint/invalid_nar_hash_length2681=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2682=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2683=== CONT TestGenerateFingerprint/no_references2684--- PASS: TestGenerateFingerprint (0.00s)2685 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2686 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2687 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2688 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2689 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2690 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2691 --- PASS: TestGenerateFingerprint/no_references (0.00s)2692=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2693=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2694=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2695=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2696--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2697 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2698 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2699 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2700 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2701 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2702=== RUN TestExternalSignerErrors/wrong_signature_name2703=== PAUSE TestExternalSignerErrors/wrong_signature_name2704=== RUN TestExternalSignerErrors/wrong_signature_length2705=== PAUSE TestExternalSignerErrors/wrong_signature_length2706=== RUN TestExternalSignerErrors/exit_at_startup2707=== PAUSE TestExternalSignerErrors/exit_at_startup2708=== RUN TestExternalSignerErrors/invalid_JSON2709=== PAUSE TestExternalSignerErrors/invalid_JSON2710=== RUN TestExternalSignerErrors/null2711=== PAUSE TestExternalSignerErrors/null2712=== RUN TestExternalSignerErrors/missing_signatures2713=== PAUSE TestExternalSignerErrors/missing_signatures2714=== RUN TestExternalSignerErrors/unrequested_key2715=== PAUSE TestExternalSignerErrors/unrequested_key2716=== RUN TestExternalSignerErrors/null_signatures2717=== PAUSE TestExternalSignerErrors/null_signatures2718=== RUN TestExternalSignerErrors/wrong_signatures_shape2719=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2720=== RUN TestExternalSignerErrors/missing_signature_name2721=== PAUSE TestExternalSignerErrors/missing_signature_name2722=== CONT TestExternalSignerErrors/wrong_shape2723=== CONT TestExternalSignerErrors/wrong_signature_length2724=== CONT TestExternalSignerErrors/exit_at_startup2725=== CONT TestExternalSignerErrors/wrong_signature_name2726=== CONT TestExternalSignerErrors/wrong_id2727=== CONT TestExternalSignerErrors/invalid_signature_base642728=== CONT TestExternalSignerErrors/missing_signature_name2729=== CONT TestExternalSignerErrors/too_few_signatures2730=== CONT TestExternalSignerErrors/unrequested_key2731--- PASS: TestSign (0.00s)2732=== CONT TestExternalSignerErrors/program_error2733=== CONT TestExternalSignerErrors/wrong_signatures_shape2734=== CONT TestExternalSignerErrors/null2735=== CONT TestExternalSignerErrors/null_signatures2736=== CONT TestExternalSignerErrors/exit_on_request2737--- PASS: TestSignBatch (0.01s)2738=== RUN TestSignErrors/nil_key2739=== PAUSE TestSignErrors/nil_key2740=== RUN TestSignErrors/nil_narinfo2741=== PAUSE TestSignErrors/nil_narinfo2742=== RUN TestSignErrors/invalid_narinfo2743=== PAUSE TestSignErrors/invalid_narinfo2744=== RUN TestSignErrors/canceled2745=== PAUSE TestSignErrors/canceled2746=== CONT TestSignErrors/nil_key2747=== CONT TestExternalSignerErrors/missing_signatures2748--- PASS: TestParseSigningKey (0.00s)2749 --- PASS: TestParseSigningKey/empty_name (0.00s)2750 --- PASS: TestParseSigningKey/wrong_length (0.00s)2751 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2752 --- PASS: TestParseSigningKey/no_colon (0.00s)2753 --- PASS: TestParseSigningKey/valid_32-byte_key (0.01s)2754 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2755=== CONT TestExternalSignerErrors/invalid_JSON2756=== CONT TestSignErrors/canceled2757=== CONT TestSignErrors/invalid_narinfo2758=== CONT TestSignErrors/nil_narinfo2759--- PASS: TestSignErrors (0.01s)2760 --- PASS: TestSignErrors/nil_key (0.00s)2761 --- PASS: TestSignErrors/canceled (0.00s)2762 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2763 --- PASS: TestSignErrors/nil_narinfo (0.00s)2764--- PASS: TestExternalSignerCancellation (0.24s)2765--- PASS: TestExternalSignerRestartsAfterCrash (0.43s)2766/private/var/tb/1/scratch/bd884a333ef9104d/build/TestExternalSignerRestartsAfterCrash346883093/001/sign program: line 7: /private/var/tb/1/scratch/bd884a333ef9104d/build/TestExternalSignerRestartsAfterCrash346883093/001/sign program.starts: No such file or directory2767--- PASS: TestExternalSigner (0.62s)2768--- PASS: TestExternalSignerWrongPublicKey (0.79s)2769--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.98s)2770--- PASS: TestExternalSignerClose (1.57s)2771--- PASS: TestExternalSignerErrors (0.00s)2772 --- PASS: TestExternalSignerErrors/missing_signature_name (1.16s)2773 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (1.35s)2774 --- PASS: TestExternalSignerErrors/unrequested_key (1.77s)2775 --- PASS: TestExternalSignerErrors/exit_on_request (1.96s)2776 --- PASS: TestExternalSignerErrors/wrong_signature_length (2.15s)2777 --- PASS: TestExternalSignerErrors/null (2.33s)2778 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (2.53s)2779 --- PASS: TestExternalSignerErrors/program_error (2.72s)2780 --- PASS: TestExternalSignerErrors/too_few_signatures (2.91s)2781 --- PASS: TestExternalSignerErrors/wrong_shape (3.11s)2782 --- PASS: TestExternalSignerErrors/missing_signatures (3.30s)2783 --- PASS: TestExternalSignerErrors/wrong_signature_name (3.49s)2784 --- PASS: TestExternalSignerErrors/exit_at_startup (3.68s)2785 --- PASS: TestExternalSignerErrors/invalid_JSON (3.88s)2786 --- PASS: TestExternalSignerErrors/null_signatures (4.07s)2787 --- PASS: TestExternalSignerErrors/wrong_id (4.26s)2788PASS2789Running OpenBao signer tests...2790=== RUN TestSign2791=== PAUSE TestSign2792=== RUN TestSignErrors2793=== PAUSE TestSignErrors2794=== RUN TestServe2795=== PAUSE TestServe2796=== RUN TestServeRejectsGarbage2797=== PAUSE TestServeRejectsGarbage2798=== CONT TestSign2799=== CONT TestServe2800=== CONT TestServeRejectsGarbage2801--- PASS: TestServeRejectsGarbage (0.00s)2802=== CONT TestSignErrors2803=== RUN TestSignErrors/invalid_json2804=== PAUSE TestSignErrors/invalid_json2805=== RUN TestSignErrors/no_prefix2806=== PAUSE TestSignErrors/no_prefix2807=== RUN TestSignErrors/invalid_base642808=== PAUSE TestSignErrors/invalid_base642809=== RUN TestSignErrors/http_error2810=== PAUSE TestSignErrors/http_error2811=== CONT TestSignErrors/invalid_json2812=== CONT TestSignErrors/invalid_base642813=== CONT TestSignErrors/http_error2814=== CONT TestSignErrors/no_prefix2815--- PASS: TestServe (0.00s)2816--- PASS: TestSign (0.00s)2817--- PASS: TestSignErrors (0.00s)2818 --- PASS: TestSignErrors/http_error (0.00s)2819 --- PASS: TestSignErrors/invalid_json (0.00s)2820 --- PASS: TestSignErrors/invalid_base64 (0.00s)2821 --- PASS: TestSignErrors/no_prefix (0.00s)2822PASS