[Home]

Summary:ASTERISK-17919: [patch] OOH323 Unexpectedly Drops Incoming Forwarded Calls in 15 Seconds
Reporter:Vladimir Mikhelson (vmikhelson)Labels:
Date Opened:2011-05-25 02:00:53Date Closed:2011-06-01 05:45:16
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Addons/chan_ooh323
Versions:1.8.4 Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) H323_LOG_2-INTERRUPTED-CALLS
( 1) h323_log_dropped-fwd.zip
( 2) H323_LOG_DROPPED-FWD-PATCH1
( 3) h323_log_fax_interruption
( 4) H323_LOG_RUNAWAY-CALL
( 5) h323_log-runaway-log.zip
( 6) issue19361-1.patch
( 7) issue19361-2.patch
( 8) issue19361-3.patch
Description:The scenario:

Unconditional forward is set on an Avaya IPO 403's extension to forward to Asterisk via OOH323 trunk.

Incoming call is dropped by Asterisk in about 15 seconds in a way that Avaya does not know about that and continues the call which Asterisk interprets as a new call.

This scenario goes on indefinitely.

Asterisk 1.8.4.1
FreePBX 2.9.0.4


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

Attached h323_log_dropped-fwd features an incoming call to Avaya's extension which was forwarded to Asterisk's DID 400. The call was placed at 01:13:36. It produced 20 incoming 15 second calls from the Asterisk's perspective. There was virtually no voice channel and IVR navigation was interrupted all the time. DTMFs seemed to be passed properly. Some unwanted noises were heard and on one occasion the tones were interpreted as a CED tones which activated an incoming FAX processing by Asterisk.

A number of "ERROR: Unbalanced structure" messages were observed in the log.
Comments:By: Alexander Anikin (may213) 2011-05-25 15:38:49

Vladimir, looks like to this is not chan_ooh323 mainly.
Suggest there is trouble with timing module on asterisk (because you
have silence with IVR, neither progress or alerting packet after call proceeding
on first calls).
Could you test how work timing on your asterisk installation with timing test
command on asterisk cli?

Second thing is empty tcs packet received on some calls here. Looks like to avaya try to connect direct way two endpoint of call (i mean avaya try connect
both legs with rtp pass directly between them). But it's possible that
avaya try to setup fax transfer by this way. Chan_ooh323 can't process properly
in the current trunk version. This processing is implemented in experimental direct_rtp branch which is in testing state now  and will merged into trunk near
future. So pls check avaya settings about direct rtp connection for asterisk
and disable it if it's possible there (i saw these parms in some avaya configs
name as DirectRTP or Direct Connect).

And small issue with ooh323 found here. In first call OOH323 received endSessionCommand -> disconnect but did further processing instead of disconnect
call. I'll produce patch for testing this thing.


By: Alexander Anikin (may213) 2011-05-25 15:43:56

'Unbalanced structure' message is small issue about debug messages with concurrent calls. I think we have time to solve it and you can create an issue if you want to do it
By: Alexander Anikin (may213) 2011-05-25 16:19:03

Vladimir, pls test attached patch. It change call to clearing state when
endsession->disconnect command received.
By: Vladimir Mikhelson (vmikhelson) 2011-05-25 18:22:12

Alexander,

On additional piece of information.

Forwarding works fine if I call from an Avaya extension to another Avaya extension which has the unconditional forward set.

If the incoming call is external to Avaya then we have the problem described.

Now I will try your patch.

Thank you,
Vladimir


By: Vladimir Mikhelson (vmikhelson) 2011-05-25 18:35:52

Alexander,

Here are replies to your information requests.


1. I ran the "timing test" 3 times:

pbx*CLI> timing test
Attempting to test a timer with 50 ticks per second.
Using the 'DAHDI' timing module for this test.
It has been 1000 milliseconds, and we got 50 timer ticks
pbx*CLI> timing test
Attempting to test a timer with 50 ticks per second.
Using the 'DAHDI' timing module for this test.
It has been 1019 milliseconds, and we got 51 timer ticks
pbx*CLI> timing test
Attempting to test a timer with 50 ticks per second.
Using the 'DAHDI' timing module for this test.
It has been 1019 milliseconds, and we got 51 timer ticks
pbx*CLI>

2. I re-verified Avaya trunk settings:

Allow Direct Media Path -- disabled
H450 support -- none

3. The reason I mentioned the "ERROR: Unbalanced structure" error message was that it only appeared at the time the problematic calls were in progress.

Thank you,
Vladimir


By: Vladimir Mikhelson (vmikhelson) 2011-05-25 19:27:47

Alexander,

I have applied the patch.

Unfortunately no change to the better.  The log is attached.

First call -- just a test call from ext.352 to Asterisk.  No problems.

Second call -- from ext.351 to ext.352 forwarded to 400 on Asterisk worked fine as before.

Third call -- from a cell phone to Avaya IVR, switched to 352, forwarded to 400 on Asterisk.  Exhibited the same exact behavior, i.e. multiple disconnects and reconnects.

The new problem became introduced.  If Avaya's extension directly calls an Asterisk extension and subsequently drops the call Asterisk is not notified and keeps the call connected, forwards to voice mail by timer, accepts an empty message, and finally the call gets disconnected by Asterisk.

Thank you,
Vladimir


By: Alexander Anikin (may213) 2011-05-26 13:57:31

Vladimir,

about new trouble. If i understand right it's last call on the attached log.
Don't see any big time difference between disconnect received from avaya side and clearing call on asterisk.

will explain below with log:

19:09:57:361  Tunneled H.245 Message = {
19:09:57:361  Decoding 1 tunneled H245 message. (incoming, ooh323c_8)
19:09:57:361     response = {
19:09:57:361        masterSlaveDeterminationAck = {
19:09:57:362           decision = {
19:09:57:362              master = {
19:09:57:363                 NULL
19:09:57:364              }
19:09:57:364           }
19:09:57:365        }
19:09:57:365     }
19:09:57:365  }
19:09:57:365  Handling H245 message. (incoming, ooh323c_8)
19:09:57:365  Listing logical channel 257 cap 4 state 3 for (incoming, ooh323c_8)
19:09:57:365  Listing logical channel 1001 cap 4 state 3 for (incoming, ooh323c_8)
19:09:57:365  Finished handling H245 message. (incoming, ooh323c_8)
19:09:57:366  Finished handling tunneled messages in empty Facility message. (incoming, ooh323c_8)

this is last packet in capability exchange and all exchange proc are finished, call is answered and goes normally.
Time is 19:09:57:366

next packet here:

19:09:59:221  H.225 Facility message Received (incoming, ooh323c_8)
19:09:59:221  Received Facility Message.(incoming, ooh323c_8)
19:09:59:221  Handling tunneled messages in empty Facility message. (incoming, ooh323c_8)
19:09:59:221  Checking for tunneled H.245 messages (incoming, ooh323c_8)
19:09:59:221  Total number of tunneled H245 messages are 1.(incoming, ooh323c_8)
19:09:59:221  Retrieving 1 of 1 tunneled H.245 messages.(incoming, ooh323c_8)
19:09:59:221  Tunneled H.245 Message = {
19:09:59:222  Decoding 1 tunneled H245 message. (incoming, ooh323c_8)
19:09:59:222     request = {
19:09:59:222        closeLogicalChannel = {
19:09:59:222           forwardLogicalChannelNumber = {
19:09:59:223              257
19:09:59:223           }
19:09:59:224           source = {

It's first packet of disconnection process from avaya. It close logical channel
first.
Time is 19:09:59.224.

After this asterisk close his transmitting channel, receive disconnect command
from avaya and send release complete. Below last log lines:

19:09:59:339  H.225 Release Complete message received (incoming, ooh323c_8)
19:09:59:339  Cause of Release Complete is 10. (incoming, ooh323c_8)
19:09:59:339  Sending H225 message (incoming, ooh323c_8)
19:09:59:339  Warning:Call marked for cleanup. Can not send message.(incoming, ooh323c_8)
19:09:59:340  In ooEndCall call state is - OO_CALL_CLEARED (incoming, ooh323c_8)
19:09:59:340  Cleaning Call (incoming, ooh323c_8)- reason:OO_REASON_REMOTE_CLEARED
19:09:59:340  Removing call 90c7bb8: ooh323c_8
19:09:59:340  Removed call (incoming, ooh323c_8) from list
19:09:59:353  Ending Call Monitor thread

Time is 19:09:59:353. Call is fully cleared on asterisk side now.

Difference between first disconnect packet and call clearing is about 100ms  but
call was answered two seconds before and if voicemail app was started
immediately on call begin it could write 2 second message.
So i think there is no problem with chan_ooh323.


By: Alexander Anikin (may213) 2011-05-26 15:33:57

Vladimir,

could you check calls from cell to 352->400 but replace ivr on 400 to
simple call to some asterisk extension?
and second way - check calls with IVR but replace key sequence that you
entered to IVR from *3... to some other (without * for example).

and one question - incoming trunk for avaya when you call from cell is TDM or
VOIP trunk?
By: Vladimir Mikhelson (vmikhelson) 2011-05-26 18:06:44

Alexander,

First about the new problem.  My fault, the log did not contain the call I was referring too.

Please find the new H323_LOG_RUNAWAY-CALL log attached.

The call was placed from Avaya ext. 352 to Asterisk ext. 462.  Avaya dropped the call in a couple seconds as there was no reply. Asterisk continued ringing the extension until the Voice Mail intercepted the call by the no-answer timer.

-Vladimir
By: Vladimir Mikhelson (vmikhelson) 2011-05-26 18:31:19

Alexander,

H323_LOG_2-INTERRUPTED-CALLS log contains the log of two incoming calls from my cell to Avaya ext. 352 which were unconditionally forwarded to the Asterisk ext. 462. Both calls were dropped for no apparent reason. I was talking all the time just to make sure that it was not a silence related event.

The difference with the "before the patch" behavior:
-- Disconnection was silent compared to some noises before disconnection the caller compared to a fax noises.

The experience was consistent as they called me three times. Asterisk CDR shows 38, 43, and 40 seconds long conversations.

The two test calls have lasted 38 and 37 seconds respectively.

-Vladimir


By: Vladimir Mikhelson (vmikhelson) 2011-05-26 18:35:48

Alexander,

I tried entering "1", "2", "3" in Asterisk IVR.  Result was the same to the second.  Please let me know if you need these logs.

Avaya receives the incoming call on a POTS line.

Thank you,
Vladimir
By: Vladimir Mikhelson (vmikhelson) 2011-05-27 02:31:30

Alexander,

One more potential side effect of the patch.

Fax is being sent from Avaya extension 347 to Asterisk DID 499 which routes to an ATA with an analog Fax machine connected. Fax transmission starts normally, then interrupts unexpectedly at 41 seconds exactly. Tested 3 times with perfect consistency. Log h323_log_fax_interruption is attached.

I am not sure whether the current patch is the root cause as last time I sent a fax using this trunk was March 05, 2011.

Thank you,
Vladimir
By: Alexander Anikin (may213) 2011-05-28 05:22:23

Vladimir,

latest pointed calls have same trouble as in issue ASTERISK-17172 (double alerting that don't understand you avaya, it's very pedantic with h.323 proto).
Unfortunately patch for previous issue was correct for trunk and incorrect for 1.8 branch.


By: Alexander Anikin (may213) 2011-05-28 05:47:42

Now about first problematic calls. I suggest that avaya can't understand calls which are answered immediately without any signalling before answer. This isn't generic way for calls and alerting must go before answer.
By: Alexander Anikin (may213) 2011-05-28 05:53:24

second patch uploaded. it's for clean 1.8 branch without first patch here.
It correct double alerting issue,
add forced alerting before answer if was not found before,
begin clearing call process after endsession packet received (it's from first patch)
send all of packets in output queue not only first from queue.
By: Vladimir Mikhelson (vmikhelson) 2011-05-28 22:10:05

Alexander,

It sounds like my earlier suspicions about the patch not being properly applied to the 1.8 branch were unfortunately right.  Can we fix it now so that 1.8.5 will at least have the right version?

Back to the patch.

1. I rolled back addons to the 1.8.4.1 unpatched.
2. Applied the patch with the following output:

patching file addons/ooh323c/src/ooh245.c
patching file addons/ooh323c/src/oochannels.c
patching file addons/chan_ooh323.c
Hunk #1 succeeded at 1078 (offset -1 lines).
Hunk #3 succeeded at 1261 (offset -2 lines).

3. Compiled and installed.

Results:
1. **Good** Call from a land line to Avaya's extension forwarded to Asterisk's extension worked fine.  I will test it more when I am back to the office.
2. **Bad**  Call from Avaya's extension to Asterisk's extension continues ringing indefinitely now after being hung up on Avaya's end. I ended up dropping it in FOP.
3. I will test the fax when I am back to the office.

Wow!! Something really bad has happened. I have almost lost control of my box.  I was unable to execute basic commands.

This is what I found out.  OOH323 was writing something to the log at the pace that brought the box to its knees.  I managed to save the log at the time it grew to almost 2GB.

Let me clean out the log so I would be able to post it.

Thank you,
Vladimir


By: Vladimir Mikhelson (vmikhelson) 2011-05-29 01:23:49

OK. Finally I managed to compact the log. Please find it attached: h323_log-runaway-log.

The log contains records of three (3) calls. Extract from CDR below provides the calls' details.

3.   2011-05-28 21:23:43 OOH323/ava... 352 "Vlad Mikhelson" <352> 462 ANSWERED 03:54
4.   2011-05-28 21:22:26 OOH323/ava... 352 "Vlad Mikhelson" <352> 462 ANSWERED 01:40
5.   2011-05-28 21:16:33 OOH323/ava... 918477155555 "Mikhelson V >VMikhelson" <918477155555> 423 ANSWERED 02:07

The huge size of the log created made it pretty complex to manage it.  That is the reason the third call initiation is not included.

Please let me know if you need more information.

Thank you,
Vladimir
By: Alexander Anikin (may213) 2011-05-29 05:38:08

Vladimir,

third patch uploaded, pls check it as previous (revert branch to clean 1.8 and apply patch). It must solve bug intoduced by previous patch in flushing sending packet queue (infinite loop in call clearing state). Sorry for that bug which
cause abnormal growing log  ;)

Double alerting bug will fixed in 1.8 and will included in 1.8.5.
By: Vladimir Mikhelson (vmikhelson) 2011-05-29 13:24:42

Alexander,

I am using 1.8.4.1 tag vs. 1.8 branch.  Just wanted to make sure it is OK.

I have applied and tested the new patch.  So far everything worked as expected.  I still need to test faxing which can only be done from the office.

Great job!! Thank you.

-Vladimir
By: Vladimir Mikhelson (vmikhelson) 2011-05-30 20:58:44

Alexander,

All tested well from the office, faxing, Avaya call hangup, forward.

"ERROR: Unbalanced structure" messages were not observed in the log any more.

As far as I am concerned the patch is ready for production.

Thank you,
Vladimir
By: Alexander Anikin (may213) 2011-06-01 05:17:50

Vladimir,

Good result, thank you for intensive testing.
will close this issue.
By: Digium Subversion (svnbot) 2011-06-01 05:40:23

Repository: asterisk
Revision: 321528

U   branches/1.8/addons/chan_ooh323.c
U   branches/1.8/addons/ooh323c/src/oochannels.c
U   branches/1.8/addons/ooh323c/src/ooh245.c

------------------------------------------------------------------------
r321528 | may | 2011-06-01 05:40:22 -0500 (Wed, 01 Jun 2011) | 14 lines

Fix double alerting, add forced alerting before answer

Fix double alerting (it wasn't fixed here by issue ASTERISK-17172)
Add forced alerting before connect (if it wasn't before)
Try to send all packets from outgoing queue rather than one only
Call goes into clearing state when disconnect command is received

(closes issue ASTERISK-17919)
Reported by: vmikhelson
Patches:
     issue19361-3.patch uploaded by may213 (license 454)
Tested by: vmikhelson


------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=321528
By: Digium Subversion (svnbot) 2011-06-01 05:45:15

Repository: asterisk
Revision: 321529

_U  trunk/
U   trunk/addons/chan_ooh323.c
U   trunk/addons/ooh323c/src/oochannels.c
U   trunk/addons/ooh323c/src/ooh245.c

------------------------------------------------------------------------
r321529 | may | 2011-06-01 05:45:15 -0500 (Wed, 01 Jun 2011) | 20 lines

Merged revisions 321528 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.8

........
 r321528 | may | 2011-06-01 14:40:19 +0400 (Wed, 01 Jun 2011) | 14 lines
 
 Fix double alerting, add forced alerting before answer
 
 Fix double alerting (it wasn't fixed here by issue ASTERISK-17172)
 Add forced alerting before connect (if it wasn't before)
 Try to send all packets from outgoing queue rather than one only
 Call goes into clearing state when disconnect command is received
 
 (closes issue ASTERISK-17919)
 Reported by: vmikhelson
 Patches:
       issue19361-3.patch uploaded by may213 (license 454)
 Tested by: vmikhelson
........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=321529