niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #220
· 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 TestDumpPathCaseHackMatchesNix14--- PASS: TestDumpPathCaseHackMatchesNix (0.03s)15=== RUN TestDumpPathCaseHackCollision16--- PASS: TestDumpPathCaseHackCollision (0.00s)17=== RUN TestDumpPathMatchesNix18=== PAUSE TestDumpPathMatchesNix19=== RUN TestDumpPathSingleFile20=== PAUSE TestDumpPathSingleFile21=== RUN TestDumpPathWriterError22=== PAUSE TestDumpPathWriterError23=== RUN TestEncodeNixBase3224=== PAUSE TestEncodeNixBase3225=== RUN TestEncodeNixBase32WithRealHash26=== PAUSE TestEncodeNixBase32WithRealHash27=== RUN TestConvertHashToNix3228=== PAUSE TestConvertHashToNix3229=== RUN TestGetStorePathHash30=== PAUSE TestGetStorePathHash31=== RUN TestPathInfoHashCompatibility32=== PAUSE TestPathInfoHashCompatibility33=== RUN TestParsePathInfoJSON34=== PAUSE TestParsePathInfoJSON35=== RUN TestParsePathInfoJSONMultiplePaths36=== PAUSE TestParsePathInfoJSONMultiplePaths37=== RUN TestPathInfoCACompatibility38=== PAUSE TestPathInfoCACompatibility39=== 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 TestStreamPushReportsEveryPath52=== PAUSE TestStreamPushReportsEveryPath53=== RUN TestStreamPushBatchesUnderLoad54=== PAUSE TestStreamPushBatchesUnderLoad55=== RUN TestStreamPushIsolatesFailures56=== PAUSE TestStreamPushIsolatesFailures57=== RUN TestStreamPushGivesUpOnDeadServer58=== PAUSE TestStreamPushGivesUpOnDeadServer59=== RUN TestStreamPushRequestLine60=== PAUSE TestStreamPushRequestLine61=== RUN TestSetClientTLS62=== PAUSE TestSetClientTLS63=== RUN TestSetClientTLSDoesNotMutateDefaultTransport64=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport65=== RUN TestSetClientTLSErrors66=== PAUSE TestSetClientTLSErrors67=== RUN TestStaticToken68=== PAUSE TestStaticToken69=== RUN TestFileTokenReadsAndCaches70=== PAUSE TestFileTokenReadsAndCaches71=== RUN TestFileTokenMissing72=== PAUSE TestFileTokenMissing73=== RUN TestFileTokenEmpty74=== PAUSE TestFileTokenEmpty75=== RUN TestScriptTokenNoExpiryRerunsEveryCall76=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall77=== RUN TestScriptTokenCachesUntilRefresh78=== PAUSE TestScriptTokenCachesUntilRefresh79=== RUN TestScriptTokenEmptyToken80=== PAUSE TestScriptTokenEmptyToken81=== RUN TestScriptTokenBadJSON82=== PAUSE TestScriptTokenBadJSON83=== RUN TestScriptTokenScriptFails84=== PAUSE TestScriptTokenScriptFails85=== RUN TestScriptTokenEmptyCommand86=== PAUSE TestScriptTokenEmptyCommand87=== CONT TestDoServerRequestAttachesToken88=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess89=== CONT TestScriptTokenNoExpiryRerunsEveryCall90=== CONT TestScriptTokenEmptyCommand91--- PASS: TestScriptTokenEmptyCommand (0.00s)92=== CONT TestFileTokenReadsAndCaches93=== CONT TestScriptTokenScriptFails94--- PASS: TestFileTokenReadsAndCaches (0.00s)95=== CONT TestStaticToken96--- PASS: TestStaticToken (0.00s)972026/09/18 18:14:39 WARN Rate limiter enabled after throttle name=server-test rate=598=== CONT TestStreamPushIsolatesFailures992026/09/18 18:14:39 ERROR Upload failed error="bad path" count=3100=== CONT TestScriptTokenBadJSON101=== CONT TestScriptTokenEmptyToken102=== CONT TestParsePathInfoJSON103=== CONT TestEncodeNixBase32WithRealHash104=== CONT TestRateLimiterFeedback105=== CONT TestPathInfoCACompatibility106=== CONT TestPathInfoHashCompatibility107=== CONT TestParsePathInfoJSONMultiplePaths108=== CONT TestGetStorePathHash109=== CONT TestDumpPathMatchesNix110=== CONT TestConvertHashToNix32111=== RUN TestConvertHashToNix32/SRI_format_to_Nix32112=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32113=== CONT TestEncodeNixBase32114=== CONT TestDumpPathWriterError115=== CONT TestStreamPushRequestLine116=== CONT TestDumpPathSingleFile117=== CONT TestFileTokenEmpty118=== CONT TestStreamPushReportsEveryPath119=== CONT TestFileTokenMissing120=== CONT TestStreamPushGivesUpOnDeadServer121=== RUN TestParsePathInfoJSON/Nix_format122--- PASS: TestScriptTokenScriptFails (0.00s)123=== CONT TestSetClientTLSErrors124=== CONT TestSetClientTLSDoesNotMutateDefaultTransport125--- PASS: TestEncodeNixBase32WithRealHash (0.00s)126=== RUN TestRateLimiterFeedback/429_enables_limiter127=== RUN TestPathInfoCACompatibility/null_ca_field128=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)129=== CONT TestStreamPushBatchesUnderLoad130=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths131=== RUN TestGetStorePathHash/valid_store_path132=== RUN TestEncodeNixBase32/test_string_hash133=== RUN TestConvertHashToNix32/already_Nix32_format134--- PASS: TestStreamPushIsolatesFailures (0.00s)1352026/09/18 18:14:39 ERROR Upload failed error="connection refused" count=20136=== PAUSE TestRateLimiterFeedback/429_enables_limiter137=== PAUSE TestConvertHashToNix32/already_Nix32_format1382026/09/18 18:14:39 ERROR Server seems unavailable, giving up on batch untried=171392026/09/18 18:14:39 ERROR Upload failed error="stale build claim" count=1140=== CONT TestSetClientTLS141--- PASS: TestStreamPushReportsEveryPath (0.00s)142=== RUN TestRateLimiterFeedback/503_enables_limiter143=== PAUSE TestParsePathInfoJSON/Nix_format144=== RUN TestParsePathInfoJSON/Lix_format145=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths146=== PAUSE TestPathInfoCACompatibility/null_ca_field147=== RUN TestConvertHashToNix32/invalid_format148=== PAUSE TestConvertHashToNix32/invalid_format149=== PAUSE TestGetStorePathHash/valid_store_path150=== PAUSE TestRateLimiterFeedback/503_enables_limiter151=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)152=== CONT TestResolveStorePath153=== RUN TestGetStorePathHash/basename_without_hyphen_should_error154=== PAUSE TestEncodeNixBase32/test_string_hash155=== RUN TestSetClientTLS/rejects_connection_without_client_cert156=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error157=== CONT TestFilterOversizedClosures158=== RUN TestFilterOversizedClosures/no_limit_keeps_everything159=== RUN TestEncodeNixBase32/empty_input160=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths161--- PASS: TestFileTokenMissing (0.00s)162--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)163--- PASS: TestScriptTokenBadJSON (0.00s)164--- PASS: TestScriptTokenEmptyToken (0.00s)165--- PASS: TestFileTokenEmpty (0.00s)166=== CONT TestShellSplit167=== CONT TestDoWithRetry_BodyReplayedViaGetBody168=== RUN TestPathInfoCACompatibility/old_string_format_-_text169=== CONT TestShellSplitErrors170=== CONT TestPartSizeForNAR171=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter172=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon173=== RUN TestSetClientTLSErrors/missing_cert_file174=== CONT TestUploadMultipart_SupersededByPeer175=== CONT TestCaseHackSuffix176=== PAUSE TestParsePathInfoJSON/Lix_format177=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert178=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error179=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything180=== PAUSE TestEncodeNixBase32/empty_input181=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths182=== CONT TestScriptTokenCachesUntilRefresh183--- PASS: TestResolveStorePath (0.00s)184=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped185=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped186--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)187=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text188=== CONT TestConvertHashToNix32/invalid_format189=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths190=== CONT TestConvertHashToNix32/already_Nix32_format191=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths192=== RUN TestPartSizeForNAR/zero_stays_at_minimum193=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter194=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon1952026/09/18 18:14:39 WARN Rate limiter enabled after throttle name=server-test rate=5196=== PAUSE TestSetClientTLSErrors/missing_cert_file1972026/09/18 18:14:39 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:36555198=== RUN TestUploadMultipart_SupersededByPeer/exists199=== RUN TestParsePathInfoJSON/empty_input200=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA201=== CONT TestEncodeNixBase32/test_string_hash202=== CONT TestEncodeNixBase32/empty_input203=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error204=== CONT TestConvertHashToNix32/SRI_format_to_Nix32205=== RUN TestFilterOversizedClosures/all_closures_skipped206--- PASS: TestDoServerRequestAttachesToken (0.01s)207=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive208--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.01s)209--- PASS: TestShellSplitErrors (0.00s)210--- PASS: TestShellSplit (0.00s)211=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter212--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)213 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)214 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)215=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum216=== RUN TestPartSizeForNAR/small_stays_at_minimum217=== PAUSE TestPartSizeForNAR/small_stays_at_minimum218=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum219=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum220=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI221=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI222=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter223=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts224=== CONT TestRateLimiterFeedback/429_enables_limiter225=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512226=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter227=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter228=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts229=== RUN TestPartSizeForNAR/1_TiB230=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512231=== RUN TestSetClientTLSErrors/missing_key_file232=== PAUSE TestUploadMultipart_SupersededByPeer/exists233=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA234=== PAUSE TestParsePathInfoJSON/empty_input235=== PAUSE TestSetClientTLSErrors/missing_key_file236=== RUN TestSetClientTLSErrors/missing_ca_file237=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)2382026/09/18 18:14:39 WARN Rate limiter backed off name=server-test rate=5239=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha5122402026/09/18 18:14:39 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:36555241--- PASS: TestConvertHashToNix32 (0.00s)242 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)243 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)244 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)245--- PASS: TestEncodeNixBase32 (0.01s)246 --- PASS: TestEncodeNixBase32/empty_input (0.00s)247 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)248=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error249=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error2502026/09/18 18:14:39 WARN Rate limiter enabled after throttle name=server-test rate=5251=== CONT TestGetStorePathHash/valid_store_path2522026/09/18 18:14:39 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:42667253=== CONT TestGetStorePathHash/basename_without_hyphen_should_error254=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error255=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon256=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive2572026/09/18 18:14:39 WARN Rate limiter backed off name=server-test rate=5258=== CONT TestRateLimiterFeedback/503_enables_limiter259=== PAUSE TestFilterOversizedClosures/all_closures_skipped260=== CONT TestFilterOversizedClosures/no_limit_keeps_everything261=== CONT TestFilterOversizedClosures/all_closures_skipped262=== RUN TestUploadMultipart_SupersededByPeer/missing2632026/09/18 18:14:39 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=50264=== RUN TestSetClientTLS/preserves_debug_logging_transport265=== PAUSE TestSetClientTLS/preserves_debug_logging_transport266=== PAUSE TestPartSizeForNAR/1_TiB267=== RUN TestPartSizeForNAR/5_TiB_S3_max_object268=== RUN TestParsePathInfoJSON/whitespace_only269=== PAUSE TestParsePathInfoJSON/whitespace_only270=== PAUSE TestSetClientTLSErrors/missing_ca_file271--- PASS: TestDumpPathSingleFile (0.05s)272=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI2732026/09/18 18:14:39 WARN Rate limiter enabled after throttle name=server-test rate=5274=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error2752026/09/18 18:14:39 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:43199276=== RUN TestPathInfoCACompatibility/new_structured_format_-_text277=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2782026/09/18 18:14:39 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=2000279=== PAUSE TestUploadMultipart_SupersededByPeer/missing280=== CONT TestUploadMultipart_SupersededByPeer/exists281=== CONT TestSetClientTLS/rejects_connection_without_client_cert2822026/09/18 18:14:39 WARN Rate limiter backed off name=server-test rate=5283=== CONT TestSetClientTLS/preserves_debug_logging_transport284=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA285=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object286=== RUN TestParsePathInfoJSON/invalid_JSON287=== RUN TestPartSizeForNAR/capped_at_5_GiB288=== PAUSE TestPartSizeForNAR/capped_at_5_GiB289=== RUN TestSetClientTLSErrors/invalid_ca_file290=== PAUSE TestSetClientTLSErrors/invalid_ca_file291=== PAUSE TestParsePathInfoJSON/invalid_JSON292=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text293=== CONT TestUploadMultipart_SupersededByPeer/missing294=== CONT TestPartSizeForNAR/zero_stays_at_minimum295=== CONT TestPartSizeForNAR/capped_at_5_GiB296=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts297=== CONT TestPartSizeForNAR/5_TiB_S3_max_object298=== CONT TestPartSizeForNAR/small_stays_at_minimum299=== CONT TestParsePathInfoJSON/Lix_format300=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum301=== CONT TestPartSizeForNAR/1_TiB302--- PASS: TestCaseHackSuffix (0.03s)303=== CONT TestSetClientTLSErrors/missing_cert_file304=== CONT TestSetClientTLSErrors/invalid_ca_file305=== CONT TestSetClientTLSErrors/missing_ca_file306=== CONT TestParsePathInfoJSON/Nix_format307=== CONT TestSetClientTLSErrors/missing_key_file308=== CONT TestParsePathInfoJSON/whitespace_only309=== CONT TestParsePathInfoJSON/invalid_JSON310=== CONT TestParsePathInfoJSON/empty_input311=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method312--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.04s)313--- PASS: TestFilterOversizedClosures (0.04s)314 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)315 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)316 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)317--- PASS: TestRateLimiterFeedback (0.02s)318 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.03s)319 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.03s)320 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.03s)321 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)322=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method323=== CONT TestPathInfoCACompatibility/null_ca_field324=== CONT TestPathInfoCACompatibility/new_structured_format_-_text325=== CONT TestPathInfoCACompatibility/old_string_format_-_text326=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive327--- PASS: TestPathInfoHashCompatibility (0.02s)328 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)329 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)330 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)331 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)332=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method333--- PASS: TestGetStorePathHash (0.05s)334 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)335 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)336 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)337 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)338--- PASS: TestPartSizeForNAR (0.04s)339 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)340 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)341 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)342 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)343 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)344 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)345 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)346--- PASS: TestParsePathInfoJSON (0.05s)347 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)348 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)349 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)350 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)351 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)352--- PASS: TestPathInfoCACompatibility (0.05s)353 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)354 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)355 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)356 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)357 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)358--- PASS: TestSetClientTLSErrors (0.05s)359 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)360 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)361 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)362 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)363--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)364--- PASS: TestUploadMultipart_SupersededByPeer (0.03s)365 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)366 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)3672026/09/18 18:14:39 http: TLS handshake error from 127.0.0.1:48798: remote error: tls: bad certificate368--- PASS: TestSetClientTLS (0.05s)369 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)370 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)371 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)372--- PASS: TestDumpPathWriterError (0.08s)373--- PASS: TestStreamPushRequestLine (0.08s)374--- PASS: TestStreamPushBatchesUnderLoad (0.10s)375--- PASS: TestDumpPathMatchesNix (0.12s)376--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)377PASS378Running server tests...379The files belonging to this database system will be owned by user "nixbld".380This user must also own the server process.381382The database cluster will be initialized with locale "C".383The default database encoding has accordingly been set to "SQL_ASCII".384The default text search configuration will be set to "english".385386Data page checksums are enabled.387388creating directory /build/postgres1197490845/data ... ok389creating subdirectories ... ok390selecting dynamic shared memory implementation ... posix391selecting default "max_connections" ... 100392selecting default "shared_buffers" ... 128MB393selecting default time zone ... UTC394creating configuration files ... ok395running bootstrap script ... ok396performing post-bootstrap initialization ... ok397syncing data to disk ... ok398399initdb: warning: enabling "trust" authentication for local connections400initdb: 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.401402Success. You can now start the database server using:403404 pg_ctl -D /build/postgres1197490845/data -l logfile start405406/build/postgres1197490845:5432 - no response4072026-09-18 18:14:40.851 UTC [127] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit4082026-09-18 18:14:40.851 UTC [127] LOG: listening on Unix socket "/build/postgres1197490845/.s.PGSQL.5432"4092026-09-18 18:14:40.856 UTC [134] LOG: database system was shut down at 2026-09-18 18:14:40 UTC4102026-09-18 18:14:40.860 UTC [127] LOG: database system is ready to accept connections411/build/postgres1197490845:5432 - accepting connections412=== RUN TestService_AuthMiddleware413=== PAUSE TestService_AuthMiddleware414=== RUN TestService_AuthMiddleware_MTLSProxyHeader415=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader416=== RUN TestService_AuthMiddleware_MTLSBoundSubjects417=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects418=== RUN TestService_ReadAuthMiddleware419=== PAUSE TestService_ReadAuthMiddleware420=== RUN TestService_AuthMiddleware_OIDC421=== PAUSE TestService_AuthMiddleware_OIDC422=== RUN TestService_RequireScope_OIDC423=== PAUSE TestService_RequireScope_OIDC424=== RUN TestService_ReadScope_PublicByDefault425=== PAUSE TestService_ReadScope_PublicByDefault426=== RUN TestCacheConfigHandler427=== PAUSE TestCacheConfigHandler428=== RUN TestCacheStatsHandler429=== PAUSE TestCacheStatsHandler430=== RUN TestClaim_BuildWaitComplete431=== PAUSE TestClaim_BuildWaitComplete432=== RUN TestClaim_GCMarkedOutputCountsAsAbsent433=== PAUSE TestClaim_GCMarkedOutputCountsAsAbsent434=== RUN TestClaim_TooManyStreams435=== PAUSE TestClaim_TooManyStreams436=== RUN TestClaim_HolderDisconnectKeepsClaim437=== PAUSE TestClaim_HolderDisconnectKeepsClaim438=== RUN TestClaim_FailWakesWaitersButIsNotRemembered439=== PAUSE TestClaim_FailWakesWaitersButIsNotRemembered440=== RUN TestClaim_FailWithoutKindReleases441=== PAUSE TestClaim_FailWithoutKindReleases442=== RUN TestClaim_StaleHeartbeatStolen443=== PAUSE TestClaim_StaleHeartbeatStolen444=== RUN TestClaim_TwoInstances445=== PAUSE TestClaim_TwoInstances446=== RUN TestClaim_InputsTouched447=== PAUSE TestClaim_InputsTouched448=== RUN TestClaim_StreamsThroughServer449=== PAUSE TestClaim_StreamsThroughServer450=== RUN TestPresent451=== PAUSE TestPresent452=== RUN TestClientCADerivations453=== PAUSE TestClientCADerivations454=== RUN TestClientErrorHandling455=== PAUSE TestClientErrorHandling456=== RUN TestClientIntegration457=== PAUSE TestClientIntegration458=== RUN TestClientMultipleUploads459=== PAUSE TestClientMultipleUploads460=== RUN TestClientWithDependencies461=== PAUSE TestClientWithDependencies462=== RUN TestClientSharedPathCommittedMidPush463=== PAUSE TestClientSharedPathCommittedMidPush464=== RUN TestPinProtectsFromGC465=== PAUSE TestPinProtectsFromGC466=== RUN TestResolveDBConnectionString467=== PAUSE TestResolveDBConnectionString468=== RUN TestGCAdvisoryLockBlocksConcurrentRun4692026-09-18 18:14:41.270 UTC [371] ERROR: relation "goose_db_version" does not exist at character 364702026-09-18 18:14:41.270 UTC [371] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4712026/09/18 18:14:41 OK 20241026095416_initial_model.sql (11.73ms)4722026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (2.04ms)4732026/09/18 18:14:41 OK 20251218171726_add_pins.sql (3.21ms)4742026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (2.87ms)4752026/09/18 18:14:41 OK 20260905000000_add_claims.sql (3.3ms)4762026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000004772026/09/18 18:14:41 OK 1_commit_pending_closure.sql (1.97ms)4782026/09/18 18:14:41 OK 2_object_stats_trigger.sql (873.89µs)4792026/09/18 18:14:41 goose: up to current file version: 2480--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.18s)481=== RUN TestGCBugBareHashReferences482=== PAUSE TestGCBugBareHashReferences483=== RUN TestGCMetrics484=== PAUSE TestGCMetrics485=== RUN TestGCTaskStore_StartNew486=== PAUSE TestGCTaskStore_StartNew487=== RUN TestGCTaskStore_DeduplicateSameParams488=== PAUSE TestGCTaskStore_DeduplicateSameParams489=== RUN TestGCTaskStore_ConflictDifferentParams490=== PAUSE TestGCTaskStore_ConflictDifferentParams491=== RUN TestGCTaskStore_GetEmpty492=== PAUSE TestGCTaskStore_GetEmpty493=== RUN TestGCTaskStore_GetReturnsLatest494=== PAUSE TestGCTaskStore_GetReturnsLatest495=== RUN TestGCTaskStore_CompletedAllowsNewTask496=== PAUSE TestGCTaskStore_CompletedAllowsNewTask497=== RUN TestGCTaskStore_PhaseUpdates498=== PAUSE TestGCTaskStore_PhaseUpdates499=== RUN TestGCTaskStore_Fail500=== PAUSE TestGCTaskStore_Fail501=== RUN TestGracefulShutdownDrainsInflight502=== PAUSE TestGracefulShutdownDrainsInflight503=== RUN TestService_healthCheckHandler504=== PAUSE TestService_healthCheckHandler505=== RUN TestService_readinessHandler506=== PAUSE TestService_readinessHandler507=== RUN TestGenerateLandingPage508=== PAUSE TestGenerateLandingPage509=== RUN TestCacheConfigHandlerMaxNarSize510=== PAUSE TestCacheConfigHandlerMaxNarSize511=== RUN TestCreatePendingClosureRejectsOversizedNAR512=== PAUSE TestCreatePendingClosureRejectsOversizedNAR513=== RUN TestNARDeduplicationMetadataUploadBug514=== PAUSE TestNARDeduplicationMetadataUploadBug515=== RUN TestMetricsInventory516=== PAUSE TestMetricsInventory517=== RUN TestService_NativeMTLS518=== PAUSE TestService_NativeMTLS519=== RUN TestServerTLSConfig520=== PAUSE TestServerTLSConfig521=== RUN TestMultipartCleanup522=== PAUSE TestMultipartCleanup523=== RUN TestObjectStatsTrigger524=== PAUSE TestObjectStatsTrigger525=== RUN TestOrphanedObjectsGC526=== PAUSE TestOrphanedObjectsGC527=== RUN TestOrphanedObjectsGCStressTest528=== PAUSE TestOrphanedObjectsGCStressTest529=== RUN TestResurrectedObjectNotDeleted530=== PAUSE TestResurrectedObjectNotDeleted531=== RUN TestParseSingleRange532=== PAUSE TestParseSingleRange533=== RUN TestIsValidCachePath534=== PAUSE TestIsValidCachePath535=== RUN TestReadProxyNarinfo536=== PAUSE TestReadProxyNarinfo537=== RUN TestReadProxyNarinfoAlreadyDecompressed538=== PAUSE TestReadProxyNarinfoAlreadyDecompressed539=== RUN TestReadProxyNarStreaming540=== PAUSE TestReadProxyNarStreaming541=== RUN TestReadProxy404542=== PAUSE TestReadProxy404543=== RUN TestReadProxyInvalidPath544=== PAUSE TestReadProxyInvalidPath545=== RUN TestReadProxyHead546=== PAUSE TestReadProxyHead547=== RUN TestReadProxyConditionalGet548=== PAUSE TestReadProxyConditionalGet549=== RUN TestReadProxyRootRedirectsToIndexHTML550=== PAUSE TestReadProxyRootRedirectsToIndexHTML551=== RUN TestReadProxyDisabled552=== PAUSE TestReadProxyDisabled553=== RUN TestReadRedirectNar554=== PAUSE TestReadRedirectNar555=== RUN TestReadRedirectKeepsNarinfoProxied556=== PAUSE TestReadRedirectKeepsNarinfoProxied557=== RUN TestReadProxyRangeRequest558=== PAUSE TestReadProxyRangeRequest559=== RUN TestReadRedirectUsesPublicS3URL560=== PAUSE TestReadRedirectUsesPublicS3URL561=== RUN TestRedundantMultipartUpload562=== PAUSE TestRedundantMultipartUpload563=== RUN TestCompleteMultipartUpload_ErrorButObjectExists564=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists565=== RUN TestCompletedNarNotReofferedAcrossClosures566=== PAUSE TestCompletedNarNotReofferedAcrossClosures567=== RUN TestPresignedUploadRegisteredBeforeCommit568=== PAUSE TestPresignedUploadRegisteredBeforeCommit569=== RUN TestService_Rustfstest570=== PAUSE TestService_Rustfstest571=== RUN TestParseSize572=== PAUSE TestParseSize573=== RUN TestSkippedUploadsHandler574=== PAUSE TestSkippedUploadsHandler575=== RUN TestSystemdListenerNotActivated576--- PASS: TestSystemdListenerNotActivated (0.00s)577=== RUN TestWatchdogBeatsWhenHealthy578--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)579=== RUN TestWatchdogSkipsWhenUnhealthy5802026/09/18 18:14:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5812026/09/18 18:14:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5822026/09/18 18:14:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5832026/09/18 18:14:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5842026/09/18 18:14:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5852026/09/18 18:14:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5862026/09/18 18:14:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5872026/09/18 18:14:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5882026/09/18 18:14:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5892026/09/18 18:14:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"590--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)591=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle592=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle593=== RUN TestProxyWriteTimeout594=== PAUSE TestProxyWriteTimeout595=== RUN TestIsValidUploadKey596=== PAUSE TestIsValidUploadKey597=== RUN TestUploadHandlersRejectInvalidKeys598=== PAUSE TestUploadHandlersRejectInvalidKeys599=== RUN TestUploadHandlersRejectOversizedBody600=== PAUSE TestUploadHandlersRejectOversizedBody601=== RUN TestService_cleanupPendingClosuresHandler602=== PAUSE TestService_cleanupPendingClosuresHandler603=== RUN TestService_createPendingClosureHandler604=== PAUSE TestService_createPendingClosureHandler605=== RUN TestService_verifyS3Integrity606=== PAUSE TestService_verifyS3Integrity607=== RUN TestCompleteMultipartUnregistered608=== PAUSE TestCompleteMultipartUnregistered609=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT610=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT611=== CONT TestService_Rustfstest612=== CONT TestService_AuthMiddleware613=== CONT TestGCTaskStore_CompletedAllowsNewTask614--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)615=== CONT TestServerTLSConfig616=== CONT TestGCTaskStore_GetReturnsLatest617--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)618=== CONT TestClientWithDependencies619=== CONT TestGCTaskStore_PhaseUpdates620--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)621=== CONT TestService_NativeMTLS622=== CONT TestGCTaskStore_GetEmpty623=== CONT TestPresignedUploadRegisteredBeforeCommit624=== CONT TestGCTaskStore_ConflictDifferentParams625=== CONT TestCompletedNarNotReofferedAcrossClosures626=== CONT TestGCTaskStore_DeduplicateSameParams627=== CONT TestCompleteMultipartUpload_ErrorButObjectExists628=== CONT TestRedundantMultipartUpload629=== CONT TestGCTaskStore_StartNew630=== CONT TestReadRedirectUsesPublicS3URL631=== CONT TestGCMetrics632=== CONT TestReadProxyRangeRequest633=== CONT TestGCBugBareHashReferences634=== CONT TestReadRedirectKeepsNarinfoProxied635=== CONT TestResolveDBConnectionString636=== CONT TestReadRedirectNar637=== CONT TestObjectStatsTrigger638=== CONT TestPinProtectsFromGC639=== CONT TestMultipartCleanup640=== CONT TestClientSharedPathCommittedMidPush641=== RUN TestServerTLSConfig/no_client_CA642=== PAUSE TestServerTLSConfig/no_client_CA643=== RUN TestServerTLSConfig/missing_CA_file644=== PAUSE TestServerTLSConfig/missing_CA_file645=== CONT TestNARDeduplicationMetadataUploadBug646=== RUN TestResolveDBConnectionString/flag_wins647=== PAUSE TestResolveDBConnectionString/flag_wins648--- PASS: TestGCTaskStore_GetEmpty (0.00s)649--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)650--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)651--- PASS: TestGCTaskStore_StartNew (0.00s)652=== RUN TestServerTLSConfig/not_a_PEM_file653=== PAUSE TestServerTLSConfig/not_a_PEM_file654=== CONT TestMetricsInventory655=== CONT TestOrphanedObjectsGC656=== CONT TestClientMultipleUploads657=== CONT TestClientIntegration658=== RUN TestResolveDBConnectionString/file_when_flag_empty659=== PAUSE TestResolveDBConnectionString/file_when_flag_empty660=== RUN TestResolveDBConnectionString/missing_file_is_an_error661=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error662=== RUN TestResolveDBConnectionString/PGHOST_allows_empty663=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty664=== RUN TestResolveDBConnectionString/nothing_configured665=== PAUSE TestResolveDBConnectionString/nothing_configured666=== CONT TestCreatePendingClosureRejectsOversizedNAR6672026/09/18 18:14:41 INFO Received uploads request method=POST path=/api/pending_closures668--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)669=== CONT TestReadProxyDisabled6702026-09-18 18:14:41.663 UTC [446] ERROR: relation "goose_db_version" does not exist at character 366712026-09-18 18:14:41.663 UTC [446] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6722026-09-18 18:14:41.664 UTC [447] ERROR: relation "goose_db_version" does not exist at character 366732026-09-18 18:14:41.664 UTC [447] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6742026-09-18 18:14:41.665 UTC [445] ERROR: relation "goose_db_version" does not exist at character 366752026-09-18 18:14:41.665 UTC [445] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6762026-09-18 18:14:41.671 UTC [448] ERROR: relation "goose_db_version" does not exist at character 366772026-09-18 18:14:41.671 UTC [448] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6782026-09-18 18:14:41.674 UTC [449] ERROR: relation "goose_db_version" does not exist at character 366792026-09-18 18:14:41.674 UTC [449] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6802026-09-18 18:14:41.710 UTC [453] ERROR: relation "goose_db_version" does not exist at character 366812026-09-18 18:14:41.710 UTC [453] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6822026/09/18 18:14:41 OK 20241026095416_initial_model.sql (67.38ms)6832026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (21.41ms)6842026/09/18 18:14:41 OK 20241026095416_initial_model.sql (88.02ms)6852026/09/18 18:14:41 OK 20241026095416_initial_model.sql (90.13ms)6862026/09/18 18:14:41 OK 20241026095416_initial_model.sql (89.75ms)6872026/09/18 18:14:41 OK 20241026095416_initial_model.sql (89.82ms)6882026/09/18 18:14:41 OK 20251218171726_add_pins.sql (9.35ms)6892026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (5.04ms)6902026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (5.01ms)6912026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (4.44ms)6922026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (4.31ms)6932026/09/18 18:14:41 OK 20241026095416_initial_model.sql (43.9ms)6942026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (3.45ms)6952026/09/18 18:14:41 OK 20251218171726_add_pins.sql (7.92ms)6962026/09/18 18:14:41 OK 20251218171726_add_pins.sql (9.06ms)6972026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (9.59ms)6982026-09-18 18:14:41.791 UTC [456] ERROR: relation "goose_db_version" does not exist at character 366992026-09-18 18:14:41.791 UTC [456] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7002026/09/18 18:14:41 OK 20251218171726_add_pins.sql (9.44ms)7012026/09/18 18:14:41 OK 20251218171726_add_pins.sql (9.86ms)7022026/09/18 18:14:41 OK 20251218171726_add_pins.sql (7.08ms)7032026-09-18 18:14:41.801 UTC [457] ERROR: relation "goose_db_version" does not exist at character 367042026-09-18 18:14:41.801 UTC [457] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7052026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (18.69ms)7062026-09-18 18:14:41.808 UTC [459] ERROR: relation "goose_db_version" does not exist at character 367072026-09-18 18:14:41.808 UTC [459] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7082026-09-18 18:14:41.808 UTC [458] ERROR: relation "goose_db_version" does not exist at character 367092026-09-18 18:14:41.808 UTC [458] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7102026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (19.67ms)7112026/09/18 18:14:41 OK 20260905000000_add_claims.sql (19.5ms)7122026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000007132026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (19.65ms)7142026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (19.6ms)7152026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (19.59ms)7162026/09/18 18:14:41 OK 1_commit_pending_closure.sql (5.94ms)7172026/09/18 18:14:41 OK 20260905000000_add_claims.sql (9.79ms)7182026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000007192026/09/18 18:14:41 OK 20260905000000_add_claims.sql (9.05ms)7202026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000007212026/09/18 18:14:41 OK 2_object_stats_trigger.sql (3.09ms)7222026/09/18 18:14:41 goose: up to current file version: 27232026/09/18 18:14:41 OK 20260905000000_add_claims.sql (7.5ms)7242026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000007252026/09/18 18:14:41 OK 20260905000000_add_claims.sql (7.19ms)7262026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000007272026/09/18 18:14:41 OK 1_commit_pending_closure.sql (3.8ms)7282026/09/18 18:14:41 OK 20260905000000_add_claims.sql (7.96ms)7292026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000007302026/09/18 18:14:41 OK 2_object_stats_trigger.sql (2.15ms)7312026/09/18 18:14:41 goose: up to current file version: 27322026/09/18 18:14:41 OK 1_commit_pending_closure.sql (4.58ms)7332026/09/18 18:14:41 OK 1_commit_pending_closure.sql (5.27ms)7342026/09/18 18:14:41 OK 1_commit_pending_closure.sql (5.55ms)7352026/09/18 18:14:41 OK 1_commit_pending_closure.sql (4.69ms)7362026/09/18 18:14:41 OK 2_object_stats_trigger.sql (3.7ms)7372026/09/18 18:14:41 goose: up to current file version: 27382026/09/18 18:14:41 OK 2_object_stats_trigger.sql (4.09ms)7392026/09/18 18:14:41 goose: up to current file version: 27402026/09/18 18:14:41 OK 20241026095416_initial_model.sql (18.41ms)7412026/09/18 18:14:41 OK 2_object_stats_trigger.sql (4.21ms)7422026/09/18 18:14:41 goose: up to current file version: 27432026/09/18 18:14:41 OK 2_object_stats_trigger.sql (2.83ms)7442026/09/18 18:14:41 goose: up to current file version: 27452026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (4.69ms)7462026/09/18 18:14:41 OK 20241026095416_initial_model.sql (23.63ms)7472026/09/18 18:14:41 OK 20251218171726_add_pins.sql (9.97ms)7482026/09/18 18:14:41 OK 20241026095416_initial_model.sql (25.39ms)7492026/09/18 18:14:41 OK 20241026095416_initial_model.sql (23.51ms)7502026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (3.5ms)7512026-09-18 18:14:41.845 UTC [460] ERROR: relation "goose_db_version" does not exist at character 367522026-09-18 18:14:41.845 UTC [460] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7532026-09-18 18:14:41.846 UTC [461] ERROR: relation "goose_db_version" does not exist at character 367542026-09-18 18:14:41.846 UTC [461] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7552026-09-18 18:14:41.847 UTC [462] ERROR: relation "goose_db_version" does not exist at character 367562026-09-18 18:14:41.847 UTC [462] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7572026-09-18 18:14:41.847 UTC [463] ERROR: relation "goose_db_version" does not exist at character 367582026-09-18 18:14:41.847 UTC [463] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7592026-09-18 18:14:41.848 UTC [465] ERROR: relation "goose_db_version" does not exist at character 367602026-09-18 18:14:41.848 UTC [465] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7612026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (4.01ms)7622026-09-18 18:14:41.849 UTC [464] ERROR: relation "goose_db_version" does not exist at character 367632026-09-18 18:14:41.849 UTC [464] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7642026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (6.16ms)7652026/09/18 18:14:41 OK 20251218171726_add_pins.sql (5.58ms)7662026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (3.34ms)7672026/09/18 18:14:41 OK 20251218171726_add_pins.sql (5.57ms)768--- PASS: TestService_Rustfstest (0.29s)769=== CONT TestCacheConfigHandlerMaxNarSize7702026/09/18 18:14:41 OK 20260905000000_add_claims.sql (4.59ms)7712026/09/18 18:14:41 goose: successfully migrated database to version: 20260905000000772--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)773=== CONT TestClientErrorHandling774=== RUN TestClientErrorHandling/InvalidStorePath775=== PAUSE TestClientErrorHandling/InvalidStorePath776=== RUN TestClientErrorHandling/InvalidAuthToken777=== PAUSE TestClientErrorHandling/InvalidAuthToken778=== RUN TestClientErrorHandling/ServerNotAvailable779=== PAUSE TestClientErrorHandling/ServerNotAvailable780=== CONT TestReadProxyRootRedirectsToIndexHTML7812026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (5.99ms)7822026/09/18 18:14:41 OK 20251218171726_add_pins.sql (7.03ms)7832026-09-18 18:14:41.859 UTC [466] ERROR: relation "goose_db_version" does not exist at character 367842026-09-18 18:14:41.859 UTC [466] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7852026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (5.52ms)7862026/09/18 18:14:41 OK 1_commit_pending_closure.sql (4.43ms)7872026-09-18 18:14:41.861 UTC [467] ERROR: relation "goose_db_version" does not exist at character 367882026-09-18 18:14:41.861 UTC [467] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7892026/09/18 18:14:41 OK 20260905000000_add_claims.sql (4.06ms)7902026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000007912026-09-18 18:14:41.862 UTC [468] ERROR: relation "goose_db_version" does not exist at character 367922026-09-18 18:14:41.862 UTC [468] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7932026-09-18 18:14:41.862 UTC [469] ERROR: relation "goose_db_version" does not exist at character 367942026-09-18 18:14:41.862 UTC [469] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7952026/09/18 18:14:41 OK 2_object_stats_trigger.sql (3.23ms)7962026/09/18 18:14:41 goose: up to current file version: 27972026-09-18 18:14:41.864 UTC [471] ERROR: relation "goose_db_version" does not exist at character 367982026-09-18 18:14:41.864 UTC [471] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7992026/09/18 18:14:41 OK 1_commit_pending_closure.sql (3.12ms)8002026-09-18 18:14:41.865 UTC [472] ERROR: relation "goose_db_version" does not exist at character 368012026-09-18 18:14:41.865 UTC [472] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8022026/09/18 18:14:41 OK 20260905000000_add_claims.sql (6.43ms)8032026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000008042026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (7.59ms)8052026/09/18 18:14:41 OK 2_object_stats_trigger.sql (2.67ms)8062026/09/18 18:14:41 goose: up to current file version: 28072026/09/18 18:14:41 OK 20241026095416_initial_model.sql (13.72ms)8082026/09/18 18:14:41 OK 20241026095416_initial_model.sql (13.83ms)8092026/09/18 18:14:41 OK 20241026095416_initial_model.sql (11.88ms)8102026/09/18 18:14:41 OK 1_commit_pending_closure.sql (3.37ms)8112026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (2.28ms)8122026/09/18 18:14:41 OK 20260905000000_add_claims.sql (4ms)8132026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000008142026/09/18 18:14:41 OK 20241026095416_initial_model.sql (13.61ms)8152026/09/18 18:14:41 OK 20241026095416_initial_model.sql (13.76ms)8162026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (2.95ms)8172026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (3.12ms)8182026/09/18 18:14:41 OK 2_object_stats_trigger.sql (2.6ms)8192026/09/18 18:14:41 goose: up to current file version: 28202026/09/18 18:14:41 OK 20241026095416_initial_model.sql (12.83ms)8212026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (2.05ms)8222026/09/18 18:14:41 OK 1_commit_pending_closure.sql (3.3ms)8232026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (3.46ms)8242026/09/18 18:14:41 OK 20251218171726_add_pins.sql (5.09ms)8252026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (2.98ms)8262026-09-18 18:14:41.875 UTC [476] ERROR: relation "goose_db_version" does not exist at character 368272026-09-18 18:14:41.875 UTC [476] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8282026/09/18 18:14:41 OK 2_object_stats_trigger.sql (2.73ms)8292026/09/18 18:14:41 goose: up to current file version: 28302026/09/18 18:14:41 OK 20251218171726_add_pins.sql (4.66ms)8312026-09-18 18:14:41.877 UTC [477] ERROR: relation "goose_db_version" does not exist at character 368322026-09-18 18:14:41.877 UTC [477] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8332026/09/18 18:14:41 OK 20251218171726_add_pins.sql (5.16ms)8342026/09/18 18:14:41 OK 20251218171726_add_pins.sql (5.8ms)8352026/09/18 18:14:41 OK 20251218171726_add_pins.sql (5.18ms)8362026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (5.68ms)8372026/09/18 18:14:41 OK 20241026095416_initial_model.sql (12.53ms)8382026/09/18 18:14:41 OK 20241026095416_initial_model.sql (12.72ms)8392026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (5.48ms)8402026/09/18 18:14:41 OK 20241026095416_initial_model.sql (12.17ms)8412026/09/18 18:14:41 OK 20251218171726_add_pins.sql (6.96ms)8422026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (4.58ms)8432026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (5.96ms)8442026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (3.1ms)8452026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (3.15ms)8462026/09/18 18:14:41 OK 20260905000000_add_claims.sql (4.17ms)8472026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000008482026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (5.69ms)8492026/09/18 18:14:41 OK 20241026095416_initial_model.sql (14.73ms)8502026/09/18 18:14:41 OK 20241026095416_initial_model.sql (14.13ms)8512026/09/18 18:14:41 OK 20241026095416_initial_model.sql (12.24ms)8522026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (2.99ms)8532026/09/18 18:14:41 OK 20260905000000_add_claims.sql (3.39ms)8542026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000008552026/09/18 18:14:41 OK 20260905000000_add_claims.sql (3.61ms)8562026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000008572026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (4.66ms)8582026/09/18 18:14:41 OK 20260905000000_add_claims.sql (4.49ms)8592026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000008602026/09/18 18:14:41 OK 20251218171726_add_pins.sql (4.25ms)8612026/09/18 18:14:41 INFO Received uploads request method=POST path=/api/pending_closures8622026/09/18 18:14:41 OK 20260905000000_add_claims.sql (4.25ms)8632026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000008642026/09/18 18:14:41 OK 1_commit_pending_closure.sql (3.37ms)8652026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (2.53ms)8662026/09/18 18:14:41 OK 20251218171726_add_pins.sql (5.15ms)8672026/09/18 18:14:41 OK 1_commit_pending_closure.sql (4.26ms)8682026/09/18 18:14:41 OK 1_commit_pending_closure.sql (3.4ms)8692026/09/18 18:14:41 OK 20251218171726_add_pins.sql (5.09ms)8702026/09/18 18:14:41 OK 2_object_stats_trigger.sql (2.27ms)8712026/09/18 18:14:41 goose: up to current file version: 28722026/09/18 18:14:41 OK 1_commit_pending_closure.sql (3.55ms)8732026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (3.18ms)8742026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (3.05ms)8752026/09/18 18:14:41 OK 2_object_stats_trigger.sql (3.46ms)8762026/09/18 18:14:41 goose: up to current file version: 28772026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (4.45ms)8782026/09/18 18:14:41 OK 1_commit_pending_closure.sql (3.58ms)8792026/09/18 18:14:41 OK 20251218171726_add_pins.sql (3.46ms)8802026/09/18 18:14:41 OK 20260905000000_add_claims.sql (5.97ms)8812026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000008822026/09/18 18:14:41 OK 2_object_stats_trigger.sql (3.32ms)8832026/09/18 18:14:41 goose: up to current file version: 28842026/09/18 18:14:41 OK 2_object_stats_trigger.sql (2.3ms)8852026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (4.78ms)8862026/09/18 18:14:41 goose: up to current file version: 28872026/09/18 18:14:41 OK 20241026095416_initial_model.sql (9.86ms)8882026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (5.09ms)8892026/09/18 18:14:41 OK 2_object_stats_trigger.sql (2.66ms)8902026/09/18 18:14:41 goose: up to current file version: 28912026/09/18 18:14:41 OK 1_commit_pending_closure.sql (3.65ms)8922026/09/18 18:14:41 OK 20251218171726_add_pins.sql (4.51ms)8932026/09/18 18:14:41 OK 20251218171726_add_pins.sql (4.6ms)8942026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (2.54ms)8952026/09/18 18:14:41 OK 20260905000000_add_claims.sql (5.11ms)8962026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000008972026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (5.06ms)8982026/09/18 18:14:41 OK 20260905000000_add_claims.sql (3.32ms)8992026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000009002026/09/18 18:14:41 OK 2_object_stats_trigger.sql (2.25ms)9012026/09/18 18:14:41 goose: up to current file version: 29022026/09/18 18:14:41 OK 20241026095416_initial_model.sql (13.51ms)9032026/09/18 18:14:41 OK 20260905000000_add_claims.sql (5.95ms)9042026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000009052026/09/18 18:14:41 OK 1_commit_pending_closure.sql (3.02ms)9062026/09/18 18:14:41 OK 20251218171726_add_pins.sql (4.24ms)9072026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (4.44ms)9082026/09/18 18:14:41 OK 1_commit_pending_closure.sql (3.31ms)9092026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (5.52ms)9102026/09/18 18:14:41 OK 20260905000000_add_claims.sql (4.26ms)9112026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000009122026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (3.45ms)9132026/09/18 18:14:41 OK 1_commit_pending_closure.sql (3.1ms)9142026/09/18 18:14:41 OK 2_object_stats_trigger.sql (2.34ms)9152026/09/18 18:14:41 goose: up to current file version: 29162026/09/18 18:14:41 OK 2_object_stats_trigger.sql (2.35ms)9172026/09/18 18:14:41 goose: up to current file version: 29182026/09/18 18:14:41 OK 1_commit_pending_closure.sql (2.81ms)9192026/09/18 18:14:41 OK 2_object_stats_trigger.sql (1.77ms)9202026/09/18 18:14:41 goose: up to current file version: 29212026/09/18 18:14:41 OK 20260905000000_add_claims.sql (4.06ms)9222026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000009232026/09/18 18:14:41 OK 20260905000000_add_claims.sql (3.15ms)9242026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000009252026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (4.12ms)9262026/09/18 18:14:41 OK 20251218171726_add_pins.sql (3.17ms)9272026/09/18 18:14:41 OK 2_object_stats_trigger.sql (1.01ms)9282026/09/18 18:14:41 goose: up to current file version: 29292026/09/18 18:14:41 OK 1_commit_pending_closure.sql (2.33ms)9302026/09/18 18:14:41 OK 1_commit_pending_closure.sql (3.47ms)9312026/09/18 18:14:41 OK 2_object_stats_trigger.sql (2.22ms)9322026/09/18 18:14:41 goose: up to current file version: 29332026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (4.38ms)9342026/09/18 18:14:41 OK 20260905000000_add_claims.sql (4.69ms)9352026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000009362026/09/18 18:14:41 OK 2_object_stats_trigger.sql (1.67ms)9372026/09/18 18:14:41 goose: up to current file version: 29382026/09/18 18:14:41 OK 1_commit_pending_closure.sql (2.13ms)9392026/09/18 18:14:41 OK 20260905000000_add_claims.sql (3.65ms)9402026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000009412026/09/18 18:14:41 OK 2_object_stats_trigger.sql (1.87ms)9422026/09/18 18:14:41 goose: up to current file version: 29432026/09/18 18:14:41 OK 1_commit_pending_closure.sql (2.49ms)9442026/09/18 18:14:41 OK 2_object_stats_trigger.sql (1.41ms)9452026/09/18 18:14:41 goose: up to current file version: 29462026/09/18 18:14:41 WARN mTLS auth: subject not in bound subjects subject="CN=reader"9472026/09/18 18:14:41 WARN mTLS auth: subject not in bound subjects subject="CN=reader"948--- PASS: TestService_NativeMTLS (0.37s)949=== CONT TestClientCADerivations9502026-09-18 18:14:41.941 UTC [479] ERROR: relation "goose_db_version" does not exist at character 369512026-09-18 18:14:41.941 UTC [479] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9522026/09/18 18:14:41 OK 20241026095416_initial_model.sql (11.45ms)9532026/09/18 18:14:41 OK 20251210153512_drop_unused_gin_index.sql (3.84ms)9542026/09/18 18:14:41 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"955--- PASS: TestService_AuthMiddleware (0.40s)956=== CONT TestReadProxyConditionalGet9572026/09/18 18:14:41 OK 20251218171726_add_pins.sql (4.42ms)9582026/09/18 18:14:41 OK 20260628120000_add_object_size_and_stats.sql (4.38ms)9592026/09/18 18:14:41 OK 20260905000000_add_claims.sql (3.82ms)9602026/09/18 18:14:41 goose: successfully migrated database to version: 202609050000009612026/09/18 18:14:41 OK 1_commit_pending_closure.sql (2.76ms)9622026/09/18 18:14:41 OK 2_object_stats_trigger.sql (2.09ms)9632026/09/18 18:14:41 goose: up to current file version: 2964=== NAME TestClientWithDependencies965 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies996548605/001/store/lybyyks4mjf3nlfgc8v9yiddz2vwypzh-test-script9662026-09-18 18:14:42.010 UTC [518] ERROR: relation "goose_db_version" does not exist at character 369672026-09-18 18:14:42.010 UTC [518] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC968--- PASS: TestObjectStatsTrigger (0.46s)969=== CONT TestPresent9702026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures9712026/09/18 18:14:42 OK 20241026095416_initial_model.sql (11.26ms)9722026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (1.95ms)9732026/09/18 18:14:42 OK 20251218171726_add_pins.sql (3.62ms)974=== NAME TestClientWithDependencies975 client_integration_test.go:615: Found 1 dependencies (including self)9762026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (4.23ms)9772026-09-18 18:14:42.041 UTC [529] ERROR: relation "goose_db_version" does not exist at character 369782026-09-18 18:14:42.041 UTC [529] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9792026/09/18 18:14:42 OK 20260905000000_add_claims.sql (3.95ms)9802026/09/18 18:14:42 goose: successfully migrated database to version: 202609050000009812026/09/18 18:14:42 OK 1_commit_pending_closure.sql (2.83ms)9822026/09/18 18:14:42 OK 2_object_stats_trigger.sql (3.5ms)9832026/09/18 18:14:42 goose: up to current file version: 29842026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures9852026/09/18 18:14:42 OK 20241026095416_initial_model.sql (12.9ms)9862026/09/18 18:14:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9872026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (2.72ms)9882026/09/18 18:14:42 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjQ1MzhkY2YtNTZmMS00YjI1LTljOTgtOWU0NjYwYmIyZjBmLmYzZTVhMWFiLTIyOTgtNDUxNC04YWE0LTU1YTE5ODAwNGVkOXgxNzg5NzU1MjgyMDM0ODI0NDAy9892026/09/18 18:14:42 OK 20251218171726_add_pins.sql (4.38ms)9902026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures9912026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (4.73ms)9922026/09/18 18:14:42 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjQ1MzhkY2YtNTZmMS00YjI1LTljOTgtOWU0NjYwYmIyZjBmLmYzZTVhMWFiLTIyOTgtNDUxNC04YWE0LTU1YTE5ODAwNGVkOXgxNzg5NzU1MjgyMDM0ODI0NDAy parts=1993--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.51s)994=== CONT TestReadProxyHead9952026/09/18 18:14:42 OK 20260905000000_add_claims.sql (4.18ms)9962026/09/18 18:14:42 goose: successfully migrated database to version: 202609050000009972026/09/18 18:14:42 OK 1_commit_pending_closure.sql (3.36ms)9982026/09/18 18:14:42 OK 2_object_stats_trigger.sql (1.19ms)9992026/09/18 18:14:42 goose: up to current file version: 210002026-09-18 18:14:42.091 UTC [560] ERROR: relation "goose_db_version" does not exist at character 3610012026-09-18 18:14:42.091 UTC [560] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1002--- PASS: TestReadRedirectKeepsNarinfoProxied (0.54s)1003=== CONT TestGenerateLandingPage1004--- PASS: TestGenerateLandingPage (0.01s)1005=== CONT TestClaim_StreamsThroughServer10062026/09/18 18:14:42 OK 20241026095416_initial_model.sql (13.41ms)10072026/09/18 18:14:42 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10082026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (2.64ms)10092026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures10102026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures10112026/09/18 18:14:42 OK 20251218171726_add_pins.sql (4.78ms)10122026/09/18 18:14:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10132026/09/18 18:14:42 INFO Uploading lybyyks4mjf3nlfgc8v9yiddz2vwypzh-test-script (136B)10142026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (9.02ms)10152026/09/18 18:14:42 WARN Failed to register uploaded object key=log/71j3gpafgh41sc5bgf505py53jm12877-test-script.drv error="server returned 404: 404 page not found\n"10162026/09/18 18:14:42 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"10172026/09/18 18:14:42 OK 20260905000000_add_claims.sql (4.9ms)10182026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000010192026/09/18 18:14:42 OK 1_commit_pending_closure.sql (3.52ms)10202026/09/18 18:14:42 WARN Failed to register uploaded object key=lybyyks4mjf3nlfgc8v9yiddz2vwypzh.ls error="server returned 404: 404 page not found\n"10212026/09/18 18:14:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10222026/09/18 18:14:42 OK 2_object_stats_trigger.sql (1.78ms)10232026/09/18 18:14:42 goose: up to current file version: 210242026/09/18 18:14:42 INFO Signed narinfos id=1 count=110252026/09/18 18:14:42 INFO Uploading 1 narinfos10262026/09/18 18:14:42 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10272026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures1028--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.58s)1029=== CONT TestReadProxyInvalidPath10302026/09/18 18:14:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10312026/09/18 18:14:42 WARN Failed to register uploaded object key=lybyyks4mjf3nlfgc8v9yiddz2vwypzh.narinfo error="server returned 404: 404 page not found\n"10322026-09-18 18:14:42.151 UTC [581] ERROR: relation "goose_db_version" does not exist at character 3610332026-09-18 18:14:42.151 UTC [581] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10342026/09/18 18:14:42 INFO Completed upload id=110352026/09/18 18:14:42 INFO Upload complete. (84ms)1036=== NAME TestClientWithDependencies1037 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies996548605/001/store) requires matching store prefix1038--- PASS: TestClientWithDependencies (0.61s)1039=== CONT TestService_readinessHandler10402026/09/18 18:14:42 OK 20241026095416_initial_model.sql (19.86ms)10412026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (3.5ms)10422026/09/18 18:14:42 OK 20251218171726_add_pins.sql (5.39ms)10432026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (4.74ms)10442026/09/18 18:14:42 OK 20260905000000_add_claims.sql (4.57ms)10452026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000010462026-09-18 18:14:42.198 UTC [588] ERROR: relation "goose_db_version" does not exist at character 3610472026-09-18 18:14:42.198 UTC [588] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10482026/09/18 18:14:42 OK 1_commit_pending_closure.sql (3.42ms)10492026/09/18 18:14:42 OK 2_object_stats_trigger.sql (3.91ms)10502026/09/18 18:14:42 goose: up to current file version: 21051--- PASS: TestReadProxyRangeRequest (0.64s)1052=== CONT TestClaim_InputsTouched10532026/09/18 18:14:42 OK 20241026095416_initial_model.sql (9.35ms)10542026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (2.58ms)10552026/09/18 18:14:42 OK 20251218171726_add_pins.sql (4.17ms)10562026-09-18 18:14:42.223 UTC [607] ERROR: relation "goose_db_version" does not exist at character 3610572026-09-18 18:14:42.223 UTC [607] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10582026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures10592026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (5.04ms)10602026/09/18 18:14:42 OK 20260905000000_add_claims.sql (4.14ms)10612026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000010622026/09/18 18:14:42 OK 1_commit_pending_closure.sql (3.15ms)10632026/09/18 18:14:42 OK 2_object_stats_trigger.sql (2.16ms)10642026/09/18 18:14:42 goose: up to current file version: 210652026/09/18 18:14:42 OK 20241026095416_initial_model.sql (10.67ms)10662026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (2.15ms)10672026/09/18 18:14:42 OK 20251218171726_add_pins.sql (3.98ms)10682026-09-18 18:14:42.250 UTC [625] ERROR: relation "goose_db_version" does not exist at character 3610692026-09-18 18:14:42.250 UTC [625] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10702026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (5.03ms)10712026/09/18 18:14:42 OK 20260905000000_add_claims.sql (4.4ms)10722026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000010732026/09/18 18:14:42 OK 1_commit_pending_closure.sql (3.18ms)10742026/09/18 18:14:42 OK 2_object_stats_trigger.sql (3.36ms)10752026/09/18 18:14:42 goose: up to current file version: 210762026/09/18 18:14:42 OK 20241026095416_initial_model.sql (10.41ms)10772026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (1.29ms)10782026/09/18 18:14:42 OK 20251218171726_add_pins.sql (3.37ms)10792026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (2.72ms)10802026/09/18 18:14:42 OK 20260905000000_add_claims.sql (2.84ms)10812026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000010822026-09-18 18:14:42.278 UTC [643] ERROR: relation "goose_db_version" does not exist at character 3610832026-09-18 18:14:42.278 UTC [643] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10842026/09/18 18:14:42 OK 1_commit_pending_closure.sql (1.98ms)10852026/09/18 18:14:42 OK 2_object_stats_trigger.sql (788.13µs)10862026/09/18 18:14:42 goose: up to current file version: 210872026/09/18 18:14:42 OK 20241026095416_initial_model.sql (9.68ms)10882026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (1.22ms)10892026/09/18 18:14:42 OK 20251218171726_add_pins.sql (2.96ms)10902026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (3.36ms)10912026/09/18 18:14:42 OK 20260905000000_add_claims.sql (2.48ms)10922026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000010932026/09/18 18:14:42 OK 1_commit_pending_closure.sql (1.62ms)10942026/09/18 18:14:42 OK 2_object_stats_trigger.sql (714.37µs)10952026/09/18 18:14:42 goose: up to current file version: 210962026/09/18 18:14:42 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10972026/09/18 18:14:42 INFO Aborted multipart uploads count=010982026/09/18 18:14:42 WARN Force mode enabled - objects will be deleted immediately without grace period10992026/09/18 18:14:42 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=01100=== NAME TestNARDeduplicationMetadataUploadBug1101 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug3936865450/001/store/jrbfscq83bhr2rfhkywzi5qdz0v8xpzj-file1.txt11022026/09/18 18:14:42 INFO Vacuumed table table=pending_closures11032026/09/18 18:14:42 INFO Vacuumed table table=pending_objects11042026/09/18 18:14:42 INFO Vacuumed table table=multipart_uploads11052026/09/18 18:14:42 INFO Vacuumed table table=closures11062026/09/18 18:14:42 INFO Vacuumed table table=objects11072026/09/18 18:14:42 INFO Received cleanup request method=DELETE path=/api/pending_closures1108--- PASS: TestGCMetrics (0.78s)1109=== CONT TestReadProxy40411102026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures11112026/09/18 18:14:42 INFO Aborted multipart uploads count=11112--- PASS: TestMultipartCleanup (0.79s)1113=== CONT TestService_healthCheckHandler1114--- PASS: TestReadRedirectUsesPublicS3URL (0.81s)1115=== CONT TestClaim_TwoInstances1116--- PASS: TestReadRedirectNar (0.82s)1117=== CONT TestReadProxyNarStreaming11182026/09/18 18:14:42 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11192026-09-18 18:14:42.419 UTC [764] ERROR: relation "goose_db_version" does not exist at character 3611202026-09-18 18:14:42.419 UTC [764] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11212026/09/18 18:14:42 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11222026/09/18 18:14:42 OK 20241026095416_initial_model.sql (12.05ms)1123--- PASS: TestMetricsInventory (0.87s)11242026-09-18 18:14:42.439 UTC [783] ERROR: relation "goose_db_version" does not exist at character 3611252026-09-18 18:14:42.439 UTC [783] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1126=== CONT TestGracefulShutdownDrainsInflight11272026/09/18 18:14:42 INFO Starting HTTP server address=127.0.0.1:4490311282026/09/18 18:14:42 INFO Shutdown signal received, draining in-flight requests timeout=10s11292026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (2.29ms)11302026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures11312026/09/18 18:14:42 OK 20251218171726_add_pins.sql (4.72ms)11322026/09/18 18:14:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11332026/09/18 18:14:42 INFO Uploading jrbfscq83bhr2rfhkywzi5qdz0v8xpzj-file1.txt (160B)11342026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (4.86ms)11352026/09/18 18:14:42 OK 20260905000000_add_claims.sql (4.11ms)11362026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000011372026/09/18 18:14:42 OK 1_commit_pending_closure.sql (2.97ms)11382026/09/18 18:14:42 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11392026/09/18 18:14:42 OK 20241026095416_initial_model.sql (11.33ms)11402026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures11412026/09/18 18:14:42 OK 2_object_stats_trigger.sql (2.26ms)11422026/09/18 18:14:42 goose: up to current file version: 211432026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (1.72ms)11442026/09/18 18:14:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11452026/09/18 18:14:42 INFO Uploading pzidfyaacw9k2hrki0zwrjv3dizdwniz-shared-dep (136B)11462026/09/18 18:14:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11472026/09/18 18:14:42 WARN Failed to register uploaded object key=jrbfscq83bhr2rfhkywzi5qdz0v8xpzj.ls error="server returned 404: 404 page not found\n"11482026/09/18 18:14:42 INFO Signed narinfos id=1 count=111492026/09/18 18:14:42 INFO Uploading 1 narinfos11502026/09/18 18:14:42 OK 20251218171726_add_pins.sql (4.03ms)11512026-09-18 18:14:42.465 UTC [819] ERROR: relation "goose_db_version" does not exist at character 3611522026-09-18 18:14:42.465 UTC [819] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11532026/09/18 18:14:42 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11542026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (4.56ms)11552026/09/18 18:14:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11562026/09/18 18:14:42 WARN Failed to register uploaded object key=jrbfscq83bhr2rfhkywzi5qdz0v8xpzj.narinfo error="server returned 404: 404 page not found\n"11572026-09-18 18:14:42.473 UTC [820] ERROR: relation "goose_db_version" does not exist at character 3611582026-09-18 18:14:42.473 UTC [820] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11592026/09/18 18:14:42 OK 20260905000000_add_claims.sql (3.57ms)11602026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000011612026/09/18 18:14:42 WARN Failed to register uploaded object key=pzidfyaacw9k2hrki0zwrjv3dizdwniz.ls error="server returned 404: 404 page not found\n"11622026/09/18 18:14:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign11632026/09/18 18:14:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11642026/09/18 18:14:42 INFO Signed narinfos id=2 count=111652026/09/18 18:14:42 INFO Uploading 1 narinfos11662026/09/18 18:14:42 OK 1_commit_pending_closure.sql (2.76ms)11672026/09/18 18:14:42 INFO Completed upload id=111682026/09/18 18:14:42 INFO Upload complete. (111ms)11692026/09/18 18:14:42 OK 2_object_stats_trigger.sql (1.75ms)11702026/09/18 18:14:42 goose: up to current file version: 21171=== NAME TestNARDeduplicationMetadataUploadBug1172 metadata_upload_test.go:54: Retrieved narinfo from S3:1173 StorePath: /build/TestNARDeduplicationMetadataUploadBug3936865450/001/store/jrbfscq83bhr2rfhkywzi5qdz0v8xpzj-file1.txt1174 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1175 Compression: zstd1176 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1177 NarSize: 1601178 References: 1179 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf11802026/09/18 18:14:42 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11812026/09/18 18:14:42 WARN Failed to register uploaded object key=pzidfyaacw9k2hrki0zwrjv3dizdwniz.narinfo error="server returned 404: 404 page not found\n"11822026/09/18 18:14:42 OK 20241026095416_initial_model.sql (11.41ms)1183 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1184 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1185 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}11862026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (2.11ms)1187=== NAME TestClientMultipleUploads1188 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads2033223312/001/store/s4nrlcdip73q55wnv9klrq4p7y9na4fh-test-file-0.txt11892026/09/18 18:14:42 INFO Completed upload id=211902026/09/18 18:14:42 INFO Upload complete. (109ms)11912026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures11922026/09/18 18:14:42 OK 20241026095416_initial_model.sql (18.76ms)11932026/09/18 18:14:42 OK 20251218171726_add_pins.sql (12.55ms)11942026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (1.93ms)11952026/09/18 18:14:42 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YjQ1MzhkY2YtNTZmMS00YjI1LTljOTgtOWU0NjYwYmIyZjBmLjk0MTFjOWM3LWQxZjctNGZkNi1hNTg2LWYxZjNlMzFlYzg4NHgxNzg5NzU1MjgxOTAwNzU1ODk4 parts=1211962026/09/18 18:14:42 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)11972026/09/18 18:14:42 INFO Uploading 5365f892fz63wpm8wfh7rg4lr2lrr942-top (224B)11982026/09/18 18:14:42 INFO Uploading pzidfyaacw9k2hrki0zwrjv3dizdwniz-shared-dep (136B)11992026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures12002026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (4.99ms)12012026/09/18 18:14:42 OK 20251218171726_add_pins.sql (3.64ms)1202--- PASS: TestGCBugBareHashReferences (0.94s)1203=== CONT TestClaim_StaleHeartbeatStolen1204--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.94s)1205=== CONT TestReadProxyNarinfoAlreadyDecompressed12062026/09/18 18:14:42 WARN Failed to register uploaded object key=nar/1dap5w17ldy7hdn4c34rmnlwgv5m0c8185m30a321x59hmj1lq2s.nar.zst error="server returned 404: 404 page not found\n"1207--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1208=== CONT TestClaim_FailWithoutKindReleases12092026/09/18 18:14:42 OK 20260905000000_add_claims.sql (4.86ms)12102026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000012112026/09/18 18:14:42 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12122026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (4.55ms)12132026/09/18 18:14:42 OK 1_commit_pending_closure.sql (2.47ms)12142026/09/18 18:14:42 OK 20260905000000_add_claims.sql (3.16ms)12152026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000012162026/09/18 18:14:42 WARN Failed to register uploaded object key=5365f892fz63wpm8wfh7rg4lr2lrr942.ls error="server returned 404: 404 page not found\n"12172026/09/18 18:14:42 OK 2_object_stats_trigger.sql (1.22ms)12182026/09/18 18:14:42 goose: up to current file version: 212192026/09/18 18:14:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12202026/09/18 18:14:42 WARN Failed to register uploaded object key=pzidfyaacw9k2hrki0zwrjv3dizdwniz.ls error="server returned 404: 404 page not found\n"12212026/09/18 18:14:42 OK 1_commit_pending_closure.sql (1.9ms)12222026/09/18 18:14:42 INFO Signed narinfos id=1 count=112232026/09/18 18:14:42 OK 2_object_stats_trigger.sql (1.39ms)12242026/09/18 18:14:42 goose: up to current file version: 212252026/09/18 18:14:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign12262026/09/18 18:14:42 INFO Signed narinfos id=3 count=112272026/09/18 18:14:42 INFO Uploading 2 narinfos1228=== NAME TestNARDeduplicationMetadataUploadBug1229 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug3936865450/001/store/1lj1qak3xrdybmljsdcix5mp46v4vpal-file2.txt12302026/09/18 18:14:42 WARN Failed to register uploaded object key=5365f892fz63wpm8wfh7rg4lr2lrr942.narinfo error="server returned 404: 404 page not found\n"1231=== NAME TestClientMultipleUploads1232 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads2033223312/001/store/2ba8lsiv6ar7491g1npgq3bmi418gzmx-test-file-1.txt12332026/09/18 18:14:42 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete12342026/09/18 18:14:42 WARN Failed to register uploaded object key=pzidfyaacw9k2hrki0zwrjv3dizdwniz.narinfo error="server returned 404: 404 page not found\n"1235=== NAME TestClientIntegration1236 client_integration_test.go:286: Created store path: /build/TestClientIntegration1238329868/002/store/phngmrymbws4f14yqh49w7yp33bya8y5-test-file.txt12372026/09/18 18:14:42 INFO Completed upload id=312382026/09/18 18:14:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12392026/09/18 18:14:42 INFO Completed upload id=112402026/09/18 18:14:42 INFO Upload complete. (254ms)1241=== NAME TestClientSharedPathCommittedMidPush1242 client_integration_test.go:680: Retrieved narinfo from S3:1243 StorePath: /build/TestClientSharedPathCommittedMidPush3256663238/001/store/pzidfyaacw9k2hrki0zwrjv3dizdwniz-shared-dep1244 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1245 Compression: zstd1246 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821247 NarSize: 1361248 References: 1249 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1250 client_integration_test.go:680: Retrieved narinfo from S3:1251 StorePath: /build/TestClientSharedPathCommittedMidPush3256663238/001/store/5365f892fz63wpm8wfh7rg4lr2lrr942-top1252 URL: nar/1dap5w17ldy7hdn4c34rmnlwgv5m0c8185m30a321x59hmj1lq2s.nar.zst1253 Compression: zstd1254 NarHash: sha256:1dap5w17ldy7hdn4c34rmnlwgv5m0c8185m30a321x59hmj1lq2s1255 NarSize: 2241256 References: /build/TestClientSharedPathCommittedMidPush3256663238/001/store/pzidfyaacw9k2hrki0zwrjv3dizdwniz-shared-dep1257 CA: text:sha256:0k8ngzafscn1w89z7z3p846xwyr7aq4rxss55301kyzkx1i68xv41258--- PASS: TestClientSharedPathCommittedMidPush (0.98s)1259=== CONT TestReadProxyNarinfo1260=== NAME TestClientMultipleUploads1261 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads2033223312/001/store/gkjn51gnhbx7sx2barkqa8q6n6y329zz-test-file-2.txt1262--- PASS: TestReadProxyDisabled (0.99s)1263=== CONT TestGCTaskStore_Fail1264--- PASS: TestGCTaskStore_Fail (0.00s)1265=== CONT TestClaim_FailWakesWaitersButIsNotRemembered1266=== NAME TestPinProtectsFromGC1267 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC433316085/001/store/ik92ab2ci9yzjf32j72bgc3kn6q3b9d6-pinned-file.txt1268 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC433316085/001/store/7k09n7wjhh21pg431jr8m7qyg7xklb54-unpinned-file.txt12692026/09/18 18:14:42 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12702026-09-18 18:14:42.592 UTC [1038] ERROR: relation "goose_db_version" does not exist at character 3612712026-09-18 18:14:42.592 UTC [1038] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12722026-09-18 18:14:42.593 UTC [1039] ERROR: relation "goose_db_version" does not exist at character 3612732026-09-18 18:14:42.593 UTC [1039] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12742026-09-18 18:14:42.594 UTC [1040] ERROR: relation "goose_db_version" does not exist at character 3612752026-09-18 18:14:42.594 UTC [1040] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1276--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.75s)1277=== CONT TestIsValidCachePath1278=== RUN TestIsValidCachePath/narinfo1279=== PAUSE TestIsValidCachePath/narinfo1280=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1281=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1282=== RUN TestIsValidCachePath/nar_zst1283=== PAUSE TestIsValidCachePath/nar_zst1284=== RUN TestIsValidCachePath/nar_xz1285=== PAUSE TestIsValidCachePath/nar_xz1286=== RUN TestIsValidCachePath/nar_bz21287=== PAUSE TestIsValidCachePath/nar_bz21288=== RUN TestIsValidCachePath/nar_uncompressed1289=== PAUSE TestIsValidCachePath/nar_uncompressed1290=== RUN TestIsValidCachePath/ls1291=== PAUSE TestIsValidCachePath/ls1292=== RUN TestIsValidCachePath/log1293=== PAUSE TestIsValidCachePath/log1294=== RUN TestIsValidCachePath/realisation1295=== PAUSE TestIsValidCachePath/realisation12962026/09/18 18:14:42 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1297=== RUN TestIsValidCachePath/nix-cache-info1298=== PAUSE TestIsValidCachePath/nix-cache-info1299=== RUN TestIsValidCachePath/index.html1300=== PAUSE TestIsValidCachePath/index.html1301=== RUN TestIsValidCachePath/traversal_parent1302=== PAUSE TestIsValidCachePath/traversal_parent1303=== RUN TestIsValidCachePath/traversal_in_middle1304=== PAUSE TestIsValidCachePath/traversal_in_middle1305=== RUN TestIsValidCachePath/invalid_char_e1306=== PAUSE TestIsValidCachePath/invalid_char_e1307=== RUN TestIsValidCachePath/invalid_char_u1308=== PAUSE TestIsValidCachePath/invalid_char_u1309=== RUN TestIsValidCachePath/random_path1310=== PAUSE TestIsValidCachePath/random_path1311=== RUN TestIsValidCachePath/empty1312=== PAUSE TestIsValidCachePath/empty1313=== RUN TestIsValidCachePath/leading_slash1314=== PAUSE TestIsValidCachePath/leading_slash1315=== RUN TestIsValidCachePath/wrong_extension1316=== PAUSE TestIsValidCachePath/wrong_extension1317=== RUN TestIsValidCachePath/short_hash1318=== PAUSE TestIsValidCachePath/short_hash1319=== CONT TestClaim_HolderDisconnectKeepsClaim13202026/09/18 18:14:42 OK 20241026095416_initial_model.sql (12.94ms)13212026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (3.58ms)13222026/09/18 18:14:42 OK 20241026095416_initial_model.sql (12.19ms)13232026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures13242026/09/18 18:14:42 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13252026/09/18 18:14:42 OK 20251218171726_add_pins.sql (4.82ms)13262026/09/18 18:14:42 OK 20241026095416_initial_model.sql (14.65ms)13272026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (4.19ms)13282026/09/18 18:14:42 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)13292026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (3.25ms)13302026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (5.25ms)13312026/09/18 18:14:42 OK 20251218171726_add_pins.sql (4.73ms)13322026/09/18 18:14:42 OK 20251218171726_add_pins.sql (5.53ms)13332026/09/18 18:14:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13342026/09/18 18:14:42 WARN Failed to register uploaded object key=1lj1qak3xrdybmljsdcix5mp46v4vpal.ls error="server returned 404: 404 page not found\n"13352026/09/18 18:14:42 INFO Signed narinfos id=2 count=113362026/09/18 18:14:42 OK 20260905000000_add_claims.sql (6.2ms)13372026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000013382026/09/18 18:14:42 INFO Uploading 1 narinfos13392026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (5.34ms)13402026/09/18 18:14:42 OK 1_commit_pending_closure.sql (3.2ms)13412026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (5.91ms)13422026/09/18 18:14:42 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13432026/09/18 18:14:42 OK 2_object_stats_trigger.sql (2.19ms)13442026/09/18 18:14:42 goose: up to current file version: 213452026/09/18 18:14:42 WARN Failed to register uploaded object key=1lj1qak3xrdybmljsdcix5mp46v4vpal.narinfo error="server returned 404: 404 page not found\n"13462026/09/18 18:14:42 OK 20260905000000_add_claims.sql (4.64ms)13472026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000013482026/09/18 18:14:42 INFO Completed upload id=213492026/09/18 18:14:42 INFO Upload complete. (93ms)13502026/09/18 18:14:42 OK 1_commit_pending_closure.sql (2.64ms)13512026-09-18 18:14:42.643 UTC [1134] ERROR: relation "goose_db_version" does not exist at character 3613522026-09-18 18:14:42.643 UTC [1134] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1353=== NAME TestNARDeduplicationMetadataUploadBug1354 metadata_upload_test.go:76: Retrieved narinfo from S3:13552026/09/18 18:14:42 OK 20260905000000_add_claims.sql (4.77ms)1356 StorePath: /build/TestNARDeduplicationMetadataUploadBug3936865450/001/store/1lj1qak3xrdybmljsdcix5mp46v4vpal-file2.txt13572026/09/18 18:14:42 goose: successfully migrated database to version: 202609050000001358 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1359 Compression: zstd1360 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1361 NarSize: 1601362 References: 1363 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf13642026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures13652026/09/18 18:14:42 OK 2_object_stats_trigger.sql (1.88ms)13662026/09/18 18:14:42 goose: up to current file version: 213672026/09/18 18:14:42 OK 1_commit_pending_closure.sql (2.94ms)1368 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1369 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1370 {"version":1,"root":{"type":"regular","size":44}}13712026/09/18 18:14:42 OK 2_object_stats_trigger.sql (2.12ms)13722026/09/18 18:14:42 goose: up to current file version: 21373--- PASS: TestNARDeduplicationMetadataUploadBug (1.09s)1374=== CONT TestProxyWriteTimeout1375=== RUN TestProxyWriteTimeout/narinfo1376=== PAUSE TestProxyWriteTimeout/narinfo1377=== RUN TestProxyWriteTimeout/1_GiB_nar1378=== PAUSE TestProxyWriteTimeout/1_GiB_nar1379=== RUN TestProxyWriteTimeout/10_GiB_nar1380=== PAUSE TestProxyWriteTimeout/10_GiB_nar1381=== RUN TestProxyWriteTimeout/unknown_size1382=== PAUSE TestProxyWriteTimeout/unknown_size1383=== CONT TestClaim_TooManyStreams13842026/09/18 18:14:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13852026/09/18 18:14:42 INFO Uploading phngmrymbws4f14yqh49w7yp33bya8y5-test-file.txt (152B)13862026-09-18 18:14:42.655 UTC [1136] ERROR: relation "goose_db_version" does not exist at character 3613872026-09-18 18:14:42.655 UTC [1136] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13882026/09/18 18:14:42 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13892026/09/18 18:14:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13902026/09/18 18:14:42 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"13912026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures13922026/09/18 18:14:42 WARN Failed to register uploaded object key=phngmrymbws4f14yqh49w7yp33bya8y5.ls error="server returned 404: 404 page not found\n"13932026/09/18 18:14:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13942026/09/18 18:14:42 OK 20241026095416_initial_model.sql (12.18ms)13952026/09/18 18:14:42 INFO Signed narinfos id=1 count=113962026/09/18 18:14:42 INFO Uploading 1 narinfos13972026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (2.02ms)13982026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures13992026/09/18 18:14:42 OK 20251218171726_add_pins.sql (4.39ms)14002026/09/18 18:14:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14012026/09/18 18:14:42 WARN Failed to register uploaded object key=phngmrymbws4f14yqh49w7yp33bya8y5.narinfo error="server returned 404: 404 page not found\n"1402--- PASS: TestReadProxyConditionalGet (0.70s)1403=== CONT TestUploadHandlersRejectInvalidKeys1404=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1405=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1406=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1407=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1408=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1409=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1410=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1411=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1412=== CONT TestClaim_GCMarkedOutputCountsAsAbsent14132026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures14142026-09-18 18:14:42.673 UTC [1192] ERROR: relation "goose_db_version" does not exist at character 3614152026-09-18 18:14:42.673 UTC [1192] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14162026/09/18 18:14:42 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)14172026/09/18 18:14:42 INFO Uploading s4nrlcdip73q55wnv9klrq4p7y9na4fh-test-file-0.txt (160B)14182026/09/18 18:14:42 INFO Uploading gkjn51gnhbx7sx2barkqa8q6n6y329zz-test-file-2.txt (160B)14192026/09/18 18:14:42 INFO Uploading 2ba8lsiv6ar7491g1npgq3bmi418gzmx-test-file-1.txt (160B)14202026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (5.93ms)14212026/09/18 18:14:42 OK 20241026095416_initial_model.sql (13.22ms)14222026/09/18 18:14:42 INFO Completed upload id=114232026/09/18 18:14:42 INFO Upload complete. (119ms)14242026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (1.55ms)14252026/09/18 18:14:42 OK 20260905000000_add_claims.sql (4.07ms)14262026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000014272026/09/18 18:14:42 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"14282026/09/18 18:14:42 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"14292026/09/18 18:14:42 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YjQ1MzhkY2YtNTZmMS00YjI1LTljOTgtOWU0NjYwYmIyZjBmLmMzMzg1ZGVmLTNmYjgtNGFhOS04ZmRjLTI3MjFkZmNiNWViMXgxNzg5NzU1MjgyMDY3NTM2NzMx parts=1214302026/09/18 18:14:42 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"14312026/09/18 18:14:42 OK 20251218171726_add_pins.sql (5.3ms)1432--- PASS: TestRedundantMultipartUpload (1.12s)1433=== CONT TestIsValidUploadKey1434=== RUN TestIsValidUploadKey/narinfo1435=== PAUSE TestIsValidUploadKey/narinfo1436=== RUN TestIsValidUploadKey/nar_zst1437=== PAUSE TestIsValidUploadKey/nar_zst1438=== RUN TestIsValidUploadKey/nar_xz1439=== PAUSE TestIsValidUploadKey/nar_xz1440=== RUN TestIsValidUploadKey/nar_plain1441=== PAUSE TestIsValidUploadKey/nar_plain1442=== RUN TestIsValidUploadKey/listing1443=== PAUSE TestIsValidUploadKey/listing1444=== RUN TestIsValidUploadKey/build_log1445=== PAUSE TestIsValidUploadKey/build_log1446=== RUN TestIsValidUploadKey/build_log_home-manager_file1447=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1448=== RUN TestIsValidUploadKey/build_log_plus_in_name14492026/09/18 18:14:42 OK 1_commit_pending_closure.sql (4.26ms)1450=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1451=== RUN TestIsValidUploadKey/build_log_question_mark1452=== PAUSE TestIsValidUploadKey/build_log_question_mark1453=== RUN TestIsValidUploadKey/build_log_equals1454=== PAUSE TestIsValidUploadKey/build_log_equals1455=== RUN TestIsValidUploadKey/realisation1456=== PAUSE TestIsValidUploadKey/realisation1457=== RUN TestIsValidUploadKey/realisation_plus_in_output1458=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1459=== RUN TestIsValidUploadKey/nix-cache-info1460=== PAUSE TestIsValidUploadKey/nix-cache-info1461=== RUN TestIsValidUploadKey/index.html1462=== PAUSE TestIsValidUploadKey/index.html1463=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1464=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1465=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1466=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type14672026/09/18 18:14:42 WARN Failed to register uploaded object key=s4nrlcdip73q55wnv9klrq4p7y9na4fh.ls error="server returned 404: 404 page not found\n"1468=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1469=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1470=== RUN TestIsValidUploadKey/traversal1471=== PAUSE TestIsValidUploadKey/traversal1472=== RUN TestIsValidUploadKey/traversal_nar1473=== PAUSE TestIsValidUploadKey/traversal_nar1474=== RUN TestIsValidUploadKey/absolute1475=== PAUSE TestIsValidUploadKey/absolute1476=== RUN TestIsValidUploadKey/empty_key1477=== PAUSE TestIsValidUploadKey/empty_key1478=== RUN TestIsValidUploadKey/unknown_type1479=== PAUSE TestIsValidUploadKey/unknown_type1480=== CONT TestClaim_BuildWaitComplete14812026/09/18 18:14:42 WARN Failed to register uploaded object key=gkjn51gnhbx7sx2barkqa8q6n6y329zz.ls error="server returned 404: 404 page not found\n"14822026/09/18 18:14:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign14832026/09/18 18:14:42 WARN Failed to register uploaded object key=2ba8lsiv6ar7491g1npgq3bmi418gzmx.ls error="server returned 404: 404 page not found\n"14842026/09/18 18:14:42 OK 2_object_stats_trigger.sql (2.3ms)14852026/09/18 18:14:42 goose: up to current file version: 214862026/09/18 18:14:42 INFO Signed narinfos id=3 count=114872026/09/18 18:14:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14882026/09/18 18:14:42 INFO Signed narinfos id=1 count=114892026/09/18 18:14:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14902026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (5.06ms)14912026/09/18 18:14:42 INFO Signed narinfos id=2 count=114922026/09/18 18:14:42 INFO Uploading 3 narinfos14932026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures14942026/09/18 18:14:42 OK 20241026095416_initial_model.sql (13.3ms)14952026/09/18 18:14:42 OK 20260905000000_add_claims.sql (4.71ms)14962026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000014972026/09/18 18:14:42 WARN Failed to register uploaded object key=gkjn51gnhbx7sx2barkqa8q6n6y329zz.narinfo error="server returned 404: 404 page not found\n"14982026/09/18 18:14:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14992026/09/18 18:14:42 WARN Failed to register uploaded object key=2ba8lsiv6ar7491g1npgq3bmi418gzmx.narinfo error="server returned 404: 404 page not found\n"15002026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (3.21ms)15012026/09/18 18:14:42 WARN Failed to register uploaded object key=s4nrlcdip73q55wnv9klrq4p7y9na4fh.narinfo error="server returned 404: 404 page not found\n"15022026/09/18 18:14:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15032026/09/18 18:14:42 INFO Uploading ik92ab2ci9yzjf32j72bgc3kn6q3b9d6-pinned-file.txt (128B)15042026/09/18 18:14:42 OK 1_commit_pending_closure.sql (4.18ms)15052026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures15062026/09/18 18:14:42 OK 20251218171726_add_pins.sql (4.03ms)15072026/09/18 18:14:42 OK 2_object_stats_trigger.sql (2.95ms)15082026/09/18 18:14:42 goose: up to current file version: 215092026/09/18 18:14:42 INFO Completed upload id=115102026/09/18 18:14:42 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15112026/09/18 18:14:42 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"15122026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (5.09ms)15132026/09/18 18:14:42 INFO Completed upload id=215142026/09/18 18:14:42 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete15152026/09/18 18:14:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15162026/09/18 18:14:42 WARN Failed to register uploaded object key=ik92ab2ci9yzjf32j72bgc3kn6q3b9d6.ls error="server returned 404: 404 page not found\n"15172026/09/18 18:14:42 INFO Signed narinfos id=1 count=115182026/09/18 18:14:42 INFO Uploading 1 narinfos15192026/09/18 18:14:42 INFO Completed upload id=315202026/09/18 18:14:42 INFO Upload complete. (127ms)1521=== NAME TestClientMultipleUploads1522 client_integration_test.go:369: Uploaded 3 paths in 155.780755ms15232026/09/18 18:14:42 OK 20260905000000_add_claims.sql (6.2ms)15242026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000015252026/09/18 18:14:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15262026/09/18 18:14:42 WARN Failed to register uploaded object key=ik92ab2ci9yzjf32j72bgc3kn6q3b9d6.narinfo error="server returned 404: 404 page not found\n"15272026/09/18 18:14:42 INFO All 1 paths already cached1528=== NAME TestClientCADerivations1529 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations965318734/001/store/iwxymwv7ifl5q84c4b0jyczyji5vqx6v-ca-test15302026/09/18 18:14:42 OK 1_commit_pending_closure.sql (11.54ms)1531=== NAME TestClientIntegration1532 client_integration_test.go:312: Retrieved narinfo from S3:15332026/09/18 18:14:42 INFO Completed upload id=11534 StorePath: /build/TestClientIntegration1238329868/002/store/phngmrymbws4f14yqh49w7yp33bya8y5-test-file.txt1535 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1536 Compression: zstd1537 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11538 NarSize: 1521539 References: 1540 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk115412026/09/18 18:14:42 INFO Upload complete. (108ms)1542--- PASS: TestClientMultipleUploads (1.16s)1543=== CONT TestParseSingleRange1544=== RUN TestParseSingleRange/none1545=== PAUSE TestParseSingleRange/none1546=== RUN TestParseSingleRange/unknown_unit1547=== PAUSE TestParseSingleRange/unknown_unit1548=== RUN TestParseSingleRange/multi-range_ignored1549=== PAUSE TestParseSingleRange/multi-range_ignored1550=== RUN TestParseSingleRange/malformed_no_dash1551=== PAUSE TestParseSingleRange/malformed_no_dash1552=== RUN TestParseSingleRange/malformed_both_empty1553=== PAUSE TestParseSingleRange/malformed_both_empty1554=== RUN TestParseSingleRange/malformed_end_before_start1555=== PAUSE TestParseSingleRange/malformed_end_before_start1556=== RUN TestParseSingleRange/closed1557=== PAUSE TestParseSingleRange/closed1558=== RUN TestParseSingleRange/open-ended1559=== PAUSE TestParseSingleRange/open-ended1560=== RUN TestParseSingleRange/end_clamped_to_size1561=== PAUSE TestParseSingleRange/end_clamped_to_size1562=== RUN TestParseSingleRange/suffix1563=== PAUSE TestParseSingleRange/suffix1564=== RUN TestParseSingleRange/suffix_exceeds_size1565=== PAUSE TestParseSingleRange/suffix_exceeds_size1566=== RUN TestParseSingleRange/single_byte1567=== PAUSE TestParseSingleRange/single_byte1568=== RUN TestParseSingleRange/start_past_EOF1569=== PAUSE TestParseSingleRange/start_past_EOF1570=== RUN TestParseSingleRange/start_far_past_EOF1571=== PAUSE TestParseSingleRange/start_far_past_EOF1572=== CONT TestService_verifyS3Integrity15732026/09/18 18:14:42 OK 2_object_stats_trigger.sql (2.27ms)15742026/09/18 18:14:42 goose: up to current file version: 21575=== NAME TestClientIntegration1576 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1577 client_integration_test.go:313: Decompressed .ls content (64 bytes):1578 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1579 client_integration_test.go:316: Testing garbage collection...1580--- PASS: TestReadProxyHead (0.66s)1581=== CONT TestCacheStatsHandler15822026-09-18 18:14:42.749 UTC [1258] ERROR: relation "goose_db_version" does not exist at character 3615832026-09-18 18:14:42.749 UTC [1258] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1584=== NAME TestClientCADerivations1585 client_ca_test.go:139: Found 1 dependencies (including self)15862026/09/18 18:14:42 INFO Starting cleanup of old closures method=DELETE path=/api/closures15872026/09/18 18:14:42 INFO Garbage collection started15882026-09-18 18:14:42.765 UTC [1293] ERROR: relation "goose_db_version" does not exist at character 3615892026-09-18 18:14:42.765 UTC [1293] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15902026-09-18 18:14:42.766 UTC [1312] ERROR: relation "goose_db_version" does not exist at character 3615912026-09-18 18:14:42.766 UTC [1312] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15922026/09/18 18:14:42 INFO Aborted multipart uploads count=015932026/09/18 18:14:42 OK 20241026095416_initial_model.sql (13.93ms)15942026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (3.16ms)15952026/09/18 18:14:42 WARN Force mode enabled - objects will be deleted immediately without grace period15962026/09/18 18:14:42 OK 20251218171726_add_pins.sql (3.79ms)15972026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (5.75ms)15982026/09/18 18:14:42 OK 20241026095416_initial_model.sql (11.57ms)15992026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (2.51ms)16002026/09/18 18:14:42 OK 20260905000000_add_claims.sql (4.65ms)16012026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000016022026/09/18 18:14:42 OK 20251218171726_add_pins.sql (4.22ms)16032026/09/18 18:14:42 OK 1_commit_pending_closure.sql (3.29ms)16042026/09/18 18:14:42 OK 20241026095416_initial_model.sql (17.48ms)16052026/09/18 18:14:42 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16062026/09/18 18:14:42 OK 2_object_stats_trigger.sql (2.22ms)16072026/09/18 18:14:42 goose: up to current file version: 21608--- PASS: TestReadProxyInvalidPath (0.65s)1609=== CONT TestResurrectedObjectNotDeleted16102026-09-18 18:14:42.804 UTC [1350] ERROR: relation "goose_db_version" does not exist at character 3616112026-09-18 18:14:42.804 UTC [1350] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16122026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (11.77ms)16132026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (13.86ms)16142026/09/18 18:14:42 OK 20251218171726_add_pins.sql (4.41ms)16152026/09/18 18:14:42 OK 20260905000000_add_claims.sql (3.59ms)16162026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000016172026/09/18 18:14:42 OK 1_commit_pending_closure.sql (3.19ms)16182026/09/18 18:14:42 OK 2_object_stats_trigger.sql (1.28ms)16192026/09/18 18:14:42 goose: up to current file version: 216202026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (5.17ms)16212026-09-18 18:14:42.816 UTC [1354] ERROR: relation "goose_db_version" does not exist at character 3616222026-09-18 18:14:42.816 UTC [1354] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16232026/09/18 18:14:42 OK 20260905000000_add_claims.sql (5.71ms)16242026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000016252026/09/18 18:14:42 OK 20241026095416_initial_model.sql (12.04ms)16262026/09/18 18:14:42 OK 1_commit_pending_closure.sql (3.53ms)16272026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (3.01ms)16282026/09/18 18:14:42 OK 2_object_stats_trigger.sql (2.8ms)16292026/09/18 18:14:42 goose: up to current file version: 216302026/09/18 18:14:42 OK 20251218171726_add_pins.sql (4.47ms)16312026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures16322026/09/18 18:14:42 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16332026/09/18 18:14:42 OK 20241026095416_initial_model.sql (9.31ms)16342026/09/18 18:14:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16352026/09/18 18:14:42 INFO Uploading 7k09n7wjhh21pg431jr8m7qyg7xklb54-unpinned-file.txt (128B)16362026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (5.05ms)16372026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (2.74ms)16382026/09/18 18:14:42 WARN readiness check failed error="closed pool"1639--- PASS: TestService_readinessHandler (0.67s)1640=== CONT TestUploadHandlersRejectOversizedBody16412026/09/18 18:14:42 OK 20260905000000_add_claims.sql (4.55ms)16422026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000016432026/09/18 18:14:42 OK 20251218171726_add_pins.sql (5.17ms)16442026/09/18 18:14:42 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"16452026/09/18 18:14:42 OK 1_commit_pending_closure.sql (3.26ms)16462026/09/18 18:14:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16472026/09/18 18:14:42 WARN Failed to register uploaded object key=7k09n7wjhh21pg431jr8m7qyg7xklb54.ls error="server returned 404: 404 page not found\n"16482026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (4.63ms)16492026/09/18 18:14:42 INFO Signed narinfos id=2 count=116502026/09/18 18:14:42 INFO Uploading 1 narinfos16512026/09/18 18:14:42 OK 2_object_stats_trigger.sql (3.14ms)16522026/09/18 18:14:42 goose: up to current file version: 216532026/09/18 18:14:42 OK 20260905000000_add_claims.sql (3.95ms)16542026/09/18 18:14:42 goose: successfully migrated database to version: 2026090500000016552026/09/18 18:14:42 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16562026/09/18 18:14:42 WARN Failed to register uploaded object key=7k09n7wjhh21pg431jr8m7qyg7xklb54.narinfo error="server returned 404: 404 page not found\n"16572026/09/18 18:14:42 OK 1_commit_pending_closure.sql (2.88ms)16582026/09/18 18:14:42 INFO Completed upload id=216592026/09/18 18:14:42 INFO Upload complete. (97ms)16602026/09/18 18:14:42 OK 2_object_stats_trigger.sql (2.23ms)16612026/09/18 18:14:42 goose: up to current file version: 216622026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures16632026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures16642026-09-18 18:14:42.871 UTC [1408] ERROR: relation "goose_db_version" does not exist at character 3616652026-09-18 18:14:42.871 UTC [1408] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16662026/09/18 18:14:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16672026/09/18 18:14:42 INFO Uploading iwxymwv7ifl5q84c4b0jyczyji5vqx6v-ca-test (144B)16682026/09/18 18:14:42 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"16692026/09/18 18:14:42 WARN Failed to register uploaded object key=log/w9x1cf2frfcir4y1swd6bjr3fy0snpkc-ca-test.drv error="server returned 404: 404 page not found\n"16702026/09/18 18:14:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16712026/09/18 18:14:42 WARN Failed to register uploaded object key=iwxymwv7ifl5q84c4b0jyczyji5vqx6v.ls error="server returned 404: 404 page not found\n"16722026/09/18 18:14:42 INFO Signed narinfos id=1 count=116732026/09/18 18:14:42 INFO Uploading 1 narinfos16742026/09/18 18:14:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16752026/09/18 18:14:42 OK 20241026095416_initial_model.sql (12.78ms)16762026/09/18 18:14:42 WARN Failed to register uploaded object key=iwxymwv7ifl5q84c4b0jyczyji5vqx6v.narinfo error="server returned 404: 404 page not found\n"16772026/09/18 18:14:42 OK 20251210153512_drop_unused_gin_index.sql (1.93ms)16782026/09/18 18:14:42 INFO Received create pin request method=POST path=/api/pins/myapp16792026/09/18 18:14:42 OK 20251218171726_add_pins.sql (3.82ms)16802026/09/18 18:14:42 INFO Completed upload id=116812026/09/18 18:14:42 INFO Upload complete. (103ms)1682=== NAME TestOrphanedObjectsGC1683 orphaned_objects_gc_test.go:290: GC Test Summary:1684 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1685 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1686 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1687 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1688 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1689--- PASS: TestOrphanedObjectsGC (1.33s)1690=== CONT TestOrphanedObjectsGCStressTest16912026/09/18 18:14:42 OK 20260628120000_add_object_size_and_stats.sql (3.34ms)1692--- PASS: TestReadProxy404 (0.56s)1693=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT1694=== NAME TestClientCADerivations1695 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations965318734/001/store/iwxymwv7ifl5q84c4b0jyczyji5vqx6v-ca-test1696 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1697 Compression: zstd1698 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1699 NarSize: 1441700 References: 1701 Deriver: /build/TestClientCADerivations965318734/001/store/w9x1cf2frfcir4y1swd6bjr3fy0snpkc-ca-test.drv1702 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1703 client_ca_test.go:185: Checking for realisation files in S3...17042026/09/18 18:14:42 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC433316085/001/store/ik92ab2ci9yzjf32j72bgc3kn6q3b9d6-pinned-file.txt narinfo_key=ik92ab2ci9yzjf32j72bgc3kn6q3b9d6.narinfo17052026/09/18 18:14:42 OK 20260905000000_add_claims.sql (3.07ms)17062026/09/18 18:14:42 goose: successfully migrated database to version: 202609050000001707 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1708 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache17092026/09/18 18:14:42 INFO Starting cleanup of old closures method=DELETE path=/api/closures17102026/09/18 18:14:42 INFO Garbage collection started17112026/09/18 18:14:42 OK 1_commit_pending_closure.sql (2.06ms)17122026/09/18 18:14:42 OK 2_object_stats_trigger.sql (1.25ms)17132026/09/18 18:14:42 goose: up to current file version: 217142026/09/18 18:14:42 INFO Aborted multipart uploads count=017152026/09/18 18:14:42 WARN Force mode enabled - objects will be deleted immediately without grace period1716--- PASS: TestService_healthCheckHandler (0.57s)1717=== CONT TestService_createPendingClosureHandler17182026/09/18 18:14:42 WARN claim: cannot clear write deadline error="feature not supported"17192026/09/18 18:14:42 WARN claim: cannot clear write deadline error="feature not supported"17202026/09/18 18:14:42 WARN claim: cannot clear write deadline error="feature not supported"17212026/09/18 18:14:42 INFO Received uploads request method=POST path=/api/pending_closures17222026-09-18 18:14:42.985 UTC [1521] ERROR: relation "goose_db_version" does not exist at character 3617232026-09-18 18:14:42.985 UTC [1521] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1724--- PASS: TestReadProxyNarStreaming (0.60s)1725=== CONT TestService_AuthMiddleware_OIDC17262026/09/18 18:14:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33731/oidc17272026/09/18 18:14:43 OK 20241026095416_initial_model.sql (9.19ms)17282026-09-18 18:14:43.001 UTC [1523] ERROR: relation "goose_db_version" does not exist at character 3617292026-09-18 18:14:43.001 UTC [1523] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17302026/09/18 18:14:43 OK 20251210153512_drop_unused_gin_index.sql (1.22ms)17312026/09/18 18:14:43 OK 20251218171726_add_pins.sql (3.53ms)17322026/09/18 18:14:43 WARN claim: cannot clear write deadline error="feature not supported"17332026/09/18 18:14:43 OK 20260628120000_add_object_size_and_stats.sql (4.26ms)17342026-09-18 18:14:43.012 UTC [1525] ERROR: relation "goose_db_version" does not exist at character 3617352026-09-18 18:14:43.012 UTC [1525] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17362026/09/18 18:14:43 OK 20260905000000_add_claims.sql (5.18ms)17372026/09/18 18:14:43 goose: successfully migrated database to version: 2026090500000017382026/09/18 18:14:43 OK 1_commit_pending_closure.sql (3.62ms)17392026/09/18 18:14:43 WARN claim: cannot clear write deadline error="feature not supported"17402026/09/18 18:14:43 OK 2_object_stats_trigger.sql (1.83ms)17412026/09/18 18:14:43 goose: up to current file version: 21742--- PASS: TestClaim_FailWithoutKindReleases (0.52s)1743=== CONT TestService_cleanupPendingClosuresHandler17442026/09/18 18:14:43 OK 20241026095416_initial_model.sql (11.45ms)17452026/09/18 18:14:43 OK 20251210153512_drop_unused_gin_index.sql (2.4ms)17462026/09/18 18:14:43 OK 20251218171726_add_pins.sql (4.19ms)17472026/09/18 18:14:43 OK 20241026095416_initial_model.sql (12.18ms)17482026/09/18 18:14:43 OK 20251210153512_drop_unused_gin_index.sql (2.95ms)17492026/09/18 18:14:43 OK 20260628120000_add_object_size_and_stats.sql (5.42ms)17502026/09/18 18:14:43 OK 20251218171726_add_pins.sql (4.79ms)17512026/09/18 18:14:43 OK 20260905000000_add_claims.sql (5.42ms)17522026/09/18 18:14:43 goose: successfully migrated database to version: 2026090500000017532026/09/18 18:14:43 OK 1_commit_pending_closure.sql (3.8ms)17542026/09/18 18:14:43 OK 20260628120000_add_object_size_and_stats.sql (6.49ms)17552026/09/18 18:14:43 OK 2_object_stats_trigger.sql (2.01ms)17562026/09/18 18:14:43 goose: up to current file version: 217572026/09/18 18:14:43 OK 20260905000000_add_claims.sql (4.61ms)17582026/09/18 18:14:43 goose: successfully migrated database to version: 202609050000001759--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.55s)1760=== CONT TestService_ReadScope_PublicByDefault17612026/09/18 18:14:43 OK 1_commit_pending_closure.sql (3.27ms)17622026/09/18 18:14:43 OK 2_object_stats_trigger.sql (1.98ms)17632026/09/18 18:14:43 goose: up to current file version: 21764=== NAME TestClientCADerivations1765 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1766 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1767 error: binary cache 's3://bucket27?endpoint=http://localhost:44339®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations965318734/001/store'1768 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11769--- PASS: TestClientCADerivations (1.12s)1770=== CONT TestService_RequireScope_OIDC17712026/09/18 18:14:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41067/oidc17722026-09-18 18:14:43.062 UTC [1567] ERROR: relation "goose_db_version" does not exist at character 3617732026-09-18 18:14:43.062 UTC [1567] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1774=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1775=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1776=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1777=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1778=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1779=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1780=== CONT TestCompleteMultipartUnregistered17812026/09/18 18:14:43 WARN claim: cannot clear write deadline error="feature not supported"17822026/09/18 18:14:43 OK 20241026095416_initial_model.sql (12.52ms)17832026/09/18 18:14:43 OK 20251210153512_drop_unused_gin_index.sql (2.89ms)17842026/09/18 18:14:43 OK 20251218171726_add_pins.sql (4ms)17852026/09/18 18:14:43 WARN claim: cannot clear write deadline error="feature not supported"1786--- PASS: TestClaim_StaleHeartbeatStolen (0.59s)1787=== CONT TestSkippedUploadsHandler17882026/09/18 18:14:43 INFO Client skipped oversized paths paths=3 nar_bytes=500000000017892026/09/18 18:14:43 OK 20260628120000_add_object_size_and_stats.sql (5.18ms)1790--- PASS: TestSkippedUploadsHandler (0.01s)1791=== CONT TestService_AuthMiddleware_MTLSBoundSubjects17922026-09-18 18:14:43.099 UTC [1574] ERROR: relation "goose_db_version" does not exist at character 3617932026-09-18 18:14:43.099 UTC [1574] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17942026/09/18 18:14:43 OK 20260905000000_add_claims.sql (11.71ms)17952026/09/18 18:14:43 goose: successfully migrated database to version: 2026090500000017962026/09/18 18:14:43 OK 1_commit_pending_closure.sql (3.06ms)17972026/09/18 18:14:43 OK 2_object_stats_trigger.sql (2.85ms)17982026/09/18 18:14:43 goose: up to current file version: 217992026/09/18 18:14:43 WARN claim: cannot clear write deadline error="feature not supported"18002026/09/18 18:14:43 OK 20241026095416_initial_model.sql (13.41ms)18012026/09/18 18:14:43 OK 20251210153512_drop_unused_gin_index.sql (3.32ms)18022026/09/18 18:14:43 WARN claim: cannot clear write deadline error="feature not supported"18032026/09/18 18:14:43 WARN claim: cannot clear write deadline error="feature not supported"18042026/09/18 18:14:43 OK 20251218171726_add_pins.sql (4.11ms)1805--- PASS: TestClaim_FailWakesWaitersButIsNotRemembered (0.57s)1806=== CONT TestService_AuthMiddleware_MTLSProxyHeader18072026/09/18 18:14:43 OK 20260628120000_add_object_size_and_stats.sql (4.57ms)18082026-09-18 18:14:43.138 UTC [1579] ERROR: relation "goose_db_version" does not exist at character 3618092026-09-18 18:14:43.138 UTC [1579] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18102026/09/18 18:14:43 OK 20260905000000_add_claims.sql (4.56ms)18112026/09/18 18:14:43 goose: successfully migrated database to version: 2026090500000018122026/09/18 18:14:43 OK 1_commit_pending_closure.sql (2.91ms)18132026/09/18 18:14:43 OK 2_object_stats_trigger.sql (2ms)18142026/09/18 18:14:43 goose: up to current file version: 218152026-09-18 18:14:43.148 UTC [1581] ERROR: relation "goose_db_version" does not exist at character 3618162026-09-18 18:14:43.148 UTC [1581] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18172026-09-18 18:14:43.149 UTC [1582] ERROR: relation "goose_db_version" does not exist at character 3618182026-09-18 18:14:43.149 UTC [1582] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1819--- PASS: TestReadProxyNarinfo (0.61s)1820=== CONT TestParseSize1821--- PASS: TestParseSize (0.00s)1822=== CONT TestService_ReadAuthMiddleware18232026/09/18 18:14:43 OK 20241026095416_initial_model.sql (12.96ms)18242026/09/18 18:14:43 OK 20251210153512_drop_unused_gin_index.sql (2.94ms)18252026/09/18 18:14:43 OK 20251218171726_add_pins.sql (4.87ms)18262026/09/18 18:14:43 OK 20241026095416_initial_model.sql (11.16ms)18272026/09/18 18:14:43 OK 20241026095416_initial_model.sql (12.43ms)18282026/09/18 18:14:43 OK 20260628120000_add_object_size_and_stats.sql (4.82ms)18292026/09/18 18:14:43 OK 20251210153512_drop_unused_gin_index.sql (2.66ms)18302026/09/18 18:14:43 OK 20251210153512_drop_unused_gin_index.sql (3.77ms)18312026/09/18 18:14:43 OK 20260905000000_add_claims.sql (3.96ms)18322026/09/18 18:14:43 goose: successfully migrated database to version: 2026090500000018332026/09/18 18:14:43 OK 20251218171726_add_pins.sql (4.44ms)18342026/09/18 18:14:43 WARN claim: cannot clear write deadline error="feature not supported"18352026-09-18 18:14:43.182 UTC [1585] ERROR: relation "goose_db_version" does not exist at character 3618362026-09-18 18:14:43.182 UTC [1585] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18372026/09/18 18:14:43 OK 20251218171726_add_pins.sql (12.23ms)18382026/09/18 18:14:43 OK 1_commit_pending_closure.sql (13.15ms)18392026/09/18 18:14:43 OK 20260628120000_add_object_size_and_stats.sql (11.56ms)18402026/09/18 18:14:43 OK 2_object_stats_trigger.sql (2.66ms)18412026/09/18 18:14:43 goose: up to current file version: 218422026/09/18 18:14:43 OK 20260628120000_add_object_size_and_stats.sql (6.22ms)18432026/09/18 18:14:43 OK 20260905000000_add_claims.sql (5.03ms)18442026/09/18 18:14:43 goose: successfully migrated database to version: 2026090500000018452026/09/18 18:14:43 WARN claim: cannot clear write deadline error="feature not supported"18462026/09/18 18:14:43 OK 1_commit_pending_closure.sql (3.34ms)18472026/09/18 18:14:43 OK 20260905000000_add_claims.sql (5.54ms)18482026/09/18 18:14:43 goose: successfully migrated database to version: 2026090500000018492026/09/18 18:14:43 OK 2_object_stats_trigger.sql (3.8ms)18502026/09/18 18:14:43 goose: up to current file version: 218512026/09/18 18:14:43 OK 1_commit_pending_closure.sql (4.04ms)18522026/09/18 18:14:43 OK 20241026095416_initial_model.sql (13.11ms)18532026/09/18 18:14:43 OK 2_object_stats_trigger.sql (2.15ms)18542026/09/18 18:14:43 goose: up to current file version: 218552026/09/18 18:14:43 OK 20251210153512_drop_unused_gin_index.sql (2.81ms)18562026/09/18 18:14:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18572026-09-18 18:14:43.211 UTC [1587] ERROR: relation "goose_db_version" does not exist at character 3618582026-09-18 18:14:43.211 UTC [1587] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18592026/09/18 18:14:43 OK 20251218171726_add_pins.sql (4.8ms)18602026/09/18 18:14:43 OK 20260628120000_add_object_size_and_stats.sql (5.16ms)18612026/09/18 18:14:43 WARN claim: cannot clear write deadline error="feature not supported"18622026/09/18 18:14:43 OK 20260905000000_add_claims.sql (4.93ms)18632026/09/18 18:14:43 goose: successfully migrated database to version: 2026090500000018642026/09/18 18:14:43 OK 1_commit_pending_closure.sql (3.11ms)18652026/09/18 18:14:43 OK 2_object_stats_trigger.sql (1.86ms)18662026/09/18 18:14:43 goose: up to current file version: 218672026/09/18 18:14:43 OK 20241026095416_initial_model.sql (11.04ms)18682026/09/18 18:14:43 INFO Completed multipart upload object_key=nar/0000000000000000000000000000002000000000000000000000.nar.zst upload_id=YjQ1MzhkY2YtNTZmMS00YjI1LTljOTgtOWU0NjYwYmIyZjBmLjNmNGExYzc4LThmMWQtNDU2MC04MTdkLTJhODc5ZTI4Njg1Y3gxNzg5NzU1MjgyNzI0MzMwNTA5 parts=1018692026/09/18 18:14:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18702026/09/18 18:14:43 OK 20251210153512_drop_unused_gin_index.sql (1.76ms)1871--- PASS: TestClaim_TooManyStreams (0.58s)1872=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle18732026/09/18 18:14:43 INFO Completed upload id=118742026/09/18 18:14:43 INFO Received uploads request method=POST path=/api/pending_closures18752026/09/18 18:14:43 OK 20251218171726_add_pins.sql (3.56ms)18762026-09-18 18:14:43.238 UTC [1589] ERROR: relation "goose_db_version" does not exist at character 3618772026-09-18 18:14:43.238 UTC [1589] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18782026/09/18 18:14:43 OK 20260628120000_add_object_size_and_stats.sql (3.2ms)18792026/09/18 18:14:43 OK 20260905000000_add_claims.sql (3.91ms)18802026/09/18 18:14:43 goose: successfully migrated database to version: 2026090500000018812026/09/18 18:14:43 OK 1_commit_pending_closure.sql (3.2ms)18822026/09/18 18:14:43 OK 2_object_stats_trigger.sql (6.15ms)18832026/09/18 18:14:43 goose: up to current file version: 218842026/09/18 18:14:43 OK 20241026095416_initial_model.sql (11.1ms)18852026/09/18 18:14:43 WARN claim: cannot clear write deadline error="feature not supported"18862026/09/18 18:14:43 OK 20251210153512_drop_unused_gin_index.sql (2.61ms)18872026/09/18 18:14:43 OK 20251218171726_add_pins.sql (6.45ms)18882026/09/18 18:14:43 OK 20260628120000_add_object_size_and_stats.sql (4.42ms)18892026/09/18 18:14:43 WARN claim: cannot clear write deadline error="feature not supported"18902026/09/18 18:14:43 WARN claim: cannot clear write deadline error="feature not supported"18912026/09/18 18:14:43 INFO Received uploads request method=POST path=/api/pending_closures18922026/09/18 18:14:43 OK 20260905000000_add_claims.sql (3.66ms)18932026/09/18 18:14:43 goose: successfully migrated database to version: 2026090500000018942026/09/18 18:14:43 OK 1_commit_pending_closure.sql (2.89ms)18952026/09/18 18:14:43 OK 2_object_stats_trigger.sql (1.74ms)18962026/09/18 18:14:43 goose: up to current file version: 218972026/09/18 18:14:43 INFO Received uploads request method=POST path=/api/pending_closures18982026-09-18 18:14:43.306 UTC [1594] ERROR: relation "goose_db_version" does not exist at character 3618992026-09-18 18:14:43.306 UTC [1594] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19002026/09/18 18:14:43 INFO Received uploads request method=POST path=/api/pending_closures19012026/09/18 18:14:43 OK 20241026095416_initial_model.sql (10.41ms)19022026/09/18 18:14:43 OK 20251210153512_drop_unused_gin_index.sql (1.42ms)19032026/09/18 18:14:43 OK 20251218171726_add_pins.sql (3.62ms)19042026/09/18 18:14:43 OK 20260628120000_add_object_size_and_stats.sql (3.71ms)19052026/09/18 18:14:43 OK 20260905000000_add_claims.sql (4.82ms)19062026/09/18 18:14:43 goose: successfully migrated database to version: 2026090500000019072026/09/18 18:14:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19082026/09/18 18:14:43 OK 1_commit_pending_closure.sql (2.34ms)19092026/09/18 18:14:43 OK 2_object_stats_trigger.sql (1.06ms)19102026/09/18 18:14:43 goose: up to current file version: 219112026/09/18 18:14:43 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001700000000000000000000.nar.zst upload_id=YjQ1MzhkY2YtNTZmMS00YjI1LTljOTgtOWU0NjYwYmIyZjBmLjEzYmRhZDFmLWJmYmQtNGVjOS1hZGI3LWQ0NmFkNjZiZDQxMXgxNzg5NzU1MjgyODgxMzQyMDc1 parts=1019122026/09/18 18:14:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1913--- PASS: TestCacheStatsHandler (0.62s)1914=== CONT TestCacheConfigHandler1915=== RUN TestCacheConfigHandler/full_config,_no_issuer1916=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1917=== RUN TestCacheConfigHandler/no_cache_url_configured1918=== PAUSE TestCacheConfigHandler/no_cache_url_configured1919=== RUN TestCacheConfigHandler/no_signing_keys1920=== PAUSE TestCacheConfigHandler/no_signing_keys1921=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1922=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1923=== CONT TestServerTLSConfig/no_client_CA1924=== CONT TestServerTLSConfig/not_a_PEM_file1925=== CONT TestServerTLSConfig/missing_CA_file1926--- PASS: TestServerTLSConfig (0.00s)1927 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1928 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1929 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1930=== CONT TestResolveDBConnectionString/flag_wins1931=== CONT TestResolveDBConnectionString/missing_file_is_an_error1932=== CONT TestResolveDBConnectionString/file_when_flag_empty1933=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1934=== CONT TestResolveDBConnectionString/nothing_configured1935=== CONT TestClientErrorHandling/InvalidStorePath1936--- PASS: TestResolveDBConnectionString (0.00s)1937 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1938 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1939 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1940 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1941 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)19422026/09/18 18:14:43 INFO Completed upload id=119432026/09/18 18:14:43 WARN claim: cannot clear write deadline error="feature not supported"19442026/09/18 18:14:43 INFO Aborted multipart uploads count=019452026/09/18 18:14:43 WARN Force mode enabled - objects will be deleted immediately without grace period19462026/09/18 18:14:43 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=019472026/09/18 18:14:43 INFO Vacuumed table table=pending_closures19482026/09/18 18:14:43 INFO Vacuumed table table=pending_objects19492026/09/18 18:14:43 INFO Vacuumed table table=multipart_uploads19502026/09/18 18:14:43 INFO Vacuumed table table=closures19512026/09/18 18:14:43 INFO Vacuumed table table=objects1952--- PASS: TestClaim_InputsTouched (1.20s)1953=== CONT TestClientErrorHandling/ServerNotAvailable19542026/09/18 18:14:43 INFO Received uploads request method=POST path=/api/pending_closures1955--- PASS: TestResurrectedObjectNotDeleted (0.63s)1956=== CONT TestClientErrorHandling/InvalidAuthToken1957--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.53s)1958=== CONT TestIsValidCachePath/narinfo1959=== CONT TestIsValidCachePath/random_path1960=== CONT TestIsValidCachePath/invalid_char_u1961=== CONT TestIsValidCachePath/invalid_char_e1962=== CONT TestIsValidCachePath/traversal_in_middle1963=== CONT TestIsValidCachePath/traversal_parent1964=== CONT TestIsValidCachePath/empty1965=== CONT TestIsValidCachePath/index.html1966=== CONT TestIsValidCachePath/nix-cache-info1967=== CONT TestIsValidCachePath/realisation1968=== CONT TestIsValidCachePath/log1969=== CONT TestIsValidCachePath/ls1970=== CONT TestIsValidCachePath/nar_uncompressed1971=== CONT TestIsValidCachePath/nar_bz21972=== CONT TestIsValidCachePath/nar_xz1973=== CONT TestIsValidCachePath/nar_zst1974=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1975=== CONT TestIsValidCachePath/wrong_extension1976=== CONT TestIsValidCachePath/short_hash1977=== CONT TestIsValidCachePath/leading_slash1978--- PASS: TestIsValidCachePath (0.00s)1979 --- PASS: TestIsValidCachePath/narinfo (0.00s)1980 --- PASS: TestIsValidCachePath/random_path (0.00s)1981 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1982 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1983 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1984 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1985 --- PASS: TestIsValidCachePath/empty (0.00s)1986 --- PASS: TestIsValidCachePath/index.html (0.00s)1987 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1988 --- PASS: TestIsValidCachePath/realisation (0.00s)1989 --- PASS: TestIsValidCachePath/log (0.00s)1990 --- PASS: TestIsValidCachePath/ls (0.00s)1991 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1992 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1993 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1994 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1995 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1996 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1997 --- PASS: TestIsValidCachePath/short_hash (0.00s)1998 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1999=== CONT TestProxyWriteTimeout/narinfo2000=== CONT TestProxyWriteTimeout/10_GiB_nar2001=== CONT TestProxyWriteTimeout/unknown_size2002=== CONT TestProxyWriteTimeout/1_GiB_nar2003--- PASS: TestProxyWriteTimeout (0.00s)2004 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2005 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2006 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2007 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2008=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info20092026/09/18 18:14:43 INFO Received uploads request method=POST path=/2010=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key20112026/09/18 18:14:43 INFO Received complete multipart upload request method=POST path=/2012=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key20132026/09/18 18:14:43 INFO Received request for more parts method=POST path=/2014=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal20152026/09/18 18:14:43 INFO Received uploads request method=POST path=/2016--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2017 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2018 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2019 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2020 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2021=== CONT TestIsValidUploadKey/narinfo2022=== CONT TestIsValidUploadKey/absolute2023=== CONT TestIsValidUploadKey/empty_key2024=== CONT TestIsValidUploadKey/traversal_nar2025=== CONT TestIsValidUploadKey/traversal2026=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2027=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2028=== CONT TestIsValidUploadKey/build_log_plus_in_name2029=== CONT TestIsValidUploadKey/build_log_home-manager_file2030=== CONT TestIsValidUploadKey/build_log2031=== CONT TestIsValidUploadKey/listing2032=== CONT TestIsValidUploadKey/nar_plain2033=== CONT TestIsValidUploadKey/nar_xz2034=== CONT TestIsValidUploadKey/nar_zst2035=== CONT TestIsValidUploadKey/build_log_question_mark2036=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2037=== CONT TestIsValidUploadKey/index.html2038=== CONT TestIsValidUploadKey/realisation_plus_in_output2039=== CONT TestIsValidUploadKey/realisation2040=== CONT TestIsValidUploadKey/nix-cache-info2041=== CONT TestIsValidUploadKey/unknown_type2042=== CONT TestIsValidUploadKey/build_log_equals2043--- PASS: TestIsValidUploadKey (0.00s)2044 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2045 --- PASS: TestIsValidUploadKey/absolute (0.00s)2046 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2047 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2048 --- PASS: TestIsValidUploadKey/traversal (0.00s)2049 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2050 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2051 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2052 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2053 --- PASS: TestIsValidUploadKey/build_log (0.00s)2054 --- PASS: TestIsValidUploadKey/listing (0.00s)2055 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2056 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2057 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2058 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2059 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2060 --- PASS: TestIsValidUploadKey/index.html (0.00s)2061 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2062 --- PASS: TestIsValidUploadKey/realisation (0.00s)2063 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2064 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2065 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2066=== CONT TestParseSingleRange/none2067=== CONT TestParseSingleRange/open-ended2068=== CONT TestParseSingleRange/start_far_past_EOF2069=== CONT TestParseSingleRange/start_past_EOF2070=== CONT TestParseSingleRange/single_byte2071=== CONT TestParseSingleRange/end_clamped_to_size2072=== CONT TestParseSingleRange/suffix_exceeds_size2073=== CONT TestParseSingleRange/malformed_both_empty2074=== CONT TestParseSingleRange/suffix2075=== CONT TestParseSingleRange/closed2076=== CONT TestParseSingleRange/malformed_end_before_start2077=== CONT TestParseSingleRange/multi-range_ignored2078=== CONT TestParseSingleRange/unknown_unit2079=== CONT TestParseSingleRange/malformed_no_dash2080--- PASS: TestParseSingleRange (0.00s)2081 --- PASS: TestParseSingleRange/none (0.00s)2082 --- PASS: TestParseSingleRange/open-ended (0.00s)2083 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2084 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2085 --- PASS: TestParseSingleRange/single_byte (0.00s)2086 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2087 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2088 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2089 --- PASS: TestParseSingleRange/suffix (0.00s)2090 --- PASS: TestParseSingleRange/closed (0.00s)2091 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2092 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2093 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2094 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2095=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure20962026/09/18 18:14:43 INFO Received uploads request method=POST path=/20972026-09-18 18:14:43.439 UTC [1601] ERROR: relation "goose_db_version" does not exist at character 3620982026-09-18 18:14:43.439 UTC [1601] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20992026/09/18 18:14:43 OK 20241026095416_initial_model.sql (19.72ms)21002026/09/18 18:14:43 OK 20251210153512_drop_unused_gin_index.sql (2.51ms)21012026/09/18 18:14:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21022026/09/18 18:14:43 OK 20251218171726_add_pins.sql (3.5ms)21032026/09/18 18:14:43 OK 20260628120000_add_object_size_and_stats.sql (4.42ms)21042026/09/18 18:14:43 OK 20260905000000_add_claims.sql (4.33ms)21052026/09/18 18:14:43 goose: successfully migrated database to version: 2026090500000021062026/09/18 18:14:43 INFO Received uploads request method=POST path=/api/pending_closures21072026/09/18 18:14:43 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21082026/09/18 18:14:43 INFO Received uploads request method=POST path=/api/pending_closures21092026/09/18 18:14:43 INFO Received uploads request method=POST path=/api/pending_closures21102026/09/18 18:14:43 OK 1_commit_pending_closure.sql (4.23ms)21112026/09/18 18:14:43 OK 2_object_stats_trigger.sql (2.22ms)21122026/09/18 18:14:43 goose: up to current file version: 221132026/09/18 18:14:43 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001600000000000000000000.nar.zst upload_id=YjQ1MzhkY2YtNTZmMS00YjI1LTljOTgtOWU0NjYwYmIyZjBmLmUzZWVhNWJiLWY4NzAtNGFjYi05OTQ3LTBmNDY0Y2NjMDdlM3gxNzg5NzU1MjgyOTkxODIzMzEw parts=1021142026/09/18 18:14:43 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign21152026/09/18 18:14:43 INFO Signed narinfos id=1 count=121162026/09/18 18:14:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21172026/09/18 18:14:43 INFO Completed upload id=12118--- PASS: TestClaim_TwoInstances (1.12s)2119=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart21202026/09/18 18:14:43 INFO Received complete multipart upload request method=POST path=/21212026-09-18 18:14:43.506 UTC [1647] ERROR: relation "goose_db_version" does not exist at character 3621222026-09-18 18:14:43.506 UTC [1647] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2123=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2124=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2125=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2126=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2127=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2128=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2129=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2130=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2131=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts21322026/09/18 18:14:43 INFO Received request for more parts method=POST path=/21332026/09/18 18:14:43 OK 20241026095416_initial_model.sql (12.23ms)21342026/09/18 18:14:43 OK 20251210153512_drop_unused_gin_index.sql (1.52ms)21352026/09/18 18:14:43 OK 20251218171726_add_pins.sql (3.66ms)21362026/09/18 18:14:43 OK 20260628120000_add_object_size_and_stats.sql (3.19ms)21372026/09/18 18:14:43 OK 20260905000000_add_claims.sql (2.64ms)21382026/09/18 18:14:43 goose: successfully migrated database to version: 2026090500000021392026/09/18 18:14:43 OK 1_commit_pending_closure.sql (2.39ms)21402026/09/18 18:14:43 INFO Received cleanup request method=DELETE path=/api/pending_closures21412026/09/18 18:14:43 OK 2_object_stats_trigger.sql (1.09ms)21422026/09/18 18:14:43 goose: up to current file version: 221432026/09/18 18:14:43 INFO Aborted multipart uploads count=021442026/09/18 18:14:43 INFO Received uploads request method=POST path=/api/pending_closures21452026/09/18 18:14:43 INFO Received cleanup request method=DELETE path=/api/pending_closures21462026/09/18 18:14:43 INFO Aborted multipart uploads count=121472026/09/18 18:14:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21482026-09-18 18:14:43.562 UTC [1574] ERROR: Closure does not exist: id=121492026-09-18 18:14:43.562 UTC [1574] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE21502026-09-18 18:14:43.562 UTC [1574] STATEMENT: -- name: CommitPendingClosure :exec2151 SELECT commit_pending_closure($1::bigint)2152 2153--- PASS: TestService_cleanupPendingClosuresHandler (0.54s)2154=== CONT TestCacheConfigHandler/full_config,_no_issuer2155=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2156=== CONT TestCacheConfigHandler/no_signing_keys2157=== CONT TestCacheConfigHandler/no_cache_url_configured2158--- PASS: TestCacheConfigHandler (0.00s)2159 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2160 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2161 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2162 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2163=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2164--- PASS: TestService_ReadScope_PublicByDefault (0.52s)2165=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected21662026/09/18 18:14:43 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]2167=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected21682026/09/18 18:14:43 INFO OIDC auth successful provider=test scopes=[write]21692026/09/18 18:14:43 WARN Authentication failed token_preview=eyJhbGciOi...7ZLXrdyBDA token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2170=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2171--- PASS: TestService_AuthMiddleware_OIDC (0.52s)2172 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2173 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)2174 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2175 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)21762026/09/18 18:14:43 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=186.073615ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21772026/09/18 18:14:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21782026/09/18 18:14:43 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst2179--- PASS: TestCompleteMultipartUnregistered (0.54s)2180=== RUN TestService_RequireScope_OIDC/builder_may_write2181=== PAUSE TestService_RequireScope_OIDC/builder_may_write2182=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2183=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2184=== RUN TestService_RequireScope_OIDC/ops_may_admin2185=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2186=== RUN TestService_RequireScope_OIDC/ops_may_not_write2187=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2188=== RUN TestService_RequireScope_OIDC/reader_may_not_write2189=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2190=== RUN TestService_RequireScope_OIDC/static_token_may_admin2191=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2192=== RUN TestService_RequireScope_OIDC/static_token_may_write2193=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2194=== RUN TestService_RequireScope_OIDC/reader_may_read2195=== PAUSE TestService_RequireScope_OIDC/reader_may_read2196=== RUN TestService_RequireScope_OIDC/writer_implies_read2197=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2198=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2199=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2200=== CONT TestService_RequireScope_OIDC/builder_may_write2201=== CONT TestService_RequireScope_OIDC/writer_implies_read2202=== CONT TestService_RequireScope_OIDC/reader_may_read2203=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2204=== CONT TestService_RequireScope_OIDC/reader_may_not_write2205=== CONT TestService_RequireScope_OIDC/static_token_may_write2206=== CONT TestService_RequireScope_OIDC/static_token_may_admin2207=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2208=== CONT TestService_RequireScope_OIDC/ops_may_not_write22092026/09/18 18:14:43 INFO OIDC auth successful provider=test scopes=[read]2210=== CONT TestService_RequireScope_OIDC/ops_may_admin22112026/09/18 18:14:43 INFO OIDC auth successful provider=test scopes=[write]22122026/09/18 18:14:43 INFO OIDC auth successful provider=test scopes=[write]22132026/09/18 18:14:43 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"22142026/09/18 18:14:43 INFO OIDC auth successful provider=test scopes=[read]22152026/09/18 18:14:43 INFO OIDC auth successful provider=test scopes=[write]22162026/09/18 18:14:43 WARN mTLS auth: bound subjects configured but subject DN unavailable22172026/09/18 18:14:43 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"22182026/09/18 18:14:43 INFO OIDC auth successful provider=test scopes=[admin]2219--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.56s)22202026/09/18 18:14:43 INFO OIDC auth successful provider=test scopes=[admin]2221--- PASS: TestService_RequireScope_OIDC (0.59s)2222 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2223 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2224 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2225 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2226 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2227 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2228 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2229 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2230 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2231 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)22322026/09/18 18:14:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22332026/09/18 18:14:43 INFO Completed multipart upload object_key=nar/0000000000000000000000000000002100000000000000000000.nar.zst upload_id=YjQ1MzhkY2YtNTZmMS00YjI1LTljOTgtOWU0NjYwYmIyZjBmLmYyMWE3ZDJmLWI2M2YtNDU5MC05OTU5LWEwM2M1OGFiYjY1NHgxNzg5NzU1MjgzMjM3Mjc4NDk3 parts=1022342026/09/18 18:14:43 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete2235--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.56s)22362026/09/18 18:14:43 INFO Completed upload id=22237--- PASS: TestPresent (1.67s)22382026/09/18 18:14:43 WARN claim: cannot clear write deadline error="feature not supported"2239--- PASS: TestService_ReadAuthMiddleware (0.56s)22402026/09/18 18:14:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22412026/09/18 18:14:43 INFO Received uploads request method=POST path=/api/pending_closures22422026/09/18 18:14:43 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001000000000000000000000.nar.zst upload_id=YjQ1MzhkY2YtNTZmMS00YjI1LTljOTgtOWU0NjYwYmIyZjBmLjkyMWYyOGMyLTFiMGQtNDA0MS05MDA2LTdiMzEyNjRkNTIzMngxNzg5NzU1MjgzMjc3ODgzODE2 parts=1022432026/09/18 18:14:43 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign22442026/09/18 18:14:43 INFO Signed narinfos id=1 count=122452026/09/18 18:14:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22462026/09/18 18:14:43 INFO Received uploads request method=POST path=/api/pending_closures22472026/09/18 18:14:43 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign22482026/09/18 18:14:43 INFO Signed narinfos id=2 count=122492026/09/18 18:14:43 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22502026/09/18 18:14:43 INFO Completed upload id=222512026/09/18 18:14:43 WARN claim: cannot clear write deadline error="feature not supported"2252--- PASS: TestClaim_BuildWaitComplete (1.07s)22532026-09-18 18:14:43.763 UTC [1649] LOG: could not send data to client: Broken pipe22542026-09-18 18:14:43.763 UTC [1649] FATAL: connection to client lost22552026/09/18 18:14:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22562026/09/18 18:14:43 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=388.879192ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22572026/09/18 18:14:43 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001100000000000000000000.nar.zst upload_id=YjQ1MzhkY2YtNTZmMS00YjI1LTljOTgtOWU0NjYwYmIyZjBmLjJjZjBjZjdjLThiMWMtNGY1Yi05MTM2LWU2NDI3NWRhZTQ3ZXgxNzg5NzU1MjgzMzA2NDkzNTA4 parts=1022582026/09/18 18:14:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22592026/09/18 18:14:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22602026/09/18 18:14:43 INFO Completed upload id=122612026/09/18 18:14:43 WARN claim: cannot clear write deadline error="feature not supported"22622026/09/18 18:14:43 WARN claim: cannot clear write deadline error="feature not supported"2263--- PASS: TestClaim_GCMarkedOutputCountsAsAbsent (1.12s)22642026/09/18 18:14:43 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YjQ1MzhkY2YtNTZmMS00YjI1LTljOTgtOWU0NjYwYmIyZjBmLmFiNzZlMzU0LWQxNjgtNDJhMS1hYTgyLTRjOGU0NTYyZTZhZngxNzg5NzU1MjgzMzMwNzE0NjYy parts=1022652026/09/18 18:14:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22662026/09/18 18:14:43 INFO Completed upload id=122672026/09/18 18:14:43 INFO Received uploads request method=POST path=/api/pending_closures22682026/09/18 18:14:43 INFO Received uploads request method=POST path=/api/pending_closures22692026/09/18 18:14:43 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo22702026/09/18 18:14:43 WARN Found objects in DB but missing from S3, will re-upload count=12271--- PASS: TestService_verifyS3Integrity (1.08s)22722026/09/18 18:14:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22732026/09/18 18:14:43 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22742026/09/18 18:14:43 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"22752026/09/18 18:14:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22762026/09/18 18:14:43 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22772026/09/18 18:14:43 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YjQ1MzhkY2YtNTZmMS00YjI1LTljOTgtOWU0NjYwYmIyZjBmLmE0ZmViZjc0LTVkZTYtNGMwZi1iZTA3LWU5MWU5YTY1ZjI0MngxNzg5NzU1MjgzNDk0OTg4ODky parts=1022782026/09/18 18:14:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22792026/09/18 18:14:43 INFO Completed upload id=122802026/09/18 18:14:43 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000022812026/09/18 18:14:43 INFO Received uploads request method=POST path=/api/pending_closures22822026/09/18 18:14:43 INFO Starting cleanup of old closures method=DELETE path=/api/closures22832026/09/18 18:14:43 INFO Aborted multipart uploads count=022842026/09/18 18:14:43 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=022852026/09/18 18:14:43 INFO Vacuumed table table=pending_closures22862026/09/18 18:14:43 INFO Vacuumed table table=pending_objects22872026/09/18 18:14:43 INFO Vacuumed table table=multipart_uploads22882026/09/18 18:14:43 INFO Vacuumed table table=closures22892026/09/18 18:14:43 INFO Vacuumed table table=objects22902026/09/18 18:14:44 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=022912026/09/18 18:14:44 INFO Vacuumed table table=pending_closures22922026/09/18 18:14:44 INFO Vacuumed table table=pending_objects22932026/09/18 18:14:44 INFO Vacuumed table table=multipart_uploads22942026/09/18 18:14:44 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000022952026/09/18 18:14:44 INFO Vacuumed table table=closures2296--- PASS: TestService_createPendingClosureHandler (1.09s)22972026/09/18 18:14:44 INFO Vacuumed table table=objects22982026/09/18 18:14:44 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=022992026/09/18 18:14:44 INFO Vacuumed table table=pending_closures23002026/09/18 18:14:44 INFO Vacuumed table table=pending_objects23012026/09/18 18:14:44 INFO Vacuumed table table=multipart_uploads23022026/09/18 18:14:44 INFO Vacuumed table table=closures23032026/09/18 18:14:44 INFO Vacuumed table table=objects23042026/09/18 18:14:44 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=844.810089ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2305--- PASS: TestClaim_StreamsThroughServer (2.15s)23062026/09/18 18:14:44 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02307=== NAME TestClientIntegration2308 client_integration_test.go:323: Objects in database after GC:2309 client_integration_test.go:323: Successfully deleted all objects with GC --force2310--- PASS: TestClientIntegration (3.20s)23112026/09/18 18:14:44 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02312=== NAME TestPinProtectsFromGC2313 client_integration_test.go:794: Pin successfully protected closure from garbage collection2314--- PASS: TestPinProtectsFromGC (3.35s)2315=== NAME TestOrphanedObjectsGCStressTest2316 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2317 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion23182026/09/18 18:14:45 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.487470517s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2319--- PASS: TestUploadHandlersRejectOversizedBody (0.23s)2320 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.11s)2321 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.10s)2322 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (1.62s)2323=== NAME TestOrphanedObjectsGCStressTest2324 orphaned_objects_gc_test.go:509: Stress test completed successfully:2325 orphaned_objects_gc_test.go:510: - Active objects preserved: 202326 orphaned_objects_gc_test.go:511: - Objects deleted: 2102327 orphaned_objects_gc_test.go:512: - Total GC'd: 2102328--- PASS: TestOrphanedObjectsGCStressTest (2.48s)2329--- PASS: TestClaim_HolderDisconnectKeepsClaim (3.09s)23302026/09/18 18:14:46 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-config23312026/09/18 18:14:46 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=210.11528ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23322026/09/18 18:14:46 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=427.224579ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23332026/09/18 18:14:47 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=765.636161ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23342026/09/18 18:14:47 WARN Rate limiter enabled after throttle name=s3-test rate=523352026/09/18 18:14:47 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2336=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2337 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102338 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002339--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.47s)23402026/09/18 18:14:48 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.679624047s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23412026/09/18 18:14:49 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"23422026/09/18 18:14:49 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_closures23432026/09/18 18:14:49 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=204.26245ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23442026/09/18 18:14:50 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=438.963532ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23452026/09/18 18:14:50 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=760.571777ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23462026/09/18 18:14:51 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.539190354s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2347--- PASS: TestClientErrorHandling (0.00s)2348 --- PASS: TestClientErrorHandling/InvalidStorePath (0.44s)2349 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.52s)2350 --- PASS: TestClientErrorHandling/ServerNotAvailable (9.41s)2351PASS23522026-09-18 18:14:53.143 UTC [127] LOG: received smart shutdown request23532026-09-18 18:14:53.148 UTC [127] LOG: background worker "logical replication launcher" (PID 137) exited with exit code 123542026-09-18 18:14:53.166 UTC [132] LOG: shutting down23552026-09-18 18:14:53.167 UTC [132] LOG: checkpoint starting: shutdown immediate23562026-09-18 18:14:53.865 UTC [132] LOG: checkpoint complete: wrote 10979 buffers (67.0%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 18 recycled; write=0.227 s, sync=0.464 s, total=0.699 s; sync files=21676, longest=0.079 s, average=0.001 s; distance=292000 kB, estimate=292000 kB; lsn=0/1348DF40, redo lsn=0/1348DF4023572026-09-18 18:14:53.962 UTC [127] LOG: database system is shut down2358Running OIDC tests...2359=== RUN TestGlobMatch2360=== PAUSE TestGlobMatch2361=== RUN TestAudienceForIssuer2362=== PAUSE TestAudienceForIssuer2363=== RUN TestValidateToken_ValidToken2364=== PAUSE TestValidateToken_ValidToken2365=== RUN TestValidateToken_WrongAudience2366=== PAUSE TestValidateToken_WrongAudience2367=== RUN TestValidateToken_Expired2368=== PAUSE TestValidateToken_Expired2369=== RUN TestValidateToken_BoundClaimsMismatch2370=== PAUSE TestValidateToken_BoundClaimsMismatch2371=== RUN TestValidateToken_BoundSubjectMismatch2372=== PAUSE TestValidateToken_BoundSubjectMismatch2373=== RUN TestValidateToken_MultipleProviders2374=== PAUSE TestValidateToken_MultipleProviders2375=== RUN TestValidateToken_NoMatchingProvider2376=== PAUSE TestValidateToken_NoMatchingProvider2377=== RUN TestValidateToken_KubernetesServiceAccount2378=== PAUSE TestValidateToken_KubernetesServiceAccount2379=== RUN TestNewValidator_KubernetesRequiresCA2380=== PAUSE TestNewValidator_KubernetesRequiresCA2381=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2382=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2383=== RUN TestScopes_LegacyProviderDefaultsToWrite2384=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2385=== RUN TestScopes_Rules2386=== PAUSE TestScopes_Rules2387=== RUN TestScopes_ConfigValidation2388=== PAUSE TestScopes_ConfigValidation2389=== CONT TestGlobMatch2390=== CONT TestValidateToken_KubernetesServiceAccount2391=== CONT TestNewValidator_KubernetesRequiresCA2392=== RUN TestGlobMatch/foo_foo2393=== CONT TestValidateToken_NoMatchingProvider2394=== CONT TestValidateToken_MultipleProviders2395=== CONT TestValidateToken_BoundSubjectMismatch2396=== CONT TestValidateToken_BoundClaimsMismatch2397=== CONT TestValidateToken_Expired2398=== CONT TestValidateToken_WrongAudience2399=== CONT TestValidateToken_ValidToken2400=== CONT TestAudienceForIssuer2401--- PASS: TestAudienceForIssuer (0.00s)2402=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2403=== CONT TestScopes_ConfigValidation2404=== CONT TestScopes_Rules2405=== CONT TestScopes_LegacyProviderDefaultsToWrite2406=== PAUSE TestGlobMatch/foo_foo2407=== RUN TestGlobMatch/foo_bar2408=== PAUSE TestGlobMatch/foo_bar2409=== RUN TestGlobMatch/*_2410=== PAUSE TestGlobMatch/*_2411=== RUN TestGlobMatch/*_anything2412=== PAUSE TestGlobMatch/*_anything2413=== RUN TestGlobMatch/foo*_foo2414=== PAUSE TestGlobMatch/foo*_foo2415=== RUN TestGlobMatch/foo*_foobar2416--- PASS: TestScopes_ConfigValidation (0.00s)2417=== PAUSE TestGlobMatch/foo*_foobar2418=== RUN TestGlobMatch/foo*_bar2419=== PAUSE TestGlobMatch/foo*_bar2420=== RUN TestGlobMatch/*bar_bar2421=== PAUSE TestGlobMatch/*bar_bar2422=== RUN TestGlobMatch/*bar_foobar2423=== PAUSE TestGlobMatch/*bar_foobar2424=== RUN TestGlobMatch/*bar_foo2425=== PAUSE TestGlobMatch/*bar_foo2426=== RUN TestGlobMatch/foo*bar_foobar24272026/09/18 18:14:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38673/oidc2428=== PAUSE TestGlobMatch/foo*bar_foobar2429=== RUN TestGlobMatch/foo*bar_foo123bar2430=== PAUSE TestGlobMatch/foo*bar_foo123bar24312026/09/18 18:14:55 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:33559/oidc2432=== RUN TestGlobMatch/foo*bar_foobarbaz24332026/09/18 18:14:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33233/oidc2434=== PAUSE TestGlobMatch/foo*bar_foobarbaz2435=== RUN TestGlobMatch/*/*_foo/bar24362026/09/18 18:14:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37259/oidc24372026/09/18 18:14:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45853/oidc24382026/09/18 18:14:55 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:41815/oidc24392026/09/18 18:14:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42669/oidc24402026/09/18 18:14:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35291/oidc2441=== PAUSE TestGlobMatch/*/*_foo/bar2442=== RUN TestGlobMatch/*/*_foo2443=== PAUSE TestGlobMatch/*/*_foo2444=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2445=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2446=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02447=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02448=== RUN TestGlobMatch/refs/*/main_refs/heads/main2449=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2450=== RUN TestGlobMatch/fo?_foo2451=== PAUSE TestGlobMatch/fo?_foo2452=== RUN TestGlobMatch/fo?_fo2453=== PAUSE TestGlobMatch/fo?_fo24542026/09/18 18:14:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:32879/oidc2455=== RUN TestGlobMatch/fo?_fooo2456=== PAUSE TestGlobMatch/fo?_fooo2457=== RUN TestGlobMatch/?oo_foo2458=== PAUSE TestGlobMatch/?oo_foo2459=== RUN TestGlobMatch/?oo_boo2460=== PAUSE TestGlobMatch/?oo_boo2461=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2462=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2463=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2464=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2465=== CONT TestGlobMatch/?oo_boo2466=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2467=== CONT TestGlobMatch/foo_foo2468=== CONT TestGlobMatch/foo*bar_foo123bar2469=== CONT TestGlobMatch/foo*bar_foobarbaz2470=== CONT TestGlobMatch/?oo_foo2471=== CONT TestGlobMatch/foo*_foobar2472=== CONT TestGlobMatch/fo?_fooo2473=== CONT TestGlobMatch/*_anything2474=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2475=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02476=== CONT TestGlobMatch/*_2477=== CONT TestGlobMatch/foo_bar2478=== CONT TestGlobMatch/*bar_foo2479=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2480=== CONT TestGlobMatch/*bar_foobar2481=== CONT TestGlobMatch/*/*_foo2482=== CONT TestGlobMatch/fo?_fo2483=== CONT TestGlobMatch/*bar_bar2484=== CONT TestGlobMatch/refs/*/main_refs/heads/main2485=== CONT TestGlobMatch/*/*_foo/bar2486=== CONT TestGlobMatch/foo*_bar2487=== CONT TestGlobMatch/foo*bar_foobar2488=== CONT TestGlobMatch/foo*_foo2489=== CONT TestGlobMatch/fo?_foo2490--- PASS: TestGlobMatch (0.01s)2491 --- PASS: TestGlobMatch/?oo_boo (0.00s)2492 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2493 --- PASS: TestGlobMatch/foo_foo (0.00s)2494 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2495 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2496 --- PASS: TestGlobMatch/?oo_foo (0.00s)2497 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2498 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2499 --- PASS: TestGlobMatch/*_anything (0.00s)2500 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2501 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2502 --- PASS: TestGlobMatch/*_ (0.00s)2503 --- PASS: TestGlobMatch/foo_bar (0.00s)2504 --- PASS: TestGlobMatch/*bar_foo (0.00s)2505 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2506 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2507 --- PASS: TestGlobMatch/*/*_foo (0.00s)2508 --- PASS: TestGlobMatch/fo?_fo (0.00s)2509 --- PASS: TestGlobMatch/*bar_bar (0.00s)2510 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2511 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2512 --- PASS: TestGlobMatch/foo*_bar (0.00s)2513 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2514 --- PASS: TestGlobMatch/foo*_foo (0.00s)2515 --- PASS: TestGlobMatch/fo?_foo (0.00s)25162026/09/18 18:14:55 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:41251/oidc25172026/09/18 18:14:55 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232518--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)2519--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.01s)2520--- PASS: TestValidateToken_Expired (0.01s)2521--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)2522--- PASS: TestValidateToken_NoMatchingProvider (0.01s)2523--- PASS: TestValidateToken_ValidToken (0.01s)2524--- PASS: TestValidateToken_WrongAudience (0.01s)25252026/09/18 18:14:55 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:360032526--- PASS: TestValidateToken_MultipleProviders (0.02s)25272026/09/18 18:14:55 http: TLS handshake error from 127.0.0.1:54078: remote error: tls: bad certificate2528--- PASS: TestNewValidator_KubernetesRequiresCA (0.02s)2529--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.02s)2530--- PASS: TestScopes_Rules (0.02s)2531--- PASS: TestValidateToken_KubernetesServiceAccount (0.03s)2532PASS2533Running hook tests...2534=== RUN TestSendPathsEmpty2535=== PAUSE TestSendPathsEmpty2536=== RUN TestQueueEnqueueAndFetch2537=== PAUSE TestQueueEnqueueAndFetch2538=== RUN TestQueueDeduplication2539=== PAUSE TestQueueDeduplication2540=== RUN TestQueueRemove2541=== PAUSE TestQueueRemove2542=== RUN TestQueueFetchBatchLimit2543=== PAUSE TestQueueFetchBatchLimit2544=== RUN TestQueueRetryMovesToBack2545=== PAUSE TestQueueRetryMovesToBack2546=== RUN TestQueueFetchRemoveLifecycle2547=== PAUSE TestQueueFetchRemoveLifecycle2548=== RUN TestQueueConcurrentWriters2549=== PAUSE TestQueueConcurrentWriters2550=== RUN TestQueueRemoveLargeClosure2551=== PAUSE TestQueueRemoveLargeClosure2552=== RUN TestServerClientIntegration2553=== PAUSE TestServerClientIntegration2554=== RUN TestServerQueueError2555=== PAUSE TestServerQueueError2556=== RUN TestGetListenerSocketActivation2557 server_test.go:210: === RUN TestGetListenerSocketActivation2558 --- PASS: TestGetListenerSocketActivation (0.00s)2559 PASS2560 2561--- PASS: TestGetListenerSocketActivation (0.01s)2562=== RUN TestDrainIsolatesPoisonPath2563=== PAUSE TestDrainIsolatesPoisonPath2564=== RUN TestRunNotBlockedByPoisonHead2565=== PAUSE TestRunNotBlockedByPoisonHead2566=== RUN TestDrainGivesUpWhenServerDown2567=== PAUSE TestDrainGivesUpWhenServerDown2568=== RUN TestFailedPathPrunedByLaterClosure2569=== PAUSE TestFailedPathPrunedByLaterClosure2570=== RUN TestWorkerUploadsAndRemoves2571=== PAUSE TestWorkerUploadsAndRemoves2572=== RUN TestWorkerSkipsGCdPaths2573=== PAUSE TestWorkerSkipsGCdPaths2574=== RUN TestWorkerPrunesClosureDeps2575=== PAUSE TestWorkerPrunesClosureDeps2576=== RUN TestDrainTimeout2577=== PAUSE TestDrainTimeout2578=== CONT TestSendPathsEmpty2579=== CONT TestDrainIsolatesPoisonPath2580=== CONT TestQueueDeduplication2581=== CONT TestWorkerUploadsAndRemoves2582--- PASS: TestSendPathsEmpty (0.00s)2583=== CONT TestDrainTimeout2584=== CONT TestServerQueueError2585=== CONT TestWorkerPrunesClosureDeps2586=== CONT TestServerClientIntegration2587=== CONT TestQueueRemoveLargeClosure2588=== CONT TestWorkerSkipsGCdPaths2589=== CONT TestQueueConcurrentWriters25902026/09/18 18:14:55 ERROR Failed to queue paths error="permission denied" count=12591=== CONT TestQueueFetchRemoveLifecycle2592=== CONT TestDrainGivesUpWhenServerDown2593=== CONT TestQueueRetryMovesToBack2594=== CONT TestQueueFetchBatchLimit2595=== CONT TestFailedPathPrunedByLaterClosure2596=== CONT TestQueueEnqueueAndFetch2597=== CONT TestQueueRemove2598=== CONT TestRunNotBlockedByPoisonHead2599--- PASS: TestServerClientIntegration (0.00s)2600--- PASS: TestServerQueueError (0.00s)26012026/09/18 18:14:55 INFO Uploading batch count=226022026/09/18 18:14:55 INFO Uploading batch count=426032026/09/18 18:14:55 ERROR Upload failed error="upload failed" count=426042026/09/18 18:14:55 INFO Uploading batch count=126052026/09/18 18:14:55 ERROR Upload failed error="upload failed" count=126062026/09/18 18:14:55 INFO Upload queue status pending=32607--- PASS: TestQueueRemove (0.01s)2608--- PASS: TestQueueFetchBatchLimit (0.01s)26092026/09/18 18:14:55 INFO Uploading batch count=126102026/09/18 18:14:55 ERROR Upload failed error="upload failed" count=126112026/09/18 18:14:55 INFO Uploading batch count=12612--- PASS: TestQueueDeduplication (0.02s)26132026/09/18 18:14:55 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath560139327/002/bbb26142026/09/18 18:14:55 INFO Upload queue status pending=22615--- PASS: TestQueueFetchRemoveLifecycle (0.01s)26162026/09/18 18:14:55 INFO Upload queue status pending=22617--- PASS: TestQueueEnqueueAndFetch (0.01s)26182026/09/18 18:14:55 INFO Uploading batch count=226192026/09/18 18:14:55 INFO Upload queue status pending=226202026/09/18 18:14:55 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths1758537509/002/nonexistent26212026/09/18 18:14:55 INFO Uploading batch count=226222026/09/18 18:14:55 ERROR Upload failed error="upload failed" count=226232026/09/18 18:14:55 INFO Uploading batch count=126242026/09/18 18:14:55 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4006662507/002/a26252026/09/18 18:14:55 INFO Uploading batch count=126262026/09/18 18:14:55 INFO Uploading batch count=126272026/09/18 18:14:55 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4006662507/002/b2628--- PASS: TestQueueRetryMovesToBack (0.02s)26292026/09/18 18:14:55 INFO Uploading batch count=226302026/09/18 18:14:55 ERROR Upload failed error="upload failed" count=226312026/09/18 18:14:55 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4006662507/002/c26322026/09/18 18:14:55 INFO Uploading batch count=126332026/09/18 18:14:55 ERROR Upload failed error="upload failed" count=126342026/09/18 18:14:55 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4006662507/002/d26352026/09/18 18:14:55 INFO Uploading batch count=126362026/09/18 18:14:55 ERROR Upload failed error="upload failed" count=126372026/09/18 18:14:55 INFO Uploading batch count=226382026/09/18 18:14:55 ERROR Upload failed error="upload failed" count=226392026/09/18 18:14:55 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4006662507/002/e26402026/09/18 18:14:55 INFO Uploading batch count=126412026/09/18 18:14:55 ERROR Upload failed error="upload failed" count=126422026/09/18 18:14:55 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown4006662507/002/f2643--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)26442026/09/18 18:14:55 ERROR Drain finished with paths left in queue remaining=126452026/09/18 18:14:55 ERROR Drain finished with paths left in queue remaining=102646--- PASS: TestDrainIsolatesPoisonPath (0.02s)2647--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2648--- PASS: TestWorkerPrunesClosureDeps (0.04s)2649--- PASS: TestWorkerUploadsAndRemoves (0.04s)2650--- PASS: TestWorkerSkipsGCdPaths (0.04s)26512026/09/18 18:14:55 ERROR Upload failed error="context deadline exceeded" count=226522026/09/18 18:14:55 ERROR Drain finished with paths left in queue remaining=42653--- PASS: TestDrainTimeout (0.22s)2654--- PASS: TestQueueConcurrentWriters (0.22s)2655--- PASS: TestQueueRemoveLargeClosure (0.23s)26562026/09/18 18:14:56 INFO Uploading batch count=126572026/09/18 18:14:56 INFO Uploading batch count=126582026/09/18 18:14:56 INFO Uploading batch count=126592026/09/18 18:14:56 ERROR Upload failed error="upload failed" count=126602026/09/18 18:14:56 INFO Uploading batch count=126612026/09/18 18:14:56 ERROR Upload failed error="upload failed" count=126622026/09/18 18:14:56 INFO Uploading batch count=126632026/09/18 18:14:56 ERROR Upload failed error="upload failed" count=126642026/09/18 18:14:56 INFO Uploading batch count=126652026/09/18 18:14:56 ERROR Upload failed error="upload failed" count=126662026/09/18 18:14:56 ERROR Drain finished with paths left in queue remaining=12667--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2668PASS