[Home]

Summary:ASTERISK-06096: Race condition when do threeway
Reporter:Martin Vit (festr)Labels:
Date Opened:2006-01-16 08:26:19.000-0600Date Closed:2011-06-07 14:02:54
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Scenario:

incoming IAX call route to FXS Zap/5. After answer, send flash and call another FXS. After first ring tone Zap/5 will hangup and person on IAX will hear nothing

look at strange warning WARNING[4195]: chan_zap.c:791 zt_get_index: Unable to get index, and nullok is not asserted

CPU is P4, CPU load is 0. Asterisk is version Asterisk 1.2.1 (official tar balls).

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

here is log:

   -- Executing Dial("Zap/5-2", "Zap/6r1|30|Tt") in new stack
   -- Called 6r1
   -- Zap/6-1 is ringing
Jan 16 14:12:22 DEBUG[4195]: chan_zap.c:4791 zt_indicate: Requested indication 3 on channel Zap/5-2
Jan 16 14:12:22 DEBUG[4195]: chan_zap.c:4325 __zt_exception: Exception on 21, channel 6
Jan 16 14:12:22 DEBUG[4195]: chan_zap.c:3517 zt_handle_event: Got event Ringer Off(11) on channel 6 (index 0)
   -- Zap/6-1 is ringing
Jan 16 14:12:22 DEBUG[4195]: chan_zap.c:4325 __zt_exception: Exception on 21, channel 6
Jan 16 14:12:22 DEBUG[4195]: chan_zap.c:3517 zt_handle_event: Got event Ringer On(10) on channel 6 (index 0)
Jan 16 14:12:24 DEBUG[4195]: chan_zap.c:4325 __zt_exception: Exception on 21, channel 6
Jan 16 14:12:24 DEBUG[4195]: chan_zap.c:3517 zt_handle_event: Got event Ringer Off(11) on channel 6 (index 0)
   -- Zap/6-1 is ringing
Jan 16 14:12:25 DEBUG[4195]: chan_zap.c:4325 __zt_exception: Exception on 20, channel 5
Jan 16 14:12:25 DEBUG[4195]: chan_zap.c:3517 zt_handle_event: Got event On hook(1) on channel 5 (index 0)
Jan 16 14:12:25 DEBUG[4195]: chan_zap.c:3698 zt_handle_event: Last flash was 7889 ms ago
   -- Stopped music on hold on IAX2/test-3
Jan 16 14:12:25 DEBUG[4195]: channel.c:1710 ast_settimeout: Scheduling timer at 0 sample intervals
Jan 16 14:12:25 DEBUG[4195]: channel.c:2741 ast_channel_masquerade: Planning to masquerade channel IAX2/test-3 into the structure of Zap/5-2
Jan 16 14:12:25 DEBUG[4195]: channel.c:2754 ast_channel_masquerade: Done planning to masquerade channel IAX2/test-3 into the structure of Zap/5-2
Jan 16 14:12:25 DEBUG[4195]: chan_zap.c:866 swap_subs: Swapping 2 and 0
Jan 16 14:12:25 DEBUG[4195]: chan_zap.c:995 unalloc_sub: Released sub 2 of channel 5
Jan 16 14:12:25 DEBUG[4195]: channel.c:2875 ast_do_masquerade: Got clone lock for masquerade on 'IAX2/test-3' at 0x40d03324
Jan 16 14:12:25 DEBUG[4195]: chan_zap.c:3256 zt_fixup: New owner for channel 5 is IAX2/test-3<MASQ>
Jan 16 14:12:25 WARNING[4195]: chan_zap.c:791 zt_get_index: Unable to get index, and nullok is not asserted
Jan 16 14:12:25 DEBUG[4195]: chan_zap.c:4791 zt_indicate: Requested indication 3 on channel IAX2/test-3<MASQ>
Jan 16 14:12:25 DEBUG[4195]: chan_zap.c:1371 update_conf: Updated conferencing on 5, with 0 conference users
Jan 16 14:12:25 DEBUG[4195]: chan_zap.c:2337 zt_hangup: Hangup: channel: 5 index = -1, normal = 20, callwait = -1, thirdcall = -1
   -- Hungup 'IAX2/test-3<MASQ>'
Jan 16 14:12:25 DEBUG[4195]: channel.c:3036 ast_do_masquerade: Putting channel IAX2/test-3 in 64/64 formats
Jan 16 14:12:25 DEBUG[4195]: channel.c:3071 ast_do_masquerade: Released clone lock on 'Zap/5-2<ZOMBIE>'
Jan 16 14:12:25 DEBUG[4195]: channel.c:3080 ast_do_masquerade: Done Masquerading IAX2/test-3 (6)
Jan 16 14:12:25 DEBUG[4154]: channel.c:3253 ast_generic_bridge: Didn't get a frame from channel: Zap/5-2<ZOMBIE>
Jan 16 14:12:25 DEBUG[4154]: channel.c:3525 ast_channel_bridge: Bridge stops bridging channels Zap/5-2<ZOMBIE> and Zap/5-1
Jan 16 14:12:25 DEBUG[4154]: chan_zap.c:2337 zt_hangup: Hangup: channel: 5 index = 0, normal = 20, callwait = -1, thirdcall = -1
Jan 16 14:12:25 DEBUG[4154]: chan_zap.c:1434 zt_disable_ec: disabled echo cancellation on channel 5
Jan 16 14:12:25 DEBUG[4154]: chan_zap.c:2766 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/5-1
Jan 16 14:12:25 DEBUG[4154]: chan_zap.c:1371 update_conf: Updated conferencing on 5, with 0 conference users
   -- Hungup 'Zap/5-1'
Jan 16 14:12:25 DEBUG[4154]: app_dial.c:1586 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
 == Spawn extension (inRoute-3, 271009511, 3) exited non-zero on 'Zap/5-2<ZOMBIE>'
Jan 16 14:12:28 DEBUG[4195]: chan_zap.c:4325 __zt_exception: Exception on 21, channel 6
Jan 16 14:12:28 DEBUG[4195]: chan_zap.c:3517 zt_handle_event: Got event Ringer On(10) on channel 6 (index 0)
Jan 16 14:12:28 DEBUG[4195]: chan_zap.c:4325 __zt_exception: Exception on 21, channel 6
Jan 16 14:12:28 DEBUG[4195]: chan_zap.c:3517 zt_handle_event: Got event Ringer Off(11) on channel 6 (index 0)
   -- Zap/6-1 is ringing
Jan 16 14:12:29 DEBUG[4195]: chan_zap.c:4325 __zt_exception: Exception on 21, channel 6
Jan 16 14:12:29 DEBUG[4195]: chan_zap.c:3517 zt_handle_event: Got event Ringer On(10) on channel 6 (index 0)
Jan 16 14:12:31 DEBUG[4195]: chan_zap.c:4325 __zt_exception: Exception on 21, channel 6
Jan 16 14:12:31 DEBUG[4195]: chan_zap.c:3517 zt_handle_event: Got event Ringer Off(11) on channel 6 (index 0)
   -- Zap/6-1 is ringing
Jan 16 14:12:35 DEBUG[4195]: chan_zap.c:4325 __zt_exception: Exception on 21, channel 6

Comments:By: Martin Vit (festr) 2006-01-16 08:56:42.000-0600

There could be more general problem.
I have tested now, that transfer with '#' cause the same problem. IAX side hear music (immidiatly after # is pressed) but when dialed another fxs, IAX side hear nothing. So maybe this is not bug? and maybe it is not releated to zaptel?

There is another log:

   -- Executing Dial("IAX2/test-1", "Zap/5|30|Tt") in new stack
   -- Called 5
   -- Zap/5-1 is ringing
Jan 16 14:50:10 DEBUG[4566]: chan_iax2.c:6653 socket_read: Ooh, voice format changed to 1024
Jan 16 14:50:12 DEBUG[4572]: chan_zap.c:4325 __zt_exception: Exception on 23, channel 5
Jan 16 14:50:12 DEBUG[4572]: chan_zap.c:3517 zt_handle_event: Got event Ringer Off(11) on channel 5 (index 0)
   -- Zap/5-1 is ringing
Jan 16 14:50:14 DEBUG[4572]: chan_zap.c:4325 __zt_exception: Exception on 23, channel 5
Jan 16 14:50:14 DEBUG[4572]: chan_zap.c:3517 zt_handle_event: Got event Ring/Answered(2) on channel 5 (index 0)
Jan 16 14:50:14 DEBUG[4572]: chan_zap.c:1402 zt_enable_ec: Enabled echo cancellation on channel 5
Jan 16 14:50:14 DEBUG[4572]: chan_zap.c:1418 zt_train_ec: Engaged echo training on channel 5
Jan 16 14:50:14 DEBUG[4572]: chan_zap.c:3802 zt_handle_event: channel 5 answered
   -- Zap/5-1 answered IAX2/test-1
Jan 16 14:50:28 DEBUG[4572]: chan_zap.c:4602 zt_read: DTMF digit: # on Zap/5-1
Jan 16 14:50:28 DEBUG[4572]: channel.c:3281 ast_generic_bridge: Got DTMF on channel (Zap/5-1)
Jan 16 14:50:28 DEBUG[4572]: channel.c:3525 ast_channel_bridge: Bridge stops bridging channels IAX2/test-1 and Zap/5-1
Jan 16 14:50:28 DEBUG[4572]: res_features.c:990 ast_feature_interpret: Feature interpret: chan=IAX2/test-1, peer=Zap/5-1, sense=2, features=2
   -- Started music on hold, class 'default', on channel 'IAX2/test-1'
Jan 16 14:50:28 DEBUG[4572]: channel.c:1710 ast_settimeout: Scheduling timer at 160 sample intervals
Jan 16 14:50:28 DEBUG[4572]: channel.c:1710 ast_settimeout: Scheduling timer at 160 sample intervals
   -- Playing 'pbx-transfer' (language 'en')
Jan 16 14:50:28 DEBUG[4578]: channel.c:1972 ast_read: Generator got voice, switching to phase locked mode
Jan 16 14:50:28 DEBUG[4578]: channel.c:1710 ast_settimeout: Scheduling timer at 0 sample intervals
Jan 16 14:50:29 DEBUG[4572]: chan_zap.c:4602 zt_read: DTMF digit: 7 on Zap/5-1
Jan 16 14:50:29 DEBUG[4572]: channel.c:1710 ast_settimeout: Scheduling timer at 0 sample intervals
Jan 16 14:50:29 DEBUG[4572]: channel.c:1710 ast_settimeout: Scheduling timer at 160 sample intervals
Jan 16 14:50:29 DEBUG[4572]: channel.c:1972 ast_read: Generator got voice, switching to phase locked mode
Jan 16 14:50:29 DEBUG[4572]: channel.c:1710 ast_settimeout: Scheduling timer at 0 sample intervals
Jan 16 14:50:30 DEBUG[4572]: chan_zap.c:4602 zt_read: DTMF digit: 0 on Zap/5-1
Jan 16 14:50:30 DEBUG[4572]: channel.c:1710 ast_settimeout: Scheduling timer at 0 sample intervals
Jan 16 14:50:31 DEBUG[4572]: chan_zap.c:4602 zt_read: DTMF digit: 1 on Zap/5-1
   -- Stopped music on hold on IAX2/test-1
Jan 16 14:50:34 DEBUG[4572]: channel.c:1710 ast_settimeout: Scheduling timer at 0 sample intervals
Jan 16 14:50:34 DEBUG[4572]: chan_zap.c:2337 zt_hangup: Hangup: channel: 5 index = 0, normal = 23, callwait = -1, thirdcall = -1
Jan 16 14:50:34 DEBUG[4572]: chan_zap.c:1434 zt_disable_ec: disabled echo cancellation on channel 5
Jan 16 14:50:34 DEBUG[4572]: chan_zap.c:2766 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/5-1
Jan 16 14:50:34 DEBUG[4572]: chan_zap.c:1371 update_conf: Updated conferencing on 5, with 0 conference users
   -- Hungup 'Zap/5-1'
Jan 16 14:50:34 DEBUG[4572]: app_dial.c:1586 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
   -- Executing SetVar("IAX2/test-1", "RCADENCE=r1") in new stack
   -- Executing Goto("IAX2/test-1", "in_6_1|701|1") in new stack
   -- Goto (in_6_1,701,1)
   -- Executing Goto("IAX2/test-1", "2") in new stack
   -- Goto (in_6_1,701,2)
   -- Executing SetCDRUserField("IAX2/test-1", ""Technici01"<701>") in new stack
   -- Executing Dial("IAX2/test-1", "Zap/6r1|30|Tt") in new stack
   -- Called 6r1
   -- Zap/6-1 is ringing
Jan 16 14:50:35 DEBUG[4572]: chan_zap.c:4325 __zt_exception: Exception on 24, channel 6
Jan 16 14:50:35 DEBUG[4572]: chan_zap.c:3517 zt_handle_event: Got event Ringer Off(11) on channel 6 (index 0)
   -- Zap/6-1 is ringing
Jan 16 14:50:35 DEBUG[4572]: chan_zap.c:4325 __zt_exception: Exception on 24, channel 6
Jan 16 14:50:35 DEBUG[4572]: chan_zap.c:3517 zt_handle_event: Got event Ringer On(10) on channel 6 (index 0)
Jan 16 14:50:37 DEBUG[4572]: chan_zap.c:4325 __zt_exception: Exception on 24, channel 6
Jan 16 14:50:37 DEBUG[4572]: chan_zap.c:3517 zt_handle_event: Got event Ringer Off(11) on channel 6 (index 0)
Jan 16 14:50:38 DEBUG[4568]: chan_zap.c:1434 zt_disable_ec: disabled echo cancellation on channel 5
Jan 16 14:50:41 DEBUG[4572]: chan_zap.c:4325 __zt_exception: Exception on 24, channel 6
Jan 16 14:50:41 DEBUG[4572]: chan_zap.c:3517 zt_handle_event: Got event Ringer On(10) on channel 6 (index 0)
Jan 16 14:50:41 DEBUG[4572]: chan_zap.c:4325 __zt_exception: Exception on 24, channel 6
Jan 16 14:50:41 DEBUG[4572]: chan_zap.c:3517 zt_handle_event: Got event Ringer Off(11) on channel 6 (index 0)
   -- Zap/6-1 is ringing
Jan 16 14:50:41 DEBUG[4572]: chan_zap.c:4325 __zt_exception: Exception on 24, channel 6
Jan 16 14:50:41 DEBUG[4572]: chan_zap.c:3517 zt_handle_event: Got event Ringer On(10) on channel 6 (index 0)
Jan 16 14:50:43 DEBUG[4572]: chan_zap.c:4325 __zt_exception: Exception on 24, channel 6
Jan 16 14:50:43 DEBUG[4572]: chan_zap.c:3517 zt_handle_event: Got event Ringer Off(11) on channel 6 (index 0)
   -- Zap/6-1 is ringin
By: Martin Vit (festr) 2006-01-16 11:03:28.000-0600

i've solved this. Problem was, that after upgrade from 1.0 to 1.2.1 there were some older /etc/asterisk/configs. I've deleted all and start convert all configuration to 1.2.

pls close this bug and sorry to bother you!
By: twisted (twisted) 2006-01-16 17:29:54.000-0600

Closed per submitter