Fix buffering of log traces in subscriber

[rafatower]

Story details: https://app.clubhouse.io/cartoteam/story/123660

[rafatower]

Tested in staging:

ubuntu@ded-dynamic-495obt8:~/www/production.cartodb.com/current$ RAILS_ENV=staging bundle exec rake message_broker:cartodb_subscribers > /tmp/subscriber.test.log 2>&1 &
[1] 30818
ubuntu@ded-dynamic-495obt8:~/www/production.cartodb.com/current$ cat /tmp/subscriber.test.log 
[1]+  Exit 1                  RAILS_ENV=staging bundle exec rake message_broker:cartodb_subscribers > /tmp/subscriber.test.log 2>&1
{"exception":{"class":"NoMethodError","message":"undefined method `[]' for nil:NilClass","backtrace_hint":["/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/bundler/gems/cartodb-common-c49a25b587e5/lib/carto/common/message_broker.rb:72:in `initialize'","/usr/lib/ruby/2.5.0/singleton.rb:141:in `new'","/usr/lib/ruby/2.5.0/singleton.rb:141:in `block in instance'","/usr/lib/ruby/2.5.0/singleton.rb:139:in `synchronize'","/usr/lib/ruby/2.5.0/singleton.rb:139:in `instance'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/bundler/gems/cartodb-common-c49a25b587e5/lib/carto/common/message_broker.rb:24:in `initialize'","/home/ubuntu/www/production.cartodb.com/releases/20201203095512/lib/tasks/central_updates_subscriber.rake:14:in `new'","/home/ubuntu/www/production.cartodb.com/releases/20201203095512/lib/tasks/central_updates_subscriber.rake:14:in `block (2 levels) in \u003ctop (required)\u003e'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/gems/rake-0.9.2.2/lib/rake/task.rb:205:in `block in execute'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/gems/rake-0.9.2.2/lib/rake/task.rb:200:in `each'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/gems/rake-0.9.2.2/lib/rake/task.rb:200:in `execute'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/gems/rake-0.9.2.2/lib/rake/task.rb:158:in `block in invoke_with_call_chain'","/usr/lib/ruby/2.5.0/monitor.rb:235:in `mon_synchronize'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/gems/rake-0.9.2.2/lib/rake/task.rb:151:in `invoke_with_call_chain'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/gems/rake-0.9.2.2/lib/rake/task.rb:144:in `invoke'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/gems/rake-0.9.2.2/lib/rake/application.rb:116:in `invoke_task'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/gems/rake-0.9.2.2/lib/rake/application.rb:94:in `block (2 levels) in top_level'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/gems/rake-0.9.2.2/lib/rake/application.rb:94:in `each'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/gems/rake-0.9.2.2/lib/rake/application.rb:94:in `block in top_level'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/gems/rake-0.9.2.2/lib/rake/application.rb:133:in `standard_exception_handling'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/gems/rake-0.9.2.2/lib/rake/application.rb:88:in `top_level'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/gems/rake-0.9.2.2/lib/rake/application.rb:66:in `block in run'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/gems/rake-0.9.2.2/lib/rake/application.rb:133:in `standard_exception_handling'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/gems/rake-0.9.2.2/lib/rake/application.rb:63:in `run'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/gems/rake-0.9.2.2/bin/rake:33:in `\u003ctop (required)\u003e'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/bin/rake:23:in `load'","/home/ubuntu/www/production.cartodb.com/shared/bundle/ruby/2.5.0/bin/rake:23:in `\u003cmain\u003e'"]},"timestamp":"2020-12-03T09:57:17.338+00:00","levelname":"error","cdb-user":null,"event_message":"undefined method `[]' for nil:NilClass"}

(the error is kind of expected as it still lacks some configuration in staging, the important thing is that we see the traces)

[rafatower]

I did another test adding this to the top of the rake:

logger.info(message: 'rtorre here')
sleep

and this is what I got:

ubuntu@ded-dynamic-495obt8:~/www/production.cartodb.com/current$ RAILS_ENV=staging bundle exec rake message_broker:cartodb_subscribers > /tmp/subscriber.test.log 2>&1 &
[1] 30818
ubuntu@ded-dynamic-495obt8:~/www/production.cartodb.com/current$ cat /tmp/subscriber.test.log
{"timestamp":"2020-12-03T09:59:46.414+00:00","levelname":"info","cdb-user":null,"event_message":"rtorre here"}
ubuntu@ded-dynamic-495obt8:~/www/production.cartodb.com/current$ kill %1
ubuntu@ded-dynamic-495obt8:~/www/production.cartodb.com/current$ cat /tmp/subscriber.test.log
[1]+  Exit 1                  RAILS_ENV=staging bundle exec rake message_broker:cartodb_subscribers > /tmp/subscriber.test.log 2>&1
{"timestamp":"2020-12-03T09:59:46.414+00:00","levelname":"info","cdb-user":null,"event_message":"rtorre here"}
rake aborted!
SIGTERM

Tasks: TOP => message_broker:cartodb_subscribers
(See full trace by running task with --trace)

so, working as expected

[amiedes]

👍