Android crash logs are hidden if phone and computer times aren't in sync

[freakboy3742]

Describe the bug

If an Android app is well behaved, Briefcase will start the app, detect the PID of the running app, then display the logs for that PID.

If an app crashes on startup, there may not be enough time for Briefcase to detect the PID; in this case, Briefcase moves into a fallback mode, and prints the last 10 seconds of logs from any PID, with a filter that captures important Toga/Chaquopy log sections.

Briefcase establishes this "10 second" window by using the local system time. However, this timestamp is passed to adb as a log filter (-t), and it is the phone's clock that is used to evaluate the log filter.

So - if the computer and the phone disagree on the current time, it is possible for the app logs to appear empty, even though there are plenty of logs - just outside the "10 second" window.

Steps to reproduce

1. Generate a "hello world" app
2. Put raise Exception() at the top of app.py
3. Deliberately change your computer's clock so that it is 1 minute faster than your phone
4. Run the app on Android.

It may be necessary to use a physical phone; an emulator will be using the host system clock.

Expected behavior

Logs for the crash should be generated in Briefcase.

Screenshots

No response

Environment

• Operating System: Any
• Python version: Any
• Software versions:
  • Briefcase: 0.3.13+

Logs

Additional context

One fix is to use the phone's perception of time to establish the start of the logging window. We currently use datetime.now() to get the start time prior to launching the app; we could instead use adb shell date, and parse the result. This would ensure that the time filter passed to adb logcat will be using a common reference time.

[mhsmith]

This is now happening to me every single time an app crashes on startup, even when the emulator and computer clocks are in sync. I wonder if it's because the adb logcat command expects UTC and Briefcase is sending it a time in my local timezone of UTC+1, or vice versa.

[freakboy3742]

Sounds like the fix in your case is to abolish daylight saving time. :-)

Definitely an observation that accelerates the importance of the issue, though.

[rmartin16]

I can probably fix this today.

As best I can tell, all of this is timezone unaware and logcat is performing a naive filter on the date/time provided against the device's date/time. (Although, I guess that doesn't preclude datetime.now() providing a different date/time than the device even if the host is "in sync" with it...)

Nonetheless, it does seem that Briefcase needs the phone's understanding of the current date/time to mitigate any differences in opinion that the host machine may have about the time.

So, it should be trivial to capture the device's date/time at the start and use that in the fallback logging method. Not having much experience with adb, I think I'm concerned about the consistency of Android's date command over time....given parsing will be necessary of the output. I think using date +%s (to get seconds since epoch) will be best to simplify this parsing. Any initial feedback appreciated but PR inbound.

[edit] Also, it looks like $EPOCHREALTIME is a thing on Android.