*: Downgrade some logging level (#10603) (#10604)

close #10574

* Downgrade some logging level from ERROR to WARN
* Downgrade S3 returning 404 http response code cause it is expected when using HEAD to check whether an object exist or not

Signed-off-by: JaySon-Huang <tshent@qq.com>

Co-authored-by: JaySon-Huang <tshent@qq.com>

Author: ti-chi-bot

dbms/src/Common/ProfileEvents.cpp

@@ -35,8 +35,6 @@
     M(ContextLock)                             \
     M(CreatedHTTPConnections)                  \
     M(DNSError)                                \
-    M(S3ReadMicroseconds)                      \
-    M(S3WriteMicroseconds)                     \
     M(S3ReadRequestsCount)                     \
     M(S3WriteRequestsCount)                    \
     M(S3ReadRequestsErrors)                    \
@@ -45,6 +43,8 @@
     M(S3WriteRequestsThrottling)               \
     M(S3ReadRequestsRedirects)                 \
     M(S3WriteRequestsRedirects)                \
+    M(S3ReadRequestsNotFound)                  \
+    M(S3WriteRequestsNotFound)                 \
                                                \
     M(RWLockAcquiredReadLocks)                 \
     M(RWLockAcquiredWriteLocks)                \

dbms/src/Flash/ResourceControl/LocalAdmissionController.cpp

@@ -491,7 +491,7 @@ void LocalAdmissionController::requestGACLoop()
         }
         catch (...)
         {
-            LOG_ERROR(
+            LOG_WARNING(
                 log,
                 "doRequestGAC got error: {}, retry {} sec later",
                 getCurrentExceptionMessage(false),

dbms/src/Storages/KVStore/tests/gtest_kvstore_fast_add_peer.cpp

@@ -788,8 +788,10 @@ try
 }
 CATCH
 
+// FIXME: Disabled because the flaky test result errors in CI.
+// And we don't plan to support enable FAP in short time.
 // Test cancel and regular snapshot
-TEST_F(RegionKVStoreTestFAP, Cancel4)
+TEST_F(RegionKVStoreTestFAP, DISABLED_Cancel4)
 try
 {
     using namespace std::chrono_literals;
@@ -856,7 +858,7 @@ try
 CATCH
 
 // Test cancel when building segments
-TEST_F(RegionKVStoreTestFAP, Cancel5)
+TEST_F(RegionKVStoreTestFAP, DISABLED_Cancel5)
 try
 {
     auto mock_data = prepareForRestart(FAPTestOpt{.second_region = true});

dbms/src/Storages/S3/FileCache.cpp

@@ -733,7 +733,7 @@ void FileCache::downloadImpl(const String & s3_key, FileSegmentPtr & file_seg)
         sw.elapsedMilliseconds());
 }
 
-void FileCache::download(const String & s3_key, FileSegmentPtr & file_seg)
+void FileCache::bgDownloadExecutor(const String & s3_key, FileSegmentPtr & file_seg)
 {
     try
     {
@@ -742,7 +742,8 @@ void FileCache::download(const String & s3_key, FileSegmentPtr & file_seg)
     }
     catch (...)
     {
-        tryLogCurrentException(log, fmt::format("Download s3_key={} failed", s3_key));
+        // ignore the exception here, and log as warning.
+        tryLogCurrentWarningException(log, fmt::format("Download s3_key={} failed", s3_key));
     }
 
     if (!file_seg->isReadyToRead())
@@ -774,7 +775,7 @@ void FileCache::bgDownload(const String & s3_key, FileSegmentPtr & file_seg)
         bg_downloading_count.load(std::memory_order_relaxed),
         s3_key);
     S3FileCachePool::get().scheduleOrThrowOnError(
-        [this, s3_key = s3_key, file_seg = file_seg]() mutable { download(s3_key, file_seg); });
+        [this, s3_key = s3_key, file_seg = file_seg]() mutable { bgDownloadExecutor(s3_key, file_seg); });
 }
 
 void FileCache::fgDownload(const String & s3_key, FileSegmentPtr & file_seg)

dbms/src/Storages/S3/FileCache.h

@@ -265,7 +265,7 @@ class FileCache
 
     void bgDownload(const String & s3_key, FileSegmentPtr & file_seg);
     void fgDownload(const String & s3_key, FileSegmentPtr & file_seg);
-    void download(const String & s3_key, FileSegmentPtr & file_seg);
+    void bgDownloadExecutor(const String & s3_key, FileSegmentPtr & file_seg);
     void downloadImpl(const String & s3_key, FileSegmentPtr & file_seg);
 
     static String toTemporaryFilename(const String & fname);

dbms/src/Storages/S3/PocoHTTPClient.cpp

@@ -38,24 +38,25 @@
 
 #include <algorithm>
 #include <functional>
+#include <magic_enum.hpp>
 #include <utility>
 
 static const int SUCCESS_RESPONSE_MIN = 200;
 static const int SUCCESS_RESPONSE_MAX = 299;
 
 namespace ProfileEvents
 {
-extern const Event S3ReadMicroseconds;
 extern const Event S3ReadRequestsCount;
 extern const Event S3ReadRequestsErrors;
 extern const Event S3ReadRequestsThrottling;
 extern const Event S3ReadRequestsRedirects;
+extern const Event S3ReadRequestsNotFound;
 
-extern const Event S3WriteMicroseconds;
 extern const Event S3WriteRequestsCount;
 extern const Event S3WriteRequestsErrors;
 extern const Event S3WriteRequestsThrottling;
 extern const Event S3WriteRequestsRedirects;
+extern const Event S3WriteRequestsNotFound;
 
 extern const Event S3GetRequestThrottlerCount;
 extern const Event S3GetRequestThrottlerSleepMicroseconds;
@@ -175,14 +176,14 @@ PocoHTTPClient::S3MetricKind PocoHTTPClient::getMetricKind(const Aws::Http::Http
 
 void PocoHTTPClient::addMetric(const Aws::Http::HttpRequest & request, S3MetricType type, ProfileEvents::Count amount)
 {
-    const ProfileEvents::Event events_map[static_cast<size_t>(S3MetricType::EnumSize)]
-                                         [static_cast<size_t>(S3MetricKind::EnumSize)]
+    const ProfileEvents::Event events_map[magic_enum::enum_count<S3MetricType>()]
+                                         [magic_enum::enum_count<S3MetricKind>()]
         = {
-            {ProfileEvents::S3ReadMicroseconds, ProfileEvents::S3WriteMicroseconds},
             {ProfileEvents::S3ReadRequestsCount, ProfileEvents::S3WriteRequestsCount},
             {ProfileEvents::S3ReadRequestsErrors, ProfileEvents::S3WriteRequestsErrors},
             {ProfileEvents::S3ReadRequestsThrottling, ProfileEvents::S3WriteRequestsThrottling},
             {ProfileEvents::S3ReadRequestsRedirects, ProfileEvents::S3WriteRequestsRedirects},
+            {ProfileEvents::S3ReadRequestsNotFound, ProfileEvents::S3WriteRequestsNotFound},
         };
 
     S3MetricKind kind = getMetricKind(request);
@@ -272,6 +273,7 @@ void PocoHTTPClient::makeRequestInternal(
     }
 }
 
+// Return redirect uri if redirect happens, otherwise return nullopt
 template <typename Session>
 std::optional<String> PocoHTTPClient::makeRequestOnce(
     const Poco::URI & target_uri,
@@ -342,8 +344,6 @@ std::optional<String> PocoHTTPClient::makeRequestOnce(
     for (const auto & [header_name, header_value] : extra_headers)
         poco_request.set(boost::algorithm::to_lower_copy(header_name), header_value);
 
-    Poco::Net::HTTPResponse poco_response;
-
     Stopwatch watch;
 
     Poco::Net::HTTPSendMetrics metrics;
@@ -372,28 +372,38 @@ std::optional<String> PocoHTTPClient::makeRequestOnce(
 
     if (enable_s3_requests_logging)
         LOG_DEBUG(tracing_logger, "Receiving response...");
+    Poco::Net::HTTPResponse poco_response;
     auto & response_body_stream = session->receiveResponse(poco_response);
     GET_METRIC(tiflash_storage_s3_http_request_seconds, type_response)
         .Observe(watch.elapsedMillisecondsFromLastTime() / 1000.0);
 
     int status_code = static_cast<int>(poco_response.getStatus());
-    if (status_code >= SUCCESS_RESPONSE_MIN && status_code <= SUCCESS_RESPONSE_MAX)
+    if (status_code >= SUCCESS_RESPONSE_MIN && status_code <= SUCCESS_RESPONSE_MAX) // 2xx
     {
         if (enable_s3_requests_logging)
             LOG_DEBUG(tracing_logger, "Response status: {}, {}", status_code, poco_response.getReason());
     }
+    else if (status_code == Poco::Net::HTTPResponse::HTTP_NOT_FOUND) // 404
+    {
+        /// 404 Not Found is a valid response for some requests (e.g., GET/HEAD of non-existing object)
+        /// so we just log it at DEBUG level when `enable_s3_requests_logging` is on.
+        if (enable_s3_requests_logging)
+            LOG_DEBUG(tracing_logger, "Response status: {}, {}", status_code, poco_response.getReason());
+    }
     else
     {
         /// Error statuses are more important so we show them even if `enable_s3_requests_logging == false`.
         LOG_INFO(tracing_logger, "Response status: {}, {}", status_code, poco_response.getReason());
     }
+
+    // handle redirect status codes
     if (poco_response.getStatus() == Poco::Net::HTTPResponse::HTTP_TEMPORARY_REDIRECT
         || poco_response.getStatus() == Poco::Net::HTTPResponse::HTTP_FOUND)
     {
         auto location = poco_response.get("location");
         remote_host_filter->checkURL(Poco::URI(location));
         if (enable_s3_requests_logging)
-            LOG_DEBUG(tracing_logger, "Redirecting request to new location: {}", location);
+            LOG_INFO(tracing_logger, "Redirecting request to new location: {}", location);
 
         addMetric(request, S3MetricType::Redirects);
 
@@ -420,7 +430,7 @@ std::optional<String> PocoHTTPClient::makeRequestOnce(
             response->AddHeader(header_name, header_value);
     }
 
-    /// Request is successful but for some special requests we can have actual error message in body
+    /// Request is successful (2xx) but for some special requests we can have actual error message in body
     if (status_code >= SUCCESS_RESPONSE_MIN && status_code <= SUCCESS_RESPONSE_MAX
         && checkRequestCanReturn2xxAndErrorInBody(request))
     {
@@ -456,10 +466,20 @@ std::optional<String> PocoHTTPClient::makeRequestOnce(
     }
     else
     {
-        if (status_code == 429 || status_code == 503)
-        { // API throttling
+        if (status_code == Poco::Net::HTTPResponse::HTTP_TOO_MANY_REQUESTS
+            || status_code == Poco::Net::HTTPResponse::HTTP_SERVICE_UNAVAILABLE)
+        {
+            // API throttling from the server side
+            // 429 Too Many Requests
+            // 503 Service Unavailable
             addMetric(request, S3MetricType::Throttling);
         }
+        else if (status_code == Poco::Net::HTTPResponse::HTTP_NOT_FOUND)
+        {
+            // Get/Head request to a non-existing object, returning 404 Not Found
+            // is a valid response.
+            addMetric(request, S3MetricType::ErrorNotFound);
+        }
         else if (status_code >= 300)
         {
             addMetric(request, S3MetricType::Errors);

dbms/src/Storages/S3/PocoHTTPClient.h

@@ -26,7 +26,6 @@
 #include <aws/core/http/standard/StandardHttpResponse.h>
 
 #include <string>
-#include <vector>
 
 namespace Aws::Http::Standard
 {
@@ -141,21 +140,17 @@ class PocoHTTPClient : public Aws::Http::HttpClient
 
     enum class S3MetricType
     {
-        Microseconds,
         Count,
         Errors,
         Throttling,
         Redirects,
-
-        EnumSize,
+        ErrorNotFound,
     };
 
     enum class S3MetricKind
     {
         Read,
         Write,
-
-        EnumSize,
     };
 
     static S3MetricKind getMetricKind(const Aws::Http::HttpRequest & request);

dbms/src/Storages/StorageDisaggregatedRemote.cpp

@@ -288,28 +288,29 @@ void StorageDisaggregated::buildReadTaskForWriteNode(
             for (const auto & region_id : error.region_ids())
                 retry_regions.insert(region_id);
 
-            LOG_INFO(
-                log,
-                "Received EstablishDisaggregated response with retryable error: {}, addr={} retry_regions={}",
+            String error_msg = fmt::format(
+                "Received EstablishDisaggTask response with retryable error: {}, addr={} retry_regions={}",
                 error.msg(),
                 batch_cop_task.store_addr,
                 retry_regions);
+            LOG_INFO(log, error_msg);
 
             dropRegionCache(cluster->region_cache, req, std::move(retry_regions));
 
-            throw Exception(error.msg(), ErrorCodes::DISAGG_ESTABLISH_RETRYABLE_ERROR);
+            throw Exception(error_msg, ErrorCodes::DISAGG_ESTABLISH_RETRYABLE_ERROR);
         }
         else if (resp.error().has_error_locked())
         {
             using namespace pingcap;
 
             const auto & error = resp.error().error_locked();
 
-            LOG_INFO(
-                log,
-                "Received EstablishDisaggregated response with retryable error: {}, addr={}",
+            String error_msg = fmt::format(
+                "Received EstablishDisaggTask response with retryable error: {}, addr={} lock_info_size={}",
                 error.msg(),
-                batch_cop_task.store_addr);
+                batch_cop_task.store_addr,
+                error.locked().size());
+            LOG_INFO(log, error_msg);
 
             Stopwatch w_resolve_lock;
 
@@ -337,7 +338,7 @@ void StorageDisaggregated::buildReadTaskForWriteNode(
             GET_METRIC(tiflash_disaggregated_breakdown_duration_seconds, type_resolve_lock)
                 .Observe(w_resolve_lock.elapsedSeconds());
 
-            throw Exception(error.msg(), ErrorCodes::DISAGG_ESTABLISH_RETRYABLE_ERROR);
+            throw Exception(error_msg, ErrorCodes::DISAGG_ESTABLISH_RETRYABLE_ERROR);
         }
         else
         {

dbms/src/TiDB/Schema/SchemaSyncService.cpp

@@ -109,7 +109,7 @@ void SchemaSyncService::addKeyspaceGCTasks()
                 }
                 catch (const Exception & e)
                 {
-                    LOG_ERROR(
+                    LOG_WARNING(
                         ks_log,
                         "{}, keyspace={} failed by {} \n stack : {}",
                         stage,
@@ -119,11 +119,11 @@ void SchemaSyncService::addKeyspaceGCTasks()
                 }
                 catch (const Poco::Exception & e)
                 {
-                    LOG_ERROR(ks_log, "{}, keyspace={} failed by {}", stage, keyspace, e.displayText());
+                    LOG_WARNING(ks_log, "{}, keyspace={} failed by {}", stage, keyspace, e.displayText());
                 }
                 catch (const std::exception & e)
                 {
-                    LOG_ERROR(ks_log, "{}, keyspace={} failed by {}", stage, keyspace, e.what());
+                    LOG_WARNING(ks_log, "{}, keyspace={} failed by {}", stage, keyspace, e.what());
                 }
                 return false;
             },