No observatory URL matching error is seen even though the iPhone system log has Observatory URL.

[pothurajtharun]

Test Environment:

• Java 11 (temurin)
• Appium: 2.2.1
• flutter@2.2.0 [installed (npm)]
• xcuitest@5.8.0 (automationName 'XCUITest')
• iPhone 8 Plus (16.7.3)

Steps followed:

1. Start a session without app capability and session has been created successfully.
2. Install and launch the app with ios-deploy commands programmatically. (While execution is going on, in parallel i started observing the iPhone device log through Console app in Mac OS)
3. App has been launched successfully. The observatory URL has been displayed in iPhone system log at 10:06 pm IST (4:36 pm UTC) as per the attached screenshot.
4. Called the flutter:connectObservatoryWsUrl to identify the observatory URL at 10:07 pm IST(4:37 pm UTC)

Actual Output:
Even though there is an observatory URL in iPhone system log at 10:06 pm IST (4:36 pm UTC) , flutter:connectObservatoryWsUrl is failed to identify the observatory URL for 10 times and thrown the error at 10:08 pm IST(4:38 pm UTC)

- No observatory URL matching to '/(Observatory listening on |An Observatory debugger and profiler on\s.+\sis available at: |The Dart VM service is listening on )((http|\/\/)[a-zA-Z0-9:/=_\-.\[\]]+)/' was found in the device log. Please make sure the application under test is configured properly according to https://github.com/appium-userland/appium-flutter-driver#usage and that it does not crash on startup.

Attaching the full appium log: appium.log

Reproducibility: Some times.

[KazuCocoa]

What happens when you switch the step of launching the app with ios-deploy and flutter:connectObservatoryWsUrl? So, like the README, ios-deploy is just after calling flutter:connectObservatoryWsUrl

iii. Calls flutter:connectObservatoryWsUrl command to keep finding an observatory URL to the Dart VM
iv. (at the same time) Launch the application under test via outside the appium-flutter-driver

https://github.com/appium/appium-flutter-driver?tab=readme-ov-file#several-ways-to-start-an-application

[pothurajtharun]

@KazuCocoa , As mentioned the Step 3 here https://github.com/appium/appium-flutter-driver?tab=readme-ov-file#several-ways-to-start-an-application the code snippets I'm using are as follows.

Step 3.i I'm using the below code.

driver = new IOSDriver(remote, mobileCapabilities);  //Start a session without app capability.

Step 3.ii - 3.iv I'm using the below code, to install and launch the app using ios-deploy. (I'm not using driver.installApphere, because Observatory URL is printing in iPhone device log only after the app launch.)

ProcessBuilder processBuilder = new ProcessBuilder();
processBuilder.command(
        "ios-deploy",
        "--debug",
        "--justlaunch",
        "--bundle",
        "/usr/local/automation/MobileApps/ios/Payload/Runner.app");
run(processBuilder);
log.debug("App installed and launched successfully.");
     

Step 3.v After launching the app with ios-deploy I'm calling the flutter:connectObservatoryWsUrl as follows.

LOG.debug("Running flutter connectObservatoryWsUrl script after launching the app with ios-deploy.");
driver.executeScript("flutter:connectObservatoryWsUrl");

What happens when you switch the step of launching the app with ios-deploy and flutter:connectObservatoryWsUrl?

As I'm already covering your question, i faced the same error that No observatory URL matching error is seen even though the iPhone system log has Observatory URL

The main problem is that observatory URL is in iPhone device log but flutter:connectObservatoryWsUrl is unable to connect.

[KazuCocoa]

As I'm already covering your question, i faced the same error that No observatory URL matching error is seen even though the iPhone system log has Observatory URL

Then, could you share the Appium log and the system log? So the observatory url should present during the flutter:connectObservatoryWsUrl command execution.

The no observatory url error occurs when the url is logs outside the flutter command, appium fails to get the syslog, or the matching pattern has changed by the Flutter’s update

[pothurajtharun]

@KazuCocoa I have taken the iPhone system logs in two methods as follows during the test executions.

Method 1:

1. Connect the iPhone to the mac system.
2. Open the Console app.
3. Select the iPhone in left side bar.
4. Start collecting the logs once the test executions are triggered.

Method_1.log

Method 2:

1. Start the appium-flutter-driver session.
2. Collected the logs through driver.manage().logs().get("syslog");

Method_2.log

Only Method 1 iPhone syslog contains the Observatory URL. Method 2 iPhone syslog doesn't contain any Observatory URL.

So the question is, could you please let me know which iPhone system log is appium-flutter-driver reading to get the Observatory URL ?

[KazuCocoa]

Appium gets logs via com.apple.syslog_relay service https://github.com/appium/appium-ios-device/blob/5735774b79dffc7f2b4afa60cd8132e16a6385ca/lib/syslog/index.js#L7, thus this driver also depends on the result of the service. Past logs may not be in the result.

You could use idevicesyslog for example to check the same as well if the com.apple.syslog_relay service contains the observatory URL. https://github.com/libimobiledevice/libimobiledevice
Probably Flutter uses the idevicesyslog https://github.com/search?q=repo%3Aflutter%2Fflutter%20idevicesyslog&type=code as well, thus if com.apple.syslog_relay contains the URL in your case, theatrically Appium also can get the same one.

[pothurajtharun]

@KazuCocoa , During the app launch i tried to take the logs with idevicesyslog command as well along with previously mentioned two methods.

Method 1: [Console App Sys Log]

1.Connect the iPhone to the mac system.
2.Open the Console app.
3.Select the iPhone in left side bar.
4.Start collecting the logs once the test executions are triggered.

console_sys_log.log

Method 2: [Driver Sys Log]

1. Start the appium-flutter-driver session.
2. Collected the logs through driver.manage().logs().get("syslog");

driver_sys_log.log

Method 3: [idevicesyslog]

1. Start collecting the logs once the test executions are triggered with the following command.
   2. idevicesyslog > idevicelog.log

idevicesyslog.log

Method 1 & Method 3 sys logs has the observatory URL but still No observatory URL matching error is seen. Attached three sys logs and appium log for the same.

appium-port-4779.log

[KazuCocoa]

When did you start com.xyz.xyzenterprise in the Method 2? Could you start a session with "appium:showIOSLog": true in the Method 2 so that the Appium log can show when the app starts instead of collecting logs with driver.manage().logs().get("syslog");?

[pothurajtharun]

@KazuCocoa , I have started the session with "appium:showIOSLog": true as mentioned in the comment. Now the appium log has the observatory URL as part of iOSDeviceLog. But still driver is unable to connect to the printed observatory URL. The error message is now changed to the port is busy due to the latest changes here. When i check the port at the same time it is free and not occupied with any other process.

Attaching the appium log: appium-showIOSLog.log

[KazuCocoa]

For the busy port, probably it is by the previous port forward remained. It could be fixed by killing the port forward before the next attempt, but what weird thing was below first attempt's result. If the dart observatory url has been valid, The Dart VM service is listening on http://127.0.0.1:49775/LPGAC72v9K0=/, maybe the first attempt succeeded but did not, thus the following attempt got the busy port message. It could indicate even if we fix the port issue, it won't get succeeded.

This situation could happen when the connection was not established by the Dart VM side's something, or the local connection got something error. Trying to find something new.

2023-11-21 04:35:02:403 [FlutterDriver] Forwarding the remote port 49775 to the local port 49775
2023-11-21 04:35:02:542 [FlutterDriver] {}
2023-11-21 04:35:02:543 [FlutterDriver] Waiting 3000ms before retrying

[pothurajtharun]

@KazuCocoa Understood. Thanks for the quick look. Please let me know if you need anything to be tested to provide more info about the issue.

[KazuCocoa]

The busy port thing is perhaps ok with 2.2.3.

[pothurajtharun]

@KazuCocoa , I tried the latest version #2.2.3 and the port busy issue is fixed.

However i can see the error message Got an error while finding an observatory url. from Attempt #5 onwards. Does it mean first four attempts driver was matching the URL with this regx ?

Attached the log : appium.log

[KazuCocoa]

As below steps in https://github.com/appium/appium-flutter-driver?tab=readme-ov-file#several-ways-to-start-an-application , can you start the app under test after flutter:connectObservatoryWsUrl call?

3. Launch the app outside the driver: for users who want to manage the application under test by yourselves
   1. Start a session without app capability
   2. Install the application under test via driver.install_app or mobile:installApp command etc
   3. Calls flutter:connectObservatoryWsUrl command to keep finding an observatory URL to the Dart VM
      appium:retryBackoffTime and appium:maxRetryCount will control the duration to keep finding an observatory URL to the Dart VM
      - (at the same time) Launch the application under test via outside the appium-flutter-driver
   4. Once flutter:connectObservatoryWsUrl identify the observatory URL, the command will establish a connection to the Dart VM

Current timeline is below. Thus the flutter:connectObservatoryWsUrl was not able to get the observatory url logged before the flutter:connectObservatoryWsUrl procedure.

2023-11-23 10:40:04:131 [IOSDeviceLog] Nov 23 16:10:04 iPhone-8-Plus Runner(Flutter)[557] <Notice>: flutter: The Dart VM service is listening on http://127.0.0.1:50790/3yxZuS23YBI=/
...
2023-11-23 10:40:29:985 [HTTP] --> POST /session/bb173db0-a943-48c6-bc03-e15dd7dedff9/execute/sync
2023-11-23 10:40:29:985 [HTTP] {"script":"flutter:connectObservatoryWsUrl","args":[]}
2023-11-23 10:40:29:992 [FlutterDriver@0f3d (bb173db0)] Calling AppiumDriver.execute() with args: ["flutter:connectObservatoryWsUrl",[],"bb173db0-a943-48c6-bc03-e15dd7dedff9"]
2023-11-23 10:40:29:992 [FlutterDriver] Executing Flutter driver command 'execute'
2023-11-23 10:40:29:993 [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.
2023-11-23 10:40:29:993 [FlutterDriver] Attempt #1 of 10
2023-11-23 10:40:29:997 [FlutterDriver] Running on iOS real device