Unit test for setTimeout is failing intermittently on Android CI

[bghgary]

The should call the given functions in the correct order test sometimes fails on Android on CI. No other setTimeout tests are failing. Never seen this test fail locally or other platforms either.

Raw log from the CI:

2023-02-16T21:43:38.9335290Z ##[section]Starting: Dump logcat from Test Results
2023-02-16T21:43:38.9347900Z ==============================================================================
2023-02-16T21:43:38.9348570Z Task         : Command line
2023-02-16T21:43:38.9348980Z Description  : Run a command line script using Bash on Linux and macOS and cmd.exe on Windows
2023-02-16T21:43:38.9349570Z Version      : 2.212.0
2023-02-16T21:43:38.9350110Z Author       : Microsoft Corporation
2023-02-16T21:43:38.9350420Z Help         : https://docs.microsoft.com/azure/devops/pipelines/tasks/utility/command-line
2023-02-16T21:43:38.9350820Z ==============================================================================
2023-02-16T21:43:39.2302390Z Generating script.
2023-02-16T21:43:39.2324190Z ========================== Starting Command Output ===========================
2023-02-16T21:43:39.2364560Z [command]/bin/bash --noprofile --norc /Users/runner/work/_temp/8a7a4a30-3378-498d-86f3-55d1e932ead6.sh
2023-02-16T21:43:39.2996660Z cat ./app/build/outputs/androidTest-results/connected/Pixel_API_27(AVD) - 8.1.0/logcat-com.jsruntimehost.unittests.Main-javaScriptTests.txt
2023-02-16T21:43:39.3094560Z 02-16 21:43:28.283  3170  3186 I TestRunner: started: javaScriptTests(com.jsruntimehost.unittests.Main)
2023-02-16T21:43:39.3098240Z 02-16 21:43:28.288  1830  1849 W zygote64: kill(-2693, 9) failed: No such process
2023-02-16T21:43:39.3099290Z 02-16 21:43:28.311  3170  3186 D JavaScriptCore.Version: 250230.2.1
2023-02-16T21:43:39.3100350Z 02-16 21:43:28.338  1830  1849 W zygote64: kill(-2693, 9) failed: No such process
2023-02-16T21:43:39.3102700Z 02-16 21:43:28.338  1830  1849 I zygote64: Successfully killed process cgroup uid 10055 pid 2693 in 98ms
2023-02-16T21:43:39.3104410Z 02-16 21:43:28.474  1397  1427 D         : HostConnection::get() New Host Connection established 0x72e773c2c180, tid 1427
2023-02-16T21:43:39.3105670Z 02-16 21:43:28.669  3170  3199 D NetworkSecurityConfig: No Network Security Config specified, using platform default
2023-02-16T21:43:39.3106900Z 02-16 21:43:28.879  3170  3175 I zygote64: Do partial code cache collection, code=29KB, data=21KB
2023-02-16T21:43:39.3108100Z 02-16 21:43:28.883  3170  3175 I zygote64: After code cache collection, code=29KB, data=21KB
2023-02-16T21:43:39.3109910Z 02-16 21:43:28.883  3170  3175 I zygote64: Increasing code cache capacity to 128KB
2023-02-16T21:43:39.3111180Z 02-16 21:43:28.992  3170  3190 I JsRuntimeHost: Passed: XMLHTTPRequest should have readyState=4 when load ends
2023-02-16T21:43:39.3112410Z 02-16 21:43:29.081  3170  3190 I JsRuntimeHost: Passed: XMLHTTPRequest should have status=200 for a file that exists
2023-02-16T21:43:39.3113590Z 02-16 21:43:29.387  3170  3190 I JsRuntimeHost: Passed: XMLHTTPRequest should load URLs with escaped unicode characters
2023-02-16T21:43:39.3115260Z 02-16 21:43:29.417  3170  3190 I JsRuntimeHost: Passed: XMLHTTPRequest should load URLs with unescaped unicode characters
2023-02-16T21:43:39.3116950Z 02-16 21:43:29.437  3170  3190 I JsRuntimeHost: Passed: XMLHTTPRequest should load URLs with unescaped unicode characters and spaces
2023-02-16T21:43:39.3118640Z 02-16 21:43:29.523  3170  3190 I JsRuntimeHost: Passed: XMLHTTPRequest should have status=404 for a file that does not exist
2023-02-16T21:43:39.3121140Z 02-16 21:43:29.527  3170  3190 I JsRuntimeHost: Passed: XMLHTTPRequest should throw something when opening //
2023-02-16T21:43:39.3123510Z 02-16 21:43:29.529  3170  3190 I JsRuntimeHost: Passed: XMLHTTPRequest should throw something when opening a url with no scheme
2023-02-16T21:43:39.3125700Z 02-16 21:43:29.530  3170  3190 I JsRuntimeHost: Passed: XMLHTTPRequest should throw something when sending before opening
2023-02-16T21:43:39.3127440Z 02-16 21:43:29.532  3170  3190 I JsRuntimeHost: Passed: setTimeout should return an id greater than zero
2023-02-16T21:43:39.3131050Z 02-16 21:43:29.533  3170  3190 I JsRuntimeHost: Passed: setTimeout should return an id greater than zero when given an undefined function
2023-02-16T21:43:39.3132740Z 02-16 21:43:29.547  3170  3190 I JsRuntimeHost: Passed: setTimeout should call the given function after the given delay
2023-02-16T21:43:39.3135050Z 02-16 21:43:29.591  3170  3190 I JsRuntimeHost: Passed: setTimeout should call the given nested function after the given delay
2023-02-16T21:43:39.3137750Z 02-16 21:43:29.606  3170  3190 I JsRuntimeHost: Passed: setTimeout should call the given function after the given delay when the delay is a string representing a valid number
2023-02-16T21:43:39.3140580Z 02-16 21:43:29.611  3170  3190 I JsRuntimeHost: Passed: setTimeout should call the given function after zero milliseconds when the delay is a string representing an invalid number
2023-02-16T21:43:39.3142190Z 02-16 21:43:29.615  3170  3190 I JsRuntimeHost: Passed: setTimeout should call the given function after other tasks execute when the given delay is zero
2023-02-16T21:43:39.3145340Z 02-16 21:43:29.620  3170  3190 I JsRuntimeHost: Passed: setTimeout should call the given function after other tasks execute when the given delay is undefined
2023-02-16T21:43:39.3147050Z 02-16 21:43:29.777  3210  3210 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdTombstone
2023-02-16T21:43:39.3149280Z 02-16 21:43:29.778  1710  1710 I /system/bin/tombstoned: received crash request for pid 3170
2023-02-16T21:43:39.3150500Z 02-16 21:43:29.778  3210  3210 I crash_dump64: performing dump of process 3170 (target tid = 3195)
2023-02-16T21:43:39.3152810Z 02-16 21:43:30.207  1710  1710 E /system/bin/tombstoned: Tombstone written to: /data/tombstones/tombstone_00
2023-02-16T21:43:39.3153930Z 02-16 21:43:30.277  1686  1686 I Zygote  : Process 3170 exited due to signal (6)
2023-02-16T21:43:39.3156480Z 02-16 21:43:30.289  1830  3217 W Binder  : Outgoing transactions from this process must be FLAG_ONEWAY
2023-02-16T21:43:39.3157650Z 02-16 21:43:30.289  1830  3217 W Binder  : java.lang.Throwable
2023-02-16T21:43:39.3159110Z 02-16 21:43:30.289  1830  3217 W Binder  : 	at android.os.BinderProxy.transact(Binder.java:752)
2023-02-16T21:43:39.3162010Z 02-16 21:43:30.289  1830  3217 W Binder  : 	at android.app.IInstrumentationWatcher$Stub$Proxy.instrumentationFinished(IInstrumentationWatcher.java:160)
2023-02-16T21:43:39.3165880Z 02-16 21:43:30.289  1830  3217 W Binder  : 	at com.android.server.am.InstrumentationReporter$MyThread.run(InstrumentationReporter.java:86)
2023-02-16T21:43:39.3168170Z 02-16 21:43:30.289  1830  1849 W zygote64: kill(-3170, 9) failed: No such process
2023-02-16T21:43:39.3169640Z 02-16 21:43:30.289  3161  3161 D AndroidRuntime: Shutting down VM
2023-02-16T21:43:39.3170690Z 02-16 21:43:30.290  1830  1849 I zygote64: Successfully killed process cgroup uid 10060 pid 3170 in 6ms
2023-02-16T21:43:39.3171880Z 02-16 21:43:30.745  3226  3226 D AndroidRuntime: >>>>>> START com.android.internal.os.RuntimeInit uid 2000 <<<<<<
2023-02-16T21:43:39.3173740Z 02-16 21:43:30.802  3226  3226 W app_process: Unexpected CPU variant for X86 using defaults: x86_64
2023-02-16T21:43:39.3175060Z 02-16 21:43:30.804  3226  3226 I app_process: The ClassLoaderContext is a special shared library.
2023-02-16T21:43:39.3177350Z 02-16 21:43:30.840  3226  3226 D AndroidRuntime: Calling main entry com.android.commands.pm.Pm
2023-02-16T21:43:39.3178590Z 02-16 21:43:30.854  3226  3234 W MessageQueue: Handler (android.os.Handler) {d92c569} sending message to a Handler on a dead thread
2023-02-16T21:43:39.3180090Z 02-16 21:43:30.854  3226  3234 W MessageQueue: java.lang.IllegalStateException: Handler (android.os.Handler) {d92c569} sending message to a Handler on a dead thread
2023-02-16T21:43:39.3181530Z 02-16 21:43:30.854  3226  3234 W MessageQueue: 	at android.os.MessageQueue.enqueueMessage(MessageQueue.java:545)
2023-02-16T21:43:39.3182850Z 02-16 21:43:30.854  3226  3234 W MessageQueue: 	at android.os.Handler.enqueueMessage(Handler.java:662)
2023-02-16T21:43:39.3184130Z 02-16 21:43:30.854  3226  3234 W MessageQueue: 	at android.os.Handler.sendMessageAtTime(Handler.java:631)
2023-02-16T21:43:39.3185760Z 02-16 21:43:30.854  3226  3234 W MessageQueue: 	at android.os.Handler.sendMessageDelayed(Handler.java:601)
2023-02-16T21:43:39.3187600Z 02-16 21:43:30.854  3226  3234 W MessageQueue: 	at android.os.Handler.post(Handler.java:357)
2023-02-16T21:43:39.3188840Z 02-16 21:43:30.854  3226  3234 W MessageQueue: 	at android.os.ResultReceiver$MyResultReceiver.send(ResultReceiver.java:57)
2023-02-16T21:43:39.3190780Z 02-16 21:43:30.854  3226  3234 W MessageQueue: 	at com.android.internal.os.IResultReceiver$Stub.onTransact(IResultReceiver.java:58)
2023-02-16T21:43:39.3192300Z 02-16 21:43:30.854  3226  3234 W MessageQueue: 	at android.os.Binder.execTransact(Binder.java:697)
2023-02-16T21:43:39.3193500Z 02-16 21:43:30.856  3226  3226 I app_process: System.exit called, status: 0
2023-02-16T21:43:39.3194520Z 02-16 21:43:30.856  3226  3226 I AndroidRuntime: VM exiting with result code 0.
2023-02-16T21:43:39.3213420Z ##[section]Finishing: Dump logcat from Test Results

[bghgary]

It seems there is an intermittent crash even without this test, so perhaps the test is unrelated.

cat ./app/build/outputs/androidTest-results/connected/Pixel_API_27(AVD) - 8.1.0/logcat-com.jsruntimehost.unittests.Main-javaScriptTests.txt
03-09 00:16:40.825  3123  3138 I TestRunner: started: javaScriptTests(com.jsruntimehost.unittests.Main)
03-09 00:16:40.838  3123  3138 D JavaScriptCore.Version: 250230.2.1
03-09 00:16:41.137  3123  3140 I JsRuntimeHost: Passed: AbortController should not throw while aborting and correctly trigger callback
03-09 00:16:41.156  3123  3149 D NetworkSecurityConfig: No Network Security Config specified, using platform default
03-09 00:16:41.243  3123  3128 I zygote64: Do partial code cache collection, code=29KB, data=21KB
03-09 00:16:41.246  3123  3128 I zygote64: After code cache collection, code=29KB, data=21KB
03-09 00:16:41.247  3123  3128 I zygote64: Increasing code cache capacity to 128KB
03-09 00:16:41.289  3123  3140 I JsRuntimeHost: Passed: XMLHTTPRequest should have readyState=4 when load ends
03-09 00:16:41.319  3156  3156 I crash_dump64: obtaining output fd from tombstoned, type: kDebuggerdTombstone
03-09 00:16:41.320  1674  1674 I /system/bin/tombstoned: received crash request for pid 3123
03-09 00:16:41.321  3156  3156 I crash_dump64: performing dump of process 3123 (target tid = 3145)
03-09 00:16:41.818  1674  1674 E /system/bin/tombstoned: Tombstone written to: /data/tombstones/tombstone_00
03-09 00:16:41.854  1645  1645 I Zygote  : Process 3123 exited due to signal (6)
03-09 00:16:41.855  1785  1802 W zygote64: kill(-3123, 9) failed: No such process
03-09 00:16:41.855  1785  1802 I zygote64: Successfully killed process cgroup uid 10060 pid 3123 in 0ms
03-09 00:16:41.865  1785  3163 W Binder  : Outgoing transactions from this process must be FLAG_ONEWAY
03-09 00:16:41.865  1785  3163 W Binder  : java.lang.Throwable
03-09 00:16:41.865  1785  3163 W Binder  : 	at android.os.BinderProxy.transact(Binder.java:752)
03-09 00:16:41.865  1785  3163 W Binder  : 	at android.app.IInstrumentationWatcher$Stub$Proxy.instrumentationFinished(IInstrumentationWatcher.java:160)
03-09 00:16:41.865  1785  3163 W Binder  : 	at com.android.server.am.InstrumentationReporter$MyThread.run(InstrumentationReporter.java:86)
03-09 00:16:41.866  3114  3114 D AndroidRuntime: Shutting down VM
03-09 00:16:42.064  3166  3166 D AndroidRuntime: >>>>>> START com.android.internal.os.RuntimeInit uid 2000 <<<<<<
03-09 00:16:42.118  3166  3166 W app_process: Unexpected CPU variant for X86 using defaults: x86_64
03-09 00:16:42.121  3166  3166 I app_process: The ClassLoaderContext is a special shared library.
03-09 00:16:42.148  3166  3166 D AndroidRuntime: Calling main entry com.android.commands.pm.Pm
03-09 00:16:42.154  3166  3174 W MessageQueue: Handler (android.os.Handler) {f679d91} sending message to a Handler on a dead thread
03-09 00:16:42.154  3166  3174 W MessageQueue: java.lang.IllegalStateException: Handler (android.os.Handler) {f679d91} sending message to a Handler on a dead thread
03-09 00:16:42.154  3166  3174 W MessageQueue: 	at android.os.MessageQueue.enqueueMessage(MessageQueue.java:545)
03-09 00:16:42.154  3166  3174 W MessageQueue: 	at android.os.Handler.enqueueMessage(Handler.java:662)
03-09 00:16:42.154  3166  3174 W MessageQueue: 	at android.os.Handler.sendMessageAtTime(Handler.java:631)
03-09 00:16:42.154  3166  3174 W MessageQueue: 	at android.os.Handler.sendMessageDelayed(Handler.java:601)
03-09 00:16:42.154  3166  3174 W MessageQueue: 	at android.os.Handler.post(Handler.java:357)
03-09 00:16:42.154  3166  3174 W MessageQueue: 	at android.os.ResultReceiver$MyResultReceiver.send(ResultReceiver.java:57)
03-09 00:16:42.154  3166  3174 W MessageQueue: 	at com.android.internal.os.IResultReceiver$Stub.onTransact(IResultReceiver.java:58)
03-09 00:16:42.154  3166  3174 W MessageQueue: 	at android.os.Binder.execTransact(Binder.java:697)
03-09 00:16:42.155  3166  3166 I app_process: System.exit called, status: 0
03-09 00:16:42.155  3166  3166 I AndroidRuntime: VM exiting with result code 0.