niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #163
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestCaseHackSuffix6=== PAUSE TestCaseHackSuffix7=== RUN TestFilterOversizedClosures8=== PAUSE TestFilterOversizedClosures9=== RUN TestPartSizeForNAR10=== PAUSE TestPartSizeForNAR11=== RUN TestUploadMultipart_SupersededByPeer12=== PAUSE TestUploadMultipart_SupersededByPeer13=== RUN TestDumpPathMatchesNix14=== PAUSE TestDumpPathMatchesNix15=== RUN TestDumpPathSingleFile16=== PAUSE TestDumpPathSingleFile17=== RUN TestDumpPathWriterError18=== PAUSE TestDumpPathWriterError19=== RUN TestEncodeNixBase3220=== PAUSE TestEncodeNixBase3221=== RUN TestEncodeNixBase32WithRealHash22=== PAUSE TestEncodeNixBase32WithRealHash23=== RUN TestConvertHashToNix3224=== PAUSE TestConvertHashToNix3225=== RUN TestGetStorePathHash26=== PAUSE TestGetStorePathHash27=== RUN TestPathInfoHashCompatibility28=== PAUSE TestPathInfoHashCompatibility29=== RUN TestParsePathInfoJSON30=== PAUSE TestParsePathInfoJSON31=== RUN TestParsePathInfoJSONMultiplePaths32=== PAUSE TestParsePathInfoJSONMultiplePaths33=== RUN TestPathInfoCACompatibility34=== PAUSE TestPathInfoCACompatibility35=== RUN TestPrepareClosuresNoClosure36=== PAUSE TestPrepareClosuresNoClosure37=== RUN TestChunkStorePaths38=== PAUSE TestChunkStorePaths39=== RUN TestRateLimiterFeedback40=== PAUSE TestRateLimiterFeedback41=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess42=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess43=== RUN TestResolveStorePath44=== PAUSE TestResolveStorePath45=== RUN TestDoWithRetry_BodyReplayedViaGetBody46=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody47=== RUN TestShellSplit48=== PAUSE TestShellSplit49=== RUN TestShellSplitErrors50=== PAUSE TestShellSplitErrors51=== RUN TestSetClientTLS52=== PAUSE TestSetClientTLS53=== RUN TestSetClientTLSDoesNotMutateDefaultTransport54=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport55=== RUN TestSetClientTLSErrors56=== PAUSE TestSetClientTLSErrors57=== RUN TestStaticToken58=== PAUSE TestStaticToken59=== RUN TestFileTokenReadsAndCaches60=== PAUSE TestFileTokenReadsAndCaches61=== RUN TestFileTokenMissing62=== PAUSE TestFileTokenMissing63=== RUN TestFileTokenEmpty64=== PAUSE TestFileTokenEmpty65=== RUN TestScriptTokenNoExpiryRerunsEveryCall66=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall67=== RUN TestScriptTokenCachesUntilRefresh68=== PAUSE TestScriptTokenCachesUntilRefresh69=== RUN TestScriptTokenEmptyToken70=== PAUSE TestScriptTokenEmptyToken71=== RUN TestScriptTokenBadJSON72=== PAUSE TestScriptTokenBadJSON73=== RUN TestScriptTokenScriptFails74=== PAUSE TestScriptTokenScriptFails75=== RUN TestScriptTokenEmptyCommand76=== PAUSE TestScriptTokenEmptyCommand77=== CONT TestDoServerRequestAttachesToken78=== CONT TestConvertHashToNix3279=== CONT TestResolveStorePath80=== CONT TestRateLimiterFeedback81=== RUN TestConvertHashToNix32/SRI_format_to_Nix3282=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix3283=== RUN TestConvertHashToNix32/already_Nix32_format84=== PAUSE TestConvertHashToNix32/already_Nix32_format85=== RUN TestConvertHashToNix32/invalid_format86=== CONT TestFileTokenReadsAndCaches87=== RUN TestRateLimiterFeedback/429_enables_limiter88=== PAUSE TestRateLimiterFeedback/429_enables_limiter89=== RUN TestRateLimiterFeedback/503_enables_limiter90=== PAUSE TestRateLimiterFeedback/503_enables_limiter91=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter92=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter93=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter94=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter95=== CONT TestStaticToken96=== CONT TestPathInfoCACompatibility97=== RUN TestPathInfoCACompatibility/null_ca_field98=== PAUSE TestPathInfoCACompatibility/null_ca_field99--- PASS: TestStaticToken (0.00s)100=== RUN TestPathInfoCACompatibility/old_string_format_-_text101=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text102=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive103=== CONT TestSetClientTLSDoesNotMutateDefaultTransport104=== CONT TestSetClientTLS105--- PASS: TestResolveStorePath (0.00s)106=== CONT TestShellSplitErrors107=== CONT TestShellSplit108=== CONT TestDoWithRetry_BodyReplayedViaGetBody109=== CONT TestScriptTokenEmptyCommand110=== CONT TestScriptTokenScriptFails111=== CONT TestScriptTokenBadJSON112=== CONT TestScriptTokenEmptyToken113=== CONT TestScriptTokenCachesUntilRefresh114=== CONT TestScriptTokenNoExpiryRerunsEveryCall115=== CONT TestFileTokenEmpty116=== CONT TestFileTokenMissing117=== CONT TestParsePathInfoJSONMultiplePaths118=== CONT TestChunkStorePaths119=== CONT TestPrepareClosuresNoClosure120=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess121=== PAUSE TestConvertHashToNix32/invalid_format122=== CONT TestSetClientTLSErrors123=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive124=== RUN TestPathInfoCACompatibility/new_structured_format_-_text125=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text126=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method127=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method128--- PASS: TestShellSplitErrors (0.00s)129=== CONT TestDumpPathWriterError130--- PASS: TestFileTokenReadsAndCaches (0.00s)131=== CONT TestDumpPathSingleFile132--- PASS: TestScriptTokenEmptyCommand (0.00s)133=== CONT TestPartSizeForNAR134=== RUN TestPartSizeForNAR/zero_stays_at_minimum135=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum136=== RUN TestPartSizeForNAR/small_stays_at_minimum137=== PAUSE TestPartSizeForNAR/small_stays_at_minimum138=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum139=== CONT TestDumpPathMatchesNix140=== CONT TestEncodeNixBase32141=== RUN TestEncodeNixBase32/test_string_hash142=== PAUSE TestEncodeNixBase32/test_string_hash143=== RUN TestEncodeNixBase32/empty_input144=== PAUSE TestEncodeNixBase32/empty_input145=== CONT TestUploadMultipart_SupersededByPeer146=== CONT TestFilterOversizedClosures147=== CONT TestEncodeNixBase32WithRealHash148=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum149=== CONT TestPathInfoHashCompatibility150--- PASS: TestDoServerRequestAttachesToken (0.00s)151=== CONT TestParsePathInfoJSON152=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)153=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)154--- PASS: TestShellSplit (0.00s)155=== CONT TestCaseHackSuffix1562026/08/27 18:11:42 WARN Rate limiter enabled after throttle name=server-test rate=5157--- PASS: TestFileTokenMissing (0.00s)158=== RUN TestUploadMultipart_SupersededByPeer/exists159=== CONT TestGetStorePathHash160=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts161=== RUN TestParsePathInfoJSON/Nix_format162=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths163=== RUN TestFilterOversizedClosures/no_limit_keeps_everything164=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything165=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon166=== PAUSE TestParsePathInfoJSON/Nix_format167=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon1682026/08/27 18:11:42 WARN Rate limiter enabled after throttle name=server-test rate=5169=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter1702026/08/27 18:11:42 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:39261171=== CONT TestRateLimiterFeedback/429_enables_limiter172--- PASS: TestEncodeNixBase32WithRealHash (0.00s)173--- PASS: TestScriptTokenEmptyToken (0.00s)174=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths175=== RUN TestPrepareClosuresNoClosure/closure_mode_pulls_in_transitive_references176=== PAUSE TestUploadMultipart_SupersededByPeer/exists177=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter178=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped179=== RUN TestGetStorePathHash/valid_store_path180=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts181=== RUN TestChunkStorePaths/keeps_a_small_set_in_one_chunk182=== RUN TestParsePathInfoJSON/Lix_format183=== CONT TestRateLimiterFeedback/503_enables_limiter184=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI185=== CONT TestPathInfoCACompatibility/null_ca_field186=== RUN TestSetClientTLSErrors/missing_cert_file187--- PASS: TestScriptTokenScriptFails (0.00s)188--- PASS: TestFileTokenEmpty (0.01s)189--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)190--- PASS: TestScriptTokenBadJSON (0.01s)191=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths192=== PAUSE TestGetStorePathHash/valid_store_path193=== PAUSE TestPrepareClosuresNoClosure/closure_mode_pulls_in_transitive_references194=== RUN TestUploadMultipart_SupersededByPeer/missing195=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped196=== RUN TestGetStorePathHash/basename_without_hyphen_should_error197=== PAUSE TestSetClientTLSErrors/missing_cert_file198=== CONT TestPathInfoCACompatibility/new_structured_format_-_text199--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.01s)200=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI201=== PAUSE TestChunkStorePaths/keeps_a_small_set_in_one_chunk202=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512203=== PAUSE TestParsePathInfoJSON/Lix_format204=== RUN TestPartSizeForNAR/1_TiB205=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive206=== PAUSE TestPartSizeForNAR/1_TiB207=== RUN TestPrepareClosuresNoClosure/no-closure_keeps_each_path_self-contained2082026/08/27 18:11:42 WARN Rate limiter backed off name=server-test rate=5209=== PAUSE TestPrepareClosuresNoClosure/no-closure_keeps_each_path_self-contained2102026/08/27 18:11:42 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:39261211=== RUN TestSetClientTLSErrors/missing_key_file212=== PAUSE TestSetClientTLSErrors/missing_key_file213=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths214=== CONT TestEncodeNixBase32/test_string_hash215=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error216=== PAUSE TestUploadMultipart_SupersededByPeer/missing217=== CONT TestEncodeNixBase32/empty_input218--- PASS: TestEncodeNixBase32 (0.00s)219 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)220 --- PASS: TestEncodeNixBase32/empty_input (0.00s)221=== CONT TestConvertHashToNix32/invalid_format222=== CONT TestConvertHashToNix32/SRI_format_to_Nix32223=== CONT TestPathInfoCACompatibility/old_string_format_-_text224=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths225=== CONT TestUploadMultipart_SupersededByPeer/exists226=== RUN TestPrepareClosuresNoClosure/no-closure_narinfos_still_record_their_references227=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths228=== PAUSE TestPrepareClosuresNoClosure/no-closure_narinfos_still_record_their_references229=== CONT TestPrepareClosuresNoClosure/closure_mode_pulls_in_transitive_references230=== CONT TestPrepareClosuresNoClosure/no-closure_narinfos_still_record_their_references231=== CONT TestConvertHashToNix32/already_Nix32_format232=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method233--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)234=== CONT TestUploadMultipart_SupersededByPeer/missing235--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)236 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)237 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)2382026/08/27 18:11:42 WARN Rate limiter enabled after throttle name=server-test rate=5239=== RUN TestChunkStorePaths/splits_on_the_byte_budget_and_preserves_every_path2402026/08/27 18:11:42 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:33139241=== RUN TestParsePathInfoJSON/empty_input242--- PASS: TestPathInfoCACompatibility (0.00s)243 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)244 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)245 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)246 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)247 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)248=== RUN TestPartSizeForNAR/5_TiB_S3_max_object249=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512250=== CONT TestPrepareClosuresNoClosure/no-closure_keeps_each_path_self-contained251=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)252=== PAUSE TestChunkStorePaths/splits_on_the_byte_budget_and_preserves_every_path2532026/08/27 18:11:42 WARN Rate limiter backed off name=server-test rate=5254=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object255=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512256=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon257--- PASS: TestScriptTokenCachesUntilRefresh (0.01s)258=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI2592026/08/27 18:11:42 WARN Rate limiter enabled after throttle name=server-test rate=5260=== PAUSE TestParsePathInfoJSON/empty_input2612026/08/27 18:11:42 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:39913262--- PASS: TestConvertHashToNix32 (0.00s)263 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)264 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)265 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)266=== RUN TestSetClientTLSErrors/missing_ca_file267--- PASS: TestPathInfoHashCompatibility (0.01s)268 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)269 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)270 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)271 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)272--- PASS: TestPrepareClosuresNoClosure (0.01s)273 --- PASS: TestPrepareClosuresNoClosure/no-closure_narinfos_still_record_their_references (0.00s)274 --- PASS: TestPrepareClosuresNoClosure/closure_mode_pulls_in_transitive_references (0.00s)275 --- PASS: TestPrepareClosuresNoClosure/no-closure_keeps_each_path_self-contained (0.00s)276=== PAUSE TestSetClientTLSErrors/missing_ca_file277=== RUN TestFilterOversizedClosures/all_closures_skipped278=== PAUSE TestFilterOversizedClosures/all_closures_skipped279=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error280=== RUN TestChunkStorePaths/emits_an_oversized_path_rather_than_dropping_it281=== PAUSE TestChunkStorePaths/emits_an_oversized_path_rather_than_dropping_it2822026/08/27 18:11:42 WARN Rate limiter backed off name=server-test rate=5283=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error284=== RUN TestFilterOversizedClosures/no-closure_judges_each_path_on_its_own_size285=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error286=== PAUSE TestFilterOversizedClosures/no-closure_judges_each_path_on_its_own_size287=== CONT TestFilterOversizedClosures/no_limit_keeps_everything288=== CONT TestFilterOversizedClosures/all_closures_skipped2892026/08/27 18:11:42 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50290=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error291=== CONT TestGetStorePathHash/valid_store_path292=== CONT TestGetStorePathHash/basename_without_hyphen_should_error293=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2942026/08/27 18:11:42 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=2000295=== RUN TestParsePathInfoJSON/whitespace_only296=== PAUSE TestParsePathInfoJSON/whitespace_only297=== RUN TestSetClientTLSErrors/invalid_ca_file298=== PAUSE TestSetClientTLSErrors/invalid_ca_file299=== RUN TestChunkStorePaths/handles_an_empty_input300=== PAUSE TestChunkStorePaths/handles_an_empty_input301=== CONT TestChunkStorePaths/keeps_a_small_set_in_one_chunk302=== CONT TestChunkStorePaths/emits_an_oversized_path_rather_than_dropping_it303=== RUN TestPartSizeForNAR/capped_at_5_GiB304=== CONT TestChunkStorePaths/handles_an_empty_input305=== CONT TestFilterOversizedClosures/no-closure_judges_each_path_on_its_own_size3062026/08/27 18:11:42 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=2000307=== RUN TestSetClientTLS/rejects_connection_without_client_cert308=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert309=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error310=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error311=== RUN TestParsePathInfoJSON/invalid_JSON312=== CONT TestSetClientTLSErrors/missing_cert_file313=== CONT TestSetClientTLSErrors/invalid_ca_file314=== CONT TestSetClientTLSErrors/missing_ca_file315=== PAUSE TestParsePathInfoJSON/invalid_JSON316=== CONT TestParsePathInfoJSON/Nix_format317=== CONT TestParsePathInfoJSON/whitespace_only318--- PASS: TestRateLimiterFeedback (0.00s)319 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)320 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)321 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)322 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)323--- PASS: TestFilterOversizedClosures (0.01s)324 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)325 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)326 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)327 --- PASS: TestFilterOversizedClosures/no-closure_judges_each_path_on_its_own_size (0.00s)328=== PAUSE TestPartSizeForNAR/capped_at_5_GiB329=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA330=== CONT TestPartSizeForNAR/capped_at_5_GiB331=== CONT TestPartSizeForNAR/zero_stays_at_minimum332=== CONT TestChunkStorePaths/splits_on_the_byte_budget_and_preserves_every_path333=== CONT TestParsePathInfoJSON/invalid_JSON334=== CONT TestParsePathInfoJSON/Lix_format335=== CONT TestParsePathInfoJSON/empty_input336--- PASS: TestGetStorePathHash (0.01s)337 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)338 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)339 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)340 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)341=== CONT TestPartSizeForNAR/5_TiB_S3_max_object342=== CONT TestPartSizeForNAR/1_TiB343=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA344=== RUN TestSetClientTLS/preserves_debug_logging_transport345=== CONT TestSetClientTLSErrors/missing_key_file346=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts347=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum348=== CONT TestPartSizeForNAR/small_stays_at_minimum349--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)350 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)351 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)352=== PAUSE TestSetClientTLS/preserves_debug_logging_transport353=== CONT TestSetClientTLS/rejects_connection_without_client_cert354--- PASS: TestChunkStorePaths (0.02s)355 --- PASS: TestChunkStorePaths/keeps_a_small_set_in_one_chunk (0.00s)356 --- PASS: TestChunkStorePaths/emits_an_oversized_path_rather_than_dropping_it (0.00s)357 --- PASS: TestChunkStorePaths/handles_an_empty_input (0.00s)358 --- PASS: TestChunkStorePaths/splits_on_the_byte_budget_and_preserves_every_path (0.00s)359=== CONT TestSetClientTLS/preserves_debug_logging_transport360=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA361--- PASS: TestParsePathInfoJSON (0.02s)362 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)363 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)364 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)365 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)366 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)367--- PASS: TestPartSizeForNAR (0.02s)368 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)369 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)370 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)371 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)372 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)373 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)374 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)375--- PASS: TestSetClientTLSErrors (0.01s)376 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)377 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)378 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)379 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)3802026/08/27 18:11:42 http: TLS handshake error from 127.0.0.1:44152: remote error: tls: bad certificate381--- PASS: TestSetClientTLS (0.02s)382 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)383 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)384 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)385--- PASS: TestDumpPathSingleFile (0.03s)386--- PASS: TestDumpPathWriterError (0.04s)387--- PASS: TestCaseHackSuffix (0.04s)388--- PASS: TestDumpPathMatchesNix (0.08s)389--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)390PASS391Running server tests...392The files belonging to this database system will be owned by user "nixbld".393This user must also own the server process.394395The database cluster will be initialized with locale "C".396The default database encoding has accordingly been set to "SQL_ASCII".397The default text search configuration will be set to "english".398399Data page checksums are enabled.400401creating directory /build/postgres1132992905/data ... ok402creating subdirectories ... ok403selecting dynamic shared memory implementation ... posix404selecting default "max_connections" ... 100405selecting default "shared_buffers" ... 128MB406selecting default time zone ... UTC407creating configuration files ... ok408running bootstrap script ... ok409performing post-bootstrap initialization ... ok410syncing data to disk ... ok411412initdb: warning: enabling "trust" authentication for local connections413initdb: 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.414415Success. You can now start the database server using:416417 pg_ctl -D /build/postgres1132992905/data -l logfile start418419/build/postgres1132992905:5432 - no response4202026-08-27 18:11:44.550 UTC [112] LOG: starting PostgreSQL 18.4 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit4212026-08-27 18:11:44.551 UTC [112] LOG: listening on Unix socket "/build/postgres1132992905/.s.PGSQL.5432"4222026-08-27 18:11:44.556 UTC [119] LOG: database system was shut down at 2026-08-27 18:11:44 UTC4232026-08-27 18:11:44.560 UTC [112] LOG: database system is ready to accept connections424/build/postgres1132992905: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:45.547 UTC [908] ERROR: relation "goose_db_version" does not exist at character 364592026-08-27 18:11:45.547 UTC [908] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4602026/08/27 18:11:45 OK 20241026095416_initial_model.sql (9.05ms)4612026/08/27 18:11:45 OK 20251210153512_drop_unused_gin_index.sql (1.23ms)4622026/08/27 18:11:45 OK 20251218171726_add_pins.sql (2.12ms)4632026/08/27 18:11:45 OK 20260628120000_add_object_size_and_stats.sql (1.96ms)4642026/08/27 18:11:45 goose: successfully migrated database to version: 202606281200004652026/08/27 18:11:45 OK 1_commit_pending_closure.sql (1.55ms)4662026/08/27 18:11:45 OK 2_object_stats_trigger.sql (750.28µs)4672026/08/27 18:11:45 goose: up to current file version: 2468--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.18s)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.02s)569=== RUN TestWatchdogSkipsWhenUnhealthy5702026/08/27 18:11:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5712026/08/27 18:11:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5722026/08/27 18:11:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5732026/08/27 18:11:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5742026/08/27 18:11:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5752026/08/27 18:11:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5762026/08/27 18:11:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5772026/08/27 18:11:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5782026/08/27 18:11:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5792026/08/27 18:11:45 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"580--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)581=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle582=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle583=== RUN TestProxyWriteTimeout584=== PAUSE TestProxyWriteTimeout585=== RUN TestIsValidUploadKey586=== PAUSE TestIsValidUploadKey587=== RUN TestUploadHandlersRejectInvalidKeys588=== PAUSE TestUploadHandlersRejectInvalidKeys589=== RUN TestUploadHandlersRejectOversizedBody590=== PAUSE TestUploadHandlersRejectOversizedBody591=== RUN TestService_cleanupPendingClosuresHandler592=== PAUSE TestService_cleanupPendingClosuresHandler593=== RUN TestService_createPendingClosureHandler594=== PAUSE TestService_createPendingClosureHandler595=== RUN TestService_verifyS3Integrity596=== PAUSE TestService_verifyS3Integrity597=== RUN TestCompleteMultipartUnregistered598=== PAUSE TestCompleteMultipartUnregistered599=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT600=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT601=== CONT TestService_AuthMiddleware602=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT603=== CONT TestGCTaskStore_GetEmpty604--- PASS: TestGCTaskStore_GetEmpty (0.00s)605=== CONT TestCompleteMultipartUpload_ErrorButObjectExists606=== CONT TestCompleteMultipartUnregistered607=== CONT TestService_verifyS3Integrity608=== CONT TestService_createPendingClosureHandler609=== CONT TestService_cleanupPendingClosuresHandler610=== CONT TestUploadHandlersRejectOversizedBody611=== CONT TestUploadHandlersRejectInvalidKeys612=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info613=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info614=== CONT TestIsValidUploadKey615=== CONT TestProxyWriteTimeout616=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle617=== CONT TestSkippedUploadsHandler618=== CONT TestParseSize619=== CONT TestService_Rustfstest620=== CONT TestPresignedUploadRegisteredBeforeCommit621=== CONT TestCompletedNarNotReofferedAcrossClosures622=== CONT TestClientIntegration623=== CONT TestGCTaskStore_ConflictDifferentParams624=== CONT TestGCTaskStore_DeduplicateSameParams625=== CONT TestGCTaskStore_StartNew626=== CONT TestGCMetrics627=== CONT TestResurrectedObjectNotDeleted628=== CONT TestGCBugBareHashReferences629=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal630=== RUN TestIsValidUploadKey/narinfo631=== RUN TestProxyWriteTimeout/narinfo632--- PASS: TestParseSize (0.00s)6332026/08/27 18:11:45 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000634--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)635=== CONT TestResolveDBConnectionString636=== CONT TestPinProtectsFromGC637--- PASS: TestSkippedUploadsHandler (0.01s)638=== CONT TestClientWithDependencies639--- PASS: TestGCTaskStore_StartNew (0.00s)640--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)641=== PAUSE TestIsValidUploadKey/narinfo642=== RUN TestResolveDBConnectionString/flag_wins643=== PAUSE TestResolveDBConnectionString/flag_wins644=== RUN TestResolveDBConnectionString/file_when_flag_empty645=== PAUSE TestResolveDBConnectionString/file_when_flag_empty646=== RUN TestResolveDBConnectionString/missing_file_is_an_error647=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error648=== RUN TestResolveDBConnectionString/PGHOST_allows_empty649=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty650=== RUN TestResolveDBConnectionString/nothing_configured651=== PAUSE TestResolveDBConnectionString/nothing_configured652=== CONT TestClientMultipleUploads653=== RUN TestIsValidUploadKey/nar_zst654=== PAUSE TestIsValidUploadKey/nar_zst655=== PAUSE TestProxyWriteTimeout/narinfo656=== CONT TestNARDeduplicationMetadataUploadBug657=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal658=== CONT TestOrphanedObjectsGCStressTest659=== RUN TestIsValidUploadKey/nar_xz660=== PAUSE TestIsValidUploadKey/nar_xz661=== RUN TestIsValidUploadKey/nar_plain662=== RUN TestProxyWriteTimeout/1_GiB_nar663=== PAUSE TestProxyWriteTimeout/1_GiB_nar664=== RUN TestProxyWriteTimeout/10_GiB_nar665=== PAUSE TestProxyWriteTimeout/10_GiB_nar666=== RUN TestProxyWriteTimeout/unknown_size667=== PAUSE TestProxyWriteTimeout/unknown_size668=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key669=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key670=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key671=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key672=== PAUSE TestIsValidUploadKey/nar_plain673=== RUN TestIsValidUploadKey/listing674=== PAUSE TestIsValidUploadKey/listing675=== CONT TestObjectStatsTrigger676=== CONT TestOrphanedObjectsGC677=== RUN TestIsValidUploadKey/build_log678=== PAUSE TestIsValidUploadKey/build_log679=== RUN TestIsValidUploadKey/build_log_home-manager_file680=== PAUSE TestIsValidUploadKey/build_log_home-manager_file681=== RUN TestIsValidUploadKey/build_log_plus_in_name682=== PAUSE TestIsValidUploadKey/build_log_plus_in_name683=== RUN TestIsValidUploadKey/build_log_question_mark684=== PAUSE TestIsValidUploadKey/build_log_question_mark685=== RUN TestIsValidUploadKey/build_log_equals686=== PAUSE TestIsValidUploadKey/build_log_equals687=== RUN TestIsValidUploadKey/realisation688=== PAUSE TestIsValidUploadKey/realisation689=== RUN TestIsValidUploadKey/realisation_plus_in_output690=== PAUSE TestIsValidUploadKey/realisation_plus_in_output691=== RUN TestIsValidUploadKey/nix-cache-info692=== PAUSE TestIsValidUploadKey/nix-cache-info693=== RUN TestIsValidUploadKey/index.html694=== PAUSE TestIsValidUploadKey/index.html695=== RUN TestIsValidUploadKey/narinfo_key,_nar_type696=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type697=== RUN TestIsValidUploadKey/nar_key,_narinfo_type698=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type699=== RUN TestIsValidUploadKey/listing_key,_narinfo_type700=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type701=== RUN TestIsValidUploadKey/traversal702=== PAUSE TestIsValidUploadKey/traversal703=== RUN TestIsValidUploadKey/traversal_nar704=== PAUSE TestIsValidUploadKey/traversal_nar705=== RUN TestIsValidUploadKey/absolute706=== PAUSE TestIsValidUploadKey/absolute707=== RUN TestIsValidUploadKey/empty_key708=== PAUSE TestIsValidUploadKey/empty_key709=== RUN TestIsValidUploadKey/unknown_type710=== PAUSE TestIsValidUploadKey/unknown_type711=== CONT TestNoClosurePushKeepsReferencedObjectsReachable712=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts713=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts714=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure715=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure716=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart717=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart718=== CONT TestNoClosurePushCreatesIndependentGCRoots7192026-08-27 18:11:46.059 UTC [981] ERROR: relation "goose_db_version" does not exist at character 367202026-08-27 18:11:46.059 UTC [981] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7212026-08-27 18:11:46.059 UTC [979] ERROR: relation "goose_db_version" does not exist at character 367222026-08-27 18:11:46.059 UTC [979] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7232026-08-27 18:11:46.061 UTC [980] ERROR: relation "goose_db_version" does not exist at character 367242026-08-27 18:11:46.061 UTC [980] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7252026-08-27 18:11:46.068 UTC [984] ERROR: relation "goose_db_version" does not exist at character 367262026-08-27 18:11:46.068 UTC [984] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7272026-08-27 18:11:46.069 UTC [985] ERROR: relation "goose_db_version" does not exist at character 367282026-08-27 18:11:46.069 UTC [985] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7292026-08-27 18:11:46.069 UTC [986] ERROR: relation "goose_db_version" does not exist at character 367302026-08-27 18:11:46.069 UTC [986] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7312026/08/27 18:11:46 OK 20241026095416_initial_model.sql (99.7ms)7322026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (7.39ms)7332026/08/27 18:11:46 OK 20251218171726_add_pins.sql (19.29ms)7342026/08/27 18:11:46 OK 20241026095416_initial_model.sql (113.81ms)7352026/08/27 18:11:46 OK 20241026095416_initial_model.sql (110.68ms)7362026/08/27 18:11:46 OK 20241026095416_initial_model.sql (110.85ms)7372026/08/27 18:11:46 OK 20241026095416_initial_model.sql (109.36ms)7382026/08/27 18:11:46 OK 20241026095416_initial_model.sql (110.93ms)7392026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (2.19ms)7402026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (3.85ms)7412026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (3.84ms)7422026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (4.02ms)7432026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (4.24ms)7442026/08/27 18:11:46 OK 20251218171726_add_pins.sql (4.23ms)7452026-08-27 18:11:46.213 UTC [989] ERROR: relation "goose_db_version" does not exist at character 367462026-08-27 18:11:46.213 UTC [989] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7472026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (8.98ms)7482026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200007492026-08-27 18:11:46.216 UTC [990] ERROR: relation "goose_db_version" does not exist at character 367502026-08-27 18:11:46.216 UTC [990] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7512026/08/27 18:11:46 OK 20251218171726_add_pins.sql (6.48ms)7522026/08/27 18:11:46 OK 20251218171726_add_pins.sql (6.56ms)7532026/08/27 18:11:46 OK 20251218171726_add_pins.sql (6.68ms)7542026/08/27 18:11:46 OK 20251218171726_add_pins.sql (6.43ms)7552026/08/27 18:11:46 OK 1_commit_pending_closure.sql (4.46ms)7562026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (8.09ms)7572026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200007582026/08/27 18:11:46 OK 2_object_stats_trigger.sql (3.13ms)7592026/08/27 18:11:46 goose: up to current file version: 27602026/08/27 18:11:46 OK 1_commit_pending_closure.sql (4.87ms)7612026-08-27 18:11:46.227 UTC [991] ERROR: relation "goose_db_version" does not exist at character 367622026-08-27 18:11:46.227 UTC [991] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7632026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (10.21ms)7642026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200007652026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (10.44ms)7662026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200007672026/08/27 18:11:46 OK 2_object_stats_trigger.sql (3.89ms)7682026/08/27 18:11:46 goose: up to current file version: 27692026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (12.59ms)7702026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200007712026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (12.37ms)7722026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200007732026-08-27 18:11:46.231 UTC [992] ERROR: relation "goose_db_version" does not exist at character 367742026-08-27 18:11:46.231 UTC [992] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7752026-08-27 18:11:46.233 UTC [993] ERROR: relation "goose_db_version" does not exist at character 367762026-08-27 18:11:46.233 UTC [993] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7772026/08/27 18:11:46 OK 1_commit_pending_closure.sql (5.18ms)7782026/08/27 18:11:46 OK 1_commit_pending_closure.sql (5.66ms)7792026/08/27 18:11:46 OK 1_commit_pending_closure.sql (7.84ms)7802026/08/27 18:11:46 OK 1_commit_pending_closure.sql (5.55ms)7812026/08/27 18:11:46 OK 2_object_stats_trigger.sql (4.34ms)7822026/08/27 18:11:46 goose: up to current file version: 27832026/08/27 18:11:46 OK 2_object_stats_trigger.sql (3.75ms)7842026/08/27 18:11:46 goose: up to current file version: 27852026/08/27 18:11:46 OK 2_object_stats_trigger.sql (3.8ms)7862026/08/27 18:11:46 goose: up to current file version: 27872026/08/27 18:11:46 OK 2_object_stats_trigger.sql (5.67ms)7882026/08/27 18:11:46 goose: up to current file version: 27892026/08/27 18:11:46 OK 20241026095416_initial_model.sql (21.65ms)7902026/08/27 18:11:46 OK 20241026095416_initial_model.sql (21.14ms)7912026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (2.4ms)7922026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (12.47ms)7932026/08/27 18:11:46 OK 20251218171726_add_pins.sql (15.15ms)7942026/08/27 18:11:46 OK 20241026095416_initial_model.sql (20.4ms)7952026/08/27 18:11:46 OK 20241026095416_initial_model.sql (23.9ms)7962026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (2.08ms)7972026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (3.62ms)7982026/08/27 18:11:46 OK 20241026095416_initial_model.sql (23.87ms)7992026/08/27 18:11:46 OK 20251218171726_add_pins.sql (11.06ms)8002026/08/27 18:11:46 OK 20251218171726_add_pins.sql (6.52ms)8012026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (9ms)8022026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200008032026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (3.83ms)8042026/08/27 18:11:46 OK 20251218171726_add_pins.sql (6.91ms)8052026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (6.37ms)8062026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200008072026/08/27 18:11:46 OK 20251218171726_add_pins.sql (5.87ms)8082026/08/27 18:11:46 OK 1_commit_pending_closure.sql (5.99ms)8092026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (6.29ms)8102026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200008112026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (6.52ms)8122026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200008132026/08/27 18:11:46 OK 1_commit_pending_closure.sql (3.6ms)8142026/08/27 18:11:46 OK 2_object_stats_trigger.sql (3.42ms)8152026/08/27 18:11:46 goose: up to current file version: 28162026/08/27 18:11:46 OK 2_object_stats_trigger.sql (3.05ms)8172026/08/27 18:11:46 goose: up to current file version: 28182026/08/27 18:11:46 OK 1_commit_pending_closure.sql (5ms)8192026/08/27 18:11:46 OK 1_commit_pending_closure.sql (4.72ms)8202026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (6.68ms)8212026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200008222026/08/27 18:11:46 OK 2_object_stats_trigger.sql (2.79ms)8232026/08/27 18:11:46 goose: up to current file version: 28242026/08/27 18:11:46 OK 2_object_stats_trigger.sql (2.66ms)8252026/08/27 18:11:46 goose: up to current file version: 28262026/08/27 18:11:46 OK 1_commit_pending_closure.sql (3.54ms)8272026-08-27 18:11:46.290 UTC [995] ERROR: relation "goose_db_version" does not exist at character 368282026-08-27 18:11:46.290 UTC [995] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8292026-08-27 18:11:46.290 UTC [994] ERROR: relation "goose_db_version" does not exist at character 368302026-08-27 18:11:46.290 UTC [994] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8312026/08/27 18:11:46 OK 2_object_stats_trigger.sql (2.19ms)8322026/08/27 18:11:46 goose: up to current file version: 28332026-08-27 18:11:46.306 UTC [996] ERROR: relation "goose_db_version" does not exist at character 368342026-08-27 18:11:46.306 UTC [996] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8352026/08/27 18:11:46 OK 20241026095416_initial_model.sql (8.98ms)8362026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (1.8ms)8372026/08/27 18:11:46 OK 20241026095416_initial_model.sql (8.67ms)8382026-08-27 18:11:46.322 UTC [997] ERROR: relation "goose_db_version" does not exist at character 368392026-08-27 18:11:46.322 UTC [997] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8402026-08-27 18:11:46.323 UTC [998] ERROR: relation "goose_db_version" does not exist at character 368412026-08-27 18:11:46.323 UTC [998] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8422026-08-27 18:11:46.323 UTC [999] ERROR: relation "goose_db_version" does not exist at character 368432026-08-27 18:11:46.323 UTC [999] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8442026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (2.36ms)8452026-08-27 18:11:46.325 UTC [1000] ERROR: relation "goose_db_version" does not exist at character 368462026-08-27 18:11:46.325 UTC [1000] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8472026-08-27 18:11:46.326 UTC [1001] ERROR: relation "goose_db_version" does not exist at character 368482026-08-27 18:11:46.326 UTC [1001] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8492026/08/27 18:11:46 OK 20251218171726_add_pins.sql (4.58ms)8502026/08/27 18:11:46 OK 20241026095416_initial_model.sql (8.83ms)8512026-08-27 18:11:46.327 UTC [1002] ERROR: relation "goose_db_version" does not exist at character 368522026-08-27 18:11:46.327 UTC [1002] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8532026-08-27 18:11:46.327 UTC [1003] ERROR: relation "goose_db_version" does not exist at character 368542026-08-27 18:11:46.327 UTC [1003] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8552026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (1.63ms)8562026/08/27 18:11:46 OK 20251218171726_add_pins.sql (3.78ms)8572026-08-27 18:11:46.329 UTC [1004] ERROR: relation "goose_db_version" does not exist at character 368582026-08-27 18:11:46.329 UTC [1004] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8592026-08-27 18:11:46.330 UTC [1005] ERROR: relation "goose_db_version" does not exist at character 368602026-08-27 18:11:46.330 UTC [1005] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8612026-08-27 18:11:46.330 UTC [1006] ERROR: relation "goose_db_version" does not exist at character 368622026-08-27 18:11:46.330 UTC [1006] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8632026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (5.1ms)8642026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200008652026/08/27 18:11:46 OK 20251218171726_add_pins.sql (3.34ms)8662026/08/27 18:11:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8672026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (3.74ms)8682026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200008692026/08/27 18:11:46 OK 1_commit_pending_closure.sql (2.83ms)8702026/08/27 18:11:46 OK 1_commit_pending_closure.sql (2.47ms)8712026/08/27 18:11:46 OK 2_object_stats_trigger.sql (1.84ms)8722026/08/27 18:11:46 goose: up to current file version: 28732026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (4.75ms)8742026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200008752026/08/27 18:11:46 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst876--- PASS: TestCompleteMultipartUnregistered (0.46s)877=== CONT TestMultipartCleanup8782026/08/27 18:11:46 OK 2_object_stats_trigger.sql (1.66ms)8792026/08/27 18:11:46 goose: up to current file version: 28802026/08/27 18:11:46 OK 1_commit_pending_closure.sql (2.33ms)8812026/08/27 18:11:46 OK 20241026095416_initial_model.sql (11.43ms)8822026/08/27 18:11:46 OK 2_object_stats_trigger.sql (3.04ms)8832026/08/27 18:11:46 goose: up to current file version: 28842026/08/27 18:11:46 OK 20241026095416_initial_model.sql (13.02ms)8852026/08/27 18:11:46 OK 20241026095416_initial_model.sql (12.92ms)8862026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (2.64ms)8872026/08/27 18:11:46 OK 20241026095416_initial_model.sql (11.69ms)8882026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (1.87ms)8892026/08/27 18:11:46 OK 20241026095416_initial_model.sql (11.11ms)8902026/08/27 18:11:46 INFO Received cleanup request method=DELETE path=/api/pending_closures8912026/08/27 18:11:46 OK 20241026095416_initial_model.sql (12.96ms)8922026/08/27 18:11:46 OK 20241026095416_initial_model.sql (10.77ms)8932026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (2.25ms)8942026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (1.27ms)8952026/08/27 18:11:46 OK 20241026095416_initial_model.sql (11.46ms)8962026/08/27 18:11:46 OK 20251218171726_add_pins.sql (3.13ms)8972026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (1.87ms)8982026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (2.07ms)8992026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (3.46ms)9002026/08/27 18:11:46 OK 20241026095416_initial_model.sql (12.8ms)9012026/08/27 18:11:46 OK 20251218171726_add_pins.sql (4.66ms)9022026/08/27 18:11:46 OK 20241026095416_initial_model.sql (11.64ms)9032026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (1.79ms)9042026/08/27 18:11:46 OK 20251218171726_add_pins.sql (3.32ms)9052026/08/27 18:11:46 OK 20251218171726_add_pins.sql (3.34ms)9062026/08/27 18:11:46 INFO Aborted multipart uploads count=09072026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (1.93ms)9082026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (2.5ms)9092026/08/27 18:11:46 OK 20251218171726_add_pins.sql (3.53ms)9102026/08/27 18:11:46 OK 20251218171726_add_pins.sql (3.43ms)9112026/08/27 18:11:46 OK 20251218171726_add_pins.sql (2.73ms)9122026/08/27 18:11:46 OK 20251218171726_add_pins.sql (3.37ms)9132026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (3.63ms)9142026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200009152026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures9162026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (4.01ms)9172026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200009182026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (4.2ms)9192026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200009202026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (4.29ms)9212026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200009222026/08/27 18:11:46 OK 1_commit_pending_closure.sql (3ms)9232026/08/27 18:11:46 OK 20251218171726_add_pins.sql (4.31ms)9242026/08/27 18:11:46 OK 20251218171726_add_pins.sql (4.38ms)9252026/08/27 18:11:46 OK 1_commit_pending_closure.sql (2.85ms)9262026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (3.99ms)9272026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200009282026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (4.05ms)9292026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200009302026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (3.97ms)9312026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200009322026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (4.13ms)9332026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200009342026/08/27 18:11:46 OK 1_commit_pending_closure.sql (2.05ms)9352026/08/27 18:11:46 OK 1_commit_pending_closure.sql (2.15ms)9362026/08/27 18:11:46 OK 2_object_stats_trigger.sql (1.04ms)9372026/08/27 18:11:46 goose: up to current file version: 29382026/08/27 18:11:46 OK 2_object_stats_trigger.sql (909.8µs)9392026/08/27 18:11:46 goose: up to current file version: 29402026/08/27 18:11:46 OK 1_commit_pending_closure.sql (1.89ms)9412026/08/27 18:11:46 OK 1_commit_pending_closure.sql (1.58ms)9422026/08/27 18:11:46 OK 2_object_stats_trigger.sql (1.47ms)9432026/08/27 18:11:46 goose: up to current file version: 29442026/08/27 18:11:46 OK 1_commit_pending_closure.sql (2.15ms)9452026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (3.18ms)9462026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200009472026/08/27 18:11:46 OK 2_object_stats_trigger.sql (1.4ms)9482026/08/27 18:11:46 goose: up to current file version: 29492026/08/27 18:11:46 OK 1_commit_pending_closure.sql (1.74ms)9502026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (2.87ms)9512026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200009522026/08/27 18:11:46 OK 2_object_stats_trigger.sql (810.51µs)9532026/08/27 18:11:46 goose: up to current file version: 29542026/08/27 18:11:46 OK 2_object_stats_trigger.sql (1.12ms)9552026/08/27 18:11:46 goose: up to current file version: 29562026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures9572026/08/27 18:11:46 OK 2_object_stats_trigger.sql (1.19ms)9582026/08/27 18:11:46 goose: up to current file version: 29592026/08/27 18:11:46 OK 2_object_stats_trigger.sql (809.24µs)9602026/08/27 18:11:46 goose: up to current file version: 29612026/08/27 18:11:46 OK 1_commit_pending_closure.sql (1.52ms)9622026/08/27 18:11:46 OK 1_commit_pending_closure.sql (1.58ms)9632026/08/27 18:11:46 OK 2_object_stats_trigger.sql (779.45µs)9642026/08/27 18:11:46 goose: up to current file version: 29652026/08/27 18:11:46 OK 2_object_stats_trigger.sql (1.02ms)9662026/08/27 18:11:46 goose: up to current file version: 29672026/08/27 18:11:46 INFO Received cleanup request method=DELETE path=/api/pending_closures9682026/08/27 18:11:46 INFO Aborted multipart uploads count=19692026/08/27 18:11:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9702026-08-27 18:11:46.370 UTC [984] ERROR: Closure does not exist: id=19712026-08-27 18:11:46.370 UTC [984] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE9722026-08-27 18:11:46.370 UTC [984] STATEMENT: -- name: CommitPendingClosure :exec973 SELECT commit_pending_closure($1::bigint)974 975--- PASS: TestService_cleanupPendingClosuresHandler (0.49s)976=== CONT TestServerTLSConfig977=== RUN TestServerTLSConfig/no_client_CA978=== PAUSE TestServerTLSConfig/no_client_CA979=== RUN TestServerTLSConfig/missing_CA_file980=== PAUSE TestServerTLSConfig/missing_CA_file981=== RUN TestServerTLSConfig/not_a_PEM_file982=== PAUSE TestServerTLSConfig/not_a_PEM_file983=== CONT TestService_NativeMTLS9842026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures9852026/08/27 18:11:46 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"986--- PASS: TestService_AuthMiddleware (0.50s)987=== CONT TestMetricsInventory9882026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures9892026/08/27 18:11:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9902026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures9912026/08/27 18:11:46 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ODFlNzFjMDktMzZjMy00MjdiLWE0ZDQtNmVjYzhiMTNlODAxLmY0NjNkOTY5LTlhNTEtNGZiMi1hNTNlLWM1MzMwOGRhZTNkNHgxNzg3ODU0MzA2MzgyODU4NTUx992--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.53s)993=== CONT TestReadProxyHead9942026/08/27 18:11:46 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ODFlNzFjMDktMzZjMy00MjdiLWE0ZDQtNmVjYzhiMTNlODAxLmY0NjNkOTY5LTlhNTEtNGZiMi1hNTNlLWM1MzMwOGRhZTNkNHgxNzg3ODU0MzA2MzgyODU4NTUx parts=1995--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.54s)996=== CONT TestRedundantMultipartUpload9972026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures9982026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures9992026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures10002026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures10012026-08-27 18:11:46.437 UTC [1018] ERROR: relation "goose_db_version" does not exist at character 3610022026-08-27 18:11:46.437 UTC [1018] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10032026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures10042026/08/27 18:11:46 OK 20241026095416_initial_model.sql (9.97ms)10052026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (2.63ms)10062026/08/27 18:11:46 OK 20251218171726_add_pins.sql (3.06ms)10072026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (4.15ms)10082026/08/27 18:11:46 goose: successfully migrated database to version: 2026062812000010092026/08/27 18:11:46 OK 1_commit_pending_closure.sql (2.62ms)10102026/08/27 18:11:46 OK 2_object_stats_trigger.sql (1.4ms)10112026-08-27 18:11:46.479 UTC [1020] ERROR: relation "goose_db_version" does not exist at character 3610122026-08-27 18:11:46.479 UTC [1020] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10132026/08/27 18:11:46 goose: up to current file version: 210142026/08/27 18:11:46 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10152026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures1016--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.60s)1017=== CONT TestReadProxyRangeRequest10182026-08-27 18:11:46.492 UTC [1037] ERROR: relation "goose_db_version" does not exist at character 3610192026-08-27 18:11:46.492 UTC [1037] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10202026/08/27 18:11:46 OK 20241026095416_initial_model.sql (9.8ms)10212026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (2.11ms)10222026/08/27 18:11:46 OK 20251218171726_add_pins.sql (2.84ms)10232026/08/27 18:11:46 OK 20241026095416_initial_model.sql (8.74ms)10242026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (2.85ms)10252026/08/27 18:11:46 goose: successfully migrated database to version: 2026062812000010262026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (1.05ms)10272026/08/27 18:11:46 OK 20251218171726_add_pins.sql (3.19ms)10282026/08/27 18:11:46 OK 1_commit_pending_closure.sql (3.55ms)10292026/08/27 18:11:46 OK 2_object_stats_trigger.sql (1.28ms)10302026/08/27 18:11:46 goose: up to current file version: 210312026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (4.62ms)10322026/08/27 18:11:46 goose: successfully migrated database to version: 2026062812000010332026-08-27 18:11:46.521 UTC [1043] ERROR: relation "goose_db_version" does not exist at character 3610342026-08-27 18:11:46.521 UTC [1043] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10352026/08/27 18:11:46 OK 1_commit_pending_closure.sql (5.36ms)10362026/08/27 18:11:46 OK 2_object_stats_trigger.sql (8.6ms)10372026/08/27 18:11:46 goose: up to current file version: 210382026-08-27 18:11:46.539 UTC [1060] ERROR: relation "goose_db_version" does not exist at character 3610392026-08-27 18:11:46.539 UTC [1060] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10402026/08/27 18:11:46 OK 20241026095416_initial_model.sql (9.86ms)1041=== NAME TestClientWithDependencies1042 client_integration_test.go:594: Built derivation: /build/TestClientWithDependencies1827114819/001/store/6sqqdgzrvnazy7ik2hpm5qwlz66ifyab-test-script10432026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (3.73ms)1044=== NAME TestClientIntegration1045 client_integration_test.go:277: Created store path: /build/TestClientIntegration1997448228/002/store/g1rpznmbj0c5n7ssyz9dh23q12mpc174-test-file.txt10462026/08/27 18:11:46 OK 20251218171726_add_pins.sql (3.19ms)10472026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (3.79ms)10482026/08/27 18:11:46 goose: successfully migrated database to version: 2026062812000010492026/08/27 18:11:46 OK 1_commit_pending_closure.sql (2.56ms)10502026/08/27 18:11:46 OK 2_object_stats_trigger.sql (1.56ms)10512026/08/27 18:11:46 goose: up to current file version: 21052--- PASS: TestObjectStatsTrigger (0.61s)1053=== CONT TestReadRedirectKeepsNarinfoProxied10542026/08/27 18:11:46 OK 20241026095416_initial_model.sql (16.29ms)10552026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (8.49ms)1056=== NAME TestClientWithDependencies1057 client_integration_test.go:596: Found 1 dependencies (including self)10582026/08/27 18:11:46 OK 20251218171726_add_pins.sql (18.24ms)1059--- PASS: TestResurrectedObjectNotDeleted (0.64s)1060=== CONT TestReadRedirectNar10612026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (5.48ms)10622026/08/27 18:11:46 goose: successfully migrated database to version: 2026062812000010632026/08/27 18:11:46 OK 1_commit_pending_closure.sql (2.94ms)10642026-08-27 18:11:46.603 UTC [1150] ERROR: relation "goose_db_version" does not exist at character 3610652026-08-27 18:11:46.603 UTC [1150] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10662026/08/27 18:11:46 OK 2_object_stats_trigger.sql (2.22ms)10672026/08/27 18:11:46 goose: up to current file version: 21068=== NAME TestPinProtectsFromGC1069 client_integration_test.go:647: Pinned store path: /build/TestPinProtectsFromGC3058170681/001/store/d0i9w48fpy04fzwr12xz3my05r0ryaxr-pinned-file.txt1070 client_integration_test.go:648: Unpinned store path: /build/TestPinProtectsFromGC3058170681/001/store/93rdjgm2j66jx5imn0gvh5ssgzraam8r-unpinned-file.txt10712026/08/27 18:11:46 OK 20241026095416_initial_model.sql (8.79ms)10722026/08/27 18:11:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10732026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (2.52ms)10742026/08/27 18:11:46 OK 20251218171726_add_pins.sql (3.19ms)10752026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (4.38ms)10762026/08/27 18:11:46 goose: successfully migrated database to version: 2026062812000010772026/08/27 18:11:46 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10782026/08/27 18:11:46 OK 1_commit_pending_closure.sql (2.84ms)10792026/08/27 18:11:46 OK 2_object_stats_trigger.sql (1.45ms)10802026/08/27 18:11:46 goose: up to current file version: 210812026/08/27 18:11:46 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10822026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures10832026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures10842026/08/27 18:11:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10852026/08/27 18:11:46 INFO Uploading 6sqqdgzrvnazy7ik2hpm5qwlz66ifyab-test-script (136B)10862026/08/27 18:11:46 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"10872026/08/27 18:11:46 WARN Failed to register uploaded object key=log/azpcqaq213i4ki98fxgnjm1q301md2as-test-script.drv error="server returned 404: 404 page not found\n"10882026/08/27 18:11:46 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10892026/08/27 18:11:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10902026/08/27 18:11:46 INFO Uploading g1rpznmbj0c5n7ssyz9dh23q12mpc174-test-file.txt (152B)10912026/08/27 18:11:46 WARN Failed to register uploaded object key=6sqqdgzrvnazy7ik2hpm5qwlz66ifyab.ls error="server returned 404: 404 page not found\n"10922026-08-27 18:11:46.682 UTC [1294] ERROR: relation "goose_db_version" does not exist at character 3610932026-08-27 18:11:46.682 UTC [1294] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10942026/08/27 18:11:46 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10952026/08/27 18:11:46 INFO Signed narinfos id=1 count=110962026/08/27 18:11:46 INFO Uploading 1 narinfos10972026/08/27 18:11:46 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"10982026/08/27 18:11:46 WARN Failed to register uploaded object key=g1rpznmbj0c5n7ssyz9dh23q12mpc174.ls error="server returned 404: 404 page not found\n"10992026/08/27 18:11:46 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11002026/08/27 18:11:46 WARN Failed to register uploaded object key=6sqqdgzrvnazy7ik2hpm5qwlz66ifyab.narinfo error="server returned 404: 404 page not found\n"11012026/08/27 18:11:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11022026/08/27 18:11:46 INFO Signed narinfos id=1 count=111032026/08/27 18:11:46 INFO Uploading 1 narinfos11042026/08/27 18:11:46 WARN Failed to register uploaded object key=g1rpznmbj0c5n7ssyz9dh23q12mpc174.narinfo error="server returned 404: 404 page not found\n"11052026/08/27 18:11:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11062026/08/27 18:11:46 OK 20241026095416_initial_model.sql (8.07ms)11072026-08-27 18:11:46.699 UTC [1299] ERROR: relation "goose_db_version" does not exist at character 3611082026-08-27 18:11:46.699 UTC [1299] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11092026/08/27 18:11:46 INFO Completed upload id=111102026/08/27 18:11:46 INFO Upload complete. (76ms)11112026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (1.59ms)11122026/08/27 18:11:46 INFO Completed upload id=111132026/08/27 18:11:46 INFO Upload complete. (110ms)11142026/08/27 18:11:46 OK 20251218171726_add_pins.sql (1.99ms)1115=== NAME TestClientWithDependencies1116 client_integration_test.go:598: Skipping nix copy test - isolated store (/build/TestClientWithDependencies1827114819/001/store) requires matching store prefix1117--- PASS: TestService_Rustfstest (0.75s)1118=== CONT TestReadProxyDisabled1119=== NAME TestClientIntegration1120 client_integration_test.go:293: Retrieved narinfo from S3:1121 StorePath: /build/TestClientIntegration1997448228/002/store/g1rpznmbj0c5n7ssyz9dh23q12mpc174-test-file.txt1122 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1123 Compression: zstd1124 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11125 NarSize: 1521126 References: 1127 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk111282026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (2.75ms)11292026/08/27 18:11:46 goose: successfully migrated database to version: 202606281200001130 client_integration_test.go:294: Retrieved .ls file from S3 (compressed size: 77 bytes)1131 client_integration_test.go:294: Decompressed .ls content (64 bytes):11322026/08/27 18:11:46 OK 1_commit_pending_closure.sql (1.45ms)1133 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1134 client_integration_test.go:297: Testing garbage collection...1135--- PASS: TestClientWithDependencies (0.81s)1136=== CONT TestReadProxyRootRedirectsToIndexHTML11372026/08/27 18:11:46 OK 2_object_stats_trigger.sql (867.26µs)11382026/08/27 18:11:46 goose: up to current file version: 21139=== NAME TestNARDeduplicationMetadataUploadBug1140 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug1804872548/001/store/00fkzl5wcbbdmq2zh0128f8fqzhh7k4s-file1.txt11412026/08/27 18:11:46 OK 20241026095416_initial_model.sql (7.15ms)11422026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (942.4µs)11432026/08/27 18:11:46 OK 20251218171726_add_pins.sql (1.83ms)11442026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (3.6ms)11452026/08/27 18:11:46 goose: successfully migrated database to version: 2026062812000011462026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures1147=== NAME TestClientMultipleUploads11482026/08/27 18:11:46 OK 1_commit_pending_closure.sql (1.8ms)1149 client_integration_test.go:339: Created store path 0: /build/TestClientMultipleUploads3890320714/001/store/h64g2kk581jgkn1aw2p8p1ndf7jnbr2h-test-file-0.txt11502026/08/27 18:11:46 OK 2_object_stats_trigger.sql (1.47ms)11512026/08/27 18:11:46 goose: up to current file version: 211522026/08/27 18:11:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11532026/08/27 18:11:46 INFO Uploading d0i9w48fpy04fzwr12xz3my05r0ryaxr-pinned-file.txt (128B)11542026/08/27 18:11:46 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"11552026/08/27 18:11:46 WARN Failed to register uploaded object key=d0i9w48fpy04fzwr12xz3my05r0ryaxr.ls error="server returned 404: 404 page not found\n"11562026/08/27 18:11:46 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11572026/08/27 18:11:46 INFO Signed narinfos id=1 count=111582026/08/27 18:11:46 INFO Uploading 1 narinfos11592026/08/27 18:11:46 WARN Failed to register uploaded object key=d0i9w48fpy04fzwr12xz3my05r0ryaxr.narinfo error="server returned 404: 404 page not found\n"11602026/08/27 18:11:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11612026/08/27 18:11:46 INFO Starting cleanup of old closures method=DELETE path=/api/closures11622026/08/27 18:11:46 INFO Garbage collection started11632026/08/27 18:11:46 INFO Completed upload id=111642026/08/27 18:11:46 INFO Upload complete. (100ms)11652026/08/27 18:11:46 INFO Aborted multipart uploads count=011662026/08/27 18:11:46 INFO Aborted multipart uploads count=011672026/08/27 18:11:46 WARN Force mode enabled - objects will be deleted immediately without grace period1168 client_integration_test.go:339: Created store path 1: /build/TestClientMultipleUploads3890320714/001/store/h8qs3q9f99rassjqf70ijxlxabsylvdy-test-file-1.txt11692026/08/27 18:11:46 WARN Force mode enabled - objects will be deleted immediately without grace period11702026/08/27 18:11:46 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011712026/08/27 18:11:46 INFO Vacuumed table table=pending_closures11722026/08/27 18:11:46 INFO Vacuumed table table=pending_objects11732026/08/27 18:11:46 INFO Vacuumed table table=multipart_uploads11742026/08/27 18:11:46 INFO Vacuumed table table=closures11752026/08/27 18:11:46 INFO Vacuumed table table=objects11762026/08/27 18:11:46 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1177--- PASS: TestGCMetrics (0.81s)1178=== CONT TestReadProxyConditionalGet11792026/08/27 18:11:46 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1180=== NAME TestClientMultipleUploads1181 client_integration_test.go:339: Created store path 2: /build/TestClientMultipleUploads3890320714/001/store/d872k2q2dcjrgirjfq6vcdmhvbmdyx4p-test-file-2.txt11822026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures11832026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures11842026-08-27 18:11:46.806 UTC [1522] ERROR: relation "goose_db_version" does not exist at character 3611852026-08-27 18:11:46.806 UTC [1522] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11862026-08-27 18:11:46.807 UTC [1521] ERROR: relation "goose_db_version" does not exist at character 3611872026-08-27 18:11:46.807 UTC [1521] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11882026/08/27 18:11:46 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)11892026/08/27 18:11:46 INFO Uploading zxpsch8g8lh1258g7wrybkfhadib7vwa-output.txt (128B)11902026/08/27 18:11:46 INFO Uploading aczggdzg8bgxc9v4zxqrg51x0hrcwr59-build-dep.txt (144B)11912026/08/27 18:11:46 WARN Failed to register uploaded object key=nar/0zf002pclvicyfpcvpn82kby55jrx8bs7cyhccsd04byqa021ymm.nar.zst error="server returned 404: 404 page not found\n"11922026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures11932026/08/27 18:11:46 WARN Failed to register uploaded object key=nar/0xq2m43h3xd3qik9rvppw8bj4fm7a4vai6y4la58ivfa7lmzcrr1.nar.zst error="server returned 404: 404 page not found\n"11942026/08/27 18:11:46 WARN Failed to register uploaded object key=zxpsch8g8lh1258g7wrybkfhadib7vwa.ls error="server returned 404: 404 page not found\n"11952026/08/27 18:11:46 WARN Failed to register uploaded object key=aczggdzg8bgxc9v4zxqrg51x0hrcwr59.ls error="server returned 404: 404 page not found\n"11962026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures11972026/08/27 18:11:46 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign11982026/08/27 18:11:46 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11992026/08/27 18:11:46 INFO Signed narinfos id=2 count=112002026/08/27 18:11:46 INFO Signed narinfos id=1 count=112012026/08/27 18:11:46 INFO Uploading 2 narinfos12022026/08/27 18:11:46 OK 20241026095416_initial_model.sql (8.09ms)12032026/08/27 18:11:46 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12042026/08/27 18:11:46 OK 20241026095416_initial_model.sql (8.81ms)12052026/08/27 18:11:46 WARN Failed to register uploaded object key=zxpsch8g8lh1258g7wrybkfhadib7vwa.narinfo error="server returned 404: 404 page not found\n"12062026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (2.86ms)12072026/08/27 18:11:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12082026/08/27 18:11:46 INFO Uploading 00fkzl5wcbbdmq2zh0128f8fqzhh7k4s-file1.txt (160B)12092026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (1.32ms)12102026/08/27 18:11:46 WARN Failed to register uploaded object key=aczggdzg8bgxc9v4zxqrg51x0hrcwr59.narinfo error="server returned 404: 404 page not found\n"12112026/08/27 18:11:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12122026/08/27 18:11:46 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12132026/08/27 18:11:46 OK 20251218171726_add_pins.sql (4.15ms)12142026/08/27 18:11:46 OK 20251218171726_add_pins.sql (4.78ms)12152026/08/27 18:11:46 INFO Completed upload id=212162026/08/27 18:11:46 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12172026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (6.05ms)12182026/08/27 18:11:46 goose: successfully migrated database to version: 2026062812000012192026/08/27 18:11:46 INFO Completed upload id=112202026/08/27 18:11:46 INFO Upload complete. (111ms)12212026/08/27 18:11:46 WARN Failed to register uploaded object key=00fkzl5wcbbdmq2zh0128f8fqzhh7k4s.ls error="server returned 404: 404 page not found\n"12222026/08/27 18:11:46 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12232026/08/27 18:11:46 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12242026/08/27 18:11:46 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1225--- PASS: TestService_NativeMTLS (0.46s)1226=== CONT TestService_ReadScope_PublicByDefault12272026/08/27 18:11:46 INFO Signed narinfos id=1 count=112282026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (8.64ms)12292026/08/27 18:11:46 goose: successfully migrated database to version: 2026062812000012302026/08/27 18:11:46 INFO Uploading 1 narinfos12312026/08/27 18:11:46 OK 1_commit_pending_closure.sql (4.69ms)12322026/08/27 18:11:46 OK 1_commit_pending_closure.sql (2.15ms)12332026/08/27 18:11:46 OK 2_object_stats_trigger.sql (1.66ms)12342026/08/27 18:11:46 goose: up to current file version: 212352026/08/27 18:11:46 OK 2_object_stats_trigger.sql (2.43ms)12362026/08/27 18:11:46 goose: up to current file version: 212372026/08/27 18:11:46 WARN Failed to register uploaded object key=00fkzl5wcbbdmq2zh0128f8fqzhh7k4s.narinfo error="server returned 404: 404 page not found\n"12382026/08/27 18:11:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12392026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures12402026/08/27 18:11:46 INFO Completed upload id=112412026/08/27 18:11:46 INFO Upload complete. (115ms)1242=== NAME TestNARDeduplicationMetadataUploadBug1243 metadata_upload_test.go:54: Retrieved narinfo from S3:1244 StorePath: /build/TestNARDeduplicationMetadataUploadBug1804872548/001/store/00fkzl5wcbbdmq2zh0128f8fqzhh7k4s-file1.txt1245 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1246 Compression: zstd1247 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1248 NarSize: 1601249 References: 1250 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf12512026/08/27 18:11:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12522026/08/27 18:11:46 INFO Uploading 93rdjgm2j66jx5imn0gvh5ssgzraam8r-unpinned-file.txt (128B)1253 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1254 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):12552026/08/27 18:11:46 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"1256 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}12572026/08/27 18:11:46 WARN Failed to register uploaded object key=93rdjgm2j66jx5imn0gvh5ssgzraam8r.ls error="server returned 404: 404 page not found\n"12582026/08/27 18:11:46 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12592026/08/27 18:11:46 INFO Signed narinfos id=2 count=112602026/08/27 18:11:46 INFO Uploading 1 narinfos12612026-08-27 18:11:46.865 UTC [1633] ERROR: relation "goose_db_version" does not exist at character 3612622026-08-27 18:11:46.865 UTC [1633] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12632026/08/27 18:11:46 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1264--- PASS: TestReadProxyHead (0.46s)1265=== CONT TestClientErrorHandling1266=== RUN TestClientErrorHandling/InvalidStorePath1267=== PAUSE TestClientErrorHandling/InvalidStorePath1268=== RUN TestClientErrorHandling/InvalidAuthToken1269=== PAUSE TestClientErrorHandling/InvalidAuthToken1270=== RUN TestClientErrorHandling/ServerNotAvailable1271=== PAUSE TestClientErrorHandling/ServerNotAvailable1272=== CONT TestClientCADerivations12732026/08/27 18:11:46 WARN Failed to register uploaded object key=93rdjgm2j66jx5imn0gvh5ssgzraam8r.narinfo error="server returned 404: 404 page not found\n"1274--- PASS: TestMetricsInventory (0.49s)12752026/08/27 18:11:46 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete1276=== CONT TestCacheStatsHandler12772026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures12782026/08/27 18:11:46 INFO Completed upload id=212792026/08/27 18:11:46 INFO Upload complete. (96ms)12802026/08/27 18:11:46 INFO Starting cleanup of old closures method=DELETE path=/api/closures12812026/08/27 18:11:46 INFO Garbage collection started12822026/08/27 18:11:46 INFO Aborted multipart uploads count=012832026/08/27 18:11:46 WARN Force mode enabled - objects will be deleted immediately without grace period12842026/08/27 18:11:46 OK 20241026095416_initial_model.sql (8.58ms)12852026/08/27 18:11:46 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=012862026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (1.84ms)12872026/08/27 18:11:46 OK 20251218171726_add_pins.sql (8.52ms)12882026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures12892026/08/27 18:11:46 INFO Vacuumed table table=pending_closures12902026/08/27 18:11:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12912026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (6.27ms)12922026/08/27 18:11:46 goose: successfully migrated database to version: 2026062812000012932026/08/27 18:11:46 INFO Vacuumed table table=pending_objects12942026/08/27 18:11:46 INFO Vacuumed table table=multipart_uploads12952026/08/27 18:11:46 OK 1_commit_pending_closure.sql (3.29ms)12962026/08/27 18:11:46 INFO Vacuumed table table=closures12972026/08/27 18:11:46 OK 2_object_stats_trigger.sql (2.14ms)12982026/08/27 18:11:46 goose: up to current file version: 212992026/08/27 18:11:46 INFO Vacuumed table table=objects1300=== NAME TestNARDeduplicationMetadataUploadBug1301 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug1804872548/001/store/hbmng5v0c1avp1cp556sxcb9r5r0bywf-file2.txt1302--- PASS: TestReadProxyRangeRequest (0.42s)1303=== CONT TestCacheConfigHandler1304=== RUN TestCacheConfigHandler/full_config,_no_issuer1305=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1306=== RUN TestCacheConfigHandler/no_cache_url_configured1307=== PAUSE TestCacheConfigHandler/no_cache_url_configured1308=== RUN TestCacheConfigHandler/no_signing_keys1309=== PAUSE TestCacheConfigHandler/no_signing_keys1310=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1311=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1312=== CONT TestService_ReadAuthMiddleware13132026/08/27 18:11:46 INFO Received create pin request method=POST path=/api/pins/myapp13142026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures13152026/08/27 18:11:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13162026/08/27 18:11:46 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ODFlNzFjMDktMzZjMy00MjdiLWE0ZDQtNmVjYzhiMTNlODAxLmIxMDFhN2Y1LTU1YTMtNDE4My05ZmNlLTE3YTAwMDJiM2M4NHgxNzg3ODU0MzA2NDE0NzI5NzA3 parts=1013172026/08/27 18:11:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13182026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures13192026/08/27 18:11:46 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC3058170681/001/store/d0i9w48fpy04fzwr12xz3my05r0ryaxr-pinned-file.txt narinfo_key=d0i9w48fpy04fzwr12xz3my05r0ryaxr.narinfo1320--- PASS: TestReadRedirectKeepsNarinfoProxied (0.36s)1321=== CONT TestService_RequireScope_OIDC13222026/08/27 18:11:46 INFO Starting cleanup of old closures method=DELETE path=/api/closures13232026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures13242026/08/27 18:11:46 INFO Garbage collection started13252026/08/27 18:11:46 INFO OIDC provider initialized name=test1326--- PASS: TestGCBugBareHashReferences (0.97s)1327=== CONT TestService_AuthMiddleware_OIDC13282026/08/27 18:11:46 INFO Completed upload id=113292026/08/27 18:11:46 INFO OIDC provider initialized name=test13302026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures13312026/08/27 18:11:46 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)13322026/08/27 18:11:46 INFO Uploading h64g2kk581jgkn1aw2p8p1ndf7jnbr2h-test-file-0.txt (160B)13332026/08/27 18:11:46 INFO Uploading h8qs3q9f99rassjqf70ijxlxabsylvdy-test-file-1.txt (160B)13342026/08/27 18:11:46 INFO Uploading d872k2q2dcjrgirjfq6vcdmhvbmdyx4p-test-file-2.txt (160B)13352026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures13362026-08-27 18:11:46.933 UTC [1763] ERROR: relation "goose_db_version" does not exist at character 3613372026-08-27 18:11:46.933 UTC [1763] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13382026/08/27 18:11:46 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo13392026/08/27 18:11:46 WARN Found objects in DB but missing from S3, will re-upload count=113402026/08/27 18:11:46 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"13412026/08/27 18:11:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13422026/08/27 18:11:46 INFO Received cleanup request method=DELETE path=/api/pending_closures13432026/08/27 18:11:46 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"13442026/08/27 18:11:46 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ODFlNzFjMDktMzZjMy00MjdiLWE0ZDQtNmVjYzhiMTNlODAxLmY2NDMzZDEzLTcwZTMtNDFhYi05ZTZmLWZhNTg3M2ZmMjdkM3gxNzg3ODU0MzA2NDMxODI5OTUw parts=1013452026/08/27 18:11:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13462026/08/27 18:11:46 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"13472026/08/27 18:11:46 WARN Failed to register uploaded object key=h8qs3q9f99rassjqf70ijxlxabsylvdy.ls error="server returned 404: 404 page not found\n"13482026/08/27 18:11:46 INFO Aborted multipart uploads count=013492026/08/27 18:11:46 WARN Failed to register uploaded object key=d872k2q2dcjrgirjfq6vcdmhvbmdyx4p.ls error="server returned 404: 404 page not found\n"13502026/08/27 18:11:46 WARN Failed to register uploaded object key=h64g2kk581jgkn1aw2p8p1ndf7jnbr2h.ls error="server returned 404: 404 page not found\n"13512026/08/27 18:11:46 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13522026/08/27 18:11:46 INFO Aborted multipart uploads count=113532026/08/27 18:11:46 INFO Signed narinfos id=1 count=113542026/08/27 18:11:46 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13552026/08/27 18:11:46 INFO Signed narinfos id=2 count=113562026/08/27 18:11:46 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign13572026/08/27 18:11:46 INFO Signed narinfos id=3 count=113582026/08/27 18:11:46 INFO Uploading 3 narinfos13592026/08/27 18:11:46 WARN Failed to register uploaded object key=d872k2q2dcjrgirjfq6vcdmhvbmdyx4p.narinfo error="server returned 404: 404 page not found\n"13602026/08/27 18:11:46 WARN Failed to register uploaded object key=h64g2kk581jgkn1aw2p8p1ndf7jnbr2h.narinfo error="server returned 404: 404 page not found\n"13612026/08/27 18:11:46 WARN Failed to register uploaded object key=h8qs3q9f99rassjqf70ijxlxabsylvdy.narinfo error="server returned 404: 404 page not found\n"13622026/08/27 18:11:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1363--- PASS: TestReadProxyDisabled (0.24s)1364=== CONT TestService_healthCheckHandler1365--- PASS: TestService_verifyS3Integrity (1.07s)1366=== CONT TestCreatePendingClosureRejectsOversizedNAR13672026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures1368--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1369=== CONT TestCacheConfigHandlerMaxNarSize1370--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1371=== CONT TestGenerateLandingPage13722026/08/27 18:11:46 WARN Force mode enabled - objects will be deleted immediately without grace period13732026/08/27 18:11:46 INFO Completed upload id=113742026/08/27 18:11:46 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000013752026/08/27 18:11:46 INFO Completed upload id=113762026/08/27 18:11:46 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete1377--- PASS: TestMultipartCleanup (0.62s)1378--- PASS: TestGenerateLandingPage (0.01s)1379=== CONT TestService_readinessHandler1380=== CONT TestService_AuthMiddleware_MTLSProxyHeader13812026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures13822026/08/27 18:11:46 INFO Completed upload id=213832026/08/27 18:11:46 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete13842026/08/27 18:11:46 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ODFlNzFjMDktMzZjMy00MjdiLWE0ZDQtNmVjYzhiMTNlODAxLjY2NGI0MjllLWRjOTktNGE4OC1hMGRlLTJlZjFmZGU1MzdhYngxNzg3ODU0MzA2MzY5ODQwNDM3 parts=1213852026/08/27 18:11:46 INFO Starting cleanup of old closures method=DELETE path=/api/closures13862026/08/27 18:11:46 INFO Received uploads request method=POST path=/api/pending_closures13872026/08/27 18:11:46 INFO Completed upload id=313882026/08/27 18:11:46 INFO Upload complete. (133ms)1389=== NAME TestClientMultipleUploads1390 client_integration_test.go:350: Uploaded 3 paths in 173.110095ms1391--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.08s)1392=== CONT TestGCTaskStore_PhaseUpdates1393=== CONT TestGCTaskStore_Fail1394=== CONT TestReadProxyNarinfoAlreadyDecompressed1395=== CONT TestGracefulShutdownDrainsInflight1396=== CONT TestReadProxyInvalidPath13972026/08/27 18:11:46 INFO Starting HTTP server address=127.0.0.1:379231398--- PASS: TestReadRedirectNar (0.37s)1399--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1400--- PASS: TestGCTaskStore_Fail (0.00s)1401--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.26s)14022026/08/27 18:11:46 INFO Shutdown signal received, draining in-flight requests timeout=10s14032026/08/27 18:11:46 OK 20241026095416_initial_model.sql (11.13ms)1404--- PASS: TestClientMultipleUploads (1.01s)1405=== CONT TestReadProxy40414062026/08/27 18:11:46 OK 20251210153512_drop_unused_gin_index.sql (5.2ms)14072026/08/27 18:11:46 OK 20251218171726_add_pins.sql (4.83ms)14082026/08/27 18:11:46 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1409--- PASS: TestReadProxyConditionalGet (0.22s)1410=== CONT TestReadProxyNarStreaming14112026/08/27 18:11:46 OK 20260628120000_add_object_size_and_stats.sql (5.16ms)14122026/08/27 18:11:46 goose: successfully migrated database to version: 2026062812000014132026-08-27 18:11:46.982 UTC [1828] ERROR: relation "goose_db_version" does not exist at character 3614142026-08-27 18:11:46.982 UTC [1828] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14152026/08/27 18:11:46 INFO Aborted multipart uploads count=014162026/08/27 18:11:46 OK 1_commit_pending_closure.sql (2.91ms)1417=== NAME TestNoClosurePushKeepsReferencedObjectsReachable1418 no_closure_test.go:189: Built app=/build/TestNoClosurePushKeepsReferencedObjectsReachable3500399845/001/store/pgfq98bjdgcgpjwvdapcs6i330wi30ls-niks3-app dep=/build/TestNoClosurePushKeepsReferencedObjectsReachable3500399845/001/store/32gv36s0wa1f5flszcvi2fhb7g5pplfs-niks3-dep14192026/08/27 18:11:46 OK 2_object_stats_trigger.sql (1.96ms)14202026/08/27 18:11:46 goose: up to current file version: 214212026-08-27 18:11:46.991 UTC [1837] ERROR: relation "goose_db_version" does not exist at character 3614222026-08-27 18:11:46.991 UTC [1837] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14232026/08/27 18:11:47 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=01424--- PASS: TestService_ReadScope_PublicByDefault (0.17s)1425=== CONT TestIsValidCachePath1426=== RUN TestIsValidCachePath/narinfo1427=== PAUSE TestIsValidCachePath/narinfo1428=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1429=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1430=== RUN TestIsValidCachePath/nar_zst1431=== PAUSE TestIsValidCachePath/nar_zst1432=== RUN TestIsValidCachePath/nar_xz1433=== PAUSE TestIsValidCachePath/nar_xz1434=== RUN TestIsValidCachePath/nar_bz21435=== PAUSE TestIsValidCachePath/nar_bz21436=== RUN TestIsValidCachePath/nar_uncompressed1437=== PAUSE TestIsValidCachePath/nar_uncompressed1438=== RUN TestIsValidCachePath/ls1439=== PAUSE TestIsValidCachePath/ls1440=== RUN TestIsValidCachePath/log1441=== PAUSE TestIsValidCachePath/log1442=== RUN TestIsValidCachePath/realisation1443=== PAUSE TestIsValidCachePath/realisation1444=== RUN TestIsValidCachePath/nix-cache-info1445=== PAUSE TestIsValidCachePath/nix-cache-info1446=== RUN TestIsValidCachePath/index.html1447=== PAUSE TestIsValidCachePath/index.html1448=== RUN TestIsValidCachePath/traversal_parent1449=== PAUSE TestIsValidCachePath/traversal_parent1450=== RUN TestIsValidCachePath/traversal_in_middle1451=== PAUSE TestIsValidCachePath/traversal_in_middle1452=== RUN TestIsValidCachePath/invalid_char_e1453=== PAUSE TestIsValidCachePath/invalid_char_e1454=== RUN TestIsValidCachePath/invalid_char_u1455=== PAUSE TestIsValidCachePath/invalid_char_u1456=== RUN TestIsValidCachePath/random_path1457=== PAUSE TestIsValidCachePath/random_path1458=== RUN TestIsValidCachePath/empty1459=== PAUSE TestIsValidCachePath/empty1460=== RUN TestIsValidCachePath/leading_slash1461=== PAUSE TestIsValidCachePath/leading_slash1462=== RUN TestIsValidCachePath/wrong_extension1463=== PAUSE TestIsValidCachePath/wrong_extension1464=== RUN TestIsValidCachePath/short_hash1465=== PAUSE TestIsValidCachePath/short_hash1466=== CONT TestReadProxyNarinfo14672026/08/27 18:11:47 INFO Received uploads request method=POST path=/api/pending_closures14682026/08/27 18:11:47 OK 20241026095416_initial_model.sql (29.1ms)14692026/08/27 18:11:47 INFO Vacuumed table table=pending_closures14702026/08/27 18:11:47 OK 20241026095416_initial_model.sql (25.25ms)14712026/08/27 18:11:47 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)14722026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (8.69ms)14732026/08/27 18:11:47 INFO Vacuumed table table=pending_objects1474--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1475=== CONT TestGCTaskStore_CompletedAllowsNewTask1476--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1477=== CONT TestParseSingleRange1478=== RUN TestParseSingleRange/none1479=== PAUSE TestParseSingleRange/none1480=== RUN TestParseSingleRange/unknown_unit1481=== PAUSE TestParseSingleRange/unknown_unit1482=== RUN TestParseSingleRange/multi-range_ignored1483=== PAUSE TestParseSingleRange/multi-range_ignored1484=== RUN TestParseSingleRange/malformed_no_dash1485=== PAUSE TestParseSingleRange/malformed_no_dash1486=== RUN TestParseSingleRange/malformed_both_empty1487=== PAUSE TestParseSingleRange/malformed_both_empty1488=== RUN TestParseSingleRange/malformed_end_before_start1489=== PAUSE TestParseSingleRange/malformed_end_before_start1490=== RUN TestParseSingleRange/closed1491=== PAUSE TestParseSingleRange/closed14922026/08/27 18:11:47 WARN Failed to register uploaded object key=hbmng5v0c1avp1cp556sxcb9r5r0bywf.ls error="server returned 404: 404 page not found\n"1493=== RUN TestParseSingleRange/open-ended1494=== PAUSE TestParseSingleRange/open-ended1495=== RUN TestParseSingleRange/end_clamped_to_size1496=== PAUSE TestParseSingleRange/end_clamped_to_size14972026/08/27 18:11:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign1498=== RUN TestParseSingleRange/suffix1499=== PAUSE TestParseSingleRange/suffix1500=== RUN TestParseSingleRange/suffix_exceeds_size1501=== PAUSE TestParseSingleRange/suffix_exceeds_size1502=== RUN TestParseSingleRange/single_byte1503=== PAUSE TestParseSingleRange/single_byte15042026/08/27 18:11:47 INFO Signed narinfos id=2 count=11505=== RUN TestParseSingleRange/start_past_EOF15062026-08-27 18:11:47.034 UTC [1879] ERROR: relation "goose_db_version" does not exist at character 3615072026-08-27 18:11:47.034 UTC [1879] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1508=== PAUSE TestParseSingleRange/start_past_EOF15092026/08/27 18:11:47 INFO Uploading 1 narinfos1510=== RUN TestParseSingleRange/start_far_past_EOF1511=== PAUSE TestParseSingleRange/start_far_past_EOF1512=== CONT TestGCTaskStore_GetReturnsLatest1513--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1514=== CONT TestService_AuthMiddleware_MTLSBoundSubjects15152026/08/27 18:11:47 OK 20251218171726_add_pins.sql (8.12ms)15162026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (8.57ms)15172026/08/27 18:11:47 WARN Failed to register uploaded object key=hbmng5v0c1avp1cp556sxcb9r5r0bywf.narinfo error="server returned 404: 404 page not found\n"15182026/08/27 18:11:47 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15192026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (5.83ms)15202026/08/27 18:11:47 goose: successfully migrated database to version: 2026062812000015212026/08/27 18:11:47 OK 20251218171726_add_pins.sql (5.76ms)15222026/08/27 18:11:47 INFO Vacuumed table table=multipart_uploads15232026/08/27 18:11:47 OK 1_commit_pending_closure.sql (3.89ms)15242026/08/27 18:11:47 INFO Completed upload id=215252026/08/27 18:11:47 INFO Upload complete. (105ms)1526=== NAME TestNARDeduplicationMetadataUploadBug1527 metadata_upload_test.go:76: Retrieved narinfo from S3:1528 StorePath: /build/TestNARDeduplicationMetadataUploadBug1804872548/001/store/hbmng5v0c1avp1cp556sxcb9r5r0bywf-file2.txt1529 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1530 Compression: zstd1531 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1532 NarSize: 1601533 References: 1534 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf15352026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (6.03ms)15362026/08/27 18:11:47 goose: successfully migrated database to version: 2026062812000015372026/08/27 18:11:47 OK 2_object_stats_trigger.sql (3.67ms)15382026/08/27 18:11:47 goose: up to current file version: 21539 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1540 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1541 {"version":1,"root":{"type":"regular","size":44}}15422026/08/27 18:11:47 INFO Vacuumed table table=closures15432026/08/27 18:11:47 OK 1_commit_pending_closure.sql (6.48ms)1544--- PASS: TestNARDeduplicationMetadataUploadBug (1.10s)1545=== CONT TestResolveDBConnectionString/flag_wins1546=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1547=== CONT TestResolveDBConnectionString/nothing_configured1548=== CONT TestResolveDBConnectionString/missing_file_is_an_error1549=== CONT TestResolveDBConnectionString/file_when_flag_empty15502026/08/27 18:11:47 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1551=== CONT TestProxyWriteTimeout/narinfo1552=== CONT TestProxyWriteTimeout/unknown_size1553=== CONT TestProxyWriteTimeout/10_GiB_nar15542026/08/27 18:11:47 INFO Received uploads request method=POST path=/api/pending_closures1555=== CONT TestProxyWriteTimeout/1_GiB_nar1556--- PASS: TestResolveDBConnectionString (0.00s)1557 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1558 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1559 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1560 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1561 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1562=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15632026/08/27 18:11:47 OK 20241026095416_initial_model.sql (13.65ms)1564--- PASS: TestProxyWriteTimeout (0.07s)1565 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1566 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1567 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1568 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)15692026/08/27 18:11:47 INFO Received uploads request method=POST path=/15702026/08/27 18:11:47 INFO Received uploads request method=POST path=/api/pending_closures1571=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15722026/08/27 18:11:47 INFO Received complete multipart upload request method=POST path=/1573=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15742026/08/27 18:11:47 INFO Received uploads request method=POST path=/1575=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15762026/08/27 18:11:47 INFO Received request for more parts method=POST path=/1577--- PASS: TestUploadHandlersRejectInvalidKeys (0.07s)1578 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1579 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1580 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1581 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1582=== CONT TestIsValidUploadKey/narinfo1583=== CONT TestIsValidUploadKey/realisation_plus_in_output1584=== CONT TestIsValidUploadKey/realisation1585=== CONT TestIsValidUploadKey/build_log_equals1586=== CONT TestIsValidUploadKey/build_log_question_mark1587=== CONT TestIsValidUploadKey/build_log_plus_in_name1588=== CONT TestIsValidUploadKey/build_log_home-manager_file1589=== CONT TestIsValidUploadKey/build_log1590=== CONT TestIsValidUploadKey/listing1591=== CONT TestIsValidUploadKey/nar_plain1592=== CONT TestIsValidUploadKey/nar_xz1593=== CONT TestIsValidUploadKey/nar_zst1594=== CONT TestIsValidUploadKey/nix-cache-info1595=== CONT TestIsValidUploadKey/traversal1596=== CONT TestIsValidUploadKey/unknown_type1597=== CONT TestIsValidUploadKey/empty_key1598=== CONT TestIsValidUploadKey/absolute1599=== CONT TestIsValidUploadKey/traversal_nar1600=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1601=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1602=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1603=== CONT TestIsValidUploadKey/index.html1604--- PASS: TestIsValidUploadKey (0.07s)1605 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1606 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1607 --- PASS: TestIsValidUploadKey/realisation (0.00s)1608 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1609 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1610 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1611 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1612 --- PASS: TestIsValidUploadKey/build_log (0.00s)1613 --- PASS: TestIsValidUploadKey/listing (0.00s)1614 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1615 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1616 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1617 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1618 --- PASS: TestIsValidUploadKey/traversal (0.00s)1619 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1620 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1621 --- PASS: TestIsValidUploadKey/absolute (0.00s)1622 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1623 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1624 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1625 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1626 --- PASS: TestIsValidUploadKey/index.html (0.00s)1627=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16282026/08/27 18:11:47 INFO Received request for more parts method=POST path=/16292026/08/27 18:11:47 INFO Vacuumed table table=objects16302026/08/27 18:11:47 OK 2_object_stats_trigger.sql (30.54ms)16312026/08/27 18:11:47 goose: up to current file version: 216322026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (29.69ms)16332026/08/27 18:11:47 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)16342026/08/27 18:11:47 INFO Uploading pgfq98bjdgcgpjwvdapcs6i330wi30ls-niks3-app (232B)16352026/08/27 18:11:47 INFO Uploading 32gv36s0wa1f5flszcvi2fhb7g5pplfs-niks3-dep (136B)16362026/08/27 18:11:47 OK 20251218171726_add_pins.sql (10.05ms)16372026/08/27 18:11:47 WARN Failed to register uploaded object key=nar/11a0zvnnxl54br96r7d5wj0myhxjs2hymqrck725x2r78zab9hhb.nar.zst error="server returned 404: 404 page not found\n"16382026/08/27 18:11:47 WARN Failed to register uploaded object key=log/bg2j8zw47g4rcpg2jv7hzjc829bpymkv-niks3-app.drv error="server returned 404: 404 page not found\n"16392026/08/27 18:11:47 WARN Failed to register uploaded object key=log/31g0i6j8kvr40z7dvkxzwyjwzhgs2j2r-niks3-dep.drv error="server returned 404: 404 page not found\n"16402026/08/27 18:11:47 WARN Failed to register uploaded object key=nar/1y80sh8wjkir6ba1cv5m2p9zqii2r8wcr66mkdkgbcwcp24r3g57.nar.zst error="server returned 404: 404 page not found\n"16412026/08/27 18:11:47 WARN Failed to register uploaded object key=pgfq98bjdgcgpjwvdapcs6i330wi30ls.ls error="server returned 404: 404 page not found\n"16422026-08-27 18:11:47.102 UTC [1903] ERROR: relation "goose_db_version" does not exist at character 3616432026-08-27 18:11:47.102 UTC [1903] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16442026/08/27 18:11:47 WARN Failed to register uploaded object key=32gv36s0wa1f5flszcvi2fhb7g5pplfs.ls error="server returned 404: 404 page not found\n"16452026/08/27 18:11:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16462026/08/27 18:11:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16472026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (7.13ms)16482026/08/27 18:11:47 goose: successfully migrated database to version: 2026062812000016492026/08/27 18:11:47 INFO Signed narinfos id=1 count=11650=== NAME TestOrphanedObjectsGC16512026/08/27 18:11:47 INFO Signed narinfos id=2 count=11652 orphaned_objects_gc_test.go:290: GC Test Summary:1653 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1654 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B16552026/08/27 18:11:47 INFO Uploading 2 narinfos1656 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1657 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1658 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1659--- PASS: TestOrphanedObjectsGC (1.15s)1660=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16612026/08/27 18:11:47 INFO Received complete multipart upload request method=POST path=/16622026/08/27 18:11:47 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000016632026/08/27 18:11:47 OK 1_commit_pending_closure.sql (4.29ms)16642026/08/27 18:11:47 WARN Failed to register uploaded object key=32gv36s0wa1f5flszcvi2fhb7g5pplfs.narinfo error="server returned 404: 404 page not found\n"1665--- PASS: TestService_createPendingClosureHandler (1.23s)16662026/08/27 18:11:47 WARN Failed to register uploaded object key=pgfq98bjdgcgpjwvdapcs6i330wi30ls.narinfo error="server returned 404: 404 page not found\n"1667=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16682026/08/27 18:11:47 INFO Received uploads request method=POST path=/16692026/08/27 18:11:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16702026/08/27 18:11:47 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16712026-08-27 18:11:47.117 UTC [1920] ERROR: relation "goose_db_version" does not exist at character 3616722026-08-27 18:11:47.117 UTC [1920] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16732026-08-27 18:11:47.120 UTC [1921] ERROR: relation "goose_db_version" does not exist at character 3616742026-08-27 18:11:47.120 UTC [1921] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16752026/08/27 18:11:47 OK 2_object_stats_trigger.sql (17.72ms)16762026/08/27 18:11:47 goose: up to current file version: 216772026/08/27 18:11:47 INFO Completed upload id=216782026/08/27 18:11:47 OK 20241026095416_initial_model.sql (20.81ms)1679--- PASS: TestCacheStatsHandler (0.26s)1680=== CONT TestServerTLSConfig/no_client_CA1681=== CONT TestServerTLSConfig/not_a_PEM_file1682=== CONT TestServerTLSConfig/missing_CA_file1683--- PASS: TestServerTLSConfig (0.00s)1684 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1685 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1686 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1687=== CONT TestClientErrorHandling/InvalidStorePath16882026/08/27 18:11:47 INFO Completed upload id=116892026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (2.42ms)16902026/08/27 18:11:47 INFO Upload complete. (113ms)16912026/08/27 18:11:47 OK 20251218171726_add_pins.sql (4.13ms)16922026/08/27 18:11:47 OK 20241026095416_initial_model.sql (10.3ms)16932026-08-27 18:11:47.142 UTC [1924] ERROR: relation "goose_db_version" does not exist at character 3616942026-08-27 18:11:47.142 UTC [1924] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16952026-08-27 18:11:47.142 UTC [1925] ERROR: relation "goose_db_version" does not exist at character 3616962026-08-27 18:11:47.142 UTC [1925] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16972026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (4.51ms)16982026/08/27 18:11:47 goose: successfully migrated database to version: 2026062812000016992026-08-27 18:11:47.144 UTC [1926] ERROR: relation "goose_db_version" does not exist at character 3617002026-08-27 18:11:47.144 UTC [1926] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1701--- PASS: TestService_ReadAuthMiddleware (0.24s)1702=== CONT TestClientErrorHandling/ServerNotAvailable1703=== CONT TestClientErrorHandling/InvalidAuthToken17042026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (2.72ms)17052026/08/27 18:11:47 OK 20241026095416_initial_model.sql (10.94ms)17062026-08-27 18:11:47.146 UTC [1929] ERROR: relation "goose_db_version" does not exist at character 3617072026-08-27 18:11:47.146 UTC [1929] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17082026/08/27 18:11:47 OK 1_commit_pending_closure.sql (3.69ms)17092026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (2.36ms)17102026/08/27 18:11:47 OK 2_object_stats_trigger.sql (2.13ms)17112026/08/27 18:11:47 goose: up to current file version: 217122026/08/27 18:11:47 OK 20251218171726_add_pins.sql (4.87ms)17132026/08/27 18:11:47 OK 20251218171726_add_pins.sql (3.9ms)17142026-08-27 18:11:47.153 UTC [1930] ERROR: relation "goose_db_version" does not exist at character 3617152026-08-27 18:11:47.153 UTC [1930] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17162026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (4.69ms)17172026/08/27 18:11:47 goose: successfully migrated database to version: 2026062812000017182026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (4.14ms)17192026/08/27 18:11:47 goose: successfully migrated database to version: 2026062812000017202026/08/27 18:11:47 OK 1_commit_pending_closure.sql (2.76ms)17212026/08/27 18:11:47 OK 20241026095416_initial_model.sql (10.02ms)17222026/08/27 18:11:47 OK 2_object_stats_trigger.sql (2.05ms)17232026/08/27 18:11:47 goose: up to current file version: 217242026/08/27 18:11:47 OK 1_commit_pending_closure.sql (3.01ms)17252026/08/27 18:11:47 OK 20241026095416_initial_model.sql (11ms)17262026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (2.68ms)17272026/08/27 18:11:47 OK 2_object_stats_trigger.sql (2.63ms)17282026/08/27 18:11:47 goose: up to current file version: 217292026/08/27 18:11:47 OK 20241026095416_initial_model.sql (12.06ms)17302026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (2.76ms)17312026-08-27 18:11:47.164 UTC [1950] ERROR: relation "goose_db_version" does not exist at character 3617322026-08-27 18:11:47.164 UTC [1950] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17332026/08/27 18:11:47 OK 20251218171726_add_pins.sql (3.67ms)17342026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (3.05ms)17352026/08/27 18:11:47 OK 20251218171726_add_pins.sql (3.45ms)17362026/08/27 18:11:47 OK 20241026095416_initial_model.sql (11.76ms)17372026/08/27 18:11:47 OK 20241026095416_initial_model.sql (10.05ms)17382026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (4.9ms)17392026/08/27 18:11:47 goose: successfully migrated database to version: 2026062812000017402026/08/27 18:11:47 OK 20251218171726_add_pins.sql (4.64ms)17412026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (2.43ms)17422026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (3.53ms)17432026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (4.66ms)17442026/08/27 18:11:47 goose: successfully migrated database to version: 2026062812000017452026/08/27 18:11:47 INFO Starting cleanup of old closures method=DELETE path=/api/closures17462026/08/27 18:11:47 INFO Garbage collection started17472026/08/27 18:11:47 OK 1_commit_pending_closure.sql (3.23ms)17482026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (3.64ms)17492026/08/27 18:11:47 goose: successfully migrated database to version: 2026062812000017502026/08/27 18:11:47 OK 2_object_stats_trigger.sql (1.43ms)17512026/08/27 18:11:47 goose: up to current file version: 217522026/08/27 18:11:47 OK 1_commit_pending_closure.sql (2.5ms)17532026/08/27 18:11:47 OK 20251218171726_add_pins.sql (3.4ms)17542026/08/27 18:11:47 OK 20251218171726_add_pins.sql (3.26ms)17552026/08/27 18:11:47 INFO Aborted multipart uploads count=01756=== NAME TestClientCADerivations1757 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations741666561/001/store/q1123rc9l9mv81p9pp6w5xa6rw2a4g7v-ca-test17582026-08-27 18:11:47.177 UTC [1969] ERROR: relation "goose_db_version" does not exist at character 3617592026-08-27 18:11:47.177 UTC [1969] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17602026/08/27 18:11:47 WARN Force mode enabled - objects will be deleted immediately without grace period17612026/08/27 18:11:47 OK 2_object_stats_trigger.sql (1.51ms)17622026/08/27 18:11:47 goose: up to current file version: 217632026/08/27 18:11:47 OK 1_commit_pending_closure.sql (2.83ms)17642026/08/27 18:11:47 OK 2_object_stats_trigger.sql (2.4ms)17652026/08/27 18:11:47 goose: up to current file version: 217662026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (5.22ms)17672026/08/27 18:11:47 goose: successfully migrated database to version: 2026062812000017682026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (6.19ms)17692026/08/27 18:11:47 goose: successfully migrated database to version: 202606281200001770--- PASS: TestService_healthCheckHandler (0.24s)1771=== CONT TestCacheConfigHandler/full_config,_no_issuer1772=== CONT TestCacheConfigHandler/no_signing_keys17732026/08/27 18:11:47 OK 20241026095416_initial_model.sql (11.63ms)1774=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1775=== CONT TestCacheConfigHandler/no_cache_url_configured1776--- PASS: TestCacheConfigHandler (0.00s)1777 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1778 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1779 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1780 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1781=== CONT TestIsValidCachePath/narinfo1782=== CONT TestIsValidCachePath/index.html1783=== CONT TestIsValidCachePath/short_hash1784=== CONT TestIsValidCachePath/wrong_extension1785=== CONT TestIsValidCachePath/leading_slash1786=== CONT TestIsValidCachePath/empty1787=== CONT TestIsValidCachePath/random_path1788=== CONT TestIsValidCachePath/invalid_char_e17892026/08/27 18:11:47 OK 1_commit_pending_closure.sql (2.33ms)1790=== CONT TestIsValidCachePath/nar_uncompressed17912026/08/27 18:11:47 OK 1_commit_pending_closure.sql (3.06ms)1792=== CONT TestIsValidCachePath/invalid_char_u1793=== CONT TestIsValidCachePath/nix-cache-info1794=== CONT TestIsValidCachePath/traversal_in_middle1795=== RUN TestService_RequireScope_OIDC/builder_may_write1796=== CONT TestIsValidCachePath/traversal_parent1797=== CONT TestIsValidCachePath/log1798=== CONT TestIsValidCachePath/nar_xz1799=== CONT TestIsValidCachePath/ls1800=== CONT TestIsValidCachePath/nar_bz21801=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1802=== CONT TestIsValidCachePath/realisation1803=== CONT TestParseSingleRange/none1804=== PAUSE TestService_RequireScope_OIDC/builder_may_write1805=== CONT TestIsValidCachePath/nar_zst18062026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (2.02ms)1807--- PASS: TestIsValidCachePath (0.00s)1808 --- PASS: TestIsValidCachePath/narinfo (0.00s)1809 --- PASS: TestIsValidCachePath/index.html (0.00s)1810 --- PASS: TestIsValidCachePath/short_hash (0.00s)1811 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1812 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1813 --- PASS: TestIsValidCachePath/empty (0.00s)1814 --- PASS: TestIsValidCachePath/random_path (0.00s)1815 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1816 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1817 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1818 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1819 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1820 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1821 --- PASS: TestIsValidCachePath/log (0.00s)1822 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1823 --- PASS: TestIsValidCachePath/ls (0.00s)1824 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1825 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1826 --- PASS: TestIsValidCachePath/realisation (0.00s)1827 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1828=== CONT TestParseSingleRange/open-ended1829=== CONT TestParseSingleRange/start_past_EOF1830=== CONT TestParseSingleRange/single_byte1831=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1832=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1833=== RUN TestService_RequireScope_OIDC/ops_may_admin1834=== CONT TestParseSingleRange/start_far_past_EOF1835=== CONT TestParseSingleRange/suffix18362026/08/27 18:11:47 OK 2_object_stats_trigger.sql (1.85ms)1837=== CONT TestParseSingleRange/end_clamped_to_size18382026/08/27 18:11:47 goose: up to current file version: 21839=== CONT TestParseSingleRange/suffix_exceeds_size18402026/08/27 18:11:47 OK 2_object_stats_trigger.sql (1.94ms)18412026/08/27 18:11:47 goose: up to current file version: 21842=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1843=== CONT TestParseSingleRange/malformed_both_empty1844=== CONT TestParseSingleRange/closed1845=== CONT TestParseSingleRange/malformed_no_dash1846=== CONT TestParseSingleRange/multi-range_ignored1847=== CONT TestParseSingleRange/unknown_unit1848=== RUN TestService_RequireScope_OIDC/ops_may_not_write1849=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1850=== RUN TestService_RequireScope_OIDC/reader_may_not_write1851=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1852=== RUN TestService_RequireScope_OIDC/static_token_may_admin1853=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1854=== RUN TestService_RequireScope_OIDC/static_token_may_write1855=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1856=== CONT TestParseSingleRange/malformed_end_before_start1857--- PASS: TestParseSingleRange (0.00s)1858 --- PASS: TestParseSingleRange/none (0.00s)1859 --- PASS: TestParseSingleRange/open-ended (0.00s)1860 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1861 --- PASS: TestParseSingleRange/single_byte (0.00s)1862 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1863 --- PASS: TestParseSingleRange/suffix (0.00s)1864 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1865 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1866 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1867 --- PASS: TestParseSingleRange/closed (0.00s)1868 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1869 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1870 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1871 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1872=== RUN TestService_RequireScope_OIDC/reader_may_read1873=== PAUSE TestService_RequireScope_OIDC/reader_may_read1874=== RUN TestService_RequireScope_OIDC/writer_implies_read1875=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1876=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1877=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1878=== CONT TestService_RequireScope_OIDC/builder_may_write1879=== CONT TestService_RequireScope_OIDC/reader_may_read1880=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1881=== CONT TestService_RequireScope_OIDC/writer_implies_read18822026/08/27 18:11:47 OK 20251218171726_add_pins.sql (2.59ms)18832026/08/27 18:11:47 INFO OIDC auth successful provider=test scopes=[write]1884=== CONT TestService_RequireScope_OIDC/reader_may_not_write18852026/08/27 18:11:47 INFO OIDC auth successful provider=test scopes=[read]18862026-08-27 18:11:47.191 UTC [1980] ERROR: relation "goose_db_version" does not exist at character 3618872026-08-27 18:11:47.191 UTC [1980] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1888=== CONT TestService_RequireScope_OIDC/static_token_may_write18892026/08/27 18:11:47 INFO OIDC auth successful provider=test scopes=[write]1890=== CONT TestService_RequireScope_OIDC/static_token_may_admin18912026/08/27 18:11:47 INFO OIDC auth successful provider=test scopes=[read]1892=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1893=== CONT TestService_RequireScope_OIDC/ops_may_not_write18942026/08/27 18:11:47 INFO OIDC auth successful provider=test scopes=[write]1895=== CONT TestService_RequireScope_OIDC/ops_may_admin18962026/08/27 18:11:47 INFO OIDC auth successful provider=test scopes=[admin]18972026/08/27 18:11:47 INFO OIDC auth successful provider=test scopes=[admin]18982026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (3.66ms)18992026/08/27 18:11:47 goose: successfully migrated database to version: 202606281200001900--- PASS: TestService_RequireScope_OIDC (0.27s)1901 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1902 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1903 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1904 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1905 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1906 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1907 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1908 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1909 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1910 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)19112026/08/27 18:11:47 OK 20241026095416_initial_model.sql (9.65ms)19122026/08/27 18:11:47 OK 1_commit_pending_closure.sql (2.03ms)19132026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (1.31ms)19142026/08/27 18:11:47 OK 2_object_stats_trigger.sql (1.26ms)19152026/08/27 18:11:47 goose: up to current file version: 219162026/08/27 18:11:47 OK 20251218171726_add_pins.sql (3.6ms)1917=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1918=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1919=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1920=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1921=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1922=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1923=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1924=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1925=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1926=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19272026/08/27 18:11:47 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]1928=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1929=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19302026/08/27 18:11:47 INFO OIDC auth successful provider=test scopes=[write]19312026/08/27 18:11:47 WARN Authentication failed token_preview=eyJhbGciOi...jo2YUH5FIg token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]19322026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (3.99ms)19332026/08/27 18:11:47 goose: successfully migrated database to version: 202606281200001934--- PASS: TestService_AuthMiddleware_OIDC (0.27s)1935 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1936 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1937 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1938 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)19392026/08/27 18:11:47 OK 1_commit_pending_closure.sql (2.42ms)19402026/08/27 18:11:47 OK 20241026095416_initial_model.sql (9.21ms)19412026/08/27 18:11:47 OK 2_object_stats_trigger.sql (2.63ms)19422026/08/27 18:11:47 goose: up to current file version: 219432026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (1.75ms)1944=== NAME TestClientCADerivations1945 client_ca_test.go:139: Found 1 dependencies (including self)19462026/08/27 18:11:47 OK 20251218171726_add_pins.sql (2.64ms)19472026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (3.34ms)19482026/08/27 18:11:47 goose: successfully migrated database to version: 2026062812000019492026/08/27 18:11:47 OK 1_commit_pending_closure.sql (18.59ms)19502026/08/27 18:11:47 OK 2_object_stats_trigger.sql (1.63ms)19512026/08/27 18:11:47 goose: up to current file version: 219522026/08/27 18:11:47 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=019532026/08/27 18:11:47 INFO Vacuumed table table=pending_closures19542026-08-27 18:11:47.249 UTC [2042] ERROR: relation "goose_db_version" does not exist at character 3619552026-08-27 18:11:47.249 UTC [2042] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19562026-08-27 18:11:47.251 UTC [2043] ERROR: relation "goose_db_version" does not exist at character 3619572026-08-27 18:11:47.251 UTC [2043] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19582026/08/27 18:11:47 INFO Vacuumed table table=pending_objects1959--- PASS: TestReadProxyInvalidPath (0.29s)19602026/08/27 18:11:47 INFO Vacuumed table table=multipart_uploads19612026/08/27 18:11:47 INFO Vacuumed table table=closures19622026/08/27 18:11:47 OK 20241026095416_initial_model.sql (7.6ms)19632026/08/27 18:11:47 INFO Vacuumed table table=objects19642026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (1.16ms)1965--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.31s)19662026/08/27 18:11:47 OK 20251218171726_add_pins.sql (3.64ms)19672026/08/27 18:11:47 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-config19682026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (8.26ms)19692026/08/27 18:11:47 goose: successfully migrated database to version: 2026062812000019702026/08/27 18:11:47 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"19712026/08/27 18:11:47 OK 20241026095416_initial_model.sql (17.15ms)19722026/08/27 18:11:47 OK 1_commit_pending_closure.sql (1.61ms)19732026/08/27 18:11:47 OK 20251210153512_drop_unused_gin_index.sql (1.71ms)19742026/08/27 18:11:47 OK 2_object_stats_trigger.sql (652.59µs)19752026/08/27 18:11:47 goose: up to current file version: 219762026/08/27 18:11:47 OK 20251218171726_add_pins.sql (2.89ms)19772026/08/27 18:11:47 OK 20260628120000_add_object_size_and_stats.sql (3.56ms)19782026/08/27 18:11:47 goose: successfully migrated database to version: 2026062812000019792026/08/27 18:11:47 OK 1_commit_pending_closure.sql (1.73ms)19802026/08/27 18:11:47 OK 2_object_stats_trigger.sql (952.24µs)19812026/08/27 18:11:47 goose: up to current file version: 219822026/08/27 18:11:47 INFO Received uploads request method=POST path=/api/pending_closures1983--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.35s)19842026/08/27 18:11:47 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=01985--- PASS: TestReadProxy404 (0.35s)19862026/08/27 18:11:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19872026/08/27 18:11:47 INFO Uploading q1123rc9l9mv81p9pp6w5xa6rw2a4g7v-ca-test (144B)19882026/08/27 18:11:47 INFO Vacuumed table table=pending_closures19892026/08/27 18:11:47 INFO Vacuumed table table=pending_objects19902026/08/27 18:11:47 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"19912026/08/27 18:11:47 WARN Failed to register uploaded object key=log/l2cbxdlkm3kx4dfh7jf9lhy3mn2p97ga-ca-test.drv error="server returned 404: 404 page not found\n"19922026/08/27 18:11:47 INFO Vacuumed table table=multipart_uploads19932026/08/27 18:11:47 WARN Failed to register uploaded object key=q1123rc9l9mv81p9pp6w5xa6rw2a4g7v.ls error="server returned 404: 404 page not found\n"19942026/08/27 18:11:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign19952026/08/27 18:11:47 INFO Signed narinfos id=1 count=119962026/08/27 18:11:47 INFO Uploading 1 narinfos19972026/08/27 18:11:47 INFO Vacuumed table table=closures19982026/08/27 18:11:47 WARN readiness check failed error="closed pool"1999--- PASS: TestService_readinessHandler (0.37s)20002026/08/27 18:11:47 WARN Failed to register uploaded object key=q1123rc9l9mv81p9pp6w5xa6rw2a4g7v.narinfo error="server returned 404: 404 page not found\n"20012026/08/27 18:11:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20022026/08/27 18:11:47 INFO Vacuumed table table=objects20032026/08/27 18:11:47 INFO Completed upload id=120042026/08/27 18:11:47 INFO Upload complete. (92ms)2005=== NAME TestClientCADerivations2006 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations741666561/001/store/q1123rc9l9mv81p9pp6w5xa6rw2a4g7v-ca-test2007 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2008 Compression: zstd2009 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2010 NarSize: 1442011 References: 2012 Deriver: /build/TestClientCADerivations741666561/001/store/l2cbxdlkm3kx4dfh7jf9lhy3mn2p97ga-ca-test.drv2013 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2014 client_ca_test.go:185: Checking for realisation files in S3...2015 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2016 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache20172026/08/27 18:11:47 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=205.498212ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2018--- PASS: TestReadProxyNarStreaming (0.39s)2019--- PASS: TestReadProxyNarinfo (0.37s)20202026/08/27 18:11:47 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20212026/08/27 18:11:47 WARN mTLS auth: bound subjects configured but subject DN unavailable20222026/08/27 18:11:47 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2023--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.35s)2024=== NAME TestClientCADerivations2025 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2026 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2027 error: binary cache 's3://bucket38?endpoint=http://localhost:36825®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations741666561/001/store'2028 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12029--- PASS: TestClientCADerivations (0.63s)20302026/08/27 18:11:47 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"20312026/08/27 18:11:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20322026/08/27 18:11:47 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20332026/08/27 18:11:47 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ODFlNzFjMDktMzZjMy00MjdiLWE0ZDQtNmVjYzhiMTNlODAxLjhlNjcwZGI2LTE2ZjAtNGU5ZC04YTMzLTc1MDE0M2IzNTA2YXgxNzg3ODU0MzA2ODc5NTg1NzE1 parts=122034--- PASS: TestRedundantMultipartUpload (1.14s)20352026/08/27 18:11:47 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=020362026/08/27 18:11:47 INFO Vacuumed table table=pending_closures20372026/08/27 18:11:47 INFO Vacuumed table table=pending_objects20382026/08/27 18:11:47 INFO Vacuumed table table=multipart_uploads20392026/08/27 18:11:47 INFO Vacuumed table table=closures20402026/08/27 18:11:47 INFO Vacuumed table table=objects20412026/08/27 18:11:47 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=425.491382ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2042--- PASS: TestUploadHandlersRejectOversizedBody (0.17s)2043 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.08s)2044 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.08s)2045 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.85s)20462026/08/27 18:11:48 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=862.153335ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2047=== NAME TestOrphanedObjectsGCStressTest2048 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2049 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion2050 orphaned_objects_gc_test.go:509: Stress test completed successfully:2051 orphaned_objects_gc_test.go:510: - Active objects preserved: 202052 orphaned_objects_gc_test.go:511: - Objects deleted: 2102053 orphaned_objects_gc_test.go:512: - Total GC'd: 2102054--- PASS: TestOrphanedObjectsGCStressTest (2.48s)20552026/08/27 18:11:48 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02056=== NAME TestClientIntegration2057 client_integration_test.go:304: Objects in database after GC:2058 client_integration_test.go:304: Successfully deleted all objects with GC --force2059--- PASS: TestClientIntegration (2.86s)20602026/08/27 18:11:48 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.578944456s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2061--- PASS: TestNoClosurePushCreatesIndependentGCRoots (2.84s)20622026/08/27 18:11:48 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02063=== NAME TestPinProtectsFromGC2064 client_integration_test.go:710: Pin successfully protected closure from garbage collection2065--- PASS: TestPinProtectsFromGC (3.05s)20662026/08/27 18:11:49 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=0 objects_marked=2 objects_deleted=2002 objects_failed=02067--- PASS: TestNoClosurePushKeepsReferencedObjectsReachable (3.23s)20682026/08/27 18:11:50 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"20692026/08/27 18:11:50 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_closures20702026/08/27 18:11:50 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=212.830258ms 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:11:50 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=395.388231ms 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:11:51 WARN Rate limiter enabled after throttle name=s3-test rate=520732026/08/27 18:11:51 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2074=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2075 throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=102076 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002077--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.15s)20782026/08/27 18:11:51 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=767.075585ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20792026/08/27 18:11:51 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.748138968s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2080--- PASS: TestClientErrorHandling (0.00s)2081 --- PASS: TestClientErrorHandling/InvalidStorePath (0.30s)2082 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.40s)2083 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.58s)2084PASS2085{"timestamp":"2026-08-27T18:11:53.728150786Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:41262","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1836,"threadName":"rustfs-worker","threadId":"ThreadId(397)"}20862026-08-27 18:11:53.966 UTC [112] LOG: received smart shutdown request20872026-08-27 18:11:53.971 UTC [112] LOG: background worker "logical replication launcher" (PID 122) exited with exit code 120882026-08-27 18:11:53.982 UTC [117] LOG: shutting down20892026-08-27 18:11:53.983 UTC [117] LOG: checkpoint starting: shutdown immediate20902026-08-27 18:11:55.653 UTC [117] LOG: checkpoint complete: wrote 11454 buffers (69.9%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 15 recycled; write=0.276 s, sync=1.380 s, total=1.672 s; sync files=17486, longest=0.002 s, average=0.001 s; distance=240894 kB, estimate=240894 kB; lsn=0/102A3650, redo lsn=0/102A365020912026-08-27 18:11:55.736 UTC [112] LOG: database system is shut down2092Running OIDC tests...2093=== RUN TestGlobMatch2094=== PAUSE TestGlobMatch2095=== RUN TestAudienceForIssuer2096=== PAUSE TestAudienceForIssuer2097=== RUN TestValidateToken_ValidToken2098=== PAUSE TestValidateToken_ValidToken2099=== RUN TestValidateToken_WrongAudience2100=== PAUSE TestValidateToken_WrongAudience2101=== RUN TestValidateToken_Expired2102=== PAUSE TestValidateToken_Expired2103=== RUN TestValidateToken_BoundClaimsMismatch2104=== PAUSE TestValidateToken_BoundClaimsMismatch2105=== RUN TestValidateToken_BoundSubjectMismatch2106=== PAUSE TestValidateToken_BoundSubjectMismatch2107=== RUN TestValidateToken_MultipleProviders2108=== PAUSE TestValidateToken_MultipleProviders2109=== RUN TestValidateToken_NoMatchingProvider2110=== PAUSE TestValidateToken_NoMatchingProvider2111=== RUN TestValidateToken_KubernetesServiceAccount2112=== PAUSE TestValidateToken_KubernetesServiceAccount2113=== RUN TestNewValidator_KubernetesRequiresCA2114=== PAUSE TestNewValidator_KubernetesRequiresCA2115=== RUN TestScopes_LegacyProviderDefaultsToWrite2116=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2117=== RUN TestScopes_Rules2118=== PAUSE TestScopes_Rules2119=== RUN TestScopes_ConfigValidation2120=== PAUSE TestScopes_ConfigValidation2121=== CONT TestGlobMatch2122=== RUN TestGlobMatch/foo_foo2123=== CONT TestValidateToken_BoundSubjectMismatch2124=== PAUSE TestGlobMatch/foo_foo2125=== CONT TestValidateToken_WrongAudience2126=== CONT TestValidateToken_ValidToken2127=== CONT TestAudienceForIssuer2128--- PASS: TestAudienceForIssuer (0.00s)2129=== CONT TestValidateToken_Expired2130=== CONT TestValidateToken_KubernetesServiceAccount2131=== CONT TestNewValidator_KubernetesRequiresCA2132=== CONT TestValidateToken_BoundClaimsMismatch2133=== CONT TestScopes_ConfigValidation2134=== CONT TestScopes_Rules2135=== CONT TestValidateToken_NoMatchingProvider2136=== CONT TestValidateToken_MultipleProviders2137=== CONT TestScopes_LegacyProviderDefaultsToWrite2138=== RUN TestGlobMatch/foo_bar2139=== PAUSE TestGlobMatch/foo_bar2140=== RUN TestGlobMatch/*_2141=== PAUSE TestGlobMatch/*_2142=== RUN TestGlobMatch/*_anything2143=== PAUSE TestGlobMatch/*_anything2144=== RUN TestGlobMatch/foo*_foo2145=== PAUSE TestGlobMatch/foo*_foo2146=== RUN TestGlobMatch/foo*_foobar2147=== PAUSE TestGlobMatch/foo*_foobar2148=== RUN TestGlobMatch/foo*_bar2149=== PAUSE TestGlobMatch/foo*_bar2150=== RUN TestGlobMatch/*bar_bar2151=== PAUSE TestGlobMatch/*bar_bar2152=== RUN TestGlobMatch/*bar_foobar2153=== PAUSE TestGlobMatch/*bar_foobar2154=== RUN TestGlobMatch/*bar_foo2155=== PAUSE TestGlobMatch/*bar_foo2156=== RUN TestGlobMatch/foo*bar_foobar2157=== PAUSE TestGlobMatch/foo*bar_foobar2158=== RUN TestGlobMatch/foo*bar_foo123bar2159=== PAUSE TestGlobMatch/foo*bar_foo123bar2160=== RUN TestGlobMatch/foo*bar_foobarbaz2161=== PAUSE TestGlobMatch/foo*bar_foobarbaz2162=== RUN TestGlobMatch/*/*_foo/bar2163=== PAUSE TestGlobMatch/*/*_foo/bar2164=== RUN TestGlobMatch/*/*_foo2165=== PAUSE TestGlobMatch/*/*_foo2166=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2167=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2168=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02169=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02170=== RUN TestGlobMatch/refs/*/main_refs/heads/main2171=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2172=== RUN TestGlobMatch/fo?_foo2173=== PAUSE TestGlobMatch/fo?_foo2174=== RUN TestGlobMatch/fo?_fo2175=== PAUSE TestGlobMatch/fo?_fo2176=== RUN TestGlobMatch/fo?_fooo2177=== PAUSE TestGlobMatch/fo?_fooo2178=== RUN TestGlobMatch/?oo_foo2179=== PAUSE TestGlobMatch/?oo_foo2180=== RUN TestGlobMatch/?oo_boo2181=== PAUSE TestGlobMatch/?oo_boo2182=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2183=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2184=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2185=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2186=== CONT TestGlobMatch/foo_foo2187=== CONT TestGlobMatch/fo?_fo2188=== CONT TestGlobMatch/foo_bar2189=== CONT TestGlobMatch/foo*bar_foobarbaz2190=== CONT TestGlobMatch/fo?_foo2191=== CONT TestGlobMatch/refs/*/main_refs/heads/main2192=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2193=== CONT TestGlobMatch/?oo_boo2194=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2195=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2196=== CONT TestGlobMatch/*/*_foo2197=== CONT TestGlobMatch/?oo_foo2198=== CONT TestGlobMatch/fo?_fooo2199=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02200=== CONT TestGlobMatch/foo*bar_foo123bar2201=== CONT TestGlobMatch/foo*bar_foobar2202=== CONT TestGlobMatch/*bar_foo2203=== CONT TestGlobMatch/*bar_foobar2204=== CONT TestGlobMatch/*bar_bar2205=== CONT TestGlobMatch/foo*_bar2206=== CONT TestGlobMatch/foo*_foobar2207=== CONT TestGlobMatch/foo*_foo2208=== CONT TestGlobMatch/*_anything2209=== CONT TestGlobMatch/*_2210=== CONT TestGlobMatch/*/*_foo/bar2211--- PASS: TestGlobMatch (0.00s)2212 --- PASS: TestGlobMatch/foo_foo (0.00s)2213 --- PASS: TestGlobMatch/fo?_fo (0.00s)2214 --- PASS: TestGlobMatch/foo_bar (0.00s)2215 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2216 --- PASS: TestGlobMatch/fo?_foo (0.00s)2217 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2218 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2219 --- PASS: TestGlobMatch/?oo_boo (0.00s)2220 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2221 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2222 --- PASS: TestGlobMatch/*/*_foo (0.00s)2223 --- PASS: TestGlobMatch/?oo_foo (0.00s)2224 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2225 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2226 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2227 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2228 --- PASS: TestGlobMatch/*bar_foo (0.00s)2229 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2230 --- PASS: TestGlobMatch/*bar_bar (0.00s)2231 --- PASS: TestGlobMatch/foo*_bar (0.00s)2232 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2233 --- PASS: TestGlobMatch/foo*_foo (0.00s)2234 --- PASS: TestGlobMatch/*_ (0.00s)2235 --- PASS: TestGlobMatch/*_anything (0.00s)2236 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)22372026/08/27 18:11:56 INFO OIDC provider initialized name=test2238--- PASS: TestScopes_ConfigValidation (0.01s)22392026/08/27 18:11:56 INFO OIDC provider initialized name=test22402026/08/27 18:11:56 INFO OIDC provider initialized name=provider122412026/08/27 18:11:56 INFO OIDC provider initialized name=test22422026/08/27 18:11:56 INFO OIDC provider initialized name=test22432026/08/27 18:11:56 INFO OIDC provider initialized name=provider122442026/08/27 18:11:56 INFO OIDC provider initialized name=test22452026/08/27 18:11:56 INFO OIDC provider initialized name=test22462026/08/27 18:11:56 INFO OIDC provider initialized name=test22472026/08/27 18:11:56 INFO OIDC provider initialized name=provider22248--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)2249--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.01s)2250--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)2251--- PASS: TestValidateToken_NoMatchingProvider (0.01s)2252--- PASS: TestValidateToken_ValidToken (0.01s)2253--- PASS: TestValidateToken_WrongAudience (0.01s)2254--- PASS: TestValidateToken_Expired (0.01s)22552026/08/27 18:11:56 INFO OIDC provider initialized name=kubernetes2256--- PASS: TestValidateToken_MultipleProviders (0.01s)22572026/08/27 18:11:56 http: TLS handshake error from 127.0.0.1:41686: remote error: tls: bad certificate2258--- PASS: TestValidateToken_KubernetesServiceAccount (0.02s)2259--- PASS: TestNewValidator_KubernetesRequiresCA (0.02s)2260--- PASS: TestScopes_Rules (0.02s)2261PASS2262Running hook tests...2263=== RUN TestSendPathsEmpty2264=== PAUSE TestSendPathsEmpty2265=== RUN TestQueueEnqueueAndFetch2266=== PAUSE TestQueueEnqueueAndFetch2267=== RUN TestQueueDeduplication2268=== PAUSE TestQueueDeduplication2269=== RUN TestQueueRemove2270=== PAUSE TestQueueRemove2271=== RUN TestQueueFetchBatchLimit2272=== PAUSE TestQueueFetchBatchLimit2273=== RUN TestQueueRetryMovesToBack2274=== PAUSE TestQueueRetryMovesToBack2275=== RUN TestQueueFetchRemoveLifecycle2276=== PAUSE TestQueueFetchRemoveLifecycle2277=== RUN TestQueueConcurrentWriters2278=== PAUSE TestQueueConcurrentWriters2279=== RUN TestQueueRemoveLargeClosure2280=== PAUSE TestQueueRemoveLargeClosure2281=== RUN TestServerClientIntegration2282=== PAUSE TestServerClientIntegration2283=== RUN TestServerQueueError2284=== PAUSE TestServerQueueError2285=== RUN TestGetListenerSocketActivation2286 server_test.go:210: === RUN TestGetListenerSocketActivation2287 --- PASS: TestGetListenerSocketActivation (0.00s)2288 PASS2289 2290--- PASS: TestGetListenerSocketActivation (0.01s)2291=== RUN TestDrainIsolatesPoisonPath2292=== PAUSE TestDrainIsolatesPoisonPath2293=== RUN TestRunNotBlockedByPoisonHead2294=== PAUSE TestRunNotBlockedByPoisonHead2295=== RUN TestDrainGivesUpWhenServerDown2296=== PAUSE TestDrainGivesUpWhenServerDown2297=== RUN TestFailedPathPrunedByLaterClosure2298=== PAUSE TestFailedPathPrunedByLaterClosure2299=== RUN TestWorkerUploadsAndRemoves2300=== PAUSE TestWorkerUploadsAndRemoves2301=== RUN TestWorkerSkipsGCdPaths2302=== PAUSE TestWorkerSkipsGCdPaths2303=== RUN TestWorkerPrunesClosureDeps2304=== PAUSE TestWorkerPrunesClosureDeps2305=== RUN TestDrainTimeout2306=== PAUSE TestDrainTimeout2307=== CONT TestSendPathsEmpty2308=== CONT TestServerQueueError2309=== CONT TestWorkerUploadsAndRemoves2310=== CONT TestQueueRetryMovesToBack2311=== CONT TestServerClientIntegration2312=== CONT TestQueueFetchBatchLimit2313=== CONT TestQueueRemove2314=== CONT TestQueueDeduplication2315=== CONT TestQueueEnqueueAndFetch2316=== CONT TestQueueConcurrentWriters2317=== CONT TestQueueRemoveLargeClosure23182026/08/27 18:11:56 ERROR Failed to queue paths error="permission denied" count=12319=== CONT TestWorkerPrunesClosureDeps2320=== CONT TestDrainTimeout2321=== CONT TestDrainGivesUpWhenServerDown2322=== CONT TestFailedPathPrunedByLaterClosure2323=== CONT TestRunNotBlockedByPoisonHead2324=== CONT TestDrainIsolatesPoisonPath2325=== CONT TestWorkerSkipsGCdPaths2326=== CONT TestQueueFetchRemoveLifecycle2327--- PASS: TestSendPathsEmpty (0.00s)2328--- PASS: TestServerQueueError (0.00s)2329--- PASS: TestServerClientIntegration (0.00s)23302026/08/27 18:11:56 INFO Uploading batch count=123312026/08/27 18:11:56 INFO Upload queue status pending=223322026/08/27 18:11:56 INFO Uploading batch count=223332026/08/27 18:11:56 ERROR Upload failed error="upload failed" count=123342026/08/27 18:11:56 INFO Uploading batch count=223352026/08/27 18:11:56 ERROR Upload failed error="upload failed" count=223362026/08/27 18:11:56 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3882857355/002/a23372026/08/27 18:11:56 INFO Upload queue status pending=323382026/08/27 18:11:56 INFO Uploading batch count=123392026/08/27 18:11:56 ERROR Upload failed error="upload failed" count=123402026/08/27 18:11:56 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3882857355/002/b2341--- PASS: TestQueueFetchBatchLimit (0.03s)23422026/08/27 18:11:56 INFO Uploading batch count=22343--- PASS: TestQueueEnqueueAndFetch (0.03s)23442026/08/27 18:11:56 INFO Upload queue status pending=223452026/08/27 18:11:56 INFO Uploading batch count=423462026/08/27 18:11:56 ERROR Upload failed error="upload failed" count=423472026/08/27 18:11:56 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths3612581392/002/nonexistent23482026/08/27 18:11:56 INFO Upload queue status pending=223492026/08/27 18:11:56 INFO Uploading batch count=223502026/08/27 18:11:56 ERROR Upload failed error="upload failed" count=223512026/08/27 18:11:56 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3882857355/002/c23522026/08/27 18:11:56 INFO Uploading batch count=12353--- PASS: TestQueueDeduplication (0.04s)23542026/08/27 18:11:56 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath1865798714/002/bbb23552026/08/27 18:11:56 INFO Uploading batch count=12356--- PASS: TestQueueFetchRemoveLifecycle (0.03s)23572026/08/27 18:11:56 INFO Uploading batch count=123582026/08/27 18:11:56 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3882857355/002/d23592026/08/27 18:11:56 INFO Uploading batch count=12360--- PASS: TestQueueRemove (0.04s)23612026/08/27 18:11:56 INFO Uploading batch count=223622026/08/27 18:11:56 ERROR Upload failed error="upload failed" count=22363--- PASS: TestQueueRetryMovesToBack (0.04s)23642026/08/27 18:11:56 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3882857355/002/e23652026/08/27 18:11:56 INFO Uploading batch count=123662026/08/27 18:11:56 ERROR Upload failed error="upload failed" count=123672026/08/27 18:11:56 INFO Uploading batch count=123682026/08/27 18:11:56 ERROR Upload failed error="upload failed" count=123692026/08/27 18:11:56 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3882857355/002/f23702026/08/27 18:11:56 INFO Uploading batch count=123712026/08/27 18:11:56 ERROR Upload failed error="upload failed" count=12372--- PASS: TestFailedPathPrunedByLaterClosure (0.04s)23732026/08/27 18:11:56 ERROR Drain finished with paths left in queue remaining=123742026/08/27 18:11:56 ERROR Drain finished with paths left in queue remaining=102375--- PASS: TestDrainIsolatesPoisonPath (0.04s)2376--- PASS: TestDrainGivesUpWhenServerDown (0.04s)2377--- PASS: TestWorkerPrunesClosureDeps (0.06s)2378--- PASS: TestWorkerUploadsAndRemoves (0.06s)2379--- PASS: TestWorkerSkipsGCdPaths (0.06s)2380--- PASS: TestQueueRemoveLargeClosure (0.21s)23812026/08/27 18:11:56 ERROR Upload failed error="context deadline exceeded" count=223822026/08/27 18:11:56 ERROR Drain finished with paths left in queue remaining=42383--- PASS: TestDrainTimeout (0.24s)2384--- PASS: TestQueueConcurrentWriters (0.50s)23852026/08/27 18:11:57 INFO Uploading batch count=123862026/08/27 18:11:57 INFO Uploading batch count=123872026/08/27 18:11:57 INFO Uploading batch count=123882026/08/27 18:11:57 ERROR Upload failed error="upload failed" count=123892026/08/27 18:11:57 INFO Uploading batch count=123902026/08/27 18:11:57 ERROR Upload failed error="upload failed" count=123912026/08/27 18:11:57 INFO Uploading batch count=123922026/08/27 18:11:57 ERROR Upload failed error="upload failed" count=123932026/08/27 18:11:57 INFO Uploading batch count=123942026/08/27 18:11:57 ERROR Upload failed error="upload failed" count=123952026/08/27 18:11:57 ERROR Drain finished with paths left in queue remaining=12396--- PASS: TestRunNotBlockedByPoisonHead (1.06s)2397PASS