niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #393
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestRegisterUploadedObjectReusesConnections6=== PAUSE TestRegisterUploadedObjectReusesConnections7=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica8=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica9=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun10=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun11=== RUN TestCaseHackSuffix12=== PAUSE TestCaseHackSuffix13=== RUN TestFilterOversizedClosures14=== PAUSE TestFilterOversizedClosures15=== RUN TestUploadMultipart_PartsInParallel16=== PAUSE TestUploadMultipart_PartsInParallel17=== RUN TestPartSizeForNAR18=== PAUSE TestPartSizeForNAR19=== RUN TestUploadMultipart_SupersededByPeer20=== PAUSE TestUploadMultipart_SupersededByPeer21=== RUN TestDumpPathCaseHackMatchesNix22--- PASS: TestDumpPathCaseHackMatchesNix (0.04s)23=== RUN TestDumpPathCaseHackCollision24--- PASS: TestDumpPathCaseHackCollision (0.00s)25=== RUN TestDumpPathMatchesNix26=== PAUSE TestDumpPathMatchesNix27=== RUN TestDumpPathSingleFile28=== PAUSE TestDumpPathSingleFile29=== RUN TestDumpPathWriterError30=== PAUSE TestDumpPathWriterError31=== RUN TestEncodeNixBase3232=== PAUSE TestEncodeNixBase3233=== RUN TestEncodeNixBase32WithRealHash34=== PAUSE TestEncodeNixBase32WithRealHash35=== RUN TestConvertHashToNix3236=== PAUSE TestConvertHashToNix3237=== RUN TestGetStorePathHash38=== PAUSE TestGetStorePathHash39=== RUN TestPathInfoHashCompatibility40=== PAUSE TestPathInfoHashCompatibility41=== RUN TestParsePathInfoJSON42=== PAUSE TestParsePathInfoJSON43=== RUN TestParsePathInfoJSONMultiplePaths44=== PAUSE TestParsePathInfoJSONMultiplePaths45=== RUN TestPathInfoCACompatibility46=== PAUSE TestPathInfoCACompatibility47=== RUN TestRateLimiterFeedback48=== PAUSE TestRateLimiterFeedback49=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess50=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess51=== RUN TestResolveStorePath52=== PAUSE TestResolveStorePath53=== RUN TestDoWithRetry_BodyReplayedViaGetBody54=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody55=== RUN TestShellSplit56=== PAUSE TestShellSplit57=== RUN TestShellSplitErrors58=== PAUSE TestShellSplitErrors59=== RUN TestStreamPushReportsEveryPath60=== PAUSE TestStreamPushReportsEveryPath61=== RUN TestStreamPushBatchesUnderLoad62=== PAUSE TestStreamPushBatchesUnderLoad63=== RUN TestStreamPushIsolatesFailures64=== PAUSE TestStreamPushIsolatesFailures65=== RUN TestStreamPushGivesUpOnDeadServer66=== PAUSE TestStreamPushGivesUpOnDeadServer67=== RUN TestStreamPushRequestLine68=== PAUSE TestStreamPushRequestLine69=== RUN TestStreamPushReportsSignatures70=== PAUSE TestStreamPushReportsSignatures71=== RUN TestClientSignaturesByStorePath72=== PAUSE TestClientSignaturesByStorePath73=== RUN TestSetClientTLS74=== PAUSE TestSetClientTLS75=== RUN TestSetClientTLSDoesNotMutateDefaultTransport76=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport77=== RUN TestSetClientTLSErrors78=== PAUSE TestSetClientTLSErrors79=== RUN TestStaticToken80=== PAUSE TestStaticToken81=== RUN TestFileTokenReadsAndCaches82=== PAUSE TestFileTokenReadsAndCaches83=== RUN TestFileTokenMissing84=== PAUSE TestFileTokenMissing85=== RUN TestFileTokenEmpty86=== PAUSE TestFileTokenEmpty87=== RUN TestScriptTokenNoExpiryRerunsEveryCall88=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall89=== RUN TestScriptTokenCachesUntilRefresh90=== PAUSE TestScriptTokenCachesUntilRefresh91=== RUN TestScriptTokenEmptyToken92=== PAUSE TestScriptTokenEmptyToken93=== RUN TestScriptTokenBadJSON94=== PAUSE TestScriptTokenBadJSON95=== RUN TestScriptTokenScriptFails96=== PAUSE TestScriptTokenScriptFails97=== RUN TestScriptTokenEmptyCommand98=== PAUSE TestScriptTokenEmptyCommand99=== CONT TestDoServerRequestAttachesToken100=== CONT TestDoWithRetry_BodyReplayedViaGetBody101=== CONT TestSetClientTLSErrors102=== CONT TestScriptTokenCachesUntilRefresh103=== CONT TestScriptTokenNoExpiryRerunsEveryCall104=== CONT TestScriptTokenEmptyCommand105--- PASS: TestScriptTokenEmptyCommand (0.00s)106=== CONT TestStreamPushGivesUpOnDeadServer107=== CONT TestFileTokenEmpty108=== CONT TestScriptTokenScriptFails109=== CONT TestFileTokenMissing110=== CONT TestScriptTokenBadJSON1112026/10/07 06:22:22 ERROR Upload failed error="connection refused" count=201122026/10/07 06:22:22 ERROR Server seems unavailable, giving up on batch untried=17113=== CONT TestFileTokenReadsAndCaches114=== CONT TestSetClientTLSDoesNotMutateDefaultTransport115=== CONT TestScriptTokenEmptyToken116=== CONT TestStaticToken117=== CONT TestParsePathInfoJSONMultiplePaths118=== CONT TestEncodeNixBase32119=== CONT TestResolveStorePath120=== CONT TestParsePathInfoJSON121=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess122=== CONT TestPathInfoHashCompatibility123=== CONT TestRateLimiterFeedback124=== CONT TestGetStorePathHash125=== CONT TestConvertHashToNix32126=== CONT TestPathInfoCACompatibility127=== CONT TestEncodeNixBase32WithRealHash128--- PASS: TestFileTokenMissing (0.00s)129=== CONT TestStreamPushRequestLine130=== RUN TestParsePathInfoJSON/Nix_format131=== RUN TestEncodeNixBase32/test_string_hash132=== RUN TestConvertHashToNix32/SRI_format_to_Nix32133--- PASS: TestFileTokenEmpty (0.00s)134--- PASS: TestScriptTokenScriptFails (0.00s)135=== RUN TestRateLimiterFeedback/429_enables_limiter136--- PASS: TestEncodeNixBase32WithRealHash (0.00s)1372026/10/07 06:22:22 WARN Rate limiter enabled after throttle name=server-test rate=5138=== CONT TestClientSignaturesByStorePath139=== CONT TestFilterOversizedClosures140=== RUN TestFilterOversizedClosures/no_limit_keeps_everything141=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything142=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped143=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped144=== RUN TestFilterOversizedClosures/all_closures_skipped145=== PAUSE TestFilterOversizedClosures/all_closures_skipped146=== PAUSE TestParsePathInfoJSON/Nix_format147=== RUN TestParsePathInfoJSON/Lix_format148=== PAUSE TestParsePathInfoJSON/Lix_format149--- PASS: TestStaticToken (0.00s)150--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)151=== PAUSE TestRateLimiterFeedback/429_enables_limiter152=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)153=== PAUSE TestEncodeNixBase32/test_string_hash154=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths155=== RUN TestGetStorePathHash/valid_store_path156=== CONT TestSetClientTLS157=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32158=== RUN TestPathInfoCACompatibility/null_ca_field159=== CONT TestStreamPushReportsSignatures160=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun161=== RUN TestParsePathInfoJSON/empty_input162=== CONT TestCaseHackSuffix163--- PASS: TestClientSignaturesByStorePath (0.00s)164--- PASS: TestScriptTokenBadJSON (0.00s)165=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica1662026/10/07 06:22:22 ERROR Upload failed error=boom count=1167=== RUN TestRateLimiterFeedback/503_enables_limiter168=== RUN TestEncodeNixBase32/empty_input169=== PAUSE TestEncodeNixBase32/empty_input170=== PAUSE TestRateLimiterFeedback/503_enables_limiter171=== CONT TestStreamPushIsolatesFailures172=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter173=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths1742026/10/07 06:22:22 ERROR Upload failed error="bad path" count=3175=== CONT TestRegisterUploadedObjectReusesConnections176=== RUN TestConvertHashToNix32/already_Nix32_format177=== PAUSE TestParsePathInfoJSON/empty_input178=== PAUSE TestConvertHashToNix32/already_Nix32_format179--- PASS: TestFileTokenReadsAndCaches (0.00s)180=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter181=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)182=== PAUSE TestPathInfoCACompatibility/null_ca_field183=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths184=== PAUSE TestGetStorePathHash/valid_store_path185=== CONT TestStreamPushReportsEveryPath186=== RUN TestGetStorePathHash/basename_without_hyphen_should_error187=== RUN TestParsePathInfoJSON/whitespace_only188=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error189=== PAUSE TestParsePathInfoJSON/whitespace_only190=== RUN TestParsePathInfoJSON/invalid_JSON191=== PAUSE TestParsePathInfoJSON/invalid_JSON192=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error193=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error194=== CONT TestUploadMultipart_SupersededByPeer195=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter196=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon197=== RUN TestConvertHashToNix32/invalid_format198=== RUN TestPathInfoCACompatibility/old_string_format_-_text199=== RUN TestSetClientTLSErrors/missing_cert_file200=== CONT TestShellSplitErrors201=== CONT TestDumpPathMatchesNix2022026/10/07 06:22:22 INFO Garbage collection started2032026/10/07 06:22:22 ERROR Upload failed error=boom count=12042026/10/07 06:22:22 WARN Rate limiter enabled after throttle name=server-test rate=5205=== PAUSE TestSetClientTLSErrors/missing_cert_file2062026/10/07 06:22:22 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:34487207=== CONT TestStreamPushBatchesUnderLoad208=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error209=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths210--- PASS: TestStreamPushIsolatesFailures (0.00s)211=== RUN TestUploadMultipart_SupersededByPeer/exists212=== PAUSE TestConvertHashToNix32/invalid_format213=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text214=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter215=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon216=== CONT TestShellSplit217=== CONT TestDumpPathWriterError218=== CONT TestPartSizeForNAR219=== CONT TestDumpPathSingleFile220=== CONT TestUploadMultipart_PartsInParallel221=== RUN TestSetClientTLSErrors/missing_key_file222=== CONT TestFilterOversizedClosures/no_limit_keeps_everything223=== CONT TestFilterOversizedClosures/all_closures_skipped224--- PASS: TestResolveStorePath (0.00s)225--- PASS: TestStreamPushReportsEveryPath (0.00s)226=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive2272026/10/07 06:22:22 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=50228=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive229=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped230=== CONT TestParsePathInfoJSON/Nix_format2312026/10/07 06:22:22 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=2000232=== CONT TestEncodeNixBase32/test_string_hash233=== CONT TestEncodeNixBase32/empty_input234--- PASS: TestShellSplitErrors (0.00s)235--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.02s)236=== PAUSE TestSetClientTLSErrors/missing_key_file237=== RUN TestPathInfoCACompatibility/new_structured_format_-_text238--- PASS: TestStreamPushReportsSignatures (0.01s)239--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.02s)240--- PASS: TestScriptTokenEmptyToken (0.02s)241--- PASS: TestDoServerRequestAttachesToken (0.02s)242=== RUN TestSetClientTLSErrors/missing_ca_file243=== RUN TestPartSizeForNAR/zero_stays_at_minimum244--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)245--- PASS: TestShellSplit (0.00s)246=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error247=== CONT TestParsePathInfoJSON/invalid_JSON248=== CONT TestParsePathInfoJSON/Lix_format2492026/10/07 06:22:22 WARN Rate limiter backed off name=server-test rate=52502026/10/07 06:22:22 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:34487251=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths252=== CONT TestParsePathInfoJSON/whitespace_only253=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths254=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter255=== RUN TestSetClientTLS/rejects_connection_without_client_cert2562026/10/07 06:22:22 INFO Garbage collection started257=== CONT TestConvertHashToNix32/SRI_format_to_Nix32258=== CONT TestRateLimiterFeedback/429_enables_limiter259--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.02s)260--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.03s)261=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter262--- PASS: TestParsePathInfoJSONMultiplePaths (0.02s)263 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)264 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)265=== CONT TestParsePathInfoJSON/empty_input266=== CONT TestRateLimiterFeedback/503_enables_limiter267=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI268=== PAUSE TestUploadMultipart_SupersededByPeer/exists269=== CONT TestConvertHashToNix32/invalid_format270=== RUN TestUploadMultipart_SupersededByPeer/missing271=== PAUSE TestUploadMultipart_SupersededByPeer/missing272=== CONT TestGetStorePathHash/valid_store_path273=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error274=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error275=== CONT TestGetStorePathHash/basename_without_hyphen_should_error276=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI277=== CONT TestUploadMultipart_SupersededByPeer/missing278=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512279=== CONT TestConvertHashToNix32/already_Nix32_format280=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text281=== CONT TestUploadMultipart_SupersededByPeer/exists282=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert283=== PAUSE TestSetClientTLSErrors/missing_ca_file284=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA285=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512286=== RUN TestSetClientTLSErrors/invalid_ca_file287=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512288--- PASS: TestEncodeNixBase32 (0.00s)289 --- PASS: TestEncodeNixBase32/empty_input (0.00s)290 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)291=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum292=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA293=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI294=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon295=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)296--- PASS: TestFilterOversizedClosures (0.00s)297 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)298 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)299 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)300=== PAUSE TestSetClientTLSErrors/invalid_ca_file301=== CONT TestSetClientTLSErrors/invalid_ca_file302--- PASS: TestConvertHashToNix32 (0.05s)303 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)304 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)305 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)306=== CONT TestSetClientTLSErrors/missing_ca_file307=== CONT TestSetClientTLSErrors/missing_key_file308=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method309--- PASS: TestGetStorePathHash (0.05s)310 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)311 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)312 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)313 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)3142026/10/07 06:22:22 WARN Rate limiter enabled after throttle name=server-test rate=53152026/10/07 06:22:22 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:38353316=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method317=== CONT TestPathInfoCACompatibility/null_ca_field318--- PASS: TestParsePathInfoJSON (0.04s)319 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)320 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)321 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)322 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)323 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)3242026/10/07 06:22:22 WARN Rate limiter enabled after throttle name=server-test rate=5325=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method3262026/10/07 06:22:22 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:43919327=== CONT TestPathInfoCACompatibility/new_structured_format_-_text3282026/10/07 06:22:22 WARN Rate limiter backed off name=server-test rate=5329=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive330=== CONT TestPathInfoCACompatibility/old_string_format_-_text331--- PASS: TestPathInfoHashCompatibility (0.04s)332 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)333 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.03s)334 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.03s)335 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.03s)3362026/10/07 06:22:22 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=0337--- PASS: TestUploadMultipart_SupersededByPeer (0.03s)338 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.03s)339 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.03s)3402026/10/07 06:22:22 WARN Rate limiter backed off name=server-test rate=5341=== RUN TestPartSizeForNAR/small_stays_at_minimum342=== PAUSE TestPartSizeForNAR/small_stays_at_minimum343=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum344=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum345=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts346=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts347=== RUN TestPartSizeForNAR/1_TiB348=== PAUSE TestPartSizeForNAR/1_TiB349=== RUN TestPartSizeForNAR/5_TiB_S3_max_object350=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object351=== RUN TestPartSizeForNAR/capped_at_5_GiB352=== RUN TestSetClientTLS/preserves_debug_logging_transport353=== CONT TestSetClientTLSErrors/missing_cert_file354--- PASS: TestPathInfoCACompatibility (0.07s)355 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)356 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)357 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)358 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)359 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)3602026/10/07 06:22:22 WARN Garbage collection finished on another replica. Its statistics are not available here361=== PAUSE TestPartSizeForNAR/capped_at_5_GiB362=== CONT TestPartSizeForNAR/1_TiB363=== PAUSE TestSetClientTLS/preserves_debug_logging_transport364=== CONT TestPartSizeForNAR/zero_stays_at_minimum365=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum366=== CONT TestPartSizeForNAR/small_stays_at_minimum367=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts368--- PASS: TestRateLimiterFeedback (0.02s)369 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.03s)370 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.03s)371 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.04s)372 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.04s)373--- PASS: TestCaseHackSuffix (0.07s)374=== CONT TestPartSizeForNAR/capped_at_5_GiB375=== CONT TestSetClientTLS/rejects_connection_without_client_cert376=== CONT TestSetClientTLS/preserves_debug_logging_transport377=== CONT TestPartSizeForNAR/5_TiB_S3_max_object378=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA379--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.08s)380--- PASS: TestSetClientTLSErrors (0.04s)381 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)382 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)383 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)384 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)385--- PASS: TestPartSizeForNAR (0.05s)386 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)387 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)388 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)389 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)390 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)391 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)392 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)3932026/10/07 06:22:22 http: TLS handshake error from 127.0.0.1:49452: remote error: tls: bad certificate394--- PASS: TestSetClientTLS (0.08s)395 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)396 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)397 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)398--- PASS: TestStreamPushRequestLine (0.09s)399--- PASS: TestRegisterUploadedObjectReusesConnections (0.09s)400--- PASS: TestDumpPathSingleFile (0.08s)401--- PASS: TestDumpPathWriterError (0.09s)402--- PASS: TestStreamPushBatchesUnderLoad (0.11s)403--- PASS: TestDumpPathMatchesNix (0.13s)404--- PASS: TestUploadMultipart_PartsInParallel (0.66s)405--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)406PASS407Running server tests...408The files belonging to this database system will be owned by user "nixbld".409This user must also own the server process.410411The database cluster will be initialized with locale "C".412The default database encoding has accordingly been set to "SQL_ASCII".413The default text search configuration will be set to "english".414415Data page checksums are enabled.416417creating directory /build/postgres278249286/data ... ok418creating subdirectories ... ok419selecting dynamic shared memory implementation ... posix420selecting default "max_connections" ... 100421selecting default "shared_buffers" ... 128MB422selecting default time zone ... UTC423creating configuration files ... ok424running bootstrap script ... ok425performing post-bootstrap initialization ... ok426syncing data to disk ... ok427428initdb: warning: enabling "trust" authentication for local connections429initdb: 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.430431Success. You can now start the database server using:432433 pg_ctl -D /build/postgres278249286/data -l logfile start434435/build/postgres278249286:5432 - no response4362026-10-07 06:22:24.471 UTC [129] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit4372026-10-07 06:22:24.471 UTC [129] LOG: listening on Unix socket "/build/postgres278249286/.s.PGSQL.5432"4382026-10-07 06:22:24.476 UTC [136] LOG: database system was shut down at 2026-10-07 06:22:24 UTC4392026-10-07 06:22:24.480 UTC [129] LOG: database system is ready to accept connections440/build/postgres278249286:5432 - accepting connections441=== 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/07 06:22:24 INFO lead: acquired remote=192.0.2.1:12344892026/10/07 06:22:25 INFO lead: released remote=192.0.2.1:12344902026/10/07 06:22:25 INFO lead: acquired remote=192.0.2.1:12344912026/10/07 06:22:26 INFO lead: released remote=192.0.2.1:1234492--- PASS: TestLeadIncumbentWinsAfterRestart (1.85s)493=== RUN TestLeadIncumbentAnnouncesAtOnce494=== PAUSE TestLeadIncumbentAnnouncesAtOnce495=== RUN TestLeadEndsOnShutdown496=== PAUSE TestLeadEndsOnShutdown497=== RUN TestLeadEndsWhenItsConnectionHangs4982026/10/07 06:22:26 INFO lead: acquired remote=192.0.2.1:12344992026-10-07 06:22:28.143 UTC [577] FATAL: terminating connection due to administrator command5002026/10/07 06:22:28 INFO lead: acquired remote=192.0.2.1:12345012026/10/07 06:22:29 WARN lead: lock connection lost error="timeout: context deadline exceeded"5022026/10/07 06:22:29 INFO lead: released remote=192.0.2.1:12345032026/10/07 06:22:29 INFO lead: released remote=192.0.2.1:1234504--- PASS: TestLeadEndsWhenItsConnectionHangs (3.11s)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 TestMetricsCommit574=== PAUSE TestMetricsCommit575=== RUN TestService_NativeMTLS576=== PAUSE TestService_NativeMTLS577=== RUN TestServerTLSConfig578=== PAUSE TestServerTLSConfig579=== RUN TestMultipartCleanup580=== PAUSE TestMultipartCleanup581=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded582=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded583=== RUN TestPendingCleanupUsesOneCutoff584=== PAUSE TestPendingCleanupUsesOneCutoff585=== RUN TestObjectStatsTrigger586=== PAUSE TestObjectStatsTrigger587=== RUN TestObjectStatsLargeCommit588=== PAUSE TestObjectStatsLargeCommit589=== RUN TestOrphanedObjectsGC590=== PAUSE TestOrphanedObjectsGC591=== RUN TestOrphanedObjectsGCStressTest592=== PAUSE TestOrphanedObjectsGCStressTest593=== RUN TestCreatePin_ReservedPins594=== PAUSE TestCreatePin_ReservedPins595=== RUN TestPresentReportsOnlyClosureRoots596=== PAUSE TestPresentReportsOnlyClosureRoots597=== RUN TestPresentRefreshesOnlyStaleClosures598=== PAUSE TestPresentRefreshesOnlyStaleClosures599=== RUN TestPresentNotReportedWhileGCDeletesClosure600=== PAUSE TestPresentNotReportedWhileGCDeletesClosure601=== RUN TestParseSingleRange602=== PAUSE TestParseSingleRange603=== RUN TestProxyHeadersOnlyTrustedOnSocket6042026/10/07 06:22:29 INFO Starting HTTP server address=127.0.0.1:345016052026/10/07 06:22:29 INFO Starting HTTP server address=proxy.sock6062026/10/07 06:22:29 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6072026/10/07 06:22:29 INFO Shutdown signal received, draining in-flight requests timeout=10s608--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.11s)609=== RUN TestIsValidCachePath610=== PAUSE TestIsValidCachePath611=== RUN TestReadProxyNarinfo612=== PAUSE TestReadProxyNarinfo613=== RUN TestReadProxyNarinfoAlreadyDecompressed614=== PAUSE TestReadProxyNarinfoAlreadyDecompressed615=== RUN TestReadProxyContentNegotiation616=== PAUSE TestReadProxyContentNegotiation617=== RUN TestReadProxyNarStreaming618=== PAUSE TestReadProxyNarStreaming619=== RUN TestReadProxy404620=== PAUSE TestReadProxy404621=== RUN TestReadProxyInvalidPath622=== PAUSE TestReadProxyInvalidPath623=== RUN TestReadProxyHead624=== PAUSE TestReadProxyHead625=== RUN TestReadProxyOutlastsServerWriteTimeout626=== PAUSE TestReadProxyOutlastsServerWriteTimeout627=== RUN TestReadProxyConditionalGet628=== PAUSE TestReadProxyConditionalGet629=== RUN TestReadProxyRootRedirectsToIndexHTML630=== PAUSE TestReadProxyRootRedirectsToIndexHTML631=== RUN TestReadProxyDisabled632=== PAUSE TestReadProxyDisabled633=== RUN TestReadRedirectNar634=== PAUSE TestReadRedirectNar635=== RUN TestReadRedirectKeepsNarinfoProxied636=== PAUSE TestReadRedirectKeepsNarinfoProxied637=== RUN TestReadProxyRangeRequest638=== PAUSE TestReadProxyRangeRequest639=== RUN TestReadRedirectUsesPublicS3URL640=== PAUSE TestReadRedirectUsesPublicS3URL641=== RUN TestPush_OverlappingRootsStoreOneRowPerKey642=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey643=== RUN TestPush_CompleteCommitsEveryRoot644=== PAUSE TestPush_CompleteCommitsEveryRoot645=== RUN TestPush_RepeatedRootCommitsOnce646=== PAUSE TestPush_RepeatedRootCommitsOnce647=== RUN TestPush_CompleteWaitsForCleanupOfThePush648=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush649=== RUN TestPush_RootsAreLockedInByteOrder650=== PAUSE TestPush_RootsAreLockedInByteOrder651=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit652=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit653=== RUN TestPush_RejectsBadRequests654=== PAUSE TestPush_RejectsBadRequests655=== RUN TestPush_SignsNarinfosOfItsPendingObjects656=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects657=== RUN TestRedundantMultipartUpload658=== PAUSE TestRedundantMultipartUpload659=== RUN TestCompleteMultipartUpload_ErrorButObjectExists660=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists661=== RUN TestCompletedNarNotReofferedAcrossClosures662=== PAUSE TestCompletedNarNotReofferedAcrossClosures663=== RUN TestPresignedUploadRegisteredBeforeCommit664=== PAUSE TestPresignedUploadRegisteredBeforeCommit665=== RUN TestService_Rustfstest666=== PAUSE TestService_Rustfstest667=== RUN TestParseSize668=== PAUSE TestParseSize669=== RUN TestSkippedUploadsHandler670=== PAUSE TestSkippedUploadsHandler671=== RUN TestSystemdListenerNotActivated672--- PASS: TestSystemdListenerNotActivated (0.00s)673=== RUN TestWatchdogBeatsWhenHealthy674--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)675=== RUN TestWatchdogSkipsWhenUnhealthy6762026/10/07 06:22:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6772026/10/07 06:22:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6782026/10/07 06:22:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6792026/10/07 06:22:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6802026/10/07 06:22:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6812026/10/07 06:22:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6822026/10/07 06:22:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6832026/10/07 06:22:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6842026/10/07 06:22:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6852026/10/07 06:22:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"686--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)687=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle688=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle689=== RUN TestProxyWriteTimeout690=== PAUSE TestProxyWriteTimeout691=== RUN TestPendingClosureWriteTimeout692=== PAUSE TestPendingClosureWriteTimeout693=== RUN TestIsValidUploadKey694=== PAUSE TestIsValidUploadKey695=== RUN TestUploadHandlersRejectInvalidKeys696=== PAUSE TestUploadHandlersRejectInvalidKeys697=== RUN TestUploadHandlersRejectOversizedBody698=== PAUSE TestUploadHandlersRejectOversizedBody699=== RUN TestService_cleanupPendingClosuresHandler700=== PAUSE TestService_cleanupPendingClosuresHandler701=== RUN TestService_createPendingClosureHandler702=== PAUSE TestService_createPendingClosureHandler703=== RUN TestService_verifyS3Integrity704=== PAUSE TestService_verifyS3Integrity705=== RUN TestCompleteMultipartUnregistered706=== PAUSE TestCompleteMultipartUnregistered707=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT708=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT709=== CONT TestService_AuthMiddleware710=== CONT TestCreatePendingClosureRejectsOversizedNAR711=== CONT TestService_cleanupPendingClosuresHandler712=== CONT TestReadProxyRootRedirectsToIndexHTML713=== CONT TestCompleteMultipartUnregistered7142026/10/07 06:22:30 INFO Received uploads request method=POST path=/api/pending_closures715=== CONT TestService_verifyS3Integrity716=== CONT TestService_createPendingClosureHandler717=== CONT TestUploadHandlersRejectOversizedBody718=== CONT TestUploadHandlersRejectInvalidKeys719=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info720=== CONT TestIsValidUploadKey721=== RUN TestIsValidUploadKey/narinfo722=== CONT TestPendingClosureWriteTimeout723=== RUN TestPendingClosureWriteTimeout/empty724=== CONT TestProxyWriteTimeout725=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle726=== CONT TestSkippedUploadsHandler727=== CONT TestParseSize728=== CONT TestService_Rustfstest729=== CONT TestPresignedUploadRegisteredBeforeCommit730=== CONT TestCompletedNarNotReofferedAcrossClosures731=== CONT TestCompleteMultipartUpload_ErrorButObjectExists732=== CONT TestRedundantMultipartUpload733=== CONT TestPush_SignsNarinfosOfItsPendingObjects734=== CONT TestPush_RejectsBadRequests735=== CONT TestPresentReportsOnlyClosureRoots736=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT737--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)738--- PASS: TestParseSize (0.00s)739=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit740=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info741=== PAUSE TestIsValidUploadKey/narinfo742=== PAUSE TestPendingClosureWriteTimeout/empty743=== RUN TestProxyWriteTimeout/narinfo744=== CONT TestPush_RootsAreLockedInByteOrder745=== RUN TestIsValidUploadKey/nar_zst7462026/10/07 06:22:30 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000747=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal748=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal749=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key750=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key751=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key752=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key753=== PAUSE TestProxyWriteTimeout/narinfo754=== RUN TestProxyWriteTimeout/1_GiB_nar755=== PAUSE TestProxyWriteTimeout/1_GiB_nar756=== RUN TestProxyWriteTimeout/10_GiB_nar757=== PAUSE TestProxyWriteTimeout/10_GiB_nar758=== RUN TestProxyWriteTimeout/unknown_size759=== PAUSE TestProxyWriteTimeout/unknown_size760=== RUN TestPendingClosureWriteTimeout/400_objects761=== PAUSE TestPendingClosureWriteTimeout/400_objects762=== RUN TestPendingClosureWriteTimeout/670k_objects763=== PAUSE TestPendingClosureWriteTimeout/670k_objects764=== CONT TestReadProxyConditionalGet765=== CONT TestPush_CompleteWaitsForCleanupOfThePush766=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline767=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline768=== PAUSE TestIsValidUploadKey/nar_zst769=== CONT TestPush_RepeatedRootCommitsOnce770=== RUN TestIsValidUploadKey/nar_xz771=== PAUSE TestIsValidUploadKey/nar_xz772=== RUN TestIsValidUploadKey/nar_plain773=== PAUSE TestIsValidUploadKey/nar_plain774=== RUN TestIsValidUploadKey/listing775=== PAUSE TestIsValidUploadKey/listing776=== RUN TestIsValidUploadKey/build_log777=== PAUSE TestIsValidUploadKey/build_log778=== RUN TestIsValidUploadKey/build_log_home-manager_file779=== PAUSE TestIsValidUploadKey/build_log_home-manager_file780=== RUN TestIsValidUploadKey/build_log_plus_in_name781=== PAUSE TestIsValidUploadKey/build_log_plus_in_name782=== RUN TestIsValidUploadKey/build_log_question_mark783=== PAUSE TestIsValidUploadKey/build_log_question_mark784=== RUN TestIsValidUploadKey/build_log_equals785=== PAUSE TestIsValidUploadKey/build_log_equals786=== RUN TestIsValidUploadKey/realisation787=== PAUSE TestIsValidUploadKey/realisation788=== RUN TestIsValidUploadKey/realisation_plus_in_output789=== PAUSE TestIsValidUploadKey/realisation_plus_in_output790=== RUN TestIsValidUploadKey/nix-cache-info791=== PAUSE TestIsValidUploadKey/nix-cache-info792=== RUN TestIsValidUploadKey/index.html793=== PAUSE TestIsValidUploadKey/index.html794=== RUN TestIsValidUploadKey/narinfo_key,_nar_type795=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type796=== RUN TestIsValidUploadKey/nar_key,_narinfo_type797=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type798=== RUN TestIsValidUploadKey/listing_key,_narinfo_type799=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type800=== RUN TestIsValidUploadKey/traversal801=== PAUSE TestIsValidUploadKey/traversal802=== RUN TestIsValidUploadKey/traversal_nar803=== PAUSE TestIsValidUploadKey/traversal_nar804=== RUN TestIsValidUploadKey/absolute805=== PAUSE TestIsValidUploadKey/absolute806=== RUN TestIsValidUploadKey/empty_key807=== PAUSE TestIsValidUploadKey/empty_key808=== RUN TestIsValidUploadKey/unknown_type809=== PAUSE TestIsValidUploadKey/unknown_type810=== CONT TestReadProxyOutlastsServerWriteTimeout811--- PASS: TestSkippedUploadsHandler (0.09s)812=== CONT TestPush_CompleteCommitsEveryRoot813=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart814=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart815=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts816=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts817=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure818=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure819=== CONT TestReadProxyHead8202026/10/07 06:22:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8212026/10/07 06:22:30 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst822--- PASS: TestCompleteMultipartUnregistered (0.38s)823=== CONT TestPush_OverlappingRootsStoreOneRowPerKey8242026/10/07 06:22:30 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"825--- PASS: TestService_AuthMiddleware (0.40s)826=== CONT TestReadProxyInvalidPath827--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.43s)828=== CONT TestReadProxy4048292026/10/07 06:22:30 INFO Received uploads request method=POST path=/api/pending_closures8302026/10/07 06:22:30 INFO Received uploads request method=POST path=/api/pending_closures8312026/10/07 06:22:30 INFO Received uploads request method=POST path=/api/pending_closures832--- PASS: TestService_Rustfstest (0.45s)833=== CONT TestReadRedirectUsesPublicS3URL8342026/10/07 06:22:30 INFO Received cleanup request method=DELETE path=/api/pending_closures8352026/10/07 06:22:30 INFO Aborted multipart uploads count=0 kept=08362026/10/07 06:22:30 INFO Received uploads request method=POST path=/api/pending_closures8372026/10/07 06:22:30 INFO Received cleanup request method=DELETE path=/api/pending_closures8382026/10/07 06:22:30 INFO Aborted multipart uploads count=1 kept=08392026/10/07 06:22:30 INFO Received uploads request method=POST path=/api/pending_closures8402026/10/07 06:22:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8412026-10-07 06:22:30.636 UTC [648] ERROR: Closure does not exist: id=18422026-10-07 06:22:30.636 UTC [648] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE8432026-10-07 06:22:30.636 UTC [648] STATEMENT: -- name: CommitPendingClosure :one844 SELECT commit_pending_closure($1::bigint)::bigint845 846--- PASS: TestService_cleanupPendingClosuresHandler (0.55s)847=== CONT TestReadProxyNarStreaming8482026/10/07 06:22:30 INFO Received push request method=POST path=/api/pushes8492026/10/07 06:22:30 INFO Received complete push request method=POST path=/api/pushes/1/complete8502026/10/07 06:22:30 INFO Received uploads request method=POST path=/api/pending_closures8512026/10/07 06:22:30 INFO Completed push id=1 objects=4 duration=8.440567ms852--- PASS: TestPush_RepeatedRootCommitsOnce (0.51s)853=== CONT TestReadProxyRangeRequest8542026/10/07 06:22:30 INFO Received uploads request method=POST path=/api/pending_closures8552026/10/07 06:22:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8562026/10/07 06:22:30 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MDFjMmVkYzUtZmE4Yy00M2YwLTk1YTEtZmFkNmFhMjU3YmRkLmM0MWMwYWQ4LWQ4ODktNGJjZC1hNGQ3LWVmMWNmY2UyMjEyNHgxNzkxMzU0MTUwNjkyNDAwNDE18572026/10/07 06:22:30 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MDFjMmVkYzUtZmE4Yy00M2YwLTk1YTEtZmFkNmFhMjU3YmRkLmM0MWMwYWQ4LWQ4ODktNGJjZC1hNGQ3LWVmMWNmY2UyMjEyNHgxNzkxMzU0MTUwNjkyNDAwNDE1 parts=18582026/10/07 06:22:30 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst8592026/10/07 06:22:30 INFO Received uploads request method=POST path=/api/pending_closures860--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.56s)861=== CONT TestReadProxyContentNegotiation862--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.56s)863=== CONT TestReadProxyNarinfoAlreadyDecompressed8642026/10/07 06:22:30 INFO Received push request method=POST path=/api/pushes8652026/10/07 06:22:30 INFO Received push request method=POST path=/api/pushes8662026/10/07 06:22:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8672026-10-07 06:22:30.782 UTC [700] ERROR: could not obtain lock on row in relation "closures"8682026-10-07 06:22:30.782 UTC [700] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT8692026/10/07 06:22:30 INFO Signed narinfos id=1 count=18702026/10/07 06:22:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8712026/10/07 06:22:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8722026-10-07 06:22:30.786 UTC [700] ERROR: could not obtain lock on row in relation "closures"8732026-10-07 06:22:30.786 UTC [700] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT8742026/10/07 06:22:30 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"8752026/10/07 06:22:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8762026-10-07 06:22:30.787 UTC [700] ERROR: could not obtain lock on row in relation "closures"8772026-10-07 06:22:30.787 UTC [700] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT8782026/10/07 06:22:30 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"8792026/10/07 06:22:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8802026/10/07 06:22:30 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=18812026/10/07 06:22:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8822026/10/07 06:22:30 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo8832026-10-07 06:22:30.787 UTC [700] ERROR: could not obtain lock on row in relation "closures"8842026-10-07 06:22:30.787 UTC [700] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT885--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.61s)886=== CONT TestReadRedirectKeepsNarinfoProxied8872026-10-07 06:22:30.788 UTC [700] ERROR: could not obtain lock on row in relation "closures"8882026-10-07 06:22:30.788 UTC [700] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT889--- PASS: TestPush_RootsAreLockedInByteOrder (0.61s)890=== CONT TestReadProxyNarinfo891--- PASS: TestPresentReportsOnlyClosureRoots (0.64s)892=== CONT TestReadRedirectNar8932026/10/07 06:22:30 INFO Received uploads request method=POST path=/api/pending_closures8942026/10/07 06:22:30 INFO Received uploads request method=POST path=/api/pending_closures8952026/10/07 06:22:30 INFO Received uploads request method=POST path=/api/pending_closures896=== RUN TestPush_RejectsBadRequests/no_roots897=== PAUSE TestPush_RejectsBadRequests/no_roots898=== RUN TestPush_RejectsBadRequests/no_objects899=== PAUSE TestPush_RejectsBadRequests/no_objects900=== RUN TestPush_RejectsBadRequests/bad_root901=== PAUSE TestPush_RejectsBadRequests/bad_root902=== RUN TestPush_RejectsBadRequests/root_not_in_objects903=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects904=== CONT TestReadProxyDisabled9052026/10/07 06:22:30 INFO Received uploads request method=POST path=/api/pending_closures906--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.73s)907=== CONT TestIsValidCachePath908=== RUN TestIsValidCachePath/narinfo909=== PAUSE TestIsValidCachePath/narinfo910=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars911=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars912=== RUN TestIsValidCachePath/nar_zst913=== PAUSE TestIsValidCachePath/nar_zst914=== RUN TestIsValidCachePath/nar_xz915=== PAUSE TestIsValidCachePath/nar_xz916=== RUN TestIsValidCachePath/nar_bz2917=== PAUSE TestIsValidCachePath/nar_bz2918=== RUN TestIsValidCachePath/nar_uncompressed919=== PAUSE TestIsValidCachePath/nar_uncompressed920=== RUN TestIsValidCachePath/ls921=== PAUSE TestIsValidCachePath/ls922=== RUN TestIsValidCachePath/log923=== PAUSE TestIsValidCachePath/log924=== RUN TestIsValidCachePath/realisation925=== PAUSE TestIsValidCachePath/realisation926=== RUN TestIsValidCachePath/nix-cache-info927=== PAUSE TestIsValidCachePath/nix-cache-info928=== RUN TestIsValidCachePath/index.html929=== PAUSE TestIsValidCachePath/index.html930=== RUN TestIsValidCachePath/traversal_parent931=== PAUSE TestIsValidCachePath/traversal_parent932=== RUN TestIsValidCachePath/traversal_in_middle933=== PAUSE TestIsValidCachePath/traversal_in_middle934=== RUN TestIsValidCachePath/invalid_char_e935=== PAUSE TestIsValidCachePath/invalid_char_e936=== RUN TestIsValidCachePath/invalid_char_u937=== PAUSE TestIsValidCachePath/invalid_char_u938=== RUN TestIsValidCachePath/random_path939=== PAUSE TestIsValidCachePath/random_path940=== RUN TestIsValidCachePath/empty941=== PAUSE TestIsValidCachePath/empty942=== RUN TestIsValidCachePath/leading_slash943=== PAUSE TestIsValidCachePath/leading_slash944=== RUN TestIsValidCachePath/wrong_extension945=== PAUSE TestIsValidCachePath/wrong_extension946=== RUN TestIsValidCachePath/short_hash947=== PAUSE TestIsValidCachePath/short_hash948=== CONT TestParseSingleRange949=== RUN TestParseSingleRange/none950=== PAUSE TestParseSingleRange/none951=== RUN TestParseSingleRange/unknown_unit952=== PAUSE TestParseSingleRange/unknown_unit953=== RUN TestParseSingleRange/multi-range_ignored954=== PAUSE TestParseSingleRange/multi-range_ignored955=== RUN TestParseSingleRange/malformed_no_dash956=== PAUSE TestParseSingleRange/malformed_no_dash957=== RUN TestParseSingleRange/malformed_both_empty958=== PAUSE TestParseSingleRange/malformed_both_empty959=== RUN TestParseSingleRange/malformed_end_before_start960=== PAUSE TestParseSingleRange/malformed_end_before_start961=== RUN TestParseSingleRange/closed962=== PAUSE TestParseSingleRange/closed963=== RUN TestParseSingleRange/open-ended964=== PAUSE TestParseSingleRange/open-ended965=== RUN TestParseSingleRange/end_clamped_to_size966=== PAUSE TestParseSingleRange/end_clamped_to_size967=== RUN TestParseSingleRange/suffix968=== PAUSE TestParseSingleRange/suffix969=== RUN TestParseSingleRange/suffix_exceeds_size970=== PAUSE TestParseSingleRange/suffix_exceeds_size971=== RUN TestParseSingleRange/single_byte972=== PAUSE TestParseSingleRange/single_byte973=== RUN TestParseSingleRange/start_past_EOF974=== PAUSE TestParseSingleRange/start_past_EOF975=== RUN TestParseSingleRange/start_far_past_EOF976=== PAUSE TestParseSingleRange/start_far_past_EOF977=== CONT TestPresentNotReportedWhileGCDeletesClosure978=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale979=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale980=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh981=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh982=== CONT TestPushDedupSurvivesConcurrentGC9832026/10/07 06:22:30 INFO Received push request method=POST path=/api/pushes9842026/10/07 06:22:30 INFO Received complete push request method=POST path=/api/pushes/1/complete9852026/10/07 06:22:30 INFO Completed push id=1 objects=4 duration=8.286307ms9862026/10/07 06:22:30 INFO Received push request method=POST path=/api/pushes987--- PASS: TestReadProxyHead (0.67s)988=== CONT TestPresentRefreshesOnlyStaleClosures9892026/10/07 06:22:30 INFO Received uploads request method=POST path=/api/pending_closures9902026/10/07 06:22:31 INFO Received push request method=POST path=/api/pushes9912026/10/07 06:22:31 INFO Aborted multipart uploads count=0 kept=09922026/10/07 06:22:31 WARN Force mode enabled - objects will be deleted immediately without grace period9932026/10/07 06:22:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9942026/10/07 06:22:31 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=09952026/10/07 06:22:31 INFO Vacuumed table table=pending_closures9962026/10/07 06:22:31 INFO Vacuumed table table=pending_objects9972026/10/07 06:22:31 INFO Vacuumed table table=multipart_uploads9982026/10/07 06:22:31 INFO Vacuumed table table=closures9992026/10/07 06:22:31 INFO Vacuumed table table=objects10002026/10/07 06:22:31 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MDFjMmVkYzUtZmE4Yy00M2YwLTk1YTEtZmFkNmFhMjU3YmRkLjRjOTNkZDgzLTViOTItNDgzZi1hOGRhLWU1NmFhZDE2NDUzM3gxNzkxMzU0MTUwNTU1MDUxNTM0 parts=1010012026/10/07 06:22:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10022026/10/07 06:22:31 INFO Received complete push request method=POST path=/api/pushes/2/complete10032026/10/07 06:22:31 INFO Completed upload id=1 objects=2 duration=3.282629ms10042026/10/07 06:22:31 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010052026/10/07 06:22:31 INFO Received uploads request method=POST path=/api/pending_closures10062026/10/07 06:22:31 INFO Completed push id=2 objects=4 duration=4.818139ms1007--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.88s)1008=== CONT TestCacheConfigHandlerMaxNarSize1009--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1010=== CONT TestClientSharedPathCommittedMidPush10112026/10/07 06:22:31 INFO Starting cleanup of old closures method=DELETE path=/api/closures10122026/10/07 06:22:31 INFO Received push request method=POST path=/api/pushes10132026/10/07 06:22:31 INFO Aborted multipart uploads count=0 kept=010142026/10/07 06:22:31 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=010152026/10/07 06:22:31 INFO Vacuumed table table=pending_closures10162026/10/07 06:22:31 INFO Vacuumed table table=pending_objects10172026/10/07 06:22:31 INFO Received complete push request method=POST path=/api/pushes/1/complete10182026/10/07 06:22:31 INFO Vacuumed table table=multipart_uploads10192026/10/07 06:22:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10202026/10/07 06:22:31 INFO Completed push id=1 objects=6 duration=9.927546ms10212026/10/07 06:22:31 INFO Vacuumed table table=closures1022--- PASS: TestPush_CompleteCommitsEveryRoot (0.92s)1023=== CONT TestGenerateLandingPage10242026/10/07 06:22:31 INFO Vacuumed table table=objects1025--- PASS: TestGenerateLandingPage (0.00s)1026=== CONT TestService_readinessHandler10272026/10/07 06:22:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1028--- PASS: TestReadProxyConditionalGet (0.93s)1029=== CONT TestGCMetrics10302026/10/07 06:22:31 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001031--- PASS: TestService_createPendingClosureHandler (1.02s)1032=== CONT TestService_healthCheckHandler10332026/10/07 06:22:31 INFO Received push request method=POST path=/api/pushes10342026/10/07 06:22:31 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MDFjMmVkYzUtZmE4Yy00M2YwLTk1YTEtZmFkNmFhMjU3YmRkLmRmMmM0MmI2LTEyZDYtNDNiYi05YTMxLWVlNWUxZTExZmVjY3gxNzkxMzU0MTUwNjQyNjM1ODMz parts=1010352026/10/07 06:22:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10362026/10/07 06:22:31 INFO Completed upload id=1 objects=2 duration=5.656187ms10372026/10/07 06:22:31 INFO Received uploads request method=POST path=/api/pending_closures10382026/10/07 06:22:31 INFO Received uploads request method=POST path=/api/pending_closures10392026/10/07 06:22:31 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10402026/10/07 06:22:31 WARN Found objects in DB but missing from S3, will re-upload count=11041--- PASS: TestService_verifyS3Integrity (1.06s)1042=== CONT TestResolveDBConnectionString1043=== RUN TestResolveDBConnectionString/flag_wins1044=== PAUSE TestResolveDBConnectionString/flag_wins1045=== RUN TestResolveDBConnectionString/file_when_flag_empty1046=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1047=== RUN TestResolveDBConnectionString/missing_file_is_an_error1048=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1049=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1050=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1051=== RUN TestResolveDBConnectionString/nothing_configured1052=== PAUSE TestResolveDBConnectionString/nothing_configured1053=== CONT TestGracefulShutdownDrainsInflight10542026/10/07 06:22:31 INFO Starting HTTP server address=127.0.0.1:3858110552026/10/07 06:22:31 INFO Shutdown signal received, draining in-flight requests timeout=10s1056--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.68s)1057=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1058--- PASS: TestReadProxyInvalidPath (0.67s)1059=== CONT TestGCTaskStore_Fail1060--- PASS: TestGCTaskStore_Fail (0.00s)1061=== CONT TestDeleteClosuresRacingPins1062--- PASS: TestReadProxy404 (0.69s)1063=== CONT TestClientFallsBackToClosures1064--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1065=== CONT TestGCTaskStore_PhaseUpdates1066--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1067=== CONT TestClientPushesUseOnePush1068--- PASS: TestReadRedirectUsesPublicS3URL (0.67s)1069=== CONT TestConnectWaitsForAPeerMigration1070--- PASS: TestReadProxyNarStreaming (0.62s)1071=== CONT TestPinProtectsFromGC1072--- PASS: TestReadProxyRangeRequest (0.61s)1073=== CONT TestGCTaskStore_CompletedAllowsNewTask1074--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1075=== CONT TestGCBugBareHashReferences1076--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.58s)1077=== CONT TestCacheConfigHandler1078=== RUN TestCacheConfigHandler/full_config,_no_issuer1079=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1080=== RUN TestCacheConfigHandler/no_cache_url_configured1081=== PAUSE TestCacheConfigHandler/no_cache_url_configured1082=== RUN TestCacheConfigHandler/no_signing_keys1083=== PAUSE TestCacheConfigHandler/no_signing_keys1084=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1085=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1086=== CONT TestGCTaskStore_GetReturnsLatest1087--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1088=== CONT TestGCAdvisoryLockBlocksConcurrentRun10892026-10-07 06:22:31.337 UTC [725] ERROR: Push does not exist: id=110902026-10-07 06:22:31.337 UTC [725] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE10912026-10-07 06:22:31.337 UTC [725] STATEMENT: SELECT commit_push($1)1092--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (1.16s)1093=== CONT TestClientWithDependencies1094--- PASS: TestReadRedirectKeepsNarinfoProxied (0.60s)1095=== CONT TestLeadEndsOnShutdown10962026/10/07 06:22:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10972026/10/07 06:22:31 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MDFjMmVkYzUtZmE4Yy00M2YwLTk1YTEtZmFkNmFhMjU3YmRkLmU3MWIyYWIxLTA1N2YtNDk2MS1iZDMzLWU2YmRiYmI0MTk1ZXgxNzkxMzU0MTUwODI1OTM0MDg3 parts=1210982026/10/07 06:22:31 INFO Received uploads request method=POST path=/api/pending_closures1099--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.24s)1100=== CONT TestClientMultipleUploads1101--- PASS: TestReadProxyContentNegotiation (0.69s)1102=== CONT TestLeadIncumbentAnnouncesAtOnce1103--- PASS: TestReadRedirectNar (0.62s)1104=== CONT TestGCTaskStore_GetEmpty1105--- PASS: TestGCTaskStore_GetEmpty (0.00s)1106=== CONT TestClientIntegration11072026/10/07 06:22:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1108--- PASS: TestReadProxyDisabled (0.59s)1109=== CONT TestGCTaskStore_ConflictDifferentParams1110--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1111=== CONT TestLeadElectsOneAndHandsOver11122026/10/07 06:22:31 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MDFjMmVkYzUtZmE4Yy00M2YwLTk1YTEtZmFkNmFhMjU3YmRkLjAwZjIwNmQxLWU0OTMtNDhlZS05MjU2LTNkNjk5ZGE2ZjI5NXgxNzkxMzU0MTUwODU0NDE0MjA3 parts=1211132026/10/07 06:22:31 INFO Received uploads request method=POST path=/api/pending_closures11142026/10/07 06:22:31 INFO Received uploads request method=POST path=/api/pending_closures11152026/10/07 06:22:31 INFO Received uploads request method=POST path=/api/pending_closures11162026/10/07 06:22:31 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1117--- PASS: TestReadProxyNarinfo (0.73s)1118=== CONT TestClientErrorHandling1119=== RUN TestClientErrorHandling/InvalidStorePath1120=== PAUSE TestClientErrorHandling/InvalidStorePath1121=== RUN TestClientErrorHandling/InvalidAuthToken1122=== PAUSE TestClientErrorHandling/InvalidAuthToken1123=== RUN TestClientErrorHandling/ServerNotAvailable1124=== PAUSE TestClientErrorHandling/ServerNotAvailable1125=== CONT TestClientCADerivations1126--- PASS: TestPresentRefreshesOnlyStaleClosures (0.57s)1127=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded11282026/10/07 06:22:31 WARN readiness check failed error="closed pool"1129--- PASS: TestService_readinessHandler (0.47s)1130=== CONT TestCacheStatsHandler11312026/10/07 06:22:31 INFO Aborted multipart uploads count=0 kept=011322026/10/07 06:22:31 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=011332026/10/07 06:22:31 INFO Vacuumed table table=pending_closures11342026/10/07 06:22:31 INFO Vacuumed table table=pending_objects11352026/10/07 06:22:31 INFO Vacuumed table table=multipart_uploads11362026/10/07 06:22:31 INFO Vacuumed table table=closures11372026/10/07 06:22:31 INFO Vacuumed table table=objects11382026/10/07 06:22:31 INFO Aborted multipart uploads count=0 kept=011392026/10/07 06:22:31 INFO Aborted multipart uploads count=0 kept=011402026/10/07 06:22:31 WARN Force mode enabled - objects will be deleted immediately without grace period11412026/10/07 06:22:31 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=011422026/10/07 06:22:31 WARN Force mode enabled - objects will be deleted immediately without grace period11432026/10/07 06:22:31 INFO Vacuumed table table=pending_closures11442026/10/07 06:22:31 INFO Vacuumed table table=pending_objects11452026/10/07 06:22:31 INFO Vacuumed table table=multipart_uploads11462026/10/07 06:22:31 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=011472026/10/07 06:22:31 INFO Vacuumed table table=closures11482026/10/07 06:22:31 INFO Vacuumed table table=objects11492026/10/07 06:22:31 INFO Vacuumed table table=pending_closures11502026/10/07 06:22:31 INFO Vacuumed table table=pending_objects11512026/10/07 06:22:31 INFO Vacuumed table table=multipart_uploads11522026/10/07 06:22:31 INFO Vacuumed table table=closures11532026/10/07 06:22:31 INFO Vacuumed table table=objects1154--- PASS: TestPushDedupSurvivesConcurrentGC (0.71s)1155=== CONT TestGCTaskStore_DeduplicateSameParams1156--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1157=== CONT TestCreatePin_ReservedPins1158--- PASS: TestService_healthCheckHandler (0.52s)1159=== CONT TestService_AuthMiddleware_OIDC1160--- PASS: TestGCMetrics (0.52s)1161=== CONT TestGCTaskStore_StartNew1162--- PASS: TestGCTaskStore_StartNew (0.00s)1163=== CONT TestService_ReadScope_PublicByDefault11642026/10/07 06:22:31 INFO Received push request method=POST path=/api/pushes11652026/10/07 06:22:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34351/oidc11662026/10/07 06:22:31 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)11672026/10/07 06:22:31 INFO Uploading 9dynqxnn7zsbf07b0gyn8diywpz0qdi8-top (224B)11682026/10/07 06:22:31 INFO Uploading p5shkrcra4nydbn59xjvrsd0kc44wmn1-shared-dep (136B)11692026/10/07 06:22:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39245/oidc11702026/10/07 06:22:31 WARN Failed to register uploaded object key=nar/02drj6rp0r6rid96ng0nm6kpajl56q2z2dccbkdm0f02zp6nna98.nar.zst error="server returned 404: 404 page not found\n"11712026/10/07 06:22:31 WARN Failed to register uploaded object key=9dynqxnn7zsbf07b0gyn8diywpz0qdi8.ls error="server returned 404: 404 page not found\n"11722026/10/07 06:22:31 WARN Failed to register uploaded object key=p5shkrcra4nydbn59xjvrsd0kc44wmn1.ls error="server returned 404: 404 page not found\n"11732026/10/07 06:22:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11742026/10/07 06:22:31 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11752026/10/07 06:22:31 INFO Signed narinfos id=1 count=211762026/10/07 06:22:31 INFO Uploading 2 narinfos11772026/10/07 06:22:31 WARN Failed to register uploaded object key=p5shkrcra4nydbn59xjvrsd0kc44wmn1.narinfo error="server returned 404: 404 page not found\n"11782026/10/07 06:22:31 INFO Received complete push request method=POST path=/api/pushes/1/complete11792026/10/07 06:22:31 WARN Failed to register uploaded object key=9dynqxnn7zsbf07b0gyn8diywpz0qdi8.narinfo error="server returned 404: 404 page not found\n"11802026/10/07 06:22:31 INFO Completed push id=1 objects=6 duration=7.153158ms11812026/10/07 06:22:31 INFO Upload complete. (68ms)1182=== NAME TestClientSharedPathCommittedMidPush1183 client_integration_test.go:680: Retrieved narinfo from S3:1184 StorePath: /build/TestClientSharedPathCommittedMidPush217991184/001/store/p5shkrcra4nydbn59xjvrsd0kc44wmn1-shared-dep1185 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1186 Compression: zstd1187 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821188 NarSize: 1361189 References: 1190 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1191 client_integration_test.go:680: Retrieved narinfo from S3:1192 StorePath: /build/TestClientSharedPathCommittedMidPush217991184/001/store/9dynqxnn7zsbf07b0gyn8diywpz0qdi8-top1193 URL: nar/02drj6rp0r6rid96ng0nm6kpajl56q2z2dccbkdm0f02zp6nna98.nar.zst1194 Compression: zstd1195 NarHash: sha256:02drj6rp0r6rid96ng0nm6kpajl56q2z2dccbkdm0f02zp6nna981196 NarSize: 2241197 References: /build/TestClientSharedPathCommittedMidPush217991184/001/store/p5shkrcra4nydbn59xjvrsd0kc44wmn1-shared-dep1198 CA: text:sha256:02hzlx8z7sglq4yjadjhzpxvnnji24qw0m2w9jf4ib3sgsra515p1199--- PASS: TestClientSharedPathCommittedMidPush (0.68s)1200=== CONT TestOrphanedObjectsGCStressTest12012026/10/07 06:22:31 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=nixbld database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1202--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.50s)1203=== CONT TestGCEndsOnShutdown1204=== RUN TestGCEndsOnShutdown/before_the_run1205=== PAUSE TestGCEndsOnShutdown/before_the_run1206=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1207=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1208=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1209=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1210=== CONT TestService_RequireScope_OIDC1211=== NAME TestPinProtectsFromGC1212 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC1646185194/001/store/pmwwdh4sc5h3lhxk00iv5z3d0dzgi65m-pinned-file.txt1213 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC1646185194/001/store/47dvs03rxk23adrkz9ir124wwzc5p6ac-unpinned-file.txt12142026/10/07 06:22:31 INFO lead: acquired remote=192.0.2.1:12341215--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.73s)1216=== CONT TestMultipartCleanup12172026/10/07 06:22:31 INFO lead: acquired remote=192.0.2.1:123412182026/10/07 06:22:31 INFO lead: released remote=192.0.2.1:12341219--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.47s)1220=== CONT TestOrphanedObjectsGC12212026/10/07 06:22:31 INFO Received uploads request method=POST path=/api/pending_closures12222026/10/07 06:22:31 INFO Received uploads request method=POST path=/api/pending_closures12232026/10/07 06:22:31 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)12242026/10/07 06:22:31 INFO Uploading kg14v3war45fpfnzjz65lisiq38v0k25-b (216B)12252026/10/07 06:22:31 INFO Uploading 4iixbbdchymlcp09869nfm5kp3xn8k1n-shared-dep (136B)12262026/10/07 06:22:31 WARN Failed to register uploaded object key=gh8nk4ccwawvjiy3piam80z93djrdj14.ls error="server returned 404: 404 page not found\n"12272026/10/07 06:22:31 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12282026/10/07 06:22:31 WARN Failed to register uploaded object key=4iixbbdchymlcp09869nfm5kp3xn8k1n.ls error="server returned 404: 404 page not found\n"12292026/10/07 06:22:31 WARN Failed to register uploaded object key=nar/06j8fac92k1xkj9mfwfajki29vbaq7yc3zxg33mzg31mz4hbg56w.nar.zst error="server returned 404: 404 page not found\n"12302026/10/07 06:22:31 WARN Failed to register uploaded object key=kg14v3war45fpfnzjz65lisiq38v0k25.ls error="server returned 404: 404 page not found\n"12312026/10/07 06:22:31 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12322026/10/07 06:22:31 INFO Signed narinfos id=1 count=212332026/10/07 06:22:31 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12342026/10/07 06:22:31 INFO Signed narinfos id=2 count=212352026/10/07 06:22:31 INFO Uploading 4 narinfos12362026/10/07 06:22:31 INFO Received push request method=POST path=/api/pushes12372026/10/07 06:22:31 INFO Received push request method=POST path=/api/pushes12382026/10/07 06:22:31 WARN Failed to register uploaded object key=4iixbbdchymlcp09869nfm5kp3xn8k1n.narinfo error="server returned 404: 404 page not found\n"12392026/10/07 06:22:31 WARN Failed to register uploaded object key=gh8nk4ccwawvjiy3piam80z93djrdj14.narinfo error="server returned 404: 404 page not found\n"12402026/10/07 06:22:31 WARN Failed to register uploaded object key=4iixbbdchymlcp09869nfm5kp3xn8k1n.narinfo error="server returned 404: 404 page not found\n"12412026/10/07 06:22:31 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12422026/10/07 06:22:31 WARN Failed to register uploaded object key=kg14v3war45fpfnzjz65lisiq38v0k25.narinfo error="server returned 404: 404 page not found\n"1243=== NAME TestClientWithDependencies1244 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies827435382/001/store/sw24ibg19d9sv5md6vk1xhcvzzxw0ai3-test-script12452026/10/07 06:22:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39731/oidc12462026/10/07 06:22:31 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12472026/10/07 06:22:31 INFO Uploading pmwwdh4sc5h3lhxk00iv5z3d0dzgi65m-pinned-file.txt (128B)12482026/10/07 06:22:31 INFO Completed upload id=2 objects=6 duration=16.024404ms12492026/10/07 06:22:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12502026/10/07 06:22:31 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)12512026/10/07 06:22:31 INFO Uploading h29i75j6i4q653fvxv0m9wwlq23vharm-shared-dep (136B)12522026/10/07 06:22:31 INFO Uploading fcjxbw4dd9hb23cgsbv2mgj2sck6anww-a (208B)12532026/10/07 06:22:31 INFO Completed upload id=1 objects=6 duration=2.931589ms12542026/10/07 06:22:31 INFO Upload complete. (91ms)12552026/10/07 06:22:31 WARN Failed to register uploaded object key=pmwwdh4sc5h3lhxk00iv5z3d0dzgi65m.ls error="server returned 404: 404 page not found\n"12562026/10/07 06:22:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12572026/10/07 06:22:31 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"1258=== NAME TestClientMultipleUploads12592026/10/07 06:22:31 INFO Signed narinfos id=1 count=11260 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads1705878311/001/store/c41rplg5vdb3xz9wm5kj18p2k2dckrw5-test-file-0.txt12612026/10/07 06:22:31 INFO Uploading 1 narinfos1262=== NAME TestClientFallsBackToClosures1263 client_pushes_test.go:112: Retrieved narinfo from S3:1264 StorePath: /build/TestClientFallsBackToClosures1340903592/001/store/4iixbbdchymlcp09869nfm5kp3xn8k1n-shared-dep1265 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1266 Compression: zstd1267 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821268 NarSize: 1361269 References: 1270 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n12712026/10/07 06:22:31 WARN Failed to register uploaded object key=cknnr495mzw0j11g47iywviwwrp0fwb7.ls error="server returned 404: 404 page not found\n"12722026/10/07 06:22:31 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12732026/10/07 06:22:31 WARN Failed to register uploaded object key=h29i75j6i4q653fvxv0m9wwlq23vharm.ls error="server returned 404: 404 page not found\n"12742026/10/07 06:22:31 WARN Failed to register uploaded object key=fcjxbw4dd9hb23cgsbv2mgj2sck6anww.ls error="server returned 404: 404 page not found\n"12752026/10/07 06:22:31 WARN Failed to register uploaded object key=nar/1gdcvbm53lkfhj4wbh1va3giddbdp0vzhkbk27pn8q9asp5mpsbx.nar.zst error="server returned 404: 404 page not found\n"12762026/10/07 06:22:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12772026/10/07 06:22:31 INFO Signed narinfos id=1 count=312782026/10/07 06:22:31 INFO Uploading 3 narinfos1279 client_pushes_test.go:112: Retrieved narinfo from S3:1280 StorePath: /build/TestClientFallsBackToClosures1340903592/001/store/gh8nk4ccwawvjiy3piam80z93djrdj14-a1281 URL: nar/06j8fac92k1xkj9mfwfajki29vbaq7yc3zxg33mzg31mz4hbg56w.nar.zst12822026/10/07 06:22:31 INFO Received complete push request method=POST path=/api/pushes/1/complete1283 Compression: zstd1284 NarHash: sha256:06j8fac92k1xkj9mfwfajki29vbaq7yc3zxg33mzg31mz4hbg56w12852026/10/07 06:22:31 WARN Failed to register uploaded object key=pmwwdh4sc5h3lhxk00iv5z3d0dzgi65m.narinfo error="server returned 404: 404 page not found\n"1286 NarSize: 2161287 References: /build/TestClientFallsBackToClosures1340903592/001/store/4iixbbdchymlcp09869nfm5kp3xn8k1n-shared-dep1288 CA: text:sha256:1kh15vcyh66p4b217kj0cjfnqd7cb2xmp76ms8ifz3dnslq8cny512892026/10/07 06:22:31 WARN Failed to register uploaded object key=cknnr495mzw0j11g47iywviwwrp0fwb7.narinfo error="server returned 404: 404 page not found\n"1290 client_pushes_test.go:112: Retrieved narinfo from S3:1291 StorePath: /build/TestClientFallsBackToClosures1340903592/001/store/kg14v3war45fpfnzjz65lisiq38v0k25-b1292 URL: nar/06j8fac92k1xkj9mfwfajki29vbaq7yc3zxg33mzg31mz4hbg56w.nar.zst1293 Compression: zstd1294 NarHash: sha256:06j8fac92k1xkj9mfwfajki29vbaq7yc3zxg33mzg31mz4hbg56w1295 NarSize: 2161296 References: /build/TestClientFallsBackToClosures1340903592/001/store/4iixbbdchymlcp09869nfm5kp3xn8k1n-shared-dep1297 CA: text:sha256:1kh15vcyh66p4b217kj0cjfnqd7cb2xmp76ms8ifz3dnslq8cny512982026/10/07 06:22:31 WARN Failed to register uploaded object key=fcjxbw4dd9hb23cgsbv2mgj2sck6anww.narinfo error="server returned 404: 404 page not found\n"1299=== NAME TestClientWithDependencies1300 client_integration_test.go:615: Found 1 dependencies (including self)13012026/10/07 06:22:31 INFO Received complete push request method=POST path=/api/pushes/1/complete13022026/10/07 06:22:31 WARN Failed to register uploaded object key=h29i75j6i4q653fvxv0m9wwlq23vharm.narinfo error="server returned 404: 404 page not found\n"13032026/10/07 06:22:31 INFO Completed push id=1 objects=3 duration=10.595106ms13042026/10/07 06:22:31 INFO Upload complete. (84ms)1305--- PASS: TestClientFallsBackToClosures (0.76s)13062026/10/07 06:22:31 INFO Completed push id=1 objects=8 duration=5.610328ms1307=== CONT TestFailedS3DeleteKeepsTombstone13082026/10/07 06:22:31 INFO Upload complete. (82ms)1309=== NAME TestClientPushesUseOnePush1310 client_pushes_test.go:97: Retrieved narinfo from S3:1311 StorePath: /build/TestClientPushesUseOnePush307416830/001/store/h29i75j6i4q653fvxv0m9wwlq23vharm-shared-dep1312 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1313 Compression: zstd1314 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821315 NarSize: 1361316 References: 1317 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1318 client_pushes_test.go:97: Retrieved narinfo from S3:1319 StorePath: /build/TestClientPushesUseOnePush307416830/001/store/fcjxbw4dd9hb23cgsbv2mgj2sck6anww-a1320 URL: nar/1gdcvbm53lkfhj4wbh1va3giddbdp0vzhkbk27pn8q9asp5mpsbx.nar.zst1321 Compression: zstd1322 NarHash: sha256:1gdcvbm53lkfhj4wbh1va3giddbdp0vzhkbk27pn8q9asp5mpsbx1323 NarSize: 2081324 References: /build/TestClientPushesUseOnePush307416830/001/store/h29i75j6i4q653fvxv0m9wwlq23vharm-shared-dep1325 CA: text:sha256:0hywpxmrc1lf75hc59qxjakphraak6fly64kfn3rryl8c34z4iab1326 client_pushes_test.go:97: Retrieved narinfo from S3:1327 StorePath: /build/TestClientPushesUseOnePush307416830/001/store/cknnr495mzw0j11g47iywviwwrp0fwb7-b1328 URL: nar/1gdcvbm53lkfhj4wbh1va3giddbdp0vzhkbk27pn8q9asp5mpsbx.nar.zst1329 Compression: zstd1330 NarHash: sha256:1gdcvbm53lkfhj4wbh1va3giddbdp0vzhkbk27pn8q9asp5mpsbx1331 NarSize: 2081332 References: /build/TestClientPushesUseOnePush307416830/001/store/h29i75j6i4q653fvxv0m9wwlq23vharm-shared-dep1333 CA: text:sha256:0hywpxmrc1lf75hc59qxjakphraak6fly64kfn3rryl8c34z4iab13342026/10/07 06:22:31 INFO lead: acquired remote=192.0.2.1:12341335=== NAME TestClientIntegration1336 client_integration_test.go:286: Created store path: /build/TestClientIntegration4132396409/002/store/v5nm2aipl0v04z25n5rgyvr8b4d73zpd-test-file.txt1337--- PASS: TestClientPushesUseOnePush (0.76s)1338=== CONT TestServerTLSConfig1339=== RUN TestServerTLSConfig/no_client_CA1340=== PAUSE TestServerTLSConfig/no_client_CA1341=== RUN TestServerTLSConfig/missing_CA_file1342=== PAUSE TestServerTLSConfig/missing_CA_file1343=== RUN TestServerTLSConfig/not_a_PEM_file1344=== PAUSE TestServerTLSConfig/not_a_PEM_file1345=== CONT TestObjectStatsLargeCommit1346=== NAME TestClientMultipleUploads1347 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads1705878311/001/store/s9sz2wrvs16cgllgixybg58wn7xa538n-test-file-1.txt13482026/10/07 06:22:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1349 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads1705878311/001/store/fa204ci9xj96vbdcmwr2cs9sy2yhcip4-test-file-2.txt1350--- PASS: TestGCBugBareHashReferences (0.72s)1351=== CONT TestObjectStatsTrigger13522026/10/07 06:22:32 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MDFjMmVkYzUtZmE4Yy00M2YwLTk1YTEtZmFkNmFhMjU3YmRkLmVhNmU0MmE5LWM4NGQtNDU0OC1hMGFjLThjZWI2MGFlNzhkMXgxNzkxMzU0MTUxNDkyMzQzNTA2 error="Get \"http://127.0.0.1:1/bucket18/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"13532026/10/07 06:22:32 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MDFjMmVkYzUtZmE4Yy00M2YwLTk1YTEtZmFkNmFhMjU3YmRkLmQ2NDA0MTM4LTgxODktNGRhYS04ZTA3LTg5OTQ3MTQ5NzlmNXgxNzkxMzU0MTUxNDgzODg4MzU5 parts=1213542026/10/07 06:22:32 INFO Received cleanup request method=DELETE path=/api/pending_closures13552026/10/07 06:22:32 INFO Aborted multipart uploads count=1 kept=013562026/10/07 06:22:32 INFO Received uploads request method=POST path=/api/pending_closures13572026/10/07 06:22:32 INFO Received push request method=POST path=/api/pushes13582026/10/07 06:22:32 INFO Received push request method=POST path=/api/pushes13592026/10/07 06:22:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13602026/10/07 06:22:32 INFO Uploading 47dvs03rxk23adrkz9ir124wwzc5p6ac-unpinned-file.txt (128B)13612026/10/07 06:22:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)1362--- PASS: TestRedundantMultipartUpload (1.87s)13632026/10/07 06:22:32 INFO Uploading sw24ibg19d9sv5md6vk1xhcvzzxw0ai3-test-script (136B)1364=== CONT TestService_NativeMTLS13652026/10/07 06:22:32 INFO Received push request method=POST path=/api/pushes13662026/10/07 06:22:32 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"13672026/10/07 06:22:32 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13682026/10/07 06:22:32 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"13692026/10/07 06:22:32 INFO Signed narinfos id=2 count=113702026/10/07 06:22:32 WARN Failed to register uploaded object key=47dvs03rxk23adrkz9ir124wwzc5p6ac.ls error="server returned 404: 404 page not found\n"13712026/10/07 06:22:32 WARN Failed to register uploaded object key=sw24ibg19d9sv5md6vk1xhcvzzxw0ai3.ls error="server returned 404: 404 page not found\n"13722026/10/07 06:22:32 INFO Uploading 1 narinfos13732026/10/07 06:22:32 WARN Failed to register uploaded object key=log/x87v11mdff6v2lvf4p6n85f81ypip1kz-test-script.drv error="server returned 404: 404 page not found\n"13742026/10/07 06:22:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13752026/10/07 06:22:32 INFO Signed narinfos id=1 count=113762026/10/07 06:22:32 INFO Uploading 1 narinfos13772026/10/07 06:22:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13782026/10/07 06:22:32 INFO Uploading v5nm2aipl0v04z25n5rgyvr8b4d73zpd-test-file.txt (152B)13792026/10/07 06:22:32 INFO Received complete push request method=POST path=/api/pushes/2/complete13802026/10/07 06:22:32 WARN Failed to register uploaded object key=47dvs03rxk23adrkz9ir124wwzc5p6ac.narinfo error="server returned 404: 404 page not found\n"13812026/10/07 06:22:32 INFO Received complete push request method=POST path=/api/pushes/1/complete13822026/10/07 06:22:32 WARN Failed to register uploaded object key=sw24ibg19d9sv5md6vk1xhcvzzxw0ai3.narinfo error="server returned 404: 404 page not found\n"13832026/10/07 06:22:32 WARN Failed to register uploaded object key=v5nm2aipl0v04z25n5rgyvr8b4d73zpd.ls error="server returned 404: 404 page not found\n"13842026/10/07 06:22:32 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"13852026/10/07 06:22:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13862026/10/07 06:22:32 INFO Signed narinfos id=1 count=113872026/10/07 06:22:32 INFO Uploading 1 narinfos13882026/10/07 06:22:32 INFO Completed push id=2 objects=3 duration=3.131059ms1389--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.54s)13902026/10/07 06:22:32 INFO Upload complete. (59ms)1391=== CONT TestPendingCleanupUsesOneCutoff13922026/10/07 06:22:32 INFO Completed push id=1 objects=4 duration=6.446148ms13932026/10/07 06:22:32 INFO Upload complete. (68ms)13942026/10/07 06:22:32 INFO Received complete push request method=POST path=/api/pushes/1/complete13952026/10/07 06:22:32 WARN Failed to register uploaded object key=v5nm2aipl0v04z25n5rgyvr8b4d73zpd.narinfo error="server returned 404: 404 page not found\n"1396=== NAME TestClientWithDependencies1397 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies827435382/001/store) requires matching store prefix13982026/10/07 06:22:32 INFO Completed push id=1 objects=3 duration=5.475538ms13992026/10/07 06:22:32 INFO Upload complete. (55ms)1400--- PASS: TestClientWithDependencies (0.74s)1401=== CONT TestMetricsCommit1402--- PASS: TestCacheStatsHandler (0.51s)1403=== CONT TestPushWaitsForSweepHoldingRow1404--- PASS: TestService_ReadScope_PublicByDefault (0.46s)1405=== CONT TestMetricsInventory14062026/10/07 06:22:32 INFO Received push request method=POST path=/api/pushes14072026/10/07 06:22:32 INFO Starting cleanup of old closures method=DELETE path=/api/closures14082026/10/07 06:22:32 INFO Garbage collection started1409=== NAME TestClientCADerivations1410 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations4254505712/001/store/fva8m8yyfp6yppx935byckk0g17a9i66-ca-test14112026/10/07 06:22:32 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)14122026/10/07 06:22:32 INFO Uploading s9sz2wrvs16cgllgixybg58wn7xa538n-test-file-1.txt (160B)14132026/10/07 06:22:32 INFO Uploading fa204ci9xj96vbdcmwr2cs9sy2yhcip4-test-file-2.txt (160B)14142026/10/07 06:22:32 INFO Uploading c41rplg5vdb3xz9wm5kj18p2k2dckrw5-test-file-0.txt (160B)14152026/10/07 06:22:32 WARN Failed to register uploaded object key=s9sz2wrvs16cgllgixybg58wn7xa538n.ls error="server returned 404: 404 page not found\n"14162026/10/07 06:22:32 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"14172026/10/07 06:22:32 WARN Failed to register uploaded object key=c41rplg5vdb3xz9wm5kj18p2k2dckrw5.ls error="server returned 404: 404 page not found\n"14182026/10/07 06:22:32 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"14192026/10/07 06:22:32 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"14202026/10/07 06:22:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14212026/10/07 06:22:32 WARN Failed to register uploaded object key=fa204ci9xj96vbdcmwr2cs9sy2yhcip4.ls error="server returned 404: 404 page not found\n"14222026/10/07 06:22:32 INFO Signed narinfos id=1 count=314232026/10/07 06:22:32 INFO Uploading 3 narinfos14242026/10/07 06:22:32 WARN Failed to register uploaded object key=c41rplg5vdb3xz9wm5kj18p2k2dckrw5.narinfo error="server returned 404: 404 page not found\n"14252026/10/07 06:22:32 INFO Received complete push request method=POST path=/api/pushes/1/complete14262026/10/07 06:22:32 WARN Failed to register uploaded object key=fa204ci9xj96vbdcmwr2cs9sy2yhcip4.narinfo error="server returned 404: 404 page not found\n"14272026/10/07 06:22:32 WARN Failed to register uploaded object key=s9sz2wrvs16cgllgixybg58wn7xa538n.narinfo error="server returned 404: 404 page not found\n"14282026/10/07 06:22:32 INFO Aborted multipart uploads count=0 kept=014292026/10/07 06:22:32 INFO All 1 paths already cached1430=== NAME TestClientIntegration1431 client_integration_test.go:312: Retrieved narinfo from S3:1432 StorePath: /build/TestClientIntegration4132396409/002/store/v5nm2aipl0v04z25n5rgyvr8b4d73zpd-test-file.txt1433 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1434 Compression: zstd1435 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11436 NarSize: 1521437 References: 1438 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11439 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1440 client_integration_test.go:313: Decompressed .ls content (64 bytes):1441 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1442 client_integration_test.go:316: Testing garbage collection...14432026/10/07 06:22:32 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14442026/10/07 06:22:32 WARN Refused reserved pin name=worker-x86_64-linux14452026/10/07 06:22:32 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14462026/10/07 06:22:32 INFO Received create pin request method=POST path=/api/pins/my-app14472026/10/07 06:22:32 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14482026/10/07 06:22:32 WARN Force mode enabled - objects will be deleted immediately without grace period1449--- PASS: TestCreatePin_ReservedPins (0.50s)1450=== CONT TestSweepRechecksPendingAfterLocking14512026/10/07 06:22:32 INFO Completed push id=1 objects=9 duration=11.201856ms14522026/10/07 06:22:32 INFO Upload complete. (75ms)1453=== NAME TestClientMultipleUploads1454 client_integration_test.go:369: Uploaded 3 paths in 106.023502ms1455=== NAME TestClientCADerivations1456 client_ca_test.go:139: Found 1 dependencies (including self)1457--- PASS: TestClientMultipleUploads (0.71s)1458=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1459=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1460=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1461=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1462=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1463=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1464=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1465=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1466=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1467=== CONT TestCommitRacingPendingCleanupKeepsObjects14682026/10/07 06:22:32 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=014692026/10/07 06:22:32 INFO Vacuumed table table=pending_closures14702026/10/07 06:22:32 INFO Vacuumed table table=pending_objects14712026/10/07 06:22:32 INFO Vacuumed table table=multipart_uploads14722026/10/07 06:22:32 INFO Starting cleanup of old closures method=DELETE path=/api/closures14732026/10/07 06:22:32 INFO Garbage collection started14742026/10/07 06:22:32 INFO Vacuumed table table=closures14752026/10/07 06:22:32 INFO Aborted multipart uploads count=0 kept=014762026/10/07 06:22:32 INFO Vacuumed table table=objects14772026/10/07 06:22:32 WARN Force mode enabled - objects will be deleted immediately without grace period14782026/10/07 06:22:32 INFO Received uploads request method=POST path=/api/pending_closures14792026/10/07 06:22:32 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=014802026/10/07 06:22:32 INFO Vacuumed table table=pending_closures14812026/10/07 06:22:32 INFO Vacuumed table table=pending_objects14822026/10/07 06:22:32 INFO Vacuumed table table=multipart_uploads14832026/10/07 06:22:32 INFO Vacuumed table table=closures14842026/10/07 06:22:32 INFO Vacuumed table table=objects14852026/10/07 06:22:32 INFO Received push request method=POST path=/api/pushes14862026/10/07 06:22:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14872026/10/07 06:22:32 INFO Uploading fva8m8yyfp6yppx935byckk0g17a9i66-ca-test (144B)1488=== RUN TestService_RequireScope_OIDC/builder_may_write1489=== PAUSE TestService_RequireScope_OIDC/builder_may_write1490=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1491=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1492=== RUN TestService_RequireScope_OIDC/ops_may_admin1493=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1494=== RUN TestService_RequireScope_OIDC/ops_may_not_write14952026/10/07 06:22:32 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"1496=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1497=== RUN TestService_RequireScope_OIDC/reader_may_not_write1498=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1499=== RUN TestService_RequireScope_OIDC/static_token_may_admin1500=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1501=== RUN TestService_RequireScope_OIDC/static_token_may_write15022026/10/07 06:22:32 WARN Failed to register uploaded object key=fva8m8yyfp6yppx935byckk0g17a9i66.ls error="server returned 404: 404 page not found\n"1503=== PAUSE TestService_RequireScope_OIDC/static_token_may_write15042026/10/07 06:22:32 WARN Failed to register uploaded object key=log/7h3xggbaijqpdb7g8kqjjxad4r4cajs5-ca-test.drv error="server returned 404: 404 page not found\n"1505=== RUN TestService_RequireScope_OIDC/reader_may_read1506=== PAUSE TestService_RequireScope_OIDC/reader_may_read15072026/10/07 06:22:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1508=== RUN TestService_RequireScope_OIDC/writer_implies_read1509=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1510=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1511=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1512=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1513=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1514=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc15152026/10/07 06:22:32 INFO Signed narinfos id=1 count=11516=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1517=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1518=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1519=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1520=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1521=== CONT TestService_ReadAuthMiddleware15222026/10/07 06:22:32 INFO Uploading 1 narinfos15232026/10/07 06:22:32 INFO Received complete push request method=POST path=/api/pushes/1/complete15242026/10/07 06:22:32 WARN Failed to register uploaded object key=fva8m8yyfp6yppx935byckk0g17a9i66.narinfo error="server returned 404: 404 page not found\n"15252026/10/07 06:22:32 INFO Completed push id=1 objects=4 duration=6.026698ms15262026/10/07 06:22:32 INFO Upload complete. (100ms)15272026/10/07 06:22:32 INFO Received uploads request method=POST path=/api/pending_closures1528=== NAME TestClientCADerivations1529 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations4254505712/001/store/fva8m8yyfp6yppx935byckk0g17a9i66-ca-test1530 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1531 Compression: zstd1532 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1533 NarSize: 1441534 References: 1535 Deriver: /build/TestClientCADerivations4254505712/001/store/7h3xggbaijqpdb7g8kqjjxad4r4cajs5-ca-test.drv1536 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1537 client_ca_test.go:185: Checking for realisation files in S3...1538 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1539 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache15402026/10/07 06:22:32 INFO Received cleanup request method=DELETE path=/api/pending_closures15412026/10/07 06:22:32 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket66/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""15422026/10/07 06:22:32 INFO Aborted multipart uploads count=0 kept=115432026/10/07 06:22:32 INFO Received cleanup request method=DELETE path=/api/pending_closures15442026/10/07 06:22:32 INFO Aborted multipart uploads count=1 kept=01545--- PASS: TestMultipartCleanup (0.44s)1546=== CONT TestForceGCDuringPushOffersSweptObject1547=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1548=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1549=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1550=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1551=== CONT TestNARDeduplicationMetadataUploadBug1552--- PASS: TestObjectStatsTrigger (0.32s)1553=== CONT TestTombstonedObjectOfferedWithoutWaiting15542026/10/07 06:22:32 WARN mTLS auth: subject not in bound subjects subject="CN=reader"15552026/10/07 06:22:32 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1556--- PASS: TestService_NativeMTLS (0.30s)1557=== CONT TestGCSweepSkipsPendingObjects15582026/10/07 06:22:32 INFO Aborted multipart uploads count=0 kept=015592026/10/07 06:22:32 WARN Force mode enabled - objects will be deleted immediately without grace period15602026/10/07 06:22:32 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."15612026/10/07 06:22:32 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1562--- PASS: TestFailedS3DeleteKeepsTombstone (0.40s)1563=== CONT TestDeduplicatedObjectsRecordedAsPending15642026/10/07 06:22:32 INFO Received uploads request method=POST path=/api/pending_closures15652026/10/07 06:22:32 INFO Received uploads request method=POST path=/api/pending_closures1566=== NAME TestClientCADerivations1567 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1568 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1569 error: binary cache 's3://bucket59?endpoint=http://localhost:33317®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations4254505712/001/store'1570 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 115712026/10/07 06:22:32 INFO Received push request method=POST path=/api/pushes1572--- PASS: TestClientCADerivations (0.88s)1573=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection15742026/10/07 06:22:32 INFO Received cleanup request method=DELETE path=/api/pending_closures15752026/10/07 06:22:32 INFO Received complete push request method=POST path=/api/pushes/1/complete15762026/10/07 06:22:32 INFO Received uploads request method=POST path=/api/pending_closures15772026/10/07 06:22:32 INFO Completed push id=1 objects=4 duration=8.324957ms15782026/10/07 06:22:32 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15792026/10/07 06:22:32 INFO Completed upload id=2 objects=2 duration=2.692059ms1580--- PASS: TestMetricsCommit (0.37s)1581=== CONT TestRegisterCompletedObjectNeedsPendingRow1582--- PASS: TestMetricsInventory (0.39s)1583=== CONT TestService_AuthMiddleware_MTLSProxyHeader15842026/10/07 06:22:32 INFO Aborted multipart uploads count=0 kept=015852026/10/07 06:22:32 WARN Force mode enabled - objects will be deleted immediately without grace period15862026/10/07 06:22:32 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15872026/10/07 06:22:32 WARN mTLS auth: bound subjects configured but subject DN unavailable15882026/10/07 06:22:32 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1589--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.37s)1590=== CONT TestGCSweepDeliversEachKeyOnce15912026/10/07 06:22:32 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=015922026/10/07 06:22:32 INFO Vacuumed table table=pending_closures15932026/10/07 06:22:32 INFO Vacuumed table table=pending_objects15942026/10/07 06:22:32 INFO Vacuumed table table=multipart_uploads15952026/10/07 06:22:32 INFO Vacuumed table table=closures15962026/10/07 06:22:32 INFO Vacuumed table table=objects1597--- PASS: TestSweepRechecksPendingAfterLocking (0.41s)1598=== CONT TestSweepSkipsRowsLockedByPush1599--- PASS: TestService_ReadAuthMiddleware (0.30s)1600=== CONT TestGetExistingObjectsLocksRows1601=== NAME TestOrphanedObjectsGC1602 orphaned_objects_gc_test.go:287: GC Test Summary:1603 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1604 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1605 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1606 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1607 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1608--- PASS: TestOrphanedObjectsGC (0.68s)1609=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16102026/10/07 06:22:32 INFO Received uploads request method=POST path=/1611=== CONT TestProxyWriteTimeout/narinfo1612=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16132026/10/07 06:22:32 INFO Received complete multipart upload request method=POST path=/1614=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16152026/10/07 06:22:32 INFO Received uploads request method=POST path=/1616=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16172026/10/07 06:22:32 INFO Received request for more parts method=POST path=/1618--- PASS: TestUploadHandlersRejectInvalidKeys (0.09s)1619 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1620 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1621 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1622 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1623=== CONT TestProxyWriteTimeout/10_GiB_nar1624=== CONT TestProxyWriteTimeout/1_GiB_nar1625=== CONT TestProxyWriteTimeout/unknown_size1626--- PASS: TestProxyWriteTimeout (0.09s)1627 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1628 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1629 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1630 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1631=== CONT TestPendingClosureWriteTimeout/empty1632=== CONT TestPendingClosureWriteTimeout/670k_objects1633=== CONT TestPendingClosureWriteTimeout/400_objects1634=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline16352026/10/07 06:22:32 INFO Aborted multipart uploads count=0 kept=016362026/10/07 06:22:32 WARN Force mode enabled - objects will be deleted immediately without grace period16372026/10/07 06:22:32 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=016382026/10/07 06:22:32 INFO Vacuumed table table=pending_closures16392026/10/07 06:22:32 INFO Vacuumed table table=pending_objects16402026/10/07 06:22:32 INFO Vacuumed table table=multipart_uploads16412026/10/07 06:22:32 INFO Vacuumed table table=closures16422026/10/07 06:22:32 INFO Vacuumed table table=objects1643--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.48s)1644=== CONT TestIsValidUploadKey/narinfo1645=== CONT TestIsValidUploadKey/realisation_plus_in_output1646=== CONT TestIsValidUploadKey/realisation1647=== CONT TestIsValidUploadKey/build_log_equals1648=== CONT TestIsValidUploadKey/build_log_question_mark1649=== CONT TestIsValidUploadKey/build_log_plus_in_name1650=== CONT TestIsValidUploadKey/build_log_home-manager_file1651=== CONT TestIsValidUploadKey/build_log1652=== CONT TestIsValidUploadKey/listing1653=== CONT TestIsValidUploadKey/nar_plain1654=== CONT TestIsValidUploadKey/nar_xz1655=== CONT TestIsValidUploadKey/nar_zst1656=== CONT TestIsValidUploadKey/traversal_nar1657=== CONT TestIsValidUploadKey/nix-cache-info1658=== CONT TestIsValidUploadKey/traversal1659=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1660=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1661=== CONT TestIsValidUploadKey/index.html1662=== CONT TestIsValidUploadKey/empty_key1663=== CONT TestIsValidUploadKey/unknown_type1664=== CONT TestIsValidUploadKey/absolute1665=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1666--- PASS: TestIsValidUploadKey (0.09s)1667 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1668 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1669 --- PASS: TestIsValidUploadKey/realisation (0.00s)1670 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1671 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1672 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1673 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1674 --- PASS: TestIsValidUploadKey/build_log (0.00s)1675 --- PASS: TestIsValidUploadKey/listing (0.00s)1676 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1677 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1678 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1679 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1680 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1681 --- PASS: TestIsValidUploadKey/traversal (0.00s)1682 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1683 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1684 --- PASS: TestIsValidUploadKey/index.html (0.00s)1685 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1686 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1687 --- PASS: TestIsValidUploadKey/absolute (0.00s)1688 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1689=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16902026/10/07 06:22:32 INFO Received complete multipart upload request method=POST path=/16912026/10/07 06:22:32 INFO Received uploads request method=POST path=/api/pending_closures1692--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.27s)1693=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16942026/10/07 06:22:32 INFO Received request for more parts method=POST path=/1695=== NAME TestNARDeduplicationMetadataUploadBug1696 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug1472780792/001/store/kpw7ghjwilz7bmqqvh8090cb3q9xviyh-file1.txt16972026/10/07 06:22:32 INFO Received uploads request method=POST path=/api/pending_closures1698=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16992026/10/07 06:22:32 INFO Received uploads request method=POST path=/17002026/10/07 06:22:32 INFO Aborted multipart uploads count=0 kept=017012026/10/07 06:22:32 WARN Force mode enabled - objects will be deleted immediately without grace period17022026/10/07 06:22:32 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=017032026/10/07 06:22:32 INFO Received uploads request method=POST path=/api/pending_closures17042026/10/07 06:22:32 INFO Vacuumed table table=pending_closures17052026/10/07 06:22:32 INFO Vacuumed table table=pending_objects17062026/10/07 06:22:32 INFO Vacuumed table table=multipart_uploads17072026/10/07 06:22:32 INFO Vacuumed table table=closures17082026/10/07 06:22:32 INFO Vacuumed table table=objects1709--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.30s)1710=== CONT TestPush_RejectsBadRequests/no_roots17112026/10/07 06:22:32 INFO Received push request method=POST path=/api/pushes1712=== CONT TestPush_RejectsBadRequests/bad_root17132026/10/07 06:22:32 INFO Received push request method=POST path=/api/pushes1714=== CONT TestPush_RejectsBadRequests/root_not_in_objects17152026/10/07 06:22:32 INFO Received push request method=POST path=/api/pushes1716=== CONT TestPush_RejectsBadRequests/no_objects17172026/10/07 06:22:32 INFO Received push request method=POST path=/api/pushes1718=== CONT TestIsValidCachePath/narinfo1719--- PASS: TestPush_RejectsBadRequests (0.69s)1720 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1721 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1722 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1723 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1724=== CONT TestIsValidCachePath/index.html1725=== CONT TestIsValidCachePath/short_hash1726=== CONT TestIsValidCachePath/wrong_extension1727=== CONT TestIsValidCachePath/leading_slash1728=== CONT TestIsValidCachePath/empty1729=== CONT TestIsValidCachePath/random_path1730=== CONT TestIsValidCachePath/invalid_char_u1731=== CONT TestIsValidCachePath/invalid_char_e1732=== CONT TestIsValidCachePath/traversal_in_middle1733=== CONT TestIsValidCachePath/traversal_parent1734=== CONT TestIsValidCachePath/nar_uncompressed1735=== CONT TestIsValidCachePath/nix-cache-info1736=== CONT TestIsValidCachePath/realisation1737=== CONT TestIsValidCachePath/log1738=== CONT TestIsValidCachePath/ls1739=== CONT TestIsValidCachePath/nar_xz1740=== CONT TestIsValidCachePath/nar_bz21741=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1742=== CONT TestIsValidCachePath/nar_zst1743--- PASS: TestIsValidCachePath (0.00s)1744 --- PASS: TestIsValidCachePath/narinfo (0.00s)1745 --- PASS: TestIsValidCachePath/index.html (0.00s)1746 --- PASS: TestIsValidCachePath/short_hash (0.00s)1747 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1748 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1749 --- PASS: TestIsValidCachePath/empty (0.00s)1750 --- PASS: TestIsValidCachePath/random_path (0.00s)1751 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1752 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1753 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1754 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1755 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1756 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1757 --- PASS: TestIsValidCachePath/realisation (0.00s)1758 --- PASS: TestIsValidCachePath/log (0.00s)1759 --- PASS: TestIsValidCachePath/ls (0.00s)1760 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1761 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1762 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1763 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1764=== CONT TestParseSingleRange/none1765=== CONT TestParseSingleRange/open-ended1766=== CONT TestParseSingleRange/start_far_past_EOF1767=== CONT TestParseSingleRange/start_past_EOF1768=== CONT TestParseSingleRange/single_byte1769=== CONT TestParseSingleRange/suffix_exceeds_size1770=== CONT TestParseSingleRange/suffix1771=== CONT TestParseSingleRange/end_clamped_to_size1772=== CONT TestParseSingleRange/malformed_both_empty1773=== CONT TestParseSingleRange/closed1774=== CONT TestParseSingleRange/malformed_end_before_start1775=== CONT TestParseSingleRange/multi-range_ignored1776=== CONT TestParseSingleRange/malformed_no_dash1777=== CONT TestParseSingleRange/unknown_unit1778=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1779--- PASS: TestParseSingleRange (0.00s)1780 --- PASS: TestParseSingleRange/none (0.00s)1781 --- PASS: TestParseSingleRange/open-ended (0.00s)1782 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1783 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1784 --- PASS: TestParseSingleRange/single_byte (0.00s)1785 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1786 --- PASS: TestParseSingleRange/suffix (0.00s)1787 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1788 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1789 --- PASS: TestParseSingleRange/closed (0.00s)1790 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1791 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1792 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1793 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1794--- PASS: TestGCSweepSkipsPendingObjects (0.33s)1795=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1796=== CONT TestResolveDBConnectionString/flag_wins1797=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1798=== CONT TestResolveDBConnectionString/nothing_configured1799=== CONT TestResolveDBConnectionString/missing_file_is_an_error1800=== CONT TestResolveDBConnectionString/file_when_flag_empty1801=== CONT TestCacheConfigHandler/full_config,_no_issuer1802=== CONT TestCacheConfigHandler/no_signing_keys1803=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1804=== CONT TestCacheConfigHandler/no_cache_url_configured1805--- PASS: TestCacheConfigHandler (0.00s)1806 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1807 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1808 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1809 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1810=== CONT TestClientErrorHandling/InvalidStorePath1811--- PASS: TestResolveDBConnectionString (0.00s)1812 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1813 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1814 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1815 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1816 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)18172026/10/07 06:22:32 INFO Received uploads request method=POST path=/api/pending_closures18182026/10/07 06:22:32 INFO Received push request method=POST path=/api/pushes18192026/10/07 06:22:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18202026/10/07 06:22:32 INFO Uploading kpw7ghjwilz7bmqqvh8090cb3q9xviyh-file1.txt (160B)18212026/10/07 06:22:32 WARN Failed to register uploaded object key=kpw7ghjwilz7bmqqvh8090cb3q9xviyh.ls error="server returned 404: 404 page not found\n"18222026/10/07 06:22:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18232026/10/07 06:22:32 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"18242026/10/07 06:22:32 INFO Signed narinfos id=1 count=118252026/10/07 06:22:32 INFO Uploading 1 narinfos18262026/10/07 06:22:32 INFO Received complete push request method=POST path=/api/pushes/1/complete18272026/10/07 06:22:32 WARN Failed to register uploaded object key=kpw7ghjwilz7bmqqvh8090cb3q9xviyh.narinfo error="server returned 404: 404 page not found\n"1828--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.28s)1829=== CONT TestClientErrorHandling/ServerNotAvailable18302026/10/07 06:22:32 INFO Completed push id=1 objects=3 duration=10.113426ms18312026/10/07 06:22:32 INFO Upload complete. (71ms)1832=== NAME TestNARDeduplicationMetadataUploadBug1833 metadata_upload_test.go:54: Retrieved narinfo from S3:1834 StorePath: /build/TestNARDeduplicationMetadataUploadBug1472780792/001/store/kpw7ghjwilz7bmqqvh8090cb3q9xviyh-file1.txt1835 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1836 Compression: zstd1837 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1838 NarSize: 1601839 References: 1840 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1841 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1842 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1843 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1844--- PASS: TestDeleteClosuresRacingPins (1.57s)1845=== CONT TestClientErrorHandling/InvalidAuthToken1846--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.27s)1847=== CONT TestGCEndsOnShutdown/before_the_run1848=== NAME TestNARDeduplicationMetadataUploadBug1849 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug1472780792/001/store/pdb9402bl1h3hkd7qa2p361giw8ab6kx-file2.txt18502026/10/07 06:22:32 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/present18512026/10/07 06:22:32 INFO Aborted multipart uploads count=0 kept=018522026/10/07 06:22:32 INFO Aborted multipart uploads count=0 kept=018532026/10/07 06:22:32 WARN Force mode enabled - objects will be deleted immediately without grace period18542026/10/07 06:22:32 WARN Force mode enabled - objects will be deleted immediately without grace period18552026/10/07 06:22:32 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=018562026/10/07 06:22:32 INFO Vacuumed table table=pending_closures18572026/10/07 06:22:32 INFO Vacuumed table table=pending_objects18582026/10/07 06:22:32 INFO Vacuumed table table=multipart_uploads18592026/10/07 06:22:32 INFO Vacuumed table table=closures18602026/10/07 06:22:32 INFO Vacuumed table table=objects18612026/10/07 06:22:32 INFO Aborted multipart uploads count=0 kept=018622026/10/07 06:22:32 INFO Received push request method=POST path=/api/pushes18632026/10/07 06:22:32 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=018642026/10/07 06:22:32 INFO Vacuumed table table=pending_closures18652026/10/07 06:22:32 INFO Vacuumed table table=pending_objects18662026/10/07 06:22:32 INFO Vacuumed table table=multipart_uploads18672026/10/07 06:22:32 INFO Vacuumed table table=closures18682026/10/07 06:22:32 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)18692026/10/07 06:22:32 WARN Force mode enabled - objects will be deleted immediately without grace period1870--- PASS: TestGetExistingObjectsLocksRows (0.34s)1871=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark18722026/10/07 06:22:32 INFO Vacuumed table table=objects1873--- PASS: TestGCSweepDeliversEachKeyOnce (0.40s)1874=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete18752026/10/07 06:22:32 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign18762026/10/07 06:22:32 INFO Signed narinfos id=2 count=118772026/10/07 06:22:32 WARN Failed to register uploaded object key=pdb9402bl1h3hkd7qa2p361giw8ab6kx.ls error="server returned 404: 404 page not found\n"18782026/10/07 06:22:32 INFO Uploading 1 narinfos1879--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.50s)1880=== CONT TestServerTLSConfig/no_client_CA1881=== CONT TestServerTLSConfig/not_a_PEM_file1882=== CONT TestServerTLSConfig/missing_CA_file1883--- PASS: TestServerTLSConfig (0.00s)1884 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1885 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1886 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1887=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1888=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected18892026/10/07 06:22:32 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=018902026/10/07 06:22:32 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]1891=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1892=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected18932026/10/07 06:22:32 INFO Received complete push request method=POST path=/api/pushes/2/complete18942026/10/07 06:22:32 INFO Vacuumed table table=pending_closures18952026/10/07 06:22:32 WARN Failed to register uploaded object key=pdb9402bl1h3hkd7qa2p361giw8ab6kx.narinfo error="server returned 404: 404 page not found\n"18962026/10/07 06:22:32 INFO Vacuumed table table=pending_objects18972026/10/07 06:22:32 INFO Vacuumed table table=multipart_uploads18982026/10/07 06:22:32 INFO Vacuumed table table=closures18992026/10/07 06:22:32 WARN Authentication failed token_preview=eyJhbGciOi...J72azL-9Aw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1900=== CONT TestService_RequireScope_OIDC/builder_may_write1901--- PASS: TestService_AuthMiddleware_OIDC (0.51s)1902 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1903 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1904 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1905 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1906=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1907=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1908=== CONT TestService_RequireScope_OIDC/writer_implies_read19092026/10/07 06:22:32 INFO Completed push id=2 objects=3 duration=2.579389ms1910=== CONT TestService_RequireScope_OIDC/reader_may_read19112026/10/07 06:22:32 INFO Upload complete. (52ms)1912=== CONT TestService_RequireScope_OIDC/static_token_may_write1913=== CONT TestService_RequireScope_OIDC/static_token_may_admin1914=== CONT TestService_RequireScope_OIDC/reader_may_not_write1915=== CONT TestService_RequireScope_OIDC/ops_may_not_write1916=== CONT TestService_RequireScope_OIDC/ops_may_admin1917=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1918=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1919=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1920=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19212026/10/07 06:22:32 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]1922=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows19232026/10/07 06:22:32 INFO Vacuumed table table=objects1924=== NAME TestNARDeduplicationMetadataUploadBug1925 metadata_upload_test.go:76: Retrieved narinfo from S3:1926 StorePath: /build/TestNARDeduplicationMetadataUploadBug1472780792/001/store/pdb9402bl1h3hkd7qa2p361giw8ab6kx-file2.txt1927 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1928 Compression: zstd1929 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1930 NarSize: 1601931--- PASS: TestService_RequireScope_OIDC (0.43s)1932 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1933 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1934 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1935 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1936 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1937 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1938 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1939 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1940 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1941 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1942 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1943 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1944 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1945 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1946=== NAME TestNARDeduplicationMetadataUploadBug1947 References: 1948 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1949--- PASS: TestSweepSkipsRowsLockedByPush (0.37s)1950=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1951=== NAME TestNARDeduplicationMetadataUploadBug1952 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1953 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1954 {"version":1,"root":{"type":"regular","size":44}}19552026/10/07 06:22:32 INFO Received uploads request method=POST path=/api/pending_closures1956--- PASS: TestNARDeduplicationMetadataUploadBug (0.60s)19572026/10/07 06:22:32 INFO lead: released remote=192.0.2.1:12341958--- PASS: TestLeadEndsOnShutdown (1.53s)1959--- PASS: TestPushWaitsForSweepHoldingRow (0.85s)19602026/10/07 06:22:32 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=218.162214ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19612026/10/07 06:22:33 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"19622026/10/07 06:22:33 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"19632026/10/07 06:22:33 INFO Aborted multipart uploads count=0 kept=019642026/10/07 06:22:33 WARN Force mode enabled - objects will be deleted immediately without grace period19652026/10/07 06:22:33 INFO Aborted multipart uploads count=0 kept=019662026-10-07 06:22:33.109 UTC [2138] ERROR: canceling statement due to user request19672026-10-07 06:22:33.109 UTC [2138] CONTEXT: SQL statement "UPDATE object_stats s1968 SET object_count = s.object_count + n.n - o.n,1969 total_bytes = s.total_bytes + n.bytes - o.bytes1970 FROM (1971 SELECT count(*) AS n, coalesce(sum(size), 0) AS bytes1972 FROM new_rows WHERE deleted_at IS NULL1973 ) AS n,1974 (1975 SELECT count(*) AS n, coalesce(sum(size), 0) AS bytes1976 FROM old_rows WHERE deleted_at IS NULL1977 ) AS o1978 WHERE s.id AND (n.n <> o.n OR n.bytes <> o.bytes)"1979 PL/pgSQL function object_stats_update() line 3 at SQL statement19802026-10-07 06:22:33.109 UTC [2138] STATEMENT: -- name: MarkStaleObjects :execrows1981 WITH RECURSIVE ct AS (1982 SELECT timezone('UTC', now()) AS now1983 ),1984 closure_reach AS (1985 -- Start with all closure keys1986 SELECT o.key, o.refs1987 FROM objects o1988 INNER JOIN closures c ON o.key = c.key1989 UNION1990 -- Recursively add all referenced objects1991 SELECT o.key, o.refs1992 FROM objects o1993 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)1994 ),1995 reachable_objects AS (1996 SELECT DISTINCT key FROM closure_reach1997 ),1998 stale_objects AS (1999 SELECT o.key2000 FROM objects AS o, ct2001 WHERE2002 NOT EXISTS (2003 SELECT 12004 FROM reachable_objects ro2005 WHERE ro.key = o.key2006 )2007 AND NOT EXISTS (2008 SELECT 12009 FROM pending_objects AS po2010 WHERE po.key = o.key2011 )2012 AND o.deleted_at IS NULL -- Only mark fresh objects2013 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2014 FOR UPDATE2015 )2016 UPDATE objects2017 SET2018 deleted_at = ct.now,2019 first_deleted_at = COALESCE(first_deleted_at, ct.now)2020 FROM stale_objects, ct2021 WHERE objects.key = stale_objects.key2022 20232026/10/07 06:22:33 WARN Force mode enabled - objects will be deleted immediately without grace period20242026/10/07 06:22:33 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:33317/bucket98/?delete=\": context canceled"2025--- PASS: TestGCEndsOnShutdown (0.00s)2026 --- PASS: TestGCEndsOnShutdown/before_the_run (0.26s)2027 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.22s)2028 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.22s)20292026/10/07 06:22:33 INFO Received uploads request method=POST path=/api/pending_closures20302026/10/07 06:22:33 INFO Aborted multipart uploads count=0 kept=020312026/10/07 06:22:33 WARN Force mode enabled - objects will be deleted immediately without grace period20322026/10/07 06:22:33 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=020332026/10/07 06:22:33 INFO Vacuumed table table=pending_closures20342026/10/07 06:22:33 INFO Vacuumed table table=pending_objects20352026/10/07 06:22:33 INFO Vacuumed table table=multipart_uploads20362026/10/07 06:22:33 INFO Vacuumed table table=closures20372026/10/07 06:22:33 INFO Vacuumed table table=objects20382026/10/07 06:22:33 INFO Received uploads request method=POST path=/api/pending_closures20392026/10/07 06:22:33 INFO Aborted multipart uploads count=0 kept=020402026/10/07 06:22:33 WARN Force mode enabled - objects will be deleted immediately without grace period20412026/10/07 06:22:33 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=020422026/10/07 06:22:33 INFO Vacuumed table table=pending_closures20432026/10/07 06:22:33 INFO Vacuumed table table=pending_objects20442026/10/07 06:22:33 INFO Vacuumed table table=multipart_uploads20452026/10/07 06:22:33 INFO Vacuumed table table=closures20462026/10/07 06:22:33 INFO Vacuumed table table=objects20472026/10/07 06:22:33 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=382.544754ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2048--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2049 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.26s)2050 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.28s)2051--- PASS: TestObjectStatsLargeCommit (1.21s)20522026/10/07 06:22:33 INFO lead: released remote=192.0.2.1:123420532026/10/07 06:22:33 INFO lead: acquired remote=192.0.2.1:12342054--- PASS: TestUploadHandlersRejectOversizedBody (0.19s)2055 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)2056 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.06s)2057 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.77s)2058--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2059 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.79s)2060 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.85s)20612026/10/07 06:22:33 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=825.096327ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2062--- PASS: TestPendingClosureWriteTimeout (0.09s)2063 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2064 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2065 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2066 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.14s)2067=== NAME TestOrphanedObjectsGCStressTest2068 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2069 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion2070 orphaned_objects_gc_test.go:503: Stress test completed successfully:2071 orphaned_objects_gc_test.go:504: - Active objects preserved: 202072 orphaned_objects_gc_test.go:505: - Objects deleted: 2102073 orphaned_objects_gc_test.go:506: - Total GC'd: 2102074--- PASS: TestOrphanedObjectsGCStressTest (2.32s)20752026/10/07 06:22:34 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=020762026/10/07 06:22:34 INFO Received create pin request method=POST path=/api/pins/myapp20772026/10/07 06:22:34 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC1646185194/001/store/pmwwdh4sc5h3lhxk00iv5z3d0dzgi65m-pinned-file.txt narinfo_key=pmwwdh4sc5h3lhxk00iv5z3d0dzgi65m.narinfo20782026/10/07 06:22:34 INFO Starting cleanup of old closures method=DELETE path=/api/closures20792026/10/07 06:22:34 INFO Garbage collection started20802026/10/07 06:22:34 INFO Aborted multipart uploads count=0 kept=020812026/10/07 06:22:34 WARN Force mode enabled - objects will be deleted immediately without grace period20822026/10/07 06:22:34 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=020832026/10/07 06:22:34 INFO Vacuumed table table=pending_closures20842026/10/07 06:22:34 INFO Vacuumed table table=pending_objects20852026/10/07 06:22:34 INFO Vacuumed table table=multipart_uploads20862026/10/07 06:22:34 INFO Vacuumed table table=closures20872026/10/07 06:22:34 INFO Vacuumed table table=objects20882026/10/07 06:22:34 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02089=== NAME TestClientIntegration2090 client_integration_test.go:323: Objects in database after GC:2091 client_integration_test.go:323: Successfully deleted all objects with GC --force2092--- PASS: TestClientIntegration (2.73s)20932026/10/07 06:22:34 INFO lead: released remote=192.0.2.1:12342094--- PASS: TestLeadElectsOneAndHandsOver (2.88s)20952026/10/07 06:22:34 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.474027319s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2096--- PASS: TestReadProxyOutlastsServerWriteTimeout (5.07s)20972026/10/07 06:22:35 WARN Rate limiter enabled after throttle name=s3-test rate=520982026/10/07 06:22:35 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2099=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2100 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102101 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002102--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.18s)21032026/10/07 06:22:35 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-config21042026/10/07 06:22:35 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=204.540778ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2105=== NAME TestPinProtectsFromGC2106 client_integration_test.go:840: Pin successfully protected closure from garbage collection2107--- PASS: TestPinProtectsFromGC (4.87s)21082026/10/07 06:22:36 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=416.951214ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2109--- PASS: TestConnectWaitsForAPeerMigration (5.19s)21102026/10/07 06:22:36 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=755.939125ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21112026/10/07 06:22:37 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.451069418s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21122026/10/07 06:22:38 INFO Aborted multipart uploads count=1 kept=021132026/10/07 06:22:38 INFO Received cleanup request method=DELETE path=/api/pending_closures21142026/10/07 06:22:38 INFO Aborted multipart uploads count=1 kept=02115--- PASS: TestPendingCleanupUsesOneCutoff (6.36s)21162026/10/07 06:22:38 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"21172026/10/07 06:22:38 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-config21182026/10/07 06:22:38 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=197.691775ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21192026/10/07 06:22:39 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=426.910721ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21202026/10/07 06:22:39 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=815.712097ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21212026/10/07 06:22:40 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.609801657s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21222026/10/07 06:22:41 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_closures21232026/10/07 06:22:42 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=206.326839ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21242026/10/07 06:22:42 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=415.816551ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21252026/10/07 06:22:42 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=743.106641ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21262026/10/07 06:22:43 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.493059378s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2127--- PASS: TestClientErrorHandling (0.00s)2128 --- PASS: TestClientErrorHandling/InvalidStorePath (0.39s)2129 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.35s)2130 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.25s)2131PASS21322026-10-07 06:22:45.357 UTC [129] LOG: received smart shutdown request21332026-10-07 06:22:45.362 UTC [129] LOG: background worker "logical replication launcher" (PID 139) exited with exit code 121342026-10-07 06:22:45.373 UTC [134] LOG: shutting down21352026-10-07 06:22:45.374 UTC [134] LOG: checkpoint starting: shutdown immediate21362026-10-07 06:22:46.972 UTC [134] LOG: checkpoint complete: wrote 11393 buffers (69.5%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.238 s, sync=1.295 s, total=1.599 s; sync files=34046, longest=0.009 s, average=0.001 s; distance=531569 kB, estimate=531569 kB; lsn=0/21E82250, redo lsn=0/21E8225021372026-10-07 06:22:47.056 UTC [129] LOG: database system is shut down2138Running OIDC tests...2139=== RUN TestAudienceForIssuer2140=== PAUSE TestAudienceForIssuer2141=== RUN TestGlobMatch2142=== PAUSE TestGlobMatch2143=== RUN TestValidateToken_ValidToken2144=== PAUSE TestValidateToken_ValidToken2145=== RUN TestValidateToken_WrongAudience2146=== PAUSE TestValidateToken_WrongAudience2147=== RUN TestValidateToken_Expired2148=== PAUSE TestValidateToken_Expired2149=== RUN TestValidateToken_BoundClaimsMismatch2150=== PAUSE TestValidateToken_BoundClaimsMismatch2151=== RUN TestValidateToken_BoundSubjectMismatch2152=== PAUSE TestValidateToken_BoundSubjectMismatch2153=== RUN TestValidateToken_MultipleProviders2154=== PAUSE TestValidateToken_MultipleProviders2155=== RUN TestValidateToken_NoMatchingProvider2156=== PAUSE TestValidateToken_NoMatchingProvider2157=== RUN TestValidateToken_KubernetesServiceAccount2158=== PAUSE TestValidateToken_KubernetesServiceAccount2159=== RUN TestNewValidator_KubernetesRequiresCA2160=== PAUSE TestNewValidator_KubernetesRequiresCA2161=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2162=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2163=== RUN TestPins_ReservedForMatchingRule2164=== PAUSE TestPins_ReservedForMatchingRule2165=== RUN TestPins_TopLevelShorthand2166=== PAUSE TestPins_TopLevelShorthand2167=== RUN TestPins_ConfigValidation2168=== PAUSE TestPins_ConfigValidation2169=== RUN TestScopes_LegacyProviderDefaultsToWrite2170=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2171=== RUN TestScopes_Rules2172=== PAUSE TestScopes_Rules2173=== RUN TestScopes_ConfigValidation2174=== PAUSE TestScopes_ConfigValidation2175=== CONT TestAudienceForIssuer2176=== CONT TestValidateToken_KubernetesServiceAccount2177--- PASS: TestAudienceForIssuer (0.00s)2178=== CONT TestValidateToken_ValidToken2179=== CONT TestGlobMatch2180=== RUN TestGlobMatch/foo_foo2181=== PAUSE TestGlobMatch/foo_foo2182=== CONT TestValidateToken_Expired2183=== CONT TestPins_ConfigValidation2184=== CONT TestScopes_ConfigValidation2185=== CONT TestScopes_Rules2186=== CONT TestScopes_LegacyProviderDefaultsToWrite2187=== CONT TestPins_ReservedForMatchingRule2188=== CONT TestPins_TopLevelShorthand2189=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2190=== CONT TestNewValidator_KubernetesRequiresCA2191=== CONT TestValidateToken_MultipleProviders2192=== CONT TestValidateToken_NoMatchingProvider2193=== CONT TestValidateToken_BoundSubjectMismatch2194=== CONT TestValidateToken_BoundClaimsMismatch2195=== CONT TestValidateToken_WrongAudience2196=== RUN TestGlobMatch/foo_bar2197=== PAUSE TestGlobMatch/foo_bar2198=== RUN TestGlobMatch/*_2199=== PAUSE TestGlobMatch/*_2200=== RUN TestGlobMatch/*_anything2201=== PAUSE TestGlobMatch/*_anything2202=== RUN TestGlobMatch/foo*_foo2203=== PAUSE TestGlobMatch/foo*_foo2204=== RUN TestGlobMatch/foo*_foobar2205=== PAUSE TestGlobMatch/foo*_foobar2206=== RUN TestGlobMatch/foo*_bar2207=== PAUSE TestGlobMatch/foo*_bar2208=== RUN TestGlobMatch/*bar_bar2209=== PAUSE TestGlobMatch/*bar_bar2210=== RUN TestGlobMatch/*bar_foobar2211=== PAUSE TestGlobMatch/*bar_foobar2212=== RUN TestGlobMatch/*bar_foo2213=== PAUSE TestGlobMatch/*bar_foo2214=== RUN TestGlobMatch/foo*bar_foobar2215=== PAUSE TestGlobMatch/foo*bar_foobar2216=== RUN TestGlobMatch/foo*bar_foo123bar2217=== PAUSE TestGlobMatch/foo*bar_foo123bar2218=== RUN TestGlobMatch/foo*bar_foobarbaz2219=== PAUSE TestGlobMatch/foo*bar_foobarbaz2220=== RUN TestGlobMatch/*/*_foo/bar2221=== PAUSE TestGlobMatch/*/*_foo/bar2222=== RUN TestGlobMatch/*/*_foo2223=== PAUSE TestGlobMatch/*/*_foo2224=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2225=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2226=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02227=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02228=== RUN TestGlobMatch/refs/*/main_refs/heads/main2229=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2230=== RUN TestGlobMatch/fo?_foo2231=== PAUSE TestGlobMatch/fo?_foo2232=== RUN TestGlobMatch/fo?_fo2233=== PAUSE TestGlobMatch/fo?_fo2234=== RUN TestGlobMatch/fo?_fooo2235=== PAUSE TestGlobMatch/fo?_fooo2236=== RUN TestGlobMatch/?oo_foo2237=== PAUSE TestGlobMatch/?oo_foo2238=== RUN TestGlobMatch/?oo_boo2239=== PAUSE TestGlobMatch/?oo_boo2240=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2241=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2242=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2243=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2244=== CONT TestGlobMatch/foo_foo2245--- PASS: TestPins_ConfigValidation (0.00s)2246=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2247=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2248=== CONT TestGlobMatch/?oo_boo2249=== CONT TestGlobMatch/?oo_foo2250=== CONT TestGlobMatch/fo?_fooo2251=== CONT TestGlobMatch/fo?_fo2252=== CONT TestGlobMatch/fo?_foo2253=== CONT TestGlobMatch/refs/*/main_refs/heads/main2254=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02255=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2256=== CONT TestGlobMatch/*/*_foo2257=== CONT TestGlobMatch/*/*_foo/bar2258=== CONT TestGlobMatch/foo*bar_foobarbaz2259=== CONT TestGlobMatch/foo*bar_foo123bar2260=== CONT TestGlobMatch/foo*bar_foobar2261=== CONT TestGlobMatch/*bar_foo2262=== CONT TestGlobMatch/*bar_foobar2263=== CONT TestGlobMatch/*bar_bar2264=== CONT TestGlobMatch/foo*_bar2265=== CONT TestGlobMatch/foo*_foobar2266=== CONT TestGlobMatch/foo*_foo2267=== CONT TestGlobMatch/*_anything2268=== CONT TestGlobMatch/*_2269--- PASS: TestScopes_ConfigValidation (0.00s)2270=== CONT TestGlobMatch/foo_bar2271--- PASS: TestGlobMatch (0.00s)2272 --- PASS: TestGlobMatch/foo_foo (0.00s)2273 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2274 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2275 --- PASS: TestGlobMatch/?oo_boo (0.00s)2276 --- PASS: TestGlobMatch/?oo_foo (0.00s)2277 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2278 --- PASS: TestGlobMatch/fo?_fo (0.00s)2279 --- PASS: TestGlobMatch/fo?_foo (0.00s)2280 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2281 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2282 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2283 --- PASS: TestGlobMatch/*/*_foo (0.00s)2284 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2285 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2286 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2287 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2288 --- PASS: TestGlobMatch/*bar_foo (0.00s)2289 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2290 --- PASS: TestGlobMatch/*bar_bar (0.00s)2291 --- PASS: TestGlobMatch/foo*_bar (0.00s)2292 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2293 --- PASS: TestGlobMatch/foo*_foo (0.00s)2294 --- PASS: TestGlobMatch/*_anything (0.00s)2295 --- PASS: TestGlobMatch/*_ (0.00s)2296 --- PASS: TestGlobMatch/foo_bar (0.00s)22972026/10/07 06:22:49 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:4137522982026/10/07 06:22:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39851/oidc2299--- PASS: TestValidateToken_KubernetesServiceAccount (0.03s)2300--- PASS: TestPins_TopLevelShorthand (0.02s)23012026/10/07 06:22:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42625/oidc2302--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.04s)23032026/10/07 06:22:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35631/oidc23042026/10/07 06:22:49 http: TLS handshake error from 127.0.0.1:55108: remote error: tls: bad certificate2305--- PASS: TestNewValidator_KubernetesRequiresCA (0.05s)23062026/10/07 06:22:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34175/oidc2307--- PASS: TestScopes_Rules (0.05s)2308--- PASS: TestValidateToken_Expired (0.05s)23092026/10/07 06:22:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46493/oidc2310--- PASS: TestValidateToken_ValidToken (0.06s)23112026/10/07 06:22:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39087/oidc23122026/10/07 06:22:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38965/oidc2313--- PASS: TestValidateToken_WrongAudience (0.06s)23142026/10/07 06:22:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41687/oidc2315--- PASS: TestPins_ReservedForMatchingRule (0.06s)2316--- PASS: TestValidateToken_BoundSubjectMismatch (0.06s)23172026/10/07 06:22:49 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:33367/oidc2318--- PASS: TestValidateToken_NoMatchingProvider (0.07s)23192026/10/07 06:22:49 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232320--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.07s)23212026/10/07 06:22:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45137/oidc2322--- PASS: TestValidateToken_BoundClaimsMismatch (0.10s)23232026/10/07 06:22:49 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:37219/oidc23242026/10/07 06:22:49 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:44621/oidc2325--- PASS: TestValidateToken_MultipleProviders (0.12s)2326PASS2327Running hook tests...2328=== RUN TestSendPathsEmpty2329=== PAUSE TestSendPathsEmpty2330=== RUN TestQueueEnqueueAndFetch2331=== PAUSE TestQueueEnqueueAndFetch2332=== RUN TestQueueDeduplication2333=== PAUSE TestQueueDeduplication2334=== RUN TestQueueRemove2335=== PAUSE TestQueueRemove2336=== RUN TestQueueFetchBatchLimit2337=== PAUSE TestQueueFetchBatchLimit2338=== RUN TestQueueRetryMovesToBack2339=== PAUSE TestQueueRetryMovesToBack2340=== RUN TestQueueFetchRemoveLifecycle2341=== PAUSE TestQueueFetchRemoveLifecycle2342=== RUN TestQueueConcurrentWriters2343=== PAUSE TestQueueConcurrentWriters2344=== RUN TestQueueRemoveLargeClosure2345=== PAUSE TestQueueRemoveLargeClosure2346=== RUN TestServerClientIntegration2347--- PASS: TestServerClientIntegration (0.00s)2348=== RUN TestServerQueueError23492026/10/07 06:22:49 ERROR Failed to queue paths error="permission denied" count=12350--- PASS: TestServerQueueError (0.00s)2351=== RUN TestGetListenerSocketActivation2352 server_test.go:219: === RUN TestGetListenerSocketActivation2353 --- PASS: TestGetListenerSocketActivation (0.00s)2354 PASS2355 2356--- PASS: TestGetListenerSocketActivation (0.01s)2357=== RUN TestDrainIsolatesPoisonPath2358=== PAUSE TestDrainIsolatesPoisonPath2359=== RUN TestRunNotBlockedByPoisonHead2360=== PAUSE TestRunNotBlockedByPoisonHead2361=== RUN TestDrainGivesUpWhenServerDown2362=== PAUSE TestDrainGivesUpWhenServerDown2363=== RUN TestFailedPathPrunedByLaterClosure2364=== PAUSE TestFailedPathPrunedByLaterClosure2365=== RUN TestWorkerUploadsAndRemoves2366=== PAUSE TestWorkerUploadsAndRemoves2367=== RUN TestWorkerSkipsGCdPaths2368=== PAUSE TestWorkerSkipsGCdPaths2369=== RUN TestWorkerPrunesClosureDeps2370=== PAUSE TestWorkerPrunesClosureDeps2371=== RUN TestDrainTimeout2372=== PAUSE TestDrainTimeout2373=== CONT TestSendPathsEmpty2374=== CONT TestDrainTimeout2375--- PASS: TestSendPathsEmpty (0.00s)2376=== CONT TestDrainIsolatesPoisonPath2377=== CONT TestQueueRemoveLargeClosure2378=== CONT TestQueueConcurrentWriters2379=== CONT TestQueueFetchRemoveLifecycle2380=== CONT TestQueueRetryMovesToBack2381=== CONT TestQueueFetchBatchLimit2382=== CONT TestQueueRemove2383=== CONT TestQueueDeduplication2384=== CONT TestQueueEnqueueAndFetch2385=== CONT TestWorkerUploadsAndRemoves2386=== CONT TestWorkerPrunesClosureDeps2387=== CONT TestDrainGivesUpWhenServerDown2388=== CONT TestWorkerSkipsGCdPaths2389=== CONT TestFailedPathPrunedByLaterClosure2390=== CONT TestRunNotBlockedByPoisonHead23912026/10/07 06:22:49 INFO Uploading batch count=423922026/10/07 06:22:49 ERROR Upload failed error="upload failed" count=423932026/10/07 06:22:49 INFO Uploading batch count=223942026/10/07 06:22:49 INFO Uploading batch count=123952026/10/07 06:22:49 ERROR Upload failed error="upload failed" count=123962026/10/07 06:22:49 INFO Upload queue status pending=223972026/10/07 06:22:49 INFO Uploading batch count=223982026/10/07 06:22:49 ERROR Upload failed error="upload failed" count=22399--- PASS: TestQueueFetchBatchLimit (0.02s)24002026/10/07 06:22:49 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2956030595/002/a24012026/10/07 06:22:49 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath1597609994/002/bbb2402--- PASS: TestQueueEnqueueAndFetch (0.02s)24032026/10/07 06:22:49 INFO Uploading batch count=224042026/10/07 06:22:49 INFO Upload queue status pending=224052026/10/07 06:22:49 INFO Upload queue status pending=224062026/10/07 06:22:49 INFO Upload queue status pending=324072026/10/07 06:22:49 INFO Uploading batch count=124082026/10/07 06:22:49 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2956030595/002/b2409--- PASS: TestQueueFetchRemoveLifecycle (0.02s)24102026/10/07 06:22:49 INFO Uploading batch count=124112026/10/07 06:22:49 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths2208455857/002/nonexistent24122026/10/07 06:22:49 INFO Uploading batch count=12413--- PASS: TestQueueDeduplication (0.02s)24142026/10/07 06:22:49 ERROR Upload failed error="upload failed" count=124152026/10/07 06:22:49 INFO Uploading batch count=224162026/10/07 06:22:49 INFO Uploading batch count=12417--- PASS: TestQueueRemove (0.02s)24182026/10/07 06:22:49 ERROR Upload failed error="upload failed" count=22419--- PASS: TestQueueRetryMovesToBack (0.02s)24202026/10/07 06:22:49 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2956030595/002/c24212026/10/07 06:22:49 INFO Uploading batch count=124222026/10/07 06:22:49 INFO Uploading batch count=124232026/10/07 06:22:49 ERROR Upload failed error="upload failed" count=124242026/10/07 06:22:49 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2956030595/002/d24252026/10/07 06:22:49 INFO Uploading batch count=124262026/10/07 06:22:49 ERROR Upload failed error="upload failed" count=124272026/10/07 06:22:49 INFO Uploading batch count=224282026/10/07 06:22:49 ERROR Upload failed error="upload failed" count=224292026/10/07 06:22:49 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2956030595/002/e24302026/10/07 06:22:49 INFO Uploading batch count=124312026/10/07 06:22:49 ERROR Upload failed error="upload failed" count=124322026/10/07 06:22:49 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2956030595/002/f2433--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)24342026/10/07 06:22:49 ERROR Drain finished with paths left in queue remaining=1024352026/10/07 06:22:49 ERROR Drain finished with paths left in queue remaining=12436--- PASS: TestDrainIsolatesPoisonPath (0.03s)2437--- PASS: TestDrainGivesUpWhenServerDown (0.03s)2438--- PASS: TestWorkerUploadsAndRemoves (0.04s)2439--- PASS: TestWorkerSkipsGCdPaths (0.04s)2440--- PASS: TestWorkerPrunesClosureDeps (0.04s)2441--- PASS: TestQueueRemoveLargeClosure (0.06s)24422026/10/07 06:22:49 ERROR Upload failed error="context deadline exceeded" count=224432026/10/07 06:22:49 ERROR Drain finished with paths left in queue remaining=42444--- PASS: TestDrainTimeout (0.22s)2445--- PASS: TestQueueConcurrentWriters (0.38s)24462026/10/07 06:22:50 INFO Uploading batch count=124472026/10/07 06:22:50 INFO Uploading batch count=124482026/10/07 06:22:50 INFO Uploading batch count=124492026/10/07 06:22:50 ERROR Upload failed error="upload failed" count=124502026/10/07 06:22:50 INFO Uploading batch count=124512026/10/07 06:22:50 ERROR Upload failed error="upload failed" count=124522026/10/07 06:22:50 INFO Uploading batch count=124532026/10/07 06:22:50 ERROR Upload failed error="upload failed" count=124542026/10/07 06:22:50 INFO Uploading batch count=124552026/10/07 06:22:50 ERROR Upload failed error="upload failed" count=124562026/10/07 06:22:50 ERROR Drain finished with paths left in queue remaining=12457--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2458PASS2459Running signing tests...2460=== RUN TestExternalSigner2461=== PAUSE TestExternalSigner2462=== RUN TestExternalSignerWrongPublicKey2463=== PAUSE TestExternalSignerWrongPublicKey2464=== RUN TestExternalSignerErrors2465=== PAUSE TestExternalSignerErrors2466=== RUN TestExternalSignerRestartsAfterCrash2467=== PAUSE TestExternalSignerRestartsAfterCrash2468=== RUN TestExternalSignerProgramErrorKeepsProcess2469=== PAUSE TestExternalSignerProgramErrorKeepsProcess2470=== RUN TestExternalSignerClose2471=== PAUSE TestExternalSignerClose2472=== RUN TestExternalSignerRejectsInvalidPublicKey2473=== PAUSE TestExternalSignerRejectsInvalidPublicKey2474=== RUN TestExternalSignerCancellation2475=== PAUSE TestExternalSignerCancellation2476=== RUN TestGenerateFingerprint2477=== PAUSE TestGenerateFingerprint2478=== RUN TestParseSigningKey2479=== PAUSE TestParseSigningKey2480=== RUN TestSign2481=== PAUSE TestSign2482=== RUN TestSignBatch2483=== PAUSE TestSignBatch2484=== RUN TestNilKeyPublicKey2485=== PAUSE TestNilKeyPublicKey2486=== RUN TestSignErrors2487=== PAUSE TestSignErrors2488=== CONT TestExternalSigner2489=== CONT TestExternalSignerCancellation2490=== CONT TestSign2491=== CONT TestExternalSignerProgramErrorKeepsProcess2492=== CONT TestExternalSignerRejectsInvalidPublicKey2493=== RUN TestExternalSignerRejectsInvalidPublicKey/#002494=== CONT TestExternalSignerClose2495=== CONT TestSignErrors2496=== CONT TestExternalSignerErrors2497=== CONT TestExternalSignerRestartsAfterCrash2498=== CONT TestExternalSignerWrongPublicKey2499=== CONT TestParseSigningKey2500=== CONT TestGenerateFingerprint2501=== CONT TestNilKeyPublicKey2502=== CONT TestSignBatch2503=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002504=== RUN TestParseSigningKey/valid_32-byte_key2505=== PAUSE TestParseSigningKey/valid_32-byte_key2506=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2507=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2508=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2509=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2510=== RUN TestExternalSignerErrors/null_signatures2511=== PAUSE TestExternalSignerErrors/null_signatures2512=== RUN TestExternalSignerErrors/wrong_signature_name2513=== PAUSE TestExternalSignerErrors/wrong_signature_name2514=== RUN TestGenerateFingerprint/basic_with_references2515--- PASS: TestNilKeyPublicKey (0.00s)2516--- PASS: TestSign (0.00s)2517=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2518=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2519=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2520=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2521=== RUN TestExternalSignerErrors/invalid_signature_base642522=== PAUSE TestExternalSignerErrors/invalid_signature_base642523=== RUN TestExternalSignerErrors/exit_on_request2524=== PAUSE TestExternalSignerErrors/exit_on_request2525=== RUN TestExternalSignerErrors/null2526=== PAUSE TestExternalSignerErrors/null2527=== RUN TestExternalSignerErrors/wrong_id2528=== PAUSE TestGenerateFingerprint/basic_with_references2529=== RUN TestSignErrors/nil_key2530=== PAUSE TestSignErrors/nil_key2531=== RUN TestParseSigningKey/no_colon2532=== PAUSE TestParseSigningKey/no_colon2533=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2534=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2535=== CONT TestExternalSignerRejectsInvalidPublicKey/#002536=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2537--- PASS: TestSignBatch (0.00s)2538=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2539=== PAUSE TestExternalSignerErrors/wrong_id2540=== RUN TestGenerateFingerprint/no_references2541=== RUN TestSignErrors/nil_narinfo2542=== PAUSE TestSignErrors/nil_narinfo2543=== RUN TestSignErrors/invalid_narinfo2544=== PAUSE TestSignErrors/invalid_narinfo2545=== RUN TestSignErrors/canceled2546=== PAUSE TestSignErrors/canceled2547=== CONT TestSignErrors/nil_key2548=== CONT TestSignErrors/invalid_narinfo2549=== RUN TestParseSigningKey/empty_name2550=== CONT TestSignErrors/canceled2551=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2552=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2553--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2554 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2555 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2556 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2557 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2558 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2559=== RUN TestExternalSignerErrors/wrong_signatures_shape2560=== PAUSE TestGenerateFingerprint/no_references2561=== CONT TestSignErrors/nil_narinfo2562--- PASS: TestSignErrors (0.00s)2563 --- PASS: TestSignErrors/nil_key (0.00s)2564 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2565 --- PASS: TestSignErrors/canceled (0.00s)2566 --- PASS: TestSignErrors/nil_narinfo (0.00s)2567=== PAUSE TestParseSigningKey/empty_name2568=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2569=== RUN TestExternalSignerErrors/unrequested_key2570=== PAUSE TestExternalSignerErrors/unrequested_key2571=== RUN TestExternalSignerErrors/program_error2572=== PAUSE TestExternalSignerErrors/program_error2573=== RUN TestExternalSignerErrors/too_few_signatures2574=== PAUSE TestExternalSignerErrors/too_few_signatures2575=== RUN TestExternalSignerErrors/exit_at_startup2576=== PAUSE TestExternalSignerErrors/exit_at_startup2577=== RUN TestExternalSignerErrors/wrong_shape2578=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2579=== RUN TestParseSigningKey/invalid_base642580=== PAUSE TestParseSigningKey/invalid_base642581=== RUN TestParseSigningKey/wrong_length2582=== PAUSE TestParseSigningKey/wrong_length2583=== CONT TestParseSigningKey/valid_32-byte_key2584=== CONT TestParseSigningKey/empty_name2585=== PAUSE TestExternalSignerErrors/wrong_shape2586=== CONT TestParseSigningKey/no_colon2587=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2588=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2589=== CONT TestParseSigningKey/wrong_length2590=== CONT TestParseSigningKey/invalid_base642591=== RUN TestExternalSignerErrors/missing_signature_name2592=== PAUSE TestExternalSignerErrors/missing_signature_name2593=== RUN TestExternalSignerErrors/wrong_signature_length2594=== PAUSE TestExternalSignerErrors/wrong_signature_length2595=== RUN TestExternalSignerErrors/invalid_JSON2596=== PAUSE TestExternalSignerErrors/invalid_JSON2597=== RUN TestExternalSignerErrors/missing_signatures2598--- PASS: TestExternalSignerClose (0.00s)2599--- PASS: TestExternalSignerWrongPublicKey (0.00s)2600=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2601=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2602=== PAUSE TestExternalSignerErrors/missing_signatures2603=== CONT TestExternalSignerErrors/null_signatures2604=== CONT TestExternalSignerErrors/unrequested_key2605--- PASS: TestParseSigningKey (0.00s)2606 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2607 --- PASS: TestParseSigningKey/empty_name (0.00s)2608 --- PASS: TestParseSigningKey/no_colon (0.00s)2609 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2610 --- PASS: TestParseSigningKey/wrong_length (0.00s)2611 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2612--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.01s)2613=== CONT TestExternalSignerErrors/wrong_shape2614=== RUN TestGenerateFingerprint/invalid_nar_hash_length2615=== CONT TestExternalSignerErrors/program_error2616=== CONT TestExternalSignerErrors/missing_signatures2617=== CONT TestExternalSignerErrors/invalid_JSON2618=== CONT TestExternalSignerErrors/wrong_signature_length2619=== CONT TestExternalSignerErrors/null2620=== CONT TestExternalSignerErrors/missing_signature_name2621=== CONT TestExternalSignerErrors/exit_at_startup2622=== CONT TestExternalSignerErrors/too_few_signatures2623=== CONT TestExternalSignerErrors/wrong_signatures_shape2624=== CONT TestExternalSignerErrors/invalid_signature_base642625=== CONT TestExternalSignerErrors/wrong_signature_name2626=== CONT TestExternalSignerErrors/wrong_id2627=== CONT TestExternalSignerErrors/exit_on_request2628=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2629--- PASS: TestExternalSigner (0.01s)2630=== RUN TestGenerateFingerprint/invalid_store_path_prefix2631=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2632=== RUN TestGenerateFingerprint/invalid_reference_prefix2633=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2634=== CONT TestGenerateFingerprint/invalid_nar_hash_length2635=== CONT TestGenerateFingerprint/basic_with_references2636=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2637=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2638=== CONT TestGenerateFingerprint/no_references2639=== CONT TestGenerateFingerprint/invalid_reference_prefix2640=== CONT TestGenerateFingerprint/invalid_store_path_prefix2641--- PASS: TestGenerateFingerprint (0.01s)2642 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2643 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2644 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2645 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2646 --- PASS: TestGenerateFingerprint/no_references (0.00s)2647 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2648 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2649--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2650--- PASS: TestExternalSignerErrors (0.00s)2651 --- PASS: TestExternalSignerErrors/unrequested_key (0.00s)2652 --- PASS: TestExternalSignerErrors/exit_at_startup (0.00s)2653 --- PASS: TestExternalSignerErrors/program_error (0.00s)2654 --- PASS: TestExternalSignerErrors/null_signatures (0.00s)2655 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)2656 --- PASS: TestExternalSignerErrors/missing_signature_name (0.00s)2657 --- PASS: TestExternalSignerErrors/missing_signatures (0.01s)2658 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.00s)2659 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)2660 --- PASS: TestExternalSignerErrors/null (0.01s)2661 --- PASS: TestExternalSignerErrors/wrong_id (0.00s)2662 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2663 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)2664 --- PASS: TestExternalSignerErrors/exit_on_request (0.01s)2665 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)2666 --- PASS: TestExternalSignerErrors/too_few_signatures (0.01s)2667--- PASS: TestExternalSignerCancellation (0.02s)2668PASS2669Running OpenBao signer tests...2670=== RUN TestSign2671=== PAUSE TestSign2672=== RUN TestSignErrors2673=== PAUSE TestSignErrors2674=== RUN TestServe2675=== PAUSE TestServe2676=== RUN TestServeRejectsGarbage2677=== PAUSE TestServeRejectsGarbage2678=== CONT TestSign2679=== CONT TestServeRejectsGarbage2680=== CONT TestSignErrors2681--- PASS: TestServeRejectsGarbage (0.00s)2682=== CONT TestServe2683=== RUN TestSignErrors/http_error2684=== PAUSE TestSignErrors/http_error2685=== RUN TestSignErrors/invalid_json2686=== PAUSE TestSignErrors/invalid_json2687=== RUN TestSignErrors/no_prefix2688=== PAUSE TestSignErrors/no_prefix2689=== RUN TestSignErrors/invalid_base642690=== PAUSE TestSignErrors/invalid_base642691=== CONT TestSignErrors/http_error2692=== CONT TestSignErrors/no_prefix2693=== CONT TestSignErrors/invalid_json2694--- PASS: TestServe (0.00s)2695=== CONT TestSignErrors/invalid_base642696--- PASS: TestSignErrors (0.00s)2697 --- PASS: TestSignErrors/no_prefix (0.00s)2698 --- PASS: TestSignErrors/http_error (0.00s)2699 --- PASS: TestSignErrors/invalid_json (0.00s)2700 --- PASS: TestSignErrors/invalid_base64 (0.00s)2701--- PASS: TestSign (0.01s)2702PASS