Ruby » Ruby master

Bug #10965

Updated by hsbt (Hiroshi SHIBATA) over 5 years ago

We have had a ruby game server running using logger.rb to log into daily rotated log files. 

 For test it's all ok, but when put on production, sometimes the log files don't rotate daily. 

 When one day passed, the logger still write to yesterday's log file. 

 When looking at the source code, I found the following in logger.rb: 

 ``` 
     
 ~~~ 

     def write(message) 
       begin 
         @mutex.synchronize do 
           if @shift_age and @dev.respond_to?(:stat) 
             begin 
               check_shift_log 
             rescue 
               warn("log shifting failed. #{$!}") 
             end 
           end 
           begin 
             @dev.write(message) 
           rescue 
             warn("log writing failed. #{$!}") 
           end 
         end 
       rescue Exception => ignored 
         warn("log writing failed. #{ignored}") 
       end 
     end 
 ``` ~~~ 

 ``` 
 # The following running sequence for two write() may bring up the bug: 

 # now is 03/11 23:59:59 
 check_shift_log 

 # scheduling happens 
 # now is 03/12 00:00:00 
 @dev.write(message) 

 # @dev.write is buffered (correct me if I'm wrong) 
 # we can assume after write, @dev.stat.mtime becomes 03/12 00:00:01 
 # now is 03/12 00:00:01, but @dev.stat.mtime > period_end (which is 03/11 23:59:59) 
 check_shift_log 

 # now is 03/12 00:00:01 
 # will write to yesterday's log file 
 @dev.write(message) 

 # Both scheduling and buffered write can cause check_shift_log to fail when the log file should be rotated. 
 ```

Back