Web2py scheduler timeout

Mike D

unread,

Dec 13, 2012, 1:17:29 AM12/13/12

to web...@googlegroups.com

Hello,

I am using the web2py scheduler to run a task to monitor a directory. Here's some code describing what I'm doing:

def get_configured_logger():

logger = logging.getLogger("ss_server")

if (len(logger.handlers) == 0):

handler = logging.handlers.RotatingFileHandler("/path/to/log/log.txt", maxBytes=1024*1024*10, backupCount=2)

handler.setLevel(logging.DEBUG)

logger.addHandler(handler)

logger.setLevel(logging.DEBUG)

logger.debug("Logger created")

return logger

def write_to_log(s):

l = get_configured_logger()

l.info(s)

...

def searchForFiles():

print("serach for files")

write_to_log("searching for files")

print os.getcwd()

write_to_log("creating watermark")

watermark_opaque = Image.open('./path/to/image/watermark.png')

watermark = reduce_opacity(watermark_opaque, 0.7)

write_to_log("done creating watermark")

write_to_log("globbing files")

files = glob.glob(INPUT_DIR + "*.jpg")

write_to_log("files globbed")

for filename in files:

write_to_log("getting basename for " + filename)

filename = os.path.basename(filename)

write_to_log("splitting filename")

parts = filename.split('-')

write_to_log("checking filename")

if (len(parts) == 6):

try:

print("processing file: " + filename)

write_to_log("processing file: " + filename)

im = Image.open(INPUT_DIR + filename)

write_to_log("adding watermark")

im.paste(watermark,(im.size[0] - watermark.size[0] - 20,im.size[1] - watermark.size[1] - 20),watermark)

im.save(INPUT_DIR + filename, "JPEG", quality=100)

write_to_log("added watermark")

write_to_log("creating scaled images")

createScaledImage(64, INPUT_DIR + filename, THUMBS_DIR)

createScaledImage(600, INPUT_DIR + filename, SMALL_DIR)

write_to_log("done creating scaled images")

pic_id = processFile(filename)

print("processed file successfully")

write_to_log("processed file successfully")

write_to_log("renaming files")

shutil.move(INPUT_DIR + filename, PROCESSED_DIR + "%d" % pic_id + ".jpg")

shutil.move(THUMBS_DIR + filename, THUMBS_DIR + "%d" % pic_id + ".jpg")

shutil.move(SMALL_DIR + filename, SMALL_DIR + "%d" % pic_id + ".jpg")

write_to_log("done renaming files")

except IOError:

#this is likely due to a partial file, so let it finish writing and try

#again next time

print("IO Error")

write_to_log("IO Error")

pass

except:

etype, eval, etb = sys.exc_info()

print("error processing file: ", eval.message)

write_to_log("error: " + eval.message)

shutil.move(INPUT_DIR + filename, ERRORS_DIR + filename)

write_to_log("end of loop")

write_to_log("ending function")

return "success"

myscheduler = Scheduler(db, tasks=dict(searchForFiles=searchForFiles))

I have a task inserted into my scheduler_task table with the following properties:

function name: searchForFiles

repeats: 0

timeout: 240

sync output: 15

Everything works fine except I get random TIMEOUT runs 1-2 times per day. Furthermore these runs will happen in the middle of the night when nothing has been added to the directory. When a TIMEOUT happens, the last line in my log file is "ending function". Also, there is no output at all in the scheduler_run record for the run that was marked as TIMEOUT.

For these reasons I do not think the timeout is happening inside my code, I believe it is somehow happening between when the scheduler tries to pick up task and when it calls my function. I could totally be wrong though. The reason I have added in such granular logging is to find exactly where the timeout was occurring so I could fix it but I cannot find the problem anywhere.

Please let me know if anyone has any ideas on what could be causing this issue. Any help would be very much appreciated. If I cannot fix it I will have to find a different solution for directory monitoring and not use the scheduler.

Thanks again,

Mike

Niphlod

unread,

Dec 13, 2012, 4:31:38 AM12/13/12

to web...@googlegroups.com

are you using sqlite ? It's possible that the timeout is reached because database is locked and the scheduler_run record (that you confirm is missing) can't be inserted. Also, just to be sure, did you try raising the timeout?

If I cannot fix it I will have to find a different solution for directory monitoring and not use the scheduler.

Can't you use a task with retry_failed ?

Next step is enabling debug logging of the scheduler to see what goes on when the task timeouts

Mike D

unread,

Dec 13, 2012, 1:40:11 PM12/13/12

to web...@googlegroups.com

I am using SQLite. The TIMEOUT record in the scheduler_run table eventually shows up. I can't be sure when since it normally happens over night. I don't know how to raise a timeout but if you tell me I can try that. That would help narrow down the issue because if the DB is locked I would not see the scheduler_run record inserted and my scheduler_task record would still be marked running. Is this correct?

From the docs I was under the impression that retry_failed would only work if the task actually raised an exception. I will certainly add that and hope that it works.

Would changing the database out for postgres or MySQL possibly solve the root issue? I would obviously rather the task did not timeout.

I will enable the debug logging. Thanks so much for your help and for your work on the scheduler Niphlod.

Niphlod

unread,

Dec 13, 2012, 2:57:01 PM12/13/12

to web...@googlegroups.com

All my statements were made under the assumption that the scheduler_run table showed absolutely no trace of the TIMOUTted task.

In any case, running the scheduler on SQLite is "safe" only for 1 or 2 workers and not with a zillion of tasks. Concurrency was never a friend of SQLite.

BTW, at this point enable the debug logging of the scheduler: can be quite a long log keep it for a day or two, but if you can't reproduce the error at will, it's the only hope to see what is really going on.

PS: confirmed: TIMEOUTted tasks do end up requeued with retry_failed != 0

PS2: don't underestimate the flexibility of the scheduler. Even if retry_failed was not available, you can always use another task that checks on the scheduler_task table for the "original" task and requeue it :P

Mike D

unread,

Dec 13, 2012, 3:16:27 PM12/13/12

to web...@googlegroups.com

I have only this one task. I am certainly going to change the retry_failed and hopefully that will be a sufficient solution. I actually tried your other solution a while ago and that "monitoring" task actually ended up in a TIMEOUT state as well. Sad face. Any idea on that one?

Do you think that switching database providers would help or is it not worth the effort?

Thanks again for your help.

Niphlod

unread,

Dec 13, 2012, 7:11:49 PM12/13/12

to web...@googlegroups.com

unless your tasks have a very narrow period they shouldn't go on timeout on SQLite (remember to commit if acting on the tables within a task). W2P_TVSeries uses 500-600 tasks with a "watcher" task coordinating those and it doesn't block.
"Upgrading" to Mysql or PostgreSQL will fix the issue if the issue is dependant on database locking. It's fairly easy to install both, so it's surely worth the effort.
Anyway, I'm more and more curious to see logs (and possibly a packed app to reproduce) ^_^

Mike D

unread,

Dec 17, 2012, 1:54:47 PM12/17/12

to web...@googlegroups.com

I'm not sure what "narrow" is by the period is 30 seconds. I'm seeing weirder behavior now. The task completes successfully but it quits being executed at a random time. The only way for me to fix it is to restart the scheduler process. I enabled the debug logging and here are the last two runs of my process that executed (sorry for the length, I don't wanna leave anything out though):

2012-12-16 21:39:24,315 - web2py.scheduler - INFO - TICKER: I'm a ticker (snapserver.local#63)

2012-12-16 21:39:27,035 - web2py.scheduler - DEBUG - looping...

2012-12-16 21:39:27,042 - web2py.scheduler - INFO - TICKER: workers are 1

2012-12-16 21:39:27,042 - web2py.scheduler - INFO - TICKER: tasks are 1

2012-12-16 21:39:27,042 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 21:39:27,320 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 21:39:30,043 - web2py.scheduler - DEBUG - looping...

2012-12-16 21:39:30,047 - web2py.scheduler - DEBUG - work to do 1

2012-12-16 21:39:30,047 - web2py.scheduler - DEBUG - new scheduler_run record

2012-12-16 21:39:30,049 - web2py.scheduler - INFO - new task 1 "search for files" ss_server/appadmin.searchForFiles

2012-12-16 21:39:30,049 - web2py.scheduler - DEBUG - new task allocated: ss_server/appadmin.searchForFiles

2012-12-16 21:39:30,050 - web2py.scheduler - DEBUG - task starting

2012-12-16 21:39:30,054 - web2py.scheduler - DEBUG - task started

2012-12-16 21:39:30,089 - ss_server - DEBUG - Logger created

2012-12-16 21:39:30,090 - ss_server - INFO - searching for files

2012-12-16 21:39:30,090 - ss_server - INFO - creating watermark

2012-12-16 21:39:30,095 - ss_server - INFO - done creating watermark

2012-12-16 21:39:30,096 - ss_server - INFO - globbing files

2012-12-16 21:39:30,096 - ss_server - INFO - files globbed

2012-12-16 21:39:30,097 - ss_server - INFO - getting basename for /usr/local/ss_server/input/S-1014.D-20121214121351.L-WIKILONG.I-000000000000000000055032,.P-2.jpg

2012-12-16 21:39:30,097 - ss_server - INFO - splitting filename

2012-12-16 21:39:30,097 - ss_server - INFO - checking filename

2012-12-16 21:39:30,098 - ss_server - INFO - processing file: S-1014.D-20121214121351.L-WIKILONG.I-000000000000000000055032,.P-2.jpg

2012-12-16 21:39:30,098 - ss_server - INFO - adding watermark

2012-12-16 21:39:30,153 - ss_server - INFO - IO Error

2012-12-16 21:39:30,153 - ss_server - INFO - end of loop

2012-12-16 21:39:30,154 - ss_server - INFO - getting basename for /usr/local/ss_server/input/S-1014.D-20121214135116.L-KONGS.I-000000000000000000055055,.P-1.jpg

2012-12-16 21:39:30,154 - ss_server - INFO - splitting filename

2012-12-16 21:39:30,155 - ss_server - INFO - checking filename

2012-12-16 21:39:30,155 - ss_server - INFO - processing file: S-1014.D-20121214135116.L-KONGS.I-000000000000000000055055,.P-1.jpg

2012-12-16 21:39:30,156 - ss_server - INFO - adding watermark

2012-12-16 21:39:30,196 - ss_server - INFO - IO Error

2012-12-16 21:39:30,197 - ss_server - INFO - end of loop

2012-12-16 21:39:30,197 - ss_server - INFO - getting basename for /usr/local/ss_server/input/S-1019.D-20121214122954.L-WIKILONG.I-xxxxxxxxxxxxxxxxxxxxTEST,.P-8.jpg

2012-12-16 21:39:30,197 - ss_server - INFO - splitting filename

2012-12-16 21:39:30,198 - ss_server - INFO - checking filename

2012-12-16 21:39:30,198 - ss_server - INFO - processing file: S-1019.D-20121214122954.L-WIKILONG.I-xxxxxxxxxxxxxxxxxxxxTEST,.P-8.jpg

2012-12-16 21:39:30,217 - ss_server - INFO - IO Error

2012-12-16 21:39:30,218 - ss_server - INFO - end of loop

2012-12-16 21:39:30,218 - ss_server - INFO - getting basename for /usr/local/ss_server/input/S-1021.D-20121214125548.L-WIKILONG.I-100000000000000000055006,.P-1.jpg

2012-12-16 21:39:30,218 - ss_server - INFO - splitting filename

2012-12-16 21:39:30,219 - ss_server - INFO - checking filename

2012-12-16 21:39:30,219 - ss_server - INFO - processing file: S-1021.D-20121214125548.L-WIKILONG.I-100000000000000000055006,.P-1.jpg

2012-12-16 21:39:30,221 - ss_server - INFO - adding watermark

2012-12-16 21:39:30,274 - ss_server - INFO - IO Error

2012-12-16 21:39:30,274 - ss_server - INFO - end of loop

2012-12-16 21:39:30,275 - ss_server - INFO - ending function

2012-12-16 21:39:30,277 - web2py.scheduler - DEBUG - new task report: COMPLETED

2012-12-16 21:39:30,277 - web2py.scheduler - DEBUG - result: "success"

2012-12-16 21:39:30,326 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 21:39:30,327 - web2py.scheduler - DEBUG - partial output: "serach for files

/usr/local/ss_server/web2py_ss_server

processing file: S-1014.D-20121214121351.L-WIKILONG.I-000000000000000000055032,.P-2.jpg

IO Error

processing file: S-1014.D-20121214135116.L-KONGS.I-000000000000000000055055,.P-1.jpg

IO Error

processing file: S-1019.D-20121214122954.L-WIKILONG.I-xxxxxxxxxxxxxxxxxxxxTEST,.P-8.jpg

IO Error

processing file: S-1021.D-20121214125548.L-WIKILONG.I-100000000000000000055006,.P-1.jpg

IO Error

"

2012-12-16 21:39:30,327 - web2py.scheduler - DEBUG - task completed or failed

2012-12-16 21:39:30,327 - web2py.scheduler - DEBUG - recording task report in db (COMPLETED)

2012-12-16 21:39:30,330 - web2py.scheduler - INFO - task completed (COMPLETED)

2012-12-16 21:39:30,331 - web2py.scheduler - DEBUG - looping...

2012-12-16 21:39:30,331 - web2py.scheduler - DEBUG - nothing to do

2012-12-16 21:39:30,332 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 21:39:33,331 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 21:39:33,333 - web2py.scheduler - DEBUG - looping...

2012-12-16 21:39:33,335 - web2py.scheduler - DEBUG - nothing to do

2012-12-16 21:39:33,335 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 21:39:36,336 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 21:39:36,337 - web2py.scheduler - DEBUG - looping...

2012-12-16 21:39:36,338 - web2py.scheduler - DEBUG - nothing to do

2012-12-16 21:39:36,339 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 21:39:39,341 - web2py.scheduler - DEBUG - looping...

2012-12-16 21:39:39,342 - web2py.scheduler - DEBUG - nothing to do

2012-12-16 21:39:39,342 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 21:39:39,391 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 21:39:39,392 - web2py.scheduler - DEBUG - freeing workers that have not sent heartbeat

2012-12-16 21:39:39,394 - web2py.scheduler - INFO - TICKER: I'm a ticker (snapserver.local#63)

2012-12-16 21:39:42,343 - web2py.scheduler - DEBUG - looping...

2012-12-16 21:39:42,347 - web2py.scheduler - INFO - TICKER: workers are 1

2012-12-16 21:39:42,348 - web2py.scheduler - INFO - TICKER: tasks are 0

2012-12-16 21:39:42,348 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 21:39:42,406 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 21:39:45,350 - web2py.scheduler - DEBUG - looping...

2012-12-16 21:39:45,351 - web2py.scheduler - DEBUG - nothing to do

2012-12-16 21:39:45,352 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 21:39:45,438 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 21:39:48,353 - web2py.scheduler - DEBUG - looping...

2012-12-16 21:39:48,354 - web2py.scheduler - DEBUG - nothing to do

2012-12-16 21:39:48,354 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 21:39:48,442 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 21:39:51,356 - web2py.scheduler - DEBUG - looping...

2012-12-16 21:39:51,357 - web2py.scheduler - DEBUG - nothing to do

2012-12-16 21:39:51,357 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 23:12:11,268 - web2py.scheduler - DEBUG - looping...

2012-12-16 23:12:11,269 - web2py.scheduler - DEBUG - nothing to do

2012-12-16 23:12:11,269 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 23:12:14,271 - web2py.scheduler - DEBUG - looping...

2012-12-16 23:12:14,273 - web2py.scheduler - DEBUG - nothing to do

2012-12-16 23:12:14,273 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 23:12:16,225 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 23:12:17,275 - web2py.scheduler - DEBUG - looping...

2012-12-16 23:12:17,277 - web2py.scheduler - DEBUG - nothing to do

2012-12-16 23:12:17,277 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 23:12:19,385 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 23:12:19,386 - web2py.scheduler - DEBUG - freeing workers that have not sent heartbeat

2012-12-16 23:12:19,388 - web2py.scheduler - INFO - TICKER: I'm a ticker (snapserver.local#63)

2012-12-16 23:12:20,278 - web2py.scheduler - DEBUG - looping...

2012-12-16 23:12:20,288 - web2py.scheduler - INFO - TICKER: workers are 1

2012-12-16 23:12:20,289 - web2py.scheduler - INFO - TICKER: tasks are 1

2012-12-16 23:12:20,289 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 23:12:22,392 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 23:12:23,291 - web2py.scheduler - DEBUG - looping...

2012-12-16 23:12:23,295 - web2py.scheduler - DEBUG - work to do 1

2012-12-16 23:12:23,296 - web2py.scheduler - DEBUG - new scheduler_run record

2012-12-16 23:12:23,298 - web2py.scheduler - INFO - new task 1 "search for files" ss_server/appadmin.searchForFiles

2012-12-16 23:12:23,298 - web2py.scheduler - DEBUG - new task allocated: ss_server/appadmin.searchForFiles

2012-12-16 23:12:23,299 - web2py.scheduler - DEBUG - task starting

2012-12-16 23:12:23,303 - web2py.scheduler - DEBUG - task started

2012-12-16 23:12:23,335 - ss_server - DEBUG - Logger created

2012-12-16 23:12:23,335 - ss_server - INFO - searching for files

2012-12-16 23:12:23,336 - ss_server - INFO - creating watermark

2012-12-16 23:12:23,341 - ss_server - INFO - done creating watermark

2012-12-16 23:12:23,341 - ss_server - INFO - globbing files

2012-12-16 23:12:23,342 - ss_server - INFO - files globbed

2012-12-16 23:12:23,342 - ss_server - INFO - getting basename for /usr/local/ss_server/input/S-1014.D-20121214121351.L-WIKILONG.I-000000000000000000055032,.P-2.jpg

2012-12-16 23:12:23,343 - ss_server - INFO - splitting filename

2012-12-16 23:12:23,343 - ss_server - INFO - checking filename

2012-12-16 23:12:23,343 - ss_server - INFO - processing file: S-1014.D-20121214121351.L-WIKILONG.I-000000000000000000055032,.P-2.jpg

2012-12-16 23:12:23,344 - ss_server - INFO - adding watermark

2012-12-16 23:12:23,400 - ss_server - INFO - IO Error

2012-12-16 23:12:23,400 - ss_server - INFO - end of loop

2012-12-16 23:12:23,401 - ss_server - INFO - getting basename for /usr/local/ss_server/input/S-1014.D-20121214135116.L-KONGS.I-000000000000000000055055,.P-1.jpg

2012-12-16 23:12:23,401 - ss_server - INFO - splitting filename

2012-12-16 23:12:23,401 - ss_server - INFO - checking filename

2012-12-16 23:12:23,402 - ss_server - INFO - processing file: S-1014.D-20121214135116.L-KONGS.I-000000000000000000055055,.P-1.jpg

2012-12-16 23:12:23,402 - ss_server - INFO - adding watermark

2012-12-16 23:12:23,441 - ss_server - INFO - IO Error

2012-12-16 23:12:23,441 - ss_server - INFO - end of loop

2012-12-16 23:12:23,442 - ss_server - INFO - getting basename for /usr/local/ss_server/input/S-1019.D-20121214122954.L-WIKILONG.I-xxxxxxxxxxxxxxxxxxxxTEST,.P-8.jpg

2012-12-16 23:12:23,442 - ss_server - INFO - splitting filename

2012-12-16 23:12:23,442 - ss_server - INFO - checking filename

2012-12-16 23:12:23,442 - ss_server - INFO - processing file: S-1019.D-20121214122954.L-WIKILONG.I-xxxxxxxxxxxxxxxxxxxxTEST,.P-8.jpg

2012-12-16 23:12:23,462 - ss_server - INFO - IO Error

2012-12-16 23:12:23,462 - ss_server - INFO - end of loop

2012-12-16 23:12:23,463 - ss_server - INFO - getting basename for /usr/local/ss_server/input/S-1021.D-20121214125548.L-WIKILONG.I-100000000000000000055006,.P-1.jpg

2012-12-16 23:12:23,463 - ss_server - INFO - splitting filename

2012-12-16 23:12:23,463 - ss_server - INFO - checking filename

2012-12-16 23:12:23,463 - ss_server - INFO - processing file: S-1021.D-20121214125548.L-WIKILONG.I-100000000000000000055006,.P-1.jpg

2012-12-16 23:12:23,465 - ss_server - INFO - adding watermark

2012-12-16 23:12:23,527 - ss_server - INFO - IO Error

2012-12-16 23:12:23,528 - ss_server - INFO - end of loop

2012-12-16 23:12:23,528 - ss_server - INFO - ending function

2012-12-16 23:12:23,531 - web2py.scheduler - DEBUG - new task report: COMPLETED

2012-12-16 23:12:23,531 - web2py.scheduler - DEBUG - result: "success"

2012-12-16 23:12:23,573 - web2py.scheduler - DEBUG - partial output: "serach for files

/usr/local/ss_server/web2py_ss_server

processing file: S-1014.D-20121214121351.L-WIKILONG.I-000000000000000000055032,.P-2.jpg

IO Error

processing file: S-1014.D-20121214135116.L-KONGS.I-000000000000000000055055,.P-1.jpg

IO Error

processing file: S-1019.D-20121214122954.L-WIKILONG.I-xxxxxxxxxxxxxxxxxxxxTEST,.P-8.jpg

IO Error

processing file: S-1021.D-20121214125548.L-WIKILONG.I-100000000000000000055006,.P-1.jpg

IO Error

"

2012-12-16 23:12:23,573 - web2py.scheduler - DEBUG - task completed or failed

2012-12-16 23:12:23,574 - web2py.scheduler - DEBUG - recording task report in db (COMPLETED)

2012-12-16 23:12:23,580 - web2py.scheduler - INFO - task completed (COMPLETED)

2012-12-16 23:12:23,580 - web2py.scheduler - DEBUG - looping...

2012-12-16 23:12:23,582 - web2py.scheduler - DEBUG - nothing to do

2012-12-16 23:12:23,582 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 23:12:25,429 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 23:12:26,584 - web2py.scheduler - DEBUG - looping...

2012-12-16 23:12:26,586 - web2py.scheduler - DEBUG - nothing to do

2012-12-16 23:12:26,586 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 23:12:28,447 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 23:12:29,588 - web2py.scheduler - DEBUG - looping...

2012-12-16 23:12:29,589 - web2py.scheduler - DEBUG - nothing to do

2012-12-16 23:12:29,590 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 23:12:31,474 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 23:12:32,592 - web2py.scheduler - DEBUG - looping...

2012-12-16 23:12:32,593 - web2py.scheduler - DEBUG - nothing to do

2012-12-16 23:12:32,594 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 23:12:34,479 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 23:12:34,480 - web2py.scheduler - DEBUG - freeing workers that have not sent heartbeat

2012-12-16 23:12:34,483 - web2py.scheduler - INFO - TICKER: I'm a ticker (snapserver.local#63)

2012-12-16 23:12:35,595 - web2py.scheduler - DEBUG - looping...

2012-12-16 23:12:35,601 - web2py.scheduler - INFO - TICKER: workers are 1

2012-12-16 23:12:35,601 - web2py.scheduler - INFO - TICKER: tasks are 0

2012-12-16 23:12:35,601 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 23:12:37,554 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 23:12:38,603 - web2py.scheduler - DEBUG - looping...

2012-12-16 23:12:38,605 - web2py.scheduler - DEBUG - nothing to do

2012-12-16 23:12:38,605 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 23:12:40,588 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 23:12:41,607 - web2py.scheduler - DEBUG - looping...

2012-12-16 23:12:41,610 - web2py.scheduler - DEBUG - nothing to do

2012-12-16 23:12:41,610 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 23:12:43,623 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 23:12:44,612 - web2py.scheduler - DEBUG - looping...

2012-12-16 23:12:44,613 - web2py.scheduler - DEBUG - nothing to do

2012-12-16 23:12:44,613 - web2py.scheduler - DEBUG - sleeping...

2012-12-16 23:12:46,785 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-16 23:12:47,615 - web2py.scheduler - DEBUG - looping...

2012-12-17 01:12:49,028 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 01:12:49,029 - web2py.scheduler - DEBUG - freeing workers that have not sent heartbeat

2012-12-17 01:12:49,032 - web2py.scheduler - INFO - TICKER: I'm a ticker (snapserver.local#63)

2012-12-17 01:12:52,036 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 01:12:55,041 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 01:12:58,045 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 01:13:01,079 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 01:13:04,136 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 01:13:04,137 - web2py.scheduler - DEBUG - freeing workers that have not sent heartbeat

2012-12-17 01:13:04,139 - web2py.scheduler - INFO - TICKER: I'm a ticker (snapserver.local#63)

2012-12-17 01:13:07,180 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:13:07,977 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:13:10,982 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:13:13,986 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:13:17,323 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:13:17,324 - web2py.scheduler - DEBUG - freeing workers that have not sent heartbeat

2012-12-17 03:13:17,327 - web2py.scheduler - INFO - TICKER: I'm a ticker (snapserver.local#63)

2012-12-17 03:13:20,331 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:13:23,336 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:13:26,360 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:28:46,026 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:28:49,068 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:28:49,069 - web2py.scheduler - DEBUG - freeing workers that have not sent heartbeat

2012-12-17 03:28:49,072 - web2py.scheduler - INFO - TICKER: I'm a ticker (snapserver.local#63)

2012-12-17 03:28:52,191 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:28:55,275 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:28:58,288 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:29:01,466 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:29:04,471 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:29:04,472 - web2py.scheduler - DEBUG - freeing workers that have not sent heartbeat

2012-12-17 03:29:04,474 - web2py.scheduler - INFO - TICKER: I'm a ticker (snapserver.local#63)

2012-12-17 03:29:07,486 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:29:10,643 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:29:13,802 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:29:16,910 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:29:19,972 - web2py.scheduler - DEBUG - ........recording heartbeat

2012-12-17 03:29:19,973 - web2py.scheduler - DEBUG - freeing workers that have not sent heartbeat

2012-12-17 03:29:19,975 - web2py.scheduler - INFO - TICKER: I'm a ticker (snapserver.local#63)

The IOErrors in the task are normal and they're caught and handled properly. This has been happening since I upgraded web2py from 1.99 to 2.2.1. The TIMEOUT problem was happening on v1.99. It doesn't run long enough for me to test if that is still happening. It just goes on like that forever. Not sure what happened. Any ideas?

Niphlod

unread,

Dec 17, 2012, 3:29:34 PM12/17/12

to web...@googlegroups.com

you could attach the log to the message, so the thread doesn't get long:P
I see 2 rounds only COMPLETED, then a huge gap

2012-12-16 21:39:30,330 - web2py.scheduler - INFO - task completed (COMPLETED)

2012-12-16 23:12:23,296 - web2py.scheduler - DEBUG - new scheduler_run record
2012-12-16 23:12:23,298 - web2py.scheduler - INFO - new task 1 "search for files" ss_server/appadmin.searchForFiles
2012-12-16 23:12:23,298 - web2py.scheduler - DEBUG - new task allocated: ss_server/appadmin.searchForFiles
2012-12-16 23:12:23,299 - web2py.scheduler - DEBUG - task starting
2012-12-16 23:12:23,303 - web2py.scheduler - DEBUG - task started

2012-12-16 23:12:23,531 - web2py.scheduler - DEBUG - new task report: COMPLETED
2012-12-16 23:12:23,531 - web2py.scheduler - DEBUG - result: "success"
2012-12-16 23:12:23,573 - web2py.scheduler - DEBUG - partial output: "serach for files
/usr/local/ss_server/web2py_ss_server
processing file: S-1014.D-20121214121351.L-WIKILONG.I-000000000000000000055032,.P-2.jpg
IO Error
processing file: S-1014.D-20121214135116.L-KONGS.I-000000000000000000055055,.P-1.jpg
IO Error
processing file: S-1019.D-20121214122954.L-WIKILONG.I-xxxxxxxxxxxxxxxxxxxxTEST,.P-8.jpg
IO Error
processing file: S-1021.D-20121214125548.L-WIKILONG.I-100000000000000000055006,.P-1.jpg
IO Error
"
2012-12-16 23:12:23,573 - web2py.scheduler - DEBUG - task completed or failed
2012-12-16 23:12:23,574 - web2py.scheduler - DEBUG - recording task report in db (COMPLETED)
2012-12-16 23:12:23,580 - web2py.scheduler - INFO - task completed (COMPLETED)

HUGE GAP here

2012-12-17 03:13:26,360 - web2py.scheduler - DEBUG - ........recording heartbeat
2012-12-17 03:28:46,026 - web2py.scheduler - DEBUG - ........recording heartbeat
2012-12-17 03:28:49,068 - web2py.scheduler - DEBUG - ........recording heartbeat

then practically nothing. Can you tell me how the task in the scheduler_task table is at this time ?

Mike D

unread,

Dec 17, 2012, 3:45:45 PM12/17/12

to web...@googlegroups.com

Sorry about that. I just tried to attach the log and it keeps giving me an error. The scheduler_task record is marked QUEUED and the last scheduler_run record is marked COMPLETED. The task just isn't being run for some reason.

Mike D

unread,

Dec 17, 2012, 3:54:38 PM12/17/12

to web...@googlegroups.com

I have now tried with two different browsers to attach the log with no success. I keep getting error (340) occurred while communicating with the server. Do you want me to just email you the log?

Niphlod

unread,

Dec 17, 2012, 4:40:58 PM12/17/12

to web...@googlegroups.com

no probl, the email is kinda obvious, at gmail.com

Reply all

Reply to author

Forward