From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.2 (2018-09-13) on dcvr.yhbt.net X-Spam-Level: X-Spam-ASN: AS4713 221.184.0.0/13 X-Spam-Status: No, score=-2.6 required=3.0 tests=BAYES_00,DKIM_ADSP_CUSTOM_MED, FORGED_GMAIL_RCVD,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,MAILING_LIST_MULTI,RCVD_IN_DNSWL_MED, SPF_HELO_NONE,SPF_PASS shortcircuit=no autolearn=no autolearn_force=no version=3.4.2 Received: from neon.ruby-lang.org (neon.ruby-lang.org [221.186.184.75]) by dcvr.yhbt.net (Postfix) with ESMTP id 6D59C1F45A for ; Sat, 17 Aug 2019 04:02:00 +0000 (UTC) Received: from neon.ruby-lang.org (localhost [IPv6:::1]) by neon.ruby-lang.org (Postfix) with ESMTP id 8FCEA12099E; Sat, 17 Aug 2019 13:01:52 +0900 (JST) Received: from o1678916x28.outbound-mail.sendgrid.net (o1678916x28.outbound-mail.sendgrid.net [167.89.16.28]) by neon.ruby-lang.org (Postfix) with ESMTPS id E621F12099E for ; Sat, 17 Aug 2019 13:01:50 +0900 (JST) Received: by filter0189p3mdw1.sendgrid.net with SMTP id filter0189p3mdw1-5965-5D577C31-26 2019-08-17 04:01:53.833352344 +0000 UTC m=+38498.453096493 Received: from herokuapp.com (unknown [54.89.44.2]) by ismtpd0041p1mdw1.sendgrid.net (SG) with ESMTP id fdaBRdx_THmWirzjdQjfJA for ; Sat, 17 Aug 2019 04:01:53.775 +0000 (UTC) Date: Sat, 17 Aug 2019 04:01:53 +0000 (UTC) From: sonots@gmail.com Message-ID: References: Mime-Version: 1.0 X-Redmine-MailingListIntegration-Message-Ids: 69947 X-Redmine-Project: ruby-trunk X-Redmine-Issue-Id: 10965 X-Redmine-Issue-Author: leiting X-Redmine-Issue-Assignee: sonots X-Redmine-Sender: sonots X-Mailer: Redmine X-Redmine-Host: bugs.ruby-lang.org X-Redmine-Site: Ruby Issue Tracking System X-Auto-Response-Suppress: All Auto-Submitted: auto-generated X-SG-EID: =?us-ascii?Q?ivKxv=2F+IDWs96swzTUdiO4z2P4QFK+ydTrfF9HmlbZSCHop7ZopHdimhCkTH02?= =?us-ascii?Q?XacggRbLLhE4JW=2FAwcIZKNYMCD=2FzYZ19JL8gyyW?= =?us-ascii?Q?wviLQtEb4UFFwdW8YTwFXpFrLQtY2R7rNFm32T9?= =?us-ascii?Q?K6O0kAHO1wAk7zTDG+uToWQ7+t9RVl8x4Jyoxls?= =?us-ascii?Q?LupFnam+UosqLYBWO8wH+stFjBrTQeyKYXw=3D=3D?= To: ruby-core@ruby-lang.org X-ML-Name: ruby-core X-Mail-Count: 94399 Subject: [ruby-core:94399] [Ruby master Bug#10965] logger.rb may not daily rotate X-BeenThere: ruby-core@ruby-lang.org X-Mailman-Version: 2.1.15 Precedence: list Reply-To: Ruby developers List-Id: Ruby developers List-Unsubscribe: , List-Post: List-Help: List-Subscribe: , Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Errors-To: ruby-core-bounces@ruby-lang.org Sender: "ruby-core" 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/