[asterisk-users] strange h323 delay issue

Giedrius Augys voipas at gmail.com
Sun Oct 19 09:39:18 CDT 2008


2008/10/19 Giedrius Augys <voipas at gmail.com>

>
>
> 2008/10/19 Mindaugas Kezys <mkezys at gmail.com>
>
>>  Hi,
>>
>>
>>
>> Try downgrade to Asterisk 1.4.18.1. It works for us perfectly with H323.
>>
>>
>>
>> Following versions has nasty bugs, not actually related to H323, but who
>> knows, maybe it will help to downgrade.
>>
>>
>>
>> Regards,
>>
>> Mindaugas Kezys
>>
>> http://www.kolmisoft.com
>>
>> VoIP Billing and Routing Solutions
>>
>>
>>
>> *From:* asterisk-users-bounces at lists.digium.com [mailto:
>> asterisk-users-bounces at lists.digium.com] *On Behalf Of *Giedrius Augys
>> *Sent:* 2008 m. spalio 18 d. 22:08
>> *To:* Asterisk Users Mailing List - Non-Commercial Discussion
>> *Subject:* [asterisk-users] strange h323 delay issue
>>
>>
>>
>> Hello,
>>
>>   I have a strange h323 issue. After executing command
>> "Dial("SIP/333-0d1dfe00", "H323/361737052390920 at ccg|5|tT")"  at Oct 18
>> 22:32:23. Meanwile I have sniffing traffic on port 1720. The call was
>> established just at Oct 18 22:33:03 (New H.323 Connection created.) and also
>> packet sniffer grabs the h323 invites at this time also. So my question is
>> what asterisk (h323 channel) was doing for 40 sec??? What reasons could
>> invoke this problem? I haven't any problems with SIP channels.
>>
>> My versions:
>> asterisk-1.4.21.1
>> asterisk-addons-1.4.6
>> openh323_v1_18_0
>> pwlib_v1_10_0
>>
>> My h323.conf configurations:
>> [general]
>> port = 1720
>> bindaddr = 192.168.1.165
>> tos=lowdelay
>> disallow=all
>> allow=g729
>> dtmfmode=rfc2833
>> gatekeeper = DISABLE
>> AllowGKRouted = no
>> AcceptAnonymous = no
>> context=from-trunk
>>
>>
>> [ccg]
>> type=friend
>> context=from-trunk
>> host=192.168.1.163
>> port=1720
>> disallow=all
>> ;allow=alaw
>> ;allow=ulaw
>> allow=g729
>> fastStart=yes
>> h245Tunneling=yes
>>
>>
>> A full log:
>>
>> [Oct 18 22:32:23] VERBOSE[18236] logger.c:     -- Executing [123 at from-sip:1]
>> Dial("SIP/333-0d1d8fb0", "H323/361737052390920 at ccg|5|tT") in new stack
>> [Oct 18 22:32:23] DEBUG[18236] chan_h323.c: type=H323, format=8,
>> data=361737052390920 at ccg.
>> [Oct 18 22:32:23] DEBUG[18236] chan_h323.c: Extension: 361737052390920
>> Host: ccg
>> [Oct 18 22:32:23] DEBUG[18236] chan_h323.c: Calling to 361737052390920 at ccgon H323/ccg-2
>> [Oct 18 22:32:23] VERBOSE[18236] logger.c:     -- Requested transfer
>> capability: 0x00 - SPEECH
>> [Oct 18 22:32:23] DEBUG[18236] chan_h323.c: Placing outgoing call to
>> 361737052390920 at 192.168.1.163:1720, 101
>> [Oct 18 22:32:23] VERBOSE[18236] logger.c:  -- Making call to
>> 361737052390920 at 192.168.1.163:1720 without gatekeeper.
>> [Oct 18 22:32:23] VERBOSE[18236] logger.c: Using 192.168.1.165 for
>> outbound call
>> [Oct 18 22:33:03] VERBOSE[18236] logger.c:      == New H.323 Connection
>> created.
>> [Oct 18 22:33:03] VERBOSE[18236] logger.c:      -- root is calling host
>> 361737052390920 at 192.168.1.163:1720
>> [Oct 18 22:33:03] VERBOSE[18236] logger.c:      -- Call token is
>> ip$localhost/6453
>> [Oct 18 22:33:03] VERBOSE[18236] logger.c:      -- Call reference is 6453
>> [Oct 18 22:33:03] VERBOSE[18236] logger.c:      -- DTMF Payload is
>> [pt=101]
>> [Oct 18 22:33:03] VERBOSE[18236] logger.c:     -- Called
>> 361737052390920 at ccg
>> [Oct 18 22:33:03] DEBUG[18238] chan_h323.c: Setting capabilities for
>> connection ip$localhost/6453
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c: Setting capabilities to 0x100
>> (g729)
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c: Capabilities in preference
>> order is (g729)
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c: Allowed Codecs:
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:       Table:
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:    G.729A <1>
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:    G.729 <2>
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:    UserInput/hookflash <3>
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:    UserInput/RFC2833 <4>
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:    UserInput/dtmf <5>
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:  Set:
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:    0:
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:      0:
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:        G.729A <1>
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:        G.729 <2>
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:      1:
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:        UserInput/hookflash <3>
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:      2:
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:        UserInput/RFC2833 <4>
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:        UserInput/dtmf <5>
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:
>> [Oct 18 22:33:03] DEBUG[18238] chan_h323.c: Capabilities for connection
>> ip$localhost/6453 is set
>> [Oct 18 22:33:03] DEBUG[18238] chan_h323.c: Created RTP channel
>> [Oct 18 22:33:03] DEBUG[18238] chan_h323.c: Setting NAT on RTP to 0
>> [Oct 18 22:33:03] DEBUG[18238] chan_h323.c: Sending RTP 'US'
>> 192.168.1.165:23786
>> [Oct 18 22:33:03] DEBUG[18238] chan_h323.c: Sending RTP 'US'
>> 192.168.1.165:23786
>> [Oct 18 22:33:03] DEBUG[18238] chan_h323.c: Sending RTP 'US'
>> 192.168.1.165:23786
>> [Oct 18 22:33:03] DEBUG[18238] chan_h323.c: Sending RTP 'US'
>> 192.168.1.165:23786
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:      -- Sending SETUP message
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:      -- Transmitting RFC2833 on
>> payload 101
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:      -- Started logical
>> channel: sending G.729A
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:              -- channelsOpen =
>> 1
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:              External RTP
>> Session Starting
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:              RTP channel id 1
>> parameters:
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:              --
>> remoteIpAddress: 192.168.1.163
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:              -- remotePort:
>> 10626
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:              --
>> ExternalIpAddress: 192.168.1.165
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:              -- ExternalPort:
>> 23786
>> [Oct 18 22:33:03] DEBUG[18238] chan_h323.c: Setting up RTP connection for
>> ip$localhost/6453
>> [Oct 18 22:33:03] DEBUG[18238] chan_h323.c: Native format is set to 256
>> from 256 by RTP payload type 18
>> [Oct 18 22:33:03] DEBUG[18238] chan_h323.c: RTP connection prepared for
>> ip$localhost/6453
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:      -- Started logical
>> channel: receiving G.729A
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:              -- channelsOpen =
>> 2
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:              External RTP
>> Session Starting
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:              RTP channel id 1
>> parameters:
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:              --
>> remoteIpAddress: 192.168.1.163
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:              -- remotePort:
>> 10626
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:              --
>> ExternalIpAddress: 192.168.1.165
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:              -- ExternalPort:
>> 23786
>> [Oct 18 22:33:03] DEBUG[18238] chan_h323.c: Setting up RTP connection for
>> ip$localhost/6453
>> [Oct 18 22:33:03] DEBUG[18238] chan_h323.c: Native format is set to 256
>> from 256 by RTP payload type 18
>> [Oct 18 22:33:03] DEBUG[18238] chan_h323.c: RTP connection prepared for
>> ip$localhost/6453
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:      ExternalRTPChannel
>> Destroyed
>> [Oct 18 22:33:03] VERBOSE[18238] logger.c:      ExternalRTPChannel
>> Destroyed
>> [Oct 18 22:33:04] VERBOSE[18238] logger.c:      =-= In OnAlerting for call
>> 6453: sessionId=0
>> [Oct 18 22:33:04] VERBOSE[18238] logger.c:      -- Ringing phone for
>> "361737052390920"
>> [Oct 18 22:33:04] VERBOSE[18238] logger.c:              - Progress
>> Indicator: 8
>> [Oct 18 22:33:04] DEBUG[18238] chan_h323.c: Received ALERT/PROGRESS
>> message for inband tones
>> [Oct 18 22:33:04] DEBUG[18238] chan_h323.c: Ringing on ip$localhost/6453
>> [Oct 18 22:33:04] VERBOSE[18236] logger.c:     -- H323/ccg-2 is making
>> progress passing it to SIP/333-0d1d8fb0
>> [Oct 18 22:33:04] VERBOSE[18236] logger.c:     -- H323/ccg-2 is ringing
>> [Oct 18 22:33:04] VERBOSE[18238] logger.c:      -- Received Facility
>> message...
>> [Oct 18 22:33:04] VERBOSE[18238] logger.c: Peer capability is G.729 <2>
>> [Oct 18 22:33:04] VERBOSE[18238] logger.c: Found peer capability G.729
>> <2>, Asterisk code is 256, frame size (in ms) is 60
>> [Oct 18 22:33:04] VERBOSE[18238] logger.c: Peer capability is G.729A <3>
>> [Oct 18 22:33:04] VERBOSE[18238] logger.c: Found peer capability G.729A
>> <3>, Asterisk code is 256, frame size (in ms) is 0
>> [Oct 18 22:33:04] VERBOSE[18238] logger.c: Peer capability is G.723.1A <4>
>> [Oct 18 22:33:04] VERBOSE[18238] logger.c: Found peer capability G.723.1A
>> <4>, Asterisk code is 1, frame size (in ms) is 60
>> [Oct 18 22:33:04] VERBOSE[18238] logger.c: Peer capability is
>> UserInput/dtmf <7>
>> [Oct 18 22:33:04] VERBOSE[18238] logger.c: Peer capability is
>> UserInput/hookflash <8>
>> [Oct 18 22:33:04] VERBOSE[18238] logger.c: Peer capabilities = 0x101
>> (g723|g729), ordered list is (g729|g723)
>> [Oct 18 22:33:04] DEBUG[18238] chan_h323.c: Got remote capabilities from
>> connection ip$localhost/6453
>> [Oct 18 22:33:04] DEBUG[18238] chan_h323.c: prefs[0]=g729:60
>> [Oct 18 22:33:04] DEBUG[18238] chan_h323.c: prefs[1]=g723:60
>> [Oct 18 22:33:04] VERBOSE[18238] logger.c:      -- Received Facility
>> message...
>> [Oct 18 22:33:08] VERBOSE[18236] logger.c:     -- Nobody picked up in 5000
>> ms
>> [Oct 18 22:33:08] DEBUG[18236] chan_h323.c: Hanging up and scheduling
>> destroy of call H323/ccg-2
>> [Oct 18 22:33:08] VERBOSE[18236] logger.c:      -- Sending RELEASE
>> COMPLETE
>> [Oct 18 22:33:08] VERBOSE[18236] logger.c:      -- ClearCall: Request to
>> clear call with token ip$localhost/6453, cause EndedByRemoteUser
>> [Oct 18 22:33:08] VERBOSE[18236] logger.c:   == Auto fallthrough, channel
>> 'SIP/333-0d1d8fb0' status is 'NOANSWER'
>> [Oct 18 22:33:08] VERBOSE[18215] logger.c:              channelsOpen = 1
>> [Oct 18 22:33:08] VERBOSE[18215] logger.c:              channelsOpen = 0
>> [Oct 18 22:33:08] VERBOSE[18215] logger.c:      ExternalRTPChannel
>> Destroyed
>> [Oct 18 22:33:08] VERBOSE[18215] logger.c:      ExternalRTPChannel
>> Destroyed
>> [Oct 18 22:33:08] VERBOSE[18238] logger.c:      -- ClearCall: Request to
>> clear call with token ip$localhost/6453, cause EndedByTransportFail
>> [Oct 18 22:33:08] VERBOSE[18215] logger.c: -- 361737052390920 has cleared
>> the call
>> [Oct 18 22:33:08] DEBUG[18215] chan_h323.c: Cleaning connection to
>> ip$localhost/6453
>> [Oct 18 22:33:08] DEBUG[18215] chan_h323.c: No connection for
>> ip$localhost/6453
>> [Oct 18 22:33:08] VERBOSE[18215] logger.c:      == H.323 Connection
>> deleted.
>>
>>
>> Thanks
>> --
>> Pagarbiai  / Best Regards,
>> Giedrius Augys
>>
>> _______________________________________________
>> -- Bandwidth and Colocation Provided by http://www.api-digital.com --
>>
>> asterisk-users mailing list
>> To UNSUBSCRIBE or update options visit:
>>   http://lists.digium.com/mailman/listinfo/asterisk-users
>>
>
>
> Not helped...
>
> --
> Pagarbiai  / Best Regards,
> Giedrius Augys
>


I solve the problem. The problem was with DNS. h323 has sent srv lookups ,
but dns server was dead....
So now I need to disable h323 srv lookups..
-- 
Pagarbiai  / Best Regards,
Giedrius Augys
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.digium.com/pipermail/asterisk-users/attachments/20081019/49e9694a/attachment.htm 


More information about the asterisk-users mailing list