4

I'm dockerizing one of my ruby apps, but I've got this very strange logging behavior. It only seems to load when the program ENDS not while it's running. When I run the program (daemon) with docker-compose all I see is this:

Starting custom_daemon_1
Attaching to custom_daemon_1

However, if I put an exit part way into the program I see all my puts and logger outputs. 

Starting custom_daemon_1
Attaching to custom_daemon_1
custom_daemon_1  | requires
custom_daemon_1  | starting logger
custom_daemon_1  | Starting loads
custom_daemon_1  | Hello base
custom_daemon_1  | Loaded track
custom_daemon_1  | Loaded geo
custom_daemon_1  | Loaded geo_all
custom_daemon_1  | Loaded unique
custom_daemon_1  | D, [2016-11-14T13:31:19.295785 #1] DEBUG -- : Starting custom_daemon...
custom_daemon_1  | D, [2016-11-14T13:31:19.295889 #1] DEBUG -- : Loading xx from disk...
custom_daemon_1 exited with code 0

The top ones without times were just puts debugging, seeing if it would show - the bottom two are created by: 

Logger.new(STDOUT)
LOG = Logger.new(STDOUT)
LOG.level = Logger::DEBUG

Then I would call LOG.debug "xxx" or LOG.error "xxx" any idea why this strange behavior is happening? When I ctrl+c out of the first one, the logs still do not show up.

This was originally run by a .sh script and now I've made the call to run it directly as the CMD of the Dockerfile.

There is a python question I found asking something similar here. Someone speculates it may have to do with PID 1 processes having logging to STDOUT surpressed.

Test

Here is a test I ran:

puts "starting logger"
Logger.new(STDOUT)
LOG = Logger.new(STDOUT)
LOG.level = Logger::DEBUG
puts "this is 'puts'"
p "this is 'p'"
LOG.debug "this is 'log.debug'"
puts "Starting loads"

outputs:

custom_daemon_1  | starting logger
custom_daemon_1  | this is 'puts'
custom_daemon_1  | "this is 'p'"

Notice that the first two puts printed but as soon as I try to use LOG.debug it didn't work.

TEST 2

I also decided to try the logger using a file, and as expected it logs to the file just fine, through docker.

All I did was change Logger.new(STDOUT) to Logger.new('mylog.log') and I can tail -f mylog.log and all the LOG.debug prompts show up.

Community
  • 1
  • 1
Jono
  • 3,393
  • 6
  • 33
  • 48

2 Answers2

10

As say in this thread Log issue in Rails4 with Docker running rake task

Try disabling output buffering to STDOUT: $stdout.sync = true

Community
  • 1
  • 1
gagalago
  • 146
  • 2
  • 8
0

I've temporarily fixed this with adding a symlink to based on this docker thread. In the Dockerfile:

RUN ln -sf /proc/1/fd/1 /var/log/mylog.log and set my logger to, LOG = Logger.new('/var/log/mylog.log') but this has two undesired consequences. First, the log file will grow and take up space and probably need to be managed - I don't want to deal with that. Second, it seems inelegant to have to add a symlink to get logging to work properly... Would love another solution.

Jono
  • 3,393
  • 6
  • 33
  • 48