jruby 1.4 webrick logs in rails

Question

I just upgraded jruby to 1.4 and I notice when I run my rails app that I get all kinds of logging spam now. Has anyone had experience with this?

I'm not sure if it's a jruby thing, or if they've change the version of Webrick (i can't remember the version being run before) but I have a log line for every static file it loads. The worst part is, is that it's being logged AFTER the "completed" line, so if I want to find out how long my controller took, I have to parse through a bunch crap.

Here's a sample output below. A majority of that log is just garbage that I don't care about.

Any Thoughts??

Processing AdminController#index (for 0:0:0:0:0:0:0:1%0 at 2009-11-17 09:52:16) [GET]
  Parameters: {"controller"=>"admin", "action"=>"index"}
  SQL (2.0ms)   SET SQL_AUTO_IS_NULL=0
  User Load (1.0ms)   SELECT * FROM `users` WHERE (`users`.`id` = 1) LIMIT 1
Rendering admin/index
Rendered admin/_search (2.0ms)
Rendered users/_row (4.0ms)
Rendered users/_row (3.0ms)
Rendered users/_row (3.0ms)
Rendered users/_row (6.0ms)
Rendered users/_row (4.0ms)
Rendered users/_row (3.0ms)
Rendered users/_row (4.0ms)
Rendered admin/_right_col (2.0ms)
Rendered layouts/_admin (12.0ms)
Rendered layouts/_body_header (4.0ms)
Rendered layouts/_main_nav (3.0ms)
Rendered layouts/_body_footer (2.0ms)
Completed in 817ms (View: 133, DB: 8) | 200 OK [http://localhost/admin]
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:16 EST] "GET /admin HTTP/1.1" 200 12852
http://localhost:3000/ -> /admin
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:18 EST] "GET /stylesheets/jquery.autocomplete.css?1245963105 HTTP/1.1" 304 0
http://localhost:3000/admin -> /stylesheets/jquery.autocomplete.css?1245963105
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:18 EST] "GET /stylesheets/admin.css?1256670028 HTTP/1.1" 304 0
http://localhost:3000/admin -> /stylesheets/admin.css?1256670028
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:18 EST] "GET /stylesheets/velo.selectbox.css?1252080426 HTTP/1.1" 304 0
http://localhost:3000/admin -> /stylesheets/velo.selectbox.css?1252080426
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:18 EST] "GET /stylesheets/styles.css?1258409239 HTTP/1.1" 304 0
http://localhost:3000/admin -> /stylesheets/styles.css?1258409239
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:18 EST] "GET /stylesheets/tooltip.css?1252696964 HTTP/1.1" 304 0
http://localhost:3000/admin -> /stylesheets/tooltip.css?1252696964
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:18 EST] "GET /stylesheets/jqModal.css?1251400183 HTTP/1.1" 304 0
http://localhost:3000/admin -> /stylesheets/jqModal.css?1251400183
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:18 EST] "GET /stylesheets/jquery-ui-1.7.2.custom.css?1251406553 HTTP/1.1" 304 0
http://localhost:3000/admin -> /stylesheets/jquery-ui-1.7.2.custom.css?1251406553
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:18 EST] "GET /stylesheets/dialog.css?1252080426 HTTP/1.1" 304 0
http://localhost:3000/admin -> /stylesheets/dialog.css?1252080426
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:18 EST] "GET /javascripts/jquery-ui-1.7.2.custom.min.js?1250099284 HTTP/1.1" 304 0
http://localhost:3000/admin -> /javascripts/jquery-ui-1.7.2.custom.min.js?1250099284
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:18 EST] "GET /javascripts/jqModal.js?1240867913 HTTP/1.1" 304 0
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:18 EST] "GET /javascripts/jquery.selectbox.js?1252088026 HTTP/1.1" 304 0
http://localhost:3000/admin -> /javascripts/jqModal.js?1240867913
http://localhost:3000/admin -> /javascripts/jquery.selectbox.js?1252088026
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /javascripts/jquery.quicksearch.min.js?1251489281 HTTP/1.1" 304 0
http://localhost:3000/admin -> /javascripts/jquery.quicksearch.min.js?1251489281
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /javascripts/jquery.watermark.js?1253224853 HTTP/1.1" 304 0
http://localhost:3000/admin -> /javascripts/jquery.watermark.js?1253224853
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /javascripts/jquery.autocomplete.js?1252080426 HTTP/1.1" 304 0
http://localhost:3000/admin -> /javascripts/jquery.autocomplete.js?1252080426
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /javascripts/jquery.alphanumeric.pack.js?1237489455 HTTP/1.1" 304 0
http://localhost:3000/admin -> /javascripts/jquery.alphanumeric.pack.js?1237489455
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /javascripts/application.js?1251407088 HTTP/1.1" 304 0
http://localhost:3000/admin -> /javascripts/application.js?1251407088
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /javascripts/velo.app.js?1255729397 HTTP/1.1" 304 0
http://localhost:3000/admin -> /javascripts/velo.app.js?1255729397
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /javascripts/velo.location.js?1248366551 HTTP/1.1" 304 0
http://localhost:3000/admin -> /javascripts/velo.location.js?1248366551
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /javascripts/jquery.charcounter.js?1249491478 HTTP/1.1" 304 0
http://localhost:3000/admin -> /javascripts/jquery.charcounter.js?1249491478
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /javascripts/velo.util.js?1256672217 HTTP/1.1" 304 0
http://localhost:3000/admin -> /javascripts/velo.util.js?1256672217
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /javascripts/velo.admin.js?1255729502 HTTP/1.1" 304 0
http://localhost:3000/admin -> /javascripts/velo.admin.js?1255729502
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /javascripts/velo.map.js?1255630558 HTTP/1.1" 304 0
http://localhost:3000/admin -> /javascripts/velo.map.js?1255630558
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /javascripts/Tooltip.v2.js?1247250164 HTTP/1.1" 304 0
http://localhost:3000/admin -> /javascripts/Tooltip.v2.js?1247250164
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /javascripts/velo.base.js?1253307437 HTTP/1.1" 304 0
http://localhost:3000/admin -> /javascripts/velo.base.js?1253307437
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /images/logo.gif HTTP/1.1" 304 0
http://localhost:3000/admin -> /images/logo.gif
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /images/checkBox.gif HTTP/1.1" 304 0
http://localhost:3000/admin -> /images/checkBox.gif
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /images/whitePanel.png HTTP/1.1" 304 0
http://localhost:3000/admin -> /images/whitePanel.png
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /images/zerofootprint-logo.gif HTTP/1.1" 304 0
http://localhost:3000/admin -> /images/zerofootprint-logo.gif
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /images/spritesBlueBg.png HTTP/1.1" 304 0
http://localhost:3000/admin -> /images/spritesBlueBg.png
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /images/sprites.png HTTP/1.1" 304 0
http://localhost:3000/admin -> /images/sprites.png
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /images/rightShadow.png HTTP/1.1" 304 0
http://localhost:3000/admin -> /images/rightShadow.png
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /images/loading.gif?1242250103 HTTP/1.1" 304 0
http://localhost:3000/admin -> /images/loading.gif?1242250103
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /images/printIcon.gif HTTP/1.1" 304 0
http://localhost:3000/admin -> /images/printIcon.gif
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /images/tab_blue_bg.png HTTP/1.1" 304 0
http://localhost:3000/admin -> /images/tab_blue_bg.png
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /images/tab_white_bg.png HTTP/1.1" 304 0
http://localhost:3000/admin -> /images/tab_white_bg.png
0:0:0:0:0:0:0:1%0 - - [17/Nov/2009:09:52:19 EST] "GET /images/theme/ui-bg_flat_75_ffffff_40x100.png HTTP/1.1" 304 0
http://localhost:3000/admin -> /images/theme/ui-bg_flat_75_ffffff_40x100.png

Answer 1

As per this blog post Webrick has two types of logging

1. Server logging, which is controlled by the :Server parameter passed to WEBrick::HTTPServer.new. This uses syslog-style log levels.
2. Access logging, which is controlled by the :AccessLog parameter. This logs each request, and is similar to the Apache access log.

Your Webrick server is logging both to the same log file. You can take the advice in the blog post and turn off access logs or you can direct the access logs to another output file.