niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #163
· raw
1tribuchet: building on eliza2Running 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 TestFileTokenReadsAndCaches79=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess80=== CONT TestStaticToken81=== CONT TestScriptTokenCachesUntilRefresh82=== CONT TestGetStorePathHash83=== RUN TestGetStorePathHash/valid_store_path84=== PAUSE TestGetStorePathHash/valid_store_path85=== RUN TestGetStorePathHash/basename_without_hyphen_should_error86=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error87=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error88=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error89=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error90=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error91=== CONT TestScriptTokenEmptyToken92=== CONT TestFileTokenEmpty93=== CONT TestScriptTokenEmptyCommand94=== CONT TestScriptTokenNoExpiryRerunsEveryCall95=== CONT TestScriptTokenScriptFails96=== CONT TestScriptTokenBadJSON972026/08/27 18:11:56 WARN Rate limiter enabled after throttle name=server-test rate=598=== CONT TestConvertHashToNix3299=== RUN TestConvertHashToNix32/SRI_format_to_Nix32100=== CONT TestRateLimiterFeedback101=== CONT TestChunkStorePaths102=== CONT TestPrepareClosuresNoClosure103=== CONT TestPathInfoCACompatibility104=== CONT TestParsePathInfoJSONMultiplePaths105=== CONT TestParsePathInfoJSON106=== CONT TestPathInfoHashCompatibility107--- PASS: TestStaticToken (0.00s)108=== CONT TestSetClientTLSErrors109=== CONT TestSetClientTLSDoesNotMutateDefaultTransport110=== CONT TestSetClientTLS111=== CONT TestShellSplitErrors112=== CONT TestShellSplit113=== CONT TestDoWithRetry_BodyReplayedViaGetBody114=== CONT TestResolveStorePath115=== CONT TestFileTokenMissing116=== CONT TestEncodeNixBase32WithRealHash117=== CONT TestDumpPathWriterError118=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths119=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths120=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths121=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths122=== RUN TestChunkStorePaths/keeps_a_small_set_in_one_chunk123=== PAUSE TestChunkStorePaths/keeps_a_small_set_in_one_chunk124=== CONT TestUploadMultipart_SupersededByPeer125=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)126=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)127=== RUN TestUploadMultipart_SupersededByPeer/exists128=== CONT TestPartSizeForNAR129=== RUN TestPartSizeForNAR/zero_stays_at_minimum130=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum131=== RUN TestPartSizeForNAR/small_stays_at_minimum132=== PAUSE TestPartSizeForNAR/small_stays_at_minimum133=== RUN TestPathInfoCACompatibility/null_ca_field134=== PAUSE TestPathInfoCACompatibility/null_ca_field135=== CONT TestFilterOversizedClosures136=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon137--- PASS: TestScriptTokenEmptyCommand (0.00s)138=== CONT TestCaseHackSuffix139=== RUN TestChunkStorePaths/splits_on_the_byte_budget_and_preserves_every_path140=== RUN TestParsePathInfoJSON/Nix_format141=== RUN TestRateLimiterFeedback/429_enables_limiter142=== PAUSE TestRateLimiterFeedback/429_enables_limiter143=== PAUSE TestUploadMultipart_SupersededByPeer/exists144=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum145=== CONT TestEncodeNixBase32146=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32147=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon148--- PASS: TestFileTokenReadsAndCaches (0.00s)149=== CONT TestDumpPathSingleFile150=== CONT TestGetStorePathHash/valid_store_path151=== CONT TestDumpPathMatchesNix152=== RUN TestPrepareClosuresNoClosure/closure_mode_pulls_in_transitive_references153=== RUN TestPathInfoCACompatibility/old_string_format_-_text154=== RUN TestFilterOversizedClosures/no_limit_keeps_everything155=== PAUSE TestChunkStorePaths/splits_on_the_byte_budget_and_preserves_every_path156=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI157=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text158=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive159=== RUN TestChunkStorePaths/emits_an_oversized_path_rather_than_dropping_it160=== PAUSE TestParsePathInfoJSON/Nix_format161=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum162=== RUN TestRateLimiterFeedback/503_enables_limiter163=== RUN TestUploadMultipart_SupersededByPeer/missing164--- PASS: TestFileTokenEmpty (0.00s)165=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error166=== RUN TestConvertHashToNix32/already_Nix32_format1672026/08/27 18:11:56 WARN Rate limiter enabled after throttle name=server-test rate=5168=== PAUSE TestPrepareClosuresNoClosure/closure_mode_pulls_in_transitive_references169=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error170=== RUN TestPrepareClosuresNoClosure/no-closure_keeps_each_path_self-contained1712026/08/27 18:11:56 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:38325172=== RUN TestParsePathInfoJSON/Lix_format173=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything174=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI175=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped176=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512177=== CONT TestGetStorePathHash/basename_without_hyphen_should_error178=== PAUSE TestChunkStorePaths/emits_an_oversized_path_rather_than_dropping_it179=== RUN TestSetClientTLSErrors/missing_cert_file180=== RUN TestChunkStorePaths/handles_an_empty_input1812026/08/27 18:11:56 WARN Rate limiter backed off name=server-test rate=5182=== PAUSE TestRateLimiterFeedback/503_enables_limiter1832026/08/27 18:11:56 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:38325184--- PASS: TestFileTokenMissing (0.00s)185=== PAUSE TestUploadMultipart_SupersededByPeer/missing186=== PAUSE TestConvertHashToNix32/already_Nix32_format187=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths188=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive189=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths190=== PAUSE TestPrepareClosuresNoClosure/no-closure_keeps_each_path_self-contained191=== RUN TestPrepareClosuresNoClosure/no-closure_narinfos_still_record_their_references192=== PAUSE TestPrepareClosuresNoClosure/no-closure_narinfos_still_record_their_references193=== CONT TestPrepareClosuresNoClosure/closure_mode_pulls_in_transitive_references194=== CONT TestPrepareClosuresNoClosure/no-closure_keeps_each_path_self-contained195=== CONT TestPrepareClosuresNoClosure/no-closure_narinfos_still_record_their_references196=== PAUSE TestParsePathInfoJSON/Lix_format197=== RUN TestParsePathInfoJSON/empty_input198=== PAUSE TestParsePathInfoJSON/empty_input199=== RUN TestParsePathInfoJSON/whitespace_only200=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped201=== RUN TestSetClientTLS/rejects_connection_without_client_cert202=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512203=== PAUSE TestParsePathInfoJSON/whitespace_only204=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert205=== PAUSE TestSetClientTLSErrors/missing_cert_file206=== PAUSE TestChunkStorePaths/handles_an_empty_input207--- PASS: TestEncodeNixBase32WithRealHash (0.00s)208=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter209=== CONT TestUploadMultipart_SupersededByPeer/exists210=== CONT TestUploadMultipart_SupersededByPeer/missing211=== RUN TestConvertHashToNix32/invalid_format212=== PAUSE TestConvertHashToNix32/invalid_format213=== CONT TestConvertHashToNix32/SRI_format_to_Nix32214=== RUN TestPathInfoCACompatibility/new_structured_format_-_text215=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text216=== CONT TestConvertHashToNix32/already_Nix32_format217=== RUN TestEncodeNixBase32/test_string_hash218=== RUN TestFilterOversizedClosures/all_closures_skipped219=== CONT TestConvertHashToNix32/invalid_format220=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)221=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512222=== PAUSE TestEncodeNixBase32/test_string_hash223=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts224=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI225=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon226=== RUN TestParsePathInfoJSON/invalid_JSON227=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA228=== RUN TestSetClientTLSErrors/missing_key_file229--- PASS: TestShellSplitErrors (0.00s)230=== CONT TestChunkStorePaths/keeps_a_small_set_in_one_chunk231=== CONT TestChunkStorePaths/emits_an_oversized_path_rather_than_dropping_it232=== CONT TestChunkStorePaths/splits_on_the_byte_budget_and_preserves_every_path233=== CONT TestChunkStorePaths/handles_an_empty_input234=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter235=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method236=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts237=== RUN TestEncodeNixBase32/empty_input238=== RUN TestPartSizeForNAR/1_TiB239=== PAUSE TestFilterOversizedClosures/all_closures_skipped240=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA241=== RUN TestSetClientTLS/preserves_debug_logging_transport242=== PAUSE TestSetClientTLS/preserves_debug_logging_transport243=== CONT TestSetClientTLS/rejects_connection_without_client_cert244=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA245=== CONT TestSetClientTLS/preserves_debug_logging_transport246=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter247=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter248=== PAUSE TestSetClientTLSErrors/missing_key_file249=== PAUSE TestParsePathInfoJSON/invalid_JSON250=== CONT TestParsePathInfoJSON/whitespace_only251=== CONT TestParsePathInfoJSON/Lix_format252=== RUN TestFilterOversizedClosures/no-closure_judges_each_path_on_its_own_size253--- PASS: TestShellSplit (0.00s)254--- PASS: TestScriptTokenScriptFails (0.00s)255--- PASS: TestScriptTokenBadJSON (0.00s)256--- PASS: TestResolveStorePath (0.00s)257--- PASS: TestScriptTokenEmptyToken (0.00s)258=== CONT TestParsePathInfoJSON/Nix_format259=== CONT TestRateLimiterFeedback/429_enables_limiter260=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter261=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter262=== CONT TestRateLimiterFeedback/503_enables_limiter263=== PAUSE TestEncodeNixBase32/empty_input2642026/08/27 18:11:56 WARN Rate limiter enabled after throttle name=server-test rate=5265=== CONT TestEncodeNixBase32/test_string_hash2662026/08/27 18:11:56 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:46361267=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method268=== PAUSE TestPartSizeForNAR/1_TiB269=== RUN TestSetClientTLSErrors/missing_ca_file270=== CONT TestParsePathInfoJSON/empty_input271=== CONT TestParsePathInfoJSON/invalid_JSON272=== PAUSE TestFilterOversizedClosures/no-closure_judges_each_path_on_its_own_size2732026/08/27 18:11:56 WARN Rate limiter backed off name=server-test rate=5274=== CONT TestFilterOversizedClosures/no_limit_keeps_everything275=== CONT TestFilterOversizedClosures/no-closure_judges_each_path_on_its_own_size2762026/08/27 18:11:56 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=2000277=== CONT TestEncodeNixBase32/empty_input2782026/08/27 18:11:56 WARN Rate limiter enabled after throttle name=server-test rate=5279=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method2802026/08/27 18:11:56 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:37743281=== CONT TestPathInfoCACompatibility/null_ca_field282=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive2832026/08/27 18:11:56 WARN Rate limiter backed off name=server-test rate=5284=== CONT TestPathInfoCACompatibility/old_string_format_-_text285=== CONT TestPathInfoCACompatibility/new_structured_format_-_text286=== RUN TestPartSizeForNAR/5_TiB_S3_max_object287=== PAUSE TestSetClientTLSErrors/missing_ca_file288=== RUN TestSetClientTLSErrors/invalid_ca_file289--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)290--- PASS: TestDoServerRequestAttachesToken (0.01s)291=== CONT TestFilterOversizedClosures/all_closures_skipped2922026/08/27 18:11:56 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=50293=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2942026/08/27 18:11:56 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=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object296=== RUN TestPartSizeForNAR/capped_at_5_GiB297=== PAUSE TestPartSizeForNAR/capped_at_5_GiB298=== CONT TestPartSizeForNAR/zero_stays_at_minimum299=== CONT TestPartSizeForNAR/5_TiB_S3_max_object300=== PAUSE TestSetClientTLSErrors/invalid_ca_file301=== CONT TestSetClientTLSErrors/missing_cert_file302=== CONT TestSetClientTLSErrors/invalid_ca_file303=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts304--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.01s)305--- PASS: TestGetStorePathHash (0.00s)306 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)307 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)308 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)309 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)310--- PASS: TestScriptTokenCachesUntilRefresh (0.02s)311=== CONT TestPartSizeForNAR/1_TiB312=== CONT TestPartSizeForNAR/capped_at_5_GiB313=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum314=== CONT TestPartSizeForNAR/small_stays_at_minimum315=== CONT TestSetClientTLSErrors/missing_ca_file316=== CONT TestSetClientTLSErrors/missing_key_file317--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)318 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)319 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)320--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)321--- PASS: TestParsePathInfoJSON (0.02s)322 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)323 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)324 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)325 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)326 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)327--- PASS: TestChunkStorePaths (0.02s)328 --- PASS: TestChunkStorePaths/keeps_a_small_set_in_one_chunk (0.00s)329 --- PASS: TestChunkStorePaths/emits_an_oversized_path_rather_than_dropping_it (0.00s)330 --- PASS: TestChunkStorePaths/splits_on_the_byte_budget_and_preserves_every_path (0.00s)331 --- PASS: TestChunkStorePaths/handles_an_empty_input (0.00s)332--- PASS: TestRateLimiterFeedback (0.02s)333 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)334 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)335 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)336 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)337--- PASS: TestFilterOversizedClosures (0.02s)338 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)339 --- PASS: TestFilterOversizedClosures/no-closure_judges_each_path_on_its_own_size (0.00s)340 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)341 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)342--- PASS: TestPrepareClosuresNoClosure (0.02s)343 --- PASS: TestPrepareClosuresNoClosure/closure_mode_pulls_in_transitive_references (0.00s)344 --- PASS: TestPrepareClosuresNoClosure/no-closure_keeps_each_path_self-contained (0.00s)345 --- PASS: TestPrepareClosuresNoClosure/no-closure_narinfos_still_record_their_references (0.00s)346--- PASS: TestConvertHashToNix32 (0.02s)347 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)348 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)349 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)350--- PASS: TestPathInfoHashCompatibility (0.02s)351 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)352 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)353 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)354 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)355--- PASS: TestEncodeNixBase32 (0.02s)356 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)357 --- PASS: TestEncodeNixBase32/empty_input (0.00s)358--- PASS: TestPathInfoCACompatibility (0.02s)359 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)360 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)361 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)362 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)363 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)364--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)365 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)366 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)367--- PASS: TestPartSizeForNAR (0.02s)368 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)369 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)370 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)371 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)372 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (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.03s)376 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)377 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)378 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)379 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)380--- PASS: TestCaseHackSuffix (0.03s)3812026/08/27 18:11:56 http: TLS handshake error from 127.0.0.1:37656: remote error: tls: bad certificate382--- PASS: TestSetClientTLS (0.02s)383 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)384 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)385 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)386--- PASS: TestDumpPathSingleFile (0.04s)387--- PASS: TestDumpPathWriterError (0.05s)388--- PASS: TestDumpPathMatchesNix (0.11s)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/postgres3324658616/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/postgres3324658616/data -l logfile start418419/build/postgres3324658616:5432 - no response4202026-08-27 18:11:58.216 UTC [111] LOG: starting PostgreSQL 18.4 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit4212026-08-27 18:11:58.217 UTC [111] LOG: listening on Unix socket "/build/postgres3324658616/.s.PGSQL.5432"4222026-08-27 18:11:58.220 UTC [118] LOG: database system was shut down at 2026-08-27 18:11:57 UTC4232026-08-27 18:11:58.224 UTC [111] LOG: database system is ready to accept connections424/build/postgres3324658616: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:12:02.041 UTC [454] ERROR: relation "goose_db_version" does not exist at character 364592026-08-27 18:12:02.041 UTC [454] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4602026/08/27 18:12:02 OK 20241026095416_initial_model.sql (10.95ms)4612026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (1.68ms)4622026/08/27 18:12:02 OK 20251218171726_add_pins.sql (3.25ms)4632026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (2.82ms)4642026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200004652026/08/27 18:12:02 OK 1_commit_pending_closure.sql (1.84ms)4662026/08/27 18:12:02 OK 2_object_stats_trigger.sql (1.32ms)4672026/08/27 18:12:02 goose: up to current file version: 2468--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.34s)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:12:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5712026/08/27 18:12:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5722026/08/27 18:12:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5732026/08/27 18:12:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5742026/08/27 18:12:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5752026/08/27 18:12:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5762026/08/27 18:12:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5772026/08/27 18:12:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5782026/08/27 18:12:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5792026/08/27 18:12:02 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 TestCompleteMultipartUnregistered602=== CONT TestService_AuthMiddleware603=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT604=== CONT TestMultipartCleanup605=== CONT TestReadRedirectNar606=== CONT TestParseSize607=== CONT TestService_Rustfstest608=== CONT TestPresignedUploadRegisteredBeforeCommit609=== CONT TestCompletedNarNotReofferedAcrossClosures610=== CONT TestCompleteMultipartUpload_ErrorButObjectExists611=== CONT TestRedundantMultipartUpload612=== CONT TestReadProxyRangeRequest613=== CONT TestReadRedirectKeepsNarinfoProxied614=== CONT TestClientCADerivations615=== CONT TestGCMetrics616=== CONT TestGCBugBareHashReferences617=== CONT TestResolveDBConnectionString618=== CONT TestPinProtectsFromGC619=== RUN TestResolveDBConnectionString/flag_wins620=== CONT TestClientWithDependencies621=== CONT TestClientMultipleUploads622=== CONT TestSkippedUploadsHandler623=== CONT TestOrphanedObjectsGCStressTest624=== CONT TestGCTaskStore_StartNew625=== CONT TestClientErrorHandling626=== RUN TestClientErrorHandling/InvalidStorePath627=== PAUSE TestClientErrorHandling/InvalidStorePath628=== RUN TestClientErrorHandling/InvalidAuthToken629=== CONT TestReadProxyNarinfo630--- PASS: TestParseSize (0.00s)631=== CONT TestClientIntegration632=== PAUSE TestResolveDBConnectionString/flag_wins633=== PAUSE TestClientErrorHandling/InvalidAuthToken634=== RUN TestClientErrorHandling/ServerNotAvailable635=== PAUSE TestClientErrorHandling/ServerNotAvailable636=== RUN TestResolveDBConnectionString/file_when_flag_empty637=== PAUSE TestResolveDBConnectionString/file_when_flag_empty638=== RUN TestResolveDBConnectionString/missing_file_is_an_error639=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error640=== RUN TestResolveDBConnectionString/PGHOST_allows_empty641=== CONT TestParseSingleRange642--- PASS: TestGCTaskStore_StartNew (0.00s)643=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty644=== RUN TestResolveDBConnectionString/nothing_configured645=== RUN TestParseSingleRange/none646=== PAUSE TestParseSingleRange/none647=== RUN TestParseSingleRange/unknown_unit648=== PAUSE TestParseSingleRange/unknown_unit649=== PAUSE TestResolveDBConnectionString/nothing_configured650=== RUN TestParseSingleRange/multi-range_ignored651=== CONT TestService_verifyS3Integrity652=== PAUSE TestParseSingleRange/multi-range_ignored653=== RUN TestParseSingleRange/malformed_no_dash654=== PAUSE TestParseSingleRange/malformed_no_dash655=== RUN TestParseSingleRange/malformed_both_empty656=== PAUSE TestParseSingleRange/malformed_both_empty657=== RUN TestParseSingleRange/malformed_end_before_start658=== PAUSE TestParseSingleRange/malformed_end_before_start659=== RUN TestParseSingleRange/closed660=== PAUSE TestParseSingleRange/closed661=== RUN TestParseSingleRange/open-ended662=== PAUSE TestParseSingleRange/open-ended663=== RUN TestParseSingleRange/end_clamped_to_size664=== PAUSE TestParseSingleRange/end_clamped_to_size665=== RUN TestParseSingleRange/suffix666=== PAUSE TestParseSingleRange/suffix667=== RUN TestParseSingleRange/suffix_exceeds_size668=== PAUSE TestParseSingleRange/suffix_exceeds_size669=== RUN TestParseSingleRange/single_byte670=== PAUSE TestParseSingleRange/single_byte671=== RUN TestParseSingleRange/start_past_EOF672=== PAUSE TestParseSingleRange/start_past_EOF673=== RUN TestParseSingleRange/start_far_past_EOF674=== PAUSE TestParseSingleRange/start_far_past_EOF675=== CONT TestIsValidCachePath676=== RUN TestIsValidCachePath/narinfo677=== PAUSE TestIsValidCachePath/narinfo678=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars679=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars680=== RUN TestIsValidCachePath/nar_zst681=== PAUSE TestIsValidCachePath/nar_zst682=== RUN TestIsValidCachePath/nar_xz683=== PAUSE TestIsValidCachePath/nar_xz684=== RUN TestIsValidCachePath/nar_bz2685=== PAUSE TestIsValidCachePath/nar_bz2686=== RUN TestIsValidCachePath/nar_uncompressed6872026/08/27 18:12:02 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000688=== PAUSE TestIsValidCachePath/nar_uncompressed689=== RUN TestIsValidCachePath/ls690=== PAUSE TestIsValidCachePath/ls691=== RUN TestIsValidCachePath/log692=== PAUSE TestIsValidCachePath/log693=== RUN TestIsValidCachePath/realisation694=== PAUSE TestIsValidCachePath/realisation695=== RUN TestIsValidCachePath/nix-cache-info696=== PAUSE TestIsValidCachePath/nix-cache-info697=== RUN TestIsValidCachePath/index.html698=== PAUSE TestIsValidCachePath/index.html699=== RUN TestIsValidCachePath/traversal_parent700=== PAUSE TestIsValidCachePath/traversal_parent701=== RUN TestIsValidCachePath/traversal_in_middle702=== PAUSE TestIsValidCachePath/traversal_in_middle703=== RUN TestIsValidCachePath/invalid_char_e704=== PAUSE TestIsValidCachePath/invalid_char_e705=== RUN TestIsValidCachePath/invalid_char_u706=== PAUSE TestIsValidCachePath/invalid_char_u707=== RUN TestIsValidCachePath/random_path708=== PAUSE TestIsValidCachePath/random_path709=== RUN TestIsValidCachePath/empty710=== PAUSE TestIsValidCachePath/empty711=== RUN TestIsValidCachePath/leading_slash712=== PAUSE TestIsValidCachePath/leading_slash713=== RUN TestIsValidCachePath/wrong_extension714=== PAUSE TestIsValidCachePath/wrong_extension715=== RUN TestIsValidCachePath/short_hash716=== PAUSE TestIsValidCachePath/short_hash717=== CONT TestService_createPendingClosureHandler718--- PASS: TestSkippedUploadsHandler (0.01s)719=== CONT TestReadProxyRootRedirectsToIndexHTML7202026-08-27 18:12:02.600 UTC [528] ERROR: relation "goose_db_version" does not exist at character 367212026-08-27 18:12:02.600 UTC [528] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7222026-08-27 18:12:02.601 UTC [529] ERROR: relation "goose_db_version" does not exist at character 367232026-08-27 18:12:02.601 UTC [529] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7242026-08-27 18:12:02.616 UTC [530] ERROR: relation "goose_db_version" does not exist at character 367252026-08-27 18:12:02.616 UTC [530] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7262026-08-27 18:12:02.624 UTC [531] ERROR: relation "goose_db_version" does not exist at character 367272026-08-27 18:12:02.624 UTC [531] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7282026-08-27 18:12:02.666 UTC [537] ERROR: relation "goose_db_version" does not exist at character 367292026-08-27 18:12:02.666 UTC [537] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7302026/08/27 18:12:02 OK 20241026095416_initial_model.sql (68.64ms)7312026-08-27 18:12:02.702 UTC [538] ERROR: relation "goose_db_version" does not exist at character 367322026-08-27 18:12:02.702 UTC [538] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7332026/08/27 18:12:02 OK 20241026095416_initial_model.sql (61.59ms)7342026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (12.73ms)7352026/08/27 18:12:02 OK 20241026095416_initial_model.sql (75.37ms)7362026/08/27 18:12:02 OK 20241026095416_initial_model.sql (80.44ms)7372026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (6.12ms)7382026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (4.5ms)7392026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (5.05ms)7402026/08/27 18:12:02 OK 20251218171726_add_pins.sql (8.44ms)7412026-08-27 18:12:02.715 UTC [539] ERROR: relation "goose_db_version" does not exist at character 367422026-08-27 18:12:02.715 UTC [539] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7432026-08-27 18:12:02.716 UTC [540] ERROR: relation "goose_db_version" does not exist at character 367442026-08-27 18:12:02.716 UTC [540] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7452026/08/27 18:12:02 OK 20251218171726_add_pins.sql (8.74ms)7462026/08/27 18:12:02 OK 20251218171726_add_pins.sql (8.93ms)7472026/08/27 18:12:02 OK 20251218171726_add_pins.sql (8.85ms)7482026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (8.94ms)7492026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200007502026/08/27 18:12:02 OK 20241026095416_initial_model.sql (27.55ms)7512026/08/27 18:12:02 OK 1_commit_pending_closure.sql (13.44ms)7522026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (16.43ms)7532026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200007542026-08-27 18:12:02.736 UTC [541] ERROR: relation "goose_db_version" does not exist at character 367552026-08-27 18:12:02.736 UTC [541] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7562026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (12.42ms)7572026/08/27 18:12:02 OK 2_object_stats_trigger.sql (4.46ms)7582026/08/27 18:12:02 goose: up to current file version: 27592026/08/27 18:12:02 OK 1_commit_pending_closure.sql (5.87ms)7602026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (19.19ms)7612026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200007622026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (19.3ms)7632026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200007642026/08/27 18:12:02 OK 2_object_stats_trigger.sql (4.18ms)7652026/08/27 18:12:02 goose: up to current file version: 27662026/08/27 18:12:02 OK 20251218171726_add_pins.sql (9.52ms)7672026/08/27 18:12:02 OK 1_commit_pending_closure.sql (5.89ms)7682026/08/27 18:12:02 OK 20241026095416_initial_model.sql (33.16ms)7692026/08/27 18:12:02 OK 1_commit_pending_closure.sql (7.53ms)7702026/08/27 18:12:02 OK 20241026095416_initial_model.sql (27.13ms)7712026/08/27 18:12:02 OK 20241026095416_initial_model.sql (27.67ms)7722026/08/27 18:12:02 OK 2_object_stats_trigger.sql (5.49ms)7732026/08/27 18:12:02 goose: up to current file version: 27742026/08/27 18:12:02 OK 2_object_stats_trigger.sql (4.12ms)7752026/08/27 18:12:02 goose: up to current file version: 27762026-08-27 18:12:02.756 UTC [542] ERROR: relation "goose_db_version" does not exist at character 367772026-08-27 18:12:02.756 UTC [542] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7782026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (9.49ms)7792026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200007802026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (4.63ms)7812026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (4.17ms)7822026-08-27 18:12:02.757 UTC [543] ERROR: relation "goose_db_version" does not exist at character 367832026-08-27 18:12:02.757 UTC [543] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7842026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (4.66ms)7852026/08/27 18:12:02 OK 20251218171726_add_pins.sql (15.23ms)7862026/08/27 18:12:02 OK 20241026095416_initial_model.sql (23.8ms)7872026/08/27 18:12:02 OK 1_commit_pending_closure.sql (15.48ms)7882026/08/27 18:12:02 OK 20251218171726_add_pins.sql (15.31ms)7892026-08-27 18:12:02.774 UTC [544] ERROR: relation "goose_db_version" does not exist at character 367902026-08-27 18:12:02.774 UTC [544] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7912026-08-27 18:12:02.775 UTC [546] ERROR: relation "goose_db_version" does not exist at character 367922026-08-27 18:12:02.775 UTC [546] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7932026-08-27 18:12:02.776 UTC [545] ERROR: relation "goose_db_version" does not exist at character 367942026-08-27 18:12:02.776 UTC [545] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7952026-08-27 18:12:02.776 UTC [548] ERROR: relation "goose_db_version" does not exist at character 367962026-08-27 18:12:02.776 UTC [548] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7972026-08-27 18:12:02.777 UTC [547] ERROR: relation "goose_db_version" does not exist at character 367982026-08-27 18:12:02.777 UTC [547] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7992026/08/27 18:12:02 OK 20251218171726_add_pins.sql (19.25ms)8002026/08/27 18:12:02 OK 2_object_stats_trigger.sql (7.99ms)8012026/08/27 18:12:02 goose: up to current file version: 28022026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (8.82ms)8032026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200008042026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (9.13ms)8052026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (10.63ms)8062026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200008072026/08/27 18:12:02 OK 1_commit_pending_closure.sql (4.63ms)8082026-08-27 18:12:02.788 UTC [549] ERROR: relation "goose_db_version" does not exist at character 368092026-08-27 18:12:02.788 UTC [549] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8102026/08/27 18:12:02 OK 1_commit_pending_closure.sql (5.87ms)8112026/08/27 18:12:02 OK 20251218171726_add_pins.sql (7.7ms)8122026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (11.19ms)8132026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200008142026/08/27 18:12:02 OK 2_object_stats_trigger.sql (5.1ms)8152026/08/27 18:12:02 goose: up to current file version: 28162026/08/27 18:12:02 OK 2_object_stats_trigger.sql (3.04ms)8172026/08/27 18:12:02 goose: up to current file version: 28182026/08/27 18:12:02 OK 20241026095416_initial_model.sql (13.29ms)8192026/08/27 18:12:02 OK 1_commit_pending_closure.sql (4.83ms)8202026-08-27 18:12:02.795 UTC [550] ERROR: relation "goose_db_version" does not exist at character 368212026-08-27 18:12:02.795 UTC [550] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8222026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (5.89ms)8232026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200008242026/08/27 18:12:02 OK 20241026095416_initial_model.sql (15.75ms)8252026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (3.26ms)8262026-08-27 18:12:02.796 UTC [551] ERROR: relation "goose_db_version" does not exist at character 368272026-08-27 18:12:02.796 UTC [551] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8282026-08-27 18:12:02.797 UTC [552] ERROR: relation "goose_db_version" does not exist at character 368292026-08-27 18:12:02.797 UTC [552] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8302026/08/27 18:12:02 OK 20241026095416_initial_model.sql (14.35ms)8312026/08/27 18:12:02 OK 20241026095416_initial_model.sql (12.78ms)8322026/08/27 18:12:02 OK 20241026095416_initial_model.sql (12.4ms)8332026-08-27 18:12:02.799 UTC [553] ERROR: relation "goose_db_version" does not exist at character 368342026-08-27 18:12:02.799 UTC [553] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8352026/08/27 18:12:02 OK 2_object_stats_trigger.sql (4.4ms)8362026/08/27 18:12:02 goose: up to current file version: 28372026-08-27 18:12:02.799 UTC [554] ERROR: relation "goose_db_version" does not exist at character 368382026-08-27 18:12:02.799 UTC [554] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8392026-08-27 18:12:02.800 UTC [555] ERROR: relation "goose_db_version" does not exist at character 368402026-08-27 18:12:02.800 UTC [555] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8412026/08/27 18:12:02 OK 1_commit_pending_closure.sql (4.74ms)8422026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (5.03ms)8432026-08-27 18:12:02.801 UTC [556] ERROR: relation "goose_db_version" does not exist at character 368442026-08-27 18:12:02.801 UTC [556] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8452026/08/27 18:12:02 OK 20241026095416_initial_model.sql (14.42ms)8462026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (3.68ms)8472026/08/27 18:12:02 OK 20251218171726_add_pins.sql (7.41ms)8482026/08/27 18:12:02 OK 2_object_stats_trigger.sql (2.89ms)8492026/08/27 18:12:02 goose: up to current file version: 28502026/08/27 18:12:02 OK 20241026095416_initial_model.sql (17.42ms)8512026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (4.82ms)8522026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (4.74ms)8532026/08/27 18:12:02 OK 20251218171726_add_pins.sql (5.55ms)8542026/08/27 18:12:02 OK 20251218171726_add_pins.sql (4.96ms)8552026/08/27 18:12:02 OK 20251218171726_add_pins.sql (4.92ms)8562026/08/27 18:12:02 OK 20251218171726_add_pins.sql (5.06ms)8572026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (5.33ms)8582026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200008592026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (4.43ms)8602026/08/27 18:12:02 OK 1_commit_pending_closure.sql (3.53ms)8612026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (6.14ms)8622026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200008632026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (4.95ms)8642026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (6.8ms)8652026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200008662026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (5.51ms)8672026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200008682026/08/27 18:12:02 OK 20241026095416_initial_model.sql (15.7ms)8692026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (5.41ms)8702026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200008712026/08/27 18:12:02 OK 2_object_stats_trigger.sql (3ms)8722026/08/27 18:12:02 goose: up to current file version: 28732026/08/27 18:12:02 OK 1_commit_pending_closure.sql (4.39ms)8742026/08/27 18:12:02 OK 20241026095416_initial_model.sql (13.03ms)8752026/08/27 18:12:02 OK 20241026095416_initial_model.sql (12.53ms)8762026/08/27 18:12:02 OK 20251218171726_add_pins.sql (6.15ms)8772026/08/27 18:12:02 OK 1_commit_pending_closure.sql (3.37ms)8782026/08/27 18:12:02 OK 20251218171726_add_pins.sql (5.28ms)8792026/08/27 18:12:02 OK 1_commit_pending_closure.sql (3.52ms)8802026/08/27 18:12:02 OK 1_commit_pending_closure.sql (3.61ms)8812026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (3.54ms)8822026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (2.34ms)8832026/08/27 18:12:02 OK 2_object_stats_trigger.sql (2.59ms)8842026/08/27 18:12:02 OK 2_object_stats_trigger.sql (3.72ms)8852026/08/27 18:12:02 goose: up to current file version: 28862026/08/27 18:12:02 goose: up to current file version: 28872026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (3.66ms)8882026/08/27 18:12:02 OK 2_object_stats_trigger.sql (2.7ms)8892026/08/27 18:12:02 goose: up to current file version: 28902026/08/27 18:12:02 OK 20241026095416_initial_model.sql (14.78ms)8912026/08/27 18:12:02 OK 20241026095416_initial_model.sql (11.37ms)8922026/08/27 18:12:02 OK 2_object_stats_trigger.sql (2.63ms)8932026/08/27 18:12:02 goose: up to current file version: 28942026/08/27 18:12:02 OK 20241026095416_initial_model.sql (13.69ms)8952026/08/27 18:12:02 OK 20241026095416_initial_model.sql (13.89ms)896--- PASS: TestReadRedirectNar (0.31s)897=== CONT TestService_cleanupPendingClosuresHandler8982026/08/27 18:12:02 OK 20251218171726_add_pins.sql (4.83ms)8992026/08/27 18:12:02 OK 20241026095416_initial_model.sql (15.42ms)9002026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (6.3ms)9012026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200009022026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (7.02ms)9032026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200009042026/08/27 18:12:02 OK 20251218171726_add_pins.sql (6.25ms)9052026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (3.53ms)9062026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (3.6ms)9072026/08/27 18:12:02 OK 20251218171726_add_pins.sql (4.01ms)9082026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (2.2ms)9092026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (2.39ms)9102026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (1.39ms)9112026/08/27 18:12:02 OK 1_commit_pending_closure.sql (3.31ms)9122026/08/27 18:12:02 OK 20251218171726_add_pins.sql (4.46ms)9132026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (4.76ms)9142026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200009152026/08/27 18:12:02 OK 20251218171726_add_pins.sql (4.42ms)9162026/08/27 18:12:02 OK 1_commit_pending_closure.sql (4.62ms)9172026/08/27 18:12:02 OK 2_object_stats_trigger.sql (2.1ms)9182026/08/27 18:12:02 goose: up to current file version: 29192026/08/27 18:12:02 OK 20251218171726_add_pins.sql (4.91ms)9202026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (5.19ms)9212026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200009222026/08/27 18:12:02 OK 20251218171726_add_pins.sql (4.3ms)9232026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (5.34ms)9242026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200009252026/08/27 18:12:02 OK 20251218171726_add_pins.sql (5.16ms)9262026/08/27 18:12:02 OK 2_object_stats_trigger.sql (2.24ms)9272026/08/27 18:12:02 goose: up to current file version: 29282026/08/27 18:12:02 OK 1_commit_pending_closure.sql (2.42ms)9292026/08/27 18:12:02 OK 1_commit_pending_closure.sql (3.57ms)9302026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (3.67ms)9312026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200009322026/08/27 18:12:02 OK 1_commit_pending_closure.sql (3.16ms)9332026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (4.12ms)9342026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200009352026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (3.51ms)9362026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200009372026/08/27 18:12:02 OK 2_object_stats_trigger.sql (858.69µs)9382026/08/27 18:12:02 goose: up to current file version: 29392026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (3.27ms)9402026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200009412026/08/27 18:12:02 OK 2_object_stats_trigger.sql (1.04ms)9422026/08/27 18:12:02 goose: up to current file version: 29432026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (4.03ms)9442026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200009452026/08/27 18:12:02 OK 2_object_stats_trigger.sql (996.35µs)9462026/08/27 18:12:02 goose: up to current file version: 29472026/08/27 18:12:02 OK 1_commit_pending_closure.sql (1.28ms)9482026/08/27 18:12:02 OK 1_commit_pending_closure.sql (2.2ms)9492026/08/27 18:12:02 OK 1_commit_pending_closure.sql (1.9ms)9502026/08/27 18:12:02 OK 1_commit_pending_closure.sql (1.63ms)9512026/08/27 18:12:02 OK 2_object_stats_trigger.sql (696.81µs)9522026/08/27 18:12:02 goose: up to current file version: 29532026/08/27 18:12:02 OK 1_commit_pending_closure.sql (1.66ms)9542026/08/27 18:12:02 OK 2_object_stats_trigger.sql (853.87µs)9552026/08/27 18:12:02 goose: up to current file version: 29562026/08/27 18:12:02 OK 2_object_stats_trigger.sql (751.47µs)9572026/08/27 18:12:02 goose: up to current file version: 29582026/08/27 18:12:02 OK 2_object_stats_trigger.sql (798.33µs)9592026/08/27 18:12:02 goose: up to current file version: 29602026/08/27 18:12:02 OK 2_object_stats_trigger.sql (2.32ms)9612026/08/27 18:12:02 goose: up to current file version: 29622026/08/27 18:12:02 INFO Received uploads request method=POST path=/api/pending_closures963--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.35s)964=== CONT TestReadProxyDisabled9652026-08-27 18:12:02.900 UTC [563] ERROR: relation "goose_db_version" does not exist at character 369662026-08-27 18:12:02.900 UTC [563] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9672026/08/27 18:12:02 OK 20241026095416_initial_model.sql (11.66ms)9682026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (1.35ms)9692026/08/27 18:12:02 OK 20251218171726_add_pins.sql (3.18ms)9702026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (2.82ms)9712026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200009722026/08/27 18:12:02 OK 1_commit_pending_closure.sql (1.74ms)9732026/08/27 18:12:02 OK 2_object_stats_trigger.sql (852.19µs)9742026/08/27 18:12:02 goose: up to current file version: 29752026-08-27 18:12:02.931 UTC [564] ERROR: relation "goose_db_version" does not exist at character 369762026-08-27 18:12:02.931 UTC [564] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9772026/08/27 18:12:02 OK 20241026095416_initial_model.sql (9.22ms)9782026/08/27 18:12:02 OK 20251210153512_drop_unused_gin_index.sql (1.12ms)9792026/08/27 18:12:02 OK 20251218171726_add_pins.sql (2.51ms)9802026/08/27 18:12:02 OK 20260628120000_add_object_size_and_stats.sql (3.02ms)9812026/08/27 18:12:02 goose: successfully migrated database to version: 202606281200009822026/08/27 18:12:02 OK 1_commit_pending_closure.sql (1.62ms)9832026/08/27 18:12:02 OK 2_object_stats_trigger.sql (751.33µs)9842026/08/27 18:12:02 goose: up to current file version: 29852026/08/27 18:12:03 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9862026/08/27 18:12:03 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst987--- PASS: TestCompleteMultipartUnregistered (0.72s)988=== CONT TestUploadHandlersRejectOversizedBody9892026/08/27 18:12:03 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"990--- PASS: TestService_AuthMiddleware (0.75s)991=== CONT TestReadProxy404992--- PASS: TestService_Rustfstest (0.76s)993=== CONT TestUploadHandlersRejectInvalidKeys994=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info995=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info996=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal997=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal998=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key999=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1000=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1001=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1002=== CONT TestReadProxyInvalidPath10032026/08/27 18:12:03 INFO Received uploads request method=POST path=/api/pending_closures10042026/08/27 18:12:03 INFO Received uploads request method=POST path=/api/pending_closures10052026-08-27 18:12:03.330 UTC [586] ERROR: relation "goose_db_version" does not exist at character 3610062026-08-27 18:12:03.330 UTC [586] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1007--- PASS: TestReadProxyRangeRequest (0.83s)1008=== CONT TestIsValidUploadKey1009=== RUN TestIsValidUploadKey/narinfo1010=== PAUSE TestIsValidUploadKey/narinfo1011=== RUN TestIsValidUploadKey/nar_zst1012=== PAUSE TestIsValidUploadKey/nar_zst1013=== RUN TestIsValidUploadKey/nar_xz1014=== PAUSE TestIsValidUploadKey/nar_xz1015=== RUN TestIsValidUploadKey/nar_plain1016=== PAUSE TestIsValidUploadKey/nar_plain1017=== RUN TestIsValidUploadKey/listing1018=== PAUSE TestIsValidUploadKey/listing1019=== RUN TestIsValidUploadKey/build_log1020=== PAUSE TestIsValidUploadKey/build_log1021=== RUN TestIsValidUploadKey/build_log_home-manager_file1022=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1023=== RUN TestIsValidUploadKey/build_log_plus_in_name1024=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1025=== RUN TestIsValidUploadKey/build_log_question_mark1026=== PAUSE TestIsValidUploadKey/build_log_question_mark1027=== RUN TestIsValidUploadKey/build_log_equals1028=== PAUSE TestIsValidUploadKey/build_log_equals1029=== RUN TestIsValidUploadKey/realisation1030=== PAUSE TestIsValidUploadKey/realisation1031=== RUN TestIsValidUploadKey/realisation_plus_in_output1032=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1033=== RUN TestIsValidUploadKey/nix-cache-info1034=== PAUSE TestIsValidUploadKey/nix-cache-info1035=== RUN TestIsValidUploadKey/index.html1036=== PAUSE TestIsValidUploadKey/index.html1037=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1038=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1039=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1040=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1041=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1042=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1043=== RUN TestIsValidUploadKey/traversal10442026/08/27 18:12:03 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10452026/08/27 18:12:03 INFO Received uploads request method=POST path=/api/pending_closures10462026/08/27 18:12:03 OK 20241026095416_initial_model.sql (12.24ms)10472026/08/27 18:12:03 INFO Received uploads request method=POST path=/api/pending_closures1048=== PAUSE TestIsValidUploadKey/traversal1049=== RUN TestIsValidUploadKey/traversal_nar1050=== PAUSE TestIsValidUploadKey/traversal_nar1051=== RUN TestIsValidUploadKey/absolute1052=== PAUSE TestIsValidUploadKey/absolute1053=== RUN TestIsValidUploadKey/empty_key1054=== PAUSE TestIsValidUploadKey/empty_key1055=== RUN TestIsValidUploadKey/unknown_type1056=== PAUSE TestIsValidUploadKey/unknown_type1057=== CONT TestReadProxyNarStreaming1058--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.85s)1059=== CONT TestProxyWriteTimeout1060=== RUN TestProxyWriteTimeout/narinfo1061=== PAUSE TestProxyWriteTimeout/narinfo1062=== RUN TestProxyWriteTimeout/1_GiB_nar1063=== PAUSE TestProxyWriteTimeout/1_GiB_nar1064=== RUN TestProxyWriteTimeout/10_GiB_nar1065=== PAUSE TestProxyWriteTimeout/10_GiB_nar1066=== RUN TestProxyWriteTimeout/unknown_size1067=== PAUSE TestProxyWriteTimeout/unknown_size1068=== CONT TestObjectStatsTrigger10692026/08/27 18:12:03 OK 20251210153512_drop_unused_gin_index.sql (1.73ms)10702026-08-27 18:12:03.368 UTC [604] ERROR: relation "goose_db_version" does not exist at character 3610712026-08-27 18:12:03.368 UTC [604] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10722026/08/27 18:12:03 OK 20251218171726_add_pins.sql (4.24ms)1073=== NAME TestClientCADerivations1074 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations2861856866/001/store/rrjrfj02h7jrxcdz2h331n5sk5mpwka6-ca-test10752026/08/27 18:12:03 OK 20260628120000_add_object_size_and_stats.sql (8.9ms)10762026/08/27 18:12:03 goose: successfully migrated database to version: 2026062812000010772026/08/27 18:12:03 OK 20241026095416_initial_model.sql (19.02ms)10782026/08/27 18:12:03 OK 1_commit_pending_closure.sql (5.87ms)10792026/08/27 18:12:03 OK 20251210153512_drop_unused_gin_index.sql (3.57ms)10802026/08/27 18:12:03 OK 2_object_stats_trigger.sql (4.82ms)10812026/08/27 18:12:03 goose: up to current file version: 210822026/08/27 18:12:03 OK 20251218171726_add_pins.sql (8.42ms)10832026/08/27 18:12:03 OK 20260628120000_add_object_size_and_stats.sql (6.55ms)10842026/08/27 18:12:03 goose: successfully migrated database to version: 202606281200001085 client_ca_test.go:139: Found 1 dependencies (including self)10862026/08/27 18:12:03 OK 1_commit_pending_closure.sql (3.76ms)10872026/08/27 18:12:03 OK 2_object_stats_trigger.sql (2.14ms)10882026/08/27 18:12:03 goose: up to current file version: 210892026/08/27 18:12:03 INFO Received cleanup request method=DELETE path=/api/pending_closures10902026/08/27 18:12:03 INFO Aborted multipart uploads count=110912026-08-27 18:12:03.428 UTC [629] ERROR: relation "goose_db_version" does not exist at character 3610922026-08-27 18:12:03.428 UTC [629] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10932026/08/27 18:12:03 INFO Aborted multipart uploads count=01094--- PASS: TestMultipartCleanup (0.92s)1095=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle10962026/08/27 18:12:03 WARN Force mode enabled - objects will be deleted immediately without grace period10972026/08/27 18:12:03 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=010982026/08/27 18:12:03 INFO Vacuumed table table=pending_closures10992026/08/27 18:12:03 INFO Vacuumed table table=pending_objects11002026/08/27 18:12:03 INFO Vacuumed table table=multipart_uploads11012026/08/27 18:12:03 INFO Vacuumed table table=closures11022026/08/27 18:12:03 INFO Vacuumed table table=objects11032026-08-27 18:12:03.456 UTC [666] ERROR: relation "goose_db_version" does not exist at character 3611042026-08-27 18:12:03.456 UTC [666] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11052026/08/27 18:12:03 OK 20241026095416_initial_model.sql (14.53ms)1106--- PASS: TestGCMetrics (0.94s)1107=== CONT TestOrphanedObjectsGC11082026/08/27 18:12:03 OK 20251210153512_drop_unused_gin_index.sql (3.55ms)11092026/08/27 18:12:03 OK 20251218171726_add_pins.sql (5.77ms)11102026/08/27 18:12:03 OK 20260628120000_add_object_size_and_stats.sql (4.72ms)11112026/08/27 18:12:03 goose: successfully migrated database to version: 2026062812000011122026/08/27 18:12:03 OK 1_commit_pending_closure.sql (3.87ms)11132026/08/27 18:12:03 OK 2_object_stats_trigger.sql (4.08ms)11142026/08/27 18:12:03 goose: up to current file version: 211152026/08/27 18:12:03 OK 20241026095416_initial_model.sql (16.86ms)11162026/08/27 18:12:03 OK 20251210153512_drop_unused_gin_index.sql (4.09ms)1117=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1118=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1119=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1120=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1121=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1122=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1123=== CONT TestReadProxyConditionalGet11242026/08/27 18:12:03 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11252026/08/27 18:12:03 OK 20251218171726_add_pins.sql (7.31ms)1126=== NAME TestClientWithDependencies1127 client_integration_test.go:594: Built derivation: /build/TestClientWithDependencies3438456677/001/store/z3va1py9sa1rm8m6dsswr3hi9x10wxa8-test-script11282026/08/27 18:12:03 OK 20260628120000_add_object_size_and_stats.sql (6.99ms)11292026/08/27 18:12:03 goose: successfully migrated database to version: 2026062812000011302026/08/27 18:12:03 OK 1_commit_pending_closure.sql (3.08ms)11312026/08/27 18:12:03 OK 2_object_stats_trigger.sql (2.37ms)11322026/08/27 18:12:03 goose: up to current file version: 211332026-08-27 18:12:03.511 UTC [709] ERROR: relation "goose_db_version" does not exist at character 3611342026-08-27 18:12:03.511 UTC [709] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11352026/08/27 18:12:03 INFO Received uploads request method=POST path=/api/pending_closures11362026/08/27 18:12:03 OK 20241026095416_initial_model.sql (13.14ms)1137 client_integration_test.go:596: Found 1 dependencies (including self)11382026/08/27 18:12:03 OK 20251210153512_drop_unused_gin_index.sql (2.95ms)11392026/08/27 18:12:03 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11402026/08/27 18:12:03 INFO Uploading rrjrfj02h7jrxcdz2h331n5sk5mpwka6-ca-test (144B)11412026/08/27 18:12:03 OK 20251218171726_add_pins.sql (4.37ms)11422026/08/27 18:12:03 OK 20260628120000_add_object_size_and_stats.sql (5.87ms)11432026/08/27 18:12:03 goose: successfully migrated database to version: 2026062812000011442026-08-27 18:12:03.551 UTC [744] ERROR: relation "goose_db_version" does not exist at character 3611452026-08-27 18:12:03.551 UTC [744] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11462026/08/27 18:12:03 OK 1_commit_pending_closure.sql (3.14ms)11472026/08/27 18:12:03 OK 2_object_stats_trigger.sql (1.71ms)11482026/08/27 18:12:03 goose: up to current file version: 211492026-08-27 18:12:03.563 UTC [745] ERROR: relation "goose_db_version" does not exist at character 3611502026-08-27 18:12:03.563 UTC [745] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11512026/08/27 18:12:03 OK 20241026095416_initial_model.sql (9.73ms)11522026/08/27 18:12:03 OK 20251210153512_drop_unused_gin_index.sql (1.4ms)11532026/08/27 18:12:03 OK 20251218171726_add_pins.sql (3.57ms)11542026/08/27 18:12:03 OK 20260628120000_add_object_size_and_stats.sql (4.56ms)11552026/08/27 18:12:03 goose: successfully migrated database to version: 2026062812000011562026/08/27 18:12:03 OK 20241026095416_initial_model.sql (10.99ms)11572026/08/27 18:12:03 OK 1_commit_pending_closure.sql (2.41ms)11582026/08/27 18:12:03 OK 2_object_stats_trigger.sql (960.53µs)11592026/08/27 18:12:03 goose: up to current file version: 211602026/08/27 18:12:03 OK 20251210153512_drop_unused_gin_index.sql (1.41ms)11612026/08/27 18:12:03 OK 20251218171726_add_pins.sql (3.99ms)11622026/08/27 18:12:03 OK 20260628120000_add_object_size_and_stats.sql (3.82ms)11632026/08/27 18:12:03 goose: successfully migrated database to version: 202606281200001164--- PASS: TestGCBugBareHashReferences (1.07s)1165=== CONT TestService_healthCheckHandler11662026/08/27 18:12:03 OK 1_commit_pending_closure.sql (2.07ms)11672026/08/27 18:12:03 OK 2_object_stats_trigger.sql (948.37µs)11682026/08/27 18:12:03 goose: up to current file version: 211692026/08/27 18:12:03 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11702026/08/27 18:12:03 INFO Received uploads request method=POST path=/api/pending_closures11712026/08/27 18:12:03 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11722026/08/27 18:12:03 INFO Uploading z3va1py9sa1rm8m6dsswr3hi9x10wxa8-test-script (136B)11732026-08-27 18:12:03.661 UTC [783] ERROR: relation "goose_db_version" does not exist at character 3611742026-08-27 18:12:03.661 UTC [783] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11752026/08/27 18:12:03 OK 20241026095416_initial_model.sql (9.47ms)11762026/08/27 18:12:03 OK 20251210153512_drop_unused_gin_index.sql (1.24ms)11772026/08/27 18:12:03 OK 20251218171726_add_pins.sql (7.41ms)11782026/08/27 18:12:03 OK 20260628120000_add_object_size_and_stats.sql (2.56ms)11792026/08/27 18:12:03 goose: successfully migrated database to version: 2026062812000011802026/08/27 18:12:03 OK 1_commit_pending_closure.sql (1.74ms)11812026/08/27 18:12:03 OK 2_object_stats_trigger.sql (844.79µs)11822026/08/27 18:12:03 goose: up to current file version: 21183=== NAME TestClientIntegration1184 client_integration_test.go:277: Created store path: /build/TestClientIntegration2109238479/002/store/r2ylsb3f1iwagfczxlwfps07fsl355v8-test-file.txt11852026/08/27 18:12:03 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"11862026/08/27 18:12:03 WARN Failed to register uploaded object key=log/bq5c5d0mx1fis9fvspp52435p5cwinxz-ca-test.drv error="server returned 404: 404 page not found\n"11872026/08/27 18:12:03 WARN Failed to register uploaded object key=log/wvyjksx491rjd3j1v0s0szvkfx54agbq-test-script.drv error="server returned 404: 404 page not found\n"11882026/08/27 18:12:03 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"11892026/08/27 18:12:03 WARN Failed to register uploaded object key=rrjrfj02h7jrxcdz2h331n5sk5mpwka6.ls error="server returned 404: 404 page not found\n"11902026/08/27 18:12:03 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11912026/08/27 18:12:03 WARN Failed to register uploaded object key=z3va1py9sa1rm8m6dsswr3hi9x10wxa8.ls error="server returned 404: 404 page not found\n"11922026/08/27 18:12:03 INFO Signed narinfos id=1 count=111932026/08/27 18:12:03 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11942026/08/27 18:12:03 INFO Uploading 1 narinfos11952026/08/27 18:12:03 INFO Signed narinfos id=1 count=111962026/08/27 18:12:03 INFO Uploading 1 narinfos11972026/08/27 18:12:03 WARN Failed to register uploaded object key=rrjrfj02h7jrxcdz2h331n5sk5mpwka6.narinfo error="server returned 404: 404 page not found\n"11982026/08/27 18:12:03 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11992026/08/27 18:12:03 WARN Failed to register uploaded object key=z3va1py9sa1rm8m6dsswr3hi9x10wxa8.narinfo error="server returned 404: 404 page not found\n"12002026/08/27 18:12:03 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12012026/08/27 18:12:03 INFO Completed upload id=112022026/08/27 18:12:03 INFO Upload complete. (423ms)12032026/08/27 18:12:03 INFO Completed upload id=112042026/08/27 18:12:03 INFO Upload complete. (316ms)1205=== NAME TestClientCADerivations1206 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations2861856866/001/store/rrjrfj02h7jrxcdz2h331n5sk5mpwka6-ca-test1207 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1208 Compression: zstd1209 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1210 NarSize: 1441211 References: 1212 Deriver: /build/TestClientCADerivations2861856866/001/store/bq5c5d0mx1fis9fvspp52435p5cwinxz-ca-test.drv1213 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1214 client_ca_test.go:185: Checking for realisation files in S3...1215=== NAME TestClientWithDependencies1216 client_integration_test.go:598: Skipping nix copy test - isolated store (/build/TestClientWithDependencies3438456677/001/store) requires matching store prefix1217=== NAME TestClientCADerivations1218 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1219 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1220--- PASS: TestClientWithDependencies (1.37s)1221=== CONT TestNoClosurePushKeepsReferencedObjectsReachable12222026/08/27 18:12:03 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12232026-08-27 18:12:03.952 UTC [859] ERROR: relation "goose_db_version" does not exist at character 3612242026-08-27 18:12:03.952 UTC [859] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12252026/08/27 18:12:03 INFO Received uploads request method=POST path=/api/pending_closures12262026/08/27 18:12:03 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12272026/08/27 18:12:03 OK 20241026095416_initial_model.sql (7.81ms)12282026/08/27 18:12:03 INFO Uploading r2ylsb3f1iwagfczxlwfps07fsl355v8-test-file.txt (152B)12292026/08/27 18:12:03 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"12302026/08/27 18:12:03 OK 20251210153512_drop_unused_gin_index.sql (1.49ms)12312026/08/27 18:12:03 WARN Failed to register uploaded object key=r2ylsb3f1iwagfczxlwfps07fsl355v8.ls error="server returned 404: 404 page not found\n"12322026/08/27 18:12:03 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12332026/08/27 18:12:03 OK 20251218171726_add_pins.sql (2.39ms)12342026/08/27 18:12:03 INFO Signed narinfos id=1 count=112352026/08/27 18:12:03 INFO Uploading 1 narinfos12362026/08/27 18:12:03 OK 20260628120000_add_object_size_and_stats.sql (2.28ms)12372026/08/27 18:12:03 goose: successfully migrated database to version: 2026062812000012382026/08/27 18:12:03 WARN Failed to register uploaded object key=r2ylsb3f1iwagfczxlwfps07fsl355v8.narinfo error="server returned 404: 404 page not found\n"12392026/08/27 18:12:03 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12402026/08/27 18:12:03 OK 1_commit_pending_closure.sql (1.69ms)12412026/08/27 18:12:03 OK 2_object_stats_trigger.sql (715.73µs)12422026/08/27 18:12:03 goose: up to current file version: 212432026/08/27 18:12:03 INFO Completed upload id=112442026/08/27 18:12:03 INFO Upload complete. (93ms)1245=== NAME TestClientIntegration1246 client_integration_test.go:293: Retrieved narinfo from S3:1247 StorePath: /build/TestClientIntegration2109238479/002/store/r2ylsb3f1iwagfczxlwfps07fsl355v8-test-file.txt1248 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1249 Compression: zstd1250 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11251 NarSize: 1521252 References: 1253 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11254 client_integration_test.go:294: Retrieved .ls file from S3 (compressed size: 77 bytes)1255 client_integration_test.go:294: Decompressed .ls content (64 bytes):1256 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1257 client_integration_test.go:297: Testing garbage collection...12582026/08/27 18:12:04 INFO Starting cleanup of old closures method=DELETE path=/api/closures12592026/08/27 18:12:04 INFO Garbage collection started12602026/08/27 18:12:04 INFO Aborted multipart uploads count=012612026/08/27 18:12:04 WARN Force mode enabled - objects will be deleted immediately without grace period1262=== NAME TestClientCADerivations1263 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1264 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1265 error: binary cache 's3://bucket7?endpoint=http://localhost:40847®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations2861856866/001/store'1266 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11267--- PASS: TestClientCADerivations (1.53s)1268=== CONT TestServerTLSConfig1269=== RUN TestServerTLSConfig/no_client_CA1270=== PAUSE TestServerTLSConfig/no_client_CA1271=== RUN TestServerTLSConfig/missing_CA_file1272=== PAUSE TestServerTLSConfig/missing_CA_file1273=== RUN TestServerTLSConfig/not_a_PEM_file1274=== PAUSE TestServerTLSConfig/not_a_PEM_file1275=== CONT TestService_RequireScope_OIDC12762026/08/27 18:12:04 INFO OIDC provider initialized name=test12772026-08-27 18:12:04.120 UTC [995] ERROR: relation "goose_db_version" does not exist at character 3612782026-08-27 18:12:04.120 UTC [995] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12792026/08/27 18:12:04 OK 20241026095416_initial_model.sql (9.64ms)12802026/08/27 18:12:04 OK 20251210153512_drop_unused_gin_index.sql (1.46ms)12812026/08/27 18:12:04 OK 20251218171726_add_pins.sql (3.76ms)12822026/08/27 18:12:04 OK 20260628120000_add_object_size_and_stats.sql (2.93ms)12832026/08/27 18:12:04 goose: successfully migrated database to version: 2026062812000012842026/08/27 18:12:04 OK 1_commit_pending_closure.sql (1.81ms)12852026/08/27 18:12:04 OK 2_object_stats_trigger.sql (1.39ms)12862026/08/27 18:12:04 goose: up to current file version: 212872026/08/27 18:12:04 INFO Received uploads request method=POST path=/api/pending_closures12882026/08/27 18:12:04 INFO Received uploads request method=POST path=/api/pending_closures12892026/08/27 18:12:04 INFO Received uploads request method=POST path=/api/pending_closures12902026/08/27 18:12:04 INFO Received uploads request method=POST path=/api/pending_closures12912026/08/27 18:12:04 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1292--- PASS: TestReadProxyNarinfo (1.99s)1293=== CONT TestService_NativeMTLS12942026/08/27 18:12:04 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=M2E5ZDhhOTYtNGVhNi00OGUyLWI4OGMtNzFlNzIyODEzYjIwLmUxYmUwNWRjLTczZDktNGM5Yy05NWEzLWEyODMyM2E2ZGRkYXgxNzg3ODU0MzI0NDgxMzM3MTA212952026/08/27 18:12:04 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=M2E5ZDhhOTYtNGVhNi00OGUyLWI4OGMtNzFlNzIyODEzYjIwLmUxYmUwNWRjLTczZDktNGM5Yy05NWEzLWEyODMyM2E2ZGRkYXgxNzg3ODU0MzI0NDgxMzM3MTA2 parts=11296--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.01s)1297=== CONT TestCacheStatsHandler12982026-08-27 18:12:04.625 UTC [1010] ERROR: relation "goose_db_version" does not exist at character 3612992026-08-27 18:12:04.625 UTC [1010] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13002026-08-27 18:12:04.626 UTC [1011] ERROR: relation "goose_db_version" does not exist at character 3613012026-08-27 18:12:04.626 UTC [1011] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13022026/08/27 18:12:04 OK 20241026095416_initial_model.sql (11ms)13032026/08/27 18:12:04 OK 20241026095416_initial_model.sql (11.34ms)13042026/08/27 18:12:04 OK 20251210153512_drop_unused_gin_index.sql (1.29ms)13052026/08/27 18:12:04 OK 20251210153512_drop_unused_gin_index.sql (1.22ms)13062026/08/27 18:12:04 OK 20251218171726_add_pins.sql (3.44ms)13072026/08/27 18:12:04 OK 20251218171726_add_pins.sql (3.53ms)13082026/08/27 18:12:04 OK 20260628120000_add_object_size_and_stats.sql (3.72ms)13092026/08/27 18:12:04 goose: successfully migrated database to version: 2026062812000013102026/08/27 18:12:04 OK 20260628120000_add_object_size_and_stats.sql (3.69ms)13112026/08/27 18:12:04 goose: successfully migrated database to version: 2026062812000013122026/08/27 18:12:04 OK 1_commit_pending_closure.sql (1.78ms)13132026/08/27 18:12:04 OK 1_commit_pending_closure.sql (2.15ms)13142026/08/27 18:12:04 OK 2_object_stats_trigger.sql (1.01ms)13152026/08/27 18:12:04 goose: up to current file version: 213162026/08/27 18:12:04 OK 2_object_stats_trigger.sql (1.01ms)13172026/08/27 18:12:04 goose: up to current file version: 21318--- PASS: TestReadRedirectKeepsNarinfoProxied (2.30s)1319=== CONT TestMetricsInventory13202026/08/27 18:12:04 INFO Received uploads request method=POST path=/api/pending_closures13212026/08/27 18:12:04 INFO Received uploads request method=POST path=/api/pending_closures13222026/08/27 18:12:04 INFO Received uploads request method=POST path=/api/pending_closures1323--- PASS: TestReadProxyRootRedirectsToIndexHTML (2.31s)1324=== CONT TestCacheConfigHandler1325=== RUN TestCacheConfigHandler/full_config,_no_issuer1326=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1327=== RUN TestCacheConfigHandler/no_cache_url_configured1328=== PAUSE TestCacheConfigHandler/no_cache_url_configured1329=== RUN TestCacheConfigHandler/no_signing_keys1330=== PAUSE TestCacheConfigHandler/no_signing_keys1331=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1332=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1333=== CONT TestNARDeduplicationMetadataUploadBug13342026/08/27 18:12:04 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13352026-08-27 18:12:04.901 UTC [1041] ERROR: relation "goose_db_version" does not exist at character 3613362026-08-27 18:12:04.901 UTC [1041] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13372026/08/27 18:12:04 INFO Received cleanup request method=DELETE path=/api/pending_closures13382026/08/27 18:12:04 INFO Aborted multipart uploads count=013392026/08/27 18:12:04 INFO Received uploads request method=POST path=/api/pending_closures13402026/08/27 18:12:04 OK 20241026095416_initial_model.sql (11.06ms)13412026/08/27 18:12:04 OK 20251210153512_drop_unused_gin_index.sql (1.34ms)13422026/08/27 18:12:04 OK 20251218171726_add_pins.sql (4.34ms)13432026/08/27 18:12:04 INFO Received cleanup request method=DELETE path=/api/pending_closures1344=== NAME TestClientMultipleUploads1345 client_integration_test.go:339: Created store path 0: /build/TestClientMultipleUploads3588377634/001/store/a4dslpxwm00d6q03hf3xk1l9bsd8r933-test-file-0.txt13462026/08/27 18:12:04 INFO Aborted multipart uploads count=113472026-08-27 18:12:04.930 UTC [1072] ERROR: relation "goose_db_version" does not exist at character 3613482026-08-27 18:12:04.930 UTC [1072] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13492026/08/27 18:12:04 OK 20260628120000_add_object_size_and_stats.sql (3.98ms)13502026/08/27 18:12:04 goose: successfully migrated database to version: 2026062812000013512026/08/27 18:12:04 OK 1_commit_pending_closure.sql (1.85ms)13522026/08/27 18:12:04 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13532026/08/27 18:12:04 OK 2_object_stats_trigger.sql (931.85µs)13542026/08/27 18:12:04 goose: up to current file version: 213552026-08-27 18:12:04.934 UTC [563] ERROR: Closure does not exist: id=113562026-08-27 18:12:04.934 UTC [563] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE13572026-08-27 18:12:04.934 UTC [563] STATEMENT: -- name: CommitPendingClosure :exec1358 SELECT commit_pending_closure($1::bigint)1359 1360--- PASS: TestService_cleanupPendingClosuresHandler (2.11s)1361=== CONT TestService_ReadScope_PublicByDefault1362=== NAME TestPinProtectsFromGC1363 client_integration_test.go:647: Pinned store path: /build/TestPinProtectsFromGC228915107/001/store/dy0ggvnc7f2q2m0xlwwl05yd7vhwjfyq-pinned-file.txt1364 client_integration_test.go:648: Unpinned store path: /build/TestPinProtectsFromGC228915107/001/store/6ifc77vpzdnn5kqqspk96wih4kb3zpy1-unpinned-file.txt13652026/08/27 18:12:04 OK 20241026095416_initial_model.sql (12.62ms)13662026/08/27 18:12:04 OK 20251210153512_drop_unused_gin_index.sql (1.99ms)13672026/08/27 18:12:04 OK 20251218171726_add_pins.sql (4.8ms)13682026/08/27 18:12:04 OK 20260628120000_add_object_size_and_stats.sql (5.83ms)13692026/08/27 18:12:04 goose: successfully migrated database to version: 202606281200001370=== NAME TestClientMultipleUploads1371 client_integration_test.go:339: Created store path 1: /build/TestClientMultipleUploads3588377634/001/store/hgckrf8jb7sy45pmmps5hrzl0mrjvlh9-test-file-1.txt13722026/08/27 18:12:04 OK 1_commit_pending_closure.sql (5.36ms)13732026/08/27 18:12:04 OK 2_object_stats_trigger.sql (3.99ms)13742026/08/27 18:12:04 goose: up to current file version: 21375 client_integration_test.go:339: Created store path 2: /build/TestClientMultipleUploads3588377634/001/store/9yfnf7bal5x45mzkngczf9qij121y34v-test-file-2.txt13762026/08/27 18:12:05 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13772026-08-27 18:12:05.032 UTC [1163] ERROR: relation "goose_db_version" does not exist at character 3613782026-08-27 18:12:05.032 UTC [1163] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13792026/08/27 18:12:05 OK 20241026095416_initial_model.sql (10.4ms)13802026/08/27 18:12:05 OK 20251210153512_drop_unused_gin_index.sql (2.27ms)13812026/08/27 18:12:05 OK 20251218171726_add_pins.sql (4.4ms)13822026/08/27 18:12:05 OK 20260628120000_add_object_size_and_stats.sql (2.76ms)13832026/08/27 18:12:05 goose: successfully migrated database to version: 2026062812000013842026/08/27 18:12:05 OK 1_commit_pending_closure.sql (8.37ms)13852026/08/27 18:12:05 OK 2_object_stats_trigger.sql (1.18ms)13862026/08/27 18:12:05 goose: up to current file version: 213872026/08/27 18:12:05 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=M2E5ZDhhOTYtNGVhNi00OGUyLWI4OGMtNzFlNzIyODEzYjIwLjVkNDg5YWZkLWUxNGQtNDEwZS1hY2VjLTBlNTY0OGEyMTI0ZngxNzg3ODU0MzIzMzY1OTUyMTEx parts=1213882026/08/27 18:12:05 INFO Received uploads request method=POST path=/api/pending_closures1389--- PASS: TestCompletedNarNotReofferedAcrossClosures (2.56s)1390=== CONT TestCreatePendingClosureRejectsOversizedNAR13912026/08/27 18:12:05 INFO Received uploads request method=POST path=/api/pending_closures1392--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1393=== CONT TestGCTaskStore_CompletedAllowsNewTask1394--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1395=== CONT TestCacheConfigHandlerMaxNarSize1396--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1397=== CONT TestGracefulShutdownDrainsInflight13982026/08/27 18:12:05 INFO Starting HTTP server address=127.0.0.1:3431513992026/08/27 18:12:05 INFO Shutdown signal received, draining in-flight requests timeout=10s14002026/08/27 18:12:05 INFO Received uploads request method=POST path=/api/pending_closures14012026/08/27 18:12:05 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14022026/08/27 18:12:05 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14032026/08/27 18:12:05 INFO Uploading dy0ggvnc7f2q2m0xlwwl05yd7vhwjfyq-pinned-file.txt (128B)14042026/08/27 18:12:05 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14052026/08/27 18:12:05 WARN Failed to register uploaded object key=dy0ggvnc7f2q2m0xlwwl05yd7vhwjfyq.ls error="server returned 404: 404 page not found\n"14062026/08/27 18:12:05 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14072026/08/27 18:12:05 INFO Signed narinfos id=1 count=114082026/08/27 18:12:05 INFO Uploading 1 narinfos14092026/08/27 18:12:05 WARN Failed to register uploaded object key=dy0ggvnc7f2q2m0xlwwl05yd7vhwjfyq.narinfo error="server returned 404: 404 page not found\n"14102026/08/27 18:12:05 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14112026/08/27 18:12:05 INFO Completed upload id=114122026/08/27 18:12:05 INFO Upload complete. (134ms)14132026/08/27 18:12:05 INFO Received uploads request method=POST path=/api/pending_closures14142026/08/27 18:12:05 INFO Received uploads request method=POST path=/api/pending_closures14152026/08/27 18:12:05 INFO Received uploads request method=POST path=/api/pending_closures14162026/08/27 18:12:05 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)14172026/08/27 18:12:05 INFO Uploading a4dslpxwm00d6q03hf3xk1l9bsd8r933-test-file-0.txt (160B)14182026/08/27 18:12:05 INFO Uploading 9yfnf7bal5x45mzkngczf9qij121y34v-test-file-2.txt (160B)14192026/08/27 18:12:05 INFO Uploading hgckrf8jb7sy45pmmps5hrzl0mrjvlh9-test-file-1.txt (160B)14202026/08/27 18:12:05 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"14212026/08/27 18:12:05 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"14222026/08/27 18:12:05 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"1423--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1424=== CONT TestGenerateLandingPage14252026/08/27 18:12:05 WARN Failed to register uploaded object key=a4dslpxwm00d6q03hf3xk1l9bsd8r933.ls error="server returned 404: 404 page not found\n"14262026/08/27 18:12:05 WARN Failed to register uploaded object key=9yfnf7bal5x45mzkngczf9qij121y34v.ls error="server returned 404: 404 page not found\n"14272026/08/27 18:12:05 WARN Failed to register uploaded object key=hgckrf8jb7sy45pmmps5hrzl0mrjvlh9.ls error="server returned 404: 404 page not found\n"14282026/08/27 18:12:05 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign1429--- PASS: TestGenerateLandingPage (0.00s)1430=== CONT TestGCTaskStore_Fail1431--- PASS: TestGCTaskStore_Fail (0.00s)1432=== CONT TestService_readinessHandler14332026/08/27 18:12:05 INFO Signed narinfos id=3 count=114342026/08/27 18:12:05 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14352026/08/27 18:12:05 INFO Signed narinfos id=1 count=114362026/08/27 18:12:05 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14372026/08/27 18:12:05 INFO Signed narinfos id=2 count=114382026/08/27 18:12:05 INFO Uploading 3 narinfos14392026/08/27 18:12:05 WARN Failed to register uploaded object key=a4dslpxwm00d6q03hf3xk1l9bsd8r933.narinfo error="server returned 404: 404 page not found\n"14402026/08/27 18:12:05 WARN Failed to register uploaded object key=hgckrf8jb7sy45pmmps5hrzl0mrjvlh9.narinfo error="server returned 404: 404 page not found\n"14412026/08/27 18:12:05 WARN Failed to register uploaded object key=9yfnf7bal5x45mzkngczf9qij121y34v.narinfo error="server returned 404: 404 page not found\n"14422026/08/27 18:12:05 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14432026/08/27 18:12:05 INFO Completed upload id=114442026/08/27 18:12:05 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14452026/08/27 18:12:05 INFO Completed upload id=214462026/08/27 18:12:05 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete14472026/08/27 18:12:05 INFO Completed upload id=314482026/08/27 18:12:05 INFO Upload complete. (136ms)1449=== NAME TestClientMultipleUploads1450 client_integration_test.go:350: Uploaded 3 paths in 170.722335ms14512026/08/27 18:12:05 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1452--- PASS: TestClientMultipleUploads (2.67s)1453=== CONT TestGCTaskStore_PhaseUpdates1454--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1455=== CONT TestResurrectedObjectNotDeleted14562026/08/27 18:12:05 INFO Received uploads request method=POST path=/api/pending_closures14572026/08/27 18:12:05 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14582026/08/27 18:12:05 INFO Uploading 6ifc77vpzdnn5kqqspk96wih4kb3zpy1-unpinned-file.txt (128B)14592026-08-27 18:12:05.224 UTC [1296] ERROR: relation "goose_db_version" does not exist at character 3614602026-08-27 18:12:05.224 UTC [1296] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14612026/08/27 18:12:05 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"14622026/08/27 18:12:05 WARN Failed to register uploaded object key=6ifc77vpzdnn5kqqspk96wih4kb3zpy1.ls error="server returned 404: 404 page not found\n"14632026/08/27 18:12:05 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14642026/08/27 18:12:05 INFO Signed narinfos id=2 count=114652026/08/27 18:12:05 INFO Uploading 1 narinfos14662026/08/27 18:12:05 WARN Failed to register uploaded object key=6ifc77vpzdnn5kqqspk96wih4kb3zpy1.narinfo error="server returned 404: 404 page not found\n"14672026/08/27 18:12:05 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14682026/08/27 18:12:05 INFO Completed upload id=214692026/08/27 18:12:05 INFO Upload complete. (95ms)14702026/08/27 18:12:05 OK 20241026095416_initial_model.sql (9.7ms)14712026/08/27 18:12:05 OK 20251210153512_drop_unused_gin_index.sql (2.85ms)14722026/08/27 18:12:05 OK 20251218171726_add_pins.sql (3.89ms)14732026/08/27 18:12:05 OK 20260628120000_add_object_size_and_stats.sql (3.75ms)14742026/08/27 18:12:05 goose: successfully migrated database to version: 2026062812000014752026/08/27 18:12:05 OK 1_commit_pending_closure.sql (2.77ms)14762026/08/27 18:12:05 OK 2_object_stats_trigger.sql (987.03µs)14772026/08/27 18:12:05 goose: up to current file version: 214782026/08/27 18:12:05 INFO Received create pin request method=POST path=/api/pins/myapp14792026-08-27 18:12:05.276 UTC [1315] ERROR: relation "goose_db_version" does not exist at character 3614802026-08-27 18:12:05.276 UTC [1315] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14812026/08/27 18:12:05 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC228915107/001/store/dy0ggvnc7f2q2m0xlwwl05yd7vhwjfyq-pinned-file.txt narinfo_key=dy0ggvnc7f2q2m0xlwwl05yd7vhwjfyq.narinfo14822026/08/27 18:12:05 INFO Starting cleanup of old closures method=DELETE path=/api/closures14832026/08/27 18:12:05 INFO Garbage collection started14842026/08/27 18:12:05 INFO Aborted multipart uploads count=014852026/08/27 18:12:05 WARN Force mode enabled - objects will be deleted immediately without grace period14862026/08/27 18:12:05 OK 20241026095416_initial_model.sql (11.33ms)14872026/08/27 18:12:05 OK 20251210153512_drop_unused_gin_index.sql (1.49ms)14882026/08/27 18:12:05 OK 20251218171726_add_pins.sql (3.16ms)14892026/08/27 18:12:05 OK 20260628120000_add_object_size_and_stats.sql (2.97ms)14902026/08/27 18:12:05 goose: successfully migrated database to version: 2026062812000014912026/08/27 18:12:05 OK 1_commit_pending_closure.sql (1.94ms)14922026/08/27 18:12:05 OK 2_object_stats_trigger.sql (906.23µs)14932026/08/27 18:12:05 goose: up to current file version: 214942026/08/27 18:12:05 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14952026/08/27 18:12:05 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=M2E5ZDhhOTYtNGVhNi00OGUyLWI4OGMtNzFlNzIyODEzYjIwLmU1NmIyODdhLTIxNzItNDBlZi1iNTYyLTg4MzgxZTU5NzhiZngxNzg3ODU0MzI0NDcyMTEyNTY0 parts=1014962026/08/27 18:12:05 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14972026/08/27 18:12:05 INFO Completed upload id=114982026/08/27 18:12:05 INFO Received uploads request method=POST path=/api/pending_closures14992026/08/27 18:12:05 INFO Received uploads request method=POST path=/api/pending_closures15002026/08/27 18:12:05 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo15012026/08/27 18:12:05 WARN Found objects in DB but missing from S3, will re-upload count=11502--- PASS: TestService_verifyS3Integrity (2.91s)1503=== CONT TestReadProxyNarinfoAlreadyDecompressed15042026-08-27 18:12:05.496 UTC [1319] ERROR: relation "goose_db_version" does not exist at character 3615052026-08-27 18:12:05.496 UTC [1319] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15062026/08/27 18:12:05 OK 20241026095416_initial_model.sql (9.21ms)15072026/08/27 18:12:05 OK 20251210153512_drop_unused_gin_index.sql (1.42ms)15082026/08/27 18:12:05 OK 20251218171726_add_pins.sql (3.55ms)15092026/08/27 18:12:05 OK 20260628120000_add_object_size_and_stats.sql (3.56ms)15102026/08/27 18:12:05 goose: successfully migrated database to version: 2026062812000015112026/08/27 18:12:05 OK 1_commit_pending_closure.sql (1.74ms)1512--- PASS: TestReadProxyDisabled (2.66s)1513=== CONT TestService_ReadAuthMiddleware15142026/08/27 18:12:05 OK 2_object_stats_trigger.sql (820.61µs)15152026/08/27 18:12:05 goose: up to current file version: 21516--- PASS: TestReadProxy404 (2.31s)1517=== CONT TestNoClosurePushCreatesIndependentGCRoots15182026-08-27 18:12:05.604 UTC [1325] ERROR: relation "goose_db_version" does not exist at character 3615192026-08-27 18:12:05.604 UTC [1325] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15202026/08/27 18:12:05 OK 20241026095416_initial_model.sql (11.07ms)15212026/08/27 18:12:05 OK 20251210153512_drop_unused_gin_index.sql (2.51ms)15222026/08/27 18:12:05 OK 20251218171726_add_pins.sql (4.62ms)15232026/08/27 18:12:05 OK 20260628120000_add_object_size_and_stats.sql (4.4ms)15242026/08/27 18:12:05 goose: successfully migrated database to version: 2026062812000015252026/08/27 18:12:05 OK 1_commit_pending_closure.sql (3.66ms)15262026/08/27 18:12:05 OK 2_object_stats_trigger.sql (1.79ms)15272026/08/27 18:12:05 goose: up to current file version: 215282026-08-27 18:12:05.664 UTC [1326] ERROR: relation "goose_db_version" does not exist at character 3615292026-08-27 18:12:05.664 UTC [1326] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15302026/08/27 18:12:05 OK 20241026095416_initial_model.sql (9.45ms)15312026/08/27 18:12:05 OK 20251210153512_drop_unused_gin_index.sql (1.28ms)15322026/08/27 18:12:05 OK 20251218171726_add_pins.sql (3.38ms)15332026/08/27 18:12:05 OK 20260628120000_add_object_size_and_stats.sql (2.98ms)15342026/08/27 18:12:05 goose: successfully migrated database to version: 2026062812000015352026/08/27 18:12:05 OK 1_commit_pending_closure.sql (1.83ms)15362026/08/27 18:12:05 OK 2_object_stats_trigger.sql (889.55µs)15372026/08/27 18:12:05 goose: up to current file version: 215382026/08/27 18:12:05 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2022 objects-failed-to-delete=015392026/08/27 18:12:05 INFO Vacuumed table table=pending_closures15402026/08/27 18:12:05 INFO Vacuumed table table=pending_objects15412026/08/27 18:12:05 INFO Vacuumed table table=multipart_uploads15422026/08/27 18:12:05 INFO Vacuumed table table=closures15432026/08/27 18:12:05 INFO Vacuumed table table=objects1544=== NAME TestOrphanedObjectsGCStressTest1545 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1546--- PASS: TestReadProxyInvalidPath (2.71s)1547=== CONT TestService_AuthMiddleware_OIDC15482026/08/27 18:12:05 INFO OIDC provider initialized name=test1549=== NAME TestOrphanedObjectsGCStressTest1550 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion15512026/08/27 18:12:06 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2022 objects_failed=01552=== NAME TestClientIntegration1553 client_integration_test.go:304: Objects in database after GC:1554--- PASS: TestReadProxyNarStreaming (2.67s)1555=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1556=== NAME TestClientIntegration1557 client_integration_test.go:304: Successfully deleted all objects with GC --force1558--- PASS: TestObjectStatsTrigger (2.68s)1559=== CONT TestGCTaskStore_GetEmpty1560--- PASS: TestGCTaskStore_GetEmpty (0.00s)1561=== CONT TestGCTaskStore_GetReturnsLatest1562--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1563=== CONT TestGCTaskStore_ConflictDifferentParams1564--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1565=== CONT TestService_AuthMiddleware_MTLSProxyHeader1566--- PASS: TestClientIntegration (3.52s)1567=== CONT TestGCTaskStore_DeduplicateSameParams1568--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1569=== CONT TestReadProxyHead15702026/08/27 18:12:06 INFO Received uploads request method=POST path=/api/pending_closures15712026-08-27 18:12:06.067 UTC [1335] ERROR: relation "goose_db_version" does not exist at character 3615722026-08-27 18:12:06.067 UTC [1335] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15732026/08/27 18:12:06 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=015742026/08/27 18:12:06 INFO Vacuumed table table=pending_closures15752026/08/27 18:12:06 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15762026/08/27 18:12:06 OK 20241026095416_initial_model.sql (22.71ms)15772026/08/27 18:12:06 INFO Vacuumed table table=pending_objects15782026/08/27 18:12:06 INFO Vacuumed table table=multipart_uploads15792026/08/27 18:12:06 OK 20251210153512_drop_unused_gin_index.sql (3.8ms)1580--- PASS: TestService_healthCheckHandler (2.51s)1581=== CONT TestClientErrorHandling/InvalidStorePath1582--- PASS: TestReadProxyConditionalGet (2.62s)1583=== CONT TestClientErrorHandling/ServerNotAvailable15842026/08/27 18:12:06 INFO Vacuumed table table=closures15852026/08/27 18:12:06 OK 20251218171726_add_pins.sql (7.15ms)15862026/08/27 18:12:06 INFO Vacuumed table table=objects15872026/08/27 18:12:06 OK 20260628120000_add_object_size_and_stats.sql (7.57ms)15882026/08/27 18:12:06 goose: successfully migrated database to version: 2026062812000015892026/08/27 18:12:06 OK 1_commit_pending_closure.sql (3.62ms)15902026/08/27 18:12:06 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=M2E5ZDhhOTYtNGVhNi00OGUyLWI4OGMtNzFlNzIyODEzYjIwLmU2ZGEyNWJiLWM0NjgtNDc1Ni04OGM2LThhN2IwNWY4MGRkM3gxNzg3ODU0MzI0NDU5ODY4Mjc2 parts=1215912026/08/27 18:12:06 OK 2_object_stats_trigger.sql (1.05ms)15922026/08/27 18:12:06 goose: up to current file version: 21593--- PASS: TestRedundantMultipartUpload (3.61s)1594=== CONT TestClientErrorHandling/InvalidAuthToken15952026-08-27 18:12:06.128 UTC [1339] ERROR: relation "goose_db_version" does not exist at character 3615962026-08-27 18:12:06.128 UTC [1339] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15972026-08-27 18:12:06.134 UTC [1341] ERROR: relation "goose_db_version" does not exist at character 3615982026-08-27 18:12:06.134 UTC [1341] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15992026-08-27 18:12:06.138 UTC [1342] ERROR: relation "goose_db_version" does not exist at character 3616002026-08-27 18:12:06.138 UTC [1342] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16012026/08/27 18:12:06 OK 20241026095416_initial_model.sql (11ms)16022026/08/27 18:12:06 OK 20241026095416_initial_model.sql (14.85ms)16032026/08/27 18:12:06 OK 20251210153512_drop_unused_gin_index.sql (6.04ms)16042026/08/27 18:12:06 OK 20241026095416_initial_model.sql (14.92ms)16052026/08/27 18:12:06 OK 20251210153512_drop_unused_gin_index.sql (5.33ms)16062026/08/27 18:12:06 OK 20251210153512_drop_unused_gin_index.sql (3.4ms)16072026/08/27 18:12:06 OK 20251218171726_add_pins.sql (7.5ms)16082026/08/27 18:12:06 OK 20251218171726_add_pins.sql (7.14ms)16092026/08/27 18:12:06 OK 20251218171726_add_pins.sql (6.3ms)16102026/08/27 18:12:06 OK 20260628120000_add_object_size_and_stats.sql (5.44ms)16112026/08/27 18:12:06 goose: successfully migrated database to version: 2026062812000016122026/08/27 18:12:06 OK 20260628120000_add_object_size_and_stats.sql (5.99ms)16132026/08/27 18:12:06 goose: successfully migrated database to version: 2026062812000016142026/08/27 18:12:06 OK 1_commit_pending_closure.sql (11.74ms)16152026-08-27 18:12:06.186 UTC [1379] ERROR: relation "goose_db_version" does not exist at character 3616162026-08-27 18:12:06.186 UTC [1379] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1617=== RUN TestService_RequireScope_OIDC/builder_may_write1618=== PAUSE TestService_RequireScope_OIDC/builder_may_write1619=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1620=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1621=== RUN TestService_RequireScope_OIDC/ops_may_admin1622=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1623=== RUN TestService_RequireScope_OIDC/ops_may_not_write1624=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1625=== RUN TestService_RequireScope_OIDC/reader_may_not_write1626=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1627=== RUN TestService_RequireScope_OIDC/static_token_may_admin1628=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1629=== RUN TestService_RequireScope_OIDC/static_token_may_write1630=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1631=== RUN TestService_RequireScope_OIDC/reader_may_read1632=== PAUSE TestService_RequireScope_OIDC/reader_may_read1633=== RUN TestService_RequireScope_OIDC/writer_implies_read1634=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1635=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1636=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1637=== CONT TestResolveDBConnectionString/flag_wins1638=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1639=== CONT TestResolveDBConnectionString/nothing_configured1640=== CONT TestResolveDBConnectionString/missing_file_is_an_error16412026/08/27 18:12:06 OK 1_commit_pending_closure.sql (12.57ms)1642=== CONT TestResolveDBConnectionString/file_when_flag_empty16432026/08/27 18:12:06 OK 20260628120000_add_object_size_and_stats.sql (16.32ms)16442026/08/27 18:12:06 goose: successfully migrated database to version: 202606281200001645=== CONT TestParseSingleRange/none1646=== CONT TestIsValidCachePath/narinfo1647=== CONT TestParseSingleRange/start_far_past_EOF1648=== CONT TestParseSingleRange/start_past_EOF1649=== CONT TestParseSingleRange/single_byte1650=== CONT TestParseSingleRange/suffix_exceeds_size1651=== CONT TestParseSingleRange/suffix1652=== CONT TestParseSingleRange/end_clamped_to_size1653=== CONT TestParseSingleRange/open-ended1654=== CONT TestParseSingleRange/closed1655=== CONT TestParseSingleRange/malformed_end_before_start1656=== CONT TestParseSingleRange/malformed_both_empty1657=== CONT TestParseSingleRange/malformed_no_dash1658=== CONT TestParseSingleRange/multi-range_ignored1659--- PASS: TestResolveDBConnectionString (0.00s)1660 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1661 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1662 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1663 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1664 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1665=== CONT TestParseSingleRange/unknown_unit1666=== CONT TestIsValidCachePath/index.html1667=== CONT TestIsValidCachePath/short_hash1668=== CONT TestIsValidCachePath/wrong_extension1669--- PASS: TestParseSingleRange (0.00s)1670 --- PASS: TestParseSingleRange/none (0.00s)1671 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1672 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1673 --- PASS: TestParseSingleRange/single_byte (0.00s)1674 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1675 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1676 --- PASS: TestParseSingleRange/suffix (0.00s)1677 --- PASS: TestParseSingleRange/closed (0.00s)1678 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1679 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1680 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1681 --- PASS: TestParseSingleRange/open-ended (0.00s)1682 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1683 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1684=== CONT TestIsValidCachePath/leading_slash1685=== CONT TestIsValidCachePath/empty1686=== CONT TestIsValidCachePath/random_path1687=== CONT TestIsValidCachePath/invalid_char_u1688=== CONT TestIsValidCachePath/invalid_char_e1689=== CONT TestIsValidCachePath/traversal_in_middle16902026/08/27 18:12:06 OK 2_object_stats_trigger.sql (4.33ms)1691=== CONT TestIsValidCachePath/traversal_parent16922026/08/27 18:12:06 goose: up to current file version: 21693=== CONT TestIsValidCachePath/nar_uncompressed1694=== CONT TestIsValidCachePath/nix-cache-info1695=== CONT TestIsValidCachePath/realisation1696=== CONT TestIsValidCachePath/log1697=== CONT TestIsValidCachePath/ls1698=== CONT TestIsValidCachePath/nar_xz1699=== CONT TestIsValidCachePath/nar_bz21700=== CONT TestIsValidCachePath/nar_zst1701=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1702=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1703--- PASS: TestIsValidCachePath (0.00s)1704 --- PASS: TestIsValidCachePath/narinfo (0.00s)1705 --- PASS: TestIsValidCachePath/index.html (0.00s)1706 --- PASS: TestIsValidCachePath/short_hash (0.00s)1707 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1708 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1709 --- PASS: TestIsValidCachePath/empty (0.00s)1710 --- PASS: TestIsValidCachePath/random_path (0.00s)1711 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1712 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1713 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1714 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1715 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1716 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1717 --- PASS: TestIsValidCachePath/realisation (0.00s)1718 --- PASS: TestIsValidCachePath/log (0.00s)1719 --- PASS: TestIsValidCachePath/ls (0.00s)1720 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1721 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1722 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1723 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)17242026/08/27 18:12:06 INFO Received uploads request method=POST path=/1725=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17262026/08/27 18:12:06 INFO Received request for more parts method=POST path=/1727=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17282026/08/27 18:12:06 INFO Received complete multipart upload request method=POST path=/1729=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17302026/08/27 18:12:06 INFO Received uploads request method=POST path=/1731--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1732 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1733 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1734 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1735 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1736=== CONT TestIsValidUploadKey/narinfo1737=== CONT TestIsValidUploadKey/realisation_plus_in_output1738=== CONT TestIsValidUploadKey/nix-cache-info1739=== CONT TestIsValidUploadKey/realisation1740=== CONT TestIsValidUploadKey/build_log_equals1741=== CONT TestIsValidUploadKey/build_log_question_mark1742=== CONT TestIsValidUploadKey/build_log_plus_in_name1743=== CONT TestIsValidUploadKey/build_log_home-manager_file1744=== CONT TestIsValidUploadKey/build_log1745=== CONT TestIsValidUploadKey/listing1746=== CONT TestIsValidUploadKey/nar_plain1747=== CONT TestIsValidUploadKey/nar_xz1748=== CONT TestIsValidUploadKey/nar_zst1749=== CONT TestIsValidUploadKey/traversal1750=== CONT TestIsValidUploadKey/unknown_type1751=== CONT TestIsValidUploadKey/empty_key1752=== CONT TestIsValidUploadKey/absolute1753=== CONT TestIsValidUploadKey/traversal_nar1754=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1755=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1756=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1757=== CONT TestIsValidUploadKey/index.html1758=== CONT TestProxyWriteTimeout/narinfo1759--- PASS: TestIsValidUploadKey (0.02s)1760 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1761 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1762 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1763 --- PASS: TestIsValidUploadKey/realisation (0.00s)1764 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1765 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1766 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1767 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1768 --- PASS: TestIsValidUploadKey/build_log (0.00s)1769 --- PASS: TestIsValidUploadKey/listing (0.00s)1770 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1771 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1772 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1773 --- PASS: TestIsValidUploadKey/traversal (0.00s)1774 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1775 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1776 --- PASS: TestIsValidUploadKey/absolute (0.00s)1777 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1778 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1779 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1780 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1781 --- PASS: TestIsValidUploadKey/index.html (0.00s)1782=== CONT TestProxyWriteTimeout/10_GiB_nar1783=== CONT TestProxyWriteTimeout/unknown_size1784=== CONT TestProxyWriteTimeout/1_GiB_nar1785--- PASS: TestProxyWriteTimeout (0.00s)1786 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1787 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1788 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1789 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1790=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17912026/08/27 18:12:06 INFO Received request for more parts method=POST path=/17922026/08/27 18:12:06 OK 2_object_stats_trigger.sql (5.82ms)17932026/08/27 18:12:06 goose: up to current file version: 217942026/08/27 18:12:06 OK 1_commit_pending_closure.sql (8.45ms)17952026/08/27 18:12:06 WARN mTLS auth: subject not in bound subjects subject="CN=reader"17962026/08/27 18:12:06 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1797--- PASS: TestService_NativeMTLS (1.69s)1798=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17992026/08/27 18:12:06 INFO Received uploads request method=POST path=/18002026/08/27 18:12:06 OK 2_object_stats_trigger.sql (4.05ms)18012026/08/27 18:12:06 goose: up to current file version: 21802--- PASS: TestCacheStatsHandler (1.68s)1803=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18042026/08/27 18:12:06 INFO Received complete multipart upload request method=POST path=/18052026/08/27 18:12:06 OK 20241026095416_initial_model.sql (12.65ms)18062026-08-27 18:12:06.212 UTC [1398] ERROR: relation "goose_db_version" does not exist at character 3618072026-08-27 18:12:06.212 UTC [1398] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18082026/08/27 18:12:06 OK 20251210153512_drop_unused_gin_index.sql (2.08ms)18092026/08/27 18:12:06 OK 20251218171726_add_pins.sql (4.51ms)18102026/08/27 18:12:06 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-config18112026/08/27 18:12:06 OK 20260628120000_add_object_size_and_stats.sql (5.19ms)18122026/08/27 18:12:06 goose: successfully migrated database to version: 2026062812000018132026/08/27 18:12:06 OK 1_commit_pending_closure.sql (3.26ms)18142026/08/27 18:12:06 OK 2_object_stats_trigger.sql (1.04ms)18152026/08/27 18:12:06 goose: up to current file version: 218162026/08/27 18:12:06 OK 20241026095416_initial_model.sql (10.89ms)18172026/08/27 18:12:06 OK 20251210153512_drop_unused_gin_index.sql (2.11ms)1818--- PASS: TestMetricsInventory (1.42s)1819=== CONT TestServerTLSConfig/no_client_CA1820=== CONT TestServerTLSConfig/not_a_PEM_file1821=== CONT TestServerTLSConfig/missing_CA_file1822=== CONT TestCacheConfigHandler/full_config,_no_issuer1823--- PASS: TestServerTLSConfig (0.00s)1824 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1825 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1826 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1827=== CONT TestCacheConfigHandler/no_signing_keys1828=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1829=== CONT TestCacheConfigHandler/no_cache_url_configured1830--- PASS: TestCacheConfigHandler (0.00s)1831 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1832 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1833 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1834 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1835=== CONT TestService_RequireScope_OIDC/builder_may_write18362026/08/27 18:12:06 OK 20251218171726_add_pins.sql (3.96ms)18372026/08/27 18:12:06 INFO OIDC auth successful provider=test scopes=[write]1838=== CONT TestService_RequireScope_OIDC/reader_may_read18392026/08/27 18:12:06 OK 20260628120000_add_object_size_and_stats.sql (3.3ms)18402026/08/27 18:12:06 goose: successfully migrated database to version: 2026062812000018412026/08/27 18:12:06 INFO OIDC auth successful provider=test scopes=[read]1842=== CONT TestService_RequireScope_OIDC/static_token_may_write1843=== CONT TestService_RequireScope_OIDC/static_token_may_admin1844=== CONT TestService_RequireScope_OIDC/reader_may_not_write18452026/08/27 18:12:06 INFO OIDC auth successful provider=test scopes=[read]1846=== CONT TestService_RequireScope_OIDC/ops_may_not_write18472026/08/27 18:12:06 INFO OIDC auth successful provider=test scopes=[admin]1848=== CONT TestService_RequireScope_OIDC/ops_may_admin18492026/08/27 18:12:06 INFO OIDC auth successful provider=test scopes=[admin]1850=== CONT TestService_RequireScope_OIDC/builder_may_not_admin18512026/08/27 18:12:06 INFO OIDC auth successful provider=test scopes=[write]1852=== CONT TestService_RequireScope_OIDC/writer_implies_read18532026/08/27 18:12:06 INFO OIDC auth successful provider=test scopes=[write]1854=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1855--- PASS: TestService_RequireScope_OIDC (2.14s)1856 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1857 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1858 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1859 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1860 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1861 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1862 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1863 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1864 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1865 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)18662026/08/27 18:12:06 OK 1_commit_pending_closure.sql (5.5ms)18672026/08/27 18:12:06 OK 2_object_stats_trigger.sql (982.81µs)18682026/08/27 18:12:06 goose: up to current file version: 21869=== NAME TestNARDeduplicationMetadataUploadBug1870 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug1424344472/001/store/wmprkmrmp2k8lx09fg0nx3v7znhssiry-file1.txt18712026/08/27 18:12:06 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1872--- PASS: TestService_ReadScope_PublicByDefault (1.38s)18732026/08/27 18:12:06 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=183.575554ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1874=== NAME TestNoClosurePushKeepsReferencedObjectsReachable1875 no_closure_test.go:189: Built app=/build/TestNoClosurePushKeepsReferencedObjectsReachable4037963682/001/store/xgi8wlyhz133my5mg14lmawj9bkyd1si-niks3-app dep=/build/TestNoClosurePushKeepsReferencedObjectsReachable4037963682/001/store/njpmxqvdzw0awxmmysklnapgnzdgsx20-niks3-dep18762026/08/27 18:12:06 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"18772026/08/27 18:12:06 INFO Received uploads request method=POST path=/api/pending_closures18782026/08/27 18:12:06 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"18792026/08/27 18:12:06 INFO Received uploads request method=POST path=/api/pending_closures18802026/08/27 18:12:06 INFO Received uploads request method=POST path=/api/pending_closures18812026/08/27 18:12:06 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18822026/08/27 18:12:06 INFO Uploading wmprkmrmp2k8lx09fg0nx3v7znhssiry-file1.txt (160B)18832026/08/27 18:12:06 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)18842026/08/27 18:12:06 INFO Uploading njpmxqvdzw0awxmmysklnapgnzdgsx20-niks3-dep (136B)18852026/08/27 18:12:06 INFO Uploading xgi8wlyhz133my5mg14lmawj9bkyd1si-niks3-app (232B)18862026/08/27 18:12:06 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=418.382844ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config18872026/08/27 18:12:06 WARN Failed to register uploaded object key=log/jnxlgz79dh506xzhb3m862dagqdj532m-niks3-app.drv error="server returned 404: 404 page not found\n"18882026/08/27 18:12:06 WARN Failed to register uploaded object key=nar/05454p501z000dwcwlmljy9v5fn3ljggmy20b3ya8ndpkv0jxc12.nar.zst error="server returned 404: 404 page not found\n"18892026/08/27 18:12:06 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"18902026/08/27 18:12:06 WARN Failed to register uploaded object key=log/072mvv5f1k82h4y5kwbh2gjv9lalcgws-niks3-dep.drv error="server returned 404: 404 page not found\n"18912026/08/27 18:12:06 WARN Failed to register uploaded object key=nar/1y80sh8wjkir6ba1cv5m2p9zqii2r8wcr66mkdkgbcwcp24r3g57.nar.zst error="server returned 404: 404 page not found\n"18922026/08/27 18:12:06 WARN Failed to register uploaded object key=xgi8wlyhz133my5mg14lmawj9bkyd1si.ls error="server returned 404: 404 page not found\n"18932026/08/27 18:12:06 WARN Failed to register uploaded object key=wmprkmrmp2k8lx09fg0nx3v7znhssiry.ls error="server returned 404: 404 page not found\n"18942026/08/27 18:12:06 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18952026/08/27 18:12:06 WARN Failed to register uploaded object key=njpmxqvdzw0awxmmysklnapgnzdgsx20.ls error="server returned 404: 404 page not found\n"18962026/08/27 18:12:06 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign18972026/08/27 18:12:06 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18982026/08/27 18:12:06 INFO Signed narinfos id=1 count=118992026/08/27 18:12:06 INFO Uploading 1 narinfos19002026/08/27 18:12:06 INFO Signed narinfos id=2 count=119012026/08/27 18:12:06 INFO Signed narinfos id=1 count=119022026/08/27 18:12:06 INFO Uploading 2 narinfos19032026/08/27 18:12:06 WARN Failed to register uploaded object key=xgi8wlyhz133my5mg14lmawj9bkyd1si.narinfo error="server returned 404: 404 page not found\n"19042026/08/27 18:12:06 WARN Failed to register uploaded object key=wmprkmrmp2k8lx09fg0nx3v7znhssiry.narinfo error="server returned 404: 404 page not found\n"19052026/08/27 18:12:06 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19062026/08/27 18:12:06 WARN Failed to register uploaded object key=njpmxqvdzw0awxmmysklnapgnzdgsx20.narinfo error="server returned 404: 404 page not found\n"19072026/08/27 18:12:06 WARN readiness check failed error="closed pool"1908--- PASS: TestService_readinessHandler (1.43s)19092026/08/27 18:12:06 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete19102026/08/27 18:12:06 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19112026/08/27 18:12:06 INFO Completed upload id=119122026/08/27 18:12:06 INFO Upload complete. (251ms)19132026/08/27 18:12:06 INFO Completed upload id=119142026/08/27 18:12:06 INFO Completed upload id=219152026/08/27 18:12:06 INFO Upload complete. (217ms)1916=== NAME TestNARDeduplicationMetadataUploadBug1917 metadata_upload_test.go:54: Retrieved narinfo from S3:1918 StorePath: /build/TestNARDeduplicationMetadataUploadBug1424344472/001/store/wmprkmrmp2k8lx09fg0nx3v7znhssiry-file1.txt1919 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1920 Compression: zstd1921 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1922 NarSize: 1601923 References: 1924 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1925 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1926 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1927 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1928=== NAME TestOrphanedObjectsGCStressTest1929 orphaned_objects_gc_test.go:509: Stress test completed successfully:19302026/08/27 18:12:06 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1931 orphaned_objects_gc_test.go:510: - Active objects preserved: 201932 orphaned_objects_gc_test.go:511: - Objects deleted: 2101933 orphaned_objects_gc_test.go:512: - Total GC'd: 2101934--- PASS: TestOrphanedObjectsGCStressTest (4.10s)19352026/08/27 18:12:06 INFO Starting cleanup of old closures method=DELETE path=/api/closures19362026/08/27 18:12:06 INFO Garbage collection started1937--- PASS: TestReadProxyNarinfoAlreadyDecompressed (1.19s)1938=== NAME TestNARDeduplicationMetadataUploadBug1939 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug1424344472/001/store/fjr035vv0qzb528hiwfavz6zbhyksnl7-file2.txt19402026/08/27 18:12:06 INFO Aborted multipart uploads count=019412026/08/27 18:12:06 WARN Force mode enabled - objects will be deleted immediately without grace period1942--- PASS: TestService_ReadAuthMiddleware (1.11s)1943--- PASS: TestResurrectedObjectNotDeleted (1.45s)19442026/08/27 18:12:06 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=M2E5ZDhhOTYtNGVhNi00OGUyLWI4OGMtNzFlNzIyODEzYjIwLmI0YzdkNjJjLTMwOGItNGUyNy1iMDdkLWM1Y2I5NDA3NjU1MHgxNzg3ODU0MzI0ODIzNjkzMDI0 parts=1019452026/08/27 18:12:06 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19462026/08/27 18:12:06 INFO Completed upload id=119472026/08/27 18:12:06 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000019482026/08/27 18:12:06 INFO Received uploads request method=POST path=/api/pending_closures19492026/08/27 18:12:06 INFO Starting cleanup of old closures method=DELETE path=/api/closures1950=== NAME TestOrphanedObjectsGC1951 orphaned_objects_gc_test.go:290: GC Test Summary:1952 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1953 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1954 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1955 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1956 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1957--- PASS: TestOrphanedObjectsGC (3.19s)19582026/08/27 18:12:06 INFO Aborted multipart uploads count=01959=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1960=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1961=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1962=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1963=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1964=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1965=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1966=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1967=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1968=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected1969=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured19702026/08/27 18:12:06 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]1971=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19722026/08/27 18:12:06 WARN Authentication failed token_preview=eyJhbGciOi...XZjyqqJn8Q token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]19732026/08/27 18:12:06 INFO OIDC auth successful provider=test scopes=[write]19742026/08/27 18:12:06 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=01975--- PASS: TestService_AuthMiddleware_OIDC (0.67s)1976 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1977 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1978 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)1979 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)19802026/08/27 18:12:06 INFO Vacuumed table table=pending_closures1981--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.63s)19822026/08/27 18:12:06 INFO Vacuumed table table=pending_objects19832026/08/27 18:12:06 INFO Vacuumed table table=multipart_uploads19842026/08/27 18:12:06 INFO Vacuumed table table=closures19852026/08/27 18:12:06 INFO Vacuumed table table=objects19862026/08/27 18:12:06 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001987--- PASS: TestService_createPendingClosureHandler (4.17s)19882026/08/27 18:12:06 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1989--- PASS: TestReadProxyHead (0.67s)19902026/08/27 18:12:06 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19912026/08/27 18:12:06 WARN mTLS auth: bound subjects configured but subject DN unavailable19922026/08/27 18:12:06 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1993--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.68s)19942026/08/27 18:12:06 INFO Received uploads request method=POST path=/api/pending_closures19952026/08/27 18:12:06 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19962026/08/27 18:12:06 WARN Failed to register uploaded object key=fjr035vv0qzb528hiwfavz6zbhyksnl7.ls error="server returned 404: 404 page not found\n"19972026/08/27 18:12:06 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign19982026/08/27 18:12:06 INFO Signed narinfos id=2 count=119992026/08/27 18:12:06 INFO Uploading 1 narinfos20002026/08/27 18:12:06 WARN Failed to register uploaded object key=fjr035vv0qzb528hiwfavz6zbhyksnl7.narinfo error="server returned 404: 404 page not found\n"20012026/08/27 18:12:06 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete20022026/08/27 18:12:06 INFO Completed upload id=220032026/08/27 18:12:06 INFO Upload complete. (84ms)2004=== NAME TestNARDeduplicationMetadataUploadBug2005 metadata_upload_test.go:76: Retrieved narinfo from S3:2006 StorePath: /build/TestNARDeduplicationMetadataUploadBug1424344472/001/store/fjr035vv0qzb528hiwfavz6zbhyksnl7-file2.txt2007 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2008 Compression: zstd2009 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2010 NarSize: 1602011 References: 2012 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2013 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2014 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2015 {"version":1,"root":{"type":"regular","size":44}}2016--- PASS: TestNARDeduplicationMetadataUploadBug (1.91s)20172026/08/27 18:12:06 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"20182026/08/27 18:12:06 INFO Received uploads request method=POST path=/api/pending_closures20192026/08/27 18:12:06 INFO Received uploads request method=POST path=/api/pending_closures20202026/08/27 18:12:06 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)20212026/08/27 18:12:06 INFO Uploading a024zcdmfjjxdq7f8gsyqpab44vcgh8c-output.txt (128B)20222026/08/27 18:12:06 INFO Uploading kc7rngrd9r46mc1fd4g8wkwvz32jd9lx-build-dep.txt (144B)20232026/08/27 18:12:06 WARN Failed to register uploaded object key=nar/0zf002pclvicyfpcvpn82kby55jrx8bs7cyhccsd04byqa021ymm.nar.zst error="server returned 404: 404 page not found\n"20242026/08/27 18:12:06 WARN Failed to register uploaded object key=nar/0xq2m43h3xd3qik9rvppw8bj4fm7a4vai6y4la58ivfa7lmzcrr1.nar.zst error="server returned 404: 404 page not found\n"20252026/08/27 18:12:06 WARN Failed to register uploaded object key=a024zcdmfjjxdq7f8gsyqpab44vcgh8c.ls error="server returned 404: 404 page not found\n"20262026/08/27 18:12:06 WARN Failed to register uploaded object key=kc7rngrd9r46mc1fd4g8wkwvz32jd9lx.ls error="server returned 404: 404 page not found\n"20272026/08/27 18:12:06 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign20282026/08/27 18:12:06 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign20292026/08/27 18:12:06 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"20302026/08/27 18:12:06 INFO Signed narinfos id=1 count=120312026/08/27 18:12:06 INFO Signed narinfos id=2 count=120322026/08/27 18:12:06 INFO Uploading 2 narinfos20332026/08/27 18:12:06 WARN Failed to register uploaded object key=kc7rngrd9r46mc1fd4g8wkwvz32jd9lx.narinfo error="server returned 404: 404 page not found\n"20342026/08/27 18:12:06 WARN Failed to register uploaded object key=a024zcdmfjjxdq7f8gsyqpab44vcgh8c.narinfo error="server returned 404: 404 page not found\n"20352026/08/27 18:12:06 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20362026/08/27 18:12:06 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete20372026/08/27 18:12:06 INFO Completed upload id=220382026/08/27 18:12:06 INFO Completed upload id=120392026/08/27 18:12:06 INFO Upload complete. (88ms)20402026/08/27 18:12:06 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20412026/08/27 18:12:06 INFO Starting cleanup of old closures method=DELETE path=/api/closures20422026/08/27 18:12:06 INFO Garbage collection started20432026/08/27 18:12:06 INFO Aborted multipart uploads count=020442026/08/27 18:12:06 WARN Force mode enabled - objects will be deleted immediately without grace period20452026/08/27 18:12:06 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=020462026/08/27 18:12:06 INFO Vacuumed table table=pending_closures20472026/08/27 18:12:06 INFO Vacuumed table table=pending_objects20482026/08/27 18:12:06 INFO Vacuumed table table=multipart_uploads20492026/08/27 18:12:06 INFO Vacuumed table table=closures20502026/08/27 18:12:06 INFO Vacuumed table table=objects20512026/08/27 18:12:06 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=796.433388ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20522026/08/27 18:12:07 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=020532026/08/27 18:12:07 INFO Vacuumed table table=pending_closures20542026/08/27 18:12:07 INFO Vacuumed table table=pending_objects20552026/08/27 18:12:07 INFO Vacuumed table table=multipart_uploads20562026/08/27 18:12:07 INFO Vacuumed table table=closures20572026/08/27 18:12:07 INFO Vacuumed table table=objects20582026/08/27 18:12:07 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02059=== NAME TestPinProtectsFromGC2060 client_integration_test.go:710: Pin successfully protected closure from garbage collection2061--- PASS: TestPinProtectsFromGC (4.77s)2062--- PASS: TestUploadHandlersRejectOversizedBody (0.25s)2063 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.08s)2064 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.11s)2065 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (1.38s)20662026/08/27 18:12:07 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.644470593s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20672026/08/27 18:12:08 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=0 objects_marked=2 objects_deleted=2002 objects_failed=02068--- PASS: TestNoClosurePushKeepsReferencedObjectsReachable (4.74s)2069--- PASS: TestNoClosurePushCreatesIndependentGCRoots (3.30s)20702026/08/27 18:12:09 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"20712026/08/27 18:12:09 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_closures20722026/08/27 18:12:09 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=201.845788ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20732026/08/27 18:12:09 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=376.741331ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20742026/08/27 18:12:10 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=757.646067ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20752026/08/27 18:12:10 WARN Rate limiter enabled after throttle name=s3-test rate=520762026/08/27 18:12:10 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2077=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2078 throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=102079 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002080--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (6.77s)20812026/08/27 18:12:10 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.596034493s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2082--- PASS: TestClientErrorHandling (0.00s)2083 --- PASS: TestClientErrorHandling/InvalidStorePath (0.65s)2084 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.74s)2085 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.34s)2086PASS2087{"timestamp":"2026-08-27T18:12:12.448465072Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:50304","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(318)"}20882026-08-27 18:12:12.762 UTC [111] LOG: received smart shutdown request20892026-08-27 18:12:12.767 UTC [111] LOG: background worker "logical replication launcher" (PID 121) exited with exit code 120902026-08-27 18:12:12.778 UTC [116] LOG: shutting down20912026-08-27 18:12:12.778 UTC [116] LOG: checkpoint starting: shutdown immediate20922026-08-27 18:12:13.883 UTC [116] LOG: checkpoint complete: wrote 11751 buffers (71.7%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 15 recycled; write=0.208 s, sync=0.887 s, total=1.106 s; sync files=17486, longest=0.002 s, average=0.001 s; distance=240890 kB, estimate=240890 kB; lsn=0/102A2880, redo lsn=0/102A288020932026-08-27 18:12:13.974 UTC [111] LOG: database system is shut down2094Running OIDC tests...2095=== RUN TestGlobMatch2096=== PAUSE TestGlobMatch2097=== RUN TestAudienceForIssuer2098=== PAUSE TestAudienceForIssuer2099=== RUN TestValidateToken_ValidToken2100=== PAUSE TestValidateToken_ValidToken2101=== RUN TestValidateToken_WrongAudience2102=== PAUSE TestValidateToken_WrongAudience2103=== RUN TestValidateToken_Expired2104=== PAUSE TestValidateToken_Expired2105=== RUN TestValidateToken_BoundClaimsMismatch2106=== PAUSE TestValidateToken_BoundClaimsMismatch2107=== RUN TestValidateToken_BoundSubjectMismatch2108=== PAUSE TestValidateToken_BoundSubjectMismatch2109=== RUN TestValidateToken_MultipleProviders2110=== PAUSE TestValidateToken_MultipleProviders2111=== RUN TestValidateToken_NoMatchingProvider2112=== PAUSE TestValidateToken_NoMatchingProvider2113=== RUN TestValidateToken_KubernetesServiceAccount2114=== PAUSE TestValidateToken_KubernetesServiceAccount2115=== RUN TestNewValidator_KubernetesRequiresCA2116=== PAUSE TestNewValidator_KubernetesRequiresCA2117=== RUN TestScopes_LegacyProviderDefaultsToWrite2118=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2119=== RUN TestScopes_Rules2120=== PAUSE TestScopes_Rules2121=== RUN TestScopes_ConfigValidation2122=== PAUSE TestScopes_ConfigValidation2123=== CONT TestGlobMatch2124=== CONT TestScopes_LegacyProviderDefaultsToWrite2125=== CONT TestValidateToken_MultipleProviders2126=== CONT TestValidateToken_Expired2127=== RUN TestGlobMatch/foo_foo2128=== PAUSE TestGlobMatch/foo_foo2129=== RUN TestGlobMatch/foo_bar2130=== PAUSE TestGlobMatch/foo_bar2131=== RUN TestGlobMatch/*_2132=== PAUSE TestGlobMatch/*_2133=== RUN TestGlobMatch/*_anything2134=== PAUSE TestGlobMatch/*_anything2135=== RUN TestGlobMatch/foo*_foo2136=== PAUSE TestGlobMatch/foo*_foo2137=== RUN TestGlobMatch/foo*_foobar2138=== PAUSE TestGlobMatch/foo*_foobar2139=== RUN TestGlobMatch/foo*_bar2140=== PAUSE TestGlobMatch/foo*_bar2141=== RUN TestGlobMatch/*bar_bar2142=== PAUSE TestGlobMatch/*bar_bar2143=== RUN TestGlobMatch/*bar_foobar2144=== PAUSE TestGlobMatch/*bar_foobar2145=== RUN TestGlobMatch/*bar_foo2146=== PAUSE TestGlobMatch/*bar_foo2147=== RUN TestGlobMatch/foo*bar_foobar2148=== PAUSE TestGlobMatch/foo*bar_foobar2149=== RUN TestGlobMatch/foo*bar_foo123bar2150=== PAUSE TestGlobMatch/foo*bar_foo123bar2151=== RUN TestGlobMatch/foo*bar_foobarbaz2152=== CONT TestValidateToken_WrongAudience2153=== CONT TestValidateToken_ValidToken2154=== CONT TestAudienceForIssuer2155--- PASS: TestAudienceForIssuer (0.00s)2156=== CONT TestValidateToken_BoundSubjectMismatch2157=== CONT TestScopes_ConfigValidation2158=== CONT TestValidateToken_KubernetesServiceAccount2159=== CONT TestNewValidator_KubernetesRequiresCA2160=== CONT TestScopes_Rules2161=== CONT TestValidateToken_BoundClaimsMismatch2162=== CONT TestValidateToken_NoMatchingProvider2163=== PAUSE TestGlobMatch/foo*bar_foobarbaz2164=== RUN TestGlobMatch/*/*_foo/bar2165--- PASS: TestScopes_ConfigValidation (0.00s)2166=== PAUSE TestGlobMatch/*/*_foo/bar2167=== RUN TestGlobMatch/*/*_foo2168=== PAUSE TestGlobMatch/*/*_foo2169=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2170=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2171=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02172=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02173=== RUN TestGlobMatch/refs/*/main_refs/heads/main2174=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2175=== RUN TestGlobMatch/fo?_foo2176=== PAUSE TestGlobMatch/fo?_foo2177=== RUN TestGlobMatch/fo?_fo2178=== PAUSE TestGlobMatch/fo?_fo2179=== RUN TestGlobMatch/fo?_fooo2180=== PAUSE TestGlobMatch/fo?_fooo2181=== RUN TestGlobMatch/?oo_foo2182=== PAUSE TestGlobMatch/?oo_foo2183=== RUN TestGlobMatch/?oo_boo2184=== PAUSE TestGlobMatch/?oo_boo2185=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2186=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2187=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main21882026/08/27 18:12:15 INFO OIDC provider initialized name=test2189=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2190=== CONT TestGlobMatch/foo_foo21912026/08/27 18:12:15 INFO OIDC provider initialized name=test2192=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2193=== CONT TestGlobMatch/foo*bar_foobar2194=== CONT TestGlobMatch/fo?_fooo2195=== CONT TestGlobMatch/?oo_foo2196=== CONT TestGlobMatch/*_anything21972026/08/27 18:12:15 INFO OIDC provider initialized name=test2198=== CONT TestGlobMatch/foo*bar_foobarbaz21992026/08/27 18:12:15 INFO OIDC provider initialized name=test2200=== CONT TestGlobMatch/*_2201=== CONT TestGlobMatch/*bar_bar2202=== CONT TestGlobMatch/*/*_foo22032026/08/27 18:12:15 INFO OIDC provider initialized name=provider12204=== CONT TestGlobMatch/fo?_fo2205=== CONT TestGlobMatch/*/*_foo/bar2206=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main22072026/08/27 18:12:15 INFO OIDC provider initialized name=test2208=== CONT TestGlobMatch/refs/*/main_refs/heads/main2209=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02210=== CONT TestGlobMatch/foo*_bar2211=== CONT TestGlobMatch/?oo_boo22122026/08/27 18:12:15 INFO OIDC provider initialized name=provider12213=== CONT TestGlobMatch/foo*bar_foo123bar2214=== CONT TestGlobMatch/fo?_foo22152026/08/27 18:12:15 INFO OIDC provider initialized name=test2216=== CONT TestGlobMatch/*bar_foo2217=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2218=== CONT TestGlobMatch/*bar_foobar2219=== CONT TestGlobMatch/foo*_foobar2220=== CONT TestGlobMatch/foo*_foo2221=== CONT TestGlobMatch/foo_bar22222026/08/27 18:12:15 INFO OIDC provider initialized name=test2223--- PASS: TestGlobMatch (0.01s)2224 --- PASS: TestGlobMatch/foo_foo (0.00s)2225 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2226 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2227 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2228 --- PASS: TestGlobMatch/?oo_foo (0.00s)2229 --- PASS: TestGlobMatch/*_anything (0.00s)2230 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2231 --- PASS: TestGlobMatch/*_ (0.00s)2232 --- PASS: TestGlobMatch/*bar_bar (0.00s)2233 --- PASS: TestGlobMatch/*/*_foo (0.00s)2234 --- PASS: TestGlobMatch/fo?_fo (0.00s)2235 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2236 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2237 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2238 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2239 --- PASS: TestGlobMatch/foo*_bar (0.00s)2240 --- PASS: TestGlobMatch/?oo_boo (0.00s)2241 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2242 --- PASS: TestGlobMatch/fo?_foo (0.00s)2243 --- PASS: TestGlobMatch/*bar_foo (0.00s)2244 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2245 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2246 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2247 --- PASS: TestGlobMatch/foo*_foo (0.00s)2248 --- PASS: TestGlobMatch/foo_bar (0.00s)22492026/08/27 18:12:15 INFO OIDC provider initialized name=provider22250--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)2251--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.01s)2252--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)2253--- PASS: TestValidateToken_ValidToken (0.01s)2254--- PASS: TestValidateToken_NoMatchingProvider (0.01s)22552026/08/27 18:12:15 INFO OIDC provider initialized name=kubernetes2256--- PASS: TestValidateToken_MultipleProviders (0.01s)2257--- PASS: TestValidateToken_Expired (0.01s)2258--- PASS: TestValidateToken_WrongAudience (0.01s)2259--- PASS: TestValidateToken_KubernetesServiceAccount (0.02s)22602026/08/27 18:12:15 http: TLS handshake error from 127.0.0.1:54414: remote error: tls: bad certificate2261--- PASS: TestNewValidator_KubernetesRequiresCA (0.02s)2262--- PASS: TestScopes_Rules (0.02s)2263PASS2264Running hook tests...2265=== RUN TestSendPathsEmpty2266=== PAUSE TestSendPathsEmpty2267=== RUN TestQueueEnqueueAndFetch2268=== PAUSE TestQueueEnqueueAndFetch2269=== RUN TestQueueDeduplication2270=== PAUSE TestQueueDeduplication2271=== RUN TestQueueRemove2272=== PAUSE TestQueueRemove2273=== RUN TestQueueFetchBatchLimit2274=== PAUSE TestQueueFetchBatchLimit2275=== RUN TestQueueRetryMovesToBack2276=== PAUSE TestQueueRetryMovesToBack2277=== RUN TestQueueFetchRemoveLifecycle2278=== PAUSE TestQueueFetchRemoveLifecycle2279=== RUN TestQueueConcurrentWriters2280=== PAUSE TestQueueConcurrentWriters2281=== RUN TestQueueRemoveLargeClosure2282=== PAUSE TestQueueRemoveLargeClosure2283=== RUN TestServerClientIntegration2284=== PAUSE TestServerClientIntegration2285=== RUN TestServerQueueError2286=== PAUSE TestServerQueueError2287=== RUN TestGetListenerSocketActivation2288 server_test.go:210: === RUN TestGetListenerSocketActivation2289 --- PASS: TestGetListenerSocketActivation (0.00s)2290 PASS2291 2292--- PASS: TestGetListenerSocketActivation (0.01s)2293=== RUN TestDrainIsolatesPoisonPath2294=== PAUSE TestDrainIsolatesPoisonPath2295=== RUN TestRunNotBlockedByPoisonHead2296=== PAUSE TestRunNotBlockedByPoisonHead2297=== RUN TestDrainGivesUpWhenServerDown2298=== PAUSE TestDrainGivesUpWhenServerDown2299=== RUN TestFailedPathPrunedByLaterClosure2300=== PAUSE TestFailedPathPrunedByLaterClosure2301=== RUN TestWorkerUploadsAndRemoves2302=== PAUSE TestWorkerUploadsAndRemoves2303=== RUN TestWorkerSkipsGCdPaths2304=== PAUSE TestWorkerSkipsGCdPaths2305=== RUN TestWorkerPrunesClosureDeps2306=== PAUSE TestWorkerPrunesClosureDeps2307=== RUN TestDrainTimeout2308=== PAUSE TestDrainTimeout2309=== CONT TestSendPathsEmpty2310=== CONT TestServerQueueError2311--- PASS: TestSendPathsEmpty (0.00s)2312=== CONT TestServerClientIntegration2313=== CONT TestQueueRemoveLargeClosure2314=== CONT TestQueueConcurrentWriters2315=== CONT TestQueueFetchRemoveLifecycle2316=== CONT TestQueueRetryMovesToBack2317=== CONT TestQueueFetchBatchLimit23182026/08/27 18:12:15 ERROR Failed to queue paths error="permission denied" count=12319=== CONT TestQueueRemove2320=== CONT TestQueueDeduplication2321=== CONT TestQueueEnqueueAndFetch2322=== CONT TestDrainGivesUpWhenServerDown2323=== CONT TestWorkerPrunesClosureDeps2324=== CONT TestDrainTimeout2325=== CONT TestRunNotBlockedByPoisonHead2326--- PASS: TestServerQueueError (0.00s)2327=== CONT TestWorkerSkipsGCdPaths2328=== CONT TestDrainIsolatesPoisonPath2329=== CONT TestFailedPathPrunedByLaterClosure2330--- PASS: TestServerClientIntegration (0.00s)2331=== CONT TestWorkerUploadsAndRemoves23322026/08/27 18:12:15 INFO Upload queue status pending=223332026/08/27 18:12:15 INFO Uploading batch count=123342026/08/27 18:12:15 INFO Uploading batch count=423352026/08/27 18:12:15 ERROR Upload failed error="upload failed" count=423362026/08/27 18:12:15 INFO Upload queue status pending=223372026/08/27 18:12:15 INFO Uploading batch count=123382026/08/27 18:12:15 ERROR Upload failed error="upload failed" count=123392026/08/27 18:12:15 INFO Uploading batch count=223402026/08/27 18:12:15 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath4133747631/002/bbb23412026/08/27 18:12:15 INFO Uploading batch count=22342--- PASS: TestQueueFetchBatchLimit (0.02s)23432026/08/27 18:12:15 INFO Uploading batch count=12344--- PASS: TestQueueDeduplication (0.02s)23452026/08/27 18:12:15 INFO Upload queue status pending=223462026/08/27 18:12:15 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths646237088/002/nonexistent23472026/08/27 18:12:15 INFO Upload queue status pending=32348--- PASS: TestQueueEnqueueAndFetch (0.02s)23492026/08/27 18:12:15 INFO Uploading batch count=123502026/08/27 18:12:15 ERROR Upload failed error="upload failed" count=123512026/08/27 18:12:15 INFO Uploading batch count=223522026/08/27 18:12:15 ERROR Upload failed error="upload failed" count=223532026/08/27 18:12:15 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4107276349/002/a23542026/08/27 18:12:15 INFO Uploading batch count=123552026/08/27 18:12:15 INFO Uploading batch count=123562026/08/27 18:12:15 INFO Uploading batch count=123572026/08/27 18:12:15 ERROR Upload failed error="upload failed" count=123582026/08/27 18:12:15 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4107276349/002/b2359--- PASS: TestQueueRetryMovesToBack (0.02s)2360--- PASS: TestQueueRemove (0.02s)2361--- PASS: TestQueueFetchRemoveLifecycle (0.02s)23622026/08/27 18:12:15 INFO Uploading batch count=123632026/08/27 18:12:15 ERROR Upload failed error="upload failed" count=123642026/08/27 18:12:15 INFO Uploading batch count=223652026/08/27 18:12:15 ERROR Upload failed error="upload failed" count=223662026/08/27 18:12:15 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4107276349/002/c23672026/08/27 18:12:15 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4107276349/002/d23682026/08/27 18:12:15 INFO Uploading batch count=123692026/08/27 18:12:15 ERROR Upload failed error="upload failed" count=12370--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)23712026/08/27 18:12:15 ERROR Drain finished with paths left in queue remaining=123722026/08/27 18:12:15 INFO Uploading batch count=223732026/08/27 18:12:15 ERROR Upload failed error="upload failed" count=223742026/08/27 18:12:15 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4107276349/002/e23752026/08/27 18:12:15 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4107276349/002/f2376--- PASS: TestDrainIsolatesPoisonPath (0.02s)23772026/08/27 18:12:15 ERROR Drain finished with paths left in queue remaining=102378--- PASS: TestDrainGivesUpWhenServerDown (0.03s)2379--- PASS: TestWorkerPrunesClosureDeps (0.04s)2380--- PASS: TestWorkerSkipsGCdPaths (0.04s)2381--- PASS: TestWorkerUploadsAndRemoves (0.04s)2382--- PASS: TestQueueConcurrentWriters (0.21s)23832026/08/27 18:12:15 ERROR Upload failed error="context deadline exceeded" count=223842026/08/27 18:12:15 ERROR Drain finished with paths left in queue remaining=42385--- PASS: TestDrainTimeout (0.22s)2386--- PASS: TestQueueRemoveLargeClosure (0.33s)23872026/08/27 18:12:16 INFO Uploading batch count=123882026/08/27 18:12:16 INFO Uploading batch count=123892026/08/27 18:12:16 INFO Uploading batch count=123902026/08/27 18:12:16 ERROR Upload failed error="upload failed" count=123912026/08/27 18:12:16 INFO Uploading batch count=123922026/08/27 18:12:16 ERROR Upload failed error="upload failed" count=123932026/08/27 18:12:16 INFO Uploading batch count=123942026/08/27 18:12:16 ERROR Upload failed error="upload failed" count=123952026/08/27 18:12:16 INFO Uploading batch count=123962026/08/27 18:12:16 ERROR Upload failed error="upload failed" count=123972026/08/27 18:12:16 ERROR Drain finished with paths left in queue remaining=12398--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2399PASS