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.

On Jun 12, 2006, at 6:54 AM, Richard Clark wrote:

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

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!

On 13/06/2006, at 1:29, Richard Clark wrote:

Nice to know I've guessed right :)

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

Thanks!
Alberto

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

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

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.

On 6/12/06, Richard Clark <richard.cl...@gmail.com> wrote:

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