Rails 3.2 feature: unreadable production logs | Hacker News Reader

Rails 3.2 feature: unreadable production logs

github.com

54 pointsskrger34 comments

If you don't flush every line, you'll lose lines in a crash. You often need those lines when trying to debug such a problem, so that's the worst possible time to lose said lines.

We added tagged logging to deal with the "not in order" problem. Find the process id of the request you're trying to follow, grep for that.

Both problems solved.

Perhaps it's a stupid question, but... if something's catching a crash and logging it, can't the same something ensure that everything is written to disk?

You can't catch every crash every time. Add to that the fact that the crashes from which you can't recover are the ones you most want to catch the fact that you really do need to just get those logs persisted as soon as you receive them becomes rather apparent.

Depending on your stack and your needs this might be true, but my experience is that if you're not segfaulting it's not much of a problem. Also systems can be tuned so that flush happens when process dies.

OTOH Rails 3.2 does have a major logging improvement, tagged logging, which by default shows process IDs. It would be useful to have a filter script that runs through the log and detangles requests based on process IDs.

I have the same issue with daemons, even prior to 3.2. Tagged logging helps to solve the problem for those too, as it's easy to output an environment variable that's set by the starting script.

Aha... I had been wondering about that. What a mess our logs have become!

http://stackoverflow.com/questions/11561846/rails-3-2-2-log-...

Basically, they rely on file system to flush logs. If you want to restore old behavior, it's restored fairly simply along the lines of:

    file = File.open("log/production.log", "w")
    file.sync = true
    Rails.logger = ActiveSupport::BufferedLogger.new(file)

Does this work? There's a lot of removed code in that commit, does this replicate the old behavior?

Most of the code deleted was related to locking around writes and flushing the buffer. Also, lots of specs testing the said behavior.

I have reread the comments, rechecked the current state of ruby code, and have an impression that might answer came off as ambiguous.

1. This commit changed two things: default file mode of open logs is no more sync in production (i.e. it is not automatically flushed by ruby write routines) AND it doesn't buffer log entries anymore (which is actually funny, since, you know, it is called ActiveSupport::BufferedLogger) 2. When IO#sync is false, which was the case, ruby didn't flush upon every write. That manifested itself in logfile entries not appearing immediately after write. 2.1. In some 3.2 release they've reversed that, so sync = true is by default in all latest versions of rails. 3. Since logger doesn't buffer requests anymore, the problem of interleaving messages should still be there, sorry for confusion. 3.1. To solve this, you can either use tag features of recent rails or port older buffered logger itself.

I think you have to add some code flushing the BufferedLogger after each request to really get the old behavior.

But this is not my point, for me rails has been about sane defaults - this is what makes it fun to start and easy to work with. I just don't see why we fix something that is not broken at all.

No. Flushing in buffered logger is a number of no-ops. Check the commit itself.

They decided to get rid of supposedly unneeded cruft that was hard to maintain and delegate file handling functions to OS.

There is so much valuable information in those log files that I often wonder why there is no tool to analyze them.

With a nice UI this would not only solve this problem here but it could potentially offer a lot more insight than just looking at isolated entries in text form.

Request-log-analyzer? https://github.com/wvanbergen/request-log-analyzer

Here is the solution I use in our production Rails apps (3.2.6). Add the following code snippet into your config/application.rb.

    config.after_initialize do
      # Reverse the deprecation of flush in BufferedLogger
      module ActiveSupport
        class BufferedLogger
          def flush
            @log_dest.flush
          end
          def respond_to?(method, include_private = false)
            super
          end
        end
     end
     # Let the OS buffer the log
       Rails.logger.instance_variable_get(:@logger).instance_variable_get(:@log_dest).sync = false
    end

Please avoid sensationalist headlines. I don't know why this is being described as a "feature" here, but not on GitHub, nor why it causes "unreadable" logs, nor why it's only in production. Context?

Well it is a deliberate choice, calling it a feature may still be a stretch. The log becomes unreadable because if you have many Rails instances (Like 25 unicorn workers in my case) writing unbuffered in one log file it becomes a holy mess. This is happening only in production because you usually don't have multiple workers in development and you also don't have hundreds of requests per second.

Rails logging has been a trainwreck from the start but this is not even scratching the surface (in deployments where logging matters it normally goes to syslog anyways).

The bigger issue is the complete absence structure.

We shouldn't have to resort to addons like lograge[1] to turn that stream of poo into something human- and machine-readable.

[1] https://github.com/roidrage/lograge

  ActiveSupport::BufferedLogger#auto_flushing is deprecated.  Either set the
  sync level on the underlying file handle like this:

        f = File.open('foo.log', 'w')
        f.sync = true
        ActiveSupport::BufferedLogger.new f

  Or tune your filesystem.  The FS cache is now what controls flushing.

The above from the commit message is incorrect. IO#sync in ruby has nothing to with the filesystem cache, and only controls Ruby's own internal buffers. And as far as I can tell the logger in rails has sync = true by default anyway.

And disabling your filesystem cache at the OS level sounds like a terrible idea.

The commit message only makes sense if he actual talks about IO#fdatasync or he means that "f.sync = false" disables the new behavior.

Interesting.

So does anyone know the rationale behind this change? I'm guessing there's actually a good reason and it's just eluding us because our logs are now messy and that appears to be bad.

The change that should be there is that if you run multiple rails instances against the same log file you should for concurrent requests get interleaved lines since it is written line by line immediately to the file (though not necessarily flushed to the HDD).

If you get scrambled lines (ie the contents of two lines can mix up) then I personally would see that as a bug.

No change to IO#sync, IO#fdatasync or the filesystem settings should make it revert to the old behavior. If you set IO#sync to false it might seem like you get something like the old behviour back, but I think you risk scrambled lines since it will the flush when Ruby's buffer is full.

Maybe a pull request reverting that commit would work?

i don't get why so many people cannot write good commit messages. 72 chars is a very useful limit. if you cannot describe it in 72 chars, you should commit more often.

and the useful info that comes after it can of course be included in the commit. but starting at line 3!

well, well.

Linus Torvalds himself is an advocate of very descriptive commit messages: https://github.com/torvalds/subsurface/blob/master/README#L1...

And more explicitly: https://github.com/torvalds/linux/pull/17#issuecomment-56599...

We have been moving towards commit messages similar to those used in the kernel development (i.e. longer, descriptive) and it has proven very useful indeed

Yes, both from search index-ability and training point of view.

Tim Pope has written about the model commit message [1] and why you should use a short first line, I'm a big believer in this setup and it's done wonders for the readability of my commit messages.

Github itself even uses these rules [2] so I think it's slightly annoying people don't follow them as it looks worse if you use long first lines on the website.

[1] http://tbaggery.com/2008/04/19/a-note-about-git-commit-messa... [2] https://github.com/blog/926-shiny-new-commit-styles

Keep in mind "it looks worse if you use long first lines on the website" is a completely arbitrarily imposed issue from GitHub. A while back they just wrapped the text and all was right in the world. Now they truncate the message and it looks like garbage.

However in this case "the website" is just one of dozens of tools out in the world. 50-character summary messages are incredibly awesome across the board, and everyone should learn to write them.

I cannot disagree any more. I haven't used a terminal that can't wrap in probably 15 years. The point of a commit message is to convey information. If you could point me to a study or something showing people retain info or learn better with a 50 char limit, awesome. But until then, I stand by it being a completely arbitrary restriction.

Sorry, but your opinion is wrong and harmful. The point of the summary line is a succinct and scannable summary of the commit.

Open up any git GUI; gitk or SourceTree are my two favorite. If you keep your summary lines under 50 characters you can quickly scan a maximal number of commits. Detailed descriptions are great and should be included as well for any substantial commits, but that is not what you want in the summary. That should be added in separate paragraphs after the summary line.

This is not arbitrary, and it has nothing to do with the ability to line wrap, it's about efficient communication faced with a history of tens or hundreds of thousands of commits over time.

I don't see Linus suggestion as disagreeing with ibotty. Linus uses a short "headline" followed by additional useful information starting from line 3, and insists on a line length of no more than 74 characters, and he wants the header to be "really meaningful [...] and should summarize the change in one readable line of text"

Long commit messages are good. But a good first line is essential, since, as Linus points out, that is what gets shown by default by a lot of tools.

when writing this i forgot that the first line should be not longer than 50 chars or so. that might have been his point.

vim's syntax highlighting will warn you when you write too much, so i usually do not really notice the length (afair emacs does as well).

On the other hand, I'm tired of short commit messages that are almost completely devoid of anything useful because the author wanted to adhere to an arbitrary restriction. It feels like the mentality that all comments are evil and can be fixed by better method names.

The short message first, longer message after is a pretty good middle ground. But if that first sentence is useless, I'd rather just have a single commit message that accurately describes the commit.

> and the useful info that comes after it can of course be included in the commit. but starting at line 3!

I think this is the part people don't understand. The first line should be < 72 chars. After that (and a blank line), write as much as you want.

Reply on news.ycombinator.com