On Wed, Oct 7, 2009 at 2:40 PM, Claudiu Filip <claudiu@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@10.4.4.254 <h323%3A05492122@10.4.4.254> initialise opal/h323:05492122@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@10.4.4.254 <h323%3A05492122@10.4.4.254> initialise opal/h323:05492122@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@10.4.4.254 <h323%3A05492122@10.4.4.254>! 2009-10-07 17:45:26.789158 [DEBUG] switch_channel.c:1822 Send signal sofia/internal/1001@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@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@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@10.4.62.7! 2009-10-07 17:45:26.793458 [DEBUG] switch_core_session.c:630 Send signal sofia/internal/1001@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@10.4.4.254<h323%3A05492122@10.4.4.254> ] 2009-10-07 17:45:26.793458 [DEBUG] switch_channel.c:182 opal/ h323:05492122@10.4.4.254 <h323%3A05492122@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@10.4.62.7 receive message [AUDIO_SYNC] 2009-10-07 17:45:26.793458 [DEBUG] switch_ivr_bridge.c:911 opal/ h323:05492122@10.4.4.254 <h323%3A05492122@10.4.4.254> receive message [BRIDGE] 2009-10-07 17:45:26.793458 [DEBUG] sofia.c:3359 Channel sofia/internal/ 1001@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@10.4.4.254 <h323%3A05492122@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@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@10.4.62.7 [BREAK] 2009-10-07 17:45:26.794816 [DEBUG] switch_ivr_bridge.c:962 (opal/ h323:05492122@10.4.4.254 <h323%3A05492122@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