Skip to content

Commit 296cbb9

Browse files
committed
feat docs: more cross references and notes for USERVER_NO_LOG_SPANS and USERVER_LOG_DYNAMIC_DEBUG
Tests: на прод не влияет commit_hash:2c9bd7714fc071cd37d337af9a72419ffdce6ff9
1 parent 8238116 commit 296cbb9

File tree

3 files changed

+66
-31
lines changed

3 files changed

+66
-31
lines changed

core/include/userver/tracing/span.hpp

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,8 @@ class SpanBuilder;
2222
/// @brief Measures the execution time of the current code block, links it with
2323
/// the parent tracing::Spans and stores that info in the log.
2424
///
25+
/// Logging of spans can be controled at runtime via @ref USERVER_NO_LOG_SPANS.
26+
///
2527
/// See @ref scripts/docs/en/userver/logging.md for usage examples and more
2628
/// descriptions.
2729
///

scripts/docs/en/schemas/dynamic_configs.md

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1211,6 +1211,8 @@ schema:
12111211
type: string
12121212
```
12131213

1214+
@warning Use @ref USERVER_NO_LOG_SPANS to disable Span logs.
1215+
12141216
Used by components::LoggingConfigurator.
12151217

12161218

@@ -1351,6 +1353,8 @@ schema:
13511353
}
13521354
```
13531355

1356+
To disable specific log lines not related to spans use @ref USERVER_LOG_DYNAMIC_DEBUG.
1357+
13541358
Used by components::LoggingConfigurator and all the logging facilities.
13551359

13561360
@anchor USERVER_RPS_CCONTROL

scripts/docs/en/userver/logging.md

Lines changed: 60 additions & 31 deletions
Original file line numberDiff line numberDiff line change
@@ -21,7 +21,7 @@ Macros are used for logging:
2121
@snippet logging/log_test.cpp Sample logging usage
2222

2323
The right part of the expression is calculated only if the logging level is less or equal to the macro log level.
24-
I.e., the right part of the expression `LOG_DEBUG ()<< ...` is calculated only in the case of the `DEBUG`
24+
I.e., the right part of the expression `LOG_DEBUG() << ...` is calculated only in the case of the `DEBUG`
2525
or `TRACE` logging level.
2626

2727
Sometimes it is useful to set the logging level of a given log entry dynamically:
@@ -33,8 +33,8 @@ Sometimes it is useful to set the logging level of a given log entry dynamically
3333
Not all logs get into the log file, but only those that are not lower than the logger's log level. The logger log level
3434
is set in static config (see components::Logging).
3535

36-
The log level can be changed in the static config for a particular handle. In this case, the log level of the logger is changed only
37-
for the request handling task of the handle and for all the subtasks:
36+
The log level can be changed in the static config for a particular handle. In this case, the log level of the logger
37+
is changed only for the request handling task of the handle and for all the subtasks:
3838

3939
```
4040
yaml
@@ -44,21 +44,29 @@ yaml
4444
log-level: WARNING
4545
```
4646

47+
Logging per line and file can be overriden at runtime using @ref USERVER_LOG_DYNAMIC_DEBUG dynamic config.
48+
4749

4850
### Dynamic change of the logging level
4951

5052
The logging `level` that was set in the static config of the components::Logging
5153
component for the entire service can be changed on the fly.
54+
5255
See @ref scripts/docs/en/userver/log_level_running_service.md for more info.
5356

5457
### Limit log length of the requests and responses
5558

56-
For per-handle limiting of the request body or response data logging you can use the `request_body_size_log_limit` and `request_headers_size_log_limit` and `response_data_size_log_limit` static options of the handler (see server::handlers::HandlerBase). Or you could override the server::handlers::HttpHandlerBase::GetRequestBodyForLogging and server::handlers::HttpHandlerBase::GetResponseDataForLogging functions.
59+
For per-handle limiting of the request body or response data logging you can use the `request_body_size_log_limit` and
60+
`request_headers_size_log_limit` and `response_data_size_log_limit` static options of the handler
61+
(see server::handlers::HandlerBase). Or you could override the
62+
server::handlers::HttpHandlerBase::GetRequestBodyForLogging and
63+
server::handlers::HttpHandlerBase::GetResponseDataForLogging functions.
5764

5865
### Limiting the log frequency
5966

6067
If some line of code generates too many logs and a small number of them is enough, then `LOG_*` should be
61-
replaced with `LOG_LIMITED_*`. For example, `LOG(lvl)` should be replaced with `LOG_LIMITED(lvl)`; `LOG_DEBUG()` should be replaced with `LOG_LIMITED_DEBUG()`, etc.
68+
replaced with `LOG_LIMITED_*`. For example, `LOG(lvl)` should be replaced with `LOG_LIMITED(lvl)`; `LOG_DEBUG()` should
69+
be replaced with `LOG_LIMITED_DEBUG()`, etc.
6270

6371
In this case, the log message is written only if the message index is a power of two. The counter is reset every second.
6472

@@ -99,7 +107,7 @@ to use `tracing::Span`, which implicitly adds tags to the log.
99107
### Stacktrace
100108

101109
Sometimes it is useful to write a full stacktrace to the log. Typical use case is for logging a "never should happen happened"
102-
situation. Use `logging::LogExtra::Stacktrace()` for such cases:
110+
situation. Use logging::LogExtra::Stacktrace() for such cases:
103111

104112
@snippet logging/log_extra_test.cpp Example using stacktrace in log
105113

@@ -128,23 +136,23 @@ LOG_INFO_TO(*my_logger) << "Look, I am a new logger!";
128136
129137
Note: do not forget to configure the logrotate for your new log file!
130138
139+
131140
## Tracing
132141
The userver implements a request tracing mechanism that is compatible with the
133142
[opentelemetry](https://opentelemetry.io/docs/) standard.
134143
135-
It allows you to save dependencies between tasks,
136-
between requests through several services,
137-
thereby building a trace of requests and interactions.
138-
It can be used to identify slow query stages, bottlenecks,
144+
It allows you to save dependencies between tasks, between requests through several services,
145+
thereby building a trace of requests and interactions. It can be used to identify slow query stages, bottlenecks,
139146
sequential queries, etc.
140147
141148
See tracing::DefaultTracingManagerLocator for more info.
142149
143150
### tracing::Span
144151
145-
When processing a request, you can create a `tracking::Span` object that measures the execution time of the current code block (technically, the time between its constructor and destructor) and stores the resulting time in the log:
152+
When processing a request, you can create a tracing::Span object that measures the execution time of the current code
153+
block (technically, the time between its constructor and destructor) and stores the resulting time in the log:
146154
147-
Example log `tracing::Span span("cache_invalidate")`:
155+
Example log for `tracing::Span span{"cache_invalidate"}`:
148156
149157
```
150158
tskv timestamp=2018-12-04T14:00:35.303132 timezone=+03:00 level=INFO module=~Impl ( userver/src/tracing/span.cpp:76 ) task_id=140572868354752 coro_id=140579682340544 text= trace_id=672a081c8004409ca79d5cc05cb5e580 span_id=12ff00c63bcc46599741bab62506881c parent_id=7a7c1c6999094d2a8e3d22bc6ecf5d70 stopwatch_name=cache_invalidate start_timestamp=1543921235.301035 total_time=2.08675 span_ref_type=child stopwatch_units=ms
@@ -156,41 +164,51 @@ Log record example for some `POST /v1/upload` handle:
156164
tskv timestamp=2020-08-13T15:30:52.507493 level=INFO module=~Impl ( userver/core/src/tracing/span.cpp:139 ) task_id=7F110B765400 thread_id=0x00007F115BDEE700 text= stopwatch_name=http/handler-v1_upload-post total_time=36.393694 span_ref_type=child stopwatch_units=ms start_timestamp=1597321852.471086 meta_type=/v1/upload _type=response method=POST body={"status":"ok"} uri=/v1/upload?provider_id=driver-metrics http_handle_request_time=36.277501 http_serialize_response_data_time=0.003394 tags_cache_mapping_time=0.018781 find_service_time=21.702876 http_parse_request_data_time=0.053233 http_check_auth_time=0.029809 http_check_ratelimit_time=0.000118 entities_cache_mapping_time=0.01037 register_request_time=0.819509 log_to_yt_time=0.047565 save_request_result_time=1.523389 upload_queries_time=5.179371 commit_time=4.11817 link=48e0029fc25e460880529b9d300967df parent_link=b1377a1b20384fe292fd77cb96b30121 source_service=driver-metrics entity_type=udid merge_policy=append provider_name=driver-metrics tags_count_append=3 meta_code=200 trace_id=2f6bf12265934260876a236c373b37dc span_id=8f828566189db0d0 parent_id=fdae1985431a6a57
157165
```
158166
159-
`tracing::Span` can only be created on stack. Currently, the ability to create `tracing::Span` as a member of a class whose objects can be passed between tasks is not supported.
167+
tracing::Span can only be created on stack. Currently, the ability to create `tracing::Span` as a member of a class
168+
whose objects can be passed between tasks is not supported.
160169
161170
### Tags
162171
163-
In addition to `trace_id`, `span_id`, `parent_id` and other tags specific to opentracing, the `tracing::Span` class can store arbitrary custom tags. To do this, Span implicitly contains LogExtra. You can add tags like this:
172+
In addition to `trace_id`, `span_id`, `parent_id` and other tags specific to opentracing, the `tracing::Span` class can
173+
store arbitrary custom tags. To do this, Span implicitly contains LogExtra. You can add tags like this:
164174
165175
@snippet tracing/span_test.cpp Example using Span tracing
166176
167-
Unlike simple `LogExtra`, tags from `Span` are automatically logged when using `LOG_XXX()`. If you create a `Span`, and you already have a `Span`, then `LogExtra` is copied from the old one to the new one (except for the tags added via `AddNonInheritableTag`).
177+
Unlike simple `LogExtra`, tags from `Span` are automatically logged when using `LOG_XXX()`. If you create a `Span`, and
178+
you already have a `Span`, then `LogExtra` is copied from the old one to the new one (except for the tags added via
179+
`AddNonInheritableTag`).
168180
169181
### Built-in tag semantics
170182
171183
- `TraceId` propagates both to sub-spans within a single service, and from client to server
172-
- `Link` propagates within a single service, but not from client to server. A new link is generated for the "root" request handling task
184+
- `Link` propagates within a single service, but not from client to server. A new link is generated for the "root"
185+
request handling task
173186
- `SpanId` identifies a specific span. It does not propagate
174187
- For "root" request handling spans, there are additionally:
175188
- `ParentSpanId`, which is the inner-most `SpanId` of the client
176189
- `ParentLink`, which is the `Link` of the client
177190
178191
### Span hierarchy and logging
179192
180-
All logs in the current task are implicitly linked to the current `Span` for the user, and tags of this `Span` are added to them (trace_id, span_id, etc.). All `Span` in the current task are implicitly stacked, and if there are several similar `Span`, the last created One (i.e., located at the top of the `Span` stack of the current task) will be used for logging.
193+
All logs in the current task are implicitly linked to the current `Span` for the user, and tags of this `Span` are added
194+
to them (trace_id, span_id, etc.). All `Span` in the current task are implicitly stacked, and if there are several
195+
similar `Span`, the last created One (i.e., located at the top of the `Span` stack of the current task) will be used for
196+
logging.
181197
182198
@snippet tracing/span_test.cpp Example span hierarchy
183199
184-
If you want to get the current `Span` (for example, you want to write something to `LogExtra`, but do not want to create an additional `Span`), then you can use the following approach:
200+
If you want to get the current `Span` (for example, you want to write something to `LogExtra`, but do not want to create
201+
an additional `Span`), then you can use the following approach:
185202
186203
@snippet core/src/tracing/span_test.cpp Example get current span
187204
188205
### Creating a Span
189206
190-
A `Span` is automatically created for each request, handled by the server::handlers::HttpHandlerBase inherited handles. `trace_id`, `parent_id` and `link` are automatically populated for the request headers (if any).
207+
A `Span` is automatically created for each request, handled by the server::handlers::HttpHandlerBase inherited handles.
208+
`trace_id`, `parent_id` and `link` are automatically populated for the request headers (if any).
191209
192-
Cache handlers do not have a parent Span, so a Span without a parent is automatically created for them, with a new `trace_id` for each update.
193-
The situation is similar for all utils::PeriodicTask.
210+
Cache handlers do not have a parent Span, so a Span without a parent is automatically created for them, with a new
211+
`trace_id` for each update. The situation is similar for all utils::PeriodicTask.
194212
195213
When creating a new task via `utils::Async`, a new `Span` is created and linked with the current `Span` of the current task.
196214
@@ -214,9 +232,12 @@ X-YaTraceId
214232
215233
### Selectively disabling Span logging
216234
217-
Using the server dynamic config @ref USERVER_NO_LOG_SPANS, you can set names and prefixes of Span names that do not need to be logged. If the span is not logged, then the ScopeTime of this span and any custom tags attached to the span via the methods of the `Add*Tag*()` are not put into the logs.
235+
Using the server dynamic config @ref USERVER_NO_LOG_SPANS, you can set names and prefixes of Span names that do not need
236+
to be logged. If the span is not logged, then the tracing::ScopeTime of this span and any custom tags attached to the
237+
span via the methods of the `Add*Tag*()` are not put into the logs.
218238
219-
For example, this is how you can disable logging of all Span for MongoDB (that is, all Span with `stopwatch_name` starting with `mongo`) and `Span` with `stopwatch_name=test`:
239+
For example, this is how you can disable logging of all Span for MongoDB (that is, all Span with `stopwatch_name`
240+
starting with `mongo`) and `Span` with `stopwatch_name=test`:
220241
221242
```json
222243
{
@@ -234,8 +255,9 @@ For example, this is how you can disable logging of all Span for MongoDB (that i
234255
## OpenTelemetry protocol
235256

236257
It is possible to use OpenTelemetry protocol for logs and tracing exporting.
237-
To use it, register all prerequisites for gRPC client and register `otlp::LoggerComponent` in component list in your `main` function.
238-
The static config file should contain a component section with OTLP logger.
258+
To use it, register all prerequisites for gRPC client and register `otlp::LoggerComponent` in component list in your
259+
`main` function. The static config file should contain a component section with OTLP logger.
260+
239261
Also remove `default` logger from `logging.loggers` as the default logger is handled by otlp component from now on.
240262

241263
The related part of static config:
@@ -259,11 +281,15 @@ The service buffers not-yet-sent logs and traces in memory, but drops them on ov
259281

260282
### Separate Sinks for Logs and Tracing
261283

262-
In certain environments, such as Kubernetes, applications typically write logs to stdout/stderr, while traces are sent efficiently through the 'push' model (via OTLP transport). Kubernetes stores the container's stdout/stderr in files on nodes, making logs available for log collectors using the 'pull' model. This approach ensures that logs remain accessible even if the application fails, capturing the most critical information.
284+
In certain environments, such as Kubernetes, applications typically write logs to stdout/stderr, while traces are sent
285+
efficiently through the 'push' model (via OTLP transport). Kubernetes stores the container's stdout/stderr in files on
286+
nodes, making logs available for log collectors using the `pull` model. This approach ensures that logs remain
287+
accessible even if the application fails, capturing the most critical information.
263288

264-
To configure separate sinks for logs and traces, use the optional 'sinks' block in the 'otlp-logger' configuration:
289+
To configure separate sinks for logs and traces, use the optional `sinks` block in the `otlp-logger` configuration:
265290

266-
```yaml
291+
```
292+
yaml
267293
otlp-logger:
268294
endpoint: $otlp-endpoint
269295
service-name: $service-name
@@ -273,21 +299,24 @@ otlp-logger:
273299
tracing: default | otlp | both
274300
```
275301

276-
If the 'sinks' block is not present in the 'otlp-logger' configuration, both logs and traces use the OTLP transport and are delivered to an OpenTelemetry-compatible collector by a background task in userver.
302+
If the 'sinks' block is not present in the 'otlp-logger' configuration, both logs and traces use the OTLP transport and
303+
are delivered to an OpenTelemetry-compatible collector by a background task in userver.
277304

278305
In the `sinks` block, you can set a value for each stream. See: `otlp::LoggerComponent`.
279306

280307
If you choose `otlp` for both streams, ensure that `logging.loggers` is empty:
281308

282-
```yaml
309+
```
310+
yaml
283311
logging:
284312
fs-task-processor: fs-task-processor
285313
loggers: {}
286314
```
287315

288316
Otherwise, add the _default_ logger in the `logging` component's `loggers` field:
289317

290-
```yaml
318+
```
319+
yaml
291320
logging:
292321
fs-task-processor: fs-task-processor
293322
loggers:

0 commit comments

Comments
 (0)