1 /* -*- MODE: C++; tab-width: 4; c-basic-offset: 4; indent-tabs-mode: nil -*- */
2 /*
3  *     Copyright 2018 Couchbase, Inc
4  *
5  *   Licensed under the Apache License, Version 2.0 (the "License");
6  *   you may not use this file except in compliance with the License.
7  *   You may obtain a copy of the License at
8  *
9  *       http://www.apache.org/licenses/LICENSE-2.0
10  *
11  *   Unless required by applicable law or agreed to in writing, software
12  *   distributed under the License is distributed on an "AS IS" BASIS,
13  *   WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14  *   See the License for the specific language governing permissions and
15  *   limitations under the License.
16  */
17 #include "custom_rotating_file_sink.h"
18 
19 #include "logger.h"
20 #include "logger_config.h"
21 
22 #include <memcached/engine.h>
23 #include <spdlog/async.h>
24 #include <spdlog/async_logger.h>
25 #include <spdlog/sinks/dist_sink.h>
26 #include <spdlog/sinks/null_sink.h>
27 #include <spdlog/sinks/stdout_color_sinks.h>
28 #include <spdlog/sinks/stdout_sinks.h>
29 #include <chrono>
30 #include <cstdio>
31 static const std::string logger_name{"spdlog_file_logger"};
32 
33 /**
34  * Custom log pattern which the loggers will use.
35  * This pattern is duplicated for some test cases. If you need to update it,
36  * please also update in all relevant places.
37  * TODO: Remove the duplication in the future, by (maybe) moving
38  *       the const to a header file.
39  */
40 static const std::string log_pattern{"%^%Y-%m-%dT%T.%f%z %l %v%$"};
41 
42 /**
43  * Instances of spdlog (async) file logger.
44  * The files logger requires a rotating file sink which is manually configured
45  * from the parsed settings.
46  * The loggers act as a handle to the sinks. They do the processing of log
47  * messages and send them to the sinks, which do the actual writing (to file,
48  * to stream etc.) or further processing.
49  */
50 static std::shared_ptr<spdlog::logger> file_logger;
51 
52 LOGGER_PUBLIC_API
flush()53 void cb::logger::flush() {
54     if (file_logger) {
55         file_logger->flush();
56     }
57 }
58 
59 LOGGER_PUBLIC_API
shutdown()60 void cb::logger::shutdown() {
61     // Force a flush (posts a message to the async logger if we are not in unit
62     // test mode)
63     flush();
64 
65     /**
66      * This will drop all spdlog instances from the registry, and destruct the
67      * thread pool which will post terminate message(s) (one per thread) to the
68      * thread pool message queue. The calling thread will then block until all
69      * thread pool workers have joined. This ensures that any messages queued
70      * before shutdown is called will be flushed to disk. Any messages that are
71      * queued after the final terminate message will not be logged.
72      *
73      * If the logger is running in unit test mode (synchronous) then this is a
74      * no-op.
75      */
76     spdlog::details::registry::instance().shutdown();
77     file_logger.reset();
78 }
79 
80 LOGGER_PUBLIC_API
isInitialized()81 const bool cb::logger::isInitialized() {
82     return file_logger != nullptr;
83 }
84 
85 /**
86  * Initialises the loggers. Called if the logger configuration is
87  * specified in a separate settings object.
88  */
initialize( const Config& logger_settings)89 boost::optional<std::string> cb::logger::initialize(
90         const Config& logger_settings) {
91     auto fname = logger_settings.filename;
92     auto buffersz = logger_settings.buffersize;
93     auto cyclesz = logger_settings.cyclesize;
94 
95     if (getenv("CB_MAXIMIZE_LOGGER_CYCLE_SIZE") != nullptr) {
96         cyclesz = 1024 * 1024 * 1024; // use up to 1 GB log file size
97     }
98 
99     try {
100         // Initialise the loggers.
101         //
102         // The structure is as follows:
103         //
104         // file_logger = sends log messages to sink
105         //   |__dist_sink_mt = Distribute log messages to multiple sinks
106         //       |     |__custom_rotating_file_sink_mt = adds opening & closing
107         //       |                                       hooks to the file
108         //       |__ (color)__stderr_sink_mt = Send log messages to console
109         //
110         // When a new log message is being submitted to the file_logger it
111         // is subject to the log level specified on the file_logger. If it
112         // is to be included it is passed down to the dist_sink which will
113         // evaluate if the message should be passed on based on its log level.
114         // It'll then try to pass the message to the file sink and the
115         // console sink and they will evaluate if the message should be
116         // logged or not. This means that we should set the file sink
117         // loglevel to TRACE so that all messages which goes all the way
118         // will end up in the file. Due to the fact that ns_server can't
119         // keep up with the rate we might produce log we want the console
120         // sink to drop everything below WARNING (unless we're running
121         // unit tests (through testapp).
122         //
123         // When the user change the verbosity level we'll modify the
124         // level for the file_logger object causing it to allow more
125         // messages to go down to the various sinks.
126 
127         auto sink = std::make_shared<spdlog::sinks::dist_sink_mt>();
128         sink->set_level(spdlog::level::trace);
129 
130         if (!fname.empty()) {
131             auto fsink = std::make_shared<custom_rotating_file_sink_mt>(
132                     fname, cyclesz, log_pattern);
133             fsink->set_level(spdlog::level::trace);
134             sink->add_sink(fsink);
135         }
136 
137         if (logger_settings.console) {
138             auto stderrsink =
139                     std::make_shared<spdlog::sinks::stderr_color_sink_mt>();
140 
141             // Set the formatting pattern of this sink
142             stderrsink->set_pattern(log_pattern);
143             if (logger_settings.unit_test) {
144                 stderrsink->set_level(spdlog::level::trace);
145             } else {
146                 stderrsink->set_level(spdlog::level::warn);
147             }
148             sink->add_sink(stderrsink);
149         }
150 
151         spdlog::drop(logger_name);
152 
153         if (logger_settings.unit_test) {
154             file_logger = std::make_shared<spdlog::logger>(logger_name, sink);
155         } else {
156             // Create the default thread pool for async logging
157             spdlog::init_thread_pool(buffersz, 1);
158 
159             // Get the thread pool so that we can actually construct the
160             // object with already created sinks...
161             auto tp = spdlog::thread_pool();
162             file_logger = std::make_shared<spdlog::async_logger>(
163                     logger_name,
164                     sink,
165                     tp,
166                     spdlog::async_overflow_policy::block);
167         }
168 
169         file_logger->set_pattern(log_pattern);
170         file_logger->set_level(logger_settings.log_level);
171 
172         // Set the flushing interval policy
173         spdlog::flush_every(std::chrono::seconds(1));
174 
175         spdlog::register_logger(file_logger);
176     } catch (const spdlog::spdlog_ex& ex) {
177         std::string msg =
178                 std::string{"Log initialization failed: "} + ex.what();
179         return boost::optional<std::string>{msg};
180     }
181     return {};
182 }
183 
get()184 spdlog::logger* cb::logger::get() {
185     return file_logger.get();
186 }
187 
188 LOGGER_PUBLIC_API
reset()189 void cb::logger::reset() {
190     spdlog::drop(logger_name);
191     file_logger.reset();
192 }
193 
createBlackholeLogger()194 void cb::logger::createBlackholeLogger() {
195     // delete if already exists
196     spdlog::drop(logger_name);
197 
198     file_logger = std::make_shared<spdlog::logger>(
199             logger_name, std::make_shared<spdlog::sinks::null_sink_mt>());
200 
201     file_logger->set_level(spdlog::level::off);
202     file_logger->set_pattern(log_pattern);
203 
204     spdlog::register_logger(file_logger);
205 }
206 
createConsoleLogger()207 void cb::logger::createConsoleLogger() {
208     // delete if already exists
209     spdlog::drop(logger_name);
210 
211     auto stderrsink = std::make_shared<spdlog::sinks::stderr_color_sink_st>();
212 
213     file_logger = std::make_shared<spdlog::logger>(logger_name, stderrsink);
214     file_logger->set_level(spdlog::level::info);
215     file_logger->set_pattern(log_pattern);
216 
217     spdlog::register_logger(file_logger);
218 }
219 
220 LOGGER_PUBLIC_API
registerSpdLogger(std::shared_ptr<spdlog::logger> l)221 void cb::logger::registerSpdLogger(std::shared_ptr<spdlog::logger> l) {
222     try {
223         file_logger->debug("Registering logger {}", l->name());
224         spdlog::register_logger(l);
225     } catch (spdlog::spdlog_ex& e) {
226         file_logger->warn(
227                 "Exception caught when attempting to register the "
228                 "logger {} in the spdlog registry. The verbosity of "
229                 "this logger cannot be changed at runtime. e.what()"
230                 "={}",
231                 l->name(),
232                 e.what());
233     }
234 }
235 
236 LOGGER_PUBLIC_API
unregisterSpdLogger(const std::string& n)237 void cb::logger::unregisterSpdLogger(const std::string& n) {
238     spdlog::drop(n);
239 }
240 
241 LOGGER_PUBLIC_API
checkLogLevels(spdlog::level::level_enum level)242 bool cb::logger::checkLogLevels(spdlog::level::level_enum level) {
243     bool correct = true;
244     spdlog::apply_all([&](std::shared_ptr<spdlog::logger> l) {
245         if (l->level() != level) {
246             correct = false;
247         }
248     });
249     return correct;
250 }
251 
252 LOGGER_PUBLIC_API
setLogLevels(spdlog::level::level_enum level)253 void cb::logger::setLogLevels(spdlog::level::level_enum level) {
254     // Apply the function to each registered spdlogger
255     spdlog::apply_all([&](std::shared_ptr<spdlog::logger> l) {
256         try {
257             l->set_level(level);
258         } catch (spdlog::spdlog_ex& e) {
259             l->warn("Exception caught when attempting to change the verbosity "
260                     "of logger {} to spdlog level {}. e.what()={}",
261                     l->name(),
262                     to_c_str(level),
263                     e.what());
264         }
265     });
266 
267     flush();
268 }
269