niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #154
· raw
1tribuchet: building on eliza2Running 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 TestEncodeNixBase32WithRealHash75=== CONT TestResolveStorePath76--- PASS: TestEncodeNixBase32WithRealHash (0.00s)77=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess78=== CONT TestRateLimiterFeedback79=== CONT TestFileTokenMissing80=== RUN TestRateLimiterFeedback/429_enables_limiter81=== PAUSE TestRateLimiterFeedback/429_enables_limiter82=== RUN TestRateLimiterFeedback/503_enables_limiter83=== CONT TestPathInfoCACompatibility84=== RUN TestPathInfoCACompatibility/null_ca_field85=== PAUSE TestPathInfoCACompatibility/null_ca_field86=== RUN TestPathInfoCACompatibility/old_string_format_-_text87=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text88=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive89=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive90=== RUN TestPathInfoCACompatibility/new_structured_format_-_text91=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text92=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method93=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method94=== CONT TestParsePathInfoJSONMultiplePaths952026/08/27 09:58:10 WARN Rate limiter enabled after throttle name=server-test rate=596=== CONT TestParsePathInfoJSON97=== RUN TestParsePathInfoJSON/Nix_format98=== CONT TestPathInfoHashCompatibility99=== CONT TestGetStorePathHash100=== CONT TestConvertHashToNix32101=== CONT TestSetClientTLSDoesNotMutateDefaultTransport102=== CONT TestFileTokenReadsAndCaches103=== RUN TestConvertHashToNix32/SRI_format_to_Nix32104=== CONT TestStaticToken105=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32106=== CONT TestSetClientTLSErrors107=== CONT TestDumpPathSingleFile108=== CONT TestUploadMultipart_SupersededByPeer109=== RUN TestUploadMultipart_SupersededByPeer/exists110=== PAUSE TestUploadMultipart_SupersededByPeer/exists111=== RUN TestUploadMultipart_SupersededByPeer/missing112=== PAUSE TestUploadMultipart_SupersededByPeer/missing113=== CONT TestDumpPathWriterError114=== CONT TestScriptTokenNoExpiryRerunsEveryCall115=== CONT TestEncodeNixBase32116=== RUN TestEncodeNixBase32/test_string_hash117=== PAUSE TestEncodeNixBase32/test_string_hash118=== RUN TestEncodeNixBase32/empty_input119=== PAUSE TestEncodeNixBase32/empty_input120=== CONT TestShellSplitErrors121=== CONT TestFileTokenEmpty122=== CONT TestScriptTokenCachesUntilRefresh123=== CONT TestFilterOversizedClosures124=== RUN TestFilterOversizedClosures/no_limit_keeps_everything125=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything126=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped127=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped128=== RUN TestFilterOversizedClosures/all_closures_skipped129=== PAUSE TestFilterOversizedClosures/all_closures_skipped130=== CONT TestCaseHackSuffix131=== CONT TestShellSplit132=== CONT TestScriptTokenEmptyToken133=== PAUSE TestRateLimiterFeedback/503_enables_limiter134=== CONT TestScriptTokenEmptyCommand135--- PASS: TestFileTokenMissing (0.00s)136=== CONT TestScriptTokenScriptFails137=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths138=== CONT TestScriptTokenBadJSON139=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)140=== PAUSE TestParsePathInfoJSON/Nix_format141=== RUN TestGetStorePathHash/valid_store_path142=== CONT TestPartSizeForNAR143=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)144=== RUN TestConvertHashToNix32/already_Nix32_format145=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon146=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon147=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI148=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI149=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512150=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512151=== PAUSE TestConvertHashToNix32/already_Nix32_format152=== RUN TestConvertHashToNix32/invalid_format153=== PAUSE TestConvertHashToNix32/invalid_format154=== CONT TestPathInfoCACompatibility/new_structured_format_-_text155=== CONT TestPathInfoCACompatibility/old_string_format_-_text156=== CONT TestDumpPathMatchesNix157--- PASS: TestResolveStorePath (0.00s)158--- PASS: TestStaticToken (0.00s)159--- PASS: TestShellSplitErrors (0.00s)160--- PASS: TestFileTokenReadsAndCaches (0.00s)161--- PASS: TestFileTokenEmpty (0.00s)162--- PASS: TestShellSplit (0.00s)163--- PASS: TestScriptTokenEmptyCommand (0.00s)164--- PASS: TestDoServerRequestAttachesToken (0.01s)165=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter166=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter167=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter168=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter169=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths170=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths171--- PASS: TestScriptTokenScriptFails (0.00s)172=== CONT TestUploadMultipart_SupersededByPeer/exists173=== RUN TestSetClientTLSErrors/missing_cert_file174=== RUN TestParsePathInfoJSON/Lix_format175=== PAUSE TestGetStorePathHash/valid_store_path176=== RUN TestPartSizeForNAR/zero_stays_at_minimum177=== CONT TestPathInfoCACompatibility/null_ca_field178=== CONT TestDoWithRetry_BodyReplayedViaGetBody179=== CONT TestSetClientTLS180=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method181=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive182=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths183=== CONT TestUploadMultipart_SupersededByPeer/missing184=== CONT TestEncodeNixBase32/test_string_hash185--- PASS: TestScriptTokenEmptyToken (0.00s)186=== PAUSE TestSetClientTLSErrors/missing_cert_file187=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped188=== RUN TestSetClientTLSErrors/missing_key_file1892026/08/27 09:58:10 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=2000190=== CONT TestConvertHashToNix32/SRI_format_to_Nix32191=== CONT TestFilterOversizedClosures/all_closures_skipped192=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon1932026/08/27 09:58:10 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=50194=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter195=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum196--- PASS: TestScriptTokenBadJSON (0.01s)197=== RUN TestGetStorePathHash/basename_without_hyphen_should_error198=== CONT TestFilterOversizedClosures/no_limit_keeps_everything199=== CONT TestEncodeNixBase32/empty_input200=== PAUSE TestParsePathInfoJSON/Lix_format201=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)202=== PAUSE TestSetClientTLSErrors/missing_key_file203=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error204=== CONT TestRateLimiterFeedback/503_enables_limiter205=== RUN TestParsePathInfoJSON/empty_input206=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths207=== RUN TestSetClientTLSErrors/missing_ca_file208=== CONT TestConvertHashToNix32/already_Nix32_format209=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter210=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI211=== CONT TestRateLimiterFeedback/429_enables_limiter212=== CONT TestConvertHashToNix32/invalid_format213=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512214--- PASS: TestPathInfoCACompatibility (0.00s)215 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)216 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)217 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)218 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)219 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.01s)220=== RUN TestPartSizeForNAR/small_stays_at_minimum221=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error222=== PAUSE TestParsePathInfoJSON/empty_input223=== PAUSE TestSetClientTLSErrors/missing_ca_file224=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths225=== RUN TestSetClientTLSErrors/invalid_ca_file2262026/08/27 09:58:10 WARN Rate limiter enabled after throttle name=server-test rate=5227--- PASS: TestFilterOversizedClosures (0.00s)228 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)229 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)230 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)2312026/08/27 09:58:10 WARN Rate limiter enabled after throttle name=server-test rate=5232=== PAUSE TestPartSizeForNAR/small_stays_at_minimum2332026/08/27 09:58:10 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:37737234=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error2352026/08/27 09:58:10 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:44497236=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error2372026/08/27 09:58:10 WARN Rate limiter backed off name=server-test rate=52382026/08/27 09:58:10 WARN Rate limiter enabled after throttle name=server-test rate=5239=== RUN TestParsePathInfoJSON/whitespace_only2402026/08/27 09:58:10 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:42239241--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.02s)242=== PAUSE TestSetClientTLSErrors/invalid_ca_file243=== CONT TestSetClientTLSErrors/missing_cert_file2442026/08/27 09:58:10 WARN Rate limiter backed off name=server-test rate=5245--- PASS: TestConvertHashToNix32 (0.00s)246 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)247 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)248 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)2492026/08/27 09:58:10 WARN Rate limiter backed off name=server-test rate=5250--- PASS: TestPathInfoHashCompatibility (0.00s)251 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)252 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)253 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)254 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)2552026/08/27 09:58:10 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:44497256--- PASS: TestEncodeNixBase32 (0.00s)257 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)258 --- PASS: TestEncodeNixBase32/empty_input (0.00s)259=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum260=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error261=== CONT TestGetStorePathHash/valid_store_path262=== CONT TestGetStorePathHash/basename_without_hyphen_should_error263=== PAUSE TestParsePathInfoJSON/whitespace_only264=== RUN TestParsePathInfoJSON/invalid_JSON265=== CONT TestSetClientTLSErrors/invalid_ca_file266=== CONT TestSetClientTLSErrors/missing_ca_file267=== CONT TestSetClientTLSErrors/missing_key_file268--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)269 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)270 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)271=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum272=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error273=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error274=== PAUSE TestParsePathInfoJSON/invalid_JSON275=== CONT TestParsePathInfoJSON/invalid_JSON276=== RUN TestSetClientTLS/rejects_connection_without_client_cert277=== CONT TestParsePathInfoJSON/Nix_format278=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert279=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA280=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts281=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts282=== CONT TestParsePathInfoJSON/whitespace_only283=== CONT TestParsePathInfoJSON/empty_input284=== CONT TestParsePathInfoJSON/Lix_format285--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.02s)286=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA287=== RUN TestPartSizeForNAR/1_TiB288=== PAUSE TestPartSizeForNAR/1_TiB289--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)290 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)291 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)292--- PASS: TestScriptTokenCachesUntilRefresh (0.02s)293=== RUN TestSetClientTLS/preserves_debug_logging_transport294=== PAUSE TestSetClientTLS/preserves_debug_logging_transport295=== CONT TestSetClientTLS/rejects_connection_without_client_cert296=== CONT TestSetClientTLS/preserves_debug_logging_transport297=== RUN TestPartSizeForNAR/5_TiB_S3_max_object298--- PASS: TestRateLimiterFeedback (0.01s)299 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)300 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)301 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)302 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)303--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)304=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA305=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object306=== RUN TestPartSizeForNAR/capped_at_5_GiB307=== PAUSE TestPartSizeForNAR/capped_at_5_GiB308=== CONT TestPartSizeForNAR/zero_stays_at_minimum309--- PASS: TestGetStorePathHash (0.02s)310 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)311 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)312 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)313 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)314=== CONT TestPartSizeForNAR/1_TiB315=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum316=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts317=== CONT TestPartSizeForNAR/small_stays_at_minimum318=== CONT TestPartSizeForNAR/capped_at_5_GiB319=== CONT TestPartSizeForNAR/5_TiB_S3_max_object320--- PASS: TestParsePathInfoJSON (0.02s)321 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)322 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)323 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)324 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)325 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)326--- PASS: TestPartSizeForNAR (0.01s)327 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)328 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)329 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)330 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)331 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)332 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)333 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)334--- PASS: TestSetClientTLSErrors (0.02s)335 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)336 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)337 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)338 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)339--- PASS: TestDumpPathSingleFile (0.03s)3402026/08/27 09:58:10 http: TLS handshake error from 127.0.0.1:45576: remote error: tls: bad certificate341--- PASS: TestSetClientTLS (0.01s)342 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)343 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)344 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)345--- PASS: TestCaseHackSuffix (0.04s)346--- PASS: TestDumpPathWriterError (0.04s)347--- PASS: TestDumpPathMatchesNix (0.08s)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/postgres3146877829/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/postgres3146877829/data -l logfile start377378/build/postgres3146877829:5432 - no response3792026-08-27 09:58:12.249 UTC [112] LOG: starting PostgreSQL 18.4 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit3802026-08-27 09:58:12.250 UTC [112] LOG: listening on Unix socket "/build/postgres3146877829/.s.PGSQL.5432"3812026-08-27 09:58:12.254 UTC [119] LOG: database system was shut down at 2026-08-27 09:58:12 UTC3822026-08-27 09:58:12.258 UTC [112] LOG: database system is ready to accept connections383/build/postgres3146877829: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:58:16.036 UTC [520] ERROR: relation "goose_db_version" does not exist at character 364122026-08-27 09:58:16.036 UTC [520] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4132026/08/27 09:58:16 OK 20241026095416_initial_model.sql (11.58ms)4142026/08/27 09:58:16 OK 20251210153512_drop_unused_gin_index.sql (2.31ms)4152026/08/27 09:58:16 OK 20251218171726_add_pins.sql (3.31ms)4162026/08/27 09:58:16 OK 20260628120000_add_object_size_and_stats.sql (2.86ms)4172026/08/27 09:58:16 goose: successfully migrated database to version: 202606281200004182026/08/27 09:58:16 OK 1_commit_pending_closure.sql (1.89ms)4192026/08/27 09:58:16 OK 2_object_stats_trigger.sql (843.95µs)4202026/08/27 09:58:16 goose: up to current file version: 2421--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.78s)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 TestReadRedirectNar493=== PAUSE TestReadRedirectNar494=== RUN TestReadRedirectKeepsNarinfoProxied495=== PAUSE TestReadRedirectKeepsNarinfoProxied496=== RUN TestReadProxyRangeRequest497=== PAUSE TestReadProxyRangeRequest498=== RUN TestRedundantMultipartUpload499=== PAUSE TestRedundantMultipartUpload500=== RUN TestCompleteMultipartUpload_ErrorButObjectExists501=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists502=== RUN TestCompletedNarNotReofferedAcrossClosures503=== PAUSE TestCompletedNarNotReofferedAcrossClosures504=== RUN TestPresignedUploadRegisteredBeforeCommit505=== PAUSE TestPresignedUploadRegisteredBeforeCommit506=== RUN TestService_Rustfstest507=== PAUSE TestService_Rustfstest508=== RUN TestParseSize509=== PAUSE TestParseSize510=== RUN TestSkippedUploadsHandler511=== PAUSE TestSkippedUploadsHandler512=== RUN TestSystemdListenerNotActivated513--- PASS: TestSystemdListenerNotActivated (0.00s)514=== RUN TestWatchdogBeatsWhenHealthy515--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)516=== RUN TestWatchdogSkipsWhenUnhealthy5172026/08/27 09:58:16 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5182026/08/27 09:58:16 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5192026/08/27 09:58:16 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5202026/08/27 09:58:16 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5212026/08/27 09:58:16 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5222026/08/27 09:58:16 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5232026/08/27 09:58:16 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5242026/08/27 09:58:16 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5252026/08/27 09:58:16 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5262026/08/27 09:58:16 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"527--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)528=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle529=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle530=== RUN TestProxyWriteTimeout531=== PAUSE TestProxyWriteTimeout532=== RUN TestIsValidUploadKey533=== PAUSE TestIsValidUploadKey534=== RUN TestUploadHandlersRejectInvalidKeys535=== PAUSE TestUploadHandlersRejectInvalidKeys536=== RUN TestUploadHandlersRejectOversizedBody537=== PAUSE TestUploadHandlersRejectOversizedBody538=== RUN TestService_cleanupPendingClosuresHandler539=== PAUSE TestService_cleanupPendingClosuresHandler540=== RUN TestService_createPendingClosureHandler541=== PAUSE TestService_createPendingClosureHandler542=== RUN TestService_verifyS3Integrity543=== PAUSE TestService_verifyS3Integrity544=== RUN TestCompleteMultipartUnregistered545=== PAUSE TestCompleteMultipartUnregistered546=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT547=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT548=== CONT TestProxyWriteTimeout549=== CONT TestService_AuthMiddleware550=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle551=== CONT TestSkippedUploadsHandler552=== CONT TestParseSize553=== CONT TestService_Rustfstest554=== CONT TestPresignedUploadRegisteredBeforeCommit555=== CONT TestCompletedNarNotReofferedAcrossClosures556=== CONT TestCompleteMultipartUpload_ErrorButObjectExists5572026/08/27 09:58:16 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000558=== CONT TestRedundantMultipartUpload559=== CONT TestReadProxyRangeRequest560=== CONT TestReadRedirectKeepsNarinfoProxied561=== CONT TestReadRedirectNar562=== CONT TestReadProxyDisabled563=== CONT TestReadProxyRootRedirectsToIndexHTML564=== CONT TestReadProxyConditionalGet565=== CONT TestUploadHandlersRejectOversizedBody566=== CONT TestReadProxyHead567=== CONT TestReadProxyInvalidPath568=== CONT TestService_cleanupPendingClosuresHandler569=== CONT TestReadProxy404570=== CONT TestUploadHandlersRejectInvalidKeys571=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info572=== CONT TestReadProxyNarStreaming573=== CONT TestService_createPendingClosureHandler574=== RUN TestProxyWriteTimeout/narinfo575--- PASS: TestParseSize (0.00s)576--- PASS: TestSkippedUploadsHandler (0.01s)577=== CONT TestReadProxyNarinfoAlreadyDecompressed578=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info579=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal580=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal581=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key582=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key583=== CONT TestIsValidUploadKey584=== RUN TestIsValidUploadKey/narinfo585=== PAUSE TestIsValidUploadKey/narinfo586=== RUN TestIsValidUploadKey/nar_zst587=== PAUSE TestIsValidUploadKey/nar_zst588=== RUN TestIsValidUploadKey/nar_xz589=== PAUSE TestIsValidUploadKey/nar_xz590=== RUN TestIsValidUploadKey/nar_plain591=== PAUSE TestIsValidUploadKey/nar_plain592=== RUN TestIsValidUploadKey/listing593=== PAUSE TestIsValidUploadKey/listing594=== RUN TestIsValidUploadKey/build_log595=== PAUSE TestProxyWriteTimeout/narinfo596=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key597=== RUN TestProxyWriteTimeout/1_GiB_nar598=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key599=== PAUSE TestProxyWriteTimeout/1_GiB_nar600=== RUN TestProxyWriteTimeout/10_GiB_nar601=== CONT TestReadProxyNarinfo602=== PAUSE TestProxyWriteTimeout/10_GiB_nar603=== RUN TestProxyWriteTimeout/unknown_size604=== PAUSE TestProxyWriteTimeout/unknown_size605=== PAUSE TestIsValidUploadKey/build_log606=== RUN TestIsValidUploadKey/build_log_home-manager_file607=== PAUSE TestIsValidUploadKey/build_log_home-manager_file608=== CONT TestIsValidCachePath609=== RUN TestIsValidCachePath/narinfo610=== PAUSE TestIsValidCachePath/narinfo611=== RUN TestIsValidUploadKey/build_log_plus_in_name612=== PAUSE TestIsValidUploadKey/build_log_plus_in_name613=== RUN TestIsValidUploadKey/build_log_question_mark614=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars615=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars616=== RUN TestIsValidCachePath/nar_zst617=== PAUSE TestIsValidCachePath/nar_zst618=== RUN TestIsValidCachePath/nar_xz619=== PAUSE TestIsValidCachePath/nar_xz620=== PAUSE TestIsValidUploadKey/build_log_question_mark621=== RUN TestIsValidCachePath/nar_bz2622=== PAUSE TestIsValidCachePath/nar_bz2623=== RUN TestIsValidUploadKey/build_log_equals624=== PAUSE TestIsValidUploadKey/build_log_equals625=== RUN TestIsValidUploadKey/realisation626=== RUN TestIsValidCachePath/nar_uncompressed627=== PAUSE TestIsValidCachePath/nar_uncompressed628=== PAUSE TestIsValidUploadKey/realisation629=== RUN TestIsValidUploadKey/realisation_plus_in_output630=== PAUSE TestIsValidUploadKey/realisation_plus_in_output631=== RUN TestIsValidCachePath/ls632=== RUN TestIsValidUploadKey/nix-cache-info633=== PAUSE TestIsValidUploadKey/nix-cache-info634=== RUN TestIsValidUploadKey/index.html635=== PAUSE TestIsValidUploadKey/index.html636=== RUN TestIsValidUploadKey/narinfo_key,_nar_type637=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type638=== RUN TestIsValidUploadKey/nar_key,_narinfo_type639=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type640=== RUN TestIsValidUploadKey/listing_key,_narinfo_type641=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type642=== RUN TestIsValidUploadKey/traversal643=== PAUSE TestIsValidUploadKey/traversal644=== PAUSE TestIsValidCachePath/ls645=== RUN TestIsValidUploadKey/traversal_nar646=== RUN TestIsValidCachePath/log647=== PAUSE TestIsValidUploadKey/traversal_nar648=== RUN TestIsValidUploadKey/absolute649=== PAUSE TestIsValidCachePath/log650=== PAUSE TestIsValidUploadKey/absolute651=== RUN TestIsValidUploadKey/empty_key652=== RUN TestIsValidCachePath/realisation653=== PAUSE TestIsValidUploadKey/empty_key654=== PAUSE TestIsValidCachePath/realisation655=== RUN TestIsValidUploadKey/unknown_type656=== PAUSE TestIsValidUploadKey/unknown_type657=== RUN TestIsValidCachePath/nix-cache-info658=== PAUSE TestIsValidCachePath/nix-cache-info659=== RUN TestIsValidCachePath/index.html660=== PAUSE TestIsValidCachePath/index.html661=== CONT TestGCTaskStore_GetReturnsLatest662--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)663=== CONT TestGCTaskStore_GetEmpty664--- PASS: TestGCTaskStore_GetEmpty (0.00s)665=== CONT TestParseSingleRange666=== RUN TestParseSingleRange/none667=== PAUSE TestParseSingleRange/none668=== RUN TestParseSingleRange/unknown_unit669=== PAUSE TestParseSingleRange/unknown_unit670=== RUN TestParseSingleRange/multi-range_ignored671=== PAUSE TestParseSingleRange/multi-range_ignored672=== RUN TestParseSingleRange/malformed_no_dash673=== RUN TestIsValidCachePath/traversal_parent674=== PAUSE TestIsValidCachePath/traversal_parent675=== PAUSE TestParseSingleRange/malformed_no_dash676=== RUN TestIsValidCachePath/traversal_in_middle677=== RUN TestParseSingleRange/malformed_both_empty678=== PAUSE TestParseSingleRange/malformed_both_empty679=== RUN TestParseSingleRange/malformed_end_before_start680=== PAUSE TestParseSingleRange/malformed_end_before_start681=== RUN TestParseSingleRange/closed682=== PAUSE TestParseSingleRange/closed683=== RUN TestParseSingleRange/open-ended684=== PAUSE TestParseSingleRange/open-ended685=== RUN TestParseSingleRange/end_clamped_to_size686=== PAUSE TestParseSingleRange/end_clamped_to_size687=== RUN TestParseSingleRange/suffix688=== PAUSE TestParseSingleRange/suffix689=== RUN TestParseSingleRange/suffix_exceeds_size690=== PAUSE TestParseSingleRange/suffix_exceeds_size691=== PAUSE TestIsValidCachePath/traversal_in_middle692=== RUN TestIsValidCachePath/invalid_char_e693=== PAUSE TestIsValidCachePath/invalid_char_e694=== RUN TestParseSingleRange/single_byte695=== PAUSE TestParseSingleRange/single_byte696=== RUN TestIsValidCachePath/invalid_char_u697=== RUN TestParseSingleRange/start_past_EOF698=== PAUSE TestIsValidCachePath/invalid_char_u699=== PAUSE TestParseSingleRange/start_past_EOF700=== RUN TestIsValidCachePath/random_path701=== PAUSE TestIsValidCachePath/random_path702=== RUN TestParseSingleRange/start_far_past_EOF703=== PAUSE TestParseSingleRange/start_far_past_EOF704=== RUN TestIsValidCachePath/empty705=== PAUSE TestIsValidCachePath/empty706=== RUN TestIsValidCachePath/leading_slash707=== CONT TestClientErrorHandling708=== RUN TestClientErrorHandling/InvalidStorePath709=== PAUSE TestClientErrorHandling/InvalidStorePath710=== RUN TestClientErrorHandling/InvalidAuthToken711=== PAUSE TestClientErrorHandling/InvalidAuthToken712=== RUN TestClientErrorHandling/ServerNotAvailable713=== PAUSE TestClientErrorHandling/ServerNotAvailable714=== PAUSE TestIsValidCachePath/leading_slash715=== CONT TestResurrectedObjectNotDeleted716=== RUN TestIsValidCachePath/wrong_extension717=== PAUSE TestIsValidCachePath/wrong_extension718=== RUN TestIsValidCachePath/short_hash719=== PAUSE TestIsValidCachePath/short_hash720=== CONT TestClientCADerivations7212026-08-27 09:58:17.050 UTC [593] ERROR: relation "goose_db_version" does not exist at character 367222026-08-27 09:58:17.050 UTC [593] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7232026-08-27 09:58:17.064 UTC [594] ERROR: relation "goose_db_version" does not exist at character 367242026-08-27 09:58:17.064 UTC [594] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7252026-08-27 09:58:17.068 UTC [595] ERROR: relation "goose_db_version" does not exist at character 367262026-08-27 09:58:17.068 UTC [595] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7272026-08-27 09:58:17.075 UTC [596] ERROR: relation "goose_db_version" does not exist at character 367282026-08-27 09:58:17.075 UTC [596] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7292026-08-27 09:58:17.083 UTC [597] ERROR: relation "goose_db_version" does not exist at character 367302026-08-27 09:58:17.083 UTC [597] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7312026-08-27 09:58:17.088 UTC [598] ERROR: relation "goose_db_version" does not exist at character 367322026-08-27 09:58:17.088 UTC [598] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC733=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure734=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure735=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart736=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart737=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts738=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts739=== CONT TestOrphanedObjectsGCStressTest7402026/08/27 09:58:17 OK 20241026095416_initial_model.sql (43.13ms)7412026/08/27 09:58:17 OK 20241026095416_initial_model.sql (48.87ms)7422026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (3.88ms)7432026-08-27 09:58:17.127 UTC [601] ERROR: relation "goose_db_version" does not exist at character 367442026-08-27 09:58:17.127 UTC [601] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7452026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (13.67ms)7462026/08/27 09:58:17 OK 20241026095416_initial_model.sql (42.41ms)7472026/08/27 09:58:17 OK 20241026095416_initial_model.sql (25.74ms)7482026/08/27 09:58:17 OK 20241026095416_initial_model.sql (36.82ms)7492026/08/27 09:58:17 OK 20241026095416_initial_model.sql (54.06ms)7502026/08/27 09:58:17 OK 20251218171726_add_pins.sql (18.09ms)7512026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (3.32ms)7522026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (4.43ms)7532026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (3.73ms)7542026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (4.92ms)7552026/08/27 09:58:17 OK 20251218171726_add_pins.sql (8.81ms)7562026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (8.02ms)7572026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200007582026/08/27 09:58:17 OK 20251218171726_add_pins.sql (9.22ms)7592026/08/27 09:58:17 OK 20251218171726_add_pins.sql (7.89ms)7602026/08/27 09:58:17 OK 20251218171726_add_pins.sql (7.73ms)7612026/08/27 09:58:17 OK 20251218171726_add_pins.sql (7.69ms)7622026/08/27 09:58:17 OK 1_commit_pending_closure.sql (4.29ms)7632026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (18.04ms)7642026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200007652026/08/27 09:58:17 OK 2_object_stats_trigger.sql (12.43ms)7662026/08/27 09:58:17 goose: up to current file version: 27672026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (15.32ms)7682026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200007692026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (13.8ms)7702026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200007712026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (15.35ms)7722026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200007732026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (16.31ms)7742026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200007752026/08/27 09:58:17 OK 1_commit_pending_closure.sql (5.98ms)7762026/08/27 09:58:17 OK 1_commit_pending_closure.sql (6.26ms)7772026/08/27 09:58:17 OK 1_commit_pending_closure.sql (5.99ms)7782026/08/27 09:58:17 OK 1_commit_pending_closure.sql (6.16ms)7792026/08/27 09:58:17 OK 20241026095416_initial_model.sql (27.69ms)7802026/08/27 09:58:17 OK 1_commit_pending_closure.sql (5.72ms)7812026/08/27 09:58:17 OK 2_object_stats_trigger.sql (4.48ms)7822026/08/27 09:58:17 goose: up to current file version: 27832026/08/27 09:58:17 OK 2_object_stats_trigger.sql (4.33ms)7842026/08/27 09:58:17 goose: up to current file version: 27852026/08/27 09:58:17 OK 2_object_stats_trigger.sql (4.65ms)7862026/08/27 09:58:17 goose: up to current file version: 27872026/08/27 09:58:17 OK 2_object_stats_trigger.sql (4.66ms)7882026/08/27 09:58:17 goose: up to current file version: 27892026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (4.67ms)7902026/08/27 09:58:17 OK 2_object_stats_trigger.sql (4.85ms)7912026/08/27 09:58:17 goose: up to current file version: 27922026/08/27 09:58:17 OK 20251218171726_add_pins.sql (6.41ms)7932026-08-27 09:58:17.189 UTC [605] ERROR: relation "goose_db_version" does not exist at character 367942026-08-27 09:58:17.189 UTC [605] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7952026-08-27 09:58:17.191 UTC [607] ERROR: relation "goose_db_version" does not exist at character 367962026-08-27 09:58:17.191 UTC [607] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7972026-08-27 09:58:17.192 UTC [606] ERROR: relation "goose_db_version" does not exist at character 367982026-08-27 09:58:17.192 UTC [606] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7992026-08-27 09:58:17.193 UTC [608] ERROR: relation "goose_db_version" does not exist at character 368002026-08-27 09:58:17.193 UTC [608] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8012026-08-27 09:58:17.196 UTC [609] ERROR: relation "goose_db_version" does not exist at character 368022026-08-27 09:58:17.196 UTC [609] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8032026-08-27 09:58:17.196 UTC [610] ERROR: relation "goose_db_version" does not exist at character 368042026-08-27 09:58:17.196 UTC [610] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8052026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (23.43ms)8062026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200008072026-08-27 09:58:17.209 UTC [611] ERROR: relation "goose_db_version" does not exist at character 368082026-08-27 09:58:17.209 UTC [611] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8092026/08/27 09:58:17 OK 1_commit_pending_closure.sql (6.03ms)8102026/08/27 09:58:17 OK 2_object_stats_trigger.sql (5.32ms)8112026/08/27 09:58:17 goose: up to current file version: 28122026-08-27 09:58:17.223 UTC [614] ERROR: relation "goose_db_version" does not exist at character 368132026-08-27 09:58:17.223 UTC [614] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8142026-08-27 09:58:17.224 UTC [612] ERROR: relation "goose_db_version" does not exist at character 368152026-08-27 09:58:17.224 UTC [612] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8162026-08-27 09:58:17.226 UTC [615] ERROR: relation "goose_db_version" does not exist at character 368172026-08-27 09:58:17.226 UTC [615] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8182026-08-27 09:58:17.226 UTC [613] ERROR: relation "goose_db_version" does not exist at character 368192026-08-27 09:58:17.226 UTC [613] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8202026-08-27 09:58:17.228 UTC [616] ERROR: relation "goose_db_version" does not exist at character 368212026-08-27 09:58:17.228 UTC [616] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8222026-08-27 09:58:17.233 UTC [617] ERROR: relation "goose_db_version" does not exist at character 368232026-08-27 09:58:17.233 UTC [617] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8242026/08/27 09:58:17 OK 20241026095416_initial_model.sql (16.49ms)8252026/08/27 09:58:17 OK 20241026095416_initial_model.sql (15.78ms)8262026-08-27 09:58:17.238 UTC [618] ERROR: relation "goose_db_version" does not exist at character 368272026-08-27 09:58:17.238 UTC [618] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8282026/08/27 09:58:17 OK 20241026095416_initial_model.sql (16.54ms)8292026/08/27 09:58:17 OK 20241026095416_initial_model.sql (19ms)8302026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (6.17ms)8312026/08/27 09:58:17 OK 20241026095416_initial_model.sql (20.31ms)8322026/08/27 09:58:17 OK 20241026095416_initial_model.sql (20.48ms)8332026/08/27 09:58:17 OK 20241026095416_initial_model.sql (20.1ms)8342026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (7.48ms)8352026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (4.32ms)8362026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (4.25ms)8372026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (3.81ms)8382026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (3.82ms)8392026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (3.93ms)8402026-08-27 09:58:17.247 UTC [619] ERROR: relation "goose_db_version" does not exist at character 368412026-08-27 09:58:17.247 UTC [619] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8422026-08-27 09:58:17.248 UTC [620] ERROR: relation "goose_db_version" does not exist at character 368432026-08-27 09:58:17.248 UTC [620] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8442026/08/27 09:58:17 OK 20251218171726_add_pins.sql (6.84ms)8452026-08-27 09:58:17.249 UTC [621] ERROR: relation "goose_db_version" does not exist at character 368462026-08-27 09:58:17.249 UTC [621] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8472026/08/27 09:58:17 OK 20251218171726_add_pins.sql (6.59ms)8482026/08/27 09:58:17 OK 20241026095416_initial_model.sql (14.29ms)8492026/08/27 09:58:17 OK 20251218171726_add_pins.sql (6.68ms)8502026/08/27 09:58:17 OK 20241026095416_initial_model.sql (13.47ms)8512026/08/27 09:58:17 OK 20241026095416_initial_model.sql (13.55ms)8522026/08/27 09:58:17 OK 20251218171726_add_pins.sql (7.03ms)8532026/08/27 09:58:17 OK 20241026095416_initial_model.sql (14.14ms)8542026/08/27 09:58:17 OK 20251218171726_add_pins.sql (6.97ms)8552026/08/27 09:58:17 OK 20251218171726_add_pins.sql (6.96ms)8562026/08/27 09:58:17 OK 20241026095416_initial_model.sql (15.06ms)8572026/08/27 09:58:17 OK 20251218171726_add_pins.sql (8.59ms)8582026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (3.08ms)8592026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (3.98ms)8602026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (7.65ms)8612026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (5.81ms)8622026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200008632026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (4.47ms)8642026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200008652026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (3.09ms)8662026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (4.28ms)8672026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (6.39ms)8682026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200008692026/08/27 09:58:17 OK 20241026095416_initial_model.sql (14.96ms)8702026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (5.85ms)8712026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200008722026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (5.48ms)8732026/08/27 09:58:17 OK 20241026095416_initial_model.sql (11.76ms)8742026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200008752026/08/27 09:58:17 OK 1_commit_pending_closure.sql (3.19ms)8762026/08/27 09:58:17 OK 20251218171726_add_pins.sql (4.51ms)8772026/08/27 09:58:17 OK 1_commit_pending_closure.sql (3.25ms)8782026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (6.33ms)8792026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200008802026/08/27 09:58:17 OK 20251218171726_add_pins.sql (5.23ms)8812026/08/27 09:58:17 OK 20251218171726_add_pins.sql (3.99ms)8822026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (5.61ms)8832026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200008842026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (2.79ms)8852026/08/27 09:58:17 OK 1_commit_pending_closure.sql (4.15ms)8862026/08/27 09:58:17 OK 20251218171726_add_pins.sql (5.42ms)8872026/08/27 09:58:17 OK 20251218171726_add_pins.sql (5.16ms)8882026/08/27 09:58:17 INFO Received uploads request method=POST path=/api/pending_closures8892026/08/27 09:58:17 OK 1_commit_pending_closure.sql (5.09ms)8902026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (4.37ms)8912026/08/27 09:58:17 OK 2_object_stats_trigger.sql (3.37ms)8922026/08/27 09:58:17 OK 1_commit_pending_closure.sql (3.31ms)8932026/08/27 09:58:17 OK 2_object_stats_trigger.sql (3.47ms)8942026/08/27 09:58:17 goose: up to current file version: 28952026/08/27 09:58:17 goose: up to current file version: 28962026/08/27 09:58:17 OK 1_commit_pending_closure.sql (5.22ms)8972026/08/27 09:58:17 OK 1_commit_pending_closure.sql (3.64ms)8982026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (4.4ms)8992026/08/27 09:58:17 OK 20251218171726_add_pins.sql (4.15ms)9002026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200009012026/08/27 09:58:17 OK 2_object_stats_trigger.sql (2.94ms)9022026/08/27 09:58:17 goose: up to current file version: 29032026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (6.09ms)9042026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200009052026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (6.8ms)9062026/08/27 09:58:17 OK 2_object_stats_trigger.sql (3.24ms)9072026/08/27 09:58:17 goose: up to current file version: 29082026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200009092026/08/27 09:58:17 OK 2_object_stats_trigger.sql (3.96ms)9102026/08/27 09:58:17 goose: up to current file version: 29112026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (5.52ms)9122026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200009132026/08/27 09:58:17 OK 20241026095416_initial_model.sql (11.65ms)9142026/08/27 09:58:17 OK 2_object_stats_trigger.sql (3.06ms)9152026/08/27 09:58:17 goose: up to current file version: 29162026/08/27 09:58:17 OK 2_object_stats_trigger.sql (4.18ms)9172026/08/27 09:58:17 OK 20241026095416_initial_model.sql (10.31ms)9182026/08/27 09:58:17 OK 20241026095416_initial_model.sql (13.41ms)9192026/08/27 09:58:17 OK 20251218171726_add_pins.sql (5.55ms)9202026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (6.9ms)9212026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200009222026/08/27 09:58:17 goose: up to current file version: 29232026/08/27 09:58:17 OK 1_commit_pending_closure.sql (3.81ms)9242026/08/27 09:58:17 OK 1_commit_pending_closure.sql (2.49ms)9252026/08/27 09:58:17 OK 1_commit_pending_closure.sql (2.62ms)9262026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (4.23ms)9272026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200009282026/08/27 09:58:17 OK 1_commit_pending_closure.sql (2.12ms)9292026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (2.15ms)9302026/08/27 09:58:17 OK 2_object_stats_trigger.sql (1.1ms)9312026/08/27 09:58:17 goose: up to current file version: 29322026/08/27 09:58:17 OK 2_object_stats_trigger.sql (1.14ms)9332026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (1.43ms)9342026/08/27 09:58:17 goose: up to current file version: 29352026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (1.41ms)9362026/08/27 09:58:17 OK 2_object_stats_trigger.sql (952.33µs)9372026/08/27 09:58:17 goose: up to current file version: 29382026/08/27 09:58:17 OK 2_object_stats_trigger.sql (1.53ms)9392026/08/27 09:58:17 goose: up to current file version: 29402026/08/27 09:58:17 OK 1_commit_pending_closure.sql (1.96ms)9412026/08/27 09:58:17 OK 1_commit_pending_closure.sql (2.04ms)9422026/08/27 09:58:17 OK 2_object_stats_trigger.sql (2.48ms)9432026/08/27 09:58:17 goose: up to current file version: 29442026/08/27 09:58:17 OK 20251218171726_add_pins.sql (5.21ms)9452026/08/27 09:58:17 OK 2_object_stats_trigger.sql (4.09ms)9462026/08/27 09:58:17 goose: up to current file version: 29472026/08/27 09:58:17 OK 20251218171726_add_pins.sql (5.15ms)9482026/08/27 09:58:17 OK 20251218171726_add_pins.sql (5.43ms)9492026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (6.66ms)9502026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200009512026/08/27 09:58:17 OK 1_commit_pending_closure.sql (3.72ms)9522026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (4.07ms)9532026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200009542026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (4.15ms)9552026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200009562026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (4.01ms)9572026/08/27 09:58:17 goose: successfully migrated database to version: 202606281200009582026/08/27 09:58:17 OK 2_object_stats_trigger.sql (1.06ms)9592026/08/27 09:58:17 goose: up to current file version: 29602026/08/27 09:58:17 OK 1_commit_pending_closure.sql (1.49ms)9612026/08/27 09:58:17 OK 1_commit_pending_closure.sql (1.85ms)9622026/08/27 09:58:17 OK 1_commit_pending_closure.sql (2.83ms)9632026/08/27 09:58:17 OK 2_object_stats_trigger.sql (1.47ms)9642026/08/27 09:58:17 goose: up to current file version: 29652026/08/27 09:58:17 OK 2_object_stats_trigger.sql (1.48ms)9662026/08/27 09:58:17 goose: up to current file version: 29672026/08/27 09:58:17 OK 2_object_stats_trigger.sql (1.59ms)9682026/08/27 09:58:17 goose: up to current file version: 29692026/08/27 09:58:17 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"970--- PASS: TestService_AuthMiddleware (0.35s)971=== CONT TestCacheStatsHandler9722026/08/27 09:58:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9732026/08/27 09:58:17 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=M2M1NWNmNjMtODExNS00ZDBhLThhOGItYzZkMjM3ZWIyOTM0LmZmYjExYmY4LTlhZGEtNGNjZS1iYWUwLTRiZDMzN2NhNDY3ZHgxNzg3ODI0Njk3MjcyNjA3NjU49742026/08/27 09:58:17 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=M2M1NWNmNjMtODExNS00ZDBhLThhOGItYzZkMjM3ZWIyOTM0LmZmYjExYmY4LTlhZGEtNGNjZS1iYWUwLTRiZDMzN2NhNDY3ZHgxNzg3ODI0Njk3MjcyNjA3NjU4 parts=1975--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.36s)976=== CONT TestOrphanedObjectsGC977--- PASS: TestService_Rustfstest (0.37s)978=== CONT TestCacheConfigHandler979=== RUN TestCacheConfigHandler/full_config,_no_issuer980=== PAUSE TestCacheConfigHandler/full_config,_no_issuer981=== RUN TestCacheConfigHandler/no_cache_url_configured982=== PAUSE TestCacheConfigHandler/no_cache_url_configured983=== RUN TestCacheConfigHandler/no_signing_keys984=== PAUSE TestCacheConfigHandler/no_signing_keys985=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator986=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator987=== CONT TestObjectStatsTrigger9882026/08/27 09:58:17 INFO Received uploads request method=POST path=/api/pending_closures9892026/08/27 09:58:17 INFO Received uploads request method=POST path=/api/pending_closures9902026-08-27 09:58:17.382 UTC [628] ERROR: relation "goose_db_version" does not exist at character 369912026-08-27 09:58:17.382 UTC [628] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9922026-08-27 09:58:17.406 UTC [629] ERROR: relation "goose_db_version" does not exist at character 369932026-08-27 09:58:17.406 UTC [629] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9942026-08-27 09:58:17.410 UTC [630] ERROR: relation "goose_db_version" does not exist at character 369952026-08-27 09:58:17.410 UTC [630] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9962026/08/27 09:58:17 OK 20241026095416_initial_model.sql (12.49ms)9972026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (2ms)9982026/08/27 09:58:17 OK 20251218171726_add_pins.sql (4.09ms)9992026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (4.96ms)10002026/08/27 09:58:17 goose: successfully migrated database to version: 2026062812000010012026/08/27 09:58:17 OK 20241026095416_initial_model.sql (11.18ms)10022026/08/27 09:58:17 OK 1_commit_pending_closure.sql (2.91ms)10032026/08/27 09:58:17 OK 20241026095416_initial_model.sql (10.61ms)10042026/08/27 09:58:17 OK 2_object_stats_trigger.sql (2.06ms)10052026/08/27 09:58:17 goose: up to current file version: 210062026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (2.69ms)10072026/08/27 09:58:17 OK 20251210153512_drop_unused_gin_index.sql (2.12ms)10082026/08/27 09:58:17 OK 20251218171726_add_pins.sql (3.33ms)10092026/08/27 09:58:17 OK 20251218171726_add_pins.sql (2.46ms)10102026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (3.88ms)10112026/08/27 09:58:17 goose: successfully migrated database to version: 2026062812000010122026/08/27 09:58:17 OK 20260628120000_add_object_size_and_stats.sql (3.39ms)10132026/08/27 09:58:17 goose: successfully migrated database to version: 2026062812000010142026/08/27 09:58:17 OK 1_commit_pending_closure.sql (1.97ms)10152026/08/27 09:58:17 OK 1_commit_pending_closure.sql (1.74ms)10162026/08/27 09:58:17 OK 2_object_stats_trigger.sql (783.41µs)10172026/08/27 09:58:17 goose: up to current file version: 210182026/08/27 09:58:17 OK 2_object_stats_trigger.sql (975.87µs)10192026/08/27 09:58:17 goose: up to current file version: 210202026/08/27 09:58:18 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10212026/08/27 09:58:18 INFO Received uploads request method=POST path=/api/pending_closures1022--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.05s)1023=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT1024--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.06s)1025=== CONT TestMultipartCleanup1026--- PASS: TestReadRedirectKeepsNarinfoProxied (1.06s)1027=== CONT TestCompleteMultipartUnregistered1028--- PASS: TestReadProxyDisabled (1.07s)1029=== CONT TestService_verifyS3Integrity1030--- PASS: TestReadProxyNarStreaming (1.08s)1031=== CONT TestServerTLSConfig1032=== RUN TestServerTLSConfig/no_client_CA1033=== PAUSE TestServerTLSConfig/no_client_CA1034=== RUN TestServerTLSConfig/missing_CA_file1035=== PAUSE TestServerTLSConfig/missing_CA_file1036=== RUN TestServerTLSConfig/not_a_PEM_file1037=== PAUSE TestServerTLSConfig/not_a_PEM_file1038=== CONT TestClientIntegration10392026/08/27 09:58:18 INFO Received cleanup request method=DELETE path=/api/pending_closures10402026/08/27 09:58:18 INFO Aborted multipart uploads count=010412026/08/27 09:58:18 INFO Received uploads request method=POST path=/api/pending_closures10422026/08/27 09:58:18 INFO Received uploads request method=POST path=/api/pending_closures10432026/08/27 09:58:18 INFO Received uploads request method=POST path=/api/pending_closures10442026/08/27 09:58:18 INFO Received uploads request method=POST path=/api/pending_closures10452026/08/27 09:58:18 INFO Received cleanup request method=DELETE path=/api/pending_closures10462026/08/27 09:58:18 INFO Aborted multipart uploads count=11047--- PASS: TestReadProxyInvalidPath (1.12s)1048=== CONT TestService_AuthMiddleware_OIDC10492026/08/27 09:58:18 INFO OIDC provider initialized name=test10502026/08/27 09:58:18 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10512026-08-27 09:58:18.092 UTC [610] ERROR: Closure does not exist: id=110522026-08-27 09:58:18.092 UTC [610] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE10532026-08-27 09:58:18.092 UTC [610] STATEMENT: -- name: CommitPendingClosure :exec1054 SELECT commit_pending_closure($1::bigint)1055 1056--- PASS: TestService_cleanupPendingClosuresHandler (1.13s)1057=== CONT TestGenerateLandingPage1058--- PASS: TestGenerateLandingPage (0.01s)1059=== CONT TestGCTaskStore_ConflictDifferentParams1060--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1061=== CONT TestService_ReadAuthMiddleware10622026/08/27 09:58:18 INFO Received uploads request method=POST path=/api/pending_closures10632026/08/27 09:58:18 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10642026-08-27 09:58:18.110 UTC [645] ERROR: relation "goose_db_version" does not exist at character 3610652026-08-27 09:58:18.110 UTC [645] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10662026-08-27 09:58:18.111 UTC [647] ERROR: relation "goose_db_version" does not exist at character 3610672026-08-27 09:58:18.111 UTC [647] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10682026-08-27 09:58:18.118 UTC [649] ERROR: relation "goose_db_version" does not exist at character 3610692026-08-27 09:58:18.118 UTC [649] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10702026-08-27 09:58:18.118 UTC [650] ERROR: relation "goose_db_version" does not exist at character 3610712026-08-27 09:58:18.118 UTC [650] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10722026/08/27 09:58:18 OK 20241026095416_initial_model.sql (15.21ms)1073--- PASS: TestReadRedirectNar (1.18s)1074=== CONT TestGCTaskStore_DeduplicateSameParams1075--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1076=== CONT TestService_AuthMiddleware_MTLSBoundSubjects10772026/08/27 09:58:18 OK 20241026095416_initial_model.sql (16.2ms)10782026/08/27 09:58:18 OK 20241026095416_initial_model.sql (12.59ms)10792026/08/27 09:58:18 OK 20251210153512_drop_unused_gin_index.sql (4.67ms)10802026/08/27 09:58:18 OK 20241026095416_initial_model.sql (16.85ms)10812026/08/27 09:58:18 OK 20251210153512_drop_unused_gin_index.sql (6.47ms)10822026/08/27 09:58:18 OK 20251210153512_drop_unused_gin_index.sql (6.01ms)10832026/08/27 09:58:18 OK 20251218171726_add_pins.sql (8.01ms)10842026/08/27 09:58:18 OK 20251210153512_drop_unused_gin_index.sql (4.65ms)10852026/08/27 09:58:18 OK 20251218171726_add_pins.sql (7.78ms)10862026/08/27 09:58:18 OK 20251218171726_add_pins.sql (9.24ms)10872026-08-27 09:58:18.161 UTC [654] ERROR: relation "goose_db_version" does not exist at character 3610882026-08-27 09:58:18.161 UTC [654] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10892026/08/27 09:58:18 OK 20251218171726_add_pins.sql (15.84ms)10902026/08/27 09:58:18 OK 20260628120000_add_object_size_and_stats.sql (16.01ms)10912026/08/27 09:58:18 goose: successfully migrated database to version: 2026062812000010922026/08/27 09:58:18 OK 20260628120000_add_object_size_and_stats.sql (14.97ms)10932026/08/27 09:58:18 goose: successfully migrated database to version: 2026062812000010942026/08/27 09:58:18 OK 20260628120000_add_object_size_and_stats.sql (14.87ms)10952026/08/27 09:58:18 goose: successfully migrated database to version: 2026062812000010962026/08/27 09:58:18 OK 1_commit_pending_closure.sql (6.67ms)10972026/08/27 09:58:18 OK 20260628120000_add_object_size_and_stats.sql (7.39ms)10982026/08/27 09:58:18 goose: successfully migrated database to version: 2026062812000010992026/08/27 09:58:18 OK 1_commit_pending_closure.sql (5.7ms)11002026/08/27 09:58:18 OK 1_commit_pending_closure.sql (5.66ms)11012026/08/27 09:58:18 OK 2_object_stats_trigger.sql (4ms)11022026/08/27 09:58:18 goose: up to current file version: 211032026/08/27 09:58:18 OK 2_object_stats_trigger.sql (3.11ms)11042026/08/27 09:58:18 OK 1_commit_pending_closure.sql (5.57ms)11052026/08/27 09:58:18 goose: up to current file version: 211062026/08/27 09:58:18 OK 2_object_stats_trigger.sql (3.04ms)11072026/08/27 09:58:18 goose: up to current file version: 211082026/08/27 09:58:18 OK 2_object_stats_trigger.sql (3ms)11092026/08/27 09:58:18 goose: up to current file version: 21110--- PASS: TestReadProxyConditionalGet (1.22s)1111=== CONT TestGCTaskStore_StartNew1112--- PASS: TestGCTaskStore_StartNew (0.00s)1113=== CONT TestMetricsInventory11142026-08-27 09:58:18.181 UTC [655] ERROR: relation "goose_db_version" does not exist at character 3611152026-08-27 09:58:18.181 UTC [655] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11162026-08-27 09:58:18.181 UTC [656] ERROR: relation "goose_db_version" does not exist at character 3611172026-08-27 09:58:18.181 UTC [656] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11182026/08/27 09:58:18 OK 20241026095416_initial_model.sql (12.22ms)11192026/08/27 09:58:18 OK 20251210153512_drop_unused_gin_index.sql (3.27ms)11202026/08/27 09:58:18 OK 20251218171726_add_pins.sql (4.26ms)11212026/08/27 09:58:18 OK 20260628120000_add_object_size_and_stats.sql (13.59ms)11222026/08/27 09:58:18 goose: successfully migrated database to version: 2026062812000011232026/08/27 09:58:18 OK 20241026095416_initial_model.sql (20.46ms)11242026/08/27 09:58:18 OK 1_commit_pending_closure.sql (3.22ms)11252026/08/27 09:58:18 OK 20251210153512_drop_unused_gin_index.sql (3.75ms)11262026/08/27 09:58:18 OK 2_object_stats_trigger.sql (2.55ms)11272026/08/27 09:58:18 goose: up to current file version: 211282026/08/27 09:58:18 OK 20241026095416_initial_model.sql (24.79ms)11292026/08/27 09:58:18 OK 20251218171726_add_pins.sql (4.84ms)11302026/08/27 09:58:18 OK 20251210153512_drop_unused_gin_index.sql (5.06ms)11312026/08/27 09:58:18 OK 20260628120000_add_object_size_and_stats.sql (6.63ms)11322026/08/27 09:58:18 goose: successfully migrated database to version: 2026062812000011332026/08/27 09:58:18 OK 20251218171726_add_pins.sql (4.43ms)11342026-08-27 09:58:18.227 UTC [676] ERROR: relation "goose_db_version" does not exist at character 3611352026-08-27 09:58:18.227 UTC [676] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11362026/08/27 09:58:18 OK 1_commit_pending_closure.sql (3.13ms)11372026/08/27 09:58:18 OK 20260628120000_add_object_size_and_stats.sql (3.86ms)11382026/08/27 09:58:18 goose: successfully migrated database to version: 2026062812000011392026/08/27 09:58:18 OK 2_object_stats_trigger.sql (2.98ms)11402026/08/27 09:58:18 goose: up to current file version: 211412026/08/27 09:58:18 OK 1_commit_pending_closure.sql (3.01ms)11422026/08/27 09:58:18 OK 2_object_stats_trigger.sql (2.28ms)11432026/08/27 09:58:18 goose: up to current file version: 21144=== NAME TestClientCADerivations1145 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations4142627863/001/store/y385l4s3hvmkv48aqkdljw4cg1i78jm3-ca-test11462026/08/27 09:58:18 OK 20241026095416_initial_model.sql (11.73ms)11472026/08/27 09:58:18 OK 20251210153512_drop_unused_gin_index.sql (2.73ms)11482026/08/27 09:58:18 OK 20251218171726_add_pins.sql (3.31ms)11492026/08/27 09:58:18 OK 20260628120000_add_object_size_and_stats.sql (3.67ms)11502026/08/27 09:58:18 goose: successfully migrated database to version: 2026062812000011512026/08/27 09:58:18 OK 1_commit_pending_closure.sql (2.25ms)11522026/08/27 09:58:18 OK 2_object_stats_trigger.sql (1.59ms)11532026/08/27 09:58:18 goose: up to current file version: 211542026-08-27 09:58:18.261 UTC [695] ERROR: relation "goose_db_version" does not exist at character 3611552026-08-27 09:58:18.261 UTC [695] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11562026/08/27 09:58:18 OK 20241026095416_initial_model.sql (9.7ms)11572026/08/27 09:58:18 OK 20251210153512_drop_unused_gin_index.sql (1.32ms)1158 client_ca_test.go:139: Found 1 dependencies (including self)11592026/08/27 09:58:18 OK 20251218171726_add_pins.sql (3.26ms)11602026/08/27 09:58:18 OK 20260628120000_add_object_size_and_stats.sql (2.74ms)11612026/08/27 09:58:18 goose: successfully migrated database to version: 2026062812000011622026/08/27 09:58:18 OK 1_commit_pending_closure.sql (1.98ms)11632026/08/27 09:58:18 OK 2_object_stats_trigger.sql (821.29µs)11642026/08/27 09:58:18 goose: up to current file version: 211652026/08/27 09:58:18 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11662026/08/27 09:58:18 INFO Received uploads request method=POST path=/api/pending_closures11672026/08/27 09:58:18 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11682026/08/27 09:58:18 INFO Uploading y385l4s3hvmkv48aqkdljw4cg1i78jm3-ca-test (144B)11692026/08/27 09:58:18 WARN Failed to register uploaded object key=log/n1izq6asxf0d2zp060h2j6kyg6w9p3nk-ca-test.drv error="server returned 404: 404 page not found\n"11702026/08/27 09:58:18 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"11712026/08/27 09:58:18 WARN Failed to register uploaded object key=y385l4s3hvmkv48aqkdljw4cg1i78jm3.ls error="server returned 404: 404 page not found\n"11722026/08/27 09:58:18 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11732026/08/27 09:58:18 INFO Signed narinfos id=1 count=111742026/08/27 09:58:18 INFO Uploading 1 narinfos11752026/08/27 09:58:18 WARN Failed to register uploaded object key=y385l4s3hvmkv48aqkdljw4cg1i78jm3.narinfo error="server returned 404: 404 page not found\n"11762026/08/27 09:58:18 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11772026/08/27 09:58:18 INFO Completed upload id=111782026/08/27 09:58:18 INFO Upload complete. (98ms)1179 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations4142627863/001/store/y385l4s3hvmkv48aqkdljw4cg1i78jm3-ca-test1180 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1181 Compression: zstd1182 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1183 NarSize: 1441184 References: 1185 Deriver: /build/TestClientCADerivations4142627863/001/store/n1izq6asxf0d2zp060h2j6kyg6w9p3nk-ca-test.drv1186 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1187 client_ca_test.go:185: Checking for realisation files in S3...1188 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1189 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1190 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1191 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1192 error: binary cache 's3://bucket16?endpoint=http://localhost:35459®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations4142627863/001/store'1193 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11194--- PASS: TestClientCADerivations (1.57s)1195=== CONT TestService_AuthMiddleware_MTLSProxyHeader11962026-08-27 09:58:18.664 UTC [884] ERROR: relation "goose_db_version" does not exist at character 3611972026-08-27 09:58:18.664 UTC [884] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11982026/08/27 09:58:18 OK 20241026095416_initial_model.sql (15.29ms)11992026/08/27 09:58:18 OK 20251210153512_drop_unused_gin_index.sql (1.35ms)12002026/08/27 09:58:18 OK 20251218171726_add_pins.sql (4.33ms)12012026/08/27 09:58:18 OK 20260628120000_add_object_size_and_stats.sql (2.9ms)12022026/08/27 09:58:18 goose: successfully migrated database to version: 2026062812000012032026/08/27 09:58:18 OK 1_commit_pending_closure.sql (1.97ms)12042026/08/27 09:58:18 OK 2_object_stats_trigger.sql (840.79µs)12052026/08/27 09:58:18 goose: up to current file version: 21206--- PASS: TestReadProxyRangeRequest (1.84s)1207=== CONT TestGCMetrics1208--- PASS: TestReadProxyNarinfoAlreadyDecompressed (1.87s)1209=== CONT TestNARDeduplicationMetadataUploadBug1210--- PASS: TestReadProxyHead (1.88s)1211=== CONT TestCreatePendingClosureRejectsOversizedNAR12122026/08/27 09:58:18 INFO Received uploads request method=POST path=/api/pending_closures1213--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1214=== CONT TestService_NativeMTLS1215--- PASS: TestReadProxy404 (1.89s)1216=== CONT TestCacheConfigHandlerMaxNarSize1217--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1218=== CONT TestGCBugBareHashReferences12192026-08-27 09:58:18.873 UTC [893] ERROR: relation "goose_db_version" does not exist at character 3612202026-08-27 09:58:18.873 UTC [893] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1221--- PASS: TestReadProxyNarinfo (1.87s)1222=== CONT TestGCTaskStore_Fail1223--- PASS: TestGCTaskStore_Fail (0.00s)1224=== CONT TestService_healthCheckHandler12252026/08/27 09:58:18 OK 20241026095416_initial_model.sql (12.37ms)12262026/08/27 09:58:18 OK 20251210153512_drop_unused_gin_index.sql (2.52ms)12272026/08/27 09:58:18 OK 20251218171726_add_pins.sql (4.92ms)12282026/08/27 09:58:18 OK 20260628120000_add_object_size_and_stats.sql (5.24ms)12292026/08/27 09:58:18 goose: successfully migrated database to version: 2026062812000012302026/08/27 09:58:18 INFO Received uploads request method=POST path=/api/pending_closures12312026/08/27 09:58:18 OK 1_commit_pending_closure.sql (10.53ms)12322026-08-27 09:58:18.920 UTC [896] ERROR: relation "goose_db_version" does not exist at character 3612332026-08-27 09:58:18.920 UTC [896] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12342026/08/27 09:58:18 OK 2_object_stats_trigger.sql (6.52ms)12352026/08/27 09:58:18 goose: up to current file version: 21236--- PASS: TestResurrectedObjectNotDeleted (1.91s)1237=== CONT TestClientMultipleUploads12382026/08/27 09:58:18 INFO Received uploads request method=POST path=/api/pending_closures12392026-08-27 09:58:18.934 UTC [897] ERROR: relation "goose_db_version" does not exist at character 3612402026-08-27 09:58:18.934 UTC [897] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12412026-08-27 09:58:18.936 UTC [899] ERROR: relation "goose_db_version" does not exist at character 3612422026-08-27 09:58:18.936 UTC [899] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12432026/08/27 09:58:18 OK 20241026095416_initial_model.sql (12.63ms)12442026/08/27 09:58:18 OK 20251210153512_drop_unused_gin_index.sql (4.73ms)12452026/08/27 09:58:18 OK 20251218171726_add_pins.sql (9.44ms)12462026/08/27 09:58:18 OK 20241026095416_initial_model.sql (13.92ms)12472026/08/27 09:58:18 OK 20251210153512_drop_unused_gin_index.sql (3.89ms)12482026/08/27 09:58:18 OK 20260628120000_add_object_size_and_stats.sql (6.91ms)12492026/08/27 09:58:18 goose: successfully migrated database to version: 2026062812000012502026/08/27 09:58:18 OK 20241026095416_initial_model.sql (15.94ms)1251--- PASS: TestCacheStatsHandler (1.67s)1252=== CONT TestGCTaskStore_PhaseUpdates1253--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1254=== CONT TestGracefulShutdownDrainsInflight12552026/08/27 09:58:18 OK 1_commit_pending_closure.sql (4.22ms)12562026/08/27 09:58:18 OK 20251218171726_add_pins.sql (6.13ms)12572026/08/27 09:58:18 INFO Starting HTTP server address=127.0.0.1:3326912582026/08/27 09:58:18 OK 20251210153512_drop_unused_gin_index.sql (5.14ms)12592026/08/27 09:58:18 INFO Shutdown signal received, draining in-flight requests timeout=10s12602026-08-27 09:58:18.968 UTC [901] ERROR: relation "goose_db_version" does not exist at character 3612612026-08-27 09:58:18.968 UTC [901] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12622026/08/27 09:58:18 OK 2_object_stats_trigger.sql (6.47ms)12632026/08/27 09:58:18 goose: up to current file version: 212642026/08/27 09:58:18 OK 20260628120000_add_object_size_and_stats.sql (7.44ms)12652026/08/27 09:58:18 goose: successfully migrated database to version: 2026062812000012662026/08/27 09:58:18 OK 20251218171726_add_pins.sql (7.83ms)12672026/08/27 09:58:18 OK 1_commit_pending_closure.sql (3.84ms)12682026/08/27 09:58:18 OK 20260628120000_add_object_size_and_stats.sql (4.76ms)12692026/08/27 09:58:18 goose: successfully migrated database to version: 2026062812000012702026/08/27 09:58:18 OK 2_object_stats_trigger.sql (4.43ms)12712026/08/27 09:58:18 goose: up to current file version: 212722026/08/27 09:58:18 OK 1_commit_pending_closure.sql (5.72ms)12732026/08/27 09:58:18 OK 2_object_stats_trigger.sql (3.62ms)12742026/08/27 09:58:18 goose: up to current file version: 212752026/08/27 09:58:18 OK 20241026095416_initial_model.sql (12.19ms)12762026/08/27 09:58:18 OK 20251210153512_drop_unused_gin_index.sql (3.05ms)12772026/08/27 09:58:18 OK 20251218171726_add_pins.sql (2.37ms)12782026/08/27 09:58:19 OK 20260628120000_add_object_size_and_stats.sql (3.49ms)12792026/08/27 09:58:19 goose: successfully migrated database to version: 2026062812000012802026/08/27 09:58:19 OK 1_commit_pending_closure.sql (1.85ms)12812026/08/27 09:58:19 OK 2_object_stats_trigger.sql (1.07ms)12822026/08/27 09:58:19 goose: up to current file version: 212832026-08-27 09:58:19.009 UTC [902] ERROR: relation "goose_db_version" does not exist at character 3612842026-08-27 09:58:19.009 UTC [902] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12852026/08/27 09:58:19 OK 20241026095416_initial_model.sql (12.11ms)12862026/08/27 09:58:19 OK 20251210153512_drop_unused_gin_index.sql (1.61ms)12872026/08/27 09:58:19 OK 20251218171726_add_pins.sql (4.06ms)12882026/08/27 09:58:19 OK 20260628120000_add_object_size_and_stats.sql (3.06ms)12892026/08/27 09:58:19 goose: successfully migrated database to version: 202606281200001290--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1291=== CONT TestGCTaskStore_CompletedAllowsNewTask1292--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1293=== CONT TestPinProtectsFromGC12942026/08/27 09:58:19 OK 1_commit_pending_closure.sql (1.73ms)12952026/08/27 09:58:19 OK 2_object_stats_trigger.sql (1.4ms)12962026/08/27 09:58:19 goose: up to current file version: 212972026-08-27 09:58:19.108 UTC [905] ERROR: relation "goose_db_version" does not exist at character 3612982026-08-27 09:58:19.108 UTC [905] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12992026/08/27 09:58:19 OK 20241026095416_initial_model.sql (10.88ms)13002026/08/27 09:58:19 OK 20251210153512_drop_unused_gin_index.sql (1.43ms)13012026/08/27 09:58:19 OK 20251218171726_add_pins.sql (3.44ms)13022026/08/27 09:58:19 OK 20260628120000_add_object_size_and_stats.sql (3.37ms)13032026/08/27 09:58:19 goose: successfully migrated database to version: 2026062812000013042026/08/27 09:58:19 OK 1_commit_pending_closure.sql (2.04ms)13052026/08/27 09:58:19 OK 2_object_stats_trigger.sql (877.23µs)13062026/08/27 09:58:19 goose: up to current file version: 21307--- PASS: TestObjectStatsTrigger (2.07s)1308=== CONT TestClientWithDependencies13092026/08/27 09:58:19 INFO Received uploads request method=POST path=/api/pending_closures1310--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.44s)1311=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info13122026/08/27 09:58:19 INFO Received uploads request method=POST path=/1313=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key13142026/08/27 09:58:19 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13152026/08/27 09:58:19 INFO Received request for more parts method=POST path=/1316=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key13172026/08/27 09:58:19 INFO Received complete multipart upload request method=POST path=/1318=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal13192026/08/27 09:58:19 INFO Received uploads request method=POST path=/1320--- PASS: TestUploadHandlersRejectInvalidKeys (0.01s)1321 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1322 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1323 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1324 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1325=== CONT TestProxyWriteTimeout/narinfo1326=== CONT TestProxyWriteTimeout/unknown_size1327=== CONT TestProxyWriteTimeout/10_GiB_nar1328=== CONT TestProxyWriteTimeout/1_GiB_nar1329--- PASS: TestProxyWriteTimeout (0.07s)1330 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1331 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1332 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1333 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1334=== CONT TestIsValidUploadKey/narinfo1335=== CONT TestIsValidUploadKey/nix-cache-info1336=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1337=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1338=== CONT TestIsValidUploadKey/traversal1339=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1340=== CONT TestIsValidUploadKey/unknown_type1341=== CONT TestIsValidUploadKey/index.html1342=== CONT TestIsValidUploadKey/empty_key1343=== CONT TestIsValidUploadKey/absolute1344=== CONT TestIsValidUploadKey/traversal_nar1345=== CONT TestIsValidUploadKey/build_log_home-manager_file1346=== CONT TestIsValidUploadKey/build_log_equals1347=== CONT TestIsValidUploadKey/build_log_question_mark1348=== CONT TestIsValidUploadKey/realisation_plus_in_output1349=== CONT TestIsValidUploadKey/realisation1350=== CONT TestIsValidUploadKey/build_log_plus_in_name1351=== CONT TestIsValidUploadKey/build_log1352=== CONT TestIsValidUploadKey/listing1353=== CONT TestIsValidUploadKey/nar_xz1354=== CONT TestIsValidUploadKey/nar_zst1355=== CONT TestIsValidUploadKey/nar_plain1356=== CONT TestParseSingleRange/none1357=== CONT TestParseSingleRange/closed1358=== CONT TestParseSingleRange/malformed_end_before_start1359=== CONT TestParseSingleRange/open-ended1360--- PASS: TestIsValidUploadKey (0.06s)1361 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1362 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1363 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1364 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1365 --- PASS: TestIsValidUploadKey/traversal (0.00s)1366 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1367 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1368 --- PASS: TestIsValidUploadKey/index.html (0.00s)1369 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1370 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1371 --- PASS: TestIsValidUploadKey/absolute (0.00s)1372 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1373 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1374 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1375 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1376 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1377 --- PASS: TestIsValidUploadKey/build_log (0.00s)1378 --- PASS: TestIsValidUploadKey/listing (0.00s)1379 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1380 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1381 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1382 --- PASS: TestIsValidUploadKey/realisation (0.00s)1383=== CONT TestParseSingleRange/malformed_both_empty1384=== CONT TestParseSingleRange/start_far_past_EOF1385=== CONT TestParseSingleRange/malformed_no_dash1386=== CONT TestParseSingleRange/start_past_EOF1387=== CONT TestParseSingleRange/multi-range_ignored1388=== CONT TestParseSingleRange/single_byte1389=== CONT TestParseSingleRange/unknown_unit1390=== CONT TestParseSingleRange/end_clamped_to_size1391=== CONT TestParseSingleRange/suffix_exceeds_size1392=== CONT TestParseSingleRange/suffix1393--- PASS: TestParseSingleRange (0.00s)1394 --- PASS: TestParseSingleRange/none (0.00s)1395 --- PASS: TestParseSingleRange/closed (0.00s)1396 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1397 --- PASS: TestParseSingleRange/open-ended (0.00s)1398 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1399 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1400 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1401 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1402 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1403 --- PASS: TestParseSingleRange/single_byte (0.00s)1404 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1405 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1406 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1407 --- PASS: TestParseSingleRange/suffix (0.00s)1408=== CONT TestClientErrorHandling/InvalidStorePath14092026/08/27 09:58:19 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1410--- PASS: TestCompleteMultipartUnregistered (1.44s)1411=== CONT TestClientErrorHandling/ServerNotAvailable14122026/08/27 09:58:19 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14132026/08/27 09:58:19 INFO Received uploads request method=POST path=/api/pending_closures1414=== NAME TestOrphanedObjectsGC1415 orphaned_objects_gc_test.go:290: GC Test Summary:1416 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1417 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1418 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1419 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1420 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1421--- PASS: TestOrphanedObjectsGC (2.18s)1422=== CONT TestClientErrorHandling/InvalidAuthToken14232026-08-27 09:58:19.494 UTC [928] ERROR: relation "goose_db_version" does not exist at character 3614242026-08-27 09:58:19.494 UTC [928] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14252026/08/27 09:58:19 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=M2M1NWNmNjMtODExNS00ZDBhLThhOGItYzZkMjM3ZWIyOTM0LmFkM2RiNTBlLWM0ZmEtNGFhZS05MDE1LTJmZDdkOTkzOWE4ZngxNzg3ODI0Njk4MDc1Nzc1NTE2 parts=1014262026/08/27 09:58:19 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14272026/08/27 09:58:19 INFO Completed upload id=114282026/08/27 09:58:19 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000014292026/08/27 09:58:19 INFO Received uploads request method=POST path=/api/pending_closures14302026/08/27 09:58:19 OK 20241026095416_initial_model.sql (19.53ms)14312026/08/27 09:58:19 INFO Starting cleanup of old closures method=DELETE path=/api/closures14322026/08/27 09:58:19 OK 20251210153512_drop_unused_gin_index.sql (5.52ms)14332026/08/27 09:58:19 OK 20251218171726_add_pins.sql (6.05ms)14342026/08/27 09:58:19 INFO Received uploads request method=POST path=/api/pending_closures14352026/08/27 09:58:19 INFO Aborted multipart uploads count=014362026/08/27 09:58:19 OK 20260628120000_add_object_size_and_stats.sql (5.45ms)14372026/08/27 09:58:19 goose: successfully migrated database to version: 2026062812000014382026-08-27 09:58:19.544 UTC [953] ERROR: relation "goose_db_version" does not exist at character 3614392026-08-27 09:58:19.544 UTC [953] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14402026/08/27 09:58:19 OK 1_commit_pending_closure.sql (6.03ms)14412026/08/27 09:58:19 OK 2_object_stats_trigger.sql (4.06ms)14422026/08/27 09:58:19 goose: up to current file version: 214432026/08/27 09:58:19 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=014442026/08/27 09:58:19 INFO Vacuumed table table=pending_closures14452026/08/27 09:58:19 OK 20241026095416_initial_model.sql (20.78ms)14462026/08/27 09:58:19 INFO Vacuumed table table=pending_objects14472026/08/27 09:58:19 OK 20251210153512_drop_unused_gin_index.sql (7.12ms)14482026/08/27 09:58:19 INFO Vacuumed table table=multipart_uploads14492026/08/27 09:58:19 INFO Vacuumed table table=closures14502026/08/27 09:58:19 OK 20251218171726_add_pins.sql (5.82ms)14512026/08/27 09:58:19 INFO Vacuumed table table=objects14522026/08/27 09:58:19 OK 20260628120000_add_object_size_and_stats.sql (4.21ms)14532026/08/27 09:58:19 goose: successfully migrated database to version: 2026062812000014542026-08-27 09:58:19.592 UTC [983] ERROR: relation "goose_db_version" does not exist at character 3614552026-08-27 09:58:19.592 UTC [983] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14562026/08/27 09:58:19 OK 1_commit_pending_closure.sql (2.55ms)14572026/08/27 09:58:19 INFO Received cleanup request method=DELETE path=/api/pending_closures14582026/08/27 09:58:19 OK 2_object_stats_trigger.sql (2.37ms)14592026/08/27 09:58:19 goose: up to current file version: 214602026/08/27 09:58:19 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-config14612026/08/27 09:58:19 INFO Aborted multipart uploads count=11462--- PASS: TestMultipartCleanup (1.60s)1463=== CONT TestIsValidCachePath/narinfo1464=== CONT TestIsValidCachePath/wrong_extension1465=== CONT TestIsValidCachePath/leading_slash1466=== CONT TestIsValidCachePath/empty1467=== CONT TestIsValidCachePath/random_path1468=== CONT TestIsValidCachePath/short_hash1469=== CONT TestIsValidCachePath/invalid_char_u1470=== CONT TestIsValidCachePath/invalid_char_e1471=== CONT TestIsValidCachePath/traversal_in_middle1472=== CONT TestIsValidCachePath/traversal_parent1473=== CONT TestIsValidCachePath/index.html1474=== CONT TestIsValidCachePath/nix-cache-info1475=== CONT TestIsValidCachePath/realisation1476=== CONT TestIsValidCachePath/nar_xz1477=== CONT TestIsValidCachePath/nar_zst1478=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1479=== CONT TestIsValidCachePath/ls1480=== CONT TestIsValidCachePath/log1481=== CONT TestIsValidCachePath/nar_uncompressed1482=== CONT TestIsValidCachePath/nar_bz21483--- PASS: TestIsValidCachePath (0.00s)1484 --- PASS: TestIsValidCachePath/narinfo (0.00s)1485 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1486 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1487 --- PASS: TestIsValidCachePath/empty (0.00s)1488 --- PASS: TestIsValidCachePath/random_path (0.00s)1489 --- PASS: TestIsValidCachePath/short_hash (0.00s)1490 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1491 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1492 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1493 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1494 --- PASS: TestIsValidCachePath/index.html (0.00s)1495 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1496 --- PASS: TestIsValidCachePath/realisation (0.00s)1497 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1498 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1499 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1500 --- PASS: TestIsValidCachePath/ls (0.00s)1501 --- PASS: TestIsValidCachePath/log (0.00s)1502 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1503 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1504=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure15052026/08/27 09:58:19 INFO Received uploads request method=POST path=/15062026/08/27 09:58:19 OK 20241026095416_initial_model.sql (9.53ms)15072026/08/27 09:58:19 OK 20251210153512_drop_unused_gin_index.sql (1.54ms)15082026/08/27 09:58:19 OK 20251218171726_add_pins.sql (3.17ms)15092026/08/27 09:58:19 OK 20260628120000_add_object_size_and_stats.sql (8.28ms)15102026/08/27 09:58:19 goose: successfully migrated database to version: 2026062812000015112026/08/27 09:58:19 OK 1_commit_pending_closure.sql (2.38ms)15122026/08/27 09:58:19 OK 2_object_stats_trigger.sql (1.04ms)15132026/08/27 09:58:19 goose: up to current file version: 215142026/08/27 09:58:19 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001515--- PASS: TestService_createPendingClosureHandler (2.67s)1516=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts15172026/08/27 09:58:19 INFO Received request for more parts method=POST path=/15182026/08/27 09:58:19 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=190.181795ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1519=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart15202026/08/27 09:58:19 INFO Received complete multipart upload request method=POST path=/1521=== CONT TestCacheConfigHandler/full_config,_no_issuer1522=== CONT TestCacheConfigHandler/no_signing_keys1523=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1524=== CONT TestCacheConfigHandler/no_cache_url_configured1525--- PASS: TestCacheConfigHandler (0.00s)1526 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1527 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1528 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1529 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1530=== CONT TestServerTLSConfig/no_client_CA1531=== CONT TestServerTLSConfig/missing_CA_file1532=== CONT TestServerTLSConfig/not_a_PEM_file1533--- PASS: TestServerTLSConfig (0.00s)1534 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1535 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1536 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)15372026/08/27 09:58:19 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1538--- PASS: TestService_ReadAuthMiddleware (1.78s)1539=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1540=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1541=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1542=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1543=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1544=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected15452026/08/27 09:58:19 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=402.84699ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1546=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1547=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1548=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1549=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected1550=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected15512026/08/27 09:58:19 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]1552=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured15532026/08/27 09:58:19 INFO OIDC auth successful provider=test15542026/08/27 09:58:19 WARN Authentication failed token_preview=eyJhbGciOi...rElOV5n6zQ 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]1555--- PASS: TestService_AuthMiddleware_OIDC (1.81s)1556 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1557 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1558 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)1559 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)15602026/08/27 09:58:19 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15612026/08/27 09:58:19 WARN mTLS auth: bound subjects configured but subject DN unavailable15622026/08/27 09:58:19 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1563--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (1.77s)1564=== NAME TestClientIntegration1565 client_integration_test.go:276: Created store path: /build/TestClientIntegration4043838481/002/store/iiyvf8hv7sc0r61hiwr0rz8v2w79ij8w-test-file.txt1566--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (1.34s)1567--- PASS: TestMetricsInventory (1.75s)15682026/08/27 09:58:19 INFO Aborted multipart uploads count=015692026/08/27 09:58:19 WARN Force mode enabled - objects will be deleted immediately without grace period15702026/08/27 09:58:19 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=015712026/08/27 09:58:19 INFO Vacuumed table table=pending_closures15722026/08/27 09:58:19 INFO Vacuumed table table=pending_objects15732026/08/27 09:58:19 INFO Vacuumed table table=multipart_uploads15742026/08/27 09:58:19 INFO Vacuumed table table=closures15752026/08/27 09:58:19 INFO Vacuumed table table=objects15762026/08/27 09:58:19 WARN mTLS auth: subject not in bound subjects subject="CN=reader"15772026/08/27 09:58:19 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1578--- PASS: TestService_NativeMTLS (1.14s)15792026/08/27 09:58:19 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1580--- PASS: TestGCMetrics (1.19s)1581=== NAME TestNARDeduplicationMetadataUploadBug1582 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug681241051/001/store/rsx2i23g0f65grlj0dxdb30x60s093b6-file1.txt15832026/08/27 09:58:20 INFO Received uploads request method=POST path=/api/pending_closures15842026/08/27 09:58:20 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15852026/08/27 09:58:20 INFO Uploading iiyvf8hv7sc0r61hiwr0rz8v2w79ij8w-test-file.txt (152B)1586--- PASS: TestService_healthCheckHandler (1.14s)15872026/08/27 09:58:20 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"15882026/08/27 09:58:20 WARN Failed to register uploaded object key=iiyvf8hv7sc0r61hiwr0rz8v2w79ij8w.ls error="server returned 404: 404 page not found\n"15892026/08/27 09:58:20 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15902026/08/27 09:58:20 INFO Signed narinfos id=1 count=115912026/08/27 09:58:20 INFO Uploading 1 narinfos15922026/08/27 09:58:20 WARN Failed to register uploaded object key=iiyvf8hv7sc0r61hiwr0rz8v2w79ij8w.narinfo error="server returned 404: 404 page not found\n"15932026/08/27 09:58:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15942026/08/27 09:58:20 INFO Completed upload id=115952026/08/27 09:58:20 INFO Upload complete. (103ms)1596=== NAME TestClientIntegration1597 client_integration_test.go:292: Retrieved narinfo from S3:1598 StorePath: /build/TestClientIntegration4043838481/002/store/iiyvf8hv7sc0r61hiwr0rz8v2w79ij8w-test-file.txt1599 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1600 Compression: zstd1601 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11602 NarSize: 1521603 References: 1604 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11605 client_integration_test.go:293: Retrieved .ls file from S3 (compressed size: 77 bytes)1606 client_integration_test.go:293: Decompressed .ls content (64 bytes):1607 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1608 client_integration_test.go:296: Testing garbage collection...16092026/08/27 09:58:20 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16102026/08/27 09:58:20 INFO Starting cleanup of old closures method=DELETE path=/api/closures16112026/08/27 09:58:20 INFO Garbage collection started1612=== NAME TestClientMultipleUploads1613 client_integration_test.go:338: Created store path 0: /build/TestClientMultipleUploads1358459901/001/store/i7n10ffr8jxmi4phg8jb5p14l1vjmwh5-test-file-0.txt16142026/08/27 09:58:20 INFO Aborted multipart uploads count=016152026/08/27 09:58:20 WARN Force mode enabled - objects will be deleted immediately without grace period1616 client_integration_test.go:338: Created store path 1: /build/TestClientMultipleUploads1358459901/001/store/nvfjqc0fmmrfbbdmawzmkfb6c3sx8xq9-test-file-1.txt16172026/08/27 09:58:20 INFO Received uploads request method=POST path=/api/pending_closures16182026/08/27 09:58:20 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16192026/08/27 09:58:20 INFO Uploading rsx2i23g0f65grlj0dxdb30x60s093b6-file1.txt (160B)16202026/08/27 09:58:20 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"16212026/08/27 09:58:20 WARN Failed to register uploaded object key=rsx2i23g0f65grlj0dxdb30x60s093b6.ls error="server returned 404: 404 page not found\n"16222026/08/27 09:58:20 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16232026/08/27 09:58:20 INFO Signed narinfos id=1 count=116242026/08/27 09:58:20 INFO Uploading 1 narinfos16252026/08/27 09:58:20 WARN Failed to register uploaded object key=rsx2i23g0f65grlj0dxdb30x60s093b6.narinfo error="server returned 404: 404 page not found\n"16262026/08/27 09:58:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16272026/08/27 09:58:20 INFO Completed upload id=116282026/08/27 09:58:20 INFO Upload complete. (107ms)1629=== NAME TestNARDeduplicationMetadataUploadBug1630 metadata_upload_test.go:54: Retrieved narinfo from S3:1631 StorePath: /build/TestNARDeduplicationMetadataUploadBug681241051/001/store/rsx2i23g0f65grlj0dxdb30x60s093b6-file1.txt1632 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1633 Compression: zstd1634 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1635 NarSize: 1601636 References: 1637 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf16382026/08/27 09:58:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1639=== NAME TestClientMultipleUploads1640 client_integration_test.go:338: Created store path 2: /build/TestClientMultipleUploads1358459901/001/store/3r2dpyhwkl9v909zipfwy7h8sjm7a8cz-test-file-2.txt1641=== NAME TestNARDeduplicationMetadataUploadBug1642 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1643 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1644 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1645=== NAME TestPinProtectsFromGC1646 client_integration_test.go:646: Pinned store path: /build/TestPinProtectsFromGC1210081982/001/store/r8j6hvxv1mpgg41jzna731zirwz1iwnm-pinned-file.txt1647 client_integration_test.go:647: Unpinned store path: /build/TestPinProtectsFromGC1210081982/001/store/hj3c8g2p726z7371d432cnkxb5cps7qx-unpinned-file.txt16482026/08/27 09:58:20 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=M2M1NWNmNjMtODExNS00ZDBhLThhOGItYzZkMjM3ZWIyOTM0LmI1ZGFlYmU2LWU3OTItNGEyOS1hYmVjLTUxZjQxMzY1M2ZjMHgxNzg3ODI0Njk4OTI3MDg5MzUw parts=121649--- PASS: TestRedundantMultipartUpload (3.23s)1650=== NAME TestClientWithDependencies1651 client_integration_test.go:593: Built derivation: /build/TestClientWithDependencies2269197962/001/store/vky4j36w3wjnb284y3yqgb5lvzbcz9mh-test-script1652=== NAME TestNARDeduplicationMetadataUploadBug1653 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug681241051/001/store/d94rbr0j260bkc0hfpaa7j7y211q86my-file2.txt1654=== NAME TestClientWithDependencies1655 client_integration_test.go:595: Found 1 dependencies (including self)1656--- PASS: TestGCBugBareHashReferences (1.37s)16572026/08/27 09:58:20 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16582026/08/27 09:58:20 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16592026/08/27 09:58:20 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16602026/08/27 09:58:20 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16612026/08/27 09:58:20 INFO Received uploads request method=POST path=/api/pending_closures16622026/08/27 09:58:20 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16632026/08/27 09:58:20 INFO Uploading r8j6hvxv1mpgg41jzna731zirwz1iwnm-pinned-file.txt (128B)16642026/08/27 09:58:20 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16652026/08/27 09:58:20 INFO Received uploads request method=POST path=/api/pending_closures16662026/08/27 09:58:20 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16672026/08/27 09:58:20 INFO Received uploads request method=POST path=/api/pending_closures16682026/08/27 09:58:20 WARN Failed to register uploaded object key=r8j6hvxv1mpgg41jzna731zirwz1iwnm.ls error="server returned 404: 404 page not found\n"16692026/08/27 09:58:20 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16702026/08/27 09:58:20 INFO Signed narinfos id=1 count=116712026/08/27 09:58:20 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16722026/08/27 09:58:20 INFO Uploading 1 narinfos16732026/08/27 09:58:20 INFO Uploading vky4j36w3wjnb284y3yqgb5lvzbcz9mh-test-script (136B)16742026/08/27 09:58:20 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=818.408054ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config16752026/08/27 09:58:20 INFO Received uploads request method=POST path=/api/pending_closures16762026/08/27 09:58:20 WARN Failed to register uploaded object key=log/zy38fkk3radhgc9x8gg4fjzchi9i2bp7-test-script.drv error="server returned 404: 404 page not found\n"16772026/08/27 09:58:20 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"16782026/08/27 09:58:20 INFO Received uploads request method=POST path=/api/pending_closures16792026/08/27 09:58:20 WARN Failed to register uploaded object key=r8j6hvxv1mpgg41jzna731zirwz1iwnm.narinfo error="server returned 404: 404 page not found\n"16802026/08/27 09:58:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16812026/08/27 09:58:20 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16822026/08/27 09:58:20 INFO Uploading i7n10ffr8jxmi4phg8jb5p14l1vjmwh5-test-file-0.txt (160B)16832026/08/27 09:58:20 INFO Uploading 3r2dpyhwkl9v909zipfwy7h8sjm7a8cz-test-file-2.txt (160B)16842026/08/27 09:58:20 INFO Uploading nvfjqc0fmmrfbbdmawzmkfb6c3sx8xq9-test-file-1.txt (160B)16852026/08/27 09:58:20 WARN Failed to register uploaded object key=vky4j36w3wjnb284y3yqgb5lvzbcz9mh.ls error="server returned 404: 404 page not found\n"16862026/08/27 09:58:20 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16872026/08/27 09:58:20 INFO Signed narinfos id=1 count=116882026/08/27 09:58:20 INFO Uploading 1 narinfos16892026/08/27 09:58:20 INFO Completed upload id=116902026/08/27 09:58:20 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16912026/08/27 09:58:20 INFO Upload complete. (107ms)16922026/08/27 09:58:20 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16932026/08/27 09:58:20 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"16942026/08/27 09:58:20 WARN Failed to register uploaded object key=i7n10ffr8jxmi4phg8jb5p14l1vjmwh5.ls error="server returned 404: 404 page not found\n"16952026/08/27 09:58:20 WARN Failed to register uploaded object key=vky4j36w3wjnb284y3yqgb5lvzbcz9mh.narinfo error="server returned 404: 404 page not found\n"16962026/08/27 09:58:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16972026/08/27 09:58:20 INFO Received uploads request method=POST path=/api/pending_closures16982026/08/27 09:58:20 WARN Failed to register uploaded object key=3r2dpyhwkl9v909zipfwy7h8sjm7a8cz.ls error="server returned 404: 404 page not found\n"16992026/08/27 09:58:20 WARN Failed to register uploaded object key=nvfjqc0fmmrfbbdmawzmkfb6c3sx8xq9.ls error="server returned 404: 404 page not found\n"17002026/08/27 09:58:20 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17012026/08/27 09:58:20 INFO Signed narinfos id=1 count=117022026/08/27 09:58:20 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17032026/08/27 09:58:20 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign17042026/08/27 09:58:20 INFO Signed narinfos id=2 count=117052026/08/27 09:58:20 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign17062026/08/27 09:58:20 INFO Signed narinfos id=3 count=117072026/08/27 09:58:20 INFO Uploading 3 narinfos17082026/08/27 09:58:20 INFO Completed upload id=117092026/08/27 09:58:20 INFO Upload complete. (57ms)17102026/08/27 09:58:20 WARN Failed to register uploaded object key=d94rbr0j260bkc0hfpaa7j7y211q86my.ls error="server returned 404: 404 page not found\n"17112026/08/27 09:58:20 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign17122026/08/27 09:58:20 INFO Signed narinfos id=2 count=117132026/08/27 09:58:20 INFO Uploading 1 narinfos17142026/08/27 09:58:20 WARN Failed to register uploaded object key=i7n10ffr8jxmi4phg8jb5p14l1vjmwh5.narinfo error="server returned 404: 404 page not found\n"17152026/08/27 09:58:20 WARN Failed to register uploaded object key=nvfjqc0fmmrfbbdmawzmkfb6c3sx8xq9.narinfo error="server returned 404: 404 page not found\n"17162026/08/27 09:58:20 WARN Failed to register uploaded object key=3r2dpyhwkl9v909zipfwy7h8sjm7a8cz.narinfo error="server returned 404: 404 page not found\n"17172026/08/27 09:58:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1718=== NAME TestClientWithDependencies1719 client_integration_test.go:597: Skipping nix copy test - isolated store (/build/TestClientWithDependencies2269197962/001/store) requires matching store prefix17202026/08/27 09:58:20 WARN Failed to register uploaded object key=d94rbr0j260bkc0hfpaa7j7y211q86my.narinfo error="server returned 404: 404 page not found\n"17212026/08/27 09:58:20 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17222026/08/27 09:58:20 INFO Completed upload id=217232026/08/27 09:58:20 INFO Upload complete. (88ms)17242026/08/27 09:58:20 INFO Completed upload id=117252026/08/27 09:58:20 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete1726=== NAME TestNARDeduplicationMetadataUploadBug1727 metadata_upload_test.go:76: Retrieved narinfo from S3:1728 StorePath: /build/TestNARDeduplicationMetadataUploadBug681241051/001/store/d94rbr0j260bkc0hfpaa7j7y211q86my-file2.txt1729 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1730 Compression: zstd1731 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1732 NarSize: 1601733 References: 1734 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1735--- PASS: TestClientWithDependencies (0.93s)17362026/08/27 09:58:20 INFO Completed upload id=217372026/08/27 09:58:20 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete17382026/08/27 09:58:20 INFO Completed upload id=317392026/08/27 09:58:20 INFO Upload complete. (116ms)1740=== NAME TestClientMultipleUploads1741 client_integration_test.go:349: Uploaded 3 paths in 163.266116ms1742=== NAME TestNARDeduplicationMetadataUploadBug1743 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1744 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1745 {"version":1,"root":{"type":"regular","size":44}}1746--- PASS: TestNARDeduplicationMetadataUploadBug (1.50s)17472026/08/27 09:58:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1748--- PASS: TestClientMultipleUploads (1.41s)17492026/08/27 09:58:20 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=M2M1NWNmNjMtODExNS00ZDBhLThhOGItYzZkMjM3ZWIyOTM0LmQxYjVhN2U2LWU5ZDktNGUwNi04OWZlLTE4Yjc3YzlmYzg2ZXgxNzg3ODI0Njk5NTUwOTMxMDg4 parts=1017502026/08/27 09:58:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17512026/08/27 09:58:20 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"17522026/08/27 09:58:20 INFO Completed upload id=117532026/08/27 09:58:20 INFO Received uploads request method=POST path=/api/pending_closures17542026/08/27 09:58:20 INFO Received uploads request method=POST path=/api/pending_closures17552026/08/27 09:58:20 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo17562026/08/27 09:58:20 WARN Found objects in DB but missing from S3, will re-upload count=11757--- PASS: TestService_verifyS3Integrity (2.34s)17582026/08/27 09:58:20 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17592026/08/27 09:58:20 INFO Received uploads request method=POST path=/api/pending_closures17602026/08/27 09:58:20 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17612026/08/27 09:58:20 INFO Uploading hj3c8g2p726z7371d432cnkxb5cps7qx-unpinned-file.txt (128B)17622026/08/27 09:58:20 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"17632026/08/27 09:58:20 WARN Failed to register uploaded object key=hj3c8g2p726z7371d432cnkxb5cps7qx.ls error="server returned 404: 404 page not found\n"17642026/08/27 09:58:20 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign17652026/08/27 09:58:20 INFO Signed narinfos id=2 count=117662026/08/27 09:58:20 INFO Uploading 1 narinfos17672026/08/27 09:58:20 WARN Failed to register uploaded object key=hj3c8g2p726z7371d432cnkxb5cps7qx.narinfo error="server returned 404: 404 page not found\n"17682026/08/27 09:58:20 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17692026/08/27 09:58:20 INFO Completed upload id=217702026/08/27 09:58:20 INFO Upload complete. (99ms)17712026/08/27 09:58:20 INFO Received create pin request method=POST path=/api/pins/myapp17722026/08/27 09:58:20 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC1210081982/001/store/r8j6hvxv1mpgg41jzna731zirwz1iwnm-pinned-file.txt narinfo_key=r8j6hvxv1mpgg41jzna731zirwz1iwnm.narinfo17732026/08/27 09:58:20 INFO Starting cleanup of old closures method=DELETE path=/api/closures17742026/08/27 09:58:20 INFO Garbage collection started17752026/08/27 09:58:20 INFO Aborted multipart uploads count=017762026/08/27 09:58:20 WARN Force mode enabled - objects will be deleted immediately without grace period1777=== NAME TestOrphanedObjectsGCStressTest1778 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1779 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion1780--- PASS: TestUploadHandlersRejectOversizedBody (0.15s)1781 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.09s)1782 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.08s)1783 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (1.44s)17842026/08/27 09:58:21 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.696705935s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17852026/08/27 09:58:21 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=017862026/08/27 09:58:21 INFO Vacuumed table table=pending_closures17872026/08/27 09:58:21 INFO Vacuumed table table=pending_objects17882026/08/27 09:58:21 INFO Vacuumed table table=multipart_uploads17892026/08/27 09:58:21 INFO Vacuumed table table=closures17902026/08/27 09:58:21 INFO Vacuumed table table=objects17912026/08/27 09:58:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17922026/08/27 09:58:21 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=M2M1NWNmNjMtODExNS00ZDBhLThhOGItYzZkMjM3ZWIyOTM0LjlkY2ZhZGRiLTQzZDEtNDk0OS04OTdkLWI1ZDQ4MWU2MzIzN3gxNzg3ODI0Njk4MTE5MDczMTQ3 parts=1217932026/08/27 09:58:21 INFO Received uploads request method=POST path=/api/pending_closures1794--- PASS: TestCompletedNarNotReofferedAcrossClosures (4.61s)1795=== NAME TestOrphanedObjectsGCStressTest1796 orphaned_objects_gc_test.go:509: Stress test completed successfully:1797 orphaned_objects_gc_test.go:510: - Active objects preserved: 201798 orphaned_objects_gc_test.go:511: - Objects deleted: 2101799 orphaned_objects_gc_test.go:512: - Total GC'd: 2101800--- PASS: TestOrphanedObjectsGCStressTest (4.66s)18012026/08/27 09:58:21 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=018022026/08/27 09:58:21 INFO Vacuumed table table=pending_closures18032026/08/27 09:58:21 INFO Vacuumed table table=pending_objects18042026/08/27 09:58:21 INFO Vacuumed table table=multipart_uploads18052026/08/27 09:58:21 INFO Vacuumed table table=closures18062026/08/27 09:58:21 INFO Vacuumed table table=objects18072026/08/27 09:58:22 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01808=== NAME TestClientIntegration1809 client_integration_test.go:303: Objects in database after GC:1810 client_integration_test.go:303: Successfully deleted all objects with GC --force1811--- PASS: TestClientIntegration (4.06s)18122026/08/27 09:58:22 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01813=== NAME TestPinProtectsFromGC1814 client_integration_test.go:709: Pin successfully protected closure from garbage collection1815--- PASS: TestPinProtectsFromGC (3.45s)18162026/08/27 09:58:22 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"18172026/08/27 09:58:22 WARN Rate limiter enabled after throttle name=s3-test rate=518182026/08/27 09:58:22 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1819=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1820 throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=101821 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001822--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.89s)18232026/08/27 09:58:22 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_closures18242026/08/27 09:58:22 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=190.593976ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures18252026/08/27 09:58:23 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=375.309977ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures18262026/08/27 09:58:23 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=736.976604ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures18272026/08/27 09:58:24 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.600528713s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1828--- PASS: TestClientErrorHandling (0.00s)1829 --- PASS: TestClientErrorHandling/InvalidStorePath (0.69s)1830 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.86s)1831 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.41s)1832PASS1833{"timestamp":"2026-08-27T09:58:25.866317626Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:59576","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(292)"}18342026-08-27 09:58:26.244 UTC [112] LOG: received smart shutdown request18352026-08-27 09:58:26.248 UTC [112] LOG: background worker "logical replication launcher" (PID 122) exited with exit code 118362026-08-27 09:58:26.259 UTC [117] LOG: shutting down18372026-08-27 09:58:26.260 UTC [117] LOG: checkpoint starting: shutdown immediate18382026-08-27 09:58:27.373 UTC [117] LOG: checkpoint complete: wrote 11720 buffers (71.5%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 13 recycled; write=0.225 s, sync=0.879 s, total=1.114 s; sync files=15825, longest=0.002 s, average=0.001 s; distance=217977 kB, estimate=217977 kB; lsn=0/EC424A0, redo lsn=0/EC424A018392026-08-27 09:58:27.467 UTC [112] LOG: database system is shut down1840Running OIDC tests...1841=== RUN TestGlobMatch1842=== PAUSE TestGlobMatch1843=== RUN TestAudienceForIssuer1844=== PAUSE TestAudienceForIssuer1845=== RUN TestValidateToken_ValidToken1846=== PAUSE TestValidateToken_ValidToken1847=== RUN TestValidateToken_WrongAudience1848=== PAUSE TestValidateToken_WrongAudience1849=== RUN TestValidateToken_Expired1850=== PAUSE TestValidateToken_Expired1851=== RUN TestValidateToken_BoundClaimsMismatch1852=== PAUSE TestValidateToken_BoundClaimsMismatch1853=== RUN TestValidateToken_BoundSubjectMismatch1854=== PAUSE TestValidateToken_BoundSubjectMismatch1855=== RUN TestValidateToken_MultipleProviders1856=== PAUSE TestValidateToken_MultipleProviders1857=== RUN TestValidateToken_NoMatchingProvider1858=== PAUSE TestValidateToken_NoMatchingProvider1859=== CONT TestGlobMatch1860=== RUN TestGlobMatch/foo_foo1861=== CONT TestValidateToken_BoundSubjectMismatch1862=== CONT TestValidateToken_BoundClaimsMismatch1863=== CONT TestValidateToken_NoMatchingProvider1864=== PAUSE TestGlobMatch/foo_foo1865=== RUN TestGlobMatch/foo_bar1866=== PAUSE TestGlobMatch/foo_bar1867=== RUN TestGlobMatch/*_1868=== PAUSE TestGlobMatch/*_1869=== RUN TestGlobMatch/*_anything1870=== PAUSE TestGlobMatch/*_anything1871=== CONT TestValidateToken_Expired1872=== CONT TestValidateToken_WrongAudience1873=== CONT TestValidateToken_ValidToken1874=== CONT TestAudienceForIssuer1875--- PASS: TestAudienceForIssuer (0.00s)1876=== CONT TestValidateToken_MultipleProviders1877=== RUN TestGlobMatch/foo*_foo1878=== PAUSE TestGlobMatch/foo*_foo1879=== RUN TestGlobMatch/foo*_foobar1880=== PAUSE TestGlobMatch/foo*_foobar1881=== RUN TestGlobMatch/foo*_bar1882=== PAUSE TestGlobMatch/foo*_bar1883=== RUN TestGlobMatch/*bar_bar1884=== PAUSE TestGlobMatch/*bar_bar1885=== RUN TestGlobMatch/*bar_foobar1886=== PAUSE TestGlobMatch/*bar_foobar1887=== RUN TestGlobMatch/*bar_foo1888=== PAUSE TestGlobMatch/*bar_foo1889=== RUN TestGlobMatch/foo*bar_foobar1890=== PAUSE TestGlobMatch/foo*bar_foobar1891=== RUN TestGlobMatch/foo*bar_foo123bar1892=== PAUSE TestGlobMatch/foo*bar_foo123bar1893=== RUN TestGlobMatch/foo*bar_foobarbaz1894=== PAUSE TestGlobMatch/foo*bar_foobarbaz1895=== RUN TestGlobMatch/*/*_foo/bar1896=== PAUSE TestGlobMatch/*/*_foo/bar1897=== RUN TestGlobMatch/*/*_foo1898=== PAUSE TestGlobMatch/*/*_foo1899=== RUN TestGlobMatch/refs/heads/*_refs/heads/main1900=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main1901=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.01902=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.01903=== RUN TestGlobMatch/refs/*/main_refs/heads/main1904=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main1905=== RUN TestGlobMatch/fo?_foo1906=== PAUSE TestGlobMatch/fo?_foo1907=== RUN TestGlobMatch/fo?_fo1908=== PAUSE TestGlobMatch/fo?_fo1909=== RUN TestGlobMatch/fo?_fooo1910=== PAUSE TestGlobMatch/fo?_fooo1911=== RUN TestGlobMatch/?oo_foo1912=== PAUSE TestGlobMatch/?oo_foo1913=== RUN TestGlobMatch/?oo_boo1914=== PAUSE TestGlobMatch/?oo_boo1915=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1916=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1917=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1918=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1919=== CONT TestGlobMatch/foo_foo1920=== CONT TestGlobMatch/foo*bar_foobarbaz1921=== CONT TestGlobMatch/foo*bar_foo123bar1922=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1923=== CONT TestGlobMatch/fo?_fo1924=== CONT TestGlobMatch/?oo_foo1925=== CONT TestGlobMatch/fo?_fooo1926=== CONT TestGlobMatch/refs/heads/*_refs/heads/main1927=== CONT TestGlobMatch/*/*_foo1928=== CONT TestGlobMatch/foo*bar_foobar1929=== CONT TestGlobMatch/*bar_foo1930=== CONT TestGlobMatch/*bar_foobar1931=== CONT TestGlobMatch/*bar_bar1932=== CONT TestGlobMatch/foo*_bar1933=== CONT TestGlobMatch/foo*_foobar1934=== CONT TestGlobMatch/foo*_foo1935=== CONT TestGlobMatch/*_anything1936=== CONT TestGlobMatch/*_1937=== CONT TestGlobMatch/foo_bar1938=== CONT TestGlobMatch/?oo_boo1939=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1940=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.01941=== CONT TestGlobMatch/fo?_foo1942=== CONT TestGlobMatch/*/*_foo/bar1943=== CONT TestGlobMatch/refs/*/main_refs/heads/main1944--- PASS: TestGlobMatch (0.00s)1945 --- PASS: TestGlobMatch/foo_foo (0.00s)1946 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)1947 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)1948 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)1949 --- PASS: TestGlobMatch/fo?_fo (0.00s)1950 --- PASS: TestGlobMatch/?oo_foo (0.00s)1951 --- PASS: TestGlobMatch/fo?_fooo (0.00s)1952 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)1953 --- PASS: TestGlobMatch/*/*_foo (0.00s)1954 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)1955 --- PASS: TestGlobMatch/*bar_foo (0.00s)1956 --- PASS: TestGlobMatch/*bar_foobar (0.00s)1957 --- PASS: TestGlobMatch/*bar_bar (0.00s)1958 --- PASS: TestGlobMatch/foo*_bar (0.00s)1959 --- PASS: TestGlobMatch/foo*_foobar (0.00s)1960 --- PASS: TestGlobMatch/foo*_foo (0.00s)1961 --- PASS: TestGlobMatch/*_anything (0.00s)1962 --- PASS: TestGlobMatch/*_ (0.00s)1963 --- PASS: TestGlobMatch/foo_bar (0.00s)1964 --- PASS: TestGlobMatch/?oo_boo (0.00s)1965 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)1966 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)1967 --- PASS: TestGlobMatch/fo?_foo (0.00s)1968 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)1969 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)19702026/08/27 09:58:28 INFO OIDC provider initialized name=test19712026/08/27 09:58:28 INFO OIDC provider initialized name=test19722026/08/27 09:58:28 INFO OIDC provider initialized name=test19732026/08/27 09:58:28 INFO OIDC provider initialized name=provider119742026/08/27 09:58:28 INFO OIDC provider initialized name=provider119752026/08/27 09:58:28 INFO OIDC provider initialized name=test19762026/08/27 09:58:28 INFO OIDC provider initialized name=test19772026/08/27 09:58:28 INFO OIDC provider initialized name=provider21978--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)1979--- PASS: TestValidateToken_WrongAudience (0.01s)1980--- PASS: TestValidateToken_NoMatchingProvider (0.01s)1981--- PASS: TestValidateToken_Expired (0.01s)1982--- PASS: TestValidateToken_ValidToken (0.01s)1983--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)1984--- PASS: TestValidateToken_MultipleProviders (0.01s)1985PASS1986Running hook tests...1987=== RUN TestSendPathsEmpty1988=== PAUSE TestSendPathsEmpty1989=== RUN TestQueueEnqueueAndFetch1990=== PAUSE TestQueueEnqueueAndFetch1991=== RUN TestQueueDeduplication1992=== PAUSE TestQueueDeduplication1993=== RUN TestQueueRemove1994=== PAUSE TestQueueRemove1995=== RUN TestQueueFetchBatchLimit1996=== PAUSE TestQueueFetchBatchLimit1997=== RUN TestQueueRetryMovesToBack1998=== PAUSE TestQueueRetryMovesToBack1999=== RUN TestQueueFetchRemoveLifecycle2000=== PAUSE TestQueueFetchRemoveLifecycle2001=== RUN TestQueueConcurrentWriters2002=== PAUSE TestQueueConcurrentWriters2003=== RUN TestQueueRemoveLargeClosure2004=== PAUSE TestQueueRemoveLargeClosure2005=== RUN TestServerClientIntegration2006=== PAUSE TestServerClientIntegration2007=== RUN TestServerQueueError2008=== PAUSE TestServerQueueError2009=== RUN TestGetListenerSocketActivation2010 server_test.go:210: === RUN TestGetListenerSocketActivation2011 --- PASS: TestGetListenerSocketActivation (0.00s)2012 PASS2013 2014--- PASS: TestGetListenerSocketActivation (0.01s)2015=== RUN TestDrainIsolatesPoisonPath2016=== PAUSE TestDrainIsolatesPoisonPath2017=== RUN TestRunNotBlockedByPoisonHead2018=== PAUSE TestRunNotBlockedByPoisonHead2019=== RUN TestDrainGivesUpWhenServerDown2020=== PAUSE TestDrainGivesUpWhenServerDown2021=== RUN TestFailedPathPrunedByLaterClosure2022=== PAUSE TestFailedPathPrunedByLaterClosure2023=== RUN TestWorkerUploadsAndRemoves2024=== PAUSE TestWorkerUploadsAndRemoves2025=== RUN TestWorkerSkipsGCdPaths2026=== PAUSE TestWorkerSkipsGCdPaths2027=== RUN TestWorkerPrunesClosureDeps2028=== PAUSE TestWorkerPrunesClosureDeps2029=== RUN TestDrainTimeoutStopsSlowDrain2030=== PAUSE TestDrainTimeoutStopsSlowDrain2031=== RUN TestDrainWithoutTimeoutRunsToCompletion2032=== PAUSE TestDrainWithoutTimeoutRunsToCompletion2033=== RUN TestDrainTimeoutNotWaitedOutOnSuccess2034=== PAUSE TestDrainTimeoutNotWaitedOutOnSuccess2035=== CONT TestSendPathsEmpty2036=== CONT TestDrainIsolatesPoisonPath2037=== CONT TestQueueEnqueueAndFetch2038--- PASS: TestSendPathsEmpty (0.00s)2039=== CONT TestServerQueueError2040=== CONT TestServerClientIntegration2041=== CONT TestQueueRemoveLargeClosure20422026/08/27 09:58:28 ERROR Failed to queue paths error="permission denied" count=12043=== CONT TestQueueConcurrentWriters2044=== CONT TestQueueFetchRemoveLifecycle2045=== CONT TestQueueRetryMovesToBack2046--- PASS: TestServerClientIntegration (0.00s)2047=== CONT TestQueueFetchBatchLimit2048=== CONT TestQueueRemove2049=== CONT TestQueueDeduplication2050=== CONT TestFailedPathPrunedByLaterClosure2051=== CONT TestWorkerUploadsAndRemoves2052=== CONT TestDrainGivesUpWhenServerDown2053=== CONT TestDrainWithoutTimeoutRunsToCompletion2054=== CONT TestDrainTimeoutNotWaitedOutOnSuccess2055=== CONT TestDrainTimeoutStopsSlowDrain2056=== CONT TestWorkerPrunesClosureDeps2057=== CONT TestRunNotBlockedByPoisonHead2058=== CONT TestWorkerSkipsGCdPaths2059--- PASS: TestServerQueueError (0.00s)20602026/08/27 09:58:28 INFO Upload queue status pending=320612026/08/27 09:58:28 INFO Uploading batch count=120622026/08/27 09:58:28 INFO Uploading batch count=120632026/08/27 09:58:28 ERROR Upload failed error="upload failed" count=120642026/08/27 09:58:28 INFO Upload queue status pending=220652026/08/27 09:58:28 INFO Upload queue status pending=220662026/08/27 09:58:28 INFO Uploading batch count=220672026/08/27 09:58:28 INFO Uploading batch count=12068--- PASS: TestQueueEnqueueAndFetch (0.03s)20692026/08/27 09:58:28 INFO Uploading batch count=220702026/08/27 09:58:28 ERROR Upload failed error="upload failed" count=220712026/08/27 09:58:28 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2458706500/002/a20722026/08/27 09:58:28 INFO Uploading batch count=220732026/08/27 09:58:28 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2458706500/002/b20742026/08/27 09:58:28 INFO Uploading batch count=420752026/08/27 09:58:28 ERROR Upload failed error="upload failed" count=420762026/08/27 09:58:28 INFO Uploading batch count=120772026/08/27 09:58:28 ERROR Upload failed error="upload failed" count=120782026/08/27 09:58:28 INFO Uploading batch count=22079--- PASS: TestQueueRemove (0.03s)20802026/08/27 09:58:28 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath3679510372/002/bbb2081--- PASS: TestQueueFetchRemoveLifecycle (0.03s)20822026/08/27 09:58:28 INFO Uploading batch count=220832026/08/27 09:58:28 ERROR Upload failed error="upload failed" count=220842026/08/27 09:58:28 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2458706500/002/c20852026/08/27 09:58:28 INFO Upload queue status pending=220862026/08/27 09:58:28 INFO Uploading batch count=220872026/08/27 09:58:28 INFO Uploading batch count=12088--- PASS: TestQueueRetryMovesToBack (0.03s)20892026/08/27 09:58:28 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2458706500/002/d20902026/08/27 09:58:28 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths3326699091/002/nonexistent2091--- PASS: TestQueueDeduplication (0.03s)20922026/08/27 09:58:28 INFO Uploading batch count=220932026/08/27 09:58:28 ERROR Upload failed error="upload failed" count=220942026/08/27 09:58:28 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2458706500/002/e20952026/08/27 09:58:28 INFO Uploading batch count=120962026/08/27 09:58:28 INFO Uploading batch count=12097--- PASS: TestQueueFetchBatchLimit (0.03s)20982026/08/27 09:58:28 INFO Uploading batch count=120992026/08/27 09:58:28 ERROR Upload failed error="upload failed" count=121002026/08/27 09:58:28 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2458706500/002/f21012026/08/27 09:58:28 INFO Uploading batch count=121022026/08/27 09:58:28 ERROR Upload failed error="upload failed" count=12103--- PASS: TestDrainTimeoutNotWaitedOutOnSuccess (0.03s)21042026/08/27 09:58:28 ERROR Drain finished with paths left in queue remaining=1021052026/08/27 09:58:28 INFO Uploading batch count=121062026/08/27 09:58:28 ERROR Upload failed error="upload failed" count=121072026/08/27 09:58:28 INFO Uploading batch count=12108--- PASS: TestFailedPathPrunedByLaterClosure (0.04s)21092026/08/27 09:58:28 ERROR Drain finished with paths left in queue remaining=12110--- PASS: TestDrainGivesUpWhenServerDown (0.04s)2111--- PASS: TestDrainIsolatesPoisonPath (0.04s)21122026/08/27 09:58:28 INFO Uploading batch count=12113--- PASS: TestWorkerPrunesClosureDeps (0.05s)2114--- PASS: TestWorkerUploadsAndRemoves (0.05s)2115--- PASS: TestWorkerSkipsGCdPaths (0.05s)21162026/08/27 09:58:28 INFO Uploading batch count=12117--- PASS: TestDrainWithoutTimeoutRunsToCompletion (0.07s)21182026/08/27 09:58:28 ERROR Upload failed error="context deadline exceeded" count=221192026/08/27 09:58:28 ERROR Upload failed, will retry later error="context deadline exceeded" path=/build/TestDrainTimeoutStopsSlowDrain3023362144/002/a21202026/08/27 09:58:28 ERROR Upload failed, will retry later error="context deadline exceeded" path=/build/TestDrainTimeoutStopsSlowDrain3023362144/002/b21212026/08/27 09:58:28 WARN Drain timed out timeout=200ms21222026/08/27 09:58:28 ERROR Drain finished with paths left in queue remaining=42123--- PASS: TestDrainTimeoutStopsSlowDrain (0.23s)2124--- PASS: TestQueueRemoveLargeClosure (0.34s)2125--- PASS: TestQueueConcurrentWriters (0.39s)21262026/08/27 09:58:29 INFO Uploading batch count=121272026/08/27 09:58:29 INFO Uploading batch count=121282026/08/27 09:58:29 INFO Uploading batch count=121292026/08/27 09:58:29 ERROR Upload failed error="upload failed" count=121302026/08/27 09:58:29 INFO Uploading batch count=121312026/08/27 09:58:29 ERROR Upload failed error="upload failed" count=121322026/08/27 09:58:29 INFO Uploading batch count=121332026/08/27 09:58:29 ERROR Upload failed error="upload failed" count=121342026/08/27 09:58:29 INFO Uploading batch count=121352026/08/27 09:58:29 ERROR Upload failed error="upload failed" count=121362026/08/27 09:58:29 ERROR Drain finished with paths left in queue remaining=12137--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2138PASS