[Freeswitch-users] mod_opal - call charged before H.225 connect
Tihomir Culjaga
tculjaga at gmail.com
Wed Oct 7 08:50:12 PDT 2009
On Wed, Oct 7, 2009 at 2:40 PM, Claudiu Filip <claudiu at globtel.ro> wrote:
>
>
>
> Hi Tihomir,
>
>
> I've done some tests to see how suitable is freeswitch as a
> SIP/H323 translator and you are right about the fact that H323
> 'alert+open logical channel' will generate a SIP '200 OK'. I was
> able to fix that with a couple of changes in mod_opal.cpp, however
> some things were changed on mod_sofia in the latest svn. (on this
> particular issue, open_logical_channel is processed BEFORE the
> alerting, so the call is in SetupPhase when the proc
> OnOpenMediaStream is triggered)
>
>
>
yep, thats correct ... i was just wondering why it hangs in SetUpPhase
2009-10-07 16:50:11.690451 [DEBUG] manager.cxx:718 OnOpenMediaStream
Call[n03f409711]-EP<h323>[localhost/3263],OpalRTPMediaStream-Source-G.711-ALaw-64k
2009-10-07 16:50:11.690451 [INFO] mod_opal.cpp:1283 opal/
h323:05492122 at 10.4.4.254 <h323%3A05492122 at 10.4.4.254> initialise
opal/h323:05492122 at 10.4.4.254read audio codec G.711-ALaw-64k for connection
FSMediaStream-Sink-G.711-ALaw-64k
2009-10-07 16:50:11.690451 [DEBUG] mod_opal.cpp:1313 Set read audio codec to
<< G.711-ALaw-64k for connection FSMediaStream-Sink-G.711-ALaw-64k
2009-10-07 16:50:11.691525 [DEBUG] manager.cxx:718 OnOpenMediaStream
Call[n03f409711]-EP<local>[1],FSMediaStream-Sink-G.711-ALaw-64k
*2009-10-07 16:50:11.691525 [CONSOLE] mod_opal.cpp:852 SetUpPhase =>
GetPhase() = '1'*
2009-10-07 16:50:11.691525 [DEBUG] connection.cxx:561 Opened sink stream
n03f409711_1 with format G.711-ALaw-64k
2009-10-07 16:50:11.691525 [DEBUG] patch.cxx:341 Created Sink:
format=G.711-ALaw-64k
2009-10-07 16:50:11.691525 [DEBUG] mediastrm.cxx:666 RTP data size cannot be
changed to 160, fixed at 2048
2009-10-07 16:50:11.691525 [DEBUG] patch.cxx:179 Added direct media stream
sink FSMediaStream-Sink-G.711-ALaw-64k
this is the original code, and it never triggers eraly_media as never
reaches AlertingPhase.
if (GetMediaStream(stream.GetSessionID(), stream.IsSink()) != NULL) {
// Have open media in both directions.
if (GetPhase() == AlertingPhase) {
switch_channel_mark_pre_answered(m_fsChannel);
switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CONSOLE, "LOG
==>\t Alerting => GetPhase() = '%d'\n",GetPhase());
} else if (GetPhase() < ReleasingPhase) {
switch_channel_mark_answered(m_fsChannel);
switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CONSOLE, "LOG
==>\t GetPhase() = '%d'\n",GetPhase());
}
}
I tried this, it works for early media but i still need to open a full media
path and say the call actually connected ....
if (GetMediaStream(stream.GetSessionID(), stream.IsSink()) != NULL) {
// Have open media in both directions.
if (GetPhase() < ConnectedPhase) {
switch_channel_mark_pre_answered(m_fsChannel);
switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CONSOLE, "EARLY
MEDIA => GetPhase() = '%d'\n",GetPhase());
} else if (GetPhase() < ReleasingPhase) {
switch_channel_mark_answered(m_fsChannel);
switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_CONSOLE, "FULL
MEDIA => GetPhase() = '%d'\n",GetPhase());
}
}
this is when i'm dong early_media:
2009-10-07 17:45:26.788082 [DEBUG] manager.cxx:718 OnOpenMediaStream
Call[c8dce50981]-EP<h323>[localhost/26906],OpalRTPMediaStream-Source-G.711-ALaw-64k
2009-10-07 17:45:26.789158 [INFO] mod_opal.cpp:1279 opal/
h323:05492122 at 10.4.4.254 <h323%3A05492122 at 10.4.4.254> initialise
opal/h323:05492122 at 10.4.4.254read audio codec G.711-ALaw-64k for connection
FSMediaStream-Sink-G.711-ALaw-64k
2009-10-07 17:45:26.789158 [DEBUG] mod_opal.cpp:1309 Set read audio codec to
<< G.711-ALaw-64k for connection FSMediaStream-Sink-G.711-ALaw-64k
2009-10-07 17:45:26.789158 [DEBUG] manager.cxx:718 OnOpenMediaStream
Call[c8dce50981]-EP<local>[1],FSMediaStream-Sink-G.711-ALaw-64k
2009-10-07 17:45:26.789158 [NOTICE] mod_opal.cpp:887 Pre-Answer opal/
h323:05492122 at 10.4.4.254 <h323%3A05492122 at 10.4.4.254>!
2009-10-07 17:45:26.789158 [DEBUG] switch_channel.c:1822 Send signal
sofia/internal/1001 at 10.4.62.7 [BREAK]
*2009-10-07 17:45:26.789158 [CONSOLE] mod_opal.cpp:888 EARLY MEDIA =>
GetPhase() = '1'*
2009-10-07 17:45:26.789158 [DEBUG] connection.cxx:561 Opened sink stream
c8dce50981_1 with format G.711-ALaw-64k
2009-10-07 17:45:26.789158 [DEBUG] patch.cxx:341 Created Sink:
format=G.711-ALaw-64k
2009-10-07 17:45:26.790236 [DEBUG] switch_ivr_originate.c:2154
sofia/internal/1001 at 10.4.62.7 receive message [PROGRESS]
2009-10-07 17:45:26.790236 [INFO] switch_ivr_originate.c:2154 Sending early
media
2009-10-07 17:45:26.790236 [DEBUG] sofia_glue.c:2329 AUDIO RTP
[sofia/internal/1001 at 10.4.62.7] 10.4.62.7 port 19594 -> 10.4.62.89 port 5004
codec: 8 ms: 20
2009-10-07 17:45:26.790236 [DEBUG] switch_rtp.c:1155 Starting timer [soft]
160 bytes per 20ms
2009-10-07 17:45:26.790236 [DEBUG] mediastrm.cxx:666 RTP data size cannot be
changed to 160, fixed at 2048
2009-10-07 17:45:26.790236 [DEBUG] patch.cxx:179 Added direct media stream
sink FSMediaStream-Sink-G.711-ALaw-64k
2009-10-07 17:45:26.790236 [DEBUG] connection.cxx:728 Sink stream of
connection Call[c8dce50981]-EP<local>[1] uses patch Patch
OpalRTPMediaStream-Source-G.711-ALaw-64k ->
FSMediaStream-Sink-G.711-ALaw-64k
2009-10-07 17:45:26.791311 [DEBUG] connection.cxx:728 Source stream of
connection Call[c8dce50981]-EP<h323>[localhost/26906] uses patch Patch
OpalRTPMediaStream-Source-G.711-ALaw-64k ->
FSMediaStream-Sink-G.711-ALaw-64k
2009-10-07 17:45:26.791311 [DEBUG] rtpconn.cxx:249 Adding RFC2833 receive
handler
2009-10-07 17:45:26.791311 [DEBUG] rtpconn.cxx:254 Adding Cisco NSE receive
handler
2009-10-07 17:45:26.791311 [DEBUG] h323ep.cxx:1118 Started receiving logical
channel: G.711-ALaw-64k <2>
2009-10-07 17:45:26.791311 [DEBUG] rtpconn.cxx:496 Releasing session 1
2009-10-07 17:45:26.792387 [DEBUG] rtpconn.cxx:496 Releasing session 1
2009-10-07 17:45:26.792387 [DEBUG] h323.cxx:2450 Fast starting 2 channels
2009-10-07 17:45:26.792387 [DEBUG] h323ep.cxx:1024 Received alerting PDU.
2009-10-07 17:45:26.792387 [DEBUG] manager.cxx:636 OnAlerting
Call[c8dce50981]-EP<h323>[localhost/26906]
2009-10-07 17:45:26.792387 [DEBUG] call.cxx:184 OnAlerting
Call[c8dce50981]-EP<h323>[localhost/26906]
2009-10-07 17:45:26.792387 [DEBUG] localep.cxx:214 SetAlerting(10.4.4.254)
2009-10-07 17:45:26.792387 [INFO] mod_sofia.c:1518 Ring SDP:
v=0
o=FreeSWITCH 1254910732 1254910733 IN IP4 10.4.62.7
s=FreeSWITCH
c=IN IP4 10.4.62.7
t=0 0
m=audio 19594 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
2009-10-07 17:45:26.792387 [DEBUG] connection.cxx:1115 SetPhase from
SetUpPhase to AlertingPhase for Call[c8dce50981]-EP<local>[1]
2009-10-07 17:45:26.792387 [NOTICE] mod_sofia.c:1521 Pre-Answer
sofia/internal/1001 at 10.4.62.7!
2009-10-07 17:45:26.793458 [DEBUG] switch_core_session.c:630 Send signal
sofia/internal/1001 at 10.4.62.7 [BREAK]
2009-10-07 17:45:26.793458 [DEBUG] switch_ivr_originate.c:2196 Originate
Resulted in Success: [opal/h323:05492122 at 10.4.4.254<h323%3A05492122 at 10.4.4.254>
]
2009-10-07 17:45:26.793458 [DEBUG] switch_channel.c:182 opal/
h323:05492122 at 10.4.4.254 <h323%3A05492122 at 10.4.4.254> receive message
[AUDIO_SYNC]
2009-10-07 17:45:26.793458 [DEBUG] mod_opal.cpp:1156 Received message 20 on
connection Call[c8dce50981]-EP<local>[1]
2009-10-07 17:45:26.793458 [DEBUG] switch_channel.c:182 sofia/internal/
1001 at 10.4.62.7 receive message [AUDIO_SYNC]
2009-10-07 17:45:26.793458 [DEBUG] switch_ivr_bridge.c:911 opal/
h323:05492122 at 10.4.4.254 <h323%3A05492122 at 10.4.4.254> receive message
[BRIDGE]
2009-10-07 17:45:26.793458 [DEBUG] sofia.c:3359 Channel sofia/internal/
1001 at 10.4.62.7 entering state [early][183]
2009-10-07 17:45:26.793458 [DEBUG] mod_opal.cpp:1156 Received message 4 on
connection Call[c8dce50981]-EP<local>[1]
2009-10-07 17:45:26.793458 [DEBUG] switch_core_session.c:630 Send signal
opal/h323:05492122 at 10.4.4.254 <h323%3A05492122 at 10.4.4.254> [BREAK]
2009-10-07 17:45:26.794816 [DEBUG] mod_opal.cpp:999 Kill 3 on connection
Call[c8dce50981]-EP<local>[1]
2009-10-07 17:45:26.794816 [DEBUG] switch_ivr_bridge.c:918 sofia/internal/
1001 at 10.4.62.7 receive message [BRIDGE]
2009-10-07 17:45:26.794816 [DEBUG] switch_core_session.c:630 Send signal
sofia/internal/1001 at 10.4.62.7 [BREAK]
2009-10-07 17:45:26.794816 [DEBUG] switch_ivr_bridge.c:962 (opal/
h323:05492122 at 10.4.4.254 <h323%3A05492122 at 10.4.4.254>) State Change
CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
< ----------------- snip ------------------>
1 entries {
[0]=dialedDigits "1001282122"
}
}
h245Tunneling = true
}
}
}
2009-10-07 17:45:31.892521 [DEBUG] h323.cxx:582 Handling PDU: Connect
callRef=26906
2009-10-07 17:45:31.892521 [DEBUG] connection.cxx:1115 SetPhase from
AlertingPhase to ConnectedPhase for
Call[c8dce50981]-EP<h323>[localhost/26906]
2009-10-07 17:45:31.892521 [DEBUG] connection.cxx:513 OnConnected for
Call[c8dce50981]-EP<h323>[localhost/26906]
2009-10-07 17:45:31.892521 [DEBUG] manager.cxx:652 OnConnected
Call[c8dce50981]-EP<h323>[localhost/26906]
2009-10-07 17:45:31.892521 [DEBUG] call.cxx:214 OnConnected
Call[c8dce50981]-EP<h323>[localhost/26906]
2009-10-07 17:45:31.892521 [DEBUG] connection.cxx:480 SetConnected for
Call[c8dce50981]-EP<local>[1]
2009-10-07 17:45:31.892521 [DEBUG] connection.cxx:1115 SetPhase from
AlertingPhase to ConnectedPhase for Call[c8dce50981]-EP<local>[1]
2009-10-07 17:45:31.892521 [DEBUG] connection.cxx:1115 SetPhase from
ConnectedPhase to EstablishedPhase for Call[c8dce50981]-EP<local>[1]
2009-10-07 17:45:31.892521 [DEBUG] connection.cxx:520 OnEstablished
Call[c8dce50981]-EP<local>[1]
2009-10-07 17:45:31.892521 [DEBUG] connection.cxx:617 Media stream threads
started.
2009-10-07 17:45:31.892521 [DEBUG] manager.cxx:660 OnEstablished
Call[c8dce50981]-EP<local>[1]
2009-10-07 17:45:31.892521 [DEBUG] call.cxx:245 OnEstablished
Call[c8dce50981]-EP<local>[1]
2009-10-07 17:45:31.892521 [DEBUG] connection.cxx:617 Media stream threads
started.
2009-10-07 17:45:31.892521 [DEBUG] connection.cxx:1115 SetPhase from
ConnectedPhase to EstablishedPhase for
Call[c8dce50981]-EP<h323>[localhost/26906]
2009-10-07 17:45:31.892521 [DEBUG] connection.cxx:520 OnEstablished
Call[c8dce50981]-EP<h323>[localhost/26906]
2009-10-07 17:45:31.892521 [DEBUG] connection.cxx:617 Media stream threads
started.
2009-10-07 17:45:31.893601 [DEBUG] manager.cxx:660 OnEstablished
Call[c8dce50981]-EP<h323>[localhost/26906]
2009-10-07 17:45:31.893601 [DEBUG] call.cxx:245 OnEstablished
Call[c8dce50981]-EP<h323>[localhost/26906]
2009-10-07 17:45:31.893601 [DEBUG] connection.cxx:617 Media stream threads
started.
2009-10-07 17:45:31.893601 [DEBUG] h323.cxx:945 Set protocol version to 5
2009-10-07 17:45:31.893601 [DEBUG] h323.cxx:1261 Set remote party name:
"10.4.4.254"
2009-10-07 17:45:31.893601 [DEBUG] h323.cxx:1269 Set remote application
name: "Avaya Multivantage R014x.00.1.731.2 181/19540 Vox Lucida Pty. Ltd."
2009-10-07 17:45:31.893601 [DEBUG] h323ep.cxx:1087 Received connect PDU.
2009-10-07 17:45:31.893601 [DEBUG] h323.cxx:2367 Fast start response with no
channels to open
2009-10-07 17:45:31.893601 [DEBUG] h323.cxx:3543
InternalEstablishedConnectionCheck: connectionState=HasExecutedSignalConnect
fastStartState=FastStartAcknowledged H.245 is ready
as ConnectMessage was never sent from opal to FS :P
what was your workaround?
> The most important problem I'm having right now is that G729 is
> still not working (poor quality due to high buffering). Even with
> the latest Opal, which includes the last week patch for jitter
> buffer. If you dont need G729, I could send you a patch for the
> latest svns (freeswitch, opal, ptlib), ofc no founding needed.
>
> There are a couple of bugs in opal itself and h323ing freeswitch
> with opal will bring them in. On the other hand, mod_opal is
> already there, it just needs a few adjustments.
>
>
> Best wishes,
>
> Claudiu Filip
>
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20091007/c0143b26/attachment-0002.html
More information about the FreeSWITCH-users
mailing list