Can two subprocesses both send messages to stdout inside a Tcl/Expect script?

Question

I have written an Expect script which spawns one subprocess (certbot), parses the output, then executes a second subprocess (a Python script) using data extracted from the first, and finally sends a carriage return (\r) to the first. I was recently debugging an issue with my script, so I thought I would add some logging to the Python script (which previously did not print any output). However, doing this caused the expect script to return this error:

    while executing
"exec ./test2.py "$SITE_DOMAIN" "$fileName" "$fileData""
    (file "./test.exp" line 23)

So then I tried changing my call to the second process / Python script from an exec call to a spawn call. This partially works and it got rid of the error. But strangely enough, I see the output from the first process right up until I start seeing output from the second process. Once the second process starts logging messages, I no longer see any output from the first.

I'm including here files to illustrate the problem as an MRE:

main.exp

#!/usr/bin/expect
set SITE_DOMAIN $env(SITE_DOMAIN)
set SITE_EMAIL $env(SITE_EMAIL)

# Spawn the certbot process
spawn ./test1.py certonly -m "$SITE_EMAIL" --agree-tos --no-eff-email --force-renew --preferred-challenges http --manual -d "$SITE_DOMAIN" -d "www.$SITE_DOMAIN"
set certbot_spawn_id $spawn_id

# Expect the output starting with 40 hyphens and capture it
expect {
    -re {(?n)^(- ){39}-\r\nCreate a file containing just this data:\r\n\r\n([\w.-]+)\r\n\r\nAnd make it available on your web server at this URL:\r\n\r\n.+/acme-challenge/([\w.-]+)} {
        set fileData $expect_out(2,string)
        set fileName $expect_out(3,string)
    }
    timeout {
        "Error: output from certbot did not match the expected pattern"
        exit 1
    }
}

# Call a separate command with the parsed value
exec ./test2.py "$SITE_DOMAIN" "$fileName" "$fileData"

# Send Enter to the certbot process to confirm
send -i $certbot_spawn_id "\r"

# Wait for the certbot process to finish
expect eof

test1.py

#!/usr/bin/env python
OUTPUT = """
Saving debug log to /var/log/letsencrypt/letsencrypt.log
Account registered.
Requesting a certificate for example.com and www.example.com

- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
Create a file containing just this data:

ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopq.rstuvwxyz01234567890ABCDEFGHIJKLMNOPQRSTUVW

And make it available on your web server at this URL:

http://example.com/.well-known/acme-challenge/ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopq

- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
"""

print(OUTPUT)
thing = input()
print("done")

test2.py

#!/usr/bin/env python
import logging
from time import sleep

logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)
logging.basicConfig()

logger.info("Uploading file to web server")
sleep(2)
logger.info("Upload complete")
sleep(1)

So if you run main.exp as-is, you'll see the first error that I mentioned. (And if you remove the logging statements from test2.py, those errors will go away.) If you change line 22 of main.exp to use spawn instead of exec, that too will fix the error, but then you won't see the word done output by the first process. The last thing displayed will be Upload complete.

Answer 1

1. Python's logging prints log messages to stderr.
2. Expect uses Tcl and Tcl's exec raises error if it sees any output to stderr.

Example:

$ expect -c 'exec bash -c "echo hello >&2" '
hello
    while executing
"exec bash -c "echo hello >&2" "

Tcl's exec has option -ignorestderr to stop it from raising error in such cases:

$ expect -c 'exec -ignorestderr bash -c "echo hello >&2" '
hello

---

Regarding "but then you won't see the word done output by the first process", you spawned a new process and then you also need to wait for it to complete:

spawn ./test2.py "$SITE_DOMAIN" "$fileName" "$fileData"
expect eof
#^^^^^^^^^

send   -i $certbot_spawn_id "\r"
expect -i $certbot_spawn_id eof
#      ^^^^^^^^^^^^^^^^^^^^

---

From Tcl's exec doc:

If standard output has not been redirected then the exec command returns the standard output from the last command in the pipeline, unless 2>@1 was specified, in which case standard error is included as well. If any of the commands in the pipeline exit abnormally or are killed or suspended, then exec will return an error and the error message will include the pipeline's output followed by error messages describing the abnormal terminations; the -errorcode return option will contain additional information about the last abnormal termination encountered. If any of the commands writes to its standard error file and that standard error is not redirected and -ignorestderr is not specified, then exec will return an error; the error message will include the pipeline's standard output, followed by messages about abnormal terminations (if any), followed by the standard error output.