Skip to content

Commit 60e276b

Browse files
alexvrualexvru
authored
Support STLOG json format for JSON output (#8205)
1 parent 79e470e commit 60e276b

File tree

9 files changed

+72
-55
lines changed

9 files changed

+72
-55
lines changed

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

Lines changed: 7 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -34,7 +34,7 @@ namespace NKikimr {
3434
////////////////////////////////////////////////////////////////////////////
3535
class ILoggerCtx {
3636
public:
37-
virtual void DeliverLogMessage(NLog::EPriority mPriority, NLog::EComponent mComponent, TString &&str) = 0;
37+
virtual void DeliverLogMessage(NLog::EPriority mPriority, NLog::EComponent mComponent, TString &&str, bool json) = 0;
3838
virtual NActors::NLog::TSettings* LoggerSettings() = 0;
3939
virtual ~ILoggerCtx() = default;
4040
};
@@ -48,8 +48,8 @@ namespace NKikimr {
4848
: ActorSystem(as)
4949
{}
5050

51-
void DeliverLogMessage(NLog::EPriority mPriority, NLog::EComponent mComponent, TString &&str) override {
52-
::NActors::DeliverLogMessage(*ActorSystem, mPriority, mComponent, std::move(str));
51+
void DeliverLogMessage(NLog::EPriority mPriority, NLog::EComponent mComponent, TString &&str, bool json) override {
52+
::NActors::DeliverLogMessage(*ActorSystem, mPriority, mComponent, std::move(str), json);
5353
}
5454

5555
virtual NActors::NLog::TSettings* LoggerSettings() override {
@@ -66,7 +66,7 @@ namespace NKikimr {
6666
public:
6767
TFakeLoggerCtx();
6868

69-
void DeliverLogMessage(NLog::EPriority mPriority, NLog::EComponent mComponent, TString &&str) override {
69+
void DeliverLogMessage(NLog::EPriority mPriority, NLog::EComponent mComponent, TString &&str, bool /*json*/) override {
7070
Y_UNUSED(mPriority);
7171
Y_UNUSED(mComponent);
7272
Y_UNUSED(str);
@@ -89,9 +89,10 @@ namespace NActors {
8989
NKikimr::ILoggerCtx& ctx,
9090
NLog::EPriority mPriority,
9191
NLog::EComponent mComponent,
92-
TString &&str)
92+
TString &&str,
93+
bool json)
9394
{
94-
ctx.DeliverLogMessage(mPriority, mComponent, std::move(str));
95+
ctx.DeliverLogMessage(mPriority, mComponent, std::move(str), json);
9596
}
9697

9798
} // NActors

‎ydb/core/driver_lib/run/run.cpp

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -131,6 +131,7 @@
131131
#include <library/cpp/malloc/api/malloc.h>
132132

133133
#include <ydb/core/util/sig.h>
134+
#include <ydb/core/util/stlog.h>
134135

135136
#include <ydb/core/node_whiteboard/node_whiteboard.h>
136137
#include <ydb/core/tablet/node_tablet_monitor.h>
@@ -1194,6 +1195,7 @@ void TKikimrRunner::InitializeLogSettings(const TKikimrRunConfig& runConfig)
11941195
LogSettings->Format = NLog::TSettings::PLAIN_SHORT_FORMAT;
11951196
} else if (logConfig.GetFormat() == "json") {
11961197
LogSettings->Format = NLog::TSettings::JSON_FORMAT;
1198+
NKikimr::NStLog::OutputLogJson = true;
11971199
} else {
11981200
Y_ABORT("Unknown log format: \"%s\"", logConfig.GetFormat().data());
11991201
}

‎ydb/core/keyvalue/keyvalue_storage_read_request.cpp

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -14,7 +14,7 @@ namespace NKeyValue {
1414
#define STLOG_WITH_ERROR_DESCRIPTION(VARIABLE, PRIO, COMP, ...) \
1515
do { \
1616
VARIABLE += "\n"; \
17-
STLOG_STREAM(__stream, 0, __VA_ARGS__); \
17+
STLOG_STREAM(__stream, __VA_ARGS__); \
1818
const TString message = __stream.Str(); \
1919
VARIABLE += message; \
2020
const auto priority = [&]{ using namespace NActors::NLog; return (PRIO); }(); \

‎ydb/core/util/stlog.cpp

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,8 @@
44

55
namespace NKikimr::NStLog {
66

7+
bool OutputLogJson = false;
8+
79
void ProtobufToJson(const NProtoBuf::Message& m, NJson::TJsonWriter& json) {
810
TString s;
911
google::protobuf::util::MessageToJsonString(m, &s);

‎ydb/core/util/stlog.h

Lines changed: 10 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -11,7 +11,7 @@ static struct STLOG_PARAM_T {} STLOG_PARAM;
1111

1212
namespace NKikimr::NStLog {
1313

14-
static constexpr bool OutputLogJson = false;
14+
extern bool OutputLogJson;
1515

1616
void ProtobufToJson(const NProtoBuf::Message& m, NJson::TJsonWriter& json);
1717

@@ -51,10 +51,10 @@ namespace NKikimr::NStLog {
5151
#define STLOG_PARAMS_15(KV, ...) STLOG_PARAMS_1(KV) STLOG_EXPAND(STLOG_PARAMS_14(__VA_ARGS__))
5252
#define STLOG_PARAMS_16(KV, ...) STLOG_PARAMS_1(KV) STLOG_EXPAND(STLOG_PARAMS_15(__VA_ARGS__))
5353

54-
#define STLOG_STREAM(NAME, JSON_OVERRIDE, MARKER, TEXT, ...) \
54+
#define STLOG_STREAM(NAME, MARKER, TEXT, ...) \
5555
struct MARKER {}; \
5656
TStringStream NAME; \
57-
if constexpr (JSON_OVERRIDE ? JSON_OVERRIDE > 0 : ::NKikimr::NStLog::OutputLogJson) { \
57+
if (::NKikimr::NStLog::OutputLogJson) { \
5858
NJson::TJsonWriter __json(&NAME, false); \
5959
::NKikimr::NStLog::TMessage<MARKER>(__FILE__, __LINE__, #MARKER)STLOG_PARAMS(__VA_ARGS__).WriteToJson(__json) << TEXT; \
6060
} else { \
@@ -67,31 +67,18 @@ namespace NKikimr::NStLog {
6767
const auto priority = [&]{ using namespace NActors::NLog; return (PRIO); }(); \
6868
const auto component = [&]{ using namespace NKikimrServices; using namespace NActorsServices; return (COMP); }(); \
6969
if (IS_LOG_PRIORITY_ENABLED(priority, component)) { \
70-
STLOG_STREAM(__stream, 0, __VA_ARGS__); \
71-
::NActors::MemLogAdapter(ctx, priority, component, __stream.Str()); \
70+
STLOG_STREAM(__stream, __VA_ARGS__); \
71+
::NActors::MemLogAdapter(ctx, priority, component, __stream.Str(), ::NKikimr::NStLog::OutputLogJson); \
7272
}; \
7373
} while (false)
7474

7575
#define STLOG(...) if (TActivationContext *ctxp = TlsActivationContext; !ctxp); else STLOGX(*ctxp, __VA_ARGS__)
7676

77-
#define STLOGJX(CTX, PRIO, COMP, ...) \
78-
do { \
79-
auto& ctx = (CTX); \
80-
const auto priority = [&]{ using namespace NActors::NLog; return (PRIO); }(); \
81-
const auto component = [&]{ using namespace NKikimrServices; using namespace NActorsServices; return (COMP); }(); \
82-
if (IS_LOG_PRIORITY_ENABLED(priority, component)) { \
83-
STLOG_STREAM(__stream, 1, __VA_ARGS__); \
84-
::NActors::MemLogAdapter(ctx, priority, component, __stream.Str()); \
85-
}; \
86-
} while (false)
87-
88-
#define STLOGJ(...) if (TActivationContext *ctxp = TlsActivationContext; !ctxp); else STLOGJX(*ctxp, __VA_ARGS__)
89-
9077
#define STLOG_DEBUG_FAIL(COMP, ...) \
9178
do { \
9279
if (TActivationContext *ctxp = TlsActivationContext) { \
9380
const auto component = [&]{ using namespace NKikimrServices; using namespace NActorsServices; return (COMP); }(); \
94-
STLOG_STREAM(__stream, 0, __VA_ARGS__); \
81+
STLOG_STREAM(__stream, __VA_ARGS__); \
9582
const TString message = __stream.Str(); \
9683
Y_VERIFY_DEBUG_S(false, message); \
9784
LOG_LOG_S(*ctxp, NLog::PRI_CRIT, component, message); \
@@ -328,14 +315,14 @@ namespace NKikimr::NStLog {
328315
~TJsonWriter() {
329316
Json.OpenMap();
330317
if (Self->Header()) {
331-
Json.WriteKey("Marker");
318+
Json.WriteKey("marker");
332319
Json.Write(Self->Marker);
333-
Json.WriteKey("File");
320+
Json.WriteKey("file");
334321
Json.Write(Self->GetFileName());
335-
Json.WriteKey("Line");
322+
Json.WriteKey("line");
336323
Json.Write(Self->Line);
337324
}
338-
Json.WriteKey("Text");
325+
Json.WriteKey("message");
339326
Json.Write(Stream.Str());
340327
Self->WriteParamsToJson(Json);
341328
Json.CloseMap();

‎ydb/core/util/stlog_ut.cpp

Lines changed: 6 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -20,19 +20,21 @@ Y_UNIT_TEST_SUITE(StLog) {
2020
struct {
2121
TString ToString() const { return "yep"; }
2222
} s;
23-
STLOG_STREAM(stream, -1, MARKER1, "hello, world", (Param1, 1), (Param2, 'c'), (Param3, 1.1f), (Param4, "abcdef"),
23+
NKikimr::NStLog::OutputLogJson = false;
24+
STLOG_STREAM(stream, MARKER1, "hello, world", (Param1, 1), (Param2, 'c'), (Param3, 1.1f), (Param4, "abcdef"),
2425
(Param5, TString("abcdef")), (Param6, x1), (Param7, x2), (Param8, x3), (Param9, y1),
2526
(Param10, y2), (Param11, y3), (Param12, true), (Param13, v), (Param14, status), (Param15, id),
2627
(Param16, &s));
27-
UNIT_ASSERT_VALUES_EQUAL(stream.Str(), "{MARKER1@stlog_ut.cpp:26} hello, world Param1# 1 Param2# c Param3# 1.1 "
28+
UNIT_ASSERT_VALUES_EQUAL(stream.Str(), "{MARKER1@stlog_ut.cpp:27} hello, world Param1# 1 Param2# c Param3# 1.1 "
2829
"Param4# abcdef Param5# abcdef Param6# 1 Param7# 2 Param8# 3 Param9# <null> Param10# <null> Param11# <null> "
2930
"Param12# true Param13# [1 2 3] Param14# RACE Param15# {RawX1: 1 RawX2: 288230376185266176 "
3031
"RawX3: 216172807883587664 } Param16# yep");
31-
STLOG_STREAM(stream2, 1, MARKER2, "hello, world", (Param1, 1), (Param2, 'c'), (Param3, 1.1f), (Param4, "abcdef"),
32+
NKikimr::NStLog::OutputLogJson = true;
33+
STLOG_STREAM(stream2, MARKER2, "hello, world", (Param1, 1), (Param2, 'c'), (Param3, 1.1f), (Param4, "abcdef"),
3234
(Param5, TString("abcdef")), (Param6, x1), (Param7, x2), (Param8, x3), (Param9, y1),
3335
(Param10, y2), (Param11, y3), (Param12, true), (Param13, v), (Param14, status), (Param15, id),
3436
(Param16, &s));
35-
UNIT_ASSERT_VALUES_EQUAL(stream2.Str(), R"({"Marker":"MARKER2","File":"stlog_ut.cpp","Line":34,"Text":"hello, world",)"
37+
UNIT_ASSERT_VALUES_EQUAL(stream2.Str(), R"({"marker":"MARKER2","file":"stlog_ut.cpp","line":36,"message":"hello, world",)"
3638
R"("Param1":1,"Param2":99,"Param3":1.1,"Param4":"abcdef","Param5":"abcdef","Param6":1,"Param7":2,"Param8":3,)"
3739
R"("Param9":null,"Param10":null,"Param11":null,"Param12":true,"Param13":[1,2,3],"Param14":"RACE","Param15":)"
3840
R"({"RawX1":"1","RawX2":"288230376185266176","RawX3":"216172807883587664"},"Param16":"yep"})");

‎ydb/library/actors/core/log.cpp

Lines changed: 18 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -85,7 +85,7 @@ namespace NActors {
8585
TString formatted;
8686
vsprintf(formatted, c, params);
8787

88-
auto ok = OutputRecord(time, NLog::EPrio(priority), component, formatted);
88+
auto ok = OutputRecord(time, NLog::EPrio(priority), component, formatted, false);
8989
Y_UNUSED(ok);
9090
va_end(params);
9191
}
@@ -115,7 +115,7 @@ namespace NActors {
115115
if (ignoredCount > 0) {
116116
NLog::EPrio prio = LogBuffer.GetIgnoredHighestPrio();
117117
TString message = Sprintf("Logger overflow! Ignored %" PRIu64 " log records with priority [%s] or lower!", ignoredCount, PriorityToString(prio));
118-
if (!OutputRecord(ctx.Now(), NActors::NLog::EPrio::Error, Settings->LoggerComponent, message)) {
118+
if (!OutputRecord(ctx.Now(), NActors::NLog::EPrio::Error, Settings->LoggerComponent, message, false)) {
119119
BecomeDefunct();
120120
}
121121
LogBuffer.ClearIgnoredCount();
@@ -447,11 +447,11 @@ namespace NActors {
447447
constexpr size_t TimeBufSize = 512;
448448

449449
bool TLoggerActor::OutputRecord(NLog::TEvLog *evLog) noexcept {
450-
return OutputRecord(evLog->Stamp, evLog->Level.ToPrio(), evLog->Component, evLog->Line);
450+
return OutputRecord(evLog->Stamp, evLog->Level.ToPrio(), evLog->Component, evLog->Line, evLog->Json);
451451
}
452452

453453
bool TLoggerActor::OutputRecord(TInstant time, NLog::EPrio priority, NLog::EComponent component,
454-
const TString& formatted) noexcept try {
454+
const TString& formatted, bool json) noexcept try {
455455
const auto logPrio = ::ELogPriority(ui16(priority));
456456

457457
char buf[TimeBufSize];
@@ -482,8 +482,8 @@ namespace NActors {
482482
} break;
483483

484484
case NActors::NLog::TSettings::JSON_FORMAT: {
485-
NJsonWriter::TBuf json;
486-
json.BeginObject()
485+
NJsonWriter::TBuf j;
486+
j.BeginObject()
487487
.WriteKey("@timestamp")
488488
.WriteString(Settings->UseLocalTimestamps ? FormatLocalTimestamp(time, buf) : time.ToString().data())
489489
.WriteKey("microseconds")
@@ -501,11 +501,18 @@ namespace NActors {
501501
.WriteKey("tag")
502502
.WriteString("KIKIMR")
503503
.WriteKey("revision")
504-
.WriteInt(GetProgramSvnRevision())
505-
.WriteKey("message")
506-
.WriteString(formatted)
507-
.EndObject();
508-
auto logRecord = json.Str();
504+
.WriteInt(GetProgramSvnRevision());
505+
if (json) {
506+
if (formatted && formatted.front() == '{' && formatted.back() == '}') {
507+
j.UnsafeWritePair(TStringBuf(formatted.data() + 1, formatted.size() - 2));
508+
} else {
509+
j.UnsafeWritePair(formatted);
510+
}
511+
} else {
512+
j.WriteKey("message").WriteString(formatted);
513+
}
514+
j.EndObject();
515+
auto logRecord = j.Str();
509516
LogBackend->WriteData(
510517
TLogRecord(logPrio, logRecord.data(), logRecord.size()));
511518
} break;

‎ydb/library/actors/core/log.h

Lines changed: 11 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -265,7 +265,7 @@ namespace NActors {
265265
void HandleMonInfo(NMon::TEvHttpInfo::TPtr& ev, const TActorContext& ctx);
266266
void HandleWakeup();
267267
[[nodiscard]] bool OutputRecord(NLog::TEvLog *evLog) noexcept;
268-
[[nodiscard]] bool OutputRecord(TInstant time, NLog::EPrio priority, NLog::EComponent component, const TString& formatted) noexcept;
268+
[[nodiscard]] bool OutputRecord(TInstant time, NLog::EPrio priority, NLog::EComponent component, const TString& formatted, bool json) noexcept;
269269
void RenderComponentPriorities(IOutputStream& str);
270270
void FlushLogBufferMessage();
271271
void WriteMessageStat(const NLog::TEvLog& ev);
@@ -342,11 +342,12 @@ namespace NActors {
342342
}
343343

344344
template <typename TCtx>
345-
inline void DeliverLogMessage(TCtx& ctx, NLog::EPriority mPriority, NLog::EComponent mComponent, TString &&str)
345+
inline void DeliverLogMessage(TCtx& ctx, NLog::EPriority mPriority, NLog::EComponent mComponent, TString &&str,
346+
bool json = false)
346347
{
347348
const NLog::TSettings *mSettings = ctx.LoggerSettings();
348349
TLoggerActor::Throttle(*mSettings);
349-
ctx.Send(new IEventHandle(mSettings->LoggerActorId, TActorId(), new NLog::TEvLog(mPriority, mComponent, std::move(str))));
350+
ctx.Send(new IEventHandle(mSettings->LoggerActorId, TActorId(), new NLog::TEvLog(mPriority, mComponent, std::move(str), json)));
350351
}
351352

352353
template <typename TCtx, typename... TArgs>
@@ -365,29 +366,31 @@ namespace NActors {
365366
}
366367

367368
MemLogWrite(Formatted.data(), Formatted.size(), true);
368-
DeliverLogMessage(actorCtxOrSystem, mPriority, mComponent, std::move(Formatted));
369+
DeliverLogMessage(actorCtxOrSystem, mPriority, mComponent, std::move(Formatted), false);
369370
}
370371

371372
template <typename TCtx>
372373
Y_WRAPPER inline void MemLogAdapter(
373374
TCtx& actorCtxOrSystem,
374375
NLog::EPriority mPriority,
375376
NLog::EComponent mComponent,
376-
const TString& str) {
377+
const TString& str,
378+
bool json = false) {
377379

378380
MemLogWrite(str.data(), str.size(), true);
379-
DeliverLogMessage(actorCtxOrSystem, mPriority, mComponent, TString(str));
381+
DeliverLogMessage(actorCtxOrSystem, mPriority, mComponent, TString(str), json);
380382
}
381383

382384
template <typename TCtx>
383385
Y_WRAPPER inline void MemLogAdapter(
384386
TCtx& actorCtxOrSystem,
385387
NLog::EPriority mPriority,
386388
NLog::EComponent mComponent,
387-
TString&& str) {
389+
TString&& str,
390+
bool json = false) {
388391

389392
MemLogWrite(str.data(), str.size(), true);
390-
DeliverLogMessage(actorCtxOrSystem, mPriority, mComponent, std::move(str));
393+
DeliverLogMessage(actorCtxOrSystem, mPriority, mComponent, std::move(str), json);
391394
}
392395

393396
class TRecordWriter: public TStringBuilder {

‎ydb/library/actors/core/log_iface.h

Lines changed: 15 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -83,19 +83,21 @@ namespace NActors {
8383
, public TIntrusiveListItem<TEvLog, TEvLogBufferLevelListTag>
8484
{
8585
public:
86-
TEvLog(TInstant stamp, TLevel level, EComponent comp, const TString &line)
86+
TEvLog(TInstant stamp, TLevel level, EComponent comp, const TString &line, bool json = false)
8787
: Stamp(stamp)
8888
, Level(level)
8989
, Component(comp)
9090
, Line(line)
91+
, Json(json)
9192
{
9293
}
9394

94-
TEvLog(TInstant stamp, TLevel level, EComponent comp, TString &&line)
95+
TEvLog(TInstant stamp, TLevel level, EComponent comp, TString &&line, bool json = false)
9596
: Stamp(stamp)
9697
, Level(level)
9798
, Component(comp)
9899
, Line(std::move(line))
100+
, Json(json)
99101
{
100102
}
101103

@@ -104,13 +106,24 @@ namespace NActors {
104106
, Level(EPrio(prio))
105107
, Component(comp)
106108
, Line(std::move(line))
109+
, Json(false)
110+
{
111+
}
112+
113+
TEvLog(EPriority prio, EComponent comp, TString line, bool json, TInstant time = TInstant::Now())
114+
: Stamp(time)
115+
, Level(EPrio(prio))
116+
, Component(comp)
117+
, Line(std::move(line))
118+
, Json(json)
107119
{
108120
}
109121

110122
const TInstant Stamp = TInstant::Max();
111123
const TLevel Level;
112124
const EComponent Component = 0;
113125
TString Line;
126+
const bool Json;
114127
};
115128

116129
}

0 commit comments

Comments
 (0)