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
37static const std::string logger_name{"spdlog_file_logger"};
38
39static 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 */
48static const std::string log_pattern{"%Y-%m-%dT%T.%fZ %l %v"};
49
50spdlog::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 */
76static 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 */
82static 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
115LOGGER_PUBLIC_API
116void cb::logger::flush() {
117    if (file_logger) {
118        file_logger->flush();
119    }
120}
121
122LOGGER_PUBLIC_API
123void cb::logger::shutdown() {
124    flush();
125    file_logger.reset();
126    spdlog::drop_all();
127}
128
129LOGGER_PUBLIC_API
130const 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 */
138boost::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
224spdlog::logger* cb::logger::get() {
225    return file_logger.get();
226}
227
228void cb::logger::reset() {
229    file_logger.reset();
230}
231
232void 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
243void 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
251LOGGER_PUBLIC_API
252EXTENSION_LOGGER_DESCRIPTOR& cb::logger::getLoggerDescriptor() {
253    descriptor.log = log;
254    return descriptor;
255}
256