[Home]

Summary:ASTERISK-22901: Originate command doesn't work through OOH323 channels
Reporter:Cyril CONSTANTIN (cyrilc)Labels:
Date Opened:2013-11-25 09:36:27.000-0600Date Closed:2013-11-29 14:44:12.000-0600
Priority:MinorRegression?
Status:Closed/CompleteComponents:Addons/chan_ooh323
Versions:11.6.0 Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) ASTERISK-22901.patch
( 1) encodestr-debug.patch
( 2) originate.jpg
( 3) Originate.rar
( 4) Originate_-_Dial.rar
( 5) originateooh323.rar
Description:Hi Guys,

When using CMD Originate into my dialplan to dial a number through OOH323 call couldn't be establish, when using tcpdump I can't see call trying to be establish with Avaya.

I don't have this problem with CMD Originate when doing it with SIP peer.

Also I'm already using OOH323 with Dial command and it works great, when looking into console log with ooh323 debug activated it looks that it try to make a call through ooh323 channel but nothing happens behind, even on Avaya I can't see anything coming from Asterisk.

See below what I'm using for CMD Originate with OOH323 (not working):
{noformat}
same => n,Originate(OOH323/00625081954@Avaya,exten,bridgetwoparty,s,1)
{noformat}

Below when I'm dialing through OOH323 (working):
{noformat}
same => n,Dial(OOH323/00625081954@Avaya)
{noformat}

Below when I'm using CMD Originate with SIP peer (working):
{noformat}
same => n,Originate(SIP/46000,exten,bridgetwoparty,s,1)
{noformat}

I'll attach tcpdump, debug, full, messages, console logs.

Best Regards
Comments:By: Matt Jordan (mjordan) 2013-11-26 12:33:24.775-0600

It certainly looks like it's doing something. {{OOH323/Avaya-4216}} is originated via a message received from the text message handler channel Message, and it certainly exists for 30 seconds or so:

{noformat}
[Nov 25 15:14:29] DEBUG[19192] manager.c: Examining event:
Event: Newexten
Privilege: dialplan,all
Timestamp: 1385388869.842732
Channel: Message/ast_msg_queue
Context: IncomingMessages
Extension: s
Priority: 11
Application: Originate
AppData: OOH323/00625081954@Avaya,exten,bridgetwoparty,s,1
Uniqueid: 1385371240.5017


[Nov 25 15:14:29] VERBOSE[19105][C-00000652] chan_ooh323.c: ---   ooh323_request - data 00625081954@Avaya format (slin192)
[Nov 25 15:14:29] VERBOSE[19105][C-00000652] chan_ooh323.c: ---   ooh323_alloc
[Nov 25 15:14:29] DEBUG[14381][C-0000106b] audiohook.c: Read factory 0xa43c7cc was pretty quick last time, waiting for them.
[Nov 25 15:14:29] VERBOSE[19105][C-00000652] chan_ooh323.c: +++   ooh323_alloc
[Nov 25 15:14:29] VERBOSE[19105][C-00000652] chan_ooh323.c: ---   find_peer "Avaya"
[Nov 25 15:14:29] VERBOSE[19105][C-00000652] chan_ooh323.c: comparing with "10.147.9.64"
[Nov 25 15:14:29] VERBOSE[19105][C-00000652] chan_ooh323.c: comparing with "10.147.9.64"
[Nov 25 15:14:29] VERBOSE[19105][C-00000652] chan_ooh323.c: found matching peer
[Nov 25 15:14:29] VERBOSE[19105][C-00000652] chan_ooh323.c: +++   find_peer "Avaya"
[Nov 25 15:14:29] VERBOSE[19105][C-00000652] chan_ooh323.c: ---   ooh323_new - Avaya
[Nov 25 15:14:29] DEBUG[19192] manager.c: Examining event:
Event: Newchannel
Privilege: call,all
Timestamp: 1385388869.843312
Channel: OOH323/Avaya-4216
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum:
CallerIDName:
AccountCode: ast_h323
Exten: 00625081954
Context: from-h323
Uniqueid: 1385388869.13016
{noformat}

...

{noformat}
[Nov 25 15:14:29] DEBUG[19105][C-00000652] channel.c: Set channel OOH323/Avaya-4216 to write format slin192
[Nov 25 15:14:29] DEBUG[19105][C-00000652] channel.c: Set channel OOH323/Avaya-4216 to read format slin192
[Nov 25 15:14:29] DEBUG[19105][C-00000652] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Nov 25 15:14:29] DEBUG[19105][C-00000652] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Nov 25 15:14:29] DEBUG[19105][C-00000652] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Nov 25 15:14:29] DEBUG[19105][C-00000652] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Nov 25 15:14:29] VERBOSE[19105][C-00000652] chan_ooh323.c: +++   h323_new
[Nov 25 15:14:29] DEBUG[19192] manager.c: Examining event:
Event: ChannelUpdate
Privilege: system,all
Timestamp: 1385388869.843593
Channel: OOH323/Avaya-4216
Channeltype: OOH323
CallRef: 0
{noformat}

...

{noformat}
[Nov 25 15:14:29] VERBOSE[19105][C-00000652] chan_ooh323.c: +++   ooh323_request
[Nov 25 15:14:29] VERBOSE[19105][C-00000652] chan_ooh323.c: ---   ooh323_call- 00625081954@Avaya
[Nov 25 15:14:29] DEBUG[19192] manager.c: Examining event:
Event: NewCallerid
Privilege: call,all
Timestamp: 1385388869.844946
Channel: OOH323/Avaya-4216
CallerIDNum:
CallerIDName:
Uniqueid: 1385388869.13016
CID-CallingPres: 67 (Number Unavailable)
{noformat}

...

{noformat}
[Nov 25 15:14:59] DEBUG[19105][C-00000652] channel.c: Hanging up channel 'OOH323/Avaya-4216'
[Nov 25 15:14:59] VERBOSE[19105][C-00000652] chan_ooh323.c: ---   ooh323_hangup
[Nov 25 15:14:59] VERBOSE[19105][C-00000652] chan_ooh323.c:     hanging Avaya with cause: 16
{noformat}

I'll leave it up to Alexandr to take a look at it any further.
By: Cyril CONSTANTIN (cyrilc) 2013-11-27 03:50:25.578-0600

Hi,

Instead of using test message handler for sending command from gtalk, I just made a test from context used by my SIP softphone and dialed the extension "test" so directly SIP to OOH323 via Originate command but it still doesn't work see below:

{noformat}
[lab-cyril]
exten => test,1,Originate(OOH323/00625081954@Avaya,exten,bridge,s,1)

[bridge]
exten => s,1,ConfBridge(118218)
{noformat}

I got no sound for 30 seconds see below logs from console it looks it try to make a call through OOH323 but nothing happens:

{noformat}
<------------>
   -- Executing [test@from-sip:1] Originate("SIP/46000-00000cfe", "OOH323/00625081954@Avaya,exten,bridge,s,1") in new stack
---   ooh323_request - data 00625081954@Avaya format (slin192)
---   ooh323_alloc
+++   ooh323_alloc
---   find_peer "Avaya"
               comparing with "10.147.9.64"
               comparing with "10.147.9.64"
               found matching peer
+++   find_peer "Avaya"
---   ooh323_new - Avaya
+++   h323_new
---   onNewCallCreated b0e0e898: ooh323c_o_11770
---   find_call
+++   find_call
Outgoing call Avaya(ooh323c_o_11770) - Codec prefs - (alaw)
       Adding capabilities to call(outgoing, ooh323c_o_11770)
       Adding g711 alaw capability to call(outgoing, ooh323c_o_11770)
---   configure_local_rtp
+++   configure_local_rtp
+++   onNewCallCreated ooh323c_o_11770
+++   ooh323_request
---   ooh323_call- 00625081954@Avaya
+++   ooh323_call
---   onOutgoingCall b0e0e898: ooh323c_o_11770
---   find_call
+++   find_call
+++   onOutgoingCall ooh323c_o_11770
{noformat}

If I do a Dial(OOH323/00625081954@Avaya) it works great, so I don't know what happens with Originate but it looks that something is not properly done when using OOH323.

Below an example when I'm replacing Originate by Dial:
{noformat}
   -- Executing [test@from-sip:1] Dial("SIP/46000-00000d16", "OOH323/00625081954@Avaya") in new stack
---   ooh323_request - data 00625081954@Avaya format (alaw)
---   ooh323_alloc
+++   ooh323_alloc
---   find_peer "Avaya"
               comparing with "10.147.9.64"
               comparing with "10.147.9.64"
               found matching peer
+++   find_peer "Avaya"
---   ooh323_new - Avaya
+++   h323_new
---   onNewCallCreated b69326e8: ooh323c_o_11830
---   find_call
+++   find_call
Outgoing call Avaya(ooh323c_o_11830) - Codec prefs - (alaw)
       Adding capabilities to call(outgoing, ooh323c_o_11830)
       Adding g711 alaw capability to call(outgoing, ooh323c_o_11830)
---   configure_local_rtp
+++   configure_local_rtp
+++   onNewCallCreated ooh323c_o_11830
+++   ooh323_request
----- ooh323_queryoption 16 on channel OOH323/Avaya-11996
+++++ ooh323_queryoption 16 on channel OOH323/Avaya-11996
+++ ooh323  get_rtp_peer
ooh323_get_rtp_peer  OOH323/Avaya-11996 -> (null):0, 2
--- ooh323  get_rtp_peer, res = 2
---   ooh323_call- 00625081954@Avaya
+++   ooh323_call
   -- Called OOH323/00625081954@Avaya
---   onOutgoingCall b69326e8: ooh323c_o_11830
---   find_call
+++   find_call
setting callid number 40075
+++   onOutgoingCall ooh323c_o_11830
Reliably Transmitting (no NAT) to 10.147.116.39:51922:
OPTIONS sip:46000@10.147.116.39:51922;rinstance=24e333eff42d355e;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.147.113.73:5060;branch=z9hG4bK2f5ff31b
Max-Forwards: 70
From: "asterisk" <sip:asterisk@10.147.113.73>;tag=as30791647
To: <sip:46000@10.147.116.39:51922;rinstance=24e333eff42d355e;transport=udp>
Contact: <sip:asterisk@10.147.113.73:5060>
Call-ID: 4ac5b3857a35181c5efd63487905197b@10.147.113.73:5060
CSeq: 102 OPTIONS
User-Agent: 118218
Date: Wed, 27 Nov 2013 09:40:15 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0
---

<--- SIP read from UDP:10.147.116.39:51922 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.147.113.73:5060;branch=z9hG4bK2f5ff31b
Contact: <sip:10.147.116.39:51922>
To: <sip:46000@10.147.116.39:51922;rinstance=24e333eff42d355e;transport=udp>;tag=103c076a
From: "asterisk"<sip:asterisk@10.147.113.73>;tag=as30791647
Call-ID: 4ac5b3857a35181c5efd63487905197b@10.147.113.73:5060
CSeq: 102 OPTIONS
Accept: application/sdp
Accept-Language: en
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
Supported: replaces, eventlist
User-Agent: Bria 3 release 3.5.5 stamp 71238
Allow-Events: hold, talk
Content-Length: 0
{noformat}


When comparing two traces between Originate and Dial I have differences below:

On Originate:
{noformat}
ooh323_request - data 00625081954@Avaya format (slin192)
{noformat}

On Dial I have all those line in more compared to Originate:
{noformat}
ooh323_request - data 00625081954@Avaya format (alaw)
----- ooh323_queryoption 16 on channel OOH323/Avaya-11996
+++++ ooh323_queryoption 16 on channel OOH323/Avaya-11996
+++ ooh323  get_rtp_peer
ooh323_get_rtp_peer  OOH323/Avaya-11996 -> (null):0, 2
--- ooh323  get_rtp_peer, res = 2
-- Called OOH323/00625081954@Avaya
setting callid number 40075
{noformat}


Also format used by Originate was slin192 when Dial used alaw don't know if it can cause the issue. As you can see above there is lot more thing happening when using Dial command.

I have added a screenshot of my comparison between both logs.

Best Regards
By: Cyril CONSTANTIN (cyrilc) 2013-11-27 04:04:41.285-0600

on left side Originate command on right side from Dial command
By: Alexander Anikin (may213) 2013-11-27 14:09:52.855-0600

Cyril, i checked originate application with ooh323 channels on 11.6 and it work in common way.
So i need more info to search the bug.
Could you make asterisk full log file which include trace for only call that issued by originate cmd? Also please setup tracelevel=6 in ooh323.conf and attach here /var/log/asterisk/h323_log for same call.
You can setup tracelevel=6 and do 'ooh323 reload' before test call and save copy h323_log and revert back to tracelevel=0 after.
By: Cyril CONSTANTIN (cyrilc) 2013-11-27 14:32:36.620-0600

Hi Alexander,

Please find in attachment traces required, I made two test call one with Originate and the other with Dial, I made two distinct traces for those calls.

Best Regards
By: Cyril CONSTANTIN (cyrilc) 2013-11-27 14:33:22.539-0600

ooh323 traces with Originate and Dial
By: Cyril CONSTANTIN (cyrilc) 2013-11-27 14:40:20.766-0600

In Originate logs I can see errors below:

{noformat}
Line 896: 21:23:19:292  Asn1Error: -23 at ooh323c/src/encode.c:439
Line 897: 21:23:19:292  ERROR: UserInfo encoding failed
Line 1679: 21:23:19:292  Error:Failed to encode uuie. (outgoing, ooh323c_o_1)
Line 1680: 21:23:19:292  Error:Failed to encode H225 message. (outgoing, ooh323c_o_1)
Line 1681: 21:23:19:292  Error:Failed to enqueue SETUP message to outbound queue. (outgoing, ooh323c_o_1)
Line 1695: 21:23:49:294  ERROR: No Open LogicalChannels - Failed FindLogicalChannelByChannelNo (outgoing, ooh323c_o_1
{noformat}
By: Alexander Anikin (may213) 2013-11-28 03:51:17.108-0600

patch to debug encoding constrained string
By: Alexander Anikin (may213) 2013-11-28 03:53:33.302-0600

Cyril, please apply attached patch and repeat test with tracelevel=6

Problem is in encoding strings in Setup packet, i guess something like called/calling number.
This patch will show numbers that encoded in setup packet to debug file.
By: Cyril CONSTANTIN (cyrilc) 2013-11-28 04:21:03.325-0600

Hi,

Thanks for that I'll try tonight as currently I have production running on it.

Best Regards
By: Cyril CONSTANTIN (cyrilc) 2013-11-28 14:05:06.758-0600

Hi,

I made traces with your patch applied, there is a missing part in Build Setup messages see below difference between both:

On Dial trace:
{noformat}
Built SETUP message (outgoing, ooh323c_o_1)
20:37:07:658  encodeConstrainedStringEx: 40075, #*,0123456789
20:37:07:658  encodeConstrainedStringEx: 00625081954, #*,0123456789
{noformat}

On Originate traces:
{noformat}
Built SETUP message (outgoing, ooh323c_o_1)

20:54:01:995  encodeConstrainedStringEx: asterisk, #*,0123456789
{noformat}

B-party (0625081954) is not populated into Originate traces.

I have added traces in attachment.

Best Regards
By: Cyril CONSTANTIN (cyrilc) 2013-11-28 14:05:58.647-0600

Originate traces with patch applied in order to have more details into h323_log.
By: Alexander Anikin (may213) 2013-11-29 06:17:29.264-0600

Hi Cyril,

Looks like to your ooh323.conf contain 'e164=asterisk' in section [general] (or in Avaya peer section) and it's wrong due to e.164 must contain digits only.

Also i'll produce patch to ignore those records on config parser.
By: Cyril CONSTANTIN (cyrilc) 2013-11-29 09:24:42.835-0600

Hi,

I tried by changing e.164 in general section and made a ooh323 reload but it doesn't change anything, I'll try tonight by restarting asterisk.

Keep you posted

Thanks
By: Cyril CONSTANTIN (cyrilc) 2013-11-29 14:43:41.120-0600

You rocks after a restart it works perfectly well !

I changed E164 by head line number from my company and originate command works as expected.

Many thanks for your time spent on it.

Have a nice evening.

Best Regards.


By: Cyril CONSTANTIN (cyrilc) 2013-11-29 14:44:12.210-0600

A patch will be produced to ignore E164 record on OOH323 config parser, to prevent in case of config error to stop Originate command working
By: Alexander Anikin (may213) 2013-12-02 11:52:28.264-0600

Patch to checking e164 values on peers and general config sections. Regenerate e164 list on config reload