Rails 3.2 feature: unreadable production logs

https://github.com/rails/rails/commit/04ef93dae6d9cec616973c1110a33894ad4ba6ed

by skrger • 14 years ago

54 34 14 years ago

ibotty2• 14 years ago

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.

thomseddon• 14 years ago

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

monsterix• 14 years ago

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

bittersweet• 14 years ago

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

vidarh• 14 years ago

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.

nirvdrum3• 14 years ago

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.

calinet62• 14 years ago

> 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.

davidw2• 14 years ago

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

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

pimeys• 14 years ago

Maybe a pull request reverting that commit would work?

xentronium4• 14 years ago

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)

jcitme• 14 years ago

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

xentronium4• 14 years ago

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

xentronium4• 14 years ago

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.

skrger2• 14 years ago

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.

xentronium4• 14 years ago

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.

mmahemoff• 14 years ago

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.

CGamesPlay• 14 years ago

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?

skrger2• 14 years ago

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.

jeltz2• 14 years ago

  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.

calinet62• 14 years ago

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.

jeltz2• 14 years ago

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.

cygwin98• 14 years ago

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

dhh• 14 years ago

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.

davidw2• 14 years ago

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?

justinjlynn• 14 years ago

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.

davidroetzel• 14 years ago

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.

richardkmichael• 14 years ago

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

moe• 14 years ago

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

Rails 3.2 feature: unreadable production logs

Related Stories