I am testing a VoIP phone in development by my company with 3CX
and seeing a strange thing I can't explain.
The phone sends an INVITE. It receives a 407 challenge from
the proxy. It ACKs that 407 and resends the INVITE with
authorization. Then it receives no further messages from the
proxy for several seconds. During this time naturally it retransmits
the INVITE several times. Finally, it gets the expected 100 and 180
replies and eventually the call is connected when the remote party
answers.
I have confirmed that if I disable authentication by removing
the username/password from the line configuration then
the problem goes away.
I have tried two other softphones - Eyebeam and SJphone - and
I get no such behavior. This testing is on a LAN with no routers
and no NAT, just using direct IP addresses so it is a pretty simple
scenario.
I have been analyzing the packets sent by our phone and have even
made changes to make them closer to those sent by the other
phones but to no avail. I can't explain why this happens and we
have tested with numerous other proxies and never seen anything
like it.
The server log from the proxy doesn't seem to reflect the delay.
It shows the incoming call followed almost immediately by the
ringing indication from the called phone.
Here are the packets followed by the log. The phone with the
problem is 192.168.0.107 (sending the INVITE). The 3CX proxy is
192.168.0.104, and the called phone is 192.168.0.102 (Eyebeam).
INVITE sip:[email protected] SIP/2.0
v: SIP/2.0/UDP 192.168.0.107:43101;branch=z9hG4bK1596188079;rport
f: "Win32 VG"<sip:[email protected]>;tag=2258520665
t: <sip:[email protected]>
CSeq: 2 INVITE
Max-Forwards: 70
i: [email protected]
m: <sip:[email protected]:43101>
l: 220
c: application/sdp
User-Agent: Win32 VG
v=0
[email protected] 1188601585 1188601585 IN IP4 192.168.0.107
s=-
c=IN IP4 192.168.0.107
t=0 0
m=audio 34220 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 192.168.0.107:43101;branch=z9hG4bK1596188079;rport=43101
Proxy-Authenticate: Digest nonce="12833075186:5113719773f231b8820d2ffeda83d705",algorithm=MD5,realm="3CXPhoneSystem"
To: <sip:[email protected]>;tag=96317623
From: "Win32 VG"<sip:[email protected]>;tag=2258520665
Call-ID: [email protected]
CSeq: 2 INVITE
User-Agent: 3CXPhoneSystem
Content-Length: 0
ACK sip:[email protected] SIP/2.0
v: SIP/2.0/UDP 192.168.0.107:43101;branch=z9hG4bK1596188079
f: "Win32 VG"<sip:[email protected]>;tag=2258520665
t: <sip:[email protected]>;tag=96317623
CSeq: 2 ACK
Max-Forwards: 70
i: [email protected]
User-Agent: Win32 VG
l: 0
INVITE sip:[email protected] SIP/2.0
v: SIP/2.0/UDP 192.168.0.107:43101;branch=z9hG4bK1596188079;rport
f: "Win32 VG"<sip:[email protected]>;tag=2258520665
t: <sip:[email protected]>
CSeq: 3 INVITE
Max-Forwards: 70
i: [email protected]
m: <sip:[email protected]:43101>
l: 220
c: application/sdp
User-Agent: Win32 VG
Proxy-Authorization: Digest username="103",realm="3CXPhoneSystem",nonce="12833075186:5113719773f231b8820d2ffeda83d705",uri="sip:[email protected]",response="270834b9aee2ac3e9c6863b94d42882f",algorithm=MD5
v=0
[email protected] 1188601585 1188601585 IN IP4 192.168.0.107
s=-
c=IN IP4 192.168.0.107
t=0 0
m=audio 34220 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
(first retransmission)
INVITE sip:[email protected] SIP/2.0
v: SIP/2.0/UDP 192.168.0.107:43101;branch=z9hG4bK1596188079;rport
f: "Win32 VG"<sip:[email protected]>;tag=2258520665
t: <sip:[email protected]>
CSeq: 3 INVITE
Max-Forwards: 70
i: [email protected]
m: <sip:[email protected]:43101>
l: 220
c: application/sdp
User-Agent: Win32 VG
Proxy-Authorization: Digest username="103",realm="3CXPhoneSystem",nonce="12833075186:5113719773f231b8820d2ffeda83d705",uri="sip:[email protected]",response="270834b9aee2ac3e9c6863b94d42882f",algorithm=MD5
v=0
[email protected] 1188601585 1188601585 IN IP4 192.168.0.107
s=-
c=IN IP4 192.168.0.107
t=0 0
m=audio 34220 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
(Remaining retransmitted packets omitted as they are identical.
Then about 8 seconds after the first INVITE with the Proxy-Authorization
header was sent a 100 is finally received from 3CX)
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.0.107:43101;branch=z9hG4bK1596188079;rport=43101
To: <sip:[email protected]>;tag=7145f349
From: "Win32 VG"<sip:[email protected]>;tag=2258520665
Call-ID: [email protected]
CSeq: 3 INVITE
User-Agent: 3CXPhoneSystem
Content-Length: 0
(Then here is the INVITE sent from 3CX to the called party)
INVITE sip:[email protected]:42434;rinstance=ba3290d993993549 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.104:5060;branch=z9hG4bK-d87543-ef092f3c772a8542-1--d87543-;rport
Max-Forwards: 70
Contact: <sip:[email protected]:5060>
To: "100"<sip:[email protected]:42434;rinstance=ba3290d993993549>
From: "103"<sip:[email protected]:5060>;tag=5c6d8b6e
Call-ID: ZmFkNTU4YTc3NTJjODk1ZjcyMTBlYWU0OWMzYTNlNzQ.
CSeq: 1 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO
Content-Type: application/sdp
User-Agent: 3CXPhoneSystem
Content-Length: 219
v=0
o=3cxPS 12833075195171 12833075195173 IN IP4 192.168.0.104
s=3cxPS Audio call
c=IN IP4 192.168.0.107
t=0 0
m=audio 34220 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
(Then the 180 from the called party to 3CX)
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.0.104:5060;branch=z9hG4bK-d87543-ef092f3c772a8542-1--d87543-;rport=5060
Contact: <sip:[email protected]:42434;rinstance=ba3290d993993549>
To: "100"<sip:[email protected]:42434;rinstance=ba3290d993993549>;tag=c65a9445
From: "103"<sip:[email protected]:5060>;tag=5c6d8b6e
Call-ID: ZmFkNTU4YTc3NTJjODk1ZjcyMTBlYWU0OWMzYTNlNzQ.
CSeq: 1 INVITE
User-Agent: eyeBeam release 1011s stamp 41121
Content-Length: 0
(Then the 180 forwarded from 3CX to the caller)
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.0.107:43101;branch=z9hG4bK1596188079;rport=43101
Contact: <sip:[email protected]:5060>
To: <sip:[email protected]>;tag=7145f349
From: "Win32 VG"<sip:[email protected]>;tag=2258520665
Call-ID: [email protected]
CSeq: 3 INVITE
User-Agent: 3CXPhoneSystem
Content-Length: 0
The 200 is then sent from the callee and forwarded to
the caller and the call connects and seems fine.
Here are the relevant entries from the 3CX proxy log
16:06:46.890 StratLink:
nHangUp [CM104001] Call(23): Ext.103 hung up call; cause: BYE; from IP:192.168.0.107
16:06:36.859 CallLegImpl:nConnected [CM103001] Call(23): Created audio channel for Ext.100 (192.168.0.102:6314) with third party (192.168.0.107:34220)
16:06:36.859 StratInOut:nConnected [CM104005] Call(23): Setup completed for call from Ext.103 to Ext.100
16:06:36.859 CallLegImpl:nConnected [CM103001] Call(23): Created audio channel for Ext.103 (192.168.0.107:34220) with third party (192.168.0.102:6314)
16:06:35.453 CallConf:nProvisional [CM103003] Call(23): Ext.100 is ringing
16:06:35.156 CallConf:nIncoming [CM103002] Call(23): Incoming call from 103 (Ext.103) to sip:[email protected]
Any help understanding how this is happening will be greatly
appreciated.
Regards,
Mike
and seeing a strange thing I can't explain.
The phone sends an INVITE. It receives a 407 challenge from
the proxy. It ACKs that 407 and resends the INVITE with
authorization. Then it receives no further messages from the
proxy for several seconds. During this time naturally it retransmits
the INVITE several times. Finally, it gets the expected 100 and 180
replies and eventually the call is connected when the remote party
answers.
I have confirmed that if I disable authentication by removing
the username/password from the line configuration then
the problem goes away.
I have tried two other softphones - Eyebeam and SJphone - and
I get no such behavior. This testing is on a LAN with no routers
and no NAT, just using direct IP addresses so it is a pretty simple
scenario.
I have been analyzing the packets sent by our phone and have even
made changes to make them closer to those sent by the other
phones but to no avail. I can't explain why this happens and we
have tested with numerous other proxies and never seen anything
like it.
The server log from the proxy doesn't seem to reflect the delay.
It shows the incoming call followed almost immediately by the
ringing indication from the called phone.
Here are the packets followed by the log. The phone with the
problem is 192.168.0.107 (sending the INVITE). The 3CX proxy is
192.168.0.104, and the called phone is 192.168.0.102 (Eyebeam).
INVITE sip:[email protected] SIP/2.0
v: SIP/2.0/UDP 192.168.0.107:43101;branch=z9hG4bK1596188079;rport
f: "Win32 VG"<sip:[email protected]>;tag=2258520665
t: <sip:[email protected]>
CSeq: 2 INVITE
Max-Forwards: 70
i: [email protected]
m: <sip:[email protected]:43101>
l: 220
c: application/sdp
User-Agent: Win32 VG
v=0
[email protected] 1188601585 1188601585 IN IP4 192.168.0.107
s=-
c=IN IP4 192.168.0.107
t=0 0
m=audio 34220 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 192.168.0.107:43101;branch=z9hG4bK1596188079;rport=43101
Proxy-Authenticate: Digest nonce="12833075186:5113719773f231b8820d2ffeda83d705",algorithm=MD5,realm="3CXPhoneSystem"
To: <sip:[email protected]>;tag=96317623
From: "Win32 VG"<sip:[email protected]>;tag=2258520665
Call-ID: [email protected]
CSeq: 2 INVITE
User-Agent: 3CXPhoneSystem
Content-Length: 0
ACK sip:[email protected] SIP/2.0
v: SIP/2.0/UDP 192.168.0.107:43101;branch=z9hG4bK1596188079
f: "Win32 VG"<sip:[email protected]>;tag=2258520665
t: <sip:[email protected]>;tag=96317623
CSeq: 2 ACK
Max-Forwards: 70
i: [email protected]
User-Agent: Win32 VG
l: 0
INVITE sip:[email protected] SIP/2.0
v: SIP/2.0/UDP 192.168.0.107:43101;branch=z9hG4bK1596188079;rport
f: "Win32 VG"<sip:[email protected]>;tag=2258520665
t: <sip:[email protected]>
CSeq: 3 INVITE
Max-Forwards: 70
i: [email protected]
m: <sip:[email protected]:43101>
l: 220
c: application/sdp
User-Agent: Win32 VG
Proxy-Authorization: Digest username="103",realm="3CXPhoneSystem",nonce="12833075186:5113719773f231b8820d2ffeda83d705",uri="sip:[email protected]",response="270834b9aee2ac3e9c6863b94d42882f",algorithm=MD5
v=0
[email protected] 1188601585 1188601585 IN IP4 192.168.0.107
s=-
c=IN IP4 192.168.0.107
t=0 0
m=audio 34220 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
(first retransmission)
INVITE sip:[email protected] SIP/2.0
v: SIP/2.0/UDP 192.168.0.107:43101;branch=z9hG4bK1596188079;rport
f: "Win32 VG"<sip:[email protected]>;tag=2258520665
t: <sip:[email protected]>
CSeq: 3 INVITE
Max-Forwards: 70
i: [email protected]
m: <sip:[email protected]:43101>
l: 220
c: application/sdp
User-Agent: Win32 VG
Proxy-Authorization: Digest username="103",realm="3CXPhoneSystem",nonce="12833075186:5113719773f231b8820d2ffeda83d705",uri="sip:[email protected]",response="270834b9aee2ac3e9c6863b94d42882f",algorithm=MD5
v=0
[email protected] 1188601585 1188601585 IN IP4 192.168.0.107
s=-
c=IN IP4 192.168.0.107
t=0 0
m=audio 34220 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
(Remaining retransmitted packets omitted as they are identical.
Then about 8 seconds after the first INVITE with the Proxy-Authorization
header was sent a 100 is finally received from 3CX)
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.0.107:43101;branch=z9hG4bK1596188079;rport=43101
To: <sip:[email protected]>;tag=7145f349
From: "Win32 VG"<sip:[email protected]>;tag=2258520665
Call-ID: [email protected]
CSeq: 3 INVITE
User-Agent: 3CXPhoneSystem
Content-Length: 0
(Then here is the INVITE sent from 3CX to the called party)
INVITE sip:[email protected]:42434;rinstance=ba3290d993993549 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.104:5060;branch=z9hG4bK-d87543-ef092f3c772a8542-1--d87543-;rport
Max-Forwards: 70
Contact: <sip:[email protected]:5060>
To: "100"<sip:[email protected]:42434;rinstance=ba3290d993993549>
From: "103"<sip:[email protected]:5060>;tag=5c6d8b6e
Call-ID: ZmFkNTU4YTc3NTJjODk1ZjcyMTBlYWU0OWMzYTNlNzQ.
CSeq: 1 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO
Content-Type: application/sdp
User-Agent: 3CXPhoneSystem
Content-Length: 219
v=0
o=3cxPS 12833075195171 12833075195173 IN IP4 192.168.0.104
s=3cxPS Audio call
c=IN IP4 192.168.0.107
t=0 0
m=audio 34220 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
(Then the 180 from the called party to 3CX)
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.0.104:5060;branch=z9hG4bK-d87543-ef092f3c772a8542-1--d87543-;rport=5060
Contact: <sip:[email protected]:42434;rinstance=ba3290d993993549>
To: "100"<sip:[email protected]:42434;rinstance=ba3290d993993549>;tag=c65a9445
From: "103"<sip:[email protected]:5060>;tag=5c6d8b6e
Call-ID: ZmFkNTU4YTc3NTJjODk1ZjcyMTBlYWU0OWMzYTNlNzQ.
CSeq: 1 INVITE
User-Agent: eyeBeam release 1011s stamp 41121
Content-Length: 0
(Then the 180 forwarded from 3CX to the caller)
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.0.107:43101;branch=z9hG4bK1596188079;rport=43101
Contact: <sip:[email protected]:5060>
To: <sip:[email protected]>;tag=7145f349
From: "Win32 VG"<sip:[email protected]>;tag=2258520665
Call-ID: [email protected]
CSeq: 3 INVITE
User-Agent: 3CXPhoneSystem
Content-Length: 0
The 200 is then sent from the callee and forwarded to
the caller and the call connects and seems fine.
Here are the relevant entries from the 3CX proxy log
16:06:46.890 StratLink:
nHangUp [CM104001] Call(23): Ext.103 hung up call; cause: BYE; from IP:192.168.0.107 16:06:36.859 CallLegImpl:
nConnected [CM103001] Call(23): Created audio channel for Ext.100 (192.168.0.102:6314) with third party (192.168.0.107:34220) 16:06:36.859 StratInOut:
nConnected [CM104005] Call(23): Setup completed for call from Ext.103 to Ext.100 16:06:36.859 CallLegImpl:
nConnected [CM103001] Call(23): Created audio channel for Ext.103 (192.168.0.107:34220) with third party (192.168.0.102:6314) 16:06:35.453 CallConf:
nProvisional [CM103003] Call(23): Ext.100 is ringing 16:06:35.156 CallConf:
nIncoming [CM103002] Call(23): Incoming call from 103 (Ext.103) to sip:[email protected] Any help understanding how this is happening will be greatly
appreciated.
Regards,
Mike
