niks3-go-unit-tests
aarch64-darwin.go-unit-tests
· build #94
· 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 TestResolveStorePath72=== CONT TestConvertHashToNix3273=== RUN TestConvertHashToNix32/SRI_format_to_Nix3274=== CONT TestParsePathInfoJSONMultiplePaths75=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix3276=== CONT TestParsePathInfoJSON77=== CONT TestPathInfoHashCompatibility78=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)79=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths80=== CONT TestGetStorePathHash81=== RUN TestGetStorePathHash/valid_store_path82=== PAUSE TestGetStorePathHash/valid_store_path83=== RUN TestGetStorePathHash/basename_without_hyphen_should_error84=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths85=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error86=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths87=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error88=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths89=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error90=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error91=== CONT TestPathInfoCACompatibility92=== RUN TestPathInfoCACompatibility/null_ca_field93=== CONT TestSetClientTLSDoesNotMutateDefaultTransport94=== PAUSE TestPathInfoCACompatibility/null_ca_field95=== RUN TestPathInfoCACompatibility/old_string_format_-_text96=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text97=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive98=== CONT TestRateLimiterFeedback99=== RUN TestRateLimiterFeedback/429_enables_limiter100=== PAUSE TestRateLimiterFeedback/429_enables_limiter101=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive102=== RUN TestRateLimiterFeedback/503_enables_limiter103=== PAUSE TestRateLimiterFeedback/503_enables_limiter104=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter105=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter106=== RUN TestPathInfoCACompatibility/new_structured_format_-_text107=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter108=== RUN TestConvertHashToNix32/already_Nix32_format109=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess110=== PAUSE TestConvertHashToNix32/already_Nix32_format111=== RUN TestConvertHashToNix32/invalid_format112=== PAUSE TestConvertHashToNix32/invalid_format113=== CONT TestFileTokenReadsAndCaches114=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text115=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method116=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method117=== RUN TestParsePathInfoJSON/Nix_format118=== PAUSE TestParsePathInfoJSON/Nix_format119=== RUN TestParsePathInfoJSON/Lix_format120=== PAUSE TestParsePathInfoJSON/Lix_format121=== RUN TestParsePathInfoJSON/empty_input1222026/07/09 07:43:50 WARN Rate limiter enabled after throttle name=server-test rate=5123=== PAUSE TestParsePathInfoJSON/empty_input124=== RUN TestParsePathInfoJSON/whitespace_only125=== PAUSE TestParsePathInfoJSON/whitespace_only126=== RUN TestParsePathInfoJSON/invalid_JSON127=== PAUSE TestParsePathInfoJSON/invalid_JSON128=== CONT TestStaticToken129--- PASS: TestStaticToken (0.00s)130=== CONT TestDumpPathSingleFile131=== CONT TestSetClientTLSErrors132=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)133=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon134=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon135=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI136=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI137=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512138=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512139=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error140=== CONT TestEncodeNixBase32WithRealHash141--- PASS: TestEncodeNixBase32WithRealHash (0.00s)142=== CONT TestDumpPathWriterError143--- PASS: TestResolveStorePath (0.00s)144=== CONT TestFileTokenMissing145=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter146=== CONT TestScriptTokenEmptyCommand147--- PASS: TestScriptTokenEmptyCommand (0.00s)148=== CONT TestScriptTokenScriptFails149=== CONT TestEncodeNixBase32150=== RUN TestEncodeNixBase32/test_string_hash151=== PAUSE TestEncodeNixBase32/test_string_hash152=== RUN TestEncodeNixBase32/empty_input153=== PAUSE TestEncodeNixBase32/empty_input154=== CONT TestScriptTokenBadJSON155--- PASS: TestFileTokenMissing (0.00s)156=== CONT TestScriptTokenEmptyToken157--- PASS: TestFileTokenReadsAndCaches (0.00s)158=== CONT TestScriptTokenCachesUntilRefresh159--- PASS: TestDoServerRequestAttachesToken (0.01s)160=== CONT TestScriptTokenNoExpiryRerunsEveryCall161=== RUN TestSetClientTLSErrors/missing_cert_file162=== PAUSE TestSetClientTLSErrors/missing_cert_file163=== RUN TestSetClientTLSErrors/missing_key_file164=== PAUSE TestSetClientTLSErrors/missing_key_file165=== RUN TestSetClientTLSErrors/missing_ca_file166=== PAUSE TestSetClientTLSErrors/missing_ca_file167=== RUN TestSetClientTLSErrors/invalid_ca_file168=== PAUSE TestSetClientTLSErrors/invalid_ca_file169=== CONT TestFileTokenEmpty170--- PASS: TestFileTokenEmpty (0.00s)171=== CONT TestUploadMultipart_SupersededByPeer172--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)173=== CONT TestDumpPathMatchesNix174=== RUN TestUploadMultipart_SupersededByPeer/exists175=== PAUSE TestUploadMultipart_SupersededByPeer/exists176=== RUN TestUploadMultipart_SupersededByPeer/missing177=== PAUSE TestUploadMultipart_SupersededByPeer/missing178=== CONT TestShellSplitErrors179--- PASS: TestShellSplitErrors (0.00s)180=== CONT TestSetClientTLS181--- PASS: TestScriptTokenScriptFails (0.01s)182=== CONT TestCaseHackSuffix183=== RUN TestSetClientTLS/rejects_connection_without_client_cert184=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert185=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA186=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA187=== RUN TestSetClientTLS/preserves_debug_logging_transport188=== PAUSE TestSetClientTLS/preserves_debug_logging_transport189=== CONT TestShellSplit190--- PASS: TestShellSplit (0.00s)191=== CONT TestDoWithRetry_BodyReplayedViaGetBody1922026/07/09 07:43:50 WARN Rate limiter enabled after throttle name=server-test rate=51932026/07/09 07:43:50 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:524091942026/07/09 07:43:50 WARN Rate limiter backed off name=server-test rate=51952026/07/09 07:43:50 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:52409196--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)197=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths198=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths199--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)200 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)201 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)202=== CONT TestPartSizeForNAR203=== RUN TestPartSizeForNAR/zero_stays_at_minimum204=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum205=== RUN TestPartSizeForNAR/small_stays_at_minimum206=== PAUSE TestPartSizeForNAR/small_stays_at_minimum207=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum208=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum209=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts210=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts211=== RUN TestPartSizeForNAR/1_TiB212=== PAUSE TestPartSizeForNAR/1_TiB213=== RUN TestPartSizeForNAR/5_TiB_S3_max_object214=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object215=== RUN TestPartSizeForNAR/capped_at_5_GiB216=== PAUSE TestPartSizeForNAR/capped_at_5_GiB217=== CONT TestConvertHashToNix32/SRI_format_to_Nix32218=== CONT TestPathInfoCACompatibility/null_ca_field219=== CONT TestParsePathInfoJSON/Nix_format220=== CONT TestParsePathInfoJSON/whitespace_only221=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)222=== CONT TestPathInfoCACompatibility/old_string_format_-_text223=== CONT TestGetStorePathHash/valid_store_path224=== CONT TestParsePathInfoJSON/empty_input225=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive226=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method227=== CONT TestPathInfoCACompatibility/new_structured_format_-_text228--- PASS: TestPathInfoCACompatibility (0.00s)229 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)230 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)231 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)232 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)233 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)234=== CONT TestConvertHashToNix32/invalid_format235=== CONT TestParsePathInfoJSON/invalid_JSON236=== CONT TestRateLimiterFeedback/429_enables_limiter2372026/07/09 07:43:50 WARN Rate limiter enabled after throttle name=server-test rate=52382026/07/09 07:43:50 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:524112392026/07/09 07:43:50 WARN Rate limiter backed off name=server-test rate=5240=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512241=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI242=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon243--- PASS: TestPathInfoHashCompatibility (0.00s)244 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)245 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)246 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)247 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)248=== CONT TestConvertHashToNix32/already_Nix32_format249--- PASS: TestConvertHashToNix32 (0.00s)250 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)251 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)252 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)253=== CONT TestParsePathInfoJSON/Lix_format254--- PASS: TestParsePathInfoJSON (0.00s)255 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)256 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)257 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)258 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)259 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)260=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter261=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter262=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error263=== CONT TestEncodeNixBase32/test_string_hash264=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error265=== CONT TestGetStorePathHash/basename_without_hyphen_should_error266--- PASS: TestGetStorePathHash (0.00s)267 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)268 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)269 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)270 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)271=== CONT TestRateLimiterFeedback/503_enables_limiter2722026/07/09 07:43:50 WARN Rate limiter enabled after throttle name=server-test rate=52732026/07/09 07:43:50 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:524172742026/07/09 07:43:50 WARN Rate limiter backed off name=server-test rate=5275--- PASS: TestRateLimiterFeedback (0.00s)276 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)277 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)278 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)279 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)280=== CONT TestEncodeNixBase32/empty_input281--- PASS: TestEncodeNixBase32 (0.00s)282 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)283 --- PASS: TestEncodeNixBase32/empty_input (0.00s)284=== CONT TestSetClientTLSErrors/missing_cert_file285=== CONT TestSetClientTLSErrors/missing_ca_file286=== CONT TestSetClientTLSErrors/invalid_ca_file287=== CONT TestSetClientTLSErrors/missing_key_file288=== CONT TestUploadMultipart_SupersededByPeer/exists289--- PASS: TestScriptTokenEmptyToken (0.01s)290=== CONT TestUploadMultipart_SupersededByPeer/missing291--- PASS: TestSetClientTLSErrors (0.01s)292 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)293 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)294 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)295 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)296--- PASS: TestScriptTokenBadJSON (0.02s)297=== CONT TestSetClientTLS/rejects_connection_without_client_cert298=== CONT TestSetClientTLS/preserves_debug_logging_transport299--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)300 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)301 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)302=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA303=== CONT TestPartSizeForNAR/zero_stays_at_minimum304=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts305=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum306=== CONT TestPartSizeForNAR/small_stays_at_minimum307=== CONT TestPartSizeForNAR/1_TiB308=== CONT TestPartSizeForNAR/5_TiB_S3_max_object309=== CONT TestPartSizeForNAR/capped_at_5_GiB310--- PASS: TestPartSizeForNAR (0.00s)311 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)312 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)313 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)314 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)315 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)316 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)317 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)3182026/07/09 07:43:50 http: TLS handshake error from 127.0.0.1:52422: remote error: tls: bad certificate319--- PASS: TestSetClientTLS (0.00s)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.02s)323--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)324--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)325--- PASS: TestDumpPathWriterError (0.04s)326--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)327--- PASS: TestDumpPathSingleFile (7.68s)328--- PASS: TestCaseHackSuffix (7.68s)329--- PASS: TestDumpPathMatchesNix (7.69s)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-24890-4261754756/postgres3481107692/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-24890-4261754756/postgres3481107692/data -l logfile start3583592026-07-09 07:44:06.400 UTC [25586] LOG: starting PostgreSQL 18.4 on aarch64-apple-darwin25.3.0, compiled by clang version 21.1.8, 64-bit3602026-07-09 07:44:06.400 UTC [25586] LOG: listening on Unix socket "/nix/var/nix/builds/nix-24890-4261754756/postgres3481107692/.s.PGSQL.5432"3612026-07-09 07:44:06.408 UTC [25594] LOG: database system was shut down at 2026-07-09 07:44:06 UTC3622026-07-09 07:44:06.410 UTC [25586] LOG: database system is ready to accept connections363/nix/var/nix/builds/nix-24890-4261754756/postgres3481107692:5432 - accepting connections364<jemalloc>: option background_thread currently supports pthread only365{"timestamp":"2026-07-09T07:44:08.566597Z","level":"ERROR","fields":{"message":"list_path_raw: revjob err VolumeNotFound"},"target":"rustfs_ecstore::cache_value::metacache_set","filename":"crates/ecstore/src/cache_value/metacache_set.rs","line_number":486,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}366=== RUN TestService_AuthMiddleware367=== PAUSE TestService_AuthMiddleware368=== RUN TestService_AuthMiddleware_MTLSProxyHeader369=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader370=== RUN TestService_AuthMiddleware_MTLSBoundSubjects371=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects372=== RUN TestService_ReadAuthMiddleware373=== PAUSE TestService_ReadAuthMiddleware374=== RUN TestService_AuthMiddleware_OIDC375=== PAUSE TestService_AuthMiddleware_OIDC376=== RUN TestCacheConfigHandler377=== PAUSE TestCacheConfigHandler378=== RUN TestCacheStatsHandler379=== PAUSE TestCacheStatsHandler380=== RUN TestClientCADerivations381=== PAUSE TestClientCADerivations382=== RUN TestClientErrorHandling383=== PAUSE TestClientErrorHandling384=== RUN TestClientIntegration385=== PAUSE TestClientIntegration386=== RUN TestClientMultipleUploads387=== PAUSE TestClientMultipleUploads388=== RUN TestClientWithDependencies389=== PAUSE TestClientWithDependencies390=== RUN TestPinProtectsFromGC391=== PAUSE TestPinProtectsFromGC392=== RUN TestGCAdvisoryLockBlocksConcurrentRun3932026-07-09 07:44:09.945 UTC [25763] ERROR: relation "goose_db_version" does not exist at character 363942026-07-09 07:44:09.945 UTC [25763] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC3952026/07/09 07:44:09 OK 20241026095416_initial_model.sql (9.09ms)3962026/07/09 07:44:09 OK 20251210153512_drop_unused_gin_index.sql (1.08ms)3972026/07/09 07:44:09 OK 20251218171726_add_pins.sql (2.53ms)3982026/07/09 07:44:09 OK 20260628120000_add_object_size_and_stats.sql (2.72ms)3992026/07/09 07:44:09 goose: successfully migrated database to version: 202606281200004002026/07/09 07:44:09 OK 1_commit_pending_closure.sql (2.47ms)4012026/07/09 07:44:09 OK 2_object_stats_trigger.sql (598.92µs)4022026/07/09 07:44:09 goose: up to current file version: 2403--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (1.39s)404=== RUN TestGCBugBareHashReferences405=== PAUSE TestGCBugBareHashReferences406=== RUN TestGCMetrics407=== PAUSE TestGCMetrics408=== RUN TestGCTaskStore_StartNew409=== PAUSE TestGCTaskStore_StartNew410=== RUN TestGCTaskStore_DeduplicateSameParams411=== PAUSE TestGCTaskStore_DeduplicateSameParams412=== RUN TestGCTaskStore_ConflictDifferentParams413=== PAUSE TestGCTaskStore_ConflictDifferentParams414=== RUN TestGCTaskStore_GetEmpty415=== PAUSE TestGCTaskStore_GetEmpty416=== RUN TestGCTaskStore_GetReturnsLatest417=== PAUSE TestGCTaskStore_GetReturnsLatest418=== RUN TestGCTaskStore_CompletedAllowsNewTask419=== PAUSE TestGCTaskStore_CompletedAllowsNewTask420=== RUN TestGCTaskStore_PhaseUpdates421=== PAUSE TestGCTaskStore_PhaseUpdates422=== RUN TestGCTaskStore_Fail423=== PAUSE TestGCTaskStore_Fail424=== RUN TestGracefulShutdownDrainsInflight425=== PAUSE TestGracefulShutdownDrainsInflight426=== RUN TestService_healthCheckHandler427=== PAUSE TestService_healthCheckHandler428=== RUN TestGenerateLandingPage429=== PAUSE TestGenerateLandingPage430=== RUN TestNARDeduplicationMetadataUploadBug431=== PAUSE TestNARDeduplicationMetadataUploadBug432=== RUN TestMetricsInventory433=== PAUSE TestMetricsInventory434=== RUN TestService_NativeMTLS435=== PAUSE TestService_NativeMTLS436=== RUN TestServerTLSConfig437=== PAUSE TestServerTLSConfig438=== RUN TestMultipartCleanup439=== PAUSE TestMultipartCleanup440=== RUN TestObjectStatsTrigger441=== PAUSE TestObjectStatsTrigger442=== RUN TestOrphanedObjectsGC443=== PAUSE TestOrphanedObjectsGC444=== RUN TestOrphanedObjectsGCStressTest445=== PAUSE TestOrphanedObjectsGCStressTest446=== RUN TestResurrectedObjectNotDeleted447=== PAUSE TestResurrectedObjectNotDeleted448=== RUN TestParseSingleRange449=== PAUSE TestParseSingleRange450=== RUN TestIsValidCachePath451=== PAUSE TestIsValidCachePath452=== RUN TestReadProxyNarinfo453=== PAUSE TestReadProxyNarinfo454=== RUN TestReadProxyNarinfoAlreadyDecompressed455=== PAUSE TestReadProxyNarinfoAlreadyDecompressed456=== RUN TestReadProxyNarStreaming457=== PAUSE TestReadProxyNarStreaming458=== RUN TestReadProxy404459=== PAUSE TestReadProxy404460=== RUN TestReadProxyInvalidPath461=== PAUSE TestReadProxyInvalidPath462=== RUN TestReadProxyHead463=== PAUSE TestReadProxyHead464=== RUN TestReadProxyConditionalGet465=== PAUSE TestReadProxyConditionalGet466=== RUN TestReadProxyRootRedirectsToIndexHTML467=== PAUSE TestReadProxyRootRedirectsToIndexHTML468=== RUN TestReadProxyDisabled469=== PAUSE TestReadProxyDisabled470=== RUN TestReadProxyRangeRequest471=== PAUSE TestReadProxyRangeRequest472=== RUN TestRedundantMultipartUpload473=== PAUSE TestRedundantMultipartUpload474=== RUN TestCompleteMultipartUpload_ErrorButObjectExists475=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists476=== RUN TestService_Rustfstest477=== PAUSE TestService_Rustfstest478=== RUN TestSystemdListenerNotActivated479--- PASS: TestSystemdListenerNotActivated (0.00s)480=== RUN TestWatchdogBeatsWhenHealthy481--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)482=== RUN TestWatchdogSkipsWhenUnhealthy4832026/07/09 07:44:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"4842026/07/09 07:44:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"4852026/07/09 07:44:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"4862026/07/09 07:44:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"4872026/07/09 07:44:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"4882026/07/09 07:44:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"4892026/07/09 07:44:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"4902026/07/09 07:44:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"4912026/07/09 07:44:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"4922026/07/09 07:44:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"493--- PASS: TestWatchdogSkipsWhenUnhealthy (0.21s)494=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle495=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle496=== RUN TestProxyWriteTimeout497=== PAUSE TestProxyWriteTimeout498=== RUN TestIsValidUploadKey499=== PAUSE TestIsValidUploadKey500=== RUN TestUploadHandlersRejectInvalidKeys501=== PAUSE TestUploadHandlersRejectInvalidKeys502=== RUN TestUploadHandlersRejectOversizedBody503=== PAUSE TestUploadHandlersRejectOversizedBody504=== RUN TestService_cleanupPendingClosuresHandler505=== PAUSE TestService_cleanupPendingClosuresHandler506=== RUN TestService_createPendingClosureHandler507=== PAUSE TestService_createPendingClosureHandler508=== RUN TestService_verifyS3Integrity509=== PAUSE TestService_verifyS3Integrity510=== RUN TestCompleteMultipartUnregistered511=== PAUSE TestCompleteMultipartUnregistered512=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT513=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT514=== CONT TestService_AuthMiddleware515=== CONT TestMultipartCleanup516=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT517=== CONT TestCompleteMultipartUnregistered518=== CONT TestService_verifyS3Integrity519=== CONT TestService_createPendingClosureHandler520=== CONT TestService_cleanupPendingClosuresHandler521=== CONT TestUploadHandlersRejectOversizedBody522=== CONT TestUploadHandlersRejectInvalidKeys523=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info524=== CONT TestIsValidUploadKey525=== RUN TestIsValidUploadKey/narinfo526=== PAUSE TestIsValidUploadKey/narinfo527=== RUN TestIsValidUploadKey/nar_zst528=== PAUSE TestIsValidUploadKey/nar_zst529=== RUN TestIsValidUploadKey/nar_xz530=== PAUSE TestIsValidUploadKey/nar_xz531=== RUN TestIsValidUploadKey/nar_plain532=== PAUSE TestIsValidUploadKey/nar_plain533=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info534=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal535=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal536=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key537=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key538=== RUN TestIsValidUploadKey/listing539=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key540=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key541=== CONT TestProxyWriteTimeout542=== RUN TestProxyWriteTimeout/narinfo543=== PAUSE TestProxyWriteTimeout/narinfo544=== RUN TestProxyWriteTimeout/1_GiB_nar545=== PAUSE TestProxyWriteTimeout/1_GiB_nar546=== RUN TestProxyWriteTimeout/10_GiB_nar547=== PAUSE TestProxyWriteTimeout/10_GiB_nar548=== RUN TestProxyWriteTimeout/unknown_size549=== PAUSE TestProxyWriteTimeout/unknown_size550=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle551=== PAUSE TestIsValidUploadKey/listing552=== RUN TestIsValidUploadKey/build_log553=== PAUSE TestIsValidUploadKey/build_log554=== RUN TestIsValidUploadKey/build_log_home-manager_file555=== PAUSE TestIsValidUploadKey/build_log_home-manager_file556=== RUN TestIsValidUploadKey/build_log_plus_in_name557=== PAUSE TestIsValidUploadKey/build_log_plus_in_name558=== RUN TestIsValidUploadKey/build_log_question_mark559=== PAUSE TestIsValidUploadKey/build_log_question_mark560=== RUN TestIsValidUploadKey/build_log_equals561=== PAUSE TestIsValidUploadKey/build_log_equals562=== RUN TestIsValidUploadKey/realisation563=== PAUSE TestIsValidUploadKey/realisation564=== RUN TestIsValidUploadKey/realisation_plus_in_output565=== PAUSE TestIsValidUploadKey/realisation_plus_in_output566=== RUN TestIsValidUploadKey/nix-cache-info567=== PAUSE TestIsValidUploadKey/nix-cache-info568=== RUN TestIsValidUploadKey/index.html569=== PAUSE TestIsValidUploadKey/index.html570=== RUN TestIsValidUploadKey/narinfo_key,_nar_type571=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type572=== RUN TestIsValidUploadKey/nar_key,_narinfo_type573=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type574=== RUN TestIsValidUploadKey/listing_key,_narinfo_type575=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type576=== RUN TestIsValidUploadKey/traversal577=== PAUSE TestIsValidUploadKey/traversal578=== RUN TestIsValidUploadKey/traversal_nar579=== PAUSE TestIsValidUploadKey/traversal_nar580=== RUN TestIsValidUploadKey/absolute581=== PAUSE TestIsValidUploadKey/absolute582=== RUN TestIsValidUploadKey/empty_key583=== PAUSE TestIsValidUploadKey/empty_key584=== RUN TestIsValidUploadKey/unknown_type585=== PAUSE TestIsValidUploadKey/unknown_type586=== CONT TestService_Rustfstest587=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure588=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure589=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart590=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart591=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts592=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts593=== CONT TestCompleteMultipartUpload_ErrorButObjectExists5942026-07-09 07:44:10.561 UTC [25806] ERROR: relation "goose_db_version" does not exist at character 365952026-07-09 07:44:10.561 UTC [25806] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5962026-07-09 07:44:10.574 UTC [25808] ERROR: relation "goose_db_version" does not exist at character 365972026-07-09 07:44:10.574 UTC [25808] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5982026-07-09 07:44:10.587 UTC [25809] ERROR: relation "goose_db_version" does not exist at character 365992026-07-09 07:44:10.587 UTC [25809] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6002026-07-09 07:44:10.588 UTC [25810] ERROR: relation "goose_db_version" does not exist at character 366012026-07-09 07:44:10.588 UTC [25810] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6022026-07-09 07:44:10.596 UTC [25814] ERROR: relation "goose_db_version" does not exist at character 366032026-07-09 07:44:10.596 UTC [25814] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6042026-07-09 07:44:10.598 UTC [25813] ERROR: relation "goose_db_version" does not exist at character 366052026-07-09 07:44:10.598 UTC [25813] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6062026-07-09 07:44:10.602 UTC [25815] ERROR: relation "goose_db_version" does not exist at character 366072026-07-09 07:44:10.602 UTC [25815] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6082026-07-09 07:44:10.604 UTC [25812] ERROR: relation "goose_db_version" does not exist at character 366092026-07-09 07:44:10.604 UTC [25812] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6102026-07-09 07:44:10.610 UTC [25816] ERROR: relation "goose_db_version" does not exist at character 366112026-07-09 07:44:10.610 UTC [25816] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6122026-07-09 07:44:10.618 UTC [25817] ERROR: relation "goose_db_version" does not exist at character 366132026-07-09 07:44:10.618 UTC [25817] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6142026/07/09 07:44:10 OK 20241026095416_initial_model.sql (14.14ms)6152026/07/09 07:44:10 OK 20241026095416_initial_model.sql (16.25ms)6162026/07/09 07:44:10 OK 20251210153512_drop_unused_gin_index.sql (1.74ms)6172026/07/09 07:44:10 OK 20251210153512_drop_unused_gin_index.sql (1.46ms)6182026/07/09 07:44:10 OK 20251218171726_add_pins.sql (2.68ms)6192026/07/09 07:44:10 OK 20251218171726_add_pins.sql (4ms)6202026/07/09 07:44:10 OK 20241026095416_initial_model.sql (11.36ms)6212026/07/09 07:44:10 OK 20260628120000_add_object_size_and_stats.sql (3.61ms)6222026/07/09 07:44:10 goose: successfully migrated database to version: 202606281200006232026/07/09 07:44:10 OK 20241026095416_initial_model.sql (11.98ms)6242026/07/09 07:44:10 OK 20241026095416_initial_model.sql (11.35ms)6252026/07/09 07:44:10 OK 20251210153512_drop_unused_gin_index.sql (1.06ms)6262026/07/09 07:44:10 OK 20251210153512_drop_unused_gin_index.sql (903.67µs)6272026/07/09 07:44:10 OK 20251210153512_drop_unused_gin_index.sql (1.02ms)6282026/07/09 07:44:10 OK 20241026095416_initial_model.sql (11.35ms)6292026/07/09 07:44:10 OK 1_commit_pending_closure.sql (2.14ms)6302026/07/09 07:44:10 OK 20260628120000_add_object_size_and_stats.sql (2.79ms)6312026/07/09 07:44:10 goose: successfully migrated database to version: 202606281200006322026/07/09 07:44:10 OK 20241026095416_initial_model.sql (10.39ms)6332026/07/09 07:44:10 OK 20241026095416_initial_model.sql (11.79ms)6342026/07/09 07:44:10 OK 2_object_stats_trigger.sql (812µs)6352026/07/09 07:44:10 goose: up to current file version: 26362026/07/09 07:44:10 OK 20251210153512_drop_unused_gin_index.sql (806.17µs)6372026/07/09 07:44:10 OK 20251210153512_drop_unused_gin_index.sql (1.13ms)6382026/07/09 07:44:10 OK 20251218171726_add_pins.sql (2.53ms)6392026/07/09 07:44:10 OK 20251218171726_add_pins.sql (2.82ms)6402026/07/09 07:44:10 OK 20251210153512_drop_unused_gin_index.sql (1.04ms)6412026/07/09 07:44:10 OK 1_commit_pending_closure.sql (1.83ms)6422026/07/09 07:44:10 OK 20241026095416_initial_model.sql (12.79ms)6432026/07/09 07:44:10 OK 20251218171726_add_pins.sql (2.66ms)6442026/07/09 07:44:10 OK 2_object_stats_trigger.sql (617.42µs)6452026/07/09 07:44:10 goose: up to current file version: 26462026/07/09 07:44:10 OK 20251218171726_add_pins.sql (2.04ms)6472026/07/09 07:44:10 OK 20251218171726_add_pins.sql (2.52ms)6482026/07/09 07:44:10 OK 20251210153512_drop_unused_gin_index.sql (1.11ms)6492026/07/09 07:44:10 INFO Received uploads request method=POST path=/api/pending_closures6502026/07/09 07:44:10 OK 20241026095416_initial_model.sql (10.56ms)6512026/07/09 07:44:10 INFO Received uploads request method=POST path=/api/pending_closures6522026/07/09 07:44:10 INFO Received uploads request method=POST path=/api/pending_closures6532026/07/09 07:44:10 OK 20260628120000_add_object_size_and_stats.sql (2.51ms)6542026/07/09 07:44:10 goose: successfully migrated database to version: 202606281200006552026/07/09 07:44:10 OK 20260628120000_add_object_size_and_stats.sql (2.79ms)6562026/07/09 07:44:10 goose: successfully migrated database to version: 202606281200006572026/07/09 07:44:10 OK 20251218171726_add_pins.sql (2.92ms)6582026/07/09 07:44:10 OK 20260628120000_add_object_size_and_stats.sql (2.38ms)6592026/07/09 07:44:10 goose: successfully migrated database to version: 202606281200006602026/07/09 07:44:10 OK 20251210153512_drop_unused_gin_index.sql (1.04ms)6612026/07/09 07:44:10 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"662--- PASS: TestService_AuthMiddleware (0.43s)663=== CONT TestRedundantMultipartUpload6642026/07/09 07:44:10 OK 20260628120000_add_object_size_and_stats.sql (2.98ms)6652026/07/09 07:44:10 OK 1_commit_pending_closure.sql (1.96ms)6662026/07/09 07:44:10 OK 20260628120000_add_object_size_and_stats.sql (2.59ms)6672026/07/09 07:44:10 goose: successfully migrated database to version: 202606281200006682026/07/09 07:44:10 goose: successfully migrated database to version: 202606281200006692026/07/09 07:44:10 OK 1_commit_pending_closure.sql (2.42ms)6702026/07/09 07:44:10 OK 20251218171726_add_pins.sql (3.72ms)6712026/07/09 07:44:10 OK 1_commit_pending_closure.sql (2.5ms)6722026/07/09 07:44:10 OK 20251218171726_add_pins.sql (2.7ms)6732026/07/09 07:44:10 OK 20260628120000_add_object_size_and_stats.sql (2.87ms)6742026/07/09 07:44:10 goose: successfully migrated database to version: 202606281200006752026/07/09 07:44:10 OK 2_object_stats_trigger.sql (1.65ms)6762026/07/09 07:44:10 goose: up to current file version: 26772026/07/09 07:44:10 OK 2_object_stats_trigger.sql (784.92µs)6782026/07/09 07:44:10 goose: up to current file version: 26792026/07/09 07:44:10 OK 1_commit_pending_closure.sql (2.08ms)6802026/07/09 07:44:10 OK 1_commit_pending_closure.sql (2.26ms)6812026/07/09 07:44:10 OK 20260628120000_add_object_size_and_stats.sql (2.02ms)6822026/07/09 07:44:10 goose: successfully migrated database to version: 202606281200006832026/07/09 07:44:10 OK 20260628120000_add_object_size_and_stats.sql (2.22ms)6842026/07/09 07:44:10 goose: successfully migrated database to version: 202606281200006852026/07/09 07:44:10 OK 2_object_stats_trigger.sql (565.96µs)6862026/07/09 07:44:10 goose: up to current file version: 26872026/07/09 07:44:10 OK 2_object_stats_trigger.sql (469.29µs)6882026/07/09 07:44:10 goose: up to current file version: 26892026/07/09 07:44:10 OK 2_object_stats_trigger.sql (706.88µs)6902026/07/09 07:44:10 goose: up to current file version: 26912026/07/09 07:44:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete6922026/07/09 07:44:10 OK 1_commit_pending_closure.sql (2.29ms)6932026/07/09 07:44:10 OK 1_commit_pending_closure.sql (2.57ms)6942026/07/09 07:44:10 OK 1_commit_pending_closure.sql (2.32ms)6952026/07/09 07:44:10 INFO Received cleanup request method=DELETE path=/api/pending_closures6962026/07/09 07:44:10 INFO Received uploads request method=POST path=/api/pending_closures6972026/07/09 07:44:10 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst698--- PASS: TestCompleteMultipartUnregistered (0.43s)699=== CONT TestReadProxyRangeRequest7002026/07/09 07:44:10 OK 2_object_stats_trigger.sql (777.96µs)7012026/07/09 07:44:10 goose: up to current file version: 27022026/07/09 07:44:10 OK 2_object_stats_trigger.sql (901.46µs)7032026/07/09 07:44:10 goose: up to current file version: 27042026/07/09 07:44:10 INFO Aborted multipart uploads count=0705--- PASS: TestService_Rustfstest (0.40s)7062026/07/09 07:44:10 OK 2_object_stats_trigger.sql (1.62ms)7072026/07/09 07:44:10 goose: up to current file version: 2708=== CONT TestReadProxyDisabled7092026/07/09 07:44:10 INFO Received uploads request method=POST path=/api/pending_closures7102026/07/09 07:44:10 INFO Received uploads request method=POST path=/api/pending_closures7112026/07/09 07:44:10 INFO Received uploads request method=POST path=/api/pending_closures7122026/07/09 07:44:10 INFO Received uploads request method=POST path=/api/pending_closures713--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.44s)714=== CONT TestReadProxyRootRedirectsToIndexHTML7152026/07/09 07:44:10 INFO Received cleanup request method=DELETE path=/api/pending_closures7162026/07/09 07:44:10 INFO Received uploads request method=POST path=/api/pending_closures7172026/07/09 07:44:10 INFO Aborted multipart uploads count=17182026/07/09 07:44:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7192026-07-09 07:44:10.656 UTC [25813] ERROR: Closure does not exist: id=17202026-07-09 07:44:10.656 UTC [25813] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE7212026-07-09 07:44:10.656 UTC [25813] STATEMENT: -- name: CommitPendingClosure :exec722 SELECT commit_pending_closure($1::bigint)723 724--- PASS: TestService_cleanupPendingClosuresHandler (0.44s)725=== CONT TestReadProxyConditionalGet726{"timestamp":"2026-07-09T07:44:10.668447Z","level":"ERROR","fields":{"message":"system path read failed","path_kind":"data_usage","operation":"read_primary","reason":"config_not_found","object":"buckets/.usage.json","error":"Config not found"},"target":"rustfs_ecstore::data_usage","filename":"crates/ecstore/src/data_usage.rs","line_number":126,"threadName":"rustfs-worker","threadId":"ThreadId(10)"}7272026/07/09 07:44:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete728{"timestamp":"2026-07-09T07:44:10.67105Z","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(2)"}729{"timestamp":"2026-07-09T07:44:10.671075Z","level":"ERROR","fields":{"message":"complete_multipart_upload etag err client=Some(\"deadbeef\"), stored=\"\", part_id=1, bucket=bucket9, 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(2)"}7302026/07/09 07:44:10 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=ZmU5ODA4MmMtNjNlZi00ZjY0LWIxZDgtYWQyZDUzZWFhNjU3LmYyNTNjNjc4LTdkMzAtNGVjMC1iZTM5LTU1NDMwNDc2ZDJkN3gxNzgzNTgzMDUwNjU1OTEzMDAw7312026/07/09 07:44:10 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZmU5ODA4MmMtNjNlZi00ZjY0LWIxZDgtYWQyZDUzZWFhNjU3LmYyNTNjNjc4LTdkMzAtNGVjMC1iZTM5LTU1NDMwNDc2ZDJkN3gxNzgzNTgzMDUwNjU1OTEzMDAw parts=1732--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.41s)733=== CONT TestReadProxyHead7342026/07/09 07:44:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7352026/07/09 07:44:10 INFO Received cleanup request method=DELETE path=/api/pending_closures7362026/07/09 07:44:10 INFO Aborted multipart uploads count=1737--- PASS: TestMultipartCleanup (0.56s)738=== CONT TestReadProxyInvalidPath7392026-07-09 07:44:10.798 UTC [25832] ERROR: relation "goose_db_version" does not exist at character 367402026-07-09 07:44:10.798 UTC [25832] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7412026-07-09 07:44:10.826 UTC [25833] ERROR: relation "goose_db_version" does not exist at character 367422026-07-09 07:44:10.826 UTC [25833] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7432026/07/09 07:44:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7442026/07/09 07:44:10 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZmU5ODA4MmMtNjNlZi00ZjY0LWIxZDgtYWQyZDUzZWFhNjU3LjJjMDc1MTkxLTdjOTQtNDY3MC1iZjMwLTYwNjM0YWRlMjRhYXgxNzgzNTgzMDUwNjQwOTEzMDAw parts=107452026/07/09 07:44:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7462026-07-09 07:44:10.839 UTC [25834] ERROR: relation "goose_db_version" does not exist at character 367472026-07-09 07:44:10.839 UTC [25834] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7482026/07/09 07:44:10 OK 20241026095416_initial_model.sql (27.98ms)7492026/07/09 07:44:10 OK 20251210153512_drop_unused_gin_index.sql (934.96µs)7502026/07/09 07:44:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7512026/07/09 07:44:10 INFO Completed upload id=17522026/07/09 07:44:10 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000007532026/07/09 07:44:10 OK 20251218171726_add_pins.sql (9.41ms)7542026/07/09 07:44:10 INFO Received uploads request method=POST path=/api/pending_closures7552026/07/09 07:44:10 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZmU5ODA4MmMtNjNlZi00ZjY0LWIxZDgtYWQyZDUzZWFhNjU3LjMxMmFjMjIyLTE3ZWEtNGFlYy1iYjRjLTU1NGVlOTMwNjJhZXgxNzgzNTgzMDUwNjU2MzcyMDAw parts=107562026/07/09 07:44:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7572026/07/09 07:44:10 INFO Starting cleanup of old closures method=DELETE path=/api/closures7582026/07/09 07:44:10 INFO Aborted multipart uploads count=07592026/07/09 07:44:10 INFO Completed upload id=17602026/07/09 07:44:10 OK 20241026095416_initial_model.sql (27.75ms)7612026/07/09 07:44:10 OK 20260628120000_add_object_size_and_stats.sql (10.71ms)7622026/07/09 07:44:10 goose: successfully migrated database to version: 202606281200007632026/07/09 07:44:10 OK 1_commit_pending_closure.sql (5.68ms)7642026/07/09 07:44:10 OK 20251210153512_drop_unused_gin_index.sql (7.17ms)7652026/07/09 07:44:10 INFO Received uploads request method=POST path=/api/pending_closures7662026/07/09 07:44:10 OK 2_object_stats_trigger.sql (5.89ms)7672026/07/09 07:44:10 goose: up to current file version: 27682026/07/09 07:44:10 OK 20251218171726_add_pins.sql (8.32ms)7692026/07/09 07:44:10 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=0 objects-failed-to-delete=07702026/07/09 07:44:10 OK 20241026095416_initial_model.sql (26.53ms)7712026/07/09 07:44:10 INFO Vacuumed table table=pending_closures7722026/07/09 07:44:10 INFO Received uploads request method=POST path=/api/pending_closures7732026/07/09 07:44:10 INFO Vacuumed table table=pending_objects7742026/07/09 07:44:10 OK 20251210153512_drop_unused_gin_index.sql (9.59ms)7752026/07/09 07:44:10 INFO Vacuumed table table=multipart_uploads7762026/07/09 07:44:10 OK 20260628120000_add_object_size_and_stats.sql (16.41ms)7772026/07/09 07:44:10 goose: successfully migrated database to version: 202606281200007782026/07/09 07:44:10 OK 20251218171726_add_pins.sql (7.21ms)7792026/07/09 07:44:10 INFO Vacuumed table table=closures7802026/07/09 07:44:10 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo7812026/07/09 07:44:10 WARN Found objects in DB but missing from S3, will re-upload count=17822026/07/09 07:44:10 OK 1_commit_pending_closure.sql (4.38ms)783--- PASS: TestService_verifyS3Integrity (0.69s)784=== CONT TestReadProxy4047852026/07/09 07:44:10 INFO Vacuumed table table=objects7862026/07/09 07:44:10 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000007872026/07/09 07:44:10 OK 2_object_stats_trigger.sql (7.72ms)7882026/07/09 07:44:10 goose: up to current file version: 27892026-07-09 07:44:10.906 UTC [25840] ERROR: relation "goose_db_version" does not exist at character 367902026-07-09 07:44:10.906 UTC [25840] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7912026-07-09 07:44:10.906 UTC [25841] ERROR: relation "goose_db_version" does not exist at character 367922026-07-09 07:44:10.906 UTC [25841] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC793--- PASS: TestService_createPendingClosureHandler (0.69s)794=== CONT TestReadProxyNarStreaming7952026/07/09 07:44:10 OK 20260628120000_add_object_size_and_stats.sql (15.07ms)7962026/07/09 07:44:10 goose: successfully migrated database to version: 202606281200007972026/07/09 07:44:10 OK 1_commit_pending_closure.sql (10.42ms)7982026/07/09 07:44:10 OK 2_object_stats_trigger.sql (4.38ms)7992026/07/09 07:44:10 goose: up to current file version: 28002026/07/09 07:44:10 INFO Received uploads request method=POST path=/api/pending_closures8012026/07/09 07:44:10 OK 20241026095416_initial_model.sql (15.36ms)8022026/07/09 07:44:10 OK 20241026095416_initial_model.sql (16.23ms)803--- PASS: TestReadProxyDisabled (0.30s)804=== CONT TestReadProxyNarinfoAlreadyDecompressed8052026/07/09 07:44:10 OK 20251210153512_drop_unused_gin_index.sql (5.06ms)8062026/07/09 07:44:10 OK 20251210153512_drop_unused_gin_index.sql (4.38ms)8072026/07/09 07:44:10 OK 20251218171726_add_pins.sql (2.94ms)8082026/07/09 07:44:10 OK 20251218171726_add_pins.sql (4.06ms)8092026/07/09 07:44:10 OK 20260628120000_add_object_size_and_stats.sql (9.18ms)8102026/07/09 07:44:10 goose: successfully migrated database to version: 202606281200008112026/07/09 07:44:10 OK 20260628120000_add_object_size_and_stats.sql (9.55ms)8122026/07/09 07:44:10 goose: successfully migrated database to version: 202606281200008132026/07/09 07:44:10 INFO Received uploads request method=POST path=/api/pending_closures8142026/07/09 07:44:10 OK 1_commit_pending_closure.sql (4.11ms)8152026/07/09 07:44:10 OK 1_commit_pending_closure.sql (6.8ms)8162026/07/09 07:44:10 OK 2_object_stats_trigger.sql (3.01ms)8172026/07/09 07:44:10 goose: up to current file version: 28182026/07/09 07:44:10 OK 2_object_stats_trigger.sql (4.11ms)8192026/07/09 07:44:10 goose: up to current file version: 2820--- PASS: TestReadProxyRangeRequest (0.34s)821=== CONT TestReadProxyNarinfo822--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.34s)823=== CONT TestIsValidCachePath824=== RUN TestIsValidCachePath/narinfo825=== PAUSE TestIsValidCachePath/narinfo826=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars827=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars828=== RUN TestIsValidCachePath/nar_zst829=== PAUSE TestIsValidCachePath/nar_zst830=== RUN TestIsValidCachePath/nar_xz831=== PAUSE TestIsValidCachePath/nar_xz832=== RUN TestIsValidCachePath/nar_bz2833=== PAUSE TestIsValidCachePath/nar_bz2834=== RUN TestIsValidCachePath/nar_uncompressed835=== PAUSE TestIsValidCachePath/nar_uncompressed836=== RUN TestIsValidCachePath/ls837=== PAUSE TestIsValidCachePath/ls838=== RUN TestIsValidCachePath/log839=== PAUSE TestIsValidCachePath/log840=== RUN TestIsValidCachePath/realisation841=== PAUSE TestIsValidCachePath/realisation842=== RUN TestIsValidCachePath/nix-cache-info843=== PAUSE TestIsValidCachePath/nix-cache-info844=== RUN TestIsValidCachePath/index.html845=== PAUSE TestIsValidCachePath/index.html846=== RUN TestIsValidCachePath/traversal_parent847=== PAUSE TestIsValidCachePath/traversal_parent848=== RUN TestIsValidCachePath/traversal_in_middle849=== PAUSE TestIsValidCachePath/traversal_in_middle850=== RUN TestIsValidCachePath/invalid_char_e851=== PAUSE TestIsValidCachePath/invalid_char_e852=== RUN TestIsValidCachePath/invalid_char_u853=== PAUSE TestIsValidCachePath/invalid_char_u854=== RUN TestIsValidCachePath/random_path855=== PAUSE TestIsValidCachePath/random_path856=== RUN TestIsValidCachePath/empty857=== PAUSE TestIsValidCachePath/empty858=== RUN TestIsValidCachePath/leading_slash859=== PAUSE TestIsValidCachePath/leading_slash860=== RUN TestIsValidCachePath/wrong_extension861=== PAUSE TestIsValidCachePath/wrong_extension862=== RUN TestIsValidCachePath/short_hash863=== PAUSE TestIsValidCachePath/short_hash864=== CONT TestParseSingleRange865=== RUN TestParseSingleRange/none866=== PAUSE TestParseSingleRange/none867=== RUN TestParseSingleRange/unknown_unit868=== PAUSE TestParseSingleRange/unknown_unit869=== RUN TestParseSingleRange/multi-range_ignored870=== PAUSE TestParseSingleRange/multi-range_ignored871=== RUN TestParseSingleRange/malformed_no_dash872=== PAUSE TestParseSingleRange/malformed_no_dash873=== RUN TestParseSingleRange/malformed_both_empty874=== PAUSE TestParseSingleRange/malformed_both_empty875=== RUN TestParseSingleRange/malformed_end_before_start876=== PAUSE TestParseSingleRange/malformed_end_before_start877=== RUN TestParseSingleRange/closed878=== PAUSE TestParseSingleRange/closed879=== RUN TestParseSingleRange/open-ended880=== PAUSE TestParseSingleRange/open-ended881=== RUN TestParseSingleRange/end_clamped_to_size882=== PAUSE TestParseSingleRange/end_clamped_to_size883=== RUN TestParseSingleRange/suffix884=== PAUSE TestParseSingleRange/suffix885=== RUN TestParseSingleRange/suffix_exceeds_size886=== PAUSE TestParseSingleRange/suffix_exceeds_size887=== RUN TestParseSingleRange/single_byte888=== PAUSE TestParseSingleRange/single_byte889=== RUN TestParseSingleRange/start_past_EOF890=== PAUSE TestParseSingleRange/start_past_EOF891=== RUN TestParseSingleRange/start_far_past_EOF892=== PAUSE TestParseSingleRange/start_far_past_EOF893=== CONT TestResurrectedObjectNotDeleted894--- PASS: TestReadProxyConditionalGet (0.34s)895=== CONT TestOrphanedObjectsGCStressTest8962026-07-09 07:44:11.026 UTC [25878] ERROR: relation "goose_db_version" does not exist at character 368972026-07-09 07:44:11.026 UTC [25878] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8982026/07/09 07:44:11 OK 20241026095416_initial_model.sql (19.27ms)8992026/07/09 07:44:11 OK 20251210153512_drop_unused_gin_index.sql (1.22ms)9002026/07/09 07:44:11 OK 20251218171726_add_pins.sql (3.32ms)9012026/07/09 07:44:11 OK 20260628120000_add_object_size_and_stats.sql (11.23ms)9022026/07/09 07:44:11 goose: successfully migrated database to version: 202606281200009032026/07/09 07:44:11 OK 1_commit_pending_closure.sql (2.78ms)9042026/07/09 07:44:11 OK 2_object_stats_trigger.sql (683.79µs)9052026/07/09 07:44:11 goose: up to current file version: 2906--- PASS: TestReadProxyHead (0.41s)907=== CONT TestOrphanedObjectsGC9082026/07/09 07:44:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9092026/07/09 07:44:11 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZmU5ODA4MmMtNjNlZi00ZjY0LWIxZDgtYWQyZDUzZWFhNjU3LjQzYjM5NjIxLTJjN2ItNDExMi1hZDQyLTZiZjdkZDQ4YmY3NngxNzgzNTgzMDUwOTQ4OTMyMDAw parts=12910--- PASS: TestRedundantMultipartUpload (0.55s)911=== CONT TestObjectStatsTrigger9122026-07-09 07:44:11.323 UTC [25888] ERROR: relation "goose_db_version" does not exist at character 369132026-07-09 07:44:11.323 UTC [25888] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9142026-07-09 07:44:11.348 UTC [25889] ERROR: relation "goose_db_version" does not exist at character 369152026-07-09 07:44:11.348 UTC [25889] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9162026-07-09 07:44:11.366 UTC [25890] ERROR: relation "goose_db_version" does not exist at character 369172026-07-09 07:44:11.366 UTC [25890] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9182026/07/09 07:44:11 OK 20241026095416_initial_model.sql (31.48ms)9192026/07/09 07:44:11 OK 20251210153512_drop_unused_gin_index.sql (1.18ms)9202026/07/09 07:44:11 OK 20251218171726_add_pins.sql (3.17ms)9212026/07/09 07:44:11 OK 20260628120000_add_object_size_and_stats.sql (5.91ms)9222026/07/09 07:44:11 goose: successfully migrated database to version: 202606281200009232026/07/09 07:44:11 OK 1_commit_pending_closure.sql (3ms)9242026/07/09 07:44:11 OK 20241026095416_initial_model.sql (13.68ms)9252026/07/09 07:44:11 OK 2_object_stats_trigger.sql (591.46µs)9262026/07/09 07:44:11 goose: up to current file version: 29272026/07/09 07:44:11 OK 20251210153512_drop_unused_gin_index.sql (992.5µs)9282026/07/09 07:44:11 OK 20251218171726_add_pins.sql (3.88ms)929--- PASS: TestReadProxy404 (0.49s)930=== CONT TestGCTaskStore_StartNew931--- PASS: TestGCTaskStore_StartNew (0.00s)932=== CONT TestServerTLSConfig933=== RUN TestServerTLSConfig/no_client_CA934=== PAUSE TestServerTLSConfig/no_client_CA935=== RUN TestServerTLSConfig/missing_CA_file936=== PAUSE TestServerTLSConfig/missing_CA_file937=== RUN TestServerTLSConfig/not_a_PEM_file938=== PAUSE TestServerTLSConfig/not_a_PEM_file939=== CONT TestService_NativeMTLS9402026-07-09 07:44:11.401 UTC [25892] ERROR: relation "goose_db_version" does not exist at character 369412026-07-09 07:44:11.401 UTC [25892] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9422026/07/09 07:44:11 OK 20260628120000_add_object_size_and_stats.sql (14.08ms)9432026/07/09 07:44:11 goose: successfully migrated database to version: 202606281200009442026/07/09 07:44:11 OK 20241026095416_initial_model.sql (28.74ms)9452026/07/09 07:44:11 OK 20251210153512_drop_unused_gin_index.sql (967.63µs)9462026/07/09 07:44:11 OK 1_commit_pending_closure.sql (2.22ms)9472026/07/09 07:44:11 OK 2_object_stats_trigger.sql (808.04µs)9482026/07/09 07:44:11 goose: up to current file version: 29492026/07/09 07:44:11 OK 20251218171726_add_pins.sql (2.55ms)9502026/07/09 07:44:11 OK 20260628120000_add_object_size_and_stats.sql (5.27ms)9512026/07/09 07:44:11 goose: successfully migrated database to version: 20260628120000952--- PASS: TestReadProxyNarStreaming (0.51s)953=== CONT TestMetricsInventory9542026/07/09 07:44:11 OK 1_commit_pending_closure.sql (2.6ms)9552026/07/09 07:44:11 OK 2_object_stats_trigger.sql (773.96µs)9562026/07/09 07:44:11 goose: up to current file version: 2957--- PASS: TestReadProxyInvalidPath (0.65s)958=== CONT TestNARDeduplicationMetadataUploadBug9592026/07/09 07:44:11 OK 20241026095416_initial_model.sql (18.07ms)9602026/07/09 07:44:11 OK 20251210153512_drop_unused_gin_index.sql (1.43ms)9612026/07/09 07:44:11 OK 20251218171726_add_pins.sql (3.16ms)9622026/07/09 07:44:11 OK 20260628120000_add_object_size_and_stats.sql (17.68ms)9632026/07/09 07:44:11 goose: successfully migrated database to version: 202606281200009642026/07/09 07:44:11 OK 1_commit_pending_closure.sql (2.29ms)9652026/07/09 07:44:11 OK 2_object_stats_trigger.sql (722.46µs)9662026/07/09 07:44:11 goose: up to current file version: 29672026-07-09 07:44:11.457 UTC [25898] ERROR: relation "goose_db_version" does not exist at character 369682026-07-09 07:44:11.457 UTC [25898] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9692026-07-09 07:44:11.459 UTC [25899] ERROR: relation "goose_db_version" does not exist at character 369702026-07-09 07:44:11.459 UTC [25899] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC971--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.52s)972=== CONT TestGenerateLandingPage973--- PASS: TestGenerateLandingPage (0.00s)974=== CONT TestService_healthCheckHandler9752026-07-09 07:44:11.475 UTC [25902] ERROR: relation "goose_db_version" does not exist at character 369762026-07-09 07:44:11.475 UTC [25902] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9772026/07/09 07:44:11 OK 20241026095416_initial_model.sql (28.88ms)9782026/07/09 07:44:11 OK 20251210153512_drop_unused_gin_index.sql (1.45ms)9792026/07/09 07:44:11 OK 20251218171726_add_pins.sql (3.42ms)9802026/07/09 07:44:11 OK 20241026095416_initial_model.sql (14.38ms)9812026/07/09 07:44:11 OK 20251210153512_drop_unused_gin_index.sql (1.15ms)9822026/07/09 07:44:11 OK 20260628120000_add_object_size_and_stats.sql (4.17ms)9832026/07/09 07:44:11 goose: successfully migrated database to version: 202606281200009842026/07/09 07:44:11 OK 20251218171726_add_pins.sql (2.8ms)9852026/07/09 07:44:11 OK 1_commit_pending_closure.sql (1.67ms)9862026/07/09 07:44:11 OK 20241026095416_initial_model.sql (13.42ms)9872026/07/09 07:44:11 OK 2_object_stats_trigger.sql (621.33µs)9882026/07/09 07:44:11 goose: up to current file version: 29892026/07/09 07:44:11 OK 20251210153512_drop_unused_gin_index.sql (1ms)9902026/07/09 07:44:11 OK 20251218171726_add_pins.sql (3.22ms)9912026/07/09 07:44:11 OK 20260628120000_add_object_size_and_stats.sql (6.06ms)9922026/07/09 07:44:11 goose: successfully migrated database to version: 202606281200009932026/07/09 07:44:11 OK 1_commit_pending_closure.sql (2.25ms)9942026/07/09 07:44:11 OK 2_object_stats_trigger.sql (628.92µs)9952026/07/09 07:44:11 goose: up to current file version: 29962026/07/09 07:44:11 OK 20260628120000_add_object_size_and_stats.sql (4.24ms)9972026/07/09 07:44:11 goose: successfully migrated database to version: 20260628120000998--- PASS: TestReadProxyNarinfo (0.53s)999=== CONT TestGracefulShutdownDrainsInflight10002026/07/09 07:44:11 INFO Starting HTTP server address=127.0.0.1:5255610012026/07/09 07:44:11 INFO Shutdown signal received, draining in-flight requests timeout=10s10022026/07/09 07:44:11 OK 1_commit_pending_closure.sql (2.12ms)10032026/07/09 07:44:11 OK 2_object_stats_trigger.sql (398.46µs)10042026/07/09 07:44:11 goose: up to current file version: 210052026-07-09 07:44:11.569 UTC [25905] ERROR: relation "goose_db_version" does not exist at character 3610062026-07-09 07:44:11.569 UTC [25905] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1007--- PASS: TestResurrectedObjectNotDeleted (0.59s)1008=== CONT TestGCTaskStore_Fail1009--- PASS: TestGCTaskStore_Fail (0.00s)1010=== CONT TestGCTaskStore_PhaseUpdates1011--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1012=== CONT TestGCTaskStore_CompletedAllowsNewTask1013--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1014=== CONT TestGCTaskStore_GetReturnsLatest1015--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1016=== CONT TestGCTaskStore_GetEmpty1017--- PASS: TestGCTaskStore_GetEmpty (0.00s)1018=== CONT TestGCTaskStore_ConflictDifferentParams1019--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1020=== CONT TestGCTaskStore_DeduplicateSameParams1021--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1022=== CONT TestClientErrorHandling1023=== RUN TestClientErrorHandling/InvalidStorePath1024=== PAUSE TestClientErrorHandling/InvalidStorePath1025=== RUN TestClientErrorHandling/InvalidAuthToken1026=== PAUSE TestClientErrorHandling/InvalidAuthToken1027=== RUN TestClientErrorHandling/ServerNotAvailable1028=== PAUSE TestClientErrorHandling/ServerNotAvailable1029=== CONT TestGCMetrics1030--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1031=== CONT TestGCBugBareHashReferences10322026/07/09 07:44:11 OK 20241026095416_initial_model.sql (12.04ms)10332026/07/09 07:44:11 OK 20251210153512_drop_unused_gin_index.sql (801.13µs)10342026/07/09 07:44:11 OK 20251218171726_add_pins.sql (2.09ms)10352026/07/09 07:44:11 OK 20260628120000_add_object_size_and_stats.sql (6.1ms)10362026/07/09 07:44:11 goose: successfully migrated database to version: 2026062812000010372026/07/09 07:44:11 OK 1_commit_pending_closure.sql (2.67ms)10382026/07/09 07:44:11 OK 2_object_stats_trigger.sql (716.63µs)10392026/07/09 07:44:11 goose: up to current file version: 210402026-07-09 07:44:11.659 UTC [25911] ERROR: relation "goose_db_version" does not exist at character 3610412026-07-09 07:44:11.659 UTC [25911] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10422026/07/09 07:44:11 OK 20241026095416_initial_model.sql (14.89ms)10432026/07/09 07:44:11 OK 20251210153512_drop_unused_gin_index.sql (789.67µs)10442026/07/09 07:44:11 OK 20251218171726_add_pins.sql (3.48ms)10452026/07/09 07:44:11 OK 20260628120000_add_object_size_and_stats.sql (3.01ms)10462026/07/09 07:44:11 goose: successfully migrated database to version: 2026062812000010472026/07/09 07:44:11 OK 1_commit_pending_closure.sql (1.7ms)10482026/07/09 07:44:11 OK 2_object_stats_trigger.sql (258.04µs)10492026/07/09 07:44:11 goose: up to current file version: 21050--- PASS: TestObjectStatsTrigger (0.51s)1051=== CONT TestPinProtectsFromGC10522026-07-09 07:44:11.824 UTC [25932] ERROR: relation "goose_db_version" does not exist at character 3610532026-07-09 07:44:11.824 UTC [25932] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10542026-07-09 07:44:11.839 UTC [25933] ERROR: relation "goose_db_version" does not exist at character 3610552026-07-09 07:44:11.839 UTC [25933] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10562026-07-09 07:44:11.846 UTC [25934] ERROR: relation "goose_db_version" does not exist at character 3610572026-07-09 07:44:11.846 UTC [25934] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10582026-07-09 07:44:11.869 UTC [25935] ERROR: relation "goose_db_version" does not exist at character 3610592026-07-09 07:44:11.869 UTC [25935] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10602026/07/09 07:44:11 OK 20241026095416_initial_model.sql (22.98ms)10612026/07/09 07:44:11 OK 20251210153512_drop_unused_gin_index.sql (1.07ms)10622026/07/09 07:44:11 OK 20241026095416_initial_model.sql (14.69ms)10632026/07/09 07:44:11 OK 20251218171726_add_pins.sql (3.11ms)10642026/07/09 07:44:11 OK 20251210153512_drop_unused_gin_index.sql (1.34ms)10652026/07/09 07:44:11 OK 20241026095416_initial_model.sql (14.31ms)10662026/07/09 07:44:11 OK 20251218171726_add_pins.sql (2.3ms)10672026/07/09 07:44:11 OK 20260628120000_add_object_size_and_stats.sql (3.24ms)10682026/07/09 07:44:11 goose: successfully migrated database to version: 2026062812000010692026/07/09 07:44:11 OK 20251210153512_drop_unused_gin_index.sql (1.33ms)10702026/07/09 07:44:11 OK 1_commit_pending_closure.sql (2.06ms)10712026/07/09 07:44:11 OK 20251218171726_add_pins.sql (2.73ms)10722026/07/09 07:44:11 OK 2_object_stats_trigger.sql (865.71µs)10732026/07/09 07:44:11 goose: up to current file version: 210742026/07/09 07:44:11 OK 20260628120000_add_object_size_and_stats.sql (7.87ms)10752026/07/09 07:44:11 goose: successfully migrated database to version: 2026062812000010762026/07/09 07:44:11 OK 20260628120000_add_object_size_and_stats.sql (5.45ms)10772026/07/09 07:44:11 goose: successfully migrated database to version: 2026062812000010782026/07/09 07:44:11 OK 1_commit_pending_closure.sql (2.15ms)10792026/07/09 07:44:11 OK 20241026095416_initial_model.sql (12.98ms)10802026/07/09 07:44:11 OK 1_commit_pending_closure.sql (2.15ms)10812026/07/09 07:44:11 OK 2_object_stats_trigger.sql (614.17µs)10822026/07/09 07:44:11 goose: up to current file version: 210832026/07/09 07:44:11 OK 2_object_stats_trigger.sql (566.46µs)10842026/07/09 07:44:11 goose: up to current file version: 210852026/07/09 07:44:11 OK 20251210153512_drop_unused_gin_index.sql (960.21µs)10862026/07/09 07:44:11 WARN mTLS auth: subject not in bound subjects subject="CN=reader"10872026/07/09 07:44:11 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1088--- PASS: TestService_NativeMTLS (0.51s)1089=== CONT TestClientWithDependencies10902026/07/09 07:44:11 OK 20251218171726_add_pins.sql (3.05ms)10912026/07/09 07:44:11 INFO Created nix-cache-info in bucket bucket=bucket291092=== NAME TestOrphanedObjectsGC1093 orphaned_objects_gc_test.go:290: GC Test Summary:1094 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1095 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1096 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1097 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1098 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1099--- PASS: TestOrphanedObjectsGC (0.82s)1100=== CONT TestClientMultipleUploads11012026-07-09 07:44:11.905 UTC [25939] ERROR: relation "goose_db_version" does not exist at character 3611022026-07-09 07:44:11.905 UTC [25939] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11032026/07/09 07:44:11 OK 20260628120000_add_object_size_and_stats.sql (12.52ms)11042026/07/09 07:44:11 goose: successfully migrated database to version: 202606281200001105--- PASS: TestMetricsInventory (0.49s)1106=== CONT TestClientIntegration11072026/07/09 07:44:11 OK 1_commit_pending_closure.sql (2.02ms)11082026/07/09 07:44:11 OK 2_object_stats_trigger.sql (2.18ms)11092026/07/09 07:44:11 goose: up to current file version: 21110--- PASS: TestService_healthCheckHandler (0.46s)1111=== CONT TestService_AuthMiddleware_OIDC11122026-07-09 07:44:11.926 UTC [25944] ERROR: relation "goose_db_version" does not exist at character 3611132026-07-09 07:44:11.926 UTC [25944] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11142026/07/09 07:44:11 INFO OIDC provider initialized name=test11152026/07/09 07:44:11 OK 20241026095416_initial_model.sql (26.85ms)11162026/07/09 07:44:11 OK 20251210153512_drop_unused_gin_index.sql (940.5µs)11172026/07/09 07:44:11 OK 20251218171726_add_pins.sql (2.61ms)11182026/07/09 07:44:11 OK 20241026095416_initial_model.sql (11.31ms)11192026/07/09 07:44:11 OK 20251210153512_drop_unused_gin_index.sql (814.42µs)11202026/07/09 07:44:11 OK 20260628120000_add_object_size_and_stats.sql (6.35ms)11212026/07/09 07:44:11 goose: successfully migrated database to version: 2026062812000011222026/07/09 07:44:11 OK 20251218171726_add_pins.sql (2.83ms)11232026/07/09 07:44:11 OK 1_commit_pending_closure.sql (1.98ms)11242026/07/09 07:44:11 OK 2_object_stats_trigger.sql (638.5µs)11252026/07/09 07:44:11 goose: up to current file version: 211262026/07/09 07:44:11 OK 20260628120000_add_object_size_and_stats.sql (4.52ms)11272026/07/09 07:44:11 goose: successfully migrated database to version: 2026062812000011282026/07/09 07:44:11 OK 1_commit_pending_closure.sql (2.42ms)11292026/07/09 07:44:11 OK 2_object_stats_trigger.sql (604.42µs)11302026/07/09 07:44:11 goose: up to current file version: 211312026/07/09 07:44:11 INFO Aborted multipart uploads count=011322026/07/09 07:44:11 WARN Force mode enabled - objects will be deleted immediately without grace period11332026/07/09 07:44:11 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011342026/07/09 07:44:11 INFO Vacuumed table table=pending_closures11352026/07/09 07:44:11 INFO Vacuumed table table=pending_objects11362026/07/09 07:44:11 INFO Vacuumed table table=multipart_uploads11372026/07/09 07:44:11 INFO Vacuumed table table=closures11382026/07/09 07:44:11 INFO Vacuumed table table=objects1139--- PASS: TestGCMetrics (0.39s)1140=== CONT TestClientCADerivations1141=== NAME TestNARDeduplicationMetadataUploadBug1142 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-24890-4261754756/TestNARDeduplicationMetadataUploadBug3253758506/001/store/44pxcsnwkbjdvn472rs6dhmkiscjq546-file1.txt11432026-07-09 07:44:12.116 UTC [25959] ERROR: relation "goose_db_version" does not exist at character 3611442026-07-09 07:44:12.116 UTC [25959] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11452026/07/09 07:44:12 OK 20241026095416_initial_model.sql (14.98ms)11462026/07/09 07:44:12 OK 20251210153512_drop_unused_gin_index.sql (907.38µs)11472026/07/09 07:44:12 OK 20251218171726_add_pins.sql (2.99ms)11482026/07/09 07:44:12 OK 20260628120000_add_object_size_and_stats.sql (4.08ms)11492026/07/09 07:44:12 goose: successfully migrated database to version: 2026062812000011502026/07/09 07:44:12 OK 1_commit_pending_closure.sql (2.42ms)11512026/07/09 07:44:12 OK 2_object_stats_trigger.sql (819.75µs)11522026/07/09 07:44:12 goose: up to current file version: 211532026/07/09 07:44:12 INFO Created nix-cache-info in bucket bucket=bucket331154--- PASS: TestGCBugBareHashReferences (0.60s)1155=== CONT TestCacheStatsHandler11562026-07-09 07:44:12.206 UTC [25965] ERROR: relation "goose_db_version" does not exist at character 3611572026-07-09 07:44:12.206 UTC [25965] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11582026/07/09 07:44:12 OK 20241026095416_initial_model.sql (32.04ms)11592026/07/09 07:44:12 OK 20251210153512_drop_unused_gin_index.sql (1.19ms)11602026/07/09 07:44:12 OK 20251218171726_add_pins.sql (2.94ms)11612026-07-09 07:44:12.267 UTC [25971] ERROR: relation "goose_db_version" does not exist at character 3611622026-07-09 07:44:12.267 UTC [25971] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11632026/07/09 07:44:12 OK 20260628120000_add_object_size_and_stats.sql (13.16ms)11642026/07/09 07:44:12 goose: successfully migrated database to version: 2026062812000011652026-07-09 07:44:12.273 UTC [25973] ERROR: relation "goose_db_version" does not exist at character 3611662026-07-09 07:44:12.273 UTC [25973] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11672026-07-09 07:44:12.274 UTC [25972] ERROR: relation "goose_db_version" does not exist at character 3611682026-07-09 07:44:12.274 UTC [25972] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11692026/07/09 07:44:12 OK 1_commit_pending_closure.sql (8.41ms)11702026/07/09 07:44:12 OK 2_object_stats_trigger.sql (913.71µs)11712026/07/09 07:44:12 goose: up to current file version: 211722026/07/09 07:44:12 INFO Created nix-cache-info in bucket bucket=bucket3411732026/07/09 07:44:12 OK 20241026095416_initial_model.sql (18.72ms)11742026/07/09 07:44:12 OK 20241026095416_initial_model.sql (8.47ms)11752026/07/09 07:44:12 OK 20251210153512_drop_unused_gin_index.sql (933.5µs)11762026/07/09 07:44:12 OK 20251210153512_drop_unused_gin_index.sql (987.08µs)11772026/07/09 07:44:12 OK 20241026095416_initial_model.sql (11.61ms)11782026/07/09 07:44:12 OK 20251218171726_add_pins.sql (2.32ms)11792026/07/09 07:44:12 OK 20251218171726_add_pins.sql (2.42ms)11802026/07/09 07:44:12 OK 20251210153512_drop_unused_gin_index.sql (949.21µs)11812026/07/09 07:44:12 OK 20251218171726_add_pins.sql (1.66ms)11822026/07/09 07:44:12 OK 20260628120000_add_object_size_and_stats.sql (3.45ms)11832026/07/09 07:44:12 goose: successfully migrated database to version: 2026062812000011842026/07/09 07:44:12 OK 20260628120000_add_object_size_and_stats.sql (2.91ms)11852026/07/09 07:44:12 goose: successfully migrated database to version: 2026062812000011862026/07/09 07:44:12 OK 1_commit_pending_closure.sql (1.8ms)11872026/07/09 07:44:12 OK 20260628120000_add_object_size_and_stats.sql (5.47ms)11882026/07/09 07:44:12 goose: successfully migrated database to version: 2026062812000011892026/07/09 07:44:12 OK 2_object_stats_trigger.sql (931.88µs)11902026/07/09 07:44:12 goose: up to current file version: 211912026/07/09 07:44:12 OK 1_commit_pending_closure.sql (2.11ms)11922026/07/09 07:44:12 OK 1_commit_pending_closure.sql (1.68ms)11932026/07/09 07:44:12 OK 2_object_stats_trigger.sql (1.38ms)11942026/07/09 07:44:12 goose: up to current file version: 211952026/07/09 07:44:12 OK 2_object_stats_trigger.sql (1.14ms)11962026/07/09 07:44:12 goose: up to current file version: 21197=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1198=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1199=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1200=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1201=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1202=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1203=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1204=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1205=== CONT TestCacheConfigHandler1206=== RUN TestCacheConfigHandler/full_config,_no_issuer1207=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1208=== RUN TestCacheConfigHandler/no_cache_url_configured1209=== PAUSE TestCacheConfigHandler/no_cache_url_configured1210=== RUN TestCacheConfigHandler/no_signing_keys1211=== PAUSE TestCacheConfigHandler/no_signing_keys1212=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1213=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1214=== CONT TestService_AuthMiddleware_MTLSBoundSubjects12152026/07/09 07:44:12 INFO Created nix-cache-info in bucket bucket=bucket3512162026/07/09 07:44:12 INFO Created nix-cache-info in bucket bucket=bucket3712172026/07/09 07:44:12 INFO Received uploads request method=POST path=/api/pending_closures1218=== NAME TestPinProtectsFromGC1219 client_integration_test.go:646: Pinned store path: /nix/var/nix/builds/nix-24890-4261754756/TestPinProtectsFromGC3709088495/001/store/4sywd18sh2bqjwdjr2rcmrdknlpar3jc-pinned-file.txt1220 client_integration_test.go:647: Unpinned store path: /nix/var/nix/builds/nix-24890-4261754756/TestPinProtectsFromGC3709088495/001/store/qlv5vka4w1vdi7a6lpd0z41asxsk2y3p-unpinned-file.txt12212026-07-09 07:44:12.319 UTC [25981] ERROR: relation "goose_db_version" does not exist at character 3612222026-07-09 07:44:12.319 UTC [25981] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12232026/07/09 07:44:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12242026/07/09 07:44:12 INFO Uploading 44pxcsnwkbjdvn472rs6dhmkiscjq546-file1.txt (160B)12252026/07/09 07:44:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12262026/07/09 07:44:12 INFO Signed narinfos id=1 count=112272026/07/09 07:44:12 INFO Uploading 1 narinfos12282026/07/09 07:44:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12292026/07/09 07:44:12 INFO Completed upload id=112302026/07/09 07:44:12 INFO Upload complete. (222ms)12312026/07/09 07:44:12 OK 20241026095416_initial_model.sql (10.5ms)1232=== NAME TestNARDeduplicationMetadataUploadBug1233 metadata_upload_test.go:54: Retrieved narinfo from S3:12342026/07/09 07:44:12 OK 20251210153512_drop_unused_gin_index.sql (831.46µs)1235 StorePath: /nix/var/nix/builds/nix-24890-4261754756/TestNARDeduplicationMetadataUploadBug3253758506/001/store/44pxcsnwkbjdvn472rs6dhmkiscjq546-file1.txt1236 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1237 Compression: zstd1238 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1239 NarSize: 1601240 References: 1241 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1242 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1243 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1244 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}12452026/07/09 07:44:12 OK 20251218171726_add_pins.sql (3.84ms)12462026/07/09 07:44:12 OK 20260628120000_add_object_size_and_stats.sql (4ms)12472026/07/09 07:44:12 goose: successfully migrated database to version: 2026062812000012482026/07/09 07:44:12 OK 1_commit_pending_closure.sql (2ms)12492026/07/09 07:44:12 OK 2_object_stats_trigger.sql (649.25µs)12502026/07/09 07:44:12 goose: up to current file version: 212512026/07/09 07:44:12 INFO Created nix-cache-info in bucket bucket=bucket381252=== NAME TestClientMultipleUploads1253 client_integration_test.go:338: Created store path 0: /nix/var/nix/builds/nix-24890-4261754756/TestClientMultipleUploads483301075/001/store/0r09mi9b1g88j375rp66kj7pyavwd9wz-test-file-0.txt1254=== NAME TestNARDeduplicationMetadataUploadBug1255 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-24890-4261754756/TestNARDeduplicationMetadataUploadBug3253758506/001/store/3mbm7i5w75g5hcs13z2mxrpz0bydi6d0-file2.txt1256=== NAME TestClientIntegration1257 client_integration_test.go:276: Created store path: /nix/var/nix/builds/nix-24890-4261754756/TestClientIntegration283463558/002/store/d43mayzgrbhbyhsjjq3k4xy813nhzbsj-test-file.txt12582026-07-09 07:44:12.472 UTC [26009] ERROR: relation "goose_db_version" does not exist at character 3612592026-07-09 07:44:12.472 UTC [26009] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12602026/07/09 07:44:12 OK 20241026095416_initial_model.sql (7.29ms)12612026/07/09 07:44:12 OK 20251210153512_drop_unused_gin_index.sql (1.37ms)12622026/07/09 07:44:12 OK 20251218171726_add_pins.sql (2.45ms)1263=== NAME TestClientMultipleUploads1264 client_integration_test.go:338: Created store path 1: /nix/var/nix/builds/nix-24890-4261754756/TestClientMultipleUploads483301075/001/store/2a4f5nn5d31hzlwk5hb0dzpk3jls27xn-test-file-1.txt12652026/07/09 07:44:12 OK 20260628120000_add_object_size_and_stats.sql (5.14ms)12662026/07/09 07:44:12 goose: successfully migrated database to version: 2026062812000012672026/07/09 07:44:12 OK 1_commit_pending_closure.sql (4.05ms)12682026/07/09 07:44:12 OK 2_object_stats_trigger.sql (761µs)12692026/07/09 07:44:12 goose: up to current file version: 212702026/07/09 07:44:12 INFO Received uploads request method=POST path=/api/pending_closures12712026-07-09 07:44:12.529 UTC [26026] ERROR: relation "goose_db_version" does not exist at character 3612722026-07-09 07:44:12.529 UTC [26026] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12732026/07/09 07:44:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12742026/07/09 07:44:12 INFO Uploading 4sywd18sh2bqjwdjr2rcmrdknlpar3jc-pinned-file.txt (128B)12752026/07/09 07:44:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12762026/07/09 07:44:12 INFO Signed narinfos id=1 count=11277--- PASS: TestCacheStatsHandler (0.35s)1278=== CONT TestService_ReadAuthMiddleware12792026/07/09 07:44:12 INFO Uploading 1 narinfos12802026/07/09 07:44:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12812026/07/09 07:44:12 INFO Completed upload id=112822026/07/09 07:44:12 INFO Upload complete. (161ms)12832026/07/09 07:44:12 OK 20241026095416_initial_model.sql (8.84ms)12842026/07/09 07:44:12 OK 20251210153512_drop_unused_gin_index.sql (1.21ms)12852026/07/09 07:44:12 OK 20251218171726_add_pins.sql (2.36ms)12862026/07/09 07:44:12 OK 20260628120000_add_object_size_and_stats.sql (3.36ms)12872026/07/09 07:44:12 goose: successfully migrated database to version: 2026062812000012882026/07/09 07:44:12 OK 1_commit_pending_closure.sql (1.32ms)12892026/07/09 07:44:12 OK 2_object_stats_trigger.sql (568.83µs)12902026/07/09 07:44:12 goose: up to current file version: 21291=== NAME TestOrphanedObjectsGCStressTest1292 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains12932026/07/09 07:44:12 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"12942026/07/09 07:44:12 WARN mTLS auth: bound subjects configured but subject DN unavailable12952026/07/09 07:44:12 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1296--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.25s)1297=== CONT TestService_AuthMiddleware_MTLSProxyHeader1298=== NAME TestOrphanedObjectsGCStressTest1299 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion1300=== NAME TestClientMultipleUploads1301 client_integration_test.go:338: Created store path 2: /nix/var/nix/builds/nix-24890-4261754756/TestClientMultipleUploads483301075/001/store/s4yg5qyd8bnrfx0s0k7549dwz3azyk8s-test-file-2.txt13022026/07/09 07:44:12 INFO Received uploads request method=POST path=/api/pending_closures13032026/07/09 07:44:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13042026/07/09 07:44:12 INFO Uploading d43mayzgrbhbyhsjjq3k4xy813nhzbsj-test-file.txt (152B)13052026/07/09 07:44:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13062026/07/09 07:44:12 INFO Signed narinfos id=1 count=113072026/07/09 07:44:12 INFO Uploading 1 narinfos13082026/07/09 07:44:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13092026/07/09 07:44:12 INFO Completed upload id=113102026/07/09 07:44:12 INFO Upload complete. (145ms)1311=== NAME TestClientIntegration1312 client_integration_test.go:292: Retrieved narinfo from S3:1313 StorePath: /nix/var/nix/builds/nix-24890-4261754756/TestClientIntegration283463558/002/store/d43mayzgrbhbyhsjjq3k4xy813nhzbsj-test-file.txt1314 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1315 Compression: zstd1316 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11317 NarSize: 1521318 References: 1319 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11320 client_integration_test.go:293: Retrieved .ls file from S3 (compressed size: 77 bytes)1321 client_integration_test.go:293: Decompressed .ls content (64 bytes):1322 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1323 client_integration_test.go:296: Testing garbage collection...13242026/07/09 07:44:12 INFO Received uploads request method=POST path=/api/pending_closures13252026/07/09 07:44:12 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)13262026/07/09 07:44:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13272026/07/09 07:44:12 INFO Signed narinfos id=2 count=113282026/07/09 07:44:12 INFO Uploading 1 narinfos13292026/07/09 07:44:12 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13302026/07/09 07:44:12 INFO Completed upload id=213312026/07/09 07:44:12 INFO Upload complete. (164ms)1332=== NAME TestNARDeduplicationMetadataUploadBug1333 metadata_upload_test.go:76: Retrieved narinfo from S3:1334 StorePath: /nix/var/nix/builds/nix-24890-4261754756/TestNARDeduplicationMetadataUploadBug3253758506/001/store/3mbm7i5w75g5hcs13z2mxrpz0bydi6d0-file2.txt1335 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1336 Compression: zstd1337 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1338 NarSize: 1601339 References: 1340 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1341 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1342 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1343 {"version":1,"root":{"type":"regular","size":44}}1344--- PASS: TestNARDeduplicationMetadataUploadBug (1.25s)1345=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info13462026/07/09 07:44:12 INFO Received uploads request method=POST path=/1347=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key13482026/07/09 07:44:12 INFO Received request for more parts method=POST path=/1349=== CONT TestProxyWriteTimeout/narinfo1350=== CONT TestProxyWriteTimeout/10_GiB_nar1351=== CONT TestProxyWriteTimeout/unknown_size1352=== CONT TestProxyWriteTimeout/1_GiB_nar1353--- PASS: TestProxyWriteTimeout (0.00s)1354 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1355 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1356 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1357 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1358=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key13592026/07/09 07:44:12 INFO Received complete multipart upload request method=POST path=/1360=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal13612026/07/09 07:44:12 INFO Received uploads request method=POST path=/1362--- PASS: TestUploadHandlersRejectInvalidKeys (0.02s)1363 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1364 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1365 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1366 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1367=== CONT TestIsValidUploadKey/nix-cache-info1368=== CONT TestIsValidUploadKey/narinfo1369=== CONT TestIsValidUploadKey/realisation_plus_in_output1370=== CONT TestIsValidUploadKey/realisation1371=== CONT TestIsValidUploadKey/build_log_equals1372=== CONT TestIsValidUploadKey/build_log_question_mark1373=== CONT TestIsValidUploadKey/build_log_plus_in_name1374=== CONT TestIsValidUploadKey/build_log_home-manager_file1375=== CONT TestIsValidUploadKey/build_log1376=== CONT TestIsValidUploadKey/listing1377=== CONT TestIsValidUploadKey/nar_plain1378=== CONT TestIsValidUploadKey/nar_xz1379=== CONT TestIsValidUploadKey/nar_zst1380=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1381=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1382=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1383=== CONT TestIsValidUploadKey/index.html1384=== CONT TestIsValidUploadKey/empty_key1385=== CONT TestIsValidUploadKey/unknown_type1386=== CONT TestIsValidUploadKey/absolute1387=== CONT TestIsValidUploadKey/traversal_nar1388=== CONT TestIsValidUploadKey/traversal1389--- PASS: TestIsValidUploadKey (0.03s)1390 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1391 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1392 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1393 --- PASS: TestIsValidUploadKey/realisation (0.00s)1394 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1395 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1396 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1397 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1398 --- PASS: TestIsValidUploadKey/build_log (0.00s)1399 --- PASS: TestIsValidUploadKey/listing (0.00s)1400 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1401 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1402 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1403 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1404 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1405 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1406 --- PASS: TestIsValidUploadKey/index.html (0.00s)1407 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1408 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1409 --- PASS: TestIsValidUploadKey/absolute (0.00s)1410 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1411 --- PASS: TestIsValidUploadKey/traversal (0.00s)1412=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure14132026/07/09 07:44:12 INFO Received uploads request method=POST path=/14142026-07-09 07:44:12.697 UTC [26049] ERROR: relation "goose_db_version" does not exist at character 3614152026-07-09 07:44:12.697 UTC [26049] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14162026/07/09 07:44:12 INFO Starting cleanup of old closures method=DELETE path=/api/closures14172026/07/09 07:44:12 INFO Garbage collection started14182026/07/09 07:44:12 OK 20241026095416_initial_model.sql (5.03ms)14192026/07/09 07:44:12 OK 20251210153512_drop_unused_gin_index.sql (937.46µs)14202026/07/09 07:44:12 INFO Aborted multipart uploads count=014212026/07/09 07:44:12 OK 20251218171726_add_pins.sql (3.74ms)14222026/07/09 07:44:12 WARN Force mode enabled - objects will be deleted immediately without grace period14232026/07/09 07:44:12 INFO Received uploads request method=POST path=/api/pending_closures14242026/07/09 07:44:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14252026/07/09 07:44:12 INFO Uploading qlv5vka4w1vdi7a6lpd0z41asxsk2y3p-unpinned-file.txt (128B)14262026/07/09 07:44:12 OK 20260628120000_add_object_size_and_stats.sql (12.62ms)14272026/07/09 07:44:12 goose: successfully migrated database to version: 2026062812000014282026/07/09 07:44:12 OK 1_commit_pending_closure.sql (2.1ms)14292026/07/09 07:44:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14302026/07/09 07:44:12 INFO Signed narinfos id=2 count=114312026/07/09 07:44:12 OK 2_object_stats_trigger.sql (552.88µs)14322026/07/09 07:44:12 goose: up to current file version: 214332026/07/09 07:44:12 INFO Uploading 1 narinfos14342026-07-09 07:44:12.729 UTC [26054] ERROR: relation "goose_db_version" does not exist at character 3614352026-07-09 07:44:12.729 UTC [26054] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14362026/07/09 07:44:12 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14372026/07/09 07:44:12 INFO Completed upload id=214382026/07/09 07:44:12 INFO Upload complete. (132ms)14392026/07/09 07:44:12 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1440--- PASS: TestService_ReadAuthMiddleware (0.20s)1441=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts14422026/07/09 07:44:12 INFO Received request for more parts method=POST path=/14432026/07/09 07:44:12 OK 20241026095416_initial_model.sql (8.62ms)14442026/07/09 07:44:12 OK 20251210153512_drop_unused_gin_index.sql (902.88µs)14452026/07/09 07:44:12 OK 20251218171726_add_pins.sql (2.21ms)14462026/07/09 07:44:12 OK 20260628120000_add_object_size_and_stats.sql (2.6ms)14472026/07/09 07:44:12 goose: successfully migrated database to version: 2026062812000014482026/07/09 07:44:12 OK 1_commit_pending_closure.sql (1.87ms)1449=== NAME TestOrphanedObjectsGCStressTest1450 orphaned_objects_gc_test.go:509: Stress test completed successfully:1451 orphaned_objects_gc_test.go:510: - Active objects preserved: 201452 orphaned_objects_gc_test.go:511: - Objects deleted: 2101453 orphaned_objects_gc_test.go:512: - Total GC'd: 2101454--- PASS: TestOrphanedObjectsGCStressTest (1.76s)1455=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart14562026/07/09 07:44:12 INFO Received complete multipart upload request method=POST path=/14572026/07/09 07:44:12 OK 2_object_stats_trigger.sql (603.25µs)14582026/07/09 07:44:12 goose: up to current file version: 21459--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.20s)1460=== CONT TestIsValidCachePath/narinfo1461=== CONT TestIsValidCachePath/index.html1462=== CONT TestIsValidCachePath/short_hash1463=== CONT TestIsValidCachePath/wrong_extension1464=== CONT TestIsValidCachePath/leading_slash1465=== CONT TestIsValidCachePath/empty1466=== CONT TestIsValidCachePath/random_path1467=== CONT TestIsValidCachePath/invalid_char_u1468=== CONT TestIsValidCachePath/invalid_char_e1469=== CONT TestIsValidCachePath/traversal_in_middle1470=== CONT TestIsValidCachePath/traversal_parent1471=== CONT TestIsValidCachePath/nar_uncompressed1472=== CONT TestIsValidCachePath/nix-cache-info1473=== CONT TestIsValidCachePath/realisation1474=== CONT TestIsValidCachePath/log1475=== CONT TestIsValidCachePath/ls1476=== CONT TestIsValidCachePath/nar_xz1477=== CONT TestIsValidCachePath/nar_bz21478=== CONT TestIsValidCachePath/nar_zst1479=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1480--- PASS: TestIsValidCachePath (0.00s)1481 --- PASS: TestIsValidCachePath/narinfo (0.00s)1482 --- PASS: TestIsValidCachePath/index.html (0.00s)1483 --- PASS: TestIsValidCachePath/short_hash (0.00s)1484 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1485 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1486 --- PASS: TestIsValidCachePath/empty (0.00s)1487 --- PASS: TestIsValidCachePath/random_path (0.00s)1488 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1489 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1490 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1491 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1492 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1493 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1494 --- PASS: TestIsValidCachePath/realisation (0.00s)1495 --- PASS: TestIsValidCachePath/log (0.00s)1496 --- PASS: TestIsValidCachePath/ls (0.00s)1497 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1498 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1499 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1500 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1501=== CONT TestParseSingleRange/none1502=== CONT TestParseSingleRange/open-ended1503=== CONT TestParseSingleRange/start_far_past_EOF1504=== CONT TestParseSingleRange/start_past_EOF1505=== CONT TestParseSingleRange/single_byte1506=== CONT TestParseSingleRange/suffix_exceeds_size1507=== CONT TestParseSingleRange/suffix1508=== CONT TestParseSingleRange/end_clamped_to_size1509=== CONT TestParseSingleRange/malformed_both_empty1510=== CONT TestParseSingleRange/closed1511=== CONT TestParseSingleRange/malformed_end_before_start1512=== CONT TestParseSingleRange/multi-range_ignored1513=== CONT TestParseSingleRange/malformed_no_dash1514=== CONT TestParseSingleRange/unknown_unit1515--- PASS: TestParseSingleRange (0.00s)1516 --- PASS: TestParseSingleRange/none (0.00s)1517 --- PASS: TestParseSingleRange/open-ended (0.00s)1518 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1519 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1520 --- PASS: TestParseSingleRange/single_byte (0.00s)1521 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1522 --- PASS: TestParseSingleRange/suffix (0.00s)1523 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1524 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1525 --- PASS: TestParseSingleRange/closed (0.00s)1526 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1527 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1528 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1529 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1530=== CONT TestServerTLSConfig/no_client_CA1531=== CONT TestServerTLSConfig/missing_CA_file1532=== CONT TestServerTLSConfig/not_a_PEM_file1533=== CONT TestClientErrorHandling/InvalidStorePath1534--- PASS: TestServerTLSConfig (0.00s)1535 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1536 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1537 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1538=== CONT TestClientErrorHandling/InvalidAuthToken15392026/07/09 07:44:12 INFO Received uploads request method=POST path=/api/pending_closures15402026/07/09 07:44:12 INFO Received uploads request method=POST path=/api/pending_closures15412026/07/09 07:44:12 INFO Received uploads request method=POST path=/api/pending_closures1542=== CONT TestClientErrorHandling/ServerNotAvailable15432026/07/09 07:44:12 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)15442026/07/09 07:44:12 INFO Uploading 2a4f5nn5d31hzlwk5hb0dzpk3jls27xn-test-file-1.txt (160B)15452026/07/09 07:44:12 INFO Uploading s4yg5qyd8bnrfx0s0k7549dwz3azyk8s-test-file-2.txt (160B)15462026/07/09 07:44:12 INFO Uploading 0r09mi9b1g88j375rp66kj7pyavwd9wz-test-file-0.txt (160B)15472026/07/09 07:44:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15482026/07/09 07:44:12 INFO Received create pin request method=POST path=/api/pins/myapp15492026/07/09 07:44:12 INFO Signed narinfos id=1 count=115502026/07/09 07:44:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15512026/07/09 07:44:12 INFO Signed narinfos id=2 count=115522026/07/09 07:44:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign15532026/07/09 07:44:12 INFO Signed narinfos id=3 count=115542026/07/09 07:44:12 INFO Uploading 3 narinfos15552026/07/09 07:44:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15562026/07/09 07:44:12 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-24890-4261754756/TestPinProtectsFromGC3709088495/001/store/4sywd18sh2bqjwdjr2rcmrdknlpar3jc-pinned-file.txt narinfo_key=4sywd18sh2bqjwdjr2rcmrdknlpar3jc.narinfo15572026/07/09 07:44:12 INFO Starting cleanup of old closures method=DELETE path=/api/closures15582026/07/09 07:44:12 INFO Garbage collection started15592026/07/09 07:44:12 INFO Completed upload id=115602026/07/09 07:44:12 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15612026/07/09 07:44:12 INFO Completed upload id=215622026/07/09 07:44:12 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete15632026/07/09 07:44:12 INFO Completed upload id=315642026/07/09 07:44:12 INFO Upload complete. (153ms)1565=== NAME TestClientMultipleUploads1566 client_integration_test.go:349: Uploaded 3 paths in 210.649ms15672026/07/09 07:44:12 INFO Aborted multipart uploads count=015682026/07/09 07:44:12 WARN Force mode enabled - objects will be deleted immediately without grace period1569--- PASS: TestClientMultipleUploads (0.90s)1570=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token15712026/07/09 07:44:12 INFO OIDC auth successful provider=test1572=== CONT TestCacheConfigHandler/full_config,_no_issuer1573=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1574=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected15752026/07/09 07:44:12 WARN Authentication failed token_preview=not-a-valid-jwt token_length=15 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]1576=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected15772026/07/09 07:44:12 WARN Authentication failed token_preview=eyJhbGciOi...fNO-RLe5CA 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]1578=== CONT TestCacheConfigHandler/no_signing_keys1579=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1580=== CONT TestCacheConfigHandler/no_cache_url_configured1581--- PASS: TestCacheConfigHandler (0.00s)1582 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1583 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1584 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1585 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1586--- PASS: TestService_AuthMiddleware_OIDC (0.38s)1587 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1588 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1589 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1590 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)15912026-07-09 07:44:12.927 UTC [26072] ERROR: relation "goose_db_version" does not exist at character 3615922026-07-09 07:44:12.927 UTC [26072] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15932026-07-09 07:44:12.927 UTC [26071] ERROR: relation "goose_db_version" does not exist at character 3615942026-07-09 07:44:12.927 UTC [26071] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15952026/07/09 07:44:12 OK 20241026095416_initial_model.sql (6.34ms)15962026/07/09 07:44:12 OK 20251210153512_drop_unused_gin_index.sql (949.08µs)15972026/07/09 07:44:12 OK 20251218171726_add_pins.sql (2.25ms)15982026/07/09 07:44:12 OK 20241026095416_initial_model.sql (11.16ms)15992026/07/09 07:44:12 OK 20260628120000_add_object_size_and_stats.sql (2.2ms)16002026/07/09 07:44:12 goose: successfully migrated database to version: 2026062812000016012026/07/09 07:44:12 OK 20251210153512_drop_unused_gin_index.sql (1.08ms)16022026/07/09 07:44:12 OK 1_commit_pending_closure.sql (3.89ms)16032026/07/09 07:44:12 OK 20251218171726_add_pins.sql (4.08ms)16042026/07/09 07:44:12 OK 2_object_stats_trigger.sql (1.01ms)16052026/07/09 07:44:12 goose: up to current file version: 216062026/07/09 07:44:12 OK 20260628120000_add_object_size_and_stats.sql (2.37ms)16072026/07/09 07:44:12 goose: successfully migrated database to version: 2026062812000016082026/07/09 07:44:12 OK 1_commit_pending_closure.sql (2.41ms)16092026/07/09 07:44:12 OK 2_object_stats_trigger.sql (765.25µs)16102026/07/09 07:44:12 goose: up to current file version: 21611=== NAME TestClientWithDependencies1612 client_integration_test.go:593: Built derivation: /nix/var/nix/builds/nix-24890-4261754756/TestClientWithDependencies2125456483/001/store/zpcg9cax3q8a69j6fwl7y9giknwp6lv1-test-script1613=== NAME TestClientCADerivations1614 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-24890-4261754756/TestClientCADerivations1286910371/001/store/hj9nynagbndkmwbfzn7h6cb767prd75y-ca-test1615=== NAME TestClientWithDependencies1616 client_integration_test.go:595: Found 1 dependencies (including self)1617=== NAME TestClientCADerivations1618 client_ca_test.go:139: Found 1 dependencies (including self)16192026/07/09 07:44:13 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_closures16202026/07/09 07:44:13 INFO Received uploads request method=POST path=/api/pending_closures16212026/07/09 07:44:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16222026/07/09 07:44:13 INFO Uploading zpcg9cax3q8a69j6fwl7y9giknwp6lv1-test-script (136B)16232026/07/09 07:44:13 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16242026/07/09 07:44:13 INFO Signed narinfos id=1 count=116252026/07/09 07:44:13 INFO Uploading 1 narinfos16262026/07/09 07:44:13 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=203.522328ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures16272026/07/09 07:44:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16282026/07/09 07:44:13 INFO Completed upload id=116292026/07/09 07:44:13 INFO Upload complete. (69ms)1630=== NAME TestClientWithDependencies1631 client_integration_test.go:597: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-24890-4261754756/TestClientWithDependencies2125456483/001/store) requires matching store prefix1632--- PASS: TestClientWithDependencies (1.27s)16332026/07/09 07:44:13 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"16342026/07/09 07:44:13 INFO Received uploads request method=POST path=/api/pending_closures16352026/07/09 07:44:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16362026/07/09 07:44:13 INFO Uploading hj9nynagbndkmwbfzn7h6cb767prd75y-ca-test (144B)16372026/07/09 07:44:13 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16382026/07/09 07:44:13 INFO Signed narinfos id=1 count=116392026/07/09 07:44:13 INFO Uploading 1 narinfos16402026/07/09 07:44:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16412026/07/09 07:44:13 INFO Completed upload id=116422026/07/09 07:44:13 INFO Upload complete. (121ms)1643=== NAME TestClientCADerivations1644 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-24890-4261754756/TestClientCADerivations1286910371/001/store/hj9nynagbndkmwbfzn7h6cb767prd75y-ca-test1645 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1646 Compression: zstd1647 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1648 NarSize: 1441649 References: 1650 Deriver: /nix/var/nix/builds/nix-24890-4261754756/TestClientCADerivations1286910371/001/store/jspl8dx2wgsdrncw46b9j5m2lxamn4bx-ca-test.drv1651 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1652 client_ca_test.go:185: Checking for realisation files in S3...1653 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1654 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1655 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket38?endpoint=http://localhost:52427®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-24890-4261754756/TestClientCADerivations1286910371/001/store'1656 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11657--- PASS: TestClientCADerivations (1.35s)16582026/07/09 07:44:13 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=409.450002ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1659--- PASS: TestUploadHandlersRejectOversizedBody (0.05s)1660 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.03s)1661 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.03s)1662 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.72s)16632026/07/09 07:44:13 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=016642026/07/09 07:44:13 INFO Vacuumed table table=pending_closures16652026/07/09 07:44:13 INFO Vacuumed table table=pending_objects16662026/07/09 07:44:13 INFO Vacuumed table table=multipart_uploads16672026/07/09 07:44:13 INFO Vacuumed table table=closures16682026/07/09 07:44:13 INFO Vacuumed table table=objects16692026/07/09 07:44:13 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=016702026/07/09 07:44:13 INFO Vacuumed table table=pending_closures16712026/07/09 07:44:13 INFO Vacuumed table table=pending_objects16722026/07/09 07:44:13 INFO Vacuumed table table=multipart_uploads16732026/07/09 07:44:13 INFO Vacuumed table table=closures16742026/07/09 07:44:13 INFO Vacuumed table table=objects16752026/07/09 07:44:13 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=856.704323ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures16762026/07/09 07:44:14 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.446321915s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures16772026/07/09 07:44:14 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01678=== NAME TestClientIntegration1679 client_integration_test.go:303: Objects in database after GC:1680 client_integration_test.go:303: Successfully deleted all objects with GC --force1681--- PASS: TestClientIntegration (2.82s)16822026/07/09 07:44:14 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01683=== NAME TestPinProtectsFromGC1684 client_integration_test.go:709: Pin successfully protected closure from garbage collection1685--- PASS: TestPinProtectsFromGC (3.11s)16862026/07/09 07:44:15 WARN Rate limiter enabled after throttle name=s3-test rate=516872026/07/09 07:44:15 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1688=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1689 throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=101690 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001691--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.86s)1692--- PASS: TestClientErrorHandling (0.00s)1693 --- PASS: TestClientErrorHandling/InvalidStorePath (0.25s)1694 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.44s)1695 --- PASS: TestClientErrorHandling/ServerNotAvailable (3.31s)1696PASS16972026-07-09 07:44:16.648 UTC [25586] LOG: received smart shutdown request16982026-07-09 07:44:16.650 UTC [25586] LOG: background worker "logical replication launcher" (PID 25597) exited with exit code 116992026-07-09 07:44:16.653 UTC [25592] LOG: shutting down17002026-07-09 07:44:16.654 UTC [25592] LOG: checkpoint starting: shutdown immediate17012026-07-09 07:44:18.072 UTC [25592] LOG: checkpoint complete: wrote 13432 buffers (82.0%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 12 recycled; write=0.815 s, sync=0.600 s, total=1.419 s; sync files=14509, longest=0.009 s, average=0.001 s; distance=202876 kB, estimate=202876 kB; lsn=0/DDA4878, redo lsn=0/DDA487817022026-07-09 07:44:18.086 UTC [25586] LOG: database system is shut down1703Running OIDC tests...1704=== RUN TestGlobMatch1705=== PAUSE TestGlobMatch1706=== RUN TestAudienceForIssuer1707=== PAUSE TestAudienceForIssuer1708=== RUN TestValidateToken_ValidToken1709=== PAUSE TestValidateToken_ValidToken1710=== RUN TestValidateToken_WrongAudience1711=== PAUSE TestValidateToken_WrongAudience1712=== RUN TestValidateToken_Expired1713=== PAUSE TestValidateToken_Expired1714=== RUN TestValidateToken_BoundClaimsMismatch1715=== PAUSE TestValidateToken_BoundClaimsMismatch1716=== RUN TestValidateToken_BoundSubjectMismatch1717=== PAUSE TestValidateToken_BoundSubjectMismatch1718=== RUN TestValidateToken_MultipleProviders1719=== PAUSE TestValidateToken_MultipleProviders1720=== RUN TestValidateToken_NoMatchingProvider1721=== PAUSE TestValidateToken_NoMatchingProvider1722=== CONT TestGlobMatch1723=== RUN TestGlobMatch/foo_foo1724=== PAUSE TestGlobMatch/foo_foo1725=== RUN TestGlobMatch/foo_bar1726=== PAUSE TestGlobMatch/foo_bar1727=== RUN TestGlobMatch/*_1728=== PAUSE TestGlobMatch/*_1729=== RUN TestGlobMatch/*_anything1730=== PAUSE TestGlobMatch/*_anything1731=== RUN TestGlobMatch/foo*_foo1732=== PAUSE TestGlobMatch/foo*_foo1733=== RUN TestGlobMatch/foo*_foobar1734=== CONT TestValidateToken_BoundClaimsMismatch1735=== CONT TestValidateToken_NoMatchingProvider1736=== CONT TestValidateToken_MultipleProviders1737=== CONT TestValidateToken_BoundSubjectMismatch1738=== CONT TestValidateToken_WrongAudience1739=== CONT TestValidateToken_Expired1740=== CONT TestValidateToken_ValidToken1741=== CONT TestAudienceForIssuer1742--- PASS: TestAudienceForIssuer (0.00s)1743=== PAUSE TestGlobMatch/foo*_foobar1744=== RUN TestGlobMatch/foo*_bar1745=== PAUSE TestGlobMatch/foo*_bar1746=== RUN TestGlobMatch/*bar_bar1747=== PAUSE TestGlobMatch/*bar_bar1748=== RUN TestGlobMatch/*bar_foobar1749=== PAUSE TestGlobMatch/*bar_foobar1750=== RUN TestGlobMatch/*bar_foo1751=== PAUSE TestGlobMatch/*bar_foo1752=== RUN TestGlobMatch/foo*bar_foobar1753=== PAUSE TestGlobMatch/foo*bar_foobar1754=== RUN TestGlobMatch/foo*bar_foo123bar1755=== PAUSE TestGlobMatch/foo*bar_foo123bar1756=== RUN TestGlobMatch/foo*bar_foobarbaz1757=== PAUSE TestGlobMatch/foo*bar_foobarbaz1758=== RUN TestGlobMatch/*/*_foo/bar1759=== PAUSE TestGlobMatch/*/*_foo/bar1760=== RUN TestGlobMatch/*/*_foo1761=== PAUSE TestGlobMatch/*/*_foo1762=== RUN TestGlobMatch/refs/heads/*_refs/heads/main1763=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main1764=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.01765=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.01766=== RUN TestGlobMatch/refs/*/main_refs/heads/main1767=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main1768=== RUN TestGlobMatch/fo?_foo1769=== PAUSE TestGlobMatch/fo?_foo1770=== RUN TestGlobMatch/fo?_fo1771=== PAUSE TestGlobMatch/fo?_fo1772=== RUN TestGlobMatch/fo?_fooo1773=== PAUSE TestGlobMatch/fo?_fooo1774=== RUN TestGlobMatch/?oo_foo1775=== PAUSE TestGlobMatch/?oo_foo1776=== RUN TestGlobMatch/?oo_boo1777=== PAUSE TestGlobMatch/?oo_boo1778=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1779=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1780=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1781=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1782=== CONT TestGlobMatch/foo_foo1783=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1784=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1785=== CONT TestGlobMatch/?oo_boo1786=== CONT TestGlobMatch/?oo_foo1787=== CONT TestGlobMatch/fo?_fooo1788=== CONT TestGlobMatch/fo?_fo1789=== CONT TestGlobMatch/fo?_foo1790=== CONT TestGlobMatch/refs/*/main_refs/heads/main1791=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.01792=== CONT TestGlobMatch/refs/heads/*_refs/heads/main1793=== CONT TestGlobMatch/*/*_foo1794=== CONT TestGlobMatch/*/*_foo/bar1795=== CONT TestGlobMatch/foo*bar_foobarbaz1796=== CONT TestGlobMatch/foo*bar_foo123bar1797=== CONT TestGlobMatch/foo*bar_foobar1798=== CONT TestGlobMatch/*bar_foo1799=== CONT TestGlobMatch/*bar_foobar1800=== CONT TestGlobMatch/*bar_bar1801=== CONT TestGlobMatch/foo*_bar1802=== CONT TestGlobMatch/foo*_foobar1803=== CONT TestGlobMatch/foo*_foo1804=== CONT TestGlobMatch/*_anything1805=== CONT TestGlobMatch/*_1806=== CONT TestGlobMatch/foo_bar1807--- PASS: TestGlobMatch (0.00s)1808 --- PASS: TestGlobMatch/foo_foo (0.00s)1809 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)1810 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)1811 --- PASS: TestGlobMatch/?oo_boo (0.00s)1812 --- PASS: TestGlobMatch/?oo_foo (0.00s)1813 --- PASS: TestGlobMatch/fo?_fooo (0.00s)1814 --- PASS: TestGlobMatch/fo?_fo (0.00s)1815 --- PASS: TestGlobMatch/fo?_foo (0.00s)1816 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)1817 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)1818 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)1819 --- PASS: TestGlobMatch/*/*_foo (0.00s)1820 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)1821 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)1822 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)1823 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)1824 --- PASS: TestGlobMatch/*bar_foo (0.00s)1825 --- PASS: TestGlobMatch/*bar_foobar (0.00s)1826 --- PASS: TestGlobMatch/*bar_bar (0.00s)1827 --- PASS: TestGlobMatch/foo*_bar (0.00s)1828 --- PASS: TestGlobMatch/foo*_foobar (0.00s)1829 --- PASS: TestGlobMatch/foo*_foo (0.00s)1830 --- PASS: TestGlobMatch/*_anything (0.00s)1831 --- PASS: TestGlobMatch/*_ (0.00s)1832 --- PASS: TestGlobMatch/foo_bar (0.00s)18332026/07/09 07:44:19 INFO OIDC provider initialized name=test18342026/07/09 07:44:19 INFO OIDC provider initialized name=test18352026/07/09 07:44:19 INFO OIDC provider initialized name=provider118362026/07/09 07:44:19 INFO OIDC provider initialized name=provider118372026/07/09 07:44:19 INFO OIDC provider initialized name=test18382026/07/09 07:44:19 INFO OIDC provider initialized name=test18392026/07/09 07:44:19 INFO OIDC provider initialized name=test18402026/07/09 07:44:19 INFO OIDC provider initialized name=provider21841--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)1842--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)1843--- PASS: TestValidateToken_WrongAudience (0.01s)1844--- PASS: TestValidateToken_Expired (0.01s)1845--- PASS: TestValidateToken_ValidToken (0.01s)1846--- PASS: TestValidateToken_NoMatchingProvider (0.01s)1847--- PASS: TestValidateToken_MultipleProviders (0.01s)1848PASS1849Running hook tests...1850=== RUN TestSendPathsEmpty1851=== PAUSE TestSendPathsEmpty1852=== RUN TestQueueEnqueueAndFetch1853=== PAUSE TestQueueEnqueueAndFetch1854=== RUN TestQueueDeduplication1855=== PAUSE TestQueueDeduplication1856=== RUN TestQueueRemove1857=== PAUSE TestQueueRemove1858=== RUN TestQueueFetchBatchLimit1859=== PAUSE TestQueueFetchBatchLimit1860=== RUN TestQueueFetchRemoveLifecycle1861=== PAUSE TestQueueFetchRemoveLifecycle1862=== RUN TestQueueConcurrentWriters1863=== PAUSE TestQueueConcurrentWriters1864=== RUN TestServerClientIntegration1865=== PAUSE TestServerClientIntegration1866=== RUN TestServerQueueError1867=== PAUSE TestServerQueueError1868=== RUN TestGetListenerSocketActivation1869 server_test.go:210: === RUN TestGetListenerSocketActivation1870 --- PASS: TestGetListenerSocketActivation (0.00s)1871 PASS1872 1873--- PASS: TestGetListenerSocketActivation (0.01s)1874=== RUN TestWorkerUploadsAndRemoves1875=== PAUSE TestWorkerUploadsAndRemoves1876=== RUN TestWorkerSkipsGCdPaths1877=== PAUSE TestWorkerSkipsGCdPaths1878=== RUN TestWorkerPrunesClosureDeps1879=== PAUSE TestWorkerPrunesClosureDeps1880=== CONT TestSendPathsEmpty1881--- PASS: TestSendPathsEmpty (0.00s)1882=== CONT TestQueueFetchRemoveLifecycle1883=== CONT TestQueueConcurrentWriters1884=== CONT TestWorkerUploadsAndRemoves1885=== CONT TestQueueRemove1886=== CONT TestServerQueueError1887=== CONT TestServerClientIntegration1888=== CONT TestQueueEnqueueAndFetch1889=== CONT TestQueueDeduplication1890=== CONT TestQueueFetchBatchLimit1891=== CONT TestWorkerPrunesClosureDeps1892--- PASS: TestServerClientIntegration (0.00s)1893=== CONT TestWorkerSkipsGCdPaths18942026/07/09 07:44:20 ERROR Failed to queue paths error="permission denied" count=11895--- PASS: TestServerQueueError (0.00s)1896--- PASS: TestQueueEnqueueAndFetch (0.00s)1897--- PASS: TestQueueFetchRemoveLifecycle (0.01s)18982026/07/09 07:44:20 INFO Upload queue status pending=218992026/07/09 07:44:20 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-24890-4261754756/TestWorkerSkipsGCdPaths439190163/002/nonexistent19002026/07/09 07:44:20 INFO Uploading batch count=11901--- PASS: TestQueueDeduplication (0.01s)19022026/07/09 07:44:20 INFO Upload queue status pending=219032026/07/09 07:44:20 INFO Uploading batch count=21904--- PASS: TestQueueFetchBatchLimit (0.01s)1905--- PASS: TestQueueRemove (0.01s)19062026/07/09 07:44:20 INFO Upload queue status pending=219072026/07/09 07:44:20 INFO Uploading batch count=11908--- PASS: TestWorkerSkipsGCdPaths (0.06s)1909--- PASS: TestWorkerUploadsAndRemoves (0.06s)1910--- PASS: TestWorkerPrunesClosureDeps (0.06s)1911--- PASS: TestQueueConcurrentWriters (0.13s)1912PASS