1 /* -*- MODE: C++; tab-width: 4; c-basic-offset: 4; indent-tabs-mode: nil -*- */
2 /*
3  *     Copyright 2017 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 
18 #include "config.h"
19 
20 #include "custom_rotating_file_sink.h"
21 
22 #include "logger.h"
23 
24 #include <memcached/engine.h>
25 #include <memcached/extension.h>
26 #include <spdlog/sinks/dist_sink.h>
27 #include <spdlog/sinks/null_sink.h>
28 #include <spdlog/sinks/stdout_sinks.h>
29 #include <spdlog/spdlog.h>
30 #include <chrono>
31 #include <cstdio>
32 
33 #ifndef WIN32
34 #include <spdlog/sinks/ansicolor_sink.h>
35 #endif
36 
37 static const std::string logger_name{"spdlog_file_logger"};
38 
39 static EXTENSION_LOGGER_DESCRIPTOR descriptor;
40 
41 /**
42  * Custom log pattern which the loggers will use.
43  * This pattern is duplicated for some test cases. If you need to update it,
44  * please also update in all relevant places.
45  * TODO: Remove the duplication in the future, by (maybe) moving
46  *       the const to a header file.
47  */
48 static const std::string log_pattern{"%Y-%m-%dT%T.%fZ %l %v"};
49 
convertToSpdSeverity( EXTENSION_LOG_LEVEL sev)50 spdlog::level::level_enum cb::logger::convertToSpdSeverity(
51         EXTENSION_LOG_LEVEL sev) {
52     using namespace spdlog::level;
53     switch (sev) {
54     case EXTENSION_LOG_DEBUG:
55         return level_enum::debug;
56     case EXTENSION_LOG_INFO:
57         return level_enum::info;
58     case EXTENSION_LOG_NOTICE:
59         return level_enum::info;
60     case EXTENSION_LOG_WARNING:
61         return level_enum::warn;
62     case EXTENSION_LOG_FATAL:
63         return level_enum::critical;
64     }
65     throw std::invalid_argument("Unknown severity level");
66 }
67 
68 /**
69  * Instances of spdlog (async) file logger.
70  * The files logger requires a rotating file sink which is manually configured
71  * from the parsed settings.
72  * The loggers act as a handle to the sinks. They do the processing of log
73  * messages and send them to the sinks, which do the actual writing (to file,
74  * to stream etc.) or further processing.
75  */
76 static std::shared_ptr<spdlog::logger> file_logger;
77 
78 /**
79  * Retrieves a message, applies formatting and then logs it to stderr and
80  * to file, according to the severity.
81  */
log(EXTENSION_LOG_LEVEL mcd_severity, const void* client_cookie, const char* fmt, ...)82 static void log(EXTENSION_LOG_LEVEL mcd_severity,
83                 const void* client_cookie,
84                 const char* fmt,
85                 ...) {
86     const auto severity = cb::logger::convertToSpdSeverity(mcd_severity);
87 
88     // Retrieve formatted log message
89     char msg[2048];
90     int len;
91     va_list va;
92     va_start(va, fmt);
93     len = vsnprintf(msg, 2048, fmt, va);
94     va_end(va);
95 
96     // Something went wrong during formatting, so return
97     if (len < 0) {
98         return;
99     }
100     // len does not include '\0', hence >= and not >
101     if (len >= int(sizeof(msg))) {
102         // Crop message for logging
103         const char cropped[] = " [cut]";
104         snprintf(msg + (sizeof(msg) - sizeof(cropped)),
105                  sizeof(cropped),
106                  "%s",
107                  cropped);
108     } else {
109         msg[len] = '\0';
110     }
111 
112     file_logger->log(severity, msg);
113 }
114 
115 LOGGER_PUBLIC_API
flush()116 void cb::logger::flush() {
117     if (file_logger) {
118         file_logger->flush();
119     }
120 }
121 
122 LOGGER_PUBLIC_API
shutdown()123 void cb::logger::shutdown() {
124     flush();
125     file_logger.reset();
126     spdlog::drop_all();
127 }
128 
129 LOGGER_PUBLIC_API
isInitialized()130 const bool cb::logger::isInitialized() {
131     return file_logger != nullptr;
132 }
133 
134 /**
135  * Initialises the loggers. Called if the logger configuration is
136  * specified in a separate settings object.
137  */
initialize( const Config& logger_settings)138 boost::optional<std::string> cb::logger::initialize(
139         const Config& logger_settings) {
140     auto fname = logger_settings.filename;
141     auto buffersz = logger_settings.buffersize;
142     auto cyclesz = logger_settings.cyclesize;
143 
144     if (getenv("CB_MAXIMIZE_LOGGER_CYCLE_SIZE") != nullptr) {
145         cyclesz = 1024 * 1024 * 1024; // use up to 1 GB log file size
146     }
147 
148     if (getenv("CB_MAXIMIZE_LOGGER_BUFFER_SIZE") != nullptr) {
149         buffersz = 8 * 1024 * 1024; // use an 8MB log buffer
150     }
151 
152     try {
153         // Initialise the loggers.
154         //
155         // The structure is as follows:
156         //
157         // file_logger = sends log messages to sink
158         //   |__dist_sink_mt = Distribute log messages to multiple sinks
159         //       |     |__custom_rotating_file_sink_mt = adds opening & closing
160         //       |                                       hooks to the file
161         //       |__ (color)__stderr_sink_mt = Send log messages to consloe
162         //
163         // When a new log message is being submitted to the file_logger it
164         // is subject to the log level specified on the file_logger. If it
165         // is to be included it is passed down to the dist_sink which will
166         // evaluate if the message should be passed on based on its log level.
167         // It'll then try to pass the message to the file sink and the
168         // console sink and they will evaluate if the message should be
169         // logged or not. This means that we should set the file sink
170         // loglevel to TRACE so that all messages which goes all the way
171         // will end up in the file. Due to the fact that ns_server can't
172         // keep up with the rate we might produce log we want the console
173         // sink to drop everything below WARNING (unless we're running
174         // unit tests (through testapp).
175         //
176         // When the user change the verbosity level we'll modify the
177         // level for the file_logger object causing it to allow more
178         // messages to go down to the various sinks.
179 
180         auto sink = std::make_shared<spdlog::sinks::dist_sink_mt>();
181         sink->set_level(spdlog::level::trace);
182 
183         if (!fname.empty()) {
184             auto fsink = std::make_shared<custom_rotating_file_sink_mt>(
185                     fname, cyclesz, log_pattern);
186             fsink->set_level(spdlog::level::trace);
187             sink->add_sink(fsink);
188         }
189 
190         if (logger_settings.console) {
191 #ifdef WIN32
192             auto stderrsink = std::make_shared<spdlog::sinks::stderr_sink_mt>();
193 #else
194             auto stderrsink =
195                     std::make_shared<spdlog::sinks::ansicolor_stderr_sink_mt>();
196 #endif
197             if (logger_settings.unit_test) {
198                 stderrsink->set_level(spdlog::level::trace);
199             } else {
200                 stderrsink->set_level(spdlog::level::warn);
201             }
202             sink->add_sink(stderrsink);
203         }
204 
205         spdlog::drop(logger_name);
206         file_logger =
207                 spdlog::create_async(logger_name,
208                                      sink,
209                                      buffersz,
210                                      spdlog::async_overflow_policy::block_retry,
211                                      nullptr,
212                                      std::chrono::milliseconds(200));
213     } catch (const spdlog::spdlog_ex& ex) {
214         std::string msg =
215                 std::string{"Log initialization failed: "} + ex.what();
216         return boost::optional<std::string>{msg};
217     }
218 
219     file_logger->set_pattern(log_pattern);
220     file_logger->set_level(logger_settings.log_level);
221     return {};
222 }
223 
get()224 spdlog::logger* cb::logger::get() {
225     return file_logger.get();
226 }
227 
reset()228 void cb::logger::reset() {
229     file_logger.reset();
230 }
231 
createBlackholeLogger()232 void cb::logger::createBlackholeLogger() {
233     // delete if already exists
234     spdlog::drop(logger_name);
235 
236     file_logger = spdlog::create(
237             logger_name, std::make_shared<spdlog::sinks::null_sink_mt>());
238 
239     file_logger->set_level(spdlog::level::off);
240     file_logger->set_pattern(log_pattern);
241 }
242 
createConsoleLogger()243 void cb::logger::createConsoleLogger() {
244     // delete if already exists
245     spdlog::drop(logger_name);
246     file_logger = spdlog::stderr_color_mt(logger_name);
247     file_logger->set_level(spdlog::level::info);
248     file_logger->set_pattern(log_pattern);
249 }
250 
251 LOGGER_PUBLIC_API
getLoggerDescriptor()252 EXTENSION_LOGGER_DESCRIPTOR& cb::logger::getLoggerDescriptor() {
253     descriptor.log = log;
254     return descriptor;
255 }
256