powershell stderr redirect breaks lines every few characters

Question

UPDATE: this seems to be specific to uncaught exceptions inside a function called by the slot/signal flow of PyQt5 (PyQt 5.11 running in Python 3.7.0). See UPDATE farther down this question text.

The overall goal is to tee the stdout and stderr of a python program to screen and to the same file, on a Windows 10 machine; I'd prefer to do this redirection at the operating system level (i.e. the shell that invokes python - Windows in this case); doing it cleanly from within the python program hasn't worked out at any rate.

Check out the broken stderr redirection lines below.

radiolog.py is a large python program which shouldn't be relevant here; inside it I trigger an exception in order to test this logging workflow. radiolog_log.ps1 is a powershell wrapper around radiolog.py:

python -u radiolog.py 2>&1 | % ToString | Tee-Object log.txt

Running radiolog_log.ps1 from inside a powershell terminal:

PS C:\Users\caver\Documents\GitHub\radiolog> .\radiolog_log.ps1
6319:Operating system is Windows.
6319:PowerShell.exe is in the path.
... (omitting a bunch of irrelevant radiolog transcript output)
6329:Accepted2
Traceback (most recent call last):
  File "
radiolog.py", line 3796, in keyPress
Eve
n
t
    sel
f.accept
(
)
  File "
r
adio
l
og.
py"
,
 line 3
9
13, in accept
    rprint(1/0)
ZeroD
ivi
sionError: division by zero

PS C:\Users\caver\Documents\GitHub\radiolog>

There are some good posts and answers out there about powershell stderr redirection splitting lines at the width of the console... however, this one seems to be splitting the lines every few characters, and it's not the same each time.

The | % ToString gets rid of the (in this case) redundant layer of powershell's exception handling; without | % ToString it looks like this (everything beginning with 'python: Traceback' is in red text):

6851:Accepted2
python : Traceback (most recent call last):
At line:1 char:1
+ python -u radiolog.py 2>&1
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : NotSpecified: (Traceback (most recent call last)::String) [], RemoteException
    + FullyQualifiedErrorId : NativeCommandError

  F
ile "radiolog.py", line 3796, in keyPressEvent
    self.accept()
  File "ra
diol
o
g.p
y",
lin
e 39
13, in accept
    rp
r
int(1/0)
Ze
r
oDivisio
n
Error:
div
i
sion by zero
PS C:\Users\caver\Documents\GitHub\radiolog>

Another attempt is to run a .bat file from the powershell terminal, then do the tee in powershell.

radiolog_log.bat:

python -u radiolog.py 2>&1

In the powershell terminal:

PS C:\Users\caver\Documents\GitHub\radiolog> .\radiolog_log.bat | % ToString | Tee-Object log.dat

which results in the following terminal display - everything as expected:

C:\Users\caver\Documents\GitHub\radiolog>python -u radiolog.py  2>&1
8314:Operating system is Windows.
8314:PowerShell.exe is in the path.
...
8327:Accepted2
Traceback (most recent call last):
  File "radiolog.py", line 3796, in keyPressEvent
    self.accept()
  File "radiolog.py", line 3913, in accept
    rprint(1/0)
ZeroDivisionError: division by zero
PS C:\Users\caver\Documents\GitHub\radiolog>

However log.dat is written in unicode, i.e. is not human-readable as a plain text file. Microsoft says as much in the Tee documentation here - not sure why...? Found a question about converting it to ascii on the fly, but, it doesn't look like you can have the same real-time file and terminal output, negating a big part of the reasoning for tee in the first place.

Any ideas on how to get everything to just play nice like it would in linux?

UPDATE: PyQt5 slot/signal flow seems to be triggering this behavior. Example code, massively pared down from the original radiolog.py:

from PyQt5.QtCore import *
from PyQt5.QtGui import *
from PyQt5.QtWidgets import *

import sys

class Ui_Dialog(object):
    def setupUi(self, Dialog):
        Dialog.setObjectName("Dialog")
        self.pushButton = QPushButton(Dialog)
        self.pushButton.setObjectName("pushButton")
        self.pushButton.setText(" Add Entry ")
        self.horizontalLayout = QHBoxLayout(Dialog)
        self.horizontalLayout.addWidget(self.pushButton)

class MyWindow(QDialog,Ui_Dialog):
    def __init__(self,parent):
        QDialog.__init__(self)
        self.ui=Ui_Dialog()
        self.ui.setupUi(self)

# click the button to see that stderr inserts line breaks every few
#   characters (different on each occurrance) when openNewEntry is called
#   from the slot/signal flow:      
        self.ui.pushButton.clicked.connect(self.openNewEntry)

# uncomment the following line to see that stderr is line-buffered when
#  openNewEntry is called from code:
#       self.openNewEntry()

    def openNewEntry(self):
        print(1/0)

def main():
    app = QApplication(sys.argv)
    w = MyWindow(app)
    w.show()
    sys.exit(app.exec_())

if __name__ == "__main__":
    main()

In a powershell terminal, after defining STD-Handler as per the earliest answer to this question (not required to observe the broken lines, but, it does make cleaner output without the powershell-exception header as well as making a plain-text log file), then execute as follows:

python -u r.py *>&1 | STD-Handler log.txt

Click the button in the GUI and you get this:

[636765635572699130]: Traceback (most recent call last):
[636765635572808866]:
[636765635572918571]:  File "r.py", line 33,
[636765635573028268]:
[636765635573118026]: in open
[636765635573207784]: New
[636765635573307659]: E
[636765635573407558]: ntry
    print(1/0)
ZeroDivisionError: division by z
[636765635573506983]: ero

Now uncomment the line in the python code as noted, so that the exception is called from code rather than from user interaction; run the same line at the powershell terminal and you get this:

[636765639350787977]: Traceback (most recent call last):
[636765639350877842]:   File "r.py", line 42, in <module>

[636765639350997857]:
[636765639351077838]: main()
  File "r.py", line 37, in main

[636765639351187538]:
[636765639351282570]: w = MyWindow(app)
  File "r.py", line 30, in __init__

[636765639351372787]:
[636765639351467301]: self.openNewEntry()
  File "r.py", line 33, in openNewEntry

[636765639351554768]:
[636765639351660016]: print(1/0)
ZeroDivisionError: division by zero

So, this probably merits a new question to the PyQt community which I'll put together soon and cross-reference here - though help on this thread would still be great!

Tried to recreate this with just '1/0' , but your script worked fine. Wondering, if you just do "python -u .\test.py *>log.txt" in PS terminal, will log.txt be broken too? — Mike Twc, Oct 29 '18 at 19:16
Thanks for giving it a spin. When you say it worked fine, do you mean you get stdio output as well as complete intact lines of uncaught exception all in the log file? I tried without the redirect, as in your first response - log.txt is indeed broken like the initial question (stdio output is as-expected, but there line breaks every few characters of the uncaught exception). Removing -u causes the file to not be written at all until the python script is finished. — Tom Grundy, Oct 30 '18 at 13:46

score 0 · Answer 1 · answered Oct 30 '18 at 15:15

0

I tried to replicate this issue with some dummy script, but got proper file and terminal outputs in both cases (ps and bat). I guess you can just use your bat script, then fix file encoding at the end. If you really need the file to be updated live, below is a possible workaround. Basically you can create some custom "Tee-Object" and handle stdout as it comes. $_ is an object coming from a pipeline (stdout), even if it broken you can fix encoding or remove new line characters inside Process block

function STD-Handler
{  param ($outFile)

    Begin { $null > $outFile }

    Process  {

    $line = "[" + (get-date).Ticks + "]: " + $_ 
     Write-Host $line
     $line >> $outFile

    }

    End  { <# can do smth with the file at the end#>}
}

usage:

python -u C:\stack\stdout.py *>&1 | STD-Handler "C:\temp\log.txt"

answered Oct 30 '18 at 15:15

Mike Twc

2,230
2
14
19

Hmm. Are you running python 2 or 3? I didn't specify, I'm running python 3.7.0 - Wondering if it is a difference in how stderr is buffered in 2 vs 3? If I run exactly as you show, I get the broken stderr lines both on screen and in the file; if I run without -u, I still get broken stderr on screen and in file (but none of the non-exception text, i.e. none of the stdout transcript). This question https://stackoverflow.com/questions/22471023 looks interesting. – Tom Grundy Oct 31 '18 at 03:17
So I just now tried using a very short python program, instead of the large program I was using in the original question - and I do get 'clean' stderr with the short program. I'll spend a while trying to find what it is about my program that is causing stderr to toss its cookies, and will post back here and will probably modify the question and/or add an answer. In the meantime, thanks for your efforts to help! – Tom Grundy Oct 31 '18 at 03:35
The big python program in question uses PyQt5. Looks like it may be something in the pyqt core that does some monkeybusiness with stderr. Will continue narrowing it down tomorrow. – Tom Grundy Oct 31 '18 at 03:59
original question edited above; your response does answer the unicode thing quite nicely - accepting it for now. Thanks! – Tom Grundy Oct 31 '18 at 13:30

score 0 · Accepted Answer · answered Nov 01 '18 at 03:30

Partial Bingo - some other questions talk about the way PyQt5 treats uncaught exceptions. Not really sure of the interactions between PyQt's stderr handling and powershell's stderr handling, but, overriding sys.excepthook in python to have the 'old' behavior does the trick. Here's the new entire r.py python code - the only changes from the updated question code are the 'def except_hook' and 'sys.excepthook = except_hook' in the 'if name' clause:

from PyQt5.QtCore import *
from PyQt5.QtGui import *
from PyQt5.QtWidgets import *

import sys

class Ui_Dialog(object):
    def setupUi(self, Dialog):
        Dialog.setObjectName("Dialog")
        self.pushButton = QPushButton(Dialog)
        self.pushButton.setObjectName("pushButton")
        self.pushButton.setText(" Add Entry ")
        self.horizontalLayout = QHBoxLayout(Dialog)
        self.horizontalLayout.addWidget(self.pushButton)

class MyWindow(QDialog,Ui_Dialog):
    def __init__(self,parent):
        QDialog.__init__(self)
        self.ui=Ui_Dialog()
        self.ui.setupUi(self)

# click the button to see that stderr inserts line breaks every few
#   characters (different on each occurrance) when openNewEntry is called
#   from the slot/signal flow:      
        self.ui.pushButton.clicked.connect(self.openNewEntry)

# uncomment the following line to see that stderr is line-buffered when
#  openNewEntry is called from code:
#       self.openNewEntry()

    def openNewEntry(self):
        print(1/0)

def except_hook(cls, exception, traceback):
    sys.__excepthook__(cls, exception, traceback)
    exit(-1)

def main():
    app = QApplication(sys.argv)
    w = MyWindow(app)
    w.show()
    sys.exit(app.exec_())

if __name__ == "__main__":
    sys.excepthook = except_hook
    main()

Now, clicking the button produces this output:

[636766143015640817]: Traceback (most recent call last):
[636766143015760489]:   File "r.py", line 33, in openNewEntry

[636766143015911442]:
[636766143016031102]: print(1/0)
ZeroDivisionError: division by zero

Sometimes (not repeatably) it comes out a bit fractured at punctuation and such, but, this is a lot more manageable:

[636766144719906619]: Traceback (most recent call last):
[636766144720006506]:   File "r.py", line 47, in <module>

[636766144720096055]:
[636766144720195662]: main()
  File "r.py", line 41, in main

[636766144720275744]:
[636766144720375114]: w = MyWindow(app)

[636766144720469728]:   File "r.py", line 30, in __init__

[636766144720565688]:
[636766144720657318]: self.openNewEntry()
  File "r.py", line 33, in openNewEntry

[636766144720757052]:
[636766144720852021]: print(1/0)
ZeroDivisionError
[636766144720946788]: :
[636766144721046802]: division by zero
[636766144721132731]:

And this better-behaved output happens in the full program too (radiolog.py).

So, it would be great if anyone can shed more light on why the intermittent partial fracturing still happens, but, I think this is a workable solution. Thanks

powershell stderr redirect breaks lines every few characters

2 Answers2