niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #381
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestRegisterUploadedObjectReusesConnections5=== PAUSE TestRegisterUploadedObjectReusesConnections6=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica7=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica8=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun9=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun10=== RUN TestCaseHackSuffix11=== PAUSE TestCaseHackSuffix12=== RUN TestFilterOversizedClosures13=== PAUSE TestFilterOversizedClosures14=== RUN TestUploadMultipart_PartsInParallel15=== PAUSE TestUploadMultipart_PartsInParallel16=== RUN TestPartSizeForNAR17=== PAUSE TestPartSizeForNAR18=== RUN TestUploadMultipart_SupersededByPeer19=== PAUSE TestUploadMultipart_SupersededByPeer20=== RUN TestDumpPathCaseHackMatchesNix21--- PASS: TestDumpPathCaseHackMatchesNix (0.12s)22=== RUN TestDumpPathCaseHackCollision23--- PASS: TestDumpPathCaseHackCollision (0.03s)24=== RUN TestDumpPathMatchesNix25=== PAUSE TestDumpPathMatchesNix26=== RUN TestDumpPathSingleFile27=== PAUSE TestDumpPathSingleFile28=== RUN TestDumpPathWriterError29=== PAUSE TestDumpPathWriterError30=== RUN TestEncodeNixBase3231=== PAUSE TestEncodeNixBase3232=== RUN TestEncodeNixBase32WithRealHash33=== PAUSE TestEncodeNixBase32WithRealHash34=== RUN TestConvertHashToNix3235=== PAUSE TestConvertHashToNix3236=== RUN TestGetStorePathHash37=== PAUSE TestGetStorePathHash38=== RUN TestPathInfoHashCompatibility39=== PAUSE TestPathInfoHashCompatibility40=== RUN TestParsePathInfoJSON41=== PAUSE TestParsePathInfoJSON42=== RUN TestParsePathInfoJSONMultiplePaths43=== PAUSE TestParsePathInfoJSONMultiplePaths44=== RUN TestPathInfoCACompatibility45=== PAUSE TestPathInfoCACompatibility46=== RUN TestRateLimiterFeedback47=== PAUSE TestRateLimiterFeedback48=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess49=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess50=== RUN TestResolveStorePath51=== PAUSE TestResolveStorePath52=== RUN TestDoWithRetry_BodyReplayedViaGetBody53=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody54=== RUN TestShellSplit55=== PAUSE TestShellSplit56=== RUN TestShellSplitErrors57=== PAUSE TestShellSplitErrors58=== RUN TestStreamPushReportsEveryPath59=== PAUSE TestStreamPushReportsEveryPath60=== RUN TestStreamPushBatchesUnderLoad61=== PAUSE TestStreamPushBatchesUnderLoad62=== RUN TestStreamPushIsolatesFailures63=== PAUSE TestStreamPushIsolatesFailures64=== RUN TestStreamPushGivesUpOnDeadServer65=== PAUSE TestStreamPushGivesUpOnDeadServer66=== RUN TestStreamPushRequestLine67=== PAUSE TestStreamPushRequestLine68=== RUN TestStreamPushReportsSignatures69=== PAUSE TestStreamPushReportsSignatures70=== RUN TestClientSignaturesByStorePath71=== PAUSE TestClientSignaturesByStorePath72=== RUN TestSetClientTLS73=== PAUSE TestSetClientTLS74=== RUN TestSetClientTLSDoesNotMutateDefaultTransport75=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport76=== RUN TestSetClientTLSErrors77=== PAUSE TestSetClientTLSErrors78=== RUN TestStaticToken79=== PAUSE TestStaticToken80=== RUN TestFileTokenReadsAndCaches81=== PAUSE TestFileTokenReadsAndCaches82=== RUN TestFileTokenMissing83=== PAUSE TestFileTokenMissing84=== RUN TestFileTokenEmpty85=== PAUSE TestFileTokenEmpty86=== RUN TestScriptTokenNoExpiryRerunsEveryCall87=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall88=== RUN TestScriptTokenCachesUntilRefresh89=== PAUSE TestScriptTokenCachesUntilRefresh90=== RUN TestScriptTokenEmptyToken91=== PAUSE TestScriptTokenEmptyToken92=== RUN TestScriptTokenBadJSON93=== PAUSE TestScriptTokenBadJSON94=== RUN TestScriptTokenScriptFails95=== PAUSE TestScriptTokenScriptFails96=== RUN TestScriptTokenEmptyCommand97=== PAUSE TestScriptTokenEmptyCommand98=== CONT TestDoServerRequestAttachesToken99=== CONT TestDoWithRetry_BodyReplayedViaGetBody100=== CONT TestSetClientTLSErrors101=== CONT TestSetClientTLSDoesNotMutateDefaultTransport102=== CONT TestEncodeNixBase32103=== RUN TestEncodeNixBase32/test_string_hash104=== PAUSE TestEncodeNixBase32/test_string_hash105=== RUN TestEncodeNixBase32/empty_input106=== PAUSE TestEncodeNixBase32/empty_input107=== CONT TestEncodeNixBase32/test_string_hash108=== CONT TestResolveStorePath109=== CONT TestStreamPushGivesUpOnDeadServer110=== CONT TestSetClientTLS111=== CONT TestParsePathInfoJSON112=== RUN TestParsePathInfoJSON/Nix_format113=== PAUSE TestParsePathInfoJSON/Nix_format114=== RUN TestParsePathInfoJSON/Lix_format115=== PAUSE TestParsePathInfoJSON/Lix_format116=== RUN TestParsePathInfoJSON/empty_input117=== PAUSE TestParsePathInfoJSON/empty_input118=== RUN TestParsePathInfoJSON/whitespace_only119=== PAUSE TestParsePathInfoJSON/whitespace_only120=== RUN TestParsePathInfoJSON/invalid_JSON121=== PAUSE TestParsePathInfoJSON/invalid_JSON122=== CONT TestParsePathInfoJSON/Nix_format123=== CONT TestStreamPushReportsEveryPath124=== CONT TestStreamPushIsolatesFailures125=== CONT TestStreamPushBatchesUnderLoad1262026/10/06 21:14:11 ERROR Upload failed error="connection refused" count=201272026/10/06 21:14:11 ERROR Server seems unavailable, giving up on batch untried=171282026/10/06 21:14:11 ERROR Upload failed error="bad path" count=3129--- PASS: TestStreamPushIsolatesFailures (0.00s)130=== CONT TestDumpPathWriterError131--- PASS: TestStreamPushReportsEveryPath (0.00s)132=== CONT TestDumpPathSingleFile133--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)134=== CONT TestDumpPathMatchesNix1352026/10/06 21:14:11 WARN Rate limiter enabled after throttle name=server-test rate=51362026/10/06 21:14:11 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:49270137--- PASS: TestDoServerRequestAttachesToken (0.00s)138=== CONT TestUploadMultipart_SupersededByPeer139=== RUN TestUploadMultipart_SupersededByPeer/exists140=== PAUSE TestUploadMultipart_SupersededByPeer/exists141=== RUN TestUploadMultipart_SupersededByPeer/missing1422026/10/06 21:14:11 WARN Rate limiter backed off name=server-test rate=5143=== PAUSE TestUploadMultipart_SupersededByPeer/missing1442026/10/06 21:14:11 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:49270145=== CONT TestPartSizeForNAR146=== RUN TestPartSizeForNAR/zero_stays_at_minimum147=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum148=== RUN TestPartSizeForNAR/small_stays_at_minimum149=== PAUSE TestPartSizeForNAR/small_stays_at_minimum150=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum151=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum152=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts153=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts154=== RUN TestPartSizeForNAR/1_TiB155=== PAUSE TestPartSizeForNAR/1_TiB156=== RUN TestPartSizeForNAR/5_TiB_S3_max_object157=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object158=== RUN TestPartSizeForNAR/capped_at_5_GiB159=== PAUSE TestPartSizeForNAR/capped_at_5_GiB160=== CONT TestUploadMultipart_PartsInParallel161--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)162=== CONT TestFilterOversizedClosures163=== RUN TestFilterOversizedClosures/no_limit_keeps_everything164=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything165=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped166=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped167=== RUN TestFilterOversizedClosures/all_closures_skipped168=== PAUSE TestFilterOversizedClosures/all_closures_skipped169=== CONT TestCaseHackSuffix170--- PASS: TestResolveStorePath (0.01s)171=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun1722026/10/06 21:14:11 INFO Garbage collection started173--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)174=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica175--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)176=== CONT TestRegisterUploadedObjectReusesConnections1772026/10/06 21:14:11 INFO Garbage collection started1782026/10/06 21:14:11 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=01792026/10/06 21:14:11 WARN Garbage collection finished on another replica. Its statistics are not available here180--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)181=== CONT TestScriptTokenCachesUntilRefresh182=== RUN TestSetClientTLS/rejects_connection_without_client_cert183=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert184=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA185=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA186=== RUN TestSetClientTLS/preserves_debug_logging_transport187=== PAUSE TestSetClientTLS/preserves_debug_logging_transport188=== CONT TestScriptTokenEmptyCommand189--- PASS: TestScriptTokenEmptyCommand (0.00s)190=== CONT TestScriptTokenScriptFails191=== RUN TestSetClientTLSErrors/missing_cert_file192=== PAUSE TestSetClientTLSErrors/missing_cert_file193--- PASS: TestScriptTokenScriptFails (0.01s)194=== CONT TestScriptTokenBadJSON195=== RUN TestSetClientTLSErrors/missing_key_file196=== PAUSE TestSetClientTLSErrors/missing_key_file197=== RUN TestSetClientTLSErrors/missing_ca_file198=== PAUSE TestSetClientTLSErrors/missing_ca_file199=== RUN TestSetClientTLSErrors/invalid_ca_file200=== PAUSE TestSetClientTLSErrors/invalid_ca_file201=== CONT TestScriptTokenEmptyToken202--- PASS: TestRegisterUploadedObjectReusesConnections (0.04s)203=== CONT TestFileTokenMissing204--- PASS: TestScriptTokenBadJSON (0.03s)205=== CONT TestScriptTokenNoExpiryRerunsEveryCall206--- PASS: TestFileTokenMissing (0.02s)207=== CONT TestFileTokenEmpty208--- PASS: TestScriptTokenEmptyToken (0.03s)209=== CONT TestShellSplitErrors210--- PASS: TestShellSplitErrors (0.00s)211=== CONT TestShellSplit212--- PASS: TestShellSplit (0.00s)213=== CONT TestParsePathInfoJSONMultiplePaths214=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths215=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths216=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths217=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths218=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess2192026/10/06 21:14:11 WARN Rate limiter enabled after throttle name=server-test rate=5220--- PASS: TestFileTokenEmpty (0.01s)221=== CONT TestRateLimiterFeedback222=== RUN TestRateLimiterFeedback/429_enables_limiter223=== PAUSE TestRateLimiterFeedback/429_enables_limiter224=== RUN TestRateLimiterFeedback/503_enables_limiter225=== PAUSE TestRateLimiterFeedback/503_enables_limiter226=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter227=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter228=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter229=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter230=== CONT TestPathInfoCACompatibility231=== RUN TestPathInfoCACompatibility/null_ca_field232=== PAUSE TestPathInfoCACompatibility/null_ca_field233=== RUN TestPathInfoCACompatibility/old_string_format_-_text234=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text235=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive236=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive237=== RUN TestPathInfoCACompatibility/new_structured_format_-_text238=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text239=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method240=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method241=== CONT TestParsePathInfoJSON/invalid_JSON242=== CONT TestParsePathInfoJSON/whitespace_only243=== CONT TestParsePathInfoJSON/empty_input244=== CONT TestParsePathInfoJSON/Lix_format245--- PASS: TestParsePathInfoJSON (0.00s)246 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)247 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)248 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)249 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)250 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)251=== CONT TestConvertHashToNix32252=== RUN TestConvertHashToNix32/SRI_format_to_Nix32253=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32254=== RUN TestConvertHashToNix32/already_Nix32_format255=== PAUSE TestConvertHashToNix32/already_Nix32_format256=== RUN TestConvertHashToNix32/invalid_format257=== PAUSE TestConvertHashToNix32/invalid_format258=== CONT TestPathInfoHashCompatibility259=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)260=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)261=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon262=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon263=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI264=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI265=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512266=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512267=== CONT TestGetStorePathHash268=== RUN TestGetStorePathHash/valid_store_path269=== PAUSE TestGetStorePathHash/valid_store_path270=== RUN TestGetStorePathHash/basename_without_hyphen_should_error271=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error272=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error273=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error274=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error275=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error276=== CONT TestFileTokenReadsAndCaches277--- PASS: TestStreamPushBatchesUnderLoad (0.10s)278=== CONT TestStaticToken279--- PASS: TestStaticToken (0.00s)280=== CONT TestEncodeNixBase32WithRealHash281--- PASS: TestEncodeNixBase32WithRealHash (0.00s)282=== CONT TestStreamPushReportsSignatures2832026/10/06 21:14:12 ERROR Upload failed error=boom count=1284--- PASS: TestStreamPushReportsSignatures (0.00s)285=== CONT TestClientSignaturesByStorePath286--- PASS: TestClientSignaturesByStorePath (0.00s)287=== CONT TestEncodeNixBase32/empty_input288--- PASS: TestEncodeNixBase32 (0.00s)289 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)290 --- PASS: TestEncodeNixBase32/empty_input (0.00s)291=== CONT TestStreamPushRequestLine2922026/10/06 21:14:12 ERROR Upload failed error=boom count=1293--- PASS: TestScriptTokenCachesUntilRefresh (0.08s)294=== CONT TestUploadMultipart_SupersededByPeer/exists295--- PASS: TestCaseHackSuffix (0.10s)296=== CONT TestUploadMultipart_SupersededByPeer/missing297--- PASS: TestDumpPathSingleFile (0.10s)298=== CONT TestPartSizeForNAR/zero_stays_at_minimum299=== CONT TestPartSizeForNAR/1_TiB300=== CONT TestPartSizeForNAR/capped_at_5_GiB301=== CONT TestPartSizeForNAR/5_TiB_S3_max_object302=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum303=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts304=== CONT TestPartSizeForNAR/small_stays_at_minimum305--- PASS: TestPartSizeForNAR (0.00s)306 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)307 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)308 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)309 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)310 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)311 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)312 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)313=== CONT TestFilterOversizedClosures/no_limit_keeps_everything314=== CONT TestFilterOversizedClosures/all_closures_skipped3152026/10/06 21:14:12 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=50316=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3172026/10/06 21:14:12 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=2000318--- PASS: TestFilterOversizedClosures (0.00s)319 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)320 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)321 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)322=== CONT TestSetClientTLS/rejects_connection_without_client_cert323--- PASS: TestFileTokenReadsAndCaches (0.02s)324=== CONT TestSetClientTLS/preserves_debug_logging_transport325=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA326=== CONT TestSetClientTLSErrors/missing_cert_file327--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)328 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)329 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)330=== CONT TestSetClientTLSErrors/missing_ca_file331=== CONT TestSetClientTLSErrors/invalid_ca_file332=== CONT TestSetClientTLSErrors/missing_key_file333=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths334=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths335--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)336 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)337 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)338=== CONT TestRateLimiterFeedback/429_enables_limiter3392026/10/06 21:14:12 WARN Rate limiter enabled after throttle name=server-test rate=53402026/10/06 21:14:12 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:493583412026/10/06 21:14:12 WARN Rate limiter backed off name=server-test rate=5342=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter343=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter344=== CONT TestRateLimiterFeedback/503_enables_limiter345=== CONT TestPathInfoCACompatibility/null_ca_field346=== CONT TestPathInfoCACompatibility/new_structured_format_-_text3472026/10/06 21:14:12 WARN Rate limiter enabled after throttle name=server-test rate=53482026/10/06 21:14:12 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:49364349=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method350=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive351=== CONT TestPathInfoCACompatibility/old_string_format_-_text352=== CONT TestConvertHashToNix32/SRI_format_to_Nix32353--- PASS: TestPathInfoCACompatibility (0.00s)354 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)355 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)356 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)357 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)358 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)359=== CONT TestConvertHashToNix32/already_Nix32_format360=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)3612026/10/06 21:14:12 WARN Rate limiter backed off name=server-test rate=5362=== CONT TestConvertHashToNix32/invalid_format363--- PASS: TestConvertHashToNix32 (0.00s)364 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)365 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)366 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)367=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI368=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon369=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512370=== CONT TestGetStorePathHash/valid_store_path371=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error372--- PASS: TestRateLimiterFeedback (0.00s)373 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)374 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)375 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)376 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)377=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error378=== CONT TestGetStorePathHash/basename_without_hyphen_should_error379--- PASS: TestPathInfoHashCompatibility (0.00s)380 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)381 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)382 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)383 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)384--- PASS: TestGetStorePathHash (0.00s)385 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)386 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)387 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)388 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)389--- PASS: TestStreamPushRequestLine (0.01s)3902026/10/06 21:14:12 http: TLS handshake error from 127.0.0.1:49355: remote error: tls: bad certificate391--- PASS: TestSetClientTLSErrors (0.05s)392 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)393 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)394 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)395 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)396--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.07s)397--- PASS: TestSetClientTLS (0.03s)398 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)399 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)400 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)401--- PASS: TestUploadMultipart_PartsInParallel (0.62s)402--- PASS: TestDumpPathMatchesNix (0.77s)403--- PASS: TestDumpPathWriterError (0.77s)404--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)405PASS406Running server tests...407The files belonging to this database system will be owned by user "_nixbld16".408This user must also own the server process.409410The database cluster will be initialized with locale "C".411The default database encoding has accordingly been set to "SQL_ASCII".412The default text search configuration will be set to "english".413414Data page checksums are enabled.415416creating directory /nix/var/nix/builds/nix-28191-160554113/postgres4282453824/data ... ok417creating subdirectories ... ok418selecting dynamic shared memory implementation ... posix419selecting default "max_connections" ... 100420selecting default "shared_buffers" ... 128MB421selecting default time zone ... UTC422creating configuration files ... ok423running bootstrap script ... ok424performing post-bootstrap initialization ... ok425syncing data to disk ... ok426427initdb: warning: enabling "trust" authentication for local connections428initdb: 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.429430Success. You can now start the database server using:431432 pg_ctl -D /nix/var/nix/builds/nix-28191-160554113/postgres4282453824/data -l logfile start433434/nix/var/nix/builds/nix-28191-160554113/postgres4282453824:5432 - no response4352026-10-06 21:14:22.255 UTC [28836] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4362026-10-06 21:14:22.264 UTC [28836] LOG: listening on Unix socket "/nix/var/nix/builds/nix-28191-160554113/postgres4282453824/.s.PGSQL.5432"4372026-10-06 21:14:22.295 UTC [28843] LOG: database system was shut down at 2026-10-06 21:14:22 UTC4382026-10-06 21:14:22.298 UTC [28836] LOG: database system is ready to accept connections439/nix/var/nix/builds/nix-28191-160554113/postgres4282453824:5432 - accepting connections440{"timestamp":"2026-10-06T21:14:22.614137Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"08c43986-966a-4847-9586-ea8843a832a5","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":501,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}441{"timestamp":"2026-10-06T21:14:22.717231Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"6402e7c0-8262-4cb1-ba98-d0ec5fd17049","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":501,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}442{"timestamp":"2026-10-06T21:14:22.820048Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"67dcaab2-40c2-412a-9c40-8846a6bb2d12","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":501,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}443{"timestamp":"2026-10-06T21:14:22.922869Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"8db93c00-abc6-4fe7-82e3-c49cf6992f5e","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":501,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}444{"timestamp":"2026-10-06T21:14:23.023897Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"bfa69902-5dad-4e4c-8331-6e7268b96d0f","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":501,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}445=== RUN TestService_AuthMiddleware446=== PAUSE TestService_AuthMiddleware447=== RUN TestService_AuthMiddleware_MTLSProxyHeader448=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader449=== RUN TestService_AuthMiddleware_MTLSBoundSubjects450=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects451=== RUN TestService_ReadAuthMiddleware452=== PAUSE TestService_ReadAuthMiddleware453=== RUN TestService_AuthMiddleware_OIDC454=== PAUSE TestService_AuthMiddleware_OIDC455=== RUN TestService_RequireScope_OIDC456=== PAUSE TestService_RequireScope_OIDC457=== RUN TestService_ReadScope_PublicByDefault458=== PAUSE TestService_ReadScope_PublicByDefault459=== RUN TestCacheConfigHandler460=== PAUSE TestCacheConfigHandler461=== RUN TestCacheStatsHandler462=== PAUSE TestCacheStatsHandler463=== RUN TestClientCADerivations464=== PAUSE TestClientCADerivations465=== RUN TestClientErrorHandling466=== PAUSE TestClientErrorHandling467=== RUN TestClientIntegration468=== PAUSE TestClientIntegration469=== RUN TestClientMultipleUploads470=== PAUSE TestClientMultipleUploads471=== RUN TestClientWithDependencies472=== PAUSE TestClientWithDependencies473=== RUN TestClientSharedPathCommittedMidPush474=== PAUSE TestClientSharedPathCommittedMidPush475=== RUN TestPinProtectsFromGC476=== PAUSE TestPinProtectsFromGC477=== RUN TestClientPushesUseOnePush478=== PAUSE TestClientPushesUseOnePush479=== RUN TestClientFallsBackToClosures480=== PAUSE TestClientFallsBackToClosures481=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock482=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock483=== RUN TestResolveDBConnectionString484=== PAUSE TestResolveDBConnectionString485=== RUN TestConnectWaitsForAPeerMigration486=== PAUSE TestConnectWaitsForAPeerMigration487=== RUN TestLeadElectsOneAndHandsOver488=== PAUSE TestLeadElectsOneAndHandsOver489=== RUN TestLeadIncumbentWinsAfterRestart4902026/10/06 21:14:27 INFO lead: acquired remote=192.0.2.1:12344912026/10/06 21:14:28 INFO lead: released remote=192.0.2.1:12344922026/10/06 21:14:28 INFO lead: acquired remote=192.0.2.1:12344932026/10/06 21:14:29 INFO lead: released remote=192.0.2.1:1234494--- PASS: TestLeadIncumbentWinsAfterRestart (6.16s)495=== RUN TestLeadIncumbentAnnouncesAtOnce496=== PAUSE TestLeadIncumbentAnnouncesAtOnce497=== RUN TestLeadEndsOnShutdown498=== PAUSE TestLeadEndsOnShutdown499=== RUN TestLeadEndsWhenItsConnectionHangs5002026/10/06 21:14:31 INFO lead: acquired remote=192.0.2.1:12345012026-10-06 21:14:32.711 UTC [29591] FATAL: terminating connection due to administrator command5022026/10/06 21:14:32 INFO lead: acquired remote=192.0.2.1:12345032026/10/06 21:14:33 WARN lead: lock connection lost error="timeout: context deadline exceeded"5042026/10/06 21:14:33 INFO lead: released remote=192.0.2.1:12345052026/10/06 21:14:34 INFO lead: released remote=192.0.2.1:1234506--- PASS: TestLeadEndsWhenItsConnectionHangs (4.83s)507=== RUN TestGCAdvisoryLockBlocksConcurrentRun508=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun509=== RUN TestGCBugBareHashReferences510=== PAUSE TestGCBugBareHashReferences511=== RUN TestGCMetrics512=== PAUSE TestGCMetrics513=== RUN TestPushDedupSurvivesConcurrentGC514=== PAUSE TestPushDedupSurvivesConcurrentGC515=== RUN TestDeduplicatedObjectsRecordedAsPending516=== PAUSE TestDeduplicatedObjectsRecordedAsPending517=== RUN TestGCSweepSkipsPendingObjects518=== PAUSE TestGCSweepSkipsPendingObjects519=== RUN TestTombstonedObjectOfferedWithoutWaiting520=== PAUSE TestTombstonedObjectOfferedWithoutWaiting521=== RUN TestGCSweepDeliversEachKeyOnce522=== PAUSE TestGCSweepDeliversEachKeyOnce523=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection524=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection525=== RUN TestForceGCDuringPushOffersSweptObject526=== PAUSE TestForceGCDuringPushOffersSweptObject527=== RUN TestFailedS3DeleteKeepsTombstone528=== PAUSE TestFailedS3DeleteKeepsTombstone529=== RUN TestSweepSkipsRowsLockedByPush530=== PAUSE TestSweepSkipsRowsLockedByPush531=== RUN TestRegisterCompletedObjectNeedsPendingRow532=== PAUSE TestRegisterCompletedObjectNeedsPendingRow533=== RUN TestGetExistingObjectsLocksRows534=== PAUSE TestGetExistingObjectsLocksRows535=== RUN TestSweepRechecksPendingAfterLocking536=== PAUSE TestSweepRechecksPendingAfterLocking537=== RUN TestPushWaitsForSweepHoldingRow538=== PAUSE TestPushWaitsForSweepHoldingRow539=== RUN TestCommitRacingPendingCleanupKeepsObjects540=== PAUSE TestCommitRacingPendingCleanupKeepsObjects541=== RUN TestGCEndsOnShutdown542=== PAUSE TestGCEndsOnShutdown543=== RUN TestGCTaskStore_StartNew544=== PAUSE TestGCTaskStore_StartNew545=== RUN TestGCTaskStore_DeduplicateSameParams546=== PAUSE TestGCTaskStore_DeduplicateSameParams547=== RUN TestGCTaskStore_ConflictDifferentParams548=== PAUSE TestGCTaskStore_ConflictDifferentParams549=== RUN TestGCTaskStore_GetEmpty550=== PAUSE TestGCTaskStore_GetEmpty551=== RUN TestGCTaskStore_GetReturnsLatest552=== PAUSE TestGCTaskStore_GetReturnsLatest553=== RUN TestGCTaskStore_CompletedAllowsNewTask554=== PAUSE TestGCTaskStore_CompletedAllowsNewTask555=== RUN TestGCTaskStore_PhaseUpdates556=== PAUSE TestGCTaskStore_PhaseUpdates557=== RUN TestGCTaskStore_Fail558=== PAUSE TestGCTaskStore_Fail559=== RUN TestGracefulShutdownDrainsInflight560=== PAUSE TestGracefulShutdownDrainsInflight561=== RUN TestService_healthCheckHandler562=== PAUSE TestService_healthCheckHandler563=== RUN TestService_readinessHandler564=== PAUSE TestService_readinessHandler565=== RUN TestGenerateLandingPage566=== PAUSE TestGenerateLandingPage567=== RUN TestCacheConfigHandlerMaxNarSize568=== PAUSE TestCacheConfigHandlerMaxNarSize569=== RUN TestCreatePendingClosureRejectsOversizedNAR570=== PAUSE TestCreatePendingClosureRejectsOversizedNAR571=== RUN TestNARDeduplicationMetadataUploadBug572=== PAUSE TestNARDeduplicationMetadataUploadBug573=== RUN TestMetricsInventory574=== PAUSE TestMetricsInventory575=== RUN TestService_NativeMTLS576=== PAUSE TestService_NativeMTLS577=== RUN TestServerTLSConfig578=== PAUSE TestServerTLSConfig579=== RUN TestMultipartCleanup580=== PAUSE TestMultipartCleanup581=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded582=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded583=== RUN TestPendingCleanupUsesOneCutoff584=== PAUSE TestPendingCleanupUsesOneCutoff585=== RUN TestObjectStatsTrigger586=== PAUSE TestObjectStatsTrigger587=== RUN TestOrphanedObjectsGC588=== PAUSE TestOrphanedObjectsGC589=== RUN TestOrphanedObjectsGCStressTest590=== PAUSE TestOrphanedObjectsGCStressTest591=== RUN TestCreatePin_ReservedPins592=== PAUSE TestCreatePin_ReservedPins593=== RUN TestPresentReportsOnlyClosureRoots594=== PAUSE TestPresentReportsOnlyClosureRoots595=== RUN TestPresentRefreshesOnlyStaleClosures596=== PAUSE TestPresentRefreshesOnlyStaleClosures597=== RUN TestPresentNotReportedWhileGCDeletesClosure598=== PAUSE TestPresentNotReportedWhileGCDeletesClosure599=== RUN TestParseSingleRange600=== PAUSE TestParseSingleRange601=== RUN TestProxyHeadersOnlyTrustedOnSocket602=== PAUSE TestProxyHeadersOnlyTrustedOnSocket603=== RUN TestIsValidCachePath604=== PAUSE TestIsValidCachePath605=== RUN TestReadProxyNarinfo606=== PAUSE TestReadProxyNarinfo607=== RUN TestReadProxyNarinfoAlreadyDecompressed608=== PAUSE TestReadProxyNarinfoAlreadyDecompressed609=== RUN TestReadProxyContentNegotiation610=== PAUSE TestReadProxyContentNegotiation611=== RUN TestReadProxyNarStreaming612=== PAUSE TestReadProxyNarStreaming613=== RUN TestReadProxy404614=== PAUSE TestReadProxy404615=== RUN TestReadProxyInvalidPath616=== PAUSE TestReadProxyInvalidPath617=== RUN TestReadProxyHead618=== PAUSE TestReadProxyHead619=== RUN TestReadProxyOutlastsServerWriteTimeout620=== PAUSE TestReadProxyOutlastsServerWriteTimeout621=== RUN TestReadProxyConditionalGet622=== PAUSE TestReadProxyConditionalGet623=== RUN TestReadProxyRootRedirectsToIndexHTML624=== PAUSE TestReadProxyRootRedirectsToIndexHTML625=== RUN TestReadProxyDisabled626=== PAUSE TestReadProxyDisabled627=== RUN TestReadRedirectNar628=== PAUSE TestReadRedirectNar629=== RUN TestReadRedirectKeepsNarinfoProxied630=== PAUSE TestReadRedirectKeepsNarinfoProxied631=== RUN TestReadProxyRangeRequest632=== PAUSE TestReadProxyRangeRequest633=== RUN TestReadRedirectUsesPublicS3URL634=== PAUSE TestReadRedirectUsesPublicS3URL635=== RUN TestPush_OverlappingRootsStoreOneRowPerKey636=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey637=== RUN TestPush_CompleteCommitsEveryRoot638=== PAUSE TestPush_CompleteCommitsEveryRoot639=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit640=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit641=== RUN TestPush_RejectsBadRequests642=== PAUSE TestPush_RejectsBadRequests643=== RUN TestPush_SignsNarinfosOfItsPendingObjects644=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects645=== RUN TestRedundantMultipartUpload646=== PAUSE TestRedundantMultipartUpload647=== RUN TestCompleteMultipartUpload_ErrorButObjectExists648=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists649=== RUN TestCompletedNarNotReofferedAcrossClosures650=== PAUSE TestCompletedNarNotReofferedAcrossClosures651=== RUN TestPresignedUploadRegisteredBeforeCommit652=== PAUSE TestPresignedUploadRegisteredBeforeCommit653=== RUN TestService_Rustfstest654=== PAUSE TestService_Rustfstest655=== RUN TestParseSize656=== PAUSE TestParseSize657=== RUN TestSkippedUploadsHandler658=== PAUSE TestSkippedUploadsHandler659=== RUN TestSystemdListenerNotActivated660--- PASS: TestSystemdListenerNotActivated (0.00s)661=== RUN TestWatchdogBeatsWhenHealthy662--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)663=== RUN TestWatchdogSkipsWhenUnhealthy6642026/10/06 21:14:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6652026/10/06 21:14:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6662026/10/06 21:14:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6672026/10/06 21:14:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6682026/10/06 21:14:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6692026/10/06 21:14:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6702026/10/06 21:14:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6712026/10/06 21:14:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6722026/10/06 21:14:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6732026/10/06 21:14:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"674--- PASS: TestWatchdogSkipsWhenUnhealthy (0.21s)675=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle676=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle677=== RUN TestProxyWriteTimeout678=== PAUSE TestProxyWriteTimeout679=== RUN TestPendingClosureWriteTimeout680=== PAUSE TestPendingClosureWriteTimeout681=== RUN TestIsValidUploadKey682=== PAUSE TestIsValidUploadKey683=== RUN TestUploadHandlersRejectInvalidKeys684=== PAUSE TestUploadHandlersRejectInvalidKeys685=== RUN TestUploadHandlersRejectOversizedBody686=== PAUSE TestUploadHandlersRejectOversizedBody687=== RUN TestService_cleanupPendingClosuresHandler688=== PAUSE TestService_cleanupPendingClosuresHandler689=== RUN TestService_createPendingClosureHandler690=== PAUSE TestService_createPendingClosureHandler691=== RUN TestService_verifyS3Integrity692=== PAUSE TestService_verifyS3Integrity693=== RUN TestCompleteMultipartUnregistered694=== PAUSE TestCompleteMultipartUnregistered695=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT696=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT697=== CONT TestService_AuthMiddleware698=== CONT TestServerTLSConfig699=== RUN TestServerTLSConfig/no_client_CA700=== PAUSE TestServerTLSConfig/no_client_CA701=== RUN TestServerTLSConfig/missing_CA_file702=== PAUSE TestServerTLSConfig/missing_CA_file703=== RUN TestServerTLSConfig/not_a_PEM_file704=== PAUSE TestServerTLSConfig/not_a_PEM_file705=== CONT TestServerTLSConfig/no_client_CA706=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT707=== CONT TestService_NativeMTLS708=== CONT TestMetricsInventory709=== CONT TestReadRedirectNar710=== CONT TestGCSweepSkipsPendingObjects711=== CONT TestDeduplicatedObjectsRecordedAsPending712=== CONT TestGCTaskStore_DeduplicateSameParams713--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)714=== CONT TestService_createPendingClosureHandler715=== CONT TestCompleteMultipartUnregistered716=== CONT TestService_verifyS3Integrity7172026/10/06 21:14:35 INFO Received uploads request method=POST path=/api/pending_closures7182026/10/06 21:14:35 WARN mTLS auth: subject not in bound subjects subject="CN=reader"7192026/10/06 21:14:35 WARN mTLS auth: subject not in bound subjects subject="CN=reader"720--- PASS: TestService_NativeMTLS (1.61s)721=== CONT TestService_cleanupPendingClosuresHandler7222026/10/06 21:14:36 INFO Received uploads request method=POST path=/api/pending_closures7232026/10/06 21:14:36 INFO Received uploads request method=POST path=/api/pending_closures7242026/10/06 21:14:36 INFO Received uploads request method=POST path=/api/pending_closures7252026/10/06 21:14:36 INFO Received uploads request method=POST path=/api/pending_closures726--- PASS: TestDeduplicatedObjectsRecordedAsPending (2.24s)727=== CONT TestUploadHandlersRejectOversizedBody728=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts729=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts730=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure731=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure732=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart733=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart734=== CONT TestUploadHandlersRejectInvalidKeys735=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info736=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info737=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal738=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal739=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key740=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key741=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key742=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key743=== CONT TestIsValidUploadKey744=== RUN TestIsValidUploadKey/narinfo745=== PAUSE TestIsValidUploadKey/narinfo746=== RUN TestIsValidUploadKey/nar_zst747=== PAUSE TestIsValidUploadKey/nar_zst748=== RUN TestIsValidUploadKey/nar_xz749=== PAUSE TestIsValidUploadKey/nar_xz750=== RUN TestIsValidUploadKey/nar_plain751=== PAUSE TestIsValidUploadKey/nar_plain752=== RUN TestIsValidUploadKey/listing753=== PAUSE TestIsValidUploadKey/listing754=== RUN TestIsValidUploadKey/build_log755=== PAUSE TestIsValidUploadKey/build_log756=== RUN TestIsValidUploadKey/build_log_home-manager_file757=== PAUSE TestIsValidUploadKey/build_log_home-manager_file758=== RUN TestIsValidUploadKey/build_log_plus_in_name759=== PAUSE TestIsValidUploadKey/build_log_plus_in_name760=== RUN TestIsValidUploadKey/build_log_question_mark761=== PAUSE TestIsValidUploadKey/build_log_question_mark762=== RUN TestIsValidUploadKey/build_log_equals763=== PAUSE TestIsValidUploadKey/build_log_equals764=== RUN TestIsValidUploadKey/realisation765=== PAUSE TestIsValidUploadKey/realisation766=== RUN TestIsValidUploadKey/realisation_plus_in_output767=== PAUSE TestIsValidUploadKey/realisation_plus_in_output768=== RUN TestIsValidUploadKey/nix-cache-info769=== PAUSE TestIsValidUploadKey/nix-cache-info770=== RUN TestIsValidUploadKey/index.html771=== PAUSE TestIsValidUploadKey/index.html772=== RUN TestIsValidUploadKey/narinfo_key,_nar_type773=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type774=== RUN TestIsValidUploadKey/nar_key,_narinfo_type775=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type776=== RUN TestIsValidUploadKey/listing_key,_narinfo_type777=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type778=== RUN TestIsValidUploadKey/traversal779=== PAUSE TestIsValidUploadKey/traversal780=== RUN TestIsValidUploadKey/traversal_nar781=== PAUSE TestIsValidUploadKey/traversal_nar782=== RUN TestIsValidUploadKey/absolute783=== PAUSE TestIsValidUploadKey/absolute784=== RUN TestIsValidUploadKey/empty_key785=== PAUSE TestIsValidUploadKey/empty_key786=== RUN TestIsValidUploadKey/unknown_type787=== PAUSE TestIsValidUploadKey/unknown_type788=== CONT TestPendingClosureWriteTimeout789=== RUN TestPendingClosureWriteTimeout/empty790=== PAUSE TestPendingClosureWriteTimeout/empty791=== RUN TestPendingClosureWriteTimeout/400_objects792=== PAUSE TestPendingClosureWriteTimeout/400_objects793=== RUN TestPendingClosureWriteTimeout/670k_objects794=== PAUSE TestPendingClosureWriteTimeout/670k_objects795=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline796=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline797=== CONT TestProxyWriteTimeout798=== RUN TestProxyWriteTimeout/narinfo799=== PAUSE TestProxyWriteTimeout/narinfo800=== RUN TestProxyWriteTimeout/1_GiB_nar801=== PAUSE TestProxyWriteTimeout/1_GiB_nar802=== RUN TestProxyWriteTimeout/10_GiB_nar803=== PAUSE TestProxyWriteTimeout/10_GiB_nar804=== RUN TestProxyWriteTimeout/unknown_size805=== PAUSE TestProxyWriteTimeout/unknown_size806=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle8072026/10/06 21:14:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8082026/10/06 21:14:36 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst809--- PASS: TestCompleteMultipartUnregistered (2.54s)810=== CONT TestSkippedUploadsHandler8112026/10/06 21:14:36 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000812--- PASS: TestSkippedUploadsHandler (0.00s)813=== CONT TestParseSize814--- PASS: TestParseSize (0.00s)815=== CONT TestService_Rustfstest8162026/10/06 21:14:37 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"817--- PASS: TestService_AuthMiddleware (2.96s)818=== CONT TestPresignedUploadRegisteredBeforeCommit8192026/10/06 21:14:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8202026/10/06 21:14:37 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NjM2YmU1MGItNTBkMy00NWRiLWJlZDEtMGQyZDM0NmIzNzYzLjI0OTRhOGUzLTQ2NzYtNGRiMi04OThkLTMxNjhkNDZmM2E3ZngxNzkxMzIxMjc1NzIwMDY4MDAw parts=108212026/10/06 21:14:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8222026/10/06 21:14:37 INFO Completed upload id=18232026/10/06 21:14:37 INFO Received uploads request method=POST path=/api/pending_closures8242026/10/06 21:14:37 INFO Received uploads request method=POST path=/api/pending_closures8252026/10/06 21:14:37 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo8262026/10/06 21:14:37 WARN Found objects in DB but missing from S3, will re-upload count=1827--- PASS: TestService_verifyS3Integrity (3.13s)828=== CONT TestCompletedNarNotReofferedAcrossClosures8292026/10/06 21:14:37 INFO Received uploads request method=POST path=/api/pending_closures830--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (3.51s)831=== CONT TestCompleteMultipartUpload_ErrorButObjectExists8322026/10/06 21:14:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8332026/10/06 21:14:38 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NjM2YmU1MGItNTBkMy00NWRiLWJlZDEtMGQyZDM0NmIzNzYzLjcwMWFhNjc1LTg4YTctNDM5Ni1hYjc2LTU4NjE3OTFjMjkzNngxNzkxMzIxMjc2Mjc5ODQ5MDAw parts=108342026/10/06 21:14:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8352026/10/06 21:14:38 INFO Completed upload id=18362026/10/06 21:14:38 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000008372026/10/06 21:14:38 INFO Received uploads request method=POST path=/api/pending_closures8382026/10/06 21:14:38 INFO Starting cleanup of old closures method=DELETE path=/api/closures8392026/10/06 21:14:38 INFO Aborted multipart uploads count=0 kept=08402026/10/06 21:14:38 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=08412026/10/06 21:14:38 INFO Vacuumed table table=pending_closures8422026/10/06 21:14:38 INFO Vacuumed table table=pending_objects843--- PASS: TestReadRedirectNar (3.85s)844=== CONT TestRedundantMultipartUpload8452026/10/06 21:14:38 INFO Vacuumed table table=multipart_uploads8462026/10/06 21:14:38 INFO Vacuumed table table=closures8472026/10/06 21:14:38 INFO Vacuumed table table=objects8482026/10/06 21:14:38 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000849--- PASS: TestService_createPendingClosureHandler (3.97s)850=== CONT TestPush_SignsNarinfosOfItsPendingObjects8512026/10/06 21:14:38 INFO Received uploads request method=POST path=/api/pending_closures8522026/10/06 21:14:38 INFO Aborted multipart uploads count=0 kept=08532026/10/06 21:14:38 WARN Force mode enabled - objects will be deleted immediately without grace period8542026/10/06 21:14:38 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=08552026/10/06 21:14:38 INFO Vacuumed table table=pending_closures8562026/10/06 21:14:38 INFO Vacuumed table table=pending_objects8572026/10/06 21:14:38 INFO Vacuumed table table=multipart_uploads8582026/10/06 21:14:38 INFO Vacuumed table table=closures8592026/10/06 21:14:38 INFO Vacuumed table table=objects860--- PASS: TestGCSweepSkipsPendingObjects (4.40s)861=== CONT TestPush_RejectsBadRequests862--- PASS: TestMetricsInventory (4.61s)863=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit8642026/10/06 21:14:39 INFO Received cleanup request method=DELETE path=/api/pending_closures8652026/10/06 21:14:39 INFO Aborted multipart uploads count=0 kept=08662026/10/06 21:14:39 INFO Received uploads request method=POST path=/api/pending_closures8672026/10/06 21:14:39 INFO Received cleanup request method=DELETE path=/api/pending_closures8682026/10/06 21:14:39 INFO Aborted multipart uploads count=1 kept=08692026/10/06 21:14:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8702026-10-06 21:14:39.338 UTC [30138] ERROR: Closure does not exist: id=18712026-10-06 21:14:39.338 UTC [30138] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE8722026-10-06 21:14:39.338 UTC [30138] STATEMENT: -- name: CommitPendingClosure :exec873 SELECT commit_pending_closure($1::bigint)874 875--- PASS: TestService_cleanupPendingClosuresHandler (3.38s)876=== CONT TestPush_CompleteCommitsEveryRoot8772026/10/06 21:14:39 INFO Received uploads request method=POST path=/api/pending_closures878--- PASS: TestService_Rustfstest (3.17s)879=== CONT TestPush_OverlappingRootsStoreOneRowPerKey8802026/10/06 21:14:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8812026/10/06 21:14:40 INFO Received uploads request method=POST path=/api/pending_closures8822026/10/06 21:14:40 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst8832026/10/06 21:14:40 INFO Received uploads request method=POST path=/api/pending_closures884--- PASS: TestPresignedUploadRegisteredBeforeCommit (3.31s)885=== CONT TestReadRedirectUsesPublicS3URL8862026/10/06 21:14:40 INFO Received uploads request method=POST path=/api/pending_closures8872026/10/06 21:14:41 INFO Received uploads request method=POST path=/api/pending_closures8882026/10/06 21:14:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8892026/10/06 21:14:41 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NjM2YmU1MGItNTBkMy00NWRiLWJlZDEtMGQyZDM0NmIzNzYzLjM5NzAwN2IxLWM3NDYtNDM1MS1iZWM2LWY3ZDhmOTUxMDFkZngxNzkxMzIxMjgxNTQ1MzU0MDAw8902026/10/06 21:14:41 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NjM2YmU1MGItNTBkMy00NWRiLWJlZDEtMGQyZDM0NmIzNzYzLjM5NzAwN2IxLWM3NDYtNDM1MS1iZWM2LWY3ZDhmOTUxMDFkZngxNzkxMzIxMjgxNTQ1MzU0MDAw parts=1891--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (4.07s)892=== CONT TestReadProxyRangeRequest8932026/10/06 21:14:41 INFO Received uploads request method=POST path=/api/pending_closures8942026/10/06 21:14:42 INFO Received uploads request method=POST path=/api/pending_closures8952026/10/06 21:14:42 INFO Received push request method=POST path=/api/pushes8962026/10/06 21:14:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8972026/10/06 21:14:42 INFO Signed narinfos id=1 count=18982026/10/06 21:14:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8992026/10/06 21:14:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9002026/10/06 21:14:42 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"9012026/10/06 21:14:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9022026/10/06 21:14:42 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"9032026/10/06 21:14:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9042026/10/06 21:14:42 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=19052026/10/06 21:14:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9062026/10/06 21:14:42 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo907--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (4.46s)908=== CONT TestReadRedirectKeepsNarinfoProxied909=== RUN TestPush_RejectsBadRequests/no_roots910=== PAUSE TestPush_RejectsBadRequests/no_roots911=== RUN TestPush_RejectsBadRequests/no_objects912=== PAUSE TestPush_RejectsBadRequests/no_objects913=== RUN TestPush_RejectsBadRequests/bad_root914=== PAUSE TestPush_RejectsBadRequests/bad_root915=== RUN TestPush_RejectsBadRequests/root_not_in_objects916=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects917=== CONT TestGracefulShutdownDrainsInflight9182026/10/06 21:14:43 INFO Starting HTTP server address=127.0.0.1:497049192026/10/06 21:14:43 INFO Shutdown signal received, draining in-flight requests timeout=10s920--- PASS: TestGracefulShutdownDrainsInflight (0.07s)921=== CONT TestNARDeduplicationMetadataUploadBug9222026/10/06 21:14:43 INFO Received push request method=POST path=/api/pushes9232026/10/06 21:14:43 INFO Received complete push request method=POST path=/api/pushes/1/complete9242026/10/06 21:14:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9252026/10/06 21:14:43 INFO Received push request method=POST path=/api/pushes9262026/10/06 21:14:43 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NjM2YmU1MGItNTBkMy00NWRiLWJlZDEtMGQyZDM0NmIzNzYzLmI4Nzg4M2E0LWI1ODktNDYzZS05ZGI3LTFjMTU2MmZiMmZmZHgxNzkxMzIxMjgxMDM4NDA4MDAw parts=129272026/10/06 21:14:43 INFO Received uploads request method=POST path=/api/pending_closures928--- PASS: TestCompletedNarNotReofferedAcrossClosures (6.49s)929=== CONT TestCreatePendingClosureRejectsOversizedNAR9302026/10/06 21:14:43 INFO Received uploads request method=POST path=/api/pending_closures931--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)932=== CONT TestCacheConfigHandlerMaxNarSize933--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)934=== CONT TestGenerateLandingPage935--- PASS: TestGenerateLandingPage (0.00s)936=== CONT TestService_readinessHandler9372026/10/06 21:14:44 INFO Aborted multipart uploads count=0 kept=09382026/10/06 21:14:44 WARN Force mode enabled - objects will be deleted immediately without grace period9392026/10/06 21:14:44 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=09402026/10/06 21:14:44 INFO Vacuumed table table=pending_closures9412026/10/06 21:14:44 INFO Vacuumed table table=pending_objects9422026/10/06 21:14:44 INFO Vacuumed table table=multipart_uploads9432026/10/06 21:14:44 INFO Vacuumed table table=closures9442026/10/06 21:14:44 INFO Received push request method=POST path=/api/pushes9452026/10/06 21:14:44 INFO Vacuumed table table=objects9462026/10/06 21:14:44 INFO Received complete push request method=POST path=/api/pushes/2/complete947--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (5.32s)948=== CONT TestService_healthCheckHandler9492026/10/06 21:14:44 WARN Rate limiter enabled after throttle name=s3-test rate=59502026/10/06 21:14:44 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."951=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle952 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=10953 throttle_test.go:215: Rate limiter: enabled=true, rate=5.00954--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (7.69s)955=== CONT TestRegisterCompletedObjectNeedsPendingRow9562026/10/06 21:14:44 INFO Received complete push request method=POST path=/api/pushes/1/complete957--- PASS: TestPush_CompleteCommitsEveryRoot (5.06s)958=== CONT TestGCTaskStore_StartNew959--- PASS: TestGCTaskStore_StartNew (0.00s)960=== CONT TestGCEndsOnShutdown961=== RUN TestGCEndsOnShutdown/before_the_run962=== PAUSE TestGCEndsOnShutdown/before_the_run963=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete964=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete965=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark966=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark967=== CONT TestCommitRacingPendingCleanupKeepsObjects9682026/10/06 21:14:44 INFO Received push request method=POST path=/api/pushes969--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (4.75s)970=== CONT TestPushWaitsForSweepHoldingRow9712026/10/06 21:14:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9722026/10/06 21:14:45 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NjM2YmU1MGItNTBkMy00NWRiLWJlZDEtMGQyZDM0NmIzNzYzLmMwMzk4ZDMyLTI2YjAtNDhkOC05Nzg0LTFlZjY4MWRkYWE3MHgxNzkxMzIxMjgyMDQ5MTY5MDAw parts=129732026/10/06 21:14:45 INFO Received uploads request method=POST path=/api/pending_closures9742026/10/06 21:14:45 INFO Received uploads request method=POST path=/api/pending_closures975--- PASS: TestReadRedirectUsesPublicS3URL (4.59s)976=== CONT TestSweepRechecksPendingAfterLocking977--- PASS: TestReadProxyRangeRequest (3.65s)978=== CONT TestGetExistingObjectsLocksRows979--- PASS: TestReadRedirectKeepsNarinfoProxied (3.33s)980=== CONT TestProxyHeadersOnlyTrustedOnSocket9812026/10/06 21:14:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9822026/10/06 21:14:47 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NjM2YmU1MGItNTBkMy00NWRiLWJlZDEtMGQyZDM0NmIzNzYzLmI1MDg0MTYxLWUxMzItNGYwMi05MmY0LWMwYTkzMmNkNzI4NXgxNzkxMzIxMjg1MTkyOTkxMDAw error="Get \"http://127.0.0.1:1/bucket19/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"9832026/10/06 21:14:47 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NjM2YmU1MGItNTBkMy00NWRiLWJlZDEtMGQyZDM0NmIzNzYzLjMwOGQxYzA5LTQ1MjktNDU0Ni05OWFlLTk0ZWYyYTY3ODRiZHgxNzkxMzIxMjg1MTQwNTY0MDAw parts=129842026/10/06 21:14:47 INFO Received cleanup request method=DELETE path=/api/pending_closures9852026/10/06 21:14:47 INFO Aborted multipart uploads count=1 kept=0986--- PASS: TestRedundantMultipartUpload (9.12s)987=== CONT TestReadProxyDisabled988--- PASS: TestService_healthCheckHandler (3.10s)989=== CONT TestReadProxyRootRedirectsToIndexHTML990=== NAME TestNARDeduplicationMetadataUploadBug991 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-28191-160554113/TestNARDeduplicationMetadataUploadBug2422961449/001/store/0kgpfx156mbphsb4h69xay0j6fzmrfcj-file1.txt9922026/10/06 21:14:47 INFO Received push request method=POST path=/api/pushes9932026/10/06 21:14:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9942026/10/06 21:14:47 INFO Uploading 0kgpfx156mbphsb4h69xay0j6fzmrfcj-file1.txt (160B)9952026/10/06 21:14:47 WARN readiness check failed error="closed pool"996--- PASS: TestService_readinessHandler (3.74s)997=== CONT TestReadProxyConditionalGet9982026/10/06 21:14:47 WARN Failed to register uploaded object key=0kgpfx156mbphsb4h69xay0j6fzmrfcj.ls error="server returned 404: 404 page not found\n"9992026/10/06 21:14:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10002026/10/06 21:14:47 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"10012026/10/06 21:14:47 INFO Signed narinfos id=1 count=110022026/10/06 21:14:47 INFO Uploading 1 narinfos10032026/10/06 21:14:47 INFO Received complete push request method=POST path=/api/pushes/1/complete10042026/10/06 21:14:47 WARN Failed to register uploaded object key=0kgpfx156mbphsb4h69xay0j6fzmrfcj.narinfo error="server returned 404: 404 page not found\n"10052026/10/06 21:14:47 INFO Upload complete. (234ms)1006=== NAME TestNARDeduplicationMetadataUploadBug1007 metadata_upload_test.go:54: Retrieved narinfo from S3:1008 StorePath: /nix/var/nix/builds/nix-28191-160554113/TestNARDeduplicationMetadataUploadBug2422961449/001/store/0kgpfx156mbphsb4h69xay0j6fzmrfcj-file1.txt1009 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1010 Compression: zstd1011 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1012 NarSize: 1601013 References: 1014 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1015 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1016 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1017 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1018 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-28191-160554113/TestNARDeduplicationMetadataUploadBug2422961449/001/store/10bjf3fhhldj95nk7spjfg4y4xyyvbyj-file2.txt10192026/10/06 21:14:48 INFO Aborted multipart uploads count=0 kept=010202026/10/06 21:14:48 WARN Force mode enabled - objects will be deleted immediately without grace period10212026/10/06 21:14: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=010222026/10/06 21:14:48 INFO Vacuumed table table=pending_closures10232026/10/06 21:14:48 INFO Received push request method=POST path=/api/pushes10242026/10/06 21:14:48 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)10252026/10/06 21:14:48 INFO Vacuumed table table=pending_objects10262026/10/06 21:14:48 INFO Vacuumed table table=multipart_uploads10272026/10/06 21:14:48 INFO Vacuumed table table=closures10282026/10/06 21:14:48 INFO Vacuumed table table=objects10292026/10/06 21:14:48 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign10302026/10/06 21:14:48 INFO Signed narinfos id=2 count=110312026/10/06 21:14:48 INFO Uploading 1 narinfos10322026/10/06 21:14:48 WARN Failed to register uploaded object key=10bjf3fhhldj95nk7spjfg4y4xyyvbyj.ls error="server returned 404: 404 page not found\n"1033--- PASS: TestCommitRacingPendingCleanupKeepsObjects (4.08s)1034=== CONT TestReadProxyOutlastsServerWriteTimeout10352026/10/06 21:14:48 INFO Received complete push request method=POST path=/api/pushes/2/complete10362026/10/06 21:14:48 WARN Failed to register uploaded object key=10bjf3fhhldj95nk7spjfg4y4xyyvbyj.narinfo error="server returned 404: 404 page not found\n"10372026/10/06 21:14:48 INFO Upload complete. (291ms)1038=== NAME TestNARDeduplicationMetadataUploadBug1039 metadata_upload_test.go:76: Retrieved narinfo from S3:1040 StorePath: /nix/var/nix/builds/nix-28191-160554113/TestNARDeduplicationMetadataUploadBug2422961449/001/store/10bjf3fhhldj95nk7spjfg4y4xyyvbyj-file2.txt1041 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1042 Compression: zstd1043 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1044 NarSize: 1601045 References: 1046 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1047 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1048 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1049 {"version":1,"root":{"type":"regular","size":44}}1050--- PASS: TestRegisterCompletedObjectNeedsPendingRow (4.27s)1051=== CONT TestReadProxyHead1052--- PASS: TestNARDeduplicationMetadataUploadBug (5.24s)1053=== CONT TestReadProxyInvalidPath10542026/10/06 21:14:48 INFO Received uploads request method=POST path=/api/pending_closures10552026/10/06 21:14:49 INFO Aborted multipart uploads count=0 kept=010562026/10/06 21:14:49 WARN Force mode enabled - objects will be deleted immediately without grace period1057--- PASS: TestPushWaitsForSweepHoldingRow (4.62s)1058=== CONT TestReadProxy40410592026/10/06 21:14:49 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=010602026/10/06 21:14:49 INFO Vacuumed table table=pending_closures10612026/10/06 21:14:49 INFO Vacuumed table table=pending_objects10622026/10/06 21:14:49 INFO Vacuumed table table=multipart_uploads10632026/10/06 21:14:49 INFO Vacuumed table table=closures10642026/10/06 21:14:49 INFO Vacuumed table table=objects1065--- PASS: TestSweepRechecksPendingAfterLocking (4.28s)1066=== CONT TestReadProxyNarStreaming1067--- PASS: TestGetExistingObjectsLocksRows (4.12s)1068=== CONT TestReadProxyContentNegotiation10692026/10/06 21:14:50 INFO Starting HTTP server address=/nix/var/nix/builds/nix-28191-160554113/TestProxyHeadersOnlyTrustedOnSocket1651936783/001/proxy.sock10702026/10/06 21:14:50 INFO Starting HTTP server address=127.0.0.1:4977210712026/10/06 21:14:50 WARN mTLS auth: subject not in bound subjects subject="CN=someone"10722026/10/06 21:14:50 INFO Shutdown signal received, draining in-flight requests timeout=10s1073--- PASS: TestProxyHeadersOnlyTrustedOnSocket (3.94s)1074=== CONT TestReadProxyNarinfoAlreadyDecompressed1075--- PASS: TestReadProxyRootRedirectsToIndexHTML (3.02s)1076=== CONT TestReadProxyNarinfo1077--- PASS: TestReadProxyDisabled (3.39s)1078=== CONT TestIsValidCachePath1079=== RUN TestIsValidCachePath/narinfo1080=== PAUSE TestIsValidCachePath/narinfo1081=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1082=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1083=== RUN TestIsValidCachePath/nar_zst1084=== PAUSE TestIsValidCachePath/nar_zst1085=== RUN TestIsValidCachePath/nar_xz1086=== PAUSE TestIsValidCachePath/nar_xz1087=== RUN TestIsValidCachePath/nar_bz21088=== PAUSE TestIsValidCachePath/nar_bz21089=== RUN TestIsValidCachePath/nar_uncompressed1090=== PAUSE TestIsValidCachePath/nar_uncompressed1091=== RUN TestIsValidCachePath/ls1092=== PAUSE TestIsValidCachePath/ls1093=== RUN TestIsValidCachePath/log1094=== PAUSE TestIsValidCachePath/log1095=== RUN TestIsValidCachePath/realisation1096=== PAUSE TestIsValidCachePath/realisation1097=== RUN TestIsValidCachePath/nix-cache-info1098=== PAUSE TestIsValidCachePath/nix-cache-info1099=== RUN TestIsValidCachePath/index.html1100=== PAUSE TestIsValidCachePath/index.html1101=== RUN TestIsValidCachePath/traversal_parent1102=== PAUSE TestIsValidCachePath/traversal_parent1103=== RUN TestIsValidCachePath/traversal_in_middle1104=== PAUSE TestIsValidCachePath/traversal_in_middle1105=== RUN TestIsValidCachePath/invalid_char_e1106=== PAUSE TestIsValidCachePath/invalid_char_e1107=== RUN TestIsValidCachePath/invalid_char_u1108=== PAUSE TestIsValidCachePath/invalid_char_u1109=== RUN TestIsValidCachePath/random_path1110=== PAUSE TestIsValidCachePath/random_path1111=== RUN TestIsValidCachePath/empty1112=== PAUSE TestIsValidCachePath/empty1113=== RUN TestIsValidCachePath/leading_slash1114=== PAUSE TestIsValidCachePath/leading_slash1115=== RUN TestIsValidCachePath/wrong_extension1116=== PAUSE TestIsValidCachePath/wrong_extension1117=== RUN TestIsValidCachePath/short_hash1118=== PAUSE TestIsValidCachePath/short_hash1119=== CONT TestOrphanedObjectsGC1120--- PASS: TestReadProxyConditionalGet (3.38s)1121=== CONT TestParseSingleRange1122=== RUN TestParseSingleRange/none1123=== PAUSE TestParseSingleRange/none1124=== RUN TestParseSingleRange/unknown_unit1125=== PAUSE TestParseSingleRange/unknown_unit1126=== RUN TestParseSingleRange/multi-range_ignored1127=== PAUSE TestParseSingleRange/multi-range_ignored1128=== RUN TestParseSingleRange/malformed_no_dash1129=== PAUSE TestParseSingleRange/malformed_no_dash1130=== RUN TestParseSingleRange/malformed_both_empty1131=== PAUSE TestParseSingleRange/malformed_both_empty1132=== RUN TestParseSingleRange/malformed_end_before_start1133=== PAUSE TestParseSingleRange/malformed_end_before_start1134=== RUN TestParseSingleRange/closed1135=== PAUSE TestParseSingleRange/closed1136=== RUN TestParseSingleRange/open-ended1137=== PAUSE TestParseSingleRange/open-ended1138=== RUN TestParseSingleRange/end_clamped_to_size1139=== PAUSE TestParseSingleRange/end_clamped_to_size1140=== RUN TestParseSingleRange/suffix1141=== PAUSE TestParseSingleRange/suffix1142=== RUN TestParseSingleRange/suffix_exceeds_size1143=== PAUSE TestParseSingleRange/suffix_exceeds_size1144=== RUN TestParseSingleRange/single_byte1145=== PAUSE TestParseSingleRange/single_byte1146=== RUN TestParseSingleRange/start_past_EOF1147=== PAUSE TestParseSingleRange/start_past_EOF1148=== RUN TestParseSingleRange/start_far_past_EOF1149=== PAUSE TestParseSingleRange/start_far_past_EOF1150=== CONT TestPresentNotReportedWhileGCDeletesClosure1151=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1152=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1153=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1154=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1155=== CONT TestPresentRefreshesOnlyStaleClosures1156--- PASS: TestReadProxyInvalidPath (3.07s)1157=== CONT TestPresentReportsOnlyClosureRoots1158--- PASS: TestReadProxyHead (3.43s)1159=== CONT TestCreatePin_ReservedPins1160--- PASS: TestReadProxy404 (2.99s)1161=== CONT TestOrphanedObjectsGCStressTest11622026/10/06 21:14:52 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49804/oidc1163--- PASS: TestReadProxyContentNegotiation (3.10s)1164=== CONT TestClientSharedPathCommittedMidPush1165--- PASS: TestReadProxyNarStreaming (3.60s)1166=== CONT TestPushDedupSurvivesConcurrentGC1167--- PASS: TestReadProxyNarinfoAlreadyDecompressed (3.35s)1168=== CONT TestGCMetrics11692026/10/06 21:14:53 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1170--- PASS: TestReadProxyNarinfo (3.34s)1171=== CONT TestGCBugBareHashReferences1172--- PASS: TestPresentRefreshesOnlyStaleClosures (3.17s)1173=== CONT TestGCAdvisoryLockBlocksConcurrentRun1174--- PASS: TestPresentReportsOnlyClosureRoots (2.96s)1175=== CONT TestLeadEndsOnShutdown1176=== NAME TestOrphanedObjectsGC1177 orphaned_objects_gc_test.go:290: GC Test Summary:1178 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1179 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1180 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1181 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1182 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1183--- PASS: TestOrphanedObjectsGC (3.98s)1184=== CONT TestLeadIncumbentAnnouncesAtOnce11852026/10/06 21:14:55 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11862026/10/06 21:14:55 WARN Refused reserved pin name=worker-x86_64-linux11872026/10/06 21:14:55 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11882026/10/06 21:14:55 INFO Received create pin request method=POST path=/api/pins/my-app11892026/10/06 21:14:55 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1190--- PASS: TestCreatePin_ReservedPins (3.25s)1191=== CONT TestLeadElectsOneAndHandsOver1192--- PASS: TestReadProxyOutlastsServerWriteTimeout (7.11s)1193=== CONT TestConnectWaitsForAPeerMigration11942026/10/06 21:14:55 INFO Received uploads request method=POST path=/api/pending_closures11952026/10/06 21:14:55 INFO Aborted multipart uploads count=0 kept=011962026/10/06 21:14:55 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=011972026/10/06 21:14:56 INFO Vacuumed table table=pending_closures11982026/10/06 21:14:56 INFO Aborted multipart uploads count=0 kept=011992026/10/06 21:14:56 INFO Vacuumed table table=pending_objects12002026/10/06 21:14:56 INFO Vacuumed table table=multipart_uploads12012026/10/06 21:14:56 WARN Force mode enabled - objects will be deleted immediately without grace period12022026/10/06 21:14:56 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=012032026/10/06 21:14:56 INFO Vacuumed table table=pending_closures12042026/10/06 21:14:56 INFO Vacuumed table table=pending_objects12052026/10/06 21:14:56 INFO Vacuumed table table=multipart_uploads12062026/10/06 21:14:56 INFO Vacuumed table table=closures12072026/10/06 21:14:56 INFO Vacuumed table table=closures12082026/10/06 21:14:56 INFO Vacuumed table table=objects1209--- PASS: TestGCMetrics (2.66s)1210=== CONT TestResolveDBConnectionString1211=== RUN TestResolveDBConnectionString/flag_wins1212=== PAUSE TestResolveDBConnectionString/flag_wins1213=== RUN TestResolveDBConnectionString/file_when_flag_empty1214=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1215=== RUN TestResolveDBConnectionString/missing_file_is_an_error1216=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1217=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1218=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1219=== RUN TestResolveDBConnectionString/nothing_configured1220=== PAUSE TestResolveDBConnectionString/nothing_configured1221=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock12222026/10/06 21:14:56 INFO Vacuumed table table=objects12232026/10/06 21:14:56 INFO Aborted multipart uploads count=0 kept=012242026/10/06 21:14:56 WARN Force mode enabled - objects will be deleted immediately without grace period12252026/10/06 21:14:56 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=012262026/10/06 21:14:56 INFO Vacuumed table table=pending_closures12272026/10/06 21:14:56 INFO Vacuumed table table=pending_objects12282026/10/06 21:14:56 INFO Vacuumed table table=multipart_uploads12292026/10/06 21:14:56 INFO Vacuumed table table=closures12302026/10/06 21:14:56 INFO Vacuumed table table=objects1231--- PASS: TestPushDedupSurvivesConcurrentGC (3.02s)1232=== CONT TestClientFallsBackToClosures12332026/10/06 21:14:56 INFO Received push request method=POST path=/api/pushes12342026/10/06 21:14:56 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)12352026/10/06 21:14:56 INFO Uploading xpw83xbgywfwm7b2pxww2mxl8166pmp3-top (256B)12362026/10/06 21:14:56 INFO Uploading sfad8pk3m2i0xp609l5y33gidm1v1n29-shared-dep (136B)12372026/10/06 21:14:56 WARN Failed to register uploaded object key=nar/15ksqr52yziy1f1bgrv20xfy3zvsrqraj4fjxbc1a02cq4ysh869.nar.zst error="server returned 404: 404 page not found\n"12382026/10/06 21:14:56 WARN Failed to register uploaded object key=sfad8pk3m2i0xp609l5y33gidm1v1n29.ls error="server returned 404: 404 page not found\n"12392026/10/06 21:14:56 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12402026/10/06 21:14:56 WARN Failed to register uploaded object key=xpw83xbgywfwm7b2pxww2mxl8166pmp3.ls error="server returned 404: 404 page not found\n"12412026/10/06 21:14:56 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12422026/10/06 21:14:56 INFO Signed narinfos id=1 count=212432026/10/06 21:14:56 INFO Uploading 2 narinfos12442026/10/06 21:14:56 INFO Received complete push request method=POST path=/api/pushes/1/complete12452026/10/06 21:14:56 WARN Failed to register uploaded object key=sfad8pk3m2i0xp609l5y33gidm1v1n29.narinfo error="server returned 404: 404 page not found\n"12462026/10/06 21:14:56 WARN Failed to register uploaded object key=xpw83xbgywfwm7b2pxww2mxl8166pmp3.narinfo error="server returned 404: 404 page not found\n"12472026/10/06 21:14:56 INFO Upload complete. (260ms)1248=== NAME TestClientSharedPathCommittedMidPush1249 client_integration_test.go:680: Retrieved narinfo from S3:1250 StorePath: /nix/var/nix/builds/nix-28191-160554113/TestClientSharedPathCommittedMidPush3692372182/001/store/sfad8pk3m2i0xp609l5y33gidm1v1n29-shared-dep1251 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1252 Compression: zstd1253 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821254 NarSize: 1361255 References: 1256 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1257 client_integration_test.go:680: Retrieved narinfo from S3:1258 StorePath: /nix/var/nix/builds/nix-28191-160554113/TestClientSharedPathCommittedMidPush3692372182/001/store/xpw83xbgywfwm7b2pxww2mxl8166pmp3-top1259 URL: nar/15ksqr52yziy1f1bgrv20xfy3zvsrqraj4fjxbc1a02cq4ysh869.nar.zst1260 Compression: zstd1261 NarHash: sha256:15ksqr52yziy1f1bgrv20xfy3zvsrqraj4fjxbc1a02cq4ysh8691262 NarSize: 2561263 References: /nix/var/nix/builds/nix-28191-160554113/TestClientSharedPathCommittedMidPush3692372182/001/store/sfad8pk3m2i0xp609l5y33gidm1v1n29-shared-dep1264 CA: text:sha256:15kynb24m7mvfkssw5gcx138a3fb7q65kr2ik9d05wr56raxdyyj1265--- PASS: TestGCBugBareHashReferences (2.77s)1266=== CONT TestClientPushesUseOnePush1267--- PASS: TestClientSharedPathCommittedMidPush (3.72s)1268=== CONT TestPinProtectsFromGC12692026/10/06 21:14:56 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_nixbld16 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1270--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (2.36s)1271=== CONT TestSweepSkipsRowsLockedByPush12722026/10/06 21:14:56 INFO lead: acquired remote=192.0.2.1:123412732026/10/06 21:14:56 INFO lead: released remote=192.0.2.1:12341274--- PASS: TestLeadIncumbentAnnouncesAtOnce (2.24s)1275=== CONT TestGCTaskStore_CompletedAllowsNewTask1276--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1277=== CONT TestGCTaskStore_Fail1278--- PASS: TestGCTaskStore_Fail (0.00s)1279=== CONT TestGCTaskStore_PhaseUpdates1280--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1281=== CONT TestGCSweepDeliversEachKeyOnce12822026/10/06 21:14:57 INFO lead: acquired remote=192.0.2.1:123412832026/10/06 21:14:57 INFO lead: acquired remote=192.0.2.1:123412842026/10/06 21:14:58 INFO lead: released remote=192.0.2.1:12341285--- PASS: TestLeadEndsOnShutdown (3.83s)1286=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection12872026/10/06 21:14:58 INFO lead: released remote=192.0.2.1:123412882026/10/06 21:14:59 INFO lead: acquired remote=192.0.2.1:123412892026/10/06 21:15:00 INFO lead: released remote=192.0.2.1:12341290--- PASS: TestLeadElectsOneAndHandsOver (4.83s)1291=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded12922026/10/06 21:15:00 INFO Aborted multipart uploads count=0 kept=012932026/10/06 21:15:00 WARN Force mode enabled - objects will be deleted immediately without grace period12942026/10/06 21:15:00 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=012952026/10/06 21:15:00 INFO Vacuumed table table=pending_closures12962026/10/06 21:15:00 INFO Vacuumed table table=pending_objects12972026/10/06 21:15:00 INFO Vacuumed table table=multipart_uploads12982026/10/06 21:15:00 INFO Vacuumed table table=closures12992026/10/06 21:15:00 INFO Vacuumed table table=objects13002026/10/06 21:15:00 INFO Aborted multipart uploads count=0 kept=013012026/10/06 21:15:00 WARN Force mode enabled - objects will be deleted immediately without grace period13022026/10/06 21:15:00 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=013032026/10/06 21:15:00 INFO Vacuumed table table=pending_closures13042026/10/06 21:15:00 INFO Vacuumed table table=pending_objects13052026/10/06 21:15:00 INFO Vacuumed table table=multipart_uploads13062026/10/06 21:15:00 INFO Vacuumed table table=closures13072026/10/06 21:15:00 INFO Vacuumed table table=objects1308--- PASS: TestSweepSkipsRowsLockedByPush (3.76s)1309=== CONT TestObjectStatsTrigger13102026/10/06 21:15:00 INFO Received uploads request method=POST path=/api/pending_closures13112026/10/06 21:15:00 INFO Received uploads request method=POST path=/api/pending_closures13122026/10/06 21:15:00 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13132026/10/06 21:15:00 INFO Uploading ph2y7ak3x0qsv1mza1r7lbmxhqc1p55v-b (248B)13142026/10/06 21:15:00 INFO Uploading h052bzl31lynjjmz80ijv03fwfn1kdhb-shared-dep (136B)13152026/10/06 21:15:00 WARN Failed to register uploaded object key=ph2y7ak3x0qsv1mza1r7lbmxhqc1p55v.ls error="server returned 404: 404 page not found\n"13162026/10/06 21:15:00 WARN Failed to register uploaded object key=h052bzl31lynjjmz80ijv03fwfn1kdhb.ls error="server returned 404: 404 page not found\n"13172026/10/06 21:15:00 WARN Failed to register uploaded object key=6a2vxk5424pbfclvddngz84xh83x57ma.ls error="server returned 404: 404 page not found\n"13182026/10/06 21:15:00 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13192026/10/06 21:15:00 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13202026/10/06 21:15:00 WARN Failed to register uploaded object key=nar/1286bf7vj03q4511zzsnrmisdjsyr75m26pbah6jfbpyrxsbb0gq.nar.zst error="server returned 404: 404 page not found\n"13212026/10/06 21:15:00 INFO Signed narinfos id=1 count=213222026/10/06 21:15:00 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13232026/10/06 21:15:00 INFO Signed narinfos id=2 count=213242026/10/06 21:15:00 INFO Uploading 4 narinfos13252026/10/06 21:15:00 WARN Failed to register uploaded object key=6a2vxk5424pbfclvddngz84xh83x57ma.narinfo error="server returned 404: 404 page not found\n"13262026/10/06 21:15:00 WARN Failed to register uploaded object key=h052bzl31lynjjmz80ijv03fwfn1kdhb.narinfo error="server returned 404: 404 page not found\n"13272026/10/06 21:15:00 WARN Failed to register uploaded object key=ph2y7ak3x0qsv1mza1r7lbmxhqc1p55v.narinfo error="server returned 404: 404 page not found\n"13282026/10/06 21:15:00 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13292026/10/06 21:15:00 WARN Failed to register uploaded object key=h052bzl31lynjjmz80ijv03fwfn1kdhb.narinfo error="server returned 404: 404 page not found\n"13302026/10/06 21:15:00 INFO Completed upload id=113312026/10/06 21:15:00 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13322026/10/06 21:15:00 INFO Completed upload id=213332026/10/06 21:15:00 INFO Upload complete. (640ms)1334=== NAME TestClientFallsBackToClosures1335 client_pushes_test.go:112: Retrieved narinfo from S3:1336 StorePath: /nix/var/nix/builds/nix-28191-160554113/TestClientFallsBackToClosures4028733115/001/store/h052bzl31lynjjmz80ijv03fwfn1kdhb-shared-dep1337 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1338 Compression: zstd1339 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821340 NarSize: 1361341 References: 1342 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1343 client_pushes_test.go:112: Retrieved narinfo from S3:1344 StorePath: /nix/var/nix/builds/nix-28191-160554113/TestClientFallsBackToClosures4028733115/001/store/6a2vxk5424pbfclvddngz84xh83x57ma-a1345 URL: nar/1286bf7vj03q4511zzsnrmisdjsyr75m26pbah6jfbpyrxsbb0gq.nar.zst1346 Compression: zstd1347 NarHash: sha256:1286bf7vj03q4511zzsnrmisdjsyr75m26pbah6jfbpyrxsbb0gq1348 NarSize: 2481349 References: /nix/var/nix/builds/nix-28191-160554113/TestClientFallsBackToClosures4028733115/001/store/h052bzl31lynjjmz80ijv03fwfn1kdhb-shared-dep1350 CA: text:sha256:0nx4x35imgmq4z625n22cq3m0gsnjh3f2na7vccg2ppw6173w81j1351 client_pushes_test.go:112: Retrieved narinfo from S3:1352 StorePath: /nix/var/nix/builds/nix-28191-160554113/TestClientFallsBackToClosures4028733115/001/store/ph2y7ak3x0qsv1mza1r7lbmxhqc1p55v-b1353 URL: nar/1286bf7vj03q4511zzsnrmisdjsyr75m26pbah6jfbpyrxsbb0gq.nar.zst1354 Compression: zstd1355 NarHash: sha256:1286bf7vj03q4511zzsnrmisdjsyr75m26pbah6jfbpyrxsbb0gq1356 NarSize: 2481357 References: /nix/var/nix/builds/nix-28191-160554113/TestClientFallsBackToClosures4028733115/001/store/h052bzl31lynjjmz80ijv03fwfn1kdhb-shared-dep1358 CA: text:sha256:0nx4x35imgmq4z625n22cq3m0gsnjh3f2na7vccg2ppw6173w81j1359--- PASS: TestClientFallsBackToClosures (4.84s)1360=== CONT TestPendingCleanupUsesOneCutoff1361--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (5.05s)1362=== CONT TestGCTaskStore_GetEmpty1363--- PASS: TestGCTaskStore_GetEmpty (0.00s)1364=== CONT TestGCTaskStore_GetReturnsLatest1365--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1366=== CONT TestServerTLSConfig/not_a_PEM_file1367=== CONT TestMultipartCleanup1368=== NAME TestPinProtectsFromGC1369 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-28191-160554113/TestPinProtectsFromGC1842848306/001/store/9ya9h6nxrabb23gllip1awf6ddcvq5c7-pinned-file.txt1370 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-28191-160554113/TestPinProtectsFromGC1842848306/001/store/gsshy8z7ng1g68kcry1gijv8ngicc415-unpinned-file.txt13712026/10/06 21:15:01 INFO Aborted multipart uploads count=0 kept=013722026/10/06 21:15:01 WARN Force mode enabled - objects will be deleted immediately without grace period13732026/10/06 21:15:01 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=013742026/10/06 21:15:01 INFO Vacuumed table table=pending_closures13752026/10/06 21:15:01 INFO Vacuumed table table=pending_objects13762026/10/06 21:15:01 INFO Vacuumed table table=multipart_uploads13772026/10/06 21:15:01 INFO Vacuumed table table=closures13782026/10/06 21:15:01 INFO Vacuumed table table=objects1379--- PASS: TestGCSweepDeliversEachKeyOnce (5.03s)1380=== CONT TestGCTaskStore_ConflictDifferentParams1381--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1382=== CONT TestServerTLSConfig/missing_CA_file1383--- PASS: TestServerTLSConfig (0.00s)1384 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1385 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.04s)1386 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1387=== CONT TestFailedS3DeleteKeepsTombstone13882026/10/06 21:15:02 INFO Received uploads request method=POST path=/api/pending_closures13892026/10/06 21:15:02 INFO Received push request method=POST path=/api/pushes13902026/10/06 21:15:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13912026/10/06 21:15:02 INFO Uploading 9ya9h6nxrabb23gllip1awf6ddcvq5c7-pinned-file.txt (128B)13922026/10/06 21:15:02 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"13932026/10/06 21:15:02 WARN Failed to register uploaded object key=9ya9h6nxrabb23gllip1awf6ddcvq5c7.ls error="server returned 404: 404 page not found\n"13942026/10/06 21:15:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13952026/10/06 21:15:02 INFO Signed narinfos id=1 count=113962026/10/06 21:15:02 INFO Uploading 1 narinfos13972026/10/06 21:15:02 INFO Received complete push request method=POST path=/api/pushes/1/complete13982026/10/06 21:15:02 WARN Failed to register uploaded object key=9ya9h6nxrabb23gllip1awf6ddcvq5c7.narinfo error="server returned 404: 404 page not found\n"13992026/10/06 21:15:02 INFO Upload complete. (684ms)1400--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (3.94s)1401=== CONT TestTombstonedObjectOfferedWithoutWaiting14022026/10/06 21:15:02 INFO Received uploads request method=POST path=/api/pending_closures1403--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (2.83s)1404=== CONT TestCacheConfigHandler1405=== RUN TestCacheConfigHandler/full_config,_no_issuer1406=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1407=== RUN TestCacheConfigHandler/no_cache_url_configured1408=== PAUSE TestCacheConfigHandler/no_cache_url_configured1409=== RUN TestCacheConfigHandler/no_signing_keys1410=== PAUSE TestCacheConfigHandler/no_signing_keys1411=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1412=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1413=== CONT TestClientWithDependencies14142026/10/06 21:15:02 INFO Received push request method=POST path=/api/pushes14152026/10/06 21:15:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14162026/10/06 21:15:02 INFO Uploading gsshy8z7ng1g68kcry1gijv8ngicc415-unpinned-file.txt (128B)14172026/10/06 21:15:03 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"14182026/10/06 21:15:03 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign14192026/10/06 21:15:03 WARN Failed to register uploaded object key=gsshy8z7ng1g68kcry1gijv8ngicc415.ls error="server returned 404: 404 page not found\n"14202026/10/06 21:15:03 INFO Signed narinfos id=2 count=114212026/10/06 21:15:03 INFO Uploading 1 narinfos14222026/10/06 21:15:03 INFO Received complete push request method=POST path=/api/pushes/2/complete14232026/10/06 21:15:03 WARN Failed to register uploaded object key=gsshy8z7ng1g68kcry1gijv8ngicc415.narinfo error="server returned 404: 404 page not found\n"14242026/10/06 21:15:03 INFO Upload complete. (408ms)14252026/10/06 21:15:03 INFO Received push request method=POST path=/api/pushes14262026/10/06 21:15:03 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14272026/10/06 21:15:03 INFO Uploading h5zbwbyyi0nfq4n6rs3hmyxgxj28acga-a (248B)14282026/10/06 21:15:03 INFO Uploading zb7znabpfa53h7mdbzqpbz3vv7d89imb-shared-dep (136B)14292026/10/06 21:15:03 WARN Failed to register uploaded object key=zb7znabpfa53h7mdbzqpbz3vv7d89imb.ls error="server returned 404: 404 page not found\n"14302026/10/06 21:15:03 WARN Failed to register uploaded object key=nar/0cdr8iji03j4a40ls5n36hiz4i5sh67spc4yd6lgijqskqzfrfjq.nar.zst error="server returned 404: 404 page not found\n"14312026/10/06 21:15:03 WARN Failed to register uploaded object key=h5zbwbyyi0nfq4n6rs3hmyxgxj28acga.ls error="server returned 404: 404 page not found\n"14322026/10/06 21:15:03 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14332026/10/06 21:15:03 WARN Failed to register uploaded object key=7b33wlljybx2x9v9paaidkfjwgw2c20p.ls error="server returned 404: 404 page not found\n"14342026/10/06 21:15:03 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14352026/10/06 21:15:03 INFO Signed narinfos id=1 count=314362026/10/06 21:15:03 INFO Uploading 3 narinfos1437--- PASS: TestConnectWaitsForAPeerMigration (7.65s)1438=== CONT TestClientMultipleUploads14392026/10/06 21:15:03 WARN Failed to register uploaded object key=zb7znabpfa53h7mdbzqpbz3vv7d89imb.narinfo error="server returned 404: 404 page not found\n"14402026/10/06 21:15:03 WARN Failed to register uploaded object key=7b33wlljybx2x9v9paaidkfjwgw2c20p.narinfo error="server returned 404: 404 page not found\n"14412026/10/06 21:15:03 INFO Received complete push request method=POST path=/api/pushes/1/complete14422026/10/06 21:15:03 WARN Failed to register uploaded object key=h5zbwbyyi0nfq4n6rs3hmyxgxj28acga.narinfo error="server returned 404: 404 page not found\n"14432026/10/06 21:15:03 INFO Starting cleanup of old closures method=DELETE path=/api/closures14442026/10/06 21:15:03 INFO Garbage collection started14452026/10/06 21:15:03 INFO Upload complete. (371ms)1446=== NAME TestClientPushesUseOnePush1447 client_pushes_test.go:97: Retrieved narinfo from S3:1448 StorePath: /nix/var/nix/builds/nix-28191-160554113/TestClientPushesUseOnePush320080959/001/store/zb7znabpfa53h7mdbzqpbz3vv7d89imb-shared-dep1449 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1450 Compression: zstd1451 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821452 NarSize: 1361453 References: 1454 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1455 client_pushes_test.go:97: Retrieved narinfo from S3:1456 StorePath: /nix/var/nix/builds/nix-28191-160554113/TestClientPushesUseOnePush320080959/001/store/h5zbwbyyi0nfq4n6rs3hmyxgxj28acga-a1457 URL: nar/0cdr8iji03j4a40ls5n36hiz4i5sh67spc4yd6lgijqskqzfrfjq.nar.zst1458 Compression: zstd1459 NarHash: sha256:0cdr8iji03j4a40ls5n36hiz4i5sh67spc4yd6lgijqskqzfrfjq1460 NarSize: 2481461 References: /nix/var/nix/builds/nix-28191-160554113/TestClientPushesUseOnePush320080959/001/store/zb7znabpfa53h7mdbzqpbz3vv7d89imb-shared-dep1462 CA: text:sha256:1axk8la97r90r1hk632rbc27l62kcdxkn65xb158h84f02ryvhdw1463 client_pushes_test.go:97: Retrieved narinfo from S3:1464 StorePath: /nix/var/nix/builds/nix-28191-160554113/TestClientPushesUseOnePush320080959/001/store/7b33wlljybx2x9v9paaidkfjwgw2c20p-b1465 URL: nar/0cdr8iji03j4a40ls5n36hiz4i5sh67spc4yd6lgijqskqzfrfjq.nar.zst1466 Compression: zstd1467 NarHash: sha256:0cdr8iji03j4a40ls5n36hiz4i5sh67spc4yd6lgijqskqzfrfjq1468 NarSize: 2481469 References: /nix/var/nix/builds/nix-28191-160554113/TestClientPushesUseOnePush320080959/001/store/zb7znabpfa53h7mdbzqpbz3vv7d89imb-shared-dep1470 CA: text:sha256:1axk8la97r90r1hk632rbc27l62kcdxkn65xb158h84f02ryvhdw14712026/10/06 21:15:03 INFO Aborted multipart uploads count=0 kept=014722026/10/06 21:15:03 WARN Force mode enabled - objects will be deleted immediately without grace period1473--- PASS: TestClientPushesUseOnePush (6.85s)1474=== CONT TestClientIntegration1475--- PASS: TestObjectStatsTrigger (2.98s)1476=== CONT TestClientErrorHandling1477=== RUN TestClientErrorHandling/InvalidStorePath1478=== PAUSE TestClientErrorHandling/InvalidStorePath1479=== RUN TestClientErrorHandling/InvalidAuthToken1480=== PAUSE TestClientErrorHandling/InvalidAuthToken1481=== RUN TestClientErrorHandling/ServerNotAvailable1482=== PAUSE TestClientErrorHandling/ServerNotAvailable1483=== CONT TestClientCADerivations14842026/10/06 21:15:03 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=01485=== NAME TestOrphanedObjectsGCStressTest1486 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains14872026/10/06 21:15:03 INFO Vacuumed table table=pending_closures14882026/10/06 21:15:03 INFO Vacuumed table table=pending_objects14892026/10/06 21:15:03 INFO Vacuumed table table=multipart_uploads14902026/10/06 21:15:03 INFO Vacuumed table table=closures1491 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion14922026/10/06 21:15:03 INFO Vacuumed table table=objects14932026/10/06 21:15:03 INFO Received uploads request method=POST path=/api/pending_closures14942026/10/06 21:15:04 INFO Received cleanup request method=DELETE path=/api/pending_closures14952026/10/06 21:15:04 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket70/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""14962026/10/06 21:15:04 INFO Aborted multipart uploads count=0 kept=114972026/10/06 21:15:04 INFO Received cleanup request method=DELETE path=/api/pending_closures14982026/10/06 21:15:04 INFO Aborted multipart uploads count=1 kept=01499--- PASS: TestMultipartCleanup (2.99s)1500=== CONT TestCacheStatsHandler15012026/10/06 21:15:04 INFO Received uploads request method=POST path=/api/pending_closures15022026/10/06 21:15:04 INFO Received uploads request method=POST path=/api/pending_closures15032026/10/06 21:15:04 INFO Received cleanup request method=DELETE path=/api/pending_closures15042026/10/06 21:15:04 INFO Received uploads request method=POST path=/api/pending_closures15052026/10/06 21:15:05 INFO Aborted multipart uploads count=0 kept=015062026/10/06 21:15:05 WARN Force mode enabled - objects will be deleted immediately without grace period15072026/10/06 21:15:05 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."15082026/10/06 21:15:05 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1509--- PASS: TestFailedS3DeleteKeepsTombstone (3.20s)1510=== CONT TestService_AuthMiddleware_OIDC15112026/10/06 21:15:05 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=015122026/10/06 21:15:05 INFO Received create pin request method=POST path=/api/pins/myapp15132026/10/06 21:15:05 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-28191-160554113/TestPinProtectsFromGC1842848306/001/store/9ya9h6nxrabb23gllip1awf6ddcvq5c7-pinned-file.txt narinfo_key=9ya9h6nxrabb23gllip1awf6ddcvq5c7.narinfo15142026/10/06 21:15:05 INFO Starting cleanup of old closures method=DELETE path=/api/closures15152026/10/06 21:15:05 INFO Garbage collection started15162026/10/06 21:15:05 INFO Aborted multipart uploads count=0 kept=015172026/10/06 21:15:05 WARN Force mode enabled - objects will be deleted immediately without grace period15182026/10/06 21:15:05 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=015192026/10/06 21:15:05 INFO Vacuumed table table=pending_closures15202026/10/06 21:15:05 INFO Vacuumed table table=pending_objects15212026/10/06 21:15:05 INFO Vacuumed table table=multipart_uploads15222026/10/06 21:15:05 INFO Received uploads request method=POST path=/api/pending_closures15232026/10/06 21:15:05 INFO Vacuumed table table=closures15242026/10/06 21:15:05 INFO Vacuumed table table=objects1525--- PASS: TestTombstonedObjectOfferedWithoutWaiting (2.97s)1526=== CONT TestService_ReadScope_PublicByDefault1527--- PASS: TestCacheStatsHandler (2.60s)1528=== CONT TestService_RequireScope_OIDC1529=== NAME TestClientMultipleUploads1530 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-28191-160554113/TestClientMultipleUploads2993235529/001/store/nc60ydl85f65qsynasyq2id66sls491b-test-file-0.txt1531--- PASS: TestService_ReadScope_PublicByDefault (1.69s)1532=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1533=== NAME TestClientIntegration1534 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-28191-160554113/TestClientIntegration4220395730/002/store/jkdcwyfn2jz67j3rhmnvb2vw9d9xvkg2-test-file.txt1535=== NAME TestOrphanedObjectsGCStressTest1536 orphaned_objects_gc_test.go:509: Stress test completed successfully:1537 orphaned_objects_gc_test.go:510: - Active objects preserved: 201538 orphaned_objects_gc_test.go:511: - Objects deleted: 2101539 orphaned_objects_gc_test.go:512: - Total GC'd: 2101540--- PASS: TestOrphanedObjectsGCStressTest (14.71s)1541=== CONT TestService_ReadAuthMiddleware1542=== NAME TestPinProtectsFromGC1543 client_integration_test.go:840: Pin successfully protected closure from garbage collection1544--- PASS: TestPinProtectsFromGC (10.83s)1545=== CONT TestService_AuthMiddleware_MTLSProxyHeader1546=== NAME TestClientMultipleUploads1547 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-28191-160554113/TestClientMultipleUploads2993235529/001/store/jy3vr07m8dav60h4m5c84ls68fqf1vcf-test-file-1.txt15482026/10/06 21:15:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49957/oidc1549 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-28191-160554113/TestClientMultipleUploads2993235529/001/store/npy941xr64ncywm1a9gxprqz3bjd7lc4-test-file-2.txt15502026/10/06 21:15:07 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15512026/10/06 21:15:07 WARN mTLS auth: bound subjects configured but subject DN unavailable15522026/10/06 21:15:07 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1553--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.88s)1554=== CONT TestForceGCDuringPushOffersSweptObject1555=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1556=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1557=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1558=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1559=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts15602026/10/06 21:15:07 INFO Received request for more parts method=POST path=/15612026/10/06 21:15:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49964/oidc1562=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15632026/10/06 21:15:07 INFO Received uploads request method=POST path=/1564=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart15652026/10/06 21:15:07 INFO Received complete multipart upload request method=POST path=/15662026/10/06 21:15:08 INFO Received push request method=POST path=/api/pushes15672026/10/06 21:15:08 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15682026/10/06 21:15:08 INFO Uploading jkdcwyfn2jz67j3rhmnvb2vw9d9xvkg2-test-file.txt (152B)15692026/10/06 21:15:08 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15702026/10/06 21:15:08 WARN Failed to register uploaded object key=jkdcwyfn2jz67j3rhmnvb2vw9d9xvkg2.ls error="server returned 404: 404 page not found\n"15712026/10/06 21:15:08 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"15722026/10/06 21:15:08 INFO Signed narinfos id=1 count=115732026/10/06 21:15:08 INFO Uploading 1 narinfos15742026/10/06 21:15:08 INFO Received complete push request method=POST path=/api/pushes/1/complete15752026/10/06 21:15:08 WARN Failed to register uploaded object key=jkdcwyfn2jz67j3rhmnvb2vw9d9xvkg2.narinfo error="server returned 404: 404 page not found\n"15762026/10/06 21:15:08 INFO Upload complete. (785ms)1577--- PASS: TestService_ReadAuthMiddleware (1.13s)1578=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure15792026/10/06 21:15:08 INFO Received uploads request method=POST path=/15802026/10/06 21:15:08 INFO All 1 paths already cached1581=== NAME TestClientIntegration1582 client_integration_test.go:312: Retrieved narinfo from S3:1583 StorePath: /nix/var/nix/builds/nix-28191-160554113/TestClientIntegration4220395730/002/store/jkdcwyfn2jz67j3rhmnvb2vw9d9xvkg2-test-file.txt1584 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1585 Compression: zstd1586 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11587 NarSize: 1521588 References: 1589 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11590 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1591 client_integration_test.go:313: Decompressed .ls content (64 bytes):1592 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1593 client_integration_test.go:316: Testing garbage collection...1594=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15952026/10/06 21:15:08 INFO Received complete multipart upload request method=POST path=/1596=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15972026/10/06 21:15:08 INFO Received request for more parts method=POST path=/1598=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15992026/10/06 21:15:08 INFO Received uploads request method=POST path=/1600--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1601 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1602 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1603 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1604 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1605=== CONT TestIsValidUploadKey/narinfo1606=== CONT TestIsValidUploadKey/realisation_plus_in_output1607=== CONT TestIsValidUploadKey/unknown_type1608=== CONT TestIsValidUploadKey/empty_key1609=== CONT TestIsValidUploadKey/absolute1610=== CONT TestIsValidUploadKey/traversal_nar1611=== CONT TestIsValidUploadKey/traversal1612=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1613=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1614=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1615=== CONT TestIsValidUploadKey/index.html1616=== CONT TestIsValidUploadKey/nix-cache-info1617=== CONT TestIsValidUploadKey/build_log_home-manager_file1618=== CONT TestIsValidUploadKey/build_log_question_mark1619=== CONT TestIsValidUploadKey/build_log_plus_in_name1620=== CONT TestIsValidUploadKey/realisation1621=== CONT TestIsValidUploadKey/build_log_equals1622=== CONT TestIsValidUploadKey/nar_plain1623=== CONT TestPendingClosureWriteTimeout/empty1624=== CONT TestIsValidUploadKey/nar_xz1625=== CONT TestIsValidUploadKey/build_log1626=== CONT TestIsValidUploadKey/listing1627=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1628{"timestamp":"2026-10-06T21:15:08.758085Z","level":"ERROR","message":"Scanner cycle completed without a durable data usage snapshot","event":"scanner_persist_state","component":"scanner","subsystem":"runtime","cycle":5,"outcome":"NoUpdate","state":"usage_not_durable","target":"rustfs::scanner","filename":"crates/scanner/src/scanner.rs","line_number":2350,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}1629=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1630=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1631=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1632=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1633=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1634=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1635=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1636=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1637=== CONT TestIsValidUploadKey/nar_zst1638--- PASS: TestIsValidUploadKey (0.00s)1639 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1640 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1641 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1642 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1643 --- PASS: TestIsValidUploadKey/absolute (0.00s)1644 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1645 --- PASS: TestIsValidUploadKey/traversal (0.00s)1646 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1647 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1648 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1649 --- PASS: TestIsValidUploadKey/index.html (0.00s)1650 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1651 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1652 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1653 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1654 --- PASS: TestIsValidUploadKey/realisation (0.00s)1655 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1656 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1657 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1658 --- PASS: TestIsValidUploadKey/build_log (0.00s)1659 --- PASS: TestIsValidUploadKey/listing (0.00s)1660 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1661=== CONT TestPendingClosureWriteTimeout/670k_objects1662=== CONT TestPendingClosureWriteTimeout/400_objects1663=== CONT TestProxyWriteTimeout/narinfo1664=== CONT TestProxyWriteTimeout/10_GiB_nar1665=== CONT TestProxyWriteTimeout/unknown_size1666=== CONT TestProxyWriteTimeout/1_GiB_nar1667--- PASS: TestProxyWriteTimeout (0.00s)1668 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1669 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1670 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1671 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1672=== CONT TestPush_RejectsBadRequests/no_roots16732026/10/06 21:15:08 INFO Received push request method=POST path=/api/pushes1674=== CONT TestPush_RejectsBadRequests/bad_root16752026/10/06 21:15:08 INFO Received push request method=POST path=/api/pushes1676=== CONT TestPush_RejectsBadRequests/root_not_in_objects16772026/10/06 21:15:08 INFO Received push request method=POST path=/api/pushes1678=== CONT TestPush_RejectsBadRequests/no_objects16792026/10/06 21:15:08 INFO Received push request method=POST path=/api/pushes1680--- PASS: TestPush_RejectsBadRequests (4.52s)1681 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1682 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1683 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1684 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1685=== CONT TestGCEndsOnShutdown/before_the_run16862026/10/06 21:15:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures16872026/10/06 21:15:09 INFO Garbage collection started16882026/10/06 21:15:09 INFO Aborted multipart uploads count=0 kept=016892026/10/06 21:15:09 WARN Force mode enabled - objects will be deleted immediately without grace period16902026/10/06 21:15:09 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=016912026/10/06 21:15:09 INFO Vacuumed table table=pending_closures16922026/10/06 21:15:09 INFO Vacuumed table table=pending_objects16932026/10/06 21:15:09 INFO Vacuumed table table=multipart_uploads16942026/10/06 21:15:09 INFO Vacuumed table table=closures16952026/10/06 21:15:09 INFO Received push request method=POST path=/api/pushes16962026/10/06 21:15:09 INFO Vacuumed table table=objects16972026/10/06 21:15:09 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16982026/10/06 21:15:09 INFO Uploading npy941xr64ncywm1a9gxprqz3bjd7lc4-test-file-2.txt (160B)16992026/10/06 21:15:09 INFO Uploading jy3vr07m8dav60h4m5c84ls68fqf1vcf-test-file-1.txt (160B)17002026/10/06 21:15:09 INFO Uploading nc60ydl85f65qsynasyq2id66sls491b-test-file-0.txt (160B)17012026/10/06 21:15:09 WARN Failed to register uploaded object key=jy3vr07m8dav60h4m5c84ls68fqf1vcf.ls error="server returned 404: 404 page not found\n"17022026/10/06 21:15:09 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"17032026/10/06 21:15:09 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"17042026/10/06 21:15:09 WARN Failed to register uploaded object key=npy941xr64ncywm1a9gxprqz3bjd7lc4.ls error="server returned 404: 404 page not found\n"17052026/10/06 21:15:09 WARN Failed to register uploaded object key=nc60ydl85f65qsynasyq2id66sls491b.ls error="server returned 404: 404 page not found\n"17062026/10/06 21:15:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17072026/10/06 21:15:09 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"17082026/10/06 21:15:09 INFO Signed narinfos id=1 count=317092026/10/06 21:15:09 INFO Uploading 3 narinfos17102026/10/06 21:15:09 WARN Failed to register uploaded object key=nc60ydl85f65qsynasyq2id66sls491b.narinfo error="server returned 404: 404 page not found\n"17112026/10/06 21:15:09 INFO Received complete push request method=POST path=/api/pushes/1/complete17122026/10/06 21:15:09 WARN Failed to register uploaded object key=npy941xr64ncywm1a9gxprqz3bjd7lc4.narinfo error="server returned 404: 404 page not found\n"17132026/10/06 21:15:09 WARN Failed to register uploaded object key=jy3vr07m8dav60h4m5c84ls68fqf1vcf.narinfo error="server returned 404: 404 page not found\n"1714--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (1.96s)1715=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark17162026/10/06 21:15:09 INFO Upload complete. (806ms)1717=== NAME TestClientMultipleUploads1718 client_integration_test.go:369: Uploaded 3 paths in 1.508425458s1719--- PASS: TestClientMultipleUploads (6.21s)1720=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1721=== NAME TestClientWithDependencies1722 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-28191-160554113/TestClientWithDependencies2684445281/001/store/ygq3f2dnb4za492d17sj0vn3r735kdhd-test-script1723=== NAME TestClientCADerivations1724 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-28191-160554113/TestClientCADerivations770564985/001/store/6ymz7cnwc2pvd5r6kmazayx8vnpq78b2-ca-test1725=== RUN TestService_RequireScope_OIDC/builder_may_write1726=== PAUSE TestService_RequireScope_OIDC/builder_may_write1727=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1728=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1729=== RUN TestService_RequireScope_OIDC/ops_may_admin1730=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1731=== RUN TestService_RequireScope_OIDC/ops_may_not_write1732=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1733=== RUN TestService_RequireScope_OIDC/reader_may_not_write1734=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1735=== RUN TestService_RequireScope_OIDC/static_token_may_admin1736=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1737=== RUN TestService_RequireScope_OIDC/static_token_may_write1738=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1739=== RUN TestService_RequireScope_OIDC/reader_may_read1740=== PAUSE TestService_RequireScope_OIDC/reader_may_read1741=== RUN TestService_RequireScope_OIDC/writer_implies_read1742=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1743=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1744=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1745=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1746=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1747=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1748=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1749=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1750=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1751=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1752=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1753=== CONT TestIsValidCachePath/narinfo1754=== CONT TestIsValidCachePath/nar_uncompressed1755=== CONT TestIsValidCachePath/nix-cache-info1756=== CONT TestIsValidCachePath/realisation1757=== CONT TestIsValidCachePath/log1758=== CONT TestIsValidCachePath/ls1759=== CONT TestIsValidCachePath/nar_xz1760=== CONT TestIsValidCachePath/nar_bz21761=== CONT TestIsValidCachePath/random_path1762=== CONT TestIsValidCachePath/short_hash1763=== CONT TestIsValidCachePath/wrong_extension1764=== CONT TestIsValidCachePath/leading_slash1765=== CONT TestIsValidCachePath/empty1766=== CONT TestIsValidCachePath/invalid_char_e1767=== CONT TestIsValidCachePath/invalid_char_u1768=== CONT TestIsValidCachePath/nar_zst1769=== CONT TestIsValidCachePath/traversal_in_middle1770=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1771=== CONT TestIsValidCachePath/traversal_parent1772=== CONT TestIsValidCachePath/index.html1773--- PASS: TestIsValidCachePath (0.00s)1774 --- PASS: TestIsValidCachePath/narinfo (0.00s)1775 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1776 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1777 --- PASS: TestIsValidCachePath/realisation (0.00s)1778 --- PASS: TestIsValidCachePath/log (0.00s)1779 --- PASS: TestIsValidCachePath/ls (0.00s)1780 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1781 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1782 --- PASS: TestIsValidCachePath/random_path (0.00s)1783 --- PASS: TestIsValidCachePath/short_hash (0.00s)1784 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1785 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1786 --- PASS: TestIsValidCachePath/empty (0.00s)1787 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1788 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1789 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1790 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1791 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1792 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1793 --- PASS: TestIsValidCachePath/index.html (0.00s)1794=== CONT TestParseSingleRange/none1795=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1796=== NAME TestClientWithDependencies1797 client_integration_test.go:615: Found 1 dependencies (including self)1798=== NAME TestClientCADerivations1799 client_ca_test.go:139: Found 1 dependencies (including self)18002026/10/06 21:15:10 INFO Received uploads request method=POST path=/api/pending_closures18012026/10/06 21:15:10 INFO Received push request method=POST path=/api/pushes18022026/10/06 21:15:10 INFO Received push request method=POST path=/api/pushes18032026/10/06 21:15:10 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18042026/10/06 21:15:10 INFO Uploading 6ymz7cnwc2pvd5r6kmazayx8vnpq78b2-ca-test (144B)18052026/10/06 21:15:10 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18062026/10/06 21:15:10 INFO Uploading ygq3f2dnb4za492d17sj0vn3r735kdhd-test-script (136B)18072026/10/06 21:15:10 WARN Failed to register uploaded object key=ygq3f2dnb4za492d17sj0vn3r735kdhd.ls error="server returned 404: 404 page not found\n"18082026/10/06 21:15:10 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18092026/10/06 21:15:10 WARN Failed to register uploaded object key=6ymz7cnwc2pvd5r6kmazayx8vnpq78b2.ls error="server returned 404: 404 page not found\n"18102026/10/06 21:15:10 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"18112026/10/06 21:15:10 WARN Failed to register uploaded object key=log/kkxsv8dzsfpwn9d5yzwj25fjdpsc16ln-test-script.drv error="server returned 404: 404 page not found\n"18122026/10/06 21:15:10 WARN Failed to register uploaded object key=log/4bw4pjyagyk48fa4nqi6z0f24qccqqq3-ca-test.drv error="server returned 404: 404 page not found\n"18132026/10/06 21:15:10 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18142026/10/06 21:15:10 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18152026/10/06 21:15:10 INFO Signed narinfos id=1 count=118162026/10/06 21:15:10 INFO Signed narinfos id=1 count=118172026/10/06 21:15:10 INFO Uploading 1 narinfos18182026/10/06 21:15:10 INFO Uploading 1 narinfos18192026/10/06 21:15:10 INFO Aborted multipart uploads count=1 kept=018202026/10/06 21:15:10 INFO Received cleanup request method=DELETE path=/api/pending_closures18212026/10/06 21:15:10 INFO Aborted multipart uploads count=1 kept=018222026/10/06 21:15:10 INFO Received complete push request method=POST path=/api/pushes/1/complete18232026/10/06 21:15:10 WARN Failed to register uploaded object key=ygq3f2dnb4za492d17sj0vn3r735kdhd.narinfo error="server returned 404: 404 page not found\n"18242026/10/06 21:15:10 INFO Received complete push request method=POST path=/api/pushes/1/complete18252026/10/06 21:15:10 WARN Failed to register uploaded object key=6ymz7cnwc2pvd5r6kmazayx8vnpq78b2.narinfo error="server returned 404: 404 page not found\n"1826--- PASS: TestPendingCleanupUsesOneCutoff (9.62s)1827=== CONT TestParseSingleRange/start_far_past_EOF1828=== CONT TestParseSingleRange/start_past_EOF1829=== CONT TestParseSingleRange/single_byte1830=== CONT TestParseSingleRange/suffix_exceeds_size1831=== CONT TestParseSingleRange/suffix1832=== CONT TestParseSingleRange/end_clamped_to_size1833=== CONT TestParseSingleRange/open-ended1834=== CONT TestParseSingleRange/closed1835=== CONT TestParseSingleRange/malformed_end_before_start1836=== CONT TestParseSingleRange/unknown_unit1837=== CONT TestParseSingleRange/multi-range_ignored1838=== CONT TestParseSingleRange/malformed_both_empty1839=== CONT TestParseSingleRange/malformed_no_dash1840--- PASS: TestParseSingleRange (0.00s)1841 --- PASS: TestParseSingleRange/none (0.00s)1842 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1843 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1844 --- PASS: TestParseSingleRange/single_byte (0.00s)1845 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1846 --- PASS: TestParseSingleRange/suffix (0.00s)1847 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1848 --- PASS: TestParseSingleRange/open-ended (0.00s)1849 --- PASS: TestParseSingleRange/closed (0.00s)1850 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1851 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1852 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1853 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1854 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1855=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh18562026/10/06 21:15:10 INFO Upload complete. (454ms)1857=== CONT TestResolveDBConnectionString/flag_wins1858=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1859=== CONT TestResolveDBConnectionString/nothing_configured1860=== CONT TestResolveDBConnectionString/missing_file_is_an_error1861=== CONT TestResolveDBConnectionString/file_when_flag_empty1862=== CONT TestCacheConfigHandler/full_config,_no_issuer1863=== CONT TestCacheConfigHandler/no_signing_keys1864=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1865=== CONT TestCacheConfigHandler/no_cache_url_configured1866=== CONT TestClientErrorHandling/InvalidStorePath1867--- PASS: TestCacheConfigHandler (0.00s)1868 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1869 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1870 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1871 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1872=== NAME TestClientWithDependencies1873 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-28191-160554113/TestClientWithDependencies2684445281/001/store) requires matching store prefix18742026/10/06 21:15:10 INFO Upload complete. (492ms)1875=== NAME TestClientCADerivations1876 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-28191-160554113/TestClientCADerivations770564985/001/store/6ymz7cnwc2pvd5r6kmazayx8vnpq78b2-ca-test1877 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1878 Compression: zstd1879 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1880 NarSize: 1441881 References: 1882 Deriver: /nix/var/nix/builds/nix-28191-160554113/TestClientCADerivations770564985/001/store/4bw4pjyagyk48fa4nqi6z0f24qccqqq3-ca-test.drv1883 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1884 client_ca_test.go:185: Checking for realisation files in S3...1885 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1886 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1887--- PASS: TestResolveDBConnectionString (0.04s)1888 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1889 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1890 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1891 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1892 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1893--- PASS: TestClientWithDependencies (7.75s)1894=== CONT TestClientErrorHandling/ServerNotAvailable1895--- PASS: TestPendingClosureWriteTimeout (0.00s)1896 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)1897 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)1898 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)1899 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (2.41s)1900=== CONT TestClientErrorHandling/InvalidAuthToken19012026/10/06 21:15:10 INFO Aborted multipart uploads count=0 kept=019022026/10/06 21:15:10 WARN Force mode enabled - objects will be deleted immediately without grace period19032026-10-06 21:15:10.998 UTC [33712] ERROR: canceling statement due to user request19042026-10-06 21:15:10.998 UTC [33712] STATEMENT: -- name: MarkStaleObjects :execrows1905 WITH RECURSIVE ct AS (1906 SELECT timezone('UTC', now()) AS now1907 ),1908 closure_reach AS (1909 -- Start with all closure keys1910 SELECT o.key, o.refs1911 FROM objects o1912 INNER JOIN closures c ON o.key = c.key1913 UNION1914 -- Recursively add all referenced objects1915 SELECT o.key, o.refs1916 FROM objects o1917 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)1918 ),1919 reachable_objects AS (1920 SELECT DISTINCT key FROM closure_reach1921 ),1922 stale_objects AS (1923 SELECT o.key1924 FROM objects AS o, ct1925 WHERE1926 NOT EXISTS (1927 SELECT 11928 FROM reachable_objects ro1929 WHERE ro.key = o.key1930 )1931 AND NOT EXISTS (1932 SELECT 11933 FROM pending_objects AS po1934 WHERE po.key = o.key1935 )1936 AND o.deleted_at IS NULL -- Only mark fresh objects1937 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure1938 FOR UPDATE1939 )1940 UPDATE objects1941 SET1942 deleted_at = ct.now,1943 first_deleted_at = COALESCE(first_deleted_at, ct.now)1944 FROM stale_objects, ct1945 WHERE objects.key = stale_objects.key1946 1947=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows19482026/10/06 21:15:11 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01949=== NAME TestClientIntegration1950 client_integration_test.go:323: Objects in database after GC:1951 client_integration_test.go:323: Successfully deleted all objects with GC --force1952=== NAME TestClientCADerivations1953 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket75?endpoint=http://localhost:49482®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-28191-160554113/TestClientCADerivations770564985/001/store'1954 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11955--- PASS: TestClientIntegration (7.79s)1956=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1957--- PASS: TestClientCADerivations (7.85s)1958=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1959=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1960=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19612026/10/06 21:15:11 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]1962=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19632026/10/06 21:15:11 WARN Authentication failed token_preview=eyJhbGciOi...ZwvE9QA4Ww token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1964=== CONT TestService_RequireScope_OIDC/builder_may_write1965=== CONT TestService_RequireScope_OIDC/reader_may_read1966=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1967=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19682026/10/06 21:15:11 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]1969=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1970=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1971=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1972=== CONT TestService_RequireScope_OIDC/writer_implies_read1973=== CONT TestService_RequireScope_OIDC/reader_may_not_write1974=== CONT TestService_RequireScope_OIDC/static_token_may_write1975=== CONT TestService_RequireScope_OIDC/static_token_may_admin1976=== CONT TestService_RequireScope_OIDC/ops_may_admin1977=== CONT TestService_RequireScope_OIDC/ops_may_not_write1978=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1979--- PASS: TestService_RequireScope_OIDC (3.01s)1980 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1981 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1982 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1983 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1984 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1985 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1986 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1987 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1988 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1989 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1990 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1991 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1992 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1993 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1994--- PASS: TestService_AuthMiddleware_OIDC (3.77s)1995 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1996 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1997 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1998 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)19992026/10/06 21:15:11 INFO Aborted multipart uploads count=0 kept=020002026/10/06 21:15:11 WARN Force mode enabled - objects will be deleted immediately without grace period20012026/10/06 21:15:11 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:49482/bucket88/?delete=\": context canceled"2002--- PASS: TestGCEndsOnShutdown (0.00s)2003 --- PASS: TestGCEndsOnShutdown/before_the_run (1.67s)2004 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (1.70s)2005 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (1.85s)20062026/10/06 21:15:11 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20072026/10/06 21:15:11 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=193.850626ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20082026/10/06 21:15:11 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=361.653762ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2009--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)2010 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.08s)2011 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.52s)2012 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (3.70s)20132026/10/06 21:15:12 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=742.572657ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20142026/10/06 21:15:12 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.485838449s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20152026/10/06 21:15:12 INFO Received uploads request method=POST path=/api/pending_closures2016--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2017 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (2.61s)2018 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (2.34s)20192026/10/06 21:15:12 INFO Aborted multipart uploads count=0 kept=020202026/10/06 21:15:12 WARN Force mode enabled - objects will be deleted immediately without grace period20212026/10/06 21:15:12 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=020222026/10/06 21:15:12 INFO Vacuumed table table=pending_closures20232026/10/06 21:15:12 INFO Vacuumed table table=pending_objects20242026/10/06 21:15:13 INFO Vacuumed table table=multipart_uploads20252026/10/06 21:15:13 INFO Vacuumed table table=closures20262026/10/06 21:15:13 INFO Vacuumed table table=objects20272026/10/06 21:15:13 INFO Received uploads request method=POST path=/api/pending_closures20282026/10/06 21:15:13 INFO Aborted multipart uploads count=0 kept=020292026/10/06 21:15:13 WARN Force mode enabled - objects will be deleted immediately without grace period20302026/10/06 21:15:13 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=020312026/10/06 21:15:13 INFO Vacuumed table table=pending_closures20322026/10/06 21:15:13 INFO Vacuumed table table=pending_objects20332026/10/06 21:15:13 INFO Vacuumed table table=multipart_uploads20342026/10/06 21:15:13 INFO Vacuumed table table=closures20352026/10/06 21:15:13 INFO Vacuumed table table=objects20362026/10/06 21:15:13 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2037--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2038 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (1.91s)2039 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (2.55s)20402026/10/06 21:15:13 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20412026/10/06 21:15:14 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20422026/10/06 21:15:14 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=210.415697ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20432026/10/06 21:15:14 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=372.661263ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20442026/10/06 21:15:15 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=769.805869ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20452026/10/06 21:15:16 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.590067783s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2046{"timestamp":"2026-10-06T21:15:17.511158Z","level":"ERROR","message":"Scanner cycle completed without a durable data usage snapshot","event":"scanner_persist_state","component":"scanner","subsystem":"runtime","cycle":5,"outcome":"NoUpdate","state":"usage_not_durable","target":"rustfs::scanner","filename":"crates/scanner/src/scanner.rs","line_number":2350,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}20472026/10/06 21:15:17 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"20482026/10/06 21:15:17 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20492026/10/06 21:15:17 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=211.40642ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20502026/10/06 21:15:17 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=406.217548ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20512026/10/06 21:15:18 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=746.486907ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20522026/10/06 21:15:19 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.465670575s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20532026/10/06 21:15:20 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20542026/10/06 21:15:20 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=205.92648ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20552026/10/06 21:15:20 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=405.904384ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20562026/10/06 21:15:21 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=809.489431ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20572026/10/06 21:15:22 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.66587411s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2058--- PASS: TestClientErrorHandling (0.00s)2059 --- PASS: TestClientErrorHandling/InvalidStorePath (2.11s)2060 --- PASS: TestClientErrorHandling/InvalidAuthToken (2.73s)2061 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.06s)2062PASS2063{"timestamp":"2026-10-06T21:15:23.742681Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:49651","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}20642026-10-06 21:15:24.378 UTC [28836] LOG: received smart shutdown request20652026-10-06 21:15:24.380 UTC [28836] LOG: background worker "logical replication launcher" (PID 28847) exited with exit code 120662026-10-06 21:15:24.390 UTC [28841] LOG: shutting down20672026-10-06 21:15:24.391 UTC [28841] LOG: checkpoint starting: shutdown immediate20682026-10-06 21:15:31.005 UTC [28841] LOG: checkpoint complete: wrote 12395 buffers (75.7%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 27 recycled; write=1.283 s, sync=5.278 s, total=6.601 s; sync files=32013, longest=0.202 s, average=0.001 s; distance=449778 kB, estimate=449778 kB; lsn=0/1CEC9940, redo lsn=0/1CEC994020692026-10-06 21:15:31.019 UTC [28836] LOG: database system is shut down2070Running OIDC tests...2071=== RUN TestAudienceForIssuer2072=== PAUSE TestAudienceForIssuer2073=== RUN TestGlobMatch2074=== PAUSE TestGlobMatch2075=== RUN TestValidateToken_ValidToken2076=== PAUSE TestValidateToken_ValidToken2077=== RUN TestValidateToken_WrongAudience2078=== PAUSE TestValidateToken_WrongAudience2079=== RUN TestValidateToken_Expired2080=== PAUSE TestValidateToken_Expired2081=== RUN TestValidateToken_BoundClaimsMismatch2082=== PAUSE TestValidateToken_BoundClaimsMismatch2083=== RUN TestValidateToken_BoundSubjectMismatch2084=== PAUSE TestValidateToken_BoundSubjectMismatch2085=== RUN TestValidateToken_MultipleProviders2086=== PAUSE TestValidateToken_MultipleProviders2087=== RUN TestValidateToken_NoMatchingProvider2088=== PAUSE TestValidateToken_NoMatchingProvider2089=== RUN TestValidateToken_KubernetesServiceAccount2090=== PAUSE TestValidateToken_KubernetesServiceAccount2091=== RUN TestNewValidator_KubernetesRequiresCA2092=== PAUSE TestNewValidator_KubernetesRequiresCA2093=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2094=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2095=== RUN TestPins_ReservedForMatchingRule2096=== PAUSE TestPins_ReservedForMatchingRule2097=== RUN TestPins_TopLevelShorthand2098=== PAUSE TestPins_TopLevelShorthand2099=== RUN TestPins_ConfigValidation2100=== PAUSE TestPins_ConfigValidation2101=== RUN TestScopes_LegacyProviderDefaultsToWrite2102=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2103=== RUN TestScopes_Rules2104=== PAUSE TestScopes_Rules2105=== RUN TestScopes_ConfigValidation2106=== PAUSE TestScopes_ConfigValidation2107=== CONT TestAudienceForIssuer2108--- PASS: TestAudienceForIssuer (0.00s)2109=== CONT TestScopes_ConfigValidation2110=== CONT TestValidateToken_BoundClaimsMismatch2111=== CONT TestValidateToken_KubernetesServiceAccount2112=== CONT TestValidateToken_MultipleProviders2113=== CONT TestValidateToken_BoundSubjectMismatch2114=== CONT TestValidateToken_WrongAudience2115=== CONT TestValidateToken_Expired2116=== CONT TestValidateToken_ValidToken2117=== CONT TestValidateToken_NoMatchingProvider2118=== CONT TestPins_TopLevelShorthand2119--- PASS: TestScopes_ConfigValidation (0.00s)2120=== CONT TestGlobMatch2121=== RUN TestGlobMatch/foo_foo2122=== PAUSE TestGlobMatch/foo_foo2123=== RUN TestGlobMatch/foo_bar2124=== PAUSE TestGlobMatch/foo_bar2125=== RUN TestGlobMatch/*_2126=== PAUSE TestGlobMatch/*_2127=== RUN TestGlobMatch/*_anything2128=== PAUSE TestGlobMatch/*_anything2129=== RUN TestGlobMatch/foo*_foo2130=== PAUSE TestGlobMatch/foo*_foo2131=== RUN TestGlobMatch/foo*_foobar2132=== PAUSE TestGlobMatch/foo*_foobar2133=== RUN TestGlobMatch/foo*_bar2134=== PAUSE TestGlobMatch/foo*_bar2135=== RUN TestGlobMatch/*bar_bar2136=== PAUSE TestGlobMatch/*bar_bar2137=== RUN TestGlobMatch/*bar_foobar2138=== PAUSE TestGlobMatch/*bar_foobar2139=== RUN TestGlobMatch/*bar_foo2140=== PAUSE TestGlobMatch/*bar_foo2141=== RUN TestGlobMatch/foo*bar_foobar2142=== PAUSE TestGlobMatch/foo*bar_foobar2143=== RUN TestGlobMatch/foo*bar_foo123bar2144=== PAUSE TestGlobMatch/foo*bar_foo123bar2145=== RUN TestGlobMatch/foo*bar_foobarbaz2146=== PAUSE TestGlobMatch/foo*bar_foobarbaz2147=== RUN TestGlobMatch/*/*_foo/bar2148=== PAUSE TestGlobMatch/*/*_foo/bar2149=== RUN TestGlobMatch/*/*_foo2150=== PAUSE TestGlobMatch/*/*_foo2151=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2152=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2153=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02154=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02155=== RUN TestGlobMatch/refs/*/main_refs/heads/main2156=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2157=== RUN TestGlobMatch/fo?_foo2158=== PAUSE TestGlobMatch/fo?_foo2159=== RUN TestGlobMatch/fo?_fo2160=== PAUSE TestGlobMatch/fo?_fo2161=== RUN TestGlobMatch/fo?_fooo2162=== PAUSE TestGlobMatch/fo?_fooo2163=== RUN TestGlobMatch/?oo_foo2164=== PAUSE TestGlobMatch/?oo_foo2165=== RUN TestGlobMatch/?oo_boo2166=== PAUSE TestGlobMatch/?oo_boo2167=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2168=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2169=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2170=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2171=== CONT TestGlobMatch/foo_foo2172=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2173=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2174=== CONT TestGlobMatch/?oo_boo2175=== CONT TestGlobMatch/?oo_foo2176=== CONT TestGlobMatch/fo?_fooo2177=== CONT TestGlobMatch/fo?_fo2178=== CONT TestGlobMatch/fo?_foo2179=== CONT TestGlobMatch/refs/*/main_refs/heads/main2180=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02181=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2182=== CONT TestGlobMatch/*/*_foo2183=== CONT TestGlobMatch/*/*_foo/bar2184=== CONT TestGlobMatch/foo*bar_foobarbaz2185=== CONT TestGlobMatch/foo*bar_foo123bar2186=== CONT TestGlobMatch/foo*bar_foobar2187=== CONT TestGlobMatch/*bar_foo2188=== CONT TestGlobMatch/*bar_foobar2189=== CONT TestGlobMatch/*bar_bar2190=== CONT TestGlobMatch/foo*_bar2191=== CONT TestGlobMatch/foo*_foobar2192=== CONT TestGlobMatch/foo*_foo2193=== CONT TestGlobMatch/*_anything2194=== CONT TestScopes_Rules21952026/10/06 21:15:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50145/oidc2196--- PASS: TestScopes_Rules (0.23s)2197=== CONT TestScopes_LegacyProviderDefaultsToWrite21982026/10/06 21:15:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50148/oidc2199--- PASS: TestPins_TopLevelShorthand (0.55s)2200=== CONT TestPins_ConfigValidation2201--- PASS: TestPins_ConfigValidation (0.00s)2202=== CONT TestGlobMatch/*_2203=== CONT TestGlobMatch/foo_bar2204--- PASS: TestGlobMatch (0.01s)2205 --- PASS: TestGlobMatch/foo_foo (0.00s)2206 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2207 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2208 --- PASS: TestGlobMatch/?oo_boo (0.00s)2209 --- PASS: TestGlobMatch/?oo_foo (0.00s)2210 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2211 --- PASS: TestGlobMatch/fo?_fo (0.00s)2212 --- PASS: TestGlobMatch/fo?_foo (0.00s)2213 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2214 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2215 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2216 --- PASS: TestGlobMatch/*/*_foo (0.00s)2217 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2218 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2219 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2220 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2221 --- PASS: TestGlobMatch/*bar_foo (0.00s)2222 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2223 --- PASS: TestGlobMatch/*bar_bar (0.00s)2224 --- PASS: TestGlobMatch/foo*_bar (0.00s)2225 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2226 --- PASS: TestGlobMatch/foo*_foo (0.00s)2227 --- PASS: TestGlobMatch/*_anything (0.00s)2228 --- PASS: TestGlobMatch/*_ (0.00s)2229 --- PASS: TestGlobMatch/foo_bar (0.00s)2230=== CONT TestPins_ReservedForMatchingRule22312026/10/06 21:15:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50152/oidc22322026/10/06 21:15:36 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:50143/oidc2233--- PASS: TestValidateToken_Expired (0.85s)2234=== CONT TestValidateToken_KubernetesIssuerFromOwnToken22352026/10/06 21:15:36 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:50147/oidc22362026/10/06 21:15:36 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:50153/oidc2237--- PASS: TestValidateToken_NoMatchingProvider (0.85s)2238=== CONT TestNewValidator_KubernetesRequiresCA2239--- PASS: TestValidateToken_MultipleProviders (0.86s)22402026/10/06 21:15:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50157/oidc2241--- PASS: TestValidateToken_WrongAudience (1.05s)22422026/10/06 21:15:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50159/oidc2243--- PASS: TestPins_ReservedForMatchingRule (0.69s)22442026/10/06 21:15:37 http: TLS handshake error from 127.0.0.1:50162: read tcp 127.0.0.1:50161->127.0.0.1:50162: use of closed network connection2245--- PASS: TestNewValidator_KubernetesRequiresCA (0.45s)22462026/10/06 21:15:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50163/oidc22472026/10/06 21:15:37 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232248--- PASS: TestScopes_LegacyProviderDefaultsToWrite (1.26s)2249--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.66s)22502026/10/06 21:15:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50167/oidc22512026/10/06 21:15:37 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:501682252--- PASS: TestValidateToken_BoundClaimsMismatch (1.63s)2253--- PASS: TestValidateToken_KubernetesServiceAccount (1.63s)22542026/10/06 21:15:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50171/oidc2255--- PASS: TestValidateToken_ValidToken (1.68s)22562026/10/06 21:15:38 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50173/oidc2257--- PASS: TestValidateToken_BoundSubjectMismatch (2.20s)2258PASS2259Running hook tests...2260=== RUN TestSendPathsEmpty2261=== PAUSE TestSendPathsEmpty2262=== RUN TestQueueEnqueueAndFetch2263=== PAUSE TestQueueEnqueueAndFetch2264=== RUN TestQueueDeduplication2265=== PAUSE TestQueueDeduplication2266=== RUN TestQueueRemove2267=== PAUSE TestQueueRemove2268=== RUN TestQueueFetchBatchLimit2269=== PAUSE TestQueueFetchBatchLimit2270=== RUN TestQueueRetryMovesToBack2271=== PAUSE TestQueueRetryMovesToBack2272=== RUN TestQueueFetchRemoveLifecycle2273=== PAUSE TestQueueFetchRemoveLifecycle2274=== RUN TestQueueConcurrentWriters2275=== PAUSE TestQueueConcurrentWriters2276=== RUN TestQueueRemoveLargeClosure2277=== PAUSE TestQueueRemoveLargeClosure2278=== RUN TestServerClientIntegration2279=== PAUSE TestServerClientIntegration2280=== RUN TestServerQueueError2281=== PAUSE TestServerQueueError2282=== RUN TestGetListenerSocketActivation2283 server_test.go:210: === RUN TestGetListenerSocketActivation2284 --- PASS: TestGetListenerSocketActivation (0.00s)2285 PASS2286 2287--- PASS: TestGetListenerSocketActivation (0.01s)2288=== RUN TestDrainIsolatesPoisonPath2289=== PAUSE TestDrainIsolatesPoisonPath2290=== RUN TestRunNotBlockedByPoisonHead2291=== PAUSE TestRunNotBlockedByPoisonHead2292=== RUN TestDrainGivesUpWhenServerDown2293=== PAUSE TestDrainGivesUpWhenServerDown2294=== RUN TestFailedPathPrunedByLaterClosure2295=== PAUSE TestFailedPathPrunedByLaterClosure2296=== RUN TestWorkerUploadsAndRemoves2297=== PAUSE TestWorkerUploadsAndRemoves2298=== RUN TestWorkerSkipsGCdPaths2299=== PAUSE TestWorkerSkipsGCdPaths2300=== RUN TestWorkerPrunesClosureDeps2301=== PAUSE TestWorkerPrunesClosureDeps2302=== RUN TestDrainTimeout2303=== PAUSE TestDrainTimeout2304=== CONT TestSendPathsEmpty2305--- PASS: TestSendPathsEmpty (0.00s)2306=== CONT TestQueueFetchBatchLimit2307=== CONT TestDrainTimeout2308=== CONT TestQueueConcurrentWriters2309=== CONT TestServerQueueError2310=== CONT TestQueueRetryMovesToBack2311=== CONT TestQueueDeduplication2312=== CONT TestServerClientIntegration2313=== CONT TestQueueRemoveLargeClosure2314=== CONT TestFailedPathPrunedByLaterClosure2315=== CONT TestQueueRemove23162026/10/06 21:15:38 ERROR Failed to queue paths error="permission denied" count=12317--- PASS: TestServerClientIntegration (0.00s)2318=== CONT TestWorkerPrunesClosureDeps2319--- PASS: TestServerQueueError (0.00s)2320=== CONT TestWorkerSkipsGCdPaths23212026/10/06 21:15:38 INFO Uploading batch count=123222026/10/06 21:15:38 ERROR Upload failed error="upload failed" count=12323--- PASS: TestQueueDeduplication (0.01s)2324=== CONT TestWorkerUploadsAndRemoves23252026/10/06 21:15:38 INFO Uploading batch count=22326--- PASS: TestQueueFetchBatchLimit (0.01s)2327=== CONT TestRunNotBlockedByPoisonHead2328--- PASS: TestQueueRemove (0.01s)2329=== CONT TestDrainGivesUpWhenServerDown23302026/10/06 21:15:38 INFO Uploading batch count=123312026/10/06 21:15:38 INFO Upload queue status pending=223322026/10/06 21:15:38 INFO Uploading batch count=123332026/10/06 21:15:38 INFO Upload queue status pending=223342026/10/06 21:15:38 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-28191-160554113/TestWorkerSkipsGCdPaths2091383389/002/nonexistent23352026/10/06 21:15:38 INFO Uploading batch count=12336--- PASS: TestQueueRetryMovesToBack (0.01s)2337=== CONT TestQueueEnqueueAndFetch23382026/10/06 21:15:38 INFO Uploading batch count=123392026/10/06 21:15:38 INFO Upload queue status pending=223402026/10/06 21:15:38 INFO Uploading batch count=223412026/10/06 21:15:38 INFO Upload queue status pending=323422026/10/06 21:15:38 INFO Uploading batch count=123432026/10/06 21:15:38 ERROR Upload failed error="upload failed" count=12344--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)2345=== CONT TestQueueFetchRemoveLifecycle2346--- PASS: TestQueueEnqueueAndFetch (0.00s)2347=== CONT TestDrainIsolatesPoisonPath23482026/10/06 21:15:38 INFO Uploading batch count=223492026/10/06 21:15:38 ERROR Upload failed error="upload failed" count=223502026/10/06 21:15:38 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-28191-160554113/TestDrainGivesUpWhenServerDown2260279394/002/a23512026/10/06 21:15:38 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-28191-160554113/TestDrainGivesUpWhenServerDown2260279394/002/b23522026/10/06 21:15:38 INFO Uploading batch count=223532026/10/06 21:15:38 ERROR Upload failed error="upload failed" count=223542026/10/06 21:15:38 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-28191-160554113/TestDrainGivesUpWhenServerDown2260279394/002/c23552026/10/06 21:15:38 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-28191-160554113/TestDrainGivesUpWhenServerDown2260279394/002/d23562026/10/06 21:15:38 INFO Uploading batch count=223572026/10/06 21:15:38 ERROR Upload failed error="upload failed" count=223582026/10/06 21:15:38 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-28191-160554113/TestDrainGivesUpWhenServerDown2260279394/002/e23592026/10/06 21:15:38 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-28191-160554113/TestDrainGivesUpWhenServerDown2260279394/002/f23602026/10/06 21:15:38 ERROR Drain finished with paths left in queue remaining=1023612026/10/06 21:15:38 INFO Uploading batch count=423622026/10/06 21:15:38 ERROR Upload failed error="upload failed" count=42363--- PASS: TestQueueFetchRemoveLifecycle (0.00s)23642026/10/06 21:15:38 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-28191-160554113/TestDrainIsolatesPoisonPath40018782/002/bbb23652026/10/06 21:15:38 INFO Uploading batch count=123662026/10/06 21:15:38 ERROR Upload failed error="upload failed" count=123672026/10/06 21:15:38 INFO Uploading batch count=123682026/10/06 21:15:38 ERROR Upload failed error="upload failed" count=123692026/10/06 21:15:38 INFO Uploading batch count=123702026/10/06 21:15:38 ERROR Upload failed error="upload failed" count=123712026/10/06 21:15:38 ERROR Drain finished with paths left in queue remaining=12372--- PASS: TestDrainGivesUpWhenServerDown (0.01s)2373--- PASS: TestDrainIsolatesPoisonPath (0.00s)2374--- PASS: TestWorkerPrunesClosureDeps (0.03s)2375--- PASS: TestWorkerSkipsGCdPaths (0.03s)2376--- PASS: TestWorkerUploadsAndRemoves (0.02s)2377--- PASS: TestQueueRemoveLargeClosure (0.09s)2378--- PASS: TestQueueConcurrentWriters (0.11s)23792026/10/06 21:15:38 ERROR Upload failed error="context deadline exceeded" count=223802026/10/06 21:15:38 ERROR Drain finished with paths left in queue remaining=42381--- PASS: TestDrainTimeout (0.21s)23822026/10/06 21:15:39 INFO Uploading batch count=123832026/10/06 21:15:39 INFO Uploading batch count=123842026/10/06 21:15:39 INFO Uploading batch count=123852026/10/06 21:15:39 ERROR Upload failed error="upload failed" count=123862026/10/06 21:15:39 INFO Uploading batch count=123872026/10/06 21:15:39 ERROR Upload failed error="upload failed" count=123882026/10/06 21:15:39 INFO Uploading batch count=123892026/10/06 21:15:39 ERROR Upload failed error="upload failed" count=123902026/10/06 21:15:39 INFO Uploading batch count=123912026/10/06 21:15:39 ERROR Upload failed error="upload failed" count=123922026/10/06 21:15:39 ERROR Drain finished with paths left in queue remaining=12393--- PASS: TestRunNotBlockedByPoisonHead (1.01s)2394PASS2395Running signing tests...2396=== RUN TestExternalSigner2397=== PAUSE TestExternalSigner2398=== RUN TestExternalSignerWrongPublicKey2399=== PAUSE TestExternalSignerWrongPublicKey2400=== RUN TestExternalSignerErrors2401=== PAUSE TestExternalSignerErrors2402=== RUN TestExternalSignerRestartsAfterCrash2403=== PAUSE TestExternalSignerRestartsAfterCrash2404=== RUN TestExternalSignerProgramErrorKeepsProcess2405=== PAUSE TestExternalSignerProgramErrorKeepsProcess2406=== RUN TestExternalSignerClose2407=== PAUSE TestExternalSignerClose2408=== RUN TestExternalSignerRejectsInvalidPublicKey2409=== PAUSE TestExternalSignerRejectsInvalidPublicKey2410=== RUN TestExternalSignerCancellation2411=== PAUSE TestExternalSignerCancellation2412=== RUN TestGenerateFingerprint2413=== PAUSE TestGenerateFingerprint2414=== RUN TestParseSigningKey2415=== PAUSE TestParseSigningKey2416=== RUN TestSign2417=== PAUSE TestSign2418=== RUN TestSignBatch2419=== PAUSE TestSignBatch2420=== RUN TestNilKeyPublicKey2421=== PAUSE TestNilKeyPublicKey2422=== RUN TestSignErrors2423=== PAUSE TestSignErrors2424=== CONT TestExternalSigner2425=== CONT TestSignBatch2426=== CONT TestExternalSignerCancellation2427=== CONT TestExternalSignerProgramErrorKeepsProcess2428=== CONT TestExternalSignerErrors2429=== RUN TestExternalSignerErrors/too_few_signatures2430=== PAUSE TestExternalSignerErrors/too_few_signatures2431=== RUN TestExternalSignerErrors/program_error2432=== PAUSE TestExternalSignerErrors/program_error2433=== RUN TestExternalSignerErrors/invalid_JSON2434=== PAUSE TestExternalSignerErrors/invalid_JSON2435=== RUN TestExternalSignerErrors/wrong_shape2436=== PAUSE TestExternalSignerErrors/wrong_shape2437=== RUN TestExternalSignerErrors/null2438=== PAUSE TestExternalSignerErrors/null2439=== RUN TestExternalSignerErrors/missing_signatures2440=== PAUSE TestExternalSignerErrors/missing_signatures2441=== RUN TestExternalSignerErrors/wrong_signatures_shape2442=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2443=== RUN TestExternalSignerErrors/exit_at_startup2444=== PAUSE TestExternalSignerErrors/exit_at_startup2445=== RUN TestExternalSignerErrors/null_signatures2446=== PAUSE TestExternalSignerErrors/null_signatures2447=== RUN TestExternalSignerErrors/missing_signature_name2448=== PAUSE TestExternalSignerErrors/missing_signature_name2449=== RUN TestExternalSignerErrors/wrong_signature_name2450=== PAUSE TestExternalSignerErrors/wrong_signature_name2451=== RUN TestExternalSignerErrors/invalid_signature_base642452=== PAUSE TestExternalSignerErrors/invalid_signature_base642453=== RUN TestExternalSignerErrors/exit_on_request2454=== PAUSE TestExternalSignerErrors/exit_on_request2455=== RUN TestExternalSignerErrors/wrong_id2456=== PAUSE TestExternalSignerErrors/wrong_id2457=== RUN TestExternalSignerErrors/unrequested_key2458=== PAUSE TestExternalSignerErrors/unrequested_key2459=== RUN TestExternalSignerErrors/wrong_signature_length2460=== PAUSE TestExternalSignerErrors/wrong_signature_length2461=== CONT TestExternalSignerErrors/too_few_signatures2462=== CONT TestParseSigningKey2463=== RUN TestParseSigningKey/valid_32-byte_key2464=== PAUSE TestParseSigningKey/valid_32-byte_key2465=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2466=== CONT TestGenerateFingerprint2467=== CONT TestExternalSignerErrors/missing_signature_name2468=== CONT TestExternalSignerRejectsInvalidPublicKey2469=== RUN TestGenerateFingerprint/basic_with_references2470=== RUN TestExternalSignerRejectsInvalidPublicKey/#002471=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2472=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002473=== CONT TestSign2474=== RUN TestParseSigningKey/no_colon2475=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2476=== PAUSE TestParseSigningKey/no_colon2477=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2478=== PAUSE TestGenerateFingerprint/basic_with_references2479=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2480=== RUN TestGenerateFingerprint/no_references2481=== PAUSE TestGenerateFingerprint/no_references2482=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2483=== RUN TestParseSigningKey/empty_name2484=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2485=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2486=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2487=== PAUSE TestParseSigningKey/empty_name2488=== RUN TestParseSigningKey/invalid_base642489=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2490=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2491=== RUN TestGenerateFingerprint/invalid_nar_hash_length2492=== PAUSE TestParseSigningKey/invalid_base642493=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2494=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2495=== RUN TestParseSigningKey/wrong_length2496=== RUN TestGenerateFingerprint/invalid_store_path_prefix2497=== PAUSE TestParseSigningKey/wrong_length2498=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2499=== CONT TestExternalSignerWrongPublicKey2500=== RUN TestGenerateFingerprint/invalid_reference_prefix2501=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2502=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2503=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2504=== CONT TestExternalSignerErrors/missing_signatures2505=== CONT TestExternalSignerErrors/null_signatures2506--- PASS: TestSign (0.00s)2507=== CONT TestExternalSignerErrors/exit_at_startup2508--- PASS: TestSignBatch (0.00s)2509=== CONT TestExternalSignerErrors/wrong_signatures_shape2510--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.10s)2511=== CONT TestExternalSignerClose2512--- PASS: TestExternalSignerCancellation (0.20s)2513=== CONT TestSignErrors2514=== RUN TestSignErrors/nil_key2515=== PAUSE TestSignErrors/nil_key2516=== RUN TestSignErrors/nil_narinfo2517=== PAUSE TestSignErrors/nil_narinfo2518=== RUN TestSignErrors/invalid_narinfo2519=== PAUSE TestSignErrors/invalid_narinfo2520=== RUN TestSignErrors/canceled2521=== PAUSE TestSignErrors/canceled2522=== CONT TestNilKeyPublicKey2523--- PASS: TestNilKeyPublicKey (0.00s)2524=== CONT TestExternalSignerErrors/wrong_id2525--- PASS: TestExternalSigner (0.28s)2526=== CONT TestExternalSignerRestartsAfterCrash2527=== CONT TestExternalSignerErrors/wrong_signature_length2528=== CONT TestExternalSignerErrors/unrequested_key2529--- PASS: TestExternalSignerWrongPublicKey (0.50s)2530=== CONT TestExternalSignerErrors/invalid_signature_base642531=== CONT TestExternalSignerErrors/exit_on_request2532=== CONT TestExternalSignerErrors/wrong_signature_name2533=== CONT TestExternalSignerErrors/wrong_shape2534=== CONT TestExternalSignerErrors/null2535--- PASS: TestExternalSignerClose (0.80s)2536=== CONT TestExternalSignerErrors/invalid_JSON2537=== CONT TestExternalSignerErrors/program_error2538--- PASS: TestExternalSignerRestartsAfterCrash (0.80s)2539=== CONT TestParseSigningKey/valid_32-byte_key2540=== CONT TestGenerateFingerprint/basic_with_references2541=== CONT TestExternalSignerRejectsInvalidPublicKey/#002542=== CONT TestParseSigningKey/wrong_length2543=== CONT TestParseSigningKey/invalid_base642544=== CONT TestParseSigningKey/empty_name2545=== CONT TestParseSigningKey/no_colon2546=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2547--- PASS: TestParseSigningKey (0.00s)2548 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2549 --- PASS: TestParseSigningKey/wrong_length (0.00s)2550 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2551 --- PASS: TestParseSigningKey/empty_name (0.00s)2552 --- PASS: TestParseSigningKey/no_colon (0.00s)2553 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2554=== CONT TestGenerateFingerprint/no_references2555=== CONT TestGenerateFingerprint/invalid_reference_prefix2556=== CONT TestGenerateFingerprint/invalid_store_path_prefix2557=== CONT TestGenerateFingerprint/invalid_nar_hash_length2558=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2559=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2560--- PASS: TestGenerateFingerprint (0.00s)2561 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2562 --- PASS: TestGenerateFingerprint/no_references (0.00s)2563 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2564 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2565 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2566 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2567 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2568=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2569=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2570=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2571=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2572--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2573 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2574 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2575 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2576 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2577 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2578=== CONT TestSignErrors/nil_key2579=== CONT TestSignErrors/invalid_narinfo2580=== CONT TestSignErrors/canceled2581=== CONT TestSignErrors/nil_narinfo2582--- PASS: TestSignErrors (0.00s)2583 --- PASS: TestSignErrors/nil_key (0.00s)2584 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2585 --- PASS: TestSignErrors/canceled (0.00s)2586 --- PASS: TestSignErrors/nil_narinfo (0.00s)2587/nix/var/nix/builds/nix-28191-160554113/TestExternalSignerRestartsAfterCrash3488406056/001/sign program: line 7: /nix/var/nix/builds/nix-28191-160554113/TestExternalSignerRestartsAfterCrash3488406056/001/sign program.starts: No such file or directory2588--- PASS: TestExternalSignerErrors (0.00s)2589 --- PASS: TestExternalSignerErrors/too_few_signatures (0.34s)2590 --- PASS: TestExternalSignerErrors/null_signatures (0.42s)2591 --- PASS: TestExternalSignerErrors/missing_signature_name (0.59s)2592 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.66s)2593 --- PASS: TestExternalSignerErrors/exit_at_startup (0.75s)2594 --- PASS: TestExternalSignerErrors/missing_signatures (0.82s)2595 --- PASS: TestExternalSignerErrors/wrong_id (0.79s)2596 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.80s)2597 --- PASS: TestExternalSignerErrors/unrequested_key (0.79s)2598 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.78s)2599 --- PASS: TestExternalSignerErrors/exit_on_request (0.77s)2600 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.79s)2601 --- PASS: TestExternalSignerErrors/wrong_shape (0.79s)2602 --- PASS: TestExternalSignerErrors/null (0.78s)2603 --- PASS: TestExternalSignerErrors/invalid_JSON (0.79s)2604 --- PASS: TestExternalSignerErrors/program_error (0.78s)2605PASS2606Running OpenBao signer tests...2607=== RUN TestSign2608=== PAUSE TestSign2609=== RUN TestSignErrors2610=== PAUSE TestSignErrors2611=== RUN TestServe2612=== PAUSE TestServe2613=== RUN TestServeRejectsGarbage2614=== PAUSE TestServeRejectsGarbage2615=== CONT TestSign2616=== CONT TestSignErrors2617=== CONT TestServe2618=== RUN TestSignErrors/http_error2619=== CONT TestServeRejectsGarbage2620=== PAUSE TestSignErrors/http_error2621=== RUN TestSignErrors/invalid_json2622=== PAUSE TestSignErrors/invalid_json2623=== RUN TestSignErrors/no_prefix2624=== PAUSE TestSignErrors/no_prefix2625=== RUN TestSignErrors/invalid_base642626=== PAUSE TestSignErrors/invalid_base642627=== CONT TestSignErrors/http_error2628--- PASS: TestServeRejectsGarbage (0.00s)2629=== CONT TestSignErrors/invalid_json2630=== CONT TestSignErrors/no_prefix2631--- PASS: TestServe (0.00s)2632=== CONT TestSignErrors/invalid_base642633--- PASS: TestSign (0.00s)2634--- PASS: TestSignErrors (0.00s)2635 --- PASS: TestSignErrors/no_prefix (0.00s)2636 --- PASS: TestSignErrors/invalid_json (0.00s)2637 --- PASS: TestSignErrors/invalid_base64 (0.00s)2638 --- PASS: TestSignErrors/http_error (0.00s)2639PASS