[Home]

Summary:ASTERISK-08880: Placing a call on hold sends two INVITES in specific cases (with Cisco 2,811 fateway)
Reporter:Yehavi Bourvine (yehavi)Labels:
Date Opened:2007-02-26 07:41:46.000-0600Date Closed:2007-04-10 08:37:38
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/Interoperability
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) extensions.conf
( 1) test.txt
( 2) test.zip
( 3) test3.txt
Description:I have a Cisco-2,811 used as a PSTN gateway. When a call arrives from the Cisco gateway to a phone, placed into hold and then resumes, Asterisk sends two
consequtive INVITE messages to the Cisco without waiting for OK forom the first one, causing the Cisco to have "internal server error".
When the receiving phone is Snom this happens immediately when putting the call on hold.

When the call is originated from a phone to the Cisco all works ok.

                          Thanks! __Yehavi:

****** ADDITIONAL INFORMATION ******

Attached:
- SIP script from Ethereal.
- Two TCPdumps for Snom and non-snom phones.
- SIP SHOW PEER of the Cisco and one of the phones. Note the difference of
 the SIP options.

Cisco's IP is 128.139.26.6 (static in sip.conf) and phones behind it are 89444, 84xxx.
Snom is 80601 and Polycom is 80607 (realtime extensions, although I had the same issue with static definitions).
Comments:By: Joshua C. Colp (jcolp) 2007-02-26 10:57:44.000-0600

Please attach a sip debug of this happening so we can see what Asterisk is doing.
By: Serge Vecher (serge-v) 2007-02-26 11:25:09.000-0600

These instructions will help you. Please attach uncompressed files.
1) Prepare test environment (reduce the amount of unrelated traffic on the server);
2) Make sure your logger.conf has the following line:
  console => notice,warning,error,debug
3) restart Asterisk with the following command:
  'asterisk -Tvvvvvdddddngc | tee /tmp/verbosedebug.txt'
4) Enable SIP transaction logging with the following CLI commands:
set debug 4
set verbose 4
sip debug
5) Reproduce the problem
6) Trim startup information and attach verbosedebug.txt to the issue.
By: Yehavi Bourvine (yehavi) 2007-02-26 23:46:55.000-0600

The file test.txt contains two transactions (separated by a line of ===== signs):
- First transaction is a call from 89444 (an extension over the PRI) to 80602
 which is a SNOM. When the call is put on hold the problem appears immediately.
- Second transaction is a call from 89444 to 80604 (a Cisco 7912 phone). When
 put on hold the 8944 hears the music on hold. When released from hold
 the problem appears.

The "hold press" is marked preceeded by ~~~~.

                      Thanks, __Yehavi:
By: Yehavi Bourvine (yehavi) 2007-02-27 00:01:33.000-0600

File test3.txt is an example of a working case where the enter/exit of hold works correct (if it helps you). The target is an X-lite softphone on extension 80681.

                             Thanks, __Yehavi:
By: Serge Vecher (serge-v) 2007-02-27 10:36:10.000-0600

what code mods did you do to the sources?
By: Yehavi Bourvine (yehavi) 2007-02-27 10:47:45.000-0600

Oooooh, shame on me! I did two minor code changes and forgot from them. I noticed (on version 1.4.0) that no CDRs are written when I use the H extension (or was it during call transfer - don't remember now) so I did two code changes to force a CDR. I'll undo them and try to find someone at work to see whether it changes the behaviour. Will update later.

                 Sorry, __Yehavi:
By: Yehavi Bourvine (yehavi) 2007-02-27 12:12:22.000-0600

OK, I've backed out my changes and it doesn't seem to help (I am at home now so I tried calling someone who put me on hold and then couldn't connect me back).

The changes I've done are related to CDRs not created when having the H extension. in pbx.c:
       if ((res != AST_PBX_KEEPALIVE) && ast_exists_extension(c, c->context, "h", 1, c->cid.cid_num)) {
               if (c->cdr && ast_opt_end_cdr_before_h_exten)
the last line was changed to:
          if (c->cdr)

and in cdr.c I've added at the end of ast_cdr_end() :
           ast_set_flag(cdr, AST_CDR_FLAG_LOCKED);

(if not, no CDR was generated).
For reference purpose I've uploaded my extensions file as well. The SIP decices are defined via realtime.

                        Thanks, __Yehavi:
By: Serge Vecher (serge-v) 2007-02-27 12:47:04.000-0600

Might be a timing issue - we get response on a reinvite, log that, but then proceed with resending the reinvite anyway ...

�[Feb 27 07:30:48] �[1;32;40mDEBUG�[0;37;40m[19189]: �[1;37;40mchan_sip.c�[0;37;40m:�[1;37;40m4727�[0;37;40m �[1;37;40mfind_call�[0;37;40m: = No match Their Call ID: 7921261c58176f0d7c530e722904adff@132.64.9.163 Their Tag 1268759603 Our tag: as668cf442
�[Feb 27 07:30:48] �[1;32;40mDEBUG�[0;37;40m[19189]: �[1;37;40mchan_sip.c�[0;37;40m:�[1;37;40m4727�[0;37;40m �[1;37;40mfind_call�[0;37;40m: = Found Their Call ID: D12B806-C55B11DB-94F086A5-87E354FD@128.139.26.6 Their Tag 270AED48-1804 Our tag: as268edf01
�[Feb 27 07:30:48] �[1;32;40mDEBUG�[0;37;40m[19189]: �[1;37;40mchan_sip.c�[0;37;40m:�[1;37;40m2268�[0;37;40m �[1;37;40m__sip_semi_ack�[0;37;40m: *** SIP TIMER: Cancelling retransmission ASTERISK-9021 - INVITE (got response)
�[Feb 27 07:30:48] �[1;32;40mDEBUG�[0;37;40m[19189]: �[1;37;40mchan_sip.c�[0;37;40m:�[1;37;40m2277�[0;37;40m �[1;37;40m__sip_semi_ack�[0;37;40m: (Provisional) Stopping retransmission (but retaining packet) on 'D12B806-C55B11DB-94F086A5-87E354FD@128.139.26.6' Request 104: Found
�[Feb 27 07:30:48] �[1;32;40mDEBUG�[0;37;40m[19189]: �[1;37;40mchan_sip.c�[0;37;40m:�[1;37;40m12285�[0;37;40m �[1;37;40mhandle_response_invite�[0;37;40m: SIP response 100 to RE-invite on outgoing call D12B806-C55B11DB-94F086A5-87E354FD@128.139.26.6
�[Feb 27 07:30:48] �[1;32;40mDEBUG�[0;37;40m[19189]: �[1;37;40mchan_sip.c�[0;37;40m:�[1;37;40m12268�[0;37;40m �[1;37;40mcheck_pendings�[0;37;40m: Sending pending reinvite on 'D12B806-C55B11DB-94F086A5-87E354FD@128.139.26.6'
�[Feb 27 07:30:48] �[1;32;40mDEBUG�[0;37;40m[19189]: �[1;37;40mchan_sip.c�[0;37;40m:�[1;37;40m6050�[0;37;40m �[1;37;40mreqprep�[0;37;40m: Strict routing enforced for session D12B806-C55B11DB-94F086A5-87E354FD@128.139.26.6
By: Yehavi Bourvine (yehavi) 2007-03-02 06:12:12.000-0600

Anything you want me to test or try in order to locate the problem?

              Thanks, __Yehavi:
By: Yehavi Bourvine (yehavi) 2007-03-05 23:35:28.000-0600

As a temporary work around I've set canrinvite=no for the Cisco (2,811) gateway.

                       Thanks, __Yehavi:
By: Daniel Weatherford (ddub) 2007-03-28 16:09:47

I've experienced the same problem running Asterisk 1.4.1 with an ADTRAN NetVanta 7100.  I place the call from Asterisk to the 7100 on hold.  I see a re-invite sent from Asterisk.  The ADTRAN NetVanta7100 responds with a 100 (Trying) at which point the Asterisk sends a second re-invite on the same call-id.  The 7100 responds with a "500 server error - re-invite inside a re-invite".  

RFC3261 implys that a second re-invite should not be sent before receiving a 2xx response.


By: Steve Davies (one47) 2007-03-30 11:30:03

FYI,

I believe I have now been able to reproduce this in Asterisk 1.2.15 with Aastra phones, so if there is a patch or workaround I would be interested in a backport :) I can try to assist with that backport if necessary. Looking at the SIP code in 1.2.15:

       switch (resp) {
       case 100:       /* Trying */
               if (!ignore)
                       sip_cancel_destroy(p);
               check_pendings(p);
               ast_set_flag(p, SIP_CAN_BYE);
               break;

Is it an absurd generalisation to say that the ONLY purpose of a SIP 100 message is a keepalive? If so, allowing the check pending and the SIP_CAN_BYE might be a bit generous.

Is that likely to break anything if I disable those 2 lines?

Now I think about it, this might even explain a SIP "BAD! BAD! BAD!" error I am getting - If a call is in setup (Trying) state, and is then hung-up... Hmmm.... I'll experiment :)
By: Clod Patry (junky) 2007-04-05 15:20:07

yehavi:
could ya take a look at the patch in bug 9305?
By: Clod Patry (junky) 2007-04-05 15:24:08

ddub: you said:
RFC3261 implys that a second re-invite should not be sent before receiving a 2xx response.

I totally agree with you on this, but there's no such mechanism at this point for that.
By: Yehavi Bourvine (yehavi) 2007-04-05 22:42:27

Ouch... This request came one day too late. I am going to a small vacation in a few minutes, thus I'll be able to test the patch only on Tuesday's mornning.
Sorry...

                  __Yehavi:
By: Yehavi Bourvine (yehavi) 2007-04-10 00:14:26

The patch specified under bug 9305 fixed the problem.

                     __Yehavi:
By: Serge Vecher (serge-v) 2007-04-10 08:37:36

alrighty then, let's close this bug then and track the resolution in 9305.