Introduction
In this multi-part series, we are going to explore log formats and protocols for sending them: two of the most fundamental pieces of any logging system. In Part 1, we will go over log formats and how metadata is encoded. Very little has changed as far as these core fundamental pieces are concerned, even as technology and computing has evolved.
We will start the journey with an application. This could be from the system, written by a user, etc. Applications write out human-readable messages to convey information. These messages help, both the user and developer understand indirectly, the state of the application. Two additional critical pieces of information are needed – the when and the how good or bad the information is for a reader who is looking at it. In essence, we have uncovered 3 mandatory parts of any log message for any logging system: the information, the when and the how good/bad it is. These are typically referred to as the message, the timestamp, and the severity.
Applications run within an operating system or nowadays what we call the cloud operating system. For an operating system dealing with many applications, it is natural to separate log messages from different applications and group them together. So here we see the fourth mandatory piece of any logging system – the application name itself, typically referred to as the application name.
As is universally known, applications are written by humans and humans have a tendency to make mistakes and like it or not we see applications, for no real fault of their own, sometimes, die horrible deaths, sometimes are forced to restart, etc.. Due to this, the operating system now has to deal with multiple incarnations of an application and in order for the intended reader of the log message to understand this discontinuity, it is critical to include the 5th vital piece of any logging system, the process identifier or the incarnation identifier or the instance identifier. This is typically referred to as the process Id or the Instance Id.
So far we have a good set of mandatory fields that are essential for an operating system to organize the logs created by an application so a human reading it can make sense of it.multi
- Message
- Timestamp
- Severity
- Application Name
- Process Identifier / Instance Identifier
RFC3164 – BSD Syslog protocol
Armed with this information, I think we are ready to segway into the first real standardized log format that came from the BSD folks – RFC 3164 – The BSD Syslog protocol. Let us look at a raw RFC3164 message
<14>Mar 29 06:15:28 customer-tooling postfix/anvil[17483]: statistics: max cache size 1 at Mar 29 06:12:05
Looking at the fields, it’s a quick guess about the mandatory fields we just talked about. Let’s see if you spotted the same as well
- Message – “statistics: max cache size 1 at Mar 29 06:12:05”
- Timestamp – “Mar 29 06:15:28”
- Severity – ???
- Application Name – “postfix/anvil”
- Process Identifier/ Instance Identifier – “17483”
It’s not quite obvious what the severity is. So, let us look at that. RFC3164 encodes the severity in the beginning up to the first 5 characters of the message. Ref: https://tools.ietf.org/html/rfc3164#section-4.1.1
So let us decode what “<14>” means and what the severity of the message is. The BSD Syslog protocol calls this field the priority field. The priority field encodes two pieces of information – the facility and the severity. So we have now encountered a new log message construct – the facility.
As you recall, we discussed the application name in the message. Operating systems group application processes into subsystems also referred to as the facility For e.g. all kernel messages/processes get assigned the kernel facility. Messages coming from the mail subsystem get grouped under a separate facility: mail system.
Facility and Severity are represented by integer codes in the BSD Syslog specification. Ref: https://tools.ietf.org/html/rfc3164#section-4.1.1
Getting back to how to decode the severity of the message, the way the priority field is calculated is to take the facility integer value, multiply it by 8 and add the severity integer value. So
Priority_Code = Facility_Code * 8 + Severity_Code
So, to find the severity, we just divide the Priority_Code by 8 and use the remainder e.g. with a priority value above 14, the Facility is the quotient – 14/8. = 1 and severity code is the remainder 14-8*1 = 6
Now let’s decode what these two numbers mean. Let us look at the BSD protocol encodings for Severity and Facility below. The two tables below are reproduced from the section 4.1.1 referenced above in the BSD Syslog protocol document.
Looking at the two tables we can now conclude that the message was sent with the severity of Informational messages so nothing serious to report! The facility was user-level messages.
Numerical Code Severity
0 Emergency: system is unusable
1 Alert: action must be taken immediately
2 Critical: critical conditions
3 Error: error conditions
4 Warning: warning conditions
5 Notice: normal but significant condition
6 Informational: informational messages
7 Debug: debug-level messages
Numerical Code Facility
0 kernel messages
1 user-level messages
2 mail system
3 system daemons
4 security/authorization messages (note 1)
5 messages generated internally by syslogd
6 line printer subsystem
7 network news subsystem
8 UUCP subsystem
9 clock daemon (note 2)
10 security/authorization messages (note 1)
11 FTP daemon
12 NTP subsystem
13 log audit (note 1)
14 log alert (note 1)
15 clock daemon (note 2)
16 local use 0 (local0)
17 local use 1 (local1)
18 local use 2 (local2)
19 local use 3 (local3)
20 local use 4 (local4)
21 local use 5 (local5)
22 local use 6 (local6)
23 local use 7 (local7)
Summary
In summary, as we conclude part 1 of the “Understanding log formats and protocols” series, we have seen what the mandatory fields of a log message are and also looked at the BSD Syslog protocol encoding for a log message, also commonly referred to as an RFC3164 log message.
