8000 improvements for logging (#13492) · tylde/arangodb@cae38f0 · GitHub
[go: up one dir, main page]
Skip to content

Commit cae38f0

Browse files
jsteemannjsteemann
authored
improvements for logging (arangodb#13492)
1 parent 0cade7b commit cae38f0

21 files changed

+1112
-96
lines changed

‎CHANGELOG

Lines changed: 40 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,45 @@
11
devel
22
-----
33

4+
* Improvements for logging. This adds the following startup options to arangod:
5+
6+
- `--log.max-entry-length`: controls the maximum line length for individual
7+
log messages that are written into normal logfiles by arangod (note: this
8+
does not include audit log messages).
9+
Any log messages longer than the specified value will be truncated and the
10+
suffix '...' will be added to them. The purpose of this parameter is to
11+
shorten long log messages in case there is not a lot of space for logfiles,
12+
and to keep rogue log messages from overusing resources.
13+
The default value is 128 MB, which is very high and should effectively
14+
mean downwards-compatiblity with previous arangod versions, which did not
15+
restrict the maximum size of log messages.
16+
17+
- `--audit.max-entry-length`: controls the maximum line length for individual
18+
audit log messages that are written into audit logs by arangod. Any audit
19+
log messages longer than the specified value will be truncated and the
20+
suffix '...' will be added to them.
21+
The default value is 128 MB, which is very high and should effectively
22+
mean downwards-compatiblity with previous arangod versions, which did not
23+
restrict the maximum size of log messages.
24+
25+
- `--log.in-memory-level`: controls which log messages are preserved in
26+
memory (in case `--log.in-memory` is set to `true`). The default value is
27+
`info`, meaning all log messages of types `info`, `warning`, `error` and
28+
`fatal` will be stored by an instance in memory (this was also the behavior
29+
in previous versions of ArangoDB). By setting this option to `warning`,
30+
only `warning` log messages will be preserved in memory, and by setting
31+
the option to `error` only error messages will be kept.
32+
This option is useful because the number of in-memory log messages is
33+
limited to the latest 2048 messages, and these slots are by default shared
34+
between informational, warning and error messages.
35+
36+
* Honor the value of startup option `--log.api-enabled` when set to `false`.
37+
THe desired behavior in this case is to turn off the REST API for logging,
38+
but was not implemented. The default value for the option is `true`, so the
39+
REST API is enabled. This behavior did not change, and neither did the
40+
behavior when setting the option to a value of `jwt` (meaning the REST API
41+
for logging is only available for superusers with a valid JWT token).
42+
443
* Split the update operations for the _fishbowl system collection with Foxx
544
apps into separate insert/replace and remove operations. This makes the
645
overall update not atomic, but as removes are unlikely here, we can now get
@@ -340,7 +379,7 @@ devel
340379
run in parallel. The defaults are intentionally high in order to not stop any valid,
341380
previously working queries from succedding.
342381

343-
* Added startup options `--audit.queue` to control audit logging queuing
382+
* Added startup option `--audit.queue` to control audit logging queuing
344383
behavior (Enterprise Edition only):
345384

346385
The option controls whether audit log messages are submitted to a queue

‎arangod/RestHandler/RestAdminLogHandler.cpp

Lines changed: 22 additions & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@
2525

2626
#include <velocypack/Builder.h>
2727
#include <velocypack/Iterator.h>
28+
#include <velocypack/Slice.h>
2829
#include <velocypack/velocypack-aliases.h>
2930

3031
#include "ApplicationFeatures/ApplicationServer.h"
@@ -45,6 +46,11 @@ RestAdminLogHandler::RestAdminLogHandler(arangodb::application_features::Applica
4546

4647
arangodb::Result RestAdminLogHandler::verifyPermitted() {
4748
auto& loggerFeature = server().getFeature<arangodb::LoggerFeature>();
49+
50+
if (!loggerFeature.isAPIEnabled()) {
51+
return arangodb::Result(
52+
TRI_ERROR_HTTP_FORBIDDEN, "log API is disabled");
53+
}
4854

4955
// do we have admin rights (if rights are active)
5056
if (loggerFeature.onlySuperUser()) {
@@ -70,8 +76,12 @@ RestStatus RestAdminLogHandler::execute() {
7076
return RestStatus::DONE;
7177
}
7278

79+
auto const type = _request->requestType();
7380
size_t const len = _request->suffixes().size();
74-
if (len == 0) {
81+
82+
if (type == rest::RequestType::DELETE_REQ) {
83+
clearLogs();
84+
} else if (len == 0) {
7585
reportLogs();
7686
} else {
7787
setLogLevel();
@@ -80,6 +90,11 @@ RestStatus RestAdminLogHandler::execute() {
8090
return RestStatus::DONE;
8191
}
8292

93+
void RestAdminLogHandler::clearLogs() {
94+
server().getFeature<LogBufferFeature>().clear();
95+
generateOk(rest::ResponseCode::OK, VPackSlice::emptyObjectSlice());
96+
}
97+
8398
void RestAdminLogHandler::reportLogs() {
8499
// check the maximal log level to report
85100
bool found1;
@@ -235,31 +250,13 @@ void RestAdminLogHandler::reportLogs() {
235250
for (size_t i = 0; i < length; ++i) {
236251
try {
237252
auto& buf = clean.at(i + static_cast<size_t>(offset));
238-
uint32_t l = 0;
239-
240-
switch (buf._level) {
241-
case LogLevel::FATAL:
242-
l = 0;
243-
break;
244-
case LogLevel::ERR:
245-
l = 1;
246-
break;
247-
case LogLevel::WARN:
248-
l = 2;
249-
break;
250-
case LogLevel::DEFAULT:
251-
case LogLevel::INFO:
252-
l = 3;
253-
break;
254-
case LogLevel::DEBUG:
255-
l = 4;
256-
break;
257-
case LogLevel::TRACE:
258-
l = 5;
259-
break;
260-
}
261253

262-
result.add(VPackValue(l));
254+
if (buf._level == LogLevel::DEFAULT) {
255+
result.add(VPackValue(3)); // INFO
256+
} else {
257+
TRI_ASSERT(static_cast<uint32_t>(buf._level) > 0);
258+
result.add(VPackValue(static_cast<uint32_t>(buf._level) - 1));
259+
}
263260
} catch (...) {
264261
}
265262
}

‎arangod/RestHandler/RestAdminLogHandler.h

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -45,6 +45,7 @@ class RestAdminLogHandler : public RestBaseHandler {
4545

4646
private:
4747
arangodb::Result verifyPermitted();
48+
void clearLogs();
4849
void reportLogs();
4950
void setLogLevel();
5051

‎lib/Logger/LogBufferFeature.cpp

Lines changed: 34 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -56,18 +56,18 @@ LogBuffer::LogBuffer()
5656
/// @brief logs to a fixed size ring buffer in memory
5757
class LogAppenderRingBuffer final : public LogAppender {
5858
public:
59-
LogAppenderRingBuffer()
59+
explicit LogAppenderRingBuffer(LogLevel minLogLevel)
6060
: LogAppender(),
61+
_minLogLevel(minLogLevel),
6162
_id(0) {
6263
MUTEX_LOCKER(guard, _lock);
6364
_buffer.resize(LogBufferFeature::BufferSize);
6465
}
6566

6667
public:
6768
void logMessage(LogMessage const& message) override {
68-
if (message._level == LogLevel::FATAL) {
69-
// no need to track FATAL messages here, as the process will go down
70-
// anyway
69+
if (message._level > _minLogLevel) {
70+
// logger not configured to log these messages
7171
return;
7272
}
7373

@@ -86,6 +86,13 @@ class LogAppenderRingBuffer final : public LogAppender {
8686
sizeof(ptr._message) - 1);
8787
}
8888

89+
void clear() {
90+
MUTEX_LOCKER(guard, _lock);
91+
_id = 0;
92+
_buffer.clear();
93+
_buffer.resize(LogBufferFeature::BufferSize);
94+
}
95+
8996
std::string details() const override {
9097
return std::string();
9198
}
@@ -133,6 +140,7 @@ class LogAppenderRingBuffer final : public LogAppender {
133140

134141
private:
135142
Mutex _lock;
143+
LogLevel const _minLogLevel;
136144
uint64_t _id;
137145
std::vector<LogBuffer> _buffer;
138146
};
@@ -184,6 +192,7 @@ class LogAppenderEventLog final : public LogAppender {
184192

185193
LogBufferFeature::LogBufferFeature(application_features::ApplicationServer& server)
186194
: ApplicationFeature(server, "LogBuffer"),
195+
_minInMemoryLogLevel("info"),
187196
_useInMemoryAppender(true) {
188197
setOptional(true);
189198
startsAfter<LoggerFeature>();
@@ -202,18 +211,38 @@ void LogBufferFeature::collectOptions(std::shared_ptr<options::ProgramOptions> o
202211
new BooleanParameter(&_useInMemoryAppender),
203212
arangodb::options::makeDefaultFlags(arangodb::options::Flags::Hidden))
204213
.setIntroducedIn(30701);
214+
215+
std::unordered_set<std::string> const logLevels = { "fatal", "error", "err", "warning", "warn", "info", "debug", "trace" };
216+
options
217+
->addOption("--log.in-memory-level", "use in-memory log appender only for this log level and higher",
218+
new DiscreteValuesParameter<StringParameter>(
219+
&_minInMemoryLogLevel, logLevels),
220+
arangodb::options::makeDefaultFlags(arangodb::options::Flags::Hidden))
221+
.setIntroducedIn(30800);
205222
}
206223

207224
void LogBufferFeature::prepare() {
208225
if (_useInMemoryAppender) {
209226
// only create the in-memory appender when we really need it. if we created it
210227
// in the ctor, we would waste a lot of memory in case we don't need the in-memory
211228
// appender. this is the case for simple command such as `--help` etc.
212-
_inMemoryAppender = std::make_shared<LogAppenderRingBuffer>();
229+
LogLevel level;
230+
bool isValid = Logger::translateLogLevel(_minInMemoryLogLevel, true, level);
231+
if (!isValid) {
232+
level = LogLevel::INFO;
233+
}
234+
235+
_inMemoryAppender = std::make_shared<LogAppenderRingBuffer>(level);
213236
LogAppender::addGlobalAppender(Logger::defaultLogGroup(), _inMemoryAppender);
214237
}
215238
}
216239

240+
void LogBufferFeature::clear() {
241+
if (_inMemoryAppender != nullptr) {
242+
static_cast<LogAppenderRingBuffer*>(_inMemoryAppender.get())->clear();
243+
}
244+
}
245+
217246
std::vector<LogBuffer> LogBufferFeature::entries(LogLevel level, uint64_t start, bool upToLevel) {
218247
if (_inMemoryAppender == nullptr) {
219248
return std::vector<LogBuffer>();

‎lib/Logger/LogBufferFeature.h

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -64,8 +64,12 @@ class LogBufferFeature final : public application_features::ApplicationFeature {
6464
/// @brief return all buffered log entries
6565
std::vector<LogBuffer> entries(LogLevel, uint64_t start, bool upToLevel);
6666

67+
/// @brief clear all log entries
68+
void clear();
69+
6770
private:
6871
std::shared_ptr<LogAppender> _inMemoryAppender;
72+
std::string _minInMemoryLogLevel;
6973
bool _useInMemoryAppender;
7074
};
7175

‎lib/Logger/LogGroup.h

Lines changed: 20 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,7 @@
2424
#ifndef ARANGODB_LOGGER_LOG_GROUP_H
2525
#define ARANGODB_LOGGER_LOG_GROUP_H 1
2626

27+
#include <atomic>
2728
#include <cstddef>
2829

2930
namespace arangodb {
@@ -32,11 +33,30 @@ class LogGroup {
3233
public:
3334
// @brief Number of log groups; must increase this when a new group is added
3435
static constexpr std::size_t Count = 2;
36+
37+
LogGroup()
38+
: _maxLogEntryLength(256U * 1048576U) {}
39+
3540
virtual ~LogGroup() = default;
3641

3742
/// @brief Must return a UNIQUE identifier amongst all LogGroup derivatives
3843
/// and must be less than Count
3944
virtual std::size_t id() const = 0;
45+
46+
/// @brief max length of log entries in this group
47+
std::size_t maxLogEntryLength() const noexcept {
48+
return _maxLogEntryLength.load(std::memory_order_relaxed);
49+
}
50+
51+
/// @brief set the max length of log entries in this group.
52+
/// should not be called during the setup of the Logger, and not at runtime
53+
void maxLogEntryLength(std::size_t value) {
54+
_maxLogEntryLength.store(value);
55+
}
56+
57+
protected:
58+
/// @brief maximum length of log entries in this LogGroup
59+
std::atomic<std::size_t> _maxLogEntryLength;
4060
};
4161

4262
} // namespace arangodb

‎lib/Logger/Logger.cpp

Lines changed: 30 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -72,7 +72,7 @@ static std::string const UNKNOWN = "UNKNOWN";
7272

7373
std::string const LogThreadName("Logging");
7474

75-
class DefaultLogGroup : public LogGroup {
75+
class DefaultLogGroup final : public LogGroup {
7676
std::size_t id() const override { return 0; }
7777
};
7878
DefaultLogGroup defaultLogGroupInstance;
@@ -141,22 +141,9 @@ void Logger::setLogLevel(std::string const& levelName) {
141141
}
142142

143143
LogLevel level;
144+
bool isValid = translateLogLevel(l, isGeneral, level);
144145

145-
if (l == "fatal") {
146-
level = LogLevel::FATAL;
147-
} else if (l == "error" || l == "err") {
148-
level = LogLevel::ERR;
149-
} else if (l == "warning" || l == "warn") {
150-
level = LogLevel::WARN;
151-
} else if (l == "info") {
152-
level = LogLevel::INFO;
153-
} else if (l == "debug") {
154-
level = LogLevel::DEBUG;
155-
} else if (l == "trace") {
156-
level = LogLevel::TRACE;
157-
} else if (!isGeneral && (l.empty() || l == "default")) {
158-
level = LogLevel::DEFAULT;
159-
} else {
146+
if (!isValid) {
160147
if (!isGeneral) {
161148
LOG_TOPIC("05367", WARN, arangodb::Logger::FIXME) << "strange log level '" << levelName << "'";
162149
return;
@@ -314,6 +301,28 @@ void Logger::setUseJson(bool value) {
314301
_useJson = value;
315302
}
316303

304+
bool Logger::translateLogLevel(std::string const& l, bool isGeneral, LogLevel& level) noexcept {
305+
if (l == "fatal") {
306+
level = LogLevel::FATAL;
307+
} else if (l == "error" || l == "err") {
308+
level = LogLevel::ERR;
309+
} else if (l == "warning" || l == "warn") {
310+
level = LogLevel::WARN;
311+
} else if (l == "info") {
312+
level = LogLevel::INFO;
313+
} else if (l == "debug") {
314+
level = LogLevel::DEBUG;
315+
} else if (l == "trace") {
316+
level = LogLevel::TRACE;
317+
} else if (!isGeneral && (l.empty() || l == "default")) {
318+
level = LogLevel::DEFAULT;
319+
} else {
320+
return false;
321+
}
322+
323+
return true;
324+
}
325+
317326
std::string const& Logger::translateLogLevel(LogLevel level) noexcept {
318327
switch (level) {
319328
case LogLevel::ERR:
@@ -568,9 +577,12 @@ void Logger::log(char const* logid, char const* function, char const* file, int
568577
// logging itself must never cause an exeption to escape
569578
}
570579

571-
void Logger::append(LogGroup& group, std::unique_ptr<LogMessage>& msg,
580+
void Logger::append(LogGroup& group,
581+
std::unique_ptr<LogMessage>& msg,
572582
bool forceDirect,
573583
std::function<void(std::unique_ptr<LogMessage>&)> const& inactive) {
584+
msg->shrink(group.maxLogEntryLength());
585+
574586
// first log to all "global" appenders, which are the in-memory ring buffer logger plus
575587
// some Windows-specifc appenders for the debug output window and the Windows event log.
576588
// note that these loggers do not require any configuration so we can always and safely invoke them.
@@ -617,7 +629,7 @@ void Logger::initialize(application_features::ApplicationServer& server, bool th
617629
if (threaded) {
618630
_loggingThread = std::make_unique<LogThread>(server, ::LogThreadName);
619631
if (!_loggingThread->start()) {
620-
LOG_TOPIC("28bd9", FATAL, arangodb::Logger::STATISTICS)
632+
LOG_TOPIC("28bd9", FATAL, arangodb::Logger::FIXME)
621633
<< "could not start logging thread";
622634
FATAL_ERROR_EXIT();
623635
}

0 commit comments

Comments
 (0)
0