[Home]

Summary:ASTERISK-15018: Kapanga softphone exposes bug in SIP channel driver
Reporter:Niccolò Belli (darkbasic)Labels:
Date Opened:2009-10-20 18:12:27Date Closed:2011-12-01 12:56:00.000-0600
Priority:TrivialRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/Interoperability
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) debug
( 1) full
( 2) messages
Description:If kapanga has direct access to the provider (no asterisk) I can send faxes flawlessly, otherwise I get errors:

   -- Registered SIP '159' at 192.168.1.44 port 5060
      > Saved useragent "Kapanga Softphone Desktop Windows 1.00/2178d+1256057634_0022FA19F312_001377B41BFA" for peer 159
[Oct 21 00:53:58] NOTICE[12729]: chan_sip.c:17790 handle_response_peerpoke: Peer '159' is now Reachable. (147ms / 2000ms)
 == Using SIP RTP CoS mark 5
 == Using UDPTL CoS mark 5
   -- Executing [<exten>@phones-sip:1] Dial("SIP/159-09614f80", "SIP/eutelia/<exten>,60") in new stack
 == Using SIP RTP CoS mark 5
 == Using UDPTL CoS mark 5
   -- Called eutelia/<exten>
<< [ TYPE: Control (4) SUBCLASS: Unknown control '14' (14) ] [SIP/eutelia-09610a90]
   -- SIP/eutelia-09610a90 is making progress passing it to SIP/159-09614f80
[Oct 21 00:54:04] NOTICE[12753]: rtp.c:1130 process_rfc3389: Comfort noise support incomplete in Asterisk (RFC 3389). Please turn off on client if possible. Client IP: 192.168.1.44
<< [ TYPE: Unknown Frametype '10' (10) SUBCLASS: Unknown Subclass (114) ] [SIP/159-09614f80]
<< [ TYPE: Unknown Frametype '10' (10) SUBCLASS: Unknown Subclass (114) ] [SIP/159-09614f80]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/eutelia-09610a90]
<< [ TYPE: Unknown Frametype '10' (10) SUBCLASS: Unknown Subclass (114) ] [SIP/159-09614f80]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/159-09614f80]
<< [ TYPE: Unknown Frametype '10' (10) SUBCLASS: Unknown Subclass (114) ] [SIP/159-09614f80]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/eutelia-09610a90]
<< [ TYPE: Control (4) SUBCLASS: Answer (4) ] [SIP/eutelia-09610a90]
   -- SIP/eutelia-09610a90 answered SIP/159-09614f80
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/eutelia-09610a90]
<< [ TYPE: Unknown Frametype '10' (10) SUBCLASS: Unknown Subclass (114) ] [SIP/159-09614f80]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/159-09614f80]
<< [ TYPE: Unknown Frametype '10' (10) SUBCLASS: Unknown Subclass (114) ] [SIP/159-09614f80]
<< [ TYPE: Control (4) SUBCLASS: T38_Parameters/Negotiation Requested (24) ] [SIP/eutelia-09610a90]
<< [ TYPE: Control (4) SUBCLASS: Unknown control '20' (20) ] [SIP/eutelia-09610a90]
<< [ TYPE: Control (4) SUBCLASS: T38_Parameters/Negotiated (24) ] [SIP/159-09614f80]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/159-09614f80]
<< [ TYPE: Control (4) SUBCLASS: T38_Parameters/Negotiated (24) ] [SIP/eutelia-09610a90]
<< [ TYPE: Unknown Frametype '10' (10) SUBCLASS: Unknown Subclass (114) ] [SIP/159-09614f80]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/159-09614f80]
<< [ TYPE: Control (4) SUBCLASS: T38_Parameters/Terminated (24) ] [SIP/eutelia-09610a90]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/159-09614f80]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/159-09614f80]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/159-09614f80]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/159-09614f80]
<< [ TYPE: Unknown Frametype '10' (10) SUBCLASS: Unknown Subclass (114) ] [SIP/159-09614f80]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/159-09614f80]
[Oct 21 00:54:35] WARNING[12729]: chan_sip.c:3557 retrans_pkt: Maximum retries exceeded on transmission 781afd3767ab81d160f2ef2c6fd30037@217.133.76.61 for seqno 101 (Critical Response) -- See doc/sip-retransmit.txt.
[Oct 21 00:54:35] WARNING[12729]: chan_sip.c:3584 retrans_pkt: Hanging up call 781afd3767ab81d160f2ef2c6fd30037@217.133.76.61 - no reply to our critical packet (see doc/sip-retransmit.txt).
 == Spawn extension (phones-sip, <exten>, 1) exited non-zero on 'SIP/159-09614f80'



This is my sip.conf:

[general]
t38pt_udptl=yes
language=it
context=default
bindport=5060
externhost=<host>
externrefresh=5
localnet=192.168.1.0/255.255.255.0
nat=yes
register=<number>:<password>@voip.eutelia.it:5060/<number>

[159]
language=it
type=friend
bindport=5060
context=phones-sip
host=dynamic
secret=<password>
nat=no
t38pt_udptl=yes
qualify=yes

[eutelia]
language=it
type=friend
host=voip.eutelia.it
username=<number>
fromuser=<number>
secret=<password>
port=5060
nat=yes
qualify=yes
canreinvite=no ;asterisk is always used as media proxy, I tried also with yes
dtmfmode=rfc2833
insecure=invite,port
context=eutelia-in
t38pt_udptl=yes
Comments:By: Kevin P. Fleming (kpfleming) 2009-10-21 16:24:14

Based on this partial log, this is not a T.38-related problem in Asterisk, but a problem with the service provider's SIP server that did not respond to a SIP request that Asterisk sent. There's no way to know any more than that without proper information being attached to the issue.

As the bug posting guidelines document, for all SIP-related issues the following information should be uploaded as *attachments*:

# SIP problem?
Include debug output! Please include output from "sip debug" if you have a SIP problem. This seems obvious, but apparently is not. Set debug to 4, verbose to 4, turn on sip history and dumphistory in sip.conf and capture all output. A packet trace from ethereal will not tell us what is happening inside your Asterisk server, so that is not a replacement.
By: Niccolò Belli (darkbasic) 2009-10-22 16:11:02

I added sipdebug = yes, recordhistory = yes, dumphistory = yes to sip.conf and I typed core set debug 4, core set verbose 4, sip set debug on, sip set history on in asterisk CLI.
I attached /var/log/messages and /var/log/debug.
I don't think it's a provider issue because if I don't use kapanga as an asterisk extentions it works flawlessly. Moreover a friend uses the same provider with callweaver and it works fine.

Thank you,
Darkbasic
By: Kevin P. Fleming (kpfleming) 2009-10-23 11:10:22

well, unfortunately those instructions on the bug posting guidelines don't quite result in the sort of log I'm looking for... I'll have to get them updated. If you could try again, please follow these steps:

1) Edit /etc/asterisk/logger.conf and create a new channel called 'complete' that has all the logger levels included (verbose, notice, warning, error, debug).

2) Run asterisk with 'core set verbose 10, 'core set debug 10', 'sip set debug on', and 'sip set history on'.

3) Make the test call, then upload the 'complete' log file.

Thanks!
By: Niccolò Belli (darkbasic) 2009-10-23 15:17:59

Here it is
By: Kevin P. Fleming (kpfleming) 2009-10-23 16:22:22

OK, it is as I suspected, this is not a T.38 issue at all. There are two problems here.

First, the Kapanga softphone sent us an INVITE, which we declined as it required authentication. It ACKed our decline, and all was good.

Second, it resent the INVITE (CSeq 2), with proper authentication. Asterisk sent 100 Trying, and proceeded to process through the dialplan and place a call out to your provider.

When the provider sent 183 Session Progress, Asterisk sent 183 Session Progress to Kapanga. Immediately after that, Kapanga sent *another* INVITE (Cseq 3), identical to the previous one. There is no reason for it to do this, but it should not be harmful.

Because the previous INVITE (CSeq 2) is still in process, Asterisk properly responded with 491 Request Pending to the INVITE (CSeq 3). This response was retransmitted four times, and the Kapanga softphone never ACKed this response. Failing to do is a SIP protocol violation, and Asterisk would normally drop the call one it has retransmitted six times.

However, after the fourth retransmission, the Kapanga softphone retransmitted the INVITE (CSeq 3), apparently assuming it had not been received (even though Asterisk had already replied to it four times). Unfortunately, instead of Asterisk immediately responding 491 Request Pending, it sent 100 Trying, followed by 491 Request Pending. While this is not ideal, it is not harmful.

The Kapanga softphone *still* did not ACK the 491 Request Pending, and eventually Asterisk tore down the call.

So there are two concerns here with the Kapanga softphone: first, it should not send a reINVITE while there is a pending INVITE, but if it is going to do that, it should properly respect the 491 Request Pending final response from Asterisk and ACK it. Failing to do is a protocol violation, and Asterisk can rightly assume that either the remote endpoint has disappeared (and is not receiving the response) or has failed in some way.

There is a minor bug here in Asterisk that it shouldn't send 100 Trying for an INVITE that is going to get a 491 response anyway, but that is trivial.
By: Niccolò Belli (darkbasic) 2009-10-24 18:00:53

Thank you very much for the clear explanation.

Cheers,
Darkbasic
By: Matt Jordan (mjordan) 2011-12-01 12:56:00.544-0600

As stated by Kevin, this is an issue with the Kapanga Softphone.  The 'minor bug' of Asterisk sending a 100 Trying before sending a 4xx response is not disallowed by the RFC, and is a behavior that we are not looking to change at this time.