[ruby-core:68498] [Ruby trunk - Bug #10965] [Open] logger.rb may not daily rotate

[ruby-core:68498] [Ruby trunk - Bug #10965] [Open] logger.rb may not daily rotate

[leiting]

Issue #10965 has been reported by Lei Ting.

----------------------------------------
Bug #10965: logger.rb may not daily rotate
https://bugs.ruby-lang.org/issues/10965

* Author: Lei Ting
* Status: Open
* Priority: Normal
* Assignee: Hiroshi Nakamura
* ruby -v: 2.0.0-p353
* Backport: 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN
----------------------------------------
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.




-- 
https://bugs.ruby-lang.org/

[ruby-core:93886] [Ruby master Bug#10965] logger.rb may not daily rotate

[hsbt]

Issue #10965 has been updated by hsbt (Hiroshi SHIBATA).

Assignee changed from nahi (Hiroshi Nakamura) to sonots (Naotoshi Seo)
Status changed from Open to Assigned
Description updated

----------------------------------------
Bug #10965: logger.rb may not daily rotate
https://bugs.ruby-lang.org/issues/10965#change-79866

* Author: leiting (Lei Ting)
* Status: Assigned
* Priority: Normal
* Assignee: sonots (Naotoshi Seo)
* Target version: 
* ruby -v: 2.0.0-p353
* Backport: 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN
----------------------------------------
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.
```



-- 
https://bugs.ruby-lang.org/

[ruby-core:94399] [Ruby master Bug#10965] logger.rb may not daily rotate

[sonots]

Issue #10965 has been updated by sonots (Naotoshi Seo).


I do not well understand the problem. Indeed, the logger sees `@dev.stat.mtime`, but it is on only at `#initialize` https://github.com/ruby/logger/blob/4278b3e4ac1d2b2df555f7cde8813c452dc85f03/lib/logger/log_device.rb#L24-L27.

The condition shifting log file daily is https://github.com/ruby/logger/blob/4278b3e4ac1d2b2df555f7cde8813c452dc85f03/lib/logger/log_device.rb#L130-L132.
Here, we do not see `@dev.stat.mtime`.

```
        now = Time.now
        if now >= @next_rotate_time
          @next_rotate_time = next_rotate_time(now, @shift_age)
```

I believe such race-condition does not occur.
I greatly appreciate if you can provide a reproducible code.

----------------------------------------
Bug #10965: logger.rb may not daily rotate
https://bugs.ruby-lang.org/issues/10965#change-80819

* Author: leiting (Lei Ting)
* Status: Assigned
* Priority: Normal
* Assignee: sonots (Naotoshi Seo)
* Target version: 
* ruby -v: 2.0.0-p353
* Backport: 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN
----------------------------------------
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.
```



-- 
https://bugs.ruby-lang.org/