niks3-go-unit-tests
aarch64-darwin.go-unit-tests
· build #103
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestCaseHackSuffix5=== PAUSE TestCaseHackSuffix6=== RUN TestPartSizeForNAR7=== PAUSE TestPartSizeForNAR8=== RUN TestUploadMultipart_SupersededByPeer9=== PAUSE TestUploadMultipart_SupersededByPeer10=== RUN TestDumpPathMatchesNix11=== PAUSE TestDumpPathMatchesNix12=== RUN TestDumpPathSingleFile13=== PAUSE TestDumpPathSingleFile14=== RUN TestDumpPathWriterError15=== PAUSE TestDumpPathWriterError16=== RUN TestEncodeNixBase3217=== PAUSE TestEncodeNixBase3218=== RUN TestEncodeNixBase32WithRealHash19=== PAUSE TestEncodeNixBase32WithRealHash20=== RUN TestConvertHashToNix3221=== PAUSE TestConvertHashToNix3222=== RUN TestGetStorePathHash23=== PAUSE TestGetStorePathHash24=== RUN TestPathInfoHashCompatibility25=== PAUSE TestPathInfoHashCompatibility26=== RUN TestParsePathInfoJSON27=== PAUSE TestParsePathInfoJSON28=== RUN TestParsePathInfoJSONMultiplePaths29=== PAUSE TestParsePathInfoJSONMultiplePaths30=== RUN TestPathInfoCACompatibility31=== PAUSE TestPathInfoCACompatibility32=== RUN TestRateLimiterFeedback33=== PAUSE TestRateLimiterFeedback34=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess35=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess36=== RUN TestResolveStorePath37=== PAUSE TestResolveStorePath38=== RUN TestDoWithRetry_BodyReplayedViaGetBody39=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody40=== RUN TestShellSplit41=== PAUSE TestShellSplit42=== RUN TestShellSplitErrors43=== PAUSE TestShellSplitErrors44=== RUN TestSetClientTLS45=== PAUSE TestSetClientTLS46=== RUN TestSetClientTLSDoesNotMutateDefaultTransport47=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport48=== RUN TestSetClientTLSErrors49=== PAUSE TestSetClientTLSErrors50=== RUN TestStaticToken51=== PAUSE TestStaticToken52=== RUN TestFileTokenReadsAndCaches53=== PAUSE TestFileTokenReadsAndCaches54=== RUN TestFileTokenMissing55=== PAUSE TestFileTokenMissing56=== RUN TestFileTokenEmpty57=== PAUSE TestFileTokenEmpty58=== RUN TestScriptTokenNoExpiryRerunsEveryCall59=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall60=== RUN TestScriptTokenCachesUntilRefresh61=== PAUSE TestScriptTokenCachesUntilRefresh62=== RUN TestScriptTokenEmptyToken63=== PAUSE TestScriptTokenEmptyToken64=== RUN TestScriptTokenBadJSON65=== PAUSE TestScriptTokenBadJSON66=== RUN TestScriptTokenScriptFails67=== PAUSE TestScriptTokenScriptFails68=== RUN TestScriptTokenEmptyCommand69=== PAUSE TestScriptTokenEmptyCommand70=== CONT TestDoServerRequestAttachesToken71=== CONT TestScriptTokenEmptyCommand72=== CONT TestScriptTokenScriptFails73=== CONT TestStaticToken74=== CONT TestScriptTokenBadJSON75=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess76=== CONT TestEncodeNixBase32WithRealHash77=== CONT TestRateLimiterFeedback78=== RUN TestRateLimiterFeedback/429_enables_limiter79=== PAUSE TestRateLimiterFeedback/429_enables_limiter80=== CONT TestShellSplitErrors81=== CONT TestSetClientTLSErrors822026/07/19 09:48:49 WARN Rate limiter enabled after throttle name=server-test rate=583=== CONT TestSetClientTLSDoesNotMutateDefaultTransport84=== CONT TestSetClientTLS85=== CONT TestShellSplit86=== RUN TestRateLimiterFeedback/503_enables_limiter87=== PAUSE TestRateLimiterFeedback/503_enables_limiter88--- PASS: TestScriptTokenEmptyCommand (0.00s)89=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter90=== CONT TestScriptTokenNoExpiryRerunsEveryCall91=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter92=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter93=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter94=== CONT TestScriptTokenEmptyToken95--- PASS: TestStaticToken (0.00s)96--- PASS: TestEncodeNixBase32WithRealHash (0.00s)97--- PASS: TestShellSplitErrors (0.00s)98--- PASS: TestShellSplit (0.00s)99=== CONT TestResolveStorePath100--- PASS: TestDoServerRequestAttachesToken (0.01s)101=== CONT TestScriptTokenCachesUntilRefresh102--- PASS: TestResolveStorePath (0.00s)103=== CONT TestDumpPathMatchesNix104=== RUN TestSetClientTLSErrors/missing_cert_file105=== PAUSE TestSetClientTLSErrors/missing_cert_file106=== RUN TestSetClientTLSErrors/missing_key_file107=== PAUSE TestSetClientTLSErrors/missing_key_file108=== RUN TestSetClientTLSErrors/missing_ca_file109=== PAUSE TestSetClientTLSErrors/missing_ca_file110=== RUN TestSetClientTLSErrors/invalid_ca_file111=== PAUSE TestSetClientTLSErrors/invalid_ca_file112=== CONT TestEncodeNixBase32113=== RUN TestEncodeNixBase32/test_string_hash114=== PAUSE TestEncodeNixBase32/test_string_hash115=== RUN TestEncodeNixBase32/empty_input116=== PAUSE TestEncodeNixBase32/empty_input117=== CONT TestDumpPathWriterError118--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)119=== CONT TestDumpPathSingleFile120--- PASS: TestScriptTokenScriptFails (0.01s)121=== CONT TestFileTokenMissing122=== RUN TestSetClientTLS/rejects_connection_without_client_cert123=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert124=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA125=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA126=== RUN TestSetClientTLS/preserves_debug_logging_transport127=== PAUSE TestSetClientTLS/preserves_debug_logging_transport128=== CONT TestFileTokenEmpty129--- PASS: TestFileTokenMissing (0.00s)130=== CONT TestPartSizeForNAR131=== RUN TestPartSizeForNAR/zero_stays_at_minimum132=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum133=== RUN TestPartSizeForNAR/small_stays_at_minimum134=== PAUSE TestPartSizeForNAR/small_stays_at_minimum135=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum136=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum137=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts138=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts139=== RUN TestPartSizeForNAR/1_TiB140=== PAUSE TestPartSizeForNAR/1_TiB141=== RUN TestPartSizeForNAR/5_TiB_S3_max_object142=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object143=== RUN TestPartSizeForNAR/capped_at_5_GiB144=== PAUSE TestPartSizeForNAR/capped_at_5_GiB145=== CONT TestUploadMultipart_SupersededByPeer146=== RUN TestUploadMultipart_SupersededByPeer/exists147=== PAUSE TestUploadMultipart_SupersededByPeer/exists148=== RUN TestUploadMultipart_SupersededByPeer/missing149=== PAUSE TestUploadMultipart_SupersededByPeer/missing150=== CONT TestFileTokenReadsAndCaches151--- PASS: TestFileTokenEmpty (0.00s)152=== CONT TestCaseHackSuffix153--- PASS: TestFileTokenReadsAndCaches (0.00s)154=== CONT TestPathInfoHashCompatibility155=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)156=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)157=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon158=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon159=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI160=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI161=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512162=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512163=== CONT TestPathInfoCACompatibility164=== RUN TestPathInfoCACompatibility/null_ca_field165=== PAUSE TestPathInfoCACompatibility/null_ca_field166=== RUN TestPathInfoCACompatibility/old_string_format_-_text167=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text168=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive169=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive170=== RUN TestPathInfoCACompatibility/new_structured_format_-_text171=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text172=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method173=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method174=== CONT TestParsePathInfoJSONMultiplePaths175=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths176=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths177=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths178=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths179=== CONT TestParsePathInfoJSON180=== RUN TestParsePathInfoJSON/Nix_format181=== PAUSE TestParsePathInfoJSON/Nix_format182=== RUN TestParsePathInfoJSON/Lix_format183=== PAUSE TestParsePathInfoJSON/Lix_format184=== RUN TestParsePathInfoJSON/empty_input185=== PAUSE TestParsePathInfoJSON/empty_input186=== RUN TestParsePathInfoJSON/whitespace_only187=== PAUSE TestParsePathInfoJSON/whitespace_only188=== RUN TestParsePathInfoJSON/invalid_JSON189=== PAUSE TestParsePathInfoJSON/invalid_JSON190=== CONT TestConvertHashToNix32191=== RUN TestConvertHashToNix32/SRI_format_to_Nix32192=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32193=== RUN TestConvertHashToNix32/already_Nix32_format194=== PAUSE TestConvertHashToNix32/already_Nix32_format195=== RUN TestConvertHashToNix32/invalid_format196=== PAUSE TestConvertHashToNix32/invalid_format197=== CONT TestGetStorePathHash198=== RUN TestGetStorePathHash/valid_store_path199=== PAUSE TestGetStorePathHash/valid_store_path200=== RUN TestGetStorePathHash/basename_without_hyphen_should_error201=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error202=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error203=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error204=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error205=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error206=== CONT TestDoWithRetry_BodyReplayedViaGetBody2072026/07/19 09:48:49 WARN Rate limiter enabled after throttle name=server-test rate=52082026/07/19 09:48:49 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:587652092026/07/19 09:48:49 WARN Rate limiter backed off name=server-test rate=52102026/07/19 09:48:49 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:58765211--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)212=== CONT TestRateLimiterFeedback/429_enables_limiter2132026/07/19 09:48:49 WARN Rate limiter enabled after throttle name=server-test rate=52142026/07/19 09:48:49 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:587672152026/07/19 09:48:49 WARN Rate limiter backed off name=server-test rate=5216=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter217=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter218=== CONT TestRateLimiterFeedback/503_enables_limiter2192026/07/19 09:48:49 WARN Rate limiter enabled after throttle name=server-test rate=52202026/07/19 09:48:49 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:58773221--- PASS: TestScriptTokenBadJSON (0.02s)222=== CONT TestSetClientTLSErrors/missing_cert_file223=== CONT TestSetClientTLSErrors/missing_ca_file2242026/07/19 09:48:49 WARN Rate limiter backed off name=server-test rate=5225=== CONT TestSetClientTLSErrors/invalid_ca_file226--- PASS: TestRateLimiterFeedback (0.00s)227 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)228 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)229 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)230 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)231=== CONT TestSetClientTLSErrors/missing_key_file232=== CONT TestEncodeNixBase32/test_string_hash233=== CONT TestEncodeNixBase32/empty_input234--- PASS: TestEncodeNixBase32 (0.00s)235 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)236 --- PASS: TestEncodeNixBase32/empty_input (0.00s)237=== CONT TestSetClientTLS/rejects_connection_without_client_cert238=== CONT TestSetClientTLS/preserves_debug_logging_transport239--- PASS: TestScriptTokenEmptyToken (0.02s)240=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA241--- PASS: TestSetClientTLSErrors (0.01s)242 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)243 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)244 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)245 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)246=== CONT TestPartSizeForNAR/zero_stays_at_minimum247=== CONT TestUploadMultipart_SupersededByPeer/exists248=== CONT TestPartSizeForNAR/capped_at_5_GiB249=== CONT TestPartSizeForNAR/5_TiB_S3_max_object250=== CONT TestPartSizeForNAR/1_TiB251=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts252=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum253=== CONT TestPartSizeForNAR/small_stays_at_minimum254--- PASS: TestPartSizeForNAR (0.00s)255 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)256 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)257 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)258 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)259 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)260 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)261 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)262=== CONT TestUploadMultipart_SupersededByPeer/missing263=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)264=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI265=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512266=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon267--- PASS: TestPathInfoHashCompatibility (0.00s)268 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)269 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)270 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)271 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)272=== CONT TestPathInfoCACompatibility/null_ca_field273=== CONT TestPathInfoCACompatibility/new_structured_format_-_text274--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)275 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)276 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)277=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method278=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive279=== CONT TestPathInfoCACompatibility/old_string_format_-_text280--- PASS: TestPathInfoCACompatibility (0.00s)281 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)282 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)283 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)284 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)285 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)286=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths287=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths288=== CONT TestParsePathInfoJSON/Nix_format289--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)290 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)291 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)292=== CONT TestParsePathInfoJSON/invalid_JSON293=== CONT TestParsePathInfoJSON/whitespace_only294=== CONT TestParsePathInfoJSON/empty_input295=== CONT TestConvertHashToNix32/SRI_format_to_Nix32296=== CONT TestParsePathInfoJSON/Lix_format297=== CONT TestConvertHashToNix32/invalid_format298=== CONT TestConvertHashToNix32/already_Nix32_format299--- PASS: TestConvertHashToNix32 (0.00s)300 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)301 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)302 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)303=== CONT TestGetStorePathHash/valid_store_path304=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error305=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error306--- PASS: TestParsePathInfoJSON (0.00s)307 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)308 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)309 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)310 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)311 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)312=== CONT TestGetStorePathHash/basename_without_hyphen_should_error313--- PASS: TestGetStorePathHash (0.00s)314 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)315 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)316 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)317 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)3182026/07/19 09:48:49 http: TLS handshake error from 127.0.0.1:58775: remote error: tls: bad certificate319--- PASS: TestSetClientTLS (0.01s)320 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)321 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)322 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)323--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)324--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)325--- PASS: TestDumpPathWriterError (0.04s)326--- PASS: TestDumpPathSingleFile (0.06s)327--- PASS: TestCaseHackSuffix (0.06s)328--- PASS: TestDumpPathMatchesNix (0.07s)329--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)330PASS331Running server tests...332The files belonging to this database system will be owned by user "_nixbld1".333This user must also own the server process.334335The database cluster will be initialized with locale "C".336The default database encoding has accordingly been set to "SQL_ASCII".337The default text search configuration will be set to "english".338339Data page checksums are enabled.340341creating directory /nix/var/nix/builds/nix-88293-4258547180/postgres2800135135/data ... ok342creating subdirectories ... ok343selecting dynamic shared memory implementation ... posix344selecting default "max_connections" ... 100345selecting default "shared_buffers" ... 128MB346selecting default time zone ... UTC347creating configuration files ... ok348running bootstrap script ... ok349performing post-bootstrap initialization ... ok350syncing data to disk ... ok351352initdb: warning: enabling "trust" authentication for local connections353initdb: 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.354355Success. You can now start the database server using:356357 pg_ctl -D /nix/var/nix/builds/nix-88293-4258547180/postgres2800135135/data -l logfile start358359/nix/var/nix/builds/nix-88293-4258547180/postgres2800135135:5432 - no response3602026-07-19 09:48:51.512 UTC [88329] LOG: starting PostgreSQL 18.4 on aarch64-apple-darwin25.3.0, compiled by clang version 21.1.8, 64-bit3612026-07-19 09:48:51.512 UTC [88329] LOG: listening on Unix socket "/nix/var/nix/builds/nix-88293-4258547180/postgres2800135135/.s.PGSQL.5432"3622026-07-19 09:48:51.514 UTC [88336] LOG: database system was shut down at 2026-07-19 09:48:51 UTC3632026-07-19 09:48:51.515 UTC [88329] LOG: database system is ready to accept connections364/nix/var/nix/builds/nix-88293-4258547180/postgres2800135135:5432 - accepting connections365<jemalloc>: option background_thread currently supports pthread only366{"timestamp":"2026-07-19T09:48:51.6402Z","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(7)"}367=== RUN TestService_AuthMiddleware368=== PAUSE TestService_AuthMiddleware369=== RUN TestService_AuthMiddleware_MTLSProxyHeader370=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader371=== RUN TestService_AuthMiddleware_MTLSBoundSubjects372=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects373=== RUN TestService_ReadAuthMiddleware374=== PAUSE TestService_ReadAuthMiddleware375=== RUN TestService_AuthMiddleware_OIDC376=== PAUSE TestService_AuthMiddleware_OIDC377=== RUN TestCacheConfigHandler378=== PAUSE TestCacheConfigHandler379=== RUN TestCacheStatsHandler380=== PAUSE TestCacheStatsHandler381=== RUN TestClientCADerivations382=== PAUSE TestClientCADerivations383=== RUN TestClientErrorHandling384=== PAUSE TestClientErrorHandling385=== RUN TestClientIntegration386=== PAUSE TestClientIntegration387=== RUN TestClientMultipleUploads388=== PAUSE TestClientMultipleUploads389=== RUN TestClientWithDependencies390=== PAUSE TestClientWithDependencies391=== RUN TestPinProtectsFromGC392=== PAUSE TestPinProtectsFromGC393=== RUN TestGCAdvisoryLockBlocksConcurrentRun3942026-07-19 09:48:51.784 UTC [88387] ERROR: relation "goose_db_version" does not exist at character 363952026-07-19 09:48:51.784 UTC [88387] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC3962026/07/19 09:48:51 OK 20241026095416_initial_model.sql (3.18ms)3972026/07/19 09:48:51 OK 20251210153512_drop_unused_gin_index.sql (451.79µs)3982026/07/19 09:48:51 OK 20251218171726_add_pins.sql (734.17µs)3992026/07/19 09:48:51 OK 20260628120000_add_object_size_and_stats.sql (820.38µs)4002026/07/19 09:48:51 goose: successfully migrated database to version: 202606281200004012026/07/19 09:48:51 OK 1_commit_pending_closure.sql (812.79µs)4022026/07/19 09:48:51 OK 2_object_stats_trigger.sql (225.04µs)4032026/07/19 09:48:51 goose: up to current file version: 2404--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.07s)405=== RUN TestGCBugBareHashReferences406=== PAUSE TestGCBugBareHashReferences407=== RUN TestGCMetrics408=== PAUSE TestGCMetrics409=== RUN TestGCTaskStore_StartNew410=== PAUSE TestGCTaskStore_StartNew411=== RUN TestGCTaskStore_DeduplicateSameParams412=== PAUSE TestGCTaskStore_DeduplicateSameParams413=== RUN TestGCTaskStore_ConflictDifferentParams414=== PAUSE TestGCTaskStore_ConflictDifferentParams415=== RUN TestGCTaskStore_GetEmpty416=== PAUSE TestGCTaskStore_GetEmpty417=== RUN TestGCTaskStore_GetReturnsLatest418=== PAUSE TestGCTaskStore_GetReturnsLatest419=== RUN TestGCTaskStore_CompletedAllowsNewTask420=== PAUSE TestGCTaskStore_CompletedAllowsNewTask421=== RUN TestGCTaskStore_PhaseUpdates422=== PAUSE TestGCTaskStore_PhaseUpdates423=== RUN TestGCTaskStore_Fail424=== PAUSE TestGCTaskStore_Fail425=== RUN TestGracefulShutdownDrainsInflight426=== PAUSE TestGracefulShutdownDrainsInflight427=== RUN TestService_healthCheckHandler428=== PAUSE TestService_healthCheckHandler429=== RUN TestGenerateLandingPage430=== PAUSE TestGenerateLandingPage431=== RUN TestNARDeduplicationMetadataUploadBug432=== PAUSE TestNARDeduplicationMetadataUploadBug433=== RUN TestMetricsInventory434=== PAUSE TestMetricsInventory435=== RUN TestService_NativeMTLS436=== PAUSE TestService_NativeMTLS437=== RUN TestServerTLSConfig438=== PAUSE TestServerTLSConfig439=== RUN TestMultipartCleanup440=== PAUSE TestMultipartCleanup441=== RUN TestObjectStatsTrigger442=== PAUSE TestObjectStatsTrigger443=== RUN TestOrphanedObjectsGC444=== PAUSE TestOrphanedObjectsGC445=== RUN TestOrphanedObjectsGCStressTest446=== PAUSE TestOrphanedObjectsGCStressTest447=== RUN TestResurrectedObjectNotDeleted448=== PAUSE TestResurrectedObjectNotDeleted449=== RUN TestParseSingleRange450=== PAUSE TestParseSingleRange451=== RUN TestIsValidCachePath452=== PAUSE TestIsValidCachePath453=== RUN TestReadProxyNarinfo454=== PAUSE TestReadProxyNarinfo455=== RUN TestReadProxyNarinfoAlreadyDecompressed456=== PAUSE TestReadProxyNarinfoAlreadyDecompressed457=== RUN TestReadProxyNarStreaming458=== PAUSE TestReadProxyNarStreaming459=== RUN TestReadProxy404460=== PAUSE TestReadProxy404461=== RUN TestReadProxyInvalidPath462=== PAUSE TestReadProxyInvalidPath463=== RUN TestReadProxyHead464=== PAUSE TestReadProxyHead465=== RUN TestReadProxyConditionalGet466=== PAUSE TestReadProxyConditionalGet467=== RUN TestReadProxyRootRedirectsToIndexHTML468=== PAUSE TestReadProxyRootRedirectsToIndexHTML469=== RUN TestReadProxyDisabled470=== PAUSE TestReadProxyDisabled471=== RUN TestReadProxyRangeRequest472=== PAUSE TestReadProxyRangeRequest473=== RUN TestRedundantMultipartUpload474=== PAUSE TestRedundantMultipartUpload475=== RUN TestCompleteMultipartUpload_ErrorButObjectExists476=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists477=== RUN TestCompletedNarNotReofferedAcrossClosures478=== PAUSE TestCompletedNarNotReofferedAcrossClosures479=== RUN TestPresignedUploadRegisteredBeforeCommit480=== PAUSE TestPresignedUploadRegisteredBeforeCommit481=== RUN TestService_Rustfstest482=== PAUSE TestService_Rustfstest483=== RUN TestSystemdListenerNotActivated484--- PASS: TestSystemdListenerNotActivated (0.00s)485=== RUN TestWatchdogBeatsWhenHealthy486--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)487=== RUN TestWatchdogSkipsWhenUnhealthy4882026/07/19 09:48:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"4892026/07/19 09:48:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"4902026/07/19 09:48:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"4912026/07/19 09:48:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"4922026/07/19 09:48:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"4932026/07/19 09:48:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"4942026/07/19 09:48:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"4952026/07/19 09:48:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"4962026/07/19 09:48:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"497--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)498=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle499=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle500=== RUN TestProxyWriteTimeout501=== PAUSE TestProxyWriteTimeout502=== RUN TestIsValidUploadKey503=== PAUSE TestIsValidUploadKey504=== RUN TestUploadHandlersRejectInvalidKeys505=== PAUSE TestUploadHandlersRejectInvalidKeys506=== RUN TestUploadHandlersRejectOversizedBody507=== PAUSE TestUploadHandlersRejectOversizedBody508=== RUN TestService_cleanupPendingClosuresHandler509=== PAUSE TestService_cleanupPendingClosuresHandler510=== RUN TestService_createPendingClosureHandler511=== PAUSE TestService_createPendingClosureHandler512=== RUN TestService_verifyS3Integrity513=== PAUSE TestService_verifyS3Integrity514=== RUN TestCompleteMultipartUnregistered515=== PAUSE TestCompleteMultipartUnregistered516=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT517=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT518=== CONT TestService_AuthMiddleware519=== CONT TestObjectStatsTrigger520=== CONT TestGCTaskStore_DeduplicateSameParams521--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)522=== CONT TestMultipartCleanup523=== CONT TestRedundantMultipartUpload524=== CONT TestServerTLSConfig525=== CONT TestClientErrorHandling526=== RUN TestServerTLSConfig/no_client_CA527=== CONT TestCacheStatsHandler528=== PAUSE TestServerTLSConfig/no_client_CA529=== RUN TestServerTLSConfig/missing_CA_file530=== PAUSE TestServerTLSConfig/missing_CA_file531=== RUN TestServerTLSConfig/not_a_PEM_file532=== PAUSE TestServerTLSConfig/not_a_PEM_file533=== CONT TestService_ReadAuthMiddleware534=== CONT TestCacheConfigHandler535=== RUN TestCacheConfigHandler/full_config,_no_issuer536=== CONT TestService_AuthMiddleware_OIDC537=== PAUSE TestCacheConfigHandler/full_config,_no_issuer538=== RUN TestCacheConfigHandler/no_cache_url_configured539=== PAUSE TestCacheConfigHandler/no_cache_url_configured540=== RUN TestCacheConfigHandler/no_signing_keys541=== PAUSE TestCacheConfigHandler/no_signing_keys542=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator543=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator544=== CONT TestService_AuthMiddleware_MTLSBoundSubjects545=== CONT TestClientCADerivations546=== RUN TestClientErrorHandling/InvalidStorePath547=== PAUSE TestClientErrorHandling/InvalidStorePath548=== RUN TestClientErrorHandling/InvalidAuthToken549=== PAUSE TestClientErrorHandling/InvalidAuthToken550=== RUN TestClientErrorHandling/ServerNotAvailable551=== PAUSE TestClientErrorHandling/ServerNotAvailable552=== CONT TestService_AuthMiddleware_MTLSProxyHeader5532026/07/19 09:48:52 INFO OIDC provider initialized name=test5542026-07-19 09:48:52.322 UTC [88409] ERROR: relation "goose_db_version" does not exist at character 365552026-07-19 09:48:52.322 UTC [88409] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5562026-07-19 09:48:52.322 UTC [88410] ERROR: relation "goose_db_version" does not exist at character 365572026-07-19 09:48:52.322 UTC [88410] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5582026-07-19 09:48:52.323 UTC [88411] ERROR: relation "goose_db_version" does not exist at character 365592026-07-19 09:48:52.323 UTC [88411] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5602026-07-19 09:48:52.328 UTC [88414] ERROR: relation "goose_db_version" does not exist at character 365612026-07-19 09:48:52.328 UTC [88414] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5622026-07-19 09:48:52.329 UTC [88412] ERROR: relation "goose_db_version" does not exist at character 365632026-07-19 09:48:52.329 UTC [88412] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5642026-07-19 09:48:52.329 UTC [88413] ERROR: relation "goose_db_version" does not exist at character 365652026-07-19 09:48:52.329 UTC [88413] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5662026-07-19 09:48:52.329 UTC [88415] ERROR: relation "goose_db_version" does not exist at character 365672026-07-19 09:48:52.329 UTC [88415] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5682026-07-19 09:48:52.330 UTC [88418] ERROR: relation "goose_db_version" does not exist at character 365692026-07-19 09:48:52.330 UTC [88418] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5702026-07-19 09:48:52.330 UTC [88416] ERROR: relation "goose_db_version" does not exist at character 365712026-07-19 09:48:52.330 UTC [88416] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5722026-07-19 09:48:52.331 UTC [88417] ERROR: relation "goose_db_version" does not exist at character 365732026-07-19 09:48:52.331 UTC [88417] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5742026/07/19 09:48:52 OK 20241026095416_initial_model.sql (6.63ms)5752026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (838.17µs)5762026/07/19 09:48:52 OK 20241026095416_initial_model.sql (8.23ms)5772026/07/19 09:48:52 OK 20241026095416_initial_model.sql (7.82ms)5782026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (733.71µs)5792026/07/19 09:48:52 OK 20251218171726_add_pins.sql (1.74ms)5802026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (572.63µs)5812026/07/19 09:48:52 OK 20251218171726_add_pins.sql (1.62ms)5822026/07/19 09:48:52 OK 20251218171726_add_pins.sql (1.73ms)5832026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (1.92ms)5842026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200005852026/07/19 09:48:52 OK 20241026095416_initial_model.sql (5.93ms)5862026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (758.83µs)5872026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (1.69ms)5882026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200005892026/07/19 09:48:52 OK 1_commit_pending_closure.sql (1.73ms)5902026/07/19 09:48:52 OK 20241026095416_initial_model.sql (7.86ms)5912026/07/19 09:48:52 OK 2_object_stats_trigger.sql (556.5µs)5922026/07/19 09:48:52 goose: up to current file version: 25932026/07/19 09:48:52 OK 20241026095416_initial_model.sql (8.14ms)5942026/07/19 09:48:52 OK 20251218171726_add_pins.sql (1.1ms)5952026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (2.95ms)5962026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200005972026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (554.54µs)5982026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (598.75µs)5992026/07/19 09:48:52 OK 20241026095416_initial_model.sql (7.58ms)6002026/07/19 09:48:52 OK 1_commit_pending_closure.sql (1.45ms)6012026/07/19 09:48:52 OK 20241026095416_initial_model.sql (7.68ms)6022026/07/19 09:48:52 OK 20241026095416_initial_model.sql (6.09ms)6032026/07/19 09:48:52 OK 20241026095416_initial_model.sql (8.65ms)6042026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (547.21µs)6052026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (544.88µs)6062026/07/19 09:48:52 OK 2_object_stats_trigger.sql (581.13µs)6072026/07/19 09:48:52 goose: up to current file version: 26082026/07/19 09:48:52 OK 1_commit_pending_closure.sql (1.22ms)6092026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (686.83µs)6102026/07/19 09:48:52 OK 20251218171726_add_pins.sql (1.51ms)6112026/07/19 09:48:52 OK 2_object_stats_trigger.sql (377.75µs)6122026/07/19 09:48:52 goose: up to current file version: 26132026/07/19 09:48:52 OK 20251218171726_add_pins.sql (1.22ms)6142026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (691µs)6152026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (2.04ms)6162026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200006172026/07/19 09:48:52 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"618--- PASS: TestService_AuthMiddleware (0.32s)6192026/07/19 09:48:52 OK 20251218171726_add_pins.sql (1.34ms)620=== CONT TestService_NativeMTLS6212026/07/19 09:48:52 OK 20251218171726_add_pins.sql (1.37ms)6222026/07/19 09:48:52 OK 20251218171726_add_pins.sql (1.71ms)623=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token624=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token625=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected626=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected627=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected628=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected629=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured630=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured631=== CONT TestMetricsInventory6322026/07/19 09:48:52 OK 1_commit_pending_closure.sql (1.47ms)6332026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (1.85ms)6342026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200006352026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (2.95ms)6362026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200006372026/07/19 09:48:52 OK 20251218171726_add_pins.sql (3ms)6382026/07/19 09:48:52 OK 2_object_stats_trigger.sql (1.3ms)6392026/07/19 09:48:52 goose: up to current file version: 26402026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (3.36ms)6412026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200006422026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (2.61ms)6432026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200006442026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (2.38ms)6452026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200006462026/07/19 09:48:52 OK 1_commit_pending_closure.sql (1.32ms)6472026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (1.25ms)6482026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200006492026/07/19 09:48:52 OK 1_commit_pending_closure.sql (1.38ms)6502026/07/19 09:48:52 OK 2_object_stats_trigger.sql (503.42µs)6512026/07/19 09:48:52 goose: up to current file version: 26522026/07/19 09:48:52 OK 1_commit_pending_closure.sql (1.25ms)6532026/07/19 09:48:52 OK 1_commit_pending_closure.sql (1.25ms)6542026/07/19 09:48:52 OK 2_object_stats_trigger.sql (947.29µs)6552026/07/19 09:48:52 goose: up to current file version: 2656{"timestamp":"2026-07-19T09:48:52.348081Z","level":"ERROR","fields":{"message":"system path read failed","path_kind":"data_usage","operation":"read_primary","reason":"config_not_found","object":"buckets/.usage.json","error":"Config not found"},"target":"rustfs_ecstore::data_usage","filename":"crates/ecstore/src/data_usage.rs","line_number":126,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}6572026/07/19 09:48:52 OK 1_commit_pending_closure.sql (2.38ms)6582026/07/19 09:48:52 INFO Created nix-cache-info in bucket bucket=bucket46592026/07/19 09:48:52 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"6602026/07/19 09:48:52 WARN mTLS auth: bound subjects configured but subject DN unavailable6612026/07/19 09:48:52 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"662--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.33s)663=== CONT TestNARDeduplicationMetadataUploadBug6642026/07/19 09:48:52 OK 1_commit_pending_closure.sql (1.47ms)6652026/07/19 09:48:52 OK 2_object_stats_trigger.sql (516.04µs)6662026/07/19 09:48:52 goose: up to current file version: 26672026/07/19 09:48:52 OK 2_object_stats_trigger.sql (1.71ms)6682026/07/19 09:48:52 goose: up to current file version: 26692026/07/19 09:48:52 OK 2_object_stats_trigger.sql (1.13ms)6702026/07/19 09:48:52 goose: up to current file version: 26712026/07/19 09:48:52 OK 2_object_stats_trigger.sql (1.01ms)6722026/07/19 09:48:52 goose: up to current file version: 26732026/07/19 09:48:52 INFO Received uploads request method=POST path=/api/pending_closures6742026/07/19 09:48:52 WARN mTLS auth: subject not in bound subjects subject="CN=writer"675--- PASS: TestService_ReadAuthMiddleware (0.33s)676=== CONT TestGenerateLandingPage677--- PASS: TestGenerateLandingPage (0.00s)678=== CONT TestService_healthCheckHandler6792026/07/19 09:48:52 INFO Received uploads request method=POST path=/api/pending_closures680--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.33s)681=== CONT TestGracefulShutdownDrainsInflight6822026/07/19 09:48:52 INFO Starting HTTP server address=127.0.0.1:588166832026/07/19 09:48:52 INFO Shutdown signal received, draining in-flight requests timeout=10s6842026/07/19 09:48:52 INFO Received uploads request method=POST path=/api/pending_closures685--- PASS: TestCacheStatsHandler (0.34s)686=== CONT TestGCTaskStore_Fail687--- PASS: TestGCTaskStore_Fail (0.00s)688=== CONT TestGCTaskStore_PhaseUpdates689--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)690=== CONT TestGCTaskStore_CompletedAllowsNewTask691--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)692=== CONT TestGCTaskStore_GetReturnsLatest693--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)694=== CONT TestPinProtectsFromGC695--- PASS: TestObjectStatsTrigger (0.34s)696=== CONT TestGCTaskStore_GetEmpty697--- PASS: TestGCTaskStore_GetEmpty (0.00s)698=== CONT TestGCTaskStore_ConflictDifferentParams699--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)700=== CONT TestService_Rustfstest701--- PASS: TestGracefulShutdownDrainsInflight (0.07s)702=== CONT TestGCTaskStore_StartNew703--- PASS: TestGCTaskStore_StartNew (0.00s)704=== CONT TestIsValidUploadKey705=== RUN TestIsValidUploadKey/narinfo706=== PAUSE TestIsValidUploadKey/narinfo707=== RUN TestIsValidUploadKey/nar_zst708=== PAUSE TestIsValidUploadKey/nar_zst709=== RUN TestIsValidUploadKey/nar_xz710=== PAUSE TestIsValidUploadKey/nar_xz711=== RUN TestIsValidUploadKey/nar_plain712=== PAUSE TestIsValidUploadKey/nar_plain713=== RUN TestIsValidUploadKey/listing714=== PAUSE TestIsValidUploadKey/listing715=== RUN TestIsValidUploadKey/build_log716=== PAUSE TestIsValidUploadKey/build_log717=== RUN TestIsValidUploadKey/build_log_home-manager_file718=== PAUSE TestIsValidUploadKey/build_log_home-manager_file719=== RUN TestIsValidUploadKey/build_log_plus_in_name720=== PAUSE TestIsValidUploadKey/build_log_plus_in_name721=== RUN TestIsValidUploadKey/build_log_question_mark722=== PAUSE TestIsValidUploadKey/build_log_question_mark723=== RUN TestIsValidUploadKey/build_log_equals724=== PAUSE TestIsValidUploadKey/build_log_equals725=== RUN TestIsValidUploadKey/realisation726=== PAUSE TestIsValidUploadKey/realisation727=== RUN TestIsValidUploadKey/realisation_plus_in_output728=== PAUSE TestIsValidUploadKey/realisation_plus_in_output729=== RUN TestIsValidUploadKey/nix-cache-info730=== PAUSE TestIsValidUploadKey/nix-cache-info731=== RUN TestIsValidUploadKey/index.html732=== PAUSE TestIsValidUploadKey/index.html733=== RUN TestIsValidUploadKey/narinfo_key,_nar_type734=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type735=== RUN TestIsValidUploadKey/nar_key,_narinfo_type736=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type737=== RUN TestIsValidUploadKey/listing_key,_narinfo_type738=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type739=== RUN TestIsValidUploadKey/traversal740=== PAUSE TestIsValidUploadKey/traversal741=== RUN TestIsValidUploadKey/traversal_nar742=== PAUSE TestIsValidUploadKey/traversal_nar743=== RUN TestIsValidUploadKey/absolute744=== PAUSE TestIsValidUploadKey/absolute745=== RUN TestIsValidUploadKey/empty_key746=== PAUSE TestIsValidUploadKey/empty_key747=== RUN TestIsValidUploadKey/unknown_type748=== PAUSE TestIsValidUploadKey/unknown_type749=== CONT TestProxyWriteTimeout750=== RUN TestProxyWriteTimeout/narinfo751=== PAUSE TestProxyWriteTimeout/narinfo752=== RUN TestProxyWriteTimeout/1_GiB_nar753=== PAUSE TestProxyWriteTimeout/1_GiB_nar754=== RUN TestProxyWriteTimeout/10_GiB_nar755=== PAUSE TestProxyWriteTimeout/10_GiB_nar756=== RUN TestProxyWriteTimeout/unknown_size757=== PAUSE TestProxyWriteTimeout/unknown_size758=== CONT TestGCMetrics7592026/07/19 09:48:52 INFO Received cleanup request method=DELETE path=/api/pending_closures7602026/07/19 09:48:52 INFO Aborted multipart uploads count=1761--- PASS: TestMultipartCleanup (0.46s)762=== CONT TestPresignedUploadRegisteredBeforeCommit7632026/07/19 09:48:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7642026/07/19 09:48:52 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NWMxOTk3MWEtOWQwOS00MWY0LTlkMTMtYTlmYjViNTc1OWJjLmFmNWE5OTJiLWEwZGUtNDZlMy05NTJlLTJkNTE3NjhmN2E3MngxNzg0NDU0NTMyMzU2ODE1MDAw parts=12765--- PASS: TestRedundantMultipartUpload (0.50s)766=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle7672026-07-19 09:48:52.525 UTC [88439] ERROR: relation "goose_db_version" does not exist at character 367682026-07-19 09:48:52.525 UTC [88439] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7692026-07-19 09:48:52.525 UTC [88440] ERROR: relation "goose_db_version" does not exist at character 367702026-07-19 09:48:52.525 UTC [88440] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7712026-07-19 09:48:52.543 UTC [88444] ERROR: relation "goose_db_version" does not exist at character 367722026-07-19 09:48:52.543 UTC [88444] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7732026/07/19 09:48:52 OK 20241026095416_initial_model.sql (14.29ms)7742026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (544.13µs)7752026/07/19 09:48:52 OK 20241026095416_initial_model.sql (9.79ms)7762026/07/19 09:48:52 OK 20251218171726_add_pins.sql (1.4ms)7772026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (451.04µs)7782026/07/19 09:48:52 OK 20251218171726_add_pins.sql (1.53ms)7792026/07/19 09:48:52 OK 20241026095416_initial_model.sql (8.05ms)7802026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (348.5µs)7812026/07/19 09:48:52 OK 20251218171726_add_pins.sql (772.71µs)7822026-07-19 09:48:52.564 UTC [88445] ERROR: relation "goose_db_version" does not exist at character 367832026-07-19 09:48:52.564 UTC [88445] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7842026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (11.49ms)7852026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200007862026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (8.06ms)7872026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200007882026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (10.75ms)7892026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200007902026/07/19 09:48:52 OK 1_commit_pending_closure.sql (1.1ms)7912026/07/19 09:48:52 OK 1_commit_pending_closure.sql (1.34ms)7922026/07/19 09:48:52 OK 2_object_stats_trigger.sql (245.83µs)7932026/07/19 09:48:52 goose: up to current file version: 27942026/07/19 09:48:52 OK 2_object_stats_trigger.sql (301.54µs)7952026/07/19 09:48:52 goose: up to current file version: 27962026/07/19 09:48:52 OK 1_commit_pending_closure.sql (1.26ms)7972026/07/19 09:48:52 OK 2_object_stats_trigger.sql (365µs)7982026/07/19 09:48:52 goose: up to current file version: 27992026/07/19 09:48:52 WARN mTLS auth: subject not in bound subjects subject="CN=reader"8002026/07/19 09:48:52 WARN mTLS auth: subject not in bound subjects subject="CN=writer"801--- PASS: TestService_NativeMTLS (0.23s)802=== CONT TestReadProxyNarStreaming803--- PASS: TestService_healthCheckHandler (0.22s)804=== CONT TestGCBugBareHashReferences8052026/07/19 09:48:52 OK 20241026095416_initial_model.sql (6.62ms)8062026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (561.04µs)8072026/07/19 09:48:52 OK 20251218171726_add_pins.sql (2.13ms)808--- PASS: TestMetricsInventory (0.24s)809=== CONT TestReadProxyRangeRequest8102026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (3.27ms)8112026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200008122026/07/19 09:48:52 OK 1_commit_pending_closure.sql (971.33µs)8132026/07/19 09:48:52 OK 2_object_stats_trigger.sql (394.54µs)8142026/07/19 09:48:52 goose: up to current file version: 28152026/07/19 09:48:52 INFO Created nix-cache-info in bucket bucket=bucket15816=== NAME TestNARDeduplicationMetadataUploadBug817 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-88293-4258547180/TestNARDeduplicationMetadataUploadBug4049220208/001/store/y4npfbp66lmz4na4v05wxaw44z0wcbgq-file1.txt8182026-07-19 09:48:52.654 UTC [88455] ERROR: relation "goose_db_version" does not exist at character 368192026-07-19 09:48:52.654 UTC [88455] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8202026-07-19 09:48:52.655 UTC [88456] ERROR: relation "goose_db_version" does not exist at character 368212026-07-19 09:48:52.655 UTC [88456] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC822=== NAME TestClientCADerivations823 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-88293-4258547180/TestClientCADerivations1888336971/001/store/0ybxd2pmjjm0ncpdhgn8g71px87nky71-ca-test8242026/07/19 09:48:52 OK 20241026095416_initial_model.sql (8.86ms)8252026/07/19 09:48:52 OK 20241026095416_initial_model.sql (9.1ms)8262026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (1.1ms)8272026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (1.25ms)8282026/07/19 09:48:52 OK 20251218171726_add_pins.sql (2.39ms)8292026/07/19 09:48:52 OK 20251218171726_add_pins.sql (2.39ms)8302026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (2.33ms)8312026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200008322026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (2.45ms)8332026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200008342026/07/19 09:48:52 OK 1_commit_pending_closure.sql (1.59ms)8352026/07/19 09:48:52 OK 1_commit_pending_closure.sql (1.96ms)8362026/07/19 09:48:52 OK 2_object_stats_trigger.sql (433.5µs)8372026/07/19 09:48:52 goose: up to current file version: 28382026/07/19 09:48:52 OK 2_object_stats_trigger.sql (640.33µs)8392026/07/19 09:48:52 goose: up to current file version: 2840--- PASS: TestService_Rustfstest (0.33s)841=== CONT TestCompletedNarNotReofferedAcrossClosures8422026/07/19 09:48:52 INFO Created nix-cache-info in bucket bucket=bucket17843=== NAME TestClientCADerivations844 client_ca_test.go:139: Found 1 dependencies (including self)8452026/07/19 09:48:52 INFO Received uploads request method=POST path=/api/pending_closures8462026/07/19 09:48:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8472026/07/19 09:48:52 INFO Uploading y4npfbp66lmz4na4v05wxaw44z0wcbgq-file1.txt (160B)8482026/07/19 09:48:52 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"8492026/07/19 09:48:52 WARN Failed to register uploaded object key=y4npfbp66lmz4na4v05wxaw44z0wcbgq.ls error="server returned 404: 404 page not found\n"8502026/07/19 09:48:52 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign8512026/07/19 09:48:52 INFO Signed narinfos id=1 count=18522026/07/19 09:48:52 INFO Uploading 1 narinfos8532026/07/19 09:48:52 WARN Failed to register uploaded object key=y4npfbp66lmz4na4v05wxaw44z0wcbgq.narinfo error="server returned 404: 404 page not found\n"8542026/07/19 09:48:52 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8552026/07/19 09:48:52 INFO Completed upload id=18562026/07/19 09:48:52 INFO Upload complete. (91ms)857=== NAME TestNARDeduplicationMetadataUploadBug858 metadata_upload_test.go:54: Retrieved narinfo from S3:859 StorePath: /nix/var/nix/builds/nix-88293-4258547180/TestNARDeduplicationMetadataUploadBug4049220208/001/store/y4npfbp66lmz4na4v05wxaw44z0wcbgq-file1.txt860 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst861 Compression: zstd862 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf863 NarSize: 160864 References: 865 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf866 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)867 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):868 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}8692026/07/19 09:48:52 INFO Received uploads request method=POST path=/api/pending_closures870=== NAME TestPinProtectsFromGC871 client_integration_test.go:646: Pinned store path: /nix/var/nix/builds/nix-88293-4258547180/TestPinProtectsFromGC1724701169/001/store/pj15275r6p5kwwpr6ywfd5ky3xxs73hb-pinned-file.txt872 client_integration_test.go:647: Unpinned store path: /nix/var/nix/builds/nix-88293-4258547180/TestPinProtectsFromGC1724701169/001/store/qv8y0r5zsly823d61hgjbldxzivkfa27-unpinned-file.txt8732026/07/19 09:48:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8742026/07/19 09:48:52 INFO Uploading 0ybxd2pmjjm0ncpdhgn8g71px87nky71-ca-test (144B)8752026/07/19 09:48:52 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"8762026/07/19 09:48:52 WARN Failed to register uploaded object key=log/spbs1dm2n4rcg14zxc1agp28a97y0h8s-ca-test.drv error="server returned 404: 404 page not found\n"8772026/07/19 09:48:52 WARN Failed to register uploaded object key=0ybxd2pmjjm0ncpdhgn8g71px87nky71.ls error="server returned 404: 404 page not found\n"8782026/07/19 09:48:52 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign8792026/07/19 09:48:52 INFO Signed narinfos id=1 count=18802026/07/19 09:48:52 INFO Uploading 1 narinfos8812026/07/19 09:48:52 WARN Failed to register uploaded object key=0ybxd2pmjjm0ncpdhgn8g71px87nky71.narinfo error="server returned 404: 404 page not found\n"8822026/07/19 09:48:52 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete883=== NAME TestNARDeduplicationMetadataUploadBug884 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-88293-4258547180/TestNARDeduplicationMetadataUploadBug4049220208/001/store/10j25yxfvylz2a56pm0xyiyikny205wy-file2.txt8852026/07/19 09:48:52 INFO Completed upload id=18862026/07/19 09:48:52 INFO Upload complete. (91ms)887=== NAME TestClientCADerivations888 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-88293-4258547180/TestClientCADerivations1888336971/001/store/0ybxd2pmjjm0ncpdhgn8g71px87nky71-ca-test889 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst890 Compression: zstd891 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n892 NarSize: 144893 References: 894 Deriver: /nix/var/nix/builds/nix-88293-4258547180/TestClientCADerivations1888336971/001/store/spbs1dm2n4rcg14zxc1agp28a97y0h8s-ca-test.drv895 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n896 client_ca_test.go:185: Checking for realisation files in S3...897 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations898 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache8992026-07-19 09:48:52.847 UTC [88504] ERROR: relation "goose_db_version" does not exist at character 369002026-07-19 09:48:52.847 UTC [88504] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9012026-07-19 09:48:52.859 UTC [88508] ERROR: relation "goose_db_version" does not exist at character 369022026-07-19 09:48:52.859 UTC [88508] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC903 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket4?endpoint=http://localhost:58782®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-88293-4258547180/TestClientCADerivations1888336971/001/store'904 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 1905--- PASS: TestClientCADerivations (0.84s)906=== CONT TestReadProxyConditionalGet9072026-07-19 09:48:52.883 UTC [88514] ERROR: relation "goose_db_version" does not exist at character 369082026-07-19 09:48:52.883 UTC [88514] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9092026/07/19 09:48:52 OK 20241026095416_initial_model.sql (22.8ms)9102026/07/19 09:48:52 OK 20241026095416_initial_model.sql (23.42ms)9112026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (954µs)9122026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (507.21µs)9132026/07/19 09:48:52 OK 20251218171726_add_pins.sql (842µs)9142026/07/19 09:48:52 OK 20251218171726_add_pins.sql (795.46µs)9152026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (3.32ms)9162026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200009172026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (4.17ms)9182026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200009192026/07/19 09:48:52 OK 1_commit_pending_closure.sql (1.41ms)9202026/07/19 09:48:52 OK 2_object_stats_trigger.sql (408.88µs)9212026/07/19 09:48:52 goose: up to current file version: 29222026/07/19 09:48:52 OK 1_commit_pending_closure.sql (1.35ms)9232026/07/19 09:48:52 OK 2_object_stats_trigger.sql (702.17µs)9242026/07/19 09:48:52 goose: up to current file version: 29252026/07/19 09:48:52 INFO Received uploads request method=POST path=/api/pending_closures9262026/07/19 09:48:52 INFO Received uploads request method=POST path=/api/pending_closures9272026/07/19 09:48:52 OK 20241026095416_initial_model.sql (11.19ms)9282026/07/19 09:48:52 INFO Received uploads request method=POST path=/api/pending_closures9292026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (491.08µs)9302026/07/19 09:48:52 OK 20251218171726_add_pins.sql (9.38ms)9312026-07-19 09:48:52.920 UTC [88517] ERROR: relation "goose_db_version" does not exist at character 369322026-07-19 09:48:52.920 UTC [88517] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9332026/07/19 09:48:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9342026/07/19 09:48:52 INFO Uploading pj15275r6p5kwwpr6ywfd5ky3xxs73hb-pinned-file.txt (128B)9352026/07/19 09:48:52 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"9362026/07/19 09:48:52 WARN Failed to register uploaded object key=pj15275r6p5kwwpr6ywfd5ky3xxs73hb.ls error="server returned 404: 404 page not found\n"9372026/07/19 09:48:52 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9382026/07/19 09:48:52 INFO Signed narinfos id=1 count=19392026/07/19 09:48:52 INFO Uploading 1 narinfos9402026/07/19 09:48:52 WARN Failed to register uploaded object key=pj15275r6p5kwwpr6ywfd5ky3xxs73hb.narinfo error="server returned 404: 404 page not found\n"9412026/07/19 09:48:52 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9422026/07/19 09:48:52 INFO Completed upload id=19432026/07/19 09:48:52 INFO Upload complete. (96ms)9442026/07/19 09:48:52 INFO Received uploads request method=POST path=/api/pending_closures9452026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (14.99ms)9462026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200009472026/07/19 09:48:52 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)9482026/07/19 09:48:52 OK 1_commit_pending_closure.sql (1.53ms)9492026/07/19 09:48:52 WARN Failed to register uploaded object key=10j25yxfvylz2a56pm0xyiyikny205wy.ls error="server returned 404: 404 page not found\n"9502026/07/19 09:48:52 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign9512026/07/19 09:48:52 INFO Signed narinfos id=2 count=19522026/07/19 09:48:52 INFO Uploading 1 narinfos9532026/07/19 09:48:52 OK 2_object_stats_trigger.sql (259.29µs)9542026/07/19 09:48:52 goose: up to current file version: 29552026/07/19 09:48:52 WARN Failed to register uploaded object key=10j25yxfvylz2a56pm0xyiyikny205wy.narinfo error="server returned 404: 404 page not found\n"9562026/07/19 09:48:52 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete9572026/07/19 09:48:52 INFO Completed upload id=29582026/07/19 09:48:52 INFO Upload complete. (81ms)959=== NAME TestNARDeduplicationMetadataUploadBug960 metadata_upload_test.go:76: Retrieved narinfo from S3:961 StorePath: /nix/var/nix/builds/nix-88293-4258547180/TestNARDeduplicationMetadataUploadBug4049220208/001/store/10j25yxfvylz2a56pm0xyiyikny205wy-file2.txt962 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst963 Compression: zstd964 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf965 NarSize: 160966 References: 967 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf968 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)969 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):970 {"version":1,"root":{"type":"regular","size":44}}9712026/07/19 09:48:52 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9722026/07/19 09:48:52 INFO Received uploads request method=POST path=/api/pending_closures9732026/07/19 09:48:52 INFO Aborted multipart uploads count=0974--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.45s)975=== CONT TestCompleteMultipartUpload_ErrorButObjectExists976--- PASS: TestNARDeduplicationMetadataUploadBug (0.59s)977=== CONT TestReadProxyHead9782026/07/19 09:48:52 WARN Force mode enabled - objects will be deleted immediately without grace period9792026/07/19 09:48:52 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=09802026/07/19 09:48:52 INFO Vacuumed table table=pending_closures9812026/07/19 09:48:52 OK 20241026095416_initial_model.sql (10.33ms)9822026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (803.5µs)9832026-07-19 09:48:52.955 UTC [88525] ERROR: relation "goose_db_version" does not exist at character 369842026-07-19 09:48:52.955 UTC [88525] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9852026/07/19 09:48:52 INFO Vacuumed table table=pending_objects9862026/07/19 09:48:52 INFO Vacuumed table table=multipart_uploads9872026/07/19 09:48:52 INFO Vacuumed table table=closures9882026/07/19 09:48:52 OK 20251218171726_add_pins.sql (6.99ms)9892026/07/19 09:48:52 INFO Vacuumed table table=objects990--- PASS: TestGCMetrics (0.53s)991=== CONT TestReadProxyDisabled9922026/07/19 09:48:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9932026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (15.29ms)9942026/07/19 09:48:52 goose: successfully migrated database to version: 202606281200009952026/07/19 09:48:52 OK 1_commit_pending_closure.sql (950.21µs)9962026/07/19 09:48:52 OK 2_object_stats_trigger.sql (241.63µs)9972026/07/19 09:48:52 goose: up to current file version: 29982026-07-19 09:48:52.980 UTC [88530] ERROR: relation "goose_db_version" does not exist at character 369992026-07-19 09:48:52.980 UTC [88530] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10002026/07/19 09:48:52 OK 20241026095416_initial_model.sql (19.34ms)10012026/07/19 09:48:52 OK 20251210153512_drop_unused_gin_index.sql (751.75µs)10022026/07/19 09:48:52 OK 20251218171726_add_pins.sql (1.35ms)10032026/07/19 09:48:52 OK 20260628120000_add_object_size_and_stats.sql (4.31ms)10042026/07/19 09:48:52 goose: successfully migrated database to version: 2026062812000010052026/07/19 09:48:52 OK 1_commit_pending_closure.sql (1.43ms)10062026/07/19 09:48:52 OK 2_object_stats_trigger.sql (300.54µs)10072026/07/19 09:48:52 goose: up to current file version: 210082026/07/19 09:48:53 OK 20241026095416_initial_model.sql (8.04ms)10092026/07/19 09:48:53 OK 20251210153512_drop_unused_gin_index.sql (739.17µs)10102026/07/19 09:48:53 OK 20251218171726_add_pins.sql (1.22ms)1011--- PASS: TestReadProxyNarStreaming (0.43s)1012=== CONT TestReadProxyInvalidPath10132026/07/19 09:48:53 OK 20260628120000_add_object_size_and_stats.sql (4.88ms)10142026/07/19 09:48:53 goose: successfully migrated database to version: 2026062812000010152026/07/19 09:48:53 OK 1_commit_pending_closure.sql (1.79ms)10162026/07/19 09:48:53 OK 2_object_stats_trigger.sql (233.42µs)10172026/07/19 09:48:53 goose: up to current file version: 21018--- PASS: TestReadProxyRangeRequest (0.43s)1019=== CONT TestReadProxy40410202026/07/19 09:48:53 INFO Received uploads request method=POST path=/api/pending_closures10212026/07/19 09:48:53 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10222026/07/19 09:48:53 INFO Uploading qv8y0r5zsly823d61hgjbldxzivkfa27-unpinned-file.txt (128B)10232026/07/19 09:48:53 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"10242026/07/19 09:48:53 WARN Failed to register uploaded object key=qv8y0r5zsly823d61hgjbldxzivkfa27.ls error="server returned 404: 404 page not found\n"10252026/07/19 09:48:53 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign10262026/07/19 09:48:53 INFO Signed narinfos id=2 count=110272026/07/19 09:48:53 INFO Uploading 1 narinfos10282026/07/19 09:48:53 WARN Failed to register uploaded object key=qv8y0r5zsly823d61hgjbldxzivkfa27.narinfo error="server returned 404: 404 page not found\n"10292026/07/19 09:48:53 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10302026/07/19 09:48:53 INFO Completed upload id=210312026/07/19 09:48:53 INFO Upload complete. (79ms)10322026-07-19 09:48:53.062 UTC [88539] ERROR: relation "goose_db_version" does not exist at character 3610332026-07-19 09:48:53.062 UTC [88539] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10342026/07/19 09:48:53 INFO Received create pin request method=POST path=/api/pins/myapp10352026/07/19 09:48:53 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-88293-4258547180/TestPinProtectsFromGC1724701169/001/store/pj15275r6p5kwwpr6ywfd5ky3xxs73hb-pinned-file.txt narinfo_key=pj15275r6p5kwwpr6ywfd5ky3xxs73hb.narinfo10362026/07/19 09:48:53 OK 20241026095416_initial_model.sql (6.76ms)10372026/07/19 09:48:53 INFO Starting cleanup of old closures method=DELETE path=/api/closures10382026/07/19 09:48:53 INFO Garbage collection started10392026/07/19 09:48:53 OK 20251210153512_drop_unused_gin_index.sql (704.46µs)10402026/07/19 09:48:53 OK 20251218171726_add_pins.sql (919.38µs)10412026/07/19 09:48:53 INFO Aborted multipart uploads count=010422026/07/19 09:48:53 OK 20260628120000_add_object_size_and_stats.sql (2.13ms)10432026/07/19 09:48:53 goose: successfully migrated database to version: 2026062812000010442026/07/19 09:48:53 WARN Force mode enabled - objects will be deleted immediately without grace period10452026/07/19 09:48:53 OK 1_commit_pending_closure.sql (885.75µs)10462026/07/19 09:48:53 OK 2_object_stats_trigger.sql (219.46µs)10472026/07/19 09:48:53 goose: up to current file version: 210482026/07/19 09:48:53 INFO Received uploads request method=POST path=/api/pending_closures1049--- PASS: TestGCBugBareHashReferences (0.63s)1050=== CONT TestReadProxyRootRedirectsToIndexHTML10512026/07/19 09:48:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10522026/07/19 09:48:53 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NWMxOTk3MWEtOWQwOS00MWY0LTlkMTMtYTlmYjViNTc1OWJjLmU3MDJhNmY0LWZhMWYtNDg1Yy05MWIzLWQxMjJjMGJhMmZlMHgxNzg0NDU0NTMzMDg4Mzk2MDAw parts=1210532026/07/19 09:48:53 INFO Received uploads request method=POST path=/api/pending_closures1054--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.52s)1055=== CONT TestService_verifyS3Integrity10562026-07-19 09:48:53.241 UTC [88547] ERROR: relation "goose_db_version" does not exist at character 3610572026-07-19 09:48:53.241 UTC [88547] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10582026/07/19 09:48:53 OK 20241026095416_initial_model.sql (8.23ms)10592026/07/19 09:48:53 OK 20251210153512_drop_unused_gin_index.sql (370µs)10602026/07/19 09:48:53 OK 20251218171726_add_pins.sql (1.77ms)10612026/07/19 09:48:53 OK 20260628120000_add_object_size_and_stats.sql (7.75ms)10622026/07/19 09:48:53 goose: successfully migrated database to version: 2026062812000010632026/07/19 09:48:53 OK 1_commit_pending_closure.sql (930.17µs)10642026/07/19 09:48:53 OK 2_object_stats_trigger.sql (209.33µs)10652026/07/19 09:48:53 goose: up to current file version: 21066--- PASS: TestReadProxyConditionalGet (0.41s)1067=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT10682026-07-19 09:48:53.278 UTC [88550] ERROR: relation "goose_db_version" does not exist at character 3610692026-07-19 09:48:53.278 UTC [88550] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10702026-07-19 09:48:53.279 UTC [88549] ERROR: relation "goose_db_version" does not exist at character 3610712026-07-19 09:48:53.279 UTC [88549] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10722026-07-19 09:48:53.279 UTC [88551] ERROR: relation "goose_db_version" does not exist at character 3610732026-07-19 09:48:53.279 UTC [88551] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10742026/07/19 09:48:53 OK 20241026095416_initial_model.sql (17.86ms)10752026/07/19 09:48:53 OK 20251210153512_drop_unused_gin_index.sql (830.83µs)10762026/07/19 09:48:53 OK 20241026095416_initial_model.sql (20.88ms)10772026/07/19 09:48:53 OK 20241026095416_initial_model.sql (21.03ms)10782026/07/19 09:48:53 OK 20251218171726_add_pins.sql (1.54ms)10792026/07/19 09:48:53 OK 20251210153512_drop_unused_gin_index.sql (458.04µs)10802026/07/19 09:48:53 OK 20251210153512_drop_unused_gin_index.sql (439.38µs)10812026/07/19 09:48:53 OK 20251218171726_add_pins.sql (725.5µs)10822026/07/19 09:48:53 OK 20251218171726_add_pins.sql (746.54µs)10832026/07/19 09:48:53 OK 20260628120000_add_object_size_and_stats.sql (2.9ms)10842026/07/19 09:48:53 goose: successfully migrated database to version: 2026062812000010852026/07/19 09:48:53 OK 20260628120000_add_object_size_and_stats.sql (4.2ms)10862026/07/19 09:48:53 goose: successfully migrated database to version: 2026062812000010872026/07/19 09:48:53 OK 1_commit_pending_closure.sql (845.71µs)10882026/07/19 09:48:53 OK 1_commit_pending_closure.sql (1.03ms)10892026/07/19 09:48:53 OK 20260628120000_add_object_size_and_stats.sql (4.25ms)10902026/07/19 09:48:53 goose: successfully migrated database to version: 2026062812000010912026/07/19 09:48:53 OK 2_object_stats_trigger.sql (384.29µs)10922026/07/19 09:48:53 goose: up to current file version: 210932026/07/19 09:48:53 OK 2_object_stats_trigger.sql (435.13µs)10942026/07/19 09:48:53 goose: up to current file version: 210952026/07/19 09:48:53 OK 1_commit_pending_closure.sql (942µs)10962026/07/19 09:48:53 OK 2_object_stats_trigger.sql (291.29µs)10972026/07/19 09:48:53 goose: up to current file version: 210982026/07/19 09:48:53 INFO Received uploads request method=POST path=/api/pending_closures1099--- PASS: TestReadProxyDisabled (0.36s)1100=== CONT TestCompleteMultipartUnregistered1101--- PASS: TestReadProxyHead (0.38s)1102=== CONT TestService_cleanupPendingClosuresHandler11032026/07/19 09:48:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1104{"timestamp":"2026-07-19T09:48:53.329148Z","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(9)"}1105{"timestamp":"2026-07-19T09:48:53.329166Z","level":"ERROR","fields":{"message":"complete_multipart_upload etag err client=Some(\"deadbeef\"), stored=\"\", part_id=1, bucket=bucket26, 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(9)"}11062026/07/19 09:48:53 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=NWMxOTk3MWEtOWQwOS00MWY0LTlkMTMtYTlmYjViNTc1OWJjLjBhMWZlYWM3LTlhMzUtNDM1NS1iNmZkLThhNjgwZDMzYjczOHgxNzg0NDU0NTMzMzI0NjA5MDAw11072026/07/19 09:48:53 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=011082026/07/19 09:48:53 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NWMxOTk3MWEtOWQwOS00MWY0LTlkMTMtYTlmYjViNTc1OWJjLjBhMWZlYWM3LTlhMzUtNDM1NS1iNmZkLThhNjgwZDMzYjczOHgxNzg0NDU0NTMzMzI0NjA5MDAw parts=11109--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.40s)1110=== CONT TestClientWithDependencies11112026/07/19 09:48:53 INFO Vacuumed table table=pending_closures11122026/07/19 09:48:53 INFO Vacuumed table table=pending_objects11132026/07/19 09:48:53 INFO Vacuumed table table=multipart_uploads11142026-07-19 09:48:53.351 UTC [88559] ERROR: relation "goose_db_version" does not exist at character 3611152026-07-19 09:48:53.351 UTC [88559] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11162026/07/19 09:48:53 INFO Vacuumed table table=closures11172026/07/19 09:48:53 INFO Vacuumed table table=objects11182026/07/19 09:48:53 OK 20241026095416_initial_model.sql (8.69ms)11192026/07/19 09:48:53 OK 20251210153512_drop_unused_gin_index.sql (388.33µs)11202026/07/19 09:48:53 OK 20251218171726_add_pins.sql (780.13µs)11212026-07-19 09:48:53.378 UTC [88560] ERROR: relation "goose_db_version" does not exist at character 3611222026-07-19 09:48:53.378 UTC [88560] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11232026/07/19 09:48:53 OK 20260628120000_add_object_size_and_stats.sql (14.93ms)11242026/07/19 09:48:53 goose: successfully migrated database to version: 2026062812000011252026/07/19 09:48:53 OK 1_commit_pending_closure.sql (950.25µs)11262026/07/19 09:48:53 OK 2_object_stats_trigger.sql (225.17µs)11272026/07/19 09:48:53 goose: up to current file version: 21128--- PASS: TestReadProxyInvalidPath (0.39s)1129=== CONT TestClientMultipleUploads11302026/07/19 09:48:53 OK 20241026095416_initial_model.sql (4.79ms)11312026/07/19 09:48:53 OK 20251210153512_drop_unused_gin_index.sql (791.46µs)11322026/07/19 09:48:53 OK 20251218171726_add_pins.sql (1.52ms)11332026/07/19 09:48:53 OK 20260628120000_add_object_size_and_stats.sql (24.64ms)11342026/07/19 09:48:53 goose: successfully migrated database to version: 2026062812000011352026/07/19 09:48:53 OK 1_commit_pending_closure.sql (1.08ms)11362026/07/19 09:48:53 OK 2_object_stats_trigger.sql (496.17µs)11372026/07/19 09:48:53 goose: up to current file version: 21138--- PASS: TestReadProxy404 (0.41s)1139=== CONT TestService_createPendingClosureHandler11402026-07-19 09:48:53.617 UTC [88565] ERROR: relation "goose_db_version" does not exist at character 3611412026-07-19 09:48:53.617 UTC [88565] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11422026-07-19 09:48:53.622 UTC [88566] ERROR: relation "goose_db_version" does not exist at character 3611432026-07-19 09:48:53.622 UTC [88566] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11442026/07/19 09:48:53 OK 20241026095416_initial_model.sql (7.92ms)11452026/07/19 09:48:53 OK 20251210153512_drop_unused_gin_index.sql (416.79µs)11462026/07/19 09:48:53 OK 20251218171726_add_pins.sql (2.7ms)11472026/07/19 09:48:53 OK 20241026095416_initial_model.sql (13.48ms)11482026/07/19 09:48:53 OK 20251210153512_drop_unused_gin_index.sql (321.33µs)11492026/07/19 09:48:53 OK 20260628120000_add_object_size_and_stats.sql (3.4ms)11502026/07/19 09:48:53 goose: successfully migrated database to version: 2026062812000011512026/07/19 09:48:53 OK 20251218171726_add_pins.sql (1.17ms)11522026/07/19 09:48:53 OK 1_commit_pending_closure.sql (1.34ms)11532026/07/19 09:48:53 OK 2_object_stats_trigger.sql (344.13µs)11542026/07/19 09:48:53 goose: up to current file version: 211552026/07/19 09:48:53 OK 20260628120000_add_object_size_and_stats.sql (1.81ms)11562026/07/19 09:48:53 goose: successfully migrated database to version: 2026062812000011572026/07/19 09:48:53 OK 1_commit_pending_closure.sql (835.21µs)11582026/07/19 09:48:53 OK 2_object_stats_trigger.sql (197.79µs)11592026/07/19 09:48:53 goose: up to current file version: 21160--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.46s)1161=== CONT TestUploadHandlersRejectOversizedBody11622026/07/19 09:48:53 INFO Received uploads request method=POST path=/api/pending_closures11632026-07-19 09:48:53.670 UTC [88567] ERROR: relation "goose_db_version" does not exist at character 3611642026-07-19 09:48:53.670 UTC [88567] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1165=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1166=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1167=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1168=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1169=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1170=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1171=== CONT TestParseSingleRange1172=== RUN TestParseSingleRange/none1173=== PAUSE TestParseSingleRange/none1174=== RUN TestParseSingleRange/unknown_unit1175=== PAUSE TestParseSingleRange/unknown_unit1176=== RUN TestParseSingleRange/multi-range_ignored1177=== PAUSE TestParseSingleRange/multi-range_ignored1178=== RUN TestParseSingleRange/malformed_no_dash1179=== PAUSE TestParseSingleRange/malformed_no_dash1180=== RUN TestParseSingleRange/malformed_both_empty1181=== PAUSE TestParseSingleRange/malformed_both_empty1182=== RUN TestParseSingleRange/malformed_end_before_start1183=== PAUSE TestParseSingleRange/malformed_end_before_start1184=== RUN TestParseSingleRange/closed1185=== PAUSE TestParseSingleRange/closed1186=== RUN TestParseSingleRange/open-ended1187=== PAUSE TestParseSingleRange/open-ended1188=== RUN TestParseSingleRange/end_clamped_to_size1189=== PAUSE TestParseSingleRange/end_clamped_to_size1190=== RUN TestParseSingleRange/suffix1191=== PAUSE TestParseSingleRange/suffix1192=== RUN TestParseSingleRange/suffix_exceeds_size1193=== PAUSE TestParseSingleRange/suffix_exceeds_size1194=== RUN TestParseSingleRange/single_byte1195=== PAUSE TestParseSingleRange/single_byte1196=== RUN TestParseSingleRange/start_past_EOF1197=== PAUSE TestParseSingleRange/start_past_EOF1198=== RUN TestParseSingleRange/start_far_past_EOF1199=== PAUSE TestParseSingleRange/start_far_past_EOF1200=== CONT TestClientIntegration12012026/07/19 09:48:53 OK 20241026095416_initial_model.sql (11.67ms)12022026/07/19 09:48:53 OK 20251210153512_drop_unused_gin_index.sql (1.17ms)12032026/07/19 09:48:53 OK 20251218171726_add_pins.sql (968.92µs)12042026/07/19 09:48:53 OK 20260628120000_add_object_size_and_stats.sql (4.93ms)12052026/07/19 09:48:53 goose: successfully migrated database to version: 2026062812000012062026/07/19 09:48:53 OK 1_commit_pending_closure.sql (1.24ms)12072026/07/19 09:48:53 OK 2_object_stats_trigger.sql (212.67µs)12082026/07/19 09:48:53 goose: up to current file version: 212092026/07/19 09:48:53 INFO Received uploads request method=POST path=/api/pending_closures1210--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.44s)1211=== CONT TestReadProxyNarinfoAlreadyDecompressed12122026-07-19 09:48:53.732 UTC [88573] ERROR: relation "goose_db_version" does not exist at character 3612132026-07-19 09:48:53.732 UTC [88573] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12142026-07-19 09:48:53.732 UTC [88572] ERROR: relation "goose_db_version" does not exist at character 3612152026-07-19 09:48:53.732 UTC [88572] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12162026/07/19 09:48:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12172026/07/19 09:48:53 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NWMxOTk3MWEtOWQwOS00MWY0LTlkMTMtYTlmYjViNTc1OWJjLmM1YTI0NzhmLWNkODctNDk4MC1hYzNkLWY4YjI3ZjEyZDdlZngxNzg0NDU0NTMzNjU3OTMzMDAw parts=1012182026/07/19 09:48:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12192026/07/19 09:48:53 INFO Completed upload id=112202026/07/19 09:48:53 INFO Received uploads request method=POST path=/api/pending_closures12212026/07/19 09:48:53 INFO Received uploads request method=POST path=/api/pending_closures12222026/07/19 09:48:53 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo12232026/07/19 09:48:53 WARN Found objects in DB but missing from S3, will re-upload count=112242026-07-19 09:48:53.766 UTC [88574] ERROR: relation "goose_db_version" does not exist at character 3612252026-07-19 09:48:53.766 UTC [88574] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1226--- PASS: TestService_verifyS3Integrity (0.55s)1227=== CONT TestOrphanedObjectsGCStressTest12282026/07/19 09:48:53 OK 20241026095416_initial_model.sql (37.93ms)12292026/07/19 09:48:53 OK 20241026095416_initial_model.sql (9.61ms)12302026/07/19 09:48:53 OK 20251210153512_drop_unused_gin_index.sql (407µs)12312026/07/19 09:48:53 OK 20251210153512_drop_unused_gin_index.sql (323.58µs)12322026/07/19 09:48:53 OK 20251218171726_add_pins.sql (690.71µs)12332026/07/19 09:48:53 OK 20251218171726_add_pins.sql (671.33µs)12342026/07/19 09:48:53 OK 20260628120000_add_object_size_and_stats.sql (3.5ms)12352026/07/19 09:48:53 goose: successfully migrated database to version: 2026062812000012362026/07/19 09:48:53 OK 20241026095416_initial_model.sql (30.03ms)12372026/07/19 09:48:53 OK 20251210153512_drop_unused_gin_index.sql (300.75µs)12382026/07/19 09:48:53 OK 1_commit_pending_closure.sql (891.33µs)12392026/07/19 09:48:53 OK 2_object_stats_trigger.sql (215.63µs)12402026/07/19 09:48:53 goose: up to current file version: 212412026/07/19 09:48:53 OK 20260628120000_add_object_size_and_stats.sql (5.31ms)12422026/07/19 09:48:53 goose: successfully migrated database to version: 2026062812000012432026/07/19 09:48:53 OK 20251218171726_add_pins.sql (1.03ms)12442026/07/19 09:48:53 OK 1_commit_pending_closure.sql (873.54µs)12452026/07/19 09:48:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12462026/07/19 09:48:53 OK 2_object_stats_trigger.sql (517.58µs)12472026/07/19 09:48:53 goose: up to current file version: 212482026/07/19 09:48:53 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1249--- PASS: TestCompleteMultipartUnregistered (0.48s)1250=== CONT TestResurrectedObjectNotDeleted12512026/07/19 09:48:53 OK 20260628120000_add_object_size_and_stats.sql (3.11ms)12522026/07/19 09:48:53 goose: successfully migrated database to version: 2026062812000012532026/07/19 09:48:53 INFO Received cleanup request method=DELETE path=/api/pending_closures12542026/07/19 09:48:53 OK 1_commit_pending_closure.sql (2.07ms)12552026/07/19 09:48:53 OK 2_object_stats_trigger.sql (616.29µs)12562026/07/19 09:48:53 goose: up to current file version: 212572026/07/19 09:48:53 INFO Aborted multipart uploads count=012582026/07/19 09:48:53 INFO Received uploads request method=POST path=/api/pending_closures12592026/07/19 09:48:53 INFO Created nix-cache-info in bucket bucket=bucket3612602026/07/19 09:48:53 INFO Received cleanup request method=DELETE path=/api/pending_closures12612026/07/19 09:48:53 INFO Aborted multipart uploads count=112622026/07/19 09:48:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12632026-07-19 09:48:53.816 UTC [88572] ERROR: Closure does not exist: id=112642026-07-19 09:48:53.816 UTC [88572] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE12652026-07-19 09:48:53.816 UTC [88572] STATEMENT: -- name: CommitPendingClosure :exec1266 SELECT commit_pending_closure($1::bigint)1267 1268--- PASS: TestService_cleanupPendingClosuresHandler (0.50s)1269=== CONT TestReadProxyNarinfo12702026-07-19 09:48:53.825 UTC [88581] ERROR: relation "goose_db_version" does not exist at character 3612712026-07-19 09:48:53.825 UTC [88581] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12722026/07/19 09:48:53 OK 20241026095416_initial_model.sql (34ms)12732026/07/19 09:48:53 OK 20251210153512_drop_unused_gin_index.sql (1.33ms)12742026/07/19 09:48:53 OK 20251218171726_add_pins.sql (1.92ms)12752026/07/19 09:48:53 OK 20260628120000_add_object_size_and_stats.sql (5.58ms)12762026/07/19 09:48:53 goose: successfully migrated database to version: 2026062812000012772026/07/19 09:48:53 OK 1_commit_pending_closure.sql (804.25µs)12782026/07/19 09:48:53 OK 2_object_stats_trigger.sql (201.54µs)12792026/07/19 09:48:53 goose: up to current file version: 212802026/07/19 09:48:53 INFO Created nix-cache-info in bucket bucket=bucket3712812026-07-19 09:48:53.888 UTC [88586] ERROR: relation "goose_db_version" does not exist at character 3612822026-07-19 09:48:53.888 UTC [88586] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12832026/07/19 09:48:53 OK 20241026095416_initial_model.sql (5.72ms)12842026/07/19 09:48:53 OK 20251210153512_drop_unused_gin_index.sql (841µs)12852026/07/19 09:48:53 OK 20251218171726_add_pins.sql (2.67ms)12862026/07/19 09:48:53 OK 20260628120000_add_object_size_and_stats.sql (14.74ms)12872026/07/19 09:48:53 goose: successfully migrated database to version: 2026062812000012882026/07/19 09:48:53 OK 1_commit_pending_closure.sql (1.81ms)12892026/07/19 09:48:53 OK 2_object_stats_trigger.sql (505µs)12902026/07/19 09:48:53 goose: up to current file version: 21291=== NAME TestClientMultipleUploads1292 client_integration_test.go:338: Created store path 0: /nix/var/nix/builds/nix-88293-4258547180/TestClientMultipleUploads2225218019/001/store/q16mrq5q7x8izjxdrnjkljl6szphk2vz-test-file-0.txt12932026/07/19 09:48:53 INFO Received uploads request method=POST path=/api/pending_closures12942026/07/19 09:48:53 INFO Received uploads request method=POST path=/api/pending_closures12952026/07/19 09:48:53 INFO Received uploads request method=POST path=/api/pending_closures1296 client_integration_test.go:338: Created store path 1: /nix/var/nix/builds/nix-88293-4258547180/TestClientMultipleUploads2225218019/001/store/ip07brlh3ijyrfcda933aqhya81fsjv0-test-file-1.txt1297 client_integration_test.go:338: Created store path 2: /nix/var/nix/builds/nix-88293-4258547180/TestClientMultipleUploads2225218019/001/store/xwpnvl9h61icad1clv8p5aymzy5ix47z-test-file-2.txt1298=== NAME TestClientWithDependencies1299 client_integration_test.go:593: Built derivation: /nix/var/nix/builds/nix-88293-4258547180/TestClientWithDependencies2035512332/001/store/9rh2ibfxga4a8fdg3igl9d18gi9fjpbx-test-script13002026/07/19 09:48:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13012026/07/19 09:48:54 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NWMxOTk3MWEtOWQwOS00MWY0LTlkMTMtYTlmYjViNTc1OWJjLjM0MjE5ZGZiLTMwZWMtNGFiYy1hOTFiLTQ4NTI0YjVlZDk5MHgxNzg0NDU0NTMzOTM3NjcyMDAw parts=1013022026/07/19 09:48:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13032026/07/19 09:48:54 INFO Completed upload id=113042026/07/19 09:48:54 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000013052026/07/19 09:48:54 INFO Received uploads request method=POST path=/api/pending_closures13062026/07/19 09:48:54 INFO Starting cleanup of old closures method=DELETE path=/api/closures13072026/07/19 09:48:54 INFO Aborted multipart uploads count=01308 client_integration_test.go:595: Found 1 dependencies (including self)13092026/07/19 09:48:54 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=013102026/07/19 09:48:54 INFO Vacuumed table table=pending_closures13112026/07/19 09:48:54 INFO Vacuumed table table=pending_objects13122026/07/19 09:48:54 INFO Vacuumed table table=multipart_uploads13132026/07/19 09:48:54 INFO Vacuumed table table=closures13142026/07/19 09:48:54 INFO Vacuumed table table=objects13152026/07/19 09:48:54 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001316--- PASS: TestService_createPendingClosureHandler (0.68s)1317=== CONT TestOrphanedObjectsGC13182026/07/19 09:48:54 INFO Received uploads request method=POST path=/api/pending_closures13192026-07-19 09:48:54.107 UTC [88607] ERROR: relation "goose_db_version" does not exist at character 3613202026-07-19 09:48:54.107 UTC [88607] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13212026/07/19 09:48:54 INFO Received uploads request method=POST path=/api/pending_closures13222026/07/19 09:48:54 INFO Received uploads request method=POST path=/api/pending_closures13232026/07/19 09:48:54 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)13242026/07/19 09:48:54 INFO Uploading xwpnvl9h61icad1clv8p5aymzy5ix47z-test-file-2.txt (160B)13252026/07/19 09:48:54 INFO Uploading q16mrq5q7x8izjxdrnjkljl6szphk2vz-test-file-0.txt (160B)13262026/07/19 09:48:54 INFO Uploading ip07brlh3ijyrfcda933aqhya81fsjv0-test-file-1.txt (160B)13272026/07/19 09:48:54 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"13282026/07/19 09:48:54 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"13292026/07/19 09:48:54 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"13302026/07/19 09:48:54 WARN Failed to register uploaded object key=xwpnvl9h61icad1clv8p5aymzy5ix47z.ls error="server returned 404: 404 page not found\n"13312026/07/19 09:48:54 WARN Failed to register uploaded object key=q16mrq5q7x8izjxdrnjkljl6szphk2vz.ls error="server returned 404: 404 page not found\n"13322026/07/19 09:48:54 WARN Failed to register uploaded object key=ip07brlh3ijyrfcda933aqhya81fsjv0.ls error="server returned 404: 404 page not found\n"13332026/07/19 09:48:54 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13342026/07/19 09:48:54 INFO Signed narinfos id=1 count=113352026/07/19 09:48:54 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13362026/07/19 09:48:54 INFO Signed narinfos id=2 count=113372026/07/19 09:48:54 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign13382026/07/19 09:48:54 INFO Signed narinfos id=3 count=113392026/07/19 09:48:54 INFO Uploading 3 narinfos13402026/07/19 09:48:54 WARN Failed to register uploaded object key=ip07brlh3ijyrfcda933aqhya81fsjv0.narinfo error="server returned 404: 404 page not found\n"13412026/07/19 09:48:54 WARN Failed to register uploaded object key=xwpnvl9h61icad1clv8p5aymzy5ix47z.narinfo error="server returned 404: 404 page not found\n"13422026/07/19 09:48:54 WARN Failed to register uploaded object key=q16mrq5q7x8izjxdrnjkljl6szphk2vz.narinfo error="server returned 404: 404 page not found\n"13432026/07/19 09:48:54 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13442026/07/19 09:48:54 INFO Completed upload id=213452026/07/19 09:48:54 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete13462026/07/19 09:48:54 OK 20241026095416_initial_model.sql (8.87ms)13472026/07/19 09:48:54 INFO Received uploads request method=POST path=/api/pending_closures13482026/07/19 09:48:54 INFO Completed upload id=313492026/07/19 09:48:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13502026/07/19 09:48:54 OK 20251210153512_drop_unused_gin_index.sql (633.13µs)13512026/07/19 09:48:54 INFO Completed upload id=113522026/07/19 09:48:54 INFO Upload complete. (86ms)1353=== NAME TestClientMultipleUploads1354 client_integration_test.go:349: Uploaded 3 paths in 117.441625ms13552026/07/19 09:48:54 OK 20251218171726_add_pins.sql (871.88µs)13562026/07/19 09:48:54 OK 20260628120000_add_object_size_and_stats.sql (2.26ms)13572026/07/19 09:48:54 goose: successfully migrated database to version: 2026062812000013582026/07/19 09:48:54 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13592026/07/19 09:48:54 INFO Uploading 9rh2ibfxga4a8fdg3igl9d18gi9fjpbx-test-script (136B)1360--- PASS: TestClientMultipleUploads (0.74s)1361=== CONT TestIsValidCachePath1362=== RUN TestIsValidCachePath/narinfo1363=== PAUSE TestIsValidCachePath/narinfo1364=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1365=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1366=== RUN TestIsValidCachePath/nar_zst1367=== PAUSE TestIsValidCachePath/nar_zst1368=== RUN TestIsValidCachePath/nar_xz1369=== PAUSE TestIsValidCachePath/nar_xz1370=== RUN TestIsValidCachePath/nar_bz21371=== PAUSE TestIsValidCachePath/nar_bz21372=== RUN TestIsValidCachePath/nar_uncompressed1373=== PAUSE TestIsValidCachePath/nar_uncompressed1374=== RUN TestIsValidCachePath/ls1375=== PAUSE TestIsValidCachePath/ls1376=== RUN TestIsValidCachePath/log1377=== PAUSE TestIsValidCachePath/log1378=== RUN TestIsValidCachePath/realisation1379=== PAUSE TestIsValidCachePath/realisation1380=== RUN TestIsValidCachePath/nix-cache-info1381=== PAUSE TestIsValidCachePath/nix-cache-info1382=== RUN TestIsValidCachePath/index.html1383=== PAUSE TestIsValidCachePath/index.html1384=== RUN TestIsValidCachePath/traversal_parent1385=== PAUSE TestIsValidCachePath/traversal_parent1386=== RUN TestIsValidCachePath/traversal_in_middle1387=== PAUSE TestIsValidCachePath/traversal_in_middle1388=== RUN TestIsValidCachePath/invalid_char_e1389=== PAUSE TestIsValidCachePath/invalid_char_e1390=== RUN TestIsValidCachePath/invalid_char_u1391=== PAUSE TestIsValidCachePath/invalid_char_u1392=== RUN TestIsValidCachePath/random_path1393=== PAUSE TestIsValidCachePath/random_path1394=== RUN TestIsValidCachePath/empty1395=== PAUSE TestIsValidCachePath/empty1396=== RUN TestIsValidCachePath/leading_slash1397=== PAUSE TestIsValidCachePath/leading_slash1398=== RUN TestIsValidCachePath/wrong_extension1399=== PAUSE TestIsValidCachePath/wrong_extension1400=== RUN TestIsValidCachePath/short_hash1401=== PAUSE TestIsValidCachePath/short_hash1402=== CONT TestServerTLSConfig/no_client_CA1403=== CONT TestServerTLSConfig/not_a_PEM_file1404=== CONT TestServerTLSConfig/missing_CA_file1405--- PASS: TestServerTLSConfig (0.00s)1406 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1407 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1408 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1409=== CONT TestCacheConfigHandler/full_config,_no_issuer1410=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1411=== CONT TestCacheConfigHandler/no_signing_keys1412=== CONT TestCacheConfigHandler/no_cache_url_configured1413--- PASS: TestCacheConfigHandler (0.00s)1414 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1415 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1416 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1417 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1418=== CONT TestUploadHandlersRejectInvalidKeys1419=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1420=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1421=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1422=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1423=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1424=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1425=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1426=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1427=== CONT TestClientErrorHandling/InvalidStorePath14282026/07/19 09:48:54 OK 1_commit_pending_closure.sql (1.6ms)14292026/07/19 09:48:54 OK 2_object_stats_trigger.sql (989.29µs)14302026/07/19 09:48:54 goose: up to current file version: 214312026/07/19 09:48:54 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"14322026/07/19 09:48:54 WARN Failed to register uploaded object key=log/pqq6fd7q0plm6dyz3v4qly40kydxdrp1-test-script.drv error="server returned 404: 404 page not found\n"14332026/07/19 09:48:54 WARN Failed to register uploaded object key=9rh2ibfxga4a8fdg3igl9d18gi9fjpbx.ls error="server returned 404: 404 page not found\n"14342026/07/19 09:48:54 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14352026/07/19 09:48:54 INFO Signed narinfos id=1 count=114362026/07/19 09:48:54 INFO Uploading 1 narinfos14372026/07/19 09:48:54 INFO Created nix-cache-info in bucket bucket=bucket3914382026-07-19 09:48:54.132 UTC [88611] ERROR: relation "goose_db_version" does not exist at character 3614392026-07-19 09:48:54.132 UTC [88611] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14402026/07/19 09:48:54 WARN Failed to register uploaded object key=9rh2ibfxga4a8fdg3igl9d18gi9fjpbx.narinfo error="server returned 404: 404 page not found\n"14412026/07/19 09:48:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14422026/07/19 09:48:54 INFO Completed upload id=114432026/07/19 09:48:54 INFO Upload complete. (49ms)1444=== NAME TestClientWithDependencies1445 client_integration_test.go:597: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-88293-4258547180/TestClientWithDependencies2035512332/001/store) requires matching store prefix1446--- PASS: TestClientWithDependencies (0.80s)1447=== CONT TestClientErrorHandling/ServerNotAvailable14482026-07-19 09:48:54.147 UTC [88615] ERROR: relation "goose_db_version" does not exist at character 3614492026-07-19 09:48:54.147 UTC [88615] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14502026/07/19 09:48:54 OK 20241026095416_initial_model.sql (14.87ms)14512026/07/19 09:48:54 OK 20251210153512_drop_unused_gin_index.sql (438.46µs)14522026/07/19 09:48:54 OK 20251218171726_add_pins.sql (1.18ms)14532026/07/19 09:48:54 OK 20260628120000_add_object_size_and_stats.sql (2.68ms)14542026/07/19 09:48:54 goose: successfully migrated database to version: 2026062812000014552026/07/19 09:48:54 OK 1_commit_pending_closure.sql (935.5µs)14562026/07/19 09:48:54 OK 2_object_stats_trigger.sql (305.54µs)14572026/07/19 09:48:54 goose: up to current file version: 214582026-07-19 09:48:54.162 UTC [88617] ERROR: relation "goose_db_version" does not exist at character 3614592026-07-19 09:48:54.162 UTC [88617] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14602026/07/19 09:48:54 OK 20241026095416_initial_model.sql (15.04ms)14612026/07/19 09:48:54 OK 20251210153512_drop_unused_gin_index.sql (1.56ms)14622026/07/19 09:48:54 OK 20251218171726_add_pins.sql (14.17ms)1463=== NAME TestClientIntegration1464 client_integration_test.go:276: Created store path: /nix/var/nix/builds/nix-88293-4258547180/TestClientIntegration477443038/002/store/bibcqan2wkqy86vxwjs0mx0fa9x2c758-test-file.txt14652026/07/19 09:48:54 OK 20260628120000_add_object_size_and_stats.sql (19.99ms)14662026/07/19 09:48:54 goose: successfully migrated database to version: 2026062812000014672026/07/19 09:48:54 OK 1_commit_pending_closure.sql (11.41ms)14682026/07/19 09:48:54 OK 2_object_stats_trigger.sql (638.21µs)14692026/07/19 09:48:54 goose: up to current file version: 214702026/07/19 09:48:54 OK 20241026095416_initial_model.sql (23.16ms)14712026/07/19 09:48:54 OK 20251210153512_drop_unused_gin_index.sql (924.46µs)14722026/07/19 09:48:54 OK 20251218171726_add_pins.sql (1.03ms)1473--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.50s)1474=== CONT TestClientErrorHandling/InvalidAuthToken14752026/07/19 09:48:54 OK 20260628120000_add_object_size_and_stats.sql (2.21ms)14762026/07/19 09:48:54 goose: successfully migrated database to version: 2026062812000014772026-07-19 09:48:54.222 UTC [88621] ERROR: relation "goose_db_version" does not exist at character 3614782026-07-19 09:48:54.222 UTC [88621] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14792026/07/19 09:48:54 OK 1_commit_pending_closure.sql (2.12ms)14802026/07/19 09:48:54 OK 2_object_stats_trigger.sql (559.54µs)14812026/07/19 09:48:54 goose: up to current file version: 214822026/07/19 09:48:54 OK 20241026095416_initial_model.sql (5.31ms)14832026/07/19 09:48:54 OK 20251210153512_drop_unused_gin_index.sql (443.67µs)14842026/07/19 09:48:54 OK 20251218171726_add_pins.sql (1.52ms)14852026/07/19 09:48:54 OK 20260628120000_add_object_size_and_stats.sql (2.08ms)14862026/07/19 09:48:54 goose: successfully migrated database to version: 2026062812000014872026/07/19 09:48:54 OK 1_commit_pending_closure.sql (914.75µs)14882026/07/19 09:48:54 OK 2_object_stats_trigger.sql (289.75µs)14892026/07/19 09:48:54 goose: up to current file version: 21490--- PASS: TestReadProxyNarinfo (0.43s)1491=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token14922026/07/19 09:48:54 INFO OIDC auth successful provider=test1493=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected14942026/07/19 09:48:54 WARN Authentication failed token_preview=eyJhbGciOi...SUhml3BirQ 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]1495=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1496=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected14972026/07/19 09:48:54 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]1498=== CONT TestIsValidUploadKey/narinfo1499=== CONT TestProxyWriteTimeout/narinfo1500=== CONT TestIsValidUploadKey/unknown_type1501=== CONT TestIsValidUploadKey/empty_key1502=== CONT TestIsValidUploadKey/absolute1503=== CONT TestIsValidUploadKey/traversal_nar1504=== CONT TestIsValidUploadKey/traversal1505=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1506=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1507=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1508=== CONT TestIsValidUploadKey/index.html1509=== CONT TestIsValidUploadKey/nix-cache-info1510=== CONT TestIsValidUploadKey/realisation_plus_in_output1511=== CONT TestIsValidUploadKey/realisation1512=== CONT TestIsValidUploadKey/build_log_equals1513=== CONT TestIsValidUploadKey/build_log_question_mark1514=== CONT TestIsValidUploadKey/build_log_plus_in_name1515=== CONT TestIsValidUploadKey/build_log_home-manager_file1516=== CONT TestIsValidUploadKey/build_log1517=== CONT TestIsValidUploadKey/listing1518=== CONT TestIsValidUploadKey/nar_plain1519=== CONT TestIsValidUploadKey/nar_xz1520=== CONT TestIsValidUploadKey/nar_zst1521--- PASS: TestIsValidUploadKey (0.00s)1522 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1523 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1524 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1525 --- PASS: TestIsValidUploadKey/absolute (0.00s)1526 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1527 --- PASS: TestIsValidUploadKey/traversal (0.00s)1528 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1529 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1530 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1531 --- PASS: TestIsValidUploadKey/index.html (0.00s)1532 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1533 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1534 --- PASS: TestIsValidUploadKey/realisation (0.00s)1535 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1536 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1537 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1538 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1539 --- PASS: TestIsValidUploadKey/build_log (0.00s)1540 --- PASS: TestIsValidUploadKey/listing (0.00s)1541 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1542 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1543 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1544=== CONT TestProxyWriteTimeout/10_GiB_nar1545=== CONT TestProxyWriteTimeout/unknown_size1546=== CONT TestProxyWriteTimeout/1_GiB_nar1547--- PASS: TestService_AuthMiddleware_OIDC (0.32s)1548 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1549 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1550 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1551 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1552--- PASS: TestProxyWriteTimeout (0.00s)1553 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1554 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1555 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1556 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1557=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure15582026/07/19 09:48:54 INFO Received uploads request method=POST path=/1559--- PASS: TestResurrectedObjectNotDeleted (0.45s)1560=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts15612026/07/19 09:48:54 INFO Received request for more parts method=POST path=/1562=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart15632026/07/19 09:48:54 INFO Received complete multipart upload request method=POST path=/1564=== CONT TestParseSingleRange/none1565=== CONT TestParseSingleRange/open-ended1566=== CONT TestParseSingleRange/start_far_past_EOF1567=== CONT TestParseSingleRange/start_past_EOF1568=== CONT TestParseSingleRange/single_byte1569=== CONT TestParseSingleRange/suffix_exceeds_size1570=== CONT TestParseSingleRange/suffix1571=== CONT TestParseSingleRange/end_clamped_to_size1572=== CONT TestParseSingleRange/malformed_both_empty1573=== CONT TestParseSingleRange/closed1574=== CONT TestParseSingleRange/malformed_end_before_start1575=== CONT TestParseSingleRange/multi-range_ignored1576=== CONT TestParseSingleRange/malformed_no_dash1577=== CONT TestParseSingleRange/unknown_unit1578--- PASS: TestParseSingleRange (0.00s)1579 --- PASS: TestParseSingleRange/none (0.00s)1580 --- PASS: TestParseSingleRange/open-ended (0.00s)1581 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1582 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1583 --- PASS: TestParseSingleRange/single_byte (0.00s)1584 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1585 --- PASS: TestParseSingleRange/suffix (0.00s)1586 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1587 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1588 --- PASS: TestParseSingleRange/closed (0.00s)1589 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1590 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1591 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1592 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1593=== CONT TestIsValidCachePath/narinfo1594=== CONT TestIsValidCachePath/short_hash1595=== CONT TestIsValidCachePath/wrong_extension1596=== CONT TestIsValidCachePath/leading_slash1597=== CONT TestIsValidCachePath/empty1598=== CONT TestIsValidCachePath/random_path1599=== CONT TestIsValidCachePath/invalid_char_u1600=== CONT TestIsValidCachePath/invalid_char_e1601=== CONT TestIsValidCachePath/traversal_in_middle1602=== CONT TestIsValidCachePath/traversal_parent1603=== CONT TestIsValidCachePath/index.html1604=== CONT TestIsValidCachePath/nix-cache-info1605=== CONT TestIsValidCachePath/realisation1606=== CONT TestIsValidCachePath/log1607=== CONT TestIsValidCachePath/ls1608=== CONT TestIsValidCachePath/nar_uncompressed1609=== CONT TestIsValidCachePath/nar_bz21610=== CONT TestIsValidCachePath/nar_xz1611=== CONT TestIsValidCachePath/nar_zst1612=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1613--- PASS: TestIsValidCachePath (0.00s)1614 --- PASS: TestIsValidCachePath/narinfo (0.00s)1615 --- PASS: TestIsValidCachePath/short_hash (0.00s)1616 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1617 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1618 --- PASS: TestIsValidCachePath/empty (0.00s)1619 --- PASS: TestIsValidCachePath/random_path (0.00s)1620 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1621 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1622 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1623 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1624 --- PASS: TestIsValidCachePath/index.html (0.00s)1625 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1626 --- PASS: TestIsValidCachePath/realisation (0.00s)1627 --- PASS: TestIsValidCachePath/log (0.00s)1628 --- PASS: TestIsValidCachePath/ls (0.00s)1629 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1630 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1631 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1632 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1633 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1634=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16352026/07/19 09:48:54 INFO Received uploads request method=POST path=/1636=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16372026/07/19 09:48:54 INFO Received complete multipart upload request method=POST path=/1638=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16392026/07/19 09:48:54 INFO Received request for more parts method=POST path=/1640=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16412026/07/19 09:48:54 INFO Received uploads request method=POST path=/1642--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1643 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1644 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1645 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1646 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)16472026/07/19 09:48:54 INFO Received uploads request method=POST path=/api/pending_closures16482026/07/19 09:48:54 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16492026/07/19 09:48:54 INFO Uploading bibcqan2wkqy86vxwjs0mx0fa9x2c758-test-file.txt (152B)16502026/07/19 09:48:54 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"16512026/07/19 09:48:54 WARN Failed to register uploaded object key=bibcqan2wkqy86vxwjs0mx0fa9x2c758.ls error="server returned 404: 404 page not found\n"16522026/07/19 09:48:54 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16532026/07/19 09:48:54 INFO Signed narinfos id=1 count=116542026/07/19 09:48:54 INFO Uploading 1 narinfos16552026/07/19 09:48:54 WARN Failed to register uploaded object key=bibcqan2wkqy86vxwjs0mx0fa9x2c758.narinfo error="server returned 404: 404 page not found\n"16562026/07/19 09:48:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16572026/07/19 09:48:54 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_closures16582026/07/19 09:48:54 INFO Completed upload id=116592026/07/19 09:48:54 INFO Upload complete. (101ms)1660=== NAME TestClientIntegration1661 client_integration_test.go:292: Retrieved narinfo from S3:1662 StorePath: /nix/var/nix/builds/nix-88293-4258547180/TestClientIntegration477443038/002/store/bibcqan2wkqy86vxwjs0mx0fa9x2c758-test-file.txt1663 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1664 Compression: zstd1665 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11666 NarSize: 1521667 References: 1668 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11669 client_integration_test.go:293: Retrieved .ls file from S3 (compressed size: 77 bytes)1670 client_integration_test.go:293: Decompressed .ls content (64 bytes):1671 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1672 client_integration_test.go:296: Testing garbage collection...16732026-07-19 09:48:54.354 UTC [88635] ERROR: relation "goose_db_version" does not exist at character 3616742026-07-19 09:48:54.354 UTC [88635] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16752026/07/19 09:48:54 INFO Starting cleanup of old closures method=DELETE path=/api/closures16762026/07/19 09:48:54 INFO Garbage collection started16772026/07/19 09:48:54 INFO Aborted multipart uploads count=016782026-07-19 09:48:54.368 UTC [88637] ERROR: relation "goose_db_version" does not exist at character 3616792026-07-19 09:48:54.368 UTC [88637] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16802026/07/19 09:48:54 WARN Force mode enabled - objects will be deleted immediately without grace period16812026/07/19 09:48:54 OK 20241026095416_initial_model.sql (13.36ms)16822026/07/19 09:48:54 OK 20251210153512_drop_unused_gin_index.sql (808.54µs)16832026/07/19 09:48:54 OK 20251218171726_add_pins.sql (855.46µs)16842026/07/19 09:48:54 OK 20260628120000_add_object_size_and_stats.sql (2.52ms)16852026/07/19 09:48:54 goose: successfully migrated database to version: 2026062812000016862026/07/19 09:48:54 OK 20241026095416_initial_model.sql (4.03ms)16872026/07/19 09:48:54 OK 1_commit_pending_closure.sql (894.83µs)16882026/07/19 09:48:54 OK 20251210153512_drop_unused_gin_index.sql (420.71µs)16892026/07/19 09:48:54 OK 2_object_stats_trigger.sql (344.92µs)16902026/07/19 09:48:54 goose: up to current file version: 216912026/07/19 09:48:54 OK 20251218171726_add_pins.sql (848.25µs)16922026/07/19 09:48:54 OK 20260628120000_add_object_size_and_stats.sql (1.16ms)16932026/07/19 09:48:54 goose: successfully migrated database to version: 2026062812000016942026/07/19 09:48:54 OK 1_commit_pending_closure.sql (941.25µs)16952026/07/19 09:48:54 OK 2_object_stats_trigger.sql (267.96µs)16962026/07/19 09:48:54 goose: up to current file version: 216972026-07-19 09:48:54.389 UTC [88640] ERROR: relation "goose_db_version" does not exist at character 3616982026-07-19 09:48:54.389 UTC [88640] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16992026/07/19 09:48:54 OK 20241026095416_initial_model.sql (6.15ms)17002026/07/19 09:48:54 OK 20251210153512_drop_unused_gin_index.sql (357.38µs)17012026/07/19 09:48:54 OK 20251218171726_add_pins.sql (686.13µs)17022026/07/19 09:48:54 OK 20260628120000_add_object_size_and_stats.sql (1.25ms)17032026/07/19 09:48:54 goose: successfully migrated database to version: 2026062812000017042026/07/19 09:48:54 OK 1_commit_pending_closure.sql (852.33µs)17052026/07/19 09:48:54 OK 2_object_stats_trigger.sql (214.71µs)17062026/07/19 09:48:54 goose: up to current file version: 217072026/07/19 09:48:54 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=206.226925ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1708--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)1709 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1710 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1711 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.29s)17122026/07/19 09:48:54 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"1713=== NAME TestOrphanedObjectsGCStressTest1714 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1715 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion17162026/07/19 09:48:54 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=017172026/07/19 09:48:54 INFO Vacuumed table table=pending_closures17182026/07/19 09:48:54 INFO Vacuumed table table=pending_objects17192026/07/19 09:48:54 INFO Vacuumed table table=multipart_uploads17202026/07/19 09:48:54 INFO Vacuumed table table=closures17212026/07/19 09:48:54 INFO Vacuumed table table=objects1722=== NAME TestOrphanedObjectsGC1723 orphaned_objects_gc_test.go:290: GC Test Summary:1724 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1725 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1726 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1727 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1728 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1729--- PASS: TestOrphanedObjectsGC (0.51s)1730=== NAME TestOrphanedObjectsGCStressTest1731 orphaned_objects_gc_test.go:509: Stress test completed successfully:1732 orphaned_objects_gc_test.go:510: - Active objects preserved: 201733 orphaned_objects_gc_test.go:511: - Objects deleted: 2101734 orphaned_objects_gc_test.go:512: - Total GC'd: 2101735--- PASS: TestOrphanedObjectsGCStressTest (0.86s)17362026/07/19 09:48:54 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=377.181058ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures17372026/07/19 09:48:55 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=748.994755ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures17382026/07/19 09:48:55 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01739=== NAME TestPinProtectsFromGC1740 client_integration_test.go:709: Pin successfully protected closure from garbage collection1741--- PASS: TestPinProtectsFromGC (2.73s)17422026/07/19 09:48:55 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.534679417s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures17432026/07/19 09:48:56 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01744=== NAME TestClientIntegration1745 client_integration_test.go:303: Objects in database after GC:1746 client_integration_test.go:303: Successfully deleted all objects with GC --force1747--- PASS: TestClientIntegration (2.71s)17482026/07/19 09:48:56 WARN Rate limiter enabled after throttle name=s3-test rate=517492026/07/19 09:48:56 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1750=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1751 throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=101752 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001753--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.24s)1754--- PASS: TestClientErrorHandling (0.00s)1755 --- PASS: TestClientErrorHandling/InvalidStorePath (0.28s)1756 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.34s)1757 --- PASS: TestClientErrorHandling/ServerNotAvailable (3.17s)1758PASS1759{"timestamp":"2026-07-19T09:48:57.815055Z","level":"ERROR","fields":{"message":"Unknown connection IO error:Cancelled","peer_addr":"127.0.0.1:58905"},"target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":973,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}17602026-07-19 09:48:57.877 UTC [88329] LOG: received smart shutdown request17612026-07-19 09:48:57.878 UTC [88329] LOG: background worker "logical replication launcher" (PID 88339) exited with exit code 117622026-07-19 09:48:57.897 UTC [88334] LOG: shutting down17632026-07-19 09:48:57.897 UTC [88334] LOG: checkpoint starting: shutdown immediate17642026-07-19 09:48:58.963 UTC [88334] LOG: checkpoint complete: wrote 13434 buffers (82.0%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 13 recycled; write=0.785 s, sync=0.279 s, total=1.067 s; sync files=15167, longest=0.023 s, average=0.001 s; distance=212067 kB, estimate=212067 kB; lsn=0/E69E0D0, redo lsn=0/E69E0D017652026-07-19 09:48:58.968 UTC [88329] LOG: database system is shut down1766Running OIDC tests...1767=== RUN TestGlobMatch1768=== PAUSE TestGlobMatch1769=== RUN TestAudienceForIssuer1770=== PAUSE TestAudienceForIssuer1771=== RUN TestValidateToken_ValidToken1772=== PAUSE TestValidateToken_ValidToken1773=== RUN TestValidateToken_WrongAudience1774=== PAUSE TestValidateToken_WrongAudience1775=== RUN TestValidateToken_Expired1776=== PAUSE TestValidateToken_Expired1777=== RUN TestValidateToken_BoundClaimsMismatch1778=== PAUSE TestValidateToken_BoundClaimsMismatch1779=== RUN TestValidateToken_BoundSubjectMismatch1780=== PAUSE TestValidateToken_BoundSubjectMismatch1781=== RUN TestValidateToken_MultipleProviders1782=== PAUSE TestValidateToken_MultipleProviders1783=== RUN TestValidateToken_NoMatchingProvider1784=== PAUSE TestValidateToken_NoMatchingProvider1785=== CONT TestGlobMatch1786=== RUN TestGlobMatch/foo_foo1787=== PAUSE TestGlobMatch/foo_foo1788=== RUN TestGlobMatch/foo_bar1789=== PAUSE TestGlobMatch/foo_bar1790=== RUN TestGlobMatch/*_1791=== PAUSE TestGlobMatch/*_1792=== CONT TestValidateToken_BoundClaimsMismatch1793=== CONT TestValidateToken_MultipleProviders1794=== CONT TestValidateToken_WrongAudience1795=== RUN TestGlobMatch/*_anything1796=== PAUSE TestGlobMatch/*_anything1797=== RUN TestGlobMatch/foo*_foo1798=== PAUSE TestGlobMatch/foo*_foo1799=== RUN TestGlobMatch/foo*_foobar1800=== PAUSE TestGlobMatch/foo*_foobar1801=== RUN TestGlobMatch/foo*_bar1802=== PAUSE TestGlobMatch/foo*_bar1803=== RUN TestGlobMatch/*bar_bar1804=== CONT TestValidateToken_ValidToken1805=== PAUSE TestGlobMatch/*bar_bar1806=== RUN TestGlobMatch/*bar_foobar1807=== PAUSE TestGlobMatch/*bar_foobar1808=== RUN TestGlobMatch/*bar_foo1809=== PAUSE TestGlobMatch/*bar_foo1810=== RUN TestGlobMatch/foo*bar_foobar1811=== PAUSE TestGlobMatch/foo*bar_foobar1812=== RUN TestGlobMatch/foo*bar_foo123bar1813=== PAUSE TestGlobMatch/foo*bar_foo123bar1814=== RUN TestGlobMatch/foo*bar_foobarbaz1815=== PAUSE TestGlobMatch/foo*bar_foobarbaz1816=== CONT TestAudienceForIssuer1817--- PASS: TestAudienceForIssuer (0.00s)1818=== CONT TestValidateToken_NoMatchingProvider1819=== CONT TestValidateToken_Expired1820=== CONT TestValidateToken_BoundSubjectMismatch1821=== RUN TestGlobMatch/*/*_foo/bar1822=== PAUSE TestGlobMatch/*/*_foo/bar1823=== RUN TestGlobMatch/*/*_foo1824=== PAUSE TestGlobMatch/*/*_foo1825=== RUN TestGlobMatch/refs/heads/*_refs/heads/main1826=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main1827=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.01828=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.01829=== RUN TestGlobMatch/refs/*/main_refs/heads/main1830=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main1831=== RUN TestGlobMatch/fo?_foo1832=== PAUSE TestGlobMatch/fo?_foo1833=== RUN TestGlobMatch/fo?_fo1834=== PAUSE TestGlobMatch/fo?_fo1835=== RUN TestGlobMatch/fo?_fooo1836=== PAUSE TestGlobMatch/fo?_fooo1837=== RUN TestGlobMatch/?oo_foo1838=== PAUSE TestGlobMatch/?oo_foo1839=== RUN TestGlobMatch/?oo_boo1840=== PAUSE TestGlobMatch/?oo_boo1841=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1842=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1843=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1844=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1845=== CONT TestGlobMatch/foo_foo1846=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1847=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1848=== CONT TestGlobMatch/?oo_boo1849=== CONT TestGlobMatch/?oo_foo1850=== CONT TestGlobMatch/fo?_fooo1851=== CONT TestGlobMatch/fo?_fo1852=== CONT TestGlobMatch/fo?_foo1853=== CONT TestGlobMatch/refs/*/main_refs/heads/main1854=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.01855=== CONT TestGlobMatch/refs/heads/*_refs/heads/main1856=== CONT TestGlobMatch/*/*_foo1857=== CONT TestGlobMatch/*/*_foo/bar1858=== CONT TestGlobMatch/foo*bar_foobarbaz1859=== CONT TestGlobMatch/foo*bar_foo123bar1860=== CONT TestGlobMatch/foo*bar_foobar1861=== CONT TestGlobMatch/*bar_foo1862=== CONT TestGlobMatch/*bar_foobar1863=== CONT TestGlobMatch/*bar_bar1864=== CONT TestGlobMatch/foo*_bar1865=== CONT TestGlobMatch/foo*_foobar1866=== CONT TestGlobMatch/*_1867=== CONT TestGlobMatch/foo_bar1868=== CONT TestGlobMatch/*_anything1869=== CONT TestGlobMatch/foo*_foo1870--- PASS: TestGlobMatch (0.00s)1871 --- PASS: TestGlobMatch/foo_foo (0.00s)1872 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)1873 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)1874 --- PASS: TestGlobMatch/?oo_boo (0.00s)1875 --- PASS: TestGlobMatch/?oo_foo (0.00s)1876 --- PASS: TestGlobMatch/fo?_fooo (0.00s)1877 --- PASS: TestGlobMatch/fo?_fo (0.00s)1878 --- PASS: TestGlobMatch/fo?_foo (0.00s)1879 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)1880 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)1881 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)1882 --- PASS: TestGlobMatch/*/*_foo (0.00s)1883 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)1884 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)1885 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)1886 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)1887 --- PASS: TestGlobMatch/*bar_foo (0.00s)1888 --- PASS: TestGlobMatch/*bar_foobar (0.00s)1889 --- PASS: TestGlobMatch/*bar_bar (0.00s)1890 --- PASS: TestGlobMatch/foo*_bar (0.00s)1891 --- PASS: TestGlobMatch/foo*_foobar (0.00s)1892 --- PASS: TestGlobMatch/*_ (0.00s)1893 --- PASS: TestGlobMatch/foo_bar (0.00s)1894 --- PASS: TestGlobMatch/*_anything (0.00s)1895 --- PASS: TestGlobMatch/foo*_foo (0.00s)18962026/07/19 09:48:59 INFO OIDC provider initialized name=provider218972026/07/19 09:48:59 INFO OIDC provider initialized name=test18982026/07/19 09:48:59 INFO OIDC provider initialized name=test18992026/07/19 09:48:59 INFO OIDC provider initialized name=test19002026/07/19 09:48:59 INFO OIDC provider initialized name=provider119012026/07/19 09:48:59 INFO OIDC provider initialized name=test19022026/07/19 09:48:59 INFO OIDC provider initialized name=test19032026/07/19 09:48:59 INFO OIDC provider initialized name=provider11904--- PASS: TestValidateToken_Expired (0.01s)1905--- PASS: TestValidateToken_NoMatchingProvider (0.01s)1906--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)1907--- PASS: TestValidateToken_WrongAudience (0.01s)1908--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)1909--- PASS: TestValidateToken_ValidToken (0.01s)1910--- PASS: TestValidateToken_MultipleProviders (0.01s)1911PASS1912Running hook tests...1913=== RUN TestSendPathsEmpty1914=== PAUSE TestSendPathsEmpty1915=== RUN TestQueueEnqueueAndFetch1916=== PAUSE TestQueueEnqueueAndFetch1917=== RUN TestQueueDeduplication1918=== PAUSE TestQueueDeduplication1919=== RUN TestQueueRemove1920=== PAUSE TestQueueRemove1921=== RUN TestQueueFetchBatchLimit1922=== PAUSE TestQueueFetchBatchLimit1923=== RUN TestQueueFetchRemoveLifecycle1924=== PAUSE TestQueueFetchRemoveLifecycle1925=== RUN TestQueueConcurrentWriters1926=== PAUSE TestQueueConcurrentWriters1927=== RUN TestServerClientIntegration1928=== PAUSE TestServerClientIntegration1929=== RUN TestServerQueueError1930=== PAUSE TestServerQueueError1931=== RUN TestGetListenerSocketActivation1932 server_test.go:210: === RUN TestGetListenerSocketActivation1933 --- PASS: TestGetListenerSocketActivation (0.00s)1934 PASS1935 1936--- PASS: TestGetListenerSocketActivation (0.01s)1937=== RUN TestWorkerUploadsAndRemoves1938=== PAUSE TestWorkerUploadsAndRemoves1939=== RUN TestWorkerSkipsGCdPaths1940=== PAUSE TestWorkerSkipsGCdPaths1941=== RUN TestWorkerPrunesClosureDeps1942=== PAUSE TestWorkerPrunesClosureDeps1943=== CONT TestSendPathsEmpty1944=== CONT TestQueueConcurrentWriters1945--- PASS: TestSendPathsEmpty (0.00s)1946=== CONT TestQueueFetchRemoveLifecycle1947=== CONT TestQueueFetchBatchLimit1948=== CONT TestQueueRemove1949=== CONT TestQueueDeduplication1950=== CONT TestQueueEnqueueAndFetch1951=== CONT TestWorkerPrunesClosureDeps1952=== CONT TestWorkerSkipsGCdPaths1953=== CONT TestServerQueueError1954=== CONT TestWorkerUploadsAndRemoves19552026/07/19 09:49:00 ERROR Failed to queue paths error="permission denied" count=11956--- PASS: TestServerQueueError (0.00s)1957=== CONT TestServerClientIntegration1958--- PASS: TestServerClientIntegration (0.00s)1959--- PASS: TestQueueEnqueueAndFetch (0.01s)19602026/07/19 09:49:00 INFO Upload queue status pending=219612026/07/19 09:49:00 INFO Uploading batch count=219622026/07/19 09:49:00 INFO Upload queue status pending=219632026/07/19 09:49:00 INFO Upload queue status pending=219642026/07/19 09:49:00 INFO Uploading batch count=119652026/07/19 09:49:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-88293-4258547180/TestWorkerSkipsGCdPaths4262887702/002/nonexistent1966--- PASS: TestQueueDeduplication (0.01s)1967--- PASS: TestQueueFetchBatchLimit (0.01s)19682026/07/19 09:49:00 INFO Uploading batch count=11969--- PASS: TestQueueRemove (0.01s)1970--- PASS: TestQueueFetchRemoveLifecycle (0.01s)1971--- PASS: TestWorkerSkipsGCdPaths (0.06s)1972--- PASS: TestWorkerPrunesClosureDeps (0.06s)1973--- PASS: TestWorkerUploadsAndRemoves (0.06s)1974--- PASS: TestQueueConcurrentWriters (0.16s)1975PASS