niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #138
· 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 TestEncodeNixBase32WithRealHash74=== CONT TestResolveStorePath75--- PASS: TestEncodeNixBase32WithRealHash (0.00s)76=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess77=== CONT TestFileTokenMissing78=== CONT TestPathInfoHashCompatibility79=== CONT TestScriptTokenEmptyToken80=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)81=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)82=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon83=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon84=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI85=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI86=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha51287=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha51288=== CONT TestPathInfoCACompatibility89=== RUN TestPathInfoCACompatibility/null_ca_field90=== PAUSE TestPathInfoCACompatibility/null_ca_field91=== RUN TestPathInfoCACompatibility/old_string_format_-_text92=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text93=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive94=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive95=== RUN TestPathInfoCACompatibility/new_structured_format_-_text96=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text97=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method98=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method99=== CONT TestParsePathInfoJSONMultiplePaths100=== CONT TestConvertHashToNix32101=== RUN TestConvertHashToNix32/SRI_format_to_Nix32102=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32103=== RUN TestConvertHashToNix32/already_Nix32_format104=== PAUSE TestConvertHashToNix32/already_Nix32_format105=== RUN TestConvertHashToNix32/invalid_format106=== PAUSE TestConvertHashToNix32/invalid_format107=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths108=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths109=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths110=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths111=== CONT TestFileTokenReadsAndCaches1122026/08/27 09:15:42 WARN Rate limiter enabled after throttle name=server-test rate=5113=== CONT TestParsePathInfoJSON114=== RUN TestParsePathInfoJSON/Nix_format115=== PAUSE TestParsePathInfoJSON/Nix_format116=== RUN TestParsePathInfoJSON/Lix_format117=== PAUSE TestParsePathInfoJSON/Lix_format118--- PASS: TestFileTokenMissing (0.00s)119=== CONT TestSetClientTLSErrors120=== CONT TestSetClientTLSDoesNotMutateDefaultTransport121=== CONT TestRateLimiterFeedback122=== RUN TestRateLimiterFeedback/429_enables_limiter123=== PAUSE TestRateLimiterFeedback/429_enables_limiter124=== RUN TestRateLimiterFeedback/503_enables_limiter125=== PAUSE TestRateLimiterFeedback/503_enables_limiter126=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter127=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter128=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter129=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter130=== CONT TestScriptTokenScriptFails131=== RUN TestParsePathInfoJSON/empty_input132=== CONT TestStaticToken133--- PASS: TestStaticToken (0.00s)134=== CONT TestScriptTokenEmptyCommand135=== PAUSE TestParsePathInfoJSON/empty_input136--- PASS: TestScriptTokenEmptyCommand (0.00s)137=== CONT TestScriptTokenBadJSON138=== RUN TestParsePathInfoJSON/whitespace_only139=== PAUSE TestParsePathInfoJSON/whitespace_only140=== RUN TestParsePathInfoJSON/invalid_JSON141=== PAUSE TestParsePathInfoJSON/invalid_JSON142=== CONT TestShellSplitErrors143--- PASS: TestShellSplitErrors (0.00s)144=== CONT TestSetClientTLS145--- PASS: TestDoServerRequestAttachesToken (0.01s)146=== CONT TestDumpPathMatchesNix147--- PASS: TestFileTokenReadsAndCaches (0.01s)148=== CONT TestEncodeNixBase32149=== RUN TestEncodeNixBase32/test_string_hash150=== PAUSE TestEncodeNixBase32/test_string_hash151=== RUN TestEncodeNixBase32/empty_input152=== PAUSE TestEncodeNixBase32/empty_input153=== CONT TestDumpPathWriterError154=== RUN TestSetClientTLSErrors/missing_cert_file155=== PAUSE TestSetClientTLSErrors/missing_cert_file156=== RUN TestSetClientTLSErrors/missing_key_file157=== PAUSE TestSetClientTLSErrors/missing_key_file158=== RUN TestSetClientTLSErrors/missing_ca_file159=== PAUSE TestSetClientTLSErrors/missing_ca_file160=== RUN TestSetClientTLSErrors/invalid_ca_file161=== PAUSE TestSetClientTLSErrors/invalid_ca_file162=== CONT TestDumpPathSingleFile163--- PASS: TestResolveStorePath (0.01s)164=== CONT TestScriptTokenNoExpiryRerunsEveryCall165--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)166=== CONT TestScriptTokenCachesUntilRefresh167=== RUN TestSetClientTLS/rejects_connection_without_client_cert168=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert169=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA170=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA171=== RUN TestSetClientTLS/preserves_debug_logging_transport172=== PAUSE TestSetClientTLS/preserves_debug_logging_transport173=== CONT TestFileTokenEmpty174--- PASS: TestFileTokenEmpty (0.00s)175=== CONT TestShellSplit176--- PASS: TestScriptTokenScriptFails (0.01s)177=== CONT TestPartSizeForNAR178=== RUN TestPartSizeForNAR/zero_stays_at_minimum179=== CONT TestUploadMultipart_SupersededByPeer180=== RUN TestUploadMultipart_SupersededByPeer/exists181=== PAUSE TestUploadMultipart_SupersededByPeer/exists182--- PASS: TestShellSplit (0.00s)183=== RUN TestUploadMultipart_SupersededByPeer/missing184=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum185=== PAUSE TestUploadMultipart_SupersededByPeer/missing186=== RUN TestPartSizeForNAR/small_stays_at_minimum187=== PAUSE TestPartSizeForNAR/small_stays_at_minimum188=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum189=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum190=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts191=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts192=== RUN TestPartSizeForNAR/1_TiB193=== PAUSE TestPartSizeForNAR/1_TiB194=== RUN TestPartSizeForNAR/5_TiB_S3_max_object195=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object196=== RUN TestPartSizeForNAR/capped_at_5_GiB197=== PAUSE TestPartSizeForNAR/capped_at_5_GiB198=== CONT TestFilterOversizedClosures199=== RUN TestFilterOversizedClosures/no_limit_keeps_everything200=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything201=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped202=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped203=== RUN TestFilterOversizedClosures/all_closures_skipped204=== CONT TestDoWithRetry_BodyReplayedViaGetBody205=== PAUSE TestFilterOversizedClosures/all_closures_skipped206=== CONT TestCaseHackSuffix2072026/08/27 09:15:42 WARN Rate limiter enabled after throttle name=server-test rate=52082026/08/27 09:15:42 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:500332092026/08/27 09:15:42 WARN Rate limiter backed off name=server-test rate=52102026/08/27 09:15:42 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:50033211--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)212=== CONT TestGetStorePathHash213=== RUN TestGetStorePathHash/valid_store_path214=== PAUSE TestGetStorePathHash/valid_store_path215=== RUN TestGetStorePathHash/basename_without_hyphen_should_error216=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error217=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error218=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error219=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error220=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error221=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)222=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI223=== CONT TestPathInfoCACompatibility/null_ca_field224=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon225=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method226=== CONT TestPathInfoCACompatibility/new_structured_format_-_text227=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive228=== CONT TestPathInfoCACompatibility/old_string_format_-_text229--- PASS: TestPathInfoCACompatibility (0.00s)230 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)231 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)232 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)233 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)234 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)235=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512236--- PASS: TestPathInfoHashCompatibility (0.00s)237 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)238 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)239 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)240 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)241=== CONT TestConvertHashToNix32/SRI_format_to_Nix32242=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths243=== CONT TestConvertHashToNix32/already_Nix32_format244=== CONT TestRateLimiterFeedback/429_enables_limiter2452026/08/27 09:15:42 WARN Rate limiter enabled after throttle name=server-test rate=52462026/08/27 09:15:42 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:500352472026/08/27 09:15:42 WARN Rate limiter backed off name=server-test rate=5248=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter249=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter250=== CONT TestConvertHashToNix32/invalid_format251--- PASS: TestConvertHashToNix32 (0.00s)252 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)253 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)254 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)255=== CONT TestRateLimiterFeedback/503_enables_limiter2562026/08/27 09:15:42 WARN Rate limiter enabled after throttle name=server-test rate=52572026/08/27 09:15:42 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:500412582026/08/27 09:15:42 WARN Rate limiter backed off name=server-test rate=5259--- PASS: TestRateLimiterFeedback (0.00s)260 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)261 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)262 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)263 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)264=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths265--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)266 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)267 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)268=== CONT TestParsePathInfoJSON/Nix_format269=== CONT TestParsePathInfoJSON/whitespace_only270=== CONT TestParsePathInfoJSON/invalid_JSON271=== CONT TestParsePathInfoJSON/empty_input272=== CONT TestParsePathInfoJSON/Lix_format273--- PASS: TestParsePathInfoJSON (0.00s)274 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)275 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)276 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)277 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)278 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)279=== CONT TestEncodeNixBase32/test_string_hash280=== CONT TestEncodeNixBase32/empty_input281--- PASS: TestEncodeNixBase32 (0.00s)282 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)283 --- PASS: TestEncodeNixBase32/empty_input (0.00s)284=== CONT TestSetClientTLSErrors/missing_cert_file285=== CONT TestSetClientTLSErrors/missing_ca_file286=== CONT TestSetClientTLSErrors/invalid_ca_file287=== CONT TestSetClientTLSErrors/missing_key_file288=== CONT TestSetClientTLS/rejects_connection_without_client_cert289--- PASS: TestScriptTokenEmptyToken (0.02s)290=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA291--- PASS: TestScriptTokenBadJSON (0.02s)292=== CONT TestSetClientTLS/preserves_debug_logging_transport293--- PASS: TestSetClientTLSErrors (0.01s)294 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)295 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)296 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)297 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)298=== CONT TestUploadMultipart_SupersededByPeer/exists299=== CONT TestUploadMultipart_SupersededByPeer/missing300=== CONT TestPartSizeForNAR/zero_stays_at_minimum301=== CONT TestPartSizeForNAR/1_TiB302=== CONT TestFilterOversizedClosures/no_limit_keeps_everything303=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts304=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum305=== CONT TestPartSizeForNAR/small_stays_at_minimum306=== CONT TestFilterOversizedClosures/all_closures_skipped3072026/08/27 09:15:42 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50308=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3092026/08/27 09:15:42 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-vm-image nar_size=5000 max_nar_size=2000310--- PASS: TestFilterOversizedClosures (0.00s)311 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)312 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)313 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)314=== CONT TestPartSizeForNAR/capped_at_5_GiB315=== CONT TestPartSizeForNAR/5_TiB_S3_max_object316--- PASS: TestPartSizeForNAR (0.00s)317 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)318 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)319 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)320 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)321 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)322 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)323 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)324=== CONT TestGetStorePathHash/valid_store_path325=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error326=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error327=== CONT TestGetStorePathHash/basename_without_hyphen_should_error328--- PASS: TestGetStorePathHash (0.00s)329 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)330 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)331 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)332 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)333--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)334 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)335 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)3362026/08/27 09:15:42 http: TLS handshake error from 127.0.0.1:50043: remote error: tls: bad certificate337--- PASS: TestSetClientTLS (0.01s)338 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)339 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)340 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)341--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)342--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)343--- PASS: TestDumpPathWriterError (0.04s)344--- PASS: TestDumpPathSingleFile (0.14s)345--- PASS: TestCaseHackSuffix (0.14s)346--- PASS: TestDumpPathMatchesNix (0.15s)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-5290-2025148623/postgres2978479187/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-5290-2025148623/postgres2978479187/data -l logfile start3763772026-08-27 09:15:43.876 UTC [5325] LOG: starting PostgreSQL 18.4 on aarch64-apple-darwin25.5.0, compiled by clang version 21.1.8, 64-bit3782026-08-27 09:15:43.876 UTC [5325] LOG: listening on Unix socket "/nix/var/nix/builds/nix-5290-2025148623/postgres2978479187/.s.PGSQL.5432"3792026-08-27 09:15:43.878 UTC [5332] LOG: database system was shut down at 2026-08-27 09:15:43 UTC3802026-08-27 09:15:43.878 UTC [5333] FATAL: the database system is starting up381/nix/var/nix/builds/nix-5290-2025148623/postgres2978479187:5432 - rejecting connections3822026-08-27 09:15:43.879 UTC [5325] LOG: database system is ready to accept connections383/nix/var/nix/builds/nix-5290-2025148623/postgres2978479187:5432 - accepting connections384=== RUN TestService_AuthMiddleware385=== PAUSE TestService_AuthMiddleware386=== RUN TestService_AuthMiddleware_MTLSProxyHeader387=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader388=== RUN TestService_AuthMiddleware_MTLSBoundSubjects389=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects390=== RUN TestService_ReadAuthMiddleware391=== PAUSE TestService_ReadAuthMiddleware392=== RUN TestService_AuthMiddleware_OIDC393=== PAUSE TestService_AuthMiddleware_OIDC394=== RUN TestCacheConfigHandler395=== PAUSE TestCacheConfigHandler396=== RUN TestCacheStatsHandler397=== PAUSE TestCacheStatsHandler398=== RUN TestClientCADerivations399=== PAUSE TestClientCADerivations400=== RUN TestClientErrorHandling401=== PAUSE TestClientErrorHandling402=== RUN TestClientIntegration403=== PAUSE TestClientIntegration404=== RUN TestClientMultipleUploads405=== PAUSE TestClientMultipleUploads406=== RUN TestClientWithDependencies407=== PAUSE TestClientWithDependencies408=== RUN TestPinProtectsFromGC409=== PAUSE TestPinProtectsFromGC410=== RUN TestGCAdvisoryLockBlocksConcurrentRun4112026-08-27 09:15:44.151 UTC [5405] ERROR: relation "goose_db_version" does not exist at character 364122026-08-27 09:15:44.151 UTC [5405] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4132026/08/27 09:15:44 OK 20241026095416_initial_model.sql (2.96ms)4142026/08/27 09:15:44 OK 20251210153512_drop_unused_gin_index.sql (375.88µs)4152026/08/27 09:15:44 OK 20251218171726_add_pins.sql (757.08µs)4162026/08/27 09:15:44 OK 20260628120000_add_object_size_and_stats.sql (754.67µs)4172026/08/27 09:15:44 goose: successfully migrated database to version: 202606281200004182026/08/27 09:15:44 OK 1_commit_pending_closure.sql (969.96µs)4192026/08/27 09:15:44 OK 2_object_stats_trigger.sql (203.42µs)4202026/08/27 09:15:44 goose: up to current file version: 2421--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.10s)422=== RUN TestGCBugBareHashReferences423=== PAUSE TestGCBugBareHashReferences424=== RUN TestGCMetrics425=== PAUSE TestGCMetrics426=== RUN TestGCTaskStore_StartNew427=== PAUSE TestGCTaskStore_StartNew428=== RUN TestGCTaskStore_DeduplicateSameParams429=== PAUSE TestGCTaskStore_DeduplicateSameParams430=== RUN TestGCTaskStore_ConflictDifferentParams431=== PAUSE TestGCTaskStore_ConflictDifferentParams432=== RUN TestGCTaskStore_GetEmpty433=== PAUSE TestGCTaskStore_GetEmpty434=== RUN TestGCTaskStore_GetReturnsLatest435=== PAUSE TestGCTaskStore_GetReturnsLatest436=== RUN TestGCTaskStore_CompletedAllowsNewTask437=== PAUSE TestGCTaskStore_CompletedAllowsNewTask438=== RUN TestGCTaskStore_PhaseUpdates439=== PAUSE TestGCTaskStore_PhaseUpdates440=== RUN TestGCTaskStore_Fail441=== PAUSE TestGCTaskStore_Fail442=== RUN TestGracefulShutdownDrainsInflight443=== PAUSE TestGracefulShutdownDrainsInflight444=== RUN TestService_healthCheckHandler445=== PAUSE TestService_healthCheckHandler446=== RUN TestGenerateLandingPage447=== PAUSE TestGenerateLandingPage448=== RUN TestCacheConfigHandlerMaxNarSize449=== PAUSE TestCacheConfigHandlerMaxNarSize450=== RUN TestCreatePendingClosureRejectsOversizedNAR451=== PAUSE TestCreatePendingClosureRejectsOversizedNAR452=== RUN TestNARDeduplicationMetadataUploadBug453=== PAUSE TestNARDeduplicationMetadataUploadBug454=== RUN TestMetricsInventory455=== PAUSE TestMetricsInventory456=== RUN TestService_NativeMTLS457=== PAUSE TestService_NativeMTLS458=== RUN TestServerTLSConfig459=== PAUSE TestServerTLSConfig460=== RUN TestMultipartCleanup461=== PAUSE TestMultipartCleanup462=== RUN TestObjectStatsTrigger463=== PAUSE TestObjectStatsTrigger464=== RUN TestOrphanedObjectsGC465=== PAUSE TestOrphanedObjectsGC466=== RUN TestOrphanedObjectsGCStressTest467=== PAUSE TestOrphanedObjectsGCStressTest468=== RUN TestResurrectedObjectNotDeleted469=== PAUSE TestResurrectedObjectNotDeleted470=== RUN TestParseSingleRange471=== PAUSE TestParseSingleRange472=== RUN TestIsValidCachePath473=== PAUSE TestIsValidCachePath474=== RUN TestReadProxyNarinfo475=== PAUSE TestReadProxyNarinfo476=== RUN TestReadProxyNarinfoAlreadyDecompressed477=== PAUSE TestReadProxyNarinfoAlreadyDecompressed478=== RUN TestReadProxyNarStreaming479=== PAUSE TestReadProxyNarStreaming480=== RUN TestReadProxy404481=== PAUSE TestReadProxy404482=== RUN TestReadProxyInvalidPath483=== PAUSE TestReadProxyInvalidPath484=== RUN TestReadProxyHead485=== PAUSE TestReadProxyHead486=== RUN TestReadProxyConditionalGet487=== PAUSE TestReadProxyConditionalGet488=== RUN TestReadProxyRootRedirectsToIndexHTML489=== PAUSE TestReadProxyRootRedirectsToIndexHTML490=== RUN TestReadProxyDisabled491=== PAUSE TestReadProxyDisabled492=== RUN TestReadProxyRangeRequest493=== PAUSE TestReadProxyRangeRequest494=== RUN TestRedundantMultipartUpload495=== PAUSE TestRedundantMultipartUpload496=== RUN TestCompleteMultipartUpload_ErrorButObjectExists497=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists498=== RUN TestCompletedNarNotReofferedAcrossClosures499=== PAUSE TestCompletedNarNotReofferedAcrossClosures500=== RUN TestPresignedUploadRegisteredBeforeCommit501=== PAUSE TestPresignedUploadRegisteredBeforeCommit502=== RUN TestService_Rustfstest503=== PAUSE TestService_Rustfstest504=== RUN TestParseSize505=== PAUSE TestParseSize506=== RUN TestSkippedUploadsHandler507=== PAUSE TestSkippedUploadsHandler508=== RUN TestSystemdListenerNotActivated509--- PASS: TestSystemdListenerNotActivated (0.00s)510=== RUN TestWatchdogBeatsWhenHealthy511--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)512=== RUN TestWatchdogSkipsWhenUnhealthy5132026/08/27 09:15:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5142026/08/27 09:15:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5152026/08/27 09:15:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5162026/08/27 09:15:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5172026/08/27 09:15:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5182026/08/27 09:15:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5192026/08/27 09:15:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5202026/08/27 09:15:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5212026/08/27 09:15:44 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 TestGCTaskStore_ConflictDifferentParams547--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)548=== CONT TestService_healthCheckHandler549=== CONT TestGenerateLandingPage550=== CONT TestServerTLSConfig551=== CONT TestGCTaskStore_DeduplicateSameParams552=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT553--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)554=== CONT TestGCTaskStore_StartNew555--- PASS: TestGCTaskStore_StartNew (0.00s)556=== CONT TestCreatePendingClosureRejectsOversizedNAR5572026/08/27 09:15:44 INFO Received uploads request method=POST path=/api/pending_closures558=== RUN TestServerTLSConfig/no_client_CA559=== CONT TestMultipartCleanup560=== CONT TestMetricsInventory561=== CONT TestGCMetrics562=== PAUSE TestServerTLSConfig/no_client_CA563=== RUN TestServerTLSConfig/missing_CA_file564=== PAUSE TestServerTLSConfig/missing_CA_file565=== RUN TestServerTLSConfig/not_a_PEM_file566=== PAUSE TestServerTLSConfig/not_a_PEM_file567--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)568=== CONT TestGCBugBareHashReferences569--- PASS: TestGenerateLandingPage (0.01s)570=== CONT TestPinProtectsFromGC5712026-08-27 09:15:44.766 UTC [5427] ERROR: relation "goose_db_version" does not exist at character 365722026-08-27 09:15:44.766 UTC [5427] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5732026-08-27 09:15:44.766 UTC [5429] ERROR: relation "goose_db_version" does not exist at character 365742026-08-27 09:15:44.766 UTC [5429] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5752026-08-27 09:15:44.766 UTC [5428] ERROR: relation "goose_db_version" does not exist at character 365762026-08-27 09:15:44.766 UTC [5428] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5772026-08-27 09:15:44.768 UTC [5430] ERROR: relation "goose_db_version" does not exist at character 365782026-08-27 09:15:44.768 UTC [5430] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5792026-08-27 09:15:44.769 UTC [5432] ERROR: relation "goose_db_version" does not exist at character 365802026-08-27 09:15:44.769 UTC [5432] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5812026-08-27 09:15:44.770 UTC [5434] ERROR: relation "goose_db_version" does not exist at character 365822026-08-27 09:15:44.770 UTC [5434] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5832026-08-27 09:15:44.770 UTC [5431] ERROR: relation "goose_db_version" does not exist at character 365842026-08-27 09:15:44.770 UTC [5431] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5852026-08-27 09:15:44.770 UTC [5433] ERROR: relation "goose_db_version" does not exist at character 365862026-08-27 09:15:44.770 UTC [5433] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5872026-08-27 09:15:44.771 UTC [5435] ERROR: relation "goose_db_version" does not exist at character 365882026-08-27 09:15:44.771 UTC [5435] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5892026-08-27 09:15:44.772 UTC [5436] ERROR: relation "goose_db_version" does not exist at character 365902026-08-27 09:15:44.772 UTC [5436] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5912026/08/27 09:15:44 OK 20241026095416_initial_model.sql (4.97ms)5922026/08/27 09:15:44 OK 20251210153512_drop_unused_gin_index.sql (975.92µs)5932026/08/27 09:15:44 OK 20251218171726_add_pins.sql (2.03ms)5942026/08/27 09:15:44 OK 20241026095416_initial_model.sql (7.18ms)5952026/08/27 09:15:44 OK 20251210153512_drop_unused_gin_index.sql (724.54µs)5962026/08/27 09:15:44 OK 20241026095416_initial_model.sql (7.16ms)5972026/08/27 09:15:44 OK 20260628120000_add_object_size_and_stats.sql (2.38ms)5982026/08/27 09:15:44 goose: successfully migrated database to version: 202606281200005992026/08/27 09:15:44 OK 20241026095416_initial_model.sql (7.72ms)6002026/08/27 09:15:44 OK 20251210153512_drop_unused_gin_index.sql (750.04µs)6012026/08/27 09:15:44 OK 20241026095416_initial_model.sql (9.25ms)6022026/08/27 09:15:44 OK 20251210153512_drop_unused_gin_index.sql (387.71µs)6032026/08/27 09:15:44 OK 20241026095416_initial_model.sql (8.2ms)6042026/08/27 09:15:44 OK 1_commit_pending_closure.sql (1.58ms)6052026/08/27 09:15:44 OK 20251210153512_drop_unused_gin_index.sql (776.04µs)6062026/08/27 09:15:44 OK 20251218171726_add_pins.sql (1.06ms)6072026/08/27 09:15:44 OK 20251210153512_drop_unused_gin_index.sql (625.92µs)6082026/08/27 09:15:44 OK 20241026095416_initial_model.sql (7.45ms)6092026/08/27 09:15:44 OK 20241026095416_initial_model.sql (7.47ms)6102026/08/27 09:15:44 OK 2_object_stats_trigger.sql (507.21µs)6112026/08/27 09:15:44 goose: up to current file version: 26122026/08/27 09:15:44 OK 20251218171726_add_pins.sql (2.79ms)6132026/08/27 09:15:44 OK 20251218171726_add_pins.sql (1.94ms)6142026/08/27 09:15:44 OK 20251210153512_drop_unused_gin_index.sql (694.67µs)6152026/08/27 09:15:44 OK 20251210153512_drop_unused_gin_index.sql (829.13µs)6162026/08/27 09:15:44 OK 20251218171726_add_pins.sql (1.33ms)6172026/08/27 09:15:44 OK 20260628120000_add_object_size_and_stats.sql (1.34ms)6182026/08/27 09:15:44 goose: successfully migrated database to version: 202606281200006192026/08/27 09:15:44 OK 20251218171726_add_pins.sql (1.53ms)6202026/08/27 09:15:44 OK 20241026095416_initial_model.sql (8.14ms)6212026/08/27 09:15:44 OK 20241026095416_initial_model.sql (7.41ms)6222026/08/27 09:15:44 OK 20260628120000_add_object_size_and_stats.sql (1.45ms)6232026/08/27 09:15:44 goose: successfully migrated database to version: 202606281200006242026/08/27 09:15:44 OK 20260628120000_add_object_size_and_stats.sql (1.34ms)6252026/08/27 09:15:44 goose: successfully migrated database to version: 202606281200006262026/08/27 09:15:44 OK 20251218171726_add_pins.sql (1.42ms)6272026/08/27 09:15:44 OK 20251218171726_add_pins.sql (1.38ms)6282026/08/27 09:15:44 OK 1_commit_pending_closure.sql (1.44ms)6292026/08/27 09:15:44 OK 20251210153512_drop_unused_gin_index.sql (786.67µs)6302026/08/27 09:15:44 OK 20251210153512_drop_unused_gin_index.sql (817.63µs)6312026/08/27 09:15:44 OK 1_commit_pending_closure.sql (1.08ms)6322026/08/27 09:15:44 OK 20260628120000_add_object_size_and_stats.sql (1.95ms)6332026/08/27 09:15:44 goose: successfully migrated database to version: 202606281200006342026/08/27 09:15:44 OK 2_object_stats_trigger.sql (604.92µs)6352026/08/27 09:15:44 goose: up to current file version: 26362026/08/27 09:15:44 OK 1_commit_pending_closure.sql (926.92µs)6372026/08/27 09:15:44 OK 2_object_stats_trigger.sql (265.79µs)6382026/08/27 09:15:44 goose: up to current file version: 26392026/08/27 09:15:44 OK 2_object_stats_trigger.sql (219.79µs)6402026/08/27 09:15:44 goose: up to current file version: 26412026/08/27 09:15:44 OK 20260628120000_add_object_size_and_stats.sql (6.5ms)6422026/08/27 09:15:44 goose: successfully migrated database to version: 202606281200006432026/08/27 09:15:44 OK 20260628120000_add_object_size_and_stats.sql (5.65ms)6442026/08/27 09:15:44 goose: successfully migrated database to version: 202606281200006452026/08/27 09:15:44 OK 20251218171726_add_pins.sql (5.57ms)6462026/08/27 09:15:44 OK 1_commit_pending_closure.sql (5.36ms)6472026/08/27 09:15:44 OK 2_object_stats_trigger.sql (187.88µs)6482026/08/27 09:15:44 goose: up to current file version: 26492026/08/27 09:15:44 OK 20260628120000_add_object_size_and_stats.sql (57.12ms)6502026/08/27 09:15:44 goose: successfully migrated database to version: 202606281200006512026/08/27 09:15:44 OK 20251218171726_add_pins.sql (56.84ms)6522026/08/27 09:15:44 OK 1_commit_pending_closure.sql (52.16ms)6532026/08/27 09:15:44 OK 2_object_stats_trigger.sql (187.21µs)6542026/08/27 09:15:44 goose: up to current file version: 26552026/08/27 09:15:44 OK 1_commit_pending_closure.sql (52.36ms)6562026/08/27 09:15:44 OK 1_commit_pending_closure.sql (1.08ms)6572026/08/27 09:15:44 OK 2_object_stats_trigger.sql (208.92µs)6582026/08/27 09:15:44 goose: up to current file version: 26592026/08/27 09:15:44 OK 2_object_stats_trigger.sql (200.58µs)6602026/08/27 09:15:44 goose: up to current file version: 26612026/08/27 09:15:44 OK 20260628120000_add_object_size_and_stats.sql (58.38ms)6622026/08/27 09:15:44 goose: successfully migrated database to version: 202606281200006632026/08/27 09:15:44 OK 20260628120000_add_object_size_and_stats.sql (11.13ms)6642026/08/27 09:15:44 goose: successfully migrated database to version: 202606281200006652026/08/27 09:15:44 OK 1_commit_pending_closure.sql (4.72ms)6662026/08/27 09:15:44 OK 2_object_stats_trigger.sql (195.5µs)6672026/08/27 09:15:44 goose: up to current file version: 2668{"timestamp":"2026-08-27T09:15:44.854114Z","level":"ERROR","duration":"71.041µ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-57705-2947227838/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(4)"}669{"timestamp":"2026-08-27T09:15:44.854173Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"29192965-6cee-4303-92ea-9e8b4f1941a3","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(4)"}6702026/08/27 09:15:44 OK 1_commit_pending_closure.sql (2.66ms)6712026/08/27 09:15:44 OK 2_object_stats_trigger.sql (199.83µs)6722026/08/27 09:15:44 goose: up to current file version: 2673{"timestamp":"2026-08-27T09:15:44.856086Z","level":"ERROR","duration":"54.25µ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-57705-2947227838/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(10)"}674{"timestamp":"2026-08-27T09:15:44.856096Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"0df32ba8-2adf-4165-878a-17abed4937ba","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(10)"}6752026/08/27 09:15:44 INFO Received uploads request method=POST path=/api/pending_closures6762026/08/27 09:15:44 INFO Aborted multipart uploads count=06772026/08/27 09:15:44 WARN Force mode enabled - objects will be deleted immediately without grace period6782026/08/27 09:15:44 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=06792026/08/27 09:15:44 INFO Vacuumed table table=pending_closures6802026/08/27 09:15:44 INFO Vacuumed table table=pending_objects6812026/08/27 09:15:44 INFO Vacuumed table table=multipart_uploads6822026/08/27 09:15:44 INFO Vacuumed table table=closures6832026/08/27 09:15:44 INFO Vacuumed table table=objects684--- PASS: TestGCMetrics (0.52s)685=== CONT TestClientWithDependencies686--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.53s)687=== CONT TestClientMultipleUploads6882026/08/27 09:15:45 INFO Received uploads request method=POST path=/api/pending_closures6892026/08/27 09:15:45 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"690--- PASS: TestService_AuthMiddleware (0.63s)691=== CONT TestClientIntegration692--- PASS: TestObjectStatsTrigger (0.73s)693=== CONT TestClientErrorHandling694=== RUN TestClientErrorHandling/InvalidStorePath695=== PAUSE TestClientErrorHandling/InvalidStorePath696=== RUN TestClientErrorHandling/InvalidAuthToken697=== PAUSE TestClientErrorHandling/InvalidAuthToken698=== RUN TestClientErrorHandling/ServerNotAvailable699=== PAUSE TestClientErrorHandling/ServerNotAvailable700=== CONT TestClientCADerivations7012026/08/27 09:15:45 INFO Received uploads request method=POST path=/api/pending_closures7022026/08/27 09:15:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7032026/08/27 09:15:45 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NGRmNTU5MDktOWY3My00NmEzLTlkYTQtZWY4MWNhMGYyMTRmLjkyZGYyODU1LWE3ZGMtNDMwMC1hZmUzLWFlNWViNmY4ZTVjMngxNzg3ODIyMTQ1MDE5NzA5MDAw7042026/08/27 09:15:45 INFO Created nix-cache-info in bucket bucket=bucket67052026/08/27 09:15:45 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NGRmNTU5MDktOWY3My00NmEzLTlkYTQtZWY4MWNhMGYyMTRmLjkyZGYyODU1LWE3ZGMtNDMwMC1hZmUzLWFlNWViNmY4ZTVjMngxNzg3ODIyMTQ1MDE5NzA5MDAw parts=1706--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.85s)707=== CONT TestCacheStatsHandler708--- PASS: TestService_healthCheckHandler (0.87s)709=== CONT TestCacheConfigHandler710=== RUN TestCacheConfigHandler/full_config,_no_issuer711=== PAUSE TestCacheConfigHandler/full_config,_no_issuer712=== RUN TestCacheConfigHandler/no_cache_url_configured713=== PAUSE TestCacheConfigHandler/no_cache_url_configured714=== RUN TestCacheConfigHandler/no_signing_keys715=== PAUSE TestCacheConfigHandler/no_signing_keys716=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator717=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator718=== CONT TestService_AuthMiddleware_OIDC7192026/08/27 09:15:45 INFO OIDC provider initialized name=test7202026/08/27 09:15:45 INFO Received cleanup request method=DELETE path=/api/pending_closures7212026/08/27 09:15:45 INFO Aborted multipart uploads count=1722--- PASS: TestMultipartCleanup (0.93s)723=== CONT TestService_ReadAuthMiddleware724--- PASS: TestMetricsInventory (0.99s)725=== CONT TestService_AuthMiddleware_MTLSBoundSubjects726=== NAME TestPinProtectsFromGC727 client_integration_test.go:646: Pinned store path: /nix/var/nix/builds/nix-5290-2025148623/TestPinProtectsFromGC4099544542/001/store/1l51hx5x7dvbcq2plafhhc56yx98miy4-pinned-file.txt728 client_integration_test.go:647: Unpinned store path: /nix/var/nix/builds/nix-5290-2025148623/TestPinProtectsFromGC4099544542/001/store/6jv70zznsxm5zag1dr0n58lb596fqfqv-unpinned-file.txt7292026/08/27 09:15:45 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"7302026/08/27 09:15:45 INFO Received uploads request method=POST path=/api/pending_closures731--- PASS: TestGCBugBareHashReferences (1.31s)732=== CONT TestService_AuthMiddleware_MTLSProxyHeader7332026/08/27 09:15:45 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)7342026/08/27 09:15:45 INFO Uploading 1l51hx5x7dvbcq2plafhhc56yx98miy4-pinned-file.txt (128B)7352026/08/27 09:15:45 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"7362026/08/27 09:15:45 WARN Failed to register uploaded object key=1l51hx5x7dvbcq2plafhhc56yx98miy4.ls error="server returned 404: 404 page not found\n"7372026/08/27 09:15:45 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign7382026/08/27 09:15:45 INFO Signed narinfos id=1 count=17392026/08/27 09:15:45 INFO Uploading 1 narinfos7402026/08/27 09:15:45 WARN Failed to register uploaded object key=1l51hx5x7dvbcq2plafhhc56yx98miy4.narinfo error="server returned 404: 404 page not found\n"7412026/08/27 09:15:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7422026/08/27 09:15:45 INFO Completed upload id=17432026/08/27 09:15:45 INFO Upload complete. (221ms)7442026/08/27 09:15:45 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"7452026/08/27 09:15:45 INFO Received uploads request method=POST path=/api/pending_closures7462026/08/27 09:15:45 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)7472026/08/27 09:15:45 INFO Uploading 6jv70zznsxm5zag1dr0n58lb596fqfqv-unpinned-file.txt (128B)7482026/08/27 09:15:46 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"7492026/08/27 09:15:46 WARN Failed to register uploaded object key=6jv70zznsxm5zag1dr0n58lb596fqfqv.ls error="server returned 404: 404 page not found\n"7502026/08/27 09:15:46 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign7512026/08/27 09:15:46 INFO Signed narinfos id=2 count=17522026/08/27 09:15:46 INFO Uploading 1 narinfos7532026/08/27 09:15:46 WARN Failed to register uploaded object key=6jv70zznsxm5zag1dr0n58lb596fqfqv.narinfo error="server returned 404: 404 page not found\n"7542026/08/27 09:15:46 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete7552026/08/27 09:15:46 INFO Completed upload id=27562026/08/27 09:15:46 INFO Upload complete. (163ms)7572026/08/27 09:15:46 INFO Received create pin request method=POST path=/api/pins/myapp7582026-08-27 09:15:46.105 UTC [5474] ERROR: relation "goose_db_version" does not exist at character 367592026-08-27 09:15:46.105 UTC [5474] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7602026-08-27 09:15:46.106 UTC [5473] ERROR: relation "goose_db_version" does not exist at character 367612026-08-27 09:15:46.106 UTC [5473] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7622026/08/27 09:15:46 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-5290-2025148623/TestPinProtectsFromGC4099544542/001/store/1l51hx5x7dvbcq2plafhhc56yx98miy4-pinned-file.txt narinfo_key=1l51hx5x7dvbcq2plafhhc56yx98miy4.narinfo7632026/08/27 09:15:46 INFO Starting cleanup of old closures method=DELETE path=/api/closures7642026/08/27 09:15:46 INFO Garbage collection started7652026/08/27 09:15:46 INFO Aborted multipart uploads count=07662026/08/27 09:15:46 WARN Force mode enabled - objects will be deleted immediately without grace period7672026-08-27 09:15:46.166 UTC [5477] ERROR: relation "goose_db_version" does not exist at character 367682026-08-27 09:15:46.166 UTC [5477] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7692026/08/27 09:15:46 OK 20241026095416_initial_model.sql (35.74ms)7702026/08/27 09:15:46 OK 20251210153512_drop_unused_gin_index.sql (7.34ms)7712026/08/27 09:15:46 OK 20241026095416_initial_model.sql (60.18ms)7722026/08/27 09:15:46 OK 20251210153512_drop_unused_gin_index.sql (7.3ms)7732026/08/27 09:15:46 OK 20251218171726_add_pins.sql (14.87ms)7742026/08/27 09:15:46 OK 20251218171726_add_pins.sql (2.14ms)7752026-08-27 09:15:46.208 UTC [5478] ERROR: relation "goose_db_version" does not exist at character 367762026-08-27 09:15:46.208 UTC [5478] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7772026/08/27 09:15:46 OK 20260628120000_add_object_size_and_stats.sql (17.54ms)7782026/08/27 09:15:46 goose: successfully migrated database to version: 202606281200007792026/08/27 09:15:46 OK 1_commit_pending_closure.sql (2.95ms)7802026/08/27 09:15:46 OK 2_object_stats_trigger.sql (528.46µs)7812026/08/27 09:15:46 goose: up to current file version: 27822026/08/27 09:15:46 OK 20260628120000_add_object_size_and_stats.sql (22.98ms)7832026/08/27 09:15:46 goose: successfully migrated database to version: 202606281200007842026/08/27 09:15:46 OK 1_commit_pending_closure.sql (2.04ms)7852026/08/27 09:15:46 OK 2_object_stats_trigger.sql (236.5µs)7862026/08/27 09:15:46 goose: up to current file version: 27872026/08/27 09:15:46 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=07882026/08/27 09:15:46 OK 20241026095416_initial_model.sql (103.44ms)7892026/08/27 09:15:46 INFO Vacuumed table table=pending_closures7902026/08/27 09:15:46 OK 20251210153512_drop_unused_gin_index.sql (19.44ms)7912026/08/27 09:15:46 INFO Vacuumed table table=pending_objects7922026/08/27 09:15:46 INFO Vacuumed table table=multipart_uploads7932026/08/27 09:15:46 OK 20251218171726_add_pins.sql (36.77ms)7942026/08/27 09:15:46 INFO Vacuumed table table=closures7952026/08/27 09:15:46 INFO Vacuumed table table=objects7962026/08/27 09:15:46 OK 20260628120000_add_object_size_and_stats.sql (52.09ms)7972026/08/27 09:15:46 goose: successfully migrated database to version: 202606281200007982026/08/27 09:15:46 OK 1_commit_pending_closure.sql (8.2ms)7992026/08/27 09:15:46 OK 2_object_stats_trigger.sql (346.88µs)8002026/08/27 09:15:46 goose: up to current file version: 28012026/08/27 09:15:46 INFO Created nix-cache-info in bucket bucket=bucket128022026/08/27 09:15:46 INFO Created nix-cache-info in bucket bucket=bucket138032026/08/27 09:15:46 OK 20241026095416_initial_model.sql (243.91ms)8042026/08/27 09:15:46 OK 20251210153512_drop_unused_gin_index.sql (22.71ms)8052026/08/27 09:15:46 OK 20251218171726_add_pins.sql (29.09ms)8062026/08/27 09:15:46 OK 20260628120000_add_object_size_and_stats.sql (35ms)8072026/08/27 09:15:46 goose: successfully migrated database to version: 202606281200008082026/08/27 09:15:46 OK 1_commit_pending_closure.sql (7.04ms)8092026/08/27 09:15:46 OK 2_object_stats_trigger.sql (245µs)8102026/08/27 09:15:46 goose: up to current file version: 28112026/08/27 09:15:46 INFO Created nix-cache-info in bucket bucket=bucket148122026-08-27 09:15:46.625 UTC [5484] ERROR: relation "goose_db_version" does not exist at character 368132026-08-27 09:15:46.625 UTC [5484] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8142026-08-27 09:15:46.626 UTC [5485] ERROR: relation "goose_db_version" does not exist at character 368152026-08-27 09:15:46.626 UTC [5485] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC816=== NAME TestClientMultipleUploads817 client_integration_test.go:338: Created store path 0: /nix/var/nix/builds/nix-5290-2025148623/TestClientMultipleUploads1143069065/001/store/a1bn2knjpz0m9jgf5ammc6jmbwhx529i-test-file-0.txt8182026/08/27 09:15:46 INFO Created nix-cache-info in bucket bucket=bucket158192026-08-27 09:15:46.760 UTC [5490] ERROR: relation "goose_db_version" does not exist at character 368202026-08-27 09:15:46.760 UTC [5490] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC821 client_integration_test.go:338: Created store path 1: /nix/var/nix/builds/nix-5290-2025148623/TestClientMultipleUploads1143069065/001/store/62njhk9f18rdz72qfk8j58yv2m85sbv7-test-file-1.txt822=== NAME TestClientIntegration823 client_integration_test.go:276: Created store path: /nix/var/nix/builds/nix-5290-2025148623/TestClientIntegration865311219/002/store/r4z9z70q57vi8hbzqlhjg000cfqj4512-test-file.txt8242026-08-27 09:15:46.800 UTC [5497] ERROR: relation "goose_db_version" does not exist at character 368252026-08-27 09:15:46.800 UTC [5497] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8262026/08/27 09:15:46 OK 20241026095416_initial_model.sql (124.94ms)8272026/08/27 09:15:46 OK 20241026095416_initial_model.sql (125.2ms)8282026/08/27 09:15:46 OK 20251210153512_drop_unused_gin_index.sql (1.17ms)8292026/08/27 09:15:46 OK 20251210153512_drop_unused_gin_index.sql (1.11ms)830=== NAME TestClientMultipleUploads831 client_integration_test.go:338: Created store path 2: /nix/var/nix/builds/nix-5290-2025148623/TestClientMultipleUploads1143069065/001/store/5vyyh4m8lfwwkh36szi6j6v9sdkgsh8p-test-file-2.txt8322026/08/27 09:15:46 OK 20251218171726_add_pins.sql (2.03ms)8332026/08/27 09:15:46 OK 20251218171726_add_pins.sql (13.81ms)8342026/08/27 09:15:46 OK 20260628120000_add_object_size_and_stats.sql (15.16ms)8352026/08/27 09:15:46 goose: successfully migrated database to version: 202606281200008362026/08/27 09:15:46 OK 20260628120000_add_object_size_and_stats.sql (27.13ms)8372026/08/27 09:15:46 goose: successfully migrated database to version: 202606281200008382026/08/27 09:15:46 OK 1_commit_pending_closure.sql (989.83µs)8392026/08/27 09:15:46 OK 2_object_stats_trigger.sql (291.63µs)8402026/08/27 09:15:46 goose: up to current file version: 28412026/08/27 09:15:46 OK 1_commit_pending_closure.sql (8.23ms)8422026/08/27 09:15:46 OK 2_object_stats_trigger.sql (281.88µs)8432026/08/27 09:15:46 goose: up to current file version: 28442026/08/27 09:15:46 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"8452026/08/27 09:15:46 OK 20241026095416_initial_model.sql (73.15ms)8462026/08/27 09:15:46 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"847=== NAME TestClientWithDependencies848 client_integration_test.go:593: Built derivation: /nix/var/nix/builds/nix-5290-2025148623/TestClientWithDependencies1859152668/001/store/4805k68km7kgy22v8fqj211psh0rsrpm-test-script8492026/08/27 09:15:46 OK 20251210153512_drop_unused_gin_index.sql (7.13ms)8502026/08/27 09:15:46 OK 20251218171726_add_pins.sql (29.44ms)8512026/08/27 09:15:46 INFO Received uploads request method=POST path=/api/pending_closures852 client_integration_test.go:595: Found 1 dependencies (including self)8532026/08/27 09:15:46 OK 20241026095416_initial_model.sql (113.12ms)8542026/08/27 09:15:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8552026/08/27 09:15:46 INFO Uploading r4z9z70q57vi8hbzqlhjg000cfqj4512-test-file.txt (152B)8562026/08/27 09:15:46 OK 20251210153512_drop_unused_gin_index.sql (11.15ms)8572026/08/27 09:15:46 OK 20260628120000_add_object_size_and_stats.sql (39.18ms)8582026/08/27 09:15:46 goose: successfully migrated database to version: 20260628120000859=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token860=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token861=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected862=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected863=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected864=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected865=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured866=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured867=== CONT TestIsValidUploadKey868=== RUN TestIsValidUploadKey/narinfo869=== PAUSE TestIsValidUploadKey/narinfo870=== RUN TestIsValidUploadKey/nar_zst871=== PAUSE TestIsValidUploadKey/nar_zst872=== RUN TestIsValidUploadKey/nar_xz873=== PAUSE TestIsValidUploadKey/nar_xz874=== RUN TestIsValidUploadKey/nar_plain875=== PAUSE TestIsValidUploadKey/nar_plain876=== RUN TestIsValidUploadKey/listing877=== PAUSE TestIsValidUploadKey/listing878=== RUN TestIsValidUploadKey/build_log879=== PAUSE TestIsValidUploadKey/build_log880=== RUN TestIsValidUploadKey/build_log_home-manager_file881=== PAUSE TestIsValidUploadKey/build_log_home-manager_file882=== RUN TestIsValidUploadKey/build_log_plus_in_name883=== PAUSE TestIsValidUploadKey/build_log_plus_in_name884=== RUN TestIsValidUploadKey/build_log_question_mark885=== PAUSE TestIsValidUploadKey/build_log_question_mark886=== RUN TestIsValidUploadKey/build_log_equals887=== PAUSE TestIsValidUploadKey/build_log_equals888=== RUN TestIsValidUploadKey/realisation889=== PAUSE TestIsValidUploadKey/realisation890=== RUN TestIsValidUploadKey/realisation_plus_in_output891=== PAUSE TestIsValidUploadKey/realisation_plus_in_output892=== RUN TestIsValidUploadKey/nix-cache-info893=== PAUSE TestIsValidUploadKey/nix-cache-info894=== RUN TestIsValidUploadKey/index.html895=== PAUSE TestIsValidUploadKey/index.html896=== RUN TestIsValidUploadKey/narinfo_key,_nar_type897=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type898=== RUN TestIsValidUploadKey/nar_key,_narinfo_type899=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type900=== RUN TestIsValidUploadKey/listing_key,_narinfo_type901=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type902=== RUN TestIsValidUploadKey/traversal903=== PAUSE TestIsValidUploadKey/traversal904=== RUN TestIsValidUploadKey/traversal_nar905=== PAUSE TestIsValidUploadKey/traversal_nar906=== RUN TestIsValidUploadKey/absolute907=== PAUSE TestIsValidUploadKey/absolute908=== RUN TestIsValidUploadKey/empty_key909=== PAUSE TestIsValidUploadKey/empty_key910=== RUN TestIsValidUploadKey/unknown_type911=== PAUSE TestIsValidUploadKey/unknown_type912=== CONT TestCompleteMultipartUnregistered9132026/08/27 09:15:46 OK 1_commit_pending_closure.sql (12.82ms)9142026/08/27 09:15:46 INFO Received uploads request method=POST path=/api/pending_closures9152026/08/27 09:15:46 OK 2_object_stats_trigger.sql (376.17µs)9162026/08/27 09:15:46 goose: up to current file version: 29172026/08/27 09:15:46 OK 20251218171726_add_pins.sql (34.55ms)9182026/08/27 09:15:46 INFO Received uploads request method=POST path=/api/pending_closures9192026/08/27 09:15:46 INFO Received uploads request method=POST path=/api/pending_closures9202026/08/27 09:15:46 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)9212026/08/27 09:15:46 INFO Uploading 62njhk9f18rdz72qfk8j58yv2m85sbv7-test-file-1.txt (160B)9222026/08/27 09:15:46 INFO Uploading 5vyyh4m8lfwwkh36szi6j6v9sdkgsh8p-test-file-2.txt (160B)9232026/08/27 09:15:46 INFO Uploading a1bn2knjpz0m9jgf5ammc6jmbwhx529i-test-file-0.txt (160B)9242026/08/27 09:15:47 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"9252026/08/27 09:15:47 OK 20260628120000_add_object_size_and_stats.sql (54.66ms)9262026/08/27 09:15:47 goose: successfully migrated database to version: 202606281200009272026/08/27 09:15:47 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"9282026/08/27 09:15:47 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"9292026/08/27 09:15:47 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9302026/08/27 09:15:47 INFO Received uploads request method=POST path=/api/pending_closures9312026/08/27 09:15:47 WARN Failed to register uploaded object key=r4z9z70q57vi8hbzqlhjg000cfqj4512.ls error="server returned 404: 404 page not found\n"9322026/08/27 09:15:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9332026/08/27 09:15:47 INFO Signed narinfos id=1 count=19342026/08/27 09:15:47 INFO Uploading 1 narinfos9352026/08/27 09:15:47 OK 1_commit_pending_closure.sql (12.04ms)9362026/08/27 09:15:47 OK 2_object_stats_trigger.sql (245.58µs)9372026/08/27 09:15:47 goose: up to current file version: 29382026/08/27 09:15:47 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"9392026/08/27 09:15:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9402026/08/27 09:15:47 INFO Uploading 4805k68km7kgy22v8fqj211psh0rsrpm-test-script (136B)9412026/08/27 09:15:47 WARN Failed to register uploaded object key=62njhk9f18rdz72qfk8j58yv2m85sbv7.ls error="server returned 404: 404 page not found\n"9422026/08/27 09:15:47 WARN Failed to register uploaded object key=r4z9z70q57vi8hbzqlhjg000cfqj4512.narinfo error="server returned 404: 404 page not found\n"9432026/08/27 09:15:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9442026/08/27 09:15:47 WARN Failed to register uploaded object key=a1bn2knjpz0m9jgf5ammc6jmbwhx529i.ls error="server returned 404: 404 page not found\n"9452026/08/27 09:15:47 WARN Failed to register uploaded object key=5vyyh4m8lfwwkh36szi6j6v9sdkgsh8p.ls error="server returned 404: 404 page not found\n"9462026/08/27 09:15:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9472026/08/27 09:15:47 INFO Signed narinfos id=1 count=19482026/08/27 09:15:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign9492026/08/27 09:15:47 INFO Signed narinfos id=2 count=19502026/08/27 09:15:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign9512026/08/27 09:15:47 INFO Signed narinfos id=3 count=19522026/08/27 09:15:47 INFO Uploading 3 narinfos953--- PASS: TestCacheStatsHandler (1.86s)954=== CONT TestService_verifyS3Integrity9552026/08/27 09:15:47 INFO Completed upload id=19562026/08/27 09:15:47 INFO Upload complete. (343ms)9572026/08/27 09:15:47 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"958=== NAME TestClientIntegration959 client_integration_test.go:292: Retrieved narinfo from S3:960 StorePath: /nix/var/nix/builds/nix-5290-2025148623/TestClientIntegration865311219/002/store/r4z9z70q57vi8hbzqlhjg000cfqj4512-test-file.txt961 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst962 Compression: zstd963 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1964 NarSize: 152965 References: 966 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1967 client_integration_test.go:293: Retrieved .ls file from S3 (compressed size: 77 bytes)968 client_integration_test.go:293: Decompressed .ls content (64 bytes):969 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}970 client_integration_test.go:296: Testing garbage collection...9712026/08/27 09:15:47 WARN Failed to register uploaded object key=log/a3hwq0246sgzgb8s1f9ay8lh876f6np0-test-script.drv error="server returned 404: 404 page not found\n"9722026/08/27 09:15:47 INFO Starting cleanup of old closures method=DELETE path=/api/closures9732026/08/27 09:15:47 INFO Garbage collection started9742026/08/27 09:15:47 INFO Aborted multipart uploads count=09752026/08/27 09:15:47 WARN Force mode enabled - objects will be deleted immediately without grace period9762026/08/27 09:15:47 WARN Failed to register uploaded object key=5vyyh4m8lfwwkh36szi6j6v9sdkgsh8p.narinfo error="server returned 404: 404 page not found\n"9772026/08/27 09:15:47 WARN Failed to register uploaded object key=a1bn2knjpz0m9jgf5ammc6jmbwhx529i.narinfo error="server returned 404: 404 page not found\n"9782026/08/27 09:15:47 WARN Failed to register uploaded object key=62njhk9f18rdz72qfk8j58yv2m85sbv7.narinfo error="server returned 404: 404 page not found\n"9792026/08/27 09:15:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete980=== NAME TestClientCADerivations981 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-5290-2025148623/TestClientCADerivations2753959568/001/store/r9b0c4d2kn084wa7lbi355v37fz09kmm-ca-test9822026/08/27 09:15:47 INFO Completed upload id=19832026/08/27 09:15:47 WARN Failed to register uploaded object key=4805k68km7kgy22v8fqj211psh0rsrpm.ls error="server returned 404: 404 page not found\n"9842026/08/27 09:15:47 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete9852026/08/27 09:15:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9862026/08/27 09:15:47 INFO Signed narinfos id=1 count=19872026/08/27 09:15:47 INFO Completed upload id=29882026/08/27 09:15:47 INFO Uploading 1 narinfos9892026/08/27 09:15:47 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete9902026/08/27 09:15:47 INFO Completed upload id=39912026/08/27 09:15:47 INFO Upload complete. (389ms)992=== NAME TestClientMultipleUploads993 client_integration_test.go:349: Uploaded 3 paths in 418.839083ms9942026/08/27 09:15:47 WARN mTLS auth: subject not in bound subjects subject="CN=writer"995--- PASS: TestService_ReadAuthMiddleware (1.91s)996=== CONT TestService_createPendingClosureHandler9972026/08/27 09:15:47 WARN Failed to register uploaded object key=4805k68km7kgy22v8fqj211psh0rsrpm.narinfo error="server returned 404: 404 page not found\n"9982026/08/27 09:15:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete999=== NAME TestClientCADerivations1000 client_ca_test.go:139: Found 1 dependencies (including self)10012026/08/27 09:15:47 INFO Completed upload id=110022026/08/27 09:15:47 INFO Upload complete. (332ms)1003=== NAME TestClientWithDependencies1004 client_integration_test.go:597: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-5290-2025148623/TestClientWithDependencies1859152668/001/store) requires matching store prefix1005--- PASS: TestClientMultipleUploads (2.36s)1006=== CONT TestService_cleanupPendingClosuresHandler10072026/08/27 09:15:47 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"10082026/08/27 09:15:47 WARN mTLS auth: bound subjects configured but subject DN unavailable10092026/08/27 09:15:47 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1010--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (1.93s)1011=== CONT TestUploadHandlersRejectOversizedBody1012--- PASS: TestClientWithDependencies (2.40s)1013=== CONT TestUploadHandlersRejectInvalidKeys1014=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1015=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1016=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1017=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1018=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1019=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1020=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1021=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1022=== CONT TestCacheConfigHandlerMaxNarSize1023--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1024=== CONT TestGCTaskStore_PhaseUpdates1025--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1026=== CONT TestGracefulShutdownDrainsInflight10272026/08/27 09:15:47 INFO Starting HTTP server address=127.0.0.1:5012210282026/08/27 09:15:47 INFO Shutdown signal received, draining in-flight requests timeout=10s10292026/08/27 09:15:47 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10302026/08/27 09:15:47 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=010312026/08/27 09:15:47 INFO Vacuumed table table=pending_closures10322026/08/27 09:15:47 INFO Vacuumed table table=pending_objects10332026/08/27 09:15:47 INFO Vacuumed table table=multipart_uploads1034=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1035=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1036=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1037=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1038=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1039=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1040=== CONT TestGCTaskStore_Fail1041--- PASS: TestGCTaskStore_Fail (0.00s)1042=== CONT TestGCTaskStore_GetReturnsLatest1043--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1044=== CONT TestGCTaskStore_CompletedAllowsNewTask1045--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1046=== CONT TestParseSize1047--- PASS: TestParseSize (0.00s)1048=== CONT TestProxyWriteTimeout1049=== RUN TestProxyWriteTimeout/narinfo1050=== PAUSE TestProxyWriteTimeout/narinfo1051=== RUN TestProxyWriteTimeout/1_GiB_nar1052=== PAUSE TestProxyWriteTimeout/1_GiB_nar1053=== RUN TestProxyWriteTimeout/10_GiB_nar1054=== PAUSE TestProxyWriteTimeout/10_GiB_nar1055=== RUN TestProxyWriteTimeout/unknown_size1056=== PAUSE TestProxyWriteTimeout/unknown_size1057=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle10582026/08/27 09:15:47 INFO Vacuumed table table=closures10592026-08-27 09:15:47.399 UTC [5539] ERROR: relation "goose_db_version" does not exist at character 3610602026-08-27 09:15:47.399 UTC [5539] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10612026/08/27 09:15:47 INFO Vacuumed table table=objects10622026/08/27 09:15:47 INFO Received uploads request method=POST path=/api/pending_closures1063--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1064=== CONT TestSkippedUploadsHandler10652026/08/27 09:15:47 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001066--- PASS: TestSkippedUploadsHandler (0.00s)1067=== CONT TestReadProxy40410682026/08/27 09:15:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10692026/08/27 09:15:47 INFO Uploading r9b0c4d2kn084wa7lbi355v37fz09kmm-ca-test (144B)10702026/08/27 09:15:47 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"10712026/08/27 09:15:47 WARN Failed to register uploaded object key=log/cq3zw4yxh4372k6y5ivfmfhqpbcjs3wg-ca-test.drv error="server returned 404: 404 page not found\n"10722026/08/27 09:15:47 WARN Failed to register uploaded object key=r9b0c4d2kn084wa7lbi355v37fz09kmm.ls error="server returned 404: 404 page not found\n"10732026/08/27 09:15:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10742026/08/27 09:15:47 INFO Signed narinfos id=1 count=110752026/08/27 09:15:47 INFO Uploading 1 narinfos10762026/08/27 09:15:47 WARN Failed to register uploaded object key=r9b0c4d2kn084wa7lbi355v37fz09kmm.narinfo error="server returned 404: 404 page not found\n"10772026/08/27 09:15:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10782026/08/27 09:15:47 INFO Completed upload id=110792026/08/27 09:15:47 INFO Upload complete. (196ms)10802026/08/27 09:15:47 OK 20241026095416_initial_model.sql (86.14ms)10812026/08/27 09:15:47 OK 20251210153512_drop_unused_gin_index.sql (692.54µs)1082=== NAME TestClientCADerivations1083 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-5290-2025148623/TestClientCADerivations2753959568/001/store/r9b0c4d2kn084wa7lbi355v37fz09kmm-ca-test1084 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1085 Compression: zstd1086 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1087 NarSize: 1441088 References: 1089 Deriver: /nix/var/nix/builds/nix-5290-2025148623/TestClientCADerivations2753959568/001/store/cq3zw4yxh4372k6y5ivfmfhqpbcjs3wg-ca-test.drv1090 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1091 client_ca_test.go:185: Checking for realisation files in S3...1092 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1093 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache10942026/08/27 09:15:47 OK 20251218171726_add_pins.sql (1.94ms)10952026/08/27 09:15:47 OK 20260628120000_add_object_size_and_stats.sql (3.23ms)10962026/08/27 09:15:47 goose: successfully migrated database to version: 2026062812000010972026/08/27 09:15:47 OK 1_commit_pending_closure.sql (7.49ms)10982026/08/27 09:15:47 OK 2_object_stats_trigger.sql (342µs)10992026/08/27 09:15:47 goose: up to current file version: 21100 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket15?endpoint=http://localhost:50050®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-5290-2025148623/TestClientCADerivations2753959568/001/store'1101 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11102--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (1.88s)1103=== CONT TestRedundantMultipartUpload1104--- PASS: TestClientCADerivations (2.47s)1105=== CONT TestReadProxyRangeRequest11062026-08-27 09:15:48.036 UTC [5551] ERROR: relation "goose_db_version" does not exist at character 3611072026-08-27 09:15:48.036 UTC [5551] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11082026/08/27 09:15:48 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01109=== NAME TestPinProtectsFromGC1110 client_integration_test.go:709: Pin successfully protected closure from garbage collection11112026-08-27 09:15:48.147 UTC [5552] ERROR: relation "goose_db_version" does not exist at character 3611122026-08-27 09:15:48.147 UTC [5552] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1113--- PASS: TestPinProtectsFromGC (3.71s)1114=== CONT TestReadProxyDisabled11152026/08/27 09:15:48 OK 20241026095416_initial_model.sql (97.53ms)11162026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (2.79ms)11172026/08/27 09:15:48 OK 20251218171726_add_pins.sql (20.25ms)11182026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (7.65ms)11192026/08/27 09:15:48 goose: successfully migrated database to version: 2026062812000011202026/08/27 09:15:48 OK 1_commit_pending_closure.sql (10.73ms)11212026/08/27 09:15:48 OK 2_object_stats_trigger.sql (399µs)11222026/08/27 09:15:48 goose: up to current file version: 211232026/08/27 09:15:48 OK 20241026095416_initial_model.sql (182.22ms)11242026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (10.95ms)11252026/08/27 09:15:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11262026/08/27 09:15:48 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1127--- PASS: TestCompleteMultipartUnregistered (1.44s)1128=== CONT TestReadProxyRootRedirectsToIndexHTML11292026/08/27 09:15:48 OK 20251218171726_add_pins.sql (44.84ms)11302026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (11.85ms)11312026/08/27 09:15:48 goose: successfully migrated database to version: 2026062812000011322026/08/27 09:15:48 OK 1_commit_pending_closure.sql (7.91ms)11332026/08/27 09:15:48 OK 2_object_stats_trigger.sql (417.17µs)11342026/08/27 09:15:48 goose: up to current file version: 211352026-08-27 09:15:48.520 UTC [5558] ERROR: relation "goose_db_version" does not exist at character 3611362026-08-27 09:15:48.520 UTC [5558] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11372026-08-27 09:15:48.521 UTC [5556] ERROR: relation "goose_db_version" does not exist at character 3611382026-08-27 09:15:48.521 UTC [5556] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11392026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures11402026-08-27 09:15:48.619 UTC [5559] ERROR: relation "goose_db_version" does not exist at character 3611412026-08-27 09:15:48.619 UTC [5559] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11422026/08/27 09:15:48 OK 20241026095416_initial_model.sql (117.64ms)11432026/08/27 09:15:48 OK 20241026095416_initial_model.sql (118.19ms)11442026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (3.19ms)11452026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (2.73ms)11462026/08/27 09:15:48 OK 20251218171726_add_pins.sql (9.09ms)11472026/08/27 09:15:48 OK 20251218171726_add_pins.sql (9.05ms)11482026-08-27 09:15:48.697 UTC [5560] ERROR: relation "goose_db_version" does not exist at character 3611492026-08-27 09:15:48.697 UTC [5560] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11502026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (38.31ms)11512026/08/27 09:15:48 goose: successfully migrated database to version: 2026062812000011522026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (38.25ms)11532026/08/27 09:15:48 goose: successfully migrated database to version: 2026062812000011542026/08/27 09:15:48 OK 1_commit_pending_closure.sql (2.33ms)11552026/08/27 09:15:48 OK 1_commit_pending_closure.sql (2.3ms)11562026/08/27 09:15:48 OK 2_object_stats_trigger.sql (405.42µs)11572026/08/27 09:15:48 goose: up to current file version: 211582026/08/27 09:15:48 OK 2_object_stats_trigger.sql (400.88µs)11592026/08/27 09:15:48 goose: up to current file version: 211602026/08/27 09:15:48 OK 20241026095416_initial_model.sql (86.4ms)11612026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (7.96ms)11622026-08-27 09:15:48.807 UTC [5561] ERROR: relation "goose_db_version" does not exist at character 3611632026-08-27 09:15:48.807 UTC [5561] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11642026/08/27 09:15:48 OK 20251218171726_add_pins.sql (38.22ms)11652026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (29.87ms)11662026/08/27 09:15:48 goose: successfully migrated database to version: 2026062812000011672026/08/27 09:15:48 OK 1_commit_pending_closure.sql (3.74ms)11682026/08/27 09:15:48 OK 2_object_stats_trigger.sql (717.92µs)11692026/08/27 09:15:48 goose: up to current file version: 211702026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures11712026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures11722026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures11732026-08-27 09:15:48.914 UTC [5562] ERROR: relation "goose_db_version" does not exist at character 3611742026-08-27 09:15:48.914 UTC [5562] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11752026/08/27 09:15:48 OK 20241026095416_initial_model.sql (144.17ms)11762026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (11.23ms)11772026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures11782026/08/27 09:15:48 OK 20251218171726_add_pins.sql (46.31ms)11792026/08/27 09:15:49 OK 20241026095416_initial_model.sql (177.94ms)11802026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (49.21ms)11812026/08/27 09:15:49 goose: successfully migrated database to version: 2026062812000011822026/08/27 09:15:49 OK 20251210153512_drop_unused_gin_index.sql (11.88ms)11832026/08/27 09:15:49 OK 1_commit_pending_closure.sql (18.21ms)11842026/08/27 09:15:49 OK 2_object_stats_trigger.sql (666.33µs)11852026/08/27 09:15:49 goose: up to current file version: 211862026/08/27 09:15:49 OK 20251218171726_add_pins.sql (57.78ms)11872026/08/27 09:15:49 INFO Received cleanup request method=DELETE path=/api/pending_closures11882026/08/27 09:15:49 INFO Aborted multipart uploads count=011892026/08/27 09:15:49 INFO Received uploads request method=POST path=/api/pending_closures11902026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (23.64ms)11912026/08/27 09:15:49 goose: successfully migrated database to version: 2026062812000011922026/08/27 09:15:49 OK 1_commit_pending_closure.sql (10.7ms)11932026/08/27 09:15:49 OK 2_object_stats_trigger.sql (548.79µs)11942026/08/27 09:15:49 goose: up to current file version: 211952026/08/27 09:15:49 INFO Received cleanup request method=DELETE path=/api/pending_closures11962026/08/27 09:15:49 INFO Aborted multipart uploads count=111972026/08/27 09:15:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11982026-08-27 09:15:49.195 UTC [5559] ERROR: Closure does not exist: id=111992026-08-27 09:15:49.195 UTC [5559] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE12002026-08-27 09:15:49.195 UTC [5559] STATEMENT: -- name: CommitPendingClosure :exec1201 SELECT commit_pending_closure($1::bigint)1202 12032026/08/27 09:15:49 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01204--- PASS: TestService_cleanupPendingClosuresHandler (1.88s)1205=== CONT TestReadProxyConditionalGet1206=== NAME TestClientIntegration1207 client_integration_test.go:303: Objects in database after GC:1208 client_integration_test.go:303: Successfully deleted all objects with GC --force12092026/08/27 09:15:49 OK 20241026095416_initial_model.sql (236.84ms)12102026/08/27 09:15:49 OK 20251210153512_drop_unused_gin_index.sql (20.92ms)12112026/08/27 09:15:49 OK 20251218171726_add_pins.sql (41.26ms)1212--- PASS: TestReadProxy404 (1.87s)1213=== CONT TestReadProxyHead12142026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (33.04ms)12152026/08/27 09:15:49 goose: successfully migrated database to version: 2026062812000012162026/08/27 09:15:49 OK 1_commit_pending_closure.sql (8.1ms)12172026/08/27 09:15:49 OK 2_object_stats_trigger.sql (289.38µs)12182026/08/27 09:15:49 goose: up to current file version: 21219--- PASS: TestClientIntegration (4.26s)1220=== CONT TestReadProxyInvalidPath12212026/08/27 09:15:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1222--- PASS: TestReadProxyRangeRequest (1.93s)1223=== CONT TestIsValidCachePath1224=== RUN TestIsValidCachePath/narinfo1225=== PAUSE TestIsValidCachePath/narinfo1226=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1227=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1228=== RUN TestIsValidCachePath/nar_zst1229=== PAUSE TestIsValidCachePath/nar_zst1230=== RUN TestIsValidCachePath/nar_xz1231=== PAUSE TestIsValidCachePath/nar_xz1232=== RUN TestIsValidCachePath/nar_bz21233=== PAUSE TestIsValidCachePath/nar_bz21234=== RUN TestIsValidCachePath/nar_uncompressed1235=== PAUSE TestIsValidCachePath/nar_uncompressed1236=== RUN TestIsValidCachePath/ls1237=== PAUSE TestIsValidCachePath/ls1238=== RUN TestIsValidCachePath/log1239=== PAUSE TestIsValidCachePath/log1240=== RUN TestIsValidCachePath/realisation1241=== PAUSE TestIsValidCachePath/realisation1242=== RUN TestIsValidCachePath/nix-cache-info1243=== PAUSE TestIsValidCachePath/nix-cache-info1244=== RUN TestIsValidCachePath/index.html1245=== PAUSE TestIsValidCachePath/index.html1246=== RUN TestIsValidCachePath/traversal_parent1247=== PAUSE TestIsValidCachePath/traversal_parent1248=== RUN TestIsValidCachePath/traversal_in_middle1249=== PAUSE TestIsValidCachePath/traversal_in_middle1250=== RUN TestIsValidCachePath/invalid_char_e1251=== PAUSE TestIsValidCachePath/invalid_char_e1252=== RUN TestIsValidCachePath/invalid_char_u1253=== PAUSE TestIsValidCachePath/invalid_char_u1254=== RUN TestIsValidCachePath/random_path1255=== PAUSE TestIsValidCachePath/random_path1256=== RUN TestIsValidCachePath/empty1257=== PAUSE TestIsValidCachePath/empty1258=== RUN TestIsValidCachePath/leading_slash1259=== PAUSE TestIsValidCachePath/leading_slash1260=== RUN TestIsValidCachePath/wrong_extension1261=== PAUSE TestIsValidCachePath/wrong_extension1262=== RUN TestIsValidCachePath/short_hash1263=== PAUSE TestIsValidCachePath/short_hash1264=== CONT TestReadProxyNarStreaming12652026/08/27 09:15:49 INFO Received uploads request method=POST path=/api/pending_closures12662026/08/27 09:15:49 INFO Received uploads request method=POST path=/api/pending_closures12672026/08/27 09:15:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12682026/08/27 09:15:50 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NGRmNTU5MDktOWY3My00NmEzLTlkYTQtZWY4MWNhMGYyMTRmLjY5ZjRlNDhjLWJmYmQtNDU0Zi1iMWQyLWFmMjQ3MDFjY2M1NngxNzg3ODIyMTQ4NjIwMDgzMDAw parts=1012692026/08/27 09:15:50 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12702026/08/27 09:15:50 INFO Completed upload id=112712026/08/27 09:15:50 INFO Received uploads request method=POST path=/api/pending_closures12722026/08/27 09:15:50 INFO Received uploads request method=POST path=/api/pending_closures12732026/08/27 09:15:50 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo12742026/08/27 09:15:50 WARN Found objects in DB but missing from S3, will re-upload count=11275--- PASS: TestService_verifyS3Integrity (3.07s)1276=== CONT TestReadProxyNarinfoAlreadyDecompressed12772026/08/27 09:15:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12782026/08/27 09:15:50 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NGRmNTU5MDktOWY3My00NmEzLTlkYTQtZWY4MWNhMGYyMTRmLjAxNzMxYmY0LWU2M2QtNGVmYy1iYjI4LWQ3MWVjOGIxMzA1OXgxNzg3ODIyMTQ4ODg3NDcxMDAw parts=1012792026/08/27 09:15:50 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12802026/08/27 09:15:50 INFO Completed upload id=112812026/08/27 09:15:50 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000012822026/08/27 09:15:50 INFO Received uploads request method=POST path=/api/pending_closures12832026/08/27 09:15:50 INFO Starting cleanup of old closures method=DELETE path=/api/closures12842026/08/27 09:15:50 INFO Aborted multipart uploads count=012852026-08-27 09:15:50.442 UTC [5573] ERROR: relation "goose_db_version" does not exist at character 3612862026-08-27 09:15:50.442 UTC [5573] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12872026/08/27 09:15:50 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=012882026/08/27 09:15:50 INFO Vacuumed table table=pending_closures12892026/08/27 09:15:50 INFO Vacuumed table table=pending_objects12902026/08/27 09:15:50 INFO Vacuumed table table=multipart_uploads12912026/08/27 09:15:50 INFO Vacuumed table table=closures12922026/08/27 09:15:50 INFO Vacuumed table table=objects12932026-08-27 09:15:50.548 UTC [5575] ERROR: relation "goose_db_version" does not exist at character 3612942026-08-27 09:15:50.548 UTC [5575] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12952026/08/27 09:15:50 OK 20241026095416_initial_model.sql (55.69ms)12962026/08/27 09:15:50 OK 20251210153512_drop_unused_gin_index.sql (1.05ms)12972026/08/27 09:15:50 OK 20251218171726_add_pins.sql (1.7ms)12982026/08/27 09:15:50 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000012992026/08/27 09:15:50 OK 20260628120000_add_object_size_and_stats.sql (23.1ms)13002026/08/27 09:15:50 goose: successfully migrated database to version: 202606281200001301--- PASS: TestService_createPendingClosureHandler (3.30s)1302=== CONT TestReadProxyNarinfo13032026/08/27 09:15:50 OK 1_commit_pending_closure.sql (9.08ms)13042026/08/27 09:15:50 OK 2_object_stats_trigger.sql (431.17µs)13052026/08/27 09:15:50 goose: up to current file version: 21306--- PASS: TestReadProxyDisabled (2.58s)1307=== CONT TestResurrectedObjectNotDeleted13082026/08/27 09:15:50 OK 20241026095416_initial_model.sql (198.26ms)13092026/08/27 09:15:50 OK 20251210153512_drop_unused_gin_index.sql (866.88µs)13102026/08/27 09:15:50 OK 20251218171726_add_pins.sql (1.83ms)13112026/08/27 09:15:50 OK 20260628120000_add_object_size_and_stats.sql (26.47ms)13122026/08/27 09:15:50 goose: successfully migrated database to version: 2026062812000013132026/08/27 09:15:50 OK 1_commit_pending_closure.sql (1.93ms)13142026/08/27 09:15:50 OK 2_object_stats_trigger.sql (383.92µs)13152026/08/27 09:15:50 goose: up to current file version: 21316--- PASS: TestReadProxyRootRedirectsToIndexHTML (2.61s)1317=== CONT TestParseSingleRange1318=== RUN TestParseSingleRange/none1319=== PAUSE TestParseSingleRange/none1320=== RUN TestParseSingleRange/unknown_unit1321=== PAUSE TestParseSingleRange/unknown_unit1322=== RUN TestParseSingleRange/multi-range_ignored1323=== PAUSE TestParseSingleRange/multi-range_ignored1324=== RUN TestParseSingleRange/malformed_no_dash1325=== PAUSE TestParseSingleRange/malformed_no_dash1326=== RUN TestParseSingleRange/malformed_both_empty1327=== PAUSE TestParseSingleRange/malformed_both_empty1328=== RUN TestParseSingleRange/malformed_end_before_start1329=== PAUSE TestParseSingleRange/malformed_end_before_start1330=== RUN TestParseSingleRange/closed1331=== PAUSE TestParseSingleRange/closed1332=== RUN TestParseSingleRange/open-ended1333=== PAUSE TestParseSingleRange/open-ended1334=== RUN TestParseSingleRange/end_clamped_to_size1335=== PAUSE TestParseSingleRange/end_clamped_to_size1336=== RUN TestParseSingleRange/suffix1337=== PAUSE TestParseSingleRange/suffix1338=== RUN TestParseSingleRange/suffix_exceeds_size1339=== PAUSE TestParseSingleRange/suffix_exceeds_size1340=== RUN TestParseSingleRange/single_byte1341=== PAUSE TestParseSingleRange/single_byte1342=== RUN TestParseSingleRange/start_past_EOF1343=== PAUSE TestParseSingleRange/start_past_EOF1344=== RUN TestParseSingleRange/start_far_past_EOF1345=== PAUSE TestParseSingleRange/start_far_past_EOF1346=== CONT TestGCTaskStore_GetEmpty1347--- PASS: TestGCTaskStore_GetEmpty (0.00s)1348=== CONT TestPresignedUploadRegisteredBeforeCommit13492026/08/27 09:15:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13502026-08-27 09:15:51.314 UTC [5582] ERROR: relation "goose_db_version" does not exist at character 3613512026-08-27 09:15:51.314 UTC [5582] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13522026-08-27 09:15:51.340 UTC [5583] ERROR: relation "goose_db_version" does not exist at character 3613532026-08-27 09:15:51.340 UTC [5583] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13542026-08-27 09:15:51.342 UTC [5584] ERROR: relation "goose_db_version" does not exist at character 3613552026-08-27 09:15:51.342 UTC [5584] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13562026/08/27 09:15:51 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NGRmNTU5MDktOWY3My00NmEzLTlkYTQtZWY4MWNhMGYyMTRmLmI1NmMzYjI0LTE2MmMtNDcyZi1iMDY3LWM5Njg2OGE1NjgxM3gxNzg3ODIyMTQ5NjAwMzY5MDAw parts=121357--- PASS: TestRedundantMultipartUpload (3.72s)1358=== CONT TestService_Rustfstest13592026-08-27 09:15:51.392 UTC [5587] ERROR: relation "goose_db_version" does not exist at character 3613602026-08-27 09:15:51.392 UTC [5587] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13612026/08/27 09:15:51 OK 20241026095416_initial_model.sql (26.78ms)13622026/08/27 09:15:51 OK 20251210153512_drop_unused_gin_index.sql (552.83µs)13632026/08/27 09:15:51 OK 20241026095416_initial_model.sql (12.23ms)13642026/08/27 09:15:51 OK 20251210153512_drop_unused_gin_index.sql (517.46µs)13652026/08/27 09:15:51 OK 20251218171726_add_pins.sql (1.22ms)13662026/08/27 09:15:51 OK 20251218171726_add_pins.sql (1.75ms)13672026/08/27 09:15:51 OK 20241026095416_initial_model.sql (12.76ms)13682026/08/27 09:15:51 OK 20251210153512_drop_unused_gin_index.sql (509.54µs)13692026/08/27 09:15:51 OK 20251218171726_add_pins.sql (2.09ms)13702026/08/27 09:15:51 OK 20260628120000_add_object_size_and_stats.sql (3.19ms)13712026/08/27 09:15:51 goose: successfully migrated database to version: 2026062812000013722026/08/27 09:15:51 OK 20260628120000_add_object_size_and_stats.sql (5.92ms)13732026/08/27 09:15:51 goose: successfully migrated database to version: 2026062812000013742026/08/27 09:15:51 OK 1_commit_pending_closure.sql (2.16ms)13752026/08/27 09:15:51 OK 2_object_stats_trigger.sql (336.08µs)13762026/08/27 09:15:51 goose: up to current file version: 213772026/08/27 09:15:51 OK 20260628120000_add_object_size_and_stats.sql (3.59ms)13782026/08/27 09:15:51 goose: successfully migrated database to version: 2026062812000013792026/08/27 09:15:51 OK 1_commit_pending_closure.sql (2.04ms)13802026/08/27 09:15:51 OK 2_object_stats_trigger.sql (765.42µs)13812026/08/27 09:15:51 goose: up to current file version: 213822026/08/27 09:15:51 OK 1_commit_pending_closure.sql (1.54ms)13832026/08/27 09:15:51 OK 2_object_stats_trigger.sql (432.08µs)13842026/08/27 09:15:51 goose: up to current file version: 213852026/08/27 09:15:51 OK 20241026095416_initial_model.sql (49.46ms)13862026/08/27 09:15:51 OK 20251210153512_drop_unused_gin_index.sql (14.05ms)13872026/08/27 09:15:51 OK 20251218171726_add_pins.sql (24.88ms)13882026/08/27 09:15:51 OK 20260628120000_add_object_size_and_stats.sql (46.95ms)13892026/08/27 09:15:51 goose: successfully migrated database to version: 2026062812000013902026/08/27 09:15:51 OK 1_commit_pending_closure.sql (11.95ms)13912026/08/27 09:15:51 OK 2_object_stats_trigger.sql (637.38µs)13922026/08/27 09:15:51 goose: up to current file version: 21393--- PASS: TestReadProxyConditionalGet (2.38s)1394=== CONT TestNARDeduplicationMetadataUploadBug1395--- PASS: TestReadProxyHead (2.38s)1396=== CONT TestOrphanedObjectsGCStressTest1397--- PASS: TestReadProxyInvalidPath (2.38s)1398=== CONT TestOrphanedObjectsGC1399--- PASS: TestReadProxyNarStreaming (2.27s)1400=== CONT TestCompletedNarNotReofferedAcrossClosures14012026-08-27 09:15:51.934 UTC [5596] ERROR: relation "goose_db_version" does not exist at character 3614022026-08-27 09:15:51.934 UTC [5596] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14032026/08/27 09:15:52 OK 20241026095416_initial_model.sql (80.71ms)14042026/08/27 09:15:52 OK 20251210153512_drop_unused_gin_index.sql (11.74ms)14052026/08/27 09:15:52 OK 20251218171726_add_pins.sql (19ms)14062026/08/27 09:15:52 OK 20260628120000_add_object_size_and_stats.sql (17.23ms)14072026/08/27 09:15:52 goose: successfully migrated database to version: 2026062812000014082026/08/27 09:15:52 OK 1_commit_pending_closure.sql (4.31ms)14092026/08/27 09:15:52 OK 2_object_stats_trigger.sql (1.84ms)14102026/08/27 09:15:52 goose: up to current file version: 214112026-08-27 09:15:52.207 UTC [5597] ERROR: relation "goose_db_version" does not exist at character 3614122026-08-27 09:15:52.207 UTC [5597] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14132026-08-27 09:15:52.306 UTC [5598] ERROR: relation "goose_db_version" does not exist at character 3614142026-08-27 09:15:52.306 UTC [5598] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1415--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.10s)1416=== CONT TestService_NativeMTLS14172026/08/27 09:15:52 OK 20241026095416_initial_model.sql (87.31ms)14182026-08-27 09:15:52.419 UTC [5601] ERROR: relation "goose_db_version" does not exist at character 3614192026-08-27 09:15:52.419 UTC [5601] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14202026/08/27 09:15:52 OK 20251210153512_drop_unused_gin_index.sql (46.85ms)14212026/08/27 09:15:52 OK 20241026095416_initial_model.sql (88.99ms)14222026/08/27 09:15:52 OK 20251210153512_drop_unused_gin_index.sql (8.63ms)14232026/08/27 09:15:52 OK 20251218171726_add_pins.sql (27.19ms)14242026/08/27 09:15:52 OK 20251218171726_add_pins.sql (17.67ms)14252026/08/27 09:15:52 OK 20260628120000_add_object_size_and_stats.sql (12.4ms)14262026/08/27 09:15:52 goose: successfully migrated database to version: 2026062812000014272026/08/27 09:15:52 OK 1_commit_pending_closure.sql (3.14ms)14282026/08/27 09:15:52 OK 2_object_stats_trigger.sql (607.29µs)14292026/08/27 09:15:52 goose: up to current file version: 214302026/08/27 09:15:52 OK 20260628120000_add_object_size_and_stats.sql (31.28ms)14312026/08/27 09:15:52 goose: successfully migrated database to version: 2026062812000014322026/08/27 09:15:52 OK 1_commit_pending_closure.sql (19.03ms)14332026/08/27 09:15:52 OK 2_object_stats_trigger.sql (3.51ms)14342026/08/27 09:15:52 goose: up to current file version: 214352026/08/27 09:15:52 OK 20241026095416_initial_model.sql (160.8ms)14362026/08/27 09:15:52 OK 20251210153512_drop_unused_gin_index.sql (16.95ms)14372026/08/27 09:15:52 OK 20251218171726_add_pins.sql (44.36ms)1438--- PASS: TestReadProxyNarinfo (2.12s)1439=== CONT TestServerTLSConfig/no_client_CA1440=== CONT TestServerTLSConfig/not_a_PEM_file1441=== CONT TestServerTLSConfig/missing_CA_file1442--- PASS: TestServerTLSConfig (0.00s)1443 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1444 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1445 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1446=== CONT TestClientErrorHandling/InvalidStorePath14472026/08/27 09:15:52 OK 20260628120000_add_object_size_and_stats.sql (34.29ms)14482026/08/27 09:15:52 goose: successfully migrated database to version: 2026062812000014492026/08/27 09:15:52 OK 1_commit_pending_closure.sql (9.29ms)14502026/08/27 09:15:52 OK 2_object_stats_trigger.sql (562.29µs)14512026/08/27 09:15:52 goose: up to current file version: 214522026/08/27 09:15:52 INFO Received uploads request method=POST path=/api/pending_closures1453--- PASS: TestResurrectedObjectNotDeleted (2.27s)1454=== CONT TestClientErrorHandling/ServerNotAvailable14552026/08/27 09:15:53 WARN Rate limiter enabled after throttle name=s3-test rate=514562026/08/27 09:15:53 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1457=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1458 throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=101459 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001460--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.65s)1461=== CONT TestClientErrorHandling/InvalidAuthToken14622026/08/27 09:15:53 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst14632026/08/27 09:15:53 INFO Received uploads request method=POST path=/api/pending_closures1464--- PASS: TestPresignedUploadRegisteredBeforeCommit (2.07s)1465=== CONT TestCacheConfigHandler/full_config,_no_issuer1466=== CONT TestCacheConfigHandler/no_signing_keys1467=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1468=== CONT TestCacheConfigHandler/no_cache_url_configured1469--- PASS: TestCacheConfigHandler (0.00s)1470 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1471 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1472 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1473 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1474=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token14752026/08/27 09:15:53 INFO OIDC auth successful provider=test1476=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected14772026/08/27 09:15:53 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]1478=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1479=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected14802026/08/27 09:15:53 WARN Authentication failed token_preview=eyJhbGciOi...E4v-AZLLRQ 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]1481=== CONT TestIsValidUploadKey/narinfo1482=== CONT TestIsValidUploadKey/realisation_plus_in_output1483=== CONT TestIsValidUploadKey/unknown_type1484=== CONT TestIsValidUploadKey/empty_key1485=== CONT TestIsValidUploadKey/absolute1486=== CONT TestIsValidUploadKey/traversal_nar1487=== CONT TestIsValidUploadKey/traversal1488=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1489=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1490=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1491=== CONT TestIsValidUploadKey/index.html1492=== CONT TestIsValidUploadKey/nix-cache-info1493=== CONT TestIsValidUploadKey/build_log_home-manager_file1494=== CONT TestIsValidUploadKey/realisation1495=== CONT TestIsValidUploadKey/build_log_equals1496=== CONT TestIsValidUploadKey/build_log_question_mark1497=== CONT TestIsValidUploadKey/build_log_plus_in_name1498=== CONT TestIsValidUploadKey/nar_plain1499=== CONT TestIsValidUploadKey/build_log1500=== CONT TestIsValidUploadKey/listing1501=== CONT TestIsValidUploadKey/nar_xz1502=== CONT TestIsValidUploadKey/nar_zst1503--- PASS: TestIsValidUploadKey (0.00s)1504 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1505 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1506 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1507 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1508 --- PASS: TestIsValidUploadKey/absolute (0.00s)1509 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1510 --- PASS: TestIsValidUploadKey/traversal (0.00s)1511 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1512 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1513 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1514 --- PASS: TestIsValidUploadKey/index.html (0.00s)1515 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1516 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1517 --- PASS: TestIsValidUploadKey/realisation (0.00s)1518 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1519 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1520 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1521 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1522 --- PASS: TestIsValidUploadKey/build_log (0.00s)1523 --- PASS: TestIsValidUploadKey/listing (0.00s)1524 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1525 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1526=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15272026/08/27 09:15:53 INFO Received uploads request method=POST path=/1528=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15292026/08/27 09:15:53 INFO Received complete multipart upload request method=POST path=/1530=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15312026/08/27 09:15:53 INFO Received request for more parts method=POST path=/1532=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15332026/08/27 09:15:53 INFO Received uploads request method=POST path=/1534--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1535 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1536 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1537 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1538 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1539=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart15402026/08/27 09:15:53 INFO Received complete multipart upload request method=POST path=/1541--- PASS: TestService_AuthMiddleware_OIDC (1.67s)1542 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1543 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1544 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1545 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)15462026-08-27 09:15:53.103 UTC [5607] ERROR: relation "goose_db_version" does not exist at character 3615472026-08-27 09:15:53.103 UTC [5607] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1548=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure15492026/08/27 09:15:53 INFO Received uploads request method=POST path=/15502026-08-27 09:15:53.149 UTC [5609] ERROR: relation "goose_db_version" does not exist at character 3615512026-08-27 09:15:53.149 UTC [5609] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15522026/08/27 09:15:53 OK 20241026095416_initial_model.sql (54.03ms)15532026/08/27 09:15:53 OK 20251210153512_drop_unused_gin_index.sql (6.63ms)15542026-08-27 09:15:53.228 UTC [5611] ERROR: relation "goose_db_version" does not exist at character 3615552026-08-27 09:15:53.228 UTC [5611] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15562026/08/27 09:15:53 OK 20251218171726_add_pins.sql (19.34ms)15572026-08-27 09:15:53.237 UTC [5614] ERROR: relation "goose_db_version" does not exist at character 3615582026-08-27 09:15:53.237 UTC [5614] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15592026/08/27 09:15:53 OK 20241026095416_initial_model.sql (48.26ms)15602026/08/27 09:15:53 OK 20260628120000_add_object_size_and_stats.sql (10.99ms)15612026/08/27 09:15:53 goose: successfully migrated database to version: 2026062812000015622026/08/27 09:15:53 OK 20251210153512_drop_unused_gin_index.sql (808.83µs)15632026/08/27 09:15:53 OK 20251218171726_add_pins.sql (1.22ms)15642026/08/27 09:15:53 OK 1_commit_pending_closure.sql (1.46ms)15652026/08/27 09:15:53 OK 2_object_stats_trigger.sql (455.83µs)15662026/08/27 09:15:53 goose: up to current file version: 215672026/08/27 09:15:53 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-config15682026/08/27 09:15:53 OK 20260628120000_add_object_size_and_stats.sql (31.32ms)15692026/08/27 09:15:53 goose: successfully migrated database to version: 2026062812000015702026/08/27 09:15:53 OK 1_commit_pending_closure.sql (6.87ms)15712026/08/27 09:15:53 OK 2_object_stats_trigger.sql (214.83µs)15722026/08/27 09:15:53 goose: up to current file version: 215732026-08-27 09:15:53.288 UTC [5615] ERROR: relation "goose_db_version" does not exist at character 3615742026-08-27 09:15:53.288 UTC [5615] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15752026/08/27 09:15:53 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=184.097979ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1576--- PASS: TestService_Rustfstest (2.02s)1577=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts15782026/08/27 09:15:53 INFO Received request for more parts method=POST path=/1579=== CONT TestProxyWriteTimeout/narinfo1580=== CONT TestProxyWriteTimeout/10_GiB_nar1581=== CONT TestProxyWriteTimeout/unknown_size1582=== CONT TestProxyWriteTimeout/1_GiB_nar1583--- PASS: TestProxyWriteTimeout (0.00s)1584 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1585 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1586 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1587 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1588=== CONT TestIsValidCachePath/narinfo1589=== CONT TestIsValidCachePath/index.html1590=== CONT TestIsValidCachePath/short_hash1591=== CONT TestIsValidCachePath/wrong_extension1592=== CONT TestIsValidCachePath/leading_slash1593=== CONT TestIsValidCachePath/empty1594=== CONT TestIsValidCachePath/random_path1595=== CONT TestIsValidCachePath/invalid_char_u1596=== CONT TestIsValidCachePath/invalid_char_e1597=== CONT TestIsValidCachePath/traversal_in_middle1598=== CONT TestIsValidCachePath/traversal_parent1599=== CONT TestIsValidCachePath/nar_uncompressed1600=== CONT TestIsValidCachePath/nix-cache-info1601=== CONT TestIsValidCachePath/realisation1602=== CONT TestIsValidCachePath/log1603=== CONT TestIsValidCachePath/ls1604=== CONT TestIsValidCachePath/nar_xz1605=== CONT TestIsValidCachePath/nar_bz21606=== CONT TestIsValidCachePath/nar_zst1607=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1608--- PASS: TestIsValidCachePath (0.00s)1609 --- PASS: TestIsValidCachePath/narinfo (0.00s)1610 --- PASS: TestIsValidCachePath/index.html (0.00s)1611 --- PASS: TestIsValidCachePath/short_hash (0.00s)1612 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1613 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1614 --- PASS: TestIsValidCachePath/empty (0.00s)1615 --- PASS: TestIsValidCachePath/random_path (0.00s)1616 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1617 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1618 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1619 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1620 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1621 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1622 --- PASS: TestIsValidCachePath/realisation (0.00s)1623 --- PASS: TestIsValidCachePath/log (0.00s)1624 --- PASS: TestIsValidCachePath/ls (0.00s)1625 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1626 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1627 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1628 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1629=== CONT TestParseSingleRange/none1630=== CONT TestParseSingleRange/start_far_past_EOF1631=== CONT TestParseSingleRange/start_past_EOF1632=== CONT TestParseSingleRange/single_byte1633=== CONT TestParseSingleRange/suffix_exceeds_size1634=== CONT TestParseSingleRange/suffix1635=== CONT TestParseSingleRange/end_clamped_to_size1636=== CONT TestParseSingleRange/open-ended1637=== CONT TestParseSingleRange/closed1638=== CONT TestParseSingleRange/malformed_end_before_start1639=== CONT TestParseSingleRange/malformed_both_empty1640=== CONT TestParseSingleRange/malformed_no_dash1641=== CONT TestParseSingleRange/multi-range_ignored1642=== CONT TestParseSingleRange/unknown_unit1643--- PASS: TestParseSingleRange (0.00s)1644 --- PASS: TestParseSingleRange/none (0.00s)1645 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1646 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1647 --- PASS: TestParseSingleRange/single_byte (0.00s)1648 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1649 --- PASS: TestParseSingleRange/suffix (0.00s)1650 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1651 --- PASS: TestParseSingleRange/open-ended (0.00s)1652 --- PASS: TestParseSingleRange/closed (0.00s)1653 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1654 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1655 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1656 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1657 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1658--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)1659 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1660 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1661 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.29s)16622026/08/27 09:15:53 OK 20241026095416_initial_model.sql (147.11ms)16632026/08/27 09:15:53 OK 20241026095416_initial_model.sql (181.33ms)16642026/08/27 09:15:53 OK 20251210153512_drop_unused_gin_index.sql (13.65ms)16652026/08/27 09:15:53 OK 20251210153512_drop_unused_gin_index.sql (13.68ms)16662026/08/27 09:15:53 OK 20251218171726_add_pins.sql (25.14ms)16672026/08/27 09:15:53 OK 20251218171726_add_pins.sql (31.94ms)16682026/08/27 09:15:53 OK 20241026095416_initial_model.sql (130.73ms)16692026/08/27 09:15:53 INFO Created nix-cache-info in bucket bucket=bucket4016702026/08/27 09:15:53 OK 20251210153512_drop_unused_gin_index.sql (8.06ms)16712026/08/27 09:15:53 OK 20260628120000_add_object_size_and_stats.sql (29.91ms)16722026/08/27 09:15:53 goose: successfully migrated database to version: 2026062812000016732026/08/27 09:15:53 OK 20260628120000_add_object_size_and_stats.sql (30.79ms)16742026/08/27 09:15:53 goose: successfully migrated database to version: 2026062812000016752026/08/27 09:15:53 OK 1_commit_pending_closure.sql (1.78ms)16762026/08/27 09:15:53 OK 2_object_stats_trigger.sql (235.92µs)16772026/08/27 09:15:53 goose: up to current file version: 216782026/08/27 09:15:53 OK 1_commit_pending_closure.sql (16.2ms)16792026/08/27 09:15:53 OK 20251218171726_add_pins.sql (32.67ms)16802026/08/27 09:15:53 OK 2_object_stats_trigger.sql (339.29µs)16812026/08/27 09:15:53 goose: up to current file version: 216822026/08/27 09:15:53 OK 20260628120000_add_object_size_and_stats.sql (26.34ms)16832026/08/27 09:15:53 goose: successfully migrated database to version: 2026062812000016842026/08/27 09:15:53 OK 1_commit_pending_closure.sql (5.15ms)16852026/08/27 09:15:53 OK 2_object_stats_trigger.sql (268.08µs)16862026/08/27 09:15:53 goose: up to current file version: 216872026/08/27 09:15:53 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=410.079109ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1688=== NAME TestNARDeduplicationMetadataUploadBug1689 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-5290-2025148623/TestNARDeduplicationMetadataUploadBug412412440/001/store/j9mlc0mhx8ljrzx3q2d4znk031y8j61p-file1.txt16902026/08/27 09:15:53 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16912026/08/27 09:15:53 INFO Received uploads request method=POST path=/api/pending_closures16922026/08/27 09:15:53 INFO Received uploads request method=POST path=/api/pending_closures16932026/08/27 09:15:53 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16942026/08/27 09:15:53 INFO Uploading j9mlc0mhx8ljrzx3q2d4znk031y8j61p-file1.txt (160B)16952026/08/27 09:15:53 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"16962026/08/27 09:15:53 WARN Failed to register uploaded object key=j9mlc0mhx8ljrzx3q2d4znk031y8j61p.ls error="server returned 404: 404 page not found\n"16972026/08/27 09:15:53 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16982026/08/27 09:15:53 INFO Signed narinfos id=1 count=116992026/08/27 09:15:53 INFO Uploading 1 narinfos17002026/08/27 09:15:53 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=826.336037ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17012026/08/27 09:15:53 WARN Failed to register uploaded object key=j9mlc0mhx8ljrzx3q2d4znk031y8j61p.narinfo error="server returned 404: 404 page not found\n"17022026/08/27 09:15:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17032026/08/27 09:15:54 INFO Completed upload id=117042026/08/27 09:15:54 INFO Upload complete. (313ms)1705 metadata_upload_test.go:54: Retrieved narinfo from S3:1706 StorePath: /nix/var/nix/builds/nix-5290-2025148623/TestNARDeduplicationMetadataUploadBug412412440/001/store/j9mlc0mhx8ljrzx3q2d4znk031y8j61p-file1.txt1707 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1708 Compression: zstd1709 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1710 NarSize: 1601711 References: 1712 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1713 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1714 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1715 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1716 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-5290-2025148623/TestNARDeduplicationMetadataUploadBug412412440/001/store/01fa32jpsmm309zpyn4kbpsaqwc34045-file2.txt17172026-08-27 09:15:54.150 UTC [5627] ERROR: relation "goose_db_version" does not exist at character 3617182026-08-27 09:15:54.150 UTC [5627] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17192026/08/27 09:15:54 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17202026/08/27 09:15:54 INFO Received uploads request method=POST path=/api/pending_closures17212026/08/27 09:15:54 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17222026/08/27 09:15:54 WARN Failed to register uploaded object key=01fa32jpsmm309zpyn4kbpsaqwc34045.ls error="server returned 404: 404 page not found\n"17232026/08/27 09:15:54 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign17242026/08/27 09:15:54 INFO Signed narinfos id=2 count=117252026/08/27 09:15:54 INFO Uploading 1 narinfos17262026/08/27 09:15:54 WARN Failed to register uploaded object key=01fa32jpsmm309zpyn4kbpsaqwc34045.narinfo error="server returned 404: 404 page not found\n"17272026/08/27 09:15:54 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17282026/08/27 09:15:54 INFO Completed upload id=217292026/08/27 09:15:54 INFO Upload complete. (191ms)1730 metadata_upload_test.go:76: Retrieved narinfo from S3:1731 StorePath: /nix/var/nix/builds/nix-5290-2025148623/TestNARDeduplicationMetadataUploadBug412412440/001/store/01fa32jpsmm309zpyn4kbpsaqwc34045-file2.txt1732 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1733 Compression: zstd1734 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1735 NarSize: 1601736 References: 1737 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1738 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1739 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1740 {"version":1,"root":{"type":"regular","size":44}}1741--- PASS: TestNARDeduplicationMetadataUploadBug (2.86s)17422026/08/27 09:15:54 OK 20241026095416_initial_model.sql (210.4ms)17432026/08/27 09:15:54 OK 20251210153512_drop_unused_gin_index.sql (7.09ms)17442026/08/27 09:15:54 OK 20251218171726_add_pins.sql (42.84ms)17452026/08/27 09:15:54 OK 20260628120000_add_object_size_and_stats.sql (12.63ms)17462026/08/27 09:15:54 goose: successfully migrated database to version: 2026062812000017472026/08/27 09:15:54 OK 1_commit_pending_closure.sql (4.06ms)17482026/08/27 09:15:54 OK 2_object_stats_trigger.sql (605.25µs)17492026/08/27 09:15:54 goose: up to current file version: 21750=== NAME TestOrphanedObjectsGC1751 orphaned_objects_gc_test.go:290: GC Test Summary:1752 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1753 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1754 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1755 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1756 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1757--- PASS: TestOrphanedObjectsGC (2.95s)17582026/08/27 09:15:54 WARN mTLS auth: subject not in bound subjects subject="CN=reader"17592026/08/27 09:15:54 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1760--- PASS: TestService_NativeMTLS (2.40s)17612026-08-27 09:15:54.785 UTC [5634] ERROR: relation "goose_db_version" does not exist at character 3617622026-08-27 09:15:54.785 UTC [5634] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17632026/08/27 09:15:54 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.463197947s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17642026/08/27 09:15:55 OK 20241026095416_initial_model.sql (161.45ms)17652026/08/27 09:15:55 OK 20251210153512_drop_unused_gin_index.sql (11.87ms)17662026/08/27 09:15:55 OK 20251218171726_add_pins.sql (26.42ms)17672026/08/27 09:15:55 OK 20260628120000_add_object_size_and_stats.sql (45.47ms)17682026/08/27 09:15:55 goose: successfully migrated database to version: 2026062812000017692026/08/27 09:15:55 OK 1_commit_pending_closure.sql (23.28ms)17702026/08/27 09:15:55 OK 2_object_stats_trigger.sql (2.06ms)17712026/08/27 09:15:55 goose: up to current file version: 217722026-08-27 09:15:55.182 UTC [5635] ERROR: relation "goose_db_version" does not exist at character 3617732026-08-27 09:15:55.182 UTC [5635] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17742026/08/27 09:15:55 OK 20241026095416_initial_model.sql (142.33ms)17752026/08/27 09:15:55 OK 20251210153512_drop_unused_gin_index.sql (11.36ms)17762026/08/27 09:15:55 OK 20251218171726_add_pins.sql (23.38ms)17772026/08/27 09:15:55 OK 20260628120000_add_object_size_and_stats.sql (30.95ms)17782026/08/27 09:15:55 goose: successfully migrated database to version: 2026062812000017792026/08/27 09:15:55 OK 1_commit_pending_closure.sql (5.4ms)17802026/08/27 09:15:55 OK 2_object_stats_trigger.sql (380.29µs)17812026/08/27 09:15:55 goose: up to current file version: 217822026/08/27 09:15:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17832026/08/27 09:15:55 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NGRmNTU5MDktOWY3My00NmEzLTlkYTQtZWY4MWNhMGYyMTRmLmEwMDExYjdlLWMxNDUtNDE2OC05YjhiLTgyYzM4YmZlZTljYXgxNzg3ODIyMTUzODg1MjA4MDAw parts=1217842026/08/27 09:15:55 INFO Received uploads request method=POST path=/api/pending_closures1785--- PASS: TestCompletedNarNotReofferedAcrossClosures (3.88s)17862026/08/27 09:15:55 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17872026/08/27 09:15:55 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"17882026/08/27 09:15:56 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"17892026/08/27 09:15:56 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_closures17902026/08/27 09:15:56 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=189.951597ms 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:15:56 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=389.5401ms 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:15:57 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=743.467842ms 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:15:57 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.677844414s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1794--- PASS: TestClientErrorHandling (0.00s)1795 --- PASS: TestClientErrorHandling/InvalidStorePath (2.63s)1796 --- PASS: TestClientErrorHandling/InvalidAuthToken (2.95s)1797 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.48s)1798=== NAME TestOrphanedObjectsGCStressTest1799 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1800 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion1801 orphaned_objects_gc_test.go:509: Stress test completed successfully:1802 orphaned_objects_gc_test.go:510: - Active objects preserved: 201803 orphaned_objects_gc_test.go:511: - Objects deleted: 2101804 orphaned_objects_gc_test.go:512: - Total GC'd: 2101805--- PASS: TestOrphanedObjectsGCStressTest (8.22s)1806PASS1807{"timestamp":"2026-08-27T09:15:59.885131Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:50174","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)"}18082026-08-27 09:15:59.954 UTC [5325] LOG: received smart shutdown request18092026-08-27 09:15:59.955 UTC [5325] LOG: background worker "logical replication launcher" (PID 5336) exited with exit code 118102026-08-27 09:15:59.963 UTC [5330] LOG: shutting down18112026-08-27 09:15:59.964 UTC [5330] LOG: checkpoint starting: shutdown immediate18122026-08-27 09:16:00.982 UTC [5330] LOG: checkpoint complete: wrote 13510 buffers (82.5%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 13 recycled; write=0.752 s, sync=0.264 s, total=1.019 s; sync files=15167, longest=0.011 s, average=0.001 s; distance=212549 kB, estimate=212549 kB; lsn=0/E71C548, redo lsn=0/E71C54818132026-08-27 09:16:00.986 UTC [5325] LOG: database system is shut down1814Running OIDC tests...1815=== RUN TestGlobMatch1816=== PAUSE TestGlobMatch1817=== RUN TestAudienceForIssuer1818=== PAUSE TestAudienceForIssuer1819=== RUN TestValidateToken_ValidToken1820=== PAUSE TestValidateToken_ValidToken1821=== RUN TestValidateToken_WrongAudience1822=== PAUSE TestValidateToken_WrongAudience1823=== RUN TestValidateToken_Expired1824=== PAUSE TestValidateToken_Expired1825=== RUN TestValidateToken_BoundClaimsMismatch1826=== PAUSE TestValidateToken_BoundClaimsMismatch1827=== RUN TestValidateToken_BoundSubjectMismatch1828=== PAUSE TestValidateToken_BoundSubjectMismatch1829=== RUN TestValidateToken_MultipleProviders1830=== PAUSE TestValidateToken_MultipleProviders1831=== RUN TestValidateToken_NoMatchingProvider1832=== PAUSE TestValidateToken_NoMatchingProvider1833=== CONT TestGlobMatch1834=== RUN TestGlobMatch/foo_foo1835=== PAUSE TestGlobMatch/foo_foo1836=== RUN TestGlobMatch/foo_bar1837=== PAUSE TestGlobMatch/foo_bar1838=== CONT TestValidateToken_MultipleProviders1839=== CONT TestValidateToken_NoMatchingProvider1840=== CONT TestValidateToken_BoundSubjectMismatch1841=== CONT TestValidateToken_ValidToken1842=== CONT TestAudienceForIssuer1843--- PASS: TestAudienceForIssuer (0.00s)1844=== CONT TestValidateToken_Expired1845=== CONT TestValidateToken_BoundClaimsMismatch1846=== RUN TestGlobMatch/*_1847=== PAUSE TestGlobMatch/*_1848=== RUN TestGlobMatch/*_anything1849=== PAUSE TestGlobMatch/*_anything1850=== RUN TestGlobMatch/foo*_foo1851=== PAUSE TestGlobMatch/foo*_foo1852=== RUN TestGlobMatch/foo*_foobar1853=== PAUSE TestGlobMatch/foo*_foobar1854=== RUN TestGlobMatch/foo*_bar1855=== PAUSE TestGlobMatch/foo*_bar1856=== RUN TestGlobMatch/*bar_bar1857=== PAUSE TestGlobMatch/*bar_bar1858=== RUN TestGlobMatch/*bar_foobar1859=== PAUSE TestGlobMatch/*bar_foobar1860=== RUN TestGlobMatch/*bar_foo1861=== PAUSE TestGlobMatch/*bar_foo1862=== RUN TestGlobMatch/foo*bar_foobar1863=== PAUSE TestGlobMatch/foo*bar_foobar1864=== RUN TestGlobMatch/foo*bar_foo123bar1865=== PAUSE TestGlobMatch/foo*bar_foo123bar1866=== RUN TestGlobMatch/foo*bar_foobarbaz1867=== PAUSE TestGlobMatch/foo*bar_foobarbaz1868=== RUN TestGlobMatch/*/*_foo/bar1869=== PAUSE TestGlobMatch/*/*_foo/bar1870=== RUN TestGlobMatch/*/*_foo1871=== PAUSE TestGlobMatch/*/*_foo1872=== RUN TestGlobMatch/refs/heads/*_refs/heads/main1873=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main1874=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.01875=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.01876=== RUN TestGlobMatch/refs/*/main_refs/heads/main1877=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main1878=== RUN TestGlobMatch/fo?_foo1879=== PAUSE TestGlobMatch/fo?_foo1880=== RUN TestGlobMatch/fo?_fo1881=== PAUSE TestGlobMatch/fo?_fo1882=== RUN TestGlobMatch/fo?_fooo1883=== PAUSE TestGlobMatch/fo?_fooo1884=== RUN TestGlobMatch/?oo_foo1885=== PAUSE TestGlobMatch/?oo_foo1886=== RUN TestGlobMatch/?oo_boo1887=== PAUSE TestGlobMatch/?oo_boo1888=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1889=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1890=== CONT TestValidateToken_WrongAudience1891=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1892=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1893=== CONT TestGlobMatch/foo_foo1894=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1895=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1896=== CONT TestGlobMatch/?oo_boo1897=== CONT TestGlobMatch/?oo_foo1898=== CONT TestGlobMatch/fo?_fooo1899=== CONT TestGlobMatch/fo?_fo1900=== CONT TestGlobMatch/fo?_foo1901=== CONT TestGlobMatch/refs/*/main_refs/heads/main1902=== CONT TestGlobMatch/*bar_foobar1903=== CONT TestGlobMatch/*bar_bar1904=== CONT TestGlobMatch/foo*_bar1905=== CONT TestGlobMatch/foo*_foobar1906=== CONT TestGlobMatch/foo*_foo1907=== CONT TestGlobMatch/*_anything1908=== CONT TestGlobMatch/*_1909=== CONT TestGlobMatch/foo_bar1910=== CONT TestGlobMatch/*/*_foo/bar1911=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.01912=== CONT TestGlobMatch/refs/heads/*_refs/heads/main1913=== CONT TestGlobMatch/*/*_foo1914=== CONT TestGlobMatch/foo*bar_foo123bar1915=== CONT TestGlobMatch/foo*bar_foobarbaz1916=== CONT TestGlobMatch/*bar_foo1917=== CONT TestGlobMatch/foo*bar_foobar1918--- PASS: TestGlobMatch (0.00s)1919 --- PASS: TestGlobMatch/foo_foo (0.00s)1920 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)1921 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)1922 --- PASS: TestGlobMatch/?oo_boo (0.00s)1923 --- PASS: TestGlobMatch/?oo_foo (0.00s)1924 --- PASS: TestGlobMatch/fo?_fooo (0.00s)1925 --- PASS: TestGlobMatch/fo?_fo (0.00s)1926 --- PASS: TestGlobMatch/fo?_foo (0.00s)1927 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)1928 --- PASS: TestGlobMatch/*bar_foobar (0.00s)1929 --- PASS: TestGlobMatch/*bar_bar (0.00s)1930 --- PASS: TestGlobMatch/foo*_bar (0.00s)1931 --- PASS: TestGlobMatch/foo*_foobar (0.00s)1932 --- PASS: TestGlobMatch/foo*_foo (0.00s)1933 --- PASS: TestGlobMatch/*_anything (0.00s)1934 --- PASS: TestGlobMatch/*_ (0.00s)1935 --- PASS: TestGlobMatch/foo_bar (0.00s)1936 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)1937 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)1938 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)1939 --- PASS: TestGlobMatch/*/*_foo (0.00s)1940 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)1941 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)1942 --- PASS: TestGlobMatch/*bar_foo (0.00s)1943 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)19442026/08/27 09:16:01 INFO OIDC provider initialized name=provider119452026/08/27 09:16:01 INFO OIDC provider initialized name=test19462026/08/27 09:16:01 INFO OIDC provider initialized name=test19472026/08/27 09:16:01 INFO OIDC provider initialized name=test19482026/08/27 09:16:01 INFO OIDC provider initialized name=test19492026/08/27 09:16:01 INFO OIDC provider initialized name=provider119502026/08/27 09:16:01 INFO OIDC provider initialized name=test19512026/08/27 09:16:01 INFO OIDC provider initialized name=provider21952--- PASS: TestValidateToken_NoMatchingProvider (0.01s)1953--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)1954--- PASS: TestValidateToken_WrongAudience (0.01s)1955--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)1956--- PASS: TestValidateToken_Expired (0.01s)1957--- PASS: TestValidateToken_ValidToken (0.01s)1958--- PASS: TestValidateToken_MultipleProviders (0.01s)1959PASS1960Running hook tests...1961=== RUN TestSendPathsEmpty1962=== PAUSE TestSendPathsEmpty1963=== RUN TestQueueEnqueueAndFetch1964=== PAUSE TestQueueEnqueueAndFetch1965=== RUN TestQueueDeduplication1966=== PAUSE TestQueueDeduplication1967=== RUN TestQueueRemove1968=== PAUSE TestQueueRemove1969=== RUN TestQueueFetchBatchLimit1970=== PAUSE TestQueueFetchBatchLimit1971=== RUN TestQueueRetryMovesToBack1972=== PAUSE TestQueueRetryMovesToBack1973=== RUN TestQueueFetchRemoveLifecycle1974=== PAUSE TestQueueFetchRemoveLifecycle1975=== RUN TestQueueConcurrentWriters1976=== PAUSE TestQueueConcurrentWriters1977=== RUN TestServerClientIntegration1978=== PAUSE TestServerClientIntegration1979=== RUN TestServerQueueError1980=== PAUSE TestServerQueueError1981=== RUN TestGetListenerSocketActivation1982 server_test.go:210: === RUN TestGetListenerSocketActivation1983 --- PASS: TestGetListenerSocketActivation (0.00s)1984 PASS1985 1986--- PASS: TestGetListenerSocketActivation (0.01s)1987=== RUN TestDrainIsolatesPoisonPath1988=== PAUSE TestDrainIsolatesPoisonPath1989=== RUN TestRunNotBlockedByPoisonHead1990=== PAUSE TestRunNotBlockedByPoisonHead1991=== RUN TestDrainGivesUpWhenServerDown1992=== PAUSE TestDrainGivesUpWhenServerDown1993=== RUN TestFailedPathPrunedByLaterClosure1994=== PAUSE TestFailedPathPrunedByLaterClosure1995=== RUN TestWorkerUploadsAndRemoves1996=== PAUSE TestWorkerUploadsAndRemoves1997=== RUN TestWorkerSkipsGCdPaths1998=== PAUSE TestWorkerSkipsGCdPaths1999=== RUN TestWorkerPrunesClosureDeps2000=== PAUSE TestWorkerPrunesClosureDeps2001=== CONT TestSendPathsEmpty2002=== CONT TestServerQueueError2003=== CONT TestFailedPathPrunedByLaterClosure2004--- PASS: TestSendPathsEmpty (0.00s)2005=== CONT TestServerClientIntegration2006=== CONT TestQueueConcurrentWriters2007=== CONT TestQueueFetchRemoveLifecycle2008=== CONT TestQueueRetryMovesToBack2009=== CONT TestQueueFetchBatchLimit2010=== CONT TestQueueRemove2011=== CONT TestQueueDeduplication2012=== CONT TestQueueEnqueueAndFetch20132026/08/27 09:16:02 ERROR Failed to queue paths error="permission denied" count=12014--- PASS: TestServerClientIntegration (0.00s)2015=== CONT TestRunNotBlockedByPoisonHead2016--- PASS: TestServerQueueError (0.00s)2017=== CONT TestDrainGivesUpWhenServerDown2018--- PASS: TestQueueFetchBatchLimit (0.01s)2019=== CONT TestWorkerSkipsGCdPaths20202026/08/27 09:16:02 INFO Uploading batch count=12021--- PASS: TestQueueEnqueueAndFetch (0.01s)20222026/08/27 09:16:02 ERROR Upload failed error="upload failed" count=12023=== CONT TestWorkerPrunesClosureDeps2024--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2025=== CONT TestWorkerUploadsAndRemoves2026--- PASS: TestQueueRetryMovesToBack (0.01s)2027=== CONT TestDrainIsolatesPoisonPath2028--- PASS: TestQueueDeduplication (0.01s)20292026/08/27 09:16:02 INFO Uploading batch count=120302026/08/27 09:16:02 INFO Uploading batch count=220312026/08/27 09:16:02 ERROR Upload failed error="upload failed" count=220322026/08/27 09:16:02 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-5290-2025148623/TestDrainGivesUpWhenServerDown775322838/002/a20332026/08/27 09:16:02 INFO Uploading batch count=120342026/08/27 09:16:02 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-5290-2025148623/TestDrainGivesUpWhenServerDown775322838/002/b2035--- PASS: TestQueueRemove (0.01s)20362026/08/27 09:16:02 INFO Upload queue status pending=320372026/08/27 09:16:02 INFO Uploading batch count=120382026/08/27 09:16:02 ERROR Upload failed error="upload failed" count=120392026/08/27 09:16:02 INFO Uploading batch count=220402026/08/27 09:16:02 ERROR Upload failed error="upload failed" count=220412026/08/27 09:16:02 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-5290-2025148623/TestDrainGivesUpWhenServerDown775322838/002/c20422026/08/27 09:16:02 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-5290-2025148623/TestDrainGivesUpWhenServerDown775322838/002/d20432026/08/27 09:16:02 INFO Uploading batch count=220442026/08/27 09:16:02 ERROR Upload failed error="upload failed" count=220452026/08/27 09:16:02 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-5290-2025148623/TestDrainGivesUpWhenServerDown775322838/002/e20462026/08/27 09:16:02 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-5290-2025148623/TestDrainGivesUpWhenServerDown775322838/002/f20472026/08/27 09:16:02 INFO Upload queue status pending=220482026/08/27 09:16:02 ERROR Drain finished with paths left in queue remaining=1020492026/08/27 09:16:02 INFO Uploading batch count=12050--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)20512026/08/27 09:16:02 INFO Upload queue status pending=220522026/08/27 09:16:02 INFO Uploading batch count=220532026/08/27 09:16:02 INFO Uploading batch count=420542026/08/27 09:16:02 ERROR Upload failed error="upload failed" count=420552026/08/27 09:16:02 INFO Upload queue status pending=220562026/08/27 09:16:02 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-5290-2025148623/TestDrainIsolatesPoisonPath1338825988/002/bbb20572026/08/27 09:16:02 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-5290-2025148623/TestWorkerSkipsGCdPaths3449361305/002/nonexistent20582026/08/27 09:16:02 INFO Uploading batch count=120592026/08/27 09:16:02 INFO Uploading batch count=120602026/08/27 09:16:02 ERROR Upload failed error="upload failed" count=120612026/08/27 09:16:02 INFO Uploading batch count=120622026/08/27 09:16:02 ERROR Upload failed error="upload failed" count=120632026/08/27 09:16:02 INFO Uploading batch count=120642026/08/27 09:16:02 ERROR Upload failed error="upload failed" count=12065--- PASS: TestDrainGivesUpWhenServerDown (0.01s)20662026/08/27 09:16:02 ERROR Drain finished with paths left in queue remaining=12067--- PASS: TestDrainIsolatesPoisonPath (0.01s)2068--- PASS: TestWorkerPrunesClosureDeps (0.02s)2069--- PASS: TestWorkerSkipsGCdPaths (0.02s)2070--- PASS: TestWorkerUploadsAndRemoves (0.02s)2071--- PASS: TestQueueConcurrentWriters (0.16s)20722026/08/27 09:16:03 INFO Uploading batch count=120732026/08/27 09:16:03 INFO Uploading batch count=120742026/08/27 09:16:03 INFO Uploading batch count=120752026/08/27 09:16:03 ERROR Upload failed error="upload failed" count=120762026/08/27 09:16:03 INFO Uploading batch count=120772026/08/27 09:16:03 ERROR Upload failed error="upload failed" count=120782026/08/27 09:16:03 INFO Uploading batch count=120792026/08/27 09:16:03 ERROR Upload failed error="upload failed" count=120802026/08/27 09:16:03 INFO Uploading batch count=120812026/08/27 09:16:03 ERROR Upload failed error="upload failed" count=120822026/08/27 09:16:03 ERROR Drain finished with paths left in queue remaining=12083--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2084PASS