search

AppiumTestDistribution / appium-device-farm

This is an Appium 2.0 plugin designed to manage and create driver sessions on available devices.
https://devicefarm.org
Other
336 stars 102 forks source link

session delete fails because of missing device_log.json file #1129

Closed ilendemli closed 5 months ago

ilendemli commented 5 months ago

Describe the bug

when quitting the driver and ergo, closing and deleting the session, I get an error thrown with the following:

[HTTP] 
[HTTP] --> DELETE /session/fe316f2b-eb31-4e11-b06e-d783673f0bde
[HTTP] {}
[device-farm-main] ******  UnhandledRejection ******
[device-farm-main] Reason:  
Error: ENOENT: no such file or directory, open '/Users/milendemli/.cache/appium-device-farm/assets/sessions/fe316f2b-eb31-4e11-b06e-d783673f0bde/device_log.json'
    at Object.fs (node:fs:2348:20)
    at logPath (/Users/milendemli/.appium/node_modules/appium-device-farm/lib/webpack:/appium-device-farm/lib/src/modules/dashboard/asset-manager.js:58:9)
    at J.generator (/Users/milendemli/.appium/node_modules/appium-device-farm/lib/webpack:/appium-device-farm/lib/src/modules/dashboard/event-manager.js:94:27)
    at Generator.next (<anonymous>)
    at H (/Users/milendemli/.appium/node_modules/appium-device-farm/lib/webpack:/appium-device-farm/lib/src/modules/dashboard/event-manager.js:5:48)
    at processTicksAndRejections (node:internal/process/task_queues:95:5) {
  errno: -2,
  code: 'ENOENT',
  syscall: 'open',
  path: '/Users/milendemli/.cache/appium-device-farm/assets/sessions/fe316f2b-eb31-4e11-b06e-d783673f0bde/device_log.json'
}
[device-farm-main] Error: ENOENT: no such file or directory, open '/Users/milendemli/.cache/appium-device-farm/assets/sessions/fe316f2b-eb31-4e11-b06e-d783673f0bde/device_log.json'
[device-farm-main]     at Object.fs (node:fs:2348:20)
[device-farm-main]     at logPath (/Users/milendemli/.appium/node_modules/appium-device-farm/lib/webpack:/appium-device-farm/lib/src/modules/dashboard/asset-manager.js:58:9)
[device-farm-main]     at J.generator (/Users/milendemli/.appium/node_modules/appium-device-farm/lib/webpack:/appium-device-farm/lib/src/modules/dashboard/event-manager.js:94:27)
[device-farm-main]     at Generator.next (<anonymous>)
[device-farm-main]     at H (/Users/milendemli/.appium/node_modules/appium-device-farm/lib/webpack:/appium-device-farm/lib/src/modules/dashboard/event-manager.js:5:48)
[device-farm-main]     at processTicksAndRejections (node:internal/process/task_queues:95:5)
[device-farm-main] Promise: 
[device-farm-main] [object Promise]

I can confirm that the files and directories do not exist, I am not sure where this comes from as the submodules in this project are private. this results in our test cases staying in limbo until a timeout occurs.

Environment

Appium version (or git revision) that exhibits the issue: 2.5.4 Last Appium version that did not exhibit the issue (if applicable): Node.js version (unless using Appium.app|exe): 21.2.0 Npm or Yarn package manager: 10.5.2 Mobile platform/version under test: iOS Real device or emulator/simulator: Real device Appium CLI or Appium.app|exe: CLI

sudharsan-selvaraj commented 5 months ago

@ilendemli Please try with 8.4.7-rc.33

ilendemli commented 5 months ago

@sudharsan-selvaraj some sort of issue still persist:

[device-farm-main] Updating lastCmdExecutedAt for device RZCT80Z3AFE in session 7c244fd2-bde0-49e7-9759-7140ffff3b7f
[AndroidUiautomator2Driver@c831 (7c244fd2)] Calling AppiumDriver.execute() with args: ["mobile: shell",[{"args":["keyevent","4"],"command":"input"}],"7c244fd2-bde0-49e7-9759-7140ffff3b7f"]
[AppiumDriver@a066] Clearing new command timeout pre-emptively since plugin(s) will handle this command
[AppiumDriver@a066] Plugins which can handle cmd 'execute': device-farm
[AppiumDriver@a066] Plugin device-farm is now handling cmd 'execute'
[AppiumDriver@a066] Executing default handling behavior for command 'execute'
[AndroidUiautomator2Driver@c831 (7c244fd2)] Executing native command 'mobile: shell'
[AndroidUiautomator2Driver@c831 (7c244fd2)] Running '/Users/automation/Library/Android/sdk/platform-tools/adb -P 5037 -s RZCT80Z3AFE shell input keyevent 4'
[device-farm-main] Updating lastCmdExecutedAt for device RZCT80Z3AFE in session 7c244fd2-bde0-49e7-9759-7140ffff3b7f
[AndroidUiautomator2Driver@c831 (7c244fd2)] Responding to client with driver.execute() result: ""
{} 7c244fd2-bde0-49e7-9759-7140ffff3b7f
[device-farm-main] Saving log entry for session 7c244fd2-bde0-49e7-9759-7140ffff3b7f with eventId undefined
[device-farm-main] ******  UnhandledRejection ******
[device-farm-main] Reason:  
PrismaClientValidationError: 
Invalid `prisma.sessionLog.create()` invocation:

{
  data: {
    sessionId: "7c244fd2-bde0-49e7-9759-7140ffff3b7f",
    commandName: "execute",
    body: "{\"args\":[{\"args\":[\"keyevent\",\"4\"],\"command\":\"input\"}],\"script\":\"mobile: shell\"}",
    response: "{\"value\":\"\"}",
    isSuccess: "",
               ~~
    method: "POST",
    title: "Execute",
    subtitle: "",
    screenshot: null,
    url: "/session/7c244fd2-bde0-49e7-9759-7140ffff3b7f/execute/sync",
    eventId: undefined
  }
}

Argument `isSuccess`: Invalid value provided. Expected Boolean or Null, provided String.
    at Tn (/Users/automation/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:115:6855)
    at In.handleRequestError (/Users/automation/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:122:6533)
    at In.handleAndLogRequestError (/Users/automation/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:122:6211)
    at In.request (/Users/automation/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:122:5919)
    at l (/Users/automation/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:127:11167) {
  clientVersion: '5.14.0'
}
[device-farm-main] PrismaClientValidationError: 
[device-farm-main] Invalid `prisma.sessionLog.create()` invocation:
[device-farm-main] 
[device-farm-main] {
[device-farm-main]   data: {
[device-farm-main]     sessionId: "7c244fd2-bde0-49e7-9759-7140ffff3b7f",
[device-farm-main]     commandName: "execute",
[device-farm-main]     body: "{\"args\":[{\"args\":[\"keyevent\",\"4\"],\"command\":\"input\"}],\"script\":\"mobile: shell\"}",
[device-farm-main]     response: "{\"value\":\"\"}",
[device-farm-main]     isSuccess: "",
[device-farm-main]                ~~
[device-farm-main]     method: "POST",
[device-farm-main]     title: "Execute",
[device-farm-main]     subtitle: "",
[device-farm-main]     screenshot: null,
[device-farm-main]     url: "/session/7c244fd2-bde0-49e7-9759-7140ffff3b7f/execute/sync",
[device-farm-main]     eventId: undefined
[device-farm-main]   }
[device-farm-main] }
[device-farm-main] 
[device-farm-main] Argument `isSuccess`: Invalid value provided. Expected Boolean or Null, provided String.
[device-farm-main]     at Tn (/Users/automation/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:115:6855)
[device-farm-main]     at In.handleRequestError (/Users/automation/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:122:6533)
[device-farm-main]     at In.handleAndLogRequestError (/Users/automation/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:122:6211)
[device-farm-main]     at In.request (/Users/automation/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:122:5919)
[device-farm-main]     at l (/Users/automation/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:127:11167)
[device-farm-main] Promise: 
[device-farm-main] [object Promise]
[HTTP] --> GET /device-farm/api/device
[HTTP] {}
sudharsan-selvaraj commented 5 months ago

Can you share the complete logs as a gist? Also, could please confirm if you are running the server in standalone mode or with hub/node setup?

ilendemli commented 5 months ago

I am trying to gather more information

ilendemli commented 5 months ago

our server is down so I can not execute any tests at the moment, not even locally. I am running the test the same way locally though, so we just run appium --use-plugins=device-farm --config node-config.json --relaxed-security with the node_config.json containing 

{
  "server": {
    "port": 4723,
    "plugin": {
      "device-farm": {
        "platform": "android",
        "iosDeviceType": "both",
        "androidDeviceType": "both",
        "hub": "http://127.0.0.1:4723",
        "skipChromeDownload": true
      }
    }
  }
}

I will confirm the above behaviour as soon as I can run a test locally, the test are executed on real devices

ilendemli commented 5 months ago

@sudharsan-selvaraj can I send you the gist in private?

ilendemli commented 5 months ago

the test cases end with the following error which then stays in limbo:

[HTTP] --> DELETE /session/d2c8f52f-5494-46b5-af60-0179aa9ce1e7
[HTTP] {}
[device-farm-main] Updating lastCmdExecutedAt for device R58NC2N2GYW in session d2c8f52f-5494-46b5-af60-0179aa9ce1e7
Failed to update session: PrismaClientKnownRequestError: 
Invalid `prisma.session.update()` invocation:

An operation failed because it depends on one or more records that were required but not found. Record to update not found.
    at In.handleRequestError (/Users/milendemli/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:122:6877)
    at In.handleAndLogRequestError (/Users/milendemli/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:122:6211)
    at In.request (/Users/milendemli/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:122:5919)
    at l (/Users/milendemli/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:127:11167) {
  code: 'P2025',
  clientVersion: '5.14.0',
  meta: { modelName: 'Session', cause: 'Record to update not found.' }
}
[device-farm-main] ******  UnhandledRejection ******
[device-farm-main] Reason:  
PrismaClientKnownRequestError: 
Invalid `prisma.session.update()` invocation:

An operation failed because it depends on one or more records that were required but not found. Record to update not found.
    at In.handleRequestError (/Users/milendemli/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:122:6877)
    at In.handleAndLogRequestError (/Users/milendemli/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:122:6211)
    at In.request (/Users/milendemli/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:122:5919)
    at l (/Users/milendemli/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:127:11167) {
  code: 'P2025',
  clientVersion: '5.14.0',
  meta: { modelName: 'Session', cause: 'Record to update not found.' }
}
[device-farm-main] PrismaClientKnownRequestError: 
[device-farm-main] Invalid `prisma.session.update()` invocation:
[device-farm-main] 
[device-farm-main] 
[device-farm-main] An operation failed because it depends on one or more records that were required but not found. Record to update not found.
[device-farm-main]     at In.handleRequestError (/Users/milendemli/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:122:6877)
[device-farm-main]     at In.handleAndLogRequestError (/Users/milendemli/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:122:6211)
[device-farm-main]     at In.request (/Users/milendemli/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:122:5919)
[device-farm-main]     at l (/Users/milendemli/.appium/node_modules/appium-device-farm/node_modules/@prisma/client/runtime/library.js:127:11167)
[device-farm-main] Promise: 
[device-farm-main] [object Promise]
ilendemli commented 5 months ago

(this is an iOS issue not really related to above) directly running Appium Inspector with the following capabilities

{
  "platformName": "iOS",
  "appium:platformVersion": "17.4",
  "appium:udid": "70BA8BA8-D2F1-4600-9BC5-B37735255568",
  "appium:automationName": "XCUITest"
}

results in the following:

[AppiumDriver@d49d] Calling AppiumDriver.createSession() with args: [{"platformName":"iOS","appium:platformVersion":"17.4","appium:udid":"70BA8BA8-D2F1-4600-9BC5-B37735255568","appium:automationName":"XCUITest","appium:includeSafariInWebviews":true,"appium:newCommandTimeout":3600,"appium:connectHardwareKeyboard":true},null,{"alwaysMatch":{"platformName":"iOS","appium:platformVersion":"17.4","appium:udid":"70BA8BA8-D2F1-4600-9BC5-B37735255568","appium:automationName":"XCUITest","appium:includeSafariInWebviews":true,"appium:newCommandTimeout":3600,"appium:connectHardwareKeyboard":true},"firstMatch":[{}]}]
[AppiumDriver@d49d] Plugins which can handle cmd 'createSession': device-farm
[AppiumDriver@d49d] Plugin device-farm is now handling cmd 'createSession'
[device-farm-main] 📱 pluginArgs: {"platform":"both","iosDeviceType":"both","androidDeviceType":"both","skipChromeDownload":true,"hub":"http://127.0.0.1:4723","maxSessions":8,"adbRemote":[],"emulators":[],"simulators":[],"deviceAvailabilityTimeoutMs":300000,"deviceAvailabilityQueryIntervalMs":10000,"sendNodeDevicesToHubIntervalMs":30000,"checkStaleDevicesIntervalMs":30000,"checkBlockedDevicesIntervalMs":30000,"newCommandTimeoutSec":60,"bindHostOrIp":"192.168.1.45","enableDashboard":false,"removeDevicesFromDatabaseBeforeRunningThePlugin":false,"remoteConnectionTimeout":60000,"liveStreaming":false,"wdaBundleId":"","preBuildWDAPath":""}
[device-farm-main] Receiving session request at host: 192.168.1.45
[device-farm-main] 📱 Creating temporary session capability_id: 93d978a3-03e7-412f-815c-7293e6f350c8
[device-farm-main] Max session count: 8, Busy device count: 0
[device-farm-main] Waiting for free device. Filter: {"platform":"ios","platformVersion":"17.4","udid":"70BA8BA8-D2F1-4600-9BC5-B37735255568","busy":false,"userBlocked":false}}
[device-farm-main] platformVersion: 17.4
[device-farm-main] Updated devices with filter: {"platform":"ios","udid":{"$in":"70BA8BA8-D2F1-4600-9BC5-B37735255568"},"busy":false,"userBlocked":false}
[device-farm-main] platformVersion: 17.4
[device-farm-main] Updated devices with filter: {"platform":"ios","udid":{"$in":"70BA8BA8-D2F1-4600-9BC5-B37735255568"},"busy":false,"userBlocked":false}
[device-farm-main] 📱 Blocking device 70BA8BA8-D2F1-4600-9BC5-B37735255568 at host http://192.168.1.45:4723 for new session
[device-farm-main] Updating allocated device: "{"userBlocked":false,"offline":false,"sdk":"17.4","lastBootedAt":"2024-05-23T16:40:13Z","dataPath":"/Users/milendemli/Library/Developer/CoreSimulator/Devices/70BA8BA8-D2F1-4600-9BC5-B37735255568/data","dataPathSize":837689344,"logPath":"/Users/milendemli/Library/Logs/CoreSimulator/70BA8BA8-D2F1-4600-9BC5-B37735255568","udid":"70BA8BA8-D2F1-4600-9BC5-B37735255568","isAvailable":true,"logPathSize":147456,"deviceTypeIdentifier":"com.apple.CoreSimulator.SimDeviceType.iPhone-SE-3rd-generation","state":"Booted","name":"iPhone SE (3rd generation)","platform":"ios","wdaLocalPort":55576,"mjpegServerPort":55577,"busy":false,"realDevice":false,"deviceType":"simulator","host":"http://192.168.1.45:4723","totalUtilizationTimeMilliSec":3663873,"sessionStartTime":0,"productModel":"iPhone14,6","width":"375","height":"667","derivedDataPath":"/Users/milendemli/Library/Developer/Xcode/DerivedData/WebDriverAgent-70BA8BA8-D2F1-4600-9BC5-B37735255568","preBuildWDAPath":"","tags":[],"meta":{"revision":2,"created":1716483858048,"version":0,"updated":1716484050631},"$loki":1}"
[device-farm-main] Updated allocated device: "[{"userBlocked":false,"offline":false,"sdk":"17.4","lastBootedAt":"2024-05-23T16:40:13Z","dataPath":"/Users/milendemli/Library/Developer/CoreSimulator/Devices/70BA8BA8-D2F1-4600-9BC5-B37735255568/data","dataPathSize":837689344,"logPath":"/Users/milendemli/Library/Logs/CoreSimulator/70BA8BA8-D2F1-4600-9BC5-B37735255568","udid":"70BA8BA8-D2F1-4600-9BC5-B37735255568","isAvailable":true,"logPathSize":147456,"deviceTypeIdentifier":"com.apple.CoreSimulator.SimDeviceType.iPhone-SE-3rd-generation","state":"Booted","name":"iPhone SE (3rd generation)","platform":"ios","wdaLocalPort":55576,"mjpegServerPort":55577,"busy":true,"realDevice":false,"deviceType":"simulator","host":"http://192.168.1.45:4723","totalUtilizationTimeMilliSec":3663873,"sessionStartTime":0,"productModel":"iPhone14,6","width":"375","height":"667","derivedDataPath":"/Users/milendemli/Library/Developer/Xcode/DerivedData/WebDriverAgent-70BA8BA8-D2F1-4600-9BC5-B37735255568","preBuildWDAPath":"","tags":[],"meta":{"revision":4,"created":1716483858048,"version":0,"updated":1716484066217},"$loki":1,"newCommandTimeout":3600}]"
[device-farm-main] device.host: http://192.168.1.45:4723 and pluginArgs.bindHostOrIp: 192.168.1.45
[device-farm-main] 📱93d978a3-03e7-412f-815c-7293e6f350c8 --- Forwarding session request to http://192.168.1.45:4723
[device-farm-main] Creating session with desiredCapabilities: "{"capabilities":{"alwaysMatch":{"platformName":"iOS","appium:automationName":"XCUITest","appium:includeSafariInWebviews":true,"appium:newCommandTimeout":3600,"appium:connectHardwareKeyboard":true},"firstMatch":[{"appium:udid":"70BA8BA8-D2F1-4600-9BC5-B37735255568","appium:deviceName":"iPhone SE (3rd generation)","appium:platformVersion":"17.4","appium:wdaLocalPort":55576,"appium:mjpegServerPort":55577}],"pendingSessionId":"93d978a3-03e7-412f-815c-7293e6f350c8"}}"
[device-farm-main] With axios config: "{"method":"post","url":"http://192.168.1.45:4723/session","timeout":60000,"httpAgent":{"_events":{},"_eventsCount":2,"defaultPort":80,"protocol":"http:","options":{"keepAlive":true,"keepAliveMsecs":60000,"noDelay":true,"path":null},"requests":{},"sockets":{},"freeSockets":{},"keepAliveMsecs":60000,"keepAlive":true,"maxSockets":null,"maxFreeSockets":256,"scheduling":"lifo","maxTotalSockets":null,"totalSocketCount":0},"httpsAgent":{"_events":{},"_eventsCount":2,"defaultPort":443,"protocol":"https:","options":{"keepAlive":true,"keepAliveMsecs":60000,"noDelay":true,"path":null},"requests":{},"sockets":{},"freeSockets":{},"keepAliveMsecs":60000,"keepAlive":true,"maxSockets":null,"maxFreeSockets":256,"scheduling":"lifo","maxTotalSockets":null,"totalSocketCount":0,"maxCachedSessions":100,"_sessionCache":{"map":{},"list":[]}},"headers":{"Content-Type":"application/json"},"data":{"capabilities":{"alwaysMatch":{"platformName":"iOS","appium:automationName":"XCUITest","appium:includeSafariInWebviews":true,"appium:newCommandTimeout":3600,"appium:connectHardwareKeyboard":true},"firstMatch":[{"appium:udid":"70BA8BA8-D2F1-4600-9BC5-B37735255568","appium:deviceName":"iPhone SE (3rd generation)","appium:platformVersion":"17.4","appium:wdaLocalPort":55576,"appium:mjpegServerPort":55577}],"pendingSessionId":"93d978a3-03e7-412f-815c-7293e6f350c8"}}}"
[device-farm-main] Received error from remote node: {"message":"socket hang up","name":"Error","stack":"Error: socket hang up\n    at Function.AxiosError.from (/Users/milendemli/.appium/node_modules/appium-device-farm/node_modules/axios/lib/core/AxiosError.js:89:14)\n    at RedirectableRequest.handleRequestError (/Users/milendemli/.appium/node_modules/appium-device-farm/node_modules/axios/lib/adapters/http.js:610:25)\n    at RedirectableRequest.emit (node:events:532:35)\n    at ClientRequest.eventHandlers.<computed> (/Users/milendemli/.appium/node_modules/appium-device-farm/node_modules/follow-redirects/index.js:38:24)\n    at ClientRequest.emit (node:events:520:28)\n    at Socket.socketOnEnd (node:_http_client:526:9)\n    at Socket.emit (node:events:532:35)\n    at endReadableNT (node:internal/streams/readable:1696:12)\n    at processTicksAndRejections (node:internal/process/task_queues:82:21)\n    at Axios.request (/Users/milendemli/.appium/node_modules/appium-device-farm/node_modules/axios/lib/core/Axios.js:45:41)\n    at processTicksAndRejections (node:internal/process/task_queues:95:5)","config":{"transitional":{"silentJSONParsing":true,"forcedJSONParsing":true,"clarifyTimeoutError":false},"adapter":["xhr","http","fetch"],"transformRequest":[null],"transformResponse":[null],"timeout":60000,"xsrfCookieName":"XSRF-TOKEN","xsrfHeaderName":"X-XSRF-TOKEN","maxContentLength":-1,"maxBodyLength":-1,"env":{},"headers":{"Accept":"application/json, text/plain, */*","Content-Type":"application/json","User-Agent":"axios/1.7.2","Content-Length":"466","Accept-Encoding":"gzip, compress, deflate, br"},"method":"post","url":"http://192.168.1.45:4723/session","httpAgent":{"_events":{},"_eventsCount":2,"defaultPort":80,"protocol":"http:","options":{"keepAlive":true,"keepAliveMsecs":60000,"noDelay":true,"path":null},"requests":{},"sockets":{"127.0.0.1:9090:":[{"connecting":false,"_hadError":true,"_parent":null,"_host":null,"_closeAfterHandlingError":false,"_events":{"close":[null,null],"end":[null,null],"timeout":[null,null]},"_readableState":{"highWaterMark":65536,"buffer":[],"bufferIndex":0,"length":0,"pipes":[],"awaitDrainWriters":null},"_writableState":{"highWaterMark":65536,"length":0,"corked":0,"writelen":0,"bufferedIndex":0,"pendingcb":0},"allowHalfOpen":false,"_eventsCount":8,"_sockname":null,"_pendingData":null,"_pendingEncoding":"","server":null,"_server":null,"parser":null,"_httpMessage":{"_events":{},"_eventsCount":7,"outputData":[],"outputSize":0,"writable":true,"destroyed":false,"_last":false,"chunkedEncoding":false,"shouldKeepAlive":true,"maxRequestsOnConnectionReached":false,"_defaultKeepAlive":true,"useChunkedEncodingByDefault":true,"sendDate":false,"_removedConnection":false,"_removedContLen":false,"_removedTE":false,"strictContentLength":false,"_contentLength":"466","_hasBody":true,"_trailer":"","finished":true,"_headerSent":true,"_closed":false,"_header":"POST http://192.168.1.45:4723/session HTTP/1.1\r\nAccept: application/json, text/plain, */*\r\nContent-Type: application/json\r\nUser-Agent: axios/1.7.2\r\nContent-Length: 466\r\nAccept-Encoding: gzip, compress, deflate, br\r\nhost: 192.168.1.45:4723\r\nConnection: keep-alive\r\n\r\n","_keepAliveTimeout":0,"method":"POST","path":"http://192.168.1.45:4723/session","_ended":false,"res":null,"aborted":false,"timeoutCb":null,"upgradeOrConnect":false,"parser":null,"maxHeadersCount":null,"reusedSocket":false,"host":"127.0.0.1","protocol":"http:","_redirectable":{"_events":{"socket":[null,null]},"_writableState":{"highWaterMark":65536,"length":0,"corked":0,"writelen":0,"bufferedIndex":0,"pendingcb":0},"_options":{"maxRedirects":21,"maxBodyLength":null,"protocol":"http:","path":"http://192.168.1.45:4723/session","method":"POST","headers":{"Accept":"application/json, text/plain, */*","Content-Type":"application/json","User-Agent":"axios/1.7.2","Content-Length":"466","Accept-Encoding":"gzip, compress, deflate, br","host":"192.168.1.45:4723"},"agents":{"https":{"_events":{},"_eventsCount":2,"defaultPort":443,"protocol":"https:","options":{"keepAlive":true,"keepAliveMsecs":60000,"noDelay":true,"path":null},"requests":{},"sockets":{},"freeSockets":{},"keepAliveMsecs":60000,"keepAlive":true,"maxSockets":null,"maxFreeSockets":256,"scheduling":"lifo","maxTotalSockets":null,"totalSocketCount":0,"maxCachedSessions":100,"_sessionCache":{"map":{},"list":[]}}},"beforeRedirects":{},"hostname":"127.0.0.1","port":"9090","nativeProtocols":{"http:":{"METHODS":["ACL","BIND","CHECKOUT","CONNECT","COPY","DELETE","GET","HEAD","LINK","LOCK","M-SEARCH","MERGE","MKACTIVITY","MKCALENDAR","MKCOL","MOVE","NOTIFY","OPTIONS","PATCH","POST","PROPFIND","PROPPATCH","PURGE","PUT","QUERY","REBIND","REPORT","SEARCH","SOURCE","SUBSCRIBE","TRACE","UNBIND","UNLINK","UNLOCK","UNSUBSCRIBE"],"STATUS_CODES":{"100":"Continue","101":"Switching Protocols","102":"Processing","103":"Early Hints","200":"OK","201":"Created","202":"Accepted","203":"Non-Authoritative Information","204":"No Content","205":"Reset Content","206":"Partial Content","207":"Multi-Status","208":"Already Reported","226":"IM Used","300":"Multiple Choices","301":"Moved Permanently","302":"Found","303":"See Other","304":"Not Modified","305":"Use Proxy","307":"Temporary Redirect","308":"Permanent Redirect","400":"Bad Request","401":"Unauthorized","402":"Payment Required","403":"Forbidden","404":"Not Found","405":"Method Not Allowed","406":"Not Acceptable","407":"Proxy Authentication Required","408":"Request Timeout","409":"Conflict","410":"Gone","411":"Length Required","412":"Precondition Failed","413":"Payload Too Large","414":"URI Too Long","415":"Unsupported Media Type","416":"Range Not Satisfiable","417":"Expectation Failed","418":"I'm a Teapot","421":"Misdirected Request","422":"Unprocessable Entity","423":"Locked","424":"Failed Dependency","425":"Too Early","426":"Upgrade Required","428":"Precondition Required","429":"Too Many Requests","431":"Request Header Fields Too Large","451":"Unavailable For Legal Reasons","500":"Internal Server Error","501":"Not Implemented","502":"Bad Gateway","503":"Service Unavailable","504":"Gateway Timeout","505":"HTTP Version Not Supported","506":"Variant Also Negotiates","507":"Insufficient Storage","508":"Loop Detected","509":"Bandwidth Limit Exceeded","510":"Not Extended","511":"Network Authentication Required"},"maxHeaderSize":16384,"globalAgent":{"_events":{},"_eventsCount":2,"defaultPort":80,"protocol":"http:","options":{"keepAlive":true,"scheduling":"lifo","timeout":5000,"noDelay":true,"path":null},"requests":{},"sockets":{},"freeSockets":{},"keepAliveMsecs":1000,"keepAlive":true,"maxSockets":null,"maxFreeSockets":256,"scheduling":"lifo","maxTotalSockets":null,"totalSocketCount":0}},"https:":{"globalAgent":{"_events":{},"_eventsCount":2,"defaultPort":443,"protocol":"https:","options":{"keepAlive":true,"scheduling":"lifo","timeout":5000,"noDelay":true,"path":null},"requests":{},"sockets":{},"freeSockets":{},"keepAliveMsecs":1000,"keepAlive":true,"maxSockets":null,"maxFreeSockets":256,"scheduling":"lifo","maxTotalSockets":null,"totalSocketCount":0,"maxCachedSessions":100,"_sessionCache":{"map":{},"list":[]}}}},"pathname":"http://192.168.1.45:4723/session"},"_ended":true,"_ending":true,"_redirectCount":0,"_redirects":[],"_requestBodyLength":466,"_requestBodyBuffers":[{"data":{"type":"Buffer","data":[123,34,99,97,112,97,98,105,108,105,116,105,101,115,34,58,123,34,97,108,119,97,121,115,77,97,116,99,104,34,58,123,34,112,108,97,116,102,111,114,109,78,97,109,101,34,58,34,105,79,83,34,44,34,97,112,112,105,117,109,58,97,117,116,111,109,97,116,105,111,110,78,97,109,101,34,58,34,88,67,85,73,84,101,115,116,34,44,34,97,112,112,105,117,109,58,105,110,99,108,117,100,101,83,97,102,97,114,105,73,110,87,101,98,118,105,101,119,115,34,58,116,114,117,101,44,34,97,112,112,105,117,109,58,110,101,119,67,111,109,109,97,110,100,84,105,109,101,111,117,116,34,58,51,54,48,48,44,34,97,112,112,105,117,109,58,99,111,110,110,101,99,116,72,97,114,100,119,97,114,101,75,101,121,98,111,97,114,100,34,58,116,114,117,101,125,44,34,102,105,114,115,116,77,97,116,99,104,34,58,91,123,34,97,112,112,105,117,109,58,117,100,105,100,34,58,34,55,48,66,65,56,66,65,56,45,68,50,70,49,45,52,54,48,48,45,57,66,67,53,45,66,51,55,55,51,53,50,53,53,53,54,56,34,44,34,97,112,112,105,117,109,58,100,101,118,105,99,101,78,97,109,101,34,58,34,105,80,104,111,110,101,32,83,69,32,40,51,114,100,32,103,101,110,101,114,97,116,105,111,110,41,34,44,34,97,112,112,105,117,109,58,112,108,97,116,102,111,114,109,86,101,114,115,105,111,110,34,58,34,49,55,46,52,34,44,34,97,112,112,105,117,109,58,119,100,97,76,111,99,97,108,80,111,114,116,34,58,53,53,53,55,54,44,34,97,112,112,105,117,109,58,109,106,112,101,103,83,101,114,118,101,114,80,111,114,116,34,58,53,53,53,55,55,125,93,44,34,112,101,110,100,105,110,103,83,101,115,115,105,111,110,73,100,34,58,34,57,51,100,57,55,56,97,51,45,48,51,101,55,45,52,49,50,102,45,56,49,53,99,45,55,50,57,51,101,54,102,51,53,48,99,56,34,125,125]}}],"_eventsCount":3,"_currentUrl":"http://192.168.1.45:4723/session","_timeout":null}},"timeout":60000}]},"freeSockets":{},"keepAliveMsecs":60000,"keepAlive":true,"maxSockets":null,"maxFreeSockets":256,"scheduling":"lifo","maxTotalSockets":null,"totalSocketCount":1},"httpsAgent":{"_events":{},"_eventsCount":2,"defaultPort":443,"protocol":"https:","options":{"keepAlive":true,"keepAliveMsecs":60000,"noDelay":true,"path":null},"requests":{},"sockets":{},"freeSockets":{},"keepAliveMsecs":60000,"keepAlive":true,"maxSockets":null,"maxFreeSockets":256,"scheduling":"lifo","maxTotalSockets":null,"totalSocketCount":0,"maxCachedSessions":100,"_sessionCache":{"map":{},"list":[]}},"data":"{\"capabilities\":{\"alwaysMatch\":{\"platformName\":\"iOS\",\"appium:automationName\":\"XCUITest\",\"appium:includeSafariInWebviews\":true,\"appium:newCommandTimeout\":3600,\"appium:connectHardwareKeyboard\":true},\"firstMatch\":[{\"appium:udid\":\"70BA8BA8-D2F1-4600-9BC5-B37735255568\",\"appium:deviceName\":\"iPhone SE (3rd generation)\",\"appium:platformVersion\":\"17.4\",\"appium:wdaLocalPort\":55576,\"appium:mjpegServerPort\":55577}],\"pendingSessionId\":\"93d978a3-03e7-412f-815c-7293e6f350c8\"}}"},"code":"ECONNRESET","status":null}
[device-farm-main] Error while creating session: undefined
[device-farm-main] 📱 93d978a3-03e7-412f-815c-7293e6f350c8 Session response: 
[device-farm-main] {}
[device-farm-main] 📱 Removing pending session with capability_id: 93d978a3-03e7-412f-815c-7293e6f350c8
[device-farm-main] 93d978a3-03e7-412f-815c-7293e6f350c8 📱 Device UDID 70BA8BA8-D2F1-4600-9BC5-B37735255568 unblocked. Reason: Failed to create session
[AppiumDriver@d49d] Command 'createSession' was *not* handled by the following behaviours or plugins, even though they were registered to handle it: ["default"]. The command *was* handled by these: ["device-farm"].
[AppiumDriver@d49d] Encountered internal error running command: Error: Unknown error while creating session
[AppiumDriver@d49d]     at yO.generator (/Users/milendemli/.appium/node_modules/appium-device-farm/lib/webpack:/appium-device-farm/lib/src/plugin.js:434:24)
[AppiumDriver@d49d]     at Generator.throw (<anonymous>)
[AppiumDriver@d49d]     at ye (/Users/milendemli/.appium/node_modules/appium-device-farm/lib/webpack:/appium-device-farm/lib/src/plugin.js:29:47)
[AppiumDriver@d49d]     at processTicksAndRejections (node:internal/process/task_queues:95:5)
[HTTP] <-- POST /session 500 84 ms - 572

node_config.json is configured for both platforms

EDIT: Ok, I figured it out, but I have no fix for it, I am connected to a VPN and behind a proxy, axios tries to send the request to 192.168.1.45:4723 which fails, it should be localhost:4723 or 127.0.0.1:4723

image

EDIT: setting "bindHostOrIp": "127.0.0.1" in the config helps here, but this issue remains

[AppiumDriver@c725] Plugin device-farm is now handling cmd 'createSession'
[device-farm-main] 📱 pluginArgs: {"platform":"both","iosDeviceType":"both","androidDeviceType":"both","skipChromeDownload":true,"hub":"http://127.0.0.1:4723","maxSessions":8,"adbRemote":[],"emulators":[],"simulators":[],"deviceAvailabilityTimeoutMs":300000,"deviceAvailabilityQueryIntervalMs":10000,"sendNodeDevicesToHubIntervalMs":30000,"checkStaleDevicesIntervalMs":30000,"checkBlockedDevicesIntervalMs":30000,"newCommandTimeoutSec":60,"bindHostOrIp":"127.0.0.1","enableDashboard":false,"removeDevicesFromDatabaseBeforeRunningThePlugin":false,"remoteConnectionTimeout":60000,"liveStreaming":false,"wdaBundleId":"","preBuildWDAPath":""}
[device-farm-main] Receiving session request at host: 127.0.0.1
[device-farm-main] 📱 Creating temporary session capability_id: a00f6f9f-2094-4c68-8e52-fb0ef480f7a0
[device-farm-main] Max session count: 8, Busy device count: 0
[device-farm-main] Waiting for free device. Filter: {"platform":"ios","platformVersion":"17.4","udid":"70BA8BA8-D2F1-4600-9BC5-B37735255568","busy":false,"userBlocked":false}}
[device-farm-main] platformVersion: 17.4
[device-farm-main] platformVersion: 17.4
[AppiumDriver@c725] Command 'createSession' was *not* handled by the following behaviours or plugins, even though they were registered to handle it: ["default"]. The command *was* handled by these: ["device-farm"].
[AppiumDriver@c725] Encountered internal error running command: TypeError: Cannot read properties of undefined (reading 'userBlocked')
[AppiumDriver@c725]     at generator (/Users/milendemli/.appium/node_modules/appium-device-farm/lib/webpack:/appium-device-farm/lib/src/data-service/device-service.js:288:33)
[AppiumDriver@c725]     at Generator.next (<anonymous>)
[AppiumDriver@c725]     at E (/Users/milendemli/.appium/node_modules/appium-device-farm/lib/webpack:/appium-device-farm/lib/src/data-service/device-service.js:5:48)
[AppiumDriver@c725]     at processTicksAndRejections (node:internal/process/task_queues:95:5)
[HTTP] <-- POST /session 500 3 ms - 693

EDIT: the Cannot read properties of undefined (reading 'userBlocked') happens when there is no device in the farm to block for session, maybe handling here could be improved, but even if there is a device to block, POST /session with

{
  "capabilities": {
    "alwaysMatch": {
      "platformName": "iOS",
      "appium:automationName": "XCUITest",
      "appium:includeSafariInWebviews": true,
      "appium:newCommandTimeout": 3600,
      "appium:connectHardwareKeyboard": true
    },
    "firstMatch": [
      {
        "appium:udid": "70BA8BA8-D2F1-4600-9BC5-B37735255568",
        "appium:deviceName": "iPhone SE (3rd generation)",
        "appium:platformVersion": "17.4",
        "appium:wdaLocalPort": 54496,
        "appium:mjpegServerPort": 54497
      }
    ],
    "pendingSessionId": "0ad9403f-c96d-429f-979c-8db6caa6240e"
  }
}

fails, it blocks the device for the session, but then it can't continue with the same device or session because it is blocked

ilendemli commented 5 months ago

@sudharsan-selvaraj could i get access to the modules repo for me to try reproduce and fix this?

ilendemli commented 5 months ago

Please trigger a new release candidate so we can try this change. @sudharsan-selvaraj @saikrishna321

dineshzinx commented 5 months ago

Did you try with their latest build 8.4.7-rc.35, I am also facing a similar issue where the session gets stopped when using the startRecordingScreen command. But still the issue persists with the latest build.

saikrishna321 commented 5 months ago

@dineshzinx please raise a new issue with full server logs