Repository: beeware/briefcase
Pull request #731 (2022-05-04 23:33:15)

Implement Popen Output Streamer
As detailed in #676, the attempt to display the iOS simulator log can miss the first few seconds of log output. This is because the capturing of the log output is started after the simulator is started; therefore, there will always be a non-zero amount of time that log output is not being captured.

Log streaming for macOS and iOS simulator now start before the app is started; once the app is running, any queued log output is flushed to the screen and new log output is printed in real time.

## Implementation
 - A new function in `subprocess.py` loops on the `stdout` output of an established `Popen` process
   - The loop will properly exit when it detects the underlying process has exited
   - The loop will properly exit and terminate the underlying process if the user sends CTRL+C
 - Starting up the iOS simulator was updated to initiate `log stream` via `Popen`
 - Once the simulator is started, the new output streaming function is called to print all of the simulator log

## PR Checklist:
<!--- Go over all the following points, and put an `x` in all the boxes that apply. -->
- [x] All new features have been tested
- [x] All new features have been documented
- [x] I have read the **CONTRIBUTING.md** file
- [x] I will abide by the code of conduct


rmartin16: @freakboy3742, before I move too much further forward with this proposal, can you please provide any thoughts you have?

I know you mentioned threading in #676 but I felt that `Popen` would give us better control over this (especially since we're already doing so much with `subprocess`). This approach makes it more straightforward to start showing output exactly when we want; and in the most general use case for this, I thought this was superior over kicking off a command in to another thread where it would definitely be trickier to control when the thread started printing....especially if we wanted to print more things in the main thread first.
codecov[bot]: # [Codecov](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) Report
> Merging [#731](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (80adf70) into [main](https://codecov.io/gh/beeware/briefcase/commit/b5ebc6d1c816aada7c1e5c1f605a671a733d1d40?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (b5ebc6d) will **decrease** coverage by `0.56%`.
> The diff coverage is `39.28%`.

| [Impacted Files](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) | Coverage Δ | |
|---|---|---|
| [src/briefcase/integrations/subprocess.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9pbnRlZ3JhdGlvbnMvc3VicHJvY2Vzcy5weQ==) | `86.17% <10.52%> (-13.83%)` | :arrow_down: |
| [src/briefcase/platforms/iOS/xcode.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9wbGF0Zm9ybXMvaU9TL3hjb2RlLnB5) | `94.82% <100.00%> (+0.18%)` | :arrow_up: |

codecov[bot]: # [Codecov](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) Report
> Merging [#731](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (80adf70) into [main](https://codecov.io/gh/beeware/briefcase/commit/b5ebc6d1c816aada7c1e5c1f605a671a733d1d40?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (b5ebc6d) will **decrease** coverage by `0.56%`.
> The diff coverage is `39.28%`.

> :exclamation: Current head 80adf70 differs from pull request most recent head d9ab3fd. Consider uploading reports for the commit d9ab3fd to get more accurate results

| [Impacted Files](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) | Coverage Δ | |
|---|---|---|
| [src/briefcase/integrations/subprocess.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9pbnRlZ3JhdGlvbnMvc3VicHJvY2Vzcy5weQ==) | `86.17% <10.52%> (-13.83%)` | :arrow_down: |
| [src/briefcase/platforms/iOS/xcode.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9wbGF0Zm9ybXMvaU9TL3hjb2RlLnB5) | `94.82% <100.00%> (+0.18%)` | :arrow_up: |

codecov[bot]: # [Codecov](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) Report
> Merging [#731](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (d9ab3fd) into [main](https://codecov.io/gh/beeware/briefcase/commit/b5ebc6d1c816aada7c1e5c1f605a671a733d1d40?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (b5ebc6d) will **increase** coverage by `0.03%`.
> The diff coverage is `100.00%`.

| [Impacted Files](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) | Coverage Δ | |
|---|---|---|
| [src/briefcase/integrations/subprocess.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9pbnRlZ3JhdGlvbnMvc3VicHJvY2Vzcy5weQ==) | `100.00% <100.00%> (ø)` | |
| [src/briefcase/platforms/iOS/xcode.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9wbGF0Zm9ybXMvaU9TL3hjb2RlLnB5) | `94.82% <100.00%> (+0.18%)` | :arrow_up: |

codecov[bot]: # [Codecov](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) Report
> Merging [#731](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (d9ab3fd) into [main](https://codecov.io/gh/beeware/briefcase/commit/b5ebc6d1c816aada7c1e5c1f605a671a733d1d40?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (b5ebc6d) will **increase** coverage by `0.03%`.
> The diff coverage is `100.00%`.

> :exclamation: Current head d9ab3fd differs from pull request most recent head c099938. Consider uploading reports for the commit c099938 to get more accurate results

| [Impacted Files](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) | Coverage Δ | |
|---|---|---|
| [src/briefcase/integrations/subprocess.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9pbnRlZ3JhdGlvbnMvc3VicHJvY2Vzcy5weQ==) | `100.00% <100.00%> (ø)` | |
| [src/briefcase/platforms/iOS/xcode.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9wbGF0Zm9ybXMvaU9TL3hjb2RlLnB5) | `94.82% <100.00%> (+0.18%)` | :arrow_up: |

codecov[bot]: # [Codecov](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) Report
> Merging [#731](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (c099938) into [main](https://codecov.io/gh/beeware/briefcase/commit/b5ebc6d1c816aada7c1e5c1f605a671a733d1d40?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (b5ebc6d) will **increase** coverage by `0.03%`.
> The diff coverage is `100.00%`.

| [Impacted Files](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) | Coverage Δ | |
|---|---|---|
| [src/briefcase/integrations/subprocess.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9pbnRlZ3JhdGlvbnMvc3VicHJvY2Vzcy5weQ==) | `100.00% <100.00%> (ø)` | |
| [src/briefcase/platforms/iOS/xcode.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9wbGF0Zm9ybXMvaU9TL3hjb2RlLnB5) | `94.82% <100.00%> (+0.18%)` | :arrow_up: |

rmartin16: I moved the stream function inside of `Subprocess` still taking a `Popen` process. However, I removed any sort of detection of "failure" from it. The more I thought about it, the more it felt out of place to try to interpret if the process was in a state of failure just because it had seemingly exited prior to the stream function being invoked. Instead, the stream function will look for output, print it, and exit as normal.

That said, if we wanted to detect failure, it seems more appropriate to do so back up where streaming is being invoked. However, even here, I was having trouble determining when `log stream` may have failed....or if it ran normally but looks like it failed. For instance, if I close the iOS simulator while `log stream` is still running, the `log stream` process is killed automatically and returns a non-zero code. However, this isn't really a failure mode but looks very similar to what might be considered one. (Replicating this on `main` results in a "unable to start log stream" error.) Finally, I'm not even sure if it's worth tracking if `log stream` itself failed....it seems other problems would likely show up elsewhere before `log stream` failed. That said, we can add checks on its return codes perhaps if you think it's worth it.

I implemented this log streaming for the iOS simulator and macOS apps. AFAICT, adb's `logcat` will print everything in its ring buffer log that matches the filter....so starting it early doesn't seem to offer a benefit. Linux and Windows apps seem to depend on normal printing `stdout` for logging. That said, let me know if I should add this anywhere else you know of.
codecov[bot]: # [Codecov](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) Report
> Merging [#731](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (c099938) into [main](https://codecov.io/gh/beeware/briefcase/commit/b5ebc6d1c816aada7c1e5c1f605a671a733d1d40?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (b5ebc6d) will **increase** coverage by `0.03%`.
> The diff coverage is `100.00%`.

> :exclamation: Current head c099938 differs from pull request most recent head 7645e12. Consider uploading reports for the commit 7645e12 to get more accurate results

| [Impacted Files](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) | Coverage Δ | |
|---|---|---|
| [src/briefcase/integrations/subprocess.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9pbnRlZ3JhdGlvbnMvc3VicHJvY2Vzcy5weQ==) | `100.00% <100.00%> (ø)` | |
| [src/briefcase/platforms/iOS/xcode.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9wbGF0Zm9ybXMvaU9TL3hjb2RlLnB5) | `94.82% <100.00%> (+0.18%)` | :arrow_up: |

codecov[bot]: # [Codecov](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) Report
> Merging [#731](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (7645e12) into [main](https://codecov.io/gh/beeware/briefcase/commit/b5ebc6d1c816aada7c1e5c1f605a671a733d1d40?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (b5ebc6d) will **increase** coverage by `0.03%`.
> The diff coverage is `100.00%`.

| [Impacted Files](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) | Coverage Δ | |
|---|---|---|
| [src/briefcase/integrations/subprocess.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9pbnRlZ3JhdGlvbnMvc3VicHJvY2Vzcy5weQ==) | `100.00% <100.00%> (ø)` | |
| [src/briefcase/platforms/iOS/xcode.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9wbGF0Zm9ybXMvaU9TL3hjb2RlLnB5) | `94.82% <100.00%> (+0.18%)` | :arrow_up: |

codecov[bot]: # [Codecov](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) Report
> Merging [#731](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (c099938) into [main](https://codecov.io/gh/beeware/briefcase/commit/b5ebc6d1c816aada7c1e5c1f605a671a733d1d40?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (b5ebc6d) will **increase** coverage by `0.03%`.
> The diff coverage is `100.00%`.

> :exclamation: Current head c099938 differs from pull request most recent head d4abeb9. Consider uploading reports for the commit d4abeb9 to get more accurate results

| [Impacted Files](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) | Coverage Δ | |
|---|---|---|
| [src/briefcase/integrations/subprocess.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9pbnRlZ3JhdGlvbnMvc3VicHJvY2Vzcy5weQ==) | `100.00% <100.00%> (ø)` | |
| [src/briefcase/platforms/iOS/xcode.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9wbGF0Zm9ybXMvaU9TL3hjb2RlLnB5) | `94.82% <100.00%> (+0.18%)` | :arrow_up: |

codecov[bot]: # [Codecov](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) Report
> Merging [#731](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (d4abeb9) into [main](https://codecov.io/gh/beeware/briefcase/commit/b5ebc6d1c816aada7c1e5c1f605a671a733d1d40?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (b5ebc6d) will **increase** coverage by `0.02%`.
> The diff coverage is `100.00%`.

| [Impacted Files](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) | Coverage Δ | |
|---|---|---|
| [src/briefcase/integrations/subprocess.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9pbnRlZ3JhdGlvbnMvc3VicHJvY2Vzcy5weQ==) | `100.00% <100.00%> (ø)` | |
| [src/briefcase/platforms/iOS/xcode.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9wbGF0Zm9ybXMvaU9TL3hjb2RlLnB5) | `94.70% <100.00%> (+0.06%)` | :arrow_up: |

rmartin16: Responded to comments.

Outstanding items:
 - Structure of `Popen` output streaming loop
 - Waiting after starting `log stream`
 - `Popen` exception catching
codecov[bot]: # [Codecov](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) Report
> Merging [#731](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (d4abeb9) into [main](https://codecov.io/gh/beeware/briefcase/commit/b5ebc6d1c816aada7c1e5c1f605a671a733d1d40?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (b5ebc6d) will **increase** coverage by `0.02%`.
> The diff coverage is `100.00%`.

> :exclamation: Current head d4abeb9 differs from pull request most recent head 96a9543. Consider uploading reports for the commit 96a9543 to get more accurate results

| [Impacted Files](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) | Coverage Δ | |
|---|---|---|
| [src/briefcase/integrations/subprocess.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9pbnRlZ3JhdGlvbnMvc3VicHJvY2Vzcy5weQ==) | `100.00% <100.00%> (ø)` | |
| [src/briefcase/platforms/iOS/xcode.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9wbGF0Zm9ybXMvaU9TL3hjb2RlLnB5) | `94.70% <100.00%> (+0.06%)` | :arrow_up: |

codecov[bot]: # [Codecov](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) Report
> Merging [#731](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (96a9543) into [main](https://codecov.io/gh/beeware/briefcase/commit/b5ebc6d1c816aada7c1e5c1f605a671a733d1d40?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) (b5ebc6d) will **increase** coverage by `0.02%`.
> The diff coverage is `100.00%`.

| [Impacted Files](https://codecov.io/gh/beeware/briefcase/pull/731?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware) | Coverage Δ | |
|---|---|---|
| [src/briefcase/integrations/subprocess.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9pbnRlZ3JhdGlvbnMvc3VicHJvY2Vzcy5weQ==) | `100.00% <100.00%> (ø)` | |
| [src/briefcase/platforms/iOS/xcode.py](https://codecov.io/gh/beeware/briefcase/pull/731/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=beeware#diff-c3JjL2JyaWVmY2FzZS9wbGF0Zm9ybXMvaU9TL3hjb2RlLnB5) | `94.70% <100.00%> (+0.06%)` | :arrow_up: |


Patch:
diff --git a/changes/731.bugfix.rst b/changes/731.bugfix.rst
new file mode 100644
index 00000000..71f38d72
--- /dev/null
+++ b/changes/731.bugfix.rst
@@ -0,0 +1,1 @@
+All log entries will now be displayed for the run command on iOS and macOS; previously, initial log entries may have been omitted.
\ No newline at end of file
diff --git a/src/briefcase/integrations/subprocess.py b/src/briefcase/integrations/subprocess.py
index 6aec2f01..e7edb48a 100644
--- a/src/briefcase/integrations/subprocess.py
+++ b/src/briefcase/integrations/subprocess.py
@@ -232,6 +232,53 @@ class Subprocess:
             **self.final_kwargs(**kwargs)
         )
 
+    def stream_output(self, label, popen_process):
+        """
+        Stream the output of a Popen process until the process exits.
+        If the user sends CTRL+C, the process will be terminated.
+
+        This is useful for starting a process via Popen such as tailing a
+        log file, then initiating a non-blocking process that populates that
+        log, and finally streaming the original process's output here.
+
+        :param label: A description of the content being streamed; used for
+            to provide context in logging messages.
+        :param popen_process: a running Popen process with output to print
+        """
+        try:
+            while True:
+                # readline should always return at least a newline (ie \n)
+                # UNLESS the underlying process is exiting/gone; then "" is returned
+                output_line = ensure_str(popen_process.stdout.readline())
+                if output_line:
+                    self.command.logger.info(output_line)
+                elif output_line == "":
+                    # a return code will be available once the process returns one to the OS.
+                    # by definition, that should mean the process has exited.
+                    return_code = popen_process.poll()
+                    # only return once all output has been read and the process has exited.
+                    if return_code is not None:
+                        self._log_return_code(return_code)
+                        return
+
+        except KeyboardInterrupt:
+            self.cleanup(label, popen_process)
+
+    def cleanup(self, label, popen_process):
+        """
+        Clean up after a Popen process, gracefully terminating if possible; forcibly if not.
+
+        :param label: A description of the content being streamed; used for
+            to provide context in logging messages.
+        :param popen_process: The Popen instance to clean up.
+        """
+        popen_process.terminate()
+        try:
+            popen_process.wait(timeout=3)
+        except subprocess.TimeoutExpired:
+            self.command.logger.warning(f"Forcibly killing {label}...")
+            popen_process.kill()
+
     def _log_command(self, args):
         """
         Log the entire console command being executed.
diff --git a/src/briefcase/platforms/iOS/xcode.py b/src/briefcase/platforms/iOS/xcode.py
index ad279d2a..f309a111 100644
--- a/src/briefcase/platforms/iOS/xcode.py
+++ b/src/briefcase/platforms/iOS/xcode.py
@@ -319,6 +319,7 @@ class iOSXcodeRunCommand(iOSXcodeMixin, RunCommand):
         # Try to uninstall the app first. If the app hasn't been installed
         # before, this will still succeed.
         app_identifier = '.'.join([app.bundle, app.app_name])
+        self.logger.info()
         self.logger.info(f'[{app.app_name}] Uninstalling old app version...')
         try:
             self.subprocess.run(
@@ -329,6 +330,7 @@ class iOSXcodeRunCommand(iOSXcodeMixin, RunCommand):
             raise BriefcaseCommandError(f"Unable to uninstall old version of app {app.app_name}.")
 
         # Install the app.
+        self.logger.info()
         self.logger.info(f'[{app.app_name}] Installing new app version...')
         try:
             self.subprocess.run(
@@ -338,6 +340,23 @@ class iOSXcodeRunCommand(iOSXcodeMixin, RunCommand):
         except subprocess.CalledProcessError:
             raise BriefcaseCommandError(f"Unable to install new version of app {app.app_name}.")
 
+        # Start log stream for the app.
+        simulator_log_popen = self.subprocess.Popen(
+            [
+                "xcrun", "simctl", "spawn", udid,
+                "log", "stream",
+                "--style", "compact",
+                "--predicate", f'senderImagePath ENDSWITH "/{app.formal_name}"'
+            ],
+            stdout=subprocess.PIPE,
+            stderr=subprocess.STDOUT,
+            bufsize=1,
+        )
+
+        # Wait for the log stream start up
+        self.sleep(0.25)
+
+        self.logger.info()
         self.logger.info(f'[{app.app_name}] Starting app...')
         try:
             self.subprocess.run(
@@ -345,24 +364,14 @@ class iOSXcodeRunCommand(iOSXcodeMixin, RunCommand):
                 check=True
             )
         except subprocess.CalledProcessError:
+            self.subprocess.cleanup("log stream", simulator_log_popen)
             raise BriefcaseCommandError(f"Unable to launch app {app.app_name}.")
 
         # Start streaming logs for the app.
-        try:
-            self.logger.info()
-            self.logger.info(f"[{app.app_name}] Following simulator log output (type CTRL-C to stop log)...")
-            self.logger.info("=" * 75)
-            self.subprocess.run(
-                [
-                    "xcrun", "simctl", "spawn", udid,
-                    "log", "stream",
-                    "--style", "compact",
-                    "--predicate", f'senderImagePath ENDSWITH "/{app.formal_name}"',
-                ],
-                check=True,
-            )
-        except subprocess.CalledProcessError:
-            raise BriefcaseCommandError(f"Unable to start log stream for app {app.app_name}.")
+        self.logger.info()
+        self.logger.info(f"[{app.app_name}] Following simulator log output (type CTRL-C to stop log)...")
+        self.logger.info("=" * 75)
+        self.subprocess.stream_output("log stream", simulator_log_popen)
 
         # Preserve the device selection as state.
         return {
diff --git a/src/briefcase/platforms/macOS/__init__.py b/src/briefcase/platforms/macOS/__init__.py
index 2d269899..5d84f064 100644
--- a/src/briefcase/platforms/macOS/__init__.py
+++ b/src/briefcase/platforms/macOS/__init__.py
@@ -1,5 +1,6 @@
 import os
 import subprocess
+import time
 from pathlib import Path
 
 from briefcase.config import BaseConfig
@@ -32,6 +33,37 @@ class macOSRunMixin:
 
         :param app: The config object for the app
         """
+        # Start log stream for the app.
+        # Streaming the system log is... a mess. The system log contains a
+        # *lot* of noise from other processes; even if you filter by
+        # process, there's a lot of macOS-generated noise. It's very
+        # difficult to extract just the "user generated" stdout/err log
+        # messages.
+        #
+        # The following sets up a log stream filter that looks for:
+        #  1. a log sender that matches that app binary; or,
+        #  2. a log sender of libffi, and a process that matches the app binary.
+        # Case (1) works for pre-Python 3.9 static linked binaries.
+        # Case (2) works for Python 3.9+ dynamic linked binaries.
+        sender = os.fsdecode(self.binary_path(app) / "Contents" / "MacOS" / app.formal_name)
+        log_popen = self.subprocess.Popen(
+            [
+                "log",
+                "stream",
+                "--style", "compact",
+                "--predicate",
+                f'senderImagePath=="{sender}"'
+                f' OR (processImagePath=="{sender}"'
+                ' AND senderImagePath=="/usr/lib/libffi.dylib")',
+            ],
+            stdout=subprocess.PIPE,
+            stderr=subprocess.STDOUT,
+            bufsize=1,
+        )
+
+        # Wait for the log stream start up
+        time.sleep(0.25)
+
         self.logger.info()
         self.logger.info(f'[{app.app_name}] Starting app...')
         try:
@@ -44,39 +76,14 @@ class macOSRunMixin:
                 check=True,
             )
         except subprocess.CalledProcessError:
+            self.subprocess.cleanup("log stream", log_popen)
             raise BriefcaseCommandError(f"Unable to start app {app.app_name}.")
 
         # Start streaming logs for the app.
-        try:
-            self.logger.info()
-            self.logger.info(f"[{app.app_name}] Following system log output (type CTRL-C to stop log)...")
-            self.logger.info("=" * 75)
-            # Streaming the system log is... a mess. The system log contains a
-            # *lot* of noise from other processes; even if you filter by
-            # process, there's a lot of macOS-generated noise. It's very
-            # difficult to extract just the "user generated" stdout/err log
-            # messages.
-            #
-            # The following sets up a log stream filter that looks for:
-            #  1. a log sender that matches that app binary; or,
-            #  2. a log sender of libffi, and a process that matches the app binary.
-            # Case (1) works for pre-Python 3.9 static linked binaries.
-            # Case (2) works for Python 3.9+ dynamic linked binaries.
-            sender = os.fsdecode(self.binary_path(app) / "Contents" / "MacOS" / app.formal_name)
-            self.subprocess.run(
-                [
-                    "log",
-                    "stream",
-                    "--style", "compact",
-                    "--predicate",
-                    f'senderImagePath=="{sender}"'
-                    f' OR (processImagePath=="{sender}"'
-                    ' AND senderImagePath=="/usr/lib/libffi.dylib")',
-                ],
-                check=True,
-            )
-        except subprocess.CalledProcessError:
-            raise BriefcaseCommandError(f"Unable to start log stream for app {app.app_name}.")
+        self.logger.info()
+        self.logger.info(f"[{app.app_name}] Following system log output (type CTRL-C to stop log)...")
+        self.logger.info("=" * 75)
+        self.subprocess.stream_output("log stream", log_popen)
 
 
 def is_mach_o_binary(path):


Test patch:
diff --git a/tests/integrations/subprocess/test_Subprocess__cleanup.py b/tests/integrations/subprocess/test_Subprocess__cleanup.py
new file mode 100644
index 00000000..177a8627
--- /dev/null
+++ b/tests/integrations/subprocess/test_Subprocess__cleanup.py
@@ -0,0 +1,34 @@
+import subprocess
+
+from unittest import mock
+
+
+def test_clean_termination(mock_sub, capsys):
+    "A popen process can be cleanly terminated"
+    process = mock.MagicMock()
+
+    mock_sub.cleanup('testing process', process)
+
+    process.terminate.assert_called_once()
+    process.wait.assert_called_once_with(timeout=3)
+    process.kill.assert_not_called()
+
+    # No log messages for a clean exit
+    assert capsys.readouterr().out == ""
+
+
+def test_dirty_termination(mock_sub, capsys):
+    "If terminate doesn't stop the process, it will be forcibly killed"
+    process = mock.MagicMock()
+    process.wait.side_effect = subprocess.TimeoutExpired(cmd="ls", timeout=3)
+
+    mock_sub.cleanup('testing process', process)
+
+    process.terminate.assert_called_once()
+    process.wait.assert_called_once_with(timeout=3)
+    process.kill.assert_called_once_with()
+
+    # Log contains a contextual message.
+    assert capsys.readouterr().out == (
+        "Forcibly killing testing process...\n"
+    )
diff --git a/tests/integrations/subprocess/test_Subprocess__stream_output.py b/tests/integrations/subprocess/test_Subprocess__stream_output.py
new file mode 100644
index 00000000..473e028e
--- /dev/null
+++ b/tests/integrations/subprocess/test_Subprocess__stream_output.py
@@ -0,0 +1,89 @@
+import pytest
+from unittest import mock
+
+from briefcase.console import Log
+
+
+@pytest.fixture
+def popen_process():
+    process = mock.MagicMock()
+
+    # There are extra empty strings at the end to simulate readline
+    # continuously returning "" once it reaches EOF
+    process.stdout.readline.side_effect = [
+        "output line 1\n",
+        "\n",
+        "output line 3\n",
+        "",
+        "",
+        "",
+        "",
+        "",
+        ""
+    ]
+    process.poll.side_effect = [None, None, None, -3]
+
+    return process
+
+
+def test_output(mock_sub, popen_process, capsys):
+    "Readline output is printed"
+    mock_sub.stream_output('testing', popen_process)
+    assert capsys.readouterr().out == (
+        "output line 1\n"
+        "\n"
+        "output line 3\n"
+    )
+
+
+def test_output_debug(mock_sub, popen_process, capsys):
+    "Readline output is printed; debug mode should not add extra output"
+    mock_sub.command.logger = Log(verbosity=2)
+
+    mock_sub.stream_output('testing', popen_process)
+    assert capsys.readouterr().out == (
+        "output line 1\n"
+        "\n"
+        "output line 3\n"
+    )
+
+
+def test_output_deep_debug(mock_sub, popen_process, capsys):
+    "Readline output is printed with debug return code in deep debug mode"
+    mock_sub.command.logger = Log(verbosity=3)
+
+    mock_sub.stream_output('testing', popen_process)
+    assert capsys.readouterr().out == (
+        "output line 1\n"
+        "\n"
+        "output line 3\n"
+        ">>> Return code: -3\n"
+    )
+
+
+def test_keyboard_interrupt(mock_sub, popen_process, capsys):
+    "Process is terminated if user sends CTRL+C"
+    popen_process.stdout.readline.side_effect = ["output line 1\n", "\n", KeyboardInterrupt()]
+    mock_sub.cleanup = mock.MagicMock()
+
+    mock_sub.stream_output("testing", popen_process)
+
+    # Response to the CTRL-C is a process cleanup.
+    mock_sub.cleanup.assert_called_once_with("testing", popen_process)
+
+    assert capsys.readouterr().out == (
+        "output line 1\n"
+        "\n"
+    )
+
+
+def test_process_exit_with_queued_output(mock_sub, popen_process, capsys):
+    "All output is printed despite the process exiting early"
+    popen_process.poll.side_effect = [None, -3, -3, -3]
+
+    mock_sub.stream_output('testing', popen_process)
+    assert capsys.readouterr().out == (
+        "output line 1\n"
+        "\n"
+        "output line 3\n"
+    )
diff --git a/tests/platforms/iOS/xcode/test_run.py b/tests/platforms/iOS/xcode/test_run.py
index 322cb524..6e2d8b77 100644
--- a/tests/platforms/iOS/xcode/test_run.py
+++ b/tests/platforms/iOS/xcode/test_run.py
@@ -23,6 +23,8 @@ def test_run_app_simulator_booted(first_app_config, tmp_path):
     command.get_device_state = mock.MagicMock(return_value=DeviceState.BOOTED)
 
     command.subprocess = mock.MagicMock()
+    log_stream_process = mock.MagicMock()
+    command.subprocess.Popen.return_value = log_stream_process
 
     # Run the app
     command.run_app(first_app_config)
@@ -66,18 +68,22 @@ def test_run_app_simulator_booted(first_app_config, tmp_path):
             ],
             check=True
         ),
-        # Start tailing the log
-        mock.call(
-            [
-                'xcrun', 'simctl', 'spawn',
-                '2D3503A3-6EB9-4B37-9B17-C7EFEF2FA32D',
-                "log", "stream",
-                "--style", "compact",
-                "--predicate", 'senderImagePath ENDSWITH "/First App"'
-            ],
-            check=True
-        )
     ])
+    # The log is being tailed; no process cleanup is triggered
+    command.subprocess.Popen.assert_called_with(
+        [
+            'xcrun', 'simctl', 'spawn',
+            '2D3503A3-6EB9-4B37-9B17-C7EFEF2FA32D',
+            "log", "stream",
+            "--style", "compact",
+            "--predicate", 'senderImagePath ENDSWITH "/First App"'
+        ],
+        stdout=subprocess.PIPE,
+        stderr=subprocess.STDOUT,
+        bufsize=1,
+    )
+    command.subprocess.stream_output.assert_called_with("log stream", log_stream_process)
+    command.subprocess.cleanup.assert_not_called()
 
 
 def test_run_app_simulator_shut_down(first_app_config, tmp_path):
@@ -95,6 +101,8 @@ def test_run_app_simulator_shut_down(first_app_config, tmp_path):
     command.get_device_state = mock.MagicMock(return_value=DeviceState.SHUTDOWN)
 
     command.subprocess = mock.MagicMock()
+    log_stream_process = mock.MagicMock()
+    command.subprocess.Popen.return_value = log_stream_process
 
     # Run the app
     command.run_app(first_app_config)
@@ -143,18 +151,22 @@ def test_run_app_simulator_shut_down(first_app_config, tmp_path):
             ],
             check=True
         ),
-        # Start tailing the log
-        mock.call(
-            [
-                'xcrun', 'simctl', 'spawn',
-                '2D3503A3-6EB9-4B37-9B17-C7EFEF2FA32D',
-                "log", "stream",
-                "--style", "compact",
-                "--predicate", 'senderImagePath ENDSWITH "/First App"'
-            ],
-            check=True
-        )
     ])
+    # The log is being tailed; no process cleanup is triggered
+    command.subprocess.Popen.assert_called_with(
+        [
+            'xcrun', 'simctl', 'spawn',
+            '2D3503A3-6EB9-4B37-9B17-C7EFEF2FA32D',
+            "log", "stream",
+            "--style", "compact",
+            "--predicate", 'senderImagePath ENDSWITH "/First App"'
+        ],
+        stdout=subprocess.PIPE,
+        stderr=subprocess.STDOUT,
+        bufsize=1,
+    )
+    command.subprocess.stream_output.assert_called_with("log stream", log_stream_process)
+    command.subprocess.cleanup.assert_not_called()
 
 
 def test_run_app_simulator_shutting_down(first_app_config, tmp_path):
@@ -182,12 +194,14 @@ def test_run_app_simulator_shutting_down(first_app_config, tmp_path):
 
     command.sleep = mock.MagicMock()
     command.subprocess = mock.MagicMock()
+    log_stream_process = mock.MagicMock()
+    command.subprocess.Popen.return_value = log_stream_process
 
     # Run the app
     command.run_app(first_app_config)
 
-    # We should have slept 3 times
-    assert command.sleep.call_count == 3
+    # We should have slept 4 times
+    assert command.sleep.call_count == 4
 
     # The correct sequence of commands was issued.
     command.subprocess.run.assert_has_calls([
@@ -233,18 +247,22 @@ def test_run_app_simulator_shutting_down(first_app_config, tmp_path):
             ],
             check=True
         ),
-        # Start tailing the log
-        mock.call(
-            [
-                'xcrun', 'simctl', 'spawn',
-                '2D3503A3-6EB9-4B37-9B17-C7EFEF2FA32D',
-                "log", "stream",
-                "--style", "compact",
-                "--predicate", 'senderImagePath ENDSWITH "/First App"'
-            ],
-            check=True
-        )
     ])
+    # The log is being tailed; no process cleanup has occurred
+    command.subprocess.Popen.assert_called_with(
+        [
+            'xcrun', 'simctl', 'spawn',
+            '2D3503A3-6EB9-4B37-9B17-C7EFEF2FA32D',
+            "log", "stream",
+            "--style", "compact",
+            "--predicate", 'senderImagePath ENDSWITH "/First App"'
+        ],
+        stdout=subprocess.PIPE,
+        stderr=subprocess.STDOUT,
+        bufsize=1,
+    )
+    command.subprocess.stream_output.assert_called_with("log stream", log_stream_process)
+    command.subprocess.cleanup.assert_not_called()
 
 
 def test_run_app_simulator_boot_failure(first_app_config, tmp_path):
@@ -279,6 +297,10 @@ def test_run_app_simulator_boot_failure(first_app_config, tmp_path):
             check=True,
         ),
     ])
+    # The log will not be tailed
+    command.subprocess.Popen.assert_not_called()
+    command.subprocess.stream_output.assert_not_called()
+    command.subprocess.cleanup.assert_not_called()
 
 
 def test_run_app_simulator_open_failure(first_app_config, tmp_path):
@@ -327,6 +349,10 @@ def test_run_app_simulator_open_failure(first_app_config, tmp_path):
             check=True
         ),
     ])
+    # The log will not be tailed
+    command.subprocess.Popen.assert_not_called()
+    command.subprocess.stream_output.assert_not_called()
+    command.subprocess.cleanup.assert_not_called()
 
 
 def test_run_app_simulator_uninstall_failure(first_app_config, tmp_path):
@@ -385,6 +411,10 @@ def test_run_app_simulator_uninstall_failure(first_app_config, tmp_path):
             check=True
         ),
     ])
+    # The log will not be tailed
+    command.subprocess.Popen.assert_not_called()
+    command.subprocess.stream_output.assert_not_called()
+    command.subprocess.cleanup.assert_not_called()
 
 
 def test_run_app_simulator_install_failure(first_app_config, tmp_path):
@@ -453,6 +483,10 @@ def test_run_app_simulator_install_failure(first_app_config, tmp_path):
             check=True
         ),
     ])
+    # The log will not be tailed
+    command.subprocess.Popen.assert_not_called()
+    command.subprocess.stream_output.assert_not_called()
+    command.subprocess.cleanup.assert_not_called()
 
 
 def test_run_app_simulator_launch_failure(first_app_config, tmp_path):
@@ -477,10 +511,12 @@ def test_run_app_simulator_launch_failure(first_app_config, tmp_path):
         0,
         0,
         subprocess.CalledProcessError(
-            cmd=['xcrun', 'simctl', 'uninstall', '...'],
+            cmd=['xcrun', 'simctl', 'launch', '...'],
             returncode=1
         ),
     ]
+    log_stream_process = mock.MagicMock()
+    command.subprocess.Popen.return_value = log_stream_process
 
     # Run the app
     with pytest.raises(BriefcaseCommandError):
@@ -531,93 +567,20 @@ def test_run_app_simulator_launch_failure(first_app_config, tmp_path):
             check=True
         )
     ])
-
-
-def test_run_app_simulator_log_stream_failure(first_app_config, tmp_path):
-    "If the log stream fails to start, raise an error"
-    command = iOSXcodeRunCommand(base_path=tmp_path)
-
-    # A valid target device will be selected.
-    command.select_target_device = mock.MagicMock(
-        return_value=(
-            '2D3503A3-6EB9-4B37-9B17-C7EFEF2FA32D', '13.2', 'iPhone 11'
-        )
+    # The log stream process will have been started; but will not be tailed
+    command.subprocess.Popen.assert_called_with(
+        [
+            'xcrun', 'simctl', 'spawn',
+            '2D3503A3-6EB9-4B37-9B17-C7EFEF2FA32D',
+            "log", "stream",
+            "--style", "compact",
+            "--predicate", 'senderImagePath ENDSWITH "/First App"'
+        ],
+        stdout=subprocess.PIPE,
+        stderr=subprocess.STDOUT,
+        bufsize=1,
     )
+    command.subprocess.stream_output.assert_not_called()
 
-    # Simulator is shut down
-    command.get_device_state = mock.MagicMock(return_value=DeviceState.SHUTDOWN)
-
-    # Call to boot and open simulator, uninstall and install succeed, but launch fails.
-    command.subprocess = mock.MagicMock()
-    command.subprocess.run.side_effect = [
-        0,
-        0,
-        0,
-        0,
-        0,
-        subprocess.CalledProcessError(
-            cmd=['xcrun', 'simctl', 'spawn', '...'],
-            returncode=1
-        ),
-    ]
-
-    # Run the app
-    with pytest.raises(BriefcaseCommandError):
-        command.run_app(first_app_config)
-
-    # The correct sequence of commands was issued.
-    command.subprocess.run.assert_has_calls([
-        # Boot the device
-        mock.call(
-            ['xcrun', 'simctl', 'boot', '2D3503A3-6EB9-4B37-9B17-C7EFEF2FA32D'],
-            check=True,
-        ),
-        # Open the simulator
-        mock.call(
-            [
-                'open',
-                '-a', 'Simulator',
-                '--args',
-                '-CurrentDeviceUDID', '2D3503A3-6EB9-4B37-9B17-C7EFEF2FA32D'
-            ],
-            check=True
-        ),
-        # Uninstall the old app
-        mock.call(
-            [
-                'xcrun', 'simctl', 'uninstall',
-                '2D3503A3-6EB9-4B37-9B17-C7EFEF2FA32D',
-                'com.example.first-app'
-            ],
-            check=True
-        ),
-        # Install the new app
-        mock.call(
-            [
-                'xcrun', 'simctl', 'install',
-                '2D3503A3-6EB9-4B37-9B17-C7EFEF2FA32D',
-                tmp_path / 'iOS' / 'Xcode' / 'First App' / 'build' / 'Debug-iphonesimulator' / 'First App.app'
-            ],
-            check=True
-        ),
-        # Launch the new app
-        mock.call(
-            [
-                'xcrun', 'simctl', 'launch',
-                '2D3503A3-6EB9-4B37-9B17-C7EFEF2FA32D',
-                'com.example.first-app'
-            ],
-            check=True
-        ),
-        # Start tailing the log
-        mock.call(
-            [
-                'xcrun', 'simctl', 'spawn',
-                '2D3503A3-6EB9-4B37-9B17-C7EFEF2FA32D',
-                "log", "stream",
-                "--style", "compact",
-                "--predicate", 'senderImagePath ENDSWITH "/First App"'
-            ],
-            check=True
-        )
-    ])
+    # The log process was cleaned up.
+    command.subprocess.cleanup.assert_called_once_with('log stream', log_stream_process)
diff --git a/tests/platforms/macOS/app/test_run.py b/tests/platforms/macOS/app/test_run.py
index b20b7c36..0de8c68e 100644
--- a/tests/platforms/macOS/app/test_run.py
+++ b/tests/platforms/macOS/app/test_run.py
@@ -12,35 +12,40 @@ def test_run_app(first_app_config, tmp_path):
     "A macOS app can be started"
     command = macOSAppRunCommand(base_path=tmp_path)
     command.subprocess = mock.MagicMock()
+    log_stream_process = mock.MagicMock()
+    command.subprocess.Popen.return_value = log_stream_process
 
     command.run_app(first_app_config)
 
     # Calls were made to start the app and to start a log stream.
     bin_path = command.binary_path(first_app_config)
     sender = bin_path / "Contents" / "MacOS" / "First App"
-    command.subprocess.run.assert_has_calls([
-        mock.call(
-            ['open', '-n', os.fsdecode(bin_path)],
-            check=True
-        ),
-        mock.call(
-            [
-                'log', 'stream',
-                '--style', 'compact',
-                '--predicate',
-                f'senderImagePath=="{sender}"'
-                f' OR (processImagePath=="{sender}"'
-                ' AND senderImagePath=="/usr/lib/libffi.dylib")',
-            ],
-            check=True,
-        )
-    ])
+    command.subprocess.Popen.assert_called_with(
+        [
+            'log', 'stream',
+            '--style', 'compact',
+            '--predicate',
+            f'senderImagePath=="{sender}"'
+            f' OR (processImagePath=="{sender}"'
+            ' AND senderImagePath=="/usr/lib/libffi.dylib")',
+        ],
+        stdout=subprocess.PIPE,
+        stderr=subprocess.STDOUT,
+        bufsize=1,
+    )
+    command.subprocess.run.assert_called_with(
+        ['open', '-n', os.fsdecode(bin_path)],
+        check=True
+    )
+    command.subprocess.stream_output.assert_called_with("log stream", log_stream_process)
 
 
 def test_run_app_failed(first_app_config, tmp_path):
     "If there's a problem started the app, an exception is raised"
     command = macOSAppRunCommand(base_path=tmp_path)
     command.subprocess = mock.MagicMock()
+    log_stream_process = mock.MagicMock()
+    command.subprocess.Popen.return_value = log_stream_process
     command.subprocess.run.side_effect = subprocess.CalledProcessError(
         cmd=['open', '-n', os.fsdecode(command.binary_path(first_app_config))],
         returncode=1
@@ -49,46 +54,27 @@ def test_run_app_failed(first_app_config, tmp_path):
     with pytest.raises(BriefcaseCommandError):
         command.run_app(first_app_config)
 
-    # The run command was still invoked, though
+    # Calls were made to start the app and to start a log stream.
+    bin_path = command.binary_path(first_app_config)
+    sender = bin_path / "Contents" / "MacOS" / "First App"
+    command.subprocess.Popen.assert_called_with(
+        [
+            'log', 'stream',
+            '--style', 'compact',
+            '--predicate',
+            f'senderImagePath=="{sender}"'
+            f' OR (processImagePath=="{sender}"'
+            ' AND senderImagePath=="/usr/lib/libffi.dylib")',
+        ],
+        stdout=subprocess.PIPE,
+        stderr=subprocess.STDOUT,
+        bufsize=1,
+    )
     command.subprocess.run.assert_called_with(
-        ['open', '-n', os.fsdecode(command.binary_path(first_app_config))],
+        ['open', '-n', os.fsdecode(bin_path)],
         check=True
     )
 
-
-def test_run_app_log_stream_failed(first_app_config, tmp_path):
-    "If the log can't be streamed, the app still starts"
-    command = macOSAppRunCommand(base_path=tmp_path)
-    command.subprocess = mock.MagicMock()
-    command.subprocess.run.side_effect = [
-        0,
-        subprocess.CalledProcessError(
-            cmd=['log', 'stream'],
-            returncode=1
-        )
-    ]
-
-    # The run command raises an error because the log stream couldn't start
-    with pytest.raises(BriefcaseCommandError):
-        command.run_app(first_app_config)
-
-    # Calls were made to start the app and to start a log stream.
-    bin_path = command.binary_path(first_app_config)
-    sender = bin_path / "Contents" / "MacOS" / "First App"
-    command.subprocess.run.assert_has_calls([
-        mock.call(
-            ['open', '-n', os.fsdecode(bin_path)],
-            check=True
-        ),
-        mock.call(
-            [
-                'log', 'stream',
-                '--style', 'compact',
-                '--predicate',
-                f'senderImagePath=="{sender}"'
-                f' OR (processImagePath=="{sender}"'
-                ' AND senderImagePath=="/usr/lib/libffi.dylib")',
-            ],
-            check=True,
-        )
-    ])
+    # No attempt was made to stream the log; but there was a cleanup
+    command.subprocess.stream_output.assert_not_called()
+    command.subprocess.cleanup.assert_called_with("log stream", log_stream_process)
diff --git a/tests/platforms/macOS/xcode/test_run.py b/tests/platforms/macOS/xcode/test_run.py
index 39401d14..570dc5eb 100644
--- a/tests/platforms/macOS/xcode/test_run.py
+++ b/tests/platforms/macOS/xcode/test_run.py
@@ -2,6 +2,7 @@
 # Run a basic test to ensure coverage, but fall back to
 # the app backend for exhaustive tests.
 import os
+import subprocess
 from unittest import mock
 
 from briefcase.platforms.macOS.xcode import macOSXcodeRunCommand
@@ -17,20 +18,20 @@ def test_run_app(first_app_config, tmp_path):
     # Calls were made to start the app and to start a log stream.
     bin_path = command.binary_path(first_app_config)
     sender = bin_path / "Contents" / "MacOS" / "First App"
-    command.subprocess.run.assert_has_calls([
-        mock.call(
-            ['open', '-n', os.fsdecode(bin_path)],
-            check=True
-        ),
-        mock.call(
-            [
-                'log', 'stream',
-                '--style', 'compact',
-                '--predicate',
-                f'senderImagePath=="{sender}"'
-                f' OR (processImagePath=="{sender}"'
-                ' AND senderImagePath=="/usr/lib/libffi.dylib")',
-            ],
-            check=True,
-        )
-    ])
+    command.subprocess.Popen.assert_called_with(
+        [
+            'log', 'stream',
+            '--style', 'compact',
+            '--predicate',
+            f'senderImagePath=="{sender}"'
+            f' OR (processImagePath=="{sender}"'
+            ' AND senderImagePath=="/usr/lib/libffi.dylib")',
+        ],
+        stdout=subprocess.PIPE,
+        stderr=subprocess.STDOUT,
+        bufsize=1,
+    )
+    command.subprocess.run.assert_called_with(
+        ['open', '-n', os.fsdecode(bin_path)],
+        check=True
+    )