Return-Path: Delivered-To: apmail-roller-user-archive@www.apache.org Received: (qmail 46709 invoked from network); 23 Jan 2008 04:17:26 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.2) by minotaur.apache.org with SMTP; 23 Jan 2008 04:17:26 -0000 Received: (qmail 97033 invoked by uid 500); 23 Jan 2008 04:17:16 -0000 Delivered-To: apmail-roller-user-archive@roller.apache.org Received: (qmail 97002 invoked by uid 500); 23 Jan 2008 04:17:16 -0000 Mailing-List: contact user-help@roller.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: user@roller.apache.org Delivered-To: mailing list user@roller.apache.org Received: (qmail 96991 invoked by uid 99); 23 Jan 2008 04:17:16 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 22 Jan 2008 20:17:16 -0800 X-ASF-Spam-Status: No, hits=-0.0 required=10.0 tests=SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of snoopdave@gmail.com designates 64.233.178.250 as permitted sender) Received: from [64.233.178.250] (HELO hs-out-2122.google.com) (64.233.178.250) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 23 Jan 2008 04:16:48 +0000 Received: by hs-out-2122.google.com with SMTP id m63so2391854hsc.13 for ; Tue, 22 Jan 2008 20:16:31 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=domainkey-signature:received:received:message-id:date:from:to:subject:in-reply-to:mime-version:content-type:content-transfer-encoding:content-disposition:references; bh=GngBLAHjIUDq0qXeNI+9VqLujZfixPacb9Eo2gtMaoQ=; b=dKgBRHWAimzzwhUbOiPBTeBnaQev7sZJ0K3o/Y15couRoJkJfus62wYZm5lV8bAQdOjJy51AXdJycVjdbrQ4a2k+d3NS0Rf7eTCncC/JIvhyTsdOeOQ50sbV4WbR+HbWwUxWwc+3cgM++pC1BwU9Iwz3aMv6VFP5sdskvnTGO48= DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=message-id:date:from:to:subject:in-reply-to:mime-version:content-type:content-transfer-encoding:content-disposition:references; b=IqG4qGSg6MFnFfCtd4Gk9eexgYcHEjww0D+co+5n6lIqb1jixXWjDMWCUsaMVqcbqp5gTXFEAC9dAhLMDpEp2Voh+xYAP5ERqg9WF+Y+hJRLjK3EspQwcoPfb7zc03RDzsm+myy79ketH2yB2MeFTc5mXHiWrbEgHLV+rbg1t3M= Received: by 10.150.57.5 with SMTP id f5mr3286604yba.140.1201061791244; Tue, 22 Jan 2008 20:16:31 -0800 (PST) Received: by 10.150.155.19 with HTTP; Tue, 22 Jan 2008 20:16:31 -0800 (PST) Message-ID: <8fb9ac720801222016m2f35ef13xe7a341b482795585@mail.gmail.com> Date: Tue, 22 Jan 2008 23:16:31 -0500 From: Dave To: user@roller.apache.org Subject: Re: Task Scheduler not running ResetHitCountsTask and other tasks In-Reply-To: <47888855.5000609@toasttechnology.com.au> MIME-Version: 1.0 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Content-Disposition: inline References: <4782BDF4.8070706@toasttechnology.com.au> <8fb9ac720801111935t75f206aex97cfd82487b3caa6@mail.gmail.com> <47888855.5000609@toasttechnology.com.au> X-Virus-Checked: Checked by ClamAV on apache.org I'm not sure what is going on here and I don't have time to investigate right now so I filed a bug: http://opensource.atlassian.com/projects/roller/browse/ROL-1657 Hopefully somebody will revisit before our next release. - Dave On Jan 12, 2008 4:28 AM, Nick Hortovanyi wrote: > Hi Dave, > > Have dumped a lot of logs etc in this email. > > Nick > > Dave wrote: > > On Jan 7, 2008 7:04 PM, Nick Hortovanyi wrote: > > > >> TaskScheduler does not appear to work with Apache Roller 4 and > >> Postgres.. any ideas? > >> > >> DEBUG 2008-01-08 00:00:00,058 TaskScheduler:run - Current time = Tue Jan > >> 08 00:00:00 CST 2008 > >> DEBUG 2008-01-08 00:00:00,059 TaskScheduler:runTasks - Started - Tue Jan > >> 08 00:00:00 CST 2008 > >> DEBUG 2008-01-08 00:00:00,060 TaskScheduler:runTasks - > >> > > > > Question: In the logs, is there any evidence that tasks ever ran? > > > This was an upgrade from Roller 3.1. Did get the tasks to run once. > Believe I removed the entries from roller_tasklock. > > > I'm not sure what is causing these problems with the scheduler. I have > > not encountered them on my Roller systems, which run MySQL. > > > > One theory is that the task lock table is getting corrupted. I believe > > some folks have been able to work around the problem by removing all > > data from the 'roller_tasklocks' table. If you try that please let us > > know if it works on not. > > > Here is the current data in the table > roller=> select * from roller_tasklock > roller-> \g > id | name | > islocked | timeacquired | timeleased | > lastrun | client > --------------------------------------+-------------------------+----------+----------------------------------+------------+---------------------------+----------------- > b6a3a294-f474-4264-b188-cc4c03708545 | SyncWebsitesTask | > f | 1970-01-01 09:30:00+09:30 | 0 | 1970-01-01 > 09:30:00+09:30 | > 3e2efcbb-e059-47b1-9ee8-29d7a5c2ca2e | RefreshRollerPlanetTask | > f | 1970-01-01 09:30:00+09:30 | 0 | 1970-01-01 > 09:30:00+09:30 | > 079b4415-1287-43c1-b720-60f24433153d | ScheduledEntriesTask | > f | 2007-12-24 10:08:00.134127+10:30 | 30 | 2007-12-24 > 10:08:00+10:30 | defaultClientId > 7762e849-cdb1-4c0e-ac76-75ee92668653 | PingQueueTask | > f | 2007-12-24 10:08:00.149668+10:30 | 30 | 2007-12-24 > 10:08:00+10:30 | defaultClientId > 485648c0-358c-42b2-8fc4-62c27740e3fa | ResetHitCountsTask | > f | 2007-12-25 00:00:00.061304+10:30 | 30 | 2007-12-25 > 00:00:00+10:30 | defaultClientId > f37c99ef-8fff-4cad-b7dd-9f64a6ed76dc | TurnoverReferersTask | > f | 2007-12-25 00:00:00.066401+10:30 | 30 | 2007-12-25 > 00:00:00+10:30 | defaultClientId > (6 rows) > > roller=> > > The log follows after I remove the entries before restarting tomcat > DEBUG 2008-01-12 19:44:00,057 TaskScheduler:run - Current time = Sat Jan > 12 19:44:00 CST 2008 > DEBUG 2008-01-12 19:44:00,057 TaskScheduler:runTasks - Started - Sat Jan > 12 19:44:00 CST 2008 > WARN 2008-01-12 19:44:00,060 TaskScheduler:runTasks - > ScheduledEntriesTask: Unhandled exception caught > java.lang.NullPointerException > at > org.apache.roller.weblogger.business.runnable.TaskScheduler.runTasks(TaskScheduler.java:142) > at > org.apache.roller.weblogger.business.runnable.TaskScheduler.run(TaskScheduler.java:90) > at java.lang.Thread.run(Thread.java:810) > WARN 2008-01-12 19:44:00,070 TaskScheduler:runTasks - > ResetHitCountsTask: Unhandled exception caught > java.lang.NullPointerException > at > org.apache.roller.weblogger.business.runnable.TaskScheduler.runTasks(TaskScheduler.java:142) > at > org.apache.roller.weblogger.business.runnable.TaskScheduler.run(TaskScheduler.java:90) > at java.lang.Thread.run(Thread.java:810) > WARN 2008-01-12 19:44:00,087 TaskScheduler:runTasks - > TurnoverReferersTask: Unhandled exception caught > java.lang.NullPointerException > at > org.apache.roller.weblogger.business.runnable.TaskScheduler.runTasks(TaskScheduler.java:142) > at > org.apache.roller.weblogger.business.runnable.TaskScheduler.run(TaskScheduler.java:90) > at java.lang.Thread.run(Thread.java:810) > WARN 2008-01-12 19:44:02,123 TaskScheduler:runTasks - PingQueueTask: > Unhandled exception caught > java.lang.NullPointerException > at > org.apache.roller.weblogger.business.runnable.TaskScheduler.runTasks(TaskScheduler.java:142) > at > org.apache.roller.weblogger.business.runnable.TaskScheduler.run(TaskScheduler.java:90) > at java.lang.Thread.run(Thread.java:810) > WARN 2008-01-12 19:44:02,125 TaskScheduler:runTasks - SyncWebsitesTask: > Unhandled exception caught > java.lang.NullPointerException > at > org.apache.roller.weblogger.business.runnable.TaskScheduler.runTasks(TaskScheduler.java:142) > at > org.apache.roller.weblogger.business.runnable.TaskScheduler.run(TaskScheduler.java:90) > at java.lang.Thread.run(Thread.java:810) > WARN 2008-01-12 19:44:02,126 TaskScheduler:runTasks - > RefreshRollerPlanetTask: Unhandled exception caught > java.lang.NullPointerException > at > org.apache.roller.weblogger.business.runnable.TaskScheduler.runTasks(TaskScheduler.java:142) > at > org.apache.roller.weblogger.business.runnable.TaskScheduler.run(TaskScheduler.java:90) > at java.lang.Thread.run(Thread.java:810) > DEBUG 2008-01-12 19:44:02,126 TaskScheduler:runTasks - Finished > DEBUG 2008-01-12 19:44:02,127 TaskScheduler:run - sleeping - 57922 > > Restarted tomcat > INFO 2008-01-12 19:47:14,435 ThreadManagerImpl:initialize - > Initializing task: ScheduledEntriesTask > DEBUG 2008-01-12 19:47:14,452 ThreadManagerImpl:initialize - Task record > does not exist, inserting empty record to start with > INFO 2008-01-12 19:47:14,454 ThreadManagerImpl:initialize - > Initializing task: ResetHitCountsTask > DEBUG 2008-01-12 19:47:14,456 ThreadManagerImpl:initialize - Task record > does not exist, inserting empty record to start with > INFO 2008-01-12 19:47:14,457 ThreadManagerImpl:initialize - > Initializing task: TurnoverReferersTask > DEBUG 2008-01-12 19:47:14,459 ThreadManagerImpl:initialize - Task record > does not exist, inserting empty record to start with > INFO 2008-01-12 19:47:14,459 ThreadManagerImpl:initialize - > Initializing task: PingQueueTask > DEBUG 2008-01-12 19:47:14,470 ThreadManagerImpl:initialize - Task record > does not exist, inserting empty record to start with > INFO 2008-01-12 19:47:14,471 ThreadManagerImpl:initialize - > Initializing task: SyncWebsitesTask > DEBUG 2008-01-12 19:47:14,492 ThreadManagerImpl:initialize - Task record > does not exist, inserting empty record to start with > INFO 2008-01-12 19:47:14,493 ThreadManagerImpl:initialize - > Initializing task: RefreshRollerPlanetTask > DEBUG 2008-01-12 19:47:14,496 ThreadManagerImpl:initialize - Task record > does not exist, inserting empty record to start with > DEBUG 2008-01-12 19:47:14,497 ThreadManagerImpl:initialize - Starting > scheduler thread > DEBUG 2008-01-12 19:47:14,498 TaskScheduler:run - Current time = Sat Jan > 12 19:47:14 CST 2008 > DEBUG 2008-01-12 19:47:14,499 TaskScheduler:run - Start time = Sat Jan > 12 19:48:00 CST 2008 > DEBUG 2008-01-12 19:47:14,501 TaskScheduler:run - sleeping - 105548 > ... > table shows > roller=> select * from roller_tasklock\g > id | name | > islocked | timeacquired | timeleased | > lastrun | client > --------------------------------------+-------------------------+----------+---------------------------+------------+---------------------------+-------- > 49646f7d-a967-49c0-a33c-1d01b52f6f4b | ScheduledEntriesTask | > f | 1970-01-01 09:30:00+09:30 | 0 | 1970-01-01 > 09:30:00+09:30 | > e736a3a9-37e1-41d3-a373-0b9ce7aca583 | ResetHitCountsTask | > f | 1970-01-01 09:30:00+09:30 | 0 | 1970-01-01 > 09:30:00+09:30 | > 5de5be9a-67c4-4ac9-ba21-1ef082b2f306 | TurnoverReferersTask | > f | 1970-01-01 09:30:00+09:30 | 0 | 1970-01-01 > 09:30:00+09:30 | > 98d4e609-2a69-4a13-a7b3-39944ac990df | PingQueueTask | > f | 1970-01-01 09:30:00+09:30 | 0 | 1970-01-01 > 09:30:00+09:30 | > 76f54a14-56b8-49d1-aeb6-159b7047f65a | SyncWebsitesTask | > f | 1970-01-01 09:30:00+09:30 | 0 | 1970-01-01 > 09:30:00+09:30 | > 2b1e1826-f43f-435d-9295-645800421398 | RefreshRollerPlanetTask | > f | 1970-01-01 09:30:00+09:30 | 0 | 1970-01-01 > 09:30:00+09:30 | > (6 rows) > > roller=> > ... > next run > ... > DEBUG 2008-01-12 19:49:00,055 TaskScheduler:run - Current time = Sat Jan > 12 19:49:00 CST 2008 > DEBUG 2008-01-12 19:49:00,055 TaskScheduler:runTasks - Started - Sat Jan > 12 19:49:00 CST 2008 > DEBUG 2008-01-12 19:49:00,058 TaskScheduler:runTasks - > ScheduledEntriesTask: next allowed run time = Thu Jan 01 09:31:00 CST 1970 > DEBUG 2008-01-12 19:49:00,058 TaskScheduler:runTasks - MISSED last run, > checking if waiting is necessary > DEBUG 2008-01-12 19:49:00,058 TaskScheduler:runTasks - > ScheduledEntriesTask: LAUNCHING task > DEBUG 2008-01-12 19:49:00,063 RollerTaskWithLeasing:run - > ScheduledEntriesTask: Attempting to acquire lease > DEBUG 2008-01-12 19:49:00,064 TaskScheduler:runTasks - > ResetHitCountsTask: next allowed run time = Fri Jan 02 09:30:00 CST 1970 > DEBUG 2008-01-12 19:49:00,064 TaskScheduler:runTasks - MISSED last run, > checking if waiting is necessary > DEBUG 2008-01-12 19:49:00,065 TaskScheduler:runTasks - WAITING for next > reasonable run time > DEBUG 2008-01-12 19:49:00,067 TaskScheduler:runTasks - > TurnoverReferersTask: next allowed run time = Fri Jan 02 09:30:00 CST 1970 > DEBUG 2008-01-12 19:49:00,067 TaskScheduler:runTasks - MISSED last run, > checking if waiting is necessary > DEBUG 2008-01-12 19:49:00,068 TaskScheduler:runTasks - WAITING for next > reasonable run time > DEBUG 2008-01-12 19:49:00,070 TaskScheduler:runTasks - PingQueueTask: > next allowed run time = Thu Jan 01 09:35:00 CST 1970 > DEBUG 2008-01-12 19:49:00,070 TaskScheduler:runTasks - MISSED last run, > checking if waiting is necessary > DEBUG 2008-01-12 19:49:00,071 TaskScheduler:runTasks - PingQueueTask: > LAUNCHING task > DEBUG 2008-01-12 19:49:00,074 TaskScheduler:runTasks - SyncWebsitesTask: > next allowed run time = Fri Jan 02 09:30:00 CST 1970 > DEBUG 2008-01-12 19:49:00,074 TaskScheduler:runTasks - MISSED last run, > checking if waiting is necessary > DEBUG 2008-01-12 19:49:00,075 TaskScheduler:runTasks - WAITING for next > reasonable run time > DEBUG 2008-01-12 19:49:00,076 TaskScheduler:runTasks - > RefreshRollerPlanetTask: next allowed run time = Thu Jan 01 10:30:00 CST > 1970 > DEBUG 2008-01-12 19:49:00,076 TaskScheduler:runTasks - MISSED last run, > checking if waiting is necessary > DEBUG 2008-01-12 19:49:00,077 TaskScheduler:runTasks - WAITING for next > reasonable run time > DEBUG 2008-01-12 19:49:00,077 TaskScheduler:runTasks - Finished > DEBUG 2008-01-12 19:49:00,078 TaskScheduler:run - sleeping - 59971 > DEBUG 2008-01-12 19:49:00,078 RollerTaskWithLeasing:run - PingQueueTask: > Attempting to acquire lease > DEBUG 2008-01-12 19:49:00,084 RollerTaskWithLeasing:run - > ScheduledEntriesTask: Lease acquired, running task > DEBUG 2008-01-12 19:49:00,084 ScheduledEntriesTask:runTask - task started > DEBUG 2008-01-12 19:49:00,085 ScheduledEntriesTask:runTask - looking up > scheduled entries older than Sat Jan 12 19:49:00 CST 2008 > DEBUG 2008-01-12 19:49:00,103 ScheduledEntriesTask:runTask - promoting 0 > entries to PUBLISHED state > DEBUG 2008-01-12 19:49:00,114 ScheduledEntriesTask:runTask - task completed > DEBUG 2008-01-12 19:49:00,114 RollerTaskWithLeasing:run - > ScheduledEntriesTask: Attempting to release lease > DEBUG 2008-01-12 19:49:00,120 RollerTaskWithLeasing:run - > ScheduledEntriesTask: Lease released, task finished > DEBUG 2008-01-12 19:50:00,051 TaskScheduler:run - Current time = Sat Jan > 12 19:50:00 CST 2008 > DEBUG 2008-01-12 19:50:00,051 TaskScheduler:runTasks - Started - Sat Jan > 12 19:50:00 CST 2008 > DEBUG 2008-01-12 19:50:00,054 TaskScheduler:runTasks - > ScheduledEntriesTask: next allowed run time = Sat Jan 12 19:50:00 CST 2008 > DEBUG 2008-01-12 19:50:00,054 TaskScheduler:runTasks - > ScheduledEntriesTask: LAUNCHING task > DEBUG 2008-01-12 19:50:00,054 RollerTaskWithLeasing:run - > ScheduledEntriesTask: Attempting to acquire lease > DEBUG 2008-01-12 19:50:00,056 TaskScheduler:runTasks - > ResetHitCountsTask: next allowed run time = Fri Jan 02 09:30:00 CST 1970 > DEBUG 2008-01-12 19:50:00,056 TaskScheduler:runTasks - MISSED last run, > checking if waiting is necessary > DEBUG 2008-01-12 19:50:00,056 TaskScheduler:runTasks - WAITING for next > reasonable run time > DEBUG 2008-01-12 19:50:00,058 TaskScheduler:runTasks - > TurnoverReferersTask: next allowed run time = Fri Jan 02 09:30:00 CST 1970 > DEBUG 2008-01-12 19:50:00,058 TaskScheduler:runTasks - MISSED last run, > checking if waiting is necessary > DEBUG 2008-01-12 19:50:00,058 TaskScheduler:runTasks - WAITING for next > reasonable run time > DEBUG 2008-01-12 19:50:00,060 TaskScheduler:runTasks - PingQueueTask: > next allowed run time = Thu Jan 01 09:35:00 CST 1970 > DEBUG 2008-01-12 19:50:00,060 TaskScheduler:runTasks - MISSED last run, > checking if waiting is necessary > DEBUG 2008-01-12 19:50:00,060 TaskScheduler:runTasks - PingQueueTask: > LAUNCHING task > DEBUG 2008-01-12 19:50:00,061 RollerTaskWithLeasing:run - PingQueueTask: > Attempting to acquire lease > DEBUG 2008-01-12 19:50:00,063 TaskScheduler:runTasks - SyncWebsitesTask: > next allowed run time = Fri Jan 02 09:30:00 CST 1970 > DEBUG 2008-01-12 19:50:00,063 TaskScheduler:runTasks - MISSED last run, > checking if waiting is necessary > DEBUG 2008-01-12 19:50:00,063 TaskScheduler:runTasks - WAITING for next > reasonable run time > DEBUG 2008-01-12 19:50:00,065 TaskScheduler:runTasks - > RefreshRollerPlanetTask: next allowed run time = Thu Jan 01 10:30:00 CST > 1970 > DEBUG 2008-01-12 19:50:00,065 TaskScheduler:runTasks - MISSED last run, > checking if waiting is necessary > DEBUG 2008-01-12 19:50:00,065 TaskScheduler:runTasks - WAITING for next > reasonable run time > DEBUG 2008-01-12 19:50:00,066 TaskScheduler:runTasks - Finished > DEBUG 2008-01-12 19:50:00,066 TaskScheduler:run - sleeping - 59983 > DEBUG 2008-01-12 19:50:00,067 RollerTaskWithLeasing:run - > ScheduledEntriesTask: Lease NOT acquired, cannot continue > DEBUG 2008-01-12 19:50:00,084 RollerTaskWithLeasing:run - PingQueueTask: > Lease acquired, running task > > > - Dave > > > > > > > > >