niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #211
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestCaseHackSuffix5=== PAUSE TestCaseHackSuffix6=== RUN TestFilterOversizedClosures7=== PAUSE TestFilterOversizedClosures8=== RUN TestPartSizeForNAR9=== PAUSE TestPartSizeForNAR10=== RUN TestUploadMultipart_SupersededByPeer11=== PAUSE TestUploadMultipart_SupersededByPeer12=== RUN TestDumpPathCaseHackMatchesNix13--- PASS: TestDumpPathCaseHackMatchesNix (0.06s)14=== RUN TestDumpPathCaseHackCollision15--- PASS: TestDumpPathCaseHackCollision (0.00s)16=== RUN TestDumpPathMatchesNix17=== PAUSE TestDumpPathMatchesNix18=== RUN TestDumpPathSingleFile19=== PAUSE TestDumpPathSingleFile20=== RUN TestDumpPathWriterError21=== PAUSE TestDumpPathWriterError22=== RUN TestEncodeNixBase3223=== PAUSE TestEncodeNixBase3224=== RUN TestEncodeNixBase32WithRealHash25=== PAUSE TestEncodeNixBase32WithRealHash26=== RUN TestConvertHashToNix3227=== PAUSE TestConvertHashToNix3228=== RUN TestGetStorePathHash29=== PAUSE TestGetStorePathHash30=== RUN TestPathInfoHashCompatibility31=== PAUSE TestPathInfoHashCompatibility32=== RUN TestParsePathInfoJSON33=== PAUSE TestParsePathInfoJSON34=== RUN TestParsePathInfoJSONMultiplePaths35=== PAUSE TestParsePathInfoJSONMultiplePaths36=== RUN TestPathInfoCACompatibility37=== PAUSE TestPathInfoCACompatibility38=== RUN TestRateLimiterFeedback39=== PAUSE TestRateLimiterFeedback40=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess41=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess42=== RUN TestResolveStorePath43=== PAUSE TestResolveStorePath44=== RUN TestDoWithRetry_BodyReplayedViaGetBody45=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody46=== RUN TestShellSplit47=== PAUSE TestShellSplit48=== RUN TestShellSplitErrors49=== PAUSE TestShellSplitErrors50=== RUN TestStreamPushReportsEveryPath51=== PAUSE TestStreamPushReportsEveryPath52=== RUN TestStreamPushBatchesUnderLoad53=== PAUSE TestStreamPushBatchesUnderLoad54=== RUN TestStreamPushIsolatesFailures55=== PAUSE TestStreamPushIsolatesFailures56=== RUN TestStreamPushGivesUpOnDeadServer57=== PAUSE TestStreamPushGivesUpOnDeadServer58=== RUN TestStreamPushRequestLine59=== PAUSE TestStreamPushRequestLine60=== RUN TestSetClientTLS61=== PAUSE TestSetClientTLS62=== RUN TestSetClientTLSDoesNotMutateDefaultTransport63=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport64=== RUN TestSetClientTLSErrors65=== PAUSE TestSetClientTLSErrors66=== RUN TestStaticToken67=== PAUSE TestStaticToken68=== RUN TestFileTokenReadsAndCaches69=== PAUSE TestFileTokenReadsAndCaches70=== RUN TestFileTokenMissing71=== PAUSE TestFileTokenMissing72=== RUN TestFileTokenEmpty73=== PAUSE TestFileTokenEmpty74=== RUN TestScriptTokenNoExpiryRerunsEveryCall75=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall76=== RUN TestScriptTokenCachesUntilRefresh77=== PAUSE TestScriptTokenCachesUntilRefresh78=== RUN TestScriptTokenEmptyToken79=== PAUSE TestScriptTokenEmptyToken80=== RUN TestScriptTokenBadJSON81=== PAUSE TestScriptTokenBadJSON82=== RUN TestScriptTokenScriptFails83=== PAUSE TestScriptTokenScriptFails84=== RUN TestScriptTokenEmptyCommand85=== PAUSE TestScriptTokenEmptyCommand86=== CONT TestDoServerRequestAttachesToken87=== CONT TestScriptTokenCachesUntilRefresh88=== CONT TestStaticToken89=== CONT TestShellSplit90--- PASS: TestStaticToken (0.00s)91=== CONT TestSetClientTLSDoesNotMutateDefaultTransport92=== CONT TestScriptTokenNoExpiryRerunsEveryCall93--- PASS: TestShellSplit (0.00s)94=== CONT TestSetClientTLS95=== CONT TestFileTokenEmpty96=== CONT TestFileTokenMissing97=== CONT TestFileTokenReadsAndCaches98=== CONT TestStreamPushGivesUpOnDeadServer99--- PASS: TestFileTokenEmpty (0.00s)100=== CONT TestStreamPushRequestLine101=== CONT TestSetClientTLSErrors1022026/09/16 20:18:03 ERROR Upload failed error="connection refused" count=201032026/09/16 20:18:03 ERROR Server seems unavailable, giving up on batch untried=17104--- PASS: TestFileTokenReadsAndCaches (0.00s)1052026/09/16 20:18:03 ERROR Upload failed error="stale build claim" count=1106=== CONT TestStreamPushBatchesUnderLoad107--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)108=== CONT TestStreamPushIsolatesFailures1092026/09/16 20:18:03 ERROR Upload failed error="bad path" count=3110--- PASS: TestFileTokenMissing (0.00s)111=== CONT TestConvertHashToNix32112=== RUN TestConvertHashToNix32/SRI_format_to_Nix32113=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32114=== RUN TestConvertHashToNix32/already_Nix32_format115=== PAUSE TestConvertHashToNix32/already_Nix32_format116=== RUN TestConvertHashToNix32/invalid_format117=== PAUSE TestConvertHashToNix32/invalid_format118=== CONT TestDoWithRetry_BodyReplayedViaGetBody119--- PASS: TestStreamPushIsolatesFailures (0.00s)120=== CONT TestResolveStorePath1212026/09/16 20:18:03 WARN Rate limiter enabled after throttle name=server-test rate=51222026/09/16 20:18:03 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:57351123--- PASS: TestDoServerRequestAttachesToken (0.00s)124--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)125=== CONT TestRateLimiterFeedback126=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess127=== RUN TestSetClientTLSErrors/missing_cert_file128=== PAUSE TestSetClientTLSErrors/missing_cert_file129=== RUN TestSetClientTLSErrors/missing_key_file130=== PAUSE TestSetClientTLSErrors/missing_key_file131=== RUN TestRateLimiterFeedback/429_enables_limiter132=== RUN TestSetClientTLSErrors/missing_ca_file133=== PAUSE TestRateLimiterFeedback/429_enables_limiter134=== PAUSE TestSetClientTLSErrors/missing_ca_file135=== RUN TestRateLimiterFeedback/503_enables_limiter136=== PAUSE TestRateLimiterFeedback/503_enables_limiter137=== RUN TestSetClientTLSErrors/invalid_ca_file138=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter139=== PAUSE TestSetClientTLSErrors/invalid_ca_file140=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter141=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter142=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter143=== CONT TestPathInfoCACompatibility144=== RUN TestPathInfoCACompatibility/null_ca_field145=== PAUSE TestPathInfoCACompatibility/null_ca_field146=== RUN TestPathInfoCACompatibility/old_string_format_-_text147=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text148=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive149=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive150=== CONT TestParsePathInfoJSONMultiplePaths1512026/09/16 20:18:03 WARN Rate limiter enabled after throttle name=server-test rate=5152=== RUN TestPathInfoCACompatibility/new_structured_format_-_text153=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text154=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method1552026/09/16 20:18:03 WARN Rate limiter backed off name=server-test rate=51562026/09/16 20:18:03 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:57351157=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method158=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths159=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths160=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths161=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths162=== CONT TestParsePathInfoJSON163=== RUN TestParsePathInfoJSON/Nix_format164=== PAUSE TestParsePathInfoJSON/Nix_format165=== CONT TestPathInfoHashCompatibility166=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)167=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)168=== RUN TestParsePathInfoJSON/Lix_format169=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon170=== PAUSE TestParsePathInfoJSON/Lix_format171=== RUN TestParsePathInfoJSON/empty_input172=== PAUSE TestParsePathInfoJSON/empty_input173=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon174=== RUN TestParsePathInfoJSON/whitespace_only175=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI176=== PAUSE TestParsePathInfoJSON/whitespace_only177=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI178=== RUN TestParsePathInfoJSON/invalid_JSON179=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512180=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512181=== PAUSE TestParsePathInfoJSON/invalid_JSON182--- PASS: TestResolveStorePath (0.00s)183=== CONT TestGetStorePathHash184=== RUN TestGetStorePathHash/valid_store_path185=== CONT TestDumpPathMatchesNix186=== CONT TestStreamPushReportsEveryPath187--- PASS: TestStreamPushReportsEveryPath (0.00s)188=== CONT TestEncodeNixBase32WithRealHash189--- PASS: TestEncodeNixBase32WithRealHash (0.00s)190=== CONT TestEncodeNixBase32191=== RUN TestEncodeNixBase32/test_string_hash192=== PAUSE TestEncodeNixBase32/test_string_hash193=== RUN TestEncodeNixBase32/empty_input194=== PAUSE TestEncodeNixBase32/empty_input195=== CONT TestDumpPathWriterError196--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)197=== CONT TestDumpPathSingleFile198=== PAUSE TestGetStorePathHash/valid_store_path199=== RUN TestGetStorePathHash/basename_without_hyphen_should_error200=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error201=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error202=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error203=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error204=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error205=== CONT TestScriptTokenBadJSON206=== RUN TestSetClientTLS/rejects_connection_without_client_cert207=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert208=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA209=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA210=== RUN TestSetClientTLS/preserves_debug_logging_transport211=== PAUSE TestSetClientTLS/preserves_debug_logging_transport212=== CONT TestScriptTokenEmptyToken213--- PASS: TestScriptTokenBadJSON (0.01s)214=== CONT TestShellSplitErrors215--- PASS: TestShellSplitErrors (0.00s)216=== CONT TestPartSizeForNAR217=== RUN TestPartSizeForNAR/zero_stays_at_minimum218=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum219=== RUN TestPartSizeForNAR/small_stays_at_minimum220=== PAUSE TestPartSizeForNAR/small_stays_at_minimum221=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum222=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum223=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts224=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts225=== RUN TestPartSizeForNAR/1_TiB226=== PAUSE TestPartSizeForNAR/1_TiB227=== RUN TestPartSizeForNAR/5_TiB_S3_max_object228=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object229=== RUN TestPartSizeForNAR/capped_at_5_GiB230=== PAUSE TestPartSizeForNAR/capped_at_5_GiB231=== CONT TestUploadMultipart_SupersededByPeer232=== RUN TestUploadMultipart_SupersededByPeer/exists233=== PAUSE TestUploadMultipart_SupersededByPeer/exists234=== RUN TestUploadMultipart_SupersededByPeer/missing235=== PAUSE TestUploadMultipart_SupersededByPeer/missing236=== CONT TestFilterOversizedClosures237=== RUN TestFilterOversizedClosures/no_limit_keeps_everything238=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything239=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped240=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped241=== RUN TestFilterOversizedClosures/all_closures_skipped242=== PAUSE TestFilterOversizedClosures/all_closures_skipped243=== CONT TestScriptTokenEmptyCommand244--- PASS: TestScriptTokenEmptyCommand (0.00s)245=== CONT TestCaseHackSuffix246--- PASS: TestScriptTokenEmptyToken (0.01s)247=== CONT TestScriptTokenScriptFails248--- PASS: TestStreamPushRequestLine (0.02s)249=== CONT TestConvertHashToNix32/SRI_format_to_Nix32250=== CONT TestConvertHashToNix32/already_Nix32_format251=== CONT TestConvertHashToNix32/invalid_format252--- PASS: TestConvertHashToNix32 (0.00s)253 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)254 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)255 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)256=== CONT TestSetClientTLSErrors/missing_cert_file257=== CONT TestRateLimiterFeedback/429_enables_limiter2582026/09/16 20:18:03 WARN Rate limiter enabled after throttle name=server-test rate=52592026/09/16 20:18:03 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:573562602026/09/16 20:18:03 WARN Rate limiter backed off name=server-test rate=5261=== CONT TestSetClientTLSErrors/missing_ca_file262=== CONT TestSetClientTLSErrors/missing_key_file263=== CONT TestSetClientTLSErrors/invalid_ca_file264=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter265--- PASS: TestSetClientTLSErrors (0.00s)266 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)267 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)268 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)269 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)270=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter271=== CONT TestRateLimiterFeedback/503_enables_limiter2722026/09/16 20:18:03 WARN Rate limiter enabled after throttle name=server-test rate=52732026/09/16 20:18:03 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:573622742026/09/16 20:18:03 WARN Rate limiter backed off name=server-test rate=5275=== CONT TestPathInfoCACompatibility/null_ca_field276--- PASS: TestRateLimiterFeedback (0.00s)277 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)278 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)279 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)280 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)281=== CONT TestPathInfoCACompatibility/new_structured_format_-_text282=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method283=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive284=== CONT TestPathInfoCACompatibility/old_string_format_-_text285--- PASS: TestPathInfoCACompatibility (0.00s)286 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)287 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)288 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)289 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)290 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)291=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths292=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths293--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)294 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)295 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)296=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)297=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512298=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI299--- PASS: TestScriptTokenScriptFails (0.00s)300=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon301--- PASS: TestPathInfoHashCompatibility (0.00s)302 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)303 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)304 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)305 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)306=== CONT TestParsePathInfoJSON/Nix_format307=== CONT TestParsePathInfoJSON/whitespace_only308=== CONT TestParsePathInfoJSON/Lix_format309=== CONT TestParsePathInfoJSON/empty_input310=== CONT TestEncodeNixBase32/test_string_hash311=== CONT TestEncodeNixBase32/empty_input312--- PASS: TestEncodeNixBase32 (0.00s)313 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)314 --- PASS: TestEncodeNixBase32/empty_input (0.00s)315=== CONT TestGetStorePathHash/valid_store_path316=== CONT TestParsePathInfoJSON/invalid_JSON317=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error318=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error319--- PASS: TestParsePathInfoJSON (0.00s)320 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)321 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)322 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)323 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)324 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)325=== CONT TestSetClientTLS/rejects_connection_without_client_cert326=== CONT TestGetStorePathHash/basename_without_hyphen_should_error327--- PASS: TestGetStorePathHash (0.00s)328 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)329 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)330 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)331 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)332=== CONT TestSetClientTLS/preserves_debug_logging_transport333--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)334=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA335=== CONT TestPartSizeForNAR/zero_stays_at_minimum336=== CONT TestUploadMultipart_SupersededByPeer/exists337=== CONT TestPartSizeForNAR/capped_at_5_GiB338=== CONT TestPartSizeForNAR/5_TiB_S3_max_object339=== CONT TestPartSizeForNAR/1_TiB340=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts341--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.03s)342=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum343=== CONT TestPartSizeForNAR/small_stays_at_minimum344--- PASS: TestPartSizeForNAR (0.00s)345 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)346 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)347 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)348 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)349 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)350 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)351 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)352=== CONT TestUploadMultipart_SupersededByPeer/missing353=== CONT TestFilterOversizedClosures/no_limit_keeps_everything354=== CONT TestFilterOversizedClosures/all_closures_skipped3552026/09/16 20:18:03 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=50356--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)357 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)358 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)359=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3602026/09/16 20:18:03 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=2000361--- PASS: TestFilterOversizedClosures (0.00s)362 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)363 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)364 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)3652026/09/16 20:18:03 http: TLS handshake error from 127.0.0.1:57364: remote error: tls: bad certificate366--- PASS: TestSetClientTLS (0.01s)367 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)368 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)369 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)370--- PASS: TestDumpPathWriterError (0.04s)371--- PASS: TestDumpPathSingleFile (0.04s)372--- PASS: TestCaseHackSuffix (0.04s)373--- PASS: TestDumpPathMatchesNix (0.06s)374--- PASS: TestStreamPushBatchesUnderLoad (0.10s)375--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)376PASS377Running server tests...378The files belonging to this database system will be owned by user "_nixbld1".379This user must also own the server process.380381The database cluster will be initialized with locale "C".382The default database encoding has accordingly been set to "SQL_ASCII".383The default text search configuration will be set to "english".384385Data page checksums are enabled.386387creating directory /nix/var/nix/builds/nix-70685-2045658380/postgres1410544709/data ... ok388creating subdirectories ... ok389selecting dynamic shared memory implementation ... posix390selecting default "max_connections" ... 100391selecting default "shared_buffers" ... 128MB392selecting default time zone ... UTC393creating configuration files ... ok394running bootstrap script ... ok395performing post-bootstrap initialization ... ok396syncing data to disk ... ok397398initdb: warning: enabling "trust" authentication for local connections399initdb: 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.400401Success. You can now start the database server using:402403 pg_ctl -D /nix/var/nix/builds/nix-70685-2045658380/postgres1410544709/data -l logfile start404405/nix/var/nix/builds/nix-70685-2045658380/postgres1410544709:5432 - no response4062026-09-16 20:18:04.944 UTC [70723] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4072026-09-16 20:18:04.944 UTC [70723] LOG: listening on Unix socket "/nix/var/nix/builds/nix-70685-2045658380/postgres1410544709/.s.PGSQL.5432"4082026-09-16 20:18:04.946 UTC [70730] LOG: database system was shut down at 2026-09-16 20:18:04 UTC4092026-09-16 20:18:04.947 UTC [70723] LOG: database system is ready to accept connections410/nix/var/nix/builds/nix-70685-2045658380/postgres1410544709:5432 - accepting connections411=== RUN TestService_AuthMiddleware412=== PAUSE TestService_AuthMiddleware413=== RUN TestService_AuthMiddleware_MTLSProxyHeader414=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader415=== RUN TestService_AuthMiddleware_MTLSBoundSubjects416=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects417=== RUN TestService_ReadAuthMiddleware418=== PAUSE TestService_ReadAuthMiddleware419=== RUN TestService_AuthMiddleware_OIDC420=== PAUSE TestService_AuthMiddleware_OIDC421=== RUN TestService_RequireScope_OIDC422=== PAUSE TestService_RequireScope_OIDC423=== RUN TestService_ReadScope_PublicByDefault424=== PAUSE TestService_ReadScope_PublicByDefault425=== RUN TestCacheConfigHandler426=== PAUSE TestCacheConfigHandler427=== RUN TestCacheStatsHandler428=== PAUSE TestCacheStatsHandler429=== RUN TestClaim_BuildWaitComplete430=== PAUSE TestClaim_BuildWaitComplete431=== RUN TestClaim_GCMarkedOutputCountsAsAbsent432=== PAUSE TestClaim_GCMarkedOutputCountsAsAbsent433=== RUN TestClaim_TooManyStreams434=== PAUSE TestClaim_TooManyStreams435=== RUN TestClaim_HolderDisconnectKeepsClaim436=== PAUSE TestClaim_HolderDisconnectKeepsClaim437=== RUN TestClaim_FailWakesWaitersButIsNotRemembered438=== PAUSE TestClaim_FailWakesWaitersButIsNotRemembered439=== RUN TestClaim_FailWithoutKindReleases440=== PAUSE TestClaim_FailWithoutKindReleases441=== RUN TestClaim_StaleHeartbeatStolen442=== PAUSE TestClaim_StaleHeartbeatStolen443=== RUN TestClaim_TwoInstances444=== PAUSE TestClaim_TwoInstances445=== RUN TestClaim_InputsTouched446=== PAUSE TestClaim_InputsTouched447=== RUN TestClaim_StreamsThroughServer448=== PAUSE TestClaim_StreamsThroughServer449=== RUN TestClientCADerivations450=== PAUSE TestClientCADerivations451=== RUN TestClientErrorHandling452=== PAUSE TestClientErrorHandling453=== RUN TestClientIntegration454=== PAUSE TestClientIntegration455=== RUN TestClientMultipleUploads456=== PAUSE TestClientMultipleUploads457=== RUN TestClientWithDependencies458=== PAUSE TestClientWithDependencies459=== RUN TestPinProtectsFromGC460=== PAUSE TestPinProtectsFromGC461=== RUN TestResolveDBConnectionString462=== PAUSE TestResolveDBConnectionString463=== RUN TestGCAdvisoryLockBlocksConcurrentRun4642026-09-16 20:18:05.326 UTC [70802] ERROR: relation "goose_db_version" does not exist at character 364652026-09-16 20:18:05.326 UTC [70802] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4662026/09/16 20:18:05 OK 20241026095416_initial_model.sql (3.91ms)4672026/09/16 20:18:05 OK 20251210153512_drop_unused_gin_index.sql (448.63µs)4682026/09/16 20:18:05 OK 20251218171726_add_pins.sql (854.08µs)4692026/09/16 20:18:05 OK 20260628120000_add_object_size_and_stats.sql (954.08µs)4702026/09/16 20:18:05 OK 20260905000000_add_claims.sql (935.29µs)4712026/09/16 20:18:05 goose: successfully migrated database to version: 202609050000004722026/09/16 20:18:05 OK 1_commit_pending_closure.sql (1.05ms)4732026/09/16 20:18:05 OK 2_object_stats_trigger.sql (200.54µs)4742026/09/16 20:18:05 goose: up to current file version: 2475--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.23s)476=== RUN TestGCBugBareHashReferences477=== PAUSE TestGCBugBareHashReferences478=== RUN TestGCMetrics479=== PAUSE TestGCMetrics480=== RUN TestGCTaskStore_StartNew481=== PAUSE TestGCTaskStore_StartNew482=== RUN TestGCTaskStore_DeduplicateSameParams483=== PAUSE TestGCTaskStore_DeduplicateSameParams484=== RUN TestGCTaskStore_ConflictDifferentParams485=== PAUSE TestGCTaskStore_ConflictDifferentParams486=== RUN TestGCTaskStore_GetEmpty487=== PAUSE TestGCTaskStore_GetEmpty488=== RUN TestGCTaskStore_GetReturnsLatest489=== PAUSE TestGCTaskStore_GetReturnsLatest490=== RUN TestGCTaskStore_CompletedAllowsNewTask491=== PAUSE TestGCTaskStore_CompletedAllowsNewTask492=== RUN TestGCTaskStore_PhaseUpdates493=== PAUSE TestGCTaskStore_PhaseUpdates494=== RUN TestGCTaskStore_Fail495=== PAUSE TestGCTaskStore_Fail496=== RUN TestGracefulShutdownDrainsInflight497=== PAUSE TestGracefulShutdownDrainsInflight498=== RUN TestService_healthCheckHandler499=== PAUSE TestService_healthCheckHandler500=== RUN TestService_readinessHandler501=== PAUSE TestService_readinessHandler502=== RUN TestGenerateLandingPage503=== PAUSE TestGenerateLandingPage504=== RUN TestCacheConfigHandlerMaxNarSize505=== PAUSE TestCacheConfigHandlerMaxNarSize506=== RUN TestCreatePendingClosureRejectsOversizedNAR507=== PAUSE TestCreatePendingClosureRejectsOversizedNAR508=== RUN TestNARDeduplicationMetadataUploadBug509=== PAUSE TestNARDeduplicationMetadataUploadBug510=== RUN TestMetricsInventory511=== PAUSE TestMetricsInventory512=== RUN TestService_NativeMTLS513=== PAUSE TestService_NativeMTLS514=== RUN TestServerTLSConfig515=== PAUSE TestServerTLSConfig516=== RUN TestMultipartCleanup517=== PAUSE TestMultipartCleanup518=== RUN TestObjectStatsTrigger519=== PAUSE TestObjectStatsTrigger520=== RUN TestOrphanedObjectsGC521=== PAUSE TestOrphanedObjectsGC522=== RUN TestOrphanedObjectsGCStressTest523=== PAUSE TestOrphanedObjectsGCStressTest524=== RUN TestResurrectedObjectNotDeleted525=== PAUSE TestResurrectedObjectNotDeleted526=== RUN TestParseSingleRange527=== PAUSE TestParseSingleRange528=== RUN TestIsValidCachePath529=== PAUSE TestIsValidCachePath530=== RUN TestReadProxyNarinfo531=== PAUSE TestReadProxyNarinfo532=== RUN TestReadProxyNarinfoAlreadyDecompressed533=== PAUSE TestReadProxyNarinfoAlreadyDecompressed534=== RUN TestReadProxyNarStreaming535=== PAUSE TestReadProxyNarStreaming536=== RUN TestReadProxy404537=== PAUSE TestReadProxy404538=== RUN TestReadProxyInvalidPath539=== PAUSE TestReadProxyInvalidPath540=== RUN TestReadProxyHead541=== PAUSE TestReadProxyHead542=== RUN TestReadProxyConditionalGet543=== PAUSE TestReadProxyConditionalGet544=== RUN TestReadProxyRootRedirectsToIndexHTML545=== PAUSE TestReadProxyRootRedirectsToIndexHTML546=== RUN TestReadProxyDisabled547=== PAUSE TestReadProxyDisabled548=== RUN TestReadRedirectNar549=== PAUSE TestReadRedirectNar550=== RUN TestReadRedirectKeepsNarinfoProxied551=== PAUSE TestReadRedirectKeepsNarinfoProxied552=== RUN TestReadProxyRangeRequest553=== PAUSE TestReadProxyRangeRequest554=== RUN TestReadRedirectUsesPublicS3URL555=== PAUSE TestReadRedirectUsesPublicS3URL556=== RUN TestRedundantMultipartUpload557=== PAUSE TestRedundantMultipartUpload558=== RUN TestCompleteMultipartUpload_ErrorButObjectExists559=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists560=== RUN TestCompletedNarNotReofferedAcrossClosures561=== PAUSE TestCompletedNarNotReofferedAcrossClosures562=== RUN TestPresignedUploadRegisteredBeforeCommit563=== PAUSE TestPresignedUploadRegisteredBeforeCommit564=== RUN TestService_Rustfstest565=== PAUSE TestService_Rustfstest566=== RUN TestParseSize567=== PAUSE TestParseSize568=== RUN TestSkippedUploadsHandler569=== PAUSE TestSkippedUploadsHandler570=== RUN TestSystemdListenerNotActivated571--- PASS: TestSystemdListenerNotActivated (0.00s)572=== RUN TestWatchdogBeatsWhenHealthy573--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)574=== RUN TestWatchdogSkipsWhenUnhealthy5752026/09/16 20:18:05 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5762026/09/16 20:18:05 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5772026/09/16 20:18:05 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5782026/09/16 20:18:05 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5792026/09/16 20:18:05 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5802026/09/16 20:18:05 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5812026/09/16 20:18:05 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5822026/09/16 20:18:05 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5832026/09/16 20:18:05 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5842026/09/16 20:18:05 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"585--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)586=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle587=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle588=== RUN TestProxyWriteTimeout589=== PAUSE TestProxyWriteTimeout590=== RUN TestIsValidUploadKey591=== PAUSE TestIsValidUploadKey592=== RUN TestUploadHandlersRejectInvalidKeys593=== PAUSE TestUploadHandlersRejectInvalidKeys594=== RUN TestUploadHandlersRejectOversizedBody595=== PAUSE TestUploadHandlersRejectOversizedBody596=== RUN TestService_cleanupPendingClosuresHandler597=== PAUSE TestService_cleanupPendingClosuresHandler598=== RUN TestService_createPendingClosureHandler599=== PAUSE TestService_createPendingClosureHandler600=== RUN TestService_verifyS3Integrity601=== PAUSE TestService_verifyS3Integrity602=== RUN TestCompleteMultipartUnregistered603=== PAUSE TestCompleteMultipartUnregistered604=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT605=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT606=== CONT TestReadRedirectKeepsNarinfoProxied607=== CONT TestService_AuthMiddleware608=== CONT TestGCTaskStore_GetReturnsLatest609=== CONT TestOrphanedObjectsGC610=== CONT TestReadProxy404611--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)612=== CONT TestObjectStatsTrigger613=== CONT TestMultipartCleanup614=== CONT TestServerTLSConfig615=== RUN TestServerTLSConfig/no_client_CA616=== PAUSE TestServerTLSConfig/no_client_CA617=== RUN TestServerTLSConfig/missing_CA_file618=== PAUSE TestServerTLSConfig/missing_CA_file619=== RUN TestServerTLSConfig/not_a_PEM_file620=== PAUSE TestServerTLSConfig/not_a_PEM_file621=== CONT TestService_NativeMTLS622=== CONT TestMetricsInventory623=== CONT TestNARDeduplicationMetadataUploadBug624=== CONT TestCreatePendingClosureRejectsOversizedNAR6252026/09/16 20:18:05 INFO Received uploads request method=POST path=/api/pending_closures626--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)627=== CONT TestCacheConfigHandlerMaxNarSize628--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)629=== CONT TestGenerateLandingPage630--- PASS: TestGenerateLandingPage (0.00s)631=== CONT TestService_readinessHandler6322026-09-16 20:18:05.997 UTC [70825] ERROR: relation "goose_db_version" does not exist at character 366332026-09-16 20:18:05.997 UTC [70825] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6342026-09-16 20:18:05.997 UTC [70826] ERROR: relation "goose_db_version" does not exist at character 366352026-09-16 20:18:05.997 UTC [70826] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6362026-09-16 20:18:05.997 UTC [70824] ERROR: relation "goose_db_version" does not exist at character 366372026-09-16 20:18:05.997 UTC [70824] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6382026-09-16 20:18:05.999 UTC [70829] ERROR: relation "goose_db_version" does not exist at character 366392026-09-16 20:18:05.999 UTC [70829] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6402026-09-16 20:18:06.000 UTC [70827] ERROR: relation "goose_db_version" does not exist at character 366412026-09-16 20:18:06.000 UTC [70827] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6422026-09-16 20:18:06.000 UTC [70828] ERROR: relation "goose_db_version" does not exist at character 366432026-09-16 20:18:06.000 UTC [70828] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6442026-09-16 20:18:06.001 UTC [70830] ERROR: relation "goose_db_version" does not exist at character 366452026-09-16 20:18:06.001 UTC [70830] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6462026-09-16 20:18:06.001 UTC [70832] ERROR: relation "goose_db_version" does not exist at character 366472026-09-16 20:18:06.001 UTC [70832] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6482026-09-16 20:18:06.002 UTC [70831] ERROR: relation "goose_db_version" does not exist at character 366492026-09-16 20:18:06.002 UTC [70831] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6502026-09-16 20:18:06.003 UTC [70833] ERROR: relation "goose_db_version" does not exist at character 366512026-09-16 20:18:06.003 UTC [70833] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6522026/09/16 20:18:06 OK 20241026095416_initial_model.sql (6.99ms)6532026/09/16 20:18:06 OK 20241026095416_initial_model.sql (8.71ms)6542026/09/16 20:18:06 OK 20251210153512_drop_unused_gin_index.sql (1.02ms)6552026/09/16 20:18:06 OK 20251210153512_drop_unused_gin_index.sql (966.88µs)6562026/09/16 20:18:06 OK 20241026095416_initial_model.sql (8.59ms)6572026/09/16 20:18:06 OK 20241026095416_initial_model.sql (6.95ms)6582026/09/16 20:18:06 OK 20241026095416_initial_model.sql (7.75ms)6592026/09/16 20:18:06 OK 20241026095416_initial_model.sql (8.2ms)6602026/09/16 20:18:06 OK 20251210153512_drop_unused_gin_index.sql (910.67µs)6612026/09/16 20:18:06 OK 20251218171726_add_pins.sql (2.34ms)6622026/09/16 20:18:06 OK 20251210153512_drop_unused_gin_index.sql (809.38µs)6632026/09/16 20:18:06 OK 20251210153512_drop_unused_gin_index.sql (733.83µs)6642026/09/16 20:18:06 OK 20251210153512_drop_unused_gin_index.sql (849.88µs)6652026/09/16 20:18:06 OK 20251218171726_add_pins.sql (2.15ms)6662026/09/16 20:18:06 OK 20241026095416_initial_model.sql (9.66ms)6672026/09/16 20:18:06 OK 20241026095416_initial_model.sql (6.82ms)6682026/09/16 20:18:06 OK 20241026095416_initial_model.sql (8.75ms)6692026/09/16 20:18:06 OK 20251218171726_add_pins.sql (1.67ms)6702026/09/16 20:18:06 OK 20251218171726_add_pins.sql (1.99ms)6712026/09/16 20:18:06 OK 20260628120000_add_object_size_and_stats.sql (1.93ms)6722026/09/16 20:18:06 OK 20251210153512_drop_unused_gin_index.sql (521.54µs)6732026/09/16 20:18:06 OK 20251218171726_add_pins.sql (2.17ms)6742026/09/16 20:18:06 OK 20251210153512_drop_unused_gin_index.sql (821.92µs)6752026/09/16 20:18:06 OK 20251210153512_drop_unused_gin_index.sql (1ms)6762026/09/16 20:18:06 OK 20260628120000_add_object_size_and_stats.sql (1.79ms)6772026/09/16 20:18:06 OK 20251218171726_add_pins.sql (2.38ms)6782026/09/16 20:18:06 OK 20260628120000_add_object_size_and_stats.sql (1.29ms)6792026/09/16 20:18:06 OK 20241026095416_initial_model.sql (6.76ms)6802026/09/16 20:18:06 OK 20260628120000_add_object_size_and_stats.sql (1.56ms)6812026/09/16 20:18:06 OK 20260905000000_add_claims.sql (2.18ms)6822026/09/16 20:18:06 goose: successfully migrated database to version: 202609050000006832026/09/16 20:18:06 OK 20251218171726_add_pins.sql (1.83ms)6842026/09/16 20:18:06 OK 20260628120000_add_object_size_and_stats.sql (1.59ms)6852026/09/16 20:18:06 OK 20251210153512_drop_unused_gin_index.sql (969µs)6862026/09/16 20:18:06 OK 20260628120000_add_object_size_and_stats.sql (2.21ms)6872026/09/16 20:18:06 OK 20251218171726_add_pins.sql (2.05ms)6882026/09/16 20:18:06 OK 20251218171726_add_pins.sql (2.63ms)6892026/09/16 20:18:06 OK 20260905000000_add_claims.sql (2.71ms)6902026/09/16 20:18:06 goose: successfully migrated database to version: 202609050000006912026/09/16 20:18:06 OK 20260905000000_add_claims.sql (2.08ms)6922026/09/16 20:18:06 goose: successfully migrated database to version: 202609050000006932026/09/16 20:18:06 OK 1_commit_pending_closure.sql (1.42ms)6942026/09/16 20:18:06 OK 20260905000000_add_claims.sql (2.3ms)6952026/09/16 20:18:06 goose: successfully migrated database to version: 202609050000006962026/09/16 20:18:06 OK 20260628120000_add_object_size_and_stats.sql (1.79ms)6972026/09/16 20:18:06 OK 20260628120000_add_object_size_and_stats.sql (1.61ms)6982026/09/16 20:18:06 OK 2_object_stats_trigger.sql (599.58µs)6992026/09/16 20:18:06 goose: up to current file version: 27002026/09/16 20:18:06 OK 20260905000000_add_claims.sql (1.9ms)7012026/09/16 20:18:06 goose: successfully migrated database to version: 202609050000007022026/09/16 20:18:06 OK 1_commit_pending_closure.sql (1.15ms)7032026/09/16 20:18:06 OK 20251218171726_add_pins.sql (1.99ms)7042026/09/16 20:18:06 OK 20260905000000_add_claims.sql (2.02ms)7052026/09/16 20:18:06 goose: successfully migrated database to version: 202609050000007062026/09/16 20:18:06 OK 20260628120000_add_object_size_and_stats.sql (1.83ms)7072026/09/16 20:18:06 OK 1_commit_pending_closure.sql (1.46ms)7082026/09/16 20:18:06 OK 2_object_stats_trigger.sql (643.08µs)7092026/09/16 20:18:06 goose: up to current file version: 27102026/09/16 20:18:06 OK 1_commit_pending_closure.sql (1.48ms)7112026/09/16 20:18:06 OK 20260905000000_add_claims.sql (1.46ms)7122026/09/16 20:18:06 goose: successfully migrated database to version: 202609050000007132026/09/16 20:18:06 OK 2_object_stats_trigger.sql (686.17µs)7142026/09/16 20:18:06 goose: up to current file version: 27152026/09/16 20:18:06 OK 1_commit_pending_closure.sql (1.08ms)7162026/09/16 20:18:06 OK 2_object_stats_trigger.sql (342.54µs)7172026/09/16 20:18:06 goose: up to current file version: 27182026/09/16 20:18:06 OK 20260628120000_add_object_size_and_stats.sql (1.16ms)7192026/09/16 20:18:06 OK 20260905000000_add_claims.sql (1.69ms)7202026/09/16 20:18:06 goose: successfully migrated database to version: 202609050000007212026/09/16 20:18:06 OK 2_object_stats_trigger.sql (525µs)7222026/09/16 20:18:06 goose: up to current file version: 27232026/09/16 20:18:06 OK 20260905000000_add_claims.sql (1.54ms)7242026/09/16 20:18:06 goose: successfully migrated database to version: 202609050000007252026/09/16 20:18:06 OK 1_commit_pending_closure.sql (732.54µs)7262026/09/16 20:18:06 OK 1_commit_pending_closure.sql (1.74ms)7272026/09/16 20:18:06 OK 2_object_stats_trigger.sql (210.25µs)7282026/09/16 20:18:06 goose: up to current file version: 27292026/09/16 20:18:06 OK 2_object_stats_trigger.sql (239.17µs)7302026/09/16 20:18:06 goose: up to current file version: 27312026/09/16 20:18:06 OK 1_commit_pending_closure.sql (751.92µs)7322026/09/16 20:18:06 OK 20260905000000_add_claims.sql (1.05ms)7332026/09/16 20:18:06 goose: successfully migrated database to version: 202609050000007342026/09/16 20:18:06 OK 2_object_stats_trigger.sql (235.25µs)7352026/09/16 20:18:06 goose: up to current file version: 27362026/09/16 20:18:06 OK 1_commit_pending_closure.sql (962.88µs)7372026/09/16 20:18:06 OK 2_object_stats_trigger.sql (177.67µs)7382026/09/16 20:18:06 goose: up to current file version: 27392026/09/16 20:18:06 OK 1_commit_pending_closure.sql (711.17µs)7402026/09/16 20:18:06 OK 2_object_stats_trigger.sql (187.58µs)7412026/09/16 20:18:06 goose: up to current file version: 27422026/09/16 20:18:06 WARN readiness check failed error="closed pool"743--- PASS: TestService_readinessHandler (0.46s)744=== CONT TestService_healthCheckHandler7452026/09/16 20:18:06 INFO Received uploads request method=POST path=/api/pending_closures7462026/09/16 20:18:06 INFO Received cleanup request method=DELETE path=/api/pending_closures7472026/09/16 20:18:06 INFO Aborted multipart uploads count=1748--- PASS: TestMultipartCleanup (0.76s)749=== CONT TestGracefulShutdownDrainsInflight7502026/09/16 20:18:06 INFO Starting HTTP server address=127.0.0.1:573887512026/09/16 20:18:06 INFO Shutdown signal received, draining in-flight requests timeout=10s752--- PASS: TestObjectStatsTrigger (0.80s)753=== CONT TestGCTaskStore_Fail754--- PASS: TestGCTaskStore_Fail (0.00s)755=== CONT TestGCTaskStore_PhaseUpdates756--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)757=== CONT TestGCTaskStore_CompletedAllowsNewTask758--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)759=== CONT TestReadProxyRootRedirectsToIndexHTML760--- PASS: TestGracefulShutdownDrainsInflight (0.07s)761=== CONT TestReadRedirectNar762--- PASS: TestReadProxy404 (0.92s)763=== CONT TestReadProxyDisabled7642026-09-16 20:18:06.601 UTC [70843] ERROR: relation "goose_db_version" does not exist at character 367652026-09-16 20:18:06.601 UTC [70843] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7662026/09/16 20:18:06 OK 20241026095416_initial_model.sql (65.46ms)7672026/09/16 20:18:06 OK 20251210153512_drop_unused_gin_index.sql (3.66ms)7682026/09/16 20:18:06 OK 20251218171726_add_pins.sql (12.07ms)769--- PASS: TestMetricsInventory (1.09s)770=== CONT TestReadProxyHead7712026/09/16 20:18:06 OK 20260628120000_add_object_size_and_stats.sql (16.42ms)7722026/09/16 20:18:06 OK 20260905000000_add_claims.sql (17.57ms)7732026/09/16 20:18:06 goose: successfully migrated database to version: 202609050000007742026/09/16 20:18:06 OK 1_commit_pending_closure.sql (2.61ms)7752026/09/16 20:18:06 OK 2_object_stats_trigger.sql (541.92µs)7762026/09/16 20:18:06 goose: up to current file version: 27772026-09-16 20:18:06.837 UTC [70846] ERROR: relation "goose_db_version" does not exist at character 367782026-09-16 20:18:06.837 UTC [70846] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7792026-09-16 20:18:06.847 UTC [70847] ERROR: relation "goose_db_version" does not exist at character 367802026-09-16 20:18:06.847 UTC [70847] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7812026/09/16 20:18:06 OK 20241026095416_initial_model.sql (45.9ms)7822026/09/16 20:18:06 OK 20251210153512_drop_unused_gin_index.sql (5.61ms)7832026/09/16 20:18:06 OK 20241026095416_initial_model.sql (43.68ms)7842026/09/16 20:18:06 OK 20251210153512_drop_unused_gin_index.sql (5.72ms)7852026/09/16 20:18:06 OK 20251218171726_add_pins.sql (7.86ms)7862026/09/16 20:18:06 OK 20251218171726_add_pins.sql (4.84ms)7872026/09/16 20:18:06 OK 20260628120000_add_object_size_and_stats.sql (18.66ms)7882026/09/16 20:18:06 OK 20260628120000_add_object_size_and_stats.sql (21.57ms)7892026-09-16 20:18:06.939 UTC [70848] ERROR: relation "goose_db_version" does not exist at character 367902026-09-16 20:18:06.939 UTC [70848] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7912026/09/16 20:18:06 OK 20260905000000_add_claims.sql (15.32ms)7922026/09/16 20:18:06 goose: successfully migrated database to version: 202609050000007932026/09/16 20:18:06 OK 20260905000000_add_claims.sql (15.43ms)7942026/09/16 20:18:06 goose: successfully migrated database to version: 202609050000007952026/09/16 20:18:06 OK 1_commit_pending_closure.sql (7.42ms)7962026/09/16 20:18:06 OK 1_commit_pending_closure.sql (7.49ms)7972026/09/16 20:18:06 OK 2_object_stats_trigger.sql (534.5µs)7982026/09/16 20:18:06 goose: up to current file version: 27992026/09/16 20:18:06 OK 2_object_stats_trigger.sql (601µs)8002026/09/16 20:18:06 goose: up to current file version: 28012026/09/16 20:18:07 OK 20241026095416_initial_model.sql (41.97ms)8022026/09/16 20:18:07 OK 20251210153512_drop_unused_gin_index.sql (9.82ms)8032026/09/16 20:18:07 OK 20251218171726_add_pins.sql (7.77ms)8042026/09/16 20:18:07 OK 20260628120000_add_object_size_and_stats.sql (6.51ms)8052026/09/16 20:18:07 OK 20260905000000_add_claims.sql (11.68ms)8062026/09/16 20:18:07 goose: successfully migrated database to version: 202609050000008072026/09/16 20:18:07 OK 1_commit_pending_closure.sql (1.41ms)8082026/09/16 20:18:07 OK 2_object_stats_trigger.sql (380.75µs)8092026/09/16 20:18:07 goose: up to current file version: 2810=== NAME TestNARDeduplicationMetadataUploadBug811 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-70685-2045658380/TestNARDeduplicationMetadataUploadBug2358181630/001/store/f25nzdq2vl4pxylx7l8zamzda31pk6h3-file1.txt812--- PASS: TestReadRedirectKeepsNarinfoProxied (1.52s)813=== CONT TestReadProxyConditionalGet8142026-09-16 20:18:07.146 UTC [70852] ERROR: relation "goose_db_version" does not exist at character 368152026-09-16 20:18:07.146 UTC [70852] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8162026/09/16 20:18:07 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"8172026/09/16 20:18:07 OK 20241026095416_initial_model.sql (40.54ms)8182026/09/16 20:18:07 OK 20251210153512_drop_unused_gin_index.sql (12.78ms)819=== NAME TestOrphanedObjectsGC820 orphaned_objects_gc_test.go:290: GC Test Summary:821 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A822 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B823 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)824 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)825 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects826--- PASS: TestOrphanedObjectsGC (1.60s)827=== CONT TestReadProxyInvalidPath8282026/09/16 20:18:07 OK 20251218171726_add_pins.sql (12.26ms)8292026/09/16 20:18:07 OK 20260628120000_add_object_size_and_stats.sql (11.21ms)8302026/09/16 20:18:07 INFO Received uploads request method=POST path=/api/pending_closures8312026/09/16 20:18:07 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8322026/09/16 20:18:07 INFO Uploading f25nzdq2vl4pxylx7l8zamzda31pk6h3-file1.txt (160B)8332026/09/16 20:18:07 OK 20260905000000_add_claims.sql (14.44ms)8342026/09/16 20:18:07 goose: successfully migrated database to version: 202609050000008352026/09/16 20:18:07 OK 1_commit_pending_closure.sql (1.49ms)8362026/09/16 20:18:07 OK 2_object_stats_trigger.sql (212.42µs)8372026/09/16 20:18:07 goose: up to current file version: 28382026/09/16 20:18:07 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"8392026/09/16 20:18:07 WARN mTLS auth: subject not in bound subjects subject="CN=reader"8402026/09/16 20:18:07 WARN mTLS auth: subject not in bound subjects subject="CN=reader"841--- PASS: TestService_NativeMTLS (1.64s)842=== CONT TestClaim_TwoInstances8432026/09/16 20:18:07 WARN Failed to register uploaded object key=f25nzdq2vl4pxylx7l8zamzda31pk6h3.ls error="server returned 404: 404 page not found\n"8442026/09/16 20:18:07 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign8452026/09/16 20:18:07 INFO Signed narinfos id=1 count=18462026/09/16 20:18:07 INFO Uploading 1 narinfos8472026/09/16 20:18:07 WARN Failed to register uploaded object key=f25nzdq2vl4pxylx7l8zamzda31pk6h3.narinfo error="server returned 404: 404 page not found\n"8482026/09/16 20:18:07 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8492026/09/16 20:18:07 INFO Completed upload id=18502026/09/16 20:18:07 INFO Upload complete. (121ms)851=== NAME TestNARDeduplicationMetadataUploadBug852 metadata_upload_test.go:54: Retrieved narinfo from S3:853 StorePath: /nix/var/nix/builds/nix-70685-2045658380/TestNARDeduplicationMetadataUploadBug2358181630/001/store/f25nzdq2vl4pxylx7l8zamzda31pk6h3-file1.txt854 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst855 Compression: zstd856 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf857 NarSize: 160858 References: 859 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf860 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)861 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):862 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}863 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-70685-2045658380/TestNARDeduplicationMetadataUploadBug2358181630/001/store/l1mjjyz38hkwn4zryk2rxmf7k5jnxbj7-file2.txt8642026/09/16 20:18:07 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"865--- PASS: TestService_AuthMiddleware (1.75s)866=== CONT TestGCTaskStore_GetEmpty867--- PASS: TestGCTaskStore_GetEmpty (0.00s)868=== CONT TestGCTaskStore_ConflictDifferentParams869--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)870=== CONT TestGCTaskStore_DeduplicateSameParams871--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)872=== CONT TestGCTaskStore_StartNew873--- PASS: TestGCTaskStore_StartNew (0.00s)874=== CONT TestGCMetrics8752026/09/16 20:18:07 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"8762026/09/16 20:18:07 INFO Received uploads request method=POST path=/api/pending_closures8772026/09/16 20:18:07 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)8782026/09/16 20:18:07 WARN Failed to register uploaded object key=l1mjjyz38hkwn4zryk2rxmf7k5jnxbj7.ls error="server returned 404: 404 page not found\n"8792026/09/16 20:18:07 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign8802026/09/16 20:18:07 INFO Signed narinfos id=2 count=18812026/09/16 20:18:07 INFO Uploading 1 narinfos8822026/09/16 20:18:07 WARN Failed to register uploaded object key=l1mjjyz38hkwn4zryk2rxmf7k5jnxbj7.narinfo error="server returned 404: 404 page not found\n"8832026/09/16 20:18:07 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete8842026/09/16 20:18:07 INFO Completed upload id=28852026/09/16 20:18:07 INFO Upload complete. (81ms)886=== NAME TestNARDeduplicationMetadataUploadBug887 metadata_upload_test.go:76: Retrieved narinfo from S3:888 StorePath: /nix/var/nix/builds/nix-70685-2045658380/TestNARDeduplicationMetadataUploadBug2358181630/001/store/l1mjjyz38hkwn4zryk2rxmf7k5jnxbj7-file2.txt889 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst890 Compression: zstd891 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf892 NarSize: 160893 References: 894 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf895 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)896 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):897 {"version":1,"root":{"type":"regular","size":44}}898--- PASS: TestNARDeduplicationMetadataUploadBug (1.84s)899=== CONT TestGCBugBareHashReferences900--- PASS: TestService_healthCheckHandler (1.41s)901=== CONT TestResolveDBConnectionString902=== RUN TestResolveDBConnectionString/flag_wins903=== PAUSE TestResolveDBConnectionString/flag_wins904=== RUN TestResolveDBConnectionString/file_when_flag_empty905=== PAUSE TestResolveDBConnectionString/file_when_flag_empty906=== RUN TestResolveDBConnectionString/missing_file_is_an_error907=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error908=== RUN TestResolveDBConnectionString/PGHOST_allows_empty909=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty910=== RUN TestResolveDBConnectionString/nothing_configured911=== PAUSE TestResolveDBConnectionString/nothing_configured912=== CONT TestPinProtectsFromGC913--- PASS: TestReadRedirectNar (1.16s)914=== CONT TestClientWithDependencies9152026-09-16 20:18:07.771 UTC [70880] ERROR: relation "goose_db_version" does not exist at character 369162026-09-16 20:18:07.771 UTC [70880] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC917--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.35s)918=== CONT TestClientMultipleUploads9192026-09-16 20:18:07.833 UTC [70883] ERROR: relation "goose_db_version" does not exist at character 369202026-09-16 20:18:07.833 UTC [70883] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9212026/09/16 20:18:07 OK 20241026095416_initial_model.sql (82.72ms)9222026/09/16 20:18:07 OK 20251210153512_drop_unused_gin_index.sql (9.88ms)9232026/09/16 20:18:07 OK 20251218171726_add_pins.sql (22.31ms)9242026/09/16 20:18:07 OK 20260628120000_add_object_size_and_stats.sql (28.73ms)925--- PASS: TestReadProxyDisabled (1.41s)926=== CONT TestClientIntegration9272026/09/16 20:18:07 OK 20260905000000_add_claims.sql (14.69ms)9282026/09/16 20:18:07 goose: successfully migrated database to version: 202609050000009292026/09/16 20:18:07 OK 20241026095416_initial_model.sql (85.84ms)9302026/09/16 20:18:07 OK 1_commit_pending_closure.sql (5.52ms)9312026/09/16 20:18:07 OK 20251210153512_drop_unused_gin_index.sql (3.6ms)9322026/09/16 20:18:07 OK 2_object_stats_trigger.sql (673.04µs)9332026/09/16 20:18:07 goose: up to current file version: 29342026/09/16 20:18:07 OK 20251218171726_add_pins.sql (10.73ms)9352026-09-16 20:18:07.976 UTC [70885] ERROR: relation "goose_db_version" does not exist at character 369362026-09-16 20:18:07.976 UTC [70885] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9372026/09/16 20:18:07 OK 20260628120000_add_object_size_and_stats.sql (20.34ms)9382026/09/16 20:18:08 OK 20260905000000_add_claims.sql (15.4ms)9392026/09/16 20:18:08 goose: successfully migrated database to version: 202609050000009402026/09/16 20:18:08 OK 1_commit_pending_closure.sql (2.73ms)9412026/09/16 20:18:08 OK 2_object_stats_trigger.sql (340.71µs)9422026/09/16 20:18:08 goose: up to current file version: 29432026/09/16 20:18:08 OK 20241026095416_initial_model.sql (83.18ms)9442026/09/16 20:18:08 OK 20251210153512_drop_unused_gin_index.sql (13.81ms)9452026/09/16 20:18:08 OK 20251218171726_add_pins.sql (22.17ms)9462026/09/16 20:18:08 OK 20260628120000_add_object_size_and_stats.sql (16.5ms)947--- PASS: TestReadProxyHead (1.43s)948=== CONT TestClientErrorHandling949=== RUN TestClientErrorHandling/InvalidStorePath950=== PAUSE TestClientErrorHandling/InvalidStorePath951=== RUN TestClientErrorHandling/InvalidAuthToken952=== PAUSE TestClientErrorHandling/InvalidAuthToken953=== RUN TestClientErrorHandling/ServerNotAvailable954=== PAUSE TestClientErrorHandling/ServerNotAvailable955=== CONT TestClientCADerivations9562026-09-16 20:18:08.148 UTC [70887] ERROR: relation "goose_db_version" does not exist at character 369572026-09-16 20:18:08.148 UTC [70887] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9582026/09/16 20:18:08 OK 20260905000000_add_claims.sql (45.23ms)9592026/09/16 20:18:08 goose: successfully migrated database to version: 202609050000009602026/09/16 20:18:08 OK 1_commit_pending_closure.sql (2.18ms)9612026/09/16 20:18:08 OK 2_object_stats_trigger.sql (397.58µs)9622026/09/16 20:18:08 goose: up to current file version: 29632026/09/16 20:18:08 OK 20241026095416_initial_model.sql (80.37ms)9642026/09/16 20:18:08 OK 20251210153512_drop_unused_gin_index.sql (7.61ms)9652026/09/16 20:18:08 OK 20251218171726_add_pins.sql (29.58ms)966--- PASS: TestReadProxyConditionalGet (1.18s)967=== CONT TestClaim_StreamsThroughServer9682026/09/16 20:18:08 OK 20260628120000_add_object_size_and_stats.sql (19.37ms)9692026/09/16 20:18:08 OK 20260905000000_add_claims.sql (22.21ms)9702026/09/16 20:18:08 goose: successfully migrated database to version: 202609050000009712026-09-16 20:18:08.349 UTC [70891] ERROR: relation "goose_db_version" does not exist at character 369722026-09-16 20:18:08.349 UTC [70891] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9732026/09/16 20:18:08 OK 1_commit_pending_closure.sql (2.04ms)9742026/09/16 20:18:08 OK 2_object_stats_trigger.sql (417.71µs)9752026/09/16 20:18:08 goose: up to current file version: 29762026-09-16 20:18:08.413 UTC [70893] ERROR: relation "goose_db_version" does not exist at character 369772026-09-16 20:18:08.413 UTC [70893] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9782026/09/16 20:18:08 OK 20241026095416_initial_model.sql (104.02ms)979--- PASS: TestReadProxyInvalidPath (1.27s)980=== CONT TestClaim_InputsTouched9812026/09/16 20:18:08 OK 20251210153512_drop_unused_gin_index.sql (6.41ms)9822026/09/16 20:18:08 OK 20251218171726_add_pins.sql (4.49ms)9832026/09/16 20:18:08 OK 20241026095416_initial_model.sql (57.36ms)9842026/09/16 20:18:08 OK 20251210153512_drop_unused_gin_index.sql (2.69ms)9852026-09-16 20:18:08.521 UTC [70895] ERROR: relation "goose_db_version" does not exist at character 369862026-09-16 20:18:08.521 UTC [70895] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9872026/09/16 20:18:08 OK 20260628120000_add_object_size_and_stats.sql (25.77ms)9882026/09/16 20:18:08 OK 20251218171726_add_pins.sql (13.35ms)9892026/09/16 20:18:08 OK 20260905000000_add_claims.sql (19.88ms)9902026/09/16 20:18:08 goose: successfully migrated database to version: 202609050000009912026/09/16 20:18:08 OK 1_commit_pending_closure.sql (2.13ms)9922026/09/16 20:18:08 OK 2_object_stats_trigger.sql (387.5µs)9932026/09/16 20:18:08 goose: up to current file version: 29942026/09/16 20:18:08 OK 20260628120000_add_object_size_and_stats.sql (26.72ms)9952026/09/16 20:18:08 OK 20260905000000_add_claims.sql (21.72ms)9962026/09/16 20:18:08 goose: successfully migrated database to version: 202609050000009972026/09/16 20:18:08 OK 1_commit_pending_closure.sql (3.11ms)9982026/09/16 20:18:08 OK 2_object_stats_trigger.sql (628.08µs)9992026/09/16 20:18:08 goose: up to current file version: 210002026/09/16 20:18:08 OK 20241026095416_initial_model.sql (72.45ms)10012026/09/16 20:18:08 OK 20251210153512_drop_unused_gin_index.sql (6.93ms)10022026/09/16 20:18:08 OK 20251218171726_add_pins.sql (25.27ms)10032026/09/16 20:18:08 WARN claim: cannot clear write deadline error="feature not supported"10042026-09-16 20:18:08.666 UTC [70897] ERROR: relation "goose_db_version" does not exist at character 3610052026-09-16 20:18:08.666 UTC [70897] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10062026/09/16 20:18:08 OK 20260628120000_add_object_size_and_stats.sql (12.24ms)10072026/09/16 20:18:08 OK 20260905000000_add_claims.sql (10.29ms)10082026/09/16 20:18:08 goose: successfully migrated database to version: 2026090500000010092026/09/16 20:18:08 WARN claim: cannot clear write deadline error="feature not supported"10102026/09/16 20:18:08 OK 1_commit_pending_closure.sql (8.65ms)10112026/09/16 20:18:08 OK 2_object_stats_trigger.sql (665.5µs)10122026/09/16 20:18:08 goose: up to current file version: 210132026/09/16 20:18:08 WARN claim: cannot clear write deadline error="feature not supported"10142026/09/16 20:18:08 INFO Received uploads request method=POST path=/api/pending_closures10152026/09/16 20:18:08 OK 20241026095416_initial_model.sql (78.02ms)10162026/09/16 20:18:08 OK 20251210153512_drop_unused_gin_index.sql (7.79ms)10172026/09/16 20:18:08 OK 20251218171726_add_pins.sql (14.81ms)10182026-09-16 20:18:08.794 UTC [70901] ERROR: relation "goose_db_version" does not exist at character 3610192026-09-16 20:18:08.794 UTC [70901] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10202026/09/16 20:18:08 OK 20260628120000_add_object_size_and_stats.sql (29.23ms)10212026/09/16 20:18:08 OK 20260905000000_add_claims.sql (47.25ms)10222026/09/16 20:18:08 goose: successfully migrated database to version: 2026090500000010232026/09/16 20:18:08 OK 1_commit_pending_closure.sql (5.56ms)10242026/09/16 20:18:08 OK 2_object_stats_trigger.sql (3.96ms)10252026/09/16 20:18:08 goose: up to current file version: 210262026/09/16 20:18:08 INFO Aborted multipart uploads count=010272026/09/16 20:18:08 WARN Force mode enabled - objects will be deleted immediately without grace period10282026/09/16 20:18:08 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=010292026/09/16 20:18:08 INFO Vacuumed table table=pending_closures10302026/09/16 20:18:08 INFO Vacuumed table table=pending_objects10312026/09/16 20:18:08 INFO Vacuumed table table=multipart_uploads10322026/09/16 20:18:08 INFO Vacuumed table table=closures10332026/09/16 20:18:08 INFO Vacuumed table table=objects1034--- PASS: TestGCMetrics (1.54s)1035=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle10362026/09/16 20:18:08 OK 20241026095416_initial_model.sql (63.66ms)10372026/09/16 20:18:08 OK 20251210153512_drop_unused_gin_index.sql (9.39ms)10382026/09/16 20:18:08 OK 20251218171726_add_pins.sql (7.97ms)10392026/09/16 20:18:08 OK 20260628120000_add_object_size_and_stats.sql (38.4ms)10402026/09/16 20:18:08 OK 20260905000000_add_claims.sql (5.58ms)10412026/09/16 20:18:08 goose: successfully migrated database to version: 2026090500000010422026/09/16 20:18:08 OK 1_commit_pending_closure.sql (9.03ms)10432026/09/16 20:18:08 OK 2_object_stats_trigger.sql (371.29µs)10442026/09/16 20:18:08 goose: up to current file version: 210452026-09-16 20:18:09.049 UTC [70905] ERROR: relation "goose_db_version" does not exist at character 3610462026-09-16 20:18:09.049 UTC [70905] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10472026/09/16 20:18:09 OK 20241026095416_initial_model.sql (105.34ms)10482026/09/16 20:18:09 OK 20251210153512_drop_unused_gin_index.sql (8.55ms)10492026/09/16 20:18:09 OK 20251218171726_add_pins.sql (36.77ms)10502026/09/16 20:18:09 OK 20260628120000_add_object_size_and_stats.sql (39.52ms)10512026/09/16 20:18:09 OK 20260905000000_add_claims.sql (25.55ms)10522026/09/16 20:18:09 goose: successfully migrated database to version: 2026090500000010532026/09/16 20:18:09 OK 1_commit_pending_closure.sql (8.87ms)10542026/09/16 20:18:09 OK 2_object_stats_trigger.sql (638µs)10552026/09/16 20:18:09 goose: up to current file version: 21056--- PASS: TestGCBugBareHashReferences (1.88s)1057=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT10582026-09-16 20:18:09.368 UTC [70906] ERROR: relation "goose_db_version" does not exist at character 3610592026-09-16 20:18:09.368 UTC [70906] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10602026/09/16 20:18:09 OK 20241026095416_initial_model.sql (103.39ms)10612026/09/16 20:18:09 OK 20251210153512_drop_unused_gin_index.sql (6.54ms)10622026/09/16 20:18:09 OK 20251218171726_add_pins.sql (20.21ms)10632026/09/16 20:18:09 OK 20260628120000_add_object_size_and_stats.sql (27.64ms)10642026/09/16 20:18:09 OK 20260905000000_add_claims.sql (15.95ms)10652026/09/16 20:18:09 goose: successfully migrated database to version: 2026090500000010662026/09/16 20:18:09 OK 1_commit_pending_closure.sql (8.12ms)10672026/09/16 20:18:09 OK 2_object_stats_trigger.sql (488.54µs)10682026/09/16 20:18:09 goose: up to current file version: 210692026-09-16 20:18:09.578 UTC [70913] ERROR: relation "goose_db_version" does not exist at character 3610702026-09-16 20:18:09.578 UTC [70913] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1071=== NAME TestPinProtectsFromGC1072 client_integration_test.go:648: Pinned store path: /nix/var/nix/builds/nix-70685-2045658380/TestPinProtectsFromGC3371781929/001/store/kd6j8nmbd5538davy987qhfz38nj2fqm-pinned-file.txt1073 client_integration_test.go:649: Unpinned store path: /nix/var/nix/builds/nix-70685-2045658380/TestPinProtectsFromGC3371781929/001/store/q9qprvqiaf932qxymdvzdiqw7q79sppb-unpinned-file.txt10742026/09/16 20:18:09 OK 20241026095416_initial_model.sql (85.41ms)10752026/09/16 20:18:09 OK 20251210153512_drop_unused_gin_index.sql (12.12ms)10762026/09/16 20:18:09 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10772026/09/16 20:18:09 OK 20251218171726_add_pins.sql (12.43ms)10782026/09/16 20:18:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10792026/09/16 20:18:09 OK 20260628120000_add_object_size_and_stats.sql (25.91ms)10802026/09/16 20:18:09 OK 20260905000000_add_claims.sql (21.28ms)10812026/09/16 20:18:09 goose: successfully migrated database to version: 2026090500000010822026/09/16 20:18:09 INFO Received uploads request method=POST path=/api/pending_closures10832026/09/16 20:18:09 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001600000000000000000000.nar.zst upload_id=NDZhNzg2MTAtOTdiMi00OTEyLTkyY2QtZTU5ZjViMDVmOWExLmRmYWM5M2ViLWE1OTAtNGY3My04ZmMxLWRiMGQxNTgyMTg5OHgxNzg5NTg5ODg4NzA4NzM3MDAw parts=1010842026/09/16 20:18:09 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10852026/09/16 20:18:09 INFO Signed narinfos id=1 count=110862026/09/16 20:18:09 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10872026/09/16 20:18:09 INFO Completed upload id=110882026/09/16 20:18:09 OK 1_commit_pending_closure.sql (5.83ms)10892026/09/16 20:18:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)1090--- PASS: TestClaim_TwoInstances (2.50s)10912026/09/16 20:18:09 INFO Uploading kd6j8nmbd5538davy987qhfz38nj2fqm-pinned-file.txt (128B)1092=== CONT TestCompleteMultipartUnregistered10932026/09/16 20:18:09 OK 2_object_stats_trigger.sql (2.18ms)10942026/09/16 20:18:09 goose: up to current file version: 210952026/09/16 20:18:09 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"10962026/09/16 20:18:09 WARN Failed to register uploaded object key=kd6j8nmbd5538davy987qhfz38nj2fqm.ls error="server returned 404: 404 page not found\n"10972026/09/16 20:18:09 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10982026/09/16 20:18:09 INFO Signed narinfos id=1 count=110992026/09/16 20:18:09 INFO Uploading 1 narinfos11002026/09/16 20:18:09 WARN Failed to register uploaded object key=kd6j8nmbd5538davy987qhfz38nj2fqm.narinfo error="server returned 404: 404 page not found\n"11012026/09/16 20:18:09 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11022026/09/16 20:18:09 INFO Completed upload id=111032026/09/16 20:18:09 INFO Upload complete. (141ms)11042026-09-16 20:18:09.833 UTC [70930] ERROR: relation "goose_db_version" does not exist at character 3611052026-09-16 20:18:09.833 UTC [70930] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1106=== NAME TestClientMultipleUploads1107 client_integration_test.go:339: Created store path 0: /nix/var/nix/builds/nix-70685-2045658380/TestClientMultipleUploads2210906898/001/store/khi16zvk4kj7dncg4ym5qqw26h1w5ja8-test-file-0.txt1108=== NAME TestClientWithDependencies1109 client_integration_test.go:594: Built derivation: /nix/var/nix/builds/nix-70685-2045658380/TestClientWithDependencies1098088166/001/store/mh48026c1ybxcpyqfywkhgq489y87inq-test-script11102026/09/16 20:18:09 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1111 client_integration_test.go:596: Found 1 dependencies (including self)1112=== NAME TestClientMultipleUploads1113 client_integration_test.go:339: Created store path 1: /nix/var/nix/builds/nix-70685-2045658380/TestClientMultipleUploads2210906898/001/store/ap0lrh7agfg8f7ilqnk8968cafvwz18m-test-file-1.txt11142026/09/16 20:18:09 OK 20241026095416_initial_model.sql (47.5ms)11152026/09/16 20:18:09 OK 20251210153512_drop_unused_gin_index.sql (1.2ms)11162026/09/16 20:18:09 INFO Received uploads request method=POST path=/api/pending_closures11172026/09/16 20:18:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11182026/09/16 20:18:09 INFO Uploading q9qprvqiaf932qxymdvzdiqw7q79sppb-unpinned-file.txt (128B)11192026/09/16 20:18:09 OK 20251218171726_add_pins.sql (6.75ms)11202026/09/16 20:18:09 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"11212026/09/16 20:18:09 WARN Failed to register uploaded object key=q9qprvqiaf932qxymdvzdiqw7q79sppb.ls error="server returned 404: 404 page not found\n"11222026/09/16 20:18:09 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign11232026/09/16 20:18:09 INFO Signed narinfos id=2 count=111242026/09/16 20:18:09 INFO Uploading 1 narinfos11252026/09/16 20:18:09 WARN Failed to register uploaded object key=q9qprvqiaf932qxymdvzdiqw7q79sppb.narinfo error="server returned 404: 404 page not found\n"11262026/09/16 20:18:09 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11272026/09/16 20:18:09 OK 20260628120000_add_object_size_and_stats.sql (18.42ms)11282026/09/16 20:18:09 INFO Completed upload id=211292026/09/16 20:18:09 INFO Upload complete. (96ms)11302026/09/16 20:18:09 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11312026/09/16 20:18:09 INFO Received uploads request method=POST path=/api/pending_closures11322026/09/16 20:18:09 INFO Received create pin request method=POST path=/api/pins/myapp11332026/09/16 20:18:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11342026/09/16 20:18:09 INFO Uploading mh48026c1ybxcpyqfywkhgq489y87inq-test-script (136B)11352026/09/16 20:18:09 OK 20260905000000_add_claims.sql (34.16ms)11362026/09/16 20:18:09 goose: successfully migrated database to version: 202609050000001137 client_integration_test.go:339: Created store path 2: /nix/var/nix/builds/nix-70685-2045658380/TestClientMultipleUploads2210906898/001/store/7942b75sx7ah9jvnivd93ralnp4cahlr-test-file-2.txt11382026/09/16 20:18:09 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-70685-2045658380/TestPinProtectsFromGC3371781929/001/store/kd6j8nmbd5538davy987qhfz38nj2fqm-pinned-file.txt narinfo_key=kd6j8nmbd5538davy987qhfz38nj2fqm.narinfo11392026/09/16 20:18:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures11402026/09/16 20:18:09 INFO Garbage collection started11412026/09/16 20:18:09 OK 1_commit_pending_closure.sql (9.72ms)11422026/09/16 20:18:09 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"11432026/09/16 20:18:09 OK 2_object_stats_trigger.sql (292.75µs)11442026/09/16 20:18:09 goose: up to current file version: 211452026/09/16 20:18:09 INFO Aborted multipart uploads count=011462026/09/16 20:18:09 WARN Force mode enabled - objects will be deleted immediately without grace period11472026/09/16 20:18:09 WARN Failed to register uploaded object key=mh48026c1ybxcpyqfywkhgq489y87inq.ls error="server returned 404: 404 page not found\n"11482026/09/16 20:18:09 WARN Failed to register uploaded object key=log/k10snbip973209slrrpf18nj46477d50-test-script.drv error="server returned 404: 404 page not found\n"11492026/09/16 20:18:09 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11502026/09/16 20:18:09 INFO Signed narinfos id=1 count=111512026/09/16 20:18:09 INFO Uploading 1 narinfos11522026/09/16 20:18:09 WARN Failed to register uploaded object key=mh48026c1ybxcpyqfywkhgq489y87inq.narinfo error="server returned 404: 404 page not found\n"11532026/09/16 20:18:09 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1154=== NAME TestClientIntegration1155 client_integration_test.go:277: Created store path: /nix/var/nix/builds/nix-70685-2045658380/TestClientIntegration482539927/002/store/p2zqa260wmm74cb54byww68ahvpas893-test-file.txt11562026/09/16 20:18:09 INFO Completed upload id=111572026/09/16 20:18:09 INFO Upload complete. (90ms)1158=== NAME TestClientWithDependencies1159 client_integration_test.go:598: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-70685-2045658380/TestClientWithDependencies1098088166/001/store) requires matching store prefix1160--- PASS: TestClientWithDependencies (2.41s)1161=== CONT TestService_verifyS3Integrity11622026/09/16 20:18:10 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11632026/09/16 20:18:10 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11642026-09-16 20:18:10.075 UTC [70965] ERROR: relation "goose_db_version" does not exist at character 3611652026-09-16 20:18:10.075 UTC [70965] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11662026/09/16 20:18:10 INFO Received uploads request method=POST path=/api/pending_closures11672026/09/16 20:18:10 INFO Received uploads request method=POST path=/api/pending_closures11682026/09/16 20:18:10 INFO Received uploads request method=POST path=/api/pending_closures11692026/09/16 20:18:10 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)11702026/09/16 20:18:10 INFO Uploading 7942b75sx7ah9jvnivd93ralnp4cahlr-test-file-2.txt (160B)11712026/09/16 20:18:10 INFO Uploading khi16zvk4kj7dncg4ym5qqw26h1w5ja8-test-file-0.txt (160B)11722026/09/16 20:18:10 INFO Uploading ap0lrh7agfg8f7ilqnk8968cafvwz18m-test-file-1.txt (160B)11732026/09/16 20:18:10 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"11742026/09/16 20:18:10 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"11752026/09/16 20:18:10 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"11762026/09/16 20:18:10 WARN Failed to register uploaded object key=khi16zvk4kj7dncg4ym5qqw26h1w5ja8.ls error="server returned 404: 404 page not found\n"11772026/09/16 20:18:10 WARN Failed to register uploaded object key=ap0lrh7agfg8f7ilqnk8968cafvwz18m.ls error="server returned 404: 404 page not found\n"11782026/09/16 20:18:10 INFO Received uploads request method=POST path=/api/pending_closures11792026/09/16 20:18:10 WARN Failed to register uploaded object key=7942b75sx7ah9jvnivd93ralnp4cahlr.ls error="server returned 404: 404 page not found\n"11802026/09/16 20:18:10 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11812026/09/16 20:18:10 INFO Signed narinfos id=1 count=111822026/09/16 20:18:10 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign11832026/09/16 20:18:10 INFO Signed narinfos id=2 count=111842026/09/16 20:18:10 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign11852026/09/16 20:18:10 INFO Signed narinfos id=3 count=111862026/09/16 20:18:10 INFO Uploading 3 narinfos11872026/09/16 20:18:10 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11882026/09/16 20:18:10 INFO Uploading p2zqa260wmm74cb54byww68ahvpas893-test-file.txt (152B)11892026/09/16 20:18:10 WARN Failed to register uploaded object key=ap0lrh7agfg8f7ilqnk8968cafvwz18m.narinfo error="server returned 404: 404 page not found\n"11902026/09/16 20:18:10 WARN Failed to register uploaded object key=khi16zvk4kj7dncg4ym5qqw26h1w5ja8.narinfo error="server returned 404: 404 page not found\n"11912026/09/16 20:18:10 WARN Failed to register uploaded object key=7942b75sx7ah9jvnivd93ralnp4cahlr.narinfo error="server returned 404: 404 page not found\n"11922026/09/16 20:18:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11932026/09/16 20:18:10 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"11942026/09/16 20:18:10 INFO Completed upload id=111952026/09/16 20:18:10 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11962026/09/16 20:18:10 INFO Completed upload id=211972026/09/16 20:18:10 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete11982026/09/16 20:18:10 INFO Completed upload id=311992026/09/16 20:18:10 INFO Upload complete. (138ms)1200=== NAME TestClientMultipleUploads1201 client_integration_test.go:350: Uploaded 3 paths in 171.490375ms12022026/09/16 20:18:10 WARN Failed to register uploaded object key=p2zqa260wmm74cb54byww68ahvpas893.ls error="server returned 404: 404 page not found\n"12032026/09/16 20:18:10 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12042026/09/16 20:18:10 INFO Signed narinfos id=1 count=112052026/09/16 20:18:10 INFO Uploading 1 narinfos12062026/09/16 20:18:10 WARN Failed to register uploaded object key=p2zqa260wmm74cb54byww68ahvpas893.narinfo error="server returned 404: 404 page not found\n"12072026/09/16 20:18:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1208--- PASS: TestClientMultipleUploads (2.38s)1209=== CONT TestService_createPendingClosureHandler12102026/09/16 20:18:10 OK 20241026095416_initial_model.sql (55.34ms)12112026/09/16 20:18:10 INFO Completed upload id=112122026/09/16 20:18:10 INFO Upload complete. (129ms)1213=== NAME TestClientIntegration1214 client_integration_test.go:293: Retrieved narinfo from S3:1215 StorePath: /nix/var/nix/builds/nix-70685-2045658380/TestClientIntegration482539927/002/store/p2zqa260wmm74cb54byww68ahvpas893-test-file.txt1216 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1217 Compression: zstd1218 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11219 NarSize: 1521220 References: 1221 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11222 client_integration_test.go:294: Retrieved .ls file from S3 (compressed size: 77 bytes)1223 client_integration_test.go:294: Decompressed .ls content (64 bytes):1224 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1225 client_integration_test.go:297: Testing garbage collection...12262026/09/16 20:18:10 OK 20251210153512_drop_unused_gin_index.sql (7.2ms)12272026/09/16 20:18:10 OK 20251218171726_add_pins.sql (11.25ms)12282026/09/16 20:18:10 OK 20260628120000_add_object_size_and_stats.sql (10ms)12292026/09/16 20:18:10 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=012302026/09/16 20:18:10 INFO Starting cleanup of old closures method=DELETE path=/api/closures12312026/09/16 20:18:10 INFO Garbage collection started12322026/09/16 20:18:10 INFO Aborted multipart uploads count=012332026/09/16 20:18:10 WARN Force mode enabled - objects will be deleted immediately without grace period12342026/09/16 20:18:10 INFO Vacuumed table table=pending_closures12352026/09/16 20:18:10 OK 20260905000000_add_claims.sql (25.56ms)12362026/09/16 20:18:10 goose: successfully migrated database to version: 2026090500000012372026/09/16 20:18:10 INFO Vacuumed table table=pending_objects12382026/09/16 20:18:10 INFO Vacuumed table table=multipart_uploads12392026/09/16 20:18:10 OK 1_commit_pending_closure.sql (7.61ms)12402026/09/16 20:18:10 OK 2_object_stats_trigger.sql (325.46µs)12412026/09/16 20:18:10 goose: up to current file version: 212422026/09/16 20:18:10 INFO Vacuumed table table=closures12432026/09/16 20:18:10 INFO Vacuumed table table=objects12442026-09-16 20:18:10.256 UTC [70980] ERROR: relation "goose_db_version" does not exist at character 3612452026-09-16 20:18:10.256 UTC [70980] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12462026/09/16 20:18:10 OK 20241026095416_initial_model.sql (38.41ms)12472026/09/16 20:18:10 OK 20251210153512_drop_unused_gin_index.sql (5.5ms)1248=== NAME TestClientCADerivations1249 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-70685-2045658380/TestClientCADerivations1694738427/001/store/8jlbv3cpqprhzn6nlrk5ps9mb3iampb1-ca-test12502026/09/16 20:18:10 OK 20251218171726_add_pins.sql (12.85ms)12512026/09/16 20:18:10 INFO Received uploads request method=POST path=/api/pending_closures12522026/09/16 20:18:10 OK 20260628120000_add_object_size_and_stats.sql (6.01ms)12532026/09/16 20:18:10 OK 20260905000000_add_claims.sql (1.43ms)12542026/09/16 20:18:10 goose: successfully migrated database to version: 2026090500000012552026/09/16 20:18:10 OK 1_commit_pending_closure.sql (1.26ms)12562026/09/16 20:18:10 OK 2_object_stats_trigger.sql (310.5µs)12572026/09/16 20:18:10 goose: up to current file version: 21258 client_ca_test.go:139: Found 1 dependencies (including self)12592026/09/16 20:18:10 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=012602026/09/16 20:18:10 INFO Vacuumed table table=pending_closures12612026/09/16 20:18:10 INFO Vacuumed table table=pending_objects12622026/09/16 20:18:10 INFO Vacuumed table table=multipart_uploads12632026/09/16 20:18:10 INFO Vacuumed table table=closures12642026/09/16 20:18:10 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12652026/09/16 20:18:10 INFO Vacuumed table table=objects12662026/09/16 20:18:10 INFO Received uploads request method=POST path=/api/pending_closures12672026/09/16 20:18:10 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12682026/09/16 20:18:10 INFO Uploading 8jlbv3cpqprhzn6nlrk5ps9mb3iampb1-ca-test (144B)12692026/09/16 20:18:10 INFO Received uploads request method=POST path=/api/pending_closures12702026/09/16 20:18:10 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"12712026/09/16 20:18:10 WARN Failed to register uploaded object key=log/i0h6y44indsznypchq5x9rgjqz2kf6sa-ca-test.drv error="server returned 404: 404 page not found\n"12722026/09/16 20:18:10 WARN Failed to register uploaded object key=8jlbv3cpqprhzn6nlrk5ps9mb3iampb1.ls error="server returned 404: 404 page not found\n"12732026/09/16 20:18:10 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12742026/09/16 20:18:10 INFO Signed narinfos id=1 count=112752026/09/16 20:18:10 INFO Uploading 1 narinfos12762026/09/16 20:18:10 WARN Failed to register uploaded object key=8jlbv3cpqprhzn6nlrk5ps9mb3iampb1.narinfo error="server returned 404: 404 page not found\n"12772026/09/16 20:18:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12782026/09/16 20:18:10 INFO Completed upload id=112792026/09/16 20:18:10 INFO Upload complete. (157ms)1280 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-70685-2045658380/TestClientCADerivations1694738427/001/store/8jlbv3cpqprhzn6nlrk5ps9mb3iampb1-ca-test1281 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1282 Compression: zstd1283 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1284 NarSize: 1441285 References: 1286 Deriver: /nix/var/nix/builds/nix-70685-2045658380/TestClientCADerivations1694738427/001/store/i0h6y44indsznypchq5x9rgjqz2kf6sa-ca-test.drv1287 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1288 client_ca_test.go:185: Checking for realisation files in S3...1289 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1290 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1291 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket26?endpoint=http://localhost:57371®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-70685-2045658380/TestClientCADerivations1694738427/001/store'1292 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 112932026-09-16 20:18:10.669 UTC [70993] ERROR: relation "goose_db_version" does not exist at character 3612942026-09-16 20:18:10.669 UTC [70993] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1295--- PASS: TestClientCADerivations (2.56s)1296=== CONT TestService_cleanupPendingClosuresHandler12972026/09/16 20:18:10 INFO Received uploads request method=POST path=/api/pending_closures12982026/09/16 20:18:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1299--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.46s)1300=== CONT TestUploadHandlersRejectOversizedBody13012026/09/16 20:18:10 OK 20241026095416_initial_model.sql (107.89ms)1302=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1303=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1304=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1305=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1306=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1307=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1308=== CONT TestUploadHandlersRejectInvalidKeys1309=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1310=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1311=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1312=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1313=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1314=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1315=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1316=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1317=== CONT TestIsValidUploadKey1318=== RUN TestIsValidUploadKey/narinfo1319=== PAUSE TestIsValidUploadKey/narinfo1320=== RUN TestIsValidUploadKey/nar_zst1321=== PAUSE TestIsValidUploadKey/nar_zst1322=== RUN TestIsValidUploadKey/nar_xz1323=== PAUSE TestIsValidUploadKey/nar_xz1324=== RUN TestIsValidUploadKey/nar_plain1325=== PAUSE TestIsValidUploadKey/nar_plain1326=== RUN TestIsValidUploadKey/listing1327=== PAUSE TestIsValidUploadKey/listing1328=== RUN TestIsValidUploadKey/build_log1329=== PAUSE TestIsValidUploadKey/build_log1330=== RUN TestIsValidUploadKey/build_log_home-manager_file1331=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1332=== RUN TestIsValidUploadKey/build_log_plus_in_name1333=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1334=== RUN TestIsValidUploadKey/build_log_question_mark1335=== PAUSE TestIsValidUploadKey/build_log_question_mark1336=== RUN TestIsValidUploadKey/build_log_equals1337=== PAUSE TestIsValidUploadKey/build_log_equals1338=== RUN TestIsValidUploadKey/realisation1339=== PAUSE TestIsValidUploadKey/realisation1340=== RUN TestIsValidUploadKey/realisation_plus_in_output1341=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1342=== RUN TestIsValidUploadKey/nix-cache-info1343=== PAUSE TestIsValidUploadKey/nix-cache-info1344=== RUN TestIsValidUploadKey/index.html1345=== PAUSE TestIsValidUploadKey/index.html1346=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1347=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1348=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1349=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1350=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1351=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1352=== RUN TestIsValidUploadKey/traversal1353=== PAUSE TestIsValidUploadKey/traversal1354=== RUN TestIsValidUploadKey/traversal_nar1355=== PAUSE TestIsValidUploadKey/traversal_nar1356=== RUN TestIsValidUploadKey/absolute1357=== PAUSE TestIsValidUploadKey/absolute1358=== RUN TestIsValidUploadKey/empty_key1359=== PAUSE TestIsValidUploadKey/empty_key1360=== RUN TestIsValidUploadKey/unknown_type1361=== PAUSE TestIsValidUploadKey/unknown_type1362=== CONT TestProxyWriteTimeout1363=== RUN TestProxyWriteTimeout/narinfo1364=== PAUSE TestProxyWriteTimeout/narinfo1365=== RUN TestProxyWriteTimeout/1_GiB_nar1366=== PAUSE TestProxyWriteTimeout/1_GiB_nar1367=== RUN TestProxyWriteTimeout/10_GiB_nar1368=== PAUSE TestProxyWriteTimeout/10_GiB_nar1369=== RUN TestProxyWriteTimeout/unknown_size1370=== PAUSE TestProxyWriteTimeout/unknown_size1371=== CONT TestIsValidCachePath1372=== RUN TestIsValidCachePath/narinfo1373=== PAUSE TestIsValidCachePath/narinfo1374=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1375=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1376=== RUN TestIsValidCachePath/nar_zst1377=== PAUSE TestIsValidCachePath/nar_zst1378=== RUN TestIsValidCachePath/nar_xz1379=== PAUSE TestIsValidCachePath/nar_xz1380=== RUN TestIsValidCachePath/nar_bz21381=== PAUSE TestIsValidCachePath/nar_bz21382=== RUN TestIsValidCachePath/nar_uncompressed1383=== PAUSE TestIsValidCachePath/nar_uncompressed1384=== RUN TestIsValidCachePath/ls1385=== PAUSE TestIsValidCachePath/ls1386=== RUN TestIsValidCachePath/log1387=== PAUSE TestIsValidCachePath/log1388=== RUN TestIsValidCachePath/realisation1389=== PAUSE TestIsValidCachePath/realisation1390=== RUN TestIsValidCachePath/nix-cache-info1391=== PAUSE TestIsValidCachePath/nix-cache-info1392=== RUN TestIsValidCachePath/index.html1393=== PAUSE TestIsValidCachePath/index.html1394=== RUN TestIsValidCachePath/traversal_parent1395=== PAUSE TestIsValidCachePath/traversal_parent1396=== RUN TestIsValidCachePath/traversal_in_middle1397=== PAUSE TestIsValidCachePath/traversal_in_middle1398=== RUN TestIsValidCachePath/invalid_char_e1399=== PAUSE TestIsValidCachePath/invalid_char_e1400=== RUN TestIsValidCachePath/invalid_char_u1401=== PAUSE TestIsValidCachePath/invalid_char_u1402=== RUN TestIsValidCachePath/random_path1403=== PAUSE TestIsValidCachePath/random_path1404=== RUN TestIsValidCachePath/empty1405=== PAUSE TestIsValidCachePath/empty1406=== RUN TestIsValidCachePath/leading_slash1407=== PAUSE TestIsValidCachePath/leading_slash1408=== RUN TestIsValidCachePath/wrong_extension1409=== PAUSE TestIsValidCachePath/wrong_extension1410=== RUN TestIsValidCachePath/short_hash1411=== PAUSE TestIsValidCachePath/short_hash1412=== CONT TestReadProxyNarStreaming14132026/09/16 20:18:10 OK 20251210153512_drop_unused_gin_index.sql (7.32ms)14142026/09/16 20:18:10 OK 20251218171726_add_pins.sql (2.19ms)14152026/09/16 20:18:10 OK 20260628120000_add_object_size_and_stats.sql (20.47ms)14162026/09/16 20:18:10 OK 20260905000000_add_claims.sql (42.08ms)14172026/09/16 20:18:10 goose: successfully migrated database to version: 2026090500000014182026/09/16 20:18:10 OK 1_commit_pending_closure.sql (5.21ms)14192026/09/16 20:18:10 OK 2_object_stats_trigger.sql (342.71µs)14202026/09/16 20:18:10 goose: up to current file version: 214212026-09-16 20:18:10.912 UTC [70998] ERROR: relation "goose_db_version" does not exist at character 3614222026-09-16 20:18:10.912 UTC [70998] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14232026/09/16 20:18:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14242026/09/16 20:18:10 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1425--- PASS: TestCompleteMultipartUnregistered (1.19s)1426=== CONT TestReadProxyNarinfoAlreadyDecompressed14272026/09/16 20:18:10 OK 20241026095416_initial_model.sql (56.34ms)14282026/09/16 20:18:10 OK 20251210153512_drop_unused_gin_index.sql (7.73ms)14292026/09/16 20:18:11 OK 20251218171726_add_pins.sql (52.61ms)14302026/09/16 20:18:11 OK 20260628120000_add_object_size_and_stats.sql (20.64ms)14312026/09/16 20:18:11 OK 20260905000000_add_claims.sql (23.44ms)14322026/09/16 20:18:11 goose: successfully migrated database to version: 2026090500000014332026/09/16 20:18:11 OK 1_commit_pending_closure.sql (1.78ms)14342026/09/16 20:18:11 OK 2_object_stats_trigger.sql (323.29µs)14352026/09/16 20:18:11 goose: up to current file version: 214362026/09/16 20:18:11 INFO Received uploads request method=POST path=/api/pending_closures14372026/09/16 20:18:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14382026/09/16 20:18:11 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001700000000000000000000.nar.zst upload_id=NDZhNzg2MTAtOTdiMi00OTEyLTkyY2QtZTU5ZjViMDVmOWExLjYzMzk1MDQ0LTk4MGMtNDg4OC1iOWE5LTMzNWVjOTAxNzM1OXgxNzg5NTg5ODkwMzUzMjI5MDAw parts=1014392026/09/16 20:18:11 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14402026/09/16 20:18:11 INFO Completed upload id=114412026/09/16 20:18:11 WARN claim: cannot clear write deadline error="feature not supported"14422026/09/16 20:18:11 INFO Aborted multipart uploads count=014432026/09/16 20:18:11 WARN Force mode enabled - objects will be deleted immediately without grace period14442026/09/16 20:18:11 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=014452026/09/16 20:18:11 INFO Received uploads request method=POST path=/api/pending_closures14462026/09/16 20:18:11 INFO Received uploads request method=POST path=/api/pending_closures14472026/09/16 20:18:11 INFO Received uploads request method=POST path=/api/pending_closures14482026/09/16 20:18:11 INFO Vacuumed table table=pending_closures14492026/09/16 20:18:11 INFO Vacuumed table table=pending_objects14502026/09/16 20:18:11 INFO Vacuumed table table=multipart_uploads14512026/09/16 20:18:11 INFO Vacuumed table table=closures14522026/09/16 20:18:11 INFO Vacuumed table table=objects1453--- PASS: TestClaim_InputsTouched (2.89s)1454=== CONT TestReadProxyNarinfo1455--- PASS: TestClaim_StreamsThroughServer (3.40s)1456=== CONT TestResurrectedObjectNotDeleted14572026-09-16 20:18:11.863 UTC [71006] ERROR: relation "goose_db_version" does not exist at character 3614582026-09-16 20:18:11.863 UTC [71006] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14592026/09/16 20:18:11 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01460=== NAME TestPinProtectsFromGC1461 client_integration_test.go:711: Pin successfully protected closure from garbage collection14622026/09/16 20:18:12 OK 20241026095416_initial_model.sql (108.54ms)14632026/09/16 20:18:12 OK 20251210153512_drop_unused_gin_index.sql (21.18ms)1464--- PASS: TestPinProtectsFromGC (4.57s)1465=== CONT TestParseSingleRange1466=== RUN TestParseSingleRange/none1467=== PAUSE TestParseSingleRange/none1468=== RUN TestParseSingleRange/unknown_unit1469=== PAUSE TestParseSingleRange/unknown_unit1470=== RUN TestParseSingleRange/multi-range_ignored1471=== PAUSE TestParseSingleRange/multi-range_ignored1472=== RUN TestParseSingleRange/malformed_no_dash1473=== PAUSE TestParseSingleRange/malformed_no_dash1474=== RUN TestParseSingleRange/malformed_both_empty1475=== PAUSE TestParseSingleRange/malformed_both_empty1476=== RUN TestParseSingleRange/malformed_end_before_start1477=== PAUSE TestParseSingleRange/malformed_end_before_start1478=== RUN TestParseSingleRange/closed1479=== PAUSE TestParseSingleRange/closed1480=== RUN TestParseSingleRange/open-ended1481=== PAUSE TestParseSingleRange/open-ended1482=== RUN TestParseSingleRange/end_clamped_to_size1483=== PAUSE TestParseSingleRange/end_clamped_to_size1484=== RUN TestParseSingleRange/suffix1485=== PAUSE TestParseSingleRange/suffix1486=== RUN TestParseSingleRange/suffix_exceeds_size1487=== PAUSE TestParseSingleRange/suffix_exceeds_size1488=== RUN TestParseSingleRange/single_byte1489=== PAUSE TestParseSingleRange/single_byte1490=== RUN TestParseSingleRange/start_past_EOF1491=== PAUSE TestParseSingleRange/start_past_EOF1492=== RUN TestParseSingleRange/start_far_past_EOF1493=== PAUSE TestParseSingleRange/start_far_past_EOF1494=== CONT TestCacheStatsHandler14952026/09/16 20:18:12 OK 20251218171726_add_pins.sql (23.26ms)14962026-09-16 20:18:12.085 UTC [71007] ERROR: relation "goose_db_version" does not exist at character 3614972026-09-16 20:18:12.085 UTC [71007] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14982026/09/16 20:18:12 OK 20260628120000_add_object_size_and_stats.sql (30.54ms)14992026/09/16 20:18:12 OK 20260905000000_add_claims.sql (60.04ms)15002026/09/16 20:18:12 goose: successfully migrated database to version: 2026090500000015012026/09/16 20:18:12 OK 1_commit_pending_closure.sql (2.22ms)15022026/09/16 20:18:12 OK 2_object_stats_trigger.sql (384.25µs)15032026/09/16 20:18:12 goose: up to current file version: 215042026/09/16 20:18:12 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01505=== NAME TestClientIntegration1506 client_integration_test.go:304: Objects in database after GC:1507 client_integration_test.go:304: Successfully deleted all objects with GC --force15082026-09-16 20:18:12.219 UTC [71010] ERROR: relation "goose_db_version" does not exist at character 3615092026-09-16 20:18:12.219 UTC [71010] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1510--- PASS: TestClientIntegration (4.30s)1511=== CONT TestClaim_StaleHeartbeatStolen15122026/09/16 20:18:12 OK 20241026095416_initial_model.sql (189.63ms)15132026/09/16 20:18:12 OK 20251210153512_drop_unused_gin_index.sql (12.74ms)15142026/09/16 20:18:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15152026/09/16 20:18:12 OK 20251218171726_add_pins.sql (43.89ms)15162026/09/16 20:18:12 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NDZhNzg2MTAtOTdiMi00OTEyLTkyY2QtZTU5ZjViMDVmOWExLjMyZGE0OWI0LTYzMDgtNGE4YS1iNDNhLWM1Y2IwNzM2YjcyMngxNzg5NTg5ODkxMTUyNDk0MDAw parts=1015172026/09/16 20:18:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15182026/09/16 20:18:12 OK 20260628120000_add_object_size_and_stats.sql (45.33ms)15192026/09/16 20:18:12 INFO Completed upload id=115202026/09/16 20:18:12 INFO Received uploads request method=POST path=/api/pending_closures15212026/09/16 20:18:12 INFO Received uploads request method=POST path=/api/pending_closures15222026/09/16 20:18:12 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo15232026/09/16 20:18:12 WARN Found objects in DB but missing from S3, will re-upload count=11524--- PASS: TestService_verifyS3Integrity (2.40s)1525=== CONT TestClaim_FailWithoutKindReleases15262026/09/16 20:18:12 INFO Received cleanup request method=DELETE path=/api/pending_closures15272026/09/16 20:18:12 OK 20260905000000_add_claims.sql (37.11ms)15282026/09/16 20:18:12 goose: successfully migrated database to version: 2026090500000015292026/09/16 20:18:12 INFO Aborted multipart uploads count=015302026/09/16 20:18:12 OK 1_commit_pending_closure.sql (3.85ms)15312026/09/16 20:18:12 OK 20241026095416_initial_model.sql (139.65ms)15322026/09/16 20:18:12 INFO Received uploads request method=POST path=/api/pending_closures15332026/09/16 20:18:12 OK 2_object_stats_trigger.sql (642.46µs)15342026/09/16 20:18:12 goose: up to current file version: 215352026/09/16 20:18:12 OK 20251210153512_drop_unused_gin_index.sql (1.73ms)15362026/09/16 20:18:12 OK 20251218171726_add_pins.sql (2.82ms)15372026/09/16 20:18:12 OK 20260628120000_add_object_size_and_stats.sql (36.78ms)15382026/09/16 20:18:12 INFO Received cleanup request method=DELETE path=/api/pending_closures15392026/09/16 20:18:12 INFO Aborted multipart uploads count=115402026/09/16 20:18:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15412026-09-16 20:18:12.525 UTC [71006] ERROR: Closure does not exist: id=115422026-09-16 20:18:12.525 UTC [71006] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE15432026-09-16 20:18:12.525 UTC [71006] STATEMENT: -- name: CommitPendingClosure :exec1544 SELECT commit_pending_closure($1::bigint)1545 1546--- PASS: TestService_cleanupPendingClosuresHandler (1.83s)1547=== CONT TestClaim_FailWakesWaitersButIsNotRemembered15482026/09/16 20:18:12 OK 20260905000000_add_claims.sql (51.29ms)15492026/09/16 20:18:12 goose: successfully migrated database to version: 2026090500000015502026/09/16 20:18:12 OK 1_commit_pending_closure.sql (2.57ms)15512026/09/16 20:18:12 OK 2_object_stats_trigger.sql (400.54µs)15522026/09/16 20:18:12 goose: up to current file version: 215532026/09/16 20:18:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15542026/09/16 20:18:12 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NDZhNzg2MTAtOTdiMi00OTEyLTkyY2QtZTU5ZjViMDVmOWExLjg2MjRlY2I0LWY4ZjgtNGIxMi05Mjk1LTFmZDQ1YzI5ZTJmNngxNzg5NTg5ODkxMzUxMDQ2MDAw parts=1015552026/09/16 20:18:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15562026/09/16 20:18:12 INFO Completed upload id=115572026/09/16 20:18:12 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000015582026/09/16 20:18:12 INFO Received uploads request method=POST path=/api/pending_closures15592026/09/16 20:18:12 INFO Starting cleanup of old closures method=DELETE path=/api/closures15602026/09/16 20:18:12 INFO Aborted multipart uploads count=015612026/09/16 20:18:12 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=015622026/09/16 20:18:12 INFO Vacuumed table table=pending_closures15632026/09/16 20:18:12 INFO Vacuumed table table=pending_objects15642026/09/16 20:18:12 INFO Vacuumed table table=multipart_uploads15652026/09/16 20:18:12 INFO Vacuumed table table=closures1566--- PASS: TestReadProxyNarStreaming (1.96s)1567=== CONT TestClaim_HolderDisconnectKeepsClaim15682026/09/16 20:18:12 INFO Vacuumed table table=objects15692026/09/16 20:18:12 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001570--- PASS: TestService_createPendingClosureHandler (2.66s)1571=== CONT TestClaim_TooManyStreams1572--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.08s)1573=== CONT TestClaim_GCMarkedOutputCountsAsAbsent15742026-09-16 20:18:13.092 UTC [71024] ERROR: relation "goose_db_version" does not exist at character 3615752026-09-16 20:18:13.092 UTC [71024] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15762026-09-16 20:18:13.207 UTC [71025] ERROR: relation "goose_db_version" does not exist at character 3615772026-09-16 20:18:13.207 UTC [71025] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15782026/09/16 20:18:13 OK 20241026095416_initial_model.sql (49.95ms)15792026/09/16 20:18:13 OK 20251210153512_drop_unused_gin_index.sql (9.88ms)15802026/09/16 20:18:13 OK 20251218171726_add_pins.sql (29.57ms)15812026/09/16 20:18:13 OK 20260628120000_add_object_size_and_stats.sql (27.27ms)15822026/09/16 20:18:13 OK 20260905000000_add_claims.sql (12.45ms)15832026/09/16 20:18:13 goose: successfully migrated database to version: 2026090500000015842026/09/16 20:18:13 OK 1_commit_pending_closure.sql (4.88ms)15852026/09/16 20:18:13 OK 2_object_stats_trigger.sql (843.96µs)15862026/09/16 20:18:13 goose: up to current file version: 215872026/09/16 20:18:13 OK 20241026095416_initial_model.sql (51.04ms)15882026/09/16 20:18:13 OK 20251210153512_drop_unused_gin_index.sql (8.74ms)15892026/09/16 20:18:13 OK 20251218171726_add_pins.sql (31.52ms)15902026/09/16 20:18:13 OK 20260628120000_add_object_size_and_stats.sql (31.76ms)15912026/09/16 20:18:13 OK 20260905000000_add_claims.sql (49.85ms)15922026/09/16 20:18:13 goose: successfully migrated database to version: 2026090500000015932026/09/16 20:18:13 OK 1_commit_pending_closure.sql (5.74ms)15942026/09/16 20:18:13 OK 2_object_stats_trigger.sql (641.13µs)15952026/09/16 20:18:13 goose: up to current file version: 21596--- PASS: TestReadProxyNarinfo (2.22s)1597=== CONT TestClaim_BuildWaitComplete15982026-09-16 20:18:13.606 UTC [71026] ERROR: relation "goose_db_version" does not exist at character 3615992026-09-16 20:18:13.606 UTC [71026] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16002026/09/16 20:18:13 OK 20241026095416_initial_model.sql (217.07ms)16012026/09/16 20:18:13 WARN Rate limiter enabled after throttle name=s3-test rate=516022026/09/16 20:18:13 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1603=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1604 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101605 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001606--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.96s)1607=== CONT TestCompletedNarNotReofferedAcrossClosures16082026/09/16 20:18:13 OK 20251210153512_drop_unused_gin_index.sql (11.63ms)16092026/09/16 20:18:13 OK 20251218171726_add_pins.sql (27.09ms)16102026-09-16 20:18:13.918 UTC [71032] ERROR: relation "goose_db_version" does not exist at character 3616112026-09-16 20:18:13.918 UTC [71032] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16122026-09-16 20:18:13.918 UTC [71031] ERROR: relation "goose_db_version" does not exist at character 3616132026-09-16 20:18:13.918 UTC [71031] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16142026/09/16 20:18:13 OK 20260628120000_add_object_size_and_stats.sql (14.61ms)16152026-09-16 20:18:13.923 UTC [71033] ERROR: relation "goose_db_version" does not exist at character 3616162026-09-16 20:18:13.923 UTC [71033] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16172026/09/16 20:18:13 OK 20260905000000_add_claims.sql (17.34ms)16182026/09/16 20:18:13 goose: successfully migrated database to version: 202609050000001619--- PASS: TestResurrectedObjectNotDeleted (2.22s)1620=== CONT TestSkippedUploadsHandler16212026/09/16 20:18:13 INFO Client skipped oversized paths paths=3 nar_bytes=500000000016222026/09/16 20:18:13 OK 1_commit_pending_closure.sql (1.56ms)1623--- PASS: TestSkippedUploadsHandler (0.00s)1624=== CONT TestParseSize1625--- PASS: TestParseSize (0.00s)1626=== CONT TestService_Rustfstest16272026/09/16 20:18:13 OK 2_object_stats_trigger.sql (1.18ms)16282026/09/16 20:18:13 goose: up to current file version: 216292026-09-16 20:18:13.940 UTC [71034] ERROR: relation "goose_db_version" does not exist at character 3616302026-09-16 20:18:13.940 UTC [71034] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16312026-09-16 20:18:13.941 UTC [71035] ERROR: relation "goose_db_version" does not exist at character 3616322026-09-16 20:18:13.941 UTC [71035] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16332026/09/16 20:18:14 OK 20241026095416_initial_model.sql (127.52ms)16342026/09/16 20:18:14 OK 20241026095416_initial_model.sql (108.39ms)16352026/09/16 20:18:14 OK 20241026095416_initial_model.sql (129.4ms)16362026/09/16 20:18:14 OK 20241026095416_initial_model.sql (103.72ms)16372026/09/16 20:18:14 OK 20241026095416_initial_model.sql (110.98ms)16382026/09/16 20:18:14 OK 20251210153512_drop_unused_gin_index.sql (3.04ms)16392026/09/16 20:18:14 OK 20251210153512_drop_unused_gin_index.sql (3.31ms)16402026/09/16 20:18:14 OK 20251210153512_drop_unused_gin_index.sql (2.33ms)16412026/09/16 20:18:14 OK 20251210153512_drop_unused_gin_index.sql (4.02ms)16422026/09/16 20:18:14 OK 20251210153512_drop_unused_gin_index.sql (7.19ms)16432026/09/16 20:18:14 OK 20251218171726_add_pins.sql (21.13ms)16442026/09/16 20:18:14 OK 20251218171726_add_pins.sql (26.39ms)16452026/09/16 20:18:14 OK 20251218171726_add_pins.sql (27.62ms)16462026/09/16 20:18:14 OK 20251218171726_add_pins.sql (27.66ms)16472026/09/16 20:18:14 OK 20251218171726_add_pins.sql (30.53ms)16482026/09/16 20:18:14 OK 20260628120000_add_object_size_and_stats.sql (38.94ms)16492026/09/16 20:18:14 OK 20260628120000_add_object_size_and_stats.sql (33.82ms)16502026/09/16 20:18:14 OK 20260628120000_add_object_size_and_stats.sql (34.68ms)16512026/09/16 20:18:14 OK 20260628120000_add_object_size_and_stats.sql (34.7ms)16522026/09/16 20:18:14 OK 20260628120000_add_object_size_and_stats.sql (32.05ms)16532026/09/16 20:18:14 OK 20260905000000_add_claims.sql (29.29ms)16542026/09/16 20:18:14 goose: successfully migrated database to version: 2026090500000016552026/09/16 20:18:14 OK 20260905000000_add_claims.sql (42.19ms)16562026/09/16 20:18:14 goose: successfully migrated database to version: 2026090500000016572026/09/16 20:18:14 OK 20260905000000_add_claims.sql (44.95ms)16582026/09/16 20:18:14 goose: successfully migrated database to version: 2026090500000016592026/09/16 20:18:14 OK 1_commit_pending_closure.sql (9.22ms)16602026/09/16 20:18:14 OK 2_object_stats_trigger.sql (582.21µs)16612026/09/16 20:18:14 goose: up to current file version: 216622026/09/16 20:18:14 OK 20260905000000_add_claims.sql (51.39ms)16632026/09/16 20:18:14 goose: successfully migrated database to version: 2026090500000016642026/09/16 20:18:14 OK 20260905000000_add_claims.sql (50.06ms)16652026/09/16 20:18:14 goose: successfully migrated database to version: 2026090500000016662026/09/16 20:18:14 OK 1_commit_pending_closure.sql (3.63ms)16672026/09/16 20:18:14 OK 1_commit_pending_closure.sql (2.85ms)16682026/09/16 20:18:14 OK 1_commit_pending_closure.sql (10.65ms)16692026/09/16 20:18:14 OK 1_commit_pending_closure.sql (10.15ms)16702026/09/16 20:18:14 OK 2_object_stats_trigger.sql (826.38µs)16712026/09/16 20:18:14 goose: up to current file version: 216722026/09/16 20:18:14 OK 2_object_stats_trigger.sql (916.88µs)16732026/09/16 20:18:14 goose: up to current file version: 216742026/09/16 20:18:14 OK 2_object_stats_trigger.sql (983.63µs)16752026/09/16 20:18:14 goose: up to current file version: 216762026/09/16 20:18:14 OK 2_object_stats_trigger.sql (1.6ms)16772026/09/16 20:18:14 goose: up to current file version: 21678--- PASS: TestCacheStatsHandler (2.16s)1679=== CONT TestPresignedUploadRegisteredBeforeCommit16802026/09/16 20:18:14 WARN claim: cannot clear write deadline error="feature not supported"16812026/09/16 20:18:14 WARN claim: cannot clear write deadline error="feature not supported"1682--- PASS: TestClaim_FailWithoutKindReleases (2.04s)1683=== CONT TestRedundantMultipartUpload16842026-09-16 20:18:14.653 UTC [71043] ERROR: relation "goose_db_version" does not exist at character 3616852026-09-16 20:18:14.653 UTC [71043] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16862026/09/16 20:18:14 WARN claim: cannot clear write deadline error="feature not supported"16872026/09/16 20:18:14 WARN claim: cannot clear write deadline error="feature not supported"1688--- PASS: TestClaim_StaleHeartbeatStolen (2.50s)1689=== CONT TestCompleteMultipartUpload_ErrorButObjectExists16902026/09/16 20:18:14 OK 20241026095416_initial_model.sql (114.5ms)16912026/09/16 20:18:14 OK 20251210153512_drop_unused_gin_index.sql (13.56ms)16922026/09/16 20:18:14 OK 20251218171726_add_pins.sql (27.33ms)16932026/09/16 20:18:14 WARN claim: cannot clear write deadline error="feature not supported"16942026/09/16 20:18:14 OK 20260628120000_add_object_size_and_stats.sql (31.15ms)16952026/09/16 20:18:14 WARN claim: cannot clear write deadline error="feature not supported"16962026/09/16 20:18:14 OK 20260905000000_add_claims.sql (42.85ms)16972026/09/16 20:18:14 goose: successfully migrated database to version: 2026090500000016982026/09/16 20:18:14 OK 1_commit_pending_closure.sql (9.59ms)16992026/09/16 20:18:14 OK 2_object_stats_trigger.sql (630.21µs)17002026/09/16 20:18:14 goose: up to current file version: 217012026/09/16 20:18:15 WARN claim: cannot clear write deadline error="feature not supported"17022026-09-16 20:18:15.189 UTC [71048] ERROR: relation "goose_db_version" does not exist at character 3617032026-09-16 20:18:15.189 UTC [71048] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17042026/09/16 20:18:15 WARN claim: cannot clear write deadline error="feature not supported"17052026/09/16 20:18:15 WARN claim: cannot clear write deadline error="feature not supported"1706--- PASS: TestClaim_FailWakesWaitersButIsNotRemembered (2.69s)1707=== CONT TestReadRedirectUsesPublicS3URL17082026-09-16 20:18:15.301 UTC [71052] ERROR: relation "goose_db_version" does not exist at character 3617092026-09-16 20:18:15.301 UTC [71052] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17102026-09-16 20:18:15.327 UTC [71053] ERROR: relation "goose_db_version" does not exist at character 3617112026-09-16 20:18:15.327 UTC [71053] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17122026/09/16 20:18:15 OK 20241026095416_initial_model.sql (83.15ms)17132026/09/16 20:18:15 OK 20251210153512_drop_unused_gin_index.sql (5.92ms)17142026/09/16 20:18:15 OK 20251218171726_add_pins.sql (12.09ms)17152026/09/16 20:18:15 OK 20260628120000_add_object_size_and_stats.sql (28.48ms)17162026/09/16 20:18:15 OK 20241026095416_initial_model.sql (90.52ms)17172026/09/16 20:18:15 OK 20260905000000_add_claims.sql (47.12ms)17182026/09/16 20:18:15 goose: successfully migrated database to version: 2026090500000017192026/09/16 20:18:15 WARN claim: cannot clear write deadline error="feature not supported"17202026/09/16 20:18:15 OK 20251210153512_drop_unused_gin_index.sql (3.98ms)17212026/09/16 20:18:15 OK 1_commit_pending_closure.sql (5.18ms)17222026/09/16 20:18:15 OK 20241026095416_initial_model.sql (84.11ms)17232026/09/16 20:18:15 OK 2_object_stats_trigger.sql (2.65ms)17242026/09/16 20:18:15 goose: up to current file version: 217252026/09/16 20:18:15 OK 20251218171726_add_pins.sql (7.61ms)17262026/09/16 20:18:15 OK 20251210153512_drop_unused_gin_index.sql (2.67ms)1727--- PASS: TestClaim_TooManyStreams (2.63s)1728=== CONT TestReadProxyRangeRequest17292026/09/16 20:18:15 WARN claim: cannot clear write deadline error="feature not supported"17302026/09/16 20:18:15 OK 20251218171726_add_pins.sql (12.06ms)17312026/09/16 20:18:15 OK 20260628120000_add_object_size_and_stats.sql (18.8ms)17322026/09/16 20:18:15 OK 20260628120000_add_object_size_and_stats.sql (23.02ms)17332026/09/16 20:18:15 OK 20260905000000_add_claims.sql (19.97ms)17342026/09/16 20:18:15 goose: successfully migrated database to version: 2026090500000017352026/09/16 20:18:15 OK 1_commit_pending_closure.sql (2.68ms)17362026/09/16 20:18:15 OK 2_object_stats_trigger.sql (417.08µs)17372026/09/16 20:18:15 goose: up to current file version: 217382026/09/16 20:18:15 OK 20260905000000_add_claims.sql (6.49ms)17392026/09/16 20:18:15 goose: successfully migrated database to version: 2026090500000017402026/09/16 20:18:15 OK 1_commit_pending_closure.sql (7.51ms)17412026/09/16 20:18:15 OK 2_object_stats_trigger.sql (321.67µs)17422026/09/16 20:18:15 goose: up to current file version: 217432026-09-16 20:18:15.497 UTC [71058] ERROR: relation "goose_db_version" does not exist at character 3617442026-09-16 20:18:15.497 UTC [71058] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17452026/09/16 20:18:15 INFO Received uploads request method=POST path=/api/pending_closures17462026/09/16 20:18:15 OK 20241026095416_initial_model.sql (95.43ms)17472026/09/16 20:18:15 OK 20251210153512_drop_unused_gin_index.sql (16.68ms)17482026/09/16 20:18:15 OK 20251218171726_add_pins.sql (32.94ms)17492026/09/16 20:18:15 OK 20260628120000_add_object_size_and_stats.sql (16.25ms)17502026-09-16 20:18:15.693 UTC [71060] ERROR: relation "goose_db_version" does not exist at character 3617512026-09-16 20:18:15.693 UTC [71060] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17522026/09/16 20:18:15 OK 20260905000000_add_claims.sql (19.95ms)17532026/09/16 20:18:15 goose: successfully migrated database to version: 2026090500000017542026/09/16 20:18:15 OK 1_commit_pending_closure.sql (9.86ms)17552026/09/16 20:18:15 OK 2_object_stats_trigger.sql (870.71µs)17562026/09/16 20:18:15 goose: up to current file version: 217572026/09/16 20:18:15 WARN claim: cannot clear write deadline error="feature not supported"17582026/09/16 20:18:15 WARN claim: cannot clear write deadline error="feature not supported"17592026/09/16 20:18:15 WARN claim: cannot clear write deadline error="feature not supported"17602026/09/16 20:18:15 INFO Received uploads request method=POST path=/api/pending_closures17612026/09/16 20:18:15 OK 20241026095416_initial_model.sql (130.71ms)17622026-09-16 20:18:15.881 UTC [71062] ERROR: relation "goose_db_version" does not exist at character 3617632026-09-16 20:18:15.881 UTC [71062] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17642026/09/16 20:18:15 OK 20251210153512_drop_unused_gin_index.sql (12.03ms)17652026/09/16 20:18:15 OK 20251218171726_add_pins.sql (6.24ms)17662026/09/16 20:18:15 OK 20260628120000_add_object_size_and_stats.sql (35.52ms)17672026/09/16 20:18:15 OK 20260905000000_add_claims.sql (54.49ms)17682026/09/16 20:18:15 goose: successfully migrated database to version: 2026090500000017692026/09/16 20:18:15 OK 1_commit_pending_closure.sql (6.82ms)17702026/09/16 20:18:15 OK 2_object_stats_trigger.sql (569.17µs)17712026/09/16 20:18:15 goose: up to current file version: 217722026/09/16 20:18:16 OK 20241026095416_initial_model.sql (159.42ms)17732026/09/16 20:18:16 OK 20251210153512_drop_unused_gin_index.sql (8.15ms)1774--- PASS: TestService_Rustfstest (2.16s)1775=== CONT TestOrphanedObjectsGCStressTest17762026/09/16 20:18:16 OK 20251218171726_add_pins.sql (35.76ms)17772026/09/16 20:18:16 OK 20260628120000_add_object_size_and_stats.sql (47.27ms)17782026/09/16 20:18:16 OK 20260905000000_add_claims.sql (64.27ms)17792026/09/16 20:18:16 goose: successfully migrated database to version: 2026090500000017802026/09/16 20:18:16 OK 1_commit_pending_closure.sql (14.93ms)17812026/09/16 20:18:16 OK 2_object_stats_trigger.sql (658.96µs)17822026/09/16 20:18:16 goose: up to current file version: 217832026/09/16 20:18:16 INFO Received uploads request method=POST path=/api/pending_closures17842026/09/16 20:18:16 INFO Received uploads request method=POST path=/api/pending_closures17852026/09/16 20:18:16 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst17862026/09/16 20:18:16 INFO Received uploads request method=POST path=/api/pending_closures1787--- PASS: TestPresignedUploadRegisteredBeforeCommit (2.59s)1788=== CONT TestService_AuthMiddleware_OIDC17892026/09/16 20:18:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57573/oidc17902026-09-16 20:18:16.893 UTC [71066] ERROR: relation "goose_db_version" does not exist at character 3617912026-09-16 20:18:16.893 UTC [71066] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17922026/09/16 20:18:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17932026/09/16 20:18:17 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001100000000000000000000.nar.zst upload_id=NDZhNzg2MTAtOTdiMi00OTEyLTkyY2QtZTU5ZjViMDVmOWExLjhiN2YyYjUwLTQ4ZDYtNDRlNy05ZWQwLWJkNzgzMzM3NjQxNngxNzg5NTg5ODk1NjI4MTYwMDAw parts=1017942026/09/16 20:18:17 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17952026/09/16 20:18:17 INFO Completed upload id=117962026/09/16 20:18:17 WARN claim: cannot clear write deadline error="feature not supported"17972026/09/16 20:18:17 WARN claim: cannot clear write deadline error="feature not supported"1798--- PASS: TestClaim_GCMarkedOutputCountsAsAbsent (4.00s)1799=== CONT TestCacheConfigHandler1800=== RUN TestCacheConfigHandler/full_config,_no_issuer1801=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1802=== RUN TestCacheConfigHandler/no_cache_url_configured1803=== PAUSE TestCacheConfigHandler/no_cache_url_configured1804=== RUN TestCacheConfigHandler/no_signing_keys1805=== PAUSE TestCacheConfigHandler/no_signing_keys1806=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1807=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1808=== CONT TestService_ReadScope_PublicByDefault18092026/09/16 20:18:17 INFO Received uploads request method=POST path=/api/pending_closures18102026/09/16 20:18:17 INFO Received uploads request method=POST path=/api/pending_closures18112026/09/16 20:18:17 OK 20241026095416_initial_model.sql (219.33ms)18122026/09/16 20:18:17 OK 20251210153512_drop_unused_gin_index.sql (10.34ms)18132026/09/16 20:18:17 OK 20251218171726_add_pins.sql (23.71ms)18142026/09/16 20:18:17 OK 20260628120000_add_object_size_and_stats.sql (45.84ms)18152026/09/16 20:18:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18162026/09/16 20:18:17 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001000000000000000000000.nar.zst upload_id=NDZhNzg2MTAtOTdiMi00OTEyLTkyY2QtZTU5ZjViMDVmOWExLjQzZjA5NzAxLWY2NDgtNGNmZS1hMTBlLWI0ZTUxZjU3ZGIyZXgxNzg5NTg5ODk1ODkyOTkyMDAw parts=1018172026/09/16 20:18:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18182026/09/16 20:18:17 INFO Signed narinfos id=1 count=118192026/09/16 20:18:17 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18202026/09/16 20:18:17 INFO Received uploads request method=POST path=/api/pending_closures18212026/09/16 20:18:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign18222026/09/16 20:18:17 INFO Signed narinfos id=2 count=118232026/09/16 20:18:17 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete18242026/09/16 20:18:17 INFO Completed upload id=218252026/09/16 20:18:17 WARN claim: cannot clear write deadline error="feature not supported"1826--- PASS: TestClaim_BuildWaitComplete (3.77s)1827=== CONT TestService_RequireScope_OIDC18282026/09/16 20:18:17 OK 20260905000000_add_claims.sql (94.66ms)18292026/09/16 20:18:17 goose: successfully migrated database to version: 2026090500000018302026/09/16 20:18:17 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57577/oidc18312026/09/16 20:18:17 OK 1_commit_pending_closure.sql (11.03ms)18322026/09/16 20:18:17 OK 2_object_stats_trigger.sql (1.04ms)18332026/09/16 20:18:17 goose: up to current file version: 218342026/09/16 20:18:17 INFO Received uploads request method=POST path=/api/pending_closures1835--- PASS: TestClaim_HolderDisconnectKeepsClaim (4.67s)1836=== CONT TestService_AuthMiddleware_MTLSBoundSubjects18372026-09-16 20:18:17.474 UTC [71073] ERROR: relation "goose_db_version" does not exist at character 3618382026-09-16 20:18:17.474 UTC [71073] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18392026/09/16 20:18:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18402026/09/16 20:18:17 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NDZhNzg2MTAtOTdiMi00OTEyLTkyY2QtZTU5ZjViMDVmOWExLjEzMjRkNzJlLWVkOTAtNGM5Ni04MDhiLTg3NWQ5NGYxOWEzMXgxNzg5NTg5ODk3NDU2NzAzMDAw1841--- PASS: TestReadRedirectUsesPublicS3URL (2.50s)1842=== CONT TestService_ReadAuthMiddleware18432026/09/16 20:18:17 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NDZhNzg2MTAtOTdiMi00OTEyLTkyY2QtZTU5ZjViMDVmOWExLjEzMjRkNzJlLWVkOTAtNGM5Ni04MDhiLTg3NWQ5NGYxOWEzMXgxNzg5NTg5ODk3NDU2NzAzMDAw parts=11844--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.98s)1845=== CONT TestService_AuthMiddleware_MTLSProxyHeader18462026/09/16 20:18:17 OK 20241026095416_initial_model.sql (202.22ms)18472026/09/16 20:18:17 OK 20251210153512_drop_unused_gin_index.sql (1.79ms)18482026/09/16 20:18:17 OK 20251218171726_add_pins.sql (17.37ms)18492026/09/16 20:18:17 OK 20260628120000_add_object_size_and_stats.sql (33.51ms)18502026/09/16 20:18:17 OK 20260905000000_add_claims.sql (22.64ms)18512026/09/16 20:18:17 goose: successfully migrated database to version: 2026090500000018522026/09/16 20:18:17 OK 1_commit_pending_closure.sql (9.87ms)18532026/09/16 20:18:17 OK 2_object_stats_trigger.sql (320.21µs)18542026/09/16 20:18:17 goose: up to current file version: 218552026/09/16 20:18:18 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1856--- PASS: TestReadProxyRangeRequest (2.69s)1857=== CONT TestServerTLSConfig/no_client_CA1858=== CONT TestServerTLSConfig/not_a_PEM_file1859=== CONT TestServerTLSConfig/missing_CA_file1860--- PASS: TestServerTLSConfig (0.00s)1861 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1862 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1863 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1864=== CONT TestResolveDBConnectionString/flag_wins1865=== CONT TestResolveDBConnectionString/missing_file_is_an_error1866=== CONT TestResolveDBConnectionString/file_when_flag_empty1867=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1868=== CONT TestResolveDBConnectionString/nothing_configured1869=== CONT TestClientErrorHandling/InvalidStorePath18702026/09/16 20:18:18 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NDZhNzg2MTAtOTdiMi00OTEyLTkyY2QtZTU5ZjViMDVmOWExLjVjYmVkZmQwLTg2MzgtNGYwZS1iNmViLTAwMDVmZDg0MzYwY3gxNzg5NTg5ODk2NDI1NzI5MDAw parts=1218712026/09/16 20:18:18 INFO Received uploads request method=POST path=/api/pending_closures1872--- PASS: TestCompletedNarNotReofferedAcrossClosures (4.30s)1873=== CONT TestClientErrorHandling/ServerNotAvailable1874--- PASS: TestResolveDBConnectionString (0.01s)1875 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1876 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1877 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1878 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1879 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)18802026-09-16 20:18:18.186 UTC [71083] ERROR: relation "goose_db_version" does not exist at character 3618812026-09-16 20:18:18.186 UTC [71083] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18822026/09/16 20:18:18 OK 20241026095416_initial_model.sql (75.45ms)18832026/09/16 20:18:18 OK 20251210153512_drop_unused_gin_index.sql (5.49ms)18842026/09/16 20:18:18 OK 20251218171726_add_pins.sql (8.61ms)18852026-09-16 20:18:18.351 UTC [71089] ERROR: relation "goose_db_version" does not exist at character 3618862026-09-16 20:18:18.351 UTC [71089] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18872026/09/16 20:18:18 OK 20260628120000_add_object_size_and_stats.sql (15.77ms)18882026/09/16 20:18:18 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-config18892026/09/16 20:18:18 OK 20260905000000_add_claims.sql (56.64ms)18902026/09/16 20:18:18 goose: successfully migrated database to version: 2026090500000018912026/09/16 20:18:18 OK 1_commit_pending_closure.sql (1.62ms)18922026/09/16 20:18:18 OK 2_object_stats_trigger.sql (253.04µs)18932026/09/16 20:18:18 goose: up to current file version: 218942026/09/16 20:18:18 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=210.386943ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config18952026/09/16 20:18:18 OK 20241026095416_initial_model.sql (118.76ms)18962026/09/16 20:18:18 OK 20251210153512_drop_unused_gin_index.sql (11.97ms)18972026/09/16 20:18:18 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18982026/09/16 20:18:18 OK 20251218171726_add_pins.sql (38.93ms)18992026/09/16 20:18:18 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NDZhNzg2MTAtOTdiMi00OTEyLTkyY2QtZTU5ZjViMDVmOWExLjMzOGM1ZGQ4LTRmMGQtNDMyYS1hYzNjLWE5ODU3MzNiMTJlYngxNzg5NTg5ODk3MDgyMjM3MDAw parts=121900--- PASS: TestRedundantMultipartUpload (4.12s)1901=== CONT TestClientErrorHandling/InvalidAuthToken19022026/09/16 20:18:18 OK 20260628120000_add_object_size_and_stats.sql (23.22ms)19032026/09/16 20:18:18 OK 20260905000000_add_claims.sql (42.54ms)19042026/09/16 20:18:18 goose: successfully migrated database to version: 2026090500000019052026-09-16 20:18:18.647 UTC [71092] ERROR: relation "goose_db_version" does not exist at character 3619062026-09-16 20:18:18.647 UTC [71092] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19072026/09/16 20:18:18 OK 1_commit_pending_closure.sql (2.38ms)19082026/09/16 20:18:18 OK 2_object_stats_trigger.sql (585.67µs)19092026/09/16 20:18:18 goose: up to current file version: 219102026/09/16 20:18:18 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=372.576384ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19112026/09/16 20:18:18 OK 20241026095416_initial_model.sql (84.39ms)19122026-09-16 20:18:18.758 UTC [71093] ERROR: relation "goose_db_version" does not exist at character 3619132026-09-16 20:18:18.758 UTC [71093] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19142026/09/16 20:18:18 OK 20251210153512_drop_unused_gin_index.sql (14.7ms)19152026/09/16 20:18:18 OK 20251218171726_add_pins.sql (7.93ms)19162026/09/16 20:18:18 OK 20260628120000_add_object_size_and_stats.sql (22.56ms)19172026/09/16 20:18:18 OK 20260905000000_add_claims.sql (25.87ms)19182026/09/16 20:18:18 goose: successfully migrated database to version: 2026090500000019192026/09/16 20:18:18 OK 1_commit_pending_closure.sql (10.33ms)19202026/09/16 20:18:18 OK 2_object_stats_trigger.sql (649.5µs)19212026/09/16 20:18:18 goose: up to current file version: 21922=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1923=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1924=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1925=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1926=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1927=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1928=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1929=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1930=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19312026/09/16 20:18:18 INFO Received uploads request method=POST path=/19322026/09/16 20:18:18 OK 20241026095416_initial_model.sql (81.49ms)19332026/09/16 20:18:18 OK 20251210153512_drop_unused_gin_index.sql (11.07ms)19342026-09-16 20:18:18.886 UTC [71094] ERROR: relation "goose_db_version" does not exist at character 3619352026-09-16 20:18:18.886 UTC [71094] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19362026/09/16 20:18:18 OK 20251218171726_add_pins.sql (9.24ms)19372026/09/16 20:18:18 OK 20260628120000_add_object_size_and_stats.sql (14.96ms)19382026/09/16 20:18:18 OK 20260905000000_add_claims.sql (12.02ms)19392026/09/16 20:18:18 goose: successfully migrated database to version: 2026090500000019402026/09/16 20:18:18 OK 1_commit_pending_closure.sql (1.9ms)19412026/09/16 20:18:18 OK 2_object_stats_trigger.sql (258.58µs)19422026/09/16 20:18:18 goose: up to current file version: 219432026-09-16 20:18:18.923 UTC [71096] ERROR: relation "goose_db_version" does not exist at character 3619442026-09-16 20:18:18.923 UTC [71096] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19452026-09-16 20:18:18.927 UTC [71095] ERROR: relation "goose_db_version" does not exist at character 3619462026-09-16 20:18:18.927 UTC [71095] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19472026/09/16 20:18:18 OK 20241026095416_initial_model.sql (38.5ms)19482026/09/16 20:18:18 OK 20251210153512_drop_unused_gin_index.sql (7.8ms)19492026/09/16 20:18:18 OK 20251218171726_add_pins.sql (6.32ms)19502026/09/16 20:18:18 OK 20260628120000_add_object_size_and_stats.sql (13.43ms)19512026/09/16 20:18:18 OK 20241026095416_initial_model.sql (46.28ms)19522026/09/16 20:18:18 OK 20251210153512_drop_unused_gin_index.sql (6.46ms)19532026/09/16 20:18:18 OK 20260905000000_add_claims.sql (20.02ms)19542026/09/16 20:18:18 goose: successfully migrated database to version: 2026090500000019552026/09/16 20:18:18 OK 20241026095416_initial_model.sql (59.43ms)19562026/09/16 20:18:18 OK 20251210153512_drop_unused_gin_index.sql (888.46µs)19572026/09/16 20:18:18 OK 20251218171726_add_pins.sql (7.47ms)19582026/09/16 20:18:18 OK 1_commit_pending_closure.sql (6.86ms)19592026/09/16 20:18:18 OK 2_object_stats_trigger.sql (254.54µs)19602026/09/16 20:18:18 goose: up to current file version: 219612026/09/16 20:18:18 OK 20251218171726_add_pins.sql (2.1ms)19622026/09/16 20:18:19 OK 20260628120000_add_object_size_and_stats.sql (12.83ms)19632026/09/16 20:18:19 OK 20260628120000_add_object_size_and_stats.sql (14.8ms)1964--- PASS: TestService_ReadScope_PublicByDefault (1.99s)1965=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart19662026/09/16 20:18:19 INFO Received complete multipart upload request method=POST path=/19672026/09/16 20:18:19 OK 20260905000000_add_claims.sql (20.84ms)19682026/09/16 20:18:19 goose: successfully migrated database to version: 2026090500000019692026/09/16 20:18:19 OK 20260905000000_add_claims.sql (20.74ms)19702026/09/16 20:18:19 goose: successfully migrated database to version: 2026090500000019712026/09/16 20:18:19 OK 1_commit_pending_closure.sql (1.63ms)19722026/09/16 20:18:19 OK 2_object_stats_trigger.sql (346.83µs)19732026/09/16 20:18:19 goose: up to current file version: 219742026/09/16 20:18:19 OK 1_commit_pending_closure.sql (2.02ms)19752026/09/16 20:18:19 OK 2_object_stats_trigger.sql (441.42µs)19762026/09/16 20:18:19 goose: up to current file version: 219772026/09/16 20:18:19 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=774.447771ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1978=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19792026/09/16 20:18:19 INFO Received request for more parts method=POST path=/19802026-09-16 20:18:19.065 UTC [71097] ERROR: relation "goose_db_version" does not exist at character 3619812026-09-16 20:18:19.065 UTC [71097] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1982=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info19832026/09/16 20:18:19 INFO Received uploads request method=POST path=/1984=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key19852026/09/16 20:18:19 INFO Received complete multipart upload request method=POST path=/1986=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key19872026/09/16 20:18:19 INFO Received request for more parts method=POST path=/1988=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal19892026/09/16 20:18:19 INFO Received uploads request method=POST path=/1990--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1991 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1992 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1993 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1994 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1995=== CONT TestIsValidUploadKey/narinfo1996=== CONT TestIsValidUploadKey/realisation_plus_in_output1997=== CONT TestIsValidUploadKey/unknown_type1998=== CONT TestIsValidUploadKey/empty_key1999=== CONT TestIsValidUploadKey/absolute2000=== CONT TestIsValidUploadKey/traversal_nar2001=== CONT TestIsValidUploadKey/traversal2002=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2003=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2004=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2005=== CONT TestIsValidUploadKey/index.html2006=== CONT TestIsValidUploadKey/nix-cache-info2007=== CONT TestIsValidUploadKey/build_log_home-manager_file2008=== CONT TestIsValidUploadKey/realisation2009=== CONT TestIsValidUploadKey/build_log_equals2010=== CONT TestIsValidUploadKey/build_log_question_mark2011=== CONT TestIsValidUploadKey/build_log_plus_in_name2012=== CONT TestProxyWriteTimeout/narinfo2013=== CONT TestIsValidUploadKey/nar_xz2014=== CONT TestIsValidUploadKey/nar_zst2015=== CONT TestIsValidUploadKey/nar_plain2016=== CONT TestIsValidUploadKey/build_log2017=== CONT TestIsValidUploadKey/listing2018--- PASS: TestIsValidUploadKey (0.00s)2019 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2020 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2021 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2022 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2023 --- PASS: TestIsValidUploadKey/absolute (0.00s)2024 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2025 --- PASS: TestIsValidUploadKey/traversal (0.00s)2026 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2027 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2028 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2029 --- PASS: TestIsValidUploadKey/index.html (0.00s)2030 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2031 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2032 --- PASS: TestIsValidUploadKey/realisation (0.00s)2033 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2034 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2035 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2036 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2037 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2038 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2039 --- PASS: TestIsValidUploadKey/build_log (0.00s)2040 --- PASS: TestIsValidUploadKey/listing (0.00s)2041=== CONT TestProxyWriteTimeout/10_GiB_nar2042=== CONT TestProxyWriteTimeout/unknown_size2043=== CONT TestProxyWriteTimeout/1_GiB_nar2044--- PASS: TestProxyWriteTimeout (0.00s)2045 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2046 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2047 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2048 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2049=== CONT TestIsValidCachePath/narinfo2050=== CONT TestIsValidCachePath/index.html2051=== CONT TestIsValidCachePath/short_hash2052=== CONT TestIsValidCachePath/invalid_char_u2053=== CONT TestIsValidCachePath/invalid_char_e2054=== CONT TestIsValidCachePath/traversal_in_middle2055=== CONT TestIsValidCachePath/traversal_parent2056=== CONT TestIsValidCachePath/nar_uncompressed2057=== CONT TestIsValidCachePath/nix-cache-info2058=== CONT TestIsValidCachePath/realisation2059=== CONT TestIsValidCachePath/log2060=== CONT TestIsValidCachePath/ls2061=== CONT TestIsValidCachePath/leading_slash2062=== CONT TestIsValidCachePath/wrong_extension2063=== CONT TestIsValidCachePath/nar_xz2064=== CONT TestIsValidCachePath/nar_bz22065=== CONT TestIsValidCachePath/nar_zst2066=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2067=== CONT TestIsValidCachePath/empty2068=== CONT TestIsValidCachePath/random_path2069--- PASS: TestIsValidCachePath (0.00s)2070 --- PASS: TestIsValidCachePath/narinfo (0.00s)2071 --- PASS: TestIsValidCachePath/index.html (0.00s)2072 --- PASS: TestIsValidCachePath/short_hash (0.00s)2073 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2074 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2075 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2076 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2077 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2078 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2079 --- PASS: TestIsValidCachePath/realisation (0.00s)2080 --- PASS: TestIsValidCachePath/log (0.00s)2081 --- PASS: TestIsValidCachePath/ls (0.00s)2082 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2083 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2084 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2085 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2086 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2087 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2088 --- PASS: TestIsValidCachePath/empty (0.00s)2089 --- PASS: TestIsValidCachePath/random_path (0.00s)2090=== CONT TestParseSingleRange/none2091=== CONT TestParseSingleRange/open-ended2092=== CONT TestParseSingleRange/start_far_past_EOF2093=== CONT TestParseSingleRange/start_past_EOF2094=== CONT TestParseSingleRange/single_byte2095=== CONT TestParseSingleRange/suffix_exceeds_size2096=== CONT TestParseSingleRange/suffix2097=== CONT TestParseSingleRange/end_clamped_to_size2098=== CONT TestParseSingleRange/malformed_both_empty2099=== CONT TestParseSingleRange/closed2100=== CONT TestParseSingleRange/malformed_end_before_start2101=== CONT TestParseSingleRange/multi-range_ignored2102=== CONT TestParseSingleRange/malformed_no_dash2103=== CONT TestParseSingleRange/unknown_unit2104--- PASS: TestParseSingleRange (0.00s)2105 --- PASS: TestParseSingleRange/none (0.00s)2106 --- PASS: TestParseSingleRange/open-ended (0.00s)2107 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2108 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2109 --- PASS: TestParseSingleRange/single_byte (0.00s)2110 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2111 --- PASS: TestParseSingleRange/suffix (0.00s)2112 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2113 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2114 --- PASS: TestParseSingleRange/closed (0.00s)2115 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2116 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2117 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2118 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2119=== CONT TestCacheConfigHandler/full_config,_no_issuer2120=== CONT TestCacheConfigHandler/no_signing_keys2121=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2122=== CONT TestCacheConfigHandler/no_cache_url_configured2123--- PASS: TestCacheConfigHandler (0.00s)2124 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2125 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2126 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2127 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2128=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token21292026/09/16 20:18:19 INFO OIDC auth successful provider=test scopes=[write]2130=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected21312026/09/16 20:18:19 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]2132=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2133=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected21342026/09/16 20:18:19 WARN Authentication failed token_preview=eyJhbGciOi...s8QDYeP0Iw token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2135--- PASS: TestService_AuthMiddleware_OIDC (2.04s)2136 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2137 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2138 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2139 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)21402026/09/16 20:18:19 OK 20241026095416_initial_model.sql (36.33ms)21412026/09/16 20:18:19 OK 20251210153512_drop_unused_gin_index.sql (997.46µs)21422026/09/16 20:18:19 OK 20251218171726_add_pins.sql (11.19ms)21432026/09/16 20:18:19 OK 20260628120000_add_object_size_and_stats.sql (7.72ms)21442026/09/16 20:18:19 OK 20260905000000_add_claims.sql (9.51ms)21452026/09/16 20:18:19 goose: successfully migrated database to version: 2026090500000021462026/09/16 20:18:19 OK 1_commit_pending_closure.sql (7.43ms)21472026/09/16 20:18:19 OK 2_object_stats_trigger.sql (274.79µs)21482026/09/16 20:18:19 goose: up to current file version: 22149--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)2150 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2151 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)2152 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.30s)2153=== RUN TestService_RequireScope_OIDC/builder_may_write2154=== PAUSE TestService_RequireScope_OIDC/builder_may_write2155=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2156=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2157=== RUN TestService_RequireScope_OIDC/ops_may_admin2158=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2159=== RUN TestService_RequireScope_OIDC/ops_may_not_write2160=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2161=== RUN TestService_RequireScope_OIDC/reader_may_not_write2162=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2163=== RUN TestService_RequireScope_OIDC/static_token_may_admin2164=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2165=== RUN TestService_RequireScope_OIDC/static_token_may_write2166=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2167=== RUN TestService_RequireScope_OIDC/reader_may_read2168=== PAUSE TestService_RequireScope_OIDC/reader_may_read2169=== RUN TestService_RequireScope_OIDC/writer_implies_read2170=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2171=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2172=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2173=== CONT TestService_RequireScope_OIDC/builder_may_write2174=== CONT TestService_RequireScope_OIDC/static_token_may_admin2175=== CONT TestService_RequireScope_OIDC/ops_may_not_write2176=== CONT TestService_RequireScope_OIDC/ops_may_admin21772026/09/16 20:18:19 INFO OIDC auth successful provider=test scopes=[admin]21782026/09/16 20:18:19 INFO OIDC auth successful provider=test scopes=[write]2179=== CONT TestService_RequireScope_OIDC/writer_implies_read21802026/09/16 20:18:19 INFO OIDC auth successful provider=test scopes=[admin]2181=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2182=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2183=== CONT TestService_RequireScope_OIDC/reader_may_not_write21842026/09/16 20:18:19 INFO OIDC auth successful provider=test scopes=[write]2185=== CONT TestService_RequireScope_OIDC/reader_may_read21862026/09/16 20:18:19 INFO OIDC auth successful provider=test scopes=[write]21872026/09/16 20:18:19 INFO OIDC auth successful provider=test scopes=[read]2188=== CONT TestService_RequireScope_OIDC/static_token_may_write21892026/09/16 20:18:19 INFO OIDC auth successful provider=test scopes=[read]2190--- PASS: TestService_RequireScope_OIDC (1.84s)2191 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2192 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2193 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2194 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2195 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2196 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2197 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2198 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2199 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2200 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)22012026-09-16 20:18:19.238 UTC [71098] ERROR: relation "goose_db_version" does not exist at character 3622022026-09-16 20:18:19.238 UTC [71098] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22032026/09/16 20:18:19 OK 20241026095416_initial_model.sql (46.45ms)22042026/09/16 20:18:19 OK 20251210153512_drop_unused_gin_index.sql (5.66ms)22052026/09/16 20:18:19 OK 20251218171726_add_pins.sql (10.83ms)22062026/09/16 20:18:19 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"22072026/09/16 20:18:19 WARN mTLS auth: bound subjects configured but subject DN unavailable22082026/09/16 20:18:19 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2209--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (1.87s)22102026/09/16 20:18:19 OK 20260628120000_add_object_size_and_stats.sql (7.68ms)22112026/09/16 20:18:19 OK 20260905000000_add_claims.sql (1.57ms)22122026/09/16 20:18:19 goose: successfully migrated database to version: 2026090500000022132026/09/16 20:18:19 OK 1_commit_pending_closure.sql (1.32ms)22142026/09/16 20:18:19 OK 2_object_stats_trigger.sql (270µs)22152026/09/16 20:18:19 goose: up to current file version: 22216--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (1.72s)2217--- PASS: TestService_ReadAuthMiddleware (1.87s)22182026/09/16 20:18:19 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.629648584s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2219=== NAME TestOrphanedObjectsGCStressTest2220 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2221 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion22222026/09/16 20:18:19 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"22232026/09/16 20:18:20 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2224 orphaned_objects_gc_test.go:509: Stress test completed successfully:2225 orphaned_objects_gc_test.go:510: - Active objects preserved: 202226 orphaned_objects_gc_test.go:511: - Objects deleted: 2102227 orphaned_objects_gc_test.go:512: - Total GC'd: 2102228--- PASS: TestOrphanedObjectsGCStressTest (3.97s)22292026/09/16 20:18:21 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"22302026/09/16 20:18:21 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_closures22312026/09/16 20:18:21 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=184.075582ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22322026/09/16 20:18:21 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=386.936339ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22332026/09/16 20:18:22 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=756.327804ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22342026/09/16 20:18:22 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.596947973s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2235--- PASS: TestClientErrorHandling (0.00s)2236 --- PASS: TestClientErrorHandling/InvalidStorePath (1.62s)2237 --- PASS: TestClientErrorHandling/InvalidAuthToken (1.41s)2238 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.40s)2239PASS2240{"timestamp":"2026-09-16T20:18:24.56071Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:57524","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1880,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}22412026-09-16 20:18:24.657 UTC [70723] LOG: received smart shutdown request22422026-09-16 20:18:24.658 UTC [70723] LOG: background worker "logical replication launcher" (PID 70733) exited with exit code 122432026-09-16 20:18:24.663 UTC [70728] LOG: shutting down22442026-09-16 20:18:24.663 UTC [70728] LOG: checkpoint starting: shutdown immediate22452026-09-16 20:18:25.700 UTC [70728] LOG: checkpoint complete: wrote 13370 buffers (81.6%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 18 recycled; write=0.679 s, sync=0.356 s, total=1.037 s; sync files=21000, longest=0.001 s, average=0.001 s; distance=287766 kB, estimate=287766 kB; lsn=0/13092908, redo lsn=0/1309290822462026-09-16 20:18:25.705 UTC [70723] LOG: database system is shut down2247Running OIDC tests...2248=== RUN TestGlobMatch2249=== PAUSE TestGlobMatch2250=== RUN TestAudienceForIssuer2251=== PAUSE TestAudienceForIssuer2252=== RUN TestValidateToken_ValidToken2253=== PAUSE TestValidateToken_ValidToken2254=== RUN TestValidateToken_WrongAudience2255=== PAUSE TestValidateToken_WrongAudience2256=== RUN TestValidateToken_Expired2257=== PAUSE TestValidateToken_Expired2258=== RUN TestValidateToken_BoundClaimsMismatch2259=== PAUSE TestValidateToken_BoundClaimsMismatch2260=== RUN TestValidateToken_BoundSubjectMismatch2261=== PAUSE TestValidateToken_BoundSubjectMismatch2262=== RUN TestValidateToken_MultipleProviders2263=== PAUSE TestValidateToken_MultipleProviders2264=== RUN TestValidateToken_NoMatchingProvider2265=== PAUSE TestValidateToken_NoMatchingProvider2266=== RUN TestValidateToken_KubernetesServiceAccount2267=== PAUSE TestValidateToken_KubernetesServiceAccount2268=== RUN TestNewValidator_KubernetesRequiresCA2269=== PAUSE TestNewValidator_KubernetesRequiresCA2270=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2271=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2272=== RUN TestScopes_LegacyProviderDefaultsToWrite2273=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2274=== RUN TestScopes_Rules2275=== PAUSE TestScopes_Rules2276=== RUN TestScopes_ConfigValidation2277=== PAUSE TestScopes_ConfigValidation2278=== CONT TestGlobMatch2279=== CONT TestValidateToken_Expired2280=== CONT TestValidateToken_NoMatchingProvider2281=== RUN TestGlobMatch/foo_foo2282=== PAUSE TestGlobMatch/foo_foo2283=== RUN TestGlobMatch/foo_bar2284=== PAUSE TestGlobMatch/foo_bar2285=== RUN TestGlobMatch/*_2286=== PAUSE TestGlobMatch/*_2287=== RUN TestGlobMatch/*_anything2288=== PAUSE TestGlobMatch/*_anything2289=== RUN TestGlobMatch/foo*_foo2290=== PAUSE TestGlobMatch/foo*_foo2291=== RUN TestGlobMatch/foo*_foobar2292=== PAUSE TestGlobMatch/foo*_foobar2293=== RUN TestGlobMatch/foo*_bar2294=== PAUSE TestGlobMatch/foo*_bar2295=== RUN TestGlobMatch/*bar_bar2296=== CONT TestValidateToken_WrongAudience2297=== PAUSE TestGlobMatch/*bar_bar2298=== RUN TestGlobMatch/*bar_foobar2299=== PAUSE TestGlobMatch/*bar_foobar2300=== RUN TestGlobMatch/*bar_foo2301=== PAUSE TestGlobMatch/*bar_foo2302=== RUN TestGlobMatch/foo*bar_foobar2303=== PAUSE TestGlobMatch/foo*bar_foobar2304=== RUN TestGlobMatch/foo*bar_foo123bar2305=== PAUSE TestGlobMatch/foo*bar_foo123bar2306=== RUN TestGlobMatch/foo*bar_foobarbaz2307=== PAUSE TestGlobMatch/foo*bar_foobarbaz2308=== RUN TestGlobMatch/*/*_foo/bar2309=== PAUSE TestGlobMatch/*/*_foo/bar2310=== RUN TestGlobMatch/*/*_foo2311=== PAUSE TestGlobMatch/*/*_foo2312=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2313=== CONT TestValidateToken_ValidToken2314=== CONT TestAudienceForIssuer2315--- PASS: TestAudienceForIssuer (0.00s)2316=== CONT TestValidateToken_KubernetesServiceAccount2317=== CONT TestScopes_ConfigValidation2318=== CONT TestScopes_Rules2319=== CONT TestNewValidator_KubernetesRequiresCA2320=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2321=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2322=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02323=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02324=== RUN TestGlobMatch/refs/*/main_refs/heads/main2325=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2326=== RUN TestGlobMatch/fo?_foo2327=== PAUSE TestGlobMatch/fo?_foo2328=== RUN TestGlobMatch/fo?_fo2329=== PAUSE TestGlobMatch/fo?_fo2330=== RUN TestGlobMatch/fo?_fooo2331=== PAUSE TestGlobMatch/fo?_fooo2332=== RUN TestGlobMatch/?oo_foo2333=== PAUSE TestGlobMatch/?oo_foo2334=== RUN TestGlobMatch/?oo_boo2335=== PAUSE TestGlobMatch/?oo_boo2336=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2337=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2338=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2339=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2340=== CONT TestValidateToken_BoundSubjectMismatch2341--- PASS: TestScopes_ConfigValidation (0.00s)2342=== CONT TestValidateToken_MultipleProviders23432026/09/16 20:18:26 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:57641/oidc23442026/09/16 20:18:26 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12323452026/09/16 20:18:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57642/oidc23462026/09/16 20:18:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57646/oidc23472026/09/16 20:18:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57639/oidc23482026/09/16 20:18:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57638/oidc23492026/09/16 20:18:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57640/oidc23502026/09/16 20:18:26 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:57656/oidc2351--- PASS: TestValidateToken_WrongAudience (0.01s)2352=== CONT TestValidateToken_BoundClaimsMismatch23532026/09/16 20:18:26 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:57657/oidc2354--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)2355=== CONT TestScopes_LegacyProviderDefaultsToWrite2356--- PASS: TestValidateToken_ValidToken (0.01s)2357=== CONT TestGlobMatch/foo_foo23582026/09/16 20:18:26 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:576452359=== CONT TestGlobMatch/*/*_foo/bar2360=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2361=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2362=== CONT TestGlobMatch/?oo_boo2363=== CONT TestGlobMatch/?oo_foo2364=== CONT TestGlobMatch/fo?_fooo2365=== CONT TestGlobMatch/fo?_fo2366=== CONT TestGlobMatch/fo?_foo2367=== CONT TestGlobMatch/refs/*/main_refs/heads/main2368=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02369=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2370=== CONT TestGlobMatch/*/*_fo2026/09/16 20:18:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57661/oidc2371o2372=== CONT TestGlobMatch/foo*bar_foobarbaz2373=== CONT TestGlobMatch/foo*bar_foo123bar2374=== CONT TestGlobMatch/foo*bar_foobar2375--- PASS: TestValidateToken_Expired (0.01s)2376=== CONT TestGlobMatch/*bar_bar2377=== CONT TestGlobMatch/*bar_foobar2378=== CONT TestGlobMatch/foo*_foo2379=== CONT TestGlobMatch/foo*_bar2380=== CONT TestGlobMatch/foo*_foobar2381=== CONT TestGlobMatch/*_2382=== CONT TestGlobMatch/*_anything2383=== CONT TestGlobMatch/foo_bar2384=== CONT TestGlobMatch/*bar_foo2385--- PASS: TestGlobMatch (0.00s)2386 --- PASS: TestGlobMatch/foo_foo (0.00s)2387 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2388 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2389 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2390 --- PASS: TestGlobMatch/?oo_boo (0.00s)2391 --- PASS: TestGlobMatch/?oo_foo (0.00s)2392 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2393 --- PASS: TestGlobMatch/fo?_fo (0.00s)2394 --- PASS: TestGlobMatch/fo?_foo (0.00s)2395 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2396 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2397 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2398 --- PASS: TestGlobMatch/*/*_foo (0.00s)2399 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2400 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2401 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2402 --- PASS: TestGlobMatch/*bar_bar (0.00s)2403 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2404 --- PASS: TestGlobMatch/foo*_foo (0.00s)2405 --- PASS: TestGlobMatch/foo*_bar (0.00s)2406 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2407 --- PASS: TestGlobMatch/*_ (0.00s)2408 --- PASS: TestGlobMatch/*_anything (0.00s)2409 --- PASS: TestGlobMatch/foo_bar (0.00s)2410 --- PASS: TestGlobMatch/*bar_foo (0.00s)2411--- PASS: TestValidateToken_NoMatchingProvider (0.02s)24122026/09/16 20:18:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57663/oidc2413--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.01s)2414--- PASS: TestScopes_Rules (0.02s)2415--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)2416--- PASS: TestValidateToken_MultipleProviders (0.01s)2417--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.01s)2418--- PASS: TestValidateToken_KubernetesServiceAccount (0.02s)24192026/09/16 20:18:26 http: TLS handshake error from 127.0.0.1:57651: remote error: tls: bad certificate2420--- PASS: TestNewValidator_KubernetesRequiresCA (0.02s)2421PASS2422Running hook tests...2423=== RUN TestSendPathsEmpty2424=== PAUSE TestSendPathsEmpty2425=== RUN TestQueueEnqueueAndFetch2426=== PAUSE TestQueueEnqueueAndFetch2427=== RUN TestQueueDeduplication2428=== PAUSE TestQueueDeduplication2429=== RUN TestQueueRemove2430=== PAUSE TestQueueRemove2431=== RUN TestQueueFetchBatchLimit2432=== PAUSE TestQueueFetchBatchLimit2433=== RUN TestQueueRetryMovesToBack2434=== PAUSE TestQueueRetryMovesToBack2435=== RUN TestQueueFetchRemoveLifecycle2436=== PAUSE TestQueueFetchRemoveLifecycle2437=== RUN TestQueueConcurrentWriters2438=== PAUSE TestQueueConcurrentWriters2439=== RUN TestQueueRemoveLargeClosure2440=== PAUSE TestQueueRemoveLargeClosure2441=== RUN TestServerClientIntegration2442=== PAUSE TestServerClientIntegration2443=== RUN TestServerQueueError2444=== PAUSE TestServerQueueError2445=== RUN TestGetListenerSocketActivation2446 server_test.go:210: === RUN TestGetListenerSocketActivation2447 --- PASS: TestGetListenerSocketActivation (0.00s)2448 PASS2449 2450--- PASS: TestGetListenerSocketActivation (0.01s)2451=== RUN TestDrainIsolatesPoisonPath2452=== PAUSE TestDrainIsolatesPoisonPath2453=== RUN TestRunNotBlockedByPoisonHead2454=== PAUSE TestRunNotBlockedByPoisonHead2455=== RUN TestDrainGivesUpWhenServerDown2456=== PAUSE TestDrainGivesUpWhenServerDown2457=== RUN TestFailedPathPrunedByLaterClosure2458=== PAUSE TestFailedPathPrunedByLaterClosure2459=== RUN TestWorkerUploadsAndRemoves2460=== PAUSE TestWorkerUploadsAndRemoves2461=== RUN TestWorkerSkipsGCdPaths2462=== PAUSE TestWorkerSkipsGCdPaths2463=== RUN TestWorkerPrunesClosureDeps2464=== PAUSE TestWorkerPrunesClosureDeps2465=== RUN TestDrainTimeout2466=== PAUSE TestDrainTimeout2467=== CONT TestSendPathsEmpty2468=== CONT TestServerQueueError2469=== CONT TestWorkerPrunesClosureDeps2470--- PASS: TestSendPathsEmpty (0.00s)2471=== CONT TestQueueRetryMovesToBack2472=== CONT TestQueueFetchBatchLimit2473=== CONT TestQueueRemove2474=== CONT TestQueueDeduplication2475=== CONT TestServerClientIntegration2476=== CONT TestQueueEnqueueAndFetch2477=== CONT TestWorkerUploadsAndRemoves2478=== CONT TestDrainTimeout24792026/09/16 20:18:26 ERROR Failed to queue paths error="permission denied" count=12480--- PASS: TestServerQueueError (0.00s)2481=== CONT TestQueueRemoveLargeClosure2482--- PASS: TestServerClientIntegration (0.00s)2483=== CONT TestQueueConcurrentWriters24842026/09/16 20:18:26 INFO Uploading batch count=22485--- PASS: TestQueueFetchBatchLimit (0.01s)2486=== CONT TestQueueFetchRemoveLifecycle2487--- PASS: TestQueueEnqueueAndFetch (0.01s)2488=== CONT TestDrainGivesUpWhenServerDown2489--- PASS: TestQueueDeduplication (0.01s)2490=== CONT TestFailedPathPrunedByLaterClosure24912026/09/16 20:18:26 INFO Upload queue status pending=224922026/09/16 20:18:26 INFO Uploading batch count=12493--- PASS: TestQueueRetryMovesToBack (0.01s)2494=== CONT TestRunNotBlockedByPoisonHead24952026/09/16 20:18:26 INFO Upload queue status pending=224962026/09/16 20:18:26 INFO Uploading batch count=22497--- PASS: TestQueueRemove (0.01s)2498=== CONT TestWorkerSkipsGCdPaths24992026/09/16 20:18:26 INFO Uploading batch count=125002026/09/16 20:18:26 ERROR Upload failed error="upload failed" count=125012026/09/16 20:18:26 INFO Upload queue status pending=325022026/09/16 20:18:26 INFO Uploading batch count=125032026/09/16 20:18:26 ERROR Upload failed error="upload failed" count=125042026/09/16 20:18:26 INFO Uploading batch count=12505--- PASS: TestQueueFetchRemoveLifecycle (0.00s)2506=== CONT TestDrainIsolatesPoisonPath25072026/09/16 20:18:26 INFO Uploading batch count=125082026/09/16 20:18:26 INFO Uploading batch count=225092026/09/16 20:18:26 ERROR Upload failed error="upload failed" count=225102026/09/16 20:18:26 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-70685-2045658380/TestDrainGivesUpWhenServerDown2896815881/002/a25112026/09/16 20:18:26 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-70685-2045658380/TestDrainGivesUpWhenServerDown2896815881/002/b25122026/09/16 20:18:26 INFO Upload queue status pending=225132026/09/16 20:18:26 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-70685-2045658380/TestWorkerSkipsGCdPaths4200539786/002/nonexistent25142026/09/16 20:18:26 INFO Uploading batch count=225152026/09/16 20:18:26 ERROR Upload failed error="upload failed" count=225162026/09/16 20:18:26 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-70685-2045658380/TestDrainGivesUpWhenServerDown2896815881/002/c25172026/09/16 20:18:26 INFO Uploading batch count=125182026/09/16 20:18:26 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-70685-2045658380/TestDrainGivesUpWhenServerDown2896815881/002/d2519--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)25202026/09/16 20:18:26 INFO Uploading batch count=225212026/09/16 20:18:26 ERROR Upload failed error="upload failed" count=225222026/09/16 20:18:26 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-70685-2045658380/TestDrainGivesUpWhenServerDown2896815881/002/e25232026/09/16 20:18:26 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-70685-2045658380/TestDrainGivesUpWhenServerDown2896815881/002/f25242026/09/16 20:18:26 ERROR Drain finished with paths left in queue remaining=1025252026/09/16 20:18:26 INFO Uploading batch count=425262026/09/16 20:18:26 ERROR Upload failed error="upload failed" count=425272026/09/16 20:18:26 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-70685-2045658380/TestDrainIsolatesPoisonPath1360089096/002/bbb25282026/09/16 20:18:26 INFO Uploading batch count=125292026/09/16 20:18:26 ERROR Upload failed error="upload failed" count=125302026/09/16 20:18:26 INFO Uploading batch count=125312026/09/16 20:18:26 ERROR Upload failed error="upload failed" count=125322026/09/16 20:18:26 INFO Uploading batch count=125332026/09/16 20:18:26 ERROR Upload failed error="upload failed" count=12534--- PASS: TestDrainGivesUpWhenServerDown (0.01s)25352026/09/16 20:18:26 ERROR Drain finished with paths left in queue remaining=12536--- PASS: TestDrainIsolatesPoisonPath (0.00s)2537--- PASS: TestWorkerUploadsAndRemoves (0.03s)2538--- PASS: TestWorkerPrunesClosureDeps (0.03s)2539--- PASS: TestWorkerSkipsGCdPaths (0.02s)2540--- PASS: TestQueueRemoveLargeClosure (0.06s)2541--- PASS: TestQueueConcurrentWriters (0.15s)25422026/09/16 20:18:27 ERROR Upload failed error="context deadline exceeded" count=225432026/09/16 20:18:27 ERROR Drain finished with paths left in queue remaining=42544--- PASS: TestDrainTimeout (0.21s)25452026/09/16 20:18:27 INFO Uploading batch count=125462026/09/16 20:18:27 INFO Uploading batch count=125472026/09/16 20:18:27 INFO Uploading batch count=125482026/09/16 20:18:27 ERROR Upload failed error="upload failed" count=125492026/09/16 20:18:27 INFO Uploading batch count=125502026/09/16 20:18:27 ERROR Upload failed error="upload failed" count=125512026/09/16 20:18:27 INFO Uploading batch count=125522026/09/16 20:18:27 ERROR Upload failed error="upload failed" count=125532026/09/16 20:18:27 INFO Uploading batch count=125542026/09/16 20:18:27 ERROR Upload failed error="upload failed" count=125552026/09/16 20:18:27 ERROR Drain finished with paths left in queue remaining=12556--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2557PASS