Summary: | ASTERISK-24400: ooh323 sends wrong hangup code | ||
Reporter: | Dmitry Melekhov (slesru) | Labels: | |
Date Opened: | 2014-10-07 23:30:37 | Date Closed: | 2016-11-08 04:58:30.000-0600 |
Priority: | Minor | Regression? | |
Status: | Closed/Complete | Components: | Addons/chan_ooh323 |
Versions: | 11.10.2 | Frequency of Occurrence | |
Related Issues: | |||
Environment: | centos x86-64 | Attachments: | ( 0) 24400-final.patch ( 1) 24400-test.patch ( 2) 24400-test-2.patch ( 3) 24400-test-3.patch ( 4) 24400-test-4.patch ( 5) cisco_log ( 6) cisco_log_tcp ( 7) cisco_log_tcp_progress ( 8) cisco-debug.dmp ( 9) cisco-nodebug.dmp (10) debug.dump (11) debug-noprogress.dump (12) h323_log (13) h323_log (14) h323_log (15) h323_log (16) h323_log (17) h323_log (18) nodebug.dump (19) nodebug-noprogress.dump (20) ooh323.conf |
Description: | Hello!
We installed yet another asterisk which works as voip gateway between panasonic kx-ta 100 and our h323 network. Connection between asterisk and panasonic is ISDN PRI, namely qsig. For some reason we have problems with generating ring back tone from panasonic , so I added Progress, so it looks like: {noformat} exten => 5880,1,SET(FAXOPT(t38gateway)=yes) exten => 5880,n,Progress exten => 5880,n,Dial(DAHDI/g1/${EXTEN}) exten => 5880,n,Hangup {noformat} but, in this case we get wrong hangup tone, like not user busy, but network congestion. If there is no Progress, then no ringback, but tone is right. Really, whole connection scheme is: {noformat} kt-ta100---asterisk--cisco3845--ts004-avaya {noformat} I'm avaya user :-) So, what I see is on asterisk: {noformat} -- Called DAHDI/g1/5880 -- Span 1: Channel 0/2 got hangup, cause 17 {noformat} on cisco: {noformat} Oct 8 03:27:58.138: //1355041/EE3142978C7C/CCAPI/ccCallDisconnect: Cause Value=38, Call Entry(Responsed=TRUE, Cause Value=38) {noformat} I placed call through another asterisk, which is connected to ts004, over ISDN, call is over ISDN (back to ts004, etc..) , and see there: {noformat} -- Span 1: Channel 0/3 got hangup request, cause 38 -- DAHDI/i1/5880-21aa is circuit-busy {noformat} I don't completely sure how to collect all data, because if I turn on debug or trace then I got different behaviour, namely I don't hear ringback tone even if Progress is in place. So I need help from developer to collect debug info. I guess that problem is in ooh323 because if I use sip to call asterisk from cisco3845 , then I get user busy tone. Thank you! | ||
Comments: | By: Matt Jordan (mjordan) 2014-10-08 07:48:16.646-0500 Assigning to Alexander Anikin to Triage. You should provide your full configuration file and a debug log illustrating the problem, as that will help Alexander diagnose your problem. By: Dmitry Melekhov (slesru) 2014-10-08 07:52:16.324-0500 As I wrote I can't get debug for some reason unknown for me- ooh323 debug changes asterisk behavior. I'll attach config. By: Dmitry Melekhov (slesru) 2014-10-08 07:53:20.861-0500 config By: Dmitry Melekhov (slesru) 2014-10-08 22:54:14.825-0500 by the way, I just found that I have debug log, as I said it changes tones, so I don't sure it is right. By: Dmitry Melekhov (slesru) 2014-10-08 22:55:26.627-0500 this is log for busy user By: Alexander Anikin (may213) 2014-10-09 15:10:08.438-0500 Hi Dmitry, I think i known where is trouble. There is TCS packet from asterisk to cisco but no reply with TCSAck from cisco. I guess cisco don't want TCS at the moment and define this packet sequence as failed. So cisco translate to origin side 38 cause not 17 that send asterisk. I will produce patch to test this assupmtion. By: Dmitry Melekhov (slesru) 2014-10-09 22:42:01.192-0500 thank you! By: Alexander Anikin (may213) 2014-10-10 02:23:37.644-0500 Dmitry, please try with attached patch By: Dmitry Melekhov (slesru) 2014-10-10 02:53:44.474-0500 unfortunately, patch doesn't change cisco behaviour :-( I still get hangup cause 38 on it: Oct 10 07:47:05.911: //1368145/766CEBFC9862/CCAPI/cc_decr_if_call_volume: Remote IP Address=192.168.122.3, Hwidb=GigabitEthernet0/0 Oct 10 07:47:05.911: //1368145/766CEBFC9862/CCAPI/cc_decr_if_call_volume: Total Call Count=265, Voip Call Count=265, MMoip Call Count=0 Oct 10 07:47:05.911: //1368145/766CEBFC9862/CCAPI/cc_api_call_disconnect_done: Disposition=0, Interface=0xC0566C04, Tag=0x0, Call Id=1368145, Call Entry(Disconnect Cause=38, Voice Class Cause Code=0, Retry Count=0) I'll get yet another debug trace with this patch in next hour - right now I can't do this because of users activity- and upload it. Thank you! By: Dmitry Melekhov (slesru) 2014-10-10 03:23:02.303-0500 This log contains to call to number 5880- first makes user busy, second one is for hangup code test. It's from patched asterisk. Thank you! By: Alexander Anikin (may213) 2014-10-10 05:09:48.815-0500 Dmitry, are you tried test such calls without forced Progress in dialplan? It could be that cisco don't like busy code after progress/ringing due to it can't take place in ideal phone network. If endpoint is busy it can't signal alerting or progress ;) If it's normal without progress then we can introduce option to supress progress signal before ringing or answer By: Dmitry Melekhov (slesru) 2014-10-10 05:24:56.502-0500 Yes, I tried without Progress, and hangup code is right, but problem is that for some reason there is no ringback tone - I guess that panasonic doesn't generate it, although ( I got screenshot from panasonic admin) option is on. This is why I added progress... And yes, looks like this is cisco problem- just tried (don't know why didn't test it before) asterisk-asterisk call and everything is OK. So, I have wrong hangup tone or no ringback and have no idea how to have both :-( By: Dmitry Melekhov (slesru) 2014-10-10 05:32:53.854-0500 Sorry , tested once again- in I remove progress I get code 38 too, so progress change nothing in this case, I'm just wrong. By: Alexander Anikin (may213) 2014-10-10 05:40:18.724-0500 Dmitry, please attach h323_log for calls with 38 but without progress. I known about no ringtone on q.sig links with Panasonic, had same problem at previous work and also add forced progress in dialplan. You're right about cisco, asterisk send to cisco cause code 17 but cisco translate 38 to originating leg of call. Need to understand why cisco think that call is failed even without progress. By: Dmitry Melekhov (slesru) 2014-10-10 05:55:35.207-0500 Here it is, with trace 6, but! but! I got normal hangup tone! I was so amused, that I called 3 times and always got right code. As I wrote before- turning on debug changes how asterisk works. May be some timings? I guess debug slows asterisk down. May be cisco just needs some delay between h323 signalling messages? And after I restarted asterisk without trace- I got 38 again... Thank you! By: Alexander Anikin (may213) 2014-10-10 07:31:31.994-0500 It's possible you're right about some delays. I'll try to make patch for this. By: Dmitry Melekhov (slesru) 2014-10-10 07:45:18.927-0500 thank you! btw, processor is Intel(R) Core(TM)2 Duo CPU E7500 @ 2.93GHz on this server. I don't sure how trace will slow ooh323 on it, hope you can guess... By: Alexander Anikin (may213) 2014-10-12 15:54:43.976-0500 Hello, Dmitry, please try with new attached patch. It change sending method of packets from output queue on h323 connection. It send one packet at one time instead of sending all packet from the queue. By: Dmitry Melekhov (slesru) 2014-10-12 23:40:01.800-0500 Hello! Unfortunately, after patch I got compilation error :-( [root@ast-gag75 asterisk-11.10.2-patched]# patch -p0 < 24400-test-2.patch patching file addons/ooh323c/src/ooq931.c patching file addons/ooh323c/src/oochannels.c [root@ast-gag75 asterisk-11.10.2-patched]# make [CC] ooh323c/src/oochannels.c -> ooh323c/src/oochannels.o ooh323c/src/oochannels.c: В функции ‘ooProcessCallFDSETsAndTimers’: ooh323c/src/oochannels.c:684: ошибка: оператор break вне цикла или оператора switch ooh323c/src/oochannels.c:707: ошибка: оператор break вне цикла или оператора switch ooh323c/src/oochannels.c:716: ошибка: оператор break вне цикла или оператора switch make[1]: *** [ooh323c/src/oochannels.o] Ошибка 1 make: *** [addons] Ошибка 2 may be I need newer asterisk version ? Thank you! By: Alexander Anikin (may213) 2014-10-13 04:09:26.273-0500 Dmitry, looks like to you have newer version of compiler ;) I replaced test-2 patch, please try again with it By: Dmitry Melekhov (slesru) 2014-10-13 04:32:42.964-0500 Hello! Unfortunately there is no change is asterisk behavior after this patch. I attached logs with this patch and tracelevel=6. There was 3 or 4 calls to number 5880 - first to make it busy , second (and may be third, I don't remember, sorry - my boss called me right in the middle :-( ) was without Progress in dialplan , I got 38 tone. Then I changed dial plan and removed Progress and called once again, and I got 17 tone. But, as I wrote before, I can get 17 tone only if tracelevel=6... I tried to reproduce this- and this is right- tracelevel=6, no progress, 17 tone tracelevel=6, progress , 38 tone no debug- always 38... This is strange and I have no idea why :-( Thank you! By: Alexander Anikin (may213) 2014-10-13 09:35:15.386-0500 Dmitry, please try with test-3 patch. There is another thing that cisco don't like h245tunnelling flag present in the release complete packet and test-3 patch remove tunnelling flag on release complete. It certainly does not explain why there is dependence from trace state, but we can try this. To check that dependence please attach tcpdump capture for signalling between cisco and asterisk for calls with trace (where you got 17 tone) and without trace where you got 38 tone. By: Dmitry Melekhov (slesru) 2014-10-13 22:49:59.762-0500 Hello! Thank you. I can't say this patch helps, but I got right busy tone , without debug, once, right after I restarted asterisk, unfortunately I didn't capture traffic :-( And always 38 tone in next tries. I captured traffic between asterisk and cisco, 4 variants- with debug and without progress - got 17 tone, with debug and with progress - 38, no debug and progress-38, no debug and no progress - 38. I'll upload dumps and I'll upload debug log.. By: Dmitry Melekhov (slesru) 2014-10-13 23:13:50.698-0500 uploaded all files. Thank you! By: Dmitry Melekhov (slesru) 2014-10-14 00:45:19.412-0500 btw, this is definitely some cisco incompatibility or bug. just (don't know why I didn't this before) did call from addpac 1100 with fxs interfaces: 20 <NetEP 200> : DoCall: calledAddr(5880@) callingAddr(5000) 21 <GK 200> : Send ARQ. 22 <GK 200> : Received ACF. 23 <H323 200> : local capabilities. number of capabilities = 6 1 : g729-8k 2 : g711alaw-64k 3 : g711ulaw-64k 4 : T.38 5 : UserInput/basicString 6 : UserInput/hookflash 24 <H225 200> : Try signalling TCP connect (192.168.122.3:1720) 25 <H225 200> : Signalling TCP connect success (200) 26 <Q931 200> : Send SETUP 27 <Q931 200> : Received CALL PROCEEDING 28 <H225 200> : Remote Endpoint (ooh323,v0.8.3m,184,0,39) 29 <Q931 200> : Received RELEASE COMPLETE 30 <GK 200> : Send DRQ. 31 <Call 200> : Terminated from(ffffffff) this(Remote:UserBusy) before(NULL) forced(0) 32 <CEP 000000> : DisconnectCall at Busy 33 <CEP 000000> : StopSignal 34 <CEP 000000> : Disconnect (1) 35 <NetEP 200> : Call TO <ast-gag75> terminated reason(Remote:UserBusy) 36 <GK 200> : Received DCF. 37 <CEP 000000> : Disconnected(17) at Disconnecting It gets user busy I generates right tone... By: Dmitry Melekhov (slesru) 2014-10-14 06:32:17.455-0500 I also got signalling log from cisco , may be it can help. To be really honest I don't know much about how h323 works, so I see nothing interesting in it, but... By: Dmitry Melekhov (slesru) 2014-10-14 06:45:38.073-0500 OK, looks like I found it. Alexander, please look into cisco_log_tcp. I see following in it: Oct 14 11:41:56.976: //1383076/EF9A67FDA5B3/H323/cch323_h225_set_new_state: Changing from H225_REQ_FS_SETUP state to H225_REQ_FS_CALLPROC state Oct 14 11:41:57.040: TCP0: FIN processed Oct 14 11:41:57.040: TCP0: state was ESTAB -> CLOSEWAIT [44892 -> 192.168.122.3(1720)] Oct 14 11:41:57.040: TCP0: RST received, Closing connection Oct 14 11:41:57.040: TCP0: state was CLOSEWAIT -> CLOSED [44892 -> 192.168.122.3(1720)] Oct 14 11:41:57.040: Released port 44892 in Transport Port Agent for TCP IP type 1 delay 240000 Oct 14 11:41:57.040: TCB 0xC09E8730 destroyed Oct 14 11:41:57.040: //1383076/EF9A67FDA5B3/H323/run_h225_sm: Received event H225_EV_CONN_LOST while at state H225_REQ_FS_CALLPROC Oct 14 11:41:57.040: //1383076/EF9A67FDA5B3/H323/run_h225_sm: Received event H225_EV_RELEASE while at state H225_REQ_FS_CALLPROC For some reason asterisk closes tcp session, this results in 38 (network problem) hangup code.... Question is why... Thank you! By: Alexander Anikin (may213) 2014-10-14 11:25:25.567-0500 Dmitry, I found difference between trace activated and not. There is some delay really (i guess to make debug output) and this delay allow send responding release complete from cisco before asterisk close tcp connection. And one question, is channel between cisco and asterisk reliable? there is retransmission of call proceeding packet in debug-noprogress capture, you can see it by wireshark. Also i guess that cisco will generate correct tone with progress even if we fix closing tcp connection, i will try make patch. By: Alexander Anikin (may213) 2014-10-14 12:03:42.225-0500 Dmitry, please try attached patch, it contain previous patches and not close tcp connection on incoming call by release complete sending. By: Dmitry Melekhov (slesru) 2014-10-14 22:42:25.147-0500 Hello! With this patch I get right busy ( i.e. code 17 ) tone , with debug and with no debug, with progress and no progress- always right result. About channel reliability- this is leased channel, not very long- in the same town, 100 Mbit , theoretically, just because we share the same switches network of the same provider, and it is encrypted by linux ipsec on both sides, but our monitoring doesn't show us any loss , there are no complains from users, so we consider it as reliable enough. Btw, I just reproduced the same problem with busy tone on another asterisk, which is connected to avaya definity, just nobody complained :-) It is connected by different channel, only same part is the same cisco gateway... Thank you very much! By: Dmitry Melekhov (slesru) 2014-10-14 23:11:14.462-0500 And about another asterisk, I mentioned, which is connected to avaya. For some reason it doesn't generate ringback tone too, so I have Progress there, really exactly the same dial plan. And this is asterisk 11.9.0. After I applied patch I get busy (17) tone only if there is no Progress in dial plan, otherwise I get network error (38) tone. I get the same log on cisco: Oct 15 04:09:14.099: //1384489/DBA89FE4A6F5/H323/cch323_h225_set_new_state: Changing from H225_REQ_FS_SETUP state to H225_REQ_FS_CALLPROC state Oct 15 04:09:14.135: TCP0: FIN processed Oct 15 04:09:14.135: TCP0: state was ESTAB -> CLOSEWAIT [63017 -> 192.168.105.6(1720)] Oct 15 04:09:14.139: TCP0: RST received, Closing connection Oct 15 04:09:14.139: TCP0: state was CLOSEWAIT -> CLOSED [63017 -> 192.168.105.6(1720)] Oct 15 04:09:14.139: Released port 63017 in Transport Port Agent for TCP IP type 1 delay 240000 Oct 15 04:09:14.139: TCB 0xC0553290 destroyed Oct 15 04:09:14.139: //1384489/DBA89FE4A6F5/H323/run_h225_sm: Received event H225_EV_CONN_LOST while at state H225_REQ_FS_CALLPROC I'll upload full log... By: Dmitry Melekhov (slesru) 2014-10-14 23:11:40.390-0500 cisco_log_tcp_progress contains this call By: Alexander Anikin (may213) 2014-10-15 03:32:55.091-0500 Hi Dmitry, looks like to there are some tcp bugs also. I'm not sure where is source of problem, but cisco don't see release complete packet before closing tcp connection. Could you please attach here h323_log and tcp capture? By: Dmitry Melekhov (slesru) 2014-10-15 03:45:52.037-0500 Yes, sure. Although I get the same behaviour with and without debug I attached two traffic dumps with and without debug cisco-debug.dmp cisco-nodebug.dmp and h323_log Thank you! By: Alexander Anikin (may213) 2014-10-15 11:12:21.212-0500 Dmitry, please check that asterisk is pacthed from the lattest dumps. I see TCS facility packet after progress but patch remove generation of TCS after progress. Also another question. I see cause in release complete packet is not busy. Please check cause that avaya return back to asterisk. By: Dmitry Melekhov (slesru) 2014-10-15 11:47:55.471-0500 Oops, I'm very sorry- really I patched asterisk , but forgot to change script which waits for inactivity and installs asterisk, so I installed not patched version :-( About return code from avaya, afair, it is busy, but will be able to check it only tomorrow morning, because I'm not able to place call over cisco from home. Sorry again for wasting you time with wrong dumps... :-((( Thank you! By: Alexander Anikin (may213) 2014-10-15 14:40:46.255-0500 No problem, will wait actual info. There could be another problem if avaya really return busy but asterisk not translate it. By: Mc GRATH Ricardo (mcgrathr) 2014-10-15 19:15:36.778-0500 I have been following this case and observed on h323_log files same error condition on incoming calls; ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_1 So question could be cause 38 make mess and confused, because in these instance call will never get to QSIG end point. Cause 38 according to standards it refer to net out of order. I paste summarized "No Open Logical Channel" error of all h323_log file (h323_log Oct 08) Line 1579 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_9 Line 3312 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_10 h323_log (10/Oct/14 3:23 AM) Line 4193 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_2 Line 5613 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_3 Line 7049 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_4 Line 8466 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_5 Line 9902 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_6 Line 11319 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_7 Line 12755 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_8 Line 14172 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_9 Line 14372 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_1 h323_log (10/Oct/14 5:55 AM) Line 8547 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_1 h323_log (13/Oct/14 4:32 AM) Line 4193 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_2 Line 5629 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_3 Line 7981 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_1 Line 12185 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_4 Line 12221 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (outgoing, ooh323c_o_1 h323_log (14/Oct/14) Line 4098 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_1 Line 8008 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_4 Line 9441 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_5 Line 9641 07:42:28:657 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_3 h323_log (15/Oct/14) line 4417 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_2 Line 6150 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_3 Line 6402 ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (incoming, ooh323c_1 By: Dmitry Melekhov (slesru) 2014-10-15 22:41:41.500-0500 Hello! With patched asterisk I do not get 38 tone with avaya anymore. And yes, it returns 16 (i.e. hangup), not 17 (user busy) for some reason: -- DAHDI/i1/7500-a is proceeding passing it to OOH323/192.168.22.253-9 -- Span 1: Channel 0/2 got hangup request, cause 16 -- Hungup 'DAHDI/i1/7500-a' -- No one is available to answer at this time (1:0/0/0) I have to ask avaya admin about this, because another definity works as expected, and yes, asterisk there has, oops, definitely had :-) the same issue, nobody complained though, this is because most calls there are between asterisks. Thank you very much! Is this fix stable or you want to, let's say, stabilize it? In last case I'm ready to test. Thank you! By: Dmitry Melekhov (slesru) 2014-10-15 22:51:30.675-0500 btw, about first avaya- this is some issue with phone I used for test, another one returns 17, all is OK with patch. thank you! By: Alexander Anikin (may213) 2014-10-16 10:41:09.842-0500 Dmitry, fine result. I will produce more accurate patch and will ask you to test it. This is not fully correct to remove tcs sending after progress and as we known now progress signal don't affect cisco behavior on busy call complete. I think there need to add delaying of sending release complete if TCS is sent until capabilities exchange and master-slave determination procedures are finished. By: Dmitry Melekhov (slesru) 2014-11-10 22:16:20.008-0600 Hello! Sorry for bothering, but I'd like to have something in newer versions. Could , you , please, provide stable patch for testing? Thank you! By: Dmitry Melekhov (slesru) 2016-10-26 03:04:42.596-0500 Hello! Installing new server and applying patch again... It works for me for years now. Could you, please, include it in main tree? Thank you! By: Alexander Anikin (may213) 2016-11-02 13:02:00.610-0500 Hi Dmitry, Could you please test attached last patch? Some part of the patch removed as i think it is unnecessary but need testing. By: Dmitry Melekhov (slesru) 2016-11-03 00:46:05.554-0500 Hello! Just tested on asterisk 13.12.1, everything seems right :-) Thank you! By: Friendly Automation (friendly-automation) 2016-11-08 04:58:32.090-0600 Change 4331 merged by Joshua Colp: chan_ooh323: Fixes to work right with Cisco devices [https://gerrit.asterisk.org/4331|https://gerrit.asterisk.org/4331] By: Friendly Automation (friendly-automation) 2016-11-08 04:58:51.747-0600 Change 4332 merged by Joshua Colp: chan_ooh323: Fixes to work right with Cisco devices [https://gerrit.asterisk.org/4332|https://gerrit.asterisk.org/4332] By: Friendly Automation (friendly-automation) 2016-11-08 04:58:56.074-0600 Change 4333 merged by Joshua Colp: chan_ooh323: Fixes to work right with Cisco devices [https://gerrit.asterisk.org/4333|https://gerrit.asterisk.org/4333] |