niks3-go-unit-tests
aarch64-darwin.go-unit-tests
· build #108
· 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=== CONT TestPathInfoCACompatibility80=== CONT TestParsePathInfoJSONMultiplePaths81=== CONT TestParsePathInfoJSON82=== CONT TestPathInfoHashCompatibility83=== CONT TestGetStorePathHash84=== RUN TestRateLimiterFeedback/429_enables_limiter85=== PAUSE TestRateLimiterFeedback/429_enables_limiter86=== RUN TestRateLimiterFeedback/503_enables_limiter87=== PAUSE TestRateLimiterFeedback/503_enables_limiter88=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter89=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter90=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter91=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter92=== CONT TestConvertHashToNix3293=== RUN TestConvertHashToNix32/SRI_format_to_Nix3294=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix3295=== RUN TestConvertHashToNix32/already_Nix32_format96=== PAUSE TestConvertHashToNix32/already_Nix32_format97=== RUN TestConvertHashToNix32/invalid_format98=== PAUSE TestConvertHashToNix32/invalid_format99=== CONT TestPartSizeForNAR100=== RUN TestPartSizeForNAR/zero_stays_at_minimum101=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum102=== RUN TestPartSizeForNAR/small_stays_at_minimum103=== PAUSE TestPartSizeForNAR/small_stays_at_minimum104=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum105=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum106=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts107=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts108=== RUN TestPartSizeForNAR/1_TiB109=== PAUSE TestPartSizeForNAR/1_TiB110=== RUN TestPartSizeForNAR/5_TiB_S3_max_object111=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object112=== RUN TestPartSizeForNAR/capped_at_5_GiB113=== PAUSE TestPartSizeForNAR/capped_at_5_GiB114=== CONT TestUploadMultipart_SupersededByPeer115=== RUN TestUploadMultipart_SupersededByPeer/exists116=== RUN TestPathInfoCACompatibility/null_ca_field117=== PAUSE TestUploadMultipart_SupersededByPeer/exists118=== RUN TestUploadMultipart_SupersededByPeer/missing119=== PAUSE TestPathInfoCACompatibility/null_ca_field120=== PAUSE TestUploadMultipart_SupersededByPeer/missing121=== RUN TestPathInfoCACompatibility/old_string_format_-_text122=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text123=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive124=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive125=== RUN TestPathInfoCACompatibility/new_structured_format_-_text126=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text127=== CONT TestSetClientTLSDoesNotMutateDefaultTransport128=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method129=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method130=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths131=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths132=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths133=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths134=== CONT TestFileTokenReadsAndCaches1352026/07/19 11:30:52 WARN Rate limiter enabled after throttle name=server-test rate=5136=== CONT TestStaticToken137--- PASS: TestStaticToken (0.00s)138=== CONT TestSetClientTLSErrors139=== RUN TestParsePathInfoJSON/Nix_format140=== PAUSE TestParsePathInfoJSON/Nix_format141=== RUN TestParsePathInfoJSON/Lix_format142=== PAUSE TestParsePathInfoJSON/Lix_format143=== RUN TestParsePathInfoJSON/empty_input144=== PAUSE TestParsePathInfoJSON/empty_input145=== RUN TestParsePathInfoJSON/whitespace_only146=== PAUSE TestParsePathInfoJSON/whitespace_only147=== RUN TestParsePathInfoJSON/invalid_JSON148=== PAUSE TestParsePathInfoJSON/invalid_JSON149=== CONT TestDumpPathWriterError150=== RUN TestGetStorePathHash/valid_store_path151=== PAUSE TestGetStorePathHash/valid_store_path152=== RUN TestGetStorePathHash/basename_without_hyphen_should_error153=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error154=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error155=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error156=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error157=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error158=== CONT TestEncodeNixBase32159=== RUN TestEncodeNixBase32/test_string_hash160=== PAUSE TestEncodeNixBase32/test_string_hash161=== RUN TestEncodeNixBase32/empty_input162=== PAUSE TestEncodeNixBase32/empty_input163=== CONT TestFilterOversizedClosures164=== RUN TestFilterOversizedClosures/no_limit_keeps_everything165=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything166=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped167=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped168=== RUN TestFilterOversizedClosures/all_closures_skipped169=== PAUSE TestFilterOversizedClosures/all_closures_skipped170=== CONT TestScriptTokenEmptyToken171--- PASS: TestResolveStorePath (0.00s)172=== CONT TestDumpPathSingleFile173--- PASS: TestFileTokenReadsAndCaches (0.00s)174=== CONT TestScriptTokenEmptyCommand175--- PASS: TestScriptTokenEmptyCommand (0.00s)176=== CONT TestScriptTokenScriptFails177=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)178=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)179=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon180=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon181=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI182=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI183=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512184=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512185=== CONT TestScriptTokenBadJSON186=== RUN TestSetClientTLSErrors/missing_cert_file187=== PAUSE TestSetClientTLSErrors/missing_cert_file188=== RUN TestSetClientTLSErrors/missing_key_file189=== PAUSE TestSetClientTLSErrors/missing_key_file190=== RUN TestSetClientTLSErrors/missing_ca_file191=== PAUSE TestSetClientTLSErrors/missing_ca_file192=== RUN TestSetClientTLSErrors/invalid_ca_file193=== PAUSE TestSetClientTLSErrors/invalid_ca_file194=== CONT TestCaseHackSuffix195--- PASS: TestDoServerRequestAttachesToken (0.01s)196=== CONT TestShellSplitErrors197--- PASS: TestShellSplitErrors (0.00s)198=== CONT TestSetClientTLS199--- PASS: TestScriptTokenScriptFails (0.01s)200=== CONT TestShellSplit201--- PASS: TestShellSplit (0.00s)202=== CONT TestDoWithRetry_BodyReplayedViaGetBody203--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)204=== CONT TestScriptTokenNoExpiryRerunsEveryCall2052026/07/19 11:30:52 WARN Rate limiter enabled after throttle name=server-test rate=52062026/07/19 11:30:52 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:600562072026/07/19 11:30:52 WARN Rate limiter backed off name=server-test rate=52082026/07/19 11:30:52 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:60056209--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)210=== CONT TestScriptTokenCachesUntilRefresh211=== RUN TestSetClientTLS/rejects_connection_without_client_cert212=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert213=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA214=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA215=== RUN TestSetClientTLS/preserves_debug_logging_transport216=== PAUSE TestSetClientTLS/preserves_debug_logging_transport217=== CONT TestFileTokenEmpty218--- PASS: TestFileTokenEmpty (0.00s)219=== CONT TestFileTokenMissing220--- PASS: TestFileTokenMissing (0.00s)221=== CONT TestRateLimiterFeedback/429_enables_limiter2222026/07/19 11:30:52 WARN Rate limiter enabled after throttle name=server-test rate=52232026/07/19 11:30:52 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:600592242026/07/19 11:30:52 WARN Rate limiter backed off name=server-test rate=5225=== CONT TestConvertHashToNix32/SRI_format_to_Nix32226=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter227=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter228=== CONT TestRateLimiterFeedback/503_enables_limiter2292026/07/19 11:30:53 WARN Rate limiter enabled after throttle name=server-test rate=52302026/07/19 11:30:53 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:600652312026/07/19 11:30:53 WARN Rate limiter backed off name=server-test rate=5232--- PASS: TestRateLimiterFeedback (0.00s)233 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)234 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)235 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)236 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)237=== CONT TestPartSizeForNAR/zero_stays_at_minimum238=== CONT TestConvertHashToNix32/invalid_format239=== CONT TestConvertHashToNix32/already_Nix32_format240--- PASS: TestConvertHashToNix32 (0.00s)241 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)242 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)243 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)244=== CONT TestUploadMultipart_SupersededByPeer/exists245--- PASS: TestScriptTokenEmptyToken (0.02s)246=== CONT TestPartSizeForNAR/capped_at_5_GiB247=== CONT TestPartSizeForNAR/5_TiB_S3_max_object248=== CONT TestPartSizeForNAR/1_TiB249=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts250=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum251=== CONT TestPartSizeForNAR/small_stays_at_minimum252--- PASS: TestPartSizeForNAR (0.00s)253 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)254 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)255 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)256 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)257 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)258 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)259 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)260=== CONT TestPathInfoCACompatibility/null_ca_field261=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths262=== CONT TestUploadMultipart_SupersededByPeer/missing263=== CONT TestPathInfoCACompatibility/old_string_format_-_text264=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method265=== CONT TestPathInfoCACompatibility/new_structured_format_-_text266=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive267--- PASS: TestPathInfoCACompatibility (0.00s)268 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)269 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)270 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)271 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)272 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)273=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths274--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)275 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)276 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)277=== CONT TestParsePathInfoJSON/Nix_format278=== CONT TestGetStorePathHash/valid_store_path279=== CONT TestEncodeNixBase32/test_string_hash280=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error281=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error282=== CONT TestGetStorePathHash/basename_without_hyphen_should_error283--- PASS: TestGetStorePathHash (0.00s)284 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)285 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)286 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)287 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)288=== CONT TestFilterOversizedClosures/no_limit_keeps_everything289=== CONT TestEncodeNixBase32/empty_input290=== CONT TestParsePathInfoJSON/whitespace_only291--- PASS: TestEncodeNixBase32 (0.00s)292 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)293 --- PASS: TestEncodeNixBase32/empty_input (0.00s)294=== CONT TestParsePathInfoJSON/invalid_JSON295--- PASS: TestScriptTokenBadJSON (0.02s)296=== CONT TestParsePathInfoJSON/empty_input297=== CONT TestParsePathInfoJSON/Lix_format298=== CONT TestFilterOversizedClosures/all_closures_skipped299--- PASS: TestParsePathInfoJSON (0.00s)300 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)301 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)302 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)303 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)304 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)3052026/07/19 11:30:53 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=50306=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3072026/07/19 11:30:53 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=2000308=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI309--- PASS: TestFilterOversizedClosures (0.00s)310 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)311 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)312 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)313=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)314=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512315=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon316=== CONT TestSetClientTLSErrors/invalid_ca_file317--- PASS: TestPathInfoHashCompatibility (0.00s)318 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)319 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)320 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)321 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)322=== CONT TestSetClientTLSErrors/missing_ca_file323--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)324 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)325 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)326=== CONT TestSetClientTLSErrors/missing_key_file327=== CONT TestSetClientTLSErrors/missing_cert_file328=== CONT TestSetClientTLS/rejects_connection_without_client_cert329=== CONT TestSetClientTLS/preserves_debug_logging_transport330=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA331--- PASS: TestSetClientTLSErrors (0.01s)332 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)333 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)334 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)335 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)3362026/07/19 11:30:53 http: TLS handshake error from 127.0.0.1:60072: read tcp 127.0.0.1:60058->127.0.0.1:60072: use of closed network connection337--- PASS: TestSetClientTLS (0.01s)338 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)339 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)340 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)341--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)342--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)343--- PASS: TestDumpPathWriterError (0.05s)344--- PASS: TestDumpPathSingleFile (0.06s)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-8213-2982444896/postgres2141739824/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-8213-2982444896/postgres2141739824/data -l logfile start376377/nix/var/nix/builds/nix-8213-2982444896/postgres2141739824:5432 - no response3782026-07-19 11:30:54.763 UTC [8248] LOG: starting PostgreSQL 18.4 on aarch64-apple-darwin25.3.0, compiled by clang version 21.1.8, 64-bit3792026-07-19 11:30:54.763 UTC [8248] LOG: listening on Unix socket "/nix/var/nix/builds/nix-8213-2982444896/postgres2141739824/.s.PGSQL.5432"3802026-07-19 11:30:54.765 UTC [8255] LOG: database system was shut down at 2026-07-19 11:30:54 UTC3812026-07-19 11:30:54.766 UTC [8248] LOG: database system is ready to accept connections382/nix/var/nix/builds/nix-8213-2982444896/postgres2141739824:5432 - accepting connections383<jemalloc>: option background_thread currently supports pthread only384{"timestamp":"2026-07-19T11:30:54.8875Z","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:30:55.024 UTC [8307] ERROR: relation "goose_db_version" does not exist at character 364132026-07-19 11:30:55.024 UTC [8307] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4142026/07/19 11:30:55 OK 20241026095416_initial_model.sql (2.83ms)4152026/07/19 11:30:55 OK 20251210153512_drop_unused_gin_index.sql (357.58µs)4162026/07/19 11:30:55 OK 20251218171726_add_pins.sql (738.17µs)4172026/07/19 11:30:55 OK 20260628120000_add_object_size_and_stats.sql (747.33µs)4182026/07/19 11:30:55 goose: successfully migrated database to version: 202606281200004192026/07/19 11:30:55 OK 1_commit_pending_closure.sql (754.08µs)4202026/07/19 11:30:55 OK 2_object_stats_trigger.sql (219.96µs)4212026/07/19 11:30:55 goose: up to current file version: 2422--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.06s)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:30:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5152026/07/19 11:30:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5162026/07/19 11:30:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5172026/07/19 11:30:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5182026/07/19 11:30:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5192026/07/19 11:30:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5202026/07/19 11:30:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5212026/07/19 11:30:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5222026/07/19 11:30:55 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5232026/07/19 11:30:55 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 TestRedundantMultipartUpload546=== CONT TestService_AuthMiddleware547=== CONT TestReadProxyRangeRequest548=== CONT TestReadProxyDisabled549=== CONT TestReadProxyRootRedirectsToIndexHTML550=== CONT TestReadProxyConditionalGet551=== CONT TestReadProxyHead552=== CONT TestReadProxyInvalidPath553=== CONT TestReadProxy404554=== CONT TestReadProxyNarStreaming5552026-07-19 11:30:55.617 UTC [8335] ERROR: relation "goose_db_version" does not exist at character 365562026-07-19 11:30:55.617 UTC [8335] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5572026-07-19 11:30:55.618 UTC [8334] ERROR: relation "goose_db_version" does not exist at character 365582026-07-19 11:30:55.618 UTC [8334] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5592026-07-19 11:30:55.618 UTC [8336] ERROR: relation "goose_db_version" does not exist at character 365602026-07-19 11:30:55.618 UTC [8336] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5612026-07-19 11:30:55.619 UTC [8338] ERROR: relation "goose_db_version" does not exist at character 365622026-07-19 11:30:55.619 UTC [8338] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5632026-07-19 11:30:55.619 UTC [8339] ERROR: relation "goose_db_version" does not exist at character 365642026-07-19 11:30:55.619 UTC [8339] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5652026-07-19 11:30:55.621 UTC [8341] ERROR: relation "goose_db_version" does not exist at character 365662026-07-19 11:30:55.621 UTC [8341] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5672026-07-19 11:30:55.621 UTC [8337] ERROR: relation "goose_db_version" does not exist at character 365682026-07-19 11:30:55.621 UTC [8337] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5692026-07-19 11:30:55.621 UTC [8343] ERROR: relation "goose_db_version" does not exist at character 365702026-07-19 11:30:55.621 UTC [8343] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5712026-07-19 11:30:55.623 UTC [8342] ERROR: relation "goose_db_version" does not exist at character 365722026-07-19 11:30:55.623 UTC [8342] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5732026-07-19 11:30:55.623 UTC [8340] ERROR: relation "goose_db_version" does not exist at character 365742026-07-19 11:30:55.623 UTC [8340] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5752026/07/19 11:30:55 OK 20241026095416_initial_model.sql (5.36ms)5762026/07/19 11:30:55 OK 20251210153512_drop_unused_gin_index.sql (1.02ms)5772026/07/19 11:30:55 OK 20241026095416_initial_model.sql (5.54ms)5782026/07/19 11:30:55 OK 20251210153512_drop_unused_gin_index.sql (1.07ms)5792026/07/19 11:30:55 OK 20251218171726_add_pins.sql (2.93ms)5802026/07/19 11:30:55 OK 20241026095416_initial_model.sql (7.37ms)5812026/07/19 11:30:55 OK 20241026095416_initial_model.sql (9.3ms)5822026/07/19 11:30:55 OK 20241026095416_initial_model.sql (6.31ms)5832026/07/19 11:30:55 OK 20241026095416_initial_model.sql (7.66ms)5842026/07/19 11:30:55 OK 20251210153512_drop_unused_gin_index.sql (682.58µs)5852026/07/19 11:30:55 OK 20260628120000_add_object_size_and_stats.sql (1.73ms)5862026/07/19 11:30:55 goose: successfully migrated database to version: 202606281200005872026/07/19 11:30:55 OK 20251210153512_drop_unused_gin_index.sql (971.88µs)5882026/07/19 11:30:55 OK 20251218171726_add_pins.sql (2.39ms)5892026/07/19 11:30:55 OK 20251210153512_drop_unused_gin_index.sql (557.75µs)5902026/07/19 11:30:55 OK 20251210153512_drop_unused_gin_index.sql (598.13µs)5912026/07/19 11:30:55 OK 20241026095416_initial_model.sql (8.27ms)5922026/07/19 11:30:55 OK 20241026095416_initial_model.sql (8.53ms)5932026/07/19 11:30:55 OK 1_commit_pending_closure.sql (1.23ms)5942026/07/19 11:30:55 OK 20251210153512_drop_unused_gin_index.sql (673.96µs)5952026/07/19 11:30:55 OK 20251210153512_drop_unused_gin_index.sql (904.79µs)5962026/07/19 11:30:55 OK 20251218171726_add_pins.sql (1.37ms)5972026/07/19 11:30:55 OK 20260628120000_add_object_size_and_stats.sql (1.5ms)5982026/07/19 11:30:55 goose: successfully migrated database to version: 202606281200005992026/07/19 11:30:55 OK 2_object_stats_trigger.sql (555.13µs)6002026/07/19 11:30:55 goose: up to current file version: 26012026/07/19 11:30:55 OK 20251218171726_add_pins.sql (1.93ms)6022026/07/19 11:30:55 OK 20251218171726_add_pins.sql (1.8ms)6032026/07/19 11:30:55 OK 20251218171726_add_pins.sql (1.81ms)6042026/07/19 11:30:55 OK 20241026095416_initial_model.sql (7.71ms)6052026/07/19 11:30:55 OK 20241026095416_initial_model.sql (7.96ms)6062026/07/19 11:30:55 OK 1_commit_pending_closure.sql (1.14ms)6072026/07/19 11:30:55 OK 20251210153512_drop_unused_gin_index.sql (671.17µs)6082026/07/19 11:30:55 OK 20260628120000_add_object_size_and_stats.sql (1.08ms)6092026/07/19 11:30:55 goose: successfully migrated database to version: 202606281200006102026/07/19 11:30:55 OK 20251218171726_add_pins.sql (1.65ms)6112026/07/19 11:30:55 OK 20251210153512_drop_unused_gin_index.sql (539.17µs)6122026/07/19 11:30:55 OK 20251218171726_add_pins.sql (1.76ms)6132026/07/19 11:30:55 OK 2_object_stats_trigger.sql (274.17µs)6142026/07/19 11:30:55 goose: up to current file version: 26152026/07/19 11:30:55 OK 20260628120000_add_object_size_and_stats.sql (2.44ms)6162026/07/19 11:30:55 goose: successfully migrated database to version: 202606281200006172026/07/19 11:30:55 OK 20260628120000_add_object_size_and_stats.sql (1.71ms)6182026/07/19 11:30:55 goose: successfully migrated database to version: 202606281200006192026/07/19 11:30:55 OK 20260628120000_add_object_size_and_stats.sql (1.85ms)6202026/07/19 11:30:55 goose: successfully migrated database to version: 202606281200006212026/07/19 11:30:55 OK 20260628120000_add_object_size_and_stats.sql (1.48ms)6222026/07/19 11:30:55 goose: successfully migrated database to version: 202606281200006232026/07/19 11:30:55 OK 20251218171726_add_pins.sql (1.69ms)6242026/07/19 11:30:55 OK 20260628120000_add_object_size_and_stats.sql (1.53ms)6252026/07/19 11:30:55 goose: successfully migrated database to version: 202606281200006262026/07/19 11:30:55 OK 20251218171726_add_pins.sql (1.56ms)6272026/07/19 11:30:55 OK 1_commit_pending_closure.sql (1.81ms)6282026/07/19 11:30:55 OK 1_commit_pending_closure.sql (1.03ms)6292026/07/19 11:30:55 OK 1_commit_pending_closure.sql (1.24ms)6302026/07/19 11:30:55 OK 2_object_stats_trigger.sql (322.92µs)6312026/07/19 11:30:55 goose: up to current file version: 26322026/07/19 11:30:55 OK 2_object_stats_trigger.sql (532.54µs)6332026/07/19 11:30:55 goose: up to current file version: 26342026/07/19 11:30:55 OK 1_commit_pending_closure.sql (1.87ms)6352026/07/19 11:30:55 OK 1_commit_pending_closure.sql (1.25ms)6362026/07/19 11:30:55 OK 2_object_stats_trigger.sql (725.54µs)6372026/07/19 11:30:55 goose: up to current file version: 26382026/07/19 11:30:55 OK 20260628120000_add_object_size_and_stats.sql (1.22ms)6392026/07/19 11:30:55 goose: successfully migrated database to version: 202606281200006402026/07/19 11:30:55 OK 20260628120000_add_object_size_and_stats.sql (1.25ms)6412026/07/19 11:30:55 goose: successfully migrated database to version: 202606281200006422026/07/19 11:30:55 OK 1_commit_pending_closure.sql (1.51ms)643{"timestamp":"2026-07-19T11:30:55.638646Z","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(3)"}6442026/07/19 11:30:55 OK 2_object_stats_trigger.sql (586.25µs)6452026/07/19 11:30:55 goose: up to current file version: 26462026/07/19 11:30:55 OK 2_object_stats_trigger.sql (618.96µs)6472026/07/19 11:30:55 goose: up to current file version: 26482026/07/19 11:30:55 OK 2_object_stats_trigger.sql (645.63µs)6492026/07/19 11:30:55 goose: up to current file version: 26502026/07/19 11:30:55 OK 1_commit_pending_closure.sql (1.21ms)651--- PASS: TestReadProxyDisabled (0.38s)652=== CONT TestGCTaskStore_CompletedAllowsNewTask653--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)654=== CONT TestGCTaskStore_GetReturnsLatest655--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)656=== CONT TestGCTaskStore_GetEmpty657--- PASS: TestGCTaskStore_GetEmpty (0.00s)658=== CONT TestGCTaskStore_ConflictDifferentParams659--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)660=== CONT TestGCTaskStore_DeduplicateSameParams661--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)662=== CONT TestGCTaskStore_StartNew663--- PASS: TestGCTaskStore_StartNew (0.00s)664=== CONT TestGCMetrics6652026/07/19 11:30:55 OK 1_commit_pending_closure.sql (1.55ms)6662026/07/19 11:30:55 OK 2_object_stats_trigger.sql (315.08µs)6672026/07/19 11:30:55 goose: up to current file version: 26682026/07/19 11:30:55 OK 2_object_stats_trigger.sql (1.04ms)6692026/07/19 11:30:55 goose: up to current file version: 26702026/07/19 11:30:55 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"671--- PASS: TestService_AuthMiddleware (0.38s)672=== CONT TestGCTaskStore_PhaseUpdates673--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)674=== CONT TestGCBugBareHashReferences675--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.38s)676=== CONT TestPinProtectsFromGC6772026/07/19 11:30:55 INFO Received uploads request method=POST path=/api/pending_closures678--- PASS: TestReadProxyInvalidPath (0.38s)679=== CONT TestReadProxyNarinfoAlreadyDecompressed680--- PASS: TestReadProxyNarStreaming (0.38s)681=== CONT TestClientWithDependencies682--- PASS: TestReadProxy404 (0.38s)683=== CONT TestReadProxyNarinfo684--- PASS: TestReadProxyConditionalGet (0.38s)685=== CONT TestClientMultipleUploads6862026/07/19 11:30:55 INFO Received uploads request method=POST path=/api/pending_closures687--- PASS: TestReadProxyHead (0.39s)688=== CONT TestIsValidCachePath689=== RUN TestIsValidCachePath/narinfo690=== PAUSE TestIsValidCachePath/narinfo691=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars692=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars693=== RUN TestIsValidCachePath/nar_zst694=== PAUSE TestIsValidCachePath/nar_zst695=== RUN TestIsValidCachePath/nar_xz696=== PAUSE TestIsValidCachePath/nar_xz697=== RUN TestIsValidCachePath/nar_bz2698=== PAUSE TestIsValidCachePath/nar_bz2699=== RUN TestIsValidCachePath/nar_uncompressed700=== PAUSE TestIsValidCachePath/nar_uncompressed701=== RUN TestIsValidCachePath/ls702=== PAUSE TestIsValidCachePath/ls703=== RUN TestIsValidCachePath/log704=== PAUSE TestIsValidCachePath/log705=== RUN TestIsValidCachePath/realisation706=== PAUSE TestIsValidCachePath/realisation707=== RUN TestIsValidCachePath/nix-cache-info708=== PAUSE TestIsValidCachePath/nix-cache-info709=== RUN TestIsValidCachePath/index.html710=== PAUSE TestIsValidCachePath/index.html711=== RUN TestIsValidCachePath/traversal_parent712=== PAUSE TestIsValidCachePath/traversal_parent713=== RUN TestIsValidCachePath/traversal_in_middle714=== PAUSE TestIsValidCachePath/traversal_in_middle715=== RUN TestIsValidCachePath/invalid_char_e716=== PAUSE TestIsValidCachePath/invalid_char_e717=== RUN TestIsValidCachePath/invalid_char_u718=== PAUSE TestIsValidCachePath/invalid_char_u719=== RUN TestIsValidCachePath/random_path720=== PAUSE TestIsValidCachePath/random_path721=== RUN TestIsValidCachePath/empty722=== PAUSE TestIsValidCachePath/empty723=== RUN TestIsValidCachePath/leading_slash724=== PAUSE TestIsValidCachePath/leading_slash725=== RUN TestIsValidCachePath/wrong_extension726=== PAUSE TestIsValidCachePath/wrong_extension727=== RUN TestIsValidCachePath/short_hash728=== PAUSE TestIsValidCachePath/short_hash729=== CONT TestParseSingleRange730=== RUN TestParseSingleRange/none731=== PAUSE TestParseSingleRange/none732=== RUN TestParseSingleRange/unknown_unit733=== PAUSE TestParseSingleRange/unknown_unit734=== RUN TestParseSingleRange/multi-range_ignored735=== PAUSE TestParseSingleRange/multi-range_ignored736=== RUN TestParseSingleRange/malformed_no_dash737=== PAUSE TestParseSingleRange/malformed_no_dash738=== RUN TestParseSingleRange/malformed_both_empty739=== PAUSE TestParseSingleRange/malformed_both_empty740=== RUN TestParseSingleRange/malformed_end_before_start741=== PAUSE TestParseSingleRange/malformed_end_before_start742=== RUN TestParseSingleRange/closed743=== PAUSE TestParseSingleRange/closed744=== RUN TestParseSingleRange/open-ended745=== PAUSE TestParseSingleRange/open-ended746=== RUN TestParseSingleRange/end_clamped_to_size747=== PAUSE TestParseSingleRange/end_clamped_to_size748=== RUN TestParseSingleRange/suffix749=== PAUSE TestParseSingleRange/suffix750=== RUN TestParseSingleRange/suffix_exceeds_size751=== PAUSE TestParseSingleRange/suffix_exceeds_size752=== RUN TestParseSingleRange/single_byte753=== PAUSE TestParseSingleRange/single_byte754=== RUN TestParseSingleRange/start_past_EOF755=== PAUSE TestParseSingleRange/start_past_EOF756=== RUN TestParseSingleRange/start_far_past_EOF757=== PAUSE TestParseSingleRange/start_far_past_EOF758=== CONT TestResurrectedObjectNotDeleted759--- PASS: TestReadProxyRangeRequest (0.39s)760=== CONT TestOrphanedObjectsGCStressTest7612026/07/19 11:30:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7622026/07/19 11:30:55 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ODMyYzA2OWEtNGQ2Mi00ZjNiLWFhNmItMTk3NTMzNTY0OWFhLmNhNmNkMTcyLTQ2ODUtNDYyYy05M2NlLTc3ZWQxZTQ4NzZlYngxNzg0NDYwNjU1NjQ4MTIwMDAw parts=12763--- PASS: TestRedundantMultipartUpload (0.53s)764=== CONT TestOrphanedObjectsGC7652026-07-19 11:30:56.039 UTC [8385] ERROR: relation "goose_db_version" does not exist at character 367662026-07-19 11:30:56.039 UTC [8385] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7672026-07-19 11:30:56.039 UTC [8386] ERROR: relation "goose_db_version" does not exist at character 367682026-07-19 11:30:56.039 UTC [8386] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7692026-07-19 11:30:56.040 UTC [8387] ERROR: relation "goose_db_version" does not exist at character 367702026-07-19 11:30:56.040 UTC [8387] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7712026-07-19 11:30:56.041 UTC [8388] ERROR: relation "goose_db_version" does not exist at character 367722026-07-19 11:30:56.041 UTC [8388] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7732026-07-19 11:30:56.042 UTC [8389] ERROR: relation "goose_db_version" does not exist at character 367742026-07-19 11:30:56.042 UTC [8389] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7752026-07-19 11:30:56.043 UTC [8390] ERROR: relation "goose_db_version" does not exist at character 367762026-07-19 11:30:56.043 UTC [8390] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7772026/07/19 11:30:56 OK 20241026095416_initial_model.sql (3.34ms)7782026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (345.63µs)7792026/07/19 11:30:56 OK 20251218171726_add_pins.sql (690.08µs)7802026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (1.39ms)7812026/07/19 11:30:56 goose: successfully migrated database to version: 202606281200007822026/07/19 11:30:56 OK 1_commit_pending_closure.sql (926.17µs)7832026/07/19 11:30:56 OK 2_object_stats_trigger.sql (216µs)7842026/07/19 11:30:56 goose: up to current file version: 27852026/07/19 11:30:56 INFO Created nix-cache-info in bucket bucket=bucket127862026/07/19 11:30:56 OK 20241026095416_initial_model.sql (3.35ms)7872026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (340.63µs)7882026/07/19 11:30:56 OK 20251218171726_add_pins.sql (674.13µs)7892026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (1.47ms)7902026/07/19 11:30:56 goose: successfully migrated database to version: 202606281200007912026/07/19 11:30:56 OK 1_commit_pending_closure.sql (793.79µs)7922026/07/19 11:30:56 OK 2_object_stats_trigger.sql (212.04µs)7932026/07/19 11:30:56 goose: up to current file version: 27942026/07/19 11:30:56 INFO Created nix-cache-info in bucket bucket=bucket137952026/07/19 11:30:56 OK 20241026095416_initial_model.sql (36.06ms)7962026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (740µs)7972026/07/19 11:30:56 OK 20241026095416_initial_model.sql (38.15ms)7982026/07/19 11:30:56 OK 20251218171726_add_pins.sql (872.63µs)7992026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (651.83µs)8002026-07-19 11:30:56.105 UTC [8394] ERROR: relation "goose_db_version" does not exist at character 368012026-07-19 11:30:56.105 UTC [8394] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8022026/07/19 11:30:56 OK 20241026095416_initial_model.sql (15.36ms)8032026/07/19 11:30:56 OK 20251218171726_add_pins.sql (9.98ms)8042026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (12.13ms)8052026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (23.47ms)8062026/07/19 11:30:56 goose: successfully migrated database to version: 202606281200008072026/07/19 11:30:56 OK 1_commit_pending_closure.sql (987.71µs)8082026/07/19 11:30:56 OK 2_object_stats_trigger.sql (245.79µs)8092026/07/19 11:30:56 goose: up to current file version: 28102026/07/19 11:30:56 OK 20251218171726_add_pins.sql (14.13ms)8112026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (29.42ms)8122026/07/19 11:30:56 goose: successfully migrated database to version: 202606281200008132026/07/19 11:30:56 OK 1_commit_pending_closure.sql (1.21ms)8142026/07/19 11:30:56 INFO Aborted multipart uploads count=08152026/07/19 11:30:56 OK 20241026095416_initial_model.sql (44.45ms)8162026/07/19 11:30:56 OK 2_object_stats_trigger.sql (397.21µs)8172026/07/19 11:30:56 goose: up to current file version: 28182026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (1.51ms)8192026/07/19 11:30:56 OK 20251218171726_add_pins.sql (8.74ms)8202026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (15.26ms)8212026/07/19 11:30:56 goose: successfully migrated database to version: 202606281200008222026/07/19 11:30:56 WARN Force mode enabled - objects will be deleted immediately without grace period8232026/07/19 11:30:56 OK 1_commit_pending_closure.sql (2.6ms)8242026/07/19 11:30:56 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=08252026/07/19 11:30:56 OK 2_object_stats_trigger.sql (2.54ms)8262026/07/19 11:30:56 goose: up to current file version: 28272026/07/19 11:30:56 INFO Vacuumed table table=pending_closures8282026/07/19 11:30:56 INFO Vacuumed table table=pending_objects8292026/07/19 11:30:56 INFO Vacuumed table table=multipart_uploads8302026/07/19 11:30:56 INFO Vacuumed table table=closures8312026/07/19 11:30:56 INFO Vacuumed table table=objects8322026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (15.63ms)8332026/07/19 11:30:56 goose: successfully migrated database to version: 20260628120000834--- PASS: TestGCMetrics (0.52s)835=== CONT TestObjectStatsTrigger8362026/07/19 11:30:56 OK 1_commit_pending_closure.sql (2.07ms)8372026/07/19 11:30:56 OK 2_object_stats_trigger.sql (570.71µs)8382026/07/19 11:30:56 goose: up to current file version: 2839--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.52s)840=== CONT TestMultipartCleanup8412026/07/19 11:30:56 OK 20241026095416_initial_model.sql (33.8ms)8422026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (887.67µs)8432026/07/19 11:30:56 OK 20251218171726_add_pins.sql (1.8ms)844--- PASS: TestReadProxyNarinfo (0.53s)845=== CONT TestServerTLSConfig846=== RUN TestServerTLSConfig/no_client_CA847=== PAUSE TestServerTLSConfig/no_client_CA848=== RUN TestServerTLSConfig/missing_CA_file849=== PAUSE TestServerTLSConfig/missing_CA_file850=== RUN TestServerTLSConfig/not_a_PEM_file851=== PAUSE TestServerTLSConfig/not_a_PEM_file852=== CONT TestService_NativeMTLS853=== NAME TestPinProtectsFromGC854 client_integration_test.go:646: Pinned store path: /nix/var/nix/builds/nix-8213-2982444896/TestPinProtectsFromGC569927186/001/store/rqj170s523blpw7j1f6qh8l8ipasvwg6-pinned-file.txt855 client_integration_test.go:647: Unpinned store path: /nix/var/nix/builds/nix-8213-2982444896/TestPinProtectsFromGC569927186/001/store/a7gsmpjb8mb9sjphs83as14qz9rl9qm1-unpinned-file.txt8562026-07-19 11:30:56.176 UTC [8402] ERROR: relation "goose_db_version" does not exist at character 368572026-07-19 11:30:56.176 UTC [8402] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8582026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (3.94ms)8592026/07/19 11:30:56 goose: successfully migrated database to version: 202606281200008602026/07/19 11:30:56 OK 1_commit_pending_closure.sql (1.7ms)8612026/07/19 11:30:56 OK 2_object_stats_trigger.sql (225.33µs)8622026/07/19 11:30:56 goose: up to current file version: 28632026-07-19 11:30:56.193 UTC [8409] ERROR: relation "goose_db_version" does not exist at character 368642026-07-19 11:30:56.193 UTC [8409] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8652026/07/19 11:30:56 OK 20241026095416_initial_model.sql (19.67ms)8662026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (686.42µs)8672026/07/19 11:30:56 OK 20251218171726_add_pins.sql (1.07ms)8682026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (2.91ms)8692026/07/19 11:30:56 goose: successfully migrated database to version: 202606281200008702026/07/19 11:30:56 OK 1_commit_pending_closure.sql (869.58µs)8712026/07/19 11:30:56 OK 20241026095416_initial_model.sql (5.37ms)8722026/07/19 11:30:56 OK 2_object_stats_trigger.sql (215µs)8732026/07/19 11:30:56 goose: up to current file version: 28742026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (398.33µs)8752026/07/19 11:30:56 OK 20251218171726_add_pins.sql (731.67µs)8762026/07/19 11:30:56 INFO Created nix-cache-info in bucket bucket=bucket198772026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (1.74ms)8782026/07/19 11:30:56 goose: successfully migrated database to version: 202606281200008792026/07/19 11:30:56 OK 1_commit_pending_closure.sql (1.77ms)8802026/07/19 11:30:56 OK 2_object_stats_trigger.sql (798.92µs)8812026/07/19 11:30:56 goose: up to current file version: 2882--- PASS: TestResurrectedObjectNotDeleted (0.56s)883=== CONT TestMetricsInventory8842026/07/19 11:30:56 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"885=== NAME TestClientMultipleUploads886 client_integration_test.go:338: Created store path 0: /nix/var/nix/builds/nix-8213-2982444896/TestClientMultipleUploads975110355/001/store/ppa36gvx3mf62vnr6d4ps5zfv4gx6pyz-test-file-0.txt8872026/07/19 11:30:56 INFO Received uploads request method=POST path=/api/pending_closures8882026/07/19 11:30:56 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8892026/07/19 11:30:56 INFO Uploading rqj170s523blpw7j1f6qh8l8ipasvwg6-pinned-file.txt (128B)8902026/07/19 11:30:56 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"8912026/07/19 11:30:56 WARN Failed to register uploaded object key=rqj170s523blpw7j1f6qh8l8ipasvwg6.ls error="server returned 404: 404 page not found\n"8922026/07/19 11:30:56 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign8932026/07/19 11:30:56 INFO Signed narinfos id=1 count=18942026/07/19 11:30:56 INFO Uploading 1 narinfos8952026/07/19 11:30:56 WARN Failed to register uploaded object key=rqj170s523blpw7j1f6qh8l8ipasvwg6.narinfo error="server returned 404: 404 page not found\n"8962026/07/19 11:30:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8972026/07/19 11:30:56 INFO Completed upload id=18982026/07/19 11:30:56 INFO Upload complete. (84ms)899 client_integration_test.go:338: Created store path 1: /nix/var/nix/builds/nix-8213-2982444896/TestClientMultipleUploads975110355/001/store/jrdrv08mknc9lhynffwl2mj9ymvgrzi7-test-file-1.txt900=== NAME TestClientWithDependencies901 client_integration_test.go:593: Built derivation: /nix/var/nix/builds/nix-8213-2982444896/TestClientWithDependencies3396011555/001/store/nfwccwkbh083vgxm4bj620l0i1g1fnpp-test-script902=== NAME TestClientMultipleUploads903 client_integration_test.go:338: Created store path 2: /nix/var/nix/builds/nix-8213-2982444896/TestClientMultipleUploads975110355/001/store/2vhaabch5czw0dc62qgqsxqqfnvgdzjm-test-file-2.txt9042026-07-19 11:30:56.347 UTC [8428] ERROR: relation "goose_db_version" does not exist at character 369052026-07-19 11:30:56.347 UTC [8428] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC906=== NAME TestClientWithDependencies907 client_integration_test.go:595: Found 1 dependencies (including self)9082026/07/19 11:30:56 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9092026/07/19 11:30:56 OK 20241026095416_initial_model.sql (11.93ms)910--- PASS: TestGCBugBareHashReferences (0.74s)911=== CONT TestClientIntegration9122026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (1.45ms)9132026/07/19 11:30:56 OK 20251218171726_add_pins.sql (1.86ms)9142026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (3.27ms)9152026/07/19 11:30:56 goose: successfully migrated database to version: 202606281200009162026/07/19 11:30:56 OK 1_commit_pending_closure.sql (1.37ms)9172026/07/19 11:30:56 OK 2_object_stats_trigger.sql (318.79µs)9182026/07/19 11:30:56 goose: up to current file version: 29192026/07/19 11:30:56 INFO Received uploads request method=POST path=/api/pending_closures9202026/07/19 11:30:56 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9212026/07/19 11:30:56 INFO Uploading a7gsmpjb8mb9sjphs83as14qz9rl9qm1-unpinned-file.txt (128B)9222026/07/19 11:30:56 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"9232026/07/19 11:30:56 WARN Failed to register uploaded object key=a7gsmpjb8mb9sjphs83as14qz9rl9qm1.ls error="server returned 404: 404 page not found\n"9242026/07/19 11:30:56 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign9252026/07/19 11:30:56 INFO Signed narinfos id=2 count=19262026/07/19 11:30:56 INFO Uploading 1 narinfos9272026/07/19 11:30:56 WARN Failed to register uploaded object key=a7gsmpjb8mb9sjphs83as14qz9rl9qm1.narinfo error="server returned 404: 404 page not found\n"9282026/07/19 11:30:56 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete9292026/07/19 11:30:56 INFO Completed upload id=29302026/07/19 11:30:56 INFO Upload complete. (83ms)9312026-07-19 11:30:56.413 UTC [8443] ERROR: relation "goose_db_version" does not exist at character 369322026-07-19 11:30:56.413 UTC [8443] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9332026-07-19 11:30:56.413 UTC [8442] ERROR: relation "goose_db_version" does not exist at character 369342026-07-19 11:30:56.413 UTC [8442] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9352026/07/19 11:30:56 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9362026/07/19 11:30:56 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9372026/07/19 11:30:56 INFO Received uploads request method=POST path=/api/pending_closures9382026/07/19 11:30:56 OK 20241026095416_initial_model.sql (6.59ms)9392026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (587.88µs)9402026/07/19 11:30:56 OK 20251218171726_add_pins.sql (966.46µs)9412026/07/19 11:30:56 OK 20241026095416_initial_model.sql (10.84ms)9422026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (396.71µs)9432026/07/19 11:30:56 OK 20251218171726_add_pins.sql (896.42µs)9442026-07-19 11:30:56.441 UTC [8448] ERROR: relation "goose_db_version" does not exist at character 369452026-07-19 11:30:56.441 UTC [8448] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9462026/07/19 11:30:56 INFO Received create pin request method=POST path=/api/pins/myapp9472026/07/19 11:30:56 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9482026/07/19 11:30:56 INFO Uploading nfwccwkbh083vgxm4bj620l0i1g1fnpp-test-script (136B)9492026/07/19 11:30:56 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"9502026/07/19 11:30:56 WARN Failed to register uploaded object key=log/z5rmfplsahjhg116axypx01nxmgml0lj-test-script.drv error="server returned 404: 404 page not found\n"9512026/07/19 11:30:56 WARN Failed to register uploaded object key=nfwccwkbh083vgxm4bj620l0i1g1fnpp.ls error="server returned 404: 404 page not found\n"9522026/07/19 11:30:56 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9532026/07/19 11:30:56 INFO Signed narinfos id=1 count=19542026/07/19 11:30:56 INFO Uploading 1 narinfos9552026/07/19 11:30:56 WARN Failed to register uploaded object key=nfwccwkbh083vgxm4bj620l0i1g1fnpp.narinfo error="server returned 404: 404 page not found\n"9562026/07/19 11:30:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9572026/07/19 11:30:56 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-8213-2982444896/TestPinProtectsFromGC569927186/001/store/rqj170s523blpw7j1f6qh8l8ipasvwg6-pinned-file.txt narinfo_key=rqj170s523blpw7j1f6qh8l8ipasvwg6.narinfo9582026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (16.54ms)9592026/07/19 11:30:56 goose: successfully migrated database to version: 202606281200009602026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (12.2ms)9612026/07/19 11:30:56 goose: successfully migrated database to version: 202606281200009622026/07/19 11:30:56 INFO Starting cleanup of old closures method=DELETE path=/api/closures9632026/07/19 11:30:56 INFO Garbage collection started9642026/07/19 11:30:56 OK 1_commit_pending_closure.sql (1.12ms)9652026/07/19 11:30:56 OK 1_commit_pending_closure.sql (1.04ms)9662026/07/19 11:30:56 INFO Completed upload id=19672026/07/19 11:30:56 OK 2_object_stats_trigger.sql (278.67µs)9682026/07/19 11:30:56 goose: up to current file version: 29692026/07/19 11:30:56 INFO Upload complete. (61ms)9702026/07/19 11:30:56 OK 2_object_stats_trigger.sql (238µs)9712026/07/19 11:30:56 goose: up to current file version: 29722026/07/19 11:30:56 WARN mTLS auth: subject not in bound subjects subject="CN=reader"9732026/07/19 11:30:56 WARN mTLS auth: subject not in bound subjects subject="CN=writer"974--- PASS: TestService_NativeMTLS (0.28s)975=== CONT TestNARDeduplicationMetadataUploadBug976=== NAME TestClientWithDependencies977 client_integration_test.go:597: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-8213-2982444896/TestClientWithDependencies3396011555/001/store) requires matching store prefix9782026/07/19 11:30:56 INFO Aborted multipart uploads count=09792026/07/19 11:30:56 INFO Received uploads request method=POST path=/api/pending_closures9802026/07/19 11:30:56 WARN Force mode enabled - objects will be deleted immediately without grace period981--- PASS: TestClientWithDependencies (0.82s)982=== CONT TestClientErrorHandling983=== RUN TestClientErrorHandling/InvalidStorePath984=== PAUSE TestClientErrorHandling/InvalidStorePath985=== RUN TestClientErrorHandling/InvalidAuthToken986=== PAUSE TestClientErrorHandling/InvalidAuthToken987=== RUN TestClientErrorHandling/ServerNotAvailable988=== PAUSE TestClientErrorHandling/ServerNotAvailable989=== CONT TestCreatePendingClosureRejectsOversizedNAR9902026/07/19 11:30:56 INFO Received uploads request method=POST path=/api/pending_closures991--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)992=== CONT TestClientCADerivations9932026/07/19 11:30:56 INFO Received uploads request method=POST path=/api/pending_closures9942026/07/19 11:30:56 OK 20241026095416_initial_model.sql (7.74ms)9952026/07/19 11:30:56 INFO Received uploads request method=POST path=/api/pending_closures9962026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (570.96µs)9972026/07/19 11:30:56 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)9982026/07/19 11:30:56 INFO Uploading ppa36gvx3mf62vnr6d4ps5zfv4gx6pyz-test-file-0.txt (160B)9992026/07/19 11:30:56 INFO Uploading jrdrv08mknc9lhynffwl2mj9ymvgrzi7-test-file-1.txt (160B)10002026/07/19 11:30:56 INFO Uploading 2vhaabch5czw0dc62qgqsxqqfnvgdzjm-test-file-2.txt (160B)10012026/07/19 11:30:56 OK 20251218171726_add_pins.sql (1.33ms)1002--- PASS: TestObjectStatsTrigger (0.30s)1003=== CONT TestCacheConfigHandlerMaxNarSize1004--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1005=== CONT TestCacheStatsHandler10062026/07/19 11:30:56 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"10072026/07/19 11:30:56 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"10082026/07/19 11:30:56 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"10092026/07/19 11:30:56 WARN Failed to register uploaded object key=ppa36gvx3mf62vnr6d4ps5zfv4gx6pyz.ls error="server returned 404: 404 page not found\n"10102026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (4.13ms)10112026/07/19 11:30:56 goose: successfully migrated database to version: 2026062812000010122026/07/19 11:30:56 WARN Failed to register uploaded object key=jrdrv08mknc9lhynffwl2mj9ymvgrzi7.ls error="server returned 404: 404 page not found\n"10132026/07/19 11:30:56 WARN Failed to register uploaded object key=2vhaabch5czw0dc62qgqsxqqfnvgdzjm.ls error="server returned 404: 404 page not found\n"10142026/07/19 11:30:56 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10152026/07/19 11:30:56 INFO Signed narinfos id=1 count=110162026/07/19 11:30:56 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign10172026/07/19 11:30:56 INFO Signed narinfos id=2 count=110182026/07/19 11:30:56 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign10192026/07/19 11:30:56 OK 1_commit_pending_closure.sql (1.34ms)10202026/07/19 11:30:56 INFO Signed narinfos id=3 count=110212026/07/19 11:30:56 INFO Uploading 3 narinfos10222026/07/19 11:30:56 OK 2_object_stats_trigger.sql (653.38µs)10232026/07/19 11:30:56 goose: up to current file version: 210242026/07/19 11:30:56 WARN Failed to register uploaded object key=2vhaabch5czw0dc62qgqsxqqfnvgdzjm.narinfo error="server returned 404: 404 page not found\n"10252026/07/19 11:30:56 WARN Failed to register uploaded object key=jrdrv08mknc9lhynffwl2mj9ymvgrzi7.narinfo error="server returned 404: 404 page not found\n"10262026/07/19 11:30:56 WARN Failed to register uploaded object key=ppa36gvx3mf62vnr6d4ps5zfv4gx6pyz.narinfo error="server returned 404: 404 page not found\n"10272026/07/19 11:30:56 INFO Received uploads request method=POST path=/api/pending_closures10282026/07/19 11:30:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10292026/07/19 11:30:56 INFO Completed upload id=110302026/07/19 11:30:56 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10312026/07/19 11:30:56 INFO Completed upload id=210322026/07/19 11:30:56 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete10332026/07/19 11:30:56 INFO Completed upload id=310342026/07/19 11:30:56 INFO Upload complete. (101ms)1035=== NAME TestClientMultipleUploads1036 client_integration_test.go:349: Uploaded 3 paths in 132.243875ms1037--- PASS: TestClientMultipleUploads (0.84s)1038=== CONT TestGenerateLandingPage1039--- PASS: TestGenerateLandingPage (0.00s)1040=== CONT TestCacheConfigHandler1041=== RUN TestCacheConfigHandler/full_config,_no_issuer1042=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1043=== RUN TestCacheConfigHandler/no_cache_url_configured1044=== PAUSE TestCacheConfigHandler/no_cache_url_configured1045=== RUN TestCacheConfigHandler/no_signing_keys1046=== PAUSE TestCacheConfigHandler/no_signing_keys1047=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1048=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1049=== CONT TestService_healthCheckHandler10502026-07-19 11:30:56.500 UTC [8459] ERROR: relation "goose_db_version" does not exist at character 3610512026-07-19 11:30:56.500 UTC [8459] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10522026/07/19 11:30:56 OK 20241026095416_initial_model.sql (4.68ms)10532026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (739.75µs)10542026/07/19 11:30:56 OK 20251218171726_add_pins.sql (2.3ms)10552026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (2.11ms)10562026/07/19 11:30:56 goose: successfully migrated database to version: 2026062812000010572026/07/19 11:30:56 OK 1_commit_pending_closure.sql (1.08ms)10582026/07/19 11:30:56 OK 2_object_stats_trigger.sql (234.08µs)10592026/07/19 11:30:56 goose: up to current file version: 21060--- PASS: TestMetricsInventory (0.32s)1061=== CONT TestGracefulShutdownDrainsInflight10622026/07/19 11:30:56 INFO Starting HTTP server address=127.0.0.1:6018510632026/07/19 11:30:56 INFO Shutdown signal received, draining in-flight requests timeout=10s10642026/07/19 11:30:56 INFO Received cleanup request method=DELETE path=/api/pending_closures10652026/07/19 11:30:56 INFO Aborted multipart uploads count=11066--- PASS: TestMultipartCleanup (0.42s)1067=== CONT TestGCTaskStore_Fail1068--- PASS: TestGCTaskStore_Fail (0.00s)1069=== CONT TestIsValidUploadKey1070=== RUN TestIsValidUploadKey/narinfo1071=== PAUSE TestIsValidUploadKey/narinfo1072=== RUN TestIsValidUploadKey/nar_zst1073=== PAUSE TestIsValidUploadKey/nar_zst1074=== RUN TestIsValidUploadKey/nar_xz1075=== PAUSE TestIsValidUploadKey/nar_xz1076=== RUN TestIsValidUploadKey/nar_plain1077=== PAUSE TestIsValidUploadKey/nar_plain1078=== RUN TestIsValidUploadKey/listing1079=== PAUSE TestIsValidUploadKey/listing1080=== RUN TestIsValidUploadKey/build_log1081=== PAUSE TestIsValidUploadKey/build_log1082=== RUN TestIsValidUploadKey/build_log_home-manager_file1083=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1084=== RUN TestIsValidUploadKey/build_log_plus_in_name1085=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1086=== RUN TestIsValidUploadKey/build_log_question_mark1087=== PAUSE TestIsValidUploadKey/build_log_question_mark1088=== RUN TestIsValidUploadKey/build_log_equals1089=== PAUSE TestIsValidUploadKey/build_log_equals1090=== RUN TestIsValidUploadKey/realisation1091=== PAUSE TestIsValidUploadKey/realisation1092=== RUN TestIsValidUploadKey/realisation_plus_in_output1093=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1094=== RUN TestIsValidUploadKey/nix-cache-info1095=== PAUSE TestIsValidUploadKey/nix-cache-info1096=== RUN TestIsValidUploadKey/index.html1097=== PAUSE TestIsValidUploadKey/index.html1098=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1099=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1100=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1101=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1102=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1103=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1104=== RUN TestIsValidUploadKey/traversal1105=== PAUSE TestIsValidUploadKey/traversal1106=== RUN TestIsValidUploadKey/traversal_nar1107=== PAUSE TestIsValidUploadKey/traversal_nar1108=== RUN TestIsValidUploadKey/absolute1109=== PAUSE TestIsValidUploadKey/absolute1110=== RUN TestIsValidUploadKey/empty_key1111=== PAUSE TestIsValidUploadKey/empty_key1112=== RUN TestIsValidUploadKey/unknown_type1113=== PAUSE TestIsValidUploadKey/unknown_type1114=== CONT TestService_createPendingClosureHandler1115=== NAME TestOrphanedObjectsGCStressTest1116 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1117 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion1118--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1119=== CONT TestService_cleanupPendingClosuresHandler1120=== NAME TestOrphanedObjectsGC1121 orphaned_objects_gc_test.go:290: GC Test Summary:1122 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1123 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1124 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1125 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1126 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1127--- PASS: TestOrphanedObjectsGC (0.83s)1128=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT11292026-07-19 11:30:56.650 UTC [8467] ERROR: relation "goose_db_version" does not exist at character 3611302026-07-19 11:30:56.650 UTC [8467] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11312026/07/19 11:30:56 OK 20241026095416_initial_model.sql (9.31ms)11322026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (558.46µs)11332026/07/19 11:30:56 OK 20251218171726_add_pins.sql (972.96µs)11342026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (4.06ms)11352026/07/19 11:30:56 goose: successfully migrated database to version: 2026062812000011362026/07/19 11:30:56 OK 1_commit_pending_closure.sql (2.02ms)11372026/07/19 11:30:56 OK 2_object_stats_trigger.sql (255µs)11382026/07/19 11:30:56 goose: up to current file version: 211392026/07/19 11:30:56 INFO Created nix-cache-info in bucket bucket=bucket261140=== NAME TestOrphanedObjectsGCStressTest1141 orphaned_objects_gc_test.go:509: Stress test completed successfully:1142 orphaned_objects_gc_test.go:510: - Active objects preserved: 201143 orphaned_objects_gc_test.go:511: - Objects deleted: 2101144 orphaned_objects_gc_test.go:512: - Total GC'd: 2101145--- PASS: TestOrphanedObjectsGCStressTest (1.05s)1146=== CONT TestUploadHandlersRejectOversizedBody1147=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1148=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1149=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1150=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1151=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1152=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1153=== CONT TestCompleteMultipartUnregistered11542026/07/19 11:30:56 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=01155=== NAME TestClientIntegration1156 client_integration_test.go:276: Created store path: /nix/var/nix/builds/nix-8213-2982444896/TestClientIntegration1965835634/002/store/7rswy348yfpw69w4ypsgzz1s7av7v4lx-test-file.txt11572026-07-19 11:30:56.760 UTC [8473] ERROR: relation "goose_db_version" does not exist at character 3611582026-07-19 11:30:56.760 UTC [8473] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11592026/07/19 11:30:56 INFO Vacuumed table table=pending_closures11602026/07/19 11:30:56 INFO Vacuumed table table=pending_objects11612026/07/19 11:30:56 INFO Vacuumed table table=multipart_uploads11622026/07/19 11:30:56 INFO Vacuumed table table=closures11632026/07/19 11:30:56 INFO Vacuumed table table=objects11642026/07/19 11:30:56 OK 20241026095416_initial_model.sql (7.66ms)11652026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (531.63µs)11662026/07/19 11:30:56 OK 20251218171726_add_pins.sql (836.04µs)11672026-07-19 11:30:56.781 UTC [8474] ERROR: relation "goose_db_version" does not exist at character 3611682026-07-19 11:30:56.781 UTC [8474] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11692026-07-19 11:30:56.781 UTC [8475] ERROR: relation "goose_db_version" does not exist at character 3611702026-07-19 11:30:56.781 UTC [8475] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11712026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (12.3ms)11722026/07/19 11:30:56 goose: successfully migrated database to version: 2026062812000011732026/07/19 11:30:56 OK 1_commit_pending_closure.sql (1.28ms)11742026/07/19 11:30:56 OK 2_object_stats_trigger.sql (234.08µs)11752026/07/19 11:30:56 goose: up to current file version: 211762026/07/19 11:30:56 INFO Created nix-cache-info in bucket bucket=bucket2711772026/07/19 11:30:56 OK 20241026095416_initial_model.sql (8.21ms)11782026/07/19 11:30:56 OK 20241026095416_initial_model.sql (8.67ms)11792026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (551.04µs)11802026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (591.33µs)11812026/07/19 11:30:56 OK 20251218171726_add_pins.sql (903µs)11822026/07/19 11:30:56 OK 20251218171726_add_pins.sql (2.59ms)11832026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (6.6ms)11842026/07/19 11:30:56 goose: successfully migrated database to version: 2026062812000011852026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (8.35ms)11862026/07/19 11:30:56 goose: successfully migrated database to version: 2026062812000011872026-07-19 11:30:56.814 UTC [8479] ERROR: relation "goose_db_version" does not exist at character 3611882026-07-19 11:30:56.814 UTC [8479] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11892026/07/19 11:30:56 OK 1_commit_pending_closure.sql (970.17µs)11902026/07/19 11:30:56 OK 2_object_stats_trigger.sql (248.46µs)11912026/07/19 11:30:56 goose: up to current file version: 211922026/07/19 11:30:56 OK 1_commit_pending_closure.sql (1.38ms)11932026/07/19 11:30:56 OK 2_object_stats_trigger.sql (201.5µs)11942026/07/19 11:30:56 goose: up to current file version: 211952026/07/19 11:30:56 INFO Created nix-cache-info in bucket bucket=bucket291196--- PASS: TestCacheStatsHandler (0.36s)1197=== CONT TestUploadHandlersRejectInvalidKeys1198=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1199=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1200=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1201=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1202=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1203=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1204=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1205=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1206=== CONT TestService_verifyS3Integrity12072026/07/19 11:30:56 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12082026/07/19 11:30:56 INFO Received uploads request method=POST path=/api/pending_closures1209=== NAME TestNARDeduplicationMetadataUploadBug1210 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-8213-2982444896/TestNARDeduplicationMetadataUploadBug4229569868/001/store/fbip665p1q85lw122nhmss990097hfyf-file1.txt12112026/07/19 11:30:56 OK 20241026095416_initial_model.sql (43.51ms)12122026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (847.25µs)12132026/07/19 11:30:56 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12142026/07/19 11:30:56 INFO Uploading 7rswy348yfpw69w4ypsgzz1s7av7v4lx-test-file.txt (152B)12152026/07/19 11:30:56 OK 20251218171726_add_pins.sql (1.71ms)12162026/07/19 11:30:56 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"12172026/07/19 11:30:56 WARN Failed to register uploaded object key=7rswy348yfpw69w4ypsgzz1s7av7v4lx.ls error="server returned 404: 404 page not found\n"12182026/07/19 11:30:56 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12192026/07/19 11:30:56 INFO Signed narinfos id=1 count=112202026/07/19 11:30:56 INFO Uploading 1 narinfos12212026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (3.7ms)12222026/07/19 11:30:56 goose: successfully migrated database to version: 2026062812000012232026/07/19 11:30:56 WARN Failed to register uploaded object key=7rswy348yfpw69w4ypsgzz1s7av7v4lx.narinfo error="server returned 404: 404 page not found\n"12242026/07/19 11:30:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12252026/07/19 11:30:56 OK 1_commit_pending_closure.sql (933.92µs)12262026/07/19 11:30:56 OK 2_object_stats_trigger.sql (247.04µs)12272026/07/19 11:30:56 goose: up to current file version: 212282026/07/19 11:30:56 INFO Completed upload id=112292026/07/19 11:30:56 INFO Upload complete. (88ms)1230--- PASS: TestService_healthCheckHandler (0.40s)1231=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1232=== NAME TestClientIntegration1233 client_integration_test.go:292: Retrieved narinfo from S3:1234 StorePath: /nix/var/nix/builds/nix-8213-2982444896/TestClientIntegration1965835634/002/store/7rswy348yfpw69w4ypsgzz1s7av7v4lx-test-file.txt1235 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1236 Compression: zstd1237 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11238 NarSize: 1521239 References: 1240 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11241 client_integration_test.go:293: Retrieved .ls file from S3 (compressed size: 77 bytes)1242 client_integration_test.go:293: Decompressed .ls content (64 bytes):1243 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1244 client_integration_test.go:296: Testing garbage collection...12452026/07/19 11:30:56 INFO Starting cleanup of old closures method=DELETE path=/api/closures12462026/07/19 11:30:56 INFO Garbage collection started12472026-07-19 11:30:56.922 UTC [8498] ERROR: relation "goose_db_version" does not exist at character 3612482026-07-19 11:30:56.922 UTC [8498] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12492026/07/19 11:30:56 INFO Aborted multipart uploads count=012502026/07/19 11:30:56 WARN Force mode enabled - objects will be deleted immediately without grace period12512026/07/19 11:30:56 OK 20241026095416_initial_model.sql (3.56ms)12522026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (387.25µs)12532026/07/19 11:30:56 OK 20251218171726_add_pins.sql (742.96µs)12542026/07/19 11:30:56 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12552026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (9.6ms)12562026/07/19 11:30:56 goose: successfully migrated database to version: 2026062812000012572026/07/19 11:30:56 OK 1_commit_pending_closure.sql (1.11ms)12582026/07/19 11:30:56 OK 2_object_stats_trigger.sql (362.17µs)12592026/07/19 11:30:56 goose: up to current file version: 212602026/07/19 11:30:56 INFO Received uploads request method=POST path=/api/pending_closures12612026/07/19 11:30:56 INFO Received uploads request method=POST path=/api/pending_closures12622026/07/19 11:30:56 INFO Received uploads request method=POST path=/api/pending_closures12632026-07-19 11:30:56.956 UTC [8502] ERROR: relation "goose_db_version" does not exist at character 3612642026-07-19 11:30:56.956 UTC [8502] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12652026-07-19 11:30:56.971 UTC [8503] ERROR: relation "goose_db_version" does not exist at character 3612662026-07-19 11:30:56.971 UTC [8503] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12672026/07/19 11:30:56 INFO Received uploads request method=POST path=/api/pending_closures12682026/07/19 11:30:56 OK 20241026095416_initial_model.sql (9.88ms)12692026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (1.03ms)12702026/07/19 11:30:56 OK 20251218171726_add_pins.sql (4.15ms)12712026/07/19 11:30:56 OK 20260628120000_add_object_size_and_stats.sql (3.98ms)12722026/07/19 11:30:56 goose: successfully migrated database to version: 2026062812000012732026/07/19 11:30:56 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12742026/07/19 11:30:56 INFO Uploading fbip665p1q85lw122nhmss990097hfyf-file1.txt (160B)12752026/07/19 11:30:56 OK 1_commit_pending_closure.sql (1.86ms)12762026/07/19 11:30:56 OK 2_object_stats_trigger.sql (387.13µs)12772026/07/19 11:30:56 goose: up to current file version: 212782026/07/19 11:30:56 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12792026/07/19 11:30:56 OK 20241026095416_initial_model.sql (7.43ms)12802026/07/19 11:30:56 OK 20251210153512_drop_unused_gin_index.sql (409.5µs)12812026/07/19 11:30:56 WARN Failed to register uploaded object key=fbip665p1q85lw122nhmss990097hfyf.ls error="server returned 404: 404 page not found\n"12822026/07/19 11:30:56 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12832026/07/19 11:30:56 INFO Received cleanup request method=DELETE path=/api/pending_closures12842026/07/19 11:30:56 OK 20251218171726_add_pins.sql (821.67µs)12852026/07/19 11:30:56 INFO Signed narinfos id=1 count=112862026/07/19 11:30:56 INFO Uploading 1 narinfos12872026/07/19 11:30:56 WARN Failed to register uploaded object key=fbip665p1q85lw122nhmss990097hfyf.narinfo error="server returned 404: 404 page not found\n"12882026/07/19 11:30:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12892026/07/19 11:30:56 INFO Aborted multipart uploads count=012902026/07/19 11:30:56 INFO Received uploads request method=POST path=/api/pending_closures12912026/07/19 11:30:57 INFO Completed upload id=112922026/07/19 11:30:57 OK 20260628120000_add_object_size_and_stats.sql (5.93ms)12932026/07/19 11:30:57 goose: successfully migrated database to version: 2026062812000012942026/07/19 11:30:57 INFO Upload complete. (92ms)1295=== NAME TestNARDeduplicationMetadataUploadBug1296 metadata_upload_test.go:54: Retrieved narinfo from S3:1297 StorePath: /nix/var/nix/builds/nix-8213-2982444896/TestNARDeduplicationMetadataUploadBug4229569868/001/store/fbip665p1q85lw122nhmss990097hfyf-file1.txt1298 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1299 Compression: zstd1300 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1301 NarSize: 1601302 References: 1303 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf13042026/07/19 11:30:57 OK 1_commit_pending_closure.sql (1.79ms)1305 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1306 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1307 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}13082026/07/19 11:30:57 INFO Received cleanup request method=DELETE path=/api/pending_closures13092026/07/19 11:30:57 OK 2_object_stats_trigger.sql (941.46µs)13102026/07/19 11:30:57 goose: up to current file version: 213112026/07/19 11:30:57 INFO Aborted multipart uploads count=113122026/07/19 11:30:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13132026-07-19 11:30:57.005 UTC [8502] ERROR: Closure does not exist: id=113142026-07-19 11:30:57.005 UTC [8502] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE13152026-07-19 11:30:57.005 UTC [8502] STATEMENT: -- name: CommitPendingClosure :exec1316 SELECT commit_pending_closure($1::bigint)1317 1318--- PASS: TestService_cleanupPendingClosuresHandler (0.40s)1319=== CONT TestParseSize1320--- PASS: TestParseSize (0.00s)1321=== CONT TestProxyWriteTimeout1322=== RUN TestProxyWriteTimeout/narinfo1323=== PAUSE TestProxyWriteTimeout/narinfo1324=== RUN TestProxyWriteTimeout/1_GiB_nar1325=== PAUSE TestProxyWriteTimeout/1_GiB_nar1326=== RUN TestProxyWriteTimeout/10_GiB_nar1327=== PAUSE TestProxyWriteTimeout/10_GiB_nar1328=== RUN TestProxyWriteTimeout/unknown_size1329=== PAUSE TestProxyWriteTimeout/unknown_size1330=== CONT TestSkippedUploadsHandler13312026/07/19 11:30:57 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001332--- PASS: TestSkippedUploadsHandler (0.00s)1333=== CONT TestService_AuthMiddleware_MTLSBoundSubjects13342026/07/19 11:30:57 INFO Received uploads request method=POST path=/api/pending_closures1335=== NAME TestClientCADerivations1336 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-8213-2982444896/TestClientCADerivations432080931/001/store/hn9lmad0mjfmvxj9fmazgkc585yj99dn-ca-test1337--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.39s)1338=== CONT TestService_AuthMiddleware_MTLSProxyHeader1339=== NAME TestNARDeduplicationMetadataUploadBug1340 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-8213-2982444896/TestNARDeduplicationMetadataUploadBug4229569868/001/store/0hzcgwqn77j1vka3cf4irjcsy4fb57hh-file2.txt1341=== NAME TestClientCADerivations1342 client_ca_test.go:139: Found 1 dependencies (including self)13432026-07-19 11:30:57.068 UTC [8515] ERROR: relation "goose_db_version" does not exist at character 3613442026-07-19 11:30:57.068 UTC [8515] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13452026/07/19 11:30:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13462026/07/19 11:30:57 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ODMyYzA2OWEtNGQ2Mi00ZjNiLWFhNmItMTk3NTMzNTY0OWFhLjhiNDcxODBlLTEzMzItNDc1NS1hNWI2LTU2NDVmZDg3NjEyNHgxNzg0NDYwNjU2OTY1MjE2MDAw parts=1013472026/07/19 11:30:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13482026/07/19 11:30:57 INFO Completed upload id=113492026/07/19 11:30:57 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000013502026/07/19 11:30:57 INFO Received uploads request method=POST path=/api/pending_closures13512026/07/19 11:30:57 INFO Starting cleanup of old closures method=DELETE path=/api/closures13522026/07/19 11:30:57 INFO Aborted multipart uploads count=013532026/07/19 11:30:57 OK 20241026095416_initial_model.sql (7.96ms)13542026/07/19 11:30:57 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=013552026/07/19 11:30:57 OK 20251210153512_drop_unused_gin_index.sql (687.46µs)13562026/07/19 11:30:57 OK 20251218171726_add_pins.sql (794.79µs)13572026/07/19 11:30:57 INFO Vacuumed table table=pending_closures13582026/07/19 11:30:57 INFO Vacuumed table table=pending_objects13592026/07/19 11:30:57 OK 20260628120000_add_object_size_and_stats.sql (3.76ms)13602026/07/19 11:30:57 goose: successfully migrated database to version: 2026062812000013612026/07/19 11:30:57 OK 1_commit_pending_closure.sql (1.08ms)13622026/07/19 11:30:57 OK 2_object_stats_trigger.sql (229.63µs)13632026/07/19 11:30:57 goose: up to current file version: 213642026/07/19 11:30:57 INFO Vacuumed table table=multipart_uploads13652026/07/19 11:30:57 INFO Vacuumed table table=closures13662026/07/19 11:30:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13672026/07/19 11:30:57 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1368--- PASS: TestCompleteMultipartUnregistered (0.39s)1369=== CONT TestService_ReadAuthMiddleware13702026/07/19 11:30:57 INFO Vacuumed table table=objects13712026/07/19 11:30:57 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13722026/07/19 11:30:57 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13732026/07/19 11:30:57 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001374--- PASS: TestService_createPendingClosureHandler (0.56s)1375=== CONT TestPresignedUploadRegisteredBeforeCommit13762026-07-19 11:30:57.151 UTC [8530] ERROR: relation "goose_db_version" does not exist at character 3613772026-07-19 11:30:57.151 UTC [8530] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13782026/07/19 11:30:57 INFO Received uploads request method=POST path=/api/pending_closures13792026/07/19 11:30:57 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)13802026/07/19 11:30:57 WARN Failed to register uploaded object key=0hzcgwqn77j1vka3cf4irjcsy4fb57hh.ls error="server returned 404: 404 page not found\n"13812026/07/19 11:30:57 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13822026/07/19 11:30:57 INFO Signed narinfos id=2 count=113832026/07/19 11:30:57 INFO Uploading 1 narinfos13842026/07/19 11:30:57 WARN Failed to register uploaded object key=0hzcgwqn77j1vka3cf4irjcsy4fb57hh.narinfo error="server returned 404: 404 page not found\n"13852026/07/19 11:30:57 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13862026/07/19 11:30:57 INFO Completed upload id=213872026/07/19 11:30:57 INFO Upload complete. (82ms)1388=== NAME TestNARDeduplicationMetadataUploadBug1389 metadata_upload_test.go:76: Retrieved narinfo from S3:1390 StorePath: /nix/var/nix/builds/nix-8213-2982444896/TestNARDeduplicationMetadataUploadBug4229569868/001/store/0hzcgwqn77j1vka3cf4irjcsy4fb57hh-file2.txt1391 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1392 Compression: zstd1393 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1394 NarSize: 1601395 References: 1396 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1397 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1398 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1399 {"version":1,"root":{"type":"regular","size":44}}14002026/07/19 11:30:57 OK 20241026095416_initial_model.sql (8.34ms)14012026/07/19 11:30:57 OK 20251210153512_drop_unused_gin_index.sql (926.46µs)1402--- PASS: TestNARDeduplicationMetadataUploadBug (0.71s)1403=== CONT TestService_Rustfstest14042026/07/19 11:30:57 OK 20251218171726_add_pins.sql (4.97ms)14052026/07/19 11:30:57 INFO Received uploads request method=POST path=/api/pending_closures14062026/07/19 11:30:57 OK 20260628120000_add_object_size_and_stats.sql (15.74ms)14072026/07/19 11:30:57 goose: successfully migrated database to version: 2026062812000014082026/07/19 11:30:57 OK 1_commit_pending_closure.sql (1.38ms)14092026/07/19 11:30:57 OK 2_object_stats_trigger.sql (459.58µs)14102026/07/19 11:30:57 goose: up to current file version: 214112026/07/19 11:30:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14122026/07/19 11:30:57 INFO Uploading hn9lmad0mjfmvxj9fmazgkc585yj99dn-ca-test (144B)14132026/07/19 11:30:57 WARN Failed to register uploaded object key=log/aksgqxff86fy3zpisy41qszqdwkprhcz-ca-test.drv error="server returned 404: 404 page not found\n"14142026/07/19 11:30:57 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"14152026/07/19 11:30:57 INFO Received uploads request method=POST path=/api/pending_closures14162026/07/19 11:30:57 WARN Failed to register uploaded object key=hn9lmad0mjfmvxj9fmazgkc585yj99dn.ls error="server returned 404: 404 page not found\n"14172026/07/19 11:30:57 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14182026/07/19 11:30:57 INFO Signed narinfos id=1 count=114192026/07/19 11:30:57 INFO Uploading 1 narinfos14202026/07/19 11:30:57 WARN Failed to register uploaded object key=hn9lmad0mjfmvxj9fmazgkc585yj99dn.narinfo error="server returned 404: 404 page not found\n"14212026/07/19 11:30:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14222026/07/19 11:30:57 INFO Completed upload id=114232026/07/19 11:30:57 INFO Upload complete. (107ms)1424=== NAME TestClientCADerivations1425 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-8213-2982444896/TestClientCADerivations432080931/001/store/hn9lmad0mjfmvxj9fmazgkc585yj99dn-ca-test1426 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1427 Compression: zstd1428 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1429 NarSize: 1441430 References: 1431 Deriver: /nix/var/nix/builds/nix-8213-2982444896/TestClientCADerivations432080931/001/store/aksgqxff86fy3zpisy41qszqdwkprhcz-ca-test.drv1432 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1433 client_ca_test.go:185: Checking for realisation files in S3...1434 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1435 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache14362026-07-19 11:30:57.204 UTC [8537] ERROR: relation "goose_db_version" does not exist at character 3614372026-07-19 11:30:57.204 UTC [8537] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14382026/07/19 11:30:57 OK 20241026095416_initial_model.sql (12.9ms)14392026/07/19 11:30:57 OK 20251210153512_drop_unused_gin_index.sql (567.92µs)14402026/07/19 11:30:57 OK 20251218171726_add_pins.sql (864.21µs)14412026/07/19 11:30:57 OK 20260628120000_add_object_size_and_stats.sql (5.91ms)14422026/07/19 11:30:57 goose: successfully migrated database to version: 2026062812000014432026/07/19 11:30:57 OK 1_commit_pending_closure.sql (2.63ms)14442026/07/19 11:30:57 OK 2_object_stats_trigger.sql (590.17µs)14452026/07/19 11:30:57 goose: up to current file version: 214462026/07/19 11:30:57 INFO Received uploads request method=POST path=/api/pending_closures1447 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket27?endpoint=http://localhost:60075®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-8213-2982444896/TestClientCADerivations432080931/001/store'1448 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11449--- PASS: TestClientCADerivations (0.78s)1450=== CONT TestCompletedNarNotReofferedAcrossClosures14512026/07/19 11:30:57 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=014522026/07/19 11:30:57 INFO Vacuumed table table=pending_closures14532026/07/19 11:30:57 INFO Vacuumed table table=pending_objects14542026/07/19 11:30:57 INFO Vacuumed table table=multipart_uploads14552026/07/19 11:30:57 INFO Vacuumed table table=closures14562026/07/19 11:30:57 INFO Vacuumed table table=objects14572026/07/19 11:30:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14582026/07/19 11:30:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14592026/07/19 11:30:57 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ODMyYzA2OWEtNGQ2Mi00ZjNiLWFhNmItMTk3NTMzNTY0OWFhLjQzM2I4MDExLWIzOTAtNGJhZS04MWU2LTE5ZmM4ZmI4YzQxYngxNzg0NDYwNjU3MTk2MDc3MDAw parts=1014602026/07/19 11:30:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14612026/07/19 11:30:57 INFO Completed upload id=114622026/07/19 11:30:57 INFO Received uploads request method=POST path=/api/pending_closures14632026/07/19 11:30:57 INFO Received uploads request method=POST path=/api/pending_closures14642026/07/19 11:30:57 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo14652026/07/19 11:30:57 WARN Found objects in DB but missing from S3, will re-upload count=11466--- PASS: TestService_verifyS3Integrity (0.48s)1467=== CONT TestCompleteMultipartUpload_ErrorButObjectExists14682026-07-19 11:30:57.311 UTC [8543] ERROR: relation "goose_db_version" does not exist at character 3614692026-07-19 11:30:57.311 UTC [8543] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14702026-07-19 11:30:57.355 UTC [8545] ERROR: relation "goose_db_version" does not exist at character 3614712026-07-19 11:30:57.355 UTC [8545] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14722026/07/19 11:30:57 OK 20241026095416_initial_model.sql (48.42ms)14732026/07/19 11:30:57 OK 20251210153512_drop_unused_gin_index.sql (570.79µs)14742026/07/19 11:30:57 OK 20251218171726_add_pins.sql (1.31ms)14752026/07/19 11:30:57 OK 20260628120000_add_object_size_and_stats.sql (2.26ms)14762026/07/19 11:30:57 goose: successfully migrated database to version: 2026062812000014772026/07/19 11:30:57 OK 1_commit_pending_closure.sql (1.24ms)14782026/07/19 11:30:57 OK 2_object_stats_trigger.sql (233.63µs)14792026/07/19 11:30:57 goose: up to current file version: 214802026/07/19 11:30:57 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"14812026/07/19 11:30:57 WARN mTLS auth: bound subjects configured but subject DN unavailable14822026/07/19 11:30:57 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1483--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.36s)1484=== CONT TestService_AuthMiddleware_OIDC14852026/07/19 11:30:57 INFO OIDC provider initialized name=test14862026/07/19 11:30:57 OK 20241026095416_initial_model.sql (6.84ms)14872026/07/19 11:30:57 OK 20251210153512_drop_unused_gin_index.sql (473.71µs)14882026/07/19 11:30:57 OK 20251218171726_add_pins.sql (1.32ms)14892026/07/19 11:30:57 OK 20260628120000_add_object_size_and_stats.sql (3.47ms)14902026/07/19 11:30:57 goose: successfully migrated database to version: 2026062812000014912026/07/19 11:30:57 OK 1_commit_pending_closure.sql (1.12ms)14922026/07/19 11:30:57 OK 2_object_stats_trigger.sql (382.38µs)14932026/07/19 11:30:57 goose: up to current file version: 21494--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.36s)1495=== CONT TestIsValidCachePath/narinfo1496=== CONT TestIsValidCachePath/index.html1497=== CONT TestIsValidCachePath/short_hash1498=== CONT TestIsValidCachePath/wrong_extension1499=== CONT TestIsValidCachePath/leading_slash1500=== CONT TestIsValidCachePath/empty1501=== CONT TestIsValidCachePath/random_path1502=== CONT TestIsValidCachePath/invalid_char_u1503=== CONT TestIsValidCachePath/invalid_char_e1504=== CONT TestIsValidCachePath/traversal_in_middle1505=== CONT TestIsValidCachePath/traversal_parent1506=== CONT TestIsValidCachePath/nar_uncompressed1507=== CONT TestIsValidCachePath/nix-cache-info1508=== CONT TestIsValidCachePath/realisation1509=== CONT TestIsValidCachePath/log1510=== CONT TestIsValidCachePath/ls1511=== CONT TestIsValidCachePath/nar_xz1512=== CONT TestIsValidCachePath/nar_bz21513=== CONT TestIsValidCachePath/nar_zst1514=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1515--- PASS: TestIsValidCachePath (0.00s)1516 --- PASS: TestIsValidCachePath/narinfo (0.00s)1517 --- PASS: TestIsValidCachePath/index.html (0.00s)1518 --- PASS: TestIsValidCachePath/short_hash (0.00s)1519 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1520 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1521 --- PASS: TestIsValidCachePath/empty (0.00s)1522 --- PASS: TestIsValidCachePath/random_path (0.00s)1523 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1524 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1525 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1526 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1527 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1528 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1529 --- PASS: TestIsValidCachePath/realisation (0.00s)1530 --- PASS: TestIsValidCachePath/log (0.00s)1531 --- PASS: TestIsValidCachePath/ls (0.00s)1532 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1533 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1534 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1535 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1536=== CONT TestParseSingleRange/none1537=== CONT TestParseSingleRange/open-ended1538=== CONT TestParseSingleRange/start_far_past_EOF1539=== CONT TestParseSingleRange/start_past_EOF1540=== CONT TestParseSingleRange/single_byte1541=== CONT TestParseSingleRange/suffix_exceeds_size1542=== CONT TestParseSingleRange/suffix1543=== CONT TestParseSingleRange/end_clamped_to_size1544=== CONT TestParseSingleRange/malformed_both_empty1545=== CONT TestParseSingleRange/closed1546=== CONT TestParseSingleRange/malformed_end_before_start1547=== CONT TestParseSingleRange/multi-range_ignored1548=== CONT TestParseSingleRange/malformed_no_dash1549=== CONT TestParseSingleRange/unknown_unit1550--- PASS: TestParseSingleRange (0.00s)1551 --- PASS: TestParseSingleRange/none (0.00s)1552 --- PASS: TestParseSingleRange/open-ended (0.00s)1553 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1554 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1555 --- PASS: TestParseSingleRange/single_byte (0.00s)1556 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1557 --- PASS: TestParseSingleRange/suffix (0.00s)1558 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1559 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1560 --- PASS: TestParseSingleRange/closed (0.00s)1561 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1562 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1563 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1564 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1565=== CONT TestServerTLSConfig/no_client_CA1566=== CONT TestServerTLSConfig/not_a_PEM_file1567=== CONT TestServerTLSConfig/missing_CA_file1568--- PASS: TestServerTLSConfig (0.00s)1569 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1570 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1571 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1572=== CONT TestClientErrorHandling/InvalidStorePath15732026-07-19 11:30:57.485 UTC [8550] ERROR: relation "goose_db_version" does not exist at character 3615742026-07-19 11:30:57.485 UTC [8550] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15752026/07/19 11:30:57 OK 20241026095416_initial_model.sql (6.37ms)15762026/07/19 11:30:57 OK 20251210153512_drop_unused_gin_index.sql (363.33µs)15772026/07/19 11:30:57 OK 20251218171726_add_pins.sql (725.42µs)15782026/07/19 11:30:57 OK 20260628120000_add_object_size_and_stats.sql (4.19ms)15792026/07/19 11:30:57 goose: successfully migrated database to version: 2026062812000015802026/07/19 11:30:57 OK 1_commit_pending_closure.sql (1.42ms)15812026/07/19 11:30:57 OK 2_object_stats_trigger.sql (350.92µs)15822026/07/19 11:30:57 goose: up to current file version: 215832026/07/19 11:30:57 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1584--- PASS: TestService_ReadAuthMiddleware (0.40s)1585=== CONT TestClientErrorHandling/ServerNotAvailable15862026-07-19 11:30:57.518 UTC [8552] ERROR: relation "goose_db_version" does not exist at character 3615872026-07-19 11:30:57.518 UTC [8552] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15882026/07/19 11:30:57 OK 20241026095416_initial_model.sql (6.22ms)15892026/07/19 11:30:57 OK 20251210153512_drop_unused_gin_index.sql (557.17µs)15902026/07/19 11:30:57 OK 20251218171726_add_pins.sql (2.21ms)15912026/07/19 11:30:57 OK 20260628120000_add_object_size_and_stats.sql (2ms)15922026/07/19 11:30:57 goose: successfully migrated database to version: 2026062812000015932026/07/19 11:30:57 OK 1_commit_pending_closure.sql (904µs)15942026/07/19 11:30:57 OK 2_object_stats_trigger.sql (279.88µs)15952026/07/19 11:30:57 goose: up to current file version: 215962026/07/19 11:30:57 INFO Received uploads request method=POST path=/api/pending_closures15972026-07-19 11:30:57.540 UTC [8554] ERROR: relation "goose_db_version" does not exist at character 3615982026-07-19 11:30:57.540 UTC [8554] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15992026/07/19 11:30:57 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst16002026/07/19 11:30:57 INFO Received uploads request method=POST path=/api/pending_closures1601--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.43s)1602=== CONT TestClientErrorHandling/InvalidAuthToken16032026/07/19 11:30:57 OK 20241026095416_initial_model.sql (7.94ms)16042026/07/19 11:30:57 OK 20251210153512_drop_unused_gin_index.sql (337.33µs)16052026/07/19 11:30:57 OK 20251218171726_add_pins.sql (722.54µs)16062026/07/19 11:30:57 OK 20260628120000_add_object_size_and_stats.sql (2.66ms)16072026/07/19 11:30:57 goose: successfully migrated database to version: 2026062812000016082026/07/19 11:30:57 OK 1_commit_pending_closure.sql (873.88µs)16092026/07/19 11:30:57 OK 2_object_stats_trigger.sql (192.42µs)16102026/07/19 11:30:57 goose: up to current file version: 21611--- PASS: TestService_Rustfstest (0.42s)1612=== CONT TestCacheConfigHandler/full_config,_no_issuer1613=== CONT TestCacheConfigHandler/no_signing_keys1614=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1615=== CONT TestCacheConfigHandler/no_cache_url_configured1616--- PASS: TestCacheConfigHandler (0.00s)1617 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1618 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1619 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1620 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1621=== CONT TestIsValidUploadKey/narinfo1622=== CONT TestIsValidUploadKey/realisation_plus_in_output1623=== CONT TestIsValidUploadKey/unknown_type1624=== CONT TestIsValidUploadKey/empty_key1625=== CONT TestIsValidUploadKey/absolute1626=== CONT TestIsValidUploadKey/traversal_nar1627=== CONT TestIsValidUploadKey/traversal1628=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1629=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1630=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1631=== CONT TestIsValidUploadKey/index.html1632=== CONT TestIsValidUploadKey/nix-cache-info1633=== CONT TestIsValidUploadKey/build_log_home-manager_file1634=== CONT TestIsValidUploadKey/realisation1635=== CONT TestIsValidUploadKey/build_log_equals1636=== CONT TestIsValidUploadKey/build_log_question_mark1637=== CONT TestIsValidUploadKey/build_log_plus_in_name1638=== CONT TestIsValidUploadKey/nar_plain1639=== CONT TestIsValidUploadKey/build_log1640=== CONT TestIsValidUploadKey/listing1641=== CONT TestIsValidUploadKey/nar_xz1642=== CONT TestIsValidUploadKey/nar_zst1643--- PASS: TestIsValidUploadKey (0.00s)1644 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1645 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1646 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1647 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1648 --- PASS: TestIsValidUploadKey/absolute (0.00s)1649 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1650 --- PASS: TestIsValidUploadKey/traversal (0.00s)1651 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1652 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1653 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1654 --- PASS: TestIsValidUploadKey/index.html (0.00s)1655 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1656 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1657 --- PASS: TestIsValidUploadKey/realisation (0.00s)1658 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1659 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1660 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1661 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1662 --- PASS: TestIsValidUploadKey/build_log (0.00s)1663 --- PASS: TestIsValidUploadKey/listing (0.00s)1664 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1665 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1666=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16672026/07/19 11:30:57 INFO Received complete multipart upload request method=POST path=/1668=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16692026/07/19 11:30:57 INFO Received uploads request method=POST path=/16702026-07-19 11:30:57.606 UTC [8560] ERROR: relation "goose_db_version" does not exist at character 3616712026-07-19 11:30:57.606 UTC [8560] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16722026/07/19 11:30:57 OK 20241026095416_initial_model.sql (10.83ms)16732026/07/19 11:30:57 OK 20251210153512_drop_unused_gin_index.sql (481.17µs)16742026/07/19 11:30:57 OK 20251218171726_add_pins.sql (839.71µs)16752026-07-19 11:30:57.630 UTC [8562] ERROR: relation "goose_db_version" does not exist at character 3616762026-07-19 11:30:57.630 UTC [8562] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16772026/07/19 11:30:57 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-config16782026/07/19 11:30:57 OK 20260628120000_add_object_size_and_stats.sql (18.16ms)16792026/07/19 11:30:57 goose: successfully migrated database to version: 2026062812000016802026/07/19 11:30:57 OK 1_commit_pending_closure.sql (970.71µs)16812026/07/19 11:30:57 OK 2_object_stats_trigger.sql (238.33µs)16822026/07/19 11:30:57 goose: up to current file version: 216832026/07/19 11:30:57 INFO Received uploads request method=POST path=/api/pending_closures16842026/07/19 11:30:57 OK 20241026095416_initial_model.sql (5.52ms)16852026/07/19 11:30:57 OK 20251210153512_drop_unused_gin_index.sql (547.42µs)16862026/07/19 11:30:57 OK 20251218171726_add_pins.sql (824.21µs)16872026/07/19 11:30:57 OK 20260628120000_add_object_size_and_stats.sql (1.73ms)16882026/07/19 11:30:57 goose: successfully migrated database to version: 2026062812000016892026/07/19 11:30:57 OK 1_commit_pending_closure.sql (993.5µs)16902026/07/19 11:30:57 OK 2_object_stats_trigger.sql (226.5µs)16912026/07/19 11:30:57 goose: up to current file version: 216922026/07/19 11:30:57 INFO Received uploads request method=POST path=/api/pending_closures16932026/07/19 11:30:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1694{"timestamp":"2026-07-19T11:30:57.675736Z","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(11)"}1695{"timestamp":"2026-07-19T11:30:57.675772Z","level":"ERROR","fields":{"message":"complete_multipart_upload etag err client=Some(\"deadbeef\"), stored=\"\", part_id=1, bucket=bucket43, 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(11)"}16962026/07/19 11:30:57 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=ODMyYzA2OWEtNGQ2Mi00ZjNiLWFhNmItMTk3NTMzNTY0OWFhLjExNjQyN2FjLTExMjEtNGI4ZS1hNmE3LTMxNTQ1ZmJhMmI5ZngxNzg0NDYwNjU3NjYyMDg5MDAw16972026-07-19 11:30:57.679 UTC [8563] ERROR: relation "goose_db_version" does not exist at character 3616982026-07-19 11:30:57.679 UTC [8563] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16992026/07/19 11:30:57 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ODMyYzA2OWEtNGQ2Mi00ZjNiLWFhNmItMTk3NTMzNTY0OWFhLjExNjQyN2FjLTExMjEtNGI4ZS1hNmE3LTMxNTQ1ZmJhMmI5ZngxNzg0NDYwNjU3NjYyMDg5MDAw parts=11700--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.38s)1701=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17022026/07/19 11:30:57 INFO Received request for more parts method=POST path=/1703=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17042026/07/19 11:30:57 INFO Received uploads request method=POST path=/1705=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17062026/07/19 11:30:57 INFO Received complete multipart upload request method=POST path=/1707=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17082026/07/19 11:30:57 INFO Received request for more parts method=POST path=/1709=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17102026/07/19 11:30:57 INFO Received uploads request method=POST path=/1711--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1712 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1713 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1714 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1715 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1716=== CONT TestProxyWriteTimeout/narinfo1717=== CONT TestProxyWriteTimeout/10_GiB_nar1718=== CONT TestProxyWriteTimeout/unknown_size1719=== CONT TestProxyWriteTimeout/1_GiB_nar1720--- PASS: TestProxyWriteTimeout (0.00s)1721 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1722 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1723 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1724 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)17252026-07-19 11:30:57.714 UTC [8564] ERROR: relation "goose_db_version" does not exist at character 3617262026-07-19 11:30:57.714 UTC [8564] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17272026/07/19 11:30:57 OK 20241026095416_initial_model.sql (30.3ms)17282026/07/19 11:30:57 OK 20251210153512_drop_unused_gin_index.sql (405.17µs)17292026/07/19 11:30:57 OK 20251218171726_add_pins.sql (759.67µs)17302026/07/19 11:30:57 OK 20260628120000_add_object_size_and_stats.sql (2.64ms)17312026/07/19 11:30:57 goose: successfully migrated database to version: 2026062812000017322026/07/19 11:30:57 OK 1_commit_pending_closure.sql (1.16ms)17332026/07/19 11:30:57 OK 2_object_stats_trigger.sql (261.13µs)17342026/07/19 11:30:57 goose: up to current file version: 21735=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1736=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1737=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1738=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1739=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1740=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1741=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1742=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1743=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1744=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected17452026/07/19 11:30:57 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]1746=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1747=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected17482026/07/19 11:30:57 INFO OIDC auth successful provider=test17492026/07/19 11:30:57 WARN Authentication failed token_preview=eyJhbGciOi...BUe2MOy95w 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]1750--- PASS: TestService_AuthMiddleware_OIDC (0.36s)1751 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1752 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1753 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1754 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)17552026/07/19 11:30:57 OK 20241026095416_initial_model.sql (4.3ms)17562026/07/19 11:30:57 OK 20251210153512_drop_unused_gin_index.sql (345.17µs)17572026/07/19 11:30:57 OK 20251218171726_add_pins.sql (758.88µs)17582026/07/19 11:30:57 OK 20260628120000_add_object_size_and_stats.sql (1ms)17592026/07/19 11:30:57 goose: successfully migrated database to version: 2026062812000017602026/07/19 11:30:57 OK 1_commit_pending_closure.sql (1.5ms)17612026/07/19 11:30:57 OK 2_object_stats_trigger.sql (292.46µs)17622026/07/19 11:30:57 goose: up to current file version: 217632026/07/19 11:30:57 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=198.362668ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17642026/07/19 11:30:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17652026/07/19 11:30:57 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ODMyYzA2OWEtNGQ2Mi00ZjNiLWFhNmItMTk3NTMzNTY0OWFhLjVkZjEyNTBjLTUyZmMtNGFkMC05ODZhLWFmZDRmMzc4YmYzOHgxNzg0NDYwNjU3NjQ4OTA1MDAw parts=1217662026/07/19 11:30:57 INFO Received uploads request method=POST path=/api/pending_closures1767--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.54s)17682026-07-19 11:30:57.795 UTC [8567] ERROR: relation "goose_db_version" does not exist at character 3617692026-07-19 11:30:57.795 UTC [8567] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17702026/07/19 11:30:57 OK 20241026095416_initial_model.sql (3.8ms)17712026/07/19 11:30:57 OK 20251210153512_drop_unused_gin_index.sql (334.71µs)17722026/07/19 11:30:57 OK 20251218171726_add_pins.sql (740.46µs)17732026/07/19 11:30:57 OK 20260628120000_add_object_size_and_stats.sql (1.13ms)17742026/07/19 11:30:57 goose: successfully migrated database to version: 2026062812000017752026/07/19 11:30:57 OK 1_commit_pending_closure.sql (839.42µs)17762026/07/19 11:30:57 OK 2_object_stats_trigger.sql (196.75µs)17772026/07/19 11:30:57 goose: up to current file version: 21778--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)1779 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1780 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1781 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.27s)17822026/07/19 11:30:57 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17832026/07/19 11:30:57 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=420.305029ms 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:30:57 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"17852026/07/19 11:30:58 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=879.673019ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17862026/07/19 11:30:58 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01787=== NAME TestPinProtectsFromGC1788 client_integration_test.go:709: Pin successfully protected closure from garbage collection1789--- PASS: TestPinProtectsFromGC (2.83s)17902026/07/19 11:30:58 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01791=== NAME TestClientIntegration1792 client_integration_test.go:303: Objects in database after GC:1793 client_integration_test.go:303: Successfully deleted all objects with GC --force1794--- PASS: TestClientIntegration (2.55s)17952026/07/19 11:30:59 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.717181696s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17962026/07/19 11:31:00 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"17972026/07/19 11:31:01 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_closures17982026/07/19 11:31:01 WARN Rate limiter enabled after throttle name=s3-test rate=517992026/07/19 11:31:01 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1800=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1801 throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=101802 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001803--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.23s)18042026/07/19 11:31:01 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=186.251926ms 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:31:01 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=424.789235ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures18062026/07/19 11:31:01 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=785.088314ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures18072026/07/19 11:31:02 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.694120446s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1808--- PASS: TestClientErrorHandling (0.00s)1809 --- PASS: TestClientErrorHandling/InvalidStorePath (0.39s)1810 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.38s)1811 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.74s)1812PASS1813{"timestamp":"2026-07-19T11:31:04.748821Z","level":"ERROR","fields":{"message":"Unknown connection IO error:Cancelled","peer_addr":"127.0.0.1:60237"},"target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":973,"threadName":"rustfs-worker","threadId":"ThreadId(10)"}18142026-07-19 11:31:04.813 UTC [8248] LOG: received smart shutdown request18152026-07-19 11:31:04.814 UTC [8248] LOG: background worker "logical replication launcher" (PID 8258) exited with exit code 118162026-07-19 11:31:04.822 UTC [8253] LOG: shutting down18172026-07-19 11:31:04.823 UTC [8253] LOG: checkpoint starting: shutdown immediate18182026-07-19 11:31:05.805 UTC [8253] LOG: checkpoint complete: wrote 12627 buffers (77.1%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 13 recycled; write=0.699 s, sync=0.258 s, total=0.983 s; sync files=15167, longest=0.001 s, average=0.001 s; distance=212066 kB, estimate=212066 kB; lsn=0/E69DFE8, redo lsn=0/E69DFE818192026-07-19 11:31:05.811 UTC [8248] LOG: database system is shut down1820Running OIDC tests...1821=== RUN TestGlobMatch1822=== PAUSE TestGlobMatch1823=== RUN TestAudienceForIssuer1824=== PAUSE TestAudienceForIssuer1825=== RUN TestValidateToken_ValidToken1826=== PAUSE TestValidateToken_ValidToken1827=== RUN TestValidateToken_WrongAudience1828=== PAUSE TestValidateToken_WrongAudience1829=== RUN TestValidateToken_Expired1830=== PAUSE TestValidateToken_Expired1831=== RUN TestValidateToken_BoundClaimsMismatch1832=== PAUSE TestValidateToken_BoundClaimsMismatch1833=== RUN TestValidateToken_BoundSubjectMismatch1834=== PAUSE TestValidateToken_BoundSubjectMismatch1835=== RUN TestValidateToken_MultipleProviders1836=== PAUSE TestValidateToken_MultipleProviders1837=== RUN TestValidateToken_NoMatchingProvider1838=== PAUSE TestValidateToken_NoMatchingProvider1839=== CONT TestGlobMatch1840=== CONT TestValidateToken_WrongAudience1841=== RUN TestGlobMatch/foo_foo1842=== PAUSE TestGlobMatch/foo_foo1843=== CONT TestValidateToken_BoundClaimsMismatch1844=== CONT TestValidateToken_NoMatchingProvider1845=== CONT TestValidateToken_ValidToken1846=== CONT TestValidateToken_BoundSubjectMismatch1847=== RUN TestGlobMatch/foo_bar1848=== CONT TestAudienceForIssuer1849=== PAUSE TestGlobMatch/foo_bar1850--- PASS: TestAudienceForIssuer (0.00s)1851=== CONT TestValidateToken_Expired1852=== RUN TestGlobMatch/*_1853=== PAUSE TestGlobMatch/*_1854=== RUN TestGlobMatch/*_anything1855=== PAUSE TestGlobMatch/*_anything1856=== RUN TestGlobMatch/foo*_foo1857=== PAUSE TestGlobMatch/foo*_foo1858=== RUN TestGlobMatch/foo*_foobar1859=== PAUSE TestGlobMatch/foo*_foobar1860=== RUN TestGlobMatch/foo*_bar1861=== PAUSE TestGlobMatch/foo*_bar1862=== RUN TestGlobMatch/*bar_bar1863=== PAUSE TestGlobMatch/*bar_bar1864=== RUN TestGlobMatch/*bar_foobar1865=== PAUSE TestGlobMatch/*bar_foobar1866=== RUN TestGlobMatch/*bar_foo1867=== PAUSE TestGlobMatch/*bar_foo1868=== RUN TestGlobMatch/foo*bar_foobar1869=== PAUSE TestGlobMatch/foo*bar_foobar1870=== RUN TestGlobMatch/foo*bar_foo123bar1871=== PAUSE TestGlobMatch/foo*bar_foo123bar1872=== RUN TestGlobMatch/foo*bar_foobarbaz1873=== PAUSE TestGlobMatch/foo*bar_foobarbaz1874=== RUN TestGlobMatch/*/*_foo/bar1875=== PAUSE TestGlobMatch/*/*_foo/bar1876=== RUN TestGlobMatch/*/*_foo1877=== PAUSE TestGlobMatch/*/*_foo1878=== RUN TestGlobMatch/refs/heads/*_refs/heads/main1879=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main1880=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.01881=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.01882=== RUN TestGlobMatch/refs/*/main_refs/heads/main1883=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main1884=== RUN TestGlobMatch/fo?_foo1885=== PAUSE TestGlobMatch/fo?_foo1886=== RUN TestGlobMatch/fo?_fo1887=== PAUSE TestGlobMatch/fo?_fo1888=== RUN TestGlobMatch/fo?_fooo1889=== PAUSE TestGlobMatch/fo?_fooo1890=== CONT TestValidateToken_MultipleProviders1891=== RUN TestGlobMatch/?oo_foo1892=== PAUSE TestGlobMatch/?oo_foo1893=== RUN TestGlobMatch/?oo_boo1894=== PAUSE TestGlobMatch/?oo_boo1895=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1896=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1897=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1898=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1899=== CONT TestGlobMatch/foo_foo1900=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1901=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1902=== CONT TestGlobMatch/?oo_boo1903=== CONT TestGlobMatch/?oo_foo1904=== CONT TestGlobMatch/foo*bar_foo123bar1905=== CONT TestGlobMatch/*bar_foo1906=== CONT TestGlobMatch/foo*bar_foobar1907=== CONT TestGlobMatch/*bar_foobar1908=== CONT TestGlobMatch/*bar_bar1909=== CONT TestGlobMatch/foo*_bar1910=== CONT TestGlobMatch/foo*_foobar1911=== CONT TestGlobMatch/fo?_fooo1912=== CONT TestGlobMatch/*_1913=== CONT TestGlobMatch/foo_bar1914=== CONT TestGlobMatch/foo*_foo1915=== CONT TestGlobMatch/fo?_fo1916=== CONT TestGlobMatch/fo?_foo1917=== CONT TestGlobMatch/refs/*/main_refs/heads/main1918=== CONT TestGlobMatch/*/*_foo1919=== CONT TestGlobMatch/refs/heads/*_refs/heads/main1920=== CONT TestGlobMatch/*/*_foo/bar1921=== CONT TestGlobMatch/foo*bar_foobarbaz1922=== CONT TestGlobMatch/*_anything1923=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.01924--- PASS: TestGlobMatch (0.00s)1925 --- PASS: TestGlobMatch/foo_foo (0.00s)1926 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)1927 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)1928 --- PASS: TestGlobMatch/?oo_boo (0.00s)1929 --- PASS: TestGlobMatch/?oo_foo (0.00s)1930 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)1931 --- PASS: TestGlobMatch/*bar_foo (0.00s)1932 --- PASS: TestGlobMatch/*bar_foobar (0.00s)1933 --- PASS: TestGlobMatch/*bar_bar (0.00s)1934 --- PASS: TestGlobMatch/foo*_bar (0.00s)1935 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)1936 --- PASS: TestGlobMatch/foo*_foobar (0.00s)1937 --- PASS: TestGlobMatch/fo?_fooo (0.00s)1938 --- PASS: TestGlobMatch/*_ (0.00s)1939 --- PASS: TestGlobMatch/foo_bar (0.00s)1940 --- PASS: TestGlobMatch/foo*_foo (0.00s)1941 --- PASS: TestGlobMatch/fo?_fo (0.00s)1942 --- PASS: TestGlobMatch/fo?_foo (0.00s)1943 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)1944 --- PASS: TestGlobMatch/*/*_foo (0.00s)1945 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)1946 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)1947 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)1948 --- PASS: TestGlobMatch/*_anything (0.00s)1949 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)19502026/07/19 11:31:06 INFO OIDC provider initialized name=test19512026/07/19 11:31:06 INFO OIDC provider initialized name=provider119522026/07/19 11:31:06 INFO OIDC provider initialized name=test19532026/07/19 11:31:06 INFO OIDC provider initialized name=test19542026/07/19 11:31:06 INFO OIDC provider initialized name=provider119552026/07/19 11:31:06 INFO OIDC provider initialized name=test19562026/07/19 11:31:06 INFO OIDC provider initialized name=test19572026/07/19 11:31:06 INFO OIDC provider initialized name=provider21958--- PASS: TestValidateToken_WrongAudience (0.01s)1959--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)1960--- PASS: TestValidateToken_ValidToken (0.01s)1961--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)1962--- PASS: TestValidateToken_NoMatchingProvider (0.01s)1963--- PASS: TestValidateToken_Expired (0.01s)1964--- PASS: TestValidateToken_MultipleProviders (0.01s)1965PASS1966Running hook tests...1967=== RUN TestSendPathsEmpty1968=== PAUSE TestSendPathsEmpty1969=== RUN TestQueueEnqueueAndFetch1970=== PAUSE TestQueueEnqueueAndFetch1971=== RUN TestQueueDeduplication1972=== PAUSE TestQueueDeduplication1973=== RUN TestQueueRemove1974=== PAUSE TestQueueRemove1975=== RUN TestQueueFetchBatchLimit1976=== PAUSE TestQueueFetchBatchLimit1977=== RUN TestQueueFetchRemoveLifecycle1978=== PAUSE TestQueueFetchRemoveLifecycle1979=== RUN TestQueueConcurrentWriters1980=== PAUSE TestQueueConcurrentWriters1981=== RUN TestServerClientIntegration1982=== PAUSE TestServerClientIntegration1983=== RUN TestServerQueueError1984=== PAUSE TestServerQueueError1985=== RUN TestGetListenerSocketActivation1986 server_test.go:210: === RUN TestGetListenerSocketActivation1987 --- PASS: TestGetListenerSocketActivation (0.00s)1988 PASS1989 1990--- PASS: TestGetListenerSocketActivation (0.01s)1991=== RUN TestWorkerUploadsAndRemoves1992=== PAUSE TestWorkerUploadsAndRemoves1993=== RUN TestWorkerSkipsGCdPaths1994=== PAUSE TestWorkerSkipsGCdPaths1995=== RUN TestWorkerPrunesClosureDeps1996=== PAUSE TestWorkerPrunesClosureDeps1997=== CONT TestSendPathsEmpty1998--- PASS: TestSendPathsEmpty (0.00s)1999=== CONT TestQueueDeduplication2000=== CONT TestQueueConcurrentWriters2001=== CONT TestQueueRemove2002=== CONT TestQueueEnqueueAndFetch2003=== CONT TestWorkerUploadsAndRemoves2004=== CONT TestWorkerPrunesClosureDeps2005=== CONT TestServerQueueError2006=== CONT TestServerClientIntegration2007=== CONT TestQueueFetchRemoveLifecycle2008=== CONT TestQueueFetchBatchLimit20092026/07/19 11:31:06 ERROR Failed to queue paths error="permission denied" count=12010--- PASS: TestServerQueueError (0.00s)2011=== CONT TestWorkerSkipsGCdPaths2012--- PASS: TestServerClientIntegration (0.00s)2013--- PASS: TestQueueDeduplication (0.01s)20142026/07/19 11:31:06 INFO Upload queue status pending=220152026/07/19 11:31:06 INFO Uploading batch count=22016--- PASS: TestQueueFetchBatchLimit (0.01s)20172026/07/19 11:31:06 INFO Upload queue status pending=220182026/07/19 11:31:06 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-8213-2982444896/TestWorkerSkipsGCdPaths3319639314/002/nonexistent2019--- PASS: TestQueueEnqueueAndFetch (0.01s)20202026/07/19 11:31:06 INFO Uploading batch count=12021--- PASS: TestQueueFetchRemoveLifecycle (0.01s)20222026/07/19 11:31:06 INFO Upload queue status pending=220232026/07/19 11:31:06 INFO Uploading batch count=12024--- PASS: TestQueueRemove (0.01s)2025--- PASS: TestWorkerSkipsGCdPaths (0.06s)2026--- PASS: TestWorkerUploadsAndRemoves (0.06s)2027--- PASS: TestWorkerPrunesClosureDeps (0.06s)2028--- PASS: TestQueueConcurrentWriters (0.16s)2029PASS