niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #163
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestCaseHackSuffix5=== PAUSE TestCaseHackSuffix6=== RUN TestFilterOversizedClosures7=== PAUSE TestFilterOversizedClosures8=== RUN TestPartSizeForNAR9=== PAUSE TestPartSizeForNAR10=== RUN TestUploadMultipart_SupersededByPeer11=== PAUSE TestUploadMultipart_SupersededByPeer12=== RUN TestDumpPathMatchesNix13=== PAUSE TestDumpPathMatchesNix14=== RUN TestDumpPathSingleFile15=== PAUSE TestDumpPathSingleFile16=== RUN TestDumpPathWriterError17=== PAUSE TestDumpPathWriterError18=== RUN TestEncodeNixBase3219=== PAUSE TestEncodeNixBase3220=== RUN TestEncodeNixBase32WithRealHash21=== PAUSE TestEncodeNixBase32WithRealHash22=== RUN TestConvertHashToNix3223=== PAUSE TestConvertHashToNix3224=== RUN TestGetStorePathHash25=== PAUSE TestGetStorePathHash26=== RUN TestPathInfoHashCompatibility27=== PAUSE TestPathInfoHashCompatibility28=== RUN TestParsePathInfoJSON29=== PAUSE TestParsePathInfoJSON30=== RUN TestParsePathInfoJSONMultiplePaths31=== PAUSE TestParsePathInfoJSONMultiplePaths32=== RUN TestPathInfoCACompatibility33=== PAUSE TestPathInfoCACompatibility34=== RUN TestPrepareClosuresNoClosure35=== PAUSE TestPrepareClosuresNoClosure36=== RUN TestChunkStorePaths37=== PAUSE TestChunkStorePaths38=== RUN TestRateLimiterFeedback39=== PAUSE TestRateLimiterFeedback40=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess41=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess42=== RUN TestResolveStorePath43=== PAUSE TestResolveStorePath44=== RUN TestDoWithRetry_BodyReplayedViaGetBody45=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody46=== RUN TestShellSplit47=== PAUSE TestShellSplit48=== RUN TestShellSplitErrors49=== PAUSE TestShellSplitErrors50=== RUN TestSetClientTLS51=== PAUSE TestSetClientTLS52=== RUN TestSetClientTLSDoesNotMutateDefaultTransport53=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport54=== RUN TestSetClientTLSErrors55=== PAUSE TestSetClientTLSErrors56=== RUN TestStaticToken57=== PAUSE TestStaticToken58=== RUN TestFileTokenReadsAndCaches59=== PAUSE TestFileTokenReadsAndCaches60=== RUN TestFileTokenMissing61=== PAUSE TestFileTokenMissing62=== RUN TestFileTokenEmpty63=== PAUSE TestFileTokenEmpty64=== RUN TestScriptTokenNoExpiryRerunsEveryCall65=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall66=== RUN TestScriptTokenCachesUntilRefresh67=== PAUSE TestScriptTokenCachesUntilRefresh68=== RUN TestScriptTokenEmptyToken69=== PAUSE TestScriptTokenEmptyToken70=== RUN TestScriptTokenBadJSON71=== PAUSE TestScriptTokenBadJSON72=== RUN TestScriptTokenScriptFails73=== PAUSE TestScriptTokenScriptFails74=== RUN TestScriptTokenEmptyCommand75=== PAUSE TestScriptTokenEmptyCommand76=== CONT TestDoServerRequestAttachesToken77=== CONT TestFileTokenReadsAndCaches78=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess79=== CONT TestShellSplitErrors80=== CONT TestSetClientTLS81--- PASS: TestShellSplitErrors (0.00s)82=== CONT TestShellSplit83--- PASS: TestShellSplit (0.00s)84=== CONT TestDoWithRetry_BodyReplayedViaGetBody85=== CONT TestConvertHashToNix3286=== RUN TestConvertHashToNix32/SRI_format_to_Nix3287=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix3288=== RUN TestConvertHashToNix32/already_Nix32_format89=== PAUSE TestConvertHashToNix32/already_Nix32_format90=== RUN TestConvertHashToNix32/invalid_format91=== PAUSE TestConvertHashToNix32/invalid_format92=== CONT TestDumpPathMatchesNix93=== CONT TestDumpPathSingleFile942026/08/27 18:11:40 WARN Rate limiter enabled after throttle name=server-test rate=595--- PASS: TestFileTokenReadsAndCaches (0.00s)96=== CONT TestResolveStorePath97=== CONT TestEncodeNixBase32WithRealHash98--- PASS: TestEncodeNixBase32WithRealHash (0.00s)99=== CONT TestSetClientTLSErrors100=== CONT TestEncodeNixBase32101=== RUN TestEncodeNixBase32/test_string_hash102=== PAUSE TestEncodeNixBase32/test_string_hash103=== RUN TestEncodeNixBase32/empty_input104=== PAUSE TestEncodeNixBase32/empty_input105=== CONT TestDumpPathWriterError106=== CONT TestStaticToken107--- PASS: TestStaticToken (0.00s)108=== CONT TestScriptTokenNoExpiryRerunsEveryCall109=== RUN TestSetClientTLSErrors/missing_cert_file110=== PAUSE TestSetClientTLSErrors/missing_cert_file111=== RUN TestSetClientTLSErrors/missing_key_file112--- PASS: TestResolveStorePath (0.00s)113=== CONT TestScriptTokenCachesUntilRefresh114=== PAUSE TestSetClientTLSErrors/missing_key_file115=== RUN TestSetClientTLSErrors/missing_ca_file116=== PAUSE TestSetClientTLSErrors/missing_ca_file117=== RUN TestSetClientTLSErrors/invalid_ca_file118=== PAUSE TestSetClientTLSErrors/invalid_ca_file1192026/08/27 18:11:40 WARN Rate limiter enabled after throttle name=server-test rate=51202026/08/27 18:11:40 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:57042121=== CONT TestScriptTokenScriptFails122--- PASS: TestDoServerRequestAttachesToken (0.01s)123=== CONT TestScriptTokenEmptyCommand124--- PASS: TestScriptTokenEmptyCommand (0.00s)125=== CONT TestFileTokenEmpty1262026/08/27 18:11:40 WARN Rate limiter backed off name=server-test rate=51272026/08/27 18:11:40 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:57042128--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)129=== CONT TestScriptTokenBadJSON130--- PASS: TestFileTokenEmpty (0.00s)131=== CONT TestPathInfoCACompatibility132=== RUN TestPathInfoCACompatibility/null_ca_field133=== PAUSE TestPathInfoCACompatibility/null_ca_field134=== RUN TestPathInfoCACompatibility/old_string_format_-_text135=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text136=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive137=== RUN TestSetClientTLS/rejects_connection_without_client_cert138=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert139=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive140=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA141=== RUN TestPathInfoCACompatibility/new_structured_format_-_text142=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA143=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text144=== RUN TestSetClientTLS/preserves_debug_logging_transport145=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method146=== PAUSE TestSetClientTLS/preserves_debug_logging_transport147=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method148=== CONT TestRateLimiterFeedback149=== RUN TestRateLimiterFeedback/429_enables_limiter150=== PAUSE TestRateLimiterFeedback/429_enables_limiter151=== RUN TestRateLimiterFeedback/503_enables_limiter152=== PAUSE TestRateLimiterFeedback/503_enables_limiter153=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter154=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter155=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter156=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter157=== CONT TestChunkStorePaths158=== RUN TestChunkStorePaths/keeps_a_small_set_in_one_chunk159=== PAUSE TestChunkStorePaths/keeps_a_small_set_in_one_chunk160=== RUN TestChunkStorePaths/splits_on_the_byte_budget_and_preserves_every_path161=== PAUSE TestChunkStorePaths/splits_on_the_byte_budget_and_preserves_every_path162=== RUN TestChunkStorePaths/emits_an_oversized_path_rather_than_dropping_it163=== PAUSE TestChunkStorePaths/emits_an_oversized_path_rather_than_dropping_it164=== RUN TestChunkStorePaths/handles_an_empty_input165=== PAUSE TestChunkStorePaths/handles_an_empty_input166=== CONT TestPrepareClosuresNoClosure167=== CONT TestSetClientTLSDoesNotMutateDefaultTransport168=== RUN TestPrepareClosuresNoClosure/closure_mode_pulls_in_transitive_references169=== PAUSE TestPrepareClosuresNoClosure/closure_mode_pulls_in_transitive_references170=== RUN TestPrepareClosuresNoClosure/no-closure_keeps_each_path_self-contained171=== PAUSE TestPrepareClosuresNoClosure/no-closure_keeps_each_path_self-contained172=== RUN TestPrepareClosuresNoClosure/no-closure_narinfos_still_record_their_references173=== PAUSE TestPrepareClosuresNoClosure/no-closure_narinfos_still_record_their_references174=== CONT TestParsePathInfoJSON175=== RUN TestParsePathInfoJSON/Nix_format176=== PAUSE TestParsePathInfoJSON/Nix_format177=== RUN TestParsePathInfoJSON/Lix_format178=== PAUSE TestParsePathInfoJSON/Lix_format179=== RUN TestParsePathInfoJSON/empty_input180=== PAUSE TestParsePathInfoJSON/empty_input181=== RUN TestParsePathInfoJSON/whitespace_only182=== PAUSE TestParsePathInfoJSON/whitespace_only183=== RUN TestParsePathInfoJSON/invalid_JSON184=== PAUSE TestParsePathInfoJSON/invalid_JSON185=== CONT TestParsePathInfoJSONMultiplePaths186=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths187=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths188=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths189=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths190=== CONT TestPathInfoHashCompatibility191=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)192=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)193=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon194=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon195=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI196=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI197=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512198=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512199=== CONT TestFilterOversizedClosures200=== RUN TestFilterOversizedClosures/no_limit_keeps_everything201=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything202=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped203=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped204=== RUN TestFilterOversizedClosures/all_closures_skipped205=== PAUSE TestFilterOversizedClosures/all_closures_skipped206=== RUN TestFilterOversizedClosures/no-closure_judges_each_path_on_its_own_size207=== PAUSE TestFilterOversizedClosures/no-closure_judges_each_path_on_its_own_size208=== CONT TestUploadMultipart_SupersededByPeer209=== RUN TestUploadMultipart_SupersededByPeer/exists210=== PAUSE TestUploadMultipart_SupersededByPeer/exists211=== RUN TestUploadMultipart_SupersededByPeer/missing212=== PAUSE TestUploadMultipart_SupersededByPeer/missing213=== CONT TestPartSizeForNAR214=== RUN TestPartSizeForNAR/zero_stays_at_minimum215=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum216=== RUN TestPartSizeForNAR/small_stays_at_minimum217=== PAUSE TestPartSizeForNAR/small_stays_at_minimum218=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum219=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum220=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts221=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts222=== RUN TestPartSizeForNAR/1_TiB223=== PAUSE TestPartSizeForNAR/1_TiB224=== RUN TestPartSizeForNAR/5_TiB_S3_max_object225=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object226=== RUN TestPartSizeForNAR/capped_at_5_GiB227=== PAUSE TestPartSizeForNAR/capped_at_5_GiB228=== CONT TestFileTokenMissing229--- PASS: TestFileTokenMissing (0.00s)230=== CONT TestCaseHackSuffix231--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)232=== CONT TestGetStorePathHash233=== RUN TestGetStorePathHash/valid_store_path234=== PAUSE TestGetStorePathHash/valid_store_path235=== RUN TestGetStorePathHash/basename_without_hyphen_should_error236=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error237=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error238=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error239=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error240=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error241=== CONT TestConvertHashToNix32/SRI_format_to_Nix32242=== CONT TestScriptTokenEmptyToken243--- PASS: TestScriptTokenScriptFails (0.01s)244=== CONT TestConvertHashToNix32/invalid_format245=== CONT TestConvertHashToNix32/already_Nix32_format246--- PASS: TestConvertHashToNix32 (0.00s)247 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)248 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)249 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)250=== CONT TestEncodeNixBase32/test_string_hash251=== CONT TestEncodeNixBase32/empty_input252--- PASS: TestEncodeNixBase32 (0.00s)253 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)254 --- PASS: TestEncodeNixBase32/empty_input (0.00s)255=== CONT TestSetClientTLSErrors/missing_cert_file256=== CONT TestSetClientTLSErrors/missing_ca_file257=== CONT TestSetClientTLSErrors/invalid_ca_file258=== CONT TestSetClientTLSErrors/missing_key_file259=== CONT TestSetClientTLS/rejects_connection_without_client_cert260--- PASS: TestSetClientTLSErrors (0.01s)261 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)262 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)263 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)264 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)265--- PASS: TestScriptTokenBadJSON (0.01s)266=== CONT TestPathInfoCACompatibility/null_ca_field267=== CONT TestSetClientTLS/preserves_debug_logging_transport268=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA269=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method270=== CONT TestPathInfoCACompatibility/new_structured_format_-_text271--- PASS: TestScriptTokenEmptyToken (0.01s)272=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive273=== CONT TestPathInfoCACompatibility/old_string_format_-_text274=== CONT TestRateLimiterFeedback/429_enables_limiter275=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter276--- PASS: TestPathInfoCACompatibility (0.00s)277 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)278 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)279 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)280 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)281 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)2822026/08/27 18:11:40 WARN Rate limiter enabled after throttle name=server-test rate=52832026/08/27 18:11:40 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:57051284=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2852026/08/27 18:11:40 WARN Rate limiter backed off name=server-test rate=5286=== CONT TestRateLimiterFeedback/503_enables_limiter2872026/08/27 18:11:40 WARN Rate limiter enabled after throttle name=server-test rate=52882026/08/27 18:11:40 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:57056289=== CONT TestChunkStorePaths/keeps_a_small_set_in_one_chunk290=== CONT TestChunkStorePaths/handles_an_empty_input291=== CONT TestChunkStorePaths/emits_an_oversized_path_rather_than_dropping_it292=== CONT TestChunkStorePaths/splits_on_the_byte_budget_and_preserves_every_path293=== CONT TestPrepareClosuresNoClosure/closure_mode_pulls_in_transitive_references294--- PASS: TestChunkStorePaths (0.00s)295 --- PASS: TestChunkStorePaths/keeps_a_small_set_in_one_chunk (0.00s)296 --- PASS: TestChunkStorePaths/handles_an_empty_input (0.00s)297 --- PASS: TestChunkStorePaths/emits_an_oversized_path_rather_than_dropping_it (0.00s)298 --- PASS: TestChunkStorePaths/splits_on_the_byte_budget_and_preserves_every_path (0.00s)299=== CONT TestParsePathInfoJSON/Nix_format300=== CONT TestPrepareClosuresNoClosure/no-closure_narinfos_still_record_their_references301=== CONT TestPrepareClosuresNoClosure/no-closure_keeps_each_path_self-contained302--- PASS: TestPrepareClosuresNoClosure (0.00s)303 --- PASS: TestPrepareClosuresNoClosure/closure_mode_pulls_in_transitive_references (0.00s)304 --- PASS: TestPrepareClosuresNoClosure/no-closure_narinfos_still_record_their_references (0.00s)305 --- PASS: TestPrepareClosuresNoClosure/no-closure_keeps_each_path_self-contained (0.00s)306=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths3072026/08/27 18:11:40 WARN Rate limiter backed off name=server-test rate=5308=== CONT TestParsePathInfoJSON/invalid_JSON309--- PASS: TestRateLimiterFeedback (0.00s)310 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)311 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)312 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)313 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)314=== CONT TestParsePathInfoJSON/whitespace_only315=== CONT TestParsePathInfoJSON/Lix_format316=== CONT TestParsePathInfoJSON/empty_input317=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)318=== CONT TestFilterOversizedClosures/no_limit_keeps_everything319=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512320--- PASS: TestParsePathInfoJSON (0.00s)321 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)322 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)323 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)324 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)325 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)326=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths327=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI328--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)329 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)330 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)331=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon332--- PASS: TestPathInfoHashCompatibility (0.00s)333 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)334 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)335 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)336 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)337=== CONT TestUploadMultipart_SupersededByPeer/exists338=== CONT TestFilterOversizedClosures/no-closure_judges_each_path_on_its_own_size3392026/08/27 18:11:40 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-vm-image oversized_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-vm-image nar_size=5000 max_nar_size=2000340=== CONT TestFilterOversizedClosures/all_closures_skipped3412026/08/27 18:11:40 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=50342=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3432026/08/27 18:11:40 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=2000344=== CONT TestPartSizeForNAR/zero_stays_at_minimum345=== CONT TestUploadMultipart_SupersededByPeer/missing346--- PASS: TestFilterOversizedClosures (0.00s)347 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)348 --- PASS: TestFilterOversizedClosures/no-closure_judges_each_path_on_its_own_size (0.00s)349 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)350 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)351=== CONT TestPartSizeForNAR/1_TiB352=== CONT TestPartSizeForNAR/capped_at_5_GiB353=== CONT TestPartSizeForNAR/5_TiB_S3_max_object354=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum355=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts356=== CONT TestPartSizeForNAR/small_stays_at_minimum357--- PASS: TestPartSizeForNAR (0.00s)358 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)359 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)360 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)361 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)362 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)363 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)364 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)365=== CONT TestGetStorePathHash/valid_store_path366=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error367=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error368=== CONT TestGetStorePathHash/basename_without_hyphen_should_error369--- PASS: TestGetStorePathHash (0.00s)370 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)371 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)372 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)373 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)374--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)375 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)376 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)3772026/08/27 18:11:40 http: TLS handshake error from 127.0.0.1:57048: remote error: tls: bad certificate378--- PASS: TestSetClientTLS (0.02s)379 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)380 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)381 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)382--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)383--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)384--- PASS: TestDumpPathWriterError (0.05s)385--- PASS: TestDumpPathSingleFile (0.17s)386--- PASS: TestCaseHackSuffix (0.16s)387--- PASS: TestDumpPathMatchesNix (0.18s)388--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)389PASS390Running server tests...391The files belonging to this database system will be owned by user "_nixbld1".392This user must also own the server process.393394The database cluster will be initialized with locale "C".395The default database encoding has accordingly been set to "SQL_ASCII".396The default text search configuration will be set to "english".397398Data page checksums are enabled.399400creating directory /nix/var/nix/builds/nix-4772-2940262897/postgres2587301562/data ... ok401creating subdirectories ... ok402selecting dynamic shared memory implementation ... posix403selecting default "max_connections" ... 100404selecting default "shared_buffers" ... 128MB405selecting default time zone ... UTC406creating configuration files ... ok407running bootstrap script ... ok408performing post-bootstrap initialization ... ok409syncing data to disk ... ok410411initdb: warning: enabling "trust" authentication for local connections412initdb: 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.413414Success. You can now start the database server using:415416 pg_ctl -D /nix/var/nix/builds/nix-4772-2940262897/postgres2587301562/data -l logfile start4174182026-08-27 18:11:41.995 UTC [4808] LOG: starting PostgreSQL 18.4 on aarch64-apple-darwin25.5.0, compiled by clang version 21.1.8, 64-bit4192026-08-27 18:11:41.995 UTC [4808] LOG: listening on Unix socket "/nix/var/nix/builds/nix-4772-2940262897/postgres2587301562/.s.PGSQL.5432"4202026-08-27 18:11:41.997 UTC [4815] LOG: database system was shut down at 2026-08-27 18:11:41 UTC4212026-08-27 18:11:41.997 UTC [4816] FATAL: the database system is starting up422/nix/var/nix/builds/nix-4772-2940262897/postgres2587301562:5432 - rejecting connections4232026-08-27 18:11:41.998 UTC [4808] LOG: database system is ready to accept connections424/nix/var/nix/builds/nix-4772-2940262897/postgres2587301562:5432 - accepting connections425=== RUN TestService_AuthMiddleware426=== PAUSE TestService_AuthMiddleware427=== RUN TestService_AuthMiddleware_MTLSProxyHeader428=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader429=== RUN TestService_AuthMiddleware_MTLSBoundSubjects430=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects431=== RUN TestService_ReadAuthMiddleware432=== PAUSE TestService_ReadAuthMiddleware433=== RUN TestService_AuthMiddleware_OIDC434=== PAUSE TestService_AuthMiddleware_OIDC435=== RUN TestService_RequireScope_OIDC436=== PAUSE TestService_RequireScope_OIDC437=== RUN TestService_ReadScope_PublicByDefault438=== PAUSE TestService_ReadScope_PublicByDefault439=== RUN TestCacheConfigHandler440=== PAUSE TestCacheConfigHandler441=== RUN TestCacheStatsHandler442=== PAUSE TestCacheStatsHandler443=== RUN TestClientCADerivations444=== PAUSE TestClientCADerivations445=== RUN TestClientErrorHandling446=== PAUSE TestClientErrorHandling447=== RUN TestClientIntegration448=== PAUSE TestClientIntegration449=== RUN TestClientMultipleUploads450=== PAUSE TestClientMultipleUploads451=== RUN TestClientWithDependencies452=== PAUSE TestClientWithDependencies453=== RUN TestPinProtectsFromGC454=== PAUSE TestPinProtectsFromGC455=== RUN TestResolveDBConnectionString456=== PAUSE TestResolveDBConnectionString457=== RUN TestGCAdvisoryLockBlocksConcurrentRun4582026-08-27 18:11:42.287 UTC [4827] ERROR: relation "goose_db_version" does not exist at character 364592026-08-27 18:11:42.287 UTC [4827] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4602026/08/27 18:11:42 OK 20241026095416_initial_model.sql (4.06ms)4612026/08/27 18:11:42 OK 20251210153512_drop_unused_gin_index.sql (683.33µs)4622026/08/27 18:11:42 OK 20251218171726_add_pins.sql (880.88µs)4632026/08/27 18:11:42 OK 20260628120000_add_object_size_and_stats.sql (1.29ms)4642026/08/27 18:11:42 goose: successfully migrated database to version: 202606281200004652026/08/27 18:11:42 OK 1_commit_pending_closure.sql (1.61ms)4662026/08/27 18:11:42 OK 2_object_stats_trigger.sql (254.08µs)4672026/08/27 18:11:42 goose: up to current file version: 2468--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.29s)469=== RUN TestGCBugBareHashReferences470=== PAUSE TestGCBugBareHashReferences471=== RUN TestGCMetrics472=== PAUSE TestGCMetrics473=== RUN TestGCTaskStore_StartNew474=== PAUSE TestGCTaskStore_StartNew475=== RUN TestGCTaskStore_DeduplicateSameParams476=== PAUSE TestGCTaskStore_DeduplicateSameParams477=== RUN TestGCTaskStore_ConflictDifferentParams478=== PAUSE TestGCTaskStore_ConflictDifferentParams479=== RUN TestGCTaskStore_GetEmpty480=== PAUSE TestGCTaskStore_GetEmpty481=== RUN TestGCTaskStore_GetReturnsLatest482=== PAUSE TestGCTaskStore_GetReturnsLatest483=== RUN TestGCTaskStore_CompletedAllowsNewTask484=== PAUSE TestGCTaskStore_CompletedAllowsNewTask485=== RUN TestGCTaskStore_PhaseUpdates486=== PAUSE TestGCTaskStore_PhaseUpdates487=== RUN TestGCTaskStore_Fail488=== PAUSE TestGCTaskStore_Fail489=== RUN TestGracefulShutdownDrainsInflight490=== PAUSE TestGracefulShutdownDrainsInflight491=== RUN TestService_healthCheckHandler492=== PAUSE TestService_healthCheckHandler493=== RUN TestService_readinessHandler494=== PAUSE TestService_readinessHandler495=== RUN TestGenerateLandingPage496=== PAUSE TestGenerateLandingPage497=== RUN TestCacheConfigHandlerMaxNarSize498=== PAUSE TestCacheConfigHandlerMaxNarSize499=== RUN TestCreatePendingClosureRejectsOversizedNAR500=== PAUSE TestCreatePendingClosureRejectsOversizedNAR501=== RUN TestNARDeduplicationMetadataUploadBug502=== PAUSE TestNARDeduplicationMetadataUploadBug503=== RUN TestMetricsInventory504=== PAUSE TestMetricsInventory505=== RUN TestService_NativeMTLS506=== PAUSE TestService_NativeMTLS507=== RUN TestServerTLSConfig508=== PAUSE TestServerTLSConfig509=== RUN TestMultipartCleanup510=== PAUSE TestMultipartCleanup511=== RUN TestNoClosurePushCreatesIndependentGCRoots512=== PAUSE TestNoClosurePushCreatesIndependentGCRoots513=== RUN TestNoClosurePushKeepsReferencedObjectsReachable514=== PAUSE TestNoClosurePushKeepsReferencedObjectsReachable515=== RUN TestObjectStatsTrigger516=== PAUSE TestObjectStatsTrigger517=== RUN TestOrphanedObjectsGC518=== PAUSE TestOrphanedObjectsGC519=== RUN TestOrphanedObjectsGCStressTest520=== PAUSE TestOrphanedObjectsGCStressTest521=== RUN TestResurrectedObjectNotDeleted522=== PAUSE TestResurrectedObjectNotDeleted523=== RUN TestParseSingleRange524=== PAUSE TestParseSingleRange525=== RUN TestIsValidCachePath526=== PAUSE TestIsValidCachePath527=== RUN TestReadProxyNarinfo528=== PAUSE TestReadProxyNarinfo529=== RUN TestReadProxyNarinfoAlreadyDecompressed530=== PAUSE TestReadProxyNarinfoAlreadyDecompressed531=== RUN TestReadProxyNarStreaming532=== PAUSE TestReadProxyNarStreaming533=== RUN TestReadProxy404534=== PAUSE TestReadProxy404535=== RUN TestReadProxyInvalidPath536=== PAUSE TestReadProxyInvalidPath537=== RUN TestReadProxyHead538=== PAUSE TestReadProxyHead539=== RUN TestReadProxyConditionalGet540=== PAUSE TestReadProxyConditionalGet541=== RUN TestReadProxyRootRedirectsToIndexHTML542=== PAUSE TestReadProxyRootRedirectsToIndexHTML543=== RUN TestReadProxyDisabled544=== PAUSE TestReadProxyDisabled545=== RUN TestReadRedirectNar546=== PAUSE TestReadRedirectNar547=== RUN TestReadRedirectKeepsNarinfoProxied548=== PAUSE TestReadRedirectKeepsNarinfoProxied549=== RUN TestReadProxyRangeRequest550=== PAUSE TestReadProxyRangeRequest551=== RUN TestRedundantMultipartUpload552=== PAUSE TestRedundantMultipartUpload553=== RUN TestCompleteMultipartUpload_ErrorButObjectExists554=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists555=== RUN TestCompletedNarNotReofferedAcrossClosures556=== PAUSE TestCompletedNarNotReofferedAcrossClosures557=== RUN TestPresignedUploadRegisteredBeforeCommit558=== PAUSE TestPresignedUploadRegisteredBeforeCommit559=== RUN TestService_Rustfstest560=== PAUSE TestService_Rustfstest561=== RUN TestParseSize562=== PAUSE TestParseSize563=== RUN TestSkippedUploadsHandler564=== PAUSE TestSkippedUploadsHandler565=== RUN TestSystemdListenerNotActivated566--- PASS: TestSystemdListenerNotActivated (0.00s)567=== RUN TestWatchdogBeatsWhenHealthy568--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)569=== RUN TestWatchdogSkipsWhenUnhealthy5702026/08/27 18:11:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5712026/08/27 18:11:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5722026/08/27 18:11:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5732026/08/27 18:11:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5742026/08/27 18:11:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5752026/08/27 18:11:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5762026/08/27 18:11:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5772026/08/27 18:11:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5782026/08/27 18:11:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"579--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)580=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle581=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle582=== RUN TestProxyWriteTimeout583=== PAUSE TestProxyWriteTimeout584=== RUN TestIsValidUploadKey585=== PAUSE TestIsValidUploadKey586=== RUN TestUploadHandlersRejectInvalidKeys587=== PAUSE TestUploadHandlersRejectInvalidKeys588=== RUN TestUploadHandlersRejectOversizedBody589=== PAUSE TestUploadHandlersRejectOversizedBody590=== RUN TestService_cleanupPendingClosuresHandler591=== PAUSE TestService_cleanupPendingClosuresHandler592=== RUN TestService_createPendingClosureHandler593=== PAUSE TestService_createPendingClosureHandler594=== RUN TestService_verifyS3Integrity595=== PAUSE TestService_verifyS3Integrity596=== RUN TestCompleteMultipartUnregistered597=== PAUSE TestCompleteMultipartUnregistered598=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT599=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT600=== CONT TestService_AuthMiddleware601=== CONT TestService_verifyS3Integrity602=== CONT TestCompleteMultipartUpload_ErrorButObjectExists603=== CONT TestProxyWriteTimeout604=== RUN TestProxyWriteTimeout/narinfo605=== CONT TestReadProxyInvalidPath606=== CONT TestReadProxyRootRedirectsToIndexHTML607=== CONT TestReadProxyNarinfo608=== PAUSE TestProxyWriteTimeout/narinfo609=== CONT TestCompleteMultipartUnregistered610=== CONT TestService_createPendingClosureHandler611=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT612=== RUN TestProxyWriteTimeout/1_GiB_nar613=== PAUSE TestProxyWriteTimeout/1_GiB_nar614=== RUN TestProxyWriteTimeout/10_GiB_nar615=== PAUSE TestProxyWriteTimeout/10_GiB_nar616=== RUN TestProxyWriteTimeout/unknown_size617=== PAUSE TestProxyWriteTimeout/unknown_size618=== CONT TestService_cleanupPendingClosuresHandler6192026-08-27 18:11:43.061 UTC [4912] ERROR: relation "goose_db_version" does not exist at character 366202026-08-27 18:11:43.061 UTC [4912] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6212026-08-27 18:11:43.063 UTC [4913] ERROR: relation "goose_db_version" does not exist at character 366222026-08-27 18:11:43.063 UTC [4913] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6232026-08-27 18:11:43.066 UTC [4915] ERROR: relation "goose_db_version" does not exist at character 366242026-08-27 18:11:43.066 UTC [4915] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6252026-08-27 18:11:43.067 UTC [4914] ERROR: relation "goose_db_version" does not exist at character 366262026-08-27 18:11:43.067 UTC [4914] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6272026-08-27 18:11:43.067 UTC [4917] ERROR: relation "goose_db_version" does not exist at character 366282026-08-27 18:11:43.067 UTC [4917] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6292026-08-27 18:11:43.068 UTC [4916] ERROR: relation "goose_db_version" does not exist at character 366302026-08-27 18:11:43.068 UTC [4916] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6312026-08-27 18:11:43.069 UTC [4918] ERROR: relation "goose_db_version" does not exist at character 366322026-08-27 18:11:43.069 UTC [4918] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6332026-08-27 18:11:43.069 UTC [4919] ERROR: relation "goose_db_version" does not exist at character 366342026-08-27 18:11:43.069 UTC [4919] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6352026-08-27 18:11:43.070 UTC [4921] ERROR: relation "goose_db_version" does not exist at character 366362026-08-27 18:11:43.070 UTC [4921] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6372026-08-27 18:11:43.070 UTC [4920] ERROR: relation "goose_db_version" does not exist at character 366382026-08-27 18:11:43.070 UTC [4920] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6392026/08/27 18:11:43 OK 20241026095416_initial_model.sql (5.93ms)6402026/08/27 18:11:43 OK 20251210153512_drop_unused_gin_index.sql (887.88µs)6412026/08/27 18:11:43 OK 20251218171726_add_pins.sql (1.89ms)6422026/08/27 18:11:43 OK 20241026095416_initial_model.sql (9.28ms)6432026/08/27 18:11:43 OK 20251210153512_drop_unused_gin_index.sql (867.42µs)6442026/08/27 18:11:43 OK 20260628120000_add_object_size_and_stats.sql (2.12ms)6452026/08/27 18:11:43 goose: successfully migrated database to version: 202606281200006462026/08/27 18:11:43 OK 20241026095416_initial_model.sql (6.81ms)6472026/08/27 18:11:43 OK 20241026095416_initial_model.sql (7.28ms)6482026/08/27 18:11:43 OK 1_commit_pending_closure.sql (1.14ms)6492026/08/27 18:11:43 OK 20251210153512_drop_unused_gin_index.sql (647.04µs)6502026/08/27 18:11:43 OK 20251218171726_add_pins.sql (2.07ms)6512026/08/27 18:11:43 OK 2_object_stats_trigger.sql (521.29µs)6522026/08/27 18:11:43 goose: up to current file version: 26532026/08/27 18:11:43 OK 20251210153512_drop_unused_gin_index.sql (802µs)6542026/08/27 18:11:43 OK 20241026095416_initial_model.sql (7.77ms)6552026/08/27 18:11:43 OK 20241026095416_initial_model.sql (7.61ms)6562026/08/27 18:11:43 OK 20251210153512_drop_unused_gin_index.sql (710.54µs)6572026/08/27 18:11:43 OK 20251210153512_drop_unused_gin_index.sql (516.96µs)6582026/08/27 18:11:43 OK 20241026095416_initial_model.sql (6.72ms)6592026/08/27 18:11:43 OK 20241026095416_initial_model.sql (7.07ms)6602026/08/27 18:11:43 OK 20251218171726_add_pins.sql (2.2ms)6612026/08/27 18:11:43 OK 20260628120000_add_object_size_and_stats.sql (2.23ms)6622026/08/27 18:11:43 goose: successfully migrated database to version: 202606281200006632026/08/27 18:11:43 OK 20241026095416_initial_model.sql (7.06ms)6642026/08/27 18:11:43 OK 20251210153512_drop_unused_gin_index.sql (572.83µs)6652026/08/27 18:11:43 OK 20251218171726_add_pins.sql (2.15ms)6662026/08/27 18:11:43 OK 20251210153512_drop_unused_gin_index.sql (606.54µs)6672026/08/27 18:11:43 OK 20251210153512_drop_unused_gin_index.sql (812.71µs)6682026/08/27 18:11:43 OK 20241026095416_initial_model.sql (8.02ms)6692026/08/27 18:11:43 OK 1_commit_pending_closure.sql (903.42µs)6702026/08/27 18:11:43 OK 20251218171726_add_pins.sql (1.85ms)6712026/08/27 18:11:43 OK 20260628120000_add_object_size_and_stats.sql (1.26ms)6722026/08/27 18:11:43 goose: successfully migrated database to version: 202606281200006732026/08/27 18:11:43 OK 20251218171726_add_pins.sql (2.2ms)6742026/08/27 18:11:43 OK 2_object_stats_trigger.sql (850.21µs)6752026/08/27 18:11:43 goose: up to current file version: 26762026/08/27 18:11:43 OK 20251210153512_drop_unused_gin_index.sql (923.88µs)6772026/08/27 18:11:43 OK 20260628120000_add_object_size_and_stats.sql (1.56ms)6782026/08/27 18:11:43 goose: successfully migrated database to version: 202606281200006792026/08/27 18:11:43 OK 20251218171726_add_pins.sql (1.34ms)6802026/08/27 18:11:43 OK 20251218171726_add_pins.sql (1.45ms)6812026/08/27 18:11:43 OK 20251218171726_add_pins.sql (2.21ms)6822026/08/27 18:11:43 OK 1_commit_pending_closure.sql (1.14ms)6832026/08/27 18:11:43 OK 20260628120000_add_object_size_and_stats.sql (1.81ms)6842026/08/27 18:11:43 goose: successfully migrated database to version: 202606281200006852026/08/27 18:11:43 OK 20251218171726_add_pins.sql (1.08ms)6862026/08/27 18:11:43 OK 2_object_stats_trigger.sql (506.46µs)6872026/08/27 18:11:43 goose: up to current file version: 26882026/08/27 18:11:43 OK 20260628120000_add_object_size_and_stats.sql (881.71µs)6892026/08/27 18:11:43 goose: successfully migrated database to version: 202606281200006902026/08/27 18:11:43 OK 20260628120000_add_object_size_and_stats.sql (1.61ms)6912026/08/27 18:11:43 goose: successfully migrated database to version: 202606281200006922026/08/27 18:11:43 OK 20260628120000_add_object_size_and_stats.sql (1.11ms)6932026/08/27 18:11:43 goose: successfully migrated database to version: 202606281200006942026/08/27 18:11:43 OK 1_commit_pending_closure.sql (1.26ms)6952026/08/27 18:11:43 OK 1_commit_pending_closure.sql (904.04µs)6962026/08/27 18:11:43 OK 2_object_stats_trigger.sql (478.71µs)6972026/08/27 18:11:43 goose: up to current file version: 26982026/08/27 18:11:43 OK 1_commit_pending_closure.sql (941.04µs)6992026/08/27 18:11:43 OK 1_commit_pending_closure.sql (784.71µs)7002026/08/27 18:11:43 OK 2_object_stats_trigger.sql (365.67µs)7012026/08/27 18:11:43 goose: up to current file version: 27022026/08/27 18:11:43 OK 20260628120000_add_object_size_and_stats.sql (1.42ms)7032026/08/27 18:11:43 goose: successfully migrated database to version: 202606281200007042026/08/27 18:11:43 OK 20260628120000_add_object_size_and_stats.sql (1.02ms)7052026/08/27 18:11:43 goose: successfully migrated database to version: 202606281200007062026/08/27 18:11:43 OK 2_object_stats_trigger.sql (301.33µs)7072026/08/27 18:11:43 goose: up to current file version: 27082026/08/27 18:11:43 OK 2_object_stats_trigger.sql (275.58µs)7092026/08/27 18:11:43 goose: up to current file version: 27102026/08/27 18:11:43 OK 1_commit_pending_closure.sql (1.29ms)7112026/08/27 18:11:43 OK 2_object_stats_trigger.sql (186.71µs)7122026/08/27 18:11:43 goose: up to current file version: 27132026/08/27 18:11:43 OK 1_commit_pending_closure.sql (703.83µs)7142026/08/27 18:11:43 OK 1_commit_pending_closure.sql (699µs)7152026/08/27 18:11:43 OK 2_object_stats_trigger.sql (184.17µs)7162026/08/27 18:11:43 goose: up to current file version: 27172026/08/27 18:11:43 OK 2_object_stats_trigger.sql (184.17µs)7182026/08/27 18:11:43 goose: up to current file version: 2719--- PASS: TestReadProxyInvalidPath (0.45s)720=== CONT TestUploadHandlersRejectOversizedBody721=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure722=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure723=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart724=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart725=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts726=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts727=== CONT TestUploadHandlersRejectInvalidKeys728=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info729=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info730=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal731=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal732=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key733=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key734=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key735=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key736=== CONT TestIsValidUploadKey737=== RUN TestIsValidUploadKey/narinfo738=== PAUSE TestIsValidUploadKey/narinfo739=== RUN TestIsValidUploadKey/nar_zst740=== PAUSE TestIsValidUploadKey/nar_zst741=== RUN TestIsValidUploadKey/nar_xz742=== PAUSE TestIsValidUploadKey/nar_xz743=== RUN TestIsValidUploadKey/nar_plain744=== PAUSE TestIsValidUploadKey/nar_plain745=== RUN TestIsValidUploadKey/listing746=== PAUSE TestIsValidUploadKey/listing747=== RUN TestIsValidUploadKey/build_log748=== PAUSE TestIsValidUploadKey/build_log749=== RUN TestIsValidUploadKey/build_log_home-manager_file750=== PAUSE TestIsValidUploadKey/build_log_home-manager_file751=== RUN TestIsValidUploadKey/build_log_plus_in_name752=== PAUSE TestIsValidUploadKey/build_log_plus_in_name753=== RUN TestIsValidUploadKey/build_log_question_mark754=== PAUSE TestIsValidUploadKey/build_log_question_mark755=== RUN TestIsValidUploadKey/build_log_equals756=== PAUSE TestIsValidUploadKey/build_log_equals757=== RUN TestIsValidUploadKey/realisation758=== PAUSE TestIsValidUploadKey/realisation759=== RUN TestIsValidUploadKey/realisation_plus_in_output760=== PAUSE TestIsValidUploadKey/realisation_plus_in_output761=== RUN TestIsValidUploadKey/nix-cache-info762=== PAUSE TestIsValidUploadKey/nix-cache-info763=== RUN TestIsValidUploadKey/index.html764=== PAUSE TestIsValidUploadKey/index.html765=== RUN TestIsValidUploadKey/narinfo_key,_nar_type766=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type767=== RUN TestIsValidUploadKey/nar_key,_narinfo_type768=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type769=== RUN TestIsValidUploadKey/listing_key,_narinfo_type770=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type771=== RUN TestIsValidUploadKey/traversal772=== PAUSE TestIsValidUploadKey/traversal773=== RUN TestIsValidUploadKey/traversal_nar774=== PAUSE TestIsValidUploadKey/traversal_nar775=== RUN TestIsValidUploadKey/absolute776=== PAUSE TestIsValidUploadKey/absolute777=== RUN TestIsValidUploadKey/empty_key778=== PAUSE TestIsValidUploadKey/empty_key779=== RUN TestIsValidUploadKey/unknown_type780=== PAUSE TestIsValidUploadKey/unknown_type781=== CONT TestReadProxyNarStreaming7822026/08/27 18:11:43 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"783--- PASS: TestService_AuthMiddleware (0.54s)784=== CONT TestReadProxy404785--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.68s)786=== CONT TestReadRedirectKeepsNarinfoProxied7872026/08/27 18:11:43 INFO Received uploads request method=POST path=/api/pending_closures7882026/08/27 18:11:43 INFO Received uploads request method=POST path=/api/pending_closures7892026/08/27 18:11:43 INFO Received uploads request method=POST path=/api/pending_closures7902026/08/27 18:11:43 INFO Received uploads request method=POST path=/api/pending_closures791--- PASS: TestReadProxyNarinfo (1.06s)792=== CONT TestRedundantMultipartUpload7932026/08/27 18:11:43 INFO Received uploads request method=POST path=/api/pending_closures794--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.27s)795=== CONT TestReadProxyRangeRequest7962026/08/27 18:11:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7972026/08/27 18:11:44 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst798--- PASS: TestCompleteMultipartUnregistered (1.34s)799=== CONT TestParseSize800--- PASS: TestParseSize (0.00s)801=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle8022026/08/27 18:11:44 INFO Received uploads request method=POST path=/api/pending_closures8032026/08/27 18:11:44 INFO Received cleanup request method=DELETE path=/api/pending_closures8042026/08/27 18:11:44 INFO Aborted multipart uploads count=08052026/08/27 18:11:44 INFO Received uploads request method=POST path=/api/pending_closures8062026/08/27 18:11:44 INFO Received cleanup request method=DELETE path=/api/pending_closures8072026/08/27 18:11:44 INFO Aborted multipart uploads count=18082026/08/27 18:11:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8092026-08-27 18:11:44.552 UTC [4921] ERROR: Closure does not exist: id=18102026-08-27 18:11:44.552 UTC [4921] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE8112026-08-27 18:11:44.552 UTC [4921] STATEMENT: -- name: CommitPendingClosure :exec812 SELECT commit_pending_closure($1::bigint)813 814--- PASS: TestService_cleanupPendingClosuresHandler (1.81s)815=== CONT TestSkippedUploadsHandler8162026/08/27 18:11:44 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000817--- PASS: TestSkippedUploadsHandler (0.00s)818=== CONT TestPresignedUploadRegisteredBeforeCommit8192026/08/27 18:11:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8202026/08/27 18:11:44 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZDBlMzcwMDMtMDgyMi00ZDhlLTllYWEtODI4MzY3MDQ3MDQwLmI2NTdjZjlhLTg5YWMtNGQyZC05MjEyLTQ4NmU4MmU2M2IzNngxNzg3ODU0MzA0MjY2NzU4MDAw8212026/08/27 18:11:44 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZDBlMzcwMDMtMDgyMi00ZDhlLTllYWEtODI4MzY3MDQ3MDQwLmI2NTdjZjlhLTg5YWMtNGQyZC05MjEyLTQ4NmU4MmU2M2IzNngxNzg3ODU0MzA0MjY2NzU4MDAw parts=1822--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.86s)823=== CONT TestService_Rustfstest8242026-08-27 18:11:44.715 UTC [4938] ERROR: relation "goose_db_version" does not exist at character 368252026-08-27 18:11:44.715 UTC [4938] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8262026-08-27 18:11:44.857 UTC [4939] ERROR: relation "goose_db_version" does not exist at character 368272026-08-27 18:11:44.857 UTC [4939] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8282026/08/27 18:11:44 OK 20241026095416_initial_model.sql (121.65ms)8292026/08/27 18:11:44 OK 20251210153512_drop_unused_gin_index.sql (18.75ms)8302026/08/27 18:11:44 OK 20251218171726_add_pins.sql (49.22ms)8312026/08/27 18:11:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8322026/08/27 18:11:45 OK 20260628120000_add_object_size_and_stats.sql (37.82ms)8332026/08/27 18:11:45 goose: successfully migrated database to version: 202606281200008342026-08-27 18:11:45.025 UTC [4940] ERROR: relation "goose_db_version" does not exist at character 368352026-08-27 18:11:45.025 UTC [4940] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8362026/08/27 18:11:45 OK 1_commit_pending_closure.sql (16.25ms)8372026/08/27 18:11:45 OK 2_object_stats_trigger.sql (908.96µs)8382026/08/27 18:11:45 goose: up to current file version: 28392026/08/27 18:11:45 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZDBlMzcwMDMtMDgyMi00ZDhlLTllYWEtODI4MzY3MDQ3MDQwLjY2ZDg3ZTRlLTA2NGUtNDRjOC1hMzIyLWY3MGRhMTIwODU3MngxNzg3ODU0MzAzNTAzNzgwMDAw parts=108402026/08/27 18:11:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8412026/08/27 18:11:45 INFO Completed upload id=18422026/08/27 18:11:45 INFO Received uploads request method=POST path=/api/pending_closures8432026/08/27 18:11:45 INFO Received uploads request method=POST path=/api/pending_closures8442026/08/27 18:11:45 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo8452026/08/27 18:11:45 WARN Found objects in DB but missing from S3, will re-upload count=1846--- PASS: TestService_verifyS3Integrity (2.32s)847=== CONT TestReadRedirectNar8482026/08/27 18:11:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8492026/08/27 18:11:45 OK 20241026095416_initial_model.sql (184.25ms)8502026/08/27 18:11:45 OK 20251210153512_drop_unused_gin_index.sql (17.69ms)8512026/08/27 18:11:45 OK 20251218171726_add_pins.sql (28.37ms)8522026/08/27 18:11:45 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZDBlMzcwMDMtMDgyMi00ZDhlLTllYWEtODI4MzY3MDQ3MDQwLjYzYjVkYjA5LWE3MTUtNDJhZS04MTBhLTZhMzE2ZTk3ZTZlOHgxNzg3ODU0MzAzNjI0NTY0MDAw parts=108532026/08/27 18:11:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete854--- PASS: TestReadProxyNarStreaming (1.99s)855=== CONT TestReadProxyDisabled8562026/08/27 18:11:45 INFO Completed upload id=18572026/08/27 18:11:45 OK 20260628120000_add_object_size_and_stats.sql (36.65ms)8582026/08/27 18:11:45 goose: successfully migrated database to version: 202606281200008592026/08/27 18:11:45 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000008602026/08/27 18:11:45 INFO Received uploads request method=POST path=/api/pending_closures8612026/08/27 18:11:45 INFO Starting cleanup of old closures method=DELETE path=/api/closures8622026/08/27 18:11:45 INFO Aborted multipart uploads count=08632026/08/27 18:11:45 OK 1_commit_pending_closure.sql (9.74ms)8642026/08/27 18:11:45 OK 2_object_stats_trigger.sql (485.88µs)8652026/08/27 18:11:45 goose: up to current file version: 28662026/08/27 18:11:45 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=0 objects-failed-to-delete=08672026/08/27 18:11:45 INFO Vacuumed table table=pending_closures8682026/08/27 18:11:45 OK 20241026095416_initial_model.sql (205.07ms)8692026/08/27 18:11:45 INFO Vacuumed table table=pending_objects8702026/08/27 18:11:45 OK 20251210153512_drop_unused_gin_index.sql (15.27ms)8712026/08/27 18:11:45 INFO Vacuumed table table=multipart_uploads8722026/08/27 18:11:45 OK 20251218171726_add_pins.sql (29.94ms)8732026/08/27 18:11:45 INFO Vacuumed table table=closures874--- PASS: TestReadProxy404 (2.08s)875=== CONT TestReadProxyConditionalGet8762026/08/27 18:11:45 OK 20260628120000_add_object_size_and_stats.sql (38.7ms)8772026/08/27 18:11:45 goose: successfully migrated database to version: 202606281200008782026/08/27 18:11:45 INFO Vacuumed table table=objects8792026/08/27 18:11:45 OK 1_commit_pending_closure.sql (4.46ms)8802026/08/27 18:11:45 OK 2_object_stats_trigger.sql (689.21µs)8812026/08/27 18:11:45 goose: up to current file version: 28822026/08/27 18:11:45 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000883--- PASS: TestService_createPendingClosureHandler (2.69s)884=== CONT TestReadProxyNarinfoAlreadyDecompressed8852026-08-27 18:11:45.465 UTC [4949] ERROR: relation "goose_db_version" does not exist at character 368862026-08-27 18:11:45.465 UTC [4949] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC887--- PASS: TestReadRedirectKeepsNarinfoProxied (2.12s)888=== CONT TestCompletedNarNotReofferedAcrossClosures8892026/08/27 18:11:45 OK 20241026095416_initial_model.sql (97.14ms)8902026/08/27 18:11:45 OK 20251210153512_drop_unused_gin_index.sql (8.34ms)8912026-08-27 18:11:45.628 UTC [4955] ERROR: relation "goose_db_version" does not exist at character 368922026-08-27 18:11:45.628 UTC [4955] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8932026-08-27 18:11:45.629 UTC [4954] ERROR: relation "goose_db_version" does not exist at character 368942026-08-27 18:11:45.629 UTC [4954] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8952026/08/27 18:11:45 OK 20251218171726_add_pins.sql (5.25ms)8962026/08/27 18:11:45 OK 20260628120000_add_object_size_and_stats.sql (5.83ms)8972026/08/27 18:11:45 goose: successfully migrated database to version: 202606281200008982026/08/27 18:11:45 OK 1_commit_pending_closure.sql (2.34ms)8992026/08/27 18:11:45 OK 2_object_stats_trigger.sql (401.13µs)9002026/08/27 18:11:45 goose: up to current file version: 29012026/08/27 18:11:45 OK 20241026095416_initial_model.sql (66.8ms)9022026/08/27 18:11:45 OK 20241026095416_initial_model.sql (66.62ms)9032026/08/27 18:11:45 OK 20251210153512_drop_unused_gin_index.sql (1.27ms)9042026/08/27 18:11:45 OK 20251210153512_drop_unused_gin_index.sql (9.88ms)9052026/08/27 18:11:45 INFO Received uploads request method=POST path=/api/pending_closures9062026/08/27 18:11:45 OK 20251218171726_add_pins.sql (29.01ms)9072026/08/27 18:11:45 OK 20251218171726_add_pins.sql (21.24ms)9082026/08/27 18:11:45 OK 20260628120000_add_object_size_and_stats.sql (19.16ms)9092026/08/27 18:11:45 goose: successfully migrated database to version: 202606281200009102026/08/27 18:11:45 OK 20260628120000_add_object_size_and_stats.sql (18.35ms)9112026/08/27 18:11:45 goose: successfully migrated database to version: 202606281200009122026/08/27 18:11:45 OK 1_commit_pending_closure.sql (15.03ms)9132026/08/27 18:11:45 OK 1_commit_pending_closure.sql (15ms)9142026/08/27 18:11:45 OK 2_object_stats_trigger.sql (537.17µs)9152026/08/27 18:11:45 goose: up to current file version: 29162026/08/27 18:11:45 OK 2_object_stats_trigger.sql (581.54µs)9172026/08/27 18:11:45 goose: up to current file version: 29182026/08/27 18:11:45 INFO Received uploads request method=POST path=/api/pending_closures9192026/08/27 18:11:45 INFO Received uploads request method=POST path=/api/pending_closures920--- PASS: TestReadProxyRangeRequest (2.14s)921=== CONT TestReadProxyHead9222026/08/27 18:11:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9232026-08-27 18:11:46.428 UTC [4960] ERROR: relation "goose_db_version" does not exist at character 369242026-08-27 18:11:46.428 UTC [4960] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9252026-08-27 18:11:46.437 UTC [4961] ERROR: relation "goose_db_version" does not exist at character 369262026-08-27 18:11:46.437 UTC [4961] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9272026/08/27 18:11:46 OK 20241026095416_initial_model.sql (103.05ms)9282026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (14.98ms)9292026/08/27 18:11:46 OK 20241026095416_initial_model.sql (144.87ms)9302026/08/27 18:11:46 OK 20251218171726_add_pins.sql (34.19ms)9312026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (10.04ms)9322026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (37.04ms)9332026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200009342026/08/27 18:11:46 OK 20251218171726_add_pins.sql (35.05ms)9352026/08/27 18:11:46 OK 1_commit_pending_closure.sql (11.4ms)9362026/08/27 18:11:46 OK 2_object_stats_trigger.sql (1.08ms)9372026/08/27 18:11:46 goose: up to current file version: 29382026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (34.62ms)9392026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200009402026/08/27 18:11:46 OK 1_commit_pending_closure.sql (8.3ms)9412026/08/27 18:11:46 OK 2_object_stats_trigger.sql (801.83µs)9422026/08/27 18:11:46 goose: up to current file version: 29432026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures9442026/08/27 18:11:47 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9452026/08/27 18:11:47 INFO Received uploads request method=POST path=/api/pending_closures946--- PASS: TestPresignedUploadRegisteredBeforeCommit (2.46s)947=== CONT TestGCTaskStore_CompletedAllowsNewTask948--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)949=== CONT TestIsValidCachePath950=== RUN TestIsValidCachePath/narinfo951=== PAUSE TestIsValidCachePath/narinfo952=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars953=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars954=== RUN TestIsValidCachePath/nar_zst955=== PAUSE TestIsValidCachePath/nar_zst956=== RUN TestIsValidCachePath/nar_xz957=== PAUSE TestIsValidCachePath/nar_xz958=== RUN TestIsValidCachePath/nar_bz2959=== PAUSE TestIsValidCachePath/nar_bz2960=== RUN TestIsValidCachePath/nar_uncompressed961=== PAUSE TestIsValidCachePath/nar_uncompressed962=== RUN TestIsValidCachePath/ls963=== PAUSE TestIsValidCachePath/ls964=== RUN TestIsValidCachePath/log965=== PAUSE TestIsValidCachePath/log966=== RUN TestIsValidCachePath/realisation967=== PAUSE TestIsValidCachePath/realisation968=== RUN TestIsValidCachePath/nix-cache-info969=== PAUSE TestIsValidCachePath/nix-cache-info970=== RUN TestIsValidCachePath/index.html971=== PAUSE TestIsValidCachePath/index.html972=== RUN TestIsValidCachePath/traversal_parent973=== PAUSE TestIsValidCachePath/traversal_parent974=== RUN TestIsValidCachePath/traversal_in_middle975=== PAUSE TestIsValidCachePath/traversal_in_middle976=== RUN TestIsValidCachePath/invalid_char_e977=== PAUSE TestIsValidCachePath/invalid_char_e978=== RUN TestIsValidCachePath/invalid_char_u979=== PAUSE TestIsValidCachePath/invalid_char_u980=== RUN TestIsValidCachePath/random_path981=== PAUSE TestIsValidCachePath/random_path982=== RUN TestIsValidCachePath/empty983=== PAUSE TestIsValidCachePath/empty984=== RUN TestIsValidCachePath/leading_slash985=== PAUSE TestIsValidCachePath/leading_slash986=== RUN TestIsValidCachePath/wrong_extension987=== PAUSE TestIsValidCachePath/wrong_extension988=== RUN TestIsValidCachePath/short_hash989=== PAUSE TestIsValidCachePath/short_hash990=== CONT TestParseSingleRange991=== RUN TestParseSingleRange/none992=== PAUSE TestParseSingleRange/none993=== RUN TestParseSingleRange/unknown_unit994=== PAUSE TestParseSingleRange/unknown_unit995=== RUN TestParseSingleRange/multi-range_ignored996=== PAUSE TestParseSingleRange/multi-range_ignored997=== RUN TestParseSingleRange/malformed_no_dash998=== PAUSE TestParseSingleRange/malformed_no_dash999=== RUN TestParseSingleRange/malformed_both_empty1000=== PAUSE TestParseSingleRange/malformed_both_empty1001=== RUN TestParseSingleRange/malformed_end_before_start1002=== PAUSE TestParseSingleRange/malformed_end_before_start1003=== RUN TestParseSingleRange/closed1004=== PAUSE TestParseSingleRange/closed1005=== RUN TestParseSingleRange/open-ended1006=== PAUSE TestParseSingleRange/open-ended1007=== RUN TestParseSingleRange/end_clamped_to_size1008=== PAUSE TestParseSingleRange/end_clamped_to_size1009=== RUN TestParseSingleRange/suffix1010=== PAUSE TestParseSingleRange/suffix1011=== RUN TestParseSingleRange/suffix_exceeds_size1012=== PAUSE TestParseSingleRange/suffix_exceeds_size1013=== RUN TestParseSingleRange/single_byte1014=== PAUSE TestParseSingleRange/single_byte1015=== RUN TestParseSingleRange/start_past_EOF1016=== PAUSE TestParseSingleRange/start_past_EOF1017=== RUN TestParseSingleRange/start_far_past_EOF1018=== PAUSE TestParseSingleRange/start_far_past_EOF1019=== CONT TestResurrectedObjectNotDeleted10202026-08-27 18:11:47.038 UTC [4962] ERROR: relation "goose_db_version" does not exist at character 3610212026-08-27 18:11:47.038 UTC [4962] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1022--- PASS: TestService_Rustfstest (2.48s)1023=== CONT TestOrphanedObjectsGCStressTest10242026-08-27 18:11:47.177 UTC [4967] ERROR: relation "goose_db_version" does not exist at character 3610252026-08-27 18:11:47.177 UTC [4967] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10262026-08-27 18:11:47.231 UTC [4968] ERROR: relation "goose_db_version" does not exist at character 3610272026-08-27 18:11:47.231 UTC [4968] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10282026/08/27 18:11:47 OK 20241026095416_initial_model.sql (124.33ms)10292026-08-27 18:11:47.232 UTC [4969] ERROR: relation "goose_db_version" does not exist at character 3610302026-08-27 18:11:47.232 UTC [4969] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10312026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (12.21ms)10322026/08/27 18:11:47 OK 20251218171726_add_pins.sql (23.33ms)10332026-08-27 18:11:47.268 UTC [4970] ERROR: relation "goose_db_version" does not exist at character 3610342026-08-27 18:11:47.268 UTC [4970] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10352026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (7.19ms)10362026/08/27 18:11:47 goose: successfully migrated database to version: 2026062812000010372026/08/27 18:11:47 OK 20241026095416_initial_model.sql (43.75ms)10382026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (1.5ms)10392026/08/27 18:11:47 OK 1_commit_pending_closure.sql (2.87ms)10402026/08/27 18:11:47 OK 2_object_stats_trigger.sql (679.42µs)10412026/08/27 18:11:47 goose: up to current file version: 210422026/08/27 18:11:47 OK 20251218171726_add_pins.sql (3.05ms)10432026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (36.41ms)10442026/08/27 18:11:47 goose: successfully migrated database to version: 2026062812000010452026/08/27 18:11:47 OK 1_commit_pending_closure.sql (2.1ms)10462026/08/27 18:11:47 OK 2_object_stats_trigger.sql (386.25µs)10472026/08/27 18:11:47 goose: up to current file version: 210482026/08/27 18:11:47 OK 20241026095416_initial_model.sql (60.42ms)10492026/08/27 18:11:47 OK 20241026095416_initial_model.sql (65.57ms)10502026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (13.38ms)10512026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (12.83ms)10522026/08/27 18:11:47 OK 20251218171726_add_pins.sql (31.43ms)10532026/08/27 18:11:47 OK 20251218171726_add_pins.sql (37.05ms)10542026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (29.89ms)10552026/08/27 18:11:47 goose: successfully migrated database to version: 2026062812000010562026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (26.98ms)10572026/08/27 18:11:47 goose: successfully migrated database to version: 2026062812000010582026/08/27 18:11:47 OK 20241026095416_initial_model.sql (136.29ms)10592026/08/27 18:11:47 OK 1_commit_pending_closure.sql (10.78ms)10602026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (3.14ms)10612026/08/27 18:11:47 OK 2_object_stats_trigger.sql (1.59ms)10622026/08/27 18:11:47 goose: up to current file version: 210632026/08/27 18:11:47 OK 1_commit_pending_closure.sql (4.61ms)10642026/08/27 18:11:47 OK 2_object_stats_trigger.sql (771.67µs)10652026/08/27 18:11:47 goose: up to current file version: 21066--- PASS: TestReadRedirectNar (2.38s)1067=== CONT TestOrphanedObjectsGC10682026/08/27 18:11:47 OK 20251218171726_add_pins.sql (47.42ms)10692026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (41.42ms)10702026/08/27 18:11:47 goose: successfully migrated database to version: 2026062812000010712026/08/27 18:11:47 OK 1_commit_pending_closure.sql (12.36ms)10722026/08/27 18:11:47 OK 2_object_stats_trigger.sql (710.21µs)10732026/08/27 18:11:47 goose: up to current file version: 210742026/08/27 18:11:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1075--- PASS: TestReadProxyDisabled (2.39s)1076=== CONT TestObjectStatsTrigger10772026/08/27 18:11:47 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZDBlMzcwMDMtMDgyMi00ZDhlLTllYWEtODI4MzY3MDQ3MDQwLmQxZTczNGJjLThlOWItNGFiMy1iYWZmLTkxZGVjNTRiYzBiNngxNzg3ODU0MzA1NzQ4ODg3MDAw parts=121078--- PASS: TestRedundantMultipartUpload (3.81s)1079=== CONT TestNoClosurePushKeepsReferencedObjectsReachable1080--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.33s)1081=== CONT TestNoClosurePushCreatesIndependentGCRoots10822026-08-27 18:11:47.847 UTC [4979] ERROR: relation "goose_db_version" does not exist at character 3610832026-08-27 18:11:47.847 UTC [4979] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1084--- PASS: TestReadProxyConditionalGet (2.52s)1085=== CONT TestMultipartCleanup10862026/08/27 18:11:47 INFO Received uploads request method=POST path=/api/pending_closures10872026/08/27 18:11:48 OK 20241026095416_initial_model.sql (77.55ms)10882026/08/27 18:11:48 OK 20251210153512_drop_unused_gin_index.sql (2.86ms)10892026/08/27 18:11:48 OK 20251218171726_add_pins.sql (7.58ms)10902026/08/27 18:11:48 OK 20260628120000_add_object_size_and_stats.sql (24.56ms)10912026/08/27 18:11:48 goose: successfully migrated database to version: 2026062812000010922026/08/27 18:11:48 OK 1_commit_pending_closure.sql (3.35ms)10932026/08/27 18:11:48 OK 2_object_stats_trigger.sql (507.38µs)10942026/08/27 18:11:48 goose: up to current file version: 21095--- PASS: TestReadProxyHead (2.13s)1096=== CONT TestServerTLSConfig1097=== RUN TestServerTLSConfig/no_client_CA1098=== PAUSE TestServerTLSConfig/no_client_CA1099=== RUN TestServerTLSConfig/missing_CA_file1100=== PAUSE TestServerTLSConfig/missing_CA_file1101=== RUN TestServerTLSConfig/not_a_PEM_file1102=== PAUSE TestServerTLSConfig/not_a_PEM_file1103=== CONT TestService_NativeMTLS11042026-08-27 18:11:48.549 UTC [4984] ERROR: relation "goose_db_version" does not exist at character 3611052026-08-27 18:11:48.549 UTC [4984] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11062026-08-27 18:11:48.619 UTC [4985] ERROR: relation "goose_db_version" does not exist at character 3611072026-08-27 18:11:48.619 UTC [4985] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11082026/08/27 18:11:48 OK 20241026095416_initial_model.sql (138.57ms)11092026/08/27 18:11:48 OK 20241026095416_initial_model.sql (108.89ms)11102026/08/27 18:11:48 OK 20251210153512_drop_unused_gin_index.sql (8.75ms)11112026/08/27 18:11:48 OK 20251210153512_drop_unused_gin_index.sql (12.88ms)11122026/08/27 18:11:48 OK 20251218171726_add_pins.sql (22.58ms)11132026/08/27 18:11:48 OK 20251218171726_add_pins.sql (20.65ms)11142026/08/27 18:11:48 OK 20260628120000_add_object_size_and_stats.sql (30.94ms)11152026/08/27 18:11:48 goose: successfully migrated database to version: 2026062812000011162026/08/27 18:11:48 OK 20260628120000_add_object_size_and_stats.sql (27.13ms)11172026/08/27 18:11:48 goose: successfully migrated database to version: 2026062812000011182026/08/27 18:11:48 OK 1_commit_pending_closure.sql (10.35ms)11192026/08/27 18:11:48 OK 2_object_stats_trigger.sql (803.75µs)11202026/08/27 18:11:48 goose: up to current file version: 211212026/08/27 18:11:48 OK 1_commit_pending_closure.sql (12.98ms)11222026/08/27 18:11:48 OK 2_object_stats_trigger.sql (853.13µs)11232026/08/27 18:11:48 goose: up to current file version: 211242026-08-27 18:11:48.944 UTC [4986] ERROR: relation "goose_db_version" does not exist at character 3611252026-08-27 18:11:48.944 UTC [4986] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11262026/08/27 18:11:49 OK 20241026095416_initial_model.sql (268.54ms)11272026/08/27 18:11:49 OK 20251210153512_drop_unused_gin_index.sql (14.39ms)11282026-08-27 18:11:49.320 UTC [4987] ERROR: relation "goose_db_version" does not exist at character 3611292026-08-27 18:11:49.320 UTC [4987] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11302026/08/27 18:11:49 OK 20251218171726_add_pins.sql (41.4ms)11312026-08-27 18:11:49.345 UTC [4988] ERROR: relation "goose_db_version" does not exist at character 3611322026-08-27 18:11:49.345 UTC [4988] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11332026/08/27 18:11:49 OK 20260628120000_add_object_size_and_stats.sql (42.74ms)11342026/08/27 18:11:49 goose: successfully migrated database to version: 2026062812000011352026/08/27 18:11:49 OK 1_commit_pending_closure.sql (16.9ms)11362026/08/27 18:11:49 OK 2_object_stats_trigger.sql (959.42µs)11372026/08/27 18:11:49 goose: up to current file version: 21138--- PASS: TestResurrectedObjectNotDeleted (2.40s)1139=== CONT TestMetricsInventory11402026/08/27 18:11:49 OK 20241026095416_initial_model.sql (253.73ms)11412026/08/27 18:11:49 OK 20251210153512_drop_unused_gin_index.sql (9.98ms)11422026/08/27 18:11:49 OK 20241026095416_initial_model.sql (256.25ms)11432026/08/27 18:11:49 OK 20251210153512_drop_unused_gin_index.sql (14.47ms)11442026/08/27 18:11:49 OK 20251218171726_add_pins.sql (45.29ms)11452026/08/27 18:11:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11462026/08/27 18:11:49 OK 20251218171726_add_pins.sql (27.07ms)11472026/08/27 18:11:49 OK 20260628120000_add_object_size_and_stats.sql (13.12ms)11482026/08/27 18:11:49 goose: successfully migrated database to version: 2026062812000011492026/08/27 18:11:49 OK 1_commit_pending_closure.sql (4.67ms)11502026/08/27 18:11:49 OK 20260628120000_add_object_size_and_stats.sql (8.73ms)11512026/08/27 18:11:49 goose: successfully migrated database to version: 2026062812000011522026/08/27 18:11:49 OK 2_object_stats_trigger.sql (1.71ms)11532026/08/27 18:11:49 goose: up to current file version: 211542026/08/27 18:11:49 OK 1_commit_pending_closure.sql (4.5ms)11552026/08/27 18:11:49 OK 2_object_stats_trigger.sql (956.83µs)11562026/08/27 18:11:49 goose: up to current file version: 211572026/08/27 18:11:49 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZDBlMzcwMDMtMDgyMi00ZDhlLTllYWEtODI4MzY3MDQ3MDQwLmJhN2M2OGUzLWFlNDItNDA1Ni05ZWRkLWRlMTFjMzYxNjAwOHgxNzg3ODU0MzA4MDAyMzk4MDAw parts=1211582026/08/27 18:11:49 INFO Received uploads request method=POST path=/api/pending_closures1159--- PASS: TestCompletedNarNotReofferedAcrossClosures (4.28s)1160=== CONT TestNARDeduplicationMetadataUploadBug11612026-08-27 18:11:49.828 UTC [4992] ERROR: relation "goose_db_version" does not exist at character 3611622026-08-27 18:11:49.828 UTC [4992] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11632026-08-27 18:11:49.953 UTC [4995] ERROR: relation "goose_db_version" does not exist at character 3611642026-08-27 18:11:49.953 UTC [4995] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11652026/08/27 18:11:49 WARN Rate limiter enabled after throttle name=s3-test rate=511662026/08/27 18:11:49 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1167=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1168 throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=101169 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001170--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.88s)1171=== CONT TestCreatePendingClosureRejectsOversizedNAR11722026/08/27 18:11:49 INFO Received uploads request method=POST path=/api/pending_closures1173--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1174=== CONT TestCacheConfigHandlerMaxNarSize1175--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1176=== CONT TestGenerateLandingPage1177--- PASS: TestGenerateLandingPage (0.01s)1178=== CONT TestService_readinessHandler11792026/08/27 18:11:50 OK 20241026095416_initial_model.sql (255.54ms)11802026/08/27 18:11:50 OK 20251210153512_drop_unused_gin_index.sql (13.58ms)1181--- PASS: TestObjectStatsTrigger (2.59s)1182=== CONT TestService_healthCheckHandler11832026/08/27 18:11:50 OK 20251218171726_add_pins.sql (49.1ms)11842026/08/27 18:11:50 OK 20260628120000_add_object_size_and_stats.sql (44.09ms)11852026/08/27 18:11:50 goose: successfully migrated database to version: 2026062812000011862026/08/27 18:11:50 OK 1_commit_pending_closure.sql (12.54ms)11872026/08/27 18:11:50 OK 2_object_stats_trigger.sql (513.04µs)11882026/08/27 18:11:50 goose: up to current file version: 211892026/08/27 18:11:50 OK 20241026095416_initial_model.sql (254.07ms)11902026/08/27 18:11:50 OK 20251210153512_drop_unused_gin_index.sql (11.39ms)11912026/08/27 18:11:50 OK 20251218171726_add_pins.sql (29.44ms)11922026/08/27 18:11:50 OK 20260628120000_add_object_size_and_stats.sql (133.05ms)11932026/08/27 18:11:50 goose: successfully migrated database to version: 2026062812000011942026/08/27 18:11:50 OK 1_commit_pending_closure.sql (6.17ms)11952026/08/27 18:11:50 OK 2_object_stats_trigger.sql (228µs)11962026/08/27 18:11:50 goose: up to current file version: 211972026-08-27 18:11:50.572 UTC [5008] ERROR: relation "goose_db_version" does not exist at character 3611982026-08-27 18:11:50.572 UTC [5008] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11992026/08/27 18:11:50 INFO Received uploads request method=POST path=/api/pending_closures1200=== NAME TestOrphanedObjectsGC1201 orphaned_objects_gc_test.go:290: GC Test Summary:1202 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1203 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1204 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1205 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1206 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1207--- PASS: TestOrphanedObjectsGC (3.18s)1208=== CONT TestGracefulShutdownDrainsInflight12092026/08/27 18:11:50 INFO Starting HTTP server address=127.0.0.1:5718612102026/08/27 18:11:50 INFO Shutdown signal received, draining in-flight requests timeout=10s1211--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1212=== CONT TestGCTaskStore_Fail1213--- PASS: TestGCTaskStore_Fail (0.00s)1214=== CONT TestGCTaskStore_PhaseUpdates1215--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1216=== CONT TestClientMultipleUploads12172026/08/27 18:11:50 OK 20241026095416_initial_model.sql (132.25ms)12182026/08/27 18:11:50 OK 20251210153512_drop_unused_gin_index.sql (5.63ms)12192026/08/27 18:11:50 OK 20251218171726_add_pins.sql (16.55ms)12202026/08/27 18:11:50 INFO Received cleanup request method=DELETE path=/api/pending_closures12212026/08/27 18:11:50 INFO Aborted multipart uploads count=11222--- PASS: TestMultipartCleanup (2.90s)1223=== CONT TestGCTaskStore_GetReturnsLatest1224--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1225=== CONT TestGCTaskStore_GetEmpty1226--- PASS: TestGCTaskStore_GetEmpty (0.00s)1227=== CONT TestGCTaskStore_ConflictDifferentParams1228--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1229=== CONT TestGCTaskStore_DeduplicateSameParams1230--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1231=== CONT TestGCTaskStore_StartNew1232--- PASS: TestGCTaskStore_StartNew (0.00s)1233=== CONT TestGCMetrics12342026/08/27 18:11:50 OK 20260628120000_add_object_size_and_stats.sql (16.41ms)12352026/08/27 18:11:50 goose: successfully migrated database to version: 2026062812000012362026/08/27 18:11:50 OK 1_commit_pending_closure.sql (7.69ms)12372026/08/27 18:11:50 OK 2_object_stats_trigger.sql (256.33µs)12382026/08/27 18:11:50 goose: up to current file version: 212392026/08/27 18:11:50 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12402026/08/27 18:11:50 INFO Received uploads request method=POST path=/api/pending_closures12412026/08/27 18:11:50 INFO Received uploads request method=POST path=/api/pending_closures1242=== NAME TestNoClosurePushKeepsReferencedObjectsReachable1243 no_closure_test.go:189: Built app=/nix/var/nix/builds/nix-4772-2940262897/TestNoClosurePushKeepsReferencedObjectsReachable3971171255/001/store/qmr1ga21kdcwp8y3qd8h266qcvl8q1k3-niks3-app dep=/nix/var/nix/builds/nix-4772-2940262897/TestNoClosurePushKeepsReferencedObjectsReachable3971171255/001/store/jmarh12kgjm1n494zkwqf8x7sxq30vs8-niks3-dep12442026/08/27 18:11:50 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)12452026/08/27 18:11:50 INFO Uploading ab27fd106d9ngf736rpl119vnshc5fc7-build-dep.txt (144B)12462026/08/27 18:11:50 INFO Uploading by5nzshg4dgqx7ddqf7ipza8drdmazr5-output.txt (128B)12472026/08/27 18:11:50 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12482026/08/27 18:11:50 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1249--- PASS: TestService_NativeMTLS (2.65s)1250=== CONT TestGCBugBareHashReferences12512026/08/27 18:11:50 WARN Failed to register uploaded object key=nar/0zf002pclvicyfpcvpn82kby55jrx8bs7cyhccsd04byqa021ymm.nar.zst error="server returned 404: 404 page not found\n"12522026/08/27 18:11:50 WARN Failed to register uploaded object key=nar/0xq2m43h3xd3qik9rvppw8bj4fm7a4vai6y4la58ivfa7lmzcrr1.nar.zst error="server returned 404: 404 page not found\n"12532026/08/27 18:11:51 WARN Failed to register uploaded object key=by5nzshg4dgqx7ddqf7ipza8drdmazr5.ls error="server returned 404: 404 page not found\n"12542026/08/27 18:11:51 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12552026/08/27 18:11:51 INFO Received uploads request method=POST path=/api/pending_closures12562026/08/27 18:11:51 INFO Received uploads request method=POST path=/api/pending_closures12572026/08/27 18:11:51 WARN Failed to register uploaded object key=ab27fd106d9ngf736rpl119vnshc5fc7.ls error="server returned 404: 404 page not found\n"12582026/08/27 18:11:51 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12592026/08/27 18:11:51 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12602026/08/27 18:11:51 INFO Signed narinfos id=2 count=112612026/08/27 18:11:51 INFO Signed narinfos id=1 count=112622026/08/27 18:11:51 INFO Uploading 2 narinfos12632026/08/27 18:11:51 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)12642026/08/27 18:11:51 INFO Uploading jmarh12kgjm1n494zkwqf8x7sxq30vs8-niks3-dep (136B)12652026/08/27 18:11:51 INFO Uploading qmr1ga21kdcwp8y3qd8h266qcvl8q1k3-niks3-app (264B)12662026/08/27 18:11:51 WARN Failed to register uploaded object key=by5nzshg4dgqx7ddqf7ipza8drdmazr5.narinfo error="server returned 404: 404 page not found\n"12672026/08/27 18:11:51 WARN Failed to register uploaded object key=ab27fd106d9ngf736rpl119vnshc5fc7.narinfo error="server returned 404: 404 page not found\n"12682026/08/27 18:11:51 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12692026/08/27 18:11:51 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12702026/08/27 18:11:51 INFO Completed upload id=212712026/08/27 18:11:51 INFO Completed upload id=112722026/08/27 18:11:51 INFO Upload complete. (309ms)12732026/08/27 18:11:51 WARN Failed to register uploaded object key=nar/1y80sh8wjkir6ba1cv5m2p9zqii2r8wcr66mkdkgbcwcp24r3g57.nar.zst error="server returned 404: 404 page not found\n"12742026/08/27 18:11:51 WARN Failed to register uploaded object key=nar/00kzwpbjg0h8j5bpqlk2x9asjpmns0y0lxiwmp8xsk0pqynvvahp.nar.zst error="server returned 404: 404 page not found\n"12752026/08/27 18:11:51 WARN Failed to register uploaded object key=log/4bhg2zcjdq7nzz17l9nwqax2g34zvrnj-niks3-app.drv error="server returned 404: 404 page not found\n"12762026/08/27 18:11:51 WARN Failed to register uploaded object key=log/nkdrrvfcxvc61rzbbw847kjyrrp62d9g-niks3-dep.drv error="server returned 404: 404 page not found\n"12772026/08/27 18:11:51 INFO Starting cleanup of old closures method=DELETE path=/api/closures12782026/08/27 18:11:51 INFO Garbage collection started12792026/08/27 18:11:51 INFO Aborted multipart uploads count=012802026/08/27 18:11:51 WARN Force mode enabled - objects will be deleted immediately without grace period12812026/08/27 18:11:51 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012822026/08/27 18:11:51 WARN Failed to register uploaded object key=jmarh12kgjm1n494zkwqf8x7sxq30vs8.ls error="server returned 404: 404 page not found\n"12832026/08/27 18:11:51 WARN Failed to register uploaded object key=qmr1ga21kdcwp8y3qd8h266qcvl8q1k3.ls error="server returned 404: 404 page not found\n"12842026/08/27 18:11:51 INFO Vacuumed table table=pending_closures12852026/08/27 18:11:51 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12862026/08/27 18:11:51 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12872026/08/27 18:11:51 INFO Signed narinfos id=1 count=112882026/08/27 18:11:51 INFO Signed narinfos id=2 count=112892026/08/27 18:11:51 INFO Uploading 2 narinfos12902026/08/27 18:11:51 WARN Failed to register uploaded object key=jmarh12kgjm1n494zkwqf8x7sxq30vs8.narinfo error="server returned 404: 404 page not found\n"12912026/08/27 18:11:51 WARN Failed to register uploaded object key=qmr1ga21kdcwp8y3qd8h266qcvl8q1k3.narinfo error="server returned 404: 404 page not found\n"12922026/08/27 18:11:51 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12932026/08/27 18:11:51 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12942026/08/27 18:11:51 INFO Vacuumed table table=pending_objects12952026/08/27 18:11:51 INFO Vacuumed table table=multipart_uploads12962026/08/27 18:11:51 INFO Completed upload id=212972026/08/27 18:11:51 INFO Completed upload id=112982026/08/27 18:11:51 INFO Vacuumed table table=closures12992026/08/27 18:11:51 INFO Upload complete. (284ms)13002026/08/27 18:11:51 INFO Vacuumed table table=objects13012026/08/27 18:11:51 INFO Starting cleanup of old closures method=DELETE path=/api/closures13022026/08/27 18:11:51 INFO Garbage collection started13032026/08/27 18:11:51 INFO Aborted multipart uploads count=013042026/08/27 18:11:51 WARN Force mode enabled - objects will be deleted immediately without grace period13052026-08-27 18:11:51.311 UTC [5039] ERROR: relation "goose_db_version" does not exist at character 3613062026-08-27 18:11:51.311 UTC [5039] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13072026/08/27 18:11:51 OK 20241026095416_initial_model.sql (108.1ms)13082026/08/27 18:11:51 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=2 objects-deleted-after-grace-period=2002 objects-failed-to-delete=013092026/08/27 18:11:51 OK 20251210153512_drop_unused_gin_index.sql (11.65ms)13102026/08/27 18:11:51 INFO Vacuumed table table=pending_closures13112026/08/27 18:11:51 OK 20251218171726_add_pins.sql (41.03ms)13122026/08/27 18:11:51 INFO Vacuumed table table=pending_objects13132026/08/27 18:11:51 INFO Vacuumed table table=multipart_uploads13142026/08/27 18:11:51 INFO Vacuumed table table=closures13152026/08/27 18:11:51 OK 20260628120000_add_object_size_and_stats.sql (40.36ms)13162026/08/27 18:11:51 goose: successfully migrated database to version: 2026062812000013172026/08/27 18:11:51 OK 1_commit_pending_closure.sql (7.52ms)13182026/08/27 18:11:51 OK 2_object_stats_trigger.sql (274.08µs)13192026/08/27 18:11:51 goose: up to current file version: 213202026/08/27 18:11:51 INFO Vacuumed table table=objects13212026-08-27 18:11:51.699 UTC [5041] ERROR: relation "goose_db_version" does not exist at character 3613222026-08-27 18:11:51.699 UTC [5041] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1323--- PASS: TestMetricsInventory (2.34s)1324=== CONT TestResolveDBConnectionString1325=== RUN TestResolveDBConnectionString/flag_wins1326=== PAUSE TestResolveDBConnectionString/flag_wins1327=== RUN TestResolveDBConnectionString/file_when_flag_empty1328=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1329=== RUN TestResolveDBConnectionString/missing_file_is_an_error1330=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1331=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1332=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1333=== RUN TestResolveDBConnectionString/nothing_configured1334=== PAUSE TestResolveDBConnectionString/nothing_configured1335=== CONT TestPinProtectsFromGC13362026-08-27 18:11:51.893 UTC [5044] ERROR: relation "goose_db_version" does not exist at character 3613372026-08-27 18:11:51.893 UTC [5044] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13382026/08/27 18:11:51 OK 20241026095416_initial_model.sql (139ms)13392026/08/27 18:11:51 OK 20251210153512_drop_unused_gin_index.sql (4.13ms)13402026/08/27 18:11:51 OK 20251218171726_add_pins.sql (38.43ms)13412026/08/27 18:11:51 OK 20260628120000_add_object_size_and_stats.sql (48.08ms)13422026/08/27 18:11:51 goose: successfully migrated database to version: 2026062812000013432026/08/27 18:11:51 OK 1_commit_pending_closure.sql (10.63ms)13442026/08/27 18:11:51 OK 2_object_stats_trigger.sql (998.63µs)13452026/08/27 18:11:51 goose: up to current file version: 213462026-08-27 18:11:52.174 UTC [5045] ERROR: relation "goose_db_version" does not exist at character 3613472026-08-27 18:11:52.174 UTC [5045] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13482026/08/27 18:11:52 OK 20241026095416_initial_model.sql (234.46ms)13492026/08/27 18:11:52 OK 20251210153512_drop_unused_gin_index.sql (13.37ms)13502026/08/27 18:11:52 OK 20251218171726_add_pins.sql (50.61ms)13512026/08/27 18:11:52 OK 20260628120000_add_object_size_and_stats.sql (48.35ms)13522026/08/27 18:11:52 goose: successfully migrated database to version: 2026062812000013532026/08/27 18:11:52 OK 1_commit_pending_closure.sql (7.61ms)13542026/08/27 18:11:52 OK 2_object_stats_trigger.sql (576.79µs)13552026/08/27 18:11:52 goose: up to current file version: 213562026/08/27 18:11:52 OK 20241026095416_initial_model.sql (181.79ms)13572026/08/27 18:11:52 OK 20251210153512_drop_unused_gin_index.sql (6.94ms)13582026/08/27 18:11:52 OK 20251218171726_add_pins.sql (37.39ms)13592026/08/27 18:11:52 WARN readiness check failed error="closed pool"1360--- PASS: TestService_readinessHandler (2.52s)1361=== CONT TestClientWithDependencies13622026/08/27 18:11:52 OK 20260628120000_add_object_size_and_stats.sql (39.97ms)13632026/08/27 18:11:52 goose: successfully migrated database to version: 202606281200001364=== NAME TestNARDeduplicationMetadataUploadBug1365 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-4772-2940262897/TestNARDeduplicationMetadataUploadBug2260999259/001/store/bpjsgssilaf5i2hvh4s8j2zfi75cfkfm-file1.txt13662026/08/27 18:11:52 OK 1_commit_pending_closure.sql (9.69ms)13672026/08/27 18:11:52 OK 2_object_stats_trigger.sql (517.46µs)13682026/08/27 18:11:52 goose: up to current file version: 213692026/08/27 18:11:52 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13702026-08-27 18:11:52.649 UTC [5054] ERROR: relation "goose_db_version" does not exist at character 3613712026-08-27 18:11:52.649 UTC [5054] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13722026/08/27 18:11:52 INFO Received uploads request method=POST path=/api/pending_closures1373--- PASS: TestService_healthCheckHandler (2.50s)1374=== CONT TestService_ReadScope_PublicByDefault13752026/08/27 18:11:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13762026/08/27 18:11:52 INFO Uploading bpjsgssilaf5i2hvh4s8j2zfi75cfkfm-file1.txt (160B)13772026/08/27 18:11:52 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"13782026/08/27 18:11:52 WARN Failed to register uploaded object key=bpjsgssilaf5i2hvh4s8j2zfi75cfkfm.ls error="server returned 404: 404 page not found\n"13792026/08/27 18:11:52 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13802026/08/27 18:11:52 INFO Signed narinfos id=1 count=113812026/08/27 18:11:52 INFO Uploading 1 narinfos13822026-08-27 18:11:52.770 UTC [5059] ERROR: relation "goose_db_version" does not exist at character 3613832026-08-27 18:11:52.770 UTC [5059] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13842026/08/27 18:11:52 WARN Failed to register uploaded object key=bpjsgssilaf5i2hvh4s8j2zfi75cfkfm.narinfo error="server returned 404: 404 page not found\n"13852026/08/27 18:11:52 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13862026/08/27 18:11:52 OK 20241026095416_initial_model.sql (100.71ms)13872026/08/27 18:11:52 OK 20251210153512_drop_unused_gin_index.sql (7.21ms)13882026/08/27 18:11:52 INFO Completed upload id=113892026/08/27 18:11:52 INFO Upload complete. (255ms)1390=== NAME TestNARDeduplicationMetadataUploadBug1391 metadata_upload_test.go:54: Retrieved narinfo from S3:1392 StorePath: /nix/var/nix/builds/nix-4772-2940262897/TestNARDeduplicationMetadataUploadBug2260999259/001/store/bpjsgssilaf5i2hvh4s8j2zfi75cfkfm-file1.txt1393 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1394 Compression: zstd1395 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1396 NarSize: 1601397 References: 1398 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1399 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1400 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1401 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}14022026/08/27 18:11:52 OK 20251218171726_add_pins.sql (20.28ms)14032026-08-27 18:11:52.827 UTC [5060] ERROR: relation "goose_db_version" does not exist at character 3614042026-08-27 18:11:52.827 UTC [5060] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14052026/08/27 18:11:52 OK 20260628120000_add_object_size_and_stats.sql (14.18ms)14062026/08/27 18:11:52 goose: successfully migrated database to version: 2026062812000014072026/08/27 18:11:52 OK 1_commit_pending_closure.sql (1.89ms)14082026/08/27 18:11:52 OK 2_object_stats_trigger.sql (259.46µs)14092026/08/27 18:11:52 goose: up to current file version: 214102026/08/27 18:11:52 OK 20241026095416_initial_model.sql (75.58ms)14112026/08/27 18:11:52 OK 20251210153512_drop_unused_gin_index.sql (8.71ms)1412 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-4772-2940262897/TestNARDeduplicationMetadataUploadBug2260999259/001/store/wlwsh4g4wp2kg0jc4ndp18hqvib7qkr6-file2.txt14132026/08/27 18:11:52 OK 20251218171726_add_pins.sql (19.2ms)14142026/08/27 18:11:52 OK 20260628120000_add_object_size_and_stats.sql (29.5ms)14152026/08/27 18:11:52 goose: successfully migrated database to version: 2026062812000014162026/08/27 18:11:52 OK 1_commit_pending_closure.sql (1.06ms)14172026/08/27 18:11:52 OK 2_object_stats_trigger.sql (234.71µs)14182026/08/27 18:11:52 goose: up to current file version: 214192026/08/27 18:11:52 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14202026/08/27 18:11:52 OK 20241026095416_initial_model.sql (138.06ms)14212026/08/27 18:11:52 OK 20251210153512_drop_unused_gin_index.sql (9.4ms)14222026/08/27 18:11:53 INFO Received uploads request method=POST path=/api/pending_closures14232026/08/27 18:11:53 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)14242026/08/27 18:11:53 OK 20251218171726_add_pins.sql (26.78ms)14252026/08/27 18:11:53 WARN Failed to register uploaded object key=wlwsh4g4wp2kg0jc4ndp18hqvib7qkr6.ls error="server returned 404: 404 page not found\n"14262026/08/27 18:11:53 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14272026/08/27 18:11:53 INFO Signed narinfos id=2 count=114282026/08/27 18:11:53 INFO Uploading 1 narinfos14292026/08/27 18:11:53 OK 20260628120000_add_object_size_and_stats.sql (41.49ms)14302026/08/27 18:11:53 goose: successfully migrated database to version: 2026062812000014312026/08/27 18:11:53 OK 1_commit_pending_closure.sql (4.67ms)14322026/08/27 18:11:53 OK 2_object_stats_trigger.sql (228.46µs)14332026/08/27 18:11:53 goose: up to current file version: 214342026/08/27 18:11:53 WARN Failed to register uploaded object key=wlwsh4g4wp2kg0jc4ndp18hqvib7qkr6.narinfo error="server returned 404: 404 page not found\n"14352026/08/27 18:11:53 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14362026/08/27 18:11:53 INFO Completed upload id=214372026/08/27 18:11:53 INFO Upload complete. (149ms)1438 metadata_upload_test.go:76: Retrieved narinfo from S3:1439 StorePath: /nix/var/nix/builds/nix-4772-2940262897/TestNARDeduplicationMetadataUploadBug2260999259/001/store/wlwsh4g4wp2kg0jc4ndp18hqvib7qkr6-file2.txt1440 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1441 Compression: zstd1442 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1443 NarSize: 1601444 References: 1445 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1446 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1447 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1448 {"version":1,"root":{"type":"regular","size":44}}1449--- PASS: TestNARDeduplicationMetadataUploadBug (3.28s)1450=== CONT TestClientIntegration14512026/08/27 18:11:53 INFO Aborted multipart uploads count=014522026/08/27 18:11:53 WARN Force mode enabled - objects will be deleted immediately without grace period14532026/08/27 18:11: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=014542026/08/27 18:11:53 INFO Vacuumed table table=pending_closures14552026/08/27 18:11:53 INFO Vacuumed table table=pending_objects14562026/08/27 18:11:53 INFO Vacuumed table table=multipart_uploads14572026/08/27 18:11:53 INFO Vacuumed table table=closures14582026/08/27 18:11:53 INFO Vacuumed table table=objects1459--- PASS: TestGCMetrics (2.36s)1460=== CONT TestClientErrorHandling1461=== RUN TestClientErrorHandling/InvalidStorePath1462=== PAUSE TestClientErrorHandling/InvalidStorePath1463=== RUN TestClientErrorHandling/InvalidAuthToken1464=== PAUSE TestClientErrorHandling/InvalidAuthToken1465=== RUN TestClientErrorHandling/ServerNotAvailable1466=== PAUSE TestClientErrorHandling/ServerNotAvailable1467=== CONT TestClientCADerivations1468=== NAME TestClientMultipleUploads1469 client_integration_test.go:339: Created store path 0: /nix/var/nix/builds/nix-4772-2940262897/TestClientMultipleUploads3483613447/001/store/f3ndkvskpaxd5ljad31adbg4bx62ddyf-test-file-0.txt1470--- PASS: TestNoClosurePushCreatesIndependentGCRoots (5.48s)1471=== CONT TestCacheStatsHandler14722026/08/27 18:11:53 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=0 objects_marked=2 objects_deleted=2002 objects_failed=01473=== NAME TestClientMultipleUploads1474 client_integration_test.go:339: Created store path 1: /nix/var/nix/builds/nix-4772-2940262897/TestClientMultipleUploads3483613447/001/store/5f2xp4vlz914z2myh25gbwyspalz6cqf-test-file-1.txt1475--- PASS: TestNoClosurePushKeepsReferencedObjectsReachable (5.75s)1476=== CONT TestCacheConfigHandler1477=== RUN TestCacheConfigHandler/full_config,_no_issuer1478=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1479=== RUN TestCacheConfigHandler/no_cache_url_configured1480=== PAUSE TestCacheConfigHandler/no_cache_url_configured1481=== RUN TestCacheConfigHandler/no_signing_keys1482=== PAUSE TestCacheConfigHandler/no_signing_keys1483=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1484=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1485=== CONT TestService_ReadAuthMiddleware1486=== NAME TestClientMultipleUploads1487 client_integration_test.go:339: Created store path 2: /nix/var/nix/builds/nix-4772-2940262897/TestClientMultipleUploads3483613447/001/store/fzma56mk3w9g6fbpy12q81nqp0hpg207-test-file-2.txt14882026/08/27 18:11:53 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14892026-08-27 18:11:53.531 UTC [5089] ERROR: relation "goose_db_version" does not exist at character 3614902026-08-27 18:11:53.531 UTC [5089] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14912026/08/27 18:11:53 INFO Received uploads request method=POST path=/api/pending_closures1492--- PASS: TestGCBugBareHashReferences (2.61s)1493=== CONT TestService_RequireScope_OIDC14942026/08/27 18:11:53 INFO OIDC provider initialized name=test14952026/08/27 18:11:53 INFO Received uploads request method=POST path=/api/pending_closures14962026/08/27 18:11:53 INFO Received uploads request method=POST path=/api/pending_closures14972026/08/27 18:11:53 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)14982026/08/27 18:11:53 INFO Uploading fzma56mk3w9g6fbpy12q81nqp0hpg207-test-file-2.txt (160B)14992026/08/27 18:11:53 INFO Uploading f3ndkvskpaxd5ljad31adbg4bx62ddyf-test-file-0.txt (160B)15002026/08/27 18:11:53 INFO Uploading 5f2xp4vlz914z2myh25gbwyspalz6cqf-test-file-1.txt (160B)15012026/08/27 18:11:53 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"15022026/08/27 18:11:53 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"15032026/08/27 18:11:53 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"15042026/08/27 18:11:53 WARN Failed to register uploaded object key=f3ndkvskpaxd5ljad31adbg4bx62ddyf.ls error="server returned 404: 404 page not found\n"15052026/08/27 18:11:53 WARN Failed to register uploaded object key=fzma56mk3w9g6fbpy12q81nqp0hpg207.ls error="server returned 404: 404 page not found\n"15062026/08/27 18:11:53 WARN Failed to register uploaded object key=5f2xp4vlz914z2myh25gbwyspalz6cqf.ls error="server returned 404: 404 page not found\n"15072026/08/27 18:11:53 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15082026/08/27 18:11:53 INFO Signed narinfos id=2 count=115092026/08/27 18:11:53 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign15102026/08/27 18:11:53 INFO Signed narinfos id=3 count=115112026/08/27 18:11:53 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15122026/08/27 18:11:53 INFO Signed narinfos id=1 count=115132026/08/27 18:11:53 INFO Uploading 3 narinfos15142026/08/27 18:11:53 WARN Failed to register uploaded object key=fzma56mk3w9g6fbpy12q81nqp0hpg207.narinfo error="server returned 404: 404 page not found\n"15152026/08/27 18:11:53 WARN Failed to register uploaded object key=f3ndkvskpaxd5ljad31adbg4bx62ddyf.narinfo error="server returned 404: 404 page not found\n"15162026/08/27 18:11:53 WARN Failed to register uploaded object key=5f2xp4vlz914z2myh25gbwyspalz6cqf.narinfo error="server returned 404: 404 page not found\n"15172026/08/27 18:11:53 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15182026/08/27 18:11:53 INFO Completed upload id=215192026/08/27 18:11:53 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete15202026/08/27 18:11:53 INFO Completed upload id=315212026/08/27 18:11:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15222026/08/27 18:11:53 INFO Completed upload id=115232026/08/27 18:11:53 INFO Upload complete. (357ms)1524=== NAME TestClientMultipleUploads1525 client_integration_test.go:350: Uploaded 3 paths in 386.237666ms15262026/08/27 18:11:53 OK 20241026095416_initial_model.sql (201.32ms)15272026/08/27 18:11:53 OK 20251210153512_drop_unused_gin_index.sql (12.58ms)1528--- PASS: TestClientMultipleUploads (3.16s)1529=== CONT TestService_AuthMiddleware_OIDC15302026/08/27 18:11:53 INFO OIDC provider initialized name=test15312026/08/27 18:11:53 OK 20251218171726_add_pins.sql (31.3ms)15322026/08/27 18:11:53 OK 20260628120000_add_object_size_and_stats.sql (68.82ms)15332026/08/27 18:11:53 goose: successfully migrated database to version: 2026062812000015342026/08/27 18:11:53 OK 1_commit_pending_closure.sql (9.76ms)15352026/08/27 18:11:53 OK 2_object_stats_trigger.sql (998µs)15362026/08/27 18:11:53 goose: up to current file version: 215372026-08-27 18:11:54.360 UTC [5097] ERROR: relation "goose_db_version" does not exist at character 3615382026-08-27 18:11:54.360 UTC [5097] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1539=== NAME TestPinProtectsFromGC1540 client_integration_test.go:647: Pinned store path: /nix/var/nix/builds/nix-4772-2940262897/TestPinProtectsFromGC342549102/001/store/rxihgi8gh4zjzqlldalpvq3jinsy5xwy-pinned-file.txt1541 client_integration_test.go:648: Unpinned store path: /nix/var/nix/builds/nix-4772-2940262897/TestPinProtectsFromGC342549102/001/store/jfk2zf532h48sn7zfzdw5mqlibqvq8mz-unpinned-file.txt15422026-08-27 18:11:54.568 UTC [5101] ERROR: relation "goose_db_version" does not exist at character 3615432026-08-27 18:11:54.568 UTC [5101] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15442026/08/27 18:11:54 OK 20241026095416_initial_model.sql (148.5ms)15452026/08/27 18:11:54 OK 20251210153512_drop_unused_gin_index.sql (6.66ms)15462026/08/27 18:11:54 OK 20251218171726_add_pins.sql (22.96ms)15472026/08/27 18:11:54 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"15482026/08/27 18:11:54 OK 20260628120000_add_object_size_and_stats.sql (24.94ms)15492026/08/27 18:11:54 goose: successfully migrated database to version: 2026062812000015502026/08/27 18:11:54 OK 1_commit_pending_closure.sql (7.55ms)15512026/08/27 18:11:54 OK 2_object_stats_trigger.sql (220.17µs)15522026/08/27 18:11:54 goose: up to current file version: 215532026/08/27 18:11:54 INFO Received uploads request method=POST path=/api/pending_closures15542026/08/27 18:11:54 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15552026/08/27 18:11:54 INFO Uploading rxihgi8gh4zjzqlldalpvq3jinsy5xwy-pinned-file.txt (128B)15562026/08/27 18:11:54 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"15572026/08/27 18:11:54 OK 20241026095416_initial_model.sql (190.71ms)15582026/08/27 18:11:54 WARN Failed to register uploaded object key=rxihgi8gh4zjzqlldalpvq3jinsy5xwy.ls error="server returned 404: 404 page not found\n"15592026/08/27 18:11:54 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15602026/08/27 18:11:54 INFO Signed narinfos id=1 count=115612026/08/27 18:11:54 INFO Uploading 1 narinfos15622026/08/27 18:11:54 OK 20251210153512_drop_unused_gin_index.sql (17.02ms)15632026/08/27 18:11:54 OK 20251218171726_add_pins.sql (48.61ms)15642026/08/27 18:11:54 WARN Failed to register uploaded object key=rxihgi8gh4zjzqlldalpvq3jinsy5xwy.narinfo error="server returned 404: 404 page not found\n"15652026/08/27 18:11:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15662026/08/27 18:11:54 OK 20260628120000_add_object_size_and_stats.sql (76.84ms)15672026/08/27 18:11:54 goose: successfully migrated database to version: 2026062812000015682026/08/27 18:11:54 INFO Completed upload id=115692026/08/27 18:11:54 INFO Upload complete. (374ms)15702026/08/27 18:11:54 OK 1_commit_pending_closure.sql (13.54ms)15712026/08/27 18:11:54 OK 2_object_stats_trigger.sql (380.75µs)15722026/08/27 18:11:54 goose: up to current file version: 215732026/08/27 18:11:55 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"15742026/08/27 18:11:55 INFO Received uploads request method=POST path=/api/pending_closures15752026/08/27 18:11:55 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15762026/08/27 18:11:55 INFO Uploading jfk2zf532h48sn7zfzdw5mqlibqvq8mz-unpinned-file.txt (128B)1577--- PASS: TestService_ReadScope_PublicByDefault (2.45s)1578=== CONT TestService_AuthMiddleware_MTLSBoundSubjects15792026/08/27 18:11:55 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"15802026/08/27 18:11:55 WARN Failed to register uploaded object key=jfk2zf532h48sn7zfzdw5mqlibqvq8mz.ls error="server returned 404: 404 page not found\n"15812026/08/27 18:11:55 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15822026/08/27 18:11:55 INFO Signed narinfos id=2 count=115832026/08/27 18:11:55 INFO Uploading 1 narinfos15842026/08/27 18:11:55 WARN Failed to register uploaded object key=jfk2zf532h48sn7zfzdw5mqlibqvq8mz.narinfo error="server returned 404: 404 page not found\n"15852026/08/27 18:11:55 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15862026/08/27 18:11:55 INFO Completed upload id=215872026/08/27 18:11:55 INFO Upload complete. (250ms)15882026/08/27 18:11:55 INFO Received create pin request method=POST path=/api/pins/myapp15892026/08/27 18:11:55 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-4772-2940262897/TestPinProtectsFromGC342549102/001/store/rxihgi8gh4zjzqlldalpvq3jinsy5xwy-pinned-file.txt narinfo_key=rxihgi8gh4zjzqlldalpvq3jinsy5xwy.narinfo15902026/08/27 18:11:55 INFO Starting cleanup of old closures method=DELETE path=/api/closures15912026/08/27 18:11:55 INFO Garbage collection started15922026/08/27 18:11:55 INFO Aborted multipart uploads count=015932026/08/27 18:11:55 WARN Force mode enabled - objects will be deleted immediately without grace period15942026-08-27 18:11:55.354 UTC [5125] ERROR: relation "goose_db_version" does not exist at character 3615952026-08-27 18:11:55.354 UTC [5125] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15962026-08-27 18:11:55.358 UTC [5126] ERROR: relation "goose_db_version" does not exist at character 3615972026-08-27 18:11:55.358 UTC [5126] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1598=== NAME TestClientWithDependencies1599 client_integration_test.go:594: Built derivation: /nix/var/nix/builds/nix-4772-2940262897/TestClientWithDependencies357724985/001/store/2lv2izb0r9qxz4maivkcwq0ndlj49kz5-test-script16002026-08-27 18:11:55.396 UTC [5127] ERROR: relation "goose_db_version" does not exist at character 3616012026-08-27 18:11:55.396 UTC [5127] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16022026-08-27 18:11:55.404 UTC [5128] ERROR: relation "goose_db_version" does not exist at character 3616032026-08-27 18:11:55.404 UTC [5128] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1604 client_integration_test.go:596: Found 1 dependencies (including self)16052026/08/27 18:11:55 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=016062026/08/27 18:11:55 INFO Vacuumed table table=pending_closures16072026/08/27 18:11:55 INFO Vacuumed table table=pending_objects16082026/08/27 18:11:55 INFO Vacuumed table table=multipart_uploads16092026/08/27 18:11:55 OK 20241026095416_initial_model.sql (100.97ms)16102026/08/27 18:11:55 OK 20251210153512_drop_unused_gin_index.sql (6.62ms)16112026/08/27 18:11:55 INFO Vacuumed table table=closures16122026/08/27 18:11:55 OK 20241026095416_initial_model.sql (110.99ms)16132026/08/27 18:11:55 OK 20241026095416_initial_model.sql (88.3ms)16142026/08/27 18:11:55 OK 20251218171726_add_pins.sql (14.03ms)16152026/08/27 18:11:55 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16162026/08/27 18:11:55 INFO Received uploads request method=POST path=/api/pending_closures16172026/08/27 18:11:55 OK 20251210153512_drop_unused_gin_index.sql (2.85ms)16182026/08/27 18:11:55 INFO Vacuumed table table=objects16192026/08/27 18:11:55 OK 20251210153512_drop_unused_gin_index.sql (10.74ms)16202026/08/27 18:11:55 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16212026/08/27 18:11:55 INFO Uploading 2lv2izb0r9qxz4maivkcwq0ndlj49kz5-test-script (136B)16222026/08/27 18:11:55 OK 20251218171726_add_pins.sql (29.98ms)16232026/08/27 18:11:55 OK 20241026095416_initial_model.sql (101ms)16242026/08/27 18:11:55 OK 20260628120000_add_object_size_and_stats.sql (32.39ms)16252026/08/27 18:11:55 goose: successfully migrated database to version: 2026062812000016262026/08/27 18:11:55 OK 1_commit_pending_closure.sql (982.46µs)16272026/08/27 18:11:55 OK 2_object_stats_trigger.sql (222.04µs)16282026/08/27 18:11:55 goose: up to current file version: 216292026/08/27 18:11:55 OK 20251210153512_drop_unused_gin_index.sql (11.68ms)16302026/08/27 18:11:55 OK 20251218171726_add_pins.sql (38.3ms)16312026-08-27 18:11:55.563 UTC [5136] ERROR: relation "goose_db_version" does not exist at character 3616322026-08-27 18:11:55.563 UTC [5136] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16332026/08/27 18:11:55 OK 20260628120000_add_object_size_and_stats.sql (52.44ms)16342026/08/27 18:11:55 goose: successfully migrated database to version: 2026062812000016352026/08/27 18:11:55 OK 20260628120000_add_object_size_and_stats.sql (45.89ms)16362026/08/27 18:11:55 goose: successfully migrated database to version: 2026062812000016372026/08/27 18:11:55 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"16382026/08/27 18:11:55 WARN Failed to register uploaded object key=log/79zy9qdpx7gkwi4q3fm13g4lgn1rqv42-test-script.drv error="server returned 404: 404 page not found\n"16392026/08/27 18:11:55 OK 1_commit_pending_closure.sql (15.05ms)16402026/08/27 18:11:55 OK 2_object_stats_trigger.sql (247.08µs)16412026/08/27 18:11:55 goose: up to current file version: 216422026/08/27 18:11:55 OK 20251218171726_add_pins.sql (60.84ms)16432026/08/27 18:11:55 OK 1_commit_pending_closure.sql (10.22ms)16442026/08/27 18:11:55 OK 2_object_stats_trigger.sql (227.54µs)16452026/08/27 18:11:55 goose: up to current file version: 216462026/08/27 18:11:55 WARN Failed to register uploaded object key=2lv2izb0r9qxz4maivkcwq0ndlj49kz5.ls error="server returned 404: 404 page not found\n"16472026/08/27 18:11:55 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16482026/08/27 18:11:55 INFO Signed narinfos id=1 count=116492026/08/27 18:11:55 INFO Uploading 1 narinfos16502026/08/27 18:11:55 OK 20260628120000_add_object_size_and_stats.sql (35.66ms)16512026/08/27 18:11:55 goose: successfully migrated database to version: 2026062812000016522026/08/27 18:11:55 OK 1_commit_pending_closure.sql (17.14ms)16532026/08/27 18:11:55 OK 2_object_stats_trigger.sql (304µs)16542026/08/27 18:11:55 goose: up to current file version: 216552026/08/27 18:11:55 WARN Failed to register uploaded object key=2lv2izb0r9qxz4maivkcwq0ndlj49kz5.narinfo error="server returned 404: 404 page not found\n"16562026/08/27 18:11:55 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16572026/08/27 18:11:55 INFO Completed upload id=116582026/08/27 18:11:55 INFO Upload complete. (232ms)1659 client_integration_test.go:598: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-4772-2940262897/TestClientWithDependencies357724985/001/store) requires matching store prefix1660--- PASS: TestClientWithDependencies (3.36s)1661=== CONT TestService_AuthMiddleware_MTLSProxyHeader16622026/08/27 18:11:55 OK 20241026095416_initial_model.sql (242.7ms)16632026/08/27 18:11:55 OK 20251210153512_drop_unused_gin_index.sql (14.54ms)16642026/08/27 18:11:55 OK 20251218171726_add_pins.sql (34.26ms)16652026/08/27 18:11:55 OK 20260628120000_add_object_size_and_stats.sql (39.93ms)16662026/08/27 18:11:55 goose: successfully migrated database to version: 2026062812000016672026/08/27 18:11:55 OK 1_commit_pending_closure.sql (6.89ms)16682026/08/27 18:11:55 OK 2_object_stats_trigger.sql (366.25µs)16692026/08/27 18:11:55 goose: up to current file version: 216702026-08-27 18:11:56.082 UTC [5144] ERROR: relation "goose_db_version" does not exist at character 3616712026-08-27 18:11:56.082 UTC [5144] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1672--- PASS: TestCacheStatsHandler (2.86s)1673=== CONT TestProxyWriteTimeout/unknown_size1674=== CONT TestProxyWriteTimeout/narinfo1675=== CONT TestProxyWriteTimeout/10_GiB_nar1676=== CONT TestProxyWriteTimeout/1_GiB_nar1677--- PASS: TestProxyWriteTimeout (0.00s)1678 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1679 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1680 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1681 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1682=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16832026/08/27 18:11:56 INFO Received uploads request method=POST path=/1684=== NAME TestClientIntegration1685 client_integration_test.go:277: Created store path: /nix/var/nix/builds/nix-4772-2940262897/TestClientIntegration891916838/002/store/k0rydskys72jys311sfnfbrgbpprfk2m-test-file.txt1686--- PASS: TestService_ReadAuthMiddleware (2.83s)1687=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16882026/08/27 18:11:56 INFO Received complete multipart upload request method=POST path=/1689=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16902026/08/27 18:11:56 INFO Received request for more parts method=POST path=/16912026/08/27 18:11:56 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1692=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16932026/08/27 18:11:56 INFO Received uploads request method=POST path=/1694=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16952026/08/27 18:11:56 INFO Received complete multipart upload request method=POST path=/1696=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16972026/08/27 18:11:56 INFO Received request for more parts method=POST path=/1698=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16992026/08/27 18:11:56 INFO Received uploads request method=POST path=/1700--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1701 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1702 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1703 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1704 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1705=== CONT TestIsValidUploadKey/narinfo1706=== CONT TestIsValidUploadKey/realisation_plus_in_output1707=== CONT TestIsValidUploadKey/unknown_type1708=== CONT TestIsValidUploadKey/empty_key1709=== CONT TestIsValidUploadKey/absolute1710=== CONT TestIsValidUploadKey/traversal_nar1711=== CONT TestIsValidUploadKey/traversal1712=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1713=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1714=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1715=== CONT TestIsValidUploadKey/index.html1716=== CONT TestIsValidUploadKey/nix-cache-info1717=== CONT TestIsValidUploadKey/build_log_home-manager_file1718=== CONT TestIsValidUploadKey/realisation1719=== CONT TestIsValidUploadKey/build_log_equals1720=== CONT TestIsValidUploadKey/build_log_question_mark1721=== CONT TestIsValidUploadKey/build_log_plus_in_name1722=== CONT TestIsValidUploadKey/nar_plain1723=== CONT TestIsValidUploadKey/build_log1724=== CONT TestIsValidUploadKey/listing1725=== CONT TestIsValidUploadKey/nar_xz1726=== CONT TestIsValidUploadKey/nar_zst1727--- PASS: TestIsValidUploadKey (0.00s)1728 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1729 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1730 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1731 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1732 --- PASS: TestIsValidUploadKey/absolute (0.00s)1733 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1734 --- PASS: TestIsValidUploadKey/traversal (0.00s)1735 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1736 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1737 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1738 --- PASS: TestIsValidUploadKey/index.html (0.00s)1739 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1740 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1741 --- PASS: TestIsValidUploadKey/realisation (0.00s)1742 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1743 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1744 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1745 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1746 --- PASS: TestIsValidUploadKey/build_log (0.00s)1747 --- PASS: TestIsValidUploadKey/listing (0.00s)1748 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1749 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1750=== CONT TestIsValidCachePath/narinfo1751=== CONT TestIsValidCachePath/index.html1752=== CONT TestIsValidCachePath/short_hash1753=== CONT TestIsValidCachePath/wrong_extension1754=== CONT TestIsValidCachePath/leading_slash1755=== CONT TestIsValidCachePath/empty1756=== CONT TestIsValidCachePath/random_path1757=== CONT TestIsValidCachePath/invalid_char_u1758=== CONT TestIsValidCachePath/invalid_char_e1759=== CONT TestIsValidCachePath/traversal_in_middle1760=== CONT TestIsValidCachePath/traversal_parent1761=== CONT TestIsValidCachePath/nar_uncompressed1762=== CONT TestIsValidCachePath/nix-cache-info1763=== CONT TestIsValidCachePath/realisation1764=== CONT TestIsValidCachePath/log1765=== CONT TestIsValidCachePath/ls1766=== CONT TestIsValidCachePath/nar_zst1767=== CONT TestIsValidCachePath/nar_bz21768=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1769=== CONT TestIsValidCachePath/nar_xz1770--- PASS: TestIsValidCachePath (0.00s)1771 --- PASS: TestIsValidCachePath/narinfo (0.00s)1772 --- PASS: TestIsValidCachePath/index.html (0.00s)1773 --- PASS: TestIsValidCachePath/short_hash (0.00s)1774 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1775 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1776 --- PASS: TestIsValidCachePath/empty (0.00s)1777 --- PASS: TestIsValidCachePath/random_path (0.00s)1778 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1779 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1780 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1781 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1782 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1783 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1784 --- PASS: TestIsValidCachePath/realisation (0.00s)1785 --- PASS: TestIsValidCachePath/log (0.00s)1786 --- PASS: TestIsValidCachePath/ls (0.00s)1787 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1788 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1789 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1790 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1791=== CONT TestParseSingleRange/none1792=== CONT TestParseSingleRange/open-ended1793=== CONT TestParseSingleRange/start_far_past_EOF1794=== CONT TestParseSingleRange/start_past_EOF1795=== CONT TestParseSingleRange/single_byte1796=== CONT TestParseSingleRange/suffix_exceeds_size1797=== CONT TestParseSingleRange/suffix1798=== CONT TestParseSingleRange/end_clamped_to_size1799=== CONT TestParseSingleRange/multi-range_ignored1800=== CONT TestParseSingleRange/malformed_no_dash1801=== CONT TestParseSingleRange/closed1802=== CONT TestParseSingleRange/malformed_end_before_start1803=== CONT TestParseSingleRange/unknown_unit1804=== CONT TestParseSingleRange/malformed_both_empty1805--- PASS: TestParseSingleRange (0.00s)1806 --- PASS: TestParseSingleRange/none (0.00s)1807 --- PASS: TestParseSingleRange/open-ended (0.00s)1808 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1809 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1810 --- PASS: TestParseSingleRange/single_byte (0.00s)1811 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1812 --- PASS: TestParseSingleRange/suffix (0.00s)1813 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1814 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1815 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1816 --- PASS: TestParseSingleRange/closed (0.00s)1817 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1818 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1819 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1820=== CONT TestServerTLSConfig/no_client_CA1821=== CONT TestServerTLSConfig/not_a_PEM_file1822=== CONT TestServerTLSConfig/missing_CA_file1823--- PASS: TestServerTLSConfig (0.00s)1824 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1825 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1826 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1827=== CONT TestResolveDBConnectionString/flag_wins1828=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1829=== CONT TestResolveDBConnectionString/nothing_configured1830=== CONT TestResolveDBConnectionString/missing_file_is_an_error1831=== CONT TestResolveDBConnectionString/file_when_flag_empty1832=== CONT TestClientErrorHandling/InvalidStorePath1833--- PASS: TestResolveDBConnectionString (0.01s)1834 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1835 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1836 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1837 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1838 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1839=== NAME TestClientCADerivations1840 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-4772-2940262897/TestClientCADerivations2774268517/001/store/s42vpr8ws5ac9lv92k2q5yg2zn9654x4-ca-test18412026/08/27 18:11:56 INFO Received uploads request method=POST path=/api/pending_closures18422026/08/27 18:11:56 OK 20241026095416_initial_model.sql (162.74ms)18432026/08/27 18:11:56 OK 20251210153512_drop_unused_gin_index.sql (12.22ms)1844 client_ca_test.go:139: Found 1 dependencies (including self)18452026/08/27 18:11:56 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18462026/08/27 18:11:56 INFO Uploading k0rydskys72jys311sfnfbrgbpprfk2m-test-file.txt (152B)18472026/08/27 18:11:56 OK 20251218171726_add_pins.sql (18.3ms)1848=== RUN TestService_RequireScope_OIDC/builder_may_write1849=== PAUSE TestService_RequireScope_OIDC/builder_may_write1850=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1851=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1852=== RUN TestService_RequireScope_OIDC/ops_may_admin1853=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1854=== RUN TestService_RequireScope_OIDC/ops_may_not_write1855=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1856=== RUN TestService_RequireScope_OIDC/reader_may_not_write1857=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1858=== RUN TestService_RequireScope_OIDC/static_token_may_admin1859=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1860=== RUN TestService_RequireScope_OIDC/static_token_may_write1861=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1862=== RUN TestService_RequireScope_OIDC/reader_may_read1863=== PAUSE TestService_RequireScope_OIDC/reader_may_read1864=== RUN TestService_RequireScope_OIDC/writer_implies_read1865=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1866=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1867=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1868=== CONT TestClientErrorHandling/ServerNotAvailable18692026/08/27 18:11:56 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"18702026/08/27 18:11:56 OK 20260628120000_add_object_size_and_stats.sql (44.43ms)18712026/08/27 18:11:56 goose: successfully migrated database to version: 2026062812000018722026/08/27 18:11:56 OK 1_commit_pending_closure.sql (1.91ms)18732026/08/27 18:11:56 OK 2_object_stats_trigger.sql (338.92µs)18742026/08/27 18:11:56 goose: up to current file version: 21875--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)1876 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1877 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1878 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.27s)1879=== CONT TestClientErrorHandling/InvalidAuthToken18802026/08/27 18:11:56 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"18812026/08/27 18:11:56 WARN Failed to register uploaded object key=k0rydskys72jys311sfnfbrgbpprfk2m.ls error="server returned 404: 404 page not found\n"18822026/08/27 18:11:56 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18832026/08/27 18:11:56 INFO Signed narinfos id=1 count=118842026/08/27 18:11:56 INFO Uploading 1 narinfos18852026/08/27 18:11:56 INFO Received uploads request method=POST path=/api/pending_closures18862026/08/27 18:11:56 WARN Failed to register uploaded object key=k0rydskys72jys311sfnfbrgbpprfk2m.narinfo error="server returned 404: 404 page not found\n"18872026/08/27 18:11:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18882026/08/27 18:11:56 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18892026/08/27 18:11:56 INFO Uploading s42vpr8ws5ac9lv92k2q5yg2zn9654x4-ca-test (144B)18902026/08/27 18:11:56 INFO Completed upload id=118912026/08/27 18:11:56 INFO Upload complete. (307ms)1892=== NAME TestClientIntegration1893 client_integration_test.go:293: Retrieved narinfo from S3:1894 StorePath: /nix/var/nix/builds/nix-4772-2940262897/TestClientIntegration891916838/002/store/k0rydskys72jys311sfnfbrgbpprfk2m-test-file.txt1895 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1896 Compression: zstd1897 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11898 NarSize: 1521899 References: 1900 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11901 client_integration_test.go:294: Retrieved .ls file from S3 (compressed size: 77 bytes)1902 client_integration_test.go:294: Decompressed .ls content (64 bytes):1903 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1904 client_integration_test.go:297: Testing garbage collection...19052026/08/27 18:11:56 INFO Starting cleanup of old closures method=DELETE path=/api/closures19062026/08/27 18:11:56 INFO Garbage collection started19072026/08/27 18:11:56 INFO Aborted multipart uploads count=019082026/08/27 18:11:56 WARN Force mode enabled - objects will be deleted immediately without grace period19092026/08/27 18:11:56 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"19102026/08/27 18:11:56 WARN Failed to register uploaded object key=log/bjva4cmznn8g9ni5sw5p3bqdc312pd7x-ca-test.drv error="server returned 404: 404 page not found\n"19112026/08/27 18:11:56 WARN Failed to register uploaded object key=s42vpr8ws5ac9lv92k2q5yg2zn9654x4.ls error="server returned 404: 404 page not found\n"19122026/08/27 18:11:56 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign19132026/08/27 18:11:56 INFO Signed narinfos id=1 count=119142026/08/27 18:11:56 INFO Uploading 1 narinfos1915=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1916=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1917=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1918=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1919=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1920=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1921=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1922=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1923=== CONT TestCacheConfigHandler/full_config,_no_issuer1924=== CONT TestCacheConfigHandler/no_signing_keys1925=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1926=== CONT TestCacheConfigHandler/no_cache_url_configured1927--- PASS: TestCacheConfigHandler (0.00s)1928 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1929 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1930 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1931 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1932=== CONT TestService_RequireScope_OIDC/builder_may_write19332026/08/27 18:11:56 INFO OIDC auth successful provider=test scopes=[write]1934=== CONT TestService_RequireScope_OIDC/static_token_may_admin1935=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1936=== CONT TestService_RequireScope_OIDC/writer_implies_read19372026/08/27 18:11:56 INFO OIDC auth successful provider=test scopes=[write]1938=== CONT TestService_RequireScope_OIDC/reader_may_read19392026/08/27 18:11:56 INFO OIDC auth successful provider=test scopes=[read]1940=== CONT TestService_RequireScope_OIDC/static_token_may_write1941=== CONT TestService_RequireScope_OIDC/ops_may_admin19422026/08/27 18:11:56 INFO OIDC auth successful provider=test scopes=[admin]1943=== CONT TestService_RequireScope_OIDC/reader_may_not_write19442026/08/27 18:11:56 INFO OIDC auth successful provider=test scopes=[read]1945=== CONT TestService_RequireScope_OIDC/ops_may_not_write19462026/08/27 18:11:56 INFO OIDC auth successful provider=test scopes=[admin]1947=== CONT TestService_RequireScope_OIDC/builder_may_not_admin19482026/08/27 18:11:56 INFO OIDC auth successful provider=test scopes=[write]1949=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token19502026/08/27 18:11:56 INFO OIDC auth successful provider=test scopes=[write]1951=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19522026/08/27 18:11:56 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]1953=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19542026/08/27 18:11:56 WARN Authentication failed token_preview=eyJhbGciOi...tFch9djgaA token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1955=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1956--- PASS: TestService_RequireScope_OIDC (2.81s)1957 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1958 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1959 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1960 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1961 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1962 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1963 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1964 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1965 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1966 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1967--- PASS: TestService_AuthMiddleware_OIDC (2.74s)1968 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1969 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1970 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1971 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)19722026/08/27 18:11:56 WARN Failed to register uploaded object key=s42vpr8ws5ac9lv92k2q5yg2zn9654x4.narinfo error="server returned 404: 404 page not found\n"19732026/08/27 18:11:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19742026/08/27 18:11:56 INFO Completed upload id=119752026/08/27 18:11:56 INFO Upload complete. (302ms)1976=== NAME TestClientCADerivations1977 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-4772-2940262897/TestClientCADerivations2774268517/001/store/s42vpr8ws5ac9lv92k2q5yg2zn9654x4-ca-test1978 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1979 Compression: zstd1980 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1981 NarSize: 1441982 References: 1983 Deriver: /nix/var/nix/builds/nix-4772-2940262897/TestClientCADerivations2774268517/001/store/bjva4cmznn8g9ni5sw5p3bqdc312pd7x-ca-test.drv1984 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1985 client_ca_test.go:185: Checking for realisation files in S3...1986 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1987 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache19882026/08/27 18:11:56 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=019892026/08/27 18:11:56 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-config19902026/08/27 18:11:56 INFO Vacuumed table table=pending_closures19912026/08/27 18:11:56 INFO Vacuumed table table=pending_objects19922026/08/27 18:11:56 INFO Vacuumed table table=multipart_uploads19932026/08/27 18:11:56 INFO Vacuumed table table=closures1994 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket44?endpoint=http://localhost:57064®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-4772-2940262897/TestClientCADerivations2774268517/001/store'1995 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 119962026/08/27 18:11:56 INFO Vacuumed table table=objects19972026/08/27 18:11:56 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=181.443029ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19982026-08-27 18:11:56.827 UTC [5177] ERROR: relation "goose_db_version" does not exist at character 3619992026-08-27 18:11:56.827 UTC [5177] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2000--- PASS: TestClientCADerivations (3.70s)20012026/08/27 18:11:56 OK 20241026095416_initial_model.sql (94.93ms)20022026/08/27 18:11:56 OK 20251210153512_drop_unused_gin_index.sql (11.66ms)20032026/08/27 18:11:56 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=401.366963ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20042026/08/27 18:11:57 OK 20251218171726_add_pins.sql (22.59ms)20052026/08/27 18:11:57 OK 20260628120000_add_object_size_and_stats.sql (25.9ms)20062026/08/27 18:11:57 goose: successfully migrated database to version: 2026062812000020072026/08/27 18:11:57 OK 1_commit_pending_closure.sql (5.48ms)20082026/08/27 18:11:57 OK 2_object_stats_trigger.sql (1.12ms)20092026/08/27 18:11:57 goose: up to current file version: 220102026/08/27 18:11:57 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20112026/08/27 18:11:57 WARN mTLS auth: bound subjects configured but subject DN unavailable20122026/08/27 18:11:57 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2013--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.11s)20142026/08/27 18:11:57 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02015=== NAME TestPinProtectsFromGC2016 client_integration_test.go:710: Pin successfully protected closure from garbage collection2017--- PASS: TestPinProtectsFromGC (5.62s)20182026/08/27 18:11:57 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=863.553272ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20192026-08-27 18:11:57.625 UTC [5178] ERROR: relation "goose_db_version" does not exist at character 3620202026-08-27 18:11:57.625 UTC [5178] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20212026/08/27 18:11:57 OK 20241026095416_initial_model.sql (191.72ms)20222026/08/27 18:11:57 OK 20251210153512_drop_unused_gin_index.sql (5.15ms)20232026/08/27 18:11:57 OK 20251218171726_add_pins.sql (25.99ms)20242026/08/27 18:11:57 OK 20260628120000_add_object_size_and_stats.sql (17.45ms)20252026/08/27 18:11:57 goose: successfully migrated database to version: 2026062812000020262026/08/27 18:11:57 OK 1_commit_pending_closure.sql (12.46ms)20272026/08/27 18:11:57 OK 2_object_stats_trigger.sql (1.18ms)20282026/08/27 18:11:57 goose: up to current file version: 22029--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (2.28s)20302026-08-27 18:11:58.206 UTC [5180] ERROR: relation "goose_db_version" does not exist at character 3620312026-08-27 18:11:58.206 UTC [5180] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20322026-08-27 18:11:58.249 UTC [5181] ERROR: relation "goose_db_version" does not exist at character 3620332026-08-27 18:11:58.249 UTC [5181] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20342026/08/27 18:11:58 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.534133732s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20352026/08/27 18:11:58 OK 20241026095416_initial_model.sql (115.62ms)20362026/08/27 18:11:58 OK 20251210153512_drop_unused_gin_index.sql (11.75ms)20372026/08/27 18:11:58 OK 20251218171726_add_pins.sql (26.02ms)20382026/08/27 18:11:58 OK 20260628120000_add_object_size_and_stats.sql (14.69ms)20392026/08/27 18:11:58 goose: successfully migrated database to version: 2026062812000020402026/08/27 18:11:58 OK 20241026095416_initial_model.sql (124.58ms)20412026/08/27 18:11:58 OK 1_commit_pending_closure.sql (4.64ms)20422026/08/27 18:11:58 OK 2_object_stats_trigger.sql (923.46µs)20432026/08/27 18:11:58 goose: up to current file version: 220442026/08/27 18:11:58 OK 20251210153512_drop_unused_gin_index.sql (5.51ms)20452026/08/27 18:11:58 OK 20251218171726_add_pins.sql (16.66ms)2046=== NAME TestOrphanedObjectsGCStressTest2047 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains20482026/08/27 18:11:58 OK 20260628120000_add_object_size_and_stats.sql (21.83ms)20492026/08/27 18:11:58 goose: successfully migrated database to version: 2026062812000020502026/08/27 18:11:58 OK 1_commit_pending_closure.sql (4.45ms)20512026/08/27 18:11:58 OK 2_object_stats_trigger.sql (1.01ms)20522026/08/27 18:11:58 goose: up to current file version: 220532026/08/27 18:11:58 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02054 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion2055=== NAME TestClientIntegration2056 client_integration_test.go:304: Objects in database after GC:2057 client_integration_test.go:304: Successfully deleted all objects with GC --force2058--- PASS: TestClientIntegration (5.43s)20592026/08/27 18:11:58 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"20602026/08/27 18:11:58 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2061=== NAME TestOrphanedObjectsGCStressTest2062 orphaned_objects_gc_test.go:509: Stress test completed successfully:2063 orphaned_objects_gc_test.go:510: - Active objects preserved: 202064 orphaned_objects_gc_test.go:511: - Objects deleted: 2102065 orphaned_objects_gc_test.go:512: - Total GC'd: 2102066--- PASS: TestOrphanedObjectsGCStressTest (11.88s)20672026/08/27 18:11:59 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"20682026/08/27 18:11:59 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_closures20692026/08/27 18:11:59 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=191.735451ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20702026/08/27 18:12:00 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=362.837361ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20712026/08/27 18:12:00 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=794.612911ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20722026/08/27 18:12:01 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.634744181s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2073--- PASS: TestClientErrorHandling (0.00s)2074 --- PASS: TestClientErrorHandling/InvalidStorePath (2.34s)2075 --- PASS: TestClientErrorHandling/InvalidAuthToken (2.44s)2076 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.64s)2077PASS20782026-08-27 18:12:03.116 UTC [4808] LOG: received smart shutdown request20792026-08-27 18:12:03.117 UTC [4808] LOG: background worker "logical replication launcher" (PID 4819) exited with exit code 120802026-08-27 18:12:03.125 UTC [4813] LOG: shutting down20812026-08-27 18:12:03.125 UTC [4813] LOG: checkpoint starting: shutdown immediate20822026-08-27 18:12:04.195 UTC [4813] LOG: checkpoint complete: wrote 13166 buffers (80.4%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 15 recycled; write=0.773 s, sync=0.296 s, total=1.071 s; sync files=17486, longest=0.001 s, average=0.001 s; distance=245078 kB, estimate=245078 kB; lsn=0/106E07A8, redo lsn=0/106E07A820832026-08-27 18:12:04.200 UTC [4808] LOG: database system is shut down2084Running OIDC tests...2085=== RUN TestGlobMatch2086=== PAUSE TestGlobMatch2087=== RUN TestAudienceForIssuer2088=== PAUSE TestAudienceForIssuer2089=== RUN TestValidateToken_ValidToken2090=== PAUSE TestValidateToken_ValidToken2091=== RUN TestValidateToken_WrongAudience2092=== PAUSE TestValidateToken_WrongAudience2093=== RUN TestValidateToken_Expired2094=== PAUSE TestValidateToken_Expired2095=== RUN TestValidateToken_BoundClaimsMismatch2096=== PAUSE TestValidateToken_BoundClaimsMismatch2097=== RUN TestValidateToken_BoundSubjectMismatch2098=== PAUSE TestValidateToken_BoundSubjectMismatch2099=== RUN TestValidateToken_MultipleProviders2100=== PAUSE TestValidateToken_MultipleProviders2101=== RUN TestValidateToken_NoMatchingProvider2102=== PAUSE TestValidateToken_NoMatchingProvider2103=== RUN TestValidateToken_KubernetesServiceAccount2104=== PAUSE TestValidateToken_KubernetesServiceAccount2105=== RUN TestNewValidator_KubernetesRequiresCA2106=== PAUSE TestNewValidator_KubernetesRequiresCA2107=== RUN TestScopes_LegacyProviderDefaultsToWrite2108=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2109=== RUN TestScopes_Rules2110=== PAUSE TestScopes_Rules2111=== RUN TestScopes_ConfigValidation2112=== PAUSE TestScopes_ConfigValidation2113=== CONT TestGlobMatch2114=== RUN TestGlobMatch/foo_foo2115=== PAUSE TestGlobMatch/foo_foo2116=== RUN TestGlobMatch/foo_bar2117=== CONT TestValidateToken_Expired2118=== PAUSE TestGlobMatch/foo_bar2119=== CONT TestAudienceForIssuer2120--- PASS: TestAudienceForIssuer (0.00s)2121=== CONT TestValidateToken_MultipleProviders2122=== RUN TestGlobMatch/*_2123=== PAUSE TestGlobMatch/*_2124=== RUN TestGlobMatch/*_anything2125=== PAUSE TestGlobMatch/*_anything2126=== RUN TestGlobMatch/foo*_foo2127=== PAUSE TestGlobMatch/foo*_foo2128=== RUN TestGlobMatch/foo*_foobar2129=== CONT TestValidateToken_BoundSubjectMismatch2130=== PAUSE TestGlobMatch/foo*_foobar2131=== RUN TestGlobMatch/foo*_bar2132=== PAUSE TestGlobMatch/foo*_bar2133=== RUN TestGlobMatch/*bar_bar2134=== PAUSE TestGlobMatch/*bar_bar2135=== RUN TestGlobMatch/*bar_foobar2136=== PAUSE TestGlobMatch/*bar_foobar2137=== RUN TestGlobMatch/*bar_foo2138=== PAUSE TestGlobMatch/*bar_foo2139=== RUN TestGlobMatch/foo*bar_foobar2140=== PAUSE TestGlobMatch/foo*bar_foobar2141=== RUN TestGlobMatch/foo*bar_foo123bar2142=== PAUSE TestGlobMatch/foo*bar_foo123bar2143=== CONT TestValidateToken_BoundClaimsMismatch2144=== RUN TestGlobMatch/foo*bar_foobarbaz2145=== PAUSE TestGlobMatch/foo*bar_foobarbaz2146=== RUN TestGlobMatch/*/*_foo/bar2147=== PAUSE TestGlobMatch/*/*_foo/bar2148=== RUN TestGlobMatch/*/*_foo2149=== PAUSE TestGlobMatch/*/*_foo2150=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2151=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2152=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02153=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02154=== RUN TestGlobMatch/refs/*/main_refs/heads/main2155=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2156=== RUN TestGlobMatch/fo?_foo2157=== PAUSE TestGlobMatch/fo?_foo2158=== RUN TestGlobMatch/fo?_fo2159=== PAUSE TestGlobMatch/fo?_fo2160=== RUN TestGlobMatch/fo?_fooo2161=== PAUSE TestGlobMatch/fo?_fooo2162=== RUN TestGlobMatch/?oo_foo2163=== PAUSE TestGlobMatch/?oo_foo2164=== CONT TestValidateToken_WrongAudience2165=== CONT TestScopes_LegacyProviderDefaultsToWrite2166=== CONT TestScopes_ConfigValidation2167=== CONT TestScopes_Rules2168=== CONT TestValidateToken_KubernetesServiceAccount2169=== RUN TestGlobMatch/?oo_boo2170=== PAUSE TestGlobMatch/?oo_boo2171=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2172=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2173=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2174=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2175=== CONT TestNewValidator_KubernetesRequiresCA21762026/08/27 18:12:05 INFO OIDC provider initialized name=test21772026/08/27 18:12:05 INFO OIDC provider initialized name=test2178--- PASS: TestScopes_ConfigValidation (0.00s)2179=== CONT TestValidateToken_NoMatchingProvider21802026/08/27 18:12:05 INFO OIDC provider initialized name=test21812026/08/27 18:12:05 INFO OIDC provider initialized name=test21822026/08/27 18:12:05 INFO OIDC provider initialized name=test21832026/08/27 18:12:05 INFO OIDC provider initialized name=provider121842026/08/27 18:12:05 INFO OIDC provider initialized name=test21852026/08/27 18:12:05 INFO OIDC provider initialized name=provider121862026/08/27 18:12:05 INFO OIDC provider initialized name=provider22187--- PASS: TestValidateToken_WrongAudience (0.01s)2188=== CONT TestValidateToken_ValidToken21892026/08/27 18:12:05 INFO OIDC provider initialized name=kubernetes2190--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.01s)2191=== CONT TestGlobMatch/foo_foo2192=== CONT TestGlobMatch/*/*_foo/bar2193=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2194=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2195=== CONT TestGlobMatch/?oo_boo2196=== CONT TestGlobMatch/?oo_foo2197=== CONT TestGlobMatch/fo?_fooo2198=== CONT TestGlobMatch/fo?_fo2199=== CONT TestGlobMatch/fo?_foo2200=== CONT TestGlobMatch/refs/*/main_refs/heads/main2201=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02202=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2203=== CONT TestGlobMatch/*/*_foo2204=== CONT TestGlobMatch/*bar_bar2205=== CONT TestGlobMatch/foo*bar_foobarbaz2206=== CONT TestGlobMatch/foo*bar_foo123bar2207=== CONT TestGlobMatch/foo*bar_foobar2208=== CONT TestGlobMatch/*bar_foo2209=== CONT TestGlobMatch/*bar_foobar2210=== CONT TestGlobMatch/foo*_foo2211=== CONT TestGlobMatch/foo*_bar2212=== CONT TestGlobMatch/foo*_foobar2213=== CONT TestGlobMatch/*_2214=== CONT TestGlobMatch/*_anything2215=== CONT TestGlobMatch/foo_bar2216--- PASS: TestGlobMatch (0.00s)2217 --- PASS: TestGlobMatch/foo_foo (0.00s)2218 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2219 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2220 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2221 --- PASS: TestGlobMatch/?oo_boo (0.00s)2222 --- PASS: TestGlobMatch/?oo_foo (0.00s)2223 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2224 --- PASS: TestGlobMatch/fo?_fo (0.00s)2225 --- PASS: TestGlobMatch/fo?_foo (0.00s)2226 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2227 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2228 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2229 --- PASS: TestGlobMatch/*/*_foo (0.00s)2230 --- PASS: TestGlobMatch/*bar_bar (0.00s)2231 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2232 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2233 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2234 --- PASS: TestGlobMatch/*bar_foo (0.00s)2235 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2236 --- PASS: TestGlobMatch/foo*_foo (0.00s)2237 --- PASS: TestGlobMatch/foo*_bar (0.00s)2238 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2239 --- PASS: TestGlobMatch/*_ (0.00s)2240 --- PASS: TestGlobMatch/*_anything (0.00s)2241 --- PASS: TestGlobMatch/foo_bar (0.00s)2242--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)22432026/08/27 18:12:05 INFO OIDC provider initialized name=test2244--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)2245--- PASS: TestValidateToken_Expired (0.01s)2246--- PASS: TestValidateToken_NoMatchingProvider (0.01s)2247--- PASS: TestValidateToken_MultipleProviders (0.01s)2248--- PASS: TestValidateToken_ValidToken (0.00s)22492026/08/27 18:12:05 http: TLS handshake error from 127.0.0.1:57328: remote error: tls: bad certificate2250--- PASS: TestNewValidator_KubernetesRequiresCA (0.01s)2251--- PASS: TestValidateToken_KubernetesServiceAccount (0.01s)2252--- PASS: TestScopes_Rules (0.01s)2253PASS2254Running hook tests...2255=== RUN TestSendPathsEmpty2256=== PAUSE TestSendPathsEmpty2257=== RUN TestQueueEnqueueAndFetch2258=== PAUSE TestQueueEnqueueAndFetch2259=== RUN TestQueueDeduplication2260=== PAUSE TestQueueDeduplication2261=== RUN TestQueueRemove2262=== PAUSE TestQueueRemove2263=== RUN TestQueueFetchBatchLimit2264=== PAUSE TestQueueFetchBatchLimit2265=== RUN TestQueueRetryMovesToBack2266=== PAUSE TestQueueRetryMovesToBack2267=== RUN TestQueueFetchRemoveLifecycle2268=== PAUSE TestQueueFetchRemoveLifecycle2269=== RUN TestQueueConcurrentWriters2270=== PAUSE TestQueueConcurrentWriters2271=== RUN TestQueueRemoveLargeClosure2272=== PAUSE TestQueueRemoveLargeClosure2273=== RUN TestServerClientIntegration2274=== PAUSE TestServerClientIntegration2275=== RUN TestServerQueueError2276=== PAUSE TestServerQueueError2277=== RUN TestGetListenerSocketActivation2278 server_test.go:210: === RUN TestGetListenerSocketActivation2279 --- PASS: TestGetListenerSocketActivation (0.00s)2280 PASS2281 2282--- PASS: TestGetListenerSocketActivation (0.01s)2283=== RUN TestDrainIsolatesPoisonPath2284=== PAUSE TestDrainIsolatesPoisonPath2285=== RUN TestRunNotBlockedByPoisonHead2286=== PAUSE TestRunNotBlockedByPoisonHead2287=== RUN TestDrainGivesUpWhenServerDown2288=== PAUSE TestDrainGivesUpWhenServerDown2289=== RUN TestFailedPathPrunedByLaterClosure2290=== PAUSE TestFailedPathPrunedByLaterClosure2291=== RUN TestWorkerUploadsAndRemoves2292=== PAUSE TestWorkerUploadsAndRemoves2293=== RUN TestWorkerSkipsGCdPaths2294=== PAUSE TestWorkerSkipsGCdPaths2295=== RUN TestWorkerPrunesClosureDeps2296=== PAUSE TestWorkerPrunesClosureDeps2297=== RUN TestDrainTimeout2298=== PAUSE TestDrainTimeout2299=== CONT TestSendPathsEmpty2300--- PASS: TestSendPathsEmpty (0.00s)2301=== CONT TestServerQueueError2302=== CONT TestServerClientIntegration2303=== CONT TestQueueRemoveLargeClosure2304=== CONT TestQueueConcurrentWriters2305=== CONT TestQueueRemove2306=== CONT TestQueueDeduplication2307=== CONT TestQueueEnqueueAndFetch2308=== CONT TestWorkerUploadsAndRemoves2309=== CONT TestDrainTimeout2310=== CONT TestWorkerPrunesClosureDeps23112026/08/27 18:12:05 ERROR Failed to queue paths error="permission denied" count=12312--- PASS: TestServerQueueError (0.00s)2313=== CONT TestWorkerSkipsGCdPaths2314--- PASS: TestServerClientIntegration (0.00s)2315=== CONT TestDrainGivesUpWhenServerDown23162026/08/27 18:12:05 INFO Upload queue status pending=223172026/08/27 18:12:05 INFO Uploading batch count=223182026/08/27 18:12:05 INFO Upload queue status pending=223192026/08/27 18:12:05 INFO Uploading batch count=123202026/08/27 18:12:05 INFO Uploading batch count=223212026/08/27 18:12:05 INFO Upload queue status pending=223222026/08/27 18:12:05 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-4772-2940262897/TestWorkerSkipsGCdPaths161167092/002/nonexistent23232026/08/27 18:12:05 INFO Uploading batch count=223242026/08/27 18:12:05 ERROR Upload failed error="upload failed" count=223252026/08/27 18:12:05 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-4772-2940262897/TestDrainGivesUpWhenServerDown4023364369/002/a23262026/08/27 18:12:05 INFO Uploading batch count=12327--- PASS: TestQueueDeduplication (0.01s)2328=== CONT TestFailedPathPrunedByLaterClosure23292026/08/27 18:12:05 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-4772-2940262897/TestDrainGivesUpWhenServerDown4023364369/002/b2330--- PASS: TestQueueEnqueueAndFetch (0.01s)2331=== CONT TestQueueFetchRemoveLifecycle23322026/08/27 18:12:05 INFO Uploading batch count=223332026/08/27 18:12:05 ERROR Upload failed error="upload failed" count=223342026/08/27 18:12:05 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-4772-2940262897/TestDrainGivesUpWhenServerDown4023364369/002/c23352026/08/27 18:12:05 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-4772-2940262897/TestDrainGivesUpWhenServerDown4023364369/002/d2336--- PASS: TestQueueRemove (0.01s)2337=== CONT TestQueueRetryMovesToBack23382026/08/27 18:12:05 INFO Uploading batch count=223392026/08/27 18:12:05 ERROR Upload failed error="upload failed" count=223402026/08/27 18:12:05 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-4772-2940262897/TestDrainGivesUpWhenServerDown4023364369/002/e23412026/08/27 18:12:05 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-4772-2940262897/TestDrainGivesUpWhenServerDown4023364369/002/f23422026/08/27 18:12:05 ERROR Drain finished with paths left in queue remaining=1023432026/08/27 18:12:05 INFO Uploading batch count=123442026/08/27 18:12:05 ERROR Upload failed error="upload failed" count=123452026/08/27 18:12:05 INFO Uploading batch count=123462026/08/27 18:12:05 INFO Uploading batch count=12347--- PASS: TestQueueFetchRemoveLifecycle (0.00s)2348=== CONT TestRunNotBlockedByPoisonHead2349--- PASS: TestDrainGivesUpWhenServerDown (0.01s)2350=== CONT TestDrainIsolatesPoisonPath2351--- PASS: TestQueueRetryMovesToBack (0.00s)2352=== CONT TestQueueFetchBatchLimit2353--- PASS: TestFailedPathPrunedByLaterClosure (0.00s)23542026/08/27 18:12:05 INFO Uploading batch count=423552026/08/27 18:12:05 ERROR Upload failed error="upload failed" count=423562026/08/27 18:12:05 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-4772-2940262897/TestDrainIsolatesPoisonPath871564497/002/bbb2357--- PASS: TestQueueFetchBatchLimit (0.00s)23582026/08/27 18:12:05 INFO Upload queue status pending=323592026/08/27 18:12:05 INFO Uploading batch count=123602026/08/27 18:12:05 ERROR Upload failed error="upload failed" count=123612026/08/27 18:12:05 INFO Uploading batch count=123622026/08/27 18:12:05 ERROR Upload failed error="upload failed" count=123632026/08/27 18:12:05 INFO Uploading batch count=123642026/08/27 18:12:05 ERROR Upload failed error="upload failed" count=123652026/08/27 18:12:05 INFO Uploading batch count=123662026/08/27 18:12:05 ERROR Upload failed error="upload failed" count=123672026/08/27 18:12:05 ERROR Drain finished with paths left in queue remaining=12368--- PASS: TestDrainIsolatesPoisonPath (0.00s)2369--- PASS: TestWorkerPrunesClosureDeps (0.03s)2370--- PASS: TestWorkerUploadsAndRemoves (0.03s)2371--- PASS: TestWorkerSkipsGCdPaths (0.03s)2372--- PASS: TestQueueRemoveLargeClosure (0.06s)2373--- PASS: TestQueueConcurrentWriters (0.12s)23742026/08/27 18:12:05 ERROR Upload failed error="context deadline exceeded" count=223752026/08/27 18:12:05 ERROR Drain finished with paths left in queue remaining=42376--- PASS: TestDrainTimeout (0.21s)23772026/08/27 18:12:06 INFO Uploading batch count=123782026/08/27 18:12:06 INFO Uploading batch count=123792026/08/27 18:12:06 INFO Uploading batch count=123802026/08/27 18:12:06 ERROR Upload failed error="upload failed" count=123812026/08/27 18:12:06 INFO Uploading batch count=123822026/08/27 18:12:06 ERROR Upload failed error="upload failed" count=123832026/08/27 18:12:06 INFO Uploading batch count=123842026/08/27 18:12:06 ERROR Upload failed error="upload failed" count=123852026/08/27 18:12:06 INFO Uploading batch count=123862026/08/27 18:12:06 ERROR Upload failed error="upload failed" count=123872026/08/27 18:12:06 ERROR Drain finished with paths left in queue remaining=12388--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2389PASS