Title: facilitate log output starting at beginning of line
Type: enhancement Stage:
Components: Library (Lib) Versions: Python 3.4
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):"setting up")
    def test1(self):
    def test2(self):



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 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
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
test2 (test_logging.Test) ... INFO:root:setting up

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):
msg179344 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2013-01-08 12:23
> and perhaps something could be added to

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 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.
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