Just some initial thoughts on what a new logging daemon should do for us:
The primary goal - we want to use a binary message format with as few format conversions as possible between log sender and log processor.
I'm thinking that we use message catalogs; we will need a tool to preprocess every logging invocation in the source tree and replace them with a integer messageID. So at runtime only the messageID and the message parameters need to be sent, not any plaintext.
The message catalog will be compiled into the binary. When it performs its "openlog" to talk to the logging server, it will send the UUID of its catalog. If the logging server doesn't know this UUID, it will transmit the message catalog to the logging server, before doing anything else. (It may make more sense just to use a SHA hash here instead of a UUID.)
This way the logging server will work with any version of the binaries, and we don't need to do special coordination to update message catalogs between revisions. The logging server will just know that a specific catalog is to be used with a particular logging session.
The message protocol will be length-prefixed. We may even just use DER, since that would allow us to encode arrays of parameters, and other such stuff.
The logging server will write the log messages to disk/network verbatim, doing no parsing at all. It may prefix the records with a log session ID, so that a postprocessor can lookup the catalog that belongs to the session, for dumping out as text.
The logging server can store its received catalogs in an LMDB database. The postprocessor can then lookup individual messageIDs in this database, interpolate the parameters, and dump out in text.
... that's what I have so far. It's a bit worrisome because of the additional moving parts: message catalog creator, log server, log postprocessor. There's definitely more complexity here, but most of it is moved out of the runtime hot path, which is the main goal. Suggestions?
Hi Howard,
This is for slapd to speak to?
What's the higher level arch/issue?
Thanks.
On Thu, Mar 05, 2020 at 04:06:42PM +0000, Howard Chu wrote:
Just some initial thoughts on what a new logging daemon should do for us:
The primary goal - we want to use a binary message format with as few format conversions as possible between log sender and log processor.
I'm thinking that we use message catalogs; we will need a tool to preprocess every logging invocation in the source tree and replace them with a integer messageID. So at runtime only the messageID and the message parameters need to be sent, not any plaintext.
This might not work in the place of loadable modules where you have to deal with many catalogs etc.
How about a different proposition, we use the message format char * as the message id, potentially sending the text over the first time it's used. This could still break if we unload a module and a new one is loaded in its place, but that sounds fixable.
... that's what I have so far. It's a bit worrisome because of the additional moving parts: message catalog creator, log server, log postprocessor. There's definitely more complexity here, but most of it is moved out of the runtime hot path, which is the main goal. Suggestions?
Moving a lot of work to the log postprocessor is good.
--On Friday, March 6, 2020 2:26 PM +0000 Gavin Henry ghenry@suretec.co.uk wrote:
Hi Howard,
This is for slapd to speak to?
What's the higher level arch/issue?
Several issues:
* The sheer volume of log files generated at large sites (i.e., multiple GB/hour) that make log retention difficult, which can cause problems when trying to diagnose issues * syslog being lossy, making it difficult to determine root cause of issues, etc * The significant negative performance impact from logging. Clearly no logging will always be faster than logging enabled, but it should be possible to reduce the impact as compared to the current state.
--Quanah
--
Quanah Gibson-Mount Product Architect Symas Corporation Packaged, certified, and supported LDAP solutions powered by OpenLDAP: http://www.symas.com
Howard Chu wrote:
Just some initial thoughts on what a new logging daemon should do for us:
The primary goal - we want to use a binary message format with as few format conversions as possible between log sender and log processor.
One other concern - what do we do about debug output to stderr? If we keep that, then we still have message formatting overhead inside slapd itself, and we're potentially managing two redundant sets of message formats.
When developing an outline for a show on the Software Engineering Radio podcast, we're asked to search through all IEEE archives for the topic in question.
You may find some inspiration or ideas:
https://www.computer.org/csdl/search/default?type=basic&basicSearchText=...
Gavin.
Ondřej Kuzník wrote:
On Thu, Mar 05, 2020 at 04:06:42PM +0000, Howard Chu wrote:
Just some initial thoughts on what a new logging daemon should do for us:
The primary goal - we want to use a binary message format with as few format conversions as possible between log sender and log processor.
I'm thinking that we use message catalogs; we will need a tool to preprocess every logging invocation in the source tree and replace them with a integer messageID. So at runtime only the messageID and the message parameters need to be sent, not any plaintext.
This might not work in the place of loadable modules where you have to deal with many catalogs etc.
How about a different proposition, we use the message format char * as the message id, potentially sending the text over the first time it's used. This could still break if we unload a module and a new one is loaded in its place, but that sounds fixable.
This sounds like we would need to keep track of which texts we've already sent, from the caller's side.
We could alternatively just add another openlog() call in our module_load() handler, to push over any module-specific messages. A catalog ID can be assigned to each module, and prefixed to the individual message IDs being transmitted.
... that's what I have so far. It's a bit worrisome because of the additional moving parts: message catalog creator, log server, log postprocessor. There's definitely more complexity here, but most of it is moved out of the runtime hot path, which is the main goal. Suggestions?
Moving a lot of work to the log postprocessor is good.
On 2020-03-06T17:02:14, Howard Chu wrote:
Howard Chu wrote:
Just some initial thoughts on what a new logging daemon should do for us:
The primary goal - we want to use a binary message format with as few format conversions as possible between log sender and log processor.
One other concern - what do we do about debug output to stderr? If we keep that, then we still have message formatting overhead inside slapd itself, and we're potentially managing two redundant sets of message formats.
I'm not sure if you're toying with the idea of removing output to stdout/stderr but I figure I'll share my 2cents anyway.
We make *heavy* use of openldap in containers and having the output go to stdout and stderr is *super* helpful when debugging issues in vanilla docker or kubernetes.
Not only does stdout allow you to use native tools such as `journalctl` or `kubectl` out of the box, log aggregation is a completely solved problem in this workflow and is trivial to implement.
That being said, persisting logs to disk in a binary format has its merits. Personally, I don't think plain text logs scale all that well.
Matt Pallissard
On 2020-03-11T07:39:45, Pallissard, Matthew wrote:
On 2020-03-06T17:02:14, Howard Chu wrote:
Howard Chu wrote:
Just some initial thoughts on what a new logging daemon should do for us:
The primary goal - we want to use a binary message format with as few format conversions as possible between log sender and log processor.
One other concern - what do we do about debug output to stderr? If we keep that, then we still have message formatting overhead inside slapd itself, and we're potentially managing two redundant sets of message formats.
And now that I'm thinking it through a little bit, you wouldn't necessarily have to maintain two sets of message formats.
A grossly over simplified idea would be to implement a log parsing library, link slapd and the log processor to it. If stdout/stderr debugging is enabled skip all of the stuff that happens in between the log server and reading the log file, parse and print.
And if you're really worried about performance overhead you could get clever at compile time and make this opt-in or out. Management overhead is a different story entirely.
I'm not sure if you're toying with the idea of removing output to stdout/stderr but I figure I'll share my 2cents anyway.
We make *heavy* use of openldap in containers and having the output go to stdout and stderr is *super* helpful when debugging issues in vanilla docker or kubernetes.
Not only does stdout allow you to use native tools such as `journalctl` or `kubectl` out of the box, log aggregation is a completely solved problem in this workflow and is trivial to implement.
That being said, persisting logs to disk in a binary format has its merits. Personally, I don't think plain text logs scale all that well.
Matt Pallissard
Matt Pallissard
Pallissard, Matthew wrote:
On 2020-03-06T17:02:14, Howard Chu wrote:
Howard Chu wrote:
Just some initial thoughts on what a new logging daemon should do for us:
The primary goal - we want to use a binary message format with as few format conversions as possible between log sender and log processor.
One other concern - what do we do about debug output to stderr? If we keep that, then we still have message formatting overhead inside slapd itself, and we're potentially managing two redundant sets of message formats.
I'm not sure if you're toying with the idea of removing output to stdout/stderr but I figure I'll share my 2cents anyway.
We make *heavy* use of openldap in containers and having the output go to stdout and stderr is *super* helpful when debugging issues in vanilla docker or kubernetes.
Not only does stdout allow you to use native tools such as `journalctl` or `kubectl` out of the box, log aggregation is a completely solved problem in this workflow and is trivial to implement.
That being said, persisting logs to disk in a binary format has its merits. Personally, I don't think plain text logs scale all that well.
Plaintext logs scale horribly. When you have servers processing hundreds of thousands to millions of queries/sec, you have to rotate log files pretty frequently otherwise your disks get filled. The majority of the text associated with each message is constant and redundant as well. (Which also means the logfiles are highly compressible, but that still requires CPU to accomplish.)
We may be able to tolerate keeping the stderr messaging intact. When it's turned on it probably won't be worse than a 10% performance hit. https://www.openldap.org/lists/openldap-devel/201511/msg00000.html And writing to stderr is still several times faster than syslog() at the moment.
--On Thursday, March 12, 2020 12:35 AM +0000 Howard Chu hyc@symas.com wrote:
Not only does stdout allow you to use native tools such as `journalctl` or `kubectl` out of the box, log aggregation is a completely solved problem in this workflow and is trivial to implement.
That being said, persisting logs to disk in a binary format has its merits. Personally, I don't think plain text logs scale all that well.
Plaintext logs scale horribly. When you have servers processing hundreds of thousands to millions of queries/sec, you have to rotate log files pretty frequently otherwise your disks get filled.
The issue I found, at least with journald, is it deadlocks when subjected to millions of queries/sec environments.
--Quanah
--
Quanah Gibson-Mount Product Architect Symas Corporation Packaged, certified, and supported LDAP solutions powered by OpenLDAP: http://www.symas.com
Howard Chu wrote:
Just some initial thoughts on what a new logging daemon should do for us:
Scaling back to something easier for now:
We'll use the existing Debug msgs as-is. The olcLogFile directive will specify the path of a local logging file to write to. Currently, writing to this logfile is controlled by the -d debuglevel flags, not the -s sysloglevel flags. When a logfile is configured, debug messages go to both stderr and the logfile.
We'll add a new option olcLogFileOnly (boolean), which will force messages to only go to the logfile (and skip writing any to stderr). Since the point of using the local file logging facility is for performance, it will be desirable to avoid this double-writing of messages.
We'll add an olcLogFileRotate option that specifies a logfile maxsize and rotation interval, in megabytes and hours, respectively. Any message that would cause the current logfile to exceed the specified size will cause the file to be closed/rotated/reopened. Any message that arrives after the specified number of hours will do likewise. Rotated files will be renamed to <logfile>.YYYYMMDDHHMM.
Supporting this rotation functionality will require a mutex around the logger function, so it's possible that we still won't gain back much performance going down this route.
Possibly the parameter should include another field for max # of logfiles to retain, I haven't really thought about that yet.
Comments?
On Wed, Jul 14, 2021 at 03:40:35PM +0100, Howard Chu wrote:
Howard Chu wrote:
Just some initial thoughts on what a new logging daemon should do for us:
Scaling back to something easier for now:
We'll use the existing Debug msgs as-is. The olcLogFile directive will specify the path of a local logging file to write to. Currently, writing to this logfile is controlled by the -d debuglevel flags, not the -s sysloglevel flags. When a logfile is configured, debug messages go to both stderr and the logfile.
We'll add a new option olcLogFileOnly (boolean), which will force messages to only go to the logfile (and skip writing any to stderr). Since the point of using the local file logging facility is for performance, it will be desirable to avoid this double-writing of messages.
We'll add an olcLogFileRotate option that specifies a logfile maxsize and rotation interval, in megabytes and hours, respectively. Any message that would cause the current logfile to exceed the specified size will cause the file to be closed/rotated/reopened. Any message that arrives after the specified number of hours will do likewise. Rotated files will be renamed to <logfile>.YYYYMMDDHHMM.
This sounds too complicated, you'd need to measure time and/or size written everywhere and all the time.
Solutions already exist that do this and everyone knows how to use them: logrotate(8). We just need to register a signal (SIGHUP or SIGUSR1 are used most often) and freopen(3) the stderr stream in the handler. No locks needed, job done.
Supporting this rotation functionality will require a mutex around the logger function, so it's possible that we still won't gain back much performance going down this route.
Possibly the parameter should include another field for max # of logfiles to retain, I haven't really thought about that yet.
Comments?
-
Gavin Henry -
Howard Chu -
Ondřej Kuzník -
Pallissard, Matthew -
Quanah Gibson-Mount