nixbot

builds
sign in

niks3-go-unit-tests checks.aarch64-darwin.go-unit-tests · build #389 · 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.17s)22=== RUN TestDumpPathCaseHackCollision23--- PASS: TestDumpPathCaseHackCollision (0.00s)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=== CONT TestSetClientTLS105=== CONT TestScriptTokenCachesUntilRefresh106=== PAUSE TestEncodeNixBase32/test_string_hash107=== RUN TestEncodeNixBase32/empty_input108=== PAUSE TestEncodeNixBase32/empty_input109=== CONT TestResolveStorePath110=== CONT TestPathInfoCACompatibility111=== RUN TestPathInfoCACompatibility/null_ca_field112=== PAUSE TestPathInfoCACompatibility/null_ca_field113=== RUN TestPathInfoCACompatibility/old_string_format_-_text114=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text115=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive116=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive117=== RUN TestPathInfoCACompatibility/new_structured_format_-_text118=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text119=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method120=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method121=== CONT TestParsePathInfoJSONMultiplePaths122=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths123=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths124=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths125=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths126=== CONT TestParsePathInfoJSON127=== RUN TestParsePathInfoJSON/Nix_format128=== PAUSE TestParsePathInfoJSON/Nix_format129=== RUN TestParsePathInfoJSON/Lix_format130=== PAUSE TestParsePathInfoJSON/Lix_format131=== RUN TestParsePathInfoJSON/empty_input132=== PAUSE TestParsePathInfoJSON/empty_input133=== RUN TestParsePathInfoJSON/whitespace_only134=== PAUSE TestParsePathInfoJSON/whitespace_only135=== RUN TestParsePathInfoJSON/invalid_JSON136=== PAUSE TestParsePathInfoJSON/invalid_JSON137=== CONT TestPathInfoHashCompatibility138=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)139=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)140=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon141=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon142=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI143=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI144=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512145=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512146=== CONT TestGetStorePathHash147=== RUN TestGetStorePathHash/valid_store_path148=== PAUSE TestGetStorePathHash/valid_store_path149=== RUN TestGetStorePathHash/basename_without_hyphen_should_error150=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error151=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess152=== CONT TestRateLimiterFeedback153=== RUN TestRateLimiterFeedback/429_enables_limiter154=== PAUSE TestRateLimiterFeedback/429_enables_limiter1552026/10/06 21:45:27 WARN Rate limiter enabled after throttle name=server-test rate=5156=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error157=== RUN TestRateLimiterFeedback/503_enables_limiter158--- PASS: TestResolveStorePath (0.00s)159=== CONT TestConvertHashToNix32160=== RUN TestConvertHashToNix32/SRI_format_to_Nix32161=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32162=== RUN TestConvertHashToNix32/already_Nix32_format163=== PAUSE TestRateLimiterFeedback/503_enables_limiter164=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error165=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error166=== PAUSE TestConvertHashToNix32/already_Nix32_format167=== RUN TestConvertHashToNix32/invalid_format168=== PAUSE TestConvertHashToNix32/invalid_format169=== CONT TestEncodeNixBase32WithRealHash170--- PASS: TestEncodeNixBase32WithRealHash (0.00s)171=== CONT TestFileTokenMissing172=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter1732026/10/06 21:45:27 WARN Rate limiter enabled after throttle name=server-test rate=5174=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter1752026/10/06 21:45:27 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:55109176=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter177=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter178=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error179=== CONT TestScriptTokenNoExpiryRerunsEveryCall180=== CONT TestFileTokenEmpty1812026/10/06 21:45:27 WARN Rate limiter backed off name=server-test rate=51822026/10/06 21:45:27 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:55109183--- PASS: TestFileTokenMissing (0.00s)184=== CONT TestScriptTokenEmptyCommand185--- PASS: TestScriptTokenEmptyCommand (0.00s)186=== CONT TestFileTokenReadsAndCaches187--- PASS: TestDoServerRequestAttachesToken (0.00s)188=== CONT TestUploadMultipart_PartsInParallel189=== RUN TestSetClientTLSErrors/missing_cert_file190--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)191=== CONT TestDumpPathWriterError192--- PASS: TestFileTokenEmpty (0.00s)193=== CONT TestDumpPathSingleFile194--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)195--- PASS: TestFileTokenReadsAndCaches (0.00s)196=== CONT TestUploadMultipart_SupersededByPeer197=== CONT TestDumpPathMatchesNix198=== RUN TestUploadMultipart_SupersededByPeer/exists199=== PAUSE TestUploadMultipart_SupersededByPeer/exists200=== RUN TestUploadMultipart_SupersededByPeer/missing201=== PAUSE TestUploadMultipart_SupersededByPeer/missing202=== RUN TestSetClientTLS/rejects_connection_without_client_cert203=== PAUSE TestSetClientTLSErrors/missing_cert_file204=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert205=== CONT TestPartSizeForNAR206=== RUN TestSetClientTLSErrors/missing_key_file207=== PAUSE TestSetClientTLSErrors/missing_key_file208=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA209=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA210=== RUN TestSetClientTLS/preserves_debug_logging_transport211=== PAUSE TestSetClientTLS/preserves_debug_logging_transport212=== RUN TestPartSizeForNAR/zero_stays_at_minimum213=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum214=== RUN TestPartSizeForNAR/small_stays_at_minimum215=== PAUSE TestPartSizeForNAR/small_stays_at_minimum216=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum217=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum218=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts219=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts220=== RUN TestPartSizeForNAR/1_TiB221=== CONT TestStaticToken222=== RUN TestSetClientTLSErrors/missing_ca_file223--- PASS: TestStaticToken (0.00s)224=== PAUSE TestSetClientTLSErrors/missing_ca_file225=== RUN TestSetClientTLSErrors/invalid_ca_file226=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun227=== PAUSE TestPartSizeForNAR/1_TiB228=== RUN TestPartSizeForNAR/5_TiB_S3_max_object229=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object230=== RUN TestPartSizeForNAR/capped_at_5_GiB231=== PAUSE TestPartSizeForNAR/capped_at_5_GiB232=== PAUSE TestSetClientTLSErrors/invalid_ca_file233=== CONT TestFilterOversizedClosures234=== RUN TestFilterOversizedClosures/no_limit_keeps_everything235=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything236=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped237=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped238=== RUN TestFilterOversizedClosures/all_closures_skipped239=== PAUSE TestFilterOversizedClosures/all_closures_skipped240=== CONT TestCaseHackSuffix241=== CONT TestRegisterUploadedObjectReusesConnections2422026/10/06 21:45:27 INFO Garbage collection started243--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)244=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica2452026/10/06 21:45:27 INFO Garbage collection started2462026/10/06 21:45:27 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=02472026/10/06 21:45:27 WARN Garbage collection finished on another replica. Its statistics are not available here248--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)249=== CONT TestScriptTokenBadJSON250--- PASS: TestDumpPathWriterError (0.04s)251=== CONT TestScriptTokenEmptyToken252--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)253=== CONT TestClientSignaturesByStorePath254--- PASS: TestClientSignaturesByStorePath (0.00s)255=== CONT TestStreamPushReportsSignatures2562026/10/06 21:45:27 ERROR Upload failed error=boom count=1257--- PASS: TestStreamPushReportsSignatures (0.00s)258--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)259=== CONT TestStreamPushRequestLine260=== CONT TestStreamPushGivesUpOnDeadServer2612026/10/06 21:45:27 ERROR Upload failed error=boom count=12622026/10/06 21:45:27 ERROR Upload failed error="connection refused" count=202632026/10/06 21:45:27 ERROR Server seems unavailable, giving up on batch untried=17264--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)265=== CONT TestStreamPushIsolatesFailures2662026/10/06 21:45:27 ERROR Upload failed error="bad path" count=3267--- PASS: TestRegisterUploadedObjectReusesConnections (0.04s)268=== CONT TestStreamPushBatchesUnderLoad269--- PASS: TestStreamPushIsolatesFailures (0.00s)270=== CONT TestStreamPushReportsEveryPath271--- PASS: TestStreamPushReportsEveryPath (0.00s)272=== CONT TestShellSplitErrors273--- PASS: TestShellSplitErrors (0.00s)274=== CONT TestShellSplit275--- PASS: TestShellSplit (0.00s)276=== CONT TestEncodeNixBase32/test_string_hash277=== CONT TestScriptTokenScriptFails278--- PASS: TestScriptTokenBadJSON (0.03s)279=== CONT TestEncodeNixBase32/empty_input280--- PASS: TestEncodeNixBase32 (0.00s)281 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)282 --- PASS: TestEncodeNixBase32/empty_input (0.00s)283=== CONT TestPathInfoCACompatibility/null_ca_field284=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths285=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method286=== CONT TestPathInfoCACompatibility/new_structured_format_-_text287=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive288=== CONT TestPathInfoCACompatibility/old_string_format_-_text289--- PASS: TestPathInfoCACompatibility (0.00s)290 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)291 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)292 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)293 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)294 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)295=== CONT TestParsePathInfoJSON/Nix_format296=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths297--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)298 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)299 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)300=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)301=== CONT TestParsePathInfoJSON/empty_input302=== CONT TestParsePathInfoJSON/Lix_format303=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI304=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512305=== CONT TestParsePathInfoJSON/invalid_JSON306=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon307--- PASS: TestPathInfoHashCompatibility (0.00s)308 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)309 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)310 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)311 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)312=== CONT TestParsePathInfoJSON/whitespace_only313--- PASS: TestParsePathInfoJSON (0.00s)314 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)315 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)316 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)317 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)318 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)319=== CONT TestConvertHashToNix32/SRI_format_to_Nix32320=== CONT TestConvertHashToNix32/invalid_format321=== CONT TestConvertHashToNix32/already_Nix32_format322=== CONT TestRateLimiterFeedback/429_enables_limiter323--- PASS: TestConvertHashToNix32 (0.00s)324 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)325 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)326 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)3272026/10/06 21:45:27 WARN Rate limiter enabled after throttle name=server-test rate=53282026/10/06 21:45:27 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:551893292026/10/06 21:45:27 WARN Rate limiter backed off name=server-test rate=5330=== CONT TestGetStorePathHash/valid_store_path331=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error332=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter333=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter334=== CONT TestRateLimiterFeedback/503_enables_limiter335--- PASS: TestScriptTokenScriptFails (0.00s)336=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error337=== CONT TestGetStorePathHash/basename_without_hyphen_should_error338=== CONT TestUploadMultipart_SupersededByPeer/exists339--- PASS: TestGetStorePathHash (0.00s)340 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)341 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)342 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)343 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)3442026/10/06 21:45:27 WARN Rate limiter enabled after throttle name=server-test rate=53452026/10/06 21:45:27 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:551953462026/10/06 21:45:27 WARN Rate limiter backed off name=server-test rate=5347--- PASS: TestRateLimiterFeedback (0.00s)348 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)349 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)350 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)351 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)352=== CONT TestUploadMultipart_SupersededByPeer/missing353=== CONT TestSetClientTLS/rejects_connection_without_client_cert354--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)355 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)356 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)357=== CONT TestSetClientTLS/preserves_debug_logging_transport358=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA359--- PASS: TestStreamPushRequestLine (0.01s)360=== CONT TestPartSizeForNAR/zero_stays_at_minimum361=== CONT TestSetClientTLSErrors/missing_cert_file362=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum363=== CONT TestPartSizeForNAR/capped_at_5_GiB364=== CONT TestPartSizeForNAR/5_TiB_S3_max_object365=== CONT TestPartSizeForNAR/1_TiB366=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts367=== CONT TestSetClientTLSErrors/invalid_ca_file368=== CONT TestPartSizeForNAR/small_stays_at_minimum369--- PASS: TestPartSizeForNAR (0.00s)370 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)371 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)372 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)373 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)374 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)375 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)376 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)377=== CONT TestSetClientTLSErrors/missing_ca_file378=== CONT TestSetClientTLSErrors/missing_key_file379=== CONT TestFilterOversizedClosures/no_limit_keeps_everything380=== CONT TestFilterOversizedClosures/all_closures_skipped3812026/10/06 21:45:27 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=50382=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3832026/10/06 21:45:27 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=2000384--- PASS: TestFilterOversizedClosures (0.00s)385 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)386 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)387 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)388--- PASS: TestSetClientTLSErrors (0.01s)389 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)390 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)391 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)392 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)393--- PASS: TestScriptTokenEmptyToken (0.01s)394--- PASS: TestCaseHackSuffix (0.05s)395--- PASS: TestDumpPathSingleFile (0.05s)3962026/10/06 21:45:27 http: TLS handshake error from 127.0.0.1:55201: remote error: tls: bad certificate397--- PASS: TestSetClientTLS (0.01s)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: TestDumpPathMatchesNix (0.08s)402--- PASS: TestStreamPushBatchesUnderLoad (0.10s)403--- PASS: TestUploadMultipart_PartsInParallel (0.63s)404--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)405PASS406Running server tests...407The files belonging to this database system will be owned by user "_nixbld1".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-98165-1098463425/postgres2958013113/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-98165-1098463425/postgres2958013113/data -l logfile start4334342026-10-06 21:45:29.387 UTC [98203] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4352026-10-06 21:45:29.387 UTC [98203] LOG: listening on Unix socket "/nix/var/nix/builds/nix-98165-1098463425/postgres2958013113/.s.PGSQL.5432"4362026-10-06 21:45:29.389 UTC [98210] LOG: database system was shut down at 2026-10-06 21:45:29 UTC4372026-10-06 21:45:29.389 UTC [98211] FATAL: the database system is starting up438/nix/var/nix/builds/nix-98165-1098463425/postgres2958013113:5432 - rejecting connections4392026-10-06 21:45:29.390 UTC [98203] LOG: database system is ready to accept connections440/nix/var/nix/builds/nix-98165-1098463425/postgres2958013113:5432 - accepting connections441{"timestamp":"2026-10-06T21:45:29.739176Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"a76ef025-07fc-48f8-bda9-2f0fa32eef7d","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":10,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}442{"timestamp":"2026-10-06T21:45:29.848563Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"e100ef21-1926-474e-a5e5-cc8575a28952","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(4)"}443=== RUN TestService_AuthMiddleware444=== PAUSE TestService_AuthMiddleware445=== RUN TestService_AuthMiddleware_MTLSProxyHeader446=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader447=== RUN TestService_AuthMiddleware_MTLSBoundSubjects448=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects449=== RUN TestService_ReadAuthMiddleware450=== PAUSE TestService_ReadAuthMiddleware451=== RUN TestService_AuthMiddleware_OIDC452=== PAUSE TestService_AuthMiddleware_OIDC453=== RUN TestService_RequireScope_OIDC454=== PAUSE TestService_RequireScope_OIDC455=== RUN TestService_ReadScope_PublicByDefault456=== PAUSE TestService_ReadScope_PublicByDefault457=== RUN TestCacheConfigHandler458=== PAUSE TestCacheConfigHandler459=== RUN TestCacheStatsHandler460=== PAUSE TestCacheStatsHandler461=== RUN TestClientCADerivations462=== PAUSE TestClientCADerivations463=== RUN TestClientErrorHandling464=== PAUSE TestClientErrorHandling465=== RUN TestClientIntegration466=== PAUSE TestClientIntegration467=== RUN TestClientMultipleUploads468=== PAUSE TestClientMultipleUploads469=== RUN TestClientWithDependencies470=== PAUSE TestClientWithDependencies471=== RUN TestClientSharedPathCommittedMidPush472=== PAUSE TestClientSharedPathCommittedMidPush473=== RUN TestPinProtectsFromGC474=== PAUSE TestPinProtectsFromGC475=== RUN TestClientPushesUseOnePush476=== PAUSE TestClientPushesUseOnePush477=== RUN TestClientFallsBackToClosures478=== PAUSE TestClientFallsBackToClosures479=== RUN TestDeleteClosuresRacingPins480=== PAUSE TestDeleteClosuresRacingPins481=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock482=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock483=== RUN TestResolveDBConnectionString484=== PAUSE TestResolveDBConnectionString485=== RUN TestConnectWaitsForAPeerMigration486=== PAUSE TestConnectWaitsForAPeerMigration487=== RUN TestLeadElectsOneAndHandsOver488=== PAUSE TestLeadElectsOneAndHandsOver489=== RUN TestLeadIncumbentWinsAfterRestart4902026/10/06 21:45:30 INFO lead: acquired remote=192.0.2.1:12344912026/10/06 21:45:30 INFO lead: released remote=192.0.2.1:12344922026/10/06 21:45:30 INFO lead: acquired remote=192.0.2.1:12344932026/10/06 21:45:31 INFO lead: released remote=192.0.2.1:1234494--- PASS: TestLeadIncumbentWinsAfterRestart (2.00s)495=== RUN TestLeadIncumbentAnnouncesAtOnce496=== PAUSE TestLeadIncumbentAnnouncesAtOnce497=== RUN TestLeadEndsOnShutdown498=== PAUSE TestLeadEndsOnShutdown499=== RUN TestLeadEndsWhenItsConnectionHangs5002026/10/06 21:45:32 INFO lead: acquired remote=192.0.2.1:12345012026-10-06 21:45:33.270 UTC [98252] FATAL: terminating connection due to administrator command5022026/10/06 21:45:33 INFO lead: acquired remote=192.0.2.1:12345032026/10/06 21:45:34 WARN lead: lock connection lost error="timeout: context deadline exceeded"5042026/10/06 21:45:34 INFO lead: released remote=192.0.2.1:12345052026/10/06 21:45:34 INFO lead: released remote=192.0.2.1:1234506--- PASS: TestLeadEndsWhenItsConnectionHangs (2.72s)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 TestObjectStatsLargeCommit588=== PAUSE TestObjectStatsLargeCommit589=== RUN TestOrphanedObjectsGC590=== PAUSE TestOrphanedObjectsGC591=== RUN TestOrphanedObjectsGCStressTest592=== PAUSE TestOrphanedObjectsGCStressTest593=== RUN TestCreatePin_ReservedPins594=== PAUSE TestCreatePin_ReservedPins595=== RUN TestPresentReportsOnlyClosureRoots596=== PAUSE TestPresentReportsOnlyClosureRoots597=== RUN TestPresentRefreshesOnlyStaleClosures598=== PAUSE TestPresentRefreshesOnlyStaleClosures599=== RUN TestPresentNotReportedWhileGCDeletesClosure600=== PAUSE TestPresentNotReportedWhileGCDeletesClosure601=== RUN TestParseSingleRange602=== PAUSE TestParseSingleRange603=== RUN TestProxyHeadersOnlyTrustedOnSocket604=== PAUSE TestProxyHeadersOnlyTrustedOnSocket605=== RUN TestIsValidCachePath606=== PAUSE TestIsValidCachePath607=== RUN TestReadProxyNarinfo608=== PAUSE TestReadProxyNarinfo609=== RUN TestReadProxyNarinfoAlreadyDecompressed610=== PAUSE TestReadProxyNarinfoAlreadyDecompressed611=== RUN TestReadProxyContentNegotiation612=== PAUSE TestReadProxyContentNegotiation613=== RUN TestReadProxyNarStreaming614=== PAUSE TestReadProxyNarStreaming615=== RUN TestReadProxy404616=== PAUSE TestReadProxy404617=== RUN TestReadProxyInvalidPath618=== PAUSE TestReadProxyInvalidPath619=== RUN TestReadProxyHead620=== PAUSE TestReadProxyHead621=== RUN TestReadProxyOutlastsServerWriteTimeout622=== PAUSE TestReadProxyOutlastsServerWriteTimeout623=== RUN TestReadProxyConditionalGet624=== PAUSE TestReadProxyConditionalGet625=== RUN TestReadProxyRootRedirectsToIndexHTML626=== PAUSE TestReadProxyRootRedirectsToIndexHTML627=== RUN TestReadProxyDisabled628=== PAUSE TestReadProxyDisabled629=== RUN TestReadRedirectNar630=== PAUSE TestReadRedirectNar631=== RUN TestReadRedirectKeepsNarinfoProxied632=== PAUSE TestReadRedirectKeepsNarinfoProxied633=== RUN TestReadProxyRangeRequest634=== PAUSE TestReadProxyRangeRequest635=== RUN TestReadRedirectUsesPublicS3URL636=== PAUSE TestReadRedirectUsesPublicS3URL637=== RUN TestPush_OverlappingRootsStoreOneRowPerKey638=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey639=== RUN TestPush_CompleteCommitsEveryRoot640=== PAUSE TestPush_CompleteCommitsEveryRoot641=== RUN TestPush_RepeatedRootCommitsOnce642=== PAUSE TestPush_RepeatedRootCommitsOnce643=== RUN TestPush_CompleteWaitsForCleanupOfThePush644=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush645=== RUN TestPush_RootsAreLockedInByteOrder646=== PAUSE TestPush_RootsAreLockedInByteOrder647=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit648=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit649=== RUN TestPush_RejectsBadRequests650=== PAUSE TestPush_RejectsBadRequests651=== RUN TestPush_SignsNarinfosOfItsPendingObjects652=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects653=== RUN TestRedundantMultipartUpload654=== PAUSE TestRedundantMultipartUpload655=== RUN TestCompleteMultipartUpload_ErrorButObjectExists656=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists657=== RUN TestCompletedNarNotReofferedAcrossClosures658=== PAUSE TestCompletedNarNotReofferedAcrossClosures659=== RUN TestPresignedUploadRegisteredBeforeCommit660=== PAUSE TestPresignedUploadRegisteredBeforeCommit661=== RUN TestService_Rustfstest662=== PAUSE TestService_Rustfstest663=== RUN TestParseSize664=== PAUSE TestParseSize665=== RUN TestSkippedUploadsHandler666=== PAUSE TestSkippedUploadsHandler667=== RUN TestSystemdListenerNotActivated668--- PASS: TestSystemdListenerNotActivated (0.00s)669=== RUN TestWatchdogBeatsWhenHealthy670--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)671=== RUN TestWatchdogSkipsWhenUnhealthy6722026/10/06 21:45:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6732026/10/06 21:45:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6742026/10/06 21:45:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6752026/10/06 21:45:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6762026/10/06 21:45:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6772026/10/06 21:45:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6782026/10/06 21:45:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6792026/10/06 21:45:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6802026/10/06 21:45:34 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"681--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)682=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle683=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle684=== RUN TestProxyWriteTimeout685=== PAUSE TestProxyWriteTimeout686=== RUN TestPendingClosureWriteTimeout687=== PAUSE TestPendingClosureWriteTimeout688=== RUN TestIsValidUploadKey689=== PAUSE TestIsValidUploadKey690=== RUN TestUploadHandlersRejectInvalidKeys691=== PAUSE TestUploadHandlersRejectInvalidKeys692=== RUN TestUploadHandlersRejectOversizedBody693=== PAUSE TestUploadHandlersRejectOversizedBody694=== RUN TestService_cleanupPendingClosuresHandler695=== PAUSE TestService_cleanupPendingClosuresHandler696=== RUN TestService_createPendingClosureHandler697=== PAUSE TestService_createPendingClosureHandler698=== RUN TestService_verifyS3Integrity699=== PAUSE TestService_verifyS3Integrity700=== RUN TestCompleteMultipartUnregistered701=== PAUSE TestCompleteMultipartUnregistered702=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT703=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT704=== CONT TestService_AuthMiddleware705=== CONT TestMetricsInventory706=== CONT TestDeduplicatedObjectsRecordedAsPending707=== CONT TestPinProtectsFromGC708=== CONT TestNARDeduplicationMetadataUploadBug709=== CONT TestReadRedirectNar710=== CONT TestCreatePendingClosureRejectsOversizedNAR711=== CONT TestCacheStatsHandler712=== CONT TestReadRedirectKeepsNarinfoProxied713=== CONT TestPushDedupSurvivesConcurrentGC7142026/10/06 21:45:34 INFO Received uploads request method=POST path=/api/pending_closures715--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)716=== CONT TestGCMetrics7172026/10/06 21:45:35 INFO Aborted multipart uploads count=0 kept=07182026/10/06 21:45:35 WARN Force mode enabled - objects will be deleted immediately without grace period7192026/10/06 21:45:35 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=07202026/10/06 21:45:35 INFO Vacuumed table table=pending_closures7212026/10/06 21:45:35 INFO Vacuumed table table=pending_objects7222026/10/06 21:45:35 INFO Vacuumed table table=multipart_uploads7232026/10/06 21:45:35 INFO Vacuumed table table=closures7242026/10/06 21:45:35 INFO Vacuumed table table=objects725--- PASS: TestGCMetrics (0.41s)726=== CONT TestGCBugBareHashReferences7272026/10/06 21:45:35 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"728--- PASS: TestService_AuthMiddleware (0.53s)729=== CONT TestGCAdvisoryLockBlocksConcurrentRun730=== NAME TestNARDeduplicationMetadataUploadBug731 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-98165-1098463425/TestNARDeduplicationMetadataUploadBug934734851/001/store/a9w0ihsgv7xd9v960nvn7bn4gs3c7xr4-file1.txt7322026/10/06 21:45:35 INFO Received push request method=POST path=/api/pushes7332026/10/06 21:45:35 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)7342026/10/06 21:45:35 INFO Uploading a9w0ihsgv7xd9v960nvn7bn4gs3c7xr4-file1.txt (160B)7352026/10/06 21:45:35 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign7362026/10/06 21:45:35 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"7372026/10/06 21:45:35 WARN Failed to register uploaded object key=a9w0ihsgv7xd9v960nvn7bn4gs3c7xr4.ls error="server returned 404: 404 page not found\n"7382026/10/06 21:45:35 INFO Signed narinfos id=1 count=17392026/10/06 21:45:35 INFO Uploading 1 narinfos7402026/10/06 21:45:35 INFO Received complete push request method=POST path=/api/pushes/1/complete7412026/10/06 21:45:35 WARN Failed to register uploaded object key=a9w0ihsgv7xd9v960nvn7bn4gs3c7xr4.narinfo error="server returned 404: 404 page not found\n"7422026/10/06 21:45:35 INFO Completed push id=17432026/10/06 21:45:35 INFO Upload complete. (90ms)744 metadata_upload_test.go:54: Retrieved narinfo from S3:745 StorePath: /nix/var/nix/builds/nix-98165-1098463425/TestNARDeduplicationMetadataUploadBug934734851/001/store/a9w0ihsgv7xd9v960nvn7bn4gs3c7xr4-file1.txt746 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst747 Compression: zstd748 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf749 NarSize: 160750 References: 751 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf752 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)753 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):754 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}755--- PASS: TestCacheStatsHandler (0.97s)756=== CONT TestLeadEndsOnShutdown757=== NAME TestPinProtectsFromGC758 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-98165-1098463425/TestPinProtectsFromGC387270121/001/store/3s2a53d496bwvkijrak159k03ls9hn5b-pinned-file.txt759 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-98165-1098463425/TestPinProtectsFromGC387270121/001/store/9lgwbqri2wvkdh17qp87bab0hii4lcm5-unpinned-file.txt760=== NAME TestNARDeduplicationMetadataUploadBug761 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-98165-1098463425/TestNARDeduplicationMetadataUploadBug934734851/001/store/i8f9dh8arrgwqxw65vzm805kh7z1pf02-file2.txt7622026/10/06 21:45:35 INFO Received push request method=POST path=/api/pushes7632026/10/06 21:45:35 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)7642026/10/06 21:45:35 INFO Uploading 3s2a53d496bwvkijrak159k03ls9hn5b-pinned-file.txt (128B)7652026/10/06 21:45:35 WARN Failed to register uploaded object key=3s2a53d496bwvkijrak159k03ls9hn5b.ls error="server returned 404: 404 page not found\n"7662026/10/06 21:45:35 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign7672026/10/06 21:45:35 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"7682026/10/06 21:45:35 INFO Signed narinfos id=1 count=17692026/10/06 21:45:35 INFO Uploading 1 narinfos7702026/10/06 21:45:35 INFO Received complete push request method=POST path=/api/pushes/1/complete7712026/10/06 21:45:35 WARN Failed to register uploaded object key=3s2a53d496bwvkijrak159k03ls9hn5b.narinfo error="server returned 404: 404 page not found\n"7722026/10/06 21:45:35 INFO Completed push id=17732026/10/06 21:45:35 INFO Upload complete. (70ms)7742026/10/06 21:45:35 INFO Received push request method=POST path=/api/pushes7752026/10/06 21:45:35 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)7762026/10/06 21:45:35 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign7772026/10/06 21:45:35 INFO Signed narinfos id=2 count=17782026/10/06 21:45:35 WARN Failed to register uploaded object key=i8f9dh8arrgwqxw65vzm805kh7z1pf02.ls error="server returned 404: 404 page not found\n"7792026/10/06 21:45:35 INFO Uploading 1 narinfos780--- PASS: TestMetricsInventory (1.09s)781=== CONT TestLeadIncumbentAnnouncesAtOnce7822026/10/06 21:45:35 INFO Received complete push request method=POST path=/api/pushes/2/complete7832026/10/06 21:45:35 WARN Failed to register uploaded object key=i8f9dh8arrgwqxw65vzm805kh7z1pf02.narinfo error="server returned 404: 404 page not found\n"7842026/10/06 21:45:35 INFO Completed push id=27852026/10/06 21:45:35 INFO Upload complete. (69ms)786=== NAME TestNARDeduplicationMetadataUploadBug787 metadata_upload_test.go:76: Retrieved narinfo from S3:788 StorePath: /nix/var/nix/builds/nix-98165-1098463425/TestNARDeduplicationMetadataUploadBug934734851/001/store/i8f9dh8arrgwqxw65vzm805kh7z1pf02-file2.txt789 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst790 Compression: zstd791 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf792 NarSize: 160793 References: 794 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf795 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)796 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):797 {"version":1,"root":{"type":"regular","size":44}}798--- PASS: TestNARDeduplicationMetadataUploadBug (1.13s)799=== CONT TestLeadElectsOneAndHandsOver8002026/10/06 21:45:36 INFO Received push request method=POST path=/api/pushes8012026/10/06 21:45:36 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8022026/10/06 21:45:36 INFO Uploading 9lgwbqri2wvkdh17qp87bab0hii4lcm5-unpinned-file.txt (128B)8032026/10/06 21:45:36 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"8042026/10/06 21:45:36 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign8052026/10/06 21:45:36 INFO Signed narinfos id=2 count=18062026/10/06 21:45:36 WARN Failed to register uploaded object key=9lgwbqri2wvkdh17qp87bab0hii4lcm5.ls error="server returned 404: 404 page not found\n"8072026/10/06 21:45:36 INFO Uploading 1 narinfos8082026/10/06 21:45:36 INFO Received complete push request method=POST path=/api/pushes/2/complete8092026/10/06 21:45:36 WARN Failed to register uploaded object key=9lgwbqri2wvkdh17qp87bab0hii4lcm5.narinfo error="server returned 404: 404 page not found\n"8102026/10/06 21:45:36 INFO Completed push id=28112026/10/06 21:45:36 INFO Upload complete. (67ms)8122026/10/06 21:45:36 INFO Starting cleanup of old closures method=DELETE path=/api/closures8132026/10/06 21:45:36 INFO Garbage collection started814--- PASS: TestReadRedirectNar (1.21s)815=== CONT TestConnectWaitsForAPeerMigration8162026/10/06 21:45:36 INFO Aborted multipart uploads count=0 kept=08172026/10/06 21:45:36 WARN Force mode enabled - objects will be deleted immediately without grace period8182026/10/06 21:45:36 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=08192026/10/06 21:45:36 INFO Vacuumed table table=pending_closures8202026/10/06 21:45:36 INFO Vacuumed table table=pending_objects8212026/10/06 21:45:36 INFO Vacuumed table table=multipart_uploads8222026/10/06 21:45:36 INFO Vacuumed table table=closures8232026/10/06 21:45:36 INFO Vacuumed table table=objects8242026/10/06 21:45:36 INFO Received uploads request method=POST path=/api/pending_closures825--- PASS: TestDeduplicatedObjectsRecordedAsPending (1.36s)826=== CONT TestResolveDBConnectionString827=== RUN TestResolveDBConnectionString/flag_wins828=== PAUSE TestResolveDBConnectionString/flag_wins829=== RUN TestResolveDBConnectionString/file_when_flag_empty830=== PAUSE TestResolveDBConnectionString/file_when_flag_empty831=== RUN TestResolveDBConnectionString/missing_file_is_an_error832=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error833=== RUN TestResolveDBConnectionString/PGHOST_allows_empty834=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty835=== RUN TestResolveDBConnectionString/nothing_configured836=== PAUSE TestResolveDBConnectionString/nothing_configured837=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock8382026/10/06 21:45:36 INFO Received uploads request method=POST path=/api/pending_closures8392026/10/06 21:45:36 INFO Aborted multipart uploads count=0 kept=08402026/10/06 21:45:36 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=0841--- PASS: TestReadRedirectKeepsNarinfoProxied (1.62s)842=== CONT TestDeleteClosuresRacingPins8432026/10/06 21:45:36 INFO Vacuumed table table=pending_closures8442026/10/06 21:45:36 INFO Vacuumed table table=pending_objects8452026/10/06 21:45:36 INFO Vacuumed table table=multipart_uploads8462026/10/06 21:45:36 INFO Vacuumed table table=closures8472026/10/06 21:45:36 INFO Vacuumed table table=objects8482026/10/06 21:45:36 INFO Aborted multipart uploads count=0 kept=08492026/10/06 21:45:36 WARN Force mode enabled - objects will be deleted immediately without grace period8502026/10/06 21:45:36 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=08512026/10/06 21:45:36 INFO Vacuumed table table=pending_closures8522026/10/06 21:45:36 INFO Vacuumed table table=pending_objects8532026/10/06 21:45:36 INFO Vacuumed table table=multipart_uploads8542026/10/06 21:45:36 INFO Vacuumed table table=closures8552026/10/06 21:45:36 INFO Vacuumed table table=objects856--- PASS: TestPushDedupSurvivesConcurrentGC (1.70s)857=== CONT TestClientFallsBackToClosures8582026/10/06 21:45:36 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_nixbld1 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"859--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (1.37s)860=== CONT TestClientPushesUseOnePush861--- PASS: TestGCBugBareHashReferences (1.58s)862=== CONT TestGCTaskStore_StartNew863--- PASS: TestGCTaskStore_StartNew (0.00s)864=== CONT TestCacheConfigHandlerMaxNarSize865--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)866=== CONT TestGenerateLandingPage867--- PASS: TestGenerateLandingPage (0.00s)868=== CONT TestService_readinessHandler8692026/10/06 21:45:36 INFO lead: acquired remote=192.0.2.1:12348702026/10/06 21:45:37 INFO lead: acquired remote=192.0.2.1:12348712026/10/06 21:45:37 INFO lead: acquired remote=192.0.2.1:12348722026/10/06 21:45:37 INFO lead: released remote=192.0.2.1:1234873--- PASS: TestLeadIncumbentAnnouncesAtOnce (1.23s)874=== CONT TestService_healthCheckHandler875--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (1.58s)876=== CONT TestGracefulShutdownDrainsInflight8772026/10/06 21:45:37 INFO Starting HTTP server address=127.0.0.1:553048782026/10/06 21:45:37 INFO Shutdown signal received, draining in-flight requests timeout=10s8792026/10/06 21:45:37 INFO Received uploads request method=POST path=/api/pending_closures8802026/10/06 21:45:37 INFO Received uploads request method=POST path=/api/pending_closures8812026/10/06 21:45:37 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)8822026/10/06 21:45:37 INFO Uploading fk2bvhjb77p3pprkl9nz4gr9vlclvg8b-b (248B)8832026/10/06 21:45:37 INFO Uploading k7n1nn8hhg9xa2zd1wn5pgfdicilslzf-shared-dep (136B)884--- PASS: TestGracefulShutdownDrainsInflight (0.07s)885=== CONT TestGCTaskStore_Fail886--- PASS: TestGCTaskStore_Fail (0.00s)887=== CONT TestGCTaskStore_PhaseUpdates888--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)889=== CONT TestGCTaskStore_CompletedAllowsNewTask890--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)891=== CONT TestGCTaskStore_GetReturnsLatest892--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)893=== CONT TestGCTaskStore_GetEmpty894--- PASS: TestGCTaskStore_GetEmpty (0.00s)895=== CONT TestGCTaskStore_ConflictDifferentParams896--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)897=== CONT TestGCTaskStore_DeduplicateSameParams898--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)899=== CONT TestService_AuthMiddleware_OIDC9002026/10/06 21:45:37 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"9012026/10/06 21:45:37 WARN Failed to register uploaded object key=fk2bvhjb77p3pprkl9nz4gr9vlclvg8b.ls error="server returned 404: 404 page not found\n"9022026/10/06 21:45:37 WARN Failed to register uploaded object key=ayz0yi9ws71iz9kw4ffbfp6przqhnnlj.ls error="server returned 404: 404 page not found\n"9032026/10/06 21:45:37 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign9042026/10/06 21:45:37 WARN Failed to register uploaded object key=k7n1nn8hhg9xa2zd1wn5pgfdicilslzf.ls error="server returned 404: 404 page not found\n"9052026/10/06 21:45:37 WARN Failed to register uploaded object key=nar/09scpynypm0n8y55j55cqn4qwl718qzdrrkaa5iqgradv32zar59.nar.zst error="server returned 404: 404 page not found\n"9062026/10/06 21:45:37 INFO Signed narinfos id=2 count=29072026/10/06 21:45:37 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9082026/10/06 21:45:37 INFO Signed narinfos id=1 count=29092026/10/06 21:45:37 INFO Uploading 4 narinfos9102026/10/06 21:45:37 WARN Failed to register uploaded object key=fk2bvhjb77p3pprkl9nz4gr9vlclvg8b.narinfo error="server returned 404: 404 page not found\n"9112026/10/06 21:45:37 WARN Failed to register uploaded object key=k7n1nn8hhg9xa2zd1wn5pgfdicilslzf.narinfo error="server returned 404: 404 page not found\n"9122026/10/06 21:45:37 WARN Failed to register uploaded object key=ayz0yi9ws71iz9kw4ffbfp6przqhnnlj.narinfo error="server returned 404: 404 page not found\n"9132026/10/06 21:45:37 WARN readiness check failed error="closed pool"914--- PASS: TestService_readinessHandler (1.06s)915=== CONT TestCacheConfigHandler916=== RUN TestCacheConfigHandler/full_config,_no_issuer917=== PAUSE TestCacheConfigHandler/full_config,_no_issuer918=== RUN TestCacheConfigHandler/no_cache_url_configured919=== PAUSE TestCacheConfigHandler/no_cache_url_configured920=== RUN TestCacheConfigHandler/no_signing_keys921=== PAUSE TestCacheConfigHandler/no_signing_keys922=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator923=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator924=== CONT TestService_ReadScope_PublicByDefault9252026/10/06 21:45:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9262026/10/06 21:45:37 WARN Failed to register uploaded object key=k7n1nn8hhg9xa2zd1wn5pgfdicilslzf.narinfo error="server returned 404: 404 page not found\n"9272026/10/06 21:45:37 INFO Completed upload id=19282026/10/06 21:45:37 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete9292026/10/06 21:45:37 INFO Completed upload id=29302026/10/06 21:45:37 INFO Upload complete. (142ms)931=== NAME TestClientFallsBackToClosures932 client_pushes_test.go:112: Retrieved narinfo from S3:933 StorePath: /nix/var/nix/builds/nix-98165-1098463425/TestClientFallsBackToClosures2722776358/001/store/k7n1nn8hhg9xa2zd1wn5pgfdicilslzf-shared-dep934 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst935 Compression: zstd936 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82937 NarSize: 136938 References: 939 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n9402026/10/06 21:45:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55321/oidc941 client_pushes_test.go:112: Retrieved narinfo from S3:942 StorePath: /nix/var/nix/builds/nix-98165-1098463425/TestClientFallsBackToClosures2722776358/001/store/ayz0yi9ws71iz9kw4ffbfp6przqhnnlj-a943 URL: nar/09scpynypm0n8y55j55cqn4qwl718qzdrrkaa5iqgradv32zar59.nar.zst944 Compression: zstd945 NarHash: sha256:09scpynypm0n8y55j55cqn4qwl718qzdrrkaa5iqgradv32zar59946 NarSize: 248947 References: /nix/var/nix/builds/nix-98165-1098463425/TestClientFallsBackToClosures2722776358/001/store/k7n1nn8hhg9xa2zd1wn5pgfdicilslzf-shared-dep948 CA: text:sha256:0lwgxdslbn8im46xry5y7q5xym0b66df2swx5yfwim7aa3bvmi49949 client_pushes_test.go:112: Retrieved narinfo from S3:950 StorePath: /nix/var/nix/builds/nix-98165-1098463425/TestClientFallsBackToClosures2722776358/001/store/fk2bvhjb77p3pprkl9nz4gr9vlclvg8b-b951 URL: nar/09scpynypm0n8y55j55cqn4qwl718qzdrrkaa5iqgradv32zar59.nar.zst952 Compression: zstd953 NarHash: sha256:09scpynypm0n8y55j55cqn4qwl718qzdrrkaa5iqgradv32zar59954 NarSize: 248955 References: /nix/var/nix/builds/nix-98165-1098463425/TestClientFallsBackToClosures2722776358/001/store/k7n1nn8hhg9xa2zd1wn5pgfdicilslzf-shared-dep956 CA: text:sha256:0lwgxdslbn8im46xry5y7q5xym0b66df2swx5yfwim7aa3bvmi499572026/10/06 21:45:37 INFO lead: released remote=192.0.2.1:1234958--- PASS: TestLeadEndsOnShutdown (2.12s)959=== CONT TestService_RequireScope_OIDC960--- PASS: TestClientFallsBackToClosures (1.39s)961=== CONT TestClientMultipleUploads9622026/10/06 21:45:38 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55325/oidc963--- PASS: TestService_healthCheckHandler (0.87s)964=== CONT TestClientSharedPathCommittedMidPush9652026/10/06 21:45:38 INFO Received push request method=POST path=/api/pushes9662026/10/06 21:45:38 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=09672026/10/06 21:45:38 INFO Received create pin request method=POST path=/api/pins/myapp9682026/10/06 21:45:38 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)9692026/10/06 21:45:38 INFO Uploading icjc1fqklgi865b99fmxy06ya4jcqxjs-shared-dep (136B)9702026/10/06 21:45:38 INFO Uploading 734pisc8l7aadwa0szkaji53wq237yin-a (248B)9712026/10/06 21:45:38 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-98165-1098463425/TestPinProtectsFromGC387270121/001/store/3s2a53d496bwvkijrak159k03ls9hn5b-pinned-file.txt narinfo_key=3s2a53d496bwvkijrak159k03ls9hn5b.narinfo9722026/10/06 21:45:38 INFO Starting cleanup of old closures method=DELETE path=/api/closures9732026/10/06 21:45:38 INFO Garbage collection started9742026/10/06 21:45:38 INFO Aborted multipart uploads count=0 kept=09752026/10/06 21:45:38 WARN Force mode enabled - objects will be deleted immediately without grace period9762026/10/06 21:45: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=09772026/10/06 21:45:38 INFO Vacuumed table table=pending_closures9782026/10/06 21:45:38 INFO Vacuumed table table=pending_objects9792026/10/06 21:45:38 INFO Vacuumed table table=multipart_uploads9802026/10/06 21:45:38 WARN Failed to register uploaded object key=734pisc8l7aadwa0szkaji53wq237yin.ls error="server returned 404: 404 page not found\n"9812026/10/06 21:45:38 WARN Failed to register uploaded object key=nar/1bdyq4swiggcldwiqm6yci2410i90lxyh8vysicjwc34ndxh4a9x.nar.zst error="server returned 404: 404 page not found\n"9822026/10/06 21:45:38 WARN Failed to register uploaded object key=dqkjs7qyfr47fz28vphcb5yr094iapw8.ls error="server returned 404: 404 page not found\n"9832026/10/06 21:45:38 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"9842026/10/06 21:45:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9852026/10/06 21:45:38 WARN Failed to register uploaded object key=icjc1fqklgi865b99fmxy06ya4jcqxjs.ls error="server returned 404: 404 page not found\n"9862026/10/06 21:45:38 INFO Signed narinfos id=1 count=39872026/10/06 21:45:38 INFO Uploading 3 narinfos9882026/10/06 21:45:38 INFO Vacuumed table table=closures9892026/10/06 21:45:38 INFO Vacuumed table table=objects9902026/10/06 21:45:38 INFO Received complete push request method=POST path=/api/pushes/1/complete9912026/10/06 21:45:38 WARN Failed to register uploaded object key=dqkjs7qyfr47fz28vphcb5yr094iapw8.narinfo error="server returned 404: 404 page not found\n"9922026/10/06 21:45:38 WARN Failed to register uploaded object key=734pisc8l7aadwa0szkaji53wq237yin.narinfo error="server returned 404: 404 page not found\n"9932026/10/06 21:45:38 WARN Failed to register uploaded object key=icjc1fqklgi865b99fmxy06ya4jcqxjs.narinfo error="server returned 404: 404 page not found\n"9942026/10/06 21:45:38 INFO Completed push id=19952026/10/06 21:45:38 INFO Upload complete. (77ms)996=== NAME TestClientPushesUseOnePush997 client_pushes_test.go:97: Retrieved narinfo from S3:998 StorePath: /nix/var/nix/builds/nix-98165-1098463425/TestClientPushesUseOnePush4219650169/001/store/icjc1fqklgi865b99fmxy06ya4jcqxjs-shared-dep999 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1000 Compression: zstd1001 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821002 NarSize: 1361003 References: 1004 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1005 client_pushes_test.go:97: Retrieved narinfo from S3:1006 StorePath: /nix/var/nix/builds/nix-98165-1098463425/TestClientPushesUseOnePush4219650169/001/store/734pisc8l7aadwa0szkaji53wq237yin-a1007 URL: nar/1bdyq4swiggcldwiqm6yci2410i90lxyh8vysicjwc34ndxh4a9x.nar.zst1008 Compression: zstd1009 NarHash: sha256:1bdyq4swiggcldwiqm6yci2410i90lxyh8vysicjwc34ndxh4a9x1010 NarSize: 2481011 References: /nix/var/nix/builds/nix-98165-1098463425/TestClientPushesUseOnePush4219650169/001/store/icjc1fqklgi865b99fmxy06ya4jcqxjs-shared-dep1012 CA: text:sha256:00cs76k48rblw5kbyii93dl9sm19zzlyg32yy24cc567lnm19hi81013 client_pushes_test.go:97: Retrieved narinfo from S3:1014 StorePath: /nix/var/nix/builds/nix-98165-1098463425/TestClientPushesUseOnePush4219650169/001/store/dqkjs7qyfr47fz28vphcb5yr094iapw8-b1015 URL: nar/1bdyq4swiggcldwiqm6yci2410i90lxyh8vysicjwc34ndxh4a9x.nar.zst1016 Compression: zstd1017 NarHash: sha256:1bdyq4swiggcldwiqm6yci2410i90lxyh8vysicjwc34ndxh4a9x1018 NarSize: 2481019 References: /nix/var/nix/builds/nix-98165-1098463425/TestClientPushesUseOnePush4219650169/001/store/icjc1fqklgi865b99fmxy06ya4jcqxjs-shared-dep1020 CA: text:sha256:00cs76k48rblw5kbyii93dl9sm19zzlyg32yy24cc567lnm19hi81021--- PASS: TestClientPushesUseOnePush (1.36s)1022=== CONT TestClientWithDependencies10232026/10/06 21:45:38 INFO lead: released remote=192.0.2.1:123410242026/10/06 21:45:38 INFO lead: acquired remote=192.0.2.1:12341025=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1026=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1027=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1028=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1029=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1030=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1031=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1032=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1033=== CONT TestReadProxy4041034=== NAME TestClientMultipleUploads1035 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-98165-1098463425/TestClientMultipleUploads356022646/001/store/lklyyk0dwz1j0rhhgwc81gi7wxwxaln0-test-file-0.txt1036--- PASS: TestService_ReadScope_PublicByDefault (1.05s)1037=== CONT TestReadProxyDisabled1038--- PASS: TestDeleteClosuresRacingPins (2.52s)1039=== CONT TestReadProxyRootRedirectsToIndexHTML1040=== NAME TestClientMultipleUploads1041 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-98165-1098463425/TestClientMultipleUploads356022646/001/store/bf655ypylimxaavg1y0gifcmh5wiacxi-test-file-1.txt1042 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-98165-1098463425/TestClientMultipleUploads356022646/001/store/80p6pngcqb8h7ksz8vj07kwk32aasqql-test-file-2.txt10432026/10/06 21:45:39 INFO Received push request method=POST path=/api/pushes10442026/10/06 21:45:39 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)10452026/10/06 21:45:39 INFO Uploading lklyyk0dwz1j0rhhgwc81gi7wxwxaln0-test-file-0.txt (160B)10462026/10/06 21:45:39 INFO Uploading bf655ypylimxaavg1y0gifcmh5wiacxi-test-file-1.txt (160B)10472026/10/06 21:45:39 INFO Uploading 80p6pngcqb8h7ksz8vj07kwk32aasqql-test-file-2.txt (160B)10482026/10/06 21:45:39 WARN Failed to register uploaded object key=bf655ypylimxaavg1y0gifcmh5wiacxi.ls error="server returned 404: 404 page not found\n"10492026/10/06 21:45:39 WARN Failed to register uploaded object key=80p6pngcqb8h7ksz8vj07kwk32aasqql.ls error="server returned 404: 404 page not found\n"10502026/10/06 21:45:39 WARN Failed to register uploaded object key=lklyyk0dwz1j0rhhgwc81gi7wxwxaln0.ls error="server returned 404: 404 page not found\n"10512026/10/06 21:45:39 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"10522026/10/06 21:45:39 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"10532026/10/06 21:45:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10542026/10/06 21:45:39 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"10552026/10/06 21:45:39 INFO Signed narinfos id=1 count=310562026/10/06 21:45:39 INFO Uploading 3 narinfos10572026/10/06 21:45:39 WARN Failed to register uploaded object key=bf655ypylimxaavg1y0gifcmh5wiacxi.narinfo error="server returned 404: 404 page not found\n"10582026/10/06 21:45:39 WARN Failed to register uploaded object key=lklyyk0dwz1j0rhhgwc81gi7wxwxaln0.narinfo error="server returned 404: 404 page not found\n"10592026/10/06 21:45:39 INFO Received complete push request method=POST path=/api/pushes/1/complete10602026/10/06 21:45:39 WARN Failed to register uploaded object key=80p6pngcqb8h7ksz8vj07kwk32aasqql.narinfo error="server returned 404: 404 page not found\n"10612026/10/06 21:45:39 INFO Completed push id=110622026/10/06 21:45:39 INFO Upload complete. (116ms)1063 client_integration_test.go:369: Uploaded 3 paths in 148.434333ms1064=== RUN TestService_RequireScope_OIDC/builder_may_write1065=== PAUSE TestService_RequireScope_OIDC/builder_may_write1066=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1067=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1068=== RUN TestService_RequireScope_OIDC/ops_may_admin1069=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1070=== RUN TestService_RequireScope_OIDC/ops_may_not_write1071=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1072=== RUN TestService_RequireScope_OIDC/reader_may_not_write1073=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1074=== RUN TestService_RequireScope_OIDC/static_token_may_admin1075=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1076=== RUN TestService_RequireScope_OIDC/static_token_may_write1077=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1078=== RUN TestService_RequireScope_OIDC/reader_may_read1079=== PAUSE TestService_RequireScope_OIDC/reader_may_read1080=== RUN TestService_RequireScope_OIDC/writer_implies_read1081=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1082=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1083=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1084=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1085=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1086=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1087=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1088=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1089=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1090=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1091=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1092=== CONT TestReadProxyConditionalGet1093--- PASS: TestClientMultipleUploads (1.30s)1094=== CONT TestReadProxyOutlastsServerWriteTimeout10952026/10/06 21:45:39 INFO Received push request method=POST path=/api/pushes10962026/10/06 21:45:39 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)10972026/10/06 21:45:39 INFO Uploading h1f81z9dcg9w423mzda4bzf3ncwffyqv-shared-dep (136B)10982026/10/06 21:45:39 INFO Uploading kmxwxmbsifbwql1lb1l4gx2d1zwhgayw-top (256B)10992026/10/06 21:45:39 WARN Failed to register uploaded object key=h1f81z9dcg9w423mzda4bzf3ncwffyqv.ls error="server returned 404: 404 page not found\n"11002026/10/06 21:45:39 WARN Failed to register uploaded object key=kmxwxmbsifbwql1lb1l4gx2d1zwhgayw.ls error="server returned 404: 404 page not found\n"11012026/10/06 21:45:39 WARN Failed to register uploaded object key=nar/1v9k8zgdxi2ybzfblk9x3q3xb0swrw4jwllllvr12j12j66rkcjr.nar.zst error="server returned 404: 404 page not found\n"11022026/10/06 21:45:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11032026/10/06 21:45:39 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11042026/10/06 21:45:39 INFO Signed narinfos id=1 count=211052026/10/06 21:45:39 INFO Uploading 2 narinfos11062026/10/06 21:45:39 INFO Received complete push request method=POST path=/api/pushes/1/complete11072026/10/06 21:45:39 WARN Failed to register uploaded object key=h1f81z9dcg9w423mzda4bzf3ncwffyqv.narinfo error="server returned 404: 404 page not found\n"11082026/10/06 21:45:39 WARN Failed to register uploaded object key=kmxwxmbsifbwql1lb1l4gx2d1zwhgayw.narinfo error="server returned 404: 404 page not found\n"11092026/10/06 21:45:39 INFO lead: released remote=192.0.2.1:12341110--- PASS: TestLeadElectsOneAndHandsOver (3.42s)1111=== CONT TestReadProxyHead11122026/10/06 21:45:39 INFO Completed push id=111132026/10/06 21:45:39 INFO Upload complete. (87ms)1114=== NAME TestClientSharedPathCommittedMidPush1115 client_integration_test.go:680: Retrieved narinfo from S3:1116 StorePath: /nix/var/nix/builds/nix-98165-1098463425/TestClientSharedPathCommittedMidPush2032940011/001/store/h1f81z9dcg9w423mzda4bzf3ncwffyqv-shared-dep1117 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1118 Compression: zstd1119 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821120 NarSize: 1361121 References: 1122 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1123 client_integration_test.go:680: Retrieved narinfo from S3:1124 StorePath: /nix/var/nix/builds/nix-98165-1098463425/TestClientSharedPathCommittedMidPush2032940011/001/store/kmxwxmbsifbwql1lb1l4gx2d1zwhgayw-top1125 URL: nar/1v9k8zgdxi2ybzfblk9x3q3xb0swrw4jwllllvr12j12j66rkcjr.nar.zst1126 Compression: zstd1127 NarHash: sha256:1v9k8zgdxi2ybzfblk9x3q3xb0swrw4jwllllvr12j12j66rkcjr1128 NarSize: 2561129 References: /nix/var/nix/builds/nix-98165-1098463425/TestClientSharedPathCommittedMidPush2032940011/001/store/h1f81z9dcg9w423mzda4bzf3ncwffyqv-shared-dep1130 CA: text:sha256:16by3skybvjc5lsphc3c5la221z947bhlm1sy2kmmjadz1h98kp11131--- PASS: TestClientSharedPathCommittedMidPush (1.39s)1132=== CONT TestReadProxyInvalidPath1133--- PASS: TestReadProxy404 (0.85s)1134=== CONT TestReadProxyNarinfoAlreadyDecompressed1135=== NAME TestClientWithDependencies1136 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-98165-1098463425/TestClientWithDependencies3318199495/001/store/3c3zshlhzrxysf3v0m2wha104vpznh84-test-script1137 client_integration_test.go:615: Found 1 dependencies (including self)11382026/10/06 21:45:39 INFO Received push request method=POST path=/api/pushes11392026/10/06 21:45:39 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11402026/10/06 21:45:39 INFO Uploading 3c3zshlhzrxysf3v0m2wha104vpznh84-test-script (136B)11412026/10/06 21:45:39 WARN Failed to register uploaded object key=3c3zshlhzrxysf3v0m2wha104vpznh84.ls error="server returned 404: 404 page not found\n"11422026/10/06 21:45:39 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"11432026/10/06 21:45:39 WARN Failed to register uploaded object key=log/zf6nhph3q3amqmnj94m8bmya9l3fhr09-test-script.drv error="server returned 404: 404 page not found\n"11442026/10/06 21:45:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11452026/10/06 21:45:39 INFO Signed narinfos id=1 count=111462026/10/06 21:45:39 INFO Uploading 1 narinfos1147--- PASS: TestReadProxyDisabled (0.84s)1148=== CONT TestReadProxyNarStreaming11492026/10/06 21:45:39 INFO Received complete push request method=POST path=/api/pushes/1/complete11502026/10/06 21:45:39 WARN Failed to register uploaded object key=3c3zshlhzrxysf3v0m2wha104vpznh84.narinfo error="server returned 404: 404 page not found\n"11512026/10/06 21:45:39 INFO Completed push id=111522026/10/06 21:45:39 INFO Upload complete. (119ms)1153=== NAME TestClientWithDependencies1154 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-98165-1098463425/TestClientWithDependencies3318199495/001/store) requires matching store prefix1155--- PASS: TestClientWithDependencies (1.77s)1156=== CONT TestReadProxyContentNegotiation1157--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.96s)1158=== CONT TestIsValidCachePath1159=== RUN TestIsValidCachePath/narinfo1160=== PAUSE TestIsValidCachePath/narinfo1161=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1162=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1163=== RUN TestIsValidCachePath/nar_zst1164=== PAUSE TestIsValidCachePath/nar_zst1165=== RUN TestIsValidCachePath/nar_xz1166=== PAUSE TestIsValidCachePath/nar_xz1167=== RUN TestIsValidCachePath/nar_bz21168=== PAUSE TestIsValidCachePath/nar_bz21169=== RUN TestIsValidCachePath/nar_uncompressed1170=== PAUSE TestIsValidCachePath/nar_uncompressed1171=== RUN TestIsValidCachePath/ls1172=== PAUSE TestIsValidCachePath/ls1173=== RUN TestIsValidCachePath/log1174=== PAUSE TestIsValidCachePath/log1175=== RUN TestIsValidCachePath/realisation1176=== PAUSE TestIsValidCachePath/realisation1177=== RUN TestIsValidCachePath/nix-cache-info1178=== PAUSE TestIsValidCachePath/nix-cache-info1179=== RUN TestIsValidCachePath/index.html1180=== PAUSE TestIsValidCachePath/index.html1181=== RUN TestIsValidCachePath/traversal_parent1182=== PAUSE TestIsValidCachePath/traversal_parent1183=== RUN TestIsValidCachePath/traversal_in_middle1184=== PAUSE TestIsValidCachePath/traversal_in_middle1185=== RUN TestIsValidCachePath/invalid_char_e1186=== PAUSE TestIsValidCachePath/invalid_char_e1187=== RUN TestIsValidCachePath/invalid_char_u1188=== PAUSE TestIsValidCachePath/invalid_char_u1189=== RUN TestIsValidCachePath/random_path1190=== PAUSE TestIsValidCachePath/random_path1191=== RUN TestIsValidCachePath/empty1192=== PAUSE TestIsValidCachePath/empty1193=== RUN TestIsValidCachePath/leading_slash1194=== PAUSE TestIsValidCachePath/leading_slash1195=== RUN TestIsValidCachePath/wrong_extension1196=== PAUSE TestIsValidCachePath/wrong_extension1197=== RUN TestIsValidCachePath/short_hash1198=== PAUSE TestIsValidCachePath/short_hash1199=== CONT TestReadProxyNarinfo1200=== NAME TestPinProtectsFromGC1201 client_integration_test.go:840: Pin successfully protected closure from garbage collection1202--- PASS: TestPinProtectsFromGC (5.23s)1203=== CONT TestClientErrorHandling1204=== RUN TestClientErrorHandling/InvalidStorePath1205=== PAUSE TestClientErrorHandling/InvalidStorePath1206=== RUN TestClientErrorHandling/InvalidAuthToken1207=== PAUSE TestClientErrorHandling/InvalidAuthToken1208=== RUN TestClientErrorHandling/ServerNotAvailable1209=== PAUSE TestClientErrorHandling/ServerNotAvailable1210=== CONT TestClientIntegration1211--- PASS: TestReadProxyConditionalGet (1.13s)1212=== CONT TestClientCADerivations1213--- PASS: TestReadProxyInvalidPath (1.06s)1214=== CONT TestService_Rustfstest1215--- PASS: TestReadProxyHead (1.30s)1216=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT1217--- PASS: TestReadProxyNarinfoAlreadyDecompressed (1.43s)1218=== CONT TestCompleteMultipartUnregistered1219--- PASS: TestReadProxyNarStreaming (1.45s)1220=== CONT TestService_verifyS3Integrity1221--- PASS: TestReadProxyContentNegotiation (1.60s)1222=== CONT TestService_createPendingClosureHandler12232026/10/06 21:45:41 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1224--- PASS: TestReadProxyNarinfo (1.77s)1225=== CONT TestService_cleanupPendingClosuresHandler1226=== NAME TestClientIntegration1227 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-98165-1098463425/TestClientIntegration2885697115/002/store/0cc6lkaz673n630n9880n3m4iayrwh87-test-file.txt12282026/10/06 21:45:42 INFO Received push request method=POST path=/api/pushes12292026/10/06 21:45:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12302026/10/06 21:45:42 INFO Uploading 0cc6lkaz673n630n9880n3m4iayrwh87-test-file.txt (152B)12312026/10/06 21:45:42 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"12322026/10/06 21:45:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12332026/10/06 21:45:42 WARN Failed to register uploaded object key=0cc6lkaz673n630n9880n3m4iayrwh87.ls error="server returned 404: 404 page not found\n"12342026/10/06 21:45:42 INFO Signed narinfos id=1 count=112352026/10/06 21:45:42 INFO Uploading 1 narinfos12362026/10/06 21:45:42 INFO Received complete push request method=POST path=/api/pushes/1/complete12372026/10/06 21:45:42 WARN Failed to register uploaded object key=0cc6lkaz673n630n9880n3m4iayrwh87.narinfo error="server returned 404: 404 page not found\n"12382026/10/06 21:45:42 INFO Completed push id=112392026/10/06 21:45:42 INFO Upload complete. (115ms)12402026/10/06 21:45:42 INFO All 1 paths already cached1241 client_integration_test.go:312: Retrieved narinfo from S3:1242 StorePath: /nix/var/nix/builds/nix-98165-1098463425/TestClientIntegration2885697115/002/store/0cc6lkaz673n630n9880n3m4iayrwh87-test-file.txt1243 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1244 Compression: zstd1245 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11246 NarSize: 1521247 References: 1248 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11249 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1250 client_integration_test.go:313: Decompressed .ls content (64 bytes):1251 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1252 client_integration_test.go:316: Testing garbage collection...1253--- PASS: TestConnectWaitsForAPeerMigration (6.18s)1254=== CONT TestUploadHandlersRejectOversizedBody1255=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1256=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1257=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1258=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1259=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1260=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1261=== CONT TestUploadHandlersRejectInvalidKeys1262=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1263=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1264=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1265=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1266=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1267=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1268=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1269=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1270=== CONT TestIsValidUploadKey1271=== RUN TestIsValidUploadKey/narinfo1272=== PAUSE TestIsValidUploadKey/narinfo1273=== RUN TestIsValidUploadKey/nar_zst1274=== PAUSE TestIsValidUploadKey/nar_zst1275=== RUN TestIsValidUploadKey/nar_xz1276=== PAUSE TestIsValidUploadKey/nar_xz1277=== RUN TestIsValidUploadKey/nar_plain1278=== PAUSE TestIsValidUploadKey/nar_plain1279=== RUN TestIsValidUploadKey/listing1280=== PAUSE TestIsValidUploadKey/listing1281=== RUN TestIsValidUploadKey/build_log1282=== PAUSE TestIsValidUploadKey/build_log1283=== RUN TestIsValidUploadKey/build_log_home-manager_file1284=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1285=== RUN TestIsValidUploadKey/build_log_plus_in_name1286=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1287=== RUN TestIsValidUploadKey/build_log_question_mark1288=== PAUSE TestIsValidUploadKey/build_log_question_mark1289=== RUN TestIsValidUploadKey/build_log_equals1290=== PAUSE TestIsValidUploadKey/build_log_equals1291=== RUN TestIsValidUploadKey/realisation1292=== PAUSE TestIsValidUploadKey/realisation1293=== RUN TestIsValidUploadKey/realisation_plus_in_output1294=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1295=== RUN TestIsValidUploadKey/nix-cache-info1296=== PAUSE TestIsValidUploadKey/nix-cache-info1297=== RUN TestIsValidUploadKey/index.html1298=== PAUSE TestIsValidUploadKey/index.html1299=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1300=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1301=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1302=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1303=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1304=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1305=== RUN TestIsValidUploadKey/traversal1306=== PAUSE TestIsValidUploadKey/traversal1307=== RUN TestIsValidUploadKey/traversal_nar1308=== PAUSE TestIsValidUploadKey/traversal_nar1309=== RUN TestIsValidUploadKey/absolute1310=== PAUSE TestIsValidUploadKey/absolute1311=== RUN TestIsValidUploadKey/empty_key1312=== PAUSE TestIsValidUploadKey/empty_key1313=== RUN TestIsValidUploadKey/unknown_type1314=== PAUSE TestIsValidUploadKey/unknown_type1315=== CONT TestPendingClosureWriteTimeout1316=== RUN TestPendingClosureWriteTimeout/empty1317=== PAUSE TestPendingClosureWriteTimeout/empty1318=== RUN TestPendingClosureWriteTimeout/400_objects1319=== PAUSE TestPendingClosureWriteTimeout/400_objects1320=== RUN TestPendingClosureWriteTimeout/670k_objects1321=== PAUSE TestPendingClosureWriteTimeout/670k_objects1322=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1323=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1324=== CONT TestProxyWriteTimeout1325=== RUN TestProxyWriteTimeout/narinfo1326=== PAUSE TestProxyWriteTimeout/narinfo1327=== RUN TestProxyWriteTimeout/1_GiB_nar1328=== PAUSE TestProxyWriteTimeout/1_GiB_nar1329=== RUN TestProxyWriteTimeout/10_GiB_nar1330=== PAUSE TestProxyWriteTimeout/10_GiB_nar1331=== RUN TestProxyWriteTimeout/unknown_size1332=== PAUSE TestProxyWriteTimeout/unknown_size1333=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle13342026/10/06 21:45:42 INFO Starting cleanup of old closures method=DELETE path=/api/closures13352026/10/06 21:45:42 INFO Garbage collection started13362026/10/06 21:45:42 INFO Aborted multipart uploads count=0 kept=013372026/10/06 21:45:42 WARN Force mode enabled - objects will be deleted immediately without grace period13382026/10/06 21:45:42 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=013392026/10/06 21:45:42 INFO Vacuumed table table=pending_closures13402026/10/06 21:45:42 INFO Vacuumed table table=pending_objects13412026/10/06 21:45:42 INFO Vacuumed table table=multipart_uploads13422026/10/06 21:45:42 INFO Vacuumed table table=closures13432026/10/06 21:45:42 INFO Vacuumed table table=objects1344--- PASS: TestService_Rustfstest (1.99s)1345=== CONT TestSkippedUploadsHandler13462026/10/06 21:45:42 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001347--- PASS: TestSkippedUploadsHandler (0.00s)1348=== CONT TestParseSize1349--- PASS: TestParseSize (0.00s)1350=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1351=== NAME TestClientCADerivations1352 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-98165-1098463425/TestClientCADerivations3335565161/001/store/l2nxvnyf6fzpgvd2g178r1cwf87a9crw-ca-test13532026/10/06 21:45:42 INFO Received uploads request method=POST path=/api/pending_closures1354 client_ca_test.go:139: Found 1 dependencies (including self)1355--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (2.02s)1356=== CONT TestService_ReadAuthMiddleware13572026/10/06 21:45:42 INFO Received push request method=POST path=/api/pushes13582026/10/06 21:45:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13592026/10/06 21:45:42 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1360--- PASS: TestCompleteMultipartUnregistered (1.81s)1361=== CONT TestProxyHeadersOnlyTrustedOnSocket13622026/10/06 21:45:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13632026/10/06 21:45:42 INFO Uploading l2nxvnyf6fzpgvd2g178r1cwf87a9crw-ca-test (144B)13642026/10/06 21:45:42 WARN Failed to register uploaded object key=l2nxvnyf6fzpgvd2g178r1cwf87a9crw.ls error="server returned 404: 404 page not found\n"13652026/10/06 21:45:42 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"13662026/10/06 21:45:42 WARN Failed to register uploaded object key=log/w379c8s2iz7gxq4cn9plwrwwmjqyacnz-ca-test.drv error="server returned 404: 404 page not found\n"13672026/10/06 21:45:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13682026/10/06 21:45:42 INFO Signed narinfos id=1 count=113692026/10/06 21:45:42 INFO Uploading 1 narinfos13702026/10/06 21:45:42 INFO Received complete push request method=POST path=/api/pushes/1/complete13712026/10/06 21:45:42 WARN Failed to register uploaded object key=l2nxvnyf6fzpgvd2g178r1cwf87a9crw.narinfo error="server returned 404: 404 page not found\n"13722026/10/06 21:45:42 INFO Completed push id=113732026/10/06 21:45:42 INFO Upload complete. (156ms)1374=== NAME TestClientCADerivations1375 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-98165-1098463425/TestClientCADerivations3335565161/001/store/l2nxvnyf6fzpgvd2g178r1cwf87a9crw-ca-test1376 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1377 Compression: zstd1378 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1379 NarSize: 1441380 References: 1381 Deriver: /nix/var/nix/builds/nix-98165-1098463425/TestClientCADerivations3335565161/001/store/w379c8s2iz7gxq4cn9plwrwwmjqyacnz-ca-test.drv1382 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1383 client_ca_test.go:185: Checking for realisation files in S3...1384 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1385 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1386 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket42?endpoint=http://localhost:55206&region=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-98165-1098463425/TestClientCADerivations3335565161/001/store'1387 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11388--- PASS: TestClientCADerivations (2.70s)1389=== CONT TestService_AuthMiddleware_MTLSProxyHeader13902026/10/06 21:45:43 INFO Received uploads request method=POST path=/api/pending_closures13912026/10/06 21:45:43 INFO Received uploads request method=POST path=/api/pending_closures13922026/10/06 21:45:43 INFO Received uploads request method=POST path=/api/pending_closures13932026/10/06 21:45:43 INFO Received uploads request method=POST path=/api/pending_closures13942026/10/06 21:45:43 INFO Received cleanup request method=DELETE path=/api/pending_closures13952026/10/06 21:45:43 INFO Aborted multipart uploads count=0 kept=013962026/10/06 21:45:43 INFO Received uploads request method=POST path=/api/pending_closures13972026/10/06 21:45:43 INFO Received cleanup request method=DELETE path=/api/pending_closures13982026/10/06 21:45:43 INFO Aborted multipart uploads count=1 kept=013992026/10/06 21:45:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14002026-10-06 21:45:43.776 UTC [98536] ERROR: Closure does not exist: id=114012026-10-06 21:45:43.776 UTC [98536] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE14022026-10-06 21:45:43.776 UTC [98536] STATEMENT: -- name: CommitPendingClosure :exec1403 SELECT commit_pending_closure($1::bigint)1404 1405--- PASS: TestService_cleanupPendingClosuresHandler (2.01s)1406=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit14072026/10/06 21:45:44 INFO Received uploads request method=POST path=/api/pending_closures14082026/10/06 21:45:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14092026/10/06 21:45:44 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=OGY1NTVjNjMtZjI3OC00NmUwLTg2ZDAtZmNkNDlkM2Y3NDgzLjZmNmFiNGMyLTk5OWQtNDYzMC1iZGIxLTVlZDA3MTA2ZGI0ZngxNzkxMzIzMTQzMjAzMjE4MDAw parts=1014102026/10/06 21:45:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14112026/10/06 21:45:44 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01412=== NAME TestClientIntegration1413 client_integration_test.go:323: Objects in database after GC:1414 client_integration_test.go:323: Successfully deleted all objects with GC --force14152026/10/06 21:45:44 INFO Completed upload id=114162026/10/06 21:45:44 INFO Received uploads request method=POST path=/api/pending_closures14172026/10/06 21:45:44 INFO Received uploads request method=POST path=/api/pending_closures14182026/10/06 21:45:44 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo14192026/10/06 21:45:44 WARN Found objects in DB but missing from S3, will re-upload count=11420--- PASS: TestService_verifyS3Integrity (3.05s)1421=== CONT TestPresignedUploadRegisteredBeforeCommit1422--- PASS: TestClientIntegration (4.28s)1423=== CONT TestCompletedNarNotReofferedAcrossClosures1424--- PASS: TestReadProxyOutlastsServerWriteTimeout (5.18s)1425=== CONT TestCompleteMultipartUpload_ErrorButObjectExists14262026/10/06 21:45:44 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"14272026/10/06 21:45:44 WARN mTLS auth: bound subjects configured but subject DN unavailable14282026/10/06 21:45:44 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1429--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (1.97s)1430=== CONT TestRedundantMultipartUpload14312026/10/06 21:45:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14322026/10/06 21:45:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14332026/10/06 21:45:44 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=OGY1NTVjNjMtZjI3OC00NmUwLTg2ZDAtZmNkNDlkM2Y3NDgzLmY0N2U3NDYxLWQ3M2QtNDdiNS05NWQ2LTUyOWE2ZmUyZjA3ZngxNzkxMzIzMTQzNDUwMDA4MDAw parts=1014342026/10/06 21:45:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14352026/10/06 21:45:44 INFO Completed upload id=114362026/10/06 21:45:44 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000014372026/10/06 21:45:44 INFO Received uploads request method=POST path=/api/pending_closures14382026/10/06 21:45:44 INFO Starting cleanup of old closures method=DELETE path=/api/closures14392026/10/06 21:45:44 INFO Aborted multipart uploads count=0 kept=014402026/10/06 21:45:44 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=014412026/10/06 21:45:44 INFO Vacuumed table table=pending_closures14422026/10/06 21:45:44 INFO Vacuumed table table=pending_objects1443--- PASS: TestService_ReadAuthMiddleware (2.02s)1444=== CONT TestPush_SignsNarinfosOfItsPendingObjects14452026/10/06 21:45:44 INFO Vacuumed table table=multipart_uploads14462026/10/06 21:45:44 INFO Vacuumed table table=closures14472026/10/06 21:45:44 INFO Vacuumed table table=objects14482026/10/06 21:45:44 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001449--- PASS: TestService_createPendingClosureHandler (3.32s)1450=== CONT TestPush_RejectsBadRequests14512026/10/06 21:45:44 INFO Starting HTTP server address=/nix/var/nix/builds/nix-98165-1098463425/TestProxyHeadersOnlyTrustedOnSocket4271269367/001/proxy.sock14522026/10/06 21:45:44 INFO Starting HTTP server address=127.0.0.1:5549814532026/10/06 21:45:44 WARN mTLS auth: subject not in bound subjects subject="CN=someone"14542026/10/06 21:45:44 INFO Shutdown signal received, draining in-flight requests timeout=10s1455--- PASS: TestProxyHeadersOnlyTrustedOnSocket (2.13s)1456=== CONT TestPush_CompleteCommitsEveryRoot1457--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (2.12s)1458=== CONT TestPush_RootsAreLockedInByteOrder14592026/10/06 21:45:45 INFO Received push request method=POST path=/api/pushes14602026/10/06 21:45:45 INFO Received complete push request method=POST path=/api/pushes/1/complete14612026/10/06 21:45:45 INFO Completed push id=114622026/10/06 21:45:45 INFO Received push request method=POST path=/api/pushes14632026/10/06 21:45:45 INFO Aborted multipart uploads count=0 kept=014642026/10/06 21:45:45 WARN Force mode enabled - objects will be deleted immediately without grace period14652026/10/06 21:45:45 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=014662026/10/06 21:45:45 INFO Vacuumed table table=pending_closures14672026/10/06 21:45:45 INFO Vacuumed table table=pending_objects14682026/10/06 21:45:45 INFO Vacuumed table table=multipart_uploads14692026/10/06 21:45:45 INFO Vacuumed table table=closures14702026/10/06 21:45:45 INFO Vacuumed table table=objects14712026/10/06 21:45:45 INFO Received complete push request method=POST path=/api/pushes/2/complete14722026/10/06 21:45:45 INFO Completed push id=21473--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (1.88s)1474=== CONT TestPush_CompleteWaitsForCleanupOfThePush14752026/10/06 21:45:45 INFO Received uploads request method=POST path=/api/pending_closures14762026/10/06 21:45:45 INFO Received uploads request method=POST path=/api/pending_closures14772026/10/06 21:45:46 INFO Received uploads request method=POST path=/api/pending_closures14782026/10/06 21:45:46 INFO Received uploads request method=POST path=/api/pending_closures14792026/10/06 21:45:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14802026/10/06 21:45:46 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OGY1NTVjNjMtZjI3OC00NmUwLTg2ZDAtZmNkNDlkM2Y3NDgzLjhmMTBlMjQ5LTM4OGMtNDE4ZS1hMTRlLTRlZDA2YjNjOGE5MHgxNzkxMzIzMTQ2MjI5NDcxMDAw14812026/10/06 21:45:46 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OGY1NTVjNjMtZjI3OC00NmUwLTg2ZDAtZmNkNDlkM2Y3NDgzLjhmMTBlMjQ5LTM4OGMtNDE4ZS1hMTRlLTRlZDA2YjNjOGE5MHgxNzkxMzIzMTQ2MjI5NDcxMDAw parts=11482--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.98s)1483=== CONT TestPush_RepeatedRootCommitsOnce14842026/10/06 21:45:46 INFO Received uploads request method=POST path=/api/pending_closures14852026/10/06 21:45:46 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst14862026/10/06 21:45:46 INFO Received uploads request method=POST path=/api/pending_closures1487--- PASS: TestPresignedUploadRegisteredBeforeCommit (2.18s)1488=== CONT TestObjectStatsLargeCommit14892026/10/06 21:45:46 INFO Received push request method=POST path=/api/pushes14902026/10/06 21:45:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14912026/10/06 21:45:46 INFO Signed narinfos id=1 count=114922026/10/06 21:45:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14932026/10/06 21:45:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14942026/10/06 21:45:46 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"14952026/10/06 21:45:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14962026/10/06 21:45:46 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"14972026/10/06 21:45:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14982026/10/06 21:45:46 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=114992026/10/06 21:45:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15002026/10/06 21:45:46 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1501--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (2.00s)1502=== CONT TestPresentNotReportedWhileGCDeletesClosure1503=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1504=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1505=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1506=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1507=== CONT TestPresentRefreshesOnlyStaleClosures1508=== RUN TestPush_RejectsBadRequests/no_roots1509=== PAUSE TestPush_RejectsBadRequests/no_roots1510=== RUN TestPush_RejectsBadRequests/no_objects1511=== PAUSE TestPush_RejectsBadRequests/no_objects1512=== RUN TestPush_RejectsBadRequests/bad_root1513=== PAUSE TestPush_RejectsBadRequests/bad_root1514=== RUN TestPush_RejectsBadRequests/root_not_in_objects1515=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1516=== CONT TestPresentReportsOnlyClosureRoots15172026/10/06 21:45:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15182026/10/06 21:45:47 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=OGY1NTVjNjMtZjI3OC00NmUwLTg2ZDAtZmNkNDlkM2Y3NDgzLmM1ZjAzZTUwLTI4NDYtNGFhYS05NTExLTM5NGYzMTgwNjJkYXgxNzkxMzIzMTQ1Nzc2OTE0MDAw parts=1215192026/10/06 21:45:47 INFO Received uploads request method=POST path=/api/pending_closures1520--- PASS: TestCompletedNarNotReofferedAcrossClosures (2.68s)1521=== CONT TestCreatePin_ReservedPins15222026/10/06 21:45:47 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55522/oidc15232026/10/06 21:45:47 INFO Received push request method=POST path=/api/pushes15242026/10/06 21:45:47 INFO Received complete push request method=POST path=/api/pushes/1/complete15252026/10/06 21:45:47 INFO Completed push id=11526--- PASS: TestPush_CompleteCommitsEveryRoot (2.30s)1527=== CONT TestOrphanedObjectsGCStressTest15282026/10/06 21:45:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15292026/10/06 21:45:47 INFO Received push request method=POST path=/api/pushes15302026/10/06 21:45:47 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=OGY1NTVjNjMtZjI3OC00NmUwLTg2ZDAtZmNkNDlkM2Y3NDgzLmNjNmE2MWVlLWNlY2EtNGRmNi1hN2QzLTNiM2EwZTIyMGZkNXgxNzkxMzIzMTQ1OTkxMjMzMDAw parts=1215312026/10/06 21:45:47 INFO Received uploads request method=POST path=/api/pending_closures15322026/10/06 21:45:47 INFO Received uploads request method=POST path=/api/pending_closures15332026-10-06 21:45:47.509 UTC [98591] ERROR: could not obtain lock on row in relation "closures"15342026-10-06 21:45:47.509 UTC [98591] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT15352026-10-06 21:45:47.509 UTC [98591] ERROR: could not obtain lock on row in relation "closures"15362026-10-06 21:45:47.509 UTC [98591] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT15372026-10-06 21:45:47.509 UTC [98591] ERROR: could not obtain lock on row in relation "closures"15382026-10-06 21:45:47.509 UTC [98591] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT15392026-10-06 21:45:47.509 UTC [98591] ERROR: could not obtain lock on row in relation "closures"15402026-10-06 21:45:47.509 UTC [98591] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT15412026-10-06 21:45:47.509 UTC [98591] ERROR: could not obtain lock on row in relation "closures"15422026-10-06 21:45:47.509 UTC [98591] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1543--- PASS: TestPush_RootsAreLockedInByteOrder (2.31s)1544=== CONT TestOrphanedObjectsGC15452026/10/06 21:45:47 INFO Received push request method=POST path=/api/pushes15462026-10-06 21:45:47.995 UTC [98594] ERROR: Push does not exist: id=115472026-10-06 21:45:47.995 UTC [98594] CONTEXT: PL/pgSQL function commit_push(bigint) line 10 at RAISE15482026-10-06 21:45:47.995 UTC [98594] STATEMENT: SELECT commit_push($1)1549--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (2.34s)1550=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded15512026/10/06 21:45:48 INFO Received push request method=POST path=/api/pushes15522026/10/06 21:45:48 INFO Received complete push request method=POST path=/api/pushes/1/complete15532026/10/06 21:45:48 INFO Completed push id=11554--- PASS: TestPush_RepeatedRootCommitsOnce (1.68s)1555=== CONT TestObjectStatsTrigger15562026/10/06 21:45:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15572026/10/06 21:45:48 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=OGY1NTVjNjMtZjI3OC00NmUwLTg2ZDAtZmNkNDlkM2Y3NDgzLjNiOTcxOWViLTU5MTItNDY1Mi04MDFjLTE2ZjQwMTRjNGVkM3gxNzkxMzIzMTQ3NDIxMzUyMDAw error="Get \"http://127.0.0.1:1/bucket56/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"15582026/10/06 21:45:48 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=OGY1NTVjNjMtZjI3OC00NmUwLTg2ZDAtZmNkNDlkM2Y3NDgzLmRiN2I3ZWQyLTM5Y2EtNDY4MS1hYzBmLWQ4NzZiMWVmMjk0MngxNzkxMzIzMTQ3NDAxOTQyMDAw parts=1215592026/10/06 21:45:48 INFO Received cleanup request method=DELETE path=/api/pending_closures15602026/10/06 21:45:48 INFO Aborted multipart uploads count=1 kept=01561--- PASS: TestRedundantMultipartUpload (4.13s)1562=== CONT TestPendingCleanupUsesOneCutoff1563--- PASS: TestPresentRefreshesOnlyStaleClosures (1.95s)1564=== CONT TestMultipartCleanup15652026/10/06 21:45:48 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux15662026/10/06 21:45:48 WARN Refused reserved pin name=worker-x86_64-linux15672026/10/06 21:45:48 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux15682026/10/06 21:45:48 INFO Received create pin request method=POST path=/api/pins/my-app15692026/10/06 21:45:48 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1570--- PASS: TestCreatePin_ReservedPins (1.78s)1571=== CONT TestServerTLSConfig1572=== RUN TestServerTLSConfig/no_client_CA1573=== PAUSE TestServerTLSConfig/no_client_CA1574=== RUN TestServerTLSConfig/missing_CA_file1575=== PAUSE TestServerTLSConfig/missing_CA_file1576=== RUN TestServerTLSConfig/not_a_PEM_file1577=== PAUSE TestServerTLSConfig/not_a_PEM_file1578=== CONT TestService_NativeMTLS1579--- PASS: TestPresentReportsOnlyClosureRoots (2.06s)1580=== CONT TestSweepSkipsRowsLockedByPush15812026/10/06 21:45:49 INFO Received uploads request method=POST path=/api/pending_closures1582--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (1.58s)1583=== CONT TestGCEndsOnShutdown1584=== RUN TestGCEndsOnShutdown/before_the_run1585=== PAUSE TestGCEndsOnShutdown/before_the_run1586=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1587=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1588=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1589=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1590=== CONT TestCommitRacingPendingCleanupKeepsObjects1591--- PASS: TestObjectStatsTrigger (1.62s)1592=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1593=== NAME TestOrphanedObjectsGC1594 orphaned_objects_gc_test.go:287: GC Test Summary:1595 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1596 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1597 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1598 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1599 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1600--- PASS: TestOrphanedObjectsGC (2.37s)1601=== CONT TestPushWaitsForSweepHoldingRow16022026/10/06 21:45:50 INFO Received uploads request method=POST path=/api/pending_closures16032026/10/06 21:45:50 INFO Received uploads request method=POST path=/api/pending_closures16042026/10/06 21:45:50 INFO Received cleanup request method=DELETE path=/api/pending_closures16052026/10/06 21:45:50 INFO Received uploads request method=POST path=/api/pending_closures16062026/10/06 21:45:50 INFO Received cleanup request method=DELETE path=/api/pending_closures16072026/10/06 21:45:50 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket74/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""16082026/10/06 21:45:50 INFO Aborted multipart uploads count=0 kept=116092026/10/06 21:45:50 INFO Received cleanup request method=DELETE path=/api/pending_closures16102026/10/06 21:45:50 INFO Aborted multipart uploads count=1 kept=01611--- PASS: TestMultipartCleanup (1.76s)1612=== CONT TestFailedS3DeleteKeepsTombstone16132026/10/06 21:45:50 WARN Rate limiter enabled after throttle name=s3-test rate=516142026/10/06 21:45:50 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1615=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1616 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101617 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001618--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (8.23s)1619=== CONT TestForceGCDuringPushOffersSweptObject1620=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1621=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1622=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1623=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1624=== CONT TestGetExistingObjectsLocksRows16252026/10/06 21:45:50 WARN mTLS auth: subject not in bound subjects subject="CN=reader"16262026/10/06 21:45:50 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1627--- PASS: TestService_NativeMTLS (1.71s)1628=== CONT TestRegisterCompletedObjectNeedsPendingRow16292026/10/06 21:45:51 INFO Aborted multipart uploads count=0 kept=016302026/10/06 21:45:51 WARN Force mode enabled - objects will be deleted immediately without grace period16312026/10/06 21:45:51 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=016322026/10/06 21:45:51 INFO Vacuumed table table=pending_closures16332026/10/06 21:45:51 INFO Vacuumed table table=pending_objects16342026/10/06 21:45:51 INFO Vacuumed table table=multipart_uploads16352026/10/06 21:45:51 INFO Vacuumed table table=closures16362026/10/06 21:45:51 INFO Vacuumed table table=objects16372026/10/06 21:45:51 INFO Aborted multipart uploads count=0 kept=016382026/10/06 21:45:51 WARN Force mode enabled - objects will be deleted immediately without grace period16392026/10/06 21:45:51 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=016402026/10/06 21:45:51 INFO Vacuumed table table=pending_closures16412026/10/06 21:45:51 INFO Vacuumed table table=pending_objects16422026/10/06 21:45:51 INFO Vacuumed table table=multipart_uploads16432026/10/06 21:45:51 INFO Vacuumed table table=closures16442026/10/06 21:45:51 INFO Vacuumed table table=objects1645--- PASS: TestSweepSkipsRowsLockedByPush (2.16s)1646=== CONT TestReadRedirectUsesPublicS3URL16472026/10/06 21:45:51 INFO Aborted multipart uploads count=0 kept=016482026/10/06 21:45:51 WARN Force mode enabled - objects will be deleted immediately without grace period16492026/10/06 21:45:51 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=016502026/10/06 21:45:51 INFO Vacuumed table table=pending_closures16512026/10/06 21:45:51 INFO Vacuumed table table=pending_objects16522026/10/06 21:45:51 INFO Vacuumed table table=multipart_uploads16532026/10/06 21:45:51 INFO Vacuumed table table=closures16542026/10/06 21:45:51 INFO Vacuumed table table=objects1655--- PASS: TestCommitRacingPendingCleanupKeepsObjects (2.43s)1656=== CONT TestPush_OverlappingRootsStoreOneRowPerKey16572026/10/06 21:45:52 INFO Received uploads request method=POST path=/api/pending_closures1658--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (2.58s)1659=== CONT TestTombstonedObjectOfferedWithoutWaiting16602026/10/06 21:45:52 INFO Received uploads request method=POST path=/api/pending_closures1661--- PASS: TestRegisterCompletedObjectNeedsPendingRow (2.16s)1662=== CONT TestGCSweepDeliversEachKeyOnce1663--- PASS: TestPushWaitsForSweepHoldingRow (2.95s)1664=== CONT TestGCSweepSkipsPendingObjects16652026/10/06 21:45:52 INFO Received uploads request method=POST path=/api/pending_closures16662026/10/06 21:45:53 INFO Aborted multipart uploads count=0 kept=016672026/10/06 21:45:53 WARN Force mode enabled - objects will be deleted immediately without grace period16682026/10/06 21:45:53 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."16692026/10/06 21:45:53 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1670--- PASS: TestFailedS3DeleteKeepsTombstone (2.63s)1671=== CONT TestReadProxyRangeRequest1672--- PASS: TestGetExistingObjectsLocksRows (2.69s)1673=== CONT TestSweepRechecksPendingAfterLocking1674--- PASS: TestReadRedirectUsesPublicS3URL (2.30s)1675=== CONT TestParseSingleRange1676=== RUN TestParseSingleRange/none1677=== PAUSE TestParseSingleRange/none1678=== RUN TestParseSingleRange/unknown_unit1679=== PAUSE TestParseSingleRange/unknown_unit1680=== RUN TestParseSingleRange/multi-range_ignored1681=== PAUSE TestParseSingleRange/multi-range_ignored1682=== RUN TestParseSingleRange/malformed_no_dash1683=== PAUSE TestParseSingleRange/malformed_no_dash1684=== RUN TestParseSingleRange/malformed_both_empty1685=== PAUSE TestParseSingleRange/malformed_both_empty1686=== RUN TestParseSingleRange/malformed_end_before_start1687=== PAUSE TestParseSingleRange/malformed_end_before_start1688=== RUN TestParseSingleRange/closed1689=== PAUSE TestParseSingleRange/closed1690=== RUN TestParseSingleRange/open-ended1691=== PAUSE TestParseSingleRange/open-ended1692=== RUN TestParseSingleRange/end_clamped_to_size1693=== PAUSE TestParseSingleRange/end_clamped_to_size1694=== RUN TestParseSingleRange/suffix1695=== PAUSE TestParseSingleRange/suffix1696=== RUN TestParseSingleRange/suffix_exceeds_size1697=== PAUSE TestParseSingleRange/suffix_exceeds_size1698=== RUN TestParseSingleRange/single_byte1699=== PAUSE TestParseSingleRange/single_byte1700=== RUN TestParseSingleRange/start_past_EOF1701=== PAUSE TestParseSingleRange/start_past_EOF1702=== RUN TestParseSingleRange/start_far_past_EOF1703=== PAUSE TestParseSingleRange/start_far_past_EOF1704=== CONT TestResolveDBConnectionString/flag_wins1705=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1706=== CONT TestResolveDBConnectionString/nothing_configured1707=== CONT TestResolveDBConnectionString/missing_file_is_an_error1708=== CONT TestResolveDBConnectionString/file_when_flag_empty1709=== CONT TestCacheConfigHandler/full_config,_no_issuer1710=== CONT TestCacheConfigHandler/no_signing_keys1711=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1712=== CONT TestCacheConfigHandler/no_cache_url_configured1713--- PASS: TestCacheConfigHandler (0.00s)1714 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1715 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1716 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1717 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1718=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1719=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected17202026/10/06 21:45:53 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]1721=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1722=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected17232026/10/06 21:45:53 WARN Authentication failed token_preview=eyJhbGciOi...gXSDC1F6og token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1724=== CONT TestService_RequireScope_OIDC/builder_may_write1725=== CONT TestService_RequireScope_OIDC/reader_may_read1726=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1727=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read17282026/10/06 21:45:53 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]1729=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1730=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1731=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1732=== CONT TestService_RequireScope_OIDC/writer_implies_read1733=== CONT TestService_RequireScope_OIDC/reader_may_not_write1734=== CONT TestService_RequireScope_OIDC/static_token_may_write1735=== CONT TestService_RequireScope_OIDC/static_token_may_admin1736=== CONT TestService_RequireScope_OIDC/ops_may_admin1737=== CONT TestService_RequireScope_OIDC/ops_may_not_write1738=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1739=== CONT TestIsValidCachePath/narinfo1740=== CONT TestIsValidCachePath/index.html1741=== CONT TestIsValidCachePath/short_hash1742=== CONT TestIsValidCachePath/wrong_extension1743=== CONT TestIsValidCachePath/leading_slash1744=== CONT TestIsValidCachePath/empty1745=== CONT TestIsValidCachePath/traversal_in_middle1746=== CONT TestIsValidCachePath/traversal_parent1747=== CONT TestIsValidCachePath/invalid_char_e1748=== CONT TestIsValidCachePath/random_path1749=== CONT TestIsValidCachePath/invalid_char_u1750=== CONT TestIsValidCachePath/nar_uncompressed1751=== CONT TestIsValidCachePath/nar_xz1752=== CONT TestIsValidCachePath/nar_bz21753=== CONT TestIsValidCachePath/nix-cache-info1754=== CONT TestIsValidCachePath/log1755=== CONT TestIsValidCachePath/realisation1756=== CONT TestIsValidCachePath/ls1757=== CONT TestIsValidCachePath/nar_zst1758=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1759--- PASS: TestIsValidCachePath (0.00s)1760 --- PASS: TestIsValidCachePath/narinfo (0.00s)1761 --- PASS: TestIsValidCachePath/index.html (0.00s)1762 --- PASS: TestIsValidCachePath/short_hash (0.00s)1763 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1764 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1765 --- PASS: TestIsValidCachePath/empty (0.00s)1766 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1767 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1768 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1769 --- PASS: TestIsValidCachePath/random_path (0.00s)1770 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1771 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1772 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1773 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1774 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1775 --- PASS: TestIsValidCachePath/log (0.00s)1776 --- PASS: TestIsValidCachePath/realisation (0.00s)1777 --- PASS: TestIsValidCachePath/ls (0.00s)1778 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1779 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1780=== CONT TestClientErrorHandling/InvalidStorePath1781--- PASS: TestService_RequireScope_OIDC (1.29s)1782 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1783 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1784 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1785 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1786 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1787 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1788 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1789 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1790 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1791 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1792 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1793 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1794 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1795 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1796--- PASS: TestResolveDBConnectionString (0.02s)1797 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1798 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1799 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1800 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1801 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1802--- PASS: TestService_AuthMiddleware_OIDC (0.88s)1803 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1804 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1805 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1806 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1807=== NAME TestOrphanedObjectsGCStressTest1808 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1809 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion18102026/10/06 21:45:53 INFO Received push request method=POST path=/api/pushes1811--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (2.04s)1812=== CONT TestClientErrorHandling/ServerNotAvailable18132026/10/06 21:45:54 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/present18142026/10/06 21:45:54 INFO Received uploads request method=POST path=/api/pending_closures1815--- PASS: TestTombstonedObjectOfferedWithoutWaiting (2.01s)1816=== CONT TestClientErrorHandling/InvalidAuthToken18172026/10/06 21:45:54 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=201.478725ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18182026/10/06 21:45:54 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=364.594522ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1819--- PASS: TestObjectStatsLargeCommit (8.11s)1820=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18212026/10/06 21:45:54 INFO Received uploads request method=POST path=/18222026/10/06 21:45:54 INFO Received uploads request method=POST path=/api/pending_closures18232026/10/06 21:45:54 INFO Aborted multipart uploads count=0 kept=018242026/10/06 21:45:54 WARN Force mode enabled - objects will be deleted immediately without grace period18252026/10/06 21:45:54 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=018262026/10/06 21:45:54 INFO Vacuumed table table=pending_closures18272026/10/06 21:45:54 INFO Vacuumed table table=pending_objects18282026/10/06 21:45:54 INFO Vacuumed table table=multipart_uploads18292026/10/06 21:45:54 INFO Vacuumed table table=closures18302026/10/06 21:45:54 INFO Vacuumed table table=objects1831--- PASS: TestGCSweepSkipsPendingObjects (2.00s)1832=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18332026/10/06 21:45:54 INFO Received request for more parts method=POST path=/1834=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18352026/10/06 21:45:54 INFO Received complete multipart upload request method=POST path=/1836=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info18372026/10/06 21:45:54 INFO Received uploads request method=POST path=/1838=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key18392026/10/06 21:45:54 INFO Received complete multipart upload request method=POST path=/1840=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key18412026/10/06 21:45:54 INFO Received request for more parts method=POST path=/1842=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal18432026/10/06 21:45:54 INFO Received uploads request method=POST path=/1844--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1845 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1846 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1847 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1848 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1849=== CONT TestIsValidUploadKey/narinfo1850=== CONT TestPendingClosureWriteTimeout/empty1851=== CONT TestIsValidUploadKey/realisation1852=== CONT TestIsValidUploadKey/build_log_equals1853=== CONT TestIsValidUploadKey/build_log_question_mark1854=== CONT TestIsValidUploadKey/build_log_plus_in_name1855=== CONT TestIsValidUploadKey/build_log_home-manager_file1856=== CONT TestIsValidUploadKey/build_log1857=== CONT TestIsValidUploadKey/listing1858=== CONT TestIsValidUploadKey/nar_plain1859=== CONT TestIsValidUploadKey/nar_xz1860=== CONT TestIsValidUploadKey/nar_zst1861=== CONT TestIsValidUploadKey/realisation_plus_in_output1862=== CONT TestIsValidUploadKey/unknown_type1863=== CONT TestIsValidUploadKey/empty_key1864=== CONT TestIsValidUploadKey/absolute1865=== CONT TestIsValidUploadKey/traversal_nar1866=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1867=== CONT TestIsValidUploadKey/index.html1868=== CONT TestIsValidUploadKey/nix-cache-info1869=== CONT TestIsValidUploadKey/traversal1870=== CONT TestPendingClosureWriteTimeout/670k_objects1871=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1872=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1873--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)1874 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1875 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1876 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.29s)1877=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1878--- PASS: TestIsValidUploadKey (0.00s)1879 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1880 --- PASS: TestIsValidUploadKey/realisation (0.00s)1881 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1882 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1883 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1884 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1885 --- PASS: TestIsValidUploadKey/build_log (0.00s)1886 --- PASS: TestIsValidUploadKey/listing (0.00s)1887 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1888 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1889 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1890 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1891 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1892 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1893 --- PASS: TestIsValidUploadKey/absolute (0.00s)1894 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1895 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1896 --- PASS: TestIsValidUploadKey/index.html (0.00s)1897 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1898 --- PASS: TestIsValidUploadKey/traversal (0.00s)1899 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1900 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1901=== CONT TestPendingClosureWriteTimeout/400_objects1902=== CONT TestProxyWriteTimeout/narinfo1903=== CONT TestProxyWriteTimeout/10_GiB_nar1904=== CONT TestProxyWriteTimeout/unknown_size1905=== CONT TestProxyWriteTimeout/1_GiB_nar1906=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1907--- PASS: TestProxyWriteTimeout (0.00s)1908 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1909 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1910 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1911 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)19122026/10/06 21:45:54 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=721.711016ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1913--- PASS: TestReadProxyRangeRequest (1.84s)1914=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1915=== NAME TestOrphanedObjectsGCStressTest1916 orphaned_objects_gc_test.go:503: Stress test completed successfully:1917 orphaned_objects_gc_test.go:504: - Active objects preserved: 201918 orphaned_objects_gc_test.go:505: - Objects deleted: 2101919 orphaned_objects_gc_test.go:506: - Total GC'd: 2101920--- PASS: TestOrphanedObjectsGCStressTest (7.75s)1921=== CONT TestPush_RejectsBadRequests/no_roots19222026/10/06 21:45:55 INFO Received push request method=POST path=/api/pushes1923=== CONT TestPush_RejectsBadRequests/bad_root19242026/10/06 21:45:55 INFO Received push request method=POST path=/api/pushes1925=== CONT TestPush_RejectsBadRequests/root_not_in_objects19262026/10/06 21:45:55 INFO Received push request method=POST path=/api/pushes1927=== CONT TestPush_RejectsBadRequests/no_objects19282026/10/06 21:45:55 INFO Received push request method=POST path=/api/pushes1929=== CONT TestServerTLSConfig/no_client_CA1930--- PASS: TestPush_RejectsBadRequests (2.13s)1931 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1932 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1933 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1934 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1935=== CONT TestServerTLSConfig/not_a_PEM_file1936=== CONT TestServerTLSConfig/missing_CA_file1937=== CONT TestGCEndsOnShutdown/before_the_run1938--- PASS: TestServerTLSConfig (0.00s)1939 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1940 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1941 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)19422026/10/06 21:45:55 INFO Aborted multipart uploads count=0 kept=019432026/10/06 21:45:55 WARN Force mode enabled - objects will be deleted immediately without grace period19442026/10/06 21:45:55 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=019452026/10/06 21:45:55 INFO Vacuumed table table=pending_closures19462026/10/06 21:45:55 INFO Vacuumed table table=pending_objects19472026/10/06 21:45:55 INFO Vacuumed table table=multipart_uploads19482026/10/06 21:45:55 INFO Vacuumed table table=closures19492026/10/06 21:45:55 INFO Vacuumed table table=objects1950--- PASS: TestGCSweepDeliversEachKeyOnce (2.71s)1951=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark19522026/10/06 21:45:55 INFO Aborted multipart uploads count=0 kept=019532026/10/06 21:45:55 WARN Force mode enabled - objects will be deleted immediately without grace period19542026/10/06 21:45:55 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=019552026/10/06 21:45:55 INFO Vacuumed table table=pending_closures19562026/10/06 21:45:55 INFO Vacuumed table table=pending_objects19572026/10/06 21:45:55 INFO Vacuumed table table=multipart_uploads19582026/10/06 21:45:55 INFO Vacuumed table table=closures19592026/10/06 21:45:55 INFO Vacuumed table table=objects1960--- PASS: TestSweepRechecksPendingAfterLocking (2.38s)1961=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete19622026/10/06 21:45:55 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.605001489s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1963=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows19642026/10/06 21:45:56 INFO Aborted multipart uploads count=1 kept=019652026/10/06 21:45:56 INFO Received cleanup request method=DELETE path=/api/pending_closures19662026/10/06 21:45:56 INFO Aborted multipart uploads count=1 kept=019672026/10/06 21:45:56 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"1968--- PASS: TestPendingCleanupUsesOneCutoff (7.52s)1969=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check19702026/10/06 21:45:56 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"1971=== CONT TestParseSingleRange/none1972=== CONT TestParseSingleRange/start_far_past_EOF1973=== CONT TestParseSingleRange/start_past_EOF1974=== CONT TestParseSingleRange/single_byte1975=== CONT TestParseSingleRange/suffix_exceeds_size1976=== CONT TestParseSingleRange/suffix1977=== CONT TestParseSingleRange/end_clamped_to_size1978=== CONT TestParseSingleRange/open-ended1979=== CONT TestParseSingleRange/closed1980=== CONT TestParseSingleRange/malformed_end_before_start1981=== CONT TestParseSingleRange/malformed_both_empty1982=== CONT TestParseSingleRange/malformed_no_dash1983=== CONT TestParseSingleRange/multi-range_ignored1984=== CONT TestParseSingleRange/unknown_unit1985--- PASS: TestParseSingleRange (0.00s)1986 --- PASS: TestParseSingleRange/none (0.00s)1987 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1988 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1989 --- PASS: TestParseSingleRange/single_byte (0.00s)1990 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1991 --- PASS: TestParseSingleRange/suffix (0.00s)1992 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1993 --- PASS: TestParseSingleRange/open-ended (0.00s)1994 --- PASS: TestParseSingleRange/closed (0.00s)1995 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1996 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1997 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1998 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1999 --- PASS: TestParseSingleRange/unknown_unit (0.00s)20002026/10/06 21:45:56 INFO Received uploads request method=POST path=/api/pending_closures20012026-10-06 21:45:56.864 UTC [98208] LOG: checkpoints are occurring too frequently (27 seconds apart)20022026-10-06 21:45:56.864 UTC [98208] HINT: Consider increasing the configuration parameter "max_wal_size".20032026-10-06 21:45:56.864 UTC [98208] LOG: checkpoint starting: wal20042026/10/06 21:45:57 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-config2005--- PASS: TestPendingClosureWriteTimeout (0.00s)2006 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2007 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2008 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2009 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (2.44s)20102026/10/06 21:45:57 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=209.469997ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20112026/10/06 21:45:57 INFO Aborted multipart uploads count=0 kept=020122026/10/06 21:45:57 WARN Force mode enabled - objects will be deleted immediately without grace period20132026-10-06 21:45:57.437 UTC [98779] ERROR: canceling statement due to user request20142026-10-06 21:45:57.437 UTC [98779] STATEMENT: -- name: MarkStaleObjects :execrows2015 WITH RECURSIVE ct AS (2016 SELECT timezone('UTC', now()) AS now2017 ),2018 closure_reach AS (2019 -- Start with all closure keys2020 SELECT o.key, o.refs2021 FROM objects o2022 INNER JOIN closures c ON o.key = c.key2023 UNION2024 -- Recursively add all referenced objects2025 SELECT o.key, o.refs2026 FROM objects o2027 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2028 ),2029 reachable_objects AS (2030 SELECT DISTINCT key FROM closure_reach2031 ),2032 stale_objects AS (2033 SELECT o.key2034 FROM objects AS o, ct2035 WHERE2036 NOT EXISTS (2037 SELECT 12038 FROM reachable_objects ro2039 WHERE ro.key = o.key2040 )2041 AND NOT EXISTS (2042 SELECT 12043 FROM pending_objects AS po2044 WHERE po.key = o.key2045 )2046 AND o.deleted_at IS NULL -- Only mark fresh objects2047 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2048 FOR UPDATE2049 )2050 UPDATE objects2051 SET2052 deleted_at = ct.now,2053 first_deleted_at = COALESCE(first_deleted_at, ct.now)2054 FROM stale_objects, ct2055 WHERE objects.key = stale_objects.key2056 2057--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2058 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (2.39s)2059 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (2.54s)20602026/10/06 21:45:57 INFO Aborted multipart uploads count=0 kept=020612026/10/06 21:45:57 WARN Force mode enabled - objects will be deleted immediately without grace period20622026/10/06 21:45:57 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:55206/bucket97/?delete=\": context canceled"2063--- PASS: TestGCEndsOnShutdown (0.00s)2064 --- PASS: TestGCEndsOnShutdown/before_the_run (2.16s)2065 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (2.01s)2066 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (1.99s)20672026/10/06 21:45:57 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=419.313507ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20682026/10/06 21:45:57 INFO Received uploads request method=POST path=/api/pending_closures20692026/10/06 21:45:57 INFO Aborted multipart uploads count=0 kept=020702026/10/06 21:45:57 WARN Force mode enabled - objects will be deleted immediately without grace period20712026/10/06 21:45:57 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=020722026/10/06 21:45:57 INFO Vacuumed table table=pending_closures20732026/10/06 21:45:57 INFO Vacuumed table table=pending_objects20742026/10/06 21:45:57 INFO Vacuumed table table=multipart_uploads20752026/10/06 21:45:57 INFO Vacuumed table table=closures20762026/10/06 21:45:57 INFO Vacuumed table table=objects20772026/10/06 21:45:57 INFO Received uploads request method=POST path=/api/pending_closures20782026/10/06 21:45:57 INFO Aborted multipart uploads count=0 kept=020792026/10/06 21:45:57 WARN Force mode enabled - objects will be deleted immediately without grace period20802026/10/06 21:45:57 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=020812026/10/06 21:45:57 INFO Vacuumed table table=pending_closures20822026/10/06 21:45:57 INFO Vacuumed table table=pending_objects20832026/10/06 21:45:57 INFO Vacuumed table table=multipart_uploads20842026/10/06 21:45:57 INFO Vacuumed table table=closures20852026/10/06 21:45:57 INFO Vacuumed table table=objects2086--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2087 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (2.08s)2088 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (1.75s)20892026/10/06 21:45:58 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=826.102593ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20902026/10/06 21:45:58 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.720955201s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20912026/10/06 21:46:00 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"20922026/10/06 21:46:00 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-config20932026/10/06 21:46:00 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=217.844572ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20942026/10/06 21:46:00 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=401.451251ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20952026/10/06 21:46:01 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=734.022434ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20962026/10/06 21:46:02 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.542513678s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20972026/10/06 21:46:03 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_closures20982026/10/06 21:46:03 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=194.831914ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20992026/10/06 21:46:03 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=425.297067ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21002026/10/06 21:46:04 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=874.235506ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21012026/10/06 21:46:05 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.741923926s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2102--- PASS: TestClientErrorHandling (0.00s)2103 --- PASS: TestClientErrorHandling/InvalidStorePath (2.23s)2104 --- PASS: TestClientErrorHandling/InvalidAuthToken (1.88s)2105 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.91s)2106PASS2107{"timestamp":"2026-10-06T21:46:06.948326Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:55487","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)"}21082026-10-06 21:46:07.096 UTC [98203] LOG: received smart shutdown request21092026-10-06 21:46:07.097 UTC [98203] LOG: background worker "logical replication launcher" (PID 98214) exited with exit code 121102026-10-06 21:46:08.343 UTC [98208] LOG: checkpoint complete: wrote 12490 buffers (76.2%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=10.771 s, sync=0.587 s, total=11.480 s; sync files=33709, longest=0.002 s, average=0.001 s; distance=533161 kB, estimate=533161 kB; lsn=0/22316750, redo lsn=0/2203770021112026-10-06 21:46:08.345 UTC [98208] LOG: shutting down21122026-10-06 21:46:08.345 UTC [98208] LOG: checkpoint starting: shutdown immediate21132026-10-06 21:46:08.352 UTC [98208] LOG: checkpoint complete: wrote 212 buffers (1.3%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.005 s, sync=0.003 s, total=0.008 s; sync files=128, longest=0.001 s, average=0.001 s; distance=2940 kB, estimate=480139 kB; lsn=0/223167C8, redo lsn=0/223167C821142026-10-06 21:46:08.359 UTC [98203] LOG: database system is shut down2115Running OIDC tests...2116=== RUN TestAudienceForIssuer2117=== PAUSE TestAudienceForIssuer2118=== RUN TestGlobMatch2119=== PAUSE TestGlobMatch2120=== RUN TestValidateToken_ValidToken2121=== PAUSE TestValidateToken_ValidToken2122=== RUN TestValidateToken_WrongAudience2123=== PAUSE TestValidateToken_WrongAudience2124=== RUN TestValidateToken_Expired2125=== PAUSE TestValidateToken_Expired2126=== RUN TestValidateToken_BoundClaimsMismatch2127=== PAUSE TestValidateToken_BoundClaimsMismatch2128=== RUN TestValidateToken_BoundSubjectMismatch2129=== PAUSE TestValidateToken_BoundSubjectMismatch2130=== RUN TestValidateToken_MultipleProviders2131=== PAUSE TestValidateToken_MultipleProviders2132=== RUN TestValidateToken_NoMatchingProvider2133=== PAUSE TestValidateToken_NoMatchingProvider2134=== RUN TestValidateToken_KubernetesServiceAccount2135=== PAUSE TestValidateToken_KubernetesServiceAccount2136=== RUN TestNewValidator_KubernetesRequiresCA2137=== PAUSE TestNewValidator_KubernetesRequiresCA2138=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2139=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2140=== RUN TestPins_ReservedForMatchingRule2141=== PAUSE TestPins_ReservedForMatchingRule2142=== RUN TestPins_TopLevelShorthand2143=== PAUSE TestPins_TopLevelShorthand2144=== RUN TestPins_ConfigValidation2145=== PAUSE TestPins_ConfigValidation2146=== RUN TestScopes_LegacyProviderDefaultsToWrite2147=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2148=== RUN TestScopes_Rules2149=== PAUSE TestScopes_Rules2150=== RUN TestScopes_ConfigValidation2151=== PAUSE TestScopes_ConfigValidation2152=== CONT TestAudienceForIssuer2153--- PASS: TestAudienceForIssuer (0.00s)2154=== CONT TestScopes_ConfigValidation2155=== CONT TestValidateToken_KubernetesServiceAccount2156=== CONT TestPins_TopLevelShorthand2157=== CONT TestValidateToken_BoundClaimsMismatch2158=== CONT TestValidateToken_BoundSubjectMismatch2159=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2160=== CONT TestPins_ReservedForMatchingRule2161=== CONT TestNewValidator_KubernetesRequiresCA2162--- PASS: TestScopes_ConfigValidation (0.00s)2163=== CONT TestValidateToken_ValidToken2164=== CONT TestValidateToken_WrongAudience2165=== CONT TestValidateToken_Expired21662026/10/06 21:46:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55699/oidc2167--- PASS: TestValidateToken_Expired (0.02s)2168=== CONT TestGlobMatch2169=== RUN TestGlobMatch/foo_foo2170=== PAUSE TestGlobMatch/foo_foo2171=== RUN TestGlobMatch/foo_bar2172=== PAUSE TestGlobMatch/foo_bar2173=== RUN TestGlobMatch/*_2174=== PAUSE TestGlobMatch/*_2175=== RUN TestGlobMatch/*_anything2176=== PAUSE TestGlobMatch/*_anything2177=== RUN TestGlobMatch/foo*_foo2178=== PAUSE TestGlobMatch/foo*_foo2179=== RUN TestGlobMatch/foo*_foobar2180=== PAUSE TestGlobMatch/foo*_foobar2181=== RUN TestGlobMatch/foo*_bar2182=== PAUSE TestGlobMatch/foo*_bar2183=== RUN TestGlobMatch/*bar_bar2184=== PAUSE TestGlobMatch/*bar_bar2185=== RUN TestGlobMatch/*bar_foobar2186=== PAUSE TestGlobMatch/*bar_foobar2187=== RUN TestGlobMatch/*bar_foo2188=== PAUSE TestGlobMatch/*bar_foo2189=== RUN TestGlobMatch/foo*bar_foobar2190=== PAUSE TestGlobMatch/foo*bar_foobar2191=== RUN TestGlobMatch/foo*bar_foo123bar2192=== PAUSE TestGlobMatch/foo*bar_foo123bar2193=== RUN TestGlobMatch/foo*bar_foobarbaz2194=== PAUSE TestGlobMatch/foo*bar_foobarbaz2195=== RUN TestGlobMatch/*/*_foo/bar2196=== PAUSE TestGlobMatch/*/*_foo/bar2197=== RUN TestGlobMatch/*/*_foo2198=== PAUSE TestGlobMatch/*/*_foo2199=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2200=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2201=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02202=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02203=== RUN TestGlobMatch/refs/*/main_refs/heads/main2204=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2205=== RUN TestGlobMatch/fo?_foo2206=== PAUSE TestGlobMatch/fo?_foo2207=== RUN TestGlobMatch/fo?_fo2208=== PAUSE TestGlobMatch/fo?_fo2209=== RUN TestGlobMatch/fo?_fooo2210=== PAUSE TestGlobMatch/fo?_fooo2211=== RUN TestGlobMatch/?oo_foo2212=== PAUSE TestGlobMatch/?oo_foo2213=== RUN TestGlobMatch/?oo_boo2214=== PAUSE TestGlobMatch/?oo_boo2215=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2216=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2217=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2218=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2219=== CONT TestScopes_LegacyProviderDefaultsToWrite22202026/10/06 21:46:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55705/oidc22212026/10/06 21:46:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55703/oidc22222026/10/06 21:46:09 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:557012223--- PASS: TestValidateToken_ValidToken (0.03s)2224=== CONT TestScopes_Rules2225--- PASS: TestPins_TopLevelShorthand (0.04s)2226=== CONT TestPins_ConfigValidation2227--- PASS: TestPins_ConfigValidation (0.00s)2228=== CONT TestValidateToken_NoMatchingProvider2229--- PASS: TestValidateToken_KubernetesServiceAccount (0.04s)2230=== CONT TestValidateToken_MultipleProviders22312026/10/06 21:46:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55707/oidc2232--- PASS: TestValidateToken_BoundClaimsMismatch (0.05s)2233=== CONT TestGlobMatch/foo_foo2234=== CONT TestGlobMatch/*/*_foo/bar2235=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2236=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2237=== CONT TestGlobMatch/?oo_boo2238=== CONT TestGlobMatch/?oo_foo2239=== CONT TestGlobMatch/fo?_fooo2240=== CONT TestGlobMatch/fo?_fo2241=== CONT TestGlobMatch/fo?_foo2242=== CONT TestGlobMatch/refs/*/main_refs/heads/main2243=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02244=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2245=== CONT TestGlobMatch/*/*_foo2246=== CONT TestGlobMatch/*bar_bar2247=== CONT TestGlobMatch/foo*bar_foobarbaz2248=== CONT TestGlobMatch/foo*bar_foo123bar2249=== CONT TestGlobMatch/foo*bar_foobar2250=== CONT TestGlobMatch/*bar_foo2251=== CONT TestGlobMatch/*bar_foobar2252=== CONT TestGlobMatch/foo*_foo2253=== CONT TestGlobMatch/foo*_bar2254=== CONT TestGlobMatch/foo*_foobar2255=== CONT TestGlobMatch/*_2256=== CONT TestGlobMatch/*_anything2257=== CONT TestGlobMatch/foo_bar2258--- PASS: TestGlobMatch (0.00s)2259 --- PASS: TestGlobMatch/foo_foo (0.00s)2260 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2261 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2262 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2263 --- PASS: TestGlobMatch/?oo_boo (0.00s)2264 --- PASS: TestGlobMatch/?oo_foo (0.00s)2265 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2266 --- PASS: TestGlobMatch/fo?_fo (0.00s)2267 --- PASS: TestGlobMatch/fo?_foo (0.00s)2268 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2269 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2270 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2271 --- PASS: TestGlobMatch/*/*_foo (0.00s)2272 --- PASS: TestGlobMatch/*bar_bar (0.00s)2273 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2274 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2275 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2276 --- PASS: TestGlobMatch/*bar_foo (0.00s)2277 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2278 --- PASS: TestGlobMatch/foo*_foo (0.00s)2279 --- PASS: TestGlobMatch/foo*_bar (0.00s)2280 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2281 --- PASS: TestGlobMatch/*_ (0.00s)2282 --- PASS: TestGlobMatch/*_anything (0.00s)2283 --- PASS: TestGlobMatch/foo_bar (0.00s)22842026/10/06 21:46:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55710/oidc2285--- PASS: TestValidateToken_BoundSubjectMismatch (0.05s)22862026/10/06 21:46:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55712/oidc2287--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.03s)22882026/10/06 21:46:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55715/oidc22892026/10/06 21:46:09 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232290--- PASS: TestPins_ReservedForMatchingRule (0.06s)2291--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.07s)22922026/10/06 21:46:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55719/oidc2293--- PASS: TestValidateToken_WrongAudience (0.07s)22942026/10/06 21:46:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55721/oidc2295--- PASS: TestScopes_Rules (0.06s)22962026/10/06 21:46:09 http: TLS handshake error from 127.0.0.1:55724: remote error: tls: bad certificate2297--- PASS: TestNewValidator_KubernetesRequiresCA (0.11s)22982026/10/06 21:46:09 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:55714/oidc2299--- PASS: TestValidateToken_NoMatchingProvider (0.09s)23002026/10/06 21:46:10 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:55727/oidc23012026/10/06 21:46:10 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:55728/oidc2302--- PASS: TestValidateToken_MultipleProviders (0.16s)2303PASS2304Running hook tests...2305=== RUN TestSendPathsEmpty2306=== PAUSE TestSendPathsEmpty2307=== RUN TestQueueEnqueueAndFetch2308=== PAUSE TestQueueEnqueueAndFetch2309=== RUN TestQueueDeduplication2310=== PAUSE TestQueueDeduplication2311=== RUN TestQueueRemove2312=== PAUSE TestQueueRemove2313=== RUN TestQueueFetchBatchLimit2314=== PAUSE TestQueueFetchBatchLimit2315=== RUN TestQueueRetryMovesToBack2316=== PAUSE TestQueueRetryMovesToBack2317=== RUN TestQueueFetchRemoveLifecycle2318=== PAUSE TestQueueFetchRemoveLifecycle2319=== RUN TestQueueConcurrentWriters2320=== PAUSE TestQueueConcurrentWriters2321=== RUN TestQueueRemoveLargeClosure2322=== PAUSE TestQueueRemoveLargeClosure2323=== RUN TestServerClientIntegration2324=== PAUSE TestServerClientIntegration2325=== RUN TestServerQueueError2326=== PAUSE TestServerQueueError2327=== RUN TestGetListenerSocketActivation2328 server_test.go:210: === RUN TestGetListenerSocketActivation2329 --- PASS: TestGetListenerSocketActivation (0.00s)2330 PASS2331 2332--- PASS: TestGetListenerSocketActivation (0.01s)2333=== RUN TestDrainIsolatesPoisonPath2334=== PAUSE TestDrainIsolatesPoisonPath2335=== RUN TestRunNotBlockedByPoisonHead2336=== PAUSE TestRunNotBlockedByPoisonHead2337=== RUN TestDrainGivesUpWhenServerDown2338=== PAUSE TestDrainGivesUpWhenServerDown2339=== RUN TestFailedPathPrunedByLaterClosure2340=== PAUSE TestFailedPathPrunedByLaterClosure2341=== RUN TestWorkerUploadsAndRemoves2342=== PAUSE TestWorkerUploadsAndRemoves2343=== RUN TestWorkerSkipsGCdPaths2344=== PAUSE TestWorkerSkipsGCdPaths2345=== RUN TestWorkerPrunesClosureDeps2346=== PAUSE TestWorkerPrunesClosureDeps2347=== RUN TestDrainTimeout2348=== PAUSE TestDrainTimeout2349=== CONT TestSendPathsEmpty2350=== CONT TestServerQueueError2351=== CONT TestQueueEnqueueAndFetch2352--- PASS: TestSendPathsEmpty (0.00s)2353=== CONT TestServerClientIntegration2354=== CONT TestQueueRemoveLargeClosure2355=== CONT TestQueueConcurrentWriters2356=== CONT TestQueueFetchRemoveLifecycle2357=== CONT TestQueueRetryMovesToBack2358=== CONT TestQueueFetchBatchLimit2359=== CONT TestQueueRemove23602026/10/06 21:46:10 ERROR Failed to queue paths error="permission denied" count=12361=== CONT TestQueueDeduplication2362--- PASS: TestServerClientIntegration (0.00s)2363=== CONT TestWorkerUploadsAndRemoves2364--- PASS: TestServerQueueError (0.00s)2365=== CONT TestDrainTimeout2366--- PASS: TestQueueRemove (0.01s)2367=== CONT TestWorkerPrunesClosureDeps2368--- PASS: TestQueueFetchBatchLimit (0.01s)2369=== CONT TestWorkerSkipsGCdPaths23702026/10/06 21:46:10 INFO Uploading batch count=22371--- PASS: TestQueueRetryMovesToBack (0.01s)2372=== CONT TestDrainGivesUpWhenServerDown23732026/10/06 21:46:10 INFO Upload queue status pending=223742026/10/06 21:46:10 INFO Uploading batch count=22375--- PASS: TestQueueDeduplication (0.01s)2376=== CONT TestFailedPathPrunedByLaterClosure2377--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2378=== CONT TestRunNotBlockedByPoisonHead2379--- PASS: TestQueueEnqueueAndFetch (0.01s)2380=== CONT TestDrainIsolatesPoisonPath23812026/10/06 21:46:10 INFO Upload queue status pending=223822026/10/06 21:46:10 INFO Uploading batch count=123832026/10/06 21:46:10 INFO Upload queue status pending=223842026/10/06 21:46:10 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-98165-1098463425/TestWorkerSkipsGCdPaths1995050849/002/nonexistent23852026/10/06 21:46:10 INFO Upload queue status pending=323862026/10/06 21:46:10 INFO Uploading batch count=123872026/10/06 21:46:10 ERROR Upload failed error="upload failed" count=123882026/10/06 21:46:10 INFO Uploading batch count=123892026/10/06 21:46:10 ERROR Upload failed error="upload failed" count=123902026/10/06 21:46:10 INFO Uploading batch count=123912026/10/06 21:46:10 INFO Uploading batch count=123922026/10/06 21:46:10 INFO Uploading batch count=123932026/10/06 21:46:10 INFO Uploading batch count=223942026/10/06 21:46:10 ERROR Upload failed error="upload failed" count=223952026/10/06 21:46:10 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-98165-1098463425/TestDrainGivesUpWhenServerDown1970574139/002/a23962026/10/06 21:46:10 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-98165-1098463425/TestDrainGivesUpWhenServerDown1970574139/002/b23972026/10/06 21:46:10 INFO Uploading batch count=423982026/10/06 21:46:10 ERROR Upload failed error="upload failed" count=423992026/10/06 21:46:10 INFO Uploading batch count=224002026/10/06 21:46:10 ERROR Upload failed error="upload failed" count=224012026/10/06 21:46:10 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-98165-1098463425/TestDrainGivesUpWhenServerDown1970574139/002/c24022026/10/06 21:46:10 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-98165-1098463425/TestDrainIsolatesPoisonPath2844219357/002/bbb24032026/10/06 21:46:10 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-98165-1098463425/TestDrainGivesUpWhenServerDown1970574139/002/d24042026/10/06 21:46:10 INFO Uploading batch count=224052026/10/06 21:46:10 ERROR Upload failed error="upload failed" count=224062026/10/06 21:46:10 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-98165-1098463425/TestDrainGivesUpWhenServerDown1970574139/002/e24072026/10/06 21:46:10 INFO Uploading batch count=124082026/10/06 21:46:10 ERROR Upload failed error="upload failed" count=124092026/10/06 21:46:10 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-98165-1098463425/TestDrainGivesUpWhenServerDown1970574139/002/f2410--- PASS: TestFailedPathPrunedByLaterClosure (0.00s)24112026/10/06 21:46:10 ERROR Drain finished with paths left in queue remaining=1024122026/10/06 21:46:10 INFO Uploading batch count=124132026/10/06 21:46:10 ERROR Upload failed error="upload failed" count=124142026/10/06 21:46:10 INFO Uploading batch count=124152026/10/06 21:46:10 ERROR Upload failed error="upload failed" count=124162026/10/06 21:46:10 ERROR Drain finished with paths left in queue remaining=12417--- PASS: TestDrainGivesUpWhenServerDown (0.01s)2418--- PASS: TestDrainIsolatesPoisonPath (0.00s)2419--- PASS: TestWorkerUploadsAndRemoves (0.03s)2420--- PASS: TestWorkerPrunesClosureDeps (0.02s)2421--- PASS: TestWorkerSkipsGCdPaths (0.02s)2422--- PASS: TestQueueRemoveLargeClosure (0.03s)2423--- PASS: TestQueueConcurrentWriters (0.15s)24242026/10/06 21:46:10 ERROR Upload failed error="context deadline exceeded" count=224252026/10/06 21:46:10 ERROR Drain finished with paths left in queue remaining=42426--- PASS: TestDrainTimeout (0.21s)24272026/10/06 21:46:11 INFO Uploading batch count=124282026/10/06 21:46:11 INFO Uploading batch count=124292026/10/06 21:46:11 INFO Uploading batch count=124302026/10/06 21:46:11 ERROR Upload failed error="upload failed" count=124312026/10/06 21:46:11 INFO Uploading batch count=124322026/10/06 21:46:11 ERROR Upload failed error="upload failed" count=124332026/10/06 21:46:11 INFO Uploading batch count=124342026/10/06 21:46:11 ERROR Upload failed error="upload failed" count=124352026/10/06 21:46:11 INFO Uploading batch count=124362026/10/06 21:46:11 ERROR Upload failed error="upload failed" count=124372026/10/06 21:46:11 ERROR Drain finished with paths left in queue remaining=12438--- PASS: TestRunNotBlockedByPoisonHead (1.01s)2439PASS2440Running signing tests...2441=== RUN TestExternalSigner2442=== PAUSE TestExternalSigner2443=== RUN TestExternalSignerWrongPublicKey2444=== PAUSE TestExternalSignerWrongPublicKey2445=== RUN TestExternalSignerErrors2446=== PAUSE TestExternalSignerErrors2447=== RUN TestExternalSignerRestartsAfterCrash2448=== PAUSE TestExternalSignerRestartsAfterCrash2449=== RUN TestExternalSignerProgramErrorKeepsProcess2450=== PAUSE TestExternalSignerProgramErrorKeepsProcess2451=== RUN TestExternalSignerClose2452=== PAUSE TestExternalSignerClose2453=== RUN TestExternalSignerRejectsInvalidPublicKey2454=== PAUSE TestExternalSignerRejectsInvalidPublicKey2455=== RUN TestExternalSignerCancellation2456=== PAUSE TestExternalSignerCancellation2457=== RUN TestGenerateFingerprint2458=== PAUSE TestGenerateFingerprint2459=== RUN TestParseSigningKey2460=== PAUSE TestParseSigningKey2461=== RUN TestSign2462=== PAUSE TestSign2463=== RUN TestSignBatch2464=== PAUSE TestSignBatch2465=== RUN TestNilKeyPublicKey2466=== PAUSE TestNilKeyPublicKey2467=== RUN TestSignErrors2468=== PAUSE TestSignErrors2469=== CONT TestExternalSigner2470=== CONT TestExternalSignerCancellation2471=== CONT TestExternalSignerProgramErrorKeepsProcess2472=== CONT TestSignBatch2473=== CONT TestSignErrors2474=== CONT TestParseSigningKey2475=== CONT TestExternalSignerErrors2476=== RUN TestParseSigningKey/valid_32-byte_key2477=== CONT TestSign2478=== CONT TestExternalSignerRestartsAfterCrash2479=== PAUSE TestParseSigningKey/valid_32-byte_key2480=== RUN TestExternalSignerErrors/null_signatures2481=== CONT TestNilKeyPublicKey2482--- PASS: TestNilKeyPublicKey (0.00s)2483=== CONT TestExternalSignerRejectsInvalidPublicKey2484=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2485=== RUN TestExternalSignerRejectsInvalidPublicKey/#002486=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002487=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2488=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2489=== PAUSE TestExternalSignerErrors/null_signatures2490=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2491=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2492=== RUN TestExternalSignerErrors/exit_at_startup2493=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2494=== RUN TestParseSigningKey/no_colon2495=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2496=== PAUSE TestExternalSignerErrors/exit_at_startup2497=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2498=== PAUSE TestParseSigningKey/no_colon2499=== RUN TestExternalSignerErrors/wrong_signature_length2500=== PAUSE TestExternalSignerErrors/wrong_signature_length2501=== RUN TestExternalSignerErrors/exit_on_request2502=== PAUSE TestExternalSignerErrors/exit_on_request2503=== RUN TestExternalSignerErrors/invalid_JSON2504=== PAUSE TestExternalSignerErrors/invalid_JSON2505=== RUN TestExternalSignerErrors/null2506=== PAUSE TestExternalSignerErrors/null2507=== RUN TestExternalSignerErrors/missing_signatures2508=== PAUSE TestExternalSignerErrors/missing_signatures2509=== RUN TestExternalSignerErrors/missing_signature_name2510=== PAUSE TestExternalSignerErrors/missing_signature_name2511=== RUN TestExternalSignerErrors/wrong_signature_name2512=== PAUSE TestExternalSignerErrors/wrong_signature_name2513=== RUN TestExternalSignerErrors/program_error2514=== PAUSE TestExternalSignerErrors/program_error2515=== RUN TestExternalSignerErrors/wrong_id2516=== PAUSE TestExternalSignerErrors/wrong_id2517=== RUN TestParseSigningKey/empty_name2518=== PAUSE TestParseSigningKey/empty_name2519=== RUN TestExternalSignerErrors/wrong_signatures_shape2520=== RUN TestParseSigningKey/invalid_base642521=== PAUSE TestParseSigningKey/invalid_base642522=== RUN TestParseSigningKey/wrong_length2523=== PAUSE TestParseSigningKey/wrong_length2524=== CONT TestExternalSignerWrongPublicKey2525=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2526=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2527=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2528=== CONT TestExternalSignerClose2529=== RUN TestExternalSignerErrors/too_few_signatures2530=== PAUSE TestExternalSignerErrors/too_few_signatures2531=== RUN TestExternalSignerErrors/unrequested_key2532=== PAUSE TestExternalSignerErrors/unrequested_key2533=== RUN TestExternalSignerErrors/invalid_signature_base642534=== PAUSE TestExternalSignerErrors/invalid_signature_base642535=== RUN TestExternalSignerErrors/wrong_shape2536=== PAUSE TestExternalSignerErrors/wrong_shape2537=== RUN TestSignErrors/nil_key2538--- PASS: TestSignBatch (0.00s)2539=== CONT TestParseSigningKey/valid_32-byte_key2540=== PAUSE TestSignErrors/nil_key2541=== CONT TestGenerateFingerprint2542=== RUN TestSignErrors/nil_narinfo2543=== RUN TestGenerateFingerprint/basic_with_references2544=== PAUSE TestSignErrors/nil_narinfo2545=== PAUSE TestGenerateFingerprint/basic_with_references2546=== RUN TestGenerateFingerprint/no_references2547=== PAUSE TestGenerateFingerprint/no_references2548=== RUN TestSignErrors/invalid_narinfo2549=== CONT TestParseSigningKey/wrong_length2550=== CONT TestParseSigningKey/invalid_base642551=== CONT TestParseSigningKey/no_colon2552=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2553=== PAUSE TestSignErrors/invalid_narinfo2554--- PASS: TestSign (0.00s)2555=== CONT TestParseSigningKey/empty_name2556=== CONT TestExternalSignerRejectsInvalidPublicKey/#002557=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2558--- PASS: TestParseSigningKey (0.00s)2559 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2560 --- PASS: TestParseSigningKey/wrong_length (0.00s)2561 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2562 --- PASS: TestParseSigningKey/no_colon (0.00s)2563 --- PASS: TestParseSigningKey/empty_name (0.00s)2564 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2565=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2566=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2567=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2568=== RUN TestGenerateFingerprint/invalid_nar_hash_length2569=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2570=== RUN TestGenerateFingerprint/invalid_store_path_prefix2571=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2572=== RUN TestGenerateFingerprint/invalid_reference_prefix2573=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2574=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2575=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2576=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2577=== CONT TestExternalSignerErrors/wrong_shape2578=== CONT TestExternalSignerErrors/null_signatures2579=== RUN TestSignErrors/canceled2580=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2581=== PAUSE TestSignErrors/canceled2582=== CONT TestExternalSignerErrors/unrequested_key2583--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2584 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2585 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2586 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2587 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2588 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2589=== CONT TestExternalSignerErrors/invalid_signature_base642590--- PASS: TestExternalSignerCancellation (0.20s)2591=== CONT TestExternalSignerErrors/too_few_signatures2592--- PASS: TestExternalSigner (0.37s)2593=== CONT TestExternalSignerErrors/wrong_signatures_shape2594--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.55s)2595=== CONT TestExternalSignerErrors/wrong_id2596--- PASS: TestExternalSignerClose (0.72s)2597=== CONT TestExternalSignerErrors/null2598--- PASS: TestExternalSignerWrongPublicKey (0.90s)2599=== CONT TestExternalSignerErrors/program_error2600--- PASS: TestExternalSignerRestartsAfterCrash (1.09s)2601=== CONT TestExternalSignerErrors/wrong_signature_name2602/nix/var/nix/builds/nix-98165-1098463425/TestExternalSignerRestartsAfterCrash2459640067/001/sign program: line 7: /nix/var/nix/builds/nix-98165-1098463425/TestExternalSignerRestartsAfterCrash2459640067/001/sign program.starts: No such file or directory2603=== CONT TestExternalSignerErrors/missing_signature_name2604=== CONT TestExternalSignerErrors/missing_signatures2605=== CONT TestExternalSignerErrors/exit_on_request2606=== CONT TestExternalSignerErrors/invalid_JSON2607=== CONT TestExternalSignerErrors/wrong_signature_length2608=== CONT TestExternalSignerErrors/exit_at_startup2609=== CONT TestGenerateFingerprint/basic_with_references2610=== CONT TestGenerateFingerprint/invalid_nar_hash_length2611=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2612=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2613=== CONT TestGenerateFingerprint/no_references2614=== CONT TestGenerateFingerprint/invalid_reference_prefix2615=== CONT TestGenerateFingerprint/invalid_store_path_prefix2616--- PASS: TestGenerateFingerprint (0.00s)2617 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2618 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2619 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2620 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2621 --- PASS: TestGenerateFingerprint/no_references (0.00s)2622 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2623 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2624=== CONT TestSignErrors/canceled2625=== CONT TestSignErrors/nil_key2626=== CONT TestSignErrors/nil_narinfo2627=== CONT TestSignErrors/invalid_narinfo2628--- PASS: TestSignErrors (0.00s)2629 --- PASS: TestSignErrors/canceled (0.00s)2630 --- PASS: TestSignErrors/nil_key (0.00s)2631 --- PASS: TestSignErrors/nil_narinfo (0.00s)2632 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2633--- PASS: TestExternalSignerErrors (0.00s)2634 --- PASS: TestExternalSignerErrors/wrong_shape (1.26s)2635 --- PASS: TestExternalSignerErrors/null_signatures (1.44s)2636 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (1.62s)2637 --- PASS: TestExternalSignerErrors/unrequested_key (1.80s)2638 --- PASS: TestExternalSignerErrors/too_few_signatures (1.78s)2639 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (1.87s)2640 --- PASS: TestExternalSignerErrors/wrong_id (1.80s)2641 --- PASS: TestExternalSignerErrors/null (1.80s)2642 --- PASS: TestExternalSignerErrors/program_error (1.79s)2643 --- PASS: TestExternalSignerErrors/wrong_signature_name (1.79s)2644 --- PASS: TestExternalSignerErrors/missing_signature_name (1.79s)2645 --- PASS: TestExternalSignerErrors/missing_signatures (1.81s)2646 --- PASS: TestExternalSignerErrors/exit_on_request (1.86s)2647 --- PASS: TestExternalSignerErrors/invalid_JSON (1.86s)2648 --- PASS: TestExternalSignerErrors/wrong_signature_length (1.86s)2649 --- PASS: TestExternalSignerErrors/exit_at_startup (1.78s)2650PASS2651Running OpenBao signer tests...2652=== RUN TestSign2653=== PAUSE TestSign2654=== RUN TestSignErrors2655=== PAUSE TestSignErrors2656=== RUN TestServe2657=== PAUSE TestServe2658=== RUN TestServeRejectsGarbage2659=== PAUSE TestServeRejectsGarbage2660=== CONT TestSign2661=== CONT TestServe2662=== CONT TestSignErrors2663=== RUN TestSignErrors/http_error2664=== PAUSE TestSignErrors/http_error2665=== RUN TestSignErrors/invalid_json2666=== PAUSE TestSignErrors/invalid_json2667=== RUN TestSignErrors/no_prefix2668=== PAUSE TestSignErrors/no_prefix2669=== RUN TestSignErrors/invalid_base642670=== PAUSE TestSignErrors/invalid_base642671=== CONT TestSignErrors/http_error2672=== CONT TestServeRejectsGarbage2673--- PASS: TestServeRejectsGarbage (0.00s)2674=== CONT TestSignErrors/no_prefix2675--- PASS: TestServe (0.00s)2676=== CONT TestSignErrors/invalid_base642677=== CONT TestSignErrors/invalid_json2678--- PASS: TestSign (0.00s)2679--- PASS: TestSignErrors (0.00s)2680 --- PASS: TestSignErrors/no_prefix (0.00s)2681 --- PASS: TestSignErrors/http_error (0.00s)2682 --- PASS: TestSignErrors/invalid_base64 (0.00s)2683 --- PASS: TestSignErrors/invalid_json (0.00s)2684PASS