Setting a loglevel for logfiles

[LuckyJosh]

Hi,

I would like to set the logging level for a logfile to DEBUG but leave the logging level
for the console log at INFO, to log debug information to the logfile without cluttering the console.
For example by defining a custom logger via

logzero.setup_logger(logfile="custom_logfile.log", level=logging.INFO, fileLoglevel=logging.DEBUG).

This does not work as I expected. After some testing I came to the conclusion that
the loglevel set via fileLoglevel can not be lower (only higher) than the loglevel set via level.
If a lower level is set via fileLoglevel it gets overwritten by level.

Is there a specific reason for this behavior?

[metachris]

I would discourage you from using setup_logger. The default logger is already setup, and you can configure it more easily and more versatile:

• Use logzero.loglevel(level=logging.DEBUG, update_custom_handlers=False) to setup the general loglevel
• Use logzero.logfile(filename, formatter=None, mode='a', maxBytes=0, backupCount=0, encoding=None, loglevel=None) to setup the logfile with a specific loglevel for the file only. This will not get overwritten by logzero.loglevel(..)

Does that work for you like this?

[LuckyJosh]

Hi,
thanks for the fast reply!
I started out with the default logger and thought I might need the custom one to achieve this.
It still does not work the way I would want it to work but maybe there is a reason for this.

Following I have my test script to highlight my issue a bit better:

# logtesting.py
#! /usr/bin/env python
# encoding: utf-8

import logging
import logzero
from logzero import logger

# setting up loglevel for console logging
logzero.loglevel(level=logging.INFO, update_custom_handlers=False)

# first logging without logfile
logger.error("Loglevel set to INFO, no logfile.")

logger.debug("DEBUG message")      # no console output (expected)
logger.info("INFO message")        # console output
logger.warning("WARNING message")  # console output
logger.error("ERROR message")      # console output

# setting up logfile with same loglevel INFO
logzero.logfile("info.log", formatter=None, mode='a', maxBytes=0, backupCount=0, encoding=None, loglevel=logging.INFO)

# second logging with logfile
logger.error("Loglevel set to INFO, logfile with loglevel set to INFO.")

logger.debug("DEBUG message")      # no console output (expected), no logfile output (expected)
logger.info("INFO message")        # console output, logfile output
logger.warning("WARNING message")  # console output, logfile output
logger.error("ERROR message")      # console output, logfile output

# setting up logfile with higher loglevel WARNING
logzero.logfile("warning.log", formatter=None, mode='a', maxBytes=0, backupCount=0, encoding=None, loglevel=logging.WARNING)

# third logging with logfile
logger.error("Loglevel set to INFO, logfile with loglevel set to WARNING.")

logger.debug("DEBUG message")      # no console output (expected), no logfile output (expected)
logger.info("INFO message")        # console output, no logfile output (expected)
logger.warning("WARNING message")  # console output, logfile output
logger.error("ERROR message")      # console output, logfile output


# setting up logfile with lower loglevel DEBUG
logzero.logfile("debug.log", formatter=None, mode='a', maxBytes=0, backupCount=0, encoding=None, loglevel=logging.DEBUG)

# fourth logging with logfile
logger.error("Loglevel set to INFO, logfile with loglevel set to DEBUG.")

logger.debug("DEBUG message")      # no console output (expected), no logfile output (unexpected!)
logger.info("INFO message")        # console output, logfile output
logger.warning("WARNING message")  # console output, logfile output
logger.error("ERROR message")      # console output, logfile output

This produces the following console output:

[E 171107 17:01:57 logtesting:12] Loglevel set to INFO, no logfile.
[I 171107 17:01:57 logtesting:15] INFO message
[W 171107 17:01:57 logtesting:16] WARNING message
[E 171107 17:01:57 logtesting:17] ERROR message
[E 171107 17:01:57 logtesting:23] Loglevel set to INFO, logfile with loglevel set to INFO.
[I 171107 17:01:57 logtesting:26] INFO message
[W 171107 17:01:57 logtesting:27] WARNING message
[E 171107 17:01:57 logtesting:28] ERROR message
[E 171107 17:01:57 logtesting:33] Loglevel set to INFO, logfile with loglevel set to WARNING.
[I 171107 17:01:57 logtesting:36] INFO message
[W 171107 17:01:57 logtesting:37] WARNING message
[E 171107 17:01:57 logtesting:38] ERROR message
[E 171107 17:01:57 logtesting:44] Loglevel set to INFO, logfile with loglevel set to DEBUG.
[I 171107 17:01:57 logtesting:47] INFO message
[W 171107 17:01:57 logtesting:48] WARNING message
[E 171107 17:01:57 logtesting:49] ERROR message

This output is just like i would have expected.

The three logfiles contain the following lines:

# info.log
[E 171107 17:05:05 logtesting:23] Loglevel set to INFO, logfile with loglevel set to INFO.
[I 171107 17:05:05 logtesting:26] INFO message
[W 171107 17:05:05 logtesting:27] WARNING message
[E 171107 17:05:05 logtesting:28] ERROR message

Also just like expected.

# warning.log
[E 171107 17:05:05 logtesting:33] Loglevel set to INFO, logfile with loglevel set to WARNING.
[W 171107 17:05:05 logtesting:37] WARNING message
[E 171107 17:05:05 logtesting:38] ERROR message

Also just like expected.

#debug.log
[E 171107 17:05:05 logtesting:44] Loglevel set to INFO, logfile with loglevel set to DEBUG.
[I 171107 17:05:05 logtesting:47] INFO message
[W 171107 17:05:05 logtesting:48] WARNING message
[E 171107 17:05:05 logtesting:49] ERROR message

In this one I would have expected a "DEBUG message" .

[metachris]

Thanks for the example. Yeah, I would also expect the DEBUG message in there. Will take a look tomorrow!

[LuckyJosh]

Thank you, I very much appreciate your support!

[LuckyJosh]

I have to admit that it did not occur to me until now that the cause of this "problem" might lie in the logging library itself. And it seems to be the case as can be seen in these to stackoverflow threads here or here.
The issue seems to be that one handler is not enough for this purpose. You need to create a StreamHandler and a FileHandler with their respective logleves and the loglevel of the logger has to be the smaller one of those two.

[metachris]

Oh, okay. Thanks for the research and information. I'll take a look when I find the time.

[mgiaco]

It would also be great if the console could be disable if needed. I do not find any way without changing the code.

[alekna]

The workaround to this problem is to change log level of StreamHandler handler directly without touching logzero.logger.level.

Not a nice way, but works for me:

logzero.logfile('test.log', loglevel=logging.DEBUG)
logzero.logger.handlers[0].level = logging.INFO

Logzero could easily abstract this bug away in a nice way.

[LuckyJosh]

@alekna
Yes, you are right, there are definitely workarounds for this.

However it just seems to defy the purpose of this package to interact with the handlers directly, so I refrained from using one up to now.

But I think as far as workarounds go the one you suggested is quite nice, actually, might give it a try. 👍

[TheButlah]

having a logzero.logstream to abstract interaction with the StreamHandler like logzero.logfile abstracts interaction with the FileHandler would be really nice. I'm having the same issue where I want the file to have a lower log level than the stream, and I can't do it without the hacky method mentioned by @alekna

[yaiqsa]

@metachris

I would discourage you from using setup_logger. The default logger is already setup, and you can configure it more easily and more versatile:

* Use `logzero.loglevel(level=logging.DEBUG, update_custom_handlers=False)` to setup the general loglevel

* Use `logzero.logfile(filename, formatter=None, mode='a', maxBytes=0, backupCount=0, encoding=None, loglevel=None)` to setup the logfile with a specific `loglevel` for the file only. This will not get overwritten by `logzero.loglevel(..)`

Does that work for you like this?

I sort of had the same issue because I used the setup_logger function, which doesn't seem to work as expected. (The following snippet turned out to work for me)

log = logzero.setup_logger(logfile='log.log', level=50, fileLoglevel=10)
log.level = 10

I didn't find any warnings in the documentation that the function shouldn't be used(in this way), so it confused me until I found this reaction of yours. Would it be possible to either fix the behaviour, or mention somewhere that it shouldn't be used like this?

[metachris]

Thanks for the reports and discussion. I'm taking a fresh look at this now.
Anyone still around and motivated to take a look at a possible approach?

[metachris]

Please take a look at the fix/implementation in #339 - i think that will work.

[LuckyJosh]

First of all I have to admit that I am on some kind of a hiatus from programming in general,
and I have not looked into this issue in particular for quite some time.
But I still wanted to give my two cents:

I just ran my test file posted above (using the current version 1.5.0) and the behaviour has not changed.
The logfile debug.log still does not contain the message at DEBUG-level.
Furthermore, looking at #339 I dont get the impression that the changes made there could have fixed this issue.

[metachris]

Thanks for the message. I'm sorry, I've accidentally referenced the wrong PR :) This is the correct one: #338

To test it you'd need to checkout that branch (logfile-loglevel).

Furthermore, wishing you all the best on your hiatus. What are you up to these days?

[LuckyJosh]

Sorry, for the late answer.
Thanks for your kind wishes. : )
Im currently in the transition phase from physics/data-analysis to physics/math-education.