The app crashes after running for a minute

[toreriklinnerud]

/Users/tel/code/log2viz/app.rb:136:in `[]': invalid number of elements (0 for 1..2)

This is the offending line (app.rb):

data = Hash[ matches[4].split(/\s+/).map{|j| j.split("=", 2)} ]

[dominic]

If possible, can you share a snippet of the log lines that are causing this problem?

[toreriklinnerud]

These all seem problematic

" Schema | Name | Type | Info "

" lib/peanut_forwarder.rb:23:in `call'"

" config/initializers/patches/logger.rb:5:in `call_with_quiet_assets'"

[toreriklinnerud]

(that is the content of matches[4])

[dominic]

Great - thanks! I'll get a patch out this afternoon.

[dominic]

I'm unable to reproduce this issue in testing. I'll add some code to catch exceptions in log parsing, but I can't see why that code would fail on your examples. For instance, parsing " Schema | Name | Type | Info " should return:

{"Schema"=>nil, "|"=>nil, "Name"=>nil, "Type"=>nil, "Info"=>nil}

Which is nonsense, but doesn't crash.

[toreriklinnerud]

If I tweak the rescue to include the line:

rescue Exception => e
  puts "Error caught while parsing logs (#{line}):"
  puts e.inspect
end

I get this:

19:09:24 web.1  | #<ArgumentError: invalid number of elements (0 for 1..2)>
19:09:25 web.1  | Error caught while parsing logs (2013-03-21T19:09:25+00:00 app[web.1]:   config/initializers/patches/logger.rb:5:in `call_with_quiet_assets'
19:09:25 web.1  | ):
19:09:25 web.1  | #<ArgumentError: invalid number of elements (0 for 1..2)>
19:09:25 web.1  | Error caught while parsing logs (2013-03-21T19:09:25+00:00 app[web.1]:   lib/legacy_url.rb:15:in `call'
19:09:25 web.1  | ):
19:09:25 web.1  | #<ArgumentError: invalid number of elements (0 for 1..2)>
19:09:25 web.1  | Error caught while parsing logs (2013-03-21T19:09:25+00:00 app[web.1]:   lib/peanut_forwarder.rb:23:in `call'
19:09:25 web.1  | ):
19:09:25 web.1  | #<ArgumentError: invalid number of elements (0 for 1..2)>
19:09:25 web.1  | Error caught while parsing logs (2013-03-21T19:09:25+00:00 app[web.1]:   config/initializers/patches/logger.rb:5:in `call_with_quiet_assets'
19:09:25 web.1  | ):
19:09:25 web.1  | #<ArgumentError: invalid number of elements (0 for 1..2)>
19:09:25 web.1  | Error caught while parsing logs (2013-03-21T19:09:25+00:00 app[web.1]:   lib/legacy_url.rb:15:in `call'
19:09:25 web.1  | ):
19:09:25 web.1  | #<ArgumentError: invalid number of elements (0 for 1..2)>
19:09:25 web.1  | Error caught while parsing logs (2013-03-21T19:09:25+00:00 app[web.1]:   lib/peanut_forwarder.rb:23:in `call'
19:09:25 web.1  | ):
19:09:25 web.1  | #<ArgumentError: invalid number of elements (0 for 1..2)>

Here is a gist in case there are any funny characters that get stripped in the quote above: https://gist.github.com/toreriklinnerud/dee24c47aff68b219e46

[toreriklinnerud]

This reproduces it

bad_line = "013-03-21T19:24:52+00:00 app[web.3]:   lib/peanut_forwarder.rb:23:in `call'"
matches = bad_line.force_encoding('utf-8').match(/(\S+)\s(\w+)\[(\w|.+)\]\:\s(.*)/)
Hash[ matches[4].split(/\s+/).map{|j| j.split("=", 2)} ]

[dominic]

Ah, then we definitely have a mismatch somewhere. I tested it locally and in a one-off process against the live Heroku app:

➡  heroku run bash -a log2viz
Running `bash` attached to terminal... up, run.2383
~ $ bundle exec irb
irb(main):001:0> bad_line = "013-03-21T19:24:52+00:00 app[web.3]:   lib/peanut_forwarder.rb:23:in `call'"
=> "013-03-21T19:24:52+00:00 app[web.3]:   lib/peanut_forwarder.rb:23:in `call'"
irb(main):002:0> matches = bad_line.force_encoding('utf-8').match(/(\S+)\s(\w+)\[(\w|.+)\]\:\s(.*)/)
=> #<MatchData "013-03-21T19:24:52+00:00 app[web.3]:   lib/peanut_forwarder.rb:23:in `call'" 1:"013-03-21T19:24:52+00:00" 2:"app" 3:"web.3" 4:"  lib/peanut_forwarder.rb:23:in `call'">
irb(main):003:0> Hash[ matches[4].split(/\s+/).map{|j| j.split("=", 2)} ]
=> {"lib/peanut_forwarder.rb:23:in"=>nil, "`call'"=>nil}

On Heroku, I'm running ruby 1.9.2p290. Locally, I'm running ruby 1.9.3p392. (which is no good - need to specify 1.9.3 in the Gemfile). Are you running on 1.9.3 locally as well?

[toreriklinnerud]

I am running Ruby 2 locally. I guess the error handling of Hash[] is different. This fixes it for me:

ps = matches[3].split('.').first
key_value_pairs = matches[4].split(/\s+/).map{|j| j.split("=", 2)}
next unless key_value_pairs.all?{ |pair| pair.size == 2}
data = Hash[ key_value_pairs ]

[dominic]

Interesting! Thanks for digging in to this.

I would definitely accept a pull request that adds Ruby 2.0 support. Otherwise, I'll leave this open until I fix the issue or explicitly note lack of 2.0.0 compatibility in the README.

[toreriklinnerud]

Let me see what I can do :)