search

appium / appium-flutter-driver

Appium Flutter Driver is a test automation tool for Flutter apps on multiple platforms/OSes. Appium Flutter Driver is part of the Appium mobile test automation tool maintained by community
MIT License
454 stars 182 forks source link

Appium flutter driver hangs without response when executing click command #557

Open TripleG opened 1 year ago

TripleG commented 1 year ago

I have a very simple experimental test for Flutter driver. I just want to try to click an element in a flutter app. I am using https://github.com/ashwithpoojary98/javaflutterfinder as Java client for flutter elements:

public class ExampleTests {
    private AppiumDriver driver;

    final String pathToApp = "C:\\Users\\gg.georgiev\\Desktop\\georgi-tests\\src\\test\\resources\\app-debug.apk";

    @BeforeMethod
    public void openApp() throws MalformedURLException {
        var IP = "127.0.0.1";
        var PORT = "3000";
        DesiredCapabilities capabilities = new DesiredCapabilities();
        capabilities.setCapability("platformName", "Android");
        capabilities.setCapability("app", pathToApp);
        capabilities.setCapability("automationName", "Flutter");
        capabilities.setCapability("platformVersion", "13");
        capabilities.setCapability("newCommandTimeout", 20);

        driver = new AppiumDriver(new URL("http://%s:%s".formatted(IP, PORT)), capabilities);
    }

    @Test
    public void appiumFlutterTest() throws InterruptedException {
        Thread.sleep(15000); //I know it's bad, it's just for debugging purposes

        FlutterFinder finder = new FlutterFinder(driver);
        driver.executeScript("flutter:setFrameSync", false, 3500);
        finder.byValueKey("loginButtonKey").click();
    }

    @AfterMethod(alwaysRun = true)
    public void tearDown() {
        if (driver != null) {
            driver.quit();
        }
    }
}

I am running the test on a physical device. The application is started successfully, but the click() command hangs without any response and I wait 600 seconds until the HTTP client throws timeout exception:

906  [AsyncHttpClient-1-2] DEBUG org.asynchttpclient.netty.channel.NettyConnectListener  - Using new Channel '[id: 0x66d2e821, L:/127.0.0.1:53111 - R:/127.0.0.1:3000]' for 'POST' to '/session'
914  [AsyncHttpClient-1-2] DEBUG io.netty.util.Recycler  - -Dio.netty.recycler.maxCapacityPerThread: 4096
914  [AsyncHttpClient-1-2] DEBUG io.netty.util.Recycler  - -Dio.netty.recycler.ratio: 8
914  [AsyncHttpClient-1-2] DEBUG io.netty.util.Recycler  - -Dio.netty.recycler.chunkSize: 32
914  [AsyncHttpClient-1-2] DEBUG io.netty.util.Recycler  - -Dio.netty.recycler.blocking: false
915  [AsyncHttpClient-1-2] DEBUG io.netty.util.Recycler  - -Dio.netty.recycler.batchFastThreadLocalOnly: true
13261 [AsyncHttpClient-1-2] DEBUG io.netty.handler.codec.compression.Brotli  - brotli4j not in the classpath; Brotli support will be unavailable.
13262 [AsyncHttpClient-1-2] DEBUG org.asynchttpclient.netty.handler.HttpHandler  - 

Request DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST /session HTTP/1.1
X-Idempotency-Key: 061a0c06-4ccb-4c09-886e-fd9d5538ac8c
User-Agent: appium/8.5.1 (selenium/4.12.1 (java windows))
Content-Length: 401
Content-Type: application/json; charset=utf-8
host: 127.0.0.1:3000
accept: */*

Response DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200 OK
X-Powered-By: Express
Vary: X-HTTP-Method-Override
Content-Type: application/json; charset=utf-8
Content-Length: 813
ETag: W/"32d-zStLd0bmBlqUUFkMNMPTd4UxicY"
Date: Wed, 06 Sep 2023 17:26:09 GMT
Connection: keep-alive
Keep-Alive: timeout=30

13266 [AsyncHttpClient-1-2] DEBUG org.asynchttpclient.netty.channel.ChannelManager  - Adding key: http://127.0.0.1:3000 for channel [id: 0x66d2e821, L:/127.0.0.1:53111 - R:/127.0.0.1:3000]
13742 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.netty.channel.DefaultChannelPool  - Entry count for : http://127.0.0.1:3000 : 1
14842 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.netty.channel.DefaultChannelPool  - Entry count for : http://127.0.0.1:3000 : 1
15943 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.netty.channel.DefaultChannelPool  - Entry count for : http://127.0.0.1:3000 : 1
17043 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.netty.channel.DefaultChannelPool  - Entry count for : http://127.0.0.1:3000 : 1
18141 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.netty.channel.DefaultChannelPool  - Entry count for : http://127.0.0.1:3000 : 1
19243 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.netty.channel.DefaultChannelPool  - Entry count for : http://127.0.0.1:3000 : 1
20346 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.netty.channel.DefaultChannelPool  - Entry count for : http://127.0.0.1:3000 : 1
21440 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.netty.channel.DefaultChannelPool  - Entry count for : http://127.0.0.1:3000 : 1
22548 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.netty.channel.DefaultChannelPool  - Entry count for : http://127.0.0.1:3000 : 1
23641 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.netty.channel.DefaultChannelPool  - Entry count for : http://127.0.0.1:3000 : 1
24742 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.netty.channel.DefaultChannelPool  - Entry count for : http://127.0.0.1:3000 : 1
25841 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.netty.channel.DefaultChannelPool  - Entry count for : http://127.0.0.1:3000 : 1
26940 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.netty.channel.DefaultChannelPool  - Entry count for : http://127.0.0.1:3000 : 1
28042 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.netty.channel.DefaultChannelPool  - Entry count for : http://127.0.0.1:3000 : 1
28339 [Forwarding executeScript on session 295e52a7-25ba-4481-847c-bf376f83d1c9 to remote] DEBUG org.asynchttpclient.netty.request.NettyRequestSender  - Using pooled Channel '[id: 0x66d2e821, L:/127.0.0.1:53111 - R:/127.0.0.1:3000]' for 'POST' to 'http://127.0.0.1:3000/session/295e52a7-25ba-4481-847c-bf376f83d1c9/execute/sync'
28339 [Forwarding executeScript on session 295e52a7-25ba-4481-847c-bf376f83d1c9 to remote] DEBUG org.asynchttpclient.netty.request.NettyRequestSender  - Using open Channel [id: 0x66d2e821, L:/127.0.0.1:53111 - R:/127.0.0.1:3000] for POST '/session/295e52a7-25ba-4481-847c-bf376f83d1c9/execute/sync'
28395 [AsyncHttpClient-1-2] DEBUG org.asynchttpclient.netty.handler.HttpHandler  - 

Request DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST /session/295e52a7-25ba-4481-847c-bf376f83d1c9/execute/sync HTTP/1.1
User-Agent: appium/8.5.1 (selenium/4.12.1 (java windows))
Content-Length: 75
Content-Type: application/json; charset=utf-8
host: 127.0.0.1:3000
accept: */*

Response DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200 OK
X-Powered-By: Express
Vary: X-HTTP-Method-Override
Content-Type: application/json; charset=utf-8
Content-Length: 95
ETag: W/"5f-UURPVJAUlgMR5e4MB0YQCTPKPXY"
Date: Wed, 06 Sep 2023 17:26:25 GMT
Connection: keep-alive
Keep-Alive: timeout=30

28395 [AsyncHttpClient-1-2] DEBUG org.asynchttpclient.netty.channel.ChannelManager  - Adding key: http://127.0.0.1:3000 for channel [id: 0x66d2e821, L:/127.0.0.1:53111 - R:/127.0.0.1:3000]
28444 [Forwarding clickElement on session 295e52a7-25ba-4481-847c-bf376f83d1c9 to remote] DEBUG org.asynchttpclient.netty.request.NettyRequestSender  - Using pooled Channel '[id: 0x66d2e821, L:/127.0.0.1:53111 - R:/127.0.0.1:3000]' for 'POST' to 'http://127.0.0.1:3000/session/295e52a7-25ba-4481-847c-bf376f83d1c9/element/eyJrZXlWYWx1ZVR5cGUiOiJTdHJpbmciLCJrZXlWYWx1ZVN0cmluZyI6ImxvZ2luQnV0dG9uS2V5IiwiZmluZGVyVHlwZSI6IkJ5VmFsdWVLZXkifQ%3D%3D/click'
28444 [Forwarding clickElement on session 295e52a7-25ba-4481-847c-bf376f83d1c9 to remote] DEBUG org.asynchttpclient.netty.request.NettyRequestSender  - Using open Channel [id: 0x66d2e821, L:/127.0.0.1:53111 - R:/127.0.0.1:3000] for POST '/session/295e52a7-25ba-4481-847c-bf376f83d1c9/element/eyJrZXlWYWx1ZVR5cGUiOiJTdHJpbmciLCJrZXlWYWx1ZVN0cmluZyI6ImxvZ2luQnV0dG9uS2V5IiwiZmluZGVyVHlwZSI6IkJ5VmFsdWVLZXkifQ%3D%3D/click'

org.openqa.selenium.TimeoutException: java.util.concurrent.TimeoutException
Build info: version: '4.12.1', revision: '8e34639b11'
System info: os.name: 'Windows 10', os.arch: 'amd64', os.version: '10.0', java.version: '17.0.1'
Driver info: io.appium.java_client.AppiumDriver
Command: [295e52a7-25ba-4481-847c-bf376f83d1c9, clickElement {id=eyJrZXlWYWx1ZVR5cGUiOiJTdHJpbmciLCJrZXlWYWx1ZVN0cmluZyI6ImxvZ2luQnV0dG9uS2V5IiwiZmluZGVyVHlwZSI6IkJ5VmFsdWVLZXkifQ==}]
Capabilities {appium:address: 0.0.0.0, appium:allowCors: false, appium:allowInsecure: [], appium:app: C:\Users\gg.georgiev\Deskto..., appium:automationName: Flutter, appium:basePath: , appium:callbackPort: 4723, appium:debugLogSpacing: false, appium:denyInsecure: [], appium:extraArgs: [], appium:fastReset: true, appium:keepAliveTimeout: 30, appium:localTimezone: false, appium:logNoColors: false, appium:logTimestamp: false, appium:loglevel: debug, appium:longStacktrace: false, appium:newCommandTimeout: 20, appium:noPermsCheck: false, appium:platformVersion: 13, appium:port: 3000, appium:relaxedSecurityEnabled: false, appium:sessionOverride: false, appium:skipUninstall: true, appium:strictCaps: false, appium:subcommand: server, appium:tmpDir: C:\Users\GG9C1F~1.GEO\AppDa..., appium:useDrivers: [], appium:usePlugins: [], platformName: ANDROID}
Element: [io.github.ashwith.flutter.FlutterElement@2bf56ccb -> unknown locator]
Session ID: 295e52a7-25ba-4481-847c-bf376f83d1c9

    at org.openqa.selenium.remote.http.netty.NettyHttpHandler.makeCall(NettyHttpHandler.java:65)
    at io.appium.java_client.AppiumUserAgentFilter.lambda$apply$0(AppiumUserAgentFilter.java:88)
    at org.openqa.selenium.remote.http.Filter.lambda$andFinally$1(Filter.java:55)
    at org.openqa.selenium.remote.http.netty.NettyHttpHandler.execute(NettyHttpHandler.java:48)
    at org.openqa.selenium.remote.http.netty.NettyClient.execute(NettyClient.java:96)
    at org.openqa.selenium.remote.HttpCommandExecutor.execute(HttpCommandExecutor.java:188)
    at io.appium.java_client.remote.AppiumCommandExecutor.execute(AppiumCommandExecutor.java:250)
    at org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:602)
    at org.openqa.selenium.remote.RemoteWebElement.execute(RemoteWebElement.java:224)
    at org.openqa.selenium.remote.RemoteWebElement.click(RemoteWebElement.java:77)
    at ExampleTests.appiumFlutterTest(ExampleTests.java:77)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at org.testng.internal.invokers.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:139)
    at org.testng.internal.invokers.TestInvoker.invokeMethod(TestInvoker.java:664)
    at org.testng.internal.invokers.TestInvoker.invokeTestMethod(TestInvoker.java:227)
    at org.testng.internal.invokers.MethodRunner.runInSequence(MethodRunner.java:50)
    at org.testng.internal.invokers.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:957)
    at org.testng.internal.invokers.TestInvoker.invokeTestMethods(TestInvoker.java:200)
    at org.testng.internal.invokers.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:148)
    at org.testng.internal.invokers.TestMethodWorker.run(TestMethodWorker.java:128)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
    at org.testng.TestRunner.privateRun(TestRunner.java:848)
    at org.testng.TestRunner.run(TestRunner.java:621)
    at org.testng.SuiteRunner.runTest(SuiteRunner.java:443)
    at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:437)
    at org.testng.SuiteRunner.privateRun(SuiteRunner.java:397)
    at org.testng.SuiteRunner.run(SuiteRunner.java:336)
    at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
    at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:95)
    at org.testng.TestNG.runSuitesSequentially(TestNG.java:1280)
    at org.testng.TestNG.runSuitesLocally(TestNG.java:1200)
    at org.testng.TestNG.runSuites(TestNG.java:1114)
    at org.testng.TestNG.run(TestNG.java:1082)
    at com.intellij.rt.testng.IDEARemoteTestNG.run(IDEARemoteTestNG.java:66)
    at com.intellij.rt.testng.RemoteTestNGStarter.main(RemoteTestNGStarter.java:105)
Caused by: java.util.concurrent.TimeoutException
    at java.base/java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1960)
    at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2095)
    at org.asynchttpclient.netty.NettyResponseFuture.get(NettyResponseFuture.java:206)
    at org.openqa.selenium.remote.http.netty.NettyHttpHandler.makeCall(NettyHttpHandler.java:59)
    ... 37 more

628491 [AsyncHttpClient-1-3] DEBUG org.asynchttpclient.netty.channel.NettyConnectListener  - Using new Channel '[id: 0x5fcbb20a, L:/127.0.0.1:53537 - R:/127.0.0.1:3000]' for 'DELETE' to '/session/295e52a7-25ba-4481-847c-bf376f83d1c9'
628545 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.netty.timeout.TimeoutTimerTask  - Request timeout to 127.0.0.1/127.0.0.1:3000 after 600000 ms for NettyResponseFuture{currentRetry=0,
    isDone=0,
    isCancelled=0,
    asyncHandler=org.asynchttpclient.AsyncCompletionHandlerBase@c743144,
    nettyRequest=org.asynchttpclient.netty.request.NettyRequest@54448e1,
    future=java.util.concurrent.CompletableFuture@7ff79e8d[Not completed],
    uri=http://127.0.0.1:3000/session/295e52a7-25ba-4481-847c-bf376f83d1c9/element/eyJrZXlWYWx1ZVR5cGUiOiJTdHJpbmciLCJrZXlWYWx1ZVN0cmluZyI6ImxvZ2luQnV0dG9uS2V5IiwiZmluZGVyVHlwZSI6IkJ5VmFsdWVLZXkifQ%3D%3D/click,
    keepAlive=true,
    redirectCount=0,
    timeoutsHolder=org.asynchttpclient.netty.timeout.TimeoutsHolder@68917da1,
    inAuth=0,
    touch=1694021185101} after 600101 ms
628545 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.netty.channel.ChannelManager  - Closing Channel [id: 0x66d2e821, L:/127.0.0.1:53111 - R:/127.0.0.1:3000] 
628546 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.netty.request.NettyRequestSender  - Aborting Future NettyResponseFuture{currentRetry=0,
    isDone=0,
    isCancelled=0,
    asyncHandler=org.asynchttpclient.AsyncCompletionHandlerBase@c743144,
    nettyRequest=org.asynchttpclient.netty.request.NettyRequest@54448e1,
    future=java.util.concurrent.CompletableFuture@7ff79e8d[Not completed],
    uri=http://127.0.0.1:3000/session/295e52a7-25ba-4481-847c-bf376f83d1c9/element/eyJrZXlWYWx1ZVR5cGUiOiJTdHJpbmciLCJrZXlWYWx1ZVN0cmluZyI6ImxvZ2luQnV0dG9uS2V5IiwiZmluZGVyVHlwZSI6IkJ5VmFsdWVLZXkifQ%3D%3D/click,
    keepAlive=true,
    redirectCount=0,
    timeoutsHolder=org.asynchttpclient.netty.timeout.TimeoutsHolder@68917da1,
    inAuth=0,
    touch=1694021185101}

628546 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.netty.request.NettyRequestSender  - Request timeout to 127.0.0.1/127.0.0.1:3000 after 600000 ms
java.util.concurrent.TimeoutException: Request timeout to 127.0.0.1/127.0.0.1:3000 after 600000 ms
    at org.asynchttpclient.netty.timeout.TimeoutTimerTask.expire(TimeoutTimerTask.java:43)
    at org.asynchttpclient.netty.timeout.RequestTimeoutTimerTask.run(RequestTimeoutTimerTask.java:50)
    at io.netty.util.HashedWheelTimer$HashedWheelTimeout.run(HashedWheelTimer.java:715)
    at io.netty.util.concurrent.ImmediateExecutor.execute(ImmediateExecutor.java:34)
    at io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:703)
    at io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:790)
    at io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:503)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:833)
628547 [AsyncHttpClient-1-2] DEBUG org.asynchttpclient.netty.handler.HttpHandler  - Channel Closed: [id: 0x66d2e821, L:/127.0.0.1:53111 ! R:/127.0.0.1:3000] with attribute DISCARD
628548 [AsyncHttpClient-1-1] DEBUG org.asynchttpclient.AsyncCompletionHandler  - Request timeout to 127.0.0.1/127.0.0.1:3000 after 600000 ms
java.util.concurrent.TimeoutException: Request timeout to 127.0.0.1/127.0.0.1:3000 after 600000 ms
    at org.asynchttpclient.netty.timeout.TimeoutTimerTask.expire(TimeoutTimerTask.java:43)
    at org.asynchttpclient.netty.timeout.RequestTimeoutTimerTask.run(RequestTimeoutTimerTask.java:50)
    at io.netty.util.HashedWheelTimer$HashedWheelTimeout.run(HashedWheelTimer.java:715)
    at io.netty.util.concurrent.ImmediateExecutor.execute(ImmediateExecutor.java:34)
    at io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:703)
    at io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:790)
    at io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:503)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:833)
628923 [AsyncHttpClient-1-3] DEBUG org.asynchttpclient.netty.handler.HttpHandler  - 

Request DefaultFullHttpRequest(decodeResult: success, version: HTTP/1.1, content: EmptyByteBufBE)
DELETE /session/295e52a7-25ba-4481-847c-bf376f83d1c9 HTTP/1.1
User-Agent: appium/8.5.1 (selenium/4.12.1 (java windows))
Content-Type: application/json; charset=utf-8
host: 127.0.0.1:3000
accept: */*

Response DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200 OK
X-Powered-By: Express
Content-Type: application/json; charset=utf-8
Content-Length: 14
ETag: W/"e-9/1BuKMgFObM1mWJm+YjxtXJnUM"
Date: Wed, 06 Sep 2023 17:36:25 GMT
Connection: keep-alive
Keep-Alive: timeout=30

628923 [AsyncHttpClient-1-3] DEBUG org.asynchttpclient.netty.channel.ChannelManager  - Adding key: http://127.0.0.1:3000 for channel [id: 0x5fcbb20a, L:/127.0.0.1:53537 - R:/127.0.0.1:3000]

===============================================
Default Suite
Total tests run: 1, Passes: 0, Failures: 1, Skips: 0
===============================================

Process finished with exit code 0

Here is the full appium log:

[Appium] Welcome to Appium v2.1.2
[Appium] Non-default server args:
[Appium] {
[Appium]   keepAliveTimeout: 30,
[Appium]   port: 3000
[Appium] }
[Appium] Attempting to load driver uiautomator2...
[debug] [Appium] Requiring driver at C:\Users\gg.georgiev\.appium\node_modules\appium-uiautomator2-driver
[Appium] Attempting to load driver flutter...
[debug] [Appium] Requiring driver at C:\Users\gg.georgiev\.appium\node_modules\appium-flutter-driver
[Appium] Appium REST http interface listener started on http://0.0.0.0:3000
[Appium] You can provide the following URLs in your client code to connect to this server:
[Appium]        http://192.168.1.14:3000/
[Appium]        http://127.0.0.1:3000/ (only accessible from the same host)
[Appium] Available drivers:
[Appium]   - uiautomator2@2.29.5 (automationName 'UiAutomator2')
[Appium]   - flutter@1.21.1 (automationName 'Flutter')
[Appium] No plugins have been installed. Use the "appium plugin" command to install the one(s) you want to use.
[debug] [HTTP] Request idempotency key: 061a0c06-4ccb-4c09-886e-fd9d5538ac8c
[HTTP] --> POST /session
[HTTP] {"capabilities":{"firstMatch":[{}],"alwaysMatch":{"appium:app":"C:\\Users\\gg.georgiev\\Desktop\\georgi-tests\\src\\test\\resources\\app-debug.apk","appium:automationName":"Flutter","appium:fastReset":true,"appium:newCommandTimeout":"20","appium:platformVersion":"13","platformName":"ANDROID"}}}
[debug] [AppiumDriver@9637] Calling AppiumDriver.createSession() with args: [null,null,{"firstMatch":[{}],"alwaysMatch":{"appium:app":"C:\\Users\\gg.georgiev\\Desktop\\georgi-tests\\src\\test\\resources\\app-debug.apk","appium:automationName":"Flutter","appium:fastReset":true,"appium:newCommandTimeout":"20","appium:platformVersion":"13","platformName":"ANDROID"}}]
[debug] [AppiumDriver@9637] Event 'newSessionRequested' logged at 1694021157601 (20:25:57 GMT+0300 (Eastern European Summer Time))
[Appium] Attempting to find matching driver for automationName 'Flutter' and platformName 'ANDROID'
[Appium] The 'flutter' driver was installed and matched caps.
[Appium] Will require it at C:\Users\gg.georgiev\.appium\node_modules\appium-flutter-driver
[debug] [Appium] Requiring driver at C:\Users\gg.georgiev\.appium\node_modules\appium-flutter-driver
[AppiumDriver@9637] Appium v2.1.2 creating new FlutterDriver (v1.21.1) session
[AppiumDriver@9637] Checking BaseDriver versions for Appium and FlutterDriver
[AppiumDriver@9637] Appium's BaseDriver version is 9.3.19
[AppiumDriver@9637] FlutterDriver's BaseDriver version is 9.3.19
[debug] [FlutterDriver@dfc3] Creating session with W3C capabilities: {
[debug] [FlutterDriver@dfc3]   "alwaysMatch": {
[debug] [FlutterDriver@dfc3]     "platformName": "ANDROID",
[debug] [FlutterDriver@dfc3]     "appium:app": "C:\\Users\\gg.georgiev\\Desktop\\georgi-tests\\src\\test\\resources\\app-debug.apk",
[debug] [FlutterDriver@dfc3]     "appium:automationName": "Flutter",
[debug] [FlutterDriver@dfc3]     "appium:fastReset": true,
[debug] [FlutterDriver@dfc3]     "appium:newCommandTimeout": "20",
[debug] [FlutterDriver@dfc3]     "appium:platformVersion": "13"
[debug] [FlutterDriver@dfc3]   },
[debug] [FlutterDriver@dfc3]   "firstMatch": [
[debug] [FlutterDriver@dfc3]     {}
[debug] [FlutterDriver@dfc3]   ]
[debug] [FlutterDriver@dfc3] }
[BaseDriver] Number capability passed in as string. Functionality may be compromised.
[FlutterDriver@dfc3] Capability 'newCommandTimeout' changed from string ('20') to integer (20). This may cause unexpected behavior
[FlutterDriver@dfc3] The following capabilities were provided, but are not recognized by Appium:
[FlutterDriver@dfc3]   fastReset
[FlutterDriver@dfc3 (295e52a7)] Session created with session id: 295e52a7-25ba-4481-847c-bf376f83d1c9
[FlutterDriver] Starting an Android proxy session
[debug] [AndroidUiautomator2Driver@151e] Creating session with W3C capabilities: {
[debug] [AndroidUiautomator2Driver@151e]   "alwaysMatch": {
[debug] [AndroidUiautomator2Driver@151e]     "platformName": "ANDROID",
[debug] [AndroidUiautomator2Driver@151e]     "appium:app": "C:\\Users\\gg.georgiev\\Desktop\\georgi-tests\\src\\test\\resources\\app-debug.apk",
[debug] [AndroidUiautomator2Driver@151e]     "appium:automationName": "Flutter",
[debug] [AndroidUiautomator2Driver@151e]     "appium:fastReset": true,
[debug] [AndroidUiautomator2Driver@151e]     "appium:newCommandTimeout": "20",
[debug] [AndroidUiautomator2Driver@151e]     "appium:platformVersion": "13"
[debug] [AndroidUiautomator2Driver@151e]   },
[debug] [AndroidUiautomator2Driver@151e]   "firstMatch": [
[debug] [AndroidUiautomator2Driver@151e]     {}
[debug] [AndroidUiautomator2Driver@151e]   ]
[debug] [AndroidUiautomator2Driver@151e] }
[BaseDriver] Number capability passed in as string. Functionality may be compromised.
[AndroidUiautomator2Driver@151e] Capability 'newCommandTimeout' changed from string ('20') to integer (20). This may cause unexpected behavior
[AndroidUiautomator2Driver@151e] The following capabilities were provided, but are not recognized by Appium:
[AndroidUiautomator2Driver@151e]   fastReset
[AndroidUiautomator2Driver@151e (9767bba7)] Session created with session id: 9767bba7-2259-4bd5-a362-6540c80be880
[BaseDriver] Using local app 'C:\Users\gg.georgiev\Desktop\georgi-tests\src\test\resources\app-debug.apk'
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Checking whether app is actually present
[ADB] Found 2 'build-tools' folders under 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk' (newest first):
[ADB]     C:/Users/gg.georgiev/AppData/Local/Android/Sdk/build-tools/34.0.0
[ADB]     C:/Users/gg.georgiev/AppData/Local/Android/Sdk/build-tools/33.0.1
[ADB] Using 'adb.exe' from 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe'
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 start-server'
[AndroidDriver] Retrieving device list
[debug] [ADB] Trying to find a connected android device
[debug] [ADB] Getting connected devices
[debug] [ADB] Connected devices: [{"udid":"S4LJGA6HEIZLRCZD","state":"device"}]
[AndroidDriver] Looking for a device with Android '13.0.0'
[debug] [ADB] Setting device id to S4LJGA6HEIZLRCZD
[ADB] Getting device platform version
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell getprop ro.build.version.release'
[debug] [ADB] Current device property 'ro.build.version.release': 13
[AndroidDriver] Using device: S4LJGA6HEIZLRCZD
[ADB] Using 'adb.exe' from 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe'
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 start-server'
[debug] [ADB] Setting device id to S4LJGA6HEIZLRCZD
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell getprop ro.build.version.sdk'
[debug] [ADB] Current device property 'ro.build.version.sdk': 33
[ADB] Getting device platform version
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell getprop ro.build.version.release'
[debug] [ADB] Current device property 'ro.build.version.release': 13
[debug] [ADB] Device API level: 33
[AndroidUiautomator2Driver@151e (9767bba7)] Relaxing hidden api policy
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell 'settings put global hidden_api_policy_pre_p_apps 1;settings put global hidden_api_policy_p_apps 1;settings put global hidden_api_policy 1''
[debug] [AndroidDriver] Parsing package and activity from app manifest
[ADB] Package name: 'com.my.app'
[ADB] Main activity name: 'com.my.app.MainActivity'
[debug] [AndroidDriver] Parsed package and activity are: com.my.app/com.my.app.MainActivity
[debug] [AndroidDriver] Pushing settings apk to device...
[debug] [ADB] Getting package info for 'io.appium.settings'
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell dumpsys package io.appium.settings'
[debug] [ADB] The version name of the installed 'io.appium.settings' is greater or equal to the application version name ('5.1.0' >= '5.1.0')
[debug] [ADB] There is no need to install/upgrade 'C:\Users\gg.georgiev\.appium\node_modules\appium-flutter-driver\node_modules\appium-uiautomator2-driver\node_modules\io.appium.settings\apks\settings_apk-debug.apk'
[debug] [ADB] Getting IDs of all 'io.appium.settings' processes
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell 'pgrep --help; echo $?''
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell pgrep -f \(\[\[:blank:\]\]\|\^\)io\.appium\.settings\(\[\[:blank:\]\]\|\$\)'
[debug] [AndroidDriver] io.appium.settings is already running. There is no need to reset its permissions.
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell appops set io.appium.settings android:mock_location allow'
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell "[ -e '/data/local/tmp/mock_apps.json' ] && echo __PASS__"'
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell cat /data/local/tmp/mock_apps.json'
[debug] [Logcat] Starting logs capture with command: C:\\Users\\gg.georgiev\\AppData\\Local\\Android\\Sdk\\platform-tools\\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD logcat -v threadtime
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Forwarding UiAutomator2 Server port 6790 to local port 8200
[debug] [ADB] Forwarding system: 8200 to device: 6790
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD forward tcp:8200 tcp:6790'
[debug] [ADB] Checking app cert for C:\Users\gg.georgiev\.appium\node_modules\appium-flutter-driver\node_modules\appium-uiautomator2-driver\node_modules\appium-uiautomator2-server\apks\appium-uiautomator2-server-v5.12.2.apk
[debug] [ADB] Checking app cert for C:\Users\gg.georgiev\.appium\node_modules\appium-flutter-driver\node_modules\appium-uiautomator2-driver\node_modules\appium-uiautomator2-server\apks\appium-uiautomator2-server-debug-androidTest.apk
[ADB] Using 'apksigner.jar' from 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\build-tools\34.0.0\lib\apksigner.jar'
[debug] [ADB] Starting apksigner: C:\\Programs\\Java\\jdk-17.0.1\\bin\\java.exe -Xmx1024M -Xss1m -jar C:\\Users\\gg.georgiev\\AppData\\Local\\Android\\Sdk\\build-tools\\34.0.0\\lib\\apksigner.jar verify --print-certs C:\\Users\\gg.georgiev\\.appium\\node_modules\\appium-flutter-driver\\node_modules\\appium-uiautomator2-driver\\node_modules\\appium-uiautomator2-server\\apks\\appium-uiautomator2-server-debug-androidTest.apk
[debug] [ADB] Starting apksigner: C:\\Programs\\Java\\jdk-17.0.1\\bin\\java.exe -Xmx1024M -Xss1m -jar C:\\Users\\gg.georgiev\\AppData\\Local\\Android\\Sdk\\build-tools\\34.0.0\\lib\\apksigner.jar verify --print-certs C:\\Users\\gg.georgiev\\.appium\\node_modules\\appium-flutter-driver\\node_modules\\appium-uiautomator2-driver\\node_modules\\appium-uiautomator2-server\\apks\\appium-uiautomator2-server-v5.12.2.apk
[debug] [ADB] apksigner stdout: Signer #1 certificate DN: EMAILADDRESS=android@android.com, CN=Android, OU=Android, O=Android, L=Mountain View, ST=California, C=US
[debug] [ADB] Signer #1 certificate SHA-256 digest: a40da80a59d170caa950cf15c18c454d47a39b26989d8b640ecd745ba71bf5dc
[debug] [ADB] Signer #1 certificate SHA-1 digest: 61ed377e85d386a8dfee6b864bd85b0bfaa5af81
[debug] [ADB] Signer #1 certificate MD5 digest: e89b158e4bcf988ebd09eb83f5378e87
[debug] [ADB]
[debug] [ADB] sha256 hash did match for 'appium-uiautomator2-server-debug-androidTest.apk'
[ADB] 'C:\Users\gg.georgiev\.appium\node_modules\appium-flutter-driver\node_modules\appium-uiautomator2-driver\node_modules\appium-uiautomator2-server\apks\appium-uiautomator2-server-debug-androidTest.apk' is signed with the default certificate
[debug] [ADB] Getting install status for io.appium.uiautomator2.server.test
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell pm path io.appium.uiautomator2.server.test'
[debug] [ADB] 'io.appium.uiautomator2.server.test' is installed
[debug] [ADB] apksigner stdout: Signer #1 certificate DN: EMAILADDRESS=android@android.com, CN=Android, OU=Android, O=Android, L=Mountain View, ST=California, C=US
[debug] [ADB] Signer #1 certificate SHA-256 digest: a40da80a59d170caa950cf15c18c454d47a39b26989d8b640ecd745ba71bf5dc
[debug] [ADB] Signer #1 certificate SHA-1 digest: 61ed377e85d386a8dfee6b864bd85b0bfaa5af81
[debug] [ADB] Signer #1 certificate MD5 digest: e89b158e4bcf988ebd09eb83f5378e87
[debug] [ADB]
[debug] [ADB] sha256 hash did match for 'appium-uiautomator2-server-v5.12.2.apk'
[ADB] 'C:\Users\gg.georgiev\.appium\node_modules\appium-flutter-driver\node_modules\appium-uiautomator2-driver\node_modules\appium-uiautomator2-server\apks\appium-uiautomator2-server-v5.12.2.apk' is signed with the default certificate
[debug] [ADB] Getting package info for 'io.appium.uiautomator2.server'
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell dumpsys package io.appium.uiautomator2.server'
[debug] [ADB] The version code of the installed 'io.appium.uiautomator2.server' is greater than the application version code (130 > 129)
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Server packages status: [{"wasSigned":true,"installState":"newerVersionInstalled","appPath":"C:\\Users\\gg.georgiev\\.appium\\node_modules\\appium-flutter-driver\\node_modules\\appium-uiautomator2-driver\\node_modules\\appium-uiautomator2-server\\apks\\appium-uiautomator2-server-v5.12.2.apk","appId":"io.appium.uiautomator2.server"},{"wasSigned":true,"installState":"sameVersionInstalled","appPath":"C:\\Users\\gg.georgiev\\.appium\\node_modules\\appium-flutter-driver\\node_modules\\appium-uiautomator2-driver\\node_modules\\appium-uiautomator2-server\\apks\\appium-uiautomator2-server-debug-androidTest.apk","appId":"io.appium.uiautomator2.server.test"}]
[AndroidUiautomator2Driver@151e (9767bba7)] Server packages are not going to be (re)installed
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Waiting up to 30000ms for services to be available
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell pm list instrumentation'
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Instrumentation target 'io.appium.uiautomator2.server.test/androidx.test.runner.AndroidJUnitRunner' is available
[ADB] Adding packages ["io.appium.settings","io.appium.uiautomator2.server","io.appium.uiautomator2.server.test"] to Doze whitelist
[debug] [ADB] Got the following command chunks to execute: [["dumpsys","deviceidle","whitelist","+io.appium.settings",";","dumpsys","deviceidle","whitelist","+io.appium.uiautomator2.server",";","dumpsys","deviceidle","whitelist","+io.appium.uiautomator2.server.test",";"]]
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell dumpsys deviceidle whitelist +io.appium.settings ; dumpsys deviceidle whitelist +io.appium.uiautomator2.server ; dumpsys deviceidle whitelist +io.appium.uiautomator2.server.test ;'
[debug] [ADB] Checking app cert for C:\Users\gg.georgiev\Desktop\georgi-tests\src\test\resources\app-debug.apk
[debug] [ADB] Starting apksigner: C:\\Programs\\Java\\jdk-17.0.1\\bin\\java.exe -Xmx1024M -Xss1m -jar C:\\Users\\gg.georgiev\\AppData\\Local\\Android\\Sdk\\build-tools\\34.0.0\\lib\\apksigner.jar verify --print-certs C:\\Users\\gg.georgiev\\Desktop\\georgi-tests\\src\\test\\resources\\app-debug.apk
[debug] [ADB] apksigner stdout: Signer #1 certificate DN: C=US, O=Android, CN=Android Debug
[debug] [ADB] Signer #1 certificate SHA-256 digest: 11b653bb420eee0344f2c78277e118ca03552135813400995caad5d5db78f811
[debug] [ADB] Signer #1 certificate SHA-1 digest: e12999f658f7d3097acaf3e5cba9b01bb60fdb44
[debug] [ADB] Signer #1 certificate MD5 digest: c9a7da65323540215cb5d21069b0dfa7
[debug] [ADB]
[ADB] 'C:\Users\gg.georgiev\Desktop\georgi-tests\src\test\resources\app-debug.apk' is signed with a non-default certificate
[debug] [ADB] Getting package info for 'com.my.app'
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell dumpsys package com.my.app'
[debug] [ADB] The version name of the installed 'com.my.app' is equal to application version name (1 === 1)
[debug] [ADB] There is no need to install/upgrade 'C:\Users\gg.georgiev\Desktop\georgi-tests\src\test\resources\app-debug.apk'
[AndroidDriver] Performing fast reset on 'com.my.app'
[debug] [ADB] Getting install status for com.my.app
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell pm path com.my.app'
[debug] [ADB] 'com.my.app' is installed
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell am force-stop com.my.app'
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell pm clear com.my.app'
[debug] [AndroidDriver] Performed fast reset on the installed 'com.my.app' application (stop and clear)
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Performing shallow cleanup of automation leftovers
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] No obsolete sessions have been detected (socket hang up)
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell am force-stop io.appium.uiautomator2.server.test'
[AndroidUiautomator2Driver@151e (9767bba7)] Starting UIAutomator2 server 5.12.2
[AndroidUiautomator2Driver@151e (9767bba7)] Using UIAutomator2 server from 'C:\Users\gg.georgiev\.appium\node_modules\appium-flutter-driver\node_modules\appium-uiautomator2-driver\node_modules\appium-uiautomator2-server\apks\appium-uiautomator2-server-v5.12.2.apk' and test from 'C:\Users\gg.georgiev\.appium\node_modules\appium-flutter-driver\node_modules\appium-uiautomator2-driver\node_modules\appium-uiautomator2-server\apks\appium-uiautomator2-server-debug-androidTest.apk'
[AndroidUiautomator2Driver@151e (9767bba7)] Waiting up to 30000ms for UiAutomator2 to be online...
[debug] [ADB] Creating ADB subprocess with args: ["-P","5037","-s","S4LJGA6HEIZLRCZD","shell","am","instrument","-w","-e","disableAnalytics",true,"io.appium.uiautomator2.server.test/androidx.test.runner.AndroidJUnitRunner"]
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Matched '/status' to command name 'getStatus'
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Proxying [GET /status] to [GET http://127.0.0.1:8200/status] with no body
[AndroidUiautomator2Driver@151e (9767bba7)] socket hang up
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Matched '/status' to command name 'getStatus'
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Proxying [GET /status] to [GET http://127.0.0.1:8200/status] with no body
[AndroidUiautomator2Driver@151e (9767bba7)] socket hang up
[debug] [Instrumentation] io.appium.uiautomator2.server.test.AppiumUiAutomator2Server:
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Matched '/status' to command name 'getStatus'
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Proxying [GET /status] to [GET http://127.0.0.1:8200/status] with no body
[AndroidUiautomator2Driver@151e (9767bba7)] socket hang up
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Matched '/status' to command name 'getStatus'
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Proxying [GET /status] to [GET http://127.0.0.1:8200/status] with no body
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Got response with status 200: {"sessionId":"None","value":{"message":"UiAutomator2 Server is ready to accept commands","ready":true}}
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] The initialization of the instrumentation process took 3084ms
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Matched '/session' to command name 'createSession'
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Proxying [POST /session] to [POST http://127.0.0.1:8200/session] with body: {"capabilities":{"firstMatch":[{"platform":"LINUX","webStorageEnabled":false,"takesScreenshot":true,"javascriptEnabled":true,"databaseEnabled":false,"networkConnectionEnabled":true,"locationContextEnabled":false,"warnings":{},"desired":{"platformName":"ANDROID","app":"C:\\Users\\gg.georgiev\\Desktop\\georgi-tests\\src\\test\\resources\\app-debug.apk","automationName":"Flutter","fastReset":true,"newCommandTimeout":20,"platformVersion":"13"},"platformName":"ANDROID","app":"C:\\Users\\gg.georgiev\\Desktop\\georgi-tests\\src\\test\\resources\\app-debug.apk","automationName":"Flutter","fastReset":true,"newCommandTimeout":20,"platformVersion":"13","deviceName":"S4LJGA6HEIZLRCZD","deviceUDID":"S4LJGA6HEIZLRCZD","appPackage":"com.my.app"}],"alwaysMatch":{}}}
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Got response with status 200: {"sessionId":"aada2717-4d8c-4ae5-bc23-c99906bbe92f","value":{"capabilities":{"firstMatch":[{"platform":"LINUX","webStorageEnabled":false,"takesScreenshot":true,"javascriptEnabled":true,"databaseEnabled":false,"networkConnectionEnabled":true,"locationContextEnabled":false,"warnings":{},"desired":{"platformName":"ANDROID","app":"C:\\Users\\gg.georgiev\\Desktop\\georgi-tests\\src\\test\\resources\\app-debug.apk","automationName":"Flutter","fastReset":true,"newCommandTimeout":20,"platformVersion":"13"},"platformName":"ANDROID","app":"C:\\Users\\gg.georgiev\\Desktop\\georgi-tests\\src\\test\\resources\\app-debug.apk","automationName":"Flutter","fastReset":true,"newCommandTimeout":20,"platformVersion":"13","deviceName":"S4LJGA6HEIZLRCZD","deviceUDID":"S4LJGA6HEIZLRCZD","appPackage":"com.my.app"}],"alwaysMatch":{}},"sessionId":"aada2717-4d8c-4ae5-bc23-c99906bbe92f"}}
[AndroidUiautomator2Driver@151e (9767bba7)] Determined the downstream protocol as 'W3C'
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Proxying [GET /appium/device/info] to [GET http://127.0.0.1:8200/session/aada2717-4d8c-4ae5-bc23-c99906bbe92f/appium/device/info] with no body
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Got response with status 200: {"sessionId":"aada2717-4d8c-4ae5-bc23-c99906bbe92f","value":{"androidId":"8bd21f287171d92b","apiVersion":"33","bluetooth":{"state":"OFF"},"brand":"Redmi","carrierName":"VIVACOM","displayDensity":440,"locale":"en_US","manufacturer":"Xiaomi","model":"M2101K7BNY","networks":[{"capabilities":{"SSID":null,"linkDownBandwidthKbps":30000,"linkUpstreamBandwidthKbps":12000,"networkCapabilities":"NET_CAPABILITY_NOT_METERED,NET_CAPABILITY_INTERNET,NET_CAPABILITY_NOT_RESTRICTED,NET_CAPABILITY_TRUSTED,NET_CAPABILITY_NOT_VPN,NET_CAPABILITY_VALIDATED,NET_CAPABILITY_NOT_ROAMING,NET_CAPABILITY_FOREGROUND,NET_CAPABILITY_NOT_CONGESTED,NET_CAPABILITY_NOT_SUSPENDED","signalStrength":-49,"transportTypes":"TRANSPORT_WIFI"},"detailedState":"CONNECTED","extraInfo":"","isAvailable":true,"isConnected":true,"isFailover":false,"isRoaming":false,"state":"CONNECTED","subtype":-1,"subtypeName":"","type":1,"typeName":"WIFI"}],"platformVersion":"13","realDisplaySize":"1080x2400","timeZone":"Europe/Sofia"}}
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell dumpsys window'
[AndroidDriver] Screen already unlocked, doing nothing
[AndroidUiautomator2Driver@151e (9767bba7)] Starting 'com.my.app/com.my.app.MainActivity and waiting for 'com.my.app/com.my.app.MainActivity'
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell am start -W -n com.my.app/com.my.app.MainActivity -S -a android.intent.action.MAIN -c android.intent.category.LAUNCHER -f 0x10200000'
[debug] [ADB] Waiting up to 20000ms for activity matching pkg: 'com.my.app' and activity: 'com.my.app.MainActivity' to be focused
[debug] [ADB] Possible activities, to be checked: 'com.my.app.MainActivity', 'com.my.app.com.my.app.MainActivity'
[debug] [ADB] Getting focused package and activity
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell dumpsys window displays'
[debug] [ADB] Found package: 'com.my.app' and fully qualified activity name : 'com.my.app.MainActivity'
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Proxying [GET /appium/device/pixel_ratio] to [GET http://127.0.0.1:8200/session/aada2717-4d8c-4ae5-bc23-c99906bbe92f/appium/device/pixel_ratio] with no body
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Got response with status 200: {"sessionId":"aada2717-4d8c-4ae5-bc23-c99906bbe92f","value":2.75}
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Matched '/appium/device/system_bars' to command name 'getSystemBars'
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Proxying [GET /appium/device/system_bars] to [GET http://127.0.0.1:8200/session/aada2717-4d8c-4ae5-bc23-c99906bbe92f/appium/device/system_bars] with no body
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Got response with status 200: {"sessionId":"aada2717-4d8c-4ae5-bc23-c99906bbe92f","value":{"statusBar":93}}
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Matched '/window/current/size' to command name 'getWindowSize'
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Proxying [GET /window/current/size] to [GET http://127.0.0.1:8200/session/aada2717-4d8c-4ae5-bc23-c99906bbe92f/window/current/size] with no body
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Got response with status 200: {"sessionId":"aada2717-4d8c-4ae5-bc23-c99906bbe92f","value":{"height":2177,"width":1080}}
[debug] [FlutterDriver] Establishing a connection to the Dart Observatory. Will retry 10 times with 3000ms delay between retries. These values could be customized by changing 'maxRetryCount' and 'retryBackoffTime' capabilities.
[FlutterDriver] Attempt #1 of 10
[debug] [ADB] Forwarding system: 46671 to device: 46671
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD forward tcp:46671 tcp:46671'
[FlutterDriver] Connecting to Dart Observatory: ws://127.0.0.1:46671/mb_QmkshrIw=/ws
[FlutterDriver] Listing all isolates: [{"type":"@Isolate","id":"isolates/334973010899427","name":"main","number":"334973010899427","isSystemIsolate":false,"isolateGroupId":"isolateGroups/7898095738913535527"}]
[AppiumDriver@9637] New FlutterDriver session created successfully, session 295e52a7-25ba-4481-847c-bf376f83d1c9 added to master session list
[debug] [AppiumDriver@9637] Event 'newSessionStarted' logged at 1694021169900 (20:26:09 GMT+0300 (Eastern European Summer Time))
[debug] [FlutterDriver@dfc3 (295e52a7)] Cached the protocol value 'W3C' for the new session 295e52a7-25ba-4481-847c-bf376f83d1c9
[debug] [FlutterDriver@dfc3 (295e52a7)] Responding to client with driver.createSession() result: {"capabilities":{"subcommand":"server","address":"0.0.0.0","keepAliveTimeout":30,"port":3000,"extraArgs":[],"allowCors":false,"allowInsecure":[],"basePath":"","callbackPort":4723,"debugLogSpacing":false,"denyInsecure":[],"localTimezone":false,"loglevel":"debug","logNoColors":false,"logTimestamp":false,"longStacktrace":false,"noPermsCheck":false,"relaxedSecurityEnabled":false,"sessionOverride":false,"strictCaps":false,"useDrivers":[],"usePlugins":[],"tmpDir":"C:\\Users\\GG9C1F~1.GEO\\AppData\\Local\\Temp","platformName":"ANDROID","app":"C:\\Users\\gg.georgiev\\Desktop\\georgi-tests\\src\\test\\resources\\app-debug.apk","automationName":"Flutter","fastReset":true,"newCommandTimeout":20,"platformVersion":"13","skipUninstall":true}}
[HTTP] <-- POST /session 200 12305 ms - 813
[HTTP]
[HTTP] --> POST /session/295e52a7-25ba-4481-847c-bf376f83d1c9/execute/sync
[HTTP] {"script":"flutter:setFrameSync","args":[false,3500]}
[debug] [FlutterDriver@dfc3 (295e52a7)] Calling AppiumDriver.execute() with args: ["flutter:setFrameSync",[false,3500],"295e52a7-25ba-4481-847c-bf376f83d1c9"]
[debug] [FlutterDriver] Executing Flutter driver command 'execute'
[debug] [FlutterDriver@dfc3 (295e52a7)] Responding to client with driver.execute() result: {"isError":false,"response":{},"type":"_extensionType","method":"ext.flutter.driver"}
[HTTP] <-- POST /session/295e52a7-25ba-4481-847c-bf376f83d1c9/execute/sync 200 46 ms - 95
[HTTP]
[HTTP] --> POST /session/295e52a7-25ba-4481-847c-bf376f83d1c9/element/eyJrZXlWYWx1ZVR5cGUiOiJTdHJpbmciLCJrZXlWYWx1ZVN0cmluZyI6ImxvZ2luQnV0dG9uS2V5IiwiZmluZGVyVHlwZSI6IkJ5VmFsdWVLZXkifQ%3D%3D/click
[HTTP] {"id":"eyJrZXlWYWx1ZVR5cGUiOiJTdHJpbmciLCJrZXlWYWx1ZVN0cmluZyI6ImxvZ2luQnV0dG9uS2V5IiwiZmluZGVyVHlwZSI6IkJ5VmFsdWVLZXkifQ=="}
[debug] [FlutterDriver@dfc3 (295e52a7)] Calling AppiumDriver.click() with args: ["eyJrZXlWYWx1ZVR5cGUiOiJTdHJpbmciLCJrZXlWYWx1ZVN0cmluZyI6ImxvZ2luQnV0dG9uS2V5IiwiZmluZGVyVHlwZSI6IkJ5VmFsdWVLZXkifQ==","295e52a7-25ba-4481-847c-bf376f83d1c9"]
[debug] [FlutterDriver] Executing Flutter driver command 'click'
[debug] [FlutterDriver] >>> {"command":"tap","keyValueType":"String","keyValueString":"loginButtonKey","finderType":"ByValueKey"}
[HTTP] --> DELETE /session/295e52a7-25ba-4481-847c-bf376f83d1c9
[HTTP] {}
[debug] [FlutterDriver@dfc3 (295e52a7)] Calling AppiumDriver.deleteSession() with args: ["295e52a7-25ba-4481-847c-bf376f83d1c9"]
[debug] [AppiumDriver@9637] Event 'quitSessionRequested' logged at 1694021785152 (20:36:25 GMT+0300 (Eastern European Summer Time))
[AppiumDriver@9637] Removing session 295e52a7-25ba-4481-847c-bf376f83d1c9 from our master session list
[debug] [FlutterDriver] Deleting Flutter Driver session
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Deleting UiAutomator2 session
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Deleting UiAutomator2 server session
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Matched '/' to command name 'deleteSession'
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Proxying [DELETE /] to [DELETE http://127.0.0.1:8200/session/aada2717-4d8c-4ae5-bc23-c99906bbe92f] with no body
[debug] [AndroidUiautomator2Driver@151e (9767bba7)] Got response with status 200: {"sessionId":"aada2717-4d8c-4ae5-bc23-c99906bbe92f","value":null}
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell dumpsys activity services io.appium.settings/.recorder.RecorderService'
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell am force-stop com.my.app'
[HTTP] <-- POST /session/295e52a7-25ba-4481-847c-bf376f83d1c9/element/eyJrZXlWYWx1ZVR5cGUiOiJTdHJpbmciLCJrZXlWYWx1ZVN0cmluZyI6ImxvZ2luQnV0dG9uS2V5IiwiZmluZGVyVHlwZSI6IkJ5VmFsdWVLZXkifQ%3D%3D/click - - ms - -
[HTTP]
[FlutterDriver] Connection to ws://127.0.0.1:46671/mb_QmkshrIw=/ws closed
[debug] [Logcat] Stopping logcat capture
[debug] [ADB] Removing forwarded port socket connection: 8200
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD forward --remove tcp:8200'
[AndroidUiautomator2Driver@151e (9767bba7)] Restoring hidden api policy to the device default configuration
[debug] [ADB] Running 'C:\Users\gg.georgiev\AppData\Local\Android\Sdk\platform-tools\adb.exe -P 5037 -s S4LJGA6HEIZLRCZD shell 'settings delete global hidden_api_policy_pre_p_apps;settings delete global hidden_api_policy_p_apps;settings delete global hidden_api_policy''
[debug] [AppiumDriver@9637] Event 'quitSessionFinished' logged at 1694021785577 (20:36:25 GMT+0300 (Eastern European Summer Time))
[debug] [AppiumDriver@9637] Received response: null
[debug] [AppiumDriver@9637] But deleting session, so not returning
[debug] [AppiumDriver@9637] Responding to client with driver.deleteSession() result: null
[HTTP] <-- DELETE /session/295e52a7-25ba-4481-847c-bf376f83d1c9 200 427 ms - 14
[HTTP]
[debug] [Instrumentation] .
[debug] [Instrumentation] Time: 622.158
[debug] [Instrumentation]
[debug] [Instrumentation] OK (1 test)
[debug] [Instrumentation] The process has exited with code 0

The interesting part of the log:

[debug] [FlutterDriver@dfc3 (295e52a7)] Calling AppiumDriver.click() with args: ["eyJrZXlWYWx1ZVR5cGUiOiJTdHJpbmciLCJrZXlWYWx1ZVN0cmluZyI6ImxvZ2luQnV0dG9uS2V5IiwiZmluZGVyVHlwZSI6IkJ5VmFsdWVLZXkifQ==","295e52a7-25ba-4481-847c-bf376f83d1c9"]
[debug] [FlutterDriver] Executing Flutter driver command 'click'
[debug] [FlutterDriver] >>> {"command":"tap","keyValueType":"String","keyValueString":"loginButtonKey","finderType":"ByValueKey"}
[HTTP] --> DELETE /session/295e52a7-25ba-4481-847c-bf376f83d1c9
[HTTP] {}
[debug] [FlutterDriver@dfc3 (295e52a7)] Calling AppiumDriver.deleteSession() with args: ["295e52a7-25ba-4481-847c-bf376f83d1c9"]
[debug] [AppiumDriver@9637] Event 'quitSessionRequested' logged at 1694021785152 (20:36:25 GMT+0300 (Eastern European Summer Time))

The click command is sent successfully, it looks good. The locator is 100% correct. But after the HTTP client timeout, the DELETE command is sent, because of the @AfterMethod cleanup.

I have few questions in general:

  1. Why the click command hangs - it doesn't throw "not found element", nor "unable to click" or something. It just hangs.
  2. Why do neither the keep-alive nor newCommandTimeout timeouts stop the execution? I need to wait 600 seconds for the HTTP client timeout. Is there a way to configure smaller timeout of the org.asynchttpclient.netty.request.NettyRequestSender?
KazuCocoa commented 1 year ago
  1. Such a thing could happen depending on the app under test
  2. org.asynchttpclient.netty.request.NettyRequestSender do you mean the Java client's timeout behavior to wait for the response by Appium? Maybe https://discuss.appium.io/ helps to ask such general questions
TripleG commented 1 year ago

After pulling my hair for hours I found the problem, but I have no logical explanation for it.

I put a breakpoint and paused the test before the click() and I decided to try send the click request with Postman. Here is what I found out:

This works POST 127.0.0.1:4723/session/793894ad-6acc-4005-bdc0-84682a231d7f/element/eyJmaW5kZXJUeXBlIjoiQnlWYWx1ZUtleSIsImtleVZhbHVlVHlwZSI6IlN0cmluZyIsImtleVZhbHVlU3RyaW5nIjoibG9nSW5CdXR0b25LZXkifQ%3D%3D/click

This does not work(it hangs as described) POST 127.0.0.1:4723/session/793894ad-6acc-4005-bdc0-84682a231d7f/element/eyJrZXlWYWx1ZVR5cGUiOiJTdHJpbmciLCJrZXlWYWx1ZVN0cmluZyI6ImxvZ2luQnV0dG9uS2V5IiwiZmluZGVyVHlwZSI6IkJ5VmFsdWVLZXkifQ%3D%3D/click

The difference between the two requests is the element_id part. Decoded values from Base64: Working - {"finderType":"ByValueKey","keyValueType":"String","keyValueString":"logInButtonKey"} Hanging - {"keyValueType":"String","keyValueString":"loginButtonKey","finderType":"ByValueKey"}

The attributes and values are exactly the same, but they are in different order.

I cannot even think of a reason why parsing a JSON would cause hanging/issue because of specific attributes order. Looks like a bug to me, but I am not sure where to open it.

@KazuCocoa Any thoughts and suggestions?

KazuCocoa commented 1 year ago

interesting... then potentially https://github.com/ashwithpoojary98/javaflutterfinder/blob/master/src/main/java/io/github/ashwith/flutter/FlutterFinder.java#L29-L48 ?

https://github.com/search?q=repo%3Aappium%2Fappium-flutter-driver%20keyValueType&type=code is possible relevant code in this repository.

Then, what about eyJmaW5kZXJUeXBlIjoiQnlWYWx1ZUtleSIsImtleVZhbHVlU3RyaW5nIjoibG9nSW5CdXR0b25LZXkiLCJrZXlWYWx1ZVR5cGUiOiJTdHJpbmcifQ==? (eyJmaW5kZXJUeXBlIjoiQnlWYWx1ZUtleSIsImtleVZhbHVlU3RyaW5nIjoibG9nSW5CdXR0b25LZXkiLCJrZXlWYWx1ZVR5cGUiOiJTdHJpbmcifQ%3D%3D as url encoded) {"finderType":"ByValueKey","keyValueString":"logInButtonKey","keyValueType":"String"}. This order is currently this driver's repository's generated base 64

TripleG commented 1 year ago

@KazuCocoa I just noticed that the attribute values are not the same. "keyValueString":"logInButtonKey" vs "keyValueString":"loginButtonKey". Notice the lower case i in login. So, this was the problem, not the attributes order.

BUT, another question arises - why the Flutter driver doesn't throw element not found, but hangs instead. Do you have any idea if I need to set some parameters to the appium server, or some options to give it timeout for searching for the element or something?

I tried to use uiAutomator2 just for the experiment and it returns 404 not found element after ~10 seconds. But the flutter driver just hangs if the element doesn't exist...

mkonev-casafari commented 1 year ago

Hey guys, I also faced with this problem... flutter driver stuck on executing any command on Dart VM side.... I assume that something wrong on Dart VM side but don't know how to get it's logs or any other helpful information

KazuCocoa commented 1 year ago

why the Flutter driver doesn't throw element not found, but hangs instead

This is because the current (original) implementation waits for the response by the DartVM, that's it. It looks like the original implementation's base design.

So like https://github.com/appium/appium-flutter-driver/issues/430 , each request perhaps can have timeout to the Dart VM to respond like no such element error in case no response by the Dart VM by the timeout. I'm not sure then also the Dart VM can accept another new request (e.g. the previous command blocks some Dart VM procedure), but maybe such timeout can be added. (PRs are welcome)

ashwithpoojary98 commented 1 year ago

@TripleG check your locator value.