Do You Know Where Your Logs Are?
Often times, when debugging applications, a number of problems show up simultaneously. Determining the order to attack each problem can be difficult to do. Despite the challenge, it is worth giving it some good thought. It could save hours of your valuable time. Here is a situation where I got it wrong.
We use Supervisord to manage our processes. Our main reason for using this tool is that it runs in user space (no root access needed). This is great when we have to manage our microservices on servers that we don’t have sudo privileges on.
Another benefit of Supervisord is that it gives easy control over logs and
their rotation. The only caveat to our process is that we need to ensure that
the logs of our various services are written to
While deploying and testing several new microservices to our staging environment, I ran into a set of small problems. These problems took far more time to debug than they should have due to misunderstandings about what the logs were showing me, and an incomplete picture of what was going on.
I got each of our services deployed, configured, and running on our staging
servers. With an expectation that everything might not run perfectly right out
of the gate, I started up each service and began tailing their respective logs:
tail -f logs/*.log. When I ran my test, I noticed there were no queries
making it to the receiving service (as evident by the log).
=> Booting Puma => Rails 5.1.1 application starting in development on http://0.0.0.0:3000 => Run `rails server -h` for more startup options Puma starting in single mode... * Version 3.9.1 (ruby 2.4.0-p0), codename: Private Caller * Min threads: 5, max threads: 5 * Environment: development * Listening on tcp://0.0.0.0:3000 Use Ctrl-C to stop
I began debugging the code of the first service in the chain. The settings appeared to be correct. The code was executing without exception. And the network calls were being made with the right data. All signs showed that the calling service was, in fact, working correctly. Time to look into the second service.
In the receiving service, the log showed the server startup and the debug print statements I littered throughout the code. I did not, however, see any requests being logged. Strange. I had already determined that the requests were making it here so, what gives? I was relatively confident that all requests were logged in our older Rails 4 applications (including hitting non-existent endpoints). But I wasn’t certain about these new Rails 5 API applications. I assumed that hadn’t changed, but I wasn’t sure. Oh well, I thought, I’ll tackle this problem once I get the services working.
We use Nix to manage and deploy our packaged services. Because the Nix store is read only, we had to jump through a few hoops to get our Rails API services to run. Some files had to be copied to a location that could be written to, the rest could be linked back to the Nix store. I began to suspect these linked files were causing me grief.
After spending some time experimenting, I learned that my suspicions were wrong. I also made some mistakes during the exploration that led me down fruitless paths (eg. querying wrong routes). Eventually, it became clear that I really needed to find the missing query logs to move forward.
The Eureka Moment
It finally occurred to me to look for another log that might not be getting
captured by Supervisord. I found it quickly in the Rails project folder. Within
it, lay all of the priceless information I needed to solve the world’s
problems. Well, at least my current tiny world of deploying these services. The
Puma server was logging to standard out and my
puts statements were making it
to standard out. But the Rails logs were being written to a file.
Armed with better knowledge, a quick search revealed the solution. Rails 5
needs to be configured to log to standard out in production. Within
config/environments/production.yml there is a block of code that looks like
if ENV["RAILS_LOG_TO_STDOUT"].present? logger = ActiveSupport::Logger.new(STDOUT) logger.formatter = config.log_formatter config.logger = ActiveSupport::TaggedLogging.new(logger) end
In our case, we didn’t want to use the environment variable, so we removed the
if statement. All of those glorious logs were now where we needed them to be
and the problem with the service communication was quickly resolved.
I spent a lot of time debugging problems that could have been quick and easy. Without those missing logs, I followed time consuming paths of debugging. Ultimately, I focused on the wrong problems first. It is important to know where all logs are being written. If I had put that at the top of the debugging priority list, I would have finished the deployment to staging in half the time it ended up taking. Learn from my mistake, know where your logs are.