niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #142
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestCaseHackSuffix5=== PAUSE TestCaseHackSuffix6=== RUN TestFilterOversizedClosures7=== PAUSE TestFilterOversizedClosures8=== RUN TestPartSizeForNAR9=== PAUSE TestPartSizeForNAR10=== RUN TestUploadMultipart_SupersededByPeer11=== PAUSE TestUploadMultipart_SupersededByPeer12=== RUN TestDumpPathMatchesNix13=== PAUSE TestDumpPathMatchesNix14=== RUN TestDumpPathSingleFile15=== PAUSE TestDumpPathSingleFile16=== RUN TestDumpPathWriterError17=== PAUSE TestDumpPathWriterError18=== RUN TestEncodeNixBase3219=== PAUSE TestEncodeNixBase3220=== RUN TestEncodeNixBase32WithRealHash21=== PAUSE TestEncodeNixBase32WithRealHash22=== RUN TestConvertHashToNix3223=== PAUSE TestConvertHashToNix3224=== RUN TestGetStorePathHash25=== PAUSE TestGetStorePathHash26=== RUN TestPathInfoHashCompatibility27=== PAUSE TestPathInfoHashCompatibility28=== RUN TestParsePathInfoJSON29=== PAUSE TestParsePathInfoJSON30=== RUN TestParsePathInfoJSONMultiplePaths31=== PAUSE TestParsePathInfoJSONMultiplePaths32=== RUN TestPathInfoCACompatibility33=== PAUSE TestPathInfoCACompatibility34=== RUN TestRateLimiterFeedback35=== PAUSE TestRateLimiterFeedback36=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess37=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess38=== RUN TestResolveStorePath39=== PAUSE TestResolveStorePath40=== RUN TestDoWithRetry_BodyReplayedViaGetBody41=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody42=== RUN TestShellSplit43=== PAUSE TestShellSplit44=== RUN TestShellSplitErrors45=== PAUSE TestShellSplitErrors46=== RUN TestSetClientTLS47=== PAUSE TestSetClientTLS48=== RUN TestSetClientTLSDoesNotMutateDefaultTransport49=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport50=== RUN TestSetClientTLSErrors51=== PAUSE TestSetClientTLSErrors52=== RUN TestStaticToken53=== PAUSE TestStaticToken54=== RUN TestFileTokenReadsAndCaches55=== PAUSE TestFileTokenReadsAndCaches56=== RUN TestFileTokenMissing57=== PAUSE TestFileTokenMissing58=== RUN TestFileTokenEmpty59=== PAUSE TestFileTokenEmpty60=== RUN TestScriptTokenNoExpiryRerunsEveryCall61=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall62=== RUN TestScriptTokenCachesUntilRefresh63=== PAUSE TestScriptTokenCachesUntilRefresh64=== RUN TestScriptTokenEmptyToken65=== PAUSE TestScriptTokenEmptyToken66=== RUN TestScriptTokenBadJSON67=== PAUSE TestScriptTokenBadJSON68=== RUN TestScriptTokenScriptFails69=== PAUSE TestScriptTokenScriptFails70=== RUN TestScriptTokenEmptyCommand71=== PAUSE TestScriptTokenEmptyCommand72=== CONT TestDoServerRequestAttachesToken73=== CONT TestResolveStorePath74=== CONT TestEncodeNixBase32WithRealHash75--- PASS: TestEncodeNixBase32WithRealHash (0.00s)76=== CONT TestParsePathInfoJSON77=== CONT TestParsePathInfoJSONMultiplePaths78=== RUN TestParsePathInfoJSON/Nix_format79=== PAUSE TestParsePathInfoJSON/Nix_format80=== RUN TestParsePathInfoJSON/Lix_format81=== PAUSE TestParsePathInfoJSON/Lix_format82=== RUN TestParsePathInfoJSON/empty_input83=== PAUSE TestParsePathInfoJSON/empty_input84=== RUN TestParsePathInfoJSON/whitespace_only85=== PAUSE TestParsePathInfoJSON/whitespace_only86=== RUN TestParsePathInfoJSON/invalid_JSON87=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess88=== CONT TestDumpPathMatchesNix89=== PAUSE TestParsePathInfoJSON/invalid_JSON90=== CONT TestParsePathInfoJSON/Nix_format91=== CONT TestDumpPathWriterError92=== CONT TestEncodeNixBase32932026/08/27 09:32:09 WARN Rate limiter enabled after throttle name=server-test rate=594=== RUN TestEncodeNixBase32/test_string_hash95=== PAUSE TestEncodeNixBase32/test_string_hash96=== RUN TestEncodeNixBase32/empty_input97=== PAUSE TestEncodeNixBase32/empty_input98=== CONT TestEncodeNixBase32/test_string_hash99=== CONT TestEncodeNixBase32/empty_input100--- PASS: TestEncodeNixBase32 (0.00s)101 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)102 --- PASS: TestEncodeNixBase32/empty_input (0.00s)103=== CONT TestFileTokenMissing104=== CONT TestUploadMultipart_SupersededByPeer105=== RUN TestUploadMultipart_SupersededByPeer/exists106=== PAUSE TestUploadMultipart_SupersededByPeer/exists107=== RUN TestUploadMultipart_SupersededByPeer/missing108=== PAUSE TestUploadMultipart_SupersededByPeer/missing109=== CONT TestUploadMultipart_SupersededByPeer/exists110=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths111=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths112=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths113=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths114=== CONT TestRateLimiterFeedback115=== RUN TestRateLimiterFeedback/429_enables_limiter116=== PAUSE TestRateLimiterFeedback/429_enables_limiter117=== RUN TestRateLimiterFeedback/503_enables_limiter118=== PAUSE TestRateLimiterFeedback/503_enables_limiter119=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter120=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter121=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter122=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter123=== CONT TestPathInfoCACompatibility124=== RUN TestPathInfoCACompatibility/null_ca_field125=== PAUSE TestPathInfoCACompatibility/null_ca_field126=== RUN TestPathInfoCACompatibility/old_string_format_-_text127=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text128=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive129=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive130=== RUN TestPathInfoCACompatibility/new_structured_format_-_text131=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text132=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method133=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method134=== CONT TestPathInfoHashCompatibility135=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)136=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)137=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon138=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon139=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI140=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI141=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512142=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512143=== CONT TestGetStorePathHash144=== RUN TestGetStorePathHash/valid_store_path145=== PAUSE TestGetStorePathHash/valid_store_path146=== RUN TestGetStorePathHash/basename_without_hyphen_should_error147=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error148=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error149=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error150=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error151=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error152=== CONT TestConvertHashToNix32153=== RUN TestConvertHashToNix32/SRI_format_to_Nix32154=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32155--- PASS: TestFileTokenMissing (0.00s)156=== RUN TestConvertHashToNix32/already_Nix32_format157=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths158=== CONT TestParsePathInfoJSON/whitespace_only159=== CONT TestParsePathInfoJSON/empty_input160=== CONT TestParsePathInfoJSON/Lix_format161=== CONT TestParsePathInfoJSON/invalid_JSON162=== PAUSE TestConvertHashToNix32/already_Nix32_format163=== CONT TestRateLimiterFeedback/429_enables_limiter164=== CONT TestPathInfoCACompatibility/null_ca_field165=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)166=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter167--- PASS: TestParsePathInfoJSON (0.00s)168 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)169 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)170 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)171 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)172 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)173--- PASS: TestResolveStorePath (0.00s)174=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths175--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)176 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)177 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)178=== RUN TestConvertHashToNix32/invalid_format179=== PAUSE TestConvertHashToNix32/invalid_format180=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter181=== CONT TestGetStorePathHash/valid_store_path182=== CONT TestRateLimiterFeedback/503_enables_limiter183--- PASS: TestDoServerRequestAttachesToken (0.00s)184=== CONT TestScriptTokenNoExpiryRerunsEveryCall185=== CONT TestScriptTokenCachesUntilRefresh1862026/08/27 09:32:09 WARN Rate limiter enabled after throttle name=server-test rate=51872026/08/27 09:32:09 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:508931882026/08/27 09:32:09 WARN Rate limiter enabled after throttle name=server-test rate=51892026/08/27 09:32:09 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:50899190=== CONT TestFileTokenEmpty191=== CONT TestDumpPathSingleFile1922026/08/27 09:32:09 WARN Rate limiter backed off name=server-test rate=51932026/08/27 09:32:09 WARN Rate limiter backed off name=server-test rate=5194=== CONT TestScriptTokenScriptFails195--- PASS: TestRateLimiterFeedback (0.00s)196 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)197 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)198 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)199 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)200=== CONT TestScriptTokenEmptyCommand201=== CONT TestCaseHackSuffix202--- PASS: TestScriptTokenEmptyCommand (0.00s)203=== CONT TestPartSizeForNAR204=== RUN TestPartSizeForNAR/zero_stays_at_minimum205=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum206=== RUN TestPartSizeForNAR/small_stays_at_minimum207=== PAUSE TestPartSizeForNAR/small_stays_at_minimum208=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum209=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum210=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts211=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts212=== RUN TestPartSizeForNAR/1_TiB213=== PAUSE TestPartSizeForNAR/1_TiB214=== RUN TestPartSizeForNAR/5_TiB_S3_max_object215=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object216=== RUN TestPartSizeForNAR/capped_at_5_GiB217=== PAUSE TestPartSizeForNAR/capped_at_5_GiB218=== CONT TestFilterOversizedClosures219=== RUN TestFilterOversizedClosures/no_limit_keeps_everything220=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything221=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped222=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped223=== RUN TestFilterOversizedClosures/all_closures_skipped224=== PAUSE TestFilterOversizedClosures/all_closures_skipped225=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI226=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method227=== CONT TestPathInfoCACompatibility/new_structured_format_-_text228=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive229=== CONT TestPathInfoCACompatibility/old_string_format_-_text230--- PASS: TestPathInfoCACompatibility (0.00s)231 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)232 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)233 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)234 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)235 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)236=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon237=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error238=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error239=== CONT TestGetStorePathHash/basename_without_hyphen_should_error240--- PASS: TestGetStorePathHash (0.00s)241 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)242 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)243 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)244 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)245--- PASS: TestFileTokenEmpty (0.00s)246=== CONT TestScriptTokenBadJSON247=== CONT TestScriptTokenEmptyToken248--- PASS: TestScriptTokenScriptFails (0.00s)249=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512250--- PASS: TestPathInfoHashCompatibility (0.00s)251 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)252 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)253 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)254 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)255=== CONT TestSetClientTLSDoesNotMutateDefaultTransport256--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)257=== CONT TestFileTokenReadsAndCaches258--- PASS: TestFileTokenReadsAndCaches (0.00s)259=== CONT TestStaticToken260--- PASS: TestStaticToken (0.00s)261=== CONT TestSetClientTLSErrors262=== RUN TestSetClientTLSErrors/missing_cert_file263=== PAUSE TestSetClientTLSErrors/missing_cert_file264=== RUN TestSetClientTLSErrors/missing_key_file265=== PAUSE TestSetClientTLSErrors/missing_key_file266=== RUN TestSetClientTLSErrors/missing_ca_file267=== PAUSE TestSetClientTLSErrors/missing_ca_file268=== RUN TestSetClientTLSErrors/invalid_ca_file269=== PAUSE TestSetClientTLSErrors/invalid_ca_file270=== CONT TestShellSplitErrors271--- PASS: TestShellSplitErrors (0.00s)272=== CONT TestSetClientTLS273=== RUN TestSetClientTLS/rejects_connection_without_client_cert274=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert275=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA276=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA277=== RUN TestSetClientTLS/preserves_debug_logging_transport278=== PAUSE TestSetClientTLS/preserves_debug_logging_transport279=== CONT TestUploadMultipart_SupersededByPeer/missing280--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)281 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)282 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)283=== CONT TestShellSplit284--- PASS: TestShellSplit (0.00s)285=== CONT TestDoWithRetry_BodyReplayedViaGetBody2862026/08/27 09:32:09 WARN Rate limiter enabled after throttle name=server-test rate=52872026/08/27 09:32:09 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:509052882026/08/27 09:32:09 WARN Rate limiter backed off name=server-test rate=52892026/08/27 09:32:09 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:50905290--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)291=== CONT TestConvertHashToNix32/SRI_format_to_Nix32292=== CONT TestConvertHashToNix32/invalid_format293=== CONT TestConvertHashToNix32/already_Nix32_format294--- PASS: TestConvertHashToNix32 (0.00s)295 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)296 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)297 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)298=== CONT TestPartSizeForNAR/zero_stays_at_minimum299=== CONT TestPartSizeForNAR/1_TiB300=== CONT TestPartSizeForNAR/capped_at_5_GiB301=== CONT TestPartSizeForNAR/5_TiB_S3_max_object302=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum303=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts304=== CONT TestPartSizeForNAR/small_stays_at_minimum305--- PASS: TestPartSizeForNAR (0.00s)306 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)307 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)308 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)309 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)310 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)311 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)312 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)313=== CONT TestFilterOversizedClosures/no_limit_keeps_everything314=== CONT TestFilterOversizedClosures/all_closures_skipped3152026/08/27 09:32:09 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50316=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3172026/08/27 09:32:09 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-vm-image nar_size=5000 max_nar_size=2000318--- PASS: TestFilterOversizedClosures (0.00s)319 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)320 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)321 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)322=== CONT TestSetClientTLSErrors/missing_cert_file323=== CONT TestSetClientTLSErrors/missing_ca_file324=== CONT TestSetClientTLSErrors/invalid_ca_file325=== CONT TestSetClientTLSErrors/missing_key_file326=== CONT TestSetClientTLS/rejects_connection_without_client_cert327--- PASS: TestSetClientTLSErrors (0.00s)328 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)329 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)330 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)331 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)332--- PASS: TestScriptTokenEmptyToken (0.02s)333=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA334--- PASS: TestScriptTokenBadJSON (0.02s)335=== CONT TestSetClientTLS/preserves_debug_logging_transport3362026/08/27 09:32:09 http: TLS handshake error from 127.0.0.1:50907: remote error: tls: bad certificate337--- PASS: TestSetClientTLS (0.00s)338 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)339 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)340 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)341--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)342--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.03s)343--- PASS: TestDumpPathWriterError (0.04s)344--- PASS: TestDumpPathSingleFile (0.05s)345--- PASS: TestCaseHackSuffix (0.05s)346--- PASS: TestDumpPathMatchesNix (0.07s)347--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)348PASS349Running server tests...350The files belonging to this database system will be owned by user "_nixbld12".351This user must also own the server process.352353The database cluster will be initialized with locale "C".354The default database encoding has accordingly been set to "SQL_ASCII".355The default text search configuration will be set to "english".356357Data page checksums are enabled.358359creating directory /nix/var/nix/builds/nix-22777-2593991874/postgres2091536695/data ... ok360creating subdirectories ... ok361selecting dynamic shared memory implementation ... posix362selecting default "max_connections" ... 100363selecting default "shared_buffers" ... 128MB364selecting default time zone ... UTC365creating configuration files ... ok366running bootstrap script ... ok367performing post-bootstrap initialization ... ok368syncing data to disk ... ok369370initdb: warning: enabling "trust" authentication for local connections371initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.372373Success. You can now start the database server using:374375 pg_ctl -D /nix/var/nix/builds/nix-22777-2593991874/postgres2091536695/data -l logfile start376377/nix/var/nix/builds/nix-22777-2593991874/postgres2091536695:5432 - no response3782026-08-27 09:32:11.548 UTC [22940] LOG: starting PostgreSQL 18.4 on aarch64-apple-darwin25.5.0, compiled by clang version 21.1.8, 64-bit3792026-08-27 09:32:11.562 UTC [22940] LOG: listening on Unix socket "/nix/var/nix/builds/nix-22777-2593991874/postgres2091536695/.s.PGSQL.5432"3802026-08-27 09:32:11.571 UTC [22947] LOG: database system was shut down at 2026-08-27 09:32:11 UTC3812026-08-27 09:32:11.573 UTC [22940] LOG: database system is ready to accept connections382/nix/var/nix/builds/nix-22777-2593991874/postgres2091536695:5432 - accepting connections383=== RUN TestService_AuthMiddleware384=== PAUSE TestService_AuthMiddleware385=== RUN TestService_AuthMiddleware_MTLSProxyHeader386=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader387=== RUN TestService_AuthMiddleware_MTLSBoundSubjects388=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects389=== RUN TestService_ReadAuthMiddleware390=== PAUSE TestService_ReadAuthMiddleware391=== RUN TestService_AuthMiddleware_OIDC392=== PAUSE TestService_AuthMiddleware_OIDC393=== RUN TestCacheConfigHandler394=== PAUSE TestCacheConfigHandler395=== RUN TestCacheStatsHandler396=== PAUSE TestCacheStatsHandler397=== RUN TestClientCADerivations398=== PAUSE TestClientCADerivations399=== RUN TestClientErrorHandling400=== PAUSE TestClientErrorHandling401=== RUN TestClientIntegration402=== PAUSE TestClientIntegration403=== RUN TestClientMultipleUploads404=== PAUSE TestClientMultipleUploads405=== RUN TestClientWithDependencies406=== PAUSE TestClientWithDependencies407=== RUN TestPinProtectsFromGC408=== PAUSE TestPinProtectsFromGC409=== RUN TestGCAdvisoryLockBlocksConcurrentRun4102026-08-27 09:32:13.643 UTC [23122] ERROR: relation "goose_db_version" does not exist at character 364112026-08-27 09:32:13.643 UTC [23122] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4122026/08/27 09:32:13 OK 20241026095416_initial_model.sql (3.19ms)4132026/08/27 09:32:13 OK 20251210153512_drop_unused_gin_index.sql (604.21µs)4142026/08/27 09:32:13 OK 20251218171726_add_pins.sql (770.58µs)4152026/08/27 09:32:13 OK 20260628120000_add_object_size_and_stats.sql (753.67µs)4162026/08/27 09:32:13 goose: successfully migrated database to version: 202606281200004172026/08/27 09:32:13 OK 1_commit_pending_closure.sql (848.46µs)4182026/08/27 09:32:13 OK 2_object_stats_trigger.sql (174.58µs)4192026/08/27 09:32:13 goose: up to current file version: 2420--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.30s)421=== RUN TestGCBugBareHashReferences422=== PAUSE TestGCBugBareHashReferences423=== RUN TestGCMetrics424=== PAUSE TestGCMetrics425=== RUN TestGCTaskStore_StartNew426=== PAUSE TestGCTaskStore_StartNew427=== RUN TestGCTaskStore_DeduplicateSameParams428=== PAUSE TestGCTaskStore_DeduplicateSameParams429=== RUN TestGCTaskStore_ConflictDifferentParams430=== PAUSE TestGCTaskStore_ConflictDifferentParams431=== RUN TestGCTaskStore_GetEmpty432=== PAUSE TestGCTaskStore_GetEmpty433=== RUN TestGCTaskStore_GetReturnsLatest434=== PAUSE TestGCTaskStore_GetReturnsLatest435=== RUN TestGCTaskStore_CompletedAllowsNewTask436=== PAUSE TestGCTaskStore_CompletedAllowsNewTask437=== RUN TestGCTaskStore_PhaseUpdates438=== PAUSE TestGCTaskStore_PhaseUpdates439=== RUN TestGCTaskStore_Fail440=== PAUSE TestGCTaskStore_Fail441=== RUN TestGracefulShutdownDrainsInflight442=== PAUSE TestGracefulShutdownDrainsInflight443=== RUN TestService_healthCheckHandler444=== PAUSE TestService_healthCheckHandler445=== RUN TestGenerateLandingPage446=== PAUSE TestGenerateLandingPage447=== RUN TestCacheConfigHandlerMaxNarSize448=== PAUSE TestCacheConfigHandlerMaxNarSize449=== RUN TestCreatePendingClosureRejectsOversizedNAR450=== PAUSE TestCreatePendingClosureRejectsOversizedNAR451=== RUN TestNARDeduplicationMetadataUploadBug452=== PAUSE TestNARDeduplicationMetadataUploadBug453=== RUN TestMetricsInventory454=== PAUSE TestMetricsInventory455=== RUN TestService_NativeMTLS456=== PAUSE TestService_NativeMTLS457=== RUN TestServerTLSConfig458=== PAUSE TestServerTLSConfig459=== RUN TestMultipartCleanup460=== PAUSE TestMultipartCleanup461=== RUN TestObjectStatsTrigger462=== PAUSE TestObjectStatsTrigger463=== RUN TestOrphanedObjectsGC464=== PAUSE TestOrphanedObjectsGC465=== RUN TestOrphanedObjectsGCStressTest466=== PAUSE TestOrphanedObjectsGCStressTest467=== RUN TestResurrectedObjectNotDeleted468=== PAUSE TestResurrectedObjectNotDeleted469=== RUN TestParseSingleRange470=== PAUSE TestParseSingleRange471=== RUN TestIsValidCachePath472=== PAUSE TestIsValidCachePath473=== RUN TestReadProxyNarinfo474=== PAUSE TestReadProxyNarinfo475=== RUN TestReadProxyNarinfoAlreadyDecompressed476=== PAUSE TestReadProxyNarinfoAlreadyDecompressed477=== RUN TestReadProxyNarStreaming478=== PAUSE TestReadProxyNarStreaming479=== RUN TestReadProxy404480=== PAUSE TestReadProxy404481=== RUN TestReadProxyInvalidPath482=== PAUSE TestReadProxyInvalidPath483=== RUN TestReadProxyHead484=== PAUSE TestReadProxyHead485=== RUN TestReadProxyConditionalGet486=== PAUSE TestReadProxyConditionalGet487=== RUN TestReadProxyRootRedirectsToIndexHTML488=== PAUSE TestReadProxyRootRedirectsToIndexHTML489=== RUN TestReadProxyDisabled490=== PAUSE TestReadProxyDisabled491=== RUN TestReadProxyRangeRequest492=== PAUSE TestReadProxyRangeRequest493=== RUN TestRedundantMultipartUpload494=== PAUSE TestRedundantMultipartUpload495=== RUN TestCompleteMultipartUpload_ErrorButObjectExists496=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists497=== RUN TestCompletedNarNotReofferedAcrossClosures498=== PAUSE TestCompletedNarNotReofferedAcrossClosures499=== RUN TestPresignedUploadRegisteredBeforeCommit500=== PAUSE TestPresignedUploadRegisteredBeforeCommit501=== RUN TestService_Rustfstest502=== PAUSE TestService_Rustfstest503=== RUN TestParseSize504=== PAUSE TestParseSize505=== RUN TestSkippedUploadsHandler506=== PAUSE TestSkippedUploadsHandler507=== RUN TestSystemdListenerNotActivated508--- PASS: TestSystemdListenerNotActivated (0.00s)509=== RUN TestWatchdogBeatsWhenHealthy510--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)511=== RUN TestWatchdogSkipsWhenUnhealthy5122026/08/27 09:32:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5132026/08/27 09:32:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5142026/08/27 09:32:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5152026/08/27 09:32:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5162026/08/27 09:32:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5172026/08/27 09:32:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5182026/08/27 09:32:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5192026/08/27 09:32:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5202026/08/27 09:32:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5212026/08/27 09:32:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"522--- PASS: TestWatchdogSkipsWhenUnhealthy (0.21s)523=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle524=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle525=== RUN TestProxyWriteTimeout526=== PAUSE TestProxyWriteTimeout527=== RUN TestIsValidUploadKey528=== PAUSE TestIsValidUploadKey529=== RUN TestUploadHandlersRejectInvalidKeys530=== PAUSE TestUploadHandlersRejectInvalidKeys531=== RUN TestUploadHandlersRejectOversizedBody532=== PAUSE TestUploadHandlersRejectOversizedBody533=== RUN TestService_cleanupPendingClosuresHandler534=== PAUSE TestService_cleanupPendingClosuresHandler535=== RUN TestService_createPendingClosureHandler536=== PAUSE TestService_createPendingClosureHandler537=== RUN TestService_verifyS3Integrity538=== PAUSE TestService_verifyS3Integrity539=== RUN TestCompleteMultipartUnregistered540=== PAUSE TestCompleteMultipartUnregistered541=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT542=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT543=== CONT TestService_AuthMiddleware544=== CONT TestObjectStatsTrigger545=== CONT TestCompleteMultipartUpload_ErrorButObjectExists546=== CONT TestGCTaskStore_ConflictDifferentParams547--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)548=== CONT TestMultipartCleanup549=== CONT TestClientIntegration550=== CONT TestRedundantMultipartUpload551=== CONT TestService_Rustfstest552=== CONT TestIsValidUploadKey553=== RUN TestIsValidUploadKey/narinfo554=== CONT TestServerTLSConfig555=== CONT TestParseSize556--- PASS: TestParseSize (0.00s)557=== CONT TestGCTaskStore_DeduplicateSameParams558--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)559=== CONT TestGCTaskStore_StartNew560--- PASS: TestGCTaskStore_StartNew (0.00s)561=== CONT TestGCMetrics562=== RUN TestServerTLSConfig/no_client_CA563=== PAUSE TestIsValidUploadKey/narinfo564=== RUN TestIsValidUploadKey/nar_zst565=== PAUSE TestServerTLSConfig/no_client_CA566=== PAUSE TestIsValidUploadKey/nar_zst567=== RUN TestServerTLSConfig/missing_CA_file568=== PAUSE TestServerTLSConfig/missing_CA_file569=== RUN TestIsValidUploadKey/nar_xz570=== RUN TestServerTLSConfig/not_a_PEM_file571=== PAUSE TestServerTLSConfig/not_a_PEM_file572=== PAUSE TestIsValidUploadKey/nar_xz573=== CONT TestReadProxyRangeRequest574=== RUN TestIsValidUploadKey/nar_plain575=== PAUSE TestIsValidUploadKey/nar_plain576=== RUN TestIsValidUploadKey/listing577=== PAUSE TestIsValidUploadKey/listing578=== RUN TestIsValidUploadKey/build_log579=== PAUSE TestIsValidUploadKey/build_log580=== RUN TestIsValidUploadKey/build_log_home-manager_file581=== PAUSE TestIsValidUploadKey/build_log_home-manager_file582=== RUN TestIsValidUploadKey/build_log_plus_in_name583=== PAUSE TestIsValidUploadKey/build_log_plus_in_name584=== RUN TestIsValidUploadKey/build_log_question_mark585=== PAUSE TestIsValidUploadKey/build_log_question_mark586=== RUN TestIsValidUploadKey/build_log_equals587=== PAUSE TestIsValidUploadKey/build_log_equals588=== RUN TestIsValidUploadKey/realisation589=== PAUSE TestIsValidUploadKey/realisation590=== RUN TestIsValidUploadKey/realisation_plus_in_output591=== PAUSE TestIsValidUploadKey/realisation_plus_in_output592=== RUN TestIsValidUploadKey/nix-cache-info593=== PAUSE TestIsValidUploadKey/nix-cache-info594=== RUN TestIsValidUploadKey/index.html595=== PAUSE TestIsValidUploadKey/index.html596=== RUN TestIsValidUploadKey/narinfo_key,_nar_type597=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type598=== RUN TestIsValidUploadKey/nar_key,_narinfo_type599=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type600=== RUN TestIsValidUploadKey/listing_key,_narinfo_type601=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type602=== RUN TestIsValidUploadKey/traversal603=== PAUSE TestIsValidUploadKey/traversal604=== RUN TestIsValidUploadKey/traversal_nar605=== PAUSE TestIsValidUploadKey/traversal_nar606=== RUN TestIsValidUploadKey/absolute607=== PAUSE TestIsValidUploadKey/absolute608=== RUN TestIsValidUploadKey/empty_key609=== PAUSE TestIsValidUploadKey/empty_key610=== RUN TestIsValidUploadKey/unknown_type611=== PAUSE TestIsValidUploadKey/unknown_type612=== CONT TestGCBugBareHashReferences6132026-08-27 09:32:14.229 UTC [23157] ERROR: relation "goose_db_version" does not exist at character 366142026-08-27 09:32:14.229 UTC [23157] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6152026/08/27 09:32:14 OK 20241026095416_initial_model.sql (23.38ms)6162026/08/27 09:32:14 OK 20251210153512_drop_unused_gin_index.sql (662.79µs)6172026/08/27 09:32:14 OK 20251218171726_add_pins.sql (856.38µs)6182026/08/27 09:32:14 OK 20260628120000_add_object_size_and_stats.sql (816.42µs)6192026/08/27 09:32:14 goose: successfully migrated database to version: 202606281200006202026/08/27 09:32:14 OK 1_commit_pending_closure.sql (2.22ms)6212026/08/27 09:32:14 OK 2_object_stats_trigger.sql (836.67µs)6222026/08/27 09:32:14 goose: up to current file version: 26232026-08-27 09:32:14.277 UTC [23158] ERROR: relation "goose_db_version" does not exist at character 366242026-08-27 09:32:14.277 UTC [23158] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6252026-08-27 09:32:14.315 UTC [23160] ERROR: relation "goose_db_version" does not exist at character 366262026-08-27 09:32:14.315 UTC [23160] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6272026-08-27 09:32:14.341 UTC [23167] ERROR: relation "goose_db_version" does not exist at character 366282026-08-27 09:32:14.341 UTC [23167] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6292026-08-27 09:32:14.341 UTC [23162] ERROR: relation "goose_db_version" does not exist at character 366302026-08-27 09:32:14.341 UTC [23162] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6312026-08-27 09:32:14.341 UTC [23165] ERROR: relation "goose_db_version" does not exist at character 366322026-08-27 09:32:14.341 UTC [23165] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6332026-08-27 09:32:14.341 UTC [23168] ERROR: relation "goose_db_version" does not exist at character 366342026-08-27 09:32:14.341 UTC [23168] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6352026-08-27 09:32:14.341 UTC [23163] ERROR: relation "goose_db_version" does not exist at character 366362026-08-27 09:32:14.341 UTC [23163] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6372026-08-27 09:32:14.342 UTC [23161] ERROR: relation "goose_db_version" does not exist at character 366382026-08-27 09:32:14.342 UTC [23161] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6392026-08-27 09:32:14.347 UTC [23169] ERROR: relation "goose_db_version" does not exist at character 366402026-08-27 09:32:14.347 UTC [23169] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6412026/08/27 09:32:14 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"642--- PASS: TestService_AuthMiddleware (0.44s)643=== CONT TestReadProxyDisabled6442026/08/27 09:32:14 OK 20241026095416_initial_model.sql (56.84ms)6452026/08/27 09:32:14 OK 20251210153512_drop_unused_gin_index.sql (1.7ms)6462026/08/27 09:32:14 OK 20251218171726_add_pins.sql (2.91ms)6472026/08/27 09:32:14 OK 20241026095416_initial_model.sql (37.88ms)6482026/08/27 09:32:14 OK 20251210153512_drop_unused_gin_index.sql (6.39ms)6492026/08/27 09:32:14 OK 20260628120000_add_object_size_and_stats.sql (18.98ms)6502026/08/27 09:32:14 goose: successfully migrated database to version: 202606281200006512026/08/27 09:32:14 OK 1_commit_pending_closure.sql (4.37ms)6522026/08/27 09:32:14 OK 2_object_stats_trigger.sql (215.42µs)6532026/08/27 09:32:14 goose: up to current file version: 26542026/08/27 09:32:14 OK 20241026095416_initial_model.sql (36.36ms)6552026/08/27 09:32:14 OK 20241026095416_initial_model.sql (44.17ms)6562026/08/27 09:32:14 OK 20251218171726_add_pins.sql (29.69ms)6572026/08/27 09:32:14 OK 20251210153512_drop_unused_gin_index.sql (8.04ms)6582026/08/27 09:32:14 OK 20251210153512_drop_unused_gin_index.sql (7.43ms)6592026/08/27 09:32:14 OK 20241026095416_initial_model.sql (56.11ms)6602026/08/27 09:32:14 OK 20241026095416_initial_model.sql (72.48ms)6612026/08/27 09:32:14 OK 20251210153512_drop_unused_gin_index.sql (22.79ms)6622026/08/27 09:32:14 OK 20260628120000_add_object_size_and_stats.sql (35.56ms)6632026/08/27 09:32:14 goose: successfully migrated database to version: 202606281200006642026/08/27 09:32:14 OK 20251218171726_add_pins.sql (35.69ms)6652026/08/27 09:32:14 OK 20251210153512_drop_unused_gin_index.sql (11.67ms)6662026/08/27 09:32:14 OK 20251218171726_add_pins.sql (34.14ms)6672026/08/27 09:32:14 OK 20241026095416_initial_model.sql (84.63ms)6682026/08/27 09:32:14 OK 1_commit_pending_closure.sql (6.57ms)6692026/08/27 09:32:14 OK 2_object_stats_trigger.sql (221.63µs)6702026/08/27 09:32:14 goose: up to current file version: 26712026/08/27 09:32:14 OK 20251218171726_add_pins.sql (16.3ms)6722026/08/27 09:32:14 OK 20241026095416_initial_model.sql (93.4ms)6732026/08/27 09:32:14 OK 20251210153512_drop_unused_gin_index.sql (21.24ms)6742026/08/27 09:32:14 OK 20251210153512_drop_unused_gin_index.sql (11.92ms)6752026/08/27 09:32:14 OK 20260628120000_add_object_size_and_stats.sql (35.6ms)6762026/08/27 09:32:14 goose: successfully migrated database to version: 202606281200006772026/08/27 09:32:14 OK 20251218171726_add_pins.sql (30.52ms)6782026/08/27 09:32:14 OK 20241026095416_initial_model.sql (111.97ms)6792026/08/27 09:32:14 OK 20260628120000_add_object_size_and_stats.sql (25.14ms)6802026/08/27 09:32:14 goose: successfully migrated database to version: 202606281200006812026/08/27 09:32:14 OK 20260628120000_add_object_size_and_stats.sql (35.09ms)6822026/08/27 09:32:14 goose: successfully migrated database to version: 202606281200006832026/08/27 09:32:14 OK 20251218171726_add_pins.sql (13.35ms)6842026/08/27 09:32:14 OK 20251218171726_add_pins.sql (13.78ms)6852026/08/27 09:32:14 OK 20251210153512_drop_unused_gin_index.sql (5.38ms)6862026/08/27 09:32:14 OK 1_commit_pending_closure.sql (5.88ms)6872026/08/27 09:32:14 OK 1_commit_pending_closure.sql (1.27ms)6882026/08/27 09:32:14 OK 2_object_stats_trigger.sql (290.42µs)6892026/08/27 09:32:14 goose: up to current file version: 26902026/08/27 09:32:14 OK 2_object_stats_trigger.sql (637µs)6912026/08/27 09:32:14 goose: up to current file version: 26922026/08/27 09:32:14 OK 1_commit_pending_closure.sql (1.6ms)6932026/08/27 09:32:14 OK 2_object_stats_trigger.sql (467.21µs)6942026/08/27 09:32:14 goose: up to current file version: 26952026/08/27 09:32:14 OK 20260628120000_add_object_size_and_stats.sql (12.71ms)6962026/08/27 09:32:14 goose: successfully migrated database to version: 202606281200006972026/08/27 09:32:14 OK 1_commit_pending_closure.sql (8.87ms)6982026/08/27 09:32:14 OK 2_object_stats_trigger.sql (197.13µs)6992026/08/27 09:32:14 goose: up to current file version: 27002026/08/27 09:32:14 OK 20251218171726_add_pins.sql (29.53ms)7012026/08/27 09:32:14 INFO Received uploads request method=POST path=/api/pending_closures7022026/08/27 09:32:14 OK 20260628120000_add_object_size_and_stats.sql (40.17ms)7032026/08/27 09:32:14 goose: successfully migrated database to version: 202606281200007042026/08/27 09:32:14 OK 20260628120000_add_object_size_and_stats.sql (40.66ms)7052026/08/27 09:32:14 goose: successfully migrated database to version: 202606281200007062026/08/27 09:32:14 OK 1_commit_pending_closure.sql (1.11ms)7072026/08/27 09:32:14 OK 2_object_stats_trigger.sql (226.83µs)7082026/08/27 09:32:14 goose: up to current file version: 27092026/08/27 09:32:14 OK 1_commit_pending_closure.sql (6.78ms)7102026/08/27 09:32:14 OK 2_object_stats_trigger.sql (226.67µs)7112026/08/27 09:32:14 goose: up to current file version: 27122026/08/27 09:32:14 OK 20260628120000_add_object_size_and_stats.sql (30.68ms)7132026/08/27 09:32:14 goose: successfully migrated database to version: 202606281200007142026/08/27 09:32:14 OK 1_commit_pending_closure.sql (994.88µs)7152026/08/27 09:32:14 OK 2_object_stats_trigger.sql (199.71µs)7162026/08/27 09:32:14 goose: up to current file version: 27172026/08/27 09:32:14 INFO Received uploads request method=POST path=/api/pending_closures7182026/08/27 09:32:14 INFO Received uploads request method=POST path=/api/pending_closures7192026/08/27 09:32:14 INFO Received uploads request method=POST path=/api/pending_closures7202026/08/27 09:32:14 INFO Received cleanup request method=DELETE path=/api/pending_closures7212026/08/27 09:32:14 INFO Aborted multipart uploads count=1722--- PASS: TestMultipartCleanup (0.90s)723=== CONT TestPinProtectsFromGC724--- PASS: TestReadProxyRangeRequest (0.94s)725=== CONT TestReadProxyRootRedirectsToIndexHTML726--- PASS: TestService_Rustfstest (0.95s)727=== CONT TestClientWithDependencies7282026/08/27 09:32:14 INFO Aborted multipart uploads count=07292026/08/27 09:32:14 WARN Force mode enabled - objects will be deleted immediately without grace period7302026/08/27 09:32:14 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=07312026/08/27 09:32:14 INFO Vacuumed table table=pending_closures7322026/08/27 09:32:14 INFO Vacuumed table table=pending_objects7332026/08/27 09:32:14 INFO Vacuumed table table=multipart_uploads7342026/08/27 09:32:14 INFO Vacuumed table table=closures7352026/08/27 09:32:14 INFO Vacuumed table table=objects736--- PASS: TestGCMetrics (1.04s)737=== CONT TestReadProxyConditionalGet7382026/08/27 09:32:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7392026/08/27 09:32:15 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OTdlOTEzYTUtYjdmMS00Y2QxLWFjNWMtODRlZWU5YjkwOTkyLjU3MmVkOWNiLTMwZjYtNGMyZS1hZmJjLTQyZDhlZjkyYWYzMHgxNzg3ODIzMTM0NzMyMjkwMDAw7402026/08/27 09:32:15 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OTdlOTEzYTUtYjdmMS00Y2QxLWFjNWMtODRlZWU5YjkwOTkyLjU3MmVkOWNiLTMwZjYtNGMyZS1hZmJjLTQyZDhlZjkyYWYzMHgxNzg3ODIzMTM0NzMyMjkwMDAw parts=1741--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.10s)742=== CONT TestClientMultipleUploads7432026/08/27 09:32:15 INFO Created nix-cache-info in bucket bucket=bucket10744--- PASS: TestObjectStatsTrigger (1.37s)745=== CONT TestReadProxyHead746=== NAME TestClientIntegration747 client_integration_test.go:276: Created store path: /nix/var/nix/builds/nix-22777-2593991874/TestClientIntegration2523759905/002/store/fn83i69x4yg4v5v942dmfk2mds26ska7-test-file.txt7482026/08/27 09:32:15 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"749--- PASS: TestGCBugBareHashReferences (1.47s)750=== CONT TestReadProxyInvalidPath7512026/08/27 09:32:15 INFO Received uploads request method=POST path=/api/pending_closures7522026/08/27 09:32:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)7532026/08/27 09:32:15 INFO Uploading fn83i69x4yg4v5v942dmfk2mds26ska7-test-file.txt (152B)7542026/08/27 09:32:15 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"7552026/08/27 09:32:15 WARN Failed to register uploaded object key=fn83i69x4yg4v5v942dmfk2mds26ska7.ls error="server returned 404: 404 page not found\n"7562026/08/27 09:32:15 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign7572026/08/27 09:32:15 INFO Signed narinfos id=1 count=17582026/08/27 09:32:15 INFO Uploading 1 narinfos7592026/08/27 09:32:15 WARN Failed to register uploaded object key=fn83i69x4yg4v5v942dmfk2mds26ska7.narinfo error="server returned 404: 404 page not found\n"7602026/08/27 09:32:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7612026/08/27 09:32:15 INFO Completed upload id=17622026/08/27 09:32:15 INFO Upload complete. (222ms)763=== NAME TestClientIntegration764 client_integration_test.go:292: Retrieved narinfo from S3:765 StorePath: /nix/var/nix/builds/nix-22777-2593991874/TestClientIntegration2523759905/002/store/fn83i69x4yg4v5v942dmfk2mds26ska7-test-file.txt766 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst767 Compression: zstd768 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1769 NarSize: 152770 References: 771 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1772 client_integration_test.go:293: Retrieved .ls file from S3 (compressed size: 77 bytes)773 client_integration_test.go:293: Decompressed .ls content (64 bytes):774 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}775 client_integration_test.go:296: Testing garbage collection...7762026/08/27 09:32:15 INFO Starting cleanup of old closures method=DELETE path=/api/closures7772026/08/27 09:32:15 INFO Garbage collection started7782026/08/27 09:32:15 INFO Aborted multipart uploads count=07792026/08/27 09:32:15 WARN Force mode enabled - objects will be deleted immediately without grace period7802026-08-27 09:32:15.721 UTC [23241] ERROR: relation "goose_db_version" does not exist at character 367812026-08-27 09:32:15.721 UTC [23241] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7822026/08/27 09:32:15 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2811 objects-failed-to-delete=07832026/08/27 09:32:15 INFO Vacuumed table table=pending_closures7842026/08/27 09:32:15 INFO Vacuumed table table=pending_objects7852026/08/27 09:32:15 INFO Vacuumed table table=multipart_uploads7862026/08/27 09:32:15 INFO Vacuumed table table=closures7872026/08/27 09:32:15 INFO Vacuumed table table=objects7882026/08/27 09:32:15 OK 20241026095416_initial_model.sql (114.78ms)7892026/08/27 09:32:15 OK 20251210153512_drop_unused_gin_index.sql (580.58µs)7902026/08/27 09:32:15 OK 20251218171726_add_pins.sql (1.88ms)7912026/08/27 09:32:15 OK 20260628120000_add_object_size_and_stats.sql (15.38ms)7922026/08/27 09:32:15 goose: successfully migrated database to version: 202606281200007932026/08/27 09:32:15 OK 1_commit_pending_closure.sql (6.88ms)7942026/08/27 09:32:15 OK 2_object_stats_trigger.sql (212.13µs)7952026/08/27 09:32:15 goose: up to current file version: 27962026/08/27 09:32:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete797--- PASS: TestReadProxyDisabled (1.74s)798=== CONT TestCompletedNarNotReofferedAcrossClosures7992026/08/27 09:32:16 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=OTdlOTEzYTUtYjdmMS00Y2QxLWFjNWMtODRlZWU5YjkwOTkyLmFmNjQ4MTg2LWRkN2MtNGRkOS04MmMxLWM4MzAwOTdiMjAyOHgxNzg3ODIzMTM0NTM4Njk4MDAw parts=12800--- PASS: TestRedundantMultipartUpload (2.21s)801=== CONT TestReadProxy4048022026-08-27 09:32:16.158 UTC [23261] ERROR: relation "goose_db_version" does not exist at character 368032026-08-27 09:32:16.158 UTC [23261] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8042026-08-27 09:32:16.158 UTC [23262] ERROR: relation "goose_db_version" does not exist at character 368052026-08-27 09:32:16.158 UTC [23262] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8062026-08-27 09:32:16.158 UTC [23263] ERROR: relation "goose_db_version" does not exist at character 368072026-08-27 09:32:16.158 UTC [23263] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8082026-08-27 09:32:16.162 UTC [23265] ERROR: relation "goose_db_version" does not exist at character 368092026-08-27 09:32:16.162 UTC [23265] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8102026-08-27 09:32:16.174 UTC [23269] ERROR: relation "goose_db_version" does not exist at character 368112026-08-27 09:32:16.174 UTC [23269] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8122026/08/27 09:32:16 OK 20241026095416_initial_model.sql (18.79ms)8132026/08/27 09:32:16 OK 20241026095416_initial_model.sql (18.76ms)8142026/08/27 09:32:16 OK 20241026095416_initial_model.sql (19.32ms)8152026/08/27 09:32:16 OK 20251210153512_drop_unused_gin_index.sql (1.09ms)8162026/08/27 09:32:16 OK 20251210153512_drop_unused_gin_index.sql (1.1ms)8172026/08/27 09:32:16 OK 20251210153512_drop_unused_gin_index.sql (1.1ms)8182026/08/27 09:32:16 OK 20241026095416_initial_model.sql (20.41ms)8192026/08/27 09:32:16 OK 20251210153512_drop_unused_gin_index.sql (835.42µs)8202026/08/27 09:32:16 OK 20251218171726_add_pins.sql (2.53ms)8212026/08/27 09:32:16 OK 20251218171726_add_pins.sql (2.51ms)8222026/08/27 09:32:16 OK 20251218171726_add_pins.sql (1.54ms)8232026/08/27 09:32:16 OK 20241026095416_initial_model.sql (15.03ms)8242026/08/27 09:32:16 OK 20251218171726_add_pins.sql (2.99ms)8252026/08/27 09:32:16 OK 20251210153512_drop_unused_gin_index.sql (1.44ms)8262026/08/27 09:32:16 OK 20251218171726_add_pins.sql (14.27ms)8272026/08/27 09:32:16 OK 20260628120000_add_object_size_and_stats.sql (16.7ms)8282026/08/27 09:32:16 OK 20260628120000_add_object_size_and_stats.sql (16.72ms)8292026/08/27 09:32:16 goose: successfully migrated database to version: 202606281200008302026/08/27 09:32:16 goose: successfully migrated database to version: 202606281200008312026/08/27 09:32:16 OK 20260628120000_add_object_size_and_stats.sql (17.23ms)8322026/08/27 09:32:16 goose: successfully migrated database to version: 202606281200008332026/08/27 09:32:16 OK 20260628120000_add_object_size_and_stats.sql (16.89ms)8342026/08/27 09:32:16 goose: successfully migrated database to version: 202606281200008352026/08/27 09:32:16 OK 1_commit_pending_closure.sql (1.88ms)8362026/08/27 09:32:16 OK 1_commit_pending_closure.sql (1.93ms)8372026/08/27 09:32:16 OK 1_commit_pending_closure.sql (1.46ms)8382026/08/27 09:32:16 OK 2_object_stats_trigger.sql (448.96µs)8392026/08/27 09:32:16 goose: up to current file version: 28402026/08/27 09:32:16 OK 2_object_stats_trigger.sql (656.5µs)8412026/08/27 09:32:16 goose: up to current file version: 28422026/08/27 09:32:16 OK 1_commit_pending_closure.sql (2.27ms)8432026/08/27 09:32:16 OK 2_object_stats_trigger.sql (852.63µs)8442026/08/27 09:32:16 goose: up to current file version: 28452026/08/27 09:32:16 OK 20260628120000_add_object_size_and_stats.sql (3.98ms)8462026/08/27 09:32:16 goose: successfully migrated database to version: 202606281200008472026/08/27 09:32:16 OK 2_object_stats_trigger.sql (610.25µs)8482026/08/27 09:32:16 goose: up to current file version: 28492026/08/27 09:32:16 OK 1_commit_pending_closure.sql (1.63ms)8502026/08/27 09:32:16 OK 2_object_stats_trigger.sql (530.21µs)8512026/08/27 09:32:16 goose: up to current file version: 28522026/08/27 09:32:16 INFO Created nix-cache-info in bucket bucket=bucket148532026/08/27 09:32:16 INFO Created nix-cache-info in bucket bucket=bucket17854--- PASS: TestReadProxyConditionalGet (1.51s)855=== CONT TestService_healthCheckHandler856--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.76s)857=== CONT TestReadProxyNarStreaming858=== NAME TestPinProtectsFromGC859 client_integration_test.go:646: Pinned store path: /nix/var/nix/builds/nix-22777-2593991874/TestPinProtectsFromGC4221639750/001/store/kzx3fazdv8dmm8kw4y8yyf2a6km58c8j-pinned-file.txt860 client_integration_test.go:647: Unpinned store path: /nix/var/nix/builds/nix-22777-2593991874/TestPinProtectsFromGC4221639750/001/store/9kn79fb6j5agp1rnf03mjcwaq68ikhfc-unpinned-file.txt861=== NAME TestClientMultipleUploads862 client_integration_test.go:338: Created store path 0: /nix/var/nix/builds/nix-22777-2593991874/TestClientMultipleUploads2174336589/001/store/bfask8z8xb9q0xrkfi2d70zm5d7jj9jx-test-file-0.txt8632026/08/27 09:32:16 INFO Created nix-cache-info in bucket bucket=bucket168642026-08-27 09:32:16.679 UTC [23296] ERROR: relation "goose_db_version" does not exist at character 368652026-08-27 09:32:16.679 UTC [23296] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8662026-08-27 09:32:16.691 UTC [23299] ERROR: relation "goose_db_version" does not exist at character 368672026-08-27 09:32:16.691 UTC [23299] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC868 client_integration_test.go:338: Created store path 1: /nix/var/nix/builds/nix-22777-2593991874/TestClientMultipleUploads2174336589/001/store/m39k1wnbdsz5x409a41r1cp3v0x0r8a6-test-file-1.txt8692026/08/27 09:32:16 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"870 client_integration_test.go:338: Created store path 2: /nix/var/nix/builds/nix-22777-2593991874/TestClientMultipleUploads2174336589/001/store/2acm9zhnlwgzljwav66afq0h9pxqd4mg-test-file-2.txt8712026/08/27 09:32:16 OK 20241026095416_initial_model.sql (60.97ms)8722026/08/27 09:32:16 OK 20251210153512_drop_unused_gin_index.sql (1.08ms)8732026/08/27 09:32:16 INFO Received uploads request method=POST path=/api/pending_closures8742026/08/27 09:32:16 OK 20241026095416_initial_model.sql (58.14ms)8752026/08/27 09:32:16 OK 20251210153512_drop_unused_gin_index.sql (826.96µs)8762026/08/27 09:32:16 OK 20251218171726_add_pins.sql (2.89ms)8772026/08/27 09:32:16 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8782026/08/27 09:32:16 INFO Uploading kzx3fazdv8dmm8kw4y8yyf2a6km58c8j-pinned-file.txt (128B)8792026/08/27 09:32:16 OK 20251218171726_add_pins.sql (2.55ms)8802026/08/27 09:32:16 OK 20260628120000_add_object_size_and_stats.sql (5.62ms)8812026/08/27 09:32:16 goose: successfully migrated database to version: 202606281200008822026/08/27 09:32:16 OK 1_commit_pending_closure.sql (11.01ms)8832026/08/27 09:32:16 OK 2_object_stats_trigger.sql (301.38µs)8842026/08/27 09:32:16 goose: up to current file version: 28852026/08/27 09:32:16 OK 20260628120000_add_object_size_and_stats.sql (31.91ms)8862026/08/27 09:32:16 goose: successfully migrated database to version: 202606281200008872026/08/27 09:32:16 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"8882026/08/27 09:32:16 OK 1_commit_pending_closure.sql (1.35ms)8892026/08/27 09:32:16 OK 2_object_stats_trigger.sql (243.75µs)8902026/08/27 09:32:16 goose: up to current file version: 28912026/08/27 09:32:16 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"8922026/08/27 09:32:16 WARN Failed to register uploaded object key=kzx3fazdv8dmm8kw4y8yyf2a6km58c8j.ls error="server returned 404: 404 page not found\n"8932026/08/27 09:32:16 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign8942026/08/27 09:32:16 INFO Signed narinfos id=1 count=18952026/08/27 09:32:16 INFO Uploading 1 narinfos8962026/08/27 09:32:16 WARN Failed to register uploaded object key=kzx3fazdv8dmm8kw4y8yyf2a6km58c8j.narinfo error="server returned 404: 404 page not found\n"8972026/08/27 09:32:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8982026/08/27 09:32:16 INFO Completed upload id=18992026/08/27 09:32:16 INFO Upload complete. (210ms)9002026/08/27 09:32:16 INFO Received uploads request method=POST path=/api/pending_closures901--- PASS: TestReadProxyInvalidPath (1.54s)902=== CONT TestService_NativeMTLS9032026/08/27 09:32:16 INFO Received uploads request method=POST path=/api/pending_closures9042026/08/27 09:32:16 INFO Received uploads request method=POST path=/api/pending_closures9052026/08/27 09:32:16 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)9062026/08/27 09:32:16 INFO Uploading 2acm9zhnlwgzljwav66afq0h9pxqd4mg-test-file-2.txt (160B)9072026/08/27 09:32:16 INFO Uploading bfask8z8xb9q0xrkfi2d70zm5d7jj9jx-test-file-0.txt (160B)9082026/08/27 09:32:16 INFO Uploading m39k1wnbdsz5x409a41r1cp3v0x0r8a6-test-file-1.txt (160B)9092026/08/27 09:32:17 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9102026/08/27 09:32:17 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"911=== NAME TestClientWithDependencies912 client_integration_test.go:593: Built derivation: /nix/var/nix/builds/nix-22777-2593991874/TestClientWithDependencies2176668631/001/store/30warnbn7d1aqyx14z2nh23fn27c172a-test-script9132026/08/27 09:32:17 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"9142026/08/27 09:32:17 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"9152026/08/27 09:32:17 INFO Received uploads request method=POST path=/api/pending_closures9162026/08/27 09:32:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9172026/08/27 09:32:17 INFO Uploading 9kn79fb6j5agp1rnf03mjcwaq68ikhfc-unpinned-file.txt (128B)9182026/08/27 09:32:17 WARN Failed to register uploaded object key=2acm9zhnlwgzljwav66afq0h9pxqd4mg.ls error="server returned 404: 404 page not found\n"9192026/08/27 09:32:17 WARN Failed to register uploaded object key=bfask8z8xb9q0xrkfi2d70zm5d7jj9jx.ls error="server returned 404: 404 page not found\n"920 client_integration_test.go:595: Found 1 dependencies (including self)9212026/08/27 09:32:17 WARN Failed to register uploaded object key=m39k1wnbdsz5x409a41r1cp3v0x0r8a6.ls error="server returned 404: 404 page not found\n"9222026/08/27 09:32:17 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"9232026/08/27 09:32:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9242026/08/27 09:32:17 INFO Signed narinfos id=1 count=19252026/08/27 09:32:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign9262026/08/27 09:32:17 INFO Signed narinfos id=2 count=19272026/08/27 09:32:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign9282026/08/27 09:32:17 INFO Signed narinfos id=3 count=19292026/08/27 09:32:17 INFO Uploading 3 narinfos930--- PASS: TestReadProxyHead (1.81s)931=== CONT TestReadProxyNarinfoAlreadyDecompressed9322026/08/27 09:32:17 WARN Failed to register uploaded object key=bfask8z8xb9q0xrkfi2d70zm5d7jj9jx.narinfo error="server returned 404: 404 page not found\n"9332026/08/27 09:32:17 WARN Failed to register uploaded object key=9kn79fb6j5agp1rnf03mjcwaq68ikhfc.ls error="server returned 404: 404 page not found\n"9342026/08/27 09:32:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign9352026/08/27 09:32:17 INFO Signed narinfos id=2 count=19362026/08/27 09:32:17 INFO Uploading 1 narinfos9372026/08/27 09:32:17 WARN Failed to register uploaded object key=2acm9zhnlwgzljwav66afq0h9pxqd4mg.narinfo error="server returned 404: 404 page not found\n"9382026/08/27 09:32:17 WARN Failed to register uploaded object key=m39k1wnbdsz5x409a41r1cp3v0x0r8a6.narinfo error="server returned 404: 404 page not found\n"9392026/08/27 09:32:17 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9402026/08/27 09:32:17 INFO Completed upload id=19412026/08/27 09:32:17 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete9422026/08/27 09:32:17 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9432026/08/27 09:32:17 INFO Received uploads request method=POST path=/api/pending_closures9442026/08/27 09:32:17 INFO Completed upload id=29452026/08/27 09:32:17 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete9462026/08/27 09:32:17 INFO Completed upload id=39472026/08/27 09:32:17 INFO Upload complete. (392ms)948=== NAME TestClientMultipleUploads949 client_integration_test.go:349: Uploaded 3 paths in 427.179ms9502026/08/27 09:32:17 WARN Failed to register uploaded object key=9kn79fb6j5agp1rnf03mjcwaq68ikhfc.narinfo error="server returned 404: 404 page not found\n"9512026/08/27 09:32:17 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete9522026/08/27 09:32:17 INFO Completed upload id=29532026/08/27 09:32:17 INFO Upload complete. (252ms)954--- PASS: TestClientMultipleUploads (2.16s)955=== CONT TestMetricsInventory9562026/08/27 09:32:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9572026/08/27 09:32:17 INFO Uploading 30warnbn7d1aqyx14z2nh23fn27c172a-test-script (136B)9582026/08/27 09:32:17 INFO Received create pin request method=POST path=/api/pins/myapp9592026/08/27 09:32:17 WARN Failed to register uploaded object key=log/qi7v4kf3qa7ac7b0ygpkrm0lilzyw0f5-test-script.drv error="server returned 404: 404 page not found\n"9602026/08/27 09:32:17 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"9612026/08/27 09:32:17 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-22777-2593991874/TestPinProtectsFromGC4221639750/001/store/kzx3fazdv8dmm8kw4y8yyf2a6km58c8j-pinned-file.txt narinfo_key=kzx3fazdv8dmm8kw4y8yyf2a6km58c8j.narinfo9622026/08/27 09:32:17 INFO Starting cleanup of old closures method=DELETE path=/api/closures9632026/08/27 09:32:17 INFO Garbage collection started9642026/08/27 09:32:17 INFO Aborted multipart uploads count=09652026/08/27 09:32:17 WARN Force mode enabled - objects will be deleted immediately without grace period9662026/08/27 09:32:17 WARN Failed to register uploaded object key=30warnbn7d1aqyx14z2nh23fn27c172a.ls error="server returned 404: 404 page not found\n"9672026/08/27 09:32:17 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9682026/08/27 09:32:17 INFO Signed narinfos id=1 count=19692026/08/27 09:32:17 INFO Uploading 1 narinfos9702026/08/27 09:32:17 WARN Failed to register uploaded object key=30warnbn7d1aqyx14z2nh23fn27c172a.narinfo error="server returned 404: 404 page not found\n"9712026/08/27 09:32:17 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9722026/08/27 09:32:17 INFO Completed upload id=19732026/08/27 09:32:17 INFO Upload complete. (188ms)974=== NAME TestClientWithDependencies975 client_integration_test.go:597: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-22777-2593991874/TestClientWithDependencies2176668631/001/store) requires matching store prefix976--- PASS: TestClientWithDependencies (2.46s)977=== CONT TestReadProxyNarinfo9782026-08-27 09:32:17.365 UTC [23350] ERROR: relation "goose_db_version" does not exist at character 369792026-08-27 09:32:17.365 UTC [23350] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9802026-08-27 09:32:17.366 UTC [23351] ERROR: relation "goose_db_version" does not exist at character 369812026-08-27 09:32:17.366 UTC [23351] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9822026/08/27 09:32:17 OK 20241026095416_initial_model.sql (18.5ms)9832026/08/27 09:32:17 OK 20241026095416_initial_model.sql (18.99ms)9842026/08/27 09:32:17 OK 20251210153512_drop_unused_gin_index.sql (561.63µs)9852026/08/27 09:32:17 OK 20251210153512_drop_unused_gin_index.sql (484.58µs)9862026/08/27 09:32:17 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=09872026/08/27 09:32:17 OK 20251218171726_add_pins.sql (7.63ms)9882026/08/27 09:32:17 OK 20251218171726_add_pins.sql (7.59ms)9892026/08/27 09:32:17 INFO Vacuumed table table=pending_closures9902026/08/27 09:32:17 OK 20260628120000_add_object_size_and_stats.sql (4.1ms)9912026/08/27 09:32:17 goose: successfully migrated database to version: 202606281200009922026/08/27 09:32:17 OK 20260628120000_add_object_size_and_stats.sql (4.51ms)9932026/08/27 09:32:17 goose: successfully migrated database to version: 202606281200009942026/08/27 09:32:17 INFO Vacuumed table table=pending_objects9952026/08/27 09:32:17 OK 1_commit_pending_closure.sql (1.04ms)9962026/08/27 09:32:17 OK 1_commit_pending_closure.sql (1.51ms)9972026/08/27 09:32:17 OK 2_object_stats_trigger.sql (563.17µs)9982026/08/27 09:32:17 goose: up to current file version: 29992026/08/27 09:32:17 OK 2_object_stats_trigger.sql (684.75µs)10002026/08/27 09:32:17 goose: up to current file version: 210012026/08/27 09:32:17 INFO Vacuumed table table=multipart_uploads10022026/08/27 09:32:17 INFO Vacuumed table table=closures10032026/08/27 09:32:17 INFO Vacuumed table table=objects1004--- PASS: TestReadProxy404 (1.39s)1005=== CONT TestNARDeduplicationMetadataUploadBug10062026/08/27 09:32:17 INFO Received uploads request method=POST path=/api/pending_closures10072026/08/27 09:32:17 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2811 objects_failed=01008=== NAME TestClientIntegration1009 client_integration_test.go:303: Objects in database after GC:1010 client_integration_test.go:303: Successfully deleted all objects with GC --force1011--- PASS: TestClientIntegration (3.71s)1012=== CONT TestIsValidCachePath1013=== RUN TestIsValidCachePath/narinfo1014=== PAUSE TestIsValidCachePath/narinfo1015=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1016=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1017=== RUN TestIsValidCachePath/nar_zst1018=== PAUSE TestIsValidCachePath/nar_zst1019=== RUN TestIsValidCachePath/nar_xz1020=== PAUSE TestIsValidCachePath/nar_xz1021=== RUN TestIsValidCachePath/nar_bz21022=== PAUSE TestIsValidCachePath/nar_bz21023=== RUN TestIsValidCachePath/nar_uncompressed1024=== PAUSE TestIsValidCachePath/nar_uncompressed1025=== RUN TestIsValidCachePath/ls1026=== PAUSE TestIsValidCachePath/ls1027=== RUN TestIsValidCachePath/log1028=== PAUSE TestIsValidCachePath/log1029=== RUN TestIsValidCachePath/realisation1030=== PAUSE TestIsValidCachePath/realisation1031=== RUN TestIsValidCachePath/nix-cache-info1032=== PAUSE TestIsValidCachePath/nix-cache-info1033=== RUN TestIsValidCachePath/index.html1034=== PAUSE TestIsValidCachePath/index.html1035=== RUN TestIsValidCachePath/traversal_parent1036=== PAUSE TestIsValidCachePath/traversal_parent1037=== RUN TestIsValidCachePath/traversal_in_middle1038=== PAUSE TestIsValidCachePath/traversal_in_middle1039=== RUN TestIsValidCachePath/invalid_char_e1040=== PAUSE TestIsValidCachePath/invalid_char_e1041=== RUN TestIsValidCachePath/invalid_char_u1042=== PAUSE TestIsValidCachePath/invalid_char_u1043=== RUN TestIsValidCachePath/random_path1044=== PAUSE TestIsValidCachePath/random_path1045=== RUN TestIsValidCachePath/empty1046=== PAUSE TestIsValidCachePath/empty1047=== RUN TestIsValidCachePath/leading_slash1048=== PAUSE TestIsValidCachePath/leading_slash1049=== RUN TestIsValidCachePath/wrong_extension1050=== PAUSE TestIsValidCachePath/wrong_extension1051=== RUN TestIsValidCachePath/short_hash1052=== PAUSE TestIsValidCachePath/short_hash1053=== CONT TestCreatePendingClosureRejectsOversizedNAR10542026/08/27 09:32:17 INFO Received uploads request method=POST path=/api/pending_closures1055--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1056=== CONT TestParseSingleRange1057=== RUN TestParseSingleRange/none1058=== PAUSE TestParseSingleRange/none1059=== RUN TestParseSingleRange/unknown_unit1060=== PAUSE TestParseSingleRange/unknown_unit1061=== RUN TestParseSingleRange/multi-range_ignored1062=== PAUSE TestParseSingleRange/multi-range_ignored1063=== RUN TestParseSingleRange/malformed_no_dash1064=== PAUSE TestParseSingleRange/malformed_no_dash1065=== RUN TestParseSingleRange/malformed_both_empty1066=== PAUSE TestParseSingleRange/malformed_both_empty1067=== RUN TestParseSingleRange/malformed_end_before_start1068=== PAUSE TestParseSingleRange/malformed_end_before_start1069=== RUN TestParseSingleRange/closed1070=== PAUSE TestParseSingleRange/closed1071=== RUN TestParseSingleRange/open-ended1072=== PAUSE TestParseSingleRange/open-ended1073=== RUN TestParseSingleRange/end_clamped_to_size1074=== PAUSE TestParseSingleRange/end_clamped_to_size1075=== RUN TestParseSingleRange/suffix1076=== PAUSE TestParseSingleRange/suffix1077=== RUN TestParseSingleRange/suffix_exceeds_size1078=== PAUSE TestParseSingleRange/suffix_exceeds_size1079=== RUN TestParseSingleRange/single_byte1080=== PAUSE TestParseSingleRange/single_byte1081=== RUN TestParseSingleRange/start_past_EOF1082=== PAUSE TestParseSingleRange/start_past_EOF1083=== RUN TestParseSingleRange/start_far_past_EOF1084=== PAUSE TestParseSingleRange/start_far_past_EOF1085=== CONT TestCacheConfigHandlerMaxNarSize1086--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1087=== CONT TestResurrectedObjectNotDeleted10882026-08-27 09:32:17.814 UTC [23376] ERROR: relation "goose_db_version" does not exist at character 3610892026-08-27 09:32:17.814 UTC [23376] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10902026/08/27 09:32:17 OK 20241026095416_initial_model.sql (110.58ms)10912026/08/27 09:32:18 OK 20251210153512_drop_unused_gin_index.sql (11.83ms)10922026/08/27 09:32:18 OK 20251218171726_add_pins.sql (21.14ms)10932026-08-27 09:32:18.049 UTC [23380] ERROR: relation "goose_db_version" does not exist at character 3610942026-08-27 09:32:18.049 UTC [23380] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10952026/08/27 09:32:18 OK 20260628120000_add_object_size_and_stats.sql (79.15ms)10962026/08/27 09:32:18 goose: successfully migrated database to version: 2026062812000010972026/08/27 09:32:18 OK 1_commit_pending_closure.sql (12.59ms)10982026/08/27 09:32:18 OK 2_object_stats_trigger.sql (677.21µs)10992026/08/27 09:32:18 goose: up to current file version: 21100--- PASS: TestService_healthCheckHandler (1.80s)1101=== CONT TestGenerateLandingPage1102--- PASS: TestGenerateLandingPage (0.01s)1103=== CONT TestOrphanedObjectsGCStressTest11042026/08/27 09:32:18 OK 20241026095416_initial_model.sql (205.63ms)11052026/08/27 09:32:18 OK 20251210153512_drop_unused_gin_index.sql (6.92ms)11062026/08/27 09:32:18 OK 20251218171726_add_pins.sql (26.26ms)11072026/08/27 09:32:18 OK 20260628120000_add_object_size_and_stats.sql (35.62ms)11082026/08/27 09:32:18 goose: successfully migrated database to version: 2026062812000011092026/08/27 09:32:18 OK 1_commit_pending_closure.sql (9.97ms)11102026/08/27 09:32:18 OK 2_object_stats_trigger.sql (693.88µs)11112026/08/27 09:32:18 goose: up to current file version: 211122026-08-27 09:32:18.621 UTC [23391] ERROR: relation "goose_db_version" does not exist at character 3611132026-08-27 09:32:18.621 UTC [23391] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1114--- PASS: TestReadProxyNarStreaming (2.01s)1115=== CONT TestCacheConfigHandler1116=== RUN TestCacheConfigHandler/full_config,_no_issuer1117=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1118=== RUN TestCacheConfigHandler/no_cache_url_configured1119=== PAUSE TestCacheConfigHandler/no_cache_url_configured1120=== RUN TestCacheConfigHandler/no_signing_keys1121=== PAUSE TestCacheConfigHandler/no_signing_keys1122=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1123=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1124=== CONT TestOrphanedObjectsGC11252026-08-27 09:32:18.806 UTC [23398] ERROR: relation "goose_db_version" does not exist at character 3611262026-08-27 09:32:18.806 UTC [23398] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11272026/08/27 09:32:18 OK 20241026095416_initial_model.sql (167.92ms)11282026/08/27 09:32:18 OK 20251210153512_drop_unused_gin_index.sql (12.42ms)11292026-08-27 09:32:18.837 UTC [23399] ERROR: relation "goose_db_version" does not exist at character 3611302026-08-27 09:32:18.837 UTC [23399] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11312026/08/27 09:32:18 OK 20251218171726_add_pins.sql (17.76ms)11322026/08/27 09:32:18 OK 20260628120000_add_object_size_and_stats.sql (7.99ms)11332026/08/27 09:32:18 goose: successfully migrated database to version: 2026062812000011342026/08/27 09:32:18 OK 1_commit_pending_closure.sql (3.49ms)11352026/08/27 09:32:18 OK 2_object_stats_trigger.sql (543.08µs)11362026/08/27 09:32:18 goose: up to current file version: 211372026-08-27 09:32:18.907 UTC [23402] ERROR: relation "goose_db_version" does not exist at character 3611382026-08-27 09:32:18.907 UTC [23402] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11392026/08/27 09:32:18 OK 20241026095416_initial_model.sql (120.8ms)11402026/08/27 09:32:18 OK 20251210153512_drop_unused_gin_index.sql (14.61ms)11412026/08/27 09:32:18 OK 20241026095416_initial_model.sql (134.68ms)11422026/08/27 09:32:18 OK 20251218171726_add_pins.sql (8.71ms)11432026/08/27 09:32:19 OK 20251210153512_drop_unused_gin_index.sql (3.09ms)11442026/08/27 09:32:19 OK 20251218171726_add_pins.sql (14.39ms)11452026/08/27 09:32:19 OK 20260628120000_add_object_size_and_stats.sql (25.23ms)11462026/08/27 09:32:19 goose: successfully migrated database to version: 2026062812000011472026/08/27 09:32:19 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11482026/08/27 09:32:19 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1149--- PASS: TestService_NativeMTLS (2.09s)1150=== CONT TestClientErrorHandling1151=== RUN TestClientErrorHandling/InvalidStorePath1152=== PAUSE TestClientErrorHandling/InvalidStorePath1153=== RUN TestClientErrorHandling/InvalidAuthToken1154=== PAUSE TestClientErrorHandling/InvalidAuthToken1155=== RUN TestClientErrorHandling/ServerNotAvailable1156=== PAUSE TestClientErrorHandling/ServerNotAvailable1157=== CONT TestClientCADerivations11582026/08/27 09:32:19 OK 1_commit_pending_closure.sql (16.04ms)11592026/08/27 09:32:19 OK 2_object_stats_trigger.sql (670.5µs)11602026/08/27 09:32:19 goose: up to current file version: 211612026/08/27 09:32:19 OK 20260628120000_add_object_size_and_stats.sql (49.4ms)11622026/08/27 09:32:19 goose: successfully migrated database to version: 2026062812000011632026/08/27 09:32:19 OK 1_commit_pending_closure.sql (10.7ms)11642026/08/27 09:32:19 OK 2_object_stats_trigger.sql (467.75µs)11652026/08/27 09:32:19 goose: up to current file version: 211662026/08/27 09:32:19 OK 20241026095416_initial_model.sql (106.35ms)11672026/08/27 09:32:19 OK 20251210153512_drop_unused_gin_index.sql (11.44ms)11682026/08/27 09:32:19 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11692026/08/27 09:32:19 OK 20251218171726_add_pins.sql (54.88ms)11702026/08/27 09:32:19 OK 20260628120000_add_object_size_and_stats.sql (47.97ms)11712026/08/27 09:32:19 goose: successfully migrated database to version: 2026062812000011722026/08/27 09:32:19 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=OTdlOTEzYTUtYjdmMS00Y2QxLWFjNWMtODRlZWU5YjkwOTkyLjhiODA0ODBiLTgyNTMtNDRiZi05ZWZjLTY1ODk5N2JhNjNlZXgxNzg3ODIzMTM3NjA1Njg5MDAw parts=1211732026/08/27 09:32:19 INFO Received uploads request method=POST path=/api/pending_closures1174--- PASS: TestCompletedNarNotReofferedAcrossClosures (3.10s)1175=== CONT TestService_createPendingClosureHandler11762026/08/27 09:32:19 OK 1_commit_pending_closure.sql (13.85ms)11772026/08/27 09:32:19 OK 2_object_stats_trigger.sql (1.1ms)11782026/08/27 09:32:19 goose: up to current file version: 211792026/08/27 09:32:19 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01180=== NAME TestPinProtectsFromGC1181 client_integration_test.go:709: Pin successfully protected closure from garbage collection11822026-08-27 09:32:19.314 UTC [23408] ERROR: relation "goose_db_version" does not exist at character 3611832026-08-27 09:32:19.314 UTC [23408] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1184--- PASS: TestMetricsInventory (2.13s)1185=== CONT TestCacheStatsHandler1186--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.21s)1187=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT1188--- PASS: TestPinProtectsFromGC (4.50s)1189=== CONT TestCompleteMultipartUnregistered1190--- PASS: TestReadProxyNarinfo (2.12s)1191=== CONT TestGCTaskStore_PhaseUpdates1192--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1193=== CONT TestService_verifyS3Integrity11942026-08-27 09:32:19.504 UTC [23418] ERROR: relation "goose_db_version" does not exist at character 3611952026-08-27 09:32:19.504 UTC [23418] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11962026/08/27 09:32:19 OK 20241026095416_initial_model.sql (115.48ms)11972026/08/27 09:32:19 OK 20251210153512_drop_unused_gin_index.sql (1.54ms)11982026/08/27 09:32:19 OK 20251218171726_add_pins.sql (21.69ms)11992026/08/27 09:32:19 OK 20260628120000_add_object_size_and_stats.sql (4.39ms)12002026/08/27 09:32:19 goose: successfully migrated database to version: 2026062812000012012026/08/27 09:32:19 OK 1_commit_pending_closure.sql (3.09ms)12022026/08/27 09:32:19 OK 2_object_stats_trigger.sql (368.92µs)12032026/08/27 09:32:19 goose: up to current file version: 212042026/08/27 09:32:19 OK 20241026095416_initial_model.sql (34.4ms)12052026/08/27 09:32:19 OK 20251210153512_drop_unused_gin_index.sql (1.16ms)12062026/08/27 09:32:19 OK 20251218171726_add_pins.sql (8.67ms)12072026/08/27 09:32:19 OK 20260628120000_add_object_size_and_stats.sql (17.95ms)12082026/08/27 09:32:19 goose: successfully migrated database to version: 2026062812000012092026/08/27 09:32:19 OK 1_commit_pending_closure.sql (6.47ms)12102026/08/27 09:32:19 OK 2_object_stats_trigger.sql (283.04µs)12112026/08/27 09:32:19 goose: up to current file version: 212122026/08/27 09:32:19 INFO Created nix-cache-info in bucket bucket=bucket281213=== NAME TestNARDeduplicationMetadataUploadBug1214 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-22777-2593991874/TestNARDeduplicationMetadataUploadBug1651668557/001/store/fdl7f3jd60x766shgvx44qkj3szvn23b-file1.txt1215--- PASS: TestResurrectedObjectNotDeleted (2.22s)1216=== CONT TestGracefulShutdownDrainsInflight12172026/08/27 09:32:19 INFO Starting HTTP server address=127.0.0.1:5111712182026/08/27 09:32:19 INFO Shutdown signal received, draining in-flight requests timeout=10s12192026-08-27 09:32:19.880 UTC [23438] ERROR: relation "goose_db_version" does not exist at character 3612202026-08-27 09:32:19.880 UTC [23438] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12212026-08-27 09:32:19.892 UTC [23442] ERROR: relation "goose_db_version" does not exist at character 3612222026-08-27 09:32:19.892 UTC [23442] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12232026/08/27 09:32:19 OK 20241026095416_initial_model.sql (15.12ms)12242026/08/27 09:32:19 OK 20251210153512_drop_unused_gin_index.sql (1.17ms)12252026/08/27 09:32:19 OK 20251218171726_add_pins.sql (3.9ms)12262026/08/27 09:32:19 OK 20260628120000_add_object_size_and_stats.sql (7.42ms)12272026/08/27 09:32:19 goose: successfully migrated database to version: 2026062812000012282026/08/27 09:32:19 OK 1_commit_pending_closure.sql (1.18ms)12292026/08/27 09:32:19 OK 2_object_stats_trigger.sql (248.88µs)12302026/08/27 09:32:19 goose: up to current file version: 21231--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1232=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle12332026/08/27 09:32:19 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12342026/08/27 09:32:19 OK 20241026095416_initial_model.sql (61.73ms)12352026/08/27 09:32:19 OK 20251210153512_drop_unused_gin_index.sql (1.28ms)12362026/08/27 09:32:20 OK 20251218171726_add_pins.sql (44.43ms)12372026/08/27 09:32:20 INFO Received uploads request method=POST path=/api/pending_closures12382026/08/27 09:32:20 OK 20260628120000_add_object_size_and_stats.sql (21.68ms)12392026/08/27 09:32:20 goose: successfully migrated database to version: 2026062812000012402026/08/27 09:32:20 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12412026/08/27 09:32:20 INFO Uploading fdl7f3jd60x766shgvx44qkj3szvn23b-file1.txt (160B)12422026/08/27 09:32:20 OK 1_commit_pending_closure.sql (9.04ms)12432026/08/27 09:32:20 OK 2_object_stats_trigger.sql (212.29µs)12442026/08/27 09:32:20 goose: up to current file version: 212452026/08/27 09:32:20 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12462026/08/27 09:32:20 WARN Failed to register uploaded object key=fdl7f3jd60x766shgvx44qkj3szvn23b.ls error="server returned 404: 404 page not found\n"12472026/08/27 09:32:20 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12482026/08/27 09:32:20 INFO Signed narinfos id=1 count=112492026/08/27 09:32:20 INFO Uploading 1 narinfos12502026/08/27 09:32:20 WARN Failed to register uploaded object key=fdl7f3jd60x766shgvx44qkj3szvn23b.narinfo error="server returned 404: 404 page not found\n"12512026/08/27 09:32:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12522026/08/27 09:32:20 INFO Completed upload id=112532026/08/27 09:32:20 INFO Upload complete. (273ms)1254=== NAME TestNARDeduplicationMetadataUploadBug1255 metadata_upload_test.go:54: Retrieved narinfo from S3:1256 StorePath: /nix/var/nix/builds/nix-22777-2593991874/TestNARDeduplicationMetadataUploadBug1651668557/001/store/fdl7f3jd60x766shgvx44qkj3szvn23b-file1.txt1257 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1258 Compression: zstd1259 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1260 NarSize: 1601261 References: 1262 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1263 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1264 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1265 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1266 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-22777-2593991874/TestNARDeduplicationMetadataUploadBug1651668557/001/store/yvz99aah2m1bfay729qynzm4i13sfpk3-file2.txt12672026/08/27 09:32:20 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12682026/08/27 09:32:20 INFO Received uploads request method=POST path=/api/pending_closures12692026/08/27 09:32:20 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12702026/08/27 09:32:20 WARN Failed to register uploaded object key=yvz99aah2m1bfay729qynzm4i13sfpk3.ls error="server returned 404: 404 page not found\n"12712026/08/27 09:32:20 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12722026/08/27 09:32:20 INFO Signed narinfos id=2 count=112732026/08/27 09:32:20 INFO Uploading 1 narinfos12742026/08/27 09:32:20 WARN Failed to register uploaded object key=yvz99aah2m1bfay729qynzm4i13sfpk3.narinfo error="server returned 404: 404 page not found\n"12752026/08/27 09:32:20 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12762026/08/27 09:32:20 INFO Completed upload id=212772026/08/27 09:32:20 INFO Upload complete. (154ms)1278 metadata_upload_test.go:76: Retrieved narinfo from S3:1279 StorePath: /nix/var/nix/builds/nix-22777-2593991874/TestNARDeduplicationMetadataUploadBug1651668557/001/store/yvz99aah2m1bfay729qynzm4i13sfpk3-file2.txt1280 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1281 Compression: zstd1282 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1283 NarSize: 1601284 References: 1285 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1286 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1287 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1288 {"version":1,"root":{"type":"regular","size":44}}1289--- PASS: TestNARDeduplicationMetadataUploadBug (2.97s)1290=== CONT TestGCTaskStore_Fail1291--- PASS: TestGCTaskStore_Fail (0.00s)1292=== CONT TestProxyWriteTimeout1293=== RUN TestProxyWriteTimeout/narinfo1294=== PAUSE TestProxyWriteTimeout/narinfo1295=== RUN TestProxyWriteTimeout/1_GiB_nar1296=== PAUSE TestProxyWriteTimeout/1_GiB_nar1297=== RUN TestProxyWriteTimeout/10_GiB_nar1298=== PAUSE TestProxyWriteTimeout/10_GiB_nar1299=== RUN TestProxyWriteTimeout/unknown_size1300=== PAUSE TestProxyWriteTimeout/unknown_size1301=== CONT TestUploadHandlersRejectOversizedBody1302=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1303=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1304=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1305=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1306=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1307=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1308=== CONT TestSkippedUploadsHandler13092026/08/27 09:32:20 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001310--- PASS: TestSkippedUploadsHandler (0.00s)1311=== CONT TestService_cleanupPendingClosuresHandler13122026-08-27 09:32:20.727 UTC [23472] ERROR: relation "goose_db_version" does not exist at character 3613132026-08-27 09:32:20.727 UTC [23472] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13142026-08-27 09:32:20.894 UTC [23475] ERROR: relation "goose_db_version" does not exist at character 3613152026-08-27 09:32:20.894 UTC [23475] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13162026-08-27 09:32:20.979 UTC [23476] ERROR: relation "goose_db_version" does not exist at character 3613172026-08-27 09:32:20.979 UTC [23476] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13182026/08/27 09:32:20 OK 20241026095416_initial_model.sql (189.14ms)13192026/08/27 09:32:20 OK 20251210153512_drop_unused_gin_index.sql (1.79ms)13202026-08-27 09:32:21.007 UTC [23477] ERROR: relation "goose_db_version" does not exist at character 3613212026-08-27 09:32:21.007 UTC [23477] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13222026/08/27 09:32:21 OK 20251218171726_add_pins.sql (35.03ms)13232026-08-27 09:32:21.037 UTC [23478] ERROR: relation "goose_db_version" does not exist at character 3613242026-08-27 09:32:21.037 UTC [23478] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13252026/08/27 09:32:21 OK 20260628120000_add_object_size_and_stats.sql (31.38ms)13262026/08/27 09:32:21 goose: successfully migrated database to version: 2026062812000013272026/08/27 09:32:21 OK 1_commit_pending_closure.sql (9.27ms)13282026/08/27 09:32:21 OK 2_object_stats_trigger.sql (217.67µs)13292026/08/27 09:32:21 goose: up to current file version: 213302026/08/27 09:32:21 OK 20241026095416_initial_model.sql (175.33ms)13312026/08/27 09:32:21 OK 20251210153512_drop_unused_gin_index.sql (20.3ms)13322026-08-27 09:32:21.189 UTC [23481] ERROR: relation "goose_db_version" does not exist at character 3613332026-08-27 09:32:21.189 UTC [23481] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1334=== NAME TestOrphanedObjectsGC1335 orphaned_objects_gc_test.go:290: GC Test Summary:1336 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1337 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1338 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1339 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1340 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1341--- PASS: TestOrphanedObjectsGC (2.55s)1342=== CONT TestUploadHandlersRejectInvalidKeys1343=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1344=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1345=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1346=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1347=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1348=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1349=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1350=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1351=== CONT TestService_ReadAuthMiddleware13522026/08/27 09:32:21 OK 20251218171726_add_pins.sql (35.87ms)13532026/08/27 09:32:21 OK 20260628120000_add_object_size_and_stats.sql (44.99ms)13542026/08/27 09:32:21 goose: successfully migrated database to version: 2026062812000013552026/08/27 09:32:21 OK 1_commit_pending_closure.sql (1.97ms)13562026/08/27 09:32:21 OK 2_object_stats_trigger.sql (228µs)13572026/08/27 09:32:21 goose: up to current file version: 213582026/08/27 09:32:21 OK 20241026095416_initial_model.sql (234.46ms)13592026/08/27 09:32:21 OK 20251210153512_drop_unused_gin_index.sql (11.73ms)13602026/08/27 09:32:21 INFO Created nix-cache-info in bucket bucket=bucket3213612026/08/27 09:32:21 OK 20241026095416_initial_model.sql (225.95ms)13622026/08/27 09:32:21 OK 20251210153512_drop_unused_gin_index.sql (15.26ms)13632026/08/27 09:32:21 OK 20251218171726_add_pins.sql (34.62ms)13642026/08/27 09:32:21 OK 20241026095416_initial_model.sql (199.1ms)13652026/08/27 09:32:21 OK 20251210153512_drop_unused_gin_index.sql (6.32ms)13662026/08/27 09:32:21 OK 20251218171726_add_pins.sql (27.41ms)13672026/08/27 09:32:21 OK 20260628120000_add_object_size_and_stats.sql (20.36ms)13682026/08/27 09:32:21 goose: successfully migrated database to version: 2026062812000013692026/08/27 09:32:21 OK 20260628120000_add_object_size_and_stats.sql (44.14ms)13702026/08/27 09:32:21 goose: successfully migrated database to version: 2026062812000013712026/08/27 09:32:21 OK 20251218171726_add_pins.sql (37.93ms)13722026/08/27 09:32:21 OK 1_commit_pending_closure.sql (6.58ms)13732026/08/27 09:32:21 OK 2_object_stats_trigger.sql (224.46µs)13742026/08/27 09:32:21 goose: up to current file version: 213752026/08/27 09:32:21 OK 1_commit_pending_closure.sql (8.13ms)13762026/08/27 09:32:21 OK 2_object_stats_trigger.sql (245.88µs)13772026/08/27 09:32:21 goose: up to current file version: 213782026/08/27 09:32:21 OK 20260628120000_add_object_size_and_stats.sql (41.39ms)13792026/08/27 09:32:21 goose: successfully migrated database to version: 2026062812000013802026/08/27 09:32:21 OK 1_commit_pending_closure.sql (6.9ms)13812026/08/27 09:32:21 OK 2_object_stats_trigger.sql (272.33µs)13822026/08/27 09:32:21 goose: up to current file version: 213832026/08/27 09:32:21 INFO Received uploads request method=POST path=/api/pending_closures1384--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (2.19s)1385=== CONT TestGCTaskStore_GetReturnsLatest1386--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1387=== CONT TestGCTaskStore_CompletedAllowsNewTask1388--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1389=== CONT TestGCTaskStore_GetEmpty1390--- PASS: TestGCTaskStore_GetEmpty (0.00s)1391=== CONT TestService_AuthMiddleware_MTLSBoundSubjects13922026/08/27 09:32:21 OK 20241026095416_initial_model.sql (269.93ms)13932026/08/27 09:32:21 OK 20251210153512_drop_unused_gin_index.sql (11.4ms)13942026/08/27 09:32:21 OK 20251218171726_add_pins.sql (54.72ms)13952026/08/27 09:32:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13962026/08/27 09:32:21 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1397--- PASS: TestCompleteMultipartUnregistered (2.26s)1398=== CONT TestService_AuthMiddleware_MTLSProxyHeader13992026/08/27 09:32:21 OK 20260628120000_add_object_size_and_stats.sql (48.68ms)14002026/08/27 09:32:21 goose: successfully migrated database to version: 2026062812000014012026/08/27 09:32:21 OK 1_commit_pending_closure.sql (7.29ms)14022026/08/27 09:32:21 OK 2_object_stats_trigger.sql (264.13µs)14032026/08/27 09:32:21 goose: up to current file version: 21404--- PASS: TestCacheStatsHandler (2.42s)1405=== CONT TestService_AuthMiddleware_OIDC14062026/08/27 09:32:21 INFO OIDC provider initialized name=test14072026/08/27 09:32:21 INFO Received uploads request method=POST path=/api/pending_closures14082026/08/27 09:32:21 INFO Received uploads request method=POST path=/api/pending_closures14092026/08/27 09:32:21 INFO Received uploads request method=POST path=/api/pending_closures14102026/08/27 09:32:21 INFO Received uploads request method=POST path=/api/pending_closures1411=== NAME TestClientCADerivations1412 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-22777-2593991874/TestClientCADerivations2243642535/001/store/l5ckn8man58wbyq6khqlyaw69sis324j-ca-test1413 client_ca_test.go:139: Found 1 dependencies (including self)14142026-08-27 09:32:22.111 UTC [23507] ERROR: relation "goose_db_version" does not exist at character 3614152026-08-27 09:32:22.111 UTC [23507] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14162026/08/27 09:32:22 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14172026/08/27 09:32:22 INFO Received uploads request method=POST path=/api/pending_closures14182026/08/27 09:32:22 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14192026/08/27 09:32:22 INFO Uploading l5ckn8man58wbyq6khqlyaw69sis324j-ca-test (144B)14202026/08/27 09:32:22 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"14212026/08/27 09:32:22 WARN Failed to register uploaded object key=log/1i6b3flnjqnqz2j3n9nrdidszsvbgd06-ca-test.drv error="server returned 404: 404 page not found\n"14222026/08/27 09:32:22 WARN Failed to register uploaded object key=l5ckn8man58wbyq6khqlyaw69sis324j.ls error="server returned 404: 404 page not found\n"14232026/08/27 09:32:22 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14242026/08/27 09:32:22 INFO Signed narinfos id=1 count=114252026/08/27 09:32:22 INFO Uploading 1 narinfos14262026/08/27 09:32:22 WARN Failed to register uploaded object key=l5ckn8man58wbyq6khqlyaw69sis324j.narinfo error="server returned 404: 404 page not found\n"14272026/08/27 09:32:22 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14282026/08/27 09:32:22 INFO Completed upload id=114292026/08/27 09:32:22 INFO Upload complete. (315ms)1430 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-22777-2593991874/TestClientCADerivations2243642535/001/store/l5ckn8man58wbyq6khqlyaw69sis324j-ca-test1431 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1432 Compression: zstd1433 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1434 NarSize: 1441435 References: 1436 Deriver: /nix/var/nix/builds/nix-22777-2593991874/TestClientCADerivations2243642535/001/store/1i6b3flnjqnqz2j3n9nrdidszsvbgd06-ca-test.drv1437 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1438 client_ca_test.go:185: Checking for realisation files in S3...1439 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1440 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache14412026/08/27 09:32:22 OK 20241026095416_initial_model.sql (229.11ms)14422026/08/27 09:32:22 OK 20251210153512_drop_unused_gin_index.sql (19.73ms)14432026/08/27 09:32:22 OK 20251218171726_add_pins.sql (25.82ms)14442026/08/27 09:32:22 OK 20260628120000_add_object_size_and_stats.sql (42.49ms)14452026/08/27 09:32:22 goose: successfully migrated database to version: 202606281200001446 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket32?endpoint=http://localhost:50915®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-22777-2593991874/TestClientCADerivations2243642535/001/store'1447 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 114482026/08/27 09:32:22 OK 1_commit_pending_closure.sql (8.11ms)14492026/08/27 09:32:22 OK 2_object_stats_trigger.sql (251.83µs)14502026/08/27 09:32:22 goose: up to current file version: 21451--- PASS: TestClientCADerivations (3.62s)1452=== CONT TestServerTLSConfig/no_client_CA1453=== CONT TestServerTLSConfig/not_a_PEM_file1454=== CONT TestServerTLSConfig/missing_CA_file1455--- PASS: TestServerTLSConfig (0.00s)1456 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1457 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.01s)1458 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1459=== CONT TestPresignedUploadRegisteredBeforeCommit14602026/08/27 09:32:22 INFO Received uploads request method=POST path=/api/pending_closures14612026-08-27 09:32:22.925 UTC [23517] ERROR: relation "goose_db_version" does not exist at character 3614622026-08-27 09:32:22.925 UTC [23517] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14632026/08/27 09:32:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14642026/08/27 09:32:23 OK 20241026095416_initial_model.sql (258.68ms)14652026/08/27 09:32:23 OK 20251210153512_drop_unused_gin_index.sql (20.08ms)14662026/08/27 09:32:23 OK 20251218171726_add_pins.sql (32.82ms)14672026/08/27 09:32:23 OK 20260628120000_add_object_size_and_stats.sql (55.24ms)14682026/08/27 09:32:23 goose: successfully migrated database to version: 2026062812000014692026/08/27 09:32:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14702026/08/27 09:32:23 OK 1_commit_pending_closure.sql (7.54ms)14712026/08/27 09:32:23 OK 2_object_stats_trigger.sql (229.54µs)14722026/08/27 09:32:23 goose: up to current file version: 214732026/08/27 09:32:23 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=OTdlOTEzYTUtYjdmMS00Y2QxLWFjNWMtODRlZWU5YjkwOTkyLjVjMWFjNWVhLTI2NjAtNDgyNy1iZGEwLWY2MDViNzA4NDUxNHgxNzg3ODIzMTQxNzkzMjM0MDAw parts=1014742026/08/27 09:32:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14752026/08/27 09:32:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14762026/08/27 09:32:23 INFO Completed upload id=114772026/08/27 09:32:23 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000014782026/08/27 09:32:23 INFO Received uploads request method=POST path=/api/pending_closures14792026/08/27 09:32:23 INFO Starting cleanup of old closures method=DELETE path=/api/closures14802026/08/27 09:32:23 INFO Aborted multipart uploads count=014812026/08/27 09:32:23 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=014822026/08/27 09:32:23 INFO Vacuumed table table=pending_closures14832026/08/27 09:32:23 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=OTdlOTEzYTUtYjdmMS00Y2QxLWFjNWMtODRlZWU5YjkwOTkyLmIzZWFlNzM2LWMwNzEtNDE2Zi04MmExLTcyMTlkOTI1YjQ0OXgxNzg3ODIzMTQxOTY0ODMzMDAw parts=1014842026/08/27 09:32:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14852026/08/27 09:32:23 INFO Completed upload id=114862026/08/27 09:32:23 INFO Received uploads request method=POST path=/api/pending_closures14872026/08/27 09:32:23 INFO Received uploads request method=POST path=/api/pending_closures14882026/08/27 09:32:23 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo14892026/08/27 09:32:23 WARN Found objects in DB but missing from S3, will re-upload count=11490--- PASS: TestService_verifyS3Integrity (4.20s)1491=== CONT TestIsValidUploadKey/narinfo1492=== CONT TestIsValidUploadKey/realisation_plus_in_output1493=== CONT TestIsValidUploadKey/unknown_type1494=== CONT TestIsValidUploadKey/empty_key1495=== CONT TestIsValidUploadKey/absolute1496=== CONT TestIsValidUploadKey/traversal_nar1497=== CONT TestIsValidUploadKey/traversal1498=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1499=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1500=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1501=== CONT TestIsValidUploadKey/index.html1502=== CONT TestIsValidUploadKey/nix-cache-info1503=== CONT TestIsValidUploadKey/build_log_home-manager_file1504=== CONT TestIsValidUploadKey/realisation1505=== CONT TestIsValidUploadKey/build_log_equals1506=== CONT TestIsValidUploadKey/build_log_question_mark1507=== CONT TestIsValidUploadKey/build_log_plus_in_name1508=== CONT TestIsValidUploadKey/nar_xz1509=== CONT TestIsValidUploadKey/build_log1510=== CONT TestIsValidUploadKey/nar_zst1511=== CONT TestIsValidUploadKey/listing1512=== CONT TestIsValidUploadKey/nar_plain1513--- PASS: TestIsValidUploadKey (0.00s)1514 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1515 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1516 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1517 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1518 --- PASS: TestIsValidUploadKey/absolute (0.00s)1519 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1520 --- PASS: TestIsValidUploadKey/traversal (0.00s)1521 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1522 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1523 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1524 --- PASS: TestIsValidUploadKey/index.html (0.00s)1525 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1526 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1527 --- PASS: TestIsValidUploadKey/realisation (0.00s)1528 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1529 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1530 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1531 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1532 --- PASS: TestIsValidUploadKey/build_log (0.00s)1533 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1534 --- PASS: TestIsValidUploadKey/listing (0.00s)1535 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1536=== CONT TestIsValidCachePath/narinfo1537=== CONT TestIsValidCachePath/index.html1538=== CONT TestIsValidCachePath/short_hash1539=== CONT TestIsValidCachePath/wrong_extension1540=== CONT TestIsValidCachePath/leading_slash1541=== CONT TestIsValidCachePath/empty1542=== CONT TestIsValidCachePath/random_path1543=== CONT TestIsValidCachePath/invalid_char_u1544=== CONT TestIsValidCachePath/invalid_char_e1545=== CONT TestIsValidCachePath/traversal_in_middle1546=== CONT TestIsValidCachePath/traversal_parent1547=== CONT TestIsValidCachePath/nar_uncompressed1548=== CONT TestIsValidCachePath/nix-cache-info1549=== CONT TestIsValidCachePath/realisation1550=== CONT TestIsValidCachePath/log1551=== CONT TestIsValidCachePath/ls1552=== CONT TestIsValidCachePath/nar_xz1553=== CONT TestIsValidCachePath/nar_bz21554=== CONT TestIsValidCachePath/nar_zst1555=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1556--- PASS: TestIsValidCachePath (0.00s)1557 --- PASS: TestIsValidCachePath/narinfo (0.00s)1558 --- PASS: TestIsValidCachePath/index.html (0.00s)1559 --- PASS: TestIsValidCachePath/short_hash (0.00s)1560 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1561 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1562 --- PASS: TestIsValidCachePath/empty (0.00s)1563 --- PASS: TestIsValidCachePath/random_path (0.00s)1564 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1565 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1566 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1567 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1568 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1569 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1570 --- PASS: TestIsValidCachePath/realisation (0.00s)1571 --- PASS: TestIsValidCachePath/log (0.00s)1572 --- PASS: TestIsValidCachePath/ls (0.00s)1573 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1574 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1575 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1576 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1577=== CONT TestParseSingleRange/none1578=== CONT TestParseSingleRange/open-ended1579=== CONT TestParseSingleRange/start_far_past_EOF1580=== CONT TestParseSingleRange/start_past_EOF1581=== CONT TestParseSingleRange/single_byte1582=== CONT TestParseSingleRange/suffix_exceeds_size1583=== CONT TestParseSingleRange/suffix1584=== CONT TestParseSingleRange/end_clamped_to_size1585=== CONT TestParseSingleRange/malformed_both_empty1586=== CONT TestParseSingleRange/closed1587=== CONT TestParseSingleRange/malformed_end_before_start1588=== CONT TestParseSingleRange/multi-range_ignored1589=== CONT TestParseSingleRange/malformed_no_dash1590=== CONT TestParseSingleRange/unknown_unit1591--- PASS: TestParseSingleRange (0.00s)1592 --- PASS: TestParseSingleRange/none (0.00s)1593 --- PASS: TestParseSingleRange/open-ended (0.00s)1594 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1595 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1596 --- PASS: TestParseSingleRange/single_byte (0.00s)1597 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1598 --- PASS: TestParseSingleRange/suffix (0.00s)1599 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1600 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1601 --- PASS: TestParseSingleRange/closed (0.00s)1602 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1603 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1604 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1605 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1606=== CONT TestCacheConfigHandler/full_config,_no_issuer1607=== CONT TestCacheConfigHandler/no_signing_keys1608=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1609=== CONT TestCacheConfigHandler/no_cache_url_configured1610--- PASS: TestCacheConfigHandler (0.00s)1611 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1612 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1613 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1614 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1615=== CONT TestClientErrorHandling/InvalidStorePath16162026/08/27 09:32:23 INFO Vacuumed table table=pending_objects16172026/08/27 09:32:23 INFO Received cleanup request method=DELETE path=/api/pending_closures16182026/08/27 09:32:23 INFO Aborted multipart uploads count=016192026/08/27 09:32:23 INFO Received uploads request method=POST path=/api/pending_closures16202026/08/27 09:32:23 INFO Vacuumed table table=multipart_uploads16212026/08/27 09:32:23 INFO Vacuumed table table=closures16222026/08/27 09:32:23 INFO Received cleanup request method=DELETE path=/api/pending_closures16232026/08/27 09:32:23 INFO Aborted multipart uploads count=116242026/08/27 09:32:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16252026-08-27 09:32:23.749 UTC [23517] ERROR: Closure does not exist: id=116262026-08-27 09:32:23.749 UTC [23517] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE16272026-08-27 09:32:23.749 UTC [23517] STATEMENT: -- name: CommitPendingClosure :exec1628 SELECT commit_pending_closure($1::bigint)1629 1630--- PASS: TestService_cleanupPendingClosuresHandler (3.23s)1631=== CONT TestClientErrorHandling/ServerNotAvailable16322026/08/27 09:32:23 INFO Vacuumed table table=objects16332026/08/27 09:32:23 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001634--- PASS: TestService_createPendingClosureHandler (4.57s)1635=== CONT TestClientErrorHandling/InvalidAuthToken16362026-08-27 09:32:23.901 UTC [23529] ERROR: relation "goose_db_version" does not exist at character 3616372026-08-27 09:32:23.901 UTC [23529] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16382026/08/27 09:32:24 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config16392026-08-27 09:32:24.057 UTC [23534] ERROR: relation "goose_db_version" does not exist at character 3616402026-08-27 09:32:24.057 UTC [23534] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16412026/08/27 09:32:24 OK 20241026095416_initial_model.sql (132.43ms)16422026/08/27 09:32:24 OK 20251210153512_drop_unused_gin_index.sql (14.03ms)16432026/08/27 09:32:24 OK 20251218171726_add_pins.sql (10.31ms)16442026/08/27 09:32:24 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=181.756482ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config16452026/08/27 09:32:24 OK 20260628120000_add_object_size_and_stats.sql (25.19ms)16462026/08/27 09:32:24 goose: successfully migrated database to version: 2026062812000016472026-08-27 09:32:24.146 UTC [23535] ERROR: relation "goose_db_version" does not exist at character 3616482026-08-27 09:32:24.146 UTC [23535] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16492026/08/27 09:32:24 OK 1_commit_pending_closure.sql (1.42ms)16502026/08/27 09:32:24 OK 2_object_stats_trigger.sql (209.71µs)16512026/08/27 09:32:24 goose: up to current file version: 216522026-08-27 09:32:24.243 UTC [23536] ERROR: relation "goose_db_version" does not exist at character 3616532026-08-27 09:32:24.243 UTC [23536] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16542026/08/27 09:32:24 OK 20241026095416_initial_model.sql (128.24ms)16552026/08/27 09:32:24 OK 20251210153512_drop_unused_gin_index.sql (17.93ms)16562026/08/27 09:32:24 OK 20251218171726_add_pins.sql (38.36ms)16572026/08/27 09:32:24 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1658--- PASS: TestService_ReadAuthMiddleware (3.12s)1659=== CONT TestProxyWriteTimeout/narinfo1660=== CONT TestProxyWriteTimeout/10_GiB_nar1661=== CONT TestProxyWriteTimeout/unknown_size1662=== CONT TestProxyWriteTimeout/1_GiB_nar1663--- PASS: TestProxyWriteTimeout (0.00s)1664 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1665 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1666 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1667 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1668=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16692026/08/27 09:32:24 INFO Received uploads request method=POST path=/16702026/08/27 09:32:24 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=381.002391ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config16712026/08/27 09:32:24 OK 20260628120000_add_object_size_and_stats.sql (39.61ms)16722026/08/27 09:32:24 goose: successfully migrated database to version: 2026062812000016732026/08/27 09:32:24 OK 1_commit_pending_closure.sql (1.62ms)16742026/08/27 09:32:24 OK 2_object_stats_trigger.sql (227.67µs)16752026/08/27 09:32:24 goose: up to current file version: 216762026/08/27 09:32:24 OK 20241026095416_initial_model.sql (191.27ms)16772026/08/27 09:32:24 OK 20251210153512_drop_unused_gin_index.sql (4.83ms)16782026/08/27 09:32:24 OK 20241026095416_initial_model.sql (134.1ms)16792026/08/27 09:32:24 OK 20251210153512_drop_unused_gin_index.sql (11.8ms)16802026/08/27 09:32:24 OK 20251218171726_add_pins.sql (30.25ms)16812026/08/27 09:32:24 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"16822026/08/27 09:32:24 WARN mTLS auth: bound subjects configured but subject DN unavailable16832026/08/27 09:32:24 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1684--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.96s)1685=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16862026/08/27 09:32:24 INFO Received request for more parts method=POST path=/16872026/08/27 09:32:24 OK 20251218171726_add_pins.sql (33.89ms)1688=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16892026/08/27 09:32:24 INFO Received complete multipart upload request method=POST path=/16902026/08/27 09:32:24 OK 20260628120000_add_object_size_and_stats.sql (38.81ms)16912026/08/27 09:32:24 goose: successfully migrated database to version: 2026062812000016922026/08/27 09:32:24 OK 1_commit_pending_closure.sql (1.24ms)16932026/08/27 09:32:24 OK 2_object_stats_trigger.sql (243.08µs)16942026/08/27 09:32:24 goose: up to current file version: 21695=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16962026/08/27 09:32:24 INFO Received uploads request method=POST path=/1697=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16982026/08/27 09:32:24 INFO Received complete multipart upload request method=POST path=/1699=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17002026/08/27 09:32:24 INFO Received request for more parts method=POST path=/1701=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17022026/08/27 09:32:24 INFO Received uploads request method=POST path=/1703--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1704 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1705 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1706 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1707 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)17082026/08/27 09:32:24 OK 20260628120000_add_object_size_and_stats.sql (49.93ms)17092026/08/27 09:32:24 goose: successfully migrated database to version: 2026062812000017102026/08/27 09:32:24 OK 1_commit_pending_closure.sql (9.88ms)17112026/08/27 09:32:24 OK 2_object_stats_trigger.sql (363.33µs)17122026/08/27 09:32:24 goose: up to current file version: 21713--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)1714 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1715 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1716 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.28s)1717--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (3.07s)17182026/08/27 09:32:24 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=753.549066ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1719=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1720=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1721=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1722=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1723=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1724=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1725=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1726=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1727=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1728=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected1729=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1730=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured17312026/08/27 09:32:24 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]17322026/08/27 09:32:24 INFO OIDC auth successful provider=test17332026/08/27 09:32:24 WARN Authentication failed token_preview=eyJhbGciOi...Q_Kk82rwjg 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]1734--- PASS: TestService_AuthMiddleware_OIDC (3.07s)1735 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1736 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1737 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1738 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)17392026-08-27 09:32:25.013 UTC [23557] ERROR: relation "goose_db_version" does not exist at character 3617402026-08-27 09:32:25.013 UTC [23557] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17412026/08/27 09:32:25 OK 20241026095416_initial_model.sql (241.39ms)17422026/08/27 09:32:25 OK 20251210153512_drop_unused_gin_index.sql (11.37ms)17432026/08/27 09:32:25 OK 20251218171726_add_pins.sql (24.38ms)17442026/08/27 09:32:25 OK 20260628120000_add_object_size_and_stats.sql (23.18ms)17452026/08/27 09:32:25 goose: successfully migrated database to version: 2026062812000017462026/08/27 09:32:25 OK 1_commit_pending_closure.sql (12.08ms)17472026/08/27 09:32:25 OK 2_object_stats_trigger.sql (1.22ms)17482026/08/27 09:32:25 goose: up to current file version: 217492026/08/27 09:32:25 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.54972583s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17502026/08/27 09:32:25 INFO Received uploads request method=POST path=/api/pending_closures17512026/08/27 09:32:25 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst17522026/08/27 09:32:25 INFO Received uploads request method=POST path=/api/pending_closures1753--- PASS: TestPresignedUploadRegisteredBeforeCommit (3.02s)17542026-08-27 09:32:25.802 UTC [23623] ERROR: relation "goose_db_version" does not exist at character 3617552026-08-27 09:32:25.802 UTC [23623] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17562026-08-27 09:32:25.813 UTC [23624] ERROR: relation "goose_db_version" does not exist at character 3617572026-08-27 09:32:25.813 UTC [23624] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17582026/08/27 09:32:25 OK 20241026095416_initial_model.sql (69.7ms)17592026/08/27 09:32:25 OK 20241026095416_initial_model.sql (70.11ms)17602026/08/27 09:32:25 OK 20251210153512_drop_unused_gin_index.sql (8.04ms)17612026/08/27 09:32:25 OK 20251210153512_drop_unused_gin_index.sql (8.07ms)17622026/08/27 09:32:25 OK 20251218171726_add_pins.sql (18.05ms)17632026/08/27 09:32:25 OK 20251218171726_add_pins.sql (17.49ms)17642026/08/27 09:32:25 OK 20260628120000_add_object_size_and_stats.sql (24.1ms)17652026/08/27 09:32:25 goose: successfully migrated database to version: 2026062812000017662026/08/27 09:32:25 OK 20260628120000_add_object_size_and_stats.sql (24.04ms)17672026/08/27 09:32:25 goose: successfully migrated database to version: 2026062812000017682026/08/27 09:32:25 OK 1_commit_pending_closure.sql (4.78ms)17692026/08/27 09:32:25 OK 2_object_stats_trigger.sql (1.11ms)17702026/08/27 09:32:25 goose: up to current file version: 217712026/08/27 09:32:25 OK 1_commit_pending_closure.sql (9.14ms)17722026/08/27 09:32:25 OK 2_object_stats_trigger.sql (1.2ms)17732026/08/27 09:32:25 goose: up to current file version: 217742026/08/27 09:32:26 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17752026/08/27 09:32:26 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"17762026/08/27 09:32:27 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"17772026/08/27 09:32:27 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_closures17782026/08/27 09:32:27 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=184.573033ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures17792026/08/27 09:32:27 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=418.26137ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures17802026/08/27 09:32:27 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=801.939143ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures17812026/08/27 09:32:27 WARN Rate limiter enabled after throttle name=s3-test rate=517822026/08/27 09:32:27 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1783=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1784 throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=101785 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001786--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (8.00s)17872026/08/27 09:32:28 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.585011356s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1788=== NAME TestOrphanedObjectsGCStressTest1789 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1790 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion1791--- PASS: TestClientErrorHandling (0.00s)1792 --- PASS: TestClientErrorHandling/InvalidStorePath (2.59s)1793 --- PASS: TestClientErrorHandling/InvalidAuthToken (2.74s)1794 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.56s)1795=== NAME TestOrphanedObjectsGCStressTest1796 orphaned_objects_gc_test.go:509: Stress test completed successfully:1797 orphaned_objects_gc_test.go:510: - Active objects preserved: 201798 orphaned_objects_gc_test.go:511: - Objects deleted: 2101799 orphaned_objects_gc_test.go:512: - Total GC'd: 2101800--- PASS: TestOrphanedObjectsGCStressTest (15.43s)1801PASS1802{"timestamp":"2026-08-27T09:32:33.71357Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:51166","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1836,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}18032026-08-27 09:32:37.731 UTC [22940] LOG: received smart shutdown request18042026-08-27 09:32:37.734 UTC [22940] LOG: background worker "logical replication launcher" (PID 22950) exited with exit code 118052026-08-27 09:32:37.776 UTC [22945] LOG: shutting down18062026-08-27 09:32:37.776 UTC [22945] LOG: checkpoint starting: shutdown immediate18072026/08/27 09:32:43 ERROR failed to kill rustfs error="no such process"18082026-08-27 09:32:44.366 UTC [22945] LOG: checkpoint complete: wrote 12916 buffers (78.8%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 13 recycled; write=4.637 s, sync=1.908 s, total=6.591 s; sync files=15167, longest=0.012 s, average=0.001 s; distance=212547 kB, estimate=212547 kB; lsn=0/E71BB90, redo lsn=0/E71BB9018092026-08-27 09:32:44.419 UTC [22940] LOG: database system is shut down18102026/08/27 09:32:47 ERROR failed to kill rustfs error="no such process"1811Running OIDC tests...1812=== RUN TestGlobMatch1813=== PAUSE TestGlobMatch1814=== RUN TestAudienceForIssuer1815=== PAUSE TestAudienceForIssuer1816=== RUN TestValidateToken_ValidToken1817=== PAUSE TestValidateToken_ValidToken1818=== RUN TestValidateToken_WrongAudience1819=== PAUSE TestValidateToken_WrongAudience1820=== RUN TestValidateToken_Expired1821=== PAUSE TestValidateToken_Expired1822=== RUN TestValidateToken_BoundClaimsMismatch1823=== PAUSE TestValidateToken_BoundClaimsMismatch1824=== RUN TestValidateToken_BoundSubjectMismatch1825=== PAUSE TestValidateToken_BoundSubjectMismatch1826=== RUN TestValidateToken_MultipleProviders1827=== PAUSE TestValidateToken_MultipleProviders1828=== RUN TestValidateToken_NoMatchingProvider1829=== PAUSE TestValidateToken_NoMatchingProvider1830=== CONT TestGlobMatch1831=== RUN TestGlobMatch/foo_foo1832=== PAUSE TestGlobMatch/foo_foo1833=== RUN TestGlobMatch/foo_bar1834=== PAUSE TestGlobMatch/foo_bar1835=== CONT TestValidateToken_BoundClaimsMismatch1836=== CONT TestValidateToken_WrongAudience1837=== RUN TestGlobMatch/*_1838=== PAUSE TestGlobMatch/*_1839=== RUN TestGlobMatch/*_anything1840=== PAUSE TestGlobMatch/*_anything1841=== RUN TestGlobMatch/foo*_foo1842=== CONT TestValidateToken_ValidToken1843=== CONT TestAudienceForIssuer1844--- PASS: TestAudienceForIssuer (0.00s)1845=== CONT TestValidateToken_MultipleProviders1846=== CONT TestValidateToken_NoMatchingProvider1847=== CONT TestValidateToken_BoundSubjectMismatch1848=== CONT TestValidateToken_Expired1849=== PAUSE TestGlobMatch/foo*_foo1850=== RUN TestGlobMatch/foo*_foobar1851=== PAUSE TestGlobMatch/foo*_foobar1852=== RUN TestGlobMatch/foo*_bar1853=== PAUSE TestGlobMatch/foo*_bar1854=== RUN TestGlobMatch/*bar_bar1855=== PAUSE TestGlobMatch/*bar_bar1856=== RUN TestGlobMatch/*bar_foobar1857=== PAUSE TestGlobMatch/*bar_foobar1858=== RUN TestGlobMatch/*bar_foo1859=== PAUSE TestGlobMatch/*bar_foo1860=== RUN TestGlobMatch/foo*bar_foobar1861=== PAUSE TestGlobMatch/foo*bar_foobar1862=== RUN TestGlobMatch/foo*bar_foo123bar1863=== PAUSE TestGlobMatch/foo*bar_foo123bar1864=== RUN TestGlobMatch/foo*bar_foobarbaz1865=== PAUSE TestGlobMatch/foo*bar_foobarbaz1866=== RUN TestGlobMatch/*/*_foo/bar1867=== PAUSE TestGlobMatch/*/*_foo/bar1868=== RUN TestGlobMatch/*/*_foo1869=== PAUSE TestGlobMatch/*/*_foo1870=== RUN TestGlobMatch/refs/heads/*_refs/heads/main1871=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main1872=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.01873=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.01874=== RUN TestGlobMatch/refs/*/main_refs/heads/main1875=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main1876=== RUN TestGlobMatch/fo?_foo1877=== PAUSE TestGlobMatch/fo?_foo1878=== RUN TestGlobMatch/fo?_fo1879=== PAUSE TestGlobMatch/fo?_fo1880=== RUN TestGlobMatch/fo?_fooo1881=== PAUSE TestGlobMatch/fo?_fooo1882=== RUN TestGlobMatch/?oo_foo1883=== PAUSE TestGlobMatch/?oo_foo1884=== RUN TestGlobMatch/?oo_boo1885=== PAUSE TestGlobMatch/?oo_boo1886=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1887=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1888=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1889=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1890=== CONT TestGlobMatch/foo_foo1891=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1892=== CONT TestGlobMatch/fo?_fooo1893=== CONT TestGlobMatch/fo?_fo1894=== CONT TestGlobMatch/fo?_foo1895=== CONT TestGlobMatch/refs/*/main_refs/heads/main1896=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.01897=== CONT TestGlobMatch/refs/heads/*_refs/heads/main1898=== CONT TestGlobMatch/*/*_foo1899=== CONT TestGlobMatch/*/*_foo/bar1900=== CONT TestGlobMatch/foo*bar_foobarbaz1901=== CONT TestGlobMatch/?oo_boo1902=== CONT TestGlobMatch/foo*bar_foobar1903=== CONT TestGlobMatch/*bar_foo1904=== CONT TestGlobMatch/*bar_foobar1905=== CONT TestGlobMatch/*bar_bar1906=== CONT TestGlobMatch/foo*_bar1907=== CONT TestGlobMatch/foo*_foobar1908=== CONT TestGlobMatch/?oo_foo1909=== CONT TestGlobMatch/foo*_foo1910=== CONT TestGlobMatch/*_anything1911=== CONT TestGlobMatch/foo_bar1912=== CONT TestGlobMatch/foo*bar_foo123bar1913=== CONT TestGlobMatch/*_1914=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1915--- PASS: TestGlobMatch (0.00s)1916 --- PASS: TestGlobMatch/foo_foo (0.00s)1917 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)1918 --- PASS: TestGlobMatch/fo?_fooo (0.00s)1919 --- PASS: TestGlobMatch/fo?_fo (0.00s)1920 --- PASS: TestGlobMatch/fo?_foo (0.00s)1921 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)1922 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)1923 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)1924 --- PASS: TestGlobMatch/*/*_foo (0.00s)1925 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)1926 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)1927 --- PASS: TestGlobMatch/?oo_boo (0.00s)1928 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)1929 --- PASS: TestGlobMatch/*bar_foo (0.00s)1930 --- PASS: TestGlobMatch/*bar_foobar (0.00s)1931 --- PASS: TestGlobMatch/*bar_bar (0.00s)1932 --- PASS: TestGlobMatch/foo*_bar (0.00s)1933 --- PASS: TestGlobMatch/foo*_foobar (0.00s)1934 --- PASS: TestGlobMatch/?oo_foo (0.00s)1935 --- PASS: TestGlobMatch/foo*_foo (0.00s)1936 --- PASS: TestGlobMatch/*_anything (0.00s)1937 --- PASS: TestGlobMatch/foo_bar (0.00s)1938 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)1939 --- PASS: TestGlobMatch/*_ (0.00s)1940 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)19412026/08/27 09:32:49 INFO OIDC provider initialized name=test19422026/08/27 09:32:49 INFO OIDC provider initialized name=test19432026/08/27 09:32:49 INFO OIDC provider initialized name=test19442026/08/27 09:32:49 INFO OIDC provider initialized name=provider119452026/08/27 09:32:49 INFO OIDC provider initialized name=test19462026/08/27 09:32:49 INFO OIDC provider initialized name=test19472026/08/27 09:32:49 INFO OIDC provider initialized name=provider119482026/08/27 09:32:49 INFO OIDC provider initialized name=provider21949--- PASS: TestValidateToken_Expired (0.00s)1950--- PASS: TestValidateToken_BoundClaimsMismatch (0.00s)1951--- PASS: TestValidateToken_WrongAudience (0.00s)1952--- PASS: TestValidateToken_BoundSubjectMismatch (0.00s)1953--- PASS: TestValidateToken_ValidToken (0.00s)1954--- PASS: TestValidateToken_NoMatchingProvider (0.00s)1955--- PASS: TestValidateToken_MultipleProviders (0.00s)1956PASS1957Running hook tests...1958=== RUN TestSendPathsEmpty1959=== PAUSE TestSendPathsEmpty1960=== RUN TestQueueEnqueueAndFetch1961=== PAUSE TestQueueEnqueueAndFetch1962=== RUN TestQueueDeduplication1963=== PAUSE TestQueueDeduplication1964=== RUN TestQueueRemove1965=== PAUSE TestQueueRemove1966=== RUN TestQueueFetchBatchLimit1967=== PAUSE TestQueueFetchBatchLimit1968=== RUN TestQueueRetryMovesToBack1969=== PAUSE TestQueueRetryMovesToBack1970=== RUN TestQueueFetchRemoveLifecycle1971=== PAUSE TestQueueFetchRemoveLifecycle1972=== RUN TestQueueConcurrentWriters1973=== PAUSE TestQueueConcurrentWriters1974=== RUN TestQueueRemoveLargeClosure1975=== PAUSE TestQueueRemoveLargeClosure1976=== RUN TestServerClientIntegration1977=== PAUSE TestServerClientIntegration1978=== RUN TestServerQueueError1979=== PAUSE TestServerQueueError1980=== RUN TestGetListenerSocketActivation1981 server_test.go:210: === RUN TestGetListenerSocketActivation1982 --- PASS: TestGetListenerSocketActivation (0.00s)1983 PASS1984 1985--- PASS: TestGetListenerSocketActivation (0.01s)1986=== RUN TestDrainIsolatesPoisonPath1987=== PAUSE TestDrainIsolatesPoisonPath1988=== RUN TestRunNotBlockedByPoisonHead1989=== PAUSE TestRunNotBlockedByPoisonHead1990=== RUN TestDrainGivesUpWhenServerDown1991=== PAUSE TestDrainGivesUpWhenServerDown1992=== RUN TestFailedPathPrunedByLaterClosure1993=== PAUSE TestFailedPathPrunedByLaterClosure1994=== RUN TestWorkerUploadsAndRemoves1995=== PAUSE TestWorkerUploadsAndRemoves1996=== RUN TestWorkerSkipsGCdPaths1997=== PAUSE TestWorkerSkipsGCdPaths1998=== RUN TestWorkerPrunesClosureDeps1999=== PAUSE TestWorkerPrunesClosureDeps2000=== CONT TestSendPathsEmpty2001=== CONT TestServerClientIntegration2002--- PASS: TestSendPathsEmpty (0.00s)2003=== CONT TestQueueRetryMovesToBack2004=== CONT TestQueueFetchBatchLimit2005=== CONT TestQueueRemove2006=== CONT TestQueueDeduplication2007=== CONT TestQueueEnqueueAndFetch2008=== CONT TestQueueFetchRemoveLifecycle2009=== CONT TestQueueRemoveLargeClosure2010=== CONT TestFailedPathPrunedByLaterClosure2011=== CONT TestWorkerPrunesClosureDeps2012--- PASS: TestServerClientIntegration (0.00s)2013=== CONT TestWorkerSkipsGCdPaths2014--- PASS: TestQueueFetchRemoveLifecycle (0.00s)2015=== CONT TestWorkerUploadsAndRemoves20162026/08/27 09:32:50 INFO Uploading batch count=120172026/08/27 09:32:50 ERROR Upload failed error="upload failed" count=12018--- PASS: TestQueueFetchBatchLimit (0.01s)2019=== CONT TestRunNotBlockedByPoisonHead20202026/08/27 09:32:50 INFO Upload queue status pending=220212026/08/27 09:32:50 INFO Upload queue status pending=220222026/08/27 09:32:50 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-22777-2593991874/TestWorkerSkipsGCdPaths1516293124/002/nonexistent2023--- PASS: TestQueueRetryMovesToBack (0.01s)2024=== CONT TestDrainGivesUpWhenServerDown20252026/08/27 09:32:50 INFO Uploading batch count=120262026/08/27 09:32:50 INFO Uploading batch count=120272026/08/27 09:32:50 INFO Uploading batch count=12028--- PASS: TestQueueEnqueueAndFetch (0.01s)2029=== CONT TestDrainIsolatesPoisonPath2030--- PASS: TestQueueRemove (0.01s)2031=== CONT TestServerQueueError20322026/08/27 09:32:50 INFO Uploading batch count=120332026/08/27 09:32:50 ERROR Failed to queue paths error="permission denied" count=12034--- PASS: TestQueueDeduplication (0.01s)2035=== CONT TestQueueConcurrentWriters2036--- PASS: TestServerQueueError (0.00s)2037--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)20382026/08/27 09:32:50 INFO Upload queue status pending=220392026/08/27 09:32:50 INFO Uploading batch count=220402026/08/27 09:32:50 INFO Uploading batch count=420412026/08/27 09:32:50 ERROR Upload failed error="upload failed" count=420422026/08/27 09:32:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-22777-2593991874/TestDrainIsolatesPoisonPath569023910/002/bbb20432026/08/27 09:32:50 INFO Upload queue status pending=320442026/08/27 09:32:50 INFO Uploading batch count=220452026/08/27 09:32:50 ERROR Upload failed error="upload failed" count=220462026/08/27 09:32:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-22777-2593991874/TestDrainGivesUpWhenServerDown4163093352/002/a20472026/08/27 09:32:50 INFO Uploading batch count=120482026/08/27 09:32:50 ERROR Upload failed error="upload failed" count=120492026/08/27 09:32:50 INFO Uploading batch count=120502026/08/27 09:32:50 ERROR Upload failed error="upload failed" count=120512026/08/27 09:32:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-22777-2593991874/TestDrainGivesUpWhenServerDown4163093352/002/b20522026/08/27 09:32:50 INFO Uploading batch count=120532026/08/27 09:32:50 ERROR Upload failed error="upload failed" count=120542026/08/27 09:32:50 INFO Uploading batch count=220552026/08/27 09:32:50 ERROR Upload failed error="upload failed" count=220562026/08/27 09:32:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-22777-2593991874/TestDrainGivesUpWhenServerDown4163093352/002/c20572026/08/27 09:32:50 INFO Uploading batch count=120582026/08/27 09:32:50 ERROR Upload failed error="upload failed" count=120592026/08/27 09:32:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-22777-2593991874/TestDrainGivesUpWhenServerDown4163093352/002/d20602026/08/27 09:32:50 ERROR Drain finished with paths left in queue remaining=120612026/08/27 09:32:50 INFO Uploading batch count=220622026/08/27 09:32:50 ERROR Upload failed error="upload failed" count=220632026/08/27 09:32:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-22777-2593991874/TestDrainGivesUpWhenServerDown4163093352/002/e20642026/08/27 09:32:50 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-22777-2593991874/TestDrainGivesUpWhenServerDown4163093352/002/f20652026/08/27 09:32:50 ERROR Drain finished with paths left in queue remaining=102066--- PASS: TestDrainIsolatesPoisonPath (0.00s)2067--- PASS: TestDrainGivesUpWhenServerDown (0.00s)2068--- PASS: TestWorkerSkipsGCdPaths (0.03s)2069--- PASS: TestWorkerPrunesClosureDeps (0.03s)2070--- PASS: TestWorkerUploadsAndRemoves (0.02s)2071--- PASS: TestQueueRemoveLargeClosure (0.04s)2072--- PASS: TestQueueConcurrentWriters (0.14s)20732026/08/27 09:32:51 INFO Uploading batch count=120742026/08/27 09:32:51 INFO Uploading batch count=120752026/08/27 09:32:51 INFO Uploading batch count=120762026/08/27 09:32:51 ERROR Upload failed error="upload failed" count=120772026/08/27 09:32:51 INFO Uploading batch count=120782026/08/27 09:32:51 ERROR Upload failed error="upload failed" count=120792026/08/27 09:32:51 INFO Uploading batch count=120802026/08/27 09:32:51 ERROR Upload failed error="upload failed" count=120812026/08/27 09:32:51 INFO Uploading batch count=120822026/08/27 09:32:51 ERROR Upload failed error="upload failed" count=120832026/08/27 09:32:51 ERROR Drain finished with paths left in queue remaining=12084--- PASS: TestRunNotBlockedByPoisonHead (1.02s)2085PASS