niks3-go-unit-tests
aarch64-darwin.go-unit-tests
· build #114
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestCaseHackSuffix5=== PAUSE TestCaseHackSuffix6=== RUN TestFilterOversizedClosures7=== PAUSE TestFilterOversizedClosures8=== RUN TestPartSizeForNAR9=== PAUSE TestPartSizeForNAR10=== RUN TestUploadMultipart_SupersededByPeer11=== PAUSE TestUploadMultipart_SupersededByPeer12=== RUN TestDumpPathMatchesNix13=== PAUSE TestDumpPathMatchesNix14=== RUN TestDumpPathSingleFile15=== PAUSE TestDumpPathSingleFile16=== RUN TestDumpPathWriterError17=== PAUSE TestDumpPathWriterError18=== RUN TestEncodeNixBase3219=== PAUSE TestEncodeNixBase3220=== RUN TestEncodeNixBase32WithRealHash21=== PAUSE TestEncodeNixBase32WithRealHash22=== RUN TestConvertHashToNix3223=== PAUSE TestConvertHashToNix3224=== RUN TestGetStorePathHash25=== PAUSE TestGetStorePathHash26=== RUN TestPathInfoHashCompatibility27=== PAUSE TestPathInfoHashCompatibility28=== RUN TestParsePathInfoJSON29=== PAUSE TestParsePathInfoJSON30=== RUN TestParsePathInfoJSONMultiplePaths31=== PAUSE TestParsePathInfoJSONMultiplePaths32=== RUN TestPathInfoCACompatibility33=== PAUSE TestPathInfoCACompatibility34=== RUN TestRateLimiterFeedback35=== PAUSE TestRateLimiterFeedback36=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess37=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess38=== RUN TestResolveStorePath39=== PAUSE TestResolveStorePath40=== RUN TestDoWithRetry_BodyReplayedViaGetBody41=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody42=== RUN TestShellSplit43=== PAUSE TestShellSplit44=== RUN TestShellSplitErrors45=== PAUSE TestShellSplitErrors46=== RUN TestSetClientTLS47=== PAUSE TestSetClientTLS48=== RUN TestSetClientTLSDoesNotMutateDefaultTransport49=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport50=== RUN TestSetClientTLSErrors51=== PAUSE TestSetClientTLSErrors52=== RUN TestStaticToken53=== PAUSE TestStaticToken54=== RUN TestFileTokenReadsAndCaches55=== PAUSE TestFileTokenReadsAndCaches56=== RUN TestFileTokenMissing57=== PAUSE TestFileTokenMissing58=== RUN TestFileTokenEmpty59=== PAUSE TestFileTokenEmpty60=== RUN TestScriptTokenNoExpiryRerunsEveryCall61=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall62=== RUN TestScriptTokenCachesUntilRefresh63=== PAUSE TestScriptTokenCachesUntilRefresh64=== RUN TestScriptTokenEmptyToken65=== PAUSE TestScriptTokenEmptyToken66=== RUN TestScriptTokenBadJSON67=== PAUSE TestScriptTokenBadJSON68=== RUN TestScriptTokenScriptFails69=== PAUSE TestScriptTokenScriptFails70=== RUN TestScriptTokenEmptyCommand71=== PAUSE TestScriptTokenEmptyCommand72=== CONT TestDoServerRequestAttachesToken73=== CONT TestEncodeNixBase32WithRealHash74=== CONT TestResolveStorePath75--- PASS: TestEncodeNixBase32WithRealHash (0.00s)76=== CONT TestParsePathInfoJSON77=== CONT TestParsePathInfoJSONMultiplePaths78=== RUN TestParsePathInfoJSON/Nix_format79=== PAUSE TestParsePathInfoJSON/Nix_format80=== RUN TestParsePathInfoJSON/Lix_format81=== PAUSE TestParsePathInfoJSON/Lix_format82=== RUN TestParsePathInfoJSON/empty_input83=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths84=== PAUSE TestParsePathInfoJSON/empty_input85=== RUN TestParsePathInfoJSON/whitespace_only86=== PAUSE TestParsePathInfoJSON/whitespace_only87=== RUN TestParsePathInfoJSON/invalid_JSON88=== PAUSE TestParsePathInfoJSON/invalid_JSON89=== CONT TestParsePathInfoJSON/Nix_format90=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths91=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths92=== CONT TestRateLimiterFeedback93=== CONT TestPathInfoHashCompatibility94=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)95=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)96=== RUN TestRateLimiterFeedback/429_enables_limiter97=== PAUSE TestRateLimiterFeedback/429_enables_limiter98=== RUN TestRateLimiterFeedback/503_enables_limiter99=== PAUSE TestRateLimiterFeedback/503_enables_limiter100=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter101=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter102=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter103=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter104=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon105=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon106=== CONT TestEncodeNixBase32107=== RUN TestEncodeNixBase32/test_string_hash108=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths109=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI110=== CONT TestDumpPathWriterError111=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI112=== CONT TestPathInfoCACompatibility113=== RUN TestPathInfoCACompatibility/null_ca_field114=== PAUSE TestPathInfoCACompatibility/null_ca_field115=== CONT TestGetStorePathHash116=== RUN TestGetStorePathHash/valid_store_path117=== CONT TestConvertHashToNix32118=== RUN TestConvertHashToNix32/SRI_format_to_Nix32119=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32120=== RUN TestConvertHashToNix32/already_Nix32_format121=== PAUSE TestConvertHashToNix32/already_Nix32_format122=== RUN TestConvertHashToNix32/invalid_format123=== PAUSE TestConvertHashToNix32/invalid_format124=== CONT TestDumpPathMatchesNix125=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess126=== CONT TestDumpPathSingleFile127=== PAUSE TestEncodeNixBase32/test_string_hash128=== RUN TestEncodeNixBase32/empty_input129=== PAUSE TestEncodeNixBase32/empty_input130=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512131=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512132=== CONT TestPartSizeForNAR133=== RUN TestPartSizeForNAR/zero_stays_at_minimum134=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum135=== RUN TestPartSizeForNAR/small_stays_at_minimum136=== PAUSE TestPartSizeForNAR/small_stays_at_minimum137=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum138=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum139=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts140=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts141=== RUN TestPartSizeForNAR/1_TiB142=== CONT TestUploadMultipart_SupersededByPeer143--- PASS: TestResolveStorePath (0.00s)144=== PAUSE TestGetStorePathHash/valid_store_path145=== RUN TestGetStorePathHash/basename_without_hyphen_should_error1462026/07/21 08:17:01 WARN Rate limiter enabled after throttle name=server-test rate=5147=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error148=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error149=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error150=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error151=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error152=== PAUSE TestPartSizeForNAR/1_TiB153=== RUN TestPartSizeForNAR/5_TiB_S3_max_object154=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object155=== RUN TestPartSizeForNAR/capped_at_5_GiB156=== PAUSE TestPartSizeForNAR/capped_at_5_GiB157=== CONT TestScriptTokenEmptyCommand158--- PASS: TestScriptTokenEmptyCommand (0.00s)159=== CONT TestScriptTokenBadJSON160=== RUN TestUploadMultipart_SupersededByPeer/exists161=== CONT TestScriptTokenScriptFails162=== PAUSE TestUploadMultipart_SupersededByPeer/exists163=== RUN TestUploadMultipart_SupersededByPeer/missing164=== PAUSE TestUploadMultipart_SupersededByPeer/missing165=== RUN TestPathInfoCACompatibility/old_string_format_-_text166=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text167=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive168=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive169=== RUN TestPathInfoCACompatibility/new_structured_format_-_text170=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text171=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method172=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method173=== CONT TestScriptTokenEmptyToken174=== CONT TestFileTokenMissing175--- PASS: TestFileTokenMissing (0.00s)176=== CONT TestScriptTokenCachesUntilRefresh177=== CONT TestScriptTokenNoExpiryRerunsEveryCall178--- PASS: TestDoServerRequestAttachesToken (0.01s)179=== CONT TestFileTokenEmpty180--- PASS: TestScriptTokenScriptFails (0.01s)181=== CONT TestSetClientTLSDoesNotMutateDefaultTransport182--- PASS: TestFileTokenEmpty (0.00s)183=== CONT TestFileTokenReadsAndCaches184--- PASS: TestFileTokenReadsAndCaches (0.00s)185=== CONT TestStaticToken186--- PASS: TestStaticToken (0.00s)187=== CONT TestSetClientTLSErrors188=== RUN TestSetClientTLSErrors/missing_cert_file189=== PAUSE TestSetClientTLSErrors/missing_cert_file190=== RUN TestSetClientTLSErrors/missing_key_file191=== PAUSE TestSetClientTLSErrors/missing_key_file192=== RUN TestSetClientTLSErrors/missing_ca_file193=== PAUSE TestSetClientTLSErrors/missing_ca_file194=== RUN TestSetClientTLSErrors/invalid_ca_file195=== PAUSE TestSetClientTLSErrors/invalid_ca_file196=== CONT TestFilterOversizedClosures197=== RUN TestFilterOversizedClosures/no_limit_keeps_everything198=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything199=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped200=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped201=== RUN TestFilterOversizedClosures/all_closures_skipped202=== PAUSE TestFilterOversizedClosures/all_closures_skipped203=== CONT TestParsePathInfoJSON/empty_input204=== CONT TestParsePathInfoJSON/whitespace_only205=== CONT TestCaseHackSuffix206--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)207=== CONT TestParsePathInfoJSON/Lix_format208=== CONT TestShellSplitErrors209--- PASS: TestShellSplitErrors (0.00s)210=== CONT TestSetClientTLS211--- PASS: TestScriptTokenBadJSON (0.01s)212=== CONT TestShellSplit213--- PASS: TestShellSplit (0.00s)214=== CONT TestDoWithRetry_BodyReplayedViaGetBody215=== RUN TestSetClientTLS/rejects_connection_without_client_cert216=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert217=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA218=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA219=== RUN TestSetClientTLS/preserves_debug_logging_transport220=== PAUSE TestSetClientTLS/preserves_debug_logging_transport221=== CONT TestRateLimiterFeedback/429_enables_limiter2222026/07/21 08:17:01 WARN Rate limiter enabled after throttle name=server-test rate=52232026/07/21 08:17:01 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:601032242026/07/21 08:17:01 WARN Rate limiter enabled after throttle name=server-test rate=52252026/07/21 08:17:01 WARN Rate limiter backed off name=server-test rate=52262026/07/21 08:17:01 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:601052272026/07/21 08:17:01 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:60103228--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)229=== CONT TestParsePathInfoJSON/invalid_JSON230--- PASS: TestParsePathInfoJSON (0.00s)231 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)232 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)233 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)234 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)235 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)236=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2372026/07/21 08:17:01 WARN Rate limiter backed off name=server-test rate=5238=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter239=== CONT TestRateLimiterFeedback/503_enables_limiter240=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths241=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths242--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)243 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)244 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)245=== CONT TestConvertHashToNix32/SRI_format_to_Nix32246=== CONT TestConvertHashToNix32/invalid_format247=== CONT TestConvertHashToNix32/already_Nix32_format248--- PASS: TestConvertHashToNix32 (0.00s)249 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)250 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)251 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)252=== CONT TestEncodeNixBase32/test_string_hash253=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)254=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512255=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI256=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon257--- PASS: TestPathInfoHashCompatibility (0.00s)258 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)259 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)260 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)261 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)2622026/07/21 08:17:01 WARN Rate limiter enabled after throttle name=server-test rate=5263=== CONT TestEncodeNixBase32/empty_input264--- PASS: TestEncodeNixBase32 (0.00s)265 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)266 --- PASS: TestEncodeNixBase32/empty_input (0.00s)2672026/07/21 08:17:01 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:60111268=== CONT TestGetStorePathHash/valid_store_path269=== CONT TestPartSizeForNAR/zero_stays_at_minimum270=== CONT TestPartSizeForNAR/capped_at_5_GiB271=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error272=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error273=== CONT TestGetStorePathHash/basename_without_hyphen_should_error274--- PASS: TestGetStorePathHash (0.00s)275 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)276 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)277 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)278 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)279=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts280=== CONT TestPartSizeForNAR/5_TiB_S3_max_object281=== CONT TestPartSizeForNAR/1_TiB282=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum2832026/07/21 08:17:01 WARN Rate limiter backed off name=server-test rate=5284=== CONT TestUploadMultipart_SupersededByPeer/exists285--- PASS: TestRateLimiterFeedback (0.00s)286 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)287 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)288 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)289 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)290=== CONT TestPathInfoCACompatibility/null_ca_field291=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method292=== CONT TestUploadMultipart_SupersededByPeer/missing293--- PASS: TestScriptTokenEmptyToken (0.02s)294=== CONT TestPartSizeForNAR/small_stays_at_minimum295--- PASS: TestPartSizeForNAR (0.00s)296 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)297 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)298 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)299 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)300 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)301 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)302 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)303=== CONT TestPathInfoCACompatibility/new_structured_format_-_text304=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive305=== CONT TestPathInfoCACompatibility/old_string_format_-_text306--- PASS: TestPathInfoCACompatibility (0.00s)307 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)308 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)309 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)310 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)311 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)312=== CONT TestSetClientTLSErrors/missing_cert_file313=== CONT TestSetClientTLSErrors/missing_ca_file314=== CONT TestSetClientTLSErrors/invalid_ca_file315=== CONT TestSetClientTLSErrors/missing_key_file316=== CONT TestFilterOversizedClosures/no_limit_keeps_everything317=== CONT TestFilterOversizedClosures/all_closures_skipped3182026/07/21 08:17:01 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=50319=== CONT TestSetClientTLS/rejects_connection_without_client_cert320=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3212026/07/21 08:17:01 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=2000322--- PASS: TestFilterOversizedClosures (0.00s)323 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)324 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)325 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)326=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA327--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)328 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)329 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)330=== CONT TestSetClientTLS/preserves_debug_logging_transport331--- PASS: TestSetClientTLSErrors (0.00s)332 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)333 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)334 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)335 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)336--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.03s)337--- PASS: TestDumpPathWriterError (0.04s)338--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)3392026/07/21 08:17:01 http: TLS handshake error from 127.0.0.1:60117: remote error: tls: bad certificate340--- PASS: TestSetClientTLS (0.00s)341 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)342 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)343 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.03s)344--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)345--- PASS: TestDumpPathSingleFile (3.94s)346--- PASS: TestCaseHackSuffix (3.93s)347--- PASS: TestDumpPathMatchesNix (3.95s)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-89852-3968335264/postgres2578882517/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-89852-3968335264/postgres2578882517/data -l logfile start3763772026-07-21 08:17:07.316 UTC [89903] LOG: starting PostgreSQL 18.4 on aarch64-apple-darwin25.3.0, compiled by clang version 21.1.8, 64-bit3782026-07-21 08:17:07.316 UTC [89903] LOG: listening on Unix socket "/nix/var/nix/builds/nix-89852-3968335264/postgres2578882517/.s.PGSQL.5432"3792026-07-21 08:17:07.318 UTC [89910] LOG: database system was shut down at 2026-07-21 08:17:07 UTC3802026-07-21 08:17:07.319 UTC [89903] LOG: database system is ready to accept connections381/nix/var/nix/builds/nix-89852-3968335264/postgres2578882517:5432 - accepting connections382<jemalloc>: option background_thread currently supports pthread only383{"timestamp":"2026-07-21T08:17:09.294916Z","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(2)"}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-21 08:17:09.599 UTC [90010] ERROR: relation "goose_db_version" does not exist at character 364122026-07-21 08:17:09.599 UTC [90010] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4132026/07/21 08:17:09 OK 20241026095416_initial_model.sql (3.37ms)4142026/07/21 08:17:09 OK 20251210153512_drop_unused_gin_index.sql (601.67µs)4152026/07/21 08:17:09 OK 20251218171726_add_pins.sql (797.13µs)4162026/07/21 08:17:09 OK 20260628120000_add_object_size_and_stats.sql (832.96µs)4172026/07/21 08:17:09 goose: successfully migrated database to version: 202606281200004182026/07/21 08:17:09 OK 1_commit_pending_closure.sql (896.54µs)4192026/07/21 08:17:09 OK 2_object_stats_trigger.sql (186.13µs)4202026/07/21 08:17:09 goose: up to current file version: 2421--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.26s)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/21 08:17:09 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5142026/07/21 08:17:09 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5152026/07/21 08:17:09 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5162026/07/21 08:17:09 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5172026/07/21 08:17:09 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5182026/07/21 08:17:09 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5192026/07/21 08:17:09 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5202026/07/21 08:17:09 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5212026/07/21 08:17:09 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5222026/07/21 08:17:09 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 TestService_AuthMiddleware545=== CONT TestObjectStatsTrigger546=== CONT TestGCTaskStore_ConflictDifferentParams547--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)548=== CONT TestMultipartCleanup549=== CONT TestGenerateLandingPage550=== CONT TestClientIntegration551=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT552=== CONT TestGCTaskStore_CompletedAllowsNewTask553=== CONT TestGCTaskStore_Fail554=== CONT TestGCTaskStore_GetEmpty555=== CONT TestProxyWriteTimeout556--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)557--- PASS: TestGCTaskStore_Fail (0.00s)558--- PASS: TestGCTaskStore_GetEmpty (0.00s)559=== CONT TestGCTaskStore_PhaseUpdates560=== CONT TestGCTaskStore_GetReturnsLatest561--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)562=== RUN TestProxyWriteTimeout/narinfo563=== CONT TestGracefulShutdownDrainsInflight564=== PAUSE TestProxyWriteTimeout/narinfo565=== CONT TestCompleteMultipartUnregistered566--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)567=== CONT TestService_verifyS3Integrity568=== RUN TestProxyWriteTimeout/1_GiB_nar569=== PAUSE TestProxyWriteTimeout/1_GiB_nar570=== RUN TestProxyWriteTimeout/10_GiB_nar571=== PAUSE TestProxyWriteTimeout/10_GiB_nar572=== RUN TestProxyWriteTimeout/unknown_size573=== PAUSE TestProxyWriteTimeout/unknown_size574=== CONT TestService_createPendingClosureHandler5752026/07/21 08:17:09 INFO Starting HTTP server address=127.0.0.1:601675762026/07/21 08:17:09 INFO Shutdown signal received, draining in-flight requests timeout=10s577--- PASS: TestGenerateLandingPage (0.00s)578=== CONT TestService_cleanupPendingClosuresHandler579--- PASS: TestGracefulShutdownDrainsInflight (0.08s)580=== CONT TestUploadHandlersRejectOversizedBody581=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure582=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure583=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart584=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart585=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts586=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts587=== CONT TestUploadHandlersRejectInvalidKeys588=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info589=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info590=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal591=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal592=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key593=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key594=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key595=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key596=== CONT TestIsValidUploadKey597=== RUN TestIsValidUploadKey/narinfo598=== PAUSE TestIsValidUploadKey/narinfo599=== RUN TestIsValidUploadKey/nar_zst600=== PAUSE TestIsValidUploadKey/nar_zst601=== RUN TestIsValidUploadKey/nar_xz602=== PAUSE TestIsValidUploadKey/nar_xz603=== RUN TestIsValidUploadKey/nar_plain604=== PAUSE TestIsValidUploadKey/nar_plain605=== RUN TestIsValidUploadKey/listing606=== PAUSE TestIsValidUploadKey/listing607=== RUN TestIsValidUploadKey/build_log608=== PAUSE TestIsValidUploadKey/build_log609=== RUN TestIsValidUploadKey/build_log_home-manager_file610=== PAUSE TestIsValidUploadKey/build_log_home-manager_file611=== RUN TestIsValidUploadKey/build_log_plus_in_name612=== PAUSE TestIsValidUploadKey/build_log_plus_in_name613=== RUN TestIsValidUploadKey/build_log_question_mark614=== PAUSE TestIsValidUploadKey/build_log_question_mark615=== RUN TestIsValidUploadKey/build_log_equals616=== PAUSE TestIsValidUploadKey/build_log_equals617=== RUN TestIsValidUploadKey/realisation618=== PAUSE TestIsValidUploadKey/realisation619=== RUN TestIsValidUploadKey/realisation_plus_in_output620=== PAUSE TestIsValidUploadKey/realisation_plus_in_output621=== RUN TestIsValidUploadKey/nix-cache-info622=== PAUSE TestIsValidUploadKey/nix-cache-info623=== RUN TestIsValidUploadKey/index.html624=== PAUSE TestIsValidUploadKey/index.html625=== RUN TestIsValidUploadKey/narinfo_key,_nar_type626=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type627=== RUN TestIsValidUploadKey/nar_key,_narinfo_type628=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type629=== RUN TestIsValidUploadKey/listing_key,_narinfo_type630=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type631=== RUN TestIsValidUploadKey/traversal632=== PAUSE TestIsValidUploadKey/traversal633=== RUN TestIsValidUploadKey/traversal_nar634=== PAUSE TestIsValidUploadKey/traversal_nar635=== RUN TestIsValidUploadKey/absolute636=== PAUSE TestIsValidUploadKey/absolute637=== RUN TestIsValidUploadKey/empty_key638=== PAUSE TestIsValidUploadKey/empty_key639=== RUN TestIsValidUploadKey/unknown_type640=== PAUSE TestIsValidUploadKey/unknown_type641=== CONT TestReadProxyNarStreaming6422026-07-21 08:17:10.111 UTC [90032] ERROR: relation "goose_db_version" does not exist at character 366432026-07-21 08:17:10.111 UTC [90032] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6442026-07-21 08:17:10.114 UTC [90033] ERROR: relation "goose_db_version" does not exist at character 366452026-07-21 08:17:10.114 UTC [90033] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6462026-07-21 08:17:10.115 UTC [90034] ERROR: relation "goose_db_version" does not exist at character 366472026-07-21 08:17:10.115 UTC [90034] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6482026-07-21 08:17:10.116 UTC [90035] ERROR: relation "goose_db_version" does not exist at character 366492026-07-21 08:17:10.116 UTC [90035] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6502026-07-21 08:17:10.117 UTC [90036] ERROR: relation "goose_db_version" does not exist at character 366512026-07-21 08:17:10.117 UTC [90036] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6522026-07-21 08:17:10.118 UTC [90037] ERROR: relation "goose_db_version" does not exist at character 366532026-07-21 08:17:10.118 UTC [90037] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6542026-07-21 08:17:10.119 UTC [90038] ERROR: relation "goose_db_version" does not exist at character 366552026-07-21 08:17:10.119 UTC [90038] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6562026-07-21 08:17:10.119 UTC [90039] ERROR: relation "goose_db_version" does not exist at character 366572026-07-21 08:17:10.119 UTC [90039] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6582026-07-21 08:17:10.119 UTC [90040] ERROR: relation "goose_db_version" does not exist at character 366592026-07-21 08:17:10.119 UTC [90040] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6602026/07/21 08:17:10 OK 20241026095416_initial_model.sql (11.11ms)6612026/07/21 08:17:10 OK 20241026095416_initial_model.sql (8.71ms)6622026/07/21 08:17:10 OK 20241026095416_initial_model.sql (11.2ms)6632026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (1.3ms)6642026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (1.77ms)6652026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (1.92ms)6662026/07/21 08:17:10 OK 20241026095416_initial_model.sql (10.57ms)6672026/07/21 08:17:10 OK 20251218171726_add_pins.sql (2.04ms)6682026/07/21 08:17:10 OK 20251218171726_add_pins.sql (1.97ms)6692026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (1.19ms)6702026/07/21 08:17:10 OK 20241026095416_initial_model.sql (8.77ms)6712026/07/21 08:17:10 OK 20251218171726_add_pins.sql (2.6ms)6722026/07/21 08:17:10 OK 20241026095416_initial_model.sql (10.5ms)6732026/07/21 08:17:10 OK 20241026095416_initial_model.sql (9.96ms)6742026/07/21 08:17:10 OK 20241026095416_initial_model.sql (8.33ms)6752026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (872.25µs)6762026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (762.17µs)6772026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (1.15ms)6782026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (2.19ms)6792026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (2.21ms)6802026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200006812026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (1.09ms)6822026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200006832026-07-21 08:17:10.134 UTC [90041] ERROR: relation "goose_db_version" does not exist at character 366842026-07-21 08:17:10.134 UTC [90041] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6852026/07/21 08:17:10 OK 20251218171726_add_pins.sql (2.35ms)6862026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (2.14ms)6872026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200006882026/07/21 08:17:10 OK 20251218171726_add_pins.sql (1.73ms)6892026/07/21 08:17:10 OK 20241026095416_initial_model.sql (10.95ms)6902026/07/21 08:17:10 OK 20251218171726_add_pins.sql (2.08ms)6912026/07/21 08:17:10 OK 1_commit_pending_closure.sql (1.4ms)6922026/07/21 08:17:10 OK 1_commit_pending_closure.sql (1.24ms)6932026/07/21 08:17:10 OK 1_commit_pending_closure.sql (1.77ms)6942026/07/21 08:17:10 OK 2_object_stats_trigger.sql (617.5µs)6952026/07/21 08:17:10 goose: up to current file version: 26962026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (954.17µs)6972026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (1.84ms)6982026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200006992026/07/21 08:17:10 OK 2_object_stats_trigger.sql (555.38µs)7002026/07/21 08:17:10 goose: up to current file version: 27012026/07/21 08:17:10 OK 20251218171726_add_pins.sql (2.36ms)7022026/07/21 08:17:10 OK 2_object_stats_trigger.sql (637.46µs)7032026/07/21 08:17:10 goose: up to current file version: 27042026/07/21 08:17:10 OK 20251218171726_add_pins.sql (2.56ms)7052026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (1.95ms)7062026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200007072026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (2.01ms)7082026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200007092026/07/21 08:17:10 OK 1_commit_pending_closure.sql (1.75ms)7102026/07/21 08:17:10 OK 20251218171726_add_pins.sql (1.85ms)7112026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (1.62ms)7122026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200007132026/07/21 08:17:10 OK 1_commit_pending_closure.sql (1.15ms)7142026/07/21 08:17:10 OK 2_object_stats_trigger.sql (515.58µs)7152026/07/21 08:17:10 goose: up to current file version: 27162026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (2.26ms)7172026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200007182026/07/21 08:17:10 OK 2_object_stats_trigger.sql (694.83µs)7192026/07/21 08:17:10 goose: up to current file version: 27202026/07/21 08:17:10 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"721--- PASS: TestService_AuthMiddleware (0.31s)722=== CONT TestReadProxyRangeRequest7232026/07/21 08:17:10 INFO Received uploads request method=POST path=/api/pending_closures7242026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (1.58ms)7252026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200007262026/07/21 08:17:10 OK 1_commit_pending_closure.sql (2.62ms)7272026/07/21 08:17:10 OK 1_commit_pending_closure.sql (2.27ms)7282026/07/21 08:17:10 OK 1_commit_pending_closure.sql (2.11ms)7292026/07/21 08:17:10 INFO Received cleanup request method=DELETE path=/api/pending_closures7302026/07/21 08:17:10 OK 2_object_stats_trigger.sql (549.04µs)7312026/07/21 08:17:10 goose: up to current file version: 27322026/07/21 08:17:10 OK 2_object_stats_trigger.sql (678.79µs)7332026/07/21 08:17:10 goose: up to current file version: 27342026/07/21 08:17:10 OK 2_object_stats_trigger.sql (465.38µs)7352026/07/21 08:17:10 goose: up to current file version: 27362026/07/21 08:17:10 OK 1_commit_pending_closure.sql (2.12ms)7372026/07/21 08:17:10 INFO Aborted multipart uploads count=07382026/07/21 08:17:10 OK 2_object_stats_trigger.sql (549.88µs)7392026/07/21 08:17:10 goose: up to current file version: 27402026/07/21 08:17:10 INFO Received uploads request method=POST path=/api/pending_closures7412026/07/21 08:17:10 INFO Received uploads request method=POST path=/api/pending_closures7422026/07/21 08:17:10 INFO Received uploads request method=POST path=/api/pending_closures7432026/07/21 08:17:10 INFO Received uploads request method=POST path=/api/pending_closures7442026/07/21 08:17:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7452026/07/21 08:17:10 INFO Received uploads request method=POST path=/api/pending_closures7462026/07/21 08:17:10 INFO Received uploads request method=POST path=/api/pending_closures7472026/07/21 08:17:10 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst748--- PASS: TestCompleteMultipartUnregistered (0.31s)749=== CONT TestReadProxyDisabled750--- PASS: TestObjectStatsTrigger (0.31s)751=== CONT TestReadProxyRootRedirectsToIndexHTML752--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.31s)753=== CONT TestReadProxyConditionalGet754{"timestamp":"2026-07-21T08:17:10.149375Z","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(2)"}7552026/07/21 08:17:10 OK 20241026095416_initial_model.sql (10.45ms)7562026/07/21 08:17:10 INFO Created nix-cache-info in bucket bucket=bucket107572026/07/21 08:17:10 INFO Received cleanup request method=DELETE path=/api/pending_closures7582026/07/21 08:17:10 INFO Aborted multipart uploads count=17592026/07/21 08:17:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7602026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (1.37ms)7612026-07-21 08:17:10.156 UTC [90034] ERROR: Closure does not exist: id=17622026-07-21 08:17:10.156 UTC [90034] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE7632026-07-21 08:17:10.156 UTC [90034] STATEMENT: -- name: CommitPendingClosure :exec764 SELECT commit_pending_closure($1::bigint)765 766--- PASS: TestService_cleanupPendingClosuresHandler (0.32s)767=== CONT TestReadProxyHead7682026/07/21 08:17:10 OK 20251218171726_add_pins.sql (2.21ms)7692026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (1.67ms)7702026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200007712026/07/21 08:17:10 OK 1_commit_pending_closure.sql (1.71ms)7722026/07/21 08:17:10 OK 2_object_stats_trigger.sql (1.21ms)7732026/07/21 08:17:10 goose: up to current file version: 2774--- PASS: TestReadProxyNarStreaming (0.24s)775=== CONT TestReadProxyInvalidPath7762026/07/21 08:17:10 INFO Received cleanup request method=DELETE path=/api/pending_closures7772026/07/21 08:17:10 INFO Aborted multipart uploads count=1778--- PASS: TestMultipartCleanup (0.43s)779=== CONT TestReadProxy4047802026/07/21 08:17:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7812026/07/21 08:17:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete782=== NAME TestClientIntegration783 client_integration_test.go:276: Created store path: /nix/var/nix/builds/nix-89852-3968335264/TestClientIntegration2094406877/002/store/0vindy0whi2672rgnx5fsmcdgx10yxnj-test-file.txt7842026/07/21 08:17:10 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YjU2MTk1ODItZjJiOC00ZTFiLThlYjUtOWQ2NzI5NTZlZTAyLjRhOTQwZTE2LTc2MDAtNGEyMS04MjNjLTMyNjNiYTVhMzQwZHgxNzg0NjIxODMwMTQ5NjQ2MDAw parts=107852026/07/21 08:17:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7862026/07/21 08:17:10 INFO Completed upload id=17872026/07/21 08:17:10 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YjU2MTk1ODItZjJiOC00ZTFiLThlYjUtOWQ2NzI5NTZlZTAyLmRmNGM3NDg1LTE4YzctNGM3My04MmQ3LTM2YTZhNTVjMWEzY3gxNzg0NjIxODMwMTQ3ODI1MDAw parts=107882026/07/21 08:17:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7892026/07/21 08:17:10 INFO Received uploads request method=POST path=/api/pending_closures7902026/07/21 08:17:10 INFO Received uploads request method=POST path=/api/pending_closures7912026/07/21 08:17:10 INFO Completed upload id=17922026/07/21 08:17:10 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000007932026-07-21 08:17:10.362 UTC [90082] ERROR: relation "goose_db_version" does not exist at character 367942026-07-21 08:17:10.362 UTC [90082] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7952026/07/21 08:17:10 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo7962026/07/21 08:17:10 WARN Found objects in DB but missing from S3, will re-upload count=17972026/07/21 08:17:10 INFO Received uploads request method=POST path=/api/pending_closures798--- PASS: TestService_verifyS3Integrity (0.53s)799=== CONT TestCacheConfigHandler800=== RUN TestCacheConfigHandler/full_config,_no_issuer801=== PAUSE TestCacheConfigHandler/full_config,_no_issuer802=== RUN TestCacheConfigHandler/no_cache_url_configured803=== PAUSE TestCacheConfigHandler/no_cache_url_configured804=== RUN TestCacheConfigHandler/no_signing_keys805=== PAUSE TestCacheConfigHandler/no_signing_keys806=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator807=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator808=== CONT TestClientErrorHandling809=== RUN TestClientErrorHandling/InvalidStorePath810=== PAUSE TestClientErrorHandling/InvalidStorePath811=== RUN TestClientErrorHandling/InvalidAuthToken812=== PAUSE TestClientErrorHandling/InvalidAuthToken813=== RUN TestClientErrorHandling/ServerNotAvailable814=== PAUSE TestClientErrorHandling/ServerNotAvailable815=== CONT TestClientCADerivations8162026/07/21 08:17:10 INFO Starting cleanup of old closures method=DELETE path=/api/closures8172026-07-21 08:17:10.368 UTC [90084] ERROR: relation "goose_db_version" does not exist at character 368182026-07-21 08:17:10.368 UTC [90084] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8192026-07-21 08:17:10.369 UTC [90085] ERROR: relation "goose_db_version" does not exist at character 368202026-07-21 08:17:10.369 UTC [90085] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8212026/07/21 08:17:10 INFO Aborted multipart uploads count=08222026-07-21 08:17:10.372 UTC [90087] ERROR: relation "goose_db_version" does not exist at character 368232026-07-21 08:17:10.372 UTC [90087] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8242026/07/21 08:17:10 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=08252026/07/21 08:17:10 INFO Vacuumed table table=pending_closures8262026/07/21 08:17:10 OK 20241026095416_initial_model.sql (22.82ms)8272026/07/21 08:17:10 OK 20241026095416_initial_model.sql (22.34ms)8282026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (430.96µs)8292026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (561µs)8302026/07/21 08:17:10 OK 20251218171726_add_pins.sql (838.33µs)8312026/07/21 08:17:10 OK 20251218171726_add_pins.sql (901.42µs)8322026/07/21 08:17:10 OK 20241026095416_initial_model.sql (29.16ms)8332026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (331.08µs)8342026/07/21 08:17:10 OK 20251218171726_add_pins.sql (719.29µs)8352026/07/21 08:17:10 INFO Vacuumed table table=pending_objects8362026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (10.52ms)8372026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200008382026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (11.59ms)8392026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200008402026/07/21 08:17:10 OK 20241026095416_initial_model.sql (33.73ms)8412026/07/21 08:17:10 INFO Vacuumed table table=multipart_uploads8422026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (6.6ms)8432026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200008442026/07/21 08:17:10 OK 1_commit_pending_closure.sql (2.02ms)8452026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (1.09ms)8462026/07/21 08:17:10 OK 2_object_stats_trigger.sql (382.88µs)8472026/07/21 08:17:10 goose: up to current file version: 28482026/07/21 08:17:10 INFO Vacuumed table table=closures8492026/07/21 08:17:10 OK 1_commit_pending_closure.sql (1.86ms)8502026/07/21 08:17:10 OK 20251218171726_add_pins.sql (898.46µs)8512026/07/21 08:17:10 OK 2_object_stats_trigger.sql (395.13µs)8522026/07/21 08:17:10 goose: up to current file version: 28532026/07/21 08:17:10 OK 1_commit_pending_closure.sql (1.53ms)8542026/07/21 08:17:10 OK 2_object_stats_trigger.sql (351.42µs)8552026/07/21 08:17:10 goose: up to current file version: 2856--- PASS: TestReadProxyDisabled (0.27s)857=== CONT TestCacheStatsHandler8582026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (3.41ms)8592026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200008602026/07/21 08:17:10 INFO Vacuumed table table=objects861--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.27s)862=== CONT TestService_ReadAuthMiddleware8632026/07/21 08:17:10 OK 1_commit_pending_closure.sql (3.46ms)8642026/07/21 08:17:10 OK 2_object_stats_trigger.sql (332.75µs)8652026/07/21 08:17:10 goose: up to current file version: 2866--- PASS: TestReadProxyRangeRequest (0.28s)867=== CONT TestService_AuthMiddleware_OIDC8682026/07/21 08:17:10 INFO OIDC provider initialized name=test869--- PASS: TestReadProxyConditionalGet (0.28s)870=== CONT TestService_AuthMiddleware_MTLSBoundSubjects8712026/07/21 08:17:10 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"8722026/07/21 08:17:10 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000873--- PASS: TestService_createPendingClosureHandler (0.63s)874=== CONT TestService_healthCheckHandler8752026-07-21 08:17:10.486 UTC [90105] ERROR: relation "goose_db_version" does not exist at character 368762026-07-21 08:17:10.486 UTC [90105] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8772026/07/21 08:17:10 INFO Received uploads request method=POST path=/api/pending_closures8782026/07/21 08:17:10 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8792026/07/21 08:17:10 INFO Uploading 0vindy0whi2672rgnx5fsmcdgx10yxnj-test-file.txt (152B)8802026/07/21 08:17:10 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"8812026/07/21 08:17:10 WARN Failed to register uploaded object key=0vindy0whi2672rgnx5fsmcdgx10yxnj.ls error="server returned 404: 404 page not found\n"8822026/07/21 08:17:10 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign8832026/07/21 08:17:10 INFO Signed narinfos id=1 count=18842026/07/21 08:17:10 INFO Uploading 1 narinfos8852026/07/21 08:17:10 WARN Failed to register uploaded object key=0vindy0whi2672rgnx5fsmcdgx10yxnj.narinfo error="server returned 404: 404 page not found\n"8862026/07/21 08:17:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8872026/07/21 08:17:10 INFO Completed upload id=18882026/07/21 08:17:10 INFO Upload complete. (109ms)889=== NAME TestClientIntegration890 client_integration_test.go:292: Retrieved narinfo from S3:891 StorePath: /nix/var/nix/builds/nix-89852-3968335264/TestClientIntegration2094406877/002/store/0vindy0whi2672rgnx5fsmcdgx10yxnj-test-file.txt892 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst893 Compression: zstd894 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1895 NarSize: 152896 References: 897 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1898 client_integration_test.go:293: Retrieved .ls file from S3 (compressed size: 77 bytes)899 client_integration_test.go:293: Decompressed .ls content (64 bytes):900 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}901 client_integration_test.go:296: Testing garbage collection...9022026/07/21 08:17:10 OK 20241026095416_initial_model.sql (14.17ms)9032026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (485.75µs)9042026/07/21 08:17:10 OK 20251218171726_add_pins.sql (784.79µs)9052026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (6.39ms)9062026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200009072026/07/21 08:17:10 OK 1_commit_pending_closure.sql (1.24ms)9082026/07/21 08:17:10 OK 2_object_stats_trigger.sql (597.13µs)9092026/07/21 08:17:10 goose: up to current file version: 2910--- PASS: TestReadProxyHead (0.37s)911=== CONT TestMetricsInventory9122026/07/21 08:17:10 INFO Starting cleanup of old closures method=DELETE path=/api/closures9132026/07/21 08:17:10 INFO Garbage collection started9142026-07-21 08:17:10.565 UTC [90110] ERROR: relation "goose_db_version" does not exist at character 369152026-07-21 08:17:10.565 UTC [90110] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9162026/07/21 08:17:10 INFO Aborted multipart uploads count=09172026/07/21 08:17:10 WARN Force mode enabled - objects will be deleted immediately without grace period9182026/07/21 08:17:10 OK 20241026095416_initial_model.sql (20.97ms)9192026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (595.71µs)9202026/07/21 08:17:10 OK 20251218171726_add_pins.sql (1.53ms)9212026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (2.62ms)9222026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200009232026/07/21 08:17:10 OK 1_commit_pending_closure.sql (1.04ms)9242026/07/21 08:17:10 OK 2_object_stats_trigger.sql (280.38µs)9252026/07/21 08:17:10 goose: up to current file version: 2926--- PASS: TestReadProxyInvalidPath (0.43s)927=== CONT TestServerTLSConfig928=== RUN TestServerTLSConfig/no_client_CA929=== PAUSE TestServerTLSConfig/no_client_CA930=== RUN TestServerTLSConfig/missing_CA_file931=== PAUSE TestServerTLSConfig/missing_CA_file932=== RUN TestServerTLSConfig/not_a_PEM_file933=== PAUSE TestServerTLSConfig/not_a_PEM_file934=== CONT TestService_NativeMTLS9352026-07-21 08:17:10.797 UTC [90115] ERROR: relation "goose_db_version" does not exist at character 369362026-07-21 08:17:10.797 UTC [90115] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9372026-07-21 08:17:10.797 UTC [90116] ERROR: relation "goose_db_version" does not exist at character 369382026-07-21 08:17:10.797 UTC [90116] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9392026/07/21 08:17:10 OK 20241026095416_initial_model.sql (11.45ms)9402026/07/21 08:17:10 OK 20241026095416_initial_model.sql (13.17ms)9412026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (465.33µs)9422026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (461.58µs)9432026/07/21 08:17:10 OK 20251218171726_add_pins.sql (1.6ms)9442026/07/21 08:17:10 OK 20251218171726_add_pins.sql (3.93ms)9452026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (6.02ms)9462026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200009472026/07/21 08:17:10 OK 1_commit_pending_closure.sql (1.22ms)9482026/07/21 08:17:10 OK 2_object_stats_trigger.sql (368µs)9492026/07/21 08:17:10 goose: up to current file version: 29502026/07/21 08:17:10 INFO Created nix-cache-info in bucket bucket=bucket189512026-07-21 08:17:10.853 UTC [90117] ERROR: relation "goose_db_version" does not exist at character 369522026-07-21 08:17:10.853 UTC [90117] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9532026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (26.75ms)9542026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200009552026/07/21 08:17:10 OK 1_commit_pending_closure.sql (1.52ms)9562026/07/21 08:17:10 OK 2_object_stats_trigger.sql (591.21µs)9572026/07/21 08:17:10 goose: up to current file version: 2958--- PASS: TestReadProxy404 (0.60s)959=== CONT TestService_AuthMiddleware_MTLSProxyHeader9602026-07-21 08:17:10.877 UTC [90121] ERROR: relation "goose_db_version" does not exist at character 369612026-07-21 08:17:10.877 UTC [90121] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9622026-07-21 08:17:10.879 UTC [90122] ERROR: relation "goose_db_version" does not exist at character 369632026-07-21 08:17:10.879 UTC [90122] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9642026/07/21 08:17:10 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2469 objects-failed-to-delete=09652026/07/21 08:17:10 OK 20241026095416_initial_model.sql (39.45ms)9662026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (1.04ms)9672026/07/21 08:17:10 OK 20251218171726_add_pins.sql (2.75ms)9682026-07-21 08:17:10.912 UTC [90125] ERROR: relation "goose_db_version" does not exist at character 369692026-07-21 08:17:10.912 UTC [90125] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9702026/07/21 08:17:10 INFO Vacuumed table table=pending_closures9712026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (4.5ms)9722026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200009732026/07/21 08:17:10 INFO Vacuumed table table=pending_objects9742026/07/21 08:17:10 INFO Vacuumed table table=multipart_uploads9752026/07/21 08:17:10 OK 1_commit_pending_closure.sql (2.39ms)9762026/07/21 08:17:10 OK 2_object_stats_trigger.sql (546.88µs)9772026/07/21 08:17:10 goose: up to current file version: 29782026/07/21 08:17:10 INFO Vacuumed table table=closures9792026/07/21 08:17:10 OK 20241026095416_initial_model.sql (12.12ms)9802026/07/21 08:17:10 OK 20241026095416_initial_model.sql (12.48ms)9812026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (633.71µs)9822026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (675.96µs)9832026/07/21 08:17:10 OK 20251218171726_add_pins.sql (1ms)9842026/07/21 08:17:10 OK 20251218171726_add_pins.sql (1.44ms)9852026/07/21 08:17:10 INFO Vacuumed table table=objects9862026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (4.3ms)9872026/07/21 08:17:10 goose: successfully migrated database to version: 202606281200009882026/07/21 08:17:10 OK 1_commit_pending_closure.sql (1.25ms)9892026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (4.94ms)9902026/07/21 08:17:10 goose: successfully migrated database to version: 20260628120000991--- PASS: TestCacheStatsHandler (0.51s)992=== CONT TestGCBugBareHashReferences9932026/07/21 08:17:10 OK 20241026095416_initial_model.sql (8.12ms)9942026/07/21 08:17:10 OK 1_commit_pending_closure.sql (2.93ms)9952026/07/21 08:17:10 OK 2_object_stats_trigger.sql (3.17ms)9962026/07/21 08:17:10 goose: up to current file version: 29972026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (3.04ms)9982026/07/21 08:17:10 OK 2_object_stats_trigger.sql (832.88µs)9992026/07/21 08:17:10 goose: up to current file version: 210002026/07/21 08:17:10 OK 20251218171726_add_pins.sql (1.31ms)1001=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1002=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1003=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1004=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected10052026/07/21 08:17:10 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1006--- PASS: TestService_ReadAuthMiddleware (0.51s)1007=== CONT TestGCTaskStore_DeduplicateSameParams1008--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1009=== CONT TestGCTaskStore_StartNew1010--- PASS: TestGCTaskStore_StartNew (0.00s)1011=== CONT TestGCMetrics1012=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1013=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1014=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1015=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1016=== CONT TestService_Rustfstest10172026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (4.09ms)10182026/07/21 08:17:10 goose: successfully migrated database to version: 2026062812000010192026/07/21 08:17:10 OK 1_commit_pending_closure.sql (1.78ms)10202026/07/21 08:17:10 OK 2_object_stats_trigger.sql (681.96µs)10212026/07/21 08:17:10 goose: up to current file version: 210222026/07/21 08:17:10 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"10232026/07/21 08:17:10 WARN mTLS auth: bound subjects configured but subject DN unavailable10242026/07/21 08:17:10 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1025--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.51s)1026=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle10272026-07-21 08:17:10.946 UTC [90131] ERROR: relation "goose_db_version" does not exist at character 3610282026-07-21 08:17:10.946 UTC [90131] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10292026/07/21 08:17:10 OK 20241026095416_initial_model.sql (12.36ms)10302026/07/21 08:17:10 OK 20251210153512_drop_unused_gin_index.sql (551.92µs)10312026/07/21 08:17:10 OK 20251218171726_add_pins.sql (804.17µs)10322026/07/21 08:17:10 OK 20260628120000_add_object_size_and_stats.sql (2.63ms)10332026/07/21 08:17:10 goose: successfully migrated database to version: 2026062812000010342026/07/21 08:17:10 OK 1_commit_pending_closure.sql (1.25ms)10352026/07/21 08:17:10 OK 2_object_stats_trigger.sql (526.29µs)10362026/07/21 08:17:10 goose: up to current file version: 21037--- PASS: TestService_healthCheckHandler (0.51s)1038=== CONT TestSkippedUploadsHandler10392026/07/21 08:17:10 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001040--- PASS: TestSkippedUploadsHandler (0.00s)1041=== CONT TestParseSize1042--- PASS: TestParseSize (0.00s)1043=== CONT TestCreatePendingClosureRejectsOversizedNAR10442026/07/21 08:17:10 INFO Received uploads request method=POST path=/api/pending_closures1045--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1046=== CONT TestNARDeduplicationMetadataUploadBug10472026-07-21 08:17:11.009 UTC [90139] ERROR: relation "goose_db_version" does not exist at character 3610482026-07-21 08:17:11.009 UTC [90139] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10492026/07/21 08:17:11 OK 20241026095416_initial_model.sql (13.26ms)10502026/07/21 08:17:11 OK 20251210153512_drop_unused_gin_index.sql (382.71µs)10512026/07/21 08:17:11 OK 20251218171726_add_pins.sql (763.96µs)10522026/07/21 08:17:11 OK 20260628120000_add_object_size_and_stats.sql (8.51ms)10532026/07/21 08:17:11 goose: successfully migrated database to version: 2026062812000010542026/07/21 08:17:11 OK 1_commit_pending_closure.sql (2.35ms)10552026/07/21 08:17:11 OK 2_object_stats_trigger.sql (517.67µs)10562026/07/21 08:17:11 goose: up to current file version: 21057--- PASS: TestMetricsInventory (0.54s)1058=== CONT TestParseSingleRange1059=== RUN TestParseSingleRange/none1060=== PAUSE TestParseSingleRange/none1061=== RUN TestParseSingleRange/unknown_unit1062=== PAUSE TestParseSingleRange/unknown_unit1063=== RUN TestParseSingleRange/multi-range_ignored1064=== PAUSE TestParseSingleRange/multi-range_ignored1065=== RUN TestParseSingleRange/malformed_no_dash1066=== PAUSE TestParseSingleRange/malformed_no_dash1067=== RUN TestParseSingleRange/malformed_both_empty1068=== PAUSE TestParseSingleRange/malformed_both_empty1069=== RUN TestParseSingleRange/malformed_end_before_start1070=== PAUSE TestParseSingleRange/malformed_end_before_start1071=== RUN TestParseSingleRange/closed1072=== PAUSE TestParseSingleRange/closed1073=== RUN TestParseSingleRange/open-ended1074=== PAUSE TestParseSingleRange/open-ended1075=== RUN TestParseSingleRange/end_clamped_to_size1076=== PAUSE TestParseSingleRange/end_clamped_to_size1077=== RUN TestParseSingleRange/suffix1078=== PAUSE TestParseSingleRange/suffix1079=== RUN TestParseSingleRange/suffix_exceeds_size1080=== PAUSE TestParseSingleRange/suffix_exceeds_size1081=== RUN TestParseSingleRange/single_byte1082=== PAUSE TestParseSingleRange/single_byte1083=== RUN TestParseSingleRange/start_past_EOF1084=== PAUSE TestParseSingleRange/start_past_EOF1085=== RUN TestParseSingleRange/start_far_past_EOF1086=== PAUSE TestParseSingleRange/start_far_past_EOF1087=== CONT TestReadProxyNarinfoAlreadyDecompressed10882026-07-21 08:17:11.096 UTC [90142] ERROR: relation "goose_db_version" does not exist at character 3610892026-07-21 08:17:11.096 UTC [90142] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1090=== NAME TestClientCADerivations1091 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-89852-3968335264/TestClientCADerivations1209402984/001/store/8b78x5a84xiab5fkvkiib9ji0xzw3sf4-ca-test10922026/07/21 08:17:11 OK 20241026095416_initial_model.sql (4.55ms)10932026/07/21 08:17:11 OK 20251210153512_drop_unused_gin_index.sql (655.17µs)10942026/07/21 08:17:11 OK 20251218171726_add_pins.sql (2.23ms)10952026/07/21 08:17:11 OK 20260628120000_add_object_size_and_stats.sql (3.31ms)10962026/07/21 08:17:11 goose: successfully migrated database to version: 2026062812000010972026/07/21 08:17:11 OK 1_commit_pending_closure.sql (1.88ms)10982026/07/21 08:17:11 OK 2_object_stats_trigger.sql (626.92µs)10992026/07/21 08:17:11 goose: up to current file version: 211002026/07/21 08:17:11 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11012026/07/21 08:17:11 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1102--- PASS: TestService_NativeMTLS (0.52s)1103=== CONT TestReadProxyNarinfo1104=== NAME TestClientCADerivations1105 client_ca_test.go:139: Found 1 dependencies (including self)11062026/07/21 08:17:11 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11072026-07-21 08:17:11.257 UTC [90153] ERROR: relation "goose_db_version" does not exist at character 3611082026-07-21 08:17:11.257 UTC [90153] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11092026/07/21 08:17:11 INFO Received uploads request method=POST path=/api/pending_closures11102026/07/21 08:17:11 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11112026/07/21 08:17:11 INFO Uploading 8b78x5a84xiab5fkvkiib9ji0xzw3sf4-ca-test (144B)11122026/07/21 08:17:11 WARN Failed to register uploaded object key=log/jyrmzlkwprj4ixrvam4rq009axddk435-ca-test.drv error="server returned 404: 404 page not found\n"11132026/07/21 08:17:11 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"11142026/07/21 08:17:11 WARN Failed to register uploaded object key=8b78x5a84xiab5fkvkiib9ji0xzw3sf4.ls error="server returned 404: 404 page not found\n"11152026/07/21 08:17:11 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11162026/07/21 08:17:11 INFO Signed narinfos id=1 count=111172026/07/21 08:17:11 INFO Uploading 1 narinfos11182026/07/21 08:17:11 OK 20241026095416_initial_model.sql (18.97ms)11192026/07/21 08:17:11 WARN Failed to register uploaded object key=8b78x5a84xiab5fkvkiib9ji0xzw3sf4.narinfo error="server returned 404: 404 page not found\n"11202026/07/21 08:17:11 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11212026/07/21 08:17:11 OK 20251210153512_drop_unused_gin_index.sql (804.96µs)11222026/07/21 08:17:11 OK 20251218171726_add_pins.sql (1.63ms)11232026/07/21 08:17:11 OK 20260628120000_add_object_size_and_stats.sql (7.4ms)11242026/07/21 08:17:11 goose: successfully migrated database to version: 2026062812000011252026/07/21 08:17:11 OK 1_commit_pending_closure.sql (1.51ms)11262026/07/21 08:17:11 OK 2_object_stats_trigger.sql (218.08µs)11272026/07/21 08:17:11 goose: up to current file version: 211282026/07/21 08:17:11 INFO Completed upload id=111292026/07/21 08:17:11 INFO Upload complete. (104ms)1130--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.43s)1131=== CONT TestIsValidCachePath1132=== RUN TestIsValidCachePath/narinfo1133=== PAUSE TestIsValidCachePath/narinfo1134=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1135=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1136=== RUN TestIsValidCachePath/nar_zst1137=== PAUSE TestIsValidCachePath/nar_zst1138=== RUN TestIsValidCachePath/nar_xz1139=== PAUSE TestIsValidCachePath/nar_xz1140=== RUN TestIsValidCachePath/nar_bz21141=== PAUSE TestIsValidCachePath/nar_bz21142=== RUN TestIsValidCachePath/nar_uncompressed1143=== PAUSE TestIsValidCachePath/nar_uncompressed1144=== RUN TestIsValidCachePath/ls1145=== PAUSE TestIsValidCachePath/ls1146=== RUN TestIsValidCachePath/log1147=== PAUSE TestIsValidCachePath/log1148=== RUN TestIsValidCachePath/realisation1149=== PAUSE TestIsValidCachePath/realisation1150=== RUN TestIsValidCachePath/nix-cache-info1151=== PAUSE TestIsValidCachePath/nix-cache-info1152=== RUN TestIsValidCachePath/index.html1153=== PAUSE TestIsValidCachePath/index.html1154=== RUN TestIsValidCachePath/traversal_parent1155=== PAUSE TestIsValidCachePath/traversal_parent1156=== RUN TestIsValidCachePath/traversal_in_middle1157=== PAUSE TestIsValidCachePath/traversal_in_middle1158=== RUN TestIsValidCachePath/invalid_char_e1159=== PAUSE TestIsValidCachePath/invalid_char_e1160=== RUN TestIsValidCachePath/invalid_char_u1161=== PAUSE TestIsValidCachePath/invalid_char_u1162=== RUN TestIsValidCachePath/random_path1163=== PAUSE TestIsValidCachePath/random_path1164=== RUN TestIsValidCachePath/empty1165=== PAUSE TestIsValidCachePath/empty1166=== RUN TestIsValidCachePath/leading_slash1167=== PAUSE TestIsValidCachePath/leading_slash1168=== RUN TestIsValidCachePath/wrong_extension1169=== PAUSE TestIsValidCachePath/wrong_extension1170=== RUN TestIsValidCachePath/short_hash1171=== PAUSE TestIsValidCachePath/short_hash1172=== CONT TestCacheConfigHandlerMaxNarSize1173--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1174=== CONT TestCompletedNarNotReofferedAcrossClosures1175=== NAME TestClientCADerivations1176 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-89852-3968335264/TestClientCADerivations1209402984/001/store/8b78x5a84xiab5fkvkiib9ji0xzw3sf4-ca-test1177 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1178 Compression: zstd1179 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1180 NarSize: 1441181 References: 1182 Deriver: /nix/var/nix/builds/nix-89852-3968335264/TestClientCADerivations1209402984/001/store/jyrmzlkwprj4ixrvam4rq009axddk435-ca-test.drv1183 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1184 client_ca_test.go:185: Checking for realisation files in S3...1185 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1186 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache11872026-07-21 08:17:11.307 UTC [90156] ERROR: relation "goose_db_version" does not exist at character 3611882026-07-21 08:17:11.307 UTC [90156] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11892026-07-21 08:17:11.327 UTC [90158] ERROR: relation "goose_db_version" does not exist at character 3611902026-07-21 08:17:11.327 UTC [90158] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11912026-07-21 08:17:11.328 UTC [90159] ERROR: relation "goose_db_version" does not exist at character 3611922026-07-21 08:17:11.328 UTC [90159] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11932026-07-21 08:17:11.335 UTC [90161] ERROR: relation "goose_db_version" does not exist at character 3611942026-07-21 08:17:11.335 UTC [90161] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11952026/07/21 08:17:11 OK 20241026095416_initial_model.sql (21.16ms)11962026/07/21 08:17:11 OK 20241026095416_initial_model.sql (36.81ms)11972026/07/21 08:17:11 OK 20251210153512_drop_unused_gin_index.sql (803.75µs)11982026/07/21 08:17:11 OK 20251210153512_drop_unused_gin_index.sql (884.21µs)11992026/07/21 08:17:11 OK 20251218171726_add_pins.sql (1.36ms)12002026/07/21 08:17:11 OK 20251218171726_add_pins.sql (1.35ms)12012026/07/21 08:17:11 OK 20260628120000_add_object_size_and_stats.sql (2.71ms)12022026/07/21 08:17:11 goose: successfully migrated database to version: 2026062812000012032026/07/21 08:17:11 OK 20260628120000_add_object_size_and_stats.sql (3.2ms)12042026/07/21 08:17:11 goose: successfully migrated database to version: 2026062812000012052026/07/21 08:17:11 OK 1_commit_pending_closure.sql (1.22ms)12062026/07/21 08:17:11 OK 2_object_stats_trigger.sql (467.29µs)12072026/07/21 08:17:11 goose: up to current file version: 212082026/07/21 08:17:11 OK 1_commit_pending_closure.sql (1.85ms)1209 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket18?endpoint=http://localhost:60122®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-89852-3968335264/TestClientCADerivations1209402984/001/store'1210 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 112112026/07/21 08:17:11 OK 2_object_stats_trigger.sql (674.5µs)12122026/07/21 08:17:11 goose: up to current file version: 212132026/07/21 08:17:11 OK 20241026095416_initial_model.sql (11.36ms)12142026/07/21 08:17:11 OK 20241026095416_initial_model.sql (11.58ms)12152026/07/21 08:17:11 OK 20251210153512_drop_unused_gin_index.sql (505.54µs)12162026/07/21 08:17:11 OK 20251210153512_drop_unused_gin_index.sql (734.46µs)1217--- PASS: TestService_Rustfstest (0.43s)1218=== CONT TestPresignedUploadRegisteredBeforeCommit12192026/07/21 08:17:11 OK 20251218171726_add_pins.sql (2.48ms)12202026/07/21 08:17:11 OK 20251218171726_add_pins.sql (3.28ms)1221--- PASS: TestClientCADerivations (1.00s)1222=== CONT TestOrphanedObjectsGCStressTest12232026/07/21 08:17:11 INFO Aborted multipart uploads count=012242026/07/21 08:17:11 OK 20260628120000_add_object_size_and_stats.sql (4.33ms)12252026/07/21 08:17:11 goose: successfully migrated database to version: 2026062812000012262026/07/21 08:17:11 OK 1_commit_pending_closure.sql (818.29µs)12272026/07/21 08:17:11 OK 2_object_stats_trigger.sql (535.58µs)12282026/07/21 08:17:11 goose: up to current file version: 212292026/07/21 08:17:11 WARN Force mode enabled - objects will be deleted immediately without grace period12302026/07/21 08:17:11 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=012312026/07/21 08:17:11 INFO Vacuumed table table=pending_closures12322026/07/21 08:17:11 INFO Vacuumed table table=pending_objects12332026/07/21 08:17:11 INFO Vacuumed table table=multipart_uploads12342026/07/21 08:17:11 INFO Vacuumed table table=closures12352026/07/21 08:17:11 INFO Vacuumed table table=objects1236--- PASS: TestGCMetrics (0.45s)1237=== CONT TestResurrectedObjectNotDeleted12382026/07/21 08:17:11 OK 20260628120000_add_object_size_and_stats.sql (18.63ms)12392026/07/21 08:17:11 goose: successfully migrated database to version: 2026062812000012402026/07/21 08:17:11 OK 1_commit_pending_closure.sql (1.79ms)12412026/07/21 08:17:11 OK 2_object_stats_trigger.sql (690.42µs)12422026/07/21 08:17:11 goose: up to current file version: 212432026/07/21 08:17:11 INFO Received uploads request method=POST path=/api/pending_closures12442026-07-21 08:17:11.407 UTC [90169] ERROR: relation "goose_db_version" does not exist at character 3612452026-07-21 08:17:11.407 UTC [90169] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12462026/07/21 08:17:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12472026/07/21 08:17:11 OK 20241026095416_initial_model.sql (15.66ms)12482026/07/21 08:17:11 OK 20251210153512_drop_unused_gin_index.sql (627.75µs)12492026/07/21 08:17:11 OK 20251218171726_add_pins.sql (2.04ms)12502026/07/21 08:17:11 OK 20260628120000_add_object_size_and_stats.sql (2.43ms)12512026/07/21 08:17:11 goose: successfully migrated database to version: 2026062812000012522026/07/21 08:17:11 OK 1_commit_pending_closure.sql (1.73ms)12532026/07/21 08:17:11 OK 2_object_stats_trigger.sql (281.5µs)12542026/07/21 08:17:11 goose: up to current file version: 212552026/07/21 08:17:11 INFO Created nix-cache-info in bucket bucket=bucket3212562026-07-21 08:17:11.476 UTC [90171] ERROR: relation "goose_db_version" does not exist at character 3612572026-07-21 08:17:11.476 UTC [90171] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12582026/07/21 08:17:11 OK 20241026095416_initial_model.sql (8.83ms)12592026/07/21 08:17:11 OK 20251210153512_drop_unused_gin_index.sql (332.38µs)12602026/07/21 08:17:11 OK 20251218171726_add_pins.sql (1.78ms)12612026/07/21 08:17:11 OK 20260628120000_add_object_size_and_stats.sql (4.31ms)12622026/07/21 08:17:11 goose: successfully migrated database to version: 2026062812000012632026/07/21 08:17:11 OK 1_commit_pending_closure.sql (945.21µs)12642026/07/21 08:17:11 OK 2_object_stats_trigger.sql (208.13µs)12652026/07/21 08:17:11 goose: up to current file version: 21266--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.44s)1267=== CONT TestOrphanedObjectsGC1268=== NAME TestNARDeduplicationMetadataUploadBug1269 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-89852-3968335264/TestNARDeduplicationMetadataUploadBug2469853066/001/store/3ng7kzclivpfacz6fchz6dw4m7x5qfcp-file1.txt12702026-07-21 08:17:11.537 UTC [90176] ERROR: relation "goose_db_version" does not exist at character 3612712026-07-21 08:17:11.537 UTC [90176] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12722026/07/21 08:17:11 OK 20241026095416_initial_model.sql (7.61ms)12732026/07/21 08:17:11 OK 20251210153512_drop_unused_gin_index.sql (713.92µs)12742026/07/21 08:17:11 OK 20251218171726_add_pins.sql (1.67ms)12752026/07/21 08:17:11 OK 20260628120000_add_object_size_and_stats.sql (2.84ms)12762026/07/21 08:17:11 goose: successfully migrated database to version: 2026062812000012772026/07/21 08:17:11 OK 1_commit_pending_closure.sql (1.41ms)12782026/07/21 08:17:11 OK 2_object_stats_trigger.sql (470µs)12792026/07/21 08:17:11 goose: up to current file version: 21280--- PASS: TestReadProxyNarinfo (0.45s)1281=== CONT TestCompleteMultipartUpload_ErrorButObjectExists1282--- PASS: TestGCBugBareHashReferences (0.67s)1283=== CONT TestClientWithDependencies12842026/07/21 08:17:11 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12852026/07/21 08:17:11 INFO Received uploads request method=POST path=/api/pending_closures12862026-07-21 08:17:11.648 UTC [90186] ERROR: relation "goose_db_version" does not exist at character 3612872026-07-21 08:17:11.648 UTC [90186] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12882026/07/21 08:17:11 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12892026/07/21 08:17:11 INFO Uploading 3ng7kzclivpfacz6fchz6dw4m7x5qfcp-file1.txt (160B)12902026/07/21 08:17:11 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12912026/07/21 08:17:11 WARN Failed to register uploaded object key=3ng7kzclivpfacz6fchz6dw4m7x5qfcp.ls error="server returned 404: 404 page not found\n"12922026/07/21 08:17:11 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12932026/07/21 08:17:11 INFO Signed narinfos id=1 count=112942026/07/21 08:17:11 INFO Uploading 1 narinfos12952026/07/21 08:17:11 WARN Failed to register uploaded object key=3ng7kzclivpfacz6fchz6dw4m7x5qfcp.narinfo error="server returned 404: 404 page not found\n"12962026/07/21 08:17:11 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12972026/07/21 08:17:11 INFO Completed upload id=112982026/07/21 08:17:11 INFO Upload complete. (115ms)1299=== NAME TestNARDeduplicationMetadataUploadBug1300 metadata_upload_test.go:54: Retrieved narinfo from S3:1301 StorePath: /nix/var/nix/builds/nix-89852-3968335264/TestNARDeduplicationMetadataUploadBug2469853066/001/store/3ng7kzclivpfacz6fchz6dw4m7x5qfcp-file1.txt1302 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1303 Compression: zstd1304 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1305 NarSize: 1601306 References: 1307 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf13082026/07/21 08:17:11 OK 20241026095416_initial_model.sql (12.59ms)13092026/07/21 08:17:11 OK 20251210153512_drop_unused_gin_index.sql (362.96µs)1310 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1311 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1312 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}13132026/07/21 08:17:11 OK 20251218171726_add_pins.sql (1.05ms)13142026/07/21 08:17:11 OK 20260628120000_add_object_size_and_stats.sql (6.58ms)13152026/07/21 08:17:11 goose: successfully migrated database to version: 2026062812000013162026/07/21 08:17:11 OK 1_commit_pending_closure.sql (1.71ms)13172026/07/21 08:17:11 OK 2_object_stats_trigger.sql (608.54µs)13182026/07/21 08:17:11 goose: up to current file version: 213192026/07/21 08:17:11 INFO Received uploads request method=POST path=/api/pending_closures13202026-07-21 08:17:11.707 UTC [90189] ERROR: relation "goose_db_version" does not exist at character 3613212026-07-21 08:17:11.707 UTC [90189] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1322 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-89852-3968335264/TestNARDeduplicationMetadataUploadBug2469853066/001/store/7rfxqypxh5s5zkd35n6p77vfa5w2wgyi-file2.txt13232026-07-21 08:17:11.728 UTC [90191] ERROR: relation "goose_db_version" does not exist at character 3613242026-07-21 08:17:11.728 UTC [90191] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13252026/07/21 08:17:11 OK 20241026095416_initial_model.sql (17.81ms)13262026/07/21 08:17:11 OK 20251210153512_drop_unused_gin_index.sql (825.17µs)13272026/07/21 08:17:11 OK 20251218171726_add_pins.sql (943.08µs)13282026/07/21 08:17:11 OK 20260628120000_add_object_size_and_stats.sql (6.24ms)13292026/07/21 08:17:11 goose: successfully migrated database to version: 2026062812000013302026/07/21 08:17:11 OK 1_commit_pending_closure.sql (1.02ms)13312026/07/21 08:17:11 OK 2_object_stats_trigger.sql (365.46µs)13322026/07/21 08:17:11 goose: up to current file version: 213332026/07/21 08:17:11 INFO Received uploads request method=POST path=/api/pending_closures13342026/07/21 08:17:11 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst13352026/07/21 08:17:11 INFO Received uploads request method=POST path=/api/pending_closures1336--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.39s)1337=== CONT TestPinProtectsFromGC13382026/07/21 08:17:11 OK 20241026095416_initial_model.sql (14.22ms)13392026/07/21 08:17:11 OK 20251210153512_drop_unused_gin_index.sql (1.37ms)13402026-07-21 08:17:11.756 UTC [90193] ERROR: relation "goose_db_version" does not exist at character 3613412026-07-21 08:17:11.756 UTC [90193] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13422026/07/21 08:17:11 OK 20251218171726_add_pins.sql (1.85ms)13432026/07/21 08:17:11 OK 20260628120000_add_object_size_and_stats.sql (10.5ms)13442026/07/21 08:17:11 goose: successfully migrated database to version: 2026062812000013452026/07/21 08:17:11 OK 1_commit_pending_closure.sql (1.25ms)13462026/07/21 08:17:11 OK 2_object_stats_trigger.sql (323.88µs)13472026/07/21 08:17:11 goose: up to current file version: 213482026/07/21 08:17:11 OK 20241026095416_initial_model.sql (12.24ms)13492026/07/21 08:17:11 OK 20251210153512_drop_unused_gin_index.sql (739.33µs)13502026/07/21 08:17:11 OK 20251218171726_add_pins.sql (2.89ms)13512026/07/21 08:17:11 OK 20260628120000_add_object_size_and_stats.sql (5.84ms)13522026/07/21 08:17:11 goose: successfully migrated database to version: 2026062812000013532026/07/21 08:17:11 OK 1_commit_pending_closure.sql (1.55ms)13542026/07/21 08:17:11 OK 2_object_stats_trigger.sql (523.33µs)13552026/07/21 08:17:11 goose: up to current file version: 21356--- PASS: TestResurrectedObjectNotDeleted (0.42s)1357=== CONT TestClientMultipleUploads13582026/07/21 08:17:11 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13592026/07/21 08:17:11 INFO Received uploads request method=POST path=/api/pending_closures13602026/07/21 08:17:11 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)13612026/07/21 08:17:11 WARN Failed to register uploaded object key=7rfxqypxh5s5zkd35n6p77vfa5w2wgyi.ls error="server returned 404: 404 page not found\n"13622026/07/21 08:17:11 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13632026/07/21 08:17:11 INFO Signed narinfos id=2 count=113642026/07/21 08:17:11 INFO Uploading 1 narinfos13652026/07/21 08:17:11 WARN Failed to register uploaded object key=7rfxqypxh5s5zkd35n6p77vfa5w2wgyi.narinfo error="server returned 404: 404 page not found\n"13662026/07/21 08:17:11 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13672026/07/21 08:17:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13682026/07/21 08:17:11 INFO Completed upload id=213692026/07/21 08:17:11 INFO Upload complete. (93ms)1370=== NAME TestNARDeduplicationMetadataUploadBug1371 metadata_upload_test.go:76: Retrieved narinfo from S3:1372 StorePath: /nix/var/nix/builds/nix-89852-3968335264/TestNARDeduplicationMetadataUploadBug2469853066/001/store/7rfxqypxh5s5zkd35n6p77vfa5w2wgyi-file2.txt1373 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1374 Compression: zstd1375 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1376 NarSize: 1601377 References: 1378 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1379 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1380 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1381 {"version":1,"root":{"type":"regular","size":44}}1382--- PASS: TestNARDeduplicationMetadataUploadBug (0.87s)1383=== CONT TestRedundantMultipartUpload13842026/07/21 08:17:11 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YjU2MTk1ODItZjJiOC00ZTFiLThlYjUtOWQ2NzI5NTZlZTAyLjgzNGNmODVkLWMyNWEtNDc3Ni04NmRhLTJkYzk3MjA0YWIzNngxNzg0NjIxODMxNjg0NDMyMDAw parts=1213852026/07/21 08:17:11 INFO Received uploads request method=POST path=/api/pending_closures1386--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.56s)1387=== CONT TestProxyWriteTimeout/narinfo1388=== CONT TestProxyWriteTimeout/10_GiB_nar1389=== CONT TestProxyWriteTimeout/unknown_size1390=== CONT TestProxyWriteTimeout/1_GiB_nar1391--- PASS: TestProxyWriteTimeout (0.00s)1392 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1393 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1394 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1395 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1396=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure13972026/07/21 08:17:11 INFO Received uploads request method=POST path=/13982026-07-21 08:17:11.887 UTC [90204] ERROR: relation "goose_db_version" does not exist at character 3613992026-07-21 08:17:11.887 UTC [90204] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14002026/07/21 08:17:11 OK 20241026095416_initial_model.sql (16.97ms)14012026/07/21 08:17:11 OK 20251210153512_drop_unused_gin_index.sql (702.42µs)14022026/07/21 08:17:11 OK 20251218171726_add_pins.sql (1.85ms)14032026/07/21 08:17:11 OK 20260628120000_add_object_size_and_stats.sql (2.76ms)14042026/07/21 08:17:11 goose: successfully migrated database to version: 2026062812000014052026/07/21 08:17:11 OK 1_commit_pending_closure.sql (1.18ms)14062026/07/21 08:17:11 OK 2_object_stats_trigger.sql (409.42µs)14072026/07/21 08:17:11 goose: up to current file version: 214082026-07-21 08:17:11.954 UTC [90205] ERROR: relation "goose_db_version" does not exist at character 3614092026-07-21 08:17:11.954 UTC [90205] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14102026-07-21 08:17:11.967 UTC [90206] ERROR: relation "goose_db_version" does not exist at character 3614112026-07-21 08:17:11.967 UTC [90206] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14122026/07/21 08:17:11 OK 20241026095416_initial_model.sql (7.06ms)14132026/07/21 08:17:11 OK 20251210153512_drop_unused_gin_index.sql (636.42µs)14142026/07/21 08:17:11 OK 20241026095416_initial_model.sql (8.53ms)14152026/07/21 08:17:11 OK 20251210153512_drop_unused_gin_index.sql (585.25µs)14162026/07/21 08:17:11 OK 20251218171726_add_pins.sql (1.78ms)14172026/07/21 08:17:11 OK 20251218171726_add_pins.sql (1.14ms)14182026/07/21 08:17:11 OK 20260628120000_add_object_size_and_stats.sql (1.48ms)14192026/07/21 08:17:11 goose: successfully migrated database to version: 2026062812000014202026/07/21 08:17:11 OK 20260628120000_add_object_size_and_stats.sql (1.89ms)14212026/07/21 08:17:11 goose: successfully migrated database to version: 2026062812000014222026/07/21 08:17:11 OK 1_commit_pending_closure.sql (1.2ms)14232026/07/21 08:17:11 OK 1_commit_pending_closure.sql (1.2ms)14242026/07/21 08:17:11 OK 2_object_stats_trigger.sql (244.75µs)14252026/07/21 08:17:11 goose: up to current file version: 214262026/07/21 08:17:11 OK 2_object_stats_trigger.sql (256.33µs)14272026/07/21 08:17:11 goose: up to current file version: 214282026/07/21 08:17:11 INFO Received uploads request method=POST path=/api/pending_closures14292026/07/21 08:17:11 INFO Created nix-cache-info in bucket bucket=bucket4014302026/07/21 08:17:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1431{"timestamp":"2026-07-21T08:17:12.007937Z","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(8)"}1432{"timestamp":"2026-07-21T08:17:12.007953Z","level":"ERROR","fields":{"message":"complete_multipart_upload etag err client=Some(\"deadbeef\"), stored=\"\", part_id=1, bucket=bucket41, 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(8)"}14332026/07/21 08:17:12 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=YjU2MTk1ODItZjJiOC00ZTFiLThlYjUtOWQ2NzI5NTZlZTAyLmM3ZmUzMzE4LThmMWItNDg2Zi1hNTFiLTI5ZjhhMjMyZjk3MngxNzg0NjIxODMxOTk4OTgyMDAw14342026/07/21 08:17:12 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjU2MTk1ODItZjJiOC00ZTFiLThlYjUtOWQ2NzI5NTZlZTAyLmM3ZmUzMzE4LThmMWItNDg2Zi1hNTFiLTI5ZjhhMjMyZjk3MngxNzg0NjIxODMxOTk4OTgyMDAw parts=11435--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.44s)1436=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts14372026/07/21 08:17:12 INFO Received request for more parts method=POST path=/14382026-07-21 08:17:12.033 UTC [90209] ERROR: relation "goose_db_version" does not exist at character 3614392026-07-21 08:17:12.033 UTC [90209] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1440=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart14412026/07/21 08:17:12 INFO Received complete multipart upload request method=POST path=/1442=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info14432026/07/21 08:17:12 INFO Received uploads request method=POST path=/1444=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key14452026/07/21 08:17:12 INFO Received complete multipart upload request method=POST path=/1446=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key14472026/07/21 08:17:12 INFO Received request for more parts method=POST path=/1448=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal14492026/07/21 08:17:12 INFO Received uploads request method=POST path=/1450--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1451 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1452 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1453 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1454 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1455=== CONT TestIsValidUploadKey/narinfo1456=== CONT TestIsValidUploadKey/realisation_plus_in_output1457=== CONT TestIsValidUploadKey/unknown_type1458=== CONT TestIsValidUploadKey/empty_key1459=== CONT TestIsValidUploadKey/absolute1460=== CONT TestIsValidUploadKey/traversal_nar1461=== CONT TestIsValidUploadKey/traversal1462=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1463=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1464=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1465=== CONT TestIsValidUploadKey/index.html1466=== CONT TestIsValidUploadKey/nix-cache-info1467=== CONT TestIsValidUploadKey/build_log_home-manager_file1468=== CONT TestIsValidUploadKey/realisation1469=== CONT TestIsValidUploadKey/build_log_equals1470=== CONT TestIsValidUploadKey/build_log_question_mark1471=== CONT TestIsValidUploadKey/build_log_plus_in_name1472=== CONT TestIsValidUploadKey/nar_plain1473=== CONT TestIsValidUploadKey/build_log1474=== CONT TestIsValidUploadKey/listing1475=== CONT TestIsValidUploadKey/nar_xz1476=== CONT TestIsValidUploadKey/nar_zst1477--- PASS: TestIsValidUploadKey (0.00s)1478 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1479 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1480 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1481 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1482 --- PASS: TestIsValidUploadKey/absolute (0.00s)1483 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1484 --- PASS: TestIsValidUploadKey/traversal (0.00s)1485 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1486 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1487 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1488 --- PASS: TestIsValidUploadKey/index.html (0.00s)1489 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1490 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1491 --- PASS: TestIsValidUploadKey/realisation (0.00s)1492 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1493 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1494 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1495 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1496 --- PASS: TestIsValidUploadKey/build_log (0.00s)1497 --- PASS: TestIsValidUploadKey/listing (0.00s)1498 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1499 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1500=== CONT TestCacheConfigHandler/full_config,_no_issuer1501=== CONT TestCacheConfigHandler/no_signing_keys1502=== CONT TestCacheConfigHandler/no_cache_url_configured1503=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1504--- PASS: TestCacheConfigHandler (0.00s)1505 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1506 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1507 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1508 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1509=== CONT TestClientErrorHandling/InvalidStorePath15102026/07/21 08:17:12 OK 20241026095416_initial_model.sql (22.91ms)15112026/07/21 08:17:12 OK 20251210153512_drop_unused_gin_index.sql (549.54µs)15122026/07/21 08:17:12 OK 20251218171726_add_pins.sql (2.14ms)15132026/07/21 08:17:12 OK 20260628120000_add_object_size_and_stats.sql (2.06ms)15142026/07/21 08:17:12 goose: successfully migrated database to version: 2026062812000015152026/07/21 08:17:12 OK 1_commit_pending_closure.sql (1.2ms)15162026/07/21 08:17:12 OK 2_object_stats_trigger.sql (230.67µs)15172026/07/21 08:17:12 goose: up to current file version: 215182026/07/21 08:17:12 INFO Created nix-cache-info in bucket bucket=bucket4215192026-07-21 08:17:12.092 UTC [90214] ERROR: relation "goose_db_version" does not exist at character 3615202026-07-21 08:17:12.092 UTC [90214] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15212026/07/21 08:17:12 OK 20241026095416_initial_model.sql (7.02ms)15222026/07/21 08:17:12 OK 20251210153512_drop_unused_gin_index.sql (619.96µs)15232026/07/21 08:17:12 OK 20251218171726_add_pins.sql (1.37ms)15242026/07/21 08:17:12 OK 20260628120000_add_object_size_and_stats.sql (4.15ms)15252026/07/21 08:17:12 goose: successfully migrated database to version: 2026062812000015262026/07/21 08:17:12 OK 1_commit_pending_closure.sql (1.86ms)15272026/07/21 08:17:12 OK 2_object_stats_trigger.sql (539.13µs)15282026/07/21 08:17:12 goose: up to current file version: 215292026/07/21 08:17:12 INFO Created nix-cache-info in bucket bucket=bucket4315302026-07-21 08:17:12.125 UTC [90219] ERROR: relation "goose_db_version" does not exist at character 3615312026-07-21 08:17:12.125 UTC [90219] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15322026/07/21 08:17:12 OK 20241026095416_initial_model.sql (7.25ms)15332026/07/21 08:17:12 OK 20251210153512_drop_unused_gin_index.sql (827.42µs)15342026/07/21 08:17:12 OK 20251218171726_add_pins.sql (2.03ms)15352026/07/21 08:17:12 OK 20260628120000_add_object_size_and_stats.sql (12.24ms)15362026/07/21 08:17:12 goose: successfully migrated database to version: 202606281200001537=== NAME TestClientMultipleUploads1538 client_integration_test.go:338: Created store path 0: /nix/var/nix/builds/nix-89852-3968335264/TestClientMultipleUploads2139641249/001/store/66v6lhnf0aqwi8jqn73h23f82d7yaasi-test-file-0.txt15392026/07/21 08:17:12 OK 1_commit_pending_closure.sql (2.25ms)15402026/07/21 08:17:12 OK 2_object_stats_trigger.sql (2.17ms)15412026/07/21 08:17:12 goose: up to current file version: 215422026/07/21 08:17:12 INFO Received uploads request method=POST path=/api/pending_closures1543=== NAME TestOrphanedObjectsGC1544 orphaned_objects_gc_test.go:290: GC Test Summary:1545 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1546 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1547 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1548 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1549 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1550--- PASS: TestOrphanedObjectsGC (0.67s)1551=== CONT TestClientErrorHandling/ServerNotAvailable15522026/07/21 08:17:12 INFO Received uploads request method=POST path=/api/pending_closures1553--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)1554 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1555 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1556 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.34s)1557=== CONT TestClientErrorHandling/InvalidAuthToken1558=== NAME TestPinProtectsFromGC1559 client_integration_test.go:646: Pinned store path: /nix/var/nix/builds/nix-89852-3968335264/TestPinProtectsFromGC4198189518/001/store/9m1yx9sv38swpi2b0jc86i25ny96dc6s-pinned-file.txt1560 client_integration_test.go:647: Unpinned store path: /nix/var/nix/builds/nix-89852-3968335264/TestPinProtectsFromGC4198189518/001/store/6zshbvamdzl184x0sclz6ss4x7mcgwsd-unpinned-file.txt1561=== NAME TestClientMultipleUploads1562 client_integration_test.go:338: Created store path 1: /nix/var/nix/builds/nix-89852-3968335264/TestClientMultipleUploads2139641249/001/store/q1f52vzl9dw0q7wbg78vqhm44a2fy227-test-file-1.txt1563=== NAME TestClientWithDependencies1564 client_integration_test.go:593: Built derivation: /nix/var/nix/builds/nix-89852-3968335264/TestClientWithDependencies480979410/001/store/pivp2i3sis60rk077hbhdky2agwvzj60-test-script1565=== NAME TestClientMultipleUploads1566 client_integration_test.go:338: Created store path 2: /nix/var/nix/builds/nix-89852-3968335264/TestClientMultipleUploads2139641249/001/store/3nzdzz84pnl8p6289wfkb2cz5xr8xhg7-test-file-2.txt15672026-07-21 08:17:12.297 UTC [90238] ERROR: relation "goose_db_version" does not exist at character 3615682026-07-21 08:17:12.297 UTC [90238] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15692026/07/21 08:17:12 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1570=== NAME TestClientWithDependencies1571 client_integration_test.go:595: Found 1 dependencies (including self)15722026/07/21 08:17:12 OK 20241026095416_initial_model.sql (14.06ms)15732026/07/21 08:17:12 OK 20251210153512_drop_unused_gin_index.sql (813µs)15742026/07/21 08:17:12 OK 20251218171726_add_pins.sql (2.05ms)15752026/07/21 08:17:12 OK 20260628120000_add_object_size_and_stats.sql (5.09ms)15762026/07/21 08:17:12 goose: successfully migrated database to version: 2026062812000015772026/07/21 08:17:12 OK 1_commit_pending_closure.sql (1.13ms)15782026/07/21 08:17:12 OK 2_object_stats_trigger.sql (412.96µs)15792026/07/21 08:17:12 goose: up to current file version: 215802026/07/21 08:17:12 INFO Received uploads request method=POST path=/api/pending_closures15812026/07/21 08:17:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15822026/07/21 08:17:12 INFO Uploading 9m1yx9sv38swpi2b0jc86i25ny96dc6s-pinned-file.txt (128B)15832026/07/21 08:17:12 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"15842026/07/21 08:17:12 WARN Failed to register uploaded object key=9m1yx9sv38swpi2b0jc86i25ny96dc6s.ls error="server returned 404: 404 page not found\n"15852026/07/21 08:17:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15862026/07/21 08:17:12 INFO Signed narinfos id=1 count=115872026/07/21 08:17:12 INFO Uploading 1 narinfos15882026/07/21 08:17:12 WARN Failed to register uploaded object key=9m1yx9sv38swpi2b0jc86i25ny96dc6s.narinfo error="server returned 404: 404 page not found\n"15892026/07/21 08:17:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15902026/07/21 08:17:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15912026/07/21 08:17:12 INFO Completed upload id=115922026/07/21 08:17:12 INFO Upload complete. (116ms)15932026/07/21 08:17:12 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-config15942026/07/21 08:17:12 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YjU2MTk1ODItZjJiOC00ZTFiLThlYjUtOWQ2NzI5NTZlZTAyLjljOTI1OThiLTA4ODUtNDg3ZS05YjExLWY3NjE0OWZhN2E3NngxNzg0NjIxODMyMTg4MzU4MDAw parts=121595--- PASS: TestRedundantMultipartUpload (0.52s)1596=== CONT TestServerTLSConfig/no_client_CA1597=== CONT TestServerTLSConfig/not_a_PEM_file1598=== CONT TestServerTLSConfig/missing_CA_file1599--- PASS: TestServerTLSConfig (0.00s)1600 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1601 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1602 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1603=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token16042026/07/21 08:17:12 INFO OIDC auth successful provider=test1605=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1606=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected16072026/07/21 08:17:12 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]1608=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected16092026/07/21 08:17:12 WARN Authentication failed token_preview=eyJhbGciOi...l1PytF0nYw 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]1610=== CONT TestParseSingleRange/none1611=== CONT TestParseSingleRange/open-ended1612=== CONT TestParseSingleRange/start_far_past_EOF1613=== CONT TestParseSingleRange/start_past_EOF1614=== CONT TestParseSingleRange/single_byte1615=== CONT TestParseSingleRange/suffix_exceeds_size1616=== CONT TestParseSingleRange/suffix1617=== CONT TestParseSingleRange/end_clamped_to_size1618=== CONT TestParseSingleRange/malformed_both_empty1619=== CONT TestParseSingleRange/closed1620=== CONT TestParseSingleRange/malformed_end_before_start1621=== CONT TestParseSingleRange/multi-range_ignored1622=== CONT TestParseSingleRange/malformed_no_dash1623=== CONT TestParseSingleRange/unknown_unit1624--- PASS: TestParseSingleRange (0.00s)1625 --- PASS: TestParseSingleRange/none (0.00s)1626 --- PASS: TestParseSingleRange/open-ended (0.00s)1627 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1628 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1629 --- PASS: TestParseSingleRange/single_byte (0.00s)1630 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1631 --- PASS: TestParseSingleRange/suffix (0.00s)1632 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1633 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1634 --- PASS: TestParseSingleRange/closed (0.00s)1635 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1636 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1637 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1638 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1639=== CONT TestIsValidCachePath/narinfo1640=== CONT TestIsValidCachePath/index.html1641=== CONT TestIsValidCachePath/short_hash1642=== CONT TestIsValidCachePath/wrong_extension1643=== CONT TestIsValidCachePath/leading_slash1644=== CONT TestIsValidCachePath/empty1645=== CONT TestIsValidCachePath/random_path1646=== CONT TestIsValidCachePath/invalid_char_u1647=== CONT TestIsValidCachePath/invalid_char_e1648=== CONT TestIsValidCachePath/traversal_in_middle1649=== CONT TestIsValidCachePath/traversal_parent1650--- PASS: TestService_AuthMiddleware_OIDC (0.51s)1651 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1652 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1653 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1654 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1655=== CONT TestIsValidCachePath/nar_uncompressed1656=== CONT TestIsValidCachePath/nix-cache-info1657=== CONT TestIsValidCachePath/realisation1658=== CONT TestIsValidCachePath/log1659=== CONT TestIsValidCachePath/ls1660=== CONT TestIsValidCachePath/nar_xz1661=== CONT TestIsValidCachePath/nar_bz21662=== CONT TestIsValidCachePath/nar_zst1663=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1664--- PASS: TestIsValidCachePath (0.00s)1665 --- PASS: TestIsValidCachePath/narinfo (0.00s)1666 --- PASS: TestIsValidCachePath/index.html (0.00s)1667 --- PASS: TestIsValidCachePath/short_hash (0.00s)1668 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1669 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1670 --- PASS: TestIsValidCachePath/empty (0.00s)1671 --- PASS: TestIsValidCachePath/random_path (0.00s)1672 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1673 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1674 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1675 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1676 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1677 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1678 --- PASS: TestIsValidCachePath/realisation (0.00s)1679 --- PASS: TestIsValidCachePath/log (0.00s)1680 --- PASS: TestIsValidCachePath/ls (0.00s)1681 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1682 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1683 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1684 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)16852026-07-21 08:17:12.387 UTC [90254] ERROR: relation "goose_db_version" does not exist at character 3616862026-07-21 08:17:12.387 UTC [90254] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16872026/07/21 08:17:12 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16882026/07/21 08:17:12 OK 20241026095416_initial_model.sql (4.95ms)16892026/07/21 08:17:12 OK 20251210153512_drop_unused_gin_index.sql (607.83µs)1690=== NAME TestOrphanedObjectsGCStressTest1691 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains16922026/07/21 08:17:12 OK 20251218171726_add_pins.sql (1.09ms)16932026/07/21 08:17:12 OK 20260628120000_add_object_size_and_stats.sql (1.31ms)16942026/07/21 08:17:12 goose: successfully migrated database to version: 2026062812000016952026/07/21 08:17:12 OK 1_commit_pending_closure.sql (1.29ms)16962026/07/21 08:17:12 OK 2_object_stats_trigger.sql (271.33µs)16972026/07/21 08:17:12 goose: up to current file version: 21698 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion16992026/07/21 08:17:12 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17002026/07/21 08:17:12 INFO Received uploads request method=POST path=/api/pending_closures17012026/07/21 08:17:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17022026/07/21 08:17:12 INFO Uploading pivp2i3sis60rk077hbhdky2agwvzj60-test-script (136B)17032026/07/21 08:17:12 WARN Failed to register uploaded object key=log/zbd84qir8ibb3wpjsq55c9h1g9wb8d6q-test-script.drv error="server returned 404: 404 page not found\n"17042026/07/21 08:17:12 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"17052026/07/21 08:17:12 WARN Failed to register uploaded object key=pivp2i3sis60rk077hbhdky2agwvzj60.ls error="server returned 404: 404 page not found\n"17062026/07/21 08:17:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17072026/07/21 08:17:12 INFO Signed narinfos id=1 count=117082026/07/21 08:17:12 INFO Uploading 1 narinfos17092026/07/21 08:17:12 WARN Failed to register uploaded object key=pivp2i3sis60rk077hbhdky2agwvzj60.narinfo error="server returned 404: 404 page not found\n"17102026/07/21 08:17:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17112026/07/21 08:17:12 INFO Completed upload id=117122026/07/21 08:17:12 INFO Upload complete. (61ms)1713=== NAME TestClientWithDependencies1714 client_integration_test.go:597: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-89852-3968335264/TestClientWithDependencies480979410/001/store) requires matching store prefix1715--- PASS: TestClientWithDependencies (0.83s)17162026/07/21 08:17:12 INFO Received uploads request method=POST path=/api/pending_closures17172026/07/21 08:17:12 INFO Received uploads request method=POST path=/api/pending_closures17182026/07/21 08:17:12 INFO Received uploads request method=POST path=/api/pending_closures17192026/07/21 08:17:12 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)17202026/07/21 08:17:12 INFO Uploading q1f52vzl9dw0q7wbg78vqhm44a2fy227-test-file-1.txt (160B)17212026/07/21 08:17:12 INFO Uploading 3nzdzz84pnl8p6289wfkb2cz5xr8xhg7-test-file-2.txt (160B)17222026/07/21 08:17:12 INFO Uploading 66v6lhnf0aqwi8jqn73h23f82d7yaasi-test-file-0.txt (160B)17232026/07/21 08:17:12 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"17242026/07/21 08:17:12 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"17252026/07/21 08:17:12 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"17262026/07/21 08:17:12 WARN Failed to register uploaded object key=3nzdzz84pnl8p6289wfkb2cz5xr8xhg7.ls error="server returned 404: 404 page not found\n"17272026/07/21 08:17:12 WARN Failed to register uploaded object key=q1f52vzl9dw0q7wbg78vqhm44a2fy227.ls error="server returned 404: 404 page not found\n"17282026/07/21 08:17:12 WARN Failed to register uploaded object key=66v6lhnf0aqwi8jqn73h23f82d7yaasi.ls error="server returned 404: 404 page not found\n"17292026/07/21 08:17:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17302026/07/21 08:17:12 INFO Signed narinfos id=1 count=117312026/07/21 08:17:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign17322026/07/21 08:17:12 INFO Signed narinfos id=2 count=117332026/07/21 08:17:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign17342026/07/21 08:17:12 INFO Signed narinfos id=3 count=117352026/07/21 08:17:12 INFO Uploading 3 narinfos17362026/07/21 08:17:12 WARN Failed to register uploaded object key=q1f52vzl9dw0q7wbg78vqhm44a2fy227.narinfo error="server returned 404: 404 page not found\n"17372026/07/21 08:17:12 WARN Failed to register uploaded object key=66v6lhnf0aqwi8jqn73h23f82d7yaasi.narinfo error="server returned 404: 404 page not found\n"17382026/07/21 08:17:12 WARN Failed to register uploaded object key=3nzdzz84pnl8p6289wfkb2cz5xr8xhg7.narinfo error="server returned 404: 404 page not found\n"17392026/07/21 08:17:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17402026/07/21 08:17:12 INFO Completed upload id=117412026/07/21 08:17:12 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17422026/07/21 08:17:12 INFO Completed upload id=217432026/07/21 08:17:12 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete17442026/07/21 08:17:12 INFO Completed upload id=317452026/07/21 08:17:12 INFO Upload complete. (113ms)1746=== NAME TestClientMultipleUploads1747 client_integration_test.go:349: Uploaded 3 paths in 165.469083ms17482026/07/21 08:17:12 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1749--- PASS: TestClientMultipleUploads (0.67s)17502026/07/21 08:17:12 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=207.375748ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17512026/07/21 08:17:12 INFO Received uploads request method=POST path=/api/pending_closures17522026/07/21 08:17:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17532026/07/21 08:17:12 INFO Uploading 6zshbvamdzl184x0sclz6ss4x7mcgwsd-unpinned-file.txt (128B)17542026/07/21 08:17:12 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"17552026/07/21 08:17:12 WARN Failed to register uploaded object key=6zshbvamdzl184x0sclz6ss4x7mcgwsd.ls error="server returned 404: 404 page not found\n"17562026/07/21 08:17:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign17572026/07/21 08:17:12 INFO Signed narinfos id=2 count=117582026/07/21 08:17:12 INFO Uploading 1 narinfos17592026/07/21 08:17:12 WARN Failed to register uploaded object key=6zshbvamdzl184x0sclz6ss4x7mcgwsd.narinfo error="server returned 404: 404 page not found\n"17602026/07/21 08:17:12 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17612026/07/21 08:17:12 INFO Completed upload id=217622026/07/21 08:17:12 INFO Upload complete. (75ms)17632026/07/21 08:17:12 INFO Received create pin request method=POST path=/api/pins/myapp17642026/07/21 08:17:12 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-89852-3968335264/TestPinProtectsFromGC4198189518/001/store/9m1yx9sv38swpi2b0jc86i25ny96dc6s-pinned-file.txt narinfo_key=9m1yx9sv38swpi2b0jc86i25ny96dc6s.narinfo17652026/07/21 08:17:12 INFO Starting cleanup of old closures method=DELETE path=/api/closures17662026/07/21 08:17:12 INFO Garbage collection started1767=== NAME TestOrphanedObjectsGCStressTest1768 orphaned_objects_gc_test.go:509: Stress test completed successfully:1769 orphaned_objects_gc_test.go:510: - Active objects preserved: 201770 orphaned_objects_gc_test.go:511: - Objects deleted: 2101771 orphaned_objects_gc_test.go:512: - Total GC'd: 2101772--- PASS: TestOrphanedObjectsGCStressTest (1.16s)17732026/07/21 08:17:12 INFO Aborted multipart uploads count=017742026/07/21 08:17:12 WARN Force mode enabled - objects will be deleted immediately without grace period17752026/07/21 08:17:12 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17762026/07/21 08:17:12 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2469 objects_failed=01777=== NAME TestClientIntegration1778 client_integration_test.go:303: Objects in database after GC:1779 client_integration_test.go:303: Successfully deleted all objects with GC --force1780--- PASS: TestClientIntegration (2.73s)17812026/07/21 08:17:12 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"17822026/07/21 08:17:12 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=383.449775ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17832026/07/21 08:17:12 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=017842026/07/21 08:17:12 INFO Vacuumed table table=pending_closures17852026/07/21 08:17:12 INFO Vacuumed table table=pending_objects17862026/07/21 08:17:12 INFO Vacuumed table table=multipart_uploads17872026/07/21 08:17:12 INFO Vacuumed table table=closures17882026/07/21 08:17:12 INFO Vacuumed table table=objects17892026/07/21 08:17:13 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=818.55229ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17902026/07/21 08:17:13 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.68415182s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17912026/07/21 08:17:14 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01792=== NAME TestPinProtectsFromGC1793 client_integration_test.go:709: Pin successfully protected closure from garbage collection1794--- PASS: TestPinProtectsFromGC (2.77s)17952026/07/21 08:17:15 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"17962026/07/21 08:17:15 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_closures17972026/07/21 08:17:15 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=192.29579ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures17982026/07/21 08:17:15 WARN Rate limiter enabled after throttle name=s3-test rate=517992026/07/21 08:17:15 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1800=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1801 throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=101802 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001803--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.88s)18042026/07/21 08:17:15 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=414.507702ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures18052026/07/21 08:17:16 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=844.8602ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures18062026/07/21 08:17:17 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.75918996s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1807--- PASS: TestClientErrorHandling (0.00s)1808 --- PASS: TestClientErrorHandling/InvalidStorePath (0.34s)1809 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.37s)1810 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.74s)1811PASS18122026-07-21 08:17:19.487 UTC [89903] LOG: received smart shutdown request18132026-07-21 08:17:19.488 UTC [89903] LOG: background worker "logical replication launcher" (PID 89913) exited with exit code 118142026-07-21 08:17:19.490 UTC [89908] LOG: shutting down18152026-07-21 08:17:19.490 UTC [89908] LOG: checkpoint starting: shutdown immediate18162026-07-21 08:17:20.678 UTC [89908] LOG: checkpoint complete: wrote 12774 buffers (78.0%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 13 recycled; write=0.763 s, sync=0.422 s, total=1.188 s; sync files=15167, longest=0.001 s, average=0.001 s; distance=212068 kB, estimate=212068 kB; lsn=0/E69E5A0, redo lsn=0/E69E5A018172026-07-21 08:17:20.686 UTC [89903] LOG: database system is shut down1818Running OIDC tests...1819=== RUN TestGlobMatch1820=== PAUSE TestGlobMatch1821=== RUN TestAudienceForIssuer1822=== PAUSE TestAudienceForIssuer1823=== RUN TestValidateToken_ValidToken1824=== PAUSE TestValidateToken_ValidToken1825=== RUN TestValidateToken_WrongAudience1826=== PAUSE TestValidateToken_WrongAudience1827=== RUN TestValidateToken_Expired1828=== PAUSE TestValidateToken_Expired1829=== RUN TestValidateToken_BoundClaimsMismatch1830=== PAUSE TestValidateToken_BoundClaimsMismatch1831=== RUN TestValidateToken_BoundSubjectMismatch1832=== PAUSE TestValidateToken_BoundSubjectMismatch1833=== RUN TestValidateToken_MultipleProviders1834=== PAUSE TestValidateToken_MultipleProviders1835=== RUN TestValidateToken_NoMatchingProvider1836=== PAUSE TestValidateToken_NoMatchingProvider1837=== CONT TestGlobMatch1838=== RUN TestGlobMatch/foo_foo1839=== PAUSE TestGlobMatch/foo_foo1840=== RUN TestGlobMatch/foo_bar1841=== PAUSE TestGlobMatch/foo_bar1842=== RUN TestGlobMatch/*_1843=== PAUSE TestGlobMatch/*_1844=== RUN TestGlobMatch/*_anything1845=== PAUSE TestGlobMatch/*_anything1846=== RUN TestGlobMatch/foo*_foo1847=== PAUSE TestGlobMatch/foo*_foo1848=== RUN TestGlobMatch/foo*_foobar1849=== PAUSE TestGlobMatch/foo*_foobar1850=== RUN TestGlobMatch/foo*_bar1851=== PAUSE TestGlobMatch/foo*_bar1852=== RUN TestGlobMatch/*bar_bar1853=== PAUSE TestGlobMatch/*bar_bar1854=== RUN TestGlobMatch/*bar_foobar1855=== PAUSE TestGlobMatch/*bar_foobar1856=== RUN TestGlobMatch/*bar_foo1857=== PAUSE TestGlobMatch/*bar_foo1858=== RUN TestGlobMatch/foo*bar_foobar1859=== PAUSE TestGlobMatch/foo*bar_foobar1860=== RUN TestGlobMatch/foo*bar_foo123bar1861=== PAUSE TestGlobMatch/foo*bar_foo123bar1862=== RUN TestGlobMatch/foo*bar_foobarbaz1863=== PAUSE TestGlobMatch/foo*bar_foobarbaz1864=== RUN TestGlobMatch/*/*_foo/bar1865=== PAUSE TestGlobMatch/*/*_foo/bar1866=== RUN TestGlobMatch/*/*_foo1867=== PAUSE TestGlobMatch/*/*_foo1868=== CONT TestValidateToken_BoundClaimsMismatch1869=== RUN TestGlobMatch/refs/heads/*_refs/heads/main1870=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main1871=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.01872=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.01873=== RUN TestGlobMatch/refs/*/main_refs/heads/main1874=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main1875=== RUN TestGlobMatch/fo?_foo1876=== PAUSE TestGlobMatch/fo?_foo1877=== RUN TestGlobMatch/fo?_fo1878=== PAUSE TestGlobMatch/fo?_fo1879=== RUN TestGlobMatch/fo?_fooo1880=== PAUSE TestGlobMatch/fo?_fooo1881=== RUN TestGlobMatch/?oo_foo1882=== PAUSE TestGlobMatch/?oo_foo1883=== RUN TestGlobMatch/?oo_boo1884=== PAUSE TestGlobMatch/?oo_boo1885=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1886=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1887=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1888=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1889=== CONT TestGlobMatch/foo_foo1890=== CONT TestValidateToken_Expired1891=== CONT TestGlobMatch/*/*_foo1892=== CONT TestValidateToken_WrongAudience1893=== CONT TestValidateToken_ValidToken1894=== CONT TestGlobMatch/foo*_foo1895=== CONT TestGlobMatch/*bar_bar1896=== CONT TestValidateToken_MultipleProviders1897=== CONT TestGlobMatch/*_anything1898=== CONT TestValidateToken_NoMatchingProvider1899=== CONT TestGlobMatch/foo*_foobar1900=== CONT TestGlobMatch/fo?_fooo1901=== CONT TestAudienceForIssuer1902--- PASS: TestAudienceForIssuer (0.00s)1903=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1904=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1905=== CONT TestGlobMatch/?oo_boo1906=== CONT TestGlobMatch/?oo_foo1907=== CONT TestGlobMatch/refs/*/main_refs/heads/main1908=== CONT TestGlobMatch/fo?_fo1909=== CONT TestGlobMatch/fo?_foo1910=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.01911=== CONT TestValidateToken_BoundSubjectMismatch1912=== CONT TestGlobMatch/foo*_bar1913=== CONT TestGlobMatch/foo*bar_foo123bar1914=== CONT TestGlobMatch/*/*_foo/bar1915=== CONT TestGlobMatch/foo*bar_foobarbaz1916=== CONT TestGlobMatch/*bar_foo1917=== CONT TestGlobMatch/foo*bar_foobar1918=== CONT TestGlobMatch/refs/heads/*_refs/heads/main1919=== CONT TestGlobMatch/*bar_foobar1920=== CONT TestGlobMatch/foo_bar1921=== CONT TestGlobMatch/*_1922--- PASS: TestGlobMatch (0.00s)1923 --- PASS: TestGlobMatch/foo_foo (0.00s)1924 --- PASS: TestGlobMatch/*/*_foo (0.00s)1925 --- PASS: TestGlobMatch/foo*_foo (0.00s)1926 --- PASS: TestGlobMatch/*bar_bar (0.00s)1927 --- PASS: TestGlobMatch/*_anything (0.00s)1928 --- PASS: TestGlobMatch/foo*_foobar (0.00s)1929 --- PASS: TestGlobMatch/fo?_fooo (0.00s)1930 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)1931 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)1932 --- PASS: TestGlobMatch/?oo_boo (0.00s)1933 --- PASS: TestGlobMatch/?oo_foo (0.00s)1934 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)1935 --- PASS: TestGlobMatch/fo?_fo (0.00s)1936 --- PASS: TestGlobMatch/fo?_foo (0.00s)1937 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)1938 --- PASS: TestGlobMatch/foo*_bar (0.00s)1939 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)1940 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)1941 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)1942 --- PASS: TestGlobMatch/*bar_foo (0.00s)1943 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)1944 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)1945 --- PASS: TestGlobMatch/*bar_foobar (0.00s)1946 --- PASS: TestGlobMatch/foo_bar (0.00s)1947 --- PASS: TestGlobMatch/*_ (0.00s)19482026/07/21 08:17:22 INFO OIDC provider initialized name=provider119492026/07/21 08:17:22 INFO OIDC provider initialized name=test19502026/07/21 08:17:22 INFO OIDC provider initialized name=test19512026/07/21 08:17:22 INFO OIDC provider initialized name=test1952--- PASS: TestValidateToken_NoMatchingProvider (0.00s)19532026/07/21 08:17:22 INFO OIDC provider initialized name=test19542026/07/21 08:17:22 INFO OIDC provider initialized name=provider119552026/07/21 08:17:22 INFO OIDC provider initialized name=test1956--- PASS: TestValidateToken_WrongAudience (0.01s)1957--- PASS: TestValidateToken_Expired (0.01s)1958--- PASS: TestValidateToken_ValidToken (0.01s)19592026/07/21 08:17:22 INFO OIDC provider initialized name=provider21960--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)1961--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)1962--- PASS: TestValidateToken_MultipleProviders (0.01s)1963PASS1964Running hook tests...1965=== RUN TestSendPathsEmpty1966=== PAUSE TestSendPathsEmpty1967=== RUN TestQueueEnqueueAndFetch1968=== PAUSE TestQueueEnqueueAndFetch1969=== RUN TestQueueDeduplication1970=== PAUSE TestQueueDeduplication1971=== RUN TestQueueRemove1972=== PAUSE TestQueueRemove1973=== RUN TestQueueFetchBatchLimit1974=== PAUSE TestQueueFetchBatchLimit1975=== RUN TestQueueFetchRemoveLifecycle1976=== PAUSE TestQueueFetchRemoveLifecycle1977=== RUN TestQueueConcurrentWriters1978=== PAUSE TestQueueConcurrentWriters1979=== RUN TestServerClientIntegration1980=== PAUSE TestServerClientIntegration1981=== RUN TestServerQueueError1982=== PAUSE TestServerQueueError1983=== RUN TestGetListenerSocketActivation1984 server_test.go:210: === RUN TestGetListenerSocketActivation1985 --- PASS: TestGetListenerSocketActivation (0.00s)1986 PASS1987 1988--- PASS: TestGetListenerSocketActivation (0.02s)1989=== RUN TestWorkerUploadsAndRemoves1990=== PAUSE TestWorkerUploadsAndRemoves1991=== RUN TestWorkerSkipsGCdPaths1992=== PAUSE TestWorkerSkipsGCdPaths1993=== RUN TestWorkerPrunesClosureDeps1994=== PAUSE TestWorkerPrunesClosureDeps1995=== CONT TestSendPathsEmpty1996--- PASS: TestSendPathsEmpty (0.00s)1997=== CONT TestWorkerPrunesClosureDeps1998=== CONT TestQueueConcurrentWriters1999=== CONT TestQueueRemove2000=== CONT TestWorkerSkipsGCdPaths2001=== CONT TestWorkerUploadsAndRemoves2002=== CONT TestServerQueueError2003=== CONT TestQueueDeduplication20042026/07/21 08:17:23 ERROR Failed to queue paths error="permission denied" count=12005=== CONT TestQueueFetchRemoveLifecycle2006=== CONT TestQueueFetchBatchLimit2007--- PASS: TestServerQueueError (0.00s)2008=== CONT TestQueueEnqueueAndFetch2009=== CONT TestServerClientIntegration2010--- PASS: TestServerClientIntegration (0.00s)20112026/07/21 08:17:23 INFO Upload queue status pending=220122026/07/21 08:17:23 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-89852-3968335264/TestWorkerSkipsGCdPaths2437941328/002/nonexistent2013--- PASS: TestQueueRemove (0.01s)2014--- PASS: TestQueueDeduplication (0.00s)2015--- PASS: TestQueueEnqueueAndFetch (0.00s)20162026/07/21 08:17:23 INFO Upload queue status pending=220172026/07/21 08:17:23 INFO Uploading batch count=220182026/07/21 08:17:23 INFO Uploading batch count=120192026/07/21 08:17:23 INFO Upload queue status pending=220202026/07/21 08:17:23 INFO Uploading batch count=12021--- PASS: TestQueueFetchBatchLimit (0.01s)2022--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2023--- PASS: TestWorkerSkipsGCdPaths (0.06s)2024--- PASS: TestWorkerUploadsAndRemoves (0.06s)2025--- PASS: TestWorkerPrunesClosureDeps (0.06s)2026--- PASS: TestQueueConcurrentWriters (0.08s)2027PASS