niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #138
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestCaseHackSuffix6=== PAUSE TestCaseHackSuffix7=== RUN TestFilterOversizedClosures8=== PAUSE TestFilterOversizedClosures9=== RUN TestPartSizeForNAR10=== PAUSE TestPartSizeForNAR11=== RUN TestUploadMultipart_SupersededByPeer12=== PAUSE TestUploadMultipart_SupersededByPeer13=== RUN TestDumpPathMatchesNix14=== PAUSE TestDumpPathMatchesNix15=== RUN TestDumpPathSingleFile16=== PAUSE TestDumpPathSingleFile17=== RUN TestDumpPathWriterError18=== PAUSE TestDumpPathWriterError19=== RUN TestEncodeNixBase3220=== PAUSE TestEncodeNixBase3221=== RUN TestEncodeNixBase32WithRealHash22=== PAUSE TestEncodeNixBase32WithRealHash23=== RUN TestConvertHashToNix3224=== PAUSE TestConvertHashToNix3225=== RUN TestGetStorePathHash26=== PAUSE TestGetStorePathHash27=== RUN TestPathInfoHashCompatibility28=== PAUSE TestPathInfoHashCompatibility29=== RUN TestParsePathInfoJSON30=== PAUSE TestParsePathInfoJSON31=== RUN TestParsePathInfoJSONMultiplePaths32=== PAUSE TestParsePathInfoJSONMultiplePaths33=== RUN TestPathInfoCACompatibility34=== PAUSE TestPathInfoCACompatibility35=== RUN TestRateLimiterFeedback36=== PAUSE TestRateLimiterFeedback37=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess38=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess39=== RUN TestResolveStorePath40=== PAUSE TestResolveStorePath41=== RUN TestDoWithRetry_BodyReplayedViaGetBody42=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody43=== RUN TestShellSplit44=== PAUSE TestShellSplit45=== RUN TestShellSplitErrors46=== PAUSE TestShellSplitErrors47=== RUN TestSetClientTLS48=== PAUSE TestSetClientTLS49=== RUN TestSetClientTLSDoesNotMutateDefaultTransport50=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport51=== RUN TestSetClientTLSErrors52=== PAUSE TestSetClientTLSErrors53=== RUN TestStaticToken54=== PAUSE TestStaticToken55=== RUN TestFileTokenReadsAndCaches56=== PAUSE TestFileTokenReadsAndCaches57=== RUN TestFileTokenMissing58=== PAUSE TestFileTokenMissing59=== RUN TestFileTokenEmpty60=== PAUSE TestFileTokenEmpty61=== RUN TestScriptTokenNoExpiryRerunsEveryCall62=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall63=== RUN TestScriptTokenCachesUntilRefresh64=== PAUSE TestScriptTokenCachesUntilRefresh65=== RUN TestScriptTokenEmptyToken66=== PAUSE TestScriptTokenEmptyToken67=== RUN TestScriptTokenBadJSON68=== PAUSE TestScriptTokenBadJSON69=== RUN TestScriptTokenScriptFails70=== PAUSE TestScriptTokenScriptFails71=== RUN TestScriptTokenEmptyCommand72=== PAUSE TestScriptTokenEmptyCommand73=== CONT TestDoServerRequestAttachesToken74=== CONT TestResolveStorePath75=== CONT TestFileTokenMissing76=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess77=== CONT TestPathInfoHashCompatibility78=== CONT TestParsePathInfoJSON79=== CONT TestRateLimiterFeedback80=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)81=== CONT TestSetClientTLSErrors82=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)83=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon84=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon85=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI86=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI87=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha51288=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha51289=== CONT TestPathInfoCACompatibility90=== RUN TestPathInfoCACompatibility/null_ca_field91=== PAUSE TestPathInfoCACompatibility/null_ca_field92=== RUN TestPathInfoCACompatibility/old_string_format_-_text93=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text94=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive95=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive96=== RUN TestPathInfoCACompatibility/new_structured_format_-_text97=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text98=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method99=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method100=== CONT TestConvertHashToNix32101=== RUN TestConvertHashToNix32/SRI_format_to_Nix32102=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32103=== RUN TestConvertHashToNix32/already_Nix32_format104=== PAUSE TestConvertHashToNix32/already_Nix32_format105=== RUN TestConvertHashToNix32/invalid_format106=== PAUSE TestConvertHashToNix32/invalid_format107=== CONT TestScriptTokenEmptyCommand108=== CONT TestScriptTokenBadJSON109=== CONT TestScriptTokenNoExpiryRerunsEveryCall110=== CONT TestScriptTokenCachesUntilRefresh111=== CONT TestScriptTokenEmptyToken1122026/08/27 09:15:45 WARN Rate limiter enabled after throttle name=server-test rate=5113--- PASS: TestFileTokenMissing (0.00s)114--- PASS: TestScriptTokenEmptyCommand (0.00s)115--- PASS: TestResolveStorePath (0.00s)116=== CONT TestEncodeNixBase32117=== CONT TestDumpPathWriterError118=== RUN TestEncodeNixBase32/test_string_hash119=== PAUSE TestEncodeNixBase32/test_string_hash120=== RUN TestEncodeNixBase32/empty_input121=== PAUSE TestEncodeNixBase32/empty_input122=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)123=== CONT TestGetStorePathHash124=== CONT TestDumpPathSingleFile125=== RUN TestParsePathInfoJSON/Nix_format126=== CONT TestFilterOversizedClosures127=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon128=== PAUSE TestParsePathInfoJSON/Nix_format129=== RUN TestFilterOversizedClosures/no_limit_keeps_everything130=== CONT TestPartSizeForNAR131=== RUN TestPartSizeForNAR/zero_stays_at_minimum132=== CONT TestCaseHackSuffix133=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum134=== RUN TestPartSizeForNAR/small_stays_at_minimum135=== CONT TestParsePathInfoJSONMultiplePaths136=== PAUSE TestPartSizeForNAR/small_stays_at_minimum137=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum138=== CONT TestFileTokenReadsAndCaches139=== CONT TestStaticToken140=== CONT TestScriptTokenScriptFails141=== CONT TestEncodeNixBase32WithRealHash142=== CONT TestDumpPathMatchesNix143=== RUN TestGetStorePathHash/valid_store_path144=== RUN TestRateLimiterFeedback/429_enables_limiter145--- PASS: TestScriptTokenBadJSON (0.00s)146=== CONT TestPathInfoCACompatibility/null_ca_field147--- PASS: TestScriptTokenEmptyToken (0.00s)148--- PASS: TestStaticToken (0.00s)149=== CONT TestUploadMultipart_SupersededByPeer150=== CONT TestConvertHashToNix32/SRI_format_to_Nix32151=== RUN TestParsePathInfoJSON/Lix_format152=== CONT TestFileTokenEmpty153=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything154=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths155=== CONT TestPathInfoCACompatibility/old_string_format_-_text156=== CONT TestSetClientTLSDoesNotMutateDefaultTransport157=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum158=== CONT TestShellSplitErrors159=== CONT TestSetClientTLS160=== PAUSE TestGetStorePathHash/valid_store_path161=== RUN TestGetStorePathHash/basename_without_hyphen_should_error162=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error163=== CONT TestDoWithRetry_BodyReplayedViaGetBody164--- PASS: TestEncodeNixBase32WithRealHash (0.00s)165=== CONT TestShellSplit166--- PASS: TestDoServerRequestAttachesToken (0.01s)167=== CONT TestConvertHashToNix32/already_Nix32_format168=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512169=== CONT TestPathInfoCACompatibility/new_structured_format_-_text170=== CONT TestEncodeNixBase32/test_string_hash171=== CONT TestEncodeNixBase32/empty_input172=== PAUSE TestParsePathInfoJSON/Lix_format173=== RUN TestParsePathInfoJSON/empty_input174=== PAUSE TestRateLimiterFeedback/429_enables_limiter175=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive176=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths177=== RUN TestUploadMultipart_SupersededByPeer/exists178=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped179=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts180=== RUN TestSetClientTLSErrors/missing_cert_file181=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error182=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths183=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method184=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI1852026/08/27 09:15:45 WARN Rate limiter enabled after throttle name=server-test rate=5186=== CONT TestConvertHashToNix32/invalid_format1872026/08/27 09:15:45 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:42529188--- PASS: TestShellSplitErrors (0.00s)189=== PAUSE TestParsePathInfoJSON/empty_input190=== RUN TestParsePathInfoJSON/whitespace_only191=== PAUSE TestParsePathInfoJSON/whitespace_only192=== RUN TestParsePathInfoJSON/invalid_JSON1932026/08/27 09:15:45 WARN Rate limiter backed off name=server-test rate=5194=== PAUSE TestParsePathInfoJSON/invalid_JSON1952026/08/27 09:15:45 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:42529196=== CONT TestParsePathInfoJSON/Nix_format197=== RUN TestRateLimiterFeedback/503_enables_limiter198=== CONT TestParsePathInfoJSON/whitespace_only199=== PAUSE TestRateLimiterFeedback/503_enables_limiter200=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter201=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error202=== PAUSE TestSetClientTLSErrors/missing_cert_file203=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts204=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped205=== RUN TestFilterOversizedClosures/all_closures_skipped206=== PAUSE TestUploadMultipart_SupersededByPeer/exists207=== RUN TestUploadMultipart_SupersededByPeer/missing208=== PAUSE TestUploadMultipart_SupersededByPeer/missing209=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths210=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths211--- PASS: TestScriptTokenScriptFails (0.00s)212=== CONT TestParsePathInfoJSON/invalid_JSON213=== CONT TestParsePathInfoJSON/Lix_format214=== CONT TestParsePathInfoJSON/empty_input215=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter216=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error217=== RUN TestSetClientTLSErrors/missing_key_file218=== RUN TestSetClientTLS/rejects_connection_without_client_cert219=== RUN TestPartSizeForNAR/1_TiB220=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error221=== PAUSE TestFilterOversizedClosures/all_closures_skipped222=== CONT TestFilterOversizedClosures/no_limit_keeps_everything223=== CONT TestUploadMultipart_SupersededByPeer/exists224=== CONT TestFilterOversizedClosures/all_closures_skipped2252026/08/27 09:15:45 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=50226=== CONT TestUploadMultipart_SupersededByPeer/missing227=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths228--- PASS: TestFileTokenReadsAndCaches (0.00s)229--- PASS: TestFileTokenEmpty (0.00s)230--- PASS: TestShellSplit (0.00s)231=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter232=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter233=== PAUSE TestSetClientTLSErrors/missing_key_file234=== CONT TestRateLimiterFeedback/503_enables_limiter235=== PAUSE TestPartSizeForNAR/1_TiB236=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert237=== CONT TestGetStorePathHash/valid_store_path238=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error239=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error240=== CONT TestGetStorePathHash/basename_without_hyphen_should_error241=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped242=== RUN TestPartSizeForNAR/5_TiB_S3_max_object243=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object2442026/08/27 09:15:45 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=2000245=== RUN TestPartSizeForNAR/capped_at_5_GiB246=== PAUSE TestPartSizeForNAR/capped_at_5_GiB247=== CONT TestPartSizeForNAR/zero_stays_at_minimum248=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts249=== CONT TestPartSizeForNAR/1_TiB250--- PASS: TestEncodeNixBase32 (0.00s)251 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)252 --- PASS: TestEncodeNixBase32/empty_input (0.00s)253--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)254--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)255=== CONT TestPartSizeForNAR/capped_at_5_GiB256=== CONT TestRateLimiterFeedback/429_enables_limiter257=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter258=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter259=== RUN TestSetClientTLSErrors/missing_ca_file260=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA261=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum262=== CONT TestPartSizeForNAR/small_stays_at_minimum263=== CONT TestPartSizeForNAR/5_TiB_S3_max_object264--- PASS: TestScriptTokenCachesUntilRefresh (0.02s)265--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.02s)2662026/08/27 09:15:45 WARN Rate limiter enabled after throttle name=server-test rate=52672026/08/27 09:15:45 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:34405268=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA269=== RUN TestSetClientTLS/preserves_debug_logging_transport270=== PAUSE TestSetClientTLS/preserves_debug_logging_transport271=== CONT TestSetClientTLS/rejects_connection_without_client_cert272=== CONT TestSetClientTLS/preserves_debug_logging_transport2732026/08/27 09:15:45 WARN Rate limiter backed off name=server-test rate=5274=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA275=== PAUSE TestSetClientTLSErrors/missing_ca_file276=== RUN TestSetClientTLSErrors/invalid_ca_file277=== PAUSE TestSetClientTLSErrors/invalid_ca_file278--- PASS: TestPathInfoHashCompatibility (0.00s)279 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)280 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)281 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)282 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)2832026/08/27 09:15:45 WARN Rate limiter enabled after throttle name=server-test rate=5284--- PASS: TestConvertHashToNix32 (0.00s)285 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)286 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)287 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)2882026/08/27 09:15:45 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:43687289=== CONT TestSetClientTLSErrors/missing_cert_file290=== CONT TestSetClientTLSErrors/invalid_ca_file291=== CONT TestSetClientTLSErrors/missing_ca_file2922026/08/27 09:15:45 WARN Rate limiter backed off name=server-test rate=5293=== CONT TestSetClientTLSErrors/missing_key_file294--- PASS: TestParsePathInfoJSON (0.01s)295 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)296 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)297 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)298 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)299 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)300--- PASS: TestPathInfoCACompatibility (0.00s)301 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)302 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)303 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)304 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)305 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)306--- PASS: TestPartSizeForNAR (0.01s)307 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)308 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)309 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)310 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)311 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)312 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)313 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)314--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)315 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)316 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)317--- PASS: TestGetStorePathHash (0.02s)318 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)319 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)320 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)321 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)322--- PASS: TestFilterOversizedClosures (0.01s)323 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)324 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)325 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)326--- PASS: TestRateLimiterFeedback (0.02s)327 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)328 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)329 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)330 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)331--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)332 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)333 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)334--- PASS: TestSetClientTLSErrors (0.02s)335 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)336 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)337 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)338 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)3392026/08/27 09:15:45 http: TLS handshake error from 127.0.0.1:52870: remote error: tls: bad certificate340--- PASS: TestSetClientTLS (0.01s)341 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)342 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)343 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)344--- PASS: TestDumpPathSingleFile (0.03s)345--- PASS: TestCaseHackSuffix (0.03s)346--- PASS: TestDumpPathWriterError (0.04s)347--- PASS: TestDumpPathMatchesNix (0.07s)348--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)349PASS350Running server tests...351The files belonging to this database system will be owned by user "nixbld".352This user must also own the server process.353354The database cluster will be initialized with locale "C".355The default database encoding has accordingly been set to "SQL_ASCII".356The default text search configuration will be set to "english".357358Data page checksums are enabled.359360creating directory /build/postgres284741243/data ... ok361creating subdirectories ... ok362selecting dynamic shared memory implementation ... posix363selecting default "max_connections" ... 100364selecting default "shared_buffers" ... 128MB365selecting default time zone ... UTC366creating configuration files ... ok367running bootstrap script ... ok368performing post-bootstrap initialization ... ok369syncing data to disk ... ok370371initdb: warning: enabling "trust" authentication for local connections372initdb: 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.373374Success. You can now start the database server using:375376 pg_ctl -D /build/postgres284741243/data -l logfile start377378/build/postgres284741243:5432 - no response3792026-08-27 09:15:47.458 UTC [112] LOG: starting PostgreSQL 18.4 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit3802026-08-27 09:15:47.458 UTC [112] LOG: listening on Unix socket "/build/postgres284741243/.s.PGSQL.5432"3812026-08-27 09:15:47.463 UTC [119] LOG: database system was shut down at 2026-08-27 09:15:47 UTC3822026-08-27 09:15:47.466 UTC [112] LOG: database system is ready to accept connections383/build/postgres284741243:5432 - accepting connections384=== RUN TestService_AuthMiddleware385=== PAUSE TestService_AuthMiddleware386=== RUN TestService_AuthMiddleware_MTLSProxyHeader387=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader388=== RUN TestService_AuthMiddleware_MTLSBoundSubjects389=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects390=== RUN TestService_ReadAuthMiddleware391=== PAUSE TestService_ReadAuthMiddleware392=== RUN TestService_AuthMiddleware_OIDC393=== PAUSE TestService_AuthMiddleware_OIDC394=== RUN TestCacheConfigHandler395=== PAUSE TestCacheConfigHandler396=== RUN TestCacheStatsHandler397=== PAUSE TestCacheStatsHandler398=== RUN TestClientCADerivations399=== PAUSE TestClientCADerivations400=== RUN TestClientErrorHandling401=== PAUSE TestClientErrorHandling402=== RUN TestClientIntegration403=== PAUSE TestClientIntegration404=== RUN TestClientMultipleUploads405=== PAUSE TestClientMultipleUploads406=== RUN TestClientWithDependencies407=== PAUSE TestClientWithDependencies408=== RUN TestPinProtectsFromGC409=== PAUSE TestPinProtectsFromGC410=== RUN TestGCAdvisoryLockBlocksConcurrentRun4112026-08-27 09:15:47.938 UTC [907] ERROR: relation "goose_db_version" does not exist at character 364122026-08-27 09:15:47.938 UTC [907] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4132026/08/27 09:15:47 OK 20241026095416_initial_model.sql (6.09ms)4142026/08/27 09:15:47 OK 20251210153512_drop_unused_gin_index.sql (1.6ms)4152026/08/27 09:15:47 OK 20251218171726_add_pins.sql (2.01ms)4162026/08/27 09:15:47 OK 20260628120000_add_object_size_and_stats.sql (1.95ms)4172026/08/27 09:15:47 goose: successfully migrated database to version: 202606281200004182026/08/27 09:15:47 OK 1_commit_pending_closure.sql (1.27ms)4192026/08/27 09:15:47 OK 2_object_stats_trigger.sql (561.34µs)4202026/08/27 09:15:47 goose: up to current file version: 2421--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.12s)422=== RUN TestGCBugBareHashReferences423=== PAUSE TestGCBugBareHashReferences424=== RUN TestGCMetrics425=== PAUSE TestGCMetrics426=== RUN TestGCTaskStore_StartNew427=== PAUSE TestGCTaskStore_StartNew428=== RUN TestGCTaskStore_DeduplicateSameParams429=== PAUSE TestGCTaskStore_DeduplicateSameParams430=== RUN TestGCTaskStore_ConflictDifferentParams431=== PAUSE TestGCTaskStore_ConflictDifferentParams432=== RUN TestGCTaskStore_GetEmpty433=== PAUSE TestGCTaskStore_GetEmpty434=== RUN TestGCTaskStore_GetReturnsLatest435=== PAUSE TestGCTaskStore_GetReturnsLatest436=== RUN TestGCTaskStore_CompletedAllowsNewTask437=== PAUSE TestGCTaskStore_CompletedAllowsNewTask438=== RUN TestGCTaskStore_PhaseUpdates439=== PAUSE TestGCTaskStore_PhaseUpdates440=== RUN TestGCTaskStore_Fail441=== PAUSE TestGCTaskStore_Fail442=== RUN TestGracefulShutdownDrainsInflight443=== PAUSE TestGracefulShutdownDrainsInflight444=== RUN TestService_healthCheckHandler445=== PAUSE TestService_healthCheckHandler446=== RUN TestGenerateLandingPage447=== PAUSE TestGenerateLandingPage448=== RUN TestCacheConfigHandlerMaxNarSize449=== PAUSE TestCacheConfigHandlerMaxNarSize450=== RUN TestCreatePendingClosureRejectsOversizedNAR451=== PAUSE TestCreatePendingClosureRejectsOversizedNAR452=== RUN TestNARDeduplicationMetadataUploadBug453=== PAUSE TestNARDeduplicationMetadataUploadBug454=== RUN TestMetricsInventory455=== PAUSE TestMetricsInventory456=== RUN TestService_NativeMTLS457=== PAUSE TestService_NativeMTLS458=== RUN TestServerTLSConfig459=== PAUSE TestServerTLSConfig460=== RUN TestMultipartCleanup461=== PAUSE TestMultipartCleanup462=== RUN TestObjectStatsTrigger463=== PAUSE TestObjectStatsTrigger464=== RUN TestOrphanedObjectsGC465=== PAUSE TestOrphanedObjectsGC466=== RUN TestOrphanedObjectsGCStressTest467=== PAUSE TestOrphanedObjectsGCStressTest468=== RUN TestResurrectedObjectNotDeleted469=== PAUSE TestResurrectedObjectNotDeleted470=== RUN TestParseSingleRange471=== PAUSE TestParseSingleRange472=== RUN TestIsValidCachePath473=== PAUSE TestIsValidCachePath474=== RUN TestReadProxyNarinfo475=== PAUSE TestReadProxyNarinfo476=== RUN TestReadProxyNarinfoAlreadyDecompressed477=== PAUSE TestReadProxyNarinfoAlreadyDecompressed478=== RUN TestReadProxyNarStreaming479=== PAUSE TestReadProxyNarStreaming480=== RUN TestReadProxy404481=== PAUSE TestReadProxy404482=== RUN TestReadProxyInvalidPath483=== PAUSE TestReadProxyInvalidPath484=== RUN TestReadProxyHead485=== PAUSE TestReadProxyHead486=== RUN TestReadProxyConditionalGet487=== PAUSE TestReadProxyConditionalGet488=== RUN TestReadProxyRootRedirectsToIndexHTML489=== PAUSE TestReadProxyRootRedirectsToIndexHTML490=== RUN TestReadProxyDisabled491=== PAUSE TestReadProxyDisabled492=== RUN TestReadProxyRangeRequest493=== PAUSE TestReadProxyRangeRequest494=== RUN TestRedundantMultipartUpload495=== PAUSE TestRedundantMultipartUpload496=== RUN TestCompleteMultipartUpload_ErrorButObjectExists497=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists498=== RUN TestCompletedNarNotReofferedAcrossClosures499=== PAUSE TestCompletedNarNotReofferedAcrossClosures500=== RUN TestPresignedUploadRegisteredBeforeCommit501=== PAUSE TestPresignedUploadRegisteredBeforeCommit502=== RUN TestService_Rustfstest503=== PAUSE TestService_Rustfstest504=== RUN TestParseSize505=== PAUSE TestParseSize506=== RUN TestSkippedUploadsHandler507=== PAUSE TestSkippedUploadsHandler508=== RUN TestSystemdListenerNotActivated509--- PASS: TestSystemdListenerNotActivated (0.00s)510=== RUN TestWatchdogBeatsWhenHealthy511--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)512=== RUN TestWatchdogSkipsWhenUnhealthy5132026/08/27 09:15:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5142026/08/27 09:15:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5152026/08/27 09:15:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5162026/08/27 09:15:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5172026/08/27 09:15:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5182026/08/27 09:15:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5192026/08/27 09:15:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5202026/08/27 09:15:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5212026/08/27 09:15:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5222026/08/27 09:15:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"523--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)524=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle525=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle526=== RUN TestProxyWriteTimeout527=== PAUSE TestProxyWriteTimeout528=== RUN TestIsValidUploadKey529=== PAUSE TestIsValidUploadKey530=== RUN TestUploadHandlersRejectInvalidKeys531=== PAUSE TestUploadHandlersRejectInvalidKeys532=== RUN TestUploadHandlersRejectOversizedBody533=== PAUSE TestUploadHandlersRejectOversizedBody534=== RUN TestService_cleanupPendingClosuresHandler535=== PAUSE TestService_cleanupPendingClosuresHandler536=== RUN TestService_createPendingClosureHandler537=== PAUSE TestService_createPendingClosureHandler538=== RUN TestService_verifyS3Integrity539=== PAUSE TestService_verifyS3Integrity540=== RUN TestCompleteMultipartUnregistered541=== PAUSE TestCompleteMultipartUnregistered542=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT543=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT544=== CONT TestService_AuthMiddleware545=== CONT TestCompleteMultipartUnregistered546=== CONT TestSkippedUploadsHandler547=== CONT TestService_NativeMTLS548=== CONT TestService_createPendingClosureHandler5492026/08/27 09:15:48 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000550=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT551=== CONT TestUploadHandlersRejectInvalidKeys552=== CONT TestIsValidUploadKey553=== CONT TestProxyWriteTimeout554=== RUN TestProxyWriteTimeout/narinfo555=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle556=== CONT TestService_verifyS3Integrity557=== CONT TestReadProxyInvalidPath558=== CONT TestParseSize559--- PASS: TestParseSize (0.00s)560=== CONT TestGCTaskStore_StartNew561--- PASS: TestGCTaskStore_StartNew (0.00s)562=== CONT TestMetricsInventory563=== CONT TestService_Rustfstest564=== CONT TestPresignedUploadRegisteredBeforeCommit565=== CONT TestCompletedNarNotReofferedAcrossClosures566=== CONT TestCompleteMultipartUpload_ErrorButObjectExists567=== CONT TestRedundantMultipartUpload568=== CONT TestReadProxyRangeRequest569=== CONT TestReadProxyDisabled570=== CONT TestReadProxyRootRedirectsToIndexHTML571--- PASS: TestSkippedUploadsHandler (0.01s)572=== CONT TestReadProxyConditionalGet573=== CONT TestReadProxyHead574=== CONT TestUploadHandlersRejectOversizedBody575=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info576=== RUN TestIsValidUploadKey/narinfo577=== PAUSE TestProxyWriteTimeout/narinfo578=== CONT TestNARDeduplicationMetadataUploadBug579=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info580=== RUN TestProxyWriteTimeout/1_GiB_nar581=== PAUSE TestProxyWriteTimeout/1_GiB_nar582=== PAUSE TestIsValidUploadKey/narinfo583=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal584=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal585=== RUN TestIsValidUploadKey/nar_zst586=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key587=== PAUSE TestIsValidUploadKey/nar_zst588=== RUN TestIsValidUploadKey/nar_xz589=== PAUSE TestIsValidUploadKey/nar_xz590=== RUN TestIsValidUploadKey/nar_plain591=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key592=== RUN TestProxyWriteTimeout/10_GiB_nar593=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key594=== PAUSE TestIsValidUploadKey/nar_plain595=== PAUSE TestProxyWriteTimeout/10_GiB_nar596=== RUN TestProxyWriteTimeout/unknown_size597=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key598=== RUN TestIsValidUploadKey/listing599=== CONT TestCreatePendingClosureRejectsOversizedNAR600=== PAUSE TestProxyWriteTimeout/unknown_size601=== PAUSE TestIsValidUploadKey/listing602=== CONT TestCacheConfigHandlerMaxNarSize6032026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures604=== RUN TestIsValidUploadKey/build_log605=== PAUSE TestIsValidUploadKey/build_log606=== RUN TestIsValidUploadKey/build_log_home-manager_file607=== CONT TestService_healthCheckHandler608--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)609--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)610=== PAUSE TestIsValidUploadKey/build_log_home-manager_file611=== RUN TestIsValidUploadKey/build_log_plus_in_name612=== PAUSE TestIsValidUploadKey/build_log_plus_in_name613=== RUN TestIsValidUploadKey/build_log_question_mark614=== CONT TestGenerateLandingPage615=== PAUSE TestIsValidUploadKey/build_log_question_mark616=== RUN TestIsValidUploadKey/build_log_equals617=== PAUSE TestIsValidUploadKey/build_log_equals618=== RUN TestIsValidUploadKey/realisation619=== PAUSE TestIsValidUploadKey/realisation620=== RUN TestIsValidUploadKey/realisation_plus_in_output621=== PAUSE TestIsValidUploadKey/realisation_plus_in_output622=== RUN TestIsValidUploadKey/nix-cache-info623=== PAUSE TestIsValidUploadKey/nix-cache-info624=== RUN TestIsValidUploadKey/index.html625=== PAUSE TestIsValidUploadKey/index.html626=== RUN TestIsValidUploadKey/narinfo_key,_nar_type627=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type628=== RUN TestIsValidUploadKey/nar_key,_narinfo_type629=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type630=== RUN TestIsValidUploadKey/listing_key,_narinfo_type631=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type632=== RUN TestIsValidUploadKey/traversal633=== PAUSE TestIsValidUploadKey/traversal634=== RUN TestIsValidUploadKey/traversal_nar635=== PAUSE TestIsValidUploadKey/traversal_nar636=== RUN TestIsValidUploadKey/absolute637=== PAUSE TestIsValidUploadKey/absolute638=== RUN TestIsValidUploadKey/empty_key639--- PASS: TestGenerateLandingPage (0.01s)640=== CONT TestGracefulShutdownDrainsInflight641=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure642=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure643=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart644=== PAUSE TestIsValidUploadKey/empty_key645=== RUN TestIsValidUploadKey/unknown_type646=== PAUSE TestIsValidUploadKey/unknown_type6472026-08-27 09:15:48.513 UTC [977] ERROR: relation "goose_db_version" does not exist at character 366482026-08-27 09:15:48.513 UTC [977] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC649=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart6502026/08/27 09:15:48 INFO Starting HTTP server address=127.0.0.1:43847651=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts652=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts653=== CONT TestGCTaskStore_PhaseUpdates654--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)655=== CONT TestGCTaskStore_Fail656--- PASS: TestGCTaskStore_Fail (0.00s)657=== CONT TestGCTaskStore_CompletedAllowsNewTask658--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)659=== CONT TestGCTaskStore_ConflictDifferentParams660--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)6612026/08/27 09:15:48 INFO Shutdown signal received, draining in-flight requests timeout=10s662=== CONT TestGCTaskStore_DeduplicateSameParams663--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)664=== CONT TestService_cleanupPendingClosuresHandler665=== CONT TestGCTaskStore_GetReturnsLatest666--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)667=== CONT TestClientErrorHandling668=== RUN TestClientErrorHandling/InvalidStorePath669=== PAUSE TestClientErrorHandling/InvalidStorePath670=== RUN TestClientErrorHandling/InvalidAuthToken671=== PAUSE TestClientErrorHandling/InvalidAuthToken672=== RUN TestClientErrorHandling/ServerNotAvailable673=== PAUSE TestClientErrorHandling/ServerNotAvailable674=== CONT TestGCMetrics6752026-08-27 09:15:48.521 UTC [978] ERROR: relation "goose_db_version" does not exist at character 366762026-08-27 09:15:48.521 UTC [978] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6772026-08-27 09:15:48.522 UTC [979] ERROR: relation "goose_db_version" does not exist at character 366782026-08-27 09:15:48.522 UTC [979] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6792026-08-27 09:15:48.523 UTC [983] ERROR: relation "goose_db_version" does not exist at character 366802026-08-27 09:15:48.523 UTC [983] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6812026-08-27 09:15:48.527 UTC [981] ERROR: relation "goose_db_version" does not exist at character 366822026-08-27 09:15:48.527 UTC [981] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC683--- PASS: TestGracefulShutdownDrainsInflight (0.07s)684=== CONT TestGCBugBareHashReferences6852026-08-27 09:15:48.636 UTC [988] ERROR: relation "goose_db_version" does not exist at character 366862026-08-27 09:15:48.636 UTC [988] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6872026-08-27 09:15:48.638 UTC [989] ERROR: relation "goose_db_version" does not exist at character 366882026-08-27 09:15:48.638 UTC [989] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6892026/08/27 09:15:48 OK 20241026095416_initial_model.sql (94.9ms)6902026/08/27 09:15:48 OK 20241026095416_initial_model.sql (101.4ms)6912026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (7.21ms)6922026-08-27 09:15:48.651 UTC [990] ERROR: relation "goose_db_version" does not exist at character 366932026-08-27 09:15:48.651 UTC [990] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6942026/08/27 09:15:48 OK 20241026095416_initial_model.sql (112.1ms)6952026/08/27 09:15:48 OK 20251218171726_add_pins.sql (20.65ms)6962026/08/27 09:15:48 OK 20241026095416_initial_model.sql (116.34ms)6972026/08/27 09:15:48 OK 20241026095416_initial_model.sql (117.7ms)6982026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (21.16ms)6992026/08/27 09:15:48 OK 20241026095416_initial_model.sql (26.51ms)7002026/08/27 09:15:48 OK 20241026095416_initial_model.sql (26.13ms)7012026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (11.15ms)7022026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (5.47ms)7032026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (5.55ms)7042026-08-27 09:15:48.678 UTC [992] ERROR: relation "goose_db_version" does not exist at character 367052026-08-27 09:15:48.678 UTC [992] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7062026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (3.25ms)7072026-08-27 09:15:48.679 UTC [991] ERROR: relation "goose_db_version" does not exist at character 367082026-08-27 09:15:48.679 UTC [991] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7092026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (3.36ms)7102026-08-27 09:15:48.682 UTC [993] ERROR: relation "goose_db_version" does not exist at character 367112026-08-27 09:15:48.682 UTC [993] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7122026/08/27 09:15:48 OK 20251218171726_add_pins.sql (10.76ms)7132026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (11.17ms)7142026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200007152026/08/27 09:15:48 OK 20251218171726_add_pins.sql (6.22ms)7162026/08/27 09:15:48 OK 20251218171726_add_pins.sql (7.04ms)7172026/08/27 09:15:48 OK 20251218171726_add_pins.sql (12.1ms)7182026/08/27 09:15:48 OK 20251218171726_add_pins.sql (12.3ms)7192026/08/27 09:15:48 OK 20251218171726_add_pins.sql (12.5ms)7202026/08/27 09:15:48 OK 1_commit_pending_closure.sql (6.82ms)7212026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (6.23ms)7222026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200007232026/08/27 09:15:48 OK 2_object_stats_trigger.sql (3.96ms)7242026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (11.27ms)7252026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200007262026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (6.33ms)7272026-08-27 09:15:48.694 UTC [994] ERROR: relation "goose_db_version" does not exist at character 367282026-08-27 09:15:48.694 UTC [994] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7292026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200007302026/08/27 09:15:48 goose: up to current file version: 27312026/08/27 09:15:48 OK 1_commit_pending_closure.sql (4.71ms)7322026/08/27 09:15:48 OK 20241026095416_initial_model.sql (19.14ms)7332026/08/27 09:15:48 OK 2_object_stats_trigger.sql (2.19ms)7342026/08/27 09:15:48 goose: up to current file version: 27352026/08/27 09:15:48 OK 1_commit_pending_closure.sql (3.87ms)7362026/08/27 09:15:48 OK 1_commit_pending_closure.sql (5.37ms)7372026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (9.91ms)7382026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200007392026/08/27 09:15:48 OK 2_object_stats_trigger.sql (2.11ms)7402026/08/27 09:15:48 goose: up to current file version: 27412026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (11.23ms)7422026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200007432026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (3.71ms)7442026-08-27 09:15:48.702 UTC [995] ERROR: relation "goose_db_version" does not exist at character 367452026-08-27 09:15:48.702 UTC [995] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7462026/08/27 09:15:48 OK 2_object_stats_trigger.sql (2.77ms)7472026/08/27 09:15:48 goose: up to current file version: 27482026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (13.2ms)7492026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200007502026/08/27 09:15:48 OK 1_commit_pending_closure.sql (3.78ms)7512026/08/27 09:15:48 OK 20241026095416_initial_model.sql (13.05ms)7522026-08-27 09:15:48.705 UTC [996] ERROR: relation "goose_db_version" does not exist at character 367532026-08-27 09:15:48.705 UTC [996] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7542026/08/27 09:15:48 OK 20241026095416_initial_model.sql (10.22ms)7552026/08/27 09:15:48 OK 2_object_stats_trigger.sql (2.03ms)7562026/08/27 09:15:48 goose: up to current file version: 27572026/08/27 09:15:48 OK 20251218171726_add_pins.sql (4.23ms)7582026/08/27 09:15:48 OK 20241026095416_initial_model.sql (15.01ms)7592026/08/27 09:15:48 OK 1_commit_pending_closure.sql (5.51ms)7602026/08/27 09:15:48 OK 1_commit_pending_closure.sql (4.5ms)7612026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (2.49ms)7622026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (2.93ms)7632026/08/27 09:15:48 OK 2_object_stats_trigger.sql (2.79ms)7642026/08/27 09:15:48 goose: up to current file version: 27652026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (3.19ms)7662026/08/27 09:15:48 OK 2_object_stats_trigger.sql (3.14ms)7672026/08/27 09:15:48 goose: up to current file version: 27682026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (5.41ms)7692026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200007702026/08/27 09:15:48 OK 20251218171726_add_pins.sql (3.97ms)7712026/08/27 09:15:48 OK 20251218171726_add_pins.sql (3.8ms)7722026/08/27 09:15:48 OK 20241026095416_initial_model.sql (9.56ms)7732026-08-27 09:15:48.713 UTC [997] ERROR: relation "goose_db_version" does not exist at character 367742026-08-27 09:15:48.713 UTC [997] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7752026/08/27 09:15:48 OK 20251218171726_add_pins.sql (3.96ms)7762026/08/27 09:15:48 OK 1_commit_pending_closure.sql (3.65ms)7772026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (2.52ms)7782026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (4.21ms)7792026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200007802026/08/27 09:15:48 OK 2_object_stats_trigger.sql (1.83ms)7812026/08/27 09:15:48 goose: up to current file version: 27822026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (5.37ms)7832026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200007842026/08/27 09:15:48 OK 1_commit_pending_closure.sql (2.54ms)7852026-08-27 09:15:48.719 UTC [999] ERROR: relation "goose_db_version" does not exist at character 367862026-08-27 09:15:48.719 UTC [999] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7872026-08-27 09:15:48.719 UTC [1000] ERROR: relation "goose_db_version" does not exist at character 367882026-08-27 09:15:48.719 UTC [1000] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7892026-08-27 09:15:48.719 UTC [998] ERROR: relation "goose_db_version" does not exist at character 367902026-08-27 09:15:48.719 UTC [998] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7912026-08-27 09:15:48.720 UTC [1001] ERROR: relation "goose_db_version" does not exist at character 367922026-08-27 09:15:48.720 UTC [1001] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7932026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (6.18ms)7942026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200007952026/08/27 09:15:48 OK 20251218171726_add_pins.sql (4.87ms)7962026-08-27 09:15:48.721 UTC [1003] ERROR: relation "goose_db_version" does not exist at character 367972026-08-27 09:15:48.721 UTC [1003] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7982026-08-27 09:15:48.721 UTC [1002] ERROR: relation "goose_db_version" does not exist at character 367992026-08-27 09:15:48.721 UTC [1002] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8002026/08/27 09:15:48 OK 2_object_stats_trigger.sql (2.8ms)8012026/08/27 09:15:48 goose: up to current file version: 28022026/08/27 09:15:48 OK 20241026095416_initial_model.sql (11.4ms)8032026/08/27 09:15:48 OK 1_commit_pending_closure.sql (4.23ms)804{"timestamp":"2026-08-27T09:15:48.723523876Z","level":"ERROR","duration":"384.621µs","resp":"Response { status: 503, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>SlowDown</Code><Message>bucket creation concurrency limit reached; retry later</Message></Error>\" } }","target":"s3s::service","filename":"/build/rustfs-1.0.0-beta.12-vendor/source-git-1/s3s-0.14.1/src/service.rs","line_number":640,"threadName":"rustfs-worker","threadId":"ThreadId(765)"}8052026/08/27 09:15:48 OK 1_commit_pending_closure.sql (2.65ms)806{"timestamp":"2026-08-27T09:15:48.723703436Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"de8cb90d-6728-4eaa-ba7f-4f96e461c91d","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket10/","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::layer","filename":"rustfs/src/server/layer.rs","line_number":392,"threadName":"rustfs-worker","threadId":"ThreadId(765)"}8072026/08/27 09:15:48 OK 20241026095416_initial_model.sql (12.3ms)8082026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (2.77ms)8092026/08/27 09:15:48 OK 2_object_stats_trigger.sql (2.05ms)8102026/08/27 09:15:48 goose: up to current file version: 28112026/08/27 09:15:48 OK 2_object_stats_trigger.sql (3.34ms)8122026/08/27 09:15:48 goose: up to current file version: 28132026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (5.8ms)8142026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (1.82ms)815{"timestamp":"2026-08-27T09:15:48.72716112Z","level":"ERROR","duration":"313.03µs","resp":"Response { status: 503, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>SlowDown</Code><Message>bucket creation concurrency limit reached; retry later</Message></Error>\" } }","target":"s3s::service","filename":"/build/rustfs-1.0.0-beta.12-vendor/source-git-1/s3s-0.14.1/src/service.rs","line_number":640,"threadName":"rustfs-worker","threadId":"ThreadId(489)"}8162026/08/27 09:15:48 goose: successfully migrated database to version: 20260628120000817{"timestamp":"2026-08-27T09:15:48.727227661Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"3132c46d-0481-483f-839b-84203498532b","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket11/","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::layer","filename":"rustfs/src/server/layer.rs","line_number":392,"threadName":"rustfs-worker","threadId":"ThreadId(489)"}818{"timestamp":"2026-08-27T09:15:48.727748821Z","level":"ERROR","duration":"346.17µs","resp":"Response { status: 503, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>SlowDown</Code><Message>bucket creation concurrency limit reached; retry later</Message></Error>\" } }","target":"s3s::service","filename":"/build/rustfs-1.0.0-beta.12-vendor/source-git-1/s3s-0.14.1/src/service.rs","line_number":640,"threadName":"rustfs-worker","threadId":"ThreadId(546)"}819{"timestamp":"2026-08-27T09:15:48.727806961Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"14e8a83d-4b6d-48d3-aeec-5c360ab36544","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket12/","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::layer","filename":"rustfs/src/server/layer.rs","line_number":392,"threadName":"rustfs-worker","threadId":"ThreadId(546)"}8202026/08/27 09:15:48 OK 1_commit_pending_closure.sql (12.54ms)8212026/08/27 09:15:48 OK 20251218171726_add_pins.sql (14.68ms)8222026/08/27 09:15:48 OK 20251218171726_add_pins.sql (12.82ms)8232026/08/27 09:15:48 OK 20241026095416_initial_model.sql (17.07ms)8242026/08/27 09:15:48 OK 20241026095416_initial_model.sql (13.2ms)8252026/08/27 09:15:48 OK 20241026095416_initial_model.sql (13.36ms)8262026/08/27 09:15:48 OK 20241026095416_initial_model.sql (13.41ms)8272026/08/27 09:15:48 OK 2_object_stats_trigger.sql (2.57ms)8282026/08/27 09:15:48 goose: up to current file version: 28292026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (2.3ms)830{"timestamp":"2026-08-27T09:15:48.744113112Z","level":"ERROR","duration":"521.26µs","resp":"Response { status: 503, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>SlowDown</Code><Message>bucket creation concurrency limit reached; retry later</Message></Error>\" } }","target":"s3s::service","filename":"/build/rustfs-1.0.0-beta.12-vendor/source-git-1/s3s-0.14.1/src/service.rs","line_number":640,"threadName":"rustfs-worker","threadId":"ThreadId(765)"}8312026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (2.2ms)832{"timestamp":"2026-08-27T09:15:48.744189182Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"0ea27fbb-b815-47df-ac0c-0c4c63907d5e","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket13/","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::layer","filename":"rustfs/src/server/layer.rs","line_number":392,"threadName":"rustfs-worker","threadId":"ThreadId(765)"}8332026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (3.4ms)8342026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (3.48ms)8352026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (6.18ms)8362026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200008372026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (6.6ms)8382026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200008392026/08/27 09:15:48 OK 20251218171726_add_pins.sql (4.89ms)8402026/08/27 09:15:48 OK 20251218171726_add_pins.sql (4.46ms)8412026/08/27 09:15:48 OK 20241026095416_initial_model.sql (11.41ms)8422026/08/27 09:15:48 OK 1_commit_pending_closure.sql (2.84ms)8432026/08/27 09:15:48 OK 20251218171726_add_pins.sql (4.28ms)8442026/08/27 09:15:48 OK 20251218171726_add_pins.sql (4.36ms)8452026/08/27 09:15:48 OK 1_commit_pending_closure.sql (3.14ms)8462026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (2.14ms)8472026/08/27 09:15:48 OK 2_object_stats_trigger.sql (1.8ms)8482026/08/27 09:15:48 goose: up to current file version: 28492026/08/27 09:15:48 OK 2_object_stats_trigger.sql (2.31ms)8502026/08/27 09:15:48 goose: up to current file version: 28512026/08/27 09:15:48 OK 20241026095416_initial_model.sql (11.7ms)8522026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (5.04ms)8532026/08/27 09:15:48 goose: successfully migrated database to version: 20260628120000854{"timestamp":"2026-08-27T09:15:48.753338994Z","level":"ERROR","duration":"466.341µs","resp":"Response { status: 503, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>SlowDown</Code><Message>bucket creation concurrency limit reached; retry later</Message></Error>\" } }","target":"s3s::service","filename":"/build/rustfs-1.0.0-beta.12-vendor/source-git-1/s3s-0.14.1/src/service.rs","line_number":640,"threadName":"rustfs-worker","threadId":"ThreadId(546)"}855{"timestamp":"2026-08-27T09:15:48.753411414Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"83680e50-4a1c-4f5c-9fbc-aecb9c35bda3","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket14/","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::layer","filename":"rustfs/src/server/layer.rs","line_number":392,"threadName":"rustfs-worker","threadId":"ThreadId(546)"}856{"timestamp":"2026-08-27T09:15:48.753844365Z","level":"ERROR","duration":"450.181µs","resp":"Response { status: 503, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>SlowDown</Code><Message>bucket creation concurrency limit reached; retry later</Message></Error>\" } }","target":"s3s::service","filename":"/build/rustfs-1.0.0-beta.12-vendor/source-git-1/s3s-0.14.1/src/service.rs","line_number":640,"threadName":"rustfs-worker","threadId":"ThreadId(584)"}857{"timestamp":"2026-08-27T09:15:48.753926325Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"99aa5099-4dd6-4a74-b4c6-504cdce44e20","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket15/","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::layer","filename":"rustfs/src/server/layer.rs","line_number":392,"threadName":"rustfs-worker","threadId":"ThreadId(584)"}8582026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (5.69ms)8592026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200008602026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (2.23ms)8612026/08/27 09:15:48 OK 20241026095416_initial_model.sql (13.99ms)8622026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (5.6ms)8632026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200008642026/08/27 09:15:48 OK 20251218171726_add_pins.sql (4.43ms)8652026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (5.67ms)8662026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200008672026/08/27 09:15:48 OK 1_commit_pending_closure.sql (3.22ms)8682026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (1.65ms)8692026/08/27 09:15:48 OK 1_commit_pending_closure.sql (2.04ms)8702026/08/27 09:15:48 OK 20251218171726_add_pins.sql (2.4ms)8712026/08/27 09:15:48 OK 1_commit_pending_closure.sql (1.84ms)8722026/08/27 09:15:48 OK 2_object_stats_trigger.sql (1.22ms)8732026/08/27 09:15:48 goose: up to current file version: 28742026/08/27 09:15:48 OK 1_commit_pending_closure.sql (1.85ms)8752026/08/27 09:15:48 OK 2_object_stats_trigger.sql (1.24ms)8762026/08/27 09:15:48 goose: up to current file version: 28772026/08/27 09:15:48 OK 2_object_stats_trigger.sql (887.57µs)8782026/08/27 09:15:48 goose: up to current file version: 28792026/08/27 09:15:48 OK 2_object_stats_trigger.sql (872.03µs)8802026/08/27 09:15:48 goose: up to current file version: 28812026/08/27 09:15:48 OK 20251218171726_add_pins.sql (2.37ms)8822026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (3.31ms)8832026/08/27 09:15:48 goose: successfully migrated database to version: 20260628120000884{"timestamp":"2026-08-27T09:15:48.759683712Z","level":"ERROR","duration":"642.471µs","resp":"Response { status: 503, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>SlowDown</Code><Message>bucket creation concurrency limit reached; retry later</Message></Error>\" } }","target":"s3s::service","filename":"/build/rustfs-1.0.0-beta.12-vendor/source-git-1/s3s-0.14.1/src/service.rs","line_number":640,"threadName":"rustfs-worker","threadId":"ThreadId(766)"}885{"timestamp":"2026-08-27T09:15:48.759721442Z","level":"ERROR","duration":"336.23µs","resp":"Response { status: 503, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>SlowDown</Code><Message>bucket creation concurrency limit reached; retry later</Message></Error>\" } }","target":"s3s::service","filename":"/build/rustfs-1.0.0-beta.12-vendor/source-git-1/s3s-0.14.1/src/service.rs","line_number":640,"threadName":"rustfs-worker","threadId":"ThreadId(546)"}886{"timestamp":"2026-08-27T09:15:48.759766192Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"36001edf-b3a0-4fbb-a33a-0f1461a22f3f","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket17/","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::layer","filename":"rustfs/src/server/layer.rs","line_number":392,"threadName":"rustfs-worker","threadId":"ThreadId(546)"}887{"timestamp":"2026-08-27T09:15:48.759765052Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"5cb80bac-4988-4c10-bc70-3dd4eb5700c6","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket16/","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::layer","filename":"rustfs/src/server/layer.rs","line_number":392,"threadName":"rustfs-worker","threadId":"ThreadId(766)"}888{"timestamp":"2026-08-27T09:15:48.760160843Z","level":"ERROR","duration":"363.371µs","resp":"Response { status: 503, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>SlowDown</Code><Message>bucket creation concurrency limit reached; retry later</Message></Error>\" } }","target":"s3s::service","filename":"/build/rustfs-1.0.0-beta.12-vendor/source-git-1/s3s-0.14.1/src/service.rs","line_number":640,"threadName":"rustfs-worker","threadId":"ThreadId(765)"}889{"timestamp":"2026-08-27T09:15:48.760201883Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"b459f088-253d-473f-9b44-6054925cb987","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket19/","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::layer","filename":"rustfs/src/server/layer.rs","line_number":392,"threadName":"rustfs-worker","threadId":"ThreadId(765)"}890{"timestamp":"2026-08-27T09:15:48.760599243Z","level":"ERROR","duration":"641.06µs","resp":"Response { status: 503, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>SlowDown</Code><Message>bucket creation concurrency limit reached; retry later</Message></Error>\" } }","target":"s3s::service","filename":"/build/rustfs-1.0.0-beta.12-vendor/source-git-1/s3s-0.14.1/src/service.rs","line_number":640,"threadName":"rustfs-worker","threadId":"ThreadId(767)"}891{"timestamp":"2026-08-27T09:15:48.760651513Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"f5e72c05-603d-4f59-8fca-b66d9cac0ac4","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket18/","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::layer","filename":"rustfs/src/server/layer.rs","line_number":392,"threadName":"rustfs-worker","threadId":"ThreadId(767)"}8922026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (3.47ms)8932026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200008942026/08/27 09:15:48 OK 1_commit_pending_closure.sql (1.57ms)8952026/08/27 09:15:48 OK 2_object_stats_trigger.sql (883.44µs)8962026/08/27 09:15:48 goose: up to current file version: 28972026/08/27 09:15:48 OK 1_commit_pending_closure.sql (1.3ms)8982026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (3.1ms)8992026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200009002026-08-27 09:15:48.763 UTC [1004] ERROR: relation "goose_db_version" does not exist at character 369012026-08-27 09:15:48.763 UTC [1004] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC902{"timestamp":"2026-08-27T09:15:48.763420957Z","level":"ERROR","duration":"348.99µs","resp":"Response { status: 503, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>SlowDown</Code><Message>bucket creation concurrency limit reached; retry later</Message></Error>\" } }","target":"s3s::service","filename":"/build/rustfs-1.0.0-beta.12-vendor/source-git-1/s3s-0.14.1/src/service.rs","line_number":640,"threadName":"rustfs-worker","threadId":"ThreadId(765)"}903{"timestamp":"2026-08-27T09:15:48.763469047Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"73e4cac9-81be-47f7-a03b-ee5a23c0285f","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket20/","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::layer","filename":"rustfs/src/server/layer.rs","line_number":392,"threadName":"rustfs-worker","threadId":"ThreadId(765)"}9042026/08/27 09:15:48 OK 2_object_stats_trigger.sql (1.08ms)905{"timestamp":"2026-08-27T09:15:48.763469577Z","level":"ERROR","duration":"146.46µs","resp":"Response { status: 503, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>SlowDown</Code><Message>bucket creation concurrency limit reached; retry later</Message></Error>\" } }","target":"s3s::service","filename":"/build/rustfs-1.0.0-beta.12-vendor/source-git-1/s3s-0.14.1/src/service.rs","line_number":640,"threadName":"rustfs-worker","threadId":"ThreadId(489)"}9062026/08/27 09:15:48 goose: up to current file version: 2907{"timestamp":"2026-08-27T09:15:48.763521547Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"7c4a342b-fdf0-44e0-ab04-61f8345e5c22","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket14/","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::layer","filename":"rustfs/src/server/layer.rs","line_number":392,"threadName":"rustfs-worker","threadId":"ThreadId(489)"}9082026/08/27 09:15:48 OK 1_commit_pending_closure.sql (1.9ms)909{"timestamp":"2026-08-27T09:15:48.765125019Z","level":"ERROR","duration":"345.67µs","resp":"Response { status: 503, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>SlowDown</Code><Message>bucket creation concurrency limit reached; retry later</Message></Error>\" } }","target":"s3s::service","filename":"/build/rustfs-1.0.0-beta.12-vendor/source-git-1/s3s-0.14.1/src/service.rs","line_number":640,"threadName":"rustfs-worker","threadId":"ThreadId(489)"}910{"timestamp":"2026-08-27T09:15:48.765174349Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"3ed84eda-c903-40ef-b9a1-e5c055e4369c","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket21/","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::layer","filename":"rustfs/src/server/layer.rs","line_number":392,"threadName":"rustfs-worker","threadId":"ThreadId(489)"}9112026/08/27 09:15:48 OK 2_object_stats_trigger.sql (828.45µs)9122026/08/27 09:15:48 goose: up to current file version: 2913{"timestamp":"2026-08-27T09:15:48.766559671Z","level":"ERROR","duration":"334.61µs","resp":"Response { status: 503, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>SlowDown</Code><Message>bucket creation concurrency limit reached; retry later</Message></Error>\" } }","target":"s3s::service","filename":"/build/rustfs-1.0.0-beta.12-vendor/source-git-1/s3s-0.14.1/src/service.rs","line_number":640,"threadName":"rustfs-worker","threadId":"ThreadId(546)"}914{"timestamp":"2026-08-27T09:15:48.766607171Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"3d480528-b003-4856-883e-e99721653367","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket22/","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::layer","filename":"rustfs/src/server/layer.rs","line_number":392,"threadName":"rustfs-worker","threadId":"ThreadId(546)"}9152026-08-27 09:15:48.767 UTC [1005] ERROR: relation "goose_db_version" does not exist at character 369162026-08-27 09:15:48.767 UTC [1005] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9172026-08-27 09:15:48.767 UTC [1006] ERROR: relation "goose_db_version" does not exist at character 369182026-08-27 09:15:48.767 UTC [1006] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC919{"timestamp":"2026-08-27T09:15:48.768054523Z","level":"ERROR","duration":"124.77µs","resp":"Response { status: 503, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>SlowDown</Code><Message>bucket creation concurrency limit reached; retry later</Message></Error>\" } }","target":"s3s::service","filename":"/build/rustfs-1.0.0-beta.12-vendor/source-git-1/s3s-0.14.1/src/service.rs","line_number":640,"threadName":"rustfs-worker","threadId":"ThreadId(489)"}920{"timestamp":"2026-08-27T09:15:48.768100203Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"144b42a1-b6c1-426e-aceb-c8ff3398c846","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket19/","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::layer","filename":"rustfs/src/server/layer.rs","line_number":392,"threadName":"rustfs-worker","threadId":"ThreadId(489)"}9212026/08/27 09:15:48 WARN mTLS auth: subject not in bound subjects subject="CN=reader"9222026/08/27 09:15:48 WARN mTLS auth: subject not in bound subjects subject="CN=writer"923--- PASS: TestService_NativeMTLS (0.56s)924=== CONT TestPinProtectsFromGC9252026/08/27 09:15:48 OK 20241026095416_initial_model.sql (7.47ms)9262026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (1.43ms)927--- PASS: TestReadProxyInvalidPath (0.57s)928=== CONT TestClientWithDependencies9292026/08/27 09:15:48 OK 20251218171726_add_pins.sql (2.68ms)9302026/08/27 09:15:48 OK 20241026095416_initial_model.sql (7.66ms)9312026/08/27 09:15:48 OK 20241026095416_initial_model.sql (7.87ms)9322026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (980.17µs)9332026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (2.32ms)9342026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200009352026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (1.37ms)9362026/08/27 09:15:48 OK 1_commit_pending_closure.sql (2.2ms)9372026/08/27 09:15:48 OK 20251218171726_add_pins.sql (3.63ms)9382026/08/27 09:15:48 OK 2_object_stats_trigger.sql (1.32ms)9392026/08/27 09:15:48 goose: up to current file version: 29402026/08/27 09:15:48 OK 20251218171726_add_pins.sql (3.25ms)9412026/08/27 09:15:48 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"942--- PASS: TestService_AuthMiddleware (0.58s)943=== CONT TestClientMultipleUploads9442026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (2.82ms)9452026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200009462026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (3.44ms)9472026/08/27 09:15:48 goose: successfully migrated database to version: 202606281200009482026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures9492026/08/27 09:15:48 OK 1_commit_pending_closure.sql (2.74ms)9502026/08/27 09:15:48 OK 1_commit_pending_closure.sql (2.49ms)9512026/08/27 09:15:48 OK 2_object_stats_trigger.sql (1.66ms)9522026/08/27 09:15:48 goose: up to current file version: 29532026/08/27 09:15:48 OK 2_object_stats_trigger.sql (905.21µs)9542026/08/27 09:15:48 goose: up to current file version: 29552026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures9562026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures9572026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures9582026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures9592026/08/27 09:15:48 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9602026/08/27 09:15:48 INFO Received cleanup request method=DELETE path=/api/pending_closures9612026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures9622026/08/27 09:15:48 INFO Aborted multipart uploads count=09632026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures964--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.61s)965=== CONT TestClientIntegration9662026/08/27 09:15:48 INFO Received cleanup request method=DELETE path=/api/pending_closures9672026/08/27 09:15:48 INFO Aborted multipart uploads count=19682026/08/27 09:15:48 INFO Aborted multipart uploads count=09692026/08/27 09:15:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9702026-08-27 09:15:48.833 UTC [1005] ERROR: Closure does not exist: id=19712026-08-27 09:15:48.833 UTC [1005] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE9722026-08-27 09:15:48.833 UTC [1005] STATEMENT: -- name: CommitPendingClosure :exec973 SELECT commit_pending_closure($1::bigint)974 975--- PASS: TestService_cleanupPendingClosuresHandler (0.32s)976=== CONT TestGCTaskStore_GetEmpty977--- PASS: TestGCTaskStore_GetEmpty (0.00s)978=== CONT TestParseSingleRange979=== RUN TestParseSingleRange/none980=== PAUSE TestParseSingleRange/none981=== RUN TestParseSingleRange/unknown_unit982=== PAUSE TestParseSingleRange/unknown_unit9832026/08/27 09:15:48 INFO Created nix-cache-info in bucket bucket=bucket20984=== RUN TestParseSingleRange/multi-range_ignored9852026/08/27 09:15:48 WARN Force mode enabled - objects will be deleted immediately without grace period986=== PAUSE TestParseSingleRange/multi-range_ignored987=== RUN TestParseSingleRange/malformed_no_dash988=== PAUSE TestParseSingleRange/malformed_no_dash989=== RUN TestParseSingleRange/malformed_both_empty990=== PAUSE TestParseSingleRange/malformed_both_empty991=== RUN TestParseSingleRange/malformed_end_before_start992=== PAUSE TestParseSingleRange/malformed_end_before_start993=== RUN TestParseSingleRange/closed994=== PAUSE TestParseSingleRange/closed995=== RUN TestParseSingleRange/open-ended996=== PAUSE TestParseSingleRange/open-ended997=== RUN TestParseSingleRange/end_clamped_to_size998=== PAUSE TestParseSingleRange/end_clamped_to_size999=== RUN TestParseSingleRange/suffix1000=== PAUSE TestParseSingleRange/suffix1001=== RUN TestParseSingleRange/suffix_exceeds_size1002=== PAUSE TestParseSingleRange/suffix_exceeds_size1003=== RUN TestParseSingleRange/single_byte1004=== PAUSE TestParseSingleRange/single_byte1005=== RUN TestParseSingleRange/start_past_EOF1006=== PAUSE TestParseSingleRange/start_past_EOF1007=== RUN TestParseSingleRange/start_far_past_EOF1008=== PAUSE TestParseSingleRange/start_far_past_EOF1009=== CONT TestReadProxy40410102026/08/27 09:15:48 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=010112026/08/27 09:15:48 INFO Vacuumed table table=pending_closures10122026/08/27 09:15:48 INFO Vacuumed table table=pending_objects10132026/08/27 09:15:48 INFO Vacuumed table table=multipart_uploads10142026/08/27 09:15:48 INFO Vacuumed table table=closures10152026/08/27 09:15:48 INFO Vacuumed table table=objects1016--- PASS: TestReadProxyDisabled (0.63s)1017=== CONT TestReadProxyNarStreaming1018--- PASS: TestGCMetrics (0.33s)1019=== CONT TestReadProxyNarinfoAlreadyDecompressed1020--- PASS: TestService_healthCheckHandler (0.56s)1021=== CONT TestService_AuthMiddleware_OIDC10222026/08/27 09:15:48 INFO OIDC provider initialized name=test10232026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures10242026-08-27 09:15:48.872 UTC [1042] ERROR: relation "goose_db_version" does not exist at character 3610252026-08-27 09:15:48.872 UTC [1042] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10262026-08-27 09:15:48.874 UTC [1043] ERROR: relation "goose_db_version" does not exist at character 3610272026-08-27 09:15:48.874 UTC [1043] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10282026/08/27 09:15:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1029=== NAME TestNARDeduplicationMetadataUploadBug1030 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug2009780148/001/store/krckk0d0jyzrainf3mrxdpk3mdj0lbnb-file1.txt10312026/08/27 09:15:48 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1032--- PASS: TestCompleteMultipartUnregistered (0.67s)1033=== CONT TestReadProxyNarinfo1034--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.67s)1035=== CONT TestIsValidCachePath1036=== RUN TestIsValidCachePath/narinfo1037=== PAUSE TestIsValidCachePath/narinfo1038=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1039=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1040=== RUN TestIsValidCachePath/nar_zst1041=== PAUSE TestIsValidCachePath/nar_zst1042=== RUN TestIsValidCachePath/nar_xz1043=== PAUSE TestIsValidCachePath/nar_xz1044=== RUN TestIsValidCachePath/nar_bz21045=== PAUSE TestIsValidCachePath/nar_bz21046=== RUN TestIsValidCachePath/nar_uncompressed1047=== PAUSE TestIsValidCachePath/nar_uncompressed1048=== RUN TestIsValidCachePath/ls1049=== PAUSE TestIsValidCachePath/ls1050=== RUN TestIsValidCachePath/log1051=== PAUSE TestIsValidCachePath/log1052=== RUN TestIsValidCachePath/realisation1053=== PAUSE TestIsValidCachePath/realisation1054=== RUN TestIsValidCachePath/nix-cache-info1055=== PAUSE TestIsValidCachePath/nix-cache-info1056=== RUN TestIsValidCachePath/index.html1057=== PAUSE TestIsValidCachePath/index.html1058=== RUN TestIsValidCachePath/traversal_parent1059=== PAUSE TestIsValidCachePath/traversal_parent1060=== RUN TestIsValidCachePath/traversal_in_middle1061=== PAUSE TestIsValidCachePath/traversal_in_middle1062=== RUN TestIsValidCachePath/invalid_char_e10632026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures1064=== PAUSE TestIsValidCachePath/invalid_char_e1065=== RUN TestIsValidCachePath/invalid_char_u1066=== PAUSE TestIsValidCachePath/invalid_char_u1067=== RUN TestIsValidCachePath/random_path1068=== PAUSE TestIsValidCachePath/random_path1069=== RUN TestIsValidCachePath/empty1070=== PAUSE TestIsValidCachePath/empty1071=== RUN TestIsValidCachePath/leading_slash1072=== PAUSE TestIsValidCachePath/leading_slash1073=== RUN TestIsValidCachePath/wrong_extension1074=== PAUSE TestIsValidCachePath/wrong_extension1075=== RUN TestIsValidCachePath/short_hash1076=== PAUSE TestIsValidCachePath/short_hash1077=== CONT TestClientCADerivations10782026-08-27 09:15:48.886 UTC [1044] ERROR: relation "goose_db_version" does not exist at character 3610792026-08-27 09:15:48.886 UTC [1044] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10802026/08/27 09:15:48 OK 20241026095416_initial_model.sql (15.3ms)10812026/08/27 09:15:48 OK 20241026095416_initial_model.sql (12.48ms)10822026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures10832026/08/27 09:15:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10842026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (2.64ms)10852026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (3.99ms)10862026/08/27 09:15:48 OK 20251218171726_add_pins.sql (4.61ms)10872026/08/27 09:15:48 OK 20251218171726_add_pins.sql (3.91ms)10882026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures10892026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (5.98ms)10902026/08/27 09:15:48 goose: successfully migrated database to version: 2026062812000010912026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (7.05ms)10922026/08/27 09:15:48 goose: successfully migrated database to version: 2026062812000010932026/08/27 09:15:48 OK 20241026095416_initial_model.sql (14.3ms)10942026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (2.18ms)10952026/08/27 09:15:48 OK 1_commit_pending_closure.sql (3.6ms)10962026/08/27 09:15:48 OK 1_commit_pending_closure.sql (3.5ms)1097--- PASS: TestService_Rustfstest (0.70s)1098=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1099--- PASS: TestReadProxyRangeRequest (0.70s)1100=== CONT TestCacheStatsHandler11012026/08/27 09:15:48 OK 2_object_stats_trigger.sql (12.12ms)11022026/08/27 09:15:48 goose: up to current file version: 211032026/08/27 09:15:48 OK 2_object_stats_trigger.sql (12.04ms)11042026/08/27 09:15:48 goose: up to current file version: 211052026/08/27 09:15:48 OK 20251218171726_add_pins.sql (18.01ms)1106--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.71s)1107=== CONT TestService_ReadAuthMiddleware11082026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (4.71ms)11092026/08/27 09:15:48 goose: successfully migrated database to version: 2026062812000011102026/08/27 09:15:48 OK 1_commit_pending_closure.sql (2.39ms)11112026/08/27 09:15:48 OK 2_object_stats_trigger.sql (4.41ms)11122026/08/27 09:15:48 goose: up to current file version: 211132026-08-27 09:15:48.942 UTC [1075] ERROR: relation "goose_db_version" does not exist at character 3611142026-08-27 09:15:48.942 UTC [1075] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1115--- PASS: TestReadProxyHead (0.73s)1116=== CONT TestCacheConfigHandler1117=== RUN TestCacheConfigHandler/full_config,_no_issuer1118=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1119=== RUN TestCacheConfigHandler/no_cache_url_configured1120=== PAUSE TestCacheConfigHandler/no_cache_url_configured1121=== RUN TestCacheConfigHandler/no_signing_keys1122=== PAUSE TestCacheConfigHandler/no_signing_keys1123=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1124=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1125=== CONT TestOrphanedObjectsGC11262026/08/27 09:15:48 INFO Created nix-cache-info in bucket bucket=bucket261127--- PASS: TestMetricsInventory (0.75s)1128=== CONT TestOrphanedObjectsGCStressTest11292026/08/27 09:15:48 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11302026/08/27 09:15:48 INFO Created nix-cache-info in bucket bucket=bucket2711312026-08-27 09:15:48.964 UTC [1099] ERROR: relation "goose_db_version" does not exist at character 3611322026-08-27 09:15:48.964 UTC [1099] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11332026/08/27 09:15:48 OK 20241026095416_initial_model.sql (21.53ms)1134--- PASS: TestReadProxyConditionalGet (0.76s)1135=== CONT TestResurrectedObjectNotDeleted11362026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (4ms)11372026/08/27 09:15:48 OK 20251218171726_add_pins.sql (5ms)11382026-08-27 09:15:48.983 UTC [1106] ERROR: relation "goose_db_version" does not exist at character 3611392026-08-27 09:15:48.983 UTC [1106] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11402026-08-27 09:15:48.986 UTC [1124] ERROR: relation "goose_db_version" does not exist at character 3611412026-08-27 09:15:48.986 UTC [1124] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11422026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures11432026/08/27 09:15:48 OK 20260628120000_add_object_size_and_stats.sql (6.2ms)11442026/08/27 09:15:48 goose: successfully migrated database to version: 2026062812000011452026/08/27 09:15:48 OK 1_commit_pending_closure.sql (5.59ms)11462026/08/27 09:15:48 INFO Received uploads request method=POST path=/api/pending_closures11472026/08/27 09:15:48 OK 20241026095416_initial_model.sql (14.65ms)11482026/08/27 09:15:48 OK 2_object_stats_trigger.sql (2.93ms)11492026/08/27 09:15:48 goose: up to current file version: 211502026-08-27 09:15:48.998 UTC [1158] ERROR: relation "goose_db_version" does not exist at character 3611512026-08-27 09:15:48.998 UTC [1158] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11522026/08/27 09:15:48 OK 20251210153512_drop_unused_gin_index.sql (2.96ms)11532026/08/27 09:15:49 INFO Created nix-cache-info in bucket bucket=bucket2811542026/08/27 09:15:49 OK 20251218171726_add_pins.sql (8.22ms)11552026/08/27 09:15:49 OK 20241026095416_initial_model.sql (15.29ms)11562026/08/27 09:15:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11572026/08/27 09:15:49 INFO Uploading krckk0d0jyzrainf3mrxdpk3mdj0lbnb-file1.txt (160B)11582026/08/27 09:15:49 OK 20241026095416_initial_model.sql (12.52ms)11592026/08/27 09:15:49 OK 20251210153512_drop_unused_gin_index.sql (3.6ms)11602026/08/27 09:15:49 OK 20251210153512_drop_unused_gin_index.sql (3.38ms)11612026/08/27 09:15:49 INFO Created nix-cache-info in bucket bucket=bucket2911622026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (7.21ms)11632026/08/27 09:15:49 goose: successfully migrated database to version: 2026062812000011642026/08/27 09:15:49 OK 20251218171726_add_pins.sql (4.35ms)11652026/08/27 09:15:49 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11662026/08/27 09:15:49 OK 20251218171726_add_pins.sql (3.68ms)11672026/08/27 09:15:49 OK 1_commit_pending_closure.sql (3.74ms)11682026/08/27 09:15:49 OK 20241026095416_initial_model.sql (12.78ms)11692026/08/27 09:15:49 WARN Failed to register uploaded object key=krckk0d0jyzrainf3mrxdpk3mdj0lbnb.ls error="server returned 404: 404 page not found\n"11702026/08/27 09:15:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11712026-08-27 09:15:49.020 UTC [1163] ERROR: relation "goose_db_version" does not exist at character 3611722026-08-27 09:15:49.020 UTC [1163] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11732026/08/27 09:15:49 INFO Signed narinfos id=1 count=111742026/08/27 09:15:49 INFO Uploading 1 narinfos11752026/08/27 09:15:49 OK 2_object_stats_trigger.sql (2.22ms)11762026/08/27 09:15:49 goose: up to current file version: 211772026/08/27 09:15:49 WARN Failed to register uploaded object key=krckk0d0jyzrainf3mrxdpk3mdj0lbnb.narinfo error="server returned 404: 404 page not found\n"11782026/08/27 09:15:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11792026/08/27 09:15:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11802026-08-27 09:15:49.027 UTC [1181] ERROR: relation "goose_db_version" does not exist at character 3611812026-08-27 09:15:49.027 UTC [1181] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11822026/08/27 09:15:49 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NWFkOWI5NzYtZTg4NS00YjFlLWEwOGQtMTA5Nzc3YjNkNTQxLmYzMWIxMzljLWZjMmUtNDJhNC05MGIzLTIwYTZjN2Y5MWFlMXgxNzg3ODIyMTQ4OTk4MjcwNzQ411832026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (13.88ms)11842026/08/27 09:15:49 goose: successfully migrated database to version: 2026062812000011852026/08/27 09:15:49 OK 20251210153512_drop_unused_gin_index.sql (12.4ms)11862026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (14.77ms)11872026/08/27 09:15:49 goose: successfully migrated database to version: 202606281200001188--- PASS: TestReadProxy404 (0.20s)1189=== CONT TestService_AuthMiddleware_MTLSProxyHeader11902026/08/27 09:15:49 INFO Completed upload id=111912026/08/27 09:15:49 INFO Upload complete. (117ms)1192=== NAME TestNARDeduplicationMetadataUploadBug1193 metadata_upload_test.go:54: Retrieved narinfo from S3:1194 StorePath: /build/TestNARDeduplicationMetadataUploadBug2009780148/001/store/krckk0d0jyzrainf3mrxdpk3mdj0lbnb-file1.txt1195 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1196 Compression: zstd1197 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1198 NarSize: 16011992026/08/27 09:15:49 OK 1_commit_pending_closure.sql (6.08ms)1200 References: 1201 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf12022026/08/27 09:15:49 OK 1_commit_pending_closure.sql (6.43ms)1203=== NAME TestPinProtectsFromGC1204 client_integration_test.go:646: Pinned store path: /build/TestPinProtectsFromGC2011157473/001/store/kx8657zgxy349dljp17hjmabpfimfima-pinned-file.txt1205 client_integration_test.go:647: Unpinned store path: /build/TestPinProtectsFromGC2011157473/001/store/726q7yxi614nqyy75p199vm5qbcngad5-unpinned-file.txt12062026/08/27 09:15:49 OK 2_object_stats_trigger.sql (1.95ms)12072026/08/27 09:15:49 goose: up to current file version: 212082026/08/27 09:15:49 OK 2_object_stats_trigger.sql (1.99ms)12092026/08/27 09:15:49 goose: up to current file version: 21210=== NAME TestClientWithDependencies1211 client_integration_test.go:593: Built derivation: /build/TestClientWithDependencies2024406373/001/store/arfm7fkm9k5nab5zjlx5wd9m2iy8ny7h-test-script1212=== NAME TestNARDeduplicationMetadataUploadBug1213 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1214 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1215 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}12162026/08/27 09:15:49 OK 20251218171726_add_pins.sql (10.06ms)12172026/08/27 09:15:49 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NWFkOWI5NzYtZTg4NS00YjFlLWEwOGQtMTA5Nzc3YjNkNTQxLmYzMWIxMzljLWZjMmUtNDJhNC05MGIzLTIwYTZjN2Y5MWFlMXgxNzg3ODIyMTQ4OTk4MjcwNzQ4 parts=11218--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.83s)1219=== CONT TestObjectStatsTrigger1220=== NAME TestClientMultipleUploads1221 client_integration_test.go:338: Created store path 0: /build/TestClientMultipleUploads415822276/001/store/vl9nkz5n7m17mfflh22z2nd5nrwl4nw6-test-file-0.txt1222--- PASS: TestGCBugBareHashReferences (0.46s)1223=== CONT TestMultipartCleanup12242026/08/27 09:15:49 OK 20241026095416_initial_model.sql (10.97ms)12252026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (7.22ms)12262026/08/27 09:15:49 goose: successfully migrated database to version: 2026062812000012272026/08/27 09:15:49 OK 20241026095416_initial_model.sql (10.8ms)12282026/08/27 09:15:49 OK 20251210153512_drop_unused_gin_index.sql (2.67ms)12292026/08/27 09:15:49 OK 20251210153512_drop_unused_gin_index.sql (2.15ms)12302026/08/27 09:15:49 OK 1_commit_pending_closure.sql (3.73ms)12312026/08/27 09:15:49 OK 20251218171726_add_pins.sql (3.08ms)1232=== NAME TestClientIntegration1233 client_integration_test.go:276: Created store path: /build/TestClientIntegration3887427590/002/store/08g5isdgks5i5a90ryf04r6bpvqpv0ik-test-file.txt12342026/08/27 09:15:49 OK 20251218171726_add_pins.sql (3.78ms)12352026/08/27 09:15:49 OK 2_object_stats_trigger.sql (2.64ms)12362026/08/27 09:15:49 goose: up to current file version: 212372026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (4.86ms)12382026/08/27 09:15:49 goose: successfully migrated database to version: 2026062812000012392026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (4.47ms)12402026/08/27 09:15:49 goose: successfully migrated database to version: 2026062812000012412026/08/27 09:15:49 OK 1_commit_pending_closure.sql (2.44ms)1242--- PASS: TestReadProxyNarStreaming (0.22s)1243=== CONT TestServerTLSConfig1244=== RUN TestServerTLSConfig/no_client_CA1245=== PAUSE TestServerTLSConfig/no_client_CA1246=== RUN TestServerTLSConfig/missing_CA_file1247=== PAUSE TestServerTLSConfig/missing_CA_file1248=== RUN TestServerTLSConfig/not_a_PEM_file1249=== PAUSE TestServerTLSConfig/not_a_PEM_file1250=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info12512026/08/27 09:15:49 INFO Received uploads request method=POST path=/12522026/08/27 09:15:49 OK 1_commit_pending_closure.sql (2.6ms)1253=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key12542026/08/27 09:15:49 INFO Received request for more parts method=POST path=/1255=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key12562026/08/27 09:15:49 INFO Received complete multipart upload request method=POST path=/1257=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal12582026-08-27 09:15:49.064 UTC [1241] ERROR: relation "goose_db_version" does not exist at character 3612592026-08-27 09:15:49.064 UTC [1241] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12602026/08/27 09:15:49 INFO Received uploads request method=POST path=/12612026-08-27 09:15:49.064 UTC [1242] ERROR: relation "goose_db_version" does not exist at character 3612622026-08-27 09:15:49.064 UTC [1242] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1263--- PASS: TestUploadHandlersRejectInvalidKeys (0.08s)1264 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1265 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1266 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1267 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)12682026/08/27 09:15:49 OK 2_object_stats_trigger.sql (1.9ms)1269=== CONT TestProxyWriteTimeout/narinfo12702026/08/27 09:15:49 goose: up to current file version: 21271=== CONT TestProxyWriteTimeout/unknown_size1272=== CONT TestProxyWriteTimeout/10_GiB_nar1273=== CONT TestProxyWriteTimeout/1_GiB_nar1274=== CONT TestIsValidUploadKey/narinfo1275--- PASS: TestProxyWriteTimeout (0.08s)1276 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1277 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1278 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1279 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1280=== CONT TestIsValidUploadKey/nix-cache-info12812026-08-27 09:15:49.065 UTC [1244] ERROR: relation "goose_db_version" does not exist at character 3612822026-08-27 09:15:49.065 UTC [1244] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1283=== CONT TestIsValidUploadKey/unknown_type1284=== CONT TestIsValidUploadKey/empty_key1285=== CONT TestIsValidUploadKey/absolute1286=== CONT TestIsValidUploadKey/traversal_nar1287=== CONT TestIsValidUploadKey/traversal1288=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1289=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1290=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1291=== CONT TestIsValidUploadKey/index.html1292=== CONT TestIsValidUploadKey/build_log_home-manager_file12932026/08/27 09:15:49 OK 2_object_stats_trigger.sql (2.16ms)1294=== CONT TestIsValidUploadKey/realisation_plus_in_output12952026/08/27 09:15:49 goose: up to current file version: 21296=== CONT TestIsValidUploadKey/realisation1297=== CONT TestIsValidUploadKey/build_log_equals1298=== CONT TestIsValidUploadKey/build_log_question_mark1299=== CONT TestIsValidUploadKey/build_log_plus_in_name1300=== CONT TestIsValidUploadKey/nar_plain1301=== CONT TestIsValidUploadKey/build_log1302=== CONT TestIsValidUploadKey/listing1303=== CONT TestIsValidUploadKey/nar_xz1304=== CONT TestIsValidUploadKey/nar_zst1305=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure13062026/08/27 09:15:49 INFO Received uploads request method=POST path=/1307--- PASS: TestIsValidUploadKey (0.30s)1308 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1309 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1310 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1311 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1312 --- PASS: TestIsValidUploadKey/absolute (0.00s)1313 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1314 --- PASS: TestIsValidUploadKey/traversal (0.00s)1315 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1316 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1317 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1318 --- PASS: TestIsValidUploadKey/index.html (0.00s)1319 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1320 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1321 --- PASS: TestIsValidUploadKey/realisation (0.00s)1322 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1323 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1324 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1325 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1326 --- PASS: TestIsValidUploadKey/build_log (0.00s)1327 --- PASS: TestIsValidUploadKey/listing (0.00s)1328 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1329 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)13302026/08/27 09:15:49 INFO Received uploads request method=POST path=/api/pending_closures1331--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.23s)1332=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts13332026/08/27 09:15:49 INFO Received request for more parts method=POST path=/1334=== NAME TestNARDeduplicationMetadataUploadBug1335 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug2009780148/001/store/zbpwrsyc145438g4s146pjvbvkbc2wzz-file2.txt13362026-08-27 09:15:49.076 UTC [1294] ERROR: relation "goose_db_version" does not exist at character 3613372026-08-27 09:15:49.076 UTC [1294] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1338=== NAME TestClientMultipleUploads1339 client_integration_test.go:338: Created store path 1: /build/TestClientMultipleUploads415822276/001/store/jpk67q3ql1fshmgjgjsvlmsc4047hcd8-test-file-1.txt13402026/08/27 09:15:49 INFO Created nix-cache-info in bucket bucket=bucket3513412026/08/27 09:15:49 OK 20241026095416_initial_model.sql (11.18ms)13422026/08/27 09:15:49 OK 20241026095416_initial_model.sql (11.16ms)13432026/08/27 09:15:49 OK 20241026095416_initial_model.sql (11.24ms)1344=== NAME TestClientWithDependencies1345 client_integration_test.go:595: Found 1 dependencies (including self)13462026/08/27 09:15:49 OK 20251210153512_drop_unused_gin_index.sql (3.36ms)13472026-08-27 09:15:49.086 UTC [1314] ERROR: relation "goose_db_version" does not exist at character 3613482026-08-27 09:15:49.086 UTC [1314] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13492026/08/27 09:15:49 OK 20251210153512_drop_unused_gin_index.sql (2.59ms)13502026/08/27 09:15:49 OK 20251210153512_drop_unused_gin_index.sql (2.67ms)13512026/08/27 09:15:49 OK 20251218171726_add_pins.sql (3.23ms)1352--- PASS: TestReadProxyNarinfo (0.21s)1353=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart13542026/08/27 09:15:49 INFO Received complete multipart upload request method=POST path=/13552026/08/27 09:15:49 OK 20251218171726_add_pins.sql (11.63ms)13562026/08/27 09:15:49 OK 20251218171726_add_pins.sql (11.84ms)13572026/08/27 09:15:49 OK 20241026095416_initial_model.sql (14.12ms)13582026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (11.13ms)13592026/08/27 09:15:49 goose: successfully migrated database to version: 2026062812000013602026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (4.33ms)13612026/08/27 09:15:49 goose: successfully migrated database to version: 2026062812000013622026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (5.26ms)13632026/08/27 09:15:49 goose: successfully migrated database to version: 2026062812000013642026/08/27 09:15:49 OK 20251210153512_drop_unused_gin_index.sql (2.83ms)13652026/08/27 09:15:49 OK 1_commit_pending_closure.sql (2.98ms)13662026/08/27 09:15:49 OK 1_commit_pending_closure.sql (2.43ms)13672026/08/27 09:15:49 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13682026/08/27 09:15:49 OK 1_commit_pending_closure.sql (2.69ms)13692026/08/27 09:15:49 OK 2_object_stats_trigger.sql (1.89ms)13702026/08/27 09:15:49 goose: up to current file version: 213712026/08/27 09:15:49 OK 2_object_stats_trigger.sql (1.96ms)13722026/08/27 09:15:49 goose: up to current file version: 213732026/08/27 09:15:49 OK 20251218171726_add_pins.sql (3.74ms)13742026/08/27 09:15:49 OK 2_object_stats_trigger.sql (1.2ms)13752026/08/27 09:15:49 goose: up to current file version: 213762026-08-27 09:15:49.111 UTC [1358] ERROR: relation "goose_db_version" does not exist at character 3613772026-08-27 09:15:49.111 UTC [1358] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13782026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (3.98ms)13792026/08/27 09:15:49 goose: successfully migrated database to version: 202606281200001380=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1381=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1382=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1383=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1384=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1385=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1386=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1387=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1388=== CONT TestClientErrorHandling/InvalidStorePath13892026/08/27 09:15:49 OK 1_commit_pending_closure.sql (2.47ms)13902026/08/27 09:15:49 OK 20241026095416_initial_model.sql (14.61ms)13912026/08/27 09:15:49 OK 2_object_stats_trigger.sql (2.23ms)1392=== NAME TestClientMultipleUploads13932026/08/27 09:15:49 goose: up to current file version: 21394 client_integration_test.go:338: Created store path 2: /build/TestClientMultipleUploads415822276/001/store/pkjwdlqchp7ddv094vp5fcf22jcnzm5j-test-file-2.txt13952026/08/27 09:15:49 OK 20251210153512_drop_unused_gin_index.sql (2.38ms)13962026/08/27 09:15:49 OK 20251218171726_add_pins.sql (3.99ms)13972026/08/27 09:15:49 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13982026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (4.24ms)13992026/08/27 09:15:49 goose: successfully migrated database to version: 202606281200001400--- PASS: TestCacheStatsHandler (0.21s)1401=== CONT TestClientErrorHandling/ServerNotAvailable14022026/08/27 09:15:49 OK 20241026095416_initial_model.sql (10.09ms)14032026/08/27 09:15:49 OK 1_commit_pending_closure.sql (2.33ms)14042026/08/27 09:15:49 OK 2_object_stats_trigger.sql (1.72ms)14052026/08/27 09:15:49 goose: up to current file version: 214062026/08/27 09:15:49 OK 20251210153512_drop_unused_gin_index.sql (2.31ms)14072026/08/27 09:15:49 OK 20251218171726_add_pins.sql (5.13ms)14082026/08/27 09:15:49 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1409=== CONT TestClientErrorHandling/InvalidAuthToken14102026/08/27 09:15:49 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1411--- PASS: TestService_ReadAuthMiddleware (0.21s)1412=== CONT TestParseSingleRange/none1413=== CONT TestParseSingleRange/single_byte1414=== CONT TestParseSingleRange/suffix_exceeds_size1415=== CONT TestParseSingleRange/suffix1416=== CONT TestParseSingleRange/end_clamped_to_size1417=== CONT TestParseSingleRange/open-ended1418=== CONT TestParseSingleRange/closed1419=== CONT TestParseSingleRange/malformed_end_before_start1420=== CONT TestParseSingleRange/malformed_both_empty1421=== CONT TestParseSingleRange/malformed_no_dash1422=== CONT TestParseSingleRange/multi-range_ignored1423=== CONT TestParseSingleRange/unknown_unit1424=== CONT TestParseSingleRange/start_past_EOF1425=== CONT TestParseSingleRange/start_far_past_EOF1426--- PASS: TestParseSingleRange (0.00s)1427 --- PASS: TestParseSingleRange/none (0.00s)1428 --- PASS: TestParseSingleRange/single_byte (0.00s)1429 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1430 --- PASS: TestParseSingleRange/suffix (0.00s)1431 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1432 --- PASS: TestParseSingleRange/open-ended (0.00s)1433 --- PASS: TestParseSingleRange/closed (0.00s)1434 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1435 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1436 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1437 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1438 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1439 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1440 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1441=== CONT TestIsValidCachePath/narinfo1442=== CONT TestIsValidCachePath/index.html1443=== CONT TestIsValidCachePath/short_hash1444=== CONT TestIsValidCachePath/wrong_extension1445=== CONT TestIsValidCachePath/leading_slash1446=== CONT TestIsValidCachePath/invalid_char_e1447=== CONT TestIsValidCachePath/traversal_in_middle1448=== CONT TestIsValidCachePath/traversal_parent1449=== CONT TestIsValidCachePath/nar_uncompressed1450=== CONT TestIsValidCachePath/invalid_char_u14512026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (4.14ms)1452=== CONT TestIsValidCachePath/empty14532026/08/27 09:15:49 goose: successfully migrated database to version: 202606281200001454=== CONT TestIsValidCachePath/nix-cache-info1455=== CONT TestIsValidCachePath/random_path1456=== CONT TestIsValidCachePath/realisation1457=== CONT TestIsValidCachePath/nar_xz1458=== CONT TestIsValidCachePath/log1459=== CONT TestIsValidCachePath/nar_bz21460=== CONT TestIsValidCachePath/ls1461=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1462=== CONT TestIsValidCachePath/nar_zst1463=== CONT TestCacheConfigHandler/full_config,_no_issuer14642026/08/27 09:15:49 INFO Received uploads request method=POST path=/api/pending_closures1465--- PASS: TestIsValidCachePath (0.00s)1466 --- PASS: TestIsValidCachePath/narinfo (0.00s)1467 --- PASS: TestIsValidCachePath/index.html (0.00s)1468 --- PASS: TestIsValidCachePath/short_hash (0.00s)1469 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1470 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1471 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1472 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1473 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1474 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1475 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1476 --- PASS: TestIsValidCachePath/empty (0.00s)1477 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1478 --- PASS: TestIsValidCachePath/random_path (0.00s)1479 --- PASS: TestIsValidCachePath/realisation (0.00s)1480 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1481 --- PASS: TestIsValidCachePath/log (0.00s)1482 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1483 --- PASS: TestIsValidCachePath/ls (0.00s)1484 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1485 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1486=== CONT TestCacheConfigHandler/no_signing_keys1487=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1488=== CONT TestCacheConfigHandler/no_cache_url_configured1489--- PASS: TestCacheConfigHandler (0.00s)1490 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1491 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1492 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1493 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1494=== CONT TestServerTLSConfig/no_client_CA1495=== CONT TestServerTLSConfig/not_a_PEM_file14962026/08/27 09:15:49 OK 1_commit_pending_closure.sql (2.32ms)1497=== CONT TestServerTLSConfig/missing_CA_file1498--- PASS: TestServerTLSConfig (0.00s)1499 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1500 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1501 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1502=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token15032026/08/27 09:15:49 OK 2_object_stats_trigger.sql (1.69ms)15042026/08/27 09:15:49 goose: up to current file version: 215052026/08/27 09:15:49 INFO OIDC auth successful provider=test1506=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected15072026/08/27 09:15:49 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]1508=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1509=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected15102026/08/27 09:15:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15112026/08/27 09:15:49 INFO Uploading kx8657zgxy349dljp17hjmabpfimfima-pinned-file.txt (128B)15122026/08/27 09:15:49 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15132026/08/27 09:15:49 WARN mTLS auth: bound subjects configured but subject DN unavailable15142026/08/27 09:15:49 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1515--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.24s)15162026/08/27 09:15:49 WARN Authentication failed token_preview=eyJhbGciOi...MwkM_J5sWA 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]1517--- PASS: TestService_AuthMiddleware_OIDC (0.26s)1518 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)1519 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1520 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1521 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)15222026/08/27 09:15:49 INFO Received uploads request method=POST path=/api/pending_closures15232026/08/27 09:15:49 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"15242026/08/27 09:15:49 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"15252026/08/27 09:15:49 INFO Received uploads request method=POST path=/api/pending_closures15262026-08-27 09:15:49.160 UTC [1551] ERROR: relation "goose_db_version" does not exist at character 3615272026-08-27 09:15:49.160 UTC [1551] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15282026/08/27 09:15:49 WARN Failed to register uploaded object key=kx8657zgxy349dljp17hjmabpfimfima.ls error="server returned 404: 404 page not found\n"15292026/08/27 09:15:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15302026/08/27 09:15:49 INFO Signed narinfos id=1 count=115312026/08/27 09:15:49 INFO Uploading 1 narinfos15322026-08-27 09:15:49.162 UTC [1553] ERROR: relation "goose_db_version" does not exist at character 3615332026-08-27 09:15:49.162 UTC [1553] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15342026/08/27 09:15:49 WARN Failed to register uploaded object key=kx8657zgxy349dljp17hjmabpfimfima.narinfo error="server returned 404: 404 page not found\n"15352026/08/27 09:15:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15362026-08-27 09:15:49.165 UTC [1569] ERROR: relation "goose_db_version" does not exist at character 3615372026-08-27 09:15:49.165 UTC [1569] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15382026/08/27 09:15:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15392026/08/27 09:15:49 INFO Uploading 08g5isdgks5i5a90ryf04r6bpvqpv0ik-test-file.txt (152B)1540=== NAME TestClientCADerivations1541 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations3590589561/001/store/hgf9p70fps4caksc0il4a5ca436ac8bm-ca-test15422026/08/27 09:15:49 INFO Completed upload id=115432026/08/27 09:15:49 INFO Upload complete. (95ms)15442026/08/27 09:15:49 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"15452026/08/27 09:15:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15462026/08/27 09:15:49 INFO Uploading arfm7fkm9k5nab5zjlx5wd9m2iy8ny7h-test-script (136B)15472026/08/27 09:15:49 WARN Failed to register uploaded object key=08g5isdgks5i5a90ryf04r6bpvqpv0ik.ls error="server returned 404: 404 page not found\n"15482026/08/27 09:15:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15492026/08/27 09:15:49 INFO Received uploads request method=POST path=/api/pending_closures15502026/08/27 09:15:49 INFO Signed narinfos id=1 count=115512026/08/27 09:15:49 INFO Uploading 1 narinfos15522026/08/27 09:15:49 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"15532026/08/27 09:15:49 WARN Failed to register uploaded object key=log/ff97zvp3vvj2f6mrn20801jwrjhx0b2f-test-script.drv error="server returned 404: 404 page not found\n"15542026/08/27 09:15:49 OK 20241026095416_initial_model.sql (9.09ms)15552026/08/27 09:15:49 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)15562026/08/27 09:15:49 OK 20241026095416_initial_model.sql (9.21ms)15572026/08/27 09:15:49 OK 20251210153512_drop_unused_gin_index.sql (1.81ms)15582026/08/27 09:15:49 WARN Failed to register uploaded object key=arfm7fkm9k5nab5zjlx5wd9m2iy8ny7h.ls error="server returned 404: 404 page not found\n"15592026/08/27 09:15:49 WARN Failed to register uploaded object key=08g5isdgks5i5a90ryf04r6bpvqpv0ik.narinfo error="server returned 404: 404 page not found\n"15602026/08/27 09:15:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15612026/08/27 09:15:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15622026/08/27 09:15:49 OK 20251210153512_drop_unused_gin_index.sql (2.17ms)15632026/08/27 09:15:49 INFO Signed narinfos id=1 count=115642026/08/27 09:15:49 WARN Failed to register uploaded object key=zbpwrsyc145438g4s146pjvbvkbc2wzz.ls error="server returned 404: 404 page not found\n"15652026/08/27 09:15:49 INFO Uploading 1 narinfos15662026/08/27 09:15:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15672026/08/27 09:15:49 INFO Signed narinfos id=2 count=115682026/08/27 09:15:49 INFO Uploading 1 narinfos15692026/08/27 09:15:49 OK 20251218171726_add_pins.sql (3.11ms)15702026/08/27 09:15:49 OK 20241026095416_initial_model.sql (8.41ms)15712026/08/27 09:15:49 OK 20251218171726_add_pins.sql (3ms)15722026/08/27 09:15:49 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"15732026/08/27 09:15:49 OK 20251210153512_drop_unused_gin_index.sql (1.66ms)15742026/08/27 09:15:49 INFO Completed upload id=115752026/08/27 09:15:49 INFO Upload complete. (93ms)15762026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (4.03ms)15772026/08/27 09:15:49 goose: successfully migrated database to version: 202606281200001578=== NAME TestClientIntegration15792026/08/27 09:15:49 OK 20251218171726_add_pins.sql (2.54ms)1580 client_integration_test.go:292: Retrieved narinfo from S3:1581 StorePath: /build/TestClientIntegration3887427590/002/store/08g5isdgks5i5a90ryf04r6bpvqpv0ik-test-file.txt15822026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (3.39ms)1583 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst15842026/08/27 09:15:49 goose: successfully migrated database to version: 202606281200001585 Compression: zstd1586 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11587 NarSize: 1521588 References: 1589 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk115902026/08/27 09:15:49 WARN Failed to register uploaded object key=zbpwrsyc145438g4s146pjvbvkbc2wzz.narinfo error="server returned 404: 404 page not found\n"15912026/08/27 09:15:49 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15922026/08/27 09:15:49 WARN Failed to register uploaded object key=arfm7fkm9k5nab5zjlx5wd9m2iy8ny7h.narinfo error="server returned 404: 404 page not found\n"15932026/08/27 09:15:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15942026/08/27 09:15:49 OK 1_commit_pending_closure.sql (2.2ms)15952026/08/27 09:15:49 OK 1_commit_pending_closure.sql (1.89ms)1596 client_integration_test.go:293: Retrieved .ls file from S3 (compressed size: 77 bytes)1597 client_integration_test.go:293: Decompressed .ls content (64 bytes):1598 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1599 client_integration_test.go:296: Testing garbage collection...16002026/08/27 09:15:49 OK 2_object_stats_trigger.sql (1.41ms)16012026/08/27 09:15:49 goose: up to current file version: 216022026/08/27 09:15:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16032026/08/27 09:15:49 INFO Completed upload id=216042026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (3.1ms)16052026/08/27 09:15:49 goose: successfully migrated database to version: 2026062812000016062026/08/27 09:15:49 INFO Upload complete. (80ms)16072026/08/27 09:15:49 OK 2_object_stats_trigger.sql (1.63ms)16082026/08/27 09:15:49 goose: up to current file version: 21609=== NAME TestNARDeduplicationMetadataUploadBug1610 metadata_upload_test.go:76: Retrieved narinfo from S3:1611 StorePath: /build/TestNARDeduplicationMetadataUploadBug2009780148/001/store/zbpwrsyc145438g4s146pjvbvkbc2wzz-file2.txt1612 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1613 Compression: zstd1614 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1615 NarSize: 1601616 References: 1617 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf16182026/08/27 09:15:49 OK 1_commit_pending_closure.sql (2.34ms)16192026/08/27 09:15:49 OK 2_object_stats_trigger.sql (775.98µs)16202026/08/27 09:15:49 goose: up to current file version: 21621 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1622 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1623 {"version":1,"root":{"type":"regular","size":44}}1624--- PASS: TestNARDeduplicationMetadataUploadBug (0.98s)1625=== NAME TestClientCADerivations1626 client_ca_test.go:139: Found 1 dependencies (including self)16272026/08/27 09:15:49 INFO Completed upload id=116282026/08/27 09:15:49 INFO Upload complete. (83ms)1629=== NAME TestClientWithDependencies1630 client_integration_test.go:597: Skipping nix copy test - isolated store (/build/TestClientWithDependencies2024406373/001/store) requires matching store prefix16312026/08/27 09:15:49 INFO Received uploads request method=POST path=/api/pending_closures16322026/08/27 09:15:49 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NWFkOWI5NzYtZTg4NS00YjFlLWEwOGQtMTA5Nzc3YjNkNTQxLmY0MjFkY2U3LTQwMjYtNDZmMS04N2UzLTk1Y2JlMzEyNjA3NngxNzg3ODIyMTQ4ODA3OTQ0NTk0 parts=1016332026/08/27 09:15:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1634--- PASS: TestClientWithDependencies (0.44s)16352026/08/27 09:15:49 INFO Completed upload id=116362026/08/27 09:15:49 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000016372026/08/27 09:15:49 INFO Starting cleanup of old closures method=DELETE path=/api/closures16382026/08/27 09:15:49 INFO Received uploads request method=POST path=/api/pending_closures16392026/08/27 09:15:49 INFO Garbage collection started1640--- PASS: TestResurrectedObjectNotDeleted (0.24s)16412026-08-27 09:15:49.220 UTC [1716] ERROR: relation "goose_db_version" does not exist at character 3616422026-08-27 09:15:49.220 UTC [1716] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16432026/08/27 09:15:49 INFO Starting cleanup of old closures method=DELETE path=/api/closures1644--- PASS: TestObjectStatsTrigger (0.18s)16452026/08/27 09:15:49 INFO Received uploads request method=POST path=/api/pending_closures16462026/08/27 09:15:49 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16472026/08/27 09:15:49 INFO Aborted multipart uploads count=016482026/08/27 09:15:49 OK 20241026095416_initial_model.sql (7.05ms)16492026/08/27 09:15:49 INFO Aborted multipart uploads count=016502026/08/27 09:15:49 OK 20251210153512_drop_unused_gin_index.sql (976.18µs)16512026/08/27 09:15:49 INFO Received uploads request method=POST path=/api/pending_closures1652--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.20s)16532026/08/27 09:15:49 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-config16542026/08/27 09:15:49 OK 20251218171726_add_pins.sql (2.41ms)16552026/08/27 09:15:49 INFO Received uploads request method=POST path=/api/pending_closures16562026/08/27 09:15:49 WARN Force mode enabled - objects will be deleted immediately without grace period16572026/08/27 09:15:49 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16582026/08/27 09:15:49 INFO Uploading pkjwdlqchp7ddv094vp5fcf22jcnzm5j-test-file-2.txt (160B)16592026/08/27 09:15:49 INFO Uploading vl9nkz5n7m17mfflh22z2nd5nrwl4nw6-test-file-0.txt (160B)16602026/08/27 09:15:49 INFO Uploading jpk67q3ql1fshmgjgjsvlmsc4047hcd8-test-file-1.txt (160B)16612026-08-27 09:15:49.239 UTC [1756] ERROR: relation "goose_db_version" does not exist at character 3616622026-08-27 09:15:49.239 UTC [1756] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16632026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (2.79ms)16642026/08/27 09:15:49 goose: successfully migrated database to version: 2026062812000016652026/08/27 09:15:49 OK 1_commit_pending_closure.sql (1.63ms)16662026/08/27 09:15:49 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=016672026/08/27 09:15:49 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16682026/08/27 09:15:49 OK 2_object_stats_trigger.sql (1.17ms)16692026/08/27 09:15:49 goose: up to current file version: 216702026/08/27 09:15:49 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"16712026/08/27 09:15:49 WARN Failed to register uploaded object key=pkjwdlqchp7ddv094vp5fcf22jcnzm5j.ls error="server returned 404: 404 page not found\n"16722026/08/27 09:15:49 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16732026/08/27 09:15:49 INFO Vacuumed table table=pending_closures16742026/08/27 09:15:49 WARN Failed to register uploaded object key=jpk67q3ql1fshmgjgjsvlmsc4047hcd8.ls error="server returned 404: 404 page not found\n"16752026/08/27 09:15:49 WARN Failed to register uploaded object key=vl9nkz5n7m17mfflh22z2nd5nrwl4nw6.ls error="server returned 404: 404 page not found\n"16762026/08/27 09:15:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16772026/08/27 09:15:49 INFO Vacuumed table table=pending_objects16782026/08/27 09:15:49 INFO Signed narinfos id=1 count=116792026/08/27 09:15:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16802026/08/27 09:15:49 INFO Signed narinfos id=2 count=116812026/08/27 09:15:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign16822026/08/27 09:15:49 INFO Vacuumed table table=multipart_uploads16832026/08/27 09:15:49 INFO Signed narinfos id=3 count=116842026/08/27 09:15:49 INFO Uploading 3 narinfos16852026/08/27 09:15:49 INFO Vacuumed table table=closures16862026/08/27 09:15:49 WARN Failed to register uploaded object key=jpk67q3ql1fshmgjgjsvlmsc4047hcd8.narinfo error="server returned 404: 404 page not found\n"16872026/08/27 09:15:49 WARN Failed to register uploaded object key=vl9nkz5n7m17mfflh22z2nd5nrwl4nw6.narinfo error="server returned 404: 404 page not found\n"16882026/08/27 09:15:49 INFO Vacuumed table table=objects16892026/08/27 09:15:49 WARN Failed to register uploaded object key=pkjwdlqchp7ddv094vp5fcf22jcnzm5j.narinfo error="server returned 404: 404 page not found\n"16902026/08/27 09:15:49 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete16912026/08/27 09:15:49 INFO Completed upload id=316922026/08/27 09:15:49 INFO Received uploads request method=POST path=/api/pending_closures16932026/08/27 09:15:49 OK 20241026095416_initial_model.sql (14.25ms)16942026/08/27 09:15:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16952026/08/27 09:15:49 OK 20251210153512_drop_unused_gin_index.sql (1.38ms)16962026/08/27 09:15:49 INFO Completed upload id=116972026/08/27 09:15:49 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16982026/08/27 09:15:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16992026/08/27 09:15:49 INFO Uploading 726q7yxi614nqyy75p199vm5qbcngad5-unpinned-file.txt (128B)17002026/08/27 09:15:49 INFO Completed upload id=217012026/08/27 09:15:49 INFO Upload complete. (116ms)1702=== NAME TestClientMultipleUploads1703 client_integration_test.go:349: Uploaded 3 paths in 147.007878ms17042026/08/27 09:15:49 OK 20251218171726_add_pins.sql (3.29ms)17052026/08/27 09:15:49 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"17062026/08/27 09:15:49 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17072026/08/27 09:15:49 WARN Failed to register uploaded object key=726q7yxi614nqyy75p199vm5qbcngad5.ls error="server returned 404: 404 page not found\n"17082026/08/27 09:15:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign17092026/08/27 09:15:49 OK 20260628120000_add_object_size_and_stats.sql (4.3ms)17102026/08/27 09:15:49 goose: successfully migrated database to version: 2026062812000017112026/08/27 09:15:49 INFO Signed narinfos id=2 count=117122026/08/27 09:15:49 INFO Uploading 1 narinfos17132026/08/27 09:15:49 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001714--- PASS: TestService_createPendingClosureHandler (1.06s)17152026/08/27 09:15:49 OK 1_commit_pending_closure.sql (2.26ms)1716--- PASS: TestClientMultipleUploads (0.49s)17172026/08/27 09:15:49 WARN Failed to register uploaded object key=726q7yxi614nqyy75p199vm5qbcngad5.narinfo error="server returned 404: 404 page not found\n"17182026/08/27 09:15:49 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17192026/08/27 09:15:49 OK 2_object_stats_trigger.sql (1.06ms)17202026/08/27 09:15:49 goose: up to current file version: 217212026/08/27 09:15:49 INFO Completed upload id=217222026/08/27 09:15:49 INFO Upload complete. (77ms)17232026/08/27 09:15:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17242026/08/27 09:15:49 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NWFkOWI5NzYtZTg4NS00YjFlLWEwOGQtMTA5Nzc3YjNkNTQxLmQyMGMxMGZjLWVhMjQtNDI3Zi1iMzJkLTBiMDdkNjVjZmZmMXgxNzg3ODIyMTQ4ODk0NTQ1NTA1 parts=1017252026/08/27 09:15:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17262026/08/27 09:15:49 INFO Received uploads request method=POST path=/api/pending_closures17272026/08/27 09:15:49 INFO Completed upload id=117282026/08/27 09:15:49 INFO Received uploads request method=POST path=/api/pending_closures17292026/08/27 09:15:49 INFO Received uploads request method=POST path=/api/pending_closures17302026/08/27 09:15:49 INFO Received create pin request method=POST path=/api/pins/myapp17312026/08/27 09:15:49 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo17322026/08/27 09:15:49 WARN Found objects in DB but missing from S3, will re-upload count=117332026/08/27 09:15:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17342026/08/27 09:15:49 INFO Uploading hgf9p70fps4caksc0il4a5ca436ac8bm-ca-test (144B)1735--- PASS: TestService_verifyS3Integrity (1.10s)17362026/08/27 09:15:49 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2011157473/001/store/kx8657zgxy349dljp17hjmabpfimfima-pinned-file.txt narinfo_key=kx8657zgxy349dljp17hjmabpfimfima.narinfo17372026/08/27 09:15:49 INFO Starting cleanup of old closures method=DELETE path=/api/closures17382026/08/27 09:15:49 INFO Garbage collection started17392026/08/27 09:15:49 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"17402026/08/27 09:15:49 WARN Failed to register uploaded object key=log/d2wxl39hp1jip277jqb6c24nr09lfjp5-ca-test.drv error="server returned 404: 404 page not found\n"17412026/08/27 09:15:49 WARN Failed to register uploaded object key=hgf9p70fps4caksc0il4a5ca436ac8bm.ls error="server returned 404: 404 page not found\n"17422026/08/27 09:15:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17432026/08/27 09:15:49 INFO Signed narinfos id=1 count=117442026/08/27 09:15:49 INFO Uploading 1 narinfos17452026/08/27 09:15:49 WARN Failed to register uploaded object key=hgf9p70fps4caksc0il4a5ca436ac8bm.narinfo error="server returned 404: 404 page not found\n"17462026/08/27 09:15:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17472026/08/27 09:15:49 INFO Received cleanup request method=DELETE path=/api/pending_closures17482026/08/27 09:15:49 INFO Aborted multipart uploads count=017492026/08/27 09:15:49 INFO Aborted multipart uploads count=117502026/08/27 09:15:49 WARN Force mode enabled - objects will be deleted immediately without grace period17512026/08/27 09:15:49 INFO Completed upload id=117522026/08/27 09:15:49 INFO Upload complete. (92ms)1753--- PASS: TestMultipartCleanup (0.28s)1754=== NAME TestClientCADerivations1755 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations3590589561/001/store/hgf9p70fps4caksc0il4a5ca436ac8bm-ca-test1756 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1757 Compression: zstd1758 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1759 NarSize: 1441760 References: 1761 Deriver: /build/TestClientCADerivations3590589561/001/store/d2wxl39hp1jip277jqb6c24nr09lfjp5-ca-test.drv1762 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1763 client_ca_test.go:185: Checking for realisation files in S3...1764 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1765 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache17662026/08/27 09:15:49 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=193.561572ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17672026/08/27 09:15:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17682026/08/27 09:15:49 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17692026/08/27 09:15:49 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NWFkOWI5NzYtZTg4NS00YjFlLWEwOGQtMTA5Nzc3YjNkNTQxLjU0MGExYmRmLWZhZjEtNDg1ZS04ZDFjLTU1NWQ1M2FiNjE5YngxNzg3ODIyMTQ4OTAyOTM3Mzg2 parts=121770--- PASS: TestRedundantMultipartUpload (1.18s)1771=== NAME TestOrphanedObjectsGC1772 orphaned_objects_gc_test.go:290: GC Test Summary:1773 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1774 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1775 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1776 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1777 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1778--- PASS: TestOrphanedObjectsGC (0.46s)17792026/08/27 09:15:49 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"17802026/08/27 09:15:49 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=017812026/08/27 09:15:49 INFO Vacuumed table table=pending_closures17822026/08/27 09:15:49 INFO Vacuumed table table=pending_objects17832026/08/27 09:15:49 INFO Vacuumed table table=multipart_uploads17842026/08/27 09:15:49 INFO Vacuumed table table=closures17852026/08/27 09:15:49 INFO Vacuumed table table=objects1786=== NAME TestClientCADerivations1787 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1788 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1789 error: binary cache 's3://bucket35?endpoint=http://localhost:37653®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations3590589561/001/store'1790 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11791--- PASS: TestClientCADerivations (0.61s)17922026/08/27 09:15:49 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=409.306303ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17932026/08/27 09:15:49 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=017942026/08/27 09:15:49 INFO Vacuumed table table=pending_closures17952026/08/27 09:15:49 INFO Vacuumed table table=pending_objects17962026/08/27 09:15:49 INFO Vacuumed table table=multipart_uploads17972026/08/27 09:15:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17982026/08/27 09:15:49 INFO Vacuumed table table=closures17992026/08/27 09:15:49 INFO Vacuumed table table=objects18002026/08/27 09:15:49 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NWFkOWI5NzYtZTg4NS00YjFlLWEwOGQtMTA5Nzc3YjNkNTQxLmUyZmUwYTVhLTg4ZDctNDI3MS1iOWI1LTA4Zjg1N2IwYzgxOHgxNzg3ODIyMTQ5MDg2MDE2MjMw parts=1218012026/08/27 09:15:49 INFO Received uploads request method=POST path=/api/pending_closures1802--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.38s)1803--- PASS: TestUploadHandlersRejectOversizedBody (0.30s)1804 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.07s)1805 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.06s)1806 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.66s)18072026/08/27 09:15:49 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=791.910121ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1808=== NAME TestOrphanedObjectsGCStressTest1809 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1810 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion1811 orphaned_objects_gc_test.go:509: Stress test completed successfully:1812 orphaned_objects_gc_test.go:510: - Active objects preserved: 201813 orphaned_objects_gc_test.go:511: - Objects deleted: 2101814 orphaned_objects_gc_test.go:512: - Total GC'd: 2101815--- PASS: TestOrphanedObjectsGCStressTest (1.51s)18162026/08/27 09:15:50 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.673154886s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config18172026/08/27 09:15:51 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01818=== NAME TestClientIntegration1819 client_integration_test.go:303: Objects in database after GC:1820 client_integration_test.go:303: Successfully deleted all objects with GC --force1821--- PASS: TestClientIntegration (2.41s)18222026/08/27 09:15:51 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01823=== NAME TestPinProtectsFromGC1824 client_integration_test.go:709: Pin successfully protected closure from garbage collection1825--- PASS: TestPinProtectsFromGC (2.56s)18262026/08/27 09:15:52 WARN Rate limiter enabled after throttle name=s3-test rate=518272026/08/27 09:15:52 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1828=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1829 throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=101830 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001831--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.07s)18322026/08/27 09:15:52 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"18332026/08/27 09:15:52 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_closures18342026/08/27 09:15:52 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=183.644046ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures18352026/08/27 09:15:52 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=422.450477ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures18362026/08/27 09:15:53 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=834.039139ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures18372026/08/27 09:15:53 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.442864472s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1838--- PASS: TestClientErrorHandling (0.00s)1839 --- PASS: TestClientErrorHandling/InvalidStorePath (0.17s)1840 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.28s)1841 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.32s)1842PASS1843{"timestamp":"2026-08-27T09:15:55.448229428Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:35408","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(438)"}18442026-08-27 09:15:55.660 UTC [112] LOG: received smart shutdown request18452026-08-27 09:15:55.664 UTC [112] LOG: background worker "logical replication launcher" (PID 122) exited with exit code 118462026-08-27 09:15:55.673 UTC [117] LOG: shutting down18472026-08-27 09:15:55.674 UTC [117] LOG: checkpoint starting: shutdown immediate18482026-08-27 09:15:57.240 UTC [117] LOG: checkpoint complete: wrote 11533 buffers (70.4%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 13 recycled; write=0.264 s, sync=1.290 s, total=1.567 s; sync files=15167, longest=0.004 s, average=0.001 s; distance=208933 kB, estimate=208933 kB; lsn=0/E36D308, redo lsn=0/E36D30818492026-08-27 09:15:57.328 UTC [112] LOG: database system is shut down1850Running OIDC tests...1851=== RUN TestGlobMatch1852=== PAUSE TestGlobMatch1853=== RUN TestAudienceForIssuer1854=== PAUSE TestAudienceForIssuer1855=== RUN TestValidateToken_ValidToken1856=== PAUSE TestValidateToken_ValidToken1857=== RUN TestValidateToken_WrongAudience1858=== PAUSE TestValidateToken_WrongAudience1859=== RUN TestValidateToken_Expired1860=== PAUSE TestValidateToken_Expired1861=== RUN TestValidateToken_BoundClaimsMismatch1862=== PAUSE TestValidateToken_BoundClaimsMismatch1863=== RUN TestValidateToken_BoundSubjectMismatch1864=== PAUSE TestValidateToken_BoundSubjectMismatch1865=== RUN TestValidateToken_MultipleProviders1866=== PAUSE TestValidateToken_MultipleProviders1867=== RUN TestValidateToken_NoMatchingProvider1868=== PAUSE TestValidateToken_NoMatchingProvider1869=== CONT TestGlobMatch1870=== RUN TestGlobMatch/foo_foo1871=== PAUSE TestGlobMatch/foo_foo1872=== CONT TestAudienceForIssuer1873--- PASS: TestAudienceForIssuer (0.00s)1874=== RUN TestGlobMatch/foo_bar1875=== CONT TestValidateToken_ValidToken1876=== PAUSE TestGlobMatch/foo_bar1877=== CONT TestValidateToken_WrongAudience1878=== CONT TestValidateToken_MultipleProviders1879=== CONT TestValidateToken_NoMatchingProvider1880=== CONT TestValidateToken_BoundSubjectMismatch1881=== CONT TestValidateToken_BoundClaimsMismatch1882=== CONT TestValidateToken_Expired1883=== RUN TestGlobMatch/*_1884=== PAUSE TestGlobMatch/*_1885=== RUN TestGlobMatch/*_anything1886=== PAUSE TestGlobMatch/*_anything1887=== RUN TestGlobMatch/foo*_foo1888=== PAUSE TestGlobMatch/foo*_foo1889=== RUN TestGlobMatch/foo*_foobar1890=== PAUSE TestGlobMatch/foo*_foobar1891=== RUN TestGlobMatch/foo*_bar1892=== PAUSE TestGlobMatch/foo*_bar1893=== RUN TestGlobMatch/*bar_bar1894=== PAUSE TestGlobMatch/*bar_bar1895=== RUN TestGlobMatch/*bar_foobar1896=== PAUSE TestGlobMatch/*bar_foobar1897=== RUN TestGlobMatch/*bar_foo1898=== PAUSE TestGlobMatch/*bar_foo1899=== RUN TestGlobMatch/foo*bar_foobar1900=== PAUSE TestGlobMatch/foo*bar_foobar1901=== RUN TestGlobMatch/foo*bar_foo123bar1902=== PAUSE TestGlobMatch/foo*bar_foo123bar1903=== RUN TestGlobMatch/foo*bar_foobarbaz1904=== PAUSE TestGlobMatch/foo*bar_foobarbaz1905=== RUN TestGlobMatch/*/*_foo/bar1906=== PAUSE TestGlobMatch/*/*_foo/bar1907=== RUN TestGlobMatch/*/*_foo1908=== PAUSE TestGlobMatch/*/*_foo1909=== RUN TestGlobMatch/refs/heads/*_refs/heads/main1910=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main1911=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.01912=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.01913=== RUN TestGlobMatch/refs/*/main_refs/heads/main1914=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main1915=== RUN TestGlobMatch/fo?_foo1916=== PAUSE TestGlobMatch/fo?_foo1917=== RUN TestGlobMatch/fo?_fo1918=== PAUSE TestGlobMatch/fo?_fo1919=== RUN TestGlobMatch/fo?_fooo1920=== PAUSE TestGlobMatch/fo?_fooo1921=== RUN TestGlobMatch/?oo_foo1922=== PAUSE TestGlobMatch/?oo_foo1923=== RUN TestGlobMatch/?oo_boo1924=== PAUSE TestGlobMatch/?oo_boo1925=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1926=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1927=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1928=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1929=== CONT TestGlobMatch/foo_foo1930=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1931=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1932=== CONT TestGlobMatch/foo*bar_foo123bar1933=== CONT TestGlobMatch/foo*bar_foobar1934=== CONT TestGlobMatch/fo?_fooo1935=== CONT TestGlobMatch/*/*_foo1936=== CONT TestGlobMatch/refs/*/main_refs/heads/main1937=== CONT TestGlobMatch/fo?_foo1938=== CONT TestGlobMatch/*bar_foo1939=== CONT TestGlobMatch/foo_bar1940=== CONT TestGlobMatch/refs/heads/*_refs/heads/main1941=== CONT TestGlobMatch/fo?_fo1942=== CONT TestGlobMatch/*/*_foo/bar1943=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.01944=== CONT TestGlobMatch/foo*_foobar1945=== CONT TestGlobMatch/*_anything1946=== CONT TestGlobMatch/foo*_bar1947=== CONT TestGlobMatch/*bar_bar1948=== CONT TestGlobMatch/foo*_foo1949=== CONT TestGlobMatch/*bar_foobar1950=== CONT TestGlobMatch/*_1951=== CONT TestGlobMatch/?oo_boo1952=== CONT TestGlobMatch/foo*bar_foobarbaz1953=== CONT TestGlobMatch/?oo_foo1954--- PASS: TestGlobMatch (0.00s)1955 --- PASS: TestGlobMatch/foo_foo (0.00s)1956 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)1957 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)1958 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)1959 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)1960 --- PASS: TestGlobMatch/fo?_fooo (0.00s)1961 --- PASS: TestGlobMatch/*/*_foo (0.00s)1962 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)1963 --- PASS: TestGlobMatch/fo?_foo (0.00s)1964 --- PASS: TestGlobMatch/*bar_foo (0.00s)1965 --- PASS: TestGlobMatch/foo_bar (0.00s)1966 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)1967 --- PASS: TestGlobMatch/fo?_fo (0.00s)1968 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)1969 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)1970 --- PASS: TestGlobMatch/foo*_foobar (0.00s)1971 --- PASS: TestGlobMatch/*_anything (0.00s)1972 --- PASS: TestGlobMatch/foo*_bar (0.00s)1973 --- PASS: TestGlobMatch/*bar_bar (0.00s)1974 --- PASS: TestGlobMatch/foo*_foo (0.00s)1975 --- PASS: TestGlobMatch/*bar_foobar (0.00s)1976 --- PASS: TestGlobMatch/*_ (0.00s)1977 --- PASS: TestGlobMatch/?oo_boo (0.00s)1978 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)1979 --- PASS: TestGlobMatch/?oo_foo (0.00s)19802026/08/27 09:15:58 INFO OIDC provider initialized name=provider119812026/08/27 09:15:58 INFO OIDC provider initialized name=test19822026/08/27 09:15:58 INFO OIDC provider initialized name=provider119832026/08/27 09:15:58 INFO OIDC provider initialized name=test19842026/08/27 09:15:58 INFO OIDC provider initialized name=test19852026/08/27 09:15:58 INFO OIDC provider initialized name=test19862026/08/27 09:15:58 INFO OIDC provider initialized name=test19872026/08/27 09:15:58 INFO OIDC provider initialized name=provider21988--- PASS: TestValidateToken_Expired (0.01s)1989--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)1990--- PASS: TestValidateToken_WrongAudience (0.01s)1991--- PASS: TestValidateToken_NoMatchingProvider (0.01s)1992--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)1993--- PASS: TestValidateToken_ValidToken (0.01s)1994--- PASS: TestValidateToken_MultipleProviders (0.01s)1995PASS1996Running hook tests...1997=== RUN TestSendPathsEmpty1998=== PAUSE TestSendPathsEmpty1999=== RUN TestQueueEnqueueAndFetch2000=== PAUSE TestQueueEnqueueAndFetch2001=== RUN TestQueueDeduplication2002=== PAUSE TestQueueDeduplication2003=== RUN TestQueueRemove2004=== PAUSE TestQueueRemove2005=== RUN TestQueueFetchBatchLimit2006=== PAUSE TestQueueFetchBatchLimit2007=== RUN TestQueueRetryMovesToBack2008=== PAUSE TestQueueRetryMovesToBack2009=== RUN TestQueueFetchRemoveLifecycle2010=== PAUSE TestQueueFetchRemoveLifecycle2011=== RUN TestQueueConcurrentWriters2012=== PAUSE TestQueueConcurrentWriters2013=== RUN TestServerClientIntegration2014=== PAUSE TestServerClientIntegration2015=== RUN TestServerQueueError2016=== PAUSE TestServerQueueError2017=== RUN TestGetListenerSocketActivation2018 server_test.go:210: === RUN TestGetListenerSocketActivation2019 --- PASS: TestGetListenerSocketActivation (0.00s)2020 PASS2021 2022--- PASS: TestGetListenerSocketActivation (0.01s)2023=== RUN TestDrainIsolatesPoisonPath2024=== PAUSE TestDrainIsolatesPoisonPath2025=== RUN TestRunNotBlockedByPoisonHead2026=== PAUSE TestRunNotBlockedByPoisonHead2027=== RUN TestDrainGivesUpWhenServerDown2028=== PAUSE TestDrainGivesUpWhenServerDown2029=== RUN TestFailedPathPrunedByLaterClosure2030=== PAUSE TestFailedPathPrunedByLaterClosure2031=== RUN TestWorkerUploadsAndRemoves2032=== PAUSE TestWorkerUploadsAndRemoves2033=== RUN TestWorkerSkipsGCdPaths2034=== PAUSE TestWorkerSkipsGCdPaths2035=== RUN TestWorkerPrunesClosureDeps2036=== PAUSE TestWorkerPrunesClosureDeps2037=== CONT TestSendPathsEmpty2038=== CONT TestServerQueueError2039=== CONT TestWorkerSkipsGCdPaths2040--- PASS: TestSendPathsEmpty (0.00s)2041=== CONT TestServerClientIntegration2042=== CONT TestFailedPathPrunedByLaterClosure2043=== CONT TestQueueConcurrentWriters2044=== CONT TestQueueFetchRemoveLifecycle2045=== CONT TestQueueRetryMovesToBack2046=== CONT TestQueueFetchBatchLimit2047=== CONT TestQueueRemove2048=== CONT TestWorkerUploadsAndRemoves2049=== CONT TestQueueDeduplication2050=== CONT TestQueueEnqueueAndFetch2051=== CONT TestWorkerPrunesClosureDeps20522026/08/27 09:15:58 ERROR Failed to queue paths error="permission denied" count=12053=== CONT TestRunNotBlockedByPoisonHead2054=== CONT TestDrainIsolatesPoisonPath2055=== CONT TestDrainGivesUpWhenServerDown2056--- PASS: TestServerClientIntegration (0.00s)2057--- PASS: TestServerQueueError (0.00s)20582026/08/27 09:15:58 INFO Uploading batch count=420592026/08/27 09:15:58 ERROR Upload failed error="upload failed" count=420602026/08/27 09:15:58 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath1754050260/002/bbb20612026/08/27 09:15:58 INFO Uploading batch count=120622026/08/27 09:15:58 ERROR Upload failed error="upload failed" count=120632026/08/27 09:15:58 INFO Upload queue status pending=32064--- PASS: TestQueueFetchBatchLimit (0.02s)20652026/08/27 09:15:58 INFO Upload queue status pending=220662026/08/27 09:15:58 INFO Uploading batch count=120672026/08/27 09:15:58 ERROR Upload failed error="upload failed" count=120682026/08/27 09:15:58 INFO Upload queue status pending=220692026/08/27 09:15:58 INFO Uploading batch count=220702026/08/27 09:15:58 ERROR Upload failed error="upload failed" count=220712026/08/27 09:15:58 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1282180039/002/a20722026/08/27 09:15:58 INFO Upload queue status pending=220732026/08/27 09:15:58 INFO Uploading batch count=220742026/08/27 09:15:58 INFO Uploading batch count=120752026/08/27 09:15:58 INFO Uploading batch count=12076--- PASS: TestQueueEnqueueAndFetch (0.02s)20772026/08/27 09:15:58 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths916268451/002/nonexistent2078--- PASS: TestQueueDeduplication (0.02s)20792026/08/27 09:15:58 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1282180039/002/b20802026/08/27 09:15:58 INFO Uploading batch count=12081--- PASS: TestQueueFetchRemoveLifecycle (0.02s)2082--- PASS: TestQueueRetryMovesToBack (0.02s)2083--- PASS: TestQueueRemove (0.02s)20842026/08/27 09:15:58 INFO Uploading batch count=220852026/08/27 09:15:58 ERROR Upload failed error="upload failed" count=220862026/08/27 09:15:58 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1282180039/002/c20872026/08/27 09:15:58 INFO Uploading batch count=120882026/08/27 09:15:58 ERROR Upload failed error="upload failed" count=120892026/08/27 09:15:58 INFO Uploading batch count=120902026/08/27 09:15:58 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1282180039/002/d20912026/08/27 09:15:58 INFO Uploading batch count=120922026/08/27 09:15:58 ERROR Upload failed error="upload failed" count=120932026/08/27 09:15:58 INFO Uploading batch count=220942026/08/27 09:15:58 ERROR Upload failed error="upload failed" count=220952026/08/27 09:15:58 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1282180039/002/e20962026/08/27 09:15:58 INFO Uploading batch count=120972026/08/27 09:15:58 ERROR Upload failed error="upload failed" count=12098--- PASS: TestFailedPathPrunedByLaterClosure (0.03s)20992026/08/27 09:15:58 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1282180039/002/f21002026/08/27 09:15:58 ERROR Drain finished with paths left in queue remaining=121012026/08/27 09:15:58 ERROR Drain finished with paths left in queue remaining=102102--- PASS: TestDrainIsolatesPoisonPath (0.03s)2103--- PASS: TestDrainGivesUpWhenServerDown (0.03s)2104--- PASS: TestWorkerPrunesClosureDeps (0.04s)2105--- PASS: TestWorkerSkipsGCdPaths (0.04s)2106--- PASS: TestWorkerUploadsAndRemoves (0.04s)2107--- PASS: TestQueueConcurrentWriters (0.28s)21082026/08/27 09:15:59 INFO Uploading batch count=121092026/08/27 09:15:59 INFO Uploading batch count=121102026/08/27 09:15:59 INFO Uploading batch count=121112026/08/27 09:15:59 ERROR Upload failed error="upload failed" count=121122026/08/27 09:15:59 INFO Uploading batch count=121132026/08/27 09:15:59 ERROR Upload failed error="upload failed" count=121142026/08/27 09:15:59 INFO Uploading batch count=121152026/08/27 09:15:59 ERROR Upload failed error="upload failed" count=121162026/08/27 09:15:59 INFO Uploading batch count=121172026/08/27 09:15:59 ERROR Upload failed error="upload failed" count=121182026/08/27 09:15:59 ERROR Drain finished with paths left in queue remaining=12119--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2120PASS