scripts: update log format#4035
Conversation
OLD: [ WARN ] <MESSAGE> NEW: <ISO 8601 TIMESTAMP> <LOG LEVEL> <WHO LOGGED>: <MESSAGE>
Because we log with timestamps now by default, we do not need the extra logging functionality anymore.
Theis information should be available with syslog IIRC, I forget the CLI command, but it's possible to call that to log a message that Likewise, for stdout, Docker (and I assume k8s) should have their own logging drivers at least for timestamp tracking. Perhaps next month I'll finally get back to the Vector PR work upstream which will make the process a bit nicer for us 😅 |
polarathene
left a comment
There was a problem hiding this comment.
logger is the command, here is a nice overview (with CLI options shown at the bottom).
Syslog has two widespread formats, RFC 3164 (DMS prior to v14), and RFC 5424 (DMS v14 onwards default), where most should be using the proper standard RFC 5424. The priority value represents the combined facility (most services in DMS should be using mail IIRC) and the severity (your log levels).
Here is some stripped down reference from my Vector PR:
Snippets (click to expand)
enum Severity {
Emergency = 0,
Alert = 1,
Critical = 2,
Error = 3,
Warning = 4,
Notice = 5,
#[default]
Informational = 6,
Debug = 7,
}enum Facility {
Kern = 0,
#[default]
User = 1,
Mail = 2,
Daemon = 3,
Auth = 4,
Syslog = 5,
LPR = 6,
News = 7,
UUCP = 8,
Cron = 9,
AuthPriv = 10,
FTP = 11,
NTP = 12,
Security = 13,
Console = 14,
SolarisCron = 15,
Local0 = 16,
Local1 = 17,
Local2 = 18,
Local3 = 19,
Local4 = 20,
Local5 = 21,
Local6 = 22,
Local7 = 23,
}The Local* facilities are for custom/local usage if desired. The syslog service (rsyslog for us presently) can parse that to handle differently like it does for filtering mail logs to files, or forwarding to another log service if configured to do so.
Calculating the priority value looks like this:
// Example (Priority value for `Facility::Mail` + `Severity::Error` is `19`):
// `(2 * 8) + 3` or `(2 << 3) + 3` (bitwise shift instead of multiplication)
let priority = (self.facility as u8 * 8) + self.severity as u8;Nevermind that, logger --priority mail.error is supported as a more friendly way for you to use, no math needed 😅 (use the relevant supported log levels from the collapsed snippet though)
Examples:
# RFC 5424 format (notq omits the structured data regarding time, msgid is rfc5424 only):
logger --rfc5424=notq --priority mail.error --id=1337 --msgid=hello --tag dms-changedetector "This is an example error message!"
<19>1 2024-05-26T11:45:28.305480+00:00 mail.example.test dms-changedetector 1337 hello - This is an example error message!
# Old RFC 3164 format (lacks a year, assumes present year):
logger --rfc3164 --priority mail.error --id=1337 --tag dms-changedetector "This is an example error message!"
<19>May 26 11:45:27 mail dms-changedetector[1337]: This is an example error message!- Use
--stderrwith the aboveloggercommand examples to get the output to stderr. - If you don't use
notq, you'll get some metadata for a log ingester to have about quality of the timestamps ([timeQuality tzKnown="1" isSynced="1" syncAccuracy="157"]), this is Structured Data from RFC5424, doesn't really exist for prior RFC 3164. --tagis the service name likeamavisorpostfix. Despite the linked resource examples, do not use spaces, that makes the log ambiguous to parse. The RFC document has a breakdown for supported tokens and expected sequence format.--idisn't really needed,it's the PID by defaultloggeromits it, PID of theloggercommand as default requires--id. Note that--id 42is not valid, that's--idthen42as part of the message rather than as part of--id, make sure assignments for the option have=😑 (-iseems to be equivalent to--idtoo?)--rfc5424is not being parsed properly byrsyslogin:edge, stick to--rfc3164
UPDATE: Nevermind. I thought logger would be appropriate, but regardless of syslog format used, rsyslog is not stripping away some of the data like expected:
# RFC 3164 followed by RFC 5424
# v13.3:
May 26 11:51:14 mail mail dms-changedetector[1337]: This is an example error message!
May 26 11:55:07 mail 1 2024-05-26T11:55:07.509942+00:00 mail.example.test dms-changedetector 1337 - - This is an example error message!
# v14
2024-05-26T12:05:58.700336+00:00 mail mail dms-changedetector[1337]: This is an example error message!
2024-05-26T12:17:07.824094+00:00 mail 1 2024-05-26T12:17:07.824035+00:00 mail.example.test dms-changedetector 1337 hello - This is an example error message!
Pretty sure on a related PR I discussed this and documented the rsyslog config. Perhaps we should address that before pushing out v14 to use the syslog format? (I was under the impression it was effectively the same as the two but omitted the priority value, and for RFC 5424 the syslog version, eg <19>1)
Seems like I made a note of this on the rsyslog changelog entry actually 🤔
So just to clarify, your change here won't exactly line up to rsyslog format
- You are using a two space delimiter.
- You skip the host.
- Your timestamp won't match.
- You add your own log level (but so do other services with their message, so.._ 🤷♂️ )
Personally I prefer the current DMS log output which is more easier to distinguish if it's not going to align with rsyslog for log parsing (_at least with the current log output, you know that if the line starts with [ it's probably emitted by DMS, otherwise if a valid timestamp is the starting portion it's more than likely from rsyslog from one of the services we run. Anything else is usually stderr or similar and could be filtered separately.
Approving this change if you still feel you want to go through with it as-is, but you should wait for @casperklein to provide input too.
| MESSAGE="$(date --iso-8601='seconds') ${!LOG_COLOR}${LOG_LEVEL_NAME}${RESET} " | ||
| MESSAGE+="$(basename "${0}" || echo 'unknown'): ${2}" |
There was a problem hiding this comment.
Do you have an example of what this looks like? (yes I'm that lazy 😄 )
I'm not sure how useful it is to log a timestamp (and I assume the basename is script file?) to the TTY / stdout, it's often noise vs proper log management.
Since v14 will break expectations of logging elsewhere, I'm not going to bikeshed this, anything you're comfortable with is fine by me if no one else raises any objections.
There was a problem hiding this comment.
Technically the date should be date --rfc-3339='seconds' (ns would be more correct, but I'm not sure how you restrict the precision to 6 digits which is expected, ns precision is optional though)
There was a problem hiding this comment.
Do you have an example of what this looks like? (yes I'm that lazy 😄 )
Not so bad, if someone was trying to parse these logs and separate them, they'll need to go based on two columns to match as DMS logs now.
Still the added verbosity of the timestamp (and a bit to the script name, but that's a little helpful), I'm not sure about. Adjusting the rsyslog config won't adjust the timestamp format here since this isn't being managed via rsyslog. If we had some consistency one could better parse the logs and filter/format them as they see fit.
|
@polarathene I adjusted the format to now look like this: I would still like to go through with this, but I will wait for @casperklein's input on this as well, just as you requested 👍🏼 |
polarathene
left a comment
There was a problem hiding this comment.
I actually never tried to be rsyslog-compatible, but if you and @casperklein think it'd be a good idea, I can make that happen.
I think it could be nice, but proper approach is to use logger as described above, which will require messing with rsyslog config to properly ingest.
As I want to replace rsyslog with Vector in future I don't know if it's worth your time to integrate with rsyslog, but if you can make it work that'd be cool 👍
|
After @polarathene suggestions are applied, LGTM 👍 |
Co-authored-by: Brennan Kinney <[email protected]>
I applied two of the 4; the ones I did not apply are related to the space; I want the space there to have the log level always aligned to five characters. |
|
@polarathene when we transition to Vector, all efforts of integrating our logs into Rsyslog would be wasted, hence I'd like to stick to what's currently on the branch and then convert to Vector once we're ready. |
Maybe add a comment so others know that context? My first thought was there was trailing white-space, especially for diff in a review that didn't occur to me 😓 |

Description
Over time, I really came to despise the log format I implemented. I recently updated the log for another project of mine, and really wanted to get this into v14.0.0 (as potentially breaking).
The new format is more akin to Postfix's current format:
<ISO 8601 TIMESTAMP> <LOG LEVEL> <WHO LOGGED>: <MESSAGE>. Having a timestamp and information about who actually logged is important; hence I included it.Type of change
Checklist
docs/)CHANGELOG.md