[Freeswitch-users] Fwd: mod_opal - call charged before H.225 connect

Wed Oct 21 08:48:47 PDT 2009

FS = 10.4.62.7
SIP phone = 10.4.62.89
H323 endpoint = 10.1.14.153

> TC>2. hangup from sip side doesn't release the h323 leg (now the difference
> is
> TC>that FS is not complaining about thread mismatch ant it looks clean but
> FS
> TC>doesn't send any releasecomplete message... strange)
> TC>3. coredumps when i place outgoing calls
>
> btw,
>
> TC> 70.552157  10.1.14.153 -> 10.4.62.7    H.245 endSessionCommand
> TC> 70.552401  10.1.14.153 -> 10.4.62.7    H.225.0 CS: releaseComplete
> TC> 70.553981    10.4.62.7 -> 10.4.62.7    RTP Unknown RTP version 3
> TC> 70.554488    10.4.62.7 -> 10.1.14.153  H.245 endSessionCommand
> TC> 70.555056    10.4.62.7 -> 10.1.14.153  H.225.0 CS: releaseComplete
>
> it send, now i have no way to test h323->sip transit, i will have it
> tomorow.
> sip->h323 for me work fine now, give backtrace from code dump of 1.0.4
> where it die?
>
>

this endSession is when i hangup from H232 side as well :P ... if i don't
hangup on H323 side the H323 leg is not released. Pls chec the time the
packets were sent ...

Here i hangup on the SIP Phone:

68.374916   10.4.62.89 -> 10.4.62.7    SIP Request: BYE
sip:mod_sofia at 10.4.62.7:5060
68.375342    10.4.62.7 -> 10.4.62.7    RTP Unknown RTP version 3
68.375620    10.4.62.7 -> 10.4.62.89   SIP Status: 200 OK

2 sec delay

Here i hangup on the H323 endpoint (releaseComplete comes from H323 endpoint
first here )
70.552157  10.1.14.153 -> 10.4.62.7    H.245 endSessionCommand
70.552401  10.1.14.153 -> 10.4.62.7    H.225.0 CS: releaseComplete

FS just acknowlages it here:
70.554488    10.4.62.7 -> 10.1.14.153  H.245 endSessionCommand
70.555056    10.4.62.7 -> 10.1.14.153  H.225.0 CS: releaseComplete

I have enabled crash-protection and when i do SIP => H323 call it doesn't
generate coredumps... it is just this thread that is crashing ... pls check
the log downbelow:

Dialplan: sofia/internal/1001 at singtel Regex (FAIL) [EMERGENCY]
destination_number(05492122) =~ /^0(112|9[23456])$/ break=on-false
Dialplan: sofia/internal/1001 at singtel parsing [default->SPECIAL_SERVICES]
continue=false
Dialplan: sofia/internal/1001 at singtel Regex (FAIL) [SPECIAL_SERVICES]
destination_number(05492122) =~ /^0(9[01789]\d{3,4})$/ break=on-false
Dialplan: sofia/internal/1001 at singtel parsing [default->ENYTHING_ELSE]
continue=false
Dialplan: sofia/internal/1001 at singtel Regex (PASS) [ENYTHING_ELSE]
destination_number(05492122) =~
/^0([2-8]\d{6,7}|0[1-9]\d{7,8}|00[1-9]\d{8,16})$/ break=on-false
Dialplan: sofia/internal/1001 at singtel Action
set(effective_caller_id_number=1001282122)
Dialplan: sofia/internal/1001 at singtel Action set(NCX_IP=10.4.4.254)
Dialplan: sofia/internal/1001 at singtel Action set(call_timeout=30)
Dialplan: sofia/internal/1001 at singtel Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/1001 at singtel Action set(bypass_media=false)
Dialplan: sofia/internal/1001 at singtel Action set(proxy_media=true)
Dialplan: sofia/internal/1001 at singtel Action bridge(h323/05492122@${NCX_IP})
2009-10-21 17:35:28.682475 [DEBUG] switch_core_state_machine.c:114
(sofia/internal/1001 at singtel) State Change CS_ROUTING -> CS_EXECUTE
2009-10-21 17:35:28.682475 [DEBUG] switch_core_session.c:932 Send signal
sofia/internal/1001 at singtel [BREAK]
2009-10-21 17:35:28.682475 [DEBUG] switch_core_state_machine.c:484
(sofia/internal/1001 at singtel) State ROUTING going to sleep
2009-10-21 17:35:28.682475 [DEBUG] switch_core_state_machine.c:398
(sofia/internal/1001 at singtel) Running State Change CS_EXECUTE
2009-10-21 17:35:28.682475 [DEBUG] switch_core_state_machine.c:491
(sofia/internal/1001 at singtel) State EXECUTE
2009-10-21 17:35:28.682475 [DEBUG] mod_sofia.c:173
sofia/internal/1001 at singtel SOFIA EXECUTE
2009-10-21 17:35:28.682475 [DEBUG] switch_core_state_machine.c:151
sofia/internal/1001 at singtel Standard EXECUTE
EXECUTE sofia/internal/1001 at singtel set(open=true)
2009-10-21 17:35:28.682475 [DEBUG] mod_dptools.c:748
sofia/internal/1001 at singtel SET [open]=[true]
EXECUTE sofia/internal/1001 at singtelhash(insert/10.4.62.7-spymap/1001/5c3ebda2-be57-11de-a6dd-e7de0b74bdc9)
EXECUTE sofia/internal/1001 at singtelhash(insert/10.4.62.7-last_dial/1001/05492122)
EXECUTE sofia/internal/1001 at singtelhash(insert/10.4.62.7-last_dial/global/5c3ebda2-be57-11de-a6dd-e7de0b74bdc9)
EXECUTE sofia/internal/1001 at singtelset(effective_caller_id_number=1001282122)
2009-10-21 17:35:28.685219 [DEBUG] mod_dptools.c:748
sofia/internal/1001 at singtel SET [effective_caller_id_number]=[1001282122]
EXECUTE sofia/internal/1001 at singtel set(NCX_IP=10.4.4.254)
2009-10-21 17:35:28.685219 [DEBUG] mod_dptools.c:748
sofia/internal/1001 at singtel SET [NCX_IP]=[10.4.4.254]
EXECUTE sofia/internal/1001 at singtel set(call_timeout=30)
2009-10-21 17:35:28.686292 [DEBUG] mod_dptools.c:748
sofia/internal/1001 at singtel SET [call_timeout]=[30]
EXECUTE sofia/internal/1001 at singtel set(hangup_after_bridge=true)
2009-10-21 17:35:28.686292 [DEBUG] mod_dptools.c:748
sofia/internal/1001 at singtel SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/1001 at singtel set(bypass_media=false)
2009-10-21 17:35:28.686292 [DEBUG] mod_dptools.c:748
sofia/internal/1001 at singtel SET [bypass_media]=[false]
EXECUTE sofia/internal/1001 at singtel set(proxy_media=true)
2009-10-21 17:35:28.686292 [DEBUG] mod_dptools.c:748
sofia/internal/1001 at singtel SET [proxy_media]=[true]
EXECUTE sofia/internal/1001 at singtel bridge(h323/05492122 at 10.4.4.254)
2009-10-21 17:35:28.687357 [DEBUG] mod_h323.cpp:1380
======>create_outgoing_channel DST NUMBER = 05492122 at 10.4.4.254
2009-10-21 17:35:28.687357 [DEBUG] mod_h323.cpp:1336
======>FSH323EndPoint::FSMakeCall DST NUMBER =
05492122 at 10.4.4.254[FSH323EndPoint]
2009-10-21 17:35:28.687357 [DEBUG] mod_h323.cpp:1348 ----> Using 10.4.62.7
for outbound call
2009-10-21 17:35:28.687357 [DEBUG] pdns.cxx:498 SRV Lookup 10.4.4.254
service _h323cs._tcp.
2009-10-21 17:35:28.689538 [DEBUG] pdns.cxx:471 SRV Lookup Fail no domain
h323:05492122 at 10.4.4.254 <h323%3A05492122 at 10.4.4.254>
2009-10-21 17:35:28.689538 [DEBUG] h323ep.cxx:2315 DNS SRV Cannot resolve
remote party 05492122 at 10.4.4.254
2009-10-21 17:35:28.689538 [DEBUG] h323ep.cxx:2103 Making call to:
05492122 at 10.4.4.254
2009-10-21 17:35:28.689538 [DEBUG] mod_h323.cpp:483
======>FSH323EndPoint::CreateConnection callReference = 12651 userDate =
0xb5e0dac0 [FSH323EndPoint]
2009-10-21 17:35:28.689538 [DEBUG] mod_h323.cpp:486 ------>
SWITCH_CALL_DIRECTION_OUTBOUND
2009-10-21 17:35:28.689538 [DEBUG] mod_h323.cpp:496 ------> fsSession =
0xb7569548
2009-10-21 17:35:28.689538 [DEBUG] h323caps.cxx:3186 Added capability:
G.711-ALaw-64k <1>
2009-10-21 17:35:28.689538 [DEBUG] h323caps.cxx:3186 Added capability:
G.711-uLaw-64k <2>
2009-10-21 17:35:28.689538 [DEBUG] h323caps.cxx:3186 Added capability:
GSM-06.10{sw} <3>
2009-10-21 17:35:28.689538 [DEBUG] h323caps.cxx:3186 Added capability:
G.729A/B{sw} <4>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3186 Added capability:
G.729A{sw} <5>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3186 Added capability:
G.729B{sw} <6>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3186 Added capability:
G.729{sw} <7>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3186 Added capability:
UserInput/hookflash <8>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3186 Added capability:
UserInput/basicString <9>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3186 Added capability:
UserInput/dtmf <10>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3186 Added capability:
UserInput/RFC2833 <11>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3186 Added capability:
UserInput/Navigation <12>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3186 Added capability:
UserInput/Softkey <13>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3186 Added capability:
UserInput/PointDevice <14>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3186 Added capability:
UserInput/Modal <15>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3248 FindCapability: 1
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3252 Found capability:
G.711-ALaw-64k <1>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3248 FindCapability: 2
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3252 Found capability:
G.711-uLaw-64k <2>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3248 FindCapability: 3
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3252 Found capability:
GSM-06.10{sw} <3>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3248 FindCapability: 4
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3252 Found capability:
G.729A/B{sw} <4>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3248 FindCapability: 5
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3252 Found capability:
G.729A{sw} <5>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3248 FindCapability: 6
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3252 Found capability:
G.729B{sw} <6>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3248 FindCapability: 7
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3252 Found capability:
G.729{sw} <7>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3248 FindCapability: 8
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3252 Found capability:
UserInput/hookflash <8>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3248 FindCapability: 9
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3252 Found capability:
UserInput/basicString <9>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3248 FindCapability: 10
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3252 Found capability:
UserInput/dtmf <10>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3248 FindCapability: 11
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3252 Found capability:
UserInput/RFC2833 <11>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3248 FindCapability: 12
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3252 Found capability:
UserInput/Navigation <12>
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3248 FindCapability: 13
2009-10-21 17:35:28.690630 [DEBUG] h323caps.cxx:3252 Found capability:
UserInput/Softkey <13>
2009-10-21 17:35:28.691688 [DEBUG] h323caps.cxx:3248 FindCapability: 14
2009-10-21 17:35:28.691688 [DEBUG] h323caps.cxx:3252 Found capability:
UserInput/PointDevice <14>
2009-10-21 17:35:28.691688 [DEBUG] h323caps.cxx:3248 FindCapability: 15
2009-10-21 17:35:28.691688 [DEBUG] h323caps.cxx:3252 Found capability:
UserInput/Modal <15>
2009-10-21 17:35:28.691688 [DEBUG] h4601.cxx:1725 Endpoint Attached
2009-10-21 17:35:28.691688 [DEBUG] rfc2833.cxx:87 Handler created
2009-10-21 17:35:28.691688 [DEBUG] mod_h323.cpp:525
======>FSH323Connection::FSH323Connection FSH323Connection
2009-10-21 17:35:28.691688 [NOTICE] switch_channel.c:602 New Channel h323/
05492122 at 10.4.4.254 [5c413af0-be57-11de-a6dd-e7de0b74bdc9]
2009-10-21 17:35:28.691688 [DEBUG] mod_h323.cpp:546 (h323/
05492122 at 10.4.4.254) State Change CS_NEW -> CS_INIT
2009-10-21 17:35:28.691688 [DEBUG] mod_h323.cpp:958
======>FSH323Connection::state_change FSH323Connection
2009-10-21 17:35:28.691688 [DEBUG] mod_h323.cpp:959 State changed on
connection FSH323Connection
2009-10-21 17:35:28.691688 [DEBUG] switch_core_session.c:932 Send signal
h323/05492122 at 10.4.4.254 [BREAK]
2009-10-21 17:35:28.691688 [DEBUG] mod_h323.cpp:831
======>FSH323Connection::kill_channel FSH323Connection
2009-10-21 17:35:28.691688 [DEBUG] mod_h323.cpp:832 Kill 3 on connection
FSH323Connection
2009-10-21 17:35:28.691688 [DEBUG] h323ep.cxx:2183 Created new connection:
ip$localhost/12651
2009-10-21 17:35:28.691688 [DEBUG] osutil.cxx:188 File handle high water
mark set: 58 Thread unblock pipe
2009-10-21 17:35:28.691688 [DEBUG] h323ep.cxx:1101 Started call thread
2009-10-21 17:35:28.691688 [CRIT] switch_core_state_machine.c:239 Obtained
10 stack frames.
/usr/local/freeswitch/lib/libfreeswitch.so.1 [0xb7f511f5]
[0xb80be400]
/usr/local/freeswitch/mod/mod_h323.so [0xb6953cc9]
/usr/local/freeswitch/lib/libfreeswitch.so.1(switch_core_session_outgoing_channel+0x1ad)
[0xb7f4f59d]
/usr/local/freeswitch/lib/libfreeswitch.so.1(switch_ivr_originate+0x1b2b)
[0xb7f7aa1b]
/usr/local/freeswitch/mod/mod_dptools.so [0xb70ea2d5]
/usr/local/freeswitch/lib/libfreeswitch.so.1(switch_core_session_exec+0x284)
[0xb7f4c5a4]
/usr/local/freeswitch/lib/libfreeswitch.so.1(switch_core_session_execute_application+0x8b)
[0xb7f4cacb]
/usr/local/freeswitch/lib/libfreeswitch.so.1(switch_core_session_run+0x12b8)
[0xb7f52658]
/usr/local/freeswitch/lib/libfreeswitch.so.1 [0xb7f4e6c5]
2009-10-21 17:35:28.691688 [DEBUG] mod_h323.cpp:509
======>FSH323EndPoint::OnSetGatewayPrefixes FSH323EndPoint
2009-10-21 17:35:28.691688 [CRIT] switch_core_state_machine.c:352 Thread has
crashed for channel sofia/internal/1001 at singtel
2009-10-21 17:35:28.691688 [NOTICE] switch_core_state_machine.c:353 Hangup
sofia/internal/1001 at singtel [CS_EXECUTE] [CRASH]
2009-10-21 17:35:28.691688 [DEBUG] transports.cxx:1828 Connecting to
10.4.4.254:1720 (local port=0)
2009-10-21 17:35:28.691688 [DEBUG] osutil.cxx:188 File handle high water
mark set: 59 PTCPSocket
2009-10-21 17:35:28.691688 [DEBUG] switch_channel.c:1683 Send signal
sofia/internal/1001 at singtel [KILL]
2009-10-21 17:35:28.691688 [DEBUG] switch_core_session.c:932 Send signal
sofia/internal/1001 at singtel [BREAK]
2009-10-21 17:35:28.691688 [DEBUG] switch_core_state_machine.c:398
(sofia/internal/1001 at singtel) Running State Change CS_HANGUP
2009-10-21 17:35:28.691688 [DEBUG] transports.cxx:1681 Started connection:
host=10.4.4.254:1720, if=10.4.62.7:52984, handle=59
2009-10-21 17:35:28.691688 [DEBUG] h323.cxx:2680 Sending Setup PDU
2009-10-21 17:35:28.691688 [DEBUG] switch_core_state_machine.c:434
(sofia/internal/1001 at singtel) State HANGUP
2009-10-21 17:35:28.691688 [DEBUG] mod_sofia.c:338 Channel
sofia/internal/1001 at singtel hanging up, cause: CRASH
2009-10-21 17:35:28.691688 [DEBUG] mod_sofia.c:417 Responding to INVITE
with: 480
2009-10-21 17:35:28.691688 [DEBUG] mod_h323.cpp:559
======>FSH323Connection::OnSetLocalCapabilities() [FSH323Connection]
2009-10-21 17:35:28.691688 [DEBUG] mod_h323.cpp:565
======>FSH323Connection::SetLocalCapabilities() Size local capability = 15
[FSH323Connection]
2009-10-21 17:35:28.691688 [DEBUG] mod_h323.cpp:600
======>FSH323Connection::decodeCapability
2009-10-21 17:35:28.691688 [INFO] mod_h323.cpp:619 capability
'G.711-ALaw-64k' format 'PCMU' payload 8
2009-10-21 17:35:28.691688 [DEBUG] mod_h323.cpp:600
======>FSH323Connection::decodeCapability
2009-10-21 17:35:28.691688 [INFO] mod_h323.cpp:619 capability
'G.711-uLaw-64k' format 'PCMA' payload 0
2009-10-21 17:35:28.691688 [DEBUG] mod_h323.cpp:600
======>FSH323Connection::decodeCapability
2009-10-21 17:35:28.691688 [INFO] mod_h323.cpp:619 capability 'GSM-06.10'
format 'GSM' payload 3
2009-10-21 17:35:28.691688 [DEBUG] mod_h323.cpp:600
======>FSH323Connection::decodeCapability
2009-10-21 17:35:28.691688 [INFO] mod_h323.cpp:619 capability 'G.729A/B'
format 'G729' payload 18
2009-10-21 17:35:28.691688 [DEBUG] switch_core_state_machine.c:46
sofia/internal/1001 at singtel Standard HANGUP, cause: CRASH
2009-10-21 17:35:28.691688 [DEBUG] switch_core_state_machine.c:434
(sofia/internal/1001 at singtel) State HANGUP going to sleep
2009-10-21 17:35:28.691688 [DEBUG] mod_h323.cpp:600
======>FSH323Connection::decodeCapability
2009-10-21 17:35:28.691688 [INFO] mod_h323.cpp:619 capability 'G.729A'
format 'G729' payload 18
2009-10-21 17:35:28.691688 [DEBUG] mod_h323.cpp:600
======>FSH323Connection::decodeCapability
2009-10-21 17:35:28.691688 [INFO] mod_h323.cpp:619 capability 'G.729B'
format 'G729b' payload 18
2009-10-21 17:35:28.691688 [DEBUG] mod_h323.cpp:600
======>FSH323Connection::decodeCapability

Well, I'm not sure if the backtrace is from 1.0.4 ... i will disable
crass-protection and will send new logs to you.

Also, if you like i can give you access to the machine itself...

T.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20091021/2b47d7dd/attachment-0002.html 