appium: Appium crashes on install_app (uncaughtException: write EPIPE) 1.16.0-beta.3

The problem

After install_app failed due to timeout, it was retried, then appium crashed with:

2019-12-19 02:48:58:423 - uncaughtException: write EPIPE
Error: write EPIPE
    at WriteWrap.onWriteComplete [as oncomplete] (internal/stream_base_commons.js:87:16)

Environment

• Appium version (or git revision) that exhibits the issue: 1.16.0-beta.3
• Last Appium version that did not exhibit the issue (if applicable): 1.14.1
• Desktop OS/version used to run Appium: OSX 10.14.6
• Node.js version (unless using Appium.app|exe): 12.10.0
• Npm or Yarn package manager: npm 6.13.4
• Mobile platform/version under test: iPhone 13.3
• Real device or emulator/simulator: Real device
• Appium CLI or Appium.app|exe: cli

Details

First install_app failure:

Install app failed the first time on what should have been fixed with new xcuitest-driver

vr-qa05:00008020-XXXXXXXX jenkins$ npm ls appium-xcuitest-driver
/Users/jenkins/build_tools/ios_phone/00008020-XXXXXXXX
└─┬ appium@1.16.0-beta.3
  ├─┬ appium-flutter-driver@0.0.20
  │ └── appium-xcuitest-driver@2.133.1  extraneous
  ├── appium-xcuitest-driver@3.10.1 
  └─┬ appium-youiengine-driver@1.2.3
    └── appium-xcuitest-driver@3.10.1  deduped

npm ERR! extraneous: appium-xcuitest-driver@2.133.1 /Users/jenkins/build_tools/ios_phone/00008020-XXXXXXXX/node_modules/appium-flutter-driver/node_modules/appium-xcuitest-driver
vr-qa05:00008020-XXXXXXXX jenkins$ 

2019-12-19 02:47:54:110 - [XCUITest] Installing '/var/folders/ll/brhhr98d59j9yjzm3fmjbssw0000gp/T/20191118-30206-120p125.yhzzh/Payload/MyCompany.app' to the real device with UDID 00008020-XXXXXXXX
2019-12-19 02:47:54:829 - [XCUITest] Falling back to ios-deploy usage
2019-12-19 02:47:54:830 - [XCUITest] Error: Unexpected response OBJECT_NOT_FOUND
2019-12-19 02:47:54:830 - [XCUITest]     at AfcService._checkStatus (/Users/jenkins/build_tools/ios_phone/00008020-XXXXXXXX/node_modules/appium/node_modules/appium-ios-device/lib/afc/index.js:271:13)
2019-12-19 02:47:54:830 - [XCUITest]     at AfcService.openFile (/Users/jenkins/build_tools/ios_phone/00008020-XXXXXXXX/node_modules/appium/node_modules/appium-ios-device/lib/afc/index.js:118:12)
2019-12-19 02:47:54:830 - [XCUITest]     at AfcService.createWriteStream (/Users/jenkins/build_tools/ios_phone/00008020-XXXXXXXX/node_modules/appium/node_modules/appium-ios-device/lib/afc/index.js:131:24)
2019-12-19 02:47:54:830 - [XCUITest]     at /Users/jenkins/build_tools/ios_phone/00008020-XXXXXXXX/node_modules/appium/node_modules/appium-xcuitest-driver/lib/ios-deploy.js:95:31
2019-12-19 02:47:54:830 - [XCUITest]     at /Users/jenkins/build_tools/ios_phone/00008020-XXXXXXXX/node_modules/appium/node_modules/appium-xcuitest-driver/node_modules/appium-support/lib/fs.js:97:47

finally:

2019-12-19 02:48:17:487 - [HTTP] --> POST /wd/hub/session/05e3c4b1-4fa9-4d20-9110-99e117092c84/appium/device/install_app
2019-12-19 02:48:17:487 - [HTTP] {"appPath":"http://myserver.com:8000/files/mycompany-prerelease-1-34.7-191223018.ipa"}
2019-12-19 02:48:17:487 - [debug] [W3C (05e3c4b1)] Calling AppiumDriver.installApp() with args: ["http://myserver.com:8000/files/mycompany-prerelease-1-34.7-191223018.ipa",null,null,null,"05e3c4b1-4fa9-4d20-9110-99e117092c84"]
2019-12-19 02:48:17:488 - [debug] [XCUITest] Executing command 'installApp'
2019-12-19 02:48:17:488 - [BaseDriver] Using downloadable app 'http://myserver.com:8000/files/mycompany-prerelease-1-34.7-191223018.ipa'
2019-12-19 02:48:17:493 - [debug] [BaseDriver] App Last-Modified: Wed, 18 Dec 2019 02:00:21 GMT
2019-12-19 02:48:17:494 - [BaseDriver] Reusing previously downloaded application at '/var/folders/ll/brhhr98d59j9yjzm3fmjbssw0000gp/T/20191118-30206-120p125.yhzzh/Payload/MyCompany.app'
2019-12-19 02:48:17:494 - [XCUITest] Installing '/var/folders/ll/brhhr98d59j9yjzm3fmjbssw0000gp/T/20191118-30206-120p125.yhzzh/Payload/MyCompany.app' to the real device with UDID 00008020-XXXXXXXX
2019-12-19 02:48:58:423 - uncaughtException: write EPIPE
Error: write EPIPE
    at WriteWrap.onWriteComplete [as oncomplete] (internal/stream_base_commons.js:87:16)
2019-12-19 02:48:59:881 - [BaseDriver] Shutting down because we waited 100 seconds for a command
2019-12-19 02:48:59:882 - [Appium] Closing session, cause was 'New Command Timeout of 100 seconds expired. Try customizing the timeout using the 'newCommandTimeout' desired capability'
2019-12-19 02:48:59:882 - [Appium] Removing session '0b4e5a65-9162-409a-933c-9eb9b0e8ca59' from our master session list
2019-12-19 02:48:59:882 - [DevCon Factory] Releasing connections for 00008020-XXXXXXXX device on any port number
2019-12-19 02:48:59:883 - [DevCon Factory] Found cached connections to release: ["00008020-XXXXXXXX:7848"]
2019-12-19 02:48:59:883 - [DevCon Factory] Releasing the listener for '00008020-XXXXXXXX:7848'
2019-12-19 02:48:59:885 - [debug] [DevCon Factory] Cached connections count: 0
2019-12-19 02:49:01:426 - [BaseDriver] The application 'http://myserver.com:8000/files/mycompany-prerelease-1-34.7-191223018.ipa' cached at '/var/folders/ll/brhhr98d59j9yjzm3fmjbssw0000gp/T/20191118-30206-120p125.yhzzh/Payload/MyCompany.app' has expired after 86400000ms
2019-12-19 02:49:01:427 - [debug] [BaseDriver] Performing cleanup of 1 cached application

Code To Reproduce Issue [ Good To Have ]

Using selenium grid Multiple phones on the same machine running multiple instances of appium.

Creation of sessions just open up the ios Settings app, uninstall all other versions / packages of our app, then call install_app with our test app.

Appium log startup

NOTE: The appium.log file is currently 5.3MB, so pretty large. Here’s the startup data:

2019-12-18 19:32:25:605 - [Appium] Welcome to Appium v1.16.0-beta.3
2019-12-18 19:32:25:607 - [Appium] Non-default server args:
2019-12-18 19:32:25:610 - [Appium]   port: 4848
2019-12-18 19:32:25:610 - [Appium]   callbackPort: 4849
2019-12-18 19:32:25:611 - [Appium]   sessionOverride: true
2019-12-18 19:32:25:612 - [Appium]   logTimestamp: true
2019-12-18 19:32:25:613 - [Appium]   logNoColors: true
2019-12-18 19:32:25:613 - [Appium]   nodeconfig: /Users/jenkins/build_tools/ios_phone/00008020-XXXXXXXX/selenium-conf.json
2019-12-18 19:32:25:613 - [Appium]   debugLogSpacing: true
2019-12-18 19:32:25:613 - [Appium]   defaultCapabilities: {
2019-12-18 19:32:25:613 - [Appium]     deviceName: 00008020-XXXXXXXX
2019-12-18 19:32:25:613 - [Appium]     udid: 00008020-XXXXXXXX
2019-12-18 19:32:25:614 - [Appium]     systemPort: 7848
2019-12-18 19:32:25:614 - [Appium]     wdaLocalPort: 7848
2019-12-18 19:32:25:614 - [Appium]     webkitDebugProxyPort: 9848
2019-12-18 19:32:25:614 - [Appium]     startIWDP: true
2019-12-18 19:32:25:614 - [Appium]     useXctestrunFile: true
2019-12-18 19:32:25:614 - [Appium]     bootstrapPath: /Users/jenkins/build_tools/ios_phone/00008020-XXXXXXXX/wda
2019-12-18 19:32:25:614 - [Appium]   }
2019-12-18 19:32:25:615 - [Appium] Default capabilities, which will be added to each request unless overridden by desired capabilities:
2019-12-18 19:32:25:616 - [Appium]   deviceName: 00008020-XXXXXXXX
2019-12-18 19:32:25:616 - [Appium]   udid: 00008020-XXXXXXXX
2019-12-18 19:32:25:616 - [Appium]   systemPort: 7848
2019-12-18 19:32:25:616 - [Appium]   wdaLocalPort: 7848
2019-12-18 19:32:25:616 - [Appium]   webkitDebugProxyPort: 9848
2019-12-18 19:32:25:617 - [Appium]   startIWDP: true
2019-12-18 19:32:25:617 - [Appium]   useXctestrunFile: true
2019-12-18 19:32:25:617 - [Appium]   bootstrapPath: /Users/jenkins/build_tools/ios_phone/00008020-XXXXXXXX/wda
2019-12-18 19:32:25:645 - [debug] [Appium] Starting auto register thread for grid. Will try to register every 5000 ms.
2019-12-18 19:32:25:646 - [Appium] Appium REST http interface listener started on 0.0.0.0:4848
2019-12-18 19:32:30:709 - [debug] [Appium] Appium successfully registered with the grid on http://myserver.com:4444

Session creation:

2019-12-19 02:47:25:247 - [HTTP] --> POST /wd/hub/session
2019-12-19 02:47:25:247 - [HTTP] {"desiredCapabilities":{"server:CONFIG_UUID":"60fcbf6d-8a2a-4405-8cf8-00212e4a25a9","simpleIsVisibleCheck":true,"noReset":false,"deviceName":"*","xcodeSigningId":"iPhone Developer","mycompany:node.defaultDevice":true,"mycompany:testng.session.hash":"ae0a01ed-69ef-47f7-9327-22908bc9ef36","newCommandTimeout":100,"platformVersion":"13.3","automationName":"XCuiTest","browserName":"","mycompany:testng.hostname":"mycompany.com","platformName":"ios","preventWDAAttachments":true,"mycompany:testng.jenkins.build":"1131","xcodeOrgId":"TEAM_ID","bundleId":"com.apple.Preferences",mycompany:testng.suite":"Attractions Native Core Ios","updatedWDABundleId":"com.mycompany.qa.WebDriverAgentRunner","mycompany:testng.jenkins.jobname":"qa-mobile-exp-core-ios","sendKeyStrategy":"grouped","mycompany:node.platformType":"Phone","mycompany:testng.test":"testAttractionsGoodPromoCode","useNewWDA":true},"capabilities":{"firstMatch":[{"browserName":"","platformName":"ios","serve
2019-12-19 02:47:25:247 - [debug] [W3C] Calling AppiumDriver.createSession() with args: [{"server:CONFIG_UUID":"60fcbf6d-8a2a-4405-8cf8-00212e4a25a9","simpleIsVisibleCheck":true,"noReset":false,"deviceName":"*","xcodeSigningId":"iPhone Developer","mycompany:node.defaultDevice":true,"mycompany:testng.session.hash":"ae0a01ed-69ef-47f7-9327-22908bc9ef36","newCommandTimeout":100,"platformVersion":"13.3","automationName":"XCuiTest","browserName":"","mycompany:testng.hostname":"mycompany.com","platformName":"ios","preventWDAAttachments":true,"mycompany.jenkins.build":"1131","xcodeOrgId":"TEAM_ID","bundled":"com.apple.Preferences","mycompany.suite":"Attractions Native Core Ios","updatedWDABundleId":"com.mycompany.qa.WebDriverAgentRunner","mycompany.jenkins.jobname":"qa-mobile-exp-core-ios","sendKeyStrategy":"grouped","mycompany:node.platformType":"Phone","mycompany.test":"testAttractionsGoodPromoCode","useNewWDA":true},null, {"firstMatch" [{"browserName":"","platformName":"ios","server:CONFIG_UUID":"60fcbf6d-8a2a-4405-8cf8-00212e4a25a9"...
2019-12-19 02:47:25:248 - [debug] [BaseDriver] Event 'newSessionRequested' logged at 1576723645248 (21:47:25 GMT-0500 (Eastern Standard Time))
2019-12-19 02:47:25:254 - [BaseDriver] The capabilities ["deviceName","udid","systemPort","wdaLocalPort","webkitDebugProxyPort","startIWDP","useXctestrunFile","bootstrapPath"] are not standard capabilities and should have an extension prefix
2019-12-19 02:47:25:262 - [Appium] The following capabilities were provided in the JSONWP desired capabilities that are missing in W3C capabilities: ["simpleIsVisibleCheck","noReset","xcodeSigningId","newCommandTimeout","platformVersion","automation Name","preventWDAAttachments","xcodeOrgId","bundleId","updatedWDABundleId","sendKeyStrategy","useNewWDA"]
2019-12-19 02:47:25:262 - [Appium] Trying to fix W3C capabilities by merging them with JSONWP caps
2019-12-19 02:47:25:265 - [BaseDriver] The capabilities ["simpleIsVisibleCheck","noReset","xcodeSigningId","newCommandTimeout","platformVersion","automationName","preventWDAAttachments","xcodeOrgId","bundleId","updatedWDABundleId","sendKeyStrategy", "useNewWDA","deviceName","udid","systemPort","wdaLocalPort","webkitDebugProxyPort","startIWDP","useXctestrunFile","bootstrapPath"] are not standard capabilities and should have an extension prefix
2019-12-19 02:47:25:267 - [Appium] Appium v1.16.0-beta.3 creating new XCUITestDriver (v3.10.1) session
2019-12-19 02:47:25:280 - [debug] [BaseDriver] W3C capabilities and MJSONWP desired capabilities were provided