18

I have a Ruby on Rails application running on Heroku. I keep getting these messages in the log:

2015-05-05T16:11:14Z app[postgres.27102]: [AQUA] connection received: host=xx.xxx.xx.26 port=60278
2015-05-05T16:11:14Z app[postgres.27102]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:14Z app[postgres.27103]: [AQUA] connection received: host=xx.xxx.xx.26 port=60291
2015-05-05T16:11:14Z app[postgres.27103]: [AQUA] connection authorized: user=postgres database=postgres
2015-05-05T16:11:18Z app[postgres.27104]: [AQUA] connection received: host=xx.xxx.x.166 port=54180
2015-05-05T16:11:18Z app[postgres.27104]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:23Z app[postgres.27105]: [AQUA] connection received: host=xx.xxx.x.166 port=55488
2015-05-05T16:11:23Z app[postgres.27105]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:28Z app[postgres.27106]: [AQUA] connection received: host=xx.xxx.x.166 port=56774
2015-05-05T16:11:28Z app[postgres.27106]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:28Z app[postgres.27107]: [AQUA] connection received: host=xx.xxx.x.166 port=56854
2015-05-05T16:11:28Z app[postgres.27107]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:28Z app[postgres.27108]: [AQUA] connection received: host=xx.xxx.x.166 port=56885
2015-05-05T16:11:28Z app[postgres.27108]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:28Z app[postgres.27109]: [AQUA] connection received: host=xx.xxx.x.166 port=56912
2015-05-05T16:11:28Z app[postgres.27109]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:33Z app[postgres.27110]: [AQUA] connection received: host=xx.xxx.x.166 port=58039
2015-05-05T16:11:33Z app[postgres.27110]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:38Z app[postgres.27111]: [AQUA] connection received: host=xx.xxx.x.166 port=59387
2015-05-05T16:11:38Z app[postgres.27111]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:43Z app[postgres.27112]: [AQUA] connection received: host=xx.xxx.x.166 port=60944
2015-05-05T16:11:43Z app[postgres.27112]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:14+00:00 app[heroku-postgres]: source=HEROKU_POSTGRESQL_AQUA sample#current_transaction=511990 sample#db_size=203303096bytes sample#tables=17 sample#active-connections=2 sample#waiting-connections=0 sample#index-cache-hit-rate=0.99997 sample#table-cache-hit-rate=0.94699 sample#load-avg-1m=0.14 sample#load-avg-5m=0.25 sample#load-avg-15m=0.24 sample#read-iops=0.1875 sample#write-iops=1 sample#memory-total=7629448kB sample#memory-free=428388kB sample#memory-cached=6784860kB sample#memory-postgres=171732kB

I can't figure out what's causing this. The application runs Cedar 10 stack, ruby 2.1.4, rails 3.2.11 and puma 2.11.2 with 3 workers and 1 thread. It's not happening in the development or staging environments, only on Heroku.

Running: select application_name from pg_stat_activity; shows:

        application_name         
---------------------------------

 puma: cluster worker 2: 3 [app]
 puma: cluster worker 1: 3 [app]
 puma: cluster worker 0: 3 [app]
 psql johnny interactive

Here's my puma configuration file (min and max threads is equal to 1):

workers Integer(ENV['PUMA_WORKERS'] || 3)
threads Integer(ENV['MIN_THREADS']  || 1), Integer(ENV['MAX_THREADS'] || 16)

preload_app!

rackup      DefaultRackup
port        ENV['PORT']     || 3000
environment ENV['RACK_ENV'] || 'development'

on_worker_boot do
  # worker specific setup
  ActiveSupport.on_load(:active_record) do
    config = ActiveRecord::Base.configurations[Rails.env] ||
                Rails.application.config.database_configuration[Rails.env]
    config['pool'] = ENV['MAX_THREADS'] || 16
    ActiveRecord::Base.establish_connection(config)
  end
end

Any ideas on how to trace this?

Update: I added a debug message to the on_worker_boot block and it only gets invoked on the application startup, so I still have no clue why connections are beings established so frequently.

Johnny
  • 7,073
  • 9
  • 46
  • 72
  • It could be an add-on making these connections. Which add-ons do you have installed? – infused May 14 '15 at 03:44
  • Postgres, Mandrill, New Relic, Papertrail, PG Backups, RedisToGo and Heroku Scheduler. – Johnny May 14 '15 at 09:00
  • A couple questions come to mind - 1) what (if anything) are you scheduling? 2) Is there any health check from New Relic that may correspond (roughly) to the frequency? – bimsapi May 20 '15 at 15:43
  • 1) There is one backup job running every 24 hours, one hourly job that sends emails and a job that runs every ten minutes that creates DB records. All are fairly quick. I don't think it has to do with them because these logs start immediately when the system comes online. 2) There is no New Relic health check. – Johnny May 22 '15 at 14:38

2 Answers2

4

This is casual logs about establish connection to Postgres. So, just ignore them or try to disable them in postgresql.conf (see log_connections option), but I don't think that you have access to it in Heroku.

willis
  • 189
  • 7
  • I don't think that's it. If you look at the logs it's creating connections several times every second. That's not how it's supposed to be. – Johnny May 05 '15 at 17:33
  • Is this beginning of log or you see such log messages after several minutes of application work? In the first case it can be related to start Puma workers, in second case this is a problem. – willis May 05 '15 at 17:36
  • It's pretty much continuous. – Johnny May 05 '15 at 17:39
0

Not worked with Heroku, but have you tried getting a thread dump of the ruby process using a tool like xray? http://blog.pivotal.io/labs/labs/inspect-running-ruby-processes-using-xray-and-kill-3

The thread stack might help point the source of these calls.

codedabbler
  • 1,231
  • 7
  • 13
  • Here are the results of the thread dump: http://dumptext.com/piqHWgAq. Not really sure how to interpret this. – Johnny May 25 '15 at 08:54
  • I don't know what is wrong in the trace. Most likely, the worker crashed due to some error and it is being restarted. Someone more knowledgeable can help here. – codedabbler May 25 '15 at 17:58