Hello,
audio communications quality of ICE-configured link on a local network
is flawless but studying the pjsua logs it appears there is something
counter-intuitive: if host A calls host B, then ICE session is
established as expected, until the point host B receives a final
"UPDATE" request from A with the nominated link configuration in SDP:
a=candidate:Hc0a80064 1 UDP 1694498815 192.168.0.100 4007 typ host
a=remote-candidates:1 192.168.0.200 4006
(192.168.0.100 is host A, 192.168.0.200 is host B).
Here host B apparently doesn't understand this request:
Processing SDP: support ICE=1, common comp_cnt=1, ice_mismatch=1,
ice_restart=0, local_role=Controlled
Stopping ICE, reason=Remote offer mismatch: :Default target doesn't
match any ICE candidates (PJNATH_EICEMISMATCH)
and replies with
a=ice-mismatch
which leads to
Stopping ICE, reason=Remote answer doesn't support ICE
on host A.
Nevertheless the media link (a direct link, not through a distant
sip-relay!) is up and functional between A and B until the call is
terminated by a BYE.
Finally, pjsua was started as
pjsip-apps/bin/pjsua \
--nameserver=192.168.0.1 \
--stun-srv=stun.stunprotocol.org \
--use-ice --ice-no-rtcp --no-tcp
on both sides (i.e. in aggressive mode, but --regular doesn't change
anything, in the final UPDATE stage B still complains about "remote
offer mismatch").
1. Is there anything wrong? (Transmitted sound quality is perfect!)
2. If 'y', then how this can be fixed?
P.S. A detailed log is attached.
Eeri Kask
-------------- next part --------------
Network topology: local network 192.168.0.0 connected through
firewall outer IP 11.11.11.11 to sip provider 22.22.22.22:
+------------------+
| 22.22.22.22 | sip.org
+---------+--------+
|
:
|
+---------+--------+
| 11.11.11.11 | firewall
| 192.168.0.1 |
+---------+--------+
|
+-----------+----------+
| |
+-------+-------+ +-------+-------+
| 192.168.0.100 | | 192.168.0.200 | host 100, host 200
+---------------+ +---------------+
User logged in host 100 starts
pjsip-apps/bin/pjsua \
--nameserver=192.168.0.1 \
--stun-srv=stun.stunprotocol.org \
--use-ice --ice-no-rtcp --no-tcp
and calls user as <sip:user at sip.org> who is logged in 200 (and
also runs pjsua as above).
(1) User 100 sees pjsua (ice-related) log:
==========================================
17:24:38.270 pjsua_media.c .Call 0: initializing media..
17:24:38.270 icetp00 ..Creating ICE stream transport with 1 component(s)
17:24:38.270 icetp00 ...Comp 1: srflx candidate starts Binding discovery
17:24:38.274 icetp00 ...Comp 1: host candidate 192.168.0.100:4007 added
17:24:38.274 icetp00 ...ICE stream transport 0x102922ca8 created
17:24:38.318 stuntp0x1026f5 .STUN mapped address found/changed: 11.11.11.11:4007
17:24:38.320 icetp00 .Comp 1: Binding discovery complete, srflx address is 11.11.11.11:4007
17:24:38.330 icetp00 ICE session created, comp_cnt=1, role is Controlling agent
17:24:38.330 icetp00 ICE nomination type set to aggressive
17:24:38.330 icetp00 Candidate 0 added: comp_id=1, type=srflx, foundation=Sc0a80064, addr=11.11.11.11:4007, base=192.168.0.100:4007, prio=0x6effffff (1862270975)
17:24:38.330 icetp00 Candidate 1 added: comp_id=1, type=host, foundation=Hc0a80064, addr=192.168.0.100:4007, base=192.168.0.100:4007, prio=0x64ffffff (1694498815)
17:24:38.354 pjsua_core.c TX 1327 bytes Request msg INVITE/cseq=19400 (tdta0x10386a200) to UDP 22.22.22.22:5060:
a=candidate:Sc0a80064 1 UDP 1862270975 11.11.11.11 4007 typ srflx raddr 192.168.0.100 rport 4007
a=candidate:Hc0a80064 1 UDP 1694498815 192.168.0.100 4007 typ host
(2) Now user 200 observes (sip.org added itself as "relay"):
============================================================
17:24:38.501 pjsua_core.c .RX 1828 bytes Request msg INVITE/cseq=19400 (rdata0x116804028) from UDP 22.22.22.22:5060:
a=candidate:R16161616 1 UDP 16777215 22.22.22.22 51476 typ relay
a=candidate:Sc0a80064 1 UDP 1862270975 11.11.11.11 4007 typ srflx raddr 192.168.0.100 rport 4007
a=candidate:Hc0a80064 1 UDP 1694498815 192.168.0.100 4007 typ host
17:24:38.501 icetp00 ...Creating ICE stream transport with 1 component(s)
17:24:38.501 icetp00 ....Comp 1: srflx candidate starts Binding discovery
17:24:38.503 icetp00 ....Comp 1: host candidate 192.168.0.200:4006 added
17:24:38.503 icetp00 ....ICE stream transport 0x10284c6a8 created
17:24:38.549 stuntp0x102732 .STUN mapped address found/changed: 11.11.11.11:4006
17:24:38.550 icetp00 .Comp 1: Binding discovery complete, srflx address is 11.11.11.11:4006
17:24:38.563 icetp00 ICE session created, comp_cnt=1, role is Controlled agent
17:24:38.563 icetp00 ICE nomination type set to aggressive
17:24:38.563 icetp00 Candidate 0 added: comp_id=1, type=srflx, foundation=Sc0a800c8, addr=11.11.11.11:4006, base=192.168.0.200:4006, prio=0x6effffff (1862270975)
17:24:38.563 icetp00 Candidate 1 added: comp_id=1, type=host, foundation=Hc0a800c8, addr=192.168.0.200:4006, base=192.168.0.200:4006, prio=0x64ffffff (1694498815)
17:24:38.563 icetp00 Processing SDP: support ICE=1, common comp_cnt=1, ice_mismatch=0, ice_restart=0, local_role=Controlled
17:24:42.756 pjsua_media.c ...Call 0: updating media..
17:24:42.756 icetp00 ....Check 1: [1] 192.168.0.200:4006-->11.11.11.11:4007 pruned (duplicate found)
17:24:42.756 icetp00 ....Check 2: [1] 192.168.0.200:4006-->192.168.0.100:4007 pruned (duplicate found)
17:24:42.756 icetp00 ....Check 3: [1] 192.168.0.200:4006-->22.22.22.22:51476 pruned (duplicate found)
17:24:42.756 icetp00 ....Checklist created:
17:24:42.756 icetp00 .... 0: [1] 192.168.0.200:4006-->11.11.11.11:4007 (not nominated, state=Frozen)
17:24:42.756 icetp00 .... 1: [1] 192.168.0.200:4006-->192.168.0.100:4007 (not nominated, state=Frozen)
17:24:42.756 icetp00 .... 2: [1] 192.168.0.200:4006-->22.22.22.22:51476 (not nominated, state=Frozen)
17:24:42.756 icetp00 ....Starting ICE check..
17:24:42.756 icetp00 .....Check 0: [1] 192.168.0.200:4006-->11.11.11.11:4007: state changed from Frozen to Waiting
17:24:42.756 pjsua_core.c ....TX 1641 bytes Response msg 200/INVITE/cseq=19400 (tdta0x119803800) to UDP 22.22.22.22:5060:
a=candidate:Sc0a800c8 1 UDP 1862270975 11.11.11.11 4006 typ srflx raddr 192.168.0.200 rport 4006
a=candidate:Hc0a800c8 1 UDP 1694498815 192.168.0.200 4006 typ host
(3) User 100 continues (sip.org added itself as "relay"):
=========================================================
17:24:42.770 icetp00 .Received an early check for comp 1
17:24:42.845 pjsua_core.c .RX 1489 bytes Response msg 200/INVITE/cseq=19400 (rdata0x103870a28) from UDP 22.22.22.22:5060:
a=candidate:R16161616 1 UDP 16777215 22.22.22.22 51490 typ relay
a=candidate:Sc0a800c8 1 UDP 1862270975 11.11.11.11 4006 typ srflx raddr 192.168.0.200 rport 4006
a=candidate:Hc0a800c8 1 UDP 1694498815 192.168.0.200 4006 typ host
17:24:42.846 pjsua_media.c .....Call 0: updating media..
17:24:42.846 icetp00 ......Processing SDP: support ICE=1, common comp_cnt=1, ice_mismatch=0, ice_restart=0, local_role=Controlling
17:24:42.846 icetp00 ......Check 2: [1] 192.168.0.100:4007-->11.11.11.11:4006 pruned (duplicate found)
17:24:42.846 icetp00 ......Check 2: [1] 192.168.0.100:4007-->192.168.0.200:4006 pruned (duplicate found)
17:24:42.846 icetp00 ......Check 3: [1] 192.168.0.100:4007-->22.22.22.22:51490 pruned (duplicate found)
17:24:42.846 icetp00 ......Checklist created:
17:24:42.846 icetp00 ...... 0: [1] 192.168.0.100:4007-->11.11.11.11:4006 (not nominated, state=Frozen)
17:24:42.846 icetp00 ...... 1: [1] 192.168.0.100:4007-->192.168.0.200:4006 (not nominated, state=Frozen)
17:24:42.846 icetp00 ...... 2: [1] 192.168.0.100:4007-->22.22.22.22:51490 (not nominated, state=Frozen)
17:24:42.846 icetp00 ......Starting ICE check..
17:24:42.846 icetp00 .......Check 0: [1] 192.168.0.100:4007-->11.11.11.11:4006: state changed from Frozen to Waiting
17:24:42.846 icetp00 .......Performing delayed triggerred check for component 1
17:24:42.846 icetp00 ........Performing triggered check for check 1
17:24:42.846 icetp00 .........Sending connectivity check for check 1: [1] 192.168.0.100:4007-->192.168.0.200:4006
17:24:42.846 icetp00 ..........Check 1: [1] 192.168.0.100:4007-->192.168.0.200:4006: state changed from Frozen to In Progress
17:24:42.847 icetp00 !Checklist: state changed from Idle to Running
17:24:42.847 icetp00 Starting checklist periodic check
17:24:42.847 icetp00 .Sending connectivity check for check 0: [1] 192.168.0.100:4007-->11.11.11.11:4006
17:24:42.847 icetp00 !..Check 0: [1] 192.168.0.100:4007-->11.11.11.11:4006: state changed from Waiting to In Progress
17:24:42.847 icetp00 !.Check 1: [1] 192.168.0.100:4007-->192.168.0.200:4006 (nominated): connectivity check SUCCESS
17:24:42.847 icetp00 .Check 1: [1] 192.168.0.100:4007-->192.168.0.200:4006: state changed from In Progress to Succeeded
17:24:42.847 icetp00 .Check 2: [1] 192.168.0.100:4007-->22.22.22.22:51490: state changed from Frozen to Waiting
17:24:42.847 icetp00 !.Check 1 is successful and nominated
17:24:42.847 icetp00 !.Cancelling check 0: [1] 192.168.0.100:4007-->11.11.11.11:4006 (In Progress)
17:24:42.848 icetp00 !.Check 0: [1] 192.168.0.100:4007-->11.11.11.11:4006: state changed from In Progress to Failed
17:24:42.848 icetp00 !.Check 2: [1] 192.168.0.100:4007-->22.22.22.22:51490 to be failed because state is Waiting
17:24:42.848 icetp00 !.Check 2: [1] 192.168.0.100:4007-->22.22.22.22:51490: state changed from Waiting to Failed
17:24:42.848 icetp00 !.ICE process complete, status=Success
17:24:42.848 icetp00 !.Valid list
17:24:42.848 sic => icetp00 !. 0: [1] 192.168.0.100:4007-->192.168.0.200:4006 (nominated, state=Succeeded)
17:24:42.849 icetp00 ICE negotiation success after 0s:003
17:24:42.849 icetp00 Comp 1: sending from host candidate 192.168.0.100:4007 to host candidate 192.168.0.200:4006
17:24:42.850 pjsua_core.c ....TX 1372 bytes Request msg UPDATE/cseq=19401 (tdta0x10293ec00) to UDP 22.22.22.20:5060:
a=candidate:Hc0a80064 1 UDP 1694498815 192.168.0.100 4007 typ host
a=remote-candidates:1 192.168.0.200 4006
(4) User 200 again (timely parallel to the above):
==================================================
17:24:42.776 icetp00 !Checklist: state changed from Idle to Running
17:24:42.776 icetp00 Starting checklist periodic check
17:24:42.776 icetp00 .Sending connectivity check for check 0: [1] 192.168.0.200:4006-->11.11.11.11:4007
17:24:42.776 icetp00 ..Check 0: [1] 192.168.0.200:4006-->11.11.11.11:4007: state changed from Waiting to In Progress
17:24:42.796 icetp00 !Starting checklist periodic check
17:24:42.796 icetp00 .Sending connectivity check for check 1: [1] 192.168.0.200:4006-->192.168.0.100:4007
17:24:42.796 icetp00 ..Check 1: [1] 192.168.0.200:4006-->192.168.0.100:4007: state changed from Frozen to In Progress
17:24:42.797 icetp00 .Check 1: [1] 192.168.0.200:4006-->192.168.0.100:4007 (not nominated): connectivity check SUCCESS
17:24:42.797 icetp00 .Check 1: [1] 192.168.0.200:4006-->192.168.0.100:4007: state changed from In Progress to Succeeded
17:24:42.797 icetp00 .Check 2: [1] 192.168.0.200:4006-->22.22.22.22:51476: state changed from Frozen to Waiting
17:24:42.797 icetp00 .Check 1 is successful
17:24:42.817 icetp00 !Starting checklist periodic check
17:24:42.817 icetp00 .Sending connectivity check for check 2: [1] 192.168.0.200:4006-->22.22.22.22:51476
17:24:42.817 icetp00 ..Check 2: [1] 192.168.0.200:4006-->22.22.22.22:51476: state changed from Waiting to In Progress
17:24:42.837 icetp00 !Starting checklist periodic check
17:24:42.874 icetp00 .Valid check 0: [1] 192.168.0.200:4006-->192.168.0.100:4007 is nominated
17:24:42.874 icetp00 .Triggered check for check 1 not performed because it's completed
17:24:42.874 icetp00 ..Check 1 is successful and nominated
17:24:42.874 icetp00 ..Cancelling check 0: [1] 192.168.0.200:4006-->11.11.11.11:4007 (In Progress)
17:24:42.874 icetp00 ..Check 0: [1] 192.168.0.200:4006-->11.11.11.11:4007: state changed from In Progress to Failed
17:24:42.874 icetp00 ..Cancelling check 2: [1] 192.168.0.200:4006-->22.22.22.22:51476 (In Progress)
17:24:42.874 icetp00 ..Check 2: [1] 192.168.0.200:4006-->22.22.22.22:51476: state changed from In Progress to Failed
17:24:42.874 icetp00 ..ICE process complete, status=Success
17:24:42.874 icetp00 ..Valid list
17:24:42.874 sic => icetp00 .. 0: [1] 192.168.0.200:4006-->192.168.0.100:4007 (nominated, state=Succeeded)
17:24:42.874 icetp00 ICE negotiation success after 0s:118
17:24:42.874 icetp00 Comp 1: sending from host candidate 192.168.0.200:4006 to host candidate 192.168.0.100:4007
17:24:42.988 pjsua_core.c .RX 1520 bytes Request msg UPDATE/cseq=19401 (rdata0x11a001828) from UDP 22.22.22.22:5060:
a=candidate:Hc0a80064 1 UDP 1694498815 192.168.0.100 4007 typ host
a=remote-candidates:1 192.168.0.200 4006
17:24:42.989 icetp00 ......Processing SDP: support ICE=1, common comp_cnt=1, ice_mismatch=1, ice_restart=0, local_role=Controlled
17:24:42.989 icetp00 .......Stopping ICE, reason=Remote offer mismatch: :Default target doesn't match any ICE candidates (PJNATH_EICEMISMATCH)
17:24:42.989 icetp00 .......Destroying ICE session 0x102871e28
17:24:42.989 pjsua_core.c .......TX 1332 bytes Response msg 200/UPDATE/cseq=19401 (tdta0x116013200) to UDP 22.22.22.22:5060:
a=ice-mismatch
(5) User 100 (timely parallel to the above):
============================================
17:24:42.868 icetp00 Starting checklist periodic check
17:24:43.058 pjsua_core.c .RX 1174 bytes Response msg 200/UPDATE/cseq=19401 (rdata0x10293b628) from UDP 22.22.22.20:5060:
a=ice-mismatch
17:24:43.058 icetp00 ......Stopping ICE, reason=Remote answer doesn't support ICE
17:24:43.058 icetp00 ......Destroying ICE session 0x103864228
***** Here audio stream between 192.168.0.100:4007 and 192.168.0.200:4006 is ok, nothing unusual *****
(6) After some time user 100 sends BYE, then:
=============================================
17:25:10.953 icetp00 ......Stopping ICE, reason=media stop requested
17:25:10.953 icetp00 .......ICE stream transport 0x102922ca8 destroyed
17:25:10.953 ice_session.c .......ICE session 0x103864228 destroyed
(7) And finally user 200:
=========================
17:25:10.903 icetp00 .......Stopping ICE, reason=media stop requested
17:25:10.904 icetp00 ........ICE stream transport 0x10284c6a8 destroyed
17:25:10.904 ice_session.c ........ICE session 0x102871e28 destroyed
