classification
Title: facilitate log output starting at beginning of line
Type: enhancement Stage:
Components: Library (Lib) Versions: Python 3.4
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: chris.jerdonek, ezio.melotti, michael.foord, r.david.murray, vinay.sajip
Priority: normal Keywords:

Created on 2013-01-08 01:58 by chris.jerdonek, last changed 2013-01-08 15:36 by vinay.sajip.

Messages (9)
msg179304 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2013-01-08 01:58
In certain situations (e.g. when logging while using unittest), log messages can start in the middle of a line, for example:

........................log: [INFO] foo
..................................................

It was trickier than I thought it needed to be to get log messages to start at the beginning of a line, which seems like a reasonable expectation.

It would be good if the logging module (or perhaps unittest for when running tests?) provided assistance here, either through documentation or an enhancement.

The way I did this was wrap sys.stderr in a class that remembers the last written character, pass this to the test runner, and then subclass logging.StreamHandler to have emit() check whether a newline was the last character.  But perhaps there is a much simpler way.
msg179330 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2013-01-08 11:02
I agree this is a reasonable expectation, but I've not encountered this problem before. Can you provide a short script demonstrating the problem?
Which platform did you encounter these problems on, and what was the logging configuration?
msg179334 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2013-01-08 11:29
This can happen with any standard logging configuration when there are writes to sys.stderr that don't end with "\n".  I'm using Mac OS X 10.7.  A minimal script:

import logging, unittest

log = logging.getLogger()

class Test(unittest.TestCase):
    def setUp(self):
        log.info("setting up")
    def test1(self):
        pass
    def test2(self):
        pass

logging.basicConfig(level=logging.INFO)
unittest.main()

Output:

INFO:root:setting up
.INFO:root:setting up
.
----------------------------------------------------------------------
Ran 2 tests in 0.001s
msg179337 - (view) Author: Ezio Melotti (ezio.melotti) * (Python committer) Date: 2013-01-08 11:36
Note that for this specific problem you could call unittest.main(verbosity=0).
msg179339 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2013-01-08 11:42
Oh, I see what you mean now. I guess the approach you used is straightforward, and perhaps something could be added to test.support. It's only an aesthetic thing, though, IIUC.

I normally don't run into this because I log to file when running unit tests, or run with -v so that the runner prints complete lines rather than just dots. And if you need to test that logging is happening, you can use the TestHandler and Matcher classes in test.support.
msg179340 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2013-01-08 11:47
Ezio, the use case is to add to the existing test output additional diagnostic logging.  In particular, you might want to run tests even with verbosity=2 in addition to the log messages.
msg179341 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2013-01-08 12:08
Yes, it's primarily for easier scanning/reading as well as aesthetic.  With -v I get the following output though:

test1 (test_logging.Test) ... INFO:root:setting up
ok
test2 (test_logging.Test) ... INFO:root:setting up
ok

----------------------------------------------------------------------
Ran 2 tests in 0.000s

At least it's good to know that I wasn't missing anything obvious.  And yes, I did read about TestHandler/Matcher (for making assertions about logging) from the following informative thread a couple years ago (which I came across when filing issue 16884):

http://mail.python.org/pipermail/python-dev/2010-December/106526.html
msg179344 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2013-01-08 12:23
> and perhaps something could be added to test.support.

Also, just to clarify, I had in mind outside projects and the larger community for this request rather than CPython development, so I'm not sure test.support would be the right location.
msg179358 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2013-01-08 15:36
> I had in mind outside projects and the larger community for this request

Fair enough - then the best place for the specialisation of stream and handler would seem to be unittest/unittest2. So I'll add Michael Foord to the nosy list.
History
Date User Action Args
2013-01-08 15:36:34vinay.sajipsetnosy: + michael.foord
messages: + msg179358
2013-01-08 12:23:47chris.jerdoneksetmessages: + msg179344
2013-01-08 12:08:59chris.jerdoneksetmessages: + msg179341
2013-01-08 11:47:55chris.jerdoneksetmessages: + msg179340
2013-01-08 11:42:50vinay.sajipsetmessages: + msg179339
2013-01-08 11:36:15ezio.melottisetnosy: + ezio.melotti
messages: + msg179337
2013-01-08 11:29:15chris.jerdoneksetmessages: + msg179334
2013-01-08 11:02:25vinay.sajipsetmessages: + msg179330
2013-01-08 01:58:04chris.jerdonekcreate