7 ms·
Rails 3.2 feature: unreadable production logs
- ibotty 14y agoi 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 14y agoLinus Torvalds himself is an advocate of very descriptive commit messages: https://github.com/torvalds/subsurface/blob/master/README#L161 https://github.com/torvalds/subsurface/blob/master/README#L1... And more explicitly: https://github.com/torvalds/linux/pull/17#issuecomment-5659933 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 14y agoYes, both from search index-ability and training point of view.
- bittersweet 14y agoTim 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-messages.html http://tbaggery.com/2008/04/19/a-note-about-git-commit-messa... [2] https://github.com/blog/926-shiny-new-commit-styles https://github.com/blog/926-shiny-new-commit-styles
- nirvdrum 14y agoKeep 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.
- dasil003 14y agoHowever 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.
- nirvdrum 14y agoI 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.
- dasil003 14y agoSorry, 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.
- vidarh 14y agoI 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.
- ibotty 14y agowhen 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).
- nirvdrum 14y agoOn 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.
- calinet6 14y 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.
- davidw 14y agoAha... I had been wondering about that. What a mess our logs have become! http://stackoverflow.com/questions/11561846/rails-3-2-2-log-files-unordered http://stackoverflow.com/questions/11561846/rails-3-2-2-log-...
- pimeys 14y agoMaybe a pull request reverting that commit would work?
- xentronium 14y agoBasically, 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 14y agoDoes this work? There's a lot of removed code in that commit, does this replicate the old behavior?
- xentronium 14y agoMost of the code deleted was related to locking around writes and flushing the buffer. Also, lots of specs testing the said behavior.
- xentronium 14y agoI 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.
- skrger 14y agoI 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.
- mmahemoff 14y agoOTOH 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 14y agoPlease 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?
- skrger 14y agoWell 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.
- jeltz 14y agoActiveSupport::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.
- calinet6 14y agoInteresting. 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.
- jeltz 14y agoThe 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 14y agoHere 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 14y agoIf 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.
- davidw 14y agoPerhaps 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 14y agoYou 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.
- IsTom 14y agoDepending 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.
- davidroetzel 14y agoThere 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 14y agoRequest-log-analyzer? https://github.com/wvanbergen/request-log-analyzer https://github.com/wvanbergen/request-log-analyzer
- moe 14y agoRails 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 https://github.com/roidrage/lograge