niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #148
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestCaseHackSuffix5=== PAUSE TestCaseHackSuffix6=== RUN TestFilterOversizedClosures7=== PAUSE TestFilterOversizedClosures8=== RUN TestPartSizeForNAR9=== PAUSE TestPartSizeForNAR10=== RUN TestUploadMultipart_SupersededByPeer11=== PAUSE TestUploadMultipart_SupersededByPeer12=== RUN TestDumpPathMatchesNix13=== PAUSE TestDumpPathMatchesNix14=== RUN TestDumpPathSingleFile15=== PAUSE TestDumpPathSingleFile16=== RUN TestDumpPathWriterError17=== PAUSE TestDumpPathWriterError18=== RUN TestEncodeNixBase3219=== PAUSE TestEncodeNixBase3220=== RUN TestEncodeNixBase32WithRealHash21=== PAUSE TestEncodeNixBase32WithRealHash22=== RUN TestConvertHashToNix3223=== PAUSE TestConvertHashToNix3224=== RUN TestGetStorePathHash25=== PAUSE TestGetStorePathHash26=== RUN TestPathInfoHashCompatibility27=== PAUSE TestPathInfoHashCompatibility28=== RUN TestParsePathInfoJSON29=== PAUSE TestParsePathInfoJSON30=== RUN TestParsePathInfoJSONMultiplePaths31=== PAUSE TestParsePathInfoJSONMultiplePaths32=== RUN TestPathInfoCACompatibility33=== PAUSE TestPathInfoCACompatibility34=== RUN TestRateLimiterFeedback35=== PAUSE TestRateLimiterFeedback36=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess37=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess38=== RUN TestResolveStorePath39=== PAUSE TestResolveStorePath40=== RUN TestDoWithRetry_BodyReplayedViaGetBody41=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody42=== RUN TestShellSplit43=== PAUSE TestShellSplit44=== RUN TestShellSplitErrors45=== PAUSE TestShellSplitErrors46=== RUN TestSetClientTLS47=== PAUSE TestSetClientTLS48=== RUN TestSetClientTLSDoesNotMutateDefaultTransport49=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport50=== RUN TestSetClientTLSErrors51=== PAUSE TestSetClientTLSErrors52=== RUN TestStaticToken53=== PAUSE TestStaticToken54=== RUN TestFileTokenReadsAndCaches55=== PAUSE TestFileTokenReadsAndCaches56=== RUN TestFileTokenMissing57=== PAUSE TestFileTokenMissing58=== RUN TestFileTokenEmpty59=== PAUSE TestFileTokenEmpty60=== RUN TestScriptTokenNoExpiryRerunsEveryCall61=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall62=== RUN TestScriptTokenCachesUntilRefresh63=== PAUSE TestScriptTokenCachesUntilRefresh64=== RUN TestScriptTokenEmptyToken65=== PAUSE TestScriptTokenEmptyToken66=== RUN TestScriptTokenBadJSON67=== PAUSE TestScriptTokenBadJSON68=== RUN TestScriptTokenScriptFails69=== PAUSE TestScriptTokenScriptFails70=== RUN TestScriptTokenEmptyCommand71=== PAUSE TestScriptTokenEmptyCommand72=== CONT TestDoServerRequestAttachesToken73=== CONT TestResolveStorePath74=== CONT TestFileTokenMissing75=== CONT TestSetClientTLSDoesNotMutateDefaultTransport76=== CONT TestScriptTokenEmptyToken77=== CONT TestShellSplitErrors78--- PASS: TestShellSplitErrors (0.00s)79=== CONT TestSetClientTLS80--- PASS: TestFileTokenMissing (0.00s)81=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess82=== CONT TestEncodeNixBase32WithRealHash83--- PASS: TestEncodeNixBase32WithRealHash (0.00s)84=== CONT TestScriptTokenScriptFails85--- PASS: TestResolveStorePath (0.00s)86=== CONT TestScriptTokenEmptyCommand87--- PASS: TestScriptTokenEmptyCommand (0.00s)88=== CONT TestShellSplit89=== CONT TestScriptTokenCachesUntilRefresh902026/08/27 09:41:28 WARN Rate limiter enabled after throttle name=server-test rate=591=== CONT TestScriptTokenNoExpiryRerunsEveryCall92=== CONT TestFileTokenEmpty93--- PASS: TestShellSplit (0.00s)94=== CONT TestDoWithRetry_BodyReplayedViaGetBody95--- PASS: TestDoServerRequestAttachesToken (0.00s)96=== CONT TestUploadMultipart_SupersededByPeer97=== RUN TestUploadMultipart_SupersededByPeer/exists98=== PAUSE TestUploadMultipart_SupersededByPeer/exists99=== RUN TestUploadMultipart_SupersededByPeer/missing100=== PAUSE TestUploadMultipart_SupersededByPeer/missing101=== CONT TestEncodeNixBase32102=== RUN TestEncodeNixBase32/test_string_hash103=== PAUSE TestEncodeNixBase32/test_string_hash104=== RUN TestEncodeNixBase32/empty_input105=== PAUSE TestEncodeNixBase32/empty_input106=== CONT TestDumpPathWriterError107--- PASS: TestFileTokenEmpty (0.00s)108=== CONT TestDumpPathSingleFile1092026/08/27 09:41:28 WARN Rate limiter enabled after throttle name=server-test rate=51102026/08/27 09:41:28 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:52322111--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)112=== CONT TestDumpPathMatchesNix1132026/08/27 09:41:28 WARN Rate limiter backed off name=server-test rate=51142026/08/27 09:41:28 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:52322115--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)116=== CONT TestFileTokenReadsAndCaches117--- PASS: TestScriptTokenScriptFails (0.00s)118=== CONT TestParsePathInfoJSON119=== RUN TestSetClientTLS/rejects_connection_without_client_cert120=== RUN TestParsePathInfoJSON/Nix_format121=== PAUSE TestParsePathInfoJSON/Nix_format122=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert123=== RUN TestParsePathInfoJSON/Lix_format124=== PAUSE TestParsePathInfoJSON/Lix_format125=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA126=== RUN TestParsePathInfoJSON/empty_input127=== PAUSE TestParsePathInfoJSON/empty_input128=== RUN TestParsePathInfoJSON/whitespace_only129=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA130=== RUN TestSetClientTLS/preserves_debug_logging_transport131=== PAUSE TestParsePathInfoJSON/whitespace_only132=== PAUSE TestSetClientTLS/preserves_debug_logging_transport133=== RUN TestParsePathInfoJSON/invalid_JSON134=== PAUSE TestParsePathInfoJSON/invalid_JSON135=== CONT TestRateLimiterFeedback136=== RUN TestRateLimiterFeedback/429_enables_limiter137=== PAUSE TestRateLimiterFeedback/429_enables_limiter138=== RUN TestRateLimiterFeedback/503_enables_limiter139=== PAUSE TestRateLimiterFeedback/503_enables_limiter140=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter141=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter142=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter143=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter144=== CONT TestPathInfoCACompatibility145=== RUN TestPathInfoCACompatibility/null_ca_field146=== PAUSE TestPathInfoCACompatibility/null_ca_field147=== CONT TestParsePathInfoJSONMultiplePaths148=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths149=== RUN TestPathInfoCACompatibility/old_string_format_-_text150=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text151=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive152=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive153=== RUN TestPathInfoCACompatibility/new_structured_format_-_text154=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text155=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method156=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method157=== CONT TestSetClientTLSErrors158=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths159=== CONT TestGetStorePathHash160--- PASS: TestFileTokenReadsAndCaches (0.00s)161=== RUN TestGetStorePathHash/valid_store_path162=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths163=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths164=== PAUSE TestGetStorePathHash/valid_store_path165=== RUN TestGetStorePathHash/basename_without_hyphen_should_error166=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error167=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error168=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error169=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error170=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error171=== CONT TestPathInfoHashCompatibility172=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)173=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)174=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon175=== CONT TestScriptTokenBadJSON176=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon177=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI178=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI179=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512180=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512181=== CONT TestFilterOversizedClosures182=== RUN TestFilterOversizedClosures/no_limit_keeps_everything183=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything184=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped185=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped186=== RUN TestFilterOversizedClosures/all_closures_skipped187=== PAUSE TestFilterOversizedClosures/all_closures_skipped188=== CONT TestPartSizeForNAR189=== RUN TestPartSizeForNAR/zero_stays_at_minimum190=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum191=== RUN TestPartSizeForNAR/small_stays_at_minimum192=== PAUSE TestPartSizeForNAR/small_stays_at_minimum193=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum194=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum195=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts196=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts197=== RUN TestPartSizeForNAR/1_TiB198=== PAUSE TestPartSizeForNAR/1_TiB199=== RUN TestPartSizeForNAR/5_TiB_S3_max_object200=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object201=== RUN TestPartSizeForNAR/capped_at_5_GiB202=== PAUSE TestPartSizeForNAR/capped_at_5_GiB203=== CONT TestConvertHashToNix32204=== RUN TestConvertHashToNix32/SRI_format_to_Nix32205=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32206=== RUN TestConvertHashToNix32/already_Nix32_format207=== PAUSE TestConvertHashToNix32/already_Nix32_format208=== RUN TestConvertHashToNix32/invalid_format209=== PAUSE TestConvertHashToNix32/invalid_format210=== CONT TestCaseHackSuffix211=== RUN TestSetClientTLSErrors/missing_cert_file212=== PAUSE TestSetClientTLSErrors/missing_cert_file213=== RUN TestSetClientTLSErrors/missing_key_file214=== PAUSE TestSetClientTLSErrors/missing_key_file215=== RUN TestSetClientTLSErrors/missing_ca_file216=== PAUSE TestSetClientTLSErrors/missing_ca_file217=== RUN TestSetClientTLSErrors/invalid_ca_file218=== PAUSE TestSetClientTLSErrors/invalid_ca_file219=== CONT TestStaticToken220--- PASS: TestStaticToken (0.00s)221=== CONT TestUploadMultipart_SupersededByPeer/exists222=== CONT TestEncodeNixBase32/test_string_hash223=== CONT TestUploadMultipart_SupersededByPeer/missing224--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)225 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)226 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)227=== CONT TestEncodeNixBase32/empty_input228--- PASS: TestEncodeNixBase32 (0.00s)229 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)230 --- PASS: TestEncodeNixBase32/empty_input (0.00s)231=== CONT TestSetClientTLS/rejects_connection_without_client_cert232--- PASS: TestScriptTokenEmptyToken (0.01s)233=== CONT TestParsePathInfoJSON/Nix_format234=== CONT TestParsePathInfoJSON/invalid_JSON235=== CONT TestParsePathInfoJSON/whitespace_only236=== CONT TestParsePathInfoJSON/empty_input237=== CONT TestParsePathInfoJSON/Lix_format238--- PASS: TestParsePathInfoJSON (0.00s)239 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)240 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)241 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)242 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)243 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)244=== CONT TestSetClientTLS/preserves_debug_logging_transport245=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA246--- PASS: TestScriptTokenBadJSON (0.01s)247=== CONT TestRateLimiterFeedback/429_enables_limiter2482026/08/27 09:41:28 WARN Rate limiter enabled after throttle name=server-test rate=52492026/08/27 09:41:28 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:523332502026/08/27 09:41:28 WARN Rate limiter backed off name=server-test rate=5251=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter252=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter253=== CONT TestRateLimiterFeedback/503_enables_limiter254=== CONT TestPathInfoCACompatibility/null_ca_field255=== CONT TestPathInfoCACompatibility/new_structured_format_-_text256=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method257=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive2582026/08/27 09:41:28 WARN Rate limiter enabled after throttle name=server-test rate=5259=== CONT TestPathInfoCACompatibility/old_string_format_-_text2602026/08/27 09:41:28 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:52339261--- PASS: TestPathInfoCACompatibility (0.00s)262 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)263 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)264 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)265 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)266 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)267=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths268=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths269--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)270 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)271 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)272=== CONT TestGetStorePathHash/valid_store_path273=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error274=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error275=== CONT TestGetStorePathHash/basename_without_hyphen_should_error2762026/08/27 09:41:28 WARN Rate limiter backed off name=server-test rate=5277--- PASS: TestGetStorePathHash (0.00s)278 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)279 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)280 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)281 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)282--- PASS: TestRateLimiterFeedback (0.00s)283 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)284 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)285 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)286 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)287=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)288=== CONT TestFilterOversizedClosures/no_limit_keeps_everything289=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512290=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon291=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI292--- PASS: TestPathInfoHashCompatibility (0.00s)293 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)294 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)295 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)296 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)297=== CONT TestFilterOversizedClosures/all_closures_skipped2982026/08/27 09:41:28 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-small nar_size=1000 max_nar_size=50299=== CONT TestPartSizeForNAR/zero_stays_at_minimum300=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3012026/08/27 09:41:28 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=2000302=== CONT TestConvertHashToNix32/SRI_format_to_Nix32303=== CONT TestPartSizeForNAR/5_TiB_S3_max_object304=== CONT TestPartSizeForNAR/1_TiB305=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts306=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum307--- PASS: TestFilterOversizedClosures (0.00s)308 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)309 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)310 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)311=== CONT TestPartSizeForNAR/small_stays_at_minimum312=== CONT TestPartSizeForNAR/capped_at_5_GiB313=== CONT TestConvertHashToNix32/already_Nix32_format314=== CONT TestConvertHashToNix32/invalid_format315=== CONT TestSetClientTLSErrors/missing_key_file316=== CONT TestSetClientTLSErrors/missing_cert_file317=== CONT TestSetClientTLSErrors/invalid_ca_file318=== CONT TestSetClientTLSErrors/missing_ca_file319--- PASS: TestPartSizeForNAR (0.00s)320 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)321 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)322 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)323 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)324 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)325 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)326 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)327--- PASS: TestConvertHashToNix32 (0.00s)328 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)329 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)330 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)331--- PASS: TestSetClientTLSErrors (0.00s)332 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)333 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)334 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)335 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)3362026/08/27 09:41:28 http: TLS handshake error from 127.0.0.1:52330: read tcp 127.0.0.1:52325->127.0.0.1:52330: use of closed network connection337--- PASS: TestSetClientTLS (0.01s)338 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)339 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)340 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)341--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.03s)342--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)343--- PASS: TestDumpPathWriterError (0.04s)344--- PASS: TestDumpPathSingleFile (0.04s)345--- PASS: TestCaseHackSuffix (0.04s)346--- PASS: TestDumpPathMatchesNix (0.07s)347--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)348PASS349Running server tests...350The files belonging to this database system will be owned by user "_nixbld1".351This user must also own the server process.352353The database cluster will be initialized with locale "C".354The default database encoding has accordingly been set to "SQL_ASCII".355The default text search configuration will be set to "english".356357Data page checksums are enabled.358359creating directory /nix/var/nix/builds/nix-44679-95555299/postgres4169715798/data ... ok360creating subdirectories ... ok361selecting dynamic shared memory implementation ... posix362selecting default "max_connections" ... 100363selecting default "shared_buffers" ... 128MB364selecting default time zone ... UTC365creating configuration files ... ok366running bootstrap script ... ok367performing post-bootstrap initialization ... ok368syncing data to disk ... ok369370initdb: warning: enabling "trust" authentication for local connections371initdb: 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.372373Success. You can now start the database server using:374375 pg_ctl -D /nix/var/nix/builds/nix-44679-95555299/postgres4169715798/data -l logfile start376377/nix/var/nix/builds/nix-44679-95555299/postgres4169715798:5432 - no response3782026-08-27 09:41:30.347 UTC [44734] LOG: starting PostgreSQL 18.4 on aarch64-apple-darwin25.5.0, compiled by clang version 21.1.8, 64-bit3792026-08-27 09:41:30.348 UTC [44734] LOG: listening on Unix socket "/nix/var/nix/builds/nix-44679-95555299/postgres4169715798/.s.PGSQL.5432"3802026-08-27 09:41:30.350 UTC [44745] LOG: database system was shut down at 2026-08-27 09:41:30 UTC3812026-08-27 09:41:30.350 UTC [44734] LOG: database system is ready to accept connections382/nix/var/nix/builds/nix-44679-95555299/postgres4169715798:5432 - accepting connections383=== RUN TestService_AuthMiddleware384=== PAUSE TestService_AuthMiddleware385=== RUN TestService_AuthMiddleware_MTLSProxyHeader386=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader387=== RUN TestService_AuthMiddleware_MTLSBoundSubjects388=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects389=== RUN TestService_ReadAuthMiddleware390=== PAUSE TestService_ReadAuthMiddleware391=== RUN TestService_AuthMiddleware_OIDC392=== PAUSE TestService_AuthMiddleware_OIDC393=== RUN TestCacheConfigHandler394=== PAUSE TestCacheConfigHandler395=== RUN TestCacheStatsHandler396=== PAUSE TestCacheStatsHandler397=== RUN TestClientCADerivations398=== PAUSE TestClientCADerivations399=== RUN TestClientErrorHandling400=== PAUSE TestClientErrorHandling401=== RUN TestClientIntegration402=== PAUSE TestClientIntegration403=== RUN TestClientMultipleUploads404=== PAUSE TestClientMultipleUploads405=== RUN TestClientWithDependencies406=== PAUSE TestClientWithDependencies407=== RUN TestPinProtectsFromGC408=== PAUSE TestPinProtectsFromGC409=== RUN TestGCAdvisoryLockBlocksConcurrentRun4102026-08-27 09:41:30.754 UTC [44858] ERROR: relation "goose_db_version" does not exist at character 364112026-08-27 09:41:30.754 UTC [44858] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4122026/08/27 09:41:30 OK 20241026095416_initial_model.sql (3.18ms)4132026/08/27 09:41:30 OK 20251210153512_drop_unused_gin_index.sql (416.58µs)4142026/08/27 09:41:30 OK 20251218171726_add_pins.sql (817.25µs)4152026/08/27 09:41:30 OK 20260628120000_add_object_size_and_stats.sql (832.13µs)4162026/08/27 09:41:30 goose: successfully migrated database to version: 202606281200004172026/08/27 09:41:30 OK 1_commit_pending_closure.sql (843.96µs)4182026/08/27 09:41:30 OK 2_object_stats_trigger.sql (201.79µs)4192026/08/27 09:41:30 goose: up to current file version: 2420--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.27s)421=== RUN TestGCBugBareHashReferences422=== PAUSE TestGCBugBareHashReferences423=== RUN TestGCMetrics424=== PAUSE TestGCMetrics425=== RUN TestGCTaskStore_StartNew426=== PAUSE TestGCTaskStore_StartNew427=== RUN TestGCTaskStore_DeduplicateSameParams428=== PAUSE TestGCTaskStore_DeduplicateSameParams429=== RUN TestGCTaskStore_ConflictDifferentParams430=== PAUSE TestGCTaskStore_ConflictDifferentParams431=== RUN TestGCTaskStore_GetEmpty432=== PAUSE TestGCTaskStore_GetEmpty433=== RUN TestGCTaskStore_GetReturnsLatest434=== PAUSE TestGCTaskStore_GetReturnsLatest435=== RUN TestGCTaskStore_CompletedAllowsNewTask436=== PAUSE TestGCTaskStore_CompletedAllowsNewTask437=== RUN TestGCTaskStore_PhaseUpdates438=== PAUSE TestGCTaskStore_PhaseUpdates439=== RUN TestGCTaskStore_Fail440=== PAUSE TestGCTaskStore_Fail441=== RUN TestGracefulShutdownDrainsInflight442=== PAUSE TestGracefulShutdownDrainsInflight443=== RUN TestService_healthCheckHandler444=== PAUSE TestService_healthCheckHandler445=== RUN TestGenerateLandingPage446=== PAUSE TestGenerateLandingPage447=== RUN TestCacheConfigHandlerMaxNarSize448=== PAUSE TestCacheConfigHandlerMaxNarSize449=== RUN TestCreatePendingClosureRejectsOversizedNAR450=== PAUSE TestCreatePendingClosureRejectsOversizedNAR451=== RUN TestNARDeduplicationMetadataUploadBug452=== PAUSE TestNARDeduplicationMetadataUploadBug453=== RUN TestMetricsInventory454=== PAUSE TestMetricsInventory455=== RUN TestService_NativeMTLS456=== PAUSE TestService_NativeMTLS457=== RUN TestServerTLSConfig458=== PAUSE TestServerTLSConfig459=== RUN TestMultipartCleanup460=== PAUSE TestMultipartCleanup461=== RUN TestObjectStatsTrigger462=== PAUSE TestObjectStatsTrigger463=== RUN TestOrphanedObjectsGC464=== PAUSE TestOrphanedObjectsGC465=== RUN TestOrphanedObjectsGCStressTest466=== PAUSE TestOrphanedObjectsGCStressTest467=== RUN TestResurrectedObjectNotDeleted468=== PAUSE TestResurrectedObjectNotDeleted469=== RUN TestParseSingleRange470=== PAUSE TestParseSingleRange471=== RUN TestIsValidCachePath472=== PAUSE TestIsValidCachePath473=== RUN TestReadProxyNarinfo474=== PAUSE TestReadProxyNarinfo475=== RUN TestReadProxyNarinfoAlreadyDecompressed476=== PAUSE TestReadProxyNarinfoAlreadyDecompressed477=== RUN TestReadProxyNarStreaming478=== PAUSE TestReadProxyNarStreaming479=== RUN TestReadProxy404480=== PAUSE TestReadProxy404481=== RUN TestReadProxyInvalidPath482=== PAUSE TestReadProxyInvalidPath483=== RUN TestReadProxyHead484=== PAUSE TestReadProxyHead485=== RUN TestReadProxyConditionalGet486=== PAUSE TestReadProxyConditionalGet487=== RUN TestReadProxyRootRedirectsToIndexHTML488=== PAUSE TestReadProxyRootRedirectsToIndexHTML489=== RUN TestReadProxyDisabled490=== PAUSE TestReadProxyDisabled491=== RUN TestReadProxyRangeRequest492=== PAUSE TestReadProxyRangeRequest493=== RUN TestRedundantMultipartUpload494=== PAUSE TestRedundantMultipartUpload495=== RUN TestCompleteMultipartUpload_ErrorButObjectExists496=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists497=== RUN TestCompletedNarNotReofferedAcrossClosures498=== PAUSE TestCompletedNarNotReofferedAcrossClosures499=== RUN TestPresignedUploadRegisteredBeforeCommit500=== PAUSE TestPresignedUploadRegisteredBeforeCommit501=== RUN TestService_Rustfstest502=== PAUSE TestService_Rustfstest503=== RUN TestParseSize504=== PAUSE TestParseSize505=== RUN TestSkippedUploadsHandler506=== PAUSE TestSkippedUploadsHandler507=== RUN TestSystemdListenerNotActivated508--- PASS: TestSystemdListenerNotActivated (0.00s)509=== RUN TestWatchdogBeatsWhenHealthy510--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)511=== RUN TestWatchdogSkipsWhenUnhealthy5122026/08/27 09:41:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5132026/08/27 09:41:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5142026/08/27 09:41:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5152026/08/27 09:41:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5162026/08/27 09:41:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5172026/08/27 09:41:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5182026/08/27 09:41:31 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5192026/08/27 09:41:31 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5202026/08/27 09:41:31 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5212026/08/27 09:41:31 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"522--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)523=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle524=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle525=== RUN TestProxyWriteTimeout526=== PAUSE TestProxyWriteTimeout527=== RUN TestIsValidUploadKey528=== PAUSE TestIsValidUploadKey529=== RUN TestUploadHandlersRejectInvalidKeys530=== PAUSE TestUploadHandlersRejectInvalidKeys531=== RUN TestUploadHandlersRejectOversizedBody532=== PAUSE TestUploadHandlersRejectOversizedBody533=== RUN TestService_cleanupPendingClosuresHandler534=== PAUSE TestService_cleanupPendingClosuresHandler535=== RUN TestService_createPendingClosureHandler536=== PAUSE TestService_createPendingClosureHandler537=== RUN TestService_verifyS3Integrity538=== PAUSE TestService_verifyS3Integrity539=== RUN TestCompleteMultipartUnregistered540=== PAUSE TestCompleteMultipartUnregistered541=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT542=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT543=== CONT TestService_AuthMiddleware544=== CONT TestObjectStatsTrigger545=== CONT TestCompleteMultipartUpload_ErrorButObjectExists546=== CONT TestIsValidUploadKey547=== CONT TestService_createPendingClosureHandler548=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT549=== CONT TestUploadHandlersRejectOversizedBody550=== RUN TestIsValidUploadKey/narinfo551=== CONT TestUploadHandlersRejectInvalidKeys552=== PAUSE TestIsValidUploadKey/narinfo553=== CONT TestCompleteMultipartUnregistered554=== RUN TestIsValidUploadKey/nar_zst555=== PAUSE TestIsValidUploadKey/nar_zst556=== RUN TestIsValidUploadKey/nar_xz557=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info558=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info559=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal560=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal561=== PAUSE TestIsValidUploadKey/nar_xz562=== RUN TestIsValidUploadKey/nar_plain563=== PAUSE TestIsValidUploadKey/nar_plain564=== CONT TestRedundantMultipartUpload565=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key566=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key567=== RUN TestIsValidUploadKey/listing568=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key569=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key570=== PAUSE TestIsValidUploadKey/listing571=== RUN TestIsValidUploadKey/build_log572=== PAUSE TestIsValidUploadKey/build_log573=== RUN TestIsValidUploadKey/build_log_home-manager_file574=== PAUSE TestIsValidUploadKey/build_log_home-manager_file575=== RUN TestIsValidUploadKey/build_log_plus_in_name576=== PAUSE TestIsValidUploadKey/build_log_plus_in_name577=== RUN TestIsValidUploadKey/build_log_question_mark578=== PAUSE TestIsValidUploadKey/build_log_question_mark579=== RUN TestIsValidUploadKey/build_log_equals580=== PAUSE TestIsValidUploadKey/build_log_equals581=== RUN TestIsValidUploadKey/realisation582=== PAUSE TestIsValidUploadKey/realisation583=== RUN TestIsValidUploadKey/realisation_plus_in_output584=== PAUSE TestIsValidUploadKey/realisation_plus_in_output585=== RUN TestIsValidUploadKey/nix-cache-info586=== PAUSE TestIsValidUploadKey/nix-cache-info587=== RUN TestIsValidUploadKey/index.html588=== PAUSE TestIsValidUploadKey/index.html589=== RUN TestIsValidUploadKey/narinfo_key,_nar_type590=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type591=== RUN TestIsValidUploadKey/nar_key,_narinfo_type592=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type593=== RUN TestIsValidUploadKey/listing_key,_narinfo_type594=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type595=== CONT TestReadProxyRangeRequest596=== RUN TestIsValidUploadKey/traversal597=== PAUSE TestIsValidUploadKey/traversal598=== RUN TestIsValidUploadKey/traversal_nar599=== PAUSE TestIsValidUploadKey/traversal_nar600=== RUN TestIsValidUploadKey/absolute601=== PAUSE TestIsValidUploadKey/absolute602=== RUN TestIsValidUploadKey/empty_key603=== PAUSE TestIsValidUploadKey/empty_key604=== RUN TestIsValidUploadKey/unknown_type605=== PAUSE TestIsValidUploadKey/unknown_type606=== CONT TestReadProxyDisabled607=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts608=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts609=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure610=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure611=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart612=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart613=== CONT TestReadProxyRootRedirectsToIndexHTML6142026-08-27 09:41:31.331 UTC [44880] ERROR: relation "goose_db_version" does not exist at character 366152026-08-27 09:41:31.331 UTC [44880] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6162026-08-27 09:41:31.340 UTC [44881] ERROR: relation "goose_db_version" does not exist at character 366172026-08-27 09:41:31.340 UTC [44881] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6182026-08-27 09:41:31.344 UTC [44882] ERROR: relation "goose_db_version" does not exist at character 366192026-08-27 09:41:31.344 UTC [44882] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6202026-08-27 09:41:31.345 UTC [44883] ERROR: relation "goose_db_version" does not exist at character 366212026-08-27 09:41:31.345 UTC [44883] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6222026-08-27 09:41:31.347 UTC [44885] ERROR: relation "goose_db_version" does not exist at character 366232026-08-27 09:41:31.347 UTC [44885] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6242026-08-27 09:41:31.348 UTC [44886] ERROR: relation "goose_db_version" does not exist at character 366252026-08-27 09:41:31.348 UTC [44886] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6262026-08-27 09:41:31.348 UTC [44884] ERROR: relation "goose_db_version" does not exist at character 366272026-08-27 09:41:31.348 UTC [44884] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6282026/08/27 09:41:31 OK 20241026095416_initial_model.sql (10.51ms)6292026/08/27 09:41:31 OK 20251210153512_drop_unused_gin_index.sql (958.63µs)6302026-08-27 09:41:31.352 UTC [44887] ERROR: relation "goose_db_version" does not exist at character 366312026-08-27 09:41:31.352 UTC [44887] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6322026-08-27 09:41:31.352 UTC [44888] ERROR: relation "goose_db_version" does not exist at character 366332026-08-27 09:41:31.352 UTC [44888] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6342026/08/27 09:41:31 OK 20251218171726_add_pins.sql (1.91ms)6352026-08-27 09:41:31.353 UTC [44889] ERROR: relation "goose_db_version" does not exist at character 366362026-08-27 09:41:31.353 UTC [44889] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6372026/08/27 09:41:31 OK 20241026095416_initial_model.sql (6.27ms)6382026/08/27 09:41:31 OK 20260628120000_add_object_size_and_stats.sql (1.65ms)6392026/08/27 09:41:31 goose: successfully migrated database to version: 202606281200006402026/08/27 09:41:31 OK 20251210153512_drop_unused_gin_index.sql (1.24ms)6412026/08/27 09:41:31 OK 1_commit_pending_closure.sql (1.48ms)6422026/08/27 09:41:31 OK 2_object_stats_trigger.sql (656.21µs)6432026/08/27 09:41:31 goose: up to current file version: 26442026/08/27 09:41:31 OK 20241026095416_initial_model.sql (8.02ms)6452026/08/27 09:41:31 OK 20251218171726_add_pins.sql (2.91ms)6462026/08/27 09:41:31 OK 20251210153512_drop_unused_gin_index.sql (900.21µs)6472026/08/27 09:41:31 OK 20241026095416_initial_model.sql (5.87ms)6482026/08/27 09:41:31 OK 20241026095416_initial_model.sql (8.86ms)6492026/08/27 09:41:31 OK 20241026095416_initial_model.sql (6.17ms)6502026/08/27 09:41:31 OK 20251210153512_drop_unused_gin_index.sql (681.96µs)6512026/08/27 09:41:31 OK 20251210153512_drop_unused_gin_index.sql (837.67µs)6522026/08/27 09:41:31 OK 20241026095416_initial_model.sql (6.9ms)6532026/08/27 09:41:31 OK 20260628120000_add_object_size_and_stats.sql (19.84ms)6542026/08/27 09:41:31 goose: successfully migrated database to version: 202606281200006552026/08/27 09:41:31 OK 20251210153512_drop_unused_gin_index.sql (17.8ms)6562026/08/27 09:41:31 OK 20251210153512_drop_unused_gin_index.sql (18.22ms)6572026/08/27 09:41:31 OK 20251218171726_add_pins.sql (19.46ms)6582026/08/27 09:41:31 OK 20251218171726_add_pins.sql (18.69ms)6592026/08/27 09:41:31 OK 20251218171726_add_pins.sql (18.79ms)6602026/08/27 09:41:31 OK 20241026095416_initial_model.sql (23.08ms)6612026/08/27 09:41:31 OK 1_commit_pending_closure.sql (1.2ms)6622026/08/27 09:41:31 OK 2_object_stats_trigger.sql (205µs)6632026/08/27 09:41:31 goose: up to current file version: 26642026/08/27 09:41:31 OK 20251210153512_drop_unused_gin_index.sql (28.33ms)6652026/08/27 09:41:31 OK 20251218171726_add_pins.sql (35.01ms)6662026/08/27 09:41:31 OK 20251218171726_add_pins.sql (35.05ms)6672026/08/27 09:41:31 OK 20260628120000_add_object_size_and_stats.sql (36.99ms)6682026/08/27 09:41:31 goose: successfully migrated database to version: 202606281200006692026/08/27 09:41:31 OK 20260628120000_add_object_size_and_stats.sql (37.27ms)6702026/08/27 09:41:31 goose: successfully migrated database to version: 202606281200006712026/08/27 09:41:31 OK 20260628120000_add_object_size_and_stats.sql (37.18ms)6722026/08/27 09:41:31 goose: successfully migrated database to version: 202606281200006732026/08/27 09:41:31 OK 1_commit_pending_closure.sql (36.85ms)6742026/08/27 09:41:31 OK 1_commit_pending_closure.sql (36.8ms)6752026/08/27 09:41:31 OK 1_commit_pending_closure.sql (36.9ms)6762026/08/27 09:41:31 OK 2_object_stats_trigger.sql (224.38µs)6772026/08/27 09:41:31 goose: up to current file version: 26782026/08/27 09:41:31 OK 2_object_stats_trigger.sql (252.29µs)6792026/08/27 09:41:31 goose: up to current file version: 26802026/08/27 09:41:31 OK 2_object_stats_trigger.sql (256.29µs)6812026/08/27 09:41:31 goose: up to current file version: 26822026/08/27 09:41:31 OK 20251218171726_add_pins.sql (48.81ms)6832026/08/27 09:41:31 OK 20260628120000_add_object_size_and_stats.sql (43.37ms)6842026/08/27 09:41:31 goose: successfully migrated database to version: 202606281200006852026/08/27 09:41:31 OK 20260628120000_add_object_size_and_stats.sql (43.55ms)6862026/08/27 09:41:31 goose: successfully migrated database to version: 202606281200006872026/08/27 09:41:31 OK 20241026095416_initial_model.sql (99.47ms)6882026/08/27 09:41:31 OK 20260628120000_add_object_size_and_stats.sql (1.68ms)6892026/08/27 09:41:31 goose: successfully migrated database to version: 202606281200006902026/08/27 09:41:31 OK 20241026095416_initial_model.sql (99.45ms)6912026/08/27 09:41:31 OK 1_commit_pending_closure.sql (1.56ms)6922026/08/27 09:41:31 OK 1_commit_pending_closure.sql (1.63ms)6932026/08/27 09:41:31 OK 2_object_stats_trigger.sql (237.33µs)6942026/08/27 09:41:31 goose: up to current file version: 26952026/08/27 09:41:31 OK 2_object_stats_trigger.sql (285.58µs)6962026/08/27 09:41:31 goose: up to current file version: 26972026/08/27 09:41:31 OK 1_commit_pending_closure.sql (3.99ms)6982026/08/27 09:41:31 OK 2_object_stats_trigger.sql (206.29µs)6992026/08/27 09:41:31 goose: up to current file version: 27002026/08/27 09:41:31 OK 20251210153512_drop_unused_gin_index.sql (7.51ms)7012026/08/27 09:41:31 OK 20251210153512_drop_unused_gin_index.sql (7.32ms)7022026/08/27 09:41:31 OK 20251218171726_add_pins.sql (23.95ms)7032026/08/27 09:41:31 OK 20251218171726_add_pins.sql (24.01ms)7042026/08/27 09:41:31 OK 20260628120000_add_object_size_and_stats.sql (8.74ms)7052026/08/27 09:41:31 goose: successfully migrated database to version: 202606281200007062026/08/27 09:41:31 OK 20260628120000_add_object_size_and_stats.sql (8.73ms)7072026/08/27 09:41:31 goose: successfully migrated database to version: 202606281200007082026/08/27 09:41:31 OK 1_commit_pending_closure.sql (3.58ms)7092026/08/27 09:41:31 OK 1_commit_pending_closure.sql (3.66ms)7102026/08/27 09:41:31 OK 2_object_stats_trigger.sql (267.54µs)7112026/08/27 09:41:31 goose: up to current file version: 27122026/08/27 09:41:31 OK 2_object_stats_trigger.sql (290.04µs)7132026/08/27 09:41:31 goose: up to current file version: 2714{"timestamp":"2026-08-27T09:41:31.502199Z","level":"ERROR","duration":"131µs","resp":"Response { status: 503, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>SlowDown</Code><Message>bucket creation concurrency limit reached; retry later</Message></Error>\" } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-35807-2406330080/rustfs-1.0.0-beta.12-vendor/source-git-1/s3s-0.14.1/src/service.rs","line_number":640,"threadName":"rustfs-worker","threadId":"ThreadId(6)"}715{"timestamp":"2026-08-27T09:41:31.502198Z","level":"ERROR","duration":"126.167µs","resp":"Response { status: 503, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>SlowDown</Code><Message>bucket creation concurrency limit reached; retry later</Message></Error>\" } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-35807-2406330080/rustfs-1.0.0-beta.12-vendor/source-git-1/s3s-0.14.1/src/service.rs","line_number":640,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}716{"timestamp":"2026-08-27T09:41:31.502293Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"b4489c97-c511-4396-a749-d77e43b5f068","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket11/","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::layer","filename":"rustfs/src/server/layer.rs","line_number":392,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}717{"timestamp":"2026-08-27T09:41:31.502296Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"9bb1ef09-4959-49ca-9a58-899c9acfe65d","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket10/","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::layer","filename":"rustfs/src/server/layer.rs","line_number":392,"threadName":"rustfs-worker","threadId":"ThreadId(6)"}7182026/08/27 09:41:31 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"719--- PASS: TestService_AuthMiddleware (0.44s)720=== CONT TestReadProxyConditionalGet7212026/08/27 09:41:31 INFO Received uploads request method=POST path=/api/pending_closures7222026/08/27 09:41:31 INFO Received uploads request method=POST path=/api/pending_closures7232026/08/27 09:41:31 INFO Received uploads request method=POST path=/api/pending_closures724--- PASS: TestObjectStatsTrigger (0.60s)725=== CONT TestReadProxyHead7262026/08/27 09:41:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7272026/08/27 09:41:31 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst728--- PASS: TestCompleteMultipartUnregistered (0.63s)729=== CONT TestReadProxyInvalidPath730--- PASS: TestReadProxyDisabled (0.67s)731=== CONT TestReadProxy404732--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.79s)733=== CONT TestReadProxyNarStreaming7342026/08/27 09:41:31 INFO Received uploads request method=POST path=/api/pending_closures7352026/08/27 09:41:31 INFO Received uploads request method=POST path=/api/pending_closures736--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.90s)737=== CONT TestReadProxyNarinfoAlreadyDecompressed7382026/08/27 09:41:32 INFO Received uploads request method=POST path=/api/pending_closures7392026/08/27 09:41:32 INFO Received uploads request method=POST path=/api/pending_closures740--- PASS: TestReadProxyRangeRequest (1.13s)741=== CONT TestReadProxyNarinfo7422026/08/27 09:41:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7432026/08/27 09:41:32 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NzE5ZTNiMzgtODViMi00MTkzLWJhNmEtYTkwYmVmYjVjYmY3LjIxYjk5OTg3LWIwNmMtNDQxNi05Y2Q0LWZhMGNkYjBiYTBiMngxNzg3ODIzNjkyMDU2NDIxMDAw7442026/08/27 09:41:32 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NzE5ZTNiMzgtODViMi00MTkzLWJhNmEtYTkwYmVmYjVjYmY3LjIxYjk5OTg3LWIwNmMtNDQxNi05Y2Q0LWZhMGNkYjBiYTBiMngxNzg3ODIzNjkyMDU2NDIxMDAw parts=1745--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.30s)746=== CONT TestIsValidCachePath747=== RUN TestIsValidCachePath/narinfo748=== PAUSE TestIsValidCachePath/narinfo749=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars750=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars751=== RUN TestIsValidCachePath/nar_zst752=== PAUSE TestIsValidCachePath/nar_zst753=== RUN TestIsValidCachePath/nar_xz754=== PAUSE TestIsValidCachePath/nar_xz755=== RUN TestIsValidCachePath/nar_bz2756=== PAUSE TestIsValidCachePath/nar_bz2757=== RUN TestIsValidCachePath/nar_uncompressed758=== PAUSE TestIsValidCachePath/nar_uncompressed759=== RUN TestIsValidCachePath/ls760=== PAUSE TestIsValidCachePath/ls761=== RUN TestIsValidCachePath/log762=== PAUSE TestIsValidCachePath/log763=== RUN TestIsValidCachePath/realisation764=== PAUSE TestIsValidCachePath/realisation765=== RUN TestIsValidCachePath/nix-cache-info766=== PAUSE TestIsValidCachePath/nix-cache-info767=== RUN TestIsValidCachePath/index.html768=== PAUSE TestIsValidCachePath/index.html769=== RUN TestIsValidCachePath/traversal_parent770=== PAUSE TestIsValidCachePath/traversal_parent771=== RUN TestIsValidCachePath/traversal_in_middle772=== PAUSE TestIsValidCachePath/traversal_in_middle773=== RUN TestIsValidCachePath/invalid_char_e774=== PAUSE TestIsValidCachePath/invalid_char_e775=== RUN TestIsValidCachePath/invalid_char_u776=== PAUSE TestIsValidCachePath/invalid_char_u777=== RUN TestIsValidCachePath/random_path778=== PAUSE TestIsValidCachePath/random_path779=== RUN TestIsValidCachePath/empty780=== PAUSE TestIsValidCachePath/empty781=== RUN TestIsValidCachePath/leading_slash782=== PAUSE TestIsValidCachePath/leading_slash783=== RUN TestIsValidCachePath/wrong_extension784=== PAUSE TestIsValidCachePath/wrong_extension785=== RUN TestIsValidCachePath/short_hash786=== PAUSE TestIsValidCachePath/short_hash787=== CONT TestParseSingleRange788=== RUN TestParseSingleRange/none789=== PAUSE TestParseSingleRange/none790=== RUN TestParseSingleRange/unknown_unit791=== PAUSE TestParseSingleRange/unknown_unit792=== RUN TestParseSingleRange/multi-range_ignored793=== PAUSE TestParseSingleRange/multi-range_ignored794=== RUN TestParseSingleRange/malformed_no_dash795=== PAUSE TestParseSingleRange/malformed_no_dash796=== RUN TestParseSingleRange/malformed_both_empty797=== PAUSE TestParseSingleRange/malformed_both_empty798=== RUN TestParseSingleRange/malformed_end_before_start799=== PAUSE TestParseSingleRange/malformed_end_before_start800=== RUN TestParseSingleRange/closed801=== PAUSE TestParseSingleRange/closed802=== RUN TestParseSingleRange/open-ended803=== PAUSE TestParseSingleRange/open-ended804=== RUN TestParseSingleRange/end_clamped_to_size805=== PAUSE TestParseSingleRange/end_clamped_to_size806=== RUN TestParseSingleRange/suffix807=== PAUSE TestParseSingleRange/suffix808=== RUN TestParseSingleRange/suffix_exceeds_size809=== PAUSE TestParseSingleRange/suffix_exceeds_size810=== RUN TestParseSingleRange/single_byte811=== PAUSE TestParseSingleRange/single_byte812=== RUN TestParseSingleRange/start_past_EOF813=== PAUSE TestParseSingleRange/start_past_EOF814=== RUN TestParseSingleRange/start_far_past_EOF815=== PAUSE TestParseSingleRange/start_far_past_EOF816=== CONT TestResurrectedObjectNotDeleted8172026/08/27 09:41:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8182026/08/27 09:41:33 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NzE5ZTNiMzgtODViMi00MTkzLWJhNmEtYTkwYmVmYjVjYmY3LjVlNDAwNmU4LThmZGYtNDc3Ni1iMjUwLWI3NjEzNzc3ZjMwZXgxNzg3ODIzNjkxNTU0Mzc1MDAw parts=108192026/08/27 09:41:33 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8202026/08/27 09:41:33 INFO Completed upload id=18212026/08/27 09:41:33 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000008222026/08/27 09:41:33 INFO Received uploads request method=POST path=/api/pending_closures8232026/08/27 09:41:33 INFO Starting cleanup of old closures method=DELETE path=/api/closures8242026/08/27 09:41:33 INFO Aborted multipart uploads count=08252026/08/27 09:41:33 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=08262026/08/27 09:41:33 INFO Vacuumed table table=pending_closures8272026-08-27 09:41:33.155 UTC [44913] ERROR: relation "goose_db_version" does not exist at character 368282026-08-27 09:41:33.155 UTC [44913] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8292026/08/27 09:41:33 INFO Vacuumed table table=pending_objects8302026/08/27 09:41:33 INFO Vacuumed table table=multipart_uploads8312026/08/27 09:41:33 INFO Vacuumed table table=closures8322026/08/27 09:41:33 INFO Vacuumed table table=objects8332026/08/27 09:41:33 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000834--- PASS: TestService_createPendingClosureHandler (2.18s)835=== CONT TestOrphanedObjectsGCStressTest8362026-08-27 09:41:33.276 UTC [44916] ERROR: relation "goose_db_version" does not exist at character 368372026-08-27 09:41:33.276 UTC [44916] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8382026-08-27 09:41:33.276 UTC [44915] ERROR: relation "goose_db_version" does not exist at character 368392026-08-27 09:41:33.276 UTC [44915] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8402026/08/27 09:41:33 OK 20241026095416_initial_model.sql (137.85ms)8412026/08/27 09:41:33 OK 20251210153512_drop_unused_gin_index.sql (1.62ms)8422026/08/27 09:41:33 OK 20251218171726_add_pins.sql (36.15ms)8432026-08-27 09:41:33.416 UTC [44921] ERROR: relation "goose_db_version" does not exist at character 368442026-08-27 09:41:33.416 UTC [44921] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8452026/08/27 09:41:33 OK 20260628120000_add_object_size_and_stats.sql (29.68ms)8462026/08/27 09:41:33 goose: successfully migrated database to version: 202606281200008472026/08/27 09:41:33 OK 1_commit_pending_closure.sql (11.37ms)8482026/08/27 09:41:33 OK 2_object_stats_trigger.sql (2.42ms)8492026/08/27 09:41:33 goose: up to current file version: 28502026/08/27 09:41:33 OK 20241026095416_initial_model.sql (133.8ms)8512026/08/27 09:41:33 OK 20241026095416_initial_model.sql (142.18ms)8522026/08/27 09:41:33 OK 20251210153512_drop_unused_gin_index.sql (3.46ms)8532026/08/27 09:41:33 OK 20251210153512_drop_unused_gin_index.sql (10.36ms)8542026/08/27 09:41:33 OK 20251218171726_add_pins.sql (29.37ms)8552026/08/27 09:41:33 OK 20251218171726_add_pins.sql (29.4ms)8562026/08/27 09:41:33 OK 20260628120000_add_object_size_and_stats.sql (39.46ms)8572026/08/27 09:41:33 goose: successfully migrated database to version: 202606281200008582026/08/27 09:41:33 OK 20260628120000_add_object_size_and_stats.sql (45.18ms)8592026/08/27 09:41:33 goose: successfully migrated database to version: 202606281200008602026/08/27 09:41:33 OK 1_commit_pending_closure.sql (7.77ms)8612026/08/27 09:41:33 OK 2_object_stats_trigger.sql (403.13µs)8622026/08/27 09:41:33 goose: up to current file version: 28632026/08/27 09:41:33 OK 1_commit_pending_closure.sql (7.87ms)8642026/08/27 09:41:33 OK 2_object_stats_trigger.sql (466.96µs)8652026/08/27 09:41:33 goose: up to current file version: 2866--- PASS: TestReadProxyConditionalGet (2.13s)867=== CONT TestOrphanedObjectsGC8682026/08/27 09:41:33 OK 20241026095416_initial_model.sql (215.38ms)8692026/08/27 09:41:33 OK 20251210153512_drop_unused_gin_index.sql (13.01ms)8702026/08/27 09:41:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete871--- PASS: TestReadProxyInvalidPath (2.02s)872=== CONT TestService_verifyS3Integrity8732026/08/27 09:41:33 OK 20251218171726_add_pins.sql (42.28ms)8742026-08-27 09:41:33.761 UTC [44922] ERROR: relation "goose_db_version" does not exist at character 368752026-08-27 09:41:33.761 UTC [44922] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8762026/08/27 09:41:33 OK 20260628120000_add_object_size_and_stats.sql (29.48ms)8772026/08/27 09:41:33 goose: successfully migrated database to version: 202606281200008782026/08/27 09:41:33 OK 1_commit_pending_closure.sql (7.96ms)8792026/08/27 09:41:33 OK 2_object_stats_trigger.sql (433.17µs)8802026/08/27 09:41:33 goose: up to current file version: 28812026/08/27 09:41:33 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NzE5ZTNiMzgtODViMi00MTkzLWJhNmEtYTkwYmVmYjVjYmY3LmJlOGJiYWU3LWE4NjMtNDIwMS04MjhiLWYxY2FjNjUwMmI5MXgxNzg3ODIzNjkxOTc5NjIyMDAw parts=12882--- PASS: TestRedundantMultipartUpload (2.71s)883=== CONT TestService_cleanupPendingClosuresHandler884--- PASS: TestReadProxyHead (2.16s)885=== CONT TestPresignedUploadRegisteredBeforeCommit8862026-08-27 09:41:33.835 UTC [44927] ERROR: relation "goose_db_version" does not exist at character 368872026-08-27 09:41:33.835 UTC [44927] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC888--- PASS: TestReadProxy404 (2.16s)889=== CONT TestService_Rustfstest8902026/08/27 09:41:33 OK 20241026095416_initial_model.sql (131.66ms)8912026/08/27 09:41:33 OK 20251210153512_drop_unused_gin_index.sql (20.14ms)8922026/08/27 09:41:33 OK 20241026095416_initial_model.sql (95.98ms)8932026/08/27 09:41:33 OK 20251210153512_drop_unused_gin_index.sql (1.69ms)8942026/08/27 09:41:33 OK 20251218171726_add_pins.sql (18.43ms)8952026/08/27 09:41:33 OK 20251218171726_add_pins.sql (7.79ms)8962026/08/27 09:41:33 OK 20260628120000_add_object_size_and_stats.sql (3.92ms)8972026/08/27 09:41:33 goose: successfully migrated database to version: 202606281200008982026/08/27 09:41:33 OK 1_commit_pending_closure.sql (1.27ms)8992026/08/27 09:41:33 OK 2_object_stats_trigger.sql (351.71µs)9002026/08/27 09:41:33 goose: up to current file version: 29012026-08-27 09:41:33.981 UTC [44938] ERROR: relation "goose_db_version" does not exist at character 369022026-08-27 09:41:33.981 UTC [44938] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9032026/08/27 09:41:34 OK 20260628120000_add_object_size_and_stats.sql (26.71ms)9042026/08/27 09:41:34 goose: successfully migrated database to version: 202606281200009052026/08/27 09:41:34 OK 1_commit_pending_closure.sql (4.86ms)9062026/08/27 09:41:34 OK 2_object_stats_trigger.sql (222.38µs)9072026/08/27 09:41:34 goose: up to current file version: 29082026-08-27 09:41:34.012 UTC [44939] ERROR: relation "goose_db_version" does not exist at character 369092026-08-27 09:41:34.012 UTC [44939] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC910--- PASS: TestReadProxyNarStreaming (2.24s)911=== CONT TestCompletedNarNotReofferedAcrossClosures912--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.21s)913=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle9142026/08/27 09:41:34 OK 20241026095416_initial_model.sql (151.18ms)9152026/08/27 09:41:34 OK 20251210153512_drop_unused_gin_index.sql (4.77ms)9162026/08/27 09:41:34 OK 20241026095416_initial_model.sql (139.2ms)9172026/08/27 09:41:34 OK 20251210153512_drop_unused_gin_index.sql (5.99ms)9182026/08/27 09:41:34 OK 20251218171726_add_pins.sql (12.4ms)9192026/08/27 09:41:34 OK 20251218171726_add_pins.sql (2.73ms)9202026/08/27 09:41:34 OK 20260628120000_add_object_size_and_stats.sql (4.61ms)9212026/08/27 09:41:34 goose: successfully migrated database to version: 202606281200009222026/08/27 09:41:34 OK 20260628120000_add_object_size_and_stats.sql (6.14ms)9232026/08/27 09:41:34 goose: successfully migrated database to version: 202606281200009242026/08/27 09:41:34 OK 1_commit_pending_closure.sql (3.81ms)9252026/08/27 09:41:34 OK 2_object_stats_trigger.sql (816.75µs)9262026/08/27 09:41:34 goose: up to current file version: 29272026/08/27 09:41:34 OK 1_commit_pending_closure.sql (2.32ms)9282026/08/27 09:41:34 OK 2_object_stats_trigger.sql (311.17µs)9292026/08/27 09:41:34 goose: up to current file version: 2930--- PASS: TestReadProxyNarinfo (2.17s)931=== CONT TestProxyWriteTimeout932=== RUN TestProxyWriteTimeout/narinfo933=== PAUSE TestProxyWriteTimeout/narinfo934=== RUN TestProxyWriteTimeout/1_GiB_nar935=== PAUSE TestProxyWriteTimeout/1_GiB_nar936=== RUN TestProxyWriteTimeout/10_GiB_nar937=== PAUSE TestProxyWriteTimeout/10_GiB_nar938=== RUN TestProxyWriteTimeout/unknown_size939=== PAUSE TestProxyWriteTimeout/unknown_size940=== CONT TestSkippedUploadsHandler9412026/08/27 09:41:34 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000942--- PASS: TestSkippedUploadsHandler (0.00s)943=== CONT TestGCTaskStore_ConflictDifferentParams944--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)945=== CONT TestMultipartCleanup946--- PASS: TestResurrectedObjectNotDeleted (2.19s)947=== CONT TestServerTLSConfig948=== RUN TestServerTLSConfig/no_client_CA949=== PAUSE TestServerTLSConfig/no_client_CA950=== RUN TestServerTLSConfig/missing_CA_file951=== PAUSE TestServerTLSConfig/missing_CA_file952=== RUN TestServerTLSConfig/not_a_PEM_file953=== PAUSE TestServerTLSConfig/not_a_PEM_file954=== CONT TestService_NativeMTLS9552026-08-27 09:41:34.611 UTC [44967] ERROR: relation "goose_db_version" does not exist at character 369562026-08-27 09:41:34.611 UTC [44967] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9572026/08/27 09:41:34 OK 20241026095416_initial_model.sql (11.46ms)9582026/08/27 09:41:34 OK 20251210153512_drop_unused_gin_index.sql (785.71µs)9592026/08/27 09:41:34 OK 20251218171726_add_pins.sql (5.46ms)9602026/08/27 09:41:34 OK 20260628120000_add_object_size_and_stats.sql (7.69ms)9612026/08/27 09:41:34 goose: successfully migrated database to version: 202606281200009622026/08/27 09:41:34 OK 1_commit_pending_closure.sql (897.17µs)9632026/08/27 09:41:34 OK 2_object_stats_trigger.sql (232.21µs)9642026/08/27 09:41:34 goose: up to current file version: 29652026-08-27 09:41:35.219 UTC [44971] ERROR: relation "goose_db_version" does not exist at character 369662026-08-27 09:41:35.219 UTC [44971] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9672026-08-27 09:41:35.262 UTC [44973] ERROR: relation "goose_db_version" does not exist at character 369682026-08-27 09:41:35.262 UTC [44973] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9692026-08-27 09:41:35.295 UTC [44974] ERROR: relation "goose_db_version" does not exist at character 369702026-08-27 09:41:35.295 UTC [44974] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9712026/08/27 09:41:35 OK 20241026095416_initial_model.sql (84.36ms)9722026/08/27 09:41:35 OK 20241026095416_initial_model.sql (63.72ms)9732026/08/27 09:41:35 OK 20251210153512_drop_unused_gin_index.sql (17.29ms)9742026/08/27 09:41:35 OK 20251210153512_drop_unused_gin_index.sql (8.79ms)9752026-08-27 09:41:35.385 UTC [44975] ERROR: relation "goose_db_version" does not exist at character 369762026-08-27 09:41:35.385 UTC [44975] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9772026/08/27 09:41:35 OK 20251218171726_add_pins.sql (22.65ms)9782026/08/27 09:41:35 OK 20251218171726_add_pins.sql (23.58ms)9792026-08-27 09:41:35.403 UTC [44976] ERROR: relation "goose_db_version" does not exist at character 369802026-08-27 09:41:35.403 UTC [44976] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9812026/08/27 09:41:35 OK 20241026095416_initial_model.sql (79.43ms)9822026/08/27 09:41:35 OK 20251210153512_drop_unused_gin_index.sql (5.35ms)9832026/08/27 09:41:35 OK 20260628120000_add_object_size_and_stats.sql (15.84ms)9842026/08/27 09:41:35 goose: successfully migrated database to version: 202606281200009852026/08/27 09:41:35 OK 20260628120000_add_object_size_and_stats.sql (20.87ms)9862026/08/27 09:41:35 goose: successfully migrated database to version: 202606281200009872026/08/27 09:41:35 OK 1_commit_pending_closure.sql (1.99ms)9882026/08/27 09:41:35 OK 1_commit_pending_closure.sql (2.01ms)9892026/08/27 09:41:35 OK 2_object_stats_trigger.sql (253.58µs)9902026/08/27 09:41:35 goose: up to current file version: 29912026/08/27 09:41:35 OK 2_object_stats_trigger.sql (259.92µs)9922026/08/27 09:41:35 goose: up to current file version: 29932026/08/27 09:41:35 OK 20251218171726_add_pins.sql (9.9ms)9942026-08-27 09:41:35.420 UTC [44977] ERROR: relation "goose_db_version" does not exist at character 369952026-08-27 09:41:35.420 UTC [44977] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9962026/08/27 09:41:35 OK 20260628120000_add_object_size_and_stats.sql (24.74ms)9972026/08/27 09:41:35 goose: successfully migrated database to version: 202606281200009982026/08/27 09:41:35 OK 1_commit_pending_closure.sql (6.92ms)9992026/08/27 09:41:35 OK 2_object_stats_trigger.sql (454.46µs)10002026/08/27 09:41:35 goose: up to current file version: 210012026/08/27 09:41:35 INFO Received cleanup request method=DELETE path=/api/pending_closures10022026/08/27 09:41:35 INFO Aborted multipart uploads count=010032026/08/27 09:41:35 INFO Received uploads request method=POST path=/api/pending_closures10042026/08/27 09:41:35 OK 20241026095416_initial_model.sql (211.95ms)10052026/08/27 09:41:35 OK 20251210153512_drop_unused_gin_index.sql (8.67ms)10062026/08/27 09:41:35 INFO Received uploads request method=POST path=/api/pending_closures10072026/08/27 09:41:35 OK 20251218171726_add_pins.sql (40.2ms)10082026/08/27 09:41:35 INFO Received cleanup request method=DELETE path=/api/pending_closures10092026/08/27 09:41:35 OK 20241026095416_initial_model.sql (253.15ms)10102026/08/27 09:41:35 OK 20251210153512_drop_unused_gin_index.sql (4.17ms)10112026/08/27 09:41:35 INFO Aborted multipart uploads count=110122026/08/27 09:41:35 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10132026-08-27 09:41:35.712 UTC [44973] ERROR: Closure does not exist: id=110142026-08-27 09:41:35.712 UTC [44973] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE10152026-08-27 09:41:35.712 UTC [44973] STATEMENT: -- name: CommitPendingClosure :exec1016 SELECT commit_pending_closure($1::bigint)1017 1018--- PASS: TestService_cleanupPendingClosuresHandler (1.93s)1019=== CONT TestMetricsInventory10202026/08/27 09:41:35 OK 20260628120000_add_object_size_and_stats.sql (38.9ms)10212026/08/27 09:41:35 goose: successfully migrated database to version: 2026062812000010222026/08/27 09:41:35 OK 1_commit_pending_closure.sql (7ms)10232026/08/27 09:41:35 OK 2_object_stats_trigger.sql (337.21µs)10242026/08/27 09:41:35 goose: up to current file version: 210252026/08/27 09:41:35 OK 20241026095416_initial_model.sql (251.71ms)10262026/08/27 09:41:35 OK 20251210153512_drop_unused_gin_index.sql (12.29ms)10272026/08/27 09:41:35 OK 20251218171726_add_pins.sql (46.57ms)10282026-08-27 09:41:35.762 UTC [44980] ERROR: relation "goose_db_version" does not exist at character 3610292026-08-27 09:41:35.762 UTC [44980] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10302026/08/27 09:41:35 OK 20251218171726_add_pins.sql (31.62ms)10312026/08/27 09:41:35 OK 20260628120000_add_object_size_and_stats.sql (42.44ms)10322026/08/27 09:41:35 goose: successfully migrated database to version: 2026062812000010332026/08/27 09:41:35 OK 1_commit_pending_closure.sql (8.22ms)10342026/08/27 09:41:35 OK 2_object_stats_trigger.sql (256.96µs)10352026/08/27 09:41:35 goose: up to current file version: 210362026/08/27 09:41:35 OK 20260628120000_add_object_size_and_stats.sql (24.7ms)10372026/08/27 09:41:35 goose: successfully migrated database to version: 2026062812000010382026/08/27 09:41:35 OK 1_commit_pending_closure.sql (14.33ms)10392026/08/27 09:41:35 OK 2_object_stats_trigger.sql (258.33µs)10402026/08/27 09:41:35 goose: up to current file version: 21041--- PASS: TestService_Rustfstest (1.99s)1042=== CONT TestNARDeduplicationMetadataUploadBug10432026/08/27 09:41:36 OK 20241026095416_initial_model.sql (210.99ms)10442026/08/27 09:41:36 INFO Received uploads request method=POST path=/api/pending_closures10452026/08/27 09:41:36 OK 20251210153512_drop_unused_gin_index.sql (10.64ms)10462026/08/27 09:41:36 OK 20251218171726_add_pins.sql (34.42ms)10472026/08/27 09:41:36 OK 20260628120000_add_object_size_and_stats.sql (46.18ms)10482026/08/27 09:41:36 goose: successfully migrated database to version: 2026062812000010492026/08/27 09:41:36 OK 1_commit_pending_closure.sql (12.33ms)10502026/08/27 09:41:36 OK 2_object_stats_trigger.sql (1.13ms)10512026/08/27 09:41:36 goose: up to current file version: 210522026/08/27 09:41:36 INFO Received uploads request method=POST path=/api/pending_closures10532026/08/27 09:41:36 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10542026/08/27 09:41:36 INFO Received uploads request method=POST path=/api/pending_closures1055--- PASS: TestPresignedUploadRegisteredBeforeCommit (2.43s)1056=== CONT TestCreatePendingClosureRejectsOversizedNAR10572026/08/27 09:41:36 INFO Received uploads request method=POST path=/api/pending_closures1058--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1059=== CONT TestCacheConfigHandlerMaxNarSize1060--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1061=== CONT TestGenerateLandingPage1062--- PASS: TestGenerateLandingPage (0.00s)1063=== CONT TestService_healthCheckHandler10642026/08/27 09:41:36 INFO Received uploads request method=POST path=/api/pending_closures10652026-08-27 09:41:36.412 UTC [44990] ERROR: relation "goose_db_version" does not exist at character 3610662026-08-27 09:41:36.412 UTC [44990] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10672026/08/27 09:41:36 OK 20241026095416_initial_model.sql (259.18ms)10682026/08/27 09:41:36 OK 20251210153512_drop_unused_gin_index.sql (18.23ms)10692026/08/27 09:41:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10702026/08/27 09:41:36 OK 20251218171726_add_pins.sql (43.17ms)10712026/08/27 09:41:36 OK 20260628120000_add_object_size_and_stats.sql (37.5ms)10722026/08/27 09:41:36 goose: successfully migrated database to version: 2026062812000010732026/08/27 09:41:36 OK 1_commit_pending_closure.sql (9.49ms)10742026/08/27 09:41:36 OK 2_object_stats_trigger.sql (1.49ms)10752026/08/27 09:41:36 goose: up to current file version: 21076=== NAME TestOrphanedObjectsGC1077 orphaned_objects_gc_test.go:290: GC Test Summary:1078 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1079 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1080 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1081 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1082 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1083--- PASS: TestOrphanedObjectsGC (3.24s)1084=== CONT TestGracefulShutdownDrainsInflight10852026/08/27 09:41:36 INFO Starting HTTP server address=127.0.0.1:5247110862026/08/27 09:41:36 INFO Shutdown signal received, draining in-flight requests timeout=10s10872026-08-27 09:41:36.910 UTC [44993] ERROR: relation "goose_db_version" does not exist at character 3610882026-08-27 09:41:36.910 UTC [44993] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1089--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1090=== CONT TestGCTaskStore_Fail1091--- PASS: TestGCTaskStore_Fail (0.00s)1092=== CONT TestGCTaskStore_PhaseUpdates1093--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1094=== CONT TestGCTaskStore_CompletedAllowsNewTask1095--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1096=== CONT TestGCTaskStore_GetReturnsLatest1097--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1098=== CONT TestGCTaskStore_GetEmpty1099--- PASS: TestGCTaskStore_GetEmpty (0.00s)1100=== CONT TestClientIntegration11012026/08/27 09:41:37 INFO Received uploads request method=POST path=/api/pending_closures11022026/08/27 09:41:37 OK 20241026095416_initial_model.sql (217.49ms)11032026/08/27 09:41:37 OK 20251210153512_drop_unused_gin_index.sql (7.19ms)11042026/08/27 09:41:37 INFO Received cleanup request method=DELETE path=/api/pending_closures11052026/08/27 09:41:37 INFO Aborted multipart uploads count=11106--- PASS: TestMultipartCleanup (2.88s)1107=== CONT TestGCTaskStore_DeduplicateSameParams1108--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1109=== CONT TestGCTaskStore_StartNew1110--- PASS: TestGCTaskStore_StartNew (0.00s)1111=== CONT TestGCMetrics11122026/08/27 09:41:37 OK 20251218171726_add_pins.sql (47.19ms)11132026/08/27 09:41:37 OK 20260628120000_add_object_size_and_stats.sql (43.11ms)11142026/08/27 09:41:37 goose: successfully migrated database to version: 2026062812000011152026/08/27 09:41:37 OK 1_commit_pending_closure.sql (6.81ms)11162026/08/27 09:41:37 OK 2_object_stats_trigger.sql (709.67µs)11172026/08/27 09:41:37 goose: up to current file version: 211182026/08/27 09:41:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11192026/08/27 09:41:37 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NzE5ZTNiMzgtODViMi00MTkzLWJhNmEtYTkwYmVmYjVjYmY3LmIzZThjOGMwLTA5ZjMtNGU0OC04OTY1LTUzZjM5NWJiYTNlNngxNzg3ODIzNjk1NzA3MDA0MDAw parts=1011202026/08/27 09:41:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11212026/08/27 09:41:37 INFO Completed upload id=111222026/08/27 09:41:37 INFO Received uploads request method=POST path=/api/pending_closures11232026/08/27 09:41:37 INFO Received uploads request method=POST path=/api/pending_closures11242026/08/27 09:41:37 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo11252026/08/27 09:41:37 WARN Found objects in DB but missing from S3, will re-upload count=11126--- PASS: TestService_verifyS3Integrity (3.75s)1127=== CONT TestGCBugBareHashReferences11282026/08/27 09:41:37 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11292026/08/27 09:41:37 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1130--- PASS: TestService_NativeMTLS (2.99s)1131=== CONT TestPinProtectsFromGC11322026/08/27 09:41:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11332026-08-27 09:41:38.076 UTC [45002] ERROR: relation "goose_db_version" does not exist at character 3611342026-08-27 09:41:38.076 UTC [45002] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11352026/08/27 09:41:38 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NzE5ZTNiMzgtODViMi00MTkzLWJhNmEtYTkwYmVmYjVjYmY3Ljg4Yjg5NTQ4LTBiODItNGJmMC1iY2I3LTUzMWRjMmJhMDM5NXgxNzg3ODIzNjk2MDcxOTIyMDAw parts=1211362026/08/27 09:41:38 INFO Received uploads request method=POST path=/api/pending_closures1137--- PASS: TestCompletedNarNotReofferedAcrossClosures (4.05s)1138=== CONT TestCacheConfigHandler1139=== RUN TestCacheConfigHandler/full_config,_no_issuer1140=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1141=== RUN TestCacheConfigHandler/no_cache_url_configured1142=== PAUSE TestCacheConfigHandler/no_cache_url_configured1143=== RUN TestCacheConfigHandler/no_signing_keys1144=== PAUSE TestCacheConfigHandler/no_signing_keys1145=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1146=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1147=== CONT TestClientErrorHandling1148=== RUN TestClientErrorHandling/InvalidStorePath1149=== PAUSE TestClientErrorHandling/InvalidStorePath1150=== RUN TestClientErrorHandling/InvalidAuthToken1151=== PAUSE TestClientErrorHandling/InvalidAuthToken1152=== RUN TestClientErrorHandling/ServerNotAvailable1153=== PAUSE TestClientErrorHandling/ServerNotAvailable1154=== CONT TestClientCADerivations11552026-08-27 09:41:38.306 UTC [45005] ERROR: relation "goose_db_version" does not exist at character 3611562026-08-27 09:41:38.306 UTC [45005] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11572026/08/27 09:41:38 OK 20241026095416_initial_model.sql (154.16ms)11582026/08/27 09:41:38 OK 20251210153512_drop_unused_gin_index.sql (12.73ms)11592026/08/27 09:41:38 OK 20251218171726_add_pins.sql (30.34ms)11602026/08/27 09:41:38 OK 20260628120000_add_object_size_and_stats.sql (36.7ms)11612026/08/27 09:41:38 goose: successfully migrated database to version: 2026062812000011622026/08/27 09:41:38 OK 1_commit_pending_closure.sql (9.98ms)11632026/08/27 09:41:38 OK 2_object_stats_trigger.sql (1.74ms)11642026/08/27 09:41:38 goose: up to current file version: 211652026/08/27 09:41:38 OK 20241026095416_initial_model.sql (225.31ms)11662026/08/27 09:41:38 OK 20251210153512_drop_unused_gin_index.sql (3.94ms)11672026/08/27 09:41:38 OK 20251218171726_add_pins.sql (37.86ms)1168--- PASS: TestMetricsInventory (2.96s)1169=== CONT TestCacheStatsHandler11702026/08/27 09:41:38 OK 20260628120000_add_object_size_and_stats.sql (54.03ms)11712026/08/27 09:41:38 goose: successfully migrated database to version: 2026062812000011722026/08/27 09:41:38 OK 1_commit_pending_closure.sql (12.87ms)11732026/08/27 09:41:38 OK 2_object_stats_trigger.sql (585.67µs)11742026/08/27 09:41:38 goose: up to current file version: 211752026-08-27 09:41:38.785 UTC [45008] ERROR: relation "goose_db_version" does not exist at character 3611762026-08-27 09:41:38.785 UTC [45008] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11772026/08/27 09:41:39 OK 20241026095416_initial_model.sql (185.28ms)11782026/08/27 09:41:39 OK 20251210153512_drop_unused_gin_index.sql (18.08ms)11792026/08/27 09:41:39 OK 20251218171726_add_pins.sql (25.33ms)11802026/08/27 09:41:39 OK 20260628120000_add_object_size_and_stats.sql (41.11ms)11812026/08/27 09:41:39 goose: successfully migrated database to version: 2026062812000011822026/08/27 09:41:39 OK 1_commit_pending_closure.sql (2.35ms)11832026/08/27 09:41:39 OK 2_object_stats_trigger.sql (312.13µs)11842026/08/27 09:41:39 goose: up to current file version: 21185=== NAME TestNARDeduplicationMetadataUploadBug1186 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-44679-95555299/TestNARDeduplicationMetadataUploadBug2001340901/001/store/bsxj8skyl7qyr4icmxx1bap7nzxsgbnj-file1.txt1187--- PASS: TestService_healthCheckHandler (3.04s)1188=== CONT TestClientWithDependencies11892026/08/27 09:41:39 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11902026-08-27 09:41:39.321 UTC [45016] ERROR: relation "goose_db_version" does not exist at character 3611912026-08-27 09:41:39.321 UTC [45016] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11922026/08/27 09:41:39 INFO Received uploads request method=POST path=/api/pending_closures11932026/08/27 09:41:39 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11942026/08/27 09:41:39 INFO Uploading bsxj8skyl7qyr4icmxx1bap7nzxsgbnj-file1.txt (160B)11952026/08/27 09:41:39 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11962026/08/27 09:41:39 WARN Failed to register uploaded object key=bsxj8skyl7qyr4icmxx1bap7nzxsgbnj.ls error="server returned 404: 404 page not found\n"11972026/08/27 09:41:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11982026/08/27 09:41:39 INFO Signed narinfos id=1 count=111992026/08/27 09:41:39 INFO Uploading 1 narinfos12002026-08-27 09:41:39.473 UTC [45022] ERROR: relation "goose_db_version" does not exist at character 3612012026-08-27 09:41:39.473 UTC [45022] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12022026/08/27 09:41:39 OK 20241026095416_initial_model.sql (130.34ms)12032026/08/27 09:41:39 OK 20251210153512_drop_unused_gin_index.sql (3.94ms)12042026/08/27 09:41:39 WARN Failed to register uploaded object key=bsxj8skyl7qyr4icmxx1bap7nzxsgbnj.narinfo error="server returned 404: 404 page not found\n"12052026/08/27 09:41:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12062026/08/27 09:41:39 INFO Completed upload id=112072026/08/27 09:41:39 INFO Upload complete. (254ms)1208=== NAME TestNARDeduplicationMetadataUploadBug1209 metadata_upload_test.go:54: Retrieved narinfo from S3:1210 StorePath: /nix/var/nix/builds/nix-44679-95555299/TestNARDeduplicationMetadataUploadBug2001340901/001/store/bsxj8skyl7qyr4icmxx1bap7nzxsgbnj-file1.txt1211 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1212 Compression: zstd1213 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1214 NarSize: 1601215 References: 1216 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1217 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1218 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1219 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}12202026/08/27 09:41:39 OK 20251218171726_add_pins.sql (34.32ms)12212026/08/27 09:41:39 OK 20260628120000_add_object_size_and_stats.sql (43.24ms)12222026/08/27 09:41:39 goose: successfully migrated database to version: 2026062812000012232026-08-27 09:41:39.585 UTC [45024] ERROR: relation "goose_db_version" does not exist at character 3612242026-08-27 09:41:39.585 UTC [45024] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12252026/08/27 09:41:39 OK 1_commit_pending_closure.sql (7.27ms)12262026/08/27 09:41:39 OK 2_object_stats_trigger.sql (285.42µs)12272026/08/27 09:41:39 goose: up to current file version: 21228 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-44679-95555299/TestNARDeduplicationMetadataUploadBug2001340901/001/store/wd7nx5fd3glz3xdibqkv7w6cm31nj7xj-file2.txt12292026/08/27 09:41:39 OK 20241026095416_initial_model.sql (161.21ms)12302026/08/27 09:41:39 OK 20251210153512_drop_unused_gin_index.sql (15.43ms)12312026/08/27 09:41:39 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12322026/08/27 09:41:39 OK 20251218171726_add_pins.sql (19.46ms)12332026-08-27 09:41:39.732 UTC [45031] ERROR: relation "goose_db_version" does not exist at character 3612342026-08-27 09:41:39.732 UTC [45031] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12352026/08/27 09:41:39 OK 20260628120000_add_object_size_and_stats.sql (24.74ms)12362026/08/27 09:41:39 goose: successfully migrated database to version: 2026062812000012372026/08/27 09:41:39 OK 1_commit_pending_closure.sql (5.76ms)12382026/08/27 09:41:39 OK 2_object_stats_trigger.sql (247.75µs)12392026/08/27 09:41:39 goose: up to current file version: 212402026/08/27 09:41:39 INFO Received uploads request method=POST path=/api/pending_closures12412026/08/27 09:41:39 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12422026/08/27 09:41:39 WARN Failed to register uploaded object key=wd7nx5fd3glz3xdibqkv7w6cm31nj7xj.ls error="server returned 404: 404 page not found\n"12432026/08/27 09:41:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12442026/08/27 09:41:39 INFO Signed narinfos id=2 count=112452026/08/27 09:41:39 INFO Uploading 1 narinfos12462026/08/27 09:41:39 OK 20241026095416_initial_model.sql (170.91ms)12472026/08/27 09:41:39 OK 20251210153512_drop_unused_gin_index.sql (10.02ms)12482026/08/27 09:41:39 WARN Failed to register uploaded object key=wd7nx5fd3glz3xdibqkv7w6cm31nj7xj.narinfo error="server returned 404: 404 page not found\n"12492026/08/27 09:41:39 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12502026/08/27 09:41:39 INFO Completed upload id=212512026/08/27 09:41:39 INFO Upload complete. (188ms)1252 metadata_upload_test.go:76: Retrieved narinfo from S3:1253 StorePath: /nix/var/nix/builds/nix-44679-95555299/TestNARDeduplicationMetadataUploadBug2001340901/001/store/wd7nx5fd3glz3xdibqkv7w6cm31nj7xj-file2.txt1254 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1255 Compression: zstd1256 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1257 NarSize: 1601258 References: 1259 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1260 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1261 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1262 {"version":1,"root":{"type":"regular","size":44}}12632026/08/27 09:41:39 OK 20251218171726_add_pins.sql (27.79ms)12642026/08/27 09:41:39 OK 20260628120000_add_object_size_and_stats.sql (27.29ms)12652026/08/27 09:41:39 goose: successfully migrated database to version: 2026062812000012662026/08/27 09:41:39 OK 1_commit_pending_closure.sql (8.99ms)12672026/08/27 09:41:39 OK 2_object_stats_trigger.sql (225.63µs)12682026/08/27 09:41:39 goose: up to current file version: 212692026/08/27 09:41:39 INFO Aborted multipart uploads count=01270--- PASS: TestNARDeduplicationMetadataUploadBug (4.03s)1271=== CONT TestClientMultipleUploads12722026/08/27 09:41:39 WARN Force mode enabled - objects will be deleted immediately without grace period12732026/08/27 09:41:39 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=012742026/08/27 09:41:39 INFO Vacuumed table table=pending_closures12752026/08/27 09:41:39 INFO Vacuumed table table=pending_objects12762026/08/27 09:41:39 INFO Vacuumed table table=multipart_uploads12772026/08/27 09:41:39 INFO Vacuumed table table=closures12782026/08/27 09:41:39 INFO Vacuumed table table=objects1279--- PASS: TestGCMetrics (2.68s)1280=== CONT TestService_ReadAuthMiddleware12812026/08/27 09:41:39 OK 20241026095416_initial_model.sql (192.13ms)12822026/08/27 09:41:39 OK 20251210153512_drop_unused_gin_index.sql (631.38µs)1283=== NAME TestClientIntegration1284 client_integration_test.go:276: Created store path: /nix/var/nix/builds/nix-44679-95555299/TestClientIntegration2475315878/002/store/p36gsw13vaaqk8i7z8ah0x215sad0ykx-test-file.txt12852026/08/27 09:41:39 OK 20251218171726_add_pins.sql (23.08ms)12862026/08/27 09:41:40 OK 20260628120000_add_object_size_and_stats.sql (15.95ms)12872026/08/27 09:41:40 goose: successfully migrated database to version: 2026062812000012882026/08/27 09:41:40 OK 1_commit_pending_closure.sql (5.28ms)12892026/08/27 09:41:40 OK 2_object_stats_trigger.sql (233.88µs)12902026/08/27 09:41:40 goose: up to current file version: 212912026/08/27 09:41:40 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12922026/08/27 09:41:40 INFO Received uploads request method=POST path=/api/pending_closures12932026/08/27 09:41:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12942026/08/27 09:41:40 INFO Uploading p36gsw13vaaqk8i7z8ah0x215sad0ykx-test-file.txt (152B)12952026/08/27 09:41:40 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"12962026/08/27 09:41:40 WARN Failed to register uploaded object key=p36gsw13vaaqk8i7z8ah0x215sad0ykx.ls error="server returned 404: 404 page not found\n"12972026/08/27 09:41:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12982026/08/27 09:41:40 INFO Signed narinfos id=1 count=112992026/08/27 09:41:40 INFO Uploading 1 narinfos13002026/08/27 09:41:40 WARN Failed to register uploaded object key=p36gsw13vaaqk8i7z8ah0x215sad0ykx.narinfo error="server returned 404: 404 page not found\n"13012026/08/27 09:41:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13022026/08/27 09:41:40 INFO Completed upload id=113032026/08/27 09:41:40 INFO Upload complete. (253ms)1304 client_integration_test.go:292: Retrieved narinfo from S3:1305 StorePath: /nix/var/nix/builds/nix-44679-95555299/TestClientIntegration2475315878/002/store/p36gsw13vaaqk8i7z8ah0x215sad0ykx-test-file.txt1306 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1307 Compression: zstd1308 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11309 NarSize: 1521310 References: 1311 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11312 client_integration_test.go:293: Retrieved .ls file from S3 (compressed size: 77 bytes)1313 client_integration_test.go:293: Decompressed .ls content (64 bytes):1314 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1315 client_integration_test.go:296: Testing garbage collection...13162026-08-27 09:41:40.265 UTC [45050] ERROR: relation "goose_db_version" does not exist at character 3613172026-08-27 09:41:40.265 UTC [45050] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13182026/08/27 09:41:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures13192026/08/27 09:41:40 INFO Garbage collection started13202026/08/27 09:41:40 INFO Aborted multipart uploads count=013212026/08/27 09:41:40 WARN Force mode enabled - objects will be deleted immediately without grace period1322--- PASS: TestGCBugBareHashReferences (2.82s)1323=== CONT TestService_AuthMiddleware_OIDC13242026/08/27 09:41:40 INFO OIDC provider initialized name=test13252026-08-27 09:41:40.324 UTC [45056] ERROR: relation "goose_db_version" does not exist at character 3613262026-08-27 09:41:40.324 UTC [45056] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13272026/08/27 09:41:40 OK 20241026095416_initial_model.sql (42.17ms)13282026/08/27 09:41:40 OK 20251210153512_drop_unused_gin_index.sql (5.57ms)1329=== NAME TestPinProtectsFromGC1330 client_integration_test.go:646: Pinned store path: /nix/var/nix/builds/nix-44679-95555299/TestPinProtectsFromGC1697177861/001/store/cw3644p1jny0gb2rkyiy8lz0hcwl4yzm-pinned-file.txt1331 client_integration_test.go:647: Unpinned store path: /nix/var/nix/builds/nix-44679-95555299/TestPinProtectsFromGC1697177861/001/store/c4k95vvx0y0sjfmqnb8ciq067d4p0d3f-unpinned-file.txt13322026/08/27 09:41:40 OK 20251218171726_add_pins.sql (18.45ms)13332026/08/27 09:41:40 OK 20260628120000_add_object_size_and_stats.sql (12.27ms)13342026/08/27 09:41:40 goose: successfully migrated database to version: 2026062812000013352026/08/27 09:41:40 OK 1_commit_pending_closure.sql (1.75ms)13362026/08/27 09:41:40 OK 2_object_stats_trigger.sql (402.75µs)13372026/08/27 09:41:40 goose: up to current file version: 213382026/08/27 09:41:40 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=013392026/08/27 09:41:40 OK 20241026095416_initial_model.sql (77.52ms)13402026/08/27 09:41:40 INFO Vacuumed table table=pending_closures13412026/08/27 09:41:40 OK 20251210153512_drop_unused_gin_index.sql (7.65ms)13422026/08/27 09:41:40 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13432026/08/27 09:41:40 INFO Vacuumed table table=pending_objects13442026/08/27 09:41:40 INFO Vacuumed table table=multipart_uploads13452026/08/27 09:41:40 OK 20251218171726_add_pins.sql (27.96ms)13462026/08/27 09:41:40 INFO Vacuumed table table=closures13472026/08/27 09:41:40 OK 20260628120000_add_object_size_and_stats.sql (22.2ms)13482026/08/27 09:41:40 goose: successfully migrated database to version: 2026062812000013492026/08/27 09:41:40 OK 1_commit_pending_closure.sql (7.37ms)13502026/08/27 09:41:40 INFO Received uploads request method=POST path=/api/pending_closures13512026/08/27 09:41:40 OK 2_object_stats_trigger.sql (271.17µs)13522026/08/27 09:41:40 goose: up to current file version: 213532026/08/27 09:41:40 INFO Vacuumed table table=objects13542026/08/27 09:41:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13552026/08/27 09:41:40 INFO Uploading cw3644p1jny0gb2rkyiy8lz0hcwl4yzm-pinned-file.txt (128B)13562026/08/27 09:41:40 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"13572026/08/27 09:41:40 WARN Failed to register uploaded object key=cw3644p1jny0gb2rkyiy8lz0hcwl4yzm.ls error="server returned 404: 404 page not found\n"13582026/08/27 09:41:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13592026/08/27 09:41:40 INFO Signed narinfos id=1 count=113602026/08/27 09:41:40 INFO Uploading 1 narinfos13612026/08/27 09:41:40 WARN Failed to register uploaded object key=cw3644p1jny0gb2rkyiy8lz0hcwl4yzm.narinfo error="server returned 404: 404 page not found\n"13622026/08/27 09:41:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13632026/08/27 09:41:40 INFO Completed upload id=113642026/08/27 09:41:40 INFO Upload complete. (284ms)1365--- PASS: TestCacheStatsHandler (2.04s)1366=== CONT TestService_AuthMiddleware_MTLSBoundSubjects13672026/08/27 09:41:40 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13682026-08-27 09:41:40.776 UTC [45076] ERROR: relation "goose_db_version" does not exist at character 3613692026-08-27 09:41:40.776 UTC [45076] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13702026/08/27 09:41:40 WARN Rate limiter enabled after throttle name=s3-test rate=513712026/08/27 09:41:40 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1372=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1373 throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=101374 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001375--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (6.61s)1376=== CONT TestService_AuthMiddleware_MTLSProxyHeader13772026/08/27 09:41:40 INFO Received uploads request method=POST path=/api/pending_closures13782026/08/27 09:41:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13792026/08/27 09:41:40 INFO Uploading c4k95vvx0y0sjfmqnb8ciq067d4p0d3f-unpinned-file.txt (128B)13802026/08/27 09:41:40 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"13812026/08/27 09:41:40 WARN Failed to register uploaded object key=c4k95vvx0y0sjfmqnb8ciq067d4p0d3f.ls error="server returned 404: 404 page not found\n"13822026/08/27 09:41:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13832026/08/27 09:41:40 INFO Signed narinfos id=2 count=113842026/08/27 09:41:40 INFO Uploading 1 narinfos13852026/08/27 09:41:40 WARN Failed to register uploaded object key=c4k95vvx0y0sjfmqnb8ciq067d4p0d3f.narinfo error="server returned 404: 404 page not found\n"13862026/08/27 09:41:40 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13872026/08/27 09:41:40 INFO Completed upload id=213882026/08/27 09:41:40 INFO Upload complete. (198ms)1389=== NAME TestClientCADerivations1390 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-44679-95555299/TestClientCADerivations615320914/001/store/ga0w4hfmy60jph4w5854vah6xmw64fh5-ca-test13912026/08/27 09:41:40 INFO Received create pin request method=POST path=/api/pins/myapp13922026/08/27 09:41:40 OK 20241026095416_initial_model.sql (143.41ms)13932026/08/27 09:41:40 OK 20251210153512_drop_unused_gin_index.sql (7.44ms)1394 client_ca_test.go:139: Found 1 dependencies (including self)13952026/08/27 09:41:40 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-44679-95555299/TestPinProtectsFromGC1697177861/001/store/cw3644p1jny0gb2rkyiy8lz0hcwl4yzm-pinned-file.txt narinfo_key=cw3644p1jny0gb2rkyiy8lz0hcwl4yzm.narinfo13962026/08/27 09:41:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures13972026/08/27 09:41:40 INFO Garbage collection started13982026/08/27 09:41:40 INFO Aborted multipart uploads count=013992026/08/27 09:41:40 WARN Force mode enabled - objects will be deleted immediately without grace period14002026/08/27 09:41:40 OK 20251218171726_add_pins.sql (13.88ms)14012026/08/27 09:41:41 OK 20260628120000_add_object_size_and_stats.sql (28.89ms)14022026/08/27 09:41:41 goose: successfully migrated database to version: 2026062812000014032026/08/27 09:41:41 OK 1_commit_pending_closure.sql (1.31ms)14042026/08/27 09:41:41 OK 2_object_stats_trigger.sql (218.83µs)14052026/08/27 09:41:41 goose: up to current file version: 214062026/08/27 09:41:41 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14072026/08/27 09:41:41 INFO Received uploads request method=POST path=/api/pending_closures14082026/08/27 09:41:41 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=014092026/08/27 09:41:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14102026/08/27 09:41:41 INFO Uploading ga0w4hfmy60jph4w5854vah6xmw64fh5-ca-test (144B)14112026/08/27 09:41:41 INFO Vacuumed table table=pending_closures14122026/08/27 09:41:41 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"14132026/08/27 09:41:41 WARN Failed to register uploaded object key=log/plas87shyzlxazamrhp4p719qwyyx5wk-ca-test.drv error="server returned 404: 404 page not found\n"14142026/08/27 09:41:41 INFO Vacuumed table table=pending_objects14152026/08/27 09:41:41 INFO Vacuumed table table=multipart_uploads14162026/08/27 09:41:41 WARN Failed to register uploaded object key=ga0w4hfmy60jph4w5854vah6xmw64fh5.ls error="server returned 404: 404 page not found\n"14172026/08/27 09:41:41 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14182026/08/27 09:41:41 INFO Signed narinfos id=1 count=114192026/08/27 09:41:41 INFO Uploading 1 narinfos14202026/08/27 09:41:41 INFO Vacuumed table table=closures14212026/08/27 09:41:41 WARN Failed to register uploaded object key=ga0w4hfmy60jph4w5854vah6xmw64fh5.narinfo error="server returned 404: 404 page not found\n"14222026/08/27 09:41:41 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14232026/08/27 09:41:41 INFO Vacuumed table table=objects14242026/08/27 09:41:41 INFO Completed upload id=114252026/08/27 09:41:41 INFO Upload complete. (292ms)1426 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-44679-95555299/TestClientCADerivations615320914/001/store/ga0w4hfmy60jph4w5854vah6xmw64fh5-ca-test1427 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1428 Compression: zstd1429 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1430 NarSize: 1441431 References: 1432 Deriver: /nix/var/nix/builds/nix-44679-95555299/TestClientCADerivations615320914/001/store/plas87shyzlxazamrhp4p719qwyyx5wk-ca-test.drv1433 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1434 client_ca_test.go:185: Checking for realisation files in S3...1435 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1436 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1437 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket37?endpoint=http://localhost:52341®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-44679-95555299/TestClientCADerivations615320914/001/store'1438 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11439--- PASS: TestClientCADerivations (3.27s)1440=== CONT TestParseSize1441--- PASS: TestParseSize (0.00s)1442=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info14432026/08/27 09:41:41 INFO Received uploads request method=POST path=/1444=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key14452026/08/27 09:41:41 INFO Received request for more parts method=POST path=/1446=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key14472026/08/27 09:41:41 INFO Received complete multipart upload request method=POST path=/1448=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal14492026/08/27 09:41:41 INFO Received uploads request method=POST path=/1450--- PASS: TestUploadHandlersRejectInvalidKeys (0.01s)1451 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1452 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1453 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1454 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1455=== CONT TestIsValidUploadKey/narinfo1456=== CONT TestIsValidUploadKey/realisation_plus_in_output1457=== CONT TestIsValidUploadKey/unknown_type1458=== CONT TestIsValidUploadKey/empty_key1459=== CONT TestIsValidUploadKey/absolute1460=== CONT TestIsValidUploadKey/traversal_nar1461=== CONT TestIsValidUploadKey/traversal1462=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1463=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1464=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1465=== CONT TestIsValidUploadKey/index.html1466=== CONT TestIsValidUploadKey/nix-cache-info1467=== CONT TestIsValidUploadKey/build_log_home-manager_file1468=== CONT TestIsValidUploadKey/realisation1469=== CONT TestIsValidUploadKey/build_log_equals1470=== CONT TestIsValidUploadKey/build_log_question_mark1471=== CONT TestIsValidUploadKey/build_log1472=== CONT TestIsValidUploadKey/listing1473=== CONT TestIsValidUploadKey/nar_plain1474=== CONT TestIsValidUploadKey/nar_xz1475=== CONT TestIsValidUploadKey/nar_zst1476=== CONT TestIsValidUploadKey/build_log_plus_in_name1477--- PASS: TestIsValidUploadKey (0.01s)1478 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1479 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1480 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1481 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1482 --- PASS: TestIsValidUploadKey/absolute (0.00s)1483 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1484 --- PASS: TestIsValidUploadKey/traversal (0.00s)1485 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1486 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1487 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1488 --- PASS: TestIsValidUploadKey/index.html (0.00s)1489 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1490 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1491 --- PASS: TestIsValidUploadKey/realisation (0.00s)1492 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1493 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1494 --- PASS: TestIsValidUploadKey/build_log (0.00s)1495 --- PASS: TestIsValidUploadKey/listing (0.00s)1496 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1497 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1498 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1499 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1500=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts15012026/08/27 09:41:41 INFO Received request for more parts method=POST path=/1502=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart15032026/08/27 09:41:41 INFO Received complete multipart upload request method=POST path=/1504=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure15052026/08/27 09:41:41 INFO Received uploads request method=POST path=/15062026-08-27 09:41:41.562 UTC [45100] ERROR: relation "goose_db_version" does not exist at character 3615072026-08-27 09:41:41.562 UTC [45100] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15082026-08-27 09:41:41.584 UTC [45101] ERROR: relation "goose_db_version" does not exist at character 3615092026-08-27 09:41:41.584 UTC [45101] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1510=== NAME TestClientWithDependencies1511 client_integration_test.go:593: Built derivation: /nix/var/nix/builds/nix-44679-95555299/TestClientWithDependencies4183608639/001/store/hd317bcwfc7fb5gmdysvw7ns1d7cvl04-test-script1512 client_integration_test.go:595: Found 1 dependencies (including self)15132026/08/27 09:41:41 OK 20241026095416_initial_model.sql (145.68ms)15142026/08/27 09:41:41 OK 20251210153512_drop_unused_gin_index.sql (4.58ms)15152026/08/27 09:41:41 OK 20241026095416_initial_model.sql (128.55ms)1516--- PASS: TestUploadHandlersRejectOversizedBody (0.03s)1517 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1518 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1519 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.28s)1520=== CONT TestIsValidCachePath/narinfo1521=== CONT TestIsValidCachePath/index.html1522=== CONT TestIsValidCachePath/short_hash1523=== CONT TestIsValidCachePath/wrong_extension1524=== CONT TestIsValidCachePath/leading_slash1525=== CONT TestIsValidCachePath/empty1526=== CONT TestIsValidCachePath/random_path1527=== CONT TestIsValidCachePath/invalid_char_u1528=== CONT TestIsValidCachePath/invalid_char_e1529=== CONT TestIsValidCachePath/traversal_in_middle1530=== CONT TestIsValidCachePath/traversal_parent1531=== CONT TestIsValidCachePath/nar_uncompressed1532=== CONT TestIsValidCachePath/nix-cache-info1533=== CONT TestIsValidCachePath/realisation1534=== CONT TestIsValidCachePath/log1535=== CONT TestIsValidCachePath/ls1536=== CONT TestIsValidCachePath/nar_xz1537=== CONT TestIsValidCachePath/nar_bz21538=== CONT TestIsValidCachePath/nar_zst1539=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1540--- PASS: TestIsValidCachePath (0.00s)1541 --- PASS: TestIsValidCachePath/narinfo (0.00s)1542 --- PASS: TestIsValidCachePath/index.html (0.00s)1543 --- PASS: TestIsValidCachePath/short_hash (0.00s)1544 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1545 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1546 --- PASS: TestIsValidCachePath/empty (0.00s)1547 --- PASS: TestIsValidCachePath/random_path (0.00s)1548 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1549 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1550 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1551 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1552 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1553 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1554 --- PASS: TestIsValidCachePath/realisation (0.00s)1555 --- PASS: TestIsValidCachePath/log (0.00s)1556 --- PASS: TestIsValidCachePath/ls (0.00s)1557 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1558 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1559 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1560 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1561=== CONT TestParseSingleRange/none1562=== CONT TestParseSingleRange/open-ended1563=== CONT TestParseSingleRange/start_far_past_EOF1564=== CONT TestParseSingleRange/start_past_EOF1565=== CONT TestParseSingleRange/single_byte1566=== CONT TestParseSingleRange/suffix_exceeds_size1567=== CONT TestParseSingleRange/suffix1568=== CONT TestParseSingleRange/end_clamped_to_size1569=== CONT TestParseSingleRange/malformed_both_empty1570=== CONT TestParseSingleRange/closed1571=== CONT TestParseSingleRange/malformed_end_before_start1572=== CONT TestParseSingleRange/multi-range_ignored1573=== CONT TestParseSingleRange/malformed_no_dash1574=== CONT TestParseSingleRange/unknown_unit1575--- PASS: TestParseSingleRange (0.00s)1576 --- PASS: TestParseSingleRange/none (0.00s)1577 --- PASS: TestParseSingleRange/open-ended (0.00s)1578 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1579 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1580 --- PASS: TestParseSingleRange/single_byte (0.00s)1581 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1582 --- PASS: TestParseSingleRange/suffix (0.00s)1583 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1584 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1585 --- PASS: TestParseSingleRange/closed (0.00s)1586 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1587 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1588 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1589 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1590=== CONT TestProxyWriteTimeout/narinfo1591=== CONT TestProxyWriteTimeout/10_GiB_nar1592=== CONT TestProxyWriteTimeout/unknown_size1593=== CONT TestProxyWriteTimeout/1_GiB_nar1594--- PASS: TestProxyWriteTimeout (0.00s)1595 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1596 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1597 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1598 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1599=== CONT TestServerTLSConfig/no_client_CA1600=== CONT TestServerTLSConfig/not_a_PEM_file16012026/08/27 09:41:41 OK 20251210153512_drop_unused_gin_index.sql (3.13ms)1602=== CONT TestServerTLSConfig/missing_CA_file1603--- PASS: TestServerTLSConfig (0.00s)1604 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1605 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1606 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1607=== CONT TestCacheConfigHandler/full_config,_no_issuer1608=== CONT TestCacheConfigHandler/no_signing_keys1609=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1610=== CONT TestCacheConfigHandler/no_cache_url_configured1611--- PASS: TestCacheConfigHandler (0.00s)1612 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1613 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1614 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1615 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1616=== CONT TestClientErrorHandling/InvalidStorePath16172026/08/27 09:41:41 OK 20251218171726_add_pins.sql (33.68ms)16182026/08/27 09:41:41 OK 20251218171726_add_pins.sql (28.73ms)16192026/08/27 09:41:41 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16202026/08/27 09:41:41 INFO Received uploads request method=POST path=/api/pending_closures16212026/08/27 09:41:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16222026/08/27 09:41:41 INFO Uploading hd317bcwfc7fb5gmdysvw7ns1d7cvl04-test-script (136B)16232026/08/27 09:41:41 OK 20260628120000_add_object_size_and_stats.sql (38.95ms)16242026/08/27 09:41:41 goose: successfully migrated database to version: 2026062812000016252026/08/27 09:41:41 OK 1_commit_pending_closure.sql (2.14ms)16262026/08/27 09:41:41 OK 2_object_stats_trigger.sql (229.13µs)16272026/08/27 09:41:41 goose: up to current file version: 216282026/08/27 09:41:41 OK 20260628120000_add_object_size_and_stats.sql (39.29ms)16292026/08/27 09:41:41 goose: successfully migrated database to version: 2026062812000016302026/08/27 09:41:41 OK 1_commit_pending_closure.sql (6.58ms)16312026/08/27 09:41:41 OK 2_object_stats_trigger.sql (226.67µs)16322026/08/27 09:41:41 goose: up to current file version: 216332026/08/27 09:41:41 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"16342026/08/27 09:41:41 WARN Failed to register uploaded object key=log/ckfyd94mdxs2hngmmfp564pa01350ay2-test-script.drv error="server returned 404: 404 page not found\n"16352026/08/27 09:41:41 WARN Failed to register uploaded object key=hd317bcwfc7fb5gmdysvw7ns1d7cvl04.ls error="server returned 404: 404 page not found\n"16362026/08/27 09:41:41 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16372026/08/27 09:41:41 INFO Signed narinfos id=1 count=116382026/08/27 09:41:41 INFO Uploading 1 narinfos16392026/08/27 09:41:41 WARN Failed to register uploaded object key=hd317bcwfc7fb5gmdysvw7ns1d7cvl04.narinfo error="server returned 404: 404 page not found\n"16402026/08/27 09:41:41 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16412026/08/27 09:41:41 INFO Completed upload id=116422026/08/27 09:41:41 INFO Upload complete. (221ms)1643=== NAME TestClientWithDependencies1644 client_integration_test.go:597: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-44679-95555299/TestClientWithDependencies4183608639/001/store) requires matching store prefix16452026-08-27 09:41:41.998 UTC [45110] ERROR: relation "goose_db_version" does not exist at character 3616462026-08-27 09:41:41.998 UTC [45110] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1647--- PASS: TestClientWithDependencies (2.79s)1648=== CONT TestClientErrorHandling/ServerNotAvailable16492026/08/27 09:41:42 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1650--- PASS: TestService_ReadAuthMiddleware (2.21s)1651=== CONT TestClientErrorHandling/InvalidAuthToken16522026/08/27 09:41:42 OK 20241026095416_initial_model.sql (185.86ms)16532026/08/27 09:41:42 OK 20251210153512_drop_unused_gin_index.sql (11.17ms)16542026/08/27 09:41:42 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01655=== NAME TestClientIntegration1656 client_integration_test.go:303: Objects in database after GC:1657 client_integration_test.go:303: Successfully deleted all objects with GC --force16582026/08/27 09:41:42 OK 20251218171726_add_pins.sql (55.34ms)16592026/08/27 09:41:42 OK 20260628120000_add_object_size_and_stats.sql (39.13ms)16602026/08/27 09:41:42 goose: successfully migrated database to version: 2026062812000016612026/08/27 09:41:42 OK 1_commit_pending_closure.sql (3.65ms)16622026/08/27 09:41:42 OK 2_object_stats_trigger.sql (608.88µs)16632026/08/27 09:41:42 goose: up to current file version: 21664=== NAME TestClientMultipleUploads1665 client_integration_test.go:338: Created store path 0: /nix/var/nix/builds/nix-44679-95555299/TestClientMultipleUploads2807628807/001/store/ndcqf61hi09ygnszaj5lgak29wywriap-test-file-0.txt1666--- PASS: TestClientIntegration (5.44s)16672026-08-27 09:41:42.448 UTC [45117] ERROR: relation "goose_db_version" does not exist at character 3616682026-08-27 09:41:42.448 UTC [45117] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16692026/08/27 09:41:42 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-config1670=== NAME TestClientMultipleUploads1671 client_integration_test.go:338: Created store path 1: /nix/var/nix/builds/nix-44679-95555299/TestClientMultipleUploads2807628807/001/store/4f261ch8x38i6lygpwbx5xky5lv31k6k-test-file-1.txt1672=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1673=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1674=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1675=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1676=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1677=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1678=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1679=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1680=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1681=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected16822026/08/27 09:41:42 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]1683=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected16842026/08/27 09:41:42 INFO OIDC auth successful provider=test1685=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured16862026/08/27 09:41:42 WARN Authentication failed token_preview=eyJhbGciOi..._RtJArum2g token_length=702 oidc_error="bound claims validation failed: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1687--- PASS: TestService_AuthMiddleware_OIDC (2.24s)1688 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1689 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1690 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1691 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1692=== NAME TestClientMultipleUploads1693 client_integration_test.go:338: Created store path 2: /nix/var/nix/builds/nix-44679-95555299/TestClientMultipleUploads2807628807/001/store/pdlsshm1cap58wyb2ig3cwi926b18d9v-test-file-2.txt16942026/08/27 09:41:42 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=185.094371ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config16952026-08-27 09:41:42.604 UTC [45126] ERROR: relation "goose_db_version" does not exist at character 3616962026-08-27 09:41:42.604 UTC [45126] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16972026/08/27 09:41:42 OK 20241026095416_initial_model.sql (103.51ms)16982026/08/27 09:41:42 OK 20251210153512_drop_unused_gin_index.sql (8.51ms)16992026/08/27 09:41:42 OK 20251218171726_add_pins.sql (16.76ms)17002026/08/27 09:41:42 OK 20260628120000_add_object_size_and_stats.sql (17.76ms)17012026/08/27 09:41:42 goose: successfully migrated database to version: 2026062812000017022026/08/27 09:41:42 OK 1_commit_pending_closure.sql (5.4ms)17032026/08/27 09:41:42 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17042026/08/27 09:41:42 OK 2_object_stats_trigger.sql (240.17µs)17052026/08/27 09:41:42 goose: up to current file version: 217062026/08/27 09:41:42 INFO Received uploads request method=POST path=/api/pending_closures17072026/08/27 09:41:42 INFO Received uploads request method=POST path=/api/pending_closures17082026/08/27 09:41:42 INFO Received uploads request method=POST path=/api/pending_closures17092026/08/27 09:41:42 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)17102026/08/27 09:41:42 INFO Uploading pdlsshm1cap58wyb2ig3cwi926b18d9v-test-file-2.txt (160B)17112026/08/27 09:41:42 INFO Uploading ndcqf61hi09ygnszaj5lgak29wywriap-test-file-0.txt (160B)17122026/08/27 09:41:42 INFO Uploading 4f261ch8x38i6lygpwbx5xky5lv31k6k-test-file-1.txt (160B)17132026/08/27 09:41:42 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=415.692391ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17142026/08/27 09:41:42 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"17152026/08/27 09:41:42 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"17162026/08/27 09:41:42 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"17172026/08/27 09:41:42 OK 20241026095416_initial_model.sql (164.17ms)17182026/08/27 09:41:42 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"17192026/08/27 09:41:42 WARN mTLS auth: bound subjects configured but subject DN unavailable17202026/08/27 09:41:42 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1721--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.11s)17222026/08/27 09:41:42 OK 20251210153512_drop_unused_gin_index.sql (17.32ms)17232026/08/27 09:41:42 WARN Failed to register uploaded object key=4f261ch8x38i6lygpwbx5xky5lv31k6k.ls error="server returned 404: 404 page not found\n"17242026/08/27 09:41:42 WARN Failed to register uploaded object key=pdlsshm1cap58wyb2ig3cwi926b18d9v.ls error="server returned 404: 404 page not found\n"17252026/08/27 09:41:42 WARN Failed to register uploaded object key=ndcqf61hi09ygnszaj5lgak29wywriap.ls error="server returned 404: 404 page not found\n"17262026/08/27 09:41:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign17272026/08/27 09:41:42 INFO Signed narinfos id=2 count=117282026/08/27 09:41:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign17292026/08/27 09:41:42 INFO Signed narinfos id=3 count=117302026/08/27 09:41:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17312026/08/27 09:41:42 INFO Signed narinfos id=1 count=117322026/08/27 09:41:42 INFO Uploading 3 narinfos17332026/08/27 09:41:42 OK 20251218171726_add_pins.sql (39.33ms)17342026/08/27 09:41:42 WARN Failed to register uploaded object key=ndcqf61hi09ygnszaj5lgak29wywriap.narinfo error="server returned 404: 404 page not found\n"17352026/08/27 09:41:42 WARN Failed to register uploaded object key=4f261ch8x38i6lygpwbx5xky5lv31k6k.narinfo error="server returned 404: 404 page not found\n"17362026/08/27 09:41:42 OK 20260628120000_add_object_size_and_stats.sql (39.58ms)17372026/08/27 09:41:42 goose: successfully migrated database to version: 2026062812000017382026/08/27 09:41:42 WARN Failed to register uploaded object key=pdlsshm1cap58wyb2ig3cwi926b18d9v.narinfo error="server returned 404: 404 page not found\n"17392026/08/27 09:41:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17402026/08/27 09:41:42 OK 1_commit_pending_closure.sql (6.74ms)17412026/08/27 09:41:42 OK 2_object_stats_trigger.sql (542.13µs)17422026/08/27 09:41:42 goose: up to current file version: 217432026/08/27 09:41:42 INFO Completed upload id=117442026/08/27 09:41:42 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17452026/08/27 09:41:42 INFO Completed upload id=217462026/08/27 09:41:42 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete17472026/08/27 09:41:42 INFO Completed upload id=317482026/08/27 09:41:42 INFO Upload complete. (303ms)1749=== NAME TestClientMultipleUploads1750 client_integration_test.go:349: Uploaded 3 paths in 334.669708ms17512026/08/27 09:41:42 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01752=== NAME TestPinProtectsFromGC1753 client_integration_test.go:709: Pin successfully protected closure from garbage collection1754--- PASS: TestClientMultipleUploads (3.08s)1755--- PASS: TestPinProtectsFromGC (5.46s)1756--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (2.26s)17572026/08/27 09:41:43 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=808.710935ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17582026-08-27 09:41:43.451 UTC [45147] ERROR: relation "goose_db_version" does not exist at character 3617592026-08-27 09:41:43.451 UTC [45147] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17602026/08/27 09:41:43 OK 20241026095416_initial_model.sql (140.46ms)17612026/08/27 09:41:43 OK 20251210153512_drop_unused_gin_index.sql (10.4ms)17622026/08/27 09:41:43 OK 20251218171726_add_pins.sql (14.5ms)17632026/08/27 09:41:43 OK 20260628120000_add_object_size_and_stats.sql (23.82ms)17642026/08/27 09:41:43 goose: successfully migrated database to version: 2026062812000017652026/08/27 09:41:43 OK 1_commit_pending_closure.sql (6.24ms)17662026/08/27 09:41:43 OK 2_object_stats_trigger.sql (457.25µs)17672026/08/27 09:41:43 goose: up to current file version: 217682026-08-27 09:41:43.841 UTC [45213] ERROR: relation "goose_db_version" does not exist at character 3617692026-08-27 09:41:43.841 UTC [45213] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17702026/08/27 09:41:43 OK 20241026095416_initial_model.sql (59.45ms)17712026/08/27 09:41:43 OK 20251210153512_drop_unused_gin_index.sql (6.26ms)17722026/08/27 09:41:43 OK 20251218171726_add_pins.sql (9.53ms)1773=== NAME TestOrphanedObjectsGCStressTest1774 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains17752026/08/27 09:41:43 OK 20260628120000_add_object_size_and_stats.sql (14.19ms)17762026/08/27 09:41:43 goose: successfully migrated database to version: 2026062812000017772026/08/27 09:41:43 OK 1_commit_pending_closure.sql (6.36ms)17782026/08/27 09:41:43 OK 2_object_stats_trigger.sql (343.67µs)17792026/08/27 09:41:43 goose: up to current file version: 21780 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion17812026/08/27 09:41:44 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.476186828s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17822026/08/27 09:41:44 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17832026/08/27 09:41:44 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"1784 orphaned_objects_gc_test.go:509: Stress test completed successfully:1785 orphaned_objects_gc_test.go:510: - Active objects preserved: 201786 orphaned_objects_gc_test.go:511: - Objects deleted: 2101787 orphaned_objects_gc_test.go:512: - Total GC'd: 2101788--- PASS: TestOrphanedObjectsGCStressTest (11.59s)17892026/08/27 09:41:45 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"17902026/08/27 09:41:45 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_closures17912026/08/27 09:41:45 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=188.492876ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures17922026/08/27 09:41:45 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=392.641235ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures17932026/08/27 09:41:46 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=849.234494ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures17942026/08/27 09:41:47 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.559501665s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1795--- PASS: TestClientErrorHandling (0.00s)1796 --- PASS: TestClientErrorHandling/InvalidStorePath (2.11s)1797 --- PASS: TestClientErrorHandling/InvalidAuthToken (2.19s)1798 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.66s)1799PASS1800{"timestamp":"2026-08-27T09:41:48.7529Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:52476","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1836,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}18012026-08-27 09:41:51.990 UTC [44734] LOG: received smart shutdown request18022026-08-27 09:41:51.993 UTC [44734] LOG: background worker "logical replication launcher" (PID 44750) exited with exit code 118032026-08-27 09:41:52.162 UTC [44743] LOG: shutting down18042026-08-27 09:41:52.168 UTC [44743] LOG: checkpoint starting: shutdown immediate18052026/08/27 09:41:58 ERROR failed to kill rustfs error="no such process"18062026-08-27 09:41:59.187 UTC [44743] LOG: checkpoint complete: wrote 13296 buffers (81.2%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 13 recycled; write=5.234 s, sync=1.710 s, total=7.026 s; sync files=15167, longest=0.010 s, average=0.001 s; distance=212548 kB, estimate=212548 kB; lsn=0/E71C158, redo lsn=0/E71C15818072026-08-27 09:41:59.256 UTC [44734] LOG: database system is shut down18082026/08/27 09:42:01 ERROR failed to kill rustfs error="no such process"1809Running OIDC tests...1810=== RUN TestGlobMatch1811=== PAUSE TestGlobMatch1812=== RUN TestAudienceForIssuer1813=== PAUSE TestAudienceForIssuer1814=== RUN TestValidateToken_ValidToken1815=== PAUSE TestValidateToken_ValidToken1816=== RUN TestValidateToken_WrongAudience1817=== PAUSE TestValidateToken_WrongAudience1818=== RUN TestValidateToken_Expired1819=== PAUSE TestValidateToken_Expired1820=== RUN TestValidateToken_BoundClaimsMismatch1821=== PAUSE TestValidateToken_BoundClaimsMismatch1822=== RUN TestValidateToken_BoundSubjectMismatch1823=== PAUSE TestValidateToken_BoundSubjectMismatch1824=== RUN TestValidateToken_MultipleProviders1825=== PAUSE TestValidateToken_MultipleProviders1826=== RUN TestValidateToken_NoMatchingProvider1827=== PAUSE TestValidateToken_NoMatchingProvider1828=== CONT TestGlobMatch1829=== RUN TestGlobMatch/foo_foo1830=== PAUSE TestGlobMatch/foo_foo1831=== RUN TestGlobMatch/foo_bar1832=== PAUSE TestGlobMatch/foo_bar1833=== RUN TestGlobMatch/*_1834=== PAUSE TestGlobMatch/*_1835=== RUN TestGlobMatch/*_anything1836=== CONT TestValidateToken_Expired1837=== PAUSE TestGlobMatch/*_anything1838=== CONT TestValidateToken_ValidToken1839=== RUN TestGlobMatch/foo*_foo1840=== PAUSE TestGlobMatch/foo*_foo1841=== RUN TestGlobMatch/foo*_foobar1842=== PAUSE TestGlobMatch/foo*_foobar1843=== RUN TestGlobMatch/foo*_bar1844=== PAUSE TestGlobMatch/foo*_bar1845=== RUN TestGlobMatch/*bar_bar1846=== PAUSE TestGlobMatch/*bar_bar1847=== RUN TestGlobMatch/*bar_foobar1848=== PAUSE TestGlobMatch/*bar_foobar1849=== RUN TestGlobMatch/*bar_foo1850=== PAUSE TestGlobMatch/*bar_foo1851=== RUN TestGlobMatch/foo*bar_foobar1852=== PAUSE TestGlobMatch/foo*bar_foobar1853=== RUN TestGlobMatch/foo*bar_foo123bar1854=== PAUSE TestGlobMatch/foo*bar_foo123bar1855=== RUN TestGlobMatch/foo*bar_foobarbaz1856=== PAUSE TestGlobMatch/foo*bar_foobarbaz1857=== RUN TestGlobMatch/*/*_foo/bar1858=== PAUSE TestGlobMatch/*/*_foo/bar1859=== RUN TestGlobMatch/*/*_foo1860=== PAUSE TestGlobMatch/*/*_foo1861=== RUN TestGlobMatch/refs/heads/*_refs/heads/main1862=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main1863=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.01864=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.01865=== RUN TestGlobMatch/refs/*/main_refs/heads/main1866=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main1867=== CONT TestValidateToken_WrongAudience1868=== CONT TestAudienceForIssuer1869--- PASS: TestAudienceForIssuer (0.00s)1870=== CONT TestValidateToken_BoundSubjectMismatch1871=== CONT TestValidateToken_MultipleProviders1872=== CONT TestValidateToken_BoundClaimsMismatch1873=== CONT TestValidateToken_NoMatchingProvider1874=== RUN TestGlobMatch/fo?_foo1875=== PAUSE TestGlobMatch/fo?_foo1876=== RUN TestGlobMatch/fo?_fo1877=== PAUSE TestGlobMatch/fo?_fo1878=== RUN TestGlobMatch/fo?_fooo1879=== PAUSE TestGlobMatch/fo?_fooo1880=== RUN TestGlobMatch/?oo_foo1881=== PAUSE TestGlobMatch/?oo_foo1882=== RUN TestGlobMatch/?oo_boo1883=== PAUSE TestGlobMatch/?oo_boo1884=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1885=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1886=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1887=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1888=== CONT TestGlobMatch/foo_foo1889=== CONT TestGlobMatch/*/*_foo/bar1890=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1891=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1892=== CONT TestGlobMatch/?oo_boo1893=== CONT TestGlobMatch/?oo_foo1894=== CONT TestGlobMatch/fo?_fooo1895=== CONT TestGlobMatch/fo?_fo1896=== CONT TestGlobMatch/fo?_foo1897=== CONT TestGlobMatch/refs/*/main_refs/heads/main1898=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.01899=== CONT TestGlobMatch/refs/heads/*_refs/heads/main1900=== CONT TestGlobMatch/*/*_foo1901=== CONT TestGlobMatch/*bar_bar1902=== CONT TestGlobMatch/foo*bar_foobarbaz1903=== CONT TestGlobMatch/foo*bar_foo123bar1904=== CONT TestGlobMatch/foo*bar_foobar1905=== CONT TestGlobMatch/*bar_foo1906=== CONT TestGlobMatch/*bar_foobar1907=== CONT TestGlobMatch/foo*_foo1908=== CONT TestGlobMatch/foo*_bar1909=== CONT TestGlobMatch/foo*_foobar1910=== CONT TestGlobMatch/*_1911=== CONT TestGlobMatch/*_anything1912=== CONT TestGlobMatch/foo_bar1913--- PASS: TestGlobMatch (0.00s)1914 --- PASS: TestGlobMatch/foo_foo (0.00s)1915 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)1916 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)1917 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)1918 --- PASS: TestGlobMatch/?oo_boo (0.00s)1919 --- PASS: TestGlobMatch/?oo_foo (0.00s)1920 --- PASS: TestGlobMatch/fo?_fooo (0.00s)1921 --- PASS: TestGlobMatch/fo?_fo (0.00s)1922 --- PASS: TestGlobMatch/fo?_foo (0.00s)1923 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)1924 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)1925 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)1926 --- PASS: TestGlobMatch/*/*_foo (0.00s)1927 --- PASS: TestGlobMatch/*bar_bar (0.00s)1928 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)1929 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)1930 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)1931 --- PASS: TestGlobMatch/*bar_foo (0.00s)1932 --- PASS: TestGlobMatch/*bar_foobar (0.00s)1933 --- PASS: TestGlobMatch/foo*_foo (0.00s)1934 --- PASS: TestGlobMatch/foo*_bar (0.00s)1935 --- PASS: TestGlobMatch/foo*_foobar (0.00s)1936 --- PASS: TestGlobMatch/*_ (0.00s)1937 --- PASS: TestGlobMatch/*_anything (0.00s)1938 --- PASS: TestGlobMatch/foo_bar (0.00s)19392026/08/27 09:42:03 INFO OIDC provider initialized name=test19402026/08/27 09:42:03 INFO OIDC provider initialized name=test19412026/08/27 09:42:03 INFO OIDC provider initialized name=provider119422026/08/27 09:42:03 INFO OIDC provider initialized name=test19432026/08/27 09:42:03 INFO OIDC provider initialized name=test19442026/08/27 09:42:03 INFO OIDC provider initialized name=provider119452026/08/27 09:42:03 INFO OIDC provider initialized name=test19462026/08/27 09:42:03 INFO OIDC provider initialized name=provider21947--- PASS: TestValidateToken_NoMatchingProvider (0.00s)1948--- PASS: TestValidateToken_BoundClaimsMismatch (0.00s)1949--- PASS: TestValidateToken_ValidToken (0.00s)1950--- PASS: TestValidateToken_WrongAudience (0.00s)1951--- PASS: TestValidateToken_Expired (0.00s)1952--- PASS: TestValidateToken_BoundSubjectMismatch (0.00s)1953--- PASS: TestValidateToken_MultipleProviders (0.00s)1954PASS1955Running hook tests...1956=== RUN TestSendPathsEmpty1957=== PAUSE TestSendPathsEmpty1958=== RUN TestQueueEnqueueAndFetch1959=== PAUSE TestQueueEnqueueAndFetch1960=== RUN TestQueueDeduplication1961=== PAUSE TestQueueDeduplication1962=== RUN TestQueueRemove1963=== PAUSE TestQueueRemove1964=== RUN TestQueueFetchBatchLimit1965=== PAUSE TestQueueFetchBatchLimit1966=== RUN TestQueueRetryMovesToBack1967=== PAUSE TestQueueRetryMovesToBack1968=== RUN TestQueueFetchRemoveLifecycle1969=== PAUSE TestQueueFetchRemoveLifecycle1970=== RUN TestQueueConcurrentWriters1971=== PAUSE TestQueueConcurrentWriters1972=== RUN TestQueueRemoveLargeClosure1973=== PAUSE TestQueueRemoveLargeClosure1974=== RUN TestServerClientIntegration1975=== PAUSE TestServerClientIntegration1976=== RUN TestServerQueueError1977=== PAUSE TestServerQueueError1978=== RUN TestGetListenerSocketActivation1979 server_test.go:210: === RUN TestGetListenerSocketActivation1980 --- PASS: TestGetListenerSocketActivation (0.00s)1981 PASS1982 1983--- PASS: TestGetListenerSocketActivation (0.01s)1984=== RUN TestDrainIsolatesPoisonPath1985=== PAUSE TestDrainIsolatesPoisonPath1986=== RUN TestRunNotBlockedByPoisonHead1987=== PAUSE TestRunNotBlockedByPoisonHead1988=== RUN TestDrainGivesUpWhenServerDown1989=== PAUSE TestDrainGivesUpWhenServerDown1990=== RUN TestFailedPathPrunedByLaterClosure1991=== PAUSE TestFailedPathPrunedByLaterClosure1992=== RUN TestWorkerUploadsAndRemoves1993=== PAUSE TestWorkerUploadsAndRemoves1994=== RUN TestWorkerSkipsGCdPaths1995=== PAUSE TestWorkerSkipsGCdPaths1996=== RUN TestWorkerPrunesClosureDeps1997=== PAUSE TestWorkerPrunesClosureDeps1998=== CONT TestSendPathsEmpty1999--- PASS: TestSendPathsEmpty (0.00s)2000=== CONT TestServerClientIntegration2001=== CONT TestQueueRetryMovesToBack2002=== CONT TestQueueFetchBatchLimit2003=== CONT TestQueueRemove2004=== CONT TestQueueDeduplication2005=== CONT TestQueueEnqueueAndFetch2006=== CONT TestFailedPathPrunedByLaterClosure2007=== CONT TestWorkerPrunesClosureDeps2008=== CONT TestWorkerSkipsGCdPaths2009=== CONT TestWorkerUploadsAndRemoves2010--- PASS: TestServerClientIntegration (0.00s)2011=== CONT TestQueueConcurrentWriters20122026/08/27 09:42:03 INFO Upload queue status pending=220132026/08/27 09:42:03 INFO Uploading batch count=220142026/08/27 09:42:03 INFO Uploading batch count=120152026/08/27 09:42:03 ERROR Upload failed error="upload failed" count=120162026/08/27 09:42:03 INFO Upload queue status pending=220172026/08/27 09:42:03 INFO Uploading batch count=12018--- PASS: TestQueueEnqueueAndFetch (0.00s)2019=== CONT TestQueueRemoveLargeClosure20202026/08/27 09:42:03 INFO Uploading batch count=120212026/08/27 09:42:03 INFO Upload queue status pending=220222026/08/27 09:42:03 INFO Uploading batch count=12023--- PASS: TestQueueFetchBatchLimit (0.01s)2024=== CONT TestRunNotBlockedByPoisonHead20252026/08/27 09:42:03 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-44679-95555299/TestWorkerSkipsGCdPaths3723401184/002/nonexistent20262026/08/27 09:42:03 INFO Uploading batch count=12027--- PASS: TestQueueDeduplication (0.01s)2028=== CONT TestDrainGivesUpWhenServerDown2029--- PASS: TestQueueRetryMovesToBack (0.01s)2030=== CONT TestQueueFetchRemoveLifecycle2031--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)2032=== CONT TestDrainIsolatesPoisonPath2033--- PASS: TestQueueRemove (0.01s)2034=== CONT TestServerQueueError20352026/08/27 09:42:03 ERROR Failed to queue paths error="permission denied" count=12036--- PASS: TestServerQueueError (0.00s)20372026/08/27 09:42:03 INFO Upload queue status pending=320382026/08/27 09:42:03 INFO Uploading batch count=120392026/08/27 09:42:03 ERROR Upload failed error="upload failed" count=120402026/08/27 09:42:03 INFO Uploading batch count=220412026/08/27 09:42:03 ERROR Upload failed error="upload failed" count=220422026/08/27 09:42:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-44679-95555299/TestDrainGivesUpWhenServerDown963692644/002/a2043--- PASS: TestQueueFetchRemoveLifecycle (0.00s)20442026/08/27 09:42:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-44679-95555299/TestDrainGivesUpWhenServerDown963692644/002/b20452026/08/27 09:42:03 INFO Uploading batch count=420462026/08/27 09:42:03 ERROR Upload failed error="upload failed" count=420472026/08/27 09:42:03 INFO Uploading batch count=220482026/08/27 09:42:03 ERROR Upload failed error="upload failed" count=220492026/08/27 09:42:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-44679-95555299/TestDrainGivesUpWhenServerDown963692644/002/c20502026/08/27 09:42:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-44679-95555299/TestDrainIsolatesPoisonPath1133226649/002/bbb20512026/08/27 09:42:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-44679-95555299/TestDrainGivesUpWhenServerDown963692644/002/d20522026/08/27 09:42:03 INFO Uploading batch count=220532026/08/27 09:42:03 ERROR Upload failed error="upload failed" count=220542026/08/27 09:42:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-44679-95555299/TestDrainGivesUpWhenServerDown963692644/002/e20552026/08/27 09:42:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-44679-95555299/TestDrainGivesUpWhenServerDown963692644/002/f20562026/08/27 09:42:03 INFO Uploading batch count=120572026/08/27 09:42:03 ERROR Upload failed error="upload failed" count=120582026/08/27 09:42:03 ERROR Drain finished with paths left in queue remaining=1020592026/08/27 09:42:03 INFO Uploading batch count=120602026/08/27 09:42:03 ERROR Upload failed error="upload failed" count=120612026/08/27 09:42:03 INFO Uploading batch count=120622026/08/27 09:42:03 ERROR Upload failed error="upload failed" count=120632026/08/27 09:42:03 ERROR Drain finished with paths left in queue remaining=12064--- PASS: TestDrainGivesUpWhenServerDown (0.00s)2065--- PASS: TestDrainIsolatesPoisonPath (0.00s)2066--- PASS: TestWorkerUploadsAndRemoves (0.03s)2067--- PASS: TestWorkerSkipsGCdPaths (0.03s)2068--- PASS: TestWorkerPrunesClosureDeps (0.03s)2069--- PASS: TestQueueRemoveLargeClosure (0.04s)2070--- PASS: TestQueueConcurrentWriters (0.15s)20712026/08/27 09:42:04 INFO Uploading batch count=120722026/08/27 09:42:04 INFO Uploading batch count=120732026/08/27 09:42:04 INFO Uploading batch count=120742026/08/27 09:42:04 ERROR Upload failed error="upload failed" count=120752026/08/27 09:42:04 INFO Uploading batch count=120762026/08/27 09:42:04 ERROR Upload failed error="upload failed" count=120772026/08/27 09:42:04 INFO Uploading batch count=120782026/08/27 09:42:04 ERROR Upload failed error="upload failed" count=120792026/08/27 09:42:04 INFO Uploading batch count=120802026/08/27 09:42:04 ERROR Upload failed error="upload failed" count=120812026/08/27 09:42:04 ERROR Drain finished with paths left in queue remaining=12082--- PASS: TestRunNotBlockedByPoisonHead (1.02s)2083PASS