Skip to content

Commit f122b64

Browse files
author
bykhovtsev
committed
feat grpc: add src tvm id to access log
Creates a LogExtra variable with which various middleware can add additional fields to the access TSKV log. Adds functionality to grpc-tvm2 middleware for sending src_tvm_id to access-log commit_hash:657539303432ee5d280f95bbe334c903f5cdab48
1 parent 16558d2 commit f122b64

File tree

12 files changed

+268
-43
lines changed

12 files changed

+268
-43
lines changed

‎.mapping.json‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4810,6 +4810,7 @@
48104810
"universal/include/userver/logging/format.hpp":"taxi/uservices/userver/universal/include/userver/logging/format.hpp",
48114811
"universal/include/userver/logging/fwd.hpp":"taxi/uservices/userver/universal/include/userver/logging/fwd.hpp",
48124812
"universal/include/userver/logging/impl/formatters/base.hpp":"taxi/uservices/userver/universal/include/userver/logging/impl/formatters/base.hpp",
4813+
"universal/include/userver/logging/impl/log_extra_tskv_formatter.hpp":"taxi/uservices/userver/universal/include/userver/logging/impl/log_extra_tskv_formatter.hpp",
48134814
"universal/include/userver/logging/impl/logger_base.hpp":"taxi/uservices/userver/universal/include/userver/logging/impl/logger_base.hpp",
48144815
"universal/include/userver/logging/impl/mem_logger.hpp":"taxi/uservices/userver/universal/include/userver/logging/impl/mem_logger.hpp",
48154816
"universal/include/userver/logging/impl/tag_writer.hpp":"taxi/uservices/userver/universal/include/userver/logging/impl/tag_writer.hpp",
@@ -5090,6 +5091,7 @@
50905091
"universal/src/logging/impl/formatters/struct.hpp":"taxi/uservices/userver/universal/src/logging/impl/formatters/struct.hpp",
50915092
"universal/src/logging/impl/formatters/tskv.cpp":"taxi/uservices/userver/universal/src/logging/impl/formatters/tskv.cpp",
50925093
"universal/src/logging/impl/formatters/tskv.hpp":"taxi/uservices/userver/universal/src/logging/impl/formatters/tskv.hpp",
5094+
"universal/src/logging/impl/log_extra_tskv_formatter.cpp":"taxi/uservices/userver/universal/src/logging/impl/log_extra_tskv_formatter.cpp",
50935095
"universal/src/logging/impl/logger_base.cpp":"taxi/uservices/userver/universal/src/logging/impl/logger_base.cpp",
50945096
"universal/src/logging/impl/mem_logger.cpp":"taxi/uservices/userver/universal/src/logging/impl/mem_logger.cpp",
50955097
"universal/src/logging/impl/tag_writer.cpp":"taxi/uservices/userver/universal/src/logging/impl/tag_writer.cpp",

‎grpc/benchmarks/format_log_message.cpp‎

Lines changed: 18 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
#include <ugrpc/server/impl/format_log_message.hpp>
22

3+
#include <userver/logging/log_extra.hpp>
34
#include <userver/utils/assert.hpp>
45
#include <userver/utils/text_light.hpp>
56

@@ -16,29 +17,34 @@ void FormatLogMessage(benchmark::State& state) {
1617
std::string peer = "2a02:aaaa:aaaa:aaaa::1:1f";
1718
std::chrono::system_clock::time_point start_time(std::chrono::seconds{1024 * 1024 * 42});
1819
std::string_view call_name = "hello.HelloService/SayHello";
20+
logging::LogExtra log_extra;
1921

2022
// NOLINTNEXTLINE(clang-analyzer-deadcode.DeadStores)
2123
for (auto _ : state) {
22-
auto result =
23-
ugrpc::server::impl::FormatLogMessage(metadata, peer, start_time, call_name, grpc::StatusCode::OK);
24+
auto result = ugrpc::server::impl::FormatLogMessage(
25+
metadata, peer, start_time, call_name, grpc::StatusCode::OK, log_extra
26+
);
2427
benchmark::DoNotOptimize(result);
2528
}
2629

27-
auto result = ugrpc::server::impl::FormatLogMessage(metadata, peer, start_time, call_name, grpc::StatusCode::OK);
30+
auto result =
31+
ugrpc::server::impl::FormatLogMessage(metadata, peer, start_time, call_name, grpc::StatusCode::OK, log_extra);
2832

29-
UINVARIANT(utils::text::StartsWith(result, "tskv\ttimestamp=1971-05-"), "Fail");
30-
UINVARIANT(result.find("\ttimezone=") != std::string::npos, "Fail 1");
33+
const std::string_view log_line_view{result.ExtractTextLogItem().log_line}; // Convert SmallString to string_view
34+
35+
UINVARIANT(utils::text::StartsWith(log_line_view, "tskv\ttimestamp=1971-05-"), "Fail");
36+
UINVARIANT(log_line_view.find("\ttimezone=") != std::string::npos, "Fail 1");
3137
UINVARIANT(
32-
result.find("\tuser_agent=grpc-go/1.45.0\t"
33-
"ip=2a02:aaaa:aaaa:aaaa::1:1f\t"
34-
"x_real_ip=2a02:aaaa:aaaa:aaaa::1:1f\t"
35-
"request=hello.HelloService/SayHello\t"
36-
"request_time=") != std::string::npos,
38+
log_line_view.find("\tuser_agent=grpc-go/1.45.0\t"
39+
"ip=2a02:aaaa:aaaa:aaaa::1:1f\t"
40+
"x_real_ip=2a02:aaaa:aaaa:aaaa::1:1f\t"
41+
"request=hello.HelloService/SayHello\t"
42+
"request_time=") != std::string::npos,
3743
"Fail 2"
3844
);
3945

40-
UINVARIANT(result.find("\tgrpc_status=0\t") != std::string::npos, "Fail 3");
41-
UINVARIANT(result.find("\tgrpc_status_code=OK\n") != std::string::npos, "Fail 4");
46+
UINVARIANT(log_line_view.find("\tgrpc_status=0\t") != std::string::npos, "Fail 3");
47+
UINVARIANT(log_line_view.find("\tgrpc_status_code=OK\n") != std::string::npos, "Fail 4");
4248
}
4349

4450
BENCHMARK(FormatLogMessage);

‎grpc/include/userver/ugrpc/server/middlewares/access_log/component.hpp‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,10 @@ USERVER_NAMESPACE_BEGIN
1414
/// @see @ref ugrpc::server::middlewares::access_log::Component
1515
namespace ugrpc::server::middlewares::access_log {
1616

17+
/// @brief Storage to handle additional fields in access_log
18+
/// @snippet grpc/tests/logging_test.cpp
19+
inline const utils::AnyStorageDataTag<ugrpc::server::StorageContext, logging::LogExtra> kLogExtraTag;
20+
1721
/// @ingroup userver_components userver_base_classes
1822
///
1923
/// @brief gRPC server access log middleware component. Writes one TSKV log line per handled RPC in a static format.

‎grpc/src/ugrpc/server/impl/format_log_message.cpp‎

Lines changed: 14 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -5,9 +5,11 @@
55
#include <fmt/format.h>
66

77
#include <userver/compiler/thread_local.hpp>
8+
#include <userver/logging/impl/logger_base.hpp>
89
#include <userver/ugrpc/impl/to_string.hpp>
910
#include <userver/utils/datetime.hpp>
1011
#include <userver/utils/encoding/tskv.hpp>
12+
#include <userver/utils/impl/source_location.hpp>
1113
#include <userver/utils/text_light.hpp>
1214

1315
USERVER_NAMESPACE_BEGIN
@@ -66,12 +68,13 @@ std::string_view GetCurrentTimeString(std::chrono::system_clock::time_point star
6668

6769
} // namespace
6870

69-
std::string FormatLogMessage(
71+
logging::impl::LogExtraTskvFormatter FormatLogMessage(
7072
const std::multimap<grpc::string_ref, grpc::string_ref>& metadata,
7173
std::string_view peer,
7274
std::chrono::system_clock::time_point start_time,
7375
std::string_view call_name,
74-
grpc::StatusCode code
76+
grpc::StatusCode code,
77+
const logging::LogExtra& log_extra
7578
) {
7679
static const auto timezone = utils::datetime::LocalTimezoneTimestring(start_time, "%z");
7780

@@ -88,9 +91,10 @@ std::string FormatLogMessage(
8891
const auto request_time_seconds = std::chrono::duration_cast<std::chrono::seconds>(request_time);
8992
const auto request_time_milliseconds = request_time - request_time_seconds;
9093

91-
// FMT_COMPILE makes it slower
92-
return fmt::format(
93-
"tskv"
94+
logging::impl::LogExtraTskvFormatter formatter(logging::Format::kRaw);
95+
96+
fmt::format_to(
97+
std::back_inserter(formatter.GetTextLogItem().log_line),
9498
"\ttimestamp={}"
9599
"\ttimezone={}"
96100
"\tuser_agent={}"
@@ -100,16 +104,13 @@ std::string FormatLogMessage(
100104
"\trequest_time={}.{:0>3}"
101105
"\tupstream_response_time={}.{:0>3}"
102106
"\tgrpc_status={}"
103-
"\tgrpc_status_code={}\n",
107+
"\tgrpc_status_code={}",
104108
GetCurrentTimeString(start_time),
105109
timezone,
106110
EscapeForAccessTskvLog(user_agent),
107111
ip,
108112
ip,
109113
EscapeForAccessTskvLog(call_name),
110-
// request_time should represent the time from the first byte received to the last byte sent.
111-
// We are currently being inexact here by not including the time for initial request deserialization
112-
// and the time for the final response serialization.
113114
request_time_seconds.count(),
114115
request_time_milliseconds.count(),
115116
// TODO remove, this is for safe migration from old access log parsers.
@@ -118,6 +119,10 @@ std::string FormatLogMessage(
118119
static_cast<int>(code),
119120
ToString(code)
120121
);
122+
123+
formatter.Append(log_extra);
124+
125+
return formatter;
121126
}
122127

123128
} // namespace ugrpc::server::impl

‎grpc/src/ugrpc/server/impl/format_log_message.hpp‎

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -4,18 +4,22 @@
44
#include <grpcpp/support/string_ref.h>
55

66
#include <userver/dynamic_config/snapshot.hpp>
7+
#include <userver/logging/impl/log_extra_tskv_formatter.hpp>
8+
#include <userver/logging/impl/logger_base.hpp>
9+
#include <userver/logging/log_extra.hpp>
710
#include <userver/ugrpc/status_codes.hpp>
811

912
USERVER_NAMESPACE_BEGIN
1013

1114
namespace ugrpc::server::impl {
1215

13-
std::string FormatLogMessage(
16+
logging::impl::LogExtraTskvFormatter FormatLogMessage(
1417
const std::multimap<grpc::string_ref, grpc::string_ref>& metadata,
1518
std::string_view peer,
1619
std::chrono::system_clock::time_point start_time,
1720
std::string_view call_name,
18-
grpc::StatusCode code
21+
grpc::StatusCode code,
22+
const logging::LogExtra& log_extra
1923
);
2024

2125
} // namespace ugrpc::server::impl

‎grpc/src/ugrpc/server/middlewares/access_log/middleware.cpp‎

Lines changed: 19 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -21,14 +21,20 @@ void WriteAccessLog(
2121
constexpr auto kLevel = logging::Level::kInfo;
2222

2323
if (access_tskv_logger.ShouldLog(kLevel)) {
24-
logging::impl::TextLogItem log_item{impl::FormatLogMessage(
25-
server_context.client_metadata(),
26-
server_context.peer(),
27-
context.GetSpan().GetStartSystemTime(),
28-
context.GetCallName(),
29-
status.error_code()
30-
)};
31-
access_tskv_logger.Log(kLevel, log_item);
24+
const auto& log_extra = context.GetStorageContext().Get(kLogExtraTag);
25+
26+
access_tskv_logger.Log(
27+
kLevel,
28+
impl::FormatLogMessage(
29+
server_context.client_metadata(),
30+
server_context.peer(),
31+
context.GetSpan().GetStartSystemTime(),
32+
context.GetCallName(),
33+
status.error_code(),
34+
log_extra
35+
)
36+
.ExtractTextLogItem()
37+
);
3238
}
3339
} catch (const std::exception& ex) {
3440
LOG_ERROR() << "Error in WriteAccessLog: " << ex;
@@ -39,6 +45,11 @@ void WriteAccessLog(
3945

4046
Middleware::Middleware(Settings&& settings) : logger_(std::move(settings.access_tskv_logger)) {}
4147

48+
void Middleware::OnCallStart(MiddlewareCallContext& context) const {
49+
// Add common storage to extra log tags for other middlewares
50+
context.GetStorageContext().Emplace(kLogExtraTag, logging::LogExtra{});
51+
}
52+
4253
void Middleware::OnCallFinish(MiddlewareCallContext& context, const grpc::Status& status) const {
4354
WriteAccessLog(context, status, *logger_);
4455
}

‎grpc/src/ugrpc/server/middlewares/access_log/middleware.hpp‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@
22

33
#include <userver/logging/fwd.hpp>
44

5+
#include <userver/ugrpc/server/middlewares/access_log/component.hpp>
56
#include <userver/ugrpc/server/middlewares/base.hpp>
67

78
USERVER_NAMESPACE_BEGIN
@@ -16,6 +17,8 @@ class Middleware final : public MiddlewareBase {
1617
public:
1718
explicit Middleware(Settings&& settings);
1819

20+
void OnCallStart(MiddlewareCallContext& context) const override;
21+
1922
void OnCallFinish(MiddlewareCallContext& context, const grpc::Status& status) const override;
2023

2124
private:

‎grpc/tests/logging_test.cpp‎

Lines changed: 76 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,28 @@ USERVER_NAMESPACE_BEGIN
1515

1616
namespace {
1717

18+
constexpr std::string_view kBaseTskvPattern = R"(tskv\t)"
19+
R"(timestamp=\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\t)"
20+
R"(timezone=[-+]\d{2}\d{2}\t)"
21+
R"(user_agent=.+\t)"
22+
R"(ip=[.0-9a-f:\[\]]+\:[0-9]+\t)"
23+
R"(x_real_ip=[.0-9a-f:\[\]]+\:[0-9]+\t)"
24+
R"(request=[a-zA-Z./0-9]+\t)"
25+
R"(request_time=\d+\.\d+\t)"
26+
R"(upstream_response_time=\d+\.\d+\t)"
27+
R"(grpc_status=\d+\t)"
28+
R"(grpc_status_code=[A-Z_]+)";
29+
30+
const utils::regex kBaseTskvRegex{std::string{kBaseTskvPattern} + R"(\n)"};
31+
32+
// Constant to check result of LogExtra middleware
33+
const utils::regex kTskvWithTagsRegex{
34+
std::string{kBaseTskvPattern} + R"(\tuser_id=12345)"
35+
R"(\tsession_id=abc-def-ghi)"
36+
R"(\trequest_id=req-98765)"
37+
R"(\tcustom_tag=test-value)"
38+
R"(\tnumeric_tag=42\n)"};
39+
1840
class UnitTestService final : public sample::ugrpc::UnitTestServiceBase {
1941
public:
2042
SayHelloResult SayHello(CallContext& /*context*/, sample::ugrpc::GreetingRequest&& request) override {
@@ -48,9 +70,51 @@ class ServiceWithAccessLogFixture : public ugrpc::tests::ServiceFixtureBase {
4870
GrpcService service_{};
4971
};
5072

73+
// Test middleware that adds custom tags to LogExtra
74+
class TagsMiddleware final : public ugrpc::server::MiddlewareBase {
75+
public:
76+
void OnCallStart(ugrpc::server::MiddlewareCallContext& context) const override {
77+
auto* log_extra = context.GetStorageContext().GetOptional(ugrpc::server::middlewares::access_log::kLogExtraTag);
78+
79+
if (log_extra) {
80+
log_extra->Extend("user_id", "12345");
81+
log_extra->Extend("session_id", "abc-def-ghi");
82+
log_extra->Extend("request_id", "req-98765");
83+
log_extra->Extend("custom_tag", "test-value");
84+
log_extra->Extend("numeric_tag", "42");
85+
}
86+
}
87+
};
88+
89+
template <typename GrpcService>
90+
class ServiceWithAccessLogTagsFixture : public ugrpc::tests::ServiceFixtureBase {
91+
public:
92+
ServiceWithAccessLogTagsFixture() {
93+
ugrpc::server::middlewares::access_log::Settings access_log_settings;
94+
access_log_settings.access_tskv_logger = access_logger_.GetLogger();
95+
96+
SetServerMiddlewares({
97+
std::make_shared<ugrpc::server::middlewares::access_log::Middleware>(std::move(access_log_settings)),
98+
std::make_shared<TagsMiddleware>(),
99+
});
100+
101+
RegisterService(service_);
102+
StartServer();
103+
}
104+
105+
~ServiceWithAccessLogTagsFixture() override { StopServer(); }
106+
107+
utest::LogCaptureLogger& AccessLog() { return access_logger_; }
108+
109+
private:
110+
utest::LogCaptureLogger access_logger_{logging::Format::kRaw};
111+
GrpcService service_{};
112+
};
113+
51114
} // namespace
52115

53116
using GrpcAccessLog = ServiceWithAccessLogFixture<UnitTestService>;
117+
using GrpcAccessLogWithTags = ServiceWithAccessLogTagsFixture<UnitTestService>;
54118

55119
UTEST_F(GrpcAccessLog, Test) {
56120
auto client = MakeClient<sample::ugrpc::UnitTestServiceClient>();
@@ -60,20 +124,20 @@ UTEST_F(GrpcAccessLog, Test) {
60124

61125
GetServer().StopServing();
62126

63-
constexpr std::string_view kExpectedPattern = R"(tskv\t)"
64-
R"(timestamp=\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\t)"
65-
R"(timezone=[-+]\d{2}\d{2}\t)"
66-
R"(user_agent=.+\t)"
67-
R"(ip=[.0-9a-f:\[\]]+\:[0-9]+\t)"
68-
R"(x_real_ip=[.0-9a-f:\[\]]+\:[0-9]+\t)"
69-
R"(request=[a-zA-Z./0-9]+\t)"
70-
R"(request_time=\d+\.\d+\t)"
71-
R"(upstream_response_time=\d+\.\d+\t)"
72-
R"(grpc_status=\d+\t)"
73-
R"(grpc_status_code=[A-Z_]+\n)";
127+
const auto logs = GetSingleLog(AccessLog().GetAll());
128+
EXPECT_TRUE(utils::regex_match(logs.GetLogRaw(), kBaseTskvRegex)) << logs;
129+
}
130+
131+
UTEST_F(GrpcAccessLogWithTags, TestWithCustomTags) {
132+
auto client = MakeClient<sample::ugrpc::UnitTestServiceClient>();
133+
sample::ugrpc::GreetingRequest out;
134+
out.set_name("userver");
135+
auto response = client.SayHello(out);
136+
137+
GetServer().StopServing();
74138

75139
const auto logs = GetSingleLog(AccessLog().GetAll());
76-
EXPECT_TRUE(utils::regex_match(logs.GetLogRaw(), utils::regex(kExpectedPattern))) << logs;
140+
EXPECT_TRUE(utils::regex_match(logs.GetLogRaw(), kTskvWithTagsRegex)) << logs;
77141
}
78142

79143
USERVER_NAMESPACE_END

‎universal/include/userver/logging/impl/log_extra_tskv_formatter.hpp‎

Lines changed: 45 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,45 @@
1+
#pragma once
2+
3+
#include <string_view>
4+
5+
#include <userver/logging/format.hpp>
6+
#include <userver/logging/impl/formatters/base.hpp>
7+
#include <userver/logging/impl/logger_base.hpp>
8+
#include <userver/logging/log_extra.hpp>
9+
#include <userver/utils/box.hpp>
10+
11+
USERVER_NAMESPACE_BEGIN
12+
13+
namespace logging::impl {
14+
15+
namespace formatters {
16+
class Tskv;
17+
} // namespace formatters
18+
19+
using TskvPtr = utils::Box<formatters::Tskv>;
20+
21+
class LogExtraTskvFormatter final {
22+
public:
23+
explicit LogExtraTskvFormatter(logging::Format format);
24+
25+
LogExtraTskvFormatter(LogExtraTskvFormatter&&) noexcept;
26+
27+
LogExtraTskvFormatter& operator=(LogExtraTskvFormatter&&) noexcept;
28+
29+
~LogExtraTskvFormatter();
30+
31+
void Append(const LogExtra& log_extra);
32+
33+
// Returns log line
34+
TextLogItem& GetTextLogItem();
35+
36+
// Finishes log line and returns it
37+
TextLogItem& ExtractTextLogItem();
38+
39+
private:
40+
TskvPtr formatter_;
41+
};
42+
43+
} // namespace logging::impl
44+
45+
USERVER_NAMESPACE_END

0 commit comments

Comments
 (0)