Can't capture localproxy log output from Python subprocess

[KyleKotowick]

Describe the bug

I'm trying to build a localproxy agent that monitors the MQTT tunnel notify topic and starts localproxy when required. Essentially the same as this example, but in Python3 instead of Java.

To do this, I'm running this command when a notification message is received:

current_localproxy_process = None

def kill_localproxy():
    if current_localproxy_process is not None:
        logging.info("Killing localproxy with PID {}".format(current_localproxy_process.pid))
        current_localproxy_process.kill()

# Callback when the subscribed topic receives a message
def on_message_received(topic, payload, dup, qos, retain, **kwargs):
    logging.info("Received message on topic '{}'".format(topic))
    message = json.loads(payload)
    # Kill any existing tunnel connection
    kill_localproxy()
    p = subprocess.Popen(
        ["/usr/local/bin/localproxy", "-c", ca_dir, "-r", message["region"], "-d", "localhost:22"], shell=False,
        env={
            "AWSIOT_TUNNEL_ACCESS_TOKEN": message["clientAccessToken"]
        }, 
        stdout=subprocess.PIPE, 
        stderr=subprocess.STDOUT
    )
    logging.info("Starting localproxy with PID {}".format(p.pid))
    global current_localproxy_process
    current_localproxy_process = p
    for line in iter(p.stdout.readline, b''):
        print(line)

But none of the localproxy logs are output. The readline hangs indefinitely (until the process is exited).

I've also tried it with a file descriptor:

def on_message_received(topic, payload, dup, qos, retain, **kwargs):
    logging.info("Received message on topic '{}'".format(topic))
    message = json.loads(payload)
    # Kill any existing tunnel connection
    kill_localproxy()
    with open("/tmp/localproxy", "w") as logfile:
        p = subprocess.Popen(
            ["/usr/local/bin/localproxy", "-c", ca_dir, "-r", message["region"], "-d", "localhost:22"], 
            shell=False, 
            env={ 
                "AWSIOT_TUNNEL_ACCESS_TOKEN": message["clientAccessToken"]
            }, 
            stdout=logfile, 
            stderr=subprocess.STDOUT
        )
        logging.info("Starting localproxy with PID {}".format(p.pid))
        global current_localproxy_process
        current_localproxy_process = p
        p.wait()

Similarly, the log file (/tmp/localproxy) remains empty and has no logs written to it.

Interestingly, if I remove the stdout= and stderr= arguments from subprocess.Popen, and I run the Python script in a terminal, it works; the localproxy output is shown in the console. If I run the Python script from a systemd service though, it doesn't output properly.

Is it possible that localproxy is hardcoded to output to /dev/tty or similar? I can't think of any other reason that the normal approach for stdout capture using Python's submodule.Popen isn't working.

To Reproduce

Steps to reproduce the behavior:

1. Install Python3
2. Try to start localproxy using Python's subprocess.Popen function.
3. Try to capture or display the log outputs from localproxy.

Expected behavior

Should be able to capture the stdout output from localproxy.

Actual behavior

Can't seem to capture any output.

Environment (please complete the following information):

• OS: Ubuntu
• Version 20.04
• Architecture: x86-64
• Localproxy commit: 8980ea8e0190c7e8fd942f2bce8bfc01aa6a6a52 (v2.1.0)

[KyleKotowick]

Upon further experimentation, it looks like it might be a buffering issue. By running:

# Callback when the subscribed topic receives a message
def on_message_received(topic, payload, dup, qos, retain, **kwargs):
    logging.info("Received message on topic '{}'".format(topic))
    message = json.loads(payload)
    # Kill any existing tunnel connection
    kill_localproxy()
    p = subprocess.Popen(
        ["stdbuf", "-o1", "/usr/local/bin/localproxy", "-c", ca_dir, "-r", message["region"], "-d", "localhost:22"], shell=False,
        env={
            "AWSIOT_TUNNEL_ACCESS_TOKEN": message["clientAccessToken"]
        }, 
        bufsize=1,
        text=True,
    )
    logging.info("Starting localproxy with PID {}".format(p.pid))
    global current_localproxy_process
    current_localproxy_process = p

i.e. don't try to capture the output, just let it output to stdout but specify bufsize=1 (line buffering) and text=True (text, not binary, output), and run the command through stdbuf -o1. This causes it to display to stdout properly, both in a terminal and when run as a service.

I'll leave this open in case there's something the devs want to do to make it easier to deal with the buffering.

[kareali]

@KyleKotowick Nothing can be done from our side because it's Python io module that's buffering the output before writing it, so the change needs to be in the Python script to change this behaviour, so you can specify smaller buffer, disable it all together or use line buffering(as you did). If you other thoughts/suggestions please let us know.