Need Post-Test Step for Converting Logs

[nibanks]

Right now, MsQuic cannot collect logs because it requires commands to be executed after the test runs. But the current setup runs the server continuously and then just kills the container. This never allows for us to collect/convert our log files. We need either:

• An explicit new step/script to be run after killing the server process.
• Or, an explicit signal to shutdown the server and then time enough to run the necessary scripts after the server app process exits.

[marten-seemann]

It looks like it's not possible to trap signals when using the --abort-on-container-exit option in docker-compose. I opened docker/compose#7652.

[nibanks]

With @larseggert's help we've been able to push an updated MsQuic Docker image that supports streaming, but it still has issues. There seems to be a race condition where the server is shutdown before all the logs flush to disk. Perhaps, as a temporary stop-gap solution you add a sleep for a second or two before killing the server?

[marten-seemann]

Perhaps, as a temporary stop-gap solution you add a sleep for a second or two before killing the server?

That would be a workaround, but not an easy one. —abort-on-container-exit doesn’t allow you to do anything like that, so we’d have to start and stop the containers manually. I really hope that someone will pick up my docker-compose issue, otherwise we’ll have no choice but to actually implement that workaround.

[marten-seemann]

Nobody picked up the issue in more than a week. Time to implement the workaround! 👎

[marten-seemann]

After playing around with this for a while, it seems like the problem is the following: We need to run a subprocess.run for every container (simulator, server and client). I haven't figured this part out yet, we might need to use the threading package to run them in parallel.
The problem is that we want to access the logs here. People log to stdout, and we need to capture that. What's more, we need to aggregate the logs of the three containers into one file such that the lines appear in the right order. subprocess.run only allows us to get the logs after the container has returned, so there's no way to restore the ordering of logs between the containers.

According to the documentation it's only possible to pass a physical file to the stdout argument of that function. I'm not sure how anyone could think that this is a sane way to design an API, why not use an interface there, so users can use their own implementation of that interface? While I could create a temporary file on disk to pass into that function, and then read that file into memory after the commands have returned, this doesn't allow me to prefix every line with [client] or [server].

@jlaine, can we ask for your wisdom here? I'm sure there must be better way in Python to do this...

[nibanks]

We have some streaming stuff enabled, but it doesn't work very well because it seems to be timer based, so much of the time we end up losing much of the end of our logs (where the relevant errors end up being). I'd really be appreciated if we could get this feature in!

[nibanks]

Any updates? I'd really like to get consistent logging for msquic working, but can't do it without this.

[anrossi]

Is it possible to make progress on this issue? Or is it blocked completely on the docker-compose issue/Python submodule API? MsQuic logging is still largely missing in interop runner failure cases due to this, which hurts our ability to diagnose and improve interop.
If there's no possible way forward, feel free close this issue.

[marten-seemann]

There's code for that in this branch: https://github.com/marten-seemann/quic-interop-runner/tree/separate-docker-compose-runs
For some reason it makes the interop runs very flaky though. Unfortunately, I won't have to time figure out what's going on there, but maybe you can make sense of this?