search

OpenVidu / openvidu-loadtest

OpenVidu load testing environment
Apache License 2.0
32 stars 19 forks source link

startSessionBrowserAfterBrowser:444 Session did not reach stable status in timeout #3

Closed umarF closed 4 months ago

umarF commented 4 years ago

I need to perform the load test and I am using version 2.13 and using region eu-west-1.

I notice that when I run load-test, it fails with this error:

Screenshot 2020-05-24 at 20 00 10 Screenshot 2020-05-24 at 20 00 02

Command and config i use: mvn -DOPENVIDU_SECRET=XXX -DOPENVIDU_URL=XXX -DREMOTE=true -DUSERS_SESSION=1 -DSESSION=1 -DBROWSER_INIT_AT_ONCE=true -DSECONDS_OF_WAIT=180 test

Thanks!

CSantosM commented 4 years ago

What openvidu-loadtest are you using?

You're launching a test with 1 users in 1 session. The orchestrator launch a session and then check if has reached the sessions limit and finish.

If you can try a single session with a single user (that really doesn't make sense) you can check webcomponent_loadtest branch and configure this line to wait X seconds before the test finish. https://github.com/OpenVidu/openvidu-loadtest/blob/fc1c8391b5cd0818ea18f911358effe2835e37e7/selenium-test/src/test/java/io/openvidu/load/test/OpenViduLoadTest.java#L133

umarF commented 4 years ago

I tried it with the default settings of sessions and users, but it was the same error. I did this to check if my AWS machines were being deployed and accessed which they were..

"What openvidu-loadtest are you using?"
I am using Master branch. I am using whatever is the one provided in the tutorials mentioned here https://github.com/OpenVidu/openvidu-loadtest.

I have my openvidu pro server deployed and i want to use the orchestrator to run clients and load my deployed pro server. I need to run benchmarks about user and sessions with regards to deployed media nodes type (c5, c5.large, etc).

CSantosM commented 4 years ago

Are you able to launch a browser in your AWS EC2 stack executing browserProvider.sh script?

umarF commented 4 years ago

createAMI.sh worked fine and browserProvider.sh script does launch my instances on AWS based on the number of session and users

CSantosM commented 4 years ago

Try to increase the number of participants and users to check if this is the problem please

umarF commented 4 years ago

Test Start Config:

13:12:12,103 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
13:12:12,103 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
13:12:12,103 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/home/ubuntu/openvidu-loadtest/selenium-test/target/test-classes/logback.xml]
13:12:12,146 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
13:12:12,150 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
13:12:12,152 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [Console]
13:12:12,177 |-WARN in ch.qos.logback.core.ConsoleAppender[Console] - This appender no longer admits a layout as a sub-component, set an encoder instead.
13:12:12,177 |-WARN in ch.qos.logback.core.ConsoleAppender[Console] - To ensure compatibility, wrapping your layout in LayoutWrappingEncoder.
13:12:12,177 |-WARN in ch.qos.logback.core.ConsoleAppender[Console] - See also http://logback.qos.ch/codes.html#layoutInsteadOfEncoder for details
13:12:12,177 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.FileAppender]
13:12:12,178 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [File]
13:12:12,180 |-INFO in ch.qos.logback.core.FileAppender[File] - File property is set to [./logs/test.log]
13:12:12,181 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
13:12:12,181 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [File] to Logger[ROOT]
13:12:12,181 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [Console] to Logger[ROOT]
13:12:12,181 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
13:12:12,182 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@1a38c59b - Registering current configuration as safe fallback point

2020-05-25 13:12:12,381 INFO  [main] io.github.bonigarcia.wdm.WebDriverManager.getDriversFromXml(999): Reading https://chromedriver.storage.googleapis.com/ to seek chromedriver
2020-05-25 13:12:13,022 INFO  [main] io.github.bonigarcia.wdm.WebDriverManager.checkLatest(884): Latest version of chromedriver is 83.0.4103.39
2020-05-25 13:12:13,034 INFO  [main] io.github.bonigarcia.wdm.Downloader.checkBinary(167): Using binary driver previously downloaded
2020-05-25 13:12:13,035 INFO  [main] io.github.bonigarcia.wdm.WebDriverManager.exportDriver(1035): Exporting webdriver.chrome.driver as /root/.m2/repository/webdriver/chromedriver/linux64/83.0.4103.39/chromedriver
2020-05-25 13:12:13,037 INFO  [main] io.openvidu.load.test.OpenViduLoadTest.initializeRecordBrowsersProperty(857): Recording browsers [0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
2020-05-25 13:12:13,054 INFO  [main] io.openvidu.load.test.OpenViduLoadTest.initializeNetworkRestrictionsBrowsersProperty(947): Network restricitions [{"ALL_OPEN":3}, {"ALL_OPEN":3}, {"ALL_OPEN":3}, {"ALL_OPEN":3}, {"ALL_OPEN":3}, {"ALL_OPEN":3}, {"ALL_OPEN":3}, {"ALL_OPEN":3}, {"ALL_OPEN":3}, {"ALL_OPEN":3}]
2020-05-25 13:12:13,062 INFO  [main] io.openvidu.load.test.OpenViduLoadTest.setup(288): 
------------ TEST CONFIGURATION ----------
OpenVidu URL:          ov2.penguinpass.it
OpenVidu secret:       XXXXX
App URL:               http://localhost:8080/
Session limit:         10
Users per session:     3
Expected browsers:     30
Expected Publishers:   30
Expected Subscribers:  60
Browsers init at once: true
Browsers recorded:     [0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
Browsers networking:   [{"ALL_OPEN":3}, {"ALL_OPEN":3}, {"ALL_OPEN":3}, {"ALL_OPEN":3}, {"ALL_OPEN":3}, {"ALL_OPEN":3}, {"ALL_OPEN":3}, {"ALL_OPEN":3}, {"ALL_OPEN":3}, {"ALL_OPEN":3}]
Start tcpdump before connect:  false
Tcpdump during:        5 s
Is remote:             true
Results stored under:  /opt/openvidu/testload/loadtest_2020-05-25_13:12:13
----------------------------------------
2020-05-25 13:12:13,067 INFO  [main] io.openvidu.load.test.OpenViduLoadTest.loadTest(376): Starting load test
2020-05-25 13:12:13,321 INFO  [main] io.openvidu.load.test.utils.OpenViduServerMonitor.deleteAllTurnLogs(101): Cleaning COTURN logs in OpenVidu Server
2020-05-25 13:12:13,554 INFO  [main] io.openvidu.load.test.utils.OpenViduServerMonitor.deleteAllTurnLogs(104): COTURN logs cleaned up in OpenVidu Server
2020-05-25 13:12:13,555 INFO  [main] io.openvidu.load.test.OpenViduServerManager.startMonitoringPolling(82): OpenVidu Server net, cpu and mem usage is now being monitored (in an interval of 5000 ms)
2020-05-25 13:12:13,556 INFO  [main] io.openvidu.load.test.OpenViduLoadTest.startSessionAllBrowsersAtOnce(511): Starting session: session-1
2020-05-25 13:12:13,556 INFO  [main] io.openvidu.load.test.OpenViduLoadTest.startMultipleBrowsers(565): Starting users: [user-1-1, user-1-2, user-1-3]
2020-05-25 13:12:13,569 INFO  [Thread-4] io.openvidu.load.test.OpenViduServerManager.lambda$startMonitoringPolling$0(69): 1590412334105 - NetInfo [netInfoMap={ens5=NetInfoEntry [rxBytes=0, txBytes=0], veth3fc53fc=NetInfoEntry [rxBytes=0, txBytes=0], veth6138322=NetInfoEntry [rxBytes=0, txBytes=0], vethfe28399=NetInfoEntry [rxBytes=0, txBytes=0]}],  CpuUsage [1.6992939166000203], MemUsage [used: 2605852.0, percentage: 68.55867071762852]]
2020-05-25 13:12:18,581 INFO  [Thread-4] io.openvidu.load.test.OpenViduServerManager.lambda$startMonitoringPolling$0(69): 1590412339119 - NetInfo [netInfoMap={ens5=NetInfoEntry [rxBytes=190619, txBytes=193406], veth3fc53fc=NetInfoEntry [rxBytes=0, txBytes=0], veth6138322=NetInfoEntry [rxBytes=5867, txBytes=2467], vethfe28399=NetInfoEntry [rxBytes=2467, txBytes=5867]}],  CpuUsage [0.9985044865403789], MemUsage [used: 2604824.0, percentage: 68.53162454866047]]
2020-05-25 13:12:23,593 INFO  [Thread-4] io.openvidu.load.test.OpenViduServerManager.lambda$startMonitoringPolling$0(69): 1590412344131 - NetInfo [netInfoMap={ens5=NetInfoEntry [rxBytes=485219, txBytes=497591], veth3fc53fc=NetInfoEntry [rxBytes=0, txBytes=0], veth6138322=NetInfoEntry [rxBytes=12755, txBytes=4923], vethfe28399=NetInfoEntry [rxBytes=5691, txBytes=14074]}],  CpuUsage [1.1006006006006006], MemUsage [used: 2606660.0, percentage: 68.5799287959614]]
2020-05-25 13:12:28,605 INFO  [Thread-4] io.openvidu.load.test.OpenViduServerManager.lambda$startMonitoringPolling$0(69): 1590412349144 - NetInfo [netInfoMap={ens5=NetInfoEntry [rxBytes=676962, txBytes=692660], veth3fc53fc=NetInfoEntry [rxBytes=0, txBytes=0], veth6138322=NetInfoEntry [rxBytes=21373, txBytes=7950], vethfe28399=NetInfoEntry [rxBytes=9102, txBytes=23322]}],  CpuUsage [0.9], MemUsage [used: 2605900.0, percentage: 68.55993357376711]]
2020-05-25 13:12:33,617 INFO  [Thread-4] io.openvidu.load.test.OpenViduServerManager.lambda$startMonitoringPolling$0(69): 1590412354155 - NetInfo [netInfoMap={ens5=NetInfoEntry [rxBytes=870665, txBytes=890736], veth3fc53fc=NetInfoEntry [rxBytes=0, txBytes=0], veth6138322=NetInfoEntry [rxBytes=25312, txBytes=9648], vethfe28399=NetInfoEntry [rxBytes=10800, txBytes=27261]}],  CpuUsage [0.7], MemUsage [used: 2606604.0, percentage: 68.5784554637997]]
2020-05-25 13:12:38,629 INFO  [Thread-4] io.openvidu.load.test.OpenViduServerManager.lambda$startMonitoringPolling$0(69): 1590412359168 - NetInfo [netInfoMap={ens5=NetInfoEntry [rxBytes=1065288, txBytes=1088221], veth3fc53fc=NetInfoEntry [rxBytes=0, txBytes=0], veth6138322=NetInfoEntry [rxBytes=34795, txBytes=13160], vethfe28399=NetInfoEntry [rxBytes=15848, txBytes=39503]}],  CpuUsage [0.9], MemUsage

EC2 spinned up

0 INFO  [Thread-4] io.openvidu.load.test.OpenViduServerManager.lambda$startMonitoringPolling$0(69): 1590412364180 - NetInfo [netInfoMap={ens5=NetInfoEntry [rxBytes=1358755, txBytes=1403542], veth3fc53fc=NetInfoEntry [rxBytes=0, txBytes=0], veth6138322=NetInfoEntry [rxBytes=41776, txBytes=16790], vethfe28399=NetInfoEntry [rxBytes=19862, txBytes=47110]}],  CpuUsage [1.0994005994005995], MemUsage [used: 2605928.0, percentage: 68.56067023984795]]
2020-05-25 13:12:48,483 INFO  [main] io.openvidu.load.test.utils.ScriptExecutor.parseInstanceJsonToMap(116): Instances: {i-00680257164ecb46c={id: "i-00680257164ecb46c", publicIp: "52.210.198.4", privateIp: "172.31.21.64"}, i-013f51f051eb2cab6={id: "i-013f51f051eb2cab6", publicIp: "54.154.33.11", privateIp: "172.31.25.27"}, i-0efc631646ca81948={id: "i-0efc631646ca81948", publicIp: "3.250.155.174", privateIp: "172.31.27.252"}, i-062640304ba7dd647={id: "i-062640304ba7dd647", publicIp: "54.78.221.232", privateIp: "172.31.24.5"}, i-06a580c24cec8cf8c={id: "i-06a580c24cec8cf8c", publicIp: "54.72.246.231", privateIp: "172.31.23.151"}, i-0dd77f4fd8786bc3e={id: "i-0dd77f4fd8786bc3e", publicIp: "34.244.168.228", privateIp: "172.31.29.16"}, i-0cf5d9e3ce659f47d={id: "i-0cf5d9e3ce659f47d", publicIp: "3.248.189.90", privateIp: "172.31.23.92"}, i-06662078b6d99bad2={id: "i-06662078b6d99bad2", publicIp: "34.241.149.133", privateIp: "172.31.18.253"}, i-0cda894d70ee09576={id: "i-0cda894d70ee09576", publicIp: "52.213.190.105", privateIp: "172.31.24.83"}, i-0c2f8a3beb76ac80a={id: "i-0c2f8a3beb76ac80a", publicIp: "34.241.215.40", privateIp: "172.31.26.129"}, i-0e535055ab510192e={id: "i-0e535055ab510192e", publicIp: "52.50.41.19", privateIp: "172.31.25.53"}, i-0fd987880b3a1a630={id: "i-0fd987880b3a1a630", publicIp: "34.250.14.8", privateIp: "172.31.24.219"}, i-0f3087adfec234348={id: "i-0f3087adfec234348", publicIp: "54.216.145.104", privateIp: "172.31.25.201"}, i-08ebd397cb3ef31bf={id: "i-08ebd397cb3ef31bf", publicIp: "3.249.194.81", privateIp: "172.31.16.134"}, i-0741c19c8750a86aa={id: "i-0741c19c8750a86aa", publicIp: "3.250.46.2", privateIp: "172.31.24.103"}, i-0abdb6d98baae5d29={id: "i-0abdb6d98baae5d29", publicIp: "34.249.144.129", privateIp: "172.31.26.218"}, i-0d0b61db9d54c864a={id: "i-0d0b61db9d54c864a", publicIp: "54.170.44.10", privateIp: "172.31.30.165"}, i-0ab5a6b3009676a93={id: "i-0ab5a6b3009676a93", publicIp: "3.249.103.95", privateIp: "172.31.29.27"}, i-0a408669a977905c5={id: "i-0a408669a977905c5", publicIp: "34.249.171.216", privateIp: "172.31.27.134"}, i-00f0bfff136e3b511={id: "i-00f0bfff136e3b511", publicIp: "3.249.32.84", privateIp: "172.31.17.85"}, i-07bb7d5a2a4460b36={id: "i-07bb7d5a2a4460b36", publicIp: "34.253.189.117", privateIp: "172.31.26.104"}, i-0c86093ddb87cbff0={id: "i-0c86093ddb87cbff0", publicIp: "3.250.199.115", privateIp: "172.31.23.182"}, i-0f4f0f0fc6c6a7d33={id: "i-0f4f0f0fc6c6a7d33", publicIp: "34.240.33.94", privateIp: "172.31.29.54"}, i-0b6f54311ebaaa0ff={id: "i-0b6f54311ebaaa0ff", publicIp: "34.243.147.116", privateIp: "172.31.28.140"}, i-0d67d1fb4b9dd82bc={id: "i-0d67d1fb4b9dd82bc", publicIp: "63.35.220.197", privateIp: "172.31.25.237"}, i-042a630b0a5c30f77={id: "i-042a630b0a5c30f77", publicIp: "34.255.137.100", privateIp: "172.31.27.153"}, i-028bd6b886a85025e={id: "i-028bd6b886a85025e", publicIp: "52.213.70.180", privateIp: "172.31.20.141"}, i-05575794eefffbcd1={id: "i-05575794eefffbcd1", publicIp: "52.211.245.10", privateIp: "172.31.25.9"}, i-0e4b83b6a2faad317={id: "i-0e4b83b6a2faad317", publicIp: "3.248.229.124", privateIp: "172.31.22.61"}, i-042b97e8a821b5f77={id: "i-042b97e8a821b5f77", publicIp: "34.253.208.43", privateIp: "172.31.30.105"}}
May 25, 2020 1:12:48 PM org.openqa.selenium.remote.DesiredCapabilities chrome
INFO: Using `new ChromeOptions()` is preferred to `DesiredCapabilities.chrome()`
May 25, 2020 1:12:48 PM org.openqa.selenium.remote.DesiredCapabilities chrome
INFO: Using `new ChromeOptions()` is preferred to `DesiredCapabilities.chrome()`
May 25, 2020 1:12:48 PM org.openqa.selenium.remote.DesiredCapabilities chrome
INFO: Using `new ChromeOptions()` is preferred to `DesiredCapabilities.chrome()`
2020-05-25 13:12:48,508 INFO  [pool-1-thread-1] io.openvidu.load.test.browser.RemoteBrowserProvider$RemoteWebDriverCallable.call(77): Connecting to browser http://52.210.198.4:4444/wd/hub
2020-05-25 13:12:48,508 INFO  [pool-1-thread-2] io.openvidu.load.test.browser.RemoteBrowserProvider$RemoteWebDriverCallable.call(77): Connecting to browser http://54.154.33.11:4444/wd/hub
2020-05-25 13:12:48,508 INFO  [pool-1-thread-3] io.openvidu.load.test.browser.RemoteBrowserProvider$RemoteWebDriverCallable.call(77): Connecting to browser http://3.250.155.174:4444/wd/hub

Error with reaching browser:


020-05-25 13:15:23,373 INFO  [pool-1-thread-1] io.openvidu.load.test.browser.RemoteBrowserProvider$RemoteWebDriverCallable.call(106): Waiting for browser. Exception caught: class org.openqa.selenium.remote.UnreachableBrowserException ({})
2020-05-25 13:15:23,776 INFO  [pool-1-thread-1] io.openvidu.load.test.browser.RemoteBrowserProvider$RemoteWebDriverCallable.call(106): Waiting for browser. Exception caught: class org.openqa.selenium.remote.UnreachableBrowserException ({})
2020-05-25 13:15:24,007 INFO  [Thread-4] io.openvidu.load.test.OpenViduServerManager.lambda$startMonitoringPolling$0(69): 1590412524547 - NetInfo [netInfoMap={ens5=NetInfoEntry [rxBytes=8386596, txBytes=8569164], veth3fc53fc=NetInfoEntry [rxBytes=0, txBytes=0], veth6138322=NetInfoEntry [rxBytes=263989, txBytes=105967], vethfe28399=NetInfoEntry [rxBytes=125167, txBytes=297329]}],  CpuUsage [1.2], MemUsage [used: 2606668.0, percentage: 68.58013927198449]]
2020-05-25 13:15:24,179 INFO  [pool-1-thread-1] io.openvidu.load.test.browser.RemoteBrowserProvider$RemoteWebDriverCallable.call(106): Waiting for browser. Exception caught: class org.openqa.selenium.remote.UnreachableBrowserException ({})
2020-05-25 13:15:24,579 ERROR [main] io.openvidu.load.test.browser.RemoteBrowserProvider.getBrowsers(279): Second attempt to launch a browser for user user-1-1 wasn't succesful. Ending test
2020-05-25 13:15:24,579 ERROR [main] io.openvidu.load.test.OpenViduLoadTest.startSessionAllBrowsersAtOnce(516): Some browser was not ready. Second attempt to launch a browser for user user-1-1 wasn't succesful. Ending test.The browser wasn't reachable in 60 seconds
2020-05-25 13:15:24,589 INFO  [main] io.openvidu.load.test.OpenViduLoadTest.bringDown(313): All browsers are now closed
2020-05-25 13:15:24,589 INFO  [Thread-4] io.openvidu.load.test.OpenViduServerManager.lambda$startMonitoringPolling$0(78): OpenVidu Server monitoring poll is now stopped
2020-05-25 13:15:24,589 INFO  [main] io.openvidu.load.test.OpenViduServerManager.stopMonitoringPolling(89): Stopping OpenVidu Server monitoring poll...
2020-05-25 13:15:24,589 INFO  [main] io.openvidu.load.test.OpenViduLoadTest.bringDown(318): Load test finished
2020-05-25 13:15:24,589 INFO  [main] io.openvidu.load.test.browser.RemoteBrowserProvider.terminateInstances(404): Terminating AWS instances
2020-05-25 13:15:26,452 WARN  [main] io.openvidu.load.test.utils.ScriptExecutor.parseInstanceJsonToMap(98): No instances found inside "Reservations" array
2020-05-25 13:15:26,452 INFO  [main] io.openvidu.load.test.browser.RemoteBrowserProvider.terminateInstances(561): All instances are now shutted down
2020-05-25 13:15:26,452 INFO  [main] io.openvidu.load.test.utils.LogHelper.closeLogFile(68): Closing test log file
2020-05-25 13:15:26,458 INFO  [main] io.openvidu.load.test.ResultsParser.presentResults(620): 

```----------------- TEST RESULTS ---------------
Test duration: 191 s
Number of browsers reached: 0 of 30
Total unstable browsers: 0
Number of lines parsed from log: 45
------- WebRTC streams stats -------
Average WebRTC receiver RTT: 0 ms
Average WebRTC sender RTT: 0 ms
Average WebRTC receiver packets lost: 0
Average WebRTC sender packets lost: 0
Average WebRTC receiver Jitter: 0
Average WebRTC receiver delay: 0 ms
Average WebRTC receiver bitrate: 0 kbps
Average WebRTC sender bitrate: 0 kbps
Average WebRTC available receive bandwidth: 0

Average WebRTC receiver frames decoded: 0
Average WebRTC available send bandwidth: 0
Max WebRTC receiver RTT: 0
Max WebRTC sender RTT: 0
Max WebRTC receiver packets lost: 0
Max WebRTC sender packets lost: 0
Max WebRTC receiver Jitter: 0
Max WebRTC receiver delay: 0 ms
------- OpenVidu Server monitoring -------
Max CPU usage in OpenVidu Server: 4.79%
Max memory usage in OpenVidu Server: 68.59%
Total received MBs by OpenVidu Server: 0.11 MB
Total sent MBs by OpenVidu Server: 0.28 MB
Average received bitrate by OpenVidu Server: 0.58 KB/s
Average sent bitrate by OpenVidu Server: 1.5 KB/s
----------------------------------------------

@CSantosM this is what's happening ...
CSantosM commented 4 years ago

Please, try with webcomponent_loadtest branch of this repository. You must launch a webapp with this CF and set te app url

public static String APP_URL = "http://localhost:8080/"; To the domain EC2 instance where the webapp is started

umarF commented 4 years ago

Please, try with webcomponent_loadtest branch of this repository. You must launch a webapp with this CF and set te app url

public static String APP_URL = "http://localhost:8080/"; To the domain EC2 instance where the webapp is started

@CSantosM Ok, I will do this and get back to you. Thanks for your quick responses.

umarF commented 4 years ago

I tried with the mentioned branch.. it is also failing at the same point. What could be the reason for connection failures? my region is: eu-west-1 ami is IMAGE_ID=ami-0a4fbfab82b4aee91 machine is:t3.medium

my security group looks like this:

Screenshot 2020-05-25 at 21 25 22 Screenshot 2020-05-25 at 21 25 15

INFO  [pool-1-thread-1] io.openvidu.load.test.browser.RemoteBrowserProvider$RemoteWebDriverCallable.call(106): Waiting for browser. Exception caught: class org.openqa.selenium.remote.UnreachableBrowserException ({})
2020-05-25 19:20:02,212 INFO  [pool-1-thread-1] io.openvidu.load.test.browser.RemoteBrowserProvider$RemoteWebDriverCallable.call(106): Waiting for browser. Exception caught: class org.openqa.selenium.remote.UnreachableBrowserException ({})
2020-05-25 19:20:02,615 INFO  [pool-1-thread-1] io.openvidu.load.test.browser.RemoteBrowserProvider$RemoteWebDriverCallable.call(106): Waiting for browser. Exception caught: class org.openqa.selenium.remote.UnreachableBrowserException ({})
2020-05-25 19:20:03,018 INFO  [pool-1-thread-1] io.openvidu.load.test.browser.RemoteBrowserProvider$RemoteWebDriverCallable.call(106): Waiting for browser. Exception caught: class org.openqa.selenium.remote.UnreachableBrowserException ({})
2020-05-25 19:20:03,421 INFO  [pool-1-thread-1] io.openvidu.load.test.browser.RemoteBrowserProvider$RemoteWebDriverCallable.call(106): Waiting for browser. Exception caught: class org.openqa.selenium.remote.UnreachableBrowserException ({})
2020-05-25 19:20:03,821 ERROR [main] io.openvidu.load.test.browser.RemoteBrowserProvider.getBrowsers(279): Second attempt to launch a browser for user user-1-1 wasn't succesful. Ending test
2020-05-25 19:20:03,821 ERROR [main] io.openvidu.load.test.OpenViduLoadTest.startSessionAllBrowsersAtOnce(555): Some browser was not ready. Second attempt to launch a browser for user user-1-1 wasn't succesful. Ending test.The browser wasn't reachable in 60 seconds
2020-05-25 19:20:03,831 INFO  [main] io.openvidu.load.test.OpenViduLoadTest.bringDown(328): All browsers are now closed
2020-05-25 19:20:03,831 INFO  [main] io.openvidu.load.test.OpenViduServerManager.stopMonitoringPolling(93): Stopping OpenVidu Server monitoring poll...
2020-05-25 19:20:03,831 INFO  [main] io.openvidu.load.test.OpenViduLoadTest.bringDown(333): Load test finished
2020-05-25 19:20:03,831 INFO  [Thread-4] io.openvidu.load.test.OpenViduServerManager.lambda$startMonitoringPolling$0(82): OpenVidu Server monitoring poll is now stopped
2020-05-25 19:20:03,831 INFO  [main] io.openvidu.load.test.browser.RemoteBrowserProvider.terminateInstances(404): Terminating AWS instances
2020-05-25 19:20:04,918 WARN  [main] io.openvidu.load.test.utils.ScriptExecutor.parseInstanceJsonToMap(98): No instances found inside "Reservations" array
2020-05-25 19:20:04,918 INFO  [main] io.openvidu.load.test.browser.RemoteBrowserProvider.terminateInstances(561): All instances are now shutted down
2020-05-25 19:20:04,918 INFO  [main] io.openvidu.load.test.utils.LogHelper.closeLogFile(68): Closing test log file
2020-05-25 19:20:04,924 INFO  [main] io.openvidu.load.test.ResultsParser.presentResults(620): 
----------------- TEST RESULTS ---------------
Test duration: 188 s
Number of browsers reached: 0 of 20
Total unstable browsers: 0
Number of lines parsed from log: 43
------- WebRTC streams stats -------
Average WebRTC receiver RTT: 0 ms
Average WebRTC sender RTT: 0 ms
Average WebRTC receiver packets lost: 0
Average WebRTC sender packets lost: 0
Average WebRTC receiver Jitter: 0
Average WebRTC receiver delay: 0 ms
Average WebRTC receiver bitrate: 0 kbps
Average WebRTC sender bitrate: 0 kbps
Average WebRTC available receive bandwidth: 0

Average WebRTC receiver frames decoded: 0
Average WebRTC available send bandwidth: 0
Max WebRTC receiver RTT: 0
Max WebRTC sender RTT: 0
Max WebRTC receiver packets lost: 0
Max WebRTC sender packets lost: 0
Max WebRTC receiver Jitter: 0
Max WebRTC receiver delay: 0 ms
------- OpenVidu Server monitoring -------
Max CPU usage in OpenVidu Server: 4.68%
Max memory usage in OpenVidu Server: 68.58%
Total received MBs by OpenVidu Server: 0.1 MB
Total sent MBs by OpenVidu Server: 0.25 MB
Average received bitrate by OpenVidu Server: 0.54 KB/s
Average sent bitrate by OpenVidu Server: 1.36 KB/s
----------------------------------------------
2020-05-25 19:20:04,924 INFO  [main] io.openvidu.load.test.ResultsParser.generateGraphsWithR(624): Generating graphs with R
2020-05-25 19:20:05,580 INFO  [main] io.openvidu.load.test.OpenViduLoadTest.bringDown(352): Test configured to download remote result files
2020-05-25 19:20:05,897 INFO  [Thread-9] io.openvidu.load.test.utils.ScpFileDownloader.downloadFile(75): Downloading file /var/log/turn_*_ from ov2.penguinpass.it
2020-05-25 19:20:05,915 INFO  [Thread-7] io.openvidu.load.test.utils.ScpFileDownloader.downloadFile(75): Downloading file /var/log/kurento-media-server/20*.log from ov2.penguinpass.it
2020-05-25 19:20:05,933 INFO  [Thread-6] io.openvidu.load.test.utils.ScpFileDownloader.downloadFile(75): Downloading file /var/log/supervisor/openvidu-server-stdout*.log from ov2.penguinpass.it
2020-05-25 19:20:05,966 INFO  [Thread-8] io.openvidu.load.test.utils.ScpFileDownloader.downloadFile(75): Downloading file /var/log/kurento-media-server/errors.log from ov2.penguinpass.it
2020-05-25 19:20:06,210 ERROR [Thread-7] io.openvidu.load.test.utils.ScpFileDownloader.checkAck(219): scp: /var/log/kurento-media-server/20*.log: No such file or directory

2020-05-25 19:20:06,213 INFO  [Thread-7] io.openvidu.load.test.utils.ScpFileDownloader.printProgress(238): 100% [null]
2020-05-25 19:20:06,213 ERROR [Thread-7] io.openvidu.load.test.utils.ScpFileDownloader.downloadFile(188): java.lang.NullPointerException
2020-05-25 19:20:06,270 ERROR [Thread-9] io.openvidu.load.test.utils.ScpFileDownloader.checkAck(219): scp: /var/log/turn_*_: No such file or directory

2020-05-25 19:20:06,270 INFO  [Thread-9] io.openvidu.load.test.utils.ScpFileDownloader.printProgress(238): 100% [null]
2020-05-25 19:20:06,270 ERROR [Thread-9] io.openvidu.load.test.utils.ScpFileDownloader.downloadFile(188): java.lang.NullPointerException
2020-05-25 19:20:06,306 ERROR [Thread-6] io.openvidu.load.test.utils.ScpFileDownloader.checkAck(219): scp: /var/log/supervisor/openvidu-server-stdout*.log: No such file or directory

2020-05-25 19:20:06,306 INFO  [Thread-6] io.openvidu.load.test.utils.ScpFileDownloader.printProgress(238): 100% [null]
2020-05-25 19:20:06,306 ERROR [Thread-6] io.openvidu.load.test.utils.ScpFileDownloader.downloadFile(188): java.lang.NullPointerException
2020-05-25 19:20:06,357 ERROR [Thread-8] io.openvidu.load.test.utils.ScpFileDownloader.checkAck(219): scp: /var/log/kurento-media-server/errors.log: No such file or directory

2020-05-25 19:20:06,357 INFO  [Thread-8] io.openvidu.load.test.utils.ScpFileDownloader.printProgress(238): 100% [null]
2020-05-25 19:20:06,358 ERROR [Thread-8] io.openvidu.load.test.utils.ScpFileDownloader.downloadFile(188): java.lang.NullPointerException
2020-05-25 19:20:06,358 INFO  [main] io.openvidu.load.test.OpenViduLoadTest.bringDown(359): All remote files have been successfully downloaded
2020-05-25 19:20:06,358 INFO  [main] io.openvidu.load.test.utils.LogHelper.closeInfoFile(73): Closing test info file
2020-05-25 19:20:06,361 INFO  [main] io.openvidu.load.test.utils.ZipGenerator.zipFiles(43): Compressing result files into loadtest_2020-05-25_19:16:55.zip
2020-05-25 19:20:06,361 INFO  [main] io.openvidu.load.test.utils.ZipGenerator.zipFile(58): Zipping loadtest_2020-05-25_19:16:55
2020-05-25 19:20:06,362 INFO  [main] io.openvidu.load.test.utils.ZipGenerator.zipFile(64): File loadtest_2020-05-25_19:16:55 is a directory. Recursive zip
2020-05-25 19:20:06,362 INFO  [main] io.openvidu.load.test.utils.ZipGenerator.zipFile(58): Zipping loadtest_2020-05-25_19:16:55/loadTestStats.txt
2020-05-25 19:20:06,363 INFO  [main] io.openvidu.load.test.utils.ZipGenerator.zipFile(58): Zipping loadtest_2020-05-25_19:16:55/loadTestPublisherResultsAverage.csv
2020-05-25 19:20:06,363 INFO  [main] io.openvidu.load.test.utils.ZipGenerator.zipFile(58): Zipping loadtest_2020-05-25_19:16:55/loadtest_2020-05-25_19:16:55.zip
2020-05-25 19:20:06,363 INFO  [main] io.openvidu.load.test.utils.ZipGenerator.zipFile(58): Zipping loadtest_2020-05-25_19:16:55/loadTestSubscriberResultsAverage.csv
2020-05-25 19:20:06,363 INFO  [main] io.openvidu.load.test.utils.ZipGenerator.zipFile(58): Zipping loadtest_2020-05-25_19:16:55/packetsInfo.txt
2020-05-25 19:20:06,364 INFO  [main] io.openvidu.load.test.utils.ZipGenerator.zipFile(58): Zipping loadtest_2020-05-25_19:16:55/test.log
2020-05-25 19:20:06,365 INFO  [main] io.openvidu.load.test.utils.ZipGenerator.zipFile(58): Zipping loadtest_2020-05-25_19:16:55/loadTestInfo.txt
2020-05-25 19:20:06,366 INFO  [main] io.openvidu.load.test.utils.ZipGenerator.zipFile(58): Zipping loadtest_2020-05-25_19:16:55/loadTestSubscriberResults.csv
2020-05-25 19:20:06,366 INFO  [main] io.openvidu.load.test.utils.ZipGenerator.zipFile(58): Zipping loadtest_2020-05-25_19:16:55/loadTestPublisherResults.csv
2020-05-25 19:20:06,367 INFO  [main] io.openvidu.load.test.utils.ZipGenerator.zipFiles(52): Zip file successfully created. Available at /opt/openvidu/testload/loadtest_2020-05-25_19:16:55/loadtest_2020-05-25_19:16:55.zip
2020-05-25 19:20:06,367 INFO  [main] io.openvidu.load.test.OpenViduLoadTest.bringDown(385): TEST FINISHED
[ERROR] Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 192.657 s <<< FAILURE! - in io.openvidu.load.test.OpenViduLoadTest
[ERROR] loadTest  Time elapsed: 188.736 s  <<< FAILURE!
java.lang.AssertionError: Some browser was not ready. Second attempt to launch a browser for user user-1-1 wasn't succesful. Ending test.The browser wasn't reachable in 60 seconds
    at io.openvidu.load.test.OpenViduLoadTest.startSessionAllBrowsersAtOnce(OpenViduLoadTest.java:556)
    at io.openvidu.load.test.OpenViduLoadTest.loadTest(OpenViduLoadTest.java:409)

[INFO] 
[INFO] Results:
[INFO] 
[ERROR] Failures: 
[ERROR]   OpenViduLoadTest.loadTest:409->startSessionAllBrowsersAtOnce:556 Some browser was not ready. Second attempt to launch a browser for user user-1-1 wasn't succesful. Ending test.The browser wasn't reachable in 60 seconds
[INFO] 
[ERROR] Tests run: 1, Failures: 1, Errors: 0, Skipped: 0
[INFO] 
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 03:14 min
[INFO] Finished at: 2020-05-25T19:20:06+00:00
[INFO] Final Memory: 22M/328M
CSantosM commented 4 years ago

We have used this repository today and everything was working fine, something should be wrong in your configuration because the test can’t access or launch a browser

umarF commented 4 years ago

I can now see my browser instances running and trying to connect to a url for making test.

I need some help with this URL that i see in the chrome instances:

http://localhost:8080/?publicurl=ov2.penguinpass.it&secret=XXXX&sessionId=session-1&userId=user-1-2 I can see this url being called when i vnc a client instance.

I want to know if i am calling it the right way. The public url is the server url hosted in same aws env, secret is the server secret. But i dont think it connects to my server. Is the test supposed to connect to my server or it is just made for the SUT machine server ?

the command i used to run test :

mvn -DOPENVIDU_SECRET=XXXXX -DOPENVIDU_URL=https://ov2.penguinpass.it  -DUSERS_SESSION=2 -DSESSION=2 -DBROWSER_INIT_AT_ONCE=true -DSECONDS_OF_WAIT=180 -DAPP_URL=http://localhost:8080/ test

some middle logs about chrome session:

020-05-26 07:56:21,767 INFO  [Thread-4] io.openvidu.load.test.OpenViduServerManager.lambda$startMonitoringPolling$0(72): 1590479781682 - NetInfo [netInfoMap={ens5=NetInfoEntry [rxBytes=7860, txBytes=23298], veth3fc53fc=NetInfoEntry [rxBytes=0, txBytes=0], veth6138322=NetInfoEntry [rxBytes=62252, txBytes=25564], vethfe28399=NetInfoEntry [rxBytes=25990, txBytes=62989]}],  CpuUsage [0.7994011976047904], MemUsage [used: 2608704.0, percentage: 68.63370541986284]]
May 26, 2020 7:56:23 AM org.openqa.selenium.remote.ProtocolHandshake createSession
INFO: Detected dialect: W3C
2020-05-26 07:56:23,974 INFO  [main] io.openvidu.load.test.browser.RemoteBrowserProvider.getBrowsers(291): All remote web drivers for session session-1 are initialized
2020-05-26 07:56:23,975 INFO  [main] io.openvidu.load.test.browser.RemoteBrowserProvider.getBrowsers(358): All network restrictions for session session-1 are now applied
2020-05-26 07:56:23,975 INFO  [main] io.openvidu.load.test.browser.RemoteBrowserProvider.getBrowsers(383): All recordings for session session-1 are now started
2020-05-26 07:56:23,975 INFO  [main] io.openvidu.load.test.browser.RemoteBrowserProvider.getBrowsers(397): All tcpdump processes for session session-1 are now started
2020-05-26 07:56:23,975 INFO  [main] io.openvidu.load.test.OpenViduLoadTest.setupBrowsers(648): Browser user-1-1 connecting now to http://localhost:8080/
2020-05-26 07:56:24,374 INFO  [main] io.openvidu.load.test.OpenViduLoadTest.setupBrowsers(651): Browser user-1-1 is now connected to to http://localhost:8080/
2020-05-26 07:56:24,375 INFO  [main] io.openvidu.load.test.OpenViduTestClientsManager.startEventPolling(127): User user-1-1 is now retrieving OpenVidu events until session session-1 is stable (in an interval of 1000 ms)
2020-05-26 07:56:24,376 INFO  [main] io.openvidu.load.test.OpenViduLoadTest.setupBrowsers(648): Browser user-1-2 connecting now to http://localhost:8080/
2020-05-26 07:56:24,609 INFO  [main] io.openvidu.load.test.OpenViduLoadTest.setupBrowsers(651): Browser user-1-2 is now connected to to http://localhost:8080/
2020-05-26 07:56:24,610 INFO  [main] io.openvidu.load.test.OpenViduTestClientsManager.startEventPolling(127): User user-1-2 is now retrieving OpenVidu events until session session-1 is stable (in an interval of 1000 ms)

Failure log:

[INFO] 
[INFO] Results:
[INFO] 
[ERROR] Failures: 
[ERROR]   OpenViduLoadTest.loadTest:409->startSessionAllBrowsersAtOnce:567 User 'user-1-1' in session 'session-1' for not receiving enough 'connectionCreated' events in 180 seconds
[INFO] 
[ERROR] Tests run: 1, Failures: 1, Errors: 0, Skipped: 0
[INFO] 
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 03:54 min
[INFO] Finished at: 2020-05-26T07:59:27+00:00
[INFO] Final Memory: 22M/328M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.22.2:test (default-test) on project openvidu-test-load: There are test failures.
[ERROR] 
[ERROR] Please refer to /home/ubuntu/openvidu-loadtest/selenium-test/target/surefire-reports for the individual test results.
[ERROR] Please refer to dump files (if any exist) [date].dump, [date]-jvmRun[N].dump and [date].dumpstream.
[ERROR] -> [Help 1]
[ERROR] 
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR]

Inside the client machine the localhost don't seem to work:

Screenshot 2020-05-26 at 09 58 39

CSantosM commented 4 years ago

If you are using webcomponent_loadtest like i suggested to you, you need to launch the webapp with this CF in EC2.

Then, you can't point to localhost, you must point to the ip of webapp that you just launched.

umarF commented 4 years ago

Ok i did as you said previously.

the command I used:

mvn -DUSERS_SESSION=3 -DSESSION=4 -DBROWSER_INIT_AT_ONCE=false -DREMOTE=true -DSECONDS_OF_WAIT=120 -DAPP_URL=https://ec2-3-250-11-64.eu-west-1.compute.amazonaws.com -DRECORD_BROWSERS=[1,0,2] test

Error now i got:

2020-05-26 08:29:09,554 INFO  [main] io.openvidu.load.test.OpenViduLoadTest.bringDown(385): TEST FINISHED
[ERROR] Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 175.888 s <<< FAILURE! - in io.openvidu.load.test.OpenViduLoadTest
[ERROR] loadTest  Time elapsed: 170.274 s  <<< FAILURE!
java.lang.AssertionError: Session did not reach stable status in timeout: User 'user-1-2' in session 'session-1' for not receiving enough 'connectionCreated' events in 120 seconds
    at io.openvidu.load.test.OpenViduLoadTest.startSessionBrowserAfterBrowser(OpenViduLoadTest.java:497)
    at io.openvidu.load.test.OpenViduLoadTest.loadTest(OpenViduLoadTest.java:411)

[INFO] 
[INFO] Results:
[INFO] 
[ERROR] Failures: 
[ERROR]   OpenViduLoadTest.loadTest:411->startSessionBrowserAfterBrowser:497 Session did not reach stable status in timeout: User 'user-1-2' in session 'session-1' for not receiving enough 'connectionCreated' events in 120 seconds
[INFO] 
[ERROR] Tests run: 1, Failures: 1, Errors: 0, Skipped: 0
[INFO] 
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 02:58 min
[INFO] Finished at: 2020-05-26T08:29:09+00:00
[INFO] Final Memory: 22M/331M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.22.2:test (default-test) on project openvidu-test-load: There are test failures.
[ERROR] 
[ERROR] Please refer to /home/ubuntu/openvidu-loadtest/selenium-test/target/surefire-reports for the individual test results.
[ERROR] Please refer to dump files (if any exist) [date].dump, [date]-jvmRun[N].dump and [date].dumpstream.
[ERROR] -> [Help 1]
[ERROR] 
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR] 
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoFailureException
root@ip-172-31-38-19:/home/ubuntu/openvidu-loadtest/selenium-test# cd /opt/openvidu/testload/loadtest_2020-05-26_08:26:14/recording-user-1-1.mp4

and a preview of the recording:

Screenshot 2020-05-26 at 10 39 16

I have a feeling i'm pretty close to setup....

CSantosM commented 4 years ago

You must add DOPENVIDU_SECRET=XXXXX -DOPENVIDU_URL=https://ov2.penguinpass.it

ivchicano commented 4 months ago

Closing because of inactivity