logging library doesn't seem to work with spyder

[pidefrem]

Hello,

I'm trying to run a script using python standard library 'logging'. This script works fine from the command line but when run from Spyder, no log is printed.

My configuration is:
Windows 7
Python 2.7.10 :: Anaconda 2.3.0 (64-bit)
spyder-app 2.3.5.2

The script is:

# -*- coding: utf-8 -*-
"""
Simple test using logging
"""
import logging

# Logger configuration:
log_level = logging.DEBUG 
log_format = '%(levelname)s:%(message)s'

# Testing logger
logger = logging.root
logger.basicConfig = logging.basicConfig(format=log_format, filename='test.log', level=log_level)
logger.info('Testing logger (info)')
logger.debug('Testing logger (debug)')
logger.warning('Testing logger (warn)')
logger.info("")

[Nodd]

What do you expect to be printed exactly ? Your logger only writes to test.log, nothing should be shown in the console.

[pidefrem]

Hello,
thank you for the reply. Have you tried running it when you say "Your logger writes to leg.log"? This was my problem actually (not printing to the file test.log). I didn't mention the console in my question but printing to console doesn't seem to work on my version as well.

[Nodd]

Yes, I ran it and the file was created with the correct content. It also works in the console if I remove filename='test.log', (I mentionned the console because you said "no log is printed", it's just a misunderstanding, sorry).
Did you check the working directory ? Since test.log is a relative filename, it will be created in whatever directory you run it from.

[pidefrem]

Ok, thank you for taking the time to run it. It might then be specific to the IPython used by Spyder I have installed on my computer (installed with Anaconda). Thank you for the feedback. I'll just avoid using the log as the problem is not reproducible.

I simplified the script above, but my actual script uses the absolute path.

# -*- coding: utf-8 -*-
import os
import logging

# Global definitions:
workspace_path = 'My/absolute/path'
log_path = os.path.join(workspace_path, 'test.log')

# Logger configuration:
log_level = logging.DEBUG 
log_format = '%(message)s'

# Testing logger
logger = logging.root
logger.basicConfig = logging.basicConfig(format=log_format, filename=log_path, level=log_level)
#logger.basicConfig = logging.basicConfig(format=log_format, level=log_level)
logger.info('Testing logger (info)')
logger.debug('Testing logger (debug)')
logger.warning('Testing logger (warn)')
logger.info("")

[Nodd]

Sorry for all the stupid question, it's only to make sure that we missed nothing obvious. Did you check if there was anything printed in the internal console ? If it's not opened, you can activate it in the Panes submenu.

My setup is quite different (I run the master branch under Linux with python3 from the system), maybe it's reproducible on windows or with python2.

[SunPowerMike]

I'm having a similar issue. The script below runs, and creates the log file in the correct location with the correct information when i run it from 1) DOS window, or 2) double clicking on a *.py file with this inside of it. But when I run it from within Spyder, either 1) using "run file" or, 2) typing into the ipython window, it prints the Warning to the console, but does not create the file.

import logging
logging.basicConfig(filename='c:\temp\logfile13.log',level=logging.DEBUG)
logging.debug('This message should go to the log file')
logging.info('So should this')
logging.warning('And this, too')

Running Python 2.7.9 (default, Dec 10 2014, 12:28:03) [MSC v.1500 64 bit (AMD64)] on win32
Spyder 2.3.7

[TimGJ]

I have the same.

If I run the following code

if __name__ == '__main__':

    logging.basicConfig(format="%(asctime)s: [%(levelname)s], %(message)s", 
                        filename="trafficlight.log", level=logging.DEBUG)
    logging.info("Started")
    for i in range(10):
        logging.debug("Hello #{}".format(i))
    logging.info("Finished!")

from the console I get the expected output

2015-10-26 14:19:30,024: [INFO], Started
2015-10-26 14:19:30,024: [DEBUG], Hello #0
2015-10-26 14:19:30,024: [DEBUG], Hello #1
2015-10-26 14:19:30,025: [DEBUG], Hello #2
2015-10-26 14:19:30,025: [DEBUG], Hello #3
2015-10-26 14:19:30,025: [DEBUG], Hello #4
2015-10-26 14:19:30,025: [DEBUG], Hello #5
2015-10-26 14:19:30,025: [DEBUG], Hello #6
2015-10-26 14:19:30,025: [DEBUG], Hello #7
2015-10-26 14:19:30,025: [DEBUG], Hello #8
2015-10-26 14:19:30,025: [DEBUG], Hello #9
2015-10-26 14:19:30,025: [INFO], Finished!

but nothing if I run it from the Spyder. If I do a logging.warning or logging.error in Spyder I get a message written to the console, but not in the format I have specified. So it's as if there is a logger running where level = logging.INFO but my own newly created logger is being ignored.

I'm running Spyder 2.3.0 Python 3.4.3 64bits, Qt 4.8.6, PyQt4 (API v2) 4.10.4 on Linux

[ccordoba12]

We'll see what to do about this problem for Spyder 3.0 (to be released at the end of the year :-)

[anduls]

I have probably the same: Ubuntu 14.04, spyder 2.3.6 , ipython 4.0.0.

logging.basicConfig(level=logging.DEBUG,format='%(name)s : %(levelname)s : %(module)s.%(funcName)s : line %(lineno)-6d %(message)s')

logger does not show the format tags as line number, module name etc. only the logger level and message. It works with ipython 4.0.0 in a shell.

[channerduan01]

I have absolutely the same problem! OS X 10.10.5, spyder 2.3.8, python 2.7.11

'logging.basicConfig' does not work in spyder.

It makes me inconvenient to use some third party packages~

[Nodd]

For information I still can't reproduce the problem (Linux, python3, master branch), with python or IPython consoles.

[ccordoba12]

I think this was solved in the latest version of ipykernel.

[robbuckley]

hi
i have a similar same issue.

spyder 2.3.9, win64, python 2.7.12, ipython 5.0.0

logging.basiconfig() does not work for me with the ipython console.
workaround (1): if i select Run/Configure/console = '..new dedicated Python console' or '..external sytstem terminal' i getting logging output as expected.

workaround(2): this sequence works fine, also in the ipython console. Im pretty sure that was not the case with ipython 4.2.0

#logging.basicConfig(filename="test.log",level=logging.DEBUG)
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

# create file handler which logs even debug messages
fh = logging.FileHandler('test.log')
fh.setLevel(logging.DEBUG)
# create console handler with a higher log level
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
# create formatter and add it to the handlers
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)
# add the handlers to the logger
logger.addHandler(fh)
logger.addHandler(ch)

But i do have to manuallly close the console in order to be able to delete the log file from windows

[versatran01]

I have the same issue. I'm using spyder 3.0.0b4, ipython 5.0.0, ubuntu 16.04.1
I just did

import logging
logging.basicConfig(level=logging.INFO)
logging.info('test')

This works in normal ipython, but prints nothing in spyder ipython.
Is there a setting I need to change? or is this a spyder issue? Thanks!

[ccordoba12]

This seems to be a problem with Qtconsole, at least according to this StackOverflow post:

http://stackoverflow.com/questions/24259952/logging-module-does-not-print-in-ipython

For all interested folks, there you can also find a solution to make logging work as expected :-)

---

@minrk or @takluyver, is it ok for us to remove the logging handlers added to QtConsole to make the logging module work on it?

[takluyver]

I don't think the logging on the Qt console would affect this, because user code runs in the kernel. There has been an issue with logging in the kernel, and that should be fixed with the upcoming 4.4 release. ipython/ipykernel#127

[ccordoba12]

This problem was fixed in ipykernel 4.4, so please update to that version.

[yw5aj]

The code snippet above (#2572 (comment)) still won't work as of today (2017/10/5) with the latest Anaconda 64 bit Python 3.6 under Windows 10 64 bit.

Python 3.6.2
IPython 6.1.0
Spyder 3.2.3
ipykernel.__version__ == '4.6.1'

[FrenchKheldar]

Correct this is still completely broken in Spyder 3.2.6, ipykernel.version == '4.6.1'

For example:

import logging
import sys

print(logging.__version__)
logging.basicConfig(format="%(message)s",level=logging.INFO,stream=sys.stdout)
#logger = logging.getLogger(__name__)
logger = logging.getLogger()
#logger.setlevel(logging.INFO)

logger.info('Start reading database')
# read database here
records = {'john': 55, 'tom': 66}
logger.debug('Records: %s', records)
logger.info('Updating records ...')
# update records here
logger.info('Finish updating records')

outputs

INFO:root:Start reading database
DEBUG:root:Records: {'john': 55, 'tom': 66}
INFO:root:Updating records ...
INFO:root:Finish updating records
0.5.1.2

The debug statement should not be shown.

Also, if I uncomment logger.setlevel(logging.INFO) I get

AttributeError: 'RootLogger' object has no attribute 'setlevel'

Hopefully this is easy to fix and/or I'm not configuring something right.

[bilderbuchi]

Also, if I uncomment logger.setlevel(logging.INFO) I get

At least that part is easily solvable, the name of the method it setLevel, not setlevel. :-)

[FrenchKheldar]

OK, thank you for that, my mistake. The problem remains that basically whatever is specified using basicConfig is simply ignored by spyder. From what I understand, there is another module imported by spyder that uses logging and that is why the commands above are ignored. Is that correct?

Doing more poking... This logging.getLogger('root').handlers = [] removes all output, which confirms the root logger is active.

[ccordoba12]

What happens if you run the same code in the Jupyter notebook?

[FrenchKheldar]

It works better. Although I can see that some settings are sticky when I rerun the cell after changing things in basicConfig. Should I somehow stop/kill the logger at the end of my program to make sure it does not stay in the background? Can't copy from Jupyter so let me know if you want me to screenshot some of the output...

[FrenchKheldar]

OK so per python documentation https://docs.python.org/3.6/howto/logging.html:

The call to basicConfig() should come before any calls to debug(), info() etc. As it’s intended as a one-off simple configuration facility, only the first call will actually do anything: subsequent calls are effectively no-ops.

I believe I'm seeing that effect. Is this thread related? jupyter/notebook#1397

And that last thread led me to the solution I think:
https://stackoverflow.com/questions/18786912/get-output-from-the-logging-module-in-ipython-notebook/21475297#21475297

Since I'm running python 3.6:

import logging
import importlib
importlib.reload(logging)
import sys

print(logging.__version__)
logging.basicConfig(format="%(message)s",level=logging.DEBUG,stream=sys.stdout)
#logger = logging.getLogger(__name__)
logger = logging.getLogger("")
#logger.setLevel(logging.INFO)

logger.info('Start reading database')
# read database here
records = {'john': 55, 'tom': 66}
logger.debug('Records: %s', records)
logger.info('Updating records ...')
# update records here
logger.info('Finish updating records')

produces the right behavior. And if I uncomment the setLevel line, the DEBUG output disappears as expected !

Not sure whether I'm messing up something else in spyder by reloading logging, but right it seems to fix my issue.

Hope this helps !

[bilderbuchi]

Question is: which component silently calls basicconfig in the background? Spider? Ipython? I'm not sure either should do that in the user's interpreter session, right?

[agrechnev]

Did you try "Execute in a dedicated console" and close the console every time the program finishes?

Or "Execute in an external system terminal"?

[elgplayer]

A bug that I encounterd with spyder and logging is that if you run a script that logs multiple times, it will log as many times as you have run the script.

So I ran a script 4 times, and it printed:

[2019-01-13 13:47:10] INFO --- Started (trades.py:26) [2019-01-13 13:47:10] INFO --- Started (trades.py:26) [2019-01-13 13:47:10] INFO --- Started (trades.py:26) [2019-01-13 13:47:10] INFO --- Started (trades.py:26)

Any ideas on how to remove this?

Also, when run a script with logging that outputs to a file, you need to close spyder to delete that file.

[bilderbuchi]

Probably it's better to report this in a new issue instead of this one, which is closed and about a different logging problem.

[ccordoba12]

I agree. @elgplayer, please open a new issue about it.

[gokhalen]

I am running Spyder 4.1.3 on Windows 8 under Anaconda, with python 3.8.3.
I am trying to run the following code:

import logging
logging.basicConfig(level=logging.ERROR)
log=logging.getLogger(__name__)

if __name__ == '__main__':
    log.debug('Debug message')
    log.info('Info message')
    log.warning('Warning message')
    log.error('Error message')
    log.critical('Critical message')

This code runs correctly the first time I run it inside a clean, new console. However, if I change the level to something else, e.g. logging.basicConfig(level=logging.DEBUG) and save the file, then that change is not reflected in the current console. I need to open a new console to make it see the new log level.

[ccordoba12]

If you modify your code a little bit, you'll be able to change your logging level without creating a new console:

import logging
log=logging.getLogger(__name__)
log.setLevel(logging.ERROR)

if __name__ == '__main__':
    log.debug('Debug message')
    log.info('Info message')
    log.warning('Warning message')
    log.error('Error message')
    log.critical('Critical message')

[ccordoba12]

@gokhalen, your use case also seems fixed in Python 3.8, by passing a new parameter called force=True to basicConfig so it can be reset each time you run new code.

[jgriffin2]

Thanks! force=True worked on my system Mac, Python 3.8.1, Spyder 4.1.3)

[PreetiMishra89]

I am having the same issue.
logging works well in vs code but somehow doesn't work in spyder.