gojuno / composer

Reactive Android Instrumentation Test Runner. Archived. Marathon is recommended as an alternative (https://github.com/Malinskiy/marathon).
Apache License 2.0
544 stars 45 forks source link

One test case is not executed and exclude from HTML report #121

Closed KyleLearnedThis closed 6 years ago

KyleLearnedThis commented 6 years ago

Environment:

It seems when I rand a suite that has 8 test cases, 1 test case gets dropped and not even included in the test result when running test in test sharding mode. (yes I know I am supposed to run the test on same type of phone, but this is proof of concept and I don' t have that many phones).

It also seems this is reproduced on one of Galaxy S7 6.0 phone repeatly.

[Wed Jan 17 13:47:47 PST 2018]: [7ccd6272] Successfully installed apk in 55 seconds, pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/worldFastProd/debug/CatanAndroid-world-fast-prod-debug.apk [Wed Jan 17 13:47:47 PST 2018]: [7ccd6272] Installing apk... pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/androidTest/worldFastProd/debug/CatanAndroid-world-fast-prod-debug-androidTest.apk [Wed Jan 17 13:47:59 PST 2018]: [7ccd6272] Successfully installed apk in 11 seconds, pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/androidTest/worldFastProd/debug/CatanAndroid-world-fast-prod-debug-androidTest.apk [Wed Jan 17 13:47:59 PST 2018]: [7ccd6272] Starting tests... [Wed Jan 17 13:48:03 PST 2018]: [7ccd6272] Test run finished, 0 passed, 0 failed, took 4 seconds.

KyleLearnedThis commented 6 years ago

catan2.log Log attached.

artem-zinnatullin commented 6 years ago

Posting log in case it gets lost:

[AndroidGenericSuite03-Composer-Run-Phone] $ /bin/bash -xe /var/folders/l7/wjqfy72x1p7dd2d11qt6s_6h0000gp/T/jenkins6616474549558900772.sh
+ java -Xms4096m -Xmx8912m -jar /Users/jenkins/labs/Composer/composer-0.2.9.jar --apk /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/worldFastProd/debug/CatanAndroid-world-fast-prod-debug.apk --test-apk /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/androidTest/worldFastProd/debug/CatanAndroid-world-fast-prod-debug-androidTest.apk --test-package com.catan.CatanMobile.test --test-runner android.support.test.runner.AndroidJUnitRunner --install-timeout 90 --output-directory /Users/jenkins/labs/Composer/composer-output --shard true --instrumentation-arguments class com.catan.CatanMobile.test.tests.cdt.MockedLoginTest --devices 01890c13 --devices 583e8f37 --devices 9887bc4153424e5647 --devices 7ccd6272 --devices 6ca05215 --devices 8379bbb0 --devices a778e7fa
[Wed Jan 17 13:46:52 PST 2018]: 7 connected adb device(s): [AdbDevice(id=01890c13, online=true), AdbDevice(id=583e8f37, online=true), AdbDevice(id=9887bc4153424e5647, online=true), AdbDevice(id=7ccd6272, online=true), AdbDevice(id=6ca05215, online=true), AdbDevice(id=8379bbb0, online=true), AdbDevice(id=a778e7fa, online=true)]
[Wed Jan 17 13:46:52 PST 2018]: [7ccd6272] Installing apk... pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/worldFastProd/debug/CatanAndroid-world-fast-prod-debug.apk
[Wed Jan 17 13:46:52 PST 2018]: [8379bbb0] Installing apk... pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/worldFastProd/debug/CatanAndroid-world-fast-prod-debug.apk
[Wed Jan 17 13:46:52 PST 2018]: [a778e7fa] Installing apk... pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/worldFastProd/debug/CatanAndroid-world-fast-prod-debug.apk
[Wed Jan 17 13:46:52 PST 2018]: [9887bc4153424e5647] Installing apk... pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/worldFastProd/debug/CatanAndroid-world-fast-prod-debug.apk
[Wed Jan 17 13:46:52 PST 2018]: [583e8f37] Installing apk... pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/worldFastProd/debug/CatanAndroid-world-fast-prod-debug.apk
[Wed Jan 17 13:46:52 PST 2018]: [01890c13] Installing apk... pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/worldFastProd/debug/CatanAndroid-world-fast-prod-debug.apk
[Wed Jan 17 13:46:52 PST 2018]: [6ca05215] Installing apk... pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/worldFastProd/debug/CatanAndroid-world-fast-prod-debug.apk
[Wed Jan 17 13:47:11 PST 2018]: [a778e7fa] Successfully installed apk in 18 seconds, pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/worldFastProd/debug/CatanAndroid-world-fast-prod-debug.apk
[Wed Jan 17 13:47:11 PST 2018]: [a778e7fa] Installing apk... pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/androidTest/worldFastProd/debug/CatanAndroid-world-fast-prod-debug-androidTest.apk
[Wed Jan 17 13:47:11 PST 2018]: [583e8f37] Successfully installed apk in 18 seconds, pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/worldFastProd/debug/CatanAndroid-world-fast-prod-debug.apk
[Wed Jan 17 13:47:11 PST 2018]: [583e8f37] Installing apk... pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/androidTest/worldFastProd/debug/CatanAndroid-world-fast-prod-debug-androidTest.apk
[Wed Jan 17 13:47:12 PST 2018]: [8379bbb0] Successfully installed apk in 19 seconds, pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/worldFastProd/debug/CatanAndroid-world-fast-prod-debug.apk
[Wed Jan 17 13:47:12 PST 2018]: [8379bbb0] Installing apk... pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/androidTest/worldFastProd/debug/CatanAndroid-world-fast-prod-debug-androidTest.apk
[Wed Jan 17 13:47:12 PST 2018]: [01890c13] Successfully installed apk in 19 seconds, pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/worldFastProd/debug/CatanAndroid-world-fast-prod-debug.apk
[Wed Jan 17 13:47:12 PST 2018]: [01890c13] Installing apk... pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/androidTest/worldFastProd/debug/CatanAndroid-world-fast-prod-debug-androidTest.apk
[Wed Jan 17 13:47:13 PST 2018]: [6ca05215] Successfully installed apk in 20 seconds, pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/worldFastProd/debug/CatanAndroid-world-fast-prod-debug.apk
[Wed Jan 17 13:47:13 PST 2018]: [6ca05215] Installing apk... pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/androidTest/worldFastProd/debug/CatanAndroid-world-fast-prod-debug-androidTest.apk
[Wed Jan 17 13:47:16 PST 2018]: [a778e7fa] Successfully installed apk in 4 seconds, pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/androidTest/worldFastProd/debug/CatanAndroid-world-fast-prod-debug-androidTest.apk
[Wed Jan 17 13:47:16 PST 2018]: [a778e7fa] Starting tests...
[Wed Jan 17 13:47:16 PST 2018]: [583e8f37] Successfully installed apk in 4 seconds, pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/androidTest/worldFastProd/debug/CatanAndroid-world-fast-prod-debug-androidTest.apk
[Wed Jan 17 13:47:16 PST 2018]: [583e8f37] Starting tests...
[Wed Jan 17 13:47:17 PST 2018]: [01890c13] Successfully installed apk in 4 seconds, pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/androidTest/worldFastProd/debug/CatanAndroid-world-fast-prod-debug-androidTest.apk
[Wed Jan 17 13:47:17 PST 2018]: [01890c13] Starting tests...
[Wed Jan 17 13:47:17 PST 2018]: [8379bbb0] Successfully installed apk in 4 seconds, pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/androidTest/worldFastProd/debug/CatanAndroid-world-fast-prod-debug-androidTest.apk
[Wed Jan 17 13:47:17 PST 2018]: [8379bbb0] Starting tests...
[Wed Jan 17 13:47:18 PST 2018]: [6ca05215] Successfully installed apk in 4 seconds, pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/androidTest/worldFastProd/debug/CatanAndroid-world-fast-prod-debug-androidTest.apk
[Wed Jan 17 13:47:18 PST 2018]: [6ca05215] Starting tests...
[Wed Jan 17 13:47:19 PST 2018]: [9887bc4153424e5647] Successfully installed apk in 26 seconds, pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/worldFastProd/debug/CatanAndroid-world-fast-prod-debug.apk
[Wed Jan 17 13:47:19 PST 2018]: [9887bc4153424e5647] Installing apk... pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/androidTest/worldFastProd/debug/CatanAndroid-world-fast-prod-debug-androidTest.apk
[Wed Jan 17 13:47:21 PST 2018]: [01890c13] Test run finished, 0 passed, 0 failed, took 4 seconds.
[Wed Jan 17 13:47:21 PST 2018]: [8379bbb0] Test run finished, 0 passed, 0 failed, took 4 seconds.
[Wed Jan 17 13:47:22 PST 2018]: [a778e7fa] Test 1/1 passed in 2 seconds: com.catan.CatanMobile.test.tests.cdt.MockedLoginTest.testInvalidEmailLogin
[Wed Jan 17 13:47:22 PST 2018]: [a778e7fa] Test run finished, 1 passed, 0 failed, took 6 seconds.
[Wed Jan 17 13:47:22 PST 2018]: [583e8f37] Test 1/2 passed in 2 seconds: com.catan.CatanMobile.test.tests.cdt.MockedLoginTest.testEmptyLogin
[Wed Jan 17 13:47:23 PST 2018]: [583e8f37] Test 2/2 passed in 1 second: com.catan.CatanMobile.test.tests.cdt.MockedLoginTest.testLoginLogout
[Wed Jan 17 13:47:23 PST 2018]: [583e8f37] Test run finished, 2 passed, 0 failed, took 7 seconds.
[Wed Jan 17 13:47:23 PST 2018]: [9887bc4153424e5647] Successfully installed apk in 4 seconds, pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/androidTest/worldFastProd/debug/CatanAndroid-world-fast-prod-debug-androidTest.apk
[Wed Jan 17 13:47:23 PST 2018]: [9887bc4153424e5647] Starting tests...
[Wed Jan 17 13:47:24 PST 2018]: [6ca05215] Test 1/2 passed in 2 seconds: com.catan.CatanMobile.test.tests.cdt.MockedLoginTest.testEmptyEmailLogin
[Wed Jan 17 13:47:25 PST 2018]: [6ca05215] Test 2/2 passed in 1 second: com.catan.CatanMobile.test.tests.cdt.MockedLoginTest.testNewTopLevelDomainLogin
[Wed Jan 17 13:47:26 PST 2018]: [6ca05215] Test run finished, 2 passed, 0 failed, took 8 seconds.
[Wed Jan 17 13:47:27 PST 2018]: [9887bc4153424e5647] Test 1/2 passed in 2 seconds: com.catan.CatanMobile.test.tests.cdt.MockedLoginTest.testForgotPasswordLogin
[Wed Jan 17 13:47:28 PST 2018]: [9887bc4153424e5647] Test 2/2 passed in 1 second: com.catan.CatanMobile.test.tests.cdt.MockedLoginTest.testWrongPasswordLogin
[Wed Jan 17 13:47:29 PST 2018]: [9887bc4153424e5647] Test run finished, 2 passed, 0 failed, took 6 seconds.
[Wed Jan 17 13:47:47 PST 2018]: [7ccd6272] Successfully installed apk in 55 seconds, pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/worldFastProd/debug/CatanAndroid-world-fast-prod-debug.apk
[Wed Jan 17 13:47:47 PST 2018]: [7ccd6272] Installing apk... pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/androidTest/worldFastProd/debug/CatanAndroid-world-fast-prod-debug-androidTest.apk
[Wed Jan 17 13:47:59 PST 2018]: [7ccd6272] Successfully installed apk in 11 seconds, pathToApk = /Users/jenkins/catanandroid/CatanAndroid/build/outputs/apk/androidTest/worldFastProd/debug/CatanAndroid-world-fast-prod-debug-androidTest.apk
[Wed Jan 17 13:47:59 PST 2018]: [7ccd6272] Starting tests...
[Wed Jan 17 13:48:03 PST 2018]: [7ccd6272] Test run finished, 0 passed, 0 failed, took 4 seconds.
[Wed Jan 17 13:48:03 PST 2018]: Generating HTML report...
[Wed Jan 17 13:48:03 PST 2018]: HTML report generated, took 0 seconds.
[Wed Jan 17 13:48:03 PST 2018]: Test run finished, total passed = 7, total failed = 0, total ignored = 0, took 1 minute 11 seconds.
[htmlpublisher] Archiving HTML reports...
[htmlpublisher] Archiving at PROJECT level /Users/jenkins/labs/Composer/composer-output/html-report to /var/lib/jenkins/jobs/Firmware-Automation/jobs/AndroidGenericSuite03-Composer-Run-Phone/htmlreports/HTML_Report
Finished: SUCCESS
artem-zinnatullin commented 6 years ago

Interesting, I know my question will look silly, but are you sure there are 8 tests you're trying to run?

According to log (which is very helpful, thanks for attaching it!) you're specifying test class:

--instrumentation-arguments class com.catan.CatanMobile.test.tests.cdt.MockedLoginTest

Maybe this class only contains 7 tests?

The fact that some devices/emulators gets to execute 0 tests is expected corner case in sharding mode because sharding is static and doesn't know upfront how many tests are there.

KyleLearnedThis commented 6 years ago

@artem-zinnatullin, yeah, I've been using same suite to develop test sharding, it really has 8 test cases in total. So I found out more about this, it seems this only happens repeatedly on 1 particular phone, a Galaxy S7 6.0.1. I examined the phone seemed to be in good state.

7ccd6272 device usb:4681728X product:heroqlteuc model:SAMSUNG_SM_G930A device:heroqlteatt transport_id:4

artem-zinnatullin commented 6 years ago

Can you try to run tests on this particular phone without others connected?

KyleLearnedThis commented 6 years ago

I ran this locally on that problematic phone, I am getting the same result that it skips all tests in the suite. I am still looking at what is different about this phone itself.

Log attached.

Is there a verbose logging mode?

KyleLearnedThis commented 6 years ago

catan03.log

yunikkk commented 6 years ago

@KyleLearnedThis its --verbose-output true

KyleLearnedThis commented 6 years ago

I think I found out why, there is a NullPointerException on from one of the java classes, but because it doesn't actually know how to handle NPE, it decided to skip all test cases. But this is only happened on a 6.0.1 Verizon Galaxy S7.

[instrumentation.output] INSTRUMENTATION_STATUS: numtests=8 INSTRUMENTATION_STATUS: stream= com.Catan.CatanMobile.test.tests.cdt.MockedLoginTest: INSTRUMENTATION_STATUS: id=AndroidJUnitRunner INSTRUMENTATION_STATUS: test=testEmptyEmailLogin INSTRUMENTATION_STATUS: class=com.Catan.CatanMobile.test.tests.cdt.MockedLoginTest INSTRUMENTATION_STATUS: current=1 INSTRUMENTATION_STATUS_CODE: 1 INSTRUMENTATION_RESULT: shortMsg=java.lang.NullPointerException INSTRUMENTATION_RESULT: longMsg=java.lang.NullPointerException: Attempt to invoke virtual method 'void java.util.logging.Logger.log(java.util.logging.Level, java.lang.String, java.lang.Throwable)' on a null object reference INSTRUMENTATION_CODE: 0

[excerpt from full.logcat] 02-06 16:17:48.769 16437 16613 I Timeline: Timeline: Activity_launch_request id:com.Catan.betabit.CatanMobile time:1842034 02-06 16:17:48.769 16437 16611 E FBExceptionLogger: FATAL EXCEPTION: NullPointerException 02-06 16:17:48.769 16437 16611 E FBExceptionLogger: java.lang.NullPointerException: Attempt to invoke virtual method 'void java.util.logging.Logger.log(java.util.logging.Level, java.lang.String, java.lang.Throwable)' on a null object reference 02-06 16:17:48.769 16437 16611 E FBExceptionLogger: at okhttp3.mockwebserver.MockWebServer$2.execute(MockWebServer.java:326) 02-06 16:17:48.769 16437 16611 E FBExceptionLogger: at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32) 02-06 16:17:48.769 16437 16611 E FBExceptionLogger: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113) 02-06 16:17:48.769 16437 16611 E FBExceptionLogger: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588) 02-06 16:17:48.769 16437 16611 E FBExceptionLogger: at java.lang.Thread.run(Thread.java:818) 02-06 16:17:48.769 1459 2593 V BroadcastQueue: [background] Process cur broadcast BroadcastRecord{629c493 u0 android.intent.action.PACKAGE_ADDED qIdx=4}, state= (APP_RECEIVE) DELIVERED for app ProcessRecord{9693c3d 6649:com.google.android.gms/u0a23} 02-06 16:17:48.769 16437 16611 E AndroidRuntime: FATAL EXCEPTION: MockWebServer 02-06 16:17:48.769 16437 16611 E AndroidRuntime: Process: com.Catan.betabit.CatanMobile, PID: 16437 02-06 16:17:48.769 16437 16611 E AndroidRuntime: java.lang.NullPointerException: Attempt to invoke virtual method 'void java.util.logging.Logger.log(java.util.logging.Level, java.lang.String, java.lang.Throwable)' on a null object reference 02-06 16:17:48.769 16437 16611 E AndroidRuntime: at okhttp3.mockwebserver.MockWebServer$2.execute(MockWebServer.java:326) 02-06 16:17:48.769 16437 16611 E AndroidRuntime: at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32) 02-06 16:17:48.769 16437 16611 E AndroidRuntime: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113) 02-06 16:17:48.769 16437 16611 E AndroidRuntime: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588) 02-06 16:17:48.769 16437 16611 E AndroidRuntime: at java.lang.Thread.run(Thread.java:818)

So the real issue is the Composer should know how to handle errors and report accordingly. @yunikkk @artem-zinnatullin

artem-zinnatullin commented 6 years ago

We of course handle errors happened during test execution, but since there is no official documentation on Instrumentation output format or status codes we basically had to "reverse engineer" it even though it's open source.

Here is how we handle it https://github.com/gojuno/composer/blob/6e039dfe1eab18e6e97161510f6d4038ae2b896a/composer/src/main/kotlin/com/gojuno/composer/Instrumentation.kt#L26-L32

I see 2 options, they are non-exclusive btw:

1) It's a bug on our side if we don't expect some sequence of instrumentation codes.

INSTRUMENTATION_STATUS_CODE: 1 
INSTRUMENTATION_RESULT: shortMsg=java.lang.NullPointerException INSTRUMENTATION_RESULT: longMsg=java.lang.NullPointerException: Attempt to invoke virtual method 'void java.util.logging.Logger.log(java.util.logging.Level, java.lang.String, java.lang.Throwable)' on a null object reference 
INSTRUMENTATION_CODE: 0

Most likely we should detect that if initial INSTRUMENTATION_STATUS_CODE: 1 was reported (test started) but no according test finished code appeared before INSTRUMENTATION_CODE: 0/etc we should mark test as failed.

2) It's a bug on Samsung side and they don't report when test fails and just finish whole test run. We definitely have seen test failed right from start and Composer reports that as error in our cases.


I believe both options take place here and we should fix it on our side, of course Samsung doesn't give a sht about such problems so I wouldn't expect any action from them.

@yunikkk what do you think?

Thanks for attaching instrumentation output, it's very helpful!

yunikkk commented 6 years ago

Hey, I believe we should handle this on our side, for sure.

artem-zinnatullin commented 6 years ago

@yunikkk do you have bandwidth to fix it?

Most likely we need to move this takeWhile after scan and report failure if we get INSTRUMENTATION_CODE in scan and previousResult.readyForProcessing == false

https://github.com/gojuno/composer/blob/6e039dfe1eab18e6e97161510f6d4038ae2b896a/composer/src/main/kotlin/com/gojuno/composer/Instrumentation.kt#L112

yunikkk commented 6 years ago

I hope so, handled personal stuff a little bit.

On Feb 20, 2018, 8:14 PM +0300, Artem Zinnatullin :slowpoke: notifications@github.com, wrote:

@yunikkk do you have bandwidth to fix it? Most likely we need to move this takeWhile after scan and report failure if we get INSTRUMENTATION_CODE in scan and previousResult.readyForProcessing == false https://github.com/gojuno/composer/blob/6e039dfe1eab18e6e97161510f6d4038ae2b896a/composer/src/main/kotlin/com/gojuno/composer/Instrumentation.kt#L112 — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.