Open felix99047 opened 1 month ago
ivchicano
commented
1 month ago Looks like a normal error thrown when the media server is overloaded, which is a condition to stop the test. Was the media server not loaded? (100% CPU) Seeing the number of sessions, it would look like it.
felix99047
commented
1 month ago When the exception occurred, the OpenVidu host CPU(4 cores) never up to 100% (total percentage), even the kurento-media-s process never up to 100% (single core percentage)
felix99047
commented
1 month ago I tested again, you see it throw exception when processing LoadTestSession28.
2024-05-30 11:16:16.199 INFO 25868 --- [ main] i.o.l.controller.LoadTestController : Starting session 'LoadTestSession28'
2024-05-30 11:16:16.199 INFO 25868 --- [ main] i.o.l.controller.LoadTestController : Creating PUBLISHER 'User1' in session
2024-05-30 11:16:16.199 INFO 25868 --- [ main] i.o.l.services.BrowserEmulatorClient : Selected worker: 10.133.195.61
2024-05-30 11:16:17.166 INFO 25868 --- [lient-AsyncIO-2] i.o.loadtest.services.WebSocketClient : Received message: {"event":"connectionCreated","connectionId":"con_BiX9xvr1dA","connection":"local"}
2024-05-30 11:16:17.174 INFO 25868 --- [lient-AsyncIO-2] i.o.loadtest.services.WebSocketClient : Received message: {"event":"accessAllowed","connectionId":"","connection":"local"}
2024-05-30 11:16:17.390 INFO 25868 --- [lient-AsyncIO-2] i.o.loadtest.services.WebSocketClient : Received message: {"event":"exception","connectionId":"con_PtooTLGoHu","reason":"There was an unexpected error on the server-side processing an ICE candidate generated and sent by the client-side"}
2024-05-30 11:16:17.392 INFO 25868 --- [lient-AsyncIO-2] i.o.loadtest.services.WebSocketClient : Received message: {"event":"exception","connectionId":"con_PtooTLGoHu","reason":"There was an unexpected error on the server-side processing an ICE candidate generated and sent by the client-side"}
2024-05-30 11:16:17.394 INFO 25868 --- [lient-AsyncIO-2] i.o.loadtest.services.WebSocketClient : Received message: {"event":"exception","connectionId":"con_PtooTLGoHu","reason":"There was an unexpected error on the server-side processing an ICE candidate generated and sent by the client-side"}
2024-05-30 11:16:17.396 INFO 25868 --- [lient-AsyncIO-2] i.o.loadtest.services.WebSocketClient : Received message: {"event":"exception","connectionId":"con_PtooTLGoHu","reason":"There was an unexpected error on the server-side processing an ICE candidate generated and sent by the client-side"}
2024-05-30 11:16:17.398 INFO 25868 --- [lient-AsyncIO-2] i.o.loadtest.services.WebSocketClient : Received message: {"event":"exception","connectionId":"con_PtooTLGoHu","reason":"There was an unexpected error on the server-side processing an ICE candidate generated and sent by the client-side"}
2024-05-30 11:16:19.004 INFO 25868 --- [lient-AsyncIO-2] i.o.loadtest.services.WebSocketClient : Received message: {"event":"streamCreated","connectionId":"str_CUS_Panr_con_BiX9xvr1dA","connection":"local"}
2024-05-30 11:16:20.040 INFO 25868 --- [ main] i.o.l.services.BrowserEmulatorClient : Connection con_BiX9xvr1dA created
2024-05-30 11:16:20.040 INFO 25868 --- [ main] i.o.l.services.BrowserEmulatorClient : Worker CPU USAGE: 58%
2024-05-30 11:16:20.040 INFO 25868 --- [ main] i.o.l.controller.LoadTestController : Waiting 2 seconds because of time between participants
2024-05-30 11:16:22.043 INFO 25868 --- [ main] i.o.l.controller.LoadTestController : Creating PUBLISHER 'User2' in session
2024-05-30 11:16:22.044 ERROR 25868 --- [ main] i.o.l.services.BrowserEmulatorClient : There was an EXCEPTION: {"event":"exception","connectionId":"con_PtooTLGoHu","reason":"There was an unexpected error on the server-side processing an ICE candidate generated and sent by the client-side"}
2024-05-30 11:16:22.044 ERROR 25868 --- [ main] i.o.l.controller.LoadTestController : Response status is not 200 OK. Exit
2024-05-30 11:16:22.044 INFO 25868 --- [ main] i.o.l.controller.LoadTestController : Waiting 60 seconds because of time after test finishedCPU usage as below.
Tasks: 3 total, 1 running, 2 sleeping, 0 stopped, 0 zombie
%Cpu(s): 15.1 us, 4.9 sy, 0.0 ni, 77.4 id, 0.0 wa, 0.0 hi, 2.6 si, 0.0 st
MiB Mem : 11952.3 total, 2571.5 free, 1257.7 used, 8123.2 buff/cache
MiB Swap: 4096.0 total, 4095.5 free, 0.5 used. 10371.0 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
1 root 20 0 9.9g 303456 28160 S 84.4 2.5 5:39.25 kurento-media-s
1979 root 20 0 6000 3584 3072 S 0.0 0.0 0:00.02 bash
2015 root 20 0 7912 3584 3072 R 0.0 0.0 0:00.12 topYou could try using RETRY_MODE=true in case it is just a Kurento fluke, as the error indicates that it comes from the server-side (kurento) kicking out a user, although RETRY_MODE in old versions is very buggy
felix99047
commented
1 month ago Where to set RETRY_MODE=true please? In the previous testing, I was using two worker nodes, just now I tried to test with one worker node again.
2024-05-31 10:52:06.426 INFO 4695 --- [ main] i.o.l.controller.LoadTestController : Starting session 'LoadTestSession14'
2024-05-31 10:52:06.426 INFO 4695 --- [ main] i.o.l.controller.LoadTestController : Creating PUBLISHER 'User1' in session
2024-05-31 10:52:06.426 INFO 4695 --- [ main] i.o.l.services.BrowserEmulatorClient : Selected worker: 10.133.195.61
2024-05-31 10:52:07.025 INFO 4695 --- [lient-AsyncIO-1] i.o.loadtest.services.WebSocketClient : Received message: {"event":"connectionCreated","connectionId":"con_S7qqx8hnyu","connection":"local"}
2024-05-31 10:52:07.038 INFO 4695 --- [lient-AsyncIO-1] i.o.loadtest.services.WebSocketClient : Received message: {"event":"accessAllowed","connectionId":"","connection":"local"}
2024-05-31 10:52:07.392 INFO 4695 --- [lient-AsyncIO-1] i.o.loadtest.services.WebSocketClient : Received message: {"event":"streamCreated","connectionId":"str_CUS_LdzN_con_S7qqx8hnyu","connection":"local"}
2024-05-31 10:52:08.419 INFO 4695 --- [ main] i.o.l.services.BrowserEmulatorClient : Connection con_S7qqx8hnyu created
2024-05-31 10:52:08.420 INFO 4695 --- [ main] i.o.l.services.BrowserEmulatorClient : Worker CPU USAGE: 55%
2024-05-31 10:52:08.420 INFO 4695 --- [ main] i.o.l.controller.LoadTestController : Waiting 2 seconds because of time between participants
2024-05-31 10:52:10.420 INFO 4695 --- [ main] i.o.l.controller.LoadTestController : Creating PUBLISHER 'User2' in session
2024-05-31 10:52:10.420 INFO 4695 --- [ main] i.o.l.services.BrowserEmulatorClient : Selected worker: 10.133.195.61
2024-05-31 10:52:11.240 INFO 4695 --- [lient-AsyncIO-1] i.o.loadtest.services.WebSocketClient : Received message: {"event":"connectionCreated","connectionId":"con_Io3lOxJS8w","connection":"local"}
2024-05-31 10:52:11.242 INFO 4695 --- [lient-AsyncIO-1] i.o.loadtest.services.WebSocketClient : Received message: {"event":"connectionCreated","connectionId":"con_S7qqx8hnyu","connection":"remote"}
2024-05-31 10:52:11.243 INFO 4695 --- [lient-AsyncIO-1] i.o.loadtest.services.WebSocketClient : Received message: {"event":"streamCreated","connectionId":"str_CUS_LdzN_con_S7qqx8hnyu","connection":"remote"}
2024-05-31 10:52:11.258 INFO 4695 --- [lient-AsyncIO-1] i.o.loadtest.services.WebSocketClient : Received message: {"event":"accessAllowed","connectionId":"","connection":"local"}
2024-05-31 10:52:12.529 INFO 4695 --- [lient-AsyncIO-1] i.o.loadtest.services.WebSocketClient : Received message: {"event":"connectionCreated","connectionId":"con_Io3lOxJS8w","connection":"remote"}
2024-05-31 10:52:12.629 INFO 4695 --- [lient-AsyncIO-1] i.o.loadtest.services.WebSocketClient : Received message: {"event":"streamCreated","connectionId":"str_CUS_LEwf_con_Io3lOxJS8w","connection":"remote"}
2024-05-31 10:52:16.277 INFO 4695 --- [lient-AsyncIO-1] i.o.loadtest.services.WebSocketClient : Received message: {"event":"streamCreated","connectionId":"str_CUS_LEwf_con_Io3lOxJS8w","connection":"local"}
2024-05-31 10:52:17.305 INFO 4695 --- [ main] i.o.l.services.BrowserEmulatorClient : Connection con_Io3lOxJS8w created
2024-05-31 10:52:17.305 INFO 4695 --- [ main] i.o.l.services.BrowserEmulatorClient : Worker CPU USAGE: 57%
2024-05-31 10:52:17.305 INFO 4695 --- [ main] i.o.l.controller.LoadTestController : Session number 14 has been succesfully created
2024-05-31 10:52:17.306 INFO 4695 --- [ main] i.o.l.controller.LoadTestController : Waiting 2 seconds because of time between sessions
2024-05-31 10:52:19.306 INFO 4695 --- [ main] i.o.l.controller.LoadTestController : Starting session 'LoadTestSession15'
2024-05-31 10:52:19.306 INFO 4695 --- [ main] i.o.l.controller.LoadTestController : Creating PUBLISHER 'User1' in session
2024-05-31 10:52:19.307 INFO 4695 --- [ main] i.o.l.services.BrowserEmulatorClient : Selected worker: 10.133.195.61
2024-05-31 10:52:20.206 INFO 4695 --- [lient-AsyncIO-1] i.o.loadtest.services.WebSocketClient : Received message: {"event":"connectionCreated","connectionId":"con_AcZYxthWDR","connection":"local"}
2024-05-31 10:52:20.217 INFO 4695 --- [lient-AsyncIO-1] i.o.loadtest.services.WebSocketClient : Received message: {"event":"accessAllowed","connectionId":"","connection":"local"}
2024-05-31 10:52:20.525 INFO 4695 --- [lient-AsyncIO-1] i.o.loadtest.services.WebSocketClient : Received message: {"event":"streamCreated","connectionId":"str_CUS_PS0W_con_AcZYxthWDR","connection":"local"}
2024-05-31 10:52:21.459 INFO 4695 --- [lient-AsyncIO-1] i.o.loadtest.services.WebSocketClient : Received message: {"event":"exception","connectionId":"con_Io3lOxJS8w","reason":"There was an unexpected error on the server-side processing an ICE candidate generated and sent by the client-side"}
2024-05-31 10:52:21.462 INFO 4695 --- [lient-AsyncIO-1] i.o.loadtest.services.WebSocketClient : Received message: {"event":"exception","connectionId":"con_Io3lOxJS8w","reason":"There was an unexpected error on the server-side processing an ICE candidate generated and sent by the client-side"}
2024-05-31 10:52:21.537 INFO 4695 --- [ main] i.o.l.services.BrowserEmulatorClient : Connection con_AcZYxthWDR created
2024-05-31 10:52:21.537 INFO 4695 --- [ main] i.o.l.services.BrowserEmulatorClient : Worker CPU USAGE: 54%
2024-05-31 10:52:21.537 INFO 4695 --- [ main] i.o.l.controller.LoadTestController : Waiting 2 seconds because of time between participants
2024-05-31 10:52:23.537 INFO 4695 --- [ main] i.o.l.controller.LoadTestController : Creating PUBLISHER 'User2' in session
2024-05-31 10:52:23.537 ERROR 4695 --- [ main] i.o.l.services.BrowserEmulatorClient : There was an EXCEPTION: {"event":"exception","connectionId":"con_Io3lOxJS8w","reason":"There was an unexpected error on the server-side processing an ICE candidate generated and sent by the client-side"}
2024-05-31 10:52:23.537 ERROR 4695 --- [ main] i.o.l.controller.LoadTestController : Response status is not 200 OK. Exit
2024-05-31 10:52:23.537 INFO 4695 --- [ main] i.o.l.controller.LoadTestController : Waiting 60 seconds because of time after test finishedYou can see the exception occurred when processing LoadTestSession14, 14 for one worker node, 28 for two worker nodes, is there any limitation for WebRTC client sessions on Kurento server? any idea?
Hi Team, When I do test with v2.1.0, there is an exception that will cause the testing finished, please help take a look, thanks. {"event":"exception","connectionId":"con_M8VzX8NMJK","reason":"There was an unexpected error on the server-side processing an ICE candidate generated and sent by the client-side"}
loadtest-controller logs as below.