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 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 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!
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]
2009-10-07 17:45:26.793458 [DEBUG] switch_channel.c:182 opal/h323:05492122@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 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 [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) 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