Skip to content

Commit 2ffc772

Browse files
author
koshkovka
committed
feat logging: SetLocalLogLevel changes level in both directions
@ref tracing::Span::SetLocalLogLevel now overrides the global log level in both directions: can raise the threshold (suppress logs) or lower it (enable debug logs even if the global level is higher). This PR leads to slowdown of a skipped `LOG_TRACE` from ~3 ns to ~10 ns, which we deemed acceptable. This place may be optimized in the future, especially if LTO will be re-enabled. commit_hash:b4c0ab9b08409ef0cfeb10dce53ec913fb82df68
1 parent a3b2ac7 commit 2ffc772

16 files changed

Lines changed: 38 additions & 53 deletions

File tree

core/include/userver/logging/logger.hpp

Lines changed: 0 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -46,8 +46,6 @@ LoggerPtr MakeFileLogger(const std::string& name, const std::string& path, Forma
4646

4747
namespace impl {
4848

49-
bool DoShouldLog(Level) noexcept;
50-
5149
void PrependCommonTags(TagWriter writer, Level logger_level);
5250

5351
} // namespace impl

core/include/userver/tracing/span.hpp

Lines changed: 5 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -196,27 +196,18 @@ class Span final {
196196
/// See @ref tracing::Span::SetLogLevel.
197197
logging::Level GetLogLevel() const;
198198

199-
/// @brief Sets an additional cutoff for the logs written in the scope of this `Span`,
200-
/// and in nested scopes recursively.
199+
/// @brief Sets the log level for the scope of this `Span` and nested scopes recursively.
200+
///
201+
/// Overrides the global log level in both directions: can raise the threshold
202+
/// (suppress logs) or lower it (enable debug logs even if the global level is higher).
201203
///
202204
/// For example, if the global log level is `info`, and the current `Span` has
203-
/// (own or inherited) local log level `warning`, then all `LOG_INFO`s within the current
204-
/// scope will be thrown away.
205+
/// local log level `debug`, then all `LOG_DEBUG`s within the current scope will be written.
205206
///
206207
/// The cutoff also applies to the span itself. If the @ref tracing::Span::SetLogLevel "span's log level"
207208
/// is less than the local log level, then the span is not written to the tracing system.
208209
///
209210
/// Local log level of child spans can override local log level of parent spans in both directions.
210-
/// For example:
211-
/// * if local log level of a parent `Span` is `warning`,
212-
/// * and local log level of a child span is set `info`,
213-
/// * then `info` logs within that `Span` will be written,
214-
/// * as long as the global log level is not higher than `info`.
215-
///
216-
/// Currently, local log level cannot override the global log level of the logger.
217-
/// For example, if the global log level is `info`, and the current `Span` has
218-
/// (own or inherited) local log level `debug`, then all `LOG_DEBUG`s within the current
219-
/// scope will **still** be thrown away.
220211
void SetLocalLogLevel(std::optional<logging::Level> log_level);
221212

222213
/// See @ref tracing::Span::SetLocalLogLevel.

core/src/logging/logger.cpp

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -67,16 +67,16 @@ LoggerPtr MakeFileLogger(const std::string& name, const std::string& path, Forma
6767

6868
namespace impl {
6969

70-
bool DoShouldLog(Level level) noexcept {
70+
bool ShouldLogWithSpanCheck(const LoggerBase& logger, Level level) noexcept {
7171
const auto* const span = tracing::Span::CurrentSpanUnchecked();
7272
if (span) {
7373
const auto local_log_level = span->GetLocalLogLevel();
74-
if (local_log_level && *local_log_level > level) {
75-
return false;
74+
if (local_log_level.has_value()) {
75+
return local_log_level.value() <= level;
7676
}
7777
}
7878

79-
return true;
79+
return ShouldLogNoSpan(logger, level);
8080
}
8181

8282
void PrependCommonTags(TagWriter writer, Level logger_level) {

core/src/logging/tp_logger.cpp

Lines changed: 1 addition & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -6,8 +6,8 @@
66
#include <userver/engine/async.hpp>
77
#include <userver/engine/task/cancel.hpp>
88
#include <userver/logging/impl/tag_writer.hpp>
9+
#include <userver/logging/log.hpp>
910
#include <userver/logging/logger.hpp>
10-
#include <userver/tracing/span.hpp>
1111
#include <userver/utils/enumerate.hpp>
1212
#include <userver/utils/fast_scope_guard.hpp>
1313

@@ -159,8 +159,6 @@ void TpLogger::Log(Level level, impl::formatters::LoggerItemRef item) {
159159

160160
void TpLogger::PrependCommonTags(TagWriter writer) const { impl::PrependCommonTags(writer, GetLevel()); }
161161

162-
bool TpLogger::DoShouldLog(Level level) const noexcept { return impl::DoShouldLog(level); }
163-
164162
void TpLogger::AddSink(impl::SinkPtr&& sink) {
165163
UASSERT(sink);
166164
sinks_.push_back(std::move(sink));

core/src/logging/tp_logger.hpp

Lines changed: 0 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -87,9 +87,6 @@ class TpLogger final : public TextLogger {
8787

8888
impl::LogStatistics& GetStatistics() noexcept;
8989

90-
protected:
91-
bool DoShouldLog(Level level) const noexcept override;
92-
9390
private:
9491
struct ActionVisitor;
9592

core/src/tracing/span.cpp

Lines changed: 13 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -223,9 +223,20 @@ std::string_view Span::Impl::GetParentIdForLogging(const Span::Impl* parent) {
223223
bool Span::Impl::ShouldLog() const {
224224
/* We must honour default log level, but use span's level from ourselves,
225225
* not the previous spans.
226+
* If local_log_level is set, it overrides the global level in both
227+
* directions (can enable logging below global level).
226228
*/
227-
return logging::impl::ShouldLogNoSpan(logging::GetDefaultLogger(), log_level_) &&
228-
local_log_level_.value_or(logging::Level::kTrace) <= log_level_;
229+
if (log_level_ == logging::Level::kNone) {
230+
return false;
231+
}
232+
const auto effective_local = local_log_level_.value_or(logging::Level::kTrace);
233+
if (effective_local > log_level_) {
234+
return false;
235+
}
236+
if (local_log_level_.has_value()) {
237+
return true;
238+
}
239+
return logging::impl::ShouldLogNoSpan(logging::GetDefaultLogger(), log_level_);
229240
}
230241

231242
std::optional<std::string_view> Span::Impl::GetSpanIdForChildLogs() const {

core/src/tracing/span_test.cpp

Lines changed: 2 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -263,13 +263,12 @@ UTEST_F(Span, LowerLocalLogLevel) {
263263

264264
UTEST_F(Span, LocalLogLevelLowerThanGlobal) {
265265
tracing::Span span("parent_span");
266-
// This currently cannot overcome global log level, which is "info" for this test.
267266
span.SetLocalLogLevel(logging::Level::kDebug);
268267

269-
LOG_DEBUG() << "message";
268+
LOG_DEBUG() << "debug_message";
270269
logging::LogFlush();
271270

272-
EXPECT_THAT(GetStreamString(), Not(HasSubstr("message")));
271+
EXPECT_THAT(GetStreamString(), HasSubstr("debug_message"));
273272
}
274273

275274
UTEST_F(Span, SpanLogLevelLowerThanGlobal) {

grpc/src/ugrpc/server/middlewares/log/component.cpp

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -23,7 +23,7 @@ Settings Parse(const yaml_config::YamlConfig& config, formats::parse::To<Setting
2323
settings.log_level = config["log-level"].As<logging::Level>(settings.log_level);
2424
settings.msg_log_level = config["msg-log-level"].As<logging::Level>(settings.msg_log_level);
2525
settings.max_msg_size = config["msg-size-log-limit"].As<std::size_t>(settings.max_msg_size);
26-
settings.local_log_level = config["local-log-level"].As<logging::Level>(settings.local_log_level);
26+
settings.local_log_level = config["local-log-level"].As<std::optional<logging::Level>>({});
2727
settings.status_codes_log_level =
2828
config["status-codes-log-level"].As<boost::container::flat_map<grpc::StatusCode, logging::Level>>({});
2929
return settings;

grpc/src/ugrpc/server/middlewares/log/component.yaml

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -17,7 +17,7 @@ properties:
1717
local-log-level:
1818
type: string
1919
description: local log level of the span for user-provided handler
20-
default: debug
20+
defaultDescription: not set
2121
status-codes-log-level:
2222
type: object
2323
properties: {}

grpc/src/ugrpc/server/middlewares/log/middleware.hpp

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -37,7 +37,7 @@ struct Settings final {
3737
/// Local log level of the server span
3838
/// It applies to logs in user-provided handler
3939
/// @ref tracing::Span::SetLocalLogLevel
40-
logging::Level local_log_level{logging::Level::kDebug};
40+
std::optional<logging::Level> local_log_level;
4141

4242
/// map of "status_code": log_level items to override span log level for specific status codes
4343
/// see @ref ugrpc::kStatusCodesMap for available statuses

0 commit comments

Comments
 (0)