For reference, here is what happens during a short call from the S850A GO (IP: 10.6.6.64) to my ekiga softphone client (extension 301, IP: 10.6.8.6) through asterisk/pjsip (IP: 10.6.6.1). All endpoints are configured for g722, alaw, ulaw and have direct_media disabled: The ekiga softphone client is deliberately configured to only allow for alaw and ulaw. Same symptoms occur when placing an outbound call through my ITSP to PSTN.
No. Timestamp (Dir) Address SIP Message
===== ========== ============================== ===================================
00000 1475913733 * <== 10.6.6.64:5060 INVITE sip:301@rakanishu.de;user=phone SIP/2.0
00001 1475913733 * ==> 10.6.6.64:5060 SIP/2.0 401 Unauthorized
00002 1475913733 * <== 10.6.6.64:5060 ACK sip:301@rakanishu.de;user=phone SIP/2.0
00003 1475913733 * <== 10.6.6.64:5060 INVITE sip:301@rakanishu.de;user=phone SIP/2.0
00004 1475913733 * ==> 10.6.6.64:5060 SIP/2.0 100 Trying
00005 1475913733 * ==> 10.6.8.6:5060 INVITE sip:ekiga@10.6.8.6 SIP/2.0
00006 1475913733 * <== 10.6.8.6:5060 SIP/2.0 100 Trying
00007 1475913733 * <== 10.6.8.6:5060 SIP/2.0 180 Ringing
00008 1475913733 * ==> 10.6.6.64:5060 SIP/2.0 180 Ringing
00009 1475913736 * <== 10.6.8.6:5060 SIP/2.0 200 OK
00010 1475913736 * ==> 10.6.8.6:5060 ACK sip:ekiga@10.6.8.6 SIP/2.0
00011 1475913736 * ==> 10.6.6.64:5060 SIP/2.0 200 OK
00012 1475913737 * <== 10.6.6.64:5060 ACK sip:10.6.6.1:5060 SIP/2.0
00013 1475913737 * <== 10.6.6.64:5060 INVITE sip:10.6.6.1:5060 SIP/2.0
00014 1475913737 * ==> 10.6.6.64:5060 SIP/2.0 200 OK
00015 1475913737 * <== 10.6.6.64:5060 ACK sip:10.6.6.1:5060 SIP/2.0
00016 1475913737 * <== 10.6.6.64:5060 INVITE sip:10.6.6.1:5060 SIP/2.0
00017 1475913737 * ==> 10.6.6.64:5060 SIP/2.0 200 OK
00018 1475913737 * <== 10.6.6.64:5060 ACK sip:10.6.6.1:5060 SIP/2.0
00019 1475913737 * <== 10.6.6.64:5060 INVITE sip:10.6.6.1:5060 SIP/2.0
00020 1475913737 * ==> 10.6.6.64:5060 SIP/2.0 200 OK
00021 1475913737 * <== 10.6.6.64:5060 ACK sip:10.6.6.1:5060 SIP/2.0
00022 1475913737 * <== 10.6.6.64:5060 INVITE sip:10.6.6.1:5060 SIP/2.0
00023 1475913737 * ==> 10.6.6.64:5060 SIP/2.0 200 OK
00024 1475913737 * <== 10.6.6.64:5060 ACK sip:10.6.6.1:5060 SIP/2.0
00025 1475913737 * <== 10.6.6.64:5060 INVITE sip:10.6.6.1:5060 SIP/2.0
00026 1475913737 * ==> 10.6.6.64:5060 SIP/2.0 200 OK
00027 1475913737 * <== 10.6.6.64:5060 ACK sip:10.6.6.1:5060 SIP/2.0
00028 1475913738 * <== 10.6.6.64:5060 INVITE sip:10.6.6.1:5060 SIP/2.0
00029 1475913738 * ==> 10.6.6.64:5060 SIP/2.0 200 OK
00030 1475913738 * <== 10.6.6.64:5060 ACK sip:10.6.6.1:5060 SIP/2.0
00031 1475913738 * <== 10.6.6.64:5060 INVITE sip:10.6.6.1:5060 SIP/2.0
00032 1475913738 * ==> 10.6.6.64:5060 SIP/2.0 200 OK
00033 1475913738 * <== 10.6.6.64:5060 ACK sip:10.6.6.1:5060 SIP/2.0
00034 1475913738 * <== 10.6.6.64:5060 INVITE sip:10.6.6.1:5060 SIP/2.0
00035 1475913738 * ==> 10.6.6.64:5060 SIP/2.0 200 OK
00036 1475913738 * <== 10.6.6.64:5060 ACK sip:10.6.6.1:5060 SIP/2.0
00037 1475913738 * <== 10.6.6.64:5060 INVITE sip:10.6.6.1:5060 SIP/2.0
00038 1475913738 * ==> 10.6.6.64:5060 SIP/2.0 200 OK
00039 1475913738 * <== 10.6.6.64:5060 ACK sip:10.6.6.1:5060 SIP/2.0
00040 1475913738 * <== 10.6.6.64:5060 INVITE sip:10.6.6.1:5060 SIP/2.0
00041 1475913738 * ==> 10.6.6.64:5060 SIP/2.0 200 OK
00042 1475913738 * <== 10.6.6.64:5060 ACK sip:10.6.6.1:5060 SIP/2.0
00043 1475913738 * <== 10.6.6.64:5060 INVITE sip:10.6.6.1:5060 SIP/2.0
00044 1475913738 * ==> 10.6.6.64:5060 SIP/2.0 200 OK
00045 1475913739 * <== 10.6.6.64:5060 ACK sip:10.6.6.1:5060 SIP/2.0
00046 1475913739 * <== 10.6.6.64:5060 INVITE sip:10.6.6.1:5060 SIP/2.0
00047 1475913739 * ==> 10.6.6.64:5060 SIP/2.0 200 OK
00048 1475913739 * <== 10.6.6.64:5060 ACK sip:10.6.6.1:5060 SIP/2.0
00049 1475913739 * <== 10.6.6.64:5060 BYE sip:10.6.6.1:5060 SIP/2.0
00050 1475913739 * ==> 10.6.6.64:5060 SIP/2.0 200 OK
00051 1475913739 * ==> 10.6.8.6:5060 BYE sip:ekiga@10.6.8.6 SIP/2.0
00052 1475913739 * <== 10.6.8.6:5060 SIP/2.0 200 OK
As you can see, from the moment the call is answered there are lots of reINVITEs being sent by the S850A GO.
This is what the initial INVITE from the S850A GO to asterisk looks like:
<--- History Entry 3 Received from 10.6.6.64:5060 at 1475913733 --->
INVITE sip:301@rakanishu.de;user=phone SIP/2.0
Via: SIP/2.0/UDP 10.6.6.64:5060;rport=5060;received=10.6.6.64;branch=z9hG4bKade1c634dd173d62f8c3eb3780f35d36
From: <sip:S850A-1@rakanishu.de>;tag=1659051246
To: <sip:301@rakanishu.de;user=phone>
Call-ID: 4125927375@10_6_6_64
CSeq: 3 INVITE
Contact: <sip:S850A-1@10.6.6.64:5060>
Authorization: Digest username="S850A-1", realm="rakanishu.de", nonce="1475913733/5c5efdb918c389e6c7a84fe1459d7a97"$
Max-Forwards: 70
User-Agent: S850A GO/42.238.00.000.000
Supported: replaces
Allow-Events: message-summary, refer, ua-profile, talk, check-sync
Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, SUBSCRIBE, NOTIFY, REFER, UPDATE
Content-Type: application/sdp
Content-Length: 240
Content-Type: application/sdp
Content-Length: 240
v=0
o=S850A-1 5012 4 IN IP4 10.6.6.64
s=Mapping
c=IN IP4 10.6.6.64
t=0 0
m=audio 5012 RTP/AVP 9 8 0 101
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
And asterisk’s reply:
<--- History Entry 11 Sent to 10.6.6.64:5060 at 1475913736 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.6.6.64:5060;rport=5060;received=10.6.6.64;branch=z9hG4bKade1c634dd173d62f8c3eb3780f35d36
Call-ID: 4125927375@10_6_6_64
From: <sip:S850A-1@rakanishu.de>;tag=1659051246
To: <sip:301@rakanishu.de;user=phone>;tag=8c881966-ea65-40ea-8225-25247f769f23
CSeq: 3 INVITE
Server: ACME
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Contact: <sip:10.6.6.1:5060>
Supported: 100rel, timer, replaces, norefersub
Content-Type: application/sdp
Content-Length: 261
v=0
o=- 5012 6 IN IP4 78.51.220.96
s=ACME
c=IN IP4 10.6.6.1
t=0 0
m=audio 5006 RTP/AVP 9 8 0 101
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
Both sides offer the same set and order of codecs, but the S850A GO internally seems to pick the first codec from asterisk’s list of codecs for which it also has support, to be the one codec it expects to be used. In this case this is G722. And as soon and as long as asterisk sends RTP encoded with a different format the S850A GO keeps sending reINVITEs, which asterisk confirms:
<--- History Entry 13 Received from 10.6.6.64:5060 at 1475913737 --->
INVITE sip:10.6.6.1:5060 SIP/2.0 Via: SIP/2.0/UDP 10.6.6.64:5060;rport=5060;received=10.6.6.64;branch=z9hG4bK370b7b836bef75f99801f70229a94f07
From: <sip:S850A-1@rakanishu.de>;tag=1659051246 To: <sip:301@rakanishu.de;user=phone>;tag=8c881966-ea65-40ea-8225-25247f769f23
Call-ID: 4125927375@10_6_6_64
CSeq: 4 INVITE
Contact: <sip:S850A-1@10.6.6.64:5060>
Authorization: Digest username="S850A-1", realm="rakanishu.de", nonce="1475913733/5c5efdb918c389e6c7a84fe1459d7a97"$
Max-Forwards: 70
User-Agent: S850A GO/42.238.00.000.000
Supported: replaces
Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, SUBSCRIBE, NOTIFY, REFER, UPDATE
Content-Type: application/sdp
Content-Length: 192
Content-Type: application/sdp
Content-Length: 192
v=0
o=S850A-1 5012 5 IN IP4 10.6.6.64
s=Mapping
c=IN IP4 10.6.6.64
t=0 0
m=audio 5012 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
<--- History Entry 14 Sent to 10.6.6.64:5060 at 1475913737 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.6.6.64:5060;rport=5060;received=10.6.6.64;branch=z9hG4bK370b7b836bef75f99801f70229a94f07
Call-ID: 4125927375@10_6_6_64
From: <sip:S850A-1@rakanishu.de>;tag=1659051246
To: <sip:301@rakanishu.de;user=phone>;tag=8c881966-ea65-40ea-8225-25247f769f23
CSeq: 4 INVITE
Contact: <sip:10.6.6.1:5060>
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Server: ACME
Content-Type: application/sdp
Content-Length: 213
v=0
o=- 5012 7 IN IP4 78.51.220.96
s=ACME
c=IN IP4 10.6.6.1
t=0 0
m=audio 5006 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
<--- History Entry 15 Received from 10.6.6.64:5060 at 1475913737 --->
ACK sip:10.6.6.1:5060 SIP/2.0
Via: SIP/2.0/UDP 10.6.6.64:5060;rport=5060;received=10.6.6.64;branch=z9hG4bKa1f03562b7d4df1ecde9e8251f06d528
From: <sip:S850A-1@rakanishu.de>;tag=1659051246
To: <sip:301@rakanishu.de;user=phone>;tag=8c881966-ea65-40ea-8225-25247f769f23
Call-ID: 4125927375@10_6_6_64
CSeq: 4 ACK
Contact: <sip:S850A-1@10.6.6.64:5060>
Authorization: Digest username="S850A-1", realm="rakanishu.de", nonce="1475913733/5c5efdb918c389e6c7a84fe1459d7a97"$
Max-Forwards: 70
User-Agent: S850A GO/42.238.00.000.000
Content-Length: 0
Content-Length: 0
And this is what happens on the RTP side of things. Although exclusive use of G722 has been acknowledged, asterisk continues to send alaw encoded data (type 08) to the S850A GO:
[2016-10-08 10:02:18.919] VERBOSE[100951][C-00000004] res_rtp_asterisk.c: Got RTP packet from 10.6.6.64:5012 (type 09, seq 000176, ts 17428160, len 000160)
[2016-10-08 10:02:18.923] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:18.939] VERBOSE[100951][C-00000004] res_rtp_asterisk.c: Got RTP packet from 10.6.6.64:5012 (type 09, seq 000177, ts 17428320, len 000160)
[2016-10-08 10:02:18.943] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:18.963] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:18.983] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:19.003] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:19.023] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:19.039] VERBOSE[100951][C-00000004] res_rtp_asterisk.c: Got RTP packet from 10.6.6.64:5012 (type 09, seq 000178, ts 17428480, len 000160)
[2016-10-08 10:02:19.042] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:19.059] VERBOSE[100951][C-00000004] res_rtp_asterisk.c: Got RTP packet from 10.6.6.64:5012 (type 09, seq 000179, ts 17428640, len 000160)
[2016-10-08 10:02:19.063] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:19.079] VERBOSE[100951][C-00000004] res_rtp_asterisk.c: Got RTP packet from 10.6.6.64:5012 (type 09, seq 000180, ts 17428800, len 000160)
[2016-10-08 10:02:19.083] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:19.099] VERBOSE[100951][C-00000004] res_rtp_asterisk.c: Got RTP packet from 10.6.6.64:5012 (type 09, seq 000181, ts 17428960, len 000160)
[2016-10-08 10:02:19.103] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:19.119] VERBOSE[100951][C-00000004] res_rtp_asterisk.c: Got RTP packet from 10.6.6.64:5012 (type 09, seq 000182, ts 17429120, len 000160)
[2016-10-08 10:02:19.123] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:19.143] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:19.163] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:19.183] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:19.203] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:19.223] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:19.226] VERBOSE[100951][C-00000004] res_rtp_asterisk.c: Got RTP packet from 10.6.6.64:5012 (type 09, seq 000183, ts 17429280, len 000160)
[2016-10-08 10:02:19.243] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:19.246] VERBOSE[100951][C-00000004] res_rtp_asterisk.c: Got RTP packet from 10.6.6.64:5012 (type 09, seq 000184, ts 17429440, len 000160)
[2016-10-08 10:02:19.264] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:19.291] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)
[2016-10-08 10:02:19.303] VERBOSE[100954][C-00000004] res_rtp_asterisk.c: Sent RTP P2P packet to 10.6.6.64:5012 (type 08, len 000160)