niks3-go-unit-tests
aarch64-darwin.go-unit-tests
· build #106
· 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 TestConvertHashToNix3274=== CONT TestScriptTokenScriptFails75=== RUN TestConvertHashToNix32/SRI_format_to_Nix3276=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix3277=== RUN TestConvertHashToNix32/already_Nix32_format78=== CONT TestDumpPathMatchesNix79=== CONT TestDoWithRetry_BodyReplayedViaGetBody80=== CONT TestScriptTokenEmptyCommand81--- PASS: TestScriptTokenEmptyCommand (0.00s)82=== CONT TestParsePathInfoJSONMultiplePaths83=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths84=== PAUSE TestConvertHashToNix32/already_Nix32_format85=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths86=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths87=== RUN TestConvertHashToNix32/invalid_format88=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths89=== PAUSE TestConvertHashToNix32/invalid_format90=== CONT TestRateLimiterFeedback91=== CONT TestParsePathInfoJSON92=== RUN TestRateLimiterFeedback/429_enables_limiter93=== RUN TestParsePathInfoJSON/Nix_format94=== PAUSE TestRateLimiterFeedback/429_enables_limiter95=== RUN TestRateLimiterFeedback/503_enables_limiter96=== PAUSE TestRateLimiterFeedback/503_enables_limiter97=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter98=== PAUSE TestParsePathInfoJSON/Nix_format99=== RUN TestParsePathInfoJSON/Lix_format100=== PAUSE TestParsePathInfoJSON/Lix_format101=== RUN TestParsePathInfoJSON/empty_input102=== PAUSE TestParsePathInfoJSON/empty_input103=== RUN TestParsePathInfoJSON/whitespace_only104=== PAUSE TestParsePathInfoJSON/whitespace_only105=== RUN TestParsePathInfoJSON/invalid_JSON106=== PAUSE TestParsePathInfoJSON/invalid_JSON107=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter108=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter109=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter110=== CONT TestGetStorePathHash111=== RUN TestGetStorePathHash/valid_store_path112=== CONT TestEncodeNixBase32113=== RUN TestEncodeNixBase32/test_string_hash114=== PAUSE TestEncodeNixBase32/test_string_hash115=== RUN TestEncodeNixBase32/empty_input116=== PAUSE TestEncodeNixBase32/empty_input117=== CONT TestEncodeNixBase32WithRealHash118--- PASS: TestEncodeNixBase32WithRealHash (0.00s)119=== CONT TestFileTokenReadsAndCaches120=== CONT TestResolveStorePath121=== PAUSE TestGetStorePathHash/valid_store_path122=== RUN TestGetStorePathHash/basename_without_hyphen_should_error123=== CONT TestPathInfoHashCompatibility124=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error125=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error126=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error127=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error128=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error129=== CONT TestScriptTokenBadJSON130=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)131=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)132=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon133=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon134=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess135=== CONT TestPathInfoCACompatibility136=== RUN TestPathInfoCACompatibility/null_ca_field137=== PAUSE TestPathInfoCACompatibility/null_ca_field138=== RUN TestPathInfoCACompatibility/old_string_format_-_text139=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text140=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive141=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive142=== RUN TestPathInfoCACompatibility/new_structured_format_-_text1432026/07/19 11:19:09 WARN Rate limiter enabled after throttle name=server-test rate=5144=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text145=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method146=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method147=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI148=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI149=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512150=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512151=== CONT TestScriptTokenEmptyToken152=== CONT TestScriptTokenCachesUntilRefresh153--- PASS: TestFileTokenReadsAndCaches (0.00s)154=== CONT TestScriptTokenNoExpiryRerunsEveryCall155--- PASS: TestResolveStorePath (0.01s)156=== CONT TestFileTokenMissing1572026/07/19 11:19:09 WARN Rate limiter enabled after throttle name=server-test rate=51582026/07/19 11:19:09 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:595041592026/07/19 11:19:09 WARN Rate limiter backed off name=server-test rate=51602026/07/19 11:19:09 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:59504161--- PASS: TestDoServerRequestAttachesToken (0.01s)162=== CONT TestDumpPathWriterError163--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)164=== CONT TestSetClientTLSDoesNotMutateDefaultTransport165--- PASS: TestFileTokenMissing (0.00s)166=== CONT TestStaticToken167--- PASS: TestStaticToken (0.00s)168=== CONT TestSetClientTLSErrors169--- PASS: TestScriptTokenScriptFails (0.01s)170=== CONT TestPartSizeForNAR171=== RUN TestPartSizeForNAR/zero_stays_at_minimum172=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum173=== RUN TestPartSizeForNAR/small_stays_at_minimum174=== PAUSE TestPartSizeForNAR/small_stays_at_minimum175=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum176=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum177=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts178=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts179=== RUN TestPartSizeForNAR/1_TiB180=== PAUSE TestPartSizeForNAR/1_TiB181=== RUN TestPartSizeForNAR/5_TiB_S3_max_object182=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object183=== RUN TestPartSizeForNAR/capped_at_5_GiB184=== PAUSE TestPartSizeForNAR/capped_at_5_GiB185=== CONT TestUploadMultipart_SupersededByPeer186=== RUN TestUploadMultipart_SupersededByPeer/exists187=== PAUSE TestUploadMultipart_SupersededByPeer/exists188=== RUN TestUploadMultipart_SupersededByPeer/missing189=== PAUSE TestUploadMultipart_SupersededByPeer/missing190=== CONT TestFilterOversizedClosures191=== RUN TestFilterOversizedClosures/no_limit_keeps_everything192=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything193=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped194=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped195=== RUN TestFilterOversizedClosures/all_closures_skipped196=== PAUSE TestFilterOversizedClosures/all_closures_skipped197=== CONT TestCaseHackSuffix198=== RUN TestSetClientTLSErrors/missing_cert_file199=== PAUSE TestSetClientTLSErrors/missing_cert_file200=== RUN TestSetClientTLSErrors/missing_key_file201=== PAUSE TestSetClientTLSErrors/missing_key_file202=== RUN TestSetClientTLSErrors/missing_ca_file203=== PAUSE TestSetClientTLSErrors/missing_ca_file204=== RUN TestSetClientTLSErrors/invalid_ca_file205=== PAUSE TestSetClientTLSErrors/invalid_ca_file206=== CONT TestShellSplitErrors207--- PASS: TestShellSplitErrors (0.00s)208=== CONT TestSetClientTLS209--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)210=== CONT TestShellSplit211--- PASS: TestShellSplit (0.00s)212=== CONT TestDumpPathSingleFile213=== RUN TestSetClientTLS/rejects_connection_without_client_cert214=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert215=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA216=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA217=== RUN TestSetClientTLS/preserves_debug_logging_transport218=== PAUSE TestSetClientTLS/preserves_debug_logging_transport219=== CONT TestFileTokenEmpty220--- PASS: TestScriptTokenEmptyToken (0.01s)221=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths222--- PASS: TestScriptTokenBadJSON (0.02s)223=== CONT TestConvertHashToNix32/SRI_format_to_Nix32224=== CONT TestConvertHashToNix32/invalid_format225=== CONT TestConvertHashToNix32/already_Nix32_format226--- PASS: TestConvertHashToNix32 (0.00s)227 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)228 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)229 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)230=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths231=== CONT TestParsePathInfoJSON/Nix_format232=== CONT TestRateLimiterFeedback/429_enables_limiter233--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)234 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)235 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)236=== CONT TestParsePathInfoJSON/invalid_JSON237=== CONT TestParsePathInfoJSON/whitespace_only238=== CONT TestParsePathInfoJSON/empty_input239=== CONT TestParsePathInfoJSON/Lix_format240--- PASS: TestParsePathInfoJSON (0.00s)241 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)242 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)243 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)244 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)245 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)246=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter2472026/07/19 11:19:09 WARN Rate limiter enabled after throttle name=server-test rate=52482026/07/19 11:19:09 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:59510249=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2502026/07/19 11:19:09 WARN Rate limiter backed off name=server-test rate=5251=== CONT TestRateLimiterFeedback/503_enables_limiter252--- PASS: TestFileTokenEmpty (0.00s)253=== CONT TestEncodeNixBase32/test_string_hash254=== CONT TestEncodeNixBase32/empty_input255--- PASS: TestEncodeNixBase32 (0.00s)256 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)257 --- PASS: TestEncodeNixBase32/empty_input (0.00s)258=== CONT TestGetStorePathHash/valid_store_path259=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error260=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error261=== CONT TestGetStorePathHash/basename_without_hyphen_should_error262--- PASS: TestGetStorePathHash (0.00s)263 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)264 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)265 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)266 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)267=== CONT TestPathInfoCACompatibility/null_ca_field268=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)269=== CONT TestPathInfoCACompatibility/old_string_format_-_text270=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method271=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive272=== CONT TestPathInfoCACompatibility/new_structured_format_-_text273=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512274--- PASS: TestPathInfoCACompatibility (0.00s)275 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)276 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)277 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)278 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)279 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)280=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI281=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon282=== CONT TestPartSizeForNAR/zero_stays_at_minimum2832026/07/19 11:19:09 WARN Rate limiter enabled after throttle name=server-test rate=5284=== CONT TestPartSizeForNAR/1_TiB2852026/07/19 11:19:09 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:59516286=== CONT TestPartSizeForNAR/5_TiB_S3_max_object287=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum288=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts289--- PASS: TestPathInfoHashCompatibility (0.00s)290 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)291 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)292 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)293 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)294=== CONT TestPartSizeForNAR/small_stays_at_minimum295=== CONT TestPartSizeForNAR/capped_at_5_GiB296--- PASS: TestPartSizeForNAR (0.00s)297 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)298 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)299 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)300 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)301 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)302 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)303 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)304=== CONT TestUploadMultipart_SupersededByPeer/exists305=== CONT TestFilterOversizedClosures/no_limit_keeps_everything306=== CONT TestUploadMultipart_SupersededByPeer/missing3072026/07/19 11:19:09 WARN Rate limiter backed off name=server-test rate=5308=== CONT TestFilterOversizedClosures/all_closures_skipped309--- PASS: TestRateLimiterFeedback (0.00s)310 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)311 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)312 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)313 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)3142026/07/19 11:19:09 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-small nar_size=1000 max_nar_size=50315=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3162026/07/19 11:19:09 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=2000317--- PASS: TestFilterOversizedClosures (0.00s)318 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)319 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)320 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)321=== CONT TestSetClientTLSErrors/missing_cert_file322=== CONT TestSetClientTLSErrors/missing_ca_file323=== CONT TestSetClientTLSErrors/invalid_ca_file324=== CONT TestSetClientTLSErrors/missing_key_file325--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)326 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)327 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)328=== CONT TestSetClientTLS/rejects_connection_without_client_cert329=== CONT TestSetClientTLS/preserves_debug_logging_transport330=== 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:19:09 http: TLS handshake error from 127.0.0.1:59522: remote error: tls: bad certificate337--- PASS: TestSetClientTLS (0.01s)338 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)339 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)340 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)341--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)342--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)343--- PASS: TestDumpPathWriterError (0.04s)344--- PASS: TestDumpPathSingleFile (0.06s)345--- PASS: TestCaseHackSuffix (0.06s)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-98732-3921061229/postgres3745689467/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-98732-3921061229/postgres3745689467/data -l logfile start376377/nix/var/nix/builds/nix-98732-3921061229/postgres3745689467:5432 - no response3782026-07-19 11:19:11.583 UTC [98767] LOG: starting PostgreSQL 18.4 on aarch64-apple-darwin25.3.0, compiled by clang version 21.1.8, 64-bit3792026-07-19 11:19:11.583 UTC [98767] LOG: listening on Unix socket "/nix/var/nix/builds/nix-98732-3921061229/postgres3745689467/.s.PGSQL.5432"3802026-07-19 11:19:11.586 UTC [98774] LOG: database system was shut down at 2026-07-19 11:19:11 UTC3812026-07-19 11:19:11.586 UTC [98767] LOG: database system is ready to accept connections382/nix/var/nix/builds/nix-98732-3921061229/postgres3745689467:5432 - accepting connections383<jemalloc>: option background_thread currently supports pthread only384{"timestamp":"2026-07-19T11:19:11.713009Z","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(9)"}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:19:11.846 UTC [98825] ERROR: relation "goose_db_version" does not exist at character 364132026-07-19 11:19:11.846 UTC [98825] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4142026/07/19 11:19:11 OK 20241026095416_initial_model.sql (3.08ms)4152026/07/19 11:19:11 OK 20251210153512_drop_unused_gin_index.sql (547.96µs)4162026/07/19 11:19:11 OK 20251218171726_add_pins.sql (770.79µs)4172026/07/19 11:19:11 OK 20260628120000_add_object_size_and_stats.sql (777.75µs)4182026/07/19 11:19:11 goose: successfully migrated database to version: 202606281200004192026/07/19 11:19:11 OK 1_commit_pending_closure.sql (779.58µs)4202026/07/19 11:19:11 OK 2_object_stats_trigger.sql (205.17µs)4212026/07/19 11:19:11 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 TestSystemdListenerNotActivated508--- PASS: TestSystemdListenerNotActivated (0.00s)509=== RUN TestWatchdogBeatsWhenHealthy510--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)511=== RUN TestWatchdogSkipsWhenUnhealthy5122026/07/19 11:19:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5132026/07/19 11:19:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5142026/07/19 11:19:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5152026/07/19 11:19:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5162026/07/19 11:19:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5172026/07/19 11:19:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5182026/07/19 11:19:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5192026/07/19 11:19:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5202026/07/19 11:19:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5212026/07/19 11:19:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"522--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)523=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle524=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle525=== RUN TestProxyWriteTimeout526=== PAUSE TestProxyWriteTimeout527=== RUN TestIsValidUploadKey528=== PAUSE TestIsValidUploadKey529=== RUN TestUploadHandlersRejectInvalidKeys530=== PAUSE TestUploadHandlersRejectInvalidKeys531=== RUN TestUploadHandlersRejectOversizedBody532=== PAUSE TestUploadHandlersRejectOversizedBody533=== RUN TestService_cleanupPendingClosuresHandler534=== PAUSE TestService_cleanupPendingClosuresHandler535=== RUN TestService_createPendingClosureHandler536=== PAUSE TestService_createPendingClosureHandler537=== RUN TestService_verifyS3Integrity538=== PAUSE TestService_verifyS3Integrity539=== RUN TestCompleteMultipartUnregistered540=== PAUSE TestCompleteMultipartUnregistered541=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT542=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT543=== CONT TestService_AuthMiddleware544=== CONT TestObjectStatsTrigger545=== CONT TestGCTaskStore_ConflictDifferentParams546--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)547=== CONT TestCreatePendingClosureRejectsOversizedNAR548=== CONT TestGenerateLandingPage549=== CONT TestMultipartCleanup550=== CONT TestCacheConfigHandlerMaxNarSize551=== CONT TestServerTLSConfig552=== RUN TestServerTLSConfig/no_client_CA553=== CONT TestService_NativeMTLS554=== CONT TestMetricsInventory555--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)556=== CONT TestGCTaskStore_PhaseUpdates557--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)558=== CONT TestService_healthCheckHandler5592026/07/19 11:19:12 INFO Received uploads request method=POST path=/api/pending_closures560=== CONT TestNARDeduplicationMetadataUploadBug561=== PAUSE TestServerTLSConfig/no_client_CA562=== CONT TestGracefulShutdownDrainsInflight563--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)564=== RUN TestServerTLSConfig/missing_CA_file565=== PAUSE TestServerTLSConfig/missing_CA_file566=== RUN TestServerTLSConfig/not_a_PEM_file567=== PAUSE TestServerTLSConfig/not_a_PEM_file568=== CONT TestGCTaskStore_Fail569--- PASS: TestGCTaskStore_Fail (0.00s)570=== CONT TestGCTaskStore_GetReturnsLatest571--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)572=== CONT TestGCTaskStore_CompletedAllowsNewTask573--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)574=== CONT TestGCTaskStore_GetEmpty575--- PASS: TestGCTaskStore_GetEmpty (0.00s)576=== CONT TestClientIntegration5772026/07/19 11:19:12 INFO Starting HTTP server address=127.0.0.1:595365782026/07/19 11:19:12 INFO Shutdown signal received, draining in-flight requests timeout=10s579--- PASS: TestGenerateLandingPage (0.01s)580=== CONT TestGCTaskStore_DeduplicateSameParams581--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)582=== CONT TestGCTaskStore_StartNew583--- PASS: TestGCTaskStore_StartNew (0.00s)584=== CONT TestGCMetrics585--- PASS: TestGracefulShutdownDrainsInflight (0.09s)586=== CONT TestGCBugBareHashReferences5872026-07-19 11:19:12.392 UTC [98847] ERROR: relation "goose_db_version" does not exist at character 365882026-07-19 11:19:12.392 UTC [98847] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5892026-07-19 11:19:12.405 UTC [98848] ERROR: relation "goose_db_version" does not exist at character 365902026-07-19 11:19:12.405 UTC [98848] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5912026/07/19 11:19:12 OK 20241026095416_initial_model.sql (12.35ms)5922026-07-19 11:19:12.414 UTC [98849] ERROR: relation "goose_db_version" does not exist at character 365932026-07-19 11:19:12.414 UTC [98849] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5942026-07-19 11:19:12.414 UTC [98850] ERROR: relation "goose_db_version" does not exist at character 365952026-07-19 11:19:12.414 UTC [98850] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5962026-07-19 11:19:12.415 UTC [98851] ERROR: relation "goose_db_version" does not exist at character 365972026-07-19 11:19:12.415 UTC [98851] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5982026-07-19 11:19:12.415 UTC [98852] ERROR: relation "goose_db_version" does not exist at character 365992026-07-19 11:19:12.415 UTC [98852] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6002026/07/19 11:19:12 OK 20251210153512_drop_unused_gin_index.sql (1.48ms)6012026/07/19 11:19:12 OK 20251218171726_add_pins.sql (1.54ms)6022026-07-19 11:19:12.418 UTC [98854] ERROR: relation "goose_db_version" does not exist at character 366032026-07-19 11:19:12.418 UTC [98854] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6042026-07-19 11:19:12.418 UTC [98853] ERROR: relation "goose_db_version" does not exist at character 366052026-07-19 11:19:12.418 UTC [98853] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6062026/07/19 11:19:12 OK 20260628120000_add_object_size_and_stats.sql (1.34ms)6072026/07/19 11:19:12 goose: successfully migrated database to version: 202606281200006082026-07-19 11:19:12.419 UTC [98855] ERROR: relation "goose_db_version" does not exist at character 366092026-07-19 11:19:12.419 UTC [98855] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6102026/07/19 11:19:12 OK 1_commit_pending_closure.sql (2.17ms)6112026/07/19 11:19:12 OK 2_object_stats_trigger.sql (420.46µs)6122026/07/19 11:19:12 goose: up to current file version: 26132026-07-19 11:19:12.422 UTC [98856] ERROR: relation "goose_db_version" does not exist at character 366142026-07-19 11:19:12.422 UTC [98856] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6152026/07/19 11:19:12 OK 20241026095416_initial_model.sql (9.14ms)6162026/07/19 11:19:12 OK 20251210153512_drop_unused_gin_index.sql (773.88µs)6172026/07/19 11:19:12 WARN mTLS auth: subject not in bound subjects subject="CN=reader"6182026/07/19 11:19:12 WARN mTLS auth: subject not in bound subjects subject="CN=writer"619--- PASS: TestService_NativeMTLS (0.34s)620=== CONT TestPinProtectsFromGC6212026/07/19 11:19:12 OK 20251218171726_add_pins.sql (2.15ms)6222026/07/19 11:19:12 OK 20241026095416_initial_model.sql (7.19ms)6232026/07/19 11:19:12 OK 20241026095416_initial_model.sql (7.38ms)6242026/07/19 11:19:12 OK 20241026095416_initial_model.sql (7.62ms)6252026/07/19 11:19:12 OK 20251210153512_drop_unused_gin_index.sql (934.88µs)6262026/07/19 11:19:12 OK 20241026095416_initial_model.sql (7.27ms)6272026/07/19 11:19:12 OK 20251210153512_drop_unused_gin_index.sql (951.46µs)6282026/07/19 11:19:12 OK 20251210153512_drop_unused_gin_index.sql (1.27ms)6292026/07/19 11:19:12 OK 20251210153512_drop_unused_gin_index.sql (758µs)6302026/07/19 11:19:12 OK 20260628120000_add_object_size_and_stats.sql (2.72ms)6312026/07/19 11:19:12 goose: successfully migrated database to version: 202606281200006322026/07/19 11:19:12 OK 20241026095416_initial_model.sql (6.73ms)6332026/07/19 11:19:12 OK 20251218171726_add_pins.sql (2.42ms)6342026/07/19 11:19:12 OK 20251218171726_add_pins.sql (1.99ms)6352026/07/19 11:19:12 OK 20241026095416_initial_model.sql (6.62ms)6362026/07/19 11:19:12 OK 20251210153512_drop_unused_gin_index.sql (815.75µs)6372026/07/19 11:19:12 OK 1_commit_pending_closure.sql (1.34ms)6382026/07/19 11:19:12 OK 20241026095416_initial_model.sql (6.45ms)6392026/07/19 11:19:12 OK 20251218171726_add_pins.sql (1.84ms)6402026/07/19 11:19:12 OK 20251218171726_add_pins.sql (2.23ms)6412026/07/19 11:19:12 OK 2_object_stats_trigger.sql (575.92µs)6422026/07/19 11:19:12 goose: up to current file version: 26432026/07/19 11:19:12 OK 20251210153512_drop_unused_gin_index.sql (599.04µs)6442026/07/19 11:19:12 OK 20251210153512_drop_unused_gin_index.sql (791µs)6452026/07/19 11:19:12 OK 20260628120000_add_object_size_and_stats.sql (1.65ms)6462026/07/19 11:19:12 goose: successfully migrated database to version: 202606281200006472026/07/19 11:19:12 OK 20260628120000_add_object_size_and_stats.sql (1.43ms)6482026/07/19 11:19:12 goose: successfully migrated database to version: 202606281200006492026/07/19 11:19:12 OK 20251218171726_add_pins.sql (1.13ms)6502026/07/19 11:19:12 OK 20260628120000_add_object_size_and_stats.sql (2.76ms)6512026/07/19 11:19:12 goose: successfully migrated database to version: 202606281200006522026/07/19 11:19:12 OK 20251218171726_add_pins.sql (2.29ms)6532026/07/19 11:19:12 OK 20260628120000_add_object_size_and_stats.sql (1.87ms)6542026/07/19 11:19:12 goose: successfully migrated database to version: 202606281200006552026/07/19 11:19:12 OK 20241026095416_initial_model.sql (5.19ms)6562026/07/19 11:19:12 OK 1_commit_pending_closure.sql (1.46ms)6572026/07/19 11:19:12 OK 20251218171726_add_pins.sql (1.93ms)6582026/07/19 11:19:12 OK 1_commit_pending_closure.sql (1.06ms)6592026/07/19 11:19:12 OK 2_object_stats_trigger.sql (561.75µs)6602026/07/19 11:19:12 goose: up to current file version: 26612026/07/19 11:19:12 OK 20260628120000_add_object_size_and_stats.sql (1.36ms)6622026/07/19 11:19:12 goose: successfully migrated database to version: 202606281200006632026/07/19 11:19:12 OK 1_commit_pending_closure.sql (1.19ms)6642026/07/19 11:19:12 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"665--- PASS: TestService_AuthMiddleware (0.35s)666=== CONT TestClientWithDependencies6672026/07/19 11:19:12 OK 20251210153512_drop_unused_gin_index.sql (816.58µs)6682026/07/19 11:19:12 OK 2_object_stats_trigger.sql (629.92µs)6692026/07/19 11:19:12 goose: up to current file version: 26702026/07/19 11:19:12 OK 1_commit_pending_closure.sql (1.33ms)6712026/07/19 11:19:12 OK 20260628120000_add_object_size_and_stats.sql (1.42ms)6722026/07/19 11:19:12 goose: successfully migrated database to version: 202606281200006732026/07/19 11:19:12 OK 2_object_stats_trigger.sql (367.88µs)6742026/07/19 11:19:12 goose: up to current file version: 26752026/07/19 11:19:12 OK 2_object_stats_trigger.sql (943.42µs)6762026/07/19 11:19:12 goose: up to current file version: 26772026/07/19 11:19:12 OK 1_commit_pending_closure.sql (1.53ms)6782026/07/19 11:19:12 OK 1_commit_pending_closure.sql (1.24ms)6792026/07/19 11:19:12 OK 20260628120000_add_object_size_and_stats.sql (2.26ms)6802026/07/19 11:19:12 goose: successfully migrated database to version: 202606281200006812026/07/19 11:19:12 OK 20251218171726_add_pins.sql (1.61ms)6822026/07/19 11:19:12 OK 2_object_stats_trigger.sql (474.13µs)6832026/07/19 11:19:12 goose: up to current file version: 26842026/07/19 11:19:12 OK 2_object_stats_trigger.sql (788.08µs)6852026/07/19 11:19:12 goose: up to current file version: 26862026/07/19 11:19:12 OK 1_commit_pending_closure.sql (1.23ms)6872026/07/19 11:19:12 OK 20260628120000_add_object_size_and_stats.sql (1.65ms)6882026/07/19 11:19:12 goose: successfully migrated database to version: 202606281200006892026/07/19 11:19:12 OK 2_object_stats_trigger.sql (391.5µs)6902026/07/19 11:19:12 goose: up to current file version: 26912026/07/19 11:19:12 INFO Received uploads request method=POST path=/api/pending_closures692--- PASS: TestService_healthCheckHandler (0.35s)693=== CONT TestClientMultipleUploads6942026/07/19 11:19:12 OK 1_commit_pending_closure.sql (2.08ms)6952026/07/19 11:19:12 OK 2_object_stats_trigger.sql (527.46µs)6962026/07/19 11:19:12 goose: up to current file version: 2697{"timestamp":"2026-07-19T11:19:12.439375Z","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(4)"}6982026/07/19 11:19:12 INFO Created nix-cache-info in bucket bucket=bucket46992026/07/19 11:19:12 INFO Created nix-cache-info in bucket bucket=bucket8700--- PASS: TestMetricsInventory (0.35s)701=== CONT TestRedundantMultipartUpload7022026/07/19 11:19:12 INFO Aborted multipart uploads count=0703--- PASS: TestObjectStatsTrigger (0.36s)704=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT7052026/07/19 11:19:12 WARN Force mode enabled - objects will be deleted immediately without grace period7062026/07/19 11:19:12 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=07072026/07/19 11:19:12 INFO Vacuumed table table=pending_closures7082026/07/19 11:19:12 INFO Vacuumed table table=pending_objects7092026/07/19 11:19:12 INFO Vacuumed table table=multipart_uploads7102026/07/19 11:19:12 INFO Vacuumed table table=closures7112026/07/19 11:19:12 INFO Vacuumed table table=objects712--- PASS: TestGCMetrics (0.35s)713=== CONT TestCompleteMultipartUnregistered7142026/07/19 11:19:12 INFO Received cleanup request method=DELETE path=/api/pending_closures7152026/07/19 11:19:12 INFO Aborted multipart uploads count=1716--- PASS: TestMultipartCleanup (0.47s)717=== CONT TestService_verifyS3Integrity718=== NAME TestClientIntegration719 client_integration_test.go:276: Created store path: /nix/var/nix/builds/nix-98732-3921061229/TestClientIntegration1786046135/002/store/qsj1d8jll536sxydc1098dcq60xgchp7-test-file.txt720=== NAME TestNARDeduplicationMetadataUploadBug721 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-98732-3921061229/TestNARDeduplicationMetadataUploadBug3618534360/001/store/l68hganw1m4fk81w0rnzs2qgrxsl0hg0-file1.txt7222026-07-19 11:19:12.608 UTC [98878] ERROR: relation "goose_db_version" does not exist at character 367232026-07-19 11:19:12.608 UTC [98878] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7242026-07-19 11:19:12.623 UTC [98881] ERROR: relation "goose_db_version" does not exist at character 367252026-07-19 11:19:12.623 UTC [98881] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7262026/07/19 11:19:12 OK 20241026095416_initial_model.sql (13.05ms)7272026/07/19 11:19:12 OK 20251210153512_drop_unused_gin_index.sql (395.25µs)7282026-07-19 11:19:12.628 UTC [98884] ERROR: relation "goose_db_version" does not exist at character 367292026-07-19 11:19:12.628 UTC [98884] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7302026/07/19 11:19:12 OK 20251218171726_add_pins.sql (809.04µs)7312026/07/19 11:19:12 OK 20260628120000_add_object_size_and_stats.sql (4.86ms)7322026/07/19 11:19:12 goose: successfully migrated database to version: 202606281200007332026/07/19 11:19:12 OK 1_commit_pending_closure.sql (1.31ms)7342026/07/19 11:19:12 OK 2_object_stats_trigger.sql (401.17µs)7352026/07/19 11:19:12 goose: up to current file version: 27362026/07/19 11:19:12 INFO Created nix-cache-info in bucket bucket=bucket127372026/07/19 11:19:12 OK 20241026095416_initial_model.sql (11.43ms)7382026/07/19 11:19:12 OK 20251210153512_drop_unused_gin_index.sql (541.08µs)7392026/07/19 11:19:12 OK 20251218171726_add_pins.sql (787.46µs)7402026/07/19 11:19:12 OK 20241026095416_initial_model.sql (10.86ms)7412026/07/19 11:19:12 OK 20251210153512_drop_unused_gin_index.sql (397.08µs)7422026/07/19 11:19:12 OK 20251218171726_add_pins.sql (780.75µs)7432026/07/19 11:19:12 OK 20260628120000_add_object_size_and_stats.sql (9.94ms)7442026/07/19 11:19:12 goose: successfully migrated database to version: 20260628120000745--- PASS: TestGCBugBareHashReferences (0.48s)746=== CONT TestService_createPendingClosureHandler7472026/07/19 11:19:12 OK 20260628120000_add_object_size_and_stats.sql (6.32ms)7482026/07/19 11:19:12 goose: successfully migrated database to version: 202606281200007492026/07/19 11:19:12 OK 1_commit_pending_closure.sql (1.47ms)7502026/07/19 11:19:12 OK 2_object_stats_trigger.sql (431.54µs)7512026/07/19 11:19:12 goose: up to current file version: 27522026/07/19 11:19:12 OK 1_commit_pending_closure.sql (1.27ms)7532026/07/19 11:19:12 OK 2_object_stats_trigger.sql (263.42µs)7542026/07/19 11:19:12 goose: up to current file version: 27552026/07/19 11:19:12 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"7562026/07/19 11:19:12 INFO Created nix-cache-info in bucket bucket=bucket137572026/07/19 11:19:12 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"7582026/07/19 11:19:12 INFO Created nix-cache-info in bucket bucket=bucket147592026/07/19 11:19:12 INFO Received uploads request method=POST path=/api/pending_closures7602026/07/19 11:19:12 INFO Received uploads request method=POST path=/api/pending_closures7612026-07-19 11:19:12.720 UTC [98899] ERROR: relation "goose_db_version" does not exist at character 367622026-07-19 11:19:12.720 UTC [98899] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC763=== NAME TestClientMultipleUploads764 client_integration_test.go:338: Created store path 0: /nix/var/nix/builds/nix-98732-3921061229/TestClientMultipleUploads1604909567/001/store/wb4ch4p2w330as46dd31211936zxk2xd-test-file-0.txt7652026/07/19 11:19:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)7662026/07/19 11:19:12 INFO Uploading l68hganw1m4fk81w0rnzs2qgrxsl0hg0-file1.txt (160B)7672026/07/19 11:19:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)7682026/07/19 11:19:12 INFO Uploading qsj1d8jll536sxydc1098dcq60xgchp7-test-file.txt (152B)7692026/07/19 11:19:12 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"7702026/07/19 11:19:12 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"7712026/07/19 11:19:12 WARN Failed to register uploaded object key=l68hganw1m4fk81w0rnzs2qgrxsl0hg0.ls error="server returned 404: 404 page not found\n"7722026/07/19 11:19:12 WARN Failed to register uploaded object key=qsj1d8jll536sxydc1098dcq60xgchp7.ls error="server returned 404: 404 page not found\n"7732026/07/19 11:19:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign7742026/07/19 11:19:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign7752026/07/19 11:19:12 INFO Signed narinfos id=1 count=17762026/07/19 11:19:12 INFO Signed narinfos id=1 count=17772026/07/19 11:19:12 INFO Uploading 1 narinfos7782026/07/19 11:19:12 INFO Uploading 1 narinfos7792026/07/19 11:19:12 WARN Failed to register uploaded object key=l68hganw1m4fk81w0rnzs2qgrxsl0hg0.narinfo error="server returned 404: 404 page not found\n"7802026/07/19 11:19:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7812026/07/19 11:19:12 WARN Failed to register uploaded object key=qsj1d8jll536sxydc1098dcq60xgchp7.narinfo error="server returned 404: 404 page not found\n"7822026/07/19 11:19:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7832026/07/19 11:19:12 OK 20241026095416_initial_model.sql (8.76ms)7842026/07/19 11:19:12 OK 20251210153512_drop_unused_gin_index.sql (662µs)7852026/07/19 11:19:12 OK 20251218171726_add_pins.sql (845.46µs)7862026-07-19 11:19:12.746 UTC [98904] ERROR: relation "goose_db_version" does not exist at character 367872026-07-19 11:19:12.746 UTC [98904] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7882026/07/19 11:19:12 INFO Completed upload id=17892026/07/19 11:19:12 INFO Upload complete. (127ms)7902026/07/19 11:19:12 INFO Completed upload id=17912026/07/19 11:19:12 INFO Upload complete. (129ms)792=== NAME TestNARDeduplicationMetadataUploadBug793 metadata_upload_test.go:54: Retrieved narinfo from S3:794 StorePath: /nix/var/nix/builds/nix-98732-3921061229/TestNARDeduplicationMetadataUploadBug3618534360/001/store/l68hganw1m4fk81w0rnzs2qgrxsl0hg0-file1.txt795 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst796 Compression: zstd797 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf798 NarSize: 160799 References: 800 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf8012026/07/19 11:19:12 OK 20260628120000_add_object_size_and_stats.sql (7.29ms)8022026/07/19 11:19:12 goose: successfully migrated database to version: 20260628120000803=== NAME TestClientIntegration804 client_integration_test.go:292: Retrieved narinfo from S3:805 StorePath: /nix/var/nix/builds/nix-98732-3921061229/TestClientIntegration1786046135/002/store/qsj1d8jll536sxydc1098dcq60xgchp7-test-file.txt806 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst807 Compression: zstd808 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1809 NarSize: 152810 References: 811 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1812=== NAME TestPinProtectsFromGC813 client_integration_test.go:646: Pinned store path: /nix/var/nix/builds/nix-98732-3921061229/TestPinProtectsFromGC2393072686/001/store/p1inv94icxixzpdcfisrjcagp6fw6ksw-pinned-file.txt814 client_integration_test.go:647: Unpinned store path: /nix/var/nix/builds/nix-98732-3921061229/TestPinProtectsFromGC2393072686/001/store/qpaxnwf7w3fnq74z7qb01b66fcp6szfq-unpinned-file.txt8152026/07/19 11:19:12 OK 1_commit_pending_closure.sql (1.48ms)816=== NAME TestNARDeduplicationMetadataUploadBug817 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)818 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):819 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}8202026/07/19 11:19:12 OK 2_object_stats_trigger.sql (901µs)8212026/07/19 11:19:12 goose: up to current file version: 2822=== NAME TestClientIntegration823 client_integration_test.go:293: Retrieved .ls file from S3 (compressed size: 77 bytes)824 client_integration_test.go:293: Decompressed .ls content (64 bytes):825 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}826 client_integration_test.go:296: Testing garbage collection...8272026/07/19 11:19:12 INFO Received uploads request method=POST path=/api/pending_closures8282026/07/19 11:19:12 OK 20241026095416_initial_model.sql (9.56ms)8292026/07/19 11:19:12 OK 20251210153512_drop_unused_gin_index.sql (925.67µs)8302026/07/19 11:19:12 INFO Received uploads request method=POST path=/api/pending_closures8312026/07/19 11:19:12 OK 20251218171726_add_pins.sql (1.02ms)8322026/07/19 11:19:12 OK 20260628120000_add_object_size_and_stats.sql (2.28ms)8332026/07/19 11:19:12 goose: successfully migrated database to version: 202606281200008342026/07/19 11:19:12 OK 1_commit_pending_closure.sql (1.27ms)8352026/07/19 11:19:12 OK 2_object_stats_trigger.sql (768.17µs)8362026/07/19 11:19:12 goose: up to current file version: 2837=== NAME TestClientMultipleUploads838 client_integration_test.go:338: Created store path 1: /nix/var/nix/builds/nix-98732-3921061229/TestClientMultipleUploads1604909567/001/store/5icrp2fwfpjxsvcqs3c3lqlc2ajfi3q7-test-file-1.txt8392026/07/19 11:19:12 INFO Received uploads request method=POST path=/api/pending_closures8402026-07-19 11:19:12.781 UTC [98933] ERROR: relation "goose_db_version" does not exist at character 368412026-07-19 11:19:12.781 UTC [98933] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC842--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.35s)843=== CONT TestService_cleanupPendingClosuresHandler8442026/07/19 11:19:12 INFO Starting cleanup of old closures method=DELETE path=/api/closures8452026/07/19 11:19:12 INFO Garbage collection started846=== NAME TestNARDeduplicationMetadataUploadBug847 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-98732-3921061229/TestNARDeduplicationMetadataUploadBug3618534360/001/store/2g3n7fc0xa2nmbqaj0cchrwm9s4i9x1n-file2.txt8482026/07/19 11:19:12 INFO Aborted multipart uploads count=08492026-07-19 11:19:12.808 UTC [98943] ERROR: relation "goose_db_version" does not exist at character 368502026-07-19 11:19:12.808 UTC [98943] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8512026/07/19 11:19:12 WARN Force mode enabled - objects will be deleted immediately without grace period852=== NAME TestClientMultipleUploads853 client_integration_test.go:338: Created store path 2: /nix/var/nix/builds/nix-98732-3921061229/TestClientMultipleUploads1604909567/001/store/kgf7m1byifvhlir0xisjf56bp9xqzyy6-test-file-2.txt8542026/07/19 11:19:12 OK 20241026095416_initial_model.sql (27.62ms)8552026/07/19 11:19:12 OK 20251210153512_drop_unused_gin_index.sql (1.24ms)8562026/07/19 11:19:12 OK 20251218171726_add_pins.sql (2.21ms)8572026/07/19 11:19:12 OK 20260628120000_add_object_size_and_stats.sql (2.99ms)8582026/07/19 11:19:12 goose: successfully migrated database to version: 202606281200008592026/07/19 11:19:12 OK 1_commit_pending_closure.sql (996.17µs)8602026/07/19 11:19:12 OK 2_object_stats_trigger.sql (725.58µs)8612026/07/19 11:19:12 goose: up to current file version: 28622026/07/19 11:19:12 OK 20241026095416_initial_model.sql (10.77ms)8632026/07/19 11:19:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8642026/07/19 11:19:12 OK 20251210153512_drop_unused_gin_index.sql (875.5µs)8652026/07/19 11:19:12 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst866--- PASS: TestCompleteMultipartUnregistered (0.38s)867=== CONT TestUploadHandlersRejectOversizedBody8682026/07/19 11:19:12 OK 20251218171726_add_pins.sql (6.78ms)8692026/07/19 11:19:12 OK 20260628120000_add_object_size_and_stats.sql (2.1ms)8702026/07/19 11:19:12 goose: successfully migrated database to version: 202606281200008712026/07/19 11:19:12 OK 1_commit_pending_closure.sql (2.04ms)8722026/07/19 11:19:12 OK 2_object_stats_trigger.sql (702.58µs)8732026/07/19 11:19:12 goose: up to current file version: 28742026/07/19 11:19:12 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"8752026/07/19 11:19:12 INFO Received uploads request method=POST path=/api/pending_closures876=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart877=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart878=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts879=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts880=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure881=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure882=== CONT TestUploadHandlersRejectInvalidKeys883=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info884=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info885=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal886=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal887=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key888=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key889=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key890=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key891=== CONT TestIsValidUploadKey892=== RUN TestIsValidUploadKey/narinfo893=== PAUSE TestIsValidUploadKey/narinfo894=== RUN TestIsValidUploadKey/nar_zst895=== PAUSE TestIsValidUploadKey/nar_zst896=== RUN TestIsValidUploadKey/nar_xz897=== PAUSE TestIsValidUploadKey/nar_xz898=== RUN TestIsValidUploadKey/nar_plain899=== PAUSE TestIsValidUploadKey/nar_plain900=== RUN TestIsValidUploadKey/listing901=== PAUSE TestIsValidUploadKey/listing902=== RUN TestIsValidUploadKey/build_log903=== PAUSE TestIsValidUploadKey/build_log904=== RUN TestIsValidUploadKey/build_log_home-manager_file905=== PAUSE TestIsValidUploadKey/build_log_home-manager_file906=== RUN TestIsValidUploadKey/build_log_plus_in_name907=== PAUSE TestIsValidUploadKey/build_log_plus_in_name908=== RUN TestIsValidUploadKey/build_log_question_mark909=== PAUSE TestIsValidUploadKey/build_log_question_mark910=== RUN TestIsValidUploadKey/build_log_equals911=== PAUSE TestIsValidUploadKey/build_log_equals912=== RUN TestIsValidUploadKey/realisation913=== PAUSE TestIsValidUploadKey/realisation914=== RUN TestIsValidUploadKey/realisation_plus_in_output915=== PAUSE TestIsValidUploadKey/realisation_plus_in_output916=== RUN TestIsValidUploadKey/nix-cache-info917=== PAUSE TestIsValidUploadKey/nix-cache-info918=== RUN TestIsValidUploadKey/index.html919=== PAUSE TestIsValidUploadKey/index.html920=== RUN TestIsValidUploadKey/narinfo_key,_nar_type921=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type922=== RUN TestIsValidUploadKey/nar_key,_narinfo_type923=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type924=== RUN TestIsValidUploadKey/listing_key,_narinfo_type925=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type926=== RUN TestIsValidUploadKey/traversal927=== PAUSE TestIsValidUploadKey/traversal928=== RUN TestIsValidUploadKey/traversal_nar929=== PAUSE TestIsValidUploadKey/traversal_nar930=== RUN TestIsValidUploadKey/absolute931=== PAUSE TestIsValidUploadKey/absolute932=== RUN TestIsValidUploadKey/empty_key933=== PAUSE TestIsValidUploadKey/empty_key934=== RUN TestIsValidUploadKey/unknown_type935=== PAUSE TestIsValidUploadKey/unknown_type936=== CONT TestProxyWriteTimeout937=== RUN TestProxyWriteTimeout/narinfo938=== PAUSE TestProxyWriteTimeout/narinfo939=== RUN TestProxyWriteTimeout/1_GiB_nar940=== PAUSE TestProxyWriteTimeout/1_GiB_nar941=== RUN TestProxyWriteTimeout/10_GiB_nar942=== PAUSE TestProxyWriteTimeout/10_GiB_nar943=== RUN TestProxyWriteTimeout/unknown_size944=== PAUSE TestProxyWriteTimeout/unknown_size945=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle9462026/07/19 11:19:12 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9472026/07/19 11:19:12 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9482026/07/19 11:19:12 INFO Received uploads request method=POST path=/api/pending_closures9492026/07/19 11:19:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9502026/07/19 11:19:12 INFO Uploading p1inv94icxixzpdcfisrjcagp6fw6ksw-pinned-file.txt (128B)9512026/07/19 11:19:12 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"9522026/07/19 11:19:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9532026/07/19 11:19:12 WARN Failed to register uploaded object key=p1inv94icxixzpdcfisrjcagp6fw6ksw.ls error="server returned 404: 404 page not found\n"9542026/07/19 11:19:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9552026/07/19 11:19:12 INFO Signed narinfos id=1 count=19562026/07/19 11:19:12 INFO Uploading 1 narinfos9572026/07/19 11:19:12 WARN Failed to register uploaded object key=p1inv94icxixzpdcfisrjcagp6fw6ksw.narinfo error="server returned 404: 404 page not found\n"9582026/07/19 11:19:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9592026/07/19 11:19:12 INFO Completed upload id=19602026/07/19 11:19:12 INFO Upload complete. (125ms)961=== NAME TestClientWithDependencies962 client_integration_test.go:593: Built derivation: /nix/var/nix/builds/nix-98732-3921061229/TestClientWithDependencies1981393807/001/store/0lbim34kj8rwr3rwnahkhh6hpmczzzll-test-script9632026/07/19 11:19:12 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YzhiNjFlMjgtNDNjYy00ZGE4LWE4ZjAtZjM4MWM0YmE3YmFjLjZiNDhiNzA0LTQxYTAtNGVkMy1iMjExLTQwZWJmMDkzM2JkYXgxNzg0NDU5OTUyNzYxMTYxMDAw parts=12964--- PASS: TestRedundantMultipartUpload (0.49s)965=== CONT TestParseSize966--- PASS: TestParseSize (0.00s)967=== CONT TestService_Rustfstest9682026/07/19 11:19:12 INFO Received uploads request method=POST path=/api/pending_closures9692026/07/19 11:19:12 INFO Received uploads request method=POST path=/api/pending_closures9702026/07/19 11:19:12 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)9712026/07/19 11:19:12 WARN Failed to register uploaded object key=2g3n7fc0xa2nmbqaj0cchrwm9s4i9x1n.ls error="server returned 404: 404 page not found\n"9722026/07/19 11:19:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign9732026/07/19 11:19:12 INFO Signed narinfos id=2 count=19742026/07/19 11:19:12 INFO Uploading 1 narinfos9752026/07/19 11:19:12 INFO Received uploads request method=POST path=/api/pending_closures9762026/07/19 11:19:12 WARN Failed to register uploaded object key=2g3n7fc0xa2nmbqaj0cchrwm9s4i9x1n.narinfo error="server returned 404: 404 page not found\n"9772026/07/19 11:19:12 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete9782026/07/19 11:19:12 INFO Completed upload id=29792026/07/19 11:19:12 INFO Upload complete. (91ms)9802026/07/19 11:19:12 INFO Received uploads request method=POST path=/api/pending_closures981=== NAME TestNARDeduplicationMetadataUploadBug982 metadata_upload_test.go:76: Retrieved narinfo from S3:983 StorePath: /nix/var/nix/builds/nix-98732-3921061229/TestNARDeduplicationMetadataUploadBug3618534360/001/store/2g3n7fc0xa2nmbqaj0cchrwm9s4i9x1n-file2.txt984 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst985 Compression: zstd986 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf987 NarSize: 160988 References: 989 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf9902026/07/19 11:19:12 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)9912026/07/19 11:19:12 INFO Uploading kgf7m1byifvhlir0xisjf56bp9xqzyy6-test-file-2.txt (160B)9922026/07/19 11:19:12 INFO Uploading 5icrp2fwfpjxsvcqs3c3lqlc2ajfi3q7-test-file-1.txt (160B)9932026/07/19 11:19:12 INFO Uploading wb4ch4p2w330as46dd31211936zxk2xd-test-file-0.txt (160B)9942026/07/19 11:19:12 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"995 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)996 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):997 {"version":1,"root":{"type":"regular","size":44}}9982026/07/19 11:19:12 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"9992026/07/19 11:19:12 WARN Failed to register uploaded object key=kgf7m1byifvhlir0xisjf56bp9xqzyy6.ls error="server returned 404: 404 page not found\n"10002026/07/19 11:19:12 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"10012026/07/19 11:19:12 WARN Failed to register uploaded object key=5icrp2fwfpjxsvcqs3c3lqlc2ajfi3q7.ls error="server returned 404: 404 page not found\n"10022026/07/19 11:19:12 WARN Failed to register uploaded object key=wb4ch4p2w330as46dd31211936zxk2xd.ls error="server returned 404: 404 page not found\n"10032026/07/19 11:19:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign1004--- PASS: TestNARDeduplicationMetadataUploadBug (0.86s)1005=== CONT TestPresignedUploadRegisteredBeforeCommit10062026/07/19 11:19:12 INFO Signed narinfos id=2 count=110072026/07/19 11:19:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign10082026/07/19 11:19:12 INFO Signed narinfos id=3 count=110092026/07/19 11:19:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10102026/07/19 11:19:12 INFO Signed narinfos id=1 count=110112026/07/19 11:19:12 INFO Uploading 3 narinfos10122026/07/19 11:19:12 WARN Failed to register uploaded object key=wb4ch4p2w330as46dd31211936zxk2xd.narinfo error="server returned 404: 404 page not found\n"10132026/07/19 11:19:12 WARN Failed to register uploaded object key=kgf7m1byifvhlir0xisjf56bp9xqzyy6.narinfo error="server returned 404: 404 page not found\n"10142026/07/19 11:19:12 WARN Failed to register uploaded object key=5icrp2fwfpjxsvcqs3c3lqlc2ajfi3q7.narinfo error="server returned 404: 404 page not found\n"10152026/07/19 11:19:12 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10162026/07/19 11:19:12 INFO Completed upload id=210172026/07/19 11:19:12 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete10182026/07/19 11:19:12 INFO Completed upload id=310192026/07/19 11:19:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10202026/07/19 11:19:12 INFO Completed upload id=110212026/07/19 11:19:12 INFO Upload complete. (103ms)1022=== NAME TestClientWithDependencies1023 client_integration_test.go:595: Found 1 dependencies (including self)1024=== NAME TestClientMultipleUploads1025 client_integration_test.go:349: Uploaded 3 paths in 150.086083ms1026--- PASS: TestClientMultipleUploads (0.53s)1027=== CONT TestCompletedNarNotReofferedAcrossClosures10282026-07-19 11:19:12.973 UTC [98970] ERROR: relation "goose_db_version" does not exist at character 3610292026-07-19 11:19:12.973 UTC [98970] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10302026/07/19 11:19:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10312026/07/19 11:19:12 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YzhiNjFlMjgtNDNjYy00ZGE4LWE4ZjAtZjM4MWM0YmE3YmFjLmJmODYyMDEwLTYxOGUtNDI0Zi1iYWM2LTJjYzkzYzNkOGI2ZngxNzg0NDU5OTUyODU0NDk5MDAw parts=1010322026/07/19 11:19:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10332026/07/19 11:19:12 INFO Completed upload id=110342026/07/19 11:19:12 INFO Received uploads request method=POST path=/api/pending_closures10352026/07/19 11:19:12 INFO Received uploads request method=POST path=/api/pending_closures10362026/07/19 11:19:12 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10372026/07/19 11:19:12 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10382026/07/19 11:19:12 WARN Found objects in DB but missing from S3, will re-upload count=11039--- PASS: TestService_verifyS3Integrity (0.44s)1040=== CONT TestCompleteMultipartUpload_ErrorButObjectExists10412026/07/19 11:19:13 OK 20241026095416_initial_model.sql (6.83ms)10422026/07/19 11:19:13 OK 20251210153512_drop_unused_gin_index.sql (625.38µs)10432026/07/19 11:19:13 OK 20251218171726_add_pins.sql (1.54ms)10442026/07/19 11:19:13 OK 20260628120000_add_object_size_and_stats.sql (3.83ms)10452026/07/19 11:19:13 goose: successfully migrated database to version: 2026062812000010462026/07/19 11:19:13 OK 1_commit_pending_closure.sql (1.17ms)10472026/07/19 11:19:13 OK 2_object_stats_trigger.sql (261.79µs)10482026/07/19 11:19:13 goose: up to current file version: 210492026/07/19 11:19:13 INFO Received uploads request method=POST path=/api/pending_closures10502026/07/19 11:19:13 INFO Received uploads request method=POST path=/api/pending_closures10512026/07/19 11:19:13 INFO Received uploads request method=POST path=/api/pending_closures10522026/07/19 11:19:13 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10532026/07/19 11:19:13 INFO Received uploads request method=POST path=/api/pending_closures10542026/07/19 11:19:13 INFO Received uploads request method=POST path=/api/pending_closures10552026/07/19 11:19:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10562026/07/19 11:19:13 INFO Uploading qpaxnwf7w3fnq74z7qb01b66fcp6szfq-unpinned-file.txt (128B)10572026/07/19 11:19:13 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"10582026/07/19 11:19:13 WARN Failed to register uploaded object key=qpaxnwf7w3fnq74z7qb01b66fcp6szfq.ls error="server returned 404: 404 page not found\n"10592026/07/19 11:19:13 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign10602026/07/19 11:19:13 INFO Signed narinfos id=2 count=110612026/07/19 11:19:13 INFO Uploading 1 narinfos10622026/07/19 11:19:13 WARN Failed to register uploaded object key=qpaxnwf7w3fnq74z7qb01b66fcp6szfq.narinfo error="server returned 404: 404 page not found\n"10632026/07/19 11:19:13 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10642026/07/19 11:19:13 INFO Completed upload id=210652026/07/19 11:19:13 INFO Upload complete. (76ms)10662026/07/19 11:19:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10672026/07/19 11:19:13 INFO Uploading 0lbim34kj8rwr3rwnahkhh6hpmczzzll-test-script (136B)10682026/07/19 11:19:13 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"10692026/07/19 11:19:13 WARN Failed to register uploaded object key=log/2cfmmj7lnkc73mr48w6332bk77bfhls8-test-script.drv error="server returned 404: 404 page not found\n"10702026/07/19 11:19:13 WARN Failed to register uploaded object key=0lbim34kj8rwr3rwnahkhh6hpmczzzll.ls error="server returned 404: 404 page not found\n"10712026/07/19 11:19:13 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10722026/07/19 11:19:13 INFO Signed narinfos id=1 count=110732026/07/19 11:19:13 INFO Uploading 1 narinfos10742026/07/19 11:19:13 WARN Failed to register uploaded object key=0lbim34kj8rwr3rwnahkhh6hpmczzzll.narinfo error="server returned 404: 404 page not found\n"10752026/07/19 11:19:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10762026/07/19 11:19:13 INFO Completed upload id=110772026/07/19 11:19:13 INFO Upload complete. (51ms)1078=== NAME TestClientWithDependencies1079 client_integration_test.go:597: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-98732-3921061229/TestClientWithDependencies1981393807/001/store) requires matching store prefix1080--- PASS: TestClientWithDependencies (0.62s)1081=== CONT TestCacheConfigHandler1082=== RUN TestCacheConfigHandler/full_config,_no_issuer1083=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1084=== RUN TestCacheConfigHandler/no_cache_url_configured1085=== PAUSE TestCacheConfigHandler/no_cache_url_configured1086=== RUN TestCacheConfigHandler/no_signing_keys1087=== PAUSE TestCacheConfigHandler/no_signing_keys1088=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1089=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1090=== CONT TestClientErrorHandling1091=== RUN TestClientErrorHandling/InvalidStorePath1092=== PAUSE TestClientErrorHandling/InvalidStorePath1093=== RUN TestClientErrorHandling/InvalidAuthToken1094=== PAUSE TestClientErrorHandling/InvalidAuthToken1095=== RUN TestClientErrorHandling/ServerNotAvailable1096=== PAUSE TestClientErrorHandling/ServerNotAvailable1097=== CONT TestClientCADerivations10982026/07/19 11:19:13 INFO Received create pin request method=POST path=/api/pins/myapp10992026/07/19 11:19:13 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-98732-3921061229/TestPinProtectsFromGC2393072686/001/store/p1inv94icxixzpdcfisrjcagp6fw6ksw-pinned-file.txt narinfo_key=p1inv94icxixzpdcfisrjcagp6fw6ksw.narinfo11002026/07/19 11:19:13 INFO Starting cleanup of old closures method=DELETE path=/api/closures11012026/07/19 11:19:13 INFO Garbage collection started11022026/07/19 11:19:13 INFO Aborted multipart uploads count=011032026/07/19 11:19:13 WARN Force mode enabled - objects will be deleted immediately without grace period11042026-07-19 11:19:13.120 UTC [98987] ERROR: relation "goose_db_version" does not exist at character 3611052026-07-19 11:19:13.120 UTC [98987] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11062026/07/19 11:19:13 OK 20241026095416_initial_model.sql (11.61ms)11072026/07/19 11:19:13 OK 20251210153512_drop_unused_gin_index.sql (1.63ms)11082026/07/19 11:19:13 OK 20251218171726_add_pins.sql (1.07ms)11092026/07/19 11:19:13 OK 20260628120000_add_object_size_and_stats.sql (1.09ms)11102026/07/19 11:19:13 goose: successfully migrated database to version: 2026062812000011112026/07/19 11:19:13 OK 1_commit_pending_closure.sql (885.04µs)11122026/07/19 11:19:13 OK 2_object_stats_trigger.sql (200.21µs)11132026/07/19 11:19:13 goose: up to current file version: 211142026/07/19 11:19:13 INFO Received cleanup request method=DELETE path=/api/pending_closures11152026/07/19 11:19:13 INFO Aborted multipart uploads count=011162026/07/19 11:19:13 INFO Received uploads request method=POST path=/api/pending_closures11172026/07/19 11:19:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11182026/07/19 11:19:13 INFO Received cleanup request method=DELETE path=/api/pending_closures11192026/07/19 11:19:13 INFO Aborted multipart uploads count=111202026/07/19 11:19:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11212026-07-19 11:19:13.163 UTC [98987] ERROR: Closure does not exist: id=111222026-07-19 11:19:13.163 UTC [98987] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE11232026-07-19 11:19:13.163 UTC [98987] STATEMENT: -- name: CommitPendingClosure :exec1124 SELECT commit_pending_closure($1::bigint)1125 1126--- PASS: TestService_cleanupPendingClosuresHandler (0.37s)1127=== CONT TestCacheStatsHandler11282026/07/19 11:19:13 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YzhiNjFlMjgtNDNjYy00ZGE4LWE4ZjAtZjM4MWM0YmE3YmFjLmIxMDJlOWQwLTRhN2QtNGQ2MC05MDRiLTQ5MDFhMzc5MjgyZHgxNzg0NDU5OTUzMDMyMjM2MDAw parts=1011292026/07/19 11:19:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11302026/07/19 11:19:13 INFO Completed upload id=111312026/07/19 11:19:13 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011322026/07/19 11:19:13 INFO Received uploads request method=POST path=/api/pending_closures11332026/07/19 11:19:13 INFO Starting cleanup of old closures method=DELETE path=/api/closures11342026/07/19 11:19:13 INFO Aborted multipart uploads count=011352026/07/19 11:19:13 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=011362026/07/19 11:19:13 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=011372026/07/19 11:19:13 INFO Vacuumed table table=pending_closures11382026/07/19 11:19:13 INFO Vacuumed table table=pending_closures11392026/07/19 11:19:13 INFO Vacuumed table table=pending_objects11402026/07/19 11:19:13 INFO Vacuumed table table=multipart_uploads11412026/07/19 11:19:13 INFO Vacuumed table table=pending_objects11422026/07/19 11:19:13 INFO Vacuumed table table=closures11432026/07/19 11:19:13 INFO Vacuumed table table=multipart_uploads11442026/07/19 11:19:13 INFO Vacuumed table table=closures11452026/07/19 11:19:13 INFO Vacuumed table table=objects11462026/07/19 11:19:13 INFO Vacuumed table table=objects11472026/07/19 11:19:13 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001148--- PASS: TestService_createPendingClosureHandler (0.57s)1149=== CONT TestReadProxyNarStreaming11502026-07-19 11:19:13.249 UTC [98993] ERROR: relation "goose_db_version" does not exist at character 3611512026-07-19 11:19:13.249 UTC [98993] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11522026/07/19 11:19:13 OK 20241026095416_initial_model.sql (7.79ms)11532026/07/19 11:19:13 OK 20251210153512_drop_unused_gin_index.sql (399.71µs)11542026/07/19 11:19:13 OK 20251218171726_add_pins.sql (843.08µs)11552026/07/19 11:19:13 OK 20260628120000_add_object_size_and_stats.sql (5.95ms)11562026/07/19 11:19:13 goose: successfully migrated database to version: 2026062812000011572026/07/19 11:19:13 OK 1_commit_pending_closure.sql (1.13ms)11582026/07/19 11:19:13 OK 2_object_stats_trigger.sql (221.71µs)11592026/07/19 11:19:13 goose: up to current file version: 211602026/07/19 11:19:13 INFO Received uploads request method=POST path=/api/pending_closures11612026-07-19 11:19:13.297 UTC [98995] ERROR: relation "goose_db_version" does not exist at character 3611622026-07-19 11:19:13.297 UTC [98995] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11632026/07/19 11:19:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11642026-07-19 11:19:13.318 UTC [98996] ERROR: relation "goose_db_version" does not exist at character 3611652026-07-19 11:19:13.318 UTC [98996] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11662026-07-19 11:19:13.333 UTC [98998] ERROR: relation "goose_db_version" does not exist at character 3611672026-07-19 11:19:13.333 UTC [98998] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11682026-07-19 11:19:13.333 UTC [98997] ERROR: relation "goose_db_version" does not exist at character 3611692026-07-19 11:19:13.333 UTC [98997] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11702026/07/19 11:19:13 OK 20241026095416_initial_model.sql (29.26ms)11712026/07/19 11:19:13 OK 20251210153512_drop_unused_gin_index.sql (372.04µs)11722026/07/19 11:19:13 OK 20251218171726_add_pins.sql (729.33µs)11732026/07/19 11:19:13 OK 20260628120000_add_object_size_and_stats.sql (6.32ms)11742026/07/19 11:19:13 goose: successfully migrated database to version: 2026062812000011752026/07/19 11:19:13 OK 1_commit_pending_closure.sql (1.28ms)11762026/07/19 11:19:13 OK 20241026095416_initial_model.sql (23.16ms)11772026/07/19 11:19:13 OK 2_object_stats_trigger.sql (337.13µs)11782026/07/19 11:19:13 goose: up to current file version: 211792026/07/19 11:19:13 OK 20251210153512_drop_unused_gin_index.sql (786.92µs)1180--- PASS: TestService_Rustfstest (0.42s)1181=== CONT TestReadProxyRangeRequest11822026/07/19 11:19:13 OK 20251218171726_add_pins.sql (1.65ms)11832026/07/19 11:19:13 OK 20241026095416_initial_model.sql (7.69ms)11842026/07/19 11:19:13 OK 20260628120000_add_object_size_and_stats.sql (3.29ms)11852026/07/19 11:19:13 goose: successfully migrated database to version: 2026062812000011862026/07/19 11:19:13 OK 20241026095416_initial_model.sql (7.49ms)11872026/07/19 11:19:13 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=011882026/07/19 11:19:13 OK 20251210153512_drop_unused_gin_index.sql (704.13µs)11892026/07/19 11:19:13 OK 20251210153512_drop_unused_gin_index.sql (654.25µs)11902026/07/19 11:19:13 OK 1_commit_pending_closure.sql (1.61ms)11912026/07/19 11:19:13 OK 2_object_stats_trigger.sql (211.92µs)11922026/07/19 11:19:13 goose: up to current file version: 211932026/07/19 11:19:13 INFO Received uploads request method=POST path=/api/pending_closures11942026/07/19 11:19:13 OK 20251218171726_add_pins.sql (2.28ms)11952026/07/19 11:19:13 OK 20251218171726_add_pins.sql (2.81ms)11962026/07/19 11:19:13 INFO Vacuumed table table=pending_closures11972026/07/19 11:19:13 OK 20260628120000_add_object_size_and_stats.sql (1.89ms)11982026/07/19 11:19:13 goose: successfully migrated database to version: 2026062812000011992026/07/19 11:19:13 OK 20260628120000_add_object_size_and_stats.sql (2.73ms)12002026/07/19 11:19:13 goose: successfully migrated database to version: 2026062812000012012026/07/19 11:19:13 OK 1_commit_pending_closure.sql (1.01ms)12022026/07/19 11:19:13 OK 2_object_stats_trigger.sql (255.63µs)12032026/07/19 11:19:13 goose: up to current file version: 212042026/07/19 11:19:13 OK 1_commit_pending_closure.sql (819.21µs)12052026/07/19 11:19:13 OK 2_object_stats_trigger.sql (289.71µs)12062026/07/19 11:19:13 goose: up to current file version: 212072026/07/19 11:19:13 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst12082026/07/19 11:19:13 INFO Received uploads request method=POST path=/api/pending_closures12092026/07/19 11:19:13 INFO Vacuumed table table=pending_objects12102026/07/19 11:19:13 INFO Received uploads request method=POST path=/api/pending_closures12112026/07/19 11:19:13 INFO Vacuumed table table=multipart_uploads1212--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.42s)1213=== CONT TestReadProxyDisabled12142026/07/19 11:19:13 INFO Vacuumed table table=closures12152026/07/19 11:19:13 INFO Received uploads request method=POST path=/api/pending_closures12162026/07/19 11:19:13 INFO Vacuumed table table=objects12172026/07/19 11:19:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1218{"timestamp":"2026-07-19T11:19:13.373607Z","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(6)"}1219{"timestamp":"2026-07-19T11:19:13.373634Z","level":"ERROR","fields":{"message":"complete_multipart_upload etag err client=Some(\"deadbeef\"), stored=\"\", part_id=1, bucket=bucket24, 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(6)"}12202026/07/19 11:19:13 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=YzhiNjFlMjgtNDNjYy00ZGE4LWE4ZjAtZjM4MWM0YmE3YmFjLmIyOTE2MDQ5LWUxM2ItNDk0ZC1iNzdmLTc0MDEzZGU2ZTQ5M3gxNzg0NDU5OTUzMzY2OTI3MDAw12212026/07/19 11:19:13 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YzhiNjFlMjgtNDNjYy00ZGE4LWE4ZjAtZjM4MWM0YmE3YmFjLmIyOTE2MDQ5LWUxM2ItNDk0ZC1iNzdmLTc0MDEzZGU2ZTQ5M3gxNzg0NDU5OTUzMzY2OTI3MDAw parts=11222--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.38s)1223=== CONT TestReadProxyRootRedirectsToIndexHTML12242026-07-19 11:19:13.432 UTC [99005] ERROR: relation "goose_db_version" does not exist at character 3612252026-07-19 11:19:13.432 UTC [99005] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12262026/07/19 11:19:13 OK 20241026095416_initial_model.sql (10.56ms)12272026/07/19 11:19:13 OK 20251210153512_drop_unused_gin_index.sql (483.04µs)12282026/07/19 11:19:13 OK 20251218171726_add_pins.sql (1ms)12292026/07/19 11:19:13 OK 20260628120000_add_object_size_and_stats.sql (6.98ms)12302026/07/19 11:19:13 goose: successfully migrated database to version: 2026062812000012312026/07/19 11:19:13 OK 1_commit_pending_closure.sql (1.12ms)12322026/07/19 11:19:13 OK 2_object_stats_trigger.sql (268.42µs)12332026/07/19 11:19:13 goose: up to current file version: 212342026/07/19 11:19:13 INFO Created nix-cache-info in bucket bucket=bucket2612352026/07/19 11:19:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12362026/07/19 11:19:13 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YzhiNjFlMjgtNDNjYy00ZGE4LWE4ZjAtZjM4MWM0YmE3YmFjLjU3OGYyMGQwLWEyNDctNDZmMS1iYmZlLWM3NTdjYmNmNzdjN3gxNzg0NDU5OTUzMzY2OTg4MDAw parts=1212372026/07/19 11:19:13 INFO Received uploads request method=POST path=/api/pending_closures1238--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.53s)1239=== CONT TestReadProxyConditionalGet12402026-07-19 11:19:13.552 UTC [99011] ERROR: relation "goose_db_version" does not exist at character 3612412026-07-19 11:19:13.552 UTC [99011] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12422026/07/19 11:19:13 OK 20241026095416_initial_model.sql (6.95ms)12432026/07/19 11:19:13 OK 20251210153512_drop_unused_gin_index.sql (454.38µs)12442026/07/19 11:19:13 OK 20251218171726_add_pins.sql (802.63µs)12452026/07/19 11:19:13 OK 20260628120000_add_object_size_and_stats.sql (3.7ms)12462026/07/19 11:19:13 goose: successfully migrated database to version: 2026062812000012472026/07/19 11:19:13 OK 1_commit_pending_closure.sql (1.15ms)12482026/07/19 11:19:13 OK 2_object_stats_trigger.sql (265.17µs)12492026/07/19 11:19:13 goose: up to current file version: 21250--- PASS: TestCacheStatsHandler (0.42s)1251=== CONT TestReadProxyHead12522026-07-19 11:19:13.602 UTC [99016] ERROR: relation "goose_db_version" does not exist at character 3612532026-07-19 11:19:13.602 UTC [99016] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12542026/07/19 11:19:13 OK 20241026095416_initial_model.sql (5.9ms)12552026/07/19 11:19:13 OK 20251210153512_drop_unused_gin_index.sql (505.88µs)12562026/07/19 11:19:13 OK 20251218171726_add_pins.sql (2.05ms)12572026/07/19 11:19:13 OK 20260628120000_add_object_size_and_stats.sql (4.73ms)12582026/07/19 11:19:13 goose: successfully migrated database to version: 2026062812000012592026/07/19 11:19:13 OK 1_commit_pending_closure.sql (1.03ms)12602026/07/19 11:19:13 OK 2_object_stats_trigger.sql (318.71µs)12612026/07/19 11:19:13 goose: up to current file version: 21262--- PASS: TestReadProxyNarStreaming (0.42s)1263=== CONT TestReadProxyInvalidPath12642026-07-19 11:19:13.643 UTC [99018] ERROR: relation "goose_db_version" does not exist at character 3612652026-07-19 11:19:13.643 UTC [99018] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12662026/07/19 11:19:13 OK 20241026095416_initial_model.sql (5.19ms)12672026/07/19 11:19:13 OK 20251210153512_drop_unused_gin_index.sql (344.88µs)12682026/07/19 11:19:13 OK 20251218171726_add_pins.sql (1.18ms)12692026/07/19 11:19:13 OK 20260628120000_add_object_size_and_stats.sql (2.78ms)12702026/07/19 11:19:13 goose: successfully migrated database to version: 2026062812000012712026/07/19 11:19:13 OK 1_commit_pending_closure.sql (893.83µs)12722026/07/19 11:19:13 OK 2_object_stats_trigger.sql (206.54µs)12732026/07/19 11:19:13 goose: up to current file version: 21274--- PASS: TestReadProxyRangeRequest (0.31s)1275=== CONT TestReadProxy40412762026-07-19 11:19:13.666 UTC [99020] ERROR: relation "goose_db_version" does not exist at character 3612772026-07-19 11:19:13.666 UTC [99020] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12782026/07/19 11:19:13 OK 20241026095416_initial_model.sql (7.36ms)12792026/07/19 11:19:13 OK 20251210153512_drop_unused_gin_index.sql (492µs)12802026/07/19 11:19:13 OK 20251218171726_add_pins.sql (1.93ms)12812026/07/19 11:19:13 OK 20260628120000_add_object_size_and_stats.sql (2.98ms)12822026/07/19 11:19:13 goose: successfully migrated database to version: 2026062812000012832026/07/19 11:19:13 OK 1_commit_pending_closure.sql (839.13µs)12842026/07/19 11:19:13 OK 2_object_stats_trigger.sql (210.71µs)12852026/07/19 11:19:13 goose: up to current file version: 21286=== NAME TestClientCADerivations1287 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-98732-3921061229/TestClientCADerivations1279398772/001/store/znf3pyf9ypxahgmgmbgnm2sqnrxmd94g-ca-test1288--- PASS: TestReadProxyDisabled (0.33s)1289=== CONT TestParseSingleRange1290=== RUN TestParseSingleRange/none1291=== PAUSE TestParseSingleRange/none1292=== RUN TestParseSingleRange/unknown_unit1293=== PAUSE TestParseSingleRange/unknown_unit1294=== RUN TestParseSingleRange/multi-range_ignored1295=== PAUSE TestParseSingleRange/multi-range_ignored1296=== RUN TestParseSingleRange/malformed_no_dash1297=== PAUSE TestParseSingleRange/malformed_no_dash1298=== RUN TestParseSingleRange/malformed_both_empty1299=== PAUSE TestParseSingleRange/malformed_both_empty1300=== RUN TestParseSingleRange/malformed_end_before_start1301=== PAUSE TestParseSingleRange/malformed_end_before_start1302=== RUN TestParseSingleRange/closed1303=== PAUSE TestParseSingleRange/closed1304=== RUN TestParseSingleRange/open-ended1305=== PAUSE TestParseSingleRange/open-ended1306=== RUN TestParseSingleRange/end_clamped_to_size1307=== PAUSE TestParseSingleRange/end_clamped_to_size1308=== RUN TestParseSingleRange/suffix1309=== PAUSE TestParseSingleRange/suffix1310=== RUN TestParseSingleRange/suffix_exceeds_size1311=== PAUSE TestParseSingleRange/suffix_exceeds_size1312=== RUN TestParseSingleRange/single_byte1313=== PAUSE TestParseSingleRange/single_byte1314=== RUN TestParseSingleRange/start_past_EOF1315=== PAUSE TestParseSingleRange/start_past_EOF1316=== RUN TestParseSingleRange/start_far_past_EOF1317=== PAUSE TestParseSingleRange/start_far_past_EOF1318=== CONT TestReadProxyNarinfoAlreadyDecompressed13192026-07-19 11:19:13.696 UTC [99025] ERROR: relation "goose_db_version" does not exist at character 3613202026-07-19 11:19:13.696 UTC [99025] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13212026/07/19 11:19:13 OK 20241026095416_initial_model.sql (7.24ms)13222026/07/19 11:19:13 OK 20251210153512_drop_unused_gin_index.sql (798.75µs)13232026/07/19 11:19:13 OK 20251218171726_add_pins.sql (1.29ms)13242026/07/19 11:19:13 OK 20260628120000_add_object_size_and_stats.sql (3.02ms)13252026/07/19 11:19:13 goose: successfully migrated database to version: 2026062812000013262026/07/19 11:19:13 OK 1_commit_pending_closure.sql (1.01ms)13272026/07/19 11:19:13 OK 2_object_stats_trigger.sql (549.25µs)13282026/07/19 11:19:13 goose: up to current file version: 21329=== NAME TestClientCADerivations1330 client_ca_test.go:139: Found 1 dependencies (including self)1331--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.35s)1332=== CONT TestReadProxyNarinfo13332026-07-19 11:19:13.767 UTC [99033] ERROR: relation "goose_db_version" does not exist at character 3613342026-07-19 11:19:13.767 UTC [99033] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13352026/07/19 11:19:13 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13362026/07/19 11:19:13 OK 20241026095416_initial_model.sql (5.84ms)13372026/07/19 11:19:13 OK 20251210153512_drop_unused_gin_index.sql (427.04µs)13382026/07/19 11:19:13 OK 20251218171726_add_pins.sql (725.17µs)13392026/07/19 11:19:13 OK 20260628120000_add_object_size_and_stats.sql (2.85ms)13402026/07/19 11:19:13 goose: successfully migrated database to version: 2026062812000013412026/07/19 11:19:13 OK 1_commit_pending_closure.sql (1.06ms)13422026/07/19 11:19:13 OK 2_object_stats_trigger.sql (323.08µs)13432026/07/19 11:19:13 goose: up to current file version: 21344--- PASS: TestReadProxyConditionalGet (0.30s)1345=== CONT TestIsValidCachePath1346=== RUN TestIsValidCachePath/narinfo1347=== PAUSE TestIsValidCachePath/narinfo1348=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1349=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1350=== RUN TestIsValidCachePath/nar_zst1351=== PAUSE TestIsValidCachePath/nar_zst1352=== RUN TestIsValidCachePath/nar_xz1353=== PAUSE TestIsValidCachePath/nar_xz1354=== RUN TestIsValidCachePath/nar_bz21355=== PAUSE TestIsValidCachePath/nar_bz21356=== RUN TestIsValidCachePath/nar_uncompressed1357=== PAUSE TestIsValidCachePath/nar_uncompressed1358=== RUN TestIsValidCachePath/ls1359=== PAUSE TestIsValidCachePath/ls1360=== RUN TestIsValidCachePath/log1361=== PAUSE TestIsValidCachePath/log1362=== RUN TestIsValidCachePath/realisation1363=== PAUSE TestIsValidCachePath/realisation1364=== RUN TestIsValidCachePath/nix-cache-info1365=== PAUSE TestIsValidCachePath/nix-cache-info1366=== RUN TestIsValidCachePath/index.html1367=== PAUSE TestIsValidCachePath/index.html1368=== RUN TestIsValidCachePath/traversal_parent1369=== PAUSE TestIsValidCachePath/traversal_parent1370=== RUN TestIsValidCachePath/traversal_in_middle1371=== PAUSE TestIsValidCachePath/traversal_in_middle1372=== RUN TestIsValidCachePath/invalid_char_e1373=== PAUSE TestIsValidCachePath/invalid_char_e1374=== RUN TestIsValidCachePath/invalid_char_u1375=== PAUSE TestIsValidCachePath/invalid_char_u1376=== RUN TestIsValidCachePath/random_path1377=== PAUSE TestIsValidCachePath/random_path1378=== RUN TestIsValidCachePath/empty1379=== PAUSE TestIsValidCachePath/empty1380=== RUN TestIsValidCachePath/leading_slash1381=== PAUSE TestIsValidCachePath/leading_slash1382=== RUN TestIsValidCachePath/wrong_extension1383=== PAUSE TestIsValidCachePath/wrong_extension1384=== RUN TestIsValidCachePath/short_hash1385=== PAUSE TestIsValidCachePath/short_hash1386=== CONT TestOrphanedObjectsGCStressTest13872026/07/19 11:19:13 INFO Received uploads request method=POST path=/api/pending_closures13882026-07-19 11:19:13.832 UTC [99039] ERROR: relation "goose_db_version" does not exist at character 3613892026-07-19 11:19:13.832 UTC [99039] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13902026/07/19 11:19:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13912026/07/19 11:19:13 INFO Uploading znf3pyf9ypxahgmgmbgnm2sqnrxmd94g-ca-test (144B)13922026/07/19 11:19:13 WARN Failed to register uploaded object key=log/c5px6xrky7wl120jhm2gz1c6aa5zz4cz-ca-test.drv error="server returned 404: 404 page not found\n"13932026/07/19 11:19:13 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"13942026/07/19 11:19:13 WARN Failed to register uploaded object key=znf3pyf9ypxahgmgmbgnm2sqnrxmd94g.ls error="server returned 404: 404 page not found\n"13952026/07/19 11:19:13 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13962026/07/19 11:19:13 INFO Signed narinfos id=1 count=113972026/07/19 11:19:13 INFO Uploading 1 narinfos13982026/07/19 11:19:13 WARN Failed to register uploaded object key=znf3pyf9ypxahgmgmbgnm2sqnrxmd94g.narinfo error="server returned 404: 404 page not found\n"13992026/07/19 11:19:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14002026/07/19 11:19:13 OK 20241026095416_initial_model.sql (8.56ms)14012026/07/19 11:19:13 INFO Completed upload id=114022026/07/19 11:19:13 INFO Upload complete. (93ms)14032026/07/19 11:19:13 OK 20251210153512_drop_unused_gin_index.sql (449.92µs)1404=== NAME TestClientCADerivations1405 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-98732-3921061229/TestClientCADerivations1279398772/001/store/znf3pyf9ypxahgmgmbgnm2sqnrxmd94g-ca-test1406 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1407 Compression: zstd1408 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1409 NarSize: 1441410 References: 1411 Deriver: /nix/var/nix/builds/nix-98732-3921061229/TestClientCADerivations1279398772/001/store/c5px6xrky7wl120jhm2gz1c6aa5zz4cz-ca-test.drv1412 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1413 client_ca_test.go:185: Checking for realisation files in S3...1414 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1415 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache14162026/07/19 11:19:13 OK 20251218171726_add_pins.sql (4.37ms)14172026/07/19 11:19:13 OK 20260628120000_add_object_size_and_stats.sql (3.5ms)14182026/07/19 11:19:13 goose: successfully migrated database to version: 2026062812000014192026/07/19 11:19:13 OK 1_commit_pending_closure.sql (901.21µs)14202026/07/19 11:19:13 OK 2_object_stats_trigger.sql (198.96µs)14212026/07/19 11:19:13 goose: up to current file version: 21422--- PASS: TestReadProxyHead (0.28s)1423=== CONT TestResurrectedObjectNotDeleted14242026-07-19 11:19:13.871 UTC [99043] ERROR: relation "goose_db_version" does not exist at character 3614252026-07-19 11:19:13.871 UTC [99043] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14262026/07/19 11:19:13 OK 20241026095416_initial_model.sql (5.66ms)14272026/07/19 11:19:13 OK 20251210153512_drop_unused_gin_index.sql (534.71µs)14282026/07/19 11:19:13 OK 20251218171726_add_pins.sql (830µs)1429=== NAME TestClientCADerivations1430 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket26?endpoint=http://localhost:59525®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-98732-3921061229/TestClientCADerivations1279398772/001/store'1431 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11432--- PASS: TestClientCADerivations (0.84s)1433=== CONT TestOrphanedObjectsGC14342026/07/19 11:19:13 OK 20260628120000_add_object_size_and_stats.sql (3.34ms)14352026/07/19 11:19:13 goose: successfully migrated database to version: 2026062812000014362026/07/19 11:19:13 OK 1_commit_pending_closure.sql (1.05ms)14372026/07/19 11:19:13 OK 2_object_stats_trigger.sql (227.5µs)14382026/07/19 11:19:13 goose: up to current file version: 21439--- PASS: TestReadProxyInvalidPath (0.26s)1440=== CONT TestService_ReadAuthMiddleware14412026-07-19 11:19:13.910 UTC [99049] ERROR: relation "goose_db_version" does not exist at character 3614422026-07-19 11:19:13.910 UTC [99049] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14432026-07-19 11:19:13.927 UTC [99050] ERROR: relation "goose_db_version" does not exist at character 3614442026-07-19 11:19:13.927 UTC [99050] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14452026/07/19 11:19:13 OK 20241026095416_initial_model.sql (32.79ms)14462026/07/19 11:19:13 OK 20241026095416_initial_model.sql (17.36ms)14472026/07/19 11:19:13 OK 20251210153512_drop_unused_gin_index.sql (496.79µs)14482026/07/19 11:19:13 OK 20251210153512_drop_unused_gin_index.sql (564.58µs)14492026/07/19 11:19:13 OK 20251218171726_add_pins.sql (1.44ms)14502026/07/19 11:19:13 OK 20251218171726_add_pins.sql (1.16ms)14512026/07/19 11:19:13 OK 20260628120000_add_object_size_and_stats.sql (2.08ms)14522026/07/19 11:19:13 goose: successfully migrated database to version: 2026062812000014532026/07/19 11:19:13 OK 1_commit_pending_closure.sql (912.92µs)14542026/07/19 11:19:13 OK 2_object_stats_trigger.sql (253.96µs)14552026/07/19 11:19:13 goose: up to current file version: 214562026/07/19 11:19:13 OK 20260628120000_add_object_size_and_stats.sql (3.32ms)14572026/07/19 11:19:13 goose: successfully migrated database to version: 2026062812000014582026/07/19 11:19:13 OK 1_commit_pending_closure.sql (781.13µs)14592026/07/19 11:19:13 OK 2_object_stats_trigger.sql (181.04µs)14602026/07/19 11:19:13 goose: up to current file version: 21461--- PASS: TestReadProxy404 (0.29s)1462=== CONT TestService_AuthMiddleware_OIDC14632026/07/19 11:19:13 INFO OIDC provider initialized name=test1464--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.27s)1465=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14662026-07-19 11:19:14.020 UTC [99055] ERROR: relation "goose_db_version" does not exist at character 3614672026-07-19 11:19:14.020 UTC [99055] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14682026/07/19 11:19:14 OK 20241026095416_initial_model.sql (6.08ms)14692026/07/19 11:19:14 OK 20251210153512_drop_unused_gin_index.sql (632.33µs)14702026/07/19 11:19:14 OK 20251218171726_add_pins.sql (1.26ms)14712026/07/19 11:19:14 OK 20260628120000_add_object_size_and_stats.sql (1.67ms)14722026/07/19 11:19:14 goose: successfully migrated database to version: 2026062812000014732026/07/19 11:19:14 OK 1_commit_pending_closure.sql (995.29µs)14742026/07/19 11:19:14 OK 2_object_stats_trigger.sql (282.96µs)14752026/07/19 11:19:14 goose: up to current file version: 21476--- PASS: TestReadProxyNarinfo (0.32s)1477=== CONT TestService_AuthMiddleware_MTLSProxyHeader14782026-07-19 11:19:14.090 UTC [99058] ERROR: relation "goose_db_version" does not exist at character 3614792026-07-19 11:19:14.090 UTC [99058] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14802026/07/19 11:19:14 OK 20241026095416_initial_model.sql (9.46ms)14812026/07/19 11:19:14 OK 20251210153512_drop_unused_gin_index.sql (498.88µs)14822026/07/19 11:19:14 OK 20251218171726_add_pins.sql (734.13µs)14832026/07/19 11:19:14 OK 20260628120000_add_object_size_and_stats.sql (19.62ms)14842026/07/19 11:19:14 goose: successfully migrated database to version: 2026062812000014852026/07/19 11:19:14 OK 1_commit_pending_closure.sql (991.83µs)14862026/07/19 11:19:14 OK 2_object_stats_trigger.sql (417.08µs)14872026/07/19 11:19:14 goose: up to current file version: 214882026-07-19 11:19:14.170 UTC [99059] ERROR: relation "goose_db_version" does not exist at character 3614892026-07-19 11:19:14.170 UTC [99059] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14902026/07/19 11:19:14 OK 20241026095416_initial_model.sql (7.08ms)14912026/07/19 11:19:14 OK 20251210153512_drop_unused_gin_index.sql (423.21µs)14922026/07/19 11:19:14 OK 20251218171726_add_pins.sql (746.83µs)14932026/07/19 11:19:14 OK 20260628120000_add_object_size_and_stats.sql (4.65ms)14942026/07/19 11:19:14 goose: successfully migrated database to version: 2026062812000014952026/07/19 11:19:14 OK 1_commit_pending_closure.sql (1.06ms)14962026/07/19 11:19:14 OK 2_object_stats_trigger.sql (324.29µs)14972026/07/19 11:19:14 goose: up to current file version: 214982026-07-19 11:19:14.208 UTC [99060] ERROR: relation "goose_db_version" does not exist at character 3614992026-07-19 11:19:14.208 UTC [99060] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1500--- PASS: TestResurrectedObjectNotDeleted (0.35s)1501=== CONT TestServerTLSConfig/no_client_CA1502=== CONT TestServerTLSConfig/not_a_PEM_file15032026-07-19 11:19:14.215 UTC [99061] ERROR: relation "goose_db_version" does not exist at character 3615042026-07-19 11:19:14.215 UTC [99061] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1505=== CONT TestServerTLSConfig/missing_CA_file1506--- PASS: TestServerTLSConfig (0.00s)1507 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1508 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1509 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1510=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart15112026/07/19 11:19:14 INFO Received complete multipart upload request method=POST path=/15122026/07/19 11:19:14 OK 20241026095416_initial_model.sql (9.57ms)15132026/07/19 11:19:14 OK 20251210153512_drop_unused_gin_index.sql (340.63µs)15142026/07/19 11:19:14 OK 20251218171726_add_pins.sql (692.17µs)15152026/07/19 11:19:14 OK 20241026095416_initial_model.sql (9.7ms)15162026/07/19 11:19:14 OK 20260628120000_add_object_size_and_stats.sql (8.34ms)15172026/07/19 11:19:14 goose: successfully migrated database to version: 2026062812000015182026/07/19 11:19:14 OK 20251210153512_drop_unused_gin_index.sql (566.67µs)15192026/07/19 11:19:14 OK 1_commit_pending_closure.sql (1.06ms)15202026/07/19 11:19:14 OK 2_object_stats_trigger.sql (228.29µs)15212026/07/19 11:19:14 goose: up to current file version: 215222026/07/19 11:19:14 OK 20251218171726_add_pins.sql (957.33µs)15232026/07/19 11:19:14 OK 20260628120000_add_object_size_and_stats.sql (956.79µs)15242026/07/19 11:19:14 goose: successfully migrated database to version: 202606281200001525=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure15262026/07/19 11:19:14 INFO Received uploads request method=POST path=/15272026/07/19 11:19:14 OK 1_commit_pending_closure.sql (842.92µs)15282026/07/19 11:19:14 OK 2_object_stats_trigger.sql (219.83µs)15292026/07/19 11:19:14 goose: up to current file version: 215302026/07/19 11:19:14 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1531--- PASS: TestService_ReadAuthMiddleware (0.34s)1532=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts15332026/07/19 11:19:14 INFO Received request for more parts method=POST path=/1534=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15352026/07/19 11:19:14 INFO Received uploads request method=POST path=/1536=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15372026/07/19 11:19:14 INFO Received complete multipart upload request method=POST path=/1538=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15392026/07/19 11:19:14 INFO Received request for more parts method=POST path=/1540=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15412026/07/19 11:19:14 INFO Received uploads request method=POST path=/1542--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1543 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1544 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1545 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1546 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1547=== CONT TestIsValidUploadKey/narinfo1548=== CONT TestIsValidUploadKey/realisation_plus_in_output1549=== CONT TestIsValidUploadKey/unknown_type1550=== CONT TestIsValidUploadKey/empty_key1551=== CONT TestIsValidUploadKey/absolute1552=== CONT TestIsValidUploadKey/traversal_nar1553=== CONT TestIsValidUploadKey/traversal1554=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1555=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1556=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1557=== CONT TestIsValidUploadKey/index.html1558=== CONT TestIsValidUploadKey/nix-cache-info1559=== CONT TestIsValidUploadKey/build_log_home-manager_file1560=== CONT TestIsValidUploadKey/realisation1561=== CONT TestIsValidUploadKey/build_log_equals1562=== CONT TestIsValidUploadKey/build_log_question_mark1563=== CONT TestIsValidUploadKey/build_log_plus_in_name1564=== CONT TestIsValidUploadKey/nar_plain1565=== CONT TestIsValidUploadKey/build_log1566=== CONT TestIsValidUploadKey/listing1567=== CONT TestIsValidUploadKey/nar_xz1568=== CONT TestIsValidUploadKey/nar_zst1569--- PASS: TestIsValidUploadKey (0.00s)1570 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1571 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1572 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1573 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1574 --- PASS: TestIsValidUploadKey/absolute (0.00s)1575 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1576 --- PASS: TestIsValidUploadKey/traversal (0.00s)1577 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1578 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1579 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1580 --- PASS: TestIsValidUploadKey/index.html (0.00s)1581 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1582 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1583 --- PASS: TestIsValidUploadKey/realisation (0.00s)1584 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1585 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1586 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1587 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1588 --- PASS: TestIsValidUploadKey/build_log (0.00s)1589 --- PASS: TestIsValidUploadKey/listing (0.00s)1590 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1591 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1592=== CONT TestProxyWriteTimeout/narinfo1593=== CONT TestProxyWriteTimeout/10_GiB_nar1594=== CONT TestProxyWriteTimeout/unknown_size1595=== CONT TestProxyWriteTimeout/1_GiB_nar1596--- PASS: TestProxyWriteTimeout (0.00s)1597 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1598 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1599 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1600 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1601=== CONT TestCacheConfigHandler/full_config,_no_issuer1602=== CONT TestCacheConfigHandler/no_signing_keys1603=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1604=== CONT TestCacheConfigHandler/no_cache_url_configured1605--- PASS: TestCacheConfigHandler (0.00s)1606 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1607 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1608 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1609 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1610=== CONT TestClientErrorHandling/InvalidStorePath16112026-07-19 11:19:14.262 UTC [99064] ERROR: relation "goose_db_version" does not exist at character 3616122026-07-19 11:19:14.262 UTC [99064] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16132026-07-19 11:19:14.262 UTC [99065] ERROR: relation "goose_db_version" does not exist at character 3616142026-07-19 11:19:14.262 UTC [99065] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16152026/07/19 11:19:14 OK 20241026095416_initial_model.sql (4.65ms)16162026/07/19 11:19:14 OK 20251210153512_drop_unused_gin_index.sql (388.38µs)16172026/07/19 11:19:14 OK 20251218171726_add_pins.sql (1.02ms)16182026/07/19 11:19:14 OK 20241026095416_initial_model.sql (4.77ms)16192026/07/19 11:19:14 OK 20251210153512_drop_unused_gin_index.sql (484.5µs)16202026/07/19 11:19:14 OK 20251218171726_add_pins.sql (798.25µs)16212026/07/19 11:19:14 OK 20260628120000_add_object_size_and_stats.sql (1.93ms)16222026/07/19 11:19:14 goose: successfully migrated database to version: 2026062812000016232026/07/19 11:19:14 OK 1_commit_pending_closure.sql (931.83µs)16242026/07/19 11:19:14 OK 20260628120000_add_object_size_and_stats.sql (1.6ms)16252026/07/19 11:19:14 goose: successfully migrated database to version: 2026062812000016262026/07/19 11:19:14 OK 2_object_stats_trigger.sql (252.83µs)16272026/07/19 11:19:14 goose: up to current file version: 216282026/07/19 11:19:14 OK 1_commit_pending_closure.sql (816.79µs)16292026/07/19 11:19:14 OK 2_object_stats_trigger.sql (222.38µs)16302026/07/19 11:19:14 goose: up to current file version: 21631=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1632=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1633=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1634=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1635=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1636=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1637=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1638=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1639=== CONT TestClientErrorHandling/ServerNotAvailable16402026/07/19 11:19:14 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"16412026/07/19 11:19:14 WARN mTLS auth: bound subjects configured but subject DN unavailable16422026/07/19 11:19:14 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1643--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.32s)1644=== CONT TestClientErrorHandling/InvalidAuthToken16452026-07-19 11:19:14.313 UTC [99070] ERROR: relation "goose_db_version" does not exist at character 3616462026-07-19 11:19:14.313 UTC [99070] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16472026/07/19 11:19:14 OK 20241026095416_initial_model.sql (8.22ms)16482026/07/19 11:19:14 OK 20251210153512_drop_unused_gin_index.sql (470.04µs)16492026/07/19 11:19:14 OK 20251218171726_add_pins.sql (801.54µs)16502026/07/19 11:19:14 OK 20260628120000_add_object_size_and_stats.sql (12.2ms)16512026/07/19 11:19:14 goose: successfully migrated database to version: 2026062812000016522026/07/19 11:19:14 OK 1_commit_pending_closure.sql (1.15ms)16532026/07/19 11:19:14 OK 2_object_stats_trigger.sql (601.63µs)16542026/07/19 11:19:14 goose: up to current file version: 21655--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.33s)1656=== CONT TestParseSingleRange/none1657=== CONT TestParseSingleRange/start_far_past_EOF1658=== CONT TestParseSingleRange/start_past_EOF1659=== CONT TestParseSingleRange/single_byte1660=== CONT TestParseSingleRange/suffix_exceeds_size1661=== CONT TestParseSingleRange/suffix1662=== CONT TestParseSingleRange/end_clamped_to_size1663=== CONT TestParseSingleRange/open-ended1664=== CONT TestParseSingleRange/closed1665=== CONT TestParseSingleRange/malformed_end_before_start1666=== CONT TestParseSingleRange/malformed_both_empty1667=== CONT TestParseSingleRange/malformed_no_dash1668=== CONT TestParseSingleRange/multi-range_ignored1669=== CONT TestParseSingleRange/unknown_unit1670--- PASS: TestParseSingleRange (0.00s)1671 --- PASS: TestParseSingleRange/none (0.00s)1672 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1673 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1674 --- PASS: TestParseSingleRange/single_byte (0.00s)1675 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1676 --- PASS: TestParseSingleRange/suffix (0.00s)1677 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1678 --- PASS: TestParseSingleRange/open-ended (0.00s)1679 --- PASS: TestParseSingleRange/closed (0.00s)1680 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1681 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1682 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1683 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1684 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1685=== CONT TestIsValidCachePath/narinfo1686=== CONT TestIsValidCachePath/index.html1687=== CONT TestIsValidCachePath/short_hash1688=== CONT TestIsValidCachePath/wrong_extension1689=== CONT TestIsValidCachePath/leading_slash1690=== CONT TestIsValidCachePath/empty1691=== CONT TestIsValidCachePath/random_path1692=== CONT TestIsValidCachePath/invalid_char_u1693=== CONT TestIsValidCachePath/invalid_char_e1694=== CONT TestIsValidCachePath/traversal_in_middle1695=== CONT TestIsValidCachePath/traversal_parent1696=== CONT TestIsValidCachePath/nar_uncompressed1697=== CONT TestIsValidCachePath/nix-cache-info1698=== CONT TestIsValidCachePath/realisation1699=== CONT TestIsValidCachePath/log1700=== CONT TestIsValidCachePath/ls1701=== CONT TestIsValidCachePath/nar_xz1702=== CONT TestIsValidCachePath/nar_bz21703=== CONT TestIsValidCachePath/nar_zst1704=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1705--- PASS: TestIsValidCachePath (0.00s)1706 --- PASS: TestIsValidCachePath/narinfo (0.00s)1707 --- PASS: TestIsValidCachePath/index.html (0.00s)1708 --- PASS: TestIsValidCachePath/short_hash (0.00s)1709 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1710 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1711 --- PASS: TestIsValidCachePath/empty (0.00s)1712 --- PASS: TestIsValidCachePath/random_path (0.00s)1713 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1714 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1715 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1716 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1717 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1718 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1719 --- PASS: TestIsValidCachePath/realisation (0.00s)1720 --- PASS: TestIsValidCachePath/log (0.00s)1721 --- PASS: TestIsValidCachePath/ls (0.00s)1722 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1723 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1724 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1725 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1726=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token17272026/07/19 11:19:14 INFO OIDC auth successful provider=test1728=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected17292026/07/19 11:19:14 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]1730=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1731=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected17322026/07/19 11:19:14 WARN Authentication failed token_preview=eyJhbGciOi...fLFwRhmz6g 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]1733--- PASS: TestService_AuthMiddleware_OIDC (0.32s)1734 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1735 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1736 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1737 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)17382026/07/19 11:19:14 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-config17392026-07-19 11:19:14.427 UTC [99075] ERROR: relation "goose_db_version" does not exist at character 3617402026-07-19 11:19:14.427 UTC [99075] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17412026/07/19 11:19:14 OK 20241026095416_initial_model.sql (5.39ms)17422026/07/19 11:19:14 OK 20251210153512_drop_unused_gin_index.sql (371.21µs)17432026/07/19 11:19:14 OK 20251218171726_add_pins.sql (763.96µs)17442026/07/19 11:19:14 OK 20260628120000_add_object_size_and_stats.sql (2.65ms)17452026/07/19 11:19:14 goose: successfully migrated database to version: 2026062812000017462026/07/19 11:19:14 OK 1_commit_pending_closure.sql (950.17µs)17472026/07/19 11:19:14 OK 2_object_stats_trigger.sql (384.17µs)17482026/07/19 11:19:14 goose: up to current file version: 217492026-07-19 11:19:14.453 UTC [99077] ERROR: relation "goose_db_version" does not exist at character 3617502026-07-19 11:19:14.453 UTC [99077] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1751=== NAME TestOrphanedObjectsGC1752 orphaned_objects_gc_test.go:290: GC Test Summary:1753 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1754 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1755 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1756 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1757 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1758--- PASS: TestOrphanedObjectsGC (0.57s)17592026/07/19 11:19:14 OK 20241026095416_initial_model.sql (3.57ms)17602026/07/19 11:19:14 OK 20251210153512_drop_unused_gin_index.sql (384.42µs)17612026/07/19 11:19:14 OK 20251218171726_add_pins.sql (766.96µs)17622026/07/19 11:19:14 OK 20260628120000_add_object_size_and_stats.sql (1.32ms)17632026/07/19 11:19:14 goose: successfully migrated database to version: 2026062812000017642026/07/19 11:19:14 OK 1_commit_pending_closure.sql (837.21µs)17652026/07/19 11:19:14 OK 2_object_stats_trigger.sql (211.29µs)17662026/07/19 11:19:14 goose: up to current file version: 21767=== NAME TestOrphanedObjectsGCStressTest1768 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1769 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion1770--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)1771 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1772 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1773 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.27s)17742026/07/19 11:19:14 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=216.331019ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1775=== NAME TestOrphanedObjectsGCStressTest1776 orphaned_objects_gc_test.go:509: Stress test completed successfully:1777 orphaned_objects_gc_test.go:510: - Active objects preserved: 201778 orphaned_objects_gc_test.go:511: - Objects deleted: 2101779 orphaned_objects_gc_test.go:512: - Total GC'd: 2101780--- PASS: TestOrphanedObjectsGCStressTest (0.76s)17812026/07/19 11:19:14 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17822026/07/19 11:19:14 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"17832026/07/19 11:19:14 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=436.574522ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17842026/07/19 11:19:14 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01785=== NAME TestClientIntegration1786 client_integration_test.go:303: Objects in database after GC:1787 client_integration_test.go:303: Successfully deleted all objects with GC --force1788--- PASS: TestClientIntegration (2.72s)17892026/07/19 11:19:15 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01790=== NAME TestPinProtectsFromGC1791 client_integration_test.go:709: Pin successfully protected closure from garbage collection1792--- PASS: TestPinProtectsFromGC (2.67s)17932026/07/19 11:19:15 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=841.959675ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17942026/07/19 11:19:16 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.672865047s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17952026/07/19 11:19:17 WARN Rate limiter enabled after throttle name=s3-test rate=517962026/07/19 11:19:17 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.77s)18012026/07/19 11:19:17 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:19:17 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:19:17 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=212.952506ms 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:19:18 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=398.203203ms 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:19:18 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=726.621046ms 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:19:19 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.751682887s 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.23s)1809 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.34s)1810 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.70s)1811PASS1812{"timestamp":"2026-07-19T11:19:21.485651Z","level":"ERROR","fields":{"message":"Unknown connection IO error:Cancelled","peer_addr":"127.0.0.1:59600"},"target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":973,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}18132026-07-19 11:19:21.548 UTC [98767] LOG: received smart shutdown request18142026-07-19 11:19:21.549 UTC [98767] LOG: background worker "logical replication launcher" (PID 98777) exited with exit code 118152026-07-19 11:19:21.553 UTC [98772] LOG: shutting down18162026-07-19 11:19:21.553 UTC [98772] LOG: checkpoint starting: shutdown immediate18172026-07-19 11:19:22.517 UTC [98772] LOG: checkpoint complete: wrote 12584 buffers (76.8%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 13 recycled; write=0.700 s, sync=0.263 s, total=0.965 s; sync files=15167, longest=0.001 s, average=0.001 s; distance=212067 kB, estimate=212067 kB; lsn=0/E69E3E8, redo lsn=0/E69E3E818182026-07-19 11:19:22.522 UTC [98767] 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=== RUN TestGlobMatch/foo_foo1840=== CONT TestValidateToken_NoMatchingProvider1841=== CONT TestValidateToken_Expired1842=== PAUSE TestGlobMatch/foo_foo1843=== RUN TestGlobMatch/foo_bar1844=== PAUSE TestGlobMatch/foo_bar1845=== CONT TestValidateToken_WrongAudience1846=== CONT TestValidateToken_ValidToken1847=== CONT TestAudienceForIssuer1848--- PASS: TestAudienceForIssuer (0.00s)1849=== CONT TestValidateToken_BoundSubjectMismatch1850=== CONT TestValidateToken_BoundClaimsMismatch1851=== CONT TestValidateToken_MultipleProviders1852=== 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/*/*_foo/bar1900=== CONT TestGlobMatch/?oo_boo1901=== CONT TestGlobMatch/?oo_foo1902=== CONT TestGlobMatch/fo?_fooo1903=== CONT TestGlobMatch/fo?_fo1904=== CONT TestGlobMatch/fo?_foo1905=== CONT TestGlobMatch/refs/*/main_refs/heads/main1906=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.01907=== CONT TestGlobMatch/refs/heads/*_refs/heads/main1908=== CONT TestGlobMatch/*/*_foo1909=== CONT TestGlobMatch/*bar_bar1910=== CONT TestGlobMatch/foo*bar_foobarbaz1911=== CONT TestGlobMatch/foo*bar_foo123bar1912=== CONT TestGlobMatch/foo*bar_foobar1913=== CONT TestGlobMatch/*bar_foo1914=== CONT TestGlobMatch/*bar_foobar1915=== CONT TestGlobMatch/foo*_foo1916=== CONT TestGlobMatch/foo*_bar1917=== CONT TestGlobMatch/foo*_foobar1918=== CONT TestGlobMatch/*_1919=== CONT TestGlobMatch/*_anything1920=== CONT TestGlobMatch/foo_bar1921=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1922=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1923--- PASS: TestGlobMatch (0.00s)1924 --- PASS: TestGlobMatch/foo_foo (0.00s)1925 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)1926 --- PASS: TestGlobMatch/?oo_boo (0.00s)1927 --- PASS: TestGlobMatch/?oo_foo (0.00s)1928 --- PASS: TestGlobMatch/fo?_fooo (0.00s)1929 --- PASS: TestGlobMatch/fo?_fo (0.00s)1930 --- PASS: TestGlobMatch/fo?_foo (0.00s)1931 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)1932 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)1933 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)1934 --- PASS: TestGlobMatch/*/*_foo (0.00s)1935 --- PASS: TestGlobMatch/*bar_bar (0.00s)1936 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)1937 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)1938 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)1939 --- PASS: TestGlobMatch/*bar_foo (0.00s)1940 --- PASS: TestGlobMatch/*bar_foobar (0.00s)1941 --- PASS: TestGlobMatch/foo*_foo (0.00s)1942 --- PASS: TestGlobMatch/foo*_bar (0.00s)1943 --- PASS: TestGlobMatch/foo*_foobar (0.00s)1944 --- PASS: TestGlobMatch/*_ (0.00s)1945 --- PASS: TestGlobMatch/*_anything (0.00s)1946 --- PASS: TestGlobMatch/foo_bar (0.00s)1947 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)1948 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)19492026/07/19 11:19:23 INFO OIDC provider initialized name=provider119502026/07/19 11:19:23 INFO OIDC provider initialized name=test19512026/07/19 11:19:23 INFO OIDC provider initialized name=test19522026/07/19 11:19:23 INFO OIDC provider initialized name=test19532026/07/19 11:19:23 INFO OIDC provider initialized name=test19542026/07/19 11:19:23 INFO OIDC provider initialized name=provider119552026/07/19 11:19:23 INFO OIDC provider initialized name=provider219562026/07/19 11:19:23 INFO OIDC provider initialized name=test1957--- PASS: TestValidateToken_ValidToken (0.01s)1958--- PASS: TestValidateToken_MultipleProviders (0.01s)1959--- PASS: TestValidateToken_NoMatchingProvider (0.01s)1960--- PASS: TestValidateToken_Expired (0.01s)1961--- PASS: TestValidateToken_WrongAudience (0.01s)1962--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)1963--- PASS: TestValidateToken_BoundSubjectMismatch (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 TestQueueDeduplication1999=== CONT TestWorkerPrunesClosureDeps2000=== CONT TestQueueRemove2001=== CONT TestQueueFetchRemoveLifecycle2002=== CONT TestWorkerUploadsAndRemoves2003=== CONT TestWorkerSkipsGCdPaths2004=== CONT TestQueueEnqueueAndFetch2005=== CONT TestServerClientIntegration2006=== CONT TestQueueFetchBatchLimit2007=== CONT TestQueueConcurrentWriters2008--- PASS: TestServerClientIntegration (0.00s)2009=== CONT TestServerQueueError20102026/07/19 11:19:23 ERROR Failed to queue paths error="permission denied" count=12011--- PASS: TestServerQueueError (0.00s)2012--- PASS: TestQueueFetchBatchLimit (0.01s)2013--- PASS: TestQueueDeduplication (0.01s)2014--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2015--- PASS: TestQueueEnqueueAndFetch (0.01s)20162026/07/19 11:19:23 INFO Upload queue status pending=220172026/07/19 11:19:23 INFO Upload queue status pending=220182026/07/19 11:19:23 INFO Uploading batch count=220192026/07/19 11:19:23 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-98732-3921061229/TestWorkerSkipsGCdPaths545035334/002/nonexistent20202026/07/19 11:19:23 INFO Upload queue status pending=220212026/07/19 11:19:23 INFO Uploading batch count=12022--- PASS: TestQueueRemove (0.01s)20232026/07/19 11:19:23 INFO Uploading batch count=12024--- PASS: TestWorkerPrunesClosureDeps (0.06s)2025--- PASS: TestWorkerUploadsAndRemoves (0.06s)2026--- PASS: TestWorkerSkipsGCdPaths (0.06s)2027--- PASS: TestQueueConcurrentWriters (0.16s)2028PASS