Skip to content

Commit 1353f57

Browse files
vladstepanyukvladstepanyuk
authored
issue-17863: added file name and line number to log (#17864)
1 parent 2972922 commit 1353f57

File tree

9 files changed

+305
-91
lines changed

9 files changed

+305
-91
lines changed

‎ydb/core/blob_depot/types.h

+1-1
Original file line numberDiff line numberDiff line change
@@ -292,7 +292,7 @@ namespace NKikimr::NBlobDepot {
292292
NJson::TJsonWriter __json(&__stream, false); \
293293
::NKikimr::NStLog::TMessage<MARKER>("", 0, #MARKER)STLOG_PARAMS(__VA_ARGS__).WriteToJson(__json) << TEXT; \
294294
} \
295-
::NActors::MemLogAdapter(ctx, priority, component, __stream.Str()); \
295+
::NActors::MemLogAdapter(ctx, priority, component, __FILE_NAME__, __LINE__, __stream.Str()); \
296296
}; \
297297
} while (false)
298298

‎ydb/core/blobstorage/vdisk/common/vdisk_log.h

+42-5
Original file line numberDiff line numberDiff line change
@@ -35,7 +35,13 @@ namespace NKikimr {
3535
////////////////////////////////////////////////////////////////////////////
3636
class ILoggerCtx {
3737
public:
38-
virtual void DeliverLogMessage(NLog::EPriority mPriority, NLog::EComponent mComponent, TString &&str, bool json) = 0;
38+
virtual void DeliverLogMessage(
39+
NLog::EPriority mPriority,
40+
NLog::EComponent mComponent,
41+
const char* fileName,
42+
ui64 lineNumber,
43+
TString&& str,
44+
bool json) = 0;
3945
virtual NActors::NLog::TSettings* LoggerSettings() = 0;
4046
virtual ~ILoggerCtx() = default;
4147
};
@@ -49,8 +55,22 @@ namespace NKikimr {
4955
: ActorSystem(as)
5056
{}
5157

52-
void DeliverLogMessage(NLog::EPriority mPriority, NLog::EComponent mComponent, TString &&str, bool json) override {
53-
::NActors::DeliverLogMessage(*ActorSystem, mPriority, mComponent, std::move(str), json);
58+
void DeliverLogMessage(
59+
NLog::EPriority mPriority,
60+
NLog::EComponent mComponent,
61+
const char* fileName,
62+
ui64 lineNumber,
63+
TString&& str,
64+
bool json) override
65+
{
66+
::NActors::DeliverLogMessage(
67+
*ActorSystem,
68+
mPriority,
69+
mComponent,
70+
fileName,
71+
lineNumber,
72+
std::move(str),
73+
json);
5474
}
5575

5676
virtual NActors::NLog::TSettings* LoggerSettings() override {
@@ -67,7 +87,16 @@ namespace NKikimr {
6787
public:
6888
TFakeLoggerCtx();
6989

70-
void DeliverLogMessage(NLog::EPriority mPriority, NLog::EComponent mComponent, TString &&str, bool /*json*/) override {
90+
void DeliverLogMessage(
91+
NLog::EPriority mPriority,
92+
NLog::EComponent mComponent,
93+
const char* fileName,
94+
ui64 lineNumber,
95+
TString&& str,
96+
bool /*json*/) override
97+
{
98+
Y_UNUSED(fileName);
99+
Y_UNUSED(lineNumber);
71100
Y_UNUSED(mPriority);
72101
Y_UNUSED(mComponent);
73102
Y_UNUSED(str);
@@ -90,10 +119,18 @@ namespace NActors {
90119
NKikimr::ILoggerCtx& ctx,
91120
NLog::EPriority mPriority,
92121
NLog::EComponent mComponent,
122+
const char *fileName,
123+
ui64 lineNumber,
93124
TString &&str,
94125
bool json)
95126
{
96-
ctx.DeliverLogMessage(mPriority, mComponent, std::move(str), json);
127+
ctx.DeliverLogMessage(
128+
mPriority,
129+
mComponent,
130+
fileName,
131+
lineNumber,
132+
std::move(str),
133+
json);
97134
}
98135

99136
} // NActors

‎ydb/core/kqp/ut/data_integrity/kqp_data_integrity_trails_ut.cpp

+93-57
Original file line numberDiff line numberDiff line change
@@ -9,14 +9,35 @@ using namespace NYdb;
99
using namespace NYdb::NTable;
1010

1111
namespace {
12-
ui64 CountSubstr(const TString& str, const TString& substr) {
13-
ui64 count = 0;
14-
for (auto pos = str.find(substr); pos != TString::npos; pos = str.find(substr, pos + substr.size())) {
15-
++count;
12+
13+
void CheckRegexMatch(
14+
const TString& str,
15+
const TVector<std::pair<TString, ui64>>& regexToMatchCount)
16+
{
17+
for (auto& [regexString, expectedMatchCount]: regexToMatchCount) {
18+
std::regex expression(regexString.c_str());
19+
20+
auto matchCount = std::distance(
21+
std::sregex_iterator(str.begin(), str.end(), expression),
22+
std::sregex_iterator());
23+
24+
UNIT_ASSERT_VALUES_EQUAL(expectedMatchCount, matchCount);
1625
}
17-
return count;
1826
}
19-
}
27+
28+
TString ConstructRegexToCheckLogs(
29+
const TString& logLevel,
30+
const TString& component)
31+
{
32+
TStringBuilder builder;
33+
34+
// [\\w]+\\.[A-Za-z]+:[0-9]+ match filename and line number
35+
builder << "DATA_INTEGRITY " << logLevel
36+
<< ": [\\w]+\\.[A-Za-z]+:[0-9]+: Component: " << component;
37+
return builder;
38+
}
39+
40+
} // namespace
2041

2142
Y_UNIT_TEST_SUITE(KqpDataIntegrityTrails) {
2243
Y_UNIT_TEST_QUAD(Upsert, LogEnabled, UseSink) {
@@ -32,7 +53,7 @@ Y_UNIT_TEST_SUITE(KqpDataIntegrityTrails) {
3253
if (LogEnabled) {
3354
kikimr.GetTestServer().GetRuntime()->SetLogPriority(NKikimrServices::DATA_INTEGRITY, NLog::PRI_TRACE);
3455
}
35-
56+
3657
auto db = kikimr.GetTableClient();
3758
auto session = db.CreateSession().GetValueSync().GetSession();
3859

@@ -47,19 +68,29 @@ Y_UNIT_TEST_SUITE(KqpDataIntegrityTrails) {
4768
UNIT_ASSERT_VALUES_EQUAL_C(result.GetStatus(), EStatus::SUCCESS, result.GetIssues().ToString());
4869
}
4970

71+
TVector<std::pair<TString, ui64>> regexToMatchCount{
72+
// check session actor logs
73+
{ConstructRegexToCheckLogs("DEBUG", "SessionActor"),
74+
LogEnabled ? 2 : 0},
75+
// check grpc logs
76+
{ConstructRegexToCheckLogs("TRACE", "Grpc"), LogEnabled ? 2 : 0},
77+
// check datashard logs
78+
{ConstructRegexToCheckLogs("INFO", "DataShard"), LogEnabled ? 2 : 0},
79+
};
80+
5081
if (UseSink) {
5182
// check write actor logs
52-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY INFO: Component: WriteActor"), LogEnabled ? 1 : 0);
83+
regexToMatchCount.emplace_back(
84+
ConstructRegexToCheckLogs("INFO", "WriteActor"),
85+
LogEnabled ? 1 : 0);
5386
} else {
5487
// check executer logs
55-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY INFO: Component: Executer"), LogEnabled ? 2 : 0);
88+
regexToMatchCount.emplace_back(
89+
ConstructRegexToCheckLogs("INFO", "Executer"),
90+
LogEnabled ? 2 : 0);
5691
}
57-
// check session actor logs
58-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY DEBUG: Component: SessionActor"), LogEnabled ? 2 : 0);
59-
// check grpc logs
60-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY TRACE: Component: Grpc"), LogEnabled ? 2 : 0);
61-
// check datashard logs
62-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY INFO: Component: DataShard"), LogEnabled ? 2 : 0);
92+
93+
CheckRegexMatch(ss.Str(), regexToMatchCount);
6394
}
6495

6596
Y_UNIT_TEST_QUAD(UpsertEvWriteQueryService, isOlap, useOltpSink) {
@@ -103,38 +134,37 @@ Y_UNIT_TEST_SUITE(KqpDataIntegrityTrails) {
103134
UNIT_ASSERT_VALUES_EQUAL_C(result.GetStatus(), EStatus::SUCCESS, result.GetIssues().ToString());
104135
}
105136

137+
TVector<std::pair<TString, ui64>> regexToMatchCount;
106138
if (!isOlap) {
139+
regexToMatchCount = {
140+
{ConstructRegexToCheckLogs("DEBUG", "SessionActor"), 2},
141+
{ConstructRegexToCheckLogs("TRACE", "Grpc"), 2},
142+
{ConstructRegexToCheckLogs("INFO", "DataShard"), 2},
143+
};
144+
107145
if (useOltpSink) {
108146
// check write actor logs
109-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY INFO: Component: WriteActor"), 1);
147+
regexToMatchCount.emplace_back(
148+
ConstructRegexToCheckLogs("INFO", "WriteActor"),
149+
1);
110150
} else {
111151
// check executer logs
112-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY INFO: Component: Executer"), 2);
152+
regexToMatchCount.emplace_back(
153+
ConstructRegexToCheckLogs("INFO", "Executer"),
154+
2);
113155
}
114-
// check session actor logs
115-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY DEBUG: Component: SessionActor"), 2);
116-
// check grpc logs
117-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY TRACE: Component: Grpc"), 2);
118-
// check datashard logs
119-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY INFO: Component: DataShard"), 2);
120156
} else {
121-
// check write actor logs
122-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY INFO: Component: WriteActor"), 3);
123-
if (useOltpSink) {
124-
// check executer logs
125-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY INFO: Component: Executer"), 1);
126-
} else {
127-
// check executer logs
128-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY INFO: Component: Executer"), 11);
129-
}
130-
// check session actor logs
131-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY DEBUG: Component: SessionActor"), 2);
132-
// check grpc logs
133-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY TRACE: Component: Grpc"), 2);
134-
// check columnshard logs
157+
regexToMatchCount = {
158+
{ConstructRegexToCheckLogs("INFO", "WriteActor"), 3},
159+
{ConstructRegexToCheckLogs("DEBUG", "SessionActor"), 2},
160+
{ConstructRegexToCheckLogs("TRACE", "Grpc"), 2},
161+
{ConstructRegexToCheckLogs("INFO", "Executer"),
162+
useOltpSink ? 1 : 11}};
163+
135164
// ColumnShard doesn't have integrity logs.
136-
// UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY INFO: Component: ColumnShard"), 6);
137165
}
166+
167+
CheckRegexMatch(ss.Str(), regexToMatchCount);
138168
}
139169

140170
Y_UNIT_TEST(Ddl) {
@@ -149,7 +179,7 @@ Y_UNIT_TEST_SUITE(KqpDataIntegrityTrails) {
149179

150180
auto result = session.ExecuteSchemeQuery(R"(
151181
--!syntax_v1
152-
182+
153183
CREATE TABLE `/Root/Tmp` (
154184
Key Uint64,
155185
Value String,
@@ -159,14 +189,14 @@ Y_UNIT_TEST_SUITE(KqpDataIntegrityTrails) {
159189
UNIT_ASSERT_VALUES_EQUAL_C(result.GetStatus(), EStatus::SUCCESS, result.GetIssues().ToString());
160190
}
161191

162-
// check executer logs
163-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY INFO: Component: Executer"), 0);
164-
// check session actor logs
165-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY DEBUG: Component: SessionActor"), 0);
166-
// check grpc logs
167-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY TRACE: Component: Grpc"), 0);
168-
// check datashard logs
169-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY INFO: Component: DataShard"), 0);
192+
TVector<std::pair<TString, ui64>> regexToMatchCount{
193+
{ConstructRegexToCheckLogs("INFO", "Executer"), 0},
194+
{ConstructRegexToCheckLogs("DEBUG", "SessionActor"), 0},
195+
{ConstructRegexToCheckLogs("TRACE", "Grpc"), 0},
196+
{ConstructRegexToCheckLogs("INFO", "DataShard"), 0},
197+
};
198+
199+
CheckRegexMatch(ss.Str(), regexToMatchCount);
170200
}
171201

172202
Y_UNIT_TEST(Select) {
@@ -187,14 +217,20 @@ Y_UNIT_TEST_SUITE(KqpDataIntegrityTrails) {
187217
UNIT_ASSERT_VALUES_EQUAL_C(result.GetStatus(), EStatus::SUCCESS, result.GetIssues().ToString());
188218
}
189219

190-
// check executer logs (should be 1, because executer only logs result for read actor)
191-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY INFO: Component: Executer"), 1);
192-
// check session actor logs
193-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY DEBUG: Component: SessionActor"), 2);
194-
// check grpc logs
195-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY TRACE: Component: Grpc"), 2);
196-
// check datashard logs (should be empty, because DataShard only logs modification operations)
197-
UNIT_ASSERT_VALUES_EQUAL(CountSubstr(ss.Str(), "DATA_INTEGRITY INFO: Component: DataShard"), 0);
220+
TVector<std::pair<TString, ui64>> regexToMatchCount{
221+
// check executer logs (should be 1, because executer only logs
222+
// result for read actor)
223+
{ConstructRegexToCheckLogs("INFO", "Executer"), 1},
224+
// check session actor logs
225+
{ConstructRegexToCheckLogs("DEBUG", "SessionActor"), 2},
226+
// check grpc logs
227+
{ConstructRegexToCheckLogs("TRACE", "Grpc"), 2},
228+
// check datashard logs (should be empty, because DataShard only
229+
// logs modification operations)
230+
{ConstructRegexToCheckLogs("INFO", "DataShard"), 0},
231+
};
232+
233+
CheckRegexMatch(ss.Str(), regexToMatchCount);
198234
}
199235

200236
Y_UNIT_TEST_TWIN(BrokenReadLock, UseSink) {
@@ -261,7 +297,7 @@ Y_UNIT_TEST_SUITE(KqpDataIntegrityTrails) {
261297
std::smatch lockIdMatch;
262298
UNIT_ASSERT_C(std::regex_search(row.data(), lockIdMatch, lockIdRegex) || lockIdMatch.size() != 2, "failed to extract broken lock id");
263299
brokenLock = lockIdMatch[1].str();
264-
}
300+
}
265301
}
266302

267303
UNIT_ASSERT_C(!readLock.empty() && readLock == brokenLock, "read lock should be broken");
@@ -333,7 +369,7 @@ Y_UNIT_TEST_SUITE(KqpDataIntegrityTrails) {
333369
std::smatch lockIdMatch;
334370
UNIT_ASSERT_C(std::regex_search(row.data(), lockIdMatch, lockIdRegex) || lockIdMatch.size() != 2, "failed to extract broken lock id");
335371
brokenLock = lockIdMatch[1].str();
336-
}
372+
}
337373
}
338374

339375
UNIT_ASSERT_C(!readLock.empty() && readLock == brokenLock, "read lock should be broken");

‎ydb/core/tx/ctor_logger.h

+7-1
Original file line numberDiff line numberDiff line change
@@ -48,7 +48,13 @@ class TCtorLogger
4848
}
4949

5050
void WriteLog() {
51-
::NActors::MemLogAdapter(Ctx, Priority, Component, std::move(*StrStream));
51+
::NActors::MemLogAdapter(
52+
Ctx,
53+
Priority,
54+
Component,
55+
__FILE_NAME__,
56+
__LINE__,
57+
std::move(*StrStream));
5258
}
5359
};
5460

‎ydb/core/util/stlog.h

+1-1
Original file line numberDiff line numberDiff line change
@@ -68,7 +68,7 @@ namespace NKikimr::NStLog {
6868
const auto component = [&]{ using namespace NKikimrServices; using namespace NActorsServices; return (COMP); }(); \
6969
if (IS_CTX_LOG_PRIORITY_ENABLED(ctx, priority, component, 0ull)) { \
7070
STLOG_STREAM(__stream, __VA_ARGS__); \
71-
::NActors::MemLogAdapter(ctx, priority, component, __stream.Str(), ::NKikimr::NStLog::OutputLogJson); \
71+
::NActors::MemLogAdapter(ctx, priority, component, nullptr, 0, __stream.Str(), ::NKikimr::NStLog::OutputLogJson); \
7272
}; \
7373
} while (false)
7474

0 commit comments

Comments
 (0)