I'm running passenger_version: 4.0.44 on redhat and I recently noticed that anytime it spawns a rails app it gets an exception but it doesn't seem to stop it from running.
The machine has Ruby 1.8, 1.9 and 2.1 and from the looks of it, it is reading from a 1.8 directory.
App 4882 stderr: /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/rubygems_integration.rb:366: warning: parenthesize argument(s) for future version
App 4882 stderr: /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/rubygems_integration.rb:8:in `version'
App 4882 stderr: : uninitialized constant Gem::VERSION (NameError)App 4882 stderr: from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/rubygems_integration.rb:12:in `provides?'
App 4882 stderr: from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/rubygems_integration.rb:555
App 4882 stderr: from /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31:in `gem_original_require'
App 4882 stderr: from /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31:in `require'App 4882 stderr: from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/shared_helpers.rb:5
App 4882 stderr: from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/setup.rb:1:in `require'
App 4882 stderr: from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/setup.rb:1
PassengerDefaultRuby /opt/ruby/bin/ruby # this is our 1.9 ruby
PassengerRuby /opt/ruby2/bin/ruby # this is our 2.1 ruby and is what this app is running.
/usr/bin has ruby 1.8
Is the spawner detecting this exception and trying again? The application starts fine but I'm wondering if this exception is slowing things down.
Here is the full log if useful. (yes.. i know this machine is slow).
Thanks in advance for any help!
Tony
[ 2015-03-17 10:34:08.0751 32082/2b5be4da8940 Pool2/Group.h:1186 ]: Requested spawning of new process for group /var/www/rails_projects/msd/live#default
[ 2015-03-17 10:34:08.0756 32082/2b5be4da8940 Pool2/Implementation.cpp:1029 ]: Restart of group /var/www/rails_projects/msd/live#default done
[ 2015-03-17 10:34:08.0757 32082/2b5be4a82940 Pool2/SmartSpawner.h:736 ]: Spawning new process: appRoot=/var/www/rails_projects/msd/live
[ 2015-03-17 10:34:08.0758 32082/2b5be4a82940 Pool2/SmartSpawner.h:206 ]: Spawning new preloader: appRoot=/var/www/rails_projects/msd/live
[ 2015-03-17 10:34:08.0810 32082/2b5be4a82940 Pool2/SmartSpawner.h:252 ]: Preloader process forked for appRoot=/var/www/rails_projects/msd/live: PID 4882
[ 2015-03-17 10:34:08.1445 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
App 4882 stdout:
[ 2015-03-17 10:34:08.2820 32082/2b5be4a82940 Pool2/Spawner.h:787 ]: [App 4882 stdout] ! I have control 1.0
[ 2015-03-17 10:34:08.2824 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] You have control 1.0
[ 2015-03-17 10:34:08.2825 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] passenger_root: /var/appl/httpd/passenger/passenger4
[ 2015-03-17 10:34:08.2825 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] ruby_libdir: /var/appl/httpd/passenger/passenger4/lib
[ 2015-03-17 10:34:08.2826 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] passenger_version: 4.0.44
[ 2015-03-17 10:34:08.2826 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] generation_dir: /tmp/passenger.1.0.8358/generation-3
[ 2015-03-17 10:34:08.2826 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] app_root: /var/www/rails_projects/msd/live
[ 2015-03-17 10:34:08.2827 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] app_group_name: /var/www/rails_projects/msd/live
[ 2015-03-17 10:34:08.2827 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] app_type: rack
[ 2015-03-17 10:34:08.2828 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] start_command: /opt/ruby2/bin/ruby /var/appl/httpd/passenger/passenger4/helper-scripts/rack-loader.rb
[ 2015-03-17 10:34:08.2828 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] startup_file:
config.ru[ 2015-03-17 10:34:08.2828 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] process_title: Passenger RackApp
[ 2015-03-17 10:34:08.2829 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] log_level: 7
[ 2015-03-17 10:34:08.2829 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] start_timeout: 90000
[ 2015-03-17 10:34:08.2829 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] environment: www_dev
[ 2015-03-17 10:34:08.2830 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] base_uri: /rails/var/msd
[ 2015-03-17 10:34:08.2830 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] spawn_method: smart
[ 2015-03-17 10:34:08.2830 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] default_user: nobody
[ 2015-03-17 10:34:08.2831 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] default_group: nobody
[ 2015-03-17 10:34:08.2831 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] ruby: /opt/ruby2/bin/ruby
[ 2015-03-17 10:34:08.2832 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] python: python
[ 2015-03-17 10:34:08.2832 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] nodejs: node
[ 2015-03-17 10:34:08.2832 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] logging_agent_address: unix:/tmp/passenger.1.0.8358/generation-3/logging
[ 2015-03-17 10:34:08.2833 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] logging_agent_username: logging
[ 2015-03-17 10:34:08.2833 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] logging_agent_password: SzXMwjsZI9jeVijzSsCIhMc3EDZnzIQED87y6hpTE19bNNyLg6PtHapdxUGzAHHy
[ 2015-03-17 10:34:08.2833 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] debugger: false
[ 2015-03-17 10:34:08.2834 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ] analytics: false
[ 2015-03-17 10:34:08.2834 32082/2b5be4a82940 Pool2/SmartSpawner.h:352 ]: [App 4882 stdin ]
[ 2015-03-17 10:34:08.4421 32082/2b5bdf0c5940 Pool2/Pool.h:676 ]: Garbage collection time...
[ 2015-03-17 10:34:08.4424 32082/2b5bdf0c5940 Pool2/Pool.h:660 ]: Garbage collect idle spawner: group=/var/www/rails_projects/cfp/live#default
[ 2015-03-17 10:34:08.4425 32082/2b5bdf0c5940 Pool2/Pool.h:725 ]: Garbage collection done; next garbage collect in 190.515 sec
[ 2015-03-17 10:34:11.0005 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:11.0506 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.949 sec
[ 2015-03-17 10:34:13.1464 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:16.0013 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:16.0546 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.945 sec
[ 2015-03-17 10:34:18.1452 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:21.0011 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:21.0523 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.948 sec
[ 2015-03-17 10:34:23.1451 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:26.0010 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:26.0506 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.949 sec
[ 2015-03-17 10:34:28.1449 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:31.0008 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:31.0513 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.949 sec
[ 2015-03-17 10:34:33.1448 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:36.0016 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:36.0505 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.950 sec
[ 2015-03-17 10:34:38.1446 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:41.0015 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:41.0514 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.949 sec
[ 2015-03-17 10:34:43.1445 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:46.0013 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:46.0502 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.950 sec
[ 2015-03-17 10:34:48.1444 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:51.0012 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:51.0497 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.950 sec
[ 2015-03-17 10:34:53.1451 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:56.0020 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:34:56.0529 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.947 sec
App 4882 stderr: /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/rubygems_integration.rb:366: warning: parenthesize argument(s) for future version
App 4882 stderr: /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/rubygems_integration.rb:8:in `version'
App 4882 stderr: : uninitialized constant Gem::VERSION (NameError)
App 4882 stderr: from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/rubygems_integration.rb:12:in `provides?'
App 4882 stderr: from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/rubygems_integration.rb:555
App 4882 stderr: from /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31:in `gem_original_require'
App 4882 stderr: from /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31:in `require'
App 4882 stderr: from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/shared_helpers.rb:5
App 4882 stderr: from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/setup.rb:1:in `require'
App 4882 stderr: from /opt/ruby2/lib/ruby/gems/2.1.0/gems/bundler-1.6.2/lib/bundler/setup.rb:1
[ 2015-03-17 10:34:58.1329 32082/2b5be4a82940 Pool2/Spawner.h:787 ]: [App 4882 stdout] ! Ready
[ 2015-03-17 10:34:58.1330 32082/2b5be4a82940 Pool2/Spawner.h:787 ]: [App 4882 stdout] ! socket: unix:/tmp/passenger.1.0.8358/generation-3/backends/preloader.4882
[ 2015-03-17 10:34:58.1330 32082/2b5be4a82940 Pool2/Spawner.h:787 ]: [App 4882 stdout] !
[ 2015-03-17 10:34:58.1344 32082/2b5be4a82940 Pool2/SmartSpawner.h:297 ]: Preloader for /var/www/rails_projects/msd/live started on PID 4882, listening on unix:/tmp/passenger.1.0.8358/generation-3/backends/preloader.4882
[ 2015-03-17 10:34:58.1450 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:34:58.2781 32082/2b5be4a82940 Pool2/Spawner.h:787 ]: [App 4984 stdout] ! I have control 1.0
[ 2015-03-17 10:34:58.2784 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] You have control 1.0
[ 2015-03-17 10:34:58.2785 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] passenger_root: /var/appl/httpd/passenger/passenger4
[ 2015-03-17 10:34:58.2785 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] passenger_version: 4.0.44
[ 2015-03-17 10:34:58.2786 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] ruby_libdir: /var/appl/httpd/passenger/passenger4/lib
[ 2015-03-17 10:34:58.2786 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] generation_dir: /tmp/passenger.1.0.8358/generation-3
[ 2015-03-17 10:34:58.2786 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] gupid: 16acdca-w2yaQWoXaag
[ 2015-03-17 10:34:58.2787 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] connect_password: 1gHzKypLukttxP05QJ0bUN5WZUBInnlfdMgGFgBIypC
[ 2015-03-17 10:34:58.2787 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] app_root: /var/www/rails_projects/msd/live
[ 2015-03-17 10:34:58.2788 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] app_group_name: /var/www/rails_projects/msd/live
[ 2015-03-17 10:34:58.2788 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] app_type: rack
[ 2015-03-17 10:34:58.2788 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] start_command: /opt/ruby2/bin/ruby /var/appl/httpd/passenger/passenger4/helper-scripts/rack-loader.rb
[ 2015-03-17 10:34:58.2789 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] startup_file:
config.ru[ 2015-03-17 10:34:58.2789 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] process_title: Passenger RackApp
[ 2015-03-17 10:34:58.2790 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] log_level: 7
[ 2015-03-17 10:34:58.2790 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] start_timeout: 90000
[ 2015-03-17 10:34:58.2791 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] environment: www_dev
[ 2015-03-17 10:34:58.2791 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] base_uri: /rails/var/msd
[ 2015-03-17 10:34:58.2791 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] spawn_method: smart
[ 2015-03-17 10:34:58.2792 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] default_user: nobody
[ 2015-03-17 10:34:58.2792 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] default_group: nobody
[ 2015-03-17 10:34:58.2793 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] ruby: /opt/ruby2/bin/ruby
[ 2015-03-17 10:34:58.2793 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] python: python
[ 2015-03-17 10:34:58.2794 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] nodejs: node
[ 2015-03-17 10:34:58.2794 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] logging_agent_address: unix:/tmp/passenger.1.0.8358/generation-3/logging
[ 2015-03-17 10:34:58.2794 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] logging_agent_username: logging
[ 2015-03-17 10:34:58.2795 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] logging_agent_password: SzXMwjsZI9jeVijzSsCIhMc3EDZnzIQED87y6hpTE19bNNyLg6PtHapdxUGzAHHy
[ 2015-03-17 10:34:58.2796 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] debugger: false
[ 2015-03-17 10:34:58.2796 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] analytics: false
[ 2015-03-17 10:34:58.2796 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ] group_secret: JQ74lIPgf3S4gtka1dxsH5ozD3Ueli6D25A6tryCG6m
[ 2015-03-17 10:34:58.2797 32082/2b5be4a82940 Pool2/Spawner.h:407 ]: [App 4984 stdin ]
App 4984 stdout:
[ 2015-03-17 10:34:58.2865 32082/2b5be4a82940 Pool2/Spawner.h:787 ]: [App 4984 stdout] ! Ready
[ 2015-03-17 10:34:58.2865 32082/2b5be4a82940 Pool2/Spawner.h:787 ]: [App 4984 stdout] ! socket: main;unix:/tmp/passenger.1.0.8358/generation-3/backends/ruby.6iPAX2V969RDNnZsHSskeXS5A2dmWPXwpMgHqobRRQgTt1V;session;1
[ 2015-03-17 10:34:58.2867 32082/2b5be4a82940 Pool2/Spawner.h:787 ]: [App 4984 stdout] ! socket: http;tcp://127.0.0.1:51631;http;1
[ 2015-03-17 10:34:58.2867 32082/2b5be4a82940 Pool2/Spawner.h:787 ]: [App 4984 stdout] !
[ 2015-03-17 10:34:58.2870 32082/2b5be4a82940 Pool2/SmartSpawner.h:771 ]: Process spawning done: appRoot=/var/www/rails_projects/msd/live, pid=4984
[ 2015-03-17 10:34:58.2872 32082/2b5be4a82940 Pool2/Group.h:989 ]: Attaching process (pid=4984, group=/var/www/rails_projects/msd/live#default)
[ 2015-03-17 10:34:58.2873 32082/2b5be4a82940 Pool2/Implementation.cpp:870 ]: New process count = 1, remaining get waiters = 0
[ 2015-03-17 10:34:58.2874 32082/2b5be4a82940 Pool2/Implementation.cpp:898 ]: Spawn loop done
[ 2015-03-17 10:34:58.2876 32082/2b5bdf0c5940 Pool2/Pool.h:676 ]: Garbage collection time...
[ 2015-03-17 10:34:58.2878 32082/2b5be4a00940 agents/HelperAgent/RequestHandler.h:2168 ]: [Client 23] Event: sessionCheckedOut
[ 2015-03-17 10:34:58.2879 32082/2b5be4a00940 agents/HelperAgent/RequestHandler.h:2196 ]: [Client 23] Session checked out: pid=4984, gupid=16acdca-w2yaQWoXaag
[ 2015-03-17 10:34:58.2880 32082/2b5be4a00940 Pool2/Socket.h:85 ]: Connecting to unix:/tmp/passenger.1.0.8358/generation-3/backends/ruby.6iPAX2V969RDNnZsHSskeXS5A2dmWPXwpMgHqobRRQgTt1V
[ 2015-03-17 10:34:58.2879 32082/2b5bdf0c5940 Pool2/Pool.h:725 ]: Garbage collection done; next garbage collect in 140.670 sec
[ 2015-03-17 10:34:58.2885 32082/2b5be4a00940 agents/HelperAgent/RequestHandler.h:2291 ]: [Client 23] Session initiated: fd=30
[ 2015-03-17 10:34:58.2886 32082/2b5be4a00940 EventedBufferedInput.h:361 ]: [EventedBufferedInput 0x2b5be0006ea0 fd=-1, state=LIVE, buffer(0)="", paused=1, socketPaused=1, nextTickInstalled=0, generation=1, error=0] reset()
[ 2015-03-17 10:34:58.2886 32082/2b5be4a00940 EventedBufferedInput.h:381 ]: [EventedBufferedInput 0x2b5be0006ea0 fd=30, state=LIVE, buffer(0)="", paused=1, socketPaused=1, nextTickInstalled=0, generation=2, error=0] start()
[ 2015-03-17 10:34:58.2887 32082/2b5be4a00940 agents/HelperAgent/RequestHandler.h:2312 ]: [Client 23] Sending headers to application
[ 2015-03-17 10:34:58.2888 32082/2b5be4a00940 agents/HelperAgent/RequestHandler.h:2458 ]: [Client 23] Begin sending body to application
[ 2015-03-17 10:34:58.2889 32082/2b5be4a00940 agents/HelperAgent/RequestHandler.h:2528 ]: [Client 23] End of (unbuffered) client body reached; done sending data to application
App 4882 stderr: [ 2015-03-17 10:34:58.2870 4984/0x002af6e694a798(Main thread) request_handler.rb:181 ]: Entering request handler main loop
App 4882 stderr: [ 2015-03-17 10:34:58.3279 4984/0x002af6e69192d8(Worker 1) request_handler/thread_handler.rb:131 ]: Accepted new request on socket main socket
[ 2015-03-17 10:35:01.0019 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:01.0725 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.928 sec
[ 2015-03-17 10:35:03.1448 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:35:06.0007 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:06.0741 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.926 sec
[ 2015-03-17 10:35:08.1447 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:35:11.0006 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:11.0733 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.927 sec
[ 2015-03-17 10:35:13.1445 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:35:16.0014 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:16.0642 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.936 sec
[ 2015-03-17 10:35:18.1444 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:35:21.0012 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:21.0738 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.926 sec
[ 2015-03-17 10:35:23.1443 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:35:26.0011 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:26.0746 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.925 sec
[ 2015-03-17 10:35:28.1450 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:35:31.0009 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:31.0745 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.926 sec
[ 2015-03-17 10:35:33.1449 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:35:36.0018 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:36.0713 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.929 sec
[ 2015-03-17 10:35:38.1448 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:35:41.0016 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:41.0751 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.925 sec
[ 2015-03-17 10:35:43.1446 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks
[ 2015-03-17 10:35:46.0014 32082/2b5bdf084940 Pool2/Pool.h:827 ]: Analytics collection time...
[ 2015-03-17 10:35:46.0670 32082/2b5bdf084940 Pool2/Pool.h:930 ]: Analytics collection done; next analytics collection in 4.933 sec
[ 2015-03-17 10:35:48.1444 32087/2b5886006360 agents/LoggingAgent/LoggingServer.h:752 ]: Flushing all sinks