python stack traces sometimes not logged until concurrently terminated

[crvarner]

concurrently version: 5.3.0

Starting webpack and flask app via npm start and the following scripts in package.json

    "scripts": {
        "start": "concurrently --kill-others -n webpack,flask -c blue,green \"npm:webpack\" \"PORT=${PORT:-5001} npm run flask\"",
        "flask": "DEVPORTAL_CFG=../development.cfg FLASK_APP=devportal PYTHONDONTWRITEBYTECODE=1 FLASK_ENV=development flask run --port=$PORT",
        "webpack": "webpack --config webpack.dev.js",

the flask app contains the following lines:

    log.info("log.info works normally")
    log.info("log.error works normally")
    raise Exception("ERROR")

repeating the request that executes these lines results in the following log output:

[flask] 2020-09-04 18:12:03,840 | devportal.api.auth |   INFO | log.info works normally
[flask] 2020-09-04 18:12:03,840 | devportal.api.auth |  ERROR | log.error works normally
[flask] Traceback (most recent call last):
        ... stacktrace ...
[flask]     raise Exception("ERROR")
[flask] Exception: ERROR
[flask] 2020-09-04 18:12:08,165 | devportal.api.auth |   INFO | log.info works normally
[flask] 2020-09-04 18:12:08,165 | devportal.api.auth |  ERROR | log.error works normally
[flask] 2020-09-04 18:12:09,145 | devportal.api.auth |   INFO | log.info works normally
[flask] 2020-09-04 18:12:09,146 | devportal.api.auth |  ERROR | log.error works normally
[flask] 2020-09-04 18:12:09,987 | devportal.api.auth |   INFO | log.info works normally
[flask] 2020-09-04 18:12:09,987 | devportal.api.auth |  ERROR | log.error works normally

Note the stacktrace was only logged once. terminating command vi CTRL-C results in the missing traces being logged:

^C[flask] Traceback (most recent call last):
        ... stacktrace ...
[flask] Exception: ERROR
[flask] Traceback (most recent call last):
        ... stacktrace ...
[flask] Exception: ERROR
[flask] Traceback (most recent call last):
        ... stacktrace ...
[flask] Exception: ERROR
[webpack] npm run webpack exited with code 0
--> Sending SIGTERM to other processes..
[flask] PORT=5001 npm run flask exited with code 0

Concurrently logs traces correctly when the --raw flag is set. Any ideas whether this is user error or a bug?

reproduction: https://github.com/crvarner/concurrently_bug.git

[coilysiren]

I'm also getting this bug

[coilysiren]

My reproduction is more or less this

runwithproxies:
    npx concurrently \
        --kill-others-on-fail --raw \
        -n lightrail,jeanne,drummajor \
        -c red,green,blue \
        "make buildandrun" \
        "proxy --service jeanne --proxy-port 8981 --local-port 8982" \
        "proxy --service drummajor --proxy-port 8983 --local-port 8984"

Where the two proxy --service commands are logging to stdout / stderr

[ixxie]

I'm also running into this with concurrently 8.2.2.

I noticed the issue also manifests when using asyncio and threading, not just stacktraces. This makes me wonder if concurrently is failing to pass the output of deeply nested processes and threads.

Another important clue: the issue doesn't occur when the --raw flag is used.

@gustavohenke if this doesn't ring any immediate bells, I could put in some time to make a little Python repo with a minimal reproduction.

I think concurrently has amazing potential for full-stack web development, but this issue kind of ruins the Python experience.

[gustavohenke]

Hey! This issue fell through the cracks. The issue wouldn't happen with raw mode because I/O handling is delegated entirely to the OS. So it must be a bug in concurrently.

@ixxie if you can make a reproduction, that'd be good - the original one doesn't work for me on macOS Sonoma.

[ixxie]

Hey! This issue fell through the cracks. The issue wouldn't happen with raw mode because I/O handling is delegated entirely to the OS. So it must be a bug in concurrently.

@ixxie if you can make a reproduction, that'd be good - the original one doesn't work for me on macOS Sonoma.

I've now published a simple reproduction repository which has a minimal Python Uvicorn/FastAPI and a minimal SvelteKit backend.

I've manage to reproduce Unicorn HMR failure and ANSI color code propagation failure. I didn't have luck reproducible the exception tracing error; I suspect it requires some subprocess to run in order to manifest. I'm going to keep trying to reproduce it, and I'll push a new commit if I succeed.

[ixxie]

@gustavohenke if you would like I could make a separate issue for the uvicorn HMR crash

[gustavohenke]

Hey, I haven't been able to reproduce either issue on macOS yet. I might take a bit of time to get around running Windows again, so if you feel like venturing into this codebase, I'll review any PRs 😃

As for the colouring issue - seems like python/poetry is disabling colours when its output is piped, so not much that can be done here (seems like FORCE_COLOR env var isn't respected either)

[ixxie]

Hey, I haven't been able to reproduce either issue on macOS yet. I might take a bit of time to get around running Windows again, so if you feel like venturing into this codebase, I'll review any PRs 😃

As for the colouring issue - seems like python/poetry is disabling colours when its output is piped, so not much that can be done here (seems like FORCE_COLOR env var isn't respected either)

When you say 'either issue' it sounds like you tried to reproduce two issues, but there are three (delayed stack trace printing, uvicorn HMR crashing the process and color output not propagating). Did you try all three or only two? If so, which two?

I would love to try and dig into the codebase, but I honestly don't even know where I would begin. For us, the HMR issue is critical right now: could you point to where in the codebase I might begin to look to try and resolve this issue?

The other two issues are no longer manifesting for us, perhaps because of the --raw flag.

[gustavohenke]

When you say 'either issue' it sounds like you tried to reproduce two issues, but there are three (delayed stack trace printing, uvicorn HMR crashing the process and color output not propagating). Did you try all three or only two? If so, which two?

Oh yeah could've been more specific, sorry! I couldn't reproduce the crash nor the delayed stack trace printing. Colouring seems to be related to the piping of output.

could you point to where in the codebase I might begin to look to try and resolve this issue?

Sure, let me try to explain the overall structure that might be significant to you:

Path	Description
https://github.com/open-cli-tools/concurrently/tree/23f97ac412f390a9913f96814da1f4070704d955/src/command-parser	command parsers take the input commands and might modify it or expand it, such as an wildcard transforming npm:server-* to several npm run server-<something> commands. Could theoretically modify the env vars a command receives, its prefix colour, etc
https://github.com/open-cli-tools/concurrently/tree/23f97ac412f390a9913f96814da1f4070704d955/src/flow-control	this is where the several flow controllers live, which handle the main features of concurrently, such as logging, killing/restarting processes and input handling. They receive the list of all commands, and can change a command's streams, for example
https://github.com/open-cli-tools/concurrently/blob/23f97ac412f390a9913f96814da1f4070704d955/src/spawn.ts	defines the options that might be passed to child_process.spawn() for each command
https://github.com/open-cli-tools/concurrently/blob/23f97ac412f390a9913f96814da1f4070704d955/src/command.ts	state of a command, which includes metadata (such as name, prefix colour, PID, etc) + its stdio and close streams;
https://github.com/open-cli-tools/concurrently/blob/23f97ac412f390a9913f96814da1f4070704d955/src/completion-listener.ts	waits for commands to exit and defines whether that was a success (exit code 0) or not based on given a success definition (e.g. first/last command to exit, all, etc)
https://github.com/open-cli-tools/concurrently/blob/23f97ac412f390a9913f96814da1f4070704d955/src/logger.ts	decorates output from commands and events such as "sending SIGTERM to other processes..." with prefixes and colours
https://github.com/open-cli-tools/concurrently/blob/23f97ac412f390a9913f96814da1f4070704d955/src/output-writer.ts	where writing to the output stream is actually done.
https://github.com/open-cli-tools/concurrently/blob/23f97ac412f390a9913f96814da1f4070704d955/src/concurrently.ts	Orchestrates all of the above.

Concurrently is structured in a quite OOP way, with interfaces that are implemented by all of the command parsers and flow controllers and they're called in sequence. Each file usually does only one thing, so it should be easy to find what you need to change given the above table.

Good luck!