search

jitsi / ice4j

A Java implementation of the ICE protocol
Apache License 2.0
437 stars 232 forks source link

Never failed if no matching ICE pair #280

Open Horcrux7 opened 6 months ago

Horcrux7 commented 6 months ago

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 commented 6 months ago

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 commented 6 months ago

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 commented 6 months ago

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 commented 6 months ago

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 commented 6 months ago

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:

Horcrux7 commented 6 months ago

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 commented 6 months ago

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 commented 6 months ago

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