niks3-go-unit-tests
aarch64-darwin.go-unit-tests
· build #107
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestCaseHackSuffix5=== PAUSE TestCaseHackSuffix6=== RUN TestFilterOversizedClosures7=== PAUSE TestFilterOversizedClosures8=== RUN TestPartSizeForNAR9=== PAUSE TestPartSizeForNAR10=== RUN TestUploadMultipart_SupersededByPeer11=== PAUSE TestUploadMultipart_SupersededByPeer12=== RUN TestDumpPathMatchesNix13=== PAUSE TestDumpPathMatchesNix14=== RUN TestDumpPathSingleFile15=== PAUSE TestDumpPathSingleFile16=== RUN TestDumpPathWriterError17=== PAUSE TestDumpPathWriterError18=== RUN TestEncodeNixBase3219=== PAUSE TestEncodeNixBase3220=== RUN TestEncodeNixBase32WithRealHash21=== PAUSE TestEncodeNixBase32WithRealHash22=== RUN TestConvertHashToNix3223=== PAUSE TestConvertHashToNix3224=== RUN TestGetStorePathHash25=== PAUSE TestGetStorePathHash26=== RUN TestPathInfoHashCompatibility27=== PAUSE TestPathInfoHashCompatibility28=== RUN TestParsePathInfoJSON29=== PAUSE TestParsePathInfoJSON30=== RUN TestParsePathInfoJSONMultiplePaths31=== PAUSE TestParsePathInfoJSONMultiplePaths32=== RUN TestPathInfoCACompatibility33=== PAUSE TestPathInfoCACompatibility34=== RUN TestRateLimiterFeedback35=== PAUSE TestRateLimiterFeedback36=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess37=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess38=== RUN TestResolveStorePath39=== PAUSE TestResolveStorePath40=== RUN TestDoWithRetry_BodyReplayedViaGetBody41=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody42=== RUN TestShellSplit43=== PAUSE TestShellSplit44=== RUN TestShellSplitErrors45=== PAUSE TestShellSplitErrors46=== RUN TestSetClientTLS47=== PAUSE TestSetClientTLS48=== RUN TestSetClientTLSDoesNotMutateDefaultTransport49=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport50=== RUN TestSetClientTLSErrors51=== PAUSE TestSetClientTLSErrors52=== RUN TestStaticToken53=== PAUSE TestStaticToken54=== RUN TestFileTokenReadsAndCaches55=== PAUSE TestFileTokenReadsAndCaches56=== RUN TestFileTokenMissing57=== PAUSE TestFileTokenMissing58=== RUN TestFileTokenEmpty59=== PAUSE TestFileTokenEmpty60=== RUN TestScriptTokenNoExpiryRerunsEveryCall61=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall62=== RUN TestScriptTokenCachesUntilRefresh63=== PAUSE TestScriptTokenCachesUntilRefresh64=== RUN TestScriptTokenEmptyToken65=== PAUSE TestScriptTokenEmptyToken66=== RUN TestScriptTokenBadJSON67=== PAUSE TestScriptTokenBadJSON68=== RUN TestScriptTokenScriptFails69=== PAUSE TestScriptTokenScriptFails70=== RUN TestScriptTokenEmptyCommand71=== PAUSE TestScriptTokenEmptyCommand72=== CONT TestDoServerRequestAttachesToken73=== CONT TestResolveStorePath74=== CONT TestEncodeNixBase32WithRealHash75--- PASS: TestEncodeNixBase32WithRealHash (0.00s)76=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess77=== CONT TestDumpPathMatchesNix78=== CONT TestPartSizeForNAR79=== RUN TestPartSizeForNAR/zero_stays_at_minimum80=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum81=== RUN TestPartSizeForNAR/small_stays_at_minimum82=== PAUSE TestPartSizeForNAR/small_stays_at_minimum83=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum84=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum85=== CONT TestParsePathInfoJSON862026/07/19 11:28:19 WARN Rate limiter enabled after throttle name=server-test rate=587=== RUN TestParsePathInfoJSON/Nix_format88=== PAUSE TestParsePathInfoJSON/Nix_format89=== RUN TestParsePathInfoJSON/Lix_format90=== PAUSE TestParsePathInfoJSON/Lix_format91=== RUN TestParsePathInfoJSON/empty_input92=== PAUSE TestParsePathInfoJSON/empty_input93=== RUN TestParsePathInfoJSON/whitespace_only94=== PAUSE TestParsePathInfoJSON/whitespace_only95=== RUN TestParsePathInfoJSON/invalid_JSON96=== PAUSE TestParsePathInfoJSON/invalid_JSON97=== CONT TestScriptTokenEmptyCommand98--- PASS: TestScriptTokenEmptyCommand (0.00s)99=== CONT TestScriptTokenScriptFails100=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts101=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts102=== RUN TestPartSizeForNAR/1_TiB103=== PAUSE TestPartSizeForNAR/1_TiB104=== RUN TestPartSizeForNAR/5_TiB_S3_max_object105=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object106=== RUN TestPartSizeForNAR/capped_at_5_GiB107=== PAUSE TestPartSizeForNAR/capped_at_5_GiB108=== CONT TestUploadMultipart_SupersededByPeer109=== RUN TestUploadMultipart_SupersededByPeer/exists110=== PAUSE TestUploadMultipart_SupersededByPeer/exists111=== RUN TestUploadMultipart_SupersededByPeer/missing112=== PAUSE TestUploadMultipart_SupersededByPeer/missing113=== CONT TestScriptTokenBadJSON114=== CONT TestPathInfoCACompatibility115=== RUN TestPathInfoCACompatibility/null_ca_field116=== PAUSE TestPathInfoCACompatibility/null_ca_field117=== RUN TestPathInfoCACompatibility/old_string_format_-_text118=== CONT TestRateLimiterFeedback119=== CONT TestFileTokenMissing120=== CONT TestScriptTokenEmptyToken121=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text122=== RUN TestRateLimiterFeedback/429_enables_limiter123=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive124=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive125=== PAUSE TestRateLimiterFeedback/429_enables_limiter126=== RUN TestPathInfoCACompatibility/new_structured_format_-_text127=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text128=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method129=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method130=== CONT TestScriptTokenCachesUntilRefresh131=== RUN TestRateLimiterFeedback/503_enables_limiter132=== PAUSE TestRateLimiterFeedback/503_enables_limiter133=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter134=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter135=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter136=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter137=== CONT TestScriptTokenNoExpiryRerunsEveryCall138--- PASS: TestFileTokenMissing (0.01s)139--- PASS: TestResolveStorePath (0.01s)140=== CONT TestGetStorePathHash141=== RUN TestGetStorePathHash/valid_store_path142=== PAUSE TestGetStorePathHash/valid_store_path143=== RUN TestGetStorePathHash/basename_without_hyphen_should_error144=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error145=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error146=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error147=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error148=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error149=== CONT TestFileTokenEmpty150=== CONT TestPathInfoHashCompatibility151--- PASS: TestScriptTokenScriptFails (0.01s)152=== CONT TestSetClientTLSDoesNotMutateDefaultTransport153=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)154=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)155=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon156=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon157=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI158=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI159=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512160=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512161=== CONT TestFileTokenReadsAndCaches162--- PASS: TestDoServerRequestAttachesToken (0.01s)163=== CONT TestStaticToken164--- PASS: TestStaticToken (0.00s)165=== CONT TestSetClientTLSErrors166--- PASS: TestFileTokenEmpty (0.00s)167=== CONT TestDumpPathWriterError168--- PASS: TestFileTokenReadsAndCaches (0.00s)169=== CONT TestEncodeNixBase32170=== RUN TestEncodeNixBase32/test_string_hash171=== PAUSE TestEncodeNixBase32/test_string_hash172=== RUN TestEncodeNixBase32/empty_input173=== PAUSE TestEncodeNixBase32/empty_input174=== CONT TestDumpPathSingleFile175=== RUN TestSetClientTLSErrors/missing_cert_file176=== PAUSE TestSetClientTLSErrors/missing_cert_file177=== RUN TestSetClientTLSErrors/missing_key_file178=== PAUSE TestSetClientTLSErrors/missing_key_file179=== RUN TestSetClientTLSErrors/missing_ca_file180=== PAUSE TestSetClientTLSErrors/missing_ca_file181=== RUN TestSetClientTLSErrors/invalid_ca_file182=== PAUSE TestSetClientTLSErrors/invalid_ca_file183=== CONT TestParsePathInfoJSONMultiplePaths184=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths185=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths186=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths187=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths188=== CONT TestFilterOversizedClosures189=== RUN TestFilterOversizedClosures/no_limit_keeps_everything190=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything191=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped192=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped193=== RUN TestFilterOversizedClosures/all_closures_skipped194=== PAUSE TestFilterOversizedClosures/all_closures_skipped195=== CONT TestShellSplitErrors196--- PASS: TestShellSplitErrors (0.00s)197=== CONT TestSetClientTLS198--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)199=== CONT TestConvertHashToNix32200=== RUN TestConvertHashToNix32/SRI_format_to_Nix32201=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32202=== RUN TestConvertHashToNix32/already_Nix32_format203=== PAUSE TestConvertHashToNix32/already_Nix32_format204=== RUN TestConvertHashToNix32/invalid_format205=== PAUSE TestConvertHashToNix32/invalid_format206=== CONT TestCaseHackSuffix207=== RUN TestSetClientTLS/rejects_connection_without_client_cert208=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert209=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA210=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA211=== RUN TestSetClientTLS/preserves_debug_logging_transport212=== PAUSE TestSetClientTLS/preserves_debug_logging_transport213=== CONT TestShellSplit214--- PASS: TestShellSplit (0.00s)215=== CONT TestDoWithRetry_BodyReplayedViaGetBody2162026/07/19 11:28:19 WARN Rate limiter enabled after throttle name=server-test rate=52172026/07/19 11:28:19 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:59767218--- PASS: TestScriptTokenEmptyToken (0.02s)219=== CONT TestParsePathInfoJSON/Nix_format2202026/07/19 11:28:19 WARN Rate limiter backed off name=server-test rate=5221=== CONT TestParsePathInfoJSON/invalid_JSON2222026/07/19 11:28:19 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:59767223=== CONT TestPartSizeForNAR/zero_stays_at_minimum224=== CONT TestUploadMultipart_SupersededByPeer/exists225--- PASS: TestScriptTokenBadJSON (0.02s)226=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum227=== CONT TestPartSizeForNAR/capped_at_5_GiB228=== CONT TestPartSizeForNAR/5_TiB_S3_max_object229=== CONT TestPartSizeForNAR/1_TiB230=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts231=== CONT TestParsePathInfoJSON/empty_input232=== CONT TestParsePathInfoJSON/whitespace_only233=== CONT TestParsePathInfoJSON/Lix_format234--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)235=== CONT TestPartSizeForNAR/small_stays_at_minimum236--- PASS: TestPartSizeForNAR (0.00s)237 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)238 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)239 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)240 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)241 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)242 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)243 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)244=== CONT TestUploadMultipart_SupersededByPeer/missing245--- PASS: TestParsePathInfoJSON (0.00s)246 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)247 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)248 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)249 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)250 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)251=== CONT TestPathInfoCACompatibility/null_ca_field252=== CONT TestPathInfoCACompatibility/new_structured_format_-_text253=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive254=== CONT TestPathInfoCACompatibility/old_string_format_-_text255=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method256--- PASS: TestPathInfoCACompatibility (0.00s)257 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)258 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)259 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)260 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)261 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)262=== CONT TestRateLimiterFeedback/429_enables_limiter2632026/07/19 11:28:19 WARN Rate limiter enabled after throttle name=server-test rate=52642026/07/19 11:28:19 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:597722652026/07/19 11:28:19 WARN Rate limiter backed off name=server-test rate=5266=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter267=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter268--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)269 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)270 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)271=== CONT TestRateLimiterFeedback/503_enables_limiter272=== CONT TestGetStorePathHash/valid_store_path273=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error274=== CONT TestGetStorePathHash/basename_without_hyphen_should_error275=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error276=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)277--- PASS: TestGetStorePathHash (0.00s)278 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)279 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)280 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)281 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)282=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI283=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon284=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512285=== CONT TestEncodeNixBase32/test_string_hash286=== CONT TestEncodeNixBase32/empty_input287--- PASS: TestEncodeNixBase32 (0.00s)288 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)289 --- PASS: TestEncodeNixBase32/empty_input (0.00s)290=== CONT TestSetClientTLSErrors/missing_cert_file291--- PASS: TestPathInfoHashCompatibility (0.00s)292 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)293 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)294 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)295 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)296=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths297=== CONT TestSetClientTLSErrors/invalid_ca_file298=== CONT TestSetClientTLSErrors/missing_ca_file299=== CONT TestSetClientTLSErrors/missing_key_file300=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths301--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)302 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)303 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)304=== CONT TestFilterOversizedClosures/no_limit_keeps_everything305=== CONT TestFilterOversizedClosures/all_closures_skipped3062026/07/19 11:28:19 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=50307=== CONT TestConvertHashToNix32/SRI_format_to_Nix32308=== CONT TestConvertHashToNix32/invalid_format309=== CONT TestConvertHashToNix32/already_Nix32_format310--- PASS: TestConvertHashToNix32 (0.00s)311 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)312 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)313 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)314=== CONT TestSetClientTLS/rejects_connection_without_client_cert315=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3162026/07/19 11:28:19 WARN Rate limiter enabled after throttle name=server-test rate=53172026/07/19 11:28:19 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:597803182026/07/19 11:28:19 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=2000319--- PASS: TestFilterOversizedClosures (0.00s)320 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)321 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)322 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)323=== CONT TestSetClientTLS/preserves_debug_logging_transport3242026/07/19 11:28:19 WARN Rate limiter backed off name=server-test rate=5325--- PASS: TestRateLimiterFeedback (0.00s)326 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)327 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)328 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)329 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)330=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA331--- PASS: TestSetClientTLSErrors (0.00s)332 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)333 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)334 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)335 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)3362026/07/19 11:28:19 http: TLS handshake error from 127.0.0.1:59782: remote error: tls: bad certificate337--- PASS: TestSetClientTLS (0.00s)338 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)339 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)340 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)341--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.03s)342--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)343--- PASS: TestDumpPathWriterError (0.04s)344--- PASS: TestDumpPathSingleFile (0.05s)345--- PASS: TestCaseHackSuffix (0.05s)346--- PASS: TestDumpPathMatchesNix (0.08s)347--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)348PASS349Running server tests...350The files belonging to this database system will be owned by user "_nixbld1".351This user must also own the server process.352353The database cluster will be initialized with locale "C".354The default database encoding has accordingly been set to "SQL_ASCII".355The default text search configuration will be set to "english".356357Data page checksums are enabled.358359creating directory /nix/var/nix/builds/nix-3323-2004179726/postgres2220783134/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-3323-2004179726/postgres2220783134/data -l logfile start376377/nix/var/nix/builds/nix-3323-2004179726/postgres2220783134:5432 - no response3782026-07-19 11:28:21.686 UTC [3364] LOG: starting PostgreSQL 18.4 on aarch64-apple-darwin25.3.0, compiled by clang version 21.1.8, 64-bit3792026-07-19 11:28:21.686 UTC [3364] LOG: listening on Unix socket "/nix/var/nix/builds/nix-3323-2004179726/postgres2220783134/.s.PGSQL.5432"3802026-07-19 11:28:21.688 UTC [3371] LOG: database system was shut down at 2026-07-19 11:28:21 UTC3812026-07-19 11:28:21.689 UTC [3364] LOG: database system is ready to accept connections382/nix/var/nix/builds/nix-3323-2004179726/postgres2220783134:5432 - accepting connections383<jemalloc>: option background_thread currently supports pthread only384{"timestamp":"2026-07-19T11:28:21.811029Z","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(8)"}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:28:21.947 UTC [3422] ERROR: relation "goose_db_version" does not exist at character 364132026-07-19 11:28:21.947 UTC [3422] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4142026/07/19 11:28:21 OK 20241026095416_initial_model.sql (3.09ms)4152026/07/19 11:28:21 OK 20251210153512_drop_unused_gin_index.sql (361.21µs)4162026/07/19 11:28:21 OK 20251218171726_add_pins.sql (678.13µs)4172026/07/19 11:28:21 OK 20260628120000_add_object_size_and_stats.sql (812.54µs)4182026/07/19 11:28:21 goose: successfully migrated database to version: 202606281200004192026/07/19 11:28:21 OK 1_commit_pending_closure.sql (817µs)4202026/07/19 11:28:21 OK 2_object_stats_trigger.sql (338.83µs)4212026/07/19 11:28:21 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:28:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5152026/07/19 11:28:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5162026/07/19 11:28:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5172026/07/19 11:28:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5182026/07/19 11:28:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5192026/07/19 11:28:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5202026/07/19 11:28:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5212026/07/19 11:28:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5222026/07/19 11:28:22 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5232026/07/19 11:28:22 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 TestService_AuthMiddleware546=== CONT TestService_verifyS3Integrity547=== CONT TestSkippedUploadsHandler548=== CONT TestGCMetrics549=== CONT TestReadProxy404550=== CONT TestClientCADerivations551=== CONT TestNARDeduplicationMetadataUploadBug552=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT553=== CONT TestCompleteMultipartUnregistered554=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle5552026/07/19 11:28:22 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000556--- PASS: TestSkippedUploadsHandler (0.01s)557=== CONT TestCreatePendingClosureRejectsOversizedNAR5582026/07/19 11:28:22 INFO Received uploads request method=POST path=/api/pending_closures559--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)560=== CONT TestCacheConfigHandlerMaxNarSize561--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)562=== CONT TestGenerateLandingPage563--- PASS: TestGenerateLandingPage (0.01s)564=== CONT TestService_healthCheckHandler5652026-07-19 11:28:22.497 UTC [3444] ERROR: relation "goose_db_version" does not exist at character 365662026-07-19 11:28:22.497 UTC [3444] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5672026-07-19 11:28:22.501 UTC [3445] ERROR: relation "goose_db_version" does not exist at character 365682026-07-19 11:28:22.501 UTC [3445] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5692026-07-19 11:28:22.502 UTC [3448] ERROR: relation "goose_db_version" does not exist at character 365702026-07-19 11:28:22.502 UTC [3448] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5712026-07-19 11:28:22.502 UTC [3446] ERROR: relation "goose_db_version" does not exist at character 365722026-07-19 11:28:22.502 UTC [3446] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5732026-07-19 11:28:22.502 UTC [3447] ERROR: relation "goose_db_version" does not exist at character 365742026-07-19 11:28:22.502 UTC [3447] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5752026-07-19 11:28:22.504 UTC [3450] ERROR: relation "goose_db_version" does not exist at character 365762026-07-19 11:28:22.504 UTC [3450] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5772026-07-19 11:28:22.504 UTC [3449] ERROR: relation "goose_db_version" does not exist at character 365782026-07-19 11:28:22.504 UTC [3449] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5792026-07-19 11:28:22.505 UTC [3451] ERROR: relation "goose_db_version" does not exist at character 365802026-07-19 11:28:22.505 UTC [3451] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5812026-07-19 11:28:22.506 UTC [3453] ERROR: relation "goose_db_version" does not exist at character 365822026-07-19 11:28:22.506 UTC [3453] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5832026-07-19 11:28:22.506 UTC [3452] ERROR: relation "goose_db_version" does not exist at character 365842026-07-19 11:28:22.506 UTC [3452] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5852026/07/19 11:28:22 OK 20241026095416_initial_model.sql (7.17ms)5862026/07/19 11:28:22 OK 20241026095416_initial_model.sql (6.18ms)5872026/07/19 11:28:22 OK 20251210153512_drop_unused_gin_index.sql (864.46µs)5882026/07/19 11:28:22 OK 20251210153512_drop_unused_gin_index.sql (795.67µs)5892026/07/19 11:28:22 OK 20241026095416_initial_model.sql (7.47ms)5902026/07/19 11:28:22 OK 20251218171726_add_pins.sql (1.77ms)5912026/07/19 11:28:22 OK 20251218171726_add_pins.sql (2.66ms)5922026/07/19 11:28:22 OK 20241026095416_initial_model.sql (8.43ms)5932026/07/19 11:28:22 OK 20251210153512_drop_unused_gin_index.sql (717.21µs)5942026/07/19 11:28:22 OK 20251210153512_drop_unused_gin_index.sql (844.5µs)5952026/07/19 11:28:22 OK 20241026095416_initial_model.sql (7.21ms)5962026/07/19 11:28:22 OK 20260628120000_add_object_size_and_stats.sql (1.32ms)5972026/07/19 11:28:22 goose: successfully migrated database to version: 202606281200005982026/07/19 11:28:22 OK 20260628120000_add_object_size_and_stats.sql (1.7ms)5992026/07/19 11:28:22 goose: successfully migrated database to version: 202606281200006002026/07/19 11:28:22 OK 20241026095416_initial_model.sql (8.05ms)6012026/07/19 11:28:22 OK 20241026095416_initial_model.sql (6.42ms)6022026/07/19 11:28:22 OK 20251210153512_drop_unused_gin_index.sql (811.88µs)6032026/07/19 11:28:22 OK 20251218171726_add_pins.sql (1.32ms)6042026/07/19 11:28:22 OK 20241026095416_initial_model.sql (8.09ms)6052026/07/19 11:28:22 OK 20251210153512_drop_unused_gin_index.sql (952.38µs)6062026/07/19 11:28:22 OK 20241026095416_initial_model.sql (7.81ms)6072026/07/19 11:28:22 OK 1_commit_pending_closure.sql (1.17ms)6082026/07/19 11:28:22 OK 20251218171726_add_pins.sql (2.48ms)6092026/07/19 11:28:22 OK 20251210153512_drop_unused_gin_index.sql (875.54µs)6102026/07/19 11:28:22 OK 1_commit_pending_closure.sql (1.64ms)6112026/07/19 11:28:22 OK 20251210153512_drop_unused_gin_index.sql (715.25µs)6122026/07/19 11:28:22 OK 2_object_stats_trigger.sql (550.46µs)6132026/07/19 11:28:22 goose: up to current file version: 26142026/07/19 11:28:22 OK 20260628120000_add_object_size_and_stats.sql (948.46µs)6152026/07/19 11:28:22 goose: successfully migrated database to version: 202606281200006162026/07/19 11:28:22 OK 20251218171726_add_pins.sql (1.15ms)6172026/07/19 11:28:22 OK 20251210153512_drop_unused_gin_index.sql (910.71µs)6182026/07/19 11:28:22 OK 2_object_stats_trigger.sql (552.13µs)6192026/07/19 11:28:22 goose: up to current file version: 26202026/07/19 11:28:22 OK 20241026095416_initial_model.sql (8.14ms)6212026/07/19 11:28:22 OK 20251218171726_add_pins.sql (1.39ms)6222026/07/19 11:28:22 OK 20251218171726_add_pins.sql (1.26ms)6232026/07/19 11:28:22 OK 1_commit_pending_closure.sql (942.46µs)6242026/07/19 11:28:22 OK 20251210153512_drop_unused_gin_index.sql (584.54µs)6252026/07/19 11:28:22 OK 2_object_stats_trigger.sql (255.08µs)6262026/07/19 11:28:22 goose: up to current file version: 26272026/07/19 11:28:22 OK 20251218171726_add_pins.sql (1.44ms)6282026/07/19 11:28:22 OK 20260628120000_add_object_size_and_stats.sql (1.91ms)6292026/07/19 11:28:22 goose: successfully migrated database to version: 202606281200006302026/07/19 11:28:22 OK 20260628120000_add_object_size_and_stats.sql (1.91ms)6312026/07/19 11:28:22 goose: successfully migrated database to version: 202606281200006322026/07/19 11:28:22 OK 20251218171726_add_pins.sql (1.84ms)6332026/07/19 11:28:22 INFO Received uploads request method=POST path=/api/pending_closures6342026/07/19 11:28:22 OK 20260628120000_add_object_size_and_stats.sql (1.95ms)6352026/07/19 11:28:22 goose: successfully migrated database to version: 202606281200006362026/07/19 11:28:22 OK 20251218171726_add_pins.sql (1.48ms)6372026/07/19 11:28:22 OK 20260628120000_add_object_size_and_stats.sql (2.28ms)6382026/07/19 11:28:22 goose: successfully migrated database to version: 202606281200006392026/07/19 11:28:22 OK 1_commit_pending_closure.sql (1.19ms)6402026/07/19 11:28:22 OK 1_commit_pending_closure.sql (1.68ms)6412026/07/19 11:28:22 OK 20260628120000_add_object_size_and_stats.sql (1.98ms)6422026/07/19 11:28:22 goose: successfully migrated database to version: 202606281200006432026/07/19 11:28:22 OK 2_object_stats_trigger.sql (400.75µs)6442026/07/19 11:28:22 goose: up to current file version: 26452026/07/19 11:28:22 OK 2_object_stats_trigger.sql (416.5µs)6462026/07/19 11:28:22 goose: up to current file version: 2647--- PASS: TestReadProxy404 (0.33s)6482026/07/19 11:28:22 OK 20260628120000_add_object_size_and_stats.sql (1.55ms)6492026/07/19 11:28:22 goose: successfully migrated database to version: 20260628120000650=== CONT TestGracefulShutdownDrainsInflight6512026/07/19 11:28:22 INFO Starting HTTP server address=127.0.0.1:598056522026/07/19 11:28:22 OK 1_commit_pending_closure.sql (1.21ms)6532026/07/19 11:28:22 OK 20260628120000_add_object_size_and_stats.sql (1.32ms)6542026/07/19 11:28:22 goose: successfully migrated database to version: 202606281200006552026/07/19 11:28:22 INFO Shutdown signal received, draining in-flight requests timeout=10s6562026/07/19 11:28:22 OK 1_commit_pending_closure.sql (1.18ms)6572026/07/19 11:28:22 OK 2_object_stats_trigger.sql (433.42µs)6582026/07/19 11:28:22 goose: up to current file version: 26592026/07/19 11:28:22 OK 2_object_stats_trigger.sql (250.5µs)6602026/07/19 11:28:22 goose: up to current file version: 26612026/07/19 11:28:22 OK 1_commit_pending_closure.sql (1.45ms)6622026/07/19 11:28:22 OK 1_commit_pending_closure.sql (1.33ms)6632026/07/19 11:28:22 OK 2_object_stats_trigger.sql (367.38µs)6642026/07/19 11:28:22 goose: up to current file version: 26652026/07/19 11:28:22 OK 2_object_stats_trigger.sql (386µs)6662026/07/19 11:28:22 goose: up to current file version: 26672026/07/19 11:28:22 OK 1_commit_pending_closure.sql (1.23ms)6682026/07/19 11:28:22 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"669--- PASS: TestService_AuthMiddleware (0.34s)670=== CONT TestGCTaskStore_Fail671--- PASS: TestGCTaskStore_Fail (0.00s)672=== CONT TestGCTaskStore_PhaseUpdates673--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)674=== CONT TestGCTaskStore_CompletedAllowsNewTask675--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)676=== CONT TestGCTaskStore_GetReturnsLatest677--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)678=== CONT TestGCTaskStore_GetEmpty679--- PASS: TestGCTaskStore_GetEmpty (0.00s)680=== CONT TestGCTaskStore_ConflictDifferentParams681--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)682=== CONT TestGCTaskStore_DeduplicateSameParams683--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)684=== CONT TestGCTaskStore_StartNew685--- PASS: TestGCTaskStore_StartNew (0.00s)6862026/07/19 11:28:22 OK 2_object_stats_trigger.sql (318.79µs)6872026/07/19 11:28:22 goose: up to current file version: 2688=== CONT TestOrphanedObjectsGCStressTest689--- PASS: TestService_healthCheckHandler (0.32s)690=== CONT TestReadProxyNarStreaming6912026/07/19 11:28:22 INFO Aborted multipart uploads count=0692{"timestamp":"2026-07-19T11:28:22.524955Z","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(7)"}6932026/07/19 11:28:22 INFO Created nix-cache-info in bucket bucket=bucket56942026/07/19 11:28:22 INFO Received uploads request method=POST path=/api/pending_closures6952026/07/19 11:28:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete6962026/07/19 11:28:22 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst697--- PASS: TestCompleteMultipartUnregistered (0.34s)698=== CONT TestReadProxyNarinfoAlreadyDecompressed6992026/07/19 11:28:22 WARN Force mode enabled - objects will be deleted immediately without grace period700--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.34s)701=== CONT TestReadProxyNarinfo7022026/07/19 11:28:22 INFO Received uploads request method=POST path=/api/pending_closures7032026/07/19 11:28:22 INFO Created nix-cache-info in bucket bucket=bucket97042026/07/19 11:28:22 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=07052026/07/19 11:28:22 INFO Vacuumed table table=pending_closures7062026/07/19 11:28:22 INFO Vacuumed table table=pending_objects7072026/07/19 11:28:22 INFO Vacuumed table table=multipart_uploads7082026/07/19 11:28:22 INFO Vacuumed table table=closures7092026/07/19 11:28:22 INFO Vacuumed table table=objects710--- PASS: TestGCMetrics (0.35s)711=== CONT TestIsValidCachePath712=== RUN TestIsValidCachePath/narinfo713=== PAUSE TestIsValidCachePath/narinfo714=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars715=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars716=== RUN TestIsValidCachePath/nar_zst717=== PAUSE TestIsValidCachePath/nar_zst718=== RUN TestIsValidCachePath/nar_xz719=== PAUSE TestIsValidCachePath/nar_xz720=== RUN TestIsValidCachePath/nar_bz2721=== PAUSE TestIsValidCachePath/nar_bz2722=== RUN TestIsValidCachePath/nar_uncompressed723=== PAUSE TestIsValidCachePath/nar_uncompressed724=== RUN TestIsValidCachePath/ls725=== PAUSE TestIsValidCachePath/ls726=== RUN TestIsValidCachePath/log727=== PAUSE TestIsValidCachePath/log728=== RUN TestIsValidCachePath/realisation729=== PAUSE TestIsValidCachePath/realisation730=== RUN TestIsValidCachePath/nix-cache-info731=== PAUSE TestIsValidCachePath/nix-cache-info732=== RUN TestIsValidCachePath/index.html733=== PAUSE TestIsValidCachePath/index.html734=== RUN TestIsValidCachePath/traversal_parent735=== PAUSE TestIsValidCachePath/traversal_parent736=== RUN TestIsValidCachePath/traversal_in_middle737=== PAUSE TestIsValidCachePath/traversal_in_middle738=== RUN TestIsValidCachePath/invalid_char_e739=== PAUSE TestIsValidCachePath/invalid_char_e740=== RUN TestIsValidCachePath/invalid_char_u741=== PAUSE TestIsValidCachePath/invalid_char_u742=== RUN TestIsValidCachePath/random_path743=== PAUSE TestIsValidCachePath/random_path744=== RUN TestIsValidCachePath/empty745=== PAUSE TestIsValidCachePath/empty746=== RUN TestIsValidCachePath/leading_slash747=== PAUSE TestIsValidCachePath/leading_slash748=== RUN TestIsValidCachePath/wrong_extension749=== PAUSE TestIsValidCachePath/wrong_extension750=== RUN TestIsValidCachePath/short_hash751=== PAUSE TestIsValidCachePath/short_hash752=== CONT TestParseSingleRange753=== RUN TestParseSingleRange/none754=== PAUSE TestParseSingleRange/none755=== RUN TestParseSingleRange/unknown_unit756=== PAUSE TestParseSingleRange/unknown_unit757=== RUN TestParseSingleRange/multi-range_ignored758=== PAUSE TestParseSingleRange/multi-range_ignored759=== RUN TestParseSingleRange/malformed_no_dash760=== PAUSE TestParseSingleRange/malformed_no_dash761=== RUN TestParseSingleRange/malformed_both_empty762=== PAUSE TestParseSingleRange/malformed_both_empty763=== RUN TestParseSingleRange/malformed_end_before_start764=== PAUSE TestParseSingleRange/malformed_end_before_start765=== RUN TestParseSingleRange/closed766=== PAUSE TestParseSingleRange/closed767=== RUN TestParseSingleRange/open-ended768=== PAUSE TestParseSingleRange/open-ended769=== RUN TestParseSingleRange/end_clamped_to_size770=== PAUSE TestParseSingleRange/end_clamped_to_size771=== RUN TestParseSingleRange/suffix772=== PAUSE TestParseSingleRange/suffix773=== RUN TestParseSingleRange/suffix_exceeds_size774=== PAUSE TestParseSingleRange/suffix_exceeds_size775=== RUN TestParseSingleRange/single_byte776=== PAUSE TestParseSingleRange/single_byte777=== RUN TestParseSingleRange/start_past_EOF778=== PAUSE TestParseSingleRange/start_past_EOF779=== RUN TestParseSingleRange/start_far_past_EOF780=== PAUSE TestParseSingleRange/start_far_past_EOF781=== CONT TestResurrectedObjectNotDeleted7822026/07/19 11:28:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete783--- PASS: TestGracefulShutdownDrainsInflight (0.07s)784=== CONT TestUploadHandlersRejectOversizedBody785=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure786=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure787=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart788=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart789=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts790=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts791=== CONT TestService_createPendingClosureHandler792=== NAME TestNARDeduplicationMetadataUploadBug793 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-3323-2004179726/TestNARDeduplicationMetadataUploadBug1969659956/001/store/n67ip0528rbpcijrw7qdlx11d1lxaq9d-file1.txt7942026/07/19 11:28:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7952026/07/19 11:28:22 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=OWMyMGJjZTAtZjEwYS00OThmLWFiODgtMWVjNmJhMTQyODdjLmYzMGVlMzVkLWZlMzUtNDMyYy1hZTM5LTY2NWNkODBlZjRkYngxNzg0NDYwNTAyNTMyMTAxMDAw parts=107962026/07/19 11:28:22 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7972026/07/19 11:28:22 INFO Completed upload id=17982026/07/19 11:28:22 INFO Received uploads request method=POST path=/api/pending_closures7992026/07/19 11:28:22 INFO Received uploads request method=POST path=/api/pending_closures8002026/07/19 11:28:22 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo8012026/07/19 11:28:22 WARN Found objects in DB but missing from S3, will re-upload count=1802--- PASS: TestService_verifyS3Integrity (0.51s)803=== CONT TestService_cleanupPendingClosuresHandler8042026/07/19 11:28:22 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"8052026-07-19 11:28:22.742 UTC [3482] ERROR: relation "goose_db_version" does not exist at character 368062026-07-19 11:28:22.742 UTC [3482] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8072026/07/19 11:28:22 INFO Received uploads request method=POST path=/api/pending_closures8082026-07-19 11:28:22.745 UTC [3483] ERROR: relation "goose_db_version" does not exist at character 368092026-07-19 11:28:22.745 UTC [3483] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8102026-07-19 11:28:22.746 UTC [3484] ERROR: relation "goose_db_version" does not exist at character 368112026-07-19 11:28:22.746 UTC [3484] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8122026-07-19 11:28:22.749 UTC [3485] ERROR: relation "goose_db_version" does not exist at character 368132026-07-19 11:28:22.749 UTC [3485] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8142026/07/19 11:28:22 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8152026/07/19 11:28:22 INFO Uploading n67ip0528rbpcijrw7qdlx11d1lxaq9d-file1.txt (160B)8162026/07/19 11:28:22 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"8172026/07/19 11:28:22 WARN Failed to register uploaded object key=n67ip0528rbpcijrw7qdlx11d1lxaq9d.ls error="server returned 404: 404 page not found\n"8182026/07/19 11:28:22 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign8192026/07/19 11:28:22 INFO Signed narinfos id=1 count=18202026/07/19 11:28:22 INFO Uploading 1 narinfos8212026/07/19 11:28:22 WARN Failed to register uploaded object key=n67ip0528rbpcijrw7qdlx11d1lxaq9d.narinfo error="server returned 404: 404 page not found\n"8222026/07/19 11:28:22 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8232026/07/19 11:28:22 INFO Completed upload id=18242026/07/19 11:28:22 INFO Upload complete. (121ms)825=== NAME TestNARDeduplicationMetadataUploadBug826 metadata_upload_test.go:54: Retrieved narinfo from S3:827 StorePath: /nix/var/nix/builds/nix-3323-2004179726/TestNARDeduplicationMetadataUploadBug1969659956/001/store/n67ip0528rbpcijrw7qdlx11d1lxaq9d-file1.txt828 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst829 Compression: zstd830 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf831 NarSize: 160832 References: 833 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf8342026/07/19 11:28:22 OK 20241026095416_initial_model.sql (8.25ms)8352026/07/19 11:28:22 OK 20241026095416_initial_model.sql (8.48ms)8362026/07/19 11:28:22 OK 20251210153512_drop_unused_gin_index.sql (830.92µs)8372026/07/19 11:28:22 OK 20251210153512_drop_unused_gin_index.sql (910.92µs)838 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)839 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):840 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}8412026/07/19 11:28:22 OK 20241026095416_initial_model.sql (9.12ms)8422026/07/19 11:28:22 OK 20241026095416_initial_model.sql (9.97ms)8432026/07/19 11:28:22 OK 20251218171726_add_pins.sql (1.76ms)8442026/07/19 11:28:22 OK 20251210153512_drop_unused_gin_index.sql (1.43ms)8452026/07/19 11:28:22 OK 20251210153512_drop_unused_gin_index.sql (1.36ms)846=== NAME TestClientCADerivations847 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-3323-2004179726/TestClientCADerivations4039898766/001/store/m40k0c6zyl5d81p2s23g2inxjqkfq15b-ca-test8482026/07/19 11:28:22 OK 20251218171726_add_pins.sql (2.68ms)8492026/07/19 11:28:22 OK 20251218171726_add_pins.sql (1.96ms)8502026/07/19 11:28:22 OK 20251218171726_add_pins.sql (1.68ms)8512026/07/19 11:28:22 OK 20260628120000_add_object_size_and_stats.sql (3.51ms)8522026/07/19 11:28:22 goose: successfully migrated database to version: 202606281200008532026/07/19 11:28:22 OK 20260628120000_add_object_size_and_stats.sql (3.15ms)8542026/07/19 11:28:22 goose: successfully migrated database to version: 202606281200008552026/07/19 11:28:22 OK 1_commit_pending_closure.sql (1.24ms)8562026/07/19 11:28:22 OK 1_commit_pending_closure.sql (1.06ms)8572026/07/19 11:28:22 OK 2_object_stats_trigger.sql (267.92µs)8582026/07/19 11:28:22 goose: up to current file version: 28592026/07/19 11:28:22 OK 2_object_stats_trigger.sql (192.63µs)8602026/07/19 11:28:22 goose: up to current file version: 28612026/07/19 11:28:22 OK 20260628120000_add_object_size_and_stats.sql (5.23ms)8622026/07/19 11:28:22 goose: successfully migrated database to version: 202606281200008632026/07/19 11:28:22 OK 20260628120000_add_object_size_and_stats.sql (5.63ms)8642026/07/19 11:28:22 goose: successfully migrated database to version: 20260628120000865--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.27s)866=== CONT TestMultipartCleanup8672026/07/19 11:28:22 OK 1_commit_pending_closure.sql (1.75ms)8682026/07/19 11:28:22 OK 1_commit_pending_closure.sql (2.17ms)869--- PASS: TestReadProxyNarStreaming (0.27s)870=== CONT TestOrphanedObjectsGC8712026/07/19 11:28:22 OK 2_object_stats_trigger.sql (805.75µs)8722026/07/19 11:28:22 goose: up to current file version: 28732026/07/19 11:28:22 OK 2_object_stats_trigger.sql (758.5µs)8742026/07/19 11:28:22 goose: up to current file version: 2875--- PASS: TestReadProxyNarinfo (0.27s)876=== CONT TestObjectStatsTrigger8772026-07-19 11:28:22.802 UTC [3511] ERROR: relation "goose_db_version" does not exist at character 368782026-07-19 11:28:22.802 UTC [3511] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8792026/07/19 11:28:22 OK 20241026095416_initial_model.sql (6.92ms)8802026/07/19 11:28:22 OK 20251210153512_drop_unused_gin_index.sql (935.46µs)8812026/07/19 11:28:22 OK 20251218171726_add_pins.sql (1.67ms)8822026/07/19 11:28:22 OK 20260628120000_add_object_size_and_stats.sql (4.13ms)8832026/07/19 11:28:22 goose: successfully migrated database to version: 20260628120000884=== NAME TestClientCADerivations885 client_ca_test.go:139: Found 1 dependencies (including self)8862026/07/19 11:28:22 OK 1_commit_pending_closure.sql (1.61ms)887=== NAME TestNARDeduplicationMetadataUploadBug888 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-3323-2004179726/TestNARDeduplicationMetadataUploadBug1969659956/001/store/vjs8lrbq09vwrp9h5b2r05dqnawkdr48-file2.txt8892026/07/19 11:28:22 OK 2_object_stats_trigger.sql (950.13µs)8902026/07/19 11:28:22 goose: up to current file version: 2891--- PASS: TestResurrectedObjectNotDeleted (0.32s)892=== CONT TestService_AuthMiddleware_OIDC8932026/07/19 11:28:22 INFO OIDC provider initialized name=test8942026-07-19 11:28:22.877 UTC [3526] ERROR: relation "goose_db_version" does not exist at character 368952026-07-19 11:28:22.877 UTC [3526] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8962026/07/19 11:28:22 OK 20241026095416_initial_model.sql (7.31ms)8972026/07/19 11:28:22 OK 20251210153512_drop_unused_gin_index.sql (607.17µs)8982026/07/19 11:28:22 OK 20251218171726_add_pins.sql (1.48ms)8992026/07/19 11:28:22 OK 20260628120000_add_object_size_and_stats.sql (1.4ms)9002026/07/19 11:28:22 goose: successfully migrated database to version: 202606281200009012026/07/19 11:28:22 OK 1_commit_pending_closure.sql (1.01ms)9022026/07/19 11:28:22 OK 2_object_stats_trigger.sql (385.21µs)9032026/07/19 11:28:22 goose: up to current file version: 29042026/07/19 11:28:22 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9052026/07/19 11:28:22 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9062026/07/19 11:28:22 INFO Received uploads request method=POST path=/api/pending_closures9072026/07/19 11:28:22 INFO Received uploads request method=POST path=/api/pending_closures9082026/07/19 11:28:22 INFO Received uploads request method=POST path=/api/pending_closures9092026/07/19 11:28:22 INFO Received uploads request method=POST path=/api/pending_closures9102026/07/19 11:28:22 INFO Received uploads request method=POST path=/api/pending_closures9112026/07/19 11:28:22 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)9122026/07/19 11:28:22 WARN Failed to register uploaded object key=vjs8lrbq09vwrp9h5b2r05dqnawkdr48.ls error="server returned 404: 404 page not found\n"9132026/07/19 11:28:22 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign9142026/07/19 11:28:22 INFO Signed narinfos id=2 count=19152026/07/19 11:28:22 INFO Uploading 1 narinfos9162026/07/19 11:28:22 WARN Failed to register uploaded object key=vjs8lrbq09vwrp9h5b2r05dqnawkdr48.narinfo error="server returned 404: 404 page not found\n"9172026/07/19 11:28:22 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete9182026/07/19 11:28:22 INFO Completed upload id=29192026/07/19 11:28:22 INFO Upload complete. (87ms)920=== NAME TestNARDeduplicationMetadataUploadBug921 metadata_upload_test.go:76: Retrieved narinfo from S3:922 StorePath: /nix/var/nix/builds/nix-3323-2004179726/TestNARDeduplicationMetadataUploadBug1969659956/001/store/vjs8lrbq09vwrp9h5b2r05dqnawkdr48-file2.txt923 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst924 Compression: zstd925 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf926 NarSize: 160927 References: 928 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf929 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)930 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):931 {"version":1,"root":{"type":"regular","size":44}}932--- PASS: TestNARDeduplicationMetadataUploadBug (0.76s)933=== CONT TestCacheStatsHandler9342026/07/19 11:28:22 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9352026/07/19 11:28:22 INFO Uploading m40k0c6zyl5d81p2s23g2inxjqkfq15b-ca-test (144B)9362026/07/19 11:28:22 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"9372026/07/19 11:28:22 WARN Failed to register uploaded object key=log/1hs6p21ybn841q6k8hsfwf7xbbhcb6y2-ca-test.drv error="server returned 404: 404 page not found\n"9382026/07/19 11:28:22 WARN Failed to register uploaded object key=m40k0c6zyl5d81p2s23g2inxjqkfq15b.ls error="server returned 404: 404 page not found\n"9392026/07/19 11:28:22 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9402026/07/19 11:28:22 INFO Signed narinfos id=1 count=19412026/07/19 11:28:22 INFO Uploading 1 narinfos9422026/07/19 11:28:22 WARN Failed to register uploaded object key=m40k0c6zyl5d81p2s23g2inxjqkfq15b.narinfo error="server returned 404: 404 page not found\n"9432026/07/19 11:28:22 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9442026/07/19 11:28:22 INFO Completed upload id=19452026/07/19 11:28:22 INFO Upload complete. (118ms)946=== NAME TestClientCADerivations947 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-3323-2004179726/TestClientCADerivations4039898766/001/store/m40k0c6zyl5d81p2s23g2inxjqkfq15b-ca-test948 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst949 Compression: zstd950 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n951 NarSize: 144952 References: 953 Deriver: /nix/var/nix/builds/nix-3323-2004179726/TestClientCADerivations4039898766/001/store/1hs6p21ybn841q6k8hsfwf7xbbhcb6y2-ca-test.drv954 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n955 client_ca_test.go:185: Checking for realisation files in S3...956 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations957 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache9582026/07/19 11:28:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9592026/07/19 11:28:23 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=OWMyMGJjZTAtZjEwYS00OThmLWFiODgtMWVjNmJhMTQyODdjLjIxMWM5M2RmLWZkNjktNGVmNi1hNzhlLWQwOTZkNTgxYjI3ZHgxNzg0NDYwNTAyOTA1NTAxMDAw parts=109602026/07/19 11:28:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9612026-07-19 11:28:23.015 UTC [3537] ERROR: relation "goose_db_version" does not exist at character 369622026-07-19 11:28:23.015 UTC [3537] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC963 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket5?endpoint=http://localhost:59785®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-3323-2004179726/TestClientCADerivations4039898766/001/store'964 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 19652026/07/19 11:28:23 INFO Completed upload id=19662026/07/19 11:28:23 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009672026/07/19 11:28:23 INFO Received uploads request method=POST path=/api/pending_closures9682026/07/19 11:28:23 INFO Starting cleanup of old closures method=DELETE path=/api/closures969--- PASS: TestClientCADerivations (0.83s)970=== CONT TestCacheConfigHandler971=== RUN TestCacheConfigHandler/full_config,_no_issuer972=== PAUSE TestCacheConfigHandler/full_config,_no_issuer973=== RUN TestCacheConfigHandler/no_cache_url_configured974=== PAUSE TestCacheConfigHandler/no_cache_url_configured975=== RUN TestCacheConfigHandler/no_signing_keys976=== PAUSE TestCacheConfigHandler/no_signing_keys977=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator978=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator979=== CONT TestClientWithDependencies9802026/07/19 11:28:23 INFO Aborted multipart uploads count=09812026/07/19 11:28:23 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=09822026/07/19 11:28:23 INFO Vacuumed table table=pending_closures9832026/07/19 11:28:23 INFO Vacuumed table table=pending_objects9842026/07/19 11:28:23 INFO Vacuumed table table=multipart_uploads9852026/07/19 11:28:23 INFO Vacuumed table table=closures9862026/07/19 11:28:23 OK 20241026095416_initial_model.sql (11.06ms)9872026/07/19 11:28:23 INFO Vacuumed table table=objects9882026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (524.13µs)9892026/07/19 11:28:23 OK 20251218171726_add_pins.sql (905.33µs)9902026-07-19 11:28:23.043 UTC [3541] ERROR: relation "goose_db_version" does not exist at character 369912026-07-19 11:28:23.043 UTC [3541] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9922026-07-19 11:28:23.043 UTC [3542] ERROR: relation "goose_db_version" does not exist at character 369932026-07-19 11:28:23.043 UTC [3542] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9942026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (20.95ms)9952026/07/19 11:28:23 goose: successfully migrated database to version: 202606281200009962026/07/19 11:28:23 OK 1_commit_pending_closure.sql (1.25ms)9972026/07/19 11:28:23 OK 2_object_stats_trigger.sql (584.54µs)9982026/07/19 11:28:23 goose: up to current file version: 29992026/07/19 11:28:23 INFO Received cleanup request method=DELETE path=/api/pending_closures10002026/07/19 11:28:23 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010012026-07-19 11:28:23.068 UTC [3543] ERROR: relation "goose_db_version" does not exist at character 3610022026-07-19 11:28:23.068 UTC [3543] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1003--- PASS: TestService_createPendingClosureHandler (0.46s)1004=== CONT TestGCBugBareHashReferences10052026/07/19 11:28:23 INFO Aborted multipart uploads count=010062026/07/19 11:28:23 INFO Received uploads request method=POST path=/api/pending_closures10072026/07/19 11:28:23 OK 20241026095416_initial_model.sql (22.58ms)10082026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (379.08µs)10092026/07/19 11:28:23 OK 20251218171726_add_pins.sql (803.29µs)10102026/07/19 11:28:23 INFO Received cleanup request method=DELETE path=/api/pending_closures10112026/07/19 11:28:23 INFO Aborted multipart uploads count=110122026/07/19 11:28:23 OK 20241026095416_initial_model.sql (28.12ms)10132026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (2.85ms)10142026/07/19 11:28:23 goose: successfully migrated database to version: 2026062812000010152026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (621.63µs)10162026/07/19 11:28:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10172026-07-19 11:28:23.090 UTC [3537] ERROR: Closure does not exist: id=110182026-07-19 11:28:23.090 UTC [3537] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE10192026-07-19 11:28:23.090 UTC [3537] STATEMENT: -- name: CommitPendingClosure :exec1020 SELECT commit_pending_closure($1::bigint)1021 1022--- PASS: TestService_cleanupPendingClosuresHandler (0.39s)1023=== CONT TestPinProtectsFromGC10242026/07/19 11:28:23 OK 20251218171726_add_pins.sql (1.53ms)10252026/07/19 11:28:23 OK 1_commit_pending_closure.sql (1.96ms)10262026/07/19 11:28:23 OK 2_object_stats_trigger.sql (1.1ms)10272026/07/19 11:28:23 goose: up to current file version: 210282026/07/19 11:28:23 OK 20241026095416_initial_model.sql (8.55ms)10292026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (532.58µs)10302026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (3.05ms)10312026/07/19 11:28:23 goose: successfully migrated database to version: 2026062812000010322026/07/19 11:28:23 OK 20251218171726_add_pins.sql (1.38ms)10332026/07/19 11:28:23 OK 1_commit_pending_closure.sql (2.13ms)10342026/07/19 11:28:23 OK 2_object_stats_trigger.sql (357.71µs)10352026/07/19 11:28:23 goose: up to current file version: 210362026/07/19 11:28:23 INFO Received uploads request method=POST path=/api/pending_closures10372026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (3.45ms)10382026/07/19 11:28:23 goose: successfully migrated database to version: 2026062812000010392026/07/19 11:28:23 OK 1_commit_pending_closure.sql (1.8ms)10402026/07/19 11:28:23 OK 2_object_stats_trigger.sql (382.58µs)10412026/07/19 11:28:23 goose: up to current file version: 21042--- PASS: TestObjectStatsTrigger (0.31s)1043=== CONT TestService_NativeMTLS10442026-07-19 11:28:23.168 UTC [3550] ERROR: relation "goose_db_version" does not exist at character 3610452026-07-19 11:28:23.168 UTC [3550] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1046=== NAME TestOrphanedObjectsGCStressTest1047 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1048 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion10492026/07/19 11:28:23 OK 20241026095416_initial_model.sql (19.71ms)10502026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (738.96µs)10512026/07/19 11:28:23 OK 20251218171726_add_pins.sql (1.09ms)10522026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (2.29ms)10532026/07/19 11:28:23 goose: successfully migrated database to version: 2026062812000010542026/07/19 11:28:23 OK 1_commit_pending_closure.sql (1.13ms)10552026/07/19 11:28:23 OK 2_object_stats_trigger.sql (357.96µs)10562026/07/19 11:28:23 goose: up to current file version: 21057=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1058=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1059=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1060=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1061=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1062=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1063=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1064=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1065=== CONT TestServerTLSConfig1066=== RUN TestServerTLSConfig/no_client_CA1067=== PAUSE TestServerTLSConfig/no_client_CA1068=== RUN TestServerTLSConfig/missing_CA_file1069=== PAUSE TestServerTLSConfig/missing_CA_file1070=== RUN TestServerTLSConfig/not_a_PEM_file1071=== PAUSE TestServerTLSConfig/not_a_PEM_file1072=== CONT TestPresignedUploadRegisteredBeforeCommit10732026/07/19 11:28:23 INFO Received cleanup request method=DELETE path=/api/pending_closures10742026/07/19 11:28:23 INFO Aborted multipart uploads count=11075--- PASS: TestMultipartCleanup (0.42s)1076=== CONT TestParseSize1077--- PASS: TestParseSize (0.00s)1078=== CONT TestService_Rustfstest1079=== NAME TestOrphanedObjectsGCStressTest1080 orphaned_objects_gc_test.go:509: Stress test completed successfully:1081 orphaned_objects_gc_test.go:510: - Active objects preserved: 201082 orphaned_objects_gc_test.go:511: - Objects deleted: 2101083 orphaned_objects_gc_test.go:512: - Total GC'd: 2101084--- PASS: TestOrphanedObjectsGCStressTest (0.74s)1085=== CONT TestReadProxyRootRedirectsToIndexHTML10862026-07-19 11:28:23.288 UTC [3557] ERROR: relation "goose_db_version" does not exist at character 3610872026-07-19 11:28:23.288 UTC [3557] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10882026/07/19 11:28:23 OK 20241026095416_initial_model.sql (7.76ms)10892026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (371.17µs)10902026/07/19 11:28:23 OK 20251218171726_add_pins.sql (1.03ms)1091=== NAME TestOrphanedObjectsGC1092 orphaned_objects_gc_test.go:290: GC Test Summary:1093 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1094 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1095 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1096 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1097 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1098--- PASS: TestOrphanedObjectsGC (0.53s)1099=== CONT TestReadProxyRangeRequest11002026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (15.77ms)11012026/07/19 11:28:23 goose: successfully migrated database to version: 2026062812000011022026/07/19 11:28:23 OK 1_commit_pending_closure.sql (862.29µs)11032026/07/19 11:28:23 OK 2_object_stats_trigger.sql (395.21µs)11042026/07/19 11:28:23 goose: up to current file version: 21105--- PASS: TestCacheStatsHandler (0.38s)1106=== CONT TestReadProxyDisabled11072026-07-19 11:28:23.360 UTC [3562] ERROR: relation "goose_db_version" does not exist at character 3611082026-07-19 11:28:23.360 UTC [3562] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11092026-07-19 11:28:23.360 UTC [3563] ERROR: relation "goose_db_version" does not exist at character 3611102026-07-19 11:28:23.360 UTC [3563] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11112026/07/19 11:28:23 OK 20241026095416_initial_model.sql (7.53ms)11122026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (624.58µs)11132026/07/19 11:28:23 OK 20251218171726_add_pins.sql (1.44ms)11142026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (2.78ms)11152026/07/19 11:28:23 goose: successfully migrated database to version: 2026062812000011162026/07/19 11:28:23 OK 20241026095416_initial_model.sql (9.22ms)11172026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (312.17µs)11182026/07/19 11:28:23 OK 1_commit_pending_closure.sql (1.57ms)11192026/07/19 11:28:23 OK 2_object_stats_trigger.sql (217.04µs)11202026/07/19 11:28:23 goose: up to current file version: 211212026/07/19 11:28:23 OK 20251218171726_add_pins.sql (801.58µs)11222026/07/19 11:28:23 INFO Created nix-cache-info in bucket bucket=bucket2411232026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (7.26ms)11242026/07/19 11:28:23 goose: successfully migrated database to version: 2026062812000011252026/07/19 11:28:23 OK 1_commit_pending_closure.sql (1.75ms)11262026/07/19 11:28:23 OK 2_object_stats_trigger.sql (680.33µs)11272026/07/19 11:28:23 goose: up to current file version: 211282026-07-19 11:28:23.419 UTC [3565] ERROR: relation "goose_db_version" does not exist at character 3611292026-07-19 11:28:23.419 UTC [3565] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11302026/07/19 11:28:23 OK 20241026095416_initial_model.sql (42.05ms)11312026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (663.46µs)11322026/07/19 11:28:23 OK 20251218171726_add_pins.sql (804.83µs)11332026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (2.65ms)11342026/07/19 11:28:23 goose: successfully migrated database to version: 2026062812000011352026/07/19 11:28:23 OK 1_commit_pending_closure.sql (1.18ms)11362026/07/19 11:28:23 OK 2_object_stats_trigger.sql (492.71µs)11372026/07/19 11:28:23 goose: up to current file version: 211382026/07/19 11:28:23 INFO Created nix-cache-info in bucket bucket=bucket2611392026-07-19 11:28:23.497 UTC [3569] ERROR: relation "goose_db_version" does not exist at character 3611402026-07-19 11:28:23.497 UTC [3569] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11412026/07/19 11:28:23 OK 20241026095416_initial_model.sql (10.05ms)11422026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (4.96ms)11432026/07/19 11:28:23 OK 20251218171726_add_pins.sql (5.72ms)11442026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (20.01ms)11452026/07/19 11:28:23 goose: successfully migrated database to version: 2026062812000011462026/07/19 11:28:23 OK 1_commit_pending_closure.sql (2.02ms)11472026/07/19 11:28:23 OK 2_object_stats_trigger.sql (338.25µs)11482026/07/19 11:28:23 goose: up to current file version: 211492026/07/19 11:28:23 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11502026/07/19 11:28:23 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1151--- PASS: TestService_NativeMTLS (0.44s)1152=== CONT TestIsValidUploadKey1153=== RUN TestIsValidUploadKey/narinfo1154=== PAUSE TestIsValidUploadKey/narinfo1155=== RUN TestIsValidUploadKey/nar_zst1156=== PAUSE TestIsValidUploadKey/nar_zst1157=== RUN TestIsValidUploadKey/nar_xz1158=== PAUSE TestIsValidUploadKey/nar_xz1159=== RUN TestIsValidUploadKey/nar_plain1160=== PAUSE TestIsValidUploadKey/nar_plain1161=== RUN TestIsValidUploadKey/listing1162=== PAUSE TestIsValidUploadKey/listing1163=== RUN TestIsValidUploadKey/build_log1164=== PAUSE TestIsValidUploadKey/build_log1165=== RUN TestIsValidUploadKey/build_log_home-manager_file1166=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1167=== RUN TestIsValidUploadKey/build_log_plus_in_name1168=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1169=== RUN TestIsValidUploadKey/build_log_question_mark1170=== PAUSE TestIsValidUploadKey/build_log_question_mark1171=== RUN TestIsValidUploadKey/build_log_equals1172=== PAUSE TestIsValidUploadKey/build_log_equals1173=== RUN TestIsValidUploadKey/realisation1174=== PAUSE TestIsValidUploadKey/realisation1175=== RUN TestIsValidUploadKey/realisation_plus_in_output1176=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1177=== RUN TestIsValidUploadKey/nix-cache-info1178=== PAUSE TestIsValidUploadKey/nix-cache-info1179=== RUN TestIsValidUploadKey/index.html1180=== PAUSE TestIsValidUploadKey/index.html1181=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1182=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1183=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1184=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1185=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1186=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1187=== RUN TestIsValidUploadKey/traversal1188=== PAUSE TestIsValidUploadKey/traversal1189=== RUN TestIsValidUploadKey/traversal_nar1190=== PAUSE TestIsValidUploadKey/traversal_nar1191=== RUN TestIsValidUploadKey/absolute1192=== PAUSE TestIsValidUploadKey/absolute1193=== RUN TestIsValidUploadKey/empty_key1194=== PAUSE TestIsValidUploadKey/empty_key1195=== RUN TestIsValidUploadKey/unknown_type1196=== PAUSE TestIsValidUploadKey/unknown_type1197=== 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 TestMetricsInventory12072026-07-19 11:28:23.566 UTC [3576] ERROR: relation "goose_db_version" does not exist at character 3612082026-07-19 11:28:23.566 UTC [3576] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12092026-07-19 11:28:23.566 UTC [3577] ERROR: relation "goose_db_version" does not exist at character 3612102026-07-19 11:28:23.566 UTC [3577] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1211=== NAME TestPinProtectsFromGC1212 client_integration_test.go:646: Pinned store path: /nix/var/nix/builds/nix-3323-2004179726/TestPinProtectsFromGC1955505907/001/store/04jnm0mc5b3ws0aifdj72ldvgzraf49x-pinned-file.txt1213 client_integration_test.go:647: Unpinned store path: /nix/var/nix/builds/nix-3323-2004179726/TestPinProtectsFromGC1955505907/001/store/cvpv2m1g6lcdric314allk650afq0x9m-unpinned-file.txt12142026/07/19 11:28:23 OK 20241026095416_initial_model.sql (6.45ms)12152026/07/19 11:28:23 OK 20241026095416_initial_model.sql (7.21ms)12162026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (463.38µs)12172026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (490.54µs)12182026/07/19 11:28:23 OK 20251218171726_add_pins.sql (772.5µs)12192026/07/19 11:28:23 OK 20251218171726_add_pins.sql (800.42µs)12202026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (2.09ms)12212026/07/19 11:28:23 goose: successfully migrated database to version: 2026062812000012222026/07/19 11:28:23 OK 1_commit_pending_closure.sql (1.1ms)12232026/07/19 11:28:23 OK 2_object_stats_trigger.sql (203.79µs)12242026/07/19 11:28:23 goose: up to current file version: 212252026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (4.69ms)12262026/07/19 11:28:23 goose: successfully migrated database to version: 202606281200001227--- PASS: TestService_Rustfstest (0.39s)1228=== CONT TestCompletedNarNotReofferedAcrossClosures12292026/07/19 11:28:23 OK 1_commit_pending_closure.sql (2.06ms)12302026/07/19 11:28:23 OK 2_object_stats_trigger.sql (361.83µs)12312026/07/19 11:28:23 goose: up to current file version: 212322026/07/19 11:28:23 INFO Received uploads request method=POST path=/api/pending_closures12332026/07/19 11:28:23 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst12342026/07/19 11:28:23 INFO Received uploads request method=POST path=/api/pending_closures1235--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.41s)1236=== CONT TestReadProxyHead12372026-07-19 11:28:23.617 UTC [3585] ERROR: relation "goose_db_version" does not exist at character 3612382026-07-19 11:28:23.617 UTC [3585] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1239--- PASS: TestGCBugBareHashReferences (0.55s)1240=== CONT TestReadProxyConditionalGet1241=== NAME TestClientWithDependencies1242 client_integration_test.go:593: Built derivation: /nix/var/nix/builds/nix-3323-2004179726/TestClientWithDependencies145710838/001/store/9yj6vgqim64vmqxvfydlcmxkz1wrnp0i-test-script12432026/07/19 11:28:23 OK 20241026095416_initial_model.sql (8.64ms)12442026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (472.63µs)12452026/07/19 11:28:23 OK 20251218171726_add_pins.sql (2.81ms)12462026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (3.35ms)12472026/07/19 11:28:23 goose: successfully migrated database to version: 2026062812000012482026/07/19 11:28:23 OK 1_commit_pending_closure.sql (860.17µs)12492026/07/19 11:28:23 OK 2_object_stats_trigger.sql (268.13µs)12502026/07/19 11:28:23 goose: up to current file version: 21251--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.38s)1252=== CONT TestCompleteMultipartUpload_ErrorButObjectExists12532026-07-19 11:28:23.648 UTC [3591] ERROR: relation "goose_db_version" does not exist at character 3612542026-07-19 11:28:23.648 UTC [3591] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12552026/07/19 11:28:23 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12562026/07/19 11:28:23 OK 20241026095416_initial_model.sql (10.5ms)12572026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (447.04µs)12582026/07/19 11:28:23 OK 20251218171726_add_pins.sql (782.58µs)1259=== NAME TestClientWithDependencies1260 client_integration_test.go:595: Found 1 dependencies (including self)12612026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (3.65ms)12622026/07/19 11:28:23 goose: successfully migrated database to version: 2026062812000012632026/07/19 11:28:23 OK 1_commit_pending_closure.sql (793.58µs)12642026/07/19 11:28:23 OK 2_object_stats_trigger.sql (199.54µs)12652026/07/19 11:28:23 goose: up to current file version: 21266--- PASS: TestReadProxyRangeRequest (0.36s)1267=== CONT TestService_AuthMiddleware_MTLSBoundSubjects12682026-07-19 11:28:23.688 UTC [3600] ERROR: relation "goose_db_version" does not exist at character 3612692026-07-19 11:28:23.688 UTC [3600] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12702026/07/19 11:28:23 INFO Received uploads request method=POST path=/api/pending_closures12712026/07/19 11:28:23 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12722026/07/19 11:28:23 INFO Uploading 04jnm0mc5b3ws0aifdj72ldvgzraf49x-pinned-file.txt (128B)12732026/07/19 11:28:23 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"12742026/07/19 11:28:23 WARN Failed to register uploaded object key=04jnm0mc5b3ws0aifdj72ldvgzraf49x.ls error="server returned 404: 404 page not found\n"12752026/07/19 11:28:23 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12762026/07/19 11:28:23 INFO Signed narinfos id=1 count=112772026/07/19 11:28:23 INFO Uploading 1 narinfos12782026/07/19 11:28:23 WARN Failed to register uploaded object key=04jnm0mc5b3ws0aifdj72ldvgzraf49x.narinfo error="server returned 404: 404 page not found\n"12792026/07/19 11:28:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12802026/07/19 11:28:23 INFO Completed upload id=112812026/07/19 11:28:23 INFO Upload complete. (99ms)12822026/07/19 11:28:23 OK 20241026095416_initial_model.sql (9.93ms)12832026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (710.63µs)12842026/07/19 11:28:23 OK 20251218171726_add_pins.sql (1.8ms)12852026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (2.01ms)12862026/07/19 11:28:23 goose: successfully migrated database to version: 2026062812000012872026/07/19 11:28:23 OK 1_commit_pending_closure.sql (2.16ms)12882026/07/19 11:28:23 OK 2_object_stats_trigger.sql (4.05ms)12892026/07/19 11:28:23 goose: up to current file version: 21290--- PASS: TestReadProxyDisabled (0.40s)1291=== CONT TestService_ReadAuthMiddleware12922026/07/19 11:28:23 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12932026/07/19 11:28:23 INFO Received uploads request method=POST path=/api/pending_closures12942026/07/19 11:28:23 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12952026/07/19 11:28:23 INFO Uploading 9yj6vgqim64vmqxvfydlcmxkz1wrnp0i-test-script (136B)12962026/07/19 11:28:23 WARN Failed to register uploaded object key=log/p10vg3llalb1rl8j6ax7vw2ka4kjl261-test-script.drv error="server returned 404: 404 page not found\n"12972026/07/19 11:28:23 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"12982026/07/19 11:28:23 WARN Failed to register uploaded object key=9yj6vgqim64vmqxvfydlcmxkz1wrnp0i.ls error="server returned 404: 404 page not found\n"12992026/07/19 11:28:23 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13002026/07/19 11:28:23 INFO Signed narinfos id=1 count=113012026/07/19 11:28:23 INFO Uploading 1 narinfos13022026/07/19 11:28:23 WARN Failed to register uploaded object key=9yj6vgqim64vmqxvfydlcmxkz1wrnp0i.narinfo error="server returned 404: 404 page not found\n"13032026/07/19 11:28:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13042026/07/19 11:28:23 INFO Completed upload id=113052026/07/19 11:28:23 INFO Upload complete. (56ms)1306=== NAME TestClientWithDependencies1307 client_integration_test.go:597: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-3323-2004179726/TestClientWithDependencies145710838/001/store) requires matching store prefix1308--- PASS: TestClientWithDependencies (0.74s)1309=== CONT TestProxyWriteTimeout1310=== RUN TestProxyWriteTimeout/narinfo1311=== PAUSE TestProxyWriteTimeout/narinfo1312=== RUN TestProxyWriteTimeout/1_GiB_nar1313=== PAUSE TestProxyWriteTimeout/1_GiB_nar1314=== RUN TestProxyWriteTimeout/10_GiB_nar1315=== PAUSE TestProxyWriteTimeout/10_GiB_nar1316=== RUN TestProxyWriteTimeout/unknown_size1317=== PAUSE TestProxyWriteTimeout/unknown_size1318=== CONT TestReadProxyInvalidPath13192026/07/19 11:28:23 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13202026/07/19 11:28:23 INFO Received uploads request method=POST path=/api/pending_closures13212026/07/19 11:28:23 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13222026/07/19 11:28:23 INFO Uploading cvpv2m1g6lcdric314allk650afq0x9m-unpinned-file.txt (128B)13232026/07/19 11:28:23 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"13242026/07/19 11:28:23 WARN Failed to register uploaded object key=cvpv2m1g6lcdric314allk650afq0x9m.ls error="server returned 404: 404 page not found\n"13252026/07/19 11:28:23 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13262026/07/19 11:28:23 INFO Signed narinfos id=2 count=113272026/07/19 11:28:23 INFO Uploading 1 narinfos13282026/07/19 11:28:23 WARN Failed to register uploaded object key=cvpv2m1g6lcdric314allk650afq0x9m.narinfo error="server returned 404: 404 page not found\n"13292026/07/19 11:28:23 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13302026/07/19 11:28:23 INFO Completed upload id=213312026/07/19 11:28:23 INFO Upload complete. (79ms)13322026-07-19 11:28:23.854 UTC [3615] ERROR: relation "goose_db_version" does not exist at character 3613332026-07-19 11:28:23.854 UTC [3615] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13342026/07/19 11:28:23 INFO Received create pin request method=POST path=/api/pins/myapp13352026/07/19 11:28:23 OK 20241026095416_initial_model.sql (12.31ms)13362026/07/19 11:28:23 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-3323-2004179726/TestPinProtectsFromGC1955505907/001/store/04jnm0mc5b3ws0aifdj72ldvgzraf49x-pinned-file.txt narinfo_key=04jnm0mc5b3ws0aifdj72ldvgzraf49x.narinfo13372026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (486.54µs)13382026/07/19 11:28:23 INFO Starting cleanup of old closures method=DELETE path=/api/closures13392026/07/19 11:28:23 INFO Garbage collection started13402026/07/19 11:28:23 OK 20251218171726_add_pins.sql (842.33µs)13412026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (12.94ms)13422026/07/19 11:28:23 goose: successfully migrated database to version: 2026062812000013432026/07/19 11:28:23 OK 1_commit_pending_closure.sql (1.47ms)13442026/07/19 11:28:23 OK 2_object_stats_trigger.sql (351.08µs)13452026/07/19 11:28:23 goose: up to current file version: 213462026/07/19 11:28:23 INFO Aborted multipart uploads count=013472026/07/19 11:28:23 WARN Force mode enabled - objects will be deleted immediately without grace period1348--- PASS: TestMetricsInventory (0.35s)1349=== CONT TestClientIntegration13502026-07-19 11:28:23.919 UTC [3620] ERROR: relation "goose_db_version" does not exist at character 3613512026-07-19 11:28:23.919 UTC [3620] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13522026-07-19 11:28:23.931 UTC [3621] ERROR: relation "goose_db_version" does not exist at character 3613532026-07-19 11:28:23.931 UTC [3621] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13542026-07-19 11:28:23.933 UTC [3622] ERROR: relation "goose_db_version" does not exist at character 3613552026-07-19 11:28:23.933 UTC [3622] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13562026/07/19 11:28:23 OK 20241026095416_initial_model.sql (12.3ms)13572026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (352.04µs)13582026/07/19 11:28:23 OK 20251218171726_add_pins.sql (857.5µs)13592026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (7.15ms)13602026/07/19 11:28:23 goose: successfully migrated database to version: 2026062812000013612026/07/19 11:28:23 OK 1_commit_pending_closure.sql (1.27ms)13622026/07/19 11:28:23 OK 2_object_stats_trigger.sql (518.33µs)13632026/07/19 11:28:23 goose: up to current file version: 213642026/07/19 11:28:23 OK 20241026095416_initial_model.sql (5.47ms)13652026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (394.58µs)13662026/07/19 11:28:23 OK 20241026095416_initial_model.sql (5.11ms)13672026/07/19 11:28:23 OK 20251218171726_add_pins.sql (863.5µs)1368--- PASS: TestReadProxyHead (0.35s)1369=== CONT TestClientMultipleUploads13702026/07/19 11:28:23 OK 20251210153512_drop_unused_gin_index.sql (607.33µs)13712026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (2.17ms)13722026/07/19 11:28:23 goose: successfully migrated database to version: 2026062812000013732026/07/19 11:28:23 OK 20251218171726_add_pins.sql (2.01ms)13742026/07/19 11:28:23 OK 1_commit_pending_closure.sql (1.24ms)13752026/07/19 11:28:23 OK 2_object_stats_trigger.sql (203.88µs)13762026/07/19 11:28:23 goose: up to current file version: 213772026/07/19 11:28:23 INFO Received uploads request method=POST path=/api/pending_closures13782026/07/19 11:28:23 OK 20260628120000_add_object_size_and_stats.sql (6.48ms)13792026/07/19 11:28:23 goose: successfully migrated database to version: 2026062812000013802026/07/19 11:28:23 OK 1_commit_pending_closure.sql (1.3ms)13812026/07/19 11:28:23 OK 2_object_stats_trigger.sql (249.75µs)13822026/07/19 11:28:23 goose: up to current file version: 21383--- PASS: TestReadProxyConditionalGet (0.36s)1384=== CONT TestService_AuthMiddleware_MTLSProxyHeader13852026-07-19 11:28:23.990 UTC [3626] ERROR: relation "goose_db_version" does not exist at character 3613862026-07-19 11:28:23.990 UTC [3626] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13872026/07/19 11:28:24 OK 20241026095416_initial_model.sql (13.25ms)13882026/07/19 11:28:24 OK 20251210153512_drop_unused_gin_index.sql (996.88µs)13892026/07/19 11:28:24 OK 20251218171726_add_pins.sql (7.02ms)13902026/07/19 11:28:24 OK 20260628120000_add_object_size_and_stats.sql (4.48ms)13912026/07/19 11:28:24 goose: successfully migrated database to version: 2026062812000013922026/07/19 11:28:24 OK 1_commit_pending_closure.sql (1.03ms)13932026/07/19 11:28:24 OK 2_object_stats_trigger.sql (281.46µs)13942026/07/19 11:28:24 goose: up to current file version: 213952026/07/19 11:28:24 INFO Received uploads request method=POST path=/api/pending_closures13962026-07-19 11:28:24.030 UTC [3628] ERROR: relation "goose_db_version" does not exist at character 3613972026-07-19 11:28:24.030 UTC [3628] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13982026/07/19 11:28:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1399{"timestamp":"2026-07-19T11:28:24.053179Z","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)"}1400{"timestamp":"2026-07-19T11:28:24.053199Z","level":"ERROR","fields":{"message":"complete_multipart_upload etag err client=Some(\"deadbeef\"), stored=\"\", part_id=1, bucket=bucket37, 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)"}14012026/07/19 11:28:24 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=OWMyMGJjZTAtZjEwYS00OThmLWFiODgtMWVjNmJhMTQyODdjLmM4NGE1NjVjLTBmYmMtNDJiZS1hNTZiLTc1Yzk2NGQ1MmUwZXgxNzg0NDYwNTA0MDM4NzY2MDAw14022026/07/19 11:28:24 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OWMyMGJjZTAtZjEwYS00OThmLWFiODgtMWVjNmJhMTQyODdjLmM4NGE1NjVjLTBmYmMtNDJiZS1hNTZiLTc1Yzk2NGQ1MmUwZXgxNzg0NDYwNTA0MDM4NzY2MDAw parts=11403--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.41s)1404=== CONT TestClientErrorHandling1405=== RUN TestClientErrorHandling/InvalidStorePath1406=== PAUSE TestClientErrorHandling/InvalidStorePath1407=== RUN TestClientErrorHandling/InvalidAuthToken1408=== PAUSE TestClientErrorHandling/InvalidAuthToken1409=== RUN TestClientErrorHandling/ServerNotAvailable1410=== PAUSE TestClientErrorHandling/ServerNotAvailable1411=== CONT TestRedundantMultipartUpload14122026/07/19 11:28:24 OK 20241026095416_initial_model.sql (18.19ms)14132026/07/19 11:28:24 OK 20251210153512_drop_unused_gin_index.sql (1.04ms)14142026/07/19 11:28:24 OK 20251218171726_add_pins.sql (2.57ms)14152026/07/19 11:28:24 OK 20260628120000_add_object_size_and_stats.sql (9.48ms)14162026/07/19 11:28:24 goose: successfully migrated database to version: 2026062812000014172026/07/19 11:28:24 OK 1_commit_pending_closure.sql (1.34ms)14182026/07/19 11:28:24 OK 2_object_stats_trigger.sql (290.83µs)14192026/07/19 11:28:24 goose: up to current file version: 214202026/07/19 11:28:24 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"14212026/07/19 11:28:24 WARN mTLS auth: bound subjects configured but subject DN unavailable14222026/07/19 11:28:24 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1423--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.40s)1424=== CONT TestIsValidCachePath/narinfo1425=== CONT TestParseSingleRange/none1426=== CONT TestIsValidCachePath/short_hash1427=== CONT TestIsValidCachePath/wrong_extension1428=== CONT TestIsValidCachePath/leading_slash1429=== CONT TestIsValidCachePath/empty1430=== CONT TestIsValidCachePath/random_path1431=== CONT TestIsValidCachePath/invalid_char_u1432=== CONT TestIsValidCachePath/invalid_char_e1433=== CONT TestIsValidCachePath/traversal_in_middle1434=== CONT TestIsValidCachePath/traversal_parent1435=== CONT TestIsValidCachePath/index.html1436=== CONT TestIsValidCachePath/nix-cache-info1437=== CONT TestIsValidCachePath/realisation1438=== CONT TestIsValidCachePath/log1439=== CONT TestIsValidCachePath/ls1440=== CONT TestIsValidCachePath/nar_uncompressed1441=== CONT TestIsValidCachePath/nar_bz21442=== CONT TestIsValidCachePath/nar_xz1443=== CONT TestIsValidCachePath/nar_zst1444=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1445--- PASS: TestIsValidCachePath (0.00s)1446 --- PASS: TestIsValidCachePath/narinfo (0.00s)1447 --- PASS: TestIsValidCachePath/short_hash (0.00s)1448 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1449 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1450 --- PASS: TestIsValidCachePath/empty (0.00s)1451 --- PASS: TestIsValidCachePath/random_path (0.00s)1452 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1453 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1454 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1455 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1456 --- PASS: TestIsValidCachePath/index.html (0.00s)1457 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1458 --- PASS: TestIsValidCachePath/realisation (0.00s)1459 --- PASS: TestIsValidCachePath/log (0.00s)1460 --- PASS: TestIsValidCachePath/ls (0.00s)1461 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1462 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1463 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1464 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1465 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1466=== CONT TestParseSingleRange/open-ended1467=== CONT TestParseSingleRange/start_far_past_EOF1468=== CONT TestParseSingleRange/start_past_EOF1469=== CONT TestParseSingleRange/single_byte1470=== CONT TestParseSingleRange/suffix_exceeds_size1471=== CONT TestParseSingleRange/suffix1472=== CONT TestParseSingleRange/end_clamped_to_size1473=== CONT TestParseSingleRange/malformed_both_empty1474=== CONT TestParseSingleRange/closed1475=== CONT TestParseSingleRange/malformed_end_before_start1476=== CONT TestParseSingleRange/multi-range_ignored1477=== CONT TestParseSingleRange/malformed_no_dash1478=== CONT TestParseSingleRange/unknown_unit1479--- PASS: TestParseSingleRange (0.00s)1480 --- PASS: TestParseSingleRange/none (0.00s)1481 --- PASS: TestParseSingleRange/open-ended (0.00s)1482 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1483 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1484 --- PASS: TestParseSingleRange/single_byte (0.00s)1485 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1486 --- PASS: TestParseSingleRange/suffix (0.00s)1487 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1488 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1489 --- PASS: TestParseSingleRange/closed (0.00s)1490 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1491 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1492 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1493 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1494=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure14952026/07/19 11:28:24 INFO Received uploads request method=POST path=/14962026-07-19 11:28:24.098 UTC [3632] ERROR: relation "goose_db_version" does not exist at character 3614972026-07-19 11:28:24.098 UTC [3632] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14982026/07/19 11:28:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14992026/07/19 11:28:24 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=OWMyMGJjZTAtZjEwYS00OThmLWFiODgtMWVjNmJhMTQyODdjLmQ0MzY5M2QyLTRjZDAtNDBjNy05NTE5LTU0ZjU4NDU4MzZiMngxNzg0NDYwNTAzOTYyNTU2MDAw parts=1215002026/07/19 11:28:24 INFO Received uploads request method=POST path=/api/pending_closures1501--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.52s)1502=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts15032026/07/19 11:28:24 INFO Received request for more parts method=POST path=/15042026/07/19 11:28:24 OK 20241026095416_initial_model.sql (8.91ms)15052026/07/19 11:28:24 OK 20251210153512_drop_unused_gin_index.sql (460.88µs)15062026/07/19 11:28:24 OK 20251218171726_add_pins.sql (930.04µs)1507=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart15082026/07/19 11:28:24 INFO Received complete multipart upload request method=POST path=/15092026-07-19 11:28:24.138 UTC [3633] ERROR: relation "goose_db_version" does not exist at character 3615102026-07-19 11:28:24.138 UTC [3633] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15112026/07/19 11:28:24 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=015122026/07/19 11:28:24 OK 20260628120000_add_object_size_and_stats.sql (26.68ms)15132026/07/19 11:28:24 goose: successfully migrated database to version: 202606281200001514=== CONT TestCacheConfigHandler/full_config,_no_issuer1515=== CONT TestCacheConfigHandler/no_signing_keys1516=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1517=== CONT TestCacheConfigHandler/no_cache_url_configured1518=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1519--- PASS: TestCacheConfigHandler (0.00s)1520 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1521 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1522 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1523 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)15242026/07/19 11:28:24 INFO Vacuumed table table=pending_closures15252026/07/19 11:28:24 OK 1_commit_pending_closure.sql (1.8ms)15262026/07/19 11:28:24 OK 2_object_stats_trigger.sql (558.21µs)15272026/07/19 11:28:24 goose: up to current file version: 215282026/07/19 11:28:24 INFO Vacuumed table table=pending_objects15292026/07/19 11:28:24 INFO OIDC auth successful provider=test1530=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected15312026/07/19 11:28:24 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]1532=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1533=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected15342026/07/19 11:28:24 INFO Vacuumed table table=multipart_uploads15352026/07/19 11:28:24 WARN Authentication failed token_preview=eyJhbGciOi...frmbOsTYXQ 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]1536=== CONT TestServerTLSConfig/no_client_CA1537=== CONT TestServerTLSConfig/not_a_PEM_file15382026/07/19 11:28:24 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1539--- PASS: TestService_ReadAuthMiddleware (0.43s)1540=== CONT TestServerTLSConfig/missing_CA_file1541=== CONT TestIsValidUploadKey/narinfo1542=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15432026/07/19 11:28:24 INFO Received uploads request method=POST path=/1544=== CONT TestIsValidUploadKey/unknown_type1545=== CONT TestIsValidUploadKey/empty_key1546=== CONT TestIsValidUploadKey/absolute1547=== CONT TestIsValidUploadKey/traversal_nar1548=== CONT TestIsValidUploadKey/traversal1549=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1550=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1551=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1552=== CONT TestIsValidUploadKey/index.html1553=== CONT TestIsValidUploadKey/nix-cache-info1554=== CONT TestIsValidUploadKey/realisation_plus_in_output1555=== CONT TestIsValidUploadKey/realisation1556=== CONT TestIsValidUploadKey/nar_xz1557=== CONT TestIsValidUploadKey/nar_zst1558=== CONT TestIsValidUploadKey/nar_plain1559=== CONT TestIsValidUploadKey/build_log_equals1560=== CONT TestIsValidUploadKey/build_log_question_mark1561=== CONT TestIsValidUploadKey/build_log_plus_in_name1562=== CONT TestIsValidUploadKey/build_log_home-manager_file1563=== CONT TestIsValidUploadKey/build_log1564=== CONT TestIsValidUploadKey/listing1565--- PASS: TestIsValidUploadKey (0.00s)1566 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1567 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1568 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1569 --- PASS: TestIsValidUploadKey/absolute (0.00s)1570 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1571 --- PASS: TestIsValidUploadKey/traversal (0.00s)1572 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1573 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1574 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1575 --- PASS: TestIsValidUploadKey/index.html (0.00s)1576 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1577 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1578 --- PASS: TestIsValidUploadKey/realisation (0.00s)1579 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1580 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1581 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1582 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1583 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1584 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1585 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1586 --- PASS: TestIsValidUploadKey/build_log (0.00s)1587 --- PASS: TestIsValidUploadKey/listing (0.00s)1588=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15892026/07/19 11:28:24 INFO Received complete multipart upload request method=POST path=/1590=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15912026/07/19 11:28:24 INFO Received request for more parts method=POST path=/1592=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1593--- PASS: TestService_AuthMiddleware_OIDC (0.35s)1594 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1595 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1596 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1597 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)15982026/07/19 11:28:24 INFO Received uploads request method=POST path=/1599--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1600 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1601 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1602 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1603 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1604=== CONT TestProxyWriteTimeout/narinfo1605=== CONT TestProxyWriteTimeout/10_GiB_nar1606=== CONT TestProxyWriteTimeout/unknown_size1607=== CONT TestProxyWriteTimeout/1_GiB_nar1608--- PASS: TestProxyWriteTimeout (0.00s)1609 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1610 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1611 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1612 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1613=== CONT TestClientErrorHandling/InvalidStorePath1614--- PASS: TestServerTLSConfig (0.00s)1615 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1616 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1617 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1618=== CONT TestClientErrorHandling/ServerNotAvailable16192026/07/19 11:28:24 INFO Vacuumed table table=closures16202026/07/19 11:28:24 INFO Vacuumed table table=objects16212026/07/19 11:28:24 OK 20241026095416_initial_model.sql (9.04ms)16222026/07/19 11:28:24 OK 20251210153512_drop_unused_gin_index.sql (684.5µs)16232026/07/19 11:28:24 OK 20251218171726_add_pins.sql (1.38ms)16242026/07/19 11:28:24 OK 20260628120000_add_object_size_and_stats.sql (2.35ms)16252026/07/19 11:28:24 goose: successfully migrated database to version: 2026062812000016262026/07/19 11:28:24 OK 1_commit_pending_closure.sql (1.01ms)16272026/07/19 11:28:24 OK 2_object_stats_trigger.sql (431.13µs)16282026/07/19 11:28:24 goose: up to current file version: 21629--- PASS: TestReadProxyInvalidPath (0.41s)1630=== CONT TestClientErrorHandling/InvalidAuthToken16312026/07/19 11:28:24 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-config16322026-07-19 11:28:24.338 UTC [3644] ERROR: relation "goose_db_version" does not exist at character 3616332026-07-19 11:28:24.338 UTC [3644] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16342026/07/19 11:28:24 OK 20241026095416_initial_model.sql (11.3ms)1635--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)1636 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1637 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1638 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.28s)16392026/07/19 11:28:24 OK 20251210153512_drop_unused_gin_index.sql (601.58µs)16402026/07/19 11:28:24 OK 20251218171726_add_pins.sql (912.67µs)16412026-07-19 11:28:24.366 UTC [3645] ERROR: relation "goose_db_version" does not exist at character 3616422026-07-19 11:28:24.366 UTC [3645] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16432026/07/19 11:28:24 OK 20260628120000_add_object_size_and_stats.sql (18.22ms)16442026/07/19 11:28:24 goose: successfully migrated database to version: 2026062812000016452026/07/19 11:28:24 OK 1_commit_pending_closure.sql (870.67µs)16462026/07/19 11:28:24 OK 2_object_stats_trigger.sql (206.88µs)16472026/07/19 11:28:24 goose: up to current file version: 216482026/07/19 11:28:24 INFO Created nix-cache-info in bucket bucket=bucket4116492026-07-19 11:28:24.393 UTC [3647] ERROR: relation "goose_db_version" does not exist at character 3616502026-07-19 11:28:24.393 UTC [3647] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16512026/07/19 11:28:24 OK 20241026095416_initial_model.sql (13.46ms)16522026/07/19 11:28:24 OK 20251210153512_drop_unused_gin_index.sql (378.5µs)16532026/07/19 11:28:24 OK 20251218171726_add_pins.sql (753.79µs)16542026/07/19 11:28:24 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=216.11788ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config16552026/07/19 11:28:24 OK 20260628120000_add_object_size_and_stats.sql (2.11ms)16562026/07/19 11:28:24 goose: successfully migrated database to version: 2026062812000016572026/07/19 11:28:24 OK 1_commit_pending_closure.sql (902.71µs)16582026/07/19 11:28:24 OK 2_object_stats_trigger.sql (223.17µs)16592026/07/19 11:28:24 goose: up to current file version: 21660--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.42s)16612026/07/19 11:28:24 OK 20241026095416_initial_model.sql (6.39ms)16622026/07/19 11:28:24 OK 20251210153512_drop_unused_gin_index.sql (373.5µs)16632026/07/19 11:28:24 OK 20251218171726_add_pins.sql (4.01ms)16642026/07/19 11:28:24 OK 20260628120000_add_object_size_and_stats.sql (1.32ms)16652026/07/19 11:28:24 goose: successfully migrated database to version: 2026062812000016662026/07/19 11:28:24 OK 1_commit_pending_closure.sql (891.88µs)16672026/07/19 11:28:24 OK 2_object_stats_trigger.sql (231.04µs)16682026/07/19 11:28:24 goose: up to current file version: 216692026/07/19 11:28:24 INFO Created nix-cache-info in bucket bucket=bucket4316702026-07-19 11:28:24.449 UTC [3650] ERROR: relation "goose_db_version" does not exist at character 3616712026-07-19 11:28:24.449 UTC [3650] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1672=== NAME TestClientIntegration1673 client_integration_test.go:276: Created store path: /nix/var/nix/builds/nix-3323-2004179726/TestClientIntegration127418436/002/store/xhwz3220zb738a6h3z435a1zii6fdc3r-test-file.txt1674=== NAME TestClientMultipleUploads1675 client_integration_test.go:338: Created store path 0: /nix/var/nix/builds/nix-3323-2004179726/TestClientMultipleUploads627274889/001/store/z7pgwx4lcbp6vw8wr8cv9w8y5d4qj67f-test-file-0.txt16762026/07/19 11:28:24 OK 20241026095416_initial_model.sql (16.89ms)16772026/07/19 11:28:24 OK 20251210153512_drop_unused_gin_index.sql (656.29µs)16782026/07/19 11:28:24 OK 20251218171726_add_pins.sql (954.5µs)16792026/07/19 11:28:24 OK 20260628120000_add_object_size_and_stats.sql (1.47ms)16802026/07/19 11:28:24 goose: successfully migrated database to version: 2026062812000016812026/07/19 11:28:24 OK 1_commit_pending_closure.sql (868.46µs)16822026/07/19 11:28:24 OK 2_object_stats_trigger.sql (211.96µs)16832026/07/19 11:28:24 goose: up to current file version: 216842026/07/19 11:28:24 INFO Received uploads request method=POST path=/api/pending_closures16852026/07/19 11:28:24 INFO Received uploads request method=POST path=/api/pending_closures16862026-07-19 11:28:24.501 UTC [3657] ERROR: relation "goose_db_version" does not exist at character 3616872026-07-19 11:28:24.501 UTC [3657] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1688 client_integration_test.go:338: Created store path 1: /nix/var/nix/builds/nix-3323-2004179726/TestClientMultipleUploads627274889/001/store/9q76fnlhcydpvz8dabz20lh9k3dalsqj-test-file-1.txt16892026/07/19 11:28:24 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16902026/07/19 11:28:24 OK 20241026095416_initial_model.sql (8.93ms)16912026/07/19 11:28:24 OK 20251210153512_drop_unused_gin_index.sql (558.08µs)16922026/07/19 11:28:24 OK 20251218171726_add_pins.sql (975.42µs)16932026/07/19 11:28:24 OK 20260628120000_add_object_size_and_stats.sql (3.14ms)16942026/07/19 11:28:24 goose: successfully migrated database to version: 2026062812000016952026/07/19 11:28:24 OK 1_commit_pending_closure.sql (1.2ms)16962026/07/19 11:28:24 OK 2_object_stats_trigger.sql (532.96µs)16972026/07/19 11:28:24 goose: up to current file version: 216982026-07-19 11:28:24.544 UTC [3664] ERROR: relation "goose_db_version" does not exist at character 3616992026-07-19 11:28:24.544 UTC [3664] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1700 client_integration_test.go:338: Created store path 2: /nix/var/nix/builds/nix-3323-2004179726/TestClientMultipleUploads627274889/001/store/iw41yqgnq81p06vqigfkbmshq6vznbcv-test-file-2.txt17012026/07/19 11:28:24 INFO Received uploads request method=POST path=/api/pending_closures17022026/07/19 11:28:24 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17032026/07/19 11:28:24 INFO Uploading xhwz3220zb738a6h3z435a1zii6fdc3r-test-file.txt (152B)17042026/07/19 11:28:24 OK 20241026095416_initial_model.sql (16.68ms)17052026/07/19 11:28:24 OK 20251210153512_drop_unused_gin_index.sql (471.13µs)17062026/07/19 11:28:24 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"17072026/07/19 11:28:24 OK 20251218171726_add_pins.sql (822.96µs)17082026/07/19 11:28:24 WARN Failed to register uploaded object key=xhwz3220zb738a6h3z435a1zii6fdc3r.ls error="server returned 404: 404 page not found\n"17092026/07/19 11:28:24 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17102026/07/19 11:28:24 INFO Signed narinfos id=1 count=117112026/07/19 11:28:24 INFO Uploading 1 narinfos17122026/07/19 11:28:24 WARN Failed to register uploaded object key=xhwz3220zb738a6h3z435a1zii6fdc3r.narinfo error="server returned 404: 404 page not found\n"17132026/07/19 11:28:24 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17142026/07/19 11:28:24 OK 20260628120000_add_object_size_and_stats.sql (4.05ms)17152026/07/19 11:28:24 goose: successfully migrated database to version: 2026062812000017162026/07/19 11:28:24 INFO Completed upload id=117172026/07/19 11:28:24 INFO Upload complete. (100ms)1718=== NAME TestClientIntegration1719 client_integration_test.go:292: Retrieved narinfo from S3:1720 StorePath: /nix/var/nix/builds/nix-3323-2004179726/TestClientIntegration127418436/002/store/xhwz3220zb738a6h3z435a1zii6fdc3r-test-file.txt1721 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1722 Compression: zstd1723 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11724 NarSize: 1521725 References: 1726 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk117272026/07/19 11:28:24 OK 1_commit_pending_closure.sql (1.66ms)1728 client_integration_test.go:293: Retrieved .ls file from S3 (compressed size: 77 bytes)1729 client_integration_test.go:293: Decompressed .ls content (64 bytes):1730 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1731 client_integration_test.go:296: Testing garbage collection...17322026/07/19 11:28:24 OK 2_object_stats_trigger.sql (1.02ms)17332026/07/19 11:28:24 goose: up to current file version: 217342026/07/19 11:28:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17352026/07/19 11:28:24 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=OWMyMGJjZTAtZjEwYS00OThmLWFiODgtMWVjNmJhMTQyODdjLmJiODQ5ZTIxLTdhNTQtNGY1My05N2I3LWVlZjg1YWVmZjE3N3gxNzg0NDYwNTA0NDgyMTU2MDAw parts=121736--- PASS: TestRedundantMultipartUpload (0.55s)17372026/07/19 11:28:24 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17382026/07/19 11:28:24 INFO Starting cleanup of old closures method=DELETE path=/api/closures17392026/07/19 11:28:24 INFO Garbage collection started17402026/07/19 11:28:24 INFO Aborted multipart uploads count=017412026/07/19 11:28:24 WARN Force mode enabled - objects will be deleted immediately without grace period17422026/07/19 11:28:24 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=397.085999ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17432026/07/19 11:28:24 INFO Received uploads request method=POST path=/api/pending_closures17442026/07/19 11:28:24 INFO Received uploads request method=POST path=/api/pending_closures17452026/07/19 11:28:24 INFO Received uploads request method=POST path=/api/pending_closures17462026/07/19 11:28:24 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)17472026/07/19 11:28:24 INFO Uploading 9q76fnlhcydpvz8dabz20lh9k3dalsqj-test-file-1.txt (160B)17482026/07/19 11:28:24 INFO Uploading iw41yqgnq81p06vqigfkbmshq6vznbcv-test-file-2.txt (160B)17492026/07/19 11:28:24 INFO Uploading z7pgwx4lcbp6vw8wr8cv9w8y5d4qj67f-test-file-0.txt (160B)17502026/07/19 11:28:24 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"17512026/07/19 11:28:24 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"17522026/07/19 11:28:24 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"17532026/07/19 11:28:24 WARN Failed to register uploaded object key=9q76fnlhcydpvz8dabz20lh9k3dalsqj.ls error="server returned 404: 404 page not found\n"17542026/07/19 11:28:24 WARN Failed to register uploaded object key=iw41yqgnq81p06vqigfkbmshq6vznbcv.ls error="server returned 404: 404 page not found\n"17552026/07/19 11:28:24 WARN Failed to register uploaded object key=z7pgwx4lcbp6vw8wr8cv9w8y5d4qj67f.ls error="server returned 404: 404 page not found\n"17562026/07/19 11:28:24 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign17572026/07/19 11:28:24 INFO Signed narinfos id=2 count=117582026/07/19 11:28:24 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign17592026/07/19 11:28:24 INFO Signed narinfos id=3 count=117602026/07/19 11:28:24 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17612026/07/19 11:28:24 INFO Signed narinfos id=1 count=117622026/07/19 11:28:24 INFO Uploading 3 narinfos17632026/07/19 11:28:24 WARN Failed to register uploaded object key=9q76fnlhcydpvz8dabz20lh9k3dalsqj.narinfo error="server returned 404: 404 page not found\n"17642026/07/19 11:28:24 WARN Failed to register uploaded object key=iw41yqgnq81p06vqigfkbmshq6vznbcv.narinfo error="server returned 404: 404 page not found\n"17652026/07/19 11:28:24 WARN Failed to register uploaded object key=z7pgwx4lcbp6vw8wr8cv9w8y5d4qj67f.narinfo error="server returned 404: 404 page not found\n"17662026/07/19 11:28:24 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17672026/07/19 11:28:24 INFO Completed upload id=117682026/07/19 11:28:24 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17692026/07/19 11:28:24 INFO Completed upload id=217702026/07/19 11:28:24 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete17712026/07/19 11:28:24 INFO Completed upload id=317722026/07/19 11:28:24 INFO Upload complete. (71ms)1773=== NAME TestClientMultipleUploads1774 client_integration_test.go:349: Uploaded 3 paths in 102.545125ms1775--- PASS: TestClientMultipleUploads (0.70s)17762026/07/19 11:28:24 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17772026/07/19 11:28:24 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"17782026/07/19 11:28:24 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=017792026/07/19 11:28:24 INFO Vacuumed table table=pending_closures17802026/07/19 11:28:24 INFO Vacuumed table table=pending_objects17812026/07/19 11:28:24 INFO Vacuumed table table=multipart_uploads17822026/07/19 11:28:24 INFO Vacuumed table table=closures17832026/07/19 11:28:24 INFO Vacuumed table table=objects17842026/07/19 11:28:25 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=831.19201ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17852026/07/19 11:28:25 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.46801381s 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:28:25 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.80s)17902026/07/19 11:28:26 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.73s)17952026/07/19 11:28:26 WARN Rate limiter enabled after throttle name=s3-test rate=517962026/07/19 11:28:26 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1797=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1798 throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=101799 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001800--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.48s)18012026/07/19 11:28:27 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"18022026/07/19 11:28:27 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_closures18032026/07/19 11:28:27 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=215.205808ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures18042026/07/19 11:28:27 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=425.796211ms 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:28:28 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=839.490196ms 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:28:28 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.684605027s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1807--- PASS: TestClientErrorHandling (0.00s)1808 --- PASS: TestClientErrorHandling/InvalidStorePath (0.40s)1809 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.56s)1810 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.52s)1811PASS1812{"timestamp":"2026-07-19T11:28:31.183956Z","level":"ERROR","fields":{"message":"Unknown connection IO error:Cancelled","peer_addr":"127.0.0.1:59830"},"target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":973,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}18132026-07-19 11:28:31.251 UTC [3364] LOG: received smart shutdown request18142026-07-19 11:28:31.252 UTC [3364] LOG: background worker "logical replication launcher" (PID 3374) exited with exit code 118152026-07-19 11:28:31.261 UTC [3369] LOG: shutting down18162026-07-19 11:28:31.261 UTC [3369] LOG: checkpoint starting: shutdown immediate18172026-07-19 11:28:32.247 UTC [3369] LOG: checkpoint complete: wrote 12555 buffers (76.6%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 13 recycled; write=0.726 s, sync=0.258 s, total=0.987 s; sync files=15167, longest=0.001 s, average=0.001 s; distance=212066 kB, estimate=212066 kB; lsn=0/E69DDA8, redo lsn=0/E69DDA818182026-07-19 11:28:32.251 UTC [3364] LOG: database system is shut down1819Running OIDC tests...1820=== RUN TestGlobMatch1821=== PAUSE TestGlobMatch1822=== RUN TestAudienceForIssuer1823=== PAUSE TestAudienceForIssuer1824=== RUN TestValidateToken_ValidToken1825=== PAUSE TestValidateToken_ValidToken1826=== RUN TestValidateToken_WrongAudience1827=== PAUSE TestValidateToken_WrongAudience1828=== RUN TestValidateToken_Expired1829=== PAUSE TestValidateToken_Expired1830=== RUN TestValidateToken_BoundClaimsMismatch1831=== PAUSE TestValidateToken_BoundClaimsMismatch1832=== RUN TestValidateToken_BoundSubjectMismatch1833=== PAUSE TestValidateToken_BoundSubjectMismatch1834=== RUN TestValidateToken_MultipleProviders1835=== PAUSE TestValidateToken_MultipleProviders1836=== RUN TestValidateToken_NoMatchingProvider1837=== PAUSE TestValidateToken_NoMatchingProvider1838=== CONT TestGlobMatch1839=== CONT TestValidateToken_BoundClaimsMismatch1840=== RUN TestGlobMatch/foo_foo1841=== PAUSE TestGlobMatch/foo_foo1842=== CONT TestValidateToken_Expired1843=== CONT TestAudienceForIssuer1844--- PASS: TestAudienceForIssuer (0.00s)1845=== CONT TestValidateToken_MultipleProviders1846=== CONT TestValidateToken_NoMatchingProvider1847=== CONT TestValidateToken_BoundSubjectMismatch1848=== CONT TestValidateToken_WrongAudience1849=== CONT TestValidateToken_ValidToken1850=== RUN TestGlobMatch/foo_bar1851=== PAUSE TestGlobMatch/foo_bar1852=== 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=== RUN TestGlobMatch/?oo_foo1891=== PAUSE TestGlobMatch/?oo_foo1892=== RUN TestGlobMatch/?oo_boo1893=== PAUSE TestGlobMatch/?oo_boo1894=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1895=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1896=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1897=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1898=== CONT TestGlobMatch/foo_foo1899=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1900=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1901=== CONT TestGlobMatch/?oo_boo1902=== CONT TestGlobMatch/?oo_foo1903=== CONT TestGlobMatch/fo?_fooo1904=== CONT TestGlobMatch/fo?_fo1905=== CONT TestGlobMatch/fo?_foo1906=== CONT TestGlobMatch/refs/*/main_refs/heads/main1907=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.01908=== CONT TestGlobMatch/refs/heads/*_refs/heads/main1909=== CONT TestGlobMatch/*/*_foo1910=== CONT TestGlobMatch/*/*_foo/bar1911=== CONT TestGlobMatch/foo*bar_foobarbaz1912=== CONT TestGlobMatch/foo*bar_foo123bar1913=== CONT TestGlobMatch/foo*bar_foobar1914=== CONT TestGlobMatch/*bar_foo1915=== CONT TestGlobMatch/*bar_foobar1916=== CONT TestGlobMatch/*bar_bar1917=== CONT TestGlobMatch/foo*_bar1918=== CONT TestGlobMatch/foo*_foobar1919=== CONT TestGlobMatch/foo*_foo1920=== CONT TestGlobMatch/*_anything1921=== CONT TestGlobMatch/*_1922=== CONT TestGlobMatch/foo_bar1923--- PASS: TestGlobMatch (0.00s)1924 --- PASS: TestGlobMatch/foo_foo (0.00s)1925 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)1926 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)1927 --- PASS: TestGlobMatch/?oo_boo (0.00s)1928 --- PASS: TestGlobMatch/?oo_foo (0.00s)1929 --- PASS: TestGlobMatch/fo?_fooo (0.00s)1930 --- PASS: TestGlobMatch/fo?_fo (0.00s)1931 --- PASS: TestGlobMatch/fo?_foo (0.00s)1932 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)1933 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)1934 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)1935 --- PASS: TestGlobMatch/*/*_foo (0.00s)1936 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)1937 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)1938 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)1939 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)1940 --- PASS: TestGlobMatch/*bar_foo (0.00s)1941 --- PASS: TestGlobMatch/*bar_foobar (0.00s)1942 --- PASS: TestGlobMatch/*bar_bar (0.00s)1943 --- PASS: TestGlobMatch/foo*_bar (0.00s)1944 --- PASS: TestGlobMatch/foo*_foobar (0.00s)1945 --- PASS: TestGlobMatch/foo*_foo (0.00s)1946 --- PASS: TestGlobMatch/*_anything (0.00s)1947 --- PASS: TestGlobMatch/*_ (0.00s)1948 --- PASS: TestGlobMatch/foo_bar (0.00s)19492026/07/19 11:28:33 INFO OIDC provider initialized name=test19502026/07/19 11:28:33 INFO OIDC provider initialized name=provider119512026/07/19 11:28:33 INFO OIDC provider initialized name=test19522026/07/19 11:28:33 INFO OIDC provider initialized name=test19532026/07/19 11:28:33 INFO OIDC provider initialized name=test19542026/07/19 11:28:33 INFO OIDC provider initialized name=test19552026/07/19 11:28:33 INFO OIDC provider initialized name=provider119562026/07/19 11:28:33 INFO OIDC provider initialized name=provider21957--- PASS: TestValidateToken_WrongAudience (0.01s)1958--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)1959--- PASS: TestValidateToken_NoMatchingProvider (0.01s)1960--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)1961--- PASS: TestValidateToken_Expired (0.01s)1962--- PASS: TestValidateToken_ValidToken (0.01s)1963--- PASS: TestValidateToken_MultipleProviders (0.01s)1964PASS1965Running hook tests...1966=== RUN TestSendPathsEmpty1967=== PAUSE TestSendPathsEmpty1968=== RUN TestQueueEnqueueAndFetch1969=== PAUSE TestQueueEnqueueAndFetch1970=== RUN TestQueueDeduplication1971=== PAUSE TestQueueDeduplication1972=== RUN TestQueueRemove1973=== PAUSE TestQueueRemove1974=== RUN TestQueueFetchBatchLimit1975=== PAUSE TestQueueFetchBatchLimit1976=== RUN TestQueueFetchRemoveLifecycle1977=== PAUSE TestQueueFetchRemoveLifecycle1978=== RUN TestQueueConcurrentWriters1979=== PAUSE TestQueueConcurrentWriters1980=== RUN TestServerClientIntegration1981=== PAUSE TestServerClientIntegration1982=== RUN TestServerQueueError1983=== PAUSE TestServerQueueError1984=== RUN TestGetListenerSocketActivation1985 server_test.go:210: === RUN TestGetListenerSocketActivation1986 --- PASS: TestGetListenerSocketActivation (0.00s)1987 PASS1988 1989--- PASS: TestGetListenerSocketActivation (0.01s)1990=== RUN TestWorkerUploadsAndRemoves1991=== PAUSE TestWorkerUploadsAndRemoves1992=== RUN TestWorkerSkipsGCdPaths1993=== PAUSE TestWorkerSkipsGCdPaths1994=== RUN TestWorkerPrunesClosureDeps1995=== PAUSE TestWorkerPrunesClosureDeps1996=== CONT TestSendPathsEmpty1997--- PASS: TestSendPathsEmpty (0.00s)1998=== CONT TestQueueConcurrentWriters1999=== CONT TestQueueFetchRemoveLifecycle2000=== CONT TestQueueFetchBatchLimit2001=== CONT TestQueueRemove2002=== CONT TestQueueDeduplication2003=== CONT TestQueueEnqueueAndFetch2004=== CONT TestWorkerPrunesClosureDeps2005=== CONT TestWorkerSkipsGCdPaths2006=== CONT TestServerQueueError2007=== CONT TestServerClientIntegration20082026/07/19 11:28:33 ERROR Failed to queue paths error="permission denied" count=12009--- PASS: TestServerQueueError (0.00s)2010=== CONT TestWorkerUploadsAndRemoves2011--- PASS: TestServerClientIntegration (0.00s)2012--- PASS: TestQueueFetchBatchLimit (0.01s)2013--- PASS: TestQueueEnqueueAndFetch (0.01s)20142026/07/19 11:28:33 INFO Upload queue status pending=220152026/07/19 11:28:33 INFO Uploading batch count=220162026/07/19 11:28:33 INFO Upload queue status pending=220172026/07/19 11:28:33 INFO Uploading batch count=12018--- PASS: TestQueueDeduplication (0.01s)20192026/07/19 11:28:33 INFO Upload queue status pending=220202026/07/19 11:28:33 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-3323-2004179726/TestWorkerSkipsGCdPaths1237630409/002/nonexistent20212026/07/19 11:28:33 INFO Uploading batch count=12022--- PASS: TestQueueRemove (0.01s)2023--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2024--- PASS: TestWorkerPrunesClosureDeps (0.06s)2025--- PASS: TestWorkerUploadsAndRemoves (0.06s)2026--- PASS: TestWorkerSkipsGCdPaths (0.06s)2027--- PASS: TestQueueConcurrentWriters (0.16s)2028PASS