niks3-go-unit-tests
aarch64-darwin.go-unit-tests
· build #110
· 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 TestDumpPathMatchesNix78=== CONT TestRateLimiterFeedback79=== RUN TestRateLimiterFeedback/429_enables_limiter80=== PAUSE TestRateLimiterFeedback/429_enables_limiter81=== RUN TestRateLimiterFeedback/503_enables_limiter82=== CONT TestPartSizeForNAR83=== PAUSE TestRateLimiterFeedback/503_enables_limiter84=== CONT TestPathInfoCACompatibility85=== CONT TestParsePathInfoJSONMultiplePaths86=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths87=== RUN TestPartSizeForNAR/zero_stays_at_minimum88=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths89=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths90=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths91=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum92=== RUN TestPartSizeForNAR/small_stays_at_minimum93=== PAUSE TestPartSizeForNAR/small_stays_at_minimum94=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum95=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum96=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts97=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts98=== RUN TestPartSizeForNAR/1_TiB99=== PAUSE TestPartSizeForNAR/1_TiB100=== RUN TestPartSizeForNAR/5_TiB_S3_max_object101=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object102=== RUN TestPartSizeForNAR/capped_at_5_GiB103=== PAUSE TestPartSizeForNAR/capped_at_5_GiB104=== CONT TestScriptTokenScriptFails105=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter106=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter1072026/07/19 11:39:20 WARN Rate limiter enabled after throttle name=server-test rate=5108=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter109=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter110=== CONT TestScriptTokenBadJSON111=== CONT TestScriptTokenEmptyToken112=== RUN TestPathInfoCACompatibility/null_ca_field113=== CONT TestFileTokenMissing114=== CONT TestScriptTokenEmptyCommand115--- PASS: TestScriptTokenEmptyCommand (0.00s)116=== CONT TestScriptTokenCachesUntilRefresh117=== PAUSE TestPathInfoCACompatibility/null_ca_field118=== RUN TestPathInfoCACompatibility/old_string_format_-_text119=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text120=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive121=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive122=== RUN TestPathInfoCACompatibility/new_structured_format_-_text123=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text124=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method125=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method126=== CONT TestScriptTokenNoExpiryRerunsEveryCall127--- PASS: TestFileTokenMissing (0.00s)128=== CONT TestFileTokenEmpty129--- PASS: TestFileTokenEmpty (0.00s)130--- PASS: TestResolveStorePath (0.01s)131=== CONT TestEncodeNixBase32132=== RUN TestEncodeNixBase32/test_string_hash133=== PAUSE TestEncodeNixBase32/test_string_hash134=== RUN TestEncodeNixBase32/empty_input135=== PAUSE TestEncodeNixBase32/empty_input136=== CONT TestCaseHackSuffix137=== CONT TestDumpPathWriterError138--- PASS: TestDoServerRequestAttachesToken (0.01s)139=== CONT TestFilterOversizedClosures140=== RUN TestFilterOversizedClosures/no_limit_keeps_everything141=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything142=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped143=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped144=== RUN TestFilterOversizedClosures/all_closures_skipped145=== PAUSE TestFilterOversizedClosures/all_closures_skipped146=== CONT TestPathInfoHashCompatibility147=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)148=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)149=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon150=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon151=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI152=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI153=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512154=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512155=== CONT TestParsePathInfoJSON156=== RUN TestParsePathInfoJSON/Nix_format157=== PAUSE TestParsePathInfoJSON/Nix_format158=== RUN TestParsePathInfoJSON/Lix_format159=== PAUSE TestParsePathInfoJSON/Lix_format160=== RUN TestParsePathInfoJSON/empty_input161=== PAUSE TestParsePathInfoJSON/empty_input162=== RUN TestParsePathInfoJSON/whitespace_only163=== PAUSE TestParsePathInfoJSON/whitespace_only164=== RUN TestParsePathInfoJSON/invalid_JSON165=== PAUSE TestParsePathInfoJSON/invalid_JSON166=== CONT TestDumpPathSingleFile167--- PASS: TestScriptTokenScriptFails (0.01s)168=== CONT TestSetClientTLSDoesNotMutateDefaultTransport169--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)170=== CONT TestFileTokenReadsAndCaches171--- PASS: TestFileTokenReadsAndCaches (0.00s)172=== CONT TestStaticToken173--- PASS: TestStaticToken (0.00s)174=== CONT TestSetClientTLSErrors175=== RUN TestSetClientTLSErrors/missing_cert_file176=== PAUSE TestSetClientTLSErrors/missing_cert_file177=== RUN TestSetClientTLSErrors/missing_key_file178=== PAUSE TestSetClientTLSErrors/missing_key_file179=== RUN TestSetClientTLSErrors/missing_ca_file180=== PAUSE TestSetClientTLSErrors/missing_ca_file181=== RUN TestSetClientTLSErrors/invalid_ca_file182=== PAUSE TestSetClientTLSErrors/invalid_ca_file183=== CONT TestShellSplitErrors184--- PASS: TestShellSplitErrors (0.00s)185=== CONT TestSetClientTLS186--- PASS: TestScriptTokenBadJSON (0.02s)187=== CONT TestShellSplit188--- PASS: TestShellSplit (0.00s)189=== CONT TestGetStorePathHash190=== RUN TestGetStorePathHash/valid_store_path191=== PAUSE TestGetStorePathHash/valid_store_path192=== RUN TestGetStorePathHash/basename_without_hyphen_should_error193=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error194=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error195=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error196=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error197=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error198=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths199=== CONT TestConvertHashToNix32200=== RUN TestConvertHashToNix32/SRI_format_to_Nix32201=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32202=== RUN TestConvertHashToNix32/already_Nix32_format203=== PAUSE TestConvertHashToNix32/already_Nix32_format204=== RUN TestConvertHashToNix32/invalid_format205=== PAUSE TestConvertHashToNix32/invalid_format206=== CONT TestPartSizeForNAR/zero_stays_at_minimum207=== CONT TestUploadMultipart_SupersededByPeer208=== RUN TestUploadMultipart_SupersededByPeer/exists209=== PAUSE TestUploadMultipart_SupersededByPeer/exists210=== RUN TestUploadMultipart_SupersededByPeer/missing211=== PAUSE TestUploadMultipart_SupersededByPeer/missing212=== CONT TestDoWithRetry_BodyReplayedViaGetBody2132026/07/19 11:39:20 WARN Rate limiter enabled after throttle name=server-test rate=52142026/07/19 11:39:20 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:605962152026/07/19 11:39:20 WARN Rate limiter backed off name=server-test rate=52162026/07/19 11:39:20 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:60596217--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)218=== CONT TestPartSizeForNAR/5_TiB_S3_max_object219=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths220--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)221 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)222 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)223=== CONT TestRateLimiterFeedback/429_enables_limiter2242026/07/19 11:39:20 WARN Rate limiter enabled after throttle name=server-test rate=52252026/07/19 11:39:20 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:605992262026/07/19 11:39:20 WARN Rate limiter backed off name=server-test rate=5227=== RUN TestSetClientTLS/rejects_connection_without_client_cert228=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts229=== CONT TestPartSizeForNAR/1_TiB230=== CONT TestPartSizeForNAR/capped_at_5_GiB231=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter232=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert233=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA234=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA235=== RUN TestSetClientTLS/preserves_debug_logging_transport236=== PAUSE TestSetClientTLS/preserves_debug_logging_transport237=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter238=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum239--- PASS: TestScriptTokenEmptyToken (0.02s)240=== CONT TestPartSizeForNAR/small_stays_at_minimum241=== CONT TestPathInfoCACompatibility/null_ca_field242=== CONT TestPathInfoCACompatibility/new_structured_format_-_text243=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method244=== CONT TestRateLimiterFeedback/503_enables_limiter245=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive246=== CONT TestPathInfoCACompatibility/old_string_format_-_text247=== CONT TestEncodeNixBase32/test_string_hash248=== CONT TestFilterOversizedClosures/no_limit_keeps_everything249=== CONT TestEncodeNixBase32/empty_input250=== CONT TestFilterOversizedClosures/all_closures_skipped251=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2522026/07/19 11:39:20 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=502532026/07/19 11:39:20 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=2000254=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)255=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI256=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512257--- PASS: TestPartSizeForNAR (0.00s)258 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)259 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)260 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)261 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)262 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)263 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)264 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)265=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon266=== CONT TestParsePathInfoJSON/Nix_format267--- PASS: TestPathInfoCACompatibility (0.00s)268 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)269 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)270 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)271 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)272 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)273--- PASS: TestEncodeNixBase32 (0.00s)274 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)275 --- PASS: TestEncodeNixBase32/empty_input (0.00s)276--- PASS: TestFilterOversizedClosures (0.00s)277 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)278 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)279 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)280=== CONT TestParsePathInfoJSON/whitespace_only281--- PASS: TestPathInfoHashCompatibility (0.00s)282 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)283 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)284 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)285 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)286=== CONT TestParsePathInfoJSON/Lix_format287=== CONT TestParsePathInfoJSON/invalid_JSON288=== CONT TestSetClientTLSErrors/missing_cert_file289=== CONT TestParsePathInfoJSON/empty_input290=== CONT TestSetClientTLSErrors/missing_ca_file291--- PASS: TestParsePathInfoJSON (0.00s)292 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)293 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)294 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)295 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)296 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)297=== CONT TestSetClientTLSErrors/invalid_ca_file2982026/07/19 11:39:20 WARN Rate limiter enabled after throttle name=server-test rate=52992026/07/19 11:39:20 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:606053002026/07/19 11:39:20 WARN Rate limiter backed off name=server-test rate=5301--- PASS: TestRateLimiterFeedback (0.00s)302 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)303 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)304 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)305 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)306=== CONT TestSetClientTLSErrors/missing_key_file307=== CONT TestGetStorePathHash/valid_store_path308=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error309=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error310=== CONT TestConvertHashToNix32/SRI_format_to_Nix32311=== CONT TestGetStorePathHash/basename_without_hyphen_should_error312--- PASS: TestGetStorePathHash (0.00s)313 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)314 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)315 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)316 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)317=== CONT TestConvertHashToNix32/invalid_format318=== CONT TestUploadMultipart_SupersededByPeer/exists319=== CONT TestConvertHashToNix32/already_Nix32_format320--- PASS: TestConvertHashToNix32 (0.00s)321 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)322 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)323 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)324=== CONT TestUploadMultipart_SupersededByPeer/missing325=== CONT TestSetClientTLS/rejects_connection_without_client_cert326--- PASS: TestSetClientTLSErrors (0.00s)327 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)328 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)329 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)330 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)331=== CONT TestSetClientTLS/preserves_debug_logging_transport332--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)333 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)334 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)335=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3362026/07/19 11:39:20 http: TLS handshake error from 127.0.0.1:60609: remote error: tls: bad certificate337--- PASS: TestSetClientTLS (0.00s)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: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)342--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)343--- PASS: TestDumpPathWriterError (0.04s)344--- PASS: TestDumpPathSingleFile (0.05s)345--- PASS: TestCaseHackSuffix (0.05s)346--- PASS: TestDumpPathMatchesNix (0.08s)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-16068-4224019181/postgres209616802/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-16068-4224019181/postgres209616802/data -l logfile start376377/nix/var/nix/builds/nix-16068-4224019181/postgres209616802:5432 - no response3782026-07-19 11:39:22.654 UTC [16104] LOG: starting PostgreSQL 18.4 on aarch64-apple-darwin25.3.0, compiled by clang version 21.1.8, 64-bit3792026-07-19 11:39:22.654 UTC [16104] LOG: listening on Unix socket "/nix/var/nix/builds/nix-16068-4224019181/postgres209616802/.s.PGSQL.5432"3802026-07-19 11:39:22.656 UTC [16111] LOG: database system was shut down at 2026-07-19 11:39:22 UTC3812026-07-19 11:39:22.657 UTC [16104] LOG: database system is ready to accept connections382/nix/var/nix/builds/nix-16068-4224019181/postgres209616802:5432 - accepting connections383<jemalloc>: option background_thread currently supports pthread only384{"timestamp":"2026-07-19T11:39:22.778189Z","level":"ERROR","fields":{"message":"list_path_raw: revjob err VolumeNotFound"},"target":"rustfs_ecstore::cache_value::metacache_set","filename":"crates/ecstore/src/cache_value/metacache_set.rs","line_number":486,"threadName":"rustfs-worker","threadId":"ThreadId(10)"}385=== RUN TestService_AuthMiddleware386=== PAUSE TestService_AuthMiddleware387=== RUN TestService_AuthMiddleware_MTLSProxyHeader388=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader389=== RUN TestService_AuthMiddleware_MTLSBoundSubjects390=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects391=== RUN TestService_ReadAuthMiddleware392=== PAUSE TestService_ReadAuthMiddleware393=== RUN TestService_AuthMiddleware_OIDC394=== PAUSE TestService_AuthMiddleware_OIDC395=== RUN TestCacheConfigHandler396=== PAUSE TestCacheConfigHandler397=== RUN TestCacheStatsHandler398=== PAUSE TestCacheStatsHandler399=== RUN TestClientCADerivations400=== PAUSE TestClientCADerivations401=== RUN TestClientErrorHandling402=== PAUSE TestClientErrorHandling403=== RUN TestClientIntegration404=== PAUSE TestClientIntegration405=== RUN TestClientMultipleUploads406=== PAUSE TestClientMultipleUploads407=== RUN TestClientWithDependencies408=== PAUSE TestClientWithDependencies409=== RUN TestPinProtectsFromGC410=== PAUSE TestPinProtectsFromGC411=== RUN TestGCAdvisoryLockBlocksConcurrentRun4122026-07-19 11:39:22.930 UTC [16162] ERROR: relation "goose_db_version" does not exist at character 364132026-07-19 11:39:22.930 UTC [16162] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4142026/07/19 11:39:22 OK 20241026095416_initial_model.sql (3.35ms)4152026/07/19 11:39:22 OK 20251210153512_drop_unused_gin_index.sql (415.79µs)4162026/07/19 11:39:22 OK 20251218171726_add_pins.sql (823.25µs)4172026/07/19 11:39:22 OK 20260628120000_add_object_size_and_stats.sql (852.83µs)4182026/07/19 11:39:22 goose: successfully migrated database to version: 202606281200004192026/07/19 11:39:22 OK 1_commit_pending_closure.sql (831µs)4202026/07/19 11:39:22 OK 2_object_stats_trigger.sql (217.04µs)4212026/07/19 11:39:22 goose: up to current file version: 2422--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.07s)423=== RUN TestGCBugBareHashReferences424=== PAUSE TestGCBugBareHashReferences425=== RUN TestGCMetrics426=== PAUSE TestGCMetrics427=== RUN TestGCTaskStore_StartNew428=== PAUSE TestGCTaskStore_StartNew429=== RUN TestGCTaskStore_DeduplicateSameParams430=== PAUSE TestGCTaskStore_DeduplicateSameParams431=== RUN TestGCTaskStore_ConflictDifferentParams432=== PAUSE TestGCTaskStore_ConflictDifferentParams433=== RUN TestGCTaskStore_GetEmpty434=== PAUSE TestGCTaskStore_GetEmpty435=== RUN TestGCTaskStore_GetReturnsLatest436=== PAUSE TestGCTaskStore_GetReturnsLatest437=== RUN TestGCTaskStore_CompletedAllowsNewTask438=== PAUSE TestGCTaskStore_CompletedAllowsNewTask439=== RUN TestGCTaskStore_PhaseUpdates440=== PAUSE TestGCTaskStore_PhaseUpdates441=== RUN TestGCTaskStore_Fail442=== PAUSE TestGCTaskStore_Fail443=== RUN TestGracefulShutdownDrainsInflight444=== PAUSE TestGracefulShutdownDrainsInflight445=== RUN TestService_healthCheckHandler446=== PAUSE TestService_healthCheckHandler447=== RUN TestGenerateLandingPage448=== PAUSE TestGenerateLandingPage449=== RUN TestCacheConfigHandlerMaxNarSize450=== PAUSE TestCacheConfigHandlerMaxNarSize451=== RUN TestCreatePendingClosureRejectsOversizedNAR452=== PAUSE TestCreatePendingClosureRejectsOversizedNAR453=== RUN TestNARDeduplicationMetadataUploadBug454=== PAUSE TestNARDeduplicationMetadataUploadBug455=== RUN TestMetricsInventory456=== PAUSE TestMetricsInventory457=== RUN TestService_NativeMTLS458=== PAUSE TestService_NativeMTLS459=== RUN TestServerTLSConfig460=== PAUSE TestServerTLSConfig461=== RUN TestMultipartCleanup462=== PAUSE TestMultipartCleanup463=== RUN TestObjectStatsTrigger464=== PAUSE TestObjectStatsTrigger465=== RUN TestOrphanedObjectsGC466=== PAUSE TestOrphanedObjectsGC467=== RUN TestOrphanedObjectsGCStressTest468=== PAUSE TestOrphanedObjectsGCStressTest469=== RUN TestResurrectedObjectNotDeleted470=== PAUSE TestResurrectedObjectNotDeleted471=== RUN TestParseSingleRange472=== PAUSE TestParseSingleRange473=== RUN TestIsValidCachePath474=== PAUSE TestIsValidCachePath475=== RUN TestReadProxyNarinfo476=== PAUSE TestReadProxyNarinfo477=== RUN TestReadProxyNarinfoAlreadyDecompressed478=== PAUSE TestReadProxyNarinfoAlreadyDecompressed479=== RUN TestReadProxyNarStreaming480=== PAUSE TestReadProxyNarStreaming481=== RUN TestReadProxy404482=== PAUSE TestReadProxy404483=== RUN TestReadProxyInvalidPath484=== PAUSE TestReadProxyInvalidPath485=== RUN TestReadProxyHead486=== PAUSE TestReadProxyHead487=== RUN TestReadProxyConditionalGet488=== PAUSE TestReadProxyConditionalGet489=== RUN TestReadProxyRootRedirectsToIndexHTML490=== PAUSE TestReadProxyRootRedirectsToIndexHTML491=== RUN TestReadProxyDisabled492=== PAUSE TestReadProxyDisabled493=== RUN TestReadProxyRangeRequest494=== PAUSE TestReadProxyRangeRequest495=== RUN TestRedundantMultipartUpload496=== PAUSE TestRedundantMultipartUpload497=== RUN TestCompleteMultipartUpload_ErrorButObjectExists498=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists499=== RUN TestCompletedNarNotReofferedAcrossClosures500=== PAUSE TestCompletedNarNotReofferedAcrossClosures501=== RUN TestPresignedUploadRegisteredBeforeCommit502=== PAUSE TestPresignedUploadRegisteredBeforeCommit503=== RUN TestService_Rustfstest504=== PAUSE TestService_Rustfstest505=== RUN TestParseSize506=== PAUSE TestParseSize507=== RUN TestSkippedUploadsHandler508=== PAUSE TestSkippedUploadsHandler509=== RUN TestSystemdListenerNotActivated510--- PASS: TestSystemdListenerNotActivated (0.00s)511=== RUN TestWatchdogBeatsWhenHealthy512--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)513=== RUN TestWatchdogSkipsWhenUnhealthy5142026/07/19 11:39:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5152026/07/19 11:39:23 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5162026/07/19 11:39:23 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5172026/07/19 11:39:23 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5182026/07/19 11:39:23 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5192026/07/19 11:39:23 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5202026/07/19 11:39:23 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5212026/07/19 11:39:23 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5222026/07/19 11:39:23 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5232026/07/19 11:39:23 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"524--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)525=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle526=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle527=== RUN TestProxyWriteTimeout528=== PAUSE TestProxyWriteTimeout529=== RUN TestIsValidUploadKey530=== PAUSE TestIsValidUploadKey531=== RUN TestUploadHandlersRejectInvalidKeys532=== PAUSE TestUploadHandlersRejectInvalidKeys533=== RUN TestUploadHandlersRejectOversizedBody534=== PAUSE TestUploadHandlersRejectOversizedBody535=== RUN TestService_cleanupPendingClosuresHandler536=== PAUSE TestService_cleanupPendingClosuresHandler537=== RUN TestService_createPendingClosureHandler538=== PAUSE TestService_createPendingClosureHandler539=== RUN TestService_verifyS3Integrity540=== PAUSE TestService_verifyS3Integrity541=== RUN TestCompleteMultipartUnregistered542=== PAUSE TestCompleteMultipartUnregistered543=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT544=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT545=== CONT TestUploadHandlersRejectOversizedBody546=== CONT TestService_AuthMiddleware547=== CONT TestService_verifyS3Integrity548=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT549=== CONT TestCompleteMultipartUnregistered550=== CONT TestUploadHandlersRejectInvalidKeys551=== CONT TestIsValidUploadKey552=== CONT TestProxyWriteTimeout553=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle554=== CONT TestSkippedUploadsHandler555=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info556=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info557=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal558=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal559=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key560=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key561=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key562=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key563=== CONT TestParseSize564=== RUN TestIsValidUploadKey/narinfo565--- PASS: TestParseSize (0.00s)566=== CONT TestService_Rustfstest567=== PAUSE TestIsValidUploadKey/narinfo568=== RUN TestProxyWriteTimeout/narinfo569=== PAUSE TestProxyWriteTimeout/narinfo570=== RUN TestProxyWriteTimeout/1_GiB_nar571=== PAUSE TestProxyWriteTimeout/1_GiB_nar572=== RUN TestProxyWriteTimeout/10_GiB_nar573=== PAUSE TestProxyWriteTimeout/10_GiB_nar574=== RUN TestProxyWriteTimeout/unknown_size575=== PAUSE TestProxyWriteTimeout/unknown_size576=== CONT TestPresignedUploadRegisteredBeforeCommit577=== RUN TestIsValidUploadKey/nar_zst578=== PAUSE TestIsValidUploadKey/nar_zst579=== RUN TestIsValidUploadKey/nar_xz580=== PAUSE TestIsValidUploadKey/nar_xz581=== RUN TestIsValidUploadKey/nar_plain582=== PAUSE TestIsValidUploadKey/nar_plain583=== RUN TestIsValidUploadKey/listing584=== PAUSE TestIsValidUploadKey/listing585=== RUN TestIsValidUploadKey/build_log586=== PAUSE TestIsValidUploadKey/build_log587=== RUN TestIsValidUploadKey/build_log_home-manager_file588=== PAUSE TestIsValidUploadKey/build_log_home-manager_file589=== RUN TestIsValidUploadKey/build_log_plus_in_name590=== PAUSE TestIsValidUploadKey/build_log_plus_in_name591=== RUN TestIsValidUploadKey/build_log_question_mark592=== PAUSE TestIsValidUploadKey/build_log_question_mark593=== RUN TestIsValidUploadKey/build_log_equals594=== PAUSE TestIsValidUploadKey/build_log_equals595=== RUN TestIsValidUploadKey/realisation596=== PAUSE TestIsValidUploadKey/realisation597=== RUN TestIsValidUploadKey/realisation_plus_in_output5982026/07/19 11:39:23 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000599=== PAUSE TestIsValidUploadKey/realisation_plus_in_output600=== RUN TestIsValidUploadKey/nix-cache-info601=== PAUSE TestIsValidUploadKey/nix-cache-info602=== RUN TestIsValidUploadKey/index.html603=== PAUSE TestIsValidUploadKey/index.html604=== RUN TestIsValidUploadKey/narinfo_key,_nar_type605=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type606=== RUN TestIsValidUploadKey/nar_key,_narinfo_type607=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type608=== RUN TestIsValidUploadKey/listing_key,_narinfo_type609=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type610=== RUN TestIsValidUploadKey/traversal611=== PAUSE TestIsValidUploadKey/traversal612=== RUN TestIsValidUploadKey/traversal_nar613=== PAUSE TestIsValidUploadKey/traversal_nar614=== RUN TestIsValidUploadKey/absolute615=== PAUSE TestIsValidUploadKey/absolute616=== RUN TestIsValidUploadKey/empty_key617=== PAUSE TestIsValidUploadKey/empty_key618=== RUN TestIsValidUploadKey/unknown_type619=== PAUSE TestIsValidUploadKey/unknown_type620=== CONT TestCompletedNarNotReofferedAcrossClosures621--- PASS: TestSkippedUploadsHandler (0.02s)622=== CONT TestCompleteMultipartUpload_ErrorButObjectExists623=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure624=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure625=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart626=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart627=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts628=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts629=== CONT TestRedundantMultipartUpload6302026-07-19 11:39:23.383 UTC [16184] ERROR: relation "goose_db_version" does not exist at character 366312026-07-19 11:39:23.383 UTC [16184] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6322026-07-19 11:39:23.385 UTC [16185] ERROR: relation "goose_db_version" does not exist at character 366332026-07-19 11:39:23.385 UTC [16185] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6342026-07-19 11:39:23.385 UTC [16186] ERROR: relation "goose_db_version" does not exist at character 366352026-07-19 11:39:23.385 UTC [16186] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6362026/07/19 11:39:23 OK 20241026095416_initial_model.sql (10.83ms)6372026/07/19 11:39:23 OK 20241026095416_initial_model.sql (13.03ms)6382026/07/19 11:39:23 OK 20251210153512_drop_unused_gin_index.sql (1.03ms)6392026/07/19 11:39:23 OK 20251210153512_drop_unused_gin_index.sql (1.27ms)6402026/07/19 11:39:23 OK 20241026095416_initial_model.sql (15.53ms)6412026/07/19 11:39:23 OK 20251218171726_add_pins.sql (2.22ms)6422026/07/19 11:39:23 OK 20251210153512_drop_unused_gin_index.sql (1.23ms)6432026/07/19 11:39:23 OK 20251218171726_add_pins.sql (3.31ms)6442026/07/19 11:39:23 OK 20260628120000_add_object_size_and_stats.sql (3.13ms)6452026/07/19 11:39:23 goose: successfully migrated database to version: 202606281200006462026/07/19 11:39:23 OK 20251218171726_add_pins.sql (2.28ms)6472026/07/19 11:39:23 OK 20260628120000_add_object_size_and_stats.sql (3.08ms)6482026/07/19 11:39:23 goose: successfully migrated database to version: 202606281200006492026/07/19 11:39:23 OK 1_commit_pending_closure.sql (2.91ms)6502026/07/19 11:39:23 OK 20260628120000_add_object_size_and_stats.sql (3.53ms)6512026/07/19 11:39:23 goose: successfully migrated database to version: 202606281200006522026/07/19 11:39:23 OK 2_object_stats_trigger.sql (1.04ms)6532026/07/19 11:39:23 goose: up to current file version: 26542026/07/19 11:39:23 OK 1_commit_pending_closure.sql (2.99ms)6552026-07-19 11:39:23.428 UTC [16187] ERROR: relation "goose_db_version" does not exist at character 366562026-07-19 11:39:23.428 UTC [16187] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6572026/07/19 11:39:23 OK 1_commit_pending_closure.sql (3.21ms)6582026/07/19 11:39:23 OK 2_object_stats_trigger.sql (1.85ms)6592026/07/19 11:39:23 goose: up to current file version: 26602026/07/19 11:39:23 OK 2_object_stats_trigger.sql (1.27ms)6612026/07/19 11:39:23 goose: up to current file version: 26622026-07-19 11:39:23.429 UTC [16188] ERROR: relation "goose_db_version" does not exist at character 366632026-07-19 11:39:23.429 UTC [16188] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6642026/07/19 11:39:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete6652026/07/19 11:39:23 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst666--- PASS: TestCompleteMultipartUnregistered (0.26s)667=== CONT TestReadProxyRangeRequest6682026-07-19 11:39:23.432 UTC [16189] ERROR: relation "goose_db_version" does not exist at character 366692026-07-19 11:39:23.432 UTC [16189] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6702026/07/19 11:39:23 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"671--- PASS: TestService_AuthMiddleware (0.26s)672=== CONT TestReadProxyDisabled6732026-07-19 11:39:23.432 UTC [16192] ERROR: relation "goose_db_version" does not exist at character 366742026-07-19 11:39:23.432 UTC [16192] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6752026/07/19 11:39:23 INFO Received uploads request method=POST path=/api/pending_closures6762026-07-19 11:39:23.434 UTC [16190] ERROR: relation "goose_db_version" does not exist at character 366772026-07-19 11:39:23.434 UTC [16190] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6782026-07-19 11:39:23.434 UTC [16193] ERROR: relation "goose_db_version" does not exist at character 366792026-07-19 11:39:23.434 UTC [16193] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6802026-07-19 11:39:23.434 UTC [16191] ERROR: relation "goose_db_version" does not exist at character 366812026-07-19 11:39:23.434 UTC [16191] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6822026/07/19 11:39:23 OK 20241026095416_initial_model.sql (6ms)6832026/07/19 11:39:23 OK 20251210153512_drop_unused_gin_index.sql (958.54µs)6842026/07/19 11:39:23 OK 20241026095416_initial_model.sql (5.55ms)6852026/07/19 11:39:23 OK 20241026095416_initial_model.sql (7.52ms)6862026/07/19 11:39:23 OK 20251210153512_drop_unused_gin_index.sql (809.79µs)6872026/07/19 11:39:23 OK 20251210153512_drop_unused_gin_index.sql (941.79µs)6882026/07/19 11:39:23 OK 20251218171726_add_pins.sql (1.94ms)6892026/07/19 11:39:23 OK 20241026095416_initial_model.sql (7.58ms)6902026/07/19 11:39:23 OK 20241026095416_initial_model.sql (7.17ms)6912026/07/19 11:39:23 OK 20251210153512_drop_unused_gin_index.sql (763.63µs)6922026/07/19 11:39:23 OK 20251210153512_drop_unused_gin_index.sql (941.67µs)6932026/07/19 11:39:23 OK 20241026095416_initial_model.sql (7.51ms)6942026/07/19 11:39:23 OK 20251218171726_add_pins.sql (2.74ms)6952026/07/19 11:39:23 OK 20260628120000_add_object_size_and_stats.sql (2.24ms)6962026/07/19 11:39:23 goose: successfully migrated database to version: 202606281200006972026/07/19 11:39:23 OK 20251218171726_add_pins.sql (2.3ms)6982026/07/19 11:39:23 OK 20251218171726_add_pins.sql (1.95ms)6992026/07/19 11:39:23 OK 20251210153512_drop_unused_gin_index.sql (869.58µs)7002026/07/19 11:39:23 OK 20251218171726_add_pins.sql (1.76ms)7012026/07/19 11:39:23 OK 20241026095416_initial_model.sql (8.04ms)7022026/07/19 11:39:23 OK 1_commit_pending_closure.sql (2.43ms)7032026/07/19 11:39:23 OK 20260628120000_add_object_size_and_stats.sql (2.63ms)7042026/07/19 11:39:23 goose: successfully migrated database to version: 202606281200007052026/07/19 11:39:23 OK 20260628120000_add_object_size_and_stats.sql (2.72ms)7062026/07/19 11:39:23 goose: successfully migrated database to version: 202606281200007072026/07/19 11:39:23 OK 20260628120000_add_object_size_and_stats.sql (1.75ms)7082026/07/19 11:39:23 goose: successfully migrated database to version: 202606281200007092026/07/19 11:39:23 OK 20251218171726_add_pins.sql (2.07ms)7102026/07/19 11:39:23 OK 20260628120000_add_object_size_and_stats.sql (2.25ms)7112026/07/19 11:39:23 goose: successfully migrated database to version: 202606281200007122026/07/19 11:39:23 OK 20251210153512_drop_unused_gin_index.sql (1.66ms)7132026/07/19 11:39:23 OK 2_object_stats_trigger.sql (550.38µs)7142026/07/19 11:39:23 goose: up to current file version: 27152026/07/19 11:39:23 OK 1_commit_pending_closure.sql (1.38ms)7162026/07/19 11:39:23 OK 1_commit_pending_closure.sql (1.65ms)7172026/07/19 11:39:23 OK 1_commit_pending_closure.sql (1.99ms)7182026/07/19 11:39:23 OK 1_commit_pending_closure.sql (2.05ms)7192026/07/19 11:39:23 OK 2_object_stats_trigger.sql (756.75µs)7202026/07/19 11:39:23 goose: up to current file version: 27212026/07/19 11:39:23 OK 2_object_stats_trigger.sql (583.67µs)7222026/07/19 11:39:23 goose: up to current file version: 27232026/07/19 11:39:23 OK 2_object_stats_trigger.sql (451.25µs)7242026/07/19 11:39:23 goose: up to current file version: 27252026/07/19 11:39:23 OK 20251218171726_add_pins.sql (2.29ms)7262026/07/19 11:39:23 OK 2_object_stats_trigger.sql (442.04µs)7272026/07/19 11:39:23 goose: up to current file version: 27282026/07/19 11:39:23 INFO Received uploads request method=POST path=/api/pending_closures7292026/07/19 11:39:23 OK 20260628120000_add_object_size_and_stats.sql (2.86ms)7302026/07/19 11:39:23 goose: successfully migrated database to version: 202606281200007312026/07/19 11:39:23 OK 20260628120000_add_object_size_and_stats.sql (2.54ms)7322026/07/19 11:39:23 goose: successfully migrated database to version: 202606281200007332026/07/19 11:39:23 INFO Received uploads request method=POST path=/api/pending_closures7342026/07/19 11:39:23 INFO Received uploads request method=POST path=/api/pending_closures735--- PASS: TestService_Rustfstest (0.27s)736=== CONT TestReadProxyRootRedirectsToIndexHTML7372026/07/19 11:39:23 OK 1_commit_pending_closure.sql (2.6ms)7382026/07/19 11:39:23 INFO Received uploads request method=POST path=/api/pending_closures7392026/07/19 11:39:23 OK 2_object_stats_trigger.sql (1.36ms)7402026/07/19 11:39:23 goose: up to current file version: 27412026/07/19 11:39:23 OK 1_commit_pending_closure.sql (2.05ms)7422026/07/19 11:39:23 INFO Received uploads request method=POST path=/api/pending_closures7432026/07/19 11:39:23 OK 2_object_stats_trigger.sql (1.63ms)7442026/07/19 11:39:23 goose: up to current file version: 27452026/07/19 11:39:23 INFO Received uploads request method=POST path=/api/pending_closures7462026/07/19 11:39:23 INFO Received uploads request method=POST path=/api/pending_closures747--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.29s)748=== CONT TestReadProxyConditionalGet749{"timestamp":"2026-07-19T11:39:23.467753Z","level":"ERROR","fields":{"message":"system path read failed","path_kind":"data_usage","operation":"read_primary","reason":"config_not_found","object":"buckets/.usage.json","error":"Config not found"},"target":"rustfs_ecstore::data_usage","filename":"crates/ecstore/src/data_usage.rs","line_number":126,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}7502026/07/19 11:39:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete751{"timestamp":"2026-07-19T11:39:23.474692Z","level":"ERROR","fields":{"message":"complete_multipart_upload part error: \"part.1 not found\""},"target":"rustfs_ecstore::set_disk","filename":"crates/ecstore/src/set_disk.rs","line_number":3463,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}752{"timestamp":"2026-07-19T11:39:23.474722Z","level":"ERROR","fields":{"message":"complete_multipart_upload etag err client=Some(\"deadbeef\"), stored=\"\", part_id=1, bucket=bucket8, object=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst"},"target":"rustfs_ecstore::set_disk","filename":"crates/ecstore/src/set_disk.rs","line_number":3534,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}7532026/07/19 11:39:23 WARN CompleteMultipartUpload errored but object exists; treating as success error="One or more of the specified parts could not be found. The part may not have been uploaded, or the specified entity tag may not match the part's entity tag." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MjY3YTczOTMtZTY1MS00ZWJjLWI2YTYtODkzOThmMzhjN2MxLjYzYTc5ODc1LWEwOTAtNDA5MS05MTc2LWFkYTkxYjljYTk4M3gxNzg0NDYxMTYzNDU4OTAyMDAw7542026/07/19 11:39:23 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst7552026/07/19 11:39:23 INFO Received uploads request method=POST path=/api/pending_closures756--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.29s)757=== CONT TestReadProxyHead7582026/07/19 11:39:23 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MjY3YTczOTMtZTY1MS00ZWJjLWI2YTYtODkzOThmMzhjN2MxLjYzYTc5ODc1LWEwOTAtNDA5MS05MTc2LWFkYTkxYjljYTk4M3gxNzg0NDYxMTYzNDU4OTAyMDAw parts=1759--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.29s)760=== CONT TestReadProxyInvalidPath7612026-07-19 11:39:23.490 UTC [16205] ERROR: relation "goose_db_version" does not exist at character 367622026-07-19 11:39:23.490 UTC [16205] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7632026-07-19 11:39:23.491 UTC [16204] ERROR: relation "goose_db_version" does not exist at character 367642026-07-19 11:39:23.491 UTC [16204] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7652026/07/19 11:39:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7662026/07/19 11:39:23 OK 20241026095416_initial_model.sql (8.33ms)7672026/07/19 11:39:23 OK 20241026095416_initial_model.sql (9.83ms)7682026/07/19 11:39:23 OK 20251210153512_drop_unused_gin_index.sql (1.35ms)7692026/07/19 11:39:23 OK 20251210153512_drop_unused_gin_index.sql (818.63µs)7702026/07/19 11:39:23 OK 20251218171726_add_pins.sql (2.54ms)7712026/07/19 11:39:23 OK 20251218171726_add_pins.sql (1.78ms)7722026/07/19 11:39:23 OK 20260628120000_add_object_size_and_stats.sql (2.65ms)7732026/07/19 11:39:23 goose: successfully migrated database to version: 202606281200007742026/07/19 11:39:23 OK 20260628120000_add_object_size_and_stats.sql (2.82ms)7752026/07/19 11:39:23 goose: successfully migrated database to version: 202606281200007762026/07/19 11:39:23 OK 1_commit_pending_closure.sql (1.84ms)7772026/07/19 11:39:23 OK 1_commit_pending_closure.sql (2.59ms)7782026/07/19 11:39:23 OK 2_object_stats_trigger.sql (1.06ms)7792026/07/19 11:39:23 goose: up to current file version: 27802026/07/19 11:39:23 OK 2_object_stats_trigger.sql (776µs)7812026/07/19 11:39:23 goose: up to current file version: 2782--- PASS: TestReadProxyDisabled (0.09s)783=== CONT TestReadProxy4047842026-07-19 11:39:23.527 UTC [16209] ERROR: relation "goose_db_version" does not exist at character 367852026-07-19 11:39:23.527 UTC [16209] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC786--- PASS: TestReadProxyRangeRequest (0.10s)787=== CONT TestReadProxyNarStreaming7882026/07/19 11:39:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7892026/07/19 11:39:23 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MjY3YTczOTMtZTY1MS00ZWJjLWI2YTYtODkzOThmMzhjN2MxLjlkZDIxMmIwLThiODUtNDljNy1iNWI4LTNlMmE4ZGVmYzZiMngxNzg0NDYxMTYzNDM3MjU0MDAw parts=107902026/07/19 11:39:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7912026/07/19 11:39:23 INFO Completed upload id=17922026/07/19 11:39:23 INFO Received uploads request method=POST path=/api/pending_closures7932026/07/19 11:39:23 INFO Received uploads request method=POST path=/api/pending_closures7942026/07/19 11:39:23 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo7952026/07/19 11:39:23 WARN Found objects in DB but missing from S3, will re-upload count=1796--- PASS: TestService_verifyS3Integrity (0.42s)797=== CONT TestReadProxyNarinfoAlreadyDecompressed7982026/07/19 11:39:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7992026/07/19 11:39:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8002026/07/19 11:39:23 OK 20241026095416_initial_model.sql (40.13ms)8012026/07/19 11:39:23 OK 20251210153512_drop_unused_gin_index.sql (419.92µs)8022026/07/19 11:39:23 OK 20251218171726_add_pins.sql (790.25µs)8032026/07/19 11:39:23 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MjY3YTczOTMtZTY1MS00ZWJjLWI2YTYtODkzOThmMzhjN2MxLjBkYjkxOWQzLWIwYWQtNGFlNy04ZjlhLTFkMWM2YTcxNjhlNHgxNzg0NDYxMTYzNDY0MTk5MDAw parts=128042026/07/19 11:39:23 INFO Received uploads request method=POST path=/api/pending_closures8052026/07/19 11:39:23 OK 20260628120000_add_object_size_and_stats.sql (4.08ms)8062026/07/19 11:39:23 goose: successfully migrated database to version: 202606281200008072026/07/19 11:39:23 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MjY3YTczOTMtZTY1MS00ZWJjLWI2YTYtODkzOThmMzhjN2MxLmQwOTVkNGE1LTEzZDgtNDkxOS04YzYzLTc0NmY3NjlkMWNhOHgxNzg0NDYxMTYzNDU1MTk3MDAw parts=12808--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.42s)809=== CONT TestReadProxyNarinfo810--- PASS: TestRedundantMultipartUpload (0.41s)811=== CONT TestIsValidCachePath812=== RUN TestIsValidCachePath/narinfo813=== PAUSE TestIsValidCachePath/narinfo814=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars815=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars816=== RUN TestIsValidCachePath/nar_zst817=== PAUSE TestIsValidCachePath/nar_zst818=== RUN TestIsValidCachePath/nar_xz819=== PAUSE TestIsValidCachePath/nar_xz820=== RUN TestIsValidCachePath/nar_bz2821=== PAUSE TestIsValidCachePath/nar_bz2822=== RUN TestIsValidCachePath/nar_uncompressed823=== PAUSE TestIsValidCachePath/nar_uncompressed824=== RUN TestIsValidCachePath/ls825=== PAUSE TestIsValidCachePath/ls826=== RUN TestIsValidCachePath/log827=== PAUSE TestIsValidCachePath/log828=== RUN TestIsValidCachePath/realisation829=== PAUSE TestIsValidCachePath/realisation830=== RUN TestIsValidCachePath/nix-cache-info831=== PAUSE TestIsValidCachePath/nix-cache-info832=== RUN TestIsValidCachePath/index.html833=== PAUSE TestIsValidCachePath/index.html834=== RUN TestIsValidCachePath/traversal_parent835=== PAUSE TestIsValidCachePath/traversal_parent836=== RUN TestIsValidCachePath/traversal_in_middle837=== PAUSE TestIsValidCachePath/traversal_in_middle838=== RUN TestIsValidCachePath/invalid_char_e839=== PAUSE TestIsValidCachePath/invalid_char_e840=== RUN TestIsValidCachePath/invalid_char_u841=== PAUSE TestIsValidCachePath/invalid_char_u842=== RUN TestIsValidCachePath/random_path843=== PAUSE TestIsValidCachePath/random_path844=== RUN TestIsValidCachePath/empty845=== PAUSE TestIsValidCachePath/empty846=== RUN TestIsValidCachePath/leading_slash847=== PAUSE TestIsValidCachePath/leading_slash848=== RUN TestIsValidCachePath/wrong_extension849=== PAUSE TestIsValidCachePath/wrong_extension850=== RUN TestIsValidCachePath/short_hash851=== PAUSE TestIsValidCachePath/short_hash852=== CONT TestParseSingleRange853=== RUN TestParseSingleRange/none854=== PAUSE TestParseSingleRange/none8552026/07/19 11:39:23 OK 1_commit_pending_closure.sql (1.3ms)856=== RUN TestParseSingleRange/unknown_unit857=== PAUSE TestParseSingleRange/unknown_unit8582026-07-19 11:39:23.609 UTC [16236] ERROR: relation "goose_db_version" does not exist at character 368592026-07-19 11:39:23.609 UTC [16236] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC860=== RUN TestParseSingleRange/multi-range_ignored861=== PAUSE TestParseSingleRange/multi-range_ignored862=== RUN TestParseSingleRange/malformed_no_dash863=== PAUSE TestParseSingleRange/malformed_no_dash864=== RUN TestParseSingleRange/malformed_both_empty865=== PAUSE TestParseSingleRange/malformed_both_empty866=== RUN TestParseSingleRange/malformed_end_before_start867=== PAUSE TestParseSingleRange/malformed_end_before_start868=== RUN TestParseSingleRange/closed869=== PAUSE TestParseSingleRange/closed870=== RUN TestParseSingleRange/open-ended871=== PAUSE TestParseSingleRange/open-ended872=== RUN TestParseSingleRange/end_clamped_to_size873=== PAUSE TestParseSingleRange/end_clamped_to_size874=== RUN TestParseSingleRange/suffix875=== PAUSE TestParseSingleRange/suffix876=== RUN TestParseSingleRange/suffix_exceeds_size877=== PAUSE TestParseSingleRange/suffix_exceeds_size878=== RUN TestParseSingleRange/single_byte879=== PAUSE TestParseSingleRange/single_byte880=== RUN TestParseSingleRange/start_past_EOF881=== PAUSE TestParseSingleRange/start_past_EOF882=== RUN TestParseSingleRange/start_far_past_EOF883=== PAUSE TestParseSingleRange/start_far_past_EOF884=== CONT TestResurrectedObjectNotDeleted8852026/07/19 11:39:23 OK 2_object_stats_trigger.sql (1.27ms)8862026/07/19 11:39:23 goose: up to current file version: 2887--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.16s)888=== CONT TestOrphanedObjectsGCStressTest8892026/07/19 11:39:23 OK 20241026095416_initial_model.sql (31.16ms)8902026/07/19 11:39:23 OK 20251210153512_drop_unused_gin_index.sql (385.29µs)8912026/07/19 11:39:23 OK 20251218171726_add_pins.sql (777.67µs)8922026/07/19 11:39:23 OK 20260628120000_add_object_size_and_stats.sql (10.64ms)8932026/07/19 11:39:23 goose: successfully migrated database to version: 202606281200008942026/07/19 11:39:23 OK 1_commit_pending_closure.sql (957.04µs)8952026/07/19 11:39:23 OK 2_object_stats_trigger.sql (226.96µs)8962026/07/19 11:39:23 goose: up to current file version: 2897--- PASS: TestReadProxyConditionalGet (0.23s)898=== CONT TestOrphanedObjectsGC8992026-07-19 11:39:23.861 UTC [16245] ERROR: relation "goose_db_version" does not exist at character 369002026-07-19 11:39:23.861 UTC [16245] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9012026-07-19 11:39:23.861 UTC [16246] ERROR: relation "goose_db_version" does not exist at character 369022026-07-19 11:39:23.861 UTC [16246] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9032026/07/19 11:39:23 OK 20241026095416_initial_model.sql (6.44ms)9042026/07/19 11:39:23 OK 20241026095416_initial_model.sql (8.09ms)9052026/07/19 11:39:23 OK 20251210153512_drop_unused_gin_index.sql (471.38µs)9062026/07/19 11:39:23 OK 20251210153512_drop_unused_gin_index.sql (441.75µs)9072026/07/19 11:39:23 OK 20251218171726_add_pins.sql (758.58µs)9082026/07/19 11:39:23 OK 20251218171726_add_pins.sql (814.79µs)9092026/07/19 11:39:23 OK 20260628120000_add_object_size_and_stats.sql (3.7ms)9102026/07/19 11:39:23 goose: successfully migrated database to version: 202606281200009112026/07/19 11:39:23 OK 20260628120000_add_object_size_and_stats.sql (4.73ms)9122026/07/19 11:39:23 goose: successfully migrated database to version: 202606281200009132026/07/19 11:39:23 OK 1_commit_pending_closure.sql (1.18ms)9142026/07/19 11:39:23 OK 2_object_stats_trigger.sql (274.08µs)9152026/07/19 11:39:23 goose: up to current file version: 29162026/07/19 11:39:23 OK 1_commit_pending_closure.sql (902.42µs)9172026/07/19 11:39:23 OK 2_object_stats_trigger.sql (203.96µs)9182026/07/19 11:39:23 goose: up to current file version: 2919--- PASS: TestReadProxyInvalidPath (0.42s)920=== CONT TestObjectStatsTrigger921--- PASS: TestReadProxyHead (0.42s)922=== CONT TestMultipartCleanup9232026-07-19 11:39:24.050 UTC [16251] ERROR: relation "goose_db_version" does not exist at character 369242026-07-19 11:39:24.050 UTC [16251] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9252026-07-19 11:39:24.075 UTC [16252] ERROR: relation "goose_db_version" does not exist at character 369262026-07-19 11:39:24.075 UTC [16252] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9272026-07-19 11:39:24.083 UTC [16253] ERROR: relation "goose_db_version" does not exist at character 369282026-07-19 11:39:24.083 UTC [16253] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9292026/07/19 11:39:24 OK 20241026095416_initial_model.sql (23ms)9302026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (476.17µs)9312026/07/19 11:39:24 OK 20251218171726_add_pins.sql (991.46µs)9322026-07-19 11:39:24.098 UTC [16254] ERROR: relation "goose_db_version" does not exist at character 369332026-07-19 11:39:24.098 UTC [16254] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9342026-07-19 11:39:24.099 UTC [16255] ERROR: relation "goose_db_version" does not exist at character 369352026-07-19 11:39:24.099 UTC [16255] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9362026-07-19 11:39:24.099 UTC [16256] ERROR: relation "goose_db_version" does not exist at character 369372026-07-19 11:39:24.099 UTC [16256] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9382026/07/19 11:39:24 OK 20241026095416_initial_model.sql (9.34ms)9392026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (337.79µs)9402026/07/19 11:39:24 OK 20251218171726_add_pins.sql (679.38µs)9412026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (19.19ms)9422026/07/19 11:39:24 goose: successfully migrated database to version: 202606281200009432026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (3.76ms)9442026/07/19 11:39:24 goose: successfully migrated database to version: 202606281200009452026/07/19 11:39:24 OK 20241026095416_initial_model.sql (8.4ms)9462026/07/19 11:39:24 OK 1_commit_pending_closure.sql (1.34ms)9472026/07/19 11:39:24 OK 1_commit_pending_closure.sql (935.63µs)9482026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (358.04µs)9492026/07/19 11:39:24 OK 2_object_stats_trigger.sql (211.42µs)9502026/07/19 11:39:24 goose: up to current file version: 29512026/07/19 11:39:24 OK 2_object_stats_trigger.sql (277.71µs)9522026/07/19 11:39:24 goose: up to current file version: 29532026/07/19 11:39:24 OK 20251218171726_add_pins.sql (726.33µs)954--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.53s)955=== CONT TestServerTLSConfig956=== RUN TestServerTLSConfig/no_client_CA957=== PAUSE TestServerTLSConfig/no_client_CA958=== RUN TestServerTLSConfig/missing_CA_file959=== PAUSE TestServerTLSConfig/missing_CA_file960=== RUN TestServerTLSConfig/not_a_PEM_file961=== PAUSE TestServerTLSConfig/not_a_PEM_file962=== CONT TestService_NativeMTLS9632026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (3.11ms)9642026/07/19 11:39:24 goose: successfully migrated database to version: 20260628120000965--- PASS: TestReadProxyNarinfo (0.51s)966=== CONT TestMetricsInventory9672026/07/19 11:39:24 OK 1_commit_pending_closure.sql (921.46µs)9682026/07/19 11:39:24 OK 2_object_stats_trigger.sql (478.42µs)9692026/07/19 11:39:24 goose: up to current file version: 2970--- PASS: TestReadProxyNarStreaming (0.59s)971=== CONT TestNARDeduplicationMetadataUploadBug9722026/07/19 11:39:24 OK 20241026095416_initial_model.sql (16.7ms)9732026/07/19 11:39:24 OK 20241026095416_initial_model.sql (16.95ms)9742026/07/19 11:39:24 OK 20241026095416_initial_model.sql (17.19ms)9752026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (922.17µs)9762026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (901.46µs)9772026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (887.58µs)9782026/07/19 11:39:24 OK 20251218171726_add_pins.sql (2.52ms)9792026/07/19 11:39:24 OK 20251218171726_add_pins.sql (3.01ms)9802026/07/19 11:39:24 OK 20251218171726_add_pins.sql (2.36ms)9812026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (5.72ms)9822026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (5.36ms)9832026/07/19 11:39:24 goose: successfully migrated database to version: 202606281200009842026/07/19 11:39:24 goose: successfully migrated database to version: 202606281200009852026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (5.46ms)9862026/07/19 11:39:24 goose: successfully migrated database to version: 202606281200009872026/07/19 11:39:24 OK 1_commit_pending_closure.sql (1.52ms)9882026/07/19 11:39:24 OK 1_commit_pending_closure.sql (1.61ms)9892026/07/19 11:39:24 OK 1_commit_pending_closure.sql (1.55ms)9902026/07/19 11:39:24 OK 2_object_stats_trigger.sql (543.46µs)9912026/07/19 11:39:24 goose: up to current file version: 29922026/07/19 11:39:24 OK 2_object_stats_trigger.sql (379.08µs)9932026/07/19 11:39:24 goose: up to current file version: 29942026/07/19 11:39:24 OK 2_object_stats_trigger.sql (502.04µs)9952026/07/19 11:39:24 goose: up to current file version: 2996--- PASS: TestReadProxy404 (0.64s)997=== CONT TestCreatePendingClosureRejectsOversizedNAR9982026/07/19 11:39:24 INFO Received uploads request method=POST path=/api/pending_closures999--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1000=== CONT TestCacheConfigHandlerMaxNarSize1001--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1002=== CONT TestGenerateLandingPage1003--- PASS: TestGenerateLandingPage (0.00s)1004=== CONT TestService_healthCheckHandler10052026-07-19 11:39:24.170 UTC [16265] ERROR: relation "goose_db_version" does not exist at character 3610062026-07-19 11:39:24.170 UTC [16265] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10072026/07/19 11:39:24 OK 20241026095416_initial_model.sql (8.7ms)10082026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (543µs)10092026/07/19 11:39:24 OK 20251218171726_add_pins.sql (1.31ms)1010--- PASS: TestResurrectedObjectNotDeleted (0.59s)1011=== CONT TestGracefulShutdownDrainsInflight10122026/07/19 11:39:24 INFO Starting HTTP server address=127.0.0.1:6070410132026/07/19 11:39:24 INFO Shutdown signal received, draining in-flight requests timeout=10s10142026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (4.73ms)10152026/07/19 11:39:24 goose: successfully migrated database to version: 2026062812000010162026/07/19 11:39:24 OK 1_commit_pending_closure.sql (1.44ms)10172026/07/19 11:39:24 OK 2_object_stats_trigger.sql (223.17µs)10182026/07/19 11:39:24 goose: up to current file version: 21019--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1020=== CONT TestGCTaskStore_Fail1021--- PASS: TestGCTaskStore_Fail (0.00s)1022=== CONT TestGCTaskStore_PhaseUpdates1023--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1024=== CONT TestGCTaskStore_CompletedAllowsNewTask1025=== CONT TestGCTaskStore_GetReturnsLatest1026--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1027=== CONT TestGCTaskStore_GetEmpty1028--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1029--- PASS: TestGCTaskStore_GetEmpty (0.00s)1030=== CONT TestGCTaskStore_ConflictDifferentParams1031--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1032=== CONT TestGCTaskStore_DeduplicateSameParams1033--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1034=== CONT TestGCTaskStore_StartNew1035--- PASS: TestGCTaskStore_StartNew (0.00s)1036=== CONT TestGCMetrics10372026-07-19 11:39:24.307 UTC [16268] ERROR: relation "goose_db_version" does not exist at character 3610382026-07-19 11:39:24.307 UTC [16268] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10392026-07-19 11:39:24.316 UTC [16269] ERROR: relation "goose_db_version" does not exist at character 3610402026-07-19 11:39:24.316 UTC [16269] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10412026/07/19 11:39:24 OK 20241026095416_initial_model.sql (6.95ms)10422026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (505.54µs)10432026/07/19 11:39:24 OK 20241026095416_initial_model.sql (5.34ms)10442026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (291.92µs)10452026/07/19 11:39:24 OK 20251218171726_add_pins.sql (732µs)10462026/07/19 11:39:24 OK 20251218171726_add_pins.sql (698.75µs)10472026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (1.56ms)10482026/07/19 11:39:24 goose: successfully migrated database to version: 2026062812000010492026/07/19 11:39:24 OK 1_commit_pending_closure.sql (872.25µs)10502026/07/19 11:39:24 OK 2_object_stats_trigger.sql (226.71µs)10512026/07/19 11:39:24 goose: up to current file version: 210522026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (3.42ms)10532026/07/19 11:39:24 goose: successfully migrated database to version: 2026062812000010542026/07/19 11:39:24 INFO Received uploads request method=POST path=/api/pending_closures10552026/07/19 11:39:24 OK 1_commit_pending_closure.sql (1.28ms)10562026/07/19 11:39:24 OK 2_object_stats_trigger.sql (289.88µs)10572026/07/19 11:39:24 goose: up to current file version: 21058--- PASS: TestObjectStatsTrigger (0.45s)1059=== CONT TestCacheStatsHandler10602026-07-19 11:39:24.407 UTC [16272] ERROR: relation "goose_db_version" does not exist at character 3610612026-07-19 11:39:24.407 UTC [16272] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10622026-07-19 11:39:24.407 UTC [16273] ERROR: relation "goose_db_version" does not exist at character 3610632026-07-19 11:39:24.407 UTC [16273] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10642026-07-19 11:39:24.415 UTC [16274] ERROR: relation "goose_db_version" does not exist at character 3610652026-07-19 11:39:24.415 UTC [16274] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10662026-07-19 11:39:24.421 UTC [16275] ERROR: relation "goose_db_version" does not exist at character 3610672026-07-19 11:39:24.421 UTC [16275] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10682026/07/19 11:39:24 INFO Received cleanup request method=DELETE path=/api/pending_closures10692026/07/19 11:39:24 INFO Aborted multipart uploads count=110702026/07/19 11:39:24 OK 20241026095416_initial_model.sql (13.39ms)10712026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (357.29µs)10722026/07/19 11:39:24 OK 20251218171726_add_pins.sql (769.79µs)1073=== NAME TestOrphanedObjectsGC1074 orphaned_objects_gc_test.go:290: GC Test Summary:1075 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1076 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1077 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1078 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1079 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1080--- PASS: TestOrphanedObjectsGC (0.76s)1081=== CONT TestService_createPendingClosureHandler10822026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (5.13ms)10832026/07/19 11:39:24 goose: successfully migrated database to version: 202606281200001084--- PASS: TestMultipartCleanup (0.55s)1085=== CONT TestService_AuthMiddleware_OIDC10862026/07/19 11:39:24 OK 1_commit_pending_closure.sql (1.14ms)10872026/07/19 11:39:24 OK 20241026095416_initial_model.sql (26.78ms)10882026/07/19 11:39:24 INFO OIDC provider initialized name=test10892026/07/19 11:39:24 OK 2_object_stats_trigger.sql (256.67µs)10902026/07/19 11:39:24 goose: up to current file version: 210912026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (965.17µs)10922026/07/19 11:39:24 OK 20251218171726_add_pins.sql (1.04ms)10932026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (8.01ms)10942026/07/19 11:39:24 goose: successfully migrated database to version: 2026062812000010952026/07/19 11:39:24 OK 1_commit_pending_closure.sql (891.21µs)10962026/07/19 11:39:24 OK 2_object_stats_trigger.sql (221.5µs)10972026/07/19 11:39:24 goose: up to current file version: 210982026/07/19 11:39:24 OK 20241026095416_initial_model.sql (24.44ms)10992026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (369.67µs)11002026/07/19 11:39:24 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11012026/07/19 11:39:24 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1102--- PASS: TestService_NativeMTLS (0.35s)1103=== CONT TestService_cleanupPendingClosuresHandler11042026/07/19 11:39:24 OK 20251218171726_add_pins.sql (1.09ms)11052026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (13.14ms)11062026/07/19 11:39:24 goose: successfully migrated database to version: 2026062812000011072026/07/19 11:39:24 OK 1_commit_pending_closure.sql (1.29ms)11082026/07/19 11:39:24 OK 2_object_stats_trigger.sql (408.46µs)11092026/07/19 11:39:24 goose: up to current file version: 21110--- PASS: TestMetricsInventory (0.36s)1111=== CONT TestCacheConfigHandler1112=== RUN TestCacheConfigHandler/full_config,_no_issuer1113=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1114=== RUN TestCacheConfigHandler/no_cache_url_configured1115=== PAUSE TestCacheConfigHandler/no_cache_url_configured1116=== RUN TestCacheConfigHandler/no_signing_keys1117=== PAUSE TestCacheConfigHandler/no_signing_keys1118=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1119=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1120=== CONT TestClientIntegration11212026/07/19 11:39:24 INFO Created nix-cache-info in bucket bucket=bucket2911222026/07/19 11:39:24 OK 20241026095416_initial_model.sql (16.68ms)11232026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (1.11ms)11242026/07/19 11:39:24 OK 20251218171726_add_pins.sql (2.93ms)11252026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (3.79ms)11262026/07/19 11:39:24 goose: successfully migrated database to version: 2026062812000011272026/07/19 11:39:24 OK 1_commit_pending_closure.sql (2.35ms)11282026/07/19 11:39:24 OK 2_object_stats_trigger.sql (538.42µs)11292026/07/19 11:39:24 goose: up to current file version: 21130--- PASS: TestService_healthCheckHandler (0.34s)1131=== CONT TestClientWithDependencies1132=== NAME TestNARDeduplicationMetadataUploadBug1133 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-16068-4224019181/TestNARDeduplicationMetadataUploadBug3858424096/001/store/dld8q2naiyvj6g4y5sxg8n51pypzmix2-file1.txt1134=== NAME TestOrphanedObjectsGCStressTest1135 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1136 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion11372026/07/19 11:39:24 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11382026/07/19 11:39:24 INFO Received uploads request method=POST path=/api/pending_closures1139 orphaned_objects_gc_test.go:509: Stress test completed successfully:1140 orphaned_objects_gc_test.go:510: - Active objects preserved: 201141 orphaned_objects_gc_test.go:511: - Objects deleted: 2101142 orphaned_objects_gc_test.go:512: - Total GC'd: 2101143--- PASS: TestOrphanedObjectsGCStressTest (1.07s)1144=== CONT TestClientMultipleUploads11452026-07-19 11:39:24.692 UTC [16295] ERROR: relation "goose_db_version" does not exist at character 3611462026-07-19 11:39:24.692 UTC [16295] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11472026/07/19 11:39:24 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11482026/07/19 11:39:24 INFO Uploading dld8q2naiyvj6g4y5sxg8n51pypzmix2-file1.txt (160B)11492026/07/19 11:39:24 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11502026/07/19 11:39:24 WARN Failed to register uploaded object key=dld8q2naiyvj6g4y5sxg8n51pypzmix2.ls error="server returned 404: 404 page not found\n"11512026/07/19 11:39:24 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11522026/07/19 11:39:24 INFO Signed narinfos id=1 count=111532026/07/19 11:39:24 INFO Uploading 1 narinfos11542026/07/19 11:39:24 WARN Failed to register uploaded object key=dld8q2naiyvj6g4y5sxg8n51pypzmix2.narinfo error="server returned 404: 404 page not found\n"11552026/07/19 11:39:24 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11562026/07/19 11:39:24 OK 20241026095416_initial_model.sql (6.51ms)11572026/07/19 11:39:24 INFO Completed upload id=111582026/07/19 11:39:24 INFO Upload complete. (109ms)11592026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (588.21µs)1160=== NAME TestNARDeduplicationMetadataUploadBug1161 metadata_upload_test.go:54: Retrieved narinfo from S3:1162 StorePath: /nix/var/nix/builds/nix-16068-4224019181/TestNARDeduplicationMetadataUploadBug3858424096/001/store/dld8q2naiyvj6g4y5sxg8n51pypzmix2-file1.txt1163 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1164 Compression: zstd1165 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1166 NarSize: 1601167 References: 1168 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1169 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1170 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1171 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}11722026/07/19 11:39:24 OK 20251218171726_add_pins.sql (3.98ms)11732026-07-19 11:39:24.721 UTC [16298] ERROR: relation "goose_db_version" does not exist at character 3611742026-07-19 11:39:24.721 UTC [16298] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11752026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (9.42ms)11762026/07/19 11:39:24 goose: successfully migrated database to version: 2026062812000011772026/07/19 11:39:24 OK 1_commit_pending_closure.sql (826.67µs)11782026/07/19 11:39:24 OK 2_object_stats_trigger.sql (230.88µs)11792026/07/19 11:39:24 goose: up to current file version: 211802026/07/19 11:39:24 INFO Aborted multipart uploads count=011812026/07/19 11:39:24 WARN Force mode enabled - objects will be deleted immediately without grace period11822026/07/19 11:39:24 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=011832026/07/19 11:39:24 INFO Vacuumed table table=pending_closures11842026/07/19 11:39:24 INFO Vacuumed table table=pending_objects11852026/07/19 11:39:24 INFO Vacuumed table table=multipart_uploads11862026/07/19 11:39:24 INFO Vacuumed table table=closures11872026/07/19 11:39:24 INFO Vacuumed table table=objects1188--- PASS: TestGCMetrics (0.46s)1189=== CONT TestGCBugBareHashReferences11902026/07/19 11:39:24 OK 20241026095416_initial_model.sql (11.25ms)11912026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (555.46µs)11922026/07/19 11:39:24 OK 20251218171726_add_pins.sql (929.13µs)11932026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (3.81ms)11942026/07/19 11:39:24 goose: successfully migrated database to version: 2026062812000011952026/07/19 11:39:24 OK 1_commit_pending_closure.sql (876.67µs)11962026/07/19 11:39:24 OK 2_object_stats_trigger.sql (292.5µs)11972026/07/19 11:39:24 goose: up to current file version: 21198=== NAME TestNARDeduplicationMetadataUploadBug1199 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-16068-4224019181/TestNARDeduplicationMetadataUploadBug3858424096/001/store/37zgvfa6r29gxr00862rawyk8d5i1l85-file2.txt1200--- PASS: TestCacheStatsHandler (0.42s)1201=== CONT TestPinProtectsFromGC12022026-07-19 11:39:24.762 UTC [16304] ERROR: relation "goose_db_version" does not exist at character 3612032026-07-19 11:39:24.762 UTC [16304] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12042026-07-19 11:39:24.771 UTC [16307] ERROR: relation "goose_db_version" does not exist at character 3612052026-07-19 11:39:24.771 UTC [16307] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12062026/07/19 11:39:24 OK 20241026095416_initial_model.sql (5.21ms)12072026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (978.38µs)12082026/07/19 11:39:24 OK 20251218171726_add_pins.sql (2.23ms)12092026-07-19 11:39:24.789 UTC [16310] ERROR: relation "goose_db_version" does not exist at character 3612102026-07-19 11:39:24.789 UTC [16310] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12112026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (12.98ms)12122026/07/19 11:39:24 goose: successfully migrated database to version: 2026062812000012132026/07/19 11:39:24 OK 20241026095416_initial_model.sql (13.21ms)12142026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (762.58µs)12152026/07/19 11:39:24 OK 1_commit_pending_closure.sql (1.55ms)12162026/07/19 11:39:24 OK 2_object_stats_trigger.sql (344.63µs)12172026/07/19 11:39:24 goose: up to current file version: 212182026/07/19 11:39:24 OK 20251218171726_add_pins.sql (2.44ms)12192026/07/19 11:39:24 INFO Received uploads request method=POST path=/api/pending_closures12202026/07/19 11:39:24 INFO Received uploads request method=POST path=/api/pending_closures12212026/07/19 11:39:24 INFO Received uploads request method=POST path=/api/pending_closures12222026/07/19 11:39:24 OK 20241026095416_initial_model.sql (8.52ms)12232026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (323.38µs)12242026/07/19 11:39:24 OK 20251218171726_add_pins.sql (1.16ms)12252026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (10.07ms)12262026/07/19 11:39:24 goose: successfully migrated database to version: 2026062812000012272026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (1.42ms)12282026/07/19 11:39:24 goose: successfully migrated database to version: 2026062812000012292026/07/19 11:39:24 OK 1_commit_pending_closure.sql (821.67µs)12302026/07/19 11:39:24 OK 2_object_stats_trigger.sql (228.29µs)12312026/07/19 11:39:24 goose: up to current file version: 212322026/07/19 11:39:24 OK 1_commit_pending_closure.sql (846.17µs)12332026/07/19 11:39:24 OK 2_object_stats_trigger.sql (361.67µs)12342026/07/19 11:39:24 goose: up to current file version: 212352026/07/19 11:39:24 INFO Received cleanup request method=DELETE path=/api/pending_closures1236=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1237=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1238=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1239=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1240=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1241=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1242=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1243=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1244=== CONT TestService_AuthMiddleware_MTLSBoundSubjects12452026/07/19 11:39:24 INFO Aborted multipart uploads count=012462026/07/19 11:39:24 INFO Received uploads request method=POST path=/api/pending_closures12472026/07/19 11:39:24 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12482026/07/19 11:39:24 INFO Received cleanup request method=DELETE path=/api/pending_closures12492026/07/19 11:39:24 INFO Aborted multipart uploads count=112502026/07/19 11:39:24 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12512026-07-19 11:39:24.844 UTC [16307] ERROR: Closure does not exist: id=112522026-07-19 11:39:24.844 UTC [16307] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE12532026-07-19 11:39:24.844 UTC [16307] STATEMENT: -- name: CommitPendingClosure :exec1254 SELECT commit_pending_closure($1::bigint)1255 1256--- PASS: TestService_cleanupPendingClosuresHandler (0.38s)1257=== CONT TestService_AuthMiddleware_MTLSProxyHeader12582026/07/19 11:39:24 INFO Received uploads request method=POST path=/api/pending_closures12592026/07/19 11:39:24 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12602026/07/19 11:39:24 WARN Failed to register uploaded object key=37zgvfa6r29gxr00862rawyk8d5i1l85.ls error="server returned 404: 404 page not found\n"12612026/07/19 11:39:24 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12622026/07/19 11:39:24 INFO Signed narinfos id=2 count=112632026/07/19 11:39:24 INFO Uploading 1 narinfos12642026/07/19 11:39:24 WARN Failed to register uploaded object key=37zgvfa6r29gxr00862rawyk8d5i1l85.narinfo error="server returned 404: 404 page not found\n"12652026/07/19 11:39:24 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12662026/07/19 11:39:24 INFO Completed upload id=212672026/07/19 11:39:24 INFO Upload complete. (76ms)1268=== NAME TestNARDeduplicationMetadataUploadBug1269 metadata_upload_test.go:76: Retrieved narinfo from S3:1270 StorePath: /nix/var/nix/builds/nix-16068-4224019181/TestNARDeduplicationMetadataUploadBug3858424096/001/store/37zgvfa6r29gxr00862rawyk8d5i1l85-file2.txt1271 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1272 Compression: zstd1273 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1274 NarSize: 1601275 References: 1276 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1277 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1278 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1279 {"version":1,"root":{"type":"regular","size":44}}1280--- PASS: TestNARDeduplicationMetadataUploadBug (0.74s)1281=== CONT TestClientCADerivations12822026-07-19 11:39:24.865 UTC [16319] ERROR: relation "goose_db_version" does not exist at character 3612832026-07-19 11:39:24.865 UTC [16319] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12842026-07-19 11:39:24.865 UTC [16318] ERROR: relation "goose_db_version" does not exist at character 3612852026-07-19 11:39:24.865 UTC [16318] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12862026/07/19 11:39:24 OK 20241026095416_initial_model.sql (9.06ms)12872026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (362.25µs)12882026/07/19 11:39:24 OK 20251218171726_add_pins.sql (737.54µs)12892026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (4.21ms)12902026/07/19 11:39:24 goose: successfully migrated database to version: 2026062812000012912026/07/19 11:39:24 OK 1_commit_pending_closure.sql (966.04µs)12922026/07/19 11:39:24 OK 2_object_stats_trigger.sql (219.67µs)12932026/07/19 11:39:24 goose: up to current file version: 212942026/07/19 11:39:24 INFO Created nix-cache-info in bucket bucket=bucket3612952026/07/19 11:39:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12962026/07/19 11:39:24 OK 20241026095416_initial_model.sql (32.03ms)12972026/07/19 11:39:24 OK 20251210153512_drop_unused_gin_index.sql (357.96µs)12982026/07/19 11:39:24 OK 20251218171726_add_pins.sql (730.58µs)12992026/07/19 11:39:24 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MjY3YTczOTMtZTY1MS00ZWJjLWI2YTYtODkzOThmMzhjN2MxLjEyY2FjOGUyLWJkYzktNDRmNi05NmY2LTM4YWQ1MGIxOWY5NHgxNzg0NDYxMTY0ODExNTkyMDAw parts=1013002026/07/19 11:39:24 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13012026/07/19 11:39:24 OK 20260628120000_add_object_size_and_stats.sql (5.15ms)13022026/07/19 11:39:24 goose: successfully migrated database to version: 2026062812000013032026/07/19 11:39:24 INFO Completed upload id=113042026/07/19 11:39:24 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000013052026/07/19 11:39:24 INFO Received uploads request method=POST path=/api/pending_closures13062026/07/19 11:39:24 OK 1_commit_pending_closure.sql (1.52ms)13072026/07/19 11:39:24 INFO Starting cleanup of old closures method=DELETE path=/api/closures13082026/07/19 11:39:24 OK 2_object_stats_trigger.sql (343.88µs)13092026/07/19 11:39:24 goose: up to current file version: 213102026/07/19 11:39:24 INFO Aborted multipart uploads count=013112026/07/19 11:39:24 INFO Created nix-cache-info in bucket bucket=bucket3713122026/07/19 11:39:24 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=013132026/07/19 11:39:24 INFO Vacuumed table table=pending_closures13142026/07/19 11:39:24 INFO Vacuumed table table=pending_objects13152026/07/19 11:39:24 INFO Vacuumed table table=multipart_uploads1316=== NAME TestClientIntegration1317 client_integration_test.go:276: Created store path: /nix/var/nix/builds/nix-16068-4224019181/TestClientIntegration1950871098/002/store/fb63vnz1xyahni31kjzxbmza6gn92shk-test-file.txt13182026/07/19 11:39:24 INFO Vacuumed table table=closures13192026/07/19 11:39:24 INFO Vacuumed table table=objects13202026/07/19 11:39:25 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001321--- PASS: TestService_createPendingClosureHandler (0.58s)1322=== CONT TestClientErrorHandling1323=== RUN TestClientErrorHandling/InvalidStorePath1324=== PAUSE TestClientErrorHandling/InvalidStorePath1325=== RUN TestClientErrorHandling/InvalidAuthToken1326=== PAUSE TestClientErrorHandling/InvalidAuthToken1327=== RUN TestClientErrorHandling/ServerNotAvailable1328=== PAUSE TestClientErrorHandling/ServerNotAvailable1329=== CONT TestService_ReadAuthMiddleware13302026/07/19 11:39:25 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13312026/07/19 11:39:25 INFO Received uploads request method=POST path=/api/pending_closures13322026/07/19 11:39:25 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13332026/07/19 11:39:25 INFO Uploading fb63vnz1xyahni31kjzxbmza6gn92shk-test-file.txt (152B)13342026/07/19 11:39:25 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"13352026/07/19 11:39:25 WARN Failed to register uploaded object key=fb63vnz1xyahni31kjzxbmza6gn92shk.ls error="server returned 404: 404 page not found\n"13362026/07/19 11:39:25 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13372026/07/19 11:39:25 INFO Signed narinfos id=1 count=113382026/07/19 11:39:25 INFO Uploading 1 narinfos13392026/07/19 11:39:25 WARN Failed to register uploaded object key=fb63vnz1xyahni31kjzxbmza6gn92shk.narinfo error="server returned 404: 404 page not found\n"13402026/07/19 11:39:25 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13412026/07/19 11:39:25 INFO Completed upload id=113422026/07/19 11:39:25 INFO Upload complete. (97ms)1343=== NAME TestClientIntegration1344 client_integration_test.go:292: Retrieved narinfo from S3:1345 StorePath: /nix/var/nix/builds/nix-16068-4224019181/TestClientIntegration1950871098/002/store/fb63vnz1xyahni31kjzxbmza6gn92shk-test-file.txt1346 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1347 Compression: zstd1348 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11349 NarSize: 1521350 References: 1351 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11352 client_integration_test.go:293: Retrieved .ls file from S3 (compressed size: 77 bytes)1353 client_integration_test.go:293: Decompressed .ls content (64 bytes):1354 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1355 client_integration_test.go:296: Testing garbage collection...13562026-07-19 11:39:25.128 UTC [16339] ERROR: relation "goose_db_version" does not exist at character 3613572026-07-19 11:39:25.128 UTC [16339] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13582026/07/19 11:39:25 INFO Starting cleanup of old closures method=DELETE path=/api/closures13592026/07/19 11:39:25 INFO Garbage collection started13602026/07/19 11:39:25 INFO Aborted multipart uploads count=01361=== NAME TestClientWithDependencies1362 client_integration_test.go:593: Built derivation: /nix/var/nix/builds/nix-16068-4224019181/TestClientWithDependencies2510571448/001/store/4gp2hq014r3h93nnsvwcl34a9g5zpj80-test-script13632026/07/19 11:39:25 WARN Force mode enabled - objects will be deleted immediately without grace period13642026-07-19 11:39:25.143 UTC [16343] ERROR: relation "goose_db_version" does not exist at character 3613652026-07-19 11:39:25.143 UTC [16343] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13662026/07/19 11:39:25 OK 20241026095416_initial_model.sql (8.74ms)13672026/07/19 11:39:25 OK 20251210153512_drop_unused_gin_index.sql (396.46µs)13682026/07/19 11:39:25 OK 20251218171726_add_pins.sql (903.79µs)13692026/07/19 11:39:25 OK 20260628120000_add_object_size_and_stats.sql (2.45ms)13702026/07/19 11:39:25 goose: successfully migrated database to version: 2026062812000013712026/07/19 11:39:25 OK 20241026095416_initial_model.sql (8.58ms)13722026/07/19 11:39:25 OK 20251210153512_drop_unused_gin_index.sql (411.79µs)13732026/07/19 11:39:25 OK 1_commit_pending_closure.sql (897.17µs)13742026/07/19 11:39:25 OK 2_object_stats_trigger.sql (382.33µs)13752026/07/19 11:39:25 goose: up to current file version: 213762026/07/19 11:39:25 OK 20251218171726_add_pins.sql (1.07ms)13772026-07-19 11:39:25.172 UTC [16345] ERROR: relation "goose_db_version" does not exist at character 3613782026-07-19 11:39:25.172 UTC [16345] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1379 client_integration_test.go:595: Found 1 dependencies (including self)13802026/07/19 11:39:25 OK 20260628120000_add_object_size_and_stats.sql (15.16ms)13812026/07/19 11:39:25 goose: successfully migrated database to version: 2026062812000013822026/07/19 11:39:25 OK 1_commit_pending_closure.sql (987.13µs)13832026/07/19 11:39:25 OK 2_object_stats_trigger.sql (415.21µs)13842026/07/19 11:39:25 goose: up to current file version: 213852026/07/19 11:39:25 INFO Created nix-cache-info in bucket bucket=bucket3913862026/07/19 11:39:25 OK 20241026095416_initial_model.sql (9.84ms)13872026/07/19 11:39:25 OK 20251210153512_drop_unused_gin_index.sql (377.17µs)13882026/07/19 11:39:25 OK 20251218171726_add_pins.sql (1.76ms)13892026/07/19 11:39:25 OK 20260628120000_add_object_size_and_stats.sql (2.94ms)13902026/07/19 11:39:25 goose: successfully migrated database to version: 2026062812000013912026/07/19 11:39:25 OK 1_commit_pending_closure.sql (1.65ms)13922026/07/19 11:39:25 OK 2_object_stats_trigger.sql (546.13µs)13932026/07/19 11:39:25 goose: up to current file version: 213942026/07/19 11:39:25 INFO Created nix-cache-info in bucket bucket=bucket4013952026-07-19 11:39:25.209 UTC [16351] ERROR: relation "goose_db_version" does not exist at character 3613962026-07-19 11:39:25.209 UTC [16351] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13972026-07-19 11:39:25.210 UTC [16350] ERROR: relation "goose_db_version" does not exist at character 3613982026-07-19 11:39:25.210 UTC [16350] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13992026-07-19 11:39:25.215 UTC [16353] ERROR: relation "goose_db_version" does not exist at character 3614002026-07-19 11:39:25.215 UTC [16353] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14012026/07/19 11:39:25 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14022026/07/19 11:39:25 INFO Received uploads request method=POST path=/api/pending_closures14032026/07/19 11:39:25 OK 20241026095416_initial_model.sql (41.91ms)1404=== NAME TestClientMultipleUploads1405 client_integration_test.go:338: Created store path 0: /nix/var/nix/builds/nix-16068-4224019181/TestClientMultipleUploads1727566962/001/store/ns3m5z666dy98if0rqbhjg45j9ahkk1r-test-file-0.txt14062026/07/19 11:39:25 OK 20251210153512_drop_unused_gin_index.sql (966.13µs)14072026/07/19 11:39:25 OK 20251218171726_add_pins.sql (14.28ms)14082026/07/19 11:39:25 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14092026/07/19 11:39:25 INFO Uploading 4gp2hq014r3h93nnsvwcl34a9g5zpj80-test-script (136B)14102026/07/19 11:39:25 OK 20260628120000_add_object_size_and_stats.sql (3.52ms)14112026/07/19 11:39:25 goose: successfully migrated database to version: 2026062812000014122026/07/19 11:39:25 OK 20241026095416_initial_model.sql (48.13ms)14132026/07/19 11:39:25 OK 20241026095416_initial_model.sql (19.11ms)14142026/07/19 11:39:25 OK 20251210153512_drop_unused_gin_index.sql (822.58µs)14152026/07/19 11:39:25 OK 20251210153512_drop_unused_gin_index.sql (657.29µs)14162026/07/19 11:39:25 OK 1_commit_pending_closure.sql (1.53ms)14172026/07/19 11:39:25 WARN Failed to register uploaded object key=log/l27s7ck3cknhpd1zii2vkhzqmqnfz6c1-test-script.drv error="server returned 404: 404 page not found\n"14182026/07/19 11:39:25 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"14192026/07/19 11:39:25 OK 2_object_stats_trigger.sql (438.96µs)14202026/07/19 11:39:25 goose: up to current file version: 214212026/07/19 11:39:25 OK 20251218171726_add_pins.sql (1.54ms)14222026/07/19 11:39:25 WARN Failed to register uploaded object key=4gp2hq014r3h93nnsvwcl34a9g5zpj80.ls error="server returned 404: 404 page not found\n"14232026/07/19 11:39:25 OK 20251218171726_add_pins.sql (2.62ms)14242026/07/19 11:39:25 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14252026/07/19 11:39:25 INFO Signed narinfos id=1 count=114262026/07/19 11:39:25 OK 20260628120000_add_object_size_and_stats.sql (1.66ms)14272026/07/19 11:39:25 goose: successfully migrated database to version: 2026062812000014282026/07/19 11:39:25 INFO Uploading 1 narinfos14292026/07/19 11:39:25 OK 20260628120000_add_object_size_and_stats.sql (1.77ms)14302026/07/19 11:39:25 goose: successfully migrated database to version: 2026062812000014312026/07/19 11:39:25 OK 1_commit_pending_closure.sql (1.55ms)14322026/07/19 11:39:25 INFO Created nix-cache-info in bucket bucket=bucket4114332026/07/19 11:39:25 WARN Failed to register uploaded object key=4gp2hq014r3h93nnsvwcl34a9g5zpj80.narinfo error="server returned 404: 404 page not found\n"14342026/07/19 11:39:25 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14352026/07/19 11:39:25 OK 2_object_stats_trigger.sql (493.63µs)14362026/07/19 11:39:25 goose: up to current file version: 214372026/07/19 11:39:25 OK 1_commit_pending_closure.sql (1.3ms)14382026/07/19 11:39:25 OK 2_object_stats_trigger.sql (413.83µs)14392026/07/19 11:39:25 goose: up to current file version: 21440--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.44s)1441=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info14422026/07/19 11:39:25 INFO Received uploads request method=POST path=/1443=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal14442026/07/19 11:39:25 INFO Received uploads request method=POST path=/1445=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key14462026/07/19 11:39:25 INFO Received request for more parts method=POST path=/1447=== CONT TestProxyWriteTimeout/narinfo1448=== CONT TestProxyWriteTimeout/10_GiB_nar1449=== CONT TestProxyWriteTimeout/unknown_size1450=== CONT TestProxyWriteTimeout/1_GiB_nar1451--- PASS: TestProxyWriteTimeout (0.02s)1452 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1453 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1454 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1455 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1456=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key14572026/07/19 11:39:25 INFO Received complete multipart upload request method=POST path=/1458--- PASS: TestUploadHandlersRejectInvalidKeys (0.02s)1459 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1460 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1461 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1462 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1463=== CONT TestIsValidUploadKey/narinfo1464=== CONT TestIsValidUploadKey/realisation_plus_in_output1465=== CONT TestIsValidUploadKey/unknown_type1466=== CONT TestIsValidUploadKey/empty_key1467=== CONT TestIsValidUploadKey/absolute1468=== CONT TestIsValidUploadKey/traversal_nar1469=== CONT TestIsValidUploadKey/traversal1470=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1471=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1472=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1473=== CONT TestIsValidUploadKey/index.html1474=== CONT TestIsValidUploadKey/nix-cache-info1475=== CONT TestIsValidUploadKey/build_log_home-manager_file1476=== CONT TestIsValidUploadKey/realisation1477=== CONT TestIsValidUploadKey/build_log_equals1478=== CONT TestIsValidUploadKey/build_log_question_mark1479=== CONT TestIsValidUploadKey/build_log_plus_in_name1480=== CONT TestIsValidUploadKey/nar_plain1481=== CONT TestIsValidUploadKey/build_log1482=== CONT TestIsValidUploadKey/listing1483=== CONT TestIsValidUploadKey/nar_xz1484=== CONT TestIsValidUploadKey/nar_zst1485--- PASS: TestIsValidUploadKey (0.02s)1486 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1487 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1488 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1489 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1490 --- PASS: TestIsValidUploadKey/absolute (0.00s)1491 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1492 --- PASS: TestIsValidUploadKey/traversal (0.00s)1493 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1494 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1495 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1496 --- PASS: TestIsValidUploadKey/index.html (0.00s)1497 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1498 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1499 --- PASS: TestIsValidUploadKey/realisation (0.00s)1500 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1501 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1502 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1503 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1504 --- PASS: TestIsValidUploadKey/build_log (0.00s)1505 --- PASS: TestIsValidUploadKey/listing (0.00s)1506 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1507 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1508=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure15092026/07/19 11:39:25 INFO Received uploads request method=POST path=/15102026/07/19 11:39:25 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15112026/07/19 11:39:25 WARN mTLS auth: bound subjects configured but subject DN unavailable15122026/07/19 11:39:25 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1513--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.48s)1514=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart15152026/07/19 11:39:25 INFO Received complete multipart upload request method=POST path=/15162026/07/19 11:39:25 INFO Completed upload id=115172026/07/19 11:39:25 INFO Upload complete. (76ms)1518=== NAME TestClientWithDependencies1519 client_integration_test.go:597: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-16068-4224019181/TestClientWithDependencies2510571448/001/store) requires matching store prefix1520--- PASS: TestClientWithDependencies (0.80s)1521=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts15222026/07/19 11:39:25 INFO Received request for more parts method=POST path=/1523=== NAME TestClientMultipleUploads1524 client_integration_test.go:338: Created store path 1: /nix/var/nix/builds/nix-16068-4224019181/TestClientMultipleUploads1727566962/001/store/sb08rap8vz8n7vwdmxg5qf4dq9x30gkm-test-file-1.txt1525=== CONT TestIsValidCachePath/narinfo1526=== CONT TestIsValidCachePath/index.html1527=== CONT TestIsValidCachePath/short_hash1528=== CONT TestIsValidCachePath/wrong_extension1529=== CONT TestIsValidCachePath/leading_slash1530=== CONT TestIsValidCachePath/empty1531=== CONT TestIsValidCachePath/random_path1532=== CONT TestIsValidCachePath/invalid_char_u1533=== CONT TestIsValidCachePath/invalid_char_e1534=== CONT TestIsValidCachePath/traversal_in_middle1535=== CONT TestIsValidCachePath/traversal_parent1536=== CONT TestIsValidCachePath/nar_uncompressed1537=== CONT TestIsValidCachePath/nix-cache-info1538=== CONT TestIsValidCachePath/realisation1539=== CONT TestIsValidCachePath/log1540=== CONT TestIsValidCachePath/ls1541=== CONT TestIsValidCachePath/nar_xz1542=== CONT TestIsValidCachePath/nar_bz21543=== CONT TestIsValidCachePath/nar_zst1544=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1545--- PASS: TestIsValidCachePath (0.00s)1546 --- PASS: TestIsValidCachePath/narinfo (0.00s)1547 --- PASS: TestIsValidCachePath/index.html (0.00s)1548 --- PASS: TestIsValidCachePath/short_hash (0.00s)1549 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1550 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1551 --- PASS: TestIsValidCachePath/empty (0.00s)1552 --- PASS: TestIsValidCachePath/random_path (0.00s)1553 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1554 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1555 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1556 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1557 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1558 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1559 --- PASS: TestIsValidCachePath/realisation (0.00s)1560 --- PASS: TestIsValidCachePath/log (0.00s)1561 --- PASS: TestIsValidCachePath/ls (0.00s)1562 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1563 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1564 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1565 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1566=== CONT TestParseSingleRange/none1567=== CONT TestParseSingleRange/open-ended1568=== CONT TestParseSingleRange/start_far_past_EOF1569=== CONT TestParseSingleRange/start_past_EOF1570=== CONT TestParseSingleRange/single_byte1571=== CONT TestParseSingleRange/suffix_exceeds_size1572=== CONT TestParseSingleRange/suffix1573=== CONT TestParseSingleRange/end_clamped_to_size1574=== CONT TestParseSingleRange/malformed_both_empty1575=== CONT TestParseSingleRange/closed1576=== CONT TestParseSingleRange/malformed_end_before_start1577=== CONT TestParseSingleRange/multi-range_ignored1578=== CONT TestParseSingleRange/malformed_no_dash1579=== CONT TestParseSingleRange/unknown_unit1580--- PASS: TestParseSingleRange (0.00s)1581 --- PASS: TestParseSingleRange/none (0.00s)1582 --- PASS: TestParseSingleRange/open-ended (0.00s)1583 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1584 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1585 --- PASS: TestParseSingleRange/single_byte (0.00s)1586 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1587 --- PASS: TestParseSingleRange/suffix (0.00s)1588 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1589 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1590 --- PASS: TestParseSingleRange/closed (0.00s)1591 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1592 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1593 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1594 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1595=== CONT TestServerTLSConfig/no_client_CA1596=== CONT TestServerTLSConfig/not_a_PEM_file1597=== CONT TestServerTLSConfig/missing_CA_file1598--- PASS: TestServerTLSConfig (0.00s)1599 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1600 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1601 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1602=== CONT TestCacheConfigHandler/full_config,_no_issuer1603=== CONT TestCacheConfigHandler/no_signing_keys1604=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1605=== CONT TestCacheConfigHandler/no_cache_url_configured1606--- PASS: TestCacheConfigHandler (0.00s)1607 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1608 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1609 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1610 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1611=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token16122026/07/19 11:39:25 INFO OIDC auth successful provider=test1613=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected16142026/07/19 11:39:25 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]1615=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1616=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected16172026-07-19 11:39:25.316 UTC [16364] ERROR: relation "goose_db_version" does not exist at character 3616182026-07-19 11:39:25.316 UTC [16364] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16192026/07/19 11:39:25 WARN Authentication failed token_preview=eyJhbGciOi...b26kgovVbw 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]1620=== CONT TestClientErrorHandling/InvalidStorePath1621--- PASS: TestService_AuthMiddleware_OIDC (0.36s)1622 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1623 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1624 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1625 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1626=== CONT TestClientErrorHandling/ServerNotAvailable1627=== NAME TestPinProtectsFromGC1628 client_integration_test.go:646: Pinned store path: /nix/var/nix/builds/nix-16068-4224019181/TestPinProtectsFromGC2699194146/001/store/c3zr1dkmbxs591jf58gs3jfplp6ycabc-pinned-file.txt1629 client_integration_test.go:647: Unpinned store path: /nix/var/nix/builds/nix-16068-4224019181/TestPinProtectsFromGC2699194146/001/store/i0y0llncrqm0vn3m54aa1rxczy6k2vaj-unpinned-file.txt16302026/07/19 11:39:25 OK 20241026095416_initial_model.sql (6.24ms)16312026/07/19 11:39:25 OK 20251210153512_drop_unused_gin_index.sql (4.63ms)16322026/07/19 11:39:25 OK 20251218171726_add_pins.sql (9.44ms)1633=== NAME TestClientMultipleUploads1634 client_integration_test.go:338: Created store path 2: /nix/var/nix/builds/nix-16068-4224019181/TestClientMultipleUploads1727566962/001/store/c7yzabc6xwx70k44bwsiq8nrx71nf58f-test-file-2.txt16352026/07/19 11:39:25 OK 20260628120000_add_object_size_and_stats.sql (2.8ms)16362026/07/19 11:39:25 goose: successfully migrated database to version: 2026062812000016372026/07/19 11:39:25 OK 1_commit_pending_closure.sql (1.9ms)16382026/07/19 11:39:25 OK 2_object_stats_trigger.sql (612.46µs)16392026/07/19 11:39:25 goose: up to current file version: 216402026/07/19 11:39:25 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1641--- PASS: TestService_ReadAuthMiddleware (0.33s)1642=== CONT TestClientErrorHandling/InvalidAuthToken1643--- PASS: TestGCBugBareHashReferences (0.65s)16442026/07/19 11:39:25 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16452026/07/19 11:39:25 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16462026/07/19 11:39:25 INFO Received uploads request method=POST path=/api/pending_closures16472026/07/19 11:39:25 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16482026/07/19 11:39:25 INFO Uploading c3zr1dkmbxs591jf58gs3jfplp6ycabc-pinned-file.txt (128B)16492026/07/19 11:39:25 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16502026/07/19 11:39:25 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=016512026/07/19 11:39:25 WARN Failed to register uploaded object key=c3zr1dkmbxs591jf58gs3jfplp6ycabc.ls error="server returned 404: 404 page not found\n"16522026/07/19 11:39:25 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16532026/07/19 11:39:25 INFO Signed narinfos id=1 count=116542026/07/19 11:39:25 INFO Uploading 1 narinfos16552026/07/19 11:39:25 WARN Failed to register uploaded object key=c3zr1dkmbxs591jf58gs3jfplp6ycabc.narinfo error="server returned 404: 404 page not found\n"16562026/07/19 11:39:25 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16572026-07-19 11:39:25.458 UTC [16391] ERROR: relation "goose_db_version" does not exist at character 3616582026-07-19 11:39:25.458 UTC [16391] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16592026/07/19 11:39:25 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-config16602026/07/19 11:39:25 INFO Vacuumed table table=pending_closures16612026/07/19 11:39:25 INFO Vacuumed table table=pending_objects16622026/07/19 11:39:25 INFO Vacuumed table table=multipart_uploads16632026/07/19 11:39:25 INFO Completed upload id=116642026/07/19 11:39:25 INFO Upload complete. (100ms)16652026/07/19 11:39:25 INFO Vacuumed table table=closures16662026/07/19 11:39:25 INFO Vacuumed table table=objects16672026/07/19 11:39:25 INFO Received uploads request method=POST path=/api/pending_closures16682026/07/19 11:39:25 INFO Received uploads request method=POST path=/api/pending_closures16692026/07/19 11:39:25 INFO Received uploads request method=POST path=/api/pending_closures16702026/07/19 11:39:25 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16712026/07/19 11:39:25 INFO Uploading c7yzabc6xwx70k44bwsiq8nrx71nf58f-test-file-2.txt (160B)16722026/07/19 11:39:25 INFO Uploading ns3m5z666dy98if0rqbhjg45j9ahkk1r-test-file-0.txt (160B)16732026/07/19 11:39:25 INFO Uploading sb08rap8vz8n7vwdmxg5qf4dq9x30gkm-test-file-1.txt (160B)16742026/07/19 11:39:25 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16752026/07/19 11:39:25 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16762026/07/19 11:39:25 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"16772026/07/19 11:39:25 OK 20241026095416_initial_model.sql (6.21ms)16782026/07/19 11:39:25 WARN Failed to register uploaded object key=c7yzabc6xwx70k44bwsiq8nrx71nf58f.ls error="server returned 404: 404 page not found\n"16792026/07/19 11:39:25 OK 20251210153512_drop_unused_gin_index.sql (508.38µs)16802026/07/19 11:39:25 WARN Failed to register uploaded object key=sb08rap8vz8n7vwdmxg5qf4dq9x30gkm.ls error="server returned 404: 404 page not found\n"16812026/07/19 11:39:25 WARN Failed to register uploaded object key=ns3m5z666dy98if0rqbhjg45j9ahkk1r.ls error="server returned 404: 404 page not found\n"16822026/07/19 11:39:25 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign16832026/07/19 11:39:25 INFO Signed narinfos id=3 count=116842026/07/19 11:39:25 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16852026/07/19 11:39:25 INFO Signed narinfos id=1 count=116862026/07/19 11:39:25 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16872026/07/19 11:39:25 INFO Signed narinfos id=2 count=116882026/07/19 11:39:25 INFO Uploading 3 narinfos16892026/07/19 11:39:25 OK 20251218171726_add_pins.sql (1.9ms)16902026/07/19 11:39:25 WARN Failed to register uploaded object key=c7yzabc6xwx70k44bwsiq8nrx71nf58f.narinfo error="server returned 404: 404 page not found\n"16912026/07/19 11:39:25 WARN Failed to register uploaded object key=sb08rap8vz8n7vwdmxg5qf4dq9x30gkm.narinfo error="server returned 404: 404 page not found\n"16922026/07/19 11:39:25 WARN Failed to register uploaded object key=ns3m5z666dy98if0rqbhjg45j9ahkk1r.narinfo error="server returned 404: 404 page not found\n"16932026/07/19 11:39:25 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete16942026/07/19 11:39:25 OK 20260628120000_add_object_size_and_stats.sql (1.75ms)16952026/07/19 11:39:25 goose: successfully migrated database to version: 2026062812000016962026/07/19 11:39:25 INFO Completed upload id=316972026/07/19 11:39:25 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16982026/07/19 11:39:25 OK 1_commit_pending_closure.sql (1.24ms)16992026/07/19 11:39:25 INFO Completed upload id=117002026/07/19 11:39:25 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17012026/07/19 11:39:25 OK 2_object_stats_trigger.sql (595.54µs)17022026/07/19 11:39:25 goose: up to current file version: 217032026/07/19 11:39:25 INFO Completed upload id=217042026/07/19 11:39:25 INFO Upload complete. (96ms)1705=== NAME TestClientMultipleUploads1706 client_integration_test.go:349: Uploaded 3 paths in 134.493875ms1707--- PASS: TestClientMultipleUploads (0.80s)17082026-07-19 11:39:25.490 UTC [16395] ERROR: relation "goose_db_version" does not exist at character 3617092026-07-19 11:39:25.490 UTC [16395] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17102026/07/19 11:39:25 OK 20241026095416_initial_model.sql (3.07ms)17112026/07/19 11:39:25 OK 20251210153512_drop_unused_gin_index.sql (626.42µs)17122026/07/19 11:39:25 OK 20251218171726_add_pins.sql (1.36ms)17132026/07/19 11:39:25 OK 20260628120000_add_object_size_and_stats.sql (883.13µs)17142026/07/19 11:39:25 goose: successfully migrated database to version: 2026062812000017152026/07/19 11:39:25 OK 1_commit_pending_closure.sql (1.31ms)17162026/07/19 11:39:25 OK 2_object_stats_trigger.sql (529.33µs)17172026/07/19 11:39:25 goose: up to current file version: 21718=== NAME TestClientCADerivations1719 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-16068-4224019181/TestClientCADerivations3704035818/001/store/x3lnywhsysx1p5k5hjkldnw0j7fi7abg-ca-test17202026/07/19 11:39:25 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1721 client_ca_test.go:139: Found 1 dependencies (including self)17222026/07/19 11:39:25 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=185.418008ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17232026/07/19 11:39:25 INFO Received uploads request method=POST path=/api/pending_closures17242026/07/19 11:39:25 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17252026/07/19 11:39:25 INFO Uploading i0y0llncrqm0vn3m54aa1rxczy6k2vaj-unpinned-file.txt (128B)17262026/07/19 11:39:25 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"17272026/07/19 11:39:25 WARN Failed to register uploaded object key=i0y0llncrqm0vn3m54aa1rxczy6k2vaj.ls error="server returned 404: 404 page not found\n"17282026/07/19 11:39:25 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign17292026/07/19 11:39:25 INFO Signed narinfos id=2 count=117302026/07/19 11:39:25 INFO Uploading 1 narinfos17312026/07/19 11:39:25 WARN Failed to register uploaded object key=i0y0llncrqm0vn3m54aa1rxczy6k2vaj.narinfo error="server returned 404: 404 page not found\n"17322026/07/19 11:39:25 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17332026/07/19 11:39:25 INFO Completed upload id=217342026/07/19 11:39:25 INFO Upload complete. (66ms)1735--- PASS: TestUploadHandlersRejectOversizedBody (0.03s)1736 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1737 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1738 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.31s)17392026/07/19 11:39:25 INFO Received create pin request method=POST path=/api/pins/myapp17402026/07/19 11:39:25 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-16068-4224019181/TestPinProtectsFromGC2699194146/001/store/c3zr1dkmbxs591jf58gs3jfplp6ycabc-pinned-file.txt narinfo_key=c3zr1dkmbxs591jf58gs3jfplp6ycabc.narinfo17412026/07/19 11:39:25 INFO Starting cleanup of old closures method=DELETE path=/api/closures17422026/07/19 11:39:25 INFO Garbage collection started17432026/07/19 11:39:25 INFO Aborted multipart uploads count=017442026/07/19 11:39:25 WARN Force mode enabled - objects will be deleted immediately without grace period17452026/07/19 11:39:25 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17462026/07/19 11:39:25 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17472026/07/19 11:39:25 INFO Received uploads request method=POST path=/api/pending_closures17482026/07/19 11:39:25 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"17492026/07/19 11:39:25 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17502026/07/19 11:39:25 INFO Uploading x3lnywhsysx1p5k5hjkldnw0j7fi7abg-ca-test (144B)17512026/07/19 11:39:25 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"17522026/07/19 11:39:25 WARN Failed to register uploaded object key=log/2cjbxzfb40dgrvdywnsajvl6w8904ixh-ca-test.drv error="server returned 404: 404 page not found\n"17532026/07/19 11:39:25 WARN Failed to register uploaded object key=x3lnywhsysx1p5k5hjkldnw0j7fi7abg.ls error="server returned 404: 404 page not found\n"17542026/07/19 11:39:25 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17552026/07/19 11:39:25 INFO Signed narinfos id=1 count=117562026/07/19 11:39:25 INFO Uploading 1 narinfos17572026/07/19 11:39:25 WARN Failed to register uploaded object key=x3lnywhsysx1p5k5hjkldnw0j7fi7abg.narinfo error="server returned 404: 404 page not found\n"17582026/07/19 11:39:25 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17592026/07/19 11:39:25 INFO Completed upload id=117602026/07/19 11:39:25 INFO Upload complete. (68ms)1761=== NAME TestClientCADerivations1762 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-16068-4224019181/TestClientCADerivations3704035818/001/store/x3lnywhsysx1p5k5hjkldnw0j7fi7abg-ca-test1763 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1764 Compression: zstd1765 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1766 NarSize: 1441767 References: 1768 Deriver: /nix/var/nix/builds/nix-16068-4224019181/TestClientCADerivations3704035818/001/store/2cjbxzfb40dgrvdywnsajvl6w8904ixh-ca-test.drv1769 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1770 client_ca_test.go:185: Checking for realisation files in S3...1771 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1772 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1773 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket41?endpoint=http://localhost:60614®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-16068-4224019181/TestClientCADerivations3704035818/001/store'1774 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11775--- PASS: TestClientCADerivations (0.83s)17762026/07/19 11:39:25 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=366.825616ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17772026/07/19 11:39:25 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=017782026/07/19 11:39:25 INFO Vacuumed table table=pending_closures17792026/07/19 11:39:25 INFO Vacuumed table table=pending_objects17802026/07/19 11:39:25 INFO Vacuumed table table=multipart_uploads17812026/07/19 11:39:25 INFO Vacuumed table table=closures17822026/07/19 11:39:25 INFO Vacuumed table table=objects17832026/07/19 11:39:26 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=824.058159ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17842026/07/19 11:39:26 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.613371352s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17852026/07/19 11:39:27 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01786=== NAME TestClientIntegration1787 client_integration_test.go:303: Objects in database after GC:1788 client_integration_test.go:303: Successfully deleted all objects with GC --force1789--- PASS: TestClientIntegration (2.67s)17902026/07/19 11:39:27 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01791=== NAME TestPinProtectsFromGC1792 client_integration_test.go:709: Pin successfully protected closure from garbage collection1793--- PASS: TestPinProtectsFromGC (2.85s)17942026/07/19 11:39:28 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"17952026/07/19 11:39:28 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_closures17962026/07/19 11:39:28 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=209.191551ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures17972026/07/19 11:39:28 WARN Rate limiter enabled after throttle name=s3-test rate=517982026/07/19 11:39:28 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1799=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1800 throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=101801 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001802--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.63s)18032026/07/19 11:39:28 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=419.139369ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures18042026/07/19 11:39:29 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=879.908511ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures18052026/07/19 11:39:30 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.503567224s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1806--- PASS: TestClientErrorHandling (0.00s)1807 --- PASS: TestClientErrorHandling/InvalidStorePath (0.20s)1808 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.29s)1809 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.45s)1810PASS1811{"timestamp":"2026-07-19T11:39:32.271574Z","level":"ERROR","fields":{"message":"Unknown connection IO error:Cancelled","peer_addr":"127.0.0.1:60667"},"target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":973,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}18122026-07-19 11:39:32.339 UTC [16104] LOG: received smart shutdown request18132026-07-19 11:39:32.340 UTC [16104] LOG: background worker "logical replication launcher" (PID 16114) exited with exit code 118142026-07-19 11:39:32.349 UTC [16109] LOG: shutting down18152026-07-19 11:39:32.349 UTC [16109] LOG: checkpoint starting: shutdown immediate18162026-07-19 11:39:33.347 UTC [16109] LOG: checkpoint complete: wrote 12660 buffers (77.3%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 13 recycled; write=0.739 s, sync=0.256 s, total=0.998 s; sync files=15167, longest=0.001 s, average=0.001 s; distance=212065 kB, estimate=212065 kB; lsn=0/E69DB90, redo lsn=0/E69DB9018172026-07-19 11:39:33.351 UTC [16104] LOG: database system is shut down1818Running OIDC tests...1819=== RUN TestGlobMatch1820=== PAUSE TestGlobMatch1821=== RUN TestAudienceForIssuer1822=== PAUSE TestAudienceForIssuer1823=== RUN TestValidateToken_ValidToken1824=== PAUSE TestValidateToken_ValidToken1825=== RUN TestValidateToken_WrongAudience1826=== PAUSE TestValidateToken_WrongAudience1827=== RUN TestValidateToken_Expired1828=== PAUSE TestValidateToken_Expired1829=== RUN TestValidateToken_BoundClaimsMismatch1830=== PAUSE TestValidateToken_BoundClaimsMismatch1831=== RUN TestValidateToken_BoundSubjectMismatch1832=== PAUSE TestValidateToken_BoundSubjectMismatch1833=== RUN TestValidateToken_MultipleProviders1834=== PAUSE TestValidateToken_MultipleProviders1835=== RUN TestValidateToken_NoMatchingProvider1836=== PAUSE TestValidateToken_NoMatchingProvider1837=== CONT TestGlobMatch1838=== CONT TestValidateToken_MultipleProviders1839=== RUN TestGlobMatch/foo_foo1840=== PAUSE TestGlobMatch/foo_foo1841=== RUN TestGlobMatch/foo_bar1842=== PAUSE TestGlobMatch/foo_bar1843=== RUN TestGlobMatch/*_1844=== PAUSE TestGlobMatch/*_1845=== CONT TestValidateToken_NoMatchingProvider1846=== RUN TestGlobMatch/*_anything1847=== PAUSE TestGlobMatch/*_anything1848=== RUN TestGlobMatch/foo*_foo1849=== PAUSE TestGlobMatch/foo*_foo1850=== RUN TestGlobMatch/foo*_foobar1851=== PAUSE TestGlobMatch/foo*_foobar1852=== RUN TestGlobMatch/foo*_bar1853=== PAUSE TestGlobMatch/foo*_bar1854=== RUN TestGlobMatch/*bar_bar1855=== PAUSE TestGlobMatch/*bar_bar1856=== RUN TestGlobMatch/*bar_foobar1857=== PAUSE TestGlobMatch/*bar_foobar1858=== RUN TestGlobMatch/*bar_foo1859=== CONT TestValidateToken_WrongAudience1860=== CONT TestValidateToken_Expired1861=== 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=== CONT TestValidateToken_BoundSubjectMismatch1872=== PAUSE TestGlobMatch/*/*_foo1873=== RUN TestGlobMatch/refs/heads/*_refs/heads/main1874=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main1875=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.01876=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.01877=== RUN TestGlobMatch/refs/*/main_refs/heads/main1878=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main1879=== RUN TestGlobMatch/fo?_foo1880=== PAUSE TestGlobMatch/fo?_foo1881=== RUN TestGlobMatch/fo?_fo1882=== PAUSE TestGlobMatch/fo?_fo1883=== RUN TestGlobMatch/fo?_fooo1884=== PAUSE TestGlobMatch/fo?_fooo1885=== RUN TestGlobMatch/?oo_foo1886=== CONT TestValidateToken_ValidToken1887=== CONT TestAudienceForIssuer1888--- PASS: TestAudienceForIssuer (0.00s)1889=== CONT TestValidateToken_BoundClaimsMismatch1890=== PAUSE TestGlobMatch/?oo_foo1891=== RUN TestGlobMatch/?oo_boo1892=== PAUSE TestGlobMatch/?oo_boo1893=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1894=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1895=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1896=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1897=== CONT TestGlobMatch/foo_foo1898=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1899=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1900=== CONT TestGlobMatch/?oo_boo1901=== CONT TestGlobMatch/?oo_foo1902=== CONT TestGlobMatch/fo?_fooo1903=== CONT TestGlobMatch/*bar_foo1904=== CONT TestGlobMatch/*bar_foobar1905=== CONT TestGlobMatch/*bar_bar1906=== CONT TestGlobMatch/foo*bar_foobar1907=== CONT TestGlobMatch/foo_bar1908=== CONT TestGlobMatch/foo*_bar1909=== CONT TestGlobMatch/fo?_fo1910=== CONT TestGlobMatch/fo?_foo1911=== CONT TestGlobMatch/refs/*/main_refs/heads/main1912=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.01913=== CONT TestGlobMatch/*/*_foo/bar1914=== CONT TestGlobMatch/*/*_foo1915=== CONT TestGlobMatch/foo*bar_foobarbaz1916=== CONT TestGlobMatch/foo*bar_foo123bar1917=== CONT TestGlobMatch/foo*_foobar1918=== CONT TestGlobMatch/foo*_foo1919=== CONT TestGlobMatch/refs/heads/*_refs/heads/main1920=== CONT TestGlobMatch/*_1921=== CONT TestGlobMatch/*_anything1922--- PASS: TestGlobMatch (0.00s)1923 --- PASS: TestGlobMatch/foo_foo (0.00s)1924 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)1925 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)1926 --- PASS: TestGlobMatch/?oo_boo (0.00s)1927 --- PASS: TestGlobMatch/?oo_foo (0.00s)1928 --- PASS: TestGlobMatch/fo?_fooo (0.00s)1929 --- PASS: TestGlobMatch/*bar_foo (0.00s)1930 --- PASS: TestGlobMatch/*bar_foobar (0.00s)1931 --- PASS: TestGlobMatch/*bar_bar (0.00s)1932 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)1933 --- PASS: TestGlobMatch/foo_bar (0.00s)1934 --- PASS: TestGlobMatch/foo*_bar (0.00s)1935 --- PASS: TestGlobMatch/fo?_fo (0.00s)1936 --- PASS: TestGlobMatch/fo?_foo (0.00s)1937 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)1938 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)1939 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)1940 --- PASS: TestGlobMatch/*/*_foo (0.00s)1941 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)1942 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)1943 --- PASS: TestGlobMatch/foo*_foobar (0.00s)1944 --- PASS: TestGlobMatch/foo*_foo (0.00s)1945 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)1946 --- PASS: TestGlobMatch/*_ (0.00s)1947 --- PASS: TestGlobMatch/*_anything (0.00s)19482026/07/19 11:39:34 INFO OIDC provider initialized name=provider119492026/07/19 11:39:34 INFO OIDC provider initialized name=test19502026/07/19 11:39:34 INFO OIDC provider initialized name=test19512026/07/19 11:39:34 INFO OIDC provider initialized name=test19522026/07/19 11:39:34 INFO OIDC provider initialized name=test19532026/07/19 11:39:34 INFO OIDC provider initialized name=test19542026/07/19 11:39:34 INFO OIDC provider initialized name=provider119552026/07/19 11:39:34 INFO OIDC provider initialized name=provider21956--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)1957--- PASS: TestValidateToken_ValidToken (0.01s)1958--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)1959--- PASS: TestValidateToken_Expired (0.01s)1960--- PASS: TestValidateToken_WrongAudience (0.01s)1961--- PASS: TestValidateToken_NoMatchingProvider (0.01s)1962--- PASS: TestValidateToken_MultipleProviders (0.01s)1963PASS1964Running hook tests...1965=== RUN TestSendPathsEmpty1966=== PAUSE TestSendPathsEmpty1967=== RUN TestQueueEnqueueAndFetch1968=== PAUSE TestQueueEnqueueAndFetch1969=== RUN TestQueueDeduplication1970=== PAUSE TestQueueDeduplication1971=== RUN TestQueueRemove1972=== PAUSE TestQueueRemove1973=== RUN TestQueueFetchBatchLimit1974=== PAUSE TestQueueFetchBatchLimit1975=== RUN TestQueueFetchRemoveLifecycle1976=== PAUSE TestQueueFetchRemoveLifecycle1977=== RUN TestQueueConcurrentWriters1978=== PAUSE TestQueueConcurrentWriters1979=== RUN TestServerClientIntegration1980=== PAUSE TestServerClientIntegration1981=== RUN TestServerQueueError1982=== PAUSE TestServerQueueError1983=== RUN TestGetListenerSocketActivation1984 server_test.go:210: === RUN TestGetListenerSocketActivation1985 --- PASS: TestGetListenerSocketActivation (0.00s)1986 PASS1987 1988--- PASS: TestGetListenerSocketActivation (0.01s)1989=== RUN TestWorkerUploadsAndRemoves1990=== PAUSE TestWorkerUploadsAndRemoves1991=== RUN TestWorkerSkipsGCdPaths1992=== PAUSE TestWorkerSkipsGCdPaths1993=== RUN TestWorkerPrunesClosureDeps1994=== PAUSE TestWorkerPrunesClosureDeps1995=== CONT TestSendPathsEmpty1996=== CONT TestQueueConcurrentWriters1997=== CONT TestQueueFetchRemoveLifecycle1998=== CONT TestQueueRemove1999--- PASS: TestSendPathsEmpty (0.00s)2000=== CONT TestQueueDeduplication2001=== CONT TestQueueEnqueueAndFetch2002=== CONT TestWorkerUploadsAndRemoves2003=== CONT TestWorkerPrunesClosureDeps2004=== CONT TestWorkerSkipsGCdPaths2005=== CONT TestServerQueueError2006=== CONT TestQueueFetchBatchLimit20072026/07/19 11:39:34 ERROR Failed to queue paths error="permission denied" count=12008--- PASS: TestServerQueueError (0.00s)2009=== CONT TestServerClientIntegration2010--- PASS: TestServerClientIntegration (0.00s)20112026/07/19 11:39:34 INFO Upload queue status pending=220122026/07/19 11:39:34 INFO Uploading batch count=120132026/07/19 11:39:34 INFO Upload queue status pending=220142026/07/19 11:39:34 INFO Uploading batch count=22015--- PASS: TestQueueFetchBatchLimit (0.01s)2016--- PASS: TestQueueDeduplication (0.01s)2017--- PASS: TestQueueEnqueueAndFetch (0.01s)20182026/07/19 11:39:34 INFO Upload queue status pending=220192026/07/19 11:39:34 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-16068-4224019181/TestWorkerSkipsGCdPaths3605371084/002/nonexistent20202026/07/19 11:39:34 INFO Uploading batch count=12021--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2022--- PASS: TestQueueRemove (0.01s)2023--- PASS: TestWorkerSkipsGCdPaths (0.06s)2024--- PASS: TestWorkerPrunesClosureDeps (0.06s)2025--- PASS: TestWorkerUploadsAndRemoves (0.06s)2026--- PASS: TestQueueConcurrentWriters (0.16s)2027PASS