Lacking error reporting for "control not found" issues in v0.9.1

[laszlo-szentes]

Describe the bug Having been upgraded to wdi5 v0.9.10 (from 0.9.0-rcX), our integrations tests run in 20 minutes instead of 40 which is a big improvement (albeit it is still pretty slow). This is a welcome addition, thank you for that. However, what we have also noticed is that error reporting seems to have regressed in particular with regards to "control no found" issues where the console output seems to be lacking any details that would be helpful to pinpoint the offensive line in our codebase where the error comes from.

Issues

1. The error message is not detailed, it does not contain the locator/selector information about the control that was not found
2. The stack trace is virtually useless. It contains details about wdio-ui5-service internals, which has little value to us. On the other hand, it completely lacks our own code, which would actually be valuable.

That being said, with regards to point 1 above, there is some info about the offending control in the log prior to the error (the line is tagged with [wdi5]), however:

• this info is often filtered out in various systems, forcing us to dive into the entire log, otherwise all that remains is a totally nondescript and generic control could not be found error message
• and the stringified locator seems to be using some other (internal?) format than previous versions

wdi5 should report the when locator of the control that has not been found when the expectation fails, not (just) when the DOM element is not found by webdriver at the low level. See issue with negative tests below.

I don't remember any of these being an issue in previous versions. AFAIK, previous versions did report a clean locator alongside the error and also a valuable stack trace that included our sources (and omitted wdi5 sources).

Also, a related problem with this is that wdi5 cannot semantically distinguish between negative tests and genuine "control not found" errors. At low level both cases manifest themselves as the control not being able to be found. However, in the case of a negative test this is exactly what should happen, as the control is not expected to be found. Now we have heaps of "errors" reported in the log for each negative test making the log rather noisy. This, however, is another issue and is of lesser importance.

To Reproduce It's a general issue, really. Also, reporting does not seem to be consistent. Sometime we get slightly more information, some other time or in some other context none at all. It's also inconsistent across different types of errors. Errors other than "control not found" seem to include our own code in stack trace more or less. But error reporting in this new version is generally confusing and sub-par.

Expected behavior I expect, in the case of a "control not found" issue that an error is reported in the log that:

• includes full control selector/locator information
• and a stack trace that omits wdi5 internals and instead includes source locations from our own code

Logs/Console Output

control could not be found

and the stack trace:

Error: control could not be found
    at WDI5Control.<anonymous> (/data/jenkins/workspace/integration-tests/_random/laszlo-app-integration-tests/node_modules/wdio-ui5-service/dist/lib/wdi5-control.js:219:35)
    at step (/data/jenkins/workspace/integration-tests/_random/laszlo-app-integration-tests/node_modules/wdio-ui5-service/dist/lib/wdi5-control.js:56:23)
    at Object.next (/data/jenkins/workspace/integration-tests/_random/laszlo-app-integration-tests/node_modules/wdio-ui5-service/dist/lib/wdi5-control.js:37:53)
    at /data/jenkins/workspace/integration-tests/_random/laszlo-app-integration-tests/node_modules/wdio-ui5-service/dist/lib/wdi5-control.js:31:71
    at new Promise (<anonymous>)
    at __awaiter (/data/jenkins/workspace/integration-tests/_random/laszlo-app-integration-tests/node_modules/wdio-ui5-service/dist/lib/wdi5-control.js:27:12)
    at WDI5Control.renewWebElement (/data/jenkins/workspace/integration-tests/_random/laszlo-app-integration-tests/node_modules/wdio-ui5-service/dist/lib/wdi5-control.js:208:16)
    at WDI5Control.<anonymous> (/data/jenkins/workspace/integration-tests/_random/laszlo-app-integration-tests/node_modules/wdio-ui5-service/dist/lib/wdi5-control.js:185:51)
    at step (/data/jenkins/workspace/integration-tests/_random/laszlo-app-integration-tests/node_modules/wdio-ui5-service/dist/lib/wdi5-control.js:56:23)
    at Object.next (/data/jenkins/workspace/integration-tests/_random/laszlo-app-integration-tests/node_modules/wdio-ui5-service/dist/lib/wdi5-control.js:37:53)

Runtime Env (please complete the following information):

• wdi5/wdio-ui5-service-version: 0.9.10
• UI5 version: [e.g. 1.98.0]
• wdio-version (output of wdio --version): 7.20.9
• node-version (output of node --version): v16.13.0
• OS: Ubuntu on WSL
• Browser + Version: Google Chrome 103.0.5060.134

Additional context Reproducible in any environment

[Siolto]

Hi @laszlo-szentes ,

thanks for that detailed description and your feedback about using wdi5. With version 0.9.10 the biggest change were actually with our error messages and logging. To answer your points:

Full control selector/locator information in error cases:

How is your wdi5 logLevel configured? When you have at least error defined there should be the desired output.

wdio.conf.js:

wdi5: {
        logLevel: "error"
    },

example output when control was not found:

[0-0] [wdi5] call of _getControl() failed because of: Error: No DOM element found using the control selector {"id":"test","properties":{"text":"open Dialog"},"viewName":"test.Sample.view.Main","sOriginalControlType":"sap.m.Button"}
[0-0] [wdi5] error retrieving control: testtestSample.view.Mainsap.m.Button{"text":"open Dialog"}
[0-0] [wdi5] Can not call press(), because control could not be found
[0-0] TypeError in "Property locators.should find the 'open dialog' button by the text property"

Do you need additional output here?

Stack trace that omits wdi5 internals

Here we implemented a small bug when improving the error messages. When using the function getWebElement() on a control that is not found we raise an exception that is not catched. The stack trace you receive should never reach the user that is executing the script. This is something we should improve.

Do you often use the getWebElement function and can you maybe decrease the usage of that function for the time being by using native wdi5 functions like press() or enterText()?

Best regards, Simon

[laszlo-szentes]

Hi @Siolto, thank you for the prompt reply much appreciated.

Yes, the log level is configured to be error.

We do get the output regarding the selectors just not where we want it, let me explain it in the next post.

We do use getWebElement() to some degree but not excessively. We have an abstraction layer sitting between wdi5 and the test page and spec code, implementing some common assertion/action/locator/arrangement functionality per control type. The usage of getWebElement() is restricted to this layer, therefore any calls to it will not leak into the test code. Some examples of what it is being used for:

• positive and negative existence checks
• calling webdriver's element API, such as waitForEnabled etc. or doing a couple of more exotic selections
• moving keyboard focus to element

We do use native wdi5 functions as well, of course.

In the past getWebElement() returned null when the element was not found, now as you said it throws, so we can mitigate the incorrect stack trace issue by swallowing the exceptions thrown from getWebElement() in the common abstraction layer code so it won't be propagated further up and instead we can use expect to handle the issue and throw its own exception, this time with correct stack trace. For example:

async function exists (anyControl) {
  let anyElement = null
  try {
    anyElement = await anyControl.getWebElement()
  } catch (e) {
  }
  expect(anyElement).not.toBe(null)
  return anyElement
}

This takes us back where we were before the upgrade and leaves us with a not-so-useful error message Expected: not null but with a useful stack trace (which is more important for us than a more obvious error message but a useless trace).

[laszlo-szentes]

...Continued. So, the above solution sorta-kinda solves our biggest problem, but our other big gripe is, as I mentioned before, that we do get output like:

[0-0] [wdi5] call of _getControl() failed because of: Error: No DOM element found using the control selector {"id":"test","properties":{"text":"open Dialog"},"viewName":"test.Sample.view.Main","sOriginalControlType":"sap.m.Button"}
[0-0] [wdi5] error retrieving control: testtestSample.view.Mainsap.m.Button{"text":"open Dialog"}

in the log, just not where and when we want it.

The problem is that the control is immediately reported missing as soon as the locator promise is settled. However, we might have this kind of situation (i.e. that a control is not found) in a number of scenarios:

1. Positive existence check fails: A control is expected to be found but it wasn't
2. Negative existence check passes: A control is not expected to be found and it is wasn't
3. Conditional branch based on existence takes negative path: We want to do different things depending on whether the control exists or not. Note that, we do not set any expectation whether the control should or should not exist.

For us, only case 1 is considered to be an error, cases 2-3, when the expectation was met or there was not expectation at all, are not. And in such cases we would rather not see these control not found messages at all. However, for now, this is not the case and our log is littered with hundreds of such false errors that have zero added value and just pollute the log. This is another reason (apart from the log simply being enormous) why practically nobody in our team is looking at the full log.

Which takes us to our next point: I mentioned that it would be nice if the actual error message would also contain the locator information. Currently it doesn't. The error is simply: control could not be found. That's it. I am aware that the locator for the missing control is reported in the log, however:

• it is reported in many other contexts too, when we don't actually want it to be reported (see above)
• it is not part of the actual error message, it's a separate entry before the error

Why this latter is important is because it is the error message (and its corresponding stack trace) that gets picked up by the jUnit reporter and the report is then used to display structured test results in Blue Ocean in Jenkins. Again, with several hundreds of test cases practically no one looks at the log. We need a better reporting mechanism than that.

What we would like to see:

• have the stack trace fixed for control not found exceptions
• an option to turn off reporting of each and every instance when a control could not be found (at the time of settling the locator promise)
• reporting the locator in case of a control not found exception when it is allowed to bubble to the surface (i.e. when we call getWebElement() on a non-existing control without swallowing the exception)

[Siolto]

@laszlo-szentes again thanks for the context and the detailed explanation with your issues about using wdi5.

Regarding the error message: Perhaps I have expressed myself a little misleadingly but that error message you are getting since 0.9.10 (control could not be found) shouldn't be there at all. There should be another entry in the log. Something like Can not call "getWebElement()", because control could not be found but nothing like an exception you have to catch. A fix for that is in the making.

Checking that controls/elements are not visible: Maybe the native wdi5 function isInitialized can help you here. This function will return true or false depending on whether the element was found in the DOM or not. So you could write something like that:

const oControl = await browser.asControl(controlSelector)
expect(await oControl.isInitialized()).toBeFalsy()

Turn the reporting on/off for specific cases: We think this is a good idea and your use case is a perfect example for that. We would add another optional property to the selector which specifically turns the logging off:

const button = browser.asControl({
    logging: false, // naming not final
    selector: {
        ...
    }
})

We will add this on our roadmap and see who could contribute that.

Regards, Simon