Logging Lessons Learned, and a Challenge for you…

For some Friday fun, I have decided to run a little contest. The first person who responds with the correct answer to the question below wins a $50 Amazon gift card.

How many times have you developed some code and then burned silly amounts of time by overlooking something basic?  See if you can figure out my Doh! moment.  I almost didn’t share this because it’s been many years since I was a real developer and so maybe I no longer know better.  But humility is a virtue…

Here’s the scenario:

A few days ago from my home in the San Francisco Bay Area, I wrote a Python program to perform some analytical functions. My intent is to cron it to run regularly, but for now I’m running it periodically on my laptop. For all my programs, I’ve created a simple common logging function that emits JSON and sends logs to Loggly via HTTP. The logging function sets up my Customer Token and puts in some standard fields like the calling function name as well as some tags that provide the foundation for my Loggly Source Groups.  Recently, I added a bulk-send mode to the logging code that periodically sends a collection of events in one message (saves round-trips on the post).  The bulk-send mode queues events into one large string and periodically flushes the events to Loggly as a single HTTP post. To ensure that each event in the bulk set has its own timestamp, the function adds a “timestamp” key and value to each of the individual events. So far, so good.

I started to test the new program, including logging events in bulk. Here’s what the individual events look like:

{“timestamp”: “2014-03-08T00:12:28.780000”, “event”: “starting lifecycle processor”, “elapsed”: 0.0, “module”: “__main__”, “line”: 38, “level”: “INFO”}

 As a test, I ran the program on my laptop and then went into my Loggly account to examine the logs.  Since I don’t have that much going to my account, I just did a wildcard “*” search on the last 10 minutes to retrieve my latest events.  But strangely, nothing from my program showed up.  I curled a “hello world” event from the command line and it showed up in just a few seconds (Loggly is fast!).  I checked the return code on the bulk event post and sure enough, it was a 200.  I verified that I was using the proper Customer Token and that the tags were all formatted correctly.

What was my mistake?

Email me at charlieo@loggly.com if you have the answer.

The Loggly and SolarWinds trademarks, service marks, and logos are the exclusive property of SolarWinds Worldwide, LLC or its affiliates. All other trademarks are the property of their respective owners.