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