U4-6320 - Log "Scrubbed" Several Times a Minute

Created by Nicholas Westby 24 Feb 2015, 16:56:53 Updated by Stephan 16 Mar 2015, 08:17:09

Not sure what it means by this, but I have a ton of these entries in my UmbracoTraceLog.txt file after upgrading from 7.1.8 to 7.2.2:

2015-02-24 16:05:25,557 [58] INFO umbraco.BusinessLogic.Log - [Thread 170] Log scrubbed. Removed all items older than 2014-12-26 16:05:24 2015-02-24 16:06:51,067 [44] INFO umbraco.BusinessLogic.Log - [Thread 196] Log scrubbed. Removed all items older than 2014-12-26 16:06:50 2015-02-24 16:06:52,232 [58] INFO umbraco.BusinessLogic.Log - [Thread 98] Log scrubbed. Removed all items older than 2014-12-26 16:06:52 2015-02-24 16:08:18,538 [44] INFO umbraco.BusinessLogic.Log - [Thread 171] Log scrubbed. Removed all items older than 2014-12-26 16:08:17 2015-02-24 16:08:19,003 [58] INFO umbraco.BusinessLogic.Log - [Thread 170] Log scrubbed. Removed all items older than 2014-12-26 16:08:18 2015-02-24 16:09:45,779 [58] INFO umbraco.BusinessLogic.Log - [Thread 196] Log scrubbed. Removed all items older than 2014-12-26 16:09:45 2015-02-24 16:09:45,615 [44] INFO umbraco.BusinessLogic.Log - [Thread 204] Log scrubbed. Removed all items older than 2014-12-26 16:09:45 2015-02-24 16:11:11,801 [44] INFO umbraco.BusinessLogic.Log - [Thread 204] Log scrubbed. Removed all items older than 2014-12-26 16:11:11 2015-02-24 16:11:14,969 [58] INFO umbraco.BusinessLogic.Log - [Thread 171] Log scrubbed. Removed all items older than 2014-12-26 16:11:12 2015-02-24 16:12:38,998 [44] INFO umbraco.BusinessLogic.Log - [Thread 162] Log scrubbed. Removed all items older than 2014-12-26 16:12:38 2015-02-24 16:12:40,172 [58] INFO umbraco.BusinessLogic.Log - [Thread 172] Log scrubbed. Removed all items older than 2014-12-26 16:12:39 2015-02-24 16:14:06,262 [44] INFO umbraco.BusinessLogic.Log - [Thread 172] Log scrubbed. Removed all items older than 2014-12-26 16:14:06 2015-02-24 16:14:06,891 [58] INFO umbraco.BusinessLogic.Log - [Thread 98] Log scrubbed. Removed all items older than 2014-12-26 16:14:06 2015-02-24 16:15:32,970 [44] INFO umbraco.BusinessLogic.Log - [Thread 98] Log scrubbed. Removed all items older than 2014-12-26 16:15:32 2015-02-24 16:15:34,870 [58] INFO umbraco.BusinessLogic.Log - [Thread 176] Log scrubbed. Removed all items older than 2014-12-26 16:15:34 2015-02-24 16:17:00,252 [44] INFO umbraco.BusinessLogic.Log - [Thread 170] Log scrubbed. Removed all items older than 2014-12-26 16:16:59 2015-02-24 16:17:02,172 [58] INFO umbraco.BusinessLogic.Log - [Thread 196] Log scrubbed. Removed all items older than 2014-12-26 16:17:01 2015-02-24 16:18:29,273 [44] INFO umbraco.BusinessLogic.Log - [Thread 162] Log scrubbed. Removed all items older than 2014-12-26 16:18:28 2015-02-24 16:18:30,285 [58] INFO umbraco.BusinessLogic.Log - [Thread 169] Log scrubbed. Removed all items older than 2014-12-26 16:18:29 2015-02-24 16:19:56,559 [44] INFO umbraco.BusinessLogic.Log - [Thread 98] Log scrubbed. Removed all items older than 2014-12-26 16:19:55 2015-02-24 16:19:58,399 [58] INFO umbraco.BusinessLogic.Log - [Thread 167] Log scrubbed. Removed all items older than 2014-12-26 16:19:58 2015-02-24 16:21:23,853 [44] INFO umbraco.BusinessLogic.Log - [Thread 165] Log scrubbed. Removed all items older than 2014-12-26 16:21:22 2015-02-24 16:21:25,070 [58] INFO umbraco.BusinessLogic.Log - [Thread 98] Log scrubbed. Removed all items older than 2014-12-26 16:21:25 2015-02-24 16:22:50,091 [44] INFO umbraco.BusinessLogic.Log - [Thread 172] Log scrubbed. Removed all items older than 2014-12-26 16:22:49 2015-02-24 16:22:53,511 [58] INFO umbraco.BusinessLogic.Log - [Thread 172] Log scrubbed. Removed all items older than 2014-12-26 16:22:53 2015-02-24 16:24:19,627 [44] INFO umbraco.BusinessLogic.Log - [Thread 196] Log scrubbed. Removed all items older than 2014-12-26 16:24:19 2015-02-24 16:24:21,981 [58] INFO umbraco.BusinessLogic.Log - [Thread 162] Log scrubbed. Removed all items older than 2014-12-26 16:24:20 2015-02-24 16:25:46,309 [44] INFO umbraco.BusinessLogic.Log - [Thread 172] Log scrubbed. Removed all items older than 2014-12-26 16:25:45 2015-02-24 16:25:50,444 [58] INFO umbraco.BusinessLogic.Log - [Thread 98] Log scrubbed. Removed all items older than 2014-12-26 16:25:49 2015-02-24 16:27:12,991 [44] INFO umbraco.BusinessLogic.Log - [Thread 164] Log scrubbed. Removed all items older than 2014-12-26 16:27:12 2015-02-24 16:27:17,277 [58] INFO umbraco.BusinessLogic.Log - [Thread 164] Log scrubbed. Removed all items older than 2014-12-26 16:27:16 2015-02-24 16:28:40,850 [44] INFO umbraco.BusinessLogic.Log - [Thread 202] Log scrubbed. Removed all items older than 2014-12-26 16:28:40 2015-02-24 16:28:44,436 [58] INFO umbraco.BusinessLogic.Log - [Thread 164] Log scrubbed. Removed all items older than 2014-12-26 16:28:44 2015-02-24 16:30:08,175 [44] INFO umbraco.BusinessLogic.Log - [Thread 202] Log scrubbed. Removed all items older than 2014-12-26 16:30:07 2015-02-24 16:30:11,729 [58] INFO umbraco.BusinessLogic.Log - [Thread 202] Log scrubbed. Removed all items older than 2014-12-26 16:30:11 2015-02-24 16:31:34,807 [44] INFO umbraco.BusinessLogic.Log - [Thread 209] Log scrubbed. Removed all items older than 2014-12-26 16:31:34 2015-02-24 16:31:39,582 [58] INFO umbraco.BusinessLogic.Log - [Thread 202] Log scrubbed. Removed all items older than 2014-12-26 16:31:38 2015-02-24 16:33:01,579 [44] INFO umbraco.BusinessLogic.Log - [Thread 193] Log scrubbed. Removed all items older than 2014-12-26 16:33:01 2015-02-24 16:33:06,880 [58] INFO umbraco.BusinessLogic.Log - [Thread 203] Log scrubbed. Removed all items older than 2014-12-26 16:33:06 2015-02-24 16:34:29,396 [44] INFO umbraco.BusinessLogic.Log - [Thread 202] Log scrubbed. Removed all items older than 2014-12-26 16:34:28 2015-02-24 16:34:33,540 [58] INFO umbraco.BusinessLogic.Log - [Thread 202] Log scrubbed. Removed all items older than 2014-12-26 16:34:33 2015-02-24 16:35:57,584 [44] INFO umbraco.BusinessLogic.Log - [Thread 17] Log scrubbed. Removed all items older than 2014-12-26 16:35:56 2015-02-24 16:36:00,234 [58] INFO umbraco.BusinessLogic.Log - [Thread 81] Log scrubbed. Removed all items older than 2014-12-26 16:35:59 2015-02-24 16:37:23,637 [44] INFO umbraco.BusinessLogic.Log - [Thread 70] Log scrubbed. Removed all items older than 2014-12-26 16:37:22 2015-02-24 16:37:27,000 [58] INFO umbraco.BusinessLogic.Log - [Thread 70] Log scrubbed. Removed all items older than 2014-12-26 16:37:26 2015-02-24 16:38:51,296 [44] INFO umbraco.BusinessLogic.Log - [Thread 70] Log scrubbed. Removed all items older than 2014-12-26 16:38:50 2015-02-24 16:38:54,840 [58] INFO umbraco.BusinessLogic.Log - [Thread 70] Log scrubbed. Removed all items older than 2014-12-26 16:38:54 2015-02-24 16:40:19,255 [44] INFO umbraco.BusinessLogic.Log - [Thread 163] Log scrubbed. Removed all items older than 2014-12-26 16:40:19 2015-02-24 16:40:21,568 [58] INFO umbraco.BusinessLogic.Log - [Thread 163] Log scrubbed. Removed all items older than 2014-12-26 16:40:21 2015-02-24 16:41:47,587 [44] INFO umbraco.BusinessLogic.Log - [Thread 207] Log scrubbed. Removed all items older than 2014-12-26 16:41:46 2015-02-24 16:41:48,319 [58] INFO umbraco.BusinessLogic.Log - [Thread 207] Log scrubbed. Removed all items older than 2014-12-26 16:41:48 2015-02-24 16:43:13,658 [44] INFO umbraco.BusinessLogic.Log - [Thread 75] Log scrubbed. Removed all items older than 2014-12-26 16:43:13 2015-02-24 16:43:15,532 [58] INFO umbraco.BusinessLogic.Log - [Thread 156] Log scrubbed. Removed all items older than 2014-12-26 16:43:15 2015-02-24 16:44:42,152 [44] INFO umbraco.BusinessLogic.Log - [Thread 156] Log scrubbed. Removed all items older than 2014-12-26 16:44:41 2015-02-24 16:44:45,262 [58] INFO umbraco.BusinessLogic.Log - [Thread 156] Log scrubbed. Removed all items older than 2014-12-26 16:44:43 2015-02-24 16:46:09,490 [44] INFO umbraco.BusinessLogic.Log - [Thread 156] Log scrubbed. Removed all items older than 2014-12-26 16:46:09 2015-02-24 16:46:11,532 [58] INFO umbraco.BusinessLogic.Log - [Thread 64] Log scrubbed. Removed all items older than 2014-12-26 16:46:11

Again, I'm not sure what that means, but it doesn't seem normal that it'd be happening so frequently. I also don't see many other entries in my log aside from these, which has me wondering if whatever is causing this is preventing me from seeing other potentially important log messages.

Comments

Daniel Quick 09 Mar 2015, 16:36:26

Any movement on this core team? I raised this issue months ago, and it persists through several releases. It is not a show stopper, but it would be nice to not have the logs fill up with this stuff, and it has to have an impact on performance!


Matt Muller 10 Mar 2015, 00:47:42

I'm seeing the same thing in 7.2.2


Matt Muller 10 Mar 2015, 00:56:53

I think this is the offending method: https://github.com/umbraco/Umbraco-CMS/blob/ded1def8e2e7ea1a4fd0f849cc7a3f1f97cd8242/src/Umbraco.Web/Scheduling/Scheduler.cs#L83

it's returning the interval in seconds but I think it should be in milliseconds?


Shannon Deminick 16 Mar 2015, 08:01:03

Logs can easily be filtered in the mean time, that is what the log4net settings are for, if you add this:

of course that only solves your log filling. We're having a look at the cause now.


Stephan 16 Mar 2015, 08:15:50

@Matt: exact. the setting should be in millis but if there's no setting we're supposed to default to "24hrs" - however we return 246060 which is 24hrs in seconds, not millis. So it's actually scrubbing every 86400ms, or 86s, which is what we see in the log. Fixing. However, I think that 24hrs is a bit long... will set the default (if no setting) to 4hrs ie 46060*1000.


Stephan 16 Mar 2015, 08:17:03

Fixed with a44b19da187c91908d5f34f87c6c1ff1740ccb44


Priority: Normal

Type: Bug

State: Fixed

Assignee: Stephan

Difficulty: Normal

Category:

Backwards Compatible: True

Fix Submitted:

Affected versions: 7.2.2

Due in version: 7.2.3

Sprint:

Story Points:

Cycle: