[Home]

Summary:ASTERISK-07161: SIP CANCEL fails due to wrong Contact: URI
Reporter:Peng Yong (ppyy)Labels:
Date Opened:2006-06-13 13:34:37Date Closed:2007-07-09 21:20:53
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) asterisk_trunk_sip.log
( 1) asterisk_trunk_sip2.log
( 2) asterisk_trunk_sip3.log
( 3) asterisk-1.2-cancel-invalid-uri.patch
( 4) asterisk-trunk-cancel-invalid-uri.patch
( 5) cancel.txt
( 6) cancel2.txt
Description:a sip call to zap, and the zap cancel the call, it fails:

U 2006/06/14 02:30:56.312832 202.106.184.2:5060 -> 202.106.184.1:5060
CANCEL :013606118682@202.106.184.2 SIP/2.0.
Via: SIP/2.0/UDP 202.106.184.2:5060;branch=z9hG4bK2b498e76;rport.
Route: <sip:202.106.184.1;ftag=1298122303646;lr=on>.
From: <sip:013606118682@202.106.184.1>.
To: "ppyy"<sip:8002@202.106.184.1>;tag=1298122303646.
Contact: <sip:013606118682@202.106.184.2>.
Call-ID: AF17B1D3-266B-478F-8919-118830504A48@192.168.0.88.
CSeq: 101 CANCEL.
User-Agent: Babale PBX.
Max-Forwards: 70.
Content-Length: 0.
.

#
U 2006/06/14 02:30:56.315160 202.106.184.1:5060 -> 202.106.184.2:5060
SIP/2.0 479 Regretfully, we were not able to process the URI (479/SL).
Via: SIP/2.0/UDP 202.106.184.2:5060;branch=z9hG4bK2b498e76;rport=5060.
From: <sip:013606118682@202.106.184.1>.
To: "ppyy"<sip:8002@202.106.184.1>;tag=1298122303646.
Call-ID: AF17B1D3-266B-478F-8919-118830504A48@192.168.0.88.
CSeq: 101 CANCEL.
Server: OpenSer (1.0.1 (i386/linux)).
Content-Length: 0.
Warning: 392 202.106.184.1:5060 "Noisy feedback tells:  pid=15814 req_src_ip=202.106.184.2 req_src_port=5060 in_uri=:013606118682@202.106.184.2 out_uri=:013606118682@202.106.184.2 via_cnt==1".
.
Comments:By: Peng Yong (ppyy) 2006-06-13 13:53:10

the contact in Cancel was wrong. it should be "sip:013606118682@202.106.184.2".

and i find the contact was get from initreq:

   if (sipmethod == SIP_CANCEL) {
       c = p->initreq.rlPart2; /* Use original URI */

and the buffer which initreq.rlPart2 pointed, req.data, is not a persistant across the call, and it was overwrite by later packet:

first request:
"INVITE sip:013606118682@bjmg.pbx.hahacom.com:5060 SIP/2.0."
       ^ p->initreq.rlPart2 point here

next request:
"ACK sip:013606118682@201.32.22.2 SIP/2.0."
       ^ p->initreq.rlPart2 point still point here, but overwrite by a new packet.
By: Serge Vecher (serge-v) 2006-06-13 14:15:18

ppyy: can you also please attach a SIP debug trace from Asterisk console too?

1) Make sure your logger.conf has the following line:
  console => notice,warning,error,debug
2) Enable SIP transaction logging with the following CLI commands:
set debug 4
set verbose 4
sip debug
3) Save complete log to file and _attach_ said file to the bug.

Thanks
By: Olle Johansson (oej) 2006-06-14 07:08:08

ppyy: Cool discovery. Thanks. Will look at your debug logs to try to find out when we overwrite the initial request.
By: Olle Johansson (oej) 2006-06-14 07:11:42

Well, since we've got an ack, we're not allowed to send cancel anyway...
By: Olle Johansson (oej) 2006-06-14 07:23:27

Try disabling re-invite and see if it happens again
By: Peng Yong (ppyy) 2006-06-14 09:57:13

sip.conf:
canreinvite=no

and "sip show peer ser" confirm it.

same problem.
By: Peng Yong (ppyy) 2006-06-14 10:03:37

oej: sip signal are correct before the PSTN hangup:
INVITE ->
SIP/2.0 100 Trying <-
SIP/2.0 180 Ringing <-

just after the PSTN hangup, asterisk send the "SIP/2.0 200 OK", and openser send "ACK". then show the problem
By: Peng Yong (ppyy) 2006-06-15 02:18:36

i found this is caused by AGI write by my partener. if busy, the call is answered and play a voice to user. remove these lines, it's ok.

BTW, i think we should also resolve this issue, it will get out in some conditions.

my $dialstatus = $mg->dial_status();
if($dialstatus eq 'BUSY') {
   $log->info('Dst is BUSY');
   $AGI->answer();
   $audio->play_busy;
} elsif($dialstatus eq 'NOANSWER') {
   $log->info('Dst No Answer');
   $AGI->answer();
   $audio->play_noanswer;
} elsif($dialstatus eq 'WRONGNUM') {
   $log->info('Wrong Number called');
   $AGI->answer();
   $audio->play_wrong_num;
}
end_call();
exit(0);
By: Olle Johansson (oej) 2006-06-15 08:09:48

So this is a timing issue with the "wait with hangup" code I guess.
By: Serge Vecher (serge-v) 2006-09-01 14:08:12

ppyy: do you have a patch for this issue?
By: Peng Yong (ppyy) 2006-09-07 10:10:12

sorry, no patch
By: Olle Johansson (oej) 2006-09-12 09:25:26

Can you please try again with latest svn trunk? Thanks.
By: Olle Johansson (oej) 2006-09-12 09:34:39

Well, trunk does not handle this issue. My mistake. ppyy - can you find where we overwrite the initreq?
By: Olle Johansson (oej) 2006-09-12 09:38:07

This whole logic is very strange.
<- INVITE
-> 200 OK
<- ACK
--- CAll is up
At hangup, we send CANCEL ???
By: Olle Johansson (oej) 2006-09-12 09:42:02

This is interesting. Since we start the hangup process at the same time as the call is ACKed, we actually don't have a call in the UP state and the logic says "send CANCEL" which is wrong. We should of course send BYE.
By: Olle Johansson (oej) 2006-09-12 09:42:22

...which still doesn't explain the bad URI, but one thing at a time...
By: Olle Johansson (oej) 2006-09-18 14:57:10

Committed some changes to svn trunk, rev 43214. Please test!
By: timrobbins (timrobbins) 2006-10-11 18:54:44

Problem still exists in 1.4.0-beta2.

One way that I've run into this bug is to enable G.729 in sip.conf *without* codec_g729a.so installed, then make a call into Asterisk from a device that only supports G.729, and have an extension do the following:
Wait(1)
Playback(tt-weasels)
Hangup

Asterisk sends a 200 OK, receives an ACK, tries to play the sound but fails, then sends a CANCEL. Asterisk shouldn't be sending a CANCEL here since it didn't initiate the INVITE transaction (it is acting as UAS).

Client: CounterPath eyeBeam 1.5.9 build 32576, fully patched WinXP SP2
Server: Asterisk 1.4.0-beta2, fully patched Solaris x86 6/06
By: Olle Johansson (oej) 2006-10-17 07:10:37

timrobbins: That's another bug. Please open another bug report and upload a debug file. Thanks.
By: Serge Vecher (serge-v) 2006-10-23 08:45:41

ppyy: any luck with testing here?
By: rbosch (rbosch) 2006-10-24 14:19:44

I have been experiencing this problem when using a SIP trunk pointing to an IVR set up using freepbx.  All other inbound calls on the SIP trunk work perfectly.  I can test the fix if someone will point me to the code segment that needs to be pulled from svn.

More specifically when an inbound call from the SIP trunk where the CID is pointing to an IVR, the following responses come from Asterisk (note, PRIVATE used to replace the inbound number, EMAIL used to replace my email address):

   -- Executing [+1PRIVATE@from-sip-external:1] NoOp("SIP/4.68.250.148-0083c
600", "Received incoming SIP connection from unknown peer to +1PRIVATE") in n
ew stack
    -- Executing [+1PRIVATE@from-sip-external:2] Set("SIP/4.68.250.148-0083c
600", "DID=PRIVATE") in new stack
    -- Executing [+1PRIVATE@from-sip-external:3] Goto("SIP/4.68.250.148-0083
c600", "s|1") in new stack
    -- Goto (from-sip-external,s,1)
    -- Executing [s@from-sip-external:1] GotoIf("SIP/4.68.250.148-0083c600", "1
?from-trunk|PRIVATE|1") in new stack
    -- Goto (from-trunk,PRIVATE,1)
    -- Executing [PRIVATE@from-trunk:1] Set("SIP/4.68.250.148-0083c600", "FR
OM_DID=PRIVATE") in new stack
    -- Executing [PRIVATE@from-trunk:2] Set("SIP/4.68.250.148-0083c600", "FA
X_RX=system") in new stack
    -- Executing [PRIVATE@from-trunk:3] Set("SIP/4.68.250.148-0083c600", "FA
X_RX_EMAIL=EMAIL") in new stack
    -- Executing [PRIVATE@from-trunk:4] Answer("SIP/4.68.250.148-0083c600",
"") in new stack
   -- Executing [PRIVATE@from-trunk:5] PlayTones("SIP/4.68.250.148-0083c600"
, "ring") in new stack
 == Spawn extension (from-trunk, PRIVATE, 6) exited non-zero on 'SIP/4.68.25
0.148-0083c600'
   -- Incoming call: Got SIP response 479 "Regretfully, we were not able to pro
cess the URI (479/SL)" back from 4.79.212.236


By: rbosch (rbosch) 2006-10-24 14:30:05

Additional information...it turns out that it is not due to the digital receptionist (IVR).  The issue only manifests itself when the fax tones are supposed to play.  I think this is related to the fax not the IVR.  I'm not sure that there is an error in Asterisk, maybe just a configuration issue on my end.
By: rbosch (rbosch) 2006-10-24 16:30:23

Through testing I have narrowed down that anytime I am detecting fax tones on a SIP trunk I'm getting the error.  Disable the fax tones and all works fine.  Is this an error in this component?  Should it be listed elsewhere?
By: Olle Johansson (oej) 2006-10-25 14:51:01

no answer from reporter. Please re-open when we have new information or answers. THanks.
By: Tilghman Lesher (tilghman) 2006-11-13 08:25:12.000-0600

Reopened upon request.
By: Olle Johansson (oej) 2006-11-13 13:25:46.000-0600

...and...
By: Mario Fdez. Alonso (mariofalonso) 2006-11-14 03:59:02.000-0600

Hi, I've sent attachment file with the asterisk log in bug 0008351.
If you need more log tell me it.
By: Olle Johansson (oej) 2006-11-14 06:12:15.000-0600

I still wonder where the SIP_ACK gets into initreq...
By: Olle Johansson (oej) 2006-11-14 06:32:03.000-0600

Please update to latest svn trunk and capture another log file. I've added some new debug output I want to see. Thanks.
By: Mario Fdez. Alonso (mariofalonso) 2006-11-14 06:35:16.000-0600

Ok. I'll send you the new log.
By: Mario Fdez. Alonso (mariofalonso) 2006-11-15 04:22:16.000-0600

Hi, the new log file using trunk version is ready.
The file name is asterisk_trunk_sip.log is located in attached files.
Thanks!
By: Olle Johansson (oej) 2006-11-15 05:59:46.000-0600

Thank you, but there's no debug logs in this. You need to enable debug to console in logger.conf, then set debug to 4, verbose to 4, turn sip debug on and capture everything. Thanks for your efforts.
By: Mario Fdez. Alonso (mariofalonso) 2006-11-15 06:20:38.000-0600

Sorry, here you are the new log file.
Filename:asterisk_trunk_sip2.log
Thanks!
By: Olle Johansson (oej) 2006-11-15 15:29:51.000-0600

Is this a clean checkout without any external modules/patchees?

Also, I've added even more logs to help to track this. Please re-run and upload a new log file from a new checkout. Thanks for your patience.
By: Mario Fdez. Alonso (mariofalonso) 2006-11-16 03:26:40.000-0600

Yes, it's a clean checkout.
File name asterisk_trunk_sip3.log.
Thanks again.
By: Olle Johansson (oej) 2006-11-16 05:22:05.000-0600

This is amazing. I think I've added logs to all places where we change initreq, and it gets changed without logging... Magical mystery tour.

Still digging.
By: Mario Fdez. Alonso (mariofalonso) 2006-11-16 05:56:22.000-0600

Another thread is writting there?
Maybe mutex_lock?
Good luck!
By: Olle Johansson (oej) 2007-02-14 10:59:42.000-0600

This bug report needs more attention, we need to fix this.
By: Mario Fdez. Alonso (mariofalonso) 2007-02-15 02:21:18.000-0600

Ok, any help?
By: Wojtek Kaniewski (wojtekka) 2007-04-24 02:37:49

copy_request() doesn't update rlPart1 and rlPart2, so they still point to source request. As source request is usually the local variable req in sipsock_read(), it is overwritten by subsequent requests (and so does data that rlPart1 and rlPart2 are pointing to).

I've attached two patches -- one for trunk, one for 1.2 branch. Disclaimer on file.
By: Olle Johansson (oej) 2007-04-27 08:47:22

wojtekka: Good catch! I'll look into this.
By: Olle Johansson (oej) 2007-04-27 08:49:05

ppyy: Can you confirm that the patch fixes your issue?
By: Olle Johansson (oej) 2007-04-27 09:03:11

Change committed to 1.2 svn rev 62126, later 1.4 and trunk.

Waiting for feedback to confirm that this really was THE fix.
By: Olle Johansson (oej) 2007-05-30 02:35:47

No answer, assume it's fixed. If not, please re-open or contact me on IRC. Thanks.