niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #354
· raw
1tribuchet: building on eliza2Running 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.03s)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 TestScriptTokenEmptyCommand102=== CONT TestSetClientTLSDoesNotMutateDefaultTransport103--- PASS: TestScriptTokenEmptyCommand (0.00s)104=== CONT TestConvertHashToNix32105=== RUN TestConvertHashToNix32/SRI_format_to_Nix32106=== CONT TestFileTokenEmpty107=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32108=== RUN TestConvertHashToNix32/already_Nix32_format109=== PAUSE TestConvertHashToNix32/already_Nix32_format110=== RUN TestConvertHashToNix32/invalid_format111=== PAUSE TestConvertHashToNix32/invalid_format112=== CONT TestDumpPathWriterError113=== CONT TestFileTokenMissing114=== CONT TestFileTokenReadsAndCaches115=== CONT TestStaticToken116--- PASS: TestStaticToken (0.00s)117=== CONT TestSetClientTLSErrors118=== CONT TestEncodeNixBase32119=== CONT TestResolveStorePath120=== CONT TestScriptTokenNoExpiryRerunsEveryCall121=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess122=== CONT TestRateLimiterFeedback123=== CONT TestScriptTokenScriptFails124=== CONT TestPathInfoCACompatibility125=== CONT TestScriptTokenBadJSON126=== CONT TestParsePathInfoJSONMultiplePaths127=== CONT TestScriptTokenEmptyToken128=== CONT TestParsePathInfoJSON129=== CONT TestScriptTokenCachesUntilRefresh130=== CONT TestPathInfoHashCompatibility131=== CONT TestGetStorePathHash132=== CONT TestUploadMultipart_PartsInParallel133=== CONT TestEncodeNixBase32WithRealHash134=== CONT TestDumpPathSingleFile135--- PASS: TestFileTokenEmpty (0.00s)136=== RUN TestEncodeNixBase32/test_string_hash137=== PAUSE TestEncodeNixBase32/test_string_hash138=== RUN TestEncodeNixBase32/empty_input139=== PAUSE TestEncodeNixBase32/empty_input140--- PASS: TestFileTokenMissing (0.00s)141--- PASS: TestFileTokenReadsAndCaches (0.00s)142--- PASS: TestResolveStorePath (0.00s)143=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun144=== RUN TestGetStorePathHash/valid_store_path145=== PAUSE TestGetStorePathHash/valid_store_path146=== CONT TestUploadMultipart_SupersededByPeer147=== RUN TestUploadMultipart_SupersededByPeer/exists148=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)149=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)150=== RUN TestPathInfoCACompatibility/null_ca_field151=== PAUSE TestPathInfoCACompatibility/null_ca_field1522026/10/04 20:03:44 WARN Rate limiter enabled after throttle name=server-test rate=5153=== RUN TestGetStorePathHash/basename_without_hyphen_should_error154=== RUN TestRateLimiterFeedback/429_enables_limiter155=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon156=== PAUSE TestUploadMultipart_SupersededByPeer/exists1572026/10/04 20:03:44 WARN Rate limiter enabled after throttle name=server-test rate=5158=== CONT TestDumpPathMatchesNix159=== RUN TestUploadMultipart_SupersededByPeer/missing160=== PAUSE TestUploadMultipart_SupersededByPeer/missing161=== CONT TestStreamPushReportsEveryPath162--- PASS: TestEncodeNixBase32WithRealHash (0.00s)163--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)164=== CONT TestFilterOversizedClosures1652026/10/04 20:03:44 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:41825166=== RUN TestParsePathInfoJSON/Nix_format167=== CONT TestPartSizeForNAR168=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths169=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon170=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI171=== CONT TestCaseHackSuffix172=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error173=== RUN TestPathInfoCACompatibility/old_string_format_-_text174=== PAUSE TestParsePathInfoJSON/Nix_format175=== PAUSE TestRateLimiterFeedback/429_enables_limiter176--- PASS: TestScriptTokenEmptyToken (0.00s)177=== CONT TestStreamPushIsolatesFailures178=== CONT TestClientSignaturesByStorePath179=== RUN TestFilterOversizedClosures/no_limit_keeps_everything180=== RUN TestPartSizeForNAR/zero_stays_at_minimum181=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica182=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths183=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI184=== RUN TestSetClientTLSErrors/missing_cert_file185=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text186=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths187=== PAUSE TestSetClientTLSErrors/missing_cert_file188=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths189=== CONT TestStreamPushBatchesUnderLoad1902026/10/04 20:03:44 ERROR Upload failed error="bad path" count=3191=== CONT TestSetClientTLS1922026/10/04 20:03:44 WARN Rate limiter backed off name=server-test rate=5193=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error1942026/10/04 20:03:44 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:41825195=== RUN TestSetClientTLSErrors/missing_key_file196=== CONT TestStreamPushRequestLine197=== CONT TestRegisterUploadedObjectReusesConnections198=== CONT TestStreamPushReportsSignatures1992026/10/04 20:03:44 ERROR Upload failed error=boom count=1200--- PASS: TestScriptTokenScriptFails (0.01s)201--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.01s)202--- PASS: TestClientSignaturesByStorePath (0.00s)203--- PASS: TestScriptTokenBadJSON (0.03s)204--- PASS: TestStreamPushReportsEveryPath (0.03s)205--- PASS: TestStreamPushIsolatesFailures (0.00s)206--- PASS: TestDoServerRequestAttachesToken (0.03s)2072026/10/04 20:03:44 INFO Garbage collection started208--- PASS: TestDumpPathSingleFile (0.03s)209=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything2102026/10/04 20:03:44 INFO Garbage collection started211=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2122026/10/04 20:03:44 ERROR Upload failed error=boom count=1213=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped214=== RUN TestFilterOversizedClosures/all_closures_skipped215=== PAUSE TestFilterOversizedClosures/all_closures_skipped216=== RUN TestParsePathInfoJSON/Lix_format217=== PAUSE TestParsePathInfoJSON/Lix_format218=== RUN TestParsePathInfoJSON/empty_input219=== PAUSE TestParsePathInfoJSON/empty_input220=== RUN TestParsePathInfoJSON/whitespace_only221=== PAUSE TestParsePathInfoJSON/whitespace_only222=== RUN TestParsePathInfoJSON/invalid_JSON223=== PAUSE TestParsePathInfoJSON/invalid_JSON224--- PASS: TestStreamPushReportsSignatures (0.00s)225--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.04s)226=== CONT TestConvertHashToNix32/SRI_format_to_Nix32227=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive228=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive229=== RUN TestPathInfoCACompatibility/new_structured_format_-_text230=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text231=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method232=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method233=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum234=== RUN TestPartSizeForNAR/small_stays_at_minimum235=== PAUSE TestPartSizeForNAR/small_stays_at_minimum236=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum237=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum238=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts239=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts240=== RUN TestPartSizeForNAR/1_TiB241=== PAUSE TestPartSizeForNAR/1_TiB242=== RUN TestPartSizeForNAR/5_TiB_S3_max_object243=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object244=== CONT TestConvertHashToNix32/invalid_format245=== CONT TestUploadMultipart_SupersededByPeer/exists246=== CONT TestEncodeNixBase32/test_string_hash247=== CONT TestShellSplitErrors248--- PASS: TestShellSplitErrors (0.00s)249=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths250=== CONT TestUploadMultipart_SupersededByPeer/missing251=== CONT TestShellSplit252--- PASS: TestShellSplit (0.00s)253=== CONT TestFilterOversizedClosures/no_limit_keeps_everything254=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error255=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error256=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error257=== CONT TestParsePathInfoJSON/Nix_format258=== PAUSE TestSetClientTLSErrors/missing_key_file259=== RUN TestSetClientTLSErrors/missing_ca_file260=== PAUSE TestSetClientTLSErrors/missing_ca_file261=== RUN TestSetClientTLSErrors/invalid_ca_file262=== RUN TestSetClientTLS/rejects_connection_without_client_cert263=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert264=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA265=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA266=== RUN TestSetClientTLS/preserves_debug_logging_transport267=== PAUSE TestSetClientTLS/preserves_debug_logging_transport268=== PAUSE TestSetClientTLSErrors/invalid_ca_file269=== CONT TestParsePathInfoJSON/empty_input2702026/10/04 20:03:44 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=0271=== CONT TestParsePathInfoJSON/whitespace_only272=== CONT TestPathInfoCACompatibility/null_ca_field273=== CONT TestConvertHashToNix32/already_Nix32_format274--- PASS: TestConvertHashToNix32 (0.00s)275 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)276 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)277 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)278=== CONT TestParsePathInfoJSON/invalid_JSON279=== CONT TestPathInfoCACompatibility/new_structured_format_-_text280=== CONT TestPathInfoCACompatibility/old_string_format_-_text281=== CONT TestGetStorePathHash/valid_store_path282=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error283=== CONT TestParsePathInfoJSON/Lix_format284=== CONT TestSetClientTLS/rejects_connection_without_client_cert285--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.03s)286=== CONT TestGetStorePathHash/basename_without_hyphen_should_error287=== CONT TestSetClientTLSErrors/missing_cert_file288--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)289 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)290 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)291=== CONT TestSetClientTLS/preserves_debug_logging_transport2922026/10/04 20:03:44 WARN Garbage collection finished on another replica; its statistics are not available here293--- PASS: TestParsePathInfoJSON (0.03s)294 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)295 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)296 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)297 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)298 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)299--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.00s)300=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA301=== CONT TestSetClientTLSErrors/missing_ca_file302=== CONT TestEncodeNixBase32/empty_input303--- PASS: TestEncodeNixBase32 (0.00s)304 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)305 --- PASS: TestEncodeNixBase32/empty_input (0.00s)306=== CONT TestFilterOversizedClosures/all_closures_skipped307=== CONT TestSetClientTLSErrors/missing_key_file308=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths309=== CONT TestStreamPushGivesUpOnDeadServer3102026/10/04 20:03:44 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50311=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive312=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error313=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512314=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method315=== RUN TestPartSizeForNAR/capped_at_5_GiB316=== RUN TestRateLimiterFeedback/503_enables_limiter317=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped318=== CONT TestSetClientTLSErrors/invalid_ca_file319=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512320=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)321--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)322--- PASS: TestParsePathInfoJSONMultiplePaths (0.03s)323 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)324 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)325=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512326=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI3272026/10/04 20:03:44 ERROR Upload failed error="connection refused" count=203282026/10/04 20:03:44 ERROR Server seems unavailable, giving up on batch untried=17329=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon330--- PASS: TestPathInfoHashCompatibility (0.03s)331 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)332 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)333 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)334 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)335--- PASS: TestGetStorePathHash (0.03s)336 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)337 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)338 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)339 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)340--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)341--- PASS: TestSetClientTLSErrors (0.04s)342 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)343 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)344 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)345 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)346=== PAUSE TestPartSizeForNAR/capped_at_5_GiB347=== PAUSE TestRateLimiterFeedback/503_enables_limiter3482026/10/04 20:03:44 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=2000349=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter350=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts351--- PASS: TestPathInfoCACompatibility (0.03s)352 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)353 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)354 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)355 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)356 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)357--- PASS: TestFilterOversizedClosures (0.03s)358 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)359 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)360 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)361=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum362=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter363=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter364=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter365=== CONT TestRateLimiterFeedback/429_enables_limiter366=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter367=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter368=== CONT TestPartSizeForNAR/1_TiB369=== CONT TestPartSizeForNAR/capped_at_5_GiB370=== CONT TestPartSizeForNAR/5_TiB_S3_max_object371=== CONT TestPartSizeForNAR/zero_stays_at_minimum372=== CONT TestPartSizeForNAR/small_stays_at_minimum373--- PASS: TestPartSizeForNAR (0.03s)374 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)375 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)376 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)377 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)378 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)379 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)380 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)381=== CONT TestRateLimiterFeedback/503_enables_limiter3822026/10/04 20:03:44 WARN Rate limiter enabled after throttle name=server-test rate=53832026/10/04 20:03:44 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:406773842026/10/04 20:03:44 WARN Rate limiter backed off name=server-test rate=53852026/10/04 20:03:44 WARN Rate limiter enabled after throttle name=server-test rate=53862026/10/04 20:03:44 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:431573872026/10/04 20:03:44 WARN Rate limiter backed off name=server-test rate=5388--- PASS: TestRateLimiterFeedback (0.04s)389 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)390 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)391 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)392 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)3932026/10/04 20:03:44 http: TLS handshake error from 127.0.0.1:35736: remote error: tls: bad certificate394--- PASS: TestSetClientTLS (0.00s)395 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)396 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)397 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)398--- PASS: TestRegisterUploadedObjectReusesConnections (0.02s)399--- PASS: TestDumpPathWriterError (0.06s)400--- PASS: TestStreamPushRequestLine (0.02s)401--- PASS: TestCaseHackSuffix (0.03s)402--- PASS: TestDumpPathMatchesNix (0.10s)403--- PASS: TestStreamPushBatchesUnderLoad (0.10s)404--- PASS: TestUploadMultipart_PartsInParallel (0.65s)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/postgres150654619/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/postgres150654619/data -l logfile start434435/build/postgres150654619:5432 - no response4362026-10-04 20:03:46.619 UTC [128] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit4372026-10-04 20:03:46.619 UTC [128] LOG: listening on Unix socket "/build/postgres150654619/.s.PGSQL.5432"4382026-10-04 20:03:46.623 UTC [135] LOG: database system was shut down at 2026-10-04 20:03:46 UTC4392026-10-04 20:03:46.627 UTC [128] LOG: database system is ready to accept connections440/build/postgres150654619: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 TestConcurrentCommitsSharingObjectsDoNotDeadlock478=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock479=== RUN TestResolveDBConnectionString480=== PAUSE TestResolveDBConnectionString481=== RUN TestConnectWaitsForAPeerMigration482=== PAUSE TestConnectWaitsForAPeerMigration483=== RUN TestLeadElectsOneAndHandsOver484=== PAUSE TestLeadElectsOneAndHandsOver485=== RUN TestLeadIncumbentWinsAfterRestart4862026/10/04 20:03:47 INFO lead: acquired remote=192.0.2.1:12344872026/10/04 20:03:48 INFO lead: released remote=192.0.2.1:12344882026/10/04 20:03:48 INFO lead: acquired remote=192.0.2.1:12344892026/10/04 20:03:49 INFO lead: released remote=192.0.2.1:1234490--- PASS: TestLeadIncumbentWinsAfterRestart (2.33s)491=== RUN TestLeadEndsOnShutdown492=== PAUSE TestLeadEndsOnShutdown493=== RUN TestLeadEndsWhenItsConnectionHangs4942026/10/04 20:03:49 INFO lead: acquired remote=192.0.2.1:12344952026-10-04 20:03:50.759 UTC [383] FATAL: terminating connection due to administrator command4962026/10/04 20:03:50 INFO lead: acquired remote=192.0.2.1:12344972026/10/04 20:03:51 WARN lead: lock connection lost error="timeout: context deadline exceeded"4982026/10/04 20:03:51 INFO lead: released remote=192.0.2.1:12344992026/10/04 20:03:52 INFO lead: released remote=192.0.2.1:1234500--- PASS: TestLeadEndsWhenItsConnectionHangs (2.91s)501=== RUN TestGCAdvisoryLockBlocksConcurrentRun502=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun503=== RUN TestGCBugBareHashReferences504=== PAUSE TestGCBugBareHashReferences505=== RUN TestGCMetrics506=== PAUSE TestGCMetrics507=== RUN TestPushDedupSurvivesConcurrentGC508=== PAUSE TestPushDedupSurvivesConcurrentGC509=== RUN TestDeduplicatedObjectsRecordedAsPending510=== PAUSE TestDeduplicatedObjectsRecordedAsPending511=== RUN TestGCSweepSkipsPendingObjects512=== PAUSE TestGCSweepSkipsPendingObjects513=== RUN TestTombstonedObjectOfferedWithoutWaiting514=== PAUSE TestTombstonedObjectOfferedWithoutWaiting515=== RUN TestGCSweepDeliversEachKeyOnce516=== PAUSE TestGCSweepDeliversEachKeyOnce517=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection518=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection519=== RUN TestForceGCDuringPushOffersSweptObject520=== PAUSE TestForceGCDuringPushOffersSweptObject521=== RUN TestFailedS3DeleteKeepsTombstone522=== PAUSE TestFailedS3DeleteKeepsTombstone523=== RUN TestSweepSkipsRowsLockedByPush524=== PAUSE TestSweepSkipsRowsLockedByPush525=== RUN TestRegisterCompletedObjectNeedsPendingRow526=== PAUSE TestRegisterCompletedObjectNeedsPendingRow527=== RUN TestGetExistingObjectsLocksRows528=== PAUSE TestGetExistingObjectsLocksRows529=== RUN TestSweepRechecksPendingAfterLocking530=== PAUSE TestSweepRechecksPendingAfterLocking531=== RUN TestPushWaitsForSweepHoldingRow532=== PAUSE TestPushWaitsForSweepHoldingRow533=== RUN TestCommitRacingPendingCleanupKeepsObjects534=== PAUSE TestCommitRacingPendingCleanupKeepsObjects535=== RUN TestGCEndsOnShutdown536=== PAUSE TestGCEndsOnShutdown537=== RUN TestGCTaskStore_StartNew538=== PAUSE TestGCTaskStore_StartNew539=== RUN TestGCTaskStore_DeduplicateSameParams540=== PAUSE TestGCTaskStore_DeduplicateSameParams541=== RUN TestGCTaskStore_ConflictDifferentParams542=== PAUSE TestGCTaskStore_ConflictDifferentParams543=== RUN TestGCTaskStore_GetEmpty544=== PAUSE TestGCTaskStore_GetEmpty545=== RUN TestGCTaskStore_GetReturnsLatest546=== PAUSE TestGCTaskStore_GetReturnsLatest547=== RUN TestGCTaskStore_CompletedAllowsNewTask548=== PAUSE TestGCTaskStore_CompletedAllowsNewTask549=== RUN TestGCTaskStore_PhaseUpdates550=== PAUSE TestGCTaskStore_PhaseUpdates551=== RUN TestGCTaskStore_Fail552=== PAUSE TestGCTaskStore_Fail553=== RUN TestGracefulShutdownDrainsInflight554=== PAUSE TestGracefulShutdownDrainsInflight555=== RUN TestService_healthCheckHandler556=== PAUSE TestService_healthCheckHandler557=== RUN TestService_readinessHandler558=== PAUSE TestService_readinessHandler559=== RUN TestGenerateLandingPage560=== PAUSE TestGenerateLandingPage561=== RUN TestCacheConfigHandlerMaxNarSize562=== PAUSE TestCacheConfigHandlerMaxNarSize563=== RUN TestCreatePendingClosureRejectsOversizedNAR564=== PAUSE TestCreatePendingClosureRejectsOversizedNAR565=== RUN TestNARDeduplicationMetadataUploadBug566=== PAUSE TestNARDeduplicationMetadataUploadBug567=== RUN TestMetricsInventory568=== PAUSE TestMetricsInventory569=== RUN TestService_NativeMTLS570=== PAUSE TestService_NativeMTLS571=== RUN TestServerTLSConfig572=== PAUSE TestServerTLSConfig573=== RUN TestMultipartCleanup574=== PAUSE TestMultipartCleanup575=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded576=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded577=== RUN TestPendingCleanupUsesOneCutoff578=== PAUSE TestPendingCleanupUsesOneCutoff579=== RUN TestObjectStatsTrigger580=== PAUSE TestObjectStatsTrigger581=== RUN TestOrphanedObjectsGC582=== PAUSE TestOrphanedObjectsGC583=== RUN TestOrphanedObjectsGCStressTest584=== PAUSE TestOrphanedObjectsGCStressTest585=== RUN TestCreatePin_ReservedPins586=== PAUSE TestCreatePin_ReservedPins587=== RUN TestPresentReportsOnlyClosureRoots588=== PAUSE TestPresentReportsOnlyClosureRoots589=== RUN TestPresentNotReportedWhileGCDeletesClosure590=== PAUSE TestPresentNotReportedWhileGCDeletesClosure591=== RUN TestParseSingleRange592=== PAUSE TestParseSingleRange593=== RUN TestProxyHeadersOnlyTrustedOnSocket594=== PAUSE TestProxyHeadersOnlyTrustedOnSocket595=== RUN TestIsValidCachePath596=== PAUSE TestIsValidCachePath597=== RUN TestReadProxyNarinfo598=== PAUSE TestReadProxyNarinfo599=== RUN TestReadProxyNarinfoAlreadyDecompressed600=== PAUSE TestReadProxyNarinfoAlreadyDecompressed601=== RUN TestReadProxyNarStreaming602=== PAUSE TestReadProxyNarStreaming603=== RUN TestReadProxy404604=== PAUSE TestReadProxy404605=== RUN TestReadProxyInvalidPath606=== PAUSE TestReadProxyInvalidPath607=== RUN TestReadProxyHead608=== PAUSE TestReadProxyHead609=== RUN TestReadProxyOutlastsServerWriteTimeout610=== PAUSE TestReadProxyOutlastsServerWriteTimeout611=== RUN TestReadProxyConditionalGet612=== PAUSE TestReadProxyConditionalGet613=== RUN TestReadProxyRootRedirectsToIndexHTML614=== PAUSE TestReadProxyRootRedirectsToIndexHTML615=== RUN TestReadProxyDisabled616=== PAUSE TestReadProxyDisabled617=== RUN TestReadRedirectNar618=== PAUSE TestReadRedirectNar619=== RUN TestReadRedirectKeepsNarinfoProxied620=== PAUSE TestReadRedirectKeepsNarinfoProxied621=== RUN TestReadProxyRangeRequest622=== PAUSE TestReadProxyRangeRequest623=== RUN TestReadRedirectUsesPublicS3URL624=== PAUSE TestReadRedirectUsesPublicS3URL625=== RUN TestPush_OverlappingRootsStoreOneRowPerKey626=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey627=== RUN TestPush_CompleteCommitsEveryRoot628=== PAUSE TestPush_CompleteCommitsEveryRoot629=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit630=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit631=== RUN TestPush_RejectsBadRequests632=== PAUSE TestPush_RejectsBadRequests633=== RUN TestPush_SignsNarinfosOfItsPendingObjects634=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects635=== RUN TestRedundantMultipartUpload636=== PAUSE TestRedundantMultipartUpload637=== RUN TestCompleteMultipartUpload_ErrorButObjectExists638=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists639=== RUN TestCompletedNarNotReofferedAcrossClosures640=== PAUSE TestCompletedNarNotReofferedAcrossClosures641=== RUN TestPresignedUploadRegisteredBeforeCommit642=== PAUSE TestPresignedUploadRegisteredBeforeCommit643=== RUN TestService_Rustfstest644=== PAUSE TestService_Rustfstest645=== RUN TestParseSize646=== PAUSE TestParseSize647=== RUN TestSkippedUploadsHandler648=== PAUSE TestSkippedUploadsHandler649=== RUN TestSystemdListenerNotActivated650--- PASS: TestSystemdListenerNotActivated (0.00s)651=== RUN TestWatchdogBeatsWhenHealthy652--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)653=== RUN TestWatchdogSkipsWhenUnhealthy6542026/10/04 20:03:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6552026/10/04 20:03:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6562026/10/04 20:03:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6572026/10/04 20:03:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6582026/10/04 20:03:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6592026/10/04 20:03:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6602026/10/04 20:03:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6612026/10/04 20:03:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6622026/10/04 20:03:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6632026/10/04 20:03:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"664--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)665=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle666=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle667=== RUN TestProxyWriteTimeout668=== PAUSE TestProxyWriteTimeout669=== RUN TestPendingClosureWriteTimeout670=== PAUSE TestPendingClosureWriteTimeout671=== RUN TestIsValidUploadKey672=== PAUSE TestIsValidUploadKey673=== RUN TestUploadHandlersRejectInvalidKeys674=== PAUSE TestUploadHandlersRejectInvalidKeys675=== RUN TestUploadHandlersRejectOversizedBody676=== PAUSE TestUploadHandlersRejectOversizedBody677=== RUN TestService_cleanupPendingClosuresHandler678=== PAUSE TestService_cleanupPendingClosuresHandler679=== RUN TestService_createPendingClosureHandler680=== PAUSE TestService_createPendingClosureHandler681=== RUN TestService_verifyS3Integrity682=== PAUSE TestService_verifyS3Integrity683=== RUN TestCompleteMultipartUnregistered684=== PAUSE TestCompleteMultipartUnregistered685=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT686=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT687=== CONT TestSkippedUploadsHandler688=== CONT TestService_AuthMiddleware689=== CONT TestParseSize690--- PASS: TestParseSize (0.00s)691=== CONT TestService_Rustfstest692=== CONT TestService_verifyS3Integrity6932026/10/04 20:03:52 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000694=== CONT TestPresignedUploadRegisteredBeforeCommit695=== CONT TestCompletedNarNotReofferedAcrossClosures696=== CONT TestCompleteMultipartUpload_ErrorButObjectExists697=== CONT TestRedundantMultipartUpload698=== CONT TestPush_SignsNarinfosOfItsPendingObjects699=== CONT TestPush_RejectsBadRequests700=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit701=== CONT TestPush_CompleteCommitsEveryRoot702=== CONT TestPush_OverlappingRootsStoreOneRowPerKey703=== CONT TestReadRedirectUsesPublicS3URL704=== CONT TestReadProxyRangeRequest705=== CONT TestReadRedirectKeepsNarinfoProxied706=== CONT TestReadRedirectNar707=== CONT TestReadProxyDisabled708=== CONT TestReadProxyRootRedirectsToIndexHTML709=== CONT TestUploadHandlersRejectOversizedBody710=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT711=== CONT TestReadProxyConditionalGet712=== CONT TestCompleteMultipartUnregistered713=== CONT TestReadProxyOutlastsServerWriteTimeout714--- PASS: TestSkippedUploadsHandler (0.01s)715=== CONT TestReadProxyHead716=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure717=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure718=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart719=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart720=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts721=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts722=== CONT TestService_createPendingClosureHandler723--- PASS: TestService_Rustfstest (0.24s)724=== CONT TestReadProxyInvalidPath7252026/10/04 20:03:52 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"726--- PASS: TestService_AuthMiddleware (0.26s)727=== CONT TestService_cleanupPendingClosuresHandler7282026/10/04 20:03:52 INFO Received uploads request method=POST path=/api/pending_closures7292026/10/04 20:03:52 INFO Received uploads request method=POST path=/api/pending_closures7302026/10/04 20:03:52 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst7312026/10/04 20:03:52 INFO Received uploads request method=POST path=/api/pending_closures732--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.31s)733=== CONT TestReadProxy4047342026/10/04 20:03:52 INFO Received uploads request method=POST path=/api/pending_closures7352026/10/04 20:03:52 INFO Received push request method=POST path=/api/pushes7362026/10/04 20:03:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7372026/10/04 20:03:52 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjViYjYwN2EtNTE1NS00YjRhLTkyOWUtNWMzZjRkMjQ1OGI3LmZmNjhmNTI1LWUzZGEtNGUyMy1iYWYzLTBlYzQ5NzExZjJiNXgxNzkxMTQ0MjMyNzEzMzU4Mjgy7382026/10/04 20:03:52 INFO Received complete push request method=POST path=/api/pushes/1/complete7392026/10/04 20:03:52 INFO Received uploads request method=POST path=/api/pending_closures7402026/10/04 20:03:52 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjViYjYwN2EtNTE1NS00YjRhLTkyOWUtNWMzZjRkMjQ1OGI3LmZmNjhmNTI1LWUzZGEtNGUyMy1iYWYzLTBlYzQ5NzExZjJiNXgxNzkxMTQ0MjMyNzEzMzU4Mjgy parts=1741--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.36s)742=== CONT TestReadProxyNarStreaming743--- PASS: TestPush_CompleteCommitsEveryRoot (0.36s)744=== CONT TestPendingClosureWriteTimeout745=== RUN TestPendingClosureWriteTimeout/empty746=== PAUSE TestPendingClosureWriteTimeout/empty747=== RUN TestPendingClosureWriteTimeout/400_objects748=== PAUSE TestPendingClosureWriteTimeout/400_objects749=== RUN TestPendingClosureWriteTimeout/670k_objects750=== PAUSE TestPendingClosureWriteTimeout/670k_objects751=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline752=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline753=== CONT TestReadProxyNarinfoAlreadyDecompressed7542026/10/04 20:03:52 INFO Received uploads request method=POST path=/api/pending_closures7552026/10/04 20:03:52 INFO Received uploads request method=POST path=/api/pending_closures7562026/10/04 20:03:52 INFO Received push request method=POST path=/api/pushes757=== RUN TestPush_RejectsBadRequests/root_not_in_objects758=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects759=== RUN TestPush_RejectsBadRequests/no_roots760=== PAUSE TestPush_RejectsBadRequests/no_roots761=== RUN TestPush_RejectsBadRequests/no_objects762=== PAUSE TestPush_RejectsBadRequests/no_objects763=== RUN TestPush_RejectsBadRequests/bad_root764=== PAUSE TestPush_RejectsBadRequests/bad_root765=== CONT TestUploadHandlersRejectInvalidKeys766=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info767=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info768=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal769=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal770=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key771=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key772=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key773=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key774=== CONT TestReadProxyNarinfo775--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.42s)776=== CONT TestIsValidUploadKey777=== RUN TestIsValidUploadKey/narinfo778=== PAUSE TestIsValidUploadKey/narinfo779=== RUN TestIsValidUploadKey/nar_zst780=== PAUSE TestIsValidUploadKey/nar_zst781=== RUN TestIsValidUploadKey/nar_xz782=== PAUSE TestIsValidUploadKey/nar_xz783=== RUN TestIsValidUploadKey/nar_plain784=== PAUSE TestIsValidUploadKey/nar_plain785=== RUN TestIsValidUploadKey/listing786=== PAUSE TestIsValidUploadKey/listing787=== RUN TestIsValidUploadKey/build_log788=== PAUSE TestIsValidUploadKey/build_log789=== RUN TestIsValidUploadKey/build_log_home-manager_file790=== PAUSE TestIsValidUploadKey/build_log_home-manager_file791=== RUN TestIsValidUploadKey/build_log_plus_in_name792=== PAUSE TestIsValidUploadKey/build_log_plus_in_name793=== RUN TestIsValidUploadKey/build_log_question_mark794=== PAUSE TestIsValidUploadKey/build_log_question_mark795=== RUN TestIsValidUploadKey/build_log_equals796=== PAUSE TestIsValidUploadKey/build_log_equals797=== RUN TestIsValidUploadKey/realisation798=== PAUSE TestIsValidUploadKey/realisation799=== RUN TestIsValidUploadKey/realisation_plus_in_output800=== PAUSE TestIsValidUploadKey/realisation_plus_in_output801=== RUN TestIsValidUploadKey/nix-cache-info802=== PAUSE TestIsValidUploadKey/nix-cache-info803=== RUN TestIsValidUploadKey/index.html804=== PAUSE TestIsValidUploadKey/index.html805=== RUN TestIsValidUploadKey/narinfo_key,_nar_type806=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type807=== RUN TestIsValidUploadKey/nar_key,_narinfo_type808=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type809=== RUN TestIsValidUploadKey/listing_key,_narinfo_type810=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type811=== RUN TestIsValidUploadKey/traversal812=== PAUSE TestIsValidUploadKey/traversal813=== RUN TestIsValidUploadKey/traversal_nar814=== PAUSE TestIsValidUploadKey/traversal_nar815=== RUN TestIsValidUploadKey/absolute816=== PAUSE TestIsValidUploadKey/absolute817=== RUN TestIsValidUploadKey/empty_key818=== PAUSE TestIsValidUploadKey/empty_key819=== RUN TestIsValidUploadKey/unknown_type820=== PAUSE TestIsValidUploadKey/unknown_type821=== CONT TestIsValidCachePath822=== RUN TestIsValidCachePath/narinfo823=== PAUSE TestIsValidCachePath/narinfo824=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars825=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars826=== RUN TestIsValidCachePath/nar_zst827=== PAUSE TestIsValidCachePath/nar_zst828=== RUN TestIsValidCachePath/nar_xz829=== PAUSE TestIsValidCachePath/nar_xz830=== RUN TestIsValidCachePath/nar_bz2831=== PAUSE TestIsValidCachePath/nar_bz2832=== RUN TestIsValidCachePath/nar_uncompressed833=== PAUSE TestIsValidCachePath/nar_uncompressed834=== RUN TestIsValidCachePath/ls835=== PAUSE TestIsValidCachePath/ls836=== RUN TestIsValidCachePath/log837=== PAUSE TestIsValidCachePath/log838=== RUN TestIsValidCachePath/realisation839=== PAUSE TestIsValidCachePath/realisation840=== RUN TestIsValidCachePath/nix-cache-info841=== PAUSE TestIsValidCachePath/nix-cache-info842=== RUN TestIsValidCachePath/index.html843=== PAUSE TestIsValidCachePath/index.html844=== RUN TestIsValidCachePath/traversal_parent845=== PAUSE TestIsValidCachePath/traversal_parent846=== RUN TestIsValidCachePath/traversal_in_middle847=== PAUSE TestIsValidCachePath/traversal_in_middle848=== RUN TestIsValidCachePath/invalid_char_e849=== PAUSE TestIsValidCachePath/invalid_char_e850=== RUN TestIsValidCachePath/invalid_char_u851=== PAUSE TestIsValidCachePath/invalid_char_u852=== RUN TestIsValidCachePath/random_path853=== PAUSE TestIsValidCachePath/random_path854=== RUN TestIsValidCachePath/empty855=== PAUSE TestIsValidCachePath/empty856=== RUN TestIsValidCachePath/leading_slash857=== PAUSE TestIsValidCachePath/leading_slash858=== RUN TestIsValidCachePath/wrong_extension859=== PAUSE TestIsValidCachePath/wrong_extension860=== RUN TestIsValidCachePath/short_hash861=== PAUSE TestIsValidCachePath/short_hash862=== CONT TestClientFallsBackToClosures8632026/10/04 20:03:52 INFO Received push request method=POST path=/api/pushes8642026/10/04 20:03:52 INFO Received complete push request method=POST path=/api/pushes/1/complete8652026/10/04 20:03:52 INFO Received uploads request method=POST path=/api/pending_closures8662026/10/04 20:03:52 INFO Received push request method=POST path=/api/pushes867--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.48s)868=== CONT TestClientPushesUseOnePush8692026/10/04 20:03:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8702026/10/04 20:03:52 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst871--- PASS: TestCompleteMultipartUnregistered (0.49s)872=== CONT TestRegisterCompletedObjectNeedsPendingRow873--- PASS: TestReadRedirectUsesPublicS3URL (0.53s)874=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock8752026/10/04 20:03:52 INFO Aborted multipart uploads count=0 kept=0876--- PASS: TestReadProxyHead (0.54s)877=== CONT TestProxyHeadersOnlyTrustedOnSocket8782026/10/04 20:03:52 WARN Force mode enabled - objects will be deleted immediately without grace period8792026/10/04 20:03:52 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=08802026/10/04 20:03:52 INFO Vacuumed table table=pending_closures8812026/10/04 20:03:52 INFO Vacuumed table table=pending_objects882--- PASS: TestReadProxyRangeRequest (0.56s)883=== CONT TestPinProtectsFromGC8842026/10/04 20:03:52 INFO Vacuumed table table=multipart_uploads8852026/10/04 20:03:52 INFO Vacuumed table table=closures8862026/10/04 20:03:52 INFO Vacuumed table table=objects8872026/10/04 20:03:52 INFO Received complete push request method=POST path=/api/pushes/2/complete888--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.57s)889=== CONT TestParseSingleRange890=== RUN TestParseSingleRange/none891=== PAUSE TestParseSingleRange/none892=== RUN TestParseSingleRange/unknown_unit893=== PAUSE TestParseSingleRange/unknown_unit894=== RUN TestParseSingleRange/multi-range_ignored895=== PAUSE TestParseSingleRange/multi-range_ignored896=== RUN TestParseSingleRange/malformed_no_dash897=== PAUSE TestParseSingleRange/malformed_no_dash898=== RUN TestParseSingleRange/malformed_both_empty899=== PAUSE TestParseSingleRange/malformed_both_empty900=== RUN TestParseSingleRange/malformed_end_before_start901=== PAUSE TestParseSingleRange/malformed_end_before_start902=== RUN TestParseSingleRange/closed903=== PAUSE TestParseSingleRange/closed904=== RUN TestParseSingleRange/open-ended905=== PAUSE TestParseSingleRange/open-ended906=== RUN TestParseSingleRange/end_clamped_to_size907=== PAUSE TestParseSingleRange/end_clamped_to_size908=== RUN TestParseSingleRange/suffix909=== PAUSE TestParseSingleRange/suffix910=== RUN TestParseSingleRange/suffix_exceeds_size911=== PAUSE TestParseSingleRange/suffix_exceeds_size912=== RUN TestParseSingleRange/single_byte913=== PAUSE TestParseSingleRange/single_byte914=== RUN TestParseSingleRange/start_past_EOF915=== PAUSE TestParseSingleRange/start_past_EOF916=== RUN TestParseSingleRange/start_far_past_EOF917=== PAUSE TestParseSingleRange/start_far_past_EOF918=== CONT TestSweepSkipsRowsLockedByPush919--- PASS: TestReadProxyConditionalGet (0.58s)920=== CONT TestClientSharedPathCommittedMidPush9212026/10/04 20:03:52 INFO Received push request method=POST path=/api/pushes9222026/10/04 20:03:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9232026/10/04 20:03:52 INFO Signed narinfos id=1 count=1924--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.61s)925=== CONT TestFailedS3DeleteKeepsTombstone926--- PASS: TestReadProxyDisabled (0.62s)927=== CONT TestPresentNotReportedWhileGCDeletesClosure928--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.64s)929=== CONT TestForceGCDuringPushOffersSweptObject930=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows931=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows932=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check933=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check934=== CONT TestClientWithDependencies9352026/10/04 20:03:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9362026/10/04 20:03:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete937--- PASS: TestReadRedirectKeepsNarinfoProxied (0.66s)938=== CONT TestPresentReportsOnlyClosureRoots9392026/10/04 20:03:53 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YjViYjYwN2EtNTE1NS00YjRhLTkyOWUtNWMzZjRkMjQ1OGI3LmI0YmI2NTI4LTg5M2UtNGQ0Mi1hYWY2LWM1YmJlMDI1ZWU0OHgxNzkxMTQ0MjMyNjk1NjAyMDA1 parts=129402026/10/04 20:03:53 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YjViYjYwN2EtNTE1NS00YjRhLTkyOWUtNWMzZjRkMjQ1OGI3LjI2NjNhMDBhLTIzNzMtNGQ4Ny04ZDAxLTU5Njc1YmExNWU4NXgxNzkxMTQ0MjMyNzQ5MzA3NzYx parts=109412026/10/04 20:03:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9422026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures9432026/10/04 20:03:53 INFO Completed upload id=1944--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.68s)945=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection9462026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures9472026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures9482026/10/04 20:03:53 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9492026/10/04 20:03:53 WARN Found objects in DB but missing from S3, will re-upload count=1950--- PASS: TestService_verifyS3Integrity (0.69s)951=== CONT TestClientMultipleUploads952--- PASS: TestReadRedirectNar (0.69s)953=== CONT TestCreatePin_ReservedPins9542026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures9552026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures9562026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures957--- PASS: TestReadProxyInvalidPath (0.48s)958=== CONT TestGCSweepDeliversEachKeyOnce9592026/10/04 20:03:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9602026/10/04 20:03:53 INFO Received cleanup request method=DELETE path=/api/pending_closures9612026/10/04 20:03:53 INFO Aborted multipart uploads count=0 kept=09622026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures9632026/10/04 20:03:53 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YjViYjYwN2EtNTE1NS00YjRhLTkyOWUtNWMzZjRkMjQ1OGI3LmJhMzc2MmQ5LWI0ZjItNDU3MC05YzAxLTM1OTFhZDhlOWQyNHgxNzkxMTQ0MjMyNzY4NTgwNTky parts=129642026/10/04 20:03:53 INFO Received cleanup request method=DELETE path=/api/pending_closures9652026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures9662026/10/04 20:03:53 INFO Aborted multipart uploads count=1 kept=09672026/10/04 20:03:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9682026-10-04 20:03:53.155 UTC [486] ERROR: Closure does not exist: id=19692026-10-04 20:03:53.155 UTC [486] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE9702026-10-04 20:03:53.155 UTC [486] STATEMENT: -- name: CommitPendingClosure :exec971 SELECT commit_pending_closure($1::bigint)972 973--- PASS: TestService_cleanupPendingClosuresHandler (0.51s)974=== CONT TestClientIntegration9752026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures976--- PASS: TestReadProxy404 (0.50s)977=== CONT TestOrphanedObjectsGCStressTest978--- PASS: TestReadProxyNarStreaming (0.46s)979=== CONT TestTombstonedObjectOfferedWithoutWaiting9802026/10/04 20:03:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35917/oidc981--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.48s)982=== CONT TestClientErrorHandling983=== RUN TestClientErrorHandling/InvalidStorePath984=== PAUSE TestClientErrorHandling/InvalidStorePath985=== RUN TestClientErrorHandling/InvalidAuthToken986=== PAUSE TestClientErrorHandling/InvalidAuthToken987=== RUN TestClientErrorHandling/ServerNotAvailable988=== PAUSE TestClientErrorHandling/ServerNotAvailable989=== CONT TestOrphanedObjectsGC9902026/10/04 20:03:53 ERROR Failed to decompress narinfo error="decompressed size exceeds configured limit"991--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.42s)992=== CONT TestGCSweepSkipsPendingObjects9932026/10/04 20:03:53 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket2867442301/001/proxy.sock9942026/10/04 20:03:53 INFO Starting HTTP server address=127.0.0.1:391519952026/10/04 20:03:53 WARN mTLS auth: subject not in bound subjects subject="CN=someone"9962026/10/04 20:03:53 INFO Shutdown signal received, draining in-flight requests timeout=10s997--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.42s)998=== CONT TestClientCADerivations9992026/10/04 20:03:53 INFO Aborted multipart uploads count=0 kept=010002026/10/04 20:03:53 WARN Force mode enabled - objects will be deleted immediately without grace period10012026/10/04 20:03:53 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010022026/10/04 20:03:53 INFO Vacuumed table table=pending_closures10032026/10/04 20:03:53 INFO Vacuumed table table=pending_objects10042026/10/04 20:03:53 INFO Vacuumed table table=multipart_uploads10052026/10/04 20:03:53 INFO Vacuumed table table=closures10062026/10/04 20:03:53 INFO Vacuumed table table=objects10072026/10/04 20:03:53 INFO Aborted multipart uploads count=0 kept=010082026/10/04 20:03:53 WARN Force mode enabled - objects will be deleted immediately without grace period10092026/10/04 20:03:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10102026/10/04 20:03:53 ERROR Refusing narinfo larger than the limit key=5hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=167772161011--- PASS: TestReadProxyNarinfo (0.62s)1012=== CONT TestObjectStatsTrigger10132026/10/04 20:03:53 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=010142026/10/04 20:03:53 INFO Vacuumed table table=pending_closures10152026/10/04 20:03:53 INFO Vacuumed table table=pending_objects10162026/10/04 20:03:53 INFO Vacuumed table table=multipart_uploads10172026/10/04 20:03:53 INFO Vacuumed table table=closures10182026/10/04 20:03:53 INFO Vacuumed table table=objects1019--- PASS: TestSweepSkipsRowsLockedByPush (0.47s)1020=== CONT TestDeduplicatedObjectsRecordedAsPending10212026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures10222026/10/04 20:03:53 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YjViYjYwN2EtNTE1NS00YjRhLTkyOWUtNWMzZjRkMjQ1OGI3LjQ1MTQ3NzRhLWRhMzktNDQwNC1iYzU1LTE1ZWI4NTJlZDdiZXgxNzkxMTQ0MjMzMTAxMTQyNzQz parts=1010232026/10/04 20:03:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10242026/10/04 20:03:53 INFO Completed upload id=110252026/10/04 20:03:53 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010262026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures10272026/10/04 20:03:53 INFO Starting cleanup of old closures method=DELETE path=/api/closures10282026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures10292026/10/04 20:03:53 INFO Aborted multipart uploads count=0 kept=010302026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures10312026/10/04 20:03:53 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)10322026/10/04 20:03:53 INFO Uploading 9hf8pwnhpzvhpqixzbvw2qfcj666big6-a (216B)10332026/10/04 20:03:53 INFO Uploading 1bnizh32dkhfqk0amsirypazdz9bpk0n-shared-dep (136B)10342026/10/04 20:03:53 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=010352026/10/04 20:03:53 INFO Vacuumed table table=pending_closures1036=== NAME TestPinProtectsFromGC1037 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC2184448754/001/store/x45n1lk04q4r2il3dwfwsg3ck82s54al-pinned-file.txt1038 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC2184448754/001/store/3arzv628inmakkiympg88cnjpkwx14c1-unpinned-file.txt10392026/10/04 20:03:53 INFO Vacuumed table table=pending_objects10402026/10/04 20:03:53 WARN Failed to register uploaded object key=7zh2q813jixpcn39kbksgv1i2j63snqr.ls error="server returned 404: 404 page not found\n"10412026/10/04 20:03:53 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"10422026/10/04 20:03:53 WARN Failed to register uploaded object key=1bnizh32dkhfqk0amsirypazdz9bpk0n.ls error="server returned 404: 404 page not found\n"10432026/10/04 20:03:53 WARN Failed to register uploaded object key=nar/1dwaccv2qp0mln6kpikp9af6zmnpwq1xsklg6jpwwc1zkqm5c0bh.nar.zst error="server returned 404: 404 page not found\n"10442026/10/04 20:03:53 WARN Failed to register uploaded object key=9hf8pwnhpzvhpqixzbvw2qfcj666big6.ls error="server returned 404: 404 page not found\n"10452026/10/04 20:03:53 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10462026/10/04 20:03:53 INFO Signed narinfos id=1 count=210472026/10/04 20:03:53 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign10482026/10/04 20:03:53 INFO Received push request method=POST path=/api/pushes10492026/10/04 20:03:53 INFO Signed narinfos id=2 count=210502026/10/04 20:03:53 INFO Uploading 4 narinfos10512026/10/04 20:03:53 WARN Failed to register uploaded object key=7zh2q813jixpcn39kbksgv1i2j63snqr.narinfo error="server returned 404: 404 page not found\n"10522026/10/04 20:03:53 WARN Failed to register uploaded object key=1bnizh32dkhfqk0amsirypazdz9bpk0n.narinfo error="server returned 404: 404 page not found\n"10532026/10/04 20:03:53 WARN Failed to register uploaded object key=9hf8pwnhpzvhpqixzbvw2qfcj666big6.narinfo error="server returned 404: 404 page not found\n"10542026/10/04 20:03:53 INFO Vacuumed table table=multipart_uploads10552026/10/04 20:03:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10562026/10/04 20:03:53 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)10572026/10/04 20:03:53 INFO Uploading bgmgd7wj5jx4kdis9758s9wqydfy9ygb-b (216B)10582026/10/04 20:03:53 WARN Failed to register uploaded object key=1bnizh32dkhfqk0amsirypazdz9bpk0n.narinfo error="server returned 404: 404 page not found\n"10592026/10/04 20:03:53 INFO Uploading fbrisr5xq07kfrvx6rvaiiw7ii25jvzc-shared-dep (136B)10602026/10/04 20:03:53 INFO Vacuumed table table=closures10612026/10/04 20:03:53 INFO Vacuumed table table=objects10622026/10/04 20:03:53 WARN Failed to register uploaded object key=7srf86rcnwniyrdazf467n9x6b3wiqd4.ls error="server returned 404: 404 page not found\n"10632026/10/04 20:03:53 INFO Completed upload id=110642026/10/04 20:03:53 WARN Failed to register uploaded object key=nar/0pvx3c0ijzqkk5vr9mp4mav3x73xpyzxmkb9lfh92vgd2v7gr1yi.nar.zst error="server returned 404: 404 page not found\n"10652026/10/04 20:03:53 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10662026/10/04 20:03:53 WARN Failed to register uploaded object key=bgmgd7wj5jx4kdis9758s9wqydfy9ygb.ls error="server returned 404: 404 page not found\n"10672026/10/04 20:03:53 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"10682026/10/04 20:03:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10692026/10/04 20:03:53 WARN Failed to register uploaded object key=fbrisr5xq07kfrvx6rvaiiw7ii25jvzc.ls error="server returned 404: 404 page not found\n"10702026/10/04 20:03:53 INFO Signed narinfos id=1 count=310712026/10/04 20:03:53 INFO Uploading 3 narinfos10722026/10/04 20:03:53 INFO Completed upload id=210732026/10/04 20:03:53 INFO Upload complete. (70ms)1074=== NAME TestClientFallsBackToClosures1075 client_pushes_test.go:112: Retrieved narinfo from S3:1076 StorePath: /build/TestClientFallsBackToClosures4135710272/001/store/1bnizh32dkhfqk0amsirypazdz9bpk0n-shared-dep1077 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1078 Compression: zstd1079 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821080 NarSize: 1361081 References: 1082 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n10832026/10/04 20:03:53 WARN Failed to register uploaded object key=7srf86rcnwniyrdazf467n9x6b3wiqd4.narinfo error="server returned 404: 404 page not found\n"10842026/10/04 20:03:53 WARN Failed to register uploaded object key=bgmgd7wj5jx4kdis9758s9wqydfy9ygb.narinfo error="server returned 404: 404 page not found\n"10852026/10/04 20:03:53 INFO Received complete push request method=POST path=/api/pushes/1/complete10862026/10/04 20:03:53 WARN Failed to register uploaded object key=fbrisr5xq07kfrvx6rvaiiw7ii25jvzc.narinfo error="server returned 404: 404 page not found\n"1087 client_pushes_test.go:112: Retrieved narinfo from S3:1088 StorePath: /build/TestClientFallsBackToClosures4135710272/001/store/9hf8pwnhpzvhpqixzbvw2qfcj666big6-a1089 URL: nar/1dwaccv2qp0mln6kpikp9af6zmnpwq1xsklg6jpwwc1zkqm5c0bh.nar.zst1090 Compression: zstd1091 NarHash: sha256:1dwaccv2qp0mln6kpikp9af6zmnpwq1xsklg6jpwwc1zkqm5c0bh1092 NarSize: 2161093 References: /build/TestClientFallsBackToClosures4135710272/001/store/1bnizh32dkhfqk0amsirypazdz9bpk0n-shared-dep1094 CA: text:sha256:119n7g019yrr1i5bw0jxxjmc4s303xvshnhlpaclqclaw9kvk61q1095 client_pushes_test.go:112: Retrieved narinfo from S3:1096 StorePath: /build/TestClientFallsBackToClosures4135710272/001/store/7zh2q813jixpcn39kbksgv1i2j63snqr-b1097 URL: nar/1dwaccv2qp0mln6kpikp9af6zmnpwq1xsklg6jpwwc1zkqm5c0bh.nar.zst1098 Compression: zstd1099 NarHash: sha256:1dwaccv2qp0mln6kpikp9af6zmnpwq1xsklg6jpwwc1zkqm5c0bh1100 NarSize: 2161101 References: /build/TestClientFallsBackToClosures4135710272/001/store/1bnizh32dkhfqk0amsirypazdz9bpk0n-shared-dep1102 CA: text:sha256:119n7g019yrr1i5bw0jxxjmc4s303xvshnhlpaclqclaw9kvk61q11032026/10/04 20:03:53 INFO Upload complete. (64ms)1104--- PASS: TestClientFallsBackToClosures (0.68s)1105=== CONT TestCacheStatsHandler1106=== NAME TestClientPushesUseOnePush1107 client_pushes_test.go:97: Retrieved narinfo from S3:1108 StorePath: /build/TestClientPushesUseOnePush1715889496/001/store/fbrisr5xq07kfrvx6rvaiiw7ii25jvzc-shared-dep1109 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1110 Compression: zstd1111 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821112 NarSize: 1361113 References: 1114 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n11152026/10/04 20:03:53 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001116--- PASS: TestService_createPendingClosureHandler (0.95s)1117=== CONT TestPendingCleanupUsesOneCutoff1118=== NAME TestClientPushesUseOnePush1119 client_pushes_test.go:97: Retrieved narinfo from S3:1120 StorePath: /build/TestClientPushesUseOnePush1715889496/001/store/7srf86rcnwniyrdazf467n9x6b3wiqd4-a1121 URL: nar/0pvx3c0ijzqkk5vr9mp4mav3x73xpyzxmkb9lfh92vgd2v7gr1yi.nar.zst1122 Compression: zstd1123 NarHash: sha256:0pvx3c0ijzqkk5vr9mp4mav3x73xpyzxmkb9lfh92vgd2v7gr1yi1124 NarSize: 2161125 References: /build/TestClientPushesUseOnePush1715889496/001/store/fbrisr5xq07kfrvx6rvaiiw7ii25jvzc-shared-dep1126 CA: text:sha256:1j8b2d145xxjdpxgxij9qpif19m8gp4i911nm2lw6nzyqzzlkxgk1127 client_pushes_test.go:97: Retrieved narinfo from S3:1128 StorePath: /build/TestClientPushesUseOnePush1715889496/001/store/bgmgd7wj5jx4kdis9758s9wqydfy9ygb-b1129 URL: nar/0pvx3c0ijzqkk5vr9mp4mav3x73xpyzxmkb9lfh92vgd2v7gr1yi.nar.zst1130 Compression: zstd1131 NarHash: sha256:0pvx3c0ijzqkk5vr9mp4mav3x73xpyzxmkb9lfh92vgd2v7gr1yi1132 NarSize: 2161133 References: /build/TestClientPushesUseOnePush1715889496/001/store/fbrisr5xq07kfrvx6rvaiiw7ii25jvzc-shared-dep1134 CA: text:sha256:1j8b2d145xxjdpxgxij9qpif19m8gp4i911nm2lw6nzyqzzlkxgk1135--- PASS: TestPresentReportsOnlyClosureRoots (0.45s)1136=== CONT TestPushDedupSurvivesConcurrentGC1137--- PASS: TestClientPushesUseOnePush (0.63s)1138=== CONT TestCacheConfigHandler1139=== RUN TestCacheConfigHandler/full_config,_no_issuer1140=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1141=== RUN TestCacheConfigHandler/no_cache_url_configured1142=== PAUSE TestCacheConfigHandler/no_cache_url_configured1143=== RUN TestCacheConfigHandler/no_signing_keys1144=== PAUSE TestCacheConfigHandler/no_signing_keys1145=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1146=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1147=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded11482026/10/04 20:03:53 INFO Aborted multipart uploads count=0 kept=011492026/10/04 20:03:53 WARN Force mode enabled - objects will be deleted immediately without grace period11502026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures11512026/10/04 20:03:53 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."11522026/10/04 20:03:53 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1153--- PASS: TestFailedS3DeleteKeepsTombstone (0.53s)1154=== CONT TestGCMetrics11552026/10/04 20:03:53 INFO Received push request method=POST path=/api/pushes11562026/10/04 20:03:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11572026/10/04 20:03:53 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11582026/10/04 20:03:53 INFO Uploading x45n1lk04q4r2il3dwfwsg3ck82s54al-pinned-file.txt (128B)11592026/10/04 20:03:53 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"11602026/10/04 20:03:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11612026/10/04 20:03:53 WARN Failed to register uploaded object key=x45n1lk04q4r2il3dwfwsg3ck82s54al.ls error="server returned 404: 404 page not found\n"11622026/10/04 20:03:53 INFO Signed narinfos id=1 count=111632026/10/04 20:03:53 INFO Uploading 1 narinfos11642026/10/04 20:03:53 INFO Received complete push request method=POST path=/api/pushes/1/complete11652026/10/04 20:03:53 WARN Failed to register uploaded object key=x45n1lk04q4r2il3dwfwsg3ck82s54al.narinfo error="server returned 404: 404 page not found\n"11662026/10/04 20:03:53 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YjViYjYwN2EtNTE1NS00YjRhLTkyOWUtNWMzZjRkMjQ1OGI3LjE0Y2YwNGI5LWU4MGYtNDg4Yy1iOGIzLTMwYTc5ZDU3OWU3MHgxNzkxMTQ0MjMzMTY2ODM0MzI2 error="Get \"http://127.0.0.1:1/bucket10/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"11672026/10/04 20:03:53 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YjViYjYwN2EtNTE1NS00YjRhLTkyOWUtNWMzZjRkMjQ1OGI3LmUwMWQzYTg5LWNiOTMtNDJkNy1hMmU3LWNhODc1NTlkYWEzMXgxNzkxMTQ0MjMzMTU1NjIyNzg2 parts=1211682026/10/04 20:03:53 INFO Upload complete. (61ms)11692026/10/04 20:03:53 INFO Received cleanup request method=DELETE path=/api/pending_closures11702026/10/04 20:03:53 INFO Aborted multipart uploads count=1 kept=011712026/10/04 20:03:53 INFO Received push request method=POST path=/api/pushes1172=== NAME TestClientWithDependencies1173 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies3231701589/001/store/dcgxlnvwrvby8562493pqjj0dshr98q5-test-script1174--- PASS: TestRedundantMultipartUpload (1.18s)1175=== CONT TestService_ReadScope_PublicByDefault11762026/10/04 20:03:53 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)11772026/10/04 20:03:53 INFO Uploading w2vg61l8cyqqn2havi1yrcl9pydggzhx-top (224B)11782026/10/04 20:03:53 INFO Uploading p8mqs68mz37mkdr6blpkidrwmg3n63jn-shared-dep (136B)11792026/10/04 20:03:53 WARN Failed to register uploaded object key=w2vg61l8cyqqn2havi1yrcl9pydggzhx.ls error="server returned 404: 404 page not found\n"11802026/10/04 20:03:53 WARN Failed to register uploaded object key=p8mqs68mz37mkdr6blpkidrwmg3n63jn.ls error="server returned 404: 404 page not found\n"11812026/10/04 20:03:53 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11822026/10/04 20:03:53 WARN Failed to register uploaded object key=nar/1vglyxck6q1rjzdifh93nihkzmjibk6m5cqsv7g8cvqmlp6mw6bc.nar.zst error="server returned 404: 404 page not found\n"11832026/10/04 20:03:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11842026/10/04 20:03:53 INFO Signed narinfos id=1 count=211852026/10/04 20:03:53 INFO Uploading 2 narinfos11862026/10/04 20:03:53 WARN Failed to register uploaded object key=w2vg61l8cyqqn2havi1yrcl9pydggzhx.narinfo error="server returned 404: 404 page not found\n"11872026/10/04 20:03:53 INFO Received complete push request method=POST path=/api/pushes/1/complete11882026/10/04 20:03:53 WARN Failed to register uploaded object key=p8mqs68mz37mkdr6blpkidrwmg3n63jn.narinfo error="server returned 404: 404 page not found\n"1189=== NAME TestClientMultipleUploads1190 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads1222467392/001/store/dwj5vv3adf1cp1zyy3c8awvyzjny6myv-test-file-0.txt11912026/10/04 20:03:53 INFO Aborted multipart uploads count=0 kept=011922026/10/04 20:03:53 INFO Upload complete. (61ms)1193=== NAME TestClientSharedPathCommittedMidPush1194 client_integration_test.go:680: Retrieved narinfo from S3:1195 StorePath: /build/TestClientSharedPathCommittedMidPush4285450576/001/store/p8mqs68mz37mkdr6blpkidrwmg3n63jn-shared-dep1196 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1197 Compression: zstd1198 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821199 NarSize: 1361200 References: 1201 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n12022026/10/04 20:03:53 WARN Force mode enabled - objects will be deleted immediately without grace period1203 client_integration_test.go:680: Retrieved narinfo from S3:1204 StorePath: /build/TestClientSharedPathCommittedMidPush4285450576/001/store/w2vg61l8cyqqn2havi1yrcl9pydggzhx-top1205 URL: nar/1vglyxck6q1rjzdifh93nihkzmjibk6m5cqsv7g8cvqmlp6mw6bc.nar.zst1206 Compression: zstd1207 NarHash: sha256:1vglyxck6q1rjzdifh93nihkzmjibk6m5cqsv7g8cvqmlp6mw6bc1208 NarSize: 2241209 References: /build/TestClientSharedPathCommittedMidPush4285450576/001/store/p8mqs68mz37mkdr6blpkidrwmg3n63jn-shared-dep1210 CA: text:sha256:1mp6362pa7kk6qwy9f18msyx8lfl5bqj6ww861i1ncv4wrak6dah1211=== NAME TestClientWithDependencies1212 client_integration_test.go:615: Found 1 dependencies (including self)1213--- PASS: TestClientSharedPathCommittedMidPush (0.62s)1214=== CONT TestMultipartCleanup12152026/10/04 20:03:53 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=012162026/10/04 20:03:53 INFO Vacuumed table table=pending_closures12172026/10/04 20:03:53 INFO Vacuumed table table=pending_objects12182026/10/04 20:03:53 INFO Vacuumed table table=multipart_uploads12192026/10/04 20:03:53 INFO Vacuumed table table=closures12202026/10/04 20:03:53 INFO Vacuumed table table=objects1221--- PASS: TestGCSweepDeliversEachKeyOnce (0.50s)1222=== CONT TestGCBugBareHashReferences1223=== NAME TestClientMultipleUploads1224 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads1222467392/001/store/p8c3p03c8csfc7zdi453wsdxfzzkdpvd-test-file-1.txt1225=== NAME TestClientIntegration1226 client_integration_test.go:286: Created store path: /build/TestClientIntegration2718015774/002/store/4nsvc1nbp034vz7ab6w0rz9vhn1c313w-test-file.txt12272026/10/04 20:03:53 INFO Received push request method=POST path=/api/pushes12282026/10/04 20:03:53 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12292026/10/04 20:03:53 INFO Uploading 3arzv628inmakkiympg88cnjpkwx14c1-unpinned-file.txt (128B)12302026/10/04 20:03:53 WARN Failed to register uploaded object key=3arzv628inmakkiympg88cnjpkwx14c1.ls error="server returned 404: 404 page not found\n"12312026/10/04 20:03:53 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12322026/10/04 20:03:53 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"12332026/10/04 20:03:53 INFO Signed narinfos id=2 count=112342026/10/04 20:03:53 INFO Uploading 1 narinfos12352026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures12362026/10/04 20:03:53 INFO Received complete push request method=POST path=/api/pushes/2/complete12372026/10/04 20:03:53 WARN Failed to register uploaded object key=3arzv628inmakkiympg88cnjpkwx14c1.narinfo error="server returned 404: 404 page not found\n"12382026/10/04 20:03:53 INFO Upload complete. (48ms)1239--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.44s)1240=== CONT TestGCTaskStore_CompletedAllowsNewTask1241--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1242=== CONT TestService_RequireScope_OIDC1243=== NAME TestClientMultipleUploads1244 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads1222467392/001/store/mpdlxrgmm687xfvg75anvl8j1nipk0jy-test-file-2.txt12452026/10/04 20:03:53 INFO Received push request method=POST path=/api/pushes12462026/10/04 20:03:53 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12472026/10/04 20:03:53 WARN Refused reserved pin name=worker-x86_64-linux12482026/10/04 20:03:53 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12492026/10/04 20:03:53 INFO Received create pin request method=POST path=/api/pins/my-app12502026/10/04 20:03:53 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1251--- PASS: TestCreatePin_ReservedPins (0.58s)1252=== CONT TestGCAdvisoryLockBlocksConcurrentRun12532026/10/04 20:03:53 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12542026/10/04 20:03:53 INFO Uploading dcgxlnvwrvby8562493pqjj0dshr98q5-test-script (136B)12552026/10/04 20:03:53 WARN Failed to register uploaded object key=dcgxlnvwrvby8562493pqjj0dshr98q5.ls error="server returned 404: 404 page not found\n"12562026/10/04 20:03:53 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"12572026/10/04 20:03:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12582026/10/04 20:03:53 WARN Failed to register uploaded object key=log/z976w5yidrfwqkymmfc38pz4jff9xgax-test-script.drv error="server returned 404: 404 page not found\n"12592026/10/04 20:03:53 INFO Signed narinfos id=1 count=112602026/10/04 20:03:53 INFO Uploading 1 narinfos12612026/10/04 20:03:53 INFO Starting cleanup of old closures method=DELETE path=/api/closures12622026/10/04 20:03:53 INFO Garbage collection started12632026/10/04 20:03:53 INFO Received complete push request method=POST path=/api/pushes/1/complete12642026/10/04 20:03:53 WARN Failed to register uploaded object key=dcgxlnvwrvby8562493pqjj0dshr98q5.narinfo error="server returned 404: 404 page not found\n"12652026/10/04 20:03:53 INFO Upload complete. (57ms)12662026/10/04 20:03:53 INFO Aborted multipart uploads count=0 kept=01267=== NAME TestClientWithDependencies1268 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies3231701589/001/store) requires matching store prefix12692026/10/04 20:03:53 WARN Force mode enabled - objects will be deleted immediately without grace period1270--- PASS: TestClientWithDependencies (0.66s)1271=== CONT TestService_AuthMiddleware_OIDC12722026/10/04 20:03:53 INFO Received push request method=POST path=/api/pushes12732026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures12742026/10/04 20:03:53 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12752026/10/04 20:03:53 INFO Uploading 4nsvc1nbp034vz7ab6w0rz9vhn1c313w-test-file.txt (152B)12762026/10/04 20:03:53 WARN Failed to register uploaded object key=4nsvc1nbp034vz7ab6w0rz9vhn1c313w.ls error="server returned 404: 404 page not found\n"12772026/10/04 20:03:53 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"12782026/10/04 20:03:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12792026/10/04 20:03:53 INFO Signed narinfos id=1 count=112802026/10/04 20:03:53 INFO Uploading 1 narinfos12812026/10/04 20:03:53 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=012822026/10/04 20:03:53 INFO Received complete push request method=POST path=/api/pushes/1/complete12832026/10/04 20:03:53 WARN Failed to register uploaded object key=4nsvc1nbp034vz7ab6w0rz9vhn1c313w.narinfo error="server returned 404: 404 page not found\n"12842026/10/04 20:03:53 INFO Vacuumed table table=pending_closures12852026/10/04 20:03:53 INFO Vacuumed table table=pending_objects12862026/10/04 20:03:53 INFO Vacuumed table table=multipart_uploads12872026/10/04 20:03:53 INFO Upload complete. (58ms)12882026/10/04 20:03:53 INFO Vacuumed table table=closures12892026/10/04 20:03:53 INFO Aborted multipart uploads count=0 kept=012902026/10/04 20:03:53 INFO Vacuumed table table=objects12912026/10/04 20:03:53 WARN Force mode enabled - objects will be deleted immediately without grace period12922026/10/04 20:03:53 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012932026/10/04 20:03:53 INFO Received push request method=POST path=/api/pushes12942026/10/04 20:03:53 INFO Vacuumed table table=pending_closures12952026/10/04 20:03:53 INFO Vacuumed table table=pending_objects12962026/10/04 20:03:53 INFO Vacuumed table table=multipart_uploads12972026/10/04 20:03:53 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)12982026/10/04 20:03:53 INFO Uploading p8c3p03c8csfc7zdi453wsdxfzzkdpvd-test-file-1.txt (160B)12992026/10/04 20:03:53 INFO Uploading dwj5vv3adf1cp1zyy3c8awvyzjny6myv-test-file-0.txt (160B)13002026/10/04 20:03:53 INFO Vacuumed table table=closures13012026/10/04 20:03:53 INFO Uploading mpdlxrgmm687xfvg75anvl8j1nipk0jy-test-file-2.txt (160B)13022026/10/04 20:03:53 INFO Vacuumed table table=objects1303--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.81s)1304=== CONT TestLeadEndsOnShutdown1305--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.66s)1306=== CONT TestService_ReadAuthMiddleware13072026/10/04 20:03:53 WARN Failed to register uploaded object key=p8c3p03c8csfc7zdi453wsdxfzzkdpvd.ls error="server returned 404: 404 page not found\n"13082026/10/04 20:03:53 WARN Failed to register uploaded object key=mpdlxrgmm687xfvg75anvl8j1nipk0jy.ls error="server returned 404: 404 page not found\n"13092026/10/04 20:03:53 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"13102026/10/04 20:03:53 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"13112026/10/04 20:03:53 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"13122026/10/04 20:03:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13132026/10/04 20:03:53 WARN Failed to register uploaded object key=dwj5vv3adf1cp1zyy3c8awvyzjny6myv.ls error="server returned 404: 404 page not found\n"13142026/10/04 20:03:53 INFO Signed narinfos id=1 count=313152026/10/04 20:03:53 INFO Uploading 3 narinfos1316--- PASS: TestGCSweepSkipsPendingObjects (0.43s)1317=== CONT TestLeadElectsOneAndHandsOver13182026/10/04 20:03:53 WARN Failed to register uploaded object key=mpdlxrgmm687xfvg75anvl8j1nipk0jy.narinfo error="server returned 404: 404 page not found\n"13192026/10/04 20:03:53 INFO Received complete push request method=POST path=/api/pushes/1/complete13202026/10/04 20:03:53 WARN Failed to register uploaded object key=p8c3p03c8csfc7zdi453wsdxfzzkdpvd.narinfo error="server returned 404: 404 page not found\n"13212026/10/04 20:03:53 WARN Failed to register uploaded object key=dwj5vv3adf1cp1zyy3c8awvyzjny6myv.narinfo error="server returned 404: 404 page not found\n"1322--- PASS: TestObjectStatsTrigger (0.31s)1323=== CONT TestService_AuthMiddleware_MTLSBoundSubjects13242026/10/04 20:03:53 INFO Upload complete. (62ms)1325=== NAME TestClientMultipleUploads1326 client_integration_test.go:369: Uploaded 3 paths in 89.992878ms13272026/10/04 20:03:53 INFO All 1 paths already cached1328=== NAME TestClientIntegration1329 client_integration_test.go:312: Retrieved narinfo from S3:1330 StorePath: /build/TestClientIntegration2718015774/002/store/4nsvc1nbp034vz7ab6w0rz9vhn1c313w-test-file.txt1331 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1332 Compression: zstd1333 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11334 NarSize: 1521335 References: 1336 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11337 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1338 client_integration_test.go:313: Decompressed .ls content (64 bytes):1339 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1340 client_integration_test.go:316: Testing garbage collection...13412026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures1342--- PASS: TestClientMultipleUploads (0.68s)1343=== CONT TestConnectWaitsForAPeerMigration1344--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.33s)1345=== CONT TestGCTaskStore_GetReturnsLatest1346--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1347=== CONT TestService_AuthMiddleware_MTLSProxyHeader1348--- PASS: TestCacheStatsHandler (0.29s)1349=== CONT TestResolveDBConnectionString1350=== RUN TestResolveDBConnectionString/flag_wins1351=== PAUSE TestResolveDBConnectionString/flag_wins1352=== RUN TestResolveDBConnectionString/file_when_flag_empty1353=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1354=== RUN TestResolveDBConnectionString/missing_file_is_an_error1355=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1356=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1357=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1358=== RUN TestResolveDBConnectionString/nothing_configured1359=== PAUSE TestResolveDBConnectionString/nothing_configured1360=== CONT TestGCTaskStore_GetEmpty1361--- PASS: TestGCTaskStore_GetEmpty (0.00s)1362=== CONT TestGCTaskStore_PhaseUpdates1363--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1364=== CONT TestGCTaskStore_ConflictDifferentParams1365--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1366=== CONT TestGenerateLandingPage1367--- PASS: TestGenerateLandingPage (0.00s)1368=== CONT TestGCTaskStore_DeduplicateSameParams1369--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1370=== CONT TestService_readinessHandler13712026/10/04 20:03:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40393/oidc13722026/10/04 20:03:53 INFO Starting cleanup of old closures method=DELETE path=/api/closures13732026/10/04 20:03:53 INFO Garbage collection started13742026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures13752026/10/04 20:03:53 INFO Aborted multipart uploads count=0 kept=013762026/10/04 20:03:53 WARN Force mode enabled - objects will be deleted immediately without grace period1377=== NAME TestClientCADerivations1378 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations3340950878/001/store/5zry4c9lyna3nz19d7fkrm9w8m56ixrf-ca-test13792026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures13802026/10/04 20:03:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37495/oidc13812026/10/04 20:03:53 INFO Received cleanup request method=DELETE path=/api/pending_closures13822026/10/04 20:03:53 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=013832026/10/04 20:03:53 INFO Vacuumed table table=pending_closures13842026/10/04 20:03:53 INFO Vacuumed table table=pending_objects13852026/10/04 20:03:53 INFO Vacuumed table table=multipart_uploads13862026/10/04 20:03:53 INFO Vacuumed table table=closures13872026/10/04 20:03:53 INFO Vacuumed table table=objects13882026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures13892026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures1390 client_ca_test.go:139: Found 1 dependencies (including self)1391--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.34s)1392=== CONT TestProxyWriteTimeout1393=== RUN TestProxyWriteTimeout/narinfo1394=== PAUSE TestProxyWriteTimeout/narinfo1395=== RUN TestProxyWriteTimeout/1_GiB_nar1396=== PAUSE TestProxyWriteTimeout/1_GiB_nar1397=== RUN TestProxyWriteTimeout/10_GiB_nar1398=== PAUSE TestProxyWriteTimeout/10_GiB_nar1399=== RUN TestProxyWriteTimeout/unknown_size1400=== PAUSE TestProxyWriteTimeout/unknown_size1401=== CONT TestService_healthCheckHandler14022026/10/04 20:03:53 INFO Aborted multipart uploads count=0 kept=014032026/10/04 20:03:53 WARN Force mode enabled - objects will be deleted immediately without grace period14042026/10/04 20:03:53 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014052026/10/04 20:03:53 INFO Vacuumed table table=pending_closures14062026/10/04 20:03:53 INFO Vacuumed table table=pending_objects14072026/10/04 20:03:53 INFO Vacuumed table table=multipart_uploads14082026/10/04 20:03:53 INFO Vacuumed table table=closures14092026/10/04 20:03:53 INFO Vacuumed table table=objects1410--- PASS: TestService_ReadScope_PublicByDefault (0.31s)1411=== CONT TestGCTaskStore_StartNew1412--- PASS: TestGCTaskStore_StartNew (0.00s)1413=== CONT TestGracefulShutdownDrainsInflight14142026/10/04 20:03:53 INFO Starting HTTP server address=127.0.0.1:421551415--- PASS: TestGCMetrics (0.35s)1416=== CONT TestPushWaitsForSweepHoldingRow14172026/10/04 20:03:53 INFO Shutdown signal received, draining in-flight requests timeout=10s14182026/10/04 20:03:53 INFO Received uploads request method=POST path=/api/pending_closures14192026/10/04 20:03:53 INFO Aborted multipart uploads count=0 kept=014202026/10/04 20:03:53 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=014212026/10/04 20:03:53 INFO Vacuumed table table=pending_closures14222026/10/04 20:03:53 INFO Vacuumed table table=pending_objects14232026/10/04 20:03:53 INFO Vacuumed table table=multipart_uploads14242026/10/04 20:03:53 INFO Vacuumed table table=closures14252026/10/04 20:03:53 INFO Vacuumed table table=objects14262026/10/04 20:03:53 INFO Aborted multipart uploads count=0 kept=014272026/10/04 20:03:53 WARN Force mode enabled - objects will be deleted immediately without grace period14282026/10/04 20:03:53 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014292026/10/04 20:03:53 INFO Vacuumed table table=pending_closures14302026/10/04 20:03:53 INFO Vacuumed table table=pending_objects14312026/10/04 20:03:53 INFO Vacuumed table table=multipart_uploads14322026/10/04 20:03:53 INFO Vacuumed table table=closures14332026/10/04 20:03:53 INFO Vacuumed table table=objects1434--- PASS: TestPushDedupSurvivesConcurrentGC (0.43s)1435=== CONT TestGCTaskStore_Fail1436--- PASS: TestGCTaskStore_Fail (0.00s)1437=== CONT TestGCEndsOnShutdown1438=== RUN TestGCEndsOnShutdown/before_the_run1439=== PAUSE TestGCEndsOnShutdown/before_the_run1440=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1441=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1442=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1443=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1444=== CONT TestCommitRacingPendingCleanupKeepsObjects14452026/10/04 20:03:53 INFO Received push request method=POST path=/api/pushes1446--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1447=== CONT TestMetricsInventory14482026/10/04 20:03:53 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"1449--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.28s)1450=== CONT TestSweepRechecksPendingAfterLocking14512026/10/04 20:03:53 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14522026/10/04 20:03:53 INFO Uploading 5zry4c9lyna3nz19d7fkrm9w8m56ixrf-ca-test (144B)14532026/10/04 20:03:53 WARN Failed to register uploaded object key=log/d5fspmc86frbm7ngp6nmh06n7wz0ih8a-ca-test.drv error="server returned 404: 404 page not found\n"14542026/10/04 20:03:53 WARN Failed to register uploaded object key=5zry4c9lyna3nz19d7fkrm9w8m56ixrf.ls error="server returned 404: 404 page not found\n"14552026/10/04 20:03:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14562026/10/04 20:03:53 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"14572026/10/04 20:03:53 INFO Signed narinfos id=1 count=114582026/10/04 20:03:53 INFO Uploading 1 narinfos14592026/10/04 20:03:53 INFO Received complete push request method=POST path=/api/pushes/1/complete14602026/10/04 20:03:53 WARN Failed to register uploaded object key=5zry4c9lyna3nz19d7fkrm9w8m56ixrf.narinfo error="server returned 404: 404 page not found\n"14612026/10/04 20:03:53 INFO lead: acquired remote=192.0.2.1:123414622026/10/04 20:03:53 INFO Upload complete. (92ms)1463--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.96s)1464=== CONT TestGetExistingObjectsLocksRows1465=== NAME TestClientCADerivations1466 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations3340950878/001/store/5zry4c9lyna3nz19d7fkrm9w8m56ixrf-ca-test1467 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1468 Compression: zstd1469 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1470 NarSize: 1441471 References: 1472 Deriver: /build/TestClientCADerivations3340950878/001/store/d5fspmc86frbm7ngp6nmh06n7wz0ih8a-ca-test.drv1473 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1474 client_ca_test.go:185: Checking for realisation files in S3...1475 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1476 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1477=== NAME TestOrphanedObjectsGC1478 orphaned_objects_gc_test.go:290: GC Test Summary:1479 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1480 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1481 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1482 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1483 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1484--- PASS: TestOrphanedObjectsGC (0.75s)1485=== CONT TestServerTLSConfig1486=== RUN TestServerTLSConfig/no_client_CA1487=== PAUSE TestServerTLSConfig/no_client_CA1488=== RUN TestServerTLSConfig/missing_CA_file1489=== PAUSE TestServerTLSConfig/missing_CA_file1490=== RUN TestServerTLSConfig/not_a_PEM_file1491=== PAUSE TestServerTLSConfig/not_a_PEM_file1492=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1493--- PASS: TestService_ReadAuthMiddleware (0.25s)1494=== CONT TestService_NativeMTLS14952026/10/04 20:03:53 INFO lead: acquired remote=192.0.2.1:123414962026/10/04 20:03:54 INFO Received cleanup request method=DELETE path=/api/pending_closures14972026/10/04 20:03:54 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket63/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""14982026/10/04 20:03:54 INFO Aborted multipart uploads count=0 kept=114992026/10/04 20:03:54 INFO Received cleanup request method=DELETE path=/api/pending_closures15002026/10/04 20:03:54 INFO Aborted multipart uploads count=1 kept=01501--- PASS: TestMultipartCleanup (0.43s)1502=== CONT TestCacheConfigHandlerMaxNarSize1503--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1504=== CONT TestCreatePendingClosureRejectsOversizedNAR15052026/10/04 20:03:54 INFO Received uploads request method=POST path=/api/pending_closures1506--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1507=== CONT TestNARDeduplicationMetadataUploadBug15082026/10/04 20:03:54 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15092026/10/04 20:03:54 WARN mTLS auth: bound subjects configured but subject DN unavailable15102026/10/04 20:03:54 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1511--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.31s)1512=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure15132026/10/04 20:03:54 INFO Received uploads request method=POST path=/1514=== NAME TestClientCADerivations1515 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1516 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1517 error: binary cache 's3://bucket54?endpoint=http://localhost:42541®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations3340950878/001/store'1518 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11519--- PASS: TestClientCADerivations (0.71s)1520=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts15212026/10/04 20:03:54 INFO Received request for more parts method=POST path=/1522--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.31s)1523=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart15242026/10/04 20:03:54 INFO Received complete multipart upload request method=POST path=/1525=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1526=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1527=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1528=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1529=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1530=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1531=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1532=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1533=== CONT TestPendingClosureWriteTimeout/empty1534=== CONT TestPendingClosureWriteTimeout/670k_objects1535=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline15362026/10/04 20:03:54 WARN readiness check failed error="closed pool"1537--- PASS: TestService_readinessHandler (0.33s)1538=== CONT TestPendingClosureWriteTimeout/400_objects1539=== CONT TestPush_RejectsBadRequests/root_not_in_objects15402026/10/04 20:03:54 INFO Received push request method=POST path=/api/pushes1541=== CONT TestPush_RejectsBadRequests/no_objects15422026/10/04 20:03:54 INFO Received push request method=POST path=/api/pushes1543=== CONT TestPush_RejectsBadRequests/bad_root15442026/10/04 20:03:54 INFO Received push request method=POST path=/api/pushes1545=== CONT TestPush_RejectsBadRequests/no_roots15462026/10/04 20:03:54 INFO Received push request method=POST path=/api/pushes1547=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1548--- PASS: TestPush_RejectsBadRequests (0.42s)1549 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1550 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1551 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1552 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)15532026/10/04 20:03:54 INFO Received uploads request method=POST path=/1554=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15552026/10/04 20:03:54 INFO Received complete multipart upload request method=POST path=/1556=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15572026/10/04 20:03:54 INFO Received uploads request method=POST path=/1558=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15592026/10/04 20:03:54 INFO Received request for more parts method=POST path=/1560--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1561 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1562 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1563 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1564 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1565=== CONT TestIsValidUploadKey/narinfo1566=== CONT TestIsValidUploadKey/realisation_plus_in_output1567=== CONT TestIsValidUploadKey/build_log_home-manager_file1568=== CONT TestIsValidUploadKey/realisation1569=== CONT TestIsValidUploadKey/unknown_type1570=== CONT TestIsValidUploadKey/build_log_equals1571=== CONT TestIsValidUploadKey/empty_key1572=== CONT TestIsValidUploadKey/build_log_question_mark1573=== CONT TestIsValidUploadKey/absolute1574=== CONT TestIsValidUploadKey/build_log_plus_in_name1575=== CONT TestIsValidUploadKey/traversal_nar1576=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1577=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1578=== CONT TestIsValidUploadKey/traversal1579=== CONT TestIsValidUploadKey/index.html1580=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1581=== CONT TestIsValidUploadKey/nix-cache-info1582=== CONT TestIsValidUploadKey/nar_plain1583=== CONT TestIsValidUploadKey/nar_xz1584=== CONT TestIsValidUploadKey/build_log1585=== CONT TestIsValidUploadKey/listing1586=== CONT TestIsValidUploadKey/nar_zst1587=== CONT TestIsValidCachePath/narinfo1588=== CONT TestIsValidCachePath/short_hash1589=== CONT TestIsValidCachePath/wrong_extension1590=== CONT TestIsValidCachePath/leading_slash1591=== CONT TestIsValidCachePath/empty1592--- PASS: TestIsValidUploadKey (0.00s)1593 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1594 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1595 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1596 --- PASS: TestIsValidUploadKey/realisation (0.00s)1597 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1598 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1599 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1600 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1601 --- PASS: TestIsValidUploadKey/absolute (0.00s)1602 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1603 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1604 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1605 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1606 --- PASS: TestIsValidUploadKey/traversal (0.00s)1607 --- PASS: TestIsValidUploadKey/index.html (0.00s)1608 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1609 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1610 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1611 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1612 --- PASS: TestIsValidUploadKey/build_log (0.00s)1613 --- PASS: TestIsValidUploadKey/listing (0.00s)1614 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1615=== CONT TestIsValidCachePath/random_path1616=== CONT TestIsValidCachePath/invalid_char_u1617=== CONT TestIsValidCachePath/invalid_char_e1618=== CONT TestIsValidCachePath/traversal_in_middle1619=== CONT TestIsValidCachePath/traversal_parent1620=== CONT TestIsValidCachePath/index.html1621=== CONT TestIsValidCachePath/nix-cache-info1622=== CONT TestIsValidCachePath/realisation1623=== CONT TestIsValidCachePath/log1624=== CONT TestIsValidCachePath/ls1625=== CONT TestIsValidCachePath/nar_uncompressed1626=== CONT TestIsValidCachePath/nar_bz21627=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1628=== CONT TestIsValidCachePath/nar_xz1629=== CONT TestIsValidCachePath/nar_zst1630--- PASS: TestIsValidCachePath (0.00s)1631 --- PASS: TestIsValidCachePath/narinfo (0.00s)1632 --- PASS: TestIsValidCachePath/short_hash (0.00s)1633 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1634 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1635 --- PASS: TestIsValidCachePath/empty (0.00s)1636 --- PASS: TestIsValidCachePath/random_path (0.00s)1637 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1638 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1639 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1640 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1641 --- PASS: TestIsValidCachePath/index.html (0.00s)1642 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1643 --- PASS: TestIsValidCachePath/realisation (0.00s)1644 --- PASS: TestIsValidCachePath/log (0.00s)1645 --- PASS: TestIsValidCachePath/ls (0.00s)1646 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1647 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1648 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1649 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1650 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1651=== CONT TestParseSingleRange/none1652=== CONT TestParseSingleRange/start_far_past_EOF1653=== CONT TestParseSingleRange/start_past_EOF1654=== CONT TestParseSingleRange/single_byte1655=== CONT TestParseSingleRange/suffix_exceeds_size1656=== CONT TestParseSingleRange/suffix1657=== CONT TestParseSingleRange/end_clamped_to_size1658=== CONT TestParseSingleRange/open-ended1659=== CONT TestParseSingleRange/closed1660=== CONT TestParseSingleRange/malformed_end_before_start1661=== CONT TestParseSingleRange/malformed_both_empty1662=== CONT TestParseSingleRange/malformed_no_dash1663=== CONT TestParseSingleRange/multi-range_ignored1664=== CONT TestParseSingleRange/unknown_unit1665=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1666--- PASS: TestParseSingleRange (0.00s)1667 --- PASS: TestParseSingleRange/none (0.00s)1668 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1669 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1670 --- PASS: TestParseSingleRange/single_byte (0.00s)1671 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1672 --- PASS: TestParseSingleRange/suffix (0.00s)1673 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1674 --- PASS: TestParseSingleRange/open-ended (0.00s)1675 --- PASS: TestParseSingleRange/closed (0.00s)1676 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1677 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1678 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1679 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1680 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1681=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1682=== CONT TestClientErrorHandling/InvalidStorePath1683--- PASS: TestService_healthCheckHandler (0.31s)1684=== CONT TestClientErrorHandling/InvalidAuthToken1685=== RUN TestService_RequireScope_OIDC/builder_may_write1686=== PAUSE TestService_RequireScope_OIDC/builder_may_write1687=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1688=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1689=== RUN TestService_RequireScope_OIDC/ops_may_admin1690=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1691=== RUN TestService_RequireScope_OIDC/ops_may_not_write1692=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1693=== RUN TestService_RequireScope_OIDC/reader_may_not_write1694=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1695=== RUN TestService_RequireScope_OIDC/static_token_may_admin1696=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1697=== RUN TestService_RequireScope_OIDC/static_token_may_write1698=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1699=== RUN TestService_RequireScope_OIDC/reader_may_read1700=== PAUSE TestService_RequireScope_OIDC/reader_may_read1701=== RUN TestService_RequireScope_OIDC/writer_implies_read1702=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1703=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1704=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1705=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1706=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1707=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1708=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1709=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1710=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1711=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1712=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1713=== CONT TestClientErrorHandling/ServerNotAvailable1714--- PASS: TestGCBugBareHashReferences (0.55s)1715=== CONT TestCacheConfigHandler/full_config,_no_issuer1716=== CONT TestCacheConfigHandler/no_signing_keys1717=== CONT TestCacheConfigHandler/no_cache_url_configured1718=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1719--- PASS: TestCacheConfigHandler (0.00s)1720 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1721 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1722 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1723 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1724=== CONT TestResolveDBConnectionString/flag_wins1725=== CONT TestResolveDBConnectionString/missing_file_is_an_error1726=== CONT TestResolveDBConnectionString/file_when_flag_empty1727=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1728=== CONT TestResolveDBConnectionString/nothing_configured1729=== CONT TestProxyWriteTimeout/narinfo1730=== CONT TestProxyWriteTimeout/unknown_size1731=== CONT TestProxyWriteTimeout/1_GiB_nar1732=== CONT TestProxyWriteTimeout/10_GiB_nar1733--- PASS: TestProxyWriteTimeout (0.00s)1734 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1735 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1736 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1737 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1738=== CONT TestGCEndsOnShutdown/before_the_run1739--- PASS: TestResolveDBConnectionString (0.00s)1740 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1741 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1742 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1743 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1744 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)17452026/10/04 20:03:54 INFO Received uploads request method=POST path=/api/pending_closures17462026/10/04 20:03:54 INFO Aborted multipart uploads count=0 kept=017472026/10/04 20:03:54 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present17482026/10/04 20:03:54 WARN Force mode enabled - objects will be deleted immediately without grace period1749--- PASS: TestMetricsInventory (0.29s)1750=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete17512026/10/04 20:03:54 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=017522026/10/04 20:03:54 INFO Vacuumed table table=pending_closures17532026/10/04 20:03:54 INFO Vacuumed table table=pending_objects17542026/10/04 20:03:54 INFO Vacuumed table table=multipart_uploads17552026/10/04 20:03:54 INFO Vacuumed table table=closures17562026/10/04 20:03:54 INFO Vacuumed table table=objects17572026/10/04 20:03:54 INFO Aborted multipart uploads count=0 kept=01758--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.31s)1759=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark17602026/10/04 20:03:54 WARN Force mode enabled - objects will be deleted immediately without grace period1761--- PASS: TestGetExistingObjectsLocksRows (0.30s)1762=== CONT TestServerTLSConfig/no_client_CA1763=== CONT TestServerTLSConfig/not_a_PEM_file1764=== CONT TestServerTLSConfig/missing_CA_file1765=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1766--- PASS: TestServerTLSConfig (0.00s)1767 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1768 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1769 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)17702026/10/04 20:03:54 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=017712026/10/04 20:03:54 INFO Vacuumed table table=pending_closures1772=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected17732026/10/04 20:03:54 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]1774=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1775=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected17762026/10/04 20:03:54 INFO Vacuumed table table=pending_objects17772026/10/04 20:03:54 INFO Vacuumed table table=multipart_uploads17782026/10/04 20:03:54 INFO Vacuumed table table=closures17792026/10/04 20:03:54 WARN Authentication failed token_preview=eyJhbGciOi...6YtGQSb0dg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1780=== CONT TestService_RequireScope_OIDC/builder_may_write17812026/10/04 20:03:54 INFO Received uploads request method=POST path=/api/pending_closures17822026/10/04 20:03:54 INFO Vacuumed table table=objects1783--- PASS: TestService_AuthMiddleware_OIDC (0.40s)1784 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1785 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1786 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1787 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1788=== CONT TestService_RequireScope_OIDC/reader_may_read1789=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1790=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read17912026/10/04 20:03:54 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]1792=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1793=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1794--- PASS: TestSweepRechecksPendingAfterLocking (0.33s)1795=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1796=== CONT TestService_RequireScope_OIDC/writer_implies_read1797=== CONT TestService_RequireScope_OIDC/reader_may_not_write1798=== CONT TestService_RequireScope_OIDC/static_token_may_write1799=== CONT TestService_RequireScope_OIDC/static_token_may_admin1800=== CONT TestService_RequireScope_OIDC/ops_may_admin1801=== CONT TestService_RequireScope_OIDC/ops_may_not_write1802=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1803--- PASS: TestService_RequireScope_OIDC (0.51s)1804 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1805 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1806 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1807 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1808 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1809 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1810 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1811 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1812 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1813 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1814 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1815 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1816 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1817 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)18182026/10/04 20:03:54 WARN mTLS auth: subject not in bound subjects subject="CN=reader"18192026/10/04 20:03:54 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1820--- PASS: TestService_NativeMTLS (0.32s)18212026/10/04 20:03:54 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=195.593535ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18222026/10/04 20:03:54 INFO Received uploads request method=POST path=/api/pending_closures18232026/10/04 20:03:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1824=== NAME TestNARDeduplicationMetadataUploadBug1825 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug2897621582/001/store/a7gzhq6zhlki9wjy2hciak98x9yrag52-file1.txt18262026/10/04 20:03:54 INFO Received uploads request method=POST path=/api/pending_closures18272026/10/04 20:03:54 INFO Aborted multipart uploads count=0 kept=018282026/10/04 20:03:54 WARN Force mode enabled - objects will be deleted immediately without grace period18292026/10/04 20:03:54 INFO Received uploads request method=POST path=/api/pending_closures18302026/10/04 20:03:54 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=018312026/10/04 20:03:54 INFO Vacuumed table table=pending_closures18322026/10/04 20:03:54 INFO Vacuumed table table=pending_objects18332026/10/04 20:03:54 INFO Vacuumed table table=multipart_uploads18342026/10/04 20:03:54 INFO Vacuumed table table=closures18352026/10/04 20:03:54 INFO Vacuumed table table=objects18362026/10/04 20:03:54 INFO Aborted multipart uploads count=0 kept=018372026/10/04 20:03:54 WARN Force mode enabled - objects will be deleted immediately without grace period18382026/10/04 20:03:54 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=018392026/10/04 20:03:54 INFO Vacuumed table table=pending_closures18402026/10/04 20:03:54 INFO Vacuumed table table=pending_objects18412026/10/04 20:03:54 INFO Vacuumed table table=multipart_uploads18422026/10/04 20:03:54 INFO Vacuumed table table=closures18432026/10/04 20:03:54 INFO Vacuumed table table=objects1844--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)1845 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.28s)1846 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.27s)18472026/10/04 20:03:54 INFO Received push request method=POST path=/api/pushes18482026/10/04 20:03:54 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18492026/10/04 20:03:54 INFO Uploading a7gzhq6zhlki9wjy2hciak98x9yrag52-file1.txt (160B)18502026/10/04 20:03:54 WARN Failed to register uploaded object key=a7gzhq6zhlki9wjy2hciak98x9yrag52.ls error="server returned 404: 404 page not found\n"18512026/10/04 20:03:54 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18522026/10/04 20:03:54 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"18532026/10/04 20:03:54 INFO Signed narinfos id=1 count=118542026/10/04 20:03:54 INFO Uploading 1 narinfos18552026/10/04 20:03:54 INFO Received complete push request method=POST path=/api/pushes/1/complete18562026/10/04 20:03:54 WARN Failed to register uploaded object key=a7gzhq6zhlki9wjy2hciak98x9yrag52.narinfo error="server returned 404: 404 page not found\n"18572026/10/04 20:03:54 INFO Upload complete. (50ms)1858=== NAME TestNARDeduplicationMetadataUploadBug1859 metadata_upload_test.go:54: Retrieved narinfo from S3:1860 StorePath: /build/TestNARDeduplicationMetadataUploadBug2897621582/001/store/a7gzhq6zhlki9wjy2hciak98x9yrag52-file1.txt1861 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1862 Compression: zstd1863 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1864 NarSize: 1601865 References: 1866 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1867 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1868 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1869 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}18702026/10/04 20:03:54 INFO Aborted multipart uploads count=0 kept=018712026/10/04 20:03:54 WARN Force mode enabled - objects will be deleted immediately without grace period18722026/10/04 20:03:54 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:42541/bucket89/?delete=\": context canceled"18732026/10/04 20:03:54 INFO Aborted multipart uploads count=0 kept=018742026/10/04 20:03:54 WARN Force mode enabled - objects will be deleted immediately without grace period18752026/10/04 20:03:54 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"18762026-10-04 20:03:54.474 UTC [1718] ERROR: canceling statement due to user request18772026-10-04 20:03:54.474 UTC [1718] CONTEXT: PL/pgSQL function object_stats_apply() line 5 at statement block18782026-10-04 20:03:54.474 UTC [1718] STATEMENT: -- name: MarkStaleObjects :execrows1879 WITH RECURSIVE ct AS (1880 SELECT timezone('UTC', now()) AS now1881 ),1882 closure_reach AS (1883 -- Start with all closure keys1884 SELECT o.key, o.refs1885 FROM objects o1886 INNER JOIN closures c ON o.key = c.key1887 UNION1888 -- Recursively add all referenced objects1889 SELECT o.key, o.refs1890 FROM objects o1891 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)1892 ),1893 reachable_objects AS (1894 SELECT DISTINCT key FROM closure_reach1895 ),1896 stale_objects AS (1897 SELECT o.key1898 FROM objects AS o, ct1899 WHERE1900 NOT EXISTS (1901 SELECT 11902 FROM reachable_objects ro1903 WHERE ro.key = o.key1904 )1905 AND NOT EXISTS (1906 SELECT 11907 FROM pending_objects AS po1908 WHERE po.key = o.key1909 )1910 AND o.deleted_at IS NULL -- Only mark fresh objects1911 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure1912 FOR UPDATE1913 )1914 UPDATE objects1915 SET1916 deleted_at = ct.now,1917 first_deleted_at = COALESCE(first_deleted_at, ct.now)1918 FROM stale_objects, ct1919 WHERE objects.key = stale_objects.key1920 1921 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug2897621582/001/store/bj7rgwa8caq7cij6hg47d8y189qn17by-file2.txt1922--- PASS: TestGCEndsOnShutdown (0.00s)1923 --- PASS: TestGCEndsOnShutdown/before_the_run (0.26s)1924 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.22s)1925 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.23s)19262026/10/04 20:03:54 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"19272026/10/04 20:03:54 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=412.316094ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19282026/10/04 20:03:54 INFO Received push request method=POST path=/api/pushes19292026/10/04 20:03:54 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19302026/10/04 20:03:54 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign19312026/10/04 20:03:54 WARN Failed to register uploaded object key=bj7rgwa8caq7cij6hg47d8y189qn17by.ls error="server returned 404: 404 page not found\n"19322026/10/04 20:03:54 INFO Signed narinfos id=2 count=119332026/10/04 20:03:54 INFO Uploading 1 narinfos19342026/10/04 20:03:54 INFO Received complete push request method=POST path=/api/pushes/2/complete19352026/10/04 20:03:54 WARN Failed to register uploaded object key=bj7rgwa8caq7cij6hg47d8y189qn17by.narinfo error="server returned 404: 404 page not found\n"19362026/10/04 20:03:54 INFO Upload complete. (90ms)1937=== NAME TestNARDeduplicationMetadataUploadBug1938 metadata_upload_test.go:76: Retrieved narinfo from S3:1939 StorePath: /build/TestNARDeduplicationMetadataUploadBug2897621582/001/store/bj7rgwa8caq7cij6hg47d8y189qn17by-file2.txt1940 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1941 Compression: zstd1942 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1943 NarSize: 1601944 References: 1945 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1946 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1947 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1948 {"version":1,"root":{"type":"regular","size":44}}1949--- PASS: TestNARDeduplicationMetadataUploadBug (0.58s)1950--- PASS: TestPushWaitsForSweepHoldingRow (0.81s)1951=== NAME TestOrphanedObjectsGCStressTest1952 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1953 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion19542026/10/04 20:03:54 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=721.17464ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19552026/10/04 20:03:55 INFO lead: released remote=192.0.2.1:12341956--- PASS: TestLeadEndsOnShutdown (1.32s)1957--- PASS: TestUploadHandlersRejectOversizedBody (0.15s)1958 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.07s)1959 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.07s)1960 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (1.05s)1961--- PASS: TestPendingClosureWriteTimeout (0.00s)1962 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)1963 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)1964 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)1965 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.05s)1966=== NAME TestOrphanedObjectsGCStressTest1967 orphaned_objects_gc_test.go:509: Stress test completed successfully:1968 orphaned_objects_gc_test.go:510: - Active objects preserved: 201969 orphaned_objects_gc_test.go:511: - Objects deleted: 2101970 orphaned_objects_gc_test.go:512: - Total GC'd: 2101971--- PASS: TestOrphanedObjectsGCStressTest (1.94s)19722026/10/04 20:03:55 INFO lead: released remote=192.0.2.1:123419732026/10/04 20:03:55 INFO lead: acquired remote=192.0.2.1:123419742026/10/04 20:03:55 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=019752026/10/04 20:03:55 INFO Received create pin request method=POST path=/api/pins/myapp19762026/10/04 20:03:55 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2184448754/001/store/x45n1lk04q4r2il3dwfwsg3ck82s54al-pinned-file.txt narinfo_key=x45n1lk04q4r2il3dwfwsg3ck82s54al.narinfo19772026/10/04 20:03:55 INFO Starting cleanup of old closures method=DELETE path=/api/closures19782026/10/04 20:03:55 INFO Garbage collection started19792026/10/04 20:03:55 INFO Aborted multipart uploads count=0 kept=019802026/10/04 20:03:55 WARN Force mode enabled - objects will be deleted immediately without grace period19812026/10/04 20:03:55 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=019822026/10/04 20:03:55 INFO Vacuumed table table=pending_closures19832026/10/04 20:03:55 INFO Vacuumed table table=pending_objects19842026/10/04 20:03:55 INFO Vacuumed table table=multipart_uploads19852026/10/04 20:03:55 INFO Vacuumed table table=closures19862026/10/04 20:03:55 INFO Vacuumed table table=objects19872026/10/04 20:03:55 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.519519993s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19882026/10/04 20:03:55 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01989=== NAME TestClientIntegration1990 client_integration_test.go:323: Objects in database after GC:1991 client_integration_test.go:323: Successfully deleted all objects with GC --force1992--- PASS: TestClientIntegration (2.63s)19932026/10/04 20:03:56 INFO lead: released remote=192.0.2.1:12341994--- PASS: TestLeadElectsOneAndHandsOver (2.52s)1995--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.65s)19962026/10/04 20:03:57 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19972026/10/04 20:03:57 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=198.921227ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19982026/10/04 20:03:57 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=397.299463ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1999=== NAME TestPinProtectsFromGC2000 client_integration_test.go:840: Pin successfully protected closure from garbage collection2001--- PASS: TestPinProtectsFromGC (4.74s)20022026/10/04 20:03:57 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=860.124036ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20032026/10/04 20:03:58 WARN Rate limiter enabled after throttle name=s3-test rate=520042026/10/04 20:03:58 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2005=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2006 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102007 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002008--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.80s)20092026/10/04 20:03:58 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.581903931s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2010--- PASS: TestConnectWaitsForAPeerMigration (5.13s)20112026/10/04 20:03:59 INFO Aborted multipart uploads count=1 kept=020122026/10/04 20:03:59 INFO Received cleanup request method=DELETE path=/api/pending_closures20132026/10/04 20:03:59 INFO Aborted multipart uploads count=1 kept=02014--- PASS: TestPendingCleanupUsesOneCutoff (6.33s)20152026/10/04 20:04:00 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"20162026/10/04 20:04:00 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20172026/10/04 20:04:00 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=200.288275ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20182026/10/04 20:04:00 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=427.78111ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20192026/10/04 20:04:01 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=741.113944ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20202026/10/04 20:04:01 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.68410927s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20212026/10/04 20:04:03 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20222026/10/04 20:04:03 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=208.750269ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20232026/10/04 20:04:03 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=361.550171ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20242026/10/04 20:04:04 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=726.101797ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20252026/10/04 20:04:04 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.748229048s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2026--- PASS: TestClientErrorHandling (0.00s)2027 --- PASS: TestClientErrorHandling/InvalidStorePath (0.28s)2028 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.35s)2029 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.58s)2030PASS20312026-10-04 20:04:06.973 UTC [128] LOG: received smart shutdown request20322026-10-04 20:04:06.977 UTC [128] LOG: background worker "logical replication launcher" (PID 138) exited with exit code 120332026-10-04 20:04:06.990 UTC [133] LOG: shutting down20342026-10-04 20:04:06.990 UTC [133] LOG: checkpoint starting: shutdown immediate20352026-10-04 20:04:07.881 UTC [133] LOG: checkpoint complete: wrote 10834 buffers (66.1%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 26 recycled; write=0.185 s, sync=0.678 s, total=0.892 s; sync files=30664, longest=0.002 s, average=0.001 s; distance=423956 kB, estimate=423956 kB; lsn=0/1B56AD08, redo lsn=0/1B56AD0820362026-10-04 20:04:07.958 UTC [128] LOG: database system is shut down2037Running OIDC tests...2038=== RUN TestAudienceForIssuer2039=== PAUSE TestAudienceForIssuer2040=== RUN TestGlobMatch2041=== PAUSE TestGlobMatch2042=== RUN TestValidateToken_ValidToken2043=== PAUSE TestValidateToken_ValidToken2044=== RUN TestValidateToken_WrongAudience2045=== PAUSE TestValidateToken_WrongAudience2046=== RUN TestValidateToken_Expired2047=== PAUSE TestValidateToken_Expired2048=== RUN TestValidateToken_BoundClaimsMismatch2049=== PAUSE TestValidateToken_BoundClaimsMismatch2050=== RUN TestValidateToken_BoundSubjectMismatch2051=== PAUSE TestValidateToken_BoundSubjectMismatch2052=== RUN TestValidateToken_MultipleProviders2053=== PAUSE TestValidateToken_MultipleProviders2054=== RUN TestValidateToken_NoMatchingProvider2055=== PAUSE TestValidateToken_NoMatchingProvider2056=== RUN TestValidateToken_KubernetesServiceAccount2057=== PAUSE TestValidateToken_KubernetesServiceAccount2058=== RUN TestNewValidator_KubernetesRequiresCA2059=== PAUSE TestNewValidator_KubernetesRequiresCA2060=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2061=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2062=== RUN TestPins_ReservedForMatchingRule2063=== PAUSE TestPins_ReservedForMatchingRule2064=== RUN TestPins_TopLevelShorthand2065=== PAUSE TestPins_TopLevelShorthand2066=== RUN TestPins_ConfigValidation2067=== PAUSE TestPins_ConfigValidation2068=== RUN TestScopes_LegacyProviderDefaultsToWrite2069=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2070=== RUN TestScopes_Rules2071=== PAUSE TestScopes_Rules2072=== RUN TestScopes_ConfigValidation2073=== PAUSE TestScopes_ConfigValidation2074=== CONT TestAudienceForIssuer2075=== CONT TestValidateToken_KubernetesServiceAccount2076=== CONT TestPins_ConfigValidation2077=== CONT TestValidateToken_BoundClaimsMismatch2078--- PASS: TestAudienceForIssuer (0.00s)2079=== CONT TestValidateToken_Expired2080=== CONT TestValidateToken_WrongAudience2081=== CONT TestValidateToken_ValidToken2082=== CONT TestGlobMatch2083=== RUN TestGlobMatch/foo_foo2084=== PAUSE TestGlobMatch/foo_foo2085=== RUN TestGlobMatch/foo_bar2086=== PAUSE TestGlobMatch/foo_bar2087=== RUN TestGlobMatch/*_2088=== PAUSE TestGlobMatch/*_2089=== RUN TestGlobMatch/*_anything2090=== PAUSE TestGlobMatch/*_anything2091=== CONT TestScopes_Rules2092=== CONT TestScopes_ConfigValidation2093=== CONT TestPins_ReservedForMatchingRule2094=== CONT TestPins_TopLevelShorthand2095=== CONT TestValidateToken_MultipleProviders2096=== CONT TestValidateToken_NoMatchingProvider2097=== CONT TestScopes_LegacyProviderDefaultsToWrite2098=== CONT TestValidateToken_BoundSubjectMismatch2099=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2100=== CONT TestNewValidator_KubernetesRequiresCA2101=== RUN TestGlobMatch/foo*_foo2102=== PAUSE TestGlobMatch/foo*_foo2103=== RUN TestGlobMatch/foo*_foobar2104=== PAUSE TestGlobMatch/foo*_foobar2105=== RUN TestGlobMatch/foo*_bar2106=== PAUSE TestGlobMatch/foo*_bar2107=== RUN TestGlobMatch/*bar_bar2108=== PAUSE TestGlobMatch/*bar_bar2109--- PASS: TestPins_ConfigValidation (0.00s)2110=== RUN TestGlobMatch/*bar_foobar2111=== PAUSE TestGlobMatch/*bar_foobar2112=== RUN TestGlobMatch/*bar_foo2113=== PAUSE TestGlobMatch/*bar_foo2114=== RUN TestGlobMatch/foo*bar_foobar2115=== PAUSE TestGlobMatch/foo*bar_foobar2116=== RUN TestGlobMatch/foo*bar_foo123bar2117=== PAUSE TestGlobMatch/foo*bar_foo123bar2118=== RUN TestGlobMatch/foo*bar_foobarbaz2119=== PAUSE TestGlobMatch/foo*bar_foobarbaz2120=== RUN TestGlobMatch/*/*_foo/bar2121=== PAUSE TestGlobMatch/*/*_foo/bar2122=== RUN TestGlobMatch/*/*_foo2123=== PAUSE TestGlobMatch/*/*_foo2124=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2125=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2126=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02127=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02128=== RUN TestGlobMatch/refs/*/main_refs/heads/main2129=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2130=== RUN TestGlobMatch/fo?_foo2131=== PAUSE TestGlobMatch/fo?_foo2132=== RUN TestGlobMatch/fo?_fo2133=== PAUSE TestGlobMatch/fo?_fo2134=== RUN TestGlobMatch/fo?_fooo2135=== PAUSE TestGlobMatch/fo?_fooo2136=== RUN TestGlobMatch/?oo_foo2137=== PAUSE TestGlobMatch/?oo_foo2138=== RUN TestGlobMatch/?oo_boo2139=== PAUSE TestGlobMatch/?oo_boo2140=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2141=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2142=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2143=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2144=== CONT TestGlobMatch/foo_foo2145=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2146=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2147=== CONT TestGlobMatch/?oo_boo2148=== CONT TestGlobMatch/?oo_foo2149=== CONT TestGlobMatch/fo?_fooo2150=== CONT TestGlobMatch/fo?_fo2151=== CONT TestGlobMatch/fo?_foo2152=== CONT TestGlobMatch/refs/*/main_refs/heads/main2153--- PASS: TestScopes_ConfigValidation (0.00s)2154=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02155=== CONT TestGlobMatch/foo*_bar2156=== CONT TestGlobMatch/foo*_foobar2157=== CONT TestGlobMatch/foo*_foo2158=== CONT TestGlobMatch/*_anything2159=== CONT TestGlobMatch/*_2160=== CONT TestGlobMatch/foo_bar2161=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2162=== CONT TestGlobMatch/*/*_foo2163=== CONT TestGlobMatch/*/*_foo/bar2164=== CONT TestGlobMatch/foo*bar_foobarbaz2165=== CONT TestGlobMatch/foo*bar_foo123bar2166=== CONT TestGlobMatch/foo*bar_foobar2167=== CONT TestGlobMatch/*bar_foo2168=== CONT TestGlobMatch/*bar_foobar2169=== CONT TestGlobMatch/*bar_bar2170--- PASS: TestGlobMatch (0.00s)2171 --- PASS: TestGlobMatch/foo_foo (0.00s)2172 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2173 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2174 --- PASS: TestGlobMatch/?oo_boo (0.00s)2175 --- PASS: TestGlobMatch/?oo_foo (0.00s)2176 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2177 --- PASS: TestGlobMatch/fo?_fo (0.00s)2178 --- PASS: TestGlobMatch/fo?_foo (0.00s)2179 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2180 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2181 --- PASS: TestGlobMatch/foo*_bar (0.00s)2182 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2183 --- PASS: TestGlobMatch/foo*_foo (0.00s)2184 --- PASS: TestGlobMatch/*_anything (0.00s)2185 --- PASS: TestGlobMatch/*_ (0.00s)2186 --- PASS: TestGlobMatch/foo_bar (0.00s)2187 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2188 --- PASS: TestGlobMatch/*/*_foo (0.00s)2189 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2190 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2191 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2192 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2193 --- PASS: TestGlobMatch/*bar_bar (0.00s)2194 --- PASS: TestGlobMatch/*bar_foo (0.00s)2195 --- PASS: TestGlobMatch/*bar_foobar (0.00s)21962026/10/04 20:04:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39707/oidc2197--- PASS: TestValidateToken_WrongAudience (0.03s)21982026/10/04 20:04:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35679/oidc2199--- PASS: TestScopes_Rules (0.06s)22002026/10/04 20:04:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39097/oidc2201--- PASS: TestValidateToken_ValidToken (0.08s)22022026/10/04 20:04:09 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12322032026/10/04 20:04:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43431/oidc2204--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.10s)2205--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.10s)22062026/10/04 20:04:09 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:343152207--- PASS: TestValidateToken_KubernetesServiceAccount (0.12s)22082026/10/04 20:04:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45437/oidc2209--- PASS: TestValidateToken_BoundClaimsMismatch (0.13s)22102026/10/04 20:04:09 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:38135/oidc22112026/10/04 20:04:09 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:34547/oidc2212--- PASS: TestValidateToken_MultipleProviders (0.14s)22132026/10/04 20:04:09 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:35429/oidc22142026/10/04 20:04:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34249/oidc2215--- PASS: TestValidateToken_NoMatchingProvider (0.20s)2216--- PASS: TestPins_ReservedForMatchingRule (0.21s)22172026/10/04 20:04:09 http: TLS handshake error from 127.0.0.1:50532: remote error: tls: bad certificate2218--- PASS: TestNewValidator_KubernetesRequiresCA (0.21s)22192026/10/04 20:04:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40195/oidc2220--- PASS: TestValidateToken_BoundSubjectMismatch (0.26s)22212026/10/04 20:04:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41079/oidc2222--- PASS: TestPins_TopLevelShorthand (0.29s)22232026/10/04 20:04:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46741/oidc2224--- PASS: TestValidateToken_Expired (0.37s)2225PASS2226Running hook tests...2227=== RUN TestSendPathsEmpty2228=== PAUSE TestSendPathsEmpty2229=== RUN TestQueueEnqueueAndFetch2230=== PAUSE TestQueueEnqueueAndFetch2231=== RUN TestQueueDeduplication2232=== PAUSE TestQueueDeduplication2233=== RUN TestQueueRemove2234=== PAUSE TestQueueRemove2235=== RUN TestQueueFetchBatchLimit2236=== PAUSE TestQueueFetchBatchLimit2237=== RUN TestQueueRetryMovesToBack2238=== PAUSE TestQueueRetryMovesToBack2239=== RUN TestQueueFetchRemoveLifecycle2240=== PAUSE TestQueueFetchRemoveLifecycle2241=== RUN TestQueueConcurrentWriters2242=== PAUSE TestQueueConcurrentWriters2243=== RUN TestQueueRemoveLargeClosure2244=== PAUSE TestQueueRemoveLargeClosure2245=== RUN TestServerClientIntegration2246=== PAUSE TestServerClientIntegration2247=== RUN TestServerQueueError2248=== PAUSE TestServerQueueError2249=== RUN TestGetListenerSocketActivation2250 server_test.go:210: === RUN TestGetListenerSocketActivation2251 --- PASS: TestGetListenerSocketActivation (0.00s)2252 PASS2253 2254--- PASS: TestGetListenerSocketActivation (0.01s)2255=== RUN TestDrainIsolatesPoisonPath2256=== PAUSE TestDrainIsolatesPoisonPath2257=== RUN TestRunNotBlockedByPoisonHead2258=== PAUSE TestRunNotBlockedByPoisonHead2259=== RUN TestDrainGivesUpWhenServerDown2260=== PAUSE TestDrainGivesUpWhenServerDown2261=== RUN TestFailedPathPrunedByLaterClosure2262=== PAUSE TestFailedPathPrunedByLaterClosure2263=== RUN TestWorkerUploadsAndRemoves2264=== PAUSE TestWorkerUploadsAndRemoves2265=== RUN TestWorkerSkipsGCdPaths2266=== PAUSE TestWorkerSkipsGCdPaths2267=== RUN TestWorkerPrunesClosureDeps2268=== PAUSE TestWorkerPrunesClosureDeps2269=== RUN TestDrainTimeout2270=== PAUSE TestDrainTimeout2271=== CONT TestSendPathsEmpty2272=== CONT TestDrainIsolatesPoisonPath2273=== CONT TestDrainGivesUpWhenServerDown2274--- PASS: TestSendPathsEmpty (0.00s)2275=== CONT TestServerQueueError2276=== CONT TestServerClientIntegration2277=== CONT TestWorkerUploadsAndRemoves2278=== CONT TestDrainTimeout2279=== CONT TestQueueRemoveLargeClosure2280=== CONT TestWorkerPrunesClosureDeps2281=== CONT TestQueueConcurrentWriters2282=== CONT TestQueueFetchRemoveLifecycle22832026/10/04 20:04:09 ERROR Failed to queue paths error="permission denied" count=12284=== CONT TestWorkerSkipsGCdPaths2285=== CONT TestQueueRetryMovesToBack2286=== CONT TestQueueFetchBatchLimit2287=== CONT TestQueueDeduplication2288=== CONT TestQueueEnqueueAndFetch2289=== CONT TestQueueRemove2290=== CONT TestRunNotBlockedByPoisonHead2291=== CONT TestFailedPathPrunedByLaterClosure2292--- PASS: TestServerQueueError (0.00s)2293--- PASS: TestServerClientIntegration (0.00s)22942026/10/04 20:04:09 INFO Uploading batch count=122952026/10/04 20:04:09 ERROR Upload failed error="upload failed" count=122962026/10/04 20:04:09 INFO Uploading batch count=222972026/10/04 20:04:09 INFO Upload queue status pending=222982026/10/04 20:04:09 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths1226218202/002/nonexistent22992026/10/04 20:04:09 INFO Uploading batch count=123002026/10/04 20:04:09 INFO Uploading batch count=123012026/10/04 20:04:09 INFO Upload queue status pending=223022026/10/04 20:04:09 INFO Uploading batch count=223032026/10/04 20:04:09 ERROR Upload failed error="upload failed" count=223042026/10/04 20:04:09 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1263215191/002/a23052026/10/04 20:04:09 INFO Upload queue status pending=323062026/10/04 20:04:09 INFO Uploading batch count=423072026/10/04 20:04:09 ERROR Upload failed error="upload failed" count=423082026/10/04 20:04:09 INFO Uploading batch count=12309--- PASS: TestQueueFetchRemoveLifecycle (0.01s)23102026/10/04 20:04:09 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1263215191/002/b2311--- PASS: TestQueueRemove (0.01s)23122026/10/04 20:04:09 INFO Uploading batch count=12313--- PASS: TestQueueEnqueueAndFetch (0.01s)23142026/10/04 20:04:09 ERROR Upload failed error="upload failed" count=12315--- PASS: TestQueueRetryMovesToBack (0.01s)23162026/10/04 20:04:09 INFO Uploading batch count=223172026/10/04 20:04:09 INFO Upload queue status pending=223182026/10/04 20:04:09 INFO Uploading batch count=12319--- PASS: TestQueueFetchBatchLimit (0.01s)23202026/10/04 20:04:09 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath1292658036/002/bbb23212026/10/04 20:04:09 INFO Uploading batch count=223222026/10/04 20:04:09 ERROR Upload failed error="upload failed" count=22323--- PASS: TestQueueDeduplication (0.01s)23242026/10/04 20:04:09 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1263215191/002/c23252026/10/04 20:04:09 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1263215191/002/d2326--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)23272026/10/04 20:04:09 INFO Uploading batch count=123282026/10/04 20:04:09 ERROR Upload failed error="upload failed" count=123292026/10/04 20:04:09 INFO Uploading batch count=223302026/10/04 20:04:09 ERROR Upload failed error="upload failed" count=223312026/10/04 20:04:09 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1263215191/002/e23322026/10/04 20:04:09 INFO Uploading batch count=123332026/10/04 20:04:09 ERROR Upload failed error="upload failed" count=123342026/10/04 20:04:09 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1263215191/002/f23352026/10/04 20:04:09 INFO Uploading batch count=123362026/10/04 20:04:09 ERROR Upload failed error="upload failed" count=123372026/10/04 20:04:09 ERROR Drain finished with paths left in queue remaining=1023382026/10/04 20:04:09 ERROR Drain finished with paths left in queue remaining=12339--- PASS: TestDrainIsolatesPoisonPath (0.02s)2340--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2341--- PASS: TestWorkerSkipsGCdPaths (0.03s)2342--- PASS: TestWorkerUploadsAndRemoves (0.03s)2343--- PASS: TestWorkerPrunesClosureDeps (0.03s)2344--- PASS: TestQueueRemoveLargeClosure (0.15s)2345--- PASS: TestQueueConcurrentWriters (0.15s)23462026/10/04 20:04:10 ERROR Upload failed error="context deadline exceeded" count=223472026/10/04 20:04:10 ERROR Drain finished with paths left in queue remaining=42348--- PASS: TestDrainTimeout (0.21s)23492026/10/04 20:04:10 INFO Uploading batch count=123502026/10/04 20:04:10 INFO Uploading batch count=123512026/10/04 20:04:10 INFO Uploading batch count=123522026/10/04 20:04:10 ERROR Upload failed error="upload failed" count=123532026/10/04 20:04:10 INFO Uploading batch count=123542026/10/04 20:04:10 ERROR Upload failed error="upload failed" count=123552026/10/04 20:04:10 INFO Uploading batch count=123562026/10/04 20:04:10 ERROR Upload failed error="upload failed" count=123572026/10/04 20:04:10 INFO Uploading batch count=123582026/10/04 20:04:10 ERROR Upload failed error="upload failed" count=123592026/10/04 20:04:10 ERROR Drain finished with paths left in queue remaining=12360--- PASS: TestRunNotBlockedByPoisonHead (1.02s)2361PASS