Ruby Syslog considered harmful (or at least undocumented) 0

Posted by dan
on Wednesday, August 20

There are 3 ways to do syslog logging from Ruby/Rails. First, there’s the the Syslog extension that comes with Ruby:

1
2
3
4
5
6
require 'syslog'
Syslog.open('my_script', Syslog::LOG_PID | Syslog::LOG_NDELAY, Syslog::LOG_LOCAL0)
# Optional: Set a minimum logging level
Syslog.mask = Syslog::LOG_UPTO(Syslog::LOG_INFO)
Syslog.info "All systems green"
Syslog.close

Next, there’s the SyslogLogger Gem:

1
2
3
4
5
# in config/environment/production.rb
require 'syslog_logger'
RAILS_DEFAULT_LOGGER = SyslogLogger.new('rails_app')
# See http://rubyforge.org/tracker/index.php?func=detail&aid=18635&group_id=1513&atid=5923 if you want to set a facility
# Also, the gem will ignore the Rails minimum log level and log everything. You have to manually set a mask using the same code as above.
Finally, you could go old-school and use the ‘logger’ command (assuming a UNIX-like OS):
1
`logger -i -t myprog -p local0.info "hey"`

In theory, Ruby is well covered on the syslog front. But the truth is more complicated (and badly documented) in practice:

  • The Ruby Syslog class is just a thin wrapper on the syslog(3) function call, which interprets % as a printf-style substitution. That means Syslog.info(my_var) could generate an exception at run-time depending on the value of my_var. Oops.
  • Newlines in messages can cause subtle problems. Most of the time, it appears to work, but we found problems with long messages where syslog-ng would start parsing our message in the middle. This caused dropped messages, incorrect dates, and wrong facility/priority codes (especially when logging to a central server).
  • Nulls always signal the end of the string for C calls, and syslog is no exception. That means your log could be truncated if you pass binary data (or even user-supplied data where the user might supply a null).
  • Syslog has a maximum message size. If you exceed that, bad things happen. Most of the time, syslog silently recovers (with truncation), but if you have angle brackets in your message (especially with newlines), you will get “unparseable log message” errors that have incorrect facility/priority codes and sometimes incorrect dates. This means logging XML is especially dangerous: everything seems to work until your XML exceeds the syslog message size. (Sometimes as small as 1K, but usually 8K for syslog-ng).
ProblemRubyRailsLogger
\n (newlines)Not escapedNot escapedEscaped as 2-char ”\n”
% (percent character)Expecting printf-style % commandsEscapes % for Ruby syslogCorrectly escapes %
\0 (null characters)Does nothing (message truncated)Does nothing (message truncated)Does nothing (message truncated)
Long messagesDoes nothingDoes nothingAutomatically breaks up messages into 1K chunks

So if you want robust logging, make sure to clean up your messages (in content and size) before sending them to Syslog. Try some torture test messages like these:
1
2
3
4
# Torture test strings
test1 = (0..255).map{|x|"<#{x.chr}>\n" }.join
test2 = (1..3000).map{|x|"<#{(97+(x%26)).chr}>\n" }.join
Syslog.info( test1 + test2 + "is this thing still on?")
Ideally, this would be fixed at the Ruby Syslog level. (C’mon lazyweb, what else do you have to do today?.)

A better alternative to Object#try: Object#nil_or 0

Posted by tom
on Thursday, August 07
Object#try is great for this case:
1
2
3
4
5
person = Person.find(:first)
puts person && person.age
# or: puts person.age if person
# or: puts person.age unless person.nil?
# or whatever you use!

It’s even greater when the variable/method names are long:

1
2
3
contractor_or_employee.attributes &&
  contractor_or_employee.attributes.address &&
  contractor_or_employee.attributes.address.country

becomes:


contractor_or_employee.try(:attributes).try(:address).try(:country)

Basically, it’s helpful any time you want to call a method on an object but aren’t sure if that object is nil or not, and you don’t want it to raise a NoMethodError if the object is nil; instead, you’d like it to return nil.

I have been aware of Object#try for some time now, particularly since this post, and the update (to accept more arguments) here , and then our own version, which accepts both arguments and a block, as follows:

1
2
3
4
5
class Object
  def try(method_name, *args, &block)
    respond_to?(method_name) ? send(method_name, *args, &block) : nil
  end
end

All these are great; however, there is an improvement. We now use nil_or for most of our needs. (Note that this is a different nil_or than is talked about here more on that below.) If your use case is strictly that you don’t know whether an object will be nil or not, the nil_or presented here is better, and here’s why:

Firstly, it doesn’t have the overhead of respond_to?, which isn’t trivial if you use this all over your code. Secondly, try could get you into problems in a few edge cases: for example, say you are trying to see if an object is nil and you use try but accidentally use the wrong method name. try will return nil without alerting you to your mistake, whereas this one will still call the method on the object and raise a NoMethodError.

The principle here is that, with try, there is a disjoint between the need (checking if an object is nil or not) and the behavior (checking respond_to? on an object), which leads to inefficiency as well as unpredictability. nil_or bridges that gap, so here it is:

1
2
3
4
5
class Object
  def nil_or(method_name, *args, &block)
    self.nil? ? nil : send(method_name, *args, &block)
  end
end

Use it just as you would try, so for example:


contractor_or_employee.nil_or(:attributes).nil_or(:address).nil_or(:country)

Yes, I know there is another Object#nil_or out there, here and (amazingly) at its own domain here, and the advantage to that one is that you can easily string along method calls like so:


contractor_or_employee.attributes.address.country

without the hassle of parameters. However, if you take a look at the code you’ll see that it’s pretty inefficient, instantiating a new class each time it hits a nil. We can’t afford that inefficiency, but if you can, it might be a better option for you.

ActiveRecord column transformations slow 2

Posted by stevie
on Wednesday, August 06

After seeing some painfully slow migrations that made simple column modifications (rename_column taking 5 minutes on a table with 2m rows in our master database?!?), I decided to do some research. My naive assumption was that a simple column rename should take the same amount of time on a table with 10 rows as it does for a table with 10m rows. Boy was I wrong. After a bit of searching, I came across this post by Eric Bergen.

I was shocked to discover that MySQL, for almost all ALTER TABLE commands, copies the entire table into a temporary table, then renames the new table and drops the old one. No wonder my column renames took so long! Why, in the name of all that is sacred, would this be necessary? I’m sure there’s good reason at a low-level in the db, but definitely a Good To Know. The only type of ALTER TABLE call that doesn’t copy the entire table is a table rename.

So please, don’t go running column transforms willy-nilly on large tables in your db—know that you will need to throw up your maintenance page and take the site down.

Errno::EMFILE "Too many open files" in Rails

Posted by stevie
on Thursday, May 29

I was spot checking a few videos on our website when I hit a 500. That’s weird, I thought. Probably a fluke. So I just hit refresh 30 times in a row, and discovered that almost 10% of refreshes resulted in a 500. Not good.

So first of all, I check the production logs, and notice errors all over the place. The weird part was that our exception notifier wasn’t emailing us to let us know about the 500s, which means that this could have been happening for a good chunk of time. Argh.

Here’s what the error would look like:

Errno::EMFILE
(Too many open files – /home/rails/web2/releases/20080521184957/vendor/plugins/exception_notification/lib/../views/exception_notifier/exception_notification.rhtml):
/vendor/rails/actionpack/lib/action_view/template.rb:39:in `read’
/vendor/rails/actionpack/lib/action_view/template.rb:39:in `source’
/vendor/rails/actionpack/lib/action_view/template_error.rb:11:in `initialize’
/vendor/rails/actionpack/lib/action_view/template.rb:29:in `new’
/vendor/rails/actionpack/lib/action_view/template.rb:29:in `render_template’
/vendor/rails/actionpack/lib/action_view/base.rb:245:in `render_file’
/vendor/rails/actionpack/lib/action_view/base.rb:269:in `render’
/vendor/rails/actionmailer/lib/action_mailer/base.rb:536:in `render’
/vendor/rails/actionmailer/lib/action_mailer/base.rb:528:in `render_message’
...

So it looks like exception notifier was catching exceptions, but when it tried to read the email template for mailing, it would throw an error because the process had exceeded the number of file handles it was allowed. Time to check out the open number of descriptors for the mongrels.

First, find out how many open file descriptors each mongrel process has:

1
2
3
4
5
6
7
8
9
10
11
pids = Dir["/home/rails/web2/shared/log/*.pid"].map{|f| `cat #{f}`}
=> ["10865", "10869", "10859", "10879", "10876", "10862", "27760", "27763"]
pids.each {|pid| puts `lsof -p #{pid} | wc -l` }
10865:  879
10869:  805
10859:  1075
10879:  904
10876:  790
10862:  550
27760:     1060
27763:  1003
Or, using some CLI magic, here’s Jeff’s version
1
ps aux | grep mongrel_rails | awk '{print $2}' | xargs -n1 -I 'foo' lsof -p 'foo' | sort | awk '{print $2}' | uniq -c
Hmm… those numbers seem really high. Let’s double check how many open descriptors are allowed per process on our systems:
1
2
ulimit -a | grep 'open files' 
=> open files                      (-n) 1024

Yup, the mongrels are exceeding the number of allowed descriptors. After doing an “lsof -p ” on a single mongrel, we quickly discovered that our auto-rotating image science code wasn’t releasing the file descriptor after serving up the rotated images, resulting in a ton of open file descriptors per process.

Ruby quirks, round two

Posted by jeff
on Sunday, May 25

This ruby quirk is more obvious than the previous one, but I have seen it bite many people (including myself).

1
2
3
4
5
6
7
# irb
>> a = nil
=> nil
>> b = a or "default value"
=> "default value"
>> b
=> nil

Huh? I wanted to set b to a, or “default value” if a is nil.

The reason is operator precedence. ’=’ has higher precedence than ‘or.’

A better approach is
1
b = a || "default value"

Ruby quirks, the first installment

Posted by tom
on Thursday, May 22

Over the last two years, I’ve been compiling a short list of some of the weirdest behaviors of Ruby (and sometimes Rails). Naturally, I can’t find my list at the moment—but I did come across one today that was noteworthy. The others will have to wait.

For you Ruby mavens out there, see if you can predict the behavior:

1
2
3
4
5
6
7
8
9
10
# irb

1.to_s  # => "1"
2.to_s  # => "2"

# likewise with the string replacements:
"one: #{1}; two: #{2}"  # => "one: 1; two: 2"

# in this specific instance, I was inserting my brother's zip code into a string:
"my brother's zip code is #{07302}"  # => ?

Now, who thinks it keeps the leading zero? Who thinks it ditches it? Give it a try. I think many of you will be surprised.

Returning 503s with the maintenance page on Apache-based APIs

Posted by stevie
on Sunday, May 18

I spent a good bit of time looking for ways to automatically return a 503 when I ran my capistrano disable_web task, which is a handy way to show your users something intelligible when you have to take your site down for maintenance (and it only works, of course, if you’ve appropriately setup your web config to allow this behaviour). This is fine and great for our animoto.com website, but it doesn’t help our API when it goes down for maintenance.

API consumers care less about a nice looking maintenance page than a correct HTTP return code to let them know that our engine is temporarily down. We told our API clients that we would return an HTTP code of 503 during maintenance periods, but I wasn’t able to find any easy way to have Apache automatically return 503s when the maintenance page was up.

A saw a great EngineYard thread about how automatically return a 503 in the presence of maintenance.html using Nginx, but couldn’t find anything about doing it with Apache. So after doing some hunting around in the Apache docs, I discovered a way to do this without having to use lame techniques that required on-the-fly apache reconfiguring, htaccess tweaking, or a php script.

1
2
3
4
5
6

ErrorDocument 503 /maintenance.html
RewriteCond %{DOCUMENT_ROOT}/maintenance.html -f
RewriteCond %{SCRIPT_FILENAME} !/maintenance.html
RewriteCond %{SCRIPT_FILENAME} !^(.+).(gif|jpg|css|js|swf)$
RewriteRule ^.*$ /maintenance.html [R=503,L]

Rails template caching gotcha

Posted by stevie
on Saturday, May 17

I wanted to update an .erb file on production without doing a full git checkout, and was unpleasantly surprised at what happened.

I was planning on updating the files, taking one of the servers out of rotation, bouncing the mongrels, and then testing that server to make sure things were ok. I first updated all the files on our production servers, and was going to continue with my plan when Pat told me that the songs page on our site was spitting out garbled html that looked like the github login page!

I immediately realized half of the problem, the first being that my wget on the github file had actually redirected to a login page b/c the file wasn’t public (duh!). But I was really surprised that the file was actually getting picked up by the mongrels when I hadn’t restarted anything. After looking at the ActionView page I understood why:

Template caching
By default, Rails will compile each template to a method in order to render it. When you alter a template, Rails will check the file‘s modification time and recompile it.

Wow. So this is definitely a Good To Know. If you update an .erb file, it will automatically get compiled and used the next time it’s requested. So don’t update any template files on production unless you’re absolutely sure they’re golden!

Ruby Weirdness

Posted by stevie
on Friday, April 25

I saw this on another blog, but I just thought I’d repost it since it was pretty interesting.

1
2
3
4
5
6
7

# wtf?
if false
  var = 'should not be executed'
end

puts 'uh oh' if var.nil? # => uh oh

Ruby is weird.