search

webdriverio / webdriverio

Next-gen browser and mobile automation test framework for Node.js
http://webdriver.io
MIT License
9.1k stars 2.52k forks source link

[🐛 Bug]: Command `isElementEnabled` returning error 'stale element reference' does not call the `onAfterCommand` #13921

Closed dprevost-LMI closed 1 day ago

dprevost-LMI commented 6 days ago

Have you read the Contributing Guidelines on issues?

WebdriverIO Version

9.3.1

Node.js Version

v18.20.4

Mode

WDIO Testrunner

Which capabilities are you using?

Config {
  "runner": "local",
  "waitforTimeout": 5000,
  "connectionRetryTimeout": 10000,
  "connectionRetryCount": 3,
  "framework": "mocha",
  "specs": [
    "../../src/tests/**/*.test.ts"
  ],
  "mochaOpts": {
    "ui": "bdd",
    "timeout": 240000,
    "retries": 0
  },
  "reporters": [
    [
      "allure",
      {
        "outputDir": "logs/allure-results",
        "addConsoleLogs": true
      }
    ],
    [
      "spec",
      {
        "showPreface": false,
        "realtimeReporting": false
      }
    ]
  ],
  "services": [
    [
      "appium",
      {
        "args": {
          "port": 4723,
          "relaxedSecurity": true,
          "log": "./logs/appium.log",
          "logFilters": "./appiumPasswordLogFilters.json"
        }
      }
    ]
  ],
  "capabilities": [
    {
      "platformName": "Android",
      "appium:udid": "masked",
      "appium:automationName": "UiAutomator2",
      "appium:appPackage": "com.my.package",
      "appium:appActivity": "MainActivity",
      "appium:newCommandTimeout": 240,
      "appium:noReset": true,
      "goto:caps": {
        "isLocalRun": true,
        "iosEnterpriseBuild": false,
        "testUserEmail": "",
        "isDevMode": true
      },
      "appium:settings[allowInvisibleElements]": true,
      "appium:locale": "en_US",
      "appium:language": ""
    }
  ]

What happened?

One line: Some afterCommand events are not triggered when a request fails!

In short, the problem is that we do not have the same number of calls to the beforeCommand and afterCommand. For example, the allure-reporter starts more steps than it can end, which generates a weird report and can even make the generation step hang!

The problem is related to the GET request of isElementEnabled, which returned a 404 with the error stale element reference (See log below). In this case, it throws an error here so the then of the request.makeRequest here will not proceed and will not do the required emit('result') that trigger the afterCommand. In consequence, we will lose a endStephave a different

What is your expected behavior?

All beforeCommand trigger a equivalent afterCommand even when a request fails!

In short, I assume that the request.makeRequest here needs a catch that will do the this.emit('result' for the afterCommand to get triggered.

However, doing so will result in an error that people may not expect, so I wonder about the impact.

Anyway, I added the below catch for fun, finally making all the startStep and endStep even.

.catch((err) => {
      log4.error("ERROR", err);
      this.emit("result", { command, method, endpoint, body, result: { error: err } });
      throw err;
    });

If someone can guide me on the proper changes, I can try to open a PR. The options I'm seeing:

  1. Add the catch and emit the error as a result
  2. Remove the throws so the then can trigger correctly
  3. Implement a new emit('error') that would also trigger a newafterCommandError that would end steps in error and so fix the problem without sending an unexpected error result

How to reproduce the bug.

I have not yet found a way to reduce my example so that it can be shared. I'll try soon to share reproducible bug!

Relevant log output

beforeCommand {
  command: 'isElementEnabled',
  method: 'GET',
  endpoint: '/session/:sessionId/element/00000000-0000-1bac-0000-12a400000c98/enabled',
  body: {}
}
response {
  statusCode: 404,
  body: {
    value: {
      error: 'stale element reference',
      message: 'androidx.test.uiautomator.StaleObjectException',
      stacktrace: 'io.appium.uiautomator2.common.exceptions.StaleElementReferenceException: androidx.test.uiautomator.StaleObjectException\n' +
        '\tat io.appium.uiautomator2.handler.request.SafeRequestHandler.handle(SafeRequestHandler.java:63)\n' +
        '\tat io.appium.uiautomator2.server.AppiumServlet.handleRequest(AppiumServlet.java:259)\n' +
        '\tat io.appium.uiautomator2.server.AppiumServlet.handleHttpRequest(AppiumServlet.java:253)\n' +
        '\tat io.appium.uiautomator2.http.ServerHandler.channelRead(ServerHandler.java:77)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:366)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:352)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:345)\n' +
        '\tat io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:366)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:352)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:345)\n' +
        '\tat io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:435)\n' +
        '\tat io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:293)\n' +
        '\tat io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:267)\n' +
        '\tat io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:250)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:366)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:352)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:345)\n' +
        '\tat io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:266)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:366)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:352)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:345)\n' +
        '\tat io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1294)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:366)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:352)\n' +
        '\tat io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:911)\n' +
        '\tat io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)\n' +
        '\tat io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:611)\n' +
        '\tat io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:552)\n' +
        '\tat io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:466)\n' +
        '\tat io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:438)\n' +
        '\tat io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:140)\n' +
        '\tat io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)\n' +
        '\tat java.lang.Thread.run(Thread.java:1012)\n' +
        'Caused by: androidx.test.uiautomator.StaleObjectException\n' +
        '\tat androidx.test.uiautomator.UiObject2.getAccessibilityNodeInfo(UiObject2.java:1018)\n' +
        '\tat androidx.test.uiautomator.UiObject2.isEnabled(UiObject2.java:450)\n' +
        '\tat io.appium.uiautomator2.model.UiObject2Element.getAttribute(UiObject2Element.java:100)\n' +
        '\tat io.appium.uiautomator2.handler.GetElementAttribute.safeHandle(GetElementAttribute.java:24)\n' +
        '\tat io.appium.uiautomator2.handler.request.SafeRequestHandler.handle(SafeRequestHandler.java:59)\n' +
        '\t... 33 more\n'
    }
  }
}
beforeCommand {
  command: 'findElement',
  method: 'POST',
  endpoint: '/session/:sessionId/element',
  body: { using: 'xpath', value: '//android.widget.EditText' }
}
response {
  statusCode: 200,
  body: {
    value: {
      'element-6066-11e4-a52e-4f735466cecf': '00000000-0000-1bac-0000-130200000c98',
      ELEMENT: '00000000-0000-1bac-0000-130200000c98'
    }
  }
}
afterCommand {
  command: 'findElement',
  method: 'POST',
  endpoint: '/session/:sessionId/element',
  body: { using: 'xpath', value: '//android.widget.EditText' },
  result: {
    value: {
      'element-6066-11e4-a52e-4f735466cecf': '00000000-0000-1bac-0000-130200000c98',
      ELEMENT: '00000000-0000-1bac-0000-130200000c98'
    }
  }
}
Nb of steps missing end steps: 1
beforeCommand {
  command: 'isElementEnabled',
  method: 'GET',
  endpoint: '/session/:sessionId/element/00000000-0000-1bac-0000-12a400000c98/enabled',
  body: {}
}
response {
  statusCode: 404,
  body: {
    value: {
      error: 'stale element reference',
      message: "The element 'By.xpath: //android.widget.EditText' is not linked to the same object in DOM anymore",
      stacktrace: "io.appium.uiautomator2.common.exceptions.StaleElementReferenceException: The element 'By.xpath: //android.widget.EditText' is not linked to the same object in DOM anymore\n" +
        '\tat io.appium.uiautomator2.model.ElementsCache.restore(ElementsCache.java:122)\n' +
        '\tat io.appium.uiautomator2.model.ElementsCache.get(ElementsCache.java:153)\n' +
        '\tat io.appium.uiautomator2.handler.GetElementAttribute.safeHandle(GetElementAttribute.java:23)\n' +
        '\tat io.appium.uiautomator2.handler.request.SafeRequestHandler.handle(SafeRequestHandler.java:59)\n' +
        '\tat io.appium.uiautomator2.server.AppiumServlet.handleRequest(AppiumServlet.java:259)\n' +
        '\tat io.appium.uiautomator2.server.AppiumServlet.handleHttpRequest(AppiumServlet.java:253)\n' +
        '\tat io.appium.uiautomator2.http.ServerHandler.channelRead(ServerHandler.java:77)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:366)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:352)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:345)\n' +
        '\tat io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:366)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:352)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:345)\n' +
        '\tat io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:435)\n' +
        '\tat io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:293)\n' +
        '\tat io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:267)\n' +
        '\tat io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:250)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:366)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:352)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:345)\n' +
        '\tat io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:266)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:366)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:352)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:345)\n' +
        '\tat io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1294)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:366)\n' +
        '\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:352)\n' +
        '\tat io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:911)\n' +
        '\tat io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)\n' +
        '\tat io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:611)\n' +
        '\tat io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:552)\n' +
        '\tat io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:466)\n' +
        '\tat io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:438)\n' +
        '\tat io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:140)\n' +
        '\tat io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)\n' +
        '\tat java.lang.Thread.run(Thread.java:1012)\n'
    }
  }
}
isElementEnabled
beforeCommand {
  command: 'isElementEnabled',
  method: 'GET',
  endpoint: '/session/:sessionId/element/00000000-0000-1bac-0000-130200000c98/enabled',
  body: {}
}
response { statusCode: 200, body: { value: true } }
afterCommand {
  command: 'isElementEnabled',
  method: 'GET',
  endpoint: '/session/:sessionId/element/00000000-0000-1bac-0000-130200000c98/enabled',
  body: {},
  result: { value: true }
}
Nb of steps missing end steps: 2
Starting test:  "before all" hook for given an authenticated user @smoke @androidOnly
Starting test:  should navigate back @smoke
Starting test:  should navigate back @smoke
Test
beforeCommand {
  command: 'terminateApp',
  method: 'POST',
  endpoint: '/session/:sessionId/appium/device/terminate_app',
  body: { appId: 'com.my.package' }
}
response { statusCode: 200, body: { value: true } }
afterCommand {
  command: 'terminateApp',
  method: 'POST',
  endpoint: '/session/:sessionId/appium/device/terminate_app',
  body: { appId: 'com.my.packaget' },
  result: { value: true }
}
Nb of steps missing end steps: 2

Code of Conduct

Is there an existing issue for this?

dprevost-LMI commented 2 days ago

FYI: Will be fixed when https://github.com/webdriverio/webdriverio/pull/13922 is merged

wdio-bot commented 1 day ago

Thanks for reporting!

We greatly appreciate any contributions that help resolve the bug. While we understand that active contributors have their own priorities, we kindly request your assistance if you rely on this bug being fixed. We encourage you to take a look at our contribution guidelines or join our friendly Discord development server, where you can ask any questions you may have. Thank you for your support, and cheers!