Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Never failed if no matching ICE pair #280

Open
Horcrux7 opened this issue May 29, 2024 · 8 comments
Open

Never failed if no matching ICE pair #280

Horcrux7 opened this issue May 29, 2024 · 8 comments

Comments

@Horcrux7
Copy link

Horcrux7 commented May 29, 2024 •
edited
Loading

If the ICE candidates of the the client and server does not match then the agent never go into the state FAILED or TERMINATED. It is for ever in the state RUNNING. There are endless log entries with will skip a check beat. See the sample log entries.

Is this a bug? Can I set any timeout? Does I must check this self after the last candidate from client? If yes, how can I check this?

I use version: 3.0-68-gd289f12

[CoWork ice4j,DEBUG ,5/29 7:06:34,#05739] Created a new Agent: ICE Agent (stream-count=0 ice-pwd:7t1q2ahueo3ocr2rvrnv45ecjj ice-ufrag:dkshb1hv1io31j tie-breaker:5008347248423258042):
[CoWork ice4j,DEBUG ,5/29 7:06:34,#05739]  with ICE controlling role = true
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05970] Create media stream for stream
[CoWork ice4j,INFO  ,5/29 7:06:35,#05970] Gathering candidates for component stream.RTP.
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05970] Candidate count in first harvest: 1
[CoWork ice4j,INFO  ,5/29 7:06:35,#05970] Start ICE connectivity establishment.
[CoWork ice4j,INFO  ,5/29 7:06:35,#05970] Init checklist for stream stream
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05970] Checklist initialized.
[CoWork ice4j,INFO  ,5/29 7:06:35,#05970] ICE state changed from Waiting to Running.
[CoWork ice4j,INFO  ,5/29 7:06:35,#05970] Start connectivity checks.
[CoWork ice4j,INFO  ,5/29 7:06:35,#05523] Update remote candidate for stream.RTP: 10.10.6.14:60177/udp
[CoWork ice4j,INFO  ,5/29 7:06:35,#05523] new Pair added: 172.17.0.2:7002/udp/host -> 10.10.6.14:60177/udp/host (stream.RTP).
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] start check for 172.17.0.2:7002/udp/host -> 10.10.6.14:60177/udp/host (stream.RTP) tid 0xB70C2CC38F01321C3F986EDD
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] sending STUN  tid 0xB70C2CC38F01321C3F986EDD from 172.17.0.2:7002/udp to 10.10.6.14:60177/udp
[CoWork ice4j,INFO  ,5/29 7:06:35,#05188] Could not start connectivity check: No socket found for 172.17.0.2:7002/udp->10.10.6.14:60177/udp
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] will skip a check beat.
[CoWork ice4j,INFO  ,5/29 7:06:35,#05739] Update remote candidate for stream.RTP: 172.20.16.1:60178/udp
[CoWork ice4j,INFO  ,5/29 7:06:35,#05739] new Pair added: 172.17.0.2:7002/udp/host -> 172.20.16.1:60178/udp/host (stream.RTP).
[CoWork ice4j,INFO  ,5/29 7:06:35,#05885] Update remote candidate for stream.RTP: 192.168.178.79:60179/udp
[CoWork ice4j,INFO  ,5/29 7:06:35,#05885] new Pair added: 172.17.0.2:7002/udp/host -> 192.168.178.79:60179/udp/host (stream.RTP).
[CoWork ice4j,INFO  ,5/29 7:06:35,#05885] Update remote candidate for stream.RTP: 192.168.96.1:60180/udp
[CoWork ice4j,INFO  ,5/29 7:06:35,#05885] new Pair added: 172.17.0.2:7002/udp/host -> 192.168.96.1:60180/udp/host (stream.RTP).
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] start check for 172.17.0.2:7002/udp/host -> 172.20.16.1:60178/udp/host (stream.RTP) tid 0xE20C2CC38F01CFE672C8BE08
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] sending STUN  tid 0xE20C2CC38F01CFE672C8BE08 from 172.17.0.2:7002/udp to 172.20.16.1:60178/udp
[CoWork ice4j,INFO  ,5/29 7:06:35,#05188] Could not start connectivity check: No socket found for 172.17.0.2:7002/udp->172.20.16.1:60178/udp
[CoWork ice4j,INFO  ,5/29 7:06:35,#05523] Update remote candidate for stream.RTP: 92.116.228.58:60179/udp
[CoWork ice4j,INFO  ,5/29 7:06:35,#05523] new Pair added: 172.17.0.2:7002/udp/host -> 92.116.228.58:60179/udp/srflx (stream.RTP).
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] start check for 172.17.0.2:7002/udp/host -> 192.168.178.79:60179/udp/host (stream.RTP) tid 0xF80C2CC38F01C98ED2230BDA
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] sending STUN  tid 0xF80C2CC38F01C98ED2230BDA from 172.17.0.2:7002/udp to 192.168.178.79:60179/udp
[CoWork ice4j,INFO  ,5/29 7:06:35,#05188] Could not start connectivity check: No socket found for 172.17.0.2:7002/udp->192.168.178.79:60179/udp
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] start check for 172.17.0.2:7002/udp/host -> 192.168.96.1:60180/udp/host (stream.RTP) tid 0x0E0D2CC38F015D22AE33DE51
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] sending STUN  tid 0x0E0D2CC38F015D22AE33DE51 from 172.17.0.2:7002/udp to 192.168.96.1:60180/udp
[CoWork ice4j,INFO  ,5/29 7:06:35,#05188] Could not start connectivity check: No socket found for 172.17.0.2:7002/udp->192.168.96.1:60180/udp
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] start check for 172.17.0.2:7002/udp/host -> 92.116.228.58:60179/udp/srflx (stream.RTP) tid 0x230D2CC38F01121249B7430A
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] sending STUN  tid 0x230D2CC38F01121249B7430A from 172.17.0.2:7002/udp to 92.116.228.58:60179/udp
[CoWork ice4j,INFO  ,5/29 7:06:35,#05188] Could not start connectivity check: No socket found for 172.17.0.2:7002/udp->92.116.228.58:60179/udp
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] will skip a check beat.
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] will skip a check beat.
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] will skip a check beat.
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] will skip a check beat.
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] will skip a check beat.
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] will skip a check beat.
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] will skip a check beat.
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] will skip a check beat.
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] will skip a check beat.
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] will skip a check beat.
[CoWork ice4j,DEBUG ,5/29 7:06:35,#05188] will skip a check beat.
@bgrozev
Copy link
Member

bgrozev commented May 29, 2024

I'm pretty sure the case of no pairs is handled correctly since in jitsi-videobridge we don't even signal remote candidates. From the logs it looks like there were matching ICE pairs, but starting their checks failed with No socket found. I suspect this error should result in the pair failing, but doesn't.

Is this using HostCandidateHarvester? Can you check if reverting #260 makes a difference?

@Horcrux7
Copy link
Author

I have try the version 3.0-57-gdec3a87 which is before #260. I see also ICE state change to FAILED. This is the log output:

[CoWork ice4j,DEBUG ,5/30 6:42:59,#04828] Created a new Agent: ICE Agent (stream-count=0 ice-pwd:4rj9c1iic55eallcgrfmd896i3 ice-ufrag:5fvup1hv43pja0 tie-breaker:4523964991461041769):
[CoWork ice4j,DEBUG ,5/30 6:42:59,#04828]  with ICE controlling role = true
[CoWork ice4j,DEBUG ,5/30 6:42:59,#04836] Create media stream for stream
[CoWork ice4j,INFO  ,5/30 6:42:59,#04836] Gathering candidates for component stream.RTP.
[CoWork ice4j,DEBUG ,5/30 6:42:59,#04836] Candidate count in first harvest: 1
[CoWork ice4j,INFO  ,5/30 6:42:59,#04836] Start ICE connectivity establishment.
[CoWork ice4j,INFO  ,5/30 6:42:59,#04836] Init checklist for stream stream
[CoWork ice4j,DEBUG ,5/30 6:42:59,#04836] Checklist initialized.
[CoWork ice4j,INFO  ,5/30 6:42:59,#04836] ICE state changed from Waiting to Running.
[CoWork ice4j,INFO  ,5/30 6:42:59,#04836] Start connectivity checks.
[CoWork ice4j,INFO  ,5/30 6:42:59,#04882] Update remote candidate for stream.RTP: 10.10.6.14:60131/udp
[CoWork ice4j,INFO  ,5/30 6:42:59,#04882] new Pair added: 172.17.0.2:7002/udp/host -> 10.10.6.14:60131/udp/host (stream.RTP).
[CoWork ice4j,INFO  ,5/30 6:42:59,#04828] Update remote candidate for stream.RTP: 192.168.178.79:60132/udp
[CoWork ice4j,INFO  ,5/30 6:42:59,#04828] new Pair added: 172.17.0.2:7002/udp/host -> 192.168.178.79:60132/udp/host (stream.RTP).
[CoWork ice4j,INFO  ,5/30 6:42:59,#04882] Update remote candidate for stream.RTP: 192.168.96.1:60133/udp
[CoWork ice4j,INFO  ,5/30 6:42:59,#04882] new Pair added: 172.17.0.2:7002/udp/host -> 192.168.96.1:60133/udp/host (stream.RTP).
[CoWork ice4j,INFO  ,5/30 6:42:59,#04828] Update remote candidate for stream.RTP: 172.31.192.1:60134/udp
[CoWork ice4j,INFO  ,5/30 6:42:59,#04828] new Pair added: 172.17.0.2:7002/udp/host -> 172.31.192.1:60134/udp/host (stream.RTP).
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] start check for 172.17.0.2:7002/udp/host -> 10.10.6.14:60131/udp/host (stream.RTP) tid 0x84CD3CC88F014E2E870B5212
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] sending STUN  tid 0x84CD3CC88F014E2E870B5212 from 172.17.0.2:7002/udp to 10.10.6.14:60131/udp
[CoWork ice4j,WARN  ,5/30 6:42:59,#03973] Failed to send BINDING-REQUEST(0x1)[attrib.count=6 len=88 tranID=0x84CD3CC88F014E2E870B5212]
[CoWork ice4j,WARN  ,5/30 6:42:59,#03973] java.lang.IllegalArgumentException: No socket found for 172.17.0.2:7002/udp->10.10.6.14:60131/udp
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.NetAccessManager.sendMessage(NetAccessManager.java:631)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.NetAccessManager.sendMessage(NetAccessManager.java:581)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.StunClientTransaction.sendRequest0(StunClientTransaction.java:267)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.StunClientTransaction.sendRequest(StunClientTransaction.java:245)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.StunStack.sendRequest(StunStack.java:680)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.ice.ConnectivityCheckClient.startCheckForPair(ConnectivityCheckClient.java:333)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.ice.ConnectivityCheckClient.startCheckForPair(ConnectivityCheckClient.java:229)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.ice.ConnectivityCheckClient$PaceMaker.run(ConnectivityCheckClient.java:939)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.util.PeriodicRunnable.executeRun(PeriodicRunnable.java:206)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.lang.Thread.run(Unknown Source)
[CoWork ice4j,INFO  ,5/30 6:42:59,#03973] Pair failed: 172.17.0.2:7002/udp/host -> 10.10.6.14:60131/udp/host (stream.RTP)
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] start check for 172.17.0.2:7002/udp/host -> 192.168.178.79:60132/udp/host (stream.RTP) tid 0x9BCD3CC88F01070AB7634930
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] sending STUN  tid 0x9BCD3CC88F01070AB7634930 from 172.17.0.2:7002/udp to 192.168.178.79:60132/udp
[CoWork ice4j,WARN  ,5/30 6:42:59,#03973] Failed to send BINDING-REQUEST(0x1)[attrib.count=6 len=88 tranID=0x9BCD3CC88F01070AB7634930]
[CoWork ice4j,WARN  ,5/30 6:42:59,#03973] java.lang.IllegalArgumentException: No socket found for 172.17.0.2:7002/udp->192.168.178.79:60132/udp
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.NetAccessManager.sendMessage(NetAccessManager.java:631)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.NetAccessManager.sendMessage(NetAccessManager.java:581)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.StunClientTransaction.sendRequest0(StunClientTransaction.java:267)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.StunClientTransaction.sendRequest(StunClientTransaction.java:245)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.StunStack.sendRequest(StunStack.java:680)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.ice.ConnectivityCheckClient.startCheckForPair(ConnectivityCheckClient.java:333)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.ice.ConnectivityCheckClient.startCheckForPair(ConnectivityCheckClient.java:229)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.ice.ConnectivityCheckClient$PaceMaker.run(ConnectivityCheckClient.java:939)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.util.PeriodicRunnable.executeRun(PeriodicRunnable.java:206)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.lang.Thread.run(Unknown Source)
[CoWork ice4j,INFO  ,5/30 6:42:59,#03973] Pair failed: 172.17.0.2:7002/udp/host -> 192.168.178.79:60132/udp/host (stream.RTP)
[CoWork ice4j,INFO  ,5/30 6:42:59,#04828] Update remote candidate for stream.RTP: 92.116.228.58:60132/udp
[CoWork ice4j,INFO  ,5/30 6:42:59,#04828] new Pair added: 172.17.0.2:7002/udp/host -> 92.116.228.58:60132/udp/srflx (stream.RTP).
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] start check for 172.17.0.2:7002/udp/host -> 192.168.96.1:60133/udp/host (stream.RTP) tid 0xB0CD3CC88F0177033682A1CC
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] sending STUN  tid 0xB0CD3CC88F0177033682A1CC from 172.17.0.2:7002/udp to 192.168.96.1:60133/udp
[CoWork ice4j,WARN  ,5/30 6:42:59,#03973] Failed to send BINDING-REQUEST(0x1)[attrib.count=6 len=88 tranID=0xB0CD3CC88F0177033682A1CC]
[CoWork ice4j,WARN  ,5/30 6:42:59,#03973] java.lang.IllegalArgumentException: No socket found for 172.17.0.2:7002/udp->192.168.96.1:60133/udp
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.NetAccessManager.sendMessage(NetAccessManager.java:631)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.NetAccessManager.sendMessage(NetAccessManager.java:581)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.StunClientTransaction.sendRequest0(StunClientTransaction.java:267)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.StunClientTransaction.sendRequest(StunClientTransaction.java:245)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.StunStack.sendRequest(StunStack.java:680)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.ice.ConnectivityCheckClient.startCheckForPair(ConnectivityCheckClient.java:333)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.ice.ConnectivityCheckClient.startCheckForPair(ConnectivityCheckClient.java:229)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.ice.ConnectivityCheckClient$PaceMaker.run(ConnectivityCheckClient.java:939)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.util.PeriodicRunnable.executeRun(PeriodicRunnable.java:206)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.lang.Thread.run(Unknown Source)
[CoWork ice4j,INFO  ,5/30 6:42:59,#03973] Pair failed: 172.17.0.2:7002/udp/host -> 192.168.96.1:60133/udp/host (stream.RTP)
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] start check for 172.17.0.2:7002/udp/host -> 172.31.192.1:60134/udp/host (stream.RTP) tid 0xC5CD3CC88F01551D1A6A5E51
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] sending STUN  tid 0xC5CD3CC88F01551D1A6A5E51 from 172.17.0.2:7002/udp to 172.31.192.1:60134/udp
[CoWork ice4j,WARN  ,5/30 6:42:59,#03973] Failed to send BINDING-REQUEST(0x1)[attrib.count=6 len=88 tranID=0xC5CD3CC88F01551D1A6A5E51]
[CoWork ice4j,WARN  ,5/30 6:42:59,#03973] java.lang.IllegalArgumentException: No socket found for 172.17.0.2:7002/udp->172.31.192.1:60134/udp
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.NetAccessManager.sendMessage(NetAccessManager.java:631)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.NetAccessManager.sendMessage(NetAccessManager.java:581)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.StunClientTransaction.sendRequest0(StunClientTransaction.java:267)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.StunClientTransaction.sendRequest(StunClientTransaction.java:245)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.StunStack.sendRequest(StunStack.java:680)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.ice.ConnectivityCheckClient.startCheckForPair(ConnectivityCheckClient.java:333)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.ice.ConnectivityCheckClient.startCheckForPair(ConnectivityCheckClient.java:229)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.ice.ConnectivityCheckClient$PaceMaker.run(ConnectivityCheckClient.java:939)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.util.PeriodicRunnable.executeRun(PeriodicRunnable.java:206)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.lang.Thread.run(Unknown Source)
[CoWork ice4j,INFO  ,5/30 6:42:59,#03973] Pair failed: 172.17.0.2:7002/udp/host -> 172.31.192.1:60134/udp/host (stream.RTP)
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] start check for 172.17.0.2:7002/udp/host -> 92.116.228.58:60132/udp/srflx (stream.RTP) tid 0xDBCD3CC88F01FC53259D14C4
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] sending STUN  tid 0xDBCD3CC88F01FC53259D14C4 from 172.17.0.2:7002/udp to 92.116.228.58:60132/udp
[CoWork ice4j,WARN  ,5/30 6:42:59,#03973] Failed to send BINDING-REQUEST(0x1)[attrib.count=6 len=88 tranID=0xDBCD3CC88F01FC53259D14C4]
[CoWork ice4j,WARN  ,5/30 6:42:59,#03973] java.lang.IllegalArgumentException: No socket found for 172.17.0.2:7002/udp->92.116.228.58:60132/udp
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.NetAccessManager.sendMessage(NetAccessManager.java:631)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.NetAccessManager.sendMessage(NetAccessManager.java:581)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.StunClientTransaction.sendRequest0(StunClientTransaction.java:267)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.StunClientTransaction.sendRequest(StunClientTransaction.java:245)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.stack.StunStack.sendRequest(StunStack.java:680)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.ice.ConnectivityCheckClient.startCheckForPair(ConnectivityCheckClient.java:333)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.ice.ConnectivityCheckClient.startCheckForPair(ConnectivityCheckClient.java:229)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.ice.ConnectivityCheckClient$PaceMaker.run(ConnectivityCheckClient.java:939)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at org.ice4j.util.PeriodicRunnable.executeRun(PeriodicRunnable.java:206)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
[CoWork ice4j,TRACE ,5/30 6:42:59,#03973] 	at java.base/java.lang.Thread.run(Unknown Source)
[CoWork ice4j,INFO  ,5/30 6:42:59,#03973] Pair failed: 172.17.0.2:7002/udp/host -> 92.116.228.58:60132/udp/srflx (stream.RTP)
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] will skip a check beat.
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] will skip a check beat.
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] will skip a check beat.
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] will skip a check beat.
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] will skip a check beat.
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] will skip a check beat.
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] will skip a check beat.
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] will skip a check beat.
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] will skip a check beat.
[CoWork ice4j,DEBUG ,5/30 6:42:59,#03973] will skip a check beat.
...

@Horcrux7
Copy link
Author

Is this using HostCandidateHarvester?

Yes. I use the follow API calls (simplified). The server run inside of a docker container which does not publish the UDP port 7002 to simulate the misconfiguration of a customer. It is impossible for the server to connect to the browser. It should failed.

       List<CandidateHarvester> harvesters = SinglePortUdpHarvester.createHarvesters( 7002 );
       ....
       agent.setControlling( true );
       agent.setTrickling( true );
       IceMediaStream stream = agent.createMediaStream( "stream" );
       agent.addStateChangeListener( evt -> {
           ....
       });
       agent.setUseDynamicPorts( false );
       for( CandidateHarvester harvester : harvesters ) {
            agent.addCandidateHarvester( harvester );
       }
       Component component = agent.createComponent( stream, 0, 0, 0 );
       sendLocalCandidatesToBrowser( component.getLocalCandidates() );
       agent.startCandidateTrickle( iceCandidates -> {
             ....
       } );
       agent.startConnectivityEstablishment();
       ....
       component.addUpdateRemoteCandidates( candidate );
       component.updateRemoteCandidates();

@bgrozev
Copy link
Member

bgrozev commented May 30, 2024

I agree that with all pairs failing the Agent should transition to the FAILED state. I don't understand why it doesn't. Is your trickle callback getting called with null to signal that trickling has completed? Have you tried with no trickle at all?

@Horcrux7
Copy link
Author

The stacktrace from the log point me to the catch of NetAccessManager.SocketNotFoundException in ConnectivityCheckClient. It does not set the TransactionID tran to null. It was added with #257. This are two release earlier. I will test release 3.0-55-g32a8aad tomorrow. But I am sure that the method startCheckForPair should return null in an error case.

To answer your questions:

  • Yes there is a final null in startCandidateTrickle
  • I have not test without trickle yet because all browser accept this. I can check this also.

@Horcrux7
Copy link
Author

I was not able to run the version 3.0-55-g32a8aadin a given time. Seems there was a large difference of the dependencies.

@Horcrux7
Copy link
Author

Horcrux7 commented Jun 3, 2024

If I return null in the method startCheckForPair after a NetAccessManager.SocketNotFoundException then I see the log output:

[CoWork ice4j,INFO  ,6/3 12:17:09,#00158] Pair failed: .....

like in the old version 3.0-57-gdec3a87. But the agent is not failing. This seems an important part of a possible fix but is not enough.

I can't find any code in the library that checks that all candidates are failing. processResponse and processTimeout is never called. The fireEndOfOrdinaryChecks is a NOP operation because there are no listener registered. Any suggestion where i can set a breakpoint? Can I give any helpful information?

Horcrux7 added a commit to Horcrux7/ice4j that referenced this issue Jun 3, 2024
@Horcrux7
Agent should failed on SocketNotFoundException jitsi#280
d9245d9 
If there are no matching candidate because a configuration mistake then the agent should failed.
Horcrux7 added a commit to Horcrux7/ice4j that referenced this issue Jun 3, 2024
@Horcrux7
Merge pull request #1 from Horcrux7/agent-failed
7679666 
Agent should failed on SocketNotFoundException jitsi#280
@Horcrux7
Copy link
Author

Horcrux7 commented Jun 3, 2024

I have create a PR #281 that after 5 Seconds (5000 milliseconds) let failing the agent with a bad configuration.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@Horcrux7 @bgrozev