Same log file opened multiple times in write mode, truncating file on each write

[evanbattaglia]

This is mostly to help other people as we are probably just going to move away from log4r to syslog or something. We have a project which uses log4r with the RollingFileOutputter. The latest log is not growing in size but instead being overwritten frequently. I believe this is the due to the fact that log4r is opening it in write mode instead of append mode.

I see in RollingFileOutputter#roll you have open_log_file('w'), I'm guessing there may be a race condition or something that is causing that to happen in multiple processes. (Extra info: we have the maximum number of logs -- eg max_backups has been reached). I'm not sure why you would ever want to open a log file in write mode, since append mode also creates the file if it doesn't exist.

$ lsof +fg |grep silo.production | grep -v W,AP
ruby      10894     seomoz   13w      REG       W,0x8000      252,0        3318     527976 /var/www/vhosts/silo/shared/log/silo.production000235.log
ruby      15449     seomoz   13w      REG       W,0x8000      252,0        4368     527976 /var/www/vhosts/silo/shared/log/silo.production000235.log
ruby      15909     seomoz   13w      REG       W,0x8000      252,0        4504     527976 /var/www/vhosts/silo/shared/log/silo.production000235.log
ruby      16020     seomoz   13w      REG       W,0x8000      252,0        4504     527976 /var/www/vhosts/silo/shared/log/silo.production000235.log
ruby      16122     seomoz   13w      REG       W,0x8000      252,0        4504     527976 /var/www/vhosts/silo/shared/log/silo.production000235.log

[muirmanders]

We are seeing this too with many processes writing to the same log file. There is certainly a race condition between checking if its time to roll and opening the next file. When the second process re-opens the same file in "w" mode you get lots of craziness because, unlike append mode, "w" does not seek to the end of the file for you when writing. That means the processes will be battling it out and overwriting the middle of the file.

[evanbattaglia]

I'll note that simply changing "w" to "a" brought up another issue -- we got occasional errors where log4r was looking for a log file that didn't exist and raising an error, on the line @start_time = File.ctime(@filename). It only happens once a week or so for us so I haven't had time to debug it further.

[bkon]

We've run into this issue in production as well; the cause of this seem to be multiple unicorn worker using the same RollingFileOutputter.

Every process tracks the log size itself (https://github.com/colbygk/log4r/blob/master/lib/log4r/outputter/rollingfileoutputter.rb#L128) and never actually checks the file size. This means that workers decide to roll over to the next file independently and when rolling over they can just overwrite existing file generated by another worker (https://github.com/colbygk/log4r/blob/master/lib/log4r/outputter/rollingfileoutputter.rb#L198).