odd behavior, is possible that the function is not called at all?
I added a log line in pop_task(), in the else branch of the first test, to
understand why fails the test: The statement is logger.info("pop task %s
%s" % (self.is_a_ticker , self.do_assign_tasks))
The log says:
2013-03-27 11:38:01,276 - web2py.scheduler.mapserver#17922 - DEBUG -
........recording heartbeat (ACTIVE)
2013-03-27 11:38:01,277 - web2py.scheduler.mapserver#17922 - DEBUG -
freeing workers that have not sent heartbeat
2013-03-27 11:38:01,278 - web2py.scheduler.mapserver#17922 - INFO - TICKER:
I'm a ticker
2013-03-27 11:38:01,315 - web2py.scheduler.mapserver#17922 - DEBUG -
looping...
2013-03-27 11:38:01,316 - web2py.scheduler.mapserver#17922 - INFO - pop
task True False
2013-03-27 11:38:01,445 - web2py.scheduler.mapserver#17922 - INFO - nothing
to do
2013-03-27 11:38:01,445 - web2py.scheduler.mapserver#17922 - DEBUG -
sleeping...
2013-03-27 11:38:04,432 - web2py.scheduler.mapserver#17922 - DEBUG -
........recording heartbeat (ACTIVE)
2013-03-27 11:38:04,449 - web2py.scheduler.mapserver#17922 - DEBUG -
looping...
2013-03-27 11:38:04,461 - web2py.scheduler.mapserver#17922 - INFO - pop
task True False
2013-03-27 11:38:04,590 - web2py.scheduler.mapserver#17922 - INFO - nothing
to do
2013-03-27 11:38:04,590 - web2py.scheduler.mapserver#17922 - DEBUG -
sleeping...
2013-03-27 11:38:07,581 - web2py.scheduler.mapserver#17922 - DEBUG -
........recording heartbeat (ACTIVE)
2013-03-27 11:38:07,594 - web2py.scheduler.mapserver#17922 - DEBUG -
looping...
2013-03-27 11:38:07,610 - web2py.scheduler.mapserver#17922 - INFO - pop
task True False
2013-03-27 11:38:07,740 - web2py.scheduler.mapserver#17922 - INFO - nothing
to do
2013-03-27 11:38:07,740 - web2py.scheduler.mapserver#17922 - DEBUG -
sleeping...
2013-03-27 11:38:10,731 - web2py.scheduler.mapserver#17922 - DEBUG -
........recording heartbeat (ACTIVE)
2013-03-27 11:38:10,741 - web2py.scheduler.mapserver#17922 - DEBUG -
looping...
2013-03-27 11:38:10,741 - web2py.scheduler.mapserver#17922 - INFO - pop
task True False
2013-03-27 11:38:10,921 - web2py.scheduler.mapserver#17922 - INFO - nothing
to do
2013-03-27 11:38:10,922 - web2py.scheduler.mapserver#17922 - DEBUG -
sleeping...
2013-03-27 11:38:13,888 - web2py.scheduler.mapserver#17922 - DEBUG -
........recording heartbeat (ACTIVE)
2013-03-27 11:38:13,925 - web2py.scheduler.mapserver#17922 - DEBUG -
looping...
2013-03-27 11:38:13,925 - web2py.scheduler.mapserver#17922 - INFO - pop
task True False
2013-03-27 11:38:14,055 - web2py.scheduler.mapserver#17922 - INFO - nothing
to do
2013-03-27 11:38:14,055 - web2py.scheduler.mapserver#17922 - DEBUG -
sleeping...
2013-03-27 11:38:17,047 - web2py.scheduler.mapserver#17922 - DEBUG -
........recording heartbeat (ACTIVE)
2013-03-27 11:38:17,048 - web2py.scheduler.mapserver#17922 - DEBUG -
freeing workers that have not sent heartbeatso, pop_task is not called because do_assign_task is False, hope it helps Paolo 2013/3/27 Niphlod <[email protected]> > well, something dark and obscure is happening ...... > either > logger.error('Error cleaning up') > logger.error('Error retrieving status') > logger.error(' error popping tasks') > logger.debug('Assigning tasks...') > "must" happen > > > On Tuesday, March 26, 2013 11:02:22 PM UTC+1, Paolo valleri wrote: > >> I will try to update sqlite as you suggested asap. >> I tried your scheduler but I cannot see any error. In the meanwhile I >> have seen that when the following logs are missing >> "INFO - TICKER: workers are 1" >> "INFO - TICKER: tasks are 0" >> even the log: "DEBUG - Assigning tasks..." is missing. >> could this mean that the function wrapped_assign_tasks is not called at >> all? >> >> >> >> >> Paolo >> >> >> 2013/3/26 Niphlod <[email protected]> >> >> here's the patch. I purposedly blocked the underlying db from another >>> terminal to see what could be the issue, but I can't reproduce in other way >>> what is happening on your system. Enough said, as soon as the db is >>> unlocked, normal operations resume. >>> There are a few error() calls to the logger, now if something goes wrong >>> it's reported accordingly. >>> >>> PS: if you want to stick to SQLite, it's better to install the most >>> updated sqlite adapter, on unix-like OSes is as simple as (giving standard >>> build tools are available) >>> >>> pip install http://pysqlite.googlecode.**com/files/pysqlite-2.6.3.tar.** >>> gz >>> <http://pysqlite.googlecode.com/files/pysqlite-2.6.3.tar.gz>--global-option >>> build_static >>> >>> and then activating WAL (reduces the chances of a locked db. Not lock >>> free, but certainly helps out). >>> WAL can be activated once on every db with a simple >>> PRAGMA journal_mode=WAL >>> or, if you are on a recent web2py distribution >>> >>> def activate_wal(db_instance): >>> db_instance.execute('PRAGMA journal_mode=WAL;') >>> >>> db = DAL('sqlite://storage.sqlite', after_connection=activate_wal) >>> >>> >>> >>> On Tuesday, March 26, 2013 8:05:44 PM UTC+1, Paolo valleri wrote: >>> >>>> I can make few tests but only tomorrow, I will be out for the rest of >>>> the week. >>>> If you send me a patch with the new log statement, I will come back >>>> with the result asap. >>>> >>>> Paolo >>>> >>>> >>>> 2013/3/26 Niphlod <[email protected]> >>>> >>>> whoa. seems that something wrong is happening trying to assing new >>>>> tasks.... >>>>> normally, every >>>>> web2py.scheduler.mapserver#**779**1 - INFO - TICKER: I'm a ticker >>>>> should be followed closely by the lines >>>>> web2py.scheduler.mapserver#**779**1 - INFO - TICKER: workers are 1 >>>>> web2py.scheduler.mapserver#**779**1 - INFO - TICKER: tasks are 0 >>>>> While in your case for several times those lines are not present.... >>>>> The fact is that the assignment is wrapped yet in a try except clause >>>>> and every exception should be logged as well, but your log doesn't show >>>>> anything of that. >>>>> >>>>> I can add more debug lines to the scheduler but this didn't ever >>>>> happen on all my platforms, so without reproducing it I'm a little bit >>>>> unsure what the fix can be. >>>>> >>>>> >>>>> On Tuesday, March 26, 2013 4:26:11 PM UTC+1, Paolo valleri wrote: >>>>> >>>>>> the flle! sorry... >>>>>> >>>>>> Paolo >>>>>> >>>>>> >>>>>> 2013/3/26 [email protected] <[email protected]> >>>>>> >>>>>>> If can be useful, I attached part of the log file in which demo1 is >>>>>>> executed. >>>>>>> First execution: 2013-03-26 15:52:31 >>>>>>> second execution: 2013-03-26 15:58:55 (+384s) >>>>>>> >>>>>>> Paolo >>>>>>> >>>>>>> >>>>>>> 2013/3/26 Paolo valleri <[email protected]> >>>>>>> >>>>>>> >>> import sqlite3 >>>>>>>> >>> print sqlite3.version >>>>>>>> 2.6.0 >>>>>>>> >>> print sqlite3.sqlite_version >>>>>>>> 3.7.9 >>>>>>>> But, if the db lock is not the problem, the test application is >>>>>>>> very easy, where is it supposed to be the problem? >>>>>>>> >>>>>>>> >>>>>>>> On Tuesday, March 26, 2013 2:32:50 PM UTC+1, Niphlod wrote: >>>>>>>>> >>>>>>>>> I find hard to believe that with a single worker, with that >>>>>>>>> function that basically just prints something and an execution every >>>>>>>>> 300 >>>>>>>>> seconds the problem lies into a lock, unless the SQLite library >>>>>>>>> available >>>>>>>>> on your system is reallly old. >>>>>>>>> >>>>>>>>> On Tuesday, March 26, 2013 2:21:21 PM UTC+1, Paolo valleri wrote: >>>>>>>>>> >>>>>>>>>> When yesterday I saw demo1 in timeout with ps auxf I have seen >>>>>>>>>> that a new process was created. For this reason I started to debug >>>>>>>>>> scheduler and I asked how to log etc. >>>>>>>>>> Moreover, I restarted the scheduler manually so I am not able to >>>>>>>>>> understand if the other different names are for an internal problem >>>>>>>>>> or >>>>>>>>>> something different. >>>>>>>>>> Do you think that should be fixed by using a different db engine? >>>>>>>>>> >>>>>>>>>> Paolo >>>>>>>>>> >>>>>>>>>> On Tuesday, March 26, 2013 12:42:14 PM UTC+1, Niphlod wrote: >>>>>>>>>>> >>>>>>>>>>> with the default logging.conf the timestamp is present as in all >>>>>>>>>>> other web2py-related logging .... >>>>>>>>>>> >>>>>>>>>>> PS: are you sure that the worker is not killed/restarted by any >>>>>>>>>>> chance (see the worker_name in the scheduler_run table) >>>>>>>>>>> >>>>>>>>>>> On Tuesday, March 26, 2013 11:33:53 AM UTC+1, Paolo valleri >>>>>>>>>>> wrote: >>>>>>>>>>>> >>>>>>>>>>>> I executed again demo1, I run it several times, I got even in >>>>>>>>>>>> this case elapsed time between two consecutive executions around >>>>>>>>>>>> 360 and >>>>>>>>>>>> even more instead of 300. What can I do to understand what is not >>>>>>>>>>>> working >>>>>>>>>>>> correctly? >>>>>>>>>>>> Moreover, I would suggest to add the timestamp to the scheduler >>>>>>>>>>>> debug log. >>>>>>>>>>>> >>>>>>>>>>>> >>>>>>>>>>>> Paolo >>>>>>>>>>>> >>>>>>>>>>>> >>>>>>>>>>>> 2013/3/25 Niphlod <[email protected]> >>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>>>> On Monday, March 25, 2013 10:46:12 PM UTC+1, Paolo valleri >>>>>>>>>>>>> wrote: >>>>>>>>>>>>>> >>>>>>>>>>>>>> I didn't get your point, with one repetitive task, should I >>>>>>>>>>>>>> start the scheduler with two or more workers? If so, I will try >>>>>>>>>>>>>> it. >>>>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>>>> The point is that the thread that manages some logic every >>>>>>>>>>>>> heartbeat seconds is the one in charge of "waiting" 5 loops to >>>>>>>>>>>>> trigger the >>>>>>>>>>>>> additional logic to pick up new tasks (a repetitive task is just >>>>>>>>>>>>> a new task >>>>>>>>>>>>> to execute). If the process "doing the work" is busy processing >>>>>>>>>>>>> the task >>>>>>>>>>>>> and the underlying thread reaches the "let's assign tasks" loop, >>>>>>>>>>>>> the logic >>>>>>>>>>>>> will be skipped (it's unuseful to assign tasks if a worker is >>>>>>>>>>>>> already >>>>>>>>>>>>> processing them). So it can happen that even if the "assignment" >>>>>>>>>>>>> time has >>>>>>>>>>>>> come, if the worker is processing tasks it will skip the >>>>>>>>>>>>> "assignment" >>>>>>>>>>>>> >>>>>>>>>>>>> Actually I have just seen the stop time, on average the task >>>>>>>>>>>>>> completes it cycle in just a few seconds (~1-2). Given that, is >>>>>>>>>>>>>> what you >>>>>>>>>>>>>> have suggested still valid? >>>>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>>>> Nope. As I said it guaranteed that even in the case that the >>>>>>>>>>>>> assignment loop falls into the timeframe of a RUNNING task, at >>>>>>>>>>>>> the next >>>>>>>>>>>>> round it will be picked up >>>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>>>>> Last but not least, demo1 has gone in timeout after one >>>>>>>>>>>>>> successful cycle, this is very odd, How I can debug the scheduler >>>>>>>>>>>>>> application and find its errors? >>>>>>>>>>>>>> I am running scheduler as a linux service, as described here: >>>>>>>>>>>>>> http://web2py.com/books/**defaul******** >>>>>>>>>>>>>> t/chapter/29/13#Start-**the-**sche******duler-as-a-Linux-** >>>>>>>>>>>>>> service-%**28up******start%29<http://web2py.com/books/default/chapter/29/13#Start-the-scheduler-as-a-Linux-service-%28upstart%29> >>>>>>>>>>>>>> >>>>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>>>> SQLite locking is the most probable cause. >>>>>>>>>>>>> The fastest way is to see what's happening is starting the >>>>>>>>>>>>> scheduler with debug logging .... >>>>>>>>>>>>> web2py.py -K appname -D 0 >>>>>>>>>>>>> >>>>>>>>>>>>> -- >>>>>>>>>>>>> >>>>>>>>>>>>> --- >>>>>>>>>>>>> You received this message because you are subscribed to a >>>>>>>>>>>>> topic in the Google Groups "web2py-users" group. >>>>>>>>>>>>> To unsubscribe from this topic, visit >>>>>>>>>>>>> https://groups.google.com/d/**to******pic/web2py/u_PgzKLuQmw/* >>>>>>>>>>>>> *unsubsc******ribe?hl=en<https://groups.google.com/d/topic/web2py/u_PgzKLuQmw/unsubscribe?hl=en> >>>>>>>>>>>>> . >>>>>>>>>>>>> To unsubscribe from this group and all its topics, send an >>>>>>>>>>>>> email to [email protected]. >>>>>>>>>>>>> For more options, visit https://groups.google.com/**grou****** >>>>>>>>>>>>> ps/opt_out <https://groups.google.com/groups/opt_out>. >>>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>>> >>>>>>>>>>>> -- >>>>>>>> >>>>>>>> --- >>>>>>>> You received this message because you are subscribed to a topic in >>>>>>>> the Google Groups "web2py-users" group. >>>>>>>> To unsubscribe from this topic, visit https://groups.google.com/d/* >>>>>>>> *to****pic/web2py/u_PgzKLuQmw/**unsubsc****ribe?hl=en<https://groups.google.com/d/topic/web2py/u_PgzKLuQmw/unsubscribe?hl=en> >>>>>>>> . >>>>>>>> To unsubscribe from this group and all its topics, send an email to >>>>>>>> web2py+un...@**googlegroups.com. >>>>>>>> For more options, visit https://groups.google.com/**grou**** >>>>>>>> ps/opt_out <https://groups.google.com/groups/opt_out>. >>>>>>>> >>>>>>>> >>>>>>>> >>>>>>> >>>>>>> >>>>>> -- >>>>> >>>>> --- >>>>> You received this message because you are subscribed to a topic in the >>>>> Google Groups "web2py-users" group. >>>>> To unsubscribe from this topic, visit https://groups.google.com/d/**to >>>>> **pic/web2py/u_PgzKLuQmw/**unsubsc**ribe?hl=en<https://groups.google.com/d/topic/web2py/u_PgzKLuQmw/unsubscribe?hl=en> >>>>> . >>>>> To unsubscribe from this group and all its topics, send an email to >>>>> web2py+un...@**googlegroups.com. >>>>> For more options, visit >>>>> https://groups.google.com/**grou**ps/opt_out<https://groups.google.com/groups/opt_out> >>>>> . >>>>> >>>>> >>>>> >>>> >>>> -- >>> >>> --- >>> You received this message because you are subscribed to a topic in the >>> Google Groups "web2py-users" group. >>> To unsubscribe from this topic, visit https://groups.google.com/d/** >>> topic/web2py/u_PgzKLuQmw/**unsubscribe?hl=en<https://groups.google.com/d/topic/web2py/u_PgzKLuQmw/unsubscribe?hl=en> >>> . >>> To unsubscribe from this group and all its topics, send an email to >>> web2py+un...@**googlegroups.com. >>> For more options, visit >>> https://groups.google.com/**groups/opt_out<https://groups.google.com/groups/opt_out> >>> . >>> >>> >>> >> >> -- > > --- > You received this message because you are subscribed to a topic in the > Google Groups "web2py-users" group. > To unsubscribe from this topic, visit > https://groups.google.com/d/topic/web2py/u_PgzKLuQmw/unsubscribe?hl=en. > To unsubscribe from this group and all its topics, send an email to > [email protected]. > For more options, visit https://groups.google.com/groups/opt_out. > > > -- --- You received this message because you are subscribed to the Google Groups "web2py-users" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. For more options, visit https://groups.google.com/groups/opt_out.
