[Home]

Summary:ASTERISK-15183: [patch][regression] DTMF Not Recognized with Exchange UM
Reporter:rsw686 (rsw686)Labels:
Date Opened:2009-11-20 09:53:34.000-0600Date Closed:2010-03-18 15:10:00
Priority:BlockerRegression?Yes
Status:Closed/CompleteComponents:Channels/chan_sip/Interoperability
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) asterisk-1.6.1.11-constantssrc.patch
( 1) asterisk-1.6.1.11-constantssrc-debug.patch
( 2) constantssrc-dtmf-1.6.1.11.patch
( 3) dtmf.patch
( 4) dtmf-1.6.1.10.log
( 5) dtmf-1.6.1.7-rc1.log
Description:I just upgraded my Asterisk 1.6.1.4 version to 1.6.1.10 and the DTMF tones are not being recognized by the Exchange UM server. I tested out the RC release and found that it worked in 1.6.1.7-rc1 and broke in 1.6.1.7-rc2.

What happens is Exchange UM will say to enter your mailbox number. I enter 8532 and it will say that 8 is not a valid entry. It appears Asterisk is only detecting the first DTMF tone.
Comments:By: Leif Madsen (lmadsen) 2009-11-20 12:50:49.000-0600

Could you provide a console output with debug enabled so we can see the DTMF being sent to Asterisk?

We may need a wireshark trace as well since it is likely your DTMF is setup to be RFC2833 which is out of band, but isn't traceable from insider Asterisk directly. Thanks!
By: rsw686 (rsw686) 2009-11-20 13:38:29.000-0600

I have attached debug logs for 1.6.1.7-rc1 and 1.6.1.10. Asterisk is receiving the dtmf tones and appears to be sending them. However something is happening different behind the scenes. I am using the same box and can make install and run 1.6.1.4 or 1.6.1.7-rc1 and it works. As soon as I make install and run 1.6.1.7-rc2, 1.6.1.10-rc2, or 1.6.1.10 it stops working. I have tried both X-Lite and Snom 370 phones.
By: Leif Madsen (lmadsen) 2009-11-23 19:57:05.000-0600

Since you've narrowed it down to between 1.6.1.7-rc1 and 1.6.1.7-rc2, would you mind checking the differences between those two differences, and tracking down which commit may have caused the regression?
By: rsw686 (rsw686) 2009-11-25 09:49:35.000-0600

The regression comes from the added "when changing sources, don't generate a new SSRC" in main/rtp.c. I have attached a patch against 1.6.1.10 removing this code, which resolves the dtmf issue.
By: rsw686 (rsw686) 2009-11-25 10:11:01.000-0600

Upon further digging I found in the changelog that there was a new setting in sip.conf that allows you to disable this new behavior and keep a constant ssrc. I added constantssrc=true like mentioned in the changelog to sip.conf. However I am not getting the expected change. I also tried =false, =yes, and =no. I'm not sure what is wrong with the logic but my attached patch defiantly resolves the problem. I can untar 1.6.1.10, apply the dtmf.patch and make install and dtmf tones are working with Exchange UM.

Can somebody look into the logic for constantssrc in sip.conf. It also might be good to make a note in UPGRADE.txt that the previous behavior is changed.


By: rsw686 (rsw686) 2009-12-01 13:25:32.000-0600

I added some verbose logging to main/rtp.c.

void ast_rtp_set_constantssrc(struct ast_rtp *rtp)
{
       ast_verbose("ast_rtp_set_constantssrc: setting flag\n");
       rtp->constantssrc = 1;
}

void ast_rtp_new_source(struct ast_rtp *rtp)
{
       if (rtp) {
               rtp->set_marker_bit = 1;
               ast_verbose("ast_rtp_new_source: constantssrc is %d\n", rtp->constantssrc);
               if (!rtp->constantssrc) {
                       rtp->ssrc = ast_random();
               }
       }
}

Have a look at the asterisk output. The flag is getting set correctly, but for some reason it is toggling back and forth when I press keys on the phone. Shouldn't this stay set the entire call? If I comment out the ast_random line in ast_rtp_new_source the DTMF tones work fine.

 == Using SIP RTP CoS mark 5
ast_rtp_set_constantssrc: setting flag
   -- Executing [3300@default:1] Answer("SIP/38678-00000003", "") in new stack
ast_rtp_new_source: constantssrc is 1
   -- Executing [3300@default:2] Dial("SIP/38678-00000003", "SIP/SIP_VM/3300,,TTr") in new stack
 == Using SIP RTP CoS mark 5
ast_rtp_set_constantssrc: setting flag
   -- Called SIP_VM/3300
   -- Got SIP response 302 "Moved Temporarily" back from 10.9.1.13
   -- Now forwarding SIP/38678-00000003 to 'SIP/3300::::TCP@10.9.1.13:5067' (thanks to SIP/SIP_VM-00000004)
 == Using SIP RTP CoS mark 5
   -- SIP/10.9.1.13:5067-00000005 is ringing
   -- SIP/10.9.1.13:5067-00000005 answered SIP/38678-00000003
ast_rtp_new_source: constantssrc is 1
ast_rtp_new_source: constantssrc is 0
ast_rtp_new_source: constantssrc is 1
ast_rtp_new_source: constantssrc is 0
ast_rtp_new_source: constantssrc is 1
ast_rtp_new_source: constantssrc is 0
ast_rtp_new_source: constantssrc is 1
ast_rtp_new_source: constantssrc is 0
ast_rtp_new_source: constantssrc is 1
ast_rtp_new_source: constantssrc is 0
ast_rtp_new_source: constantssrc is 1
ast_rtp_new_source: constantssrc is 0
ast_rtp_new_source: constantssrc is 1
ast_rtp_new_source: constantssrc is 0
ast_rtp_new_source: constantssrc is 1
ast_rtp_new_source: constantssrc is 0
ast_rtp_new_source: constantssrc is 1
ast_rtp_new_source: constantssrc is 0
ast_rtp_new_source: constantssrc is 1
ast_rtp_new_source: constantssrc is 0
ast_rtp_new_source: constantssrc is 1
ast_rtp_new_source: constantssrc is 0
ast_rtp_new_source: constantssrc is 1
ast_rtp_new_source: constantssrc is 0
ast_rtp_new_source: constantssrc is 1
ast_rtp_new_source: constantssrc is 0
ast_rtp_new_source: constantssrc is 1
ast_rtp_new_source: constantssrc is 0
ast_rtp_new_source: constantssrc is 1
ast_rtp_new_source: constantssrc is 0
ast_rtp_new_source: constantssrc is 1
ast_rtp_new_source: constantssrc is 0
ast_rtp_new_source: constantssrc is 1
ast_rtp_new_source: constantssrc is 0
By: rsw686 (rsw686) 2009-12-01 13:51:52.000-0600

Looks like there is a second rtp stream being for the DTMF that the constantssrc bit isn't getting set for.

void ast_rtp_set_constantssrc(struct ast_rtp *rtp)
{
       ast_verbose("ast_rtp_set_constantssrc: setting flag\n");
       rtp->constantssrc = 1;
}

void ast_rtp_new_source(struct ast_rtp *rtp)
{
       if (rtp) {
               rtp->set_marker_bit = 1;
               unsigned int oldssrc = rtp->ssrc;
               if (!rtp->constantssrc) {
                       rtp->ssrc = ast_random();
               }
               ast_verbose("ast_rtp_new_source: ssrc is %d, new ssrc is %d, constantssrc is %d\n", oldssrc, rtp->ssrc, rtp->constantssrc);
       }
}

 == Using SIP RTP CoS mark 5
ast_rtp_set_constantssrc: setting flag
   -- Executing [3300@default:1] Answer("SIP/38678-00000000", "") in new stack
ast_rtp_new_source: ssrc is 492797963, new ssrc is 492797963, constantssrc is 1
   -- Executing [3300@default:2] Dial("SIP/38678-00000000", "SIP/SIP_VM/3300,,TTr") in new stack
 == Using SIP RTP CoS mark 5
ast_rtp_set_constantssrc: setting flag
   -- Called SIP_VM/3300
   -- Got SIP response 302 "Moved Temporarily" back from 10.9.1.13
   -- Now forwarding SIP/38678-00000000 to 'SIP/3300::::TCP@10.9.1.13:5067' (thanks to SIP/SIP_VM-00000001)
 == Using SIP RTP CoS mark 5
   -- SIP/10.9.1.13:5067-00000002 is ringing
   -- SIP/10.9.1.13:5067-00000002 answered SIP/38678-00000000
ast_rtp_new_source: ssrc is 492797963, new ssrc is 492797963, constantssrc is 1
ast_rtp_new_source: ssrc is 461866577, new ssrc is 1555714261, constantssrc is 0
ast_rtp_new_source: ssrc is 492797963, new ssrc is 492797963, constantssrc is 1
ast_rtp_new_source: ssrc is 1555714261, new ssrc is 1352119684, constantssrc is 0
ast_rtp_new_source: ssrc is 492797963, new ssrc is 492797963, constantssrc is 1
ast_rtp_new_source: ssrc is 1352119684, new ssrc is 691442459, constantssrc is 0
ast_rtp_new_source: ssrc is 492797963, new ssrc is 492797963, constantssrc is 1
ast_rtp_new_source: ssrc is 691442459, new ssrc is 244400140, constantssrc is 0
ast_rtp_new_source: ssrc is 492797963, new ssrc is 492797963, constantssrc is 1
ast_rtp_new_source: ssrc is 244400140, new ssrc is 628275142, constantssrc is 0
ast_rtp_new_source: ssrc is 492797963, new ssrc is 492797963, constantssrc is 1
ast_rtp_new_source: ssrc is 628275142, new ssrc is 1397725581, constantssrc is 0
ast_rtp_new_source: ssrc is 492797963, new ssrc is 492797963, constantssrc is 1
ast_rtp_new_source: ssrc is 1397725581, new ssrc is 1011292212, constantssrc is 0
ast_rtp_new_source: ssrc is 492797963, new ssrc is 492797963, constantssrc is 1
ast_rtp_new_source: ssrc is 1011292212, new ssrc is 216313247, constantssrc is 0
ast_rtp_new_source: ssrc is 492797963, new ssrc is 492797963, constantssrc is 1
ast_rtp_new_source: ssrc is 216313247, new ssrc is 1340074936, constantssrc is 0
ast_rtp_new_source: ssrc is 492797963, new ssrc is 492797963, constantssrc is 1
ast_rtp_new_source: ssrc is 1340074936, new ssrc is 1693137277, constantssrc is 0
ast_rtp_new_source: ssrc is 492797963, new ssrc is 492797963, constantssrc is 1
ast_rtp_new_source: ssrc is 1693137277, new ssrc is 1536225844, constantssrc is 0
ast_rtp_new_source: ssrc is 492797963, new ssrc is 492797963, constantssrc is 1
ast_rtp_new_source: ssrc is 1536225844, new ssrc is 1916174420, constantssrc is 0
ast_rtp_new_source: ssrc is 492797963, new ssrc is 492797963, constantssrc is 1
ast_rtp_new_source: ssrc is 1916174420, new ssrc is 1708622714, constantssrc is 0
ast_rtp_new_source: ssrc is 492797963, new ssrc is 492797963, constantssrc is 1
ast_rtp_new_source: ssrc is 1708622714, new ssrc is 1612280003, constantssrc is 0
ast_rtp_new_source: ssrc is 492797963, new ssrc is 492797963, constantssrc is 1
ast_rtp_new_source: ssrc is 1612280003, new ssrc is 279440336, constantssrc is 0
ast_rtp_new_source: ssrc is 492797963, new ssrc is 492797963, constantssrc is 1
ast_rtp_new_source: ssrc is 279440336, new ssrc is 2073867699, constantssrc is 0
ast_rtp_new_source: ssrc is 492797963, new ssrc is 492797963, constantssrc is 1
ast_rtp_new_source: ssrc is 2073867699, new ssrc is 197138117, constantssrc is 0
ast_rtp_new_source: ssrc is 197138117, new ssrc is 434141706, constantssrc is 0
By: rsw686 (rsw686) 2009-12-01 14:08:31.000-0600

I've attached constantssrc-dtmf-1.6.1.11.patch, which fixes the DTMF issue and still keeps the random ssrc functionality. With RFC2833 DTMF the RTP stream used to send the digits wasn't being set with the constantssrc flag.
By: rsw686 (rsw686) 2009-12-01 14:35:48.000-0600

That patch doesn't look to address the root of the problem. I entered down a few lines before pressing any digits. Notice the first two ast_rtp_new_source lines where constantssrc is set to 0 when it should be 1. My patch just bandaid fixes this when it matters with the DTMF.

 == Using SIP RTP CoS mark 5
ast_rtp_set_constantssrc: setting flag
   -- Executing [3300@default:1] Answer("SIP/38678-00000003", "") in new stack
ast_rtp_new_source: ssrc is 737283680, new ssrc is 737283680, constantssrc is 1
   -- Executing [3300@default:2] Dial("SIP/38678-00000003", "SIP/SIP_VM/3300,,TTr") in new stack
 == Using SIP RTP CoS mark 5
ast_rtp_set_constantssrc: setting flag
   -- Called SIP_VM/3300
   -- Got SIP response 302 "Moved Temporarily" back from 10.9.1.13
   -- Now forwarding SIP/38678-00000003 to 'SIP/3300::::TCP@10.9.1.13:5067' (thanks to SIP/SIP_VM-00000004)
 == Using SIP RTP CoS mark 5
   -- SIP/10.9.1.13:5067-00000005 is ringing
   -- SIP/10.9.1.13:5067-00000005 answered SIP/38678-00000003
ast_rtp_new_source: ssrc is 737283680, new ssrc is 737283680, constantssrc is 1
ast_rtp_new_source: ssrc is 1680399766, new ssrc is 1059187456, constantssrc is 0
asterisk*CLI>
asterisk*CLI>
asterisk*CLI>
asterisk*CLI>
asterisk*CLI>
asterisk*CLI>
asterisk*CLI>
asterisk*CLI>
asterisk*CLI>
ast_rtp_new_source: ssrc is 737283680, new ssrc is 737283680, constantssrc is 1
ast_rtp_new_source: ssrc is 1059187456, new ssrc is 948522615, constantssrc is 0
ast_rtp_new_source: ssrc is 737283680, new ssrc is 737283680, constantssrc is 1
ast_rtp_new_source: ssrc is 948522615, new ssrc is 379902569, constantssrc is 0
ast_rtp_new_source: ssrc is 737283680, new ssrc is 737283680, constantssrc is 1
ast_rtp_new_source: ssrc is 379902569, new ssrc is 95827666, constantssrc is 0
sip_senddigit_begin: caller id: 3300
ast_rtp_set_constantssrc: setting flag
ast_rtp_new_source: ssrc is 737283680, new ssrc is 737283680, constantssrc is 1
ast_rtp_new_source: ssrc is 95827666, new ssrc is 95827666, constantssrc is 1
ast_rtp_new_source: ssrc is 737283680, new ssrc is 737283680, constantssrc is 1
ast_rtp_new_source: ssrc is 95827666, new ssrc is 95827666, constantssrc is 1
ast_rtp_new_source: ssrc is 737283680, new ssrc is 737283680, constantssrc is 1
ast_rtp_new_source: ssrc is 95827666, new ssrc is 95827666, constantssrc is 1
ast_rtp_new_source: ssrc is 737283680, new ssrc is 737283680, constantssrc is 1
ast_rtp_new_source: ssrc is 95827666, new ssrc is 95827666, constantssrc is 1
sip_senddigit_begin: caller id: 3300
ast_rtp_set_constantssrc: setting flag
ast_rtp_new_source: ssrc is 737283680, new ssrc is 737283680, constantssrc is 1
ast_rtp_new_source: ssrc is 95827666, new ssrc is 95827666, constantssrc is 1
ast_rtp_new_source: ssrc is 737283680, new ssrc is 737283680, constantssrc is 1
ast_rtp_new_source: ssrc is 95827666, new ssrc is 95827666, constantssrc is 1
ast_rtp_new_source: ssrc is 737283680, new ssrc is 737283680, constantssrc is 1
ast_rtp_new_source: ssrc is 95827666, new ssrc is 95827666, constantssrc is 1
ast_rtp_new_source: ssrc is 737283680, new ssrc is 737283680, constantssrc is 1
ast_rtp_new_source: ssrc is 95827666, new ssrc is 95827666, constantssrc is 1
sip_senddigit_begin: caller id: 3300
ast_rtp_set_constantssrc: setting flag
ast_rtp_new_source: ssrc is 737283680, new ssrc is 737283680, constantssrc is 1
ast_rtp_new_source: ssrc is 95827666, new ssrc is 95827666, constantssrc is 1
ast_rtp_new_source: ssrc is 737283680, new ssrc is 737283680, constantssrc is 1
ast_rtp_new_source: ssrc is 95827666, new ssrc is 95827666, constantssrc is 1
ast_rtp_new_source: ssrc is 737283680, new ssrc is 737283680, constantssrc is 1
ast_rtp_new_source: ssrc is 95827666, new ssrc is 95827666, constantssrc is 1
ast_rtp_new_source: ssrc is 737283680, new ssrc is 737283680, constantssrc is 1
ast_rtp_new_source: ssrc is 95827666, new ssrc is 95827666, constantssrc is 1
sip_senddigit_begin: caller id: 3300
ast_rtp_set_constantssrc: setting flag
ast_rtp_new_source: ssrc is 737283680, new ssrc is 737283680, constantssrc is 1
ast_rtp_new_source: ssrc is 95827666, new ssrc is 95827666, constantssrc is 1
ast_rtp_new_source: ssrc is 95827666, new ssrc is 95827666, constantssrc is 1
By: rsw686 (rsw686) 2009-12-01 15:04:39.000-0600

Here is the debug output from the console. It looks like the root of the problem is that when the channel is forwarded the constantssrc bit isn't copied. You can see where the constantssrc flag is set just before the forward, but not set afterwards. I'm not sure where in the code this should be fixed.

 == Using SIP RTP CoS mark 5
[Dec  1 15:55:14] DEBUG[11430]: chan_sip.c:4626 do_setnat: Setting NAT on RTP to Off
[Dec  1 15:55:14] DEBUG[11430]: chan_sip.c:6830 sip_alloc: Allocating new SIP dialog for ZjFmYjA3Mzg1MDc1NDIxMTdhYTJiNmY0NjcxYmUzNWQ. - INVITE (With RTP)
[Dec  1 15:55:14] DEBUG[11430]: chan_sip.c:4626 do_setnat: Setting NAT on RTP to Off
[Dec  1 15:55:14] DEBUG[11430]: chan_sip.c:3174 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.9.5.63:64274
[Dec  1 15:55:14] DEBUG[11430]: chan_sip.c:3709 __sip_ack: Stopping retransmission on 'ZjFmYjA3Mzg1MDc1NDIxMTdhYTJiNmY0NjcxYmUzNWQ.' of Response 1: Match Found
[Dec  1 15:55:14] DEBUG[11430]: chan_sip.c:4626 do_setnat: Setting NAT on RTP to Off
ast_rtp_set_constantssrc: setting flag
[Dec  1 15:55:14] DEBUG[11430]: chan_sip.c:19021 handle_request_invite: Checking SIP call limits for device 38678
[Dec  1 15:55:14] DEBUG[11430]: chan_sip.c:3174 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.9.5.63:64274
[Dec  1 15:55:14] DEBUG[22941]: pbx.c:3200 pbx_extension_helper: Launching 'Answer'
   -- Executing [3300@default:1] Answer("SIP/38678-0000000f", "") in new stack
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:5772 sip_answer: SIP answering channel: SIP/38678-0000000f
ast_rtp_new_source: ssrc is 49978530, new ssrc is 49978530, constantssrc is 1
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:9736 transmit_response_with_sdp: Setting framing from config on incoming call
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:9405 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:9406 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:3174 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.9.5.63:64274
[Dec  1 15:55:14] DEBUG[22941]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 132 bytes
[Dec  1 15:55:14] DEBUG[22941]: pbx.c:3200 pbx_extension_helper: Launching 'Dial'
   -- Executing [3300@default:2] Dial("SIP/38678-0000000f", "SIP/SIP_VM/3300,,TTr") in new stack
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:22016 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
 == Using SIP RTP CoS mark 5
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:6830 sip_alloc: Allocating new SIP dialog for 75cf3053617b088f658353b81dda2aea@127.0.0.1 - INVITE (With RTP)
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:4626 do_setnat: Setting NAT on RTP to Off
ast_rtp_set_constantssrc: setting flag
[Dec  1 15:55:14] DEBUG[22941]: channel.c:4262 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[Dec  1 15:55:14] DEBUG[22941]: channel.c:4262 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[Dec  1 15:55:14] DEBUG[22941]: channel.c:4262 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[Dec  1 15:55:14] DEBUG[22941]: channel.c:4262 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[Dec  1 15:55:14] DEBUG[22941]: channel.c:4262 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[Dec  1 15:55:14] DEBUG[22941]: channel.c:4262 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Dec  1 15:55:14] DEBUG[22941]: channel.c:4262 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Dec  1 15:55:14] DEBUG[22941]: channel.c:4262 ast_channel_inherit_variables: Not copying variable SIPURI.
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:5030 sip_call: Outgoing Call for 3300
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:9405 add_sdp: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False Text flag: False
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:9406 add_sdp: ** Our prefcodec: 0x4 (ulaw)
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:2897 initialize_initreq: Initializing initreq for method INVITE - callid 7641df9072b9c28a41b566c06bcbd11f@10.9.1.121
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:3174 __sip_xmit: Trying to put 'INVITE sip:' onto TCP socket destined for 10.9.1.13:5060
   -- Called SIP_VM/3300
[Dec  1 15:55:14] DEBUG[22941]: channel.c:3178 ast_indicate_data: Driver for channel 'SIP/38678-0000000f' does not support indication 3, emulating it
[Dec  1 15:55:14] DEBUG[22941]: channel.c:3655 set_format: Set channel SIP/38678-0000000f to write format slin
[Dec  1 15:55:14] DEBUG[22941]: channel.c:2377 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Dec  1 15:55:14] DEBUG[22941]: channel.c:2490 ast_read_generator_actions: Generator got voice, switching to phase locked mode
[Dec  1 15:55:14] DEBUG[22941]: channel.c:2377 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Dec  1 15:55:14] DEBUG[22941]: rtp.c:3806 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Dec  1 15:55:14] DEBUG[22941]: rtp.c:3822 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
   -- Got SIP response 302 "Moved Temporarily" back from 10.9.1.13
   -- Now forwarding SIP/38678-0000000f to 'SIP/3300::::TCP@10.9.1.13:5067' (thanks to SIP/SIP_VM-00000010)
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:22016 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
 == Using SIP RTP CoS mark 5
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:6830 sip_alloc: Allocating new SIP dialog for 3f58a80332343f772b91ca9b32f5cb55@127.0.0.1 - INVITE (With RTP)
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:4626 do_setnat: Setting NAT on RTP to Off
[Dec  1 15:55:14] DEBUG[22941]: channel.c:4262 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[Dec  1 15:55:14] DEBUG[22941]: channel.c:4262 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[Dec  1 15:55:14] DEBUG[22941]: channel.c:4262 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[Dec  1 15:55:14] DEBUG[22941]: channel.c:4262 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[Dec  1 15:55:14] DEBUG[22941]: channel.c:4262 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[Dec  1 15:55:14] DEBUG[22941]: channel.c:4262 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Dec  1 15:55:14] DEBUG[22941]: channel.c:4262 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Dec  1 15:55:14] DEBUG[22941]: channel.c:4262 ast_channel_inherit_variables: Not copying variable SIPURI.
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:5030 sip_call: Outgoing Call for 3300
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:9405 add_sdp: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False Text flag: False
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:9406 add_sdp: ** Our prefcodec: 0x4 (ulaw)
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:2897 initialize_initreq: Initializing initreq for method INVITE - callid 60567a2b593d6fb83e2e3d2b769db223@10.9.1.121
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:3174 __sip_xmit: Trying to put 'INVITE sip:' onto TCP socket destined for 10.9.1.13:5067
[Dec  1 15:55:14] DEBUG[11450]: chan_sip.c:3174 __sip_xmit: Trying to put 'ACK sip:330' onto TCP socket destined for 10.9.1.13:5060
[Dec  1 15:55:14] DEBUG[22941]: channel.c:1711 ast_hangup: Hanging up channel 'SIP/SIP_VM-00000010'
[Dec  1 15:55:14] DEBUG[22941]: chan_sip.c:5583 sip_hangup: Hangup call SIP/SIP_VM-00000010, SIP callid 7641df9072b9c28a41b566c06bcbd11f@10.9.1.121
   -- SIP/10.9.1.13:5067-00000011 is ringing
[Dec  1 15:55:14] DEBUG[22941]: channel.c:3178 ast_indicate_data: Driver for channel 'SIP/38678-0000000f' does not support indication 3, emulating it
[Dec  1 15:55:14] DEBUG[22941]: channel.c:3655 set_format: Set channel SIP/38678-0000000f to write format ulaw
[Dec  1 15:55:14] DEBUG[22941]: channel.c:3655 set_format: Set channel SIP/38678-0000000f to write format slin
[Dec  1 15:55:14] DEBUG[22941]: channel.c:2377 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Dec  1 15:55:14] DEBUG[22941]: channel.c:2490 ast_read_generator_actions: Generator got voice, switching to phase locked mode
[Dec  1 15:55:14] DEBUG[22941]: channel.c:2377 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Dec  1 15:55:14] DEBUG[11430]: chan_sip.c:3709 __sip_ack: Stopping retransmission on 'ZjFmYjA3Mzg1MDc1NDIxMTdhYTJiNmY0NjcxYmUzNWQ.' of Response 2: Match Found
[Dec  1 15:55:14] DEBUG[22926]: chan_sip.c:3174 __sip_xmit: Trying to put 'ACK sip:dia' onto TCP socket destined for 10.9.1.13:5067
   -- SIP/10.9.1.13:5067-00000011 answered SIP/38678-0000000f
[Dec  1 15:55:14] DEBUG[22941]: channel.c:3655 set_format: Set channel SIP/38678-0000000f to write format ulaw
[Dec  1 15:55:14] DEBUG[22941]: channel.c:2377 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
ast_rtp_new_source: ssrc is 49978530, new ssrc is 49978530, constantssrc is 1
ast_rtp_new_source: ssrc is 1553236498, new ssrc is 1156920430, constantssrc is 0
[Dec  1 15:55:14] DEBUG[22941]: rtp.c:3806 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Dec  1 15:55:14] DEBUG[22941]: rtp.c:3822 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
asterisk*CLI>
asterisk*CLI>
asterisk*CLI>
asterisk*CLI>
asterisk*CLI>
asterisk*CLI>
[Dec  1 15:55:16] DEBUG[22941]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 28 bytes
[Dec  1 15:55:16] DEBUG[22941]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 104 bytes
[Dec  1 15:55:17] DEBUG[22941]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec  1 15:55:17] DEBUG[22941]: rtp.c:886 send_dtmf: Sending dtmf: 56 (8), at 10.9.5.63
[Dec  1 15:55:17] DEBUG[22941]: channel.c:4854 ast_generic_bridge: Got DTMF begin on channel (SIP/38678-0000000f)
ast_rtp_new_source: ssrc is 49978530, new ssrc is 49978530, constantssrc is 1
ast_rtp_new_source: ssrc is 1156920430, new ssrc is 276804749, constantssrc is 0
[Dec  1 15:55:17] DEBUG[22941]: channel.c:5227 ast_channel_bridge: Bridge stops bridging channels SIP/38678-0000000f and SIP/10.9.1.13:5067-00000011
ast_rtp_new_source: ssrc is 49978530, new ssrc is 49978530, constantssrc is 1
ast_rtp_new_source: ssrc is 276804749, new ssrc is 53644514, constantssrc is 0
[Dec  1 15:55:17] DEBUG[22941]: rtp.c:886 send_dtmf: Sending dtmf: 56 (8), at 10.9.5.63
[Dec  1 15:55:17] DEBUG[22941]: channel.c:4854 ast_generic_bridge: Got DTMF end on channel (SIP/38678-0000000f)
ast_rtp_new_source: ssrc is 49978530, new ssrc is 49978530, constantssrc is 1
ast_rtp_new_source: ssrc is 53644514, new ssrc is 1602003665, constantssrc is 0
[Dec  1 15:55:17] DEBUG[22941]: channel.c:5227 ast_channel_bridge: Bridge stops bridging channels SIP/38678-0000000f and SIP/10.9.1.13:5067-00000011
sip_senddigit_begin: caller id: 3300
ast_rtp_set_constantssrc: setting flag
ast_rtp_new_source: ssrc is 49978530, new ssrc is 49978530, constantssrc is 1
ast_rtp_new_source: ssrc is 1602003665, new ssrc is 1602003665, constantssrc is 1
[Dec  1 15:55:17] DEBUG[22941]: rtp.c:886 send_dtmf: Sending dtmf: 54 (6), at 10.9.5.63
[Dec  1 15:55:17] DEBUG[22941]: channel.c:4854 ast_generic_bridge: Got DTMF begin on channel (SIP/38678-0000000f)
ast_rtp_new_source: ssrc is 49978530, new ssrc is 49978530, constantssrc is 1
ast_rtp_new_source: ssrc is 1602003665, new ssrc is 1602003665, constantssrc is 1
[Dec  1 15:55:17] DEBUG[22941]: channel.c:5227 ast_channel_bridge: Bridge stops bridging channels SIP/38678-0000000f and SIP/10.9.1.13:5067-00000011
ast_rtp_new_source: ssrc is 49978530, new ssrc is 49978530, constantssrc is 1
ast_rtp_new_source: ssrc is 1602003665, new ssrc is 1602003665, constantssrc is 1
[Dec  1 15:55:17] DEBUG[22941]: rtp.c:886 send_dtmf: Sending dtmf: 54 (6), at 10.9.5.63
[Dec  1 15:55:17] DEBUG[22941]: channel.c:4854 ast_generic_bridge: Got DTMF end on channel (SIP/38678-0000000f)
ast_rtp_new_source: ssrc is 49978530, new ssrc is 49978530, constantssrc is 1
ast_rtp_new_source: ssrc is 1602003665, new ssrc is 1602003665, constantssrc is 1
[Dec  1 15:55:17] DEBUG[22941]: channel.c:5227 ast_channel_bridge: Bridge stops bridging channels SIP/38678-0000000f and SIP/10.9.1.13:5067-00000011
sip_senddigit_begin: caller id: 3300
ast_rtp_set_constantssrc: setting flag
ast_rtp_new_source: ssrc is 49978530, new ssrc is 49978530, constantssrc is 1
ast_rtp_new_source: ssrc is 1602003665, new ssrc is 1602003665, constantssrc is 1
[Dec  1 15:55:18] DEBUG[22941]: rtp.c:886 send_dtmf: Sending dtmf: 55 (7), at 10.9.5.63
[Dec  1 15:55:18] DEBUG[22941]: channel.c:4854 ast_generic_bridge: Got DTMF begin on channel (SIP/38678-0000000f)
ast_rtp_new_source: ssrc is 49978530, new ssrc is 49978530, constantssrc is 1
ast_rtp_new_source: ssrc is 1602003665, new ssrc is 1602003665, constantssrc is 1
[Dec  1 15:55:18] DEBUG[22941]: channel.c:5227 ast_channel_bridge: Bridge stops bridging channels SIP/38678-0000000f and SIP/10.9.1.13:5067-00000011
ast_rtp_new_source: ssrc is 49978530, new ssrc is 49978530, constantssrc is 1
ast_rtp_new_source: ssrc is 1602003665, new ssrc is 1602003665, constantssrc is 1
[Dec  1 15:55:18] DEBUG[22941]: rtp.c:886 send_dtmf: Sending dtmf: 55 (7), at 10.9.5.63
[Dec  1 15:55:18] DEBUG[22941]: channel.c:4854 ast_generic_bridge: Got DTMF end on channel (SIP/38678-0000000f)
ast_rtp_new_source: ssrc is 49978530, new ssrc is 49978530, constantssrc is 1
ast_rtp_new_source: ssrc is 1602003665, new ssrc is 1602003665, constantssrc is 1
[Dec  1 15:55:18] DEBUG[22941]: channel.c:5227 ast_channel_bridge: Bridge stops bridging channels SIP/38678-0000000f and SIP/10.9.1.13:5067-00000011
sip_senddigit_begin: caller id: 3300
ast_rtp_set_constantssrc: setting flag
ast_rtp_new_source: ssrc is 49978530, new ssrc is 49978530, constantssrc is 1
ast_rtp_new_source: ssrc is 1602003665, new ssrc is 1602003665, constantssrc is 1
[Dec  1 15:55:18] DEBUG[22941]: rtp.c:886 send_dtmf: Sending dtmf: 56 (8), at 10.9.5.63
[Dec  1 15:55:18] DEBUG[22941]: channel.c:4854 ast_generic_bridge: Got DTMF begin on channel (SIP/38678-0000000f)
ast_rtp_new_source: ssrc is 49978530, new ssrc is 49978530, constantssrc is 1
ast_rtp_new_source: ssrc is 1602003665, new ssrc is 1602003665, constantssrc is 1
[Dec  1 15:55:18] DEBUG[22941]: channel.c:5227 ast_channel_bridge: Bridge stops bridging channels SIP/38678-0000000f and SIP/10.9.1.13:5067-00000011
ast_rtp_new_source: ssrc is 49978530, new ssrc is 49978530, constantssrc is 1
ast_rtp_new_source: ssrc is 1602003665, new ssrc is 1602003665, constantssrc is 1
[Dec  1 15:55:18] DEBUG[22941]: rtp.c:886 send_dtmf: Sending dtmf: 56 (8), at 10.9.5.63
[Dec  1 15:55:18] DEBUG[22941]: channel.c:4854 ast_generic_bridge: Got DTMF end on channel (SIP/38678-0000000f)
ast_rtp_new_source: ssrc is 49978530, new ssrc is 49978530, constantssrc is 1
ast_rtp_new_source: ssrc is 1602003665, new ssrc is 1602003665, constantssrc is 1
[Dec  1 15:55:18] DEBUG[22941]: channel.c:5227 ast_channel_bridge: Bridge stops bridging channels SIP/38678-0000000f and SIP/10.9.1.13:5067-00000011
sip_senddigit_begin: caller id: 3300
ast_rtp_set_constantssrc: setting flag
ast_rtp_new_source: ssrc is 49978530, new ssrc is 49978530, constantssrc is 1
ast_rtp_new_source: ssrc is 1602003665, new ssrc is 1602003665, constantssrc is 1
[Dec  1 15:55:19] DEBUG[22941]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 28 bytes
[Dec  1 15:55:19] DEBUG[22941]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 128 bytes
[Dec  1 15:55:19] DEBUG[22941]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 28 bytes
[Dec  1 15:55:19] DEBUG[22941]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 104 bytes
[Dec  1 15:55:20] DEBUG[22941]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 28 bytes
[Dec  1 15:55:20] DEBUG[22941]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 104 bytes
[Dec  1 15:55:20] DEBUG[22941]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec  1 15:55:20] DEBUG[22941]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 28 bytes
[Dec  1 15:55:20] DEBUG[22941]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 104 bytes
[Dec  1 15:55:20] DEBUG[22941]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 160 bytes
[Dec  1 15:55:20] DEBUG[11430]: chan_sip.c:3174 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.9.5.63:64274
[Dec  1 15:55:20] DEBUG[22941]: channel.c:4803 ast_generic_bridge: Didn't get a frame from channel: SIP/38678-0000000f
ast_rtp_new_source: ssrc is 1602003665, new ssrc is 1602003665, constantssrc is 1
[Dec  1 15:55:20] DEBUG[22941]: channel.c:5227 ast_channel_bridge: Bridge stops bridging channels SIP/38678-0000000f and SIP/10.9.1.13:5067-00000011
[Dec  1 15:55:20] DEBUG[22941]: channel.c:1711 ast_hangup: Hanging up channel 'SIP/10.9.1.13:5067-00000011'
[Dec  1 15:55:20] DEBUG[22941]: chan_sip.c:5583 sip_hangup: Hangup call SIP/10.9.1.13:5067-00000011, SIP callid 60567a2b593d6fb83e2e3d2b769db223@10.9.1.121
[Dec  1 15:55:20] DEBUG[22941]: chan_sip.c:3174 __sip_xmit: Trying to put 'BYE sip:dia' onto TCP socket destined for 10.9.1.13:5067
[Dec  1 15:55:20] DEBUG[22941]: rtp.c:2113 ast_rtp_early_bridge: Channel '<unspecified>' has no RTP, not doing anything
[Dec  1 15:55:20] DEBUG[22941]: app_dial.c:2113 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Dec  1 15:55:20] DEBUG[22941]: pbx.c:3806 __ast_pbx_run: Spawn extension (default,3300,2) exited non-zero on 'SIP/38678-0000000f'
 == Spawn extension (default, 3300, 2) exited non-zero on 'SIP/38678-0000000f'
[Dec  1 15:55:20] DEBUG[22941]: channel.c:1606 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/38678-0000000f'
[Dec  1 15:55:20] DEBUG[22941]: channel.c:1711 ast_hangup: Hanging up channel 'SIP/38678-0000000f'
[Dec  1 15:55:20] DEBUG[22941]: chan_sip.c:5583 sip_hangup: Hangup call SIP/38678-0000000f, SIP callid ZjFmYjA3Mzg1MDc1NDIxMTdhYTJiNmY0NjcxYmUzNWQ.
asterisk*CLI>
By: Leif Madsen (lmadsen) 2009-12-02 13:52:36.000-0600

Dropping this back to Confirmed as we have supplied patches, but the reporter states these do not resolve the root of the problem.
By: rsw686 (rsw686) 2009-12-03 20:57:34.000-0600

I've added two more patches (asterisk-1.6.1.11-constantssrc-debug.patch and asterisk-1.6.1.11-constantssrc.patch). The debug has verbose logging so you can see what is going on and the other is my final patch for the constant ssrc dtmf issue. The final patch applies against 1.6.2 as well.

Here is the console output with the debug patch. Notice that the constantssrc flag is being properly set after forwarding the SIP channel with the lines I added to sip_pvt. Also note the redundant setting of the flag in handle_request_invite, which I removed in the final patch. Both sip_pvt and create_addr_from_peer follow the same structure and set the dtmf and rtp timeouts for the audio and video streams along with the constantssrc flag. The handle_request_invite constantssrc flag setting seemed out of place and unnecessary.

 == Using SIP RTP CoS mark 5
sip_pvt: setting constantsrc flag for audio
handle_request_invite: setting constantsrc flag for audio
   -- Executing [3300@default:1] Answer("SIP/38678-00000000", "") in new stack
ast_rtp_new_source: constantssrc is 1, ssrc is 476670726
   -- Executing [3300@default:2] Dial("SIP/38678-00000000", "SIP/SIP_VM/3300,,TTr") in new stack
 == Using SIP RTP CoS mark 5
sip_pvt: setting constantsrc flag for audio
create_addr_from_peer: setting constantsrc flag for audio
   -- Called SIP_VM/3300
   -- Got SIP response 302 "Moved Temporarily" back from 10.9.1.13
   -- Now forwarding SIP/38678-00000000 to 'SIP/3300::::TCP@10.9.1.13:5067' (thanks to SIP/SIP_VM-00000001)
 == Using SIP RTP CoS mark 5
sip_pvt: setting constantsrc flag for audio
   -- SIP/10.9.1.13:5067-00000002 is ringing
   -- SIP/10.9.1.13:5067-00000002 answered SIP/38678-00000000
ast_rtp_new_source: constantssrc is 1, ssrc is 476670726
ast_rtp_new_source: constantssrc is 1, ssrc is 989379290
ast_rtp_new_source: constantssrc is 1, ssrc is 476670726
ast_rtp_new_source: constantssrc is 1, ssrc is 989379290


By: rsw686 (rsw686) 2009-12-08 13:15:43.000-0600

Can this be marked ready for testing? I've been using it in production without issue for a few days now.
By: Leif Madsen (lmadsen) 2009-12-08 14:18:49.000-0600

Ask and ye shall receive!
By: mejor (mejor) 2009-12-16 00:50:31.000-0600

This has not fixed my issue in 1.6.1.10. Can anyone confirm this is working and the steps they took to get it going?
By: rsw686 (rsw686) 2009-12-16 08:34:25.000-0600

What is your issue? Are you using Exchange UM 2007 with Asterisk? If so download Asterisk and the patch into the same folder. The steps to patch and compile are

tar zxf asterisk-1.6.1.11.tar.gz
cd asterisk-1.6.1.11/
patch -p1 < ../asterisk-1.6.1.11-constantssrc.patch
./configure
make
make install

Make sure to add constantssrc = yes to the [general] section of your sip.conf. If it still is not working try asterisk-1.6.1.11-constantssrc-debug.patch, which will show what is happening on the console. Your output should look like similar to my note a few above.


By: rsw686 (rsw686) 2009-12-16 08:58:40.000-0600

mejor forgot to ask if everything worked in Asterisk 1.6.1.7-rc1? If not then you have a configuration problem as that version works.
By: mejor (mejor) 2009-12-16 16:21:00.000-0600

I am using the PIAF build. I guess i have to update asterisk to 1.6.1.11 for the patch to work right?
By: rsw686 (rsw686) 2009-12-17 08:16:58.000-0600

The patch works for 1.6.1.7-rc2 and up. What do you have Asterisk connected to? You haven't provided any information on what is happening or your setup.
By: mejor (mejor) 2009-12-17 20:12:57.000-0600

Sorry about that. Here is what I have: asterisk 1.6.1.10, FreePBX 2.6, Polycom 450's, aastra analog phones tied into a TDM card, and a PRI card.

The issue I am having is when I try to call my voicemail box from an IP450 it does not hear me entering the password. I have also tested from xlite and one of the analog phones everything works fine that way. Any ideas?
By: mejor (mejor) 2010-01-05 10:37:55.000-0600

upgrading to 1.6.1.12 fixed the DTMF issues but broke faxing.. :(
By: Leif Madsen (lmadsen) 2010-01-05 10:48:17.000-0600

Closing this issue as the reporter states DTMF is fixed in a later version. For the faxing issue, please look to see if a later version (i.e. from SVN directly from the branch) has fixed your issue. If not, please search for an existing fax issue that matches your problem, or if not found, open a new issue for tracking fax.
By: rsw686 (rsw686) 2010-01-26 08:13:55.000-0600

mejor is reporting about a different issue. The issues I reported about has not been fixed. I still have to patch every version to use Asterisk with Exchange UM. Right now I am running 1.6.2.1.

Can this be reopened and patch asterisk-1.6.1.11-constantssrc.patch reviewed for inclusion in the Asterisk code? If one of the contributors uses the debug patch and looks at the output they will notice that constantssrc had been forgotten to be set when a SIP call is forwarded.


By: Leif Madsen (lmadsen) 2010-01-28 09:29:45.000-0600

Oops! My apologies -- I looked through this issue too quickly. Thank you for reopening.

As this is a regression, I'm marking this as a blocker for the next release. Thanks!
By: Terry Wilson (twilson) 2010-03-12 18:58:38.000-0600

Ok, the constantssrc stuff was just a broken idea in general. It has been fixed so that the default behavior is to never change the ssrc unless we see the other side has changed it.  If you update to the latest 1.4, 1.6.0, 1.6.1, 1.6.2 or trunk from svn, this will probably be fixed. rsw686 can you confirm?
By: rsw686 (rsw686) 2010-03-13 10:23:36.000-0600

I can confirm this has been resolved in the svn version SVN-trunk-r252133.
By: rsw686 (rsw686) 2010-03-16 12:47:27

This can be closed as I see 1.6.1.19 will include revision 252135 which fixes the constantssrc DTMF issue.
By: Leif Madsen (lmadsen) 2010-03-16 14:16:35

Leaving this issue open for a few as the change that went in may need to be tweaked as it may have broke ABI compatibility in other areas of the code.
By: Leif Madsen (lmadsen) 2010-03-18 15:09:59

OK, this is fixed now. Thanks!