Introduce logging in 'tools restore' (#10681)

Author: CyberROFL

ydb/apps/ydb/ut/ydb-dump.cpp

@@ -9,19 +9,24 @@
 
 #include <ydb/public/api/protos/ydb_table.pb.h>
 
+#include <util/stream/file.h>
+#include <util/string/printf.h>
+
 Y_UNIT_TEST_SUITE(YdbDump) {
 
 Y_UNIT_TEST(NotNullTypeDump) {
+    const char* tableName = "TableWithNotNullTypeForDump";
     RunYdb({"-v", "yql", "-s",
-        R"(CREATE TABLE TableWithNotNullTypeForDump (
+        Sprintf(R"(CREATE TABLE %s (
             k Uint32 NOT NULL,
             v String NOT NULL,
             ov String,
             PRIMARY KEY(k));
-        )"},
+        )", tableName)},
         TList<TString>());
 
-    const TString output = RunYdb({"-v", "tools", "dump", "--scheme-only"}, TList<TString>());
+    const auto dumpPath = GetOutputPath() / "dump";
+    RunYdb({"-v", "tools", "dump", "--scheme-only", "--output", dumpPath.GetPath()}, TList<TString>());
 
     struct TFlags {
         const bool HasNullFlag;
@@ -35,6 +40,7 @@ Y_UNIT_TEST(NotNullTypeDump) {
         column_flags.emplace_back(TFlags{meta.has_not_null(), meta.type().has_optional_type()});
     };
 
+    const auto output = TFileInput(dumpPath / tableName / "scheme.pb").ReadAll();
     const TString token = "columns {";
     size_t start = 0;
     while (true) {

ydb/library/backup/backup.cpp

@@ -7,7 +7,6 @@
 #include <library/cpp/regex/pcre/regexp.h>
 
 #include <util/folder/path.h>
-#include <util/generic/singleton.h>
 #include <util/stream/output.h>
 #include <util/system/file.h>
 

ydb/library/backup/backup.h

@@ -1,5 +1,3 @@
-#include <util/datetime/cputimer.h>
-
 #include "query_uploader.h"
 #include "util.h"
 
@@ -62,17 +60,12 @@ bool TUploader::Push(const TString& path, TValue&& value) {
 
             if (status.IsSuccess()) {
                 if (status.GetIssues()) {
-                    LOG_ERR("BulkUpsert has finished successfull, but has issues# {"
-                            << status.GetIssues().ToString() << "}");
+                    LOG_W("Bulk upsert was completed with issues: " << status.GetIssues().ToOneLineString());
                 }
                 return;
             // Since upsert of data is an idempotent operation it is possible to retry transport errors
             } else if (status.IsTransportError() && retry < Opts.TransportErrorsMaxRetries) {
-                LOG_DEBUG("Notice: transport error in BulkUpsert, issues# {" << status.GetIssues().ToString() << "}"
-                        << " current Retry is " << retry
-                        << " < MaxRetries# " << Opts.TransportErrorsMaxRetries
-                        << ", so sleep for " << retrySleep.Seconds() << "s"
-                        << " and try again");
+                LOG_D("Retry bulk upsert: " << status.GetIssues().ToOneLineString());
                 ++retry;
                 TInstant deadline = retrySleep.ToDeadLine();
                 while (TInstant::Now() < deadline) {
@@ -84,9 +77,7 @@ bool TUploader::Push(const TString& path, TValue&& value) {
                 retrySleep *= 2;
                 continue;
             } else {
-                LOG_ERR("Error in BulkUpsert, so stop working. Issues# {" << status.GetIssues().ToString() << "}"
-                        << " IsTransportError# " << (status.IsTransportError() ? "true" : "false")
-                        << " retries done# " << retry);
+                LOG_E("Bulk upsert failed: " << status.GetIssues().ToOneLineString());
                 PleaseStop();
                 return;
             }
@@ -136,11 +127,10 @@ bool TUploader::Push(TParams params) {
 
         if (status.IsSuccess()) {
             if (status.GetIssues()) {
-                LOG_ERR("Upload tx has finished successfull, but has issues# {"
-                    << status.GetIssues().ToString() << "}");
+                LOG_W("Write tx was completed with issues: " << status.GetIssues().ToOneLineString());
             }
         } else {
-            LOG_ERR("Error in upload tx, issues# {" << status.GetIssues().ToString() << "}");
+            LOG_E("Write tx failed: " << status.GetIssues().ToOneLineString());
             PleaseStop();
             return;
         }

ydb/library/backup/query_uploader.cpp

@@ -1,15 +1,35 @@
 #include "util.h"
 
-#include <util/generic/yexception.h>
-#include <util/string/builder.h>
-#include <util/string/cast.h>
 #include <util/generic/map.h>
+#include <util/generic/singleton.h>
+#include <util/generic/yexception.h>
 #include <util/generic/ymath.h>
+#include <util/string/cast.h>
 
 #include <ctype.h>
 
 namespace NYdb {
 
+namespace NBackup {
+
+struct TLog {
+    std::shared_ptr<::TLog> Log;
+
+    TLog()
+        : Log(std::make_shared<::TLog>(CreateLogBackend("cerr")))
+    {}
+};
+
+void SetLog(std::shared_ptr<::TLog>&& log) {
+    Singleton<TLog>()->Log = std::move(log);
+}
+
+std::shared_ptr<::TLog>& GetLog() {
+    return Singleton<TLog>()->Log;
+}
+
+} // NBackup
+
 TString RelPathFromAbsolute(TString db, TString path) {
     if (!db.StartsWith('/')) {
         db.prepend('/');
@@ -77,21 +97,4 @@ ui64 SizeFromString(TStringBuf s) {
     return FromString<ui64>(number) * it->second;
 }
 
-namespace {
-
-struct TIsVerbosePrint {
-    bool IsVerbose = false;
-};
-
-}
-
-void SetVerbosity(bool isVerbose) {
-    Singleton<TIsVerbosePrint>()->IsVerbose = isVerbose;
-}
-
-bool GetVerbosity() {
-    return Singleton<TIsVerbosePrint>()->IsVerbose;
-}
-
-
 }

ydb/library/backup/util.cpp

@@ -1,23 +1,26 @@
 #pragma once
 
-#include <util/datetime/base.h>
-#include <util/generic/string.h>
-#include <util/stream/output.h>
-#include <util/stream/null.h>
+#include <library/cpp/logger/log.h>
 
-namespace NYdb {
-
-void SetVerbosity(bool isVerbose);
-bool GetVerbosity();
+#include <util/string/builder.h>
 
-#define LOG_NULL(s) Cnull << s
-#define EXTEND_MSG(s) TInstant::Now().ToIsoStringLocal() << ": " << s << Endl
+#define LOG_IMPL(log, level, message) \
+    if (log->FiltrationLevel() >= level) { \
+        log->Write(level, TStringBuilder() << message); \
+    } \
+    Y_SEMICOLON_GUARD
 
-#define LOG_INFO(s) Cout << EXTEND_MSG(s)
-#define LOG_ERR(s) Cerr << EXTEND_MSG(s)
-#define LOG_DEBUG(s) (NYdb::GetVerbosity() ? LOG_INFO(s) : LOG_NULL(s))
+#define LOG_D(message) LOG_IMPL(NYdb::NBackup::GetLog(), ELogPriority::TLOG_DEBUG, message)
+#define LOG_I(message) LOG_IMPL(NYdb::NBackup::GetLog(), ELogPriority::TLOG_INFO, message)
+#define LOG_W(message) LOG_IMPL(NYdb::NBackup::GetLog(), ELogPriority::TLOG_WARNING, message)
+#define LOG_E(message) LOG_IMPL(NYdb::NBackup::GetLog(), ELogPriority::TLOG_ERR, message)
 
+namespace NYdb {
 
+namespace NBackup {
+    void SetLog(std::shared_ptr<::TLog>&& log);
+    std::shared_ptr<::TLog>& GetLog();
+}
 
 // Retrive path relative to database root from absolute
 TString RelPathFromAbsolute(TString db, TString path);
@@ -28,19 +31,4 @@ TString RelPathFromAbsolute(TString db, TString path);
 // Example: "2Ki" -> 2048
 ui64 SizeFromString(TStringBuf s);
 
-class TScopedTimer {
-    TInstant Start;
-    TString Msg;
-
-public:
-    TScopedTimer(const TString& msg)
-        : Start(TInstant::Now())
-        , Msg(msg)
-    {}
-
-    ~TScopedTimer() {
-        LOG_INFO(Msg << (TInstant::Now() - Start).SecondsFloat() << "s");
-    }
-};
-
 }

ydb/library/backup/util.h

@@ -2,6 +2,7 @@ LIBRARY(kikimr_backup)
 
 PEERDIR(
     library/cpp/bucket_quoter
+    library/cpp/logger
     library/cpp/regex/pcre
     library/cpp/string_utils/quote
     util

ydb/library/backup/ya.make

@@ -1,5 +1,9 @@
 #include "ydb_tools.h"
 
+#define INCLUDE_YDB_INTERNAL_H
+#include <ydb/public/sdk/cpp/client/impl/ydb_internal/logger/log.h>
+#undef INCLUDE_YDB_INTERNAL_H
+
 #include <ydb/public/lib/ydb_cli/common/normalize_path.h>
 #include <ydb/public/lib/ydb_cli/common/pg_dump_parser.h>
 #include <ydb/public/lib/ydb_cli/dump/dump.h>
@@ -94,7 +98,9 @@ int TCommandDump::Run(TConfig& config) {
         throw yexception() << "Incorrect consistency level. Available options: \"database\", \"table\"" << Endl;
     }
 
-    NYdb::SetVerbosity(config.IsVerbose());
+    auto log = std::make_shared<TLog>(CreateLogBackend("cerr", TConfig::VerbosityLevelToELogPriority(config.VerbosityLevel)));
+    log->SetFormatter(GetPrefixLogFormatter(""));
+    NYdb::NBackup::SetLog(std::move(log));
 
     try {
         TString relPath = NYdb::RelPathFromAbsolute(config.Database, Path);
@@ -196,8 +202,6 @@ void TCommandRestore::Parse(TConfig& config) {
 }
 
 int TCommandRestore::Run(TConfig& config) {
-    NYdb::SetVerbosity(config.IsVerbose());
-
     auto settings = NDump::TRestoreSettings()
         .DryRun(IsDryRun)
         .RestoreData(RestoreData)
@@ -234,7 +238,10 @@ int TCommandRestore::Run(TConfig& config) {
         settings.Mode(NDump::TRestoreSettings::EMode::ImportData);
     }
 
-    NDump::TClient client(CreateDriver(config));
+    auto log = std::make_shared<TLog>(CreateLogBackend("cerr", TConfig::VerbosityLevelToELogPriority(config.VerbosityLevel)));
+    log->SetFormatter(GetPrefixLogFormatter(""));
+
+    NDump::TClient client(CreateDriver(config), std::move(log));
     ThrowOnError(client.Restore(FilePath, Path, settings));
 
     return EXIT_SUCCESS;

ydb/public/lib/ydb_cli/commands/ydb_tools.cpp

@@ -7,6 +7,8 @@
 #include <ydb/public/sdk/cpp/client/ydb_scheme/scheme.h>
 #include <ydb/public/sdk/cpp/client/ydb_table/table.h>
 
+#include <library/cpp/logger/log.h>
+
 #include <util/string/printf.h>
 
 namespace NYdb {
@@ -23,8 +25,9 @@ TString DataFileName(ui32 id) {
 
 class TClient::TImpl {
 public:
-    explicit TImpl(const TDriver& driver)
-        : ImportClient(driver)
+    explicit TImpl(const TDriver& driver, std::shared_ptr<TLog>&& log)
+        : Log(log)
+        , ImportClient(driver)
         , OperationClient(driver)
         , SchemeClient(driver)
         , TableClient(driver)
@@ -37,11 +40,12 @@ class TClient::TImpl {
     }
 
     TRestoreResult Restore(const TString& fsPath, const TString& dbPath, const TRestoreSettings& settings) {
-        auto client = TRestoreClient(ImportClient, OperationClient, SchemeClient, TableClient);
+        auto client = TRestoreClient(*Log, ImportClient, OperationClient, SchemeClient, TableClient);
         return client.Restore(fsPath, dbPath, settings);
     }
 
 private:
+    std::shared_ptr<TLog> Log;
     NImport::TImportClient ImportClient;
     NOperation::TOperationClient OperationClient;
     NScheme::TSchemeClient SchemeClient;
@@ -60,7 +64,12 @@ TRestoreResult::TRestoreResult(TStatus&& status)
 }
 
 TClient::TClient(const TDriver& driver)
-    : Impl_(new TImpl(driver))
+    : Impl_(new TImpl(driver, std::make_shared<TLog>(CreateLogBackend("cerr"))))
+{
+}
+
+TClient::TClient(const TDriver& driver, std::shared_ptr<TLog>&& log)
+    : Impl_(new TImpl(driver, std::move(log)))
 {
 }
 

ydb/public/lib/ydb_cli/dump/dump.cpp

@@ -6,6 +6,8 @@
 
 #include <util/generic/size_literals.h>
 
+class TLog;
+
 namespace NYdb {
 namespace NDump {
 
@@ -92,6 +94,7 @@ class TClient {
 
 public:
     explicit TClient(const TDriver& driver);
+    explicit TClient(const TDriver& driver, std::shared_ptr<TLog>&& log);
 
     TDumpResult Dump(const TString& dbPath, const TString& fsPath, const TDumpSettings& settings = {});
     TRestoreResult Restore(const TString& fsPath, const TString& dbPath, const TRestoreSettings& settings = {});