8:06 a.m.
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?
--
-- Howard Chu
CTO, Symas Corp. http://www.symas.com
Director, Highland Sun http://highlandsun.com/hyc/
Chief Architect, OpenLDAP http://www.openldap.org/project/
6:26 a.m.
Hi Howard,
This is for slapd to speak to?
What's the higher level arch/issue?
Thanks.
8:50 a.m.
--On Friday, March 6, 2020 2:26 PM +0000 Gavin Henry <ghenry(a)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>
7:24 a.m.
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.
--
Ondřej Kuzník
Senior Software Engineer
Symas Corporation http://www.symas.com
Packaged, certified, and supported LDAP solutions powered by OpenLDAP
2:51 p.m.
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.
--
-- Howard Chu
CTO, Symas Corp. http://www.symas.com
Director, Highland Sun http://highlandsun.com/hyc/
Chief Architect, OpenLDAP http://www.openldap.org/project/
9:02 a.m.
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.
--
-- Howard Chu
CTO, Symas Corp. http://www.symas.com
Director, Highland Sun http://highlandsun.com/hyc/
Chief Architect, OpenLDAP http://www.openldap.org/project/
2:38 p.m.
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&basicSearchTe...
Gavin.
7:39 a.m.
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
9:19 a.m.
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
4:35 p.m.
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.
--
-- Howard Chu
CTO, Symas Corp. http://www.symas.com
Director, Highland Sun http://highlandsun.com/hyc/
Chief Architect, OpenLDAP http://www.openldap.org/project/
4:41 p.m.
--On Thursday, March 12, 2020 12:35 AM +0000 Howard Chu <hyc(a)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>
7:40 a.m.
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?
--
-- Howard Chu
CTO, Symas Corp. http://www.symas.com
Director, Highland Sun http://highlandsun.com/hyc/
Chief Architect, OpenLDAP http://www.openldap.org/project/
5:19 a.m.
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?
616
days inactive
1116
days old
12 comments
5 participants
participants (5)
-
Gavin Henry -
Howard Chu -
Ondřej Kuzník -
Pallissard, Matthew -
Quanah Gibson-Mount