Ruby has Logger. It is good, but strings suck. In a world where more and more people are using log data for inputs and analysis, structured data is good. I want to log structured data.

This lead to me subclassing Logger and additionally providing my own logger format class. The code for this is in logstash, logging.rb.

What did I add? Two main goals: First, improve context. Second, log structured data (objects). This is achieved by style changes (log objects, not strings), adding awesome_print support, adding code context to each log (line/file/method), etc.

To support the first goal (context), if the loglevel is 'debug' I will inspect the call stack and include the file and line of code that is logging. I also set the 'progname' to the name of the program by default. To support the second goal, log objects and improve how objects are formatted into strings with Object#inspect (or awesome_inspect, if available).

Some examples:

>> logger = LogStash::Logger.new(STDOUT)
I, [2010-11-12T15:19:48.388469 #18782]  INFO -- : ["Failed: require 'ap' (aka awesome_print); some logging features may be disabled", #<LoadError: no such file to load -- ap>]
# This is an example of what javascript folks call 'progressive enhancement'
# - we still function if awesome_print is not available.

>> logger.level = Logger::WARN
>> logger.warn("Hello")
W, [2010-11-12T15:20:05.465705 #18782]  WARN -- irb: Hello

>> logger.warn(["rejecting bad client", { :client => "1.2.3.4" }])
W, [2010-11-12T15:21:04.639404 #18782]  WARN -- irb: ["rejecting bad client", {:client=>"1.2.3.4"}]

>> logger.level = Logger::DEBUG
>> logger.warn("Hello")
W, [2010-11-12T15:21:57.754874 #18782]  WARN -- (irb):12#irb_binding: Hello
# Notice the context (file, line, method)       ^^^^^^^^^^^^^^^^^^^^
# When DEBUG level is set only due to performance and verbosity concerns.

The main benefit personally is logging objects instead of strings, which you can do, today, with the standard Logger. However, standard logger doesn't make nice with awesome_print or add file/line/method context. Anyway, logging objects lets you later hook a smarter error handling tool up to your logging that can inspect the structured data rather than having to regex your way through a single string.

If you have awesome_print available, the object output by my formatter gets even more useful for human viewing:

Why log structured? Easier to parse and query later, like in a logstash query.

I see this in my server logs quiet often:

Oct 23 05:37:48 pww-5 snmpd[23946]: Connection from UDP: [XX.XX.XX.XX]:34650 
Oct 23 05:37:48 pww-5 last message repeated 16 times
Oct 23 05:37:48 pww-5 snmpd[23946]: Connection from UDP: [XX.XX.XX.XX]:34652 
Oct 23 05:37:48 pww-5 last message repeated 24 times

Googling points out that in snmpd.conf we should use "dontLogTCPWrappersConnects" - but thet top search results claim that it doesn't work (syntax errors, etc). I tried this:

dontLogTCPWrappersConnects

This makes an error of:

/etc/snmp/snmpd.conf: line 29: Error: Blank line following dontLogTCPWrappersConnects token.

So I took a guess and changed it to:

dontLogTCPWrappersConnects 1

This works to quiet the 'Connection from UDP: ...' messages. However, it still logs things like:

Oct 22 23:17:35 pww-4 snmpd[29383]: Received SNMP packet(s) from UDP: [XX.XX.XX.XX]:42926

Fixing this requires telling snmpd to log less stuff to syslog. The '-L' logging options support upper-case versions which set the level at which it will log. Fixing syslog to not log the snmp packet info means setting this flag "-LSnd". This means we'll log at 'notice' levels and above to syslog with the daemon facility. Setting this flag seems to make snmpd less chatty in logs about packets it gets. Setting the log level to '-LSid' (info level) will make it once again log the packet receipts.

In CentOS (and other redhat variants) you'll edit this file to make this change permanent: /etc/sysconfig/snmpd.options - just change "-Lsd" (default in my version of net-snmp) to "-LSnd" and make sure the OPTIONS line is uncommented.