/src/Fast-DDS/src/cpp/fastdds/log/Log.cpp
Line | Count | Source (jump to first uncovered line) |
1 | | // Copyright 2019 Proyectos y Sistemas de Mantenimiento SL (eProsima). |
2 | | // |
3 | | // Licensed under the Apache License, Version 2.0 (the "License"); |
4 | | // you may not use this file except in compliance with the License. |
5 | | // You may obtain a copy of the License at |
6 | | // |
7 | | // http://www.apache.org/licenses/LICENSE-2.0 |
8 | | // |
9 | | // Unless required by applicable law or agreed to in writing, software |
10 | | // distributed under the License is distributed on an "AS IS" BASIS, |
11 | | // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
12 | | // See the License for the specific language governing permissions and |
13 | | // limitations under the License. |
14 | | |
15 | | #include <chrono> |
16 | | #include <iomanip> |
17 | | #include <iostream> |
18 | | #include <memory> |
19 | | #include <mutex> |
20 | | |
21 | | #include <fastdds/dds/log/Colors.hpp> |
22 | | #include <fastdds/dds/log/Log.hpp> |
23 | | #include <fastdds/dds/log/OStreamConsumer.hpp> |
24 | | #include <fastdds/dds/log/StdoutConsumer.hpp> |
25 | | #include <fastdds/dds/log/StdoutErrConsumer.hpp> |
26 | | |
27 | | #include <utils/DBQueue.hpp> |
28 | | #include <utils/SystemInfo.hpp> |
29 | | #include <utils/thread.hpp> |
30 | | #include <utils/threading.hpp> |
31 | | |
32 | | namespace eprosima { |
33 | | namespace fastdds { |
34 | | namespace dds { |
35 | | namespace detail { |
36 | | |
37 | | struct LogResources |
38 | | { |
39 | | LogResources() |
40 | 2 | : logging_(false) |
41 | 2 | , work_(false) |
42 | 2 | , current_loop_(0) |
43 | 2 | , filenames_(false) |
44 | 2 | , functions_(true) |
45 | 2 | , verbosity_(Log::Error) |
46 | 2 | { |
47 | 2 | #if STDOUTERR_LOG_CONSUMER |
48 | 2 | consumers_.emplace_back(new StdoutErrConsumer); |
49 | | #else |
50 | | consumers_.emplace_back(new StdoutConsumer); |
51 | | #endif // STDOUTERR_LOG_CONSUMER |
52 | 2 | } |
53 | | |
54 | | ~LogResources() |
55 | 2 | { |
56 | 2 | Flush(); |
57 | 2 | KillThread(); |
58 | 2 | } |
59 | | |
60 | | /** |
61 | | * Registers an user defined consumer to route log output. |
62 | | * There is a default stdout consumer active as default. |
63 | | * @param consumer r-value to a consumer unique_ptr. It will be invalidated after the call. |
64 | | */ |
65 | | void RegisterConsumer( |
66 | | std::unique_ptr<LogConsumer>&& consumer) |
67 | 0 | { |
68 | 0 | std::unique_lock<std::mutex> guard(config_mutex_); |
69 | 0 | consumers_.emplace_back(std::move(consumer)); |
70 | 0 | } |
71 | | |
72 | | //! Removes all registered consumers_, including the default stdout. |
73 | | void ClearConsumers() |
74 | 0 | { |
75 | 0 | Flush(); |
76 | |
|
77 | 0 | std::lock_guard<std::mutex> guard(config_mutex_); |
78 | 0 | consumers_.clear(); |
79 | 0 | } |
80 | | |
81 | | //! Enables the reporting of filenames_ in log entries. Disabled by default. |
82 | | void ReportFilenames( |
83 | | bool report) |
84 | 0 | { |
85 | 0 | std::lock_guard<std::mutex> configGuard(config_mutex_); |
86 | 0 | filenames_ = report; |
87 | 0 | } |
88 | | |
89 | | //! Enables the reporting of function names in log entries. Enabled by default when supported. |
90 | | void ReportFunctions( |
91 | | bool report) |
92 | 0 | { |
93 | 0 | std::lock_guard<std::mutex> configGuard(config_mutex_); |
94 | 0 | functions_ = report; |
95 | 0 | } |
96 | | |
97 | | //! Sets the verbosity_ level, allowing for messages equal or under that priority to be logged. |
98 | | void SetVerbosity( |
99 | | Log::Kind kind) |
100 | 0 | { |
101 | 0 | verbosity_ = kind; |
102 | 0 | } |
103 | | |
104 | | //! Returns the current verbosity_ level. |
105 | | Log::Kind GetVerbosity() |
106 | 4.21k | { |
107 | 4.21k | return verbosity_; |
108 | 4.21k | } |
109 | | |
110 | | //! Sets a filter that will pattern-match against log categories, dropping any unmatched categories. |
111 | | void SetCategoryFilter( |
112 | | const std::regex& filter) |
113 | 0 | { |
114 | 0 | std::unique_lock<std::mutex> configGuard(config_mutex_); |
115 | 0 | category_filter_.reset(new std::regex(filter)); |
116 | 0 | } |
117 | | |
118 | | void UnsetCategoryFilter() |
119 | 0 | { |
120 | 0 | std::unique_lock<std::mutex> configGuard(config_mutex_); |
121 | 0 | category_filter_.reset(); |
122 | 0 | } |
123 | | |
124 | | bool HasCategoryFilter() |
125 | 0 | { |
126 | 0 | std::unique_lock<std::mutex> configGuard(config_mutex_); |
127 | 0 | return !!category_filter_; |
128 | 0 | } |
129 | | |
130 | | //! Returns a copy of the current category filter or an empty object otherwise |
131 | | std::regex GetCategoryFilter() |
132 | 0 | { |
133 | 0 | std::unique_lock<std::mutex> configGuard(config_mutex_); |
134 | 0 | return category_filter_ ? *category_filter_ : std::regex{}; |
135 | 0 | } |
136 | | |
137 | | //! Sets a filter that will pattern-match against filenames_, dropping any unmatched categories. |
138 | | void SetFilenameFilter( |
139 | | const std::regex& filter) |
140 | 0 | { |
141 | 0 | std::unique_lock<std::mutex> configGuard(config_mutex_); |
142 | 0 | filename_filter_.reset(new std::regex(filter)); |
143 | 0 | } |
144 | | |
145 | | //! Returns a copy of the current filename filter or an empty object otherwise |
146 | | std::regex GetFilenameFilter() |
147 | 0 | { |
148 | 0 | std::unique_lock<std::mutex> configGuard(config_mutex_); |
149 | 0 | return filename_filter_ ? *filename_filter_: std::regex{}; |
150 | 0 | } |
151 | | |
152 | | //! Sets a filter that will pattern-match against the provided error string, dropping any unmatched categories. |
153 | | void SetErrorStringFilter( |
154 | | const std::regex& filter) |
155 | 0 | { |
156 | 0 | std::unique_lock<std::mutex> configGuard(config_mutex_); |
157 | 0 | error_string_filter_.reset(new std::regex(filter)); |
158 | 0 | } |
159 | | |
160 | | //! Sets thread configuration for the logging thread. |
161 | | void SetThreadConfig( |
162 | | const rtps::ThreadSettings& config) |
163 | 644 | { |
164 | 644 | std::lock_guard<std::mutex> guard(cv_mutex_); |
165 | 644 | thread_settings_ = config; |
166 | 644 | } |
167 | | |
168 | | //! Returns a copy of the current filename filter or an empty object otherwise |
169 | | std::regex GetErrorStringFilter() |
170 | 0 | { |
171 | 0 | std::unique_lock<std::mutex> configGuard(config_mutex_); |
172 | 0 | return error_string_filter_ ? *error_string_filter_: std::regex{}; |
173 | 0 | } |
174 | | |
175 | | //! Returns the logging_ engine to configuration defaults. |
176 | | void Reset() |
177 | 0 | { |
178 | 0 | rtps::ThreadSettings thr_config{}; |
179 | 0 | SetThreadConfig(thr_config); |
180 | |
|
181 | 0 | std::lock_guard<std::mutex> configGuard(config_mutex_); |
182 | 0 | category_filter_.reset(); |
183 | 0 | filename_filter_.reset(); |
184 | 0 | error_string_filter_.reset(); |
185 | 0 | filenames_ = false; |
186 | 0 | functions_ = true; |
187 | 0 | verbosity_ = Log::Error; |
188 | 0 | consumers_.clear(); |
189 | |
|
190 | 0 | #if STDOUTERR_LOG_CONSUMER |
191 | 0 | consumers_.emplace_back(new StdoutErrConsumer); |
192 | | #else |
193 | | consumers_.emplace_back(new StdoutConsumer); |
194 | | #endif // if STDOUTERR_LOG_CONSUMER |
195 | 0 | } |
196 | | |
197 | | //! Waits until all info logged up to the call time is consumed |
198 | | void Flush() |
199 | 2 | { |
200 | 2 | std::unique_lock<std::mutex> guard(cv_mutex_); |
201 | | |
202 | 2 | if (!logging_ && !logging_thread_.joinable()) |
203 | 2 | { |
204 | | // already killed |
205 | 2 | return; |
206 | 2 | } |
207 | | |
208 | | /* Flush() two steps strategy: |
209 | | |
210 | | We must assure Log::Run swaps the queues twice |
211 | | because its the only way the content in the background queue |
212 | | will be consumed (first Run() loop). |
213 | | |
214 | | Then, we must assure the new front queue content is consumed (second Run() loop). |
215 | | */ |
216 | | |
217 | 0 | int last_loop = current_loop_; |
218 | |
|
219 | 0 | for (int i = 0; i < 2; ++i) |
220 | 0 | { |
221 | 0 | cv_.wait(guard, |
222 | 0 | [&]() |
223 | 0 | { |
224 | | /* We must avoid: |
225 | | + the two calls be processed without an intermediate Run() loop |
226 | | (by using last_loop sequence number and checking if the foreground queue is empty) |
227 | | + deadlock by absence of Run() loop activity (by using BothEmpty() call) |
228 | | */ |
229 | 0 | return !logging_ || |
230 | 0 | logs_.BothEmpty() || |
231 | 0 | (last_loop != current_loop_ && logs_.Empty()); |
232 | 0 | }); |
233 | |
|
234 | 0 | last_loop = current_loop_; |
235 | |
|
236 | 0 | } |
237 | 0 | } |
238 | | |
239 | | /** |
240 | | * Not recommended to call this method directly! Use the following macros: |
241 | | * * EPROSIMA_LOG_INFO(cat, msg); |
242 | | * * EPROSIMA_LOG_WARNING(cat, msg); |
243 | | * * EPROSIMA_LOG_ERROR(cat, msg); |
244 | | * |
245 | | * @todo this method takes 2 mutexes (same mutex) internally. |
246 | | * This is a very high sensible point of the code and it should be refactored to be as efficient as possible. |
247 | | */ |
248 | | void QueueLog( |
249 | | const std::string& message, |
250 | | const Log::Context& context, |
251 | | Log::Kind kind) |
252 | 1.32M | { |
253 | 1.32M | StartThread(); |
254 | | |
255 | 1.32M | std::string timestamp = SystemInfo::get_timestamp(); |
256 | 1.32M | logs_.Push(Log::Entry{ message, context, kind, timestamp }); |
257 | 1.32M | { |
258 | 1.32M | std::unique_lock<std::mutex> guard(cv_mutex_); |
259 | 1.32M | work_ = true; |
260 | | // pessimization |
261 | 1.32M | cv_.notify_all(); |
262 | | // wait till the thread is initialized |
263 | 1.32M | cv_.wait(guard, [&] |
264 | 1.32M | { |
265 | 1.32M | return current_loop_; |
266 | 1.32M | }); |
267 | 1.32M | } |
268 | 1.32M | } |
269 | | |
270 | | //! Stops the logging_ thread. It will re-launch on the next call to QueueLog. |
271 | | void KillThread() |
272 | 3 | { |
273 | 3 | { |
274 | 3 | std::unique_lock<std::mutex> guard(cv_mutex_); |
275 | 3 | logging_ = false; |
276 | 3 | work_ = false; |
277 | 3 | } |
278 | | |
279 | 3 | if (logging_thread_.joinable()) |
280 | 1 | { |
281 | 1 | cv_.notify_all(); |
282 | 1 | if (!logging_thread_.is_calling_thread()) |
283 | 1 | { |
284 | 1 | logging_thread_.join(); |
285 | 1 | } |
286 | 1 | } |
287 | 3 | } |
288 | | |
289 | | private: |
290 | | |
291 | | void StartThread() |
292 | 1.32M | { |
293 | 1.32M | std::unique_lock<std::mutex> guard(cv_mutex_); |
294 | 1.32M | if (!logging_ && !logging_thread_.joinable()) |
295 | 1 | { |
296 | 1 | logging_ = true; |
297 | 1 | auto thread_fn = [this]() |
298 | 1 | { |
299 | 1 | run(); |
300 | 1 | }; |
301 | 1 | logging_thread_ = eprosima::create_thread(thread_fn, thread_settings_, "dds.log"); |
302 | 1 | } |
303 | 1.32M | } |
304 | | |
305 | | void run() |
306 | 1 | { |
307 | 1 | std::unique_lock<std::mutex> guard(cv_mutex_); |
308 | | |
309 | 13 | while (logging_) |
310 | 12 | { |
311 | 12 | cv_.wait(guard, |
312 | 12 | [&]() |
313 | 13 | { |
314 | 13 | return !logging_ || work_; |
315 | 13 | }); |
316 | | |
317 | 12 | work_ = false; |
318 | | |
319 | 12 | guard.unlock(); |
320 | 12 | { |
321 | 12 | logs_.Swap(); |
322 | 1.32M | while (!logs_.Empty()) |
323 | 1.32M | { |
324 | 1.32M | Log::Entry& entry = logs_.Front(); |
325 | 1.32M | { |
326 | 1.32M | std::unique_lock<std::mutex> configGuard(config_mutex_); |
327 | | |
328 | 1.32M | if (preprocess(entry)) |
329 | 1.32M | { |
330 | 1.32M | for (auto& consumer : consumers_) |
331 | 1.32M | { |
332 | 1.32M | consumer->Consume(entry); |
333 | 1.32M | } |
334 | 1.32M | } |
335 | 1.32M | } |
336 | | // This Pop() is also a barrier for Log::Flush wait condition |
337 | 1.32M | logs_.Pop(); |
338 | 1.32M | } |
339 | 12 | } |
340 | 12 | guard.lock(); |
341 | | |
342 | | // avoid overflow |
343 | 12 | if (++current_loop_ > 10000) |
344 | 0 | { |
345 | 0 | current_loop_ = 0; |
346 | 0 | } |
347 | | |
348 | 12 | cv_.notify_all(); |
349 | 12 | } |
350 | 1 | } |
351 | | |
352 | | bool preprocess( |
353 | | Log::Entry& entry) |
354 | 1.32M | { |
355 | 1.32M | if (category_filter_ && !regex_search(entry.context.category, *category_filter_)) |
356 | 0 | { |
357 | 0 | return false; |
358 | 0 | } |
359 | 1.32M | if (filename_filter_ && !regex_search(entry.context.filename, *filename_filter_)) |
360 | 0 | { |
361 | 0 | return false; |
362 | 0 | } |
363 | 1.32M | if (error_string_filter_ && !regex_search(entry.message, *error_string_filter_)) |
364 | 0 | { |
365 | 0 | return false; |
366 | 0 | } |
367 | 1.32M | if (!filenames_) |
368 | 1.32M | { |
369 | 1.32M | entry.context.filename = nullptr; |
370 | 1.32M | } |
371 | 1.32M | if (!functions_) |
372 | 0 | { |
373 | 0 | entry.context.function = nullptr; |
374 | 0 | } |
375 | | |
376 | 1.32M | return true; |
377 | 1.32M | } |
378 | | |
379 | | DBQueue<Log::Entry> logs_; |
380 | | std::vector<std::unique_ptr<LogConsumer>> consumers_; |
381 | | eprosima::thread logging_thread_; |
382 | | |
383 | | // Condition variable segment. |
384 | | std::condition_variable cv_; |
385 | | std::mutex cv_mutex_; |
386 | | bool logging_; |
387 | | bool work_; |
388 | | int current_loop_; |
389 | | |
390 | | // Context configuration. |
391 | | std::mutex config_mutex_; |
392 | | bool filenames_; |
393 | | bool functions_; |
394 | | std::unique_ptr<std::regex> category_filter_; |
395 | | std::unique_ptr<std::regex> filename_filter_; |
396 | | std::unique_ptr<std::regex> error_string_filter_; |
397 | | |
398 | | std::atomic<Log::Kind> verbosity_; |
399 | | rtps::ThreadSettings thread_settings_; |
400 | | }; |
401 | | |
402 | | const std::shared_ptr<LogResources>& get_log_resources() |
403 | 1.32M | { |
404 | 1.32M | static std::shared_ptr<LogResources> instance = std::make_shared<LogResources>(); |
405 | 1.32M | return instance; |
406 | 1.32M | } |
407 | | |
408 | | } // namespace detail |
409 | | |
410 | | void Log::RegisterConsumer( |
411 | | std::unique_ptr<LogConsumer>&& consumer) |
412 | 0 | { |
413 | 0 | detail::get_log_resources()->RegisterConsumer(std::move(consumer)); |
414 | 0 | } |
415 | | |
416 | | void Log::ClearConsumers() |
417 | 0 | { |
418 | 0 | detail::get_log_resources()->ClearConsumers(); |
419 | 0 | } |
420 | | |
421 | | void Log::Reset() |
422 | 0 | { |
423 | 0 | detail::get_log_resources()->Reset(); |
424 | 0 | } |
425 | | |
426 | | void Log::Flush() |
427 | 0 | { |
428 | 0 | detail::get_log_resources()->Flush(); |
429 | 0 | } |
430 | | |
431 | | void Log::ReportFilenames( |
432 | | bool report) |
433 | 0 | { |
434 | 0 | detail::get_log_resources()->ReportFilenames(report); |
435 | 0 | } |
436 | | |
437 | | void Log::ReportFunctions( |
438 | | bool report) |
439 | 0 | { |
440 | 0 | detail::get_log_resources()->ReportFunctions(report); |
441 | 0 | } |
442 | | |
443 | | void Log::KillThread() |
444 | 1 | { |
445 | 1 | detail::get_log_resources()->KillThread(); |
446 | 1 | } |
447 | | |
448 | | void Log::QueueLog( |
449 | | const std::string& message, |
450 | | const Log::Context& context, |
451 | | Log::Kind kind) |
452 | 1.32M | { |
453 | 1.32M | detail::get_log_resources()->QueueLog(message, context, kind); |
454 | 1.32M | } |
455 | | |
456 | | Log::Kind Log::GetVerbosity() |
457 | 4.21k | { |
458 | 4.21k | return detail::get_log_resources()->GetVerbosity(); |
459 | 4.21k | } |
460 | | |
461 | | void Log::SetVerbosity( |
462 | | Log::Kind kind) |
463 | 0 | { |
464 | 0 | detail::get_log_resources()->SetVerbosity(kind); |
465 | 0 | } |
466 | | |
467 | | void Log::SetCategoryFilter( |
468 | | const std::regex& filter) |
469 | 0 | { |
470 | 0 | detail::get_log_resources()->SetCategoryFilter(filter); |
471 | 0 | } |
472 | | |
473 | | void Log::SetFilenameFilter( |
474 | | const std::regex& filter) |
475 | 0 | { |
476 | 0 | detail::get_log_resources()->SetFilenameFilter(filter); |
477 | 0 | } |
478 | | |
479 | | void Log::SetErrorStringFilter( |
480 | | const std::regex& filter) |
481 | 0 | { |
482 | 0 | detail::get_log_resources()->SetErrorStringFilter(filter); |
483 | 0 | } |
484 | | |
485 | | void Log::SetThreadConfig( |
486 | | const rtps::ThreadSettings& config) |
487 | 644 | { |
488 | 644 | detail::get_log_resources()->SetThreadConfig(config); |
489 | 644 | } |
490 | | |
491 | | void Log::UnsetCategoryFilter() |
492 | 0 | { |
493 | 0 | return detail::get_log_resources()->UnsetCategoryFilter(); |
494 | 0 | } |
495 | | |
496 | | bool Log::HasCategoryFilter() |
497 | 0 | { |
498 | 0 | return detail::get_log_resources()->HasCategoryFilter(); |
499 | 0 | } |
500 | | |
501 | | std::regex Log::GetCategoryFilter() |
502 | 0 | { |
503 | 0 | return detail::get_log_resources()->GetCategoryFilter(); |
504 | 0 | } |
505 | | |
506 | | std::regex Log::GetFilenameFilter() |
507 | 0 | { |
508 | 0 | return detail::get_log_resources()->GetFilenameFilter(); |
509 | 0 | } |
510 | | |
511 | | std::regex Log::GetErrorStringFilter() |
512 | 0 | { |
513 | 0 | return detail::get_log_resources()->GetErrorStringFilter(); |
514 | 0 | } |
515 | | |
516 | | void LogConsumer::print_timestamp( |
517 | | std::ostream& stream, |
518 | | const Log::Entry& entry, |
519 | | bool color) const |
520 | 1.32M | { |
521 | 1.32M | std::string white = (color) ? C_B_WHITE : ""; |
522 | 1.32M | stream << white << entry.timestamp << " "; |
523 | 1.32M | } |
524 | | |
525 | | void LogConsumer::print_header( |
526 | | std::ostream& stream, |
527 | | const Log::Entry& entry, |
528 | | bool color) const |
529 | 1.32M | { |
530 | 1.32M | std::string c_b_color = (!color) ? "" : |
531 | 1.32M | (entry.kind == Log::Kind::Error) ? C_B_RED : |
532 | 1.32M | (entry.kind == Log::Kind::Warning) ? C_B_YELLOW : |
533 | 0 | (entry.kind == Log::Kind::Info) ? C_B_GREEN : ""; |
534 | | |
535 | 1.32M | std::string white = (color) ? C_B_WHITE : ""; |
536 | | |
537 | 1.32M | stream << c_b_color << "[" << white << entry.context.category << c_b_color << " " << entry.kind << "] "; |
538 | 1.32M | } |
539 | | |
540 | | void LogConsumer::print_context( |
541 | | std::ostream& stream, |
542 | | const Log::Entry& entry, |
543 | | bool color) const |
544 | 1.32M | { |
545 | 1.32M | if (color) |
546 | 1.32M | { |
547 | 1.32M | stream << C_B_BLUE; |
548 | 1.32M | } |
549 | 1.32M | if (entry.context.filename) |
550 | 0 | { |
551 | 0 | stream << " (" << entry.context.filename; |
552 | 0 | stream << ":" << entry.context.line << ")"; |
553 | 0 | } |
554 | 1.32M | if (entry.context.function) |
555 | 1.32M | { |
556 | 1.32M | stream << " -> Function "; |
557 | 1.32M | if (color) |
558 | 1.32M | { |
559 | 1.32M | stream << C_CYAN; |
560 | 1.32M | } |
561 | 1.32M | stream << entry.context.function; |
562 | 1.32M | } |
563 | 1.32M | } |
564 | | |
565 | | void LogConsumer::print_message( |
566 | | std::ostream& stream, |
567 | | const Log::Entry& entry, |
568 | | bool color) const |
569 | 1.32M | { |
570 | 1.32M | std::string white = (color) ? C_WHITE : ""; |
571 | 1.32M | stream << white << entry.message; |
572 | 1.32M | } |
573 | | |
574 | | void LogConsumer::print_new_line( |
575 | | std::ostream& stream, |
576 | | bool color) const |
577 | 1.32M | { |
578 | 1.32M | std::string def = (color) ? C_DEF : ""; |
579 | 1.32M | stream << def << std::endl; |
580 | 1.32M | } |
581 | | |
582 | | } //namespace dds |
583 | | } //namespace fastdds |
584 | | } //namespace eprosima |