call_on_startup, called twice?

[Richard Clark]

Not really sure what's going on here, I'm really scratching my head.

I'm using call_on_startup to fire up a couple of threads, one which
performs background processing, and another which logs into a jabber
conference and provides logging services.

The problem is that any function I add to call_on_startup gets called
twice, and worse, this appears to happen in two independant forks
because no amount of attempted thread syncronisation allows me to
detect that it has previously been called.

It's really really spooky, for example, the "offending" code is in
startup.py:

for item in call_on_startup:
item()

Looks simple enough, but if I change it to this:

for item in call_on_startup:
log.info("Thingy starting: %s" % str(item))
item(random.randint(0,1000))
log.info("Thingy started: %s" % str(item))

and do this in controllers.py:

turbogears.startup.call_on_startup = [lambda x: log.debug("Foo: %d" %
x)]

I get the following in the log:

2006-06-12 16:48:26,202 turbogears.startup INFO Thingy starting:
<function <lambda> at 0xb7348b8c>
2006-06-12 16:48:26,280 dmt.controllers DEBUG Foo: 769
2006-06-12 16:48:26,280 dmt.controllers DEBUG Foo: 769
2006-06-12 16:48:26,280 turbogears.startup INFO Thingy started:
<function <lambda> at 0xb7348b8c>

Ie, the logs bracketting the call only get called once, but the lambda
gets called twice, and with exactly the same random number no less.

I'm gonna keep working on it, gonna try on a few different machines and
see if I see the same behaviour, it's really creepy. But I figured i'd
put this here in case anyone else has seen the same behaviour or later
goes searching for it.

[Alberto Valverde]

Hmmm, interesting.... I've notice similar behaviour but didn't really
dig too much into it as the double-called code didn't cause any
trouble...

Could this be related to TG logging perhaps? I mean, *maybe* the code
is called just once but the message is logged twice... just a guess.

Hope I didn't add much more creepyness into the issue ;)

Alberto

[Richard Clark]

I have in fact discovered what it was, I discovered it about half an
hour after that post but it took a while for the post to turn up :)

It was in fact double-logging. The default dev.cfg logging
configuration appears to send the log to stdout twice for anything in
the <projectname>.* heirachy.

I simply changed handlers=['debug_out'] to handlers=[] in the dev.cfg
logger config and it fixed the double logging. Probably not the best
solution but at least it stopped confusing me so much :)

Thanks for the message anyway!

[Alberto Valverde]

On 13/06/2006, at 1:29, Richard Clark wrote:
> I have in fact discovered what it was, I discovered it about half an
> hour after that post but it took a while for the post to turn up :)
>
> It was in fact double-logging. The default dev.cfg logging
> configuration appears to send the log to stdout twice for anything in
> the <projectname>.* heirachy.

Nice to know I've guessed right :)

> I simply changed handlers=['debug_out'] to handlers=[] in the dev.cfg
> logger config and it fixed the double logging. Probably not the best
> solution but at least it stopped confusing me so much :)

Maybe this fix could go upstream into 1.0b1. Going to open a ticket
linking to this thread.

Thanks!
Alberto

[Randall]

I'm using svn 1587

I'm having a similar problem and I'm pretty sure it is executing twice
on startup. I didn't trust stanard output, so within the code, I
appended text to a file. The code being run twice is a widget creation
function. When its module is imported, the widget is created with info
from the db like so:

*************************************************************
# module mywidgets.py

def createMyWidget():
# ...
# get info from db
file('/tmp/tglog.txt', 'ab').write('widget created \n') # Log to
file.
print 'my_widget was created'
return widget

my_widget = createMyWidget()
*************************************************************

Currently, this widget is being imported and used by a form widget
elsewhere like this:

from myproj.mywidgets import my_widget

form = TableForm(..., fields=[..., my_widget])

When I start up turbogears, /tmp/tglog.txt has two entries and
'my_widget was created' is on the stdout twice. This bothers me
because it is not necessary and is making two trips to the database.

Randall

[Randall]

I realize now that my message is not completely relevant to the topic
since it doesn't use the call_on_startup feature.

[Kaan]

I'm not quite sure how your code is organized, but perhaps you could
place the database access and/or logging code under the __init__ method
of your widget class? That way, the code should only be executed when
you instantiate the widget.

[Andrew Grover]

It appears that filtering on qualname works, but filtering on level
does not Therefore the [[[projectname]]] and [[[allinfo]]] loggers
are both catching all levels and sending it to debug_out twice.

Is this a ConfigObj issue?

Regards -- Andy