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 <[EMAIL PROTECTED]> 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 <[EMAIL PROTECTED]> 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 > > > > > > > > >
