[asterisk-bugs] [Asterisk 0019361]: [patch] OOH323 Unexpectedly Drops Incoming Forwarded Calls in 15 Seconds

[Asterisk Bug Tracker]

A NOTE has been added to this issue. 
====================================================================== 
https://issues.asterisk.org/view.php?id=19361 
====================================================================== 
Reported By:                vmikhelson
Assigned To:                may213
====================================================================== 
Project:                    Asterisk
Issue ID:                   19361
Category:                   Addons/chan_ooh323
Reproducibility:            always
Severity:                   major
Priority:                   normal
Status:                     feedback
Asterisk Version:           1.8.4.1 
JIRA:                        
Regression:                 No 
Reviewboard Link:            
SVN Branch (only for SVN checkouts, not tarball releases): N/A 
SVN Revision (number only!):  
Request Review:              
====================================================================== 
Date Submitted:             2011-05-25 02:00 CDT
Last Modified:              2011-05-26 13:57 CDT
====================================================================== 
Summary:                    [patch] OOH323 Unexpectedly Drops Incoming Forwarded
Calls in 15 Seconds
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

====================================================================== 

---------------------------------------------------------------------- 
 (0135447) may213 (manager) - 2011-05-26 13:57
 https://issues.asterisk.org/view.php?id=19361#c135447 
---------------------------------------------------------------------- 
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 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 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. 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2011-05-26 13:57 may213         Note Added: 0135447                          
======================================================================