iOS testbed doesn't reliably capture *all* log output

[freakboy3742]

Bug report

Bug description:

The iOS testbed captures test output by streaming the system log. It does this by running a log stream in parallel to the process that is running the test suite.

However, it takes time for this log stream to start; if the test suite finishes really quickly, it's possible no output will be captured at all. The test status will be accurately reported, because that's based on the return code of the process and is handled by Xcode; but in the case of a test failure, there won't be any log output that reports why the test failed.

Alternatively, if the test machine is busy and is generating lots of other log content, it will occasionally drop lines of output, as log stream will prioritizes currency of the log over completeness. These can be seen in iOS buildbot logs:

=== Messages dropped during live streaming (use `log show` to see what they were)

Ideally, we wouldn't lose any log output; however, this may not be possible given the constraints of iOS stdout logging.

As a workaround, it may be preferable to use log show after the completion of a test run to get a complete log. This will result in log output being output twice - an initial "live" log (which might contain dropped lines) to indicate test progress, and then a "complete" log that contains everything at the completion of the test run. This "complete" log can be generated with log show, which is guaranteed to produce a complete log. As the log is only truly useful in the case of a test failure, it might be desirable to only generate the complete log on test failure.

CPython versions tested on:

CPython main branch

Operating systems tested on:

Other

[mhsmith]

It may be possible to address both of these problems by filtering by PID. See discussion in beeware/briefcase#2086.

[freakboy3742]

The situation for the testbed slightly is a little different to Briefcase - in Briefcase, we're directly starting the app, which gives some options for discovering the PID; in testbed, we're telling Xcode to start the app, and we have very little visibility of the internals of that process. That makes the process of finding the executable a little more difficult.

It might be possible to make it work, but we'd effectively going to be in a similar situation to the simulator startup where can't directly interrogate the ID of the simulator, instead getting a list of all processes and looking for one that has the right name. That could probably work, but it's going to be at least a little fragile (as we've seen with the simulator identification process being intolerant to being run in parallel).

[freakboy3742]

An anecdotal observation is that this seems to be a lot less common on Xcode 16/iOS 18.

The 5 most recent CI builds on main (CI builds 2845-2849) only include 1 instance of the "Messages dropped" message - and that occurrence is always the very first message printed, and there isn't any actual loss of log data (the first printed log line is Test command: (test, "-uall", ...), which is the first expected line of log output.

A month ago (CI builds 2451-2455), when we were running on Xcode 15/iOS 17, there were between 4 and 9 of these messages per test run, resulting in the loss of 1-5 test results from the log (usually in the first 20 or so tests executed).

There's still a notable gap if the test suite finishes really quickly - i.e., a print("hello world"); sys.exit(1) test can result in no test output being observed - but that's a fairly extreme case not seen in practice.

That's probably not enough to call this "fixed" - but it definitely makes it a less urgent problem to address.

FWIW: I did a bit of poking around to see if it there was a possible fix based on process ID filtering - but it's difficult to establish if a fix is working when the problem isn't actually observable any more.

I also investigated the possibility of the "log show > timestamp" approach suggested in the original report; it turns out the approach won't work because Xcode is in control of the simulator, and will shut the simulator down before we get a chance to run log show. You can't run log show on a terminated simulator, and the simulator instance is intentionally transient, so it's destroyed as soon as the test completes.