niks3-go-unit-tests
aarch64-darwin.go-unit-tests
· build #113
· 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 TestShellSplit74--- PASS: TestShellSplit (0.00s)75=== CONT TestSetClientTLSDoesNotMutateDefaultTransport76=== CONT TestFileTokenEmpty77=== CONT TestSetClientTLSErrors78=== CONT TestStaticToken79=== CONT TestFileTokenReadsAndCaches80--- PASS: TestStaticToken (0.00s)81=== CONT TestConvertHashToNix3282=== RUN TestConvertHashToNix32/SRI_format_to_Nix3283=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix3284=== RUN TestConvertHashToNix32/already_Nix32_format85=== CONT TestDumpPathMatchesNix86=== CONT TestDoWithRetry_BodyReplayedViaGetBody87=== CONT TestFileTokenMissing88=== CONT TestScriptTokenBadJSON89--- PASS: TestFileTokenEmpty (0.00s)90=== CONT TestParsePathInfoJSONMultiplePaths91=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths92=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths93=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths94=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths95=== CONT TestResolveStorePath96--- PASS: TestFileTokenMissing (0.00s)97=== PAUSE TestConvertHashToNix32/already_Nix32_format98=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess99=== RUN TestConvertHashToNix32/invalid_format100=== PAUSE TestConvertHashToNix32/invalid_format101=== CONT TestRateLimiterFeedback102=== RUN TestRateLimiterFeedback/429_enables_limiter103=== PAUSE TestRateLimiterFeedback/429_enables_limiter104=== RUN TestRateLimiterFeedback/503_enables_limiter105=== PAUSE TestRateLimiterFeedback/503_enables_limiter106=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter107=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter108=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter109=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter110=== CONT TestPathInfoCACompatibility111=== RUN TestPathInfoCACompatibility/null_ca_field112=== PAUSE TestPathInfoCACompatibility/null_ca_field113=== RUN TestPathInfoCACompatibility/old_string_format_-_text114=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text115=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive116=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive117=== RUN TestPathInfoCACompatibility/new_structured_format_-_text118=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text119=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method120--- PASS: TestFileTokenReadsAndCaches (0.00s)121=== CONT TestSetClientTLS1222026/07/23 15:28:44 WARN Rate limiter enabled after throttle name=server-test rate=5123=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method124=== CONT TestEncodeNixBase32125=== RUN TestEncodeNixBase32/test_string_hash126=== PAUSE TestEncodeNixBase32/test_string_hash127=== RUN TestEncodeNixBase32/empty_input128=== PAUSE TestEncodeNixBase32/empty_input129=== CONT TestScriptTokenCachesUntilRefresh1302026/07/23 15:28:44 WARN Rate limiter enabled after throttle name=server-test rate=51312026/07/23 15:28:44 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:53486132--- PASS: TestResolveStorePath (0.00s)133=== CONT TestEncodeNixBase32WithRealHash134--- PASS: TestDoServerRequestAttachesToken (0.01s)135--- PASS: TestEncodeNixBase32WithRealHash (0.00s)136=== CONT TestDumpPathWriterError137=== CONT TestScriptTokenEmptyToken138=== RUN TestSetClientTLSErrors/missing_cert_file1392026/07/23 15:28:44 WARN Rate limiter backed off name=server-test rate=51402026/07/23 15:28:44 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:53486141=== PAUSE TestSetClientTLSErrors/missing_cert_file142=== RUN TestSetClientTLSErrors/missing_key_file143=== PAUSE TestSetClientTLSErrors/missing_key_file144=== RUN TestSetClientTLSErrors/missing_ca_file145=== PAUSE TestSetClientTLSErrors/missing_ca_file146=== RUN TestSetClientTLSErrors/invalid_ca_file147=== PAUSE TestSetClientTLSErrors/invalid_ca_file148=== CONT TestShellSplitErrors149--- PASS: TestShellSplitErrors (0.00s)150=== CONT TestScriptTokenEmptyCommand151--- PASS: TestScriptTokenEmptyCommand (0.00s)152=== CONT TestScriptTokenNoExpiryRerunsEveryCall153--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)154=== CONT TestPathInfoHashCompatibility155=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)156=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)157=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon158=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon159=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI160=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI161=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512162=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512163=== CONT TestGetStorePathHash164=== RUN TestGetStorePathHash/valid_store_path165=== PAUSE TestGetStorePathHash/valid_store_path166=== RUN TestGetStorePathHash/basename_without_hyphen_should_error167=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error168=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error169=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error170=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error171=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error172=== CONT TestParsePathInfoJSON173=== RUN TestParsePathInfoJSON/Nix_format174=== PAUSE TestParsePathInfoJSON/Nix_format175=== RUN TestParsePathInfoJSON/Lix_format176--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)177=== CONT TestFilterOversizedClosures178=== PAUSE TestParsePathInfoJSON/Lix_format179=== RUN TestFilterOversizedClosures/no_limit_keeps_everything180=== RUN TestParsePathInfoJSON/empty_input181=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything182=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped183=== RUN TestSetClientTLS/rejects_connection_without_client_cert184=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped185=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert186=== RUN TestFilterOversizedClosures/all_closures_skipped187=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA188=== PAUSE TestParsePathInfoJSON/empty_input189=== RUN TestParsePathInfoJSON/whitespace_only190=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA191=== PAUSE TestFilterOversizedClosures/all_closures_skipped192=== RUN TestSetClientTLS/preserves_debug_logging_transport193=== PAUSE TestSetClientTLS/preserves_debug_logging_transport194=== PAUSE TestParsePathInfoJSON/whitespace_only195=== CONT TestUploadMultipart_SupersededByPeer196=== CONT TestPartSizeForNAR197=== RUN TestUploadMultipart_SupersededByPeer/exists198=== RUN TestPartSizeForNAR/zero_stays_at_minimum199=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum200=== PAUSE TestUploadMultipart_SupersededByPeer/exists201=== RUN TestPartSizeForNAR/small_stays_at_minimum202=== RUN TestUploadMultipart_SupersededByPeer/missing203=== PAUSE TestUploadMultipart_SupersededByPeer/missing204=== PAUSE TestPartSizeForNAR/small_stays_at_minimum205=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum206=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum207=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts208=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts209=== RUN TestPartSizeForNAR/1_TiB210=== PAUSE TestPartSizeForNAR/1_TiB211=== RUN TestPartSizeForNAR/5_TiB_S3_max_object212=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object213=== RUN TestPartSizeForNAR/capped_at_5_GiB214=== PAUSE TestPartSizeForNAR/capped_at_5_GiB215=== RUN TestParsePathInfoJSON/invalid_JSON216=== CONT TestDumpPathSingleFile217=== CONT TestCaseHackSuffix218=== PAUSE TestParsePathInfoJSON/invalid_JSON219=== CONT TestScriptTokenScriptFails220--- PASS: TestScriptTokenScriptFails (0.00s)221=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths222=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths223--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)224 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)225 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)226=== CONT TestConvertHashToNix32/SRI_format_to_Nix32227=== CONT TestConvertHashToNix32/invalid_format228=== CONT TestConvertHashToNix32/already_Nix32_format229--- PASS: TestConvertHashToNix32 (0.00s)230 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)231 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)232 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)233=== CONT TestRateLimiterFeedback/429_enables_limiter234--- PASS: TestScriptTokenBadJSON (0.01s)235=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2362026/07/23 15:28:44 WARN Rate limiter enabled after throttle name=server-test rate=52372026/07/23 15:28:44 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:534922382026/07/23 15:28:44 WARN Rate limiter backed off name=server-test rate=5239=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter240=== CONT TestRateLimiterFeedback/503_enables_limiter2412026/07/23 15:28:44 WARN Rate limiter enabled after throttle name=server-test rate=52422026/07/23 15:28:44 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:534972432026/07/23 15:28:44 WARN Rate limiter backed off name=server-test rate=5244=== CONT TestPathInfoCACompatibility/null_ca_field245--- PASS: TestRateLimiterFeedback (0.00s)246 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)247 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)248 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)249 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)250=== CONT TestEncodeNixBase32/test_string_hash251=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method252=== CONT TestPathInfoCACompatibility/new_structured_format_-_text253=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive254=== 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 TestSetClientTLSErrors/missing_cert_file259=== CONT TestPathInfoCACompatibility/old_string_format_-_text260--- PASS: TestPathInfoCACompatibility (0.00s)261 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)262 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)263 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)264 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)265 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)266=== CONT TestSetClientTLSErrors/invalid_ca_file267=== CONT TestSetClientTLSErrors/missing_ca_file268=== CONT TestSetClientTLSErrors/missing_key_file269=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)270=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI271=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon272=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512273--- PASS: TestPathInfoHashCompatibility (0.00s)274 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)275 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)276 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)277 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)278=== CONT TestGetStorePathHash/valid_store_path279=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error280=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error281=== CONT TestGetStorePathHash/basename_without_hyphen_should_error282--- PASS: TestGetStorePathHash (0.00s)283 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)284 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)285 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)286 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)287=== CONT TestFilterOversizedClosures/all_closures_skipped2882026/07/23 15:28:44 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50289=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2902026/07/23 15:28:44 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=2000291=== CONT TestFilterOversizedClosures/no_limit_keeps_everything292--- PASS: TestFilterOversizedClosures (0.00s)293 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)294 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)295 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)296=== CONT TestSetClientTLS/preserves_debug_logging_transport297=== CONT TestSetClientTLS/rejects_connection_without_client_cert298--- PASS: TestSetClientTLSErrors (0.01s)299 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)300 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)301 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)302 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)303--- PASS: TestScriptTokenEmptyToken (0.01s)304=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA305=== CONT TestUploadMultipart_SupersededByPeer/exists306=== CONT TestPartSizeForNAR/zero_stays_at_minimum307=== CONT TestUploadMultipart_SupersededByPeer/missing308=== CONT TestPartSizeForNAR/capped_at_5_GiB309=== CONT TestPartSizeForNAR/5_TiB_S3_max_object310=== CONT TestPartSizeForNAR/1_TiB311=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts312=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum313=== CONT TestPartSizeForNAR/small_stays_at_minimum314=== CONT TestParsePathInfoJSON/Nix_format315--- PASS: TestPartSizeForNAR (0.00s)316 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)317 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)318 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)319 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)320 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)321 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)322 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)323=== CONT TestParsePathInfoJSON/whitespace_only324=== CONT TestParsePathInfoJSON/invalid_JSON325=== CONT TestParsePathInfoJSON/empty_input326=== CONT TestParsePathInfoJSON/Lix_format327--- PASS: TestParsePathInfoJSON (0.00s)328 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)329 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)330 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)331 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)332 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)333--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)334 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)335 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)336--- PASS: TestScriptTokenCachesUntilRefresh (0.02s)3372026/07/23 15:28:44 http: TLS handshake error from 127.0.0.1:53500: remote error: tls: bad certificate338--- PASS: TestSetClientTLS (0.01s)339 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)340 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)341 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)342--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)343--- PASS: TestDumpPathWriterError (0.05s)344--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)345--- PASS: TestDumpPathSingleFile (7.62s)346--- PASS: TestCaseHackSuffix (7.62s)347--- PASS: TestDumpPathMatchesNix (7.64s)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-45316-59033543/postgres2638598619/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-45316-59033543/postgres2638598619/data -l logfile start3763772026-07-23 15:28:56.037 UTC [45409] LOG: starting PostgreSQL 18.4 on aarch64-apple-darwin25.5.0, compiled by clang version 21.1.8, 64-bit3782026-07-23 15:28:56.037 UTC [45409] LOG: listening on Unix socket "/nix/var/nix/builds/nix-45316-59033543/postgres2638598619/.s.PGSQL.5432"3792026-07-23 15:28:56.040 UTC [45416] LOG: database system was shut down at 2026-07-23 15:28:56 UTC3802026-07-23 15:28:56.040 UTC [45409] LOG: database system is ready to accept connections381/nix/var/nix/builds/nix-45316-59033543/postgres2638598619:5432 - accepting connections382<jemalloc>: option background_thread currently supports pthread only383{"timestamp":"2026-07-23T15:28:58.068703Z","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(5)"}384=== RUN TestService_AuthMiddleware385=== PAUSE TestService_AuthMiddleware386=== RUN TestService_AuthMiddleware_MTLSProxyHeader387=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader388=== RUN TestService_AuthMiddleware_MTLSBoundSubjects389=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects390=== RUN TestService_ReadAuthMiddleware391=== PAUSE TestService_ReadAuthMiddleware392=== RUN TestService_AuthMiddleware_OIDC393=== PAUSE TestService_AuthMiddleware_OIDC394=== RUN TestCacheConfigHandler395=== PAUSE TestCacheConfigHandler396=== RUN TestCacheStatsHandler397=== PAUSE TestCacheStatsHandler398=== RUN TestClientCADerivations399=== PAUSE TestClientCADerivations400=== RUN TestClientErrorHandling401=== PAUSE TestClientErrorHandling402=== RUN TestClientIntegration403=== PAUSE TestClientIntegration404=== RUN TestClientMultipleUploads405=== PAUSE TestClientMultipleUploads406=== RUN TestClientWithDependencies407=== PAUSE TestClientWithDependencies408=== RUN TestPinProtectsFromGC409=== PAUSE TestPinProtectsFromGC410=== RUN TestGCAdvisoryLockBlocksConcurrentRun4112026-07-23 15:28:58.443 UTC [45466] ERROR: relation "goose_db_version" does not exist at character 364122026-07-23 15:28:58.443 UTC [45466] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4132026/07/23 15:28:58 OK 20241026095416_initial_model.sql (3.66ms)4142026/07/23 15:28:58 OK 20251210153512_drop_unused_gin_index.sql (549µs)4152026/07/23 15:28:58 OK 20251218171726_add_pins.sql (797.75µs)4162026/07/23 15:28:58 OK 20260628120000_add_object_size_and_stats.sql (988.46µs)4172026/07/23 15:28:58 goose: successfully migrated database to version: 202606281200004182026/07/23 15:28:58 OK 1_commit_pending_closure.sql (978.88µs)4192026/07/23 15:28:58 OK 2_object_stats_trigger.sql (209.5µs)4202026/07/23 15:28:58 goose: up to current file version: 2421--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.33s)422=== RUN TestGCBugBareHashReferences423=== PAUSE TestGCBugBareHashReferences424=== RUN TestGCMetrics425=== PAUSE TestGCMetrics426=== RUN TestGCTaskStore_StartNew427=== PAUSE TestGCTaskStore_StartNew428=== RUN TestGCTaskStore_DeduplicateSameParams429=== PAUSE TestGCTaskStore_DeduplicateSameParams430=== RUN TestGCTaskStore_ConflictDifferentParams431=== PAUSE TestGCTaskStore_ConflictDifferentParams432=== RUN TestGCTaskStore_GetEmpty433=== PAUSE TestGCTaskStore_GetEmpty434=== RUN TestGCTaskStore_GetReturnsLatest435=== PAUSE TestGCTaskStore_GetReturnsLatest436=== RUN TestGCTaskStore_CompletedAllowsNewTask437=== PAUSE TestGCTaskStore_CompletedAllowsNewTask438=== RUN TestGCTaskStore_PhaseUpdates439=== PAUSE TestGCTaskStore_PhaseUpdates440=== RUN TestGCTaskStore_Fail441=== PAUSE TestGCTaskStore_Fail442=== RUN TestGracefulShutdownDrainsInflight443=== PAUSE TestGracefulShutdownDrainsInflight444=== RUN TestService_healthCheckHandler445=== PAUSE TestService_healthCheckHandler446=== RUN TestGenerateLandingPage447=== PAUSE TestGenerateLandingPage448=== RUN TestCacheConfigHandlerMaxNarSize449=== PAUSE TestCacheConfigHandlerMaxNarSize450=== RUN TestCreatePendingClosureRejectsOversizedNAR451=== PAUSE TestCreatePendingClosureRejectsOversizedNAR452=== RUN TestNARDeduplicationMetadataUploadBug453=== PAUSE TestNARDeduplicationMetadataUploadBug454=== RUN TestMetricsInventory455=== PAUSE TestMetricsInventory456=== RUN TestService_NativeMTLS457=== PAUSE TestService_NativeMTLS458=== RUN TestServerTLSConfig459=== PAUSE TestServerTLSConfig460=== RUN TestMultipartCleanup461=== PAUSE TestMultipartCleanup462=== RUN TestObjectStatsTrigger463=== PAUSE TestObjectStatsTrigger464=== RUN TestOrphanedObjectsGC465=== PAUSE TestOrphanedObjectsGC466=== RUN TestOrphanedObjectsGCStressTest467=== PAUSE TestOrphanedObjectsGCStressTest468=== RUN TestResurrectedObjectNotDeleted469=== PAUSE TestResurrectedObjectNotDeleted470=== RUN TestParseSingleRange471=== PAUSE TestParseSingleRange472=== RUN TestIsValidCachePath473=== PAUSE TestIsValidCachePath474=== RUN TestReadProxyNarinfo475=== PAUSE TestReadProxyNarinfo476=== RUN TestReadProxyNarinfoAlreadyDecompressed477=== PAUSE TestReadProxyNarinfoAlreadyDecompressed478=== RUN TestReadProxyNarStreaming479=== PAUSE TestReadProxyNarStreaming480=== RUN TestReadProxy404481=== PAUSE TestReadProxy404482=== RUN TestReadProxyInvalidPath483=== PAUSE TestReadProxyInvalidPath484=== RUN TestReadProxyHead485=== PAUSE TestReadProxyHead486=== RUN TestReadProxyConditionalGet487=== PAUSE TestReadProxyConditionalGet488=== RUN TestReadProxyRootRedirectsToIndexHTML489=== PAUSE TestReadProxyRootRedirectsToIndexHTML490=== RUN TestReadProxyDisabled491=== PAUSE TestReadProxyDisabled492=== RUN TestReadProxyRangeRequest493=== PAUSE TestReadProxyRangeRequest494=== RUN TestRedundantMultipartUpload495=== PAUSE TestRedundantMultipartUpload496=== RUN TestCompleteMultipartUpload_ErrorButObjectExists497=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists498=== RUN TestCompletedNarNotReofferedAcrossClosures499=== PAUSE TestCompletedNarNotReofferedAcrossClosures500=== RUN TestPresignedUploadRegisteredBeforeCommit501=== PAUSE TestPresignedUploadRegisteredBeforeCommit502=== RUN TestService_Rustfstest503=== PAUSE TestService_Rustfstest504=== RUN TestParseSize505=== PAUSE TestParseSize506=== RUN TestSkippedUploadsHandler507=== PAUSE TestSkippedUploadsHandler508=== RUN TestSystemdListenerNotActivated509--- PASS: TestSystemdListenerNotActivated (0.00s)510=== RUN TestWatchdogBeatsWhenHealthy511--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)512=== RUN TestWatchdogSkipsWhenUnhealthy5132026/07/23 15:28:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5142026/07/23 15:28:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5152026/07/23 15:28:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5162026/07/23 15:28:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5172026/07/23 15:28:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5182026/07/23 15:28:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5192026/07/23 15:28:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5202026/07/23 15:28:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5212026/07/23 15:28:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5222026/07/23 15:28:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"523--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)524=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle525=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle526=== RUN TestProxyWriteTimeout527=== PAUSE TestProxyWriteTimeout528=== RUN TestIsValidUploadKey529=== PAUSE TestIsValidUploadKey530=== RUN TestUploadHandlersRejectInvalidKeys531=== PAUSE TestUploadHandlersRejectInvalidKeys532=== RUN TestUploadHandlersRejectOversizedBody533=== PAUSE TestUploadHandlersRejectOversizedBody534=== RUN TestService_cleanupPendingClosuresHandler535=== PAUSE TestService_cleanupPendingClosuresHandler536=== RUN TestService_createPendingClosureHandler537=== PAUSE TestService_createPendingClosureHandler538=== RUN TestService_verifyS3Integrity539=== PAUSE TestService_verifyS3Integrity540=== RUN TestCompleteMultipartUnregistered541=== PAUSE TestCompleteMultipartUnregistered542=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT543=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT544=== CONT TestReadProxyConditionalGet545=== CONT TestReadProxyInvalidPath546=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle547=== CONT TestCompletedNarNotReofferedAcrossClosures548=== CONT TestService_cleanupPendingClosuresHandler549=== CONT TestGCTaskStore_PhaseUpdates550--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)551=== CONT TestGCTaskStore_CompletedAllowsNewTask552=== CONT TestGCTaskStore_Fail553=== CONT TestGCTaskStore_ConflictDifferentParams554=== CONT TestGCTaskStore_DeduplicateSameParams555=== CONT TestGCTaskStore_StartNew556--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)557--- PASS: TestGCTaskStore_Fail (0.00s)558--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)559=== CONT TestReadProxyHead560=== CONT TestGCMetrics561=== CONT TestGCTaskStore_GetReturnsLatest562=== CONT TestService_AuthMiddleware563=== CONT TestGCBugBareHashReferences564--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)565--- PASS: TestGCTaskStore_StartNew (0.00s)566--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)567=== CONT TestGCTaskStore_GetEmpty568--- PASS: TestGCTaskStore_GetEmpty (0.00s)569=== CONT TestPinProtectsFromGC5702026-07-23 15:28:58.985 UTC [45489] ERROR: relation "goose_db_version" does not exist at character 365712026-07-23 15:28:58.985 UTC [45489] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5722026-07-23 15:28:58.985 UTC [45488] ERROR: relation "goose_db_version" does not exist at character 365732026-07-23 15:28:58.985 UTC [45488] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5742026-07-23 15:28:58.988 UTC [45490] ERROR: relation "goose_db_version" does not exist at character 365752026-07-23 15:28:58.988 UTC [45490] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5762026-07-23 15:28:58.989 UTC [45491] ERROR: relation "goose_db_version" does not exist at character 365772026-07-23 15:28:58.989 UTC [45491] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5782026-07-23 15:28:58.991 UTC [45492] ERROR: relation "goose_db_version" does not exist at character 365792026-07-23 15:28:58.991 UTC [45492] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5802026-07-23 15:28:58.991 UTC [45495] ERROR: relation "goose_db_version" does not exist at character 365812026-07-23 15:28:58.991 UTC [45495] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5822026-07-23 15:28:58.992 UTC [45493] ERROR: relation "goose_db_version" does not exist at character 365832026-07-23 15:28:58.992 UTC [45493] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5842026-07-23 15:28:58.992 UTC [45494] ERROR: relation "goose_db_version" does not exist at character 365852026-07-23 15:28:58.992 UTC [45494] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5862026-07-23 15:28:58.992 UTC [45497] ERROR: relation "goose_db_version" does not exist at character 365872026-07-23 15:28:58.992 UTC [45497] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5882026-07-23 15:28:58.993 UTC [45496] ERROR: relation "goose_db_version" does not exist at character 365892026-07-23 15:28:58.993 UTC [45496] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5902026/07/23 15:28:58 OK 20241026095416_initial_model.sql (7.12ms)5912026/07/23 15:28:58 OK 20241026095416_initial_model.sql (6.16ms)5922026/07/23 15:28:58 OK 20251210153512_drop_unused_gin_index.sql (852.17µs)5932026/07/23 15:28:58 OK 20251210153512_drop_unused_gin_index.sql (488.17µs)5942026/07/23 15:28:59 OK 20241026095416_initial_model.sql (8.42ms)5952026/07/23 15:28:59 OK 20241026095416_initial_model.sql (9.57ms)5962026/07/23 15:28:59 OK 20251218171726_add_pins.sql (1.75ms)5972026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (789.25µs)5982026/07/23 15:28:59 OK 20251218171726_add_pins.sql (2.85ms)5992026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (785µs)6002026/07/23 15:28:59 OK 20241026095416_initial_model.sql (6.22ms)6012026/07/23 15:28:59 OK 20241026095416_initial_model.sql (6.57ms)6022026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (626.75µs)6032026/07/23 15:28:59 OK 20241026095416_initial_model.sql (8.52ms)6042026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (752.25µs)6052026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (1.66ms)6062026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200006072026/07/23 15:28:59 OK 20241026095416_initial_model.sql (7.31ms)6082026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (2.28ms)6092026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200006102026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (755.46µs)6112026/07/23 15:28:59 OK 20251218171726_add_pins.sql (2.14ms)6122026/07/23 15:28:59 OK 20251218171726_add_pins.sql (2.06ms)6132026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (825.13µs)6142026/07/23 15:28:59 OK 20251218171726_add_pins.sql (1.9ms)6152026/07/23 15:28:59 OK 20251218171726_add_pins.sql (1.24ms)6162026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.15ms)6172026/07/23 15:28:59 OK 20241026095416_initial_model.sql (7.38ms)6182026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.41ms)6192026/07/23 15:28:59 OK 20251218171726_add_pins.sql (1.23ms)6202026/07/23 15:28:59 OK 2_object_stats_trigger.sql (488.58µs)6212026/07/23 15:28:59 goose: up to current file version: 26222026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (1.39ms)6232026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200006242026/07/23 15:28:59 OK 2_object_stats_trigger.sql (603.25µs)6252026/07/23 15:28:59 goose: up to current file version: 26262026/07/23 15:28:59 OK 20251218171726_add_pins.sql (1.13ms)6272026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (1.66ms)6282026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200006292026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (757.17µs)6302026/07/23 15:28:59 OK 20241026095416_initial_model.sql (8.37ms)6312026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (1.97ms)6322026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200006332026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (2.12ms)6342026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200006352026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (1.71ms)6362026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200006372026/07/23 15:28:59 OK 20251218171726_add_pins.sql (1.38ms)6382026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (942.42µs)6392026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.51ms)6402026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.66ms)6412026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (1.92ms)6422026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200006432026/07/23 15:28:59 OK 2_object_stats_trigger.sql (411.67µs)6442026/07/23 15:28:59 goose: up to current file version: 26452026/07/23 15:28:59 OK 2_object_stats_trigger.sql (598.33µs)6462026/07/23 15:28:59 goose: up to current file version: 26472026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.08ms)6482026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.13ms)6492026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.76ms)6502026/07/23 15:28:59 OK 2_object_stats_trigger.sql (490.29µs)6512026/07/23 15:28:59 goose: up to current file version: 26522026/07/23 15:28:59 OK 2_object_stats_trigger.sql (688.25µs)6532026/07/23 15:28:59 goose: up to current file version: 26542026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.22ms)6552026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (1.66ms)6562026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200006572026/07/23 15:28:59 OK 2_object_stats_trigger.sql (513.33µs)6582026/07/23 15:28:59 goose: up to current file version: 26592026/07/23 15:28:59 OK 20251218171726_add_pins.sql (1.91ms)6602026/07/23 15:28:59 OK 2_object_stats_trigger.sql (658.46µs)6612026/07/23 15:28:59 goose: up to current file version: 26622026/07/23 15:28:59 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"663--- PASS: TestService_AuthMiddleware (0.32s)664=== CONT TestClientWithDependencies665{"timestamp":"2026-07-23T15:28:59.010372Z","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(10)"}6662026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (1.7ms)6672026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200006682026/07/23 15:28:59 INFO Received uploads request method=POST path=/api/pending_closures6692026/07/23 15:28:59 OK 1_commit_pending_closure.sql (2.54ms)6702026/07/23 15:28:59 INFO Received uploads request method=POST path=/api/pending_closures6712026/07/23 15:28:59 INFO Aborted multipart uploads count=06722026/07/23 15:28:59 INFO Received cleanup request method=DELETE path=/api/pending_closures673--- PASS: TestReadProxyInvalidPath (0.33s)674=== CONT TestClientMultipleUploads6752026/07/23 15:28:59 OK 2_object_stats_trigger.sql (1.72ms)6762026/07/23 15:28:59 INFO Aborted multipart uploads count=06772026/07/23 15:28:59 goose: up to current file version: 26782026/07/23 15:28:59 WARN Force mode enabled - objects will be deleted immediately without grace period6792026/07/23 15:28:59 OK 1_commit_pending_closure.sql (2.63ms)6802026/07/23 15:28:59 INFO Received uploads request method=POST path=/api/pending_closures6812026/07/23 15:28:59 OK 2_object_stats_trigger.sql (546µs)6822026/07/23 15:28:59 goose: up to current file version: 26832026/07/23 15:28:59 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=06842026/07/23 15:28:59 INFO Vacuumed table table=pending_closures6852026/07/23 15:28:59 INFO Vacuumed table table=pending_objects686--- PASS: TestReadProxyHead (0.33s)687=== CONT TestClientIntegration6882026/07/23 15:28:59 INFO Vacuumed table table=multipart_uploads6892026/07/23 15:28:59 INFO Vacuumed table table=closures6902026/07/23 15:28:59 INFO Vacuumed table table=objects691--- PASS: TestGCMetrics (0.33s)692=== CONT TestClientErrorHandling693=== RUN TestClientErrorHandling/InvalidStorePath694=== PAUSE TestClientErrorHandling/InvalidStorePath695=== RUN TestClientErrorHandling/InvalidAuthToken696=== PAUSE TestClientErrorHandling/InvalidAuthToken697=== RUN TestClientErrorHandling/ServerNotAvailable698=== PAUSE TestClientErrorHandling/ServerNotAvailable699=== CONT TestClientCADerivations700--- PASS: TestReadProxyConditionalGet (0.33s)701=== CONT TestCacheStatsHandler7022026/07/23 15:28:59 INFO Received cleanup request method=DELETE path=/api/pending_closures7032026/07/23 15:28:59 INFO Created nix-cache-info in bucket bucket=bucket117042026/07/23 15:28:59 INFO Aborted multipart uploads count=17052026/07/23 15:28:59 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7062026-07-23 15:28:59.029 UTC [45493] ERROR: Closure does not exist: id=17072026-07-23 15:28:59.029 UTC [45493] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE7082026-07-23 15:28:59.029 UTC [45493] STATEMENT: -- name: CommitPendingClosure :exec709 SELECT commit_pending_closure($1::bigint)710 711--- PASS: TestService_cleanupPendingClosuresHandler (0.34s)712=== CONT TestCacheConfigHandler713=== RUN TestCacheConfigHandler/full_config,_no_issuer714=== PAUSE TestCacheConfigHandler/full_config,_no_issuer715=== RUN TestCacheConfigHandler/no_cache_url_configured716=== PAUSE TestCacheConfigHandler/no_cache_url_configured717=== RUN TestCacheConfigHandler/no_signing_keys718=== PAUSE TestCacheConfigHandler/no_signing_keys719=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator720=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator721=== CONT TestService_AuthMiddleware_OIDC7222026/07/23 15:28:59 INFO OIDC provider initialized name=test7232026/07/23 15:28:59 INFO Received complete multipart upload request method=POST path=/api/multipart/complete724=== NAME TestPinProtectsFromGC725 client_integration_test.go:646: Pinned store path: /nix/var/nix/builds/nix-45316-59033543/TestPinProtectsFromGC421696926/001/store/i2r4p8zczx70nca85zp7gs4wzrb1lnmf-pinned-file.txt726 client_integration_test.go:647: Unpinned store path: /nix/var/nix/builds/nix-45316-59033543/TestPinProtectsFromGC421696926/001/store/7q7nxwn4p46ds4lnnp1lwp15h4d8rqkk-unpinned-file.txt7272026/07/23 15:28:59 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7282026/07/23 15:28:59 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YTA4MDc5MzctMmNmYS00YTliLThmNTItMmEyNjU5ZjFkOGJmLmY5ZTExZmYzLTkwYTItNDIwZi04OWM4LWM3YTUzYWU0ZDAxM3gxNzg0ODIwNTM5MDE1Nzg2MDAw parts=127292026/07/23 15:28:59 INFO Received uploads request method=POST path=/api/pending_closures730--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.51s)731=== CONT TestService_ReadAuthMiddleware7322026-07-23 15:28:59.205 UTC [45540] ERROR: relation "goose_db_version" does not exist at character 367332026-07-23 15:28:59.205 UTC [45540] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7342026-07-23 15:28:59.205 UTC [45541] ERROR: relation "goose_db_version" does not exist at character 367352026-07-23 15:28:59.205 UTC [45541] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7362026-07-23 15:28:59.220 UTC [45544] ERROR: relation "goose_db_version" does not exist at character 367372026-07-23 15:28:59.220 UTC [45544] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7382026/07/23 15:28:59 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"739--- PASS: TestGCBugBareHashReferences (0.55s)740=== CONT TestService_AuthMiddleware_MTLSBoundSubjects7412026/07/23 15:28:59 OK 20241026095416_initial_model.sql (16.77ms)7422026/07/23 15:28:59 OK 20241026095416_initial_model.sql (10.42ms)7432026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (527.79µs)7442026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (682.42µs)7452026/07/23 15:28:59 OK 20241026095416_initial_model.sql (10.8ms)7462026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (779.79µs)7472026/07/23 15:28:59 OK 20251218171726_add_pins.sql (2.25ms)7482026/07/23 15:28:59 OK 20251218171726_add_pins.sql (1.93ms)7492026/07/23 15:28:59 OK 20251218171726_add_pins.sql (1.42ms)7502026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (5.89ms)7512026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200007522026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (6.87ms)7532026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200007542026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (6.98ms)7552026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200007562026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.12ms)7572026/07/23 15:28:59 OK 1_commit_pending_closure.sql (857.75µs)7582026-07-23 15:28:59.249 UTC [45549] ERROR: relation "goose_db_version" does not exist at character 367592026-07-23 15:28:59.249 UTC [45549] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7602026/07/23 15:28:59 OK 2_object_stats_trigger.sql (458.29µs)7612026/07/23 15:28:59 goose: up to current file version: 27622026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.39ms)7632026-07-23 15:28:59.249 UTC [45548] ERROR: relation "goose_db_version" does not exist at character 367642026-07-23 15:28:59.249 UTC [45548] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7652026/07/23 15:28:59 OK 2_object_stats_trigger.sql (401µs)7662026/07/23 15:28:59 goose: up to current file version: 27672026/07/23 15:28:59 OK 2_object_stats_trigger.sql (377.92µs)7682026/07/23 15:28:59 goose: up to current file version: 27692026/07/23 15:28:59 INFO Created nix-cache-info in bucket bucket=bucket147702026/07/23 15:28:59 INFO Created nix-cache-info in bucket bucket=bucket127712026/07/23 15:28:59 INFO Created nix-cache-info in bucket bucket=bucket137722026/07/23 15:28:59 INFO Received uploads request method=POST path=/api/pending_closures7732026/07/23 15:28:59 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)7742026/07/23 15:28:59 INFO Uploading i2r4p8zczx70nca85zp7gs4wzrb1lnmf-pinned-file.txt (128B)7752026/07/23 15:28:59 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"7762026/07/23 15:28:59 OK 20241026095416_initial_model.sql (6.29ms)7772026/07/23 15:28:59 WARN Failed to register uploaded object key=i2r4p8zczx70nca85zp7gs4wzrb1lnmf.ls error="server returned 404: 404 page not found\n"7782026/07/23 15:28:59 OK 20241026095416_initial_model.sql (6.63ms)7792026/07/23 15:28:59 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign7802026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (1.3ms)7812026/07/23 15:28:59 INFO Signed narinfos id=1 count=17822026/07/23 15:28:59 INFO Uploading 1 narinfos7832026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (1.22ms)7842026/07/23 15:28:59 WARN Failed to register uploaded object key=i2r4p8zczx70nca85zp7gs4wzrb1lnmf.narinfo error="server returned 404: 404 page not found\n"7852026/07/23 15:28:59 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7862026/07/23 15:28:59 OK 20251218171726_add_pins.sql (1.35ms)7872026/07/23 15:28:59 OK 20251218171726_add_pins.sql (1.63ms)7882026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (2.84ms)7892026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200007902026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.28ms)7912026/07/23 15:28:59 INFO Completed upload id=17922026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (3.3ms)7932026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200007942026/07/23 15:28:59 INFO Upload complete. (85ms)7952026/07/23 15:28:59 OK 2_object_stats_trigger.sql (222µs)7962026/07/23 15:28:59 goose: up to current file version: 27972026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.08ms)7982026/07/23 15:28:59 OK 2_object_stats_trigger.sql (334.5µs)7992026/07/23 15:28:59 goose: up to current file version: 28002026/07/23 15:28:59 INFO Created nix-cache-info in bucket bucket=bucket16801--- PASS: TestCacheStatsHandler (0.26s)802=== CONT TestService_AuthMiddleware_MTLSProxyHeader803=== NAME TestClientMultipleUploads804 client_integration_test.go:338: Created store path 0: /nix/var/nix/builds/nix-45316-59033543/TestClientMultipleUploads4093849613/001/store/bcyg90f5qn5b62ranr0w9ks8ybpn71dp-test-file-0.txt805=== NAME TestClientIntegration806 client_integration_test.go:276: Created store path: /nix/var/nix/builds/nix-45316-59033543/TestClientIntegration1322840590/002/store/x9jyilcv1hphk8vzxzqghy73r20acrbp-test-file.txt8072026/07/23 15:28:59 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"8082026-07-23 15:28:59.360 UTC [45570] ERROR: relation "goose_db_version" does not exist at character 368092026-07-23 15:28:59.360 UTC [45570] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC810=== NAME TestClientMultipleUploads811 client_integration_test.go:338: Created store path 1: /nix/var/nix/builds/nix-45316-59033543/TestClientMultipleUploads4093849613/001/store/ns8m4cafck9c5j62g6j9mbpj72k884hd-test-file-1.txt8122026/07/23 15:28:59 OK 20241026095416_initial_model.sql (7.44ms)8132026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (936.67µs)8142026/07/23 15:28:59 OK 20251218171726_add_pins.sql (1.57ms)8152026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (1.74ms)8162026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200008172026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.62ms)8182026/07/23 15:28:59 OK 2_object_stats_trigger.sql (467.58µs)8192026/07/23 15:28:59 goose: up to current file version: 2820=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token821=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token822=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected823=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected824=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected825=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected826=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured827=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured828=== CONT TestMultipartCleanup8292026/07/23 15:28:59 INFO Received uploads request method=POST path=/api/pending_closures8302026/07/23 15:28:59 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8312026/07/23 15:28:59 INFO Uploading 7q7nxwn4p46ds4lnnp1lwp15h4d8rqkk-unpinned-file.txt (128B)8322026/07/23 15:28:59 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"8332026/07/23 15:28:59 WARN Failed to register uploaded object key=7q7nxwn4p46ds4lnnp1lwp15h4d8rqkk.ls error="server returned 404: 404 page not found\n"8342026/07/23 15:28:59 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign8352026/07/23 15:28:59 INFO Signed narinfos id=2 count=18362026/07/23 15:28:59 INFO Uploading 1 narinfos8372026/07/23 15:28:59 WARN Failed to register uploaded object key=7q7nxwn4p46ds4lnnp1lwp15h4d8rqkk.narinfo error="server returned 404: 404 page not found\n"8382026/07/23 15:28:59 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete8392026/07/23 15:28:59 INFO Completed upload id=28402026/07/23 15:28:59 INFO Upload complete. (90ms)8412026/07/23 15:28:59 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"842=== NAME TestClientMultipleUploads843 client_integration_test.go:338: Created store path 2: /nix/var/nix/builds/nix-45316-59033543/TestClientMultipleUploads4093849613/001/store/l6l3k7bbia8h0f9brk56df9ymc3djdfc-test-file-2.txt8442026/07/23 15:28:59 INFO Received create pin request method=POST path=/api/pins/myapp8452026/07/23 15:28:59 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-45316-59033543/TestPinProtectsFromGC421696926/001/store/i2r4p8zczx70nca85zp7gs4wzrb1lnmf-pinned-file.txt narinfo_key=i2r4p8zczx70nca85zp7gs4wzrb1lnmf.narinfo8462026/07/23 15:28:59 INFO Starting cleanup of old closures method=DELETE path=/api/closures8472026/07/23 15:28:59 INFO Garbage collection started8482026/07/23 15:28:59 INFO Received uploads request method=POST path=/api/pending_closures8492026/07/23 15:28:59 INFO Aborted multipart uploads count=08502026/07/23 15:28:59 WARN Force mode enabled - objects will be deleted immediately without grace period8512026/07/23 15:28:59 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8522026/07/23 15:28:59 INFO Uploading x9jyilcv1hphk8vzxzqghy73r20acrbp-test-file.txt (152B)8532026/07/23 15:28:59 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"8542026/07/23 15:28:59 WARN Failed to register uploaded object key=x9jyilcv1hphk8vzxzqghy73r20acrbp.ls error="server returned 404: 404 page not found\n"8552026/07/23 15:28:59 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign8562026/07/23 15:28:59 INFO Signed narinfos id=1 count=18572026/07/23 15:28:59 INFO Uploading 1 narinfos8582026/07/23 15:28:59 WARN Failed to register uploaded object key=x9jyilcv1hphk8vzxzqghy73r20acrbp.narinfo error="server returned 404: 404 page not found\n"8592026/07/23 15:28:59 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8602026/07/23 15:28:59 INFO Completed upload id=18612026/07/23 15:28:59 INFO Upload complete. (101ms)862=== NAME TestClientIntegration863 client_integration_test.go:292: Retrieved narinfo from S3:864 StorePath: /nix/var/nix/builds/nix-45316-59033543/TestClientIntegration1322840590/002/store/x9jyilcv1hphk8vzxzqghy73r20acrbp-test-file.txt865 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst866 Compression: zstd867 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1868 NarSize: 152869 References: 870 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1871 client_integration_test.go:293: Retrieved .ls file from S3 (compressed size: 77 bytes)872 client_integration_test.go:293: Decompressed .ls content (64 bytes):873 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}874 client_integration_test.go:296: Testing garbage collection...8752026/07/23 15:28:59 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"8762026-07-23 15:28:59.501 UTC [45596] ERROR: relation "goose_db_version" does not exist at character 368772026-07-23 15:28:59.501 UTC [45596] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8782026-07-23 15:28:59.503 UTC [45595] ERROR: relation "goose_db_version" does not exist at character 368792026-07-23 15:28:59.503 UTC [45595] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC880=== NAME TestClientWithDependencies881 client_integration_test.go:593: Built derivation: /nix/var/nix/builds/nix-45316-59033543/TestClientWithDependencies4080080388/001/store/33lln0xgf6awb0fpw279mkmdlpq1b39g-test-script8822026/07/23 15:28:59 INFO Starting cleanup of old closures method=DELETE path=/api/closures8832026/07/23 15:28:59 INFO Garbage collection started8842026/07/23 15:28:59 OK 20241026095416_initial_model.sql (9.82ms)8852026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (517.38µs)8862026/07/23 15:28:59 INFO Aborted multipart uploads count=08872026/07/23 15:28:59 OK 20251218171726_add_pins.sql (937.83µs)8882026/07/23 15:28:59 WARN Force mode enabled - objects will be deleted immediately without grace period8892026/07/23 15:28:59 OK 20241026095416_initial_model.sql (16.56ms)8902026/07/23 15:28:59 INFO Received uploads request method=POST path=/api/pending_closures8912026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (673.29µs)8922026-07-23 15:28:59.531 UTC [45601] ERROR: relation "goose_db_version" does not exist at character 368932026-07-23 15:28:59.531 UTC [45601] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC894=== NAME TestClientCADerivations895 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-45316-59033543/TestClientCADerivations3983726743/001/store/6x7dcnzgqjnjpcqvzvdyqgkkmr3kqp8r-ca-test8962026/07/23 15:28:59 OK 20251218171726_add_pins.sql (3.55ms)8972026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (14.84ms)8982026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200008992026/07/23 15:28:59 INFO Received uploads request method=POST path=/api/pending_closures9002026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.58ms)9012026/07/23 15:28:59 INFO Received uploads request method=POST path=/api/pending_closures9022026/07/23 15:28:59 OK 2_object_stats_trigger.sql (416.17µs)9032026/07/23 15:28:59 goose: up to current file version: 29042026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (3.16ms)9052026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200009062026/07/23 15:28:59 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)9072026/07/23 15:28:59 INFO Uploading ns8m4cafck9c5j62g6j9mbpj72k884hd-test-file-1.txt (160B)9082026/07/23 15:28:59 INFO Uploading l6l3k7bbia8h0f9brk56df9ymc3djdfc-test-file-2.txt (160B)9092026/07/23 15:28:59 INFO Uploading bcyg90f5qn5b62ranr0w9ks8ybpn71dp-test-file-0.txt (160B)9102026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.76ms)9112026/07/23 15:28:59 WARN mTLS auth: subject not in bound subjects subject="CN=writer"912--- PASS: TestService_ReadAuthMiddleware (0.34s)913=== CONT TestReadProxy4049142026/07/23 15:28:59 OK 2_object_stats_trigger.sql (1.57ms)9152026/07/23 15:28:59 goose: up to current file version: 29162026/07/23 15:28:59 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"9172026/07/23 15:28:59 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"9182026/07/23 15:28:59 WARN Failed to register uploaded object key=ns8m4cafck9c5j62g6j9mbpj72k884hd.ls error="server returned 404: 404 page not found\n"9192026/07/23 15:28:59 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"9202026/07/23 15:28:59 WARN Failed to register uploaded object key=bcyg90f5qn5b62ranr0w9ks8ybpn71dp.ls error="server returned 404: 404 page not found\n"9212026/07/23 15:28:59 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"9222026/07/23 15:28:59 WARN mTLS auth: bound subjects configured but subject DN unavailable9232026/07/23 15:28:59 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"924--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.31s)925=== CONT TestReadProxyNarStreaming9262026/07/23 15:28:59 WARN Failed to register uploaded object key=l6l3k7bbia8h0f9brk56df9ymc3djdfc.ls error="server returned 404: 404 page not found\n"9272026/07/23 15:28:59 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9282026/07/23 15:28:59 INFO Signed narinfos id=1 count=19292026/07/23 15:28:59 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign9302026/07/23 15:28:59 INFO Signed narinfos id=2 count=19312026/07/23 15:28:59 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign9322026/07/23 15:28:59 INFO Signed narinfos id=3 count=19332026/07/23 15:28:59 INFO Uploading 3 narinfos9342026/07/23 15:28:59 OK 20241026095416_initial_model.sql (9.41ms)9352026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (1.01ms)9362026/07/23 15:28:59 WARN Failed to register uploaded object key=bcyg90f5qn5b62ranr0w9ks8ybpn71dp.narinfo error="server returned 404: 404 page not found\n"9372026/07/23 15:28:59 WARN Failed to register uploaded object key=ns8m4cafck9c5j62g6j9mbpj72k884hd.narinfo error="server returned 404: 404 page not found\n"9382026/07/23 15:28:59 WARN Failed to register uploaded object key=l6l3k7bbia8h0f9brk56df9ymc3djdfc.narinfo error="server returned 404: 404 page not found\n"9392026/07/23 15:28:59 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9402026/07/23 15:28:59 OK 20251218171726_add_pins.sql (2.33ms)9412026/07/23 15:28:59 INFO Completed upload id=19422026/07/23 15:28:59 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete9432026/07/23 15:28:59 INFO Completed upload id=29442026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (2.13ms)9452026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200009462026/07/23 15:28:59 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete9472026/07/23 15:28:59 INFO Completed upload id=39482026/07/23 15:28:59 INFO Upload complete. (101ms)949=== NAME TestClientMultipleUploads950 client_integration_test.go:349: Uploaded 3 paths in 137.02025ms9512026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.04ms)9522026/07/23 15:28:59 OK 2_object_stats_trigger.sql (438.5µs)9532026/07/23 15:28:59 goose: up to current file version: 2954--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.27s)955=== CONT TestReadProxyNarinfoAlreadyDecompressed956=== NAME TestClientWithDependencies957 client_integration_test.go:595: Found 1 dependencies (including self)958--- PASS: TestClientMultipleUploads (0.55s)959=== CONT TestReadProxyNarinfo960=== NAME TestClientCADerivations961 client_ca_test.go:139: Found 1 dependencies (including self)9622026-07-23 15:28:59.599 UTC [45617] ERROR: relation "goose_db_version" does not exist at character 369632026-07-23 15:28:59.599 UTC [45617] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9642026/07/23 15:28:59 OK 20241026095416_initial_model.sql (5.47ms)9652026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (1.31ms)9662026/07/23 15:28:59 OK 20251218171726_add_pins.sql (1.72ms)9672026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (2.03ms)9682026/07/23 15:28:59 goose: successfully migrated database to version: 202606281200009692026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.17ms)9702026/07/23 15:28:59 OK 2_object_stats_trigger.sql (212.38µs)9712026/07/23 15:28:59 goose: up to current file version: 29722026/07/23 15:28:59 INFO Received uploads request method=POST path=/api/pending_closures9732026/07/23 15:28:59 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9742026/07/23 15:28:59 INFO Received uploads request method=POST path=/api/pending_closures9752026/07/23 15:28:59 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9762026/07/23 15:28:59 INFO Uploading 33lln0xgf6awb0fpw279mkmdlpq1b39g-test-script (136B)9772026/07/23 15:28:59 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9782026/07/23 15:28:59 INFO Received uploads request method=POST path=/api/pending_closures9792026/07/23 15:28:59 WARN Failed to register uploaded object key=log/7am9j9p3jyvpl99z928k55bddxgy46am-test-script.drv error="server returned 404: 404 page not found\n"9802026/07/23 15:28:59 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"9812026/07/23 15:28:59 WARN Failed to register uploaded object key=33lln0xgf6awb0fpw279mkmdlpq1b39g.ls error="server returned 404: 404 page not found\n"9822026/07/23 15:28:59 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9832026/07/23 15:28:59 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9842026/07/23 15:28:59 INFO Uploading 6x7dcnzgqjnjpcqvzvdyqgkkmr3kqp8r-ca-test (144B)9852026/07/23 15:28:59 INFO Signed narinfos id=1 count=19862026/07/23 15:28:59 INFO Uploading 1 narinfos9872026/07/23 15:28:59 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"9882026/07/23 15:28:59 WARN Failed to register uploaded object key=log/jbyfm4yzzz7f2w89jas89kn4nb8gx0vc-ca-test.drv error="server returned 404: 404 page not found\n"9892026/07/23 15:28:59 WARN Failed to register uploaded object key=33lln0xgf6awb0fpw279mkmdlpq1b39g.narinfo error="server returned 404: 404 page not found\n"9902026/07/23 15:28:59 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9912026/07/23 15:28:59 WARN Failed to register uploaded object key=6x7dcnzgqjnjpcqvzvdyqgkkmr3kqp8r.ls error="server returned 404: 404 page not found\n"9922026/07/23 15:28:59 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9932026/07/23 15:28:59 INFO Signed narinfos id=1 count=19942026/07/23 15:28:59 INFO Uploading 1 narinfos9952026/07/23 15:28:59 WARN Failed to register uploaded object key=6x7dcnzgqjnjpcqvzvdyqgkkmr3kqp8r.narinfo error="server returned 404: 404 page not found\n"9962026/07/23 15:28:59 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9972026/07/23 15:28:59 INFO Completed upload id=19982026/07/23 15:28:59 INFO Upload complete. (109ms)9992026/07/23 15:28:59 INFO Completed upload id=110002026/07/23 15:28:59 INFO Upload complete. (94ms)1001=== NAME TestClientWithDependencies1002 client_integration_test.go:597: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-45316-59033543/TestClientWithDependencies4080080388/001/store) requires matching store prefix1003=== NAME TestClientCADerivations1004 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-45316-59033543/TestClientCADerivations3983726743/001/store/6x7dcnzgqjnjpcqvzvdyqgkkmr3kqp8r-ca-test1005 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1006 Compression: zstd1007 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1008 NarSize: 1441009 References: 1010 Deriver: /nix/var/nix/builds/nix-45316-59033543/TestClientCADerivations3983726743/001/store/jbyfm4yzzz7f2w89jas89kn4nb8gx0vc-ca-test.drv1011 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1012 client_ca_test.go:185: Checking for realisation files in S3...1013 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1014 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1015--- PASS: TestClientWithDependencies (0.70s)1016=== CONT TestIsValidCachePath1017=== RUN TestIsValidCachePath/narinfo1018=== PAUSE TestIsValidCachePath/narinfo1019=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1020=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1021=== RUN TestIsValidCachePath/nar_zst1022=== PAUSE TestIsValidCachePath/nar_zst1023=== RUN TestIsValidCachePath/nar_xz1024=== PAUSE TestIsValidCachePath/nar_xz1025=== RUN TestIsValidCachePath/nar_bz21026=== PAUSE TestIsValidCachePath/nar_bz21027=== RUN TestIsValidCachePath/nar_uncompressed1028=== PAUSE TestIsValidCachePath/nar_uncompressed1029=== RUN TestIsValidCachePath/ls1030=== PAUSE TestIsValidCachePath/ls1031=== RUN TestIsValidCachePath/log1032=== PAUSE TestIsValidCachePath/log1033=== RUN TestIsValidCachePath/realisation1034=== PAUSE TestIsValidCachePath/realisation1035=== RUN TestIsValidCachePath/nix-cache-info1036=== PAUSE TestIsValidCachePath/nix-cache-info1037=== RUN TestIsValidCachePath/index.html1038=== PAUSE TestIsValidCachePath/index.html1039=== RUN TestIsValidCachePath/traversal_parent1040=== PAUSE TestIsValidCachePath/traversal_parent1041=== RUN TestIsValidCachePath/traversal_in_middle1042=== PAUSE TestIsValidCachePath/traversal_in_middle1043=== RUN TestIsValidCachePath/invalid_char_e1044=== PAUSE TestIsValidCachePath/invalid_char_e1045=== RUN TestIsValidCachePath/invalid_char_u1046=== PAUSE TestIsValidCachePath/invalid_char_u1047=== RUN TestIsValidCachePath/random_path1048=== PAUSE TestIsValidCachePath/random_path1049=== RUN TestIsValidCachePath/empty1050=== PAUSE TestIsValidCachePath/empty1051=== RUN TestIsValidCachePath/leading_slash1052=== PAUSE TestIsValidCachePath/leading_slash1053=== RUN TestIsValidCachePath/wrong_extension1054=== PAUSE TestIsValidCachePath/wrong_extension1055=== RUN TestIsValidCachePath/short_hash1056=== PAUSE TestIsValidCachePath/short_hash1057=== CONT TestParseSingleRange1058=== RUN TestParseSingleRange/none1059=== PAUSE TestParseSingleRange/none1060=== RUN TestParseSingleRange/unknown_unit1061=== PAUSE TestParseSingleRange/unknown_unit1062=== RUN TestParseSingleRange/multi-range_ignored1063=== PAUSE TestParseSingleRange/multi-range_ignored1064=== RUN TestParseSingleRange/malformed_no_dash1065=== PAUSE TestParseSingleRange/malformed_no_dash1066=== RUN TestParseSingleRange/malformed_both_empty1067=== PAUSE TestParseSingleRange/malformed_both_empty1068=== RUN TestParseSingleRange/malformed_end_before_start1069=== PAUSE TestParseSingleRange/malformed_end_before_start1070=== RUN TestParseSingleRange/closed1071=== PAUSE TestParseSingleRange/closed1072=== RUN TestParseSingleRange/open-ended1073=== PAUSE TestParseSingleRange/open-ended1074=== RUN TestParseSingleRange/end_clamped_to_size1075=== PAUSE TestParseSingleRange/end_clamped_to_size1076=== RUN TestParseSingleRange/suffix1077=== PAUSE TestParseSingleRange/suffix1078=== RUN TestParseSingleRange/suffix_exceeds_size1079=== PAUSE TestParseSingleRange/suffix_exceeds_size1080=== RUN TestParseSingleRange/single_byte1081=== PAUSE TestParseSingleRange/single_byte1082=== RUN TestParseSingleRange/start_past_EOF1083=== PAUSE TestParseSingleRange/start_past_EOF1084=== RUN TestParseSingleRange/start_far_past_EOF1085=== PAUSE TestParseSingleRange/start_far_past_EOF1086=== CONT TestResurrectedObjectNotDeleted10872026/07/23 15:28:59 INFO Received cleanup request method=DELETE path=/api/pending_closures10882026/07/23 15:28:59 INFO Aborted multipart uploads count=11089--- PASS: TestMultipartCleanup (0.35s)1090=== CONT TestOrphanedObjectsGCStressTest10912026-07-23 15:28:59.741 UTC [45630] ERROR: relation "goose_db_version" does not exist at character 3610922026-07-23 15:28:59.741 UTC [45630] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1093=== NAME TestClientCADerivations1094 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket16?endpoint=http://localhost:53507®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-45316-59033543/TestClientCADerivations3983726743/001/store'1095 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11096--- PASS: TestClientCADerivations (0.73s)1097=== CONT TestOrphanedObjectsGC10982026-07-23 15:28:59.752 UTC [45632] ERROR: relation "goose_db_version" does not exist at character 3610992026-07-23 15:28:59.752 UTC [45632] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11002026/07/23 15:28:59 OK 20241026095416_initial_model.sql (9.91ms)11012026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (688.08µs)11022026/07/23 15:28:59 OK 20251218171726_add_pins.sql (2.01ms)11032026/07/23 15:28:59 OK 20241026095416_initial_model.sql (10.27ms)11042026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (772.5µs)11052026/07/23 15:28:59 OK 20251218171726_add_pins.sql (814.58µs)11062026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (10.2ms)11072026/07/23 15:28:59 goose: successfully migrated database to version: 2026062812000011082026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (6.74ms)11092026/07/23 15:28:59 goose: successfully migrated database to version: 2026062812000011102026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.92ms)11112026/07/23 15:28:59 OK 2_object_stats_trigger.sql (565µs)11122026/07/23 15:28:59 goose: up to current file version: 211132026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.77ms)11142026/07/23 15:28:59 OK 2_object_stats_trigger.sql (303.58µs)11152026/07/23 15:28:59 goose: up to current file version: 211162026-07-23 15:28:59.781 UTC [45635] ERROR: relation "goose_db_version" does not exist at character 3611172026-07-23 15:28:59.781 UTC [45635] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11182026-07-23 15:28:59.782 UTC [45636] ERROR: relation "goose_db_version" does not exist at character 3611192026-07-23 15:28:59.782 UTC [45636] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1120--- PASS: TestReadProxy404 (0.24s)1121=== CONT TestObjectStatsTrigger1122--- PASS: TestReadProxyNarStreaming (0.24s)1123=== CONT TestCreatePendingClosureRejectsOversizedNAR11242026/07/23 15:28:59 INFO Received uploads request method=POST path=/api/pending_closures1125--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1126=== CONT TestServerTLSConfig1127=== RUN TestServerTLSConfig/no_client_CA1128=== PAUSE TestServerTLSConfig/no_client_CA1129=== RUN TestServerTLSConfig/missing_CA_file1130=== PAUSE TestServerTLSConfig/missing_CA_file1131=== RUN TestServerTLSConfig/not_a_PEM_file1132=== PAUSE TestServerTLSConfig/not_a_PEM_file1133=== CONT TestService_NativeMTLS11342026/07/23 15:28:59 OK 20241026095416_initial_model.sql (11.7ms)11352026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (7.29ms)11362026/07/23 15:28:59 OK 20241026095416_initial_model.sql (13.9ms)11372026/07/23 15:28:59 OK 20251218171726_add_pins.sql (1.3ms)11382026/07/23 15:28:59 OK 20251210153512_drop_unused_gin_index.sql (810.71µs)11392026/07/23 15:28:59 OK 20251218171726_add_pins.sql (719.54µs)11402026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (5.55ms)11412026/07/23 15:28:59 goose: successfully migrated database to version: 2026062812000011422026/07/23 15:28:59 OK 20260628120000_add_object_size_and_stats.sql (4.16ms)11432026/07/23 15:28:59 goose: successfully migrated database to version: 2026062812000011442026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.44ms)11452026/07/23 15:28:59 OK 1_commit_pending_closure.sql (1.59ms)11462026/07/23 15:28:59 OK 2_object_stats_trigger.sql (486.25µs)11472026/07/23 15:28:59 goose: up to current file version: 211482026/07/23 15:28:59 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=011492026/07/23 15:28:59 OK 2_object_stats_trigger.sql (695.54µs)11502026/07/23 15:28:59 goose: up to current file version: 211512026/07/23 15:28:59 INFO Vacuumed table table=pending_closures1152--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.28s)1153=== CONT TestMetricsInventory1154--- PASS: TestReadProxyNarinfo (0.27s)1155=== CONT TestNARDeduplicationMetadataUploadBug11562026/07/23 15:28:59 INFO Vacuumed table table=pending_objects11572026/07/23 15:28:59 INFO Vacuumed table table=multipart_uploads11582026/07/23 15:28:59 INFO Vacuumed table table=closures11592026/07/23 15:28:59 INFO Vacuumed table table=objects11602026/07/23 15:28:59 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=011612026/07/23 15:28:59 INFO Vacuumed table table=pending_closures11622026/07/23 15:28:59 INFO Vacuumed table table=pending_objects11632026/07/23 15:28:59 INFO Vacuumed table table=multipart_uploads11642026/07/23 15:28:59 INFO Vacuumed table table=closures11652026/07/23 15:28:59 INFO Vacuumed table table=objects11662026-07-23 15:29:00.047 UTC [45649] ERROR: relation "goose_db_version" does not exist at character 3611672026-07-23 15:29:00.047 UTC [45649] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11682026-07-23 15:29:00.047 UTC [45648] ERROR: relation "goose_db_version" does not exist at character 3611692026-07-23 15:29:00.047 UTC [45648] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11702026-07-23 15:29:00.072 UTC [45651] ERROR: relation "goose_db_version" does not exist at character 3611712026-07-23 15:29:00.072 UTC [45651] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11722026/07/23 15:29:00 OK 20241026095416_initial_model.sql (7.43ms)11732026/07/23 15:29:00 OK 20251210153512_drop_unused_gin_index.sql (607.96µs)11742026/07/23 15:29:00 OK 20241026095416_initial_model.sql (6.79ms)11752026/07/23 15:29:00 OK 20251210153512_drop_unused_gin_index.sql (349.04µs)11762026/07/23 15:29:00 OK 20251218171726_add_pins.sql (873.54µs)11772026/07/23 15:29:00 OK 20251218171726_add_pins.sql (730.29µs)11782026/07/23 15:29:00 OK 20241026095416_initial_model.sql (10.34ms)11792026/07/23 15:29:00 OK 20251210153512_drop_unused_gin_index.sql (341.67µs)11802026/07/23 15:29:00 OK 20251218171726_add_pins.sql (738.71µs)11812026/07/23 15:29:00 OK 20260628120000_add_object_size_and_stats.sql (6.96ms)11822026/07/23 15:29:00 goose: successfully migrated database to version: 2026062812000011832026/07/23 15:29:00 OK 20260628120000_add_object_size_and_stats.sql (6.65ms)11842026/07/23 15:29:00 goose: successfully migrated database to version: 2026062812000011852026/07/23 15:29:00 OK 20260628120000_add_object_size_and_stats.sql (2.46ms)11862026/07/23 15:29:00 goose: successfully migrated database to version: 2026062812000011872026/07/23 15:29:00 OK 1_commit_pending_closure.sql (1.11ms)11882026/07/23 15:29:00 OK 1_commit_pending_closure.sql (1.2ms)11892026/07/23 15:29:00 OK 2_object_stats_trigger.sql (275.75µs)11902026/07/23 15:29:00 goose: up to current file version: 211912026/07/23 15:29:00 OK 2_object_stats_trigger.sql (246.04µs)11922026/07/23 15:29:00 goose: up to current file version: 211932026/07/23 15:29:00 OK 1_commit_pending_closure.sql (886.67µs)11942026/07/23 15:29:00 OK 2_object_stats_trigger.sql (205.67µs)11952026/07/23 15:29:00 goose: up to current file version: 211962026-07-23 15:29:00.096 UTC [45652] ERROR: relation "goose_db_version" does not exist at character 3611972026-07-23 15:29:00.096 UTC [45652] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11982026-07-23 15:29:00.107 UTC [45653] ERROR: relation "goose_db_version" does not exist at character 3611992026-07-23 15:29:00.107 UTC [45653] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12002026/07/23 15:29:00 OK 20241026095416_initial_model.sql (4.77ms)12012026/07/23 15:29:00 OK 20251210153512_drop_unused_gin_index.sql (585.13µs)12022026/07/23 15:29:00 OK 20241026095416_initial_model.sql (4.42ms)12032026/07/23 15:29:00 OK 20251210153512_drop_unused_gin_index.sql (343.42µs)12042026/07/23 15:29:00 OK 20251218171726_add_pins.sql (732.25µs)12052026/07/23 15:29:00 OK 20251218171726_add_pins.sql (1.81ms)12062026/07/23 15:29:00 OK 20260628120000_add_object_size_and_stats.sql (2.39ms)12072026/07/23 15:29:00 goose: successfully migrated database to version: 2026062812000012082026/07/23 15:29:00 OK 20260628120000_add_object_size_and_stats.sql (3.05ms)12092026/07/23 15:29:00 goose: successfully migrated database to version: 2026062812000012102026/07/23 15:29:00 OK 1_commit_pending_closure.sql (975.92µs)12112026/07/23 15:29:00 OK 1_commit_pending_closure.sql (1ms)12122026/07/23 15:29:00 OK 2_object_stats_trigger.sql (271.67µs)12132026/07/23 15:29:00 goose: up to current file version: 212142026/07/23 15:29:00 OK 2_object_stats_trigger.sql (291.58µs)12152026/07/23 15:29:00 goose: up to current file version: 21216--- PASS: TestResurrectedObjectNotDeleted (0.42s)1217=== CONT TestReadProxyRangeRequest12182026/07/23 15:29:00 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12192026/07/23 15:29:00 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1220--- PASS: TestService_NativeMTLS (0.34s)1221=== CONT TestCompleteMultipartUpload_ErrorButObjectExists1222--- PASS: TestObjectStatsTrigger (0.35s)1223=== CONT TestRedundantMultipartUpload12242026-07-23 15:29:00.156 UTC [45660] ERROR: relation "goose_db_version" does not exist at character 3612252026-07-23 15:29:00.156 UTC [45660] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12262026-07-23 15:29:00.157 UTC [45661] ERROR: relation "goose_db_version" does not exist at character 3612272026-07-23 15:29:00.157 UTC [45661] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12282026/07/23 15:29:00 OK 20241026095416_initial_model.sql (25.28ms)12292026/07/23 15:29:00 OK 20241026095416_initial_model.sql (25.33ms)12302026/07/23 15:29:00 OK 20251210153512_drop_unused_gin_index.sql (366.25µs)12312026/07/23 15:29:00 OK 20251210153512_drop_unused_gin_index.sql (386.67µs)12322026/07/23 15:29:00 OK 20251218171726_add_pins.sql (750.75µs)12332026/07/23 15:29:00 OK 20251218171726_add_pins.sql (782.29µs)12342026/07/23 15:29:00 OK 20260628120000_add_object_size_and_stats.sql (3.3ms)12352026/07/23 15:29:00 goose: successfully migrated database to version: 2026062812000012362026/07/23 15:29:00 OK 1_commit_pending_closure.sql (904.25µs)12372026/07/23 15:29:00 OK 2_object_stats_trigger.sql (184.79µs)12382026/07/23 15:29:00 goose: up to current file version: 212392026/07/23 15:29:00 OK 20260628120000_add_object_size_and_stats.sql (5.5ms)12402026/07/23 15:29:00 goose: successfully migrated database to version: 2026062812000012412026/07/23 15:29:00 OK 1_commit_pending_closure.sql (883.04µs)12422026/07/23 15:29:00 INFO Created nix-cache-info in bucket bucket=bucket3112432026/07/23 15:29:00 OK 2_object_stats_trigger.sql (235µs)12442026/07/23 15:29:00 goose: up to current file version: 21245--- PASS: TestMetricsInventory (0.39s)1246=== CONT TestService_healthCheckHandler1247=== NAME TestNARDeduplicationMetadataUploadBug1248 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-45316-59033543/TestNARDeduplicationMetadataUploadBug3127523435/001/store/p1y0qa37j6jkrp3xdyq6h2gbxzkjh4za-file1.txt12492026/07/23 15:29:00 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1250=== NAME TestOrphanedObjectsGC1251 orphaned_objects_gc_test.go:290: GC Test Summary:1252 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1253 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1254 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1255 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1256 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1257--- PASS: TestOrphanedObjectsGC (0.59s)1258=== CONT TestCacheConfigHandlerMaxNarSize1259--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1260=== CONT TestGenerateLandingPage1261--- PASS: TestGenerateLandingPage (0.00s)1262=== CONT TestParseSize1263--- PASS: TestParseSize (0.00s)1264=== CONT TestSkippedUploadsHandler12652026/07/23 15:29:00 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001266--- PASS: TestSkippedUploadsHandler (0.00s)1267=== CONT TestReadProxyDisabled12682026-07-23 15:29:00.354 UTC [45673] ERROR: relation "goose_db_version" does not exist at character 3612692026-07-23 15:29:00.354 UTC [45673] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12702026-07-23 15:29:00.372 UTC [45675] ERROR: relation "goose_db_version" does not exist at character 3612712026-07-23 15:29:00.372 UTC [45675] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12722026/07/23 15:29:00 INFO Received uploads request method=POST path=/api/pending_closures12732026/07/23 15:29:00 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12742026/07/23 15:29:00 INFO Uploading p1y0qa37j6jkrp3xdyq6h2gbxzkjh4za-file1.txt (160B)12752026/07/23 15:29:00 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12762026/07/23 15:29:00 WARN Failed to register uploaded object key=p1y0qa37j6jkrp3xdyq6h2gbxzkjh4za.ls error="server returned 404: 404 page not found\n"12772026/07/23 15:29:00 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12782026/07/23 15:29:00 INFO Signed narinfos id=1 count=112792026/07/23 15:29:00 INFO Uploading 1 narinfos12802026/07/23 15:29:00 OK 20241026095416_initial_model.sql (21.81ms)12812026/07/23 15:29:00 OK 20251210153512_drop_unused_gin_index.sql (606.75µs)12822026/07/23 15:29:00 WARN Failed to register uploaded object key=p1y0qa37j6jkrp3xdyq6h2gbxzkjh4za.narinfo error="server returned 404: 404 page not found\n"12832026/07/23 15:29:00 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12842026/07/23 15:29:00 OK 20241026095416_initial_model.sql (4.7ms)12852026/07/23 15:29:00 OK 20251218171726_add_pins.sql (1.31ms)12862026/07/23 15:29:00 OK 20251210153512_drop_unused_gin_index.sql (591.21µs)12872026/07/23 15:29:00 OK 20251218171726_add_pins.sql (799.25µs)12882026/07/23 15:29:00 INFO Completed upload id=112892026/07/23 15:29:00 INFO Upload complete. (94ms)1290=== NAME TestNARDeduplicationMetadataUploadBug1291 metadata_upload_test.go:54: Retrieved narinfo from S3:1292 StorePath: /nix/var/nix/builds/nix-45316-59033543/TestNARDeduplicationMetadataUploadBug3127523435/001/store/p1y0qa37j6jkrp3xdyq6h2gbxzkjh4za-file1.txt1293 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1294 Compression: zstd1295 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1296 NarSize: 1601297 References: 1298 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1299 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1300 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1301 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}13022026-07-23 15:29:00.398 UTC [45676] ERROR: relation "goose_db_version" does not exist at character 3613032026-07-23 15:29:00.398 UTC [45676] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13042026/07/23 15:29:00 OK 20260628120000_add_object_size_and_stats.sql (15.34ms)13052026/07/23 15:29:00 goose: successfully migrated database to version: 2026062812000013062026/07/23 15:29:00 OK 20260628120000_add_object_size_and_stats.sql (14.19ms)13072026/07/23 15:29:00 goose: successfully migrated database to version: 2026062812000013082026/07/23 15:29:00 OK 20241026095416_initial_model.sql (4.55ms)13092026/07/23 15:29:00 OK 20251210153512_drop_unused_gin_index.sql (612.67µs)13102026/07/23 15:29:00 OK 1_commit_pending_closure.sql (1.61ms)13112026/07/23 15:29:00 OK 1_commit_pending_closure.sql (1.56ms)13122026/07/23 15:29:00 OK 2_object_stats_trigger.sql (357.92µs)13132026/07/23 15:29:00 goose: up to current file version: 213142026/07/23 15:29:00 OK 2_object_stats_trigger.sql (414.29µs)13152026/07/23 15:29:00 goose: up to current file version: 213162026/07/23 15:29:00 OK 20251218171726_add_pins.sql (805.92µs)13172026/07/23 15:29:00 INFO Received uploads request method=POST path=/api/pending_closures1318--- PASS: TestReadProxyRangeRequest (0.28s)1319=== CONT TestCompleteMultipartUnregistered13202026/07/23 15:29:00 OK 20260628120000_add_object_size_and_stats.sql (4.81ms)13212026/07/23 15:29:00 goose: successfully migrated database to version: 2026062812000013222026/07/23 15:29:00 OK 1_commit_pending_closure.sql (961.79µs)13232026/07/23 15:29:00 OK 2_object_stats_trigger.sql (298.67µs)13242026/07/23 15:29:00 goose: up to current file version: 213252026/07/23 15:29:00 INFO Received uploads request method=POST path=/api/pending_closures13262026/07/23 15:29:00 INFO Received uploads request method=POST path=/api/pending_closures13272026/07/23 15:29:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1328{"timestamp":"2026-07-23T15:29:00.422438Z","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(10)"}1329{"timestamp":"2026-07-23T15:29:00.422467Z","level":"ERROR","fields":{"message":"complete_multipart_upload etag err client=Some(\"deadbeef\"), stored=\"\", part_id=1, bucket=bucket33, 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(10)"}13302026/07/23 15:29:00 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=YTA4MDc5MzctMmNmYS00YTliLThmNTItMmEyNjU5ZjFkOGJmLjE0YThiNDM3LTFiYjQtNDVkNi1hYmI4LTExNWFlMTk0NGUzOHgxNzg0ODIwNTQwNDE0OTA1MDAw13312026/07/23 15:29:00 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YTA4MDc5MzctMmNmYS00YTliLThmNTItMmEyNjU5ZjFkOGJmLjE0YThiNDM3LTFiYjQtNDVkNi1hYmI4LTExNWFlMTk0NGUzOHgxNzg0ODIwNTQwNDE0OTA1MDAw parts=11332--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.29s)1333=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT1334=== NAME TestNARDeduplicationMetadataUploadBug1335 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-45316-59033543/TestNARDeduplicationMetadataUploadBug3127523435/001/store/h1jd443cdrxyrki81a66ksid4hvwr8xk-file2.txt13362026-07-23 15:29:00.458 UTC [45684] ERROR: relation "goose_db_version" does not exist at character 3613372026-07-23 15:29:00.458 UTC [45684] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13382026/07/23 15:29:00 OK 20241026095416_initial_model.sql (9.92ms)13392026/07/23 15:29:00 OK 20251210153512_drop_unused_gin_index.sql (451.88µs)13402026/07/23 15:29:00 OK 20251218171726_add_pins.sql (790.08µs)13412026/07/23 15:29:00 OK 20260628120000_add_object_size_and_stats.sql (3.05ms)13422026/07/23 15:29:00 goose: successfully migrated database to version: 2026062812000013432026/07/23 15:29:00 OK 1_commit_pending_closure.sql (1.1ms)13442026/07/23 15:29:00 OK 2_object_stats_trigger.sql (449.38µs)13452026/07/23 15:29:00 goose: up to current file version: 21346--- PASS: TestService_healthCheckHandler (0.25s)1347=== CONT TestUploadHandlersRejectInvalidKeys1348=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1349=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1350=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1351=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1352=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1353=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1354=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1355=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1356=== CONT TestUploadHandlersRejectOversizedBody1357=== NAME TestOrphanedObjectsGCStressTest1358 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1359 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion1360=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1361=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1362=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1363=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1364=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1365=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1366=== CONT TestGracefulShutdownDrainsInflight13672026/07/23 15:29:00 INFO Starting HTTP server address=127.0.0.1:5368413682026/07/23 15:29:00 INFO Shutdown signal received, draining in-flight requests timeout=10s13692026/07/23 15:29:00 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13702026/07/23 15:29:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13712026/07/23 15:29:00 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YTA4MDc5MzctMmNmYS00YTliLThmNTItMmEyNjU5ZjFkOGJmLjRjYjQ1NzA1LTVlNWUtNDI5YS05Zjk0LWVjYWExMjVkOGVlZXgxNzg0ODIwNTQwNDE2NDM2MDAw parts=1213722026/07/23 15:29:00 INFO Received uploads request method=POST path=/api/pending_closures1373--- PASS: TestRedundantMultipartUpload (0.41s)1374=== CONT TestIsValidUploadKey1375=== RUN TestIsValidUploadKey/narinfo1376=== PAUSE TestIsValidUploadKey/narinfo1377=== RUN TestIsValidUploadKey/nar_zst1378=== PAUSE TestIsValidUploadKey/nar_zst1379=== RUN TestIsValidUploadKey/nar_xz1380=== PAUSE TestIsValidUploadKey/nar_xz1381=== RUN TestIsValidUploadKey/nar_plain1382=== PAUSE TestIsValidUploadKey/nar_plain1383=== RUN TestIsValidUploadKey/listing1384=== PAUSE TestIsValidUploadKey/listing1385=== RUN TestIsValidUploadKey/build_log1386=== PAUSE TestIsValidUploadKey/build_log1387=== RUN TestIsValidUploadKey/build_log_home-manager_file1388=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1389=== RUN TestIsValidUploadKey/build_log_plus_in_name1390=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1391=== RUN TestIsValidUploadKey/build_log_question_mark1392=== PAUSE TestIsValidUploadKey/build_log_question_mark1393=== RUN TestIsValidUploadKey/build_log_equals1394=== PAUSE TestIsValidUploadKey/build_log_equals1395=== RUN TestIsValidUploadKey/realisation1396=== PAUSE TestIsValidUploadKey/realisation1397=== RUN TestIsValidUploadKey/realisation_plus_in_output1398=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1399=== RUN TestIsValidUploadKey/nix-cache-info1400=== PAUSE TestIsValidUploadKey/nix-cache-info1401=== RUN TestIsValidUploadKey/index.html1402=== PAUSE TestIsValidUploadKey/index.html1403=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1404=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1405=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1406=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1407=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1408=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1409=== RUN TestIsValidUploadKey/traversal1410=== PAUSE TestIsValidUploadKey/traversal1411=== RUN TestIsValidUploadKey/traversal_nar1412=== PAUSE TestIsValidUploadKey/traversal_nar1413=== RUN TestIsValidUploadKey/absolute1414=== PAUSE TestIsValidUploadKey/absolute1415=== RUN TestIsValidUploadKey/empty_key1416=== PAUSE TestIsValidUploadKey/empty_key1417=== RUN TestIsValidUploadKey/unknown_type1418=== PAUSE TestIsValidUploadKey/unknown_type1419=== CONT TestService_verifyS3Integrity14202026/07/23 15:29:00 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)14212026/07/23 15:29:00 WARN Failed to register uploaded object key=h1jd443cdrxyrki81a66ksid4hvwr8xk.ls error="server returned 404: 404 page not found\n"14222026/07/23 15:29:00 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14232026/07/23 15:29:00 INFO Signed narinfos id=2 count=114242026/07/23 15:29:00 INFO Uploading 1 narinfos14252026/07/23 15:29:00 WARN Failed to register uploaded object key=h1jd443cdrxyrki81a66ksid4hvwr8xk.narinfo error="server returned 404: 404 page not found\n"14262026/07/23 15:29:00 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14272026/07/23 15:29:00 INFO Completed upload id=214282026/07/23 15:29:00 INFO Upload complete. (78ms)1429=== NAME TestNARDeduplicationMetadataUploadBug1430 metadata_upload_test.go:76: Retrieved narinfo from S3:1431 StorePath: /nix/var/nix/builds/nix-45316-59033543/TestNARDeduplicationMetadataUploadBug3127523435/001/store/h1jd443cdrxyrki81a66ksid4hvwr8xk-file2.txt1432 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1433 Compression: zstd1434 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1435 NarSize: 1601436 References: 1437 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1438 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1439 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1440 {"version":1,"root":{"type":"regular","size":44}}1441--- PASS: TestNARDeduplicationMetadataUploadBug (0.72s)1442=== CONT TestService_createPendingClosureHandler1443--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1444=== CONT TestProxyWriteTimeout1445=== RUN TestProxyWriteTimeout/narinfo1446=== PAUSE TestProxyWriteTimeout/narinfo1447=== RUN TestProxyWriteTimeout/1_GiB_nar1448=== PAUSE TestProxyWriteTimeout/1_GiB_nar1449=== RUN TestProxyWriteTimeout/10_GiB_nar1450=== PAUSE TestProxyWriteTimeout/10_GiB_nar1451=== RUN TestProxyWriteTimeout/unknown_size1452=== PAUSE TestProxyWriteTimeout/unknown_size1453=== CONT TestService_Rustfstest1454=== NAME TestOrphanedObjectsGCStressTest1455 orphaned_objects_gc_test.go:509: Stress test completed successfully:1456 orphaned_objects_gc_test.go:510: - Active objects preserved: 201457 orphaned_objects_gc_test.go:511: - Objects deleted: 2101458 orphaned_objects_gc_test.go:512: - Total GC'd: 2101459--- PASS: TestOrphanedObjectsGCStressTest (0.84s)1460=== CONT TestPresignedUploadRegisteredBeforeCommit14612026-07-23 15:29:00.604 UTC [45698] ERROR: relation "goose_db_version" does not exist at character 3614622026-07-23 15:29:00.604 UTC [45698] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14632026/07/23 15:29:00 OK 20241026095416_initial_model.sql (4.79ms)14642026/07/23 15:29:00 OK 20251210153512_drop_unused_gin_index.sql (452.46µs)14652026/07/23 15:29:00 OK 20251218171726_add_pins.sql (1.74ms)14662026/07/23 15:29:00 OK 20260628120000_add_object_size_and_stats.sql (2.16ms)14672026/07/23 15:29:00 goose: successfully migrated database to version: 2026062812000014682026/07/23 15:29:00 OK 1_commit_pending_closure.sql (1.01ms)14692026/07/23 15:29:00 OK 2_object_stats_trigger.sql (229.88µs)14702026/07/23 15:29:00 goose: up to current file version: 21471--- PASS: TestReadProxyDisabled (0.28s)1472=== CONT TestReadProxyRootRedirectsToIndexHTML14732026-07-23 15:29:00.672 UTC [45701] ERROR: relation "goose_db_version" does not exist at character 3614742026-07-23 15:29:00.672 UTC [45701] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14752026-07-23 15:29:00.674 UTC [45702] ERROR: relation "goose_db_version" does not exist at character 3614762026-07-23 15:29:00.674 UTC [45702] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14772026/07/23 15:29:00 OK 20241026095416_initial_model.sql (5.21ms)14782026/07/23 15:29:00 OK 20241026095416_initial_model.sql (6.1ms)14792026/07/23 15:29:00 OK 20251210153512_drop_unused_gin_index.sql (513.38µs)14802026/07/23 15:29:00 OK 20251210153512_drop_unused_gin_index.sql (592.17µs)14812026/07/23 15:29:00 OK 20251218171726_add_pins.sql (859.67µs)14822026/07/23 15:29:00 OK 20251218171726_add_pins.sql (1.08ms)14832026/07/23 15:29:00 OK 20260628120000_add_object_size_and_stats.sql (4.16ms)14842026/07/23 15:29:00 goose: successfully migrated database to version: 2026062812000014852026/07/23 15:29:00 OK 20260628120000_add_object_size_and_stats.sql (4.4ms)14862026/07/23 15:29:00 goose: successfully migrated database to version: 2026062812000014872026/07/23 15:29:00 OK 1_commit_pending_closure.sql (1.44ms)14882026/07/23 15:29:00 OK 1_commit_pending_closure.sql (925.5µs)14892026/07/23 15:29:00 OK 2_object_stats_trigger.sql (272.08µs)14902026/07/23 15:29:00 goose: up to current file version: 214912026/07/23 15:29:00 OK 2_object_stats_trigger.sql (436.58µs)14922026/07/23 15:29:00 goose: up to current file version: 214932026/07/23 15:29:00 INFO Received uploads request method=POST path=/api/pending_closures14942026/07/23 15:29:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14952026/07/23 15:29:00 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1496--- PASS: TestCompleteMultipartUnregistered (0.31s)1497=== CONT TestClientErrorHandling/InvalidStorePath1498--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.30s)1499=== CONT TestClientErrorHandling/ServerNotAvailable15002026-07-23 15:29:00.816 UTC [45708] ERROR: relation "goose_db_version" does not exist at character 3615012026-07-23 15:29:00.816 UTC [45708] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15022026-07-23 15:29:00.817 UTC [45709] ERROR: relation "goose_db_version" does not exist at character 3615032026-07-23 15:29:00.817 UTC [45709] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15042026/07/23 15:29:00 OK 20241026095416_initial_model.sql (9.54ms)15052026/07/23 15:29:00 OK 20251210153512_drop_unused_gin_index.sql (444.46µs)15062026/07/23 15:29:00 OK 20241026095416_initial_model.sql (9.6ms)15072026/07/23 15:29:00 OK 20251218171726_add_pins.sql (1.22ms)15082026/07/23 15:29:00 OK 20251210153512_drop_unused_gin_index.sql (903.88µs)15092026/07/23 15:29:00 OK 20251218171726_add_pins.sql (4.75ms)15102026/07/23 15:29:00 OK 20260628120000_add_object_size_and_stats.sql (5.7ms)15112026/07/23 15:29:00 goose: successfully migrated database to version: 2026062812000015122026/07/23 15:29:00 OK 20260628120000_add_object_size_and_stats.sql (1.68ms)15132026/07/23 15:29:00 goose: successfully migrated database to version: 2026062812000015142026/07/23 15:29:00 OK 1_commit_pending_closure.sql (1.37ms)15152026/07/23 15:29:00 OK 2_object_stats_trigger.sql (357.5µs)15162026/07/23 15:29:00 goose: up to current file version: 215172026/07/23 15:29:00 OK 1_commit_pending_closure.sql (1.28ms)15182026/07/23 15:29:00 OK 2_object_stats_trigger.sql (235.25µs)15192026/07/23 15:29:00 goose: up to current file version: 215202026/07/23 15:29:00 INFO Received uploads request method=POST path=/api/pending_closures15212026/07/23 15:29:00 INFO Received uploads request method=POST path=/api/pending_closures15222026/07/23 15:29:00 INFO Received uploads request method=POST path=/api/pending_closures15232026/07/23 15:29:00 INFO Received uploads request method=POST path=/api/pending_closures15242026/07/23 15:29:00 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-config15252026-07-23 15:29:00.874 UTC [45713] ERROR: relation "goose_db_version" does not exist at character 3615262026-07-23 15:29:00.874 UTC [45713] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15272026-07-23 15:29:00.874 UTC [45714] ERROR: relation "goose_db_version" does not exist at character 3615282026-07-23 15:29:00.874 UTC [45714] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15292026/07/23 15:29:00 OK 20241026095416_initial_model.sql (13.34ms)15302026/07/23 15:29:00 OK 20251210153512_drop_unused_gin_index.sql (400µs)15312026/07/23 15:29:00 OK 20251218171726_add_pins.sql (845.96µs)15322026/07/23 15:29:00 OK 20260628120000_add_object_size_and_stats.sql (1.13ms)15332026/07/23 15:29:00 goose: successfully migrated database to version: 2026062812000015342026/07/23 15:29:00 OK 1_commit_pending_closure.sql (909.38µs)15352026/07/23 15:29:00 OK 2_object_stats_trigger.sql (217.17µs)15362026/07/23 15:29:00 goose: up to current file version: 21537--- PASS: TestService_Rustfstest (0.35s)1538=== CONT TestClientErrorHandling/InvalidAuthToken15392026/07/23 15:29:00 OK 20241026095416_initial_model.sql (15.27ms)15402026/07/23 15:29:00 OK 20251210153512_drop_unused_gin_index.sql (516.83µs)15412026/07/23 15:29:00 OK 20251218171726_add_pins.sql (947.33µs)15422026/07/23 15:29:00 OK 20260628120000_add_object_size_and_stats.sql (21.14ms)15432026/07/23 15:29:00 goose: successfully migrated database to version: 2026062812000015442026/07/23 15:29:00 OK 1_commit_pending_closure.sql (993.92µs)15452026/07/23 15:29:00 OK 2_object_stats_trigger.sql (225.92µs)15462026/07/23 15:29:00 goose: up to current file version: 215472026/07/23 15:29:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15482026/07/23 15:29:00 INFO Received uploads request method=POST path=/api/pending_closures15492026/07/23 15:29:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15502026/07/23 15:29:00 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=189.383799ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config15512026/07/23 15:29:00 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YTA4MDc5MzctMmNmYS00YTliLThmNTItMmEyNjU5ZjFkOGJmLjRkY2VmNWQ4LTBkODAtNGUzNi04N2YyLTZjMTBlOTBhOTc2NHgxNzg0ODIwNTQwODUzMDAzMDAw parts=1015522026/07/23 15:29:00 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15532026/07/23 15:29:00 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YTA4MDc5MzctMmNmYS00YTliLThmNTItMmEyNjU5ZjFkOGJmLjRlY2FkOWRiLTg1OGItNGZlYS1iYWZiLTQxYTllNGFhMjVhMHgxNzg0ODIwNTQwODUzMDUwMDAw parts=1015542026/07/23 15:29:00 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15552026/07/23 15:29:00 INFO Completed upload id=115562026/07/23 15:29:00 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000015572026/07/23 15:29:00 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst15582026/07/23 15:29:00 INFO Received uploads request method=POST path=/api/pending_closures15592026/07/23 15:29:00 INFO Completed upload id=115602026/07/23 15:29:00 INFO Received uploads request method=POST path=/api/pending_closures1561--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.40s)1562=== CONT TestCacheConfigHandler/full_config,_no_issuer15632026/07/23 15:29:00 INFO Received uploads request method=POST path=/api/pending_closures1564=== CONT TestCacheConfigHandler/no_signing_keys1565=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1566=== CONT TestCacheConfigHandler/no_cache_url_configured1567--- PASS: TestCacheConfigHandler (0.00s)1568 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1569 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1570 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1571 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1572=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token15732026/07/23 15:29:00 INFO Starting cleanup of old closures method=DELETE path=/api/closures15742026/07/23 15:29:00 INFO Received uploads request method=POST path=/api/pending_closures15752026/07/23 15:29:00 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo15762026/07/23 15:29:00 WARN Found objects in DB but missing from S3, will re-upload count=11577--- PASS: TestService_verifyS3Integrity (0.43s)1578=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected15792026/07/23 15:29:00 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]1580=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1581=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected15822026/07/23 15:29:00 INFO OIDC auth successful provider=test1583=== CONT TestIsValidCachePath/narinfo1584=== CONT TestIsValidCachePath/index.html1585=== CONT TestIsValidCachePath/nix-cache-info1586=== CONT TestIsValidCachePath/realisation1587=== CONT TestIsValidCachePath/log1588=== CONT TestIsValidCachePath/ls1589=== CONT TestIsValidCachePath/nar_uncompressed1590=== CONT TestIsValidCachePath/nar_bz21591=== CONT TestIsValidCachePath/nar_xz1592=== CONT TestIsValidCachePath/nar_zst1593=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1594=== CONT TestIsValidCachePath/empty1595=== CONT TestIsValidCachePath/traversal_parent1596=== CONT TestIsValidCachePath/random_path1597=== CONT TestIsValidCachePath/invalid_char_u1598=== CONT TestIsValidCachePath/invalid_char_e1599=== CONT TestIsValidCachePath/traversal_in_middle1600=== CONT TestIsValidCachePath/wrong_extension1601=== CONT TestIsValidCachePath/short_hash1602=== CONT TestIsValidCachePath/leading_slash1603--- PASS: TestIsValidCachePath (0.00s)1604 --- PASS: TestIsValidCachePath/narinfo (0.00s)1605 --- PASS: TestIsValidCachePath/index.html (0.00s)1606 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1607 --- PASS: TestIsValidCachePath/realisation (0.00s)1608 --- PASS: TestIsValidCachePath/log (0.00s)1609 --- PASS: TestIsValidCachePath/ls (0.00s)1610 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1611 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1612 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1613 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1614 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1615 --- PASS: TestIsValidCachePath/empty (0.00s)1616 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1617 --- PASS: TestIsValidCachePath/random_path (0.00s)1618 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1619 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1620 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1621 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1622 --- PASS: TestIsValidCachePath/short_hash (0.00s)1623 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1624=== CONT TestParseSingleRange/none1625=== CONT TestParseSingleRange/open-ended1626=== CONT TestParseSingleRange/start_far_past_EOF1627=== CONT TestParseSingleRange/start_past_EOF1628=== CONT TestParseSingleRange/single_byte1629=== CONT TestParseSingleRange/suffix_exceeds_size1630=== CONT TestParseSingleRange/suffix1631=== CONT TestParseSingleRange/end_clamped_to_size1632=== CONT TestParseSingleRange/malformed_both_empty1633=== CONT TestParseSingleRange/closed1634=== CONT TestParseSingleRange/malformed_end_before_start1635=== CONT TestParseSingleRange/multi-range_ignored1636=== CONT TestParseSingleRange/malformed_no_dash1637=== CONT TestParseSingleRange/unknown_unit1638--- PASS: TestParseSingleRange (0.00s)1639 --- PASS: TestParseSingleRange/none (0.00s)1640 --- PASS: TestParseSingleRange/open-ended (0.00s)1641 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1642 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1643 --- PASS: TestParseSingleRange/single_byte (0.00s)1644 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1645 --- PASS: TestParseSingleRange/suffix (0.00s)1646 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1647 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1648 --- PASS: TestParseSingleRange/closed (0.00s)1649 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1650 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1651 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1652 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1653=== CONT TestServerTLSConfig/no_client_CA1654=== CONT TestServerTLSConfig/not_a_PEM_file16552026/07/23 15:29:00 WARN Authentication failed token_preview=eyJhbGciOi...Gp_ZIT8x_A 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]1656=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16572026/07/23 15:29:00 INFO Received uploads request method=POST path=/1658=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16592026/07/23 15:29:00 INFO Received complete multipart upload request method=POST path=/1660=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16612026/07/23 15:29:00 INFO Received request for more parts method=POST path=/1662=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16632026/07/23 15:29:00 INFO Received uploads request method=POST path=/1664--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1665 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1666 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1667 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1668 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1669=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16702026/07/23 15:29:00 INFO Received uploads request method=POST path=/1671=== CONT TestServerTLSConfig/missing_CA_file16722026/07/23 15:29:00 INFO Aborted multipart uploads count=01673--- PASS: TestServerTLSConfig (0.00s)1674 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1675 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1676 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1677=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16782026/07/23 15:29:00 INFO Received request for more parts method=POST path=/1679--- PASS: TestService_AuthMiddleware_OIDC (0.36s)1680 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1681 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1682 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1683 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)16842026/07/23 15:29:00 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=016852026/07/23 15:29:00 INFO Vacuumed table table=pending_closures16862026/07/23 15:29:00 INFO Vacuumed table table=pending_objects16872026/07/23 15:29:00 INFO Vacuumed table table=multipart_uploads16882026/07/23 15:29:00 INFO Vacuumed table table=closures16892026/07/23 15:29:00 INFO Vacuumed table table=objects1690=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16912026/07/23 15:29:00 INFO Received complete multipart upload request method=POST path=/1692=== CONT TestIsValidUploadKey/narinfo1693=== CONT TestIsValidUploadKey/realisation_plus_in_output1694=== CONT TestIsValidUploadKey/unknown_type1695=== CONT TestIsValidUploadKey/empty_key1696=== CONT TestIsValidUploadKey/absolute1697=== CONT TestIsValidUploadKey/traversal_nar1698=== CONT TestIsValidUploadKey/traversal1699=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1700=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1701=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1702=== CONT TestIsValidUploadKey/index.html1703=== CONT TestIsValidUploadKey/nix-cache-info1704=== CONT TestIsValidUploadKey/build_log_home-manager_file1705=== CONT TestIsValidUploadKey/realisation1706=== CONT TestIsValidUploadKey/build_log_equals1707=== CONT TestIsValidUploadKey/build_log_question_mark1708=== CONT TestIsValidUploadKey/build_log_plus_in_name1709=== CONT TestIsValidUploadKey/nar_plain1710=== CONT TestIsValidUploadKey/build_log1711=== CONT TestIsValidUploadKey/listing1712=== CONT TestIsValidUploadKey/nar_xz1713=== CONT TestIsValidUploadKey/nar_zst1714--- PASS: TestIsValidUploadKey (0.00s)1715 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1716 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1717 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1718 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1719 --- PASS: TestIsValidUploadKey/absolute (0.00s)1720 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1721 --- PASS: TestIsValidUploadKey/traversal (0.00s)1722 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1723 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1724 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1725 --- PASS: TestIsValidUploadKey/index.html (0.00s)1726 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1727 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1728 --- PASS: TestIsValidUploadKey/realisation (0.00s)1729 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1730 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1731 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1732 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1733 --- PASS: TestIsValidUploadKey/build_log (0.00s)1734 --- PASS: TestIsValidUploadKey/listing (0.00s)1735 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1736 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1737=== CONT TestProxyWriteTimeout/narinfo1738=== CONT TestProxyWriteTimeout/10_GiB_nar1739=== CONT TestProxyWriteTimeout/unknown_size1740=== CONT TestProxyWriteTimeout/1_GiB_nar1741--- PASS: TestProxyWriteTimeout (0.00s)1742 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1743 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1744 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1745 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)17462026-07-23 15:29:01.010 UTC [45718] ERROR: relation "goose_db_version" does not exist at character 3617472026-07-23 15:29:01.010 UTC [45718] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17482026/07/23 15:29:01 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001749--- PASS: TestService_createPendingClosureHandler (0.47s)17502026/07/23 15:29:01 OK 20241026095416_initial_model.sql (4.21ms)17512026/07/23 15:29:01 OK 20251210153512_drop_unused_gin_index.sql (486.54µs)17522026/07/23 15:29:01 OK 20251218171726_add_pins.sql (786.92µs)17532026/07/23 15:29:01 OK 20260628120000_add_object_size_and_stats.sql (1.05ms)17542026/07/23 15:29:01 goose: successfully migrated database to version: 2026062812000017552026/07/23 15:29:01 OK 1_commit_pending_closure.sql (848.38µs)17562026/07/23 15:29:01 OK 2_object_stats_trigger.sql (182.25µs)17572026/07/23 15:29:01 goose: up to current file version: 21758--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.40s)17592026-07-23 15:29:01.046 UTC [45719] ERROR: relation "goose_db_version" does not exist at character 3617602026-07-23 15:29:01.046 UTC [45719] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17612026/07/23 15:29:01 OK 20241026095416_initial_model.sql (4.46ms)17622026/07/23 15:29:01 OK 20251210153512_drop_unused_gin_index.sql (333µs)17632026/07/23 15:29:01 OK 20251218171726_add_pins.sql (815.21µs)17642026/07/23 15:29:01 OK 20260628120000_add_object_size_and_stats.sql (1.52ms)17652026/07/23 15:29:01 goose: successfully migrated database to version: 2026062812000017662026/07/23 15:29:01 OK 1_commit_pending_closure.sql (886.96µs)17672026/07/23 15:29:01 OK 2_object_stats_trigger.sql (187.71µs)17682026/07/23 15:29:01 goose: up to current file version: 217692026-07-23 15:29:01.097 UTC [45722] ERROR: relation "goose_db_version" does not exist at character 3617702026-07-23 15:29:01.097 UTC [45722] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17712026/07/23 15:29:01 OK 20241026095416_initial_model.sql (4.14ms)17722026/07/23 15:29:01 OK 20251210153512_drop_unused_gin_index.sql (367.88µs)17732026/07/23 15:29:01 OK 20251218171726_add_pins.sql (758.63µs)17742026/07/23 15:29:01 OK 20260628120000_add_object_size_and_stats.sql (1.24ms)17752026/07/23 15:29:01 goose: successfully migrated database to version: 2026062812000017762026/07/23 15:29:01 OK 1_commit_pending_closure.sql (862.29µs)17772026/07/23 15:29:01 OK 2_object_stats_trigger.sql (194.29µs)17782026/07/23 15:29:01 goose: up to current file version: 217792026/07/23 15:29:01 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=423.182785ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17802026/07/23 15:29:01 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1781--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)1782 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1783 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1784 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.28s)17852026/07/23 15:29:01 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"17862026/07/23 15:29:01 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01787=== NAME TestPinProtectsFromGC1788 client_integration_test.go:709: Pin successfully protected closure from garbage collection1789--- PASS: TestPinProtectsFromGC (2.78s)17902026/07/23 15:29:01 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01791=== NAME TestClientIntegration1792 client_integration_test.go:303: Objects in database after GC:1793 client_integration_test.go:303: Successfully deleted all objects with GC --force1794--- PASS: TestClientIntegration (2.52s)17952026/07/23 15:29:01 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=846.860073ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17962026/07/23 15:29:02 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.473629284s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17972026/07/23 15:29:03 WARN Rate limiter enabled after throttle name=s3-test rate=517982026/07/23 15:29:03 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1799=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1800 throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=101801 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001802--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.96s)18032026/07/23 15:29:03 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"18042026/07/23 15:29:03 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_closures18052026/07/23 15:29:04 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=188.314315ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures18062026/07/23 15:29:04 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=368.68905ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures18072026/07/23 15:29:04 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=827.79724ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures18082026/07/23 15:29:05 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.48829313s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1809--- PASS: TestClientErrorHandling (0.00s)1810 --- PASS: TestClientErrorHandling/InvalidStorePath (0.38s)1811 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.34s)1812 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.25s)1813PASS1814{"timestamp":"2026-07-23T15:29:07.474797Z","level":"ERROR","fields":{"message":"Unknown connection IO error:Cancelled","peer_addr":"127.0.0.1:53712"},"target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":973,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}18152026-07-23 15:29:07.539 UTC [45409] LOG: received smart shutdown request18162026-07-23 15:29:07.540 UTC [45409] LOG: background worker "logical replication launcher" (PID 45419) exited with exit code 118172026-07-23 15:29:07.548 UTC [45414] LOG: shutting down18182026-07-23 15:29:07.548 UTC [45414] LOG: checkpoint starting: shutdown immediate18192026-07-23 15:29:08.562 UTC [45414] LOG: checkpoint complete: wrote 12763 buffers (77.9%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 13 recycled; write=0.732 s, sync=0.259 s, total=1.014 s; sync files=15167, longest=0.001 s, average=0.001 s; distance=212547 kB, estimate=212547 kB; lsn=0/E71BB50, redo lsn=0/E71BB5018202026-07-23 15:29:08.567 UTC [45409] LOG: database system is shut down1821Running OIDC tests...1822=== RUN TestGlobMatch1823=== PAUSE TestGlobMatch1824=== RUN TestAudienceForIssuer1825=== PAUSE TestAudienceForIssuer1826=== RUN TestValidateToken_ValidToken1827=== PAUSE TestValidateToken_ValidToken1828=== RUN TestValidateToken_WrongAudience1829=== PAUSE TestValidateToken_WrongAudience1830=== RUN TestValidateToken_Expired1831=== PAUSE TestValidateToken_Expired1832=== RUN TestValidateToken_BoundClaimsMismatch1833=== PAUSE TestValidateToken_BoundClaimsMismatch1834=== RUN TestValidateToken_BoundSubjectMismatch1835=== PAUSE TestValidateToken_BoundSubjectMismatch1836=== RUN TestValidateToken_MultipleProviders1837=== PAUSE TestValidateToken_MultipleProviders1838=== RUN TestValidateToken_NoMatchingProvider1839=== PAUSE TestValidateToken_NoMatchingProvider1840=== CONT TestGlobMatch1841=== CONT TestValidateToken_MultipleProviders1842=== RUN TestGlobMatch/foo_foo1843=== CONT TestValidateToken_BoundClaimsMismatch1844=== CONT TestAudienceForIssuer1845--- PASS: TestAudienceForIssuer (0.00s)1846=== CONT TestValidateToken_BoundSubjectMismatch1847=== CONT TestValidateToken_NoMatchingProvider1848=== PAUSE TestGlobMatch/foo_foo1849=== RUN TestGlobMatch/foo_bar1850=== PAUSE TestGlobMatch/foo_bar1851=== CONT TestValidateToken_Expired1852=== CONT TestValidateToken_WrongAudience1853=== CONT TestValidateToken_ValidToken1854=== RUN TestGlobMatch/*_1855=== PAUSE TestGlobMatch/*_1856=== RUN TestGlobMatch/*_anything1857=== PAUSE TestGlobMatch/*_anything1858=== RUN TestGlobMatch/foo*_foo1859=== PAUSE TestGlobMatch/foo*_foo1860=== RUN TestGlobMatch/foo*_foobar1861=== PAUSE TestGlobMatch/foo*_foobar1862=== RUN TestGlobMatch/foo*_bar1863=== PAUSE TestGlobMatch/foo*_bar1864=== RUN TestGlobMatch/*bar_bar1865=== PAUSE TestGlobMatch/*bar_bar1866=== RUN TestGlobMatch/*bar_foobar1867=== PAUSE TestGlobMatch/*bar_foobar1868=== RUN TestGlobMatch/*bar_foo1869=== PAUSE TestGlobMatch/*bar_foo1870=== RUN TestGlobMatch/foo*bar_foobar1871=== PAUSE TestGlobMatch/foo*bar_foobar1872=== RUN TestGlobMatch/foo*bar_foo123bar1873=== PAUSE TestGlobMatch/foo*bar_foo123bar1874=== RUN TestGlobMatch/foo*bar_foobarbaz1875=== PAUSE TestGlobMatch/foo*bar_foobarbaz1876=== RUN TestGlobMatch/*/*_foo/bar1877=== PAUSE TestGlobMatch/*/*_foo/bar1878=== RUN TestGlobMatch/*/*_foo1879=== PAUSE TestGlobMatch/*/*_foo1880=== RUN TestGlobMatch/refs/heads/*_refs/heads/main1881=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main1882=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.01883=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.01884=== RUN TestGlobMatch/refs/*/main_refs/heads/main1885=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main1886=== RUN TestGlobMatch/fo?_foo1887=== PAUSE TestGlobMatch/fo?_foo1888=== RUN TestGlobMatch/fo?_fo1889=== PAUSE TestGlobMatch/fo?_fo1890=== RUN TestGlobMatch/fo?_fooo1891=== PAUSE TestGlobMatch/fo?_fooo1892=== RUN TestGlobMatch/?oo_foo1893=== PAUSE TestGlobMatch/?oo_foo1894=== RUN TestGlobMatch/?oo_boo1895=== PAUSE TestGlobMatch/?oo_boo1896=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1897=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1898=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1899=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1900=== CONT TestGlobMatch/foo_foo1901=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1902=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1903=== CONT TestGlobMatch/?oo_boo1904=== CONT TestGlobMatch/?oo_foo1905=== CONT TestGlobMatch/fo?_fooo1906=== CONT TestGlobMatch/fo?_fo1907=== CONT TestGlobMatch/fo?_foo1908=== CONT TestGlobMatch/*bar_foobar1909=== CONT TestGlobMatch/*bar_bar1910=== CONT TestGlobMatch/foo*_bar1911=== CONT TestGlobMatch/foo*_foobar1912=== CONT TestGlobMatch/*bar_foo1913=== CONT TestGlobMatch/*_1914=== CONT TestGlobMatch/foo_bar1915=== CONT TestGlobMatch/foo*_foo1916=== CONT TestGlobMatch/refs/*/main_refs/heads/main1917=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.01918=== CONT TestGlobMatch/refs/heads/*_refs/heads/main1919=== CONT TestGlobMatch/foo*bar_foo123bar1920=== CONT TestGlobMatch/*/*_foo/bar1921=== CONT TestGlobMatch/foo*bar_foobarbaz1922=== CONT TestGlobMatch/foo*bar_foobar1923=== CONT TestGlobMatch/*/*_foo1924=== CONT TestGlobMatch/*_anything1925--- PASS: TestGlobMatch (0.00s)1926 --- PASS: TestGlobMatch/foo_foo (0.00s)1927 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)1928 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)1929 --- PASS: TestGlobMatch/?oo_boo (0.00s)1930 --- PASS: TestGlobMatch/?oo_foo (0.00s)1931 --- PASS: TestGlobMatch/fo?_fooo (0.00s)1932 --- PASS: TestGlobMatch/fo?_fo (0.00s)1933 --- PASS: TestGlobMatch/fo?_foo (0.00s)1934 --- PASS: TestGlobMatch/*bar_foobar (0.00s)1935 --- PASS: TestGlobMatch/*bar_bar (0.00s)1936 --- PASS: TestGlobMatch/foo*_bar (0.00s)1937 --- PASS: TestGlobMatch/foo*_foobar (0.00s)1938 --- PASS: TestGlobMatch/*bar_foo (0.00s)1939 --- PASS: TestGlobMatch/*_ (0.00s)1940 --- PASS: TestGlobMatch/foo_bar (0.00s)1941 --- PASS: TestGlobMatch/foo*_foo (0.00s)1942 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)1943 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)1944 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)1945 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)1946 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)1947 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)1948 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)1949 --- PASS: TestGlobMatch/*/*_foo (0.00s)1950 --- PASS: TestGlobMatch/*_anything (0.00s)19512026/07/23 15:29:09 INFO OIDC provider initialized name=test19522026/07/23 15:29:09 INFO OIDC provider initialized name=provider119532026/07/23 15:29:09 INFO OIDC provider initialized name=test19542026/07/23 15:29:09 INFO OIDC provider initialized name=test19552026/07/23 15:29:09 INFO OIDC provider initialized name=provider119562026/07/23 15:29:09 INFO OIDC provider initialized name=test19572026/07/23 15:29:09 INFO OIDC provider initialized name=provider219582026/07/23 15:29:09 INFO OIDC provider initialized name=test1959--- PASS: TestValidateToken_WrongAudience (0.01s)1960--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)1961--- PASS: TestValidateToken_NoMatchingProvider (0.01s)1962--- PASS: TestValidateToken_MultipleProviders (0.01s)1963--- PASS: TestValidateToken_Expired (0.01s)1964--- PASS: TestValidateToken_ValidToken (0.01s)1965--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)1966PASS1967Running hook tests...1968=== RUN TestSendPathsEmpty1969=== PAUSE TestSendPathsEmpty1970=== RUN TestQueueEnqueueAndFetch1971=== PAUSE TestQueueEnqueueAndFetch1972=== RUN TestQueueDeduplication1973=== PAUSE TestQueueDeduplication1974=== RUN TestQueueRemove1975=== PAUSE TestQueueRemove1976=== RUN TestQueueFetchBatchLimit1977=== PAUSE TestQueueFetchBatchLimit1978=== RUN TestQueueFetchRemoveLifecycle1979=== PAUSE TestQueueFetchRemoveLifecycle1980=== RUN TestQueueConcurrentWriters1981=== PAUSE TestQueueConcurrentWriters1982=== RUN TestServerClientIntegration1983=== PAUSE TestServerClientIntegration1984=== RUN TestServerQueueError1985=== PAUSE TestServerQueueError1986=== RUN TestGetListenerSocketActivation1987 server_test.go:210: === RUN TestGetListenerSocketActivation1988 --- PASS: TestGetListenerSocketActivation (0.00s)1989 PASS1990 1991--- PASS: TestGetListenerSocketActivation (0.01s)1992=== RUN TestWorkerUploadsAndRemoves1993=== PAUSE TestWorkerUploadsAndRemoves1994=== RUN TestWorkerSkipsGCdPaths1995=== PAUSE TestWorkerSkipsGCdPaths1996=== RUN TestWorkerPrunesClosureDeps1997=== PAUSE TestWorkerPrunesClosureDeps1998=== CONT TestSendPathsEmpty1999--- PASS: TestSendPathsEmpty (0.00s)2000=== CONT TestQueueConcurrentWriters2001=== CONT TestQueueRemove2002=== CONT TestQueueFetchRemoveLifecycle2003=== CONT TestQueueDeduplication2004=== CONT TestQueueEnqueueAndFetch2005=== CONT TestQueueFetchBatchLimit2006=== CONT TestWorkerUploadsAndRemoves2007=== CONT TestWorkerPrunesClosureDeps2008=== CONT TestWorkerSkipsGCdPaths2009=== CONT TestServerQueueError20102026/07/23 15:29:09 ERROR Failed to queue paths error="permission denied" count=12011--- PASS: TestServerQueueError (0.00s)2012=== CONT TestServerClientIntegration2013--- PASS: TestServerClientIntegration (0.00s)2014--- PASS: TestQueueDeduplication (0.01s)20152026/07/23 15:29:09 INFO Upload queue status pending=220162026/07/23 15:29:09 INFO Uploading batch count=22017--- PASS: TestQueueFetchBatchLimit (0.01s)20182026/07/23 15:29:09 INFO Upload queue status pending=220192026/07/23 15:29:09 INFO Uploading batch count=12020--- PASS: TestQueueRemove (0.01s)20212026/07/23 15:29:09 INFO Upload queue status pending=220222026/07/23 15:29:09 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-45316-59033543/TestWorkerSkipsGCdPaths3582377064/002/nonexistent20232026/07/23 15:29:09 INFO Uploading batch count=12024--- PASS: TestQueueEnqueueAndFetch (0.01s)2025--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2026--- PASS: TestWorkerSkipsGCdPaths (0.06s)2027--- PASS: TestWorkerUploadsAndRemoves (0.06s)2028--- PASS: TestWorkerPrunesClosureDeps (0.06s)2029--- PASS: TestQueueConcurrentWriters (0.16s)2030PASS