1

I've hit a very bizarre issue and I honestly haven't got a clue what to do about it, hence decided to ask around. Long story short, when I try to log a byte 0x90 in my logging.Logger, it gets the entire Python terminal stuck. Of all the bytes I've tried (all ASCII and plenty of others, too) this is the only one that shows this behaviour. See below for more details.

A bit of context

I've got a WX application that receives data from a serial port, displays it and logs it. Reception of the data from the port is handled by a backend, which I've extensively tested via unit tests. I'm quite sure that it works, both when I use a "bent pipe" to send/receive bytes and when I use an Arduino to send the bytes to the app. The frontend=the WX app also seems to work, i.e. displays the bytes that it receives and logs them in logging.Logger.

Specific problem

I tried to repeat all my unit backend tests as a black box test of the entire app. Everything works fine except one case, which sends several bytes, including 0x90 = 58256 = 'ã'. To my surprise, as soon as this byte is received, the logging.Logger stops displaying any further messages. The app, however, continues on quite happily.

Things I've tried and results

This poor guy seems to have had an issue with the same byte but hasn't got any replies. They had a similar issue here but don't mention any specifics. All in all, there doesn't seem to be anything special about 0x90, is there?

I've narrowed down my problem to just the logging facility, see the MWE below. If I just run the MWE from terminal, it finishes without issues. Same if I run it from Python or IPython interpreter within Anaconda. The result is:

.../tests$ python3 ./mwe.py 
0.5.1.2
(3, 5, 4)
2020-01-19 20:15:49,184 - MyLog - INFO - j
2020-01-19 20:15:49,184 - MyLog - INFO -

However, if I open a Python interpreter and then execute the MWE line by line, it eventually gets stuck as soon as I try to log 0x90. There seems to be no way to unblock the terminal, not even with a ctrl+C. I just have to kill the interpreter process.

Any ideas what's going on? Thanks a lot for having a look at this.

MWE

import logging, sys
print(logging.__version__)
# 0.5.1.2
print(sys.version_info[:3])
# (3, 5, 4)
logger = logging.getLogger("MyLog")
handler = logging.StreamHandler()
logger.setLevel(logging.INFO)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
handler.setLevel(logging.INFO)
logger.addHandler(handler)
logger.info(chr(0x6a))
# 2020-01-18 20:39:00,696 - MyLog - INFO - j
logger.info(chr(0x90))
# 2020-01-18 20:39:07,617 - MyLog - INFO -
# Python console is stalled from now-on.

Solution

An elegant solution to the problem, which turns out to be about sanitising the string from control characters, is in this post.

Aleksander Lidtke
  • 2,876
  • 4
  • 29
  • 41
  • 1
    Note that this is unrelated to logging. Try starting an interactive python session and `print(chr(0x90))` should similarly destroy your terminal. – blues Jan 20 '20 at 10:11

1 Answers1

2

This happens because the python console improperly sees this as special control character for the terminal. Specifically it starts a device control string. And those need to be terminated or the terminal will hang. To verify try to execute print(chr(0x90)) or print(chr(0x90)+chr(0x9C)) in the python console. The second will do nothing as it has the terminating 0x9c byte while the first will hang it.

blues
  • 4,547
  • 3
  • 23
  • 39
  • Thanks a lot @blues ! Never thought of this. In order to make my application fail-safe, do you reckon that I should keep an eye out for all those control strings and somehow make sure I that treat them separately? Is there any Python built-in list of the control strings? – Aleksander Lidtke Jan 20 '20 at 20:20