search

zebrunner / community-edition

Zebrunner is a Test Automation Management Tool
https://zebrunner.github.io/community-edition
Apache License 2.0
216 stars 53 forks source link

Video is not available on CE with integrated mcloud-agent devices #524

Closed dhreben closed 1 year ago

dhreben commented 2 years ago

Test scenario:

  1. ssh ec2 instance
  2. ./zebrunner.sh setup. - Aws s3 [N]
  3. Open Jenkins and run RegisterHubCredentials
  4. Add STF token to mcloud/variables.env
  5. Update main.yml
  6. Run Mobile-Android-Demo-Test

Actual result: Video is not available on CE with integrated mcloud-agent devices

Note: Screenshots are available

Screenshot 2022-07-06 at 14 52 19

Logs: 

Attacted device udid: F........2369; name: HTC_10
2022-07-06T11:11:25.690Z INF/device:plugins:solo 20 [F........2369] Subscribing to permanent channel "iX7Qn7bXJIWfyx/wqWbnbeAN6dk="
2022-07-06T11:11:25.691Z INF/device:plugins:screen:stream 20 [F........2369] ScreenGrabber option set to minicap-bin
2022-07-06T11:11:25.691Z INF/device:plugins:screen:stream 20 [F........2369] Starting WebSocket server on port 7444
2022-07-06T11:11:25.693Z INF/device:plugins:screen:stream 20 [F........2369] creating FrameProducer: minicap-bin
2022-07-06T11:11:25.933Z INF/device:resources:minitouch 20 [F........2369] Installing "/opt/node_modules/@devicefarmer/minitouch-prebuilt/prebuilt/arm64-v8a/bin/minitouch" as "/data/local/tmp/minitouch"
2022-07-06T11:11:25.966Z WRN/device:plugins:data 20 [F........2369] Unable to find device data {
  serial: 'F........2369',
  platform: 'Android',
  manufacturer: 'HTC',
  operator: null,
  model: 'HTC_10',
  version: '8.0.0',
  abi: 'arm64-v8a',
  sdk: '26',
  product: 'pmeuhl_00709',
  cpuPlatform: 'msm8996',
  openGLESVersion: '0.0',
  marketName: '10',
  display: {
    id: 0,
    width: 1440,
    height: 2560,
    xdpi: 571.5,
    ydpi: 570.385986328125,
    fps: 60.000003814697266,
    density: 4,
    rotation: 0,
    secure: true,
    size: 5.147101268933361,
    url: 'ws://3.210.50.48:80/d/demo.zebrunner.farm/F........2369/7444/'
  },
  phone: [Object: null prototype] { network: 'UNKNOWN' },
  module: 'HTC_10'
}
2022-07-06T11:11:25.968Z INF/device:plugins:touch 20 [F........2369] Touch origin is top left
2022-07-06T11:11:25.973Z INF/device:plugins:touch 20 [F........2369] Connecting to minitouch service
2022-07-06T11:11:26.015Z INF/device:plugins:touch 20 [F........2369] minitouch says: "Note: device /dev/input/mouse0 is not supported by libevdev"
2022-07-06T11:11:26.016Z INF/device:plugins:touch 20 F........2369] minitouch says: "Note: device /dev/input/mice is not supported by libevdev"
2022-07-06T11:11:26.016Z INF/device:plugins:touch 20 [F........2369] minitouch says: "Type B touch device synaptics_dsx (1439x2559 with 10 contacts) detected on /dev/input/event8 (score 22927)"
2022-07-06T11:11:26.084Z INF/device:plugins:touch 20 [F........2369] Reading minitouch banner
2022-07-06T11:11:26.086Z INF/device:plugins:touch 20 [F........2369] minitouch says: "Connection established"
2022-07-06T11:11:26.135Z INF/device:plugins:vnc 20 [F........2369] Starting VNC server on port 5900
2022-07-06T11:11:26.139Z INF/device:plugins:browser 20 [F........2369] Loading browser list
2022-07-06T11:11:26.222Z INF/device:plugins:browser 20 [F........2369] Updating browser list
2022-07-06T11:11:26.226Z INF/device:plugins:mute 20 [F........2369] Will not mute master volume
2022-07-06T11:11:26.465Z INF/device:resources:minirev 20 [F........2369] Installing "/opt/vendor/minirev/arm64-v8a/minirev" as "/data/local/tmp/minirev"
2022-07-06T11:11:26.499Z INF/device:plugins:forward 20 [F........2369] Launching reverse port forwarding service
2022-07-06T11:11:26.508Z INF/device:plugins:forward 20 [F........2369] Connecting to reverse port forwarding service
2022-07-06T11:11:26.621Z INF/device 20 [F........2369] Fully operational
2022-07-06T11:11:28.966Z INF/provider 7 [*] Providing all 1 device(s)
2022-07-06T11:12:20.249Z FTL/util:lifecycle 20 [F........2369] Forward shell ended; we shall share its fate
2022-07-06T11:12:20.252Z FTL/util:lifecycle 20 [F........2369] Shutting down due to fatal error with optional error :  undefined
2022-07-06T11:12:20.255Z FTL/util:lifecycle 7 [*] Tracker had an error Error: Connection closed
    at /opt/node_modules/@devicefarmer/adbkit/lib/adb/tracker.js:21:13
    at tryCatcher (/opt/node_modules/@devicefarmer/adbkit/node_modules/bluebird/js/main/util.js:26:23)
    at CatchFilter.doFilter (/opt/node_modules/@devicefarmer/adbkit/node_modules/bluebird/js/main/catch_filter.js:40:36)
    at CatchFilter.tryCatcher (/opt/node_modules/@devicefarmer/adbkit/node_modules/bluebird/js/main/util.js:26:23)
    at Promise._settlePromiseFromHandler (/opt/node_modules/@devicefarmer/adbkit/node_modules/bluebird/js/main/promise.js:503:31)
    at Promise._settlePromiseAt (/opt/node_modules/@devicefarmer/adbkit/node_modules/bluebird/js/main/promise.js:577:18)
    at Promise._settlePromises (/opt/node_modules/@devicefarmer/adbkit/node_modules/bluebird/js/main/promise.js:693:14)
    at Async._drainQueue (/opt/node_modules/@devicefarmer/adbkit/node_modules/bluebird/js/main/async.js:123:16)
    at Async._drainQueues (/opt/node_modules/@devicefarmer/adbkit/node_modules/bluebird/js/main/async.js:133:10)
    at Immediate.Async.drainQueues [as _onImmediate] (/opt/node_modules/@devicefarmer/adbkit/node_modules/bluebird/js/main/async.js:15:14)
    at processImmediate (node:internal/timers:466:21)
2022-07-06T11:12:20.255Z FTL/util:lifecycle 7 [*] Shutting down due to fatal error with optional error :  undefined
Exit status: 1
2022-07-06T11:12:31.325Z INF/provider 7 [*] Subscribing to permanent channel "zJExTChaTO+3qJsIX8urWQ=="
2022-07-06T11:12:31.331Z INF/db 7 [*] Connecting to 3.210.50.48:28015
2022-07-06T11:12:31.333Z INF/provider 7 [*] Sending output to "tcp://3.210.50.48:7270"
2022-07-06T11:12:31.334Z INF/provider 7 [*] Receiving input from "tcp://3.210.50.48:7250"
2022-07-06T11:12:31.340Z INF/provider 7 [*] output promise resolve  [Function (anonymous)]
2022-07-06T11:12:31.818Z INF/provider 7 [*] DeviceRegisteredMessage , channel  <Buffer 7a 4a 45 78 54 43 68 61 54 4f 2b 33 71 4a 73 49 58 38 75 72 57 51 3d 3d>
2022-07-06T11:12:31.820Z INF/provider 7 [*] DeviceRegisteredMessage , channel  { serial: 'F........2369' }
2022-07-06T11:12:31.823Z INF/provider 7 [*] deviceListener , output type : register
2022-07-06T11:12:31.824Z INF/provider 7 [*] Registered device "F........2369"
2022-07-06T11:12:32.151Z INF/db 20 [F........2369] Connecting to 3.210.50.48:28015
2022-07-06T11:12:32.155Z INF/device:support:push 20 [F........2369] Sending output to "tcp://3.210.50.48:7270"
2022-07-06T11:12:32.156Z INF/device 20 [F........2369] Preparing device
2022-07-06T11:12:32.438Z INF/device:support:sub 20 [F........2369] Receiving input from "tcp://3.210.50.48:7250"
2022-07-06T11:12:32.440Z INF/device:support:sub 20 [F........2369] Subscribing to permanent channel "*ALL"
2022-07-06T11:12:32.510Z INF/device:support:properties 20 [F........2369] Loading properties
2022-07-06T11:12:32.562Z INF/device:support:sdk 20 [F........2369] Supports SDK 26
2022-07-06T11:12:32.565Z INF/device:support:abi 20 [F........2369] Supports ABIs arm64-v8a, armeabi-v7a, armeabi
2022-07-06T11:12:32.817Z INF/device:resources:minicap 20 [F........2369] Installing "/opt/node_modules/@devicefarmer/minicap-prebuilt/prebuilt/arm64-v8a/bin/minicap" as "/data/local/tmp/minicap"
2022-07-06T11:12:32.820Z INF/device:resources:minicap 20 [F........2369] Installing "/opt/node_modules/@devicefarmer/minicap-prebuilt/prebuilt/arm64-v8a/lib/android-26/minicap.so" as "/data/local/tmp/minicap.so"
2022-07-06T11:12:32.823Z INF/device:resources:minicap 20 [F........2369] Installing "/opt/node_modules/@devicefarmer/minicap-prebuilt/prebuilt/noarch/minicap.apk" as "/data/local/tmp/minicap.apk"
2022-07-06T11:12:33.174Z INF/device:resources:service 20 [F........2369] Checking whether we need to install STFService
2022-07-06T11:12:33.593Z INF/device:resources:service 20 [F........2369] Running version check
2022-07-06T11:12:34.066Z INF/device:resources:service 20 [F........2369] STFService up to date
2022-07-06T11:12:34.067Z INF/device:plugins:service 20 [F........23699] Launching agent
2022-07-06T11:12:34.717Z INF/device:plugins:service 20 F........2369] Agent says: "Starting minitouch agent"
2022-07-06T11:12:34.730Z INF/device:plugins:service 20 [F........2369] Agent says: "Listening on @stfagent"
2022-07-06T11:12:34.818Z INF/device:plugins:service 20 [F........2369] Launching service
2022-07-06T11:12:34.818Z INF/device:plugins:service 20 [F........2369] using 'start-foreground-service' command for API 26
2022-07-06T11:12:34.833Z INF/device:plugins:service 20 F........2369] Agent says: "InputClient started"
2022-07-06T11:12:34.898Z INF/device:plugins:display 20 [F........2369] Reading display info
2022-07-06T11:12:34.968Z INF/device:plugins:phone 20 [F........2369] Fetching phone info
2022-07-06T11:12:35.012Z INF/device:plugins:identity 20 [F........2369] Solving identity

Appium logs:

2022-07-06 10:47:34:657 - [HTTP] <-- GET /wd/hub/session/21bb2c3d-2966-4ab0-983d-ae7700d0a1be/screenshot 200 2697 ms - 2572966
2022-07-06 10:47:34:657 - [HTTP] 
2022-07-06 10:47:36:223 - [HTTP] --> POST /wd/hub/session/21bb2c3d-2966-4ab0-983d-ae7700d0a1be/timeouts
2022-07-06 10:47:36:224 - [HTTP] {"pageLoad":300000}
2022-07-06 10:47:36:224 - [debug] [W3C (21bb2c3d)] Calling AppiumDriver.timeouts() with args: [null,null,null,300000,null,"21bb2c3d-2966-4ab0-983d-ae7700d0a1be"]
2022-07-06 10:47:36:225 - [debug] [BaseDriver] W3C timeout argument: {"pageLoad":300000}}
2022-07-06 10:47:36:228 - [debug] [W3C (21bb2c3d)] Encountered internal error running command: Not implemented yet for pageLoad.[[[--udid F........2369 --name HTC_10 --sessionId 21bb2c3d-2966-4ab0-983d-ae7700d0a1be]]]
2022-07-06 10:47:36:228 - [debug] [W3C (21bb2c3d)] NotImplementedError: Not implemented yet for pageLoad.
2022-07-06 10:47:36:229 - [debug] [W3C (21bb2c3d)]     at AndroidUiautomator2Driver.pageLoadTimeoutW3C (/usr/lib/node_modules/appium/node_modules/appium-base-driver/lib/basedriver/commands/timeout.js:83:9)
2022-07-06 10:47:36:229 - [debug] [W3C (21bb2c3d)]     at AndroidUiautomator2Driver.timeouts (/usr/lib/node_modules/appium/node_modules/appium-base-driver/lib/basedriver/commands/timeout.js:40:16)
2022-07-06 10:47:36:230 - [debug] [W3C (21bb2c3d)]     at commandExecutor (/usr/lib/node_modules/appium/node_modules/appium-base-driver/lib/basedriver/driver.js:374:9)
2022-07-06 10:47:36:230 - [debug] [W3C (21bb2c3d)]     at /usr/lib/node_modules/appium/node_modules/async-lock/lib/index.js:146:12
2022-07-06 10:47:36:230 - [debug] [W3C (21bb2c3d)]     at AsyncLock._promiseTry (/usr/lib/node_modules/appium/node_modules/async-lock/lib/index.js:280:31)
2022-07-06 10:47:36:231 - [debug] [W3C (21bb2c3d)]     at exec (/usr/lib/node_modules/appium/node_modules/async-lock/lib/index.js:145:9)
2022-07-06 10:47:36:231 - [debug] [W3C (21bb2c3d)]     at AsyncLock.acquire (/usr/lib/node_modules/appium/node_modules/async-lock/lib/index.js:162:3)
2022-07-06 10:47:36:231 - [debug] [W3C (21bb2c3d)]     at AndroidUiautomator2Driver.executeCommand (/usr/lib/node_modules/appium/node_modules/appium-base-driver/lib/basedriver/driver.js:391:39)
2022-07-06 10:47:36:232 - [debug] [W3C (21bb2c3d)]     at AppiumDriver.executeCommand (/usr/lib/node_modules/appium/lib/appium.js:563:36)
2022-07-06 10:47:36:232 - [debug] [W3C (21bb2c3d)]     at runMicrotasks (<anonymous>)
2022-07-06 10:47:36:232 - [debug] [W3C (21bb2c3d)]     at processTicksAndRejections (internal/process/task_queues.js:97:5)
2022-07-06 10:47:36:233 - [debug] [W3C (21bb2c3d)]     at asyncHandler (/usr/lib/node_modules/appium/node_modules/appium-base-driver/lib/protocol/protocol.js:297:21)
2022-07-06 10:47:36:234 - [HTTP] <-- POST /wd/hub/session/21bb2c3d-2966-4ab0-983d-ae7700d0a1be/timeouts 405 11 ms - 1491
2022-07-06 10:47:36:235 - [HTTP] 
2022-07-06 10:47:37:203 - [HTTP] --> POST /wd/hub/session/21bb2c3d-2966-4ab0-983d-ae7700d0a1be/elements
2022-07-06 10:47:37:204 - [HTTP] {"using":"id","value":"content_frame"}
2022-07-06 10:47:37:204 - [debug] [W3C (21bb2c3d)] Calling AppiumDriver.findElements() with args: ["id","content_frame","21bb2c3d-2966-4ab0-983d-ae7700d0a1be"]
2022-07-06 10:47:37:204 - [debug] [BaseDriver] Valid locator strategies for this request: xpath, id, class name, accessibility id, css selector, -android uiautomator
2022-07-06 10:47:37:204 - [debug] [BaseDriver] Waiting up to 0 ms for condition
2022-07-06 10:47:37:205 - [debug] [WD Proxy] Matched '/elements' to command name 'findElements'
2022-07-06 10:47:37:205 - [debug] [WD Proxy] Proxying [POST /elements] to [POST http://127.0.0.1:8200/wd/hub/session/d98f684c-1cab-4312-ac17-1bd5cf441dff/elements] with body: {"strategy":"id","selector":"content_frame","context":"","multiple":true}
2022-07-06 10:47:37:505 - [debug] [WD Proxy] Got response with status 200: {"sessionId":"d98f684c-1cab-4312-ac17-1bd5cf441dff","value":[{"ELEMENT":"00000000-0000-00b2-ffff-ffff00000039","element-6066-11e4-a52e-4f735466cecf":"00000000-0000-00b2-ffff-ffff00000039"}]}
2022-07-06 10:47:37:506 - [debug] [W3C (21bb2c3d)] Responding to client with driver.findElements() result: [{"element-6066-11e4-a52e-4f735466cecf":"00000000-0000-00b2-ffff-ffff00000039","ELEMENT":"00000000-0000-00b2-ffff-ffff00000039"}]
2022-07-06 10:47:37:508 - [HTTP] <-- POST /wd/hub/session/21bb2c3d-2966-4ab0-983d-ae7700d0a1be/elements 200 303 ms - 139
2022-07-06 10:47:37:508 - [HTTP] 
2022-07-06 10:47:37:622 - [HTTP] --> GET /wd/hub/session/21bb2c3d-2966-4ab0-983d-ae7700d0a1be/element/00000000-0000-00b2-ffff-ffff00000039/displayed
2022-07-06 10:47:37:622 - [HTTP] {}
2022-07-06 10:47:37:623 - [debug] [W3C (21bb2c3d)] Calling AppiumDriver.elementDisplayed() with args: ["00000000-0000-00b2-ffff-ffff00000039","21bb2c3d-2966-4ab0-983d-ae7700d0a1be"]
2022-07-06 10:47:37:625 - [debug] [WD Proxy] Matched '/element/00000000-0000-00b2-ffff-ffff00000039/attribute/displayed' to command name 'getAttribute'
2022-07-06 10:47:37:625 - [debug] [WD Proxy] Proxying [GET /element/00000000-0000-00b2-ffff-ffff00000039/attribute/displayed] to [GET http://127.0.0.1:8200/wd/hub/session/d98f684c-1cab-4312-ac17-1bd5cf441dff/element/00000000-0000-00b2-ffff-ffff00000039/attribute/displayed] with no body
2022-07-06 10:47:37:658 - [debug] [WD Proxy] Got response with status 200: {"sessionId":"d98f684c-1cab-4312-ac17-1bd5cf441dff","value":"true"}
2022-07-06 10:47:37:659 - [debug] [W3C (21bb2c3d)] Responding to client with driver.elementDisplayed() result: true
2022-07-06 10:47:37:659 - [HTTP] <-- GET /wd/hub/session/21bb2c3d-2966-4ab0-983d-ae7700d0a1be/element/00000000-0000-00b2-ffff-ffff00000039/displayed 200 37 ms - 14
2022-07-06 10:47:37:659 - [HTTP] 
2022-07-06 10:47:37:870 - [HTTP] --> DELETE /wd/hub/session/21bb2c3d-2966-4ab0-983d-ae7700d0a1be
2022-07-06 10:47:37:871 - [HTTP] {}
2022-07-06 10:47:37:872 - [debug] [W3C (21bb2c3d)] Calling AppiumDriver.deleteSession() with args: ["21bb2c3d-2966-4ab0-983d-ae7700d0a1be"]
2022-07-06 10:47:37:873 - [debug] [BaseDriver] Event 'quitSessionRequested' logged at 1657104457872 (03:47:37 GMT-0700 (Pacific Daylight Time))
2022-07-06 10:47:37:874 - [Appium] Removing session 21bb2c3d-2966-4ab0-983d-ae7700d0a1be from our master session list
2022-07-06 10:47:37:875 - [debug] [UiAutomator2] Deleting UiAutomator2 session
2022-07-06 10:47:37:875 - [debug] [UiAutomator2] Deleting UiAutomator2 server session
2022-07-06 10:47:37:875 - [debug] [WD Proxy] Matched '/' to command name 'deleteSession'
2022-07-06 10:47:37:875 - [debug] [WD Proxy] Proxying [DELETE /] to [DELETE http://127.0.0.1:8200/wd/hub/session/d98f684c-1cab-4312-ac17-1bd5cf441dff] with no body
2022-07-06 10:47:37:926 - [debug] [WD Proxy] Got response with status 200: {"sessionId":"d98f684c-1cab-4312-ac17-1bd5cf441dff","value":null}
2022-07-06 10:47:37:927 - [debug] [ADB] Running '/root/platform-tools/adb -P 5037 -s F........2369 shell am force-stop com.solvd.carinademoapplication'
2022-07-06 10:47:38:067 - [debug] [Logcat] Stopping logcat capture
2022-07-06 10:47:38:073 - [debug] [ADB] Removing forwarded port socket connection: 8200 
2022-07-06 10:47:38:074 - [debug] [ADB] Running '/root/platform-tools/adb -P 5037 -s F........2369 forward --remove tcp:8200'
2022-07-06 10:47:38:098 - [debug] [BaseDriver] [MCLOUD] stopping capturing artifacts for session 21bb2c3d-2966-4ab0-983d-ae7700d0a1be
2022-07-06 10:47:38:134 - [BaseDriver] [MCLOUD] [MCLOUD] stop capturing artifacts command was successfully executed
2022-07-06 10:47:38:135 - [BaseDriver] [MCLOUD] [MCLOUD] start capturing artifacts error: Command failed: /opt/start-capture-artifacts.sh 21bb2c3d-2966-4ab0-983d-ae7700d0a1be >> /tmp/video.log 2>&1
2022-07-06 10:47:38:135 - [BaseDriver] 
2022-07-06 10:47:38:272 - [debug] [Instrumentation] .
2022-07-06 10:47:38:301 - [debug] [Instrumentation] Time: 58.181
2022-07-06 10:47:38:301 - [debug] [Instrumentation] 
2022-07-06 10:47:38:301 - [debug] [Instrumentation] OK (1 test)
2022-07-06 10:47:38:413 - [debug] [BaseDriver] [MCLOUD] uploading captured artifacts
2022-07-06 10:47:38:421 - [debug] [BaseDriver] Event 'quitSessionFinished' logged at 1657104458421 (03:47:38 GMT-0700 (Pacific Daylight Time))
2022-07-06 10:47:38:422 - [debug] [W3C (21bb2c3d)] Received response: null
2022-07-06 10:47:38:422 - [debug] [W3C (21bb2c3d)] But deleting session, so not returning
2022-07-06 10:47:38:422 - [debug] [W3C (21bb2c3d)] Responding to client with driver.deleteSession() result: null
2022-07-06 10:47:38:422 - [HTTP] <-- DELETE /wd/hub/session/21bb2c3d-2966-4ab0-983d-ae7700d0a1be 200 553 ms - 14
2022-07-06 10:47:38:423 - [HTTP] 
2022-07-06 10:47:38:607 - [debug] [Instrumentation] The process has exited with code 0
2022-07-06 10:47:39:109 - [HTTP] --> GET /wd/hub/status
2022-07-06 10:47:39:109 - [HTTP] {}
2022-07-06 10:47:39:109 - [debug] [GENERIC] Calling AppiumDriver.getStatus() with args: []
2022-07-06 10:47:39:109 - [debug] [GENERIC] Responding to client with driver.getStatus() result: {"build":{"version":"1.22.2"}}
2022-07-06 10:47:39:110 - [HTTP] <-- GET /wd/hub/status 200 1 ms - 68
2022-07-06 10:47:39:110 - [HTTP] 
2022-07-06 10:47:40:739 - [BaseDriver] [MCLOUD] [MCLOUD] upload captured artifacts stderr: upload failed: ./21bb2c3d-2966-4ab0-983d-ae7700d0a1be.log to s3://zebrunner.org-engine/artifacts/test-sessions/21bb2c3d-2966-4ab0-983d-ae7700d0a1be/session.log An error occurred (InvalidAccessKeyId) when calling the PutObject operation: The AWS Access Key Id you provided does not exist in our records.
2022-07-06 10:47:40:740 - [BaseDriver] upload failed: ./21bb2c3d-2966-4ab0-983d-ae7700d0a1be.mp4 to s3://zebrunner.org-engine/artifacts/test-sessions/21bb2c3d-2966-4ab0-983d-ae7700d0a1be/video.mp4 An error occurred (InvalidAccessKeyId) when calling the PutObject operation: The AWS Access Key Id you provided does not exist in our records.
vdelendik commented 1 year ago

@dhreben it should work if you configure correctly mcloud-agent pointing to the minio storage (make sure minio host/port available from the agent server)

dhreben commented 1 year ago

Video is available Closed