mirror of
				https://github.com/python/cpython.git
				synced 2025-10-31 10:26:02 +00:00 
			
		
		
		
	gh-88352: Fix logging.TimedRotatingFileHandler (GH-116191)
* Do not overwrite already rolled over files. It happened at midnight or during the DST change and caused the loss of data. * computeRollover() now always return the timestamp larger than the specified time. * Fix computation of the rollover time during the DST change.
This commit is contained in:
		
							parent
							
								
									9b7f253b55
								
							
						
					
					
						commit
						fee86fd9a4
					
				
					 3 changed files with 373 additions and 32 deletions
				
			
		|  | @ -299,7 +299,7 @@ class TimedRotatingFileHandler(BaseRotatingHandler): | ||||||
| 
 | 
 | ||||||
|             r = rotate_ts - ((currentHour * 60 + currentMinute) * 60 + |             r = rotate_ts - ((currentHour * 60 + currentMinute) * 60 + | ||||||
|                 currentSecond) |                 currentSecond) | ||||||
|             if r < 0: |             if r <= 0: | ||||||
|                 # Rotate time is before the current time (for example when |                 # Rotate time is before the current time (for example when | ||||||
|                 # self.rotateAt is 13:45 and it now 14:15), rotation is |                 # self.rotateAt is 13:45 and it now 14:15), rotation is | ||||||
|                 # tomorrow. |                 # tomorrow. | ||||||
|  | @ -328,17 +328,18 @@ class TimedRotatingFileHandler(BaseRotatingHandler): | ||||||
|                         daysToWait = self.dayOfWeek - day |                         daysToWait = self.dayOfWeek - day | ||||||
|                     else: |                     else: | ||||||
|                         daysToWait = 6 - day + self.dayOfWeek + 1 |                         daysToWait = 6 - day + self.dayOfWeek + 1 | ||||||
|                     newRolloverAt = result + (daysToWait * (60 * 60 * 24)) |                     result += daysToWait * (60 * 60 * 24) | ||||||
|                     if not self.utc: |             if not self.utc: | ||||||
|                         dstNow = t[-1] |                 dstNow = t[-1] | ||||||
|                         dstAtRollover = time.localtime(newRolloverAt)[-1] |                 dstAtRollover = time.localtime(result)[-1] | ||||||
|                         if dstNow != dstAtRollover: |                 if dstNow != dstAtRollover: | ||||||
|                             if not dstNow:  # DST kicks in before next rollover, so we need to deduct an hour |                     if not dstNow:  # DST kicks in before next rollover, so we need to deduct an hour | ||||||
|                                 addend = -3600 |                         addend = -3600 | ||||||
|                             else:           # DST bows out before next rollover, so we need to add an hour |                         if not time.localtime(result-3600)[-1]: | ||||||
|                                 addend = 3600 |                             addend = 0 | ||||||
|                             newRolloverAt += addend |                     else:           # DST bows out before next rollover, so we need to add an hour | ||||||
|                     result = newRolloverAt |                         addend = 3600 | ||||||
|  |                     result += addend | ||||||
|         return result |         return result | ||||||
| 
 | 
 | ||||||
|     def shouldRollover(self, record): |     def shouldRollover(self, record): | ||||||
|  | @ -415,17 +416,14 @@ class TimedRotatingFileHandler(BaseRotatingHandler): | ||||||
|         then we have to get a list of matching filenames, sort them and remove |         then we have to get a list of matching filenames, sort them and remove | ||||||
|         the one with the oldest suffix. |         the one with the oldest suffix. | ||||||
|         """ |         """ | ||||||
|         if self.stream: |  | ||||||
|             self.stream.close() |  | ||||||
|             self.stream = None |  | ||||||
|         # get the time that this sequence started at and make it a TimeTuple |         # get the time that this sequence started at and make it a TimeTuple | ||||||
|         currentTime = int(time.time()) |         currentTime = int(time.time()) | ||||||
|         dstNow = time.localtime(currentTime)[-1] |  | ||||||
|         t = self.rolloverAt - self.interval |         t = self.rolloverAt - self.interval | ||||||
|         if self.utc: |         if self.utc: | ||||||
|             timeTuple = time.gmtime(t) |             timeTuple = time.gmtime(t) | ||||||
|         else: |         else: | ||||||
|             timeTuple = time.localtime(t) |             timeTuple = time.localtime(t) | ||||||
|  |             dstNow = time.localtime(currentTime)[-1] | ||||||
|             dstThen = timeTuple[-1] |             dstThen = timeTuple[-1] | ||||||
|             if dstNow != dstThen: |             if dstNow != dstThen: | ||||||
|                 if dstNow: |                 if dstNow: | ||||||
|  | @ -436,26 +434,19 @@ class TimedRotatingFileHandler(BaseRotatingHandler): | ||||||
|         dfn = self.rotation_filename(self.baseFilename + "." + |         dfn = self.rotation_filename(self.baseFilename + "." + | ||||||
|                                      time.strftime(self.suffix, timeTuple)) |                                      time.strftime(self.suffix, timeTuple)) | ||||||
|         if os.path.exists(dfn): |         if os.path.exists(dfn): | ||||||
|             os.remove(dfn) |             # Already rolled over. | ||||||
|  |             return | ||||||
|  | 
 | ||||||
|  |         if self.stream: | ||||||
|  |             self.stream.close() | ||||||
|  |             self.stream = None | ||||||
|         self.rotate(self.baseFilename, dfn) |         self.rotate(self.baseFilename, dfn) | ||||||
|         if self.backupCount > 0: |         if self.backupCount > 0: | ||||||
|             for s in self.getFilesToDelete(): |             for s in self.getFilesToDelete(): | ||||||
|                 os.remove(s) |                 os.remove(s) | ||||||
|         if not self.delay: |         if not self.delay: | ||||||
|             self.stream = self._open() |             self.stream = self._open() | ||||||
|         newRolloverAt = self.computeRollover(currentTime) |         self.rolloverAt = self.computeRollover(currentTime) | ||||||
|         while newRolloverAt <= currentTime: |  | ||||||
|             newRolloverAt = newRolloverAt + self.interval |  | ||||||
|         #If DST changes and midnight or weekly rollover, adjust for this. |  | ||||||
|         if (self.when == 'MIDNIGHT' or self.when.startswith('W')) and not self.utc: |  | ||||||
|             dstAtRollover = time.localtime(newRolloverAt)[-1] |  | ||||||
|             if dstNow != dstAtRollover: |  | ||||||
|                 if not dstNow:  # DST kicks in before next rollover, so we need to deduct an hour |  | ||||||
|                     addend = -3600 |  | ||||||
|                 else:           # DST bows out before next rollover, so we need to add an hour |  | ||||||
|                     addend = 3600 |  | ||||||
|                 newRolloverAt += addend |  | ||||||
|         self.rolloverAt = newRolloverAt |  | ||||||
| 
 | 
 | ||||||
| class WatchedFileHandler(logging.FileHandler): | class WatchedFileHandler(logging.FileHandler): | ||||||
|     """ |     """ | ||||||
|  |  | ||||||
|  | @ -6080,6 +6080,73 @@ class TimedRotatingFileHandlerTest(BaseFileTest): | ||||||
|                     print(tf.read()) |                     print(tf.read()) | ||||||
|         self.assertTrue(found, msg=msg) |         self.assertTrue(found, msg=msg) | ||||||
| 
 | 
 | ||||||
|  |     def test_rollover_at_midnight(self): | ||||||
|  |         atTime = datetime.datetime.now().time() | ||||||
|  |         fmt = logging.Formatter('%(asctime)s %(message)s') | ||||||
|  |         for i in range(3): | ||||||
|  |             fh = logging.handlers.TimedRotatingFileHandler( | ||||||
|  |                 self.fn, encoding="utf-8", when='MIDNIGHT', atTime=atTime) | ||||||
|  |             fh.setFormatter(fmt) | ||||||
|  |             r2 = logging.makeLogRecord({'msg': f'testing1 {i}'}) | ||||||
|  |             fh.emit(r2) | ||||||
|  |             fh.close() | ||||||
|  |         self.assertLogFile(self.fn) | ||||||
|  |         with open(self.fn, encoding="utf-8") as f: | ||||||
|  |             for i, line in enumerate(f): | ||||||
|  |                 self.assertIn(f'testing1 {i}', line) | ||||||
|  | 
 | ||||||
|  |         os.utime(self.fn, (time.time() - 1,)*2) | ||||||
|  |         for i in range(2): | ||||||
|  |             fh = logging.handlers.TimedRotatingFileHandler( | ||||||
|  |                 self.fn, encoding="utf-8", when='MIDNIGHT', atTime=atTime) | ||||||
|  |             fh.setFormatter(fmt) | ||||||
|  |             r2 = logging.makeLogRecord({'msg': f'testing2 {i}'}) | ||||||
|  |             fh.emit(r2) | ||||||
|  |             fh.close() | ||||||
|  |         rolloverDate = datetime.datetime.now() - datetime.timedelta(days=1) | ||||||
|  |         otherfn = f'{self.fn}.{rolloverDate:%Y-%m-%d}' | ||||||
|  |         self.assertLogFile(otherfn) | ||||||
|  |         with open(self.fn, encoding="utf-8") as f: | ||||||
|  |             for i, line in enumerate(f): | ||||||
|  |                 self.assertIn(f'testing2 {i}', line) | ||||||
|  |         with open(otherfn, encoding="utf-8") as f: | ||||||
|  |             for i, line in enumerate(f): | ||||||
|  |                 self.assertIn(f'testing1 {i}', line) | ||||||
|  | 
 | ||||||
|  |     def test_rollover_at_weekday(self): | ||||||
|  |         now = datetime.datetime.now() | ||||||
|  |         atTime = now.time() | ||||||
|  |         fmt = logging.Formatter('%(asctime)s %(message)s') | ||||||
|  |         for i in range(3): | ||||||
|  |             fh = logging.handlers.TimedRotatingFileHandler( | ||||||
|  |                 self.fn, encoding="utf-8", when=f'W{now.weekday()}', atTime=atTime) | ||||||
|  |             fh.setFormatter(fmt) | ||||||
|  |             r2 = logging.makeLogRecord({'msg': f'testing1 {i}'}) | ||||||
|  |             fh.emit(r2) | ||||||
|  |             fh.close() | ||||||
|  |         self.assertLogFile(self.fn) | ||||||
|  |         with open(self.fn, encoding="utf-8") as f: | ||||||
|  |             for i, line in enumerate(f): | ||||||
|  |                 self.assertIn(f'testing1 {i}', line) | ||||||
|  | 
 | ||||||
|  |         os.utime(self.fn, (time.time() - 1,)*2) | ||||||
|  |         for i in range(2): | ||||||
|  |             fh = logging.handlers.TimedRotatingFileHandler( | ||||||
|  |                 self.fn, encoding="utf-8", when=f'W{now.weekday()}', atTime=atTime) | ||||||
|  |             fh.setFormatter(fmt) | ||||||
|  |             r2 = logging.makeLogRecord({'msg': f'testing2 {i}'}) | ||||||
|  |             fh.emit(r2) | ||||||
|  |             fh.close() | ||||||
|  |         rolloverDate = datetime.datetime.now() - datetime.timedelta(days=7) | ||||||
|  |         otherfn = f'{self.fn}.{rolloverDate:%Y-%m-%d}' | ||||||
|  |         self.assertLogFile(otherfn) | ||||||
|  |         with open(self.fn, encoding="utf-8") as f: | ||||||
|  |             for i, line in enumerate(f): | ||||||
|  |                 self.assertIn(f'testing2 {i}', line) | ||||||
|  |         with open(otherfn, encoding="utf-8") as f: | ||||||
|  |             for i, line in enumerate(f): | ||||||
|  |                 self.assertIn(f'testing1 {i}', line) | ||||||
|  | 
 | ||||||
|     def test_invalid(self): |     def test_invalid(self): | ||||||
|         assertRaises = self.assertRaises |         assertRaises = self.assertRaises | ||||||
|         assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler, |         assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler, | ||||||
|  | @ -6089,22 +6156,47 @@ class TimedRotatingFileHandlerTest(BaseFileTest): | ||||||
|         assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler, |         assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler, | ||||||
|                      self.fn, 'W7', encoding="utf-8", delay=True) |                      self.fn, 'W7', encoding="utf-8", delay=True) | ||||||
| 
 | 
 | ||||||
|  |     # TODO: Test for utc=False. | ||||||
|     def test_compute_rollover_daily_attime(self): |     def test_compute_rollover_daily_attime(self): | ||||||
|         currentTime = 0 |         currentTime = 0 | ||||||
|  |         rh = logging.handlers.TimedRotatingFileHandler( | ||||||
|  |             self.fn, encoding="utf-8", when='MIDNIGHT', | ||||||
|  |             utc=True, atTime=None) | ||||||
|  |         try: | ||||||
|  |             actual = rh.computeRollover(currentTime) | ||||||
|  |             self.assertEqual(actual, currentTime + 24 * 60 * 60) | ||||||
|  | 
 | ||||||
|  |             actual = rh.computeRollover(currentTime + 24 * 60 * 60 - 1) | ||||||
|  |             self.assertEqual(actual, currentTime + 24 * 60 * 60) | ||||||
|  | 
 | ||||||
|  |             actual = rh.computeRollover(currentTime + 24 * 60 * 60) | ||||||
|  |             self.assertEqual(actual, currentTime + 48 * 60 * 60) | ||||||
|  | 
 | ||||||
|  |             actual = rh.computeRollover(currentTime + 25 * 60 * 60) | ||||||
|  |             self.assertEqual(actual, currentTime + 48 * 60 * 60) | ||||||
|  |         finally: | ||||||
|  |             rh.close() | ||||||
|  | 
 | ||||||
|         atTime = datetime.time(12, 0, 0) |         atTime = datetime.time(12, 0, 0) | ||||||
|         rh = logging.handlers.TimedRotatingFileHandler( |         rh = logging.handlers.TimedRotatingFileHandler( | ||||||
|             self.fn, encoding="utf-8", when='MIDNIGHT', interval=1, backupCount=0, |             self.fn, encoding="utf-8", when='MIDNIGHT', | ||||||
|             utc=True, atTime=atTime) |             utc=True, atTime=atTime) | ||||||
|         try: |         try: | ||||||
|             actual = rh.computeRollover(currentTime) |             actual = rh.computeRollover(currentTime) | ||||||
|             self.assertEqual(actual, currentTime + 12 * 60 * 60) |             self.assertEqual(actual, currentTime + 12 * 60 * 60) | ||||||
| 
 | 
 | ||||||
|  |             actual = rh.computeRollover(currentTime + 12 * 60 * 60 - 1) | ||||||
|  |             self.assertEqual(actual, currentTime + 12 * 60 * 60) | ||||||
|  | 
 | ||||||
|  |             actual = rh.computeRollover(currentTime + 12 * 60 * 60) | ||||||
|  |             self.assertEqual(actual, currentTime + 36 * 60 * 60) | ||||||
|  | 
 | ||||||
|             actual = rh.computeRollover(currentTime + 13 * 60 * 60) |             actual = rh.computeRollover(currentTime + 13 * 60 * 60) | ||||||
|             self.assertEqual(actual, currentTime + 36 * 60 * 60) |             self.assertEqual(actual, currentTime + 36 * 60 * 60) | ||||||
|         finally: |         finally: | ||||||
|             rh.close() |             rh.close() | ||||||
| 
 | 
 | ||||||
|     #@unittest.skipIf(True, 'Temporarily skipped while failures investigated.') |     # TODO: Test for utc=False. | ||||||
|     def test_compute_rollover_weekly_attime(self): |     def test_compute_rollover_weekly_attime(self): | ||||||
|         currentTime = int(time.time()) |         currentTime = int(time.time()) | ||||||
|         today = currentTime - currentTime % 86400 |         today = currentTime - currentTime % 86400 | ||||||
|  | @ -6129,14 +6221,28 @@ class TimedRotatingFileHandlerTest(BaseFileTest): | ||||||
|                 expected += 12 * 60 * 60 |                 expected += 12 * 60 * 60 | ||||||
|                 # Add in adjustment for today |                 # Add in adjustment for today | ||||||
|                 expected += today |                 expected += today | ||||||
|  | 
 | ||||||
|                 actual = rh.computeRollover(today) |                 actual = rh.computeRollover(today) | ||||||
|                 if actual != expected: |                 if actual != expected: | ||||||
|                     print('failed in timezone: %d' % time.timezone) |                     print('failed in timezone: %d' % time.timezone) | ||||||
|                     print('local vars: %s' % locals()) |                     print('local vars: %s' % locals()) | ||||||
|                 self.assertEqual(actual, expected) |                 self.assertEqual(actual, expected) | ||||||
|  | 
 | ||||||
|  |                 actual = rh.computeRollover(today + 12 * 60 * 60 - 1) | ||||||
|  |                 if actual != expected: | ||||||
|  |                     print('failed in timezone: %d' % time.timezone) | ||||||
|  |                     print('local vars: %s' % locals()) | ||||||
|  |                 self.assertEqual(actual, expected) | ||||||
|  | 
 | ||||||
|                 if day == wday: |                 if day == wday: | ||||||
|                     # goes into following week |                     # goes into following week | ||||||
|                     expected += 7 * 24 * 60 * 60 |                     expected += 7 * 24 * 60 * 60 | ||||||
|  |                 actual = rh.computeRollover(today + 12 * 60 * 60) | ||||||
|  |                 if actual != expected: | ||||||
|  |                     print('failed in timezone: %d' % time.timezone) | ||||||
|  |                     print('local vars: %s' % locals()) | ||||||
|  |                 self.assertEqual(actual, expected) | ||||||
|  | 
 | ||||||
|                 actual = rh.computeRollover(today + 13 * 60 * 60) |                 actual = rh.computeRollover(today + 13 * 60 * 60) | ||||||
|                 if actual != expected: |                 if actual != expected: | ||||||
|                     print('failed in timezone: %d' % time.timezone) |                     print('failed in timezone: %d' % time.timezone) | ||||||
|  | @ -6231,6 +6337,244 @@ class TimedRotatingFileHandlerTest(BaseFileTest): | ||||||
|                 suffix = fn[(len(prefix)+1):] |                 suffix = fn[(len(prefix)+1):] | ||||||
|                 self.assertRegex(suffix, matcher) |                 self.assertRegex(suffix, matcher) | ||||||
| 
 | 
 | ||||||
|  |     # Run with US-style DST rules: DST begins 2 a.m. on second Sunday in | ||||||
|  |     # March (M3.2.0) and ends 2 a.m. on first Sunday in November (M11.1.0). | ||||||
|  |     @support.run_with_tz('EST+05EDT,M3.2.0,M11.1.0') | ||||||
|  |     def test_compute_rollover_MIDNIGHT_local(self): | ||||||
|  |         # DST begins at 2012-3-11T02:00:00 and ends at 2012-11-4T02:00:00. | ||||||
|  |         DT = datetime.datetime | ||||||
|  |         def test(current, expected): | ||||||
|  |             actual = fh.computeRollover(current.timestamp()) | ||||||
|  |             diff = actual - expected.timestamp() | ||||||
|  |             if diff: | ||||||
|  |                 self.assertEqual(diff, 0, datetime.timedelta(seconds=diff)) | ||||||
|  | 
 | ||||||
|  |         fh = logging.handlers.TimedRotatingFileHandler( | ||||||
|  |             self.fn, encoding="utf-8", when='MIDNIGHT', utc=False) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 3, 10, 23, 59, 59), DT(2012, 3, 11, 0, 0)) | ||||||
|  |         test(DT(2012, 3, 11, 0, 0), DT(2012, 3, 12, 0, 0)) | ||||||
|  |         test(DT(2012, 3, 11, 1, 0), DT(2012, 3, 12, 0, 0)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 11, 3, 23, 59, 59), DT(2012, 11, 4, 0, 0)) | ||||||
|  |         test(DT(2012, 11, 4, 0, 0), DT(2012, 11, 5, 0, 0)) | ||||||
|  |         test(DT(2012, 11, 4, 1, 0), DT(2012, 11, 5, 0, 0)) | ||||||
|  | 
 | ||||||
|  |         fh.close() | ||||||
|  | 
 | ||||||
|  |         fh = logging.handlers.TimedRotatingFileHandler( | ||||||
|  |             self.fn, encoding="utf-8", when='MIDNIGHT', utc=False, | ||||||
|  |             atTime=datetime.time(12, 0, 0)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 3, 10, 11, 59, 59), DT(2012, 3, 10, 12, 0)) | ||||||
|  |         test(DT(2012, 3, 10, 12, 0), DT(2012, 3, 11, 12, 0)) | ||||||
|  |         test(DT(2012, 3, 10, 13, 0), DT(2012, 3, 11, 12, 0)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 11, 3, 11, 59, 59), DT(2012, 11, 3, 12, 0)) | ||||||
|  |         test(DT(2012, 11, 3, 12, 0), DT(2012, 11, 4, 12, 0)) | ||||||
|  |         test(DT(2012, 11, 3, 13, 0), DT(2012, 11, 4, 12, 0)) | ||||||
|  | 
 | ||||||
|  |         fh.close() | ||||||
|  | 
 | ||||||
|  |         fh = logging.handlers.TimedRotatingFileHandler( | ||||||
|  |             self.fn, encoding="utf-8", when='MIDNIGHT', utc=False, | ||||||
|  |             atTime=datetime.time(2, 0, 0)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 3, 10, 1, 59, 59), DT(2012, 3, 10, 2, 0)) | ||||||
|  |         # 2:00:00 is the same as 3:00:00 at 2012-3-11. | ||||||
|  |         test(DT(2012, 3, 10, 2, 0), DT(2012, 3, 11, 3, 0)) | ||||||
|  |         test(DT(2012, 3, 10, 3, 0), DT(2012, 3, 11, 3, 0)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 3, 11, 1, 59, 59), DT(2012, 3, 11, 3, 0)) | ||||||
|  |         # No time between 2:00:00 and 3:00:00 at 2012-3-11. | ||||||
|  |         test(DT(2012, 3, 11, 3, 0), DT(2012, 3, 12, 2, 0)) | ||||||
|  |         test(DT(2012, 3, 11, 4, 0), DT(2012, 3, 12, 2, 0)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 11, 3, 1, 59, 59), DT(2012, 11, 3, 2, 0)) | ||||||
|  |         test(DT(2012, 11, 3, 2, 0), DT(2012, 11, 4, 2, 0)) | ||||||
|  |         test(DT(2012, 11, 3, 3, 0), DT(2012, 11, 4, 2, 0)) | ||||||
|  | 
 | ||||||
|  |         # 1:00:00-2:00:00 is repeated twice at 2012-11-4. | ||||||
|  |         test(DT(2012, 11, 4, 1, 59, 59), DT(2012, 11, 4, 2, 0)) | ||||||
|  |         test(DT(2012, 11, 4, 1, 59, 59, fold=1), DT(2012, 11, 4, 2, 0)) | ||||||
|  |         test(DT(2012, 11, 4, 2, 0), DT(2012, 11, 5, 2, 0)) | ||||||
|  |         test(DT(2012, 11, 4, 3, 0), DT(2012, 11, 5, 2, 0)) | ||||||
|  | 
 | ||||||
|  |         fh.close() | ||||||
|  | 
 | ||||||
|  |         fh = logging.handlers.TimedRotatingFileHandler( | ||||||
|  |             self.fn, encoding="utf-8", when='MIDNIGHT', utc=False, | ||||||
|  |             atTime=datetime.time(2, 30, 0)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 3, 10, 2, 29, 59), DT(2012, 3, 10, 2, 30)) | ||||||
|  |         # No time 2:30:00 at 2012-3-11. | ||||||
|  |         test(DT(2012, 3, 10, 2, 30), DT(2012, 3, 11, 3, 30)) | ||||||
|  |         test(DT(2012, 3, 10, 3, 0), DT(2012, 3, 11, 3, 30)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 3, 11, 1, 59, 59), DT(2012, 3, 11, 3, 30)) | ||||||
|  |         # No time between 2:00:00 and 3:00:00 at 2012-3-11. | ||||||
|  |         test(DT(2012, 3, 11, 3, 0), DT(2012, 3, 12, 2, 30)) | ||||||
|  |         test(DT(2012, 3, 11, 3, 30), DT(2012, 3, 12, 2, 30)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 11, 3, 2, 29, 59), DT(2012, 11, 3, 2, 30)) | ||||||
|  |         test(DT(2012, 11, 3, 2, 30), DT(2012, 11, 4, 2, 30)) | ||||||
|  |         test(DT(2012, 11, 3, 3, 0), DT(2012, 11, 4, 2, 30)) | ||||||
|  | 
 | ||||||
|  |         fh.close() | ||||||
|  | 
 | ||||||
|  |         fh = logging.handlers.TimedRotatingFileHandler( | ||||||
|  |             self.fn, encoding="utf-8", when='MIDNIGHT', utc=False, | ||||||
|  |             atTime=datetime.time(1, 30, 0)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 3, 11, 1, 29, 59), DT(2012, 3, 11, 1, 30)) | ||||||
|  |         test(DT(2012, 3, 11, 1, 30), DT(2012, 3, 12, 1, 30)) | ||||||
|  |         test(DT(2012, 3, 11, 1, 59, 59), DT(2012, 3, 12, 1, 30)) | ||||||
|  |         # No time between 2:00:00 and 3:00:00 at 2012-3-11. | ||||||
|  |         test(DT(2012, 3, 11, 3, 0), DT(2012, 3, 12, 1, 30)) | ||||||
|  |         test(DT(2012, 3, 11, 3, 30), DT(2012, 3, 12, 1, 30)) | ||||||
|  | 
 | ||||||
|  |         # 1:00:00-2:00:00 is repeated twice at 2012-11-4. | ||||||
|  |         test(DT(2012, 11, 4, 1, 0), DT(2012, 11, 4, 1, 30)) | ||||||
|  |         test(DT(2012, 11, 4, 1, 29, 59), DT(2012, 11, 4, 1, 30)) | ||||||
|  |         test(DT(2012, 11, 4, 1, 30), DT(2012, 11, 5, 1, 30)) | ||||||
|  |         test(DT(2012, 11, 4, 1, 59, 59), DT(2012, 11, 5, 1, 30)) | ||||||
|  |         # It is weird, but the rollover date jumps back from 2012-11-5 | ||||||
|  |         # to 2012-11-4. | ||||||
|  |         test(DT(2012, 11, 4, 1, 0, fold=1), DT(2012, 11, 4, 1, 30, fold=1)) | ||||||
|  |         test(DT(2012, 11, 4, 1, 29, 59, fold=1), DT(2012, 11, 4, 1, 30, fold=1)) | ||||||
|  |         test(DT(2012, 11, 4, 1, 30, fold=1), DT(2012, 11, 5, 1, 30)) | ||||||
|  |         test(DT(2012, 11, 4, 1, 59, 59, fold=1), DT(2012, 11, 5, 1, 30)) | ||||||
|  |         test(DT(2012, 11, 4, 2, 0), DT(2012, 11, 5, 1, 30)) | ||||||
|  |         test(DT(2012, 11, 4, 2, 30), DT(2012, 11, 5, 1, 30)) | ||||||
|  | 
 | ||||||
|  |         fh.close() | ||||||
|  | 
 | ||||||
|  |     # Run with US-style DST rules: DST begins 2 a.m. on second Sunday in | ||||||
|  |     # March (M3.2.0) and ends 2 a.m. on first Sunday in November (M11.1.0). | ||||||
|  |     @support.run_with_tz('EST+05EDT,M3.2.0,M11.1.0') | ||||||
|  |     def test_compute_rollover_W6_local(self): | ||||||
|  |         # DST begins at 2012-3-11T02:00:00 and ends at 2012-11-4T02:00:00. | ||||||
|  |         DT = datetime.datetime | ||||||
|  |         def test(current, expected): | ||||||
|  |             actual = fh.computeRollover(current.timestamp()) | ||||||
|  |             diff = actual - expected.timestamp() | ||||||
|  |             if diff: | ||||||
|  |                 self.assertEqual(diff, 0, datetime.timedelta(seconds=diff)) | ||||||
|  | 
 | ||||||
|  |         fh = logging.handlers.TimedRotatingFileHandler( | ||||||
|  |             self.fn, encoding="utf-8", when='W6', utc=False) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 3, 4, 23, 59, 59), DT(2012, 3, 5, 0, 0)) | ||||||
|  |         test(DT(2012, 3, 5, 0, 0), DT(2012, 3, 12, 0, 0)) | ||||||
|  |         test(DT(2012, 3, 5, 1, 0), DT(2012, 3, 12, 0, 0)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 10, 28, 23, 59, 59), DT(2012, 10, 29, 0, 0)) | ||||||
|  |         test(DT(2012, 10, 29, 0, 0), DT(2012, 11, 5, 0, 0)) | ||||||
|  |         test(DT(2012, 10, 29, 1, 0), DT(2012, 11, 5, 0, 0)) | ||||||
|  | 
 | ||||||
|  |         fh.close() | ||||||
|  | 
 | ||||||
|  |         fh = logging.handlers.TimedRotatingFileHandler( | ||||||
|  |             self.fn, encoding="utf-8", when='W6', utc=False, | ||||||
|  |             atTime=datetime.time(0, 0, 0)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 3, 10, 23, 59, 59), DT(2012, 3, 11, 0, 0)) | ||||||
|  |         test(DT(2012, 3, 11, 0, 0), DT(2012, 3, 18, 0, 0)) | ||||||
|  |         test(DT(2012, 3, 11, 1, 0), DT(2012, 3, 18, 0, 0)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 11, 3, 23, 59, 59), DT(2012, 11, 4, 0, 0)) | ||||||
|  |         test(DT(2012, 11, 4, 0, 0), DT(2012, 11, 11, 0, 0)) | ||||||
|  |         test(DT(2012, 11, 4, 1, 0), DT(2012, 11, 11, 0, 0)) | ||||||
|  | 
 | ||||||
|  |         fh.close() | ||||||
|  | 
 | ||||||
|  |         fh = logging.handlers.TimedRotatingFileHandler( | ||||||
|  |             self.fn, encoding="utf-8", when='W6', utc=False, | ||||||
|  |             atTime=datetime.time(12, 0, 0)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 3, 4, 11, 59, 59), DT(2012, 3, 4, 12, 0)) | ||||||
|  |         test(DT(2012, 3, 4, 12, 0), DT(2012, 3, 11, 12, 0)) | ||||||
|  |         test(DT(2012, 3, 4, 13, 0), DT(2012, 3, 11, 12, 0)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 10, 28, 11, 59, 59), DT(2012, 10, 28, 12, 0)) | ||||||
|  |         test(DT(2012, 10, 28, 12, 0), DT(2012, 11, 4, 12, 0)) | ||||||
|  |         test(DT(2012, 10, 28, 13, 0), DT(2012, 11, 4, 12, 0)) | ||||||
|  | 
 | ||||||
|  |         fh.close() | ||||||
|  | 
 | ||||||
|  |         fh = logging.handlers.TimedRotatingFileHandler( | ||||||
|  |             self.fn, encoding="utf-8", when='W6', utc=False, | ||||||
|  |             atTime=datetime.time(2, 0, 0)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 3, 4, 1, 59, 59), DT(2012, 3, 4, 2, 0)) | ||||||
|  |         # 2:00:00 is the same as 3:00:00 at 2012-3-11. | ||||||
|  |         test(DT(2012, 3, 4, 2, 0), DT(2012, 3, 11, 3, 0)) | ||||||
|  |         test(DT(2012, 3, 4, 3, 0), DT(2012, 3, 11, 3, 0)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 3, 11, 1, 59, 59), DT(2012, 3, 11, 3, 0)) | ||||||
|  |         # No time between 2:00:00 and 3:00:00 at 2012-3-11. | ||||||
|  |         test(DT(2012, 3, 11, 3, 0), DT(2012, 3, 18, 2, 0)) | ||||||
|  |         test(DT(2012, 3, 11, 4, 0), DT(2012, 3, 18, 2, 0)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 10, 28, 1, 59, 59), DT(2012, 10, 28, 2, 0)) | ||||||
|  |         test(DT(2012, 10, 28, 2, 0), DT(2012, 11, 4, 2, 0)) | ||||||
|  |         test(DT(2012, 10, 28, 3, 0), DT(2012, 11, 4, 2, 0)) | ||||||
|  | 
 | ||||||
|  |         # 1:00:00-2:00:00 is repeated twice at 2012-11-4. | ||||||
|  |         test(DT(2012, 11, 4, 1, 59, 59), DT(2012, 11, 4, 2, 0)) | ||||||
|  |         test(DT(2012, 11, 4, 1, 59, 59, fold=1), DT(2012, 11, 4, 2, 0)) | ||||||
|  |         test(DT(2012, 11, 4, 2, 0), DT(2012, 11, 11, 2, 0)) | ||||||
|  |         test(DT(2012, 11, 4, 3, 0), DT(2012, 11, 11, 2, 0)) | ||||||
|  | 
 | ||||||
|  |         fh.close() | ||||||
|  | 
 | ||||||
|  |         fh = logging.handlers.TimedRotatingFileHandler( | ||||||
|  |             self.fn, encoding="utf-8", when='W6', utc=False, | ||||||
|  |             atTime=datetime.time(2, 30, 0)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 3, 4, 2, 29, 59), DT(2012, 3, 4, 2, 30)) | ||||||
|  |         # No time 2:30:00 at 2012-3-11. | ||||||
|  |         test(DT(2012, 3, 4, 2, 30), DT(2012, 3, 11, 3, 30)) | ||||||
|  |         test(DT(2012, 3, 4, 3, 0), DT(2012, 3, 11, 3, 30)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 3, 11, 1, 59, 59), DT(2012, 3, 11, 3, 30)) | ||||||
|  |         # No time between 2:00:00 and 3:00:00 at 2012-3-11. | ||||||
|  |         test(DT(2012, 3, 11, 3, 0), DT(2012, 3, 18, 2, 30)) | ||||||
|  |         test(DT(2012, 3, 11, 3, 30), DT(2012, 3, 18, 2, 30)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 10, 28, 2, 29, 59), DT(2012, 10, 28, 2, 30)) | ||||||
|  |         test(DT(2012, 10, 28, 2, 30), DT(2012, 11, 4, 2, 30)) | ||||||
|  |         test(DT(2012, 10, 28, 3, 0), DT(2012, 11, 4, 2, 30)) | ||||||
|  | 
 | ||||||
|  |         fh.close() | ||||||
|  | 
 | ||||||
|  |         fh = logging.handlers.TimedRotatingFileHandler( | ||||||
|  |             self.fn, encoding="utf-8", when='W6', utc=False, | ||||||
|  |             atTime=datetime.time(1, 30, 0)) | ||||||
|  | 
 | ||||||
|  |         test(DT(2012, 3, 11, 1, 29, 59), DT(2012, 3, 11, 1, 30)) | ||||||
|  |         test(DT(2012, 3, 11, 1, 30), DT(2012, 3, 18, 1, 30)) | ||||||
|  |         test(DT(2012, 3, 11, 1, 59, 59), DT(2012, 3, 18, 1, 30)) | ||||||
|  |         # No time between 2:00:00 and 3:00:00 at 2012-3-11. | ||||||
|  |         test(DT(2012, 3, 11, 3, 0), DT(2012, 3, 18, 1, 30)) | ||||||
|  |         test(DT(2012, 3, 11, 3, 30), DT(2012, 3, 18, 1, 30)) | ||||||
|  | 
 | ||||||
|  |         # 1:00:00-2:00:00 is repeated twice at 2012-11-4. | ||||||
|  |         test(DT(2012, 11, 4, 1, 0), DT(2012, 11, 4, 1, 30)) | ||||||
|  |         test(DT(2012, 11, 4, 1, 29, 59), DT(2012, 11, 4, 1, 30)) | ||||||
|  |         test(DT(2012, 11, 4, 1, 30), DT(2012, 11, 11, 1, 30)) | ||||||
|  |         test(DT(2012, 11, 4, 1, 59, 59), DT(2012, 11, 11, 1, 30)) | ||||||
|  |         # It is weird, but the rollover date jumps back from 2012-11-11 | ||||||
|  |         # to 2012-11-4. | ||||||
|  |         test(DT(2012, 11, 4, 1, 0, fold=1), DT(2012, 11, 4, 1, 30, fold=1)) | ||||||
|  |         test(DT(2012, 11, 4, 1, 29, 59, fold=1), DT(2012, 11, 4, 1, 30, fold=1)) | ||||||
|  |         test(DT(2012, 11, 4, 1, 30, fold=1), DT(2012, 11, 11, 1, 30)) | ||||||
|  |         test(DT(2012, 11, 4, 1, 59, 59, fold=1), DT(2012, 11, 11, 1, 30)) | ||||||
|  |         test(DT(2012, 11, 4, 2, 0), DT(2012, 11, 11, 1, 30)) | ||||||
|  |         test(DT(2012, 11, 4, 2, 30), DT(2012, 11, 11, 1, 30)) | ||||||
|  | 
 | ||||||
|  |         fh.close() | ||||||
|  | 
 | ||||||
| def secs(**kw): | def secs(**kw): | ||||||
|     return datetime.timedelta(**kw) // datetime.timedelta(seconds=1) |     return datetime.timedelta(**kw) // datetime.timedelta(seconds=1) | ||||||
| 
 | 
 | ||||||
|  |  | ||||||
|  | @ -0,0 +1,6 @@ | ||||||
|  | Fix the computation of the next rollover time in the | ||||||
|  | :class:`logging.TimedRotatingFileHandler` handler. :meth:`!computeRollover` | ||||||
|  | now always returns a timestamp larger than the specified time and works | ||||||
|  | correctly during the DST change. :meth:`!doRollover` no longer overwrite the | ||||||
|  | already rolled over file, saving from data loss when run at midnight or | ||||||
|  | during repeated time at the DST change. | ||||||
		Loading…
	
	Add table
		Add a link
		
	
		Reference in a new issue
	
	 Serhiy Storchaka
						Serhiy Storchaka