Cannot run supervisorctl tail -f

[CMajeri]

Hello,
I've updated from 3.3.5 to 4.0.2 and I suddenly can't run supervisorctl tail -f on my various services. supervisorctl tail works great.

Here's a sample output:

# supervisorctl tail geth
      count=192  elapsed=46.758ms  number=146496 hash=9edcd2…e572c6 age=3y8mo1w
INFO [04-19|03:14:41.907] Imported new block receipts              count=191  elapsed=13.248ms  number=146305 hash=d927db…f9c746 age=3y8mo1w  size=45.37kB
INFO [04-19|03:14:41.946] Imported new block headers               count=192  elapsed=55.244ms  number=146688 hash=57d94b…381088 age=3y8mo1w
INFO [04-19|03:14:42.632] Imported new state entries               count=1152 elapsed=7.838ms   processed=269879 pending=14675 retry=0 duplicate=0 unexpected=0
INFO [04-19|03:14:42.638] Imported new block receipts              count=1    elapsed=165.711µs number=146306 hash=6295e3…194dc7 age=3y8mo1w  size=547.00B
INFO [04-19|03:14:42.660] Imported new block receipts              count=197  elapsed=6.803ms   number=146503 hash=57c683…5754ac age=3y8mo1w  size=45.37kB
INFO [04-19|03:14:42.694] Imported new block headers               count=192  elapsed=46.846ms  number=146880 hash=b1b46d…713aea age=3y8mo1w
INFO [04-19|03:14:43.362] Imported new block receipts              count=186  elapsed=9.575ms   number=146689 hash=fc206b…7a87dd age=3y8mo1w  size=85.38kB
INFO [04-19|03:14:43.396] Imported new block headers               count=192  elapsed=46.491ms  number=147072 hash=dfdb9d…e8ee91 age=3y8mo1w
INFO [04-19|03:14:44.046] Imported new block receipts              count=194  elapsed=7.549ms   number=146883 hash=9bed0e…30f78b age=3y8mo1w  size=54.38kB
INFO [04-19|03:14:44.097] Imported new block headers               count=192  elapsed=64.584ms  number=147264 hash=e4d9f1…1bb15a age=3y8mo1w

# supervisorctl tail -f geth
==> Press Ctrl-C to exit <==
unix:///run/supervisord.sock/logtail/geth/stdout Cannot connect, error: <type 'exceptions.UnicodeEncodeError'> ('ascii' codec can't encode character u'\u2026' in position 244: ordinal not in range(128))

I run python 2.7.15

Is there a workaround of some sort with environment variables to allow python to understand UTF-8? I'm guessing it has issues with ellipsis and the μ character in my other units.

[vsajip]

Some more information may be needed to help diagnose the problem. With the current repository version of supervisor and Python 2.7.12 (happens to be what's installed on my system), with this conf:

[unix_http_server]
file=supervisor.sock

[supervisord]
logfile=supervisord.log
pidfile=supervisord.pid
; nodaemon should be overridden on the command line when run as a service
nodaemon=false
nocleanup=true

[rpcinterface:supervisor]
supervisor.rpcinterface_factory = supervisor.rpcinterface:make_main_rpcinterface

[supervisorctl]
serverurl=unix://supervisor.sock

[program:geth]
command=/home/vinay/.virtualenvs/supervisor2/bin/python geth.py

and this script geth.py

# -*- coding: utf-8 -*-
import logging
import random
import sys
import time

def main():
    logging.basicConfig(level=logging.INFO, stream=sys.stdout,
                        format='%(levelname)s [%(asctime)s] %(message)s',
                        datefmt='%m-%d|%H:%M:%S')
    while True:
        delay = random.randint(400, 1200)
        time.sleep(delay / 1000.0)
        logging.info('delay=%4d hash=57d94b…381088', delay)

if __name__ == '__main__':
    main()

I'm able to run tail -f without issues: after running supervisord, then

$ supervisorctl tail -f geth
==> Press Ctrl-C to exit <==
INFO [04-25|16:07:58] delay=1179 hash=57d94b…381088
INFO [04-25|16:07:59] delay=1035 hash=57d94b…381088
INFO [04-25|16:07:59] delay= 643 hash=57d94b…381088
INFO [04-25|16:08:00] delay= 833 hash=57d94b…381088
[many lines elided]
INFO [04-25|16:09:19] delay= 708 hash=57d94b…381088
INFO [04-25|16:09:19] delay= 523 hash=57d94b…381088
^C

So it may not be a simple failure to handle an ellipsis or other Unicode character.

I get the same result with Supervisor 4.0.2 from PyPI.

So, your help is needed in getting to a minimal configuration/script which allows us to reproduce the problem.

[mnaberez]

I found a way to duplicate this on master (6bd04b6) using @vsajip's geth.py script. By changing the LANG environment variable, I am able to get the same behavior described by @CMajeri.

Python 2.7.15 tail (ok)

$ LANG=en_US.UTF-8 supervisorctl tail geth
] delay=1061 hash=57d94b…381088
INFO [04-28|14:31:53] delay=1044 hash=57d94b…381088
INFO [04-28|14:31:54] delay=1159 hash=57d94b…381088
INFO [04-28|14:31:55] delay=1130 hash=57d94b…381088

$ LANG=oops supervisorctl tail geth
] delay= 979 hash=57d94b…381088
INFO [04-28|14:32:22] delay= 692 hash=57d94b…381088
INFO [04-28|14:32:23] delay=1136 hash=57d94b…381088
INFO [04-28|14:32:24] delay= 505 hash=57d94b…381088

Python 2.7.15 tail -f (error)

$ LANG=en_US.UTF-8 supervisorctl tail -f geth
==> Press Ctrl-C to exit <==
INFO [04-28|14:33:15] delay= 457 hash=57d94b…381088
INFO [04-28|14:33:15] delay= 657 hash=57d94b…381088
INFO [04-28|14:33:16] delay= 853 hash=57d94b…381088

$ LANG=oops supervisorctl tail -f geth
==> Press Ctrl-C to exit <==
http://localhost:9001/logtail/geth/stdout Cannot connect, error: <type 'exceptions.UnicodeEncodeError'> ('ascii' codec can't encode character u'\u2026' in position 42: ordinal not in range(128))

Python 3.7.2 tail (ok)

$ LANG=en_US.UTF-8 supervisorctl tail geth
] delay= 500 hash=57d94b…381088
INFO [04-28|14:37:52] delay= 449 hash=57d94b…381088
INFO [04-28|14:37:53] delay= 932 hash=57d94b…381088
INFO [04-28|14:37:54] delay= 511 hash=57d94b…381088

$ LANG=oops supervisorctl tail geth
] delay= 877 hash=57d94b…381088
INFO [04-28|14:38:20] delay= 912 hash=57d94b…381088
INFO [04-28|14:38:20] delay= 756 hash=57d94b…381088
INFO [04-28|14:38:21] delay= 889 hash=57d94b…381088

Python 3.7.2 tail -f (ok)

$ LANG=en_US.UTF-8 supervisorctl tail -f geth
==> Press Ctrl-C to exit <==
FO [04-28|14:40:34] delay= 601 hash=57d94b…381088
INFO [04-28|14:40:35] delay= 870 hash=57d94b…381088
INFO [04-28|14:40:36] delay=1099 hash=57d94b…381088

$ LANG=oops supervisorctl tail -f geth
==> Press Ctrl-C to exit <==
FO [04-28|14:41:01] delay= 822 hash=57d94b…381088
INFO [04-28|14:41:02] delay= 714 hash=57d94b…381088
INFO [04-28|14:41:02] delay= 441 hash=57d94b…381088
INFO [04-28|14:41:03] delay= 474 hash=57d94b…381088

Shown above, it only seems to happen when tail -f is run on Python 2.

I am not able to work on this issue right now. Any help fixing this would be much appreciated.

[vsajip]

The problem is that you can't just output Unicode to any old terminal encoding. I have "overcome" the problem on Python 2.x, but failures can still occur on Python 3.x in some scenarios. The following script:

# soencoding.py
import sys

print(sys.stdout.encoding)

Shows the following for various versions on Python on my system:

$ .tox/py27/bin/python ../scratch/soencoding.py
UTF-8
$ .tox/py35/bin/python ../scratch/soencoding.py
UTF-8
$ .tox/py36/bin/python ../scratch/soencoding.py
UTF-8
$ .tox/py37/bin/python ../scratch/soencoding.py
UTF-8
$ LANG=oops .tox/py27/bin/python ../scratch/soencoding.py
ANSI_X3.4-1968
$ LANG=oops .tox/py35/bin/python ../scratch/soencoding.py
ANSI_X3.4-1968
$ LANG=oops .tox/py36/bin/python ../scratch/soencoding.py
ANSI_X3.4-1968
$ LANG=oops .tox/py37/bin/python ../scratch/soencoding.py
utf-8

So, my "fix" works on 2.7 by catching the UnicodeEncodeError and just dumping bytes to sys.stdout - not the right thing to do, but 2.7 copes somehow (though it could conceivably still fail for other values of LANG). On 3.x, you can't write bytes to sys.stdout. The end-to-end test fails on 3.5 and 3.6 with LANG=oops, but succeeds on 3.7 because the encoding is set to utf-8 rather than ANSI_X3.4-1968, even for LANG=oops. I'm not sure it's worth trying to bodge a fix in Supervisor - perhaps just a better error message will do, such as something like "Unable to write Unicode to stdout with encoding ANSI_X3.4-1968".

@CMajeri, what's the value of sys.stdout.encoding in the environment where your failure occurs, for the supervisorctl process which fails?

[mnaberez]

I'm not sure it's worth trying to bodge a fix in Supervisor - perhaps just a better error message will do, such as something like "Unable to write Unicode to stdout with encoding ANSI_X3.4-1968".

Thanks for looking into this, @vsajip.

If I understand correctly, this issue affects more than Python 2.7. It also affects Python 3 before 3.7. It could happen when running supervisorctl or running supervisord -n (foreground mode).

I would merge a change that addresses this by adding a warning message, either at the time encoding fails or at startup (or both). We might consider checking sys.stdout.encoding at startup and emitting the warning proactively, to help users fix their setup before it fails. Hopefully, we could also add some notes to the docs to help users fix it.

@CMajeri, what's the value of sys.stdout.encoding in the environment where your failure occurs, for the supervisorctl process which fails?

Please do let us know, @CMajeri. My attempt above setting LANG=oops was just a guess. It would help us to find out what's actually happening.

In searching around a bit, it seems this has been an issue for running Python programs under Docker (see docker-library/python#147). Users often write into the issue tracker saying that they are running Supervisor under Docker.

[vsajip]

See PR #1235

[mnaberez]

Fixed in #1235