niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #385
· 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.03s)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 TestEncodeNixBase32101=== RUN TestEncodeNixBase32/test_string_hash102=== PAUSE TestEncodeNixBase32/test_string_hash103=== RUN TestEncodeNixBase32/empty_input104=== PAUSE TestEncodeNixBase32/empty_input105=== CONT TestParsePathInfoJSONMultiplePaths106=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths107=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths108=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths109=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths110=== CONT TestEncodeNixBase32/test_string_hash111=== CONT TestParsePathInfoJSON112=== RUN TestParsePathInfoJSON/Nix_format113=== PAUSE TestParsePathInfoJSON/Nix_format114=== RUN TestParsePathInfoJSON/Lix_format115=== PAUSE TestParsePathInfoJSON/Lix_format116=== RUN TestParsePathInfoJSON/empty_input117=== PAUSE TestParsePathInfoJSON/empty_input118=== RUN TestParsePathInfoJSON/whitespace_only119=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess120=== CONT TestResolveStorePath121=== PAUSE TestParsePathInfoJSON/whitespace_only122=== RUN TestParsePathInfoJSON/invalid_JSON123=== PAUSE TestParsePathInfoJSON/invalid_JSON124=== CONT TestRateLimiterFeedback125=== RUN TestRateLimiterFeedback/429_enables_limiter126=== PAUSE TestRateLimiterFeedback/429_enables_limiter127=== RUN TestRateLimiterFeedback/503_enables_limiter128=== PAUSE TestRateLimiterFeedback/503_enables_limiter129=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter130=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter131=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter132=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter133=== CONT TestPathInfoCACompatibility134=== RUN TestPathInfoCACompatibility/null_ca_field1352026/10/06 21:19:28 WARN Rate limiter enabled after throttle name=server-test rate=5136=== PAUSE TestPathInfoCACompatibility/null_ca_field137=== RUN TestPathInfoCACompatibility/old_string_format_-_text138=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text139=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive140=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive141=== RUN TestPathInfoCACompatibility/new_structured_format_-_text142=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text143=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method144=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method145=== CONT TestUploadMultipart_PartsInParallel146=== 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=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error152=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error153=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error154=== CONT TestConvertHashToNix32155=== RUN TestConvertHashToNix32/SRI_format_to_Nix32156=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32157=== RUN TestConvertHashToNix32/already_Nix32_format158=== PAUSE TestConvertHashToNix32/already_Nix32_format159=== RUN TestConvertHashToNix32/invalid_format160=== PAUSE TestConvertHashToNix32/invalid_format161=== CONT TestEncodeNixBase32WithRealHash162--- PASS: TestEncodeNixBase32WithRealHash (0.00s)163=== CONT TestDumpPathSingleFile164=== CONT TestDumpPathWriterError165=== CONT TestEncodeNixBase32/empty_input166--- PASS: TestEncodeNixBase32 (0.00s)167 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)168 --- PASS: TestEncodeNixBase32/empty_input (0.00s)169=== CONT TestPathInfoHashCompatibility170=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)171=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error172=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)173=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon174=== CONT TestDumpPathMatchesNix175=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon176=== CONT TestUploadMultipart_SupersededByPeer177--- PASS: TestResolveStorePath (0.00s)178=== CONT TestPartSizeForNAR179=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI180=== RUN TestPartSizeForNAR/zero_stays_at_minimum181=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum182=== RUN TestUploadMultipart_SupersededByPeer/exists183=== PAUSE TestUploadMultipart_SupersededByPeer/exists184=== RUN TestUploadMultipart_SupersededByPeer/missing185=== PAUSE TestUploadMultipart_SupersededByPeer/missing186=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI187=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512188=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun1892026/10/06 21:19:28 WARN Rate limiter enabled after throttle name=server-test rate=51902026/10/06 21:19:28 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:52079191=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512192=== RUN TestPartSizeForNAR/small_stays_at_minimum193=== PAUSE TestPartSizeForNAR/small_stays_at_minimum194=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum195=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum196=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts197=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts198=== RUN TestPartSizeForNAR/1_TiB199=== PAUSE TestPartSizeForNAR/1_TiB200=== RUN TestPartSizeForNAR/5_TiB_S3_max_object201=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object202=== RUN TestPartSizeForNAR/capped_at_5_GiB203=== CONT TestFilterOversizedClosures204=== RUN TestFilterOversizedClosures/no_limit_keeps_everything205=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything206=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped207=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped208=== RUN TestFilterOversizedClosures/all_closures_skipped209=== PAUSE TestFilterOversizedClosures/all_closures_skipped210=== PAUSE TestPartSizeForNAR/capped_at_5_GiB211=== CONT TestCaseHackSuffix212=== CONT TestSetClientTLSErrors2132026/10/06 21:19:28 WARN Rate limiter backed off name=server-test rate=52142026/10/06 21:19:28 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:52079215--- PASS: TestDoServerRequestAttachesToken (0.00s)216=== CONT TestScriptTokenEmptyCommand217--- PASS: TestScriptTokenEmptyCommand (0.00s)218=== CONT TestScriptTokenScriptFails219--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)220=== CONT TestScriptTokenBadJSON2212026/10/06 21:19:28 INFO Garbage collection started222=== RUN TestSetClientTLSErrors/missing_cert_file223=== PAUSE TestSetClientTLSErrors/missing_cert_file224=== RUN TestSetClientTLSErrors/missing_key_file225=== PAUSE TestSetClientTLSErrors/missing_key_file226=== RUN TestSetClientTLSErrors/missing_ca_file227=== PAUSE TestSetClientTLSErrors/missing_ca_file228=== RUN TestSetClientTLSErrors/invalid_ca_file229=== PAUSE TestSetClientTLSErrors/invalid_ca_file230=== CONT TestScriptTokenEmptyToken231--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.00s)232=== CONT TestScriptTokenCachesUntilRefresh233--- PASS: TestScriptTokenScriptFails (0.01s)234=== CONT TestScriptTokenNoExpiryRerunsEveryCall235--- PASS: TestScriptTokenBadJSON (0.01s)236=== CONT TestFileTokenEmpty237--- PASS: TestFileTokenEmpty (0.00s)238=== CONT TestFileTokenMissing239--- PASS: TestFileTokenMissing (0.00s)240=== CONT TestFileTokenReadsAndCaches241--- PASS: TestFileTokenReadsAndCaches (0.00s)242=== CONT TestStaticToken243--- PASS: TestStaticToken (0.00s)244=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica245--- PASS: TestScriptTokenEmptyToken (0.01s)246=== CONT TestRegisterUploadedObjectReusesConnections2472026/10/06 21:19:28 INFO Garbage collection started2482026/10/06 21:19:28 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=02492026/10/06 21:19:28 WARN Garbage collection finished on another replica. Its statistics are not available here250--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)251=== CONT TestStreamPushGivesUpOnDeadServer2522026/10/06 21:19:28 ERROR Upload failed error="connection refused" count=202532026/10/06 21:19:28 ERROR Server seems unavailable, giving up on batch untried=17254--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)255=== CONT TestSetClientTLSDoesNotMutateDefaultTransport256--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)257=== CONT TestSetClientTLS258=== RUN TestSetClientTLS/rejects_connection_without_client_cert259=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert260=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA261=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA262=== RUN TestSetClientTLS/preserves_debug_logging_transport263=== PAUSE TestSetClientTLS/preserves_debug_logging_transport264=== CONT TestClientSignaturesByStorePath265--- PASS: TestClientSignaturesByStorePath (0.00s)266=== CONT TestStreamPushReportsSignatures2672026/10/06 21:19:28 ERROR Upload failed error=boom count=1268--- PASS: TestStreamPushReportsSignatures (0.00s)269=== CONT TestStreamPushRequestLine2702026/10/06 21:19:28 ERROR Upload failed error=boom count=1271--- PASS: TestDumpPathWriterError (0.05s)272=== CONT TestStreamPushReportsEveryPath273--- PASS: TestStreamPushReportsEveryPath (0.00s)274=== CONT TestStreamPushIsolatesFailures2752026/10/06 21:19:28 ERROR Upload failed error="bad path" count=3276--- PASS: TestStreamPushIsolatesFailures (0.00s)277=== CONT TestStreamPushBatchesUnderLoad278--- PASS: TestStreamPushRequestLine (0.01s)279=== CONT TestShellSplitErrors280--- PASS: TestShellSplitErrors (0.00s)281=== CONT TestShellSplit282--- PASS: TestShellSplit (0.00s)283=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths284=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths285--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)286 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)287 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)288=== CONT TestParsePathInfoJSON/Nix_format289=== CONT TestRateLimiterFeedback/429_enables_limiter2902026/10/06 21:19:28 WARN Rate limiter enabled after throttle name=server-test rate=52912026/10/06 21:19:28 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:521592922026/10/06 21:19:28 WARN Rate limiter backed off name=server-test rate=5293=== CONT TestParsePathInfoJSON/invalid_JSON294=== CONT TestParsePathInfoJSON/whitespace_only295=== CONT TestParsePathInfoJSON/empty_input296=== CONT TestParsePathInfoJSON/Lix_format297--- PASS: TestParsePathInfoJSON (0.00s)298 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)299 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)300 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)301 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)302 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)303=== CONT TestPathInfoCACompatibility/null_ca_field304=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter305=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter306=== CONT TestRateLimiterFeedback/503_enables_limiter307--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)308=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method309=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive310=== CONT TestPathInfoCACompatibility/old_string_format_-_text311=== CONT TestConvertHashToNix32/SRI_format_to_Nix32312=== CONT TestConvertHashToNix32/invalid_format313=== CONT TestConvertHashToNix32/already_Nix32_format314--- PASS: TestConvertHashToNix32 (0.00s)315 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)316 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)317 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)318=== CONT TestPathInfoCACompatibility/new_structured_format_-_text3192026/10/06 21:19:28 WARN Rate limiter enabled after throttle name=server-test rate=53202026/10/06 21:19:28 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:52165321--- PASS: TestPathInfoCACompatibility (0.00s)322 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)323 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)324 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)325 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)326 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)327=== CONT TestGetStorePathHash/valid_store_path328=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error329=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error330=== CONT TestGetStorePathHash/basename_without_hyphen_should_error331--- PASS: TestGetStorePathHash (0.00s)332 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)333 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)334 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)335 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)336=== CONT TestUploadMultipart_SupersededByPeer/exists3372026/10/06 21:19:28 WARN Rate limiter backed off name=server-test rate=5338--- PASS: TestRateLimiterFeedback (0.00s)339 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)340 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)341 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)342 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)343=== CONT TestUploadMultipart_SupersededByPeer/missing344=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)345=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512346=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI347=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon348--- PASS: TestPathInfoHashCompatibility (0.00s)349 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)350 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)351 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)352 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)353=== CONT TestFilterOversizedClosures/no_limit_keeps_everything354=== CONT TestPartSizeForNAR/zero_stays_at_minimum355=== CONT TestPartSizeForNAR/5_TiB_S3_max_object356=== CONT TestFilterOversizedClosures/all_closures_skipped3572026/10/06 21:19:28 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-small nar_size=1000 max_nar_size=50358=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3592026/10/06 21:19:28 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=2000360--- PASS: TestFilterOversizedClosures (0.00s)361 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)362 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)363 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)364=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts365=== CONT TestPartSizeForNAR/1_TiB366=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum367=== CONT TestPartSizeForNAR/capped_at_5_GiB368=== CONT TestPartSizeForNAR/small_stays_at_minimum369--- PASS: TestPartSizeForNAR (0.00s)370 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)371 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)372 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)373 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)374 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)375 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)376 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)377=== CONT TestSetClientTLSErrors/missing_cert_file378--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)379 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)380 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)381=== CONT TestSetClientTLSErrors/missing_ca_file382=== CONT TestSetClientTLSErrors/invalid_ca_file383=== CONT TestSetClientTLSErrors/missing_key_file384=== CONT TestSetClientTLS/rejects_connection_without_client_cert385=== CONT TestSetClientTLS/preserves_debug_logging_transport386--- PASS: TestSetClientTLSErrors (0.00s)387 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)388 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)389 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)390 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)391=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA392--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)393--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)3942026/10/06 21:19:28 http: TLS handshake error from 127.0.0.1:52171: remote error: tls: bad certificate395--- PASS: TestSetClientTLS (0.00s)396 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)397 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)398 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)399--- PASS: TestDumpPathSingleFile (0.06s)400--- PASS: TestCaseHackSuffix (0.06s)401--- PASS: TestDumpPathMatchesNix (0.07s)402--- PASS: TestStreamPushBatchesUnderLoad (0.10s)403--- PASS: TestUploadMultipart_PartsInParallel (0.61s)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-43476-3212982383/postgres2944873813/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-43476-3212982383/postgres2944873813/data -l logfile start433434/nix/var/nix/builds/nix-43476-3212982383/postgres2944873813:5432 - no response4352026-10-06 21:19:30.313 UTC [43514] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4362026-10-06 21:19:30.314 UTC [43514] LOG: listening on Unix socket "/nix/var/nix/builds/nix-43476-3212982383/postgres2944873813/.s.PGSQL.5432"4372026-10-06 21:19:30.315 UTC [43521] LOG: database system was shut down at 2026-10-06 21:19:30 UTC4382026-10-06 21:19:30.316 UTC [43514] LOG: database system is ready to accept connections439/nix/var/nix/builds/nix-43476-3212982383/postgres2944873813:5432 - accepting connections440{"timestamp":"2026-10-06T21:19:30.527925Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"4732b42a-c455-4012-9ea2-0956983bed78","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(6)"}441=== RUN TestService_AuthMiddleware442=== PAUSE TestService_AuthMiddleware443=== RUN TestService_AuthMiddleware_MTLSProxyHeader444=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader445=== RUN TestService_AuthMiddleware_MTLSBoundSubjects446=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects447=== RUN TestService_ReadAuthMiddleware448=== PAUSE TestService_ReadAuthMiddleware449=== RUN TestService_AuthMiddleware_OIDC450=== PAUSE TestService_AuthMiddleware_OIDC451=== RUN TestService_RequireScope_OIDC452=== PAUSE TestService_RequireScope_OIDC453=== RUN TestService_ReadScope_PublicByDefault454=== PAUSE TestService_ReadScope_PublicByDefault455=== RUN TestCacheConfigHandler456=== PAUSE TestCacheConfigHandler457=== RUN TestCacheStatsHandler458=== PAUSE TestCacheStatsHandler459=== RUN TestClientCADerivations460=== PAUSE TestClientCADerivations461=== RUN TestClientErrorHandling462=== PAUSE TestClientErrorHandling463=== RUN TestClientIntegration464=== PAUSE TestClientIntegration465=== RUN TestClientMultipleUploads466=== PAUSE TestClientMultipleUploads467=== RUN TestClientWithDependencies468=== PAUSE TestClientWithDependencies469=== RUN TestClientSharedPathCommittedMidPush470=== PAUSE TestClientSharedPathCommittedMidPush471=== RUN TestPinProtectsFromGC472=== PAUSE TestPinProtectsFromGC473=== RUN TestClientPushesUseOnePush474=== PAUSE TestClientPushesUseOnePush475=== RUN TestClientFallsBackToClosures476=== PAUSE TestClientFallsBackToClosures477=== RUN TestDeleteClosuresRacingPins478=== PAUSE TestDeleteClosuresRacingPins479=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock480=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock481=== RUN TestResolveDBConnectionString482=== PAUSE TestResolveDBConnectionString483=== RUN TestConnectWaitsForAPeerMigration484=== PAUSE TestConnectWaitsForAPeerMigration485=== RUN TestLeadElectsOneAndHandsOver486=== PAUSE TestLeadElectsOneAndHandsOver487=== RUN TestLeadIncumbentWinsAfterRestart4882026/10/06 21:19:30 INFO lead: acquired remote=192.0.2.1:12344892026/10/06 21:19:31 INFO lead: released remote=192.0.2.1:12344902026/10/06 21:19:31 INFO lead: acquired remote=192.0.2.1:12344912026/10/06 21:19:32 INFO lead: released remote=192.0.2.1:1234492--- PASS: TestLeadIncumbentWinsAfterRestart (1.94s)493=== RUN TestLeadIncumbentAnnouncesAtOnce494=== PAUSE TestLeadIncumbentAnnouncesAtOnce495=== RUN TestLeadEndsOnShutdown496=== PAUSE TestLeadEndsOnShutdown497=== RUN TestLeadEndsWhenItsConnectionHangs4982026/10/06 21:19:32 INFO lead: acquired remote=192.0.2.1:12344992026-10-06 21:19:33.880 UTC [43556] FATAL: terminating connection due to administrator command5002026/10/06 21:19:34 INFO lead: acquired remote=192.0.2.1:12345012026/10/06 21:19:35 WARN lead: lock connection lost error="timeout: context deadline exceeded"5022026/10/06 21:19:35 INFO lead: released remote=192.0.2.1:12345032026/10/06 21:19:35 INFO lead: released remote=192.0.2.1:1234504--- PASS: TestLeadEndsWhenItsConnectionHangs (2.71s)505=== RUN TestGCAdvisoryLockBlocksConcurrentRun506=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun507=== RUN TestGCBugBareHashReferences508=== PAUSE TestGCBugBareHashReferences509=== RUN TestGCMetrics510=== PAUSE TestGCMetrics511=== RUN TestPushDedupSurvivesConcurrentGC512=== PAUSE TestPushDedupSurvivesConcurrentGC513=== RUN TestDeduplicatedObjectsRecordedAsPending514=== PAUSE TestDeduplicatedObjectsRecordedAsPending515=== RUN TestGCSweepSkipsPendingObjects516=== PAUSE TestGCSweepSkipsPendingObjects517=== RUN TestTombstonedObjectOfferedWithoutWaiting518=== PAUSE TestTombstonedObjectOfferedWithoutWaiting519=== RUN TestGCSweepDeliversEachKeyOnce520=== PAUSE TestGCSweepDeliversEachKeyOnce521=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection522=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection523=== RUN TestForceGCDuringPushOffersSweptObject524=== PAUSE TestForceGCDuringPushOffersSweptObject525=== RUN TestFailedS3DeleteKeepsTombstone526=== PAUSE TestFailedS3DeleteKeepsTombstone527=== RUN TestSweepSkipsRowsLockedByPush528=== PAUSE TestSweepSkipsRowsLockedByPush529=== RUN TestRegisterCompletedObjectNeedsPendingRow530=== PAUSE TestRegisterCompletedObjectNeedsPendingRow531=== RUN TestGetExistingObjectsLocksRows532=== PAUSE TestGetExistingObjectsLocksRows533=== RUN TestSweepRechecksPendingAfterLocking534=== PAUSE TestSweepRechecksPendingAfterLocking535=== RUN TestPushWaitsForSweepHoldingRow536=== PAUSE TestPushWaitsForSweepHoldingRow537=== RUN TestCommitRacingPendingCleanupKeepsObjects538=== PAUSE TestCommitRacingPendingCleanupKeepsObjects539=== RUN TestGCEndsOnShutdown540=== PAUSE TestGCEndsOnShutdown541=== RUN TestGCTaskStore_StartNew542=== PAUSE TestGCTaskStore_StartNew543=== RUN TestGCTaskStore_DeduplicateSameParams544=== PAUSE TestGCTaskStore_DeduplicateSameParams545=== RUN TestGCTaskStore_ConflictDifferentParams546=== PAUSE TestGCTaskStore_ConflictDifferentParams547=== RUN TestGCTaskStore_GetEmpty548=== PAUSE TestGCTaskStore_GetEmpty549=== RUN TestGCTaskStore_GetReturnsLatest550=== PAUSE TestGCTaskStore_GetReturnsLatest551=== RUN TestGCTaskStore_CompletedAllowsNewTask552=== PAUSE TestGCTaskStore_CompletedAllowsNewTask553=== RUN TestGCTaskStore_PhaseUpdates554=== PAUSE TestGCTaskStore_PhaseUpdates555=== RUN TestGCTaskStore_Fail556=== PAUSE TestGCTaskStore_Fail557=== RUN TestGracefulShutdownDrainsInflight558=== PAUSE TestGracefulShutdownDrainsInflight559=== RUN TestService_healthCheckHandler560=== PAUSE TestService_healthCheckHandler561=== RUN TestService_readinessHandler562=== PAUSE TestService_readinessHandler563=== RUN TestGenerateLandingPage564=== PAUSE TestGenerateLandingPage565=== RUN TestCacheConfigHandlerMaxNarSize566=== PAUSE TestCacheConfigHandlerMaxNarSize567=== RUN TestCreatePendingClosureRejectsOversizedNAR568=== PAUSE TestCreatePendingClosureRejectsOversizedNAR569=== RUN TestNARDeduplicationMetadataUploadBug570=== PAUSE TestNARDeduplicationMetadataUploadBug571=== RUN TestMetricsInventory572=== PAUSE TestMetricsInventory573=== RUN TestService_NativeMTLS574=== PAUSE TestService_NativeMTLS575=== RUN TestServerTLSConfig576=== PAUSE TestServerTLSConfig577=== RUN TestMultipartCleanup578=== PAUSE TestMultipartCleanup579=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded580=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded581=== RUN TestPendingCleanupUsesOneCutoff582=== PAUSE TestPendingCleanupUsesOneCutoff583=== RUN TestObjectStatsTrigger584=== PAUSE TestObjectStatsTrigger585=== RUN TestOrphanedObjectsGC586=== PAUSE TestOrphanedObjectsGC587=== RUN TestOrphanedObjectsGCStressTest588=== PAUSE TestOrphanedObjectsGCStressTest589=== RUN TestCreatePin_ReservedPins590=== PAUSE TestCreatePin_ReservedPins591=== RUN TestPresentReportsOnlyClosureRoots592=== PAUSE TestPresentReportsOnlyClosureRoots593=== RUN TestPresentRefreshesOnlyStaleClosures594=== PAUSE TestPresentRefreshesOnlyStaleClosures595=== RUN TestPresentNotReportedWhileGCDeletesClosure596=== PAUSE TestPresentNotReportedWhileGCDeletesClosure597=== RUN TestParseSingleRange598=== PAUSE TestParseSingleRange599=== RUN TestProxyHeadersOnlyTrustedOnSocket600=== PAUSE TestProxyHeadersOnlyTrustedOnSocket601=== RUN TestIsValidCachePath602=== PAUSE TestIsValidCachePath603=== RUN TestReadProxyNarinfo604=== PAUSE TestReadProxyNarinfo605=== RUN TestReadProxyNarinfoAlreadyDecompressed606=== PAUSE TestReadProxyNarinfoAlreadyDecompressed607=== RUN TestReadProxyContentNegotiation608=== PAUSE TestReadProxyContentNegotiation609=== RUN TestReadProxyNarStreaming610=== PAUSE TestReadProxyNarStreaming611=== RUN TestReadProxy404612=== PAUSE TestReadProxy404613=== RUN TestReadProxyInvalidPath614=== PAUSE TestReadProxyInvalidPath615=== RUN TestReadProxyHead616=== PAUSE TestReadProxyHead617=== RUN TestReadProxyOutlastsServerWriteTimeout618=== PAUSE TestReadProxyOutlastsServerWriteTimeout619=== RUN TestReadProxyConditionalGet620=== PAUSE TestReadProxyConditionalGet621=== RUN TestReadProxyRootRedirectsToIndexHTML622=== PAUSE TestReadProxyRootRedirectsToIndexHTML623=== RUN TestReadProxyDisabled624=== PAUSE TestReadProxyDisabled625=== RUN TestReadRedirectNar626=== PAUSE TestReadRedirectNar627=== RUN TestReadRedirectKeepsNarinfoProxied628=== PAUSE TestReadRedirectKeepsNarinfoProxied629=== RUN TestReadProxyRangeRequest630=== PAUSE TestReadProxyRangeRequest631=== RUN TestReadRedirectUsesPublicS3URL632=== PAUSE TestReadRedirectUsesPublicS3URL633=== RUN TestPush_OverlappingRootsStoreOneRowPerKey634=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey635=== RUN TestPush_CompleteCommitsEveryRoot636=== PAUSE TestPush_CompleteCommitsEveryRoot637=== RUN TestPush_RepeatedRootCommitsOnce638=== PAUSE TestPush_RepeatedRootCommitsOnce639=== RUN TestPush_CompleteWaitsForCleanupOfThePush640=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush641=== RUN TestPush_RootsAreLockedInByteOrder642=== PAUSE TestPush_RootsAreLockedInByteOrder643=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit644=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit645=== RUN TestPush_RejectsBadRequests646=== PAUSE TestPush_RejectsBadRequests647=== RUN TestPush_SignsNarinfosOfItsPendingObjects648=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects649=== RUN TestRedundantMultipartUpload650=== PAUSE TestRedundantMultipartUpload651=== RUN TestCompleteMultipartUpload_ErrorButObjectExists652=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists653=== RUN TestCompletedNarNotReofferedAcrossClosures654=== PAUSE TestCompletedNarNotReofferedAcrossClosures655=== RUN TestPresignedUploadRegisteredBeforeCommit656=== PAUSE TestPresignedUploadRegisteredBeforeCommit657=== RUN TestService_Rustfstest658=== PAUSE TestService_Rustfstest659=== RUN TestParseSize660=== PAUSE TestParseSize661=== RUN TestSkippedUploadsHandler662=== PAUSE TestSkippedUploadsHandler663=== RUN TestSystemdListenerNotActivated664--- PASS: TestSystemdListenerNotActivated (0.00s)665=== RUN TestWatchdogBeatsWhenHealthy666--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)667=== RUN TestWatchdogSkipsWhenUnhealthy6682026/10/06 21:19:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6692026/10/06 21:19:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6702026/10/06 21:19:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6712026/10/06 21:19:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6722026/10/06 21:19:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6732026/10/06 21:19:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6742026/10/06 21:19:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6752026/10/06 21:19:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6762026/10/06 21:19:35 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"677--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)678=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle679=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle680=== RUN TestProxyWriteTimeout681=== PAUSE TestProxyWriteTimeout682=== RUN TestPendingClosureWriteTimeout683=== PAUSE TestPendingClosureWriteTimeout684=== RUN TestIsValidUploadKey685=== PAUSE TestIsValidUploadKey686=== RUN TestUploadHandlersRejectInvalidKeys687=== PAUSE TestUploadHandlersRejectInvalidKeys688=== RUN TestUploadHandlersRejectOversizedBody689=== PAUSE TestUploadHandlersRejectOversizedBody690=== RUN TestService_cleanupPendingClosuresHandler691=== PAUSE TestService_cleanupPendingClosuresHandler692=== RUN TestService_createPendingClosureHandler693=== PAUSE TestService_createPendingClosureHandler694=== RUN TestService_verifyS3Integrity695=== PAUSE TestService_verifyS3Integrity696=== RUN TestCompleteMultipartUnregistered697=== PAUSE TestCompleteMultipartUnregistered698=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT699=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT700=== CONT TestService_AuthMiddleware701=== CONT TestMetricsInventory702=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT703=== CONT TestCompleteMultipartUnregistered704=== CONT TestService_verifyS3Integrity705=== CONT TestService_createPendingClosureHandler706=== CONT TestService_cleanupPendingClosuresHandler707=== CONT TestUploadHandlersRejectOversizedBody708=== CONT TestUploadHandlersRejectInvalidKeys709=== CONT TestIsValidUploadKey710=== RUN TestIsValidUploadKey/narinfo711=== PAUSE TestIsValidUploadKey/narinfo712=== RUN TestIsValidUploadKey/nar_zst713=== PAUSE TestIsValidUploadKey/nar_zst714=== RUN TestIsValidUploadKey/nar_xz715=== PAUSE TestIsValidUploadKey/nar_xz716=== RUN TestIsValidUploadKey/nar_plain717=== PAUSE TestIsValidUploadKey/nar_plain718=== RUN TestIsValidUploadKey/listing719=== PAUSE TestIsValidUploadKey/listing720=== RUN TestIsValidUploadKey/build_log721=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info722=== PAUSE TestIsValidUploadKey/build_log723=== RUN TestIsValidUploadKey/build_log_home-manager_file724=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info725=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal726=== PAUSE TestIsValidUploadKey/build_log_home-manager_file727=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal728=== RUN TestIsValidUploadKey/build_log_plus_in_name729=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key730=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key731=== PAUSE TestIsValidUploadKey/build_log_plus_in_name732=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key733=== RUN TestIsValidUploadKey/build_log_question_mark734=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key735=== PAUSE TestIsValidUploadKey/build_log_question_mark736=== CONT TestPendingClosureWriteTimeout737=== RUN TestPendingClosureWriteTimeout/empty738=== RUN TestIsValidUploadKey/build_log_equals739=== PAUSE TestPendingClosureWriteTimeout/empty740=== RUN TestPendingClosureWriteTimeout/400_objects741=== PAUSE TestPendingClosureWriteTimeout/400_objects742=== RUN TestPendingClosureWriteTimeout/670k_objects743=== PAUSE TestIsValidUploadKey/build_log_equals744=== PAUSE TestPendingClosureWriteTimeout/670k_objects745=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline746=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline747=== RUN TestIsValidUploadKey/realisation748=== CONT TestProxyWriteTimeout749=== RUN TestProxyWriteTimeout/narinfo750=== PAUSE TestIsValidUploadKey/realisation751=== RUN TestIsValidUploadKey/realisation_plus_in_output752=== PAUSE TestProxyWriteTimeout/narinfo753=== RUN TestProxyWriteTimeout/1_GiB_nar754=== PAUSE TestProxyWriteTimeout/1_GiB_nar755=== RUN TestProxyWriteTimeout/10_GiB_nar756=== PAUSE TestProxyWriteTimeout/10_GiB_nar757=== RUN TestProxyWriteTimeout/unknown_size758=== PAUSE TestProxyWriteTimeout/unknown_size759=== PAUSE TestIsValidUploadKey/realisation_plus_in_output760=== RUN TestIsValidUploadKey/nix-cache-info761=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle762=== PAUSE TestIsValidUploadKey/nix-cache-info763=== RUN TestIsValidUploadKey/index.html764=== PAUSE TestIsValidUploadKey/index.html765=== RUN TestIsValidUploadKey/narinfo_key,_nar_type766=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type767=== RUN TestIsValidUploadKey/nar_key,_narinfo_type768=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type769=== RUN TestIsValidUploadKey/listing_key,_narinfo_type770=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type771=== RUN TestIsValidUploadKey/traversal772=== PAUSE TestIsValidUploadKey/traversal773=== RUN TestIsValidUploadKey/traversal_nar774=== PAUSE TestIsValidUploadKey/traversal_nar775=== RUN TestIsValidUploadKey/absolute776=== PAUSE TestIsValidUploadKey/absolute777=== RUN TestIsValidUploadKey/empty_key778=== PAUSE TestIsValidUploadKey/empty_key779=== RUN TestIsValidUploadKey/unknown_type780=== PAUSE TestIsValidUploadKey/unknown_type781=== CONT TestSkippedUploadsHandler7822026/10/06 21:19:35 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000783--- PASS: TestSkippedUploadsHandler (0.00s)784=== CONT TestParseSize785--- PASS: TestParseSize (0.00s)786=== CONT TestService_Rustfstest787=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure788=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure789=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart790=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart791=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts792=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts793=== CONT TestPresignedUploadRegisteredBeforeCommit7942026/10/06 21:19:35 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"795--- PASS: TestService_AuthMiddleware (0.36s)796=== CONT TestCompletedNarNotReofferedAcrossClosures797--- PASS: TestMetricsInventory (0.51s)798=== CONT TestCompleteMultipartUpload_ErrorButObjectExists7992026/10/06 21:19:36 INFO Received uploads request method=POST path=/api/pending_closures8002026/10/06 21:19:36 INFO Received uploads request method=POST path=/api/pending_closures8012026/10/06 21:19:36 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst8022026/10/06 21:19:36 INFO Received uploads request method=POST path=/api/pending_closures803--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.85s)804=== CONT TestReadProxyNarStreaming805--- PASS: TestService_Rustfstest (1.04s)806=== CONT TestReadProxyContentNegotiation8072026/10/06 21:19:36 INFO Received uploads request method=POST path=/api/pending_closures8082026/10/06 21:19:36 INFO Received uploads request method=POST path=/api/pending_closures8092026/10/06 21:19:36 INFO Received uploads request method=POST path=/api/pending_closures8102026/10/06 21:19:37 INFO Received uploads request method=POST path=/api/pending_closures811--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.56s)812=== CONT TestReadProxyNarinfoAlreadyDecompressed8132026/10/06 21:19:37 INFO Received cleanup request method=DELETE path=/api/pending_closures8142026/10/06 21:19:37 INFO Aborted multipart uploads count=0 kept=08152026/10/06 21:19:37 INFO Received uploads request method=POST path=/api/pending_closures8162026/10/06 21:19:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8172026/10/06 21:19:37 INFO Received cleanup request method=DELETE path=/api/pending_closures8182026/10/06 21:19:37 INFO Aborted multipart uploads count=1 kept=08192026/10/06 21:19:37 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=OGJkZGU3NDAtMDYwNy00MTdiLTg1OTUtMDUwNjhiODRhYjg2LjljZDA0MzNlLWM1M2EtNGQyYS1hNzliLTY5ZDQ4ZjFhMmFlZXgxNzkxMzIxNTc2MjA2MDY5MDAw parts=108202026/10/06 21:19:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8212026/10/06 21:19:37 INFO Completed upload id=18222026/10/06 21:19:37 INFO Received uploads request method=POST path=/api/pending_closures8232026/10/06 21:19:37 INFO Received uploads request method=POST path=/api/pending_closures8242026/10/06 21:19:37 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo8252026/10/06 21:19:37 WARN Found objects in DB but missing from S3, will re-upload count=1826--- PASS: TestService_verifyS3Integrity (1.92s)827=== CONT TestReadProxyNarinfo8282026/10/06 21:19:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8292026-10-06 21:19:37.430 UTC [43592] ERROR: Closure does not exist: id=18302026-10-06 21:19:37.430 UTC [43592] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE8312026-10-06 21:19:37.430 UTC [43592] STATEMENT: -- name: CommitPendingClosure :exec832 SELECT commit_pending_closure($1::bigint)833 834--- PASS: TestService_cleanupPendingClosuresHandler (1.92s)835=== CONT TestIsValidCachePath836=== RUN TestIsValidCachePath/narinfo837=== PAUSE TestIsValidCachePath/narinfo838=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars839=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars840=== RUN TestIsValidCachePath/nar_zst841=== PAUSE TestIsValidCachePath/nar_zst842=== RUN TestIsValidCachePath/nar_xz843=== PAUSE TestIsValidCachePath/nar_xz844=== RUN TestIsValidCachePath/nar_bz2845=== PAUSE TestIsValidCachePath/nar_bz2846=== RUN TestIsValidCachePath/nar_uncompressed847=== PAUSE TestIsValidCachePath/nar_uncompressed848=== RUN TestIsValidCachePath/ls849=== PAUSE TestIsValidCachePath/ls850=== RUN TestIsValidCachePath/log851=== PAUSE TestIsValidCachePath/log852=== RUN TestIsValidCachePath/realisation853=== PAUSE TestIsValidCachePath/realisation854=== RUN TestIsValidCachePath/nix-cache-info855=== PAUSE TestIsValidCachePath/nix-cache-info856=== RUN TestIsValidCachePath/index.html857=== PAUSE TestIsValidCachePath/index.html858=== RUN TestIsValidCachePath/traversal_parent859=== PAUSE TestIsValidCachePath/traversal_parent860=== RUN TestIsValidCachePath/traversal_in_middle861=== PAUSE TestIsValidCachePath/traversal_in_middle862=== RUN TestIsValidCachePath/invalid_char_e863=== PAUSE TestIsValidCachePath/invalid_char_e864=== RUN TestIsValidCachePath/invalid_char_u865=== PAUSE TestIsValidCachePath/invalid_char_u866=== RUN TestIsValidCachePath/random_path867=== PAUSE TestIsValidCachePath/random_path868=== RUN TestIsValidCachePath/empty869=== PAUSE TestIsValidCachePath/empty870=== RUN TestIsValidCachePath/leading_slash871=== PAUSE TestIsValidCachePath/leading_slash872=== RUN TestIsValidCachePath/wrong_extension873=== PAUSE TestIsValidCachePath/wrong_extension874=== RUN TestIsValidCachePath/short_hash875=== PAUSE TestIsValidCachePath/short_hash876=== CONT TestProxyHeadersOnlyTrustedOnSocket8772026/10/06 21:19:37 INFO Received uploads request method=POST path=/api/pending_closures8782026/10/06 21:19:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8792026/10/06 21:19:37 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst880--- PASS: TestCompleteMultipartUnregistered (2.29s)881=== CONT TestParseSingleRange882=== RUN TestParseSingleRange/none883=== PAUSE TestParseSingleRange/none884=== RUN TestParseSingleRange/unknown_unit885=== PAUSE TestParseSingleRange/unknown_unit886=== RUN TestParseSingleRange/multi-range_ignored887=== PAUSE TestParseSingleRange/multi-range_ignored888=== RUN TestParseSingleRange/malformed_no_dash889=== PAUSE TestParseSingleRange/malformed_no_dash890=== RUN TestParseSingleRange/malformed_both_empty891=== PAUSE TestParseSingleRange/malformed_both_empty892=== RUN TestParseSingleRange/malformed_end_before_start893=== PAUSE TestParseSingleRange/malformed_end_before_start894=== RUN TestParseSingleRange/closed895=== PAUSE TestParseSingleRange/closed896=== RUN TestParseSingleRange/open-ended897=== PAUSE TestParseSingleRange/open-ended898=== RUN TestParseSingleRange/end_clamped_to_size899=== PAUSE TestParseSingleRange/end_clamped_to_size900=== RUN TestParseSingleRange/suffix901=== PAUSE TestParseSingleRange/suffix902=== RUN TestParseSingleRange/suffix_exceeds_size903=== PAUSE TestParseSingleRange/suffix_exceeds_size904=== RUN TestParseSingleRange/single_byte905=== PAUSE TestParseSingleRange/single_byte906=== RUN TestParseSingleRange/start_past_EOF907=== PAUSE TestParseSingleRange/start_past_EOF908=== RUN TestParseSingleRange/start_far_past_EOF909=== PAUSE TestParseSingleRange/start_far_past_EOF910=== CONT TestPresentNotReportedWhileGCDeletesClosure911=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale912=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale913=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh914=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh915=== CONT TestPresentRefreshesOnlyStaleClosures9162026/10/06 21:19:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9172026/10/06 21:19:38 INFO Received uploads request method=POST path=/api/pending_closures9182026/10/06 21:19:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9192026/10/06 21:19:38 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=OGJkZGU3NDAtMDYwNy00MTdiLTg1OTUtMDUwNjhiODRhYjg2LjVmMTk5MGQ1LTU2ZTYtNDU3Mi05MzU3LTE3YTQyODM1NTg0ZngxNzkxMzIxNTc2Nzg5ODY0MDAw parts=109202026/10/06 21:19:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9212026/10/06 21:19:38 INFO Completed upload id=19222026/10/06 21:19:38 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009232026/10/06 21:19:38 INFO Received uploads request method=POST path=/api/pending_closures9242026/10/06 21:19:38 INFO Starting cleanup of old closures method=DELETE path=/api/closures9252026/10/06 21:19:38 INFO Aborted multipart uploads count=0 kept=09262026/10/06 21:19:38 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=09272026/10/06 21:19:38 INFO Vacuumed table table=pending_closures9282026/10/06 21:19:38 INFO Vacuumed table table=pending_objects9292026/10/06 21:19:38 INFO Vacuumed table table=multipart_uploads9302026/10/06 21:19:38 INFO Vacuumed table table=closures9312026/10/06 21:19:38 INFO Vacuumed table table=objects9322026/10/06 21:19:38 INFO Received uploads request method=POST path=/api/pending_closures9332026/10/06 21:19:38 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000934--- PASS: TestService_createPendingClosureHandler (2.78s)935=== CONT TestPresentReportsOnlyClosureRoots9362026/10/06 21:19:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9372026/10/06 21:19:38 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OGJkZGU3NDAtMDYwNy00MTdiLTg1OTUtMDUwNjhiODRhYjg2LmNhZmJkYTA1LTQ0MTQtNGE4ZS1iZDdmLWNkMzNmNjA5N2EzM3gxNzkxMzIxNTc4Mjk2NjE1MDAw9382026/10/06 21:19:38 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OGJkZGU3NDAtMDYwNy00MTdiLTg1OTUtMDUwNjhiODRhYjg2LmNhZmJkYTA1LTQ0MTQtNGE4ZS1iZDdmLWNkMzNmNjA5N2EzM3gxNzkxMzIxNTc4Mjk2NjE1MDAw parts=1939--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.48s)940=== CONT TestCreatePin_ReservedPins941--- PASS: TestReadProxyNarStreaming (2.15s)942=== CONT TestOrphanedObjectsGCStressTest9432026/10/06 21:19:38 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52232/oidc944--- PASS: TestReadProxyContentNegotiation (2.27s)945=== CONT TestOrphanedObjectsGC946--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.19s)947=== CONT TestObjectStatsTrigger9482026/10/06 21:19:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9492026/10/06 21:19:39 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=OGJkZGU3NDAtMDYwNy00MTdiLTg1OTUtMDUwNjhiODRhYjg2LjNmN2EyNjFhLTFlYzMtNGY2My1hZDRiLTJlZGI4OTg1NGRhYXgxNzkxMzIxNTc4MDQ4MTY2MDAw parts=129502026/10/06 21:19:39 INFO Received uploads request method=POST path=/api/pending_closures951--- PASS: TestCompletedNarNotReofferedAcrossClosures (3.56s)952=== CONT TestReadProxy4049532026/10/06 21:19:39 INFO Starting HTTP server address=127.0.0.1:522469542026/10/06 21:19:39 INFO Starting HTTP server address=/nix/var/nix/builds/nix-43476-3212982383/TestProxyHeadersOnlyTrustedOnSocket1360684169/001/proxy.sock9552026/10/06 21:19:39 WARN mTLS auth: subject not in bound subjects subject="CN=someone"9562026/10/06 21:19:39 INFO Shutdown signal received, draining in-flight requests timeout=10s957--- PASS: TestProxyHeadersOnlyTrustedOnSocket (2.05s)958=== CONT TestPendingCleanupUsesOneCutoff9592026/10/06 21:19:39 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>960--- PASS: TestReadProxyNarinfo (2.32s)961=== CONT TestRedundantMultipartUpload962--- PASS: TestPresentRefreshesOnlyStaleClosures (2.13s)963=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded964--- PASS: TestPresentReportsOnlyClosureRoots (1.85s)965=== CONT TestMultipartCleanup9662026/10/06 21:19:40 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9672026/10/06 21:19:40 WARN Refused reserved pin name=worker-x86_64-linux9682026/10/06 21:19:40 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9692026/10/06 21:19:40 INFO Received create pin request method=POST path=/api/pins/my-app9702026/10/06 21:19:40 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux971--- PASS: TestCreatePin_ReservedPins (1.85s)972=== CONT TestPush_SignsNarinfosOfItsPendingObjects973--- PASS: TestObjectStatsTrigger (1.97s)974=== CONT TestPush_RejectsBadRequests975=== NAME TestOrphanedObjectsGC976 orphaned_objects_gc_test.go:287: GC Test Summary:977 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A978 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B979 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)980 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)981 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects982--- PASS: TestOrphanedObjectsGC (2.48s)983=== CONT TestServerTLSConfig984=== RUN TestServerTLSConfig/no_client_CA985=== PAUSE TestServerTLSConfig/no_client_CA986=== RUN TestServerTLSConfig/missing_CA_file987=== PAUSE TestServerTLSConfig/missing_CA_file988=== RUN TestServerTLSConfig/not_a_PEM_file989=== PAUSE TestServerTLSConfig/not_a_PEM_file990=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit9912026/10/06 21:19:41 INFO Received uploads request method=POST path=/api/pending_closures9922026/10/06 21:19:41 INFO Received uploads request method=POST path=/api/pending_closures9932026/10/06 21:19:41 INFO Received cleanup request method=DELETE path=/api/pending_closures9942026/10/06 21:19:41 WARN Rate limiter enabled after throttle name=s3-test rate=59952026/10/06 21:19:41 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."996=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle997 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=10998 throttle_test.go:215: Rate limiter: enabled=true, rate=5.00999--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (6.25s)1000=== CONT TestService_NativeMTLS1001--- PASS: TestReadProxy404 (2.50s)1002=== CONT TestPush_RootsAreLockedInByteOrder10032026/10/06 21:19:42 INFO Received uploads request method=POST path=/api/pending_closures10042026/10/06 21:19:42 INFO Received uploads request method=POST path=/api/pending_closures10052026/10/06 21:19:42 INFO Received uploads request method=POST path=/api/pending_closures1006--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (2.64s)1007=== CONT TestReadRedirectNar10082026/10/06 21:19:42 INFO Received uploads request method=POST path=/api/pending_closures10092026/10/06 21:19:43 INFO Received cleanup request method=DELETE path=/api/pending_closures10102026/10/06 21:19:43 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket30/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""10112026/10/06 21:19:43 INFO Aborted multipart uploads count=0 kept=110122026/10/06 21:19:43 INFO Received cleanup request method=DELETE path=/api/pending_closures10132026/10/06 21:19:43 INFO Aborted multipart uploads count=1 kept=01014--- PASS: TestMultipartCleanup (2.97s)1015=== CONT TestReadRedirectKeepsNarinfoProxied10162026/10/06 21:19:43 INFO Received push request method=POST path=/api/pushes10172026/10/06 21:19:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10182026/10/06 21:19:43 INFO Signed narinfos id=1 count=110192026/10/06 21:19:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10202026/10/06 21:19:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10212026/10/06 21:19:43 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"10222026/10/06 21:19:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10232026/10/06 21:19:43 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"10242026/10/06 21:19:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10252026/10/06 21:19:43 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=110262026/10/06 21:19:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10272026/10/06 21:19:43 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1028--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (3.19s)1029=== CONT TestReadProxyDisabled10302026/10/06 21:19:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10312026/10/06 21:19:44 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=OGJkZGU3NDAtMDYwNy00MTdiLTg1OTUtMDUwNjhiODRhYjg2Ljg0NDg4ZmVlLWNlODEtNDkwNi1iZTRjLTZiNWY3ODgyZTAzMngxNzkxMzIxNTgyMTUwNzU5MDAw parts=1210322026/10/06 21:19:44 INFO Received uploads request method=POST path=/api/pending_closures10332026/10/06 21:19:44 INFO Received uploads request method=POST path=/api/pending_closures1034=== RUN TestPush_RejectsBadRequests/no_roots1035=== PAUSE TestPush_RejectsBadRequests/no_roots1036=== RUN TestPush_RejectsBadRequests/no_objects1037=== PAUSE TestPush_RejectsBadRequests/no_objects1038=== RUN TestPush_RejectsBadRequests/bad_root1039=== PAUSE TestPush_RejectsBadRequests/bad_root1040=== RUN TestPush_RejectsBadRequests/root_not_in_objects1041=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1042=== CONT TestPush_CompleteWaitsForCleanupOfThePush10432026/10/06 21:19:45 INFO Received push request method=POST path=/api/pushes10442026/10/06 21:19:45 INFO Received complete push request method=POST path=/api/pushes/1/complete10452026/10/06 21:19:45 INFO Received push request method=POST path=/api/pushes10462026/10/06 21:19:45 INFO Aborted multipart uploads count=0 kept=010472026/10/06 21:19:45 WARN Force mode enabled - objects will be deleted immediately without grace period10482026/10/06 21:19: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=010492026/10/06 21:19:45 INFO Vacuumed table table=pending_closures10502026/10/06 21:19:45 INFO Vacuumed table table=pending_objects10512026/10/06 21:19:45 INFO Vacuumed table table=multipart_uploads10522026/10/06 21:19:45 WARN mTLS auth: subject not in bound subjects subject="CN=reader"10532026/10/06 21:19:45 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1054--- PASS: TestService_NativeMTLS (3.77s)1055=== CONT TestReadProxyRootRedirectsToIndexHTML10562026/10/06 21:19:45 INFO Vacuumed table table=closures10572026/10/06 21:19:45 INFO Vacuumed table table=objects10582026/10/06 21:19:45 INFO Received complete push request method=POST path=/api/pushes/2/complete1059--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (4.29s)1060=== CONT TestPush_RepeatedRootCommitsOnce10612026/10/06 21:19:45 INFO Received push request method=POST path=/api/pushes10622026-10-06 21:19:45.997 UTC [43710] ERROR: could not obtain lock on row in relation "closures"10632026-10-06 21:19:45.997 UTC [43710] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10642026-10-06 21:19:45.997 UTC [43710] ERROR: could not obtain lock on row in relation "closures"10652026-10-06 21:19:45.997 UTC [43710] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10662026-10-06 21:19:45.997 UTC [43710] ERROR: could not obtain lock on row in relation "closures"10672026-10-06 21:19:45.997 UTC [43710] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10682026-10-06 21:19:45.997 UTC [43710] ERROR: could not obtain lock on row in relation "closures"10692026-10-06 21:19:45.997 UTC [43710] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10702026-10-06 21:19:45.998 UTC [43710] ERROR: could not obtain lock on row in relation "closures"10712026-10-06 21:19:45.998 UTC [43710] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1072--- PASS: TestPush_RootsAreLockedInByteOrder (4.08s)1073=== CONT TestReadProxyConditionalGet1074--- PASS: TestReadRedirectNar (3.79s)1075=== CONT TestPush_CompleteCommitsEveryRoot10762026/10/06 21:19:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10772026/10/06 21:19:46 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=OGJkZGU3NDAtMDYwNy00MTdiLTg1OTUtMDUwNjhiODRhYjg2LjQ5OWEwYmYwLTJlM2EtNDc4NC1iNGZlLTE1ZjY3YzJmYmE0NXgxNzkxMzIxNTg0MjMzMzY5MDAw error="Get \"http://127.0.0.1:1/bucket28/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"10782026/10/06 21:19:46 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=OGJkZGU3NDAtMDYwNy00MTdiLTg1OTUtMDUwNjhiODRhYjg2LjkyNTU5MmYxLTRlYTctNGZhMy1iN2JmLWU3OTI4NWUxOGZjNHgxNzkxMzIxNTg0MTQ2MDczMDAw parts=1210792026/10/06 21:19:46 INFO Received cleanup request method=DELETE path=/api/pending_closures10802026/10/06 21:19:46 INFO Aborted multipart uploads count=1 kept=01081--- PASS: TestRedundantMultipartUpload (6.83s)1082=== CONT TestReadProxyOutlastsServerWriteTimeout1083--- PASS: TestReadRedirectKeepsNarinfoProxied (3.55s)1084=== CONT TestReadProxyHead1085--- PASS: TestReadProxyDisabled (3.52s)1086=== CONT TestPush_OverlappingRootsStoreOneRowPerKey1087=== NAME TestOrphanedObjectsGCStressTest1088 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains10892026/10/06 21:19:47 INFO Received push request method=POST path=/api/pushes1090 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion10912026/10/06 21:19:47 INFO Aborted multipart uploads count=1 kept=010922026/10/06 21:19:47 INFO Received cleanup request method=DELETE path=/api/pending_closures10932026/10/06 21:19:47 INFO Aborted multipart uploads count=1 kept=01094--- PASS: TestPendingCleanupUsesOneCutoff (8.11s)1095=== CONT TestReadProxyInvalidPath1096--- PASS: TestReadProxyRootRedirectsToIndexHTML (2.28s)1097=== CONT TestReadRedirectUsesPublicS3URL10982026-10-06 21:19:47.898 UTC [43784] ERROR: Push does not exist: id=110992026-10-06 21:19:47.898 UTC [43784] CONTEXT: PL/pgSQL function commit_push(bigint) line 10 at RAISE11002026-10-06 21:19:47.898 UTC [43784] STATEMENT: SELECT commit_push($1)1101--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (3.24s)1102=== CONT TestReadProxyRangeRequest11032026/10/06 21:19:48 INFO Received push request method=POST path=/api/pushes11042026/10/06 21:19:48 INFO Received complete push request method=POST path=/api/pushes/1/complete1105--- PASS: TestPush_RepeatedRootCommitsOnce (2.60s)1106=== CONT TestDeduplicatedObjectsRecordedAsPending1107--- PASS: TestReadProxyConditionalGet (2.34s)1108=== CONT TestGCTaskStore_DeduplicateSameParams1109--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1110=== CONT TestGCTaskStore_StartNew1111--- PASS: TestGCTaskStore_StartNew (0.00s)1112=== CONT TestNARDeduplicationMetadataUploadBug11132026/10/06 21:19:48 INFO Received push request method=POST path=/api/pushes11142026/10/06 21:19:48 INFO Received complete push request method=POST path=/api/pushes/1/complete1115--- PASS: TestPush_CompleteCommitsEveryRoot (2.33s)1116=== CONT TestCreatePendingClosureRejectsOversizedNAR11172026/10/06 21:19:48 INFO Received uploads request method=POST path=/api/pending_closures1118--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1119=== CONT TestGCEndsOnShutdown1120=== RUN TestGCEndsOnShutdown/before_the_run1121=== PAUSE TestGCEndsOnShutdown/before_the_run1122=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1123=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1124=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1125=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1126=== CONT TestCacheConfigHandlerMaxNarSize1127--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1128=== CONT TestCommitRacingPendingCleanupKeepsObjects1129--- PASS: TestReadProxyHead (2.56s)1130=== CONT TestGenerateLandingPage1131--- PASS: TestGenerateLandingPage (0.00s)1132=== CONT TestPushWaitsForSweepHoldingRow11332026/10/06 21:19:49 INFO Received push request method=POST path=/api/pushes1134--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (2.55s)1135=== CONT TestService_readinessHandler1136--- PASS: TestReadProxyInvalidPath (2.27s)1137=== CONT TestSweepRechecksPendingAfterLocking1138--- PASS: TestReadRedirectUsesPublicS3URL (2.42s)1139=== CONT TestService_healthCheckHandler1140=== NAME TestOrphanedObjectsGCStressTest1141 orphaned_objects_gc_test.go:503: Stress test completed successfully:1142 orphaned_objects_gc_test.go:504: - Active objects preserved: 201143 orphaned_objects_gc_test.go:505: - Objects deleted: 2101144 orphaned_objects_gc_test.go:506: - Total GC'd: 2101145--- PASS: TestOrphanedObjectsGCStressTest (11.74s)1146=== CONT TestGetExistingObjectsLocksRows1147--- PASS: TestReadProxyRangeRequest (2.59s)1148=== CONT TestGracefulShutdownDrainsInflight11492026/10/06 21:19:50 INFO Starting HTTP server address=127.0.0.1:5237511502026/10/06 21:19:50 INFO Shutdown signal received, draining in-flight requests timeout=10s1151--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1152=== CONT TestRegisterCompletedObjectNeedsPendingRow11532026/10/06 21:19:50 INFO Received uploads request method=POST path=/api/pending_closures1154--- PASS: TestDeduplicatedObjectsRecordedAsPending (2.67s)1155=== CONT TestGCTaskStore_Fail1156--- PASS: TestGCTaskStore_Fail (0.00s)1157=== CONT TestSweepSkipsRowsLockedByPush1158=== NAME TestNARDeduplicationMetadataUploadBug1159 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-43476-3212982383/TestNARDeduplicationMetadataUploadBug3857245979/001/store/4zb3rdgq15gzix7vxhkkb5a7ydqjx1hb-file1.txt11602026/10/06 21:19:51 INFO Received push request method=POST path=/api/pushes11612026/10/06 21:19:51 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11622026/10/06 21:19:51 INFO Uploading 4zb3rdgq15gzix7vxhkkb5a7ydqjx1hb-file1.txt (160B)11632026/10/06 21:19:51 WARN Failed to register uploaded object key=4zb3rdgq15gzix7vxhkkb5a7ydqjx1hb.ls error="server returned 404: 404 page not found\n"11642026/10/06 21:19:51 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11652026/10/06 21:19:51 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11662026/10/06 21:19:51 INFO Signed narinfos id=1 count=111672026/10/06 21:19:51 INFO Uploading 1 narinfos11682026/10/06 21:19:51 INFO Aborted multipart uploads count=0 kept=011692026/10/06 21:19:51 WARN Force mode enabled - objects will be deleted immediately without grace period11702026/10/06 21:19: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=011712026/10/06 21:19:51 INFO Vacuumed table table=pending_closures11722026/10/06 21:19:51 INFO Received complete push request method=POST path=/api/pushes/1/complete11732026/10/06 21:19:51 WARN Failed to register uploaded object key=4zb3rdgq15gzix7vxhkkb5a7ydqjx1hb.narinfo error="server returned 404: 404 page not found\n"11742026/10/06 21:19:51 INFO Vacuumed table table=pending_objects11752026/10/06 21:19:51 INFO Vacuumed table table=multipart_uploads11762026/10/06 21:19:51 INFO Upload complete. (233ms)1177 metadata_upload_test.go:54: Retrieved narinfo from S3:1178 StorePath: /nix/var/nix/builds/nix-43476-3212982383/TestNARDeduplicationMetadataUploadBug3857245979/001/store/4zb3rdgq15gzix7vxhkkb5a7ydqjx1hb-file1.txt1179 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1180 Compression: zstd1181 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1182 NarSize: 1601183 References: 1184 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1185 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1186 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1187 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}11882026/10/06 21:19:51 INFO Vacuumed table table=closures11892026/10/06 21:19:51 INFO Vacuumed table table=objects1190--- PASS: TestCommitRacingPendingCleanupKeepsObjects (3.10s)1191=== CONT TestGCTaskStore_PhaseUpdates1192--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1193=== CONT TestGCTaskStore_CompletedAllowsNewTask1194--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1195=== CONT TestFailedS3DeleteKeepsTombstone1196=== NAME TestNARDeduplicationMetadataUploadBug1197 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-43476-3212982383/TestNARDeduplicationMetadataUploadBug3857245979/001/store/1686qk0hs81f18frarxclbajr5pkc0d1-file2.txt11982026/10/06 21:19:51 INFO Received uploads request method=POST path=/api/pending_closures11992026/10/06 21:19:52 INFO Received push request method=POST path=/api/pushes12002026/10/06 21:19:52 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12012026/10/06 21:19:52 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12022026/10/06 21:19:52 INFO Signed narinfos id=2 count=112032026/10/06 21:19:52 WARN Failed to register uploaded object key=1686qk0hs81f18frarxclbajr5pkc0d1.ls error="server returned 404: 404 page not found\n"12042026/10/06 21:19:52 INFO Uploading 1 narinfos12052026/10/06 21:19:52 INFO Received complete push request method=POST path=/api/pushes/2/complete12062026/10/06 21:19:52 WARN Failed to register uploaded object key=1686qk0hs81f18frarxclbajr5pkc0d1.narinfo error="server returned 404: 404 page not found\n"12072026/10/06 21:19:52 INFO Upload complete. (108ms)1208 metadata_upload_test.go:76: Retrieved narinfo from S3:1209 StorePath: /nix/var/nix/builds/nix-43476-3212982383/TestNARDeduplicationMetadataUploadBug3857245979/001/store/1686qk0hs81f18frarxclbajr5pkc0d1-file2.txt1210 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1211 Compression: zstd1212 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1213 NarSize: 1601214 References: 1215 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1216 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1217 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1218 {"version":1,"root":{"type":"regular","size":44}}1219=== CONT TestGCTaskStore_GetReturnsLatest1220--- PASS: TestNARDeduplicationMetadataUploadBug (3.86s)1221=== CONT TestForceGCDuringPushOffersSweptObject1222--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1223=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1224=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1225=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1226=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1227=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection12282026/10/06 21:19:52 WARN readiness check failed error="closed pool"1229--- PASS: TestService_readinessHandler (2.83s)1230=== CONT TestGCTaskStore_GetEmpty1231--- PASS: TestGCTaskStore_GetEmpty (0.00s)1232=== CONT TestGCSweepDeliversEachKeyOnce1233--- PASS: TestPushWaitsForSweepHoldingRow (3.24s)1234=== CONT TestGCTaskStore_ConflictDifferentParams1235--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1236=== CONT TestTombstonedObjectOfferedWithoutWaiting12372026/10/06 21:19:52 INFO Aborted multipart uploads count=0 kept=012382026/10/06 21:19:52 WARN Force mode enabled - objects will be deleted immediately without grace period12392026/10/06 21:19:53 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=012402026/10/06 21:19:53 INFO Vacuumed table table=pending_closures12412026/10/06 21:19:53 INFO Vacuumed table table=pending_objects12422026/10/06 21:19:53 INFO Vacuumed table table=multipart_uploads1243--- PASS: TestReadProxyOutlastsServerWriteTimeout (6.51s)1244=== CONT TestGCSweepSkipsPendingObjects12452026/10/06 21:19:53 INFO Vacuumed table table=closures12462026/10/06 21:19:53 INFO Vacuumed table table=objects1247--- PASS: TestSweepRechecksPendingAfterLocking (3.24s)1248=== CONT TestPinProtectsFromGC1249--- PASS: TestService_healthCheckHandler (3.13s)1250=== CONT TestPushDedupSurvivesConcurrentGC1251--- PASS: TestGetExistingObjectsLocksRows (3.49s)1252=== CONT TestGCMetrics1253--- PASS: TestRegisterCompletedObjectNeedsPendingRow (3.50s)1254=== CONT TestGCBugBareHashReferences12552026/10/06 21:19:54 INFO Aborted multipart uploads count=0 kept=012562026/10/06 21:19:54 WARN Force mode enabled - objects will be deleted immediately without grace period12572026/10/06 21:19: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=012582026/10/06 21:19:54 INFO Vacuumed table table=pending_closures12592026/10/06 21:19:54 INFO Vacuumed table table=pending_objects12602026/10/06 21:19:54 INFO Vacuumed table table=multipart_uploads12612026/10/06 21:19:54 INFO Vacuumed table table=closures12622026/10/06 21:19:54 INFO Vacuumed table table=objects12632026/10/06 21:19:54 INFO Aborted multipart uploads count=0 kept=012642026/10/06 21:19:54 WARN Force mode enabled - objects will be deleted immediately without grace period12652026/10/06 21:19:54 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=012662026/10/06 21:19:54 INFO Vacuumed table table=pending_closures12672026/10/06 21:19:54 INFO Vacuumed table table=pending_objects12682026/10/06 21:19:54 INFO Vacuumed table table=multipart_uploads12692026/10/06 21:19:54 INFO Vacuumed table table=closures12702026/10/06 21:19:54 INFO Vacuumed table table=objects1271--- PASS: TestSweepSkipsRowsLockedByPush (3.79s)1272=== CONT TestGCAdvisoryLockBlocksConcurrentRun12732026/10/06 21:19:54 INFO Received uploads request method=POST path=/api/pending_closures12742026/10/06 21:19:55 INFO Aborted multipart uploads count=0 kept=012752026/10/06 21:19:55 WARN Force mode enabled - objects will be deleted immediately without grace period12762026/10/06 21:19:55 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."12772026/10/06 21:19:55 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1278--- PASS: TestFailedS3DeleteKeepsTombstone (3.41s)1279=== CONT TestLeadEndsOnShutdown12802026/10/06 21:19:55 INFO Received uploads request method=POST path=/api/pending_closures1281--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (3.46s)1282=== CONT TestLeadIncumbentAnnouncesAtOnce12832026/10/06 21:19:56 INFO Aborted multipart uploads count=0 kept=012842026/10/06 21:19:56 WARN Force mode enabled - objects will be deleted immediately without grace period12852026/10/06 21:19:56 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=012862026/10/06 21:19:56 INFO Vacuumed table table=pending_closures12872026/10/06 21:19:56 INFO Vacuumed table table=pending_objects12882026/10/06 21:19:56 INFO Vacuumed table table=multipart_uploads12892026/10/06 21:19:56 INFO Vacuumed table table=closures12902026/10/06 21:19:56 INFO Vacuumed table table=objects1291--- PASS: TestGCSweepDeliversEachKeyOnce (3.82s)1292=== CONT TestLeadElectsOneAndHandsOver12932026/10/06 21:19:56 INFO Received uploads request method=POST path=/api/pending_closures1294--- PASS: TestTombstonedObjectOfferedWithoutWaiting (3.89s)1295=== CONT TestConnectWaitsForAPeerMigration12962026/10/06 21:19:57 INFO Received uploads request method=POST path=/api/pending_closures12972026/10/06 21:19:57 INFO Aborted multipart uploads count=0 kept=012982026/10/06 21:19:57 WARN Force mode enabled - objects will be deleted immediately without grace period12992026/10/06 21:19: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=013002026/10/06 21:19:57 INFO Vacuumed table table=pending_closures13012026/10/06 21:19:57 INFO Vacuumed table table=pending_objects13022026/10/06 21:19:57 INFO Vacuumed table table=multipart_uploads13032026/10/06 21:19:57 INFO Vacuumed table table=closures13042026/10/06 21:19:57 INFO Vacuumed table table=objects1305=== NAME TestPinProtectsFromGC1306 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-43476-3212982383/TestPinProtectsFromGC3892350635/001/store/37dyg0vvim7ciij15pil2qw22vwhjaqj-pinned-file.txt1307 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-43476-3212982383/TestPinProtectsFromGC3892350635/001/store/7rgbn8yk0ph33vcxnfr1wbi4amcb44vp-unpinned-file.txt1308--- PASS: TestGCSweepSkipsPendingObjects (4.35s)1309=== CONT TestResolveDBConnectionString1310=== RUN TestResolveDBConnectionString/flag_wins1311=== PAUSE TestResolveDBConnectionString/flag_wins1312=== RUN TestResolveDBConnectionString/file_when_flag_empty1313=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1314=== RUN TestResolveDBConnectionString/missing_file_is_an_error1315=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1316=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1317=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1318=== RUN TestResolveDBConnectionString/nothing_configured1319=== PAUSE TestResolveDBConnectionString/nothing_configured1320=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock13212026/10/06 21:19:57 INFO Received push request method=POST path=/api/pushes13222026/10/06 21:19:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13232026/10/06 21:19:57 INFO Uploading 37dyg0vvim7ciij15pil2qw22vwhjaqj-pinned-file.txt (128B)13242026/10/06 21:19:57 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"13252026/10/06 21:19:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13262026/10/06 21:19:57 WARN Failed to register uploaded object key=37dyg0vvim7ciij15pil2qw22vwhjaqj.ls error="server returned 404: 404 page not found\n"13272026/10/06 21:19:57 INFO Signed narinfos id=1 count=113282026/10/06 21:19:57 INFO Uploading 1 narinfos13292026/10/06 21:19:57 INFO Received complete push request method=POST path=/api/pushes/1/complete13302026/10/06 21:19:57 WARN Failed to register uploaded object key=37dyg0vvim7ciij15pil2qw22vwhjaqj.narinfo error="server returned 404: 404 page not found\n"13312026/10/06 21:19:57 INFO Received uploads request method=POST path=/api/pending_closures13322026/10/06 21:19:57 INFO Upload complete. (263ms)13332026/10/06 21:19:57 INFO Aborted multipart uploads count=0 kept=013342026/10/06 21:19:57 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=013352026/10/06 21:19:57 INFO Received push request method=POST path=/api/pushes13362026/10/06 21:19:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13372026/10/06 21:19:57 INFO Uploading 7rgbn8yk0ph33vcxnfr1wbi4amcb44vp-unpinned-file.txt (128B)13382026/10/06 21:19:57 INFO Aborted multipart uploads count=0 kept=013392026/10/06 21:19:57 WARN Force mode enabled - objects will be deleted immediately without grace period13402026/10/06 21:19: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=013412026/10/06 21:19:57 INFO Vacuumed table table=pending_closures13422026/10/06 21:19:57 INFO Vacuumed table table=pending_closures13432026/10/06 21:19:57 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13442026/10/06 21:19:57 INFO Signed narinfos id=2 count=113452026/10/06 21:19:57 INFO Uploading 1 narinfos13462026/10/06 21:19:57 WARN Failed to register uploaded object key=7rgbn8yk0ph33vcxnfr1wbi4amcb44vp.ls error="server returned 404: 404 page not found\n"13472026/10/06 21:19:57 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"13482026/10/06 21:19:57 INFO Vacuumed table table=pending_objects13492026/10/06 21:19:57 INFO Vacuumed table table=multipart_uploads13502026/10/06 21:19:57 INFO Vacuumed table table=closures13512026/10/06 21:19:57 INFO Vacuumed table table=objects1352--- PASS: TestGCMetrics (4.09s)1353=== CONT TestDeleteClosuresRacingPins13542026/10/06 21:19:57 INFO Received complete push request method=POST path=/api/pushes/2/complete13552026/10/06 21:19:57 WARN Failed to register uploaded object key=7rgbn8yk0ph33vcxnfr1wbi4amcb44vp.narinfo error="server returned 404: 404 page not found\n"13562026/10/06 21:19:57 INFO Upload complete. (109ms)13572026/10/06 21:19:57 INFO Vacuumed table table=pending_objects13582026/10/06 21:19:57 INFO Vacuumed table table=multipart_uploads13592026/10/06 21:19:57 INFO Vacuumed table table=closures13602026/10/06 21:19:57 INFO Starting cleanup of old closures method=DELETE path=/api/closures13612026/10/06 21:19:57 INFO Garbage collection started13622026/10/06 21:19:57 INFO Aborted multipart uploads count=0 kept=013632026/10/06 21:19:57 WARN Force mode enabled - objects will be deleted immediately without grace period13642026/10/06 21:19:57 INFO Vacuumed table table=objects13652026/10/06 21:19:57 INFO Aborted multipart uploads count=0 kept=013662026/10/06 21:19:57 WARN Force mode enabled - objects will be deleted immediately without grace period13672026/10/06 21:19: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=013682026/10/06 21:19:57 INFO Vacuumed table table=pending_closures13692026/10/06 21:19:57 INFO Vacuumed table table=pending_objects13702026/10/06 21:19:57 INFO Vacuumed table table=multipart_uploads13712026/10/06 21:19:57 INFO Vacuumed table table=closures13722026/10/06 21:19:57 INFO Vacuumed table table=objects1373--- PASS: TestPushDedupSurvivesConcurrentGC (4.63s)1374=== CONT TestClientFallsBackToClosures13752026/10/06 21:19:58 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=013762026/10/06 21:19:58 INFO Vacuumed table table=pending_closures13772026/10/06 21:19:58 INFO Vacuumed table table=pending_objects13782026/10/06 21:19:58 INFO Vacuumed table table=multipart_uploads13792026/10/06 21:19:58 INFO Vacuumed table table=closures13802026/10/06 21:19:58 INFO Vacuumed table table=objects1381--- PASS: TestGCBugBareHashReferences (4.41s)1382=== CONT TestClientPushesUseOnePush13832026/10/06 21:19:58 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"1384--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (3.94s)1385=== CONT TestService_AuthMiddleware_OIDC13862026/10/06 21:19:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52455/oidc13872026/10/06 21:19:58 INFO lead: acquired remote=192.0.2.1:123413882026/10/06 21:19:59 INFO lead: acquired remote=192.0.2.1:123413892026/10/06 21:19:59 INFO lead: released remote=192.0.2.1:12341390--- PASS: TestLeadIncumbentAnnouncesAtOnce (3.39s)1391=== CONT TestCacheConfigHandler1392=== RUN TestCacheConfigHandler/full_config,_no_issuer1393=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1394=== RUN TestCacheConfigHandler/no_cache_url_configured1395=== PAUSE TestCacheConfigHandler/no_cache_url_configured1396=== RUN TestCacheConfigHandler/no_signing_keys1397=== PAUSE TestCacheConfigHandler/no_signing_keys1398=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1399=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1400=== CONT TestService_ReadScope_PublicByDefault14012026/10/06 21:19:59 INFO lead: acquired remote=192.0.2.1:123414022026/10/06 21:19:59 INFO lead: released remote=192.0.2.1:12341403--- PASS: TestLeadEndsOnShutdown (4.68s)1404=== CONT TestService_RequireScope_OIDC14052026/10/06 21:19:59 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=014062026/10/06 21:19:59 INFO Received create pin request method=POST path=/api/pins/myapp14072026/10/06 21:19:59 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-43476-3212982383/TestPinProtectsFromGC3892350635/001/store/37dyg0vvim7ciij15pil2qw22vwhjaqj-pinned-file.txt narinfo_key=37dyg0vvim7ciij15pil2qw22vwhjaqj.narinfo14082026/10/06 21:19:59 INFO Starting cleanup of old closures method=DELETE path=/api/closures14092026/10/06 21:19:59 INFO Garbage collection started14102026/10/06 21:19:59 INFO Aborted multipart uploads count=0 kept=014112026/10/06 21:19:59 WARN Force mode enabled - objects will be deleted immediately without grace period14122026/10/06 21:19:59 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=014132026/10/06 21:19:59 INFO Vacuumed table table=pending_closures14142026/10/06 21:19:59 INFO Vacuumed table table=pending_objects14152026/10/06 21:19:59 INFO Vacuumed table table=multipart_uploads14162026/10/06 21:19:59 INFO Vacuumed table table=closures14172026/10/06 21:19:59 INFO Vacuumed table table=objects14182026/10/06 21:19:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52467/oidc1419--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (2.92s)1420=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14212026/10/06 21:20:00 INFO Received uploads request method=POST path=/api/pending_closures14222026/10/06 21:20:00 INFO Received uploads request method=POST path=/api/pending_closures14232026/10/06 21:20:00 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14242026/10/06 21:20:00 INFO Uploading bsiw6lkzrxcv5csi3h6d948hw8mcj66l-shared-dep (136B)14252026/10/06 21:20:00 INFO Uploading z4p349j74hpxivyz384n981sqjahi3r2-a (248B)14262026/10/06 21:20:00 WARN Failed to register uploaded object key=bsiw6lkzrxcv5csi3h6d948hw8mcj66l.ls error="server returned 404: 404 page not found\n"14272026/10/06 21:20:00 WARN Failed to register uploaded object key=z4p349j74hpxivyz384n981sqjahi3r2.ls error="server returned 404: 404 page not found\n"14282026/10/06 21:20:00 WARN Failed to register uploaded object key=fbzccy5za4zxc3l233299aiicaqw5j2a.ls error="server returned 404: 404 page not found\n"14292026/10/06 21:20:00 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14302026/10/06 21:20:00 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14312026/10/06 21:20:00 WARN Failed to register uploaded object key=nar/149b031z1kxk5j9yj5xvfl51w3qa8hn9qi4ixb22kmll0fvdjpwb.nar.zst error="server returned 404: 404 page not found\n"14322026/10/06 21:20:00 INFO Signed narinfos id=1 count=214332026/10/06 21:20:00 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14342026/10/06 21:20:00 INFO Signed narinfos id=2 count=214352026/10/06 21:20:00 INFO Uploading 4 narinfos14362026/10/06 21:20:00 WARN Failed to register uploaded object key=z4p349j74hpxivyz384n981sqjahi3r2.narinfo error="server returned 404: 404 page not found\n"14372026/10/06 21:20:00 WARN Failed to register uploaded object key=bsiw6lkzrxcv5csi3h6d948hw8mcj66l.narinfo error="server returned 404: 404 page not found\n"14382026/10/06 21:20:00 WARN Failed to register uploaded object key=fbzccy5za4zxc3l233299aiicaqw5j2a.narinfo error="server returned 404: 404 page not found\n"14392026/10/06 21:20:00 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14402026/10/06 21:20:00 WARN Failed to register uploaded object key=bsiw6lkzrxcv5csi3h6d948hw8mcj66l.narinfo error="server returned 404: 404 page not found\n"1441=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1442=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1443=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1444=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1445=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1446=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1447=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1448=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1449=== CONT TestService_ReadAuthMiddleware14502026/10/06 21:20:00 INFO Completed upload id=114512026/10/06 21:20:00 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14522026/10/06 21:20:00 INFO Completed upload id=214532026/10/06 21:20:00 INFO Upload complete. (146ms)1454=== NAME TestClientFallsBackToClosures1455 client_pushes_test.go:112: Retrieved narinfo from S3:1456 StorePath: /nix/var/nix/builds/nix-43476-3212982383/TestClientFallsBackToClosures4017277430/001/store/bsiw6lkzrxcv5csi3h6d948hw8mcj66l-shared-dep1457 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1458 Compression: zstd1459 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821460 NarSize: 1361461 References: 1462 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1463 client_pushes_test.go:112: Retrieved narinfo from S3:1464 StorePath: /nix/var/nix/builds/nix-43476-3212982383/TestClientFallsBackToClosures4017277430/001/store/z4p349j74hpxivyz384n981sqjahi3r2-a1465 URL: nar/149b031z1kxk5j9yj5xvfl51w3qa8hn9qi4ixb22kmll0fvdjpwb.nar.zst1466 Compression: zstd1467 NarHash: sha256:149b031z1kxk5j9yj5xvfl51w3qa8hn9qi4ixb22kmll0fvdjpwb1468 NarSize: 2481469 References: /nix/var/nix/builds/nix-43476-3212982383/TestClientFallsBackToClosures4017277430/001/store/bsiw6lkzrxcv5csi3h6d948hw8mcj66l-shared-dep1470 CA: text:sha256:1lx5h4vlh21hqc2a9wqlq7ghzgr1gcaczs7k685skxdwmx5y4x931471 client_pushes_test.go:112: Retrieved narinfo from S3:1472 StorePath: /nix/var/nix/builds/nix-43476-3212982383/TestClientFallsBackToClosures4017277430/001/store/fbzccy5za4zxc3l233299aiicaqw5j2a-b1473 URL: nar/149b031z1kxk5j9yj5xvfl51w3qa8hn9qi4ixb22kmll0fvdjpwb.nar.zst1474 Compression: zstd1475 NarHash: sha256:149b031z1kxk5j9yj5xvfl51w3qa8hn9qi4ixb22kmll0fvdjpwb1476 NarSize: 2481477 References: /nix/var/nix/builds/nix-43476-3212982383/TestClientFallsBackToClosures4017277430/001/store/bsiw6lkzrxcv5csi3h6d948hw8mcj66l-shared-dep1478 CA: text:sha256:1lx5h4vlh21hqc2a9wqlq7ghzgr1gcaczs7k685skxdwmx5y4x9314792026/10/06 21:20:00 INFO lead: released remote=192.0.2.1:12341480--- PASS: TestClientFallsBackToClosures (2.59s)1481=== CONT TestClientMultipleUploads14822026/10/06 21:20:00 INFO lead: acquired remote=192.0.2.1:123414832026/10/06 21:20:00 INFO Received push request method=POST path=/api/pushes14842026/10/06 21:20:00 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14852026/10/06 21:20:00 INFO Uploading zfv27k3a46sl5p00xqidl3922lrygfb3-shared-dep (136B)14862026/10/06 21:20:00 INFO Uploading qby583jnbivqfm3nbxsnqgqczcisv4s4-b (248B)14872026/10/06 21:20:00 WARN Failed to register uploaded object key=nar/129048p7vif32qml1ikb54vh26jwq1i5sxmk61dfq46zzhw1pzhp.nar.zst error="server returned 404: 404 page not found\n"14882026/10/06 21:20:00 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14892026/10/06 21:20:00 WARN Failed to register uploaded object key=qby583jnbivqfm3nbxsnqgqczcisv4s4.ls error="server returned 404: 404 page not found\n"14902026/10/06 21:20:00 WARN Failed to register uploaded object key=hkys2d3qzzfzwc20c3vzjgl17adijm06.ls error="server returned 404: 404 page not found\n"14912026/10/06 21:20:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14922026/10/06 21:20:00 WARN Failed to register uploaded object key=zfv27k3a46sl5p00xqidl3922lrygfb3.ls error="server returned 404: 404 page not found\n"14932026/10/06 21:20:00 INFO Signed narinfos id=1 count=314942026/10/06 21:20:00 INFO Uploading 3 narinfos14952026/10/06 21:20:00 WARN Failed to register uploaded object key=zfv27k3a46sl5p00xqidl3922lrygfb3.narinfo error="server returned 404: 404 page not found\n"14962026/10/06 21:20:00 WARN Failed to register uploaded object key=hkys2d3qzzfzwc20c3vzjgl17adijm06.narinfo error="server returned 404: 404 page not found\n"14972026/10/06 21:20:00 INFO Received complete push request method=POST path=/api/pushes/1/complete14982026/10/06 21:20:00 WARN Failed to register uploaded object key=qby583jnbivqfm3nbxsnqgqczcisv4s4.narinfo error="server returned 404: 404 page not found\n"14992026/10/06 21:20:00 INFO Upload complete. (123ms)1500=== NAME TestClientPushesUseOnePush1501 client_pushes_test.go:97: Retrieved narinfo from S3:1502 StorePath: /nix/var/nix/builds/nix-43476-3212982383/TestClientPushesUseOnePush1687391249/001/store/zfv27k3a46sl5p00xqidl3922lrygfb3-shared-dep1503 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1504 Compression: zstd1505 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821506 NarSize: 1361507 References: 1508 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1509 client_pushes_test.go:97: Retrieved narinfo from S3:1510 StorePath: /nix/var/nix/builds/nix-43476-3212982383/TestClientPushesUseOnePush1687391249/001/store/hkys2d3qzzfzwc20c3vzjgl17adijm06-a1511 URL: nar/129048p7vif32qml1ikb54vh26jwq1i5sxmk61dfq46zzhw1pzhp.nar.zst1512 Compression: zstd1513 NarHash: sha256:129048p7vif32qml1ikb54vh26jwq1i5sxmk61dfq46zzhw1pzhp1514 NarSize: 2481515 References: /nix/var/nix/builds/nix-43476-3212982383/TestClientPushesUseOnePush1687391249/001/store/zfv27k3a46sl5p00xqidl3922lrygfb3-shared-dep1516 CA: text:sha256:1cbbvbb2amg6kg2w45n6v37lv0j4pk9j09ji3ijpp778s67yahzi1517 client_pushes_test.go:97: Retrieved narinfo from S3:1518 StorePath: /nix/var/nix/builds/nix-43476-3212982383/TestClientPushesUseOnePush1687391249/001/store/qby583jnbivqfm3nbxsnqgqczcisv4s4-b1519 URL: nar/129048p7vif32qml1ikb54vh26jwq1i5sxmk61dfq46zzhw1pzhp.nar.zst1520 Compression: zstd1521 NarHash: sha256:129048p7vif32qml1ikb54vh26jwq1i5sxmk61dfq46zzhw1pzhp1522 NarSize: 2481523 References: /nix/var/nix/builds/nix-43476-3212982383/TestClientPushesUseOnePush1687391249/001/store/zfv27k3a46sl5p00xqidl3922lrygfb3-shared-dep1524 CA: text:sha256:1cbbvbb2amg6kg2w45n6v37lv0j4pk9j09ji3ijpp778s67yahzi1525--- PASS: TestService_ReadScope_PublicByDefault (1.71s)1526=== CONT TestClientSharedPathCommittedMidPush1527--- PASS: TestClientPushesUseOnePush (2.31s)1528=== CONT TestClientWithDependencies1529=== RUN TestService_RequireScope_OIDC/builder_may_write1530=== PAUSE TestService_RequireScope_OIDC/builder_may_write1531=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1532=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1533=== RUN TestService_RequireScope_OIDC/ops_may_admin1534=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1535=== RUN TestService_RequireScope_OIDC/ops_may_not_write1536=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1537=== RUN TestService_RequireScope_OIDC/reader_may_not_write1538=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1539=== RUN TestService_RequireScope_OIDC/static_token_may_admin1540=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1541=== RUN TestService_RequireScope_OIDC/static_token_may_write1542=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1543=== RUN TestService_RequireScope_OIDC/reader_may_read1544=== PAUSE TestService_RequireScope_OIDC/reader_may_read1545=== RUN TestService_RequireScope_OIDC/writer_implies_read1546=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1547=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1548=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1549=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1550=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1551=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1552=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1553=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1554=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1555=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1556=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1557=== CONT TestClientErrorHandling1558=== RUN TestClientErrorHandling/InvalidStorePath1559=== PAUSE TestClientErrorHandling/InvalidStorePath1560=== RUN TestClientErrorHandling/InvalidAuthToken1561=== PAUSE TestClientErrorHandling/InvalidAuthToken1562=== RUN TestClientErrorHandling/ServerNotAvailable1563=== PAUSE TestClientErrorHandling/ServerNotAvailable1564=== CONT TestCacheStatsHandler15652026/10/06 21:20:01 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15662026/10/06 21:20:01 WARN mTLS auth: bound subjects configured but subject DN unavailable15672026/10/06 21:20:01 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1568--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (1.02s)1569=== CONT TestClientIntegration1570--- PASS: TestService_ReadAuthMiddleware (1.05s)1571=== CONT TestService_AuthMiddleware_MTLSProxyHeader15722026/10/06 21:20:01 INFO lead: released remote=192.0.2.1:12341573--- PASS: TestLeadElectsOneAndHandsOver (5.39s)1574=== CONT TestClientCADerivations1575=== NAME TestPinProtectsFromGC1576 client_integration_test.go:840: Pin successfully protected closure from garbage collection1577=== NAME TestClientMultipleUploads1578 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-43476-3212982383/TestClientMultipleUploads3999402409/001/store/llzvlsbi4l5zy71qr45pslzb87f9cmwm-test-file-0.txt1579--- PASS: TestPinProtectsFromGC (8.86s)1580=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15812026/10/06 21:20:01 INFO Received uploads request method=POST path=/1582=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15832026/10/06 21:20:01 INFO Received request for more parts method=POST path=/1584=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15852026/10/06 21:20:01 INFO Received complete multipart upload request method=POST path=/1586=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15872026/10/06 21:20:01 INFO Received uploads request method=POST path=/1588--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1589 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1590 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1591 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1592 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1593=== CONT TestPendingClosureWriteTimeout/empty1594=== CONT TestPendingClosureWriteTimeout/670k_objects1595=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1596=== NAME TestClientMultipleUploads1597 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-43476-3212982383/TestClientMultipleUploads3999402409/001/store/nxcnncphazapw995ccb3wwwqlk1a514q-test-file-1.txt1598--- PASS: TestDeleteClosuresRacingPins (4.16s)1599=== CONT TestPendingClosureWriteTimeout/400_objects1600=== CONT TestProxyWriteTimeout/narinfo1601=== CONT TestProxyWriteTimeout/unknown_size1602=== CONT TestProxyWriteTimeout/10_GiB_nar1603=== CONT TestProxyWriteTimeout/1_GiB_nar1604--- PASS: TestProxyWriteTimeout (0.00s)1605 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1606 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1607 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1608 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1609=== CONT TestIsValidUploadKey/narinfo1610=== CONT TestIsValidUploadKey/realisation_plus_in_output1611=== CONT TestIsValidUploadKey/unknown_type1612=== CONT TestIsValidUploadKey/empty_key1613=== CONT TestIsValidUploadKey/absolute1614=== CONT TestIsValidUploadKey/traversal_nar1615=== CONT TestIsValidUploadKey/traversal1616=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1617=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1618=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1619=== CONT TestIsValidUploadKey/index.html1620=== CONT TestIsValidUploadKey/nix-cache-info1621=== CONT TestIsValidUploadKey/build_log_home-manager_file1622=== CONT TestIsValidUploadKey/realisation1623=== CONT TestIsValidUploadKey/build_log_equals1624=== CONT TestIsValidUploadKey/build_log_question_mark1625=== CONT TestIsValidUploadKey/build_log_plus_in_name1626=== CONT TestIsValidUploadKey/nar_plain1627=== CONT TestIsValidUploadKey/build_log1628=== CONT TestIsValidUploadKey/listing1629=== CONT TestIsValidUploadKey/nar_xz1630=== CONT TestIsValidUploadKey/nar_zst1631--- PASS: TestIsValidUploadKey (0.01s)1632 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1633 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1634 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1635 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1636 --- PASS: TestIsValidUploadKey/absolute (0.00s)1637 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1638 --- PASS: TestIsValidUploadKey/traversal (0.00s)1639 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1640 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1641 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1642 --- PASS: TestIsValidUploadKey/index.html (0.00s)1643 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1644 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1645 --- PASS: TestIsValidUploadKey/realisation (0.00s)1646 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1647 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1648 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1649 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1650 --- PASS: TestIsValidUploadKey/build_log (0.00s)1651 --- PASS: TestIsValidUploadKey/listing (0.00s)1652 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1653 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1654=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16552026/10/06 21:20:02 INFO Received uploads request method=POST path=/1656=== NAME TestClientMultipleUploads1657 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-43476-3212982383/TestClientMultipleUploads3999402409/001/store/mr8vispcpvfa5gjg8yzn2x6j0cyhsh3h-test-file-2.txt16582026/10/06 21:20:02 INFO Received push request method=POST path=/api/pushes16592026/10/06 21:20:02 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16602026/10/06 21:20:02 INFO Uploading mr8vispcpvfa5gjg8yzn2x6j0cyhsh3h-test-file-2.txt (160B)16612026/10/06 21:20:02 INFO Uploading llzvlsbi4l5zy71qr45pslzb87f9cmwm-test-file-0.txt (160B)16622026/10/06 21:20:02 INFO Uploading nxcnncphazapw995ccb3wwwqlk1a514q-test-file-1.txt (160B)16632026/10/06 21:20:02 WARN Failed to register uploaded object key=mr8vispcpvfa5gjg8yzn2x6j0cyhsh3h.ls error="server returned 404: 404 page not found\n"16642026/10/06 21:20:02 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"16652026/10/06 21:20:02 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16662026/10/06 21:20:02 WARN Failed to register uploaded object key=nxcnncphazapw995ccb3wwwqlk1a514q.ls error="server returned 404: 404 page not found\n"16672026/10/06 21:20:02 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16682026/10/06 21:20:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16692026/10/06 21:20:02 WARN Failed to register uploaded object key=llzvlsbi4l5zy71qr45pslzb87f9cmwm.ls error="server returned 404: 404 page not found\n"16702026/10/06 21:20:02 INFO Signed narinfos id=1 count=316712026/10/06 21:20:02 INFO Uploading 3 narinfos16722026/10/06 21:20:02 WARN Failed to register uploaded object key=mr8vispcpvfa5gjg8yzn2x6j0cyhsh3h.narinfo error="server returned 404: 404 page not found\n"16732026/10/06 21:20:02 WARN Failed to register uploaded object key=llzvlsbi4l5zy71qr45pslzb87f9cmwm.narinfo error="server returned 404: 404 page not found\n"16742026/10/06 21:20:02 INFO Received complete push request method=POST path=/api/pushes/1/complete16752026/10/06 21:20:02 WARN Failed to register uploaded object key=nxcnncphazapw995ccb3wwwqlk1a514q.narinfo error="server returned 404: 404 page not found\n"16762026/10/06 21:20:02 INFO Upload complete. (122ms)1677 client_integration_test.go:369: Uploaded 3 paths in 157.584125ms1678--- PASS: TestClientMultipleUploads (1.70s)1679=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16802026/10/06 21:20:02 INFO Received request for more parts method=POST path=/16812026/10/06 21:20:02 INFO Received push request method=POST path=/api/pushes1682=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16832026/10/06 21:20:02 INFO Received complete multipart upload request method=POST path=/16842026/10/06 21:20:02 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)1685=== CONT TestIsValidCachePath/narinfo1686=== CONT TestIsValidCachePath/index.html1687=== CONT TestIsValidCachePath/short_hash16882026/10/06 21:20:02 INFO Uploading bm1nbakj51ir230sjl0yc9zxskl5gxy4-top (256B)1689=== CONT TestIsValidCachePath/wrong_extension1690=== CONT TestIsValidCachePath/leading_slash1691=== CONT TestIsValidCachePath/empty1692=== CONT TestIsValidCachePath/random_path1693=== CONT TestIsValidCachePath/invalid_char_u1694=== CONT TestIsValidCachePath/invalid_char_e1695=== CONT TestIsValidCachePath/traversal_in_middle1696=== CONT TestIsValidCachePath/traversal_parent1697=== CONT TestIsValidCachePath/nar_uncompressed1698=== CONT TestIsValidCachePath/nix-cache-info1699=== CONT TestIsValidCachePath/realisation17002026/10/06 21:20:02 INFO Uploading 1fa99zx004bjhjyd8l6z2sx4ph0pm3dy-shared-dep (136B)1701=== CONT TestIsValidCachePath/log1702=== CONT TestIsValidCachePath/nar_xz1703=== CONT TestIsValidCachePath/nar_bz21704=== CONT TestIsValidCachePath/nar_zst1705=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1706=== CONT TestIsValidCachePath/ls1707--- PASS: TestIsValidCachePath (0.00s)1708 --- PASS: TestIsValidCachePath/narinfo (0.00s)1709 --- PASS: TestIsValidCachePath/index.html (0.00s)1710 --- PASS: TestIsValidCachePath/short_hash (0.00s)1711 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1712 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1713 --- PASS: TestIsValidCachePath/empty (0.00s)1714 --- PASS: TestIsValidCachePath/random_path (0.00s)1715 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1716 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1717 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1718 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1719 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1720 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1721 --- PASS: TestIsValidCachePath/realisation (0.00s)1722 --- PASS: TestIsValidCachePath/log (0.00s)1723 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1724 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1725 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1726 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1727 --- PASS: TestIsValidCachePath/ls (0.00s)1728=== CONT TestParseSingleRange/none1729=== CONT TestParseSingleRange/open-ended1730=== CONT TestParseSingleRange/start_far_past_EOF1731=== CONT TestParseSingleRange/start_past_EOF1732=== CONT TestParseSingleRange/single_byte1733=== CONT TestParseSingleRange/suffix_exceeds_size1734=== CONT TestParseSingleRange/suffix1735=== CONT TestParseSingleRange/end_clamped_to_size1736=== CONT TestParseSingleRange/malformed_both_empty1737=== CONT TestParseSingleRange/closed1738=== CONT TestParseSingleRange/malformed_end_before_start1739=== CONT TestParseSingleRange/multi-range_ignored1740=== CONT TestParseSingleRange/malformed_no_dash1741=== CONT TestParseSingleRange/unknown_unit1742--- PASS: TestParseSingleRange (0.00s)1743 --- PASS: TestParseSingleRange/none (0.00s)1744 --- PASS: TestParseSingleRange/open-ended (0.00s)1745 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1746 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1747 --- PASS: TestParseSingleRange/single_byte (0.00s)1748 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1749 --- PASS: TestParseSingleRange/suffix (0.00s)1750 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1751 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1752 --- PASS: TestParseSingleRange/closed (0.00s)1753 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1754 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1755 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1756 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1757=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale17582026/10/06 21:20:02 WARN Failed to register uploaded object key=1fa99zx004bjhjyd8l6z2sx4ph0pm3dy.ls error="server returned 404: 404 page not found\n"17592026/10/06 21:20:02 WARN Failed to register uploaded object key=bm1nbakj51ir230sjl0yc9zxskl5gxy4.ls error="server returned 404: 404 page not found\n"17602026/10/06 21:20:02 WARN Failed to register uploaded object key=nar/0pvhyqwyk1xb2rhxg8p7qyygv3caxwqw28wkzky6ycwj78i7vhmb.nar.zst error="server returned 404: 404 page not found\n"17612026/10/06 21:20:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17622026/10/06 21:20:02 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17632026/10/06 21:20:02 INFO Signed narinfos id=1 count=217642026/10/06 21:20:02 INFO Uploading 2 narinfos1765--- PASS: TestUploadHandlersRejectOversizedBody (0.03s)1766 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.29s)1767 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.03s)1768 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1769=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh17702026/10/06 21:20:02 INFO Received complete push request method=POST path=/api/pushes/1/complete17712026/10/06 21:20:02 WARN Failed to register uploaded object key=bm1nbakj51ir230sjl0yc9zxskl5gxy4.narinfo error="server returned 404: 404 page not found\n"17722026/10/06 21:20:02 WARN Failed to register uploaded object key=1fa99zx004bjhjyd8l6z2sx4ph0pm3dy.narinfo error="server returned 404: 404 page not found\n"17732026/10/06 21:20:02 INFO Upload complete. (139ms)1774=== NAME TestClientSharedPathCommittedMidPush1775 client_integration_test.go:680: Retrieved narinfo from S3:1776 StorePath: /nix/var/nix/builds/nix-43476-3212982383/TestClientSharedPathCommittedMidPush2762691911/001/store/1fa99zx004bjhjyd8l6z2sx4ph0pm3dy-shared-dep1777 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1778 Compression: zstd1779 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821780 NarSize: 1361781 References: 1782 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1783 client_integration_test.go:680: Retrieved narinfo from S3:1784 StorePath: /nix/var/nix/builds/nix-43476-3212982383/TestClientSharedPathCommittedMidPush2762691911/001/store/bm1nbakj51ir230sjl0yc9zxskl5gxy4-top1785 URL: nar/0pvhyqwyk1xb2rhxg8p7qyygv3caxwqw28wkzky6ycwj78i7vhmb.nar.zst1786 Compression: zstd1787 NarHash: sha256:0pvhyqwyk1xb2rhxg8p7qyygv3caxwqw28wkzky6ycwj78i7vhmb1788 NarSize: 2561789 References: /nix/var/nix/builds/nix-43476-3212982383/TestClientSharedPathCommittedMidPush2762691911/001/store/1fa99zx004bjhjyd8l6z2sx4ph0pm3dy-shared-dep1790 CA: text:sha256:0g6zbsf57dgkpsiw2lp9wzi9pbz0akma3q7qvwwa4jqwcdndv77i1791--- PASS: TestClientSharedPathCommittedMidPush (1.66s)1792=== CONT TestServerTLSConfig/no_client_CA1793=== CONT TestServerTLSConfig/not_a_PEM_file1794=== CONT TestServerTLSConfig/missing_CA_file1795--- PASS: TestServerTLSConfig (0.00s)1796 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1797 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1798 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1799=== CONT TestPush_RejectsBadRequests/no_roots18002026/10/06 21:20:02 INFO Received push request method=POST path=/api/pushes1801=== CONT TestPush_RejectsBadRequests/bad_root18022026/10/06 21:20:02 INFO Received push request method=POST path=/api/pushes1803=== CONT TestPush_RejectsBadRequests/root_not_in_objects18042026/10/06 21:20:02 INFO Received push request method=POST path=/api/pushes1805=== CONT TestPush_RejectsBadRequests/no_objects18062026/10/06 21:20:02 INFO Received push request method=POST path=/api/pushes1807=== CONT TestGCEndsOnShutdown/before_the_run1808--- PASS: TestPush_RejectsBadRequests (3.42s)1809 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1810 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1811 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1812 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1813--- PASS: TestCacheStatsHandler (1.38s)1814=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1815=== NAME TestClientWithDependencies1816 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-43476-3212982383/TestClientWithDependencies2825184650/001/store/bx3pgxp7b83bgrvanw3ldlf55b15vlw4-test-script1817 client_integration_test.go:615: Found 1 dependencies (including self)18182026/10/06 21:20:02 INFO Received push request method=POST path=/api/pushes18192026/10/06 21:20:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18202026/10/06 21:20:02 INFO Uploading bx3pgxp7b83bgrvanw3ldlf55b15vlw4-test-script (136B)18212026/10/06 21:20:02 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"18222026/10/06 21:20:02 WARN Failed to register uploaded object key=bx3pgxp7b83bgrvanw3ldlf55b15vlw4.ls error="server returned 404: 404 page not found\n"18232026/10/06 21:20:02 WARN Failed to register uploaded object key=log/v9kd8mvn4m2z7jvpkfycqb10niffmqzz-test-script.drv error="server returned 404: 404 page not found\n"18242026/10/06 21:20:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18252026/10/06 21:20:02 INFO Signed narinfos id=1 count=118262026/10/06 21:20:02 INFO Uploading 1 narinfos18272026/10/06 21:20:02 INFO Received complete push request method=POST path=/api/pushes/1/complete18282026/10/06 21:20:02 WARN Failed to register uploaded object key=bx3pgxp7b83bgrvanw3ldlf55b15vlw4.narinfo error="server returned 404: 404 page not found\n"18292026/10/06 21:20:02 INFO Upload complete. (134ms)1830 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-43476-3212982383/TestClientWithDependencies2825184650/001/store) requires matching store prefix1831--- PASS: TestClientWithDependencies (2.04s)1832=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1833=== NAME TestClientIntegration1834 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-43476-3212982383/TestClientIntegration2248036906/002/store/9zspf4xz51z7dx8944samdz03msl25xd-test-file.txt1835--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (1.30s)1836=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows18372026/10/06 21:20:02 INFO Received push request method=POST path=/api/pushes18382026/10/06 21:20:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18392026/10/06 21:20:02 INFO Uploading 9zspf4xz51z7dx8944samdz03msl25xd-test-file.txt (152B)18402026/10/06 21:20:02 WARN Failed to register uploaded object key=9zspf4xz51z7dx8944samdz03msl25xd.ls error="server returned 404: 404 page not found\n"18412026/10/06 21:20:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18422026/10/06 21:20:02 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"18432026/10/06 21:20:02 INFO Signed narinfos id=1 count=118442026/10/06 21:20:02 INFO Uploading 1 narinfos18452026/10/06 21:20:02 INFO Received complete push request method=POST path=/api/pushes/1/complete18462026/10/06 21:20:02 WARN Failed to register uploaded object key=9zspf4xz51z7dx8944samdz03msl25xd.narinfo error="server returned 404: 404 page not found\n"18472026/10/06 21:20:03 INFO Upload complete. (118ms)18482026/10/06 21:20:03 INFO All 1 paths already cached1849=== NAME TestClientIntegration1850 client_integration_test.go:312: Retrieved narinfo from S3:1851 StorePath: /nix/var/nix/builds/nix-43476-3212982383/TestClientIntegration2248036906/002/store/9zspf4xz51z7dx8944samdz03msl25xd-test-file.txt1852 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1853 Compression: zstd1854 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11855 NarSize: 1521856 References: 1857 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11858 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1859 client_integration_test.go:313: Decompressed .ls content (64 bytes):1860 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1861 client_integration_test.go:316: Testing garbage collection...18622026/10/06 21:20:03 INFO Starting cleanup of old closures method=DELETE path=/api/closures18632026/10/06 21:20:03 INFO Garbage collection started18642026/10/06 21:20:03 INFO Aborted multipart uploads count=0 kept=018652026/10/06 21:20:03 WARN Force mode enabled - objects will be deleted immediately without grace period18662026/10/06 21:20:03 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=018672026/10/06 21:20:03 INFO Vacuumed table table=pending_closures18682026/10/06 21:20:03 INFO Vacuumed table table=pending_objects18692026/10/06 21:20:03 INFO Vacuumed table table=multipart_uploads18702026/10/06 21:20:03 INFO Vacuumed table table=closures18712026/10/06 21:20:03 INFO Vacuumed table table=objects1872=== NAME TestClientCADerivations1873 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-43476-3212982383/TestClientCADerivations2970386703/001/store/p1ia0554wzp380n2fbzwxj0s884xaai5-ca-test18742026/10/06 21:20:03 INFO Received uploads request method=POST path=/api/pending_closures1875 client_ca_test.go:139: Found 1 dependencies (including self)18762026/10/06 21:20:03 INFO Received push request method=POST path=/api/pushes18772026/10/06 21:20:03 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18782026/10/06 21:20:03 INFO Uploading p1ia0554wzp380n2fbzwxj0s884xaai5-ca-test (144B)18792026/10/06 21:20:03 WARN Failed to register uploaded object key=p1ia0554wzp380n2fbzwxj0s884xaai5.ls error="server returned 404: 404 page not found\n"18802026/10/06 21:20:03 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18812026/10/06 21:20:03 WARN Failed to register uploaded object key=log/srbzkhz4qx3jx0zcfz91wiyi0bqhf56s-ca-test.drv error="server returned 404: 404 page not found\n"18822026/10/06 21:20:03 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18832026/10/06 21:20:03 INFO Signed narinfos id=1 count=118842026/10/06 21:20:03 INFO Uploading 1 narinfos18852026/10/06 21:20:03 INFO Received complete push request method=POST path=/api/pushes/1/complete18862026/10/06 21:20:03 WARN Failed to register uploaded object key=p1ia0554wzp380n2fbzwxj0s884xaai5.narinfo error="server returned 404: 404 page not found\n"18872026/10/06 21:20:03 INFO Upload complete. (156ms)1888 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-43476-3212982383/TestClientCADerivations2970386703/001/store/p1ia0554wzp380n2fbzwxj0s884xaai5-ca-test1889 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1890 Compression: zstd1891 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1892 NarSize: 1441893 References: 1894 Deriver: /nix/var/nix/builds/nix-43476-3212982383/TestClientCADerivations2970386703/001/store/srbzkhz4qx3jx0zcfz91wiyi0bqhf56s-ca-test.drv1895 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1896 client_ca_test.go:185: Checking for realisation files in S3...1897 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1898 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1899 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket88?endpoint=http://localhost:52176®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-43476-3212982383/TestClientCADerivations2970386703/001/store'1900 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11901--- PASS: TestClientCADerivations (2.12s)1902=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1903--- PASS: TestConnectWaitsForAPeerMigration (7.76s)1904=== CONT TestResolveDBConnectionString/flag_wins1905=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1906=== CONT TestResolveDBConnectionString/nothing_configured1907=== CONT TestResolveDBConnectionString/missing_file_is_an_error1908=== CONT TestResolveDBConnectionString/file_when_flag_empty1909=== CONT TestCacheConfigHandler/full_config,_no_issuer1910=== CONT TestCacheConfigHandler/no_signing_keys1911=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1912=== CONT TestCacheConfigHandler/no_cache_url_configured1913--- PASS: TestCacheConfigHandler (0.00s)1914 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1915 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1916 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1917 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1918=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1919--- PASS: TestResolveDBConnectionString (0.02s)1920 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1921 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1922 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1923 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1924 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1925=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19262026/10/06 21:20:04 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]1927=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1928=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19292026/10/06 21:20:04 WARN Authentication failed token_preview=eyJhbGciOi..._ZgWGZKKMg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1930=== CONT TestService_RequireScope_OIDC/builder_may_write1931=== CONT TestService_RequireScope_OIDC/reader_may_read1932=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1933=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19342026/10/06 21:20:04 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]1935=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1936=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1937=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1938=== CONT TestService_RequireScope_OIDC/writer_implies_read1939=== CONT TestService_RequireScope_OIDC/reader_may_not_write1940=== CONT TestService_RequireScope_OIDC/static_token_may_write1941=== CONT TestService_RequireScope_OIDC/static_token_may_admin1942=== CONT TestService_RequireScope_OIDC/ops_may_admin1943=== CONT TestService_RequireScope_OIDC/ops_may_not_write1944=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1945=== CONT TestClientErrorHandling/InvalidStorePath1946=== CONT TestClientErrorHandling/ServerNotAvailable1947--- PASS: TestService_AuthMiddleware_OIDC (1.94s)1948 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)1949 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1950 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1951 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1952--- PASS: TestService_RequireScope_OIDC (1.20s)1953 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1954 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1955 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1956 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1957 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1958 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1959 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1960 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1961 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1962 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1963 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1964 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1965 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1966 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)19672026/10/06 21:20:04 INFO Aborted multipart uploads count=0 kept=019682026/10/06 21:20:04 WARN Force mode enabled - objects will be deleted immediately without grace period19692026-10-06 21:20:04.210 UTC [44160] ERROR: canceling statement due to user request19702026-10-06 21:20:04.210 UTC [44160] STATEMENT: -- name: MarkStaleObjects :execrows1971 WITH RECURSIVE ct AS (1972 SELECT timezone('UTC', now()) AS now1973 ),1974 closure_reach AS (1975 -- Start with all closure keys1976 SELECT o.key, o.refs1977 FROM objects o1978 INNER JOIN closures c ON o.key = c.key1979 UNION1980 -- Recursively add all referenced objects1981 SELECT o.key, o.refs1982 FROM objects o1983 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)1984 ),1985 reachable_objects AS (1986 SELECT DISTINCT key FROM closure_reach1987 ),1988 stale_objects AS (1989 SELECT o.key1990 FROM objects AS o, ct1991 WHERE1992 NOT EXISTS (1993 SELECT 11994 FROM reachable_objects ro1995 WHERE ro.key = o.key1996 )1997 AND NOT EXISTS (1998 SELECT 11999 FROM pending_objects AS po2000 WHERE po.key = o.key2001 )2002 AND o.deleted_at IS NULL -- Only mark fresh objects2003 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2004 FOR UPDATE2005 )2006 UPDATE objects2007 SET2008 deleted_at = ct.now,2009 first_deleted_at = COALESCE(first_deleted_at, ct.now)2010 FROM stale_objects, ct2011 WHERE objects.key = stale_objects.key2012 2013=== CONT TestClientErrorHandling/InvalidAuthToken2014--- PASS: TestPendingClosureWriteTimeout (0.01s)2015 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2016 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2017 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2018 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (2.30s)2019--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2020 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (1.81s)2021 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (2.10s)20222026/10/06 21:20:04 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/present20232026/10/06 21:20:04 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=188.623476ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20242026/10/06 21:20:04 INFO Aborted multipart uploads count=0 kept=020252026/10/06 21:20:04 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=379.273765ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20262026/10/06 21:20:04 WARN Force mode enabled - objects will be deleted immediately without grace period20272026/10/06 21:20:04 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:52176/bucket94/?delete=\": context canceled"2028--- PASS: TestGCEndsOnShutdown (0.00s)2029 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (1.78s)2030 --- PASS: TestGCEndsOnShutdown/before_the_run (2.02s)2031 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (1.94s)20322026/10/06 21:20:04 INFO Received uploads request method=POST path=/api/pending_closures20332026/10/06 21:20:04 INFO Aborted multipart uploads count=0 kept=020342026/10/06 21:20:04 WARN Force mode enabled - objects will be deleted immediately without grace period20352026/10/06 21:20:04 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=020362026/10/06 21:20:04 INFO Vacuumed table table=pending_closures20372026/10/06 21:20:04 INFO Vacuumed table table=pending_objects20382026/10/06 21:20:04 INFO Vacuumed table table=multipart_uploads20392026/10/06 21:20:04 INFO Vacuumed table table=closures20402026/10/06 21:20:04 INFO Vacuumed table table=objects20412026/10/06 21:20:05 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02042=== NAME TestClientIntegration2043 client_integration_test.go:323: Objects in database after GC:2044 client_integration_test.go:323: Successfully deleted all objects with GC --force20452026/10/06 21:20:05 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=793.6443ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2046--- PASS: TestClientIntegration (3.75s)20472026/10/06 21:20:05 INFO Received uploads request method=POST path=/api/pending_closures20482026/10/06 21:20:05 INFO Aborted multipart uploads count=0 kept=020492026/10/06 21:20:05 WARN Force mode enabled - objects will be deleted immediately without grace period20502026/10/06 21:20:05 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=020512026/10/06 21:20:05 INFO Vacuumed table table=pending_closures20522026/10/06 21:20:05 INFO Vacuumed table table=pending_objects20532026/10/06 21:20:05 INFO Vacuumed table table=multipart_uploads20542026/10/06 21:20:05 INFO Vacuumed table table=closures20552026/10/06 21:20:05 INFO Vacuumed table table=objects2056--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2057 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (2.13s)2058 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (2.02s)20592026/10/06 21:20:05 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.678667063s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20602026/10/06 21:20:06 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20612026/10/06 21:20:06 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20622026/10/06 21:20:07 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-config20632026/10/06 21:20:07 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=195.533152ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20642026/10/06 21:20:07 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=393.060087ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20652026/10/06 21:20:08 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=753.594667ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20662026/10/06 21:20:09 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.671488594s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20672026/10/06 21:20:10 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"20682026/10/06 21:20:10 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-config20692026/10/06 21:20:10 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=186.31472ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20702026/10/06 21:20:11 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=362.865251ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20712026/10/06 21:20:11 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=818.864185ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20722026/10/06 21:20:12 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.516830284s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20732026/10/06 21:20:13 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_closures20742026/10/06 21:20:13 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=216.202175ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20752026/10/06 21:20:14 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=368.380932ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20762026/10/06 21:20:14 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=822.256547ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20772026/10/06 21:20:15 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.758072965s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2078--- PASS: TestClientErrorHandling (0.00s)2079 --- PASS: TestClientErrorHandling/InvalidStorePath (2.11s)2080 --- PASS: TestClientErrorHandling/InvalidAuthToken (2.06s)2081 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.94s)2082PASS2083{"timestamp":"2026-10-06T21:20:17.086359Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:52218","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(2)"}20842026-10-06 21:20:17.240 UTC [43514] LOG: received smart shutdown request20852026-10-06 21:20:17.240 UTC [43514] LOG: background worker "logical replication launcher" (PID 43524) exited with exit code 120862026-10-06 21:20:17.244 UTC [43519] LOG: shutting down20872026-10-06 21:20:17.244 UTC [43519] LOG: checkpoint starting: shutdown immediate20882026-10-06 21:20:18.546 UTC [43519] LOG: checkpoint complete: wrote 12459 buffers (76.0%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 30 recycled; write=0.686 s, sync=0.569 s, total=1.303 s; sync files=33373, longest=0.001 s, average=0.001 s; distance=491972 kB, estimate=491972 kB; lsn=0/1F7FE1D8, redo lsn=0/1F7FE1D820892026-10-06 21:20:18.554 UTC [43514] LOG: database system is shut down2090Running OIDC tests...2091=== RUN TestAudienceForIssuer2092=== PAUSE TestAudienceForIssuer2093=== RUN TestGlobMatch2094=== PAUSE TestGlobMatch2095=== RUN TestValidateToken_ValidToken2096=== PAUSE TestValidateToken_ValidToken2097=== RUN TestValidateToken_WrongAudience2098=== PAUSE TestValidateToken_WrongAudience2099=== RUN TestValidateToken_Expired2100=== PAUSE TestValidateToken_Expired2101=== RUN TestValidateToken_BoundClaimsMismatch2102=== PAUSE TestValidateToken_BoundClaimsMismatch2103=== RUN TestValidateToken_BoundSubjectMismatch2104=== PAUSE TestValidateToken_BoundSubjectMismatch2105=== RUN TestValidateToken_MultipleProviders2106=== PAUSE TestValidateToken_MultipleProviders2107=== RUN TestValidateToken_NoMatchingProvider2108=== PAUSE TestValidateToken_NoMatchingProvider2109=== RUN TestValidateToken_KubernetesServiceAccount2110=== PAUSE TestValidateToken_KubernetesServiceAccount2111=== RUN TestNewValidator_KubernetesRequiresCA2112=== PAUSE TestNewValidator_KubernetesRequiresCA2113=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2114=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2115=== RUN TestPins_ReservedForMatchingRule2116=== PAUSE TestPins_ReservedForMatchingRule2117=== RUN TestPins_TopLevelShorthand2118=== PAUSE TestPins_TopLevelShorthand2119=== RUN TestPins_ConfigValidation2120=== PAUSE TestPins_ConfigValidation2121=== RUN TestScopes_LegacyProviderDefaultsToWrite2122=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2123=== RUN TestScopes_Rules2124=== PAUSE TestScopes_Rules2125=== RUN TestScopes_ConfigValidation2126=== PAUSE TestScopes_ConfigValidation2127=== CONT TestAudienceForIssuer2128--- PASS: TestAudienceForIssuer (0.00s)2129=== CONT TestValidateToken_NoMatchingProvider2130=== CONT TestScopes_Rules2131=== CONT TestValidateToken_MultipleProviders2132=== CONT TestValidateToken_BoundSubjectMismatch2133=== CONT TestValidateToken_BoundClaimsMismatch2134=== CONT TestValidateToken_Expired2135=== CONT TestValidateToken_WrongAudience2136=== CONT TestValidateToken_ValidToken2137=== CONT TestGlobMatch2138=== RUN TestGlobMatch/foo_foo2139=== CONT TestPins_ReservedForMatchingRule2140=== PAUSE TestGlobMatch/foo_foo2141=== RUN TestGlobMatch/foo_bar2142=== PAUSE TestGlobMatch/foo_bar2143=== RUN TestGlobMatch/*_2144=== PAUSE TestGlobMatch/*_2145=== RUN TestGlobMatch/*_anything2146=== PAUSE TestGlobMatch/*_anything2147=== RUN TestGlobMatch/foo*_foo2148=== PAUSE TestGlobMatch/foo*_foo2149=== RUN TestGlobMatch/foo*_foobar2150=== PAUSE TestGlobMatch/foo*_foobar2151=== RUN TestGlobMatch/foo*_bar2152=== PAUSE TestGlobMatch/foo*_bar2153=== RUN TestGlobMatch/*bar_bar2154=== PAUSE TestGlobMatch/*bar_bar2155=== RUN TestGlobMatch/*bar_foobar2156=== PAUSE TestGlobMatch/*bar_foobar2157=== RUN TestGlobMatch/*bar_foo2158=== PAUSE TestGlobMatch/*bar_foo2159=== RUN TestGlobMatch/foo*bar_foobar2160=== PAUSE TestGlobMatch/foo*bar_foobar2161=== RUN TestGlobMatch/foo*bar_foo123bar2162=== PAUSE TestGlobMatch/foo*bar_foo123bar2163=== RUN TestGlobMatch/foo*bar_foobarbaz2164=== PAUSE TestGlobMatch/foo*bar_foobarbaz2165=== RUN TestGlobMatch/*/*_foo/bar2166=== PAUSE TestGlobMatch/*/*_foo/bar2167=== RUN TestGlobMatch/*/*_foo2168=== PAUSE TestGlobMatch/*/*_foo2169=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2170=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2171=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02172=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02173=== RUN TestGlobMatch/refs/*/main_refs/heads/main2174=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2175=== RUN TestGlobMatch/fo?_foo2176=== PAUSE TestGlobMatch/fo?_foo2177=== RUN TestGlobMatch/fo?_fo2178=== PAUSE TestGlobMatch/fo?_fo2179=== RUN TestGlobMatch/fo?_fooo2180=== PAUSE TestGlobMatch/fo?_fooo2181=== RUN TestGlobMatch/?oo_foo2182=== PAUSE TestGlobMatch/?oo_foo2183=== RUN TestGlobMatch/?oo_boo2184=== PAUSE TestGlobMatch/?oo_boo2185=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2186=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2187=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2188=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2189=== CONT TestScopes_LegacyProviderDefaultsToWrite21902026/10/06 21:20:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52665/oidc2191--- PASS: TestValidateToken_BoundClaimsMismatch (0.02s)2192=== CONT TestPins_ConfigValidation2193--- PASS: TestPins_ConfigValidation (0.00s)2194=== CONT TestPins_TopLevelShorthand21952026/10/06 21:20:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52668/oidc21962026/10/06 21:20:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52670/oidc2197--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.07s)2198=== CONT TestNewValidator_KubernetesRequiresCA21992026/10/06 21:20:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52672/oidc2200--- PASS: TestValidateToken_Expired (0.08s)2201=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2202--- PASS: TestScopes_Rules (0.08s)2203=== CONT TestValidateToken_KubernetesServiceAccount22042026/10/06 21:20:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52675/oidc22052026/10/06 21:20:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52677/oidc2206--- PASS: TestPins_ReservedForMatchingRule (0.11s)2207=== CONT TestScopes_ConfigValidation2208--- PASS: TestValidateToken_WrongAudience (0.11s)2209=== CONT TestGlobMatch/foo_foo2210=== CONT TestGlobMatch/*/*_foo/bar2211=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2212=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2213=== CONT TestGlobMatch/?oo_boo2214=== CONT TestGlobMatch/?oo_foo2215=== CONT TestGlobMatch/fo?_fooo2216=== CONT TestGlobMatch/fo?_fo2217=== CONT TestGlobMatch/fo?_foo2218=== CONT TestGlobMatch/refs/*/main_refs/heads/main2219=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02220=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2221=== CONT TestGlobMatch/*/*_foo2222=== CONT TestGlobMatch/*bar_bar2223=== CONT TestGlobMatch/foo*bar_foobarbaz2224=== CONT TestGlobMatch/foo*bar_foo123bar2225=== CONT TestGlobMatch/foo*bar_foobar2226=== CONT TestGlobMatch/*bar_foo2227=== CONT TestGlobMatch/*bar_foobar2228=== CONT TestGlobMatch/foo*_foo2229=== CONT TestGlobMatch/foo*_bar2230=== CONT TestGlobMatch/foo*_foobar2231=== CONT TestGlobMatch/*_2232=== CONT TestGlobMatch/*_anything2233=== CONT TestGlobMatch/foo_bar2234--- PASS: TestGlobMatch (0.00s)2235 --- PASS: TestGlobMatch/foo_foo (0.00s)2236 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2237 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2238 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2239 --- PASS: TestGlobMatch/?oo_boo (0.00s)2240 --- PASS: TestGlobMatch/?oo_foo (0.00s)2241 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2242 --- PASS: TestGlobMatch/fo?_fo (0.00s)2243 --- PASS: TestGlobMatch/fo?_foo (0.00s)2244 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2245 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2246 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2247 --- PASS: TestGlobMatch/*/*_foo (0.00s)2248 --- PASS: TestGlobMatch/*bar_bar (0.00s)2249 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2250 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2251 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2252 --- PASS: TestGlobMatch/*bar_foo (0.00s)2253 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2254 --- PASS: TestGlobMatch/foo*_foo (0.00s)2255 --- PASS: TestGlobMatch/foo*_bar (0.00s)2256 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2257 --- PASS: TestGlobMatch/*_ (0.00s)2258 --- PASS: TestGlobMatch/*_anything (0.00s)2259 --- PASS: TestGlobMatch/foo_bar (0.00s)2260--- PASS: TestScopes_ConfigValidation (0.00s)22612026/10/06 21:20:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52680/oidc22622026/10/06 21:20:20 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232263--- PASS: TestValidateToken_ValidToken (0.11s)2264--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.04s)22652026/10/06 21:20:20 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:526832266--- PASS: TestValidateToken_KubernetesServiceAccount (0.05s)22672026/10/06 21:20:20 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:52667/oidc2268--- PASS: TestValidateToken_NoMatchingProvider (0.14s)22692026/10/06 21:20:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52689/oidc22702026/10/06 21:20:20 http: TLS handshake error from 127.0.0.1:52688: remote error: tls: bad certificate2271--- PASS: TestNewValidator_KubernetesRequiresCA (0.07s)2272--- PASS: TestPins_TopLevelShorthand (0.12s)22732026/10/06 21:20:20 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:52674/oidc22742026/10/06 21:20:20 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:52692/oidc2275--- PASS: TestValidateToken_MultipleProviders (0.15s)22762026/10/06 21:20:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52695/oidc2277--- PASS: TestValidateToken_BoundSubjectMismatch (0.17s)2278PASS2279Running hook tests...2280=== RUN TestSendPathsEmpty2281=== PAUSE TestSendPathsEmpty2282=== RUN TestQueueEnqueueAndFetch2283=== PAUSE TestQueueEnqueueAndFetch2284=== RUN TestQueueDeduplication2285=== PAUSE TestQueueDeduplication2286=== RUN TestQueueRemove2287=== PAUSE TestQueueRemove2288=== RUN TestQueueFetchBatchLimit2289=== PAUSE TestQueueFetchBatchLimit2290=== RUN TestQueueRetryMovesToBack2291=== PAUSE TestQueueRetryMovesToBack2292=== RUN TestQueueFetchRemoveLifecycle2293=== PAUSE TestQueueFetchRemoveLifecycle2294=== RUN TestQueueConcurrentWriters2295=== PAUSE TestQueueConcurrentWriters2296=== RUN TestQueueRemoveLargeClosure2297=== PAUSE TestQueueRemoveLargeClosure2298=== RUN TestServerClientIntegration2299=== PAUSE TestServerClientIntegration2300=== RUN TestServerQueueError2301=== PAUSE TestServerQueueError2302=== RUN TestGetListenerSocketActivation2303 server_test.go:210: === RUN TestGetListenerSocketActivation2304 --- PASS: TestGetListenerSocketActivation (0.00s)2305 PASS2306 2307--- PASS: TestGetListenerSocketActivation (0.01s)2308=== RUN TestDrainIsolatesPoisonPath2309=== PAUSE TestDrainIsolatesPoisonPath2310=== RUN TestRunNotBlockedByPoisonHead2311=== PAUSE TestRunNotBlockedByPoisonHead2312=== RUN TestDrainGivesUpWhenServerDown2313=== PAUSE TestDrainGivesUpWhenServerDown2314=== RUN TestFailedPathPrunedByLaterClosure2315=== PAUSE TestFailedPathPrunedByLaterClosure2316=== RUN TestWorkerUploadsAndRemoves2317=== PAUSE TestWorkerUploadsAndRemoves2318=== RUN TestWorkerSkipsGCdPaths2319=== PAUSE TestWorkerSkipsGCdPaths2320=== RUN TestWorkerPrunesClosureDeps2321=== PAUSE TestWorkerPrunesClosureDeps2322=== RUN TestDrainTimeout2323=== PAUSE TestDrainTimeout2324=== CONT TestSendPathsEmpty2325--- PASS: TestSendPathsEmpty (0.00s)2326=== CONT TestServerClientIntegration2327=== CONT TestFailedPathPrunedByLaterClosure2328=== CONT TestServerQueueError2329=== CONT TestWorkerUploadsAndRemoves2330=== CONT TestWorkerPrunesClosureDeps2331=== CONT TestWorkerSkipsGCdPaths2332=== CONT TestRunNotBlockedByPoisonHead2333=== CONT TestDrainGivesUpWhenServerDown2334=== CONT TestDrainIsolatesPoisonPath2335=== CONT TestDrainTimeout23362026/10/06 21:20:20 ERROR Failed to queue paths error="permission denied" count=12337--- PASS: TestServerClientIntegration (0.00s)2338=== CONT TestQueueRetryMovesToBack2339--- PASS: TestServerQueueError (0.00s)2340=== CONT TestQueueRemoveLargeClosure23412026/10/06 21:20:20 INFO Upload queue status pending=223422026/10/06 21:20:20 INFO Uploading batch count=223432026/10/06 21:20:20 INFO Upload queue status pending=223442026/10/06 21:20:20 INFO Uploading batch count=123452026/10/06 21:20:20 ERROR Upload failed error="upload failed" count=123462026/10/06 21:20:20 INFO Uploading batch count=423472026/10/06 21:20:20 ERROR Upload failed error="upload failed" count=423482026/10/06 21:20:20 INFO Uploading batch count=123492026/10/06 21:20:20 INFO Uploading batch count=123502026/10/06 21:20:20 INFO Uploading batch count=223512026/10/06 21:20:20 INFO Upload queue status pending=223522026/10/06 21:20:20 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-43476-3212982383/TestWorkerSkipsGCdPaths2163715667/002/nonexistent2353--- PASS: TestQueueRetryMovesToBack (0.01s)2354=== CONT TestQueueConcurrentWriters23552026/10/06 21:20:20 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-43476-3212982383/TestDrainIsolatesPoisonPath4208044431/002/bbb23562026/10/06 21:20:20 INFO Uploading batch count=123572026/10/06 21:20:20 INFO Uploading batch count=123582026/10/06 21:20:20 INFO Upload queue status pending=323592026/10/06 21:20:20 INFO Uploading batch count=123602026/10/06 21:20:20 ERROR Upload failed error="upload failed" count=123612026/10/06 21:20:20 INFO Uploading batch count=223622026/10/06 21:20:20 ERROR Upload failed error="upload failed" count=223632026/10/06 21:20:20 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-43476-3212982383/TestDrainGivesUpWhenServerDown3460785910/002/a23642026/10/06 21:20:20 INFO Uploading batch count=123652026/10/06 21:20:20 ERROR Upload failed error="upload failed" count=123662026/10/06 21:20:20 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-43476-3212982383/TestDrainGivesUpWhenServerDown3460785910/002/b23672026/10/06 21:20:20 INFO Uploading batch count=223682026/10/06 21:20:20 ERROR Upload failed error="upload failed" count=223692026/10/06 21:20:20 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-43476-3212982383/TestDrainGivesUpWhenServerDown3460785910/002/c23702026/10/06 21:20:20 INFO Uploading batch count=123712026/10/06 21:20:20 ERROR Upload failed error="upload failed" count=123722026/10/06 21:20:20 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-43476-3212982383/TestDrainGivesUpWhenServerDown3460785910/002/d23732026/10/06 21:20:20 INFO Uploading batch count=123742026/10/06 21:20:20 ERROR Upload failed error="upload failed" count=12375--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)2376=== CONT TestQueueFetchRemoveLifecycle23772026/10/06 21:20:20 ERROR Drain finished with paths left in queue remaining=123782026/10/06 21:20:20 INFO Uploading batch count=223792026/10/06 21:20:20 ERROR Upload failed error="upload failed" count=223802026/10/06 21:20:20 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-43476-3212982383/TestDrainGivesUpWhenServerDown3460785910/002/e23812026/10/06 21:20:20 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-43476-3212982383/TestDrainGivesUpWhenServerDown3460785910/002/f23822026/10/06 21:20:20 ERROR Drain finished with paths left in queue remaining=102383--- PASS: TestDrainIsolatesPoisonPath (0.01s)2384=== CONT TestQueueRemove2385--- PASS: TestDrainGivesUpWhenServerDown (0.01s)2386=== CONT TestQueueFetchBatchLimit2387--- PASS: TestQueueFetchRemoveLifecycle (0.00s)2388=== CONT TestQueueDeduplication2389--- PASS: TestQueueRemove (0.00s)2390=== CONT TestQueueEnqueueAndFetch2391--- PASS: TestQueueFetchBatchLimit (0.00s)2392--- PASS: TestQueueDeduplication (0.00s)2393--- PASS: TestQueueEnqueueAndFetch (0.00s)2394--- PASS: TestWorkerPrunesClosureDeps (0.03s)2395--- PASS: TestWorkerUploadsAndRemoves (0.03s)2396--- PASS: TestWorkerSkipsGCdPaths (0.03s)2397--- PASS: TestQueueRemoveLargeClosure (0.04s)2398--- PASS: TestQueueConcurrentWriters (0.15s)23992026/10/06 21:20:20 ERROR Upload failed error="context deadline exceeded" count=224002026/10/06 21:20:20 ERROR Drain finished with paths left in queue remaining=42401--- PASS: TestDrainTimeout (0.21s)24022026/10/06 21:20:21 INFO Uploading batch count=124032026/10/06 21:20:21 INFO Uploading batch count=124042026/10/06 21:20:21 INFO Uploading batch count=124052026/10/06 21:20:21 ERROR Upload failed error="upload failed" count=124062026/10/06 21:20:21 INFO Uploading batch count=124072026/10/06 21:20:21 ERROR Upload failed error="upload failed" count=124082026/10/06 21:20:21 INFO Uploading batch count=124092026/10/06 21:20:21 ERROR Upload failed error="upload failed" count=124102026/10/06 21:20:21 INFO Uploading batch count=124112026/10/06 21:20:21 ERROR Upload failed error="upload failed" count=124122026/10/06 21:20:21 ERROR Drain finished with paths left in queue remaining=12413--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2414PASS2415Running signing tests...2416=== RUN TestExternalSigner2417=== PAUSE TestExternalSigner2418=== RUN TestExternalSignerWrongPublicKey2419=== PAUSE TestExternalSignerWrongPublicKey2420=== RUN TestExternalSignerErrors2421=== PAUSE TestExternalSignerErrors2422=== RUN TestExternalSignerRestartsAfterCrash2423=== PAUSE TestExternalSignerRestartsAfterCrash2424=== RUN TestExternalSignerProgramErrorKeepsProcess2425=== PAUSE TestExternalSignerProgramErrorKeepsProcess2426=== RUN TestExternalSignerClose2427=== PAUSE TestExternalSignerClose2428=== RUN TestExternalSignerRejectsInvalidPublicKey2429=== PAUSE TestExternalSignerRejectsInvalidPublicKey2430=== RUN TestExternalSignerCancellation2431=== PAUSE TestExternalSignerCancellation2432=== RUN TestGenerateFingerprint2433=== PAUSE TestGenerateFingerprint2434=== RUN TestParseSigningKey2435=== PAUSE TestParseSigningKey2436=== RUN TestSign2437=== PAUSE TestSign2438=== RUN TestSignBatch2439=== PAUSE TestSignBatch2440=== RUN TestNilKeyPublicKey2441=== PAUSE TestNilKeyPublicKey2442=== RUN TestSignErrors2443=== PAUSE TestSignErrors2444=== CONT TestExternalSigner2445=== CONT TestExternalSignerCancellation2446=== CONT TestExternalSignerWrongPublicKey2447=== CONT TestExternalSignerErrors2448=== CONT TestSignBatch2449=== CONT TestSignErrors2450=== CONT TestNilKeyPublicKey2451--- PASS: TestNilKeyPublicKey (0.00s)2452=== CONT TestExternalSignerRestartsAfterCrash2453=== CONT TestExternalSignerProgramErrorKeepsProcess2454=== CONT TestExternalSignerRejectsInvalidPublicKey2455=== RUN TestExternalSignerRejectsInvalidPublicKey/#002456=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002457=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2458=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2459=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2460=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2461=== CONT TestExternalSignerClose2462=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2463=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2464=== RUN TestExternalSignerErrors/exit_on_request2465=== PAUSE TestExternalSignerErrors/exit_on_request2466=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2467=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2468=== RUN TestExternalSignerErrors/null2469=== CONT TestParseSigningKey2470=== PAUSE TestExternalSignerErrors/null2471=== RUN TestExternalSignerErrors/null_signatures2472=== RUN TestParseSigningKey/valid_32-byte_key2473=== PAUSE TestExternalSignerErrors/null_signatures2474=== PAUSE TestParseSigningKey/valid_32-byte_key2475=== RUN TestExternalSignerErrors/wrong_signatures_shape2476=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2477=== RUN TestExternalSignerErrors/unrequested_key2478=== PAUSE TestExternalSignerErrors/unrequested_key2479=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2480=== RUN TestExternalSignerErrors/missing_signature_name2481=== PAUSE TestExternalSignerErrors/missing_signature_name2482=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2483=== RUN TestExternalSignerErrors/wrong_signature_length2484=== PAUSE TestExternalSignerErrors/wrong_signature_length2485=== RUN TestParseSigningKey/no_colon2486=== RUN TestExternalSignerErrors/program_error2487=== PAUSE TestParseSigningKey/no_colon2488=== RUN TestParseSigningKey/empty_name2489=== PAUSE TestParseSigningKey/empty_name2490=== RUN TestParseSigningKey/invalid_base642491=== PAUSE TestParseSigningKey/invalid_base642492=== RUN TestParseSigningKey/wrong_length2493=== PAUSE TestParseSigningKey/wrong_length2494=== PAUSE TestExternalSignerErrors/program_error2495=== CONT TestSign2496=== RUN TestExternalSignerErrors/wrong_shape2497=== PAUSE TestExternalSignerErrors/wrong_shape2498=== RUN TestExternalSignerErrors/wrong_id2499=== PAUSE TestExternalSignerErrors/wrong_id2500=== RUN TestExternalSignerErrors/too_few_signatures2501=== PAUSE TestExternalSignerErrors/too_few_signatures2502=== RUN TestExternalSignerErrors/invalid_signature_base642503=== PAUSE TestExternalSignerErrors/invalid_signature_base642504=== RUN TestExternalSignerErrors/exit_at_startup2505=== PAUSE TestExternalSignerErrors/exit_at_startup2506=== RUN TestExternalSignerErrors/invalid_JSON2507=== PAUSE TestExternalSignerErrors/invalid_JSON2508=== RUN TestExternalSignerErrors/missing_signatures2509=== PAUSE TestExternalSignerErrors/missing_signatures2510=== RUN TestExternalSignerErrors/wrong_signature_name2511=== PAUSE TestExternalSignerErrors/wrong_signature_name2512=== CONT TestGenerateFingerprint2513=== RUN TestGenerateFingerprint/basic_with_references2514=== PAUSE TestGenerateFingerprint/basic_with_references2515=== RUN TestGenerateFingerprint/no_references2516=== PAUSE TestGenerateFingerprint/no_references2517=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2518=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2519=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2520=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2521=== RUN TestGenerateFingerprint/invalid_nar_hash_length2522=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2523=== RUN TestGenerateFingerprint/invalid_store_path_prefix2524=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2525=== RUN TestGenerateFingerprint/invalid_reference_prefix2526=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2527=== CONT TestExternalSignerRejectsInvalidPublicKey/#002528=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2529=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2530=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2531=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2532--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2533 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2534 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2535 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2536 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2537 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2538=== CONT TestParseSigningKey/valid_32-byte_key2539=== CONT TestParseSigningKey/wrong_length2540=== RUN TestSignErrors/nil_key2541=== CONT TestParseSigningKey/invalid_base642542=== CONT TestParseSigningKey/empty_name2543=== CONT TestParseSigningKey/no_colon2544=== PAUSE TestSignErrors/nil_key2545=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2546--- PASS: TestParseSigningKey (0.00s)2547 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2548 --- PASS: TestParseSigningKey/wrong_length (0.00s)2549 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2550 --- PASS: TestParseSigningKey/empty_name (0.00s)2551 --- PASS: TestParseSigningKey/no_colon (0.00s)2552 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2553=== CONT TestExternalSignerErrors/wrong_shape2554--- PASS: TestSign (0.00s)2555=== RUN TestSignErrors/nil_narinfo2556=== PAUSE TestSignErrors/nil_narinfo2557=== RUN TestSignErrors/invalid_narinfo2558=== PAUSE TestSignErrors/invalid_narinfo2559=== RUN TestSignErrors/canceled2560=== PAUSE TestSignErrors/canceled2561=== CONT TestExternalSignerErrors/exit_on_request2562=== CONT TestExternalSignerErrors/wrong_signature_name2563--- PASS: TestSignBatch (0.01s)2564=== CONT TestExternalSignerErrors/missing_signatures2565--- PASS: TestExternalSignerCancellation (0.24s)2566=== CONT TestExternalSignerErrors/invalid_JSON2567--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.41s)2568=== CONT TestExternalSignerErrors/exit_at_startup2569--- PASS: TestExternalSignerClose (0.59s)2570=== CONT TestExternalSignerErrors/invalid_signature_base642571--- PASS: TestExternalSignerRestartsAfterCrash (0.80s)2572=== CONT TestExternalSignerErrors/too_few_signatures2573/nix/var/nix/builds/nix-43476-3212982383/TestExternalSignerRestartsAfterCrash475766594/001/sign program: line 7: /nix/var/nix/builds/nix-43476-3212982383/TestExternalSignerRestartsAfterCrash475766594/001/sign program.starts: No such file or directory2574--- PASS: TestExternalSigner (0.98s)2575=== CONT TestExternalSignerErrors/wrong_id2576--- PASS: TestExternalSignerWrongPublicKey (1.16s)2577=== CONT TestExternalSignerErrors/null_signatures2578=== CONT TestExternalSignerErrors/unrequested_key2579=== CONT TestExternalSignerErrors/wrong_signatures_shape2580=== CONT TestExternalSignerErrors/program_error2581=== CONT TestExternalSignerErrors/wrong_signature_length2582=== CONT TestExternalSignerErrors/missing_signature_name2583=== CONT TestExternalSignerErrors/null2584=== CONT TestGenerateFingerprint/basic_with_references2585=== CONT TestGenerateFingerprint/invalid_nar_hash_length2586=== CONT TestGenerateFingerprint/invalid_reference_prefix2587=== CONT TestGenerateFingerprint/invalid_store_path_prefix2588=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2589=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2590=== CONT TestGenerateFingerprint/no_references2591--- PASS: TestGenerateFingerprint (0.00s)2592 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2593 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2594 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2595 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2596 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2597 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2598 --- PASS: TestGenerateFingerprint/no_references (0.00s)2599=== CONT TestSignErrors/nil_key2600=== CONT TestSignErrors/canceled2601=== CONT TestSignErrors/invalid_narinfo2602=== CONT TestSignErrors/nil_narinfo2603--- PASS: TestSignErrors (0.01s)2604 --- PASS: TestSignErrors/nil_key (0.00s)2605 --- PASS: TestSignErrors/canceled (0.00s)2606 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2607 --- PASS: TestSignErrors/nil_narinfo (0.00s)2608--- PASS: TestExternalSignerErrors (0.00s)2609 --- PASS: TestExternalSignerErrors/wrong_signature_name (1.34s)2610 --- PASS: TestExternalSignerErrors/wrong_shape (1.53s)2611 --- PASS: TestExternalSignerErrors/exit_on_request (1.72s)2612 --- PASS: TestExternalSignerErrors/missing_signatures (1.91s)2613 --- PASS: TestExternalSignerErrors/invalid_JSON (1.86s)2614 --- PASS: TestExternalSignerErrors/exit_at_startup (1.89s)2615 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (1.89s)2616 --- PASS: TestExternalSignerErrors/too_few_signatures (1.87s)2617 --- PASS: TestExternalSignerErrors/wrong_id (1.88s)2618 --- PASS: TestExternalSignerErrors/null_signatures (1.90s)2619 --- PASS: TestExternalSignerErrors/unrequested_key (1.90s)2620 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (1.89s)2621 --- PASS: TestExternalSignerErrors/program_error (1.90s)2622 --- PASS: TestExternalSignerErrors/wrong_signature_length (1.88s)2623 --- PASS: TestExternalSignerErrors/missing_signature_name (1.88s)2624 --- PASS: TestExternalSignerErrors/null (1.88s)2625PASS2626Running OpenBao signer tests...2627=== RUN TestSign2628=== PAUSE TestSign2629=== RUN TestSignErrors2630=== PAUSE TestSignErrors2631=== RUN TestServe2632=== PAUSE TestServe2633=== RUN TestServeRejectsGarbage2634=== PAUSE TestServeRejectsGarbage2635=== CONT TestSign2636=== CONT TestServe2637=== CONT TestServeRejectsGarbage2638=== CONT TestSignErrors2639=== RUN TestSignErrors/invalid_base642640=== PAUSE TestSignErrors/invalid_base642641=== RUN TestSignErrors/http_error2642=== PAUSE TestSignErrors/http_error2643=== RUN TestSignErrors/invalid_json2644=== PAUSE TestSignErrors/invalid_json2645=== RUN TestSignErrors/no_prefix2646=== PAUSE TestSignErrors/no_prefix2647=== CONT TestSignErrors/invalid_base642648--- PASS: TestServeRejectsGarbage (0.00s)2649=== CONT TestSignErrors/invalid_json2650=== CONT TestSignErrors/no_prefix2651=== CONT TestSignErrors/http_error2652--- PASS: TestServe (0.00s)2653--- PASS: TestSign (0.00s)2654--- PASS: TestSignErrors (0.00s)2655 --- PASS: TestSignErrors/invalid_base64 (0.00s)2656 --- PASS: TestSignErrors/no_prefix (0.00s)2657 --- PASS: TestSignErrors/invalid_json (0.00s)2658 --- PASS: TestSignErrors/http_error (0.00s)2659PASS