Event listeners crash supervisord on Python 3

[palmkevin]

I get the following error when running the master with Python 3.2:

 File "/opt/ls/lx/env/d/python32/supervisor/process.py", line 825, in dispatch
    ok = self._dispatchEvent(event)
  File "/opt/ls/lx/env/d/python32/supervisor/process.py", line 873, in _dispatchEvent
    process.write(as_bytes(envelope))
  File "/opt/ls/lx/env/d/python32/supervisor/process.py", line 100, in write
    dispatcher.input_buffer += chars
TypeError: Can't convert 'bytes' object to str implicitly

When I do replace in process.py (line 873) as_bytes by as_string, then it is working...

[Pehat]

Consider using six package, so you would have the same-named byte-string conversion functions for Python 2 and Python 3 code.

[mnaberez]

Consider using six package

Supervisor has its own compat.py module for Python 2/3 shims. If any more are needed, they can can be added to compat.py. Adding more package dependencies to Supervisor is undesirable, and compat.py is already there.

[mnaberez]

Instructions to reproduce the crash above:

$ python --version
Python 3.5.2

$ cat supervisord.conf
[supervisord]
loglevel=blather
nodaemon=true

[eventlistener:cat]
command=bash -c 'echo READY; exec cat'
events=TICK_5

$ supervisord -c supervisord.conf
2016-10-08 22:18:30,370 INFO Increased RLIMIT_NOFILE limit to 1024
2016-10-08 22:18:30,373 INFO supervisord started with pid 15411
2016-10-08 22:18:31,376 INFO spawned: 'cat' with pid 15414
2016-10-08 22:18:31,384 BLAT read event caused by <PEventListenerDispatcher at 4425371432 for <Subprocess at 4436932312 with name cat in state STARTING> (stdout)>
2016-10-08 22:18:31,385 DEBG 'cat' stdout output:
READY

2016-10-08 22:18:31,385 DEBG cat: ACKNOWLEDGED -> READY
2016-10-08 22:18:32,391 INFO success: cat entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Traceback (most recent call last):
  File "/usr/local/bin/supervisord", line 9, in <module>
    load_entry_point('supervisor', 'console_scripts', 'supervisord')()
  File "/path/to/supervisor/supervisor/supervisord.py", line 361, in main
    go(options)
  File "/path/to/supervisor/supervisor/supervisord.py", line 371, in go
    d.main()
  File "/path/to/supervisor/supervisor/supervisord.py", line 82, in main
    self.run()
  File "/path/to/supervisor/supervisor/supervisord.py", line 99, in run
    self.runforever()
  File "/path/to/supervisor/supervisor/supervisord.py", line 249, in runforever
    group.transition()
  File "/path/to/supervisor/supervisor/process.py", line 824, in transition
    self.dispatch()
  File "/path/to/supervisor/supervisor/process.py", line 830, in dispatch
    ok = self._dispatchEvent(event)
  File "/path/to/supervisor/supervisor/process.py", line 878, in _dispatchEvent
    process.write(as_bytes(envelope))
  File "/path/to/supervisor/supervisor/process.py", line 100, in write
    dispatcher.input_buffer += chars
TypeError: Can't convert 'bytes' object to str implicitly

Tested on e73d017 but it looks like this crash has always existed in the Python 3 port.

[woutervh]

Adding more package dependencies to Supervisor is undesirable

why?
Ever heard of "pip install"?
I really don't care how much dependencies supervisor has.

You rather create your own very buggy python2-to-3 conversion library, rather than using a very mature well tested tool that the rest of the python-world uses?

Please rethink about this.

[mnaberez]

Ever heard of "pip install"?

I'd appreciate if you'd refrain from comments like this if you can. You're welcome to participate here but there's nicer ways to do it.

I really don't care how much dependencies supervisor has.

Other users have said on this issue tracker that they do.

You rather create your own very buggy python2-to-3 conversion library, rather than using a very mature well tested tool that the rest of the python-world uses?

The approach of bundling a small compat module with just the functions needed is shared by other packages, e.g. pyramid. There isn't much needed in Supervisor's compat module, and the Python 3 issues we have remaining are caused by larger design problems that changing out the module isn't going to solve.

[evanunderscore]

One advantage of six is that most people will be familiar with exactly how it works. This is an example of something that won't do what anybody expects (and I'm fairly sure needs changing). Since six is only one file, it could be included in the source tree to avoid another dependency.

[vsajip]

Working on a fix, this is what I get now:

$ supervisord -c ~/Documents/issue-663.conf 
2017-01-04 23:54:20,572 TRAC 127.0.0.1:Medusa (V1.12) started at Wed Jan  4 23:54:20 2017
	Hostname: localhost
	Port:9001
2017-01-04 23:54:20,577 INFO RPC interface 'supervisor' initialized
2017-01-04 23:54:20,577 CRIT Server 'inet_http_server' running without any HTTP authentication checking
2017-01-04 23:54:20,577 INFO supervisord started with pid 4032
2017-01-04 23:54:21,586 INFO spawned: 'cat' with pid 4035
2017-01-04 23:54:21,595 BLAT read event caused by <PEventListenerDispatcher at 140441467655952 for <Subprocess at 140441467907656 with name cat in state STARTING> (stdout)>
2017-01-04 23:54:21,596 DEBG 'cat' stdout output:
b'READY\n'
2017-01-04 23:54:21,596 DEBG cat: ACKNOWLEDGED -> READY
2017-01-04 23:54:22,599 INFO success: cat entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2017-01-04 23:54:26,608 DEBG event 0 sent to listener cat
2017-01-04 23:54:26,609 BLAT read event caused by <PEventListenerDispatcher at 140441467655952 for <Subprocess at 140441467907656 with name cat in state RUNNING> (stdout)>
2017-01-04 23:54:26,610 DEBG 'cat' stdout output:
b'ver:3.0 server:supervisor serial:0 pool:cat poolserial:0 eventname:TICK_5 len:15\nwhen:1483574065'
2017-01-04 23:54:26,610 WARN cat: bad result line: 'ver:3.0 server:supervisor serial:0 pool:cat poolserial:0 eventname:TICK_5 len:15'
2017-01-04 23:54:26,611 DEBG cat: BUSY -> UNKNOWN
2017-01-04 23:54:26,611 WARN cat: has entered the UNKNOWN state and will no longer receive events, this usually indicates the process violated the eventlistener protocol
2017-01-04 23:54:26,611 DEBG rebuffering event 0 for pool cat (bufsize 0)
2017-01-04 23:55:15,703 ERRO pool cat event buffer overflowed, discarding event 0
2017-01-04 23:55:20,712 ERRO pool cat event buffer overflowed, discarding event 1
2017-01-04 23:55:25,721 ERRO pool cat event buffer overflowed, discarding event 2
2017-01-04 23:55:30,732 ERRO pool cat event buffer overflowed, discarding event 3
2017-01-04 23:55:35,744 ERRO pool cat event buffer overflowed, discarding event 4
2017-01-04 23:55:40,754 ERRO pool cat event buffer overflowed, discarding event 5
...

Is this what one would expect given that the event listener is a cat command? Not that familiar with the event listener protocol yet ...

[mnaberez]

Is this what one would expect given that the event listener is a cat command?

Yes, supervisord is performing as expected for cat in your log. I only used cat as a minimal reproduce case for the original exception. The output from cat is not valid for the eventlistener protocol, so the messages bad result line... and ...usually indicates the process violated the eventlistener protocol are expected.

Now that you have fixed the original exception, you need a process that implements the eventlistener protocol to see if eventlisteners really work. You can try this minimal example or the superlance package). A further thing to check is PROCESS_LOG_STDOUT. That event includes bytes from the stdout of the subprocess so it will be prone to bytes/strings conversion issues.