Django 1.3 logging not working as I'd expect

[Scott Danzig]

I have Django 1.3 working with Python 2.7 and MySQL 5.5 on Mac OSX Lion...

I'm betting I'm missing something straight forward, but:

I have a simple Django app in development that uses a dictConfig setting simpler than the default in settings.py:

LOGGING = {

    'version': 1,

    'disable_existing_loggers': False,

    'formatters': {

        'verbose': {

            'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'

        },

    },

    'handlers': {

        'console':{

            'level':'DEBUG',

            'class':'logging.StreamHandler',

            'formatter': 'verbose'

        },

        'file':{

            'level':'DEBUG',

            'class':'logging.FileHandler',

            'formatter': 'verbose',

            'filename': 'testdjango.log',

        },

    },

    'loggers': {

        'testlogger': {

            'handlers': ['console','file'],

            'level': 'DEBUG',

            'propagate': True,

       },

    },

}

Then later in code that I know is run... (I tried in my app's views.py and also the backend).. I put something like this:

import logging

logger = logging.getLogger('testlogger')

logger.warn('hello')

logger.info('please appear')

And I just don't see it, neither in the console, nor the file.

I have also tried something like this:

import logging

logger = logging.getLogger('otherlogger')

hdlr = logging.FileHandler('newlogger.log')

formatter = logging.Formatter('%(asctime)s %(levelname)s %(message)s')

hdlr.setFormatter(formatter)

logger.addHandler(hdlr) 

logger.setLevel(logging.DEBUG)

logger.warn('In settings.py!')

And that doesn't work either, unless I put it right in settings.py.. in which case it appears 4 times, because, from what I understand, settings.py gets loaded that many times.  But then this doesn't work in the views.py/backend .. perhaps because the dictConfig gets loaded after settings.py is run?  I don't know.

I'm hoping for someone to give me a heads up about what I'm missing here.  Django's been pretty easy to deal with until I started to look into logging.

Thanks.

[Reinout van Rees]

On 20-08-11 06:51, Scott Danzig wrote:
>
> I have a simple Django app in development that uses a dictConfig setting
> simpler than the default in settings.py:
>
> LOGGING = {

[snip]

> }
>
> Then later in code that I know is run... (I tried in my app's views.py
> and also the backend).. I put something like this:
>
> import logging
> logger = logging.getLogger('testlogger')
> logger.warn('hello')
> logger.info('please appear')
>
> And I just don't see it, neither in the console, nor the file.

Probably all your logging statements are executed right at file import
time before the logging is actually configured.

Just as a simple test, put such a logging statement inside one of your
view methods and hit it in your browser. Just to make sure your logging
setup as such works.

Reinout

--
Reinout van Rees http://reinout.vanrees.org/
rei...@vanrees.org http://www.nelen-schuurmans.nl/
"If you're not sure what to do, make something. -- Paul Graham"

[bruno desthuilliers]

On 22 août, 13:27, Reinout van Rees <rein...@vanrees.org> wrote:
>
> Probably all your logging statements are executed right at file import
> time before the logging is actually configured.

Using the DictConfig in settings.py, the logger is configured before
the apps models / views / whatever are imported.

@Scott: Are you running the dev server ? If yes, the settings module
should be imported "only" twice so you may import it directly (ie:
"import settings") from your app. If yes, replace this with "from
django.conf import settings", which is the right way to access the
settings from an app.

[Gelonida N]

You have to be sure, that logging is configured before actually logging
anything.

So before your three lines:

> import logging
> logger = logging.getLogger('otherlogger')

> logger.warn('hello')
you had to be sure, that the django settings and thus the logging
configuration has really been completed.

You could for example add following two lines before:
> from django.conf import settings
> LOGGING = settings.LOGGING # force import

The second line is needed, as the first line is a 'lazy import' and will
only read the settings and configure logging when you access the first
time a element of settings.
I just used settings.LOGGING, as it should always exist, when you try to
log.

I am not sure whether there is a more elegant solution.
When I asked this question recently on this list, I didn't receive any
other suggestions.

> And that doesn't work either, unless I put it right in settings.py.. in
> which case it appears 4 times, because, from what I understand,
> settings.py gets loaded that many times. But then this doesn't work in
> the views.py/backend .. perhaps because the dictConfig gets loaded after
> settings.py is run? I don't know.
>
> I'm hoping for someone to give me a heads up about what I'm missing
> here. Django's been pretty easy to deal with until I started to look
> into logging.
>
> Thanks.
>

> --
> You received this message because you are subscribed to the Google
> Groups "Django users" group.
> To view this discussion on the web visit
> https://groups.google.com/d/msg/django-users/-/JvmqgFNPMu4J.
> To post to this group, send email to django...@googlegroups.com.
> To unsubscribe from this group, send email to
> django-users...@googlegroups.com.
> For more options, visit this group at
> http://groups.google.com/group/django-users?hl=en.

[Scott Danzig]

@Reinout: Thanks, but yeah, already tried logging from a view function..
didn't work...

@Bruno: Yeah, I am using the dev server. I have been using from django.conf
import settings within my app to access settings..although unless I do
something like what Gelondia suggested... with the LOGGING =
settings.LOGGING, I'm not sure how the logging normally "invokes" the
settings. The way I see it, django magically loads the settings at some
point in the background, then when you use the logging, it accesses those
settings, and there's a certain time when these settings become accessible
so this works. But it's not working like this, so perhaps I'm mistaken. So
you're saying to replace all instances of "from django.conf import settings"
with just "import settings"? Or the other way around? Not sure about what
importing only twice does, and how importing settings more or less affects
this.

Thanks all for answering.
--
View this message in context: http://old.nabble.com/Django-1.3-logging-not-working-as-I%27d-expect-tp32299898p32349226.html
Sent from the django-users mailing list archive at Nabble.com.

[Scott Danzig]

Gelonida N wrote:
>
> On 08/20/2011 06:51 AM, Scott Danzig wrote:
> You have to be sure, that logging is configured before actually logging
> anything.
>
> So before your three lines:
>> import logging
>> logger = logging.getLogger('otherlogger')
>> logger.warn('hello')
> you had to be sure, that the django settings and thus the logging
> configuration has really been completed.
>
> You could for example add following two lines before:
>> from django.conf import settings
>> LOGGING = settings.LOGGING # force import
>
> The second line is needed, as the first line is a 'lazy import' and will
> only read the settings and configure logging when you access the first
> time a element of settings.
> I just used settings.LOGGING, as it should always exist, when you try to
> log.
>

Thanks Gelonida.. tried your suggestion and added those two lines before my
import logging ... unfortunately no change. Perhaps it's not
straightforward. Sounds like it wasn't obvious to you either.
--
View this message in context: http://old.nabble.com/Django-1.3-logging-not-working-as-I%27d-expect-tp32299898p32349240.html

[Gelonida N]

On 08/28/2011 12:00 AM, Scott Danzig wrote:

>
>
> Gelonida N wrote:
>> So before your three lines:
>>> import logging
>>> logger = logging.getLogger('otherlogger')
>>> logger.warn('hello')
>> you had to be sure, that the django settings and thus the logging
>> configuration has really been completed.
>>
>> You could for example add following two lines before:
>>> from django.conf import settings
>>> LOGGING = settings.LOGGING # force import
>>
>> The second line is needed, as the first line is a 'lazy import' and will
>> only read the settings and configure logging when you access the first
>> time a element of settings.
>> I just used settings.LOGGING, as it should always exist, when you try to
>> log.
>>
>
> Thanks Gelonida.. tried your suggestion and added those two lines before my
> import logging ... unfortunately no change. Perhaps it's not
> straightforward. Sounds like it wasn't obvious to you either.

That's weird.
This works fine for me.

Just some more things to test:

Is ee, that you didn't add a root logger in your
log config.

you could add following two handlers.

'loggers': {
# root loggers
'': {
'handlers': ['console'],
'level': 'WARNING', # or 'DEBUG'
'propagate': True,
},
# not sure if this is really useful
'root': {
'handlers': ['console'],
'level': 'WARNING', # or 'DEBUG'
'propagate': True,
},

If this doesn't help you could add some print statements to be sure,
that your settings file is really read.

You could add a print statement after the assignment of
LOGGING in settings.py

LOGGING={ .. ..}
print "LOGGING VARIABLE IS SET NOW"

and in your file.

print "CHECKPOINT 1"
from django.conf import settings
print "CHECKPOINT 2"

LOGGING = settings.LOGGING # force import

print "CHECKPOINT 3"

import logging
logger = logging.getLogger('otherlogger')

print "CHECKPOINT 4"
logger.warn('hello')
print "CHECKPOINT 5"

What do you get as output?

[Scott Danzig]

Okay.. update.. it does seem to work right, even without forcing the
initialization as you suggested.. which is a relief.. Was losing my mind
(maybe Django 1.3 doesn't require the settings.LOGGING?) While testing with
prints, I realized the view function I thought should be called wasn't
called until AFTER login.. Oops :)

Thanks all.

> --
> You received this message because you are subscribed to the Google Groups
> "Django users" group.

> To post to this group, send email to django...@googlegroups.com.
> To unsubscribe from this group, send email to
> django-users...@googlegroups.com.
> For more options, visit this group at
> http://groups.google.com/group/django-users?hl=en.
>
>
>

--
View this message in context: http://old.nabble.com/Django-1.3-logging-not-working-as-I%27d-expect-tp32299898p32349771.html

[Gelonida N]

On 08/28/2011 03:43 AM, Scott Danzig wrote:
>
> Okay.. update.. it does seem to work right, even without forcing the
> initialization as you suggested.. which is a relief.. Was losing my mind
> (maybe Django 1.3 doesn't require the settings.LOGGING?) While testing with
> prints, I realized the view function I thought should be called wasn't
> called until AFTER login.. Oops :)
>
> Thanks all.

Just for your info.

Forcing the import of 'settings.py' with the two lines, that I suggested
might be required in case, that your module might be
THE module using as very first module settings.py.

This is probaly NEVER the case when running in a 'normal' environment.

However for debugging I import some of my modules from a command line
script, which just sets
sys.path and
os.environ['DJANGO_SETTINGS_MODULE']

In this case you had to force the evaluation of settings.py before
creating a logger.

[Alexey Luchko]

Hi,

try executing

import logging
logger = logging.getLogger('testlogger')
logger.warn('hello')
logger.info('please appear')

in ./manage shell.

--
Alex