Skip to content

Webapp logs take too much space.

Last week somebody made several requests per second (between 40 and 50, probably a scanner) riseup's webapp. This create huge log files at syslog and user.log. Webapp currently logs the same to both files, and user.log is rotated weekly. The result were several GB of logs and a full disk (In this state, webapp was unable to allow logins or registrations).

This is an example of the logged information per request

syslog

Jul 29 17:57:17 choroy webapp[13199]: Completed   in 19.3ms
Jul 29 17:57:17 choroy webapp[13199]: Started PUT "/1/sessions/lootsah" for 0.0.0.0 at 2014-07-29 17:57:17 -0700
Jul 29 17:57:17 choroy webapp[13199]: Processing by V1::SessionsController#update as JSON
Jul 29 17:57:17 choroy webapp[13199]: Parameters: {"client_auth"=>"28b794bfb30f21d8c2621b7c71ba90b78d193e2557eea39cf9b5788a9334d18a", "id"=>"lootsah"}
Jul 29 17:57:17 choroy webapp[13199]: Completed 200 OK in 32.4ms (Views: 0.3ms)
Jul 29 18:14:20 choroy webapp[13199]: Started GET "/error_log" for 0.0.0.0 at 2014-07-29 18:14:20 -0700
Jul 29 18:14:20 choroy webapp[13199]: ActionController::RoutingError (No route matches [GET] "/error_log"):#012  vendor/bundle/ruby/1.9.1/gems/actionpa
ck-3.2.18/lib/action_dispatch/middleware/debug_exceptions.rb:21:in `call'#012  vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.18/lib/action_dispatch/midd
leware/show_exceptions.rb:56:in `call'#012  vendor/bundle/ruby/1.9.1/gems/railties-3.2.18/lib/rails/rack/logger.rb:32:in `call_app'#012  vendor/bundle/
ruby/1.9.1/gems/railties-3.2.18/lib/rails/rack/logger.rb:16:in `block in call'#012  vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.18/lib/active_suppo
rt/tagged_logging.rb:22:in `tagged'#012  vendor/bundle/ruby/1.9.1/gems/railties-3.2.18/lib/rails/rack/logger.rb:16:in `call'#012  vendor/bundle/ruby/1.
9.1/gems/actionpack-3.2.18/lib/action_dispatch/middleware/request_id.rb:22:in `call'#012  vendor/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/methodoverr
ide.rb:21:in `call'#012  vendor/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/runtime.rb:17:in `call'#012  vendor/bundle/ruby/1.9.1/gems/activesupport-3.2
.18/lib/active_support/cache/strategy/local_cache.rb:72:in `call'#012  vendor/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/lock.rb:15:in `call'#012  vend
or/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:136:in `forward'#012  vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/co
ntext.rb:245:in `fetch'#012  vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:185:in `lookup'#012  vendor/bundle/ruby/1.9.1/gems/
rack-cache-1.2/lib/rack/cache/context.rb:66:in `call!'#012  vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:51:in `call'#012  ve
ndor/bundle/ruby/1.9.1/gems/railties-3.2.18/lib/rails/engine.rb:484:in `call'#012  vendor/bundle/ruby/1.9.1/gems/railties-3.2.18/lib/rails/application.
rb:231:in `call'#012  vendor/bundle/ruby/1.9.1/gems/railties-3.2.18/lib/rails/railtie/configurable.rb:30:in `method_missing'#012  vendor/bundle/ruby/1.
9.1/gems/http_accept_language-2.0.0/lib/http_accept_language/middleware.rb:13:in `call'#012  /usr/lib/ruby/vendor_ruby/phusion_passenger/rack/request_h
andler.rb:96:in `process_request'#012  /usr/lib/ruby/vendor_ruby/phusion_passenger/abstract_request_handler.rb:516:in `accept_and_process_next_request'
#012  /usr/lib/ruby/vendor_ruby/phusion_passenger/abstract_request_handler.rb:274:in `main_loop'#012  /usr/lib/ruby/vendor_ruby/phusion_passenger/rack/
application_spawner.rb:206:in `start_request_handler'#012  /usr/lib/ruby/vendor_ruby/phusion_passenger/rack/application_spawner.rb:171:in `block in han
dle_spawn_application'#012  /usr/lib/ruby/vendor_ruby/phusion_passenger/utils.rb:479:in `safe_fork'#012  /usr/lib/ruby/vendor_ruby/phusion_passenger/ra
ck/application_spawner.rb:166:in `handle_spawn_application'#012  /usr/lib/ruby/vendor_ruby/phusion_passenger/abstract_server.rb:357:in `server_main_loo
p'#012  /usr/lib/ruby/vendor_ruby/phusion_passenger/abstract_server.rb:206:in `start_synchronously'#012  /usr/lib/ruby/vendor_ruby/phusion_passenger/ab
stract_server.rb:180:in `start'#012  /usr/lib/ruby/vendor_ruby/phusion_passenger/rack/application_spawner.rb:129:in `start'#012  /usr/lib/ruby/vendor_r
uby/phusion_passenger/spawn_manager.rb:253:in `block (2 levels) in spawn_rack_application'#012  /usr/lib/ruby/vendor_ruby/phusion_passenger/abstract_se
rver_collection.rb:132:in `lookup_or_add'#012  /usr/lib/ruby/vendor_ruby/phusion_passenger/spawn_manager.rb:246:in `block in spawn_rack_application'#01
2  /usr/lib/ruby/vendor_ruby/phusion_passenger/abstract_server_collection.rb:82:in `block in synchronize'#012  :10:in `synchronize'#0
12  /usr/lib/ruby/vendor_ruby/phusion_passenger/abstract_server_collection.rb:79:in `synchronize'#012  /usr/lib/ruby/vendor_ruby/phusion_passenger/spaw
n_manager.rb:244:in `spawn_rack_application'#012  /usr/lib/ruby/vendor_ruby/phusion_passenger/spawn_manager.rb:137:in `spawn_application'#012  /usr/lib
/ruby/vendor_ruby/phusion_passenger/spawn_manager.rb:275:in `handle_spawn_application'#012  /usr/lib/ruby/vendor_ruby/phusion_passenger/abstract_server
.rb:357:in `server_main_loop'#012  /usr/lib/ruby/vendor_ruby/phusion_passenger/abstract_server.rb:206:in `start_synchronously'#012  /usr/share/phusion-
passenger/helper-scripts/passenger-spawn-server:99:in `'
Jul 29 18:14:20 choroy webapp[13199]: Processing by ErrorsController#not_found as */*
Jul 29 18:14:20 choroy webapp[13199]: Rendered errors/not_found.html.haml within layouts/application (2.1ms)
Jul 29 18:14:20 choroy webapp[13199]: Rendered layouts/_masthead.html.haml (0.3ms)
Jul 29 18:14:20 choroy webapp[13199]: Rendered layouts/_messages.html.haml (0.1ms)
Jul 29 18:14:20 choroy webapp[13199]: Rendered layouts/_content.html.haml (0.2ms)
Jul 29 18:14:20 choroy webapp[13199]: Rendered layouts/_footer.html.haml (0.5ms)
Jul 29 18:14:20 choroy webapp[13199]: Completed 200 OK in 8.9ms (Views: 8.1ms)
Jul 29 18:14:20 choroy webapp[13199]: Started GET "/sitemap.php" for 0.0.0.0 at 2014-07-29 18:14:20 -0700

The first step we took was to make webapp only to log to one file, the other was to put an initializer made by azul to not log the full trace when having 404's.

(from redmine: created on 2014-08-05, closed on 2014-08-05, relates #5953)