[Asterisk-Users] Re: Zap channel calling back after hangup (dueto polarity CID detection)

Tue Mar 1 06:06:44 MST 2005

> > > That issue is fixed in the CVS HEAD version of asterisk.
> > > There are a couple of workarounds possible with 1.0.6. Check the 
> > > bugtracker for the bug where it was implemented for more 
> > > information. (sorry, don't remember the bug-number and don't have 
> > > time to look it up right now).
> > I'm running CVS-HEAD-02/28/05-23:18:39 at the moment, and 
> it still happens.
> > I've seen the bugs in Mantis, but the answeronpolarity 
> doesn't seem to 
> > make any difference ...
> 
> Could you post a debug-log of when it happens?
> (enable debug and verbose in logger.conf)

This is the log:

Mar  1 13:57:06 VERBOSE[15245]:     -- Accepting AUTHENTICATED call from
213.136.48.247:
       > requested format = alaw,
       > requested prefs = (),
       > actual format = alaw,
       > host prefs = (alaw|ulaw|gsm),
       > priority = mine
Mar  1 13:57:06 VERBOSE[15253]:     -- Executing
[1;36;40mDial[0;37;40m("[1;35;40mIAX2/afe at afe-2[0;37;40m",
"[1;35;40mZap/g2/0850007225|120|W[0;37;40m") in new stack
Mar  1 13:57:06 DEBUG[15253]: Dialing '0850007225'
Mar  1 13:57:06 DEBUG[15253]: Deferring dialing...
Mar  1 13:57:06 VERBOSE[15253]:     -- Called g2/0850007225
Mar  1 13:57:06 DEBUG[15245]: Ooh, voice format changed to 8
Mar  1 13:57:06 DEBUG[15253]: Exception on 19, channel 4
Mar  1 13:57:06 DEBUG[15253]: Got event Hook Transition Complete(12) on
channel 4 (index 0)
Mar  1 13:57:08 DEBUG[15253]: Exception on 19, channel 4
Mar  1 13:57:08 DEBUG[15253]: Got event Dial Complete(9) on channel 4 (index
0)
Mar  1 13:57:08 DEBUG[15253]: Enabled echo cancellation on channel 4
Mar  1 13:57:08 DEBUG[15253]: Engaged echo training on channel 4
Mar  1 13:57:10 DEBUG[15253]: Exception on 19, channel 4
Mar  1 13:57:10 DEBUG[15253]: Got event Dial Complete(9) on channel 4 (index
0)
Mar  1 13:57:10 DEBUG[15253]: Echo cancellation already on
Mar  1 13:57:10 DEBUG[15253]: Dropping duplicate answer!
Mar  1 13:57:10 VERBOSE[15253]:     -- Zap/4-1 answered IAX2/afe at afe-2
Mar  1 13:57:10 DEBUG[15253]: Exception on 19, channel 4
Mar  1 13:57:10 DEBUG[15253]: Got event Polarity Reversal(17) on channel 4
(index 0)
Mar  1 13:57:10 DEBUG[15253]: Ignore switch to REVERSED Polarity on channel
4, state 6
Mar  1 13:57:14 DEBUG[15245]: Raw Hangup 69.73.19.178:4569, src=3, dst=143
Mar  1 13:57:15 VERBOSE[15239]:     -- Remote UNIX connection
Mar  1 13:57:20 DEBUG[15245]: Immediately destroying 2, having received
hangup
Mar  1 13:57:20 DEBUG[15253]: Didn't get a frame from channel:
IAX2/afe at afe-2
Mar  1 13:57:20 DEBUG[15253]: Bridge stops bridging channels IAX2/afe at afe-2
and Zap/4-1
Mar  1 13:57:20 DEBUG[15253]: Hangup: channel: 4 index = 0, normal = 19,
callwait = -1, thirdcall = -1
Mar  1 13:57:20 DEBUG[15253]: disabled echo cancellation on channel 4
Mar  1 13:57:20 DEBUG[15253]: Set option TDD MODE, value: OFF(0) on Zap/4-1
Mar  1 13:57:20 DEBUG[15253]: Updated conferencing on 4, with 0 conference
users
Mar  1 13:57:20 VERBOSE[15253]:     -- Hungup 'Zap/4-1'
Mar  1 13:57:20 DEBUG[15253]: Exiting with DIALSTATUS=ANSWER.
Mar  1 13:57:20 VERBOSE[15253]:   == Spawn extension (norby, 90850007225, 1)
exited non-zero on 'IAX2/afe at afe-2'
Mar  1 13:57:20 VERBOSE[15253]:     -- Executing
[1;36;40mHangup[0;37;40m("[1;35;40mIAX2/afe at afe-2[0;37;40m",
"[1;35;40m[0;37;40m") in new stack
Mar  1 13:57:20 VERBOSE[15253]:   == Spawn extension (norby, h, 1) exited
non-zero on 'IAX2/afe at afe-2'
Mar  1 13:57:20 DEBUG[15253]: We're hanging up IAX2/afe at afe-2 now...
Mar  1 13:57:20 DEBUG[15253]: Really destroying IAX2/afe at afe-2 now...
Mar  1 13:57:20 VERBOSE[15253]:     -- Hungup 'IAX2/afe at afe-2'
Mar  1 13:57:22 VERBOSE[15246]:   == Starting post polarity CID detection on
channel 4
Mar  1 13:57:22 VERBOSE[15256]:     -- Starting simple switch on 'Zap/4-1'
Mar  1 13:57:22 DEBUG[15256]: Receiving DTMF cid on channel Zap/4-1
Mar  1 13:57:23 DEBUG[15256]: Exception on 19, channel 4
Mar  1 13:57:23 DEBUG[15256]: Got event Ring/Answered(2) on channel 4 (index
0)
Mar  1 13:57:23 DEBUG[15256]: Setting IDLE polarity due to ring. Old
polarity was 1
Mar  1 13:57:23 DEBUG[15256]: CID got string ''
Mar  1 13:57:23 DEBUG[15256]: No cid detected
Mar  1 13:57:23 DEBUG[15256]: CID is '', flags 8
Mar  1 13:57:23 VERBOSE[15256]:     -- Executing
[1;36;40mSetCallerID[0;37;40m("[1;35;40mZap/4-1[0;37;40m",
"[1;35;40m0[0;37;40m") in new stack
Mar  1 13:57:23 VERBOSE[15256]:     -- Executing
[1;36;40mDial[0;37;40m("[1;35;40mZap/4-1[0;37;40m",
"[1;35;40mSIP/400&Zap/1|45|tw[0;37;40m") in new stack
Mar  1 13:57:23 DEBUG[15256]: Setting NAT on RTP to 0
Mar  1 13:57:23 DEBUG[15256]: Outgoing Call for 400
Mar  1 13:57:23 VERBOSE[15256]:     -- Called 400
Mar  1 13:57:23 VERBOSE[15256]:     -- Called 1
Mar  1 13:57:23 VERBOSE[15256]:     -- Zap/1-1 is ringing
Mar  1 13:57:23 DEBUG[15256]: Requested indication 3 on channel Zap/4-1
Mar  1 13:57:23 DEBUG[15244]: (Provisional) Stopping retransmission (but
retaining packet) on '0422e4a8749e9e3529130f0b35f43d16 at 85.224.22.230'
Request 102: Found
Mar  1 13:57:23 DEBUG[15244]: (Provisional) Stopping retransmission (but
retaining packet) on '0422e4a8749e9e3529130f0b35f43d16 at 85.224.22.230'
Request 102: Found
Mar  1 13:57:23 VERBOSE[15256]:     -- SIP/400-c26c is ringing
Mar  1 13:57:24 DEBUG[15245]: Raw Hangup 69.73.19.178:4569, src=3, dst=143
Mar  1 13:57:24 DEBUG[15256]: Exception on 18, channel 1
Mar  1 13:57:24 DEBUG[15256]: Got event Ringer Off(11) on channel 1 (index
0)
Mar  1 13:57:24 VERBOSE[15256]:     -- Zap/1-1 is ringing
Mar  1 13:57:29 DEBUG[15256]: Exception on 18, channel 1
Mar  1 13:57:29 DEBUG[15256]: Got event Ringer On(10) on channel 1 (index 0)
Mar  1 13:57:30 DEBUG[15256]: Exception on 18, channel 1
Mar  1 13:57:30 DEBUG[15256]: Got event Ringer Off(11) on channel 1 (index
0)
Mar  1 13:57:30 VERBOSE[15256]:     -- Zap/1-1 is ringing
Mar  1 13:57:31 DEBUG[15256]: Hangup: channel: 1 index = 0, normal = 18,
callwait = -1, thirdcall = -1
Mar  1 13:57:31 DEBUG[15256]: disabled echo cancellation on channel 1
Mar  1 13:57:31 DEBUG[15256]: Set option TDD MODE, value: OFF(0) on Zap/1-1
Mar  1 13:57:31 DEBUG[15256]: Updated conferencing on 1, with 0 conference
users
Mar  1 13:57:31 VERBOSE[15256]:     -- Hungup 'Zap/1-1'
Mar  1 13:57:31 DEBUG[15256]: update_user_counter(400) - decrement outUse
counter
Mar  1 13:57:31 DEBUG[15256]: Exiting with DIALSTATUS=CANCEL.
Mar  1 13:57:31 VERBOSE[15256]:   == Spawn extension (analog_in, s, 2)
exited non-zero on 'Zap/4-1'
Mar  1 13:57:31 VERBOSE[15256]:     -- Executing
[1;36;40mHangup[0;37;40m("[1;35;40mZap/4-1[0;37;40m",
"[1;35;40m[0;37;40m") in new stack
Mar  1 13:57:31 VERBOSE[15256]:   == Spawn extension (analog_in, h, 1)
exited non-zero on 'Zap/4-1'
Mar  1 13:57:31 DEBUG[15256]: Hangup: channel: 4 index = 0, normal = 19,
callwait = -1, thirdcall = -1
Mar  1 13:57:31 DEBUG[15256]: disabled echo cancellation on channel 4
Mar  1 13:57:31 DEBUG[15256]: Set option TDD MODE, value: OFF(0) on Zap/4-1
Mar  1 13:57:31 DEBUG[15256]: Updated conferencing on 4, with 0 conference
users
Mar  1 13:57:31 VERBOSE[15256]:     -- Hungup 'Zap/4-1' 