search

zebrunner / mcloud-ios

15 stars 8 forks source link

iOS device is not up and running after disconnect and connect to Mac #166

Closed dhreben closed 1 year ago

dhreben commented 1 year ago

Steps:

  1. Disconnect iOS device
  2. ./zebrunner.sh status --> iPhone_8 (b09fa................862b5) is disconnected!
  3. Connect iOS device -->iPhone_8 (b09fa2........243f862b5) is unhealthy!

Actual result: iOS device is not up and running after disconnect and connect to Mac

Linked with https://github.com/zebrunner/stf/issues/468. I believe its the same issue

Logs: 

idmclouds-Mac-mini:mcloud-ios idmcloud$ tail -f ./logs/iPhone_8.log
{"level":"info","msg":"device called local method","sel":"_XCT_testCase:method:willStartActivity:","time":"2023-01-06T13:11:37+03:00"}
{"level":"info","msg":"device called local method","sel":"_XCT_testCase:method:didFinishActivity:","time":"2023-01-06T13:11:37+03:00"}
{"fields.msg":"2023-01-06 13:11:37.775196+0300 WebDriverAgentRunner-Runner[3455:269856] ServerURLHere-\u003ehttp://192.168.88.208:20001\u003c-ServerURLHere\n","fields.time":1853940635110,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3455,"time":"2023-01-06T13:11:37+03:00"}
{"fields.msg":"2023-01-06 13:11:37.775467+0300 WebDriverAgentRunner-Runner[3455:269857] Using singleton test manager\n","fields.time":1853940641868,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3455,"time":"2023-01-06T13:11:37+03:00"}
2023-01-06 10:11:39:259 - [HTTP] --> GET /wd/hub/status
2023-01-06 10:11:39:260 - [HTTP] {}
2023-01-06 10:11:39:260 - [debug] [GENERIC] Calling AppiumDriver.getStatus() with args: []
2023-01-06 10:11:39:260 - [debug] [GENERIC] Responding to client with driver.getStatus() result: {"build":{"version":"1.22.3"}}
2023-01-06 10:11:39:260 - [HTTP] <-- GET /wd/hub/status 200 1 ms - 68
2023-01-06 10:11:39:260 - [HTTP] 
2023-01-06 10:11:44:264 - [HTTP] --> GET /wd/hub/status
2023-01-06 10:11:44:264 - [HTTP] {}
2023-01-06 10:11:44:264 - [debug] [GENERIC] Calling AppiumDriver.getStatus() with args: []
2023-01-06 10:11:44:264 - [debug] [GENERIC] Responding to client with driver.getStatus() result: {"build":{"version":"1.22.3"}}
2023-01-06 10:11:44:265 - [HTTP] <-- GET /wd/hub/status 200 1 ms - 68
2023-01-06 10:11:44:265 - [HTTP] 
Starting WDA: iPhone_8, udid: b09fa2.............3348b7243f862b5, WDA_PORT: 20001, MJPEG_PORT: 20002
[06/01/2023 13:11:45] Starting WebDriverAgent application on port 20001
Starting appium: b09f...........e3348b7243f862b5 - device name : iPhone_8
Starting iSTF ios-device: b09fa...........b7243f862b5 device name : iPhone_8
{"bundleid":"com.facebook.WebDriverAgentRunner.xctrunner","level":"info","msg":"Running wda","testbundleid":"com.facebook.WebDriverAgentRunner.xctrunner","time":"2023-01-06T13:11:45+03:00","xctestconfig":"WebDriverAgentRunner.xctest"}
WDA started successfully on iPhone_8 within 0 seconds.
Now using node v17.1.0 (npm v8.3.0)
2023-01-06 10:11:46:426 - [Appium] Welcome to Appium v1.22.3
2023-01-06 10:11:46:428 - [Appium] Non-default server args:
2023-01-06 10:11:46:429 - [Appium]   port: 4841
2023-01-06 10:11:46:429 - [Appium]   sessionOverride: true
2023-01-06 10:11:46:430 - [Appium]   logTimestamp: true
2023-01-06 10:11:46:430 - [Appium]   logNoColors: true
2023-01-06 10:11:46:430 - [Appium]   nodeconfig: ./metaData/b09..............7243f862b5.json
2023-01-06 10:11:46:431 - [Appium]   tmpDir: /Users/idmcloud/tools/mcloud-ios/tmp/AppiumData/b09fa..........348b7243f862b5
2023-01-06 10:11:46:432 - [Appium]   defaultCapabilities: {
2023-01-06 10:11:46:432 - [Appium]     mjpegServerPort: 20002
2023-01-06 10:11:46:432 - [Appium]     webkitDebugProxyPort: 20003
2023-01-06 10:11:46:433 - [Appium]     clearSystemFiles: false
2023-01-06 10:11:46:434 - [Appium]     webDriverAgentUrl: http://localhost:20001
2023-01-06 10:11:46:434 - [Appium]     preventWDAAttachments: true
2023-01-06 10:11:46:435 - [Appium]     simpleIsVisibleCheck: true
2023-01-06 10:11:46:435 - [Appium]     wdaLocalPort: 20001
2023-01-06 10:11:46:436 - [Appium]     usePrebuiltWDA: true
2023-01-06 10:11:46:436 - [Appium]     useNewWDA: false
2023-01-06 10:11:46:436 - [Appium]     platformVersion: 
2023-01-06 10:11:46:436 - [Appium]     automationName: XCUITest
2023-01-06 10:11:46:437 - [Appium]     deviceName: iPhone_8
2023-01-06 10:11:46:437 - [Appium]   }
2023-01-06 10:11:46:437 - [Appium]   deviceName: iPhone_8
2023-01-06 10:11:46:437 - [Appium]   udid: b09fa26ac.......43f862b5
2023-01-06 10:11:46:438 - [Appium] Deprecated server args:
2023-01-06 10:11:46:438 - [Appium]   --device-name => --default-capabilities
2023-01-06 10:11:46:438 - [Appium]   -U => --default-capabilities
2023-01-06 10:11:46:438 - [Appium] Default capabilities, which will be added to each request unless overridden by desired capabilities:
2023-01-06 10:11:46:439 - [Appium]   mjpegServerPort: 20002
2023-01-06 10:11:46:439 - [Appium]   webkitDebugProxyPort: 20003
2023-01-06 10:11:46:439 - [Appium]   clearSystemFiles: false
2023-01-06 10:11:46:439 - [Appium]   webDriverAgentUrl: http://localhost:20001
2023-01-06 10:11:46:439 - [Appium]   preventWDAAttachments: true
2023-01-06 10:11:46:439 - [Appium]   simpleIsVisibleCheck: true
2023-01-06 10:11:46:440 - [Appium]   wdaLocalPort: 20001
2023-01-06 10:11:46:440 - [Appium]   usePrebuiltWDA: true
2023-01-06 10:11:46:440 - [Appium]   useNewWDA: false
2023-01-06 10:11:46:440 - [Appium]   platformVersion: 
2023-01-06 10:11:46:440 - [Appium]   automationName: XCUITest
2023-01-06 10:11:46:440 - [Appium]   deviceName: iPhone_8
2023-01-06 10:11:46:459 - [HTTP] Could not start REST http interface listener. The requested port may already be in use. Please make sure there is no other instance of this server running already.
Fatal Error: listen EADDRINUSE: address already in use 0.0.0.0:4841
    at Server.setupListenHandle [as _listen2] (node:net:1334:16)
    at listenInCluster (node:net:1382:12)
    at doListen (node:net:1520:7)
    at processTicksAndRejections (node:internal/process/task_queues:84:21)
{"bundleID":"com.facebook.WebDriverAgentRunner.xctrunner","channel_id":"com.apple.instruments.server.services.processcontrol","level":"info","msg":"Launching process","time":"2023-01-06T13:11:46+03:00"}
2023-01-06T10:11:46.678Z INF/db 6336 [b09f............348b7243f862b5] Connecting to demo.zebrunner.farm:28015
2023-01-06T10:11:46.686Z INF/device:support:push 6336 [b09fa2.............7243f862b5] Ios device sending output to "tcp://demo.zebrunner.farm:7270"
2023-01-06T10:11:46.687Z INF/ios-device 6336 [b09fa26acc...............8b7243f862b5] Preparing device options:  {
  serial: 'b09fa26acc4c.............8b7243f862b5',
  provider: 'mcloud-ios',
  publicIp: 'demo.zebrunner.farm',
  endpoints: {
    sub: [ 'tcp://demo.zebrunner.farm:7250' ],
    push: [ 'tcp://demo.zebrunner.farm:7270' ],
    appDealer: [ 'tcp://demo.zebrunner.farm:7160' ],
    devDealer: [ 'tcp://demo.zebrunner.farm:7260' ]
  },
  groupTimeout: 3600000,
  storageUrl: 'https://demo.zebrunner.farm:443/',
  adbHost: '127.0.0.1',
  adbPort: 5037,
  screenJpegQuality: 30,
  screenPingInterval: 30000,
  screenPort: 7701,
  screenWsUrlPattern: 'wss://demo.zebrunner.farm:443/d/192.168.89.189/b09fa...............b7243f862b5/7701/',
  connectUrlPattern: '${publicIp}:${publicPort}',
  connectPort: 20002,
  wdaHost: 'localhost',
  wdaPort: 20001,
  vncInitialSize: [ 600, 800 ],
  heartbeatInterval: 10000,
  bootCompleteTimeout: 60000,
  muteMaster: 'never',
  lockRotation: false,
  cleanup: false,
  screenReset: true,
  udidStorage: false,
  iproxy: false,
  deviceName: 'iPhone_8',
  deviceType: 'Phone',
  host: '192.168.89.189'
}
{"channel_id":"com.apple.instruments.server.services.processcontrol","level":"info","msg":"Process started successfully","pid":3457,"time":"2023-01-06T13:11:46+03:00"}
{"fields.msg":"2023-01-06 13:11:46.835516+0300 WebDriverAgentRunner-Runner[3457:270037] Running tests...\n","fields.time":1854158083121,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:46+03:00"}
2023-01-06T10:11:46.969Z INF/device:support:sub 6336 [b09fa26a...........243f862b5] Receiving input from "tcp://demo.zebrunner.farm:7250"
2023-01-06T10:11:46.972Z INF/device:support:sub 6336 [b09fa26............8b7243f862b5] Subscribing to permanent channel "*ALL"
2023-01-06T10:11:46.975Z INF/device:plugins:solo 6336 [b09fa26acc4...............b7243f862b5] Subscribing to permanent channel "dzTlyg6o9YlxdBizOqIGbhlToWI="
2023-01-06T10:11:46.978Z INF/wdaClient 6336 [b09fa............348b7243f862b5] WdaClient.js initializing...
connecting to WdaMjpeg
2023-01-06T10:11:46.991Z INF/device:info 6336 [b09f..........243f862b5] device.name: iPhone_8
Connected to WdaMjpeg localhost:20002
WdaMjpeg connection was closed
2023-01-06T10:11:47.007Z INF/util:lifecycle 6336 [b09fa............f862b5] Winding down for graceful exit, with optional error :  WdaMjpeg connection is lost
2023-01-06T10:11:47.033Z FTL/util:lifecycle 6336 [b09f..............8b7243f862b5] Shutting down due to fatal error with optional error :  WdaMjpeg connection is lost
{"level":"info","msg":"device called local method","sel":"_XCT_didBeginExecutingTestPlan","time":"2023-01-06T13:11:47+03:00"}
{"level":"info","msg":"device called local method","sel":"_XCT_didBeginInitializingForUITesting","time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"Test Suite 'All tests' started at 2023-01-06 13:11:48.271\n","fields.time":1854192535466,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"XCTestOutputBarrier","fields.time":1854192542218,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
{"level":"info","msg":"device called local method","sel":"_XCT_testSuite:didStartAt:","time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"Test Suite 'WebDriverAgentRunner.xctest' started at 2023-01-06 13:11:48.272\nXCTestOutputBarrier","fields.time":1854192550399,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
{"level":"info","msg":"device called local method","sel":"_XCT_testSuite:didStartAt:","time":"2023-01-06T13:11:48+03:00"}
{"level":"info","msg":"device called local method","sel":"_XCT_testSuite:didStartAt:","time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"Test Suite 'UITestingUITests' started at 2023-01-06 13:11:48.272\nXCTestOutputBarrier","fields.time":1854192560969,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"    t =      nans Suite Set Up\n","fields.time":1854192565852,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
{"level":"info","msg":"device called local method","sel":"_XCT_testCase:method:willStartActivity:","time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"2023-01-06 13:11:48.300806+0300 WebDriverAgentRunner-Runner[3457:270037] [User Defaults] Couldn't write values for keys (\n    KeyboardAutocorrection\n) in CFPrefsPlistSource\u003c0x2824bfe00\u003e (Domain: com.apple.keyboard.preferences, User: kCFPreferencesCurrentUser, ByHost: No, Container: (null), Contents Need Refresh: No): setting preferences outside an application's container requires user-preference-write or file-write-data sandbox access\n","fields.time":1854193247608,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"2023-01-06 13:11:48.301693+0300 WebDriverAgentRunner-Runner[3457:270037] [User Defaults] Couldn't write values for keys (\n    \"KeyboardAutocorrection_changedAt\"\n) in CFPrefsPlistSource\u003c0x2824bfe00\u003e (Domain: com.apple.keyboard.preferences, User: kCFPreferencesCurrentUser, ByHost: No, Container: (null), Contents Need Refresh: No): setting preferences outside an application's container requires user-preference-write or file-write-data sandbox access\n","fields.time":1854193267664,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"2023-01-06 13:11:48.302196+0300 WebDriverAgentRunner-Runner[3457:270037] [User Defaults] Couldn't write values for keys (\n    \"KeyboardAutocorrection_buildAtChange\"\n) in CFPrefsPlistSource\u003c0x2824bfe00\u003e (Domain: com.apple.keyboard.preferences, User: kCFPreferencesCurrentUser, ByHost: No, Container: (null), Contents Need Refresh: No): setting preferences outside an application's container requires user-preference-write or file-write-data sandbox access\n","fields.time":1854193283140,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"2023-01-06 13:11:48.302626+0300 WebDriverAgentRunner-Runner[3457:270037] [User Defaults] Couldn't write values for keys (\n    \"KeyboardAutocorrection_previousValue\"\n) in CFPrefsPlistSource\u003c0x2824bfe00\u003e (Domain: com.apple.keyboard.preferences, User: kCFPreferencesCurrentUser, ByHost: No, Container: (null), Contents Need Refresh: No): setting preferences outside an application's container requires user-preference-write or file-write-data sandbox access\n","fields.time":1854193290560,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"2023-01-06 13:11:48.303073+0300 WebDriverAgentRunner-Runner[3457:270037] [User Defaults] Couldn't write values for keys (\n    \"KeyboardAutocorrection_analyzedAt\"\n) in CFPrefsPlistSource\u003c0x2824bfe00\u003e (Domain: com.apple.keyboard.preferences, User: kCFPreferencesCurrentUser, ByHost: No, Container: (null), Contents Need Refresh: No): setting preferences outside an application's container requires user-preference-write or file-write-data sandbox access\n","fields.time":1854193301004,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"2023-01-06 13:11:48.320030+0300 WebDriverAgentRunner-Runner[3457:270037] [User Defaults] Couldn't write values for keys (\n    KeyboardPrediction\n) in CFPrefsPlistSource\u003c0x2824bfe00\u003e (Domain: com.apple.keyboard.preferences, User: kCFPreferencesCurrentUser, ByHost: No, Container: (null), Contents Need Refresh: No): setting preferences outside an application's container requires user-preference-write or file-write-data sandbox access\n","fields.time":1854193709300,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"2023-01-06 13:11:48.320540+0300 WebDriverAgentRunner-Runner[3457:270037] [User Defaults] Couldn't write values for keys (\n    KeyboardShowPredictionBar\n) in CFPrefsPlistSource\u003c0x2824bfe00\u003e (Domain: com.apple.keyboard.preferences, User: kCFPreferencesCurrentUser, ByHost: No, Container: (null), Contents Need Refresh: No): setting preferences outside an application's container requires user-preference-write or file-write-data sandbox access\n","fields.time":1854193726100,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"2023-01-06 13:11:48.321161+0300 WebDriverAgentRunner-Runner[3457:270037] [User Defaults] Couldn't write values for keys (\n    DidShowGestureKeyboardIntroduction\n) in CFPrefsPlistSource\u003c0x2824bfe00\u003e (Domain: com.apple.keyboard.preferences, User: kCFPreferencesCurrentUser, ByHost: No, Container: (null), Contents Need Refresh: No): setting preferences outside an application's container requires user-preference-write or file-write-data sandbox access\n","fields.time":1854193750347,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
{"level":"info","msg":"device called local method","sel":"_XCT_testCase:method:didFinishActivity:","time":"2023-01-06T13:11:48+03:00"}
{"level":"info","msg":"device called local method","sel":"_XCT_testCaseDidStartForTestClass:method:","time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"Test Case '-[UITestingUITests testRunner]' started.\n","fields.time":1854193858784,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"XCTestOutputBarrier    t =     0.00s Start Test at 2023-01-06 13:11:48.327\n","fields.time":1854193898245,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
{"level":"info","msg":"device called local method","sel":"_XCT_testCase:method:willStartActivity:","time":"2023-01-06T13:11:48+03:00"}
{"level":"info","msg":"device called local method","sel":"_XCT_testCase:method:didFinishActivity:","time":"2023-01-06T13:11:48+03:00"}
{"level":"info","msg":"device called local method","sel":"_XCT_testCase:method:willStartActivity:","time":"2023-01-06T13:11:48+03:00"}
{"level":"info","msg":"device called local method","sel":"_XCT_testCase:method:didFinishActivity:","time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"    t =     0.00s Set Up\n","fields.time":1854193920777,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"2023-01-06 13:11:48.328765+0300 WebDriverAgentRunner-Runner[3457:270037] Built at Dec 13 2022 16:29:59\n","fields.time":1854193934429,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"2023-01-06 13:11:48.344127+0300 WebDriverAgentRunner-Runner[3457:270037] ServerURLHere-\u003ehttp://192.168.88.208:20001\u003c-ServerURLHere\n","fields.time":1854194290367,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
{"fields.msg":"2023-01-06 13:11:48.344625+0300 WebDriverAgentRunner-Runner[3457:270042] Using singleton test manager\n","fields.time":1854194300434,"level":"info","msg":"outputReceived:fromProcess:atTime:","pid":3457,"time":"2023-01-06T13:11:48+03:00"}
2023-01-06 10:11:49:268 - [HTTP] --> GET /wd/hub/status
2023-01-06 10:11:49:268 - [HTTP] {}
2023-01-06 10:11:49:268 - [debug] [GENERIC] Calling AppiumDriver.getStatus() with args: []
2023-01-06 10:11:49:269 - [debug] [GENERIC] Responding to client with driver.getStatus() result: {"build":{"version":"1.22.3"}}
2023-01-06 10:11:49:269 - [HTTP] <-- GET /wd/hub/status 200 1 ms - 68
2023-01-06 10:11:49:269 - [HTTP] 
2023-01-06 10:11:54:272 - [HTTP] --> GET /wd/hub/status
2023-01-06 10:11:54:272 - [HTTP] {}
2023-01-06 10:11:54:273 - [debug] [GENERIC] Calling AppiumDriver.getStatus() with args: []
2023-01-06 10:11:54:273 - [debug] [GENERIC] Responding to client with driver.getStatus() result: {"build":{"version":"1.22.3"}}
2023-01-06 10:11:54:273 - [HTTP] <-- GET /wd/hub/status 200 1 ms - 68
2023-01-06 10:11:54:274 - [HTTP] 
Starting WDA: iPhone_8, udid: b09fa26acc...........243f862b5, WDA_PORT: 20001, MJPEG_PORT: 20002
Starting iSTF ios-device: b09fa26ac...........f862b5 device name : iPhone_8
[06/01/2023 13:11:55] Starting WebDriverAgent application on port 20001
Starting appium: b09fa26...........7243f862b5 - device name : iPhone_8
{"bundleid":"com.facebook.WebDriverAgentRunner.xctrunner","level":"info","msg":"Running wda","testbundleid":"com.facebook.WebDriverAgentRunner.xctrunner","time":"2023-01-06T13:11:56+03:00","xctestconfig":"WebDriverAgentRunner.xctest"}
WDA started successfully on iPhone_8 within 0 seconds.
vdelendik commented 1 year ago

it should be fixed now. @dhreben, pay attention that device is in disconnected state in STF as well. If not - submit new issue. This one covered only case when connected back

dhreben commented 1 year ago

Fixed.