Debugging npyscreen apps using two consoles
291 views
Skip to first unread message
Edward K. Ream
May 7, 2017, 8:27:18 AM5/7/17
to npyscreen
This post may be of great interest to those that develop npyscreen apps.
This is a very long post. tl;dr: Read the summary.
I don't see any documentation about how to debug npyscreen (or curses) apps on the npyscreen site. This post may serve as pre-writing for such missing docs.
Overview
Debugging npyscreen apps is challenging because the console isn't available for tracing or pdb. At first, I used winpdb and or rpdb2, but that is excruciatingly slow. The methods described here accelerate development speed by about 10x.
The idea is simple: use two consoles for debugging. The npyscreen app broadcasts logging messages to a second console using Python's logging module, per this part of Python's Logging Cookbook. This is a super solution: it works with both Python 2 and 3, and should work on all Python platforms.
The actual implementation is embedded into Leo, but can easily be adapted as described below for use with any IDE. The workflow contains two simple steps:
1. From the IDE, start a listener programmer. The listener program starts a localhost listener in its console.
In my case, Leo's listen-to-log command starts the listener (in a separate process, so Leo remains responsive) in the console from which Leo is running.
2. Run the npyscreen app in a second console. A few lines of code in the app's startup logic turns the app into a broadcaster. All broadcast messages appear in the first console!
That's all!
The last section describes how to run your npyscreen app's unit tests from the app itself. The solution can be adapted to any IDE. It's way better than the solutions discussed in stack overflow. No changes are (typically) needed to the unit tests themselves.
The broadcast code
The npyscreen app calls this method early in its startup sequence. It is straight out of the Logging Cookbook:
def init_logger(self):
self.rootLogger = logging.getLogger('')
self.rootLogger.setLevel(logging.DEBUG)
socketHandler = logging.handlers.SocketHandler(
'localhost',
logging.handlers.DEFAULT_TCP_LOGGING_PORT,
)
self.rootLogger.addHandler(socketHandler)
logging.info('-' * 20) # I added this line, to separate traces from multiple runs.
The Leo-specific version of init_logger concludes by monkey-patching Leo's standard tracing functions to functions that simply call logging.info:
g.es = es
g.pr = pr # Most output goes through here, including g.es_exception.
g.trace = trace
Your npyscreen app can do something similar, or the app can simply call logging.info directly.
The listener code
I created a log_listener.py file, which Leo's listen-to-log command executes in a separate process. This is a verbatim copy to the cookbook code, except that I changed the imports so it runs on either Python 2 or 3:
...
try:
import SocketServer # Python 2
except ImportError:
import socketserver as SocketServer # Python 3
...
class LogRecordStreamHandler(SocketServer.StreamRequestHandler):
[See the cookbook]
...
class LogRecordSocketReceiver(SocketServer.ThreadingTCPServer):
[ See the cookbook]
Running the listener from an IDE
Leo's listen-to-log command runs the listener in a separate process. This step isn't necessary if you invoke the listener directly from a console, but the following code is useful if you want to start the listener from your IDE:
path = << path to log_listener.py >>
listener = subprocess.Popen(
[sys.executable, path],
shell=False,
universal_newlines=True,
)
This code works on both Linux and Windows.
Running unit test from the npyscreen app
I am still in the early stages of developing the npyscreen front-end for Leo. But as a check on my work, I wanted to run Leo's unit tests as early as I could while using the npyscreen gui. Here is the (end of) the output that appeared in the listener pane:
Ran 901 tests in 15.940s
FAILED
(failures=177, errors=30, skipped=15)
...s.....s..................E..E.E..F..............................................sssss.EE..........
............................FFF.....F.......F...........E.........FF..............FFFFFFFF.....F.FFFF
.EEFFFFEFss.FF......F....F.............FFFFFFFF............FFFFFFFFFFFFEF..F..FFFFFFFFFFFFFEFFFFF.FFF
FFF.FFFF.FFF..FFFF..FFFFFF..F..FF.F..FFEFFFFF..FFFFFEEFFFFF.....................F...sE.FFFF..........
....F................F..................................sF.....sEs..............FFFFFFFFFFEEEEFFE.FE.
EEEEFFFF....E.F....F.....................................................FFFFFFFFFFF........s........
F..E.....................F..F..F......FFFEFFFFFFFE.........F........s................................
......................FFFFFFFFF.F....................................................................
..............................................................................................
This was a huge step forward in the development process.
To get this to work, a few hacks were need. You can adapt these for your purposes:
1. The script that launches Leo with the npyscreen gui enabled causes Leo to load unitTests.leo, containing Leo's standard unit tests. This is necessary because not enough of the npyscreen gui was working to load unitTests.leo any other way!
2. I hacked the InputHandler.handle_input method in wgwidget.py so that it intercepted 268 (F4) and set it directly to Leo's internal key handler. This code appears first so that 268 doesn't get eaten by the npyscreen widgets.
if i == 268:
# g is Leo's leoGlobals module, and g.app.gui is Leo's npyscreen gui code.
g.app.gui.do_key(i)
return True
To make this work, I bound Leo's run-all-unit-tests-locally command to F4. This is different from Leo's standard binding (Alt-4) which curses doesn't/can't generate.
3. Most importantly, Leo's unit test runner special-cases the curses gui. Here is the "good part":
if g.app.gui.guiName() == 'curses':
logger, handler, stream = self.create_logging_stream()
else:
stream = None
runner = unittest.TextTestRunner(
stream=stream,
failfast=g.app.failFast,
verbosity=verbosity,
)
result = runner.run(suite)
if stream:
if stream.aList:
logger.info('\n'+''.join(stream.aList))
logger.removeHandler(handler)
And here is the supporting code:
def create_logging_stream(self):
logger = logging.getLogger()
logger.setLevel(logging.INFO)
# Don't use debug: it includes Qt debug messages.
for handler in logger.handlers or []:
if isinstance(handler, logging.handlers.SocketHandler):
stream = None
break
else:
handler = logging.handlers.SocketHandler(
'localhost',
logging.handlers.DEFAULT_TCP_LOGGING_PORT,
)
logger.addHandler(handler)
stream = self.LoggingStream(logger)
return logger, handler, stream
Important: the above code makes sure that only one listener is active. Otherwise the output can get duplicated.
Finally, here is a the stream class. Its hacks produce more reasonable output than the obvious code.
class LoggingStream:
'''A class that can serve as a logging stream.'''
def __init__(self, logger):
self.aList = []
self.logger = logger
def write(self, s):
'''Called from pr and also unittest.addSuccess/addFailure.'''
if 0: # Write everything on a new line.
if not s.isspace():
self.logger.info(s.rstrip())
else:
s = s.strip()
if len(s) == 1:
self.aList.append(s)
elif s:
if self.aList:
self.logger.info(''.join(self.aList))
self.aList = []
self.logger.info(s.rstrip())
def flush(self):
pass
Summary
Broadcasting debugging traces from the npyscreen app to a listener in a separate console is hugely more effective than using a debugger.
Python's Logging Cookbook provides broadcast/listener code that your app can use virtually unchanged (except for imports). This code is portable across platforms and Python 2/3.
IDE's can easily run the listener in a separate process so that the IDE remains responsive while debugging the npyscreen app.
Unit tests can be run from the npyscreen app under development. These tests can be run "early", when the app is just barely functional. A modified unittest.TextTestRunner sends output to the listener pane.
The techniques described here work only for tracing and unit testing. If you must single step through code, winpdb is required. Afaik, winpdb works only on Linux.
Edward
This is a very long post. tl;dr: Read the summary.
I don't see any documentation about how to debug npyscreen (or curses) apps on the npyscreen site. This post may serve as pre-writing for such missing docs.
Overview
Debugging npyscreen apps is challenging because the console isn't available for tracing or pdb. At first, I used winpdb and or rpdb2, but that is excruciatingly slow. The methods described here accelerate development speed by about 10x.
The idea is simple: use two consoles for debugging. The npyscreen app broadcasts logging messages to a second console using Python's logging module, per this part of Python's Logging Cookbook. This is a super solution: it works with both Python 2 and 3, and should work on all Python platforms.
The actual implementation is embedded into Leo, but can easily be adapted as described below for use with any IDE. The workflow contains two simple steps:
1. From the IDE, start a listener programmer. The listener program starts a localhost listener in its console.
In my case, Leo's listen-to-log command starts the listener (in a separate process, so Leo remains responsive) in the console from which Leo is running.
2. Run the npyscreen app in a second console. A few lines of code in the app's startup logic turns the app into a broadcaster. All broadcast messages appear in the first console!
That's all!
The last section describes how to run your npyscreen app's unit tests from the app itself. The solution can be adapted to any IDE. It's way better than the solutions discussed in stack overflow. No changes are (typically) needed to the unit tests themselves.
The broadcast code
The npyscreen app calls this method early in its startup sequence. It is straight out of the Logging Cookbook:
def init_logger(self):
self.rootLogger = logging.getLogger('')
self.rootLogger.setLevel(logging.DEBUG)
socketHandler = logging.handlers.SocketHandler(
'localhost',
logging.handlers.DEFAULT_TCP_LOGGING_PORT,
)
self.rootLogger.addHandler(socketHandler)
logging.info('-' * 20) # I added this line, to separate traces from multiple runs.
The Leo-specific version of init_logger concludes by monkey-patching Leo's standard tracing functions to functions that simply call logging.info:
g.es = es
g.pr = pr # Most output goes through here, including g.es_exception.
g.trace = trace
Your npyscreen app can do something similar, or the app can simply call logging.info directly.
The listener code
I created a log_listener.py file, which Leo's listen-to-log command executes in a separate process. This is a verbatim copy to the cookbook code, except that I changed the imports so it runs on either Python 2 or 3:
...
try:
import SocketServer # Python 2
except ImportError:
import socketserver as SocketServer # Python 3
...
class LogRecordStreamHandler(SocketServer.StreamRequestHandler):
[See the cookbook]
...
class LogRecordSocketReceiver(SocketServer.ThreadingTCPServer):
[ See the cookbook]
Running the listener from an IDE
Leo's listen-to-log command runs the listener in a separate process. This step isn't necessary if you invoke the listener directly from a console, but the following code is useful if you want to start the listener from your IDE:
path = << path to log_listener.py >>
listener = subprocess.Popen(
[sys.executable, path],
shell=False,
universal_newlines=True,
)
This code works on both Linux and Windows.
Running unit test from the npyscreen app
I am still in the early stages of developing the npyscreen front-end for Leo. But as a check on my work, I wanted to run Leo's unit tests as early as I could while using the npyscreen gui. Here is the (end of) the output that appeared in the listener pane:
Ran 901 tests in 15.940s
FAILED
(failures=177, errors=30, skipped=15)
...s.....s..................E..E.E..F..............................................sssss.EE..........
............................FFF.....F.......F...........E.........FF..............FFFFFFFF.....F.FFFF
.EEFFFFEFss.FF......F....F.............FFFFFFFF............FFFFFFFFFFFFEF..F..FFFFFFFFFFFFFEFFFFF.FFF
FFF.FFFF.FFF..FFFF..FFFFFF..F..FF.F..FFEFFFFF..FFFFFEEFFFFF.....................F...sE.FFFF..........
....F................F..................................sF.....sEs..............FFFFFFFFFFEEEEFFE.FE.
EEEEFFFF....E.F....F.....................................................FFFFFFFFFFF........s........
F..E.....................F..F..F......FFFEFFFFFFFE.........F........s................................
......................FFFFFFFFF.F....................................................................
..............................................................................................
This was a huge step forward in the development process.
To get this to work, a few hacks were need. You can adapt these for your purposes:
1. The script that launches Leo with the npyscreen gui enabled causes Leo to load unitTests.leo, containing Leo's standard unit tests. This is necessary because not enough of the npyscreen gui was working to load unitTests.leo any other way!
2. I hacked the InputHandler.handle_input method in wgwidget.py so that it intercepted 268 (F4) and set it directly to Leo's internal key handler. This code appears first so that 268 doesn't get eaten by the npyscreen widgets.
if i == 268:
# g is Leo's leoGlobals module, and g.app.gui is Leo's npyscreen gui code.
g.app.gui.do_key(i)
return True
To make this work, I bound Leo's run-all-unit-tests-locally command to F4. This is different from Leo's standard binding (Alt-4) which curses doesn't/can't generate.
3. Most importantly, Leo's unit test runner special-cases the curses gui. Here is the "good part":
if g.app.gui.guiName() == 'curses':
logger, handler, stream = self.create_logging_stream()
else:
stream = None
runner = unittest.TextTestRunner(
stream=stream,
failfast=g.app.failFast,
verbosity=verbosity,
)
result = runner.run(suite)
if stream:
if stream.aList:
logger.info('\n'+''.join(stream.aList))
logger.removeHandler(handler)
And here is the supporting code:
def create_logging_stream(self):
logger = logging.getLogger()
logger.setLevel(logging.INFO)
# Don't use debug: it includes Qt debug messages.
for handler in logger.handlers or []:
if isinstance(handler, logging.handlers.SocketHandler):
stream = None
break
else:
handler = logging.handlers.SocketHandler(
'localhost',
logging.handlers.DEFAULT_TCP_LOGGING_PORT,
)
logger.addHandler(handler)
stream = self.LoggingStream(logger)
return logger, handler, stream
Important: the above code makes sure that only one listener is active. Otherwise the output can get duplicated.
Finally, here is a the stream class. Its hacks produce more reasonable output than the obvious code.
class LoggingStream:
'''A class that can serve as a logging stream.'''
def __init__(self, logger):
self.aList = []
self.logger = logger
def write(self, s):
'''Called from pr and also unittest.addSuccess/addFailure.'''
if 0: # Write everything on a new line.
if not s.isspace():
self.logger.info(s.rstrip())
else:
s = s.strip()
if len(s) == 1:
self.aList.append(s)
elif s:
if self.aList:
self.logger.info(''.join(self.aList))
self.aList = []
self.logger.info(s.rstrip())
def flush(self):
pass
Summary
Broadcasting debugging traces from the npyscreen app to a listener in a separate console is hugely more effective than using a debugger.
Python's Logging Cookbook provides broadcast/listener code that your app can use virtually unchanged (except for imports). This code is portable across platforms and Python 2/3.
IDE's can easily run the listener in a separate process so that the IDE remains responsive while debugging the npyscreen app.
Unit tests can be run from the npyscreen app under development. These tests can be run "early", when the app is just barely functional. A modified unittest.TextTestRunner sends output to the listener pane.
The techniques described here work only for tracing and unit testing. If you must single step through code, winpdb is required. Afaik, winpdb works only on Linux.
Edward
Nicholas Cole
May 8, 2017, 9:03:42 AM5/8/17
to npys...@googlegroups.com
Excellent. I look forward to trying this out!
--
You received this message because you are subscribed to the Google Groups "npyscreen" group.
To unsubscribe from this group and stop receiving emails from it, send an email to npyscreen+...@googlegroups.com.
To post to this group, send email to npys...@googlegroups.com.
Visit this group at https://groups.google.com/group/npyscreen.
For more options, visit https://groups.google.com/d/optout.
Edward K. Ream
May 14, 2017, 6:54:21 AM5/14/17
to npyscreen
On Sunday, May 7, 2017 at 7:27:18 AM UTC-5, Edward K. Ream wrote:
This post may be of great interest to those that develop npyscreen apps.
In general, this approach is working very well, but I found two small glitches:
1. Traces (calls to logging.info, etc.) are extremely slow if no listener has been started. Not a problem, except after debugging, when all traces should be disabled.
2. Sometimes the listener or broadcaster seems to go away. This is might be problem with the broadcaster's shutdown logic. Maybe it's only a problem when the broadcaster crashes. Or maybe something else. No big deal, I just restart the listener.
Edward
Reply all
Reply to author
Forward
0 new messages