この記事は、Selenium/Appium Advent Calendar 2019の9日目の記事です。

環境

MacBookPro - macOS Mojave 10.14.6
Appium for Mac バージョン 1.15.1

経緯

Mac miniなどにJenkinsを入れてアプリのビルド環境を作り、そこにAppiumを入れてCI連携し、ビルド後に簡単なアプリテストをやりたいため、本格的にAppiumを使い始めました。そこで日々知見が溜まっているため、今回はとあるバグについてまとめます。

目的

ビルドしたアプリファイルをシミュレータに入れてアプリを実行させる。

問題

Appium for Macアプリから以下の設定を行い実行してみると次のエラーが表示されました。
まず成功体験を得るために、空のプロジェクトを作っただけのアプリを入れて開こうとしています。

[HTTP] --> POST /wd/hub/session
[HTTP] {"desiredCapabilities":{"app":"/Users/gremito/Xcode/AppiumTestApp/build/Build/Products/Debug-iphonesimulator/AppiumTestApp.app","automationName":"XCUITest","bundledId":"net.gremito.app.AppiumTestApp","deviceName":"iPhone 11","platformName":"iOS","platformVersion":"13.2","newCommandTimeout":0,"connectHardwareKeyboard":true}}
[MJSONWP] Calling AppiumDriver.createSession() with args: [{"app":"/Users/gremito/Xcode/AppiumTestApp/build/Build/Products/Debug-iphonesimulator/AppiumTestApp.app","automationName":"XCUITest","bundledId":"net.gremito.app.AppiumTestApp","deviceName":"iPhone 11","platformName":"iOS","platformVersion":"13.2","newCommandTimeout":0,"connectHardwareKeyboard":true},null,null]
[BaseDriver] Event 'newSessionRequested' logged at 1576129927063 (14:52:07 GMT+0900 (JST))
[BaseDriver] Event 'newSessionStarted' logged at 1576129927071 (14:52:07 GMT+0900 (JST))
[MJSONWP] Encountered internal error running command: Error: Could not find a driver for automationName 'XCUITest' and platformName 'iOS'. Please check your desired capabilities.
[MJSONWP]     at AppiumDriver.getDriverAndVersionForCaps (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/lib/appium.js:226:11)
[MJSONWP]     at AppiumDriver.getDriverAndVersionForCaps [as createSession] (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/lib/appium.js:300:66)
[MJSONWP]     at AppiumDriver.executeCommand (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/appium-base-driver/lib/basedriver/driver.js:376:19)
[MJSONWP]     at AppiumDriver.executeCommand (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/lib/appium.js:482:26)
[MJSONWP]     at executeCommand (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/appium-base-driver/lib/protocol/protocol.js:306:34)
[MJSONWP]     at asyncHandler (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/appium-base-driver/lib/protocol/protocol.js:432:15)
[MJSONWP]     at Layer.handle [as handle_request] (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/layer.js:95:5)
[MJSONWP]     at next (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/route.js:137:13)
[MJSONWP]     at Route.dispatch (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/route.js:112:3)
[MJSONWP]     at Layer.handle [as handle_request] (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/layer.js:95:5)
[MJSONWP]     at /Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:281:22
[MJSONWP]     at Function.process_params (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:335:12)
[MJSONWP]     at next (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:275:10)
[MJSONWP]     at logger (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/morgan/index.js:144:5)
[MJSONWP]     at Layer.handle [as handle_request] (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/layer.js:95:5)
[MJSONWP]     at trim_prefix (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:317:13)
[MJSONWP]     at /Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:284:7
[MJSONWP]     at Function.process_params (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:335:12)
[MJSONWP]     at next (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:275:10)
[MJSONWP]     at /Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/body-parser/lib/read.js:130:5
[MJSONWP]     at invokeCallback (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/raw-body/index.js:224:16)
[MJSONWP]     at done (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/raw-body/index.js:213:7)
[MJSONWP]     at IncomingMessage.onEnd (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/raw-body/index.js:273:7)
[MJSONWP]     at IncomingMessage.emit (events.js:182:13)
[MJSONWP]     at endReadableNT (_stream_readable.js:1090:12)
[MJSONWP]     at process._tickCallback (internal/process/next_tick.js:63:19)
[HTTP] <-- POST /wd/hub/session 500 12 ms - 254
[HTTP] 
[HTTP] --> DELETE /wd/hub/session
[HTTP] {}
[HTTP] No route found. Setting content type to 'text/plain'
[HTTP] <-- DELETE /wd/hub/session 404 0 ms - 57
[HTTP]

調査

上記のエラー内容と全く同じ現象がissuesにあったものの参考程度にしかなりませんでした。

Could not find a driver for automationName 'XCUItest' and platformName 'iOS' #13070

再起動

Appiumを再起動して再度実行してみました。
すると起動して少しするとアプリが強制終了するようになり全く機能しなくなりました。

すでにAndroidでは、同じように空のプロジェクトを作ってサンプルアプリを使いAppiumを実行して成功していました。
そのため一度Androidを実行させ、再度iOSを実行してみると再び先ほどの上記エラーが出るようになりアプリの強制終了は止まりました。
ですが、また再起動してiOSから実行すると強制終了するのでものすごく不安定です笑汗

`appium-doctor`

ちなみにappium-doctorすると以下のような状況でした。
今回のエラーには関係ないと思うものの念のため × を無くすも状況変わらず。

$ appium-doctor
info AppiumDoctor Appium Doctor v.1.12.1
info AppiumDoctor ### Diagnostic for necessary dependencies starting ###
info AppiumDoctor  ✔ The Node.js binary was found at: /usr/local/bin/node
info AppiumDoctor  ✔ Node version is 12.13.1
info AppiumDoctor  ✔ Xcode is installed at: /Applications/Xcode.app/Contents/Developer
info AppiumDoctor  ✔ Xcode Command Line Tools are installed in: /Applications/Xcode.app/Contents/Developer
info AppiumDoctor  ✔ DevToolsSecurity is enabled.
info AppiumDoctor  ✔ The Authorization DB is set up properly.
info AppiumDoctor  ✔ Carthage was found at: /usr/local/bin/carthage. Installed version is: 0.34.0
info AppiumDoctor  ✔ HOME is set to: /Users/gremito
info AppiumDoctor  ✔ ANDROID_HOME is set to: /Users/gremito/Library/Android/sdk
info AppiumDoctor  ✔ JAVA_HOME is set to: /Library/Java/JavaVirtualMachines/jdk-13.0.1.jdk/Contents/Home
info AppiumDoctor  ✔ adb exists at: /Users/gremito/Library/Android/sdk/platform-tools/adb
info AppiumDoctor  ✔ android exists at: /Users/gremito/Library/Android/sdk/tools/android
info AppiumDoctor  ✔ emulator exists at: /Users/gremito/Library/Android/sdk/tools/emulator
info AppiumDoctor  ✔ Bin directory of $JAVA_HOME is set
info AppiumDoctor ### Diagnostic for necessary dependencies completed, no fix needed. ###
info AppiumDoctor 
info AppiumDoctor ### Diagnostic for optional dependencies starting ###
info AppiumDoctor  ✔ opencv4nodejs is installed at: /usr/local/lib. Installed version is: 5.5.0
info AppiumDoctor  ✔ ffmpeg is installed at: /usr/local/bin/ffmpeg. ffmpeg version 4.2.1 Copyright (c) 2000-2019 the FFmpeg developers
WARN AppiumDoctor  ✖ mjpeg-consumer cannot be found.
info AppiumDoctor  ✔ idb and idb_companion are installed
info AppiumDoctor  ✔ applesimutils is installed at: /usr/local/bin/applesimutils. Installed versions are: applesimutils HEAD-ca1f4b3
WARN AppiumDoctor  ✖ bundletool.jar cannot be found
info AppiumDoctor ### Diagnostic for optional dependencies completed, 2 fixes possible. ###
info AppiumDoctor 
info AppiumDoctor ### Optional Manual Fixes ###
info AppiumDoctor The configuration can install optionally. Please do the following manually:
WARN AppiumDoctor  ➜ mjpeg-consumer module is required to use MJPEG-over-HTTP features. Please install it with 'npm i -g mjpeg-consumer'.
WARN AppiumDoctor  ➜ bundletool.jar is used to handle Android App Bundle. Please read http://appium.io/docs/en/writing-running-appium/android/android-appbundle/ to install it
info AppiumDoctor 
info AppiumDoctor ###
info AppiumDoctor 
info AppiumDoctor Bye! Run appium-doctor again when all manual fixes have been applied!
info AppiumDoctor

調査

元々は開発/運用しているアプリに対してAppiumを連携させたかったのですが上手く連携せず、そのため新規作成後のサンプルアプリを用いてAppium連携させても上記のエラーが発生したことが経緯でした。

去年のアドカレで @devnokiyo さんが書かれた『AppiumでiOS/Androidアプリの自動テストを試した〜Appiumをインストールして自作サンプルアプリをなんとか動かすまで〜』で作られているデモアプリのdevnokiyo/AppiumDemoを試したところ、Androidは上手く動作しましたが、以下のログのようにiOSがシミュレータの起動だけでその後すぐにappiumが落ちました。

$ appium
[Appium] Welcome to Appium v1.15.1
[Appium] Appium REST http interface listener started on 0.0.0.0:4723
[HTTP] --> POST /wd/hub/session
[HTTP] {"desiredCapabilities":{"platformName":"iOS","platformVersion":"13.2","deviceName":"iPhone Simulator","automationName":"XCUITest","app":"/Users/gremito/appium/AppiumDemo/SampleApp/AppiumDemo.app"},"capabilities":{"firstMatch":[{"platformName":"iOS","appium:platformVersion":"13.2","appium:deviceName":"iPhone Simulator","appium:automationName":"XCUITest","appium:app":"/Users/gremito/appium/AppiumDemo/SampleApp/AppiumDemo.app"}]}}
[debug] [W3C] Calling AppiumDriver.createSession() with args: [{"platformName":"iOS","platformVersion":"13.2","deviceName":"iPhone Simulator","automationName":"XCUITest","app":"/Users/gremito/appium/AppiumDemo/SampleApp/AppiumDemo.app"},null,{"firstMatch":[{"platformName":"iOS","appium:platformVersion":"13.2","appium:deviceName":"iPhone Simulator","appium:automationName":"XCUITest","appium:app":"/Users/gremito/appium/AppiumDemo/SampleApp/AppiumDemo.app"}]}]
[debug] [BaseDriver] Event 'newSessionRequested' logged at 1576208518883 (12:41:58 GMT+0900 (GMT+09:00))
[Appium] Appium v1.15.1 creating new XCUITestDriver (v2.133.1) session
[debug] [BaseDriver] W3C capabilities and MJSONWP desired capabilities were provided
[debug] [BaseDriver] Creating session with W3C capabilities: {
[debug] [BaseDriver]   "alwaysMatch": {
[debug] [BaseDriver]     "platformName": "iOS",
[debug] [BaseDriver]     "appium:platformVersion": "13.2",
[debug] [BaseDriver]     "appium:deviceName": "iPhone Simulator",
[debug] [BaseDriver]     "appium:automationName": "XCUITest",
[debug] [BaseDriver]     "appium:app": "/Users/gremito/appium/AppiumDemo/SampleApp/AppiumDemo.app"
[debug] [BaseDriver]   },
[debug] [BaseDriver]   "firstMatch": [
[debug] [BaseDriver]     {}
[debug] [BaseDriver]   ]
[debug] [BaseDriver] }
[BaseDriver] Session created with session id: 639a858d-28b9-4b40-8024-4633139a6135
[debug] [XCUITest] Current user: 'gremito'
[debug] [XCUITest] Changing deviceName from 'iPhone Simulator' to 'iPhone X'
[XCUITest] iOS SDK Version set to '13.2'
[XCUITest] Simulator udid not provided
[XCUITest] Using desired caps to create a new simulator
[debug] [simctl] Creating simulator with name 'appiumTest-C8A83FE9-BEFE-4FC8-BCFD-C7F99D80C63C-iPhone X', device type id 'iPhone X' and runtime id 'com.apple.CoreSimulator.SimRuntime.iOS-13-2'
[iOSSim] Constructing iOS simulator for Xcode version 11.2 with udid '7040357D-66BF-40B9-B5BB-EE693A7A4CBA'
[XCUITest] Created simulator with udid '7040357D-66BF-40B9-B5BB-EE693A7A4CBA'.
[XCUITest] Determining device to run tests on: udid: '7040357D-66BF-40B9-B5BB-EE693A7A4CBA', real device: false
[debug] [BaseDriver] Event 'xcodeDetailsRetrieved' logged at 1576208519748 (12:41:59 GMT+0900 (GMT+09:00))
[BaseDriver] Using local app '/Users/gremito/appium/AppiumDemo/SampleApp/AppiumDemo.app'
[debug] [BaseDriver] Event 'appConfigured' logged at 1576208519751 (12:41:59 GMT+0900 (GMT+09:00))
[debug] [XCUITest] Checking whether app '/Users/gremito/appium/AppiumDemo/SampleApp/AppiumDemo.app' is actually present on file system
[debug] [XCUITest] App is present
[debug] [iOS] Getting bundle ID from app '/Users/gremito/appium/AppiumDemo/SampleApp/AppiumDemo.app': 'devnokiyo.AppiumDemo'
[debug] [BaseDriver] Event 'resetStarted' logged at 1576208519753 (12:41:59 GMT+0900 (GMT+09:00))
[XCUITest] Not scrubbing third party app in anticipation of uninstall
[debug] [BaseDriver] Event 'resetComplete' logged at 1576208519830 (12:41:59 GMT+0900 (GMT+09:00))
[XCUITest] Continuing without capturing device logs: iOS Simulator with udid 7040357D-66BF-40B9-B5BB-EE693A7A4CBA is not running
[XCUITest] Setting up simulator
[debug] [iOS] No reason to set locale
[debug] [iOS] No iOS / app preferences to set
[debug] [iOS] Setting did not need to be updated
[debug] [iOSSim] Setting preferences of 7040357D-66BF-40B9-B5BB-EE693A7A4CBA Simulator to {"ConnectHardwareKeyboard":false}
[debug] [iOSSim] Setting common Simulator preferences to {"RotateWindowWhenSignaledByGuest":true,"ConnectHardwareKeyboard":false}
[debug] [iOSSim] Updated 7040357D-66BF-40B9-B5BB-EE693A7A4CBA Simulator preferences at '/Users/gremito/Library/Preferences/com.apple.iphonesimulator.plist' with {"DevicePreferences":{"7040357D-66BF-40B9-B5BB-EE693A7A4CBA":{"ConnectHardwareKeyboard":false}},"RotateWindowWhenSignaledByGuest":true,"ConnectHardwareKeyboard":false}
[iOSSim] Booting Simulator with UDID 7040357D-66BF-40B9-B5BB-EE693A7A4CBA...
[iOSSim] Starting Simulator UI with command: open -Fn /Applications/Xcode.app/Contents/Developer/Applications/Simulator.app --args -CurrentDeviceUDID 7040357D-66BF-40B9-B5BB-EE693A7A4CBA -ConnectHardwareKeyboard 0
[iOSSim] Simulator with UDID 7040357D-66BF-40B9-B5BB-EE693A7A4CBA booted in 19 seconds
[debug] [IDB] Connecting idb service to '7040357D-66BF-40B9-B5BB-EE693A7A4CBA'
[debug] [IDB] Disconnecting idb service from '7040357D-66BF-40B9-B5BB-EE693A7A4CBA'
[Appium] Received SIGTERM - shutting down
[debug] [IDB] idb daemon started on port 9889
[debug] [IDB] Could not connect to 7040357D-66BF-40B9-B5BB-EE693A7A4CBA:None.
[debug] [IDB]             Make sure both host and port are correct and reachable
[debug] [IDB] 
[debug] [IDB] Disconnecting idb service from '7040357D-66BF-40B9-B5BB-EE693A7A4CBA'
Terminated: 15
$

また、@Kazu_cocoa さんからアドバイスをいただきいくつか試したところ、safariすら起動しなかったため、サンプルアプリよりも既存アプリに対してAppiumが連携できるのかを調査していくことにしました。

解決方法

既存アプリを起動する方針に入る前に上記エラーの

[debug] [IDB] Could not connect to 7040357D-66BF-40B9-B5BB-EE693A7A4CBA:None.
[debug] [IDB] Make sure both host and port are correct and reachable

が気になったため先にidb環境を見直すことにしました。
エラーでググると @Kazu_cocoa さんも会話されているAppium can't run IOS simulator, others can #13599を見つけ参考にしてみることに。

このisuue上では、idbとidb_companionをアンインストールする会話があります。
ただ、idbを消すとCI環境内でコマンドを扱っているため、idb_companionだけ消して再度devnokiyo/AppiumDemoのiOSテストを試したところ、、、やっとiOSとAppiumの連携ができました笑汗

$ which idb
/Library/Frameworks/Python.framework/Versions/3.8/bin/idb
$ which idb_companion
/usr/local/bin/idb_companion
$ which fb-idb
$ pip3 install fb-idb
Requirement already satisfied: fb-idb in /Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages (0.0.7)
Requirement already satisfied: protobuf in /Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages (from fb-idb) (3.11.0)
Requirement already satisfied: aiofiles in /Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages (from fb-idb) (0.4.0)
Requirement already satisfied: grpclib in /Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages (from fb-idb) (0.3.1)
Requirement already satisfied: setuptools in /Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages (from protobuf->fb-idb) (41.2.0)
Requirement already satisfied: six>=1.9 in /Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages (from protobuf->fb-idb) (1.13.0)
Requirement already satisfied: h2 in /Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages (from grpclib->fb-idb) (3.1.1)
Requirement already satisfied: multidict in /Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages (from grpclib->fb-idb) (4.6.1)
Requirement already satisfied: hpack<4,>=2.3 in /Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages (from h2->grpclib->fb-idb) (3.0.0)
Requirement already satisfied: hyperframe<6,>=5.2.0 in /Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages (from h2->grpclib->fb-idb) (5.2.0)
WARNING: You are using pip version 19.2.3, however version 19.3.1 is available.
You should consider upgrading via the 'pip install --upgrade pip' command.

$ brew uninstall idb-companion
$ which idb_companion
$

appiumログ

ただ、ログ上を見ると

[XCUITest] idb will not be used for Simulator interaction. Original error: 'idb_companion' has not been found in PATH. Is it installed? Read https://www.fbidb.io for more details

とエラーが出ていますが、次のように最後までテストが行われました、、笑

$ appium
[Appium] Welcome to Appium v1.15.1
[Appium] Appium REST http interface listener started on 0.0.0.0:4723
[HTTP] --> POST /wd/hub/session
[HTTP] {"desiredCapabilities":{"platformName":"iOS","platformVersion":"13.2","deviceName":"iPhone Simulator","automationName":"XCUITest","app":"/Users/gremito/appium/AppiumDemo/SampleApp/AppiumDemo.app"},"capabilities":{"firstMatch":[{"platformName":"iOS","appium:platformVersion":"13.2","appium:deviceName":"iPhone Simulator","appium:automationName":"XCUITest","appium:app":"/Users/gremito/appium/AppiumDemo/SampleApp/AppiumDemo.app"}]}}
[debug] [W3C] Calling AppiumDriver.createSession() with args: [{"platformName":"iOS","platformVersion":"13.2","deviceName":"iPhone Simulator","automationName":"XCUITest","app":"/Users/gremito/appium/AppiumDemo/SampleApp/AppiumDemo.app"},null,{"firstMatch":[{"platformName":"iOS","appium:platformVersion":"13.2","appium:deviceName":"iPhone Simulator","appium:automationName":"XCUITest","appium:app":"/Users/gremito/appium/AppiumDemo/SampleApp/AppiumDemo.app"}]}]
[debug] [BaseDriver] Event 'newSessionRequested' logged at 1576213801400 (14:10:01 GMT+0900 (GMT+09:00))
[Appium] Appium v1.15.1 creating new XCUITestDriver (v2.133.1) session
[debug] [BaseDriver] W3C capabilities and MJSONWP desired capabilities were provided
[debug] [BaseDriver] Creating session with W3C capabilities: {
[debug] [BaseDriver]   "alwaysMatch": {
[debug] [BaseDriver]     "platformName": "iOS",
[debug] [BaseDriver]     "appium:platformVersion": "13.2",
[debug] [BaseDriver]     "appium:deviceName": "iPhone Simulator",
[debug] [BaseDriver]     "appium:automationName": "XCUITest",
[debug] [BaseDriver]     "appium:app": "/Users/gremito/appium/AppiumDemo/SampleApp/AppiumDemo.app"
[debug] [BaseDriver]   },
[debug] [BaseDriver]   "firstMatch": [
[debug] [BaseDriver]     {}
[debug] [BaseDriver]   ]
[debug] [BaseDriver] }
[BaseDriver] Session created with session id: 397fd4d4-6181-4dea-8617-48bd8c26509e
[debug] [XCUITest] Current user: 'gremito'
[debug] [XCUITest] Changing deviceName from 'iPhone Simulator' to 'iPhone X'
[XCUITest] iOS SDK Version set to '13.2'
[XCUITest] Simulator udid not provided
[XCUITest] Using desired caps to create a new simulator
[debug] [simctl] Creating simulator with name 'appiumTest-405FD3A5-1476-483E-84E8-BEF70B54FCEB-iPhone X', device type id 'iPhone X' and runtime id 'com.apple.CoreSimulator.SimRuntime.iOS-13-2'
[iOSSim] Constructing iOS simulator for Xcode version 11.2 with udid 'C21A6141-57DA-4DAF-91D6-EBF2ED2F5588'
[XCUITest] Created simulator with udid 'C21A6141-57DA-4DAF-91D6-EBF2ED2F5588'.
[XCUITest] Determining device to run tests on: udid: 'C21A6141-57DA-4DAF-91D6-EBF2ED2F5588', real device: false
[debug] [BaseDriver] Event 'xcodeDetailsRetrieved' logged at 1576213802458 (14:10:02 GMT+0900 (GMT+09:00))
[BaseDriver] Using local app '/Users/gremito/appium/AppiumDemo/SampleApp/AppiumDemo.app'
[debug] [BaseDriver] Event 'appConfigured' logged at 1576213802461 (14:10:02 GMT+0900 (GMT+09:00))
[debug] [XCUITest] Checking whether app '/Users/gremito/appium/AppiumDemo/SampleApp/AppiumDemo.app' is actually present on file system
[debug] [XCUITest] App is present
[debug] [iOS] Getting bundle ID from app '/Users/gremito/appium/AppiumDemo/SampleApp/AppiumDemo.app': 'devnokiyo.AppiumDemo'
[debug] [BaseDriver] Event 'resetStarted' logged at 1576213802463 (14:10:02 GMT+0900 (GMT+09:00))
[XCUITest] Not scrubbing third party app in anticipation of uninstall
[debug] [BaseDriver] Event 'resetComplete' logged at 1576213802542 (14:10:02 GMT+0900 (GMT+09:00))
[XCUITest] Continuing without capturing device logs: iOS Simulator with udid C21A6141-57DA-4DAF-91D6-EBF2ED2F5588 is not running
[XCUITest] Setting up simulator
[debug] [iOS] No reason to set locale
[debug] [iOS] No iOS / app preferences to set
[debug] [iOS] Setting did not need to be updated
[debug] [iOSSim] Setting preferences of C21A6141-57DA-4DAF-91D6-EBF2ED2F5588 Simulator to {"ConnectHardwareKeyboard":false}
[debug] [iOSSim] Setting common Simulator preferences to {"RotateWindowWhenSignaledByGuest":true,"ConnectHardwareKeyboard":false}
[debug] [iOSSim] Updated C21A6141-57DA-4DAF-91D6-EBF2ED2F5588 Simulator preferences at '/Users/gremito/Library/Preferences/com.apple.iphonesimulator.plist' with {"DevicePreferences":{"C21A6141-57DA-4DAF-91D6-EBF2ED2F5588":{"ConnectHardwareKeyboard":false}},"RotateWindowWhenSignaledByGuest":true,"ConnectHardwareKeyboard":false}
[iOSSim] Booting Simulator with UDID C21A6141-57DA-4DAF-91D6-EBF2ED2F5588...
[iOSSim] Starting Simulator UI with command: open -Fn /Applications/Xcode.app/Contents/Developer/Applications/Simulator.app --args -CurrentDeviceUDID C21A6141-57DA-4DAF-91D6-EBF2ED2F5588 -ConnectHardwareKeyboard 0
[iOSSim] Simulator with UDID C21A6141-57DA-4DAF-91D6-EBF2ED2F5588 booted in 22 seconds
[debug] [IDB] Connecting idb service to 'C21A6141-57DA-4DAF-91D6-EBF2ED2F5588'

[XCUITest] idb will not be used for Simulator interaction. Original error: 'idb_companion' has not been found in PATH. Is it installed? Read https://www.fbidb.io for more details
[debug] [BaseDriver] Event 'simStarted' logged at 1576213825321 (14:10:25 GMT+0900 (GMT+09:00))
[debug] [IOSSimulatorLog] Starting log capture for iOS Simulator with udid 'C21A6141-57DA-4DAF-91D6-EBF2ED2F5588', using 'xcrun simctl spawn C21A6141-57DA-4DAF-91D6-EBF2ED2F5588 log stream --style compact'
[debug] [BaseDriver] Event 'logCaptureStarted' logged at 1576213825625 (14:10:25 GMT+0900 (GMT+09:00))
[debug] [XCUITest] Verifying application platform
[debug] [XCUITest] CFBundleSupportedPlatforms: ["iPhoneSimulator"]
[debug] [XCUITest] Cleaning installd cache to save the disk space
[debug] [XCUITest] Installing '/Users/gremito/appium/AppiumDemo/SampleApp/AppiumDemo.app' on Simulator with UUID 'C21A6141-57DA-4DAF-91D6-EBF2ED2F5588'...
[debug] [XCUITest] The app has been installed successfully.
[debug] [BaseDriver] Event 'appInstalled' logged at 1576213827657 (14:10:27 GMT+0900 (GMT+09:00))
[XCUITest] Using WDA path: '/usr/local/lib/node_modules/appium/node_modules/appium-webdriveragent'
[XCUITest] Using WDA agent: '/usr/local/lib/node_modules/appium/node_modules/appium-webdriveragent/WebDriverAgent.xcodeproj'
[debug] [XCUITest] No obsolete cached processes from previous WDA sessions listening on port 8100 have been found
[DevCon Factory] Requesting connection for device C21A6141-57DA-4DAF-91D6-EBF2ED2F5588 on local port 8100, device port 8100
[debug] [DevCon Factory] Cached connections count: 0
[DevCon Factory] Successfully requested the connection for C21A6141-57DA-4DAF-91D6-EBF2ED2F5588:8100
[debug] [XCUITest] Starting WebDriverAgent initialization with the synchronization key 'XCUITestDriver'
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [XCUITest] WDA is not listening at 'http://localhost:8100/'
[debug] [XCUITest] WDA is currently not running. There is nothing to cache
[debug] [XCUITest] Trying to start WebDriverAgent 2 times with 10000ms interval
[debug] [XCUITest] These values can be customized by changing wdaStartupRetries/wdaStartupRetryInterval capabilities
[debug] [BaseDriver] Event 'wdaStartAttempted' logged at 1576213827766 (14:10:27 GMT+0900 (GMT+09:00))
[XCUITest] Launching WebDriverAgent on the device
[WebDriverAgent] Fetching dependencies
[WebDriverAgent] Installing/updating dependencies for platforms 'iOS', 'tvOS'
[debug] [WebDriverAgent] *** Checking out YYCache at "1.1.0"
[debug] [WebDriverAgent] *** Checking out RoutingHTTPServer at "v1.0.2"
[debug] [WebDriverAgent] *** Checking out CocoaAsyncSocket at "7.6.3"
[debug] [WebDriverAgent] *** Cloning CocoaAsyncSocket
[debug] [WebDriverAgent] *** Cloning YYCache
[debug] [WebDriverAgent] *** Cloning RoutingHTTPServer
[debug] [WebDriverAgent] *** xcodebuild output can be found in /var/folders/p8/37pd2jf119jd4tlmf0nm85kw0000gn/T/carthage-xcodebuild.jB3HuY.log
[debug] [WebDriverAgent] *** Downloading CocoaAsyncSocket.framework binary at "Version 7.6.3"
[debug] [WebDriverAgent] *** Building scheme "RoutingHTTPServer tvOS" in RoutingHTTPServer.xcodeproj
[debug] [WebDriverAgent] *** Building scheme "RoutingHTTPServer iOS" in RoutingHTTPServer.xcodeproj
[debug] [WebDriverAgent] *** Building scheme "YYCache tvOS" in YYCache.xcodeproj
[debug] [WebDriverAgent] *** Building scheme "YYCache iOS" in YYCache.xcodeproj
[debug] [WebDriverAgent] Finished fetching dependencies
[debug] [XCUITest] Cleaning the project scheme 'WebDriverAgentLib' to make sure there are no leftovers from previous installs
[debug] [XCUITest] Cleaning the project scheme 'WebDriverAgentRunner' to make sure there are no leftovers from previous installs
[debug] [XCUITest] Killing running processes 'xcodebuild.*C21A6141-57DA-4DAF-91D6-EBF2ED2F5588, C21A6141-57DA-4DAF-91D6-EBF2ED2F5588.*XCTRunner' for the device C21A6141-57DA-4DAF-91D6-EBF2ED2F5588...
[debug] [XCUITest] 'pgrep -ifn xcodebuild.*C21A6141-57DA-4DAF-91D6-EBF2ED2F5588' didn't detect any matching processes. Return code: 1
[debug] [XCUITest] 'pgrep -ifn C21A6141-57DA-4DAF-91D6-EBF2ED2F5588.*XCTRunner' didn't detect any matching processes. Return code: 1
[debug] [XCUITest] Beginning test with command 'xcodebuild build-for-testing test-without-building -project /usr/local/lib/node_modules/appium/node_modules/appium-webdriveragent/WebDriverAgent.xcodeproj -scheme WebDriverAgentRunner -destination id=C21A6141-57DA-4DAF-91D6-EBF2ED2F5588 IPHONEOS_DEPLOYMENT_TARGET=13.2 GCC_TREAT_WARNINGS_AS_ERRORS=0 COMPILER_INDEX_STORE_ENABLE=NO' in directory '/usr/local/lib/node_modules/appium/node_modules/appium-webdriveragent'
[debug] [XCUITest] Output from xcodebuild will only be logged if any errors are present there. To change this, use 'showXcodeLog' desired capability
[debug] [XCUITest] Waiting up to 60000ms for WebDriverAgent to start
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [XCUITest] Log file for xcodebuild test: /Users/gremito/Library/Developer/Xcode/DerivedData/WebDriverAgent-ciegwgvxzxdrqthilmrmczmqvrgu/Logs/Test/Test-WebDriverAgentRunner-2019.12.13_14-11-50-+0900.xcresult/Staging/2_Test/Diagnostics/WebDriverAgentRunner-186B31F2-9C79-4ED4-8845-1746F65371B8/WebDriverAgentRunner-A86A188C-597B-4F8D-8674-A912A2000A49/Session-WebDriverAgentRunner-2019-12-13_141205-ZTpnDE.log
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[WD Proxy] Got an unexpected response with status undefined: {"errno":"ECONNREFUSED","code":"ECONNREFUSED","syscall":"connect","address":"127.0.0.1","port":8100}
[debug] [WD Proxy] Matched '/status' to command name 'getStatus'
[debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
[debug] [WD Proxy] Got response with status 200: {
[debug] [WD Proxy]   "value" : {
[debug] [WD Proxy]     "message" : "WebDriverAgent is ready to accept commands",
[debug] [WD Proxy]     "state" : "success",
[debug] [WD Proxy]     "os" : {
[debug] [WD Proxy]       "name" : "iOS",
[debug] [WD Proxy]       "version" : "13.2",
[debug] [WD Proxy]       "sdkVersion" : "13.0"
[debug] [WD Proxy]     },
[debug] [WD Proxy]     "ios" : {
[debug] [WD Proxy]       "simulatorVersion" : "13.2",
[debug] [WD Proxy]       "ip" : "192.168.100.66"
[debug] [WD Proxy]     },
[debug] [WD Proxy]     "ready" : true,
[debug] [WD Proxy]     "build" : {
[debug] [WD Proxy]       "upgradedAt" : "1576213906607",
[debug] [WD Proxy]       "time" : "Dec 13 2019 14:11:54",
[debug] [WD Proxy]       "productBundleIdentifier" : "com.facebook.WebDriverAgentRunner"
[debug] [WD Proxy]     }
[debug] [WD Proxy]   },
[debug] [WD Proxy]   "sessionId" : "1F4B0C9A-3742-441D-A505-4619F346577F"
[debug] [WD Proxy] }
[debug] [XCUITest] WebDriverAgent information:
[debug] [XCUITest] {
[debug] [XCUITest]   "message": "WebDriverAgent is ready to accept commands",
[debug] [XCUITest]   "state": "success",
[debug] [XCUITest]   "os": {
[debug] [XCUITest]     "name": "iOS",
[debug] [XCUITest]     "version": "13.2",
[debug] [XCUITest]     "sdkVersion": "13.0"
[debug] [XCUITest]   },
[debug] [XCUITest]   "ios": {
[debug] [XCUITest]     "simulatorVersion": "13.2",
[debug] [XCUITest]     "ip": "192.168.100.66"
[debug] [XCUITest]   },
[debug] [XCUITest]   "ready": true,
[debug] [XCUITest]   "build": {
[debug] [XCUITest]     "upgradedAt": "1576213906607",
[debug] [XCUITest]     "time": "Dec 13 2019 14:11:54",
[debug] [XCUITest]     "productBundleIdentifier": "com.facebook.WebDriverAgentRunner"
[debug] [XCUITest]   }
[debug] [XCUITest] }
[debug] [XCUITest] WebDriverAgent successfully started after 20519ms
[debug] [BaseDriver] Event 'wdaSessionAttempted' logged at 1576213929843 (14:12:09 GMT+0900 (GMT+09:00))
[debug] [XCUITest] Sending createSession command to WDA
[debug] [WD Proxy] Matched '/session' to command name 'createSession'
[debug] [WD Proxy] Proxying [POST /session] to [POST http://localhost:8100/session] with body: {"capabilities":{"firstMatch":[{"bundleId":"devnokiyo.AppiumDemo","arguments":[],"environment":{},"eventloopIdleDelaySec":0,"shouldWaitForQuiescence":true,"shouldUseTestManagerForVisibilityDetection":false,"maxTypingFrequency":60,"shouldUseSingletonTestManager":true}],"alwaysMatch":{}}}
[debug] [WD Proxy] Got response with status 200: {"value":{"sessionId":"91A50FCF-1D41-4A4E-A240-35D41F5EF631","capabilities":{"device":"iphone","browserName":"AppiumDemo","sdkVersion":"13.2","CFBundleIdentifier":"devnokiyo.AppiumDemo"}},"sessionId":"91A50FCF-1D41-4A4E-A240-35D41F5EF631"}
[WD Proxy] Determined the downstream protocol as 'W3C'
[debug] [BaseDriver] Event 'wdaSessionStarted' logged at 1576213931173 (14:12:11 GMT+0900 (GMT+09:00))
[debug] [BaseDriver] Event 'wdaStarted' logged at 1576213931174 (14:12:11 GMT+0900 (GMT+09:00))
[XCUITest] Skipping setting of the initial display orientation. Set the "orientation" capability to either "LANDSCAPE" or "PORTRAIT", if this is an undesired behavior.
[debug] [BaseDriver] Event 'orientationSet' logged at 1576213931174 (14:12:11 GMT+0900 (GMT+09:00))
[Appium] New XCUITestDriver session created successfully, session 397fd4d4-6181-4dea-8617-48bd8c26509e added to master session list
[debug] [BaseDriver] Event 'newSessionStarted' logged at 1576213931175 (14:12:11 GMT+0900 (GMT+09:00))
[debug] [W3C (397fd4d4)] Cached the protocol value 'W3C' for the new session 397fd4d4-6181-4dea-8617-48bd8c26509e
[debug] [W3C (397fd4d4)] Responding to client with driver.createSession() result: {"capabilities":{"webStorageEnabled":false,"locationContextEnabled":false,"browserName":"","platform":"MAC","javascriptEnabled":true,"databaseEnabled":false,"takesScreenshot":true,"networkConnectionEnabled":false,"platformName":"iOS","platformVersion":"13.2","deviceName":"iPhone Simulator","automationName":"XCUITest","app":"/Users/gremito/appium/AppiumDemo/SampleApp/AppiumDemo.app","udid":"C21A6141-57DA-4DAF-91D6-EBF2ED2F5588"}}
[HTTP] <-- POST /wd/hub/session 200 129781 ms - 493
[HTTP] 
[HTTP] --> POST /wd/hub/session/397fd4d4-6181-4dea-8617-48bd8c26509e/timeouts
[HTTP] {"implicit":10000}
[debug] [W3C (397fd4d4)] Calling AppiumDriver.timeouts() with args: [null,null,null,null,10000,"397fd4d4-6181-4dea-8617-48bd8c26509e"]
[debug] [XCUITest] Executing command 'timeouts'
[debug] [BaseDriver] W3C timeout argument: {"implicit":10000}}
[debug] [BaseDriver] Set implicit wait to 10000ms
[debug] [W3C (397fd4d4)] Responding to client with driver.timeouts() result: null
[HTTP] <-- POST /wd/hub/session/397fd4d4-6181-4dea-8617-48bd8c26509e/timeouts 200 48 ms - 14
[HTTP] 
[HTTP] --> GET /wd/hub/status
[HTTP] {}
[debug] [GENERIC] Calling AppiumDriver.getStatus() with args: []
[debug] [GENERIC] Responding to client with driver.getStatus() result: {"build":{"version":"1.15.1"}}
[HTTP] <-- GET /wd/hub/status 200 1 ms - 68
[HTTP] 
[HTTP] --> POST /wd/hub/session/397fd4d4-6181-4dea-8617-48bd8c26509e/element
[HTTP] {"using":"id","value":"txtId"}
[debug] [W3C (397fd4d4)] Calling AppiumDriver.findElement() with args: ["id","txtId","397fd4d4-6181-4dea-8617-48bd8c26509e"]
[debug] [XCUITest] Executing command 'findElement'
[debug] [BaseDriver] Valid locator strategies for this request: xpath, id, name, class name, -ios predicate string, -ios class chain, accessibility id
[debug] [BaseDriver] Waiting up to 10000 ms for condition
[debug] [WD Proxy] Matched '/element' to command name 'findElement'
[debug] [WD Proxy] Proxying [POST /element] to [POST http://localhost:8100/session/91A50FCF-1D41-4A4E-A240-35D41F5EF631/element] with body: {"using":"id","value":"txtId"}
[debug] [WD Proxy] Got response with status 200: {"value":{"ELEMENT":"0B000000-0000-0000-8F74-010000000000","element-6066-11e4-a52e-4f735466cecf":"0B000000-0000-0000-8F74-010000000000"},"sessionId":"91A50FCF-1D41-4A4E-A240-35D41F5EF631"}
[debug] [W3C (397fd4d4)] Responding to client with driver.findElement() result: {"element-6066-11e4-a52e-4f735466cecf":"0B000000-0000-0000-8F74-010000000000","ELEMENT":"0B000000-0000-0000-8F74-010000000000"}
[HTTP] <-- POST /wd/hub/session/397fd4d4-6181-4dea-8617-48bd8c26509e/element 200 79 ms - 137
[HTTP] 
[HTTP] --> POST /wd/hub/session/397fd4d4-6181-4dea-8617-48bd8c26509e/element/0B000000-0000-0000-8F74-010000000000/value
[HTTP] {"value":["d","e","v","n","o","k","i","y","o"],"text":"devnokiyo"}
[debug] [W3C (397fd4d4)] Calling AppiumDriver.setValue() with args: [["d","e","v","n","o","k","i","y","o"],"0B000000-0000-0000-8F74-010000000000","397fd4d4-6181-4dea-8617-48bd8c26509e"]
[debug] [XCUITest] Executing command 'setValue'
[debug] [WD Proxy] Matched '/element/0B000000-0000-0000-8F74-010000000000/value' to command name 'setValue'
[debug] [Protocol Converter] Added 'text' property "devnokiyo" to 'setValue' request body
[debug] [WD Proxy] Proxying [POST /element/0B000000-0000-0000-8F74-010000000000/value] to [POST http://localhost:8100/session/91A50FCF-1D41-4A4E-A240-35D41F5EF631/element/0B000000-0000-0000-8F74-010000000000/value] with body: {"value":["d","e","v","n","o","k","i","y","o"],"text":"devnokiyo"}
[debug] [WD Proxy] Got response with status 200: {"value":null,"sessionId":"91A50FCF-1D41-4A4E-A240-35D41F5EF631"}
[debug] [W3C (397fd4d4)] Responding to client with driver.setValue() result: null
[HTTP] <-- POST /wd/hub/session/397fd4d4-6181-4dea-8617-48bd8c26509e/element/0B000000-0000-0000-8F74-010000000000/value 200 1366 ms - 14
[HTTP] 
[HTTP] --> POST /wd/hub/session/397fd4d4-6181-4dea-8617-48bd8c26509e/element
[HTTP] {"using":"id","value":"txtPassword"}

# 省略

[HTTP] <-- POST /wd/hub/session/24162c38-9a34-482a-b415-07fb425c4c66/elements 200 10462 ms - 12
[HTTP] 
[HTTP] --> DELETE /wd/hub/session/24162c38-9a34-482a-b415-07fb425c4c66
[HTTP] {}
[debug] [W3C (24162c38)] Calling AppiumDriver.deleteSession() with args: ["24162c38-9a34-482a-b415-07fb425c4c66"]
[debug] [BaseDriver] Event 'quitSessionRequested' logged at 1576214130947 (14:15:30 GMT+0900 (GMT+09:00))
[Appium] Removing session 24162c38-9a34-482a-b415-07fb425c4c66 from our master session list
[debug] [WD Proxy] Matched '/session/24162c38-9a34-482a-b415-07fb425c4c66' to command name 'deleteSession'
[debug] [WD Proxy] Proxying [DELETE /session/24162c38-9a34-482a-b415-07fb425c4c66] to [DELETE http://localhost:8100/session/894E8342-969F-445C-B436-3B94E84DAC6A] with no body
[debug] [WD Proxy] Got response with status 200: {
[debug] [WD Proxy]   "value" : null,
[debug] [WD Proxy]   "sessionId" : "DDF37883-7EBB-4435-AAE6-377FFB624279"
[debug] [WD Proxy] }
[DevCon Factory] Releasing connections for 8E9E79E4-B83C-414E-A86A-A15BE0E52BBB device on any port number
[DevCon Factory] Found cached connections to release: ["8E9E79E4-B83C-414E-A86A-A15BE0E52BBB:8100"]
[debug] [DevCon Factory] Cached connections count: 0
[debug] [XCUITest] Not clearing log files. Use `clearSystemFiles` capability to turn on.
[debug] [XCUITest] Deleting simulator created for this run (udid: '8E9E79E4-B83C-414E-A86A-A15BE0E52BBB')
[debug] [XCUITest] Killing running processes 'xcodebuild.*8E9E79E4-B83C-414E-A86A-A15BE0E52BBB, 8E9E79E4-B83C-414E-A86A-A15BE0E52BBB.*XCTRunner' for the device 8E9E79E4-B83C-414E-A86A-A15BE0E52BBB...
[XCUITest] xcodebuild exited with code 'null' and signal 'SIGTERM'
[debug] [XCUITest] 'pgrep -ifn xcodebuild.*8E9E79E4-B83C-414E-A86A-A15BE0E52BBB' didn't detect any matching processes. Return code: 1
[debug] [XCUITest] 'pgrep -ifn 8E9E79E4-B83C-414E-A86A-A15BE0E52BBB.*XCTRunner' didn't detect any matching processes. Return code: 1
[debug] [BaseDriver] Event 'quitSessionFinished' logged at 1576214138710 (14:15:38 GMT+0900 (GMT+09:00))
[debug] [W3C (24162c38)] Received response: null
[debug] [W3C (24162c38)] But deleting session, so not returning
[debug] [W3C (24162c38)] Responding to client with driver.deleteSession() result: null
[HTTP] <-- DELETE /wd/hub/session/24162c38-9a34-482a-b415-07fb425c4c66 200 7764 ms - 14
[HTTP]

実行ログ

$ PLATFORM=iOS rspec spec/test.rb 
[DEPRECATION] Appium::Driver.new(opts) will not generate global driver by default.If you would like to generate the global driver dy default, please initialise driver with Appium::Driver.new(opts, true)
.[DEPRECATION] Appium::Driver.new(opts) will not generate global driver by default.If you would like to generate the global driver dy default, please initialise driver with Appium::Driver.new(opts, true)
.[DEPRECATION] Appium::Driver.new(opts) will not generate global driver by default.If you would like to generate the global driver dy default, please initialise driver with Appium::Driver.new(opts, true)
.[DEPRECATION] Appium::Driver.new(opts) will not generate global driver by default.If you would like to generate the global driver dy default, please initialise driver with Appium::Driver.new(opts, true)
.[DEPRECATION] Appium::Driver.new(opts) will not generate global driver by default.If you would like to generate the global driver dy default, please initialise driver with Appium::Driver.new(opts, true)
.

Finished in 5 minutes 37 seconds (files took 0.32186 seconds to load)
5 examples, 0 failures

さいごに

Sierra/High SierraでもAppiumを少し触ったときがあって、その時は上記のようなことはありませんでした（その代わり他のバグで辛かったことはあったw）。
おそらく今回の原因は、途中からiOS連携のアーキテクチャがidbに移行されて新たな問題が出てきているんだと感じました。

また、Mojaveから全体的にシステムセキュリティのアップデータがあったことで起きるバグもあるため、Mac mini/Mac Pro(ゴミ箱)で古いOSから対応されていた方々は特に変化が無いか古いままで動いているから今回のような新しいバグに遭遇していないのでは無いかと思いました。

再確認

idbコマンドを扱いたい場合は、idb_companionは必須みたいですねー、、、笑
先ほどCI上で扱っているシェルでidbコマンドを使っていると紹介しましたが、詳細は、シミュレータのboot/connect/terminateやアプリのインストール/アンインストールなどでした。

Appiumは、毎回アプリをアンスコしてインスコすることとシミュレータは起動しっぱなしでもAppiumと連携できるようなので、CIとAppiumを連携させる際にCI側で調整してこのまま進めていこうと思います。

$ idb boot --udid xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx
2019-12-13 17:42:08,919 [ERROR] - root - Exception thrown in main
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages/idb/cli/main.py", line 211, in gen_main
    await root_command.run(args)
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages/idb/cli/commands/base.py", line 94, in run
    return await self._get_subcommand_for_args(args).run(args)
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages/idb/cli/commands/base.py", line 126, in run
    await self._run_impl(args)
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages/idb/cli/commands/base.py", line 157, in _run_impl
    await self.run_with_client(args=args, client=client)
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages/idb/cli/commands/boot.py", line 20, in run_with_client
    await client.boot()
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages/idb/common/logging.py", line 110, in _async_wrapper
    raise self.translate_exception(ex)
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages/idb/common/logging.py", line 85, in _async_wrapper
    value = await function(*args, **kwargs)
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages/idb/client/grpc.py", line 151, in func_wrapper
    return await func(*args, **kwargs)
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/site-packages/idb/client/grpc.py", line 813, in boot
    process = await asyncio.create_subprocess_exec(
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/asyncio/subprocess.py", line 236, in create_subprocess_exec
    transport, protocol = await loop.subprocess_exec(
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/asyncio/base_events.py", line 1615, in subprocess_exec
    transport = await self._make_subprocess_transport(
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/asyncio/unix_events.py", line 197, in _make_subprocess_transport
    transp = _UnixSubprocessTransport(self, protocol, args, shell,
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/asyncio/base_subprocess.py", line 36, in __init__
    self._start(args=args, shell=shell, stdin=stdin, stdout=stdout,
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/asyncio/unix_events.py", line 789, in _start
    self._proc = subprocess.Popen(
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/subprocess.py", line 854, in __init__
    self._execute_child(args, executable, preexec_fn, close_fds,
  File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/subprocess.py", line 1702, in _execute_child
    raise child_exception_type(errno_num, err_msg, err_filename)
FileNotFoundError: [Errno 2] No such file or directory: 'idb_companion'